[Home]

Summary:ASTERISK-15085: chan_mobile pairs, dials, and receives calls, but no audio
Reporter:Mark Haun (haunma)Labels:
Date Opened:2009-11-05 23:26:54.000-0600Date Closed:2011-07-27 13:30:24
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Addons/chan_mobile
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) asterisk_console.txt
( 1) chan_mobile_debug
( 2) debug.txt
( 3) dmesg
( 4) extensions.conf
( 5) hcidump.out
( 6) hcidump.txt
( 7) mobile.conf
( 8) new_asterisk_incoming
( 9) new_asterisk_outgoing
(10) new_asterisk_startup
(11) new_bluetoothd_log
(12) new_hcidump_incoming
(13) new_hcidump_outgoing
Description:I am using Asterisk 1.6.2.0~dfsg~rc1-1 from Debian Squeeze with a custom compiled chan_mobile.c from the trunk version (svn 209993) supplied as an attachment to issue ASTERISK-15000.

It appears to be a working configuration with no obvious errors, but I get no audio over the bluetooth link.  (I test by calling my cell phone from the Asterisk console via an IAX provider, with the incoming call going to an echo test.)

I've attached the Asterisk debugging output (with some IAX debugging output removed) as well as hcidump -X -V.


****** ADDITIONAL INFORMATION ******

$ hciconfig -a
hci0: Type: USB
BD Address: 00:02:72:CA:DF:9C ACL MTU: 377:10 SCO MTU: 64:8
UP RUNNING PSCAN ISCAN
RX bytes:1945696 acl:112 sco:38057 events:301 errors:9
TX bytes:3048 acl:62 sco:0 commands:137 errors:0
Features: 0xff 0xfe 0x0d 0x38 0x08 0x08 0x00 0x00
Packet type: DM1 DM3 DM5 DH1 DH3 DH5 HV1 HV2 HV3
Link policy:
Link mode: SLAVE ACCEPT
Name: 'angwin'
Class: 0x4a2104
Service Classes: Networking, Capturing, Telephony
Device Class: Computer, Desktop workstation
HCI Ver: 1.2 (0x2) HCI Rev: 0xc LMP Ver: 1.2 (0x2) LMP Subver: 0x309
Manufacturer: Broadcom Corporation (15)

Comments:By: Mark Haun (haunma) 2009-11-05 23:37:16.000-0600

I attached dmesg because there are occasional "hci0 SCO packet for unknown connection handle 0" errors.  There are only a handful, and they don't seem to happen on every connection.  Possibly harmless?

I also tried this with "disable_esco=1" passed to the sco kernel module, with no effect.

Phone:  LG 290c (StraightTalk prepaid version of Sprint LX-290) on Verizon
Dongle: Zonet CCBT2035BDGP23-1 (Broadcom)
By: Mark Haun (haunma) 2009-11-22 14:27:08.000-0600

Update:  The bluez version in Debian squeeze recently changed from 4.42 to 4.57.  I tried chan_mobile again, but the symptoms are the same.

If I call the mobile extension from another line, and asterisk runs the echo test on the mobile extension, I can actually see my own voice flying by in the SCO packets with hcidump -X -V, interspersed with silence.  The weird thing is, all of the SCO packets seem to be coming from the phone, with none going to the phone.  Without more knowledge of the proper packet cadence (e.g. is it supposed to be full duplex, or not?), I don't know what this means.  And, I can't hear any audio (not surprising if it were working one way).

If I console dial out of the mobile extension, I can again see the expected patterns of silence and non-silence in the SCO packets coming from the phone, but that audio does not make it into asterisk and the console ALSA driver.  (I do have sound if I console dial via my IAX provider.)  Again, no errors are raised, at least in "console set debug 1".

I have verified that the phone works with a regular BT headset.

I'm hoping an asterisk dev can suggest some experiments to probe this further.  It seems really close.


By: Matthew Nicholson (mnicholson) 2009-11-25 11:59:22.000-0600

