Added Net logging to FileStream.

net/base/file_stream_posix.cc

Index: net/base/file_stream_posix.cc
diff --git a/net/base/file_stream_posix.cc b/net/base/file_stream_posix.cc
index 50b1593202a762dcc69a0a1dca1aeee1f28b46e3..1c6a5909852259a80d059ea8984b1bddcaaefc8c 100644
--- a/net/base/file_stream_posix.cc
+++ b/net/base/file_stream_posix.cc
@@ -27,6 +27,7 @@
 #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)
@@ -49,21 +50,34 @@ COMPILE_ASSERT(FROM_BEGIN   == SEEK_SET &&
 
 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);
 }
 
@@ -71,37 +85,45 @@ 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;
 }
 
@@ -138,9 +160,11 @@ class FileStream::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_; }
@@ -207,14 +231,19 @@ FileStream::AsyncContext::~AsyncContext() {
 
 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 */);
@@ -222,18 +251,21 @@ void FileStream::AsyncContext::InitiateAsyncRead(
 
 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 */);
 }
 
@@ -281,6 +313,16 @@ FileStream::FileStream()
   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),
@@ -296,9 +338,13 @@ 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);
+
   // Abort any existing asynchronous operations.
   async_context_.reset();
 
@@ -307,10 +353,18 @@ void FileStream::Close() {
       NOTREACHED();
     }
     file_ = base::kInvalidPlatformFileValue;
+
+    bound_net_log_.EndEvent(net::NetLog::TYPE_FILE_STREAM_OPEN, NULL);
   }
 }
 
-int FileStream::Open(const FilePath& path, int open_flags) {
+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;
@@ -318,8 +372,12 @@ int FileStream::Open(const FilePath& path, int open_flags) {
 
   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());
@@ -342,8 +400,12 @@ int64 FileStream::Seek(Whence whence, int64 offset) {
 
   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;
 }
@@ -359,8 +421,12 @@ int64 FileStream::Available() {
     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);
@@ -383,10 +449,11 @@ int FileStream::Read(
     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_);
   }
 }
 
@@ -425,10 +492,11 @@ int FileStream::Write(
     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_);
   }
 }
 
@@ -438,7 +506,7 @@ int64 FileStream::Truncate(int64 bytes) {
   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.
@@ -451,18 +519,41 @@ int64 FileStream::Truncate(int64 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