AppRTCDemo file logging.

AppRTCDemo file logging.

Adds logging macros to log logs to a file. Undeletes CircularFileStream
for that purpose.

BUG=
R=jiayl@webrtc.org, pbos@webrtc.org

Committed: https://chromium.googlesource.com/external/webrtc/+/2d3b7e2173c672dca5d97d9a5c8ab4217652c442

[tkchin_webrtc, 2015-07-01 19:28:44]

Patchset #1 (id:1) has been deleted

[tkchin_webrtc, 2015-07-01 19:38:10]

Patchset #1 (id:20001) has been deleted

[tkchin_webrtc, 2015-07-01 19:38:18]

Patchset #1 (id:40001) has been deleted

[tkchin_webrtc, 2015-07-01 20:51:16]

tkchin@webrtc.org changed reviewers:
+ jiayl@webrtc.org, pbos@webrtc.org

[pbos-webrtc, 2015-07-02 07:41:44]

lgtm, thanks

[tkchin_webrtc, 2015-07-06 18:11:16]

On 2015/07/02 07:41:44, pbos-webrtc wrote:
> lgtm, thanks

thanks pbos!

ping jiayl@ for webrtc/base/* OWNERS.

[jiayl2, 2015-07-06 18:18:14]

https://codereview.chromium.org/1217473011/diff/60001/talk/app/webrtc/objc/RT...
File talk/app/webrtc/objc/RTCFileLogger.mm (right):

https://codereview.chromium.org/1217473011/diff/60001/talk/app/webrtc/objc/RT...
talk/app/webrtc/objc/RTCFileLogger.mm:71: NSString *defaultFilePath =
[documentsDirPath stringByAppendingPathComponent:kDefaultLogFileName];
Is this file private to the application? We shouldn't allow other applications
to read/write to it.

https://codereview.chromium.org/1217473011/diff/60001/talk/app/webrtc/objc/RT...
talk/app/webrtc/objc/RTCFileLogger.mm:103:
rtc::LogMessage::AddLogToStream(_logSink.get(), rtc::LS_INFO);
FYI we'll need a switch to turn on verbose logging from the application
settings. Might be easier to add it now. Up to you.

https://codereview.chromium.org/1217473011/diff/60001/talk/examples/objc/AppR...
File talk/examples/objc/AppRTCDemo/common/ARDLogging.mm (right):

https://codereview.chromium.org/1217473011/diff/60001/talk/examples/objc/AppR...
talk/examples/objc/AppRTCDemo/common/ARDLogging.mm:32: void
ARDLogToWebRTCLogger(NSString *logString) {
Add a severity level instead of all LS_INFO?

https://codereview.chromium.org/1217473011/diff/60001/webrtc/base/stream.cc
File webrtc/base/stream.cc (right):

https://codereview.chromium.org/1217473011/diff/60001/webrtc/base/stream.cc#n...
webrtc/base/stream.cc:609: position_ = marked_position_;
I'm not sure this is what we want IIUC. If the max size is 1000 and the actual
total log size is 1001, this class will result in the fist 500 and the last 1
bytes written, right?
What we really want will be the first 500 and the last 500.

https://codereview.chromium.org/1217473011/diff/60001/webrtc/base/stream.h
File webrtc/base/stream.h (right):

https://codereview.chromium.org/1217473011/diff/60001/webrtc/base/stream.h#ne...
webrtc/base/stream.h:424: class CircularFileStream : public FileStream {
I think we need unit tests for this class. If the current design makes it hard
to mock the file system dependency, we can change the inheritance to
composition, i.e. inject a StreamInterface to the ctor.

[tkchin, 2015-07-06 20:36:49]

tkchin@chromium.org changed reviewers:
+ tkchin@chromium.org

[tkchin, 2015-07-06 20:36:50]

https://codereview.chromium.org/1217473011/diff/60001/talk/app/webrtc/objc/RT...
File talk/app/webrtc/objc/RTCFileLogger.mm (right):

https://codereview.chromium.org/1217473011/diff/60001/talk/app/webrtc/objc/RT...
talk/app/webrtc/objc/RTCFileLogger.mm:71: NSString *defaultFilePath =
[documentsDirPath stringByAppendingPathComponent:kDefaultLogFileName];
On 2015/07/06 18:18:14, jiayl2 wrote:
> Is this file private to the application? We shouldn't allow other applications
> to read/write to it.

Yes, it's private to the app bundle. Applications on iOS are sandboxed. You
could potentially read it if you read the iOS files using USB cable but
otherwise no (so maybe don't write sensitive things).

https://codereview.chromium.org/1217473011/diff/60001/talk/app/webrtc/objc/RT...
talk/app/webrtc/objc/RTCFileLogger.mm:103:
rtc::LogMessage::AddLogToStream(_logSink.get(), rtc::LS_INFO);
On 2015/07/06 18:18:14, jiayl2 wrote:
> FYI we'll need a switch to turn on verbose logging from the application
> settings. Might be easier to add it now. Up to you.

What logs do we get in verbose?

https://codereview.chromium.org/1217473011/diff/60001/talk/examples/objc/AppR...
File talk/examples/objc/AppRTCDemo/common/ARDLogging.mm (right):

https://codereview.chromium.org/1217473011/diff/60001/talk/examples/objc/AppR...
talk/examples/objc/AppRTCDemo/common/ARDLogging.mm:32: void
ARDLogToWebRTCLogger(NSString *logString) {
On 2015/07/06 18:18:14, jiayl2 wrote:
> Add a severity level instead of all LS_INFO? 

How useful is severity level in app context? I feel like it's easier just to use
one macro (ARDLog) and severity because odds are there won't be much app logging
compared to WebRTC spew. If there are app level errors they should be fairly
obvious from the logs without needing to filter.

https://codereview.chromium.org/1217473011/diff/60001/webrtc/base/stream.cc
File webrtc/base/stream.cc (right):

https://codereview.chromium.org/1217473011/diff/60001/webrtc/base/stream.cc#n...
webrtc/base/stream.cc:609: position_ = marked_position_;
On 2015/07/06 18:18:14, jiayl2 wrote:
> I'm not sure this is what we want IIUC. If the max size is 1000 and the actual
> total log size is 1001, this class will result in the fist 500 and the last 1
> bytes written, right?
> What we really want will be the first 500 and the last 500.

Hmm I should've looked closer at this, I just undeleted and glanced through,
thanks for pointing out the strangeness here. This has been the historical
behavior used by webrtc consumers.

If max size is 1000 and 1001 bytes are written, what's written depends on the
data lengths. Assuming that the data_len each call is made so that we don't
truncate, the file structure will be:
[0-499] Log bytes 0-499 (start)
[500] Log byte 1000 [the 1001st byte] (end)
[501-999]  Log bytes 501-999 (middle)
Where log byte 500 is gone.

So you do get the first 500 and the last 500. It's the middle portion that's not
quite the middle.

e.g.
If we wrote 1500 bytes we'd have:
[0-499] Log bytes 0-499 (start)
[500-999] Log bytes 1000-1499 (end)

and if we wrote 1750 bytes we'd have:
[0-499] Log bytes 0-499 (start)
[500-749] Log bytes 1500-1749 (end)
[750-999] Log bytes 1250-1499 (middle)

So really we're keeping the first and last 500 bytes always, but the way you
read the last 500 bytes is wonky / timestamp dependent.

The other way we could do this is with two files for the last 500 bytes, where
we swap writing between files if the current one gets full. I don't think there
is much benefit to doing that though since our logs should have timestamps on
them and it should be easy to isolate the sections we care about. wdyt?

https://codereview.chromium.org/1217473011/diff/60001/webrtc/base/stream.h
File webrtc/base/stream.h (right):

https://codereview.chromium.org/1217473011/diff/60001/webrtc/base/stream.h#ne...
webrtc/base/stream.h:424: class CircularFileStream : public FileStream {
On 2015/07/06 18:18:14, jiayl2 wrote:
> I think we need unit tests for this class. If the current design makes it hard
> to mock the file system dependency, we can change the inheritance to
> composition, i.e. inject a StreamInterface to the ctor.

I just reverted the deletion which didn't have UTs before. Working on adding
them now.

[jiayl2, 2015-07-06 20:55:22]

https://codereview.chromium.org/1217473011/diff/60001/webrtc/base/stream.cc
File webrtc/base/stream.cc (right):

https://codereview.chromium.org/1217473011/diff/60001/webrtc/base/stream.cc#n...
webrtc/base/stream.cc:609: position_ = marked_position_;
On 2015/07/06 20:36:50, tkchin wrote:
> On 2015/07/06 18:18:14, jiayl2 wrote:
> > I'm not sure this is what we want IIUC. If the max size is 1000 and the
actual
> > total log size is 1001, this class will result in the fist 500 and the last
1
> > bytes written, right?
> > What we really want will be the first 500 and the last 500.
> 
> Hmm I should've looked closer at this, I just undeleted and glanced through,
> thanks for pointing out the strangeness here. This has been the historical
> behavior used by webrtc consumers.
> 
> If max size is 1000 and 1001 bytes are written, what's written depends on the
> data lengths. Assuming that the data_len each call is made so that we don't
> truncate, the file structure will be:
> [0-499] Log bytes 0-499 (start)
> [500] Log byte 1000 [the 1001st byte] (end)
> [501-999]  Log bytes 501-999 (middle)
> Where log byte 500 is gone.
> 
> So you do get the first 500 and the last 500. It's the middle portion that's
not
> quite the middle.
> 
> e.g.
> If we wrote 1500 bytes we'd have:
> [0-499] Log bytes 0-499 (start)
> [500-999] Log bytes 1000-1499 (end)
> 
> and if we wrote 1750 bytes we'd have:
> [0-499] Log bytes 0-499 (start)
> [500-749] Log bytes 1500-1749 (end)
> [750-999] Log bytes 1250-1499 (middle)
> 
> So really we're keeping the first and last 500 bytes always, but the way you
> read the last 500 bytes is wonky / timestamp dependent.
> 
> The other way we could do this is with two files for the last 500 bytes, where
> we swap writing between files if the current one gets full. I don't think
there
> is much benefit to doing that though since our logs should have timestamps on
> them and it should be easy to isolate the sections we care about. wdyt?

The log uploaded should have the messages in the right order, otherwise it'll be
super confusing to analyze the log.

Looking at ::Read, it seems it already reorders the segments, so we can just
make sure to read the file using that method. But we should verify it in unit
tests. :)

[jiayl2, 2015-07-06 20:57:56]

https://codereview.chromium.org/1217473011/diff/60001/talk/app/webrtc/objc/RT...
File talk/app/webrtc/objc/RTCFileLogger.mm (right):

https://codereview.chromium.org/1217473011/diff/60001/talk/app/webrtc/objc/RT...
talk/app/webrtc/objc/RTCFileLogger.mm:103:
rtc::LogMessage::AddLogToStream(_logSink.get(), rtc::LS_INFO);
On 2015/07/06 20:36:50, tkchin wrote:
> On 2015/07/06 18:18:14, jiayl2 wrote:
> > FYI we'll need a switch to turn on verbose logging from the application
> > settings. Might be easier to add it now. Up to you.
> 
> What logs do we get in verbose?

Verbose webrtc logs contain detailed information about the ICE processes and
have been useful for debugging ICE issues on Android.

https://codereview.chromium.org/1217473011/diff/60001/talk/examples/objc/AppR...
File talk/examples/objc/AppRTCDemo/common/ARDLogging.mm (right):

https://codereview.chromium.org/1217473011/diff/60001/talk/examples/objc/AppR...
talk/examples/objc/AppRTCDemo/common/ARDLogging.mm:32: void
ARDLogToWebRTCLogger(NSString *logString) {
On 2015/07/06 20:36:50, tkchin wrote:
> On 2015/07/06 18:18:14, jiayl2 wrote:
> > Add a severity level instead of all LS_INFO? 
> 
> How useful is severity level in app context? I feel like it's easier just to
use
> one macro (ARDLog) and severity because odds are there won't be much app
logging
> compared to WebRTC spew. If there are app level errors they should be fairly
> obvious from the logs without needing to filter.

It'll make it easier to automatically analyze the log, e.g. listing
errors/warnings from the application.

[tkchin_webrtc, 2015-07-07 23:30:10]

PTAL

https://codereview.webrtc.org/1217473011/diff/60001/talk/app/webrtc/objc/RTCF...
File talk/app/webrtc/objc/RTCFileLogger.mm (right):

https://codereview.webrtc.org/1217473011/diff/60001/talk/app/webrtc/objc/RTCF...
talk/app/webrtc/objc/RTCFileLogger.mm:103:
rtc::LogMessage::AddLogToStream(_logSink.get(), rtc::LS_INFO);
On 2015/07/06 20:57:56, jiayl2 wrote:
> On 2015/07/06 20:36:50, tkchin wrote:
> > On 2015/07/06 18:18:14, jiayl2 wrote:
> > > FYI we'll need a switch to turn on verbose logging from the application
> > > settings. Might be easier to add it now. Up to you.
> > 
> > What logs do we get in verbose?
> 
> Verbose webrtc logs contain detailed information about the ICE processes and
> have been useful for debugging ICE issues on Android.

Ok. Making that the default then if it contains useful details. Assumption is
that this file logger is to log things useful for debugging anyway.

https://codereview.webrtc.org/1217473011/diff/60001/talk/examples/objc/AppRTC...
File talk/examples/objc/AppRTCDemo/common/ARDLogging.mm (right):

https://codereview.webrtc.org/1217473011/diff/60001/talk/examples/objc/AppRTC...
talk/examples/objc/AppRTCDemo/common/ARDLogging.mm:32: void
ARDLogToWebRTCLogger(NSString *logString) {
On 2015/07/06 20:57:56, jiayl2 wrote:
> On 2015/07/06 20:36:50, tkchin wrote:
> > On 2015/07/06 18:18:14, jiayl2 wrote:
> > > Add a severity level instead of all LS_INFO? 
> > 
> > How useful is severity level in app context? I feel like it's easier just to
> use
> > one macro (ARDLog) and severity because odds are there won't be much app
> logging
> > compared to WebRTC spew. If there are app level errors they should be fairly
> > obvious from the logs without needing to filter.
> 
> It'll make it easier to automatically analyze the log, e.g. listing
> errors/warnings from the application.

The philosophy on iOS (at least that I've been following) is that we only log
things worthy of warning/error in release builds. In debug builds we have
additional logging through a macro that gets compiled out during release. But
that might just be because there aren't good logging facilities on iOS. Added
severity bits since we get them for free anyway.

[jiayl2, 2015-07-08 16:32:13]

https://codereview.webrtc.org/1217473011/diff/60001/talk/app/webrtc/objc/RTCF...
File talk/app/webrtc/objc/RTCFileLogger.mm (right):

https://codereview.webrtc.org/1217473011/diff/60001/talk/app/webrtc/objc/RTCF...
talk/app/webrtc/objc/RTCFileLogger.mm:103:
rtc::LogMessage::AddLogToStream(_logSink.get(), rtc::LS_INFO);
On 2015/07/07 23:30:10, tkchin_webrtc wrote:
> On 2015/07/06 20:57:56, jiayl2 wrote:
> > On 2015/07/06 20:36:50, tkchin wrote:
> > > On 2015/07/06 18:18:14, jiayl2 wrote:
> > > > FYI we'll need a switch to turn on verbose logging from the application
> > > > settings. Might be easier to add it now. Up to you.
> > > 
> > > What logs do we get in verbose?
> > 
> > Verbose webrtc logs contain detailed information about the ICE processes and
> > have been useful for debugging ICE issues on Android.
> 
> Ok. Making that the default then if it contains useful details. Assumption is
> that this file logger is to log things useful for debugging anyway.

We should default to "info". Verbose is too noisy for most cases since it logs
every STUN ping and response.

https://codereview.webrtc.org/1217473011/diff/120001/webrtc/base/stream.cc
File webrtc/base/stream.cc (right):

https://codereview.webrtc.org/1217473011/diff/120001/webrtc/base/stream.cc#ne...
webrtc/base/stream.cc:520: CircularFileStream::CircularFileStream(size_t
max_size)
I thought you were going to write a new impl of circular buffer?

[tkchin_webrtc, 2015-07-08 18:18:23]

https://codereview.webrtc.org/1217473011/diff/60001/talk/app/webrtc/objc/RTCF...
File talk/app/webrtc/objc/RTCFileLogger.mm (right):

https://codereview.webrtc.org/1217473011/diff/60001/talk/app/webrtc/objc/RTCF...
talk/app/webrtc/objc/RTCFileLogger.mm:103:
rtc::LogMessage::AddLogToStream(_logSink.get(), rtc::LS_INFO);
On 2015/07/08 16:32:12, jiayl2 wrote:
> On 2015/07/07 23:30:10, tkchin_webrtc wrote:
> > On 2015/07/06 20:57:56, jiayl2 wrote:
> > > On 2015/07/06 20:36:50, tkchin wrote:
> > > > On 2015/07/06 18:18:14, jiayl2 wrote:
> > > > > FYI we'll need a switch to turn on verbose logging from the
application
> > > > > settings. Might be easier to add it now. Up to you.
> > > > 
> > > > What logs do we get in verbose?
> > > 
> > > Verbose webrtc logs contain detailed information about the ICE processes
and
> > > have been useful for debugging ICE issues on Android.
> > 
> > Ok. Making that the default then if it contains useful details. Assumption
is
> > that this file logger is to log things useful for debugging anyway.
> 
> We should default to "info". Verbose is too noisy for most cases since it logs
> every STUN ping and response.

Done.

https://codereview.webrtc.org/1217473011/diff/120001/webrtc/base/stream.cc
File webrtc/base/stream.cc (right):

https://codereview.webrtc.org/1217473011/diff/120001/webrtc/base/stream.cc#ne...
webrtc/base/stream.cc:520: CircularFileStream::CircularFileStream(size_t
max_size)
On 2015/07/08 16:32:13, jiayl2 wrote:
> I thought you were going to write a new impl of circular buffer?

The reason I wanted to was because in crash scenario we could end up with
unordered log. But with rolling dual log solution we talked about yesterday
we'll end up with either truncated log (if we delete the second file when we
attempt to write to it) or similar disordered log (if we just start writing to
the start without clearing contents first). In fact if we delete then in common
case we will have almost always cleared up to a quarter of the data
unnecessarily. So we're not really better off, and it made sense to me to just
keep this impl for now where we use just one file.

In order to get good crash behavior, this class probably just needs two reserved
position markers embedded into the file stream. A simple scheme for marker could
just be to restrict logging to ascii characters, then we can use anything > 0x7F
as a marker. As long as we can make writes atomic, we'll always be able to
recover the original stream ordering.

Given that it was mentioned there there could be automated log filtering tools,
and that logs have timestamps, I figured that it was better just to get this in
first, since automated tool can just sort the log by timestamp anyway if indeed
we crash. For general diagnostics where we look for verbose logs this should
work just fine. We can improve the class in future CL, and leave it unmodified
for now.

[jiayl2, 2015-07-08 18:26:14]

https://codereview.webrtc.org/1217473011/diff/120001/webrtc/base/stream.cc
File webrtc/base/stream.cc (right):

https://codereview.webrtc.org/1217473011/diff/120001/webrtc/base/stream.cc#ne...
webrtc/base/stream.cc:520: CircularFileStream::CircularFileStream(size_t
max_size)
On 2015/07/08 18:18:23, tkchin_webrtc wrote:
> On 2015/07/08 16:32:13, jiayl2 wrote:
> > I thought you were going to write a new impl of circular buffer?
> 
> The reason I wanted to was because in crash scenario we could end up with
> unordered log. But with rolling dual log solution we talked about yesterday
> we'll end up with either truncated log (if we delete the second file when we
> attempt to write to it) or similar disordered log (if we just start writing to
> the start without clearing contents first). In fact if we delete then in
common
> case we will have almost always cleared up to a quarter of the data
> unnecessarily. So we're not really better off, and it made sense to me to just
> keep this impl for now where we use just one file.
> 
> In order to get good crash behavior, this class probably just needs two
reserved
> position markers embedded into the file stream. A simple scheme for marker
could
> just be to restrict logging to ascii characters, then we can use anything >
0x7F
> as a marker. As long as we can make writes atomic, we'll always be able to
> recover the original stream ordering.
> 
> Given that it was mentioned there there could be automated log filtering
tools,
> and that logs have timestamps, I figured that it was better just to get this
in
> first, since automated tool can just sort the log by timestamp anyway if
indeed
> we crash. For general diagnostics where we look for verbose logs this should
> work just fine. We can improve the class in future CL, and leave it unmodified
> for now.
> 
> 
> 
> 

I'm fine with landing the CL as is and file bugs for remaining issues.

Besides the crash scenario, we also need delayed upload, i.e. upload in the next
app launch if there is no network at the end of a call.
We would need to remember if there is a log pending to upload, which could be
written to a meta data file with the info of the log size/ordering.
Please file a bug for the remaining work.

[tkchin, 2015-07-14 17:53:00]

On 2015/07/08 18:26:14, jiayl2 wrote:
> https://codereview.webrtc.org/1217473011/diff/120001/webrtc/base/stream.cc
> File webrtc/base/stream.cc (right):
> 
>
https://codereview.webrtc.org/1217473011/diff/120001/webrtc/base/stream.cc#ne...
> webrtc/base/stream.cc:520: CircularFileStream::CircularFileStream(size_t
> max_size)
> On 2015/07/08 18:18:23, tkchin_webrtc wrote:
> > On 2015/07/08 16:32:13, jiayl2 wrote:
> > > I thought you were going to write a new impl of circular buffer?
> > 
> > The reason I wanted to was because in crash scenario we could end up with
> > unordered log. But with rolling dual log solution we talked about yesterday
> > we'll end up with either truncated log (if we delete the second file when we
> > attempt to write to it) or similar disordered log (if we just start writing
to
> > the start without clearing contents first). In fact if we delete then in
> common
> > case we will have almost always cleared up to a quarter of the data
> > unnecessarily. So we're not really better off, and it made sense to me to
just
> > keep this impl for now where we use just one file.
> > 
> > In order to get good crash behavior, this class probably just needs two
> reserved
> > position markers embedded into the file stream. A simple scheme for marker
> could
> > just be to restrict logging to ascii characters, then we can use anything >
> 0x7F
> > as a marker. As long as we can make writes atomic, we'll always be able to
> > recover the original stream ordering.
> > 
> > Given that it was mentioned there there could be automated log filtering
> tools,
> > and that logs have timestamps, I figured that it was better just to get this
> in
> > first, since automated tool can just sort the log by timestamp anyway if
> indeed
> > we crash. For general diagnostics where we look for verbose logs this should
> > work just fine. We can improve the class in future CL, and leave it
unmodified
> > for now.
> > 
> > 
> > 
> > 
> 
> I'm fine with landing the CL as is and file bugs for remaining issues.
> 
> Besides the crash scenario, we also need delayed upload, i.e. upload in the
next
> app launch if there is no network at the end of a call.
> We would need to remember if there is a log pending to upload, which could be
> written to a meta data file with the info of the log size/ordering.
> Please file a bug for the remaining work.

Filed:
https://code.google.com/p/webrtc/issues/detail?id=4838
https://code.google.com/p/webrtc/issues/detail?id=4839

Does this mean I get an l-g-t-m? :)

[jiayl2, 2015-07-14 17:55:18]

lgtm

[tkchin_webrtc, 2015-07-14 19:56:02]

Committed patchset #6 (id:160001) manually as
2d3b7e2173c672dca5d97d9a5c8ab4217652c442 (presubmit successful).

[henrika_webrtc, 2015-07-15 08:36:00]

henrika@webrtc.org changed reviewers:
+ henrika@webrtc.org

[henrika_webrtc, 2015-07-15 08:36:01]

Nice work!

https://codereview.webrtc.org/1217473011/diff/160001/talk/app/webrtc/objc/RTC...
File talk/app/webrtc/objc/RTCFileLogger.mm (right):

https://codereview.webrtc.org/1217473011/diff/160001/talk/app/webrtc/objc/RTC...
talk/app/webrtc/objc/RTCFileLogger.mm:116: // TODO(tkchin): Log thead info on
iOS, currently this doesn't do anything.
It actually does now :-) Please try it out.