[Home]

Summary:ASTERISK-24027: MixMonitor AMI action called during AGI execution from bridge feature causes channel to leave AGI has hung up
Reporter:Matt Jordan (mjordan)Labels:
Date Opened:2014-07-11 12:34:59Date Closed:2014-08-13 10:23:05
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Applications/app_mixmonitor Resources/res_agi
Versions:12.4.0 Frequency of
Occurrence
Related
Issues:
is related toASTERISK-24195 bridge_native_rtp: Removing mixmonitor from a native RTP capable smart bridge doesn't cause the bridge to resume being a native rtp bridge
Environment:Attachments:
Description:MixMonitor has a check in it that, when applied to a channel, determines if the channel is in a bridge and, if it is, sets the UNBRIDGE soft hangup flag. This is the bridging framework's sign that it needs to check the state of the world.

Unfortunately, res_agi decides this means that the channel has hung up, kills the AGI, and terminates the whole thing.

{code}
[1404943348] DEBUG[10460]: autochan.c:58 ast_autochan_setup: Created autochan 0xb4b96c30 to hold channel PJSIP/201-00000042 (0xb4bf6a04)
[1404943348] DEBUG[10460]: channel.c:2597 ast_softhangup_nolock: Soft-Hanging (0x40) up channel 'PJSIP/201-00000042'
[1404943348] DEBUG[31077][C-00000018]: res_agi.c:3809 run_agi: PJSIP/201-00000042 hungup
<PJSIP/201-00000042>AGI Tx >> HANGUP
{code}

You should be able to run the MixMonitor AMI action on a channel that is in an AGI called from a bridge feature and not have it hang up.
Comments:By: Michael L. Young (elguero) 2014-07-16 18:33:58.213-0500

It would appear that this also affects starting MixMonitor using Dynamic Features.

{noformat}
[Jul 16 19:22:07] DEBUG[29099][C-00000002]: bridge_channel.c:1543 bridge_channel_feature: DTMF feature string on 0x7f19c40029a8(SIP/6002-00000004) is now '*91'
[Jul 16 19:22:07] DEBUG[29099][C-00000002]: bridge_channel.c:1554 bridge_channel_feature: DTMF feature hook 0x7f19c40026e0 matched DTMF string '*91' on 0x7f19c40029a8(SIP/6002-00000004)
[Jul 16 19:22:07] DEBUG[29099][C-00000002]: autochan.c:58 ast_autochan_setup: Created autochan 0x7f19c4016090 to hold channel SIP/6002-00000004 (0x7f19bc015498)
[Jul 16 19:22:07] DEBUG[29099][C-00000002]: channel.c:2597 ast_softhangup_nolock: Soft-Hanging (0x40) up channel 'SIP/6002-00000004'
[Jul 16 19:22:07] DEBUG[29099][C-00000002]: bridge_channel.c:288 ast_bridge_channel_leave_bridge_nolock: Setting 0x7f19c40029a8(SIP/6002-00000004) state from:0 to:1
[Jul 16 19:22:07] DEBUG[29099][C-00000002]: bridge_channel.c:1880 bridge_channel_internal_pull: Bridge bd67a29d-3534-40dd-bde1-dd9d6ac3b2f8: pulling 0x7f19c40029a8(SIP/6002-00000004)
   -- Channel SIP/6002-00000004 left 'simple_bridge' basic-bridge <bd67a29d-3534-40dd-bde1-dd9d6ac3b2f8>
[Jul 16 19:22:07] DEBUG[29099][C-00000002]: bridge_channel.c:1892 bridge_channel_internal_pull: Bridge bd67a29d-3534-40dd-bde1-dd9d6ac3b2f8: 0x7f19c40029a8(SIP/6002-00000004) is leaving simple_bridge technology
[Jul 16 19:22:07] DEBUG[29099][C-00000002]: bridge.c:311 bridge_dissolve: Bridge bd67a29d-3534-40dd-bde1-dd9d6ac3b2f8: dissolving bridge with cause 16(Normal Clearing)
[Jul 16 19:22:07] DEBUG[29099][C-00000002]: bridge_channel.c:288 ast_bridge_channel_leave_bridge_nolock: Setting 0x7f19c4016a78(SIP/6003-00000005) state from:0 to:2
[Jul 16 19:22:07] DEBUG[29099][C-00000002]: bridge.c:272 bridge_queue_action_nodup: Bridge bd67a29d-3534-40dd-bde1-dd9d6ac3b2f8: queueing action type:13 sub:1001
[Jul 16 19:22:07] DEBUG[28966]: cdr.c:1267 cdr_object_finalize: Finalized CDR for SIP/6002-00000004 - start 1405552920.554139 answer 1405552922.439876 end 1405552927.332988 dispo ANSWERED
[Jul 16 19:22:07] DEBUG[29099][C-00000002]: bridge.c:1030 smart_bridge_operation: Bridge bd67a29d-3534-40dd-bde1-dd9d6ac3b2f8 is dissolved, not performing smart bridge operation.
[Jul 16 19:22:07] DEBUG[29100][C-00000002]: bridge_channel.c:1880 bridge_channel_internal_pull: Bridge bd67a29d-3534-40dd-bde1-dd9d6ac3b2f8: pulling 0x7f19c4016a78(SIP/6003-00000005)
   -- Channel SIP/6003-00000005 left 'simple_bridge' basic-bridge <bd67a29d-3534-40dd-bde1-dd9d6ac3b2f8>
[Jul 16 19:22:07] DEBUG[29100][C-00000002]: bridge_channel.c:1892 bridge_channel_internal_pull: Bridge bd67a29d-3534-40dd-bde1-dd9d6ac3b2f8: 0x7f19c4016a78(SIP/6003-00000005) is leaving simple_bridge technology
[Jul 16 19:22:07] DEBUG[29100][C-00000002]: bridge.c:1030 smart_bridge_operation: Bridge bd67a29d-3534-40dd-bde1-dd9d6ac3b2f8 is dissolved, not performing smart bridge operation.
[Jul 16 19:22:07] DEBUG[29100][C-00000002]: res_rtp_asterisk.c:2524 ast_rtp_change_source: Changing ssrc from 308471819 to 99570149 due to a source change
[Jul 16 19:22:07] DEBUG[29100][C-00000002]: channel.c:2753 ast_hangup: Hanging up channel 'SIP/6003-00000005'
[Jul 16 19:22:07] DEBUG[29100][C-00000002]: chan_sip.c:7147 sip_hangup: Hangup call SIP/6003-00000005, SIP callid 7d6d273c342565d61afda399424631b1@192.168.23.140:5060
[Jul 16 19:22:07] DEBUG[29100][C-00000002]: res_rtp_asterisk.c:4375 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f19c400a2a8'
[Jul 16 19:22:07] DEBUG[29100][C-00000002]: chan_sip.c:3921 __sip_xmit: Trying to put 'BYE sip:600' onto UDP socket destined for 192.168.23.128:62898
[Jul 16 19:22:07] DEBUG[28964]: chan_sip.c:29441 sip_devicestate: Checking device state for peer 6003
[Jul 16 19:22:07] DEBUG[28964]: devicestate.c:462 do_state_change: Changing state for SIP/6003 - state 1 (Not in use)
[Jul 16 19:22:07] DEBUG[28966]: cdr.c:1095 cdr_object_create_public_records: CDR for SIP/6003-00000005 is dialed and has no Party B; discarding
[Jul 16 19:22:07] DEBUG[29099][C-00000002]: bridge.c:634 destroy_bridge: Bridge bd67a29d-3534-40dd-bde1-dd9d6ac3b2f8: actually destroying basic bridge, nobody wants it anymore
[Jul 16 19:22:07] DEBUG[29099][C-00000002]: bridge.c:659 destroy_bridge: Bridge bd67a29d-3534-40dd-bde1-dd9d6ac3b2f8: calling basic bridge destructor
[Jul 16 19:22:07] DEBUG[29099][C-00000002]: bridge.c:665 destroy_bridge: Bridge bd67a29d-3534-40dd-bde1-dd9d6ac3b2f8: calling simple_bridge technology stop
[Jul 16 19:22:07] DEBUG[29099][C-00000002]: bridge.c:672 destroy_bridge: Bridge bd67a29d-3534-40dd-bde1-dd9d6ac3b2f8: calling simple_bridge technology destructor
[Jul 16 19:22:07] DEBUG[29099][C-00000002]: app_dial.c:3089 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[Jul 16 19:22:07] DEBUG[29099][C-00000002]: pbx.c:6389 __ast_pbx_run: Spawn extension (default,9992,5) exited non-zero on 'SIP/6002-00000004'
 == Spawn extension (default, 9992, 5) exited non-zero on 'SIP/6002-00000004'
[Jul 16 19:22:07] DEBUG[29099][C-00000002]: channel.c:2597 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'SIP/6002-00000004'
[Jul 16 19:22:07] DEBUG[29099][C-00000002]: channel.c:2753 ast_hangup: Hanging up channel 'SIP/6002-00000004'
[Jul 16 19:22:07] DEBUG[29099][C-00000002]: chan_sip.c:7147 sip_hangup: Hangup call SIP/6002-00000004, SIP callid 005CC6A7-AD0B-E411-BE51-7F7C92AFF181@192.168.23.128
[Jul 16 19:22:07] DEBUG[29099][C-00000002]: res_rtp_asterisk.c:4375 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f19bc019738'
[Jul 16 19:22:07] DEBUG[29099][C-00000002]: chan_sip.c:3921 __sip_xmit: Trying to put 'BYE sip:600' onto UDP socket destined for 192.168.23.128:5060
 == Begin MixMonitor Recording SIP/6002-00000004
[Jul 16 19:22:07] DEBUG[28994][C-00000002]: chan_sip.c:4613 __sip_ack: Stopping retransmission on '005CC6A7-AD0B-E411-BE51-7F7C92AFF181@192.168.23.128' of Request 102: Match Found
[Jul 16 19:22:07] DEBUG[28994]: chan_sip.c:6912 sip_destroy: Destroying SIP dialog 005CC6A7-AD0B-E411-BE51-7F7C92AFF181@192.168.23.128
[Jul 16 19:22:07] DEBUG[28994]: rtp_engine.c:338 instance_destructor: Destroyed RTP instance '0x7f19bc019738'
[Jul 16 19:22:07] DEBUG[29101][C-00000002]: autochan.c:71 ast_autochan_destroy: Removed autochan 0x7f19c4016090 from the list, about to free it
[Jul 16 19:22:07] DEBUG[28966]: pbx.c:4717 pbx_substitute_variables_helper_full: Function CDR(start) result is '2014-07-16 19:22:00'
[Jul 16 19:22:07] DEBUG[28966]: pbx.c:4717 pbx_substitute_variables_helper_full: Function CDR(clid) result is '"PhonerLite" <+18882275945>'
[Jul 16 19:22:07] DEBUG[28966]: pbx.c:4717 pbx_substitute_variables_helper_full: Function CDR(dcontext) result is 'default'
[Jul 16 19:22:07] DEBUG[28966]: pbx.c:4717 pbx_substitute_variables_helper_full: Function CDR(channel) result is 'SIP/6002-00000004'
[Jul 16 19:22:07] DEBUG[28966]: pbx.c:4717 pbx_substitute_variables_helper_full: Function CDR(dstchannel) result is 'SIP/6003-00000005'
[Jul 16 19:22:07] DEBUG[28966]: pbx.c:4717 pbx_substitute_variables_helper_full: Function CDR(lastapp) result is 'Dial'
[Jul 16 19:22:07] DEBUG[28966]: pbx.c:4717 pbx_substitute_variables_helper_full: Function CDR(lastdata) result is 'SIP/6003,,TW'
[Jul 16 19:22:07] DEBUG[28966]: pbx.c:4717 pbx_substitute_variables_helper_full: Function CDR(duration) result is '6'
[Jul 16 19:22:07] DEBUG[28966]: pbx.c:4717 pbx_substitute_variables_helper_full: Function CDR(billsec) result is '4'
[Jul 16 19:22:07] DEBUG[28966]: pbx.c:4717 pbx_substitute_variables_helper_full: Function CDR(disposition) result is 'ANSWERED'
[Jul 16 19:22:07] DEBUG[28966]: pbx.c:4717 pbx_substitute_variables_helper_full: Function CDR(amaflags) result is 'DOCUMENTATION'
[Jul 16 19:22:07] DEBUG[28966]: pbx.c:4717 pbx_substitute_variables_helper_full: Function CDR(accountcode) result is ''
[Jul 16 19:22:07] DEBUG[28966]: pbx.c:4717 pbx_substitute_variables_helper_full: Function CDR(uniqueid) result is '1405552920.8'
[Jul 16 19:22:07] DEBUG[28966]: pbx.c:4717 pbx_substitute_variables_helper_full: Function CDR(userfield) result is ''
[Jul 16 19:22:07] DEBUG[28966]: pbx.c:4717 pbx_substitute_variables_helper_full: Function CDR(test) result is ''
[Jul 16 19:22:07] DEBUG[28966]: cdr_sqlite3_custom.c:261 write_cdr: About to log: INSERT INTO cdr (calldate,clid,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield,test) VALUES ('2014-07-16 19:22:00','"PhonerLite" <+18882275945>','default','SIP/6002-00000004','SIP/6003-00000005','Dial','SIP/6003,,TW','6','4','ANSWERED','DOCUMENTATION','','1405552920.8','','')
[Jul 16 19:22:07] DEBUG[28964]: chan_sip.c:29441 sip_devicestate: Checking device state for peer 6002
[Jul 16 19:22:07] DEBUG[28964]: devicestate.c:462 do_state_change: Changing state for SIP/6002 - state 1 (Not in use)
 == MixMonitor close filestream (mixed)
 == End MixMonitor Recording SIP/6002-00000004
[Jul 16 19:22:07] DEBUG[29101][C-00000002]: app_mixmonitor.c:776 mixmonitor_thread: No recipients to forward monitor to, moving on.
{noformat}
By: Jonathan Rose (jrose) 2014-08-05 15:47:41.016-0500

I've got a fairly simple patch that fixes the channel from being kicked from the bridge afterward, but I don't know if its realistically going to be feasible to get the dynamic feature to keep running when the mixmonitor sets the soft hangup flag the way it is currently doing so. The dynamic features themselves are running through one of pbx_exec, macros, or gosub and from that point whatever application is running is going to see the soft hangup flag first and act on it. I'm not sure what to do about this at the moment.