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
Comments
|
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
In the cli type Then attempt your connection. Post the results. |
|
Looking up the node comes back immediately root@allstar1:~# asl-node-lookup 49520 SRV (_iax._udp.49520.nodes.allstarlink.org) A (49520.remotebase.nodes.allstarlink.org) TXT (49520.remotebase.nodes.allstarlink.org) RPT LOOKUP (49520) root@allstar1:~# asl-node-lookup --ns 8.8.8.8 49520 SRV (_iax._udp.49520.nodes.allstarlink.org) A (49520.remotebase.nodes.allstarlink.org) TXT (49520.remotebase.nodes.allstarlink.org) RPT LOOKUP (49520) SRV (_iax._udp.49555.nodes.allstarlink.org) A (49555.nodes.allstarlink.org) TXT (49555.nodes.allstarlink.org) RPT LOOKUP (49555) root@allstar1:~# asl-node-lookup --ns 8.8.8.8 49555 SRV (_iax._udp.49555.nodes.allstarlink.org) A (49555.nodes.allstarlink.org) TXT (49555.nodes.allstarlink.org) RPT LOOKUP (49555) |
root@allstar1:~# asterisk -r
|
|
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 |
|
tcpdump shows dns response from my dns in less than half second: root@allstar1:~# tcpdump port 53 |
|
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. |
|
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. |
|
Did you Enable debug in the logger.config? The following are two duliffwrent commands. logger reload I did not see any debug messages in the above. |
|
[2024-08-25 22:50:20.104] DTMF[856]: channel.c:3894 __ast_read: DTMF end '' received on IAX2/iaxclient-7415, duration 0 ms |
There was an 18 second delay between the SRV query and the reply :-( |
|
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. |
|
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 ;; OPT PSEUDOSECTION: ;; Query time: 103 msec |
|
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 ;; OPT PSEUDOSECTION: ;; Query time: 199 msec |
|
The latter queries may have been cached. Do you get the same quick replies with "different" node #'s ? |
|
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 ;; OPT PSEUDOSECTION: ;; Query time: 259 msec 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 ;; OPT PSEUDOSECTION: ;; Query time: 299 msec |
|
Lookups work fine in ASL1, but I don't currently have an instance to test with. |
|
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 ;; OPT PSEUDOSECTION: ;; Query time: 307 msec |
|
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") ? |
|
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). |
|
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. |
|
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> Edit: no there is no DNS node lookup when connecting |
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. |
|
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. |
|
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? |
You likely need to update (revert) the change you made to the |
|
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. |
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, |
|
This is most likely the same issue as #392. |
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 722722*722 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.
The text was updated successfully, but these errors were encountered: