Failed to authenticate if sip hostname couldn't be resolved when asterisk was starting

embed · May 29, 2020, 8:39pm

Hi,

I have a problem that asterisk isn’t accepting accepting calls if the hostname of the SIP server couldn’t be resolved by the dns server when asterisk is starting (e.g. network isn’t ready yet). Otherwise it works perfectly.

NOTICE[153][C-00000001] chan_sip.c: Failed to authenticate device <sip:015111111111@fritz.box>;tag=A0F8533AA472D405 for INVITE, code = -1

The only way to get asterisk to work is to restart asterisk (sip reload isn’t helping). A workaround is to add the IP address of the SIP server to the /etc/hosts to ensure that the hostname can be resolved. This obviously isn’t a nice solution.

I thought that asterisk would retry to resolve the hostname, like it retries to connect to the SIP server. Is this a configuration error or could this be a bug?

My config:

cat /etc/asterisk/sip.conf

[general]
allowguest=no

videosupport=no
dtmfmode=rfc2833
srvlookup=yes
directmedia=no
nat=no
registerattempts=0 # attempt to reregister indefinitely
qualify=5000 # check if client is reachable

; set codecs
disallow=all
allow=g722
allow=alaw
allow=ulaw

language = de

register => 620:password@fritz.box/620

[620]
callerid = Heizung
type = peer
host = fritz.box

transport = udp

context = incoming

; internet says this is necessary for some fritzbox versions
authuser = 620
defaultuser = 620
fromuser = 620


call-limit = 1

canreinvite = no

Logs of asterisk starting without network connection and later connecting the network:

cat /var/log/asterisk/full

