search

AllStarLink / app_rpt

Refactoring and upgrade of AllStarLink's app_rpt, etc.
8 stars 6 forks source link

dahdi/usbradio channels hang with "Exceptionally long queue length" message when trying to join nodes with more than 4 digits in the node number #390

Open knobby4444 opened 2 months ago

knobby4444 commented 2 months ago

With Asterisk 20.9.1+asl3-3.0.4-1.deb12 I am not able to join nodes with more than 4 digits in the node number. I have tried fresh installs in the last week several times on a pi3b+ and pi5. Either installing debian and then asterisk, or using the asterisk pi appliance, same result. When entering DTMF via radio or DVSwitch, or using rpt fun, the node is never connected. I can connect successfully to nodes with 4 digit node numbers. Any 5 digit or greater nodes fail. I am able to connect to these nodes using Allmon3. And I can disconnect from these nodes with DTMF successfully. I enabled the beta channel and same result. Using asl-lookup-node, the node lookups are successful and result match exactly with local DNS (from my ISP) or google DNS at 8.8.8.8. I can enter long DTMF strings like 722722722 and it will 'hear' all the chars and then output the time 3 times as expected. If I am on my first node, 49555 and I dial up my second node to connect using 349520, I see this in /var/log/asterisk/messages:

[2024-08-25 12:57:32.761] NOTICE[48219] app_rpt.c: Normal Repeater Init 49555
[2024-08-25 12:57:32.772] NOTICE[48222] chan_usbradio.c: Channel 49555: Set option TONE VERIFY, mode: OFF(0). [2024-08-25 12:57:32.792] WARNING[48222] chan_usbradio.c: Possibly stuck USB read channel. [49555] [2024-08-25 12:57:32.815] WARNING[48222] chan_usbradio.c: USB read channel [49555] was not stuck. [2024-08-25 12:57:53.275] DTMF[48222] channel.c: DTMF end '' received on IAX2/iaxclient-8379, duration 0 ms [2024-08-25 12:57:53.275] DTMF[48222] channel.c: DTMF begin emulation of '' with duration 100 queued on IAX2/iaxclient-8379 [2024-08-25 12:57:53.375] DTMF[48222] channel.c: DTMF end emulation of '*' queued on IAX2/iaxclient-8379 [2024-08-25 12:57:53.436] DTMF[48222] channel.c: DTMF end '3' received on IAX2/iaxclient-8379, duration 0 ms [2024-08-25 12:57:53.436] DTMF[48222] channel.c: DTMF begin emulation of '3' with duration 100 queued on IAX2/iaxclient-8379 [2024-08-25 12:57:53.536] DTMF[48222] channel.c: DTMF end emulation of '3' queued on IAX2/iaxclient-8379 [2024-08-25 12:57:53.596] DTMF[48222] channel.c: DTMF end '4' received on IAX2/iaxclient-8379, duration 0 ms [2024-08-25 12:57:53.596] DTMF[48222] channel.c: DTMF begin emulation of '4' with duration 100 queued on IAX2/iaxclient-8379 [2024-08-25 12:57:53.696] DTMF[48222] channel.c: DTMF end emulation of '4' queued on IAX2/iaxclient-8379 [2024-08-25 12:57:53.756] DTMF[48222] channel.c: DTMF end '9' received on IAX2/iaxclient-8379, duration 0 ms [2024-08-25 12:57:53.756] DTMF[48222] channel.c: DTMF begin emulation of '9' with duration 100 queued on IAX2/iaxclient-8379 [2024-08-25 12:57:53.856] DTMF[48222] channel.c: DTMF end emulation of '9' queued on IAX2/iaxclient-8379 [2024-08-25 12:57:53.916] DTMF[48222] channel.c: DTMF end '5' received on IAX2/iaxclient-8379, duration 0 ms [2024-08-25 12:57:53.916] DTMF[48222] channel.c: DTMF begin emulation of '5' with duration 100 queued on IAX2/iaxclient-8379 [2024-08-25 12:57:54.016] DTMF[48222] channel.c: DTMF end emulation of '5' queued on IAX2/iaxclient-8379 [2024-08-25 12:57:54.075] DTMF[48222] channel.c: DTMF end '2' received on IAX2/iaxclient-8379, duration 0 ms [2024-08-25 12:57:54.075] DTMF[48222] channel.c: DTMF begin emulation of '2' with duration 100 queued on IAX2/iaxclient-8379 [2024-08-25 12:57:54.176] DTMF[48222] channel.c: DTMF end emulation of '2' queued on IAX2/iaxclient-8379 [2024-08-25 12:57:56.116] WARNING[48214] channel.c: Exceptionally long voice queue length (97 voice / 98 total) queuing to IAX2/iaxclient-8379 [2024-08-25 12:57:57.396] WARNING[48214] channel.c: Exceptionally long voice queue length (97 voice / 98 total) queuing to IAX2/iaxclient-8379 [2024-08-25 12:57:58.675] WARNING[48210] channel.c: Exceptionally long voice queue length (97 voice / 98 total) queuing to IAX2/iaxclient-8379 [2024-08-25 12:57:59.955] WARNING[48209] channel.c: Exceptionally long voice queue length (97 voice / 98 total) queuing to IAX2/iaxclient-8379 [2024-08-25 12:58:01.235] WARNING[48208] channel.c: Exceptionally long voice queue length (97 voice / 98 total) queuing to IAX2/iaxclient-8379 [2024-08-25 12:58:02.516] WARNING[48215] channel.c: Exceptionally long voice queue length (97 voice / 98 total) queuing to IAX2/iaxclient-8379 [2024-08-25 12:58:03.796] WARNING[48213] channel.c: Exceptionally long voice queue length (97 voice / 98 total) queuing to IAX2/iaxclient-8379 [2024-08-25 12:58:05.075] WARNING[48210] channel.c: Exceptionally long voice queue length (97 voice / 98 total) queuing to IAX2/iaxclient-8379 [2024-08-25 12:58:12.577] DTMF[48222] channel.c: DTMF end '0' received on IAX2/iaxclient-8379, duration 0 ms [2024-08-25 12:58:12.577] DTMF[48222] channel.c: DTMF begin emulation of '0' with duration 100 queued on IAX2/iaxclient-8379 [2024-08-25 12:58:12.677] DTMF[48222] channel.c: DTMF end emulation of '0' queued on IAX2/iaxclient-8379

