Add net log to UploadDataStream.

net/base/upload_data_stream.cc

 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "net/base/upload_data_stream.h"
 
 #include "base/callback_helpers.h"
 #include "base/logging.h"
+#include "base/values.h"
 #include "net/base/io_buffer.h"
 #include "net/base/net_errors.h"
 
 namespace net {
 
+namespace {
+
+std::unique_ptr<base::Value> NetLogInitInfoCallback(
+    int result,
+    bool is_eof,
+    bool is_chunked,
+    NetLogCaptureMode /* capture_mode */) {
+  std::unique_ptr<base::DictionaryValue> dict(new base::DictionaryValue());
+
+  dict->SetInteger("result:", result);
+  dict->SetBoolean("is_eof:", is_eof);
+  dict->SetBoolean("is_chunked:", is_chunked);

[mmenke, 2016/08/10 20:44:49]

Colons aren't needed on any of these.  If you want, you can see what they look
like by opening up about:net-internals#events, downloading something, and
looking for the URL_REQUEST for that entry (Just search for the URL of the
download in filters, or using ctrl-s).

[maksims (do not use this acc), 2016/08/16 12:00:19]

I have already checked that before but did not pay attention to the colons.

+  return std::move(dict);
+}
+
+std::unique_ptr<base::Value> NetLogStartreadingInfoCallback(
+    int result,
+    int current_position,
+    int total_size,
+    bool is_eof,
+    bool is_chunked,
+    NetLogCaptureMode /* capture_mode */) {
+  std::unique_ptr<base::DictionaryValue> dict(new base::DictionaryValue());
+
+  dict->SetInteger("result:", result);
+  dict->SetInteger("current_position:", current_position);
+  dict->SetInteger("total_size:", total_size);
+  dict->SetBoolean("is_eof:", is_eof);
+  dict->SetBoolean("is_chunked:", is_chunked);

[mmenke, 2016/08/10 20:44:49]

Remove colons.

[maksims (do not use this acc), 2016/08/16 12:00:19]

Done.

+  return std::move(dict);
+}
+
+// Logs when a request has just been started.
+void LogInit(const BoundNetLog& net_log,
+             int error,
+             bool is_eof,
+             bool is_chunked) {
+  net_log.BeginEvent(
+      NetLog::TYPE_UPLOAD_DATA_STREAM_INIT,
+      base::Bind(&NetLogInitInfoCallback, error, is_eof, is_chunked));
+}
+
+// Logs when a request has just completed (before its callback is run).
+void LogRead(const BoundNetLog& net_log,
+             NetLog::EventType event_type,
+             int result,
+             int current_position,
+             int total_size,
+             bool is_eof,
+             bool is_chunked) {
+  if (event_type == NetLog::TYPE_UPLOAD_DATA_STREAM_START_READING) {
+    net_log.AddEvent(event_type, base::Bind(&NetLogStartreadingInfoCallback,
+                                            result, current_position,
+                                            total_size, is_eof, is_chunked));
+  } else {
+    net_log.EndEvent(event_type, base::Bind(&NetLogStartreadingInfoCallback,

[mmenke, 2016/08/10 20:44:49]

The way End event works is there should be a matching Begin event with the same
event type before it.  i.e., we've have a NetLog::TYPE_UPLOAD_DATA_STREAM_READ,
and have a BEGIN_EVENT on start reading, and an END_EVENT on stop reading.

[maksims (do not use this acc), 2016/08/16 12:00:19]

Done.

+                                            result, current_position,
+                                            total_size, is_eof, is_chunked));
+  }
+}
+}

[mmenke, 2016/08/10 20:44:50]

nit:  }  // namespace

(Also should have a blank line before it, to match the blank line after the
start of the namespace)

[maksims (do not use this acc), 2016/08/16 12:00:19]

Done.

+
 UploadDataStream::UploadDataStream(bool is_chunked, int64_t identifier)
     : total_size_(0),
       current_position_(0),
       identifier_(identifier),
       is_chunked_(is_chunked),
       initialized_successfully_(false),
       is_eof_(false) {
 }
 
 UploadDataStream::~UploadDataStream() {
 }
 
