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