ASTERISK-27833: hangup handlers sometimes called on answer and not on hangup (depending on usage of local channels, bridge, originate, mixmonitor)

[Home]

Summary: ASTERISK-27833: hangup handlers sometimes called on answer and not on hangup (depending on usage of local channels, bridge, originate, mixmonitor)

Reporter: Frederic Steinfels (fredo) Labels: pjsip

Date Opened: 2018-05-01 17:49:23 Date Closed: 2018-05-29 15:39:31

Priority: Major Regression?

Status: Closed/Complete Components: Core/Bridging

Versions: 15.3.0 Frequency of
Occurrence Constant

Related
Issues:

Environment: Fedora 27, probably all Attachments: ( 0) scenario2_20180502-002816-29-28.wav
( 1) scenario3_20180502-003400-29-28.wav

Description: The behaviour of the bridge command is different depending on wheter MixMonitor is used. MixMonitor itself does not work if used before the PlayBack(beep) command. MixMonitor works if used after the PlayBack command.

Scenario 1: Bridge command without MixMonitor
{noformat}
exten => s,1001,Set(CALLEDNUM=${SHARED(connecttocid)})
exten => s,1002,agi(googletts.agi,"Sie werden mit ${ADMIN-${SHARED(connecttoadminid)}-spokenfname} ${ADMIN-${SHARED(connecttoadminid)}-spokenlname} verbunden.",de,,1.4)
exten => s,1003,Set(CHANNEL(hangup_handler_push)=logoutemployee,s,1(hangup_handler))
exten => s,1004,Set(CHANNEL(after_bridge_goto)=logoutemployee,s,1(after_bridge))
exten => s,1005,Playback(beep)
exten => s,1006,Noop()
exten => s,1007,Bridge(${SHARED(connecttochannel)},p)
exten => h,1,Noop(in hangup)
{noformat}

This will happen:
{noformat}
-- Executing [s@newanswer:1001] Set("Local/69@default-000000b8;2", "CALLEDNUM=28") in new stack
-- Executing [s@newanswer:1002] AGI("Local/69@default-000000b8;2", "googletts.agi,"Sie werden mit Frédéric Steinfels verbunden.",de,,1.4") in new stack
-- Launched AGI Script /var/lib/asterisk/agi-bin/googletts.agi
== Spawn extension (local-sccp-call, s, 14) exited non-zero on 'Local/22@default-000000b9;2'
-- <Local/69@default-000000b8;2> Playing '/data/Telefon/googletts//9c3c06da9e11b5448585f24c9285641b.1.4.slin16' (escape_digits=) (sample_offset 0) (language 'en')
-- <Local/69@default-000000b8;2>AGI Script googletts.agi completed, returning 0
-- Executing [s@newanswer:1003] Set("Local/69@default-000000b8;2", "CHANNEL(hangup_handler_push)=logoutemployee,s,1(hangup_handler)") in new stack
-- Executing [s@newanswer:1004] Set("Local/69@default-000000b8;2", "CHANNEL(after_bridge_goto)=logoutemployee,s,1(after_bridge)") in new stack
-- Executing [s@newanswer:1005] Playback("Local/69@default-000000b8;2", "beep") in new stack
-- <Local/69@default-000000b8;2> Playing 'beep.gsm' (language 'en')
-- Executing [s@newanswer:1006] NoOp("Local/69@default-000000b8;2", "") in new stack
-- Executing [s@newanswer:1007] Bridge("Local/69@default-000000b8;2", "Local/28@default-000000ba;1,p") in new stack
== Spawn extension (receptionist4, s, 16) exited non-zero on 'Surrogate/Local/28@default-000000ba;1'
-- Channel Local/28@default-000000ba;1 joined 'simple_bridge' basic-bridge <db41b6a4-3a40-43eb-892e-1d496da479db>
-- Channel Local/69@default-000000b8;2 joined 'simple_bridge' basic-bridge <db41b6a4-3a40-43eb-892e-1d496da479db>
[May 2 00:06:18] WARNING[22967][C-0000003f]: file.c:1245 ast_streamfile: Unable to open beep (format (slin192)): No such file or directory
> Move-swap optimizing Local/28@default-000000ba;1 <-- PJSIP/28-000000b6.
-- Channel PJSIP/28-000000b6 left 'simple_bridge' basic-bridge <b7992456-512e-4047-b4b2-c5a02e4b05ab>
-- Channel Local/28@default-000000ba;1 left 'simple_bridge' basic-bridge <db41b6a4-3a40-43eb-892e-1d496da479db>
-- Channel PJSIP/28-000000b6 swapped with Local/28@default-000000ba;1 into 'simple_bridge' basic-bridge <db41b6a4-3a40-43eb-892e-1d496da479db>
-- Channel Local/28@default-000000ba;2 left 'simple_bridge' basic-bridge <b7992456-512e-4047-b4b2-c5a02e4b05ab>
== Spawn extension (local-sip-call, s, 11) exited non-zero on 'Local/28@default-000000ba;2'
-- Executing [s@receptionist4:17] Playback("Local/28@default-000000ba;1", "beep") in new stack
-- <Local/28@default-000000ba;1> Playing 'beep.gsm' (language 'en')
> Move-swap optimizing Local/69@default-000000b8;2 <-- PJSIP/mobile-000000b4.
-- Channel PJSIP/mobile-000000b4 left 'simple_bridge' basic-bridge <f6726fe1-c05f-4d7b-87ad-cf1eb8cfc113>
-- Channel Local/69@default-000000b8;2 left 'simple_bridge' basic-bridge <db41b6a4-3a40-43eb-892e-1d496da479db>
-- Channel PJSIP/mobile-000000b4 swapped with Local/69@default-000000b8;2 into 'simple_bridge' basic-bridge <db41b6a4-3a40-43eb-892e-1d496da479db>
> Bridge db41b6a4-3a40-43eb-892e-1d496da479db: switching from simple_bridge technology to native_rtp
> Remotely bridged 'PJSIP/mobile-000000b4' and 'PJSIP/28-000000b6' - media will flow directly between them
-- Channel Local/69@default-000000b8;1 left 'simple_bridge' basic-bridge <f6726fe1-c05f-4d7b-87ad-cf1eb8cfc113>
-- Executing [h@newanswer:1] NoOp("Local/69@default-000000b8;2", "in hangup") in new stack
-- Local/69@default-000000b8;2 Internal Gosub(logoutemployee,s,1(hangup_handler)) start
-- Executing [s@logoutemployee:1] NoOp("Local/69@default-000000b8;2", "I am channel Local/69@default-000000b8;2 and and hangup_handler") in new stack
-- Executing [s@logoutemployee:2] Return("Local/69@default-000000b8;2", "") in new stack
== Spawn extension (newanswer, h, 2) exited non-zero on 'Local/69@default-000000b8;2'
-- Local/69@default-000000b8;2 Internal Gosub(logoutemployee,s,1(hangup_handler)) complete GOSUB_RETVAL=
{noformat}