-int UploadDataStream::Init(const CompletionCallback& callback) {
+int UploadDataStream::Init(const CompletionCallback& callback,
+                           const BoundNetLog& net_log) {
   Reset();
   DCHECK(!initialized_successfully_);
   DCHECK(callback_.is_null());
   DCHECK(!callback.is_null() || IsInMemory());
-  int result = InitInternal();
+  net_log_ = net_log;

[mmenke, 2016/08/10 20:44:50]

Seems like we should have a begin event here, with no parameters.  That way, if
init hangs, we can see it.

[maksims (do not use this acc), 2016/08/16 12:00:19]

Done.

+
+  int result = InitInternal(net_log_);
   if (result == ERR_IO_PENDING) {
     DCHECK(!IsInMemory());
     callback_ = callback;
   } else {
     OnInitCompleted(result);
   }
+
   return result;
 }
 
 int UploadDataStream::Read(IOBuffer* buf,
                            int buf_len,
                            const CompletionCallback& callback) {
   DCHECK(!callback.is_null() || IsInMemory());
   DCHECK(initialized_successfully_);
   DCHECK_GT(buf_len, 0);
+
+  LogRead(net_log_, NetLog::TYPE_UPLOAD_DATA_STREAM_START_READING, 0,
+          current_position_, total_size_, is_eof_, is_chunked_);

[mmenke, 2016/08/10 20:44:49]

total_size_ is constant, so should just log that when init completes, same with
is_chunked_.

I suggest just logging current_position_ here, and result in the end event. 
Don't think all the extra fields on every event get us enough to be worth the
increase in log size (Makes logs harder to read, and bigger in memory and on
disk)

[maksims (do not use this acc), 2016/08/16 12:00:19]

Done.

+
   if (is_eof_)
     return 0;

[mmenke, 2016/08/10 20:44:49]

This case is missing an end event.  To make sure we always have the event,
suggest getting rid of the early return.  if is_eof_ is true, just set result to
0 and don't call read internal, but *do* call OnReadCompleted.

That makes the logging consistent.

[maksims (do not use this acc), 2016/08/16 12:00:19]

Done.

   int result = ReadInternal(buf, buf_len);
   if (result == ERR_IO_PENDING) {
     DCHECK(!IsInMemory());
     callback_ = callback;
   } else {
     OnReadCompleted(result);
   }
+
   return result;
 }
 
 bool UploadDataStream::IsEOF() const {
   DCHECK(initialized_successfully_);
   DCHECK(is_chunked_ || is_eof_ == (current_position_ == total_size_));
   return is_eof_;
 }
 
 void UploadDataStream::Reset() {

[mmenke, 2016/08/10 20:44:49]

If callback isn't NULL, we should log a read end event, as this also cancels any
pending read.  Maybe log it with the error ERR_ABORTED?

[maksims (do not use this acc), 2016/08/16 12:00:19]

Reset() is called on Init(). It will add more confusion. 

   current_position_ = 0;
   initialized_successfully_ = false;
   is_eof_ = false;
   total_size_ = 0;
   callback_.Reset();
   ResetInternal();
 }
 
 void UploadDataStream::SetSize(uint64_t size) {
   DCHECK(!initialized_successfully_);
@@ skipping 21 matching lines @@
   DCHECK_NE(ERR_IO_PENDING, result);
   DCHECK(!initialized_successfully_);
   DCHECK_EQ(0u, current_position_);
   DCHECK(!is_eof_);
 
   if (result == OK) {
     initialized_successfully_ = true;
     if (!is_chunked_ && total_size_ == 0)
       is_eof_ = true;
   }
+
+  LogInit(net_log_, result, is_eof_, is_chunked_);

[mmenke, 2016/08/10 20:44:49]

I don't think we really need is_eof_ here.  total_size_, on the other hand,
would be useful.

[maksims (do not use this acc), 2016/08/16 12:00:19]

Done.

+
   if (!callback_.is_null())
     base::ResetAndReturn(&callback_).Run(result);
 }
 
 void UploadDataStream::OnReadCompleted(int result) {
   DCHECK(initialized_successfully_);
   DCHECK(result != 0 || is_eof_);
   DCHECK_NE(ERR_IO_PENDING, result);
 
   if (result > 0) {
     current_position_ += result;
     if (!is_chunked_) {
       DCHECK_LE(current_position_, total_size_);
       if (current_position_ == total_size_)
         is_eof_ = true;
     }
   }
 
+  LogRead(net_log_, NetLog::TYPE_UPLOAD_DATA_STREAM_READING_DONE, result,
+          current_position_, total_size_, is_eof_, is_chunked_);
   if (!callback_.is_null())
     base::ResetAndReturn(&callback_).Run(result);
 }
 
 }  // namespace net