[Serusers] PSTN call receives a bye after 5 seconds using SER+B2BUA+MEDIAPROXY

Hi all I have been looking at the debugs in order to try to figure out If I'm doing something wrong at my SER.CFG I have the following: UA ----> SER -----> B2BUA -----> SER ------> PSTN-GW 1. The user agent place a call to the SER proxy. 2. SER Proxy receives the call and forwads to B2BUA (VOCAL at the same server using UDP port 5065) 3. B2BUA receives the calls activates the Billing supervision and Sends an invite for a new call to the SER. 4. SER receives the call from the B2BUA and rewrite host and port to the PSTN-GW. 5. PSTN-GW receives the invite from the SER and sends back the ACK. 6. Inmediatly from some reason SER is sending a BYE to the call. I'm attaching a debug from the SER and my SER.CFG file Could anybody help me please? Regards Alberto Cruz Jun 25 08:43:31 sipsrv ser[1936]: SIP Request: Jun 25 08:43:31 sipsrv ser[1936]: method: <INVITE> Jun 25 08:43:31 sipsrv ser[1936]: uri: <sip:018183324166@sipsrv.conecta-te.com> Jun 25 08:43:31 sipsrv ser[1936]: version: <SIP/2.0> Jun 25 08:43:31 sipsrv ser[1936]: parse_headers: flags=1 Jun 25 08:43:31 sipsrv ser[1936]: Found param type 232, <branch> = <z9hG4bK-46d68929>; state=16 Jun 25 08:43:31 sipsrv ser[1936]: end of header reached, state=5 Jun 25 08:43:31 sipsrv ser[1936]: parse_headers: Via found, flags=1 Jun 25 08:43:31 sipsrv ser[1936]: parse_headers: this is the first via Jun 25 08:43:31 sipsrv ser[1936]: After parse_msg... Jun 25 08:43:31 sipsrv ser[1936]: preparing to run routing scripts... Jun 25 08:43:31 sipsrv ser[1936]: parse_headers: flags=128 Jun 25 08:43:31 sipsrv ser[1936]: end of header reached, state=9 Jun 25 08:43:31 sipsrv ser[1936]: DEBUG: get_hdr_field: <To> [42]; uri=[sip:018183324166@sipsrv.conecta-te.com] Jun 25 08:43:31 sipsrv ser[1936]: DEBUG: to body [<sip:018183324166@sipsrv.conecta-te.com>^M ] Jun 25 08:43:31 sipsrv ser[1936]: get_hdr_field: cseq <CSeq>: <101> <INVITE> Jun 25 08:43:31 sipsrv ser[1936]: DEBUG:maxfwd:is_maxfwd_present: value = 70 Jun 25 08:43:31 sipsrv ser[1936]: DBG:maxfwd:process_maxfwd_header: value 70 decreased to 16 Jun 25 08:43:31 sipsrv ser[1936]: parse_headers: flags=64 Jun 25 08:43:31 sipsrv ser[1936]: DEBUG: add_param: tag=7a83401cfe54b69o0 Jun 25 08:43:31 sipsrv ser[1936]: end of header reached, state=29 Jun 25 08:43:31 sipsrv ser[1936]: parse_headers: flags=256 Jun 25 08:43:31 sipsrv ser[1936]: DEBUG: get_hdr_body : content_length=316 Jun 25 08:43:31 sipsrv ser[1936]: found end of header Jun 25 08:43:31 sipsrv ser[1936]: find_first_route: No Route headers found Jun 25 08:43:31 sipsrv ser[1936]: loose_route: There is no Route HF Jun 25 08:43:31 sipsrv ser[1936]: grep_sock_info - checking if host==us: 21==11 && [sipsrv.conecta-te.com] == [200.94.75.6] Jun 25 08:43:31 sipsrv ser[1936]: grep_sock_info - checking if port 5060 matches port 5060 Jun 25 08:43:31 sipsrv ser[1936]: grep_sock_info - checking if host==us: 21==11 && [sipsrv.conecta-te.com] == [200.94.75.6] Jun 25 08:43:31 sipsrv ser[1936]: grep_sock_info - checking if port 5060 matches port 5060 Jun 25 08:43:31 sipsrv ser[1936]: grep_sock_info - checking if host==us: 21==11 && [sipsrv.conecta-te.com] == [200.94.75.6] Jun 25 08:43:31 sipsrv ser[1936]: grep_sock_info - checking if port 5060 matches port 5060 Jun 25 08:43:31 sipsrv ser[1936]: grep_sock_info - checking if host==us: 21==11 && [sipsrv.conecta-te.com] == [200.94.75.6] Jun 25 08:43:31 sipsrv ser[1936]: grep_sock_info - checking if port 5060 matches port 5060 Jun 25 08:43:31 sipsrv ser[1936]: Hey this request is NOT from B2BUA Jun 25 08:43:31 sipsrv ser[1936]: FORWARDING TO B2BUA Jun 25 08:43:31 sipsrv ser[1936]: parse_headers: flags=-1 Jun 25 08:43:31 sipsrv ser[1936]: parse_headers: flags=64 Jun 25 08:43:31 sipsrv ser[1936]: parse_headers: flags=64 Jun 25 08:43:31 sipsrv ser[1936]: parse_headers: flags=-1 Jun 25 08:43:31 sipsrv ser[1936]: check_via_address(200.67.33.247, 172.31.253.127, 0) Jun 25 08:43:31 sipsrv ser[1936]: Sending: INVITE sip:018183324166@sipsrv.conecta-te.com SIP/2.0^M Record-Route: <sip:018183324166@200.94.75.6:5060;nat=yes;ftag=7a83401cfe54b69o0;lr=on>^M Via: SIP/2.0/UDP 200.94.75.6;branch=0^M Via: SIP/2.0/UDP 172.31.253.127:5060;rport=60425;received=200.67.33.247;branch=z9hG4bK-46d68929^M From: 8183651723 <sip:8183651723@sipsrv.conecta-te.com>;tag=7a83401cfe54b69o0^M To: <sip:018183324166@sipsrv.conecta-te.com>^M Call-ID: b5fcf1e1-baf4a709(a)172.31.253.127^M CSeq: 101 INVITE^M Max-Forwards: 16^M Contact: 8183651723 <sip:8183651723@200.67.33.247:60425>^M Expires: 240^M User-Agent: Linksys/PAP2-2.0.12(LS)^M Content-Length: 316^M Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER^M Supported: x-sipura^M Content-Type: application/sdp^M P-hint: PASANDO POR EL B2BUA^M P-hint: APLICO NAT AL B2BUA^M ^M v=0^M o=- 23012599 23012599 IN IP4 172.31.253.127^M s=-^M c=IN IP4 172.31.253.127^M t=0 0^M m=audio 16458 RTP/AVP 18 0 4 8 100 101^M a=rtpmap:18 G729a/8000^M a=rtpmap:0 PCMU/800 Jun 25 08:43:31 sipsrv ser[1936]: orig. len=884, new_len=1105, proto=1 Jun 25 08:43:31 sipsrv ser[1936]: DEBUG:destroy_avp_list: destroying list (nil) Jun 25 08:43:31 sipsrv ser[1936]: receive_msg: cleaning up Jun 25 08:43:31 sipsrv ser[1929]: SIP Request: Jun 25 08:43:31 sipsrv ser[1929]: method: <INVITE> Jun 25 08:43:31 sipsrv ser[1929]: uri: <sip:018183324166@200.94.75.6:5060> Jun 25 08:43:31 sipsrv ser[1929]: version: <SIP/2.0> Jun 25 08:43:31 sipsrv ser[1929]: parse_headers: flags=1 Jun 25 08:43:31 sipsrv ser[1929]: end of header reached, state=5 Jun 25 08:43:31 sipsrv ser[1929]: parse_headers: Via found, flags=1 Jun 25 08:43:31 sipsrv ser[1929]: parse_headers: this is the first via Jun 25 08:43:31 sipsrv ser[1929]: After parse_msg... Jun 25 08:43:31 sipsrv ser[1929]: preparing to run routing scripts... Jun 25 08:43:31 sipsrv ser[1929]: parse_headers: flags=128 Jun 25 08:43:31 sipsrv ser[1929]: end of header reached, state=9 Jun 25 08:43:31 sipsrv ser[1929]: DEBUG: get_hdr_field: <To> [42]; uri=[sip:018183324166@sipsrv.conecta-te.com] Jun 25 08:43:31 sipsrv ser[1929]: DEBUG: to body [<sip:018183324166@sipsrv.conecta-te.com>^M ] Jun 25 08:43:31 sipsrv ser[1929]: get_hdr_field: cseq <CSeq>: <101> <INVITE> Jun 25 08:43:31 sipsrv ser[1929]: DEBUG:maxfwd:is_maxfwd_present: value = 16 Jun 25 08:43:31 sipsrv ser[1929]: parse_headers: flags=64 Jun 25 08:43:31 sipsrv ser[1929]: check_via_address(200.94.75.6, 200.94.75.6, 0) Jun 25 08:43:31 sipsrv ser[1929]: parse_headers: flags=33554432 Jun 25 08:43:31 sipsrv ser[1929]: DEBUG: add_param: tag=7a83401cfe54b69o0 Jun 25 08:43:31 sipsrv ser[1929]: end of header reached, state=29 Jun 25 08:43:31 sipsrv ser[1929]: parse_headers: flags=256 Jun 25 08:43:31 sipsrv ser[1929]: DEBUG: get_hdr_body : content_length=316 Jun 25 08:43:31 sipsrv ser[1929]: found end of header Jun 25 08:43:31 sipsrv ser[1929]: find_first_route: No Route headers found Jun 25 08:43:31 sipsrv ser[1929]: loose_route: There is no Route HF Jun 25 08:43:31 sipsrv ser[1929]: grep_sock_info - checking if host==us: 11==11 && [200.94.75.6] == [200.94.75.6] Jun 25 08:43:31 sipsrv ser[1929]: grep_sock_info - checking if port 5060 matches port 5060 Jun 25 08:43:31 sipsrv ser[1929]: grep_sock_info - checking if host==us: 11==11 && [200.94.75.6] == [200.94.75.6] Jun 25 08:43:31 sipsrv ser[1929]: grep_sock_info - checking if port 5060 matches port 5060 Jun 25 08:43:31 sipsrv ser[1929]: parse_headers: flags=64 Jun 25 08:43:31 sipsrv ser[1929]: check_via_address(200.94.75.6, 200.94.75.6, 0) Jun 25 08:43:31 sipsrv ser[1929]: parse_headers: flags=33554432 Jun 25 08:43:31 sipsrv ser[1929]: lookup(): '018183324166' Not found in usrloc Jun 25 08:43:31 sipsrv ser[1929]: grep_sock_info - checking if host==us: 11==11 && [200.94.75.6] == [200.94.75.6] Jun 25 08:43:31 sipsrv ser[1929]: grep_sock_info - checking if port 5060 matches port 5060 Jun 25 08:43:31 sipsrv ser[1929]: lookup(): '018183324166' Not found in usrloc Jun 25 08:43:31 sipsrv ser[1929]: DEBUG: t_newtran: msg id=9 , global msg id=1 , T on entrance=0xffffffff Jun 25 08:43:31 sipsrv ser[1929]: parse_headers: flags=-1 Jun 25 08:43:31 sipsrv ser[1929]: parse_headers: flags=60 Jun 25 08:43:31 sipsrv ser[1929]: t_lookup_request: start searching: hash=21902, isACK=0 Jun 25 08:43:31 sipsrv ser[1929]: DEBUG: proceeding to pre-RFC3261 transaction matching Jun 25 08:43:31 sipsrv ser[1929]: DEBUG: t_lookup_request: no transaction found Jun 25 08:43:31 sipsrv ser[1929]: DBG: trans=0x4057c048, callback type 1, id 0 entered Jun 25 08:43:31 sipsrv ser[1929]: SER: new INVITE Jun 25 08:43:31 sipsrv ser[1929]: parse_headers: flags=-1 Jun 25 08:43:31 sipsrv ser[1929]: check_via_address(200.94.75.6, 200.94.75.6, 0) Jun 25 08:43:31 sipsrv ser[1929]: WARNING:vqm_resize: resize(0) called Jun 25 08:43:31 sipsrv ser[1929]: DEBUG: reply sent out. buf=0x810fe78: SIP/2.0 1..., shmem=0x4057bcd8: SIP/2.0 1 Jun 25 08:43:31 sipsrv ser[1929]: DEBUG: _reply_light: finished Jun 25 08:43:31 sipsrv ser[1929]: DEBUG: mk_proxy: doing DNS lookup... Jun 25 08:43:31 sipsrv ser[1929]: check_via_address(200.94.75.6, 200.94.75.6, 0) Jun 25 08:43:31 sipsrv ser[1929]: DEBUG: add_to_tail_of_timer[4]: 0x4057c160 Jun 25 08:43:31 sipsrv ser[1929]: DEBUG: add_to_tail_of_timer[0]: 0x4057c170 Jun 25 08:43:31 sipsrv ser[1929]: SER: new transaction fwd'ed Jun 25 08:43:31 sipsrv ser[1929]: DEBUG:destroy_avp_list: destroying list (nil) Jun 25 08:43:31 sipsrv ser[1929]: receive_msg: cleaning up Jun 25 08:43:31 sipsrv ser[1931]: SIP Reply (status): Jun 25 08:43:31 sipsrv ser[1931]: version: <SIP/2.0> Jun 25 08:43:31 sipsrv ser[1931]: status: <100> Jun 25 08:43:31 sipsrv ser[1931]: reason: <Trying> Jun 25 08:43:31 sipsrv ser[1931]: parse_headers: flags=1 Jun 25 08:43:31 sipsrv ser[1931]: Found param type 232, <branch> = <z9hG4bKe855.757a9ce3.0>; state=9 Jun 25 08:43:31 sipsrv ser[1931]: parse_via: next_via Jun 25 08:43:31 sipsrv ser[1931]: end of header reached, state=5 Jun 25 08:43:31 sipsrv ser[1931]: parse_headers: Via found, flags=1 Jun 25 08:43:31 sipsrv ser[1931]: parse_headers: this is the first via Jun 25 08:43:31 sipsrv ser[1931]: After parse_msg... Jun 25 08:43:31 sipsrv ser[1931]: forward_reply: found module tm, passing reply to it Jun 25 08:43:31 sipsrv ser[1931]: DEBUG: t_check: msg id=12 global id=2 T start=(nil) Jun 25 08:43:31 sipsrv ser[1931]: parse_headers: flags=17 Jun 25 08:43:31 sipsrv ser[1931]: DEBUG: add_param: tag=2BBC1008-1340 Jun 25 08:43:31 sipsrv ser[1931]: end of header reached, state=29 Jun 25 08:43:31 sipsrv ser[1931]: DEBUG: get_hdr_field: <To> [60]; uri=[sip:018183324166@sipsrv.conecta-te.com] Jun 25 08:43:31 sipsrv ser[1931]: DEBUG: to body [<sip:018183324166@sipsrv.conecta-te.com>] Jun 25 08:43:31 sipsrv ser[1931]: get_hdr_field: cseq <CSeq>: <101> <INVITE> Jun 25 08:43:31 sipsrv ser[1931]: parse_headers: flags=4 Jun 25 08:43:31 sipsrv ser[1931]: DEBUG: t_reply_matching: hash 21902 label 1053402967 branch 0 Jun 25 08:43:31 sipsrv ser[1931]: DEBUG: t_reply_matching: reply matched (T=0x4057c048)! Jun 25 08:43:31 sipsrv ser[1931]: DEBUG: t_check: msg id=12 global id=12 T end=0x4057c048 Jun 25 08:43:31 sipsrv ser[1931]: DEBUG: reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1) Jun 25 08:43:31 sipsrv ser[1931]: ->>>>>>>>> T_code=100, new_code=100 Jun 25 08:43:31 sipsrv ser[1931]: DEBUG: relay_reply: branch=0, save=0, relay=-1 Jun 25 08:43:31 sipsrv ser[1931]: DEBUG: add_to_tail_of_timer[1]: 0x4057c170 Jun 25 08:43:31 sipsrv ser[1931]: DEBUG:destroy_avp_list: destroying list (nil) Jun 25 08:43:31 sipsrv ser[1931]: receive_msg: cleaning up Jun 25 08:43:32 sipsrv ser[1943]: DEBUG: timer routine:4,tl=0x4057c160 next=(nil) Jun 25 08:43:36 sipsrv ser[1930]: SIP Reply (status): Jun 25 08:43:36 sipsrv ser[1930]: version: <SIP/2.0> Jun 25 08:43:36 sipsrv ser[1930]: status: <183> Jun 25 08:43:36 sipsrv ser[1930]: reason: <Session Progress> Jun 25 08:43:36 sipsrv ser[1930]: parse_headers: flags=1 Jun 25 08:43:36 sipsrv ser[1930]: Found param type 232, <branch> = <z9hG4bKe855.757a9ce3.0>; state=9 Jun 25 08:43:36 sipsrv ser[1930]: parse_via: next_via Jun 25 08:43:36 sipsrv ser[1930]: end of header reached, state=5 Jun 25 08:43:36 sipsrv ser[1930]: parse_headers: Via found, flags=1 Jun 25 08:43:36 sipsrv ser[1930]: parse_headers: this is the first via Jun 25 08:43:36 sipsrv ser[1930]: After parse_msg... Jun 25 08:43:36 sipsrv ser[1930]: forward_reply: found module tm, passing reply to it Jun 25 08:43:36 sipsrv ser[1930]: DEBUG: t_check: msg id=6 global id=2 T start=0xffffffff Jun 25 08:43:36 sipsrv ser[1930]: parse_headers: flags=17 Jun 25 08:43:36 sipsrv ser[1930]: DEBUG: add_param: tag=2BBC1008-1340 Jun 25 08:43:36 sipsrv ser[1930]: end of header reached, state=29 Jun 25 08:43:36 sipsrv ser[1930]: DEBUG: get_hdr_field: <To> [60]; uri=[sip:018183324166@sipsrv.conecta-te.com] Jun 25 08:43:36 sipsrv ser[1930]: DEBUG: to body [<sip:018183324166@sipsrv.conecta-te.com>] Jun 25 08:43:36 sipsrv ser[1930]: get_hdr_field: cseq <CSeq>: <101> <INVITE> Jun 25 08:43:36 sipsrv ser[1930]: parse_headers: flags=4 Jun 25 08:43:36 sipsrv ser[1930]: DEBUG: t_reply_matching: hash 21902 label 1053402967 branch 0 Jun 25 08:43:36 sipsrv ser[1930]: DEBUG: t_reply_matching: reply matched (T=0x4057c048)! Jun 25 08:43:36 sipsrv ser[1930]: DEBUG: t_check: msg id=6 global id=6 T end=0x4057c048 Jun 25 08:43:36 sipsrv ser[1930]: DEBUG: reply_received: org. status uas=100, uac[0]=100 local=0 is_invite=1) Jun 25 08:43:36 sipsrv ser[1930]: ->>>>>>>>> T_code=100, new_code=183 Jun 25 08:43:36 sipsrv ser[1930]: DEBUG: relay_reply: branch=0, save=0, relay=0 Jun 25 08:43:36 sipsrv ser[1930]: old size: 752, new size: 698 Jun 25 08:43:36 sipsrv ser[1930]: build_res_from_sip_res: copied size: orig:89, new: 35, rest: 663 msg= SIP/2.0 183 Session Progress^M Via: SIP/2.0/UDP 200.94.75.6:5065^M From: 8183651723 <sip:8183651723@sipsrv.conecta-te.com>;tag=7a83401cfe54b69o0^M To: <sip:018183324166@sipsrv.conecta-te.com>;tag=2BBC1008-1340^M Date: Sat, 25 Jun 2005 13:43:56 GMT^M Call-ID: 5c2d7341271e8b55e0cb066402224168(a)200.94.75.6^M Server: Cisco-SIPGateway/IOS-12.x^M CSeq: 101 INVITE^M Allow-Events: telephone-event^M Content-Type: application/sdp^M Content-Disposition: session;handling=required^M Content-Length: 212^M ^M v=0^M o=CiscoSystemsSIP-GW-UserAgent 375 1794 IN IP4 200.94.75.1^M s=SIP Call^M c=IN IP4 200.94.27.30^M t=0 0^M m=audio 16960 RTP/AVP 18^M c=IN IP4 200.94.27.30^M a=rtpmap:18 G729/8000^M a=fmtp:18 annexb=no^M a=ptime:20^M Jun 25 08:43:36 sipsrv ser[1930]: DEBUG: reply relayed. buf=0x810f708: SIP/2.0 1..., shmem=0x4057bcd8: SIP/2.0 1 Jun 25 08:43:36 sipsrv ser[1930]: DEBUG: add_to_tail_of_timer[1]: 0x4057c170 Jun 25 08:43:36 sipsrv ser[1930]: DEBUG:destroy_avp_list: destroying list (nil) Jun 25 08:43:36 sipsrv ser[1930]: receive_msg: cleaning up Jun 25 08:43:41 sipsrv ser[1935]: SIP Reply (status): Jun 25 08:43:41 sipsrv ser[1935]: version: <SIP/2.0> Jun 25 08:43:41 sipsrv ser[1935]: status: <200> Jun 25 08:43:41 sipsrv ser[1935]: reason: <OK> Jun 25 08:43:41 sipsrv ser[1935]: parse_headers: flags=1 Jun 25 08:43:41 sipsrv ser[1935]: Found param type 232, <branch> = <z9hG4bKe855.757a9ce3.0>; state=9 Jun 25 08:43:41 sipsrv ser[1935]: parse_via: next_via Jun 25 08:43:41 sipsrv ser[1935]: end of header reached, state=5 Jun 25 08:43:41 sipsrv ser[1935]: parse_headers: Via found, flags=1 Jun 25 08:43:41 sipsrv ser[1935]: parse_headers: this is the first via Jun 25 08:43:41 sipsrv ser[1935]: After parse_msg... Jun 25 08:43:41 sipsrv ser[1935]: forward_reply: found module tm, passing reply to it Jun 25 08:43:41 sipsrv ser[1935]: DEBUG: t_check: msg id=11 global id=0 T start=0xffffffff Jun 25 08:43:41 sipsrv ser[1935]: parse_headers: flags=17 Jun 25 08:43:41 sipsrv ser[1935]: DEBUG: add_param: tag=2BBC1008-1340 Jun 25 08:43:41 sipsrv ser[1935]: end of header reached, state=29 Jun 25 08:43:41 sipsrv ser[1935]: DEBUG: get_hdr_field: <To> [60]; uri=[sip:018183324166@sipsrv.conecta-te.com] Jun 25 08:43:41 sipsrv ser[1935]: DEBUG: to body [<sip:018183324166@sipsrv.conecta-te.com>] Jun 25 08:43:41 sipsrv ser[1935]: get_hdr_field: cseq <CSeq>: <101> <INVITE> Jun 25 08:43:41 sipsrv ser[1935]: parse_headers: flags=4 Jun 25 08:43:41 sipsrv ser[1935]: DEBUG: t_reply_matching: hash 21902 label 1053402967 branch 0 Jun 25 08:43:41 sipsrv ser[1935]: DEBUG: t_reply_matching: reply matched (T=0x4057c048)! Jun 25 08:43:41 sipsrv ser[1935]: parse_headers: flags=4 Jun 25 08:43:41 sipsrv ser[1935]: DEBUG: t_check: msg id=11 global id=11 T end=0x4057c048 Jun 25 08:43:41 sipsrv ser[1935]: DEBUG: reply_received: org. status uas=183, uac[0]=183 local=0 is_invite=1) Jun 25 08:43:41 sipsrv ser[1935]: ->>>>>>>>> T_code=183, new_code=200 Jun 25 08:43:41 sipsrv ser[1935]: DEBUG: relay_reply: branch=0, save=0, relay=0 Jun 25 08:43:41 sipsrv ser[1935]: old size: 886, new size: 832 Jun 25 08:43:41 sipsrv ser[1935]: build_res_from_sip_res: copied size: orig:75, new: 21, rest: 811 msg= SIP/2.0 200 OK^M Via: SIP/2.0/UDP 200.94.75.6:5065^M From: 8183651723 <sip:8183651723@sipsrv.conecta-te.com>;tag=7a83401cfe54b69o0^M To: <sip:018183324166@sipsrv.conecta-te.com>;tag=2BBC1008-1340^M Date: Sat, 25 Jun 2005 13:43:56 GMT^M Call-ID: 5c2d7341271e8b55e0cb066402224168(a)200.94.75.6^M Server: Cisco-SIPGateway/IOS-12.x^M CSeq: 101 INVITE^M Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO^M Allow-Events: telephone-event^M Contact: <sip:018183324166@200.94.75.1:5060>^M Record-Route: <sip:200.94.75.6;ftag=7a83401cfe54b69o0;lr=on>^M Content-Type: application/sdp^M Content-Length: 212^M ^M v=0^M o=CiscoSystemsSIP-GW-UserAgent 375 1794 IN IP4 200.94.75.1^M s=SIP Call^M c=IN IP4 200.94.27.30^M t=0 0^M m=audio 16960 RTP/AVP 18^M c=IN IP4 200.94.27.30^M a=rtpmap:18 G729/8000^M a=fmtp:18 annexb=no^M a=ptime:20^M Jun 25 08:43:41 sipsrv ser[1935]: DEBUG: update_totag_set: new totag Jun 25 08:43:41 sipsrv ser[1935]: DEBUG: add_to_tail_of_timer[2]: 0x4057c090 Jun 25 08:43:41 sipsrv ser[1935]: DEBUG: reply relayed. buf=0x8110388: SIP/2.0 2..., shmem=0x4057bcd8: SIP/2.0 2 Jun 25 08:43:41 sipsrv ser[1935]: DEBUG: cleanup_uac_timers: RETR/FR timers reset Jun 25 08:43:41 sipsrv ser[1935]: DEBUG:destroy_avp_list: destroying list (nil) Jun 25 08:43:41 sipsrv ser[1935]: receive_msg: cleaning up Jun 25 08:43:41 sipsrv ser[1924]: SIP Request: Jun 25 08:43:41 sipsrv ser[1924]: method: <ACK> Jun 25 08:43:41 sipsrv ser[1924]: uri: <sip:018183324166@200.94.75.6:5060> Jun 25 08:43:41 sipsrv ser[1924]: version: <SIP/2.0> Jun 25 08:43:41 sipsrv ser[1924]: parse_headers: flags=1 Jun 25 08:43:41 sipsrv ser[1924]: Found param type 232, <branch> = <z9hG4bK-76d2bc25>; state=16 Jun 25 08:43:41 sipsrv ser[1924]: end of header reached, state=5 Jun 25 08:43:41 sipsrv ser[1924]: parse_headers: Via found, flags=1 Jun 25 08:43:41 sipsrv ser[1924]: parse_headers: this is the first via Jun 25 08:43:41 sipsrv ser[1924]: After parse_msg... Jun 25 08:43:41 sipsrv ser[1924]: preparing to run routing scripts... Jun 25 08:43:41 sipsrv ser[1924]: DEBUG : sl_filter_ACK: to late to be a local ACK! Jun 25 08:43:41 sipsrv ser[1924]: parse_headers: flags=128 Jun 25 08:43:41 sipsrv ser[1924]: DEBUG: add_param: tag=2cbe59e2 Jun 25 08:43:41 sipsrv ser[1924]: end of header reached, state=29 Jun 25 08:43:41 sipsrv ser[1924]: DEBUG: get_hdr_field: <To> [55]; uri=[sip:018183324166@sipsrv.conecta-te.com] Jun 25 08:43:41 sipsrv ser[1924]: DEBUG: to body [<sip:018183324166@sipsrv.conecta-te.com>] Jun 25 08:43:41 sipsrv ser[1924]: get_hdr_field: cseq <CSeq>: <101> <ACK> Jun 25 08:43:41 sipsrv ser[1924]: DEBUG:maxfwd:is_maxfwd_present: value = 70 Jun 25 08:43:41 sipsrv ser[1924]: DBG:maxfwd:process_maxfwd_header: value 70 decreased to 16 Jun 25 08:43:41 sipsrv ser[1924]: DEBUG: add_param: tag=7a83401cfe54b69o0 Jun 25 08:43:41 sipsrv ser[1924]: end of header reached, state=29 Jun 25 08:43:41 sipsrv ser[1924]: parse_headers: flags=256 Jun 25 08:43:41 sipsrv ser[1924]: is_preloaded: No Jun 25 08:43:41 sipsrv ser[1924]: grep_sock_info - checking if host==us: 11==11 && [200.94.75.6] == [200.94.75.6] Jun 25 08:43:41 sipsrv ser[1924]: grep_sock_info - checking if port 5060 matches port 5060 Jun 25 08:43:41 sipsrv ser[1924]: grep_sock_info - checking if host==us: 11==11 && [200.94.75.6] == [200.94.75.6] Jun 25 08:43:41 sipsrv ser[1924]: grep_sock_info - checking if port 5060 matches port 5065 Jun 25 08:43:41 sipsrv ser[1924]: grep_sock_info - checking if host==us: 11==11 && [200.94.75.6] == [200.94.75.6] Jun 25 08:43:41 sipsrv ser[1924]: grep_sock_info - checking if port 5060 matches port 5065 Jun 25 08:43:41 sipsrv ser[1924]: parse_headers: flags=256 Jun 25 08:43:41 sipsrv ser[1924]: DEBUG: get_hdr_body : content_length=0 Jun 25 08:43:41 sipsrv ser[1924]: found end of header Jun 25 08:43:41 sipsrv ser[1924]: find_next_route: No next Route HF found Jun 25 08:43:41 sipsrv ser[1924]: after_strict: No next URI found Jun 25 08:43:41 sipsrv ser[1924]: grep_sock_info - checking if host==us: 11==11 && [200.94.75.6] == [200.94.75.6] Jun 25 08:43:41 sipsrv ser[1924]: grep_sock_info - checking if port 5060 matches port 5060 Jun 25 08:43:41 sipsrv ser[1924]: grep_sock_info - checking if host==us: 11==11 && [200.94.75.6] == [200.94.75.6] Jun 25 08:43:41 sipsrv ser[1924]: grep_sock_info - checking if port 5060 matches port 5060 Jun 25 08:43:41 sipsrv ser[1924]: lookup(): '018183324166' Not found in usrloc Jun 25 08:43:41 sipsrv ser[1924]: grep_sock_info - checking if host==us: 11==11 && [200.94.75.6] == [200.94.75.6] Jun 25 08:43:41 sipsrv ser[1924]: grep_sock_info - checking if port 5060 matches port 5060 Jun 25 08:43:41 sipsrv ser[1924]: PASE POR AQUI POR QUE NO SOY CANCEL, INVITE O REGISTER Jun 25 08:43:41 sipsrv ser[1924]: parse_headers: flags=-1 Jun 25 08:43:41 sipsrv ser[1924]: lookup(): '018183324166' Not found in usrloc Jun 25 08:43:41 sipsrv ser[1924]: LOOKUP LOCATION PARA CUALQUIER COSA Jun 25 08:43:41 sipsrv ser[1924]: DEBUG:destroy_avp_list: destroying list (nil) Jun 25 08:43:41 sipsrv ser[1924]: receive_msg: cleaning up Jun 25 08:43:41 sipsrv ser[1943]: DEBUG: timer routine:1,tl=0x4057c170 next=(nil) Jun 25 08:43:41 sipsrv ser[1942]: SIP Reply (status): Jun 25 08:43:41 sipsrv ser[1942]: version: <SIP/2.0> Jun 25 08:43:41 sipsrv ser[1942]: status: <200> Jun 25 08:43:41 sipsrv ser[1942]: reason: <OK> Jun 25 08:43:41 sipsrv ser[1942]: parse_headers: flags=1 Jun 25 08:43:41 sipsrv ser[1942]: Found param type 232, <branch> = <z9hG4bKe855.757a9ce3.0>; state=9 Jun 25 08:43:41 sipsrv ser[1942]: parse_via: next_via Jun 25 08:43:41 sipsrv ser[1942]: end of header reached, state=5 Jun 25 08:43:41 sipsrv ser[1942]: parse_headers: Via found, flags=1 Jun 25 08:43:41 sipsrv ser[1942]: parse_headers: this is the first via Jun 25 08:43:41 sipsrv ser[1942]: After parse_msg... Jun 25 08:43:41 sipsrv ser[1942]: forward_reply: found module tm, passing reply to it Jun 25 08:43:41 sipsrv ser[1942]: DEBUG: t_check: msg id=14 global id=2 T start=0xffffffff Jun 25 08:43:41 sipsrv ser[1942]: parse_headers: flags=17 Jun 25 08:43:41 sipsrv ser[1942]: DEBUG: add_param: tag=2BBC1008-1340 Jun 25 08:43:41 sipsrv ser[1942]: end of header reached, state=29 Jun 25 08:43:41 sipsrv ser[1942]: DEBUG: get_hdr_field: <To> [60]; uri=[sip:018183324166@sipsrv.conecta-te.com] Jun 25 08:43:41 sipsrv ser[1942]: DEBUG: to body [<sip:018183324166@sipsrv.conecta-te.com>] Jun 25 08:43:41 sipsrv ser[1942]: get_hdr_field: cseq <CSeq>: <101> <INVITE> Jun 25 08:43:41 sipsrv ser[1942]: parse_headers: flags=4 Jun 25 08:43:41 sipsrv ser[1942]: DEBUG: t_reply_matching: hash 21902 label 1053402967 branch 0 Jun 25 08:43:41 sipsrv ser[1942]: DEBUG: t_reply_matching: reply matched (T=0x4057c048)! Jun 25 08:43:41 sipsrv ser[1942]: parse_headers: flags=4 Jun 25 08:43:41 sipsrv ser[1942]: DEBUG: t_check: msg id=14 global id=14 T end=0x4057c048 Jun 25 08:43:41 sipsrv ser[1942]: DEBUG: reply_received: org. status uas=200, uac[0]=200 local=0 is_invite=1) Jun 25 08:43:41 sipsrv ser[1942]: ->>>>>>>>> T_code=200, new_code=200 Jun 25 08:43:41 sipsrv ser[1942]: DBG: t_should_relay_response: 200 INV after final sent Jun 25 08:43:41 sipsrv ser[1942]: DEBUG: relay_reply: branch=0, save=0, relay=0 Jun 25 08:43:41 sipsrv ser[1942]: old size: 886, new size: 832 Jun 25 08:43:41 sipsrv ser[1942]: build_res_from_sip_res: copied size: orig:75, new: 21, rest: 811 msg= SIP/2.0 200 OK^M Via: SIP/2.0/UDP 200.94.75.6:5065^M From: 8183651723 <sip:8183651723@sipsrv.conecta-te.com>;tag=7a83401cfe54b69o0^M To: <sip:018183324166@sipsrv.conecta-te.com>;tag=2BBC1008-1340^M Date: Sat, 25 Jun 2005 13:43:56 GMT^M Call-ID: 5c2d7341271e8b55e0cb066402224168(a)200.94.75.6^M Server: Cisco-SIPGateway/IOS-12.x^M CSeq: 101 INVITE^M Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO^M Allow-Events: telephone-event^M Contact: <sip:018183324166@200.94.75.1:5060>^M Record-Route: <sip:200.94.75.6;ftag=7a83401cfe54b69o0;lr=on>^M Content-Type: application/sdp^M Content-Length: 212^M ^M v=0^M o=CiscoSystemsSIP-GW-UserAgent 375 1794 IN IP4 200.94.75.1^M s=SIP Call^M c=IN IP4 200.94.27.30^M t=0 0^M m=audio 16960 RTP/AVP 18^M c=IN IP4 200.94.27.30^M a=rtpmap:18 G729/8000^M a=fmtp:18 annexb=no^M a=ptime:20^M Jun 25 08:43:41 sipsrv ser[1942]: DEBUG: update_totag_set: totag retransmission Jun 25 08:43:41 sipsrv ser[1942]: DEBUG: reply relayed. buf=0x8110218: SIP/2.0 2..., shmem=0x4057bcd8: SIP/2.0 2 Jun 25 08:43:41 sipsrv ser[1942]: DEBUG:destroy_avp_list: destroying list (nil) Jun 25 08:43:41 sipsrv ser[1942]: receive_msg: cleaning up Jun 25 08:43:42 sipsrv ser[1931]: SIP Reply (status): Jun 25 08:43:42 sipsrv ser[1931]: version: <SIP/2.0> Jun 25 08:43:42 sipsrv ser[1931]: status: <200> Jun 25 08:43:42 sipsrv ser[1931]: reason: <OK> Jun 25 08:43:42 sipsrv ser[1931]: parse_headers: flags=1 Jun 25 08:43:42 sipsrv ser[1931]: Found param type 232, <branch> = <z9hG4bKe855.757a9ce3.0>; state=9 Jun 25 08:43:42 sipsrv ser[1931]: parse_via: next_via Jun 25 08:43:42 sipsrv ser[1931]: end of header reached, state=5 Jun 25 08:43:42 sipsrv ser[1931]: parse_headers: Via found, flags=1 Jun 25 08:43:42 sipsrv ser[1931]: parse_headers: this is the first via Jun 25 08:43:42 sipsrv ser[1931]: After parse_msg... Jun 25 08:43:42 sipsrv ser[1931]: forward_reply: found module tm, passing reply to it Jun 25 08:43:42 sipsrv ser[1931]: DEBUG: t_check: msg id=13 global id=12 T start=0xffffffff Jun 25 08:43:42 sipsrv ser[1931]: parse_headers: flags=17 Jun 25 08:43:42 sipsrv ser[1931]: DEBUG: add_param: tag=2BBC1008-1340 Jun 25 08:43:42 sipsrv ser[1931]: end of header reached, state=29 Jun 25 08:43:42 sipsrv ser[1931]: DEBUG: get_hdr_field: <To> [60]; uri=[sip:018183324166@sipsrv.conecta-te.com] Jun 25 08:43:42 sipsrv ser[1931]: DEBUG: to body [<sip:018183324166@sipsrv.conecta-te.com>] Jun 25 08:43:42 sipsrv ser[1931]: get_hdr_field: cseq <CSeq>: <101> <INVITE> Jun 25 08:43:42 sipsrv ser[1931]: parse_headers: flags=4 Jun 25 08:43:42 sipsrv ser[1931]: DEBUG: t_reply_matching: hash 21902 label 1053402967 branch 0 Jun 25 08:43:42 sipsrv ser[1931]: DEBUG: t_reply_matching: reply matched (T=0x4057c048)! Jun 25 08:43:42 sipsrv ser[1931]: parse_headers: flags=4 Jun 25 08:43:42 sipsrv ser[1931]: DEBUG: t_check: msg id=13 global id=13 T end=0x4057c048 Jun 25 08:43:42 sipsrv ser[1931]: DEBUG: reply_received: org. status uas=200, uac[0]=200 local=0 is_invite=1) Jun 25 08:43:42 sipsrv ser[1931]: ->>>>>>>>> T_code=200, new_code=200 Jun 25 08:43:42 sipsrv ser[1931]: DBG: t_should_relay_response: 200 INV after final sent Jun 25 08:43:42 sipsrv ser[1931]: DEBUG: relay_reply: branch=0, save=0, relay=0 Jun 25 08:43:42 sipsrv ser[1931]: old size: 886, new size: 832 Jun 25 08:43:42 sipsrv ser[1931]: build_res_from_sip_res: copied size: orig:75, new: 21, rest: 811 msg= SIP/2.0 200 OK^M Via: SIP/2.0/UDP 200.94.75.6:5065^M From: 8183651723 <sip:8183651723@sipsrv.conecta-te.com>;tag=7a83401cfe54b69o0^M To: <sip:018183324166@sipsrv.conecta-te.com>;tag=2BBC1008-1340^M Date: Sat, 25 Jun 2005 13:43:56 GMT^M Call-ID: 5c2d7341271e8b55e0cb066402224168(a)200.94.75.6^M Server: Cisco-SIPGateway/IOS-12.x^M CSeq: 101 INVITE^M Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO^M Allow-Events: telephone-event^M Contact: <sip:018183324166@200.94.75.1:5060>^M Record-Route: <sip:200.94.75.6;ftag=7a83401cfe54b69o0;lr=on>^M Content-Type: application/sdp^M Content-Length: 212^M ^M v=0^M o=CiscoSystemsSIP-GW-UserAgent 375 1794 IN IP4 200.94.75.1^M s=SIP Call^M c=IN IP4 200.94.27.30^M t=0 0^M m=audio 16960 RTP/AVP 18^M c=IN IP4 200.94.27.30^M a=rtpmap:18 G729/8000^M a=fmtp:18 annexb=no^M a=ptime:20^M Jun 25 08:43:42 sipsrv ser[1931]: DEBUG: update_totag_set: totag retransmission Jun 25 08:43:42 sipsrv ser[1931]: DEBUG: reply relayed. buf=0x81102a8: SIP/2.0 2..., shmem=0x4057bcd8: SIP/2.0 2 Jun 25 08:43:42 sipsrv ser[1931]: DEBUG:destroy_avp_list: destroying list (nil) Jun 25 08:43:42 sipsrv ser[1931]: receive_msg: cleaning up Jun 25 08:43:50 sipsrv ser[1936]: SIP Request: Jun 25 08:43:50 sipsrv ser[1936]: method: <BYE> Jun 25 08:43:50 sipsrv ser[1936]: uri: <sip:018183324166@200.94.75.6:5060> Jun 25 08:43:50 sipsrv ser[1936]: version: <SIP/2.0> Jun 25 08:43:50 sipsrv ser[1936]: parse_headers: flags=1 Jun 25 08:43:50 sipsrv ser[1936]: Found param type 232, <branch> = <z9hG4bK-c79dc8ef>; state=16 Jun 25 08:43:50 sipsrv ser[1936]: end of header reached, state=5 Jun 25 08:43:50 sipsrv ser[1936]: parse_headers: Via found, flags=1 Jun 25 08:43:50 sipsrv ser[1936]: parse_headers: this is the first via Jun 25 08:43:50 sipsrv ser[1936]: After parse_msg... Jun 25 08:43:50 sipsrv ser[1936]: preparing to run routing scripts... Jun 25 08:43:50 sipsrv ser[1936]: parse_headers: flags=128 Jun 25 08:43:50 sipsrv ser[1936]: DEBUG: add_param: tag=2cbe59e2 Jun 25 08:43:50 sipsrv ser[1936]: end of header reached, state=29 Jun 25 08:43:50 sipsrv ser[1936]: DEBUG: get_hdr_field: <To> [55]; uri=[sip:018183324166@sipsrv.conecta-te.com] Jun 25 08:43:50 sipsrv ser[1936]: DEBUG: to body [<sip:018183324166@sipsrv.conecta-te.com>] Jun 25 08:43:50 sipsrv ser[1936]: get_hdr_field: cseq <CSeq>: <102> <BYE> Jun 25 08:43:50 sipsrv ser[1936]: DEBUG:maxfwd:is_maxfwd_present: value = 70 Jun 25 08:43:50 sipsrv ser[1936]: DBG:maxfwd:process_maxfwd_header: value 70 decreased to 16 Jun 25 08:43:50 sipsrv ser[1936]: DEBUG: add_param: tag=7a83401cfe54b69o0 Jun 25 08:43:50 sipsrv ser[1936]: end of header reached, state=29 Jun 25 08:43:50 sipsrv ser[1936]: parse_headers: flags=-1 Jun 25 08:43:50 sipsrv ser[1936]: DEBUG: get_hdr_body : content_length=0 Jun 25 08:43:50 sipsrv ser[1936]: found end of header Jun 25 08:43:50 sipsrv ser[1936]: parse_headers: flags=256 Jun 25 08:43:50 sipsrv ser[1936]: is_preloaded: No Jun 25 08:43:50 sipsrv ser[1936]: grep_sock_info - checking if host==us: 11==11 && [200.94.75.6] == [200.94.75.6] Jun 25 08:43:50 sipsrv ser[1936]: grep_sock_info - checking if port 5060 matches port 5060 Jun 25 08:43:50 sipsrv ser[1936]: grep_sock_info - checking if host==us: 11==11 && [200.94.75.6] == [200.94.75.6] Jun 25 08:43:50 sipsrv ser[1936]: grep_sock_info - checking if port 5060 matches port 5065 Jun 25 08:43:50 sipsrv ser[1936]: grep_sock_info - checking if host==us: 11==11 && [200.94.75.6] == [200.94.75.6] Jun 25 08:43:50 sipsrv ser[1936]: grep_sock_info - checking if port 5060 matches port 5065 Jun 25 08:43:50 sipsrv ser[1936]: parse_headers: flags=256 Jun 25 08:43:50 sipsrv ser[1936]: found end of header Jun 25 08:43:50 sipsrv ser[1936]: find_next_route: No next Route HF found Jun 25 08:43:50 sipsrv ser[1936]: after_strict: No next URI found Jun 25 08:43:50 sipsrv ser[1936]: grep_sock_info - checking if host==us: 11==11 && [200.94.75.6] == [200.94.75.6] Jun 25 08:43:50 sipsrv ser[1936]: grep_sock_info - checking if port 5060 matches port 5060 Jun 25 08:43:50 sipsrv ser[1936]: grep_sock_info - checking if host==us: 11==11 && [200.94.75.6] == [200.94.75.6] Jun 25 08:43:50 sipsrv ser[1936]: grep_sock_info - checking if port 5060 matches port 5060 Jun 25 08:43:50 sipsrv ser[1936]: Hey this request is NOT from B2BUA Jun 25 08:43:50 sipsrv ser[1936]: FORWARDING TO B2BUA Jun 25 08:43:50 sipsrv ser[1936]: parse_headers: flags=-1 Jun 25 08:43:50 sipsrv ser[1936]: parse_headers: flags=64 Jun 25 08:43:50 sipsrv ser[1936]: check_via_address(200.67.33.247, 172.31.253.127, 0) Jun 25 08:43:50 sipsrv ser[1936]: parse_headers: flags=33554432 Jun 25 08:43:50 sipsrv ser[1936]: parse_headers: flags=64 Jun 25 08:43:50 sipsrv ser[1936]: parse_headers: flags=-1 Jun 25 08:43:50 sipsrv ser[1936]: check_via_address(200.67.33.247, 172.31.253.127, 0) Jun 25 08:43:50 sipsrv ser[1936]: Sending: BYE sip:018183324166@200.94.75.6:5060 SIP/2.0^M Record-Route: <sip:200.94.75.6;ftag=7a83401cfe54b69o0;lr=on>^M Via: SIP/2.0/UDP 200.94.75.6;branch=0^M Via: SIP/2.0/UDP 172.31.253.127:5060;rport=60425;received=200.67.33.247;branch=z9hG4bK-c79dc8ef^M From: 8183651723 <sip:8183651723@sipsrv.conecta-te.com>;tag=7a83401cfe54b69o0^M To: <sip:018183324166@sipsrv.conecta-te.com>;tag=2cbe59e2^M Call-ID: b5fcf1e1-baf4a709(a)172.31.253.127^M CSeq: 102 BYE^M Max-Forwards: 16^M User-Agent: Linksys/PAP2-2.0.12(LS)^M Content-Length: 0^M P-hint: finishing call^M P-hint: PASANDO POR EL B2BUA^M P-hint: APLICO NAT AL B2BUA^M ^M . Jun 25 08:43:50 sipsrv ser[1936]: orig. len=425, new_len=600, proto=1 Jun 25 08:43:50 sipsrv ser[1936]: DEBUG:destroy_avp_list: destroying list (nil) Jun 25 08:43:50 sipsrv ser[1936]: receive_msg: cleaning up Jun 25 08:43:50 sipsrv ser[1924]: SIP Reply (status): Jun 25 08:43:50 sipsrv ser[1924]: version: <SIP/2.0> Jun 25 08:43:50 sipsrv ser[1924]: status: <200> Jun 25 08:43:50 sipsrv ser[1924]: reason: <OK> Jun 25 08:43:50 sipsrv ser[1924]: parse_headers: flags=1 Jun 25 08:43:50 sipsrv ser[1924]: Found param type 232, <branch> = <0>; state=16 Jun 25 08:43:50 sipsrv ser[1924]: end of header reached, state=5 Jun 25 08:43:50 sipsrv ser[1924]: parse_headers: Via found, flags=1 Jun 25 08:43:50 sipsrv ser[1924]: parse_headers: this is the first via Jun 25 08:43:50 sipsrv ser[1924]: After parse_msg... Jun 25 08:43:50 sipsrv ser[1924]: forward_reply: found module tm, passing reply to it Jun 25 08:43:50 sipsrv ser[1924]: DEBUG: t_check: msg id=8 global id=2 T start=0xffffffff Jun 25 08:43:50 sipsrv ser[1924]: parse_headers: flags=17 Jun 25 08:43:50 sipsrv ser[1924]: Found param type 235, <rport> = <60425>; state=6 Jun 25 08:43:50 sipsrv ser[1924]: Found param type 234, <received> = <200.67.33.247>; state=6 Jun 25 08:43:50 sipsrv ser[1924]: Found param type 232, <branch> = <z9hG4bK-c79dc8ef>; state=16 Jun 25 08:43:50 sipsrv ser[1924]: end of header reached, state=5 Jun 25 08:43:50 sipsrv ser[1924]: parse_headers: Via found, flags=17 Jun 25 08:43:50 sipsrv ser[1924]: parse_headers: this is the second via Jun 25 08:43:50 sipsrv ser[1924]: DEBUG: add_param: tag=2cbe59e2 Jun 25 08:43:50 sipsrv ser[1924]: end of header reached, state=29 Jun 25 08:43:50 sipsrv ser[1924]: DEBUG: get_hdr_field: <To> [55]; uri=[sip:018183324166@sipsrv.conecta-te.com] Jun 25 08:43:50 sipsrv ser[1924]: DEBUG: to body [<sip:018183324166@sipsrv.conecta-te.com>] Jun 25 08:43:50 sipsrv ser[1924]: get_hdr_field: cseq <CSeq>: <102> <BYE> Jun 25 08:43:50 sipsrv ser[1924]: DEBUG: t_reply_matching: failure to match a transaction Jun 25 08:43:50 sipsrv ser[1924]: DEBUG: t_check: msg id=8 global id=8 T end=(nil) Jun 25 08:43:50 sipsrv ser[1924]: parse_headers: flags=2 Jun 25 08:43:50 sipsrv ser[1924]: old size: 436, new size: 392 Jun 25 08:43:50 sipsrv ser[1924]: build_res_from_sip_res: copied size: orig:60, new: 16, rest: 376 msg= SIP/2.0 200 OK^M Via: SIP/2.0/UDP 172.31.253.127:5060;rport=60425;received=200.67.33.247;branch=z9hG4bK-c79dc8ef^M To: <sip:018183324166@sipsrv.conecta-te.com>;tag=2cbe59e2^M From: 8183651723 <sip:8183651723@sipsrv.conecta-te.com>;tag=7a83401cfe54b69o0^M Call-ID: b5fcf1e1-baf4a709(a)172.31.253.127^M CSeq: 102 BYE^M Record-Route: <sip:200.94.75.6;ftag=7a83401cfe54b69o0;lr=on>^M Content-Length: 0^M ^M Jun 25 08:43:50 sipsrv ser[1924]: update_sock_struct_from_via: using 'rport' Jun 25 08:43:50 sipsrv ser[1924]: update_sock_struct_from_via: using 'received' Jun 25 08:43:50 sipsrv ser[1924]: update_sock_struct_from_via: trying SRV lookup Jun 25 08:43:50 sipsrv ser[1924]: reply forwarded to 172.31.253.127:5060 Jun 25 08:43:50 sipsrv ser[1924]: DEBUG:destroy_avp_list: destroying list (nil) Jun 25 08:43:50 sipsrv ser[1924]: receive_msg: cleaning up Jun 25 08:43:50 sipsrv ser[1942]: SIP Request: Jun 25 08:43:50 sipsrv ser[1942]: method: <BYE> Jun 25 08:43:50 sipsrv ser[1942]: uri: <sip:200.94.75.6;lr=on> Jun 25 08:43:50 sipsrv ser[1942]: version: <SIP/2.0> Jun 25 08:43:50 sipsrv ser[1942]: parse_headers: flags=1 Jun 25 08:43:50 sipsrv ser[1942]: end of header reached, state=5 Jun 25 08:43:50 sipsrv ser[1942]: parse_headers: Via found, flags=1 Jun 25 08:43:50 sipsrv ser[1942]: parse_headers: this is the first via Jun 25 08:43:50 sipsrv ser[1942]: After parse_msg... Jun 25 08:43:50 sipsrv ser[1942]: preparing to run routing scripts... Jun 25 08:43:50 sipsrv ser[1942]: parse_headers: flags=128 Jun 25 08:43:50 sipsrv ser[1942]: DEBUG: add_param: tag=2BBC1008-1340 Jun 25 08:43:50 sipsrv ser[1942]: end of header reached, state=29 Jun 25 08:43:50 sipsrv ser[1942]: DEBUG: get_hdr_field: <To> [60]; uri=[sip:018183324166@sipsrv.conecta-te.com] Jun 25 08:43:50 sipsrv ser[1942]: DEBUG: to body [<sip:018183324166@sipsrv.conecta-te.com>] Jun 25 08:43:50 sipsrv ser[1942]: get_hdr_field: cseq <CSeq>: <102> <BYE> Jun 25 08:43:50 sipsrv ser[1942]: DEBUG:maxfwd:is_maxfwd_present: value = 70 Jun 25 08:43:50 sipsrv ser[1942]: DBG:maxfwd:process_maxfwd_header: value 70 decreased to 16 Jun 25 08:43:50 sipsrv ser[1942]: DEBUG: add_param: tag=7a83401cfe54b69o0 Jun 25 08:43:50 sipsrv ser[1942]: end of header reached, state=29 Jun 25 08:43:50 sipsrv ser[1942]: parse_headers: flags=-1 Jun 25 08:43:50 sipsrv ser[1942]: DEBUG: get_hdr_body : content_length=0 Jun 25 08:43:50 sipsrv ser[1942]: found end of header Jun 25 08:43:50 sipsrv ser[1942]: parse_headers: flags=256 Jun 25 08:43:50 sipsrv ser[1942]: is_preloaded: No Jun 25 08:43:50 sipsrv ser[1942]: grep_sock_info - checking if host==us: 11==11 && [200.94.75.6] == [200.94.75.6] Jun 25 08:43:50 sipsrv ser[1942]: grep_sock_info - checking if port 5060 matches port 5060 Jun 25 08:43:50 sipsrv ser[1942]: grep_sock_info - checking if host==us: 11==11 && [200.94.75.1] == [200.94.75.6] Jun 25 08:43:50 sipsrv ser[1942]: grep_sock_info - checking if port 5060 matches port 5060 Jun 25 08:43:50 sipsrv ser[1942]: grep_sock_info - checking if host==us: 11==11 && [200.94.75.1] == [200.94.75.6] Jun 25 08:43:50 sipsrv ser[1942]: grep_sock_info - checking if port 5060 matches port 5060 Jun 25 08:43:50 sipsrv ser[1942]: check_self: host != me Jun 25 08:43:50 sipsrv ser[1942]: after_strict: Next hop: 'sip:018183324166@200.94.75.1:5060' is strict router Jun 25 08:43:50 sipsrv ser[1942]: TOI: rewrite_uri: Rewriting Request-URI with 'sip:018183324166@200.94.75.1:5060' Jun 25 08:43:50 sipsrv ser[1942]: parse_headers: flags=-1 Jun 25 08:43:50 sipsrv ser[1942]: DEBUG: has_totag: totag found Jun 25 08:43:50 sipsrv ser[1942]: DEBUG: t_newtran: msg id=15 , global msg id=14 , T on entrance=0xffffffff Jun 25 08:43:50 sipsrv ser[1942]: parse_headers: flags=-1 Jun 25 08:43:50 sipsrv ser[1942]: parse_headers: flags=60 Jun 25 08:43:50 sipsrv ser[1942]: t_lookup_request: start searching: hash=21899, isACK=0 Jun 25 08:43:50 sipsrv ser[1942]: DEBUG: proceeding to pre-RFC3261 transaction matching Jun 25 08:43:50 sipsrv ser[1942]: DEBUG: t_lookup_request: no transaction found Jun 25 08:43:50 sipsrv ser[1942]: DBG: trans=0x40579e98, callback type 1, id 0 entered Jun 25 08:43:50 sipsrv ser[1942]: DEBUG: mk_proxy: doing DNS lookup... Jun 25 08:43:50 sipsrv ser[1942]: check_via_address(200.94.75.6, 200.94.75.6, 0) Jun 25 08:43:50 sipsrv ser[1942]: DEBUG: add_to_tail_of_timer[4]: 0x40579fb0 Jun 25 08:43:50 sipsrv ser[1942]: DEBUG: add_to_tail_of_timer[0]: 0x40579fc0 Jun 25 08:43:50 sipsrv ser[1942]: SER: new transaction fwd'ed Jun 25 08:43:50 sipsrv ser[1942]: DEBUG:destroy_avp_list: destroying list (nil) Jun 25 08:43:50 sipsrv ser[1942]: receive_msg: cleaning up Jun 25 08:43:50 sipsrv ser[1931]: SIP Reply (status): Jun 25 08:43:50 sipsrv ser[1931]: version: <SIP/2.0> Jun 25 08:43:50 sipsrv ser[1931]: status: <481> Jun 25 08:43:50 sipsrv ser[1931]: reason: <Call Leg/Transaction Does Not Exist> Jun 25 08:43:50 sipsrv ser[1931]: parse_headers: flags=1 Jun 25 08:43:50 sipsrv ser[1931]: Found param type 232, <branch> = <z9hG4bKb855.107310d2.0>; state=9 Jun 25 08:43:50 sipsrv ser[1931]: parse_via: next_via Jun 25 08:43:50 sipsrv ser[1931]: end of header reached, state=5 Jun 25 08:43:50 sipsrv ser[1931]: parse_headers: Via found, flags=1 Jun 25 08:43:50 sipsrv ser[1931]: parse_headers: this is the first via Jun 25 08:43:50 sipsrv ser[1931]: After parse_msg... Jun 25 08:43:50 sipsrv ser[1931]: forward_reply: found module tm, passing reply to it Jun 25 08:43:50 sipsrv ser[1931]: DEBUG: t_check: msg id=14 global id=13 T start=0xffffffff Jun 25 08:43:50 sipsrv ser[1931]: parse_headers: flags=17 Jun 25 08:43:50 sipsrv ser[1931]: DEBUG: add_param: tag=2BBC1008-1340 Jun 25 08:43:50 sipsrv ser[1931]: end of header reached, state=29 Jun 25 08:43:50 sipsrv ser[1931]: DEBUG: get_hdr_field: <To> [60]; uri=[sip:018183324166@sipsrv.conecta-te.com] Jun 25 08:43:50 sipsrv ser[1931]: DEBUG: to body [<sip:018183324166@sipsrv.conecta-te.com>] Jun 25 08:43:50 sipsrv ser[1931]: get_hdr_field: cseq <CSeq>: <102> <BYE> Jun 25 08:43:50 sipsrv ser[1931]: DEBUG: t_reply_matching: hash 21899 label 755054337 branch 0 Jun 25 08:43:50 sipsrv ser[1931]: DEBUG: t_reply_matching: reply matched (T=0x40579e98)! Jun 25 08:43:50 sipsrv ser[1931]: DEBUG: t_check: msg id=14 global id=14 T end=0x40579e98 Jun 25 08:43:50 sipsrv ser[1931]: DEBUG: reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0) Jun 25 08:43:50 sipsrv ser[1931]: ->>>>>>>>> T_code=0, new_code=481 Jun 25 08:43:50 sipsrv ser[1931]: DEBUG: relay_reply: branch=0, save=0, relay=0 Jun 25 08:43:50 sipsrv ser[1931]: old size: 372, new size: 318 Jun 25 08:43:50 sipsrv ser[1931]: build_res_from_sip_res: copied size: orig:108, new: 54, rest: 264 msg= SIP/2.0 481 Call Leg/Transaction Does Not Exist^M Via: SIP/2.0/UDP 200.94.75.6:5065^M From: 8183651723 <sip:8183651723@sipsrv.conecta-te.com>;tag=7a83401cfe54b69o0^M To: <sip:018183324166@sipsrv.conecta-te.com>;tag=2BBC1008-1340^M Call-ID: 5c2d7341271e8b55e0cb066402224168(a)200.94.75.6^M CSeq: 102 BYE^M Content-Length: 0^M ^M Jun 25 08:43:50 sipsrv ser[1931]: WARNING:vqm_resize: resize(0) called Jun 25 08:43:50 sipsrv ser[1931]: DEBUG: add_to_tail_of_timer[2]: 0x40579ee0 Jun 25 08:43:50 sipsrv ser[1931]: DEBUG: reply relayed. buf=0x810f708: SIP/2.0 4..., shmem=0x4057d8d8: SIP/2.0 4 Jun 25 08:43:50 sipsrv ser[1931]: DEBUG: cleanup_uac_timers: RETR/FR timers reset Jun 25 08:43:50 sipsrv ser[1931]: DEBUG:destroy_avp_list: destroying list (nil) Jun 25 08:43:50 sipsrv ser[1931]: receive_msg: cleaning up Jun 25 08:43:51 sipsrv ser[1943]: DEBUG: timer routine:0,tl=0x40579fc0 next=(nil) Jun 25 08:43:51 sipsrv ser[1943]: DEBUG: timer routine:4,tl=0x40579fb0 next=(nil) Jun 25 08:44:00 sipsrv ser[1943]: DEBUG: timer routine:2,tl=0x4057c090 next=(nil) Jun 25 08:44:00 sipsrv ser[1943]: DEBUG: wait_handler : removing 0x4057c048 from table Jun 25 08:44:00 sipsrv ser[1943]: DEBUG: delete transaction 0x4057c048 Jun 25 08:44:00 sipsrv ser[1943]: DEBUG: wait_handler : done Jun 25 08:44:10 sipsrv ser[1943]: DEBUG: timer routine:2,tl=0x40579ee0 next=(nil) Jun 25 08:44:10 sipsrv ser[1943]: DEBUG: wait_handler : removing 0x40579e98 from table Jun 25 08:44:10 sipsrv ser[1943]: DEBUG: delete transaction 0x40579e98 Jun 25 08:44:10 sipsrv ser[1943]: DEBUG: wait_handler : done # # $Id: ser.cfg,v 1.25.2.1 2005/02/18 14:30:44 andrei Exp $ # # simple quick-start config script # # ----------- global configuration parameters ------------------------ debug=5 # debug level (cmd line: -ddddd) fork=yes log_stderror=no /* Uncomment these lines to enter debugging mode fork=no log_stderror=yes # (cmd line: -E) debug=7 */ check_via=no # (cmd. line: -v) dns=no # (cmd. line: -r) rev_dns=no # (cmd. line: -R) listen=200.94.75.6 port=5060 alias=200.94.75.6 alias=sipsrv.conecta-te.com fifo_mode=0666 fifo="/tmp/ser_fifo" fifo_db_url="mysql://ser:heslo@localhost/ser" # ------------------ module loading ---------------------------------- # Uncomment this if you want to use SQL database loadmodule "/usr/local/lib/ser/modules/mysql.so" loadmodule "/usr/local/lib/ser/modules/sl.so" loadmodule "/usr/local/lib/ser/modules/tm.so" loadmodule "/usr/local/lib/ser/modules/rr.so" loadmodule "/usr/local/lib/ser/modules/maxfwd.so" loadmodule "/usr/local/lib/ser/modules/usrloc.so" loadmodule "/usr/local/lib/ser/modules/registrar.so" loadmodule "/usr/local/lib/ser/modules/auth.so" loadmodule "/usr/local/lib/ser/modules/auth_radius.so" loadmodule "/usr/local/lib/ser/modules/auth_db.so" loadmodule "/usr/local/lib/ser/modules/uri.so" loadmodule "/usr/local/lib/ser/modules/uri_db.so" loadmodule "/usr/local/lib/ser/modules/uri_radius.so" loadmodule "/usr/local/lib/ser/modules/group.so" loadmodule "/usr/local/lib/ser/modules/group_radius.so" loadmodule "/usr/local/lib/ser/modules/mediaproxy.so" loadmodule "/usr/local/lib/ser/modules/nathelper.so" loadmodule "/usr/local/lib/ser/modules/textops.so" loadmodule "/usr/local/lib/ser/modules/acc.so" loadmodule "/usr/local/lib/ser/modules/domain.so" # ----------------- setting module-specific parameters --------------- # -- usrloc params -- # modparam("usrloc", "db_mode", 0) # Uncomment this if you want to use SQL database # for persistent storage and comment the previous line modparam("usrloc", "db_mode", 2) modparam("domain", "db_mode", 1) modparam("usrloc|domain", "db_url", "mysql://ser:heslo@localhost/ser") # -- auth params -- # Uncomment if you are using auth module #modparam("auth_db", "calculate_ha1", yes) # # If you set "calculate_ha1" parameter to yes (which true in this config), # uncomment also the following parameter) #modparam("auth_db", "password_column", "password") # -- Radius Configuration -- modparam("auth_radius", "radius_config", "/usr/local/etc/radiusclient/radiusclient.conf") modparam("auth_radius", "service_type", 15) modparam("group_radius", "radius_config", "/usr/local/etc/radiusclient/radiusclient.conf") modparam("group_radius", "use_domain", 0) # -- nathelper params -- modparam("nathelper", "rtpproxy_disable", 1) modparam("nathelper", "natping_interval", 0) # -- mediaproxy params -- modparam("mediaproxy", "natping_interval", 30) modparam("mediaproxy", "mediaproxy_socket", "/var/run/mediaproxy.sock") modparam("mediaproxy", "sip_asymmetrics", "/usr/local/etc/ser/sip-clients") modparam("mediaproxy", "rtp_asymmetrics", "/usr/local/etc/ser/rtp-clients") # -- rr params -- # add value to ;lr param to make some broken UAs happy modparam("rr", "enable_full_lr", 1) modparam("registrar", "nat_flag", 6) # ------------------------- request routing logic ------------------- # main routing logic route{ #---------------------------------------------- # initial sanity checks -- messages with # max_forwards==0, or excessively long requests #---------------------------------------------- if (!mf_process_maxfwd_header("10")) { sl_send_reply("483","Too Many Hops"); break; }; if (msg:len > max_len ) { sl_send_reply("513", "Message too big"); break; }; #---------------------------------------------------- # we record-route all messages -- to make sure that # subsequent messages will go through our proxy; that's # particularly good if upstream and downstream entities # use different transport protocol #---------------------------------------------------- if (method=="INVITE" && client_nat_test("3")){ record_route_preset("200.94.75.6:5060;nat=yes"); }else if (!method=="REGISTER"){ record_route(); }; #--------------------------------------------- # we tear down the call before entering to loose route #--------------------------------------------- if (method=="BYE" || method=="CANCEL") { end_media_session(); append_hf("P-hint: finishing call\r\n"); }; #------------------------------------------------- # subsequent messages withing a dialog should take the # path determined by record-routing #------------------------------------------------- if (loose_route()) { append_hf("P-hint: rr-enforced\r\n"); # The following lines are added due media proxy if (has_totag() && (method=="INVITE" || method=="ACK")) { if (client_nat_test("3") || search("^Route:.*;nat=yes")) { # Mark as NAT'ed setflag(6); use_media_proxy(); }; }; # end media session for BYE and CANCEL is done above # before entering the loose route. no need to call it here route(1); break; }; #---------------------------------------- # processing the most common sip messages # for all the calls #---------------------------------------- if (!uri==myself) { # mark routing logic in request append_hf("P-hint: outbound\r\n"); route(1); break; }; if (uri==myself) { #--------------------------------- #all the calls from the sip uacs should #be handled by the b2bua for authorization #and accounting #--------------------------------- if (!(src_ip==200.94.75.6 || src_ip==200.94.75.1)and(method=="INVITE" || method=="BYE" || method=="CANCEL")) { log("Hey this request is NOT from B2BUA\n"); log("Forwarding to B2BUA\n"); if (client_nat_test("3")) { setflag(7); force_rport(); fix_nated_contact(); }; forward(200.94.75.6,5065); break; }; if (method=="CANCEL" || method=="INVITE") { route(3); break; } else if (method=="REGISTER") { route(2); break; }; route(4); if (!lookup("location")) { sl_send_reply("404", "User Not Found"); break; }; }; route(1); } route[1] { #------------------------------- # Default SIP message handler # forward to current uri now; use stateful forwarding; that # works reliably even if we forward from TCP to UDP #------------------------------ t_on_reply("1"); if (!t_relay()) { if (method=="INVITE" || method=="ACK") { end_media_session(); append_hf("P-hint: finishing call no-relay\r\n"); }; sl_reply_error(); }; } route[2] { #--------------------------- # "REGISTER" message handler #--------------------------- sl_send_reply("100", "Trying"); if (!search("^Contact:\ +\*") && client_nat_test("7")) { setflag(6); fix_nated_register(); force_rport(); }; if (is_from_local() || uri==myself) { if (!radius_www_authorize("")) { www_challenge("", "0"); break; } else if (!check_to()){ sl_send_reply("403", "Username!=To not allowed"); break; }; if (!save("location")) { sl_reply_error(); }; } else { append_hf("P-hint: outbound alias\r\n"); sl_send_reply("403", "This domain is not served here"); }; } route[3] { #-------------------------- #"CANCEL" and "INVITE" message handler #-------------------------- if (client_nat_test("3")) { setflag(7); force_rport(); fix_nated_contact(); }; if (method=="INVITE") { if (!(is_from_local() || uri==myself || is_uri_host_local())) { sl_send_reply("403", "Relaying is forbidden"); break; }; } else if (method=="CANCEL") { route(1); break; }; route(4); if (!lookup("location")) { if ((uri=~"sip:01[1-9][0-9]+@.*") || (uri=~"sip:00[1-9][0-9]+@.*")) { rewritehost("200.94.75.1"); }; } else { sl_send_reply("404", "User not found"); break; }; #------------------------------------- #RTP Proxy handler #------------------------------------- if (isflagset(6) || isflagset(7)) { use_media_proxy(); append_hf("P-hint: are you nated?\r\n"); }; route(1); } route[4] { #--------------- #we need to check for the alias #--------------- lookup("aliases"); if (uri!=myself) { route(1); break; }; } failure_route[1] { end_media_session(); append_hf("P-hint: finishing call on failure\r\n"); } onreply_route[1] { if ((isflagset(6) || isflagset(7)) && (status=~"(180)|(183)|(2[0-9][0-9])")) { if (client_nat_test("1")) { fix_nated_contact(); }; if (!search("^Content-Length:\ +0")) { use_media_proxy(); append_hf("P-hint: use nat for call\r\n"); }; }; }