943618 - complete audio silence with (at least some plantronics) headsets

Status: RESOLVED FIXED

(Core :: WebRTC: Audio/Video, defect)

Description

[Dan Mosedale (:dmosedale, :dmose)]

Recently, we've started seeing talkilla calls become unusable due to audio-silence on one side.  After some debugging, we've learned a number of things:

* this seems to be somehow triggered by (at least) some plantronics headsets
* we see it fairly frequently on Firefox 27 and 28, rarely (if ever) on 26

Recent scenarios I've hit: the audio to the caller's plantronics headset is working, because the caller hears OS sounds and even the talkilla "ringing" sound through the headset.  However, the audio coming from the callee is either silent to the caller the whole time, or present for a few seconds and then silent.

I'll attach mtransport and signalling logs for the caller's side both for a call on beta that had functional audio, and a call on 28 that had non-functional audio.

Comment 1

[Dan Mosedale (:dmosedale, :dmose)]

More info about my end:

Mac OS X 10.8.5
Headset: Plantronics .Audio 646 DSP on USB 3.0 Hi-Speed Bus
MacBook Pro w/2.6 GHz Intel Core i7

Once, I saw unplugging and replugging the headset fix the problem.

The upcoming logs are mtransport:5,signalling:5, and I _think_, but am not certain, that I was the caller on both of them.

Comment 2

[Dan Mosedale (:dmosedale, :dmose)]

Attachment: log from beta (26) of call with working audio

Also possibly relevant: this stderr output:

Timecard created 1385402632.470325

 Timestamp   | Delta       | Event                         | File                         | Function               
====================================================================================================================
    0.000059 |    0.000059 | Constructor Completed         | PeerConnectionImpl.cpp:355   | PeerConnectionImpl     
    0.000379 |    0.000320 | Initializing PC Ctx           | PeerConnectionImpl.cpp:608   | Initialize             
    0.004158 |    0.003779 | Done Initializing PC Ctx      | PeerConnectionImpl.cpp:614   | Initialize             
    0.004522 |    0.000364 | Generating DTLS Identity      | PeerConnectionImpl.cpp:651   | Initialize             
    0.045953 |    0.041431 | Done Generating DTLS Identity | PeerConnectionImpl.cpp:654   | Initialize             
    0.200659 |    0.154706 | Ice state: waiting            | PeerConnectionImpl.cpp:1562  | IceStateChange_m       
    4.024284 |    3.823625 | Create Offer                  | PeerConnectionImpl.cpp:1022  | CreateOffer            
    4.025969 |    0.001685 | Processing create offer event |           ccprovider.c:666   | processSessionEvent    
    4.025980 |    0.000011 | Sending message to queue      |                ccapi.c:1238  | send_message_helper    
    4.032430 |    0.006450 | Posting message to PC         |                   ui.c:1573  | post_message_helper    
    4.033126 |    0.000696 | Operation Completed           | PeerConnectionImpl.cpp:1406  | onCallEvent            
    4.033652 |    0.000526 | Set Local Description         | PeerConnectionImpl.cpp:1073  | SetLocalDescription    
    4.033666 |    0.000014 | Processing set local event    |           ccprovider.c:676   | processSessionEvent    
    4.033685 |    0.000019 | Sending message to queue      |                ccapi.c:1238  | send_message_helper    
    4.034596 |    0.000911 | Posting message to PC         |                   ui.c:1573  | post_message_helper    
    4.034711 |    0.000115 | Operation Completed           | PeerConnectionImpl.cpp:1406  | onCallEvent            
   14.364140 |   10.329429 | Set Remote Description        | PeerConnectionImpl.cpp:1093  | SetRemoteDescription   
   14.364189 |    0.000049 | Processing set remote event   |           ccprovider.c:680   | processSessionEvent    
   14.364222 |    0.000033 | Sending message to queue      |                ccapi.c:1238  | send_message_helper    
   14.366822 |    0.002600 | ICE Attributes Installed      |               fsmdef.c:3802  | fsmdef_ev_setremotedesc
   14.390415 |    0.023593 | Posting message to PC         |                   ui.c:1573  | post_message_helper    
   14.390814 |    0.000399 | Operation Completed           | PeerConnectionImpl.cpp:1406  | onCallEvent            
   14.720294 |    0.329480 | Ice state: connected          | PeerConnectionImpl.cpp:1568  | IceStateChange_m       
   41.502586 |   26.782292 | Destructor Invoked            | PeerConnectionImpl.cpp:361   | ~PeerConnectionImpl

