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..0d61cc41fe35bfcb39a02670a14ee0c3c682a9ba 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(

[rvargas (doing something else), 2012/01/30 23:11:38]

nit: indent under the first argument

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

Done.

+          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) {
+  net_log_ = net::BoundNetLog::Make(log, net::NetLog::SOURCE_FILESTREAM);
+
+  net_log_.BeginEvent(net::NetLog::TYPE_FILE_STREAM_ALIVE, NULL);

[Randy Smith (Not in Mondays), 2012/01/30 23:29:13]

I'm a bit uncomfortable with the asymmetry between this constructor and the
other one with regard to this line; it's got a code smell.  All other operations
on net_log_ are done whichever constructor we use except for this one.  I feel
like we either want to comment the asymmetry or make it symmetrical
(incorporating my comment about the constructor interface would make it
symmetrical).

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

It is now symmetrical.

+}
+
 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();
+
+  net_log_.EndEvent(net::NetLog::TYPE_FILE_STREAM_ALIVE, NULL);
 }
 
 void FileStream::Close() {
+  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;
+
+    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) {
+  net_log_.BeginEvent(

[rvargas (doing something else), 2012/01/30 23:11:38]

Maybe move this to after IsOpen(). In fact, failure to open the file will end up
leaving an event hanging here...

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

Done.

[rvargas (doing something else), 2012/01/31 23:07:23]

This will still leave events with begin but no end whenever there is a failure
creating the file.

[ahendrickson, 2012/02/01 00:13:29]

There is now an EndEvent for OPEN if an error occurs opening the file.

+      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_,
+                             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_,
+                             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_,
+                             net_log_);
+  }
 
   int64 size = static_cast<int64>(info.st_size);
   DCHECK_GT(size, cur_pos);
@@ -383,10 +449,10 @@ 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, net_log_, callback);
     return ERR_IO_PENDING;
   } else {
-    return ReadFile(file_, buf, buf_len, record_uma_);
+    return ReadFile(file_, buf, buf_len, record_uma_, net_log_);
   }
 }
 
@@ -425,10 +491,10 @@ 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, net_log_, callback);
     return ERR_IO_PENDING;
   } else {
-    return WriteFile(file_, buf, buf_len, record_uma_);
+    return WriteFile(file_, buf, buf_len, record_uma_, net_log_);
   }
 }
 
@@ -438,7 +504,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 +517,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_,
+                           net_log_);
 }
 
 int FileStream::Flush() {
   if (!IsOpen())
     return ERR_UNEXPECTED;
 
-  return FlushFile(file_, record_uma_);
+  return FlushFile(file_, record_uma_, net_log_);
 }
 
 void FileStream::EnableErrorStatistics() {
   record_uma_ = true;
 }
 
+void FileStream::SetBoundNetLogSource(const net::BoundNetLog& log) {
+  if (log.source().id == net::NetLog::Source::kInvalidId)
+    return;
+
+  if (log.source().id == net_log_.source().id)
+    return;
+
+  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",
+                                         net_log_.source())));

[Randy Smith (Not in Mondays), 2012/01/30 23:29:13]

What does this end up looking like if net_log_ is invalid, but log is not?

[mmenke, 2012/01/30 23:43:47]

NetLogSourceParameter has logic to handle that case, though perhaps it should be
moved into Javascript, so it will work with more complicated event parameters.

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

But what does it look like in the output?  I want to make sure that we have
reasonably consistent understandable output for all input parameter variations.

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

We just don't display any dependencies.

+}
+
 }  // namespace net