BYE message is not relayed to the UAC
Hi, We have the following network architecture : UAC1------------------------->kamailio-------------------->VoipSwitch----->PSTN---------->Phone1 (Sip Client) Now UAC1 calls Phone1 and everything is ok. If UAC1 hangs up session is terminated cleanly. But if Phone1 hangs up the BYE message which comes to kamailio and goes back to VoipSwitch instead of relayed to UAC1 . So The session becomes a zombie one, And UAC1 unfortunately gets billed for a session which should be terminated. Following is the Call flow as seen from VoipSwitch : | <kamilio IP> | | | | <VoipSwitch IP> | |134.856 | INVITE SDP | |(7890) ------------------> (5060) | |134.858 | 407 Proxy Authentication Required | |(7890) <------------------ (5060) | |134.902 | ACK | | |(7890) ------------------> (5060) | |135.408 | INVITE SDP | |(7890) ------------------> (5060) | |135.414 | 100 Trying| | |(7890) <------------------ (5060) | |140.121 | 183 Session Progress SDP | |(7890) <------------------ (5060) | |140.184 | RTP (g729) | | |(61868) <------------------ (5136) | |141.295 | RTP (g729) | | |(61868) ------------------> (5136) | |153.701 | 200 OK SDP | |(7890) <------------------ (5060) | |153.713 | RTP (g729) | | |(61868) ------------------> (5136) | |154.126 | ACK | | |(7890) ------------------> (5060) | |159.988 | BYE | | |(7890) <------------------ (5060) | |160.031 | BYE | | |(7890) ------------------> (5060) | |160.478 | BYE | | |(7890) ------------------> (5060) | |161.412 | BYE | | |(7890) ------------------> (5060) | |163.280 | BYE | | |(7890) ------------------> (5060) | |167.015 | BYE | | |(7890) ------------------> (5060) | |170.750 | BYE | | |(7890) ------------------> (5060) | |174.481 | BYE | | |(7890) ------------------> (5060) | |178.216 | BYE | | |(7890) ------------------> (5060) | |181.952 | BYE | | |(7890) ------------------> (5060) | |185.687 | BYE | | |(7890) ------------------> (5060) | |188.018 | 408 Request Timeout | |(7890) ------------------> (5060) | |211.849 | BYE | | |(7890) ------------------> (5060) | |212.292 | BYE | Sip Traces : kamailio------>VoipSwitch I'm posting only the offending BYE msg instead of full trace , because of the mail will become difficult to read . If more traces needed, i can post it. The following BYE message is sent by VoipSwitch: BYE sip:ipphone@205.164.40.74 SIP/2.0 Route: <sip:108.166.195.189:7890;lr=on;nat=yes> CSeq: 2 BYE Via: SIP/2.0/UDP 205.164.40.74:5060 From: sip:008801673345531@205.164.40.74;tag=100528120745985872655137 Call-ID: IqBknV19AuxW0jk.8BjuE4hyx93Ws9qS To: "123456" <sip:ipphone@205.164.40.74>;tag=Zopl5lj5YiqyaSR5Le3QnfoR-G0NZAGG Content-Length: 0 Kamailio instead of relaying the message, sends a BYE message towards VoipSwitch: BYE sip:ipphone@205.164.40.74 SIP/2.0 Max-Forwards: 10 CSeq: 2 BYE Via: SIP/2.0/UDP 108.166.195.189:7890;branch=z9hG4bK4b2b.5d893e95.0 Via: SIP/2.0/UDP 205.164.40.74:5060;rport=5060 From: sip:008801673345531@205.164.40.74;tag=100528120745985872655137 Call-ID: IqBknV19AuxW0jk.8BjuE4hyx93Ws9qS To: "123456" <sip:ipphone@205.164.40.74>;tag=Zopl5lj5YiqyaSR5Le3QnfoR-G0NZAGG Content-Length: 0 When the first BYE message comes from VoipSwitch , kamailio does the following : May 20 02:25:53 VOS20-108 /usr/local/sbin/kamailio[16442]: DEBUG: <core> [receive.c:289]: receive_msg: cleaning up May 20 02:25:53 VOS20-108 /usr/local/sbin/kamailio[16442]: DEBUG: <core> [parser/sdp/sdp.c:751]: _sdp = 0x831bf10 May 20 02:25:53 VOS20-108 /usr/local/sbin/kamailio[16442]: DEBUG: <core> [parser/sdp/sdp.c:753]: sdp = 0x83043dc May 20 02:25:53 VOS20-108 /usr/local/sbin/kamailio[16442]: DEBUG: <core> [parser/sdp/sdp.c:755]: session = 0x8304504 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:630]: SIP Request: May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:632]: method: <BYE> May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:634]: uri: <sip:ipphone@205.164.40.74> May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:636]: version: <SIP/2.0> May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:167]: get_hdr_field: cseq <CSeq>: <1> <BYE> May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/parse_via.c:1287]: Found param type 232, <branch> = <z9hG4bk19052612230719933454843>; state=16 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/parse_via.c:2300]: end of header reached, state=5 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:515]: parse_headers: Via found, flags=2 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:517]: parse_headers: this is the first via May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [receive.c:145]: After parse_msg... May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [receive.c:186]: preparing to run routing scripts... May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=arILprdVR1srJ76HHlt4BEc3XsyaWcZm May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/parse_to.c:803]: end of header reached, state=29 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: get_hdr_field: <To> [76]; uri=[sip:ipphone@205.164.40.74] May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:189]: DEBUG: to body ["ipphone" <sip:ipphone@205.164.40.74>] May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:201]: DEBUG: get_hdr_body : content_length=0 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:103]: found end of header May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: maxfwd [mf_funcs.c:66]: max_forwards header not found! May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=1905251223419334290936029 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/parse_to.c:803]: end of header reached, state=29 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: siputils [checks.c:76]: totag found May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: rr [loose.c:85]: is_preloaded: No May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking if host==us: 13==15 && [205.164.40.74] == [108.166.195.189] May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking if port 7890 matches port 5060 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking if host==us: 13==15 && [205.164.40.74] == [108.166.195.189] May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking if port 5060 matches port 5060 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [forward.c:448]: check_self: host != me May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking if host==us: 15==15 && [108.166.195.189] == [108.166.195.189] May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking if port 7890 matches port 7890 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: rr [loose.c:792]: Topmost route URI: 'sip:108.166.195.189:7890;lr=on;nat=yes' is me May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:103]: found end of header May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: rr [loose.c:257]: No next Route HF found May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: rr [loose.c:811]: No next URI found May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: rr [loose.c:983]: params are <;lr=on;nat=yes> May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: siputils [checks.c:76]: totag found May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: tm [t_lookup.c:1379]: DEBUG: t_newtran: msg id=2501 , global msg id=2500 , T on entrance=0xffffffff May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: tm [t_lookup.c:528]: t_lookup_request: start searching: hash=29177, isACK=0 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: tm [t_lookup.c:564]: DEBUG: proceeding to pre-RFC3261 transaction matching May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: tm [t_lookup.c:711]: DEBUG: t_lookup_request: no transaction found May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: tm [t_hooks.c:374]: DBG: trans=0xb61626a4, callback type 1, id 0 entered May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [msg_translator.c:204]: check_via_address(205.164.40.74, 205.164.40.74, 0) May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: tm [t_funcs.c:388]: SER: new transaction fwd'ed May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil) May 20 02:26:04 VOS20-108 last message repeated 5 times May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [receive.c:289]: receive_msg: cleaning up May 20 02:26:22 VOS20-108 /usr/local/sbin/kamailio[16445]: DEBUG: <core> [udp_server.c:486]: udp_rcv_loop: probing packet received from 180.234.62.230 38722 May 20 02:26:34 VOS20-108 /usr/local/sbin/kamailio[16450]: DEBUG: tm [t_reply.c:1134]: ->>>>>>>>> T_code=0, new_code=408 May 20 02:26:34 VOS20-108 /usr/local/sbin/kamailio[16450]: DEBUG: tm [t_reply.c:1636]: DEBUG: relay_reply: branch=0, save=0, relay=0 May 20 02:26:34 VOS20-108 /usr/local/sbin/kamailio[16450]: DEBUG: <core> [msg_translator.c:204]: check_via_address(205.164.40.74, 205.164.40.74, 0) May 20 02:26:34 VOS20-108 /usr/local/sbin/kamailio[16450]: DEBUG: <core> [mem/shm_mem.c:105]: WARNING:vqm_resize: resize(0) called May 20 02:26:34 VOS20-108 /usr/local/sbin/kamailio[16450]: DEBUG: tm [t_hooks.c:288]: DBG: trans=0xb61626a4, callback type 128, id 0 entered May 20 02:26:54 VOS20-108 /usr/local/sbin/kamailio[16451]: WARNING: <core> [timer.c:450]: WARNING: our timer runs faster then real-time (300000 ms / 4800 ticks our time .-> 299923 ms / 4798 ticks real time) OT: How do you guys maintain 80 column mails? i do not use a mail client, use gmail mailbox. -- -aft -- -aft
Your best bet is to use a pastebin for this sort of thing. The FreeSWITCH project maintains their own at pastebin.freeswitch.org. There are numerous others (pastie, pastebin.com, etc.) After you put all the information in a pastebin you'll get a handy URL that you can include in the email thread. One other advantage to pastebins is that you can refer to a specific line number in paste. ("Look at the BYE message at line xxx - it looks unusual...") -MC On Mon, May 21, 2012 at 12:26 AM, Arif Hossain <aftnix@gmail.com> wrote:
Hi,
We have the following network architecture :
UAC1------------------------->kamailio-------------------->VoipSwitch----->PSTN---------->Phone1 (Sip Client)
Now UAC1 calls Phone1 and everything is ok. If UAC1 hangs up session is terminated cleanly. But if Phone1 hangs up the BYE message which comes to kamailio and goes back to VoipSwitch instead of relayed to UAC1 .
So The session becomes a zombie one, And UAC1 unfortunately gets billed for a session which should be terminated.
Following is the Call flow as seen from VoipSwitch :
| <kamilio IP> | | | | <VoipSwitch IP> | |134.856 | INVITE SDP | |(7890) ------------------> (5060) | |134.858 | 407 Proxy Authentication Required | |(7890) <------------------ (5060) | |134.902 | ACK | | |(7890) ------------------> (5060) | |135.408 | INVITE SDP | |(7890) ------------------> (5060) | |135.414 | 100 Trying| | |(7890) <------------------ (5060) | |140.121 | 183 Session Progress SDP | |(7890) <------------------ (5060) | |140.184 | RTP (g729) | | |(61868) <------------------ (5136) | |141.295 | RTP (g729) | | |(61868) ------------------> (5136) | |153.701 | 200 OK SDP | |(7890) <------------------ (5060) | |153.713 | RTP (g729) | | |(61868) ------------------> (5136) | |154.126 | ACK | | |(7890) ------------------> (5060) | |159.988 | BYE | | |(7890) <------------------ (5060) | |160.031 | BYE | | |(7890) ------------------> (5060) | |160.478 | BYE | | |(7890) ------------------> (5060) | |161.412 | BYE | | |(7890) ------------------> (5060) | |163.280 | BYE | | |(7890) ------------------> (5060) | |167.015 | BYE | | |(7890) ------------------> (5060) | |170.750 | BYE | | |(7890) ------------------> (5060) | |174.481 | BYE | | |(7890) ------------------> (5060) | |178.216 | BYE | | |(7890) ------------------> (5060) | |181.952 | BYE | | |(7890) ------------------> (5060) | |185.687 | BYE | | |(7890) ------------------> (5060) | |188.018 | 408 Request Timeout | |(7890) ------------------> (5060) | |211.849 | BYE | | |(7890) ------------------> (5060) | |212.292 | BYE |
Sip Traces :
kamailio------>VoipSwitch
I'm posting only the offending BYE msg instead of full trace , because of the mail will become difficult to read . If more traces needed, i can post it.
The following BYE message is sent by VoipSwitch:
BYE sip:ipphone@205.164.40.74 SIP/2.0 Route: <sip:108.166.195.189:7890;lr=on;nat=yes> CSeq: 2 BYE Via: SIP/2.0/UDP 205.164.40.74:5060 From: sip:008801673345531@205.164.40.74;tag=100528120745985872655137 Call-ID: IqBknV19AuxW0jk.8BjuE4hyx93Ws9qS To: "123456" <sip:ipphone@205.164.40.74
;tag=Zopl5lj5YiqyaSR5Le3QnfoR-G0NZAGG Content-Length: 0
Kamailio instead of relaying the message, sends a BYE message towards VoipSwitch:
BYE sip:ipphone@205.164.40.74 SIP/2.0 Max-Forwards: 10 CSeq: 2 BYE Via: SIP/2.0/UDP 108.166.195.189:7890;branch=z9hG4bK4b2b.5d893e95.0 Via: SIP/2.0/UDP 205.164.40.74:5060;rport=5060 From: sip:008801673345531@205.164.40.74;tag=100528120745985872655137 Call-ID: IqBknV19AuxW0jk.8BjuE4hyx93Ws9qS To: "123456" <sip:ipphone@205.164.40.74
;tag=Zopl5lj5YiqyaSR5Le3QnfoR-G0NZAGG Content-Length: 0
When the first BYE message comes from VoipSwitch , kamailio does the following : May 20 02:25:53 VOS20-108 /usr/local/sbin/kamailio[16442]: DEBUG: <core> [receive.c:289]: receive_msg: cleaning up May 20 02:25:53 VOS20-108 /usr/local/sbin/kamailio[16442]: DEBUG: <core> [parser/sdp/sdp.c:751]: _sdp = 0x831bf10 May 20 02:25:53 VOS20-108 /usr/local/sbin/kamailio[16442]: DEBUG: <core> [parser/sdp/sdp.c:753]: sdp = 0x83043dc May 20 02:25:53 VOS20-108 /usr/local/sbin/kamailio[16442]: DEBUG: <core> [parser/sdp/sdp.c:755]: session = 0x8304504 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:630]: SIP Request: May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:632]: method: <BYE> May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:634]: uri: <sip:ipphone@205.164.40.74> May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:636]: version: <SIP/2.0> May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:167]: get_hdr_field: cseq <CSeq>: <1> <BYE> May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/parse_via.c:1287]: Found param type 232, <branch> = <z9hG4bk19052612230719933454843>; state=16 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/parse_via.c:2300]: end of header reached, state=5 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:515]: parse_headers: Via found, flags=2 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:517]: parse_headers: this is the first via May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [receive.c:145]: After parse_msg... May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [receive.c:186]: preparing to run routing scripts... May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=arILprdVR1srJ76HHlt4BEc3XsyaWcZm May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/parse_to.c:803]: end of header reached, state=29 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: get_hdr_field: <To> [76]; uri=[sip:ipphone@205.164.40.74] May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:189]: DEBUG: to body ["ipphone" <sip:ipphone@205.164.40.74>] May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:201]: DEBUG: get_hdr_body : content_length=0 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:103]: found end of header May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: maxfwd [mf_funcs.c:66]: max_forwards header not found! May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=1905251223419334290936029 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/parse_to.c:803]: end of header reached, state=29 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: siputils [checks.c:76]: totag found May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: rr [loose.c:85]: is_preloaded: No May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking if host==us: 13==15 && [205.164.40.74] == [108.166.195.189] May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking if port 7890 matches port 5060 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking if host==us: 13==15 && [205.164.40.74] == [108.166.195.189] May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking if port 5060 matches port 5060 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [forward.c:448]: check_self: host != me May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking if host==us: 15==15 && [108.166.195.189] == [108.166.195.189] May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking if port 7890 matches port 7890 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: rr [loose.c:792]: Topmost route URI: 'sip:108.166.195.189:7890;lr=on;nat=yes' is me May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:103]: found end of header May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: rr [loose.c:257]: No next Route HF found May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: rr [loose.c:811]: No next URI found May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: rr [loose.c:983]: params are <;lr=on;nat=yes> May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: siputils [checks.c:76]: totag found May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: tm [t_lookup.c:1379]: DEBUG: t_newtran: msg id=2501 , global msg id=2500 , T on entrance=0xffffffff May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: tm [t_lookup.c:528]: t_lookup_request: start searching: hash=29177, isACK=0 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: tm [t_lookup.c:564]: DEBUG: proceeding to pre-RFC3261 transaction matching May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: tm [t_lookup.c:711]: DEBUG: t_lookup_request: no transaction found May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: tm [t_hooks.c:374]: DBG: trans=0xb61626a4, callback type 1, id 0 entered May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [msg_translator.c:204]: check_via_address(205.164.40.74, 205.164.40.74, 0) May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: tm [t_funcs.c:388]: SER: new transaction fwd'ed May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil) May 20 02:26:04 VOS20-108 last message repeated 5 times May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [receive.c:289]: receive_msg: cleaning up May 20 02:26:22 VOS20-108 /usr/local/sbin/kamailio[16445]: DEBUG: <core> [udp_server.c:486]: udp_rcv_loop: probing packet received from 180.234.62.230 38722 May 20 02:26:34 VOS20-108 /usr/local/sbin/kamailio[16450]: DEBUG: tm [t_reply.c:1134]: ->>>>>>>>> T_code=0, new_code=408 May 20 02:26:34 VOS20-108 /usr/local/sbin/kamailio[16450]: DEBUG: tm [t_reply.c:1636]: DEBUG: relay_reply: branch=0, save=0, relay=0 May 20 02:26:34 VOS20-108 /usr/local/sbin/kamailio[16450]: DEBUG: <core> [msg_translator.c:204]: check_via_address(205.164.40.74, 205.164.40.74, 0) May 20 02:26:34 VOS20-108 /usr/local/sbin/kamailio[16450]: DEBUG: <core> [mem/shm_mem.c:105]: WARNING:vqm_resize: resize(0) called May 20 02:26:34 VOS20-108 /usr/local/sbin/kamailio[16450]: DEBUG: tm [t_hooks.c:288]: DBG: trans=0xb61626a4, callback type 128, id 0 entered May 20 02:26:54 VOS20-108 /usr/local/sbin/kamailio[16451]: WARNING: <core> [timer.c:450]: WARNING: our timer runs faster then real-time (300000 ms / 4800 ticks our time .-> 299923 ms / 4798 ticks real time)
OT: How do you guys maintain 80 column mails? i do not use a mail client, use gmail mailbox. -- -aft
-- -aft
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
Join Us At ClueCon - Aug 7-9, 2012
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
On Mon, May 21, 2012 at 10:22 PM, Michael Collins <msc@freeswitch.org> wrote:
Your best bet is to use a pastebin for this sort of thing. The FreeSWITCH project maintains their own at pastebin.freeswitch.org. There are numerous others (pastie, pastebin.com, etc.) After you put all the information in a pastebin you'll get a handy URL that you can include in the email thread. One other advantage to pastebins is that you can refer to a specific line number in paste. ("Look at the BYE message at line xxx - it looks unusual...")
-MC
freeswitch's pastebin asks for authentication.
On Mon, May 21, 2012 at 12:26 AM, Arif Hossain <aftnix@gmail.com> wrote:
Hi,
We have the following network architecture :
UAC1------------------------->kamailio-------------------->VoipSwitch----->PSTN---------->Phone1 (Sip Client)
Now UAC1 calls Phone1 and everything is ok. If UAC1 hangs up session is terminated cleanly. But if Phone1 hangs up the BYE message which comes to kamailio and goes back to VoipSwitch instead of relayed to UAC1 .
So The session becomes a zombie one, And UAC1 unfortunately gets billed for a session which should be terminated.
Following is the Call flow as seen from VoipSwitch :
| <kamilio IP> | | | | <VoipSwitch IP> | |134.856 | INVITE SDP | |(7890) ------------------> (5060) | |134.858 | 407 Proxy Authentication Required | |(7890) <------------------ (5060) | |134.902 | ACK | | |(7890) ------------------> (5060) | |135.408 | INVITE SDP | |(7890) ------------------> (5060) | |135.414 | 100 Trying| | |(7890) <------------------ (5060) | |140.121 | 183 Session Progress SDP | |(7890) <------------------ (5060) | |140.184 | RTP (g729) | | |(61868) <------------------ (5136) | |141.295 | RTP (g729) | | |(61868) ------------------> (5136) | |153.701 | 200 OK SDP | |(7890) <------------------ (5060) | |153.713 | RTP (g729) | | |(61868) ------------------> (5136) | |154.126 | ACK | | |(7890) ------------------> (5060) | |159.988 | BYE | | |(7890) <------------------ (5060) | |160.031 | BYE | | |(7890) ------------------> (5060) | |160.478 | BYE | | |(7890) ------------------> (5060) | |161.412 | BYE | | |(7890) ------------------> (5060) | |163.280 | BYE | | |(7890) ------------------> (5060) | |167.015 | BYE | | |(7890) ------------------> (5060) | |170.750 | BYE | | |(7890) ------------------> (5060) | |174.481 | BYE | | |(7890) ------------------> (5060) | |178.216 | BYE | | |(7890) ------------------> (5060) | |181.952 | BYE | | |(7890) ------------------> (5060) | |185.687 | BYE | | |(7890) ------------------> (5060) | |188.018 | 408 Request Timeout | |(7890) ------------------> (5060) | |211.849 | BYE | | |(7890) ------------------> (5060) | |212.292 | BYE |
Sip Traces :
kamailio------>VoipSwitch
I'm posting only the offending BYE msg instead of full trace , because of the mail will become difficult to read . If more traces needed, i can post it.
The following BYE message is sent by VoipSwitch:
BYE sip:ipphone@205.164.40.74 SIP/2.0 Route: <sip:108.166.195.189:7890;lr=on;nat=yes> CSeq: 2 BYE Via: SIP/2.0/UDP 205.164.40.74:5060 From: sip:008801673345531@205.164.40.74;tag=100528120745985872655137 Call-ID: IqBknV19AuxW0jk.8BjuE4hyx93Ws9qS To: "123456" <sip:ipphone@205.164.40.74>;tag=Zopl5lj5YiqyaSR5Le3QnfoR-G0NZAGG Content-Length: 0
Kamailio instead of relaying the message, sends a BYE message towards VoipSwitch:
BYE sip:ipphone@205.164.40.74 SIP/2.0 Max-Forwards: 10 CSeq: 2 BYE Via: SIP/2.0/UDP 108.166.195.189:7890;branch=z9hG4bK4b2b.5d893e95.0 Via: SIP/2.0/UDP 205.164.40.74:5060;rport=5060 From: sip:008801673345531@205.164.40.74;tag=100528120745985872655137 Call-ID: IqBknV19AuxW0jk.8BjuE4hyx93Ws9qS To: "123456" <sip:ipphone@205.164.40.74>;tag=Zopl5lj5YiqyaSR5Le3QnfoR-G0NZAGG Content-Length: 0
When the first BYE message comes from VoipSwitch , kamailio does the following : May 20 02:25:53 VOS20-108 /usr/local/sbin/kamailio[16442]: DEBUG: <core> [receive.c:289]: receive_msg: cleaning up May 20 02:25:53 VOS20-108 /usr/local/sbin/kamailio[16442]: DEBUG: <core> [parser/sdp/sdp.c:751]: _sdp = 0x831bf10 May 20 02:25:53 VOS20-108 /usr/local/sbin/kamailio[16442]: DEBUG: <core> [parser/sdp/sdp.c:753]: sdp = 0x83043dc May 20 02:25:53 VOS20-108 /usr/local/sbin/kamailio[16442]: DEBUG: <core> [parser/sdp/sdp.c:755]: session = 0x8304504 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:630]: SIP Request: May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:632]: method: <BYE> May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:634]: uri: <sip:ipphone@205.164.40.74> May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:636]: version: <SIP/2.0> May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:167]: get_hdr_field: cseq <CSeq>: <1> <BYE> May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/parse_via.c:1287]: Found param type 232, <branch> = <z9hG4bk19052612230719933454843>; state=16 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/parse_via.c:2300]: end of header reached, state=5 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:515]: parse_headers: Via found, flags=2 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:517]: parse_headers: this is the first via May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [receive.c:145]: After parse_msg... May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [receive.c:186]: preparing to run routing scripts... May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=arILprdVR1srJ76HHlt4BEc3XsyaWcZm May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/parse_to.c:803]: end of header reached, state=29 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: get_hdr_field: <To> [76]; uri=[sip:ipphone@205.164.40.74] May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:189]: DEBUG: to body ["ipphone" <sip:ipphone@205.164.40.74>] May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:201]: DEBUG: get_hdr_body : content_length=0 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:103]: found end of header May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: maxfwd [mf_funcs.c:66]: max_forwards header not found! May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=1905251223419334290936029 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/parse_to.c:803]: end of header reached, state=29 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: siputils [checks.c:76]: totag found May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: rr [loose.c:85]: is_preloaded: No May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking if host==us: 13==15 && [205.164.40.74] == [108.166.195.189] May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking if port 7890 matches port 5060 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking if host==us: 13==15 && [205.164.40.74] == [108.166.195.189] May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking if port 5060 matches port 5060 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [forward.c:448]: check_self: host != me May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking if host==us: 15==15 && [108.166.195.189] == [108.166.195.189] May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking if port 7890 matches port 7890 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: rr [loose.c:792]: Topmost route URI: 'sip:108.166.195.189:7890;lr=on;nat=yes' is me May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [parser/msg_parser.c:103]: found end of header May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: rr [loose.c:257]: No next Route HF found May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: rr [loose.c:811]: No next URI found May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: rr [loose.c:983]: params are <;lr=on;nat=yes> May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: siputils [checks.c:76]: totag found May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: tm [t_lookup.c:1379]: DEBUG: t_newtran: msg id=2501 , global msg id=2500 , T on entrance=0xffffffff May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: tm [t_lookup.c:528]: t_lookup_request: start searching: hash=29177, isACK=0 May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: tm [t_lookup.c:564]: DEBUG: proceeding to pre-RFC3261 transaction matching May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: tm [t_lookup.c:711]: DEBUG: t_lookup_request: no transaction found May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: tm [t_hooks.c:374]: DBG: trans=0xb61626a4, callback type 1, id 0 entered May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [msg_translator.c:204]: check_via_address(205.164.40.74, 205.164.40.74, 0) May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: tm [t_funcs.c:388]: SER: new transaction fwd'ed May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil) May 20 02:26:04 VOS20-108 last message repeated 5 times May 20 02:26:04 VOS20-108 /usr/local/sbin/kamailio[16443]: DEBUG: <core> [receive.c:289]: receive_msg: cleaning up May 20 02:26:22 VOS20-108 /usr/local/sbin/kamailio[16445]: DEBUG: <core> [udp_server.c:486]: udp_rcv_loop: probing packet received from 180.234.62.230 38722 May 20 02:26:34 VOS20-108 /usr/local/sbin/kamailio[16450]: DEBUG: tm [t_reply.c:1134]: ->>>>>>>>> T_code=0, new_code=408 May 20 02:26:34 VOS20-108 /usr/local/sbin/kamailio[16450]: DEBUG: tm [t_reply.c:1636]: DEBUG: relay_reply: branch=0, save=0, relay=0 May 20 02:26:34 VOS20-108 /usr/local/sbin/kamailio[16450]: DEBUG: <core> [msg_translator.c:204]: check_via_address(205.164.40.74, 205.164.40.74, 0) May 20 02:26:34 VOS20-108 /usr/local/sbin/kamailio[16450]: DEBUG: <core> [mem/shm_mem.c:105]: WARNING:vqm_resize: resize(0) called May 20 02:26:34 VOS20-108 /usr/local/sbin/kamailio[16450]: DEBUG: tm [t_hooks.c:288]: DBG: trans=0xb61626a4, callback type 128, id 0 entered May 20 02:26:54 VOS20-108 /usr/local/sbin/kamailio[16451]: WARNING: <core> [timer.c:450]: WARNING: our timer runs faster then real-time (300000 ms / 4800 ticks our time .-> 299923 ms / 4798 ticks real time)
OT: How do you guys maintain 80 column mails? i do not use a mail client, use gmail mailbox. -- -aft
-- -aft
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
Join Us At ClueCon - Aug 7-9, 2012
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
Join Us At ClueCon - Aug 7-9, 2012
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- -aft
On Mon, May 21, 2012 at 12:33 PM, Arif Hossain <aftnix@gmail.com> wrote:
On Mon, May 21, 2012 at 10:22 PM, Michael Collins <msc@freeswitch.org> wrote:
Your best bet is to use a pastebin for this sort of thing. The FreeSWITCH project maintains their own at pastebin.freeswitch.org. There are numerous others (pastie, pastebin.com, etc.) After you put all the information in a pastebin you'll get a handy URL that you can include in the email thread. One other advantage to pastebins is that you can refer to a specific line number in paste. ("Look at the BYE message at line xxx - it looks unusual...")
-MC
freeswitch's pastebin asks for authentication.
Yes, it does. ;) -MC
Someone else failed the IQ test it seems... I mean really people how hard is it to READ that little popup box that tells you want to put in there K On 5/21/12 2:35 PM, "Michael Collins" <msc@freeswitch.org> wrote:
On Mon, May 21, 2012 at 12:33 PM, Arif Hossain <aftnix@gmail.com> wrote:
On Mon, May 21, 2012 at 10:22 PM, Michael Collins <msc@freeswitch.org> wrote:
Your best bet is to use a pastebin for this sort of thing. The FreeSWITCH project maintains their own at pastebin.freeswitch.org <http://pastebin.freeswitch.org> . There are numerous others (pastie, pastebin.com <http://pastebin.com> , etc.) After you put all the information in a pastebin you'll get a handy URL that you can include in the email thread. One other advantage to pastebins is that you can refer to a specific line number in paste. ("Look at the BYE message at line xxx - it looks unusual...")
-MC
freeswitch's pastebin asks for authentication.
Yes, it does. ;)
-MC
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
Join Us At ClueCon - Aug 7-9, 2012
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
On Tue, May 22, 2012 at 1:38 AM, Ken Rice <krice@freeswitch.org> wrote:
Someone else failed the IQ test it seems...
I mean really people how hard is it to READ that little popup box that tells you want to put in there
Hi Ken, I can hear laughter sounds from here, deep inside asia :) -- -aft
On Tue, May 22, 2012 at 1:35 AM, Michael Collins <msc@freeswitch.org> wrote:
Yes, it does. ;)
-MC
Ok done http://pastebin.freeswitch.org/19136 now we can talk problems :) -- -aft
Could you post the complete SIP trace, starting from INVITE? Is 205.164.40.74 IP address of voipswitch? On Tuesday 22 May 2012 01:51:31 Arif Hossain wrote:
On Tue, May 22, 2012 at 1:35 AM, Michael Collins <msc@freeswitch.org> wrote:
Yes, it does. ;)
-MC
Ok done http://pastebin.freeswitch.org/19136
now we can talk problems :)
participants (4)
-
Arif Hossain
-
Ken Rice
-
Michael Collins
-
Sergey Okhapkin