Comment 3

[Dan Mosedale (:dmosedale, :dmose)]

Attachment: log from nightly (28) with non-functioning audio

Also conceivably relevant, the stderr output from this call:

Timecard created 1385402125.315146

 Timestamp   | Delta       | Event                         | File                         | Function               
====================================================================================================================
    0.000043 |    0.000043 | Constructor Completed         | PeerConnectionImpl.cpp:476   | PeerConnectionImpl     
    0.000406 |    0.000363 | Initializing PC Ctx           | PeerConnectionImpl.cpp:727   | Initialize             
    0.004217 |    0.003811 | Done Initializing PC Ctx      | PeerConnectionImpl.cpp:733   | Initialize             
    0.004616 |    0.000399 | Generating DTLS Identity      | PeerConnectionImpl.cpp:770   | Initialize             
    0.106134 |    0.101518 | Done Generating DTLS Identity | PeerConnectionImpl.cpp:773   | Initialize             
    0.371970 |    0.265836 | Ice state: waiting            | PeerConnectionImpl.cpp:1669  | IceStateChange_m       
    6.188176 |    5.816206 | Create Offer                  | PeerConnectionImpl.cpp:1099  | CreateOffer            
    6.188720 |    0.000544 | Processing create offer event |           ccprovider.c:666   | processSessionEvent    
    6.188729 |    0.000009 | Sending message to queue      |                ccapi.c:1246  | send_message_helper    
    6.192877 |    0.004148 | Posting message to PC         |                   ui.c:1574  | post_message_helper    
    6.193053 |    0.000176 | Operation Completed           | PeerConnectionImpl.cpp:1510  | onCallEvent            
    6.193583 |    0.000530 | Set Local Description         | PeerConnectionImpl.cpp:1140  | SetLocalDescription    
    6.193599 |    0.000016 | Processing set local event    |           ccprovider.c:676   | processSessionEvent    
    6.193614 |    0.000015 | Sending message to queue      |                ccapi.c:1246  | send_message_helper    
    6.193955 |    0.000341 | Posting message to PC         |                   ui.c:1574  | post_message_helper    
    6.194042 |    0.000087 | Operation Completed           | PeerConnectionImpl.cpp:1510  | onCallEvent            
   19.558997 |   13.364955 | Set Remote Description        | PeerConnectionImpl.cpp:1160  | SetRemoteDescription   
   19.559015 |    0.000018 | Processing set remote event   |           ccprovider.c:680   | processSessionEvent    
   19.559044 |    0.000029 | Sending message to queue      |                ccapi.c:1246  | send_message_helper    
   19.561545 |    0.002501 | ICE Attributes Installed      |               fsmdef.c:3853  | fsmdef_ev_setremotedesc
   19.584287 |    0.022742 | Posting message to PC         |                   ui.c:1574  | post_message_helper    
   19.584563 |    0.000276 | Operation Completed           | PeerConnectionImpl.cpp:1510  | onCallEvent            
   19.968892 |    0.384329 | Ice state: connected          | PeerConnectionImpl.cpp:1675  | IceStateChange_m       
   59.541718 |   39.572826 | Destructor Invoked            | PeerConnectionImpl.cpp:482   | ~PeerConnectionImpl

Comment 4

[Dan Mosedale (:dmosedale, :dmose)]

Interestingly, https://bugzilla.mozilla.org/show_bug.cgi?id=879576 sounds somewhat similar to this.

I believe both Mark and Florian are likely to have more data to add this bug tomorrow.