After the 4th digit of the node number, we see the long queue messages. Then 15-20 seconds later it 'hears' the last digit, the 0, but it's too late to be recognized. Same result with any node number more than 4 digits that I have tried.

KB4MDD commented 2 months ago

My first thought is the dns is not responding fast enough.

Post the output of asl lookup node.

What dns server are you using?

Please edit /etc/asterisk/logger.conf. Change the following:

console => notice,warning,error,dtmf to be console => notice,warning,error,dtmf,debug

In the cli type logger reload core set debug 7 app_rpt.so

Then attempt your connection.

Post the results.

knobby4444 commented 2 months ago

Looking up the node comes back immediately

root@allstar1:~# asl-node-lookup 49520

SRV (_iax._udp.49520.nodes.allstarlink.org) 11 10 4570 49520.remotebase.nodes.allstarlink.org.

A (49520.remotebase.nodes.allstarlink.org) 209.65.151.206

TXT (49520.remotebase.nodes.allstarlink.org) NN=49520 RT=2024-08-25 13:07:28 RB=1 IP=209.65.151.206 PIP=0 PT=4570 RH=register-west

RPT LOOKUP (49520) radio@209.65.151.206:4570/49520,209.65.151.206

root@allstar1:~# asl-node-lookup --ns 8.8.8.8 49520

SRV (_iax._udp.49520.nodes.allstarlink.org) 11 10 4570 49520.remotebase.nodes.allstarlink.org.

A (49520.remotebase.nodes.allstarlink.org) 209.65.151.206

TXT (49520.remotebase.nodes.allstarlink.org) NN=49520 RT=2024-08-25 13:07:28 RB=1 IP=209.65.151.206 PIP=0 PT=4570 RH=register-west

RPT LOOKUP (49520) radio@209.65.151.206:4570/49520,209.65.151.206 root@allstar1:~# asl-node-lookup 49555

SRV (_iax._udp.49555.nodes.allstarlink.org) 11 10 4569 49555.nodes.allstarlink.org.

A (49555.nodes.allstarlink.org) 209.65.151.206

TXT (49555.nodes.allstarlink.org) NN=49555 RT=2024-08-25 13:04:03 RB=0 IP=209.65.151.206 PIP=0 PT=4569 RH=register-west

RPT LOOKUP (49555) radio@127.0.0.1/49555,NONE

root@allstar1:~# asl-node-lookup --ns 8.8.8.8 49555

SRV (_iax._udp.49555.nodes.allstarlink.org) 11 10 4569 49555.nodes.allstarlink.org.

A (49555.nodes.allstarlink.org) 209.65.151.206

TXT (49555.nodes.allstarlink.org) NN=49555 RT=2024-08-25 13:04:03 RB=0 IP=209.65.151.206 PIP=0 PT=4569 RH=register-west

RPT LOOKUP (49555) radio@127.0.0.1/49555,NONE

knobby4444 commented 2 months ago