when hanging up:
{noformat}
-- Channel PJSIP/mobile-000000b4 left 'native_rtp' basic-bridge <db41b6a4-3a40-43eb-892e-1d496da479db>
-- Channel PJSIP/28-000000b6 left 'native_rtp' basic-bridge <db41b6a4-3a40-43eb-892e-1d496da479db>
== Spawn extension (internal2local, s, 13) exited non-zero on 'PJSIP/mobile-000000b4'
{noformat}

Scenario 2: Bridge command with MixMonitor, beep after MixMonitor
{noformat}
exten => s,1001,Set(CALLEDNUM=${SHARED(connecttocid)})
exten => s,1002,agi(googletts.agi,"Sie werden mit ${ADMIN-${SHARED(connecttoadminid)}-spokenfname} ${ADMIN-${SHARED(connecttoadminid)}-spokenlname} verbunden.",de,,1.4)
exten => s,1003,Set(CHANNEL(hangup_handler_push)=logoutemployee,s,1(hangup_handler))
exten => s,1004,Set(CHANNEL(after_bridge_goto)=logoutemployee,s,1(after_bridge))
exten => s,1005,MixMonitor(${STRFTIME(${EPOCH},,%Y%m%d-%H%M%S)}-${CALLERID(num)}-${CALLEDNUM}.wav)
exten => s,1006,Playback(beep)
exten => s,1007,Bridge(${SHARED(connecttochannel)},p)
exten => s,1008,Noop(here ${BRIDGEPEER})
exten => s,1009,Wait(5)
exten => s,1010,Hangup()
exten => h,1,Noop(in hangup)
{noformat}

{noformat}
-- Executing [s@newanswer:1001] Set("Local/69@default-000000bb;2", "CALLEDNUM=28") in new stack
-- Executing [s@newanswer:1002] AGI("Local/69@default-000000bb;2", "googletts.agi,"Sie werden mit Frédéric Steinfels verbunden.",de,,1.4") in new stack
-- Launched AGI Script /var/lib/asterisk/agi-bin/googletts.agi
-- <Local/69@default-000000bb;2> Playing '/data/Telefon/googletts//9c3c06da9e11b5448585f24c9285641b.1.4.slin16' (escape_digits=) (sample_offset 0) (language 'en')
-- <Local/69@default-000000bb;2>AGI Script googletts.agi completed, returning 0
-- Executing [s@newanswer:1003] Set("Local/69@default-000000bb;2", "CHANNEL(hangup_handler_push)=logoutemployee,s,1(hangup_handler)") in new stack
-- Executing [s@newanswer:1004] Set("Local/69@default-000000bb;2", "CHANNEL(after_bridge_goto)=logoutemployee,s,1(after_bridge)") in new stack
-- Executing [s@newanswer:1005] MixMonitor("Local/69@default-000000bb;2", "20180502-002543-29-28.wav") in new stack
-- Executing [s@newanswer:1006] Playback("Local/69@default-000000bb;2", "beep") in new stack
== Begin MixMonitor Recording Local/69@default-000000bb;2
-- <Local/69@default-000000bb;2> Playing 'beep.gsm' (language 'en')
-- Executing [s@newanswer:1007] Bridge("Local/69@default-000000bb;2", "Local/28@default-000000bd;1,p") in new stack
== Spawn extension (receptionist4, s, 16) exited non-zero on 'Surrogate/Local/28@default-000000bd;1'
-- Channel Local/28@default-000000bd;1 joined 'simple_bridge' basic-bridge <8e648097-8dcd-451d-9bb6-5cd7a3aa57a9>
-- Channel Local/69@default-000000bb;2 joined 'simple_bridge' basic-bridge <8e648097-8dcd-451d-9bb6-5cd7a3aa57a9>
-- <Local/28@default-000000bd;1> Playing 'beep.slin192' (language 'en')
> Move-swap optimizing Local/28@default-000000bd;1 <-- PJSIP/28-000000b9.
-- Channel PJSIP/28-000000b9 left 'simple_bridge' basic-bridge <e08c964b-c6a1-4c37-8322-16118a5644c2>
-- Channel Local/28@default-000000bd;1 left 'simple_bridge' basic-bridge <8e648097-8dcd-451d-9bb6-5cd7a3aa57a9>
-- Channel PJSIP/28-000000b9 swapped with Local/28@default-000000bd;1 into 'simple_bridge' basic-bridge <8e648097-8dcd-451d-9bb6-5cd7a3aa57a9>
-- Channel Local/28@default-000000bd;2 left 'simple_bridge' basic-bridge <e08c964b-c6a1-4c37-8322-16118a5644c2>
-- Executing [s@receptionist4:17] Playback("Local/28@default-000000bd;1", "beep") in new stack
== Spawn extension (local-sip-call, s, 11) exited non-zero on 'Local/28@default-000000bd;2'
-- <Local/28@default-000000bd;1> Playing 'beep.gsm' (language 'en')
{noformat}

when hanging up:
{noformat}
-- Channel PJSIP/mobile-000000b7 left 'simple_bridge' basic-bridge <a5a00ca2-c9f0-4943-8ccc-39837695842b>
-- Channel Local/69@default-000000bb;1 left 'simple_bridge' basic-bridge <a5a00ca2-c9f0-4943-8ccc-39837695842b>
== Spawn extension (internal2local, s, 13) exited non-zero on 'PJSIP/mobile-000000b7'
-- Executing [s@logoutemployee:1] NoOp("Local/69@default-000000bb;1", "I am channel Local/69@default-000000bb;1 and and ") in new stack
-- Executing [s@logoutemployee:2] Return("Local/69@default-000000bb;1", "") in new stack
[May 2 00:25:49] ERROR[8746][C-00000040]: app_stack.c:389 return_exec: Return without Gosub: stack is unallocated
== Spawn extension (logoutemployee, s, 2) exited non-zero on 'Local/69@default-000000bb;1'
-- Channel Local/69@default-000000bb;2 left 'simple_bridge' basic-bridge <8e648097-8dcd-451d-9bb6-5cd7a3aa57a9>
-- Channel PJSIP/28-000000b9 left 'simple_bridge' basic-bridge <8e648097-8dcd-451d-9bb6-5cd7a3aa57a9>
-- Executing [h@newanswer:1] NoOp("Local/69@default-000000bb;2", "in hangup") in new stack
-- Local/69@default-000000bb;2 Internal Gosub(logoutemployee,s,1(hangup_handler)) start
-- Executing [s@logoutemployee:1] NoOp("Local/69@default-000000bb;2", "I am channel Local/69@default-000000bb;2 and and hangup_handler") in new stack
-- Executing [s@logoutemployee:2] Return("Local/69@default-000000bb;2", "") in new stack
== Spawn extension (newanswer, h, 2) exited non-zero on 'Local/69@default-000000bb;2'
-- Local/69@default-000000bb;2 Internal Gosub(logoutemployee,s,1(hangup_handler)) complete GOSUB_RETVAL=
== Spawn extension (newanswer, h, 2) exited non-zero on 'Local/69@default-000000bb;2'
-- Local/69@default-000000bb;2 Internal Gosub(kill-originated,s,1) complete GOSUB_RETVAL=
== MixMonitor close filestream (mixed)
== End MixMonitor Recording Local/69@default-000000bb;2
{noformat}

