[ASTERISK-111] chan_dahdi: MWI while off-hook when hung up on after recall ring

← All Issues || New Issue →

Sort Normal || Priority

Details

Steps to reproduce (phone B must be a DAHDI channel, phone A can be anything)

in chan_dahdi, threewaycalling must be enabled and a mailbox should be assigned to a line (to trigger MWI).

For some reason, on one of my systems, autoreoriginate=yes only affects when an outgoing call is hung up on, rather than incoming. On that system, this setting doesn't matter. On another system, it affects both incoming and outgoing clearings, and autoreoriginate must be set to no in order to reproduce this issue. (This discrepancy is a separate bug, see [ASTERISK-64].)

1. Call from A to B
2. Answer on B, then flash to put A on hold
3. Hang up B, which will trigger recall ring for the call on hold
4. Re-answer on B. Time does not matter (e.g. could before first full ring has completed, could be multiple rings, etc.)
5. Hang up A, which will drop B to reorder.
6. After a couple seconds, an MWI FSK burst will be heard on B and the reorder will stop completely. This should not happen!

Reproduces on multiple 21.3.1 systems like clockwork, so it's still an issue in master.

Example debug where A is 122 and B is 121 (the phone with the MWI it should not hear):

[2024-09-08 09:42:17.839] DEBUG[271694][C-00000008]: sig_analog.c:3050 analog_handle_event: Got event ANALOG_EVENT_ONHOOK(1) on channel 122 (index 0)
[2024-09-08 09:42:17.841]     -- Channel DAHDI/122-1 left 'native_dahdi' basic-bridge <64983730-6685-4bfe-820c-d554378f3b64>
[2024-09-08 09:42:17.840] DEBUG[271694][C-00000008]: chan_dahdi.c:4983 dahdi_ec_enable: Enabled echo cancellation on channel 122
[2024-09-08 09:42:17.840] DEBUG[271694][C-00000008]: chan_dahdi.c:4983 dahdi_ec_enable: Enabled echo cancellation on channel 121
[2024-09-08 09:42:17.841] DEBUG[271694][C-00000008]: chan_dahdi.c:7403 dahdi_master_slave_unlink: Unlinking slave 121 from 122
[2024-09-08 09:42:17.841] DEBUG[271694][C-00000008]: chan_dahdi.c:4816 conf_del: Removed 9 from conference 9/122
[2024-09-08 09:42:17.841] DEBUG[271694][C-00000008]: chan_dahdi.c:4816 conf_del: Removed 10 from conference 9/121
[2024-09-08 09:42:17.841] DEBUG[271694][C-00000008]: chan_dahdi.c:4931 dahdi_conf_update: Updated conferencing on 122, with 0 conference users
[2024-09-08 09:42:17.841] DEBUG[271694][C-00000008]: dahdi/bridge_native_dahdi.c:166 native_stop: Stop native bridging DAHDI/122-1 and DAHDI/121-1
[2024-09-08 09:42:17.843]     -- Channel DAHDI/121-1 left 'native_dahdi' basic-bridge <64983730-6685-4bfe-820c-d554378f3b64>
[2024-09-08 09:42:17.844]        > Call ended, DIALSTATUS: ANSWER
[2024-09-08 09:42:17.845]   == Spawn extension (from-internal, 221, 1) exited non-zero on 'DAHDI/122-1'
[2024-09-08 09:42:17.845] DEBUG[271694][C-00000008]: chan_dahdi.c:6295 dahdi_hangup: dahdi_hangup(DAHDI/122-1)
[2024-09-08 09:42:17.845] DEBUG[271694][C-00000008]: sig_analog.c:1295 analog_hangup: analog_hangup 122
[2024-09-08 09:42:17.845] DEBUG[271694][C-00000008]: sig_analog.c:1317 analog_hangup: Hangup: channel: 122 index = 0, normal = 1, callwait = 0, thirdcall = 0
[2024-09-08 09:42:17.844] DEBUG[271696][C-00000008]: chan_dahdi.c:9450 dahdi_indicate: Requested indication 26 on channel DAHDI/121-1
[2024-09-08 09:42:17.846] DEBUG[271694][C-00000008]: chan_dahdi.c:5018 dahdi_ec_disable: Disabled echo cancellation on channel 122
[2024-09-08 09:42:17.846] DEBUG[271694][C-00000008]: chan_dahdi.c:6931 dahdi_setoption: Set option TONE VERIFY, mode: OFF(0) on DAHDI/122-1
[2024-09-08 09:42:17.846] DEBUG[271694][C-00000008]: chan_dahdi.c:6941 dahdi_setoption: Set option TDD MODE, value: OFF(0) on DAHDI/122-1
[2024-09-08 09:42:17.846] DEBUG[271694][C-00000008]: sig_analog.c:768 analog_update_conf: Updated conferencing on 122, with 0 conference users
[2024-09-08 09:42:17.846]     -- Hanging up on 'DAHDI/122-1'
[2024-09-08 09:42:17.846]     -- Hungup 'DAHDI/122-1'
[2024-09-08 09:42:17.848] DEBUG[271696][C-00000008]: chan_dahdi.c:6295 dahdi_hangup: dahdi_hangup(DAHDI/121-1)
[2024-09-08 09:42:17.848] DEBUG[271696][C-00000008]: sig_analog.c:1295 analog_hangup: analog_hangup 121
[2024-09-08 09:42:17.848] DEBUG[271696][C-00000008]: sig_analog.c:1317 analog_hangup: Hangup: channel: 121 index = 0, normal = 1, callwait = 0, thirdcall = 0
[2024-09-08 09:42:17.849] DEBUG[271696][C-00000008]: chan_dahdi.c:5018 dahdi_ec_disable: Disabled echo cancellation on channel 121
[2024-09-08 09:42:17.849] DEBUG[271696][C-00000008]: chan_dahdi.c:6931 dahdi_setoption: Set option TONE VERIFY, mode: OFF(0) on DAHDI/121-1
[2024-09-08 09:42:17.849] DEBUG[271696][C-00000008]: chan_dahdi.c:6941 dahdi_setoption: Set option TDD MODE, value: OFF(0) on DAHDI/121-1
[2024-09-08 09:42:17.849] DEBUG[271696][C-00000008]: sig_analog.c:768 analog_update_conf: Updated conferencing on 121, with 0 conference users
[2024-09-08 09:42:17.850]     -- Hanging up on 'DAHDI/121-1'
[2024-09-08 09:42:17.850]     -- Hungup 'DAHDI/121-1'
[2024-09-08 09:42:17.901] DEBUG[271692]: chan_dahdi.c:12233 do_monitor: Monitor doohicky got event Event 32 on channel 121
[2024-09-08 09:42:17.901] DEBUG[271692]: sig_analog.c:4074 analog_handle_init_event: channel (121) - signaling (2) - event (ANALOG_EVENT_PULSE_BREAK)
[2024-09-08 09:42:18.349] DEBUG[271692]: chan_dahdi.c:12233 do_monitor: Monitor doohicky got event Hook Transition Complete on channel 121
[2024-09-08 09:42:18.349] DEBUG[271692]: sig_analog.c:4074 analog_handle_init_event: channel (121) - signaling (2) - event (ANALOG_EVENT_HOOKCOMPLETE)
debian*CLI>
debian*CLI>
debian*CLI>
debian*CLI>
debian*CLI>
[2024-09-08 09:42:21.353] DEBUG[271692]: chan_dahdi.c:12102 do_monitor: Initiating MWI FSK spill on channel 121
[2024-09-08 09:42:22.012] DEBUG[271692]: chan_dahdi.c:12102 do_monitor: Initiating MWI FSK spill on channel 122
[2024-09-08 09:42:42.157] DEBUG[271692]: chan_dahdi.c:12233 do_monitor: Monitor doohicky got event Event 32 on channel 121
[2024-09-08 09:42:42.157] DEBUG[271692]: sig_analog.c:4074 analog_handle_init_event: channel (121) - signaling (2) - event (ANALOG_EVENT_PULSE_BREAK)
[2024-09-08 09:42:43.406] DEBUG[271692]: chan_dahdi.c:12233 do_monitor: Monitor doohicky got event On hook on channel 121
[2024-09-08 09:42:43.406] DEBUG[271692]: sig_analog.c:4074 analog_handle_init_event: channel (121) - signaling (2) - event (ANALOG_EVENT_ONHOOK)