root@allstar1:~# asterisk -r Asterisk 20.9.1+asl3-3.0.4-1.deb12, Copyright (C) 1999 - 2022, Sangoma Technologies Corporation 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 20.9.1+asl3-3.0.4-1.deb12 currently running on allstar1 (pid = 782) allstar1CLI> logger reload core set debug 7 app_rpt.so [2024-08-25 14:54:37.303] DTMF[856]: channel.c:3894 __ast_read: DTMF end '' received on IAX2/iaxclient-6295, duration 0 ms [2024-08-25 14:54:37.303] DTMF[856]: channel.c:3921 ast_read: DTMF begin emulation of '' with duration 100 queued on IAX2/iaxclient-6295 [2024-08-25 14:54:37.403] DTMF[856]: channel.c:4042 __ast_read: DTMF end emulation of '' queued on IAX2/iaxclient-6295 [2024-08-25 14:54:37.462] DTMF[856]: channel.c:3894 ast_read: DTMF end '3' received on IAX2/iaxclient-6295, duration 0 ms [2024-08-25 14:54:37.463] DTMF[856]: channel.c:3921 ast_read: DTMF begin emulation of '3' with duration 100 queued on IAX2/iaxclient-6295 [2024-08-25 14:54:37.564] DTMF[856]: channel.c:4100 __ast_read: DTMF end emulation of '3' queued on IAX2/iaxclient-6295 [2024-08-25 14:54:37.623] DTMF[856]: channel.c:3894 ast_read: DTMF end '4' received on IAX2/iaxclient-6295, duration 0 ms [2024-08-25 14:54:37.623] DTMF[856]: channel.c:3921 ast_read: DTMF begin emulation of '4' with duration 100 queued on IAX2/iaxclient-6295 [2024-08-25 14:54:37.723] DTMF[856]: channel.c:4042 __ast_read: DTMF end emulation of '4' queued on IAX2/iaxclient-6295 [2024-08-25 14:54:37.783] DTMF[856]: channel.c:3894 ast_read: DTMF end '9' received on IAX2/iaxclient-6295, duration 0 ms [2024-08-25 14:54:37.783] DTMF[856]: channel.c:3921 ast_read: DTMF begin emulation of '9' with duration 100 queued on IAX2/iaxclient-6295 [2024-08-25 14:54:37.884] DTMF[856]: channel.c:4100 __ast_read: DTMF end emulation of '9' queued on IAX2/iaxclient-6295 [2024-08-25 14:54:37.943] DTMF[856]: channel.c:3894 ast_read: DTMF end '5' received on IAX2/iaxclient-6295, duration 0 ms [2024-08-25 14:54:37.943] DTMF[856]: channel.c:3921 ast_read: DTMF begin emulation of '5' with duration 100 queued on IAX2/iaxclient-6295 [2024-08-25 14:54:38.043] DTMF[856]: channel.c:4042 __ast_read: DTMF end emulation of '5' queued on IAX2/iaxclient-6295 [2024-08-25 14:54:38.102] DTMF[856]: channel.c:3894 ast_read: DTMF end '2' received on IAX2/iaxclient-6295, duration 0 ms [2024-08-25 14:54:38.102] DTMF[856]: channel.c:3921 ast_read: DTMF begin emulation of '2' with duration 100 queued on IAX2/iaxclient-6295 [2024-08-25 14:54:38.204] DTMF[856]: channel.c:4100 __ast_read: DTMF end emulation of '2' queued on IAX2/iaxclient-6295 [2024-08-25 14:54:40.143] WARNING[841]: channel.c:1086 ast_queue_frame: Exceptionally long voice queue length (97 voice / 98 total) queuing to IAX2/iaxclient-6295 [2024-08-25 14:54:41.423] WARNING[848]: channel.c:1086 ast_queue_frame: Exceptionally long voice queue length (97 voice / 98 total) queuing to IAX2/iaxclient-6295 [2024-08-25 14:54:42.703] WARNING[848]: channel.c:1086 ast_queue_frame: Exceptionally long voice queue length (97 voice / 98 total) queuing to IAX2/iaxclient-6295 [2024-08-25 14:54:43.983] WARNING[849]: channel.c:1086 ast_queue_frame: Exceptionally long voice queue length (97 voice / 98 total) queuing to IAX2/iaxclient-6295 [2024-08-25 14:54:45.262] WARNING[847]: channel.c:1086 ast_queue_frame: Exceptionally long voice queue length (97 voice / 98 total) queuing to IAX2/iaxclient-6295 [2024-08-25 14:54:46.543] WARNING[841]: channel.c:1086 ast_queue_frame: Exceptionally long voice queue length (97 voice / 98 total) queuing to IAX2/iaxclient-6295 [2024-08-25 14:54:49.034] WARNING[845]: channel.c:1086 ast_queue_frame: Exceptionally long voice queue length (97 voice / 98 total) queuing to IAX2/iaxclient-6295 [2024-08-25 14:54:56.600] DTMF[856]: channel.c:3894 ast_read: DTMF end '0' received on IAX2/iaxclient-6295, duration 0 ms [2024-08-25 14:54:56.600] DTMF[856]: channel.c:3921 __ast_read: DTMF begin emulation of '0' with duration 100 queued on IAX2/iaxclient-6295 [2024-08-25 14:54:56.700] DTMF[856]: channel.c:4042 ast_read: DTMF end emulation of '0' queued on IAX2/iaxclient-6295 allstar1*CLI>

knobby4444 commented 2 months ago

Trying to connect to another node number give the same result. Sometimes I see several long queue messages. It seems most often I only see one such as here:

[2024-08-25 14:55:59.957] DTMF[856]: channel.c:3894 ast_read: DTMF end '' received on IAX2/iaxclient-6295, duration 0 ms [2024-08-25 14:55:59.957] DTMF[856]: channel.c:3921 __ast_read: DTMF begin emulation of '' with duration 100 queued on IAX2/iaxclient-6295 [2024-08-25 14:56:00.057] DTMF[856]: channel.c:4042 ast_read: DTMF end emulation of '' queued on IAX2/iaxclient-6295 [2024-08-25 14:56:00.111] DTMF[856]: channel.c:3894 ast_read: DTMF end '3' received on IAX2/iaxclient-6295, duration 0 ms [2024-08-25 14:56:00.111] DTMF[856]: channel.c:3921 __ast_read: DTMF begin emulation of '3' with duration 100 queued on IAX2/iaxclient-6295 [2024-08-25 14:56:00.211] DTMF[856]: channel.c:4042 ast_read: DTMF end emulation of '3' queued on IAX2/iaxclient-6295 [2024-08-25 14:56:00.273] DTMF[856]: channel.c:3894 ast_read: DTMF end '5' received on IAX2/iaxclient-6295, duration 0 ms [2024-08-25 14:56:00.273] DTMF[856]: channel.c:3921 __ast_read: DTMF begin emulation of '5' with duration 100 queued on IAX2/iaxclient-6295 [2024-08-25 14:56:00.373] DTMF[856]: channel.c:4042 ast_read: DTMF end emulation of '5' queued on IAX2/iaxclient-6295 [2024-08-25 14:56:00.432] DTMF[856]: channel.c:3894 ast_read: DTMF end '1' received on IAX2/iaxclient-6295, duration 0 ms [2024-08-25 14:56:00.432] DTMF[856]: channel.c:3921 __ast_read: DTMF begin emulation of '1' with duration 100 queued on IAX2/iaxclient-6295 [2024-08-25 14:56:00.532] DTMF[856]: channel.c:4042 ast_read: DTMF end emulation of '1' queued on IAX2/iaxclient-6295 [2024-08-25 14:56:00.592] DTMF[856]: channel.c:3894 ast_read: DTMF end '4' received on IAX2/iaxclient-6295, duration 0 ms [2024-08-25 14:56:00.593] DTMF[856]: channel.c:3921 __ast_read: DTMF begin emulation of '4' with duration 100 queued on IAX2/iaxclient-6295 [2024-08-25 14:56:00.693] DTMF[856]: channel.c:4042 ast_read: DTMF end emulation of '4' queued on IAX2/iaxclient-6295 [2024-08-25 14:56:00.752] DTMF[856]: channel.c:3894 ast_read: DTMF end '4' received on IAX2/iaxclient-6295, duration 0 ms [2024-08-25 14:56:00.752] DTMF[856]: channel.c:3921 __ast_read: DTMF begin emulation of '4' with duration 100 queued on IAX2/iaxclient-6295 [2024-08-25 14:56:00.852] DTMF[856]: channel.c:4042 ast_read: DTMF end emulation of '4' queued on IAX2/iaxclient-6295 [2024-08-25 14:56:16.413] WARNING[843]: channel.c:1086 ast_queue_frame: Exceptionally long voice queue length (97 voice / 98 total) queuing to IAX2/iaxclient-6295 [2024-08-25 14:56:19.291] DTMF[856]: channel.c:3894 ast_read: DTMF end '4' received on IAX2/iaxclient-6295, duration 0 ms [2024-08-25 14:56:19.291] DTMF[856]: channel.c:3921 __ast_read: DTMF begin emulation of '4' with duration 100 queued on IAX2/iaxclient-6295 [2024-08-25 14:56:19.391] DTMF[856]: channel.c:4042 __ast_read: DTMF end emulation of '4' queued on IAX2/iaxclient-6295 allstar1CLI>

