[Home]

Summary:ASTERISK-27756: bridge: Failure to impart a channel results in bad data causing crash
Reporter:Abhay Gupta (agupta)Labels:pjsip
Date Opened:2018-03-21 02:49:02Date Closed:2019-05-03 10:49:16
Priority:MinorRegression?
Status:Closed/CompleteComponents:Resources/res_stasis
Versions:15.2.0 15.3.0 Frequency of
Occurrence		Frequent
Related
Issues:
duplicatesASTERISK-28377 ARI: Crash when unanswered channel rejoins dial bridge automatically
is duplicated byASTERISK-27767 Asterisk got creshed
Environment:Ubuntu 16.04 with asterisk 15.2.0 using ARI for bridge. Attachments:( 0) ari.txt
( 1) bt.txt
( 2) btfull.txt
( 3) btthread.txt
( 4) full
( 5) Full_main_ERROR_Log
Description:The is a incoming call on IAX channel and at times we get this message on trying to bridge this channel

[Mar 21 12:43:31] WARNING[1685][C-000066a0] bridge.c: Channel IAX2/2_1-10099 has a PBX thread and cannot be imparted into bridge 3cdd7200-ed20-403d-a6d9-53c2db73ed2c
at this time asterisk crashes with the following message .
[Mar 21 12:43:37] ERROR[1685][C-000066a0] stasis/control.c: FRACK!, Failed assertion bad magic number 0x0 for object 0x8f2ed2 (0)

The ari log at the time of error is attached where the same IAX channel comes is stasis bridge command is fired and then asterisk crashes .
Comments:By: Asterisk Team (asteriskteam) 2018-03-21 02:49:04.485-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: Abhay Gupta (agupta) 2018-03-21 02:49:50.500-0500

ARI log for crash
By: Abhay Gupta (agupta) 2018-03-21 04:13:06.697-0500

This bug is similar to ASTERISK-26679 and ASTERISK-26699 which was on PJSIP and this is on IAX .
By: Abhay Gupta (agupta) 2018-03-23 00:50:05.010-0500

Got this in full logs , can someone explain me as to where to look for the problem ?

[Mar 23 12:36:01] ERROR[19145][C-000070a9] stasis/control.c: FRACK!, Failed assertion bad magic number 0x0 for object 0x7efc30007d78 (0)
[Mar 23 12:36:01] VERBOSE[19145][C-000070a9] logger.c: Got 20 backtrace records
[Mar 23 12:36:01] VERBOSE[19145][C-000070a9] logger.c: #0: [0x63f210] main/utils.c:2446 __ast_assert_failed() (0x63f183+8D)
[Mar 23 12:36:01] VERBOSE[19145][C-000070a9] logger.c: #1: [0x4623a0] main/astobj2.c:190 log_bad_ao2()
[Mar 23 12:36:01] VERBOSE[19145][C-000070a9] logger.c: #2: [0x462417] main/astobj2.c:194 __ao2_lock() (0x4623b6+61)
[Mar 23 12:36:01] VERBOSE[19145][C-000070a9] logger.c: #3: [0x7efcda2e27d0] stasis/control.c:914 dial_bridge_after_cb()
[Mar 23 12:36:01] VERBOSE[19145][C-000070a9] logger.c: #4: [0x7efcda2e29d0] stasis/control.c:930 dial_bridge_after_cb_failed()
[Mar 23 12:36:01] VERBOSE[19145][C-000070a9] logger.c: #5: [0x47fe9c] main/bridge_after.c:71 after_bridge_cb_failed()
[Mar 23 12:36:01] VERBOSE[19145][C-000070a9] logger.c: #6: [0x47ff77] main/bridge_after.c:100 after_bridge_cb_run_discard()
[Mar 23 12:36:01] VERBOSE[19145][C-000070a9] logger.c: #7: [0x47ffb1] main/bridge_after.c:119 after_bridge_cb_destroy()
[Mar 23 12:36:01] VERBOSE[19145][C-000070a9] logger.c: #8: [0x50950e] main/datastore.c:69 ast_datastore_free() (0x5094c4+4A)
[Mar 23 12:36:01] VERBOSE[19145][C-000070a9] logger.c: #9: [0x4c239d] main/channel.c:2252 ast_channel_destructor()
[Mar 23 12:36:01] VERBOSE[19145][C-000070a9] logger.c: #10: [0x463216] main/astobj2.c:585 __ao2_ref() (0x462ba4+672)
[Mar 23 12:36:01] VERBOSE[19145][C-000070a9] logger.c: #11: [0x4c3bef] main/channel.c:2656 ast_hangup() (0x4c3761+48E)
[Mar 23 12:36:01] VERBOSE[19145][C-000070a9] logger.c: #12: [0x5a149a] main/pbx.c:4564 __ast_pbx_run()
[Mar 23 12:36:01] VERBOSE[19145][C-000070a9] logger.c: #13: [0x5a1861] main/pbx.c:4654 pbx_thread()
[Mar 23 12:36:01] VERBOSE[19145][C-000070a9] logger.c: #14: [0x63c0b0] main/utils.c:1257 dummy_start()
By: Abhay Gupta (agupta) 2018-03-23 02:04:56.808-0500

