[Freeswitch-users] BYE message is not relayed to the UAC
Arif Hossain
aftnix at gmail.com
Mon May 21 11:26:25 MSD 2012
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 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
--
-aft
Join us at ClueCon 2011 Aug 9-11, 2011
More information about the FreeSWITCH-users
mailing list