cop,48 produces choppy and broken telemetry

[AI3I]

Description
cop,48 in app_rpt does not produce consistent audio fidelity with tone playback, either with single tones, mixed tones/tone sequences, or pre-programmed tones, i.e. dual-tone multi-frequency (DTMF) sequences. The bug seems to manifest as though it has a buffering issue; it may, for example, produce one or two DTMF digits from a named sequence and not produce the rest, or skip through sequences, or hold on and play some tone sequences endlessly.

Reproduction
Two examples that 'stress' cop,48 behavior:
node504381*CLI> rpt cmd 504381 cop 48 !830+827/450,!0/250,!659+656/450,!0/250,!739+736/450,!0/250,!493+490/450,!0/750,!493+490/450,!0/250,!739+736/450,!0/250,!830+827/45 0,!0/250,!659+656/450 ...should emulate a Computer Automated Technology CAT-1000 grandfather clock feature, but produces clipped audio and completes one or two tone sequences before playing what remains in its buffer endlessly. Results vary.

node504381*CLI> rpt cmd 504381 cop 48 6,5,4,5,6,6,6,5,5,5,6,#,# ...should whimsically play 'Mary Had a Little Lamb' in DTMF, but produces 6, 5, may skip other digits, perhaps #, and stops. Results vary.

Playing multiple sequences may even return chan_simpleusb errors, with Asterisk abruptly restarting:

[2025-01-31 21:19:29.073] WARNING[1049]: chan_simpleusb.c:2073 simpleusb_read: Possibly stuck USB read channel. [504381]
[2025-01-31 21:19:29.135] WARNING[1049]: chan_simpleusb.c:2084 simpleusb_read: USB read channel [504381] was not stuck.

Additional logging during observed behavior (from /var/log/asterisk/messages.log):

[2025-01-31 20:36:07.311] Asterisk 20.11.0+asl3-3.2.0-2.deb12 built by builder @ allstarlink.org on a aarch64 running Linux on 2024-12-20 20:30:41 UTC
[2025-01-31 20:36:07.404] NOTICE[883] loader.c: 70 modules will be loaded.
[2025-01-31 20:36:07.930] NOTICE[883] cdr.c: CDR simple logging enabled.
[2025-01-31 20:36:07.937] NOTICE[883] dnsmgr.c: Managed DNS entries will be refreshed every 300 seconds.
[2025-01-31 20:36:08.003] NOTICE[883] indications.c: Default country for indication tones: us
[2025-01-31 20:36:08.003] NOTICE[883] indications.c: Setting default indication country to 'us'
[2025-01-31 20:36:08.223] NOTICE[883] res_smdi.c: No SMDI interfaces are available to listen on, not starting SMDI listener.
[2025-01-31 20:36:08.261] WARNING[883] chan_dahdi.c: Only FXO signalled channels may belong to a call group
[2025-01-31 20:36:08.261] WARNING[883] chan_dahdi.c: Only FXO signalled channels may belong to a pickup group
[2025-01-31 20:36:08.261] NOTICE[883] chan_dahdi.c: Ignoring any changes to 'userbase' (on reload) at line 23.
[2025-01-31 20:36:08.261] NOTICE[883] chan_dahdi.c: Ignoring any changes to 'vmsecret' (on reload) at line 31.
[2025-01-31 20:36:08.261] NOTICE[883] chan_dahdi.c: Ignoring any changes to 'hassip' (on reload) at line 35.
[2025-01-31 20:36:08.261] NOTICE[883] chan_dahdi.c: Ignoring any changes to 'hasiax' (on reload) at line 39.
[2025-01-31 20:36:08.261] NOTICE[883] chan_dahdi.c: Ignoring any changes to 'hasmanager' (on reload) at line 47.
[2025-01-31 20:36:08.261] WARNING[883] chan_dahdi.c: Only FXO signalled channels may belong to a call group
[2025-01-31 20:36:08.261] WARNING[883] chan_dahdi.c: Only FXO signalled channels may belong to a pickup group
[2025-01-31 20:36:08.780] WARNING[883] loader.c: Module 'res_adsi' has been loaded but may be removed in a future release.
[2025-01-31 20:36:09.096] NOTICE[1034] app_rpt.c: Normal Repeater Init  504381    
[2025-01-31 20:36:09.105] NOTICE[1049] chan_simpleusb.c: Channel 504381: Set option TONE VERIFY, mode: OFF(0).
[2025-01-31 20:36:09.180] WARNING[1049] chan_simpleusb.c: Possibly stuck USB read channel. [504381]
[2025-01-31 20:36:09.206] WARNING[1049] chan_simpleusb.c: USB read channel [504381] was not stuck.