The flow is that incoming call comes on IAX channel -> is sent to stasis -> stasis is used to bridge to a existing bridge . The traces above is when we have upgraded to 15.3 but still the problem remains the same .

By: Abhay Gupta (agupta) 2018-03-23 02:25:04.577-0500

Attached , bt , bt full and thread apply all bt for the issue .
By: shaurya jain (shaurya) 2018-03-23 06:08:53.011-0500

[Mar 22 20:11:43] WARNING[31575][C-00002b3e] bridge.c: Channel IAX2/1_1-3498 has a PBX thread and cannot be imparted into bridge ea31c87b-7b2a-4f82-854d-dd586513af28
[Mar 22 20:11:43] DEBUG[31609][C-00002b40] format_wav.c: Skipping unknown block 'LIST'
[Mar 22 20:11:44] DEBUG[31628][C-00002b41] format_wav.c: Skipping unknown block 'LIST'
[Mar 22 20:11:48] DEBUG[30704][C-00002b21] format_wav.c: Skipping unknown block 'LIST'
[Mar 22 20:11:49] DEBUG[30943][C-00002b2a] format_wav.c: Skipping unknown block 'LIST'
[Mar 22 20:11:49] DTMF[31489][C-00002b3a] channel.c: DTMF begin '1' received on DAHDI/i2/028170088-955
[Mar 22 20:11:49] DTMF[31489][C-00002b3a] channel.c: DTMF begin ignored '1' on DAHDI/i2/028170088-955
[Mar 22 20:11:49] DTMF[31489][C-00002b3a] channel.c: DTMF end '1' received on DAHDI/i2/028170088-955, duration 127 ms
[Mar 22 20:11:49] DTMF[31489][C-00002b3a] channel.c: DTMF end passthrough '1' on DAHDI/i2/028170088-955
[Mar 22 20:11:49] NOTICE[31489][C-00002b3a] res_stasis_playback.c: 1521720692.34066: Playback stopped for sound:11/mixivr
[Mar 22 20:11:49] DEBUG[31489][C-00002b3a] format_wav.c: Skipping unknown block 'LIST'
[Mar 22 20:11:50] DEBUG[31251][C-00002b33] format_wav.c: Skipping unknown block 'LIST'
[Mar 22 20:11:51] DEBUG[31002][C-00002b2c] format_wav.c: Skipping unknown block 'LIST'
[Mar 22 20:11:51] DEBUG[31235][C-00002b32] format_wav.c: Skipping unknown block 'LIST'
[Mar 22 20:11:52] DEBUG[31759][C-00002b43] format_wav.c: Skipping unknown block 'LIST'
[Mar 22 20:11:53] DEBUG[30845][C-00002b27] format_wav.c: Skipping unknown block 'LIST'
[Mar 22 20:11:54] DTMF[31609][C-00002b40] channel.c: DTMF begin '9' received on DAHDI/i1/09209046513-97a
[Mar 22 20:11:54] DTMF[31609][C-00002b40] channel.c: DTMF begin ignored '9' on DAHDI/i1/09209046513-97a
[Mar 22 20:11:54] DTMF[31609][C-00002b40] channel.c: DTMF end '9' received on DAHDI/i1/09209046513-97a, duration 25 ms
[Mar 22 20:11:54] DTMF[31609][C-00002b40] channel.c: DTMF end passthrough '9' on DAHDI/i1/09209046513-97a
[Mar 22 20:11:54] NOTICE[31609][C-00002b40] res_stasis_playback.c: 1521720703.34081: Playback stopped for sound:11/mixivr
[Mar 22 20:11:54] DEBUG[31609][C-00002b40] format_wav.c: Skipping unknown block 'LIST'
[Mar 22 20:11:54] DTMF[31505][C-00002b3c] channel.c: DTMF begin '1' received on DAHDI/i2/029503644-956
[Mar 22 20:11:54] DTMF[31505][C-00002b3c] channel.c: DTMF begin ignored '1' on DAHDI/i2/029503644-956
[Mar 22 20:11:54] DTMF[31505][C-00002b3c] channel.c: DTMF end '1' received on DAHDI/i2/029503644-956, duration 127 ms
[Mar 22 20:11:54] DTMF[31505][C-00002b3c] channel.c: DTMF end passthrough '1' on DAHDI/i2/029503644-956
[Mar 22 20:11:54] NOTICE[31505][C-00002b3c] res_stasis_playback.c: 1521720696.34070: Playback stopped for sound:11/mixivr
[Mar 22 20:11:54] DEBUG[31505][C-00002b3c] format_wav.c: Skipping unknown block 'LIST'
[Mar 22 20:11:54] DEBUG[30804][C-00002b24] format_wav.c: Skipping unknown block 'LIST'
[Mar 22 20:11:54] DEBUG[31774][C-00002b44] format_wav.c: Skipping unknown block 'LIST'
[Mar 22 20:11:55] DEBUG[31494][C-00002b3b] format_wav.c: Skipping unknown block 'LIST'
[Mar 22 20:11:56] DEBUG[31021][C-00002b2d] format_wav.c: Skipping unknown block 'LIST'
[Mar 22 20:11:58] DEBUG[31798][C-00002b45] format_wav.c: Skipping unknown block 'LIST'
[Mar 22 20:11:59] WARNING[31774][C-00002b44] res_stasis_playback.c: 1521720714.34091: Playback failed for sound:11/mixivr
[Mar 22 20:12:01] DEBUG[31810][C-00002b46] format_wav.c: Skipping unknown block 'LIST'
[Mar 22 20:12:02] ERROR[31575][C-00002b3e] stasis/control.c: FRACK!, Failed assertion bad magic number 0x0 for object 0x91e95a (0)
[Mar 22 20:12:02] VERBOSE[31575][C-00002b3e] logger.c: Got 20 backtrace records
[Mar 22 20:12:02] VERBOSE[31575][C-00002b3e] logger.c: #0: [0x63f210] main/utils.c:2446 __ast_assert_failed() (0x63f183+8D)
[Mar 22 20:12:02] VERBOSE[31575][C-00002b3e] logger.c: #1: [0x4623a0] main/astobj2.c:190 log_bad_ao2()
[Mar 22 20:12:02] VERBOSE[31575][C-00002b3e] logger.c: #2: [0x462417] main/astobj2.c:194 __ao2_lock() (0x4623b6+61)

