SPDY - Better SPDY error logging in NetLog.

Moved all logging messages into net_log_.AddEvents.

BUG=112657
R=willchan
TEST=network unit tests.

Review URL: http://codereview.chromium.org/9424041

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@123317 0039d316-1c4b-4281-b951-d872f2087c98

12 files changed, 397 insertions, 85 deletions

diff --git a/net/base/net_log_event_type_list.h b/net/base/net_log_event_type_list.h
index b6b02d3..ceb4a72 100644
--- a/net/base/net_log_event_type_list.h
+++ b/net/base/net_log_event_type_list.h
@@ -1056,7 +1056,8 @@ EVENT_TYPE(SPDY_SESSION_STALLED_ON_SEND_WINDOW)
 
 // Session is closing
 //   {
-//     "status": <The error status of the closure>,
+//     "status"     : <The error status of the closure>,
+//     "description": <The textual description for the closure>,
 //   }
 EVENT_TYPE(SPDY_SESSION_CLOSE)
 
@@ -1125,6 +1126,14 @@ EVENT_TYPE(SPDY_STREAM_UPDATE_SEND_WINDOW)
 //   }
 EVENT_TYPE(SPDY_STREAM_UPDATE_RECV_WINDOW)
 
+// This event indicates a stream error
+//   {
+//     "id":          <The stream id>,
+//     "status":      <The error status>,
+//     "description": <The textual description for the error>,
+//   }
+EVENT_TYPE(SPDY_STREAM_ERROR)
+
 // ------------------------------------------------------------------------
 // HttpStreamParser
 // ------------------------------------------------------------------------
diff --git a/net/spdy/buffered_spdy_framer.cc b/net/spdy/buffered_spdy_framer.cc
index ff5b361..a1d12da 100644
--- a/net/spdy/buffered_spdy_framer.cc
+++ b/net/spdy/buffered_spdy_framer.cc
@@ -26,8 +26,9 @@ void BufferedSpdyFramer::set_visitor(
   spdy_framer_.set_visitor(this);
 }
 