Scenario 3: Bridge command with MixMonitor, beep before MixMonitor
{noformat}
exten => s,1001,Set(CALLEDNUM=${SHARED(connecttocid)})
exten => s,1002,agi(googletts.agi,"Sie werden mit ${ADMIN-${SHARED(connecttoadminid)}-spokenfname} ${ADMIN-${SHARED(connecttoadminid)}-spokenlname} verbunden.",de,,1.4)
exten => s,1003,Set(CHANNEL(hangup_handler_push)=logoutemployee,s,1(hangup_handler))
exten => s,1004,Set(CHANNEL(after_bridge_goto)=logoutemployee,s,1(after_bridge))
exten => s,1005,Playback(beep)
exten => s,1006,MixMonitor(${STRFTIME(${EPOCH},,%Y%m%d-%H%M%S)}-${CALLERID(num)}-${CALLEDNUM}.wav)
exten => s,1007,Bridge(${SHARED(connecttochannel)},p)
exten => s,1008,Noop(here ${BRIDGEPEER})
exten => s,1009,Wait(5)
exten => s,1010,Hangup()
exten => h,1,Noop(in hangup)
{noformat}

{noformat}
-- Executing [s@newanswer:1001] Set("Local/69@default-000000c1;2", "CALLEDNUM=28") in new stack
-- Executing [s@newanswer:1002] AGI("Local/69@default-000000c1;2", "googletts.agi,"Sie werden mit Frédéric Steinfels verbunden.",de,,1.4") in new stack
-- Launched AGI Script /var/lib/asterisk/agi-bin/googletts.agi
-- <Local/69@default-000000c1;2> Playing '/data/Telefon/googletts//9c3c06da9e11b5448585f24c9285641b.1.4.slin16' (escape_digits=) (sample_offset 0) (language 'en')
-- <Local/69@default-000000c1;2>AGI Script googletts.agi completed, returning 0
-- Executing [s@newanswer:1003] Set("Local/69@default-000000c1;2", "CHANNEL(hangup_handler_push)=logoutemployee,s,1(hangup_handler)") in new stack
-- Executing [s@newanswer:1004] Set("Local/69@default-000000c1;2", "CHANNEL(after_bridge_goto)=logoutemployee,s,1(after_bridge)") in new stack
-- Executing [s@newanswer:1005] Playback("Local/69@default-000000c1;2", "beep") in new stack
-- <Local/69@default-000000c1;2> Playing 'beep.gsm' (language 'en')
-- Executing [s@newanswer:1006] MixMonitor("Local/69@default-000000c1;2", "20180502-003048-29-28.wav") in new stack
-- Executing [s@newanswer:1007] Bridge("Local/69@default-000000c1;2", "Local/28@default-000000c3;1,p") in new stack
== Begin MixMonitor Recording Local/69@default-000000c1;2
== Spawn extension (receptionist4, s, 16) exited non-zero on 'Surrogate/Local/28@default-000000c3;1'
-- Channel Local/28@default-000000c3;1 joined 'simple_bridge' basic-bridge <2702b6fb-41e5-4696-bc54-cd7312b0a68d>
-- Channel Local/69@default-000000c1;2 joined 'simple_bridge' basic-bridge <2702b6fb-41e5-4696-bc54-cd7312b0a68d>
-- <Local/28@default-000000c3;1> Playing 'beep.gsm' (language 'en')
> Move-swap optimizing Local/28@default-000000c3;1 <-- PJSIP/28-000000bf.
-- Channel PJSIP/28-000000bf left 'simple_bridge' basic-bridge <9078b1e8-0149-430b-acb2-3b351814be3d>
-- Channel Local/28@default-000000c3;1 left 'simple_bridge' basic-bridge <2702b6fb-41e5-4696-bc54-cd7312b0a68d>
-- Channel PJSIP/28-000000bf swapped with Local/28@default-000000c3;1 into 'simple_bridge' basic-bridge <2702b6fb-41e5-4696-bc54-cd7312b0a68d>
-- Channel Local/28@default-000000c3;2 left 'simple_bridge' basic-bridge <9078b1e8-0149-430b-acb2-3b351814be3d>
-- Executing [s@receptionist4:17] Playback("Local/28@default-000000c3;1", "beep") in new stack
== Spawn extension (local-sip-call, s, 11) exited non-zero on 'Local/28@default-000000c3;2'
-- <Local/28@default-000000c3;1> Playing 'beep.gsm' (language 'en')
{noformat}

when hanging up:
{noformat}
-- Channel PJSIP/mobile-000000bd left 'simple_bridge' basic-bridge <bf89b7d9-10af-4586-a6f7-fdc42444bcc9>
-- Channel Local/69@default-000000c1;1 left 'simple_bridge' basic-bridge <bf89b7d9-10af-4586-a6f7-fdc42444bcc9>
== Spawn extension (internal2local, s, 13) exited non-zero on 'PJSIP/mobile-000000bd'
-- Executing [s@logoutemployee:1] NoOp("Local/69@default-000000c1;1", "I am channel Local/69@default-000000c1;1 and and ") in new stack
-- Executing [s@logoutemployee:2] Return("Local/69@default-000000c1;1", "") in new stack
[May 2 00:30:53] ERROR[12280][C-00000042]: app_stack.c:389 return_exec: Return without Gosub: stack is unallocated
== Spawn extension (logoutemployee, s, 2) exited non-zero on 'Local/69@default-000000c1;1'
-- Channel Local/69@default-000000c1;2 left 'simple_bridge' basic-bridge <2702b6fb-41e5-4696-bc54-cd7312b0a68d>
-- Channel PJSIP/28-000000bf left 'simple_bridge' basic-bridge <2702b6fb-41e5-4696-bc54-cd7312b0a68d>
-- Executing [h@newanswer:1] NoOp("Local/69@default-000000c1;2", "in hangup") in new stack
-- Local/69@default-000000c1;2 Internal Gosub(logoutemployee,s,1(hangup_handler)) start
-- Executing [s@logoutemployee:1] NoOp("Local/69@default-000000c1;2", "I am channel Local/69@default-000000c1;2 and and hangup_handler") in new stack
-- Executing [s@logoutemployee:2] Return("Local/69@default-000000c1;2", "") in new stack
== Spawn extension (newanswer, h, 2) exited non-zero on 'Local/69@default-000000c1;2'
-- Local/69@default-000000c1;2 Internal Gosub(logoutemployee,s,1(hangup_handler)) complete GOSUB_RETVAL=
== Spawn extension (newanswer, h, 2) exited non-zero on 'Local/69@default-000000c1;2'
-- Local/69@default-000000c1;2 Internal Gosub(kill-originated,s,1) complete GOSUB_RETVAL=
== MixMonitor close filestream (mixed)
== End MixMonitor Recording Local/69@default-000000c1;2
{noformat}

I am seeing these errors/facts:
- In scenario 1, after_bridge_goto is not called at all
- In scenario 1, hangup_handler_push is called immediately after the Bridge command
- In scenario 1, h extension is not called at all
- In scenario 1, for some reason, the Beep command can not be played on one of the channels
- In scenario 2, after_bridge is ok
- In scenario 2, hangup_handler_push is ok
- In scenario 2, h extension is ok
- In scenario 2, mixmonitor file is too long and contains no audio except the beep
- In scenario 3, after_bridge is ok
- In scenario 3, hangup_handler_push is ok
- In scenario 3, h extension is ok
- In scenario 3, mixmonitor file is ok