By: Joshua C. Colp (jcolp) 2018-03-26 10:06:25.039-0500

You seem to be missing the dialplan execution logging to see what exactly is going on there. Can you enable it and attach that information?
By: Abhay Gupta (agupta) 2018-03-27 11:57:24.509-0500

The call comes in stasis directly and so full log does not display any dial plan execution. Let me know what exactly is required.
By: Joshua C. Colp (jcolp) 2018-03-27 12:19:56.803-0500

Are you originating the call over ARI and sending it directly to the app? If not then there is still dialplan involved.
By: shaurya jain (shaurya) 2018-03-27 12:58:56.980-0500

This is the dial plan that is running on the call:-


exten = _call.,1(dial1),Stasis(agent-dial)
By: Naama Gertel (naamag) 2018-12-25 08:12:39.384-0600

Any progress on this issue?
I'm having the same problem but I'm running asterisk 14.7.2 and running it with kubuntu 18.10 and from my logs it seems that the problem is also with Channel/SIP and not just PJSIP. After that I get segmentation fault and asterisk crashed. These are the logs I see:
{noformat}
asterisk  > Dec 24 23:17:44 xxx asterisk[14953]: WARNING[15119][C-00000001]: bridge.c:1819 in bridge_impart_internal: Channel SIP/yyy-00000000 has a PBX thread and cannot be imparted into bridge 2cd90e8e-5f91-4d6f-85c1-57cc
asterisk  > 177ca1ea
asterisk  > Dec 24 23:17:44 xxx asterisk[14953]: ERROR[15119][C-00000001]: stasis/control.c:898 in dial_bridge_after_cb: FRACK!, Failed assertion bad magic number 0x0 for object 0x7f7b18000fb0 (0)
asterisk  > Dec 24 23:17:44 xxx asterisk[14953]: ERROR[15119][C-00000001]: stasis/control.c:900 in dial_bridge_after_cb: FRACK!, Failed assertion bad magic number 0x0 for object 0x7f7b18000fb0 (0)
asterisk  > Dec 24 23:18:10 xxx asterisk[14953]: WARNING[15160][C-00000002]: bridge.c:1819 in bridge_impart_internal: Channel SIP/yyy-00000001 has a PBX thread and cannot be imparted into bridge 2cd90e8e-5f91-4d6f-85c1-57cc177ca1ea
asterisk  > Dec 24 23:18:11 xxx asterisk[14953]: WARNING[15160][C-00000002]: bridge.c:1819 in bridge_impart_internal: Channel SIP/yyy-00000001 has a PBX thread and cannot be imparted into bridge 2cd90e8e-5f91-4d6f-85c1-57cc177ca1ea
asterisk  > Dec 24 23:18:11 xxx asterisk[13969]: /usr/sbin/safe_asterisk: line 171: 14953 Segmentation fault      (core dumped) nice -n $PRIORITY "${ASTSBINDIR}/asterisk" -f ${CLIARGS} ${ASTARGS} > /dev/${TTY} 2>&1 < /dev/${TTY}
{noformat}

