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.
Hello,
is 205.164.40.74 the IP address of VoipSwitch? If yes, then the BYE is constructed to be sent back to it, because the r-uri has this IP address.
R-uri in the BYE must have the IP address and port of UAC1.
If you give here all the sip trace for such call (from INVITE to the BYE, taken with ngrep for example, on kamailio host), we may be able to spot where the mistake is made. R-URI should be constructed from Contact header of INVITE or 200ok.
Cheers, Daniel
On 5/21/12 9:21 PM, Arif Hossain 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) | |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.
On Tue, May 22, 2012 at 5:41 PM, Daniel-Constantin Mierla miconda@gmail.com wrote:
Hello,
is 205.164.40.74 the IP address of VoipSwitch? If yes, then the BYE is constructed to be sent back to it, because the r-uri has this IP address.
R-uri in the BYE must have the IP address and port of UAC1.
If you give here all the sip trace for such call (from INVITE to the BYE, taken with ngrep for example, on kamailio host), we may be able to spot where the mistake is made. R-URI should be constructed from Contact header of INVITE or 200ok.
Cheers, Daniel
Hi Daniel,
Thanks for the reply.
We have already came to the same conclusion by some testing in our lab. It seems its a bug in provider which not constructing BYE message properly.
But i'm interested in if its possible to detect the fault in this BYE and construct a new one and then relay it to the UAC.
I mean can i do this :
contact-header = INVITE's contact-header if (contact-header != BYE's ruri) { construct BYE message with contact header t_relay() }
Cheers aft
On 5/21/12 9:21 PM, Arif Hossain 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) | |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.
-- Daniel-Constantin Mierla - http://www.asipto.com http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Thanks for the reply.
We have already came to the same conclusion by some testing in our lab. It seems its a bug in provider which not constructing BYE message properly.
But i'm interested in if its possible to detect the fault in this BYE and construct a new one and then relay it to the UAC.
I mean can i do this :
contact-header = INVITE's contact-header if (contact-header != BYE's ruri) { construct BYE message with contact header t_relay() }
Cheers aft
Hi aft,
I think to do what you want you can save Contact field + callid pair taken from the INVITEs that comes from your side. Then when BYE comes from such provider you should find a correct Contact for that call-id and if it exists and not equal to R-URI you can rewrite it.
For example to write to R-URI value from $var(correct_ruri) you can use *$ru = $var(correct_ruri);* statement.
What about a place where contact can be saved, i think htable will be the nice one. Please pay attention to "autoexpire" parameter of htable module. You should take care about the staled records to avoid memory usage problems.
Cheers, Vitaliy Aleksandrov
On Thu, May 24, 2012 at 6:41 PM, Vitaliy Aleksandrov vitalik.voip@gmail.com wrote:
Thanks for the reply.
We have already came to the same conclusion by some testing in our lab. It seems its a bug in provider which not constructing BYE message properly.
But i'm interested in if its possible to detect the fault in this BYE and construct a new one and then relay it to the UAC.
I mean can i do this :
contact-header = INVITE's contact-header if (contact-header != BYE's ruri) { construct BYE message with contact header t_relay() }
Cheers aft
Hi aft,
I think to do what you want you can save Contact field + callid pair taken from the INVITEs that comes from your side. Then when BYE comes from such provider you should find a correct Contact for that call-id and if it exists and not equal to R-URI you can rewrite it.
For example to write to R-URI value from $var(correct_ruri) you can use $ru = $var(correct_ruri); statement.
What about a place where contact can be saved, i think htable will be the nice one. Please pay attention to "autoexpire" parameter of htable module. You should take care about the staled records to avoid memory usage problems.
Cheers, Vitaliy Aleksandrov
Hi Aleksandrov,
Thanks for the suggestion. I was playing with the dialog module to achieve the same thing. But your suggestion seems more lightweight ans sensible than invoking full blown dialog functionality most of which i do not need for my purpose.
I will try your approach and post the update.
In the mean time, my dialog module approach is not working either as expected.
I used dialog module like following :
#!ifdef WITH_DLG modparam("dialog", "enable_stats",0) modparam("dialog", "dlg_flag",DLG_FLAG ) modparam("dialog", "default_timeout",100) #!endif
request_route { # per request initial checks route(REQINIT); #!ifdef WITH_DLG if (is_method("INVITE") && !has_totag()){ $dlg_ctx(timeout_route) = 12; $dlg_ctx(timeout_bye) = 1; } dlg_manage(); #!endif
................................................................... ................................................................... route[WITHINDLG] {
if (has_totag()) { # sequential request withing a dialog should # take the path determined by record-routing #!ifdef WITH_DLG if (is_method("BYE")){ dlg_get ("$ci","$ft","$tt"); dlg_bye ("all"); return; } #!endif if (loose_route()) { if (is_method("BYE")) { setflag(FLT_ACC); # do accounting ... setflag(FLT_ACCFAILED); # ... even if tansaction fails .................................................................... ....................................................................
#!ifdef WITH_DLG route[12]{ dlg_bye("all"); xdbg("bye everyone"); } #!endif
I'm not worried about timeout right now. This does not work. When bye message arrives i can see the following in kamailio log :
[4016]: DEBUG: <core> [parser/msg_parser.c:624]: SIP Request: [4016]: DEBUG: <core> [parser/msg_parser.c:626]: method: <BYE> [4016]: DEBUG: <core> [parser/msg_parser.c:628]: uri: sip:1010@x.x.x.x:5060 [4016]: DEBUG: <core> [parser/msg_parser.c:630]: version: <SIP/2.0> [4016]: DEBUG: <core> [parser/parse_via.c:1289]: Found param type 232, <branch> = <z9hG4bK-d8754z-d51775683d085d3b-1---d8754z->; state=16 [4016]: DEBUG: <core> [parser/parse_via.c:2564]: end of header reached, state=5 [4016]: DEBUG: <core> [parser/msg_parser.c:511]: parse_headers: Via found, flags=2 [4016]: DEBUG: <core> [parser/msg_parser.c:513]: parse_headers: this is the first via -- [4016]: DEBUG: <core> [parser/msg_parser.c:190]: DEBUG: to body ["1010"sip:1010@x.x.x.x] [4016]: DEBUG: <core> [parser/msg_parser.c:168]: get_hdr_field: cseq <CSeq>: <3> <BYE> [4016]: DEBUG: <core> [parser/msg_parser.c:202]: DEBUG: get_hdr_body : content_length=0 [4016]: DEBUG: <core> [parser/msg_parser.c:104]: found end of header [4016]: DEBUG: <core> [parser/parse_to.c:178]: DEBUG: add_param: tag=e06d7c6a [4016]: DEBUG: <core> [parser/parse_to.c:802]: end of header reached, state=29 [4016]: DEBUG: sanity [mod_sanity.c:255]: sanity checks result: 1 [4016]: DEBUG: dialog [dlg_hash.c:652]: no dialog callid='OTljOWU1NTU1NWE1ZmEzZGE4NDNhNGQyNDE2MmUzZDc.' found [4016]: DEBUG: dialog [dlg_hash.c:683]: no dialog callid='OTljOWU1NTU1NWE1ZmEzZGE4NDNhNGQyNDE2MmUzZDc.' found [4016]: DEBUG: dialog [dlg_handlers.c:1166]: Callid 'OTljOWU1NTU1NWE1ZmEzZGE4NDNhNGQyNDE2MmUzZDc.' not found ..... ..... [4016]: DEBUG: dialog [dlg_hash.c:652]: no dialog callid='OTljOWU1NTU1NWE1ZmEzZGE4NDNhNGQyNDE2MmUzZDc.' found [4016]: DEBUG: dialog [dlg_hash.c:683]: no dialog callid='OTljOWU1NTU1NWE1ZmEzZGE4NDNhNGQyNDE2MmUzZDc.' found
After some inspection i found out this :
[4017]: DEBUG: dialog [dlg_hash.c:646]: dialog callid='OTljOWU1NTU1NWE1ZmEzZGE4NDNhNGQyNDE2MmUzZDc.' found on entry 321, dir=1 [4017]: DEBUG: dialog [dlg_profile.c:406]: setting current dialog [321:12199] [4017]: DEBUG: dialog [dlg_hash.c:940]: dialog 0xb5d10150 changed from state 5 to state 5, due event 6 (ref 2) [4017]: DEBUG: dialog [dlg_hash.c:753]: unref dlg 0xb5d10150 with 1 -> 1 -- [4017]: DEBUG: tm [t_lookup.c:1379]: DEBUG: t_newtran: msg id=6 , global msg id=5 , T on entrance=0xffffffff [4017]: DEBUG: tm [t_lookup.c:527]: t_lookup_request: start searching: hash=53621, isACK=1 [4017]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed [4017]: DEBUG: tm [t_lookup.c:709]: DEBUG: t_lookup_request: no transaction found [4017]: DEBUG: tm [t_funcs.c:315]: SER: forwarding ACK statelessly [4017]: DEBUG: <core> [receive.c:293]: receive_msg: cleaning up [4021]: DEBUG: tm [t_hooks.c:288]: DBG: trans=0xb5d0e930, callback type 131072, id 0 entered [4021]: DEBUG: dialog [dlg_hash.c:588]: ref dlg 0xb5d10150 with 1 -> 2 [4021]: DEBUG: dialog [dlg_hash.c:590]: dialog id=12199 found on entry 321 [4021]: DEBUG: dialog [dlg_hash.c:753]: unref dlg 0xb5d10150 with 2 -> 0 [4021]: DEBUG: dialog [dlg_hash.c:753]: ref <=0 for dialog 0xb5d10150 [4021]: DEBUG: dialog [dlg_hash.c:315]: destroying dialog 0xb5d10150 (ref 0) [4021]: DEBUG: dialog [dlg_hash.c:331]: removed timer for dlg 0xb5d10150 [321:12199] with clid 'OTljOWU1NTU1NWE1ZmEzZGE4NDNhNGQyNDE2MmUzZDc.' and tags 'e06d7c6a' '' [4021]: DEBUG: dialog [dlg_handlers.c:322]: freeing dlg iuid [321:12199] (0xb5d0f5c0) [4021]: DEBUG: dialog [dlg_handlers.c:322]: freeing dlg iuid [321:12199] (0xb5d100d0)
It seems to me that after forwarding ACK, the dialog entry is removed for some reason. And hence when BYE arrives and i try to generate a dlg_bye() by searching the dialog, no dialog is found.
Cheers.
SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list sr-users@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
Hi
I am experiencing the exact same issue.
Did you ever find a working solution?
Thank you very much for your assistance.
All the best.
Will Ferrer
Aft nix 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) | |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 at 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 at 205.164.40.74;tag=100528120745985872655137 Call-ID: IqBknV19AuxW0jk.8BjuE4hyx93Ws9qS To: "123456" <sip:ipphone at 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 at 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 at 205.164.40.74;tag=100528120745985872655137 Call-ID: IqBknV19AuxW0jk.8BjuE4hyx93Ws9qS To: "123456" <sip:ipphone at 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 at 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 at 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 at 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
-- View this message in context: http://sip-router.1086192.n5.nabble.com/kamailioi-is-not-relaying-BYE-messag... Sent from the Users mailing list archive at Nabble.com.
Hi All
For the record I inspected my issue further and it was not the exact same issue as the initial poster after all.
I am using a dispatcher for load balancing and I had nat fix up running on both the boxes in the path of the call. This was causing add_contact_alias to be called on both the dispatcher box and the call processing box. This made me end up with 2 aliases on the contact-- both the softphones outside as an alias and the dispatchers outside. This was causing the carrier to form the ruri of the bye message with both aliases and when the dispatcher box saw this it tried to send the bye message to it's self instead of to the soft phone (since it's own ip was in the ruri as an alias).
The contact looked like this: Contact: sip:user@<softphone inside;alias=<dispatcher outside>~5060~1;alias=<softphone outside>~5060~1>\r\n
So the bye message looked like this: BYE sip:user@<softphone inside>;alias=<dispatcher outside>~5060~1;alias=<softphone outside>~5060~1 SIP/2.0\r\n
I had thought the carrier had messed up my ruri which is why I thought it was the same issue but really it was one of my boxes messing up the contact.
I am posting my find in case any one else ends up with the same issue I had.
All the best.
Will Ferrer
-- View this message in context: http://sip-router.1086192.n5.nabble.com/kamailioi-is-not-relaying-BYE-messag... Sent from the Users mailing list archive at Nabble.com.
-
Aft nix -
Arif Hossain
-
Daniel-Constantin Mierla -
Vitaliy Aleksandrov -
willf1976