Expected Behavior
cop,48 should playback with fidelity, no choppiness, and be able to handle all buffered tone sequences without clipping, halting, and observing internal timings for pre-defined sequences (either DTMF) or timings declared in explicit timings. It should be noted that precision values in previous versions of app_rpt with decimal values were played back; whether rounded to the nearest cycle or generated with precision remains to be seen.

Screenshots
No screenshots are available for this report.

Software Versions

********** AllStarLink [ASL] Version Info **********

OS            : Debian GNU/Linux 12 (bookworm)
OS Kernel     : 6.6.62+rpt-rpi-v8

Asterisk      : 20.11.0+asl3-3.2.0-2.deb12
ASL [app_rpt] : 3.2.0

Installed ASL packages :

  Package                         Version
  ==============================  ==============================
  allmon3                         1.4.2-1.deb12
  asl3                            3.6.0-1.deb
  asl3-asterisk                   2:20.11.0+asl3-3.2.0-2.deb12
  asl3-asterisk-config            2:20.11.0+asl3-3.2.0-2.deb12
  asl3-asterisk-modules           2:20.11.0+asl3-3.2.0-2.deb12
  asl3-menu                       1.11-1.deb12
  asl3-pi-appliance               1.9.0-5.deb12
  asl3-update-nodelist            1.5.1-1.deb12
  cockpit                         287.1-0+deb12u3
  cockpit-bridge                  287.1-0+deb12u3
  cockpit-networkmanager          287.1-0+deb12u3
  cockpit-packagekit              287.1-0+deb12u3
  cockpit-sosreport               287.1-0+deb12u3
  cockpit-storaged                287.1-0+deb12u3
  cockpit-system                  287.1-0+deb12u3
  cockpit-wifimanager             1.1.1-1.deb12
  cockpit-ws                      287.1-0+deb12u3
  dahdi                           1:3.1.0-2
  dahdi-dkms                      1:3.4.0-4+asl
  dahdi-linux                     1:3.4.0-4+asl

Have you run a software update and rebooted?
YES

Platform

root@node504381:~# cat /proc/cpuinfo | grep Model 
Model		: Raspberry Pi 3 Model B Plus Rev 1.3

Additional context
It is not readily known whether this is fully reproducible on X86_64 platforms, but should be tested. It is also not known whether this is specific to or extends beyond chan_simpleusb.

[AI3I]

Observed as early as July 2024 from AllStarLink Community forums: Am I the only seeing ‘cop 48’ weirdness in ASL3?

[Allan-N]

The July 2024 community reference suggests a regression between ASL2 and ASL3

[jxmx]

Moving to app_rpt

[mkmer]

This seems to make "sense" - when we trigger the code generating the error message:

app_rpt/channels/chan_simpleusb.c

Lines 2072 to 2076 in bbb6a19

	if (o->readerrs == 1) {
	ast_log(LOG_WARNING, "Possibly stuck USB read channel. [%s]\n", o->name);
	}
	return &ast_null_frame;
	}

The function exits without processing the usb write logic (which is after the read)

app_rpt/channels/chan_simpleusb.c

Lines 2092 to 2099 in bbb6a19

	/* Process the transmit queue */
	for (;;) {
	num_frames = 0;
	ast_mutex_lock(&o->txqlock);
	AST_LIST_TRAVERSE(&o->txq, f1, frame_list) num_frames++;
	ast_mutex_unlock(&o->txqlock);
	i = used_blocks(o);

Skipping the write buffer for too long will cause it to overflow, essentially dropping tones (or making weird sounds).
I'm not sure it makes sense to skip processing the write part when the read fails (although we probably can't write if we can't read)

I was looking at this same code while researching the "scratchy audio" problem in the newer kernels >.29, and thought it was interesting that we coupled reading and writing. I suspect the difficulty we have keeping the write buffer full is caused by the coupling here.

No solution yet.... only some ideas :)

[KB4MDD]

I think it would be helpful to listen to the audio that is being set to the channel driver. That will point us in the correct direction. Assuming you are using simpleusb.

Use this command to capture the TX audio.
susb tune txcap

Send the cop,48 command.

When it finishes, issue this command.
susb tune nocap

The above will give you the following file.
/tmp/tx_cap_in.pcm

This is a raw wave file with no header. Please post it to this issue.

[mkmer]

I can also confirm similar results with COP 48 - debug file attached with thread blocking complaints.
Does rpt cmd launch a new thread? I don't see the 300x threads in the active list...

debug.log

Active threads from core show threads:

