[asterisk-bugs] [JIRA] (ASTERISK-30201) app_senddtmf: Repeat uses of PlayDTMF AMI action can cause infinite DTMF, or potential for crash
Jonathan Rose (JIRA)
noreply at issues.asterisk.org
Tue Sep 6 19:14:09 CDT 2022
[ https://issues.asterisk.org/jira/browse/ASTERISK-30201?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=260028#comment-260028 ]
Jonathan Rose edited comment on ASTERISK-30201 at 9/6/22 7:12 PM:
------------------------------------------------------------------
After further investigation, I no longer think there is a risk of free'd memory use when this failure occurs. What happens in each case is the generatordata is constantly flipped back and forth between NULL and the data that was initially set for the generator. If generatordata is null when deactivate_generator_nolock is called and hits the if (ast_channel_generatordata(chan) check, it'll effectively skip deactivating the generator all together.
I'm not sure about the exact details, but in a simple one on one dial example (PJSIP caller A calls PJSIP caller B) I've added some stuff to print the before and after value as well as a backtrace so we can have a rough idea of what invoked the change:
{code}
[Sep 6 18:13:33] NOTICE[52875]: channel_internal_api.c:573 ast_channel_generatordata_set: generatordata_set was (nil), setting to 0x7f1d40004c30
> 0x7f1e2c01bb90 -- Strict RTP switching to RTP target address 192.168.1.7:1046 as source
[Sep 6 18:13:33] ERROR[52875]: Got 13 backtrace records
# 0: asterisk ast_channel_generatordata_set()
# 1: asterisk ast_activate_generator()
# 2: asterisk ast_playtones_start()
# 3: asterisk ast_senddigit_begin()
# 4: asterisk ast_senddigit_external()
# 5: [0x7f1e30c9fb65] app_senddtmf.so app_senddtmf.c:183 manager_play_dtmf()
# 6: asterisk <unknown>()
# 7: asterisk <unknown>()
# 8: asterisk <unknown>()
# 9: asterisk <unknown>()
#10: asterisk <unknown>()
#11: [0x7f1e43047b43] libc.so.6 pthread_create.c:442 start_thread()
#12: [0x7f1e430d9a00] libc.so.6 clone3.S:83 __clone3()
[Sep 6 18:13:33] NOTICE[52875]: channel_internal_api.c:743 ast_channel_generator_set: generator was (nil), setting to 0x5627ed0bf820
[Sep 6 18:13:33] ERROR[52875]: Got 13 backtrace records
# 0: asterisk ast_channel_generator_set()
# 1: asterisk ast_activate_generator()
# 2: asterisk ast_playtones_start()
# 3: asterisk ast_senddigit_begin()
# 4: asterisk ast_senddigit_external()
# 5: [0x7f1e30c9fb65] app_senddtmf.so app_senddtmf.c:183 manager_play_dtmf()
# 6: asterisk <unknown>()
# 7: asterisk <unknown>()
# 8: asterisk <unknown>()
# 9: asterisk <unknown>()
#10: asterisk <unknown>()
#11: [0x7f1e43047b43] libc.so.6 pthread_create.c:442 start_thread()
#12: [0x7f1e430d9a00] libc.so.6 clone3.S:83 __clone3()
[Sep 6 18:13:33] NOTICE[52879][C-00000001]: channel_internal_api.c:573 ast_channel_generatordata_set: generatordata_set was 0x7f1d40004c30, setting to (nil)
[Sep 6 18:13:33] ERROR[52879][C-00000001]: Got 20 backtrace records
# 0: asterisk ast_channel_generatordata_set()
# 1: asterisk <unknown>()
# 2: asterisk <unknown>()
# 3: asterisk ast_read_stream()
# 4: asterisk <unknown>()
# 5: asterisk <unknown>()
# 6: asterisk bridge_channel_internal_join()
# 7: asterisk ast_bridge_join()
# 8: asterisk ast_bridge_call_with_flags()
# 9: asterisk ast_bridge_call()
#10: [0x7f1e3149886b] app_dial.so app_dial.c:3442 dial_exec_full()
#11: [0x7f1e314992ca] app_dial.so app_dial.c:3516 dial_exec()
#12: asterisk pbx_exec()
#13: asterisk <unknown>()
#14: asterisk ast_spawn_extension()
#15: asterisk <unknown>()
#16: asterisk <unknown>()
#17: asterisk <unknown>()
#18: [0x7f1e43047b43] libc.so.6 pthread_create.c:442 start_thread()
#19: [0x7f1e430d9a00] libc.so.6 clone3.S:83 __clone3()
[Sep 6 18:13:33] NOTICE[52879][C-00000001]: channel_internal_api.c:573 ast_channel_generatordata_set: generatordata_set was (nil), setting to 0x7f1d40004c30
[Sep 6 18:13:33] ERROR[52879][C-00000001]: Got 20 backtrace records
# 0: asterisk ast_channel_generatordata_set()
# 1: asterisk <unknown>()
# 2: asterisk <unknown>()
# 3: asterisk ast_read_stream()
# 4: asterisk <unknown>()
# 5: asterisk <unknown>()
# 6: asterisk bridge_channel_internal_join()
# 7: asterisk ast_bridge_join()
# 8: asterisk ast_bridge_call_with_flags()
# 9: asterisk ast_bridge_call()
#10: [0x7f1e3149886b] app_dial.so app_dial.c:3442 dial_exec_full()
#11: [0x7f1e314992ca] app_dial.so app_dial.c:3516 dial_exec()
#12: asterisk pbx_exec()
#13: asterisk <unknown>()
#14: asterisk ast_spawn_extension()
#15: asterisk <unknown>()
#16: asterisk <unknown>()
#17: asterisk <unknown>()
#18: [0x7f1e43047b43] libc.so.6 pthread_create.c:442 start_thread()
#19: [0x7f1e430d9a00] libc.so.6 clone3.S:83 __clone3()
[Sep 6 18:13:33] NOTICE[52879][C-00000001]: channel_internal_api.c:573 ast_channel_generatordata_set: generatordata_set was 0x7f1d40004c30, setting to (nil)
[Sep 6 18:13:33] ERROR[52879][C-00000001]: Got 20 backtrace records
# 0: asterisk ast_channel_generatordata_set()
# 1: asterisk <unknown>()
# 2: asterisk <unknown>()
# 3: asterisk ast_read_stream()
# 4: asterisk <unknown>()
# 5: asterisk <unknown>()
# 6: asterisk bridge_channel_internal_join()
# 7: asterisk ast_bridge_join()
# 8: asterisk ast_bridge_call_with_flags()
# 9: asterisk ast_bridge_call()
#10: [0x7f1e3149886b] app_dial.so app_dial.c:3442 dial_exec_full()
#11: [0x7f1e314992ca] app_dial.so app_dial.c:3516 dial_exec()
#12: asterisk pbx_exec()
#13: asterisk <unknown>()
#14: asterisk ast_spawn_extension()
#15: asterisk <unknown>()
#16: asterisk <unknown>()
#17: asterisk <unknown>()
#18: [0x7f1e43047b43] libc.so.6 pthread_create.c:442 start_thread()
#19: [0x7f1e430d9a00] libc.so.6 clone3.S:83 __clone3()
[Sep 6 18:13:33] NOTICE[52879][C-00000001]: channel_internal_api.c:573 ast_channel_generatordata_set: generatordata_set was (nil), setting to 0x7f1d40004c30
[Sep 6 18:13:33] ERROR[52879][C-00000001]: Got 20 backtrace records
# 0: asterisk ast_channel_generatordata_set()
# 1: asterisk <unknown>()
# 2: asterisk <unknown>()
# 3: asterisk ast_read_stream()
# 4: asterisk <unknown>()
# 5: asterisk <unknown>()
# 6: asterisk bridge_channel_internal_join()
# 7: asterisk ast_bridge_join()
# 8: asterisk ast_bridge_call_with_flags()
# 9: asterisk ast_bridge_call()
#10: [0x7f1e3149886b] app_dial.so app_dial.c:3442 dial_exec_full()
#11: [0x7f1e314992ca] app_dial.so app_dial.c:3516 dial_exec()
#12: asterisk pbx_exec()
#13: asterisk <unknown>()
#14: asterisk ast_spawn_extension()
#15: asterisk <unknown>()
#16: asterisk <unknown>()
#17: asterisk <unknown>()
#18: [0x7f1e43047b43] libc.so.6 pthread_create.c:442 start_thread()
#19: [0x7f1e430d9a00] libc.so.6 clone3.S:83 __clone3()
{code}
this pattern will repeat rather frequently for the duration of the DTMF pulse.
I would guess at this point that the only way to make accessing the generator (or at least the generatordata) externally after it's been set already to be thread safe would be to require locking around the channel while ast_read has the generator temporarily set to null (see channel.c around line 3646 in current git 18)
{code}
} else if (ast_channel_fd_isset(chan, AST_GENERATOR_FD) && ast_channel_fdno(chan) == AST_GENERATOR_FD) {
/* if the AST_GENERATOR_FD is set, call the generator with args
* set to -1 so it can do whatever it needs to.
*/
void *tmp = ast_channel_generatordata(chan);
ast_channel_generatordata_set(chan, NULL); /* reset to let ast_write get through */ ast_channel_generator(chan)->generate(chan, tmp, -1, -1);
ast_channel_generatordata_set(chan, tmp);
f = &ast_null_frame;
ast_channel_fdno_set(chan, -1);
goto done;
}
{code}
I'm guessing adding additional locking here might be questionable for performance, so an alternate proposal for how to do this...
1. ast_senddigit_begin gets a duration argument. If zero, it behaves the same way as it did before (since the external function is going to have a minimum of AST_EMULATE_DTMF_DURATION, it will always have a non-zero value). It also starts returning an enum that has a success value, a failure value, and a value that indicates that it is handled by the generator. (or an alternate api can be provided to avoid disrupting other code)
2. ast_playtones_start gets a duration argument as well (or an alternate api can be provided since that's probably less disruptive to other code)
3. playtones generator will set an end time based on the duration to the generatordata if it is provided in ast_playtones_start. From that point on it will perform a time check during its generate callback and end itself if the current time exceeds the stop time.
I'm still trying to work out a patch for this myself, but I may not be able to provide it (or at least not expediently) because I have to run anything I might contribute past legal for the immediate future.
was (Author: jonathanrrose):
After further investigation, I no longer think there is a risk of free'd memory use when this failure occurs. What happens in each case is the generatordata is constantly flipped back and forth between NULL and the data that was initially set for the generator. If generatordata is null when deactivate_generator_nolock is called and hits the if (ast_channel_generatordata(chan) check, it'll effectively skip deactivating the generator all together.
I'm not sure about the exact details, but in the simple one on one dial example above I've added some stuff to print the before and after value as well as a backtrace so we can have a rough idea of what invoked the change:
{code}
[Sep 6 18:13:33] NOTICE[52875]: channel_internal_api.c:573 ast_channel_generatordata_set: generatordata_set was (nil), setting to 0x7f1d40004c30
> 0x7f1e2c01bb90 -- Strict RTP switching to RTP target address 192.168.1.7:1046 as source
[Sep 6 18:13:33] ERROR[52875]: Got 13 backtrace records
# 0: asterisk ast_channel_generatordata_set()
# 1: asterisk ast_activate_generator()
# 2: asterisk ast_playtones_start()
# 3: asterisk ast_senddigit_begin()
# 4: asterisk ast_senddigit_external()
# 5: [0x7f1e30c9fb65] app_senddtmf.so app_senddtmf.c:183 manager_play_dtmf()
# 6: asterisk <unknown>()
# 7: asterisk <unknown>()
# 8: asterisk <unknown>()
# 9: asterisk <unknown>()
#10: asterisk <unknown>()
#11: [0x7f1e43047b43] libc.so.6 pthread_create.c:442 start_thread()
#12: [0x7f1e430d9a00] libc.so.6 clone3.S:83 __clone3()
[Sep 6 18:13:33] NOTICE[52875]: channel_internal_api.c:743 ast_channel_generator_set: generator was (nil), setting to 0x5627ed0bf820
[Sep 6 18:13:33] ERROR[52875]: Got 13 backtrace records
# 0: asterisk ast_channel_generator_set()
# 1: asterisk ast_activate_generator()
# 2: asterisk ast_playtones_start()
# 3: asterisk ast_senddigit_begin()
# 4: asterisk ast_senddigit_external()
# 5: [0x7f1e30c9fb65] app_senddtmf.so app_senddtmf.c:183 manager_play_dtmf()
# 6: asterisk <unknown>()
# 7: asterisk <unknown>()
# 8: asterisk <unknown>()
# 9: asterisk <unknown>()
#10: asterisk <unknown>()
#11: [0x7f1e43047b43] libc.so.6 pthread_create.c:442 start_thread()
#12: [0x7f1e430d9a00] libc.so.6 clone3.S:83 __clone3()
[Sep 6 18:13:33] NOTICE[52879][C-00000001]: channel_internal_api.c:573 ast_channel_generatordata_set: generatordata_set was 0x7f1d40004c30, setting to (nil)
[Sep 6 18:13:33] ERROR[52879][C-00000001]: Got 20 backtrace records
# 0: asterisk ast_channel_generatordata_set()
# 1: asterisk <unknown>()
# 2: asterisk <unknown>()
# 3: asterisk ast_read_stream()
# 4: asterisk <unknown>()
# 5: asterisk <unknown>()
# 6: asterisk bridge_channel_internal_join()
# 7: asterisk ast_bridge_join()
# 8: asterisk ast_bridge_call_with_flags()
# 9: asterisk ast_bridge_call()
#10: [0x7f1e3149886b] app_dial.so app_dial.c:3442 dial_exec_full()
#11: [0x7f1e314992ca] app_dial.so app_dial.c:3516 dial_exec()
#12: asterisk pbx_exec()
#13: asterisk <unknown>()
#14: asterisk ast_spawn_extension()
#15: asterisk <unknown>()
#16: asterisk <unknown>()
#17: asterisk <unknown>()
#18: [0x7f1e43047b43] libc.so.6 pthread_create.c:442 start_thread()
#19: [0x7f1e430d9a00] libc.so.6 clone3.S:83 __clone3()
[Sep 6 18:13:33] NOTICE[52879][C-00000001]: channel_internal_api.c:573 ast_channel_generatordata_set: generatordata_set was (nil), setting to 0x7f1d40004c30
[Sep 6 18:13:33] ERROR[52879][C-00000001]: Got 20 backtrace records
# 0: asterisk ast_channel_generatordata_set()
# 1: asterisk <unknown>()
# 2: asterisk <unknown>()
# 3: asterisk ast_read_stream()
# 4: asterisk <unknown>()
# 5: asterisk <unknown>()
# 6: asterisk bridge_channel_internal_join()
# 7: asterisk ast_bridge_join()
# 8: asterisk ast_bridge_call_with_flags()
# 9: asterisk ast_bridge_call()
#10: [0x7f1e3149886b] app_dial.so app_dial.c:3442 dial_exec_full()
#11: [0x7f1e314992ca] app_dial.so app_dial.c:3516 dial_exec()
#12: asterisk pbx_exec()
#13: asterisk <unknown>()
#14: asterisk ast_spawn_extension()
#15: asterisk <unknown>()
#16: asterisk <unknown>()
#17: asterisk <unknown>()
#18: [0x7f1e43047b43] libc.so.6 pthread_create.c:442 start_thread()
#19: [0x7f1e430d9a00] libc.so.6 clone3.S:83 __clone3()
[Sep 6 18:13:33] NOTICE[52879][C-00000001]: channel_internal_api.c:573 ast_channel_generatordata_set: generatordata_set was 0x7f1d40004c30, setting to (nil)
[Sep 6 18:13:33] ERROR[52879][C-00000001]: Got 20 backtrace records
# 0: asterisk ast_channel_generatordata_set()
# 1: asterisk <unknown>()
# 2: asterisk <unknown>()
# 3: asterisk ast_read_stream()
# 4: asterisk <unknown>()
# 5: asterisk <unknown>()
# 6: asterisk bridge_channel_internal_join()
# 7: asterisk ast_bridge_join()
# 8: asterisk ast_bridge_call_with_flags()
# 9: asterisk ast_bridge_call()
#10: [0x7f1e3149886b] app_dial.so app_dial.c:3442 dial_exec_full()
#11: [0x7f1e314992ca] app_dial.so app_dial.c:3516 dial_exec()
#12: asterisk pbx_exec()
#13: asterisk <unknown>()
#14: asterisk ast_spawn_extension()
#15: asterisk <unknown>()
#16: asterisk <unknown>()
#17: asterisk <unknown>()
#18: [0x7f1e43047b43] libc.so.6 pthread_create.c:442 start_thread()
#19: [0x7f1e430d9a00] libc.so.6 clone3.S:83 __clone3()
[Sep 6 18:13:33] NOTICE[52879][C-00000001]: channel_internal_api.c:573 ast_channel_generatordata_set: generatordata_set was (nil), setting to 0x7f1d40004c30
[Sep 6 18:13:33] ERROR[52879][C-00000001]: Got 20 backtrace records
# 0: asterisk ast_channel_generatordata_set()
# 1: asterisk <unknown>()
# 2: asterisk <unknown>()
# 3: asterisk ast_read_stream()
# 4: asterisk <unknown>()
# 5: asterisk <unknown>()
# 6: asterisk bridge_channel_internal_join()
# 7: asterisk ast_bridge_join()
# 8: asterisk ast_bridge_call_with_flags()
# 9: asterisk ast_bridge_call()
#10: [0x7f1e3149886b] app_dial.so app_dial.c:3442 dial_exec_full()
#11: [0x7f1e314992ca] app_dial.so app_dial.c:3516 dial_exec()
#12: asterisk pbx_exec()
#13: asterisk <unknown>()
#14: asterisk ast_spawn_extension()
#15: asterisk <unknown>()
#16: asterisk <unknown>()
#17: asterisk <unknown>()
#18: [0x7f1e43047b43] libc.so.6 pthread_create.c:442 start_thread()
#19: [0x7f1e430d9a00] libc.so.6 clone3.S:83 __clone3()
{code}
this pattern will repeat rather frequently for the duration of the DTMF pulse.
I would guess at this point that the only way to make accessing the generator (or at least the generatordata) externally after it's been set already to be thread safe would be to require locking around the channel while ast_read has the generator temporarily set to null (see channel.c around line 3646 in current git 18)
{code}
} else if (ast_channel_fd_isset(chan, AST_GENERATOR_FD) && ast_channel_fdno(chan) == AST_GENERATOR_FD) {
/* if the AST_GENERATOR_FD is set, call the generator with args
* set to -1 so it can do whatever it needs to.
*/
void *tmp = ast_channel_generatordata(chan);
ast_channel_generatordata_set(chan, NULL); /* reset to let ast_write get through */ ast_channel_generator(chan)->generate(chan, tmp, -1, -1);
ast_channel_generatordata_set(chan, tmp);
f = &ast_null_frame;
ast_channel_fdno_set(chan, -1);
goto done;
}
{code}
I'm guessing adding additional locking here might be questionable for performance, so an alternate proposal for how to do this...
1. ast_senddigit_begin gets a duration argument. If zero, it behaves the same way as it did before (since the external function is going to have a minimum of AST_EMULATE_DTMF_DURATION, it will always have a non-zero value). It also starts returning an enum that has a success value, a failure value, and a value that indicates that it is handled by the generator. (or an alternate api can be provided to avoid disrupting other code)
2. ast_playtones_start gets a duration argument as well (or an alternate api can be provided since that's probably less disruptive to other code)
3. playtones generator will set an end time based on the duration to the generatordata if it is provided in ast_playtones_start. From that point on it will perform a time check during its generate callback and end itself if the current time exceeds the stop time.
I'm still trying to work out a patch for this myself, but I may not be able to provide it (or at least not expediently) because I have to run anything I might contribute past legal for the immediate future.
> app_senddtmf: Repeat uses of PlayDTMF AMI action can cause infinite DTMF, or potential for crash
> ------------------------------------------------------------------------------------------------
>
> Key: ASTERISK-30201
> URL: https://issues.asterisk.org/jira/browse/ASTERISK-30201
> Project: Asterisk
> Issue Type: Bug
> Security Level: None
> Components: Applications/app_senddtmf
> Affects Versions: 16.3.0, 18.9.0, 18.12.1
> Environment: System 1 - Ubuntu 22.04 - Intel core i7 6th generation NUC
> System 2 - Centos 7 - some dell server blade thing with server grade hardware, it's not important, I'm just including it for the purpose of indicating that I've reproduced this on multiple systems
> Reporter: Jonathan Rose
>
> The PlayDTMF manager command results in a sticking tone intermittently. I haven't seen this happen the first time this command is used on a channel, but frequently (not always) if I use PlayDTMF several times on a channel during a call the tone will persist until I send another PlayDTMF command at which point it will stop. I'm generally able to reproduce this every other call, but depending on chance it may be more or less frequent. Presently I think this only happens for channels that use Inband DTMF modes, but I haven't fully investigated the effects in other instances since they are harder to discern (an endless noise is easier to notice than a strange behavior with an info message)
> The bug was discovered on a test system in the lab. We have a browser 'softphone' that uses playdtmf to inject DTMF into a call... there are other circumstances where we use playdtmf, but that's not super important. Our prod/test systems use a heavily modified version of Asterisk anyway (plus they are still using chan_sip).
> So I did a fresh clone of Asterisk 18 (commit bd821549af3bccb000c809121094adb5b84fec7f) tonight on a relatively clean Ubuntu 22.04 system and reproduced it with a very minimal setup while making sure everything is super recent and still supported.
> PJSIP config:
> [general]
> allowoverlap = no
> [transport-udp]
> type = transport
> protocol = udp
> bind = 0.0.0.0
> [testuser1]
> type = aor
> max_contacts = 1
> [testuser1]
> type = endpoint
> context = testtext
> disallow = all
> allow = ulaw
> allow = alaw
> aors = testuser1
> asymmetric_rtp_codec = true
> direct_media = false
> dtmf_mode = inband
> extensions.conf
> [testtext]
> exten => 100,1,Answer()
> exten => 100,n,Echo()
> manager.conf
> [general]
> enabled = yes
> [adminpizzapasta]
> secret=itsasecrettoeveryone
> deny=0.0.0.0/0.0.0.0
> permit=127.0.0.1
> read=system,call,log
> write=system,call,log
> Step 1:
> Start a call using the phone/softphone of your choice (specifically a Polycom VVX 410 was the one it was reproduced on in the lab while I reproduced it with TipCon1 softphone at home -- doesn't really matter, I have also prodded deeply enough to figure out that the DTMF is being repeatedly generated by Asterisk even after the generator detach function was called) to extension 100 using the testuser1 account. This will play an echo which is mostly just used so we have some media.
> Step 2:
> Login to manager using adminpizzapasta
> Step 3:
> Start spamming the call with PlayDTMF messages until you get a sticky tone
> Some examples of manager commands I sent:
> Action: PlayDTMF
> Channel: PJSIP/testuser1-00000000
> Digit: 4
> Action: PlayDTMF
> Channel: PJSIP/testuser1-00000000
> Digit: 5
> Action: PlayDTMF
> Channel: PJSIP/testuser1-00000000
> Digit: 6
> Action: PlayDTMF
> Channel: PJSIP/testuser1-00000000
> Digit: #
> Note the lack of a specified duration. It makes no difference if I include a duration, but it will use the default lowest possible value as a result.
> If you don't get it within 20 tones or so, I recommend starting over and trying again. Usually if I can get it to happen once on a call I can get it to happen again quite frequently.
> It's technically a regression, but it started happening after we moved from 1.6.2 to 16.3, so I can't really help to isolate specifically when it started right now. That said, there was a patch by Richard Mudgett back in 2019 that may have been involved. It changed some channel API stuff around so that there is a specific 'ast_senddigit_external' function intended for use when invoking DTMF outside the main media thread of a channel.
> Now onto the scary part...
> In the event of these tones sticking, I noticed ast_playtones_stop is invoked on the channel which in turn invokes ast_deactivate_generator, which I think is then going to call the generator release function in ast_generator_playtones (indications.c) which will then also free the playtones_state which is used by the playtones_generator function which is still running after the fact. I don't know with certainy right now if anything is going to use this free'd memory and I haven't seen any errors coming out of Asterisk during these times just yet, so it might be insignificant, but I still found it a little spooky.
> One other thing to note I suppose -- it might be better to move to schedule the stops in a task processor or something rather than having it block for the duration of the DTMF. Probably not super important and it isn't exactly hurting our use any, but I can imagine that would get annoying with long duration DTMF.
> I'll be trying to isolate this more over the next week and hopefully get a patch written, I just figured I'd go ahead and let you guys know about it.
--
This message was sent by Atlassian JIRA
(v6.2#6252)
More information about the asterisk-bugs
mailing list