In your debug log I don't see any debug messages indicating that the handset ever attempted to make an audio connection to asterisk.  This is mostly likely the problem.  I am not sure if this is a bug in asterisk, the phone, the adapter, bluez, or the kernel drivers.


By: Mark Haun (haunma) 2009-11-25 23:44:34.000-0600

I think I may have had the debug level set too low.  I ran the test again with "core set debug 5" during incoming and outgoing calls, saving the asterisk log and hcidump as attachments (see the files "new_xxxxxx" above).

Clearly there is an audio connection.  Just to make sure I ran "hcitool con" during various call phases.  When the phone has registered with Asterisk and is in the free state, this reports

< ACL 00:25:E5:FA:BD:9A handle 6 state 1 lm MASTER

and during a call it reports

> SCO 00:25:E5:FA:BD:9A handle 1 state 1 lm SLAVE
< ACL 00:25:E5:FA:BD:9A handle 6 state 1 lm MASTER

(This is the same for either an incoming or outgoing call.)

As you can see in the asterisk logs, at debug level 5 there are now some errors visible, starting with

[Nov 25 20:51:21] DEBUG[4004]: channel.c:1843 __ast_answer: Didn't receive a media frame from Mobile/MarksLG-bb1f within 500 ms of answering. Continuing anyway
[Nov 25 20:51:21] DEBUG[4004]: channel.c:3661 set_format: Set channel Mobile/MarksLG-bb1f to write format gsm
[Nov 25 20:51:21] DEBUG[4004]: chan_mobile.c:1130 mbl_write: *** mbl_write
[Nov 25 20:51:21] DEBUG[4004]: chan_mobile.c:1704 sco_write: sco_write() not ready
[Nov 25 20:51:21] DEBUG[4004]: chan_mobile.c:1704 sco_write: sco_write() not ready

and continuing this way endlessly as it tries to play the echo test announcement.  During the call SCO packets are arriving continually from the phone and I can see my voice in the packet dump.  But, we are not sending any packets to the phone.

I have just described an incoming call.  For an outgoing call the same errors appear from chan_mobile.c (sco_write() not ready) but there is no preceding complaint from channel.c about "no media frame within 500 ms."  Again the incoming sound is good in the packet dump, but doesn't make it into Asterisk, and there are no outgoing SCO packets.

Another odd thing during the incoming call was that the SCO connection persisted after I hang up the remote extension, and after the mobile phone display indicated that the call had ended.  Even "mobile show devices" listed the handset as free, but hcidump showed SCO packets of silence streaming continuously from the phone, and "hcitool con" showed the SCO connection still up.  I don't know if this would continue indefinitely; it stopped when I quit asterisk.

Regards,

Mark


By: Mark Haun (haunma) 2009-11-27 16:54:10.000-0600

Oops, I was still missing some of the startup messages--sorry!  They were mixed into the flood of other module debug output, and the later chan_mobile.c output wasn't complaining about anything so I didn't think to go back and check.

I've uploaded a "new_asterisk_startup" with absolutely everything from the start of execution until the phone has registered.  (Debug output from incoming/outgoing calls is already there in the new_asterisk_incoming and new_asterisk_outgoing files.)

Here's the output of "grep chan_mobile new_asterisk_startup":

