cpaulin@ and/or niklase@ - can you take a look? I took a quick glance at the bisect range, and nothing obvious stands out. If I had to guess, I would suspect https://codereview.chromium.org/1759323003, but that is just a guess.

I can reproduce the problem on win 10 canary.

Could reproduce on Win7 with a ToT debug build (#384705). 

The recorded video looks fine but the playback doesn't like it:

[3860:13344:0401/164620:WARNING:webmediaplayer_impl.cc(315)] Using MultibufferDataSource
[3860:14004:0401/164620:ERROR:ffmpeg_audio_decoder.cc(397)] Could not initialize audio decoder: 86077

and then, probably harmless:
[13604:13100:0401/164620:INFO:gpu_video_decode_accelerator.cc(399)] Initializing DXVA HW decoder for windows.
[13604:13100:0401/164620:ERROR:dxva_video_decode_accelerator_win.cc(1440)] Unsupported codec.
[13604:13100:0401/164620:ERROR:gpu_video_decode_accelerator.cc(387)] HW video decode not available for profile 11
[3860:14004:0401/164620:ERROR:gpu_video_decode_accelerator_host.cc(98)] Send(GpuCommandBufferMsg_CreateVideoDecoder()) failed
[3860:14004:0401/164620:ERROR:gpu_video_decoder.cc(720)] VDA Error: 4


Vlc on Windows plays it fine (see my short cameo attached).

Deleted: test.webm 235 KB

test.webm 235 KB Download

dalecurtis@ just to confirm: ffmpeg on Windows ToT
should or should not support WebM with Opus and VP8?
(assume yes, yes, and yes).

vda doesn't support profile 11 which is vp8 IIRC. ffmpeg will decode vp8 and libopus will decode opus. the logs in this case are harmless.

What does chrome://media-internals say?

Player properties:

render_id: 4
player_id: 1
pipeline_state: kPlaying
event: PLAY
url: blob:https%3A//webrtc.github.io/78d81c08-de55-478b-a965-fc3abdb382d7
total_bytes: 161599
streaming: false
single_origin: true
passed_cors_access_check: false
range_header_supported: true
info: FFmpegDemuxer: created audio stream, config codec: opus bytes_per_channel: 4 channel_layout: 2 samples_per_second: 48000 sample_format: 4 bytes_per_frame: 4 seek_preroll: 0ms codec_delay: 0 has extra data? true encrypted? false
duration: unknown
audio_channels_count: 1
audio_codec_name: opus
audio_sample_format: Float 32-bit
audio_samples_per_second: 48000
bitrate: 0
coded_height: 480
coded_width: 640
found_audio_stream: true
found_video_stream: true
height: 480
max_duration: kInfiniteDuration
start_time: 0
time_base: 1/1000
video_codec_name: vp8
video_format: PIXEL_FORMAT_YV12
video_is_encrypted: false
width: 640
audio_dds: false
audio_decoder: OpusAudioDecoder
video_dds: false
video_decoder: FFmpegVideoDecoder

and then the log says:

Log 
property filter

Timestamp	Property	Value
00:00:00 00	pipeline_state	kCreated
00:00:00 00	event	WEBMEDIAPLAYER_CREATED
00:00:00 01	url	blob:https%3A//webrtc.github.io/78d81c08-de55-478b-a965-fc3abdb382d7
00:00:00 14	total_bytes	161599
00:00:00 14	streaming	false
00:00:00 14	single_origin	true
00:00:00 14	passed_cors_access_check	false
00:00:00 14	range_header_supported	true
00:00:00 28	pipeline_state	kInitDemuxer
00:00:00 37	info	FFmpegDemuxer: created video stream, config codec: vp8 format: 2 profile: vp8 coded size: [640,480] visible rect: [0,0,640,480] natural size: [640,480] has extra data? false encrypted? false
00:00:00 38	info	FFmpegDemuxer: created audio stream, config codec: opus bytes_per_channel: 4 channel_layout: 2 samples_per_second: 48000 sample_format: 4 bytes_per_frame: 4 seek_preroll: 0ms codec_delay: 0 has extra data? true encrypted? false
00:00:00 39	duration	unknown
00:00:00 39	audio_channels_count	1
00:00:00 39	audio_codec_name	opus
00:00:00 39	audio_sample_format	Float 32-bit
00:00:00 39	audio_samples_per_second	48000
00:00:00 39	bitrate	0
00:00:00 39	coded_height	480
00:00:00 39	coded_width	640
00:00:00 39	found_audio_stream	true
00:00:00 39	found_video_stream	true
00:00:00 39	height	480
00:00:00 39	max_duration	kInfiniteDuration
00:00:00 39	start_time	0
00:00:00 39	time_base	1/1000
00:00:00 39	video_codec_name	vp8
00:00:00 39	video_format	PIXEL_FORMAT_YV12
00:00:00 39	video_is_encrypted	false
00:00:00 39	width	640
00:00:00 39	pipeline_state	kInitRenderer
00:00:00 40	audio_dds	false
00:00:00 40	audio_decoder	OpusAudioDecoder
00:00:00 49	video_dds	false
00:00:00 49	video_decoder	FFmpegVideoDecoder
00:00:00 50	pipeline_state	kPlaying
00:00:00 83	event	PLAY

With more logging I get the impression that WMPImpl-wise
everything looks OK, this is the log after I passed the
video to play into the <video> tag:

[13480:11820:0401/170304:INFO:CONSOLE(148)] "Recorded Blobs: ", source: https://webrtc.github.io/samples/src/content/getusermedia/record/js/main.js (148)
[13480:11820:0401/170304:INFO:CONSOLE(98)] "Recorder stopped: ", source: https://webrtc.github.io/samples/src/content/getusermedia/record/js/main.js (98)
[10044:6372:0401/170305:VERBOSE1:webmediaplayer_impl.cc(490)] media::WebMediaPlayerImpl::setVolume(1)
[10044:6372:0401/170305:VERBOSE1:webmediaplayer_impl.cc(518)] media::WebMediaPlayerImpl::setPreload(2)
[10044:6372:0401/170305:VERBOSE1:webmediaplayer_impl.cc(264)] media::WebMediaPlayerImpl::load(0, blob:https%3A//webrtc.github.io/a66556c6-eb98-4804-bef0-642cf2bfe34c, 0)
[10044:6372:0401/170305:VERBOSE1:webmediaplayer_impl.cc(289)] media::WebMediaPlayerImpl::DoLoad
[10044:6372:0401/170305:VERBOSE1:webmediaplayer_impl.cc(1360)] media::WebMediaPlayerImpl::SetNetworkState(2)
[10044:6372:0401/170305:VERBOSE1:webmediaplayer_impl.cc(1368)] media::WebMediaPlayerImpl::SetReadyState(0)
[10044:6372:0401/170305:WARNING:webmediaplayer_impl.cc(315)] Using MultibufferDataSource
[10044:6372:0401/170305:VERBOSE1:render_media_log.cc(26)] MediaEvent: PIPELINE_STATE_CHANGED {"pipeline_state":"kCreated"}
[10044:6372:0401/170305:VERBOSE1:render_media_log.cc(26)] MediaEvent: WEBMEDIAPLAYER_CREATED {}
[10044:6372:0401/170305:VERBOSE1:render_media_log.cc(26)] MediaEvent: LOAD {"url":"blob:https%3A//webrtc.github.io/a66556c6-eb98-4804-bef0-642cf2bfe34c"}
[10044:6372:0401/170305:VERBOSE1:webmediaplayer_impl.cc(1245)] media::WebMediaPlayerImpl::DataSourceInitialized
[10044:6372:0401/170305:VERBOSE1:render_media_log.cc(26)] MediaEvent: PIPELINE_STATE_CHANGED {"pipeline_state":"kInitDemuxer"}
[10044:6372:0401/170305:VERBOSE1:render_media_log.cc(26)] MediaEvent: MEDIA_INFO_LOG_ENTRY {"info":"FFmpegDemuxer: created video stream, config codec: vp8 format: 2 profile: vp8 coded size: [640,480] visible rect: [0,0,640,480] natural size: [640,480] has extra data? false encrypted? false"}
[10044:6372:0401/170305:VERBOSE1:render_media_log.cc(26)] MediaEvent: MEDIA_INFO_LOG_ENTRY {"info":"FFmpegDemuxer: created audio stream, config codec: opus bytes_per_channel: 4 channel_layout: 2 samples_per_second: 48000 sample_format: 4 bytes_per_frame: 4 seek_preroll: 0ms codec_delay: 0 has extra data? true encrypted? false"}
[10044:6372:0401/170305:VERBOSE1:render_media_log.cc(26)] MediaEvent: DURATION_SET {"duration":"unknown"}
[10044:10876:0401/170305:ERROR:ffmpeg_audio_decoder.cc(397)] Could not initialize audio decoder: 86077
[10044:6372:0401/170305:VERBOSE1:render_media_log.cc(26)] MediaEvent: PIPELINE_STATE_CHANGED {"pipeline_state":"kInitRenderer"}
[10044:6372:0401/170305:VERBOSE1:webmediaplayer_impl.cc(985)] media::WebMediaPlayerImpl::OnPipelineMetadata
[10044:6372:0401/170305:VERBOSE1:webmediaplayer_impl.cc(1368)] media::WebMediaPlayerImpl::SetReadyState(1)
[11216:11140:0401/170305:INFO:gpu_video_decode_accelerator.cc(399)] Initializing DXVA HW decoder for windows.
[11216:11140:0401/170305:ERROR:dxva_video_decode_accelerator_win.cc(1440)] Unsupported codec.
[11216:11140:0401/170305:ERROR:gpu_video_decode_accelerator.cc(387)] HW video decode not available for profile 11
[10044:10876:0401/170305:ERROR:gpu_video_decode_accelerator_host.cc(98)] Send(GpuCommandBufferMsg_CreateVideoDecoder()) failed
[10044:10876:0401/170305:ERROR:gpu_video_decoder.cc(720)] VDA Error: 4
[11216:4560:0401/170305:ERROR:gpu_channel.cc(571)] Could not find message queue
[10044:6372:0401/170305:VERBOSE1:render_media_log.cc(26)] MediaEvent: PIPELINE_STATE_CHANGED {"pipeline_state":"kPlaying"}
[10044:6372:0401/170305:VERBOSE1:webmediaplayer_impl.cc(1022)] media::WebMediaPlayerImpl::OnPipelineBufferingStateChanged(1)
[10044:6372:0401/170305:VERBOSE1:webmediaplayer_impl.cc(1368)] media::WebMediaPlayerImpl::SetReadyState(4)
[10044:6372:0401/170305:VERBOSE1:webmediaplayer_impl.cc(1360)] media::WebMediaPlayerImpl::SetNetworkState(3)
[10044:6372:0401/170305:VERBOSE1:webmediaplayer_impl.cc(461)] media::WebMediaPlayerImpl::setRate(1)
[10044:6372:0401/170305:VERBOSE1:webmediaplayer_impl.cc(490)] media::WebMediaPlayerImpl::setVolume(1)
[10044:6372:0401/170305:VERBOSE1:webmediaplayer_impl.cc(339)] media::WebMediaPlayerImpl::play
[10044:6372:0401/170305:VERBOSE1:render_media_log.cc(26)] MediaEvent: PLAY {}

Playback looks fine. You might add logging to VideoRendererImpl::Render() to see which frame its picking and to VideoRendererImpl::FrameReady() to see what timestamps are being queued. If it has audio you should log the audio time in AudioRendererImpl.

If playback is frozen but things aren't in an error state, it's likely that the renderers think the timestamps are far in the future or incorrect in some other way.

Continuing investigation and updated name
https://cdn.rawgit.com/Miguelao/demos/master/mediarecorder.html,
which has no audio capture, works fine. 

I think I found the issue: the timestamps of audio
and video have different origins which makes line [1] in
WebmMuxer::AddFrame() jump wildly causing the freeze
in certain players (notably Chrome).


[1] https://code.google.com/p/chromium/codesearch#chromium/src/media/muxers/webm_muxer.cc&q=webmmuxer::addframe&sq=package:chromium&type=cs&l=289

I had an interchange with miu@ on the CL I think is  worth
reposting here:

On 2016/04/06 00:49:01, miu wrote:
> lgtm, HOWEVER: The reason the timestamps are far apart is because there is
> more/less playout buffering going on for audio versus video.  The timestamps
> should be reflecting the playout time at which each frame should be displayed
> on screen (or, for audio, when each frame should come out the speaker).
> 
> With this change, I'm willing to bet A/V sync is now a problem.  At least, it
> will be on some platforms.  Solving this may involve having your WebM muxer
> queuing-up either audio or video (or both), and then only output both to the
> WebM container once they've been aligned w.r.t. their playout timestamps.
> 
> So, I'm lgtm'ing this, and leave it up to you to decide whether this change
> should be committed as-is, and whether the A/V sync performance aspects of
> your feature should be addressed now or later.

I don't think this is a case of audio/video sync adjustments. I 
printed out the base::TimeTicks timestamps of the incoming video
and audio recorded frames and I got the following numbers. 

First a bunch of Video Frames arrive with correlative timestamps

media::WebmMuxer::OnEncodedVideo - 59928B @ 2149924 bogo-microseconds
media::WebmMuxer::OnEncodedVideo: delaying until audio track ready.
media::WebmMuxer::OnEncodedVideo - 108B @ 2183258 bogo-microseconds
media::WebmMuxer::OnEncodedVideo: delaying until audio track ready.
media::WebmMuxer::OnEncodedVideo - 143B @ 2216591 bogo-microseconds
media::WebmMuxer::OnEncodedVideo: delaying until audio track ready.

and now the first Audio arrives with completely different timestamps:

media::WebmMuxer::OnEncodedAudio - 386B @ 1269455645930 bogo-microseconds
media::WebmMuxer::AddAudioTrack format: 1 channel_layout: 2 channels: 1
sample_rate: 48000 bits_per_sample: 16 frames_per_buffer: 2880 effects: 0
mic_positions:

and now they start mingling, each with their own reference.

media::WebmMuxer::OnEncodedVideo - 214B @ 2249924 bogo-microseconds
media::WebmMuxer::OnEncodedVideo - 217B @ 2283258 bogo-microseconds
media::WebmMuxer::OnEncodedVideo - 308B @ 2316591 bogo-microseconds
media::WebmMuxer::OnEncodedAudio - 383B @ 1269455771097 bogo-microseconds
media::WebmMuxer::OnEncodedVideo - 348B @ 2349924 bogo-microseconds
media::WebmMuxer::OnEncodedVideo - 309B @ 2383257 bogo-microseconds
media::WebmMuxer::OnEncodedVideo - 640B @ 2416591 bogo-microseconds
media::WebmMuxer::OnEncodedAudio - 383B @ 1269455878194 bogo-microseconds
media::WebmMuxer::OnEncodedVideo - 809B @ 2449924 bogo-microseconds
media::WebmMuxer::OnEncodedVideo - 977B @ 2483257 bogo-microseconds
media::WebmMuxer::OnEncodedVideo - 1118B @ 2516591 bogo-microseconds
media::WebmMuxer::OnEncodedAudio - 383B @ 1269455988642 bogo-microseconds
media::WebmMuxer::OnEncodedVideo - 1296B @ 2549924 bogo-microseconds

(I also checked that these timestamps correlate with
those coming from the Tracks, the recorders did not
interfere with them significantly).

qiangchen@ is it possible that Video and Audio capture
from local devices have very different TimeTick origins?
(And that this is platform-dependent?)

Re #13: Yes. We wrapped the raw timestamp from camera into TimeTick. So the TimeTick is not comparable to base::TimeTick::Now. Let me take look whether this is the cause.

Re #13: I've confirmed this is the cause. As webrtc now can resolve an arbitrary timestamp offset, so the raw timestamp works well with webrtc.

For recorder case, are you going to align video audio timestamps in WebmMuxer or, will I make a CL to align the camera timestamp with system timestamp at the frame generation stage?

P.S.
The original CL that uses camera timestamp for captured frames:
https://codereview.chromium.org/1324683004/

It gets essentially reverted, as webrtc does not resolve clock rate difference in: 
https://codereview.chromium.org/1671943003/

Later, webrtc resolved the clock rate difference, the revert gets reverted in:
https://codereview.chromium.org/1783603004/

We should align at webMMuxer if possible, otherwise we'll lose the advantage of HW timestamps.

#15: no need for you to further retimestamp, I have
a CL keeping different origins for audio and video
timestamps at [1]. miu@ was asking as to where the
change came from, and now we know.


[1] https://codereview.chromium.org/1863893002/

I think the ideal case is that we need to write a utility class that can smoothly translate Clock 1's timestamp to Clock 2's timestamp.

As we've encountered similar timestamp issue many times. Possibly, I can take over this. Any idea?

We need a quick fix for 51 so we should continue with mcasas' approach. 

Generally speaking I see a risk for a utility class like being used a lot for convenience, and that we could lose precision because of that, or get clock drift in other cases. It's better to have designs that acknowledge the fact that audio and video are driven by different clocks.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/aa575cd9100984ba7cf7fc0377d7c5d40abbdb5f

commit aa575cd9100984ba7cf7fc0377d7c5d40abbdb5f
Author: mcasas <mcasas@chromium.org>
Date: Thu Apr 07 22:15:46 2016

MediaStreamRecorder: Separate video/audio origin of timestamps for WebM muxer

In certain conditions (see bug), the origin of
timestamps for audio and video is quite separated
which causes a jump on the WebM frame timestamps.
This seems to be an issue for certain players (chrome)
and not so much for others (vlc).

This CL solves the problem by keeping a different
origin-of-timestamps for audio and video separately,
and passing a TimeDelta to the AddFrame() method.

See the bug for an investigation as to why this
started happening recently.

BUG= 597034 
TEST=On my Win7 laptop, navigate to [1], record
stream for a few seconds, then stop recording and
try playing back. With this CL, no freeze.

[1] https://webrtc.github.io/samples/src/content/getusermedia/record/

Review URL: https://codereview.chromium.org/1863893002

Cr-Commit-Position: refs/heads/master@{#385899}

[modify] https://crrev.com/aa575cd9100984ba7cf7fc0377d7c5d40abbdb5f/media/muxers/webm_muxer.cc
[modify] https://crrev.com/aa575cd9100984ba7cf7fc0377d7c5d40abbdb5f/media/muxers/webm_muxer.h

cpaulin@ please verify in the appropriate Canary.

Re-opening because, as I explained in my comments pasted into comment #12, Miguel's code change is a band-aid solution that papers over a bigger problem.

qiangcheng (per comment 14): I've filed  bug 601657  to explain why the video timestamps need to be fixed, and to track resolution of that.  It's likely the bad timestamps are also the main cause of  bug 587553 .

mcasas: Like I said, I understand the need for the short-term workaround for M51.  However, this issue isn't fixed until the root problem is addressed and the workaround reverted.

Since #20 patched the problem, I'm lowering the
prio to P2.

cpaulin@ can you please verify, regardless of
the status?

Problem is no longer present on Win 10 chrome canary version 52.0.2715.0

Renamed component Blink>MediaStreamRecording to Blink>MediaStream>Recording. Moving issues to the new component. 

Moving this nonessential bug to the next milestone.

For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot

Is there anything going into M53?

#28: nothing really to add to any dev rel items,
the band-aid solution miu@s mentioning in #23 is
in place (see #25), and I guess I'll eventually get 
to refry this bug into another one to solve more 
properly the underlying timestamp mismatch when I
get some time. 

This issue has been moved once and is lower than Pri-1. Removing the milestone.

For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot

What's the current status of this issue? Is any more work planned to be done here?

Can someone please verify this bug? I'm still not being able to play a video using MSE and feeding with webm chunks in sequence mode. Video freezes and only a few frames are showed and with poor quality.
Audio does not seem to make a difference, neither vp8 or vp9, vorbis or opus.

#32: this bug is about the recorded timestamps having
jumps in its monotonicity causing issues in playback, but
the problem you mention pertains to  https://crbug.com/606000 ,
since it's an MSE issue. IOW, if you can download the
recorded file and play it back correctly via either Chrome
or a player, then this is not the right bug :-)

FTR the issue there seems to be the different views of MR
(https://bugs.chromium.org/p/chromium/issues/detail?id=606000#c25)
and MSE 
(https://bugs.chromium.org/p/chromium/issues/detail?id=606000#c26)
of how discontinuous timestamp trains should be dealt with.

Bulk move
Blink>MediaStream>Recording ---> Blink>MediaRecording

Hey everyone,

Sorry if this is not the correct issue to comment on.

I have noticed similar (to the original issue statement) behaviour. Using https://webrtc.github.io/samples/src/content/getusermedia/record/ I tried recording a short clip, 3-4 seconds, but seemingly no blobs get captured, as seen in the attached screenshot. For clarification, this does not happen all the time. The circumstances under which this happens are unclear to me, it just starts happening randomly, then goes away after restarting the browser.

Deleted: Screen Shot 2017-01-20 at 14.12.56.png 422 KB

	Screen Shot 2017-01-20 at 14.12.56.png 422 KB View Download

mcasas@ are you currently looking at this one?

Just following up to see if there is any update on this?

Occasionaly, our customers still experience this behaviour with Chrome. We had a customer this morning who restarted their computer, but nothing changed. Switching to Firefox solved the problem for them.

karl@ do you still see this situation with the latest Canary (61+) ?
We have landed a few CLs that might affect the way the webm muxer
treats encoder errors which might affect (positively) your situation.

Also, I think we should separate the timestamp jumps out of this issue,
which has been around for a while, and in the new one we'll deal with
the comments of #12.