Comment 5

[Mark Banner (:standard8)]

I'm also on Mac 10.8, but using a Logitech USB headset, and I'm not affected by the issues.

Florian mentioned on irc that he could reproduce on https://apprtc.appspot.com, and that the regression range was:

Last good nightly: 2013-10-24
First bad nightly: 2013-10-25

http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=19fd3388c372&tochange=9f8233fcce1d 

Bug 928797 is one of 4 obvious audio bugs landed in that range, but looks more likely to have potentially caused this issue.

Florian is going to try and confirm that bug as the issue tomorrow I believe.

Comment 6

[Florian Quèze [:florian]]

(In reply to Mark Banner (:standard8) from comment #5)

> Florian is going to try and confirm that bug as the issue tomorrow I believe.

I bisected, and the changeset causing the regression is:
http://hg.mozilla.org/mozilla-central/rev/348904f9fc0c

Just in case this is of any use, here is the list of revisions that mozregression made me test and the test result:
bad: 152023:fe16e582db9f
good: 151988:cf2089a7c924
bad: 152005:df702b934950
bad 151996:e3c9d95e5bc0
good: 151992:cdfbe1d54ba1
bad: 151994:1203ba8ffc0d
bad: 151993:348904f9fc0c

Comment 7

[Paul Adenot (:padenot)]

Someone should ship me those headphones so I can try to repro and fix it.

Comment 8

[Paul Adenot (:padenot)]

Ha, the changeset that causes the regression is the backout of the feature, this does not make any sense.

Comment 9

[Florian Quèze [:florian]]

(In reply to Paul Adenot (:padenot) from comment #7)
> Someone should ship me those headphones so I can try to repro and fix it.

It's the headset I got from Guillaume when I requested a new one on ServiceNow. I think there's a stock of them in the Paris office.

Comment 10

[Florian Quèze [:florian]]

The exact reference of my headset is "Plantronics .Audio 648 USB", and I'm on OS X 10.8.2.

Comment 11

[Paul Adenot (:padenot)]

Indeed, he gave me one. I'll write the patch, now.

Comment 12

[Paul Adenot (:padenot)]

Okay. What happens here is that the driver for this headset cannot handle the lowest latency it says it can handle. My guess is that there is a bug in the headset driver.

A couple solutions:

- detect what headset is being used, and request a higher latency when we see a headset we know have problem.
- request higher latency all the time for MacOS. Note that this will be better than any other platforms we support anyways, so it's not the end of the world.

Thoughts ? Other solutions ?

Comment 13

[Mark Banner (:standard8)]

I think this also affects the Logitech H555 headset (the one I mentioned earlier was the H550). The effect is slightly different - the sound plays, but is distorted with a fuzziness type sound.

Comment 14

[Dan Mosedale (:dmosedale, :dmose)]

(In reply to Paul Adenot (:padenot) from comment #12)
> Okay. What happens here is that the driver for this headset cannot handle
> the lowest latency it says it can handle. My guess is that there is a bug in
> the headset driver.

Good times. :-)

> A couple solutions:
> 
> - detect what headset is being used, and request a higher latency when we
> see a headset we know have problem.
> - request higher latency all the time for MacOS. Note that this will be
> better than any other platforms we support anyways, so it's not the end of
> the world.
> 
> Thoughts ? Other solutions ?

Assuming it's sufficiently straightforward to write & maintain, my guess is that a headset lookup table would be the way to go.  Presumably a decent chunk of Mac users do most or all of their work on a Mac, so they'd be more likely to mentally notice a difference between Mac applications, rather than between Firefox on different platforms.  The issue being that if the difference in latency is either (on its own, or combined with other latency in the pipeline) is _perceptibly_ different between Firefox and other Mac apps, that hurts our relative user experience. In that case, the idea of penalizing all headsets for the misbehavior of a few would seem to work against our larger interests.  Of course, this depends entirely on perceptibility.

Paul, do you have any idea whether this bug is likely to manifest on Windows too?

Comment 15

[Randell Jesup [:jesup] (needinfo me)]

On mac, the requested latencies can get down <10ms (I had to add a patch to avoid cubeb rounding down to 0ms on my MacBook Pro 2011, and 1ms requested got 4ms IIRC).   So a few more ms won't be noticable.  How much more do you think would be needed paul?

Comment 16

[Paul Adenot (:padenot)]

I'm not sure, but one can certainly experiment using the pref "media.cubeb_latency_ms" in about:config (if this value is set, it is preferred to the min value the OS gives us).

If someone here could try to bisect a good value with the specific hardware that causes the problem, we could try to up the limit a bit, or try to devise a plan if the latency we have to request to avoid the glitching is too high.

Comment 17

[Florian Quèze [:florian]]

Paul, I tested various values of the media.cubeb_latency_ms pref with my headset (Plantronics .Audio 648 USB), here are the results:
- 25 is the lowest value that outputs excellent sound.
- values between 24 and 12 produce crackling noise (very minor at 24; covering the expected output completely at 12).
- with 11 and lower, there's no output at all: complete silence.

Hope this helps. Mark may still want to test with his headset, as he has a different one (comment 13).

Comment 18

[Mark Banner (:standard8)]

With my Logitech H555 testing I've done a couple of things. I also have a USB hub where the headset was originally plugged in when I saw this issue.

From my testing:

- without media.cubeb_latency_ms set, I get crackling noise both directly plugged into my mac and via the USB hub.
- with media.cubeb_latency_ms set to 0 I get good audio only when directly plugged into my mac
- media.cubeb_latency_ms needs to be set to a minimum of 3 for me to get good audio in both direct mac and via the USB hub.

Comment 19

[Dan Mosedale (:dmosedale, :dmose)]

My understanding from Mark is that you've now got enough info to move forward.  Feel free to re-ping with needinfo if I've misunderstood.

Comment 20

[Florian Quèze [:florian]]

Attachment: Patch

Comment 21

[Paul Adenot (:padenot)]

Comment on attachment 8368555 [details] [diff] [review]
Patch

Review of attachment 8368555 [details] [diff] [review]:
-----------------------------------------------------------------

We don't have a clear solution that would be better than to revert to the state before bug 907817, so we just do that.

The latency is low enough on OSX anyways that it really does not affect user experience. We can revisit later if we find a magic solution to find the _headset_ latency, rather than OSX's default latency (which is what seems to be reported).

Comment 22

[Florian Quèze [:florian]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/eca43063ea0f

Comment 23

[Florian Quèze [:florian]]

Comment on attachment 8368555 [details] [diff] [review]
Patch

[Approval Request Comment]
Bug caused by (feature/regressing bug #): bug 907817
User impact if declined: No sound at all or cracking sounds for Mac users when starting a WebRTC call with a USB headset.
Testing completed (on m-c, etc.): (not reached m-c yet)
Risk to taking this patch (and alternatives if risky): Low; the patch just reverts to the behavior we had before.
String or IDL/UUID changes made by this patch: none.

I'm afraid it's too late to fix this for Firefox 27, but we should at least fix it for 28.

Comment 24

[Lukas Blakk [:lsblakk] use ?needinfo]

No need to track this, will approve for uplift once it's on mozilla-central without issues.

Comment 25

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/eca43063ea0f

Comment 26

[Sylvestre Ledru [:Sylvestre]]

Comment on attachment 8368555 [details] [diff] [review]
Patch

Sounds good Florian for Aurora!

Comment 27

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/e9224caee6bb

Comment 28

[Catalin Varga [QA][:VarCat]]

I verified this bug using the following setup:

Firefox 28.0b9
Build Id:20140306171728
User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.9; rv:28.0) Gecko/20100101 Firefox/28.0
Os: Mac Os X 10.9
Headsets: Microsoft Lifechat LX - 3000

and the issue is reproducible. As you can see I used a different model for the headsets because we didn't have the same model as the one from this bug. I choose this model because it was the only USB headset available.