Added Net logging to FileStream.

net/base/file_stream_win.cc

 // Copyright (c) 2011 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/file_stream.h"
 
 #include <windows.h>
 
 #include "base/file_path.h"
 #include "base/logging.h"
 #include "base/message_loop.h"
 #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 {
 
 // Ensure that we can just use our Whence values directly.
 COMPILE_ASSERT(FROM_BEGIN == FILE_BEGIN, bad_whence_begin);
 COMPILE_ASSERT(FROM_CURRENT == FILE_CURRENT, bad_whence_current);
 COMPILE_ASSERT(FROM_END == FILE_END, bad_whence_end);
 
 static void SetOffset(OVERLAPPED* overlapped, const LARGE_INTEGER& offset) {
   overlapped->Offset = offset.LowPart;
   overlapped->OffsetHigh = offset.HighPart;
 }
 
 static void IncrementOffset(OVERLAPPED* overlapped, DWORD count) {
   LARGE_INTEGER offset;
   offset.LowPart = overlapped->Offset;
   offset.HighPart = overlapped->OffsetHigh;
   offset.QuadPart += static_cast<LONGLONG>(count);
   SetOffset(overlapped, offset);
 }
 
 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);
 }
 
 }  // namespace
 
 // FileStream::AsyncContext ----------------------------------------------
 
 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();
 
   void IOCompletionIsPending(const CompletionCallback& callback);
 
   OVERLAPPED* overlapped() { return &context_.overlapped; }
   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;
   }
 
  private:
   virtual void OnIOCompleted(MessageLoopForIO::IOContext* context,
                              DWORD bytes_read, DWORD error);
 
   FileStream* owner_;
   MessageLoopForIO::IOContext context_;
   CompletionCallback callback_;
   bool is_closing_;
   bool record_uma_;
+  net::BoundNetLog bound_net_log_;
   FileErrorSource error_source_;
 };
 
 FileStream::AsyncContext::~AsyncContext() {
   is_closing_ = true;
   bool waited = false;
   base::TimeTicks start = base::TimeTicks::Now();
   while (!callback_.is_null()) {
     waited = true;
     MessageLoopForIO::current()->WaitForIOCompletion(INFINITE, this);
@@ skipping 15 matching lines @@
     MessageLoopForIO::IOContext* context, DWORD bytes_read, DWORD error) {
   DCHECK_EQ(&context_, context);
   DCHECK(!callback_.is_null());
 
   if (is_closing_) {
     callback_.Reset();
     return;
   }
 
   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);
 
   CompletionCallback temp;
   std::swap(temp, callback_);
   temp.Run(result);
 }
 
 // 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),
       auto_closed_(false),
       record_uma_(false) {
   // If the file handle is opened with base::PLATFORM_FILE_ASYNC, we need to
   // make sure we will perform asynchronous File IO to it.
   if (flags & base::PLATFORM_FILE_ASYNC) {
     async_context_.reset(new AsyncContext(this));
     MessageLoopForIO::current()->RegisterIOHandler(file_,
                                                    async_context_.get());
   }
 }
 
 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_);
 
   async_context_.reset();
   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;
   }
 
   open_flags_ = open_flags;
   file_ = base::CreatePlatformFile(path, open_flags_, NULL, NULL);
   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) {
     async_context_.reset(new AsyncContext(this));
     if (record_uma_)
       async_context_->EnableErrorStatistics();
     MessageLoopForIO::current()->RegisterIOHandler(file_,
                                                    async_context_.get());
   }
 
   return OK;
 }
 
 bool FileStream::IsOpen() const {
   return file_ != INVALID_HANDLE_VALUE;
 }
 
 int64 FileStream::Seek(Whence whence, int64 offset) {
   if (!IsOpen())
     return ERR_UNEXPECTED;
 
   DCHECK(!async_context_.get() || async_context_->callback().is_null());
 
   LARGE_INTEGER distance, result;
   distance.QuadPart = offset;
   DWORD move_method = static_cast<DWORD>(whence);
   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;
 }
 
 int64 FileStream::Available() {
   base::ThreadRestrictions::AssertIOAllowed();
 
   if (!IsOpen())
     return ERR_UNEXPECTED;
 
   int64 cur_pos = Seek(FROM_CURRENT, 0);
   if (cur_pos < 0)
     return cur_pos;
 
   LARGE_INTEGER file_size;
   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;
 }
 
 int FileStream::Read(
     char* buf, int buf_len, const CompletionCallback& callback) {
   if (!IsOpen())
     return ERR_UNEXPECTED;
 
   DCHECK(open_flags_ & base::PLATFORM_FILE_READ);
 
   OVERLAPPED* overlapped = NULL;
   if (async_context_.get()) {
     DCHECK(!callback.is_null());
     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();
   }
 
   int rv;
 
   DWORD bytes_read;
   if (!ReadFile(file_, buf, buf_len, &bytes_read, overlapped)) {
     DWORD error = GetLastError();
     if (async_context_.get() && error == ERROR_IO_PENDING) {
       async_context_->IOCompletionIsPending(callback);
       rv = ERR_IO_PENDING;
     } else if (error == ERROR_HANDLE_EOF) {
       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);
     rv = ERR_IO_PENDING;
   } else {
     rv = static_cast<int>(bytes_read);
   }
   return rv;
 }
 
@@ skipping 24 matching lines @@
     return ERR_UNEXPECTED;
 
   DCHECK(open_flags_ & base::PLATFORM_FILE_WRITE);
 
   OVERLAPPED* overlapped = NULL;
   if (async_context_.get()) {
     DCHECK(!callback.is_null());
     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();
   }
 
   int rv;
   DWORD bytes_written;
   if (!WriteFile(file_, buf, buf_len, &bytes_written, overlapped)) {
     DWORD error = GetLastError();
     if (async_context_.get() && error == ERROR_IO_PENDING) {
       async_context_->IOCompletionIsPending(callback);
       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);
     rv = ERR_IO_PENDING;
   } else {
     rv = static_cast<int>(bytes_written);
   }
   return rv;
 }
 
 int FileStream::Flush() {
   base::ThreadRestrictions::AssertIOAllowed();
 
   if (!IsOpen())
     return ERR_UNEXPECTED;
 
   DCHECK(open_flags_ & base::PLATFORM_FILE_WRITE);
   if (FlushFileBuffers(file_)) {
     return OK;
   }
 
   return RecordAndMapError(GetLastError(),
                            FILE_ERROR_SOURCE_FLUSH,
-                           record_uma_);
+                           record_uma_,
+                           bound_net_log_);
 }
 
 int64 FileStream::Truncate(int64 bytes) {
   base::ThreadRestrictions::AssertIOAllowed();
 
   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.
   int64 seek_position = Seek(FROM_BEGIN, bytes);
   if (seek_position != bytes)
     return ERR_UNEXPECTED;
 
   // And truncate the file.
   BOOL result = SetEndOfFile(file_);
   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.
   return seek_position;
 }
 
 void FileStream::EnableErrorStatistics() {
   record_uma_ = true;
 
   if (async_context_.get())
     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