Btw: The bridge command lacks various flags that the Queue and Dial command have like pre-bridge macros (M and U flags in the dial command).

Comments: By: Asterisk Team (asteriskteam) 2018-05-01 17:49:25.067-0500

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].
By: George Joseph (gjoseph) 2018-05-07 07:51:32.971-0500

Frederic, Can you reproduce this with 2 simple PJSIP channels? It's a little difficult trying to sort through your current examples. Step by step instructions on how we could reproduce the issue would help greatly.

By: Frederic Steinfels (fredo) 2018-05-07 09:11:49.775-0500

Hi. Ok, while refactoring this, I found out an important thing. If I do this
{noformat}
[internal]
exten => 66,1,Goto(newanswer,s,1)
{noformat}

Command bridge will behave as expected.

If I am using a local channel, the error will occur:
{noformat}
[internal]
exten => _6X,1,Dial(LOCAL/66@default,gr)

[default]
exten => 66,1,Goto(newanswer,s,1)
{noformat}

By: Frederic Steinfels (fredo) 2018-05-07 09:13:22.341-0500

{noformat}
-- Executing [s@newanswertest:1003] Set("Local/64@default-00000ace;2", "CHANNEL(hangup_handler_push)=logoutemployee,s,1(hangup_handler)") in new stack
-- Executing [s@newanswertest:1004] NoOp("Local/64@default-00000ace;2", "") in new stack
-- Executing [s@newanswertest:1005] Playback("Local/64@default-00000ace;2", "beep") in new stack
-- <Local/64@default-00000ace;2> Playing 'beep.gsm' (language 'en')
-- Executing [s@newanswertest:1006] NoOp("Local/64@default-00000ace;2", "") in new stack
-- Executing [s@newanswertest:1007] Bridge("Local/64@default-00000ace;2", "Local/22@default-00000acf;1,p") in new stack
== Spawn extension (receptionist4, s, 17) exited non-zero on 'Surrogate/Local/22@default-00000acf;1'
-- Channel Local/22@default-00000acf;1 joined 'simple_bridge' basic-bridge <ac512869-904d-4d20-a871-fdc29b96f192>
-- Channel Local/64@default-00000ace;2 joined 'simple_bridge' basic-bridge <ac512869-904d-4d20-a871-fdc29b96f192>
[May 7 16:05:49] WARNING[22759][C-000000a8]: file.c:1245 ast_streamfile: Unable to open beep (format (slin192)): No such file or directory
> Move-swap optimizing Local/64@default-00000ace;2 <-- PJSIP/28-00000341.
-- Channel PJSIP/28-00000341 left 'simple_bridge' basic-bridge <4186b79e-16fc-4fe6-bd2d-e8b7a21cd5c4>
-- Channel Local/64@default-00000ace;2 left 'simple_bridge' basic-bridge <ac512869-904d-4d20-a871-fdc29b96f192>
-- Channel PJSIP/28-00000341 swapped with Local/64@default-00000ace;2 into 'simple_bridge' basic-bridge <ac512869-904d-4d20-a871-fdc29b96f192>
-- Channel Local/64@default-00000ace;1 left 'simple_bridge' basic-bridge <4186b79e-16fc-4fe6-bd2d-e8b7a21cd5c4>
-- Auto fallthrough, channel 'Local/64@default-00000ace;2' status is 'UNKNOWN'
-- Local/64@default-00000ace;2 Internal Gosub(logoutemployee,s,1(hangup_handler)) start
-- Executing [s@logoutemployee:1] GotoIf("Local/64@default-00000ace;2", "0?2:3") in new stack
{noformat}
By: Benjamin Keith Ford (bford) 2018-05-08 16:17:51.857-0500

Hey Frederic, thanks for gathering a little more information. I think the next thing to do here is try to simplify the scenario down so that we can isolate the problem. Like George mentioned, can you trim your dialplan down to the minimum amount required to reproduce this issue? There's a lot going on in your examples, and this would help us to narrow the problem down so we can move forward with replicating the issue.
By: Benjamin Keith Ford (bford) 2018-05-11 14:20:10.181-0500

Moving the conversation back to here because if an issue is opened as an outcome from this report, the developer working on it will need all information.

From your dialplan, there's a lot going on. In particular, a lot of AGI scripts. If you can simplify this down to a basic dialplan scenario that can be easily reproduced by anyone, that will help us know whether or not it's a problem with your setup or if it's an underlying problem with Asterisk itself. Try to isolate the problem to as few lines as possible to see where the problem occurs. Comment out lines and remove AGI scripts. This way, you don't have to post information you don't want others to see. It will just be a very basic scenario that replicates your problem.
By: Frederic Steinfels (fredo) 2018-05-12 14:14:09.261-0500

Thanks to various feedback, I have decided to take the time to strip my example down. This second example does not verify "h" extension functionality but I assume you can easily test this. I think you can also experiment with the "beep" sample as described in my initial report.

Please also make sure you have the branch with the "a" flag in the originate command. This was added on my request. However the sample should also work without the "a" flag but I have not tested what will happen.

