[SR-Users] kamailioi is not relaying BYE message to 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) | |181.952 | BYE | | |(7890) ------------------> (5060) | |185.687 | BYE | | |(7890) ------------------> (5060) | |188.018 | 408 Request Timeout | |(7890) ------------------> (5060) | 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