n administrator@pbx:~$ 00:14:32.198730 IP 66.192.107.225.5060 > 66.192.106.194.2621: R 0:0(0) ack 2944717504 win 0 00:14:32.692077 IP 66.192.106.194.2621 > 66.192.107.225.5060: S 2944717503:2944717503(0) win 65535 00:14:32.692172 IP 66.192.107.225.5060 > 66.192.106.194.2621: R 0:0(0) ack 1 win 0 00:14:33.195013 IP 66.192.106.194.2621 > 66.192.107.225.5060: S 2944717503:2944717503(0) win 65535 00:14:33.195104 IP 66.192.107.225.5060 > 66.192.106.194.2621: R 0:0(0) ack 1 win 0 00:14:33.197167 IP 66.192.106.194.2622 > 66.192.107.225.5060: S 2138520751:2138520751(0) win 65535 00:14:33.197218 IP 66.192.107.225.5060 > 66.192.106.194.2622: R 0:0(0) ack 2138520752 win 0 00:14:33.697952 IP 66.192.106.194.2622 > 66.192.107.225.5060: S 2138520751:2138520751(0) win 65535 00:14:33.698039 IP 66.192.107.225.5060 > 66.192.106.194.2622: R 0:0(0) ack 1 win 0 795 packets captured 795 packets received by filter 0 packets dropped by kernel administrator@pbx:~$ sl_send_reply("483","Too Many Hops"); exit; }; record_route(); ## If asterisks ends us a packet forward it to Exchange(TCP) (webcode.com) otherwise redirect it back to asterisk (UDP) if (src_ip=="66.192.107.225") { log("\n====================\n === Relaying to Exchange ===\n====================\n"); t_relay("tcp:66.192.106.194:5060"); # forward("tcp:66.192.106.194:5060"); } else { log("\n====================\n === Relaying to Asterisk ===\n====================\n"); t_relay("udp:66.192.107.225:5060"); # forward("udp:66.192.107.225:5060"); }; ### ### http://lists.digium.com/pipermail/asterisk-users/2006-January/137763.html "/etc/openser/openser.cfg" 211L, 5655C written administrator@pbx:~$ ps aux|grep openser adminis 20791 0.0 0.0 1648 496 pts/5 R+ 02:12 0:00 grep openser administrator@pbx:~$ sudo invoke-rc.d openser start Password: Starting openser: openser 0(20819) loading module /usr/lib/openser/modules/sl.so 0(20819) loading module /usr/lib/openser/modules/tm.so 0(20819) loading module /usr/lib/openser/modules/rr.so 0(20819) loading module /usr/lib/openser/modules/maxfwd.so 0(20819) set_mod_param_regex: rr matches module rr 0(20819) set_mod_param_regex: found in module rr [/usr/lib/openser/modules/rr.so] 0(20819) set_mod_param_regex: rr matches module rr 0(20819) set_mod_param_regex: found in module rr [/usr/lib/openser/modules/rr.so] 0(20819) set_mod_param_regex: rr matches module rr 0(20819) set_mod_param_regex: found in module rr [/usr/lib/openser/modules/rr.so] 0(20819) find_cmd_export_t: found (1) in module maxfwd [/usr/lib/openser/modules/maxfwd.so] 0(20819) find_cmd_export_t: found (2) in module sl [/usr/lib/openser/modules/sl.so] 0(20819) find_cmd_export_t: found (0) in module rr [/usr/lib/openser/modules/rr.so] 0(20819) find_cmd_export_t: found (1) in module tm [/usr/lib/openser/modules/tm.so] 0(20819) find_cmd_export_t: found (1) in module tm [/usr/lib/openser/modules/tm.so] 0(20819) find_cmd_export_t: found (0) in module tm [/usr/lib/openser/modules/tm.so] 0(20819) find_cmd_export_t: found (0) in module sl [/usr/lib/openser/modules/sl.so] 0(20819) routing table 0: 0(20819) if ( 0(20819) NOT( 0(20819) external_module_call( 0(20819) f 0(20819) , "10" 0(20819) ); 0(20819) ) 0(20819) ) { 0(20819) external_module_call( 0(20819) f 0(20819) , "483" 0(20819) , "Too Many Hops" 0(20819) ); 0(20819) exit( 0(20819) type<0> 0(20819) ); 0(20819) } else { 0(20819) }; 0(20819) external_module_call( 0(20819) f 0(20819) ); 0(20819) if ( 0(20819) srcip 0(20819) == 0(20819) 66.192.107.225/ 0(20819) 255.255.255.255 0(20819) ) { 0(20819) log( 0(20819) 4 0(20819) , " ==================== === Relaying to Exchange === ==================== " 0(20819) ); 0(20819) external_module_call( 0(20819) f 0(20819) , "tcp:66.192.106.194:5060" 0(20819) ); 0(20819) } else { 0(20819) log( 0(20819) 4 0(20819) , " ==================== === Relaying to Asterisk === ==================== " 0(20819) ); 0(20819) external_module_call( 0(20819) f 0(20819) , "udp:66.192.107.225:5060" 0(20819) ); 0(20819) }; 0(20819) if ( 0(20819) method 0(20819) == 0(20819) "INVITE" 0(20819) ) { 0(20819) if ( 0(20819) uri 0(20819) =~ 0(20819) "sip:9[0-9](10)@*" 0(20819) ) { 0(20819) log( 0(20819) 1 0(20819) , "Forwarding to Asterisk " 0(20819) ); 0(20819) sethostport( 0(20819) "66.192.107.225:5060" 0(20819) ); 0(20819) } else { 0(20819) }; 0(20819) } else { 0(20819) }; 0(20819) if ( 0(20819) NOT( 0(20819) external_module_call( 0(20819) f 0(20819) ); 0(20819) ) 0(20819) ) { 0(20819) external_module_call( 0(20819) f 0(20819) ); 0(20819) } else { 0(20819) }; 0(20819) 0(20819) DEBUG:socket2str: 0(20819) DEBUG:socket2str: Listening on udp: 66.192.107.225 [66.192.107.225]:5070 tcp: 66.192.107.225 [66.192.107.225]:5070 Aliases: tcp: pbx.elephantoutlook.com:5070 udp: pbx.elephantoutlook.com:5070 0(20819) fm_malloc_init: F_OPTIMIZE=16384, /ROUNDTO=2048 0(20819) fm_malloc_init: F_HASH_SIZE=2067, fm_block size=16560 0(20819) fm_malloc_init(0xb5d9a000, 33554432), start=0xb5d9a000 0(20819) shm_mem_init: success 0(20819) init_tcp: using epoll_lt as the io watch method (auto detected) 0(0) core dump limits set to 4294967295 0(0) DEBUG:add_avp_galias: registering for avp id <16725044> 0(0) DEBUG: register_fifo_cmd: new command (get_statistics) registered 0(0) DEBUG: register_fifo_cmd: new command (reset_statistics) registered 0(0) INFO: statistics manager successfully initialized 0(0) DEBUG: init_mod: sl 0(0) StateLess module - initializing 0(0) DEBUG: MD5 calculated: ff0593a3ce80005043f79ea67dccae1c 0(0) DEBUG: init_stats: sl 0(0) DEBUG: init_mod: tm 0(0) TM - initializing... 0(0) Call-ID initialization: '5758bfff' 0(0) DEBUG: register_fifo_cmd: new command (t_uac_dlg) registered 0(0) DEBUG: register_fifo_cmd: new command (t_uac_cancel) registered 0(0) DEBUG: register_fifo_cmd: new command (t_hash) registered 0(0) DEBUG: register_fifo_cmd: new command (t_reply) registered 0(0) unixsock_register_cmd: New command (t_uac_dlg) registered 0(0) unixsock_register_cmd: New command (t_uac_cancel) registered 0(0) unixsock_register_cmd: New command (t_hash) registered 0(0) unixsock_register_cmd: New command (t_reply) registered . administrator@pbx:~$ 0(0) DEBUG: lock_initialize: lock initialization started 0(0) DEBUG: MD5 calculated: 61ca39b0619cde6cec91de154b7c9a9a 0(0) DEBUG: MD5 calculated: ee1687ae4f112bbfe1bb0915cccbdec2 0(0) xl_add_extra_spec: extra items list is not initialized 0(0) xl_add_extra_spec: inserting extra item [T_branch_idx] at [0] 0(0) DEBUG: init_stats: tm 0(0) DEBUG: init_mod: rr 0(0) rr - initializing 0(0) DEBUG: init_mod: maxfwd 0(0) Maxfwd module- initializing 0(0) fixing mf_process_maxfwd_header, line 85 0(0) fixing sl_send_reply, line 86 0(0) fixing record_route, line 90 0(0) fixing t_relay, line 95 0(0) DEBUG: mk_proxy: doing DNS lookup... 0(0) fixing t_relay, line 100 0(0) DEBUG: mk_proxy: doing DNS lookup... 0(0) fixing t_relay, line 114 0(0) fixing sl_reply_error, line 115 0(0) INFO: udp_init: SO_RCVBUF is initially 105472 0(0) DEBUG: udp_init: trying SO_RCVBUF: 210944 0(0) DEBUG: setting SO_RCVBUF; set=210944,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 212992 0(0) DEBUG: setting SO_RCVBUF; set=212992,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 215040 0(0) DEBUG: setting SO_RCVBUF; set=215040,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 217088 0(0) DEBUG: setting SO_RCVBUF; set=217088,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 219136 0(0) DEBUG: setting SO_RCVBUF; set=219136,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 221184 0(0) DEBUG: setting SO_RCVBUF; set=221184,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 223232 0(0) DEBUG: setting SO_RCVBUF; set=223232,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 225280 0(0) DEBUG: setting SO_RCVBUF; set=225280,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 227328 0(0) DEBUG: setting SO_RCVBUF; set=227328,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 229376 0(0) DEBUG: setting SO_RCVBUF; set=229376,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 231424 0(0) DEBUG: setting SO_RCVBUF; set=231424,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 233472 0(0) DEBUG: setting SO_RCVBUF; set=233472,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 235520 0(0) DEBUG: setting SO_RCVBUF; set=235520,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 237568 0(0) DEBUG: setting SO_RCVBUF; set=237568,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 239616 0(0) DEBUG: setting SO_RCVBUF; set=239616,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 241664 0(0) DEBUG: setting SO_RCVBUF; set=241664,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 243712 0(0) DEBUG: setting SO_RCVBUF; set=243712,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 245760 0(0) DEBUG: setting SO_RCVBUF; set=245760,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 247808 0(0) DEBUG: setting SO_RCVBUF; set=247808,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 249856 0(0) DEBUG: setting SO_RCVBUF; set=249856,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 251904 0(0) DEBUG: setting SO_RCVBUF; set=251904,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 253952 0(0) DEBUG: setting SO_RCVBUF; set=253952,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 256000 0(0) DEBUG: setting SO_RCVBUF; set=256000,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 258048 0(0) DEBUG: setting SO_RCVBUF; set=258048,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 260096 0(0) DEBUG: setting SO_RCVBUF; set=260096,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 262144 0(0) DEBUG: setting SO_RCVBUF; set=262144,verify=262142 0(0) DEBUG: setting SO_RCVBUF has no effect 0(0) INFO: udp_init: SO_RCVBUF is finally 262142 0(0) DBG: open_uac_fifo: opening fifo... 0(0) DEBUG: FIFO created @ /tmp/openser_fifo 0(0) DEBUG: fifo /tmp/openser_fifo opened, mode=432 0(0) init_unixsock_socket: No unix domain socket will be opened 1(20822) INFO: fifo process starting: 20822 1(20822) DEBUG:init_mod_child: PROC_FIFO , rank=-2, module=tm 1(20822) DEBUG: callid: '5758bfff-20822@66.192.107.225' 1(20822) INFO:open_uac_fifo: fifo server up at /tmp/openser_fifo... 1(20822) DEBUG: register_fifo_cmd: new command (print) registered 1(20822) DEBUG: register_fifo_cmd: new command (uptime) registered 1(20822) DEBUG: register_fifo_cmd: new command (version) registered 1(20822) DEBUG: register_fifo_cmd: new command (pwd) registered 1(20822) DEBUG: register_fifo_cmd: new command (arg) registered 1(20822) DEBUG: register_fifo_cmd: new command (which) registered 1(20822) DEBUG: register_fifo_cmd: new command (ps) registered 1(20822) DEBUG: register_fifo_cmd: new command (kill) registered 1(20822) DEBUG: register_fifo_cmd: new command (meminfo) registered 1(20822) INFO: no fifo_db_url given - fifo DB commands disabled! 2(20823) DEBUG:init_mod_child: CHILD , rank=1, module=tm 2(20823) DEBUG: callid: '5758bfff-20823@66.192.107.225' 3(20824) DEBUG:init_mod_child: CHILD , rank=2, module=tm 3(20824) DEBUG: callid: '5758bfff-20824@66.192.107.225' 4(20825) DEBUG:init_mod_child: CHILD , rank=3, module=tm 4(20825) DEBUG: callid: '5758bfff-20825@66.192.107.225' 5(20826) DEBUG:init_mod_child: CHILD , rank=4, module=tm 5(20826) DEBUG: callid: '5758bfff-20826@66.192.107.225' 6(20827) DEBUG:init_mod_child: PROC_TIMER , rank=-1, module=tm 6(20827) DEBUG: callid: '5758bfff-20827@66.192.107.225' 7(20828) DEBUG:init_mod_child: CHILD , rank=5, module=tm 7(20828) DEBUG: callid: '5758bfff-20828@66.192.107.225' 7(20828) DBG: io_watch_add(0x80dfe80, 17, 1, (nil)), fd_no=0 8(20829) DEBUG:init_mod_child: CHILD , rank=6, module=tm 8(20829) DEBUG: callid: '5758bfff-20829@66.192.107.225' 8(20829) DBG: io_watch_add(0x80dfe80, 19, 1, (nil)), fd_no=0 9(20830) DEBUG:init_mod_child: CHILD , rank=7, module=tm 9(20830) DEBUG: callid: '5758bfff-20830@66.192.107.225' 9(20830) DBG: io_watch_add(0x80dfe80, 21, 1, (nil)), fd_no=0 10(20831) DEBUG:init_mod_child: CHILD , rank=8, module=tm 10(20831) DEBUG: callid: '5758bfff-20831@66.192.107.225' 10(20831) DBG: io_watch_add(0x80dfe80, 23, 1, (nil)), fd_no=0 11(20832) DEBUG:init_mod_child: PROC_TCP_MAIN , rank=-4, module=tm 11(20832) DEBUG: callid: '5758bfff-20832@66.192.107.225' 11(20832) DBG: io_watch_add(0x80dfd20, 5, 1, 0x8115c98), fd_no=0 11(20832) DBG: io_watch_add(0x80dfd20, 8, 4, 0xb5da0194), fd_no=1 11(20832) DBG: io_watch_add(0x80dfd20, 9, 4, 0xb5da0220), fd_no=2 11(20832) DBG: io_watch_add(0x80dfd20, 10, 4, 0xb5da02ac), fd_no=3 11(20832) DBG: io_watch_add(0x80dfd20, 11, 4, 0xb5da0338), fd_no=4 11(20832) DBG: io_watch_add(0x80dfd20, 12, 4, 0xb5da03c4), fd_no=5 11(20832) DBG: io_watch_add(0x80dfd20, 13, 4, 0xb5da0450), fd_no=6 11(20832) DBG: io_watch_add(0x80dfd20, 14, 4, 0xb5da04dc), fd_no=7 11(20832) DBG: io_watch_add(0x80dfd20, 15, 4, 0xb5da0568), fd_no=8 11(20832) DBG: io_watch_add(0x80dfd20, 17, 4, 0xb5da05f4), fd_no=9 11(20832) DBG: io_watch_add(0x80dfd20, 19, 4, 0xb5da0680), fd_no=10 11(20832) DBG: io_watch_add(0x80dfd20, 16, 3, 0x8111300), fd_no=11 11(20832) DBG: io_watch_add(0x80dfd20, 18, 3, 0x8111314), fd_no=12 11(20832) DBG: io_watch_add(0x80dfd20, 20, 3, 0x8111328), fd_no=13 11(20832) DBG: io_watch_add(0x80dfd20, 22, 3, 0x811133c), fd_no=14 0(20821) DEBUG:init_mod_child: PROC_MAIN , rank=0, module=tm 0(20821) DEBUG: callid: '5758bfff-20821@66.192.107.225' 2(20823) SIP Request: 2(20823) method: 2(20823) uri: 2(20823) version: 2(20823) parse_headers: flags=2 2(20823) Found param type 232, = ; state=6 2(20823) Found param type 235, = ; state=17 2(20823) end of header reached, state=5 2(20823) parse_headers: Via found, flags=2 2(20823) parse_headers: this is the first via 2(20823) After parse_msg... 2(20823) preparing to run routing scripts... 2(20823) parse_headers: flags=100 2(20823) DEBUG:parse_to:end of header reached, state=10 2(20823) DBUG:parse_to: display={}, ruri={sip:666666@pbx.elephantoutlook.com:5070} 2(20823) DEBUG: get_hdr_field: [43]; uri=[sip:666666@pbx.elephantoutlook.com:5070] 2(20823) DEBUG: to body [ ] 2(20823) get_hdr_field: cseq : <102> 2(20823) DEBUG:maxfwd:is_maxfwd_present: value = 70 2(20823) DEBUG: add_param: tag=as5931bfaa 2(20823) DEBUG:parse_to:end of header reached, state=29 2(20823) DBUG:parse_to: display={"Jon Webster"}, ruri={sip:3149@66.192.107.225} 2(20823) ==================== === Relaying to Exchange === ==================== 2(20823) DEBUG: t_newtran: msg id=1 , global msg id=0 , T on entrance=0xffffffff 2(20823) parse_headers: flags=ffffffffffffffff 2(20823) DEBUG: get_hdr_body : content_length=291 2(20823) found end of header 2(20823) parse_headers: flags=78 2(20823) t_lookup_request: start searching: hash=60621, isACK=0 2(20823) DEBUG: RFC3261 transaction matching failed 2(20823) DEBUG: t_lookup_request: no transaction found 2(20823) DEBUG:tm:t_relay: new INVITE 2(20823) parse_headers: flags=ffffffffffffffff 2(20823) check_via_address(66.192.107.225, 66.192.107.225, 0) 2(20823) WARNING:vqm_resize: resize(0) called 2(20823) DEBUG:tm:_reply_light: reply sent out. buf=0x8117e58: SIP/2.0 1..., shmem=0xb5f22a98: SIP/2.0 1 2(20823) DEBUG:tm:_reply_light: finished 2(20823) parse_headers: flags=2000 2(20823) check_via_address(66.192.107.225, 66.192.107.225, 0) 2(20823) tcp_send: no open tcp connection found, opening new one 2(20823) tcpconn_new: new tcp connection to: 66.192.106.194 2(20823) tcpconn_new: on port 5060, type 2 2(20823) tcp_send: sending... 2(20823) tcp_send: after write: c= 0xb5f23170 n=973 fd=9 2(20823) tcp_send: buf= INVITE sip:666666@pbx.elephantoutlook.com:5070 SIP/2.0 Record-Route: Via: SIP/2.0/TCP 66.192.107.225:5070;branch=z9hG4bKdcce.a219e4c.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK6709593e;rport=5060 From: "Jon Webster" ;tag=as5931bfaa To: Contact: Call-ID: 4e26f9f962b415886f3a84fb17f92c18@66.192.107.225 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 69 Date: Thu, 07 Dec 2006 07:13:18 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 291 v=0 o=root 8640 8640 IN IP4 66.192.107.225 s=session c=IN IP4 66.192.107.225 t=0 0 m=audio 15766 RTP/AVP 0 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - m=video 16690 RTP/AVP 34 a=rtpmap:34 H263/90000 2(20823) DEBUG: add_to_tail_of_timer[0]: 0xb5f21664 2(20823) SER: new transaction fwd'ed 2(20823) DEBUG: t_newtran: msg id=1 , global msg id=1 , T on entrance=0xb5f21538 2(20823) ERROR: t_newtran: transaction already in process 0xb5f21538 2(20823) DEBUG:sl:sl_reply_error: error text is I'm terribly sorry, server error occurred (1/SL) 2(20823) parse_headers: flags=ffffffffffffffff 2(20823) check_via_address(66.192.107.225, 66.192.107.225, 0) 2(20823) DEBUG:tm:UNREF_UNSAFE: after is 0 2(20823) DEBUG:destroy_avp_list: destroying list (nil) 2(20823) receive_msg: cleaning up 11(20832) handle_ser_child: read response= b5f23170, 2, fd 23 from 2 (20823) 11(20832) tcpconn_add: hashes: 902, 1 11(20832) DBG: io_watch_add(0x80dfd20, 23, 2, 0xb5f23170), fd_no=15 5(20826) SIP Request: 5(20826) method: 5(20826) uri: 5(20826) version: 5(20826) parse_headers: flags=2 5(20826) Found param type 232, = ; state=6 5(20826) Found param type 235, = ; state=17 5(20826) end of header reached, state=5 5(20826) parse_headers: Via found, flags=2 5(20826) parse_headers: this is the first via 5(20826) After parse_msg... 5(20826) preparing to run routing scripts... 5(20826) parse_headers: flags=8 5(20826) DEBUG: add_param: tag=ff0593a3ce80005043f79ea67dccae1c.8335 5(20826) DEBUG:parse_to:end of header reached, state=29 5(20826) DBUG:parse_to: display={}, ruri={sip:666666@pbx.elephantoutlook.com:5070} 5(20826) DEBUG: get_hdr_field: [85]; uri=[sip:666666@pbx.elephantoutlook.com:5070] 5(20826) DEBUG: to body [] 5(20826) DEBUG: sl_filter_ACK : local ACK found -> dropping it! 5(20826) DEBUG:destroy_avp_list: destroying list (nil) 5(20826) receive_msg: cleaning up 11(20832) handle_tcpconn_ev: data available on 0xb5f23170 23 11(20832) DBG: io_watch_del (0x80dfd20, 23, -1, 0x0) fd_no=16 called 11(20832) send2child: to tcp child 0 7(20828), 0xb5f23170 7(20828) received n=4 con=0xb5f23170, fd=18 7(20828) DBG: io_watch_add(0x80dfe80, 18, 2, 0xb5f23170), fd_no=1 7(20828) tcp_read_req: content-length= 0 7(20828) SIP Reply (status): 7(20828) version: 7(20828) status: <100> 7(20828) reason: 7(20828) parse_headers: flags=2 7(20828) DEBUG:parse_to:end of header reached, state=10 7(20828) DBUG:parse_to: display={}, ruri={sip:666666@pbx.elephantoutlook.com:5070} 7(20828) DEBUG: get_hdr_field: [43]; uri=[sip:666666@pbx.elephantoutlook.com:5070] 7(20828) DEBUG: to body [ ] 7(20828) get_hdr_field: cseq : <102> 7(20828) Found param type 232, = ; state=9 7(20828) parse_via: next_via 7(20828) Found param type 232, = ; state=6 7(20828) Found param type 235, = <5060>; state=16 7(20828) end of header reached, state=5 7(20828) parse_headers: Via found, flags=2 7(20828) parse_headers: this is the first via 7(20828) After parse_msg... 7(20828) forward_reply: found module tm, passing reply to it 7(20828) DEBUG: t_check: msg id=1 global id=0 T start=0xffffffff 7(20828) parse_headers: flags=22 7(20828) parse_headers: flags=8 7(20828) DEBUG: t_reply_matching: hash 60621 label 206475562 branch 0 7(20828) DEBUG:tm:REF_UNSAFE: after is 1 7(20828) DEBUG: t_reply_matching: reply matched (T=0xb5f21538)! 7(20828) DEBUG: t_check: msg id=1 global id=1 T end=0xb5f21538 7(20828) DEBUG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1) 7(20828) DEBUG:tm:t_should_relay_response: T_code=100, new_code=100 7(20828) DEBUG:tm:relay_reply: branch=0, save=0, relay=-1 7(20828) DEBUG: add_to_tail_of_timer[1]: 0xb5f21664 7(20828) DEBUG:tm:UNREF_UNSAFE: after is 0 7(20828) DEBUG:destroy_avp_list: destroying list (nil) 7(20828) receive_msg: cleaning up 7(20828) tcp_read_req: content-length= 0 7(20828) SIP Reply (status): 7(20828) version: 7(20828) status: <302> 7(20828) reason: 7(20828) parse_headers: flags=2 7(20828) DEBUG: add_param: tag=4c997c972c 7(20828) DEBUG:parse_to:end of header reached, state=29 7(20828) DBUG:parse_to: display={}, ruri={sip:666666@pbx.elephantoutlook.com:5070} 7(20828) DEBUG: get_hdr_field: [58]; uri=[sip:666666@pbx.elephantoutlook.com:5070] 7(20828) DEBUG: to body [] 7(20828) get_hdr_field: cseq : <102> 7(20828) Found param type 232, = ; state=9 7(20828) parse_via: next_via 7(20828) Found param type 232, = ; state=6 7(20828) Found param type 235, = <5060>; state=16 7(20828) end of header reached, state=5 7(20828) parse_headers: Via found, flags=2 7(20828) parse_headers: this is the first via 7(20828) After parse_msg... 7(20828) forward_reply: found module tm, passing reply to it 7(20828) DEBUG: t_check: msg id=2 global id=1 T start=0xffffffff 7(20828) parse_headers: flags=22 7(20828) parse_headers: flags=8 7(20828) DEBUG: t_reply_matching: hash 60621 label 206475562 branch 0 7(20828) DEBUG:tm:REF_UNSAFE: after is 1 7(20828) DEBUG: t_reply_matching: reply matched (T=0xb5f21538)! 7(20828) DEBUG: t_check: msg id=2 global id=2 T end=0xb5f21538 7(20828) DEBUG:tm:reply_received: org. status uas=100, uac[0]=100 local=0 is_invite=1) 7(20828) parse_headers: flags=8 7(20828) DEBUG:tm:build_local: using FROM=;tag=as5931bfaa >, TO=;tag=4c997c972c >, CSEQ_N= 7(20828) tcp_send: tcp connection found (0xb5f23170), acquiring fd 7(20828) tcp_send, c= 0xb5f23170, n=8 11(20832) handle_ser_child: read response= b5f23170, 1, fd -1 from 7 (20828) 7(20828) tcp_send: after receive_fd: c= 0xb5f23170 n=4 fd=19 7(20828) tcp_send: sending... 7(20828) tcp_send: after write: c= 0xb5f23170 n=386 fd=19 7(20828) tcp_send: buf= ACK sip:666666@pbx.elephantoutlook.com:5070 SIP/2.0 Via: SIP/2.0/TCP 66.192.107.225:5070;branch=z9hG4bKdcce.a219e4c.0 From: "Jon Webster" ;tag=as5931bfaa Call-ID: 4e26f9f962b415886f3a84fb17f92c18@66.192.107.225 TO: ;tag=4c997c972c CSeq: 102 ACK User-Agent: OpenSer (1.1.0-notls (i386/linux)) Content-Length: 0 7(20828) DEBUG:tm:t_should_relay_response: T_code=100, new_code=302 7(20828) DEBUG:tm:t_pick_branch: picked branch 0, code 302 7(20828) DEBUG:tm:relay_reply: branch=0, save=0, relay=0 7(20828) old size: 493, new size: 432 7(20828) build_res_from_sip_res: copied size: orig:314, new: 253, rest: 179 msg= SIP/2.0 302 Moved Temporarily FROM: "Jon Webster";tag=as5931bfaa TO: ;tag=4c997c972c CSEQ: 102 INVITE CALL-ID: 4e26f9f962b415886f3a84fb17f92c18@66.192.107.225 MAX-FORWARDS: 70 VIA: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK6709593e;rport=5060 CONTENT-LENGTH: 0 SERVER: RTCC/2.0.6010.0 CONTACT: 7(20828) DEBUG: add_to_tail_of_timer[4]: 0xb5f215e8 7(20828) DEBUG: add_to_tail_of_timer[0]: 0xb5f215f8 7(20828) DEBUG:tm:relay_reply: sent buf=0x8117af8: SIP/2.0 3..., shmem=0xb5f22a98: SIP/2.0 3 7(20828) DEBUG: cleanup_uac_timers: RETR/FR timers reset 7(20828) DEBUG:tm:UNREF_UNSAFE: after is 0 7(20828) DEBUG:destroy_avp_list: destroying list (nil) 7(20828) receive_msg: cleaning up 7(20828) tcp_read: EOF on 0xb5f23170, FD 18 7(20828) tcp_read_req: EOF 7(20828) DBG: io_watch_del (0x80dfe80, 18, -1, 0x10) fd_no=2 called 7(20828) releasing con 0xb5f23170, state -1, fd=18, id=1 7(20828) extra_data (nil) 2(20823) SIP Request: 2(20823) method: 2(20823) uri: 2(20823) version: 2(20823) parse_headers: flags=2 2(20823) Found param type 232, = ; state=6 2(20823) Found param type 235, = ; state=17 2(20823) end of header reached, state=5 2(20823) parse_headers: Via found, flags=2 2(20823) parse_headers: this is the first via 2(20823) After parse_msg... 2(20823) preparing to run routing scripts... 2(20823) parse_headers: flags=8 2(20823) DEBUG: add_param: tag=4c997c972c 2(20823) DEBUG:parse_to:end of header reached, state=29 2(20823) DBUG:parse_to: display={}, ruri={sip:666666@pbx.elephantoutlook.com:5070} 2(20823) DEBUG: get_hdr_field: [58]; uri=[sip:666666@pbx.elephantoutlook.com:5070] 2(20823) DEBUG: to body [] 2(20823) parse_headers: flags=100 2(20823) get_hdr_field: cseq : <102> 2(20823) DEBUG:maxfwd:is_maxfwd_present: value = 70 2(20823) DEBUG: add_param: tag=as5931bfaa 2(20823) DEBUG:parse_to:end of header reached, state=29 2(20823) DBUG:parse_to: display={"Jon Webster"}, ruri={sip:3149@66.192.107.225} 2(20823) ==================== === Relaying to Exchange === ==================== 2(20823) DEBUG: t_newtran: msg id=2 , global msg id=1 , T on entrance=0xffffffff 2(20823) parse_headers: flags=ffffffffffffffff 2(20823) DEBUG: get_hdr_body : content_length=0 2(20823) found end of header 2(20823) parse_headers: flags=78 2(20823) t_lookup_request: start searching: hash=60621, isACK=1 2(20823) DEBUG: RFC3261 transaction matched, tid=6709593e 2(20823) DEBUG:tm:REF_UNSAFE: after is 1 2(20823) DEBUG: t_lookup_request: transaction found (T=0xb5f21538) 2(20823) DEBUG: cleanup_uac_timers: RETR/FR timers reset 2(20823) DEBUG: add_to_tail_of_timer[2]: 0xb5f21580 2(20823) DEBUG: t_newtran: msg id=2 , global msg id=2 , T on entrance=0xb5f21538 2(20823) ERROR: t_newtran: transaction already in process 0xb5f21538 2(20823) DEBUG:sl:sl_reply_error: error text is I'm terribly sorry, server error occurred (1/SL) 2(20823) WARNING:sl:sl_send_reply: I won't send a reply for ACK!! 2(20823) DEBUG:tm:UNREF_UNSAFE: after is 0 2(20823) DEBUG:destroy_avp_list: destroying list (nil) 2(20823) receive_msg: cleaning up 11(20832) handle_tcp_child: reader response= b5f23170, -1 from 0 11(20832) tcpconn_destroy: destroying connection 0xb5f23170, flags 0002 6(20827) DEBUG: timer routine:0,tl=0xb5f215f8 next=(nil) 6(20827) DEBUG: timer routine:1,tl=0xb5f21664 next=(nil) 6(20827) DEBUG: timer routine:4,tl=0xb5f215e8 next=(nil) 6(20827) DEBUG: timer routine:2,tl=0xb5f21580 next=(nil) 6(20827) DEBUG: wait_handler : removing 0xb5f21538 from table 6(20827) DEBUG: delete transaction 0xb5f21538 6(20827) DEBUG: wait_handler : done