Dialling through local channel, not using mixmonitor. Both channels are executing the hangup handlers immediately on answer of child channel when they should not.
{noformat}
== Setting global variable 'SIPDOMAIN' to '192.168.99.10'
-- Executing [64@internal:1] Set("PJSIP/28-00000012", "CALLEDNUM=64") in new stack
-- Executing [64@internal:2] Dial("PJSIP/28-00000012", "Local/64@default,300,gr") in new stack
-- Called Local/64@default
-- Executing [64@default:1] Goto("Local/64@default-00000030;2", "astbugtest,s,1") in new stack
-- Goto (astbugtest,s,1)
-- Executing [s@astbugtest:1] Set("Local/64@default-00000030;2", "CHANNEL(hangup_handler_push)=astbugtestparenthanguphandler,s,1") in new stack
-- Executing [s@astbugtest:2] Set("Local/64@default-00000030;2", "ORIGINATECHANNELS=Local/29@default") in new stack
-- Executing [s@astbugtest:3] Originate("Local/64@default-00000030;2", "Local/29@default,exten,astbugchildchanneltest,s,1,3600,ab(astbugtest,new,1(Local/64@default-00000030;2))") in new stack
-- Local/29@default-00000031;1 Internal Gosub(astbugtest,new,1(Local/64@default-00000030;2)) start
-- Executing [new@astbugtest:1] Set("Local/29@default-00000031;1", "PARENTCHANNEL=Local/64@default-00000030;2") in new stack
[May 12 21:01:28] NOTICE[21838][C-00000006]: app_stack.c:1080 gosub_run: Local/29@default-00000031;1 Abnormal 'Gosub(astbugtest,new,1(Local/64@default-00000030;2))' exit. Popping routine return locations.
-- Called 29@default
-- Executing [29@default:1] Gosub("Local/29@default-00000031;2", "local-sip-call,s,1(29,mobile)") in new stack
-- Executing [s@local-sip-call:1] Set("Local/29@default-00000031;2", "CALLEDNUM=29") in new stack
-- Executing [s@local-sip-call:2] ChanIsAvail("Local/29@default-00000031;2", "PJSIP/mobile,s") in new stack
-- Executing [s@astbugtest:4] Wait("Local/64@default-00000030;2", "3600") in new stack
-- Executing [s@local-sip-call:3] NoOp("Local/29@default-00000031;2", "1 0") in new stack
-- Executing [s@local-sip-call:4] GotoIf("Local/29@default-00000031;2", "0?11:5") in new stack
-- Goto (local-sip-call,s,5)
-- Executing [s@local-sip-call:5] GotoIf("Local/29@default-00000031;2", "0?11:6") in new stack
-- Goto (local-sip-call,s,6)
-- Executing [s@local-sip-call:6] GotoIf("Local/29@default-00000031;2", "1?11:7") in new stack
-- Goto (local-sip-call,s,11)
-- Executing [s@local-sip-call:11] Dial("Local/29@default-00000031;2", "PJSIP/mobile") in new stack
-- Called PJSIP/mobile
-- PJSIP/mobile-00000014 is ringing
-- Local/29@default-00000031;1 is ringing
-- PJSIP/mobile-00000014 answered Local/29@default-00000031;2
-- Local/29@default-00000031;1 answered
-- Executing [s@astbugchildchanneltest:1] Set("Local/29@default-00000031;1", "CHANNEL(hangup_handler_push)=astbugtestchildhanguphandler,s,1") in new stack
-- Channel PJSIP/mobile-00000014 joined 'simple_bridge' basic-bridge <000e21c1-05e1-4fa4-8046-afcfac638ef8>
-- Channel Local/29@default-00000031;2 joined 'simple_bridge' basic-bridge <000e21c1-05e1-4fa4-8046-afcfac638ef8>
-- Executing [s@astbugchildchanneltest:2] Set("Local/29@default-00000031;1", "SHARED(connecttochannel,Local/64@default-00000030;2)=Local/29@default-00000031;1") in new stack
-- Executing [s@astbugchildchanneltest:3] ChannelRedirect("Local/29@default-00000031;1", "Local/64@default-00000030;2,astbugtest,s,1000") in new stack
== Spawn extension (astbugtest, s, 1000) exited non-zero on 'Local/64@default-00000030;2'
-- Executing [s@astbugtest:1000] NoOp("Local/64@default-00000030;2", "Child channel has redirected me") in new stack
-- Executing [s@astbugchildchanneltest:4] Wait("Local/29@default-00000031;1", "1000") in new stack
-- Executing [s@astbugtest:1001] Playback("Local/64@default-00000030;2", "beep") in new stack
-- Local/64@default-00000030;1 answered PJSIP/28-00000012
-- Channel Local/64@default-00000030;1 joined 'simple_bridge' basic-bridge <ab2a194c-e6f3-4909-a7bb-f77a88f8e37a>
-- Channel PJSIP/28-00000012 joined 'simple_bridge' basic-bridge <ab2a194c-e6f3-4909-a7bb-f77a88f8e37a>
-- <Local/64@default-00000030;2> Playing 'beep.gsm' (language 'en')
-- Executing [s@astbugtest:1002] NoOp("Local/64@default-00000030;2", "") in new stack
-- Executing [s@astbugtest:1003] Bridge("Local/64@default-00000030;2", "Local/29@default-00000031;1,p") in new stack
== Spawn extension (astbugchildchanneltest, s, 4) exited non-zero on 'Surrogate/Local/29@default-00000031;1'
-- Channel Local/29@default-00000031;1 joined 'simple_bridge' basic-bridge <ad5ea4aa-8223-414a-aa3d-80b8038e895d>
-- Channel Local/64@default-00000030;2 joined 'simple_bridge' basic-bridge <ad5ea4aa-8223-414a-aa3d-80b8038e895d>
-- <Local/29@default-00000031;1> Playing 'beep.gsm' (language 'en')
> Move-swap optimizing Local/64@default-00000030;2 <-- PJSIP/28-00000012.
-- Channel PJSIP/28-00000012 left 'simple_bridge' basic-bridge <ab2a194c-e6f3-4909-a7bb-f77a88f8e37a>
-- Channel Local/64@default-00000030;2 left 'simple_bridge' basic-bridge <ad5ea4aa-8223-414a-aa3d-80b8038e895d>
-- Channel PJSIP/28-00000012 swapped with Local/64@default-00000030;2 into 'simple_bridge' basic-bridge <ad5ea4aa-8223-414a-aa3d-80b8038e895d>
-- Channel Local/64@default-00000030;1 left 'simple_bridge' basic-bridge <ab2a194c-e6f3-4909-a7bb-f77a88f8e37a>
-- Executing [s@astbugtest:1004] Wait("Local/64@default-00000030;2", "5") in new stack
== Spawn extension (astbugtest, s, 1004) exited non-zero on 'Local/64@default-00000030;2'
-- Local/64@default-00000030;2 Internal Gosub(astbugtestparenthanguphandler,s,1) start
-- Executing [s@astbugtestparenthanguphandler:1] NoOp("Local/64@default-00000030;2", "============== Parent channel hung up") in new stack
-- Executing [s@astbugtestparenthanguphandler:2] Return("Local/64@default-00000030;2", "") in new stack
== Spawn extension (astbugtest, s, 1004) exited non-zero on 'Local/64@default-00000030;2'
-- Local/64@default-00000030;2 Internal Gosub(astbugtestparenthanguphandler,s,1) complete GOSUB_RETVAL=
> Move-swap optimizing Local/29@default-00000031;1 <-- PJSIP/mobile-00000014.
-- Channel PJSIP/mobile-00000014 left 'simple_bridge' basic-bridge <000e21c1-05e1-4fa4-8046-afcfac638ef8>
-- Channel Local/29@default-00000031;1 left 'simple_bridge' basic-bridge <ad5ea4aa-8223-414a-aa3d-80b8038e895d>
-- Channel PJSIP/mobile-00000014 swapped with Local/29@default-00000031;1 into 'simple_bridge' basic-bridge <ad5ea4aa-8223-414a-aa3d-80b8038e895d>
> Bridge ad5ea4aa-8223-414a-aa3d-80b8038e895d: switching from simple_bridge technology to native_rtp
> Remotely bridged 'PJSIP/mobile-00000014' and 'PJSIP/28-00000012' - media will flow directly between them
-- Channel Local/29@default-00000031;2 left 'simple_bridge' basic-bridge <000e21c1-05e1-4fa4-8046-afcfac638ef8>
== Spawn extension (local-sip-call, s, 11) exited non-zero on 'Local/29@default-00000031;2'
-- Local/29@default-00000031;1 Internal Gosub(astbugtestchildhanguphandler,s,1) start
-- Executing [s@astbugtestchildhanguphandler:1] NoOp("Local/29@default-00000031;1", "============== Child channel hung up") in new stack
-- Executing [s@astbugtestchildhanguphandler:2] Return("Local/29@default-00000031;1", "") in new stack
== Spawn extension (astbugchildchanneltest, s, 5) exited non-zero on 'Local/29@default-00000031;1'
-- Local/29@default-00000031;1 Internal Gosub(astbugtestchildhanguphandler,s,1) complete GOSUB_RETVAL=
{noformat}

