[Home]

Summary:ASTERISK-15229: [patch] chan_mobile doesn't hangup
Reporter:pj (pj)Labels:
Date Opened:2009-11-27 17:50:17.000-0600Date Closed:2011-07-26 14:33:54
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Addons/chan_mobile
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) blue.pcap
( 1) gdb.txt
( 2) hangup-fail.txt
( 3) hangup-ok.txt
( 4) mobile-continue-on-error1.diff
( 5) phone_init.txt
Description:chan_mobile doesn't hangup call, when it receives audio from mobile device. It can be progress audio message from gsm network (eg. ringback) or audio from answered call. Phone is also disconnected from chan_mobile in this case.

When call setup is terminated before any incomming audio is received from gsm network by chan_mobile, mobile channel is successfully terminated and phone is not disconnected from chan_mobile.

Comments:By: pj (pj) 2009-11-30 16:22:26.000-0600

this appears in /var/log/messagess when incorrect hangup from chan_mobile occurs:

Nov 30 17:11:26 localhost kernel: hci_scodata_packet: hci0 SCO packet for unknown connection handle 1
Nov 30 17:12:15 localhost kernel: btusb_isoc_complete: hci0 corrupted SCO packet
Nov 30 17:12:15 localhost kernel: hci_scodata_packet: hci0 SCO packet for unknown connection handle 0
Nov 30 17:12:15 localhost kernel: hci_scodata_packet: hci0 SCO packet for unknown connection handle 0
Nov 30 17:12:15 localhost kernel: hci_scodata_packet: hci0 SCO packet for unknown connection handle 0
Nov 30 17:12:15 localhost kernel: hci_scodata_packet: hci0 SCO packet for unknown connection handle 0
Nov 30 17:12:15 localhost kernel: hci_scodata_packet: hci0 SCO packet for unknown connection handle 0
By: pj (pj) 2009-11-30 17:04:32.000-0600

uploading also hcidump file, it seems, that chan_mobile sends hci disconnect request to phone, immediatelly after call hangup request.
By: Matthew Nicholson (mnicholson) 2009-12-02 14:43:29.000-0600

Chan mobile disconnects from the phone because it encounters a read error.  I am not sure this is a bug in chan mobile.
By: Matthew Nicholson (mnicholson) 2009-12-02 14:53:06.000-0600

I need more information to determine if this is a problem with cahn_mobile or if this is a problem with something else.  How relibly does this happen?  Does it happen on every call?  Also, does the call the handset is connected to get disconnected?
By: pj (pj) 2009-12-02 15:13:19.000-0600

hangup issue happen in every call, in case audio is received from gsm network, if I look to phone display, I see message, that bluetooth is disconnected, and audio is heard from phone handset and then call can be hang up only from phone keypad.

if I terminate call attempt by chan_mobile before progress audio (ringback) is received from gsm network, call attempt could be terminated successfully.
By: pj (pj) 2009-12-02 15:16:53.000-0600

if you look into packet capture from asterisk server, it seems, that first disconnect request is in frame ASTERISK-1588 and it's in 'send' direction from asterisk perspective.
By: Matthew Nicholson (mnicholson) 2009-12-02 15:25:37.000-0600

I see that the disconnect request is comming from asterisk, but the request is sent as the restult of a read error.  Asterisk gets and error when trying to read data from the phone and closes the connection.

What should happen is asterisk should send AT+CHUP and the phone should respond with and OK message.  This is what happens before any progress is sent, but for some reason, after progress is sent, there is a read error following the hangup request from asterisk.

Does the debug trace for this error condition always look the same?  In other words, does asterisk always report a read error and disconnect the line after sending the AT+CHUP request?
By: pj (pj) 2009-12-02 15:58:26.000-0600

some more testing: read error and bluetooth disconnection happened in all cases (when ringback was heard), but in some of this cases, call was successfully hangup (it seems, that in some rare circumstances AT+CHUP is successfully received by phone).
By: pj (pj) 2009-12-02 16:02:05.000-0600

also some note, that sometimes, I got error below, when asterisk is starting and chan_mobile refuses to load, I must try to start again...

[Dec  2 16:40:07] ERROR[8132]: chan_mobile.c:4030 mbl_load_adapter: Skipping adapter blue. Voice setting must be 0x0060 - see 'man hciconfig' for details.
[Dec  2 16:40:07] ERROR[8132]: chan_mobile.c:4275 mbl_load_config: ***********************************************************************
No adapters could be loaded from the configuration file.
Please review mobile.conf. See sample for details.
***********************************************************************
[Dec  2 16:40:07] ERROR[8132]: chan_mobile.c:4409 load_module: Errors reading config file chan_mobile.conf. Not loading module.
By: Matthew Nicholson (mnicholson) 2009-12-03 08:03:24.000-0600

I don't think that error is related to the disconnects.  To fix this, we need to determine the cause of the read error.  I am not sure how to do this.  Asterisk reports the error as "connection reset by peer", but that does not tell us much.
By: Matthew Nicholson (mnicholson) 2009-12-03 08:07:08.000-0600

Perhaps some sort of timeout is occurring in the phone or bluetooth adapter and it is closing the bluetooth connection or something.  Do these disconnects seem related to the amount of time the channel is up?

