Added Net logging to FileStream.

net/base/file_stream_posix.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.
 
 // For 64-bit file access (off_t = off64_t, lseek64, etc).
 #define _FILE_OFFSET_BITS 64
 
 #include "net/base/file_stream.h"
 
 #include <sys/types.h>
 #include <sys/stat.h>
 #include <fcntl.h>
 #include <unistd.h>
 #include <errno.h>
 
 #include "base/basictypes.h"
 #include "base/bind.h"
 #include "base/bind_helpers.h"
 #include "base/callback.h"
 #include "base/eintr_wrapper.h"
 #include "base/file_path.h"
 #include "base/logging.h"
 #include "base/message_loop.h"
 #include "base/metrics/histogram.h"
 #include "base/string_util.h"
 #include "base/threading/thread_restrictions.h"
 #include "base/threading/worker_pool.h"
 #include "base/synchronization/waitable_event.h"
 #include "net/base/file_stream_metrics.h"
+#include "net/base/file_stream_net_log_parameters.h"
 #include "net/base/net_errors.h"
 
 #if defined(OS_ANDROID)
 // Android's bionic libc only supports the LFS transitional API.
 #define off_t off64_t
 #define lseek lseek64
 #define stat stat64
 #define fstat fstat64
 #endif
 
 namespace net {
 
 // We cast back and forth, so make sure it's the size we're expecting.
 COMPILE_ASSERT(sizeof(int64) == sizeof(off_t), off_t_64_bit);
 
 // Make sure our Whence mappings match the system headers.
 COMPILE_ASSERT(FROM_BEGIN   == SEEK_SET &&
                FROM_CURRENT == SEEK_CUR &&
                FROM_END     == SEEK_END, whence_matches_system);
 
 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);
 }
 
 // ReadFile() is a simple wrapper around read() that handles EINTR signals and
 // calls MapSystemError() to map errno to net error codes.
