Reproducible with: - Firefox 38 Beta 9 - BuildID: 20150429135941 - Firefox 40 Nightly latest - BuildID: 20150429030202 Reproducible on: Windows 7 x64 (did NOT try Mac or Linux) Prerequisites: Logitech QuickCam Fusion webcam Steps to reproduce: 1. Open Firefox with a fresh profile. 2. Take part in a Hello conversation: either create one (click the Hello button in the toolbar and create a conversation) or join one (click on a link from someone else). 3. Click on the camera button to disable video for the Logitech QuickCam Fusion webcam. 4. After 1-2 seconds re-enable video. Expected results: The other side will see the video restored immediately and then continue without delay. Actual results: The other side sees one frozen frame for up to 8 seconds, and then video resumes but with a delay of ~2 seconds. Notes: - prior to disabling the camera at step 3, the other side sees the video from Logitech QuickCam Fusion without any delay - the issue does NOT show on Firefox 37.0 - there the other side will see a black frame for 1-2 seconds after video is re-enabled, and then the video continues with no delay - the issue shows in Firefox 38 beta 1, so it seems that it was introduced somewhere in Firefox 38 - the issue is linked to this specific camera - it did not show with other webcams that we have, and it still showed after connecting it to another PC
I suspect this is most likely a core issue. We did change the sdks that we use between 37 & 38, but I doubt they'd affect this specific item. Maire, any ideas?
Let me summarize this things that changed that could be involved. Please chime in if I missed something. Things that changed in 38: the SDK, Byron's landing early on of renegotiation and multistream, and the webrtc 40 import. I'm not sure when the SDK change landed, but I know both Bryon's rewrite and the webrtc 40 import landed early in 38 nightly (but on different days), so regression testing should work on 38 Nightly Interesting question: on disabling the camera, does it merely set video_track.enabled to false, or does it actually change the call? If it changes the call, does it use RTPSender.replaceTrack() or not? The behavior in 37 and 38 implies it changes the call. A big question is if the SDK changed from replacing the call with a new one in 37 (since there's no renegotiation) to using renegotiation? It's very unusual and interesting that it's tied to the camera as well. Is just the video delayed, or are both video and audio delayed?
Here's some additional info from what I've investigated today: - this issue affects only Video, NOT Audio - Audio remains in sync and works without delay when Video is frozen (right after re-enabling the camera) and afterwards when Video is received with 1-2 seconds delay - the issue is more visible with Firefox 38 Beta 9, but seems to be visibly improved on Firefox 38 RC: there is only a 2-4 second freeze when re-enabling Video, and then the Video delay is of ~0.5-1 seconds (still perceivable). I'm not sure which change could have affected this, but it must have entered in Firefox 38 RC: bug 1159300 and bug 1146061 were WebRTC fixes in 38 RC.
Can you do a run with NSPR_LOG_MODULES=signaling:6,webrtc_trace:65535,timestamp WEBRTC_TRACE_FILE=nspr ? Compress and attach the output, or email it to me. Try to keep the overall test short, just long enough to be sure you're seeing what you expect. Then repeat the test with 37 so we can compare. Thanks Note this level of logging may impact functionality; if it's too slow and things don't work, please drop to 5 for signaling
Created attachment 8601479 [details] 37_38b9_logs.zip Logs taken with 37.0.2 and 38b9.
Thanks; I'm seeing something weird; it seems to be inserting (VideoConduit::SendVideoFrame Inserted a frame) around 100 frames/second. Can you redo the test with NSPR_LOG_MODULES=getusermedia:6,mediamanager:6,timestamp ? Also, I assume only a single call is being made via Loop, correct? Is this from the link-sharer or link-clicker side? Thanks!
(In reply to Randell Jesup [:jesup] from comment #6) > Can you redo the test with > NSPR_LOG_MODULES=getusermedia:6,mediamanager:6,timestamp ? I've tried what you've suggested, but unfortunately whenever I initiate/join a conversation I also get a crash (e.g. bp-36729bf6-7bf1-4b29-8cc6-27b812150506). I used the following in cmd: set NSPR_LOG_MODULES=getusermedia:6,mediamanager:6,timestamp set WEBRTC_TRACE_FILE=nspr set NSPR_LOG_FILE=%TEMP%\log38b9_2.txt .\firefox.exe Did I do something wrong Randell? > Also, I assume only a single call is being made via Loop, correct? Is this > from the link-sharer or link-clicker side? Yes, only one call was made, one camera disabling and one camera re-enabling, then closed Firefox after about 3-4 seconds (when I was convinced I was seeing the issue). The logs were taken from the link-sharer side.
(In reply to Florin Mezei, QA (:FlorinMezei) from comment #7) > (In reply to Randell Jesup [:jesup] from comment #6) > > Can you redo the test with > > NSPR_LOG_MODULES=getusermedia:6,mediamanager:6,timestamp ? > > I've tried what you've suggested, but unfortunately whenever I initiate/join > a conversation I also get a crash (e.g. > bp-36729bf6-7bf1-4b29-8cc6-27b812150506). Looks like a bad format at least on your platform; probably %lld instead of %ld (canonically it's more like "foo=" PRIu64 " bar=" PRIu64 etc). Drop mediamanager to 5 or change that format line that's crashing in MediaEngineWebrtcVideo.cpp thanks
Created attachment 8602773 [details] logs2.zip Logs with mediamanager:5.
(In reply to Florin Mezei, QA (:FlorinMezei) from comment #9) > Created attachment 8602773 [details] > logs2.zip > > Logs with mediamanager:5. I still need getusermedia:6,timestamp (i.e. mediamanager:5,getusermedia:6,timestamp). I'd definitely prefer it if you can try it with the fix (or try it on a 64-bit build with mediamanager:6); mediamanager:5 logs don't log individual frames. If you can't get mediamanager:6 logs to work try this: NSPR_LOG_MODULES=mediamanager:5,getusermedia:6,timestamp,webrtc_trace:65535 WEBRTC_TRACE_FILE=nspr NSPR_LOG_FILE=whatever Thanks
Also: please retest with 40 - bug 1150539 is at least making it select a different resolution/framerate, though I can't see why that would matter here unless there's a bug in the camera (which is possible).
Created attachment 8603317 [details] logs_x64.zip I've retested this using the latest Firefox 40 x64 and Firefox 38b9 x64, using: set NSPR_LOG_MODULES=getusermedia:6,mediamanager:6,timestamp set WEBRTC_TRACE_FILE=nspr set NSPR_LOG_FILE=%TEMP%\log38b9_2.txt .\firefox.exe I've attached the two logs. Note that the issue shows for 38 Beta 9, but not so much for Firefox 40. Firefox 40 x64 and x86 work well with ~2-3 seconds delay after webcam is re-enabled, and just about ~0.5 seconds delay in Video and Audio (Video and Audio are in sync)... this is the same behavior that I saw in Firefox 38 RC, so it's likely that a fix that landed in 38 RC fixed this.
Florin - do I understand correctly that you believe this is fixed?
(In reply to Randell Jesup [:jesup] from comment #13) > Florin - do I understand correctly that you believe this is fixed? Yes, it appeared to be fixed. I will however give it another try when I get a bit of time, and update the bug (I'm leaving the needinfo on for this).
I've re-tested today on Windows 7 x64, with Firefox 39 Beta 6, latest Aurora 40 and latest Nightly 41, and I get the same results as reported in comment 12: ~2-3 seconds delay after webcam is re-enabled, and just about ~0.5 seconds delay in Video and Audio (Video and Audio are in sync - sound seems to be just very slightly delayed from the video, but difficult to tell). Since the results above are far from the issues initially reported in this bug, I'm resolving this.