Intermittent Busy Signal - invite problem?

Asterisk Asterisk SIP
1

Intermittently incoming calls get a busy signal. Without doing anything about 15 minutes later calls go through sometimes. Usually I restart Asterisk.

I asked for info from my service provider:
Your system IP 79.55.41 is sending a 401 Unauthorized message to generate the busy. Could you review the system logs to see why the system is doing this?

invite copy
invite copy403×843 123 KB

debug log:

[2025-01-06 05:42:20] NOTICE[1021] chan_sip.c: Registration from '<sip:1471@cats.com>' failed for '94.23.166.27:53799' - Wrong password
[2025-01-06 05:42:20] DEBUG[1021] chan_sip.c: SIP message could not be handled, bad request: e5f4a244222481e4f7a                                            $
[2025-01-06 05:42:25] DEBUG[955] cdr.c: CDR Engine termination request received; waiting on messages...
[2025-01-06 05:42:25] VERBOSE[955] asterisk.c: Asterisk cleanly ending (0).
[2025-01-06 05:42:25] VERBOSE[955] asterisk.c: Executing last minute cleanups
[2025-01-06 05:42:25] DEBUG[955] res_musiconhold.c: Destroying MOH class 'default'
[2025-01-06 05:42:25] DEBUG[955] res_musiconhold.c: Destroying MOH class 'wish'
[2025-01-06 05:42:25] DEBUG[955] asterisk.c: Asterisk ending (0).

Another debug log:

