idrecording playback sporadic and tailmessage playback very rare

[knobby4444]

Describe the bug
When using idrecording in ASL3 the playback is sporadic. Sometimes the idrecording will play after someone keys the radio when the repeater had been idle for 10 minutes or more. Sometimes the idrecording will not play at all for an entire day. It will sometimes I have not been able to identify and pattern yet. But.. sometimes after I issue a command like "rpt playback 49520 hello" the hello message will play followed by the idrecording. After that the idrecording may continue to play as expected for some time, and then stop again. It's as though the idrecording playback got stuck and once I played the other file, it started again. Yesterday idrecording was not playing at all in the early morning, then someone linked their node and keyed down, and the idrecording played and then continued to work when someone would keydown from the linked node, or if I key down on dvswitch connected to my node via iaxuser. But if someone keyed the radio, idrecording would never play. By this morning idrecording was once again not playing after a keydown from anywhere. Then the person linked their node again and it played the idrecording. Tailmessage seems much different, it almost never plays. 3 times I have done an rpt playback command and heard the tailmessage right after. This morning I heard someone keydown over the linked node and heard the tailmessage play. That's the only time I've heard tailmessage play as I would expect it. Perhaps this issue should concentrate on the idrecording and leave tailmessage as another issue.

To Reproduce
Default install of ASL3, on debian or the appliance. Setup the node like this:
49520
statpost_url = http://stats.allstarlink.org/uhandler
duplex = 1
rxchannel = SimpleUSB/49520
;;;;;;;;;;;;;;;;;;; Your node settings here ;;;;;;;;;;;;;;;;;;;
;startup_macro = *8132000
hangtime = 10 ; squelch tail hang time (in ms) (optional, default 5 seconds, 5000 ms)
althangtime = 40 ; longer squelch tail
totime = 180000 ; transmit time-out time (in ms) (optional, default 3 minutes 180000 ms)

;idrecording = /etc/asterisk/rpt/k5fdrepeater-hector ; id recording or morse string
idrecording = /usr/share/asterisk/sounds/en/hello ; test sound
;idtalkover = ; Talkover ID (optional) default is none
idtime = 120000 ; id interval time (in ms) (optional) Default 5 minutes (300000 ms)
politeid = 30000 ; time in milliseconds before ID timer expires to try and ID in the tail. (optional, default 30000)

;tailmessagelist=/etc/asterisk/rpt/plinuse
tailmessagelist = /usr/share/asterisk/sounds/en/goodbye

Expected behavior
If the repeater system is idle and someone keys down via radio or direct iaxclient, after then unkey, the idrecording should play after the idtime expires. That's what I would expect compared to other systems I have worked with, but I'm not certain that is how it is designed in ASL3. When it is playing the idrecording, it seems to work this way except the idrecording plays after idtime minus politeid which is fine.

Screenshots
No screens

Software versions (listed in asl-menu, option 4)

        │ OS            : Debian GNU/Linux 12 (bookworm)                                                     
             │ OS Kernel     : 6.6.47+rpt-rpi-v8                                                                  
             │                                                                                                    
             │ Asterisk      : 20.9.1+asl3-3.0.4-1.deb12                                                          
             │ ASL [app_rpt] : 3.0.4                                                                              
             │                                                                                                    
             │ Installed ASL packages :                                                                           
             │                                                                                                    
             │   Package               Version                                                                    
             │   ====================  ==============================                                             
             │   allmon3               1.3.4-1.deb12                                                              
             │   asl3                  3.4.0-1.deb                                                                
             │   asl3-asterisk         2:20.9.1+asl3-3.0.4-1.deb12                                                
             │   asl3-asterisk-config  2:20.9.1+asl3-3.0.4-1.deb12                                                
             │   asl3-asterisk-module  2:20.9.1+asl3-3.0.4-1.deb12                                                
             │   asl3-menu             1.8-1.deb12                                                                
             │                                                      

Have you run a software update and rebooted?
I have installed a few times using debian, and this last test I'm using the raspi appliance. Using pi3b+ and pi4b. This last time I was careful to only make changes in rpt.conf in one spot, as shown above. Rebooted, updated, restarted more than a few times.

What is the platform - e.g. Raspberry Pi 4, Raspberry Pi 5, Virtual Machine, Desktop, etc.
Above

Additional context
I first noticed this problem using my own sound files to play. But, I have tested using canned sound files from asterisk and it's the same result. Someone mentioned ider_state in the stats and it flips between 1 and 2 and doesn't seem to have an effect on the playback. I just switched back to canned sound files for testing and playback seemed to work fine. Then switched back to custom files and things seem to be working well:

13:13:00 asterisk restart
13:13:37 idrecording plays, about the politeid time after restart
13:14:20 key dbswitch
13:15:55 idrecording plays about 1.5 minutes after keydown. That's the idtime of 2 minutes, minus the politeid time of 30 seconds. I think this is how it should work. I restarted asterisk again and keyed dvswitch and it played the idrecording as soon as I unkeyed. I haven't been able to see a pattern as to when it will id as soon as someone keys, or after the idtime. But I think after the idtime would be correct. In its current state it seems to id over someone keying dvswitch, then playing the idrecording again after the idtime. But if someone keys the radio, it does not id over them, it only ids after the idtime. In a few hours or tomorrow morning, I expect that it will not play the idrecording at all. I will report back with more data...

