Cast channel: Add cast.channel.getLogs extension API.

Cast channel: Add cast.channel.getLogs extension API.

Added gzip compression to the logs after serialization.

The cast.channel.getLogs API will calls the Logger class, which in
turns assmebles the Log in protocol buffer format, serializes it, and
apply gzip compression to it. The resulting blob is then passed through
the caller-supplied callback.

BUG=343228
Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=289842

[imcheng, 2014-08-10 20:14:01]

I am going to talk to Haibin about how to surface the error events to the
extension itself so we can log them via analytics. We can probably use the same
getLogs API and just add an extra parameter to the callback.

Reviews requested:
wez, mfoltz - everything
isherman@ - histograms.xml OWNERs review.

[imcheng, 2014-08-10 22:40:24]

Add gavinp@ for adding +third_party/zlib rule to DEPS.

[mark a. foltz, 2014-08-11 23:01:44]

Mostly looks good, hopefully there is a working zlib wrapper we can use rather
than crafting our own compression/decompression routines.

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
File extensions/browser/api/cast_channel/cast_channel_api.cc (right):

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/cast_channel_api.cc:475: if
(api_->GetLogger()->LogToString(&log)) {
How about having a LogToValue() method that can have the value take ownership of
the buffer, avoiding a copy?

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/cast_channel_api.cc:477:
base::BinaryValue::CreateWithCopiedBuffer(&log[0], log.size());
log.data()

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/cast_channel_api.cc:480: SetResult(new
base::BinaryValue());
Does this mean no events were logged?  Or is this how an error is signaled?

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
File extensions/browser/api/cast_channel/logger.cc (right):

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.cc:70: DCHECK_EQ(Z_OK, result);
Can this never actually fail?

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.cc:72: stream.next_in =
reinterpret_cast<uint8*>(const_cast<char*>(&input[0]));
input.data()

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.cc:72: stream.next_in =
reinterpret_cast<uint8*>(const_cast<char*>(&input[0]));
Add a COMPILE_ASSERT that sizeof(uint8) == sizeof(char).

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.cc:74: stream.next_out =
reinterpret_cast<uint8*>(&(*output)[0]);
output->data()

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.cc:83: if (result == Z_OK) {
while (result == Z_OK) {
...
}

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.cc:86: output->resize(old_size +
input.size());
net::GrowableIOBuffer would be a better abstraction than dealing with
std::string.

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.cc:87: stream.next_out =
reinterpret_cast<uint8*>(&(*output)[old_size]);
Is this code cribbed from somewhere else?  I would be surprised if there isn't a
utility function already written for this.

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.cc:96: VLOG(2) << "deflate() failed.
Result: " << result;
return early here?

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.cc:101: if (success)
Do we need to check result here?

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
File extensions/browser/api/cast_channel/logger_unittest.cc (right):

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger_unittest.cc:90: std::string output;
Lines 90-101 could be encapsulated in a utility function that returns a
decompressed Log instance from logger_.

Or, add an API to logger_ to get the Log object directly so you don't have to
decompress it for every test case.

https://codereview.chromium.org/456213002/diff/20001/extensions/common/api/ca...
File extensions/common/api/cast_channel.idl (right):

https://codereview.chromium.org/456213002/diff/20001/extensions/common/api/ca...
extensions/common/api/cast_channel.idl:169: // it is invoked with an empty
ArrayBuffer.
I think the preferred approach is to use chrome.runtime.lastError to report
errors instead.  See the examples in other API functions.

[Ilya Sherman, 2014-08-12 01:37:46]

Histograms LGTM.  Thanks for updating the comment.

[imcheng, 2014-08-12 07:42:10]

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
File extensions/browser/api/cast_channel/cast_channel_api.cc (right):

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/cast_channel_api.cc:475: if
(api_->GetLogger()->LogToString(&log)) {
On 2014/08/11 23:01:43, mark a. foltz wrote:
> How about having a LogToValue() method that can have the value take ownership
of
> the buffer, avoiding a copy?

Yes, that's possible by asking zlib for the compressed upper bound size, then
Logger can allocate that buffer,  populate it, and return it. Done here.

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/cast_channel_api.cc:477:
base::BinaryValue::CreateWithCopiedBuffer(&log[0], log.size());
On 2014/08/11 23:01:43, mark a. foltz wrote:
> log.data()

Done.

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/cast_channel_api.cc:480: SetResult(new
base::BinaryValue());
On 2014/08/11 23:01:43, mark a. foltz wrote:
> Does this mean no events were logged?  Or is this how an error is signaled?

If no events is logged then a blob representing an empty Log proto will be
returned. This branch means something failed while getting logs (e.g.
serialization failed, compression failed, or some other reason). But I changed
it to SetError() instead.

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
File extensions/browser/api/cast_channel/logger.cc (right):

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.cc:70: DCHECK_EQ(Z_OK, result);
On 2014/08/11 23:01:44, mark a. foltz wrote:
> Can this never actually fail?

Normally this shouldn't fail, unless there is not enough memory or if the
parameters are invalid.

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.cc:72: stream.next_in =
reinterpret_cast<uint8*>(const_cast<char*>(&input[0]));
On 2014/08/11 23:01:44, mark a. foltz wrote:
> Add a COMPILE_ASSERT that sizeof(uint8) == sizeof(char).

Done.

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.cc:72: stream.next_in =
reinterpret_cast<uint8*>(const_cast<char*>(&input[0]));
On 2014/08/11 23:01:44, mark a. foltz wrote:
> Add a COMPILE_ASSERT that sizeof(uint8) == sizeof(char).

Done.

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.cc:74: stream.next_out =
reinterpret_cast<uint8*>(&(*output)[0]);
On 2014/08/11 23:01:44, mark a. foltz wrote:
> output->data()

Done.

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.cc:83: if (result == Z_OK) {
On 2014/08/11 23:01:44, mark a. foltz wrote:
> while (result == Z_OK) {
> ...
> }

Removed since we are doing one-shot compression.

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.cc:86: output->resize(old_size +
input.size());
On 2014/08/11 23:01:43, mark a. foltz wrote:
> net::GrowableIOBuffer would be a better abstraction than dealing with
> std::string.

Removed since we are doing one-shot compression.

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.cc:87: stream.next_out =
reinterpret_cast<uint8*>(&(*output)[old_size]);
On 2014/08/11 23:01:44, mark a. foltz wrote:
> Is this code cribbed from somewhere else?  I would be surprised if there isn't
a
> utility function already written for this.

There is an utility function close to this in zlib.h, but it outputs in zlib
format instead of gzip. I have not found an utility function that outputs in
gzip format. (There's a net::GzipFilter but is only used privately in the
namespace)

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.cc:96: VLOG(2) << "deflate() failed.
Result: " << result;
On 2014/08/11 23:01:44, mark a. foltz wrote:
> return early here?

deflateEnd() needs to be called even if deflate() failed.

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.cc:101: if (success)
On 2014/08/11 23:01:44, mark a. foltz wrote:
> Do we need to check result here?

No. deflateEnd() returns Z_OK if deflate() was successful, Z_DATA_ERROR
otherwise. Checking success is sufficient.

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
File extensions/browser/api/cast_channel/logger_unittest.cc (right):

https://codereview.chromium.org/456213002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger_unittest.cc:90: std::string output;
On 2014/08/11 23:01:44, mark a. foltz wrote:
> Lines 90-101 could be encapsulated in a utility function that returns a
> decompressed Log instance from logger_.
> 
> Or, add an API to logger_ to get the Log object directly so you don't have to
> decompress it for every test case.

Added utility function in this test. Since we don't need to use decompression in
production code.

https://codereview.chromium.org/456213002/diff/20001/extensions/common/api/ca...
File extensions/common/api/cast_channel.idl (right):

https://codereview.chromium.org/456213002/diff/20001/extensions/common/api/ca...
extensions/common/api/cast_channel.idl:169: // it is invoked with an empty
ArrayBuffer.
On 2014/08/11 23:01:44, mark a. foltz wrote:
> I think the preferred approach is to use chrome.runtime.lastError to report
> errors instead.  See the examples in other API functions.

Done. I assume this is done using SetError()? Is the new comment accurate?

[imcheng, 2014-08-13 00:03:08]

Adding kalman@ for cast_channel.idl.

[not at google - send to devlin, 2014-08-13 00:07:43]

idl lgtm

[imcheng, 2014-08-13 16:54:33]

Ping for review and zlib owners LGTM.

[Wez, 2014-08-13 20:32:25]

https://codereview.chromium.org/456213002/diff/40001/extensions/browser/api/c...
File extensions/browser/api/cast_channel/cast_channel_apitest.cc (right):

https://codereview.chromium.org/456213002/diff/40001/extensions/browser/api/c...
extensions/browser/api/cast_channel/cast_channel_apitest.cc:122: InSequence
dummy;
nit: s/dummy/sequence or simply 's'

https://codereview.chromium.org/456213002/diff/60001/extensions/browser/api/c...
File extensions/browser/api/cast_channel/logger.h (right):

https://codereview.chromium.org/456213002/diff/60001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.h:76: scoped_ptr<char[]> GetLogs(int*
length) const;
What's the rationale for changing this API from having returning data in
std::string (or via scoped_ptr<std::string>)?

[imcheng, 2014-08-13 20:46:04]

https://codereview.chromium.org/456213002/diff/40001/extensions/browser/api/c...
File extensions/browser/api/cast_channel/cast_channel_apitest.cc (right):

https://codereview.chromium.org/456213002/diff/40001/extensions/browser/api/c...
extensions/browser/api/cast_channel/cast_channel_apitest.cc:122: InSequence
dummy;
On 2014/08/13 20:32:25, Wez wrote:
> nit: s/dummy/sequence or simply 's'

Done.

https://codereview.chromium.org/456213002/diff/60001/extensions/browser/api/c...
File extensions/browser/api/cast_channel/logger.h (right):

https://codereview.chromium.org/456213002/diff/60001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.h:76: scoped_ptr<char[]> GetLogs(int*
length) const;
On 2014/08/13 20:32:25, Wez wrote:
> What's the rationale for changing this API from having returning data in
> std::string (or via scoped_ptr<std::string>)?

The rationale is to avoid an extra copy when constructing the base::BinaryValue
in cast_channel_api.cc, by passing ownership of the char[] in the constructor.

[mark a. foltz, 2014-08-13 22:00:24]

lgtm

https://codereview.chromium.org/456213002/diff/80001/extensions/browser/api/c...
File extensions/browser/api/cast_channel/logger_unittest.cc (right):

https://codereview.chromium.org/456213002/diff/80001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger_unittest.cc:105:
ASSERT_TRUE(GetLog(&log));
I might write this as

scoped_ptr<Log> log(GetLog());

where GetLog() returns a Log* and calls the ASSERT.  But not a big deal.

[imcheng, 2014-08-13 23:58:14]

https://codereview.chromium.org/456213002/diff/80001/extensions/browser/api/c...
File extensions/browser/api/cast_channel/logger_unittest.cc (right):

https://codereview.chromium.org/456213002/diff/80001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger_unittest.cc:105:
ASSERT_TRUE(GetLog(&log));
On 2014/08/13 22:00:24, mark a. foltz wrote:
> I might write this as
> 
> scoped_ptr<Log> log(GetLog());
> 
> where GetLog() returns a Log* and calls the ASSERT.  But not a big deal.
> 
> 
> 

Done.

[mark a. foltz, 2014-08-14 00:09:38]

https://codereview.chromium.org/456213002/diff/100001/extensions/browser/api/...
File extensions/browser/api/cast_channel/logger_unittest.cc (right):

https://codereview.chromium.org/456213002/diff/100001/extensions/browser/api/...
extensions/browser/api/cast_channel/logger_unittest.cc:109:
ASSERT_TRUE(log.get() != NULL);
Sorry, to be clear the ASSERTs would move into GetLog() so you wouldn't need to
add one here. GetLog would always return a non-NULL Log.

[agl, 2014-08-14 00:13:27]

https://codereview.chromium.org/456213002/diff/100001/extensions/browser/api/...
File extensions/browser/api/cast_channel/logger.cc (right):

https://codereview.chromium.org/456213002/diff/100001/extensions/browser/api/...
extensions/browser/api/cast_channel/logger.cc:59: scoped_ptr<char[]>
Compress(const std::string& input, int* length) {
size_t* for length.

https://codereview.chromium.org/456213002/diff/100001/extensions/browser/api/...
extensions/browser/api/cast_channel/logger.cc:70: int out_size =
deflateBound(&stream, input.size());
s/int/size_t/

https://codereview.chromium.org/456213002/diff/100001/extensions/browser/api/...
extensions/browser/api/cast_channel/logger.cc:90: DCHECK(result == Z_OK ||
result == Z_DATA_ERROR);
Why accept Z_DATA_ERROR?

https://codereview.chromium.org/456213002/diff/100001/extensions/browser/api/...
extensions/browser/api/cast_channel/logger.cc:93: *length = out_size -
stream.avail_out;
if not successful, *length is never set. That's probably not good. Maybe set it
to zero at the top of the function?

https://codereview.chromium.org/456213002/diff/100001/extensions/browser/api/...
extensions/browser/api/cast_channel/logger.cc:279: scoped_ptr<char[]>
Logger::GetLogs(int* length) const {
Either the call chain need to be cleaned up so that this can take a size_t* for
the output length (in which case make it a scoped_ptr<uint8[]> too. Or else, at
the bottom, the output of Compress needs to be checked against INT_MAX.

[imcheng, 2014-08-14 00:59:19]

Thanks for the review.

https://codereview.chromium.org/456213002/diff/100001/extensions/browser/api/...
File extensions/browser/api/cast_channel/logger.cc (right):

https://codereview.chromium.org/456213002/diff/100001/extensions/browser/api/...
extensions/browser/api/cast_channel/logger.cc:59: scoped_ptr<char[]>
Compress(const std::string& input, int* length) {
On 2014/08/14 00:13:26, agl wrote:
> size_t* for length.

Done.

https://codereview.chromium.org/456213002/diff/100001/extensions/browser/api/...
extensions/browser/api/cast_channel/logger.cc:70: int out_size =
deflateBound(&stream, input.size());
On 2014/08/14 00:13:26, agl wrote:
> s/int/size_t/

Done.

https://codereview.chromium.org/456213002/diff/100001/extensions/browser/api/...
extensions/browser/api/cast_channel/logger.cc:90: DCHECK(result == Z_OK ||
result == Z_DATA_ERROR);
On 2014/08/14 00:13:27, agl wrote:
> Why accept Z_DATA_ERROR?

deflateEnd() returns Z_DATA_ERROR if deflate() failed since it is discarding
unprocessed input/output. I believe it is not an actual error, but deflateEnd()
needs to be called after deflate() anyway in order to avoid a leak.

https://codereview.chromium.org/456213002/diff/100001/extensions/browser/api/...
extensions/browser/api/cast_channel/logger.cc:93: *length = out_size -
stream.avail_out;
On 2014/08/14 00:13:26, agl wrote:
> if not successful, *length is never set. That's probably not good. Maybe set
it
> to zero at the top of the function?

Done.

https://codereview.chromium.org/456213002/diff/100001/extensions/browser/api/...
extensions/browser/api/cast_channel/logger.cc:279: scoped_ptr<char[]>
Logger::GetLogs(int* length) const {
On 2014/08/14 00:13:26, agl wrote:
> Either the call chain need to be cleaned up so that this can take a size_t*
for
> the output length (in which case make it a scoped_ptr<uint8[]> too. Or else,
at
> the bottom, the output of Compress needs to be checked against INT_MAX.

Changed argument type to size_t*. However changing the return type to
scoped_ptr<uint8[]> results in some ugly reinterpret_casts one level up in
cast_channel_api.cc, since the returned value ultimately needs to be passed into
base::BinaryValue's ctor which expects a scoped_ptr<char[]>. I would prefer
handle the uint8* -> char* casting here.

https://codereview.chromium.org/456213002/diff/100001/extensions/browser/api/...
File extensions/browser/api/cast_channel/logger_unittest.cc (right):

https://codereview.chromium.org/456213002/diff/100001/extensions/browser/api/...
extensions/browser/api/cast_channel/logger_unittest.cc:109:
ASSERT_TRUE(log.get() != NULL);
On 2014/08/14 00:09:38, mark a. foltz wrote:
> Sorry, to be clear the ASSERTs would move into GetLog() so you wouldn't need
to
> add one here. GetLog would always return a non-NULL Log.

Done.

[agl, 2014-08-14 01:01:49]

lgtm

[agl, 2014-08-14 01:01:49]

lgtm

lgtm

[Wez, 2014-08-14 18:51:24]

lgtm

https://codereview.chromium.org/456213002/diff/60001/extensions/browser/api/c...
File extensions/browser/api/cast_channel/logger.h (right):

https://codereview.chromium.org/456213002/diff/60001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.h:76: scoped_ptr<char[]> GetLogs(int*
length) const;
On 2014/08/13 20:46:04, imcheng1 wrote:
> On 2014/08/13 20:32:25, Wez wrote:
> > What's the rationale for changing this API from having returning data in
> > std::string (or via scoped_ptr<std::string>)?
> 
> The rationale is to avoid an extra copy when constructing the
base::BinaryValue
> in cast_channel_api.cc, by passing ownership of the char[] in the constructor.

Would it make sense to have GetLogs() return a scoped_ptr<base::BinaryValue>
then?

https://codereview.chromium.org/456213002/diff/140001/extensions/browser/api/...
File extensions/browser/api/cast_channel/logger_unittest.cc (right):

https://codereview.chromium.org/456213002/diff/140001/extensions/browser/api/...
extensions/browser/api/cast_channel/logger_unittest.cc:66: // 100kb should be
enough for test purposes.
Do any of these tests even generate 10kb of data?

[imcheng, 2014-08-14 21:12:35]

https://codereview.chromium.org/456213002/diff/60001/extensions/browser/api/c...
File extensions/browser/api/cast_channel/logger.h (right):

https://codereview.chromium.org/456213002/diff/60001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.h:76: scoped_ptr<char[]> GetLogs(int*
length) const;
On 2014/08/14 18:51:23, Wez wrote:
> On 2014/08/13 20:46:04, imcheng1 wrote:
> > On 2014/08/13 20:32:25, Wez wrote:
> > > What's the rationale for changing this API from having returning data in
> > > std::string (or via scoped_ptr<std::string>)?
> > 
> > The rationale is to avoid an extra copy when constructing the
> base::BinaryValue
> > in cast_channel_api.cc, by passing ownership of the char[] in the
constructor.
> 
> Would it make sense to have GetLogs() return a scoped_ptr<base::BinaryValue>
> then?

I think either way is fine. We can change it to base::BinaryValue in a later
patch.

https://codereview.chromium.org/456213002/diff/140001/extensions/browser/api/...
File extensions/browser/api/cast_channel/logger_unittest.cc (right):

https://codereview.chromium.org/456213002/diff/140001/extensions/browser/api/...
extensions/browser/api/cast_channel/logger_unittest.cc:66: // 100kb should be
enough for test purposes.
On 2014/08/14 18:51:23, Wez wrote:
> Do any of these tests even generate 10kb of data?

Changed to 20kb. 10kb wasn't enough for the eviction test cases.

[imcheng, 2014-08-14 21:12:41]

The CQ bit was checked by imcheng@chromium.org

[commit-bot: I haz the power, 2014-08-14 21:16:18]

CQ is trying da patch. Follow status at
 https://chromium-status.appspot.com/cq/imcheng@chromium.org/456213002/160001

[imcheng, 2014-08-14 21:32:29]

The CQ bit was checked by imcheng@chromium.org

[commit-bot: I haz the power, 2014-08-14 21:35:59]

CQ is trying da patch. Follow status at
 https://chromium-status.appspot.com/cq/imcheng@chromium.org/456213002/180001

[commit-bot: I haz the power, 2014-08-15 03:39:52]

FYI, CQ is re-trying this CL (attempt #1).
The failing builders are:
  linux_chromium_rel_swarming on tryserver.chromium.linux
(http://build.chromium.org/p/tryserver.chromium.linux/builders/linux_chromium_...)

[imcheng, 2014-08-15 05:10:55]

The CQ bit was checked by imcheng@chromium.org

[commit-bot: I haz the power, 2014-08-15 05:16:52]

CQ is trying da patch. Follow status at
 https://chromium-status.appspot.com/cq/imcheng@chromium.org/456213002/200001

[commit-bot: I haz the power, 2014-08-15 09:17:59]

FYI, CQ is re-trying this CL (attempt #1).
The failing builders are:
  win_chromium_x64_rel on tryserver.chromium.win
(http://build.chromium.org/p/tryserver.chromium.win/builders/win_chromium_x64_...)

[commit-bot: I haz the power, 2014-08-15 14:26:32]

Committed patchset #10 (200001) as 289842