66.192.107.225 is an Asterisk/OpenSER box Asterisk is on port 5060 OpenSER is on port 5070 66.192.106.194 is Exchange 2007 exchange 2007 <-> TCP:OpenSER:UDP <-> Asterisk <-- SIP read from 66.192.107.225:5070: OPTIONS sip:pbx.elephantoutlook.com:5060;transport=TCP SIP/2.0 Record-Route: FROM: ;epid=8C-D4-0D-19-22;tag=fa65c1f0e8 TO: CSEQ: 1 OPTIONS CALL-ID: d38c461e61394f8daee840cced983efe MAX-FORWARDS: 69 Via: SIP/2.0/UDP 66.192.107.225:5070;branch=z9hG4bK5e1e.cf185942.0;i=1 VIA: SIP/2.0/TCP 66.192.106.194:2201;branch=z9hG4bK51e4e352 ACCEPT: application/sdp CONTACT: CONTENT-LENGTH: 0 USER-AGENT: RTCC/2.0.6010.0 --- (13 headers 0 lines)--- Looking for s in local (domain pbx.elephantoutlook.com) Transmitting (no NAT) to 66.192.107.225:5070: SIP/2.0 404 Not Found Via: SIP/2.0/UDP 66.192.107.225:5070;branch=z9hG4bK5e1e.cf185942.0;i=1;received=66.192.107.225 Via: SIP/2.0/TCP 66.192.106.194:2201;branch=z9hG4bK51e4e352 From: ;epid=8C-D4-0D-19-22;tag=fa65c1f0e8 To: ;tag=as0b8ccbeb Call-ID: d38c461e61394f8daee840cced983efe CSeq: 1 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 --- Destroying call 'd38c461e61394f8daee840cced983efe' pbx*CLI> 11(19974) tcpconn_new: new tcp connection to: 66.192.106.194 11(19974) tcpconn_new: on port 2201, type 2 11(19974) tcpconn_add: hashes: 219, 1 11(19974) handle_new_connect: new connection: 0xb5e94538 23 flags: 0002 11(19974) send2child: to tcp child 0 7(19970), 0xb5e94538 7(19970) received n=4 con=0xb5e94538, fd=18 7(19970) DBG: io_watch_add(0x80dfe80, 18, 2, 0xb5e94538), fd_no=1 7(19970) tcp_read_req: content-length= 0 7(19970) SIP Request: 7(19970) method: 7(19970) uri: 7(19970) version: 7(19970) parse_headers: flags=2 7(19970) DEBUG:parse_to:end of header reached, state=10 7(19970) DBUG:parse_to: display={}, ruri={sip:pbx.elephantoutlook.com:5060;transport=TCP} 7(19970) DEBUG: get_hdr_field: [50]; uri=[sip:pbx.elephantoutlook.com:5060;transport=TCP] 7(19970) DEBUG: to body [ ] 7(19970) get_hdr_field: cseq : <1> 7(19970) Found param type 232, = ; state=16 7(19970) end of header reached, state=5 7(19970) parse_headers: Via found, flags=2 7(19970) parse_headers: this is the first via 7(19970) After parse_msg... 7(19970) preparing to run routing scripts... 7(19970) DEBUG:maxfwd:is_maxfwd_present: value = 70 7(19970) DEBUG: add_param: epid=8C-D4-0D-19-22 7(19970) DEBUG: add_param: tag=fa65c1f0e8 7(19970) DEBUG:parse_to:end of header reached, state=29 7(19970) DBUG:parse_to: display={}, ruri={sip:eo-dev.webcode.com:5060} 7(19970) DEBUG: t_newtran: msg id=1 , global msg id=0 , T on entrance=0xffffffff 7(19970) parse_headers: flags=ffffffffffffffff 7(19970) DEBUG: get_hdr_body : content_length=0 7(19970) found end of header 7(19970) parse_headers: flags=78 7(19970) t_lookup_request: start searching: hash=57829, isACK=0 7(19970) DEBUG: RFC3261 transaction matching failed 7(19970) DEBUG: t_lookup_request: no transaction found 7(19970) build_req_from_req: id added: <;i=1>, rcv proto=2 7(19970) check_via_address(66.192.106.194, 66.192.106.194, 0) 7(19970) DEBUG: add_to_tail_of_timer[4]: 0xb5ea476c 7(19970) DEBUG: add_to_tail_of_timer[0]: 0xb5ea477c 7(19970) SER: new transaction fwd'ed 7(19970) DEBUG: t_newtran: msg id=1 , global msg id=1 , T on entrance=0xb5ea4650 7(19970) ERROR: t_newtran: transaction already in process 0xb5ea4650 7(19970) DEBUG:sl:sl_reply_error: error text is I'm terribly sorry, server error occurred (1/SL) 7(19970) parse_headers: flags=ffffffffffffffff 7(19970) check_via_address(66.192.106.194, 66.192.106.194, 0) 7(19970) tcp_send: tcp connection found (0xb5e94538), acquiring fd 7(19970) tcp_send, c= 0xb5e94538, n=8 11(19974) handle_ser_child: read response= b5e94538, 1, fd -1 from 7 (19970) 7(19970) tcp_send: after receive_fd: c= 0xb5e94538 n=4 fd=19 7(19970) tcp_send: sending... 7(19970) tcp_send: after write: c= 0xb5e94538 n=649 fd=19 7(19970) tcp_send: buf= SIP/2.0 500 I'm terribly sorry, server error occurred (1/SL) FROM: ;epid=8C-D4-0D-19-22;tag=fa65c1f0e8 TO: ;tag=ff0593a3ce80005043f79ea67dccae1c.1371 CSEQ: 1 OPTIONS CALL-ID: d38c461e61394f8daee840cced983efe VIA: SIP/2.0/TCP 66.192.106.194:2201;branch=z9hG4bK51e4e352 Server: OpenSer (1.1.0-notls (i386/linux)) Content-Length: 0 Warning: 392 66.192.107.225:5070 "Noisy feedback tells: pid=19970 req_src_ip=66.192.106.194 req_src_port=2201 in_uri=sip:pbx.elephantoutlook.com:5060;transport=TCP out_uri=sip:pbx.elephantoutlook.com:5060;transport=TCP via_cnt==1" 7(19970) DEBUG:tm:UNREF_UNSAFE: after is 0 7(19970) DEBUG:destroy_avp_list: destroying list (nil) 7(19970) receive_msg: cleaning up 2(19965) SIP Reply (status): 2(19965) version: 2(19965) status: <404> 2(19965) reason: 2(19965) parse_headers: flags=2 2(19965) Found param type 232, = ; state=6 2(19965) Found param type 236, = <1>; state=6 2(19965) Found param type 234, = <66.192.107.225>; state=16 2(19965) end of header reached, state=5 2(19965) parse_headers: Via found, flags=2 2(19965) parse_headers: this is the first via 2(19965) After parse_msg... 2(19965) forward_reply: found module tm, passing reply to it 2(19965) DEBUG: t_check: msg id=1 global id=0 T start=0xffffffff 2(19965) parse_headers: flags=22 2(19965) Found param type 232, = ; state=16 2(19965) end of header reached, state=5 2(19965) parse_headers: Via found, flags=22 2(19965) parse_headers: this is the second via 2(19965) DEBUG: add_param: tag=as0b8ccbeb 2(19965) DEBUG:parse_to:end of header reached, state=29 2(19965) DBUG:parse_to: display={}, ruri={sip:pbx.elephantoutlook.com:5060;transport=TCP} 2(19965) DEBUG: get_hdr_field: [65]; uri=[sip:pbx.elephantoutlook.com:5060;transport=TCP] 2(19965) DEBUG: to body [] 2(19965) get_hdr_field: cseq : <1> 2(19965) DEBUG: t_reply_matching: hash 57829 label 613777916 branch 0 2(19965) DEBUG:tm:REF_UNSAFE: after is 1 2(19965) DEBUG: t_reply_matching: reply matched (T=0xb5ea4650)! 2(19965) DEBUG: t_check: msg id=1 global id=1 T end=0xb5ea4650 2(19965) DEBUG:tm:reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0) 2(19965) DEBUG:tm:t_should_relay_response: T_code=0, new_code=404 2(19965) DEBUG:tm:t_pick_branch: picked branch 0, code 404 2(19965) DEBUG:tm:relay_reply: branch=0, save=0, relay=0 2(19965) parse_headers: flags=2000 2(19965) DEBUG: get_hdr_body : content_length=0 2(19965) old size: 552, new size: 456 2(19965) build_res_from_sip_res: copied size: orig:119, new: 23, rest: 433 msg= SIP/2.0 404 Not Found Via: SIP/2.0/TCP 66.192.106.194:2201;branch=z9hG4bK51e4e352 From: ;epid=8C-D4-0D-19-22;tag=fa65c1f0e8 To: ;tag=as0b8ccbeb Call-ID: d38c461e61394f8daee840cced983efe CSeq: 1 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 2(19965) WARNING:vqm_resize: resize(0) called 2(19965) DEBUG: add_to_tail_of_timer[2]: 0xb5ea4698 2(19965) tcp_send: tcp connection found (0xb5e94538), acquiring fd 11(19974) handle_ser_child: read response= b5e94538, 1, fd -1 from 2 (19965) 2(19965) tcp_send, c= 0xb5e94538, n=8 2(19965) tcp_send: after receive_fd: c= 0xb5e94538 n=4 fd=9 2(19965) tcp_send: sending... 2(19965) tcp_send: after write: c= 0xb5e94538 n=456 fd=9 2(19965) tcp_send: buf= SIP/2.0 404 Not Found Via: SIP/2.0/TCP 66.192.106.194:2201;branch=z9hG4bK51e4e352 From: ;epid=8C-D4-0D-19-22;tag=fa65c1f0e8 To: ;tag=as0b8ccbeb Call-ID: d38c461e61394f8daee840cced983efe CSeq: 1 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 2(19965) DEBUG:tm:relay_reply: sent buf=0x8117a78: SIP/2.0 4..., shmem=0xb5ea5c78: SIP/2.0 4 2(19965) DEBUG: cleanup_uac_timers: RETR/FR timers reset 2(19965) DEBUG:tm:UNREF_UNSAFE: after is 0 2(19965) DEBUG:destroy_avp_list: destroying list (nil) 2(19965) receive_msg: cleaning up 6(19969) DEBUG: timer routine:0,tl=0xb5ea477c next=(nil) 6(19969) DEBUG: timer routine:4,tl=0xb5ea476c next=(nil) 6(19969) DEBUG: timer routine:2,tl=0xb5ea4698 next=(nil) 6(19969) DEBUG: wait_handler : removing 0xb5ea4650 from table 6(19969) DEBUG: delete transaction 0xb5ea4650 6(19969) DEBUG: wait_handler : done 11(19974) tcpconn_new: new tcp connection to: 66.192.106.194 11(19974) tcpconn_new: on port 2207, type 2 11(19974) tcpconn_add: hashes: 221, 2 11(19974) handle_new_connect: new connection: 0xb5ea5e48 24 flags: 0002 11(19974) send2child: to tcp child 1 8(19971), 0xb5ea5e48 8(19971) received n=4 con=0xb5ea5e48, fd=20 8(19971) DBG: io_watch_add(0x80dfe80, 20, 2, 0xb5ea5e48), fd_no=1 8(19971) tcp_read_req: content-length= 0 8(19971) SIP Request: 8(19971) method: 8(19971) uri: 8(19971) version: 8(19971) parse_headers: flags=2 8(19971) DEBUG:parse_to:end of header reached, state=10 8(19971) DBUG:parse_to: display={}, ruri={sip:pbx.elephantoutlook.com:5060;transport=TCP} 8(19971) DEBUG: get_hdr_field: [50]; uri=[sip:pbx.elephantoutlook.com:5060;transport=TCP] 8(19971) DEBUG: to body [ ] 8(19971) get_hdr_field: cseq : <2> 8(19971) Found param type 232, = ; state=16 8(19971) end of header reached, state=5 8(19971) parse_headers: Via found, flags=2 8(19971) parse_headers: this is the first via 8(19971) After parse_msg... 8(19971) preparing to run routing scripts... 8(19971) DEBUG:maxfwd:is_maxfwd_present: value = 70 8(19971) DEBUG: add_param: epid=8C-D4-0D-19-22 8(19971) DEBUG: add_param: tag=db435721fa 8(19971) DEBUG:parse_to:end of header reached, state=29 8(19971) DBUG:parse_to: display={}, ruri={sip:eo-dev.webcode.com:5060} 8(19971) DEBUG: t_newtran: msg id=1 , global msg id=0 , T on entrance=0xffffffff 8(19971) parse_headers: flags=ffffffffffffffff 8(19971) DEBUG: get_hdr_body : content_length=0 8(19971) found end of header 8(19971) parse_headers: flags=78 8(19971) t_lookup_request: start searching: hash=31405, isACK=0 8(19971) DEBUG: RFC3261 transaction matching failed 8(19971) DEBUG: t_lookup_request: no transaction found 8(19971) build_req_from_req: id added: <;i=2>, rcv proto=2 8(19971) check_via_address(66.192.106.194, 66.192.106.194, 0) 8(19971) DEBUG: add_to_tail_of_timer[4]: 0xb5ea476c 8(19971) DEBUG: add_to_tail_of_timer[0]: 0xb5ea477c 8(19971) SER: new transaction fwd'ed 8(19971) DEBUG: t_newtran: msg id=1 , global msg id=1 , T on entrance=0xb5ea4650 8(19971) ERROR: t_newtran: transaction already in process 0xb5ea4650 8(19971) DEBUG:sl:sl_reply_error: error text is I'm terribly sorry, server error occurred (1/SL) 8(19971) parse_headers: flags=ffffffffffffffff 8(19971) check_via_address(66.192.106.194, 66.192.106.194, 0) 8(19971) tcp_send: tcp connection found (0xb5ea5e48), acquiring fd 8(19971) tcp_send, c= 0xb5ea5e48, n=8 4(19967) SIP Reply (status): 4(19967) version: 4(19967) status: <404> 4(19967) reason: 4(19967) parse_headers: flags=2 4(19967) Found param type 232, = ; state=6 4(19967) Found param type 236, = <2>; state=6 4(19967) Found param type 234, = <66.192.107.225>; state=16 4(19967) end of header reached, state=5 4(19967) parse_headers: Via found, flags=2 4(19967) parse_headers: this is the first via 4(19967) After parse_msg... 4(19967) forward_reply: found module tm, passing reply to it 4(19967) DEBUG: t_check: msg id=1 global id=0 T start=0xffffffff 4(19967) parse_headers: flags=22 4(19967) Found param type 232, = ; state=16 4(19967) end of header reached, state=5 4(19967) parse_headers: Via found, flags=22 4(19967) parse_headers: this is the second via 4(19967) DEBUG: add_param: tag=as44b943bd 4(19967) DEBUG:parse_to:end of header reached, state=29 4(19967) DBUG:parse_to: display={}, ruri={sip:pbx.elephantoutlook.com:5060;transport=TCP} 4(19967) DEBUG: get_hdr_field: [65]; uri=[sip:pbx.elephantoutlook.com:5060;transport=TCP] 4(19967) DEBUG: to body [] 4(19967) get_hdr_field: cseq : <2> 4(19967) DEBUG: t_reply_matching: hash 31405 label 992895506 branch 0 4(19967) DEBUG:tm:REF_UNSAFE: after is 2 4(19967) DEBUG: t_reply_matching: reply matched (T=0xb5ea4650)! 4(19967) DEBUG: t_check: msg id=1 global id=1 T end=0xb5ea4650 4(19967) DEBUG:tm:reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0) 4(19967) DEBUG:tm:t_should_relay_response: T_code=0, new_code=404 4(19967) DEBUG:tm:t_pick_branch: picked branch 0, code 404 4(19967) DEBUG:tm:relay_reply: branch=0, save=0, relay=0 4(19967) parse_headers: flags=2000 4(19967) DEBUG: get_hdr_body : content_length=0 4(19967) old size: 552, new size: 456 4(19967) build_res_from_sip_res: copied size: orig:119, new: 23, rest: 433 msg= SIP/2.0 404 Not Found Via: SIP/2.0/TCP 66.192.106.194:2207;branch=z9hG4bKfe72ee8d From: ;epid=8C-D4-0D-19-22;tag=db435721fa To: ;tag=as44b943bd Call-ID: d41967c5979642fd966ff0a7f5f74aa2 CSeq: 2 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 4(19967) WARNING:vqm_resize: resize(0) called 4(19967) DEBUG: add_to_tail_of_timer[2]: 0xb5ea4698 4(19967) tcp_send: tcp connection found (0xb5ea5e48), acquiring fd 4(19967) tcp_send, c= 0xb5ea5e48, n=8 11(19974) handle_ser_child: read response= b5ea5e48, 1, fd -1 from 4 (19967) 11(19974) handle_ser_child: read response= b5ea5e48, 1, fd -1 from 8 (19971) 4(19967) tcp_send: after receive_fd: c= 0xb5ea5e48 n=4 fd=11 4(19967) tcp_send: sending... 4(19967) tcp_send: after write: c= 0xb5ea5e48 n=456 fd=11 4(19967) tcp_send: buf= SIP/2.0 404 Not Found Via: SIP/2.0/TCP 66.192.106.194:2207;branch=z9hG4bKfe72ee8d From: ;epid=8C-D4-0D-19-22;tag=db435721fa To: ;tag=as44b943bd Call-ID: d41967c5979642fd966ff0a7f5f74aa2 CSeq: 2 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 4(19967) DEBUG:tm:relay_reply: sent buf=0x8117a78: SIP/2.0 4..., shmem=0xb5ea5c78: SIP/2.0 4 4(19967) DEBUG: cleanup_uac_timers: RETR/FR timers reset 4(19967) DEBUG:tm:UNREF_UNSAFE: after is 1 4(19967) DEBUG:destroy_avp_list: destroying list (nil) 4(19967) receive_msg: cleaning up 8(19971) tcp_send: after receive_fd: c= 0xb5ea5e48 n=4 fd=21 8(19971) tcp_send: sending... 8(19971) tcp_send: after write: c= 0xb5ea5e48 n=649 fd=21 8(19971) tcp_send: buf= SIP/2.0 500 I'm terribly sorry, server error occurred (1/SL) FROM: ;epid=8C-D4-0D-19-22;tag=db435721fa TO: ;tag=ff0593a3ce80005043f79ea67dccae1c.cd32 CSEQ: 2 OPTIONS CALL-ID: d41967c5979642fd966ff0a7f5f74aa2 VIA: SIP/2.0/TCP 66.192.106.194:2207;branch=z9hG4bKfe72ee8d Server: OpenSer (1.1.0-notls (i386/linux)) Content-Length: 0 Warning: 392 66.192.107.225:5070 "Noisy feedback tells: pid=19971 req_src_ip=66.192.106.194 req_src_port=2207 in_uri=sip:pbx.elephantoutlook.com:5060;transport=TCP out_uri=sip:pbx.elephantoutlook.com:5060;transport=TCP via_cnt==1" 8(19971) DEBUG:tm:UNREF_UNSAFE: after is 0 8(19971) DEBUG:destroy_avp_list: destroying list (nil) 8(19971) receive_msg: cleaning up 6(19969) DEBUG: timer routine:0,tl=0xb5ea477c next=(nil) 6(19969) DEBUG: timer routine:4,tl=0xb5ea476c next=(nil) 7(19970) tcp_read: EOF on 0xb5e94538, FD 18 7(19970) tcp_read_req: EOF 7(19970) DBG: io_watch_del (0x80dfe80, 18, -1, 0x10) fd_no=2 called 7(19970) releasing con 0xb5e94538, state -1, fd=18, id=1 7(19970) extra_data (nil) 11(19974) handle_tcp_child: reader response= b5e94538, -1 from 0 11(19974) tcpconn_destroy: destroying connection 0xb5e94538, flags 0002 6(19969) DEBUG: timer routine:2,tl=0xb5ea4698 next=(nil) 6(19969) DEBUG: wait_handler : removing 0xb5ea4650 from table 6(19969) DEBUG: delete transaction 0xb5ea4650 6(19969) DEBUG: wait_handler : done 8(19971) tcp_receive_timeout: 0xb5ea5e48 expired (93, 94) lt=0 8(19971) DBG: io_watch_del (0x80dfe80, 20, -1, 0x10) fd_no=2 called 8(19971) releasing con 0xb5ea5e48, state 0, fd=20, id=2 8(19971) extra_data (nil) 11(19974) handle_tcp_child: reader response= b5ea5e48, 0 from 1 11(19974) DBG: io_watch_add(0x80dfd20, 24, 2, 0xb5ea5e48), fd_no=15 11(19974) handle_tcp_child: CONN_RELEASE 0xb5ea5e48 refcnt= 0