-void BufferedSpdyFramer::OnError(spdy::SpdyFramer* /*framer*/) {
-  visitor_->OnError();
+void BufferedSpdyFramer::OnError(spdy::SpdyFramer* spdy_framer) {
+  DCHECK(spdy_framer);
+  visitor_->OnError(spdy_framer->error_code());
 }
 
 void BufferedSpdyFramer::OnControl(const SpdyControlFrame* frame) {
@@ -82,8 +83,8 @@ bool BufferedSpdyFramer::OnControlFrameHeaderData(SpdyStreamId stream_id,
     bool parsed_headers = SpdyFramer::ParseHeaderBlockInBuffer(
         header_buffer_, header_buffer_used_, headers.get());
     if (!parsed_headers) {
-      LOG(WARNING) << "Could not parse Spdy Control Frame Header.";
-      visitor_->OnStreamError(stream_id);
+      visitor_->OnStreamError(
+          stream_id, "Could not parse Spdy Control Frame Header.");
       return false;
     }
     SpdyControlFrame* control_frame =
@@ -114,7 +115,8 @@ bool BufferedSpdyFramer::OnControlFrameHeaderData(SpdyStreamId stream_id,
   const size_t available = kHeaderBufferSize - header_buffer_used_;
   if (len > available) {
     header_buffer_valid_ = false;
-    visitor_->OnStreamError(stream_id);
+    visitor_->OnStreamError(
+        stream_id, "Received more data than the allocated size.");
     return false;
   }
   memcpy(header_buffer_ + header_buffer_used_, header_data, len);
diff --git a/net/spdy/buffered_spdy_framer.h b/net/spdy/buffered_spdy_framer.h
index b4f819d..ae6b9ba 100644
--- a/net/spdy/buffered_spdy_framer.h
+++ b/net/spdy/buffered_spdy_framer.h
@@ -6,6 +6,8 @@
 #define NET_SPDY_BUFFERED_SPDY_FRAMER_H_
 #pragma once
 
+#include <string>
+
 #include "base/basictypes.h"
 #include "base/gtest_prod_util.h"
 #include "base/memory/linked_ptr.h"
@@ -22,10 +24,11 @@ class NET_EXPORT_PRIVATE BufferedSpdyFramerVisitorInterface {
   virtual ~BufferedSpdyFramerVisitorInterface() {}
 
   // Called if an error is detected in the SpdyFrame protocol.
-  virtual void OnError() = 0;
+  virtual void OnError(int error_code) = 0;
 
   // Called if an error is detected in a SPDY stream.
-  virtual void OnStreamError(spdy::SpdyStreamId stream_id) = 0;
+  virtual void OnStreamError(spdy::SpdyStreamId stream_id,
+                             const std::string& description) = 0;
 
   // Called after all the header data for SYN_STREAM control frame is received.
   virtual void OnSynStream(const SpdySynStreamControlFrame& frame,
@@ -81,7 +84,7 @@ class NET_EXPORT_PRIVATE BufferedSpdyFramer
   void set_visitor(BufferedSpdyFramerVisitorInterface* visitor);
 
   // SpdyFramerVisitorInterface
-  virtual void OnError(SpdyFramer* /*framer*/) OVERRIDE;
+  virtual void OnError(spdy::SpdyFramer* spdy_framer) OVERRIDE;
   virtual void OnControl(const SpdyControlFrame* frame) OVERRIDE;
   virtual bool OnCredentialFrameData(const char* frame_data,
                                      size_t len) OVERRIDE;
diff --git a/net/spdy/buffered_spdy_framer_unittest.cc b/net/spdy/buffered_spdy_framer_unittest.cc
index 16b3d0b..3c2921e 100644
--- a/net/spdy/buffered_spdy_framer_unittest.cc
+++ b/net/spdy/buffered_spdy_framer_unittest.cc
@@ -21,13 +21,15 @@ class TestBufferedSpdyVisitor : public BufferedSpdyFramerVisitorInterface {
       header_stream_id_(-1) {
   }
 
-  void OnError() {
-    LOG(INFO) << "SpdyFramer Error";
+  void OnError(int error_code) {
+    LOG(INFO) << "SpdyFramer Error: " << error_code;
     error_count_++;
   }
 
-  void OnStreamError(spdy::SpdyStreamId stream_id) {
-    LOG(INFO) << "SpdyFramer Error on stream: " << stream_id;
+  void OnStreamError(spdy::SpdyStreamId stream_id,
+                     const std::string& description) {
+    LOG(INFO) << "SpdyFramer Error on stream: " << stream_id  << " "
+              << description;
     error_count_++;
   }
 
diff --git a/net/spdy/spdy_session.cc b/net/spdy/spdy_session.cc
index bd4381d..a1a806d 100644
--- a/net/spdy/spdy_session.cc
+++ b/net/spdy/spdy_session.cc
@@ -83,6 +83,22 @@ Value* NetLogSpdyCredentialParameter::ToValue() const {
   return dict;
 }
 
+NetLogSpdySessionCloseParameter::NetLogSpdySessionCloseParameter(
+    int status,
+    const std::string& description)
+    : status_(status),
+      description_(description) {}
+
+NetLogSpdySessionCloseParameter::~NetLogSpdySessionCloseParameter() {
+}
+
+Value* NetLogSpdySessionCloseParameter::ToValue() const {
+  DictionaryValue* dict = new DictionaryValue();
+  dict->SetInteger("status", status_);
+  dict->SetString("description", description_);
+  return dict;
+}
+
 namespace {
 
 const int kReadBufferSize = 8 * 1024;
@@ -341,7 +357,7 @@ SpdySession::~SpdySession() {
   }
 
   if (connection_->is_initialized()) {
-    // With Spdy we can't recycle sockets.
+    // With SPDY we can't recycle sockets.
     connection_->socket()->Disconnect();
   }
 
@@ -424,9 +440,11 @@ int SpdySession::GetPushStream(
   // encrypted SSL socket.
   if (is_secure_ && certificate_error_code_ != OK &&
       (url.SchemeIs("https") || url.SchemeIs("wss"))) {
-    LOG(ERROR) << "Tried to get pushed spdy stream for secure content over an "
-               << "unauthenticated session.";
-    CloseSessionOnError(static_cast<net::Error>(certificate_error_code_), true);
+    CloseSessionOnError(
+        static_cast<net::Error>(certificate_error_code_),
+        true,
+        "Tried to get SPDY stream for secure content over an unauthenticated "
+        "session.");
     return ERR_SPDY_PROTOCOL_ERROR;
   }
 
@@ -521,9 +539,11 @@ int SpdySession::CreateStreamImpl(
   // encrypted SSL socket.
   if (is_secure_ && certificate_error_code_ != OK &&
       (url.SchemeIs("https") || url.SchemeIs("wss"))) {
-    LOG(ERROR) << "Tried to create spdy stream for secure content over an "
-               << "unauthenticated session.";
-    CloseSessionOnError(static_cast<net::Error>(certificate_error_code_), true);
+    CloseSessionOnError(
+        static_cast<net::Error>(certificate_error_code_),
+        true,
+        "Tried to create SPDY stream for secure content over an "
+        "unauthenticated session.");
     return ERR_SPDY_PROTOCOL_ERROR;
   }
 
@@ -803,7 +823,7 @@ void SpdySession::OnReadComplete(int bytes_read) {
     net::Error error = static_cast<net::Error>(bytes_read);
     if (bytes_read == 0)
       error = ERR_CONNECTION_CLOSED;
-    CloseSessionOnError(error, true);
+    CloseSessionOnError(error, true, "bytes_read is <= 0.");
     return;
   }
 
@@ -879,7 +899,8 @@ void SpdySession::OnWriteComplete(int result) {
     in_flight_write_.release();
 
     // The stream is now errored.  Close it down.
-    CloseSessionOnError(static_cast<net::Error>(result), true);
+    CloseSessionOnError(
+        static_cast<net::Error>(result), true, "The stream has errored.");
   }
 }
 
@@ -901,7 +922,7 @@ net::Error SpdySession::ReadSocket() {
   switch (bytes_read) {
     case 0:
       // Socket is closed!
-      CloseSessionOnError(ERR_CONNECTION_CLOSED, true);
+      CloseSessionOnError(ERR_CONNECTION_CLOSED, true, "bytes_read is 0.");
       return ERR_CONNECTION_CLOSED;
     case net::ERR_IO_PENDING:
       // Waiting for data.  Nothing to do now.
@@ -964,8 +985,8 @@ void SpdySession::WriteSocket() {
         scoped_ptr<spdy::SpdyFrame> compressed_frame(
             buffered_spdy_framer_.CompressFrame(uncompressed_frame));
         if (!compressed_frame.get()) {
-          LOG(ERROR) << "SPDY Compression failure";
-          CloseSessionOnError(net::ERR_SPDY_PROTOCOL_ERROR, true);
+          CloseSessionOnError(
+              net::ERR_SPDY_PROTOCOL_ERROR, true, "SPDY Compression failure.");
           return;
         }
 
@@ -1030,8 +1051,9 @@ void SpdySession::CloseAllStreams(net::Error status) {
     ActiveStreamMap::iterator it = active_streams_.begin();
     const scoped_refptr<SpdyStream>& stream = it->second;
     DCHECK(stream);
-    VLOG(1) << "ABANDONED (stream_id=" << stream->stream_id()
-            << "): " << stream->path();
+    std::string description = base::StringPrintf(
+        "ABANDONED (stream_id=%d): ", stream->stream_id()) + stream->path();
+    stream->LogStreamError(status, description);
     DeleteStream(stream->stream_id(), status);
   }
 
@@ -1059,7 +1081,9 @@ void SpdySession::QueueFrame(spdy::SpdyFrame* frame,
   WriteSocketLater();
 }
 
-void SpdySession::CloseSessionOnError(net::Error err, bool remove_from_pool) {
+void SpdySession::CloseSessionOnError(net::Error err,
+                                      bool remove_from_pool,
+                                      const std::string& description) {
   // Closing all streams can have a side-effect of dropping the last reference
   // to |this|.  Hold a reference through this function.
   scoped_refptr<SpdySession> self(this);
@@ -1067,7 +1091,8 @@ void SpdySession::CloseSessionOnError(net::Error err, bool remove_from_pool) {
   DCHECK_LT(err, OK);
   net_log_.AddEvent(
       NetLog::TYPE_SPDY_SESSION_CLOSE,
-      make_scoped_refptr(new NetLogIntegerParameter("status", err)));
+      make_scoped_refptr(
+          new NetLogSpdySessionCloseParameter(err, description)));
 
   // Don't close twice.  This can occur because we can have both
   // a read and a write outstanding, and each can complete with
@@ -1229,13 +1254,16 @@ SSLClientCertType SpdySession::GetOriginBoundCertType() const {
   return ssl_socket->origin_bound_cert_type();
 }
 
-void SpdySession::OnError() {
-  CloseSessionOnError(net::ERR_SPDY_PROTOCOL_ERROR, true);
+void SpdySession::OnError(int error_code) {
+  std::string description = base::StringPrintf(
+      "SPDY_ERROR error_code: %d.", error_code);
+  CloseSessionOnError(net::ERR_SPDY_PROTOCOL_ERROR, true, description);
 }
 
-void SpdySession::OnStreamError(spdy::SpdyStreamId stream_id) {
+void SpdySession::OnStreamError(spdy::SpdyStreamId stream_id,
+                                const std::string& description) {
   if (IsStreamActive(stream_id))
-    ResetStream(stream_id, spdy::PROTOCOL_ERROR, "");
+    ResetStream(stream_id, spdy::PROTOCOL_ERROR, description);
 }
 
 void SpdySession::OnStreamFrameData(spdy::SpdyStreamId stream_id,
@@ -1297,13 +1325,10 @@ void SpdySession::OnSynStream(
   }
 
   if (associated_stream_id == 0) {
-    LOG(WARNING) << "Received invalid OnSyn associated stream id "
-                 << associated_stream_id
-                 << " for stream " << stream_id;
-    std::string desc = base::StringPrintf(
+    std::string description = base::StringPrintf(
         "Received invalid OnSyn associated stream id %d for stream %d",
         associated_stream_id, stream_id);
-    ResetStream(stream_id, spdy::INVALID_STREAM, desc);
+    ResetStream(stream_id, spdy::INVALID_STREAM, description);
     return;
   }
 
@@ -1317,7 +1342,6 @@ void SpdySession::OnSynStream(
   if (url.empty()) {
     ResetStream(stream_id, spdy::PROTOCOL_ERROR,
                 "Pushed stream did not contain a url.");
-    LOG(WARNING) << "Pushed stream did not contain a url.";
     return;
   }
 
@@ -1325,14 +1349,11 @@ void SpdySession::OnSynStream(
   if (!gurl.is_valid()) {
     ResetStream(stream_id, spdy::PROTOCOL_ERROR,
                 "Pushed stream url was invalid: " + url);
-    LOG(WARNING) << "Pushed stream url was invalid: " << url;
     return;
   }
 
   // Verify we have a valid stream association.
   if (!IsStreamActive(associated_stream_id)) {
-    LOG(WARNING) << "Received OnSyn with inactive associated stream "
-               << associated_stream_id;
     ResetStream(stream_id, spdy::INVALID_ASSOCIATED_STREAM,
                 base::StringPrintf(
                     "Received OnSyn with inactive associated stream %d",
@@ -1344,8 +1365,6 @@ void SpdySession::OnSynStream(
       active_streams_[associated_stream_id];
   GURL associated_url(associated_stream->GetUrl());
   if (associated_url.GetOrigin() != gurl.GetOrigin()) {
-    LOG(WARNING) << "Rejected Cross Origin Push Stream "
-                 << associated_stream_id;
     ResetStream(stream_id, spdy::REFUSED_STREAM,
                 base::StringPrintf(
                     "Rejected Cross Origin Push Stream %d",
@@ -1356,7 +1375,6 @@ void SpdySession::OnSynStream(
   // There should not be an existing pushed stream with the same path.
   PushedStreamMap::iterator it = unclaimed_pushed_streams_.find(url);
   if (it != unclaimed_pushed_streams_.end()) {
-    LOG(WARNING) << "Received duplicate pushed stream with url: " << url;
     ResetStream(stream_id, spdy::PROTOCOL_ERROR,
                 "Received duplicate pushed stream with url: " + url);
     return;
@@ -1386,6 +1404,14 @@ void SpdySession::OnSynReply(const spdy::SpdySynReplyControlFrame& frame,
                              const linked_ptr<spdy::SpdyHeaderBlock>& headers) {
   spdy::SpdyStreamId stream_id = frame.stream_id();
 
+  if (net_log().IsLoggingAllEvents()) {
+    net_log().AddEvent(
+        NetLog::TYPE_SPDY_SESSION_SYN_REPLY,
+        make_scoped_refptr(new NetLogSpdySynParameter(
+            headers, static_cast<spdy::SpdyControlFlags>(frame.flags()),
+            stream_id, 0)));
+  }
+
   bool valid_stream = IsStreamActive(stream_id);
   if (!valid_stream) {
     // NOTE:  it may just be that the stream was cancelled.
@@ -1398,20 +1424,13 @@ void SpdySession::OnSynReply(const spdy::SpdySynReplyControlFrame& frame,
   CHECK(!stream->cancelled());
 
   if (stream->response_received()) {
-    LOG(WARNING) << "Received duplicate SYN_REPLY for stream " << stream_id;
+    stream->LogStreamError(ERR_SYN_REPLY_NOT_RECEIVED,
+                           "Received duplicate SYN_REPLY for stream.");
     CloseStream(stream->stream_id(), ERR_SPDY_PROTOCOL_ERROR);
     return;
   }
   stream->set_response_received();
 
-  if (net_log().IsLoggingAllEvents()) {
-    net_log().AddEvent(
-        NetLog::TYPE_SPDY_SESSION_SYN_REPLY,
-        make_scoped_refptr(new NetLogSpdySynParameter(
-            headers, static_cast<spdy::SpdyControlFlags>(frame.flags()),
-            stream_id, 0)));
-  }
-
   Respond(*headers, stream);
 }
 
@@ -1419,6 +1438,14 @@ void SpdySession::OnHeaders(const spdy::SpdyHeadersControlFrame& frame,
                             const linked_ptr<spdy::SpdyHeaderBlock>& headers) {
   spdy::SpdyStreamId stream_id = frame.stream_id();
 
+  if (net_log().IsLoggingAllEvents()) {
+    net_log().AddEvent(
+        NetLog::TYPE_SPDY_SESSION_HEADERS,
+        make_scoped_refptr(new NetLogSpdySynParameter(
+            headers, static_cast<spdy::SpdyControlFlags>(frame.flags()),
+            stream_id, 0)));
+  }
+
   bool valid_stream = IsStreamActive(stream_id);
   if (!valid_stream) {
     // NOTE:  it may just be that the stream was cancelled.
@@ -1430,14 +1457,6 @@ void SpdySession::OnHeaders(const spdy::SpdyHeadersControlFrame& frame,
   CHECK_EQ(stream->stream_id(), stream_id);
   CHECK(!stream->cancelled());
 
-  if (net_log().IsLoggingAllEvents()) {
-    net_log().AddEvent(
-        NetLog::TYPE_SPDY_SESSION_HEADERS,
-        make_scoped_refptr(new NetLogSpdySynParameter(
-            headers, static_cast<spdy::SpdyControlFlags>(frame.flags()),
-            stream_id, 0)));
-  }
-
   int rv = stream->OnHeaders(*headers);
   if (rv < 0) {
     DCHECK_NE(rv, ERR_IO_PENDING);
@@ -1469,7 +1488,9 @@ void SpdySession::OnRstStream(const spdy::SpdyRstStreamControlFrame& frame) {
   } else if (frame.status() == spdy::REFUSED_STREAM) {
     DeleteStream(stream_id, ERR_SPDY_SERVER_REFUSED_STREAM);
   } else {
-    LOG(ERROR) << "Spdy stream closed: " << frame.status();
+    stream->LogStreamError(ERR_SPDY_PROTOCOL_ERROR,
+                           base::StringPrintf("SPDY stream closed: %d",
+                                              frame.status()));
     // TODO(mbelshe): Map from Spdy-protocol errors to something sensical.
     //                For now, it doesn't matter much - it is a protocol error.
     DeleteStream(stream_id, ERR_SPDY_PROTOCOL_ERROR);
@@ -1508,7 +1529,8 @@ void SpdySession::OnPing(const spdy::SpdyPingControlFrame& frame) {
 
   --pings_in_flight_;
   if (pings_in_flight_ < 0) {
-    CloseSessionOnError(net::ERR_SPDY_PROTOCOL_ERROR, true);
+    CloseSessionOnError(
+        net::ERR_SPDY_PROTOCOL_ERROR, true, "pings_in_flight_ is < 0.");
     return;
   }
 
@@ -1554,8 +1576,6 @@ void SpdySession::OnWindowUpdate(
   }
 
   if (delta_window_size < 1) {
-    LOG(WARNING) << "Received WINDOW_UPDATE with an invalid delta_window_size "
-                 << delta_window_size;
     ResetStream(stream_id, spdy::FLOW_CONTROL_ERROR,
                 base::StringPrintf(
                     "Received WINDOW_UPDATE with an invalid "
@@ -1769,7 +1789,7 @@ void SpdySession::CheckPingStatus(base::TimeTicks last_check_time) {
       (now - received_data_time_);
 
   if (delay.InMilliseconds() < 0 || received_data_time_ < last_check_time) {
-    CloseSessionOnError(net::ERR_SPDY_PING_FAILED, true);
+    CloseSessionOnError(net::ERR_SPDY_PING_FAILED, true, "Failed ping.");
     // Track all failed PING messages in a separate bucket.
     const base::TimeDelta kFailedPing =
         base::TimeDelta::FromInternalValue(INT_MAX);
diff --git a/net/spdy/spdy_session.h b/net/spdy/spdy_session.h
index 92af8b6..1e49559 100644
--- a/net/spdy/spdy_session.h
+++ b/net/spdy/spdy_session.h
@@ -222,7 +222,10 @@ class NET_EXPORT SpdySession : public base::RefCounted<SpdySession>,
   // error.
   // |remove_from_pool| indicates whether to also remove the session from the
   // session pool.
-  void CloseSessionOnError(net::Error err, bool remove_from_pool);
+  // |description| indicates the reason for the error.
+  void CloseSessionOnError(net::Error err,
+                           bool remove_from_pool,
+                           const std::string& description);
 
   // Retrieves information on the current state of the SPDY session as a
   // Value.  Caller takes possession of the returned value.
@@ -419,8 +422,9 @@ class NET_EXPORT SpdySession : public base::RefCounted<SpdySession>,
   void InvokeUserStreamCreationCallback(scoped_refptr<SpdyStream>* stream);
 
   // BufferedSpdyFramerVisitorInterface:
-  virtual void OnError() OVERRIDE;
-  virtual void OnStreamError(spdy::SpdyStreamId stream_id) OVERRIDE;
+  virtual void OnError(int error_code) OVERRIDE;
+  virtual void OnStreamError(spdy::SpdyStreamId stream_id,
+                             const std::string& description) OVERRIDE;
   virtual void OnRstStream(
       const spdy::SpdyRstStreamControlFrame& frame) OVERRIDE;
   virtual void OnGoAway(const spdy::SpdyGoAwayControlFrame& frame) OVERRIDE;
@@ -681,6 +685,23 @@ class NetLogSpdyCredentialParameter : public NetLog::EventParameters {
   DISALLOW_COPY_AND_ASSIGN(NetLogSpdyCredentialParameter);
 };
 
+class NetLogSpdySessionCloseParameter : public NetLog::EventParameters {
+ public:
+  NetLogSpdySessionCloseParameter(int status,
+                                  const std::string& description);
+
+  int status() const { return status_; }
+  virtual Value* ToValue() const  OVERRIDE;
+
+ private:
+  virtual ~NetLogSpdySessionCloseParameter();
+
+  const int status_;
+  const std::string description_;
+
+  DISALLOW_COPY_AND_ASSIGN(NetLogSpdySessionCloseParameter);
+};
+
 }  // namespace net
 
 #endif  // NET_SPDY_SPDY_SESSION_H_
diff --git a/net/spdy/spdy_session_pool.cc b/net/spdy/spdy_session_pool.cc
index ed490e4..215bf29 100644
--- a/net/spdy/spdy_session_pool.cc
+++ b/net/spdy/spdy_session_pool.cc
@@ -1,4 +1,4 @@
-// Copyright (c) 2011 The Chromium Authors. All rights reserved.
+// Copyright (c) 2012 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.
 
@@ -385,7 +385,8 @@ void SpdySessionPool::CloseAllSessions() {
     CHECK(session);
     // This call takes care of removing the session from the pool, as well as
     // removing the session list if the list is empty.
-    session->CloseSessionOnError(net::ERR_ABORTED, true);
+    session->CloseSessionOnError(
+        net::ERR_ABORTED, true, "Closing all sessions.");
   }
 }
 
@@ -406,7 +407,8 @@ void SpdySessionPool::CloseCurrentSessions() {
     CHECK(list);
     const scoped_refptr<SpdySession>& session = list->front();
     CHECK(session);
-    session->CloseSessionOnError(net::ERR_ABORTED, false);
+    session->CloseSessionOnError(
+        net::ERR_ABORTED, false, "Closing current sessions.");
     list->pop_front();
     if (list->empty()) {
       delete list;
@@ -429,8 +431,10 @@ void SpdySessionPool::CloseIdleSessions() {
     SpdySessionList::iterator session_it = list->begin();
     const scoped_refptr<SpdySession>& session = *session_it;
     CHECK(session);
-    if (!session->is_active())
-      session->CloseSessionOnError(net::ERR_ABORTED, true);
+    if (!session->is_active()) {
+      session->CloseSessionOnError(
+          net::ERR_ABORTED, true, "Closing idle sessions.");
+    }
   }
 }
 
diff --git a/net/spdy/spdy_session_unittest.cc b/net/spdy/spdy_session_unittest.cc
index d8e6dd5..fe3becd 100644
--- a/net/spdy/spdy_session_unittest.cc
+++ b/net/spdy/spdy_session_unittest.cc
@@ -5,6 +5,7 @@
 #include "net/spdy/spdy_session.h"
 
 #include "net/base/ip_endpoint.h"
+#include "net/base/net_log_unittest.h"
 #include "net/spdy/spdy_io_buffer.h"
 #include "net/spdy/spdy_session_pool.h"
 #include "net/spdy/spdy_stream.h"
@@ -367,7 +368,7 @@ class StreamReleaserCallback : public TestCompletionCallbackBase {
 
  private:
   void OnComplete(int result) {
-    session_->CloseSessionOnError(ERR_FAILED, false);
+    session_->CloseSessionOnError(ERR_FAILED, false, "On complete.");
     session_ = NULL;
     first_stream_->Cancel();
     first_stream_ = NULL;
@@ -1050,4 +1051,73 @@ TEST_F(SpdySessionTest, SendCredentials) {
   EXPECT_FALSE(spdy_session_pool->HasSession(pair));
 }
 
+TEST_F(SpdySessionTest, CloseSessionOnError) {
+  SpdySessionDependencies session_deps;
+  session_deps.host_resolver->set_synchronous_mode(true);
+
+  MockConnect connect_data(SYNCHRONOUS, OK);
+  scoped_ptr<spdy::SpdyFrame> goaway(ConstructSpdyGoAway());
+  MockRead reads[] = {
+    CreateMockRead(*goaway),
+    MockRead(SYNCHRONOUS, 0, 0)  // EOF
+  };
+
+  net::CapturingBoundNetLog log(net::CapturingNetLog::kUnbounded);
+
+  StaticSocketDataProvider data(reads, arraysize(reads), NULL, 0);
+  data.set_connect_data(connect_data);
+  session_deps.socket_factory->AddSocketDataProvider(&data);
+
+  SSLSocketDataProvider ssl(SYNCHRONOUS, OK);
+  session_deps.socket_factory->AddSSLSocketDataProvider(&ssl);
+
+  scoped_refptr<HttpNetworkSession> http_session(
+      SpdySessionDependencies::SpdyCreateSession(&session_deps));
+
+  const std::string kTestHost("www.foo.com");
+  const int kTestPort = 80;
+  HostPortPair test_host_port_pair(kTestHost, kTestPort);
+  HostPortProxyPair pair(test_host_port_pair, ProxyServer::Direct());
+
+  SpdySessionPool* spdy_session_pool(http_session->spdy_session_pool());
+  EXPECT_FALSE(spdy_session_pool->HasSession(pair));
+  scoped_refptr<SpdySession> session =
+      spdy_session_pool->Get(pair, log.bound());
+  EXPECT_TRUE(spdy_session_pool->HasSession(pair));
+
+  scoped_refptr<TransportSocketParams> transport_params(
+      new TransportSocketParams(test_host_port_pair,
+                                MEDIUM,
+                                false,
+                                false));
+  scoped_ptr<ClientSocketHandle> connection(new ClientSocketHandle);
+  EXPECT_EQ(OK, connection->Init(test_host_port_pair.ToString(),
+                                 transport_params, MEDIUM, CompletionCallback(),
+                                 http_session->GetTransportSocketPool(),
+                                 log.bound()));
+  EXPECT_EQ(OK, session->InitializeWithSocket(connection.release(), false, OK));
+
+  // Flush the SpdySession::OnReadComplete() task.
+  MessageLoop::current()->RunAllPending();
+
+  EXPECT_FALSE(spdy_session_pool->HasSession(pair));
+
+  // Check that the NetLog was filled reasonably.
+  net::CapturingNetLog::EntryList entries;
+  log.GetEntries(&entries);
+  EXPECT_LT(0u, entries.size());
+
+  // Check that we logged SPDY_SESSION_CLOSE correctly.
+  int pos = net::ExpectLogContainsSomewhere(
+      entries, 0,
+      net::NetLog::TYPE_SPDY_SESSION_CLOSE,
+      net::NetLog::PHASE_NONE);
+
+  CapturingNetLog::Entry entry = entries[pos];
+  NetLogSpdySessionCloseParameter* request_params =
+      static_cast<NetLogSpdySessionCloseParameter*>(
+          entry.extra_parameters.get());
+  EXPECT_EQ(ERR_CONNECTION_CLOSED, request_params->status());
+}
+
 }  // namespace net
diff --git a/net/spdy/spdy_stream.cc b/net/spdy/spdy_stream.cc
index dd7e75d..ab2cbfa 100644
--- a/net/spdy/spdy_stream.cc
+++ b/net/spdy/spdy_stream.cc
@@ -13,6 +13,26 @@
 
 namespace net {
 
+NetLogSpdyStreamErrorParameter::NetLogSpdyStreamErrorParameter(
+    spdy::SpdyStreamId stream_id,
+    int status,
+    const std::string& description)
+    : stream_id_(stream_id),
+      status_(status),
+      description_(description) {
+}
+
+NetLogSpdyStreamErrorParameter::~NetLogSpdyStreamErrorParameter() {
+}
+
+Value* NetLogSpdyStreamErrorParameter::ToValue() const {
+  DictionaryValue* dict = new DictionaryValue();
+  dict->SetInteger("stream_id", static_cast<int>(stream_id_));
+  dict->SetInteger("status", status_);
+  dict->SetString("description", description_);
+  return dict;
+}
+
 namespace {
 
 class NetLogSpdyStreamWindowUpdateParameter : public NetLog::EventParameters {
@@ -158,10 +178,6 @@ void SpdyStream::IncreaseSendWindowSize(int32 delta_window_size) {
   // it positive; however, if send_window_size_ is positive and incoming
   // WINDOW_UPDATE makes it negative, we have an overflow.
   if (send_window_size_ > 0 && new_window_size < 0) {
-    LOG(WARNING) << "Received WINDOW_UPDATE [delta:" << delta_window_size
-                 << "] for stream " << stream_id_
-                 << " overflows send_window_size_ [current:"
-                 << send_window_size_ << "]";
     std::string desc = base::StringPrintf(
         "Received WINDOW_UPDATE [delta: %d] for stream %d overflows "
         "send_window_size_ [current: %d]", delta_window_size, stream_id_,
@@ -288,7 +304,6 @@ int SpdyStream::OnResponseReceived(const spdy::SpdyHeaderBlock& response) {
        it != response.end(); ++it) {
     // Disallow uppercase headers.
     if (ContainsUpperAscii(it->first)) {
-      LOG(WARNING) << "Upper case characters in header: " << it->first;
       session_->ResetStream(stream_id_, spdy::PROTOCOL_ERROR,
                             "Upper case characters in header: " + it->first);
       response_status_ = ERR_SPDY_PROTOCOL_ERROR;
@@ -312,14 +327,13 @@ int SpdyStream::OnHeaders(const spdy::SpdyHeaderBlock& headers) {
       it != headers.end(); ++it) {
     // Disallow duplicate headers.  This is just to be conservative.
     if ((*response_).find(it->first) != (*response_).end()) {
-      LOG(WARNING) << "HEADERS duplicate header";
+      LogStreamError(ERR_SPDY_PROTOCOL_ERROR, "HEADERS duplicate header");
       response_status_ = ERR_SPDY_PROTOCOL_ERROR;
       return ERR_SPDY_PROTOCOL_ERROR;
     }
 
     // Disallow uppercase headers.
     if (ContainsUpperAscii(it->first)) {
-      LOG(WARNING) << "Upper case characters in header: " << it->first;
       session_->ResetStream(stream_id_, spdy::PROTOCOL_ERROR,
                             "Upper case characters in header: " + it->first);
       response_status_ = ERR_SPDY_PROTOCOL_ERROR;
@@ -347,6 +361,7 @@ void SpdyStream::OnDataReceived(const char* data, int length) {
   // We cannot pass data up to the caller unless the reply headers have been
   // received.
   if (!response_received()) {
+    LogStreamError(ERR_SYN_REPLY_NOT_RECEIVED, "Didn't receive a response.");
     session_->CloseStream(stream_id_, ERR_SYN_REPLY_NOT_RECEIVED);
     return;
   }
@@ -412,6 +427,13 @@ void SpdyStream::OnChunkAvailable() {
     OnWriteComplete(0);
 }
 
+void SpdyStream::LogStreamError(int status, const std::string& description) {
+  net_log_.AddEvent(
+      NetLog::TYPE_SPDY_STREAM_ERROR,
+      make_scoped_refptr(
+          new NetLogSpdyStreamErrorParameter(stream_id_, status, description)));
+}
+
 void SpdyStream::OnClose(int status) {
   io_state_ = STATE_DONE;
   response_status_ = status;
diff --git a/net/spdy/spdy_stream.h b/net/spdy/spdy_stream.h
index 051330e..a40c744 100644
--- a/net/spdy/spdy_stream.h
+++ b/net/spdy/spdy_stream.h
@@ -204,6 +204,9 @@ class NET_EXPORT_PRIVATE SpdyStream
   // |status| is an error code or OK.
   void OnClose(int status);
 
+  // Called by the SpdySession to log stream related errors.
+  void LogStreamError(int status, const std::string& description);
+
   void Cancel();
   void Close();
   bool cancelled() const { return cancelled_; }
@@ -352,6 +355,25 @@ class NET_EXPORT_PRIVATE SpdyStream
   DISALLOW_COPY_AND_ASSIGN(SpdyStream);
 };
 
+class NetLogSpdyStreamErrorParameter : public NetLog::EventParameters {
+ public:
+  NetLogSpdyStreamErrorParameter(spdy::SpdyStreamId stream_id,
+                                 int status,
+                                 const std::string& description);
+
+  spdy::SpdyStreamId stream_id() const { return stream_id_; }
+  virtual base::Value* ToValue() const OVERRIDE;
+
+ private:
+  virtual ~NetLogSpdyStreamErrorParameter();
+
+  const spdy::SpdyStreamId stream_id_;
+  const int status_;
+  const std::string description_;
+
+  DISALLOW_COPY_AND_ASSIGN(NetLogSpdyStreamErrorParameter);
+};
+
 }  // namespace net
 
 #endif  // NET_SPDY_SPDY_STREAM_H_
diff --git a/net/spdy/spdy_stream_unittest.cc b/net/spdy/spdy_stream_unittest.cc
index b722917..f29b99e 100644
--- a/net/spdy/spdy_stream_unittest.cc
+++ b/net/spdy/spdy_stream_unittest.cc
@@ -4,6 +4,7 @@
 
 #include "base/memory/ref_counted.h"
 #include "net/base/completion_callback.h"
+#include "net/base/net_log_unittest.h"
 #include "net/spdy/spdy_stream.h"
 #include "net/spdy/spdy_http_utils.h"
 #include "net/spdy/spdy_session.h"
@@ -265,5 +266,140 @@ TEST_F(SpdyStreamTest, PushedStream) {
   EXPECT_EQ(kStreamUrl, stream->GetUrl().spec());
 }
 
+TEST_F(SpdyStreamTest, StreamError) {
+  SpdySessionDependencies session_deps;
+
+  session_ = SpdySessionDependencies::SpdyCreateSession(&session_deps);
+  SpdySessionPoolPeer pool_peer_(session_->spdy_session_pool());
+
+  const SpdyHeaderInfo kSynStartHeader = {
+    spdy::SYN_STREAM,
+    1,
+    0,
+    net::ConvertRequestPriorityToSpdyPriority(LOWEST),
+    spdy::CONTROL_FLAG_NONE,
+    false,
+    spdy::INVALID,
+    NULL,
+    0,
+    spdy::DATA_FLAG_NONE
+  };
+  static const char* const kGetHeaders[] = {
+    "method",
+    "GET",
+    "scheme",
+    "http",
+    "host",
+    "www.google.com",
+    "path",
+    "/",
+    "version",
+    "HTTP/1.1",
+  };
+  scoped_ptr<spdy::SpdyFrame> req(
+      ConstructSpdyPacket(
+          kSynStartHeader, NULL, 0, kGetHeaders, arraysize(kGetHeaders) / 2));
+  scoped_ptr<spdy::SpdyFrame> msg(
+      ConstructSpdyBodyFrame("\0hello!\xff", 8));
+  MockWrite writes[] = {
+    CreateMockWrite(*req),
+    CreateMockWrite(*msg),
+  };
+  writes[0].sequence_number = 0;
+  writes[1].sequence_number = 2;
+
+  scoped_ptr<spdy::SpdyFrame> resp(ConstructSpdyGetSynReply(NULL, 0, 1));
+  scoped_ptr<spdy::SpdyFrame> echo(
+      ConstructSpdyBodyFrame("\0hello!\xff", 8));
+  MockRead reads[] = {
+    CreateMockRead(*resp),
+    CreateMockRead(*echo),
+    MockRead(ASYNC, 0, 0),  // EOF
+  };
+  reads[0].sequence_number = 1;
+  reads[1].sequence_number = 3;
+  reads[2].sequence_number = 4;
+
+  net::CapturingBoundNetLog log(net::CapturingNetLog::kUnbounded);
+
+  scoped_ptr<OrderedSocketData> data(
+      new OrderedSocketData(reads, arraysize(reads),
+                            writes, arraysize(writes)));
+  MockConnect connect_data(SYNCHRONOUS, OK);
+  data->set_connect_data(connect_data);
+
+  session_deps.socket_factory->AddSocketDataProvider(data.get());
+  SpdySession::SetSSLMode(false);
+
+  scoped_refptr<SpdySession> session(CreateSpdySession());
+  const char* kStreamUrl = "http://www.google.com/";
+  GURL url(kStreamUrl);
+
+  HostPortPair host_port_pair("www.google.com", 80);
+  scoped_refptr<TransportSocketParams> transport_params(
+      new TransportSocketParams(host_port_pair, LOWEST, false, false));
+
+  scoped_ptr<ClientSocketHandle> connection(new ClientSocketHandle);
+  EXPECT_EQ(OK, connection->Init(host_port_pair.ToString(), transport_params,
+                                 LOWEST, CompletionCallback(),
+                                 session_->GetTransportSocketPool(),
+                                 log.bound()));
+  session->InitializeWithSocket(connection.release(), false, OK);
+
+  scoped_refptr<SpdyStream> stream;
+  ASSERT_EQ(
+      OK,
+      session->CreateStream(url, LOWEST, &stream, log.bound(),
+                            CompletionCallback()));
+  scoped_refptr<IOBufferWithSize> buf(new IOBufferWithSize(8));
+  memcpy(buf->data(), "\0hello!\xff", 8);
+  TestCompletionCallback callback;
+
+  scoped_ptr<TestSpdyStreamDelegate> delegate(
+      new TestSpdyStreamDelegate(stream.get(), buf.get(), callback.callback()));
+  stream->SetDelegate(delegate.get());
+
+  EXPECT_FALSE(stream->HasUrl());
+
+  linked_ptr<spdy::SpdyHeaderBlock> headers(new spdy::SpdyHeaderBlock);
+  (*headers)["method"] = "GET";
+  (*headers)["scheme"] = url.scheme();
+  (*headers)["host"] = url.host();
+  (*headers)["path"] = url.path();
+  (*headers)["version"] = "HTTP/1.1";
+  stream->set_spdy_headers(headers);
+  EXPECT_TRUE(stream->HasUrl());
+  EXPECT_EQ(kStreamUrl, stream->GetUrl().spec());
+
+  EXPECT_EQ(ERR_IO_PENDING, stream->SendRequest(true));
+
+  const spdy::SpdyStreamId stream_id = stream->stream_id();
+
+  EXPECT_EQ(OK, callback.WaitForResult());
+
+  EXPECT_TRUE(delegate->send_headers_completed());
+  EXPECT_EQ("200", (*delegate->response())["status"]);
+  EXPECT_EQ("HTTP/1.1", (*delegate->response())["version"]);
+  EXPECT_EQ(std::string("\0hello!\xff", 8), delegate->received_data());
+  EXPECT_EQ(8, delegate->data_sent());
+  EXPECT_TRUE(delegate->closed());
+
+  // Check that the NetLog was filled reasonably.
+  net::CapturingNetLog::EntryList entries;
+  log.GetEntries(&entries);
+  EXPECT_LT(0u, entries.size());
+
+  // Check that we logged SPDY_STREAM_ERROR correctly.
+  int pos = net::ExpectLogContainsSomewhere(
+      entries, 0,
+      net::NetLog::TYPE_SPDY_STREAM_ERROR,
+      net::NetLog::PHASE_NONE);
+
+  CapturingNetLog::Entry entry = entries[pos];
+  NetLogSpdyStreamErrorParameter* request_params =
+      static_cast<NetLogSpdyStreamErrorParameter*>(
+          entry.extra_parameters.get());
+  EXPECT_EQ(stream_id, request_params->stream_id());
+}
 
 }  // namespace net
diff --git a/net/tools/flip_server/spdy_interface.h b/net/tools/flip_server/spdy_interface.h
index df4e5df..d0e30ee 100644
--- a/net/tools/flip_server/spdy_interface.h
+++ b/net/tools/flip_server/spdy_interface.h
@@ -61,8 +61,9 @@ class SpdySM : public spdy::BufferedSpdyFramerVisitorInterface,
                           bool* is_https_scheme);
 
   // BufferedSpdyFramerVisitorInterface:
-  virtual void OnError() OVERRIDE {}
-  virtual void OnStreamError(spdy::SpdyStreamId stream_id) OVERRIDE {}
+  virtual void OnError(int error_code) OVERRIDE {}
+  virtual void OnStreamError(spdy::SpdyStreamId stream_id,
+                             const std::string& description) OVERRIDE {}
   virtual void OnRstStream(
       const spdy::SpdyRstStreamControlFrame& frame) OVERRIDE;
   virtual void OnGoAway(const spdy::SpdyGoAwayControlFrame& frame) OVERRIDE {}