[KB4MDD]

Please post your rpt.conf and simpleusb.conf files.

[Allan-N]

Note: in order to upload your .conf files to GitHub you may need to add a .txt extension.

[knobby4444]

rpt.conf.txt
simpleusb.conf.txt

[knobby4444]

I have just tested again and it seems keying the radio is no longer causing idrecording to play, and keying dvswwitch causes idrecording to play over the person keying, and then again after a delay.

15:50:15 key radio
15:54:32 key dvswitch
15:54:32 idrecording plays
15:56:47 idrecording plays
16:04:14 key radio
16:10:45 another HAM keys radio, we go back and forth a few times
16:18:00 test ends,

Never any idrec resulting from radio keying at this time, but dvswitch is doing it every time.

[knobby4444]

17:30 yesterday I linked the system with a large system for the monthly emergency net. After linking the idrecording began playing again after radio keying. And it began iding over someone keying dvswitch, and then again in about 2 minteus. It was working every time and I had set the idtimer to 2 minutes, so it was iding often. I didn't want to change the config so I renamed the idrecording file. I would see errors in the log when it would try to id because the file was missing. I left it like this for the net. As I was driving to the EOC, I heard the tailmessage one time and have not heard it again since. After the net I unlinked the node. Currently the system will id 2 minutes after a dvswitch keydown, but nothing after a radio keydown.

Previously it would not id after a dvswitch keydown or radio keydown. I believe that was due to the wrong duplex setting. Right now it appears that dvswitch (iax-client with passwd) works as expected when no other nodes are linked. Keying dvswitch results in idrecording playing after idtimer-politeid, or close to that time, expires. Radio keydown results in nothing when no other nodes are linked. When another node is linked, dvswitch keydown causes immediate id and then another id after the delay. Radio keydown causes id after delay with another node connected. I've ordered another RA-40 for my own node setup to test with. Once someone wakes up today I will ask to test with their node and report back repeatability of all this.

[knobby4444]

Someone just linked to the node I'm working on and we had a QSO with me on the radio and him coming in over linked allstar node.
09:21:59 key radio, call ham on linked node
09:22:15 linked ham responds
09:22:19 idrecording plays as soon as ham unkeys
09:22:25 QSO continues
09:24:18 idrecording plays
09:26:15 QSO ends, 73s
09:26:16 idrecording plays
09:28:32 idrecording plays
09:43:00 nothing else heard

idtimer is set for 120000ms so the above behavior seems correct. I'm hearing the idrecording on the air and in dvswitch and the linked node does not hear my idrecording on his end. I will wait a bit and unlink that node and test again.

[knobby4444]

I was hoping to have identified a pattern but it appear not. Just about to unlink everything and test. I tested before unlinking and the system has fallen back to no id from radio keying, and immediate id followed by another id after idtimer from dvswitch keying. The linked node seemed to be related but here I have been able to document it 'changing modes' while still linked to another node.

[knobby4444]

We had a net last night, so in the afternoon I did some final testing, switch idtimer to 1 minute and someone came on the system and we had a QSO. idrecording played every minute as expected. That's the first time I have noticed it start working again after asterisk restart. Switched the idtimer to 10 minutes for the net. idrecording continues to play as expected. The net went okay and this morning, no idrecording after radio key or dvswitch key.

[knobby4444]

This problem continues. Sometimes the idrecording plays pretty much as expected, then the system flips over to where it never ids at the result of a radio key, but in the past week or so it appears to always id after a key from a linked node or a direct client. Our 2m repeaters do a cwid so the system is still legal, but anyone relying on ASL to do iding and having this problem would not be legal. I have reinstalled several times on different hardware and always have this problem, so I would be surprised if it is not affecting others. The other day I heard the tail message right after I did a *712 and it announced the time. That's is about the 4th time I have ever heard the tailmessage play. It's always right after allstar says something.

[knobby4444]

I have setup a second node so I can better test this. It has run for several days and so far always plays the idrecording as expected. To keep things simple I have not yet tried enabling tailmessage on this new node.

I did a diff on the 2 rpt.conf files and going through it now. Must be one of my config changes that's messing with idrecording playback. The node with the issue has nounkeyct and holdofftelem both =1 while the working node has =0 for both. I will report back after more testing...

[knobby4444]

It is the nounkeyct = 1 setting that is doing strange things to the idrecording playback as previously described. tailmessage continues to almost never play. Yesterday I keyed the system early in the morning, the idrecording played, and then the tailmessage played. It did the same thing 2 mornings previous to that. I have not heard it play otherwise. With nounkeyct = 0, the idrecording seems to play every time I would expect it to. Since the testing began around 3 days ago, it has always played when I expect it. I think the config change has fixed the idrecording playback.

Next I will setup a tailmessage on my 2nd node and see how it does there.

[knobby4444]

Interesting thing, there's a courtesy tone that plays when someone unkeys that I can't get rid of except by using nounkeyct = 1. If I leave it = 0 and then comment out all the ct entries, they all go silent, except on. There's a tone that plays when someone unkeys, while a node or phone is linked, but doesn't play if there is nothing linked.

[Allan-N]

Moved to app_rpt