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=100 5(20826) DEBUG:parse_to:end of header reached, state=10 5(20826) DBUG:parse_to: display={}, ruri={sip:666666@pbx.elephantoutlook.com:5070} 5(20826) DEBUG: get_hdr_field: [43]; uri=[sip:666666@pbx.elephantoutlook.com:5070] 5(20826) DEBUG: to body [ ] 5(20826) get_hdr_field: cseq : <102> 5(20826) DEBUG:maxfwd:is_maxfwd_present: value = 70 5(20826) DEBUG: add_param: tag=as5c3450e3 5(20826) DEBUG:parse_to:end of header reached, state=29 5(20826) DBUG:parse_to: display={"Jon Webster"}, ruri={sip:3149@66.192.107.225} 5(20826) ==================== === Relaying to Exchange === ==================== 5(20826) DEBUG: t_newtran: msg id=3 , global msg id=2 , T on entrance=0xffffffff 5(20826) parse_headers: flags=ffffffffffffffff 5(20826) DEBUG: get_hdr_body : content_length=291 5(20826) found end of header 5(20826) parse_headers: flags=78 5(20826) t_lookup_request: start searching: hash=30016, isACK=0 5(20826) DEBUG: RFC3261 transaction matching failed 5(20826) DEBUG: t_lookup_request: no transaction found 5(20826) DEBUG:tm:t_relay: new INVITE 5(20826) parse_headers: flags=ffffffffffffffff 5(20826) check_via_address(66.192.107.225, 66.192.107.225, 0) 5(20826) WARNING:vqm_resize: resize(0) called 5(20826) DEBUG:tm:_reply_light: reply sent out. buf=0x8117e58: SIP/2.0 1..., shmem=0xb5f22a98: SIP/2.0 1 5(20826) DEBUG:tm:_reply_light: finished 5(20826) parse_headers: flags=2000 5(20826) check_via_address(66.192.107.225, 66.192.107.225, 0) 5(20826) tcp_send: no open tcp connection found, opening new one 5(20826) tcpconn_new: new tcp connection to: 66.192.106.194 5(20826) tcpconn_new: on port 5060, type 2 5(20826) tcp_send: sending... 5(20826) tcp_send: after write: c= 0xb5f44d70 n=974 fd=12 5(20826) 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=z9hG4bK0457.16a34e92.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK313e9ff7;rport=5060 From: "Jon Webster" ;tag=as5c3450e3 To: Contact: Call-ID: 4d1f33b47f8cbc2237b44eb051f1f17e@66.192.107.225 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 69 Date: Thu, 07 Dec 2006 07:19:50 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 13976 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 14142 RTP/AVP 34 a=rtpmap:34 H263/90000 5(20826) DEBUG: add_to_tail_of_timer[0]: 0xb5f4365c 5(20826) SER: new transaction fwd'ed 5(20826) DEBUG: t_newtran: msg id=3 , global msg id=3 , T on entrance=0xb5f43530 5(20826) ERROR: t_newtran: transaction already in process 0xb5f43530 5(20826) DEBUG:sl:sl_reply_error: error text is I'm terribly sorry, server error occurred (1/SL) 5(20826) parse_headers: flags=ffffffffffffffff 5(20826) check_via_address(66.192.107.225, 66.192.107.225, 0) 5(20826) DEBUG:tm:UNREF_UNSAFE: after is 0 5(20826) DEBUG:destroy_avp_list: destroying list (nil) 5(20826) receive_msg: cleaning up 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.3701 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_ser_child: read response= b5f44d70, 2, fd 25 from 5 (20826) 11(20832) tcpconn_add: hashes: 902, 8 11(20832) DBG: io_watch_add(0x80dfd20, 25, 2, 0xb5f44d70), fd_no=17 11(20832) handle_tcpconn_ev: data available on 0xb5f44d70 25 11(20832) DBG: io_watch_del (0x80dfd20, 25, -1, 0x0) fd_no=18 called 11(20832) send2child: to tcp child 0 7(20828), 0xb5f44d70 7(20828) received n=4 con=0xb5f44d70, fd=18 7(20828) DBG: io_watch_add(0x80dfe80, 18, 2, 0xb5f44d70), 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=8 global id=7 T start=0xffffffff 7(20828) parse_headers: flags=22 7(20828) parse_headers: flags=8 7(20828) DEBUG: t_reply_matching: hash 30016 label 702823009 branch 0 7(20828) DEBUG:tm:REF_UNSAFE: after is 1 7(20828) DEBUG: t_reply_matching: reply matched (T=0xb5f43530)! 7(20828) DEBUG: t_check: msg id=8 global id=8 T end=0xb5f43530 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]: 0xb5f4365c 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=3c2de362d0 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=9 global id=8 T start=0xffffffff 7(20828) parse_headers: flags=22 7(20828) parse_headers: flags=8 7(20828) DEBUG: t_reply_matching: hash 30016 label 702823009 branch 0 7(20828) DEBUG:tm:REF_UNSAFE: after is 1 7(20828) DEBUG: t_reply_matching: reply matched (T=0xb5f43530)! 7(20828) DEBUG: t_check: msg id=9 global id=9 T end=0xb5f43530 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=as5c3450e3 >, TO=;tag=3c2de362d0 >, CSEQ_N= 7(20828) tcp_send: tcp connection found (0xb5f44d70), acquiring fd 7(20828) tcp_send, c= 0xb5f44d70, n=8 11(20832) handle_ser_child: read response= b5f44d70, 1, fd -1 from 7 (20828) 7(20828) tcp_send: after receive_fd: c= 0xb5f44d70 n=4 fd=19 7(20828) tcp_send: sending... 7(20828) tcp_send: after write: c= 0xb5f44d70 n=387 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=z9hG4bK0457.16a34e92.0 From: "Jon Webster" ;tag=as5c3450e3 Call-ID: 4d1f33b47f8cbc2237b44eb051f1f17e@66.192.107.225 TO: ;tag=3c2de362d0 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: 494, new size: 432 7(20828) build_res_from_sip_res: copied size: orig:315, new: 253, rest: 179 msg= SIP/2.0 302 Moved Temporarily FROM: "Jon Webster";tag=as5c3450e3 TO: ;tag=3c2de362d0 CSEQ: 102 INVITE CALL-ID: 4d1f33b47f8cbc2237b44eb051f1f17e@66.192.107.225 MAX-FORWARDS: 70 VIA: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK313e9ff7;rport=5060 CONTENT-LENGTH: 0 SERVER: RTCC/2.0.6010.0 CONTACT: 7(20828) DEBUG: add_to_tail_of_timer[4]: 0xb5f435e0 7(20828) DEBUG: add_to_tail_of_timer[0]: 0xb5f435f0 7(20828) DEBUG:tm:relay_reply: sent buf=0x8117e58: SIP/2.0 3..., shmem=0xb5f44b58: 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 0xb5f44d70, 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 0xb5f44d70, state -1, fd=18, id=8 7(20828) extra_data (nil) 4(20825) SIP Request: 4(20825) method: 4(20825) uri: 4(20825) version: 4(20825) parse_headers: flags=2 4(20825) Found param type 232, = ; state=6 4(20825) Found param type 235, = ; state=17 4(20825) end of header reached, state=5 4(20825) parse_headers: Via found, flags=2 4(20825) parse_headers: this is the first via 4(20825) After parse_msg... 4(20825) preparing to run routing scripts... 4(20825) parse_headers: flags=8 4(20825) DEBUG: add_param: tag=3c2de362d0 4(20825) DEBUG:parse_to:end of header reached, state=29 4(20825) DBUG:parse_to: display={}, ruri={sip:666666@pbx.elephantoutlook.com:5070} 4(20825) DEBUG: get_hdr_field: [58]; uri=[sip:666666@pbx.elephantoutlook.com:5070] 4(20825) DEBUG: to body [] 4(20825) parse_headers: flags=100 4(20825) get_hdr_field: cseq : <102> 4(20825) DEBUG:maxfwd:is_maxfwd_present: value = 70 4(20825) DEBUG: add_param: tag=as5c3450e3 4(20825) DEBUG:parse_to:end of header reached, state=29 4(20825) DBUG:parse_to: display={"Jon Webster"}, ruri={sip:3149@66.192.107.225} 4(20825) ==================== === Relaying to Exchange === ==================== 4(20825) DEBUG: t_newtran: msg id=4 , global msg id=3 , T on entrance=0xffffffff 4(20825) parse_headers: flags=ffffffffffffffff 4(20825) DEBUG: get_hdr_body : content_length=0 4(20825) found end of header 4(20825) parse_headers: flags=78 4(20825) t_lookup_request: start searching: hash=30016, isACK=1 4(20825) DEBUG: RFC3261 transaction matched, tid=313e9ff7 4(20825) DEBUG:tm:REF_UNSAFE: after is 1 4(20825) DEBUG: t_lookup_request: transaction found (T=0xb5f43530) 4(20825) DEBUG: cleanup_uac_timers: RETR/FR timers reset 4(20825) DEBUG: add_to_tail_of_timer[2]: 0xb5f43578 4(20825) DEBUG: t_newtran: msg id=4 , global msg id=4 , T on entrance=0xb5f43530 4(20825) ERROR: t_newtran: transaction already in process 0xb5f43530 4(20825) DEBUG:sl:sl_reply_error: error text is I'm terribly sorry, server error occurred (1/SL) 4(20825) WARNING:sl:sl_send_reply: I won't send a reply for ACK!! 4(20825) DEBUG:tm:UNREF_UNSAFE: after is 0 4(20825) DEBUG:destroy_avp_list: destroying list (nil) 4(20825) receive_msg: cleaning up 11(20832) handle_tcp_child: reader response= b5f44d70, -1 from 0 11(20832) tcpconn_destroy: destroying connection 0xb5f44d70, flags 0002 6(20827) DEBUG: timer routine:0,tl=0xb5f435f0 next=(nil) 6(20827) DEBUG: timer routine:1,tl=0xb5f4365c next=(nil) 6(20827) DEBUG: timer routine:4,tl=0xb5f435e0 next=(nil) 6(20827) DEBUG: timer routine:2,tl=0xb5f43578 next=(nil) 6(20827) DEBUG: wait_handler : removing 0xb5f43530 from table 6(20827) DEBUG: delete transaction 0xb5f43530 6(20827) DEBUG: wait_handler : done 11(20832) handle_tcpconn_ev: data available on 0xb5f23170 23 11(20832) DBG: io_watch_del (0x80dfd20, 23, -1, 0x0) fd_no=17 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: 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=6 7(20828) extra_data (nil) 11(20832) handle_tcp_child: reader response= b5f23170, -1 from 0 11(20832) tcpconn_destroy: destroying connection 0xb5f23170, flags 0002 11(20832) tcpconn_new: new tcp connection to: 66.192.106.194 11(20832) tcpconn_new: on port 3437, type 2 11(20832) tcpconn_add: hashes: 303, 9 11(20832) handle_new_connect: new connection: 0xb5f23170 23 flags: 0002 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 Request: 7(20828) method: 7(20828) uri: 7(20828) version: 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:pbx.elephantoutlook.com:5060;transport=TCP} 7(20828) DEBUG: get_hdr_field: [50]; uri=[sip:pbx.elephantoutlook.com:5060;transport=TCP] 7(20828) DEBUG: to body [ ] 7(20828) get_hdr_field: cseq : <312> 7(20828) Found param type 232, = ; 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) preparing to run routing scripts... 7(20828) DEBUG:maxfwd:is_maxfwd_present: value = 70 7(20828) DEBUG: add_param: epid=8C-D4-0D-19-22 7(20828) DEBUG: add_param: tag=1ed053927e 7(20828) DEBUG:parse_to:end of header reached, state=29 7(20828) DBUG:parse_to: display={}, ruri={sip:eo-dev.webcode.com:5060} 7(20828) ==================== === Relaying to Asterisk === ==================== 7(20828) DEBUG: t_newtran: msg id=10 , global msg id=9 , T on entrance=0xffffffff 7(20828) parse_headers: flags=ffffffffffffffff 7(20828) DEBUG: get_hdr_body : content_length=0 7(20828) found end of header 7(20828) parse_headers: flags=78 7(20828) t_lookup_request: start searching: hash=51084, isACK=0 7(20828) DEBUG: RFC3261 transaction matching failed 7(20828) DEBUG: t_lookup_request: no transaction found 7(20828) build_req_from_req: id added: <;i=9>, rcv proto=2 7(20828) check_via_address(66.192.106.194, 66.192.106.194, 0) 7(20828) DEBUG: add_to_tail_of_timer[4]: 0xb5f4364c 7(20828) DEBUG: add_to_tail_of_timer[0]: 0xb5f4365c 7(20828) SER: new transaction fwd'ed 7(20828) DEBUG: t_newtran: msg id=10 , global msg id=10 , T on entrance=0xb5f43530 7(20828) ERROR: t_newtran: transaction already in process 0xb5f43530 7(20828) DEBUG:sl:sl_reply_error: error text is I'm terribly sorry, server error occurred (1/SL) 7(20828) parse_headers: flags=ffffffffffffffff 7(20828) check_via_address(66.192.106.194, 66.192.106.194, 0) 7(20828) tcp_send: tcp connection found (0xb5f23170), acquiring fd 7(20828) tcp_send, c= 0xb5f23170, n=8 2(20823) SIP Reply (status): 2(20823) version: 2(20823) status: <200> 2(20823) reason: 2(20823) parse_headers: flags=2 2(20823) Found param type 232, = ; state=6 2(20823) Found param type 236, = <9>; state=6 2(20823) Found param type 234, = <66.192.107.225>; state=16 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) forward_reply: found module tm, passing reply to it 2(20823) DEBUG: t_check: msg id=4 global id=3 T start=0xffffffff 2(20823) parse_headers: flags=22 2(20823) Found param type 232, = ; state=16 2(20823) end of header reached, state=5 2(20823) parse_headers: Via found, flags=22 2(20823) parse_headers: this is the second via 2(20823) DEBUG: add_param: tag=as5f48131a 2(20823) DEBUG:parse_to:end of header reached, state=29 2(20823) DBUG:parse_to: display={}, ruri={sip:pbx.elephantoutlook.com:5060;transport=TCP} 2(20823) DEBUG: get_hdr_field: [65]; uri=[sip:pbx.elephantoutlook.com:5060;transport=TCP] 2(20823) DEBUG: to body [] 2(20823) get_hdr_field: cseq : <312> 2(20823) DEBUG: t_reply_matching: hash 51084 label 12463356 branch 0 2(20823) DEBUG:tm:REF_UNSAFE: after is 2 2(20823) DEBUG: t_reply_matching: reply matched (T=0xb5f43530)! 2(20823) DEBUG: t_check: msg id=4 global id=4 T end=0xb5f43530 2(20823) DEBUG:tm:reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0) 2(20823) DEBUG:tm:t_should_relay_response: T_code=0, new_code=200 2(20823) DEBUG:tm:relay_reply: branch=0, save=0, relay=0 2(20823) parse_headers: flags=2000 2(20823) DEBUG: get_hdr_body : content_length=0 2(20823) old size: 622, new size: 528 2(20823) build_res_from_sip_res: copied size: orig:110, new: 16, rest: 512 msg= SIP/2.0 200 OK Via: SIP/2.0/TCP 66.192.106.194:3437;branch=z9hG4bKffb45234 Record-Route: From: ;epid=8C-D4-0D-19-22;tag=1ed053927e To: ;tag=as5f48131a Call-ID: 2b0405658d76427999f7dec5c813028b CSeq: 312 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 2(20823) WARNING:vqm_resize: resize(0) called 2(20823) DEBUG: add_to_tail_of_timer[2]: 0xb5f43578 2(20823) tcp_send: tcp connection found (0xb5f23170), acquiring fd 2(20823) tcp_send, c= 0xb5f23170, n=8 11(20832) handle_ser_child: read response= b5f23170, 1, fd -1 from 2 (20823) 11(20832) handle_ser_child: read response= b5f23170, 1, fd -1 from 7 (20828) 2(20823) tcp_send: after receive_fd: c= 0xb5f23170 n=4 fd=9 2(20823) tcp_send: sending... 2(20823) tcp_send: after write: c= 0xb5f23170 n=528 fd=9 2(20823) tcp_send: buf= SIP/2.0 200 OK Via: SIP/2.0/TCP 66.192.106.194:3437;branch=z9hG4bKffb45234 Record-Route: From: ;epid=8C-D4-0D-19-22;tag=1ed053927e To: ;tag=as5f48131a Call-ID: 2b0405658d76427999f7dec5c813028b CSeq: 312 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 2(20823) DEBUG:tm:relay_reply: sent buf=0x8117e58: SIP/2.0 2..., shmem=0xb5f44b58: SIP/2.0 2 2(20823) DEBUG: cleanup_uac_timers: RETR/FR timers reset 2(20823) DEBUG:tm:UNREF_UNSAFE: after is 1 2(20823) DEBUG:destroy_avp_list: destroying list (nil) 2(20823) receive_msg: cleaning up 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=651 fd=19 7(20828) tcp_send: buf= SIP/2.0 500 I'm terribly sorry, server error occurred (1/SL) FROM: ;epid=8C-D4-0D-19-22;tag=1ed053927e TO: ;tag=ff0593a3ce80005043f79ea67dccae1c.9392 CSEQ: 312 OPTIONS CALL-ID: 2b0405658d76427999f7dec5c813028b VIA: SIP/2.0/TCP 66.192.106.194:3437;branch=z9hG4bKffb45234 Server: OpenSer (1.1.0-notls (i386/linux)) Content-Length: 0 Warning: 392 66.192.107.225:5070 "Noisy feedback tells: pid=20828 req_src_ip=66.192.106.194 req_src_port=3437 in_uri=sip:pbx.elephantoutlook.com:5060;transport=TCP out_uri=sip:pbx.elephantoutlook.com:5060;transport=TCP via_cnt==1" 7(20828) DEBUG:tm:UNREF_UNSAFE: after is 0 7(20828) DEBUG:destroy_avp_list: destroying list (nil) 7(20828) receive_msg: cleaning up 6(20827) DEBUG: timer routine:0,tl=0xb5f4365c next=(nil) 6(20827) DEBUG: timer routine:4,tl=0xb5f4364c next=(nil) 11(20832) handle_tcpconn_ev: data available on 0xb5f33418 24 11(20832) DBG: io_watch_del (0x80dfd20, 24, -1, 0x0) fd_no=16 called 11(20832) send2child: to tcp child 1 8(20829), 0xb5f33418 8(20829) received n=4 con=0xb5f33418, fd=20 8(20829) DBG: io_watch_add(0x80dfe80, 20, 2, 0xb5f33418), fd_no=1 8(20829) tcp_read: EOF on 0xb5f33418, FD 20 8(20829) tcp_read_req: EOF 8(20829) DBG: io_watch_del (0x80dfe80, 20, -1, 0x10) fd_no=2 called 8(20829) releasing con 0xb5f33418, state -1, fd=20, id=7 8(20829) extra_data (nil) 11(20832) handle_tcp_child: reader response= b5f33418, -1 from 1 11(20832) tcpconn_destroy: destroying connection 0xb5f33418, flags 0002 6(20827) DEBUG: timer routine:2,tl=0xb5f43578 next=(nil) 6(20827) DEBUG: wait_handler : removing 0xb5f43530 from table 6(20827) DEBUG: delete transaction 0xb5f43530 6(20827) DEBUG: wait_handler : done 7(20828) tcp_receive_timeout: 0xb5f23170 expired (371, 372) lt=0 7(20828) DBG: io_watch_del (0x80dfe80, 18, -1, 0x10) fd_no=2 called 7(20828) releasing con 0xb5f23170, state 0, fd=18, id=9 7(20828) extra_data (nil) 11(20832) handle_tcp_child: reader response= b5f23170, 0 from 0 11(20832) DBG: io_watch_add(0x80dfd20, 23, 2, 0xb5f23170), fd_no=15 11(20832) handle_tcp_child: CONN_RELEASE 0xb5f23170 refcnt= 0 11(20832) tcpconn_new: new tcp connection to: 66.192.106.194 11(20832) tcpconn_new: on port 3446, type 2 11(20832) tcpconn_add: hashes: 308, 10 11(20832) handle_new_connect: new connection: 0xb5f33418 24 flags: 0002 11(20832) send2child: to tcp child 0 7(20828), 0xb5f33418 7(20828) received n=4 con=0xb5f33418, fd=18 7(20828) DBG: io_watch_add(0x80dfe80, 18, 2, 0xb5f33418), fd_no=1 7(20828) tcp_read_req: content-length= 0 7(20828) SIP Request: 7(20828) method: 7(20828) uri: 7(20828) version: 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:pbx.elephantoutlook.com:5060;transport=TCP} 7(20828) DEBUG: get_hdr_field: [50]; uri=[sip:pbx.elephantoutlook.com:5060;transport=TCP] 7(20828) DEBUG: to body [ ] 7(20828) get_hdr_field: cseq : <313> 7(20828) Found param type 232, = ; 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) preparing to run routing scripts... 7(20828) DEBUG:maxfwd:is_maxfwd_present: value = 70 7(20828) DEBUG: add_param: epid=8C-D4-0D-19-22 7(20828) DEBUG: add_param: tag=7e9f7b41ce 7(20828) DEBUG:parse_to:end of header reached, state=29 7(20828) DBUG:parse_to: display={}, ruri={sip:eo-dev.webcode.com:5060} 7(20828) ==================== === Relaying to Asterisk === ==================== 7(20828) DEBUG: t_newtran: msg id=11 , global msg id=10 , T on entrance=0xffffffff 7(20828) parse_headers: flags=ffffffffffffffff 7(20828) DEBUG: get_hdr_body : content_length=0 7(20828) found end of header 7(20828) parse_headers: flags=78 7(20828) t_lookup_request: start searching: hash=21177, isACK=0 7(20828) DEBUG: RFC3261 transaction matching failed 7(20828) DEBUG: t_lookup_request: no transaction found 7(20828) build_req_from_req: id added: <;i=a>, rcv proto=2 7(20828) check_via_address(66.192.106.194, 66.192.106.194, 0) 7(20828) DEBUG: add_to_tail_of_timer[4]: 0xb5f4364c 7(20828) DEBUG: add_to_tail_of_timer[0]: 0xb5f4365c 7(20828) SER: new transaction fwd'ed 7(20828) DEBUG: t_newtran: msg id=11 , global msg id=11 , T on entrance=0xb5f43530 7(20828) ERROR: t_newtran: transaction already in process 0xb5f43530 7(20828) DEBUG:sl:sl_reply_error: error text is I'm terribly sorry, server error occurred (1/SL) 7(20828) parse_headers: flags=ffffffffffffffff 7(20828) check_via_address(66.192.106.194, 66.192.106.194, 0) 7(20828) tcp_send: tcp connection found (0xb5f33418), acquiring fd 7(20828) tcp_send, c= 0xb5f33418, n=8 11(20832) handle_ser_child: read response= b5f33418, 1, fd -1 from 7 (20828) 4(20825) SIP Reply (status): 4(20825) version: 4(20825) status: <200> 4(20825) reason: 4(20825) parse_headers: flags=2 4(20825) Found param type 232, = ; state=6 4(20825) Found param type 236, = ; state=6 4(20825) Found param type 234, = <66.192.107.225>; state=16 4(20825) end of header reached, state=5 4(20825) parse_headers: Via found, flags=2 4(20825) parse_headers: this is the first via 4(20825) After parse_msg... 4(20825) forward_reply: found module tm, passing reply to it 4(20825) DEBUG: t_check: msg id=5 global id=4 T start=0xffffffff 4(20825) parse_headers: flags=22 4(20825) Found param type 232, = ; state=16 4(20825) end of header reached, state=5 4(20825) parse_headers: Via found, flags=22 4(20825) parse_headers: this is the second via 4(20825) DEBUG: add_param: tag=as5b3ab11b 4(20825) DEBUG:parse_to:end of header reached, state=29 4(20825) DBUG:parse_to: display={}, ruri={sip:pbx.elephantoutlook.com:5060;transport=TCP} 4(20825) DEBUG: get_hdr_field: [65]; uri=[sip:pbx.elephantoutlook.com:5060;transport=TCP] 4(20825) DEBUG: to body [] 4(20825) get_hdr_field: cseq : <313> 4(20825) DEBUG: t_reply_matching: hash 21177 label 568187708 branch 0 4(20825) DEBUG:tm:REF_UNSAFE: after is 2 4(20825) DEBUG: t_reply_matching: reply matched (T=0xb5f43530)! 4(20825) DEBUG: t_check: msg id=5 global id=5 T end=0xb5f43530 4(20825) DEBUG:tm:reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0) 4(20825) DEBUG:tm:t_should_relay_response: T_code=0, new_code=200 4(20825) DEBUG:tm:relay_reply: branch=0, save=0, relay=0 4(20825) parse_headers: flags=2000 4(20825) DEBUG: get_hdr_body : content_length=0 4(20825) old size: 624, new size: 528 4(20825) build_res_from_sip_res: copied size: orig:112, new: 16, rest: 512 msg= SIP/2.0 200 OK Via: SIP/2.0/TCP 66.192.106.194:3446;branch=z9hG4bK68c390d5 Record-Route: From: ;epid=8C-D4-0D-19-22;tag=7e9f7b41ce To: ;tag=as5b3ab11b Call-ID: b63c8e8c7d6c40f8825c34c689937a10 CSeq: 313 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 4(20825) WARNING:vqm_resize: resize(0) called 4(20825) DEBUG: add_to_tail_of_timer[2]: 0xb5f43578 4(20825) tcp_send: tcp connection found (0xb5f33418), acquiring fd 4(20825) tcp_send, c= 0xb5f33418, n=8 7(20828) tcp_send: after receive_fd: c= 0xb5f33418 n=4 fd=19 7(20828) tcp_send: sending... 7(20828) tcp_send: after write: c= 0xb5f33418 n=651 fd=19 7(20828) tcp_send: buf= SIP/2.0 500 I'm terribly sorry, server error occurred (1/SL) FROM: ;epid=8C-D4-0D-19-22;tag=7e9f7b41ce TO: ;tag=ff0593a3ce80005043f79ea67dccae1c.e648 CSEQ: 313 OPTIONS CALL-ID: b63c8e8c7d6c40f8825c34c689937a10 VIA: SIP/2.0/TCP 66.192.106.194:3446;branch=z9hG4bK68c390d5 Server: OpenSer (1.1.0-notls (i386/linux)) Content-Length: 0 Warning: 392 66.192.107.225:5070 "Noisy feedback tells: pid=20828 req_src_ip=66.192.106.194 req_src_port=3446 in_uri=sip:pbx.elephantoutlook.com:5060;transport=TCP out_uri=sip:pbx.elephantoutlook.com:5060;transport=TCP via_cnt==1" 7(20828) DEBUG:tm:UNREF_UNSAFE: after is 1 7(20828) DEBUG:destroy_avp_list: destroying list (nil) 7(20828) receive_msg: cleaning up 11(20832) handle_ser_child: read response= b5f33418, 1, fd -1 from 4 (20825) 4(20825) tcp_send: after receive_fd: c= 0xb5f33418 n=4 fd=11 4(20825) tcp_send: sending... 4(20825) tcp_send: after write: c= 0xb5f33418 n=528 fd=11 4(20825) tcp_send: buf= SIP/2.0 200 OK Via: SIP/2.0/TCP 66.192.106.194:3446;branch=z9hG4bK68c390d5 Record-Route: From: ;epid=8C-D4-0D-19-22;tag=7e9f7b41ce To: ;tag=as5b3ab11b Call-ID: b63c8e8c7d6c40f8825c34c689937a10 CSeq: 313 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 4(20825) DEBUG:tm:relay_reply: sent buf=0x8117e58: SIP/2.0 2..., shmem=0xb5f44b58: SIP/2.0 2 4(20825) DEBUG: cleanup_uac_timers: RETR/FR timers reset 4(20825) DEBUG:tm:UNREF_UNSAFE: after is 0 4(20825) DEBUG:destroy_avp_list: destroying list (nil) 4(20825) receive_msg: cleaning up 6(20827) DEBUG: timer routine:0,tl=0xb5f4365c next=(nil) 6(20827) DEBUG: timer routine:4,tl=0xb5f4364c next=(nil) 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 1 8(20829), 0xb5f23170 8(20829) received n=4 con=0xb5f23170, fd=20 8(20829) DBG: io_watch_add(0x80dfe80, 20, 2, 0xb5f23170), fd_no=1 8(20829) tcp_read: EOF on 0xb5f23170, FD 20 8(20829) tcp_read_req: EOF 8(20829) DBG: io_watch_del (0x80dfe80, 20, -1, 0x10) fd_no=2 called 8(20829) releasing con 0xb5f23170, state -1, fd=20, id=9 8(20829) extra_data (nil) 11(20832) handle_tcp_child: reader response= b5f23170, -1 from 1 11(20832) tcpconn_destroy: destroying connection 0xb5f23170, flags 0002 6(20827) DEBUG: timer routine:2,tl=0xb5f43578 next=(nil) 6(20827) DEBUG: wait_handler : removing 0xb5f43530 from table 6(20827) DEBUG: delete transaction 0xb5f43530 6(20827) DEBUG: wait_handler : done 7(20828) tcp_receive_timeout: 0xb5f33418 expired (431, 432) lt=0 7(20828) DBG: io_watch_del (0x80dfe80, 18, -1, 0x10) fd_no=2 called 7(20828) releasing con 0xb5f33418, state 0, fd=18, id=10 7(20828) extra_data (nil) 11(20832) handle_tcp_child: reader response= b5f33418, 0 from 0 11(20832) DBG: io_watch_add(0x80dfd20, 24, 2, 0xb5f33418), fd_no=15 11(20832) handle_tcp_child: CONN_RELEASE 0xb5f33418 refcnt= 0 11(20832) tcpconn_new: new tcp connection to: 66.192.106.194 11(20832) tcpconn_new: on port 3453, type 2 11(20832) tcpconn_add: hashes: 319, 11 11(20832) handle_new_connect: new connection: 0xb5f23170 23 flags: 0002 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 Request: 7(20828) method: 7(20828) uri: 7(20828) version: 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:pbx.elephantoutlook.com:5060;transport=TCP} 7(20828) DEBUG: get_hdr_field: [50]; uri=[sip:pbx.elephantoutlook.com:5060;transport=TCP] 7(20828) DEBUG: to body [ ] 7(20828) get_hdr_field: cseq : <314> 7(20828) Found param type 232, = ; 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) preparing to run routing scripts... 7(20828) DEBUG:maxfwd:is_maxfwd_present: value = 70 7(20828) DEBUG: add_param: epid=8C-D4-0D-19-22 7(20828) DEBUG: add_param: tag=8a6030c58c 7(20828) DEBUG:parse_to:end of header reached, state=29 7(20828) DBUG:parse_to: display={}, ruri={sip:eo-dev.webcode.com:5060} 7(20828) ==================== === Relaying to Asterisk === ==================== 7(20828) DEBUG: t_newtran: msg id=12 , global msg id=11 , T on entrance=0xffffffff 7(20828) parse_headers: flags=ffffffffffffffff 7(20828) DEBUG: get_hdr_body : content_length=0 7(20828) found end of header 7(20828) parse_headers: flags=78 7(20828) t_lookup_request: start searching: hash=59279, isACK=0 7(20828) DEBUG: RFC3261 transaction matching failed 7(20828) DEBUG: t_lookup_request: no transaction found 7(20828) build_req_from_req: id added: <;i=b>, rcv proto=2 7(20828) check_via_address(66.192.106.194, 66.192.106.194, 0) 7(20828) DEBUG: add_to_tail_of_timer[4]: 0xb5f4364c 7(20828) DEBUG: add_to_tail_of_timer[0]: 0xb5f4365c 7(20828) SER: new transaction fwd'ed 7(20828) DEBUG: t_newtran: msg id=12 , global msg id=12 , T on entrance=0xb5f43530 7(20828) ERROR: t_newtran: transaction already in process 0xb5f43530 7(20828) DEBUG:sl:sl_reply_error: error text is I'm terribly sorry, server error occurred (1/SL) 7(20828) parse_headers: flags=ffffffffffffffff 7(20828) check_via_address(66.192.106.194, 66.192.106.194, 0) 7(20828) tcp_send: tcp connection found (0xb5f23170), acquiring fd 7(20828) tcp_send, c= 0xb5f23170, n=8 3(20824) SIP Reply (status): 3(20824) version: 3(20824) status: <200> 3(20824) reason: 3(20824) parse_headers: flags=2 3(20824) Found param type 232, = ; state=6 3(20824) Found param type 236, = ; state=6 3(20824) Found param type 234, = <66.192.107.225>; state=16 3(20824) end of header reached, state=5 3(20824) parse_headers: Via found, flags=2 3(20824) parse_headers: this is the first via 3(20824) After parse_msg... 3(20824) forward_reply: found module tm, passing reply to it 3(20824) DEBUG: t_check: msg id=4 global id=3 T start=0xffffffff 3(20824) parse_headers: flags=22 3(20824) Found param type 232, = ; state=16 3(20824) end of header reached, state=5 3(20824) parse_headers: Via found, flags=22 3(20824) parse_headers: this is the second via 3(20824) DEBUG: add_param: tag=as4226570b 3(20824) DEBUG:parse_to:end of header reached, state=29 3(20824) DBUG:parse_to: display={}, ruri={sip:pbx.elephantoutlook.com:5060;transport=TCP} 3(20824) DEBUG: get_hdr_field: [65]; uri=[sip:pbx.elephantoutlook.com:5060;transport=TCP] 3(20824) DEBUG: to body [] 3(20824) get_hdr_field: cseq : <314> 3(20824) DEBUG: t_reply_matching: hash 59279 label 564567733 branch 0 3(20824) DEBUG:tm:REF_UNSAFE: after is 2 3(20824) DEBUG: t_reply_matching: reply matched (T=0xb5f43530)! 3(20824) DEBUG: t_check: msg id=4 global id=4 T end=0xb5f43530 3(20824) DEBUG:tm:reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0) 3(20824) DEBUG:tm:t_should_relay_response: T_code=0, new_code=200 3(20824) DEBUG:tm:relay_reply: branch=0, save=0, relay=0 3(20824) parse_headers: flags=2000 3(20824) DEBUG: get_hdr_body : content_length=0 3(20824) old size: 624, new size: 528 3(20824) build_res_from_sip_res: copied size: orig:112, new: 16, rest: 512 msg= SIP/2.0 200 OK Via: SIP/2.0/TCP 66.192.106.194:3453;branch=z9hG4bK197a6ad9 Record-Route: From: ;epid=8C-D4-0D-19-22;tag=8a6030c58c To: ;tag=as4226570b Call-ID: 238060bb462b4b6fbdee9352fb924389 CSeq: 314 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 3(20824) WARNING:vqm_resize: resize(0) called 3(20824) DEBUG: add_to_tail_of_timer[2]: 0xb5f43578 3(20824) tcp_send: tcp connection found (0xb5f23170), acquiring fd 3(20824) tcp_send, c= 0xb5f23170, n=8 11(20832) handle_ser_child: read response= b5f23170, 1, fd -1 from 3 (20824) 11(20832) handle_ser_child: read response= b5f23170, 1, fd -1 from 7 (20828) 3(20824) tcp_send: after receive_fd: c= 0xb5f23170 n=4 fd=10 3(20824) tcp_send: sending... 3(20824) tcp_send: after write: c= 0xb5f23170 n=528 fd=10 3(20824) tcp_send: buf= SIP/2.0 200 OK Via: SIP/2.0/TCP 66.192.106.194:3453;branch=z9hG4bK197a6ad9 Record-Route: From: ;epid=8C-D4-0D-19-22;tag=8a6030c58c To: ;tag=as4226570b Call-ID: 238060bb462b4b6fbdee9352fb924389 CSeq: 314 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 3(20824) DEBUG:tm:relay_reply: sent buf=0x8117c18: SIP/2.0 2..., shmem=0xb5f44b58: SIP/2.0 2 3(20824) DEBUG: cleanup_uac_timers: RETR/FR timers reset 3(20824) DEBUG:tm:UNREF_UNSAFE: after is 1 3(20824) DEBUG:destroy_avp_list: destroying list (nil) 3(20824) receive_msg: cleaning up 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=651 fd=19 7(20828) tcp_send: buf= SIP/2.0 500 I'm terribly sorry, server error occurred (1/SL) FROM: ;epid=8C-D4-0D-19-22;tag=8a6030c58c TO: ;tag=ff0593a3ce80005043f79ea67dccae1c.543a CSEQ: 314 OPTIONS CALL-ID: 238060bb462b4b6fbdee9352fb924389 VIA: SIP/2.0/TCP 66.192.106.194:3453;branch=z9hG4bK197a6ad9 Server: OpenSer (1.1.0-notls (i386/linux)) Content-Length: 0 Warning: 392 66.192.107.225:5070 "Noisy feedback tells: pid=20828 req_src_ip=66.192.106.194 req_src_port=3453 in_uri=sip:pbx.elephantoutlook.com:5060;transport=TCP out_uri=sip:pbx.elephantoutlook.com:5060;transport=TCP via_cnt==1" 7(20828) DEBUG:tm:UNREF_UNSAFE: after is 0 7(20828) DEBUG:destroy_avp_list: destroying list (nil) 7(20828) receive_msg: cleaning up 6(20827) DEBUG: timer routine:0,tl=0xb5f4365c next=(nil) 6(20827) DEBUG: timer routine:4,tl=0xb5f4364c next=(nil) 11(20832) handle_tcpconn_ev: data available on 0xb5f33418 24 11(20832) DBG: io_watch_del (0x80dfd20, 24, -1, 0x0) fd_no=16 called 11(20832) send2child: to tcp child 1 8(20829), 0xb5f33418 8(20829) received n=4 con=0xb5f33418, fd=20 8(20829) DBG: io_watch_add(0x80dfe80, 20, 2, 0xb5f33418), fd_no=1 8(20829) tcp_read: EOF on 0xb5f33418, FD 20 8(20829) tcp_read_req: EOF 8(20829) DBG: io_watch_del (0x80dfe80, 20, -1, 0x10) fd_no=2 called 8(20829) releasing con 0xb5f33418, state -1, fd=20, id=10 8(20829) extra_data (nil) 11(20832) handle_tcp_child: reader response= b5f33418, -1 from 1 11(20832) tcpconn_destroy: destroying connection 0xb5f33418, flags 0002 6(20827) DEBUG: timer routine:2,tl=0xb5f43578 next=(nil) 6(20827) DEBUG: wait_handler : removing 0xb5f43530 from table 6(20827) DEBUG: delete transaction 0xb5f43530 6(20827) DEBUG: wait_handler : done 7(20828) tcp_receive_timeout: 0xb5f23170 expired (491, 492) lt=0 7(20828) DBG: io_watch_del (0x80dfe80, 18, -1, 0x10) fd_no=2 called 7(20828) releasing con 0xb5f23170, state 0, fd=18, id=11 7(20828) extra_data (nil) 11(20832) handle_tcp_child: reader response= b5f23170, 0 from 0 11(20832) DBG: io_watch_add(0x80dfd20, 23, 2, 0xb5f23170), fd_no=15 11(20832) handle_tcp_child: CONN_RELEASE 0xb5f23170 refcnt= 0 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 Request: 7(20828) method: 7(20828) uri: 7(20828) version: 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:pbx.elephantoutlook.com:5060;transport=TCP} 7(20828) DEBUG: get_hdr_field: [50]; uri=[sip:pbx.elephantoutlook.com:5060;transport=TCP] 7(20828) DEBUG: to body [ ] 7(20828) get_hdr_field: cseq : <315> 7(20828) Found param type 232, = ; 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) preparing to run routing scripts... 7(20828) DEBUG:maxfwd:is_maxfwd_present: value = 70 7(20828) DEBUG: add_param: epid=8C-D4-0D-19-22 7(20828) DEBUG: add_param: tag=823640edad 7(20828) DEBUG:parse_to:end of header reached, state=29 7(20828) DBUG:parse_to: display={}, ruri={sip:eo-dev.webcode.com:5060} 7(20828) ==================== === Relaying to Asterisk === ==================== 7(20828) DEBUG: t_newtran: msg id=13 , global msg id=12 , T on entrance=0xffffffff 7(20828) parse_headers: flags=ffffffffffffffff 7(20828) DEBUG: get_hdr_body : content_length=0 7(20828) found end of header 7(20828) parse_headers: flags=78 7(20828) t_lookup_request: start searching: hash=53057, isACK=0 7(20828) DEBUG: RFC3261 transaction matching failed 7(20828) DEBUG: t_lookup_request: no transaction found 7(20828) build_req_from_req: id added: <;i=b>, rcv proto=2 7(20828) check_via_address(66.192.106.194, 66.192.106.194, 0) 7(20828) DEBUG: add_to_tail_of_timer[4]: 0xb5f4364c 7(20828) DEBUG: add_to_tail_of_timer[0]: 0xb5f4365c 7(20828) SER: new transaction fwd'ed 7(20828) DEBUG: t_newtran: msg id=13 , global msg id=13 , T on entrance=0xb5f43530 7(20828) ERROR: t_newtran: transaction already in process 0xb5f43530 7(20828) DEBUG:sl:sl_reply_error: error text is I'm terribly sorry, server error occurred (1/SL) 7(20828) parse_headers: flags=ffffffffffffffff 7(20828) check_via_address(66.192.106.194, 66.192.106.194, 0) 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) 5(20826) SIP Reply (status): 5(20826) version: 5(20826) status: <200> 5(20826) reason: 5(20826) parse_headers: flags=2 5(20826) Found param type 232, = ; state=6 5(20826) Found param type 236, = ; state=6 5(20826) Found param type 234, = <66.192.107.225>; state=16 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) forward_reply: found module tm, passing reply to it 5(20826) DEBUG: t_check: msg id=5 global id=3 T start=0xffffffff 5(20826) parse_headers: flags=22 5(20826) Found param type 232, = ; state=16 5(20826) end of header reached, state=5 5(20826) parse_headers: Via found, flags=22 5(20826) parse_headers: this is the second via 5(20826) DEBUG: add_param: tag=as5fb44801 5(20826) DEBUG:parse_to:end of header reached, state=29 5(20826) DBUG:parse_to: display={}, ruri={sip:pbx.elephantoutlook.com:5060;transport=TCP} 5(20826) DEBUG: get_hdr_field: [65]; uri=[sip:pbx.elephantoutlook.com:5060;transport=TCP] 5(20826) DEBUG: to body [] 5(20826) get_hdr_field: cseq : <315> 5(20826) DEBUG: t_reply_matching: hash 53057 label 1092942253 branch 0 5(20826) DEBUG:tm:REF_UNSAFE: after is 2 5(20826) DEBUG: t_reply_matching: reply matched (T=0xb5f43530)! 5(20826) DEBUG: t_check: msg id=5 global id=5 T end=0xb5f43530 5(20826) DEBUG:tm:reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0) 5(20826) DEBUG:tm:t_should_relay_response: T_code=0, new_code=200 5(20826) DEBUG:tm:relay_reply: branch=0, save=0, relay=0 5(20826) parse_headers: flags=2000 5(20826) DEBUG: get_hdr_body : content_length=0 5(20826) old size: 624, new size: 528 5(20826) build_res_from_sip_res: copied size: orig:112, new: 16, rest: 512 msg= SIP/2.0 200 OK Via: SIP/2.0/TCP 66.192.106.194:3453;branch=z9hG4bK7c8ef656 Record-Route: From: ;epid=8C-D4-0D-19-22;tag=823640edad To: ;tag=as5fb44801 Call-ID: 1a7698dc0e9f4232a32992781774f25b CSeq: 315 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 5(20826) WARNING:vqm_resize: resize(0) called 5(20826) DEBUG: add_to_tail_of_timer[2]: 0xb5f43578 5(20826) tcp_send: tcp connection found (0xb5f23170), acquiring fd 5(20826) tcp_send, c= 0xb5f23170, n=8 11(20832) handle_ser_child: read response= b5f23170, 1, fd -1 from 5 (20826) 5(20826) tcp_send: after receive_fd: c= 0xb5f23170 n=4 fd=12 5(20826) tcp_send: sending... 5(20826) tcp_send: after write: c= 0xb5f23170 n=528 fd=12 5(20826) tcp_send: buf= SIP/2.0 200 OK Via: SIP/2.0/TCP 66.192.106.194:3453;branch=z9hG4bK7c8ef656 Record-Route: From: ;epid=8C-D4-0D-19-22;tag=823640edad To: ;tag=as5fb44801 Call-ID: 1a7698dc0e9f4232a32992781774f25b CSeq: 315 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 5(20826) DEBUG:tm:relay_reply: sent buf=0x81180b8: SIP/2.0 2..., shmem=0xb5f44b58: SIP/2.0 2 5(20826) DEBUG: cleanup_uac_timers: RETR/FR timers reset 5(20826) DEBUG:tm:UNREF_UNSAFE: after is 1 5(20826) DEBUG:destroy_avp_list: destroying list (nil) 5(20826) receive_msg: cleaning up 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=651 fd=19 7(20828) tcp_send: buf= SIP/2.0 500 I'm terribly sorry, server error occurred (1/SL) FROM: ;epid=8C-D4-0D-19-22;tag=823640edad TO: ;tag=ff0593a3ce80005043f79ea67dccae1c.dddd CSEQ: 315 OPTIONS CALL-ID: 1a7698dc0e9f4232a32992781774f25b VIA: SIP/2.0/TCP 66.192.106.194:3453;branch=z9hG4bK7c8ef656 Server: OpenSer (1.1.0-notls (i386/linux)) Content-Length: 0 Warning: 392 66.192.107.225:5070 "Noisy feedback tells: pid=20828 req_src_ip=66.192.106.194 req_src_port=3453 in_uri=sip:pbx.elephantoutlook.com:5060;transport=TCP out_uri=sip:pbx.elephantoutlook.com:5060;transport=TCP via_cnt==1" 7(20828) DEBUG:tm:UNREF_UNSAFE: after is 0 7(20828) DEBUG:destroy_avp_list: destroying list (nil) 7(20828) receive_msg: cleaning up 6(20827) DEBUG: timer routine:0,tl=0xb5f4365c next=(nil) 6(20827) DEBUG: timer routine:4,tl=0xb5f4364c next=(nil) 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=11 7(20828) extra_data (nil) 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:2,tl=0xb5f43578 next=(nil) 6(20827) DEBUG: wait_handler : removing 0xb5f43530 from table 6(20827) DEBUG: delete transaction 0xb5f43530 6(20827) DEBUG: wait_handler : done 11(20832) tcpconn_new: new tcp connection to: 66.192.106.194 11(20832) tcpconn_new: on port 3462, type 2 11(20832) tcpconn_add: hashes: 452, 12 11(20832) handle_new_connect: new connection: 0xb5f23170 23 flags: 0002 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 Request: 7(20828) method: 7(20828) uri: 7(20828) version: 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:pbx.elephantoutlook.com:5060;transport=TCP} 7(20828) DEBUG: get_hdr_field: [50]; uri=[sip:pbx.elephantoutlook.com:5060;transport=TCP] 7(20828) DEBUG: to body [ ] 7(20828) get_hdr_field: cseq : <316> 7(20828) Found param type 232, = ; 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) preparing to run routing scripts... 7(20828) DEBUG:maxfwd:is_maxfwd_present: value = 70 7(20828) DEBUG: add_param: epid=8C-D4-0D-19-22 7(20828) DEBUG: add_param: tag=aec54a587 7(20828) DEBUG:parse_to:end of header reached, state=29 7(20828) DBUG:parse_to: display={}, ruri={sip:eo-dev.webcode.com:5060} 7(20828) ==================== === Relaying to Asterisk === ==================== 7(20828) DEBUG: t_newtran: msg id=14 , global msg id=13 , T on entrance=0xffffffff 7(20828) parse_headers: flags=ffffffffffffffff 7(20828) DEBUG: get_hdr_body : content_length=0 7(20828) found end of header 7(20828) parse_headers: flags=78 7(20828) t_lookup_request: start searching: hash=49203, isACK=0 7(20828) DEBUG: RFC3261 transaction matching failed 7(20828) DEBUG: t_lookup_request: no transaction found 7(20828) build_req_from_req: id added: <;i=c>, rcv proto=2 7(20828) check_via_address(66.192.106.194, 66.192.106.194, 0) 7(20828) DEBUG: add_to_tail_of_timer[4]: 0xb5f4364c 7(20828) DEBUG: add_to_tail_of_timer[0]: 0xb5f4365c 7(20828) SER: new transaction fwd'ed 7(20828) DEBUG: t_newtran: msg id=14 , global msg id=14 , T on entrance=0xb5f43530 7(20828) ERROR: t_newtran: transaction already in process 0xb5f43530 7(20828) DEBUG:sl:sl_reply_error: error text is I'm terribly sorry, server error occurred (1/SL) 7(20828) parse_headers: flags=ffffffffffffffff 7(20828) check_via_address(66.192.106.194, 66.192.106.194, 0) 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) 2(20823) SIP Reply (status): 2(20823) version: 2(20823) status: <200> 2(20823) reason: 2(20823) parse_headers: flags=2 2(20823) Found param type 232, = ; state=6 2(20823) Found param type 236, = ; state=6 2(20823) Found param type 234, = <66.192.107.225>; state=16 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) forward_reply: found module tm, passing reply to it 2(20823) DEBUG: t_check: msg id=5 global id=4 T start=0xffffffff 2(20823) parse_headers: flags=22 2(20823) Found param type 232, = ; state=16 2(20823) end of header reached, state=5 2(20823) parse_headers: Via found, flags=22 2(20823) parse_headers: this is the second via 2(20823) DEBUG: add_param: tag=as433af07b 2(20823) DEBUG:parse_to:end of header reached, state=29 2(20823) DBUG:parse_to: display={}, ruri={sip:pbx.elephantoutlook.com:5060;transport=TCP} 2(20823) DEBUG: get_hdr_field: [65]; uri=[sip:pbx.elephantoutlook.com:5060;transport=TCP] 2(20823) DEBUG: to body [] 2(20823) get_hdr_field: cseq : <316> 2(20823) DEBUG: t_reply_matching: hash 49203 label 822806759 branch 0 2(20823) DEBUG:tm:REF_UNSAFE: after is 2 2(20823) DEBUG: t_reply_matching: reply matched (T=0xb5f43530)! 2(20823) DEBUG: t_check: msg id=5 global id=5 T end=0xb5f43530 2(20823) DEBUG:tm:reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0) 2(20823) DEBUG:tm:t_should_relay_response: T_code=0, new_code=200 2(20823) DEBUG:tm:relay_reply: branch=0, save=0, relay=0 2(20823) parse_headers: flags=2000 2(20823) DEBUG: get_hdr_body : content_length=0 2(20823) old size: 622, new size: 526 2(20823) build_res_from_sip_res: copied size: orig:112, new: 16, rest: 510 msg= SIP/2.0 200 OK Via: SIP/2.0/TCP 66.192.106.194:3462;branch=z9hG4bK3de82c5d Record-Route: From: ;epid=8C-D4-0D-19-22;tag=aec54a587 To: ;tag=as433af07b Call-ID: 20e728d968b34c37ac78bd1b89bc1e8e CSeq: 316 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 2(20823) WARNING:vqm_resize: resize(0) called 2(20823) DEBUG: add_to_tail_of_timer[2]: 0xb5f43578 2(20823) tcp_send: tcp connection found (0xb5f23170), acquiring fd 2(20823) tcp_send, c= 0xb5f23170, n=8 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=650 fd=19 7(20828) tcp_send: buf= SIP/2.0 500 I'm terribly sorry, server error occurred (1/SL) FROM: ;epid=8C-D4-0D-19-22;tag=aec54a587 TO: ;tag=ff0593a3ce80005043f79ea67dccae1c.182a CSEQ: 316 OPTIONS CALL-ID: 20e728d968b34c37ac78bd1b89bc1e8e VIA: SIP/2.0/TCP 66.192.106.194:3462;branch=z9hG4bK3de82c5d Server: OpenSer (1.1.0-notls (i386/linux)) Content-Length: 0 Warning: 392 66.192.107.225:5070 "Noisy feedback tells: pid=20828 req_src_ip=66.192.106.194 req_src_port=3462 in_uri=sip:pbx.elephantoutlook.com:5060;transport=TCP out_uri=sip:pbx.elephantoutlook.com:5060;transport=TCP via_cnt==1" 7(20828) DEBUG:tm:UNREF_UNSAFE: after is 1 7(20828) DEBUG:destroy_avp_list: destroying list (nil) 7(20828) receive_msg: cleaning up 11(20832) handle_ser_child: read response= b5f23170, 1, fd -1 from 2 (20823) 2(20823) tcp_send: after receive_fd: c= 0xb5f23170 n=4 fd=9 2(20823) tcp_send: sending... 2(20823) tcp_send: after write: c= 0xb5f23170 n=526 fd=9 2(20823) tcp_send: buf= SIP/2.0 200 OK Via: SIP/2.0/TCP 66.192.106.194:3462;branch=z9hG4bK3de82c5d Record-Route: From: ;epid=8C-D4-0D-19-22;tag=aec54a587 To: ;tag=as433af07b Call-ID: 20e728d968b34c37ac78bd1b89bc1e8e CSeq: 316 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 2(20823) DEBUG:tm:relay_reply: sent buf=0x8117e58: SIP/2.0 2..., shmem=0xb5f44b58: SIP/2.0 2 2(20823) DEBUG: cleanup_uac_timers: RETR/FR timers reset 2(20823) DEBUG:tm:UNREF_UNSAFE: after is 0 2(20823) DEBUG:destroy_avp_list: destroying list (nil) 2(20823) receive_msg: cleaning up 6(20827) DEBUG: timer routine:0,tl=0xb5f4365c next=(nil) 6(20827) DEBUG: timer routine:4,tl=0xb5f4364c next=(nil) 6(20827) DEBUG: timer routine:2,tl=0xb5f43578 next=(nil) 6(20827) DEBUG: wait_handler : removing 0xb5f43530 from table 6(20827) DEBUG: delete transaction 0xb5f43530 6(20827) DEBUG: wait_handler : done 7(20828) tcp_receive_timeout: 0xb5f23170 expired (610, 611) lt=0 7(20828) DBG: io_watch_del (0x80dfe80, 18, -1, 0x10) fd_no=2 called 7(20828) releasing con 0xb5f23170, state 0, fd=18, id=12 7(20828) extra_data (nil) 11(20832) handle_tcp_child: reader response= b5f23170, 0 from 0 11(20832) DBG: io_watch_add(0x80dfd20, 23, 2, 0xb5f23170), fd_no=15 11(20832) handle_tcp_child: CONN_RELEASE 0xb5f23170 refcnt= 0 11(20832) tcpconn_new: new tcp connection to: 66.192.106.194 11(20832) tcpconn_new: on port 3464, type 2 11(20832) tcpconn_add: hashes: 458, 13 11(20832) handle_new_connect: new connection: 0xb5f33418 24 flags: 0002 11(20832) send2child: to tcp child 0 7(20828), 0xb5f33418 7(20828) received n=4 con=0xb5f33418, fd=18 7(20828) DBG: io_watch_add(0x80dfe80, 18, 2, 0xb5f33418), fd_no=1 7(20828) tcp_read_req: content-length= 0 7(20828) SIP Request: 7(20828) method: 7(20828) uri: 7(20828) version: 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:pbx.elephantoutlook.com:5060;transport=TCP} 7(20828) DEBUG: get_hdr_field: [50]; uri=[sip:pbx.elephantoutlook.com:5060;transport=TCP] 7(20828) DEBUG: to body [ ] 7(20828) get_hdr_field: cseq : <317> 7(20828) Found param type 232, = ; 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) preparing to run routing scripts... 7(20828) DEBUG:maxfwd:is_maxfwd_present: value = 70 7(20828) DEBUG: add_param: epid=8C-D4-0D-19-22 7(20828) DEBUG: add_param: tag=9c62043b0 7(20828) DEBUG:parse_to:end of header reached, state=29 7(20828) DBUG:parse_to: display={}, ruri={sip:eo-dev.webcode.com:5060} 7(20828) ==================== === Relaying to Asterisk === ==================== 7(20828) DEBUG: t_newtran: msg id=15 , global msg id=14 , T on entrance=0xffffffff 7(20828) parse_headers: flags=ffffffffffffffff 7(20828) DEBUG: get_hdr_body : content_length=0 7(20828) found end of header 7(20828) parse_headers: flags=78 7(20828) t_lookup_request: start searching: hash=60250, isACK=0 7(20828) DEBUG: RFC3261 transaction matching failed 7(20828) DEBUG: t_lookup_request: no transaction found 7(20828) build_req_from_req: id added: <;i=d>, rcv proto=2 7(20828) check_via_address(66.192.106.194, 66.192.106.194, 0) 7(20828) DEBUG: add_to_tail_of_timer[4]: 0xb5f4364c 7(20828) DEBUG: add_to_tail_of_timer[0]: 0xb5f4365c 7(20828) SER: new transaction fwd'ed 7(20828) DEBUG: t_newtran: msg id=15 , global msg id=15 , T on entrance=0xb5f43530 7(20828) ERROR: t_newtran: transaction already in process 0xb5f43530 7(20828) DEBUG:sl:sl_reply_error: error text is I'm terribly sorry, server error occurred (1/SL) 7(20828) parse_headers: flags=ffffffffffffffff 7(20828) check_via_address(66.192.106.194, 66.192.106.194, 0) 7(20828) tcp_send: tcp connection found (0xb5f33418), acquiring fd 7(20828) tcp_send, c= 0xb5f33418, n=8 11(20832) handle_ser_child: read response= b5f33418, 1, fd -1 from 7 (20828) 4(20825) 7(20828) SIP Reply (status): 4(20825) version: 4(20825) status: <200> 4(20825) reason: 4(20825) parse_headers: flags=2 4(20825) Found param type 232, = ; state=6 tcp_send: after receive_fd: c= 0xb5f33418 n=4 fd=19 7(20828) tcp_send: sending... 7(20828) tcp_send: after write: c= 0xb5f33418 n=650 fd=19 7(20828) tcp_send: buf= SIP/2.0 500 I'm terribly sorry, server error occurred (1/SL) FROM: ;epid=8C-D4-0D-19-22;tag=9c62043b0 TO: ;tag=ff0593a3ce80005043f79ea67dccae1c.757e CSEQ: 317 OPTIONS CALL-ID: 6aea8d3d32fb4261ad3a96f91803aa89 VIA: SIP/2.0/TCP 66.192.106.194:3464;branch=z9hG4bK1223ffb5 Server: OpenSer (1.1.0-notls (i386/linux)) Content-Length: 0 Warning: 392 66.192.107.225:5070 "Noisy feedback tells: pid=20828 req_src_ip=66.192.106.194 req_src_port=3464 in_uri=sip:pbx.elephantoutlook.com:5060;transport=TCP out_uri=sip:pbx.elephantoutlook.com:5060;transport=TCP via_cnt==1" 7(20828) DEBUG:tm:UNREF_UNSAFE: after is 0 7(20828) DEBUG:destroy_avp_list: destroying list (nil) 7(20828) receive_msg: cleaning up 4(20825) Found param type 236, = ; state=6 4(20825) Found param type 234, = <66.192.107.225>; state=16 4(20825) end of header reached, state=5 4(20825) parse_headers: Via found, flags=2 4(20825) parse_headers: this is the first via 4(20825) After parse_msg... 4(20825) forward_reply: found module tm, passing reply to it 4(20825) DEBUG: t_check: msg id=6 global id=5 T start=0xffffffff 4(20825) parse_headers: flags=22 4(20825) Found param type 232, = ; state=16 4(20825) end of header reached, state=5 4(20825) parse_headers: Via found, flags=22 4(20825) parse_headers: this is the second via 4(20825) DEBUG: add_param: tag=as467485c4 4(20825) DEBUG:parse_to:end of header reached, state=29 4(20825) DBUG:parse_to: display={}, ruri={sip:pbx.elephantoutlook.com:5060;transport=TCP} 4(20825) DEBUG: get_hdr_field: [65]; uri=[sip:pbx.elephantoutlook.com:5060;transport=TCP] 4(20825) DEBUG: to body [] 4(20825) get_hdr_field: cseq : <317> 4(20825) DEBUG: t_reply_matching: hash 60250 label 319491094 branch 0 4(20825) DEBUG:tm:REF_UNSAFE: after is 1 4(20825) DEBUG: t_reply_matching: reply matched (T=0xb5f43530)! 4(20825) DEBUG: t_check: msg id=6 global id=6 T end=0xb5f43530 4(20825) DEBUG:tm:reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0) 4(20825) DEBUG:tm:t_should_relay_response: T_code=0, new_code=200 4(20825) DEBUG:tm:relay_reply: branch=0, save=0, relay=0 4(20825) parse_headers: flags=2000 4(20825) DEBUG: get_hdr_body : content_length=0 4(20825) old size: 622, new size: 526 4(20825) build_res_from_sip_res: copied size: orig:112, new: 16, rest: 510 msg= SIP/2.0 200 OK Via: SIP/2.0/TCP 66.192.106.194:3464;branch=z9hG4bK1223ffb5 Record-Route: From: ;epid=8C-D4-0D-19-22;tag=9c62043b0 To: ;tag=as467485c4 Call-ID: 6aea8d3d32fb4261ad3a96f91803aa89 CSeq: 317 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 4(20825) WARNING:vqm_resize: resize(0) called 4(20825) DEBUG: add_to_tail_of_timer[2]: 0xb5f43578 4(20825) tcp_send: tcp connection found (0xb5f33418), acquiring fd 4(20825) tcp_send, c= 0xb5f33418, n=8 11(20832) handle_ser_child: read response= b5f33418, 1, fd -1 from 4 (20825) 4(20825) tcp_send: after receive_fd: c= 0xb5f33418 n=4 fd=11 4(20825) tcp_send: sending... 4(20825) tcp_send: after write: c= 0xb5f33418 n=526 fd=11 4(20825) tcp_send: buf= SIP/2.0 200 OK Via: SIP/2.0/TCP 66.192.106.194:3464;branch=z9hG4bK1223ffb5 Record-Route: From: ;epid=8C-D4-0D-19-22;tag=9c62043b0 To: ;tag=as467485c4 Call-ID: 6aea8d3d32fb4261ad3a96f91803aa89 CSeq: 317 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 4(20825) DEBUG:tm:relay_reply: sent buf=0x8117e58: SIP/2.0 2..., shmem=0xb5f44b58: SIP/2.0 2 4(20825) DEBUG: cleanup_uac_timers: RETR/FR timers reset 4(20825) DEBUG:tm:UNREF_UNSAFE: after is 0 4(20825) DEBUG:destroy_avp_list: destroying list (nil) 4(20825) receive_msg: cleaning up 6(20827) DEBUG: timer routine:0,tl=0xb5f4365c next=(nil) 6(20827) DEBUG: timer routine:4,tl=0xb5f4364c next=(nil) 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 1 8(20829), 0xb5f23170 8(20829) received n=4 con=0xb5f23170, fd=20 8(20829) DBG: io_watch_add(0x80dfe80, 20, 2, 0xb5f23170), fd_no=1 8(20829) tcp_read: EOF on 0xb5f23170, FD 20 8(20829) tcp_read_req: EOF 8(20829) DBG: io_watch_del (0x80dfe80, 20, -1, 0x10) fd_no=2 called 8(20829) releasing con 0xb5f23170, state -1, fd=20, id=12 8(20829) extra_data (nil) 11(20832) handle_tcp_child: reader response= b5f23170, -1 from 1 11(20832) tcpconn_destroy: destroying connection 0xb5f23170, flags 0002 6(20827) DEBUG: timer routine:2,tl=0xb5f43578 next=(nil) 6(20827) DEBUG: wait_handler : removing 0xb5f43530 from table 6(20827) DEBUG: delete transaction 0xb5f43530 6(20827) DEBUG: wait_handler : done 11(20832) tcpconn_new: new tcp connection to: 66.192.106.194 11(20832) tcpconn_new: on port 3472, type 2 11(20832) tcpconn_add: hashes: 466, 14 11(20832) handle_new_connect: new connection: 0xb5f23170 23 flags: 0002 11(20832) send2child: to tcp child 1 8(20829), 0xb5f23170 8(20829) received n=4 con=0xb5f23170, fd=20 8(20829) DBG: io_watch_add(0x80dfe80, 20, 2, 0xb5f23170), fd_no=1 8(20829) tcp_read_req: content-length= 0 8(20829) SIP Request: 8(20829) method: 8(20829) uri: 8(20829) version: 8(20829) parse_headers: flags=2 8(20829) DEBUG:parse_to:end of header reached, state=10 8(20829) DBUG:parse_to: display={}, ruri={sip:pbx.elephantoutlook.com:5060;transport=TCP} 8(20829) DEBUG: get_hdr_field: [50]; uri=[sip:pbx.elephantoutlook.com:5060;transport=TCP] 8(20829) DEBUG: to body [ ] 8(20829) get_hdr_field: cseq : <318> 8(20829) Found param type 232, = ; state=16 8(20829) end of header reached, state=5 8(20829) parse_headers: Via found, flags=2 8(20829) parse_headers: this is the first via 8(20829) After parse_msg... 8(20829) preparing to run routing scripts... 8(20829) DEBUG:maxfwd:is_maxfwd_present: value = 70 8(20829) DEBUG: add_param: epid=8C-D4-0D-19-22 8(20829) DEBUG: add_param: tag=3c8ee3b9d3 8(20829) DEBUG:parse_to:end of header reached, state=29 8(20829) DBUG:parse_to: display={}, ruri={sip:eo-dev.webcode.com:5060} 8(20829) ==================== === Relaying to Asterisk === ==================== 8(20829) DEBUG: t_newtran: msg id=3 , global msg id=2 , T on entrance=0xffffffff 8(20829) parse_headers: flags=ffffffffffffffff 8(20829) DEBUG: get_hdr_body : content_length=0 8(20829) found end of header 8(20829) parse_headers: flags=78 8(20829) t_lookup_request: start searching: hash=44239, isACK=0 8(20829) DEBUG: RFC3261 transaction matching failed 8(20829) DEBUG: t_lookup_request: no transaction found 8(20829) build_req_from_req: id added: <;i=e>, rcv proto=2 8(20829) check_via_address(66.192.106.194, 66.192.106.194, 0) 8(20829) DEBUG: add_to_tail_of_timer[4]: 0xb5f4364c 8(20829) DEBUG: add_to_tail_of_timer[0]: 0xb5f4365c 8(20829) SER: new transaction fwd'ed 8(20829) DEBUG: t_newtran: msg id=3 , global msg id=3 , T on entrance=0xb5f43530 8(20829) ERROR: t_newtran: transaction already in process 0xb5f43530 8(20829) DEBUG:sl:sl_reply_error: error text is I'm terribly sorry, server error occurred (1/SL) 8(20829) parse_headers: flags=ffffffffffffffff 8(20829) check_via_address(66.192.106.194, 66.192.106.194, 0) 8(20829) tcp_send: tcp connection found (0xb5f23170), acquiring fd 8(20829) tcp_send, c= 0xb5f23170, n=8 11(20832) handle_ser_child: read response= b5f23170, 1, fd -1 from 8 (20829) 3(20824) SIP Reply (status): 3(20824) version: 3(20824) status: <200> 3(20824) reason: 3(20824) parse_headers: flags=2 3(20824) Found param type 232, = ; state=6 3(20824) Found param type 236, = ; state=6 3(20824) Found param type 234, = <66.192.107.225>; state=16 3(20824) end of header reached, state=5 3(20824) parse_headers: Via found, flags=2 3(20824) parse_headers: this is the first via 3(20824) After parse_msg... 3(20824) forward_reply: found module tm, passing reply to it 3(20824) DEBUG: t_check: msg id=5 global id=4 T start=0xffffffff 3(20824) parse_headers: flags=22 3(20824) Found param type 232, = ; state=16 3(20824) end of header reached, state=5 3(20824) parse_headers: Via found, flags=22 3(20824) parse_headers: this is the second via 3(20824) DEBUG: add_param: tag=as1282439a 3(20824) DEBUG:parse_to:end of header reached, state=29 3(20824) DBUG:parse_to: display={}, ruri={sip:pbx.elephantoutlook.com:5060;transport=TCP} 3(20824) DEBUG: get_hdr_field: [65]; uri=[sip:pbx.elephantoutlook.com:5060;transport=TCP] 3(20824) DEBUG: to body [] 3(20824) get_hdr_field: cseq : <318> 3(20824) DEBUG: t_reply_matching: hash 44239 label 1716633844 branch 0 3(20824) DEBUG:tm:REF_UNSAFE: after is 2 3(20824) DEBUG: t_reply_matching: reply matched (T=0xb5f43530)! 3(20824) DEBUG: t_check: msg id=5 global id=5 T end=0xb5f43530 3(20824) DEBUG:tm:reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0) 3(20824) DEBUG:tm:t_should_relay_response: T_code=0, new_code=200 3(20824) DEBUG:tm:relay_reply: branch=0, save=0, relay=0 3(20824) parse_headers: flags=2000 3(20824) DEBUG: get_hdr_body : content_length=0 3(20824) old size: 624, new size: 528 3(20824) build_res_from_sip_res: copied size: orig:112, new: 16, rest: 512 msg= SIP/2.0 200 OK Via: SIP/2.0/TCP 66.192.106.194:3472;branch=z9hG4bKf7b4f39d Record-Route: From: ;epid=8C-D4-0D-19-22;tag=3c8ee3b9d3 To: ;tag=as1282439a Call-ID: 5a7257b8759848b7b80e4fd5d9061e57 CSeq: 318 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 3(20824) WARNING:vqm_resize: resize(0) called 3(20824) DEBUG: add_to_tail_of_timer[2]: 0xb5f43578 3(20824) tcp_send: tcp connection found (0xb5f23170), acquiring fd 3(20824) tcp_send, c= 0xb5f23170, n=8 11(20832) handle_ser_child: read response= b5f23170, 1, fd -1 from 3 (20824) 3(20824) tcp_send: after receive_fd: c= 0xb5f23170 n=4 fd=10 3(20824) tcp_send: sending... 3(20824) tcp_send: after write: c= 0xb5f23170 n=528 fd=10 3(20824) tcp_send: buf= SIP/2.0 200 OK Via: SIP/2.0/TCP 66.192.106.194:3472;branch=z9hG4bKf7b4f39d Record-Route: From: ;epid=8C-D4-0D-19-22;tag=3c8ee3b9d3 To: ;tag=as1282439a Call-ID: 5a7257b8759848b7b80e4fd5d9061e57 CSeq: 318 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 3(20824) DEBUG:tm:relay_reply: sent buf=0x8117c18: SIP/2.0 2..., shmem=0xb5f44b58: SIP/2.0 2 3(20824) DEBUG: cleanup_uac_timers: RETR/FR timers reset 3(20824) DEBUG:tm:UNREF_UNSAFE: after is 1 3(20824) DEBUG:destroy_avp_list: destroying list (nil) 3(20824) receive_msg: cleaning up 8(20829) tcp_send: after receive_fd: c= 0xb5f23170 n=4 fd=21 8(20829) tcp_send: sending... 8(20829) tcp_send: after write: c= 0xb5f23170 n=651 fd=21 8(20829) tcp_send: buf= SIP/2.0 500 I'm terribly sorry, server error occurred (1/SL) FROM: ;epid=8C-D4-0D-19-22;tag=3c8ee3b9d3 TO: ;tag=ff0593a3ce80005043f79ea67dccae1c.f972 CSEQ: 318 OPTIONS CALL-ID: 5a7257b8759848b7b80e4fd5d9061e57 VIA: SIP/2.0/TCP 66.192.106.194:3472;branch=z9hG4bKf7b4f39d Server: OpenSer (1.1.0-notls (i386/linux)) Content-Length: 0 Warning: 392 66.192.107.225:5070 "Noisy feedback tells: pid=20829 req_src_ip=66.192.106.194 req_src_port=3472 in_uri=sip:pbx.elephantoutlook.com:5060;transport=TCP out_uri=sip:pbx.elephantoutlook.com:5060;transport=TCP via_cnt==1" 8(20829) DEBUG:tm:UNREF_UNSAFE: after is 0 8(20829) DEBUG:destroy_avp_list: destroying list (nil) 8(20829) receive_msg: cleaning up 7(20828) tcp_read: EOF on 0xb5f33418, 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 0xb5f33418, state -1, fd=18, id=13 7(20828) extra_data (nil) 11(20832) handle_tcp_child: reader response= b5f33418, -1 from 0 11(20832) tcpconn_destroy: destroying connection 0xb5f33418, flags 0002 6(20827) DEBUG: timer routine:0,tl=0xb5f4365c next=(nil) 6(20827) DEBUG: timer routine:4,tl=0xb5f4364c next=(nil) 6(20827) DEBUG: timer routine:2,tl=0xb5f43578 next=(nil) 6(20827) DEBUG: wait_handler : removing 0xb5f43530 from table 6(20827) DEBUG: delete transaction 0xb5f43530 6(20827) DEBUG: wait_handler : done 8(20829) tcp_receive_timeout: 0xb5f23170 expired (730, 731) lt=0 8(20829) DBG: io_watch_del (0x80dfe80, 20, -1, 0x10) fd_no=2 called 8(20829) releasing con 0xb5f23170, state 0, fd=20, id=14 8(20829) extra_data (nil) 11(20832) handle_tcp_child: reader response= b5f23170, 0 from 1 11(20832) DBG: io_watch_add(0x80dfd20, 23, 2, 0xb5f23170), fd_no=15 11(20832) handle_tcp_child: CONN_RELEASE 0xb5f23170 refcnt= 0