// Copyright (c) 2010 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. #include "net/spdy/spdy_session.h" #include "base/basictypes.h" #include "base/linked_ptr.h" #include "base/logging.h" #include "base/message_loop.h" #include "base/rand_util.h" #include "base/stats_counters.h" #include "base/stl_util-inl.h" #include "base/string_util.h" #include "base/time.h" #include "base/values.h" #include "net/base/connection_type_histograms.h" #include "net/base/load_flags.h" #include "net/base/net_log.h" #include "net/base/net_util.h" #include "net/http/http_network_session.h" #include "net/http/http_request_info.h" #include "net/http/http_response_headers.h" #include "net/http/http_response_info.h" #include "net/socket/client_socket.h" #include "net/socket/client_socket_factory.h" #include "net/socket/ssl_client_socket.h" #include "net/spdy/spdy_frame_builder.h" #include "net/spdy/spdy_http_stream.h" #include "net/spdy/spdy_protocol.h" #include "net/spdy/spdy_settings_storage.h" #include "net/spdy/spdy_stream.h" namespace { // Diagnostics function to dump the headers of a request. // TODO(mbelshe): Remove this function. void DumpSpdyHeaders(const spdy::SpdyHeaderBlock& headers) { // Because this function gets called on every request, // take extra care to optimize it away if logging is turned off. if (logging::LOG_INFO < logging::GetMinLogLevel()) return; spdy::SpdyHeaderBlock::const_iterator it = headers.begin(); while (it != headers.end()) { std::string val = (*it).second; std::string::size_type pos = 0; while ((pos = val.find('\0', pos)) != val.npos) val[pos] = '\n'; LOG(INFO) << (*it).first << "==" << val; ++it; } } } // namespace namespace net { namespace { #ifdef WIN32 // We use an artificially small buffer size on windows because the async IO // system will artifiially delay IO completions when we use large buffers. const int kReadBufferSize = 2 * 1024; #else const int kReadBufferSize = 8 * 1024; #endif // Convert a SpdyHeaderBlock into an HttpResponseInfo. // |headers| input parameter with the SpdyHeaderBlock. // |info| output parameter for the HttpResponseInfo. // Returns true if successfully converted. False if there was a failure // or if the SpdyHeaderBlock was invalid. bool SpdyHeadersToHttpResponse(const spdy::SpdyHeaderBlock& headers, HttpResponseInfo* response) { std::string version; std::string status; // The "status" and "version" headers are required. spdy::SpdyHeaderBlock::const_iterator it; it = headers.find("status"); if (it == headers.end()) { LOG(ERROR) << "SpdyHeaderBlock without status header."; return false; } status = it->second; // Grab the version. If not provided by the server, it = headers.find("version"); if (it == headers.end()) { LOG(ERROR) << "SpdyHeaderBlock without version header."; return false; } version = it->second; response->response_time = base::Time::Now(); std::string raw_headers(version); raw_headers.push_back(' '); raw_headers.append(status); raw_headers.push_back('\0'); for (it = headers.begin(); it != headers.end(); ++it) { // For each value, if the server sends a NUL-separated // list of values, we separate that back out into // individual headers for each value in the list. // e.g. // Set-Cookie "foo\0bar" // becomes // Set-Cookie: foo\0 // Set-Cookie: bar\0 std::string value = it->second; size_t start = 0; size_t end = 0; do { end = value.find('\0', start); std::string tval; if (end != value.npos) tval = value.substr(start, (end - start)); else tval = value.substr(start); raw_headers.append(it->first); raw_headers.push_back(':'); raw_headers.append(tval); raw_headers.push_back('\0'); start = end + 1; } while (end != value.npos); } response->headers = new HttpResponseHeaders(raw_headers); response->was_fetched_via_spdy = true; return true; } // Create a SpdyHeaderBlock for a Spdy SYN_STREAM Frame from // a HttpRequestInfo block. void CreateSpdyHeadersFromHttpRequest( const HttpRequestInfo& info, spdy::SpdyHeaderBlock* headers) { // TODO(willchan): It's not really necessary to convert from // HttpRequestHeaders to spdy::SpdyHeaderBlock. static const char kHttpProtocolVersion[] = "HTTP/1.1"; HttpRequestHeaders::Iterator it(info.extra_headers); while (it.GetNext()) { std::string name = StringToLowerASCII(it.name()); if (headers->find(name) == headers->end()) { (*headers)[name] = it.value(); } else { std::string new_value = (*headers)[name]; new_value.append(1, '\0'); // +=() doesn't append 0's new_value += it.value(); (*headers)[name] = new_value; } } // TODO(mbelshe): Add Proxy headers here. (See http_network_transaction.cc) // TODO(mbelshe): Add authentication headers here. (*headers)["method"] = info.method; (*headers)["url"] = info.url.spec(); (*headers)["version"] = kHttpProtocolVersion; if (!info.referrer.is_empty()) (*headers)["referer"] = info.referrer.spec(); // Honor load flags that impact proxy caches. if (info.load_flags & LOAD_BYPASS_CACHE) { (*headers)["pragma"] = "no-cache"; (*headers)["cache-control"] = "no-cache"; } else if (info.load_flags & LOAD_VALIDATE_CACHE) { (*headers)["cache-control"] = "max-age=0"; } } void AdjustSocketBufferSizes(ClientSocket* socket) { // Adjust socket buffer sizes. // SPDY uses one socket, and we want a really big buffer. // This greatly helps on links with packet loss - we can even // outperform Vista's dynamic window sizing algorithm. // TODO(mbelshe): more study. const int kSocketBufferSize = 512 * 1024; socket->SetReceiveBufferSize(kSocketBufferSize); socket->SetSendBufferSize(kSocketBufferSize); } class NetLogSpdySynParameter : public NetLog::EventParameters { public: NetLogSpdySynParameter(const linked_ptr& headers, spdy::SpdyControlFlags flags, spdy::SpdyStreamId id) : headers_(headers), flags_(flags), id_(id) {} Value* ToValue() const { DictionaryValue* dict = new DictionaryValue(); DictionaryValue* headers_dict = new DictionaryValue(); for (spdy::SpdyHeaderBlock::const_iterator it = headers_->begin(); it != headers_->end(); ++it) { headers_dict->SetString(ASCIIToWide(it->first), it->second); } dict->SetInteger(L"flags", flags_); dict->Set(L"headers", headers_dict); dict->SetInteger(L"id", id_); return dict; } private: ~NetLogSpdySynParameter() {} const linked_ptr headers_; spdy::SpdyControlFlags flags_; spdy::SpdyStreamId id_; DISALLOW_COPY_AND_ASSIGN(NetLogSpdySynParameter); }; class NetLogSpdySettingsParameter : public NetLog::EventParameters { public: explicit NetLogSpdySettingsParameter(const spdy::SpdySettings& settings) : settings_(settings) {} Value* ToValue() const { DictionaryValue* dict = new DictionaryValue(); ListValue* settings = new ListValue(); for (spdy::SpdySettings::const_iterator it = settings_.begin(); it != settings_.end(); ++it) { settings->Append(new StringValue( StringPrintf("[%u:%u]", it->first.id(), it->second))); } dict->Set(L"settings", settings); return dict; } private: ~NetLogSpdySettingsParameter() {} const spdy::SpdySettings settings_; DISALLOW_COPY_AND_ASSIGN(NetLogSpdySettingsParameter); }; } // namespace // static bool SpdySession::use_ssl_ = true; SpdySession::SpdySession(const HostPortPair& host_port_pair, HttpNetworkSession* session, NetLog* net_log) : ALLOW_THIS_IN_INITIALIZER_LIST( connect_callback_(this, &SpdySession::OnTCPConnect)), ALLOW_THIS_IN_INITIALIZER_LIST( ssl_connect_callback_(this, &SpdySession::OnSSLConnect)), ALLOW_THIS_IN_INITIALIZER_LIST( read_callback_(this, &SpdySession::OnReadComplete)), ALLOW_THIS_IN_INITIALIZER_LIST( write_callback_(this, &SpdySession::OnWriteComplete)), host_port_pair_(host_port_pair), session_(session), connection_(new ClientSocketHandle), read_buffer_(new IOBuffer(kReadBufferSize)), read_pending_(false), stream_hi_water_mark_(1), // Always start at 1 for the first stream id. write_pending_(false), delayed_write_pending_(false), is_secure_(false), error_(OK), state_(IDLE), streams_initiated_count_(0), streams_pushed_count_(0), streams_pushed_and_claimed_count_(0), streams_abandoned_count_(0), sent_settings_(false), received_settings_(false), in_session_pool_(true), net_log_(BoundNetLog::Make(net_log, NetLog::SOURCE_SPDY_SESSION)) { net_log_.BeginEvent( NetLog::TYPE_SPDY_SESSION, new NetLogStringParameter("host_port", host_port_pair_.ToString())); // TODO(mbelshe): consider randomization of the stream_hi_water_mark. spdy_framer_.set_visitor(this); session_->ssl_config_service()->GetSSLConfig(&ssl_config_); SendSettings(); } SpdySession::~SpdySession() { // Cleanup all the streams. CloseAllStreams(net::ERR_ABORTED); if (connection_->is_initialized()) { // With Spdy we can't recycle sockets. connection_->socket()->Disconnect(); } RecordHistograms(); net_log_.EndEvent(NetLog::TYPE_SPDY_SESSION, NULL); } void SpdySession::InitializeWithSSLSocket(ClientSocketHandle* connection) { static StatsCounter spdy_sessions("spdy.sessions"); spdy_sessions.Increment(); AdjustSocketBufferSizes(connection->socket()); state_ = CONNECTED; connection_.reset(connection); is_secure_ = true; // |connection| contains an SSLClientSocket. // This is a newly initialized session that no client should have a handle to // yet, so there's no need to start writing data as in OnTCPConnect(), but we // should start reading data. ReadSocket(); } net::Error SpdySession::Connect(const std::string& group_name, const TCPSocketParams& destination, RequestPriority priority) { DCHECK(priority >= SPDY_PRIORITY_HIGHEST && priority <= SPDY_PRIORITY_LOWEST); // If the connect process is started, let the caller continue. if (state_ > IDLE) return net::OK; state_ = CONNECTING; static StatsCounter spdy_sessions("spdy.sessions"); spdy_sessions.Increment(); int rv = connection_->Init(group_name, destination, priority, &connect_callback_, session_->tcp_socket_pool(), net_log_); DCHECK(rv <= 0); // If the connect is pending, we still return ok. The APIs enqueue // work until after the connect completes asynchronously later. if (rv == net::ERR_IO_PENDING) return net::OK; OnTCPConnect(rv); return static_cast(rv); } scoped_refptr SpdySession::GetOrCreateStream( const HttpRequestInfo& request, const UploadDataStream* upload_data, const BoundNetLog& stream_net_log) { const GURL& url = request.url; const std::string& path = url.PathForRequest(); scoped_refptr stream; // Check if we have a push stream for this path. if (request.method == "GET") { // Only HTTP will push a stream. scoped_refptr stream = GetPushStream(path); if (stream) { DCHECK(streams_pushed_and_claimed_count_ < streams_pushed_count_); // Update the request time stream->SetRequestTime(base::Time::Now()); // Change the request info, updating the response's request time too stream->SetRequestInfo(request); const HttpResponseInfo* response = stream->GetResponseInfo(); if (response && response->headers->HasHeader("vary")) { // TODO(ahendrickson) -- What is the right thing to do if the server // pushes data with a vary field? void* iter = NULL; std::string value; response->headers->EnumerateHeader(&iter, "vary", &value); LOG(ERROR) << "SpdyStream: " << "Received pushed stream ID " << stream->stream_id() << "with vary field value '" << value << "'"; } streams_pushed_and_claimed_count_++; return stream; } } // Check if we have a pending push stream for this url. PendingStreamMap::iterator it; it = pending_streams_.find(path); if (it != pending_streams_.end()) { // Server has advertised a stream, but not yet sent it. DCHECK(!it->second); // Server will assign a stream id when the push stream arrives. Use 0 for // now. net_log_.AddEvent(NetLog::TYPE_SPDY_STREAM_ADOPTED_PUSH_STREAM, NULL); stream = new SpdyHttpStream(this, 0, true); stream->SetRequestInfo(request); stream->set_path(path); stream->set_net_log(stream_net_log); it->second = stream; return stream; } const spdy::SpdyStreamId stream_id = GetNewStreamId(); // If we still don't have a stream, activate one now. stream = new SpdyHttpStream(this, stream_id, false); stream->SetRequestInfo(request); stream->set_priority(request.priority); stream->set_path(path); stream->set_net_log(stream_net_log); ActivateStream(stream); UMA_HISTOGRAM_CUSTOM_COUNTS("Net.SpdyPriorityCount", static_cast(request.priority), 0, 10, 11); LOG(INFO) << "SpdyStream: Creating stream " << stream_id << " for " << url; // TODO(mbelshe): Optimize memory allocations DCHECK(request.priority >= SPDY_PRIORITY_HIGHEST && request.priority <= SPDY_PRIORITY_LOWEST); // Convert from HttpRequestHeaders to Spdy Headers. linked_ptr headers(new spdy::SpdyHeaderBlock); CreateSpdyHeadersFromHttpRequest(request, headers.get()); spdy::SpdyControlFlags flags = spdy::CONTROL_FLAG_NONE; if (!request.upload_data || !upload_data->size()) flags = spdy::CONTROL_FLAG_FIN; // Create a SYN_STREAM packet and add to the output queue. scoped_ptr syn_frame( spdy_framer_.CreateSynStream(stream_id, 0, request.priority, flags, false, headers.get())); QueueFrame(syn_frame.get(), request.priority, stream); static StatsCounter spdy_requests("spdy.requests"); spdy_requests.Increment(); LOG(INFO) << "FETCHING: " << request.url.spec(); streams_initiated_count_++; LOG(INFO) << "SPDY SYN_STREAM HEADERS ----------------------------------"; DumpSpdyHeaders(*headers); if (stream_net_log.HasListener()) { stream_net_log.AddEvent( NetLog::TYPE_SPDY_STREAM_SYN_STREAM, new NetLogSpdySynParameter(headers, flags, stream_id)); } return stream; } int SpdySession::WriteStreamData(spdy::SpdyStreamId stream_id, net::IOBuffer* data, int len) { LOG(INFO) << "Writing Stream Data for stream " << stream_id << " (" << len << " bytes)"; const int kMss = 1430; // This is somewhat arbitrary and not really fixed, // but it will always work reasonably with ethernet. // Chop the world into 2-packet chunks. This is somewhat arbitrary, but // is reasonably small and ensures that we elicit ACKs quickly from TCP // (because TCP tries to only ACK every other packet). const int kMaxSpdyFrameChunkSize = (2 * kMss) - spdy::SpdyFrame::size(); // Find our stream DCHECK(IsStreamActive(stream_id)); scoped_refptr stream = active_streams_[stream_id]; CHECK_EQ(stream->stream_id(), stream_id); if (!stream) return ERR_INVALID_SPDY_STREAM; // TODO(mbelshe): Setting of the FIN is assuming that the caller will pass // all data to write in a single chunk. Is this always true? // Set the flags on the upload. spdy::SpdyDataFlags flags = spdy::DATA_FLAG_FIN; if (len > kMaxSpdyFrameChunkSize) { len = kMaxSpdyFrameChunkSize; flags = spdy::DATA_FLAG_NONE; } // TODO(mbelshe): reduce memory copies here. scoped_ptr frame( spdy_framer_.CreateDataFrame(stream_id, data->data(), len, flags)); QueueFrame(frame.get(), stream->priority(), stream); return ERR_IO_PENDING; } void SpdySession::CloseStream(spdy::SpdyStreamId stream_id, int status) { LOG(INFO) << "Closing stream " << stream_id << " with status " << status; // TODO(mbelshe): We should send a RST_STREAM control frame here // so that the server can cancel a large send. DeleteStream(stream_id, status); } bool SpdySession::IsStreamActive(spdy::SpdyStreamId stream_id) const { return ContainsKey(active_streams_, stream_id); } LoadState SpdySession::GetLoadState() const { // NOTE: The application only queries the LoadState via the // SpdyNetworkTransaction, and details are only needed when // we're in the process of connecting. // If we're connecting, defer to the connection to give us the actual // LoadState. if (state_ == CONNECTING) return connection_->GetLoadState(); // Just report that we're idle since the session could be doing // many things concurrently. return LOAD_STATE_IDLE; } void SpdySession::OnTCPConnect(int result) { LOG(INFO) << "Spdy socket connected (result=" << result << ")"; // We shouldn't be coming through this path if we didn't just open a fresh // socket (or have an error trying to do so). DCHECK(!connection_->socket() || !connection_->is_reused()); if (result != net::OK) { DCHECK_LT(result, 0); CloseSessionOnError(static_cast(result)); return; } else { UpdateConnectionTypeHistograms(CONNECTION_SPDY); } AdjustSocketBufferSizes(connection_->socket()); if (use_ssl_) { // Add a SSL socket on top of our existing transport socket. ClientSocket* socket = connection_->release_socket(); // TODO(mbelshe): Fix the hostname. This is BROKEN without having // a real hostname. socket = session_->socket_factory()->CreateSSLClientSocket( socket, "" /* request_->url.HostNoBrackets() */ , ssl_config_); connection_->set_socket(socket); is_secure_ = true; int status = connection_->socket()->Connect(&ssl_connect_callback_); if (status != ERR_IO_PENDING) OnSSLConnect(status); } else { DCHECK_EQ(state_, CONNECTING); state_ = CONNECTED; // Make sure we get any pending data sent. WriteSocketLater(); // Start reading ReadSocket(); } } void SpdySession::OnSSLConnect(int result) { // TODO(mbelshe): We need to replicate the functionality of // HttpNetworkTransaction::DoSSLConnectComplete here, where it calls // HandleCertificateError() and such. if (IsCertificateError(result)) result = OK; // TODO(mbelshe): pretend we're happy anyway. if (result == OK) { DCHECK_EQ(state_, CONNECTING); state_ = CONNECTED; // After we've connected, send any data to the server, and then issue // our read. WriteSocketLater(); ReadSocket(); } else { DCHECK_LT(result, 0); // It should be an error, not a byte count. CloseSessionOnError(static_cast(result)); } } void SpdySession::OnReadComplete(int bytes_read) { // Parse a frame. For now this code requires that the frame fit into our // buffer (32KB). // TODO(mbelshe): support arbitrarily large frames! LOG(INFO) << "Spdy socket read: " << bytes_read << " bytes"; read_pending_ = false; if (bytes_read <= 0) { // Session is tearing down. net::Error error = static_cast(bytes_read); if (bytes_read == 0) { LOG(INFO) << "Spdy socket closed by server[" << host_port_pair().ToString() << "]."; error = ERR_CONNECTION_CLOSED; } CloseSessionOnError(error); return; } // The SpdyFramer will use callbacks onto |this| as it parses frames. // When errors occur, those callbacks can lead to teardown of all references // to |this|, so maintain a reference to self during this call for safe // cleanup. scoped_refptr self(this); char *data = read_buffer_->data(); while (bytes_read && spdy_framer_.error_code() == spdy::SpdyFramer::SPDY_NO_ERROR) { uint32 bytes_processed = spdy_framer_.ProcessInput(data, bytes_read); bytes_read -= bytes_processed; data += bytes_processed; if (spdy_framer_.state() == spdy::SpdyFramer::SPDY_DONE) spdy_framer_.Reset(); } if (state_ != CLOSED) ReadSocket(); } void SpdySession::OnWriteComplete(int result) { DCHECK(write_pending_); DCHECK(in_flight_write_.size()); DCHECK_NE(result, 0); // This shouldn't happen for write. write_pending_ = false; scoped_refptr stream = in_flight_write_.stream(); LOG(INFO) << "Spdy write complete (result=" << result << ")" << (stream ? std::string(" for stream ") + IntToString(stream->stream_id()) : ""); if (result >= 0) { // It should not be possible to have written more bytes than our // in_flight_write_. DCHECK_LE(result, in_flight_write_.buffer()->BytesRemaining()); in_flight_write_.buffer()->DidConsume(result); // We only notify the stream when we've fully written the pending frame. if (!in_flight_write_.buffer()->BytesRemaining()) { scoped_refptr stream = in_flight_write_.stream(); if (stream) { // Report the number of bytes written to the caller, but exclude the // frame size overhead. NOTE: if this frame was compressed the // reported bytes written is the compressed size, not the original // size. if (result > 0) { result = in_flight_write_.buffer()->size(); DCHECK_GT(result, static_cast(spdy::SpdyFrame::size())); result -= static_cast(spdy::SpdyFrame::size()); } // It is possible that the stream was cancelled while we were writing // to the socket. if (!stream->cancelled()) stream->OnWriteComplete(result); } // Cleanup the write which just completed. in_flight_write_.release(); } // Write more data. We're already in a continuation, so we can // go ahead and write it immediately (without going back to the // message loop). WriteSocketLater(); } else { in_flight_write_.release(); // The stream is now errored. Close it down. CloseSessionOnError(static_cast(result)); } } void SpdySession::ReadSocket() { if (read_pending_) return; if (state_ == CLOSED) { NOTREACHED(); return; } CHECK(connection_.get()); CHECK(connection_->socket()); int bytes_read = connection_->socket()->Read(read_buffer_.get(), kReadBufferSize, &read_callback_); switch (bytes_read) { case 0: // Socket is closed! CloseSessionOnError(ERR_CONNECTION_CLOSED); return; case net::ERR_IO_PENDING: // Waiting for data. Nothing to do now. read_pending_ = true; return; default: // Data was read, process it. // Schedule the work through the message loop to avoid recursive // callbacks. read_pending_ = true; MessageLoop::current()->PostTask(FROM_HERE, NewRunnableMethod( this, &SpdySession::OnReadComplete, bytes_read)); break; } } void SpdySession::WriteSocketLater() { if (delayed_write_pending_) return; if (state_ < CONNECTED) return; delayed_write_pending_ = true; MessageLoop::current()->PostTask(FROM_HERE, NewRunnableMethod( this, &SpdySession::WriteSocket)); } void SpdySession::WriteSocket() { // This function should only be called via WriteSocketLater. DCHECK(delayed_write_pending_); delayed_write_pending_ = false; // If the socket isn't connected yet, just wait; we'll get called // again when the socket connection completes. If the socket is // closed, just return. if (state_ < CONNECTED || state_ == CLOSED) return; if (write_pending_) // Another write is in progress still. return; // Loop sending frames until we've sent everything or until the write // returns error (or ERR_IO_PENDING). while (in_flight_write_.buffer() || !queue_.empty()) { if (!in_flight_write_.buffer()) { // Grab the next SpdyFrame to send. SpdyIOBuffer next_buffer = queue_.top(); queue_.pop(); // We've deferred compression until just before we write it to the socket, // which is now. At this time, we don't compress our data frames. spdy::SpdyFrame uncompressed_frame(next_buffer.buffer()->data(), false); size_t size; if (spdy_framer_.IsCompressible(uncompressed_frame)) { scoped_ptr compressed_frame( spdy_framer_.CompressFrame(uncompressed_frame)); if (!compressed_frame.get()) { LOG(ERROR) << "SPDY Compression failure"; CloseSessionOnError(net::ERR_SPDY_PROTOCOL_ERROR); return; } size = compressed_frame->length() + spdy::SpdyFrame::size(); DCHECK_GT(size, 0u); // TODO(mbelshe): We have too much copying of data here. IOBufferWithSize* buffer = new IOBufferWithSize(size); memcpy(buffer->data(), compressed_frame->data(), size); // Attempt to send the frame. in_flight_write_ = SpdyIOBuffer(buffer, size, 0, next_buffer.stream()); } else { size = uncompressed_frame.length() + spdy::SpdyFrame::size(); in_flight_write_ = next_buffer; } } else { DCHECK(in_flight_write_.buffer()->BytesRemaining()); } write_pending_ = true; int rv = connection_->socket()->Write(in_flight_write_.buffer(), in_flight_write_.buffer()->BytesRemaining(), &write_callback_); if (rv == net::ERR_IO_PENDING) break; // We sent the frame successfully. OnWriteComplete(rv); // TODO(mbelshe): Test this error case. Maybe we should mark the socket // as in an error state. if (rv < 0) break; } } void SpdySession::CloseAllStreams(net::Error status) { LOG(INFO) << "Closing all SPDY Streams for " << host_port_pair().ToString(); static StatsCounter abandoned_streams("spdy.abandoned_streams"); static StatsCounter abandoned_push_streams("spdy.abandoned_push_streams"); if (!active_streams_.empty()) abandoned_streams.Add(active_streams_.size()); if (!pushed_streams_.empty()) { streams_abandoned_count_ += pushed_streams_.size(); abandoned_push_streams.Add(pushed_streams_.size()); } while (!active_streams_.empty()) { ActiveStreamMap::iterator it = active_streams_.begin(); const scoped_refptr& stream = it->second; DCHECK(stream); LOG(ERROR) << "ABANDONED (stream_id=" << stream->stream_id() << "): " << stream->path(); DeleteStream(stream->stream_id(), status); } // TODO(erikchen): ideally stream->OnClose() is only ever called by // DeleteStream, but pending streams fall into their own category for now. PendingStreamMap::iterator it; for (it = pending_streams_.begin(); it != pending_streams_.end(); ++it) { const scoped_refptr& stream = it->second; if (stream) stream->OnClose(ERR_ABORTED); } pending_streams_.clear(); // We also need to drain the queue. while (queue_.size()) queue_.pop(); } int SpdySession::GetNewStreamId() { int id = stream_hi_water_mark_; stream_hi_water_mark_ += 2; if (stream_hi_water_mark_ > 0x7fff) stream_hi_water_mark_ = 1; return id; } void SpdySession::QueueFrame(spdy::SpdyFrame* frame, spdy::SpdyPriority priority, SpdyStream* stream) { int length = spdy::SpdyFrame::size() + frame->length(); IOBuffer* buffer = new IOBuffer(length); memcpy(buffer->data(), frame->data(), length); queue_.push(SpdyIOBuffer(buffer, length, priority, stream)); WriteSocketLater(); } void SpdySession::CloseSessionOnError(net::Error err) { // 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); DCHECK_LT(err, OK); LOG(INFO) << "spdy::CloseSessionOnError(" << err << ") for " << host_port_pair().ToString(); // Don't close twice. This can occur because we can have both // a read and a write outstanding, and each can complete with // an error. if (state_ != CLOSED) { state_ = CLOSED; error_ = err; CloseAllStreams(err); RemoveFromPool(); } } void SpdySession::ActivateStream(SpdyStream* stream) { const spdy::SpdyStreamId id = stream->stream_id(); DCHECK(!IsStreamActive(id)); active_streams_[id] = stream; } void SpdySession::DeleteStream(spdy::SpdyStreamId id, int status) { // Remove the stream from pushed_streams_ and active_streams_. ActivePushedStreamList::iterator it; for (it = pushed_streams_.begin(); it != pushed_streams_.end(); ++it) { scoped_refptr curr = *it; if (id == curr->stream_id()) { pushed_streams_.erase(it); break; } } // The stream might have been deleted. ActiveStreamMap::iterator it2 = active_streams_.find(id); if (it2 == active_streams_.end()) return; // If this is an active stream, call the callback. const scoped_refptr& stream = it2->second; if (stream) stream->OnClose(status); active_streams_.erase(it2); } void SpdySession::RemoveFromPool() { if (in_session_pool_) { session_->spdy_session_pool()->Remove(this); in_session_pool_ = false; } } scoped_refptr SpdySession::GetPushStream( const std::string& path) { static StatsCounter used_push_streams("spdy.claimed_push_streams"); LOG(INFO) << "Looking for push stream: " << path; scoped_refptr stream; // We just walk a linear list here. ActivePushedStreamList::iterator it; for (it = pushed_streams_.begin(); it != pushed_streams_.end(); ++it) { stream = *it; if (path == stream->path()) { CHECK(stream->pushed()); pushed_streams_.erase(it); used_push_streams.Increment(); LOG(INFO) << "Push Stream Claim for: " << path; return stream; } } return NULL; } void SpdySession::GetSSLInfo(SSLInfo* ssl_info) { if (is_secure_) { SSLClientSocket* ssl_socket = reinterpret_cast(connection_->socket()); ssl_socket->GetSSLInfo(ssl_info); } } void SpdySession::OnError(spdy::SpdyFramer* framer) { LOG(ERROR) << "SpdySession error: " << framer->error_code(); CloseSessionOnError(net::ERR_SPDY_PROTOCOL_ERROR); } void SpdySession::OnStreamFrameData(spdy::SpdyStreamId stream_id, const char* data, size_t len) { LOG(INFO) << "Spdy data for stream " << stream_id << ", " << len << " bytes"; if (!IsStreamActive(stream_id)) { // NOTE: it may just be that the stream was cancelled. LOG(WARNING) << "Received data frame for invalid stream " << stream_id; return; } scoped_refptr stream = active_streams_[stream_id]; stream->OnDataReceived(data, len); } bool SpdySession::Respond(const spdy::SpdyHeaderBlock& headers, const scoped_refptr stream) { // TODO(mbelshe): For now we convert from our nice hash map back // to a string of headers; this is because the HttpResponseInfo // is a bit rigid for its http (non-spdy) design. HttpResponseInfo response; // TODO(ahendrickson): This is recorded after the entire SYN_STREAM control // frame has been received and processed. Move to framer? response.response_time = base::Time::Now(); int rv = OK; if (SpdyHeadersToHttpResponse(headers, &response)) { GetSSLInfo(&response.ssl_info); response.request_time = stream->GetRequestTime(); response.vary_data.Init(*stream->GetRequestInfo(), *response.headers); if (is_secure_) { SSLClientSocket* ssl_socket = reinterpret_cast(connection_->socket()); response.was_npn_negotiated = ssl_socket->wasNpnNegotiated(); } rv = stream->OnResponseReceived(response); } else { rv = ERR_INVALID_RESPONSE; } if (rv < 0) { DCHECK_NE(rv, ERR_IO_PENDING); const spdy::SpdyStreamId stream_id = stream->stream_id(); DeleteStream(stream_id, rv); return false; } return true; } void SpdySession::OnSyn(const spdy::SpdySynStreamControlFrame& frame, const linked_ptr& headers) { spdy::SpdyStreamId stream_id = frame.stream_id(); LOG(INFO) << "Spdy SynStream for stream " << stream_id; // Server-initiated streams should have even sequence numbers. if ((stream_id & 0x1) != 0) { LOG(ERROR) << "Received invalid OnSyn stream id " << stream_id; return; } if (IsStreamActive(stream_id)) { LOG(ERROR) << "Received OnSyn for active stream " << stream_id; return; } streams_pushed_count_++; LOG(INFO) << "SpdySession: Syn received for stream: " << stream_id; LOG(INFO) << "SPDY SYN RESPONSE HEADERS -----------------------"; DumpSpdyHeaders(*headers); // TODO(mbelshe): DCHECK that this is a GET method? const std::string& path = ContainsKey(*headers, "path") ? headers->find("path")->second : ""; // Verify that the response had a URL for us. DCHECK(!path.empty()); if (path.empty()) { LOG(WARNING) << "Pushed stream did not contain a path."; return; } // Only HTTP push a stream. scoped_refptr stream; // Check if we already have a delegate awaiting this stream. PendingStreamMap::iterator it; it = pending_streams_.find(path); if (it != pending_streams_.end()) { stream = it->second; pending_streams_.erase(it); } if (stream) { CHECK(stream->pushed()); CHECK_EQ(0u, stream->stream_id()); stream->set_stream_id(stream_id); const BoundNetLog& log = stream->net_log(); if (log.HasListener()) { log.AddEvent( NetLog::TYPE_SPDY_STREAM_PUSHED_SYN_STREAM, new NetLogSpdySynParameter( headers, static_cast(frame.flags()), stream_id)); } } else { stream = new SpdyHttpStream(this, stream_id, true); if (net_log_.HasListener()) { net_log_.AddEvent( NetLog::TYPE_SPDY_SESSION_PUSHED_SYN_STREAM, new NetLogSpdySynParameter( headers, static_cast(frame.flags()), stream_id)); } // A new HttpResponseInfo object needs to be generated so the call to // OnResponseReceived below has something to fill in. // When a SpdyNetworkTransaction is created for this resource, the // response_info is copied over and this version is destroyed. // // TODO(cbentzel): Minimize allocations and copies of HttpResponseInfo // object. Should it just be part of SpdyStream? stream->SetPushResponse(new HttpResponseInfo()); } pushed_streams_.push_back(stream); // Activate a stream and parse the headers. ActivateStream(stream); stream->set_path(path); if (!Respond(*headers, stream)) return; LOG(INFO) << "Got pushed stream for " << stream->path(); static StatsCounter push_requests("spdy.pushed_streams"); push_requests.Increment(); } void SpdySession::OnSynReply(const spdy::SpdySynReplyControlFrame& frame, const linked_ptr& headers) { spdy::SpdyStreamId stream_id = frame.stream_id(); LOG(INFO) << "Spdy SynReply for stream " << stream_id; bool valid_stream = IsStreamActive(stream_id); if (!valid_stream) { // NOTE: it may just be that the stream was cancelled. LOG(WARNING) << "Received SYN_REPLY for invalid stream " << stream_id; return; } LOG(INFO) << "SPDY SYN_REPLY RESPONSE HEADERS for stream: " << stream_id; DumpSpdyHeaders(*headers); // We record content declared as being pushed so that we don't // request a duplicate stream which is already scheduled to be // sent to us. spdy::SpdyHeaderBlock::const_iterator it; it = headers->find("x-associated-content"); if (it != headers->end()) { const std::string& content = it->second; std::string::size_type start = 0; std::string::size_type end = 0; do { end = content.find("||", start); if (end == std::string::npos) end = content.length(); std::string url = content.substr(start, end - start); std::string::size_type pos = url.find("??"); if (pos == std::string::npos) break; url = url.substr(pos + 2); GURL gurl(url); std::string path = gurl.PathForRequest(); if (path.length()) pending_streams_[path] = NULL; else LOG(INFO) << "Invalid X-Associated-Content path: " << url; start = end + 2; } while (start < content.length()); } scoped_refptr stream = active_streams_[stream_id]; CHECK_EQ(stream->stream_id(), stream_id); CHECK(!stream->cancelled()); const BoundNetLog& log = stream->net_log(); if (log.HasListener()) { log.AddEvent( NetLog::TYPE_SPDY_STREAM_SYN_REPLY, new NetLogSpdySynParameter( headers, static_cast(frame.flags()), stream_id)); } Respond(*headers, stream); } void SpdySession::OnControl(const spdy::SpdyControlFrame* frame) { const linked_ptr headers(new spdy::SpdyHeaderBlock); uint32 type = frame->type(); if (type == spdy::SYN_STREAM || type == spdy::SYN_REPLY) { if (!spdy_framer_.ParseHeaderBlock(frame, headers.get())) { LOG(WARNING) << "Could not parse Spdy Control Frame Header"; // TODO(mbelshe): Error the session? return; } } switch (type) { case spdy::GOAWAY: OnGoAway(*reinterpret_cast(frame)); break; case spdy::SETTINGS: OnSettings( *reinterpret_cast(frame)); break; case spdy::RST_STREAM: OnFin(*reinterpret_cast(frame)); break; case spdy::SYN_STREAM: OnSyn(*reinterpret_cast(frame), headers); break; case spdy::SYN_REPLY: OnSynReply( *reinterpret_cast(frame), headers); break; default: DCHECK(false); // Error! } } void SpdySession::OnFin(const spdy::SpdyRstStreamControlFrame& frame) { spdy::SpdyStreamId stream_id = frame.stream_id(); LOG(INFO) << "Spdy Fin for stream " << stream_id; bool valid_stream = IsStreamActive(stream_id); if (!valid_stream) { // NOTE: it may just be that the stream was cancelled. LOG(WARNING) << "Received FIN for invalid stream" << stream_id; return; } scoped_refptr stream = active_streams_[stream_id]; CHECK_EQ(stream->stream_id(), stream_id); CHECK(!stream->cancelled()); const BoundNetLog& log = stream->net_log(); log.AddEvent( NetLog::TYPE_SPDY_STREAM_RST_STREAM, new NetLogIntegerParameter("status", frame.status())); if (frame.status() == 0) { stream->OnDataReceived(NULL, 0); } else { LOG(ERROR) << "Spdy stream closed: " << 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); } } void SpdySession::OnGoAway(const spdy::SpdyGoAwayControlFrame& frame) { LOG(INFO) << "Spdy GOAWAY for session[" << this << "] for " << host_port_pair().ToString(); net_log_.AddEvent( NetLog::TYPE_SPDY_SESSION_GOAWAY, new NetLogIntegerParameter( "last_accepted_stream_id", frame.last_accepted_stream_id())); RemoveFromPool(); // TODO(willchan): Cancel any streams that are past the GoAway frame's // |last_accepted_stream_id|. // Don't bother killing any streams that are still reading. They'll either // complete successfully or get an ERR_CONNECTION_CLOSED when the socket is // closed. } void SpdySession::OnSettings(const spdy::SpdySettingsControlFrame& frame) { spdy::SpdySettings settings; if (spdy_framer_.ParseSettings(&frame, &settings)) { SpdySettingsStorage* settings_storage = session_->mutable_spdy_settings(); settings_storage->Set(host_port_pair_, settings); } received_settings_ = true; net_log_.AddEvent( NetLog::TYPE_SPDY_SESSION_RECV_SETTINGS, new NetLogSpdySettingsParameter(settings)); } void SpdySession::SendSettings() { const SpdySettingsStorage& settings_storage = session_->spdy_settings(); const spdy::SpdySettings& settings = settings_storage.Get(host_port_pair_); if (settings.empty()) return; net_log_.AddEvent( NetLog::TYPE_SPDY_SESSION_SEND_SETTINGS, new NetLogSpdySettingsParameter(settings)); // Create the SETTINGS frame and send it. scoped_ptr settings_frame( spdy_framer_.CreateSettings(settings)); sent_settings_ = true; QueueFrame(settings_frame.get(), 0, NULL); } void SpdySession::RecordHistograms() { UMA_HISTOGRAM_CUSTOM_COUNTS("Net.SpdyStreamsPerSession", streams_initiated_count_, 0, 300, 50); UMA_HISTOGRAM_CUSTOM_COUNTS("Net.SpdyStreamsPushedPerSession", streams_pushed_count_, 0, 300, 50); UMA_HISTOGRAM_CUSTOM_COUNTS("Net.SpdyStreamsPushedAndClaimedPerSession", streams_pushed_and_claimed_count_, 0, 300, 50); UMA_HISTOGRAM_CUSTOM_COUNTS("Net.SpdyStreamsAbandonedPerSession", streams_abandoned_count_, 0, 300, 50); UMA_HISTOGRAM_ENUMERATION("Net.SpdySettingsSent", sent_settings_ ? 1 : 0, 2); UMA_HISTOGRAM_ENUMERATION("Net.SpdySettingsReceived", received_settings_ ? 1 : 0, 2); if (received_settings_) { // Enumerate the saved settings, and set histograms for it. const SpdySettingsStorage& settings_storage = session_->spdy_settings(); const spdy::SpdySettings& settings = settings_storage.Get(host_port_pair_); if (settings.empty()) { NOTREACHED(); // If we lost our settings already, something is wrong! return; } spdy::SpdySettings::const_iterator it; for (it = settings.begin(); it != settings.end(); ++it) { const spdy::SpdySetting setting = *it; switch (setting.first.id()) { case spdy::SETTINGS_CURRENT_CWND: UMA_HISTOGRAM_CUSTOM_COUNTS("Net.SpdySettingsCwnd", setting.second, 1, 200, 100); break; case spdy::SETTINGS_ROUND_TRIP_TIME: UMA_HISTOGRAM_CUSTOM_COUNTS("Net.SpdySettingsRTT", setting.second, 1, 1200, 100); break; case spdy::SETTINGS_DOWNLOAD_RETRANS_RATE: UMA_HISTOGRAM_CUSTOM_COUNTS("Net.SpdySettingsRetransRate", setting.second, 1, 100, 50); break; } } } } } // namespace net