0x7fd55e5ff6c0 3179 netconsole           started at [ 1576] asterisk.c listener()
0x7fd53e9bd6c0 1009 hidthread            started at [ 1871] chan_simpleusb.c simpleusb_call()
0x7fd53ea3a6c0 1008 rpt                  started at [ 5704] app_rpt.c rpt_master()
0x7fd53f2b86c0 991 do_refresh           started at [  569] res_rpt_http_registrations.c load_module()
0x7fd53f3356c0 988 rpt_master           started at [ 7525] app_rpt.c load_module()
0x7fd53f3b26c0 987 network_thread       started at [12807] chan_iax2.c start_network_thread()
0x7fd53f42f6c0 986 iax2_process_thread  started at [12785] chan_iax2.c start_network_thread()
0x7fd53f4ac6c0 985 iax2_process_thread  started at [12785] chan_iax2.c start_network_thread()
0x7fd53f5296c0 984 iax2_process_thread  started at [12785] chan_iax2.c start_network_thread()
0x7fd53f5a66c0 983 iax2_process_thread  started at [12785] chan_iax2.c start_network_thread()
0x7fd53f6236c0 982 iax2_process_thread  started at [12785] chan_iax2.c start_network_thread()
0x7fd53f6a06c0 981 iax2_process_thread  started at [12785] chan_iax2.c start_network_thread()
0x7fd53f71d6c0 980 iax2_process_thread  started at [12785] chan_iax2.c start_network_thread()
0x7fd53f79a6c0 979 iax2_process_thread  started at [12785] chan_iax2.c start_network_thread()
0x7fd53f8176c0 978 iax2_process_thread  started at [12785] chan_iax2.c start_network_thread()
0x7fd53f8946c0 977 iax2_process_thread  started at [12785] chan_iax2.c start_network_thread()
0x7fd53f9116c0 976 default_tps_processing_function started at [  229] taskprocessor.c default_listener_start()
0x7fd53f98e6c0 975 sched_run            started at [  216] sched.c ast_sched_start_thread()
0x7fd53fa0b6c0 974 default_tps_processing_function started at [  229] taskprocessor.c default_listener_start()
0x7fd53fa886c0 973 do_monitor           started at [12189] chan_dahdi.c restart_monitor()
0x7fd53fb056c0 972 desc->accept_fn      started at [  881] tcptls.c ast_tcptls_server_start()
0x7fd53fb826c0 971 default_tps_processing_function started at [  229] taskprocessor.c default_listener_start()
0x7fd53fbff6c0 970 default_tps_processing_function started at [  229] taskprocessor.c default_listener_start()
0x7fd53fe886c0 969 do_refresh           started at [  500] dnsmgr.c do_reload()
0x7fd53ff056c0 968 default_tps_processing_function started at [  229] taskprocessor.c default_listener_start()
0x7fd53ff826c0 967 sched_run            started at [  216] sched.c ast_sched_start_thread()
0x7fd53ffff6c0 966 default_tps_processing_function started at [  229] taskprocessor.c default_listener_start()
0x7fd55deac6c0 964 default_tps_processing_function started at [  229] taskprocessor.c default_listener_start()
0x7fd55df296c0 963 default_tps_processing_function started at [  229] taskprocessor.c default_listener_start()
0x7fd55dfa66c0 962 default_tps_processing_function started at [  229] taskprocessor.c default_listener_start()
0x7fd55e0236c0 961 sched_run            started at [  216] sched.c ast_sched_start_thread()
0x7fd55e0a06c0 960 do_devstate_changes  started at [  621] devicestate.c ast_device_state_engine_init()
0x7fd55e11d6c0 959 bridge_manager_thread started at [ 4964] bridge.c bridge_manager_create()
0x7fd55e19a6c0 958 default_tps_processing_function started at [  229] taskprocessor.c default_listener_start()
0x7fd55e2176c0 957 default_tps_processing_function started at [  229] taskprocessor.c default_listener_start()
0x7fd55e2946c0 956 logger_thread        started at [ 2219] logger.c init_logger()
0x7fd55e3116c0 955 listener             started at [ 1642] asterisk.c ast_makesocket()
0x7fd55e5826c0 950 default_tps_processing_function started at [  229] taskprocessor.c default_listener_start()
0x7fd55e8b56c0 948 default_tps_processing_function started at [  229] taskprocessor.c default_listener_start()
0x7fd55e9326c0 947 db_sync_thread       started at [ 1264] db.c astdb_init()
0x7fd55e9af6c0 918 canary_thread        started at [ 4159] asterisk.c asterisk_daemon()
41 threads listed.