Add media log messages to the main log

Add media log messages to the main log

Currently media code uses a separate logging system (MediaLog) and some important messages are reported there, but are not reported in the main browser log. Currently media log messages can only be seen in the chrome://media-internals, but since they are very useful, we should add them to the main browser log as well.

BUG=453180
Committed: https://crrev.com/cdeb28057cd67404de3383f70208b43763473c6a
Cr-Commit-Position: refs/heads/master@{#322425}

[servolk, 2015-01-28 02:49:09]

servolk@chromium.org changed reviewers:
+ dalecurtis@chromium.org, gunsch@chromium.org, lcwu@chromium.org,
wolenetz@chromium.org

[servolk, 2015-01-28 03:12:00]

Media_log messages are very useful, let's add them to the main browser log as
well. Would this be a good place to add this or should this be done somewhere
else, e.g. in MediaInternals::OnMediaEvents or MediaInternals::SendUpdate? If we
added logging to the MediaInternals::OnMediaEvents or MediaInternals::SendUpdate
it would work for media logs instantiated anywhere, not just in webmediaplayer,
but I'm not sure how readable is the JSON string that we get there. Feel free to
suggest a better place to do this.

[servolk, 2015-01-28 03:19:48]

On 2015/01/28 03:12:00, servolk wrote:
> Media_log messages are very useful, let's add them to the main browser log as
> well. Would this be a good place to add this or should this be done somewhere
> else, e.g. in MediaInternals::OnMediaEvents or MediaInternals::SendUpdate? If
we
> added logging to the MediaInternals::OnMediaEvents or
MediaInternals::SendUpdate
> it would work for media logs instantiated anywhere, not just in
webmediaplayer,
> but I'm not sure how readable is the JSON string that we get there. Feel free
to
> suggest a better place to do this.

To add a bit more context, some important errors are reported into media log,
e.g. media segments not beginning with a key frame, segments with negative
timestamps, unexpected config changes, unsupported codecs, etc. These errors
usually lead to playback being stopped, but these are no present in the main
browser log even when running with --vmodule=*media/*=4, which is confusing,
since you have to go check chrome://media-internals to see what kind of error
caused the failure. Would be nice to have those messages in both places.

[gunsch, 2015-01-28 03:30:35]

Can you do the same for WebMediaPlayerAndroid?

https://codereview.chromium.org/877273002/diff/1/media/blink/webmediaplayer_i...
File media/blink/webmediaplayer_impl.cc (right):

https://codereview.chromium.org/877273002/diff/1/media/blink/webmediaplayer_i...
media/blink/webmediaplayer_impl.cc:107: DVLOG(1) << "MediaLog: " << error;
why DVLOG? These are highly useful messages, and not terribly frequent. I would
strongly prefer LOG(INFO) if possible, since we look for these in production
Chromecast logs; of, if that's potentially too much logging, then changing this
callback such that it can specify log type and/or verbosity level (and thus all
the call sites).

[wolenetz, 2015-01-28 18:47:48]

On 2015/01/28 03:12:00, servolk wrote:
> Media_log messages are very useful, let's add them to the main browser log as
> well. Would this be a good place to add this or should this be done somewhere
> else, e.g. in MediaInternals::OnMediaEvents or MediaInternals::SendUpdate? If
we
> added logging to the MediaInternals::OnMediaEvents or
MediaInternals::SendUpdate
> it would work for media logs instantiated anywhere, not just in
webmediaplayer,
> but I'm not sure how readable is the JSON string that we get there. Feel free
to
> suggest a better place to do this.

My preference would be a more general interception using LOG(INFO,...) of all
media log events (but perhaps not property changes or buffering status updates),
not just MediaSourceErrors from WMPI.
Have you considered adding the new LOG(INFO,...) to the various
MediaLog::AddEvent(...) implementations?
I'm unclear on how the new log messages might be buffered/delayed if done in the
Browser process's MediaInternals::{OnMediaEvents,SendUpdate} versus the behavior
of LOG(INFO,...) done directly in the renderer process. Would the interleaving
of these LOG messages with the rest of the renderer process's potential logging
be mixed up if we LOGged from MediaLog:... in the browser process?

[DaleCurtis, 2015-01-28 23:36:22]

I defer to Matt on this, but want to note that we've had performance problems in
the past from high volume render to browser logging.

[DaleCurtis, 2015-01-29 00:03:10]

dalecurtis@chromium.org changed reviewers:
- dalecurtis@chromium.org

[servolk, 2015-01-29 00:43:54]

On 2015/01/28 18:47:48, wolenetz wrote:
> On 2015/01/28 03:12:00, servolk wrote:
> > Media_log messages are very useful, let's add them to the main browser log
as
> > well. Would this be a good place to add this or should this be done
somewhere
> > else, e.g. in MediaInternals::OnMediaEvents or MediaInternals::SendUpdate?
If
> we
> > added logging to the MediaInternals::OnMediaEvents or
> MediaInternals::SendUpdate
> > it would work for media logs instantiated anywhere, not just in
> webmediaplayer,
> > but I'm not sure how readable is the JSON string that we get there. Feel
free
> to
> > suggest a better place to do this.
> 
> My preference would be a more general interception using LOG(INFO,...) of all
> media log events (but perhaps not property changes or buffering status
updates),
> not just MediaSourceErrors from WMPI.
> Have you considered adding the new LOG(INFO,...) to the various
> MediaLog::AddEvent(...) implementations?
> I'm unclear on how the new log messages might be buffered/delayed if done in
the
> Browser process's MediaInternals::{OnMediaEvents,SendUpdate} versus the
behavior
> of LOG(INFO,...) done directly in the renderer process. Would the interleaving
> of these LOG messages with the rest of the renderer process's potential
logging
> be mixed up if we LOGged from MediaLog:... in the browser process?

Yeah, I thought about adding this extra logging somewhere in MediaInternals or 
RenderMediaLog::AddEvent, that might be a better place indeed, we'll just have
to decide if we want to extract just a subset of data from a given MediaLogEvent
or dump the serialized JSON produced for MediaInternals::SendUpdate. I was
worried that JSON wouldn't be as readable in the log as a simple text string,
but even that would be much better than not having media log events in the main
browser log at all. I'll try to play with this a bit locally to see what actual
JSON looks like there.

[servolk, 2015-01-29 00:47:30]

On 2015/01/28 23:36:22, DaleCurtis wrote:
> I defer to Matt on this, but want to note that we've had performance problems
in
> the past from high volume render to browser logging.

Yeah, I was a bit worried about performance implications too, that's why I used
DVLOG(1) here. We might want to turn on logging as DVLOG(1) for now, and we'll
just change that into LOG(INFO) for Chromecast. Btw, Dale we have been using
LOG(INFO) for media log event in Chromecast for a while, and haven't seen any
perf issues, if you happen to remember a bug number or a feedback report for
perf issues with that send it my way? Perhaps we need to be more cautious about
that (or maybe we are not affected by that simply because we are using custom
media renderer, CmaRenderer, for Chromecast).

[servolk, 2015-01-29 01:39:37]

servolk@chromium.org changed reviewers:
+ dalecurtis@chromium.org

[gunsch, 2015-01-29 02:11:12]

On 2015/01/29 00:47:30, servolk wrote:
> On 2015/01/28 23:36:22, DaleCurtis wrote:
> > I defer to Matt on this, but want to note that we've had performance
problems
> in
> > the past from high volume render to browser logging.
> 
> Yeah, I was a bit worried about performance implications too, that's why I
used
> DVLOG(1) here. We might want to turn on logging as DVLOG(1) for now, and we'll
> just change that into LOG(INFO) for Chromecast. Btw, Dale we have been using
> LOG(INFO) for media log event in Chromecast for a while, and haven't seen any
> perf issues, if you happen to remember a bug number or a feedback report for
> perf issues with that send it my way? Perhaps we need to be more cautious
about
> that (or maybe we are not affected by that simply because we are using custom
> media renderer, CmaRenderer, for Chromecast).

Drive-by comments:

1) In general, I think these are pretty extremely low-volume, and worth noticing
when they do. We've had this as a LOG(INFO) downstream for awhile, and I think
we usually get < 5 per video playback total.

2) If we check this in as a DVLOG but change downstream to a LOG(INFO), it
doesn't really get Chromecast team any closer to building upstream :)

[servolk, 2015-01-29 02:18:27]

On 2015/01/29 02:11:12, gunsch wrote:
> On 2015/01/29 00:47:30, servolk wrote:
> > On 2015/01/28 23:36:22, DaleCurtis wrote:
> > > I defer to Matt on this, but want to note that we've had performance
> problems
> > in
> > > the past from high volume render to browser logging.
> > 
> > Yeah, I was a bit worried about performance implications too, that's why I
> used
> > DVLOG(1) here. We might want to turn on logging as DVLOG(1) for now, and
we'll
> > just change that into LOG(INFO) for Chromecast. Btw, Dale we have been using
> > LOG(INFO) for media log event in Chromecast for a while, and haven't seen
any
> > perf issues, if you happen to remember a bug number or a feedback report for
> > perf issues with that send it my way? Perhaps we need to be more cautious
> about
> > that (or maybe we are not affected by that simply because we are using
custom
> > media renderer, CmaRenderer, for Chromecast).
> 
> Drive-by comments:
> 
> 1) In general, I think these are pretty extremely low-volume, and worth
noticing
> when they do. We've had this as a LOG(INFO) downstream for awhile, and I think
> we usually get < 5 per video playback total.
> 
> 2) If we check this in as a DVLOG but change downstream to a LOG(INFO), it
> doesn't really get Chromecast team any closer to building upstream :)

Re #1 - keep in mind that we are using a custom media renderer, maybe that's why
those messages are low volume for us. But I agree, given the importance of some
of those messages (e.g. unsupported codec) I'd prefer to have them as noticeable
as possible.

Re #2 - well, I'd still say that puts us a bit closer. Sure ideally we want no
diff at all, but we are not quite there yet anyway (e.g. we disable some
AVC::IsValidAnnexB checks on Chromecast, presumably due to perf concerns, but I
don't know details around that).

Dale, if you could help us find bugs/discussions on perf issues with having
media log messages as LOG(INFO) that would be very helpful.

[servolk, 2015-01-29 02:26:28]

On 2015/01/29 02:18:27, servolk wrote:
> On 2015/01/29 02:11:12, gunsch wrote:
> > On 2015/01/29 00:47:30, servolk wrote:
> > > On 2015/01/28 23:36:22, DaleCurtis wrote:
> > > > I defer to Matt on this, but want to note that we've had performance
> > problems
> > > in
> > > > the past from high volume render to browser logging.
> > > 
> > > Yeah, I was a bit worried about performance implications too, that's why I
> > used
> > > DVLOG(1) here. We might want to turn on logging as DVLOG(1) for now, and
> we'll
> > > just change that into LOG(INFO) for Chromecast. Btw, Dale we have been
using
> > > LOG(INFO) for media log event in Chromecast for a while, and haven't seen
> any
> > > perf issues, if you happen to remember a bug number or a feedback report
for
> > > perf issues with that send it my way? Perhaps we need to be more cautious
> > about
> > > that (or maybe we are not affected by that simply because we are using
> custom
> > > media renderer, CmaRenderer, for Chromecast).
> > 
> > Drive-by comments:
> > 
> > 1) In general, I think these are pretty extremely low-volume, and worth
> noticing
> > when they do. We've had this as a LOG(INFO) downstream for awhile, and I
think
> > we usually get < 5 per video playback total.
> > 
> > 2) If we check this in as a DVLOG but change downstream to a LOG(INFO), it
> > doesn't really get Chromecast team any closer to building upstream :)
> 
> Re #1 - keep in mind that we are using a custom media renderer, maybe that's
why
> those messages are low volume for us. But I agree, given the importance of
some
> of those messages (e.g. unsupported codec) I'd prefer to have them as
noticeable
> as possible.
> 
> Re #2 - well, I'd still say that puts us a bit closer. Sure ideally we want no
> diff at all, but we are not quite there yet anyway (e.g. we disable some
> AVC::IsValidAnnexB checks on Chromecast, presumably due to perf concerns, but
I
> don't know details around that).
> 
> Dale, if you could help us find bugs/discussions on perf issues with having
> media log messages as LOG(INFO) that would be very helpful.

Btw, looking at event types defined in media/base/media_log_event.h, yeah I
think if we ignore BUFFERED_EXTENTS_CHANGED, PROPERTY_CHANGE and maybe
NETWORK_ACTIVITY_SET then the remaining events shouldn't be too noisy and
unlikely to flood logs or cause perf concerns even when using LOG(INFO), I'll
update this CL shortly.

[servolk, 2015-01-29 03:28:56]

On 2015/01/29 02:26:28, servolk wrote:
> On 2015/01/29 02:18:27, servolk wrote:
> > On 2015/01/29 02:11:12, gunsch wrote:
> > > On 2015/01/29 00:47:30, servolk wrote:
> > > > On 2015/01/28 23:36:22, DaleCurtis wrote:
> > > > > I defer to Matt on this, but want to note that we've had performance
> > > problems
> > > > in
> > > > > the past from high volume render to browser logging.
> > > > 
> > > > Yeah, I was a bit worried about performance implications too, that's why
I
> > > used
> > > > DVLOG(1) here. We might want to turn on logging as DVLOG(1) for now, and
> > we'll
> > > > just change that into LOG(INFO) for Chromecast. Btw, Dale we have been
> using
> > > > LOG(INFO) for media log event in Chromecast for a while, and haven't
seen
> > any
> > > > perf issues, if you happen to remember a bug number or a feedback report
> for
> > > > perf issues with that send it my way? Perhaps we need to be more
cautious
> > > about
> > > > that (or maybe we are not affected by that simply because we are using
> > custom
> > > > media renderer, CmaRenderer, for Chromecast).
> > > 
> > > Drive-by comments:
> > > 
> > > 1) In general, I think these are pretty extremely low-volume, and worth
> > noticing
> > > when they do. We've had this as a LOG(INFO) downstream for awhile, and I
> think
> > > we usually get < 5 per video playback total.
> > > 
> > > 2) If we check this in as a DVLOG but change downstream to a LOG(INFO), it
> > > doesn't really get Chromecast team any closer to building upstream :)
> > 
> > Re #1 - keep in mind that we are using a custom media renderer, maybe that's
> why
> > those messages are low volume for us. But I agree, given the importance of
> some
> > of those messages (e.g. unsupported codec) I'd prefer to have them as
> noticeable
> > as possible.
> > 
> > Re #2 - well, I'd still say that puts us a bit closer. Sure ideally we want
no
> > diff at all, but we are not quite there yet anyway (e.g. we disable some
> > AVC::IsValidAnnexB checks on Chromecast, presumably due to perf concerns,
but
> I
> > don't know details around that).
> > 
> > Dale, if you could help us find bugs/discussions on perf issues with having
> > media log messages as LOG(INFO) that would be very helpful.
> 
> Btw, looking at event types defined in media/base/media_log_event.h, yeah I
> think if we ignore BUFFERED_EXTENTS_CHANGED, PROPERTY_CHANGE and maybe
> NETWORK_ACTIVITY_SET then the remaining events shouldn't be too noisy and
> unlikely to flood logs or cause perf concerns even when using LOG(INFO), I'll
> update this CL shortly.

Ok, so I've implemented an alternative approach, this should be ok even
long-term. I've had to use LOG(ERROR) though instead of LOG(INFO), since
presubmit check was complaining:

** Presubmit ERRORS **
These files spam the console log with LOG(INFO):
  content/renderer/media/render_media_log.cc

Any ideas how to overcome that?

[DaleCurtis, 2015-01-29 19:22:16]

dalecurtis@chromium.org changed reviewers:
- dalecurtis@chromium.org

[DaleCurtis, 2015-01-29 19:22:17]

http://crbug.com/352585 is the one I'm thinking of.

[servolk, 2015-01-29 19:51:59]

On 2015/01/29 19:22:17, DaleCurtis wrote:
> http://crbug.com/352585 is the one I'm thinking of.

Ok, thanks, that confirms it - the bug talks about BUFFERED_EXTENTS_CHANGED
being problematic, but looking at the other event types I think they shouldn't
be too noisy, so this CL should be good.

[servolk, 2015-02-04 21:29:50]

On 2015/01/29 19:51:59, servolk wrote:
> On 2015/01/29 19:22:17, DaleCurtis wrote:
> > http://crbug.com/352585 is the one I'm thinking of.
> 
> Ok, thanks, that confirms it - the bug talks about BUFFERED_EXTENTS_CHANGED
> being problematic, but looking at the other event types I think they shouldn't
> be too noisy, so this CL should be good.

ping

[wolenetz, 2015-02-04 22:04:19]

https://codereview.chromium.org/877273002/diff/20001/content/renderer/media/r...
File content/renderer/media/render_media_log.cc (right):

https://codereview.chromium.org/877273002/diff/20001/content/renderer/media/r...
content/renderer/media/render_media_log.cc:43: LOG(ERROR) << "MediaEvent: "
I suspect you can get PRESUBMIT to allow LOG(INFO) if you update the blacklist
at https://code.google.com/p/chromium/codesearch#chromium/src/PRESUBMIT.py&l=945
to include this file. You'll need PRESUBMIT.py OWNER l*tm, of course, for that
change.

https://codereview.chromium.org/877273002/diff/20001/media/base/media_log.cc
File media/base/media_log.cc (right):

https://codereview.chromium.org/877273002/diff/20001/media/base/media_log.cc#...
media/base/media_log.cc:102: std::string MediaLog::MediaEventToLogString(const
MediaLogEvent& event) {
This method seems quite fragile to event parameter type changes elsewhere in
code. What did the JSON look like? Might there be a better way to dump all event
properties, that isn't so fragile?

https://codereview.chromium.org/877273002/diff/20001/media/base/media_log.cc#...
media/base/media_log.cc:165: default:
Please drop the default case and instead let build fail if not all enum
MediaLogEvent::Type are handled in cases in this switch.

[chromium-reviews, 2015-02-05 00:48:29]

The serialized JSON looks like this (see also attached log file):
[15279:15301:0204/162705:INFO:media_internals.cc(421)] MediaEvent
JSON:media.onMediaEvent({"params":{"pipeline_state":"kCreated"},"player":0,"renderer":4,"ticksMillis":613355993.779,"type":"PIPELINE_STATE_CHANGED"});
[15279:15301:0204/162705:INFO:media_internals.cc(421)] MediaEvent
JSON:media.onMediaEvent({"params":{},"player":0,"renderer":4,"ticksMillis":613355994.032,"type":"PIPELINE_CREATED"});
[15279:15301:0204/162705:INFO:media_internals.cc(421)] MediaEvent
JSON:media.onMediaEvent({"params":{},"player":0,"renderer":4,"ticksMillis":613355994.17,"type":"WEBMEDIAPLAYER_CREATED"});
[15279:15301:0204/162705:INFO:media_internals.cc(421)] MediaEvent
JSON:media.onMediaEvent({"params":{"url":"blob:http%3A//
storage.googleapis.com/404da943-00d7-42cc-a0ef-f1d28ce5406e
"},"player":0,"renderer":4,"ticksMillis":613355994.823,"type":"LOAD"});
[15279:15301:0204/162705:INFO:media_internals.cc(421)] MediaEvent
JSON:media.onMediaEvent({"params":{"pipeline_state":"kInitDemuxer"},"player":0,"renderer":4,"ticksMillis":613355995.376,"type":"PIPELINE_STATE_CHANGED"});
[15279:15301:0204/162705:INFO:media_internals.cc(421)] MediaEvent
JSON:media.onMediaEvent({"params":{"duration":19.9999},"player":0,"renderer":4,"ticksMillis":613356073.654,"type":"DURATION_SET"});
[15279:15301:0204/162705:INFO:media_internals.cc(421)] MediaEvent
JSON:media.onMediaEvent({"params":{"error":"Video codec:
avc1.64028"},"player":0,"renderer":4,"ticksMillis":613356116.961,"type":"MEDIA_SOURCE_ERROR"});

But JSON is created in MediaInternals::OnMediaEvents, which is invoked
asynchronously a while after the event actually happens (since MediaEvent
has to be passed to the browser process via IPC and to the IO thread before
we get to MediaInternals::OnMediaEvents.
Here is the change that I've tried:
diff --git a/content/browser/media/media_internals.cc
b/content/browser/media/media_internals.cc
index e2a5ede..617e1a2 100644
--- a/content/browser/media/media_internals.cc
+++ b/content/browser/media/media_internals.cc
@@ -417,7 +417,9 @@ void MediaInternals::OnMediaEvents(
       dict.Set("params", event->params.DeepCopy());
     }

-    SendUpdate(SerializeUpdate("media.onMediaEvent", &dict));
+    auto json = SerializeUpdate("media.onMediaEvent", &dict);
+    LOG(INFO) << "MediaEvent JSON:" << json;
+    SendUpdate(json);
     uma_handler_->SavePlayerState(*event, render_process_id);
   }
 }

And that gave me the attached log file. Note how all "MediaEvent JSON:" are
delayed and that makes the log quite confusing since they are not properly
interspersed with the corresponding JS messages from the JS player. Taking
into account this, and the fact that JSON is less readable, I prefer the
current approach in this CL.
Although ultimately it's your call, I'm fine with either approach as long
as we have those messages in the main browser log.

On Wed, Feb 4, 2015 at 2:04 PM, <wolenetz@chromium.org> wrote:

>
> https://codereview.chromium.org/877273002/diff/20001/
> content/renderer/media/render_media_log.cc
> File content/renderer/media/render_media_log.cc (right):
>
> https://codereview.chromium.org/877273002/diff/20001/
> content/renderer/media/render_media_log.cc#newcode43
> content/renderer/media/render_media_log.cc:43: LOG(ERROR) <<
> "MediaEvent: "
> I suspect you can get PRESUBMIT to allow LOG(INFO) if you update the
> blacklist at
> https://code.google.com/p/chromium/codesearch#chromium/
> src/PRESUBMIT.py&l=945
> to include this file. You'll need PRESUBMIT.py OWNER l*tm, of course,
> for that change.
>
> https://codereview.chromium.org/877273002/diff/20001/
> media/base/media_log.cc
> File media/base/media_log.cc (right):
>
> https://codereview.chromium.org/877273002/diff/20001/
> media/base/media_log.cc#newcode102
> media/base/media_log.cc:102: std::string
> MediaLog::MediaEventToLogString(const MediaLogEvent& event) {
> This method seems quite fragile to event parameter type changes
> elsewhere in code. What did the JSON look like? Might there be a better
> way to dump all event properties, that isn't so fragile?
>
> https://codereview.chromium.org/877273002/diff/20001/
> media/base/media_log.cc#newcode165
> media/base/media_log.cc:165: default:
> Please drop the default case and instead let build fail if not all enum
> MediaLogEvent::Type are handled in cases in this switch.
>
> https://codereview.chromium.org/877273002/
>

To unsubscribe from this group and stop receiving emails from it, send an email
to chromium-reviews+unsubscribe@chromium.org.

[chromium-reviews, 2015-02-05 00:57:11]

Btw, quick note: there are both types of messages in the log file attached
to previous message - current "MediaEvent:" messages
from render_media_log.cc and "MediaEvent JSON:" messages
from media_internals.cc. Just let me know which one you prefer and I'll
update this CL (will also convert it LOG(INFO) and add an appropriate file
to presubmit ignore list).

On Wed, Feb 4, 2015 at 4:48 PM, Sergey Volk <servolk@google.com> wrote:

> The serialized JSON looks like this (see also attached log file):
> [15279:15301:0204/162705:INFO:media_internals.cc(421)] MediaEvent
>
JSON:media.onMediaEvent({"params":{"pipeline_state":"kCreated"},"player":0,"renderer":4,"ticksMillis":613355993.779,"type":"PIPELINE_STATE_CHANGED"});
> [15279:15301:0204/162705:INFO:media_internals.cc(421)] MediaEvent
>
JSON:media.onMediaEvent({"params":{},"player":0,"renderer":4,"ticksMillis":613355994.032,"type":"PIPELINE_CREATED"});
> [15279:15301:0204/162705:INFO:media_internals.cc(421)] MediaEvent
>
JSON:media.onMediaEvent({"params":{},"player":0,"renderer":4,"ticksMillis":613355994.17,"type":"WEBMEDIAPLAYER_CREATED"});
> [15279:15301:0204/162705:INFO:media_internals.cc(421)] MediaEvent
> JSON:media.onMediaEvent({"params":{"url":"blob:http%3A//
> storage.googleapis.com/404da943-00d7-42cc-a0ef-f1d28ce5406e
> "},"player":0,"renderer":4,"ticksMillis":613355994.823,"type":"LOAD"});
> [15279:15301:0204/162705:INFO:media_internals.cc(421)] MediaEvent
>
JSON:media.onMediaEvent({"params":{"pipeline_state":"kInitDemuxer"},"player":0,"renderer":4,"ticksMillis":613355995.376,"type":"PIPELINE_STATE_CHANGED"});
> [15279:15301:0204/162705:INFO:media_internals.cc(421)] MediaEvent
>
JSON:media.onMediaEvent({"params":{"duration":19.9999},"player":0,"renderer":4,"ticksMillis":613356073.654,"type":"DURATION_SET"});
> [15279:15301:0204/162705:INFO:media_internals.cc(421)] MediaEvent
> JSON:media.onMediaEvent({"params":{"error":"Video codec:
>
avc1.64028"},"player":0,"renderer":4,"ticksMillis":613356116.961,"type":"MEDIA_SOURCE_ERROR"});
>
> But JSON is created in MediaInternals::OnMediaEvents, which is invoked
> asynchronously a while after the event actually happens (since MediaEvent
> has to be passed to the browser process via IPC and to the IO thread before
> we get to MediaInternals::OnMediaEvents.
> Here is the change that I've tried:
> diff --git a/content/browser/media/media_internals.cc
> b/content/browser/media/media_internals.cc
> index e2a5ede..617e1a2 100644
> --- a/content/browser/media/media_internals.cc
> +++ b/content/browser/media/media_internals.cc
> @@ -417,7 +417,9 @@ void MediaInternals::OnMediaEvents(
>        dict.Set("params", event->params.DeepCopy());
>      }
>
> -    SendUpdate(SerializeUpdate("media.onMediaEvent", &dict));
> +    auto json = SerializeUpdate("media.onMediaEvent", &dict);
> +    LOG(INFO) << "MediaEvent JSON:" << json;
> +    SendUpdate(json);
>      uma_handler_->SavePlayerState(*event, render_process_id);
>    }
>  }
>
> And that gave me the attached log file. Note how all "MediaEvent JSON:"
> are delayed and that makes the log quite confusing since they are not
> properly interspersed with the corresponding JS messages from the JS
> player. Taking into account this, and the fact that JSON is less readable,
> I prefer the current approach in this CL.
> Although ultimately it's your call, I'm fine with either approach as long
> as we have those messages in the main browser log.
>
> On Wed, Feb 4, 2015 at 2:04 PM, <wolenetz@chromium.org> wrote:
>
>>
>> https://codereview.chromium.org/877273002/diff/20001/
>> content/renderer/media/render_media_log.cc
>> File content/renderer/media/render_media_log.cc (right):
>>
>> https://codereview.chromium.org/877273002/diff/20001/
>> content/renderer/media/render_media_log.cc#newcode43
>> content/renderer/media/render_media_log.cc:43: LOG(ERROR) <<
>> "MediaEvent: "
>> I suspect you can get PRESUBMIT to allow LOG(INFO) if you update the
>> blacklist at
>> https://code.google.com/p/chromium/codesearch#chromium/
>> src/PRESUBMIT.py&l=945
>> to include this file. You'll need PRESUBMIT.py OWNER l*tm, of course,
>> for that change.
>>
>> https://codereview.chromium.org/877273002/diff/20001/
>> media/base/media_log.cc
>> File media/base/media_log.cc (right):
>>
>> https://codereview.chromium.org/877273002/diff/20001/
>> media/base/media_log.cc#newcode102
>> media/base/media_log.cc:102: std::string
>> MediaLog::MediaEventToLogString(const MediaLogEvent& event) {
>> This method seems quite fragile to event parameter type changes
>> elsewhere in code. What did the JSON look like? Might there be a better
>> way to dump all event properties, that isn't so fragile?
>>
>> https://codereview.chromium.org/877273002/diff/20001/
>> media/base/media_log.cc#newcode165
>> media/base/media_log.cc:165: default:
>> Please drop the default case and instead let build fail if not all enum
>> MediaLogEvent::Type are handled in cases in this switch.
>>
>> https://codereview.chromium.org/877273002/
>>
>
>

To unsubscribe from this group and stop receiving emails from it, send an email
to chromium-reviews+unsubscribe@chromium.org.

[servolk, 2015-02-10 18:10:02]

On 2015/02/05 00:57:11, chromium-reviews wrote:
> Btw, quick note: there are both types of messages in the log file attached
> to previous message - current "MediaEvent:" messages
> from render_media_log.cc and "MediaEvent JSON:" messages
> from media_internals.cc. Just let me know which one you prefer and I'll
> update this CL (will also convert it LOG(INFO) and add an appropriate file
> to presubmit ignore list).
> 
> On Wed, Feb 4, 2015 at 4:48 PM, Sergey Volk <mailto:servolk@google.com> wrote:
> 
> > The serialized JSON looks like this (see also attached log file):
> > [15279:15301:0204/162705:INFO:media_internals.cc(421)] MediaEvent
> >
>
JSON:media.onMediaEvent({"params":{"pipeline_state":"kCreated"},"player":0,"renderer":4,"ticksMillis":613355993.779,"type":"PIPELINE_STATE_CHANGED"});
> > [15279:15301:0204/162705:INFO:media_internals.cc(421)] MediaEvent
> >
>
JSON:media.onMediaEvent({"params":{},"player":0,"renderer":4,"ticksMillis":613355994.032,"type":"PIPELINE_CREATED"});
> > [15279:15301:0204/162705:INFO:media_internals.cc(421)] MediaEvent
> >
>
JSON:media.onMediaEvent({"params":{},"player":0,"renderer":4,"ticksMillis":613355994.17,"type":"WEBMEDIAPLAYER_CREATED"});
> > [15279:15301:0204/162705:INFO:media_internals.cc(421)] MediaEvent
> > JSON:media.onMediaEvent({"params":{"url":"blob:http%3A//
> > storage.googleapis.com/404da943-00d7-42cc-a0ef-f1d28ce5406e
> > "},"player":0,"renderer":4,"ticksMillis":613355994.823,"type":"LOAD"});
> > [15279:15301:0204/162705:INFO:media_internals.cc(421)] MediaEvent
> >
>
JSON:media.onMediaEvent({"params":{"pipeline_state":"kInitDemuxer"},"player":0,"renderer":4,"ticksMillis":613355995.376,"type":"PIPELINE_STATE_CHANGED"});
> > [15279:15301:0204/162705:INFO:media_internals.cc(421)] MediaEvent
> >
>
JSON:media.onMediaEvent({"params":{"duration":19.9999},"player":0,"renderer":4,"ticksMillis":613356073.654,"type":"DURATION_SET"});
> > [15279:15301:0204/162705:INFO:media_internals.cc(421)] MediaEvent
> > JSON:media.onMediaEvent({"params":{"error":"Video codec:
> >
>
avc1.64028"},"player":0,"renderer":4,"ticksMillis":613356116.961,"type":"MEDIA_SOURCE_ERROR"});
> >
> > But JSON is created in MediaInternals::OnMediaEvents, which is invoked
> > asynchronously a while after the event actually happens (since MediaEvent
> > has to be passed to the browser process via IPC and to the IO thread before
> > we get to MediaInternals::OnMediaEvents.
> > Here is the change that I've tried:
> > diff --git a/content/browser/media/media_internals.cc
> > b/content/browser/media/media_internals.cc
> > index e2a5ede..617e1a2 100644
> > --- a/content/browser/media/media_internals.cc
> > +++ b/content/browser/media/media_internals.cc
> > @@ -417,7 +417,9 @@ void MediaInternals::OnMediaEvents(
> >        dict.Set("params", event->params.DeepCopy());
> >      }
> >
> > -    SendUpdate(SerializeUpdate("media.onMediaEvent", &dict));
> > +    auto json = SerializeUpdate("media.onMediaEvent", &dict);
> > +    LOG(INFO) << "MediaEvent JSON:" << json;
> > +    SendUpdate(json);
> >      uma_handler_->SavePlayerState(*event, render_process_id);
> >    }
> >  }
> >
> > And that gave me the attached log file. Note how all "MediaEvent JSON:"
> > are delayed and that makes the log quite confusing since they are not
> > properly interspersed with the corresponding JS messages from the JS
> > player. Taking into account this, and the fact that JSON is less readable,
> > I prefer the current approach in this CL.
> > Although ultimately it's your call, I'm fine with either approach as long
> > as we have those messages in the main browser log.
> >
> > On Wed, Feb 4, 2015 at 2:04 PM, <mailto:wolenetz@chromium.org> wrote:
> >
> >>
> >> https://codereview.chromium.org/877273002/diff/20001/
> >> content/renderer/media/render_media_log.cc
> >> File content/renderer/media/render_media_log.cc (right):
> >>
> >> https://codereview.chromium.org/877273002/diff/20001/
> >> content/renderer/media/render_media_log.cc#newcode43
> >> content/renderer/media/render_media_log.cc:43: LOG(ERROR) <<
> >> "MediaEvent: "
> >> I suspect you can get PRESUBMIT to allow LOG(INFO) if you update the
> >> blacklist at
> >> https://code.google.com/p/chromium/codesearch#chromium/
> >> src/PRESUBMIT.py&l=945
> >> to include this file. You'll need PRESUBMIT.py OWNER l*tm, of course,
> >> for that change.
> >>
> >> https://codereview.chromium.org/877273002/diff/20001/
> >> media/base/media_log.cc
> >> File media/base/media_log.cc (right):
> >>
> >> https://codereview.chromium.org/877273002/diff/20001/
> >> media/base/media_log.cc#newcode102
> >> media/base/media_log.cc:102: std::string
> >> MediaLog::MediaEventToLogString(const MediaLogEvent& event) {
> >> This method seems quite fragile to event parameter type changes
> >> elsewhere in code. What did the JSON look like? Might there be a better
> >> way to dump all event properties, that isn't so fragile?
> >>
> >> https://codereview.chromium.org/877273002/diff/20001/
> >> media/base/media_log.cc#newcode165
> >> media/base/media_log.cc:165: default:
> >> Please drop the default case and instead let build fail if not all enum
> >> MediaLogEvent::Type are handled in cases in this switch.
> >>
> >> https://codereview.chromium.org/877273002/
> >>
> >
> >
> 
> To unsubscribe from this group and stop receiving emails from it, send an
email
> to mailto:chromium-reviews+unsubscribe@chromium.org.

Ping. I've uploaded a new patch that logs PIPELINE_ERROR events as LOG(ERROR)
and the rest of reportable events as DVLOG(1). Pipeline errors are most useful
by far, although longer term we might want to introduce notion of message
severity into media logs.

[wolenetz, 2015-02-13 20:36:37]

Sorry about the review delay again. w.r.t. current patch set 3:

https://codereview.chromium.org/877273002/diff/40001/content/renderer/media/r...
File content/renderer/media/render_media_log.cc (right):

https://codereview.chromium.org/877273002/diff/40001/content/renderer/media/r...
content/renderer/media/render_media_log.cc:41: LOG(ERROR) <<
media::MediaLog::MediaEventToLogString(*event.get());
nit: *. --> ->

https://codereview.chromium.org/877273002/diff/40001/content/renderer/media/r...
content/renderer/media/render_media_log.cc:46: <<
media::MediaLog::MediaEventToLogString(*event.get());
nit: ditto

https://codereview.chromium.org/877273002/diff/40001/media/base/media_log.cc
File media/base/media_log.cc (right):

https://codereview.chromium.org/877273002/diff/40001/media/base/media_log.cc#...
media/base/media_log.cc:119: case MediaLogEvent::LOAD:
I still think this method is too fragile to changes elsewhere in which params
are populated differently for each event type. Mitigations might include:
1) Tests
2) Implementing a custom ValueSerializer and iterate across all event params (if
the existing JSON impl is too wordy for logs).
3) Refactoring MediaLogEvent creation to also setup all the requisite parameters
per each event type *here*, not in the scattered callers of
MediaLog::CreateEvent. A further refactoring (IMO not required, but could be
nice) might make MediaLogEvent abstract with concrete subtypes for each specific
log event type.

At a bare minimum, DCHECK the retval of the various event.params.Get*() used
here.

I do not want this CL to introduce technical debt that will bite us later when
the log event params might diverge from current impl.

ISTM like a combination of (3) and the DCHECK might be the best way forward.

Alternatively, a more scoped-to-the-current-problem CL might not add this
method, and instead use the JSON serializer directly for the non-PIPELINE_ERROR
DVLOGs (to show full detail), and a very specific construction of pipeline error
media log message for PIPELINE_ERROR LOG(INFO)s.

[servolk, 2015-02-19 23:56:03]

On 2015/02/13 20:36:37, wolenetz_OoO_Feb_19 wrote:
> Sorry about the review delay again. w.r.t. current patch set 3:
> 
>
https://codereview.chromium.org/877273002/diff/40001/content/renderer/media/r...
> File content/renderer/media/render_media_log.cc (right):
> 
>
https://codereview.chromium.org/877273002/diff/40001/content/renderer/media/r...
> content/renderer/media/render_media_log.cc:41: LOG(ERROR) <<
> media::MediaLog::MediaEventToLogString(*event.get());
> nit: *. --> ->
> 
>
https://codereview.chromium.org/877273002/diff/40001/content/renderer/media/r...
> content/renderer/media/render_media_log.cc:46: <<
> media::MediaLog::MediaEventToLogString(*event.get());
> nit: ditto
> 
> https://codereview.chromium.org/877273002/diff/40001/media/base/media_log.cc
> File media/base/media_log.cc (right):
> 
>
https://codereview.chromium.org/877273002/diff/40001/media/base/media_log.cc#...
> media/base/media_log.cc:119: case MediaLogEvent::LOAD:
> I still think this method is too fragile to changes elsewhere in which params
> are populated differently for each event type. Mitigations might include:
> 1) Tests
> 2) Implementing a custom ValueSerializer and iterate across all event params
(if
> the existing JSON impl is too wordy for logs).
> 3) Refactoring MediaLogEvent creation to also setup all the requisite
parameters
> per each event type *here*, not in the scattered callers of
> MediaLog::CreateEvent. A further refactoring (IMO not required, but could be
> nice) might make MediaLogEvent abstract with concrete subtypes for each
specific
> log event type.
> 
> At a bare minimum, DCHECK the retval of the various event.params.Get*() used
> here.
> 
> I do not want this CL to introduce technical debt that will bite us later when
> the log event params might diverge from current impl.
> 
> ISTM like a combination of (3) and the DCHECK might be the best way forward.
> 
> Alternatively, a more scoped-to-the-current-problem CL might not add this
> method, and instead use the JSON serializer directly for the
non-PIPELINE_ERROR
> DVLOGs (to show full detail), and a very specific construction of pipeline
error
> media log message for PIPELINE_ERROR LOG(INFO)s.

Actually looking at this some more I'm starting to wonder if moving towards more
structured approach (abstract classes and subtypes) is a good idea here.
Ultimately most of those MediaEvents are just strings that get added to the
chrome://media-internals log. So why don't we just make them plain strings? That
would give us maximum flexibility. I'm not sure how useful it is to have
multiple columns in the media log. Why don't we make it just a regular
plain-text log?

[wolenetz, 2015-02-24 19:15:32]

On 2015/02/19 23:56:03, servolk wrote:
> On 2015/02/13 20:36:37, wolenetz_OoO_Feb_19 wrote:
> > Sorry about the review delay again. w.r.t. current patch set 3:
> > 
> >
>
https://codereview.chromium.org/877273002/diff/40001/content/renderer/media/r...
> > File content/renderer/media/render_media_log.cc (right):
> > 
> >
>
https://codereview.chromium.org/877273002/diff/40001/content/renderer/media/r...
> > content/renderer/media/render_media_log.cc:41: LOG(ERROR) <<
> > media::MediaLog::MediaEventToLogString(*event.get());
> > nit: *. --> ->
> > 
> >
>
https://codereview.chromium.org/877273002/diff/40001/content/renderer/media/r...
> > content/renderer/media/render_media_log.cc:46: <<
> > media::MediaLog::MediaEventToLogString(*event.get());
> > nit: ditto
> > 
> > https://codereview.chromium.org/877273002/diff/40001/media/base/media_log.cc
> > File media/base/media_log.cc (right):
> > 
> >
>
https://codereview.chromium.org/877273002/diff/40001/media/base/media_log.cc#...
> > media/base/media_log.cc:119: case MediaLogEvent::LOAD:
> > I still think this method is too fragile to changes elsewhere in which
params
> > are populated differently for each event type. Mitigations might include:
> > 1) Tests
> > 2) Implementing a custom ValueSerializer and iterate across all event params
> (if
> > the existing JSON impl is too wordy for logs).
> > 3) Refactoring MediaLogEvent creation to also setup all the requisite
> parameters
> > per each event type *here*, not in the scattered callers of
> > MediaLog::CreateEvent. A further refactoring (IMO not required, but could be
> > nice) might make MediaLogEvent abstract with concrete subtypes for each
> specific
> > log event type.
> > 
> > At a bare minimum, DCHECK the retval of the various event.params.Get*() used
> > here.
> > 
> > I do not want this CL to introduce technical debt that will bite us later
when
> > the log event params might diverge from current impl.
> > 
> > ISTM like a combination of (3) and the DCHECK might be the best way forward.
> > 
> > Alternatively, a more scoped-to-the-current-problem CL might not add this
> > method, and instead use the JSON serializer directly for the
> non-PIPELINE_ERROR
> > DVLOGs (to show full detail), and a very specific construction of pipeline
> error
> > media log message for PIPELINE_ERROR LOG(INFO)s.
> 
> Actually looking at this some more I'm starting to wonder if moving towards
more
> structured approach (abstract classes and subtypes) is a good idea here.
> Ultimately most of those MediaEvents are just strings that get added to the
> chrome://media-internals log. So why don't we just make them plain strings?
That
> would give us maximum flexibility. I'm not sure how useful it is to have
> multiple columns in the media log. Why don't we make it just a regular
> plain-text log?

Splitting into two discussions:
A) abstract classes+subtypes per event: sgtm, though not a must-have in this CL
(see #3)
B) plain strings instead of discrete event types: this would undo the logic we
have included for uma (e.g.
https://code.google.com/p/chromium/codesearch#chromium/src/content/browser/me...).
media-internals is not the only recipient of MediaLogEvents. I'm not clear how
this route (B) would be an improvement.

[servolk, 2015-03-26 00:03:59]

On 2015/02/24 19:15:32, wolenetz wrote:
> On 2015/02/19 23:56:03, servolk wrote:
> > On 2015/02/13 20:36:37, wolenetz_OoO_Feb_19 wrote:
> > > Sorry about the review delay again. w.r.t. current patch set 3:
> > > 
> > >
> >
>
https://codereview.chromium.org/877273002/diff/40001/content/renderer/media/r...
> > > File content/renderer/media/render_media_log.cc (right):
> > > 
> > >
> >
>
https://codereview.chromium.org/877273002/diff/40001/content/renderer/media/r...
> > > content/renderer/media/render_media_log.cc:41: LOG(ERROR) <<
> > > media::MediaLog::MediaEventToLogString(*event.get());
> > > nit: *. --> ->
> > > 
> > >
> >
>
https://codereview.chromium.org/877273002/diff/40001/content/renderer/media/r...
> > > content/renderer/media/render_media_log.cc:46: <<
> > > media::MediaLog::MediaEventToLogString(*event.get());
> > > nit: ditto
> > > 
> > >
https://codereview.chromium.org/877273002/diff/40001/media/base/media_log.cc
> > > File media/base/media_log.cc (right):
> > > 
> > >
> >
>
https://codereview.chromium.org/877273002/diff/40001/media/base/media_log.cc#...
> > > media/base/media_log.cc:119: case MediaLogEvent::LOAD:
> > > I still think this method is too fragile to changes elsewhere in which
> params
> > > are populated differently for each event type. Mitigations might include:
> > > 1) Tests
> > > 2) Implementing a custom ValueSerializer and iterate across all event
params
> > (if
> > > the existing JSON impl is too wordy for logs).
> > > 3) Refactoring MediaLogEvent creation to also setup all the requisite
> > parameters
> > > per each event type *here*, not in the scattered callers of
> > > MediaLog::CreateEvent. A further refactoring (IMO not required, but could
be
> > > nice) might make MediaLogEvent abstract with concrete subtypes for each
> > specific
> > > log event type.
> > > 
> > > At a bare minimum, DCHECK the retval of the various event.params.Get*()
used
> > > here.
> > > 
> > > I do not want this CL to introduce technical debt that will bite us later
> when
> > > the log event params might diverge from current impl.
> > > 
> > > ISTM like a combination of (3) and the DCHECK might be the best way
forward.
> > > 
> > > Alternatively, a more scoped-to-the-current-problem CL might not add this
> > > method, and instead use the JSON serializer directly for the
> > non-PIPELINE_ERROR
> > > DVLOGs (to show full detail), and a very specific construction of pipeline
> > error
> > > media log message for PIPELINE_ERROR LOG(INFO)s.
> > 
> > Actually looking at this some more I'm starting to wonder if moving towards
> more
> > structured approach (abstract classes and subtypes) is a good idea here.
> > Ultimately most of those MediaEvents are just strings that get added to the
> > chrome://media-internals log. So why don't we just make them plain strings?
> That
> > would give us maximum flexibility. I'm not sure how useful it is to have
> > multiple columns in the media log. Why don't we make it just a regular
> > plain-text log?
> 
> Splitting into two discussions:
> A) abstract classes+subtypes per event: sgtm, though not a must-have in this
CL
> (see #3)
> B) plain strings instead of discrete event types: this would undo the logic we
> have included for uma (e.g.
>
https://code.google.com/p/chromium/codesearch#chromium/src/content/browser/me...).
> media-internals is not the only recipient of MediaLogEvents. I'm not clear how
> this route (B) would be an improvement.

Ok, thanks, I wasn't aware of other uses of the media event parameters.
I think I've found a better way to do this now, by using base::JSONWriter, so
please take another look at the latest patchset.
Here is what the new messages look like. Successful playback case:

[10487:10487:0325/165701:VERBOSE1:render_media_log.cc(36)] MediaEvent:
PIPELINE_STATE_CHANGED {"pipeline_state":"kCreated"}
[10487:10487:0325/165701:VERBOSE1:render_media_log.cc(36)] MediaEvent:
PIPELINE_CREATED {}
[10487:10487:0325/165701:VERBOSE1:render_media_log.cc(36)] MediaEvent:
WEBMEDIAPLAYER_CREATED {}
[10487:10487:0325/165701:VERBOSE1:render_media_log.cc(36)] MediaEvent: LOAD
{"url":"blob:http%3A//storage.googleapis.com/7dea5487-65c7-4114-89ee-565ddfad1701"}
[10487:10487:0325/165701:VERBOSE1:render_media_log.cc(36)] MediaEvent:
PIPELINE_STATE_CHANGED {"pipeline_state":"kInitDemuxer"}
[10487:10487:0325/165701:VERBOSE1:render_media_log.cc(36)] MediaEvent:
DURATION_SET {"duration":151.8499}
[10487:10487:0325/165701:VERBOSE1:render_media_log.cc(36)] MediaEvent:
MEDIA_SOURCE_ERROR {"error":"Video codec: hevc"}
[10487:10487:0325/165702:VERBOSE1:render_media_log.cc(36)] MediaEvent:
MEDIA_SOURCE_ERROR {"error":"Audio codec: mp4a.40.1"}
[10487:10487:0325/165702:VERBOSE1:render_media_log.cc(36)] MediaEvent:
PIPELINE_STATE_CHANGED {"pipeline_state":"kInitRenderer"}
[10487:10487:0325/165702:VERBOSE1:render_media_log.cc(36)] MediaEvent:
PIPELINE_STATE_CHANGED {"pipeline_state":"kPlaying"}
[10487:10487:0325/165715:VERBOSE1:render_media_log.cc(36)] MediaEvent:
WEBMEDIAPLAYER_DESTROYED {}
[10487:10487:0325/165715:VERBOSE1:render_media_log.cc(36)] MediaEvent:
PIPELINE_DESTROYED {}
[10487:10487:0325/165715:VERBOSE1:render_media_log.cc(36)] MediaEvent:
PIPELINE_STATE_CHANGED {"pipeline_state":"kStopping"}
[10487:10487:0325/165715:VERBOSE1:render_media_log.cc(36)] MediaEvent:
PIPELINE_STATE_CHANGED {"pipeline_state":"kStopped"}

Failed playback (to demonstrate PIPELINE_ERROR handling):
[10487:10487:0325/165715:VERBOSE1:render_media_log.cc(36)] MediaEvent:
PIPELINE_CREATED {}
[10487:10487:0325/165715:VERBOSE1:render_media_log.cc(36)] MediaEvent:
WEBMEDIAPLAYER_CREATED {}
[10487:10487:0325/165715:VERBOSE1:render_media_log.cc(36)] MediaEvent: LOAD
{"url":"http://storage.googleapis.com/hevc/invalid.mp4"}
[10487:10487:0325/165715:VERBOSE1:render_media_log.cc(36)] MediaEvent:
PIPELINE_STATE_CHANGED {"pipeline_state":"kInitDemuxer"}
[10487:10487:0325/165715:ERROR:render_media_log.cc(31)] MediaEvent:
PIPELINE_ERROR demuxer: could not open
[10487:10487:0325/165715:VERBOSE1:render_media_log.cc(36)] MediaEvent:
PIPELINE_STATE_CHANGED {"pipeline_state":"kStopping"}
[10487:10487:0325/165715:VERBOSE1:render_media_log.cc(36)] MediaEvent:
PIPELINE_STATE_CHANGED {"pipeline_state":"kStopped"}

[servolk, 2015-03-26 00:04:09]

https://codereview.chromium.org/877273002/diff/40001/content/renderer/media/r...
File content/renderer/media/render_media_log.cc (right):

https://codereview.chromium.org/877273002/diff/40001/content/renderer/media/r...
content/renderer/media/render_media_log.cc:41: LOG(ERROR) <<
media::MediaLog::MediaEventToLogString(*event.get());
On 2015/02/13 20:36:36, wolenetz wrote:
> nit: *. --> ->

This won't work (compile error). We are not trying to invoke the get() method on
MediaLogEvent here. We are calling .get() on scoped_ptr and then we are applying
* to get a reference from the raw pointer returned by .get().

https://codereview.chromium.org/877273002/diff/40001/content/renderer/media/r...
content/renderer/media/render_media_log.cc:46: <<
media::MediaLog::MediaEventToLogString(*event.get());
On 2015/02/13 20:36:36, wolenetz wrote:
> nit: ditto

See above

https://codereview.chromium.org/877273002/diff/40001/media/base/media_log.cc
File media/base/media_log.cc (right):

https://codereview.chromium.org/877273002/diff/40001/media/base/media_log.cc#...
media/base/media_log.cc:119: case MediaLogEvent::LOAD:
On 2015/02/13 20:36:36, wolenetz wrote:
> I still think this method is too fragile to changes elsewhere in which params
> are populated differently for each event type. Mitigations might include:
> 1) Tests
> 2) Implementing a custom ValueSerializer and iterate across all event params
(if
> the existing JSON impl is too wordy for logs).
> 3) Refactoring MediaLogEvent creation to also setup all the requisite
parameters
> per each event type *here*, not in the scattered callers of
> MediaLog::CreateEvent. A further refactoring (IMO not required, but could be
> nice) might make MediaLogEvent abstract with concrete subtypes for each
specific
> log event type.
> 
> At a bare minimum, DCHECK the retval of the various event.params.Get*() used
> here.
> 
> I do not want this CL to introduce technical debt that will bite us later when
> the log event params might diverge from current impl.
> 
> ISTM like a combination of (3) and the DCHECK might be the best way forward.
> 
> Alternatively, a more scoped-to-the-current-problem CL might not add this
> method, and instead use the JSON serializer directly for the
non-PIPELINE_ERROR
> DVLOGs (to show full detail), and a very specific construction of pipeline
error
> media log message for PIPELINE_ERROR LOG(INFO)s.

Ok, I understand your concert. I've looked a bit more into this, and found a
more maintainable way to do this. We could use base::JSONWriter for most event
types, and special case just PIPELINE_ERROR events (since for those we can get a
pretty,human-readable message via media::MediaLog::PipelineStatusToString,
instead of cryptic numeric error code written by JSONWriter by default)

[wolenetz, 2015-03-26 01:38:53]

lgtm
Thanks for working to make this more maintainable!

https://codereview.chromium.org/877273002/diff/40001/content/renderer/media/r...
File content/renderer/media/render_media_log.cc (right):

https://codereview.chromium.org/877273002/diff/40001/content/renderer/media/r...
content/renderer/media/render_media_log.cc:41: LOG(ERROR) <<
media::MediaLog::MediaEventToLogString(*event.get());
On 2015/03/26 00:04:08, servolk wrote:
> On 2015/02/13 20:36:36, wolenetz wrote:
> > nit: *. --> ->
> 
> This won't work (compile error). We are not trying to invoke the get() method
on
> MediaLogEvent here. We are calling .get() on scoped_ptr and then we are
applying
> * to get a reference from the raw pointer returned by .get().

Silly me.  Precedence bit me.

https://codereview.chromium.org/877273002/diff/40001/content/renderer/media/r...
content/renderer/media/render_media_log.cc:46: <<
media::MediaLog::MediaEventToLogString(*event.get());
On 2015/03/26 00:04:08, servolk wrote:
> On 2015/02/13 20:36:36, wolenetz wrote:
> > nit: ditto
> 
> See above

Acknowledged.

https://codereview.chromium.org/877273002/diff/60001/media/base/media_log.cc
File media/base/media_log.cc (right):

https://codereview.chromium.org/877273002/diff/60001/media/base/media_log.cc#...
media/base/media_log.cc:105: // pipeline status as numberic code is not very
helpful/user-friendly.
nit: s/numberic/numeric/

[servolk, 2015-03-26 17:06:17]

The CQ bit was checked by servolk@chromium.org

[servolk, 2015-03-26 17:06:18]

The patchset sent to the CQ was uploaded after l-g-t-m from
wolenetz@chromium.org
Link to the patchset: https://codereview.chromium.org/877273002/#ps80001 (title:
"Fixed a typo in comments")

[servolk, 2015-03-26 17:06:47]

https://codereview.chromium.org/877273002/diff/60001/media/base/media_log.cc
File media/base/media_log.cc (right):

https://codereview.chromium.org/877273002/diff/60001/media/base/media_log.cc#...
media/base/media_log.cc:105: // pipeline status as numberic code is not very
helpful/user-friendly.
On 2015/03/26 01:38:52, wolenetz wrote:
> nit: s/numberic/numeric/

Done.

[commit-bot: I haz the power, 2015-03-26 17:07:39]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/877273002/80001

[commit-bot: I haz the power, 2015-03-26 18:20:21]

Committed patchset #5 (id:80001)

[commit-bot: I haz the power, 2015-03-26 18:21:11]

Patchset 5 (id:??) landed as
https://crrev.com/cdeb28057cd67404de3383f70208b43763473c6a
Cr-Commit-Position: refs/heads/master@{#322425}