[2025-01-06 12:35:40] Asterisk 18.24.2 built by root @ ubuntu.aroint.com on a x86_64 running Linux on 2024-08-22 06:05:16 UTC
[2025-01-06 12:35:45] DEBUG[29706] chan_sip.c: Allocating new SIP dialog for 056a7de02ccbbc716a225cd46117e415@33.33.33.33.245:5060 - OPTIONS (No RTP)
[2025-01-06 12:35:45] DEBUG[29706] acl.c: For destination '208.100.60.14', our source address is '33.33.33.33.245'.
[2025-01-06 12:35:45] DEBUG[29706] chan_sip.c: Target address 208.100.60.14:5060 is not local, substituting externaddr
[2025-01-06 12:35:45] DEBUG[29706] chan_sip.c: Setting AST_TRANSPORT_UDP with address 33.33.33.33.245:5060
[2025-01-06 12:35:45] DEBUG[29706] chan_sip.c: SIP call-id changed from '056a7de02ccbbc716a225cd46117e415@33.33.33.33.245:5060' to '6fda9e785d71d569200416e9738af791@33.33.33.33.245:5060'
[2025-01-06 12:35:45] DEBUG[29706] chan_sip.c: Initializing initreq for method OPTIONS - callid 6fda9e785d71d569200416e9738af791@33.33.33.33.245:5060
[2025-01-06 12:35:45] DEBUG[29706] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 208.100.60.14:5060
[2025-01-06 12:35:45] DEBUG[29706] chan_sip.c: = Looking for  Call ID: 6fda9e785d71d569200416e9738af791@33.33.33.33.245:5060 (Checking To) --From tag as4152f2e7 --To-tag as460052d7  
[2025-01-06 12:35:45] DEBUG[29706] chan_sip.c: Stopping retransmission on '6fda9e785d71d569200416e9738af791@33.33.33.33.245:5060' of Request 102: Match Found
[2025-01-06 12:35:45] DEBUG[29706] chan_sip.c: Destroying SIP dialog 6fda9e785d71d569200416e9738af791@33.33.33.33.245:5060
[2025-01-06 12:35:46] DEBUG[29706] chan_sip.c: = Looking for  Call ID: 22e2620804696080386252k14420rmwp (Checking From) --From tag 24g5304656822717573231m --To-tag   
[2025-01-06 12:35:46] DEBUG[29706] acl.c: For destination '192.168.1.2', our source address is '192.168.1.1'.
[2025-01-06 12:35:46] DEBUG[29706] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.1.1:5060
[2025-01-06 12:35:46] DEBUG[29706] netsock2.c: Splitting '192.168.0.6:17746' into...
[2025-01-06 12:35:46] DEBUG[29706] netsock2.c: ...host '192.168.0.6' and port '17746'.
[2025-01-06 12:35:46] DEBUG[29706] chan_sip.c: NAT detected for 192.168.0.6 / 192.168.1.2
[2025-01-06 12:35:46] DEBUG[29706] chan_sip.c: Allocating new SIP dialog for 22e2620804696080386252k14420rmwp - REGISTER (No RTP)
[2025-01-06 12:35:46] DEBUG[29706] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[2025-01-06 12:35:46] DEBUG[29706] netsock2.c: Splitting '192.168.0.6:17746' into...
[2025-01-06 12:35:46] DEBUG[29706] netsock2.c: ...host '192.168.0.6' and port '17746'.
[2025-01-06 12:35:46] DEBUG[29706] chan_sip.c: NAT detected for 192.168.0.6 / 192.168.1.2
[2025-01-06 12:35:46] DEBUG[29706] netsock2.c: Splitting '192.168.1.1' into...
[2025-01-06 12:35:46] DEBUG[29706] netsock2.c: ...host '192.168.1.1' and port ''.
[2025-01-06 12:35:46] DEBUG[29706] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.1.2:17746
[2025-01-06 12:35:47] DEBUG[29706] chan_sip.c: = Looking for  Call ID: 22e2620804696080386252k14420rmwp (Checking From) --From tag 24g5304656822717573231m --To-tag   
[2025-01-06 12:35:47] DEBUG[29706] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[2025-01-06 12:35:47] DEBUG[29706] netsock2.c: Splitting '192.168.0.6:17746' into...
[2025-01-06 12:35:47] DEBUG[29706] netsock2.c: ...host '192.168.0.6' and port '17746'.
[2025-01-06 12:35:47] DEBUG[29706] chan_sip.c: NAT detected for 192.168.0.6 / 192.168.1.2
[2025-01-06 12:35:47] DEBUG[29706] netsock2.c: Splitting '192.168.1.1' into...
[2025-01-06 12:35:47] DEBUG[29706] netsock2.c: ...host '192.168.1.1' and port ''.
[2025-01-06 12:35:47] DEBUG[29706] chan_sip.c: Store REGISTER's src-IP:port for call routing.
[2025-01-06 12:35:47] DEBUG[29706] chan_sip.c: build_path: do not use Path headers
[2025-01-06 12:35:47] VERBOSE[29706] chan_sip.c: Registered SIP '6002' at 192.168.1.2:17746
[2025-01-06 12:35:47] DEBUG[29706] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.2:17746
[2025-01-06 12:35:47] DEBUG[29671] devicestate.c: No provider found, checking channel drivers for SIP - 6002
[2025-01-06 12:35:47] DEBUG[29671] chan_sip.c: Checking device state for peer 6002
[2025-01-06 12:35:47] DEBUG[29671] devicestate.c: Changing state for SIP/6002 - state 1 (Not in use)
[2025-01-06 12:35:47] DEBUG[29743] app_queue.c: Device 'SIP/6002' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: = Looking for  Call ID: e5f4a482037437e4f7a (Checking From) --From tag e5f4a4820373e4f7a --To-tag   
[2025-01-06 12:35:51] DEBUG[29706] acl.c: For destination '94.23.166.27', our source address is '33.33.33.33.245'.
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: Target address 94.23.166.27:60641 is not local, substituting externaddr
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: Setting AST_TRANSPORT_UDP with address 33.33.33.33.245:5060
[2025-01-06 12:35:51] DEBUG[29706] netsock2.c: Splitting '172.21.18.11:60641' into...
[2025-01-06 12:35:51] DEBUG[29706] netsock2.c: ...host '172.21.18.11' and port '60641'.
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: NAT detected for 172.21.18.11 / 94.23.166.27
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: Allocating new SIP dialog for e5f4a482037437e4f7a - REGISTER (No RTP)
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[2025-01-06 12:35:51] DEBUG[29706] netsock2.c: Splitting '172.21.18.11:60641' into...
[2025-01-06 12:35:51] DEBUG[29706] netsock2.c: ...host '172.21.18.11' and port '60641'.
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: NAT detected for 172.21.18.11 / 94.23.166.27
[2025-01-06 12:35:51] DEBUG[29706] netsock2.c: Splitting 'trackincats.com' into...
[2025-01-06 12:35:51] DEBUG[29706] netsock2.c: ...host 'trackincats.com' and port ''.
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 94.23.166.27:60641
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: = Looking for  Call ID: e5f4a482037437e4f7a (Checking From) --From tag e5f4a4820373e4f7a --To-tag   
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[2025-01-06 12:35:51] DEBUG[29706] netsock2.c: Splitting '172.21.18.11:60641' into...
[2025-01-06 12:35:51] DEBUG[29706] netsock2.c: ...host '172.21.18.11' and port '60641'.
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: NAT detected for 172.21.18.11 / 94.23.166.27
[2025-01-06 12:35:51] DEBUG[29706] netsock2.c: Splitting 'trackincats.com' into...
[2025-01-06 12:35:51] DEBUG[29706] netsock2.c: ...host 'trackincats.com' and port ''.
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: Trying to put 'SIP/2.0 403' onto UDP socket destined for 94.23.166.27:60641
[2025-01-06 12:35:51] NOTICE[29706] chan_sip.c: Registration from '<sip:5371@trackincats.com>' failed for '94.23.166.27:60641' - Wrong password
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: SIP message could not be handled, bad request: e5f4a482037437e4f7a                                                   
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: = Looking for  Call ID: e5f4a302833222e4f7a (Checking From) --From tag e5f4a3028331e4f7a --To-tag   
[2025-01-06 12:35:51] DEBUG[29706] acl.c: For destination '94.23.166.27', our source address is '33.33.33.33.245'.
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: Target address 94.23.166.27:62926 is not local, substituting externaddr
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: Setting AST_TRANSPORT_UDP with address 33.33.33.33.245:5060
[2025-01-06 12:35:51] DEBUG[29706] netsock2.c: Splitting '172.21.18.11:62926' into...
[2025-01-06 12:35:51] DEBUG[29706] netsock2.c: ...host '172.21.18.11' and port '62926'.
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: NAT detected for 172.21.18.11 / 94.23.166.27
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: Allocating new SIP dialog for e5f4a302833222e4f7a - REGISTER (No RTP)
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[2025-01-06 12:35:51] DEBUG[29706] netsock2.c: Splitting '172.21.18.11:62926' into...
[2025-01-06 12:35:51] DEBUG[29706] netsock2.c: ...host '172.21.18.11' and port '62926'.
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: NAT detected for 172.21.18.11 / 94.23.166.27
[2025-01-06 12:35:51] DEBUG[29706] netsock2.c: Splitting 'trackincats.com' into...
[2025-01-06 12:35:51] DEBUG[29706] netsock2.c: ...host 'trackincats.com' and port ''.
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 94.23.166.27:62926
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: = Looking for  Call ID: e5f4a302833222e4f7a (Checking From) --From tag e5f4a3028331e4f7a --To-tag   
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[2025-01-06 12:35:51] DEBUG[29706] netsock2.c: Splitting '172.21.18.11:62926' into...
[2025-01-06 12:35:51] DEBUG[29706] netsock2.c: ...host '172.21.18.11' and port '62926'.
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: NAT detected for 172.21.18.11 / 94.23.166.27
[2025-01-06 12:35:51] DEBUG[29706] netsock2.c: Splitting 'trackincats.com' into...
[2025-01-06 12:35:51] DEBUG[29706] netsock2.c: ...host 'trackincats.com' and port ''.
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: Trying to put 'SIP/2.0 403' onto UDP socket destined for 94.23.166.27:62926
[2025-01-06 12:35:51] NOTICE[29706] chan_sip.c: Registration from '<sip:4535@trackincats.com>' failed for '94.23.166.27:62926' - Wrong password
[2025-01-06 12:35:51] DEBUG[29706] chan_sip.c: SIP message could not be handled, bad request: e5f4a302833222e4f7a

/var/log/asterisk/messages:
[2025-01-06 06:25:02] Asterisk 18.24.2 built by root @ ubuntu.arppynt.com on a x86_64 running Linux on 2024-08-22 06:05:16 UTC

Any suggestions what’s going wrong?

2

You haven’t provided your sip.conf.

I can’t find the failed call anywhere in your logs.

Also, in the unlikely event that there is a bug in the channel driver, it won’t get investigated or fixed, because chan_sip is no longer supported.

3

Thanks for info.

I was trying different versions of extensions.conf and sip.conf

Now nothing works. Even old versions of the files aren’t working. Another all-nighter ahead.

4

I guess I need another topic. Using /etc/init.d/asterisk status it’s “active
exited” and “asterisk -rvv” doesn’t work.

I can’t understand how this happened.

More and more errors.

Read somewhere to reboot the machine and it worked!