rendered paste bodyn
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 <mss 1460,nop,nop,sackOK>
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 <mss 1460,nop,nop,sackOK>
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 <mss 1460,nop,nop,sackOK>
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 <mss 1460,nop,nop,sackOK>
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 <enable_full_lr> 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 <enable_double_rr> 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 <enable_full_lr> in module rr [/usr/lib/openser/modules/rr.so]
0(20819) find_cmd_export_t: found <mf_process_maxfwd_header>(1) in module maxfwd [/usr/lib/openser/modules/maxfwd.so]
0(20819) find_cmd_export_t: found <sl_send_reply>(2) in module sl [/usr/lib/openser/modules/sl.so]
0(20819) find_cmd_export_t: found <record_route>(0) in module rr [/usr/lib/openser/modules/rr.so]
0(20819) find_cmd_export_t: found <t_relay>(1) in module tm [/usr/lib/openser/modules/tm.so]
0(20819) find_cmd_export_t: found <t_relay>(1) in module tm [/usr/lib/openser/modules/tm.so]
0(20819) find_cmd_export_t: found <t_relay>(0) in module tm [/usr/lib/openser/modules/tm.so]
0(20819) find_cmd_export_t: found <sl_reply_error>(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<mf_process_maxfwd_header> 0(20819) , "10" 0(20819) ); 0(20819) ) 0(20819) ) { 0(20819) external_module_call( 0(20819) f<sl_send_reply> 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<record_route> 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<t_relay> 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<t_relay> 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<t_relay> 0(20819) ); 0(20819) ) 0(20819) ) { 0(20819) external_module_call( 0(20819) f<sl_reply_error> 0(20819) ); 0(20819) } else { 0(20819) }; 0(20819)
0(20819) DEBUG:socket2str: <udp:66.192.107.225:5070>
0(20819) DEBUG:socket2str: <tcp:66.192.107.225:5070>
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 <serial_branch> 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: <INVITE>
2(20823) uri: <sip:666666@pbx.elephantoutlook.com:5070>
2(20823) version: <SIP/2.0>
2(20823) parse_headers: flags=2
2(20823) Found param type 232, <branch> = <z9hG4bK6709593e>; state=6
2(20823) Found param type 235, <rport> = <n/a>; 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: <To> [43]; uri=[sip:666666@pbx.elephantoutlook.com:5070]
2(20823) DEBUG: to body [<sip:666666@pbx.elephantoutlook.com:5070>
]
2(20823) get_hdr_field: cseq <CSeq>: <102> <INVITE>
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: <sip:66.192.107.225:5070;lr=on;ftag=as5931bfaa>
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" <sip:3149@66.192.107.225>;tag=as5931bfaa
To: <sip:666666@pbx.elephantoutlook.com:5070>
Contact: <sip:3149@66.192.107.225>
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: <ACK>
5(20826) uri: <sip:666666@pbx.elephantoutlook.com:5070>
5(20826) version: <SIP/2.0>
5(20826) parse_headers: flags=2
5(20826) Found param type 232, <branch> = <z9hG4bK6709593e>; state=6
5(20826) Found param type 235, <rport> = <n/a>; 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: <To> [85]; uri=[sip:666666@pbx.elephantoutlook.com:5070]
5(20826) DEBUG: to body [<sip:666666@pbx.elephantoutlook.com:5070>]
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: <SIP/2.0>
7(20828) status: <100>
7(20828) reason: <Trying>
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: <TO> [43]; uri=[sip:666666@pbx.elephantoutlook.com:5070]
7(20828) DEBUG: to body [<sip:666666@pbx.elephantoutlook.com:5070>
]
7(20828) get_hdr_field: cseq <CSEQ>: <102> <INVITE>
7(20828) Found param type 232, <branch> = <z9hG4bKdcce.a219e4c.0>; state=9
7(20828) parse_via: next_via
7(20828) Found param type 232, <branch> = <z9hG4bK6709593e>; state=6
7(20828) Found param type 235, <rport> = <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: <SIP/2.0>
7(20828) status: <302>
7(20828) reason: <Moved Temporarily>
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: <TO> [58]; uri=[sip:666666@pbx.elephantoutlook.com:5070]
7(20828) DEBUG: to body [<sip:666666@pbx.elephantoutlook.com:5070>]
7(20828) get_hdr_field: cseq <CSEQ>: <102> <INVITE>
7(20828) Found param type 232, <branch> = <z9hG4bKdcce.a219e4c.0>; state=9
7(20828) parse_via: next_via
7(20828) Found param type 232, <branch> = <z9hG4bK6709593e>; state=6
7(20828) Found param type 235, <rport> = <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=<From: "Jon Webster" <sip:3149@66.192.107.225>;tag=as5931bfaa
>, TO=<TO: <sip:666666@pbx.elephantoutlook.com:5070>;tag=4c997c972c
>, CSEQ_N=<CSeq: 102>
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" <sip:3149@66.192.107.225>;tag=as5931bfaa
Call-ID: 4e26f9f962b415886f3a84fb17f92c18@66.192.107.225
TO: <sip:666666@pbx.elephantoutlook.com:5070>;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"<sip:3149@66.192.107.225>;tag=as5931bfaa
TO: <sip:666666@pbx.elephantoutlook.com:5070>;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: <sip:666666@pbx.elephantoutlook.com:5061;transport=TCP>
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: <ACK>
2(20823) uri: <sip:666666@pbx.elephantoutlook.com:5070>
2(20823) version: <SIP/2.0>
2(20823) parse_headers: flags=2
2(20823) Found param type 232, <branch> = <z9hG4bK6709593e>; state=6
2(20823) Found param type 235, <rport> = <n/a>; 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: <To> [58]; uri=[sip:666666@pbx.elephantoutlook.com:5070]
2(20823) DEBUG: to body [<sip:666666@pbx.elephantoutlook.com:5070>]
2(20823) parse_headers: flags=100
2(20823) get_hdr_field: cseq <CSeq>: <102> <ACK>
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