Added Net logging to FileStream.

net/base/file_stream_win.cc

Index: net/base/file_stream_win.cc
diff --git a/net/base/file_stream_win.cc b/net/base/file_stream_win.cc
index 07d365f0597b1ef6178f7dd742a92263d8c46d66..ce3858c0277ef5ef690d0c6b8b1d5255ef607038 100644
--- a/net/base/file_stream_win.cc
+++ b/net/base/file_stream_win.cc
@@ -12,6 +12,7 @@
 #include "base/metrics/histogram.h"
 #include "base/threading/thread_restrictions.h"
 #include "net/base/file_stream_metrics.h"
+#include "net/base/file_stream_net_log_parameters.h"
 #include "net/base/net_errors.h"
 
 namespace net {
@@ -36,7 +37,16 @@ static void IncrementOffset(OVERLAPPED* overlapped, DWORD count) {
 
 namespace {
 
-int RecordAndMapError(int error, FileErrorSource source, bool record_uma) {
+int RecordAndMapError(int error,
+                      FileErrorSource source,
+                      bool record_uma,
+                      const net::BoundNetLog& log) {
+  log.AddEvent(net::NetLog::TYPE_FILE_STREAM_ERROR,
+      make_scoped_refptr(
+          new FileStreamErrorParameters(
+              GetFileErrorSourceName(source),
+              error)));
+
   RecordFileError(error, source, record_uma);
   return MapSystemError(error);
 }
@@ -49,7 +59,8 @@ class FileStream::AsyncContext : public MessageLoopForIO::IOHandler {
  public:
   AsyncContext(FileStream* owner)
       : owner_(owner), context_(), is_closing_(false),
-        record_uma_(false), error_source_(FILE_ERROR_SOURCE_COUNT) {
+        record_uma_(false),
+        error_source_(FILE_ERROR_SOURCE_COUNT) {
     context_.handler = this;
   }
   ~AsyncContext();
@@ -60,6 +71,7 @@ class FileStream::AsyncContext : public MessageLoopForIO::IOHandler {
   const CompletionCallback& callback() const { return callback_; }
 
   void set_error_source(FileErrorSource source) { error_source_ = source; }
+  void set_bound_net_log(const net::BoundNetLog& log) { bound_net_log_ = log; }

[mmenke, 2012/01/30 22:38:39]

nit:  Suggest you use bound_net_log everywhere, to be clearer and for
consistency.

[ahendrickson, 2012/01/31 20:12:41]

Done.

 
   void EnableErrorStatistics() {
     record_uma_ = true;
@@ -74,6 +86,7 @@ class FileStream::AsyncContext : public MessageLoopForIO::IOHandler {
   CompletionCallback callback_;
   bool is_closing_;
   bool record_uma_;
+  net::BoundNetLog bound_net_log_;
   FileErrorSource error_source_;
 };
 
@@ -109,8 +122,10 @@ void FileStream::AsyncContext::OnIOCompleted(
   }
 
   int result = static_cast<int>(bytes_read);
-  if (error && error != ERROR_HANDLE_EOF)
-    result = RecordAndMapError(error, error_source_, record_uma_);
+  if (error && error != ERROR_HANDLE_EOF) {
+    result = RecordAndMapError(error, error_source_, record_uma_,
+                               bound_net_log_);

[mmenke, 2012/01/31 18:28:43]

Any reason not to just get the bound net log from |owner_|?  Think getting rid
of all the set_bound_net_log calls would simplify things a little.

[Randy Smith (Not in Mondays), 2012/01/31 19:29:03]

Sorry, Matt, confused by this comment and I'd like to understand it.  The
semantics of the ownership changes for FileStream are one of the trickier parts
of this CL from my POV.  Where is owner_ declared?  If you're talking about the
argument to SetBoundNetLogSource() that could show up after the open (== first
event) occurs, and I thought we agreed that we wanted to have an all-or-none
semantics around logging from FileStream.

[ahendrickson, 2012/01/31 20:12:41]

Hmm, I suppose we could do that.  However, there are only 2 calls to
set_bound_net_log().

How strongly do you feel about this?

[ahendrickson, 2012/01/31 20:12:41]

Randy, he means that the AsyncContext class can use the FileStream's bound net
log, as it has a pointer to the FS that owns it.

[mmenke, 2012/01/31 21:20:31]

3 calls, actually.  I don't feel that strongly about it, I just think it adds
additional state information when none is needed.

Alternatively, you could just get rid of set_bound_net_log and make the
AsyncContext's constructor take it.  Come to think of it, is owner_ even used
anywhere?

[Randy Smith (Not in Mondays), 2012/01/31 22:22:41]

Ah, that makes sense.  As long as they only run on the same thread :-}.

[ahendrickson, 2012/01/31 22:29:47]

Hmm, I like the constructor approach.  In my original design, the bound_net_log_
could be created after construction, so I had set_bound_net_log().  Now it's
created at FileStream construction, so this will work.

Also, removed owner_, and made the AsyncContext constructor take a BoundNetLog
instead of a FileStream.

Done.

[ahendrickson, 2012/01/31 22:29:47]

I'm not at all sure they run on the same thread.

[Randy Smith (Not in Mondays), 2012/02/01 16:21:52]

Now that I look more closely, it looks like Async context gets its own copy of
the BoundNetLog, and that copy is done on the same thread as FileStream, so I
think we're ok (but if I'm wrong about those two beliefs, please raise a flag.)

[mmenke, 2012/02/01 16:25:52]

It's stored in a scoped_ptr owned by the stream, and Release() is never called,
so either it's safe to use from the AsyncContext, or we have a bug, or I'm
missing something.

+  }
 
   if (bytes_read)
     IncrementOffset(&context->overlapped, bytes_read);
@@ -123,12 +138,22 @@ void FileStream::AsyncContext::OnIOCompleted(
 // FileStream ------------------------------------------------------------
 
 FileStream::FileStream()
-    : file_(INVALID_HANDLE_VALUE),
+    : file_(base::kInvalidPlatformFileValue),
       open_flags_(0),
       auto_closed_(true),
       record_uma_(false) {
 }
 
+FileStream::FileStream(net::NetLog* log)
+    : file_(base::kInvalidPlatformFileValue),
+      open_flags_(0),
+      auto_closed_(true),
+      record_uma_(false) {
+  bound_net_log_ = net::BoundNetLog::Make(log, net::NetLog::SOURCE_FILESTREAM);
+
+  bound_net_log_.BeginEvent(net::NetLog::TYPE_FILE_STREAM_ALIVE, NULL);
+}
+
 FileStream::FileStream(base::PlatformFile file, int flags)
     : file_(file),
       open_flags_(flags),
@@ -146,9 +171,12 @@ FileStream::FileStream(base::PlatformFile file, int flags)
 FileStream::~FileStream() {
   if (auto_closed_)
     Close();
+
+  bound_net_log_.EndEvent(net::NetLog::TYPE_FILE_STREAM_ALIVE, NULL);
 }
 
 void FileStream::Close() {
+  bound_net_log_.AddEvent(net::NetLog::TYPE_FILE_STREAM_CLOSE, NULL);
   if (file_ != INVALID_HANDLE_VALUE)
     CancelIo(file_);
 
@@ -156,10 +184,18 @@ void FileStream::Close() {
   if (file_ != INVALID_HANDLE_VALUE) {
     CloseHandle(file_);
     file_ = INVALID_HANDLE_VALUE;
+
+    bound_net_log_.EndEvent(net::NetLog::TYPE_FILE_STREAM_OPEN, NULL);
   }
 }
 
 int FileStream::Open(const FilePath& path, int open_flags) {
+  bound_net_log_.BeginEvent(
+      net::NetLog::TYPE_FILE_STREAM_OPEN,
+      make_scoped_refptr(
+          new net::NetLogStringParameter("file_name",
+                                         path.AsUTF8Unsafe())));
+
   if (IsOpen()) {
     DLOG(FATAL) << "File is already open!";
     return ERR_UNEXPECTED;
@@ -170,7 +206,10 @@ int FileStream::Open(const FilePath& path, int open_flags) {
   if (file_ == INVALID_HANDLE_VALUE) {
     DWORD error = GetLastError();
     LOG(WARNING) << "Failed to open file: " << error;
-    return RecordAndMapError(error, FILE_ERROR_SOURCE_OPEN, record_uma_);
+    return RecordAndMapError(error,
+                             FILE_ERROR_SOURCE_OPEN,
+                             record_uma_,
+                             bound_net_log_);
   }
 
   if (open_flags_ & base::PLATFORM_FILE_ASYNC) {
@@ -200,10 +239,14 @@ int64 FileStream::Seek(Whence whence, int64 offset) {
   if (!SetFilePointerEx(file_, distance, &result, move_method)) {
     DWORD error = GetLastError();
     LOG(WARNING) << "SetFilePointerEx failed: " << error;
-    return RecordAndMapError(error, FILE_ERROR_SOURCE_SEEK, record_uma_);
+    return RecordAndMapError(error,
+                             FILE_ERROR_SOURCE_SEEK,
+                             record_uma_,
+                             bound_net_log_);
   }
   if (async_context_.get()) {
     async_context_->set_error_source(FILE_ERROR_SOURCE_SEEK);
+    async_context_->set_bound_net_log(bound_net_log_);
     SetOffset(async_context_->overlapped(), result);
   }
   return result.QuadPart;
@@ -223,7 +266,10 @@ int64 FileStream::Available() {
   if (!GetFileSizeEx(file_, &file_size)) {
     DWORD error = GetLastError();
     LOG(WARNING) << "GetFileSizeEx failed: " << error;
-    return RecordAndMapError(error, FILE_ERROR_SOURCE_GET_SIZE, record_uma_);
+    return RecordAndMapError(error,
+                             FILE_ERROR_SOURCE_GET_SIZE,
+                             record_uma_,
+                             bound_net_log_);
   }
 
   return file_size.QuadPart - cur_pos;
@@ -242,6 +288,7 @@ int FileStream::Read(
     DCHECK(async_context_->callback().is_null());
     overlapped = async_context_->overlapped();
     async_context_->set_error_source(FILE_ERROR_SOURCE_READ);
+    async_context_->set_bound_net_log(bound_net_log_);
   } else {
     DCHECK(callback.is_null());
     base::ThreadRestrictions::AssertIOAllowed();
@@ -259,7 +306,10 @@ int FileStream::Read(
       rv = 0;  // Report EOF by returning 0 bytes read.
     } else {
       LOG(WARNING) << "ReadFile failed: " << error;
-      rv = RecordAndMapError(error, FILE_ERROR_SOURCE_READ, record_uma_);
+      rv = RecordAndMapError(error,
+                             FILE_ERROR_SOURCE_READ,
+                             record_uma_,
+                             bound_net_log_);
     }
   } else if (overlapped) {
     async_context_->IOCompletionIsPending(callback);
@@ -304,6 +354,7 @@ int FileStream::Write(
     DCHECK(async_context_->callback().is_null());
     overlapped = async_context_->overlapped();
     async_context_->set_error_source(FILE_ERROR_SOURCE_WRITE);
+    async_context_->set_bound_net_log(bound_net_log_);
   } else {
     DCHECK(callback.is_null());
     base::ThreadRestrictions::AssertIOAllowed();
@@ -318,7 +369,10 @@ int FileStream::Write(
       rv = ERR_IO_PENDING;
     } else {
       LOG(WARNING) << "WriteFile failed: " << error;
-      rv = RecordAndMapError(error, FILE_ERROR_SOURCE_WRITE, record_uma_);
+      rv = RecordAndMapError(error,
+                             FILE_ERROR_SOURCE_WRITE,
+                             record_uma_,
+                             bound_net_log_);
     }
   } else if (overlapped) {
     async_context_->IOCompletionIsPending(callback);
@@ -342,7 +396,8 @@ int FileStream::Flush() {
 
   return RecordAndMapError(GetLastError(),
                            FILE_ERROR_SOURCE_FLUSH,
-                           record_uma_);
+                           record_uma_,
+                           bound_net_log_);
 }
 
 int64 FileStream::Truncate(int64 bytes) {
@@ -351,7 +406,7 @@ int64 FileStream::Truncate(int64 bytes) {
   if (!IsOpen())
     return ERR_UNEXPECTED;
 
-  // We better be open for reading.
+  // We'd better be open for reading.

[mmenke, 2012/01/31 18:28:43]

Sorry, wasn't clear with my original comment.  That should be "writing"

[ahendrickson, 2012/01/31 20:12:41]

Done.

   DCHECK(open_flags_ & base::PLATFORM_FILE_WRITE);
 
   // Seek to the position to truncate from.
@@ -364,7 +419,10 @@ int64 FileStream::Truncate(int64 bytes) {
   if (!result) {
     DWORD error = GetLastError();
     LOG(WARNING) << "SetEndOfFile failed: " << error;
-    return RecordAndMapError(error, FILE_ERROR_SOURCE_SET_EOF, record_uma_);
+    return RecordAndMapError(error,
+                             FILE_ERROR_SOURCE_SET_EOF,
+                             record_uma_,
+                             bound_net_log_);
   }
 
   // Success.
@@ -378,4 +436,24 @@ void FileStream::EnableErrorStatistics() {
     async_context_->EnableErrorStatistics();
 }
 
+void FileStream::SetBoundNetLogSource(const net::BoundNetLog& log) {
+  if (log.source().id == net::NetLog::Source::kInvalidId)
+    return;
+
+  if (log.source().id == bound_net_log_.source().id)
+    return;
+
+  bound_net_log_.AddEvent(
+      net::NetLog::TYPE_FILE_STREAM_BOUND_TO_OWNER,
+      make_scoped_refptr(
+          new net::NetLogSourceParameter("source_dependency",
+                                         log.source())));
+
+  log.AddEvent(
+      net::NetLog::TYPE_FILE_STREAM_SOURCE,
+      make_scoped_refptr(
+          new net::NetLogSourceParameter("source_dependency",
+                                         bound_net_log_.source())));
+}
+
 }  // namespace net