With mixmonitor, child hangup handler is being executed on answer when it should not. Parent hangup handler is not executed which is correct.
{noformat}
== Setting global variable 'SIPDOMAIN' to '192.168.99.10'
-- Executing [64@internal:1] Set("PJSIP/28-00000015", "CALLEDNUM=64") in new stack
-- Executing [64@internal:2] Dial("PJSIP/28-00000015", "Local/64@default,300,gr") in new stack
-- Called Local/64@default
-- Executing [64@default:1] Goto("Local/64@default-00000032;2", "astbugtest,s,1") in new stack
-- Goto (astbugtest,s,1)
-- Executing [s@astbugtest:1] Set("Local/64@default-00000032;2", "CHANNEL(hangup_handler_push)=astbugtestparenthanguphandler,s,1") in new stack
-- Executing [s@astbugtest:2] Set("Local/64@default-00000032;2", "ORIGINATECHANNELS=Local/29@default") in new stack
-- Executing [s@astbugtest:3] Originate("Local/64@default-00000032;2", "Local/29@default,exten,astbugchildchanneltest,s,1,3600,ab(astbugtest,new,1(Local/64@default-00000032;2))") in new stack
-- Local/29@default-00000033;1 Internal Gosub(astbugtest,new,1(Local/64@default-00000032;2)) start
-- Executing [new@astbugtest:1] Set("Local/29@default-00000033;1", "PARENTCHANNEL=Local/64@default-00000032;2") in new stack
[May 12 21:07:47] NOTICE[26818][C-00000007]: app_stack.c:1080 gosub_run: Local/29@default-00000033;1 Abnormal 'Gosub(astbugtest,new,1(Local/64@default-00000032;2))' exit. Popping routine return locations.
-- Called 29@default
-- Executing [29@default:1] Gosub("Local/29@default-00000033;2", "local-sip-call,s,1(29,mobile)") in new stack
-- Executing [s@local-sip-call:1] Set("Local/29@default-00000033;2", "CALLEDNUM=29") in new stack
-- Executing [s@local-sip-call:2] ChanIsAvail("Local/29@default-00000033;2", "PJSIP/mobile,s") in new stack
-- Executing [s@astbugtest:4] Wait("Local/64@default-00000032;2", "3600") in new stack
-- Executing [s@local-sip-call:3] NoOp("Local/29@default-00000033;2", "1 0") in new stack
-- Executing [s@local-sip-call:4] GotoIf("Local/29@default-00000033;2", "0?11:5") in new stack
-- Goto (local-sip-call,s,5)
-- Executing [s@local-sip-call:5] GotoIf("Local/29@default-00000033;2", "0?11:6") in new stack
-- Goto (local-sip-call,s,6)
-- Executing [s@local-sip-call:6] GotoIf("Local/29@default-00000033;2", "1?11:7") in new stack
-- Goto (local-sip-call,s,11)
-- Executing [s@local-sip-call:11] Dial("Local/29@default-00000033;2", "PJSIP/mobile") in new stack
-- Called PJSIP/mobile
-- PJSIP/mobile-00000017 is ringing
-- Local/29@default-00000033;1 is ringing
-- PJSIP/mobile-00000017 answered Local/29@default-00000033;2
-- Local/29@default-00000033;1 answered
-- Executing [s@astbugchildchanneltest:1] Set("Local/29@default-00000033;1", "CHANNEL(hangup_handler_push)=astbugtestchildhanguphandler,s,1") in new stack
-- Executing [s@astbugchildchanneltest:2] Set("Local/29@default-00000033;1", "SHARED(connecttochannel,Local/64@default-00000032;2)=Local/29@default-00000033;1") in new stack
-- Executing [s@astbugchildchanneltest:3] ChannelRedirect("Local/29@default-00000033;1", "Local/64@default-00000032;2,astbugtest,s,1000") in new stack
== Spawn extension (astbugtest, s, 1000) exited non-zero on 'Local/64@default-00000032;2'
-- Executing [s@astbugchildchanneltest:4] Wait("Local/29@default-00000033;1", "1000") in new stack
-- Executing [s@astbugtest:1000] NoOp("Local/64@default-00000032;2", "Child channel has redirected me") in new stack
-- Executing [s@astbugtest:1001] Playback("Local/64@default-00000032;2", "beep") in new stack
-- Local/64@default-00000032;1 answered PJSIP/28-00000015
-- Channel PJSIP/mobile-00000017 joined 'simple_bridge' basic-bridge <072abc15-faed-48ed-b790-792e2828fd1b>
-- Channel Local/29@default-00000033;2 joined 'simple_bridge' basic-bridge <072abc15-faed-48ed-b790-792e2828fd1b>
-- Channel Local/64@default-00000032;1 joined 'simple_bridge' basic-bridge <7736c840-a1fd-462d-94b5-efdb1f5ab1cb>
-- Channel PJSIP/28-00000015 joined 'simple_bridge' basic-bridge <7736c840-a1fd-462d-94b5-efdb1f5ab1cb>
-- <Local/64@default-00000032;2> Playing 'beep.gsm' (language 'en')
-- Executing [s@astbugtest:1002] MixMonitor("Local/64@default-00000032;2", "test.wav") in new stack
== Begin MixMonitor Recording Local/64@default-00000032;2
-- Executing [s@astbugtest:1003] Bridge("Local/64@default-00000032;2", "Local/29@default-00000033;1,p") in new stack
== Spawn extension (astbugchildchanneltest, s, 4) exited non-zero on 'Surrogate/Local/29@default-00000033;1'
-- Channel Local/29@default-00000033;1 joined 'simple_bridge' basic-bridge <f69504a1-426e-4b23-bfbf-852c5d485eeb>
-- Channel Local/64@default-00000032;2 joined 'simple_bridge' basic-bridge <f69504a1-426e-4b23-bfbf-852c5d485eeb>
-- <Local/29@default-00000033;1> Playing 'beep.slin192' (language 'en')
> Move-swap optimizing Local/29@default-00000033;1 <-- PJSIP/mobile-00000017.
-- Channel PJSIP/mobile-00000017 left 'simple_bridge' basic-bridge <072abc15-faed-48ed-b790-792e2828fd1b>
-- Channel Local/29@default-00000033;1 left 'simple_bridge' basic-bridge <f69504a1-426e-4b23-bfbf-852c5d485eeb>
-- Channel PJSIP/mobile-00000017 swapped with Local/29@default-00000033;1 into 'simple_bridge' basic-bridge <f69504a1-426e-4b23-bfbf-852c5d485eeb>
-- Channel Local/29@default-00000033;2 left 'simple_bridge' basic-bridge <072abc15-faed-48ed-b790-792e2828fd1b>
-- Local/29@default-00000033;1 Internal Gosub(astbugtestchildhanguphandler,s,1) start
-- Executing [s@astbugtestchildhanguphandler:1] NoOp("Local/29@default-00000033;1", "============== Child channel hung up") in new stack
-- Executing [s@astbugtestchildhanguphandler:2] Return("Local/29@default-00000033;1", "") in new stack
== Spawn extension (astbugchildchanneltest, s, 5) exited non-zero on 'Local/29@default-00000033;1'
-- Local/29@default-00000033;1 Internal Gosub(astbugtestchildhanguphandler,s,1) complete GOSUB_RETVAL=
== Spawn extension (local-sip-call, s, 11) exited non-zero on 'Local/29@default-00000033;2'
{noformat}

