Strange behavior on authorization invite

Hello! Sorry for my bad engliesh.

I try to integrate Kamailio 4.3.3 and Asterisk 11.20 and get strange behavior at asterisk in next case:
drive.google.com/file/d/0B3z4r2 … sp=sharing

Kamailio work as registrar and router (some our gateways work with asterisk very strange, but its not one of them), asterisk as voice services and PSTN gateway.

When kamailio redirect call to asterisk it should authorize. I use example from this function
kamailio.org/docs/modules/4.3.x/ … .uac_auth(

And get from asterisk debug this log:

[quote][Nov 2 17:26:36] DEBUG[1745]: config.c:1808 config_text_file_load: Parsing /etc/asterisk/cli_permissions.conf
== Parsing ‘/etc/asterisk/cli_permissions.conf’: Found
Asterisk Ready.
[Nov 2 17:26:36] DEBUG[1745]: config.c:1808 config_text_file_load: Parsing /etc/asterisk/cli.conf
== Parsing ‘/etc/asterisk/cli.conf’: Found
[Nov 2 17:26:41] DEBUG[2492]: chan_sip.c:9038 find_call: = Looking for Call ID: d1069ec5-fbff-1233-dcbd-a8f94b094353 (Checking From) --From tag m6H03jQ5v1Q9B --To-tag
[Nov 2 17:26:41] DEBUG[2492]: acl.c:979 ast_ouraddrfor: For destination ‘10.10.9.202’, our source address is ‘10.10.9.101’.
[Nov 2 17:26:41] DEBUG[2492]: chan_sip.c:3881 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.10.9.101:5060
[Nov 2 17:26:41] DEBUG[2492]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting ‘10.10.9.202:5060’ into…
[Nov 2 17:26:41] DEBUG[2492]: netsock2.c:192 ast_sockaddr_split_hostport: …host ‘10.10.9.202’ and port ‘5060’.
[Nov 2 17:26:41] DEBUG[2492]: chan_sip.c:8641 sip_alloc: Allocating new SIP dialog for d1069ec5-fbff-1233-dcbd-a8f94b094353 - INVITE (No RTP)
[Nov 2 17:26:41] DEBUG[2492][C-00000000]: chan_sip.c:28475 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Nov 2 17:26:41] DEBUG[2492][C-00000000]: sip/reqresp_parser.c:1603 parse_sip_options: Begin: parsing SIP “Supported: timer, 100rel, replaces”
[Nov 2 17:26:41] DEBUG[2492][C-00000000]: sip/reqresp_parser.c:1618 parse_sip_options: Found SIP option: -timer-
[Nov 2 17:26:41] DEBUG[2492][C-00000000]: sip/reqresp_parser.c:1626 parse_sip_options: Matched SIP option: timer
[Nov 2 17:26:41] DEBUG[2492][C-00000000]: sip/reqresp_parser.c:1618 parse_sip_options: Found SIP option: -100rel-
[Nov 2 17:26:41] DEBUG[2492][C-00000000]: sip/reqresp_parser.c:1626 parse_sip_options: Matched SIP option: 100rel
[Nov 2 17:26:41] DEBUG[2492][C-00000000]: sip/reqresp_parser.c:1618 parse_sip_options: Found SIP option: -replaces-
[Nov 2 17:26:41] DEBUG[2492][C-00000000]: sip/reqresp_parser.c:1626 parse_sip_options: Matched SIP option: replaces
[Nov 2 17:26:41] DEBUG[2492][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting ‘10.10.9.202:5060’ into…
[Nov 2 17:26:41] DEBUG[2492][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: …host ‘10.10.9.202’ and port ‘5060’.
[Nov 2 17:26:41] DEBUG[2492][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting ‘10.10.9.202:5060’ into…
[Nov 2 17:26:41] DEBUG[2492][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: …host ‘10.10.9.202’ and port ‘’.
[Nov 2 17:26:41] DEBUG[2492][C-00000000]: chan_sip.c:3724 __sip_xmit: Trying to put ‘SIP/2.0 401’ onto UDP socket destined for 10.10.9.202:5060
[Nov 2 17:26:41] DEBUG[2492]: chan_sip.c:9038 find_call: = Looking for Call ID: d1069ec5-fbff-1233-dcbd-a8f94b094353 (Checking From) --From tag m6H03jQ5v1Q9B --To-tag as17709763
[Nov 2 17:26:41] DEBUG[2492][C-00000000]: chan_sip.c:28475 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Nov 2 17:26:41] DEBUG[2492][C-00000000]: chan_sip.c:4421 __sip_ack: Stopping retransmission on ‘d1069ec5-fbff-1233-dcbd-a8f94b094353’ of Response 6573: Match Found
[Nov 2 17:26:41] DEBUG[2492]: chan_sip.c:9038 find_call: = Looking for Call ID: d1069ec5-fbff-1233-dcbd-a8f94b094353 (Checking From) --From tag m6H03jQ5v1Q9B --To-tag
[Nov 2 17:26:41] DEBUG[2492]: acl.c:979 ast_ouraddrfor: For destination ‘10.10.9.202’, our source address is ‘10.10.9.101’.
[Nov 2 17:26:41] DEBUG[2492]: chan_sip.c:3881 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.10.9.101:5060
[Nov 2 17:26:41] DEBUG[2492]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting ‘10.10.9.202:5060’ into…
[Nov 2 17:26:41] DEBUG[2492]: netsock2.c:192 ast_sockaddr_split_hostport: …host ‘10.10.9.202’ and port ‘5060’.
[Nov 2 17:26:41] DEBUG[2492]: chan_sip.c:8641 sip_alloc: Allocating new SIP dialog for d1069ec5-fbff-1233-dcbd-a8f94b094353 - INVITE (No RTP)
[Nov 2 17:26:41] DEBUG[2492][C-00000001]: chan_sip.c:28475 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Nov 2 17:26:41] DEBUG[2492][C-00000001]: sip/reqresp_parser.c:1603 parse_sip_options: Begin: parsing SIP “Supported: timer, 100rel, replaces”
[Nov 2 17:26:41] DEBUG[2492][C-00000001]: sip/reqresp_parser.c:1618 parse_sip_options: Found SIP option: -timer-
[Nov 2 17:26:41] DEBUG[2492][C-00000001]: sip/reqresp_parser.c:1626 parse_sip_options: Matched SIP option: timer
[Nov 2 17:26:41] DEBUG[2492][C-00000001]: sip/reqresp_parser.c:1618 parse_sip_options: Found SIP option: -100rel-
[Nov 2 17:26:41] DEBUG[2492][C-00000001]: sip/reqresp_parser.c:1626 parse_sip_options: Matched SIP option: 100rel
[Nov 2 17:26:41] DEBUG[2492][C-00000001]: sip/reqresp_parser.c:1618 parse_sip_options: Found SIP option: -replaces-
[Nov 2 17:26:41] DEBUG[2492][C-00000001]: sip/reqresp_parser.c:1626 parse_sip_options: Matched SIP option: replaces
[Nov 2 17:26:41] DEBUG[2492][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting ‘10.10.9.202:5060’ into…
[Nov 2 17:26:41] DEBUG[2492][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: …host ‘10.10.9.202’ and port ‘5060’.
[Nov 2 17:26:41] DEBUG[2492][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting ‘10.10.9.202:5060’ into…
[Nov 2 17:26:41] DEBUG[2492][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: …host ‘10.10.9.202’ and port ‘’.
[Nov 2 17:26:41] DEBUG[2492][C-00000001]: chan_sip.c:3724 __sip_xmit: Trying to put ‘SIP/2.0 401’ onto UDP socket destined for 10.10.9.202:5060
[Nov 2 17:26:41] DEBUG[2492]: chan_sip.c:9038 find_call: = Looking for Call ID: d1069ec5-fbff-1233-dcbd-a8f94b094353 (Checking From) --From tag m6H03jQ5v1Q9B --To-tag as4033856c
[Nov 2 17:26:41] DEBUG[2492][C-00000001]: chan_sip.c:28475 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Nov 2 17:26:41] DEBUG[2492][C-00000001]: chan_sip.c:4421 __sip_ack: Stopping retransmission on ‘d1069ec5-fbff-1233-dcbd-a8f94b094353’ of Response 6573: Match Found
[Nov 2 17:26:41] DEBUG[2492]: chan_sip.c:9038 find_call: = Looking for Call ID: d1069ec5-fbff-1233-dcbd-a8f94b094353 (Checking From) --From tag m6H03jQ5v1Q9B --To-tag
[Nov 2 17:26:41] DEBUG[2492]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting ‘10.10.9.101:5060’ into…
[Nov 2 17:26:41] DEBUG[2492]: netsock2.c:192 ast_sockaddr_split_hostport: …host ‘10.10.9.101’ and port ‘5060’.
[Nov 2 17:26:41] DEBUG[2492]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting ‘10.10.9.101:5060’ into…
[Nov 2 17:26:41] DEBUG[2492]: netsock2.c:192 ast_sockaddr_split_hostport: …host ‘10.10.9.101’ and port ‘5060’.
[Nov 2 17:26:41] DEBUG[2492][C-00000000]: chan_sip.c:28475 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Nov 2 17:26:41] DEBUG[2492][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting ‘10.10.9.202:5060’ into…
[Nov 2 17:26:41] DEBUG[2492][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: …host ‘10.10.9.202’ and port ‘5060’.
[Nov 2 17:26:41] DEBUG[2492][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting ‘10.10.9.202:5060’ into…
[Nov 2 17:26:41] DEBUG[2492][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: …host ‘10.10.9.202’ and port ‘’.
[Nov 2 17:26:41] WARNING[2492][C-00000000]: chan_sip.c:16539 check_auth: username mismatch, have , digest has <2729>
[Nov 2 17:26:41] NOTICE[2492][C-00000000]: chan_sip.c:25751 handle_request_invite: Failed to authenticate device OldOnes sip:OldOnes@10.10.9.202:5060;tag=m6H03jQ5v1Q9B
[Nov 2 17:26:41] DEBUG[2492][C-00000000]: chan_sip.c:3724 __sip_xmit: Trying to put ‘SIP/2.0 403’ onto UDP socket destined for 10.10.9.202:5060
[Nov 2 17:26:41] DEBUG[2492]: chan_sip.c:9038 find_call: = Looking for Call ID: d1069ec5-fbff-1233-dcbd-a8f94b094353 (Checking From) --From tag m6H03jQ5v1Q9B --To-tag as17709763
[Nov 2 17:26:41] DEBUG[2492][C-00000000]: chan_sip.c:28475 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Nov 2 17:26:41] DEBUG[2492][C-00000000]: chan_sip.c:4421 __sip_ack: Stopping retransmission on ‘d1069ec5-fbff-1233-dcbd-a8f94b094353’ of Response 6574: Match Found
[Nov 2 17:26:47] DEBUG[2492]: chan_sip.c:4277 __sip_autodestruct: Auto destroying SIP dialog ‘d1069ec5-fbff-1233-dcbd-a8f94b094353’
[Nov 2 17:26:47] DEBUG[2492]: chan_sip.c:6681 sip_destroy: Destroying SIP dialog d1069ec5-fbff-1233-dcbd-a8f94b094353
[Nov 2 17:26:47] DEBUG[2492]: chan_sip.c:4277 __sip_autodestruct: Auto destroying SIP dialog ‘d1069ec5-fbff-1233-dcbd-a8f94b094353’
[Nov 2 17:26:47] DEBUG[2492]: chan_sip.c:6681 sip_destroy: Destroying SIP dialog d1069ec5-fbff-1233-dcbd-a8f94b094353
[/quote]

Asterisk without any reasons send 401 on authorization INVITE, and kamailio resend answer to GW. GW send digest authorization that it use at kamailio and i get username mismatch from asterisk.

I think problem is - asterisk dont search digest authorization in INVITE. It process headers step by step until get Content-type - and decide that invite dont have digest authorization. Because only difference between both INVITEs - headers order.

Peer definition: (same user and password i use at kamailio)

When i use insecure=invite it work, but asterisk dont authorize INVITE. insecure=port dont affect at process.

PS: I use different combinations username fromuser authuser fromdomain peer host defaultuser defaultip and always get same result - 401 Unauthorize withouth reasons

The device thinks its name is 2729. Asterisk thinks its name is OldOnes.

If you look in pcap file at google drive you will see, that there is 2 authorization. First - from Kamailio like OldOnes. Second from phone directly.
Problem that asterisk drop first authorization without reasons.