I'm running this dial plan:
{noformat}
exten => _.,1,Noop(**** Activating call for CLID: ${CALLERID(num)} ****)
same =>    n,Stasis(myStasisApp)
same =>    n,Hangup()
{noformat}

By: Joshua C. Colp (jcolp) 2018-12-25 15:32:54.839-0600

Any progress will be posted on the issue. As there is no post, there is no update.
By: Horacio Peña (hache3) 2018-12-29 14:37:26.698-0600

Still happens on Asterisk 16.1.0, using chan_sip.

We've had this happening once two or three days on a box that's running near 50 IVR outgoing channels plus some manned calls.

Is there something I could do to help diagnose the problem?

Thanks,
By: Joshua C. Colp (jcolp) 2018-12-29 15:18:47.678-0600

Examples to show the problem, logs, and backtraces have already been provided. Someone has to actually do the work to dig into things, determine the precise code which is causing the problem, determine the fix, and fix it.
By: Morten Tryfoss (mtryfoss) 2019-02-19 16:37:27.972-0600

I got a similar issue.

My scenario is:
Adding two channels to a bridge, and executing dial on the second (similar functionality as app_dial). That channel immediately gets a "603 Declined".
In my stasis app I then remove the first channel from the bridge on stasisend-event for the second and then hanging up. By just hanging up the first call leg, Asterisk will not crash.