I am going to try and lab this up with my blackberry and get an hcidump to see what happens when I hangup in a normal case.
By: Matthew Nicholson (mnicholson) 2009-12-03 09:45:48.000-0600

Ok, so there are some differences I noticed in my trace vs your trace.  In my trace, the protocol for the RFCOMM messages is listed as RFCOMM, but in your trace it is listed as L2CAP.  I know that RFCOMM is built on top of L2CAP, so I am not sure if this difference is significant.  Beyond that, the disconnection sequence looks normal as far as I can tell.  I don't see anything related to a read error and I am not sure if that would even be in this trace.  The bluetooth connection is not terminated until after we request a disconnect.

Something that might be useful is modifying chan_mobile to continue after it receives that read error and see what happens.  I'll work on a patch to do that.
By: Matthew Nicholson (mnicholson) 2009-12-04 12:07:12.000-0600

Ok, I just uploaded the patch.  It should prevent asterisk from killing the connection on error.  This may give us some more insight on the nature of the error.
By: pj (pj) 2009-12-04 13:02:44.000-0600

after patching asterisk, it doesn't hangup nor reconnect to phone after bluetooth disconnection (even I have interval=10 in chan_mobile.conf)

'mobile show device' still shows phone as connected and free
When I try to unload chan_mobile, asterisk locks...


[Dec  4 13:41:56] DEBUG[8849]: channel.c:2218 ast_hangup: Hanging up channel 'Mobile/E61-861f'
[Dec  4 13:41:56] DEBUG[8849]: chan_mobile.c:1004 mbl_hangup: [E61] hanging up device
]Dec  4 13:41:56] DEBUG[8849]: chan_mobile.c:1404 rfcomm_write_full: rfcomm_write() (16) [AT+CHUP
[Dec  4 13:41:56] DEBUG[8833]: chan_mobile.c:1185 mbl_devicestate: Checking device state for device E61
[Dec  4 13:41:57] DEBUG[8846]: chan_mobile.c:3585 do_monitor_phone: [E61] error reading from device: Connection reset by peer (104)
[Dec  4 13:41:57] DEBUG[8846]: chan_mobile.c:3586 do_monitor_phone: [E61] continuing

*CLI> mobile show devices
ID              Address           Group Adapter         Connected State SMS
E61             00:12:D1:86:91:C5 0     blue            Yes       Free  No


=== Thread ID: -1226896528 (monitor_sig_flags    started at [ 3711] asterisk.c main())
=== ---> Waiting for Lock #0 (loader.c): MUTEX 178 ast_module_unregister &(&module_list)->lock 0x824b528 (1)
       /usr/sbin/asterisk(ast_bt_get_addresses+0x19) [0x8115e01]
       /usr/sbin/asterisk() [0x810d7f0]
       /usr/sbin/asterisk(ast_module_unregister+0x39) [0x810e3ab]
       /usr/lib/asterisk/modules/pbx_ael.so(+0x10c6) [0xb6f670c6]
       /usr/lib/asterisk/modules/pbx_ael.so(+0x938) [0xb6f66938]
       /usr/lib/asterisk/modules/pbx_ael.so(+0x1120) [0xb6f67120]
       /lib/ld-linux.so.2(+0xe7de) [0xb782c7de]
       /lib/i686/libc.so.6(+0x2cb1f) [0xb76deb1f]
       /lib/i686/libc.so.6(+0x2cb8f) [0xb76deb8f]
       /usr/sbin/asterisk() [0x807a01d]
       /usr/sbin/asterisk() [0x807e262]
       /usr/sbin/asterisk() [0x818a255]
       /lib/i686/libpthread.so.0(+0x5ae5) [0xb751bae5]
       /lib/i686/libc.so.6(clone+0x5e) [0xb7789ece]
=== --- ---> Locked Here: loader.c line 487 (ast_unload_resource)
By: Matthew Nicholson (mnicholson) 2009-12-04 13:07:20.000-0600

Hmm, it may be that poll never returns after that, or that poll never indicates that there is data because there is an error on the RFCOMM socket.
By: Matthew Nicholson (mnicholson) 2009-12-04 15:32:53.000-0600

Build without optimizations, and grab a backtrace from the running process just after you see the connection reset error.
By: pj (pj) 2009-12-04 16:01:15.000-0600

after bluetooth disconnect, I attach gdb to asterisk process and do
'thread apply all bt full'
gdb.txt uploaded
By: pj (pj) 2009-12-11 06:22:35.000-0600

do you have sufficient infos yet to discover this issue, or should I try to collect further traces/debugs, eg. valgrind?
By: Matthew Nicholson (mnicholson) 2009-12-11 07:44:04.000-0600

My attention has been diverted from this issue for the time being, but right now, I don't have any other information for you to collect. Thanks for your efforts thus far.
By: Leif Madsen (lmadsen) 2011-07-26 14:33:48.085-0500

Suspended due to lack of activity. Please request a bug marshal in #asterisk-bugs on the IRC network irc.freenode.net to reopen the issue should you have the additional information requested.  Further information can be found at http://www.asterisk.org/developers/bug-guidelines