summaryrefslogtreecommitdiffstats
path: root/net
diff options
context:
space:
mode:
authormmenke@chromium.org <mmenke@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98>2013-02-02 00:35:22 +0000
committermmenke@chromium.org <mmenke@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98>2013-02-02 00:35:22 +0000
commitf6c63db5717961da5fee29631da4c3dcbf9d038f (patch)
tree1ef3d5fecd8147946ecc94ccb4cab9d0ddb3bf0f /net
parent0d0b59d9367b35ff7d6649c8dd1b5deaadf80bf4 (diff)
downloadchromium_src-f6c63db5717961da5fee29631da4c3dcbf9d038f.zip
chromium_src-f6c63db5717961da5fee29631da4c3dcbf9d038f.tar.gz
chromium_src-f6c63db5717961da5fee29631da4c3dcbf9d038f.tar.bz2
LoadTiming in net part 5:
Add a NetLog event source for SpdyProxyClientSockets, and a couple new NetLog events as well. This results in all requests that go over the same tunnelled stream having the same unique socket ID. This also serves to prevent too much random stuff, like SSL handshakes and SSL reads/writes from being logged in the proxy's SPDY_SESSION. BUG=77446 Review URL: https://codereview.chromium.org/12093011 git-svn-id: svn://svn.chromium.org/chrome/trunk/src@180214 0039d316-1c4b-4281-b951-d872f2087c98
Diffstat (limited to 'net')
-rw-r--r--net/base/capturing_net_log.cc17
-rw-r--r--net/base/capturing_net_log.h9
-rw-r--r--net/base/load_timing_info.h18
-rw-r--r--net/base/net_log.cc1
-rw-r--r--net/base/net_log_event_type_list.h16
-rw-r--r--net/base/net_log_source_type_list.h1
-rw-r--r--net/http/http_network_transaction_spdy2_unittest.cc421
-rw-r--r--net/http/http_network_transaction_spdy3_unittest.cc401
-rw-r--r--net/http/http_proxy_client_socket_pool.cc1
-rw-r--r--net/socket/socket_test_util.cc13
-rw-r--r--net/socket/socket_test_util.h5
-rw-r--r--net/spdy/spdy_proxy_client_socket.cc43
-rw-r--r--net/spdy/spdy_proxy_client_socket.h1
-rw-r--r--net/spdy/spdy_proxy_client_socket_spdy2_unittest.cc81
-rw-r--r--net/spdy/spdy_proxy_client_socket_spdy3_unittest.cc81
15 files changed, 1066 insertions, 43 deletions
diff --git a/net/base/capturing_net_log.cc b/net/base/capturing_net_log.cc
index 0ffdfb7..b90dcae 100644
--- a/net/base/capturing_net_log.cc
+++ b/net/base/capturing_net_log.cc
@@ -79,6 +79,17 @@ void CapturingNetLog::GetEntries(CapturedEntryList* entry_list) const {
*entry_list = captured_entries_;
}
+void CapturingNetLog::GetEntriesForSource(NetLog::Source source,
+ CapturedEntryList* entry_list) const {
+ base::AutoLock lock(lock_);
+ entry_list->clear();
+ for (CapturedEntryList::const_iterator entry = captured_entries_.begin();
+ entry != captured_entries_.end(); ++entry) {
+ if (entry->source.id == source.id)
+ entry_list->push_back(*entry);
+ }
+}
+
size_t CapturingNetLog::GetSize() const {
base::AutoLock lock(lock_);
return captured_entries_.size();
@@ -152,6 +163,12 @@ void CapturingBoundNetLog::GetEntries(
capturing_net_log_.GetEntries(entry_list);
}
+void CapturingBoundNetLog::GetEntriesForSource(
+ NetLog::Source source,
+ CapturingNetLog::CapturedEntryList* entry_list) const {
+ capturing_net_log_.GetEntriesForSource(source, entry_list);
+}
+
size_t CapturingBoundNetLog::GetSize() const {
return capturing_net_log_.GetSize();
}
diff --git a/net/base/capturing_net_log.h b/net/base/capturing_net_log.h
index ec78a3f..d3586d1 100644
--- a/net/base/capturing_net_log.h
+++ b/net/base/capturing_net_log.h
@@ -74,6 +74,10 @@ class CapturingNetLog : public NetLog {
// Returns the list of all entries in the log.
void GetEntries(CapturedEntryList* entry_list) const;
+ // Fills |entry_list| with all entries in the log from the specified Source.
+ void GetEntriesForSource(NetLog::Source source,
+ CapturedEntryList* entry_list) const;
+
// Returns number of entries in the log.
size_t GetSize() const;
@@ -121,6 +125,11 @@ class CapturingBoundNetLog {
// Fills |entry_list| with all entries in the log.
void GetEntries(CapturingNetLog::CapturedEntryList* entry_list) const;
+ // Fills |entry_list| with all entries in the log from the specified Source.
+ void GetEntriesForSource(
+ NetLog::Source source,
+ CapturingNetLog::CapturedEntryList* entry_list) const;
+
// Returns number of entries in the log.
size_t GetSize() const;
diff --git a/net/base/load_timing_info.h b/net/base/load_timing_info.h
index 3e876bd..82cd9fb 100644
--- a/net/base/load_timing_info.h
+++ b/net/base/load_timing_info.h
@@ -11,6 +11,12 @@
namespace net {
+// Structure containing timing information for a request.
+// It addresses the needs of
+// http://groups.google.com/group/http-archive-specification/web/har-1-1-spec,
+// http://dev.w3.org/2006/webapi/WebTiming/, and
+// http://www.w3.org/TR/resource-timing/.
+//
// All events that do not apply to a request have null times. For non-HTTP
// requests, all times other than the request_start times are null.
//
@@ -96,11 +102,13 @@ struct NET_EXPORT LoadTimingInfo {
bool socket_reused;
// Unique socket ID, can be used to identify requests served by the same
- // socket.
- // TODO(mmenke): Do something reasonable for SPDY proxies. Currently, SPDY
- // sessions (And HTTPS requests?) over SPDY proxies use the ID
- // of the SPDY proxy's session. HTTP requests, however, use
- // the ID of the SPDY proxy's socket.
+ // socket. For connections tunnelled over SPDY proxies, this is the ID of
+ // the virtual connection (The SpdyProxyClientSocket), not the ID of the
+ // actual socket. HTTP requests handled by the SPDY proxy itself all use the
+ // actual socket's ID.
+ //
+ // 0 when there is no socket associated with the request, or it's not an HTTP
+ // request.
uint32 socket_log_id;
// Start time as a base::Time, so times can be coverted into actual times.
diff --git a/net/base/net_log.cc b/net/base/net_log.cc
index b811db4..d6b6f39 100644
--- a/net/base/net_log.cc
+++ b/net/base/net_log.cc
@@ -73,6 +73,7 @@ Value* NetLogString16Callback(const char* name,
} // namespace
+// LoadTimingInfo requires this be 0.
const uint32 NetLog::Source::kInvalidId = 0;
NetLog::Source::Source() : type(SOURCE_NONE), id(kInvalidId) {
diff --git a/net/base/net_log_event_type_list.h b/net/base/net_log_event_type_list.h
index faa231f7..10fa5c4 100644
--- a/net/base/net_log_event_type_list.h
+++ b/net/base/net_log_event_type_list.h
@@ -333,7 +333,7 @@ EVENT_TYPE(SUBMITTED_TO_RESOLVER_THREAD)
// Socket (Shared by stream and datagram sockets)
// ------------------------------------------------------------------------
-// Marks the begin/end of a socket (TCP/SOCKS/SSL/UDP).
+// Marks the begin/end of a socket (TCP/SOCKS/SSL/UDP/"SpdyProxyClientSocket").
//
// The BEGIN phase contains the following parameters:
//
@@ -518,7 +518,9 @@ EVENT_TYPE(SSL_VERIFICATION_MERGED)
// }
EVENT_TYPE(SSL_NSS_ERROR)
-// The specified number of bytes were sent on the socket.
+// The specified number of bytes were sent on the socket. Depending on the
+// source of the event, may be logged either once the data is sent, or when it
+// is queued to be sent.
// The following parameters are attached:
// {
// "byte_count": <Number of bytes that were just sent>,
@@ -1205,6 +1207,16 @@ EVENT_TYPE(SPDY_STREAM_UPDATE_RECV_WINDOW)
EVENT_TYPE(SPDY_STREAM_ERROR)
// ------------------------------------------------------------------------
+// SpdyProxyClientSocket
+// ------------------------------------------------------------------------
+
+EVENT_TYPE(SPDY_PROXY_CLIENT_SESSION)
+// Identifies the SPDY session a source is using.
+// {
+// "source_dependency": <Source identifier for the underlying session>,
+// }
+
+// ------------------------------------------------------------------------
// HttpStreamParser
// ------------------------------------------------------------------------
diff --git a/net/base/net_log_source_type_list.h b/net/base/net_log_source_type_list.h
index 24d9574..66a5298 100644
--- a/net/base/net_log_source_type_list.h
+++ b/net/base/net_log_source_type_list.h
@@ -27,3 +27,4 @@ SOURCE_TYPE(DOWNLOAD)
SOURCE_TYPE(FILESTREAM)
SOURCE_TYPE(IPV6_PROBE_JOB)
SOURCE_TYPE(DNS_PROBER)
+SOURCE_TYPE(PROXY_CLIENT_SOCKET)
diff --git a/net/http/http_network_transaction_spdy2_unittest.cc b/net/http/http_network_transaction_spdy2_unittest.cc
index 7cb6f91..c76d205d 100644
--- a/net/http/http_network_transaction_spdy2_unittest.cc
+++ b/net/http/http_network_transaction_spdy2_unittest.cc
@@ -2943,6 +2943,408 @@ TEST_F(HttpNetworkTransactionSpdy2Test, HttpsProxySpdyConnectFailure) {
// TODO(ttuttle): Anything else to check here?
}
+// Test load timing in the case of two HTTPS (non-SPDY) requests through a SPDY
+// HTTPS Proxy to different servers.
+TEST_F(HttpNetworkTransactionSpdy2Test,
+ HttpsProxySpdyConnectHttpsLoadTimingTwoRequestsTwoServers) {
+ // Configure against https proxy server "proxy:70".
+ SpdySessionDependencies session_deps(ProxyService::CreateFixed(
+ "https://proxy:70"));
+ CapturingBoundNetLog log;
+ session_deps.net_log = log.bound().net_log();
+ scoped_refptr<HttpNetworkSession> session(
+ SpdySessionDependencies::SpdyCreateSessionDeterministic(&session_deps));
+
+ HttpRequestInfo request1;
+ request1.method = "GET";
+ request1.url = GURL("https://www.google.com/");
+ request1.load_flags = 0;
+
+ HttpRequestInfo request2;
+ request2.method = "GET";
+ request2.url = GURL("https://news.google.com/");
+ request2.load_flags = 0;
+
+ // CONNECT to www.google.com:443 via SPDY.
+ scoped_ptr<SpdyFrame> connect1(ConstructSpdyConnect(NULL, 0, 1));
+ scoped_ptr<SpdyFrame> conn_resp1(ConstructSpdyGetSynReply(NULL, 0, 1));
+
+ // Fetch https://www.google.com/ via HTTP.
+ const char get1[] = "GET / HTTP/1.1\r\n"
+ "Host: www.google.com\r\n"
+ "Connection: keep-alive\r\n\r\n";
+ scoped_ptr<SpdyFrame> wrapped_get1(
+ ConstructSpdyBodyFrame(1, get1, strlen(get1), false));
+ const char resp1[] = "HTTP/1.1 200 OK\r\n"
+ "Content-Length: 1\r\n\r\n";
+ scoped_ptr<SpdyFrame> wrapped_get_resp1(
+ ConstructSpdyBodyFrame(1, resp1, strlen(resp1), false));
+ scoped_ptr<SpdyFrame> wrapped_body1(ConstructSpdyBodyFrame(1, "1", 1, false));
+ scoped_ptr<SpdyFrame> window_update(
+ ConstructSpdyWindowUpdate(1, wrapped_get_resp1->length()));
+
+ // CONNECT to news.google.com:443 via SPDY.
+ const char* const kConnectHeaders2[] = {
+ "method", "CONNECT",
+ "url", "news.google.com:443",
+ "host", "news.google.com",
+ "version", "HTTP/1.1",
+ };
+ scoped_ptr<SpdyFrame> connect2(
+ ConstructSpdyControlFrame(NULL,
+ 0,
+ /*compressed*/ false,
+ 3,
+ LOWEST,
+ SYN_STREAM,
+ CONTROL_FLAG_NONE,
+ kConnectHeaders2,
+ arraysize(kConnectHeaders2)));
+ scoped_ptr<SpdyFrame> conn_resp2(ConstructSpdyGetSynReply(NULL, 0, 3));
+
+ // Fetch https://news.google.com/ via HTTP.
+ const char get2[] = "GET / HTTP/1.1\r\n"
+ "Host: news.google.com\r\n"
+ "Connection: keep-alive\r\n\r\n";
+ scoped_ptr<SpdyFrame> wrapped_get2(
+ ConstructSpdyBodyFrame(3, get2, strlen(get2), false));
+ const char resp2[] = "HTTP/1.1 200 OK\r\n"
+ "Content-Length: 2\r\n\r\n";
+ scoped_ptr<SpdyFrame> wrapped_get_resp2(
+ ConstructSpdyBodyFrame(3, resp2, strlen(resp2), false));
+ scoped_ptr<SpdyFrame> wrapped_body2(
+ ConstructSpdyBodyFrame(3, "22", 2, false));
+
+ MockWrite spdy_writes[] = {
+ CreateMockWrite(*connect1, 0),
+ CreateMockWrite(*wrapped_get1, 2),
+ CreateMockWrite(*connect2, 5),
+ CreateMockWrite(*wrapped_get2, 7),
+ };
+
+ MockRead spdy_reads[] = {
+ CreateMockRead(*conn_resp1, 1, ASYNC),
+ CreateMockRead(*wrapped_get_resp1, 3, ASYNC),
+ CreateMockRead(*wrapped_body1, 4, ASYNC),
+ CreateMockRead(*conn_resp2, 6, ASYNC),
+ CreateMockRead(*wrapped_get_resp2, 8, ASYNC),
+ CreateMockRead(*wrapped_body2, 9, ASYNC),
+ MockRead(ASYNC, 0, 10),
+ };
+
+ DeterministicSocketData spdy_data(
+ spdy_reads, arraysize(spdy_reads),
+ spdy_writes, arraysize(spdy_writes));
+ session_deps.deterministic_socket_factory->AddSocketDataProvider(&spdy_data);
+
+ SSLSocketDataProvider ssl(ASYNC, OK);
+ ssl.SetNextProto(kProtoSPDY2);
+ session_deps.deterministic_socket_factory->AddSSLSocketDataProvider(&ssl);
+ SSLSocketDataProvider ssl2(ASYNC, OK);
+ ssl2.was_npn_negotiated = false;
+ ssl2.protocol_negotiated = kProtoUnknown;
+ session_deps.deterministic_socket_factory->AddSSLSocketDataProvider(&ssl2);
+ SSLSocketDataProvider ssl3(ASYNC, OK);
+ ssl3.was_npn_negotiated = false;
+ ssl3.protocol_negotiated = kProtoUnknown;
+ session_deps.deterministic_socket_factory->AddSSLSocketDataProvider(&ssl3);
+
+ TestCompletionCallback callback;
+
+ scoped_ptr<HttpTransaction> trans(new HttpNetworkTransaction(session));
+ int rv = trans->Start(&request1, callback.callback(), BoundNetLog());
+ EXPECT_EQ(ERR_IO_PENDING, rv);
+ // The first connect and request, each of their responses, and the body.
+ spdy_data.RunFor(5);
+
+ rv = callback.WaitForResult();
+ EXPECT_EQ(OK, rv);
+
+ LoadTimingInfo load_timing_info;
+ EXPECT_TRUE(trans->GetLoadTimingInfo(&load_timing_info));
+ TestLoadTimingNotReused(load_timing_info, CONNECT_TIMING_HAS_SSL_TIMES);
+
+ const HttpResponseInfo* response = trans->GetResponseInfo();
+ ASSERT_TRUE(response != NULL);
+ ASSERT_TRUE(response->headers != NULL);
+ EXPECT_EQ("HTTP/1.1 200 OK", response->headers->GetStatusLine());
+
+ std::string response_data;
+ scoped_refptr<net::IOBuffer> buf(new net::IOBuffer(256));
+ EXPECT_EQ(1, trans->Read(buf, 256, callback.callback()));
+
+ scoped_ptr<HttpTransaction> trans2(new HttpNetworkTransaction(session));
+ rv = trans2->Start(&request2, callback.callback(), BoundNetLog());
+ EXPECT_EQ(ERR_IO_PENDING, rv);
+
+ // The second connect and request, each of their responses, and the body.
+ spdy_data.RunFor(5);
+ rv = callback.WaitForResult();
+ EXPECT_EQ(OK, rv);
+
+ LoadTimingInfo load_timing_info2;
+ EXPECT_TRUE(trans2->GetLoadTimingInfo(&load_timing_info2));
+ // Even though the SPDY connection is reused, a new tunnelled connection has
+ // to be created, so the socket's load timing looks like a fresh connection.
+ TestLoadTimingNotReused(load_timing_info2, CONNECT_TIMING_HAS_SSL_TIMES);
+
+ // The requests should have different IDs, since they each are using their own
+ // separate stream.
+ EXPECT_NE(load_timing_info.socket_log_id, load_timing_info2.socket_log_id);
+
+ EXPECT_EQ(2, trans2->Read(buf, 256, callback.callback()));
+}
+
+// Test load timing in the case of two HTTPS (non-SPDY) requests through a SPDY
+// HTTPS Proxy to the same server.
+TEST_F(HttpNetworkTransactionSpdy2Test,
+ HttpsProxySpdyConnectHttpsLoadTimingTwoRequestsSameServer) {
+ // Configure against https proxy server "proxy:70".
+ SpdySessionDependencies session_deps(ProxyService::CreateFixed(
+ "https://proxy:70"));
+ CapturingBoundNetLog log;
+ session_deps.net_log = log.bound().net_log();
+ scoped_refptr<HttpNetworkSession> session(
+ SpdySessionDependencies::SpdyCreateSessionDeterministic(&session_deps));
+
+ HttpRequestInfo request1;
+ request1.method = "GET";
+ request1.url = GURL("https://www.google.com/");
+ request1.load_flags = 0;
+
+ HttpRequestInfo request2;
+ request2.method = "GET";
+ request2.url = GURL("https://www.google.com/2");
+ request2.load_flags = 0;
+
+ // CONNECT to www.google.com:443 via SPDY.
+ scoped_ptr<SpdyFrame> connect1(ConstructSpdyConnect(NULL, 0, 1));
+ scoped_ptr<SpdyFrame> conn_resp1(ConstructSpdyGetSynReply(NULL, 0, 1));
+
+ // Fetch https://www.google.com/ via HTTP.
+ const char get1[] = "GET / HTTP/1.1\r\n"
+ "Host: www.google.com\r\n"
+ "Connection: keep-alive\r\n\r\n";
+ scoped_ptr<SpdyFrame> wrapped_get1(
+ ConstructSpdyBodyFrame(1, get1, strlen(get1), false));
+ const char resp1[] = "HTTP/1.1 200 OK\r\n"
+ "Content-Length: 1\r\n\r\n";
+ scoped_ptr<SpdyFrame> wrapped_get_resp1(
+ ConstructSpdyBodyFrame(1, resp1, strlen(resp1), false));
+ scoped_ptr<SpdyFrame> wrapped_body1(ConstructSpdyBodyFrame(1, "1", 1, false));
+ scoped_ptr<SpdyFrame> window_update(
+ ConstructSpdyWindowUpdate(1, wrapped_get_resp1->length()));
+
+ // Fetch https://www.google.com/2 via HTTP.
+ const char get2[] = "GET /2 HTTP/1.1\r\n"
+ "Host: www.google.com\r\n"
+ "Connection: keep-alive\r\n\r\n";
+ scoped_ptr<SpdyFrame> wrapped_get2(
+ ConstructSpdyBodyFrame(1, get2, strlen(get2), false));
+ const char resp2[] = "HTTP/1.1 200 OK\r\n"
+ "Content-Length: 2\r\n\r\n";
+ scoped_ptr<SpdyFrame> wrapped_get_resp2(
+ ConstructSpdyBodyFrame(1, resp2, strlen(resp2), false));
+ scoped_ptr<SpdyFrame> wrapped_body2(
+ ConstructSpdyBodyFrame(1, "22", 2, false));
+
+ MockWrite spdy_writes[] = {
+ CreateMockWrite(*connect1, 0),
+ CreateMockWrite(*wrapped_get1, 2),
+ CreateMockWrite(*wrapped_get2, 5),
+ };
+
+ MockRead spdy_reads[] = {
+ CreateMockRead(*conn_resp1, 1, ASYNC),
+ CreateMockRead(*wrapped_get_resp1, 3, ASYNC),
+ CreateMockRead(*wrapped_body1, 4, ASYNC),
+ CreateMockRead(*wrapped_get_resp2, 6, ASYNC),
+ CreateMockRead(*wrapped_body2, 7, ASYNC),
+ MockRead(ASYNC, 0, 8),
+ };
+
+ DeterministicSocketData spdy_data(
+ spdy_reads, arraysize(spdy_reads),
+ spdy_writes, arraysize(spdy_writes));
+ session_deps.deterministic_socket_factory->AddSocketDataProvider(&spdy_data);
+
+ SSLSocketDataProvider ssl(ASYNC, OK);
+ ssl.SetNextProto(kProtoSPDY2);
+ session_deps.deterministic_socket_factory->AddSSLSocketDataProvider(&ssl);
+ SSLSocketDataProvider ssl2(ASYNC, OK);
+ ssl2.was_npn_negotiated = false;
+ ssl2.protocol_negotiated = kProtoUnknown;
+ session_deps.deterministic_socket_factory->AddSSLSocketDataProvider(&ssl2);
+
+ TestCompletionCallback callback;
+
+ scoped_ptr<HttpTransaction> trans(new HttpNetworkTransaction(session));
+ int rv = trans->Start(&request1, callback.callback(), BoundNetLog());
+ EXPECT_EQ(ERR_IO_PENDING, rv);
+ // The first connect and request, each of their responses, and the body.
+ spdy_data.RunFor(5);
+
+ rv = callback.WaitForResult();
+ EXPECT_EQ(OK, rv);
+
+ LoadTimingInfo load_timing_info;
+ EXPECT_TRUE(trans->GetLoadTimingInfo(&load_timing_info));
+ TestLoadTimingNotReused(load_timing_info, CONNECT_TIMING_HAS_SSL_TIMES);
+
+ const HttpResponseInfo* response = trans->GetResponseInfo();
+ ASSERT_TRUE(response != NULL);
+ ASSERT_TRUE(response->headers != NULL);
+ EXPECT_EQ("HTTP/1.1 200 OK", response->headers->GetStatusLine());
+
+ std::string response_data;
+ scoped_refptr<net::IOBuffer> buf(new net::IOBuffer(256));
+ EXPECT_EQ(1, trans->Read(buf, 256, callback.callback()));
+ trans.reset();
+
+ scoped_ptr<HttpTransaction> trans2(new HttpNetworkTransaction(session));
+ rv = trans2->Start(&request2, callback.callback(), BoundNetLog());
+ EXPECT_EQ(ERR_IO_PENDING, rv);
+
+ // The second request, response, and body. There should not be a second
+ // connect.
+ spdy_data.RunFor(3);
+ rv = callback.WaitForResult();
+ EXPECT_EQ(OK, rv);
+
+ LoadTimingInfo load_timing_info2;
+ EXPECT_TRUE(trans2->GetLoadTimingInfo(&load_timing_info2));
+ TestLoadTimingReused(load_timing_info2);
+
+ // The requests should have the same ID.
+ EXPECT_EQ(load_timing_info.socket_log_id, load_timing_info2.socket_log_id);
+
+ EXPECT_EQ(2, trans2->Read(buf, 256, callback.callback()));
+}
+
+// Test load timing in the case of of two HTTP requests through a SPDY HTTPS
+// Proxy to different servers.
+TEST_F(HttpNetworkTransactionSpdy2Test,
+ HttpsProxySpdyLoadTimingTwoHttpRequests) {
+ // Configure against https proxy server "proxy:70".
+ SpdySessionDependencies session_deps(ProxyService::CreateFixed(
+ "https://proxy:70"));
+ CapturingBoundNetLog log;
+ session_deps.net_log = log.bound().net_log();
+ scoped_refptr<HttpNetworkSession> session(
+ SpdySessionDependencies::SpdyCreateSessionDeterministic(&session_deps));
+
+ HttpRequestInfo request1;
+ request1.method = "GET";
+ request1.url = GURL("http://www.google.com/");
+ request1.load_flags = 0;
+
+ HttpRequestInfo request2;
+ request2.method = "GET";
+ request2.url = GURL("http://news.google.com/");
+ request2.load_flags = 0;
+
+ // http://www.google.com/
+ const char* const headers1[] = {
+ "method", "GET",
+ "url", "http://www.google.com/",
+ "host", "www.google.com",
+ "scheme", "http",
+ "version", "HTTP/1.1"
+ };
+ scoped_ptr<SpdyFrame> get1(ConstructSpdyControlFrame(NULL, 0, false, 1,
+ LOWEST, SYN_STREAM,
+ CONTROL_FLAG_FIN,
+ headers1,
+ arraysize(headers1)));
+ scoped_ptr<SpdyFrame> get_resp1(ConstructSpdyGetSynReply(NULL, 0, 1));
+ scoped_ptr<SpdyFrame> body1(ConstructSpdyBodyFrame(1, "1", 1, true));
+
+ // http://news.google.com/
+ const char* const headers2[] = {
+ "method", "GET",
+ "url", "http://news.google.com/",
+ "host", "news.google.com",
+ "scheme", "http",
+ "version", "HTTP/1.1"
+ };
+ scoped_ptr<SpdyFrame> get2(ConstructSpdyControlFrame(NULL, 0, false, 3,
+ LOWEST, SYN_STREAM,
+ CONTROL_FLAG_FIN,
+ headers2,
+ arraysize(headers2)));
+ scoped_ptr<SpdyFrame> get_resp2(ConstructSpdyGetSynReply(NULL, 0, 3));
+ scoped_ptr<SpdyFrame> body2(ConstructSpdyBodyFrame(3, "22", 2, true));
+
+ MockWrite spdy_writes[] = {
+ CreateMockWrite(*get1, 0),
+ CreateMockWrite(*get2, 3),
+ };
+
+ MockRead spdy_reads[] = {
+ CreateMockRead(*get_resp1, 1, ASYNC),
+ CreateMockRead(*body1, 2, ASYNC),
+ CreateMockRead(*get_resp2, 4, ASYNC),
+ CreateMockRead(*body2, 5, ASYNC),
+ MockRead(ASYNC, 0, 6),
+ };
+
+ DeterministicSocketData spdy_data(
+ spdy_reads, arraysize(spdy_reads),
+ spdy_writes, arraysize(spdy_writes));
+ session_deps.deterministic_socket_factory->AddSocketDataProvider(&spdy_data);
+
+ SSLSocketDataProvider ssl(ASYNC, OK);
+ ssl.SetNextProto(kProtoSPDY2);
+ session_deps.deterministic_socket_factory->AddSSLSocketDataProvider(&ssl);
+
+ TestCompletionCallback callback;
+
+ scoped_ptr<HttpTransaction> trans(new HttpNetworkTransaction(session));
+ int rv = trans->Start(&request1, callback.callback(), BoundNetLog());
+ EXPECT_EQ(ERR_IO_PENDING, rv);
+ spdy_data.RunFor(2);
+
+ rv = callback.WaitForResult();
+ EXPECT_EQ(OK, rv);
+
+ LoadTimingInfo load_timing_info;
+ EXPECT_TRUE(trans->GetLoadTimingInfo(&load_timing_info));
+ TestLoadTimingNotReused(load_timing_info,
+ CONNECT_TIMING_HAS_CONNECT_TIMES_ONLY);
+
+ const HttpResponseInfo* response = trans->GetResponseInfo();
+ ASSERT_TRUE(response != NULL);
+ ASSERT_TRUE(response->headers != NULL);
+ EXPECT_EQ("HTTP/1.1 200 OK", response->headers->GetStatusLine());
+
+ std::string response_data;
+ scoped_refptr<net::IOBuffer> buf(new net::IOBuffer(256));
+ EXPECT_EQ(ERR_IO_PENDING, trans->Read(buf, 256, callback.callback()));
+ spdy_data.RunFor(1);
+ EXPECT_EQ(1, callback.WaitForResult());
+ // Delete the first request, so the second one can reuse the socket.
+ trans.reset();
+
+ scoped_ptr<HttpTransaction> trans2(new HttpNetworkTransaction(session));
+ rv = trans2->Start(&request2, callback.callback(), BoundNetLog());
+ EXPECT_EQ(ERR_IO_PENDING, rv);
+
+ spdy_data.RunFor(2);
+ rv = callback.WaitForResult();
+ EXPECT_EQ(OK, rv);
+
+ LoadTimingInfo load_timing_info2;
+ EXPECT_TRUE(trans2->GetLoadTimingInfo(&load_timing_info2));
+ TestLoadTimingReused(load_timing_info2);
+
+ // The requests should have the same ID.
+ EXPECT_EQ(load_timing_info.socket_log_id, load_timing_info2.socket_log_id);
+
+ EXPECT_EQ(ERR_IO_PENDING, trans2->Read(buf, 256, callback.callback()));
+ spdy_data.RunFor(1);
+ EXPECT_EQ(2, callback.WaitForResult());
+}
+
// Test the challenge-response-retry sequence through an HTTPS Proxy
TEST_F(HttpNetworkTransactionSpdy2Test, HttpsProxyAuthRetry) {
HttpRequestInfo request;
@@ -10487,8 +10889,10 @@ TEST_F(HttpNetworkTransactionSpdy2Test, DoNotUseSpdySessionForHttpOverTunnel) {
MockConnect connect_data1(ASYNC, OK);
data1.set_connect_data(connect_data1);
- SpdySessionDependencies session_deps(ProxyService::CreateFixed(
- "https://proxy:70"));
+ SpdySessionDependencies session_deps(
+ ProxyService::CreateFixedFromPacResult("HTTPS proxy:70"));
+ CapturingNetLog log;
+ session_deps.net_log = &log;
SSLSocketDataProvider ssl1(ASYNC, OK); // to the proxy
ssl1.SetNextProto(kProtoSPDY2);
session_deps.deterministic_socket_factory->AddSSLSocketDataProvider(&ssl1);
@@ -10516,6 +10920,11 @@ TEST_F(HttpNetworkTransactionSpdy2Test, DoNotUseSpdySessionForHttpOverTunnel) {
EXPECT_EQ(OK, callback1.WaitForResult());
EXPECT_TRUE(trans1.GetResponseInfo()->was_fetched_via_spdy);
+ LoadTimingInfo load_timing_info1;
+ EXPECT_TRUE(trans1.GetLoadTimingInfo(&load_timing_info1));
+ TestLoadTimingNotReusedWithPac(load_timing_info1,
+ CONNECT_TIMING_HAS_SSL_TIMES);
+
// Now, start the HTTP request
HttpRequestInfo request2;
request2.method = "GET";
@@ -10531,6 +10940,14 @@ TEST_F(HttpNetworkTransactionSpdy2Test, DoNotUseSpdySessionForHttpOverTunnel) {
EXPECT_EQ(OK, callback2.WaitForResult());
EXPECT_TRUE(trans2.GetResponseInfo()->was_fetched_via_spdy);
+
+ LoadTimingInfo load_timing_info2;
+ EXPECT_TRUE(trans2.GetLoadTimingInfo(&load_timing_info2));
+ // The established SPDY sessions is considered reused by the HTTP request.
+ TestLoadTimingReusedWithPac(load_timing_info2);
+ // HTTP requests over a SPDY session should have a different connection
+ // socket_log_id than requests over a tunnel.
+ EXPECT_NE(load_timing_info1.socket_log_id, load_timing_info2.socket_log_id);
}
TEST_F(HttpNetworkTransactionSpdy2Test, UseSpdySessionForHttpWhenForced) {
diff --git a/net/http/http_network_transaction_spdy3_unittest.cc b/net/http/http_network_transaction_spdy3_unittest.cc
index fdcf111..e0787d6 100644
--- a/net/http/http_network_transaction_spdy3_unittest.cc
+++ b/net/http/http_network_transaction_spdy3_unittest.cc
@@ -2943,6 +2943,389 @@ TEST_F(HttpNetworkTransactionSpdy3Test, HttpsProxySpdyConnectFailure) {
// TODO(ttuttle): Anything else to check here?
}
+// Test load timing in the case of two HTTPS (non-SPDY) requests through a SPDY
+// HTTPS Proxy to different servers.
+TEST_F(HttpNetworkTransactionSpdy3Test,
+ HttpsProxySpdyConnectHttpsLoadTimingTwoRequestsTwoServers) {
+ // Configure against https proxy server "proxy:70".
+ SpdySessionDependencies session_deps(ProxyService::CreateFixed(
+ "https://proxy:70"));
+ CapturingBoundNetLog log;
+ session_deps.net_log = log.bound().net_log();
+ scoped_refptr<HttpNetworkSession> session(
+ SpdySessionDependencies::SpdyCreateSessionDeterministic(&session_deps));
+
+ HttpRequestInfo request1;
+ request1.method = "GET";
+ request1.url = GURL("https://www.google.com/");
+ request1.load_flags = 0;
+
+ HttpRequestInfo request2;
+ request2.method = "GET";
+ request2.url = GURL("https://news.google.com/");
+ request2.load_flags = 0;
+
+ // CONNECT to www.google.com:443 via SPDY.
+ scoped_ptr<SpdyFrame> connect1(ConstructSpdyConnect(NULL, 0, 1));
+ scoped_ptr<SpdyFrame> conn_resp1(ConstructSpdyGetSynReply(NULL, 0, 1));
+
+ // Fetch https://www.google.com/ via HTTP.
+ const char get1[] = "GET / HTTP/1.1\r\n"
+ "Host: www.google.com\r\n"
+ "Connection: keep-alive\r\n\r\n";
+ scoped_ptr<SpdyFrame> wrapped_get1(
+ ConstructSpdyBodyFrame(1, get1, strlen(get1), false));
+ const char resp1[] = "HTTP/1.1 200 OK\r\n"
+ "Content-Length: 1\r\n\r\n";
+ scoped_ptr<SpdyFrame> wrapped_get_resp1(
+ ConstructSpdyBodyFrame(1, resp1, strlen(resp1), false));
+ scoped_ptr<SpdyFrame> wrapped_body1(ConstructSpdyBodyFrame(1, "1", 1, false));
+ scoped_ptr<SpdyFrame> window_update(
+ ConstructSpdyWindowUpdate(1, wrapped_get_resp1->length()));
+
+ // CONNECT to news.google.com:443 via SPDY.
+ const char* const kConnectHeaders2[] = {
+ ":method", "CONNECT",
+ ":path", "news.google.com:443",
+ ":host", "news.google.com",
+ ":version", "HTTP/1.1",
+ };
+ scoped_ptr<SpdyFrame> connect2(
+ ConstructSpdyControlFrame(NULL,
+ 0,
+ /*compressed*/ false,
+ 3,
+ LOWEST,
+ SYN_STREAM,
+ CONTROL_FLAG_NONE,
+ kConnectHeaders2,
+ arraysize(kConnectHeaders2)));
+ scoped_ptr<SpdyFrame> conn_resp2(ConstructSpdyGetSynReply(NULL, 0, 3));
+
+ // Fetch https://news.google.com/ via HTTP.
+ const char get2[] = "GET / HTTP/1.1\r\n"
+ "Host: news.google.com\r\n"
+ "Connection: keep-alive\r\n\r\n";
+ scoped_ptr<SpdyFrame> wrapped_get2(
+ ConstructSpdyBodyFrame(3, get2, strlen(get2), false));
+ const char resp2[] = "HTTP/1.1 200 OK\r\n"
+ "Content-Length: 2\r\n\r\n";
+ scoped_ptr<SpdyFrame> wrapped_get_resp2(
+ ConstructSpdyBodyFrame(3, resp2, strlen(resp2), false));
+ scoped_ptr<SpdyFrame> wrapped_body2(
+ ConstructSpdyBodyFrame(3, "22", 2, false));
+
+ MockWrite spdy_writes[] = {
+ CreateMockWrite(*connect1, 0),
+ CreateMockWrite(*wrapped_get1, 2),
+ CreateMockWrite(*connect2, 5),
+ CreateMockWrite(*wrapped_get2, 7),
+ };
+
+ MockRead spdy_reads[] = {
+ CreateMockRead(*conn_resp1, 1, ASYNC),
+ CreateMockRead(*wrapped_get_resp1, 3, ASYNC),
+ CreateMockRead(*wrapped_body1, 4, ASYNC),
+ CreateMockRead(*conn_resp2, 6, ASYNC),
+ CreateMockRead(*wrapped_get_resp2, 8, ASYNC),
+ CreateMockRead(*wrapped_body2, 9, ASYNC),
+ MockRead(ASYNC, 0, 10),
+ };
+
+ DeterministicSocketData spdy_data(
+ spdy_reads, arraysize(spdy_reads),
+ spdy_writes, arraysize(spdy_writes));
+ session_deps.deterministic_socket_factory->AddSocketDataProvider(&spdy_data);
+
+ SSLSocketDataProvider ssl(ASYNC, OK);
+ ssl.SetNextProto(kProtoSPDY3);
+ session_deps.deterministic_socket_factory->AddSSLSocketDataProvider(&ssl);
+ SSLSocketDataProvider ssl2(ASYNC, OK);
+ ssl2.was_npn_negotiated = false;
+ ssl2.protocol_negotiated = kProtoUnknown;
+ session_deps.deterministic_socket_factory->AddSSLSocketDataProvider(&ssl2);
+ SSLSocketDataProvider ssl3(ASYNC, OK);
+ ssl3.was_npn_negotiated = false;
+ ssl3.protocol_negotiated = kProtoUnknown;
+ session_deps.deterministic_socket_factory->AddSSLSocketDataProvider(&ssl3);
+
+ TestCompletionCallback callback;
+
+ scoped_ptr<HttpTransaction> trans(new HttpNetworkTransaction(session));
+ int rv = trans->Start(&request1, callback.callback(), BoundNetLog());
+ EXPECT_EQ(ERR_IO_PENDING, rv);
+ // The first connect and request, each of their responses, and the body.
+ spdy_data.RunFor(5);
+
+ rv = callback.WaitForResult();
+ EXPECT_EQ(OK, rv);
+
+ LoadTimingInfo load_timing_info;
+ EXPECT_TRUE(trans->GetLoadTimingInfo(&load_timing_info));
+ TestLoadTimingNotReused(load_timing_info, CONNECT_TIMING_HAS_SSL_TIMES);
+
+ const HttpResponseInfo* response = trans->GetResponseInfo();
+ ASSERT_TRUE(response != NULL);
+ ASSERT_TRUE(response->headers != NULL);
+ EXPECT_EQ("HTTP/1.1 200 OK", response->headers->GetStatusLine());
+
+ std::string response_data;
+ scoped_refptr<net::IOBuffer> buf(new net::IOBuffer(256));
+ EXPECT_EQ(1, trans->Read(buf, 256, callback.callback()));
+
+ scoped_ptr<HttpTransaction> trans2(new HttpNetworkTransaction(session));
+ rv = trans2->Start(&request2, callback.callback(), BoundNetLog());
+ EXPECT_EQ(ERR_IO_PENDING, rv);
+
+ // The second connect and request, each of their responses, and the body.
+ spdy_data.RunFor(5);
+ rv = callback.WaitForResult();
+ EXPECT_EQ(OK, rv);
+
+ LoadTimingInfo load_timing_info2;
+ EXPECT_TRUE(trans2->GetLoadTimingInfo(&load_timing_info2));
+ // Even though the SPDY connection is reused, a new tunnelled connection has
+ // to be created, so the socket's load timing looks like a fresh connection.
+ TestLoadTimingNotReused(load_timing_info2, CONNECT_TIMING_HAS_SSL_TIMES);
+
+ // The requests should have different IDs, since they each are using their own
+ // separate stream.
+ EXPECT_NE(load_timing_info.socket_log_id, load_timing_info2.socket_log_id);
+
+ EXPECT_EQ(2, trans2->Read(buf, 256, callback.callback()));
+}
+
+// Test load timing in the case of two HTTPS (non-SPDY) requests through a SPDY
+// HTTPS Proxy to the same server.
+TEST_F(HttpNetworkTransactionSpdy3Test,
+ HttpsProxySpdyConnectHttpsLoadTimingTwoRequestsSameServer) {
+ // Configure against https proxy server "proxy:70".
+ SpdySessionDependencies session_deps(ProxyService::CreateFixed(
+ "https://proxy:70"));
+ CapturingBoundNetLog log;
+ session_deps.net_log = log.bound().net_log();
+ scoped_refptr<HttpNetworkSession> session(
+ SpdySessionDependencies::SpdyCreateSessionDeterministic(&session_deps));
+
+ HttpRequestInfo request1;
+ request1.method = "GET";
+ request1.url = GURL("https://www.google.com/");
+ request1.load_flags = 0;
+
+ HttpRequestInfo request2;
+ request2.method = "GET";
+ request2.url = GURL("https://www.google.com/2");
+ request2.load_flags = 0;
+
+ // CONNECT to www.google.com:443 via SPDY.
+ scoped_ptr<SpdyFrame> connect1(ConstructSpdyConnect(NULL, 0, 1));
+ scoped_ptr<SpdyFrame> conn_resp1(ConstructSpdyGetSynReply(NULL, 0, 1));
+
+ // Fetch https://www.google.com/ via HTTP.
+ const char get1[] = "GET / HTTP/1.1\r\n"
+ "Host: www.google.com\r\n"
+ "Connection: keep-alive\r\n\r\n";
+ scoped_ptr<SpdyFrame> wrapped_get1(
+ ConstructSpdyBodyFrame(1, get1, strlen(get1), false));
+ const char resp1[] = "HTTP/1.1 200 OK\r\n"
+ "Content-Length: 1\r\n\r\n";
+ scoped_ptr<SpdyFrame> wrapped_get_resp1(
+ ConstructSpdyBodyFrame(1, resp1, strlen(resp1), false));
+ scoped_ptr<SpdyFrame> wrapped_body1(ConstructSpdyBodyFrame(1, "1", 1, false));
+ scoped_ptr<SpdyFrame> window_update(
+ ConstructSpdyWindowUpdate(1, wrapped_get_resp1->length()));
+
+ // Fetch https://www.google.com/2 via HTTP.
+ const char get2[] = "GET /2 HTTP/1.1\r\n"
+ "Host: www.google.com\r\n"
+ "Connection: keep-alive\r\n\r\n";
+ scoped_ptr<SpdyFrame> wrapped_get2(
+ ConstructSpdyBodyFrame(1, get2, strlen(get2), false));
+ const char resp2[] = "HTTP/1.1 200 OK\r\n"
+ "Content-Length: 2\r\n\r\n";
+ scoped_ptr<SpdyFrame> wrapped_get_resp2(
+ ConstructSpdyBodyFrame(1, resp2, strlen(resp2), false));
+ scoped_ptr<SpdyFrame> wrapped_body2(
+ ConstructSpdyBodyFrame(1, "22", 2, false));
+
+ MockWrite spdy_writes[] = {
+ CreateMockWrite(*connect1, 0),
+ CreateMockWrite(*wrapped_get1, 2),
+ CreateMockWrite(*wrapped_get2, 5),
+ };
+
+ MockRead spdy_reads[] = {
+ CreateMockRead(*conn_resp1, 1, ASYNC),
+ CreateMockRead(*wrapped_get_resp1, 3, ASYNC),
+ CreateMockRead(*wrapped_body1, 4, ASYNC),
+ CreateMockRead(*wrapped_get_resp2, 6, ASYNC),
+ CreateMockRead(*wrapped_body2, 7, ASYNC),
+ MockRead(ASYNC, 0, 8),
+ };
+
+ DeterministicSocketData spdy_data(
+ spdy_reads, arraysize(spdy_reads),
+ spdy_writes, arraysize(spdy_writes));
+ session_deps.deterministic_socket_factory->AddSocketDataProvider(&spdy_data);
+
+ SSLSocketDataProvider ssl(ASYNC, OK);
+ ssl.SetNextProto(kProtoSPDY3);
+ session_deps.deterministic_socket_factory->AddSSLSocketDataProvider(&ssl);
+ SSLSocketDataProvider ssl2(ASYNC, OK);
+ ssl2.was_npn_negotiated = false;
+ ssl2.protocol_negotiated = kProtoUnknown;
+ session_deps.deterministic_socket_factory->AddSSLSocketDataProvider(&ssl2);
+
+ TestCompletionCallback callback;
+
+ scoped_ptr<HttpTransaction> trans(new HttpNetworkTransaction(session));
+ int rv = trans->Start(&request1, callback.callback(), BoundNetLog());
+ EXPECT_EQ(ERR_IO_PENDING, rv);
+ // The first connect and request, each of their responses, and the body.
+ spdy_data.RunFor(5);
+
+ rv = callback.WaitForResult();
+ EXPECT_EQ(OK, rv);
+
+ LoadTimingInfo load_timing_info;
+ EXPECT_TRUE(trans->GetLoadTimingInfo(&load_timing_info));
+ TestLoadTimingNotReused(load_timing_info, CONNECT_TIMING_HAS_SSL_TIMES);
+
+ const HttpResponseInfo* response = trans->GetResponseInfo();
+ ASSERT_TRUE(response != NULL);
+ ASSERT_TRUE(response->headers != NULL);
+ EXPECT_EQ("HTTP/1.1 200 OK", response->headers->GetStatusLine());
+
+ std::string response_data;
+ scoped_refptr<net::IOBuffer> buf(new net::IOBuffer(256));
+ EXPECT_EQ(1, trans->Read(buf, 256, callback.callback()));
+ // Delete the first request, so the second one can reuse the socket.
+ trans.reset();
+
+ scoped_ptr<HttpTransaction> trans2(new HttpNetworkTransaction(session));
+ rv = trans2->Start(&request2, callback.callback(), BoundNetLog());
+ EXPECT_EQ(ERR_IO_PENDING, rv);
+
+ // The second request, response, and body. There should not be a second
+ // connect.
+ spdy_data.RunFor(3);
+ rv = callback.WaitForResult();
+ EXPECT_EQ(OK, rv);
+
+ LoadTimingInfo load_timing_info2;
+ EXPECT_TRUE(trans2->GetLoadTimingInfo(&load_timing_info2));
+ TestLoadTimingReused(load_timing_info2);
+
+ // The requests should have the same ID.
+ EXPECT_EQ(load_timing_info.socket_log_id, load_timing_info2.socket_log_id);
+
+ EXPECT_EQ(2, trans2->Read(buf, 256, callback.callback()));
+}
+
+// Test load timing in the case of of two HTTP requests through a SPDY HTTPS
+// Proxy to different servers.
+TEST_F(HttpNetworkTransactionSpdy3Test,
+ HttpsProxySpdyLoadTimingTwoHttpRequests) {
+ const char* const url1 = "http://www.google.com/";
+ const char* const url2 = "http://news.google.com/";
+
+ // Configure against https proxy server "proxy:70".
+ SpdySessionDependencies session_deps(ProxyService::CreateFixed(
+ "https://proxy:70"));
+ CapturingBoundNetLog log;
+ session_deps.net_log = log.bound().net_log();
+ scoped_refptr<HttpNetworkSession> session(
+ SpdySessionDependencies::SpdyCreateSessionDeterministic(&session_deps));
+
+ HttpRequestInfo request1;
+ request1.method = "GET";
+ request1.url = GURL(url1);
+ request1.load_flags = 0;
+
+ HttpRequestInfo request2;
+ request2.method = "GET";
+ request2.url = GURL(url2);
+ request2.load_flags = 0;
+
+ scoped_ptr<SpdyFrame> get1(ConstructSpdyGet(url1, false, 1, LOWEST));
+ scoped_ptr<SpdyFrame> get_resp1(ConstructSpdyGetSynReply(NULL, 0, 1));
+ scoped_ptr<SpdyFrame> body1(ConstructSpdyBodyFrame(1, "1", 1, true));
+
+ // http://news.google.com/
+ scoped_ptr<SpdyFrame> get2(ConstructSpdyGet(url2, false, 3, LOWEST));
+ scoped_ptr<SpdyFrame> get_resp2(ConstructSpdyGetSynReply(NULL, 0, 3));
+ scoped_ptr<SpdyFrame> body2(ConstructSpdyBodyFrame(3, "22", 2, true));
+
+ MockWrite spdy_writes[] = {
+ CreateMockWrite(*get1, 0),
+ CreateMockWrite(*get2, 3),
+ };
+
+ MockRead spdy_reads[] = {
+ CreateMockRead(*get_resp1, 1, ASYNC),
+ CreateMockRead(*body1, 2, ASYNC),
+ CreateMockRead(*get_resp2, 4, ASYNC),
+ CreateMockRead(*body2, 5, ASYNC),
+ MockRead(ASYNC, 0, 6),
+ };
+
+ DeterministicSocketData spdy_data(
+ spdy_reads, arraysize(spdy_reads),
+ spdy_writes, arraysize(spdy_writes));
+ session_deps.deterministic_socket_factory->AddSocketDataProvider(&spdy_data);
+
+ SSLSocketDataProvider ssl(ASYNC, OK);
+ ssl.SetNextProto(kProtoSPDY3);
+ session_deps.deterministic_socket_factory->AddSSLSocketDataProvider(&ssl);
+
+ TestCompletionCallback callback;
+
+ scoped_ptr<HttpTransaction> trans(new HttpNetworkTransaction(session));
+ int rv = trans->Start(&request1, callback.callback(), BoundNetLog());
+ EXPECT_EQ(ERR_IO_PENDING, rv);
+ spdy_data.RunFor(2);
+
+ rv = callback.WaitForResult();
+ EXPECT_EQ(OK, rv);
+
+ LoadTimingInfo load_timing_info;
+ EXPECT_TRUE(trans->GetLoadTimingInfo(&load_timing_info));
+ TestLoadTimingNotReused(load_timing_info,
+ CONNECT_TIMING_HAS_CONNECT_TIMES_ONLY);
+
+ const HttpResponseInfo* response = trans->GetResponseInfo();
+ ASSERT_TRUE(response != NULL);
+ ASSERT_TRUE(response->headers != NULL);
+ EXPECT_EQ("HTTP/1.1 200 OK", response->headers->GetStatusLine());
+
+ std::string response_data;
+ scoped_refptr<net::IOBuffer> buf(new net::IOBuffer(256));
+ EXPECT_EQ(ERR_IO_PENDING, trans->Read(buf, 256, callback.callback()));
+ spdy_data.RunFor(1);
+ EXPECT_EQ(1, callback.WaitForResult());
+ // Delete the first request, so the second one can reuse the socket.
+ trans.reset();
+
+ scoped_ptr<HttpTransaction> trans2(new HttpNetworkTransaction(session));
+ rv = trans2->Start(&request2, callback.callback(), BoundNetLog());
+ EXPECT_EQ(ERR_IO_PENDING, rv);
+
+ spdy_data.RunFor(2);
+ rv = callback.WaitForResult();
+ EXPECT_EQ(OK, rv);
+
+ LoadTimingInfo load_timing_info2;
+ EXPECT_TRUE(trans2->GetLoadTimingInfo(&load_timing_info2));
+ TestLoadTimingReused(load_timing_info2);
+
+ // The requests should have the same ID.
+ EXPECT_EQ(load_timing_info.socket_log_id, load_timing_info2.socket_log_id);
+
+ EXPECT_EQ(ERR_IO_PENDING, trans2->Read(buf, 256, callback.callback()));
+ spdy_data.RunFor(1);
+ EXPECT_EQ(2, callback.WaitForResult());
+}
+
// Test the challenge-response-retry sequence through an HTTPS Proxy
TEST_F(HttpNetworkTransactionSpdy3Test, HttpsProxyAuthRetry) {
HttpRequestInfo request;
@@ -10461,8 +10844,10 @@ TEST_F(HttpNetworkTransactionSpdy3Test, DoNotUseSpdySessionForHttpOverTunnel) {
MockConnect connect_data1(ASYNC, OK);
data1.set_connect_data(connect_data1);
- SpdySessionDependencies session_deps(ProxyService::CreateFixed(
- "https://proxy:70"));
+ SpdySessionDependencies session_deps(
+ ProxyService::CreateFixedFromPacResult("HTTPS proxy:70"));
+ CapturingNetLog log;
+ session_deps.net_log = &log;
SSLSocketDataProvider ssl1(ASYNC, OK); // to the proxy
ssl1.SetNextProto(kProtoSPDY3);
session_deps.deterministic_socket_factory->AddSSLSocketDataProvider(&ssl1);
@@ -10490,6 +10875,11 @@ TEST_F(HttpNetworkTransactionSpdy3Test, DoNotUseSpdySessionForHttpOverTunnel) {
EXPECT_EQ(OK, callback1.WaitForResult());
EXPECT_TRUE(trans1.GetResponseInfo()->was_fetched_via_spdy);
+ LoadTimingInfo load_timing_info1;
+ EXPECT_TRUE(trans1.GetLoadTimingInfo(&load_timing_info1));
+ TestLoadTimingNotReusedWithPac(load_timing_info1,
+ CONNECT_TIMING_HAS_SSL_TIMES);
+
// Now, start the HTTP request
HttpRequestInfo request2;
request2.method = "GET";
@@ -10505,6 +10895,13 @@ TEST_F(HttpNetworkTransactionSpdy3Test, DoNotUseSpdySessionForHttpOverTunnel) {
EXPECT_EQ(OK, callback2.WaitForResult());
EXPECT_TRUE(trans2.GetResponseInfo()->was_fetched_via_spdy);
+
+ // HTTP requests over a SPDY session should have a different connection
+ // socket_log_id than requests over a tunnel.
+ LoadTimingInfo load_timing_info2;
+ EXPECT_TRUE(trans2.GetLoadTimingInfo(&load_timing_info2));
+ TestLoadTimingReusedWithPac(load_timing_info2);
+ EXPECT_NE(load_timing_info1.socket_log_id, load_timing_info2.socket_log_id);
}
TEST_F(HttpNetworkTransactionSpdy3Test, UseSpdySessionForHttpWhenForced) {
diff --git a/net/http/http_proxy_client_socket_pool.cc b/net/http/http_proxy_client_socket_pool.cc
index e612cd9..0b559af 100644
--- a/net/http/http_proxy_client_socket_pool.cc
+++ b/net/http/http_proxy_client_socket_pool.cc
@@ -330,6 +330,7 @@ int HttpProxyConnectJob::DoSpdyProxyCreateStreamComplete(int result) {
params_->endpoint(),
params_->request_url(),
params_->destination().host_port_pair(),
+ net_log(),
params_->http_auth_cache(),
params_->http_auth_handler_factory()));
return transport_socket_->Connect(callback_);
diff --git a/net/socket/socket_test_util.cc b/net/socket/socket_test_util.cc
index d7111cc..6d38f8f 100644
--- a/net/socket/socket_test_util.cc
+++ b/net/socket/socket_test_util.cc
@@ -693,10 +693,10 @@ void MockClientSocketFactory::ClearSSLSessionCache() {
const char MockClientSocket::kTlsUnique[] = "MOCK_TLSUNIQ";
-MockClientSocket::MockClientSocket(net::NetLog* net_log)
+MockClientSocket::MockClientSocket(const BoundNetLog& net_log)
: ALLOW_THIS_IN_INITIALIZER_LIST(weak_factory_(this)),
connected_(false),
- net_log_(BoundNetLog::Make(net_log, net::NetLog::SOURCE_NONE)) {
+ net_log_(net_log) {
IPAddressNumber ip;
CHECK(ParseIPLiteralToNumber("192.0.2.33", &ip));
peer_addr_ = IPEndPoint(ip, 0);
@@ -787,7 +787,7 @@ void MockClientSocket::RunCallback(const net::CompletionCallback& callback,
MockTCPClientSocket::MockTCPClientSocket(const AddressList& addresses,
net::NetLog* net_log,
SocketDataProvider* data)
- : MockClientSocket(net_log),
+ : MockClientSocket(BoundNetLog::Make(net_log, net::NetLog::SOURCE_NONE)),
addresses_(addresses),
data_(data),
read_offset_(0),
@@ -982,7 +982,7 @@ int MockTCPClientSocket::CompleteRead() {
DeterministicMockTCPClientSocket::DeterministicMockTCPClientSocket(
net::NetLog* net_log, DeterministicSocketData* data)
- : MockClientSocket(net_log),
+ : MockClientSocket(BoundNetLog::Make(net_log, net::NetLog::SOURCE_NONE)),
write_pending_(false),
write_result_(0),
read_data_(),
@@ -1144,7 +1144,10 @@ MockSSLClientSocket::MockSSLClientSocket(
const HostPortPair& host_port_pair,
const SSLConfig& ssl_config,
SSLSocketDataProvider* data)
- : MockClientSocket(transport_socket->socket()->NetLog().net_log()),
+ : MockClientSocket(
+ // Have to use the right BoundNetLog for LoadTimingInfo regression
+ // tests.
+ transport_socket->socket()->NetLog()),
transport_(transport_socket),
data_(data),
is_npn_state_set_(false),
diff --git a/net/socket/socket_test_util.h b/net/socket/socket_test_util.h
index febd22a..7b79bda 100644
--- a/net/socket/socket_test_util.h
+++ b/net/socket/socket_test_util.h
@@ -591,8 +591,9 @@ class MockClientSocket : public SSLClientSocket {
// Value returned by GetTLSUniqueChannelBinding().
static const char kTlsUnique[];
- // TODO(ajwong): Why do we need net::NetLog?
- explicit MockClientSocket(net::NetLog* net_log);
+ // The BoundNetLog is needed to test LoadTimingInfo, which uses NetLog IDs as
+ // unique socket IDs.
+ explicit MockClientSocket(const BoundNetLog& net_log);
// Socket implementation.
virtual int Read(IOBuffer* buf, int buf_len,
diff --git a/net/spdy/spdy_proxy_client_socket.cc b/net/spdy/spdy_proxy_client_socket.cc
index 0d62ce7..ade487c 100644
--- a/net/spdy/spdy_proxy_client_socket.cc
+++ b/net/spdy/spdy_proxy_client_socket.cc
@@ -10,6 +10,7 @@
#include "base/bind_helpers.h"
#include "base/logging.h"
#include "base/string_util.h"
+#include "base/values.h"
#include "googleurl/src/gurl.h"
#include "net/base/auth.h"
#include "net/base/io_buffer.h"
@@ -27,6 +28,7 @@ SpdyProxyClientSocket::SpdyProxyClientSocket(
const HostPortPair& endpoint,
const GURL& url,
const HostPortPair& proxy_server,
+ const BoundNetLog& source_net_log,
HttpAuthCache* auth_cache,
HttpAuthHandlerFactory* auth_handler_factory)
: next_state_(STATE_DISCONNECTED),
@@ -41,18 +43,27 @@ SpdyProxyClientSocket::SpdyProxyClientSocket(
write_buffer_len_(0),
write_bytes_outstanding_(0),
ALLOW_THIS_IN_INITIALIZER_LIST(weak_factory_(this)),
- net_log_(spdy_stream->net_log()) {
+ net_log_(BoundNetLog::Make(spdy_stream->net_log().net_log(),
+ NetLog::SOURCE_PROXY_CLIENT_SOCKET)) {
request_.method = "CONNECT";
request_.url = url;
if (!user_agent.empty())
request_.extra_headers.SetHeader(HttpRequestHeaders::kUserAgent,
user_agent);
+
+ net_log_.BeginEvent(NetLog::TYPE_SOCKET_ALIVE,
+ source_net_log.source().ToEventParametersCallback());
+ net_log_.AddEvent(
+ NetLog::TYPE_SPDY_PROXY_CLIENT_SESSION,
+ spdy_stream->net_log().source().ToEventParametersCallback());
+
spdy_stream_->SetDelegate(this);
was_ever_used_ = spdy_stream_->WasEverUsed();
}
SpdyProxyClientSocket::~SpdyProxyClientSocket() {
Disconnect();
+ net_log_.EndEvent(NetLog::TYPE_SOCKET_ALIVE);
}
const HttpResponseInfo* SpdyProxyClientSocket::GetConnectResponseInfo() const {
@@ -244,6 +255,15 @@ int SpdyProxyClientSocket::Write(IOBuffer* buf, int buf_len,
write_bytes_outstanding_= buf_len;
if (buf_len <= kMaxSpdyFrameChunkSize) {
int rv = spdy_stream_->WriteStreamData(buf, buf_len, DATA_FLAG_NONE);
+
+ // If there's an error, log the error. Otherwise, log the number of bytes
+ // regardless of whether or not they were actually written.
+ if (rv < 0 && rv != ERR_IO_PENDING) {
+ net_log_.AddByteTransferEvent(NetLog::TYPE_SOCKET_BYTES_SENT, rv, NULL);
+ } else {
+ net_log_.AddByteTransferEvent(NetLog::TYPE_SOCKET_BYTES_SENT,
+ buf_len, buf->data());
+ }
if (rv == ERR_IO_PENDING) {
write_callback_ = callback;
write_buffer_len_ = buf_len;
@@ -258,6 +278,16 @@ int SpdyProxyClientSocket::Write(IOBuffer* buf, int buf_len,
scoped_refptr<DrainableIOBuffer> iobuf(new DrainableIOBuffer(buf, i + len));
iobuf->SetOffset(i);
int rv = spdy_stream_->WriteStreamData(iobuf, len, DATA_FLAG_NONE);
+
+ // If there's an error, log the error. Otherwise, log the number of bytes
+ // regardless of whether or not they were actually written.
+ if (rv < 0 && rv != ERR_IO_PENDING) {
+ net_log_.AddByteTransferEvent(NetLog::TYPE_SOCKET_BYTES_SENT, rv, NULL);
+ } else {
+ net_log_.AddByteTransferEvent(NetLog::TYPE_SOCKET_BYTES_SENT,
+ len, buf->data());
+ }
+
if (rv > 0) {
write_bytes_outstanding_ -= rv;
} else if (rv != ERR_IO_PENDING) {
@@ -330,14 +360,19 @@ int SpdyProxyClientSocket::DoLoop(int last_io_result) {
break;
case STATE_SEND_REQUEST:
DCHECK_EQ(OK, rv);
- net_log_.BeginEvent(
- NetLog::TYPE_HTTP_TRANSACTION_TUNNEL_SEND_REQUEST);
+ net_log_.BeginEvent(NetLog::TYPE_HTTP_TRANSACTION_TUNNEL_SEND_REQUEST);
rv = DoSendRequest();
break;
case STATE_SEND_REQUEST_COMPLETE:
net_log_.EndEventWithNetErrorCode(
NetLog::TYPE_HTTP_TRANSACTION_TUNNEL_SEND_REQUEST, rv);
rv = DoSendRequestComplete(rv);
+ if (rv >= 0 || rv == ERR_IO_PENDING) {
+ // Emit extra event so can use the same events as
+ // HttpProxyClientSocket.
+ net_log_.BeginEvent(
+ NetLog::TYPE_HTTP_TRANSACTION_TUNNEL_READ_HEADERS);
+ }
break;
case STATE_READ_REPLY_COMPLETE:
rv = DoReadReplyComplete(rv);
@@ -519,6 +554,8 @@ void SpdyProxyClientSocket::OnHeadersSent() {
// Called when data is received.
int SpdyProxyClientSocket::OnDataReceived(const char* data, int length) {
+ net_log_.AddByteTransferEvent(NetLog::TYPE_SOCKET_BYTES_RECEIVED,
+ length, data);
if (length > 0) {
// Save the received data.
scoped_refptr<IOBuffer> io_buffer(new IOBuffer(length));
diff --git a/net/spdy/spdy_proxy_client_socket.h b/net/spdy/spdy_proxy_client_socket.h
index a5da281..596e62b 100644
--- a/net/spdy/spdy_proxy_client_socket.h
+++ b/net/spdy/spdy_proxy_client_socket.h
@@ -46,6 +46,7 @@ class NET_EXPORT_PRIVATE SpdyProxyClientSocket : public ProxyClientSocket,
const HostPortPair& endpoint,
const GURL& url,
const HostPortPair& proxy_server,
+ const BoundNetLog& source_net_log,
HttpAuthCache* auth_cache,
HttpAuthHandlerFactory* auth_handler_factory);
diff --git a/net/spdy/spdy_proxy_client_socket_spdy2_unittest.cc b/net/spdy/spdy_proxy_client_socket_spdy2_unittest.cc
index 5216e4a..0b6a191 100644
--- a/net/spdy/spdy_proxy_client_socket_spdy2_unittest.cc
+++ b/net/spdy/spdy_proxy_client_socket_spdy2_unittest.cc
@@ -8,6 +8,7 @@
#include "base/bind_helpers.h"
#include "base/utf_string_conversions.h"
#include "net/base/address_list.h"
+#include "net/base/capturing_net_log.h"
#include "net/base/net_log.h"
#include "net/base/net_log_unittest.h"
#include "net/base/mock_host_resolver.h"
@@ -110,6 +111,7 @@ class SpdyProxyClientSocketSpdy2Test : public PlatformTest {
TestCompletionCallback read_callback_;
TestCompletionCallback write_callback_;
scoped_ptr<DeterministicSocketData> data_;
+ CapturingBoundNetLog net_log_;
private:
scoped_refptr<HttpNetworkSession> session_;
@@ -152,6 +154,7 @@ SpdyProxyClientSocketSpdy2Test::SpdyProxyClientSocketSpdy2Test()
false,
false,
OnHostResolutionCallback())) {
+ session_deps_.net_log = net_log_.bound().net_log();
}
void SpdyProxyClientSocketSpdy2Test::TearDown() {
@@ -165,9 +168,9 @@ void SpdyProxyClientSocketSpdy2Test::TearDown() {
}
void SpdyProxyClientSocketSpdy2Test::Initialize(MockRead* reads,
- size_t reads_count,
- MockWrite* writes,
- size_t writes_count) {
+ size_t reads_count,
+ MockWrite* writes,
+ size_t writes_count) {
data_.reset(new DeterministicSocketData(reads, reads_count,
writes, writes_count));
data_->set_connect_data(connect_data_);
@@ -180,32 +183,33 @@ void SpdyProxyClientSocketSpdy2Test::Initialize(MockRead* reads,
session_ = SpdySessionDependencies::SpdyCreateSessionDeterministic(
&session_deps_);
- // Creates a new spdy session
+ // Creates a new spdy session.
spdy_session_ =
session_->spdy_session_pool()->Get(endpoint_host_port_proxy_pair_,
- BoundNetLog());
+ net_log_.bound());
- // Perform the TCP connect
+ // Perform the TCP connect.
scoped_ptr<ClientSocketHandle> connection(new ClientSocketHandle);
EXPECT_EQ(OK,
connection->Init(endpoint_host_port_pair_.ToString(),
transport_params_, LOWEST, CompletionCallback(),
session_->GetTransportSocketPool(
HttpNetworkSession::NORMAL_SOCKET_POOL),
- BoundNetLog()));
+ net_log_.bound()));
spdy_session_->InitializeWithSocket(connection.release(), false, OK);
- // Create the SPDY Stream
+ // Create the SPDY Stream.
ASSERT_EQ(
OK,
- spdy_session_->CreateStream(url_, LOWEST, &spdy_stream_, BoundNetLog(),
+ spdy_session_->CreateStream(url_, LOWEST, &spdy_stream_, net_log_.bound(),
CompletionCallback()));
- // Create the SpdyProxyClientSocket
+ // Create the SpdyProxyClientSocket.
sock_.reset(
new SpdyProxyClientSocket(spdy_stream_, user_agent_,
endpoint_host_port_pair_, url_,
- proxy_host_port_, session_->http_auth_cache(),
+ proxy_host_port_, net_log_.bound(),
+ session_->http_auth_cache(),
session_->http_auth_handler_factory()));
}
@@ -1286,6 +1290,61 @@ TEST_F(SpdyProxyClientSocketSpdy2Test, RstWithReadAndWritePending) {
EXPECT_TRUE(write_callback_.have_result());
}
+// Makes sure the proxy client socket's source gets the expected NetLog events
+// and only the expected NetLog events (No SpdySession events).
+TEST_F(SpdyProxyClientSocketSpdy2Test, NetLog) {
+ scoped_ptr<SpdyFrame> conn(ConstructConnectRequestFrame());
+ MockWrite writes[] = {
+ CreateMockWrite(*conn, 0, SYNCHRONOUS),
+ };
+
+ scoped_ptr<SpdyFrame> resp(ConstructConnectReplyFrame());
+ scoped_ptr<SpdyFrame> msg1(ConstructBodyFrame(kMsg1, kLen1));
+ MockRead reads[] = {
+ CreateMockRead(*resp, 1, ASYNC),
+ CreateMockRead(*msg1, 2, ASYNC),
+ MockRead(ASYNC, 0, 3), // EOF
+ };
+
+ Initialize(reads, arraysize(reads), writes, arraysize(writes));
+
+ AssertConnectSucceeds();
+
+ Run(1); // SpdySession consumes the next read and sends it to
+ // sock_ to be buffered.
+ AssertSyncReadEquals(kMsg1, kLen1);
+
+ NetLog::Source sock_source = sock_->NetLog().source();
+ sock_.reset();
+
+ CapturingNetLog::CapturedEntryList entry_list;
+ net_log_.GetEntriesForSource(sock_source, &entry_list);
+
+ ASSERT_EQ(entry_list.size(), 10u);
+ EXPECT_TRUE(LogContainsBeginEvent(entry_list, 0, NetLog::TYPE_SOCKET_ALIVE));
+ EXPECT_TRUE(LogContainsEvent(entry_list, 1,
+ NetLog::TYPE_SPDY_PROXY_CLIENT_SESSION,
+ NetLog::PHASE_NONE));
+ EXPECT_TRUE(LogContainsBeginEvent(entry_list, 2,
+ NetLog::TYPE_HTTP_TRANSACTION_TUNNEL_SEND_REQUEST));
+ EXPECT_TRUE(LogContainsEvent(entry_list, 3,
+ NetLog::TYPE_HTTP_TRANSACTION_SEND_TUNNEL_HEADERS,
+ NetLog::PHASE_NONE));
+ EXPECT_TRUE(LogContainsEndEvent(entry_list, 4,
+ NetLog::TYPE_HTTP_TRANSACTION_TUNNEL_SEND_REQUEST));
+ EXPECT_TRUE(LogContainsBeginEvent(entry_list, 5,
+ NetLog::TYPE_HTTP_TRANSACTION_TUNNEL_READ_HEADERS));
+ EXPECT_TRUE(LogContainsEvent(entry_list, 6,
+ NetLog::TYPE_HTTP_TRANSACTION_READ_TUNNEL_RESPONSE_HEADERS,
+ NetLog::PHASE_NONE));
+ EXPECT_TRUE(LogContainsEndEvent(entry_list, 7,
+ NetLog::TYPE_HTTP_TRANSACTION_TUNNEL_READ_HEADERS));
+ EXPECT_TRUE(LogContainsEvent(entry_list, 8,
+ NetLog::TYPE_SOCKET_BYTES_RECEIVED,
+ NetLog::PHASE_NONE));
+ EXPECT_TRUE(LogContainsEndEvent(entry_list, 9, NetLog::TYPE_SOCKET_ALIVE));
+}
+
// CompletionCallback that causes the SpdyProxyClientSocket to be
// deleted when Run is invoked.
class DeleteSockCallback : public TestCompletionCallbackBase {
diff --git a/net/spdy/spdy_proxy_client_socket_spdy3_unittest.cc b/net/spdy/spdy_proxy_client_socket_spdy3_unittest.cc
index 627568f..58a4fdc 100644
--- a/net/spdy/spdy_proxy_client_socket_spdy3_unittest.cc
+++ b/net/spdy/spdy_proxy_client_socket_spdy3_unittest.cc
@@ -8,6 +8,7 @@
#include "base/bind_helpers.h"
#include "base/utf_string_conversions.h"
#include "net/base/address_list.h"
+#include "net/base/capturing_net_log.h"
#include "net/base/net_log.h"
#include "net/base/net_log_unittest.h"
#include "net/base/mock_host_resolver.h"
@@ -110,6 +111,7 @@ class SpdyProxyClientSocketSpdy3Test : public PlatformTest {
TestCompletionCallback read_callback_;
TestCompletionCallback write_callback_;
scoped_ptr<DeterministicSocketData> data_;
+ CapturingBoundNetLog net_log_;
private:
scoped_refptr<HttpNetworkSession> session_;
@@ -152,6 +154,7 @@ SpdyProxyClientSocketSpdy3Test::SpdyProxyClientSocketSpdy3Test()
false,
false,
OnHostResolutionCallback())) {
+ session_deps_.net_log = net_log_.bound().net_log();
}
void SpdyProxyClientSocketSpdy3Test::TearDown() {
@@ -165,9 +168,9 @@ void SpdyProxyClientSocketSpdy3Test::TearDown() {
}
void SpdyProxyClientSocketSpdy3Test::Initialize(MockRead* reads,
- size_t reads_count,
- MockWrite* writes,
- size_t writes_count) {
+ size_t reads_count,
+ MockWrite* writes,
+ size_t writes_count) {
data_.reset(new DeterministicSocketData(reads, reads_count,
writes, writes_count));
data_->set_connect_data(connect_data_);
@@ -180,32 +183,33 @@ void SpdyProxyClientSocketSpdy3Test::Initialize(MockRead* reads,
session_ = SpdySessionDependencies::SpdyCreateSessionDeterministic(
&session_deps_);
- // Creates a new spdy session
+ // Creates a new spdy session.
spdy_session_ =
session_->spdy_session_pool()->Get(endpoint_host_port_proxy_pair_,
- BoundNetLog());
+ net_log_.bound());
- // Perform the TCP connect
+ // Perform the TCP connect.
scoped_ptr<ClientSocketHandle> connection(new ClientSocketHandle);
EXPECT_EQ(OK,
connection->Init(endpoint_host_port_pair_.ToString(),
transport_params_, LOWEST, CompletionCallback(),
session_->GetTransportSocketPool(
HttpNetworkSession::NORMAL_SOCKET_POOL),
- BoundNetLog()));
+ net_log_.bound()));
spdy_session_->InitializeWithSocket(connection.release(), false, OK);
- // Create the SPDY Stream
+ // Create the SPDY Stream.
ASSERT_EQ(
OK,
- spdy_session_->CreateStream(url_, LOWEST, &spdy_stream_, BoundNetLog(),
+ spdy_session_->CreateStream(url_, LOWEST, &spdy_stream_, net_log_.bound(),
CompletionCallback()));
- // Create the SpdyProxyClientSocket
+ // Create the SpdyProxyClientSocket.
sock_.reset(
new SpdyProxyClientSocket(spdy_stream_, user_agent_,
endpoint_host_port_pair_, url_,
- proxy_host_port_, session_->http_auth_cache(),
+ proxy_host_port_, net_log_.bound(),
+ session_->http_auth_cache(),
session_->http_auth_handler_factory()));
}
@@ -1289,6 +1293,61 @@ TEST_F(SpdyProxyClientSocketSpdy3Test, RstWithReadAndWritePending) {
EXPECT_TRUE(write_callback_.have_result());
}
+// Makes sure the proxy client socket's source gets the expected NetLog events
+// and only the expected NetLog events (No SpdySession events).
+TEST_F(SpdyProxyClientSocketSpdy3Test, NetLog) {
+ scoped_ptr<SpdyFrame> conn(ConstructConnectRequestFrame());
+ MockWrite writes[] = {
+ CreateMockWrite(*conn, 0, SYNCHRONOUS),
+ };
+
+ scoped_ptr<SpdyFrame> resp(ConstructConnectReplyFrame());
+ scoped_ptr<SpdyFrame> msg1(ConstructBodyFrame(kMsg1, kLen1));
+ MockRead reads[] = {
+ CreateMockRead(*resp, 1, ASYNC),
+ CreateMockRead(*msg1, 2, ASYNC),
+ MockRead(ASYNC, 0, 3), // EOF
+ };
+
+ Initialize(reads, arraysize(reads), writes, arraysize(writes));
+
+ AssertConnectSucceeds();
+
+ Run(1); // SpdySession consumes the next read and sends it to
+ // sock_ to be buffered.
+ AssertSyncReadEquals(kMsg1, kLen1);
+
+ NetLog::Source sock_source = sock_->NetLog().source();
+ sock_.reset();
+
+ CapturingNetLog::CapturedEntryList entry_list;
+ net_log_.GetEntriesForSource(sock_source, &entry_list);
+
+ ASSERT_EQ(entry_list.size(), 10u);
+ EXPECT_TRUE(LogContainsBeginEvent(entry_list, 0, NetLog::TYPE_SOCKET_ALIVE));
+ EXPECT_TRUE(LogContainsEvent(entry_list, 1,
+ NetLog::TYPE_SPDY_PROXY_CLIENT_SESSION,
+ NetLog::PHASE_NONE));
+ EXPECT_TRUE(LogContainsBeginEvent(entry_list, 2,
+ NetLog::TYPE_HTTP_TRANSACTION_TUNNEL_SEND_REQUEST));
+ EXPECT_TRUE(LogContainsEvent(entry_list, 3,
+ NetLog::TYPE_HTTP_TRANSACTION_SEND_TUNNEL_HEADERS,
+ NetLog::PHASE_NONE));
+ EXPECT_TRUE(LogContainsEndEvent(entry_list, 4,
+ NetLog::TYPE_HTTP_TRANSACTION_TUNNEL_SEND_REQUEST));
+ EXPECT_TRUE(LogContainsBeginEvent(entry_list, 5,
+ NetLog::TYPE_HTTP_TRANSACTION_TUNNEL_READ_HEADERS));
+ EXPECT_TRUE(LogContainsEvent(entry_list, 6,
+ NetLog::TYPE_HTTP_TRANSACTION_READ_TUNNEL_RESPONSE_HEADERS,
+ NetLog::PHASE_NONE));
+ EXPECT_TRUE(LogContainsEndEvent(entry_list, 7,
+ NetLog::TYPE_HTTP_TRANSACTION_TUNNEL_READ_HEADERS));
+ EXPECT_TRUE(LogContainsEvent(entry_list, 8,
+ NetLog::TYPE_SOCKET_BYTES_RECEIVED,
+ NetLog::PHASE_NONE));
+ EXPECT_TRUE(LogContainsEndEvent(entry_list, 9, NetLog::TYPE_SOCKET_ALIVE));
+}
+
// CompletionCallback that causes the SpdyProxyClientSocket to be
// deleted when Run is invoked.
class DeleteSockCallback : public TestCompletionCallbackBase {