knobby4444 commented 2 months ago

tcpdump shows dns response from my dns in less than half second:

root@allstar1:~# tcpdump port 53 tcpdump: verbose output suppressed, use -v[v]... for full protocol decode listening on eth0, link-type EN10MB (Ethernet), snapshot length 262144 bytes 15:03:12.023159 IP 192.168.10.26.46648 > 192.168.10.1.domain: 53612+ SRV? _iax._udp.49520.nodes.allstarlink.org. (55) 15:03:12.088495 IP 192.168.10.26.41589 > 192.168.10.1.domain: 58472+ PTR? 26.10.168.192.in-addr.arpa. (44) 15:03:12.091015 IP 192.168.10.1.domain > 192.168.10.26.41589: 58472 NXDomain 0/1/0 (79) 15:03:12.091408 IP 192.168.10.26.44963 > 192.168.10.1.domain: 6815+ PTR? 1.10.168.192.in-addr.arpa. (43) 15:03:12.094083 IP 192.168.10.1.domain > 192.168.10.26.44963: 6815 NXDomain 0/1/0 (78) 15:03:12.099008 IP 192.168.10.1.domain > 192.168.10.26.46648: 53612 1/2/2 SRV 49520.remotebase.nodes.allstarlink.org.:4570 11 10 (201) 15:03:12.189114 IP 192.168.10.26.53502 > 192.168.10.1.domain: 3129+ A? 49520.remotebase.nodes.allstarlink.org. (56) 15:03:12.242117 IP 192.168.10.1.domain > 192.168.10.26.53502: 3129 1/2/2 A 209.65.151.206 (160) 15:03:12.313421 IP 192.168.10.26.37676 > 192.168.10.1.domain: 46230+ TXT? 49520.remotebase.nodes.allstarlink.org. (56) 15:03:12.366128 IP 192.168.10.1.domain > 192.168.10.26.37676: 46230 1/2/2 TXT "NN=49520" "RT=2024-08-25 13:07:28" "RB=1" "IP=209.65.151.206" "PIP=0" "PT=4570" "RH=register-west" (242) 15:03:12.423941 IP 192.168.10.26.40812 > 192.168.10.1.domain: 47818+ SRV? _iax._udp.49520.nodes.allstarlink.org. (55) 15:03:12.427026 IP 192.168.10.1.domain > 192.168.10.26.40812: 47818 1/2/3 SRV 49520.remotebase.nodes.allstarlink.org.:4570 11 10 (217) 15:03:12.427253 IP 192.168.10.26.42135 > 192.168.10.1.domain: 61140+ A? 49520.remotebase.nodes.allstarlink.org. (56) 15:03:12.430145 IP 192.168.10.1.domain > 192.168.10.26.42135: 61140 1/2/2 A 209.65.151.206 (160) 15:03:12.469484 IP 192.168.10.26.50114 > 192.168.10.1.domain: 51417+ A? register.allstarlink.org. (42) 15:03:12.469538 IP 192.168.10.26.50114 > 192.168.10.1.domain: 48835+ AAAA? register.allstarlink.org. (42) 15:03:12.472184 IP 192.168.10.1.domain > 192.168.10.26.50114: 48835 0/1/0 (106) 15:03:12.472184 IP 192.168.10.1.domain > 192.168.10.26.50114: 51417 2/6/12 A 34.105.111.212, A 162.248.92.131 (476) ^C 18 packets captured 18 packets received by filter 0 packets dropped by kernel

knobby4444 commented 2 months ago

Another point I forgot, I have setup the 49555 node on ASL1 on the same hardware and all the same networking, and it will connect successfully to the other node 49520 running ASL3.

knobby4444 commented 2 months ago

Yet another thing I have noticed. Anytime I connect to a node running on ASL3, it takes about 10-15 seconds to complete. If I've got DVSwitch registered and I click the connect button there, I hear the ring sound one time and then it hangs for the delay before connecting normally. When doing the same with ASL1 there is no delay it just connects almost immediately. I don't think this is related to the issue we are talking about, but it is something I have noticed when I join any ASL3 I've tried. Either node I use does it, Pi3 or Pi5, appliance or install on deb12. Figured I should mention it just in case it is related. I do not get any output in console with debug on when I test it.

