[SR-Users] Problem with calling - SL local ACK found -> dropping it!
Ismir Saljic
isaljic at gmail.com
Tue Jul 16 13:32:15 CEST 2013
Hi,
i have some strange problem with calling using kamailio 3.3.3. From the
same client somethimes calls work well and after 2 or 3 successful calls I
get this scenario.
After receiving ACK as response to 407 Authentication Required Message,
kamailio drops that ACK message and I got "SL local ACK found -> dropping
it!" message in debug file.
After this ACK message I get also 7 INVITES from client but there is no
response from kamailio.
I got this problem with clients that is behind multiple NATs. Other clients
works well.
Any advice would be appreciated.
Thanks
Ismir
This debug log and SIP trace:
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[parser/msg_parser.c:626]: method: <INVITE>
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[parser/msg_parser.c:628]: uri: <sip:18 at xxxxxxxxxxxxxxxx:51313>
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[parser/msg_parser.c:630]: version: <SIP/2.0>
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[parser/parse_via.c:1286]: Found param type 235, <rport> = <n/a>; state=6
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[parser/parse_via.c:1286]: Found param type 232, <branch> =
<z9hG4bKPjae181f78c1b9456da09ed7b34575c0e3>; state=16
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[parser/parse_via.c:2561]: end of header reached, state=5
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[parser/msg_parser.c:511]: parse_headers: Via found, flags=2
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[parser/msg_parser.c:513]: parse_headers: this is the first via
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[receive.c:149]: After parse_msg...
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[receive.c:190]: preparing to run routing scripts...
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: maxfwd
[mf_funcs.c:85]: value = 70
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[parser/parse_to.c:802]: end of header reached, state=9
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[parser/msg_parser.c:188]: DEBUG: get_hdr_field: <To> [30];
uri=[sip:18 at xxxxxxxxxxxxxxxx]
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[parser/msg_parser.c:190]: DEBUG: to body [sip:18 at xxxxxxxxxxxxxxxx#015#012]
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[parser/msg_parser.c:168]: get_hdr_field: cseq <CSeq>: <23125> <INVITE>
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[parser/msg_parser.c:202]: DEBUG: get_hdr_body : content_length=728
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[parser/msg_parser.c:104]: found end of header
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[parser/parse_to.c:178]: DEBUG: add_param:
tag=33fff09131774cf5a738a74919c50c90
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[parser/parse_to.c:802]: end of header reached, state=29
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: sanity
[mod_sanity.c:255]: sanity checks result: 1
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[msg_translator.c:206]: check_via_address(64.61.94.148, 64.61.94.148, 0)
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: siputils
[checks.c:103]: no totag
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: tm
[t_lookup.c:1079]: DEBUG: t_check_msg: msg id=4 global id=3 T start=(nil)
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: tm
[t_lookup.c:527]: t_lookup_request: start searching: hash=63666, isACK=0
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: tm
[t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: tm
[t_lookup.c:709]: DEBUG: t_lookup_request: no transaction found
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: tm
[t_lookup.c:1148]: DEBUG: t_check_msg: msg id=4 global id=4 T end=(nil)
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[socket_info.c:583]: grep_sock_info - checking if host==us: 21==14 &&
[xxxxxxxxxxxxxxxx] == [xxxxxxxxxxxxxxxx]
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[socket_info.c:587]: grep_sock_info - checking if port 51313 (advertise 0)
matches port 5060
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[socket_info.c:583]: grep_sock_info - checking if host==us: 21==14 &&
[xxxxxxxxxxxxxxxx] == [xxxxxxxxxxxxxxxx]
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[socket_info.c:587]: grep_sock_info - checking if port 51313 (advertise 0)
matches port 5060
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: auth_db
[authorize.c:363]: realm [xxxxxxxxxxxxxxxx] table [subscriber] flags [1]
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: auth
[api.c:86]: auth:pre_auth: Credentials with realm 'xxxxxxxxxxxxxxxx' not
found
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: auth_db
[authorize.c:180]: no credentials
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: auth
[challenge.c:128]: build_challenge_hf: realm='xxxxxxxxxxxxxxxx'
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: auth
[challenge.c:270]: auth: 'Proxy-Authenticate: Digest
realm="xxxxxxxxxxxxxxxx", nonce="UeRf01HkXqcKFA6LGeN8ssw6rbUNtt9N"#015#012'
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: sl [sl.c:278]:
reply in stateless mode (sl)
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[msg_translator.c:206]: check_via_address(64.61.94.148, 64.61.94.148, 0)
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[xavp.c:365]: destroying xavp list (nil)
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core>
[receive.c:293]: receive_msg: cleaning up
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31892]: DEBUG: <core>
[parser/msg_parser.c:624]: SIP Request:
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31892]: DEBUG: <core>
[parser/msg_parser.c:626]: method: <ACK>
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31892]: DEBUG: <core>
[parser/msg_parser.c:628]: uri: <sip:18 at xxxxxxxxxxxxxxxx:51313>
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31892]: DEBUG: <core>
[parser/msg_parser.c:630]: version: <SIP/2.0>
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31892]: DEBUG: <core>
[parser/parse_via.c:1286]: Found param type 235, <rport> = <n/a>; state=6
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31892]: DEBUG: <core>
[parser/parse_via.c:1286]: Found param type 232, <branch> =
<z9hG4bKPjae181f78c1b9456da09ed7b34575c0e3>; state=16
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31892]: DEBUG: <core>
[parser/parse_via.c:2561]: end of header reached, state=5
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31892]: DEBUG: <core>
[parser/msg_parser.c:511]: parse_headers: Via found, flags=2
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31892]: DEBUG: <core>
[parser/msg_parser.c:513]: parse_headers: this is the first via
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31892]: DEBUG: <core>
[receive.c:149]: After parse_msg...
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31892]: DEBUG: <core>
[receive.c:190]: preparing to run routing scripts...
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31892]: DEBUG: <core>
[parser/parse_to.c:178]: DEBUG: add_param:
tag=2551d5cef8d8d01ed7d219eb9d65ff77.495f
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31892]: DEBUG: <core>
[parser/parse_to.c:802]: end of header reached, state=29
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31892]: DEBUG: <core>
[parser/msg_parser.c:188]: DEBUG: get_hdr_field: <To> [72];
uri=[sip:18 at xxxxxxxxxxxxxxxx]
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31892]: DEBUG: <core>
[parser/msg_parser.c:190]: DEBUG: to body [sip:18 at xxxxxxxxxxxxxxxx]
*Jul 15 15:42:16 www /usr/local/sbin/kamailio[31892]: DEBUG: sl
[sl_funcs.c:415]: SL **local ACK found -> dropping it!*
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31892]: DEBUG: <core>
[usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31892]: DEBUG: <core>
[usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31892]: DEBUG: <core>
[usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31892]: DEBUG: <core>
[usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31892]: DEBUG: <core>
[usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31892]: DEBUG: <core>
[usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31892]: DEBUG: <core>
[xavp.c:365]: destroying xavp list (nil)
Jul 15 15:42:16 www /usr/local/sbin/kamailio[31892]: DEBUG: <core>
[receive.c:293]: receive_msg: cleaning up
Jul 15 15:42:17 www rsyslogd-2177: imuxsock lost 198 messages from pid
31904 due to rate-limiting
*
*
This is SIP trace from wireshark exported like text file.
Session Initiation Protocol
Request-Line: INVITE sip:18 at xxxxxxxx:51414 SIP/2.0
Via: SIP/2.0/UDP 64.61.94.148:34402
;rport;branch=z9hG4bKPjca2e03042a3541e2a0e7c99ae186e391
Max-Forwards: 70
From: <sip:tin4 at xxxxxxx>;tag=cb5a108eb1be4bbd9487d18dab422f01
To: sip:18 at xxxxxxxxxxxx
Contact: <sip:tin4 at 64.61.94.148:34402;ob>
Call-ID: 730a5b16f91e4031a6b2c082d77528de
CSeq: 836 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE,
NOTIFY, REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800
Min-SE: 90
Content-Type: application/sdp
Content-Length: 728
Message Body
Session Description Protocol
Session Description Protocol Version (v): 0
Owner/Creator, Session Id (o): - 3582902074 3582902074 IN IP4
192.168.1.189
Session Name (s): pjmedia
Bandwidth Information (b): AS:352
Time Description, active time (t): 0 0
Session Attribute (a): X-nat:0
Media Description, name and address (m): audio 40012 RTP/AVP 98
97 99 104 3 0 8 9 96
Connection Information (c): IN IP4 192.168.1.189
Bandwidth Information (b): TIAS:64000
Media Attribute (a): rtcp:40013 IN IP4 192.168.1.189
Media Attribute (a): sendrecv
Media Attribute (a): rtpmap:98 speex/16000
Media Attribute (a): rtpmap:97 speex/8000
Media Attribute (a): rtpmap:99 speex/32000
Media Attribute (a): rtpmap:104 iLBC/8000
Media Attribute (a): fmtp:104 mode=30
Media Attribute (a): rtpmap:3 GSM/8000
Media Attribute (a): rtpmap:0 PCMU/8000
Media Attribute (a): rtpmap:8 PCMA/8000
Media Attribute (a): rtpmap:9 G722/8000
Media Attribute (a): rtpmap:96 telephone-event/8000
Media Attribute (a): fmtp:96 0-15
Media Description, name and address (m): video 40014 RTP/AVP 97
96
Connection Information (c): IN IP4 192.168.1.189
Bandwidth Information (b): TIAS:256000
Media Attribute (a): rtcp:40015 IN IP4 192.168.1.189
Media Attribute (a): sendrecv
Media Attribute (a): rtpmap:97 H264/90000
Media Attribute (a): fmtp:97 profile-level-id=42e01e;
packetization-mode=1
Media Attribute (a): rtpmap:96 H263-1998/90000
Media Attribute (a): fmtp:96 CIF=1;QCIF=1
Status-Line: SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/UDP 64.61.94.148:34402
;rport=34402;branch=z9hG4bKPjca2e03042a3541e2a0e7c99ae186e391
From: <sip:tin4 at xxxxxxxxxxxx>;tag=cb5a108eb1be4bbd9487d18dab422f01
To: sip:18 at xxxxxxxxxxxx;tag=2551d5cef8d8d01ed7d219eb9d65ff77.6100
Call-ID: 730a5b16f91e4031a6b2c082d77528de
CSeq: 836 INVITE
Proxy-Authenticate: Digest realm="xxxxxxxxxxxx",
nonce="UeR6JVHkePlxwVxs8eXM+HEbe9pFHRZR"
Server: kamailio (3.3.3 (x86_64/linux))
Content-Length: 0
Request-Line: ACK sip:18 at xxxxxxxxxxxx:51414 SIP/2.0
Via: SIP/2.0/UDP 64.61.94.148:34402
;rport;branch=z9hG4bKPjca2e03042a3541e2a0e7c99ae186e391
Max-Forwards: 70
From: <sip:tin4 at xxxxxxxxxxxx>;tag=cb5a108eb1be4bbd9487d18dab422f01
To: sip:18 at xxxxxxxxxxxx;tag=2551d5cef8d8d01ed7d219eb9d65ff77.6100
Call-ID: 730a5b16f91e4031a6b2c082d77528de
CSeq: 836 ACK
Sequence Number: 836
Method: ACK
Content-Length: 0
Request-Line: INVITE sip:18 at xxxxxxxxxxxx:51414 SIP/2.0
Via: SIP/2.0/UDP 64.61.94.148:34402
;rport;branch=z9hG4bKPjb155205250d944078ed58fef7aa8e1c0
Max-Forwards: 70
From: <sip:tin4 at xxxxxxxxxxxx>;tag=cb5a108eb1be4bbd9487d18dab422f01
To: sip:18 at xxxxxxxxxxxx
Contact: <sip:tin4 at 64.61.94.148:34402;ob>
Call-ID: 730a5b16f91e4031a6b2c082d77528de
CSeq: 837 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE,
NOTIFY, REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800
Min-SE: 90
Proxy-Authorization: Digest username="tin4", realm="xxxxxxxxxxxx",
nonce="UeR6JVHkePlxwVxs8eXM+HEbe9pFHRZR", uri="sip:18 at xxxxxxxxxxxx:51414",
response="7e98dbc33c039e358728a08e8582c990"
Content-Type: application/sdp
Content-Length: 728
Message Body
Session Description Protocol
Session Description Protocol Version (v): 0
Owner/Creator, Session Id (o): - 3582902074 3582902074 IN IP4
192.168.1.189
Session Name (s): pjmedia
Bandwidth Information (b): AS:352
Time Description, active time (t): 0 0
Session Attribute (a): X-nat:0
Media Description, name and address (m): audio 40012 RTP/AVP 98
97 99 104 3 0 8 9 96
Connection Information (c): IN IP4 192.168.1.189
Bandwidth Information (b): TIAS:64000
Media Attribute (a): rtcp:40013 IN IP4 192.168.1.189
Media Attribute (a): sendrecv
Media Attribute (a): rtpmap:98 speex/16000
Media Attribute (a): rtpmap:97 speex/8000
Media Attribute (a): rtpmap:99 speex/32000
Media Attribute (a): rtpmap:104 iLBC/8000
Media Attribute (a): fmtp:104 mode=30
Media Attribute (a): rtpmap:3 GSM/8000
Media Attribute (a): rtpmap:0 PCMU/8000
Media Attribute (a): rtpmap:8 PCMA/8000
Media Attribute (a): rtpmap:9 G722/8000
Media Attribute (a): rtpmap:96 telephone-event/8000
Media Attribute (a): fmtp:96 0-15
Media Description, name and address (m): video 40014 RTP/AVP 97
96
Connection Information (c): IN IP4 192.168.1.189
Bandwidth Information (b): TIAS:256000
Media Attribute (a): rtcp:40015 IN IP4 192.168.1.189
Media Attribute (a): sendrecv
Media Attribute (a): rtpmap:97 H264/90000
Media Attribute (a): fmtp:97 profile-level-id=42e01e;
packetization-mode=1
Media Attribute (a): rtpmap:96 H263-1998/90000
Media Attribute (a): fmtp:96 CIF=1;QCIF=1
......i deleted other INVITES (there was 7 INVITES)
Request-Line: INVITE sip:18 at xxxxxxxxxxxx:51414 SIP/2.0
Via: SIP/2.0/UDP 64.61.94.148:34402
;rport;branch=z9hG4bKPjb155205250d944078ed58fef7aa8e1c0
Max-Forwards: 70
From: <sip:tin4 at xxxxxxxxxxxx>;tag=cb5a108eb1be4bbd9487d18dab422f01
To: sip:18 at xxxxxxxxxxx
Contact: <sip:tin4 at 64.61.94.148:34402;ob>
Call-ID: 730a5b16f91e4031a6b2c082d77528de
CSeq: 837 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE,
NOTIFY, REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800
Min-SE: 90
Proxy-Authorization: Digest username="tin4", realm="xxxxxxxxxxxx",
nonce="UeR6JVHkePlxwVxs8eXM+HEbe9pFHRZR", uri="sip:18 at xxxxxxxxxxxx:51414",
response="7e98dbc33c039e358728a08e8582c990"
Content-Type: application/sdp
Content-Length: 728
Message Body
Session Description Protocol
Session Description Protocol Version (v): 0
Owner/Creator, Session Id (o): - 3582902074 3582902074 IN IP4
192.168.1.189
Session Name (s): pjmedia
Bandwidth Information (b): AS:352
Time Description, active time (t): 0 0
Session Attribute (a): X-nat:0
Media Description, name and address (m): audio 40012 RTP/AVP 98
97 99 104 3 0 8 9 96
Connection Information (c): IN IP4 192.168.1.189
Bandwidth Information (b): TIAS:64000
Media Attribute (a): rtcp:40013 IN IP4 192.168.1.189
Media Attribute (a): sendrecv
Media Attribute (a): rtpmap:98 speex/16000
Media Attribute (a): rtpmap:97 speex/8000
Media Attribute (a): rtpmap:99 speex/32000
Media Attribute (a): rtpmap:104 iLBC/8000
Media Attribute (a): fmtp:104 mode=30
Media Attribute (a): rtpmap:3 GSM/8000
Media Attribute (a): rtpmap:0 PCMU/8000
Media Attribute (a): rtpmap:8 PCMA/8000
Media Attribute (a): rtpmap:9 G722/8000
Media Attribute (a): rtpmap:96 telephone-event/8000
Media Attribute (a): fmtp:96 0-15
Media Description, name and address (m): video 40014 RTP/AVP 97
96
Connection Information (c): IN IP4 192.168.1.189
Bandwidth Information (b): TIAS:256000
Media Attribute (a): rtcp:40015 IN IP4 192.168.1.189
Media Attribute (a): sendrecv
Media Attribute (a): rtpmap:97 H264/90000
Media Attribute (a): fmtp:97 profile-level-id=42e01e;
packetization-mode=1
Media Attribute (a): rtpmap:96 H263-1998/90000
Media Attribute (a): fmtp:96 CIF=1;QCIF=1
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sip-router.org/pipermail/sr-users/attachments/20130716/db3d8039/attachment-0001.html>
More information about the sr-users
mailing list