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
        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
        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
        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
        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
        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


-- 
Daniel-Constantin Mierla - http://www.asipto.com
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda