Hello,

dropping ack after 407 is the right behaviour.

Regarding the 7 INVITEs, do you have pike enabled or some other firewall? Your logs showed only invite-407-ack, not the following invites.

Cheers, Daniel

On 7/16/13 1:32 PM, Ismir Saljic wrote:

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@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@xxxxxxxxxxxxxxxx] Jul 15 15:42:16 www /usr/local/sbin/kamailio[31893]: DEBUG: <core> [parser/msg_parser.c:190]: DEBUG: to body [sip:18@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@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@xxxxxxxxxxxxxxxx] Jul 15 15:42:16 www /usr/local/sbin/kamailio[31892]: DEBUG: <core> [parser/msg_parser.c:190]: DEBUG: to body [sip:18@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@xxxxxxxx:51414 SIP/2.0 Via: SIP/2.0/UDP 64.61.94.148:34402;rport;branch=z9hG4bKPjca2e03042a3541e2a0e7c99ae186e391 Max-Forwards: 70 From: sip:tin4@xxxxxxx;tag=cb5a108eb1be4bbd9487d18dab422f01 To: sip:18@xxxxxxxxxxxx Contact: sip:tin4@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@xxxxxxxxxxxx;tag=cb5a108eb1be4bbd9487d18dab422f01 To: sip:18@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@xxxxxxxxxxxx:51414 SIP/2.0
    Via: SIP/2.0/UDP 

64.61.94.148:34402;rport;branch=z9hG4bKPjca2e03042a3541e2a0e7c99ae186e391 Max-Forwards: 70 From: sip:tin4@xxxxxxxxxxxx;tag=cb5a108eb1be4bbd9487d18dab422f01 To: sip:18@xxxxxxxxxxxx;tag=2551d5cef8d8d01ed7d219eb9d65ff77.6100 Call-ID: 730a5b16f91e4031a6b2c082d77528de CSeq: 836 ACK Sequence Number: 836 Method: ACK Content-Length: 0

Request-Line: INVITE sip:18@xxxxxxxxxxxx:51414 SIP/2.0
    Via: SIP/2.0/UDP 

64.61.94.148:34402;rport;branch=z9hG4bKPjb155205250d944078ed58fef7aa8e1c0 Max-Forwards: 70 From: sip:tin4@xxxxxxxxxxxx;tag=cb5a108eb1be4bbd9487d18dab422f01 To: sip:18@xxxxxxxxxxxx Contact: sip:tin4@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@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@xxxxxxxxxxxx:51414 SIP/2.0
    Via: SIP/2.0/UDP 

64.61.94.148:34402;rport;branch=z9hG4bKPjb155205250d944078ed58fef7aa8e1c0 Max-Forwards: 70 From: sip:tin4@xxxxxxxxxxxx;tag=cb5a108eb1be4bbd9487d18dab422f01 To: sip:18@xxxxxxxxxxx Contact: sip:tin4@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@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

---

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