The fix here will be tightening the conditions in do_monitor as somehow that logic thinks it's okay to send MWI when it isn't. Note above that we don't go off hook until 20 seconds after the MWI.

There was a previous fix for this issue here: https://github.com/asterisk/asterisk/commit/0a8b3d34673277b70be6b0e8ac50191b1f3c72c6

Predictably, that fixed the issue in that case, but in this case, there is no owner, which is why that fix does not work. A more comprehensive fix would likely have also prevented this scenario from happening. For example:

[2024-09-08 09:56:16.740] WARNING[280289]: chan_dahdi.c:12095 do_monitor: This channel is still off hook, can't send MWI!
[2024-09-08 09:56:16.740] DEBUG[280289]: chan_dahdi.c:12105 do_monitor: Initiating MWI FSK spill on channel 122
[2024-09-08 09:56:18.923] WARNING[280289]: chan_dahdi.c:12095 do_monitor: This channel is still off hook, can't send MWI!
[2024-09-08 09:56:19.924] WARNING[280289]: chan_dahdi.c:12095 do_monitor: This channel is still off hook, can't send MWI!
[2024-09-08 09:56:20.924] WARNING[280289]: chan_dahdi.c:12095 do_monitor: This channel is still off hook, can't send MWI!
[2024-09-08 09:56:21.926] WARNING[280289]: chan_dahdi.c:12095 do_monitor: This channel is still off hook, can't send MWI!
[2024-09-08 09:56:22.927] WARNING[280289]: chan_dahdi.c:12095 do_monitor: This channel is still off hook, can't send MWI!
[2024-09-08 09:56:23.928] WARNING[280289]: chan_dahdi.c:12095 do_monitor: This channel is still off hook, can't send MWI!
[2024-09-08 09:56:24.930] WARNING[280289]: chan_dahdi.c:12095 do_monitor: This channel is still off hook, can't send MWI!
[2024-09-08 09:56:25.931] WARNING[280289]: chan_dahdi.c:12095 do_monitor: This channel is still off hook, can't send MWI!
[2024-09-08 09:56:26.933] WARNING[280289]: chan_dahdi.c:12095 do_monitor: This channel is still off hook, can't send MWI!
[2024-09-08 09:56:27.934] WARNING[280289]: chan_dahdi.c:12095 do_monitor: This channel is still off hook, can't send MWI!
[2024-09-08 09:56:28.403] DEBUG[280289]: chan_dahdi.c:12105 do_monitor: Initiating MWI FSK spill on channel 121
[2024-09-08 09:56:28.403] DEBUG[280289]: chan_dahdi.c:12236 do_monitor: Monitor doohicky got event Event 32 on channel 121
[2024-09-08 09:56:28.403] DEBUG[280289]: sig_analog.c:4074 analog_handle_init_event: channel (121) - signaling (2) - event (ANALOG_EVENT_PULSE_BREAK)
[2024-09-08 09:56:29.651] DEBUG[280289]: chan_dahdi.c:12236 do_monitor: Monitor doohicky got event On hook on channel 121
[2024-09-08 09:56:29.651] DEBUG[280289]: sig_analog.c:4074 analog_handle_init_event: channel (121) - signaling (2) - event (ANALOG_EVENT_ONHOOK)

Fix:

• add this debug statement: ast_debug(5, "Initiating MWI FSK spill on channel %d\n", last->channel); before mwi_send_init is called
• add && !my_is_off_hook(last) as one of the conditions in the giant MWI check. It should be the last one since this makes an ioctl call so it is "expensive" (not just checking existing state information). Because of all the other checks, this won't get called a bunch, and it should ensure correct behavior 100% of the time.

Comments

You must be logged in to leave a comment.