I'm not that familiar with this part of Asterisk code, but the problem seems to be some kind of race condition related to this:
{noformat}
static int depart_channel(struct stasis_app_control *control, struct ast_channel *chan)
{
ast_bridge_depart(chan);

if (!ast_check_hangup(chan) && ast_channel_state(chan) != AST_STATE_UP) {
/* Channel is still being dialed, so put it back in the dialing bridge */
add_to_dial_bridge(control, chan); <----- As an experiment, commenting out this causes Asterisk not to crash for me
}

return 0;
}
{noformat}
By: Abhay Gupta (agupta) 2019-03-21 05:34:35.503-0500

I will also try this and let you know the feedback
By: Abhay Gupta (agupta) 2019-03-22 09:42:33.878-0500

I tried to analyse the gdb again and strangely this is what i see that after_bridge_cb_failed function is called in bridge_after.c which sets node->failed to null and then enters stasis/control.c dial_bridge_after_callback and channel is NULL as far as i understand from the below backtrace and asterisk have not crashed from the time i also added the line as shown by Morten above

#0  ast_channel_internal_bridge_channel (chan=chan@entry=0x0) at channel_internal_api.c:1212
#1  0x00000000004c6606 in ast_channel_get_bridge_channel (chan=chan@entry=0x0) at channel.c:10593
#2  0x00007ff6575b8736 in dial_bridge_after_cb (data=0x7ff4bc0082a8, chan=0x0) at stasis/control.c:936
#3  dial_bridge_after_cb_failed (reason=<optimized out>, data=0x7ff4bc0082a8) at stasis/control.c:951
#4  0x0000000000474c41 in after_bridge_cb_failed (node=0x7ff4bc009b80) at bridge_after.c:70
#5  after_bridge_cb_run_discard (reason=AST_BRIDGE_AFTER_CB_REASON_DESTROY, after_bridge=0x7ff4bc009a50) at bridge_after.c:99
#6  after_bridge_cb_destroy (data=0x7ff4bc009a50) at bridge_after.c:117
#7  0x00000000004f3dfc in ast_datastore_free (datastore=datastore@entry=0x7ff4bc009cd0) at datastore.c:68
#8  0x00000000004b653e in ast_channel_destructor (obj=0x7ff5280165c8) at channel.c:2255
#9  0x000000000045b253 in __ao2_ref (user_data=user_data@entry=0x7ff5280165c8, delta=delta@entry=-1, tag=tag@entry=0x6230a0 "", file=file@entry=0x62cf26 "channel.c", line=line@entry=2657,
   func=func@entry=0x63c510 <__PRETTY_FUNCTION__.21555> "ast_hangup") at astobj2.c:576
#10 0x00000000004b7be9 in ast_hangup (chan=chan@entry=0x7ff5280165c8) at channel.c:2657

By: Abhay Gupta (agupta) 2019-03-25 07:40:24.899-0500

No crash after commenting this line

add_to_dial_bridge(control, chan);
By: Abhay Gupta (agupta) 2019-04-22 04:25:00.605-0500

Is the issue similar to ASTERISK-28377
By: Abhay Gupta (agupta) 2019-04-30 08:23:27.027-0500

Checked the issue . Sequence of event is
1. Incoming Call comes in Stasis without ANSWER
2. Create a bridge
3. Add the channel in bridge
4. Destroy bridge
At this point we get the issue of Failure to impart channel
5. As soon as the channel is Hangup Asterisk segfaults with same back trace
By: Friendly Automation (friendly-automation) 2019-05-03 10:49:17.292-0500

Change 11320 merged by Friendly Automation:
stasis: Only place stasis created and dialed channels into dial bridge.

[https://gerrit.asterisk.org/c/asterisk/+/11320|https://gerrit.asterisk.org/c/asterisk/+/11320]
By: Friendly Automation (friendly-automation) 2019-05-03 10:52:35.995-0500

Change 11332 merged by Joshua Colp:
stasis: Only place stasis created and dialed channels into dial bridge.

[https://gerrit.asterisk.org/c/asterisk/+/11332|https://gerrit.asterisk.org/c/asterisk/+/11332]