From d245c349f07a4b3ce71e0e921c7ff47ed72a88ea Mon Sep 17 00:00:00 2001 From: "rtenneti@chromium.org" Date: Thu, 23 Feb 2012 20:49:15 +0000 Subject: 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 --- net/base/net_log_event_type_list.h | 11 ++- net/spdy/buffered_spdy_framer.cc | 12 +-- net/spdy/buffered_spdy_framer.h | 9 +- net/spdy/buffered_spdy_framer_unittest.cc | 10 ++- net/spdy/spdy_session.cc | 128 ++++++++++++++++------------ net/spdy/spdy_session.h | 27 +++++- net/spdy/spdy_session_pool.cc | 14 +-- net/spdy/spdy_session_unittest.cc | 72 +++++++++++++++- net/spdy/spdy_stream.cc | 36 ++++++-- net/spdy/spdy_stream.h | 22 +++++ net/spdy/spdy_stream_unittest.cc | 136 ++++++++++++++++++++++++++++++ net/tools/flip_server/spdy_interface.h | 5 +- 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": , +// "status" : , +// "description": , // } 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": , +// "status": , +// "description": , +// } +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 + #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(certificate_error_code_), true); + CloseSessionOnError( + static_cast(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(certificate_error_code_), true); + CloseSessionOnError( + static_cast(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(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(result), true); + CloseSessionOnError( + static_cast(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 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& 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 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& 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(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(frame.flags()), - stream_id, 0))); - } - Respond(*headers, stream); } @@ -1419,6 +1438,14 @@ void SpdySession::OnHeaders(const spdy::SpdyHeadersControlFrame& frame, const linked_ptr& 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(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(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, // 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, void InvokeUserStreamCreationCallback(scoped_refptr* 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& 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& 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 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 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 session = + spdy_session_pool->Get(pair, log.bound()); + EXPECT_TRUE(spdy_session_pool->HasSession(pair)); + + scoped_refptr transport_params( + new TransportSocketParams(test_host_port_pair, + MEDIUM, + false, + false)); + scoped_ptr 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( + 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(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 req( + ConstructSpdyPacket( + kSynStartHeader, NULL, 0, kGetHeaders, arraysize(kGetHeaders) / 2)); + scoped_ptr msg( + ConstructSpdyBodyFrame("\0hello!\xff", 8)); + MockWrite writes[] = { + CreateMockWrite(*req), + CreateMockWrite(*msg), + }; + writes[0].sequence_number = 0; + writes[1].sequence_number = 2; + + scoped_ptr resp(ConstructSpdyGetSynReply(NULL, 0, 1)); + scoped_ptr 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 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 session(CreateSpdySession()); + const char* kStreamUrl = "http://www.google.com/"; + GURL url(kStreamUrl); + + HostPortPair host_port_pair("www.google.com", 80); + scoped_refptr transport_params( + new TransportSocketParams(host_port_pair, LOWEST, false, false)); + + scoped_ptr 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 stream; + ASSERT_EQ( + OK, + session->CreateStream(url, LOWEST, &stream, log.bound(), + CompletionCallback())); + scoped_refptr buf(new IOBufferWithSize(8)); + memcpy(buf->data(), "\0hello!\xff", 8); + TestCompletionCallback callback; + + scoped_ptr delegate( + new TestSpdyStreamDelegate(stream.get(), buf.get(), callback.callback())); + stream->SetDelegate(delegate.get()); + + EXPECT_FALSE(stream->HasUrl()); + + linked_ptr 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( + 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 {} -- cgit v1.1