-int ReadFile(base::PlatformFile file, char* buf, int buf_len, bool record_uma) {
+int ReadFile(base::PlatformFile file,
+             char* buf,
+             int buf_len,
+             bool record_uma,
+             const net::BoundNetLog& log) {
   base::ThreadRestrictions::AssertIOAllowed();
   // read(..., 0) returns 0 to indicate end-of-file.
 
   // Loop in the case of getting interrupted by a signal.
   ssize_t res = HANDLE_EINTR(read(file, buf, static_cast<size_t>(buf_len)));
   if (res == static_cast<ssize_t>(-1))
-    RecordAndMapError(errno, FILE_ERROR_SOURCE_READ, record_uma);
+    RecordAndMapError(errno, FILE_ERROR_SOURCE_READ, record_uma, log);
   return static_cast<int>(res);
 }
 
 void ReadFileTask(base::PlatformFile file,
                   char* buf,
                   int buf_len,
                   bool record_uma,
+                  const net::BoundNetLog& log,
                   const CompletionCallback& callback) {
-  callback.Run(ReadFile(file, buf, buf_len, record_uma));
+  callback.Run(ReadFile(file, buf, buf_len, record_uma, log));
 }
 
 // WriteFile() is a simple wrapper around write() that handles EINTR signals and
 // calls MapSystemError() to map errno to net error codes.  It tries to write to
 // completion.
-int WriteFile(base::PlatformFile file, const char* buf, int buf_len,
-              bool record_uma) {
+int WriteFile(base::PlatformFile file,
+              const char* buf,
+              int buf_len,
+              bool record_uma,
+              const net::BoundNetLog& log) {
   base::ThreadRestrictions::AssertIOAllowed();
   ssize_t res = HANDLE_EINTR(write(file, buf, buf_len));
   if (res == -1)
-    RecordAndMapError(errno, FILE_ERROR_SOURCE_WRITE, record_uma);
+    RecordAndMapError(errno, FILE_ERROR_SOURCE_WRITE, record_uma, log);
   return res;
 }
 
 void WriteFileTask(base::PlatformFile file,
                    const char* buf,
-                   int buf_len, bool record_uma,
+                   int buf_len,
+                   bool record_uma,
+                   const net::BoundNetLog& log,
                    const CompletionCallback& callback) {
-  callback.Run(WriteFile(file, buf, buf_len, record_uma));
+  callback.Run(WriteFile(file, buf, buf_len, record_uma, log));
 }
 
 // FlushFile() is a simple wrapper around fsync() that handles EINTR signals and
 // calls MapSystemError() to map errno to net error codes.  It tries to flush to
 // completion.
-int FlushFile(base::PlatformFile file, bool record_uma) {
+int FlushFile(base::PlatformFile file,
+              bool record_uma,
+              const net::BoundNetLog& log) {
   base::ThreadRestrictions::AssertIOAllowed();
   ssize_t res = HANDLE_EINTR(fsync(file));
   if (res == -1)
-    RecordAndMapError(errno, FILE_ERROR_SOURCE_FLUSH, record_uma);
+    RecordAndMapError(errno, FILE_ERROR_SOURCE_FLUSH, record_uma, log);
   return res;
 }
 
 }  // namespace
 
 // Cancelable wrapper around a Closure.
 class CancelableCallback {
  public:
   explicit CancelableCallback(const base::Closure& callback)
       : canceled_(false),
@@ skipping 16 matching lines @@
 // FileStream::AsyncContext ----------------------------------------------
 
 class FileStream::AsyncContext {
  public:
   AsyncContext();
   ~AsyncContext();
 
   // These methods post synchronous read() and write() calls to a WorkerThread.
   void InitiateAsyncRead(
       base::PlatformFile file, char* buf, int buf_len,
+      const net::BoundNetLog& log,
       const CompletionCallback& callback);
   void InitiateAsyncWrite(
       base::PlatformFile file, const char* buf, int buf_len,
+      const net::BoundNetLog& log,
       const CompletionCallback& callback);
 
   const CompletionCallback& callback() const { return callback_; }
 
   // Called by the WorkerPool thread executing the IO after the IO completes.
   // This method queues RunAsynchronousCallback() on the MessageLoop and signals
   // |background_io_completed_callback_|, in case the destructor is waiting.  In
   // that case, the destructor will call RunAsynchronousCallback() instead, and
   // cancel |message_loop_task_|.
   // |result| is the result of the Read/Write task.
@@ skipping 46 matching lines @@
     if (need_to_wait) {
       // We want to see if we block the message loop for too long.
       UMA_HISTOGRAM_TIMES("AsyncIO.FileStreamClose",
                           base::TimeTicks::Now() - start);
     }
   }
 }
 
 void FileStream::AsyncContext::InitiateAsyncRead(
     base::PlatformFile file, char* buf, int buf_len,
+    const net::BoundNetLog& log,
     const CompletionCallback& callback) {
   DCHECK(callback_.is_null());
   callback_ = callback;
 
   base::WorkerPool::PostTask(
       FROM_HERE,
-      base::Bind(&ReadFileTask, file, buf, buf_len,
+      base::Bind(&ReadFileTask,
+                 file,
+                 buf,
+                 buf_len,
                  record_uma_,
+                 log,
                  base::Bind(&AsyncContext::OnBackgroundIOCompleted,
                             base::Unretained(this))),
       true /* task_is_slow */);
 }
 
 void FileStream::AsyncContext::InitiateAsyncWrite(
     base::PlatformFile file, const char* buf, int buf_len,
+    const net::BoundNetLog& log,
     const CompletionCallback& callback) {
   DCHECK(callback_.is_null());
   callback_ = callback;
 
   base::WorkerPool::PostTask(
       FROM_HERE,
-      base::Bind(
-          &WriteFileTask,
-          file, buf, buf_len,
-          record_uma_,
-          base::Bind(&AsyncContext::OnBackgroundIOCompleted,
-                     base::Unretained(this))),
+      base::Bind(&WriteFileTask,
+                 file,
+                 buf,
+                 buf_len,
+                 record_uma_,
+                 log,
+                 base::Bind(&AsyncContext::OnBackgroundIOCompleted,
+                            base::Unretained(this))),
       true /* task_is_slow */);
 }
 
 void FileStream::AsyncContext::OnBackgroundIOCompleted(int result) {
   result_ = result;
   message_loop_task_ = new CancelableCallback(
       base::Bind(&AsyncContext::RunAsynchronousCallback,
                  base::Unretained(this)));
   message_loop_->PostTask(FROM_HERE,
                           base::Bind(&CancelableCallback::Run,
@@ skipping 27 matching lines @@
 // FileStream ------------------------------------------------------------
 
 FileStream::FileStream()
     : file_(base::kInvalidPlatformFileValue),
       open_flags_(0),
       auto_closed_(true),
       record_uma_(false) {
   DCHECK(!IsOpen());
 }
 
+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());
   }
 }
 
 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);
+
   // Abort any existing asynchronous operations.
   async_context_.reset();
 
   if (file_ != base::kInvalidPlatformFileValue) {
     if (close(file_) != 0) {
       NOTREACHED();
     }
     file_ = base::kInvalidPlatformFileValue;
+
+    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_ == base::kInvalidPlatformFileValue)
-    return RecordAndMapError(errno, FILE_ERROR_SOURCE_OPEN, record_uma_);
+  if (file_ == base::kInvalidPlatformFileValue) {
+    return RecordAndMapError(errno,
+                             FILE_ERROR_SOURCE_OPEN,
+                             record_uma_,
+                             bound_net_log_);
+  }
 
   if (open_flags_ & base::PLATFORM_FILE_ASYNC)
     async_context_.reset(new AsyncContext());
 
   return OK;
 }
 
 bool FileStream::IsOpen() const {
   return file_ != base::kInvalidPlatformFileValue;
 }
 
 int64 FileStream::Seek(Whence whence, int64 offset) {
   base::ThreadRestrictions::AssertIOAllowed();
 
   if (!IsOpen())
     return ERR_UNEXPECTED;
 
   // If we're in async, make sure we don't have a request in flight.
   DCHECK(!async_context_.get() || async_context_->callback().is_null());
 
   off_t res = lseek(file_, static_cast<off_t>(offset),
                     static_cast<int>(whence));
-  if (res == static_cast<off_t>(-1))
-    return RecordAndMapError(errno, FILE_ERROR_SOURCE_SEEK, record_uma_);
+  if (res == static_cast<off_t>(-1)) {
+    return RecordAndMapError(errno,
+                             FILE_ERROR_SOURCE_SEEK,
+                             record_uma_,
+                             bound_net_log_);
+  }
 
   return res;
 }
 
 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;
 
   struct stat info;
-  if (fstat(file_, &info) != 0)
-    return RecordAndMapError(errno, FILE_ERROR_SOURCE_GET_SIZE, record_uma_);
+  if (fstat(file_, &info) != 0) {
+    return RecordAndMapError(errno,
+                             FILE_ERROR_SOURCE_GET_SIZE,
+                             record_uma_,
+                             bound_net_log_);
+  }
 
   int64 size = static_cast<int64>(info.st_size);
   DCHECK_GT(size, cur_pos);
 
   return size - cur_pos;
 }
 
 int FileStream::Read(
     char* buf, int buf_len, const CompletionCallback& callback) {
   if (!IsOpen())
     return ERR_UNEXPECTED;
 
   // read(..., 0) will return 0, which indicates end-of-file.
   DCHECK_GT(buf_len, 0);
   DCHECK(open_flags_ & base::PLATFORM_FILE_READ);
 
   if (async_context_.get()) {
     DCHECK(open_flags_ & base::PLATFORM_FILE_ASYNC);
     // If we're in async, make sure we don't have a request in flight.
     DCHECK(async_context_->callback().is_null());
     if (record_uma_)
       async_context_->EnableErrorStatistics();
-    async_context_->InitiateAsyncRead(file_, buf, buf_len, callback);
+    async_context_->InitiateAsyncRead(file_, buf, buf_len, bound_net_log_,
+                                      callback);
     return ERR_IO_PENDING;
   } else {
-    return ReadFile(file_, buf, buf_len, record_uma_);
+    return ReadFile(file_, buf, buf_len, record_uma_, bound_net_log_);
   }
 }
 
 int FileStream::ReadUntilComplete(char *buf, int buf_len) {
   int to_read = buf_len;
   int bytes_total = 0;
 
   do {
     int bytes_read = Read(buf, to_read, CompletionCallback());
     if (bytes_read <= 0) {
@@ skipping 18 matching lines @@
 
   if (!IsOpen())
     return ERR_UNEXPECTED;
 
   if (async_context_.get()) {
     DCHECK(open_flags_ & base::PLATFORM_FILE_ASYNC);
     // If we're in async, make sure we don't have a request in flight.
     DCHECK(async_context_->callback().is_null());
     if (record_uma_)
       async_context_->EnableErrorStatistics();
-    async_context_->InitiateAsyncWrite(file_, buf, buf_len, callback);
+    async_context_->InitiateAsyncWrite(file_, buf, buf_len, bound_net_log_,
+                                       callback);
     return ERR_IO_PENDING;
   } else {
-    return WriteFile(file_, buf, buf_len, record_uma_);
+    return WriteFile(file_, buf, buf_len, 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.
   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.
   int result = ftruncate(file_, bytes);
   if (result == 0)
     return seek_position;
 
-  return RecordAndMapError(errno, FILE_ERROR_SOURCE_SET_EOF, record_uma_);
+  return RecordAndMapError(errno,
+                           FILE_ERROR_SOURCE_SET_EOF,
+                           record_uma_,
+                           bound_net_log_);
 }
 
 int FileStream::Flush() {
   if (!IsOpen())
     return ERR_UNEXPECTED;
 
-  return FlushFile(file_, record_uma_);
+  return FlushFile(file_, record_uma_, bound_net_log_);
 }
 
 void FileStream::EnableErrorStatistics() {
   record_uma_ = true;
 }
 
+void FileStream::SetBoundNetLogSource(const net::BoundNetLog& log) {
+  if (log.source().id == net::NetLog::Source::kInvalidId)

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

Is it worth logging some sort of unbound to no owner event here, if
log.source().id is not invalid?  Is this ever going to be called more than once
on the same stream?

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

I think it is OK not to be bound to an owner (as by passing in an invalid
BoundNetLog), and this will be obvious by the lack of a source dependency.

It is legal to call this more than once, because ownership can be transferred
from one source to another.  In this case you might see more than one source
dependency in the event log.

[mmenke, 2012/01/31 21:25:33]

Don't think that's a problem, was just wondering if we want to log anything if
we're being switched from a source with a BoundNetLog to one without one.

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

I don't think we currently have a use case for that.

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

Well, strictly speaking we don't have a use case for anything in this CL :-}. 
But understood that there's no currently anticipated use case for that.  Still,
if we don't DCHECK (and document in the header file that the case isn't allowed)
we're handling it in some fashion, and it behooves us to think about how we're
handling it rather than just letting the behavior be random.

If we imagine that at some point in the future that this happens, do you think
we should log something for this case, or not?  

[ahendrickson, 2012/01/31 23:14:33]

OK, I've changed it so that it behaves as before if  both sources are valid, but
if only one is then it gets an event indicating that something happened (but not
a source dependency).

Matt, could you take a look & let me know if it's acceptable?

+    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