when using goto instead of dialling a local channel, the parent channel is not hung up immediately on answer with or without mixmonitor. however child channel is hung up immediately anyway
{noformat}
== Setting global variable 'SIPDOMAIN' to '192.168.99.10'
-- Executing [64@internal:1] Set("PJSIP/28-00000018", "CALLEDNUM=64") in new stack
-- Executing [64@internal:2] Goto("PJSIP/28-00000018", "astbugtest,s,1") in new stack
-- Goto (astbugtest,s,1)
-- Executing [s@astbugtest:1] Set("PJSIP/28-00000018", "CHANNEL(hangup_handler_push)=astbugtestparenthanguphandler,s,1") in new stack
-- Executing [s@astbugtest:2] Set("PJSIP/28-00000018", "ORIGINATECHANNELS=Local/29@default") in new stack
-- Executing [s@astbugtest:3] Originate("PJSIP/28-00000018", "Local/29@default,exten,astbugchildchanneltest,s,1,3600,ab(astbugtest,new,1(PJSIP/28-00000018))") in new stack
-- Local/29@default-00000034;1 Internal Gosub(astbugtest,new,1(PJSIP/28-00000018)) start
-- Executing [new@astbugtest:1] Set("Local/29@default-00000034;1", "PARENTCHANNEL=PJSIP/28-00000018") in new stack
[May 12 21:10:44] NOTICE[29106][C-00000008]: app_stack.c:1080 gosub_run: Local/29@default-00000034;1 Abnormal 'Gosub(astbugtest,new,1(PJSIP/28-00000018))' exit. Popping routine return locations.
-- Called 29@default
-- Executing [29@default:1] Gosub("Local/29@default-00000034;2", "local-sip-call,s,1(29,mobile)") in new stack
-- Executing [s@local-sip-call:1] Set("Local/29@default-00000034;2", "CALLEDNUM=29") in new stack
-- Executing [s@local-sip-call:2] ChanIsAvail("Local/29@default-00000034;2", "PJSIP/mobile,s") in new stack
-- Executing [s@astbugtest:4] Wait("PJSIP/28-00000018", "3600") in new stack
-- Executing [s@local-sip-call:3] NoOp("Local/29@default-00000034;2", "1 0") in new stack
-- Executing [s@local-sip-call:4] GotoIf("Local/29@default-00000034;2", "0?11:5") in new stack
-- Goto (local-sip-call,s,5)
-- Executing [s@local-sip-call:5] GotoIf("Local/29@default-00000034;2", "0?11:6") in new stack
-- Goto (local-sip-call,s,6)
-- Executing [s@local-sip-call:6] GotoIf("Local/29@default-00000034;2", "1?11:7") in new stack
-- Goto (local-sip-call,s,11)
-- Executing [s@local-sip-call:11] Dial("Local/29@default-00000034;2", "PJSIP/mobile") in new stack
-- Called PJSIP/mobile
-- PJSIP/mobile-0000001a is ringing
-- Local/29@default-00000034;1 is ringing
-- PJSIP/mobile-0000001a answered Local/29@default-00000034;2
-- Local/29@default-00000034;1 answered
-- Executing [s@astbugchildchanneltest:1] Set("Local/29@default-00000034;1", "CHANNEL(hangup_handler_push)=astbugtestchildhanguphandler,s,1") in new stack
-- Channel PJSIP/mobile-0000001a joined 'simple_bridge' basic-bridge <74173f50-98cc-473c-a614-0cdbb5dae8f3>
-- Executing [s@astbugchildchanneltest:2] Set("Local/29@default-00000034;1", "SHARED(connecttochannel,PJSIP/28-00000018)=Local/29@default-00000034;1") in new stack
-- Channel Local/29@default-00000034;2 joined 'simple_bridge' basic-bridge <74173f50-98cc-473c-a614-0cdbb5dae8f3>
-- Executing [s@astbugchildchanneltest:3] ChannelRedirect("Local/29@default-00000034;1", "PJSIP/28-00000018,astbugtest,s,1000") in new stack
== Spawn extension (astbugtest, s, 1000) exited non-zero on 'PJSIP/28-00000018'
-- Executing [s@astbugtest:1000] NoOp("PJSIP/28-00000018", "Child channel has redirected me") in new stack
-- Executing [s@astbugchildchanneltest:4] Wait("Local/29@default-00000034;1", "1000") in new stack
-- Executing [s@astbugtest:1001] Playback("PJSIP/28-00000018", "beep") in new stack
-- <PJSIP/28-00000018> Playing 'beep.gsm' (language 'en')
-- Executing [s@astbugtest:1002] NoOp("PJSIP/28-00000018", "") in new stack
-- Executing [s@astbugtest:1003] Bridge("PJSIP/28-00000018", "Local/29@default-00000034;1,p") in new stack
== Spawn extension (astbugchildchanneltest, s, 4) exited non-zero on 'Surrogate/Local/29@default-00000034;1'
-- Channel Local/29@default-00000034;1 joined 'simple_bridge' basic-bridge <2f138631-1852-4983-a179-58908ac338c8>
-- Channel PJSIP/28-00000018 joined 'simple_bridge' basic-bridge <2f138631-1852-4983-a179-58908ac338c8>
[May 12 21:10:49] WARNING[29156][C-00000008]: file.c:1245 ast_streamfile: Unable to open beep (format (slin192)): No such file or directory
> Move-swap optimizing Local/29@default-00000034;2 <-- PJSIP/28-00000018.
-- Channel PJSIP/28-00000018 left 'simple_bridge' basic-bridge <2f138631-1852-4983-a179-58908ac338c8>
-- Channel Local/29@default-00000034;2 left 'simple_bridge' basic-bridge <74173f50-98cc-473c-a614-0cdbb5dae8f3>
-- Channel PJSIP/28-00000018 swapped with Local/29@default-00000034;2 into 'simple_bridge' basic-bridge <74173f50-98cc-473c-a614-0cdbb5dae8f3>
> Bridge 74173f50-98cc-473c-a614-0cdbb5dae8f3: switching from simple_bridge technology to native_rtp
> Remotely bridged 'PJSIP/28-00000018' and 'PJSIP/mobile-0000001a' - media will flow directly between them
-- Channel Local/29@default-00000034;1 left 'simple_bridge' basic-bridge <2f138631-1852-4983-a179-58908ac338c8>
-- Local/29@default-00000034;1 Internal Gosub(astbugtestchildhanguphandler,s,1) start
-- Executing [s@astbugtestchildhanguphandler:1] NoOp("Local/29@default-00000034;1", "============== Child channel hung up") in new stack
-- Executing [s@astbugtestchildhanguphandler:2] Return("Local/29@default-00000034;1", "") in new stack
== Spawn extension (astbugchildchanneltest, s, 5) exited non-zero on 'Local/29@default-00000034;1'
-- Local/29@default-00000034;1 Internal Gosub(astbugtestchildhanguphandler,s,1) complete GOSUB_RETVAL=
== Spawn extension (local-sip-call, s, 11) exited non-zero on 'Local/29@default-00000034;2'
{noformat}

