WARNING[13714] res_srtp.c: SRTP unprotect: authentication failure

[Nick Ustinov]

Hello!

Ater several successful SRTP-enabled calls with SRTP set to Mandatory,
asterisk starts to give the following warnings in Log:

WARNING[13714] res_srtp.c: SRTP unprotect: authentication failure

and client hears no sound. After i restart the client program it works
fine again for a while. Then the same warning again.

Asterisk 1.8.1.1, RealTime engine, sip peer has encrytion yes and
srtpcapable yes
The client program is CSipSimple on Android


Here's some log file:

[2010-12-23 11:06:22] DEBUG[5941] sip/sdp_crypto.c: SRTP policy
activated
[2010-12-23 11:06:22] DEBUG[5941] chan_sip.c: Processing media-level
(audio) SDP a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:0VyG/
fnup0U9qDoTGlWvVuE5yAef5MfYU6F67oI+... OK.
[2010-12-23 11:06:22] DEBUG[5941] chan_sip.c: We've already processed
a crypto attribute, skipping 'crypto:2 AES_CM_128_HMAC_SHA1_32 inline:
5X/Zqep5tNdDGFhOY1//VFQ7diCCH1Y1FUKgYXLp'
[2010-12-23 11:06:22] DEBUG[5941] chan_sip.c: Processing media-level
(audio) SDP a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:5X/
Zqep5tNdDGFhOY1//VFQ7diCCH1Y1FUKgYXLp... UNSUPPORTED.
[2010-12-23 11:06:22] DEBUG[5941] rtp_engine.c: Incorporating payload
18 on 0x4d614f0
[2010-12-23 11:06:22] DEBUG[5941] rtp_engine.c: Incorporating payload
96 on 0x4d614f0
[2010-12-23 11:06:22] DEBUG[5941] res_rtp_asterisk.c: Setting RTCP
address on RTP instance '0xb793b8f8'
[2010-12-23 11:06:22] DEBUG[5941] rtp_engine.c: Copying payload 18
from 0x4d614f0 to 0xb793baa4
[2010-12-23 11:06:22] DEBUG[5941] rtp_engine.c: Copying payload 96
from 0x4d614f0 to 0xb793baa4
[2010-12-23 11:06:22] DEBUG[5941] chan_sip.c: We're settling with
these formats: 0x100 (g729)
[2010-12-23 11:06:22] DEBUG[5941] chan_sip.c: Checking SIP call limits
for device nlcyhguv
[2010-12-23 11:06:22] DEBUG[5941] chan_sip.c: Updating call counter
for incoming call
[2010-12-23 11:06:22] DEBUG[5941] res_config_mysql.c: MySQL RealTime:
Connection okay.
[2010-12-23 11:06:22] DEBUG[5941] res_config_mysql.c: MySQL RealTime:
Retrieve SQL: SELECT * FROM extensions_table WHERE exten =
'+380504446595' AND context = 'sip-direct' AND priority = '1'
[2010-12-23 11:06:22] DEBUG[5941] res_config_mysql.c: MySQL RealTime:
Connection okay.
[2010-12-23 11:06:22] DEBUG[5941] res_config_mysql.c: MySQL RealTime:
Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%'
AND context = 'sip-direct' AND priority = '1' ORDER BY exten
[2010-12-23 11:06:22] DEBUG[5941] chan_sip.c: *** Our native formats
are 0x100 (g729)
[2010-12-23 11:06:22] DEBUG[5941] chan_sip.c: *** Joint capabilities
are 0x100 (g729)
[2010-12-23 11:06:22] DEBUG[5941] chan_sip.c: *** Our capabilities are
0x10e (gsm|ulaw|alaw|g729)
[2010-12-23 11:06:22] DEBUG[5941] chan_sip.c: *** AST_CODEC_CHOOSE
formats are 0x100 (g729)
[2010-12-23 11:06:22] DEBUG[5941] chan_sip.c: This channel will not be
able to handle video.
[2010-12-23 11:06:22] DEBUG[5941] res_config_mysql.c: MySQL RealTime:
Connection okay.
[2010-12-23 11:06:22] DEBUG[5941] res_config_mysql.c: MySQL RealTime:
Retrieve SQL: SELECT * FROM extensions_table WHERE exten =
'+380504446595' AND context = 'sip-direct' AND priority = '1'
[2010-12-23 11:06:22] DEBUG[5941] res_config_mysql.c: MySQL RealTime:
Connection okay.
[2010-12-23 11:06:22] DEBUG[5941] res_config_mysql.c: MySQL RealTime:
Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%'
AND context = 'sip-direct' AND priority = '1' ORDER BY exten
[2010-12-23 11:06:22] DEBUG[5941] chan_sip.c: build_route: Contact
hop: <sip:001...@78.84.207.114:5060;transport=UDP;ob>
[2010-12-23 11:06:22] DEBUG[5941] chan_sip.c: Incoming INVITE with
'timer' option supported and "Session-Expires" header.
[2010-12-23 11:06:22] DEBUG[5941] chan_sip.c: Session-Expires: 1800
[2010-12-23 11:06:22] DEBUG[5941] chan_sip.c: Received Min-SE: 90
[2010-12-23 11:06:22] DEBUG[5941] chan_sip.c: Session timer started:
27725 - 2WZXYS-qTPPfXylUor4tckg25TetmIVP
[2010-12-23 11:06:22] DEBUG[5941] chan_sip.c: SIP/0010101-0000004b:
New call is still down.... Trying...
[2010-12-23 11:06:22] DEBUG[5941] chan_sip.c: Trying to put 'SIP/2.0
100' onto UDP socket destined for 78.84.207.114:5060
[2010-12-23 11:06:22] DEBUG[5931] devicestate.c: No provider found,
checking channel drivers for SIP - 0010101
[2010-12-23 11:06:22] DEBUG[5931] chan_sip.c: Checking device state
for peer 0010101
[2010-12-23 11:06:22] DEBUG[8264] res_config_mysql.c: MySQL RealTime:
Connection okay.
[2010-12-23 11:06:22] DEBUG[8264] res_config_mysql.c: MySQL RealTime:
Retrieve SQL: SELECT * FROM extensions_table WHERE exten =
'+380504446595' AND context = 'sip-direct' AND priority = '1'
[2010-12-23 11:06:22] DEBUG[5931] res_config_mysql.c: MySQL RealTime:
Connection okay.
[2010-12-23 11:06:22] DEBUG[5931] res_config_mysql.c: MySQL RealTime:
Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '0010101' AND
host = 'dynamic'
[2010-12-23 11:06:22] DEBUG[5931] chan_sip.c: -REALTIME- peer built.
Name: 0010101. Peer objects: 660
[2010-12-23 11:06:22] DEBUG[5931] netsock2.c: Splitting
'78.84.207.114' gives...
[2010-12-23 11:06:22] DEBUG[5931] netsock2.c: ...host '78.84.207.114'
and port '(null)'.
[2010-12-23 11:06:22] DEBUG[5931] chan_sip.c: Not an IPv4 nor IPv6
address, cannot get port.
[2010-12-23 11:06:22] DEBUG[5931] chan_sip.c: Not an IPv4 nor IPv6
address, cannot set port.
[2010-12-23 11:06:22] DEBUG[5931] chan_sip.c: -REALTIME- loading peer
from database to memory. Name: 0010101. Peer objects: 660
[2010-12-23 11:06:22] DEBUG[5931] chan_sip.c: Destroying SIP peer
0010101
[2010-12-23 11:06:22] DEBUG[5931] chan_sip.c: -REALTIME- peer
Destroyed. Name: 0010101. Realtime Peer objects: 659
[2010-12-23 11:06:22] DEBUG[5931] devicestate.c: Changing state for
SIP/0010101 - state 1 (Not in use)
[2010-12-23 11:06:22] DEBUG[5931] devicestate.c: device 'SIP/0010101'
state '1'
[2010-12-23 11:06:22] DEBUG[8264] res_config_mysql.c: MySQL RealTime:
Connection okay.
[2010-12-23 11:06:22] DEBUG[8264] res_config_mysql.c: MySQL RealTime:
Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%'
AND context = 'sip-direct' AND priority = '1' ORDER BY exten
[2010-12-23 11:06:22] DEBUG[8264] res_config_mysql.c: MySQL RealTime:
Connection okay.
[2010-12-23 11:06:22] DEBUG[8264] res_config_mysql.c: MySQL RealTime:
Retrieve SQL: SELECT * FROM extensions_table WHERE exten =
'+380504446595' AND context = 'sip-direct' AND priority = '1'
[2010-12-23 11:06:22] DEBUG[8264] res_config_mysql.c: MySQL RealTime:
Connection okay.
[2010-12-23 11:06:22] DEBUG[8264] res_config_mysql.c: MySQL RealTime:
Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%'
AND context = 'sip-direct' AND priority = '1' ORDER BY exten
[2010-12-23 11:06:22] DEBUG[8264] pbx.c: Result of 'EXTEN' is
'+380504446595'
[2010-12-23 11:06:22] DEBUG[8264] pbx.c: Launching 'Goto'
[2010-12-23 11:06:22] VERBOSE[8264] pbx.c: -- Executing
[+380504446595@from-client:1] Goto("SIP/0010101-0000004b", "a2billing,
380504446595,1") in new stack
[2010-12-23 11:06:22] VERBOSE[8264] pbx.c: -- Goto (a2billing,
380504446595,1)
[2010-12-23 11:06:22] DEBUG[8264] pbx.c: Launching 'AGI'
[2010-12-23 11:06:22] VERBOSE[8264] pbx.c: -- Executing
[380504446595@a2billing:1] AGI("SIP/0010101-0000004b", "a2billing.php,
8") in new stack
[2010-12-23 11:06:22] VERBOSE[8264] res_agi.c: -- Launched AGI
Script /var/lib/asterisk/agi-bin/a2billing.php
[2010-12-23 11:06:22] DEBUG[5941] chan_sip.c: = Looking for Call ID:
6d2e7b316aa9ec0a...@193.200.241.188:5060 (Checking To) --
From tag as60bf21d0 --To-tag z9hG4bK16a5d6f5
[2010-12-23 11:06:22] DEBUG[5941] chan_sip.c: Stopping retransmission
on '6d2e7b316aa9ec0a...@193.200.241.188:5060' of Request
102: Match Found
[2010-12-23 11:06:22] DEBUG[5941] chan_sip.c: Got 200 accepted on
NOTIFY
[2010-12-23 11:06:22] DEBUG[5941] chan_sip.c: Destroying SIP dialog
6d2e7b316aa9ec0a...@193.200.241.188:5060
[2010-12-23 11:06:22] DEBUG[8264] pbx.c: Result of 'IDCONF' is NULL
[2010-12-23 11:06:22] DEBUG[5931] devicestate.c: No provider found,
checking channel drivers for SIP - 0010101
[2010-12-23 11:06:22] DEBUG[5931] chan_sip.c: Checking device state
for peer 0010101
[2010-12-23 11:06:22] DEBUG[8264] chan_sip.c: SIP answering channel:
SIP/0010101-0000004b
[2010-12-23 11:06:22] DEBUG[8264] res_rtp_asterisk.c: Setting the
marker bit due to a source update
[2010-12-23 11:06:22] DEBUG[8264] chan_sip.c: Setting framing from
config on incoming call
[2010-12-23 11:06:22] DEBUG[8264] chan_sip.c: ** Our capability: 0x100
(g729) Video flag: True Text flag: True
[2010-12-23 11:06:22] DEBUG[8264] chan_sip.c: ** Our prefcodec: 0x0
(nothing)
[2010-12-23 11:06:22] DEBUG[8264] chan_sip.c: -- Done with adding
codecs to SDP
[2010-12-23 11:06:22] DEBUG[8264] chan_sip.c: Done building SDP.
Settling with this capability: 0x100 (g729)
[2010-12-23 11:06:22] DEBUG[8264] chan_sip.c: Trying to put 'SIP/2.0
200' onto UDP socket destined for 78.84.207.114:5060
[2010-12-23 11:06:22] DEBUG[5931] res_config_mysql.c: MySQL RealTime:
Connection okay.
[2010-12-23 11:06:22] DEBUG[5931] res_config_mysql.c: MySQL RealTime:
Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '0010101' AND
host = 'dynamic'
[2010-12-23 11:06:22] DEBUG[5931] chan_sip.c: -REALTIME- peer built.
Name: 0010101. Peer objects: 660
[2010-12-23 11:06:22] DEBUG[5931] netsock2.c: Splitting
'78.84.207.114' gives...
[2010-12-23 11:06:22] DEBUG[5931] netsock2.c: ...host '78.84.207.114'
and port '(null)'.
[2010-12-23 11:06:22] DEBUG[5931] chan_sip.c: Not an IPv4 nor IPv6
address, cannot get port.
[2010-12-23 11:06:22] DEBUG[5931] chan_sip.c: Not an IPv4 nor IPv6
address, cannot set port.
[2010-12-23 11:06:22] DEBUG[5931] chan_sip.c: -REALTIME- loading peer
from database to memory. Name: 0010101. Peer objects: 660
[2010-12-23 11:06:22] DEBUG[5931] chan_sip.c: Destroying SIP peer
0010101
[2010-12-23 11:06:22] DEBUG[5931] chan_sip.c: -REALTIME- peer
Destroyed. Name: 0010101. Realtime Peer objects: 659
[2010-12-23 11:06:22] DEBUG[5931] devicestate.c: Changing state for
SIP/0010101 - state 1 (Not in use)
[2010-12-23 11:06:22] DEBUG[5931] devicestate.c: device 'SIP/0010101'
state '1'
[2010-12-23 11:06:22] WARNING[8264] res_srtp.c: SRTP unprotect:
authentication failure
[2010-12-23 11:06:22] DEBUG[5941] chan_sip.c: = Looking for Call ID:
2WZXYS-qTPPfXylUor4tckg25TetmIVP (Checking From) --From tag
50FYKcXAUIrUwsIpR5xm9pjrSrMaDglb --To-tag as46be1cdb
[2010-12-23 11:06:22] DEBUG[5941] chan_sip.c: **** Received ACK (6) -
Command in SIP ACK
[2010-12-23 11:06:22] DEBUG[5941] chan_sip.c: Stopping retransmission
on '2WZXYS-qTPPfXylUor4tckg25TetmIVP' of Response 20465: Match Found
[2010-12-23 11:06:22] WARNING[8264] res_srtp.c: SRTP unprotect:
authentication failure
[2010-12-23 11:06:22] WARNING[8264] res_srtp.c: SRTP unprotect:
authentication failure
[2010-12-23 11:06:22] WARNING[8264] res_srtp.c: SRTP unprotect:
authentication failure
[2010-12-23 11:06:22] WARNING[8264] res_srtp.c: SRTP unprotect:
authentication failure
[2010-12-23 11:06:22] WARNING[8264] res_srtp.c: SRTP unprotect:
authentication failure
[2010-12-23 11:06:22] WARNING[8264] res_srtp.c: SRTP unprotect:
authentication failure
[2010-12-23 11:06:22] WARNING[8264] res_srtp.c: SRTP unprotect:
authentication failure
[2010-12-23 11:06:22] WARNING[8264] res_srtp.c: SRTP unprotect:
authentication failure