KB4MDD commented 2 months ago

Did you Enable debug in the logger.config?

The following are two duliffwrent commands.

logger reload core set debug 7 app_rpt.so

I did not see any debug messages in the above.

knobby4444 commented 2 months ago

[2024-08-25 22:50:20.104] DTMF[856]: channel.c:3894 ast_read: DTMF end '' received on IAX2/iaxclient-7415, duration 0 ms [2024-08-25 22:50:20.104] DTMF[856]: channel.c:3921 __ast_read: DTMF begin emulation of '' with duration 100 queued on IAX2/iaxclient-7415 [2024-08-25 22:50:20.204] DTMF[856]: channel.c:4042 ast_read: DTMF end emulation of '' queued on IAX2/iaxclient-7415 [2024-08-25 22:50:20.264] DTMF[856]: channel.c:3894 ast_read: DTMF end '3' received on IAX2/iaxclient-7415, duration 0 ms [2024-08-25 22:50:20.264] DTMF[856]: channel.c:3921 __ast_read: DTMF begin emulation of '3' with duration 100 queued on IAX2/iaxclient-7415 [2024-08-25 22:50:20.365] DTMF[856]: channel.c:4100 ast_read: DTMF end emulation of '3' queued on IAX2/iaxclient-7415 [2024-08-25 22:50:20.365] DEBUG[856]: app_rpt.c:1435 collect_function_digits: digits=3 source=3 [2024-08-25 22:50:20.365] DEBUG[856]: app_rpt.c:1487 collect_function_digits: @@@@ action: ilink, param = 3 [2024-08-25 22:50:20.365] DEBUG[856]: app_rpt.c:1493 collect_function_digits: @@@@ table index i = 3 [2024-08-25 22:50:20.365] DEBUG[856]: app_rpt/rpt_functions.c:69 function_ilink: @@@@ ilink param = 3, digitbuf = [2024-08-25 22:50:20.365] DEBUG[856]: app_rpt.c:1505 collect_function_digits: rv=0 [2024-08-25 22:50:20.410] DEBUG[856]: app_rpt.c:3171 periodic_process_links: @@@@ node 49555 sent node string L to node KG5DRT-1-P [2024-08-25 22:50:20.424] DTMF[856]: channel.c:3894 ast_read: DTMF end '4' received on IAX2/iaxclient-7415, duration 0 ms [2024-08-25 22:50:20.424] DTMF[856]: channel.c:3921 __ast_read: DTMF begin emulation of '4' with duration 100 queued on IAX2/iaxclient-7415 [2024-08-25 22:50:20.524] DTMF[856]: channel.c:4042 ast_read: DTMF end emulation of '4' queued on IAX2/iaxclient-7415 [2024-08-25 22:50:20.524] DEBUG[856]: app_rpt.c:1435 collect_function_digits: digits=34 source=3 [2024-08-25 22:50:20.524] DEBUG[856]: app_rpt.c:1487 collect_function_digits: @@@@ action: ilink, param = 3 [2024-08-25 22:50:20.524] DEBUG[856]: app_rpt.c:1493 collect_function_digits: @@@@ table index i = 3 [2024-08-25 22:50:20.524] DEBUG[856]: app_rpt/rpt_functions.c:69 function_ilink: @@@@ ilink param = 3, digitbuf = 4 [2024-08-25 22:50:20.524] DEBUG[856]: app_rpt/rpt_config.c:312 tlb_query_node_exists: chan_tlb not loaded. [2024-08-25 22:50:20.524] DEBUG[856]: app_rpt.c:1505 collect_function_digits: rv=0 [2024-08-25 22:50:20.583] DTMF[856]: channel.c:3894 ast_read: DTMF end '9' received on IAX2/iaxclient-7415, duration 0 ms [2024-08-25 22:50:20.583] DTMF[856]: channel.c:3921 __ast_read: DTMF begin emulation of '9' with duration 100 queued on IAX2/iaxclient-7415 [2024-08-25 22:50:20.684] DTMF[856]: channel.c:4100 ast_read: DTMF end emulation of '9' queued on IAX2/iaxclient-7415 [2024-08-25 22:50:20.684] DEBUG[856]: app_rpt.c:1435 collect_function_digits: digits=349 source=3 [2024-08-25 22:50:20.685] DEBUG[856]: app_rpt.c:1487 collect_function_digits: @@@@ action: ilink, param = 3 [2024-08-25 22:50:20.685] DEBUG[856]: app_rpt.c:1493 collect_function_digits: @@@@ table index i = 3 [2024-08-25 22:50:20.685] DEBUG[856]: app_rpt/rpt_functions.c:69 function_ilink: @@@@ ilink param = 3, digitbuf = 49 [2024-08-25 22:50:20.685] DEBUG[856]: app_rpt/rpt_config.c:312 tlb_query_node_exists: chan_tlb not loaded. [2024-08-25 22:50:20.685] DEBUG[856]: app_rpt.c:1505 collect_function_digits: rv=0 [2024-08-25 22:50:20.744] DTMF[856]: channel.c:3894 ast_read: DTMF end '5' received on IAX2/iaxclient-7415, duration 0 ms [2024-08-25 22:50:20.744] DTMF[856]: channel.c:3921 __ast_read: DTMF begin emulation of '5' with duration 100 queued on IAX2/iaxclient-7415 [2024-08-25 22:50:20.844] DTMF[856]: channel.c:4042 ast_read: DTMF end emulation of '5' queued on IAX2/iaxclient-7415 [2024-08-25 22:50:20.844] DEBUG[856]: app_rpt.c:1435 collect_function_digits: digits=3495 source=3 [2024-08-25 22:50:20.844] DEBUG[856]: app_rpt.c:1487 collect_function_digits: @@@@ action: ilink, param = 3 [2024-08-25 22:50:20.844] DEBUG[856]: app_rpt.c:1493 collect_function_digits: @@@@ table index i = 3 [2024-08-25 22:50:20.844] DEBUG[856]: app_rpt/rpt_functions.c:69 function_ilink: @@@@ ilink param = 3, digitbuf = 495 [2024-08-25 22:50:20.844] DEBUG[856]: app_rpt/rpt_config.c:312 tlb_query_node_exists: chan_tlb not loaded. [2024-08-25 22:50:20.844] DEBUG[856]: app_rpt.c:1505 collect_function_digits: rv=0 [2024-08-25 22:50:20.904] DTMF[856]: channel.c:3894 ast_read: DTMF end '2' received on IAX2/iaxclient-7415, duration 0 ms [2024-08-25 22:50:20.904] DTMF[856]: channel.c:3921 __ast_read: DTMF begin emulation of '2' with duration 100 queued on IAX2/iaxclient-7415 [2024-08-25 22:50:21.004] DTMF[856]: channel.c:4100 ast_read: DTMF end emulation of '2' queued on IAX2/iaxclient-7415 [2024-08-25 22:50:21.005] DEBUG[856]: app_rpt.c:1435 collect_function_digits: digits=34952 source=3 [2024-08-25 22:50:21.005] DEBUG[856]: app_rpt.c:1487 collect_function_digits: @@@@ action: ilink, param = 3 [2024-08-25 22:50:21.005] DEBUG[856]: app_rpt.c:1493 collect_function_digits: @@@@ table index i = 3 [2024-08-25 22:50:21.005] DEBUG[856]: app_rpt/rpt_functions.c:69 function_ilink: @@@@ ilink param = 3, digitbuf = 4952 [2024-08-25 22:50:21.005] DEBUG[856]: app_rpt/rpt_config.c:312 tlb_query_node_exists: chan_tlb not loaded. [2024-08-25 22:50:21.005] DEBUG[856]: app_rpt/rpt_config.c:396 node_lookup_bydns: Resolving DNS SRV records for: _iax._udp.4952.nodes.allstarlink.org [2024-08-25 22:50:23.026] WARNING[845]: channel.c:1086 ast_queue_frame: Exceptionally long voice queue length (97 voice / 98 total) queuing to IAX2/iaxclient-7415 [2024-08-25 22:50:33.265] WARNING[846]: channel.c:1086 ast_queue_frame: Exceptionally long voice queue length (97 voice / 98 total) queuing to IAX2/iaxclient-7415 [2024-08-25 22:50:39.410] DEBUG[856]: app_rpt/rpt_config.c:411 node_lookup_bydns: No SRV records returned for _iax._udp.4952.nodes.allstarlink.org [2024-08-25 22:50:39.411] DEBUG[856]: app_rpt.c:1505 collect_function_digits: rv=0 [2024-08-25 22:50:39.411] DEBUG[856]: app_rpt.c:3171 periodic_process_links: @@@@ node 49555 sent node string L to node KG5DRT-1-P [2024-08-25 22:50:39.411] DEBUG[856]: app_rpt.c:1038 statpost: Making statpost to http://stats.allstarlink.org/uhandler?node=49555&time=1724622639&seqno=1787&keyed=0&keytime=30203 [2024-08-25 22:50:39.416] DTMF[856]: channel.c:3894 ast_read: DTMF end '0' received on IAX2/iaxclient-7415, duration 0 ms [2024-08-25 22:50:39.416] DTMF[856]: channel.c:3921 __ast_read: DTMF begin emulation of '0' with duration 100 queued on IAX2/iaxclient-7415 [2024-08-25 22:50:39.516] DTMF[856]: channel.c:4042 ast_read: DTMF end emulation of '0' queued on IAX2/iaxclient-7415 [2024-08-25 22:50:40.626] DEBUG[856]: app_rpt.c:1038 statpost: Making statpost to http://stats.allstarlink.org/uhandler?node=49555&time=1724622640&seqno=1788&nodes=TKG5DRT-1-P&apprptvers=3.0.4&apprptuptime=30204&totalkerchunks=0&totalkeyups=0&totaltxtime=0&timeouts=0&totalexecdcommands=2 allstar1CLI>