[Nov 27 14:29:45] DEBUG[12236]: chan_mobile.c:4004 mbl_load_adapter: Reading configuration for adapter zonet 00:02:72:CA:DF:9C.
[Nov 27 14:29:45] DEBUG[12236]: chan_mobile.c:4078 mbl_load_adapter: Loaded adapter zonet 00:02:72:CA:DF:9C.
[Nov 27 14:29:45] DEBUG[12236]: chan_mobile.c:4110 mbl_load_device: Reading configuration for device MarksLG.
[Nov 27 14:29:45] DEBUG[12236]: chan_mobile.c:4224 mbl_load_device: Loaded device MarksLG.
chan_mobile.so => (Bluetooth Mobile Device Channel Driver)
[Nov 27 14:29:45] DEBUG[12247]: chan_mobile.c:1357 rfcomm_connect: connect() failed (4).
[Nov 27 14:29:45] ERROR[12246]: chan_mobile.c:3964 do_sco_listen: ast_io_wait() failed for audio on adapter zonet
]Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:1400 rfcomm_write_full: rfcomm_write() (28) [AT+BRSF=4
[Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:3585 do_monitor_phone: [MarksLG] +BRSF: 359
[Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:3585 do_monitor_phone: [MarksLG] OK
[Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:2999 handle_response_ok: [MarksLG] BSRF sent successfully
]Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:1400 rfcomm_write_full: rfcomm_write() (28) [AT+CIND=?
[Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:3585 do_monitor_phone: [MarksLG] +CIND: ("call",(0,1)),("callsetup",(0-3)),("service",(0,1)),("signal",(0-5)),("roam",(0,1)),("battchg",(0-5)),("callheld",(0-2))
[Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:3585 do_monitor_phone: [MarksLG] OK
[Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:3016 handle_response_ok: [MarksLG] CIND test sent successfully
]Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:1400 rfcomm_write_full: rfcomm_write() (28) [AT+CIND?
[Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:3585 do_monitor_phone: [MarksLG] +CIND: 0,0,1,5,0,2,0
[Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:3585 do_monitor_phone: [MarksLG] OK
[Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:3027 handle_response_ok: [MarksLG] CIND sent successfully
]Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:1400 rfcomm_write_full: rfcomm_write() (28) [AT+CMER=3,0,0,1
[Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:3585 do_monitor_phone: [MarksLG] OK
[Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:3050 handle_response_ok: [MarksLG] CMER sent successfully
]Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:1400 rfcomm_write_full: rfcomm_write() (28) [AT+CLIP=1
[Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:3585 do_monitor_phone: [MarksLG] +VGS: 15
[Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:3585 do_monitor_phone: [MarksLG] OK
[Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:3067 handle_response_ok: [MarksLG] caling line indication enabled
]Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:1400 rfcomm_write_full: rfcomm_write() (28) [AT+VGS=15
[Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:3585 do_monitor_phone: [MarksLG] OK
[Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:3079 handle_response_ok: [MarksLG] volume level synchronization successful
]Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:1400 rfcomm_write_full: rfcomm_write() (28) [AT+CMGF=1
[Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:3585 do_monitor_phone: [MarksLG] ERROR
[Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:3195 handle_response_error: [MarksLG] error setting CMGF
[Nov 27 14:30:18] DEBUG[12286]: chan_mobile.c:3196 handle_response_error: [MarksLG] no SMS support
[Nov 27 14:30:29] DEBUG[12286]: chan_mobile.c:3585 do_monitor_phone: [MarksLG] +CIEV: 4,4

If I am tracing the errnos correctly, errno 4 in rfcomm_connect() translates to "Interrupted system call."  Does that mean anything to you?

Mark
By: Matthew Nicholson (mnicholson) 2009-12-02 15:18:58.000-0600

The phone may be making a connection to the bluetooth adapter, but for some reason the bluetooth stack does not realize this connection is for asterisk.  From your previous debug, asterisk never received a connection.  As I said before, I am not sure how to fix this bug.
By: Mark Haun (haunma) 2009-12-02 17:45:28.000-0600

Could you describe for me what is happening in line 5 of the excerpt above,

[Nov 27 14:29:45] DEBUG[12247]: chan_mobile.c:1357 rfcomm_connect: connect() failed (4).

?  I.e. what is this connection used for?  I thought the rfcomm channel would be for the AT command dialog with the phone.  But that dialog is going just fine even with this rfcomm failed connection.  Is this rfcomm connection failure somehow related to the next error, in do_sco_listen?

I realize you may not have any idea how to fix this in chan_mobile (if indeed that is possible), but I do need to understand the sequence of events better in order to pursue this further.  It could be a problem in bluez, but I can't expect the bluez folks to dive in until I can explain exactly what is happening and how it deviates from the expected behavior.

Thanks,

Mark
By: Matthew Nicholson (mnicholson) 2009-12-03 08:01:21.000-0600

That connect is asterisk attempting to connect to the phone for the AT commands.  It may fail several times before succeeding for various reasons.  If the AT commands are going through, then it succeeded, also a verbose message should be printed saying the device is connected when that function succeeds.

You should see a debug message that says "Incoming Audio Connection from device..." when a call comes in or goes out.  That indicates that the phone made an audio connection to asterisk.  This message is not in your debugs even though we know sco data is being sent from the phone.

The problem is that even though the phone is trying to connect to asterisk, the bluetooth stack does not pass this connection along to asterisk.  This could be because asterisk is not listening for the connection properly, it could be because of a bug in the bluetooth stack or driver, and it could be because of a bug in the phone causing it not to connection with the proper parameters.
By: Mark Haun (haunma) 2009-12-03 12:06:08.000-0600

Thanks, that helps.  Maybe I'll try adding some more debug output around that rfcomm stuff to understand it better.  But it sounds like the next error could be more relevant to the failed incoming audio connection.

I'm trying to understand this loop in do_sco_listen():

while (!check_unloading()) {
       /* check for new sco connections */
       if ((res = ast_io_wait(adapter->accept_io, 0)) == -1) {
               /* handle errors */
               ast_log(LOG_ERROR, "ast_io_wait() failed for adapter %s\n", adapter->id);
               break;
       }

       /* handle audio data */
       if ((res = ast_io_wait(adapter->io, 1)) == -1) {
               ast_log(LOG_ERROR, "ast_io_wait() failed for audio on adapter %s\n", adapter->id);
               break;
       }
}

Which of the calls to ast_io_wait is meant to block while waiting for a connection?  It is interesting that my error is coming from the second ast_io_wait call ("handle audio data"), and right at initialization too, before any call activity.  Could the phone be initiating an audio connection right away, before asterisk expects it?  It does use an audio channel for voice-activated dialing when I pair a regular BT headset.

It is possible that a failure in do_sco_listen() during initialization could leave asterisk in a state where it cannot accept subsequent SCO connections?

In any case, perhaps a close examination of the packet dump, correlating the timestamps with asterisk debug output, will be enlightening.  I'll take a look at that tonight.
By: Matthew Nicholson (mnicholson) 2009-12-03 12:38:56.000-0600

In that loop, the second call blocks for 1 millisecond to prevent the thread from busy looping.

In theory a failed connection during initialization should not cause any problems, but there could be some bugs there.  In theory the "Incoming Audio Connection..." message should be printed then a message saying either a device for that connection could not be found or something.

Another thing to consider is that the phone may not react well to us not handling the audio channel it uses for voice activated dialing.  The phone may be trying to use the same audio connection to send the call's audio to asterisk.  I am not sure if this is standard compliant behavior or not.

I don't see that initial audio connection in the asterisk debugs at all, so I don't think asterisk is even seeing it.
By: Mark Haun (haunma) 2009-12-03 14:35:58.000-0600

After the "ast_io_wait() failed for audio..." error, do_sco_listen() is going to return NULL.  I don't know pthreads, but is anything going to restart the polling loop at that point?  If not, there's our answer as to why asterisk isn't seeing any incoming connections later on...

I guess I should add some debug output to see what errno is set to by poll() in ast_io_wait().
By: Matthew Nicholson (mnicholson) 2009-12-04 10:40:11.000-0600

Actually that would cause a problem.  I didn't even notice that before.  Nothing is going to restart that loop.  Perhaps exiting the thread in the event of an ast_io_wait error is not the best thing to do.
By: Mark Haun (haunma) 2009-12-04 12:45:21.000-0600

Success!  Well, mostly :)

Inside ast_io_wait(), poll() is setting errno 4 EINTR "interrupted system call", but on subsequent calls it returns ok.  I added code which tries ast_io_wait() a second time in the event of failure, and if it succeeds, prints an error message warning that it took two tries.  Now the SCO listener thread continues to run and processes the incoming connection from the phone correctly.

I didn't have a lot of time to explore last night, but in my last version, I just commented out the second break statement; that is sufficient.  Of course, if there were a persistent failure I'd be getting reams of errors in the log.  I'm happy to test a better patch if you'd like.

There are some nagging issues which are off-topic here, but briefly:

1) I route incoming mobile calls to the echo test.  When I dial in I hear the announcement but I can't hear any echo coming back.  I remember seeing an issue where this turned out to be a volume-control thing, but I haven't had time to investigate.

2) Outgoing calls from the mobile extension have good audio in both directions, but the latency is a full two seconds, so pretty much unusable.  I know others have encountered this too; what's the conventional wisdom?  Tuning?  Dongle chipset?

Oh, one more thing, while dialed in to the echo test I sent a DTMF tone.  It was received by the mobile extension and noted in the asterisk log, but asterisk immediately crashed with glibc double-free warnings.  This asterisk is Debian testing, not svn, so I guess I need to try building from svn before sending a bug report.  At least the DTMF got through the mobile phone, which seems to be the main hurdle.
By: Matthew Nicholson (mnicholson) 2009-12-04 15:30:53.000-0600

Great!  Good work tracking this down.  The best thing to do would probably be to test for the specific error type when an error occurs and if it is not something fatal, then don't exit the loop.  Also, in the event of a fatal error, we should probably have a way to disable the adapter or something so that the user does not get reams of errors and so that the user does not get successful calls without any audio as well.

1) I am not sure about that one

2) Yes, this has come up before.  I have not been able to find a specific cause yet and it does not happen to everyone.

3) Yes, try with svn trunk, or svn 1.6.2.  If you still get a crash, open a bug.
By: Mark Haun (haunma) 2009-12-07 00:18:28.000-0600

Ok, so I've had some more time for testing, and happily, most of my secondary issues appear unrelated to chan_mobile.

1) Volume levels are fine.  The echo test doesn't work because Verizon's adaptive echo canceler is very effective!  What finally tipped me off (besides ordinary calls sounding fine) was that I could get an echo on impulsive/clicking sounds, but not my voice.

2) The bad delay only happens at the console, with ALSA.  Routing calls to and from my ATA, the latency is about what you'd expect.

3) I haven't reproduced this crash on non-console calls.

So in summary, it performs quite well.  Dialing from an analog telephone through Asterisk and out chan_mobile, I was told that I sound about the same as using the cell phone by itself.  Nice work!

BTW, my phone is CDMA.  I'm sure there are other CDMA phones working with chan_mobile, but I could not find any definitive report on google.  Maybe this paragraph will help :)
By: Milon (mtalukder) 2009-12-29 04:50:18.000-0600

dear admin & reporter, i know i'm being optimist to hope for a response of my note. still i'm looking forward to it. i am too stumble into no audio problem like many other enthusiastic chan_mobile learner. below is my details:

hci0:   Type: USB
       BD Address: B3:34:0D:96:20:7B ACL MTU: 1017:8 SCO MTU: 64:0
       UP RUNNING PSCAN ISCAN
       RX bytes:1938360 acl:339 sco:37574 events:424 errors:0
       TX bytes:4144 acl:144 sco:0 commands:180 errors:0
       Features: 0xff 0xff 0x8d 0xfe 0x9b 0xf9 0x00 0x80
       Packet type: DM1 DM3 DM5 DH1 DH3 DH5 HV1 HV2 HV3
       Link policy: RSWITCH HOLD SNIFF PARK
       Link mode: SLAVE ACCEPT
       Name: 'Our PBX System'
       Class: 0x082104
       Service Classes: Capturing
       Device Class: Computer, Desktop workstation
       HCI Ver: 2.0 (0x3) HCI Rev: 0x4000 LMP Ver: 2.0 (0x3) LMP Subver: 0x430e
       Manufacturer: Broadcom Corporation (15)

Note: All RX SCO; No TX SCO

Tested with:

1. Nokia N91 8GB
2. Nokia 5310
3. Samsung SGH-M620
4. Nokia 6320

Note: all with similar result

I've read above notes & failed to analyze my logging. asterisk, hcidump log files attached with this note.

Can you guys please help?
By: Milon (mtalukder) 2009-12-29 04:57:08.000-0600

sorry, i've missed my env details.

1. Kernel version:   2.6.25-14
2. Bluez version:    3.30
3. Asterisk version: 1.6.2.0
4. Asterisk-addons:  1.6.2.0
5. Distro:           FC9

just to inform i've also tested in FC10 with kernel version 2.6.27 & bluez version 4.5 without any luck.
By: BrettS (ughnz) 2009-12-31 22:43:54.000-0600

I am having an issue with the Nokia 23xx series phones as well as a few other nokia phones that may be related to this issue.

What is happening is that outgoing calls will progress, be answered, but there will be no audio for the first 20-30 seconds.
Also sometimes the call will progress, be answered by the remote party, yet ringing tone is heard for 20-30 seconds then audio.

Oddly enough incoming calls work OK.

I have attached a debug of the situation.
By: Zoltan Arvai (azbest) 2010-01-12 11:11:13.000-0600

in mobile.conf
port=2 ; the rfcomm port number (from mobile search)

behavier of the phones depends on the port number used by.

Most of Nokia phones works with port 28.
A configuration with port 2 makes the phone to use its own speaker.
By: Leif Madsen (lmadsen) 2010-03-26 11:13:55

I think I'm having this with trunk as well. When I receive a call I just get:

   -- Executing [s@incoming-bluetooth:1] Answer("Mobile/NokiaE71-cec7", "") in new stack
   -- Executing [s@incoming-bluetooth:2] Verbose("Mobile/NokiaE71-cec7", "2,Incoming callerID "NokiaE71" <+16473460000>") in new stack
 == Incoming callerID "NokiaE71" <+16473460000>
   -- Executing [s@incoming-bluetooth:3] Wait("Mobile/NokiaE71-cec7", "2") in new stack
   -- Executing [s@incoming-bluetooth:4] NoOp("Mobile/NokiaE71-cec7", "") in new stack
   -- Executing [s@incoming-bluetooth:5] Playback("Mobile/NokiaE71-cec7", "tt-weasels") in new stack
   -- <Mobile/NokiaE71-cec7> Playing 'tt-weasels.slin' (language 'en')


At this point the call just sits at the Playing tt-weasels.slin and I don't hear any audio. The thing is that it just sits there and doesn't actually move past it, so it's not like the audio just isn't passed... so not entirely sure exactly what it's doing there.
By: Matthew Nicholson (mnicholson) 2010-07-01 08:14:51

In order to fix this a check for (errno == EINTR || errno == EAGAIN) should be added to the loop in do_sco_listen() and those two error conditions should be ignored instead of exiting the loop.

Also exiting the thread is probably never the best choice here, because that will cause things to silently fail in the future.  Perhaps a big warning should be printed in the event of a fatal failure and the thread should sleep for a few mins then try again.
By: Russell Bryant (russell) 2011-07-27 13:30:18.281-0500

Per the Asterisk maintenance timeline page at http://www.asterisk.org/asterisk-versions maintenance (bug) support for the 1.4 and 1.6.x branches has ended. For continued maintenance support please move to the 1.8 branch which is a long term support (LTS) branch. For more information about branch support, please see https://wiki.asterisk.org/wiki/display/AST/Asterisk+Versions

If this is still an issue, please open a new issue so it can be re-triaged appropriately. Thanks!