and finally the nice little dialplan
{noformat}
[internal]
exten => 64,1,Set(CALLEDNUM=${EXTEN})
exten => 64,n,Goto(astbugtest,s,1)
{noformat}
or
{noformat}
[internal]
exten => 64,1,Set(CALLEDNUM=${EXTEN})
exten => 64,n,Dial(Local/64@default,300,gr)
{noformat}

{noformat}
[astbugtestparenthanguphandler]
exten => s,1,Noop(============== Parent channel hung up)
exten => s,2,Return()

[astbugtestchildhanguphandler]
exten => s,1,Noop(============== Child channel hung up)
exten => s,2,Return()

[astbugtest]
exten => s,1,Set(CHANNEL(hangup_handler_push)=astbugtestparenthanguphandler,s,1)
exten => s,2,Set(ORIGINATECHANNELS=Local/29@default)
exten => s,3,Originate(Local/29@default,exten,astbugchildchanneltest,s,1,3600,ab(astbugtest,new,1(${CHANNEL})))
exten => s,4,Wait(3600)

exten => new,1,Set(PARENTCHANNEL=${ARG1})

exten => s,1000,Noop(Child channel has redirected me)
exten => s,1001,Playback(beep)
;exten => s,1002,MixMonitor(test.wav)
exten => s,1002,Noop()
exten => s,1003,Bridge(${SHARED(connecttochannel)},p)
exten => s,1004,Wait(5)
exten => s,1005,Hangup()

[astbugchildchanneltest]
exten => s,1,Set(CHANNEL(hangup_handler_push)=astbugtestchildhanguphandler,s,1)
exten => s,2,Set(SHARED(connecttochannel,${PARENTCHANNEL})=${CHANNEL})
exten => s,3,ChannelRedirect(${PARENTCHANNEL},astbugtest,s,1000)
exten => s,4,Wait(1000)

[default]
exten => 29,1,GoSub(local-sip-call,s,1(${EXTEN},mobile))

[local-sip-call]
exten => s,1,Set(CALLEDNUM=${ARG1})
exten => s,2,ChanIsAvail(${SIPCHAN}/${ARG2},s)
exten => s,3,Noop(${AVAILSTATUS} ${AVAILCAUSECODE})
exten => s,4,GotoIf($[${LEN(${AVAILSTATUS})}=0]?11:5)
exten => s,5,GotoIf($[${AVAILSTATUS}=0]?11:6)
exten => s,6,GotoIf($[${AVAILSTATUS}=1]?11:7)
exten => s,7,GotoIf($[${AVAILSTATUS}=2]?11:8)
exten => s,8,GotoIf($[${AVAILSTATUS}=3]?11:9)
exten => s,9,GotoIf($[${AVAILSTATUS}=7]?11:10)
exten => s,10,GotoIf($[${AVAILSTATUS}=8]?11:12)
exten => s,11,Dial(${SIPCHAN}/${ARG2})
exten => s,12,Return()
{noformat}

By: Richard Mudgett (rmudgett) 2018-05-29 15:38:57.657-0500

I am not seeing any bugs in this issue. Asterisk is behaving as expected.

{quote}
I am seeing these errors/facts:
- In scenario 1, after_bridge_goto is not called at all
- In scenario 1, hangup_handler_push is called immediately after the Bridge command
- In scenario 1, h extension is not called at all
- In scenario 1, for some reason, the Beep command can not be played on one of the channels
- In scenario 2, after_bridge is ok
- In scenario 2, hangup_handler_push is ok
- In scenario 2, h extension is ok
- In scenario 2, mixmonitor file is too long and contains no audio except the beep
- In scenario 3, after_bridge is ok
- In scenario 3, hangup_handler_push is ok
- In scenario 3, h extension is ok
- In scenario 3, mixmonitor file is ok
{quote}

In scenario 1
- The after_bridge_goto does not execute because the local channel you attached it to optimized out and hung up as a result.
- You attached the hangup handler to the optimizing local channel that optimized itself out of the call when the call answered. Thus it optimized out, hung up, and executed the hangup handler you attached to it.
- The h exten was run on the optimized out local channel that hung up. I cannot say anything about which PJSIP channel you expected to execute the h exten but there is likely no h exten in the context where the non-local channels last executed dialplan.
- I cannot say why the beep didn't play other than local channels assume the codecs of the initiating channel. If they haven't been determined yet then the local channel has all codecs available.

In scenario 2
- You still have the after_bridge_goto and hangup handler associated with the local channel.
- The mixmonitor you attached to the local channel prevents the local channel from optimizing out. Thus things executed as you expected but not for the reasons you thought.
- I don't know why the mixmonitor file is "large". Did you take awhile to hanging up the call?

The simplified examples you added on May 12, 2018 are showing the same thing.

In the first log fragment you attach the hangup handlers \[1] to optimizing local channels that optimize themselves out of the call. An optimizing local channel will extract itself from a call when the call is answered and it is not prevented from optimizing out. Any state you have associated with the local channel will also disappear when the local channel optimizes out.

In the second log fragment, the "parent" channel is prevented from optimizing out because you attached MixMonitor. The child hangup handler is executing because the "child" local channel is able to optimize itself out.

In the third log fragment the "parent" channel is not a local channel but a channel to outside asterisk so it must stay around for the entire call. The "child" channel is still a local channel.

Your dialplan is written assuming that local channels will not optimize themselves out when you have not used the {{/n}} local channel modifier. You need to read about local channels \[2]. You especially need to understand local channel optimization and the local channel modifiers available. I'd also recommend reading the Asterisk book \[3].

\[1] https://wiki.asterisk.org/wiki/display/AST/Hangup+Handlers
\[2] https://wiki.asterisk.org/wiki/display/AST/Local+Channel
\[3] Asterisk: The Definitive Guide, 4th Edition (ISBN 1-4493-3242-0) available at http://oreilly.com/catalog/0636920025894 - Asterisk: The Definitive Guide is released under a Creative Commons License (http://creativecommons.org/licenses/by-nc-nd/3.0/us/) and a version is available for reading online at http://www.asteriskdocs.org/

By: Frederic Steinfels (fredo) 2018-06-07 05:04:40.801-0500

I understand how you mean that but unfortunately it does not make any sense in practical terms. Hangup handlers are called hangup handler because they are called when a call is hung up. They should not be called when local channels are optimized away. The optimization routine should move the hangup handler to the new channel. I consider this a bug in the channel optimzation code.
By: Asterisk Team (asteriskteam) 2018-06-07 05:04:41.521-0500

This issue has been reopened as a result of your commenting on it as the reporter. It will be triaged once again as applicable.
By: Richard Mudgett (rmudgett) 2018-06-07 06:29:24.718-0500

The hangup handlers are working AS DESIGNED. The local channels are hanging up when they are optimized out. It is you who has the wrong idea of how to use them. Asterisk has *no* internal concept of what a call is.