Allan-N commented 2 months ago

[2024-08-25 22:50:21.005] DEBUG[856]: app_rpt/rpt_config.c:396 node_lookup_bydns: Resolving DNS SRV records for: _iax._udp.4952.nodes.allstarlink.org [2024-08-25 22:50:39.410] DEBUG[856]: app_rpt/rpt_config.c:411 node_lookup_bydns: No SRV records returned for _iax._udp.4952.nodes.allstarlink.org

There was an 18 second delay between the SRV query and the reply :-(

knobby4444 commented 2 months ago

Strange that there is only a delay when trying to connect to the node. asl-node-looup is fast. It is typical to that long queue warnings when it's trying to lookup a node? I guess I will stick with ASL1 for the setup I'm working on currently.

knobby4444 commented 2 months ago

Dig comes back in about 100msec

root@allstar1:~# dig -t SRV _iax._udp.4952.nodes.allstarlink.org

; <<>> DiG 9.18.28-1~deb12u2-Debian <<>> -t SRV _iax._udp.4952.nodes.allstarlink.org ;; global options: +cmd ;; Got answer: ;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 63626 ;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION: ; EDNS: version: 0, flags:; udp: 4096 ;; QUESTION SECTION: ;_iax._udp.4952.nodes.allstarlink.org. IN SRV

;; Query time: 103 msec ;; SERVER: 192.168.10.1#53(192.168.10.1) (UDP) ;; WHEN: Sun Aug 25 23:17:44 BST 2024 ;; MSG SIZE rcvd: 65

knobby4444 commented 2 months ago

200msec for google dns

root@allstar1:~# dig @8.8.8.8 -t SRV _iax._udp.4952.nodes.allstarlink.org

; <<>> DiG 9.18.28-1~deb12u2-Debian <<>> @8.8.8.8 -t SRV _iax._udp.4952.nodes.allstarlink.org ; (1 server found) ;; global options: +cmd ;; Got answer: ;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 31293 ;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION: ; EDNS: version: 0, flags:; udp: 512 ; EDE: 23 (Network Error): ([34.105.111.212] rcode=SERVFAIL for _iax._udp.4952.nodes.allstarlink.org/srv) ; EDE: 22 (No Reachable Authority): (At delegation nodes.allstarlink.org for _iax._udp.4952.nodes.allstarlink.org/srv) ;; QUESTION SECTION: ;_iax._udp.4952.nodes.allstarlink.org. IN SRV

;; Query time: 199 msec ;; SERVER: 8.8.8.8#53(8.8.8.8) (UDP) ;; WHEN: Sun Aug 25 23:19:07 BST 2024 ;; MSG SIZE rcvd: 233

Allan-N commented 2 months ago

The latter queries may have been cached. Do you get the same quick replies with "different" node #'s ?

knobby4444 commented 2 months ago

Just a little bit longer for different nodes. Always well under half second

root@allstar1:~# dig @8.8.8.8 -t SRV _iax._udp.4953.nodes.allstarlink.org

; <<>> DiG 9.18.28-1~deb12u2-Debian <<>> @8.8.8.8 -t SRV _iax._udp.4953.nodes.allstarlink.org ; (1 server found) ;; global options: +cmd ;; Got answer: ;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 20180 ;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION: ; EDNS: version: 0, flags:; udp: 512 ; EDE: 23 (Network Error): ([34.105.111.212] rcode=SERVFAIL for _iax._udp.4953.nodes.allstarlink.org/srv) ; EDE: 22 (No Reachable Authority): (At delegation nodes.allstarlink.org for _iax._udp.4953.nodes.allstarlink.org/srv) ;; QUESTION SECTION: ;_iax._udp.4953.nodes.allstarlink.org. IN SRV

;; Query time: 259 msec ;; SERVER: 8.8.8.8#53(8.8.8.8) (UDP) ;; WHEN: Sun Aug 25 23:26:35 BST 2024 ;; MSG SIZE rcvd: 233

root@allstar1:~# dig @8.8.8.8 -t SRV _iax._udp.4555.nodes.allstarlink.org

; <<>> DiG 9.18.28-1~deb12u2-Debian <<>> @8.8.8.8 -t SRV _iax._udp.4555.nodes.allstarlink.org ; (1 server found) ;; global options: +cmd ;; Got answer: ;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 22063 ;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION: ; EDNS: version: 0, flags:; udp: 512 ; EDE: 23 (Network Error): ([34.105.111.212] rcode=SERVFAIL for _iax._udp.4555.nodes.allstarlink.org/srv) ; EDE: 22 (No Reachable Authority): (At delegation nodes.allstarlink.org for _iax._udp.4555.nodes.allstarlink.org/srv) ;; QUESTION SECTION: ;_iax._udp.4555.nodes.allstarlink.org. IN SRV

;; Query time: 299 msec ;; SERVER: 8.8.8.8#53(8.8.8.8) (UDP) ;; WHEN: Sun Aug 25 23:26:48 BST 2024 ;; MSG SIZE rcvd: 233

knobby4444 commented 2 months ago

Lookups work fine in ASL1, but I don't currently have an instance to test with.

knobby4444 commented 2 months ago

root@allstar1:~# dig -t SRV _iax._udp.4556.nodes.allstarlink.org

; <<>> DiG 9.18.28-1~deb12u2-Debian <<>> -t SRV _iax._udp.4556.nodes.allstarlink.org ;; global options: +cmd ;; Got answer: ;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 22828 ;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION: ; EDNS: version: 0, flags:; udp: 4096 ;; QUESTION SECTION: ;_iax._udp.4556.nodes.allstarlink.org. IN SRV

;; Query time: 307 msec ;; SERVER: 192.168.10.1#53(192.168.10.1) (UDP) ;; WHEN: Sun Aug 25 23:29:29 BST 2024 ;; MSG SIZE rcvd: 65

Allan-N commented 2 months ago

I haven't looked back in the history for "this" issue but have you tried changing the "node_lookup_method" in your "rpt.conf" file to "file" (instead of "both" or "dns") ?

Allan-N commented 2 months ago

Also, know that we understand that there's at least one issue with our DNS queries not behaving as expected. We're looking at both the client (asterisk+app_rpt) usage and the server (DNS infrastructure).

knobby4444 commented 2 months ago

I have changed node lookup method. The file referenced by the file method does not exist on my system, so it fails with that method.

knobby4444 commented 2 months ago

I'm starting to wonder if the connection from DVSwitch delay is related. Is there a lookup on a node when a DVSwitch IAX connection comes in? The only reason I ask is the delay is similar in length to the issue we are discussing. It did "allstar1*CLI> core set debug 7 iax" and connected with DVSwitch and didn't see anything interesting in the console. In fact, nothing happens in the console until after the connection message ends in DVSwitch:

allstar1CLI> [2024-08-25 23:56:07.831] DEBUG[856]: app_rpt.c:1038 statpost: Making statpost to http://stats.allstarlink.org/uhandler?node=49555&time=1724626567&seqno=2026&nodes=&apprptvers=3.0.4&apprptuptime=34131&totalkerchunks=0&totalkeyups=0&totaltxtime=0&timeouts=0&totalexecdcommands=2 [2024-08-25 23:56:21.834] DEBUG[856]: app_rpt.c:1038 statpost: Making statpost to http://stats.allstarlink.org/uhandler?node=49555&time=1724626581&seqno=2027&keyed=0&keytime=34145 [2024-08-25 23:56:23.980] DEBUG[6010][C-00000016]: app_rpt.c:6691 rpt_exec: newkey: 0 [2024-08-25 23:56:23.980] DEBUG[6010][C-00000016]: app_rpt/rpt_bridging.c:308 __rpt_request_pseudo: Requested channel DAHDI/pseudo-808509946 [2024-08-25 23:56:23.980] DEBUG[6010][C-00000016]: app_rpt/rpt_call.c:32 rpt_disable_cdr: No CDR present on DAHDI/pseudo-808509946 [2024-08-25 23:56:23.981] DEBUG[6010][C-00000016]: app_rpt/rpt_bridging.c:374 dahdi_conf_add: Channel DAHDI/pseudo-808509946 joining conference 1022 [2024-08-25 23:56:23.984] DEBUG[6010][C-00000016]: app_rpt/rpt_telemetry.c:2613 rpt_telemetry: Tracepoint rpt_telemetry() entered mode=9 [2024-08-25 23:56:23.984] DEBUG[6010][C-00000016]: app_rpt/rpt_telemetry.c:2613 rpt_telemetry: Tracepoint rpt_telemetry() entered mode=46 [2024-08-25 23:56:23.984] DEBUG[6010][C-00000016]: app_rpt.c:6766 rpt_exec: Stopped PBX on IAX2/iaxclient-1751 [2024-08-25 23:56:24.203] DEBUG[856]: app_rpt.c:3171 periodic_process_links: @@@@ node 49555 sent node string L to node KG5DRT-1-P [2024-08-25 23:56:24.203] DEBUG[856]: app_rpt.c:1038 statpost: Making statpost to http://stats.allstarlink.org/uhandler?node=49555&time=1724626584&seqno=2028&nodes=TKG5DRT-1-P&apprptvers=3.0.4&apprptuptime=34148&totalkerchunks=0&totalkeyups=0&totaltxtime=0&timeouts=0&totalexecdcommands=2 allstar1CLI>

Edit: no there is no DNS node lookup when connecting root@allstar1:~# tcpdump port 53 tcpdump: verbose output suppressed, use -v[v]... for full protocol decode listening on eth0, link-type EN10MB (Ethernet), snapshot length 262144 bytes 00:05:47.472840 IP 192.168.10.26.50081 > 192.168.10.1.domain: 45378+ A? stats.allstarlink.org. (39) 00:05:47.475842 IP 192.168.10.1.domain > 192.168.10.26.50081: 45378 2/2/12 CNAME stats-west.allstarlink.org., A 34.105.111.212 (401) 00:05:47.525186 IP 192.168.10.26.48712 > 192.168.10.1.domain: 8728+ PTR? 26.10.168.192.in-addr.arpa. (44) 00:05:47.527871 IP 192.168.10.1.domain > 192.168.10.26.48712: 8728 NXDomain 0/1/0 (79) 00:05:47.528300 IP 192.168.10.26.42879 > 192.168.10.1.domain: 56634+ PTR? 1.10.168.192.in-addr.arpa. (43) 00:05:47.531124 IP 192.168.10.1.domain > 192.168.10.26.42879: 56634 NXDomain 0/1/0 (78) 00:05:56.349994 IP 192.168.10.26.47642 > 192.168.10.1.domain: 31664+ A? stats.allstarlink.org. (39) 00:05:56.353000 IP 192.168.10.1.domain > 192.168.10.26.47642: 31664 2/2/12 CNAME stats-west.allstarlink.org., A 34.105.111.212 (401)

Allan-N commented 2 months ago

I have changed node lookup method. The file referenced by the file method does not exist on my system, so it fails with that method.

This must not be an ASL3 Pi Appliance where the ASL3 Nodelist Updater service. This is mentioned in the ASL3 Manual's Debian 12 Install page. The following command should get "node_lookup_method=file" working.

sudo apt install asl3-update-nodelist
knobby4444 commented 2 months ago

File method works great after above command.

Allan-N commented 2 months ago

File method works great after above command.

Great! At least you now have a workaround until we figure out and resolve the DNS lookup issues.

knobby4444 commented 2 months ago

Yes excellent. Let me know if I can help with more testing going forward. I tried core set debug 0 rpt_app.so but still seeing debug messages in console after reload. Is that not the right way to turn debug off?

Allan-N commented 2 months ago

Is that not the right way to turn debug off?

You likely need to update (revert) the change you made to the /etc/asterisk/logger.conf file (and re-exec the Asterisk CLI logger reload command)

knobby4444 commented 2 months ago

It seems to have finally decided to stop with debug messages on its own. I reverted the file as well just to be sure. Thanks.

InterLinked1 commented 2 months ago

Yes excellent. Let me know if I can help with more testing going forward. I tried core set debug 0 rpt_app.so but still seeing debug messages in console after reload. Is that not the right way to turn debug off?

This should work - I leave debug enabled for console in my logger.conf on all my systems, and only selectively enable/disable it from the CLI when needed. The command you did would have worked for app_rpt but not other modules, core set debug 0 would disable all debug logging (whether to the console or elsewhere) in general.

jxmx commented 2 months ago

This is most likely the same issue as #392. Please see DTMF Linking + DNS Lookup Timeouts - Known Issue.