[Jan1 00:00:05] Asterisk 17.4.0 built by user @ user-pc on a x86_64 running Linux on 2020-05-29 19:03:05 UTC
[Jan1 00:00:05] NOTICE[128] loader.c: 34 modules will be loaded.
[Jan1 00:00:05] NOTICE[128] cdr.c: CDR logging disabled.
[Jan1 00:00:05] VERBOSE[128] chan_sip.c: SIP channel loading...
[Jan1 00:00:05] ERROR[128] netsock2.c: getaddrinfo("fritz.box", "(null)", ...): Temporary failure in name resolution
[Jan1 00:00:05] WARNING[128] acl.c: Unable to lookup 'fritz.box'
[Jan1 00:00:05] WARNING[133] chan_sip.c: chan_sip has no official maintainer and is deprecated.Migration to
[Jan1 00:00:05] WARNING[133] chan_sip.c: chan_pjsip is recommended.See guides at the Asterisk Wiki:
[Jan1 00:00:05] WARNING[133] chan_sip.c: https://wiki.asterisk.org/wiki/display/AST/Migrating+from+chan_sip+to+res_pjsip
[Jan1 00:00:05] WARNING[133] chan_sip.c: https://wiki.asterisk.org/wiki/display/AST/Configuring+res_pjsip
[Jan1 00:00:05] VERBOSE[128] asterisk.c: Asterisk Ready.
[Jan1 00:00:05] ERROR[153] netsock2.c: getaddrinfo("fritz.box", "(null)", ...): Temporary failure in name resolution
[Jan1 00:00:05] WARNING[153] acl.c: Unable to lookup 'fritz.box'
[Jan1 00:00:05] WARNING[153] acl.c: Cannot connect to (null): Invalid argument
[Jan1 00:00:05] WARNING[153] chan_sip.c: sip_xmit of 0x768030b8 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:00:06] WARNING[153] chan_sip.c: sip_xmit of 0x768030b8 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:00:07] WARNING[153] chan_sip.c: sip_xmit of 0x768030b8 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:00:09] WARNING[153] chan_sip.c: sip_xmit of 0x768030b8 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:00:13] WARNING[153] chan_sip.c: sip_xmit of 0x768030b8 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:00:17] WARNING[153] chan_sip.c: sip_xmit of 0x768030b8 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:00:21] WARNING[153] chan_sip.c: sip_xmit of 0x768030b8 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:00:25] WARNING[153] chan_sip.c: sip_xmit of 0x768030b8 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:00:25] ERROR[153] netsock2.c: getaddrinfo("fritz.box", "(null)", ...): Temporary failure in name resolution
[Jan1 00:00:25] WARNING[153] acl.c: Unable to lookup 'fritz.box'
[Jan1 00:00:25] WARNING[153] acl.c: Cannot connect to (null): Invalid argument
[Jan1 00:00:25] WARNING[153] chan_sip.c: sip_xmit of 0x76803328 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:00:25] NOTICE[153] chan_sip.c:-- Registration for '620@fritz.box' timed out, trying again (Attempt #2)
[Jan1 00:00:26] WARNING[153] chan_sip.c: sip_xmit of 0x76803328 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:00:27] WARNING[153] chan_sip.c: sip_xmit of 0x76803328 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:00:29] WARNING[153] chan_sip.c: sip_xmit of 0x76803328 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:00:33] WARNING[153] chan_sip.c: sip_xmit of 0x76803328 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:00:37] WARNING[153] chan_sip.c: sip_xmit of 0x76803328 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:00:41] WARNING[153] chan_sip.c: sip_xmit of 0x76803328 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:00:45] WARNING[153] chan_sip.c: sip_xmit of 0x76803328 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:00:45] ERROR[153] netsock2.c: getaddrinfo("fritz.box", "(null)", ...): Temporary failure in name resolution
[Jan1 00:00:45] WARNING[153] acl.c: Unable to lookup 'fritz.box'
[Jan1 00:00:45] WARNING[153] acl.c: Cannot connect to (null): Invalid argument
[Jan1 00:00:45] WARNING[153] chan_sip.c: sip_xmit of 0x76801b60 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:00:45] NOTICE[153] chan_sip.c:-- Registration for '620@fritz.box' timed out, trying again (Attempt #3)
[Jan1 00:00:46] WARNING[153] chan_sip.c: sip_xmit of 0x76801b60 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:00:47] WARNING[153] chan_sip.c: sip_xmit of 0x76801b60 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:00:49] WARNING[153] chan_sip.c: sip_xmit of 0x76801b60 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:00:53] WARNING[153] chan_sip.c: sip_xmit of 0x76801b60 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:00:57] WARNING[153] chan_sip.c: sip_xmit of 0x76801b60 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:01:01] WARNING[153] chan_sip.c: sip_xmit of 0x76801b60 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:01:05] WARNING[153] chan_sip.c: sip_xmit of 0x76801b60 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:01:05] ERROR[153] netsock2.c: getaddrinfo("fritz.box", "(null)", ...): Temporary failure in name resolution
[Jan1 00:01:05] WARNING[153] acl.c: Unable to lookup 'fritz.box'
[Jan1 00:01:05] WARNING[153] acl.c: Cannot connect to (null): Invalid argument
[Jan1 00:01:05] WARNING[153] chan_sip.c: sip_xmit of 0x76804b28 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:01:05] NOTICE[153] chan_sip.c:-- Registration for '620@fritz.box' timed out, trying again (Attempt #4)
[Jan1 00:01:06] WARNING[153] chan_sip.c: sip_xmit of 0x76804b28 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:01:07] WARNING[153] chan_sip.c: sip_xmit of 0x76804b28 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:01:09] WARNING[153] chan_sip.c: sip_xmit of 0x76804b28 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:01:13] WARNING[153] chan_sip.c: sip_xmit of 0x76804b28 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:01:17] WARNING[153] chan_sip.c: sip_xmit of 0x76804b28 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:01:21] WARNING[153] chan_sip.c: sip_xmit of 0x76804b28 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:01:25] WARNING[153] chan_sip.c: sip_xmit of 0x76804b28 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:01:25] ERROR[153] netsock2.c: getaddrinfo("fritz.box", "(null)", ...): Temporary failure in name resolution
[Jan1 00:01:25] WARNING[153] acl.c: Unable to lookup 'fritz.box'
[Jan1 00:01:25] WARNING[153] acl.c: Cannot connect to (null): Invalid argument
[Jan1 00:01:25] WARNING[153] chan_sip.c: sip_xmit of 0x76805a80 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:01:25] NOTICE[153] chan_sip.c:-- Registration for '620@fritz.box' timed out, trying again (Attempt #5)
[Jan1 00:01:26] WARNING[153] chan_sip.c: sip_xmit of 0x76805a80 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:01:27] WARNING[153] chan_sip.c: sip_xmit of 0x76805a80 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:01:29] WARNING[153] chan_sip.c: sip_xmit of 0x76805a80 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:01:33] WARNING[153] chan_sip.c: sip_xmit of 0x76805a80 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:01:37] WARNING[153] chan_sip.c: sip_xmit of 0x76805a80 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:01:41] WARNING[153] chan_sip.c: sip_xmit of 0x76805a80 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:01:45] WARNING[153] chan_sip.c: sip_xmit of 0x76805a80 (len 377) to (null) returned -1: Invalid argument
[Jan1 00:01:45] NOTICE[153] chan_sip.c:-- Registration for '620@fritz.box' timed out, trying again (Attempt #6)
[Jan1 00:02:24] NOTICE[153][C-00000001] chan_sip.c: Failed to authenticate device <sip:015111111111@fritz.box>;tag=A0F8533AA472D405 for INVITE, code = -1

sip log

Asterisk 17.4.0, Copyright (C) 1999 - 2018, Digium, Inc. and others.
Created by Mark Spencer <markster@digium.com>
Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details.
This is free software, with components licensed under the GNU General Public
License version 2 and other licenses; you are welcome to redistribute it under
certain conditions. Type 'core show license' for details.
=========================================================================
Connected to Asterisk 17.4.0 currently running on sip-foo-gateway (pid = 128)
sip-foo-gateway*CLI> sip set debug on
SIP Debugging enabled

<--- SIP read from UDP:192.168.178.1:5060 --->
INVITE sip:620@192.168.178.81:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.178.1:5060;branch=z9hG4bK81BC1166F51DF18F
From: <sip:015111111111@fritz.box>;tag=45A85C4F10C17B1B
To: <sip:620@192.168.178.81:5060>
Call-ID: 92FAC1E8F2E515D5@192.168.178.1
CSeq: 36 INVITE
Contact: <sip:06C9D5D562651075DA4B678A9C224@192.168.178.1>
Max-Forwards: 70
Expires: 120
User-Agent: AVM FRITZ!Box Fon WLAN 7360 SL 109.06.34 (Mar 28 2017)
Supported: 100rel,replaces,timer
Allow-Events: telephone-event,refer
Allow: INVITE,ACK,OPTIONS,CANCEL,BYE,UPDATE,PRACK,INFO,SUBSCRIBE,NOTIFY,REFER,MESSAGE,PUBLISH
Content-Type: application/sdp
Accept: application/sdp, multipart/mixed
Accept-Encoding: identity
Content-Length: 421

v=0
o=user 14256808 14256808 IN IP4 192.168.178.1
s=call
c=IN IP4 192.168.178.1
t=0 0
m=audio 7082 RTP/AVP 9 8 0 2 102 100 99 97 120 121 101
a=sendrecv
a=rtpmap:2 G726-32/8000
a=rtpmap:102 G726-32/8000
a=rtpmap:100 G726-40/8000
a=rtpmap:99 G726-24/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:120 PCMA/16000
a=rtpmap:121 PCMU/16000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtcp:7083
<------------->
--- (17 headers 18 lines) ---
Sending to 192.168.178.1:5060 (no NAT)
Sending to 192.168.178.1:5060 (no NAT)
Using INVITE request as basis request - 92FAC1E8F2E515D5@192.168.178.1
No matching peer for '015111111111' from '192.168.178.1:5060'

<--- Reliably Transmitting (no NAT) to 192.168.178.1:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.178.1:5060;branch=z9hG4bK81BC1166F51DF18F;received=192.168.178.1
From: <sip:015111111111@fritz.box>;tag=45A85C4F10C17B1B
To: <sip:620@192.168.178.81:5060>;tag=as466fcb4d
Call-ID: 92FAC1E8F2E515D5@192.168.178.1
CSeq: 36 INVITE
Server: Asterisk PBX 17.4.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="057210e8"
Content-Length: 0


<------------>
Scheduling destruction of SIP dialog '92FAC1E8F2E515D5@192.168.178.1' in 32000 ms (Method: INVITE)

<--- SIP read from UDP:192.168.178.1:5060 --->
ACK sip:620@192.168.178.81:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.178.1:5060;branch=z9hG4bK81BC1166F51DF18F
From: <sip:015111111111@fritz.box>;tag=45A85C4F10C17B1B
To: <sip:620@192.168.178.81:5060>;tag=as466fcb4d
Call-ID: 92FAC1E8F2E515D5@192.168.178.1
CSeq: 36 ACK
User-Agent: AVM FRITZ!Box Fon WLAN 7360 SL 109.06.34 (Mar 28 2017)
Content-Length: 0

<------------->
--- (8 headers 0 lines) ---

<--- SIP read from UDP:192.168.178.1:5060 --->
INVITE sip:620@192.168.178.81:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.178.1:5060;branch=z9hG4bK050014180D1AEF8A
From: <sip:015111111111@fritz.box>;tag=45A85C4F10C17B1B
To: <sip:620@192.168.178.81:5060>
Call-ID: 92FAC1E8F2E515D5@192.168.178.1
CSeq: 37 INVITE
Contact: <sip:06C9D5D562651075DA4B678A9C224@192.168.178.1>
Authorization: Digest username="620", realm="asterisk", nonce="057210e8", uri="sip:620@192.168.178.81:5060", response="ff1698291cb074671c31b0086b94c4e1", algorithm=MD5
Max-Forwards: 70
Expires: 120
User-Agent: AVM FRITZ!Box Fon WLAN 7360 SL 109.06.34 (Mar 28 2017)
Supported: 100rel,replaces,timer
Allow-Events: telephone-event,refer
Allow: INVITE,ACK,OPTIONS,CANCEL,BYE,UPDATE,PRACK,INFO,SUBSCRIBE,NOTIFY,REFER,MESSAGE,PUBLISH
Content-Type: application/sdp
Accept: application/sdp, multipart/mixed
Accept-Encoding: identity
Content-Length: 421

v=0
o=user 14256808 14256808 IN IP4 192.168.178.1
s=call
c=IN IP4 192.168.178.1
t=0 0
m=audio 7082 RTP/AVP 9 8 0 2 102 100 99 97 120 121 101
a=sendrecv
a=rtpmap:2 G726-32/8000
a=rtpmap:102 G726-32/8000
a=rtpmap:100 G726-40/8000
a=rtpmap:99 G726-24/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:120 PCMA/16000
a=rtpmap:121 PCMU/16000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtcp:7083
<------------->
--- (18 headers 18 lines) ---
Sending to 192.168.178.1:5060 (no NAT)
Using INVITE request as basis request - 92FAC1E8F2E515D5@192.168.178.1
No matching peer for '015111111111' from '192.168.178.1:5060'
[Jan1 00:05:11] NOTICE[153][C-00000002]: chan_sip.c:19663 send_check_user_failure_response: Failed to authenticate device <sip:015111111111@fritz.box>;tag=45A85C4F10C17B1B for INVITE, code = -1

<--- Reliably Transmitting (no NAT) to 192.168.178.1:5060 --->
SIP/2.0 403 Forbidden
Via: SIP/2.0/UDP 192.168.178.1:5060;branch=z9hG4bK050014180D1AEF8A;received=192.168.178.1
From: <sip:015111111111@fritz.box>;tag=45A85C4F10C17B1B
To: <sip:620@192.168.178.81:5060>;tag=as466fcb4d
Call-ID: 92FAC1E8F2E515D5@192.168.178.1
CSeq: 37 INVITE
Server: Asterisk PBX 17.4.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


<------------>
Scheduling destruction of SIP dialog '92FAC1E8F2E515D5@192.168.178.1' in 32000 ms (Method: INVITE)

<--- SIP read from UDP:192.168.178.1:5060 --->
ACK sip:620@192.168.178.81:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.178.1:5060;branch=z9hG4bK050014180D1AEF8A
From: <sip:015111111111@fritz.box>;tag=45A85C4F10C17B1B
To: <sip:620@192.168.178.81:5060>;tag=as466fcb4d
Call-ID: 92FAC1E8F2E515D5@192.168.178.1
CSeq: 37 ACK
User-Agent: AVM FRITZ!Box Fon WLAN 7360 SL 109.06.34 (Mar 28 2017)
Content-Length: 0

<------------->
--- (8 headers 0 lines) ---

Logs if the network was always connected (no problems):

full log with sip log

[Jan1 00:02:02] Asterisk 17.4.0 built by user @ user-pc on a x86_64 running Linux on 2020-05-29 19:03:05 UTC
[Jan1 00:02:02] NOTICE[220] loader.c: 34 modules will be loaded.
[Jan1 00:02:02] NOTICE[220] cdr.c: CDR logging disabled.
[Jan1 00:02:02] VERBOSE[220] chan_sip.c: SIP channel loading...
[Jan1 00:02:02] NOTICE[243] chan_sip.c: Peer '620' is now Reachable. (12ms / 5000ms)
[Jan1 00:02:02] WARNING[223] chan_sip.c: chan_sip has no official maintainer and is deprecated.Migration to
[Jan1 00:02:02] WARNING[223] chan_sip.c: chan_pjsip is recommended.See guides at the Asterisk Wiki:
[Jan1 00:02:02] WARNING[223] chan_sip.c: https://wiki.asterisk.org/wiki/display/AST/Migrating+from+chan_sip+to+res_pjsip
[Jan1 00:02:02] WARNING[223] chan_sip.c: https://wiki.asterisk.org/wiki/display/AST/Configuring+res_pjsip
[Jan1 00:02:02] VERBOSE[220] asterisk.c: Asterisk Ready.
[Jan1 00:02:24] VERBOSE[243] chan_sip.c:
<--- SIP read from UDP:192.168.178.1:5060 --->
INVITE sip:620@192.168.178.81:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.178.1:5060;branch=z9hG4bKF702CED66C6D8B5D
From: <sip:015111111111@fritz.box>;tag=7E1290EB5A74B437
To: <sip:620@192.168.178.81:5060>
Call-ID: 34882F37FE5F9F93@192.168.178.1
CSeq: 42 INVITE
Contact: <sip:06C9D5D562651075DA4B678A9C224@192.168.178.1>
Max-Forwards: 70
Expires: 120
User-Agent: AVM FRITZ!Box Fon WLAN 7360 SL 109.06.34 (Mar 28 2017)
Supported: 100rel,replaces,timer
Allow-Events: telephone-event,refer
Allow: INVITE,ACK,OPTIONS,CANCEL,BYE,UPDATE,PRACK,INFO,SUBSCRIBE,NOTIFY,REFER,MESSAGE,PUBLISH
Content-Type: application/sdp
Accept: application/sdp, multipart/mixed
Accept-Encoding: identity
Content-Length: 421

v=0
o=user 15532776 15532776 IN IP4 192.168.178.1
s=call
c=IN IP4 192.168.178.1
t=0 0
m=audio 7078 RTP/AVP 9 8 0 2 102 100 99 97 120 121 101
a=sendrecv
a=rtpmap:2 G726-32/8000
a=rtpmap:102 G726-32/8000
a=rtpmap:100 G726-40/8000
a=rtpmap:99 G726-24/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:120 PCMA/16000
a=rtpmap:121 PCMU/16000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtcp:7079
<------------->
[Jan1 00:02:24] VERBOSE[243] chan_sip.c: --- (17 headers 18 lines) ---
[Jan1 00:02:24] VERBOSE[243] chan_sip.c: Sending to 192.168.178.1:5060 (no NAT)
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Sending to 192.168.178.1:5060 (no NAT)
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Using INVITE request as basis request - 34882F37FE5F9F93@192.168.178.1
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Found peer '620' for '015111111111' from 192.168.178.1:5060
[Jan1 00:02:24] VERBOSE[243][C-00000001] netsock2.c: Using SIP RTP CoS mark 5
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Got SDP version 15532776 and unique parts [user 15532776 IN IP4 192.168.178.1]
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Found RTP audio format 9
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Found RTP audio format 8
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Found RTP audio format 0
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Found RTP audio format 2
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Found RTP audio format 102
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Found RTP audio format 100
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Found RTP audio format 99
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Found RTP audio format 97
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Found RTP audio format 120
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Found RTP audio format 121
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Found RTP audio format 101
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Found audio description format G726-32 for ID 2
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Found audio description format G726-32 for ID 102
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Found unknown media description format G726-40 for ID 100
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Found unknown media description format G726-24 for ID 99
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Found audio description format iLBC for ID 97
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Found unknown media description format PCMA for ID 120
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Found unknown media description format PCMU for ID 121
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Found audio description format telephone-event for ID 101
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Capabilities: us - (g722|alaw|ulaw), peer - audio=(ulaw|g726|alaw|g722|ilbc)/video=(nothing)/text=(nothing), combined - (g722|alaw|ulaw)
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
[Jan1 00:02:24] VERBOSE[243][C-00000001] res_rtp_asterisk.c: 0x1212238 -- Strict RTP learning after remote address set to: 192.168.178.1:7078
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Peer audio RTP is at port 192.168.178.1:7078
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c: Looking for 620 in incoming (domain 192.168.178.81)
[Jan1 00:02:24] VERBOSE[243][C-00000001] sip/route.c: sip_route_dump: route/path hop: <sip:06C9D5D562651075DA4B678A9C224@192.168.178.1>
[Jan1 00:02:24] VERBOSE[243][C-00000001] chan_sip.c:
<--- Transmitting (no NAT) to 192.168.178.1:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.178.1:5060;branch=z9hG4bKF702CED66C6D8B5D;received=192.168.178.1
From: <sip:015111111111@fritz.box>;tag=7E1290EB5A74B437
To: <sip:620@192.168.178.81:5060>
Call-ID: 34882F37FE5F9F93@192.168.178.1
CSeq: 42 INVITE
Server: Asterisk PBX 17.4.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:620@192.168.178.81:5060>
Content-Length: 0


<------------>
[Jan1 00:02:24] VERBOSE[248][C-00000001] pbx.c: Executing [620@incoming:1] Set("SIP/620-00000000", "TIMEOUT(absolute)=60") in new stack
[Jan1 00:02:24] VERBOSE[248][C-00000001] func_timeout.c: Channel will hangup at 1970-01-01 00:03:24.241 UTC.
[Jan1 00:02:24] VERBOSE[248][C-00000001] pbx.c: Executing [620@incoming:2] Ringing("SIP/620-00000000", "") in new stack
[Jan1 00:02:24] VERBOSE[248][C-00000001] chan_sip.c:
<--- Transmitting (no NAT) to 192.168.178.1:5060 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.178.1:5060;branch=z9hG4bKF702CED66C6D8B5D;received=192.168.178.1
From: <sip:015111111111@fritz.box>;tag=7E1290EB5A74B437
To: <sip:620@192.168.178.81:5060>;tag=as60d084d2
Call-ID: 34882F37FE5F9F93@192.168.178.1
CSeq: 42 INVITE
Server: Asterisk PBX 17.4.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:620@192.168.178.81:5060>
Content-Length: 0


<------------>
[Jan1 00:02:24] VERBOSE[248][C-00000001] pbx.c: Executing [620@incoming:3] Wait("SIP/620-00000000", "10") in new stack
[Jan1 00:02:31] VERBOSE[243] chan_sip.c:
<--- SIP read from UDP:192.168.178.1:5060 --->
CANCEL sip:620@192.168.178.81:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.178.1:5060;branch=z9hG4bKF702CED66C6D8B5D
From: <sip:015111111111@fritz.box>;tag=7E1290EB5A74B437
To: <sip:620@192.168.178.81:5060>
Call-ID: 34882F37FE5F9F93@192.168.178.1
CSeq: 42 CANCEL
Reason: Q.850; cause=16
Max-Forwards: 70
User-Agent: AVM FRITZ!Box Fon WLAN 7360 SL 109.06.34 (Mar 28 2017)
Supported: 100rel,replaces,timer
Allow-Events: telephone-event,refer
Content-Length: 0

<------------->
[Jan1 00:02:31] VERBOSE[243] chan_sip.c: --- (12 headers 0 lines) ---
[Jan1 00:02:31] VERBOSE[243][C-00000001] chan_sip.c: Sending to 192.168.178.1:5060 (no NAT)
[Jan1 00:02:31] VERBOSE[243][C-00000001] chan_sip.c:
<--- Reliably Transmitting (no NAT) to 192.168.178.1:5060 --->
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 192.168.178.1:5060;branch=z9hG4bKF702CED66C6D8B5D;received=192.168.178.1
From: <sip:015111111111@fritz.box>;tag=7E1290EB5A74B437
To: <sip:620@192.168.178.81:5060>;tag=as60d084d2
Call-ID: 34882F37FE5F9F93@192.168.178.1
CSeq: 42 INVITE
Server: Asterisk PBX 17.4.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


<------------>
[Jan1 00:02:31] VERBOSE[243][C-00000001] chan_sip.c:
<--- Transmitting (no NAT) to 192.168.178.1:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.178.1:5060;branch=z9hG4bKF702CED66C6D8B5D;received=192.168.178.1
From: <sip:015111111111@fritz.box>;tag=7E1290EB5A74B437
To: <sip:620@192.168.178.81:5060>;tag=as60d084d2
Call-ID: 34882F37FE5F9F93@192.168.178.1
CSeq: 42 CANCEL
Server: Asterisk PBX 17.4.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


<------------>
[Jan1 00:02:31] VERBOSE[248][C-00000001] pbx.c: Spawn extension (incoming, 620, 3) exited non-zero on 'SIP/620-00000000'
[Jan1 00:02:31] VERBOSE[243] chan_sip.c:
<--- SIP read from UDP:192.168.178.1:5060 --->
ACK sip:620@192.168.178.81:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.178.1:5060;branch=z9hG4bKF702CED66C6D8B5D
From: <sip:015111111111@fritz.box>;tag=7E1290EB5A74B437
To: <sip:620@192.168.178.81:5060>;tag=as60d084d2
Call-ID: 34882F37FE5F9F93@192.168.178.1
CSeq: 42 ACK
User-Agent: AVM FRITZ!Box Fon WLAN 7360 SL 109.06.34 (Mar 28 2017)
Content-Length: 0

<------------->
[Jan1 00:02:31] VERBOSE[243] chan_sip.c: --- (8 headers 0 lines) ---
[Jan1 00:02:31] VERBOSE[243] chan_sip.c: Really destroying SIP dialog '34882F37FE5F9F93@192.168.178.1' Method: ACK
[Jan1 00:03:02] VERBOSE[243] chan_sip.c: Reliably Transmitting (no NAT) to 192.168.178.1:5060:
OPTIONS sip:fritz.box SIP/2.0
Via: SIP/2.0/UDP 192.168.178.81:5060;branch=z9hG4bK69bf1170
Max-Forwards: 70
From: "asterisk" <sip:620@192.168.178.81>;tag=as012f9a44
To: <sip:fritz.box>
Contact: <sip:620@192.168.178.81:5060>
Call-ID: 7efdb7f80a488441789076751a52e06a@192.168.178.81:5060
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX 17.4.0
Date: Thu, 01 Jan 1970 00:03:02 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---
[Jan1 00:03:02] VERBOSE[243] chan_sip.c:
<--- SIP read from UDP:192.168.178.1:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.178.81:5060;branch=z9hG4bK69bf1170
From: "asterisk" <sip:620@192.168.178.81>;tag=as012f9a44
To: <sip:fritz.box>;tag=06C69E3AD2734FD7
Call-ID: 7efdb7f80a488441789076751a52e06a@192.168.178.81:5060
CSeq: 102 OPTIONS
Contact: <sip:06C9D5D562651075DA4B678A9C224@127.0.0.1>
WWW-Authenticate: Digest realm="fritz.box", nonce="F0AC1103DCCEDAF7"
User-Agent: FRITZ!OS
Content-Length: 0

<------------->
[Jan1 00:03:02] VERBOSE[243] chan_sip.c: --- (10 headers 0 lines) ---
[Jan1 00:03:02] VERBOSE[243] chan_sip.c: Really destroying SIP dialog '7efdb7f80a488441789076751a52e06a@192.168.178.81:5060' Method: OPTIONS
[Jan1 00:04:02] VERBOSE[243] chan_sip.c: Reliably Transmitting (no NAT) to 192.168.178.1:5060:
OPTIONS sip:fritz.box SIP/2.0
Via: SIP/2.0/UDP 192.168.178.81:5060;branch=z9hG4bK39498c8f
Max-Forwards: 70
From: "asterisk" <sip:620@192.168.178.81>;tag=as728d1848
To: <sip:fritz.box>
Contact: <sip:620@192.168.178.81:5060>
Call-ID: 38b81e9868ea4a3f38d82fbe137d2589@192.168.178.81:5060
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX 17.4.0
Date: Thu, 01 Jan 1970 00:04:02 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---
[Jan1 00:04:02] VERBOSE[243] chan_sip.c:
<--- SIP read from UDP:192.168.178.1:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.178.81:5060;branch=z9hG4bK39498c8f
From: "asterisk" <sip:620@192.168.178.81>;tag=as728d1848
To: <sip:fritz.box>;tag=DB8857DF3E970B17
Call-ID: 38b81e9868ea4a3f38d82fbe137d2589@192.168.178.81:5060
CSeq: 102 OPTIONS
Contact: <sip:06C9D5D562651075DA4B678A9C224@127.0.0.1>
WWW-Authenticate: Digest realm="fritz.box", nonce="08393D5F480B2743"
User-Agent: FRITZ!OS
Content-Length: 0

<------------->
[Jan1 00:04:02] VERBOSE[243] chan_sip.c: --- (10 headers 0 lines) ---
[Jan1 00:04:02] VERBOSE[243] chan_sip.c: Really destroying SIP dialog '38b81e9868ea4a3f38d82fbe137d2589@192.168.178.81:5060' Method: OPTIONS
[Jan1 00:05:02] VERBOSE[243] chan_sip.c: Reliably Transmitting (no NAT) to 192.168.178.1:5060:
OPTIONS sip:fritz.box SIP/2.0
Via: SIP/2.0/UDP 192.168.178.81:5060;branch=z9hG4bK7ad43744
Max-Forwards: 70
From: "asterisk" <sip:620@192.168.178.81>;tag=as53efd4d9
To: <sip:fritz.box>
Contact: <sip:620@192.168.178.81:5060>
Call-ID: 608aa520676f0303641bc87f274049bd@192.168.178.81:5060
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX 17.4.0
Date: Thu, 01 Jan 1970 00:05:02 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---
[Jan1 00:05:02] VERBOSE[243] chan_sip.c:
<--- SIP read from UDP:192.168.178.1:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.178.81:5060;branch=z9hG4bK7ad43744
From: "asterisk" <sip:620@192.168.178.81>;tag=as53efd4d9
To: <sip:fritz.box>;tag=EF15F42FF3509FDC
Call-ID: 608aa520676f0303641bc87f274049bd@192.168.178.81:5060
CSeq: 102 OPTIONS
Contact: <sip:06C9D5D562651075DA4B678A9C224@127.0.0.1>
WWW-Authenticate: Digest realm="fritz.box", nonce="C4AF44198B78261C"
User-Agent: FRITZ!OS
Content-Length: 0

<------------->
[Jan1 00:05:02] VERBOSE[243] chan_sip.c: --- (10 headers 0 lines) ---
[Jan1 00:05:02] VERBOSE[243] chan_sip.c: Really destroying SIP dialog '608aa520676f0303641bc87f274049bd@192.168.178.81:5060' Method: OPTIONS
#

david551 · May 30, 2020, 12:23am

Lots of things will break on Unix type systems if your startup sequence tries to start network type daemons before the network and DNS are up. Their startup scripts shouldn’t be run until the network startup script has been run, and you should not start the boot sequence until the network infrastructure is powered up and ready. How are you starting Asterisk? Is it correctly sequenced relative to the network startup script?

embed · May 30, 2020, 10:03am

Thanks for your answer. I have an embedded device, which is running asterisk. The problem occurs in practice after a power outage. After such an event the network router usually needs much longer to get ready than my embedded device and the dns lookup will obviously fail. I could probably wait to start asterisk until the hostname resolves, but this sounds like a hack.

Isn’t the current behavior also problematic if the ip address of the SIP server would change? I mean asterisk wouldn’t ask the DNS to see if the ip has changed.

Edit: I just found externhost and externrefresh. Maybe this is the solution for me? I’ll try them out later.

embed · May 30, 2020, 11:31am

I tried externhost and externrefresh, but no change. My peer stays at status unknown if the network wasn’t ready when asterisk started:

sip-foo-gateway*CLI> sip show peers
Name/username             Host                                    Dyn Forcerport Comedia    ACL Port     Status      Description              
620/620                   (Unspecified)                            D  No         No             0        UNKNOWN                   
1 sip peers [Monitored: 0 online, 1 offline Unmonitored: 0 online, 0 offline]

But the registry is fine:

sip-foo-gateway*CLI> sip show registry 
Host                                    dnsmgr Username       Refresh State                Reg.Time                 
fritz.box:5060                          N      620                285 Registered           Thu, 01 Jan 1970 00:13:15
1 SIP registrations.

david551 · May 30, 2020, 12:06pm

If you cannot sequence the power-up properly, you could try running caching name servers.

However, if you have a dynamic address, your options probably are proper power sequencing or changing to a service provider that will provide a stable address.

jcolp · June 1, 2020, 9:59am

The chan_sip module resolves at load time, and it may not reload the configuration if it has not changed. You could do “touch /etc/asterisk/sip.conf” before “sip reload” to see if that helps. Otherwise the other options presented are probably it.

embed · June 4, 2020, 11:12am

Ok, thx. I decided to add a watchdog script, which will restart asterisk if needed.

#!/bin/sh

CHECK_INTERVAL=60 # interval in seconds
FAIL_COUNTER=0
THRESHOLD=3


while true; do
  sleep $CHECK_INTERVAL
  
  # check if asterisk is running and start asterisk in case it isn't running
  if ! pgrep -x "asterisk" > /dev/null; then
    logger -s "asterisk_wdog: Asterisk not running! Starting asterisk"
    /etc/init.d/S50asterisk start
  fi
  
  # check peer and registry status
  if asterisk -rx 'sip show peers' | grep -qE 'UNREACHABLE|UNKNOWN' ||
     asterisk -rx 'sip show registry' | grep -qE 'Failed|Unregistered|Request Sent|Auth. Sent|Rejected|No Authentication'; then
    logger -s "asterisk_wdog: Asterisk failure, increasing fail counter..."
    FAIL_COUNTER=$((FAIL_COUNTER+1))
  elif [ "$FAIL_COUNTER" -gt "0" ]; then
    # reset counter if there wasn't a failure
    logger -s "asterisk_wdog: Reset fail counter"
    FAIL_COUNTER=0
  fi
  
  # restart asterisk if threshold is reached (and reset counter)
  if [ "$FAIL_COUNTER" -gt "$THRESHOLD" ]; then
    logger -s "asterisk_wdog: Failure threshold reached, restarting asterisk"
    /etc/init.d/S50asterisk restart
    FAIL_COUNTER=0
  fi
  
done

system · July 4, 2020, 11:12am

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.