SpdySession now sets the following fields in HttpResponseInfo:

request_time 
response_time 
vary_data 

There is also a unit test to exercise the new functionality. 

- Changed CreateSpdyHeadersFromHttpRequest() to use std::string::append()
  rather than std::string::operator+() to append a single '\0' character
  to the string, as the former does nothing.

- Now using SpdyFramer.

- The unit tests now include all server push cases.

BUG=34505
TEST=Run netunittests.exe --gtest_filter=SpdyNetworkTransactionTest.* 

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

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

10 files changed, 1128 insertions, 133 deletions

diff --git a/net/http/http_response_headers.cc b/net/http/http_response_headers.cc
index 82272bb..ec3ec3b 100644
--- a/net/http/http_response_headers.cc
+++ b/net/http/http_response_headers.cc
@@ -464,6 +464,10 @@ bool HttpResponseHeaders::HasHeaderValue(const std::string& name,
   return false;
 }
 
+bool HttpResponseHeaders::HasHeader(const std::string& name) const {
+  return FindHeader(0, name) != std::string::npos;
+}
+
 // Note: this implementation implicitly assumes that line_end points at a valid
 // sentinel character (such as '\0').
 // static
diff --git a/net/http/http_response_headers.h b/net/http/http_response_headers.h
index f6656e3..c66e701 100644
--- a/net/http/http_response_headers.h
+++ b/net/http/http_response_headers.h
@@ -154,6 +154,10 @@ class HttpResponseHeaders
   // Both name and value are compared case insensitively.
   bool HasHeaderValue(const std::string& name, const std::string& value) const;
 
+  // Returns true if the response contains the specified header.
+  // The name is compared case insensitively.
+  bool HasHeader(const std::string& name) const;
+
   // Get the mime type and charset values in lower case form from the headers.
   // Empty strings are returned if the values are not present.
   void GetMimeTypeAndCharset(std::string* mime_type,
diff --git a/net/socket/socket_test_util.cc b/net/socket/socket_test_util.cc
index 8b8153e..4a8311c 100644
--- a/net/socket/socket_test_util.cc
+++ b/net/socket/socket_test_util.cc
@@ -9,6 +9,7 @@
 #include "base/basictypes.h"
 #include "base/compiler_specific.h"
 #include "base/message_loop.h"
+#include "base/time.h"
 #include "net/base/address_family.h"
 #include "net/base/host_resolver_proc.h"
 #include "net/base/ssl_info.h"
@@ -287,6 +288,7 @@ int MockSSLClientSocket::Write(net::IOBuffer* buf, int buf_len,
 
 MockRead StaticSocketDataProvider::GetNextRead() {
   DCHECK(!at_read_eof());
+  reads_[read_index_].time_stamp = base::Time::Now();
   return reads_[read_index_++];
 }
 
@@ -301,6 +303,7 @@ MockWriteResult StaticSocketDataProvider::OnWrite(const std::string& data) {
   // Check that what we are writing matches the expectation.
   // Then give the mocked return value.
   net::MockWrite* w = &writes_[write_index_++];
+  w->time_stamp = base::Time::Now();
   int result = w->result;
   if (w->data) {
     // Note - we can simulate a partial write here.  If the expected data
@@ -321,6 +324,26 @@ MockWriteResult StaticSocketDataProvider::OnWrite(const std::string& data) {
   return MockWriteResult(w->async, result);
 }
 
+const MockRead& StaticSocketDataProvider::PeekRead() const {
+  DCHECK(!at_read_eof());
+  return reads_[read_index_];
+}
+
+const MockWrite& StaticSocketDataProvider::PeekWrite() const {
+  DCHECK(!at_write_eof());
+  return writes_[write_index_];
+}
+
+const MockRead& StaticSocketDataProvider::PeekRead(size_t index) const {
+  DCHECK_LT(index, read_count_);
+  return reads_[index];
+}
+
+const MockWrite& StaticSocketDataProvider::PeekWrite(size_t index) const {
+  DCHECK_LT(index, write_count_);
+  return writes_[index];
+}
+
 void StaticSocketDataProvider::Reset() {
   read_index_ = 0;
   write_index_ = 0;
diff --git a/net/socket/socket_test_util.h b/net/socket/socket_test_util.h
index 2daa901..b42b272 100644
--- a/net/socket/socket_test_util.h
+++ b/net/socket/socket_test_util.h
@@ -50,29 +50,55 @@ struct MockConnect {
 };
 
 struct MockRead {
+  // Flag to indicate that the message loop should be terminated.
+  enum {
+    STOPLOOP = 1 << 31
+  };
+
   // Default
-  MockRead() : async(false), result(0), data(NULL), data_len(0) {}
+  MockRead() : async(false), result(0), data(NULL), data_len(0),
+      sequence_number(0), time_stamp(base::Time::Now()) {}
 
   // Read failure (no data).
   MockRead(bool async, int result) : async(async) , result(result), data(NULL),
-      data_len(0) { }
+      data_len(0), sequence_number(0), time_stamp(base::Time::Now()) { }
+
+  // Read failure (no data), with sequence information.
+  MockRead(bool async, int result, int seq) : async(async) , result(result),
+      data(NULL), data_len(0), sequence_number(seq),
+      time_stamp(base::Time::Now()) { }
 
   // Asynchronous read success (inferred data length).
   explicit MockRead(const char* data) : async(true),  result(0), data(data),
-      data_len(strlen(data)) { }
+      data_len(strlen(data)), sequence_number(0),
+      time_stamp(base::Time::Now()) { }
 
   // Read success (inferred data length).
   MockRead(bool async, const char* data) : async(async), result(0), data(data),
-      data_len(strlen(data)) { }
+      data_len(strlen(data)), sequence_number(0),
+      time_stamp(base::Time::Now()) { }
 
   // Read success.
   MockRead(bool async, const char* data, int data_len) : async(async),
-      result(0), data(data), data_len(data_len) { }
+      result(0), data(data), data_len(data_len), sequence_number(0),
+      time_stamp(base::Time::Now()) { }
+
+  // Read success with sequence information.
+  MockRead(bool async, const char* data, int data_len, int seq) : async(async),
+      result(0), data(data), data_len(data_len), sequence_number(seq),
+      time_stamp(base::Time::Now()) { }
 
   bool async;
   int result;
   const char* data;
   int data_len;
+
+  // For OrderedSocketData in spdy_network_transaction_unittest.cc, which only
+  // allows reads to occur in a particular sequence.  If a read occurs before
+  // the given |sequence_number| is reached, an ERR_IO_PENDING is returned.
+  int sequence_number;      // The sequence number at which a read is allowed
+                            // to occur.
+  base::Time time_stamp;    // The time stamp at which the operation occurred.
 };
 
 // MockWrite uses the same member fields as MockRead, but with different
@@ -139,6 +165,17 @@ class StaticSocketDataProvider : public SocketDataProvider {
   virtual MockWriteResult OnWrite(const std::string& data);
   virtual void Reset();
 
+  // These functions get access to the next available read and write data.
+  const MockRead& PeekRead() const;
+  const MockWrite& PeekWrite() const;
+  // These functions get random access to the read and write data, for timing.
+  const MockRead& PeekRead(size_t index) const;
+  const MockWrite& PeekWrite(size_t index) const;
+  size_t read_index() const { return read_index_; }
+  size_t write_index() const { return write_index_; }
+  size_t read_count() const { return read_count_; }
+  size_t write_count() const { return write_count_; }
+
   bool at_read_eof() const { return read_index_ >= read_count_; }
   bool at_write_eof() const { return write_index_ >= write_count_; }
 
diff --git a/net/spdy/spdy_network_transaction_unittest.cc b/net/spdy/spdy_network_transaction_unittest.cc
index 5b1aa84..412b34e 100644
--- a/net/spdy/spdy_network_transaction_unittest.cc
+++ b/net/spdy/spdy_network_transaction_unittest.cc
@@ -6,6 +6,7 @@
 
 #include "base/basictypes.h"
 #include "base/ref_counted.h"
+#include "base/string_util.h"
 #include "net/base/completion_callback.h"
 #include "net/base/mock_host_resolver.h"
 #include "net/base/net_log_unittest.h"
@@ -17,6 +18,7 @@
 #include "net/http/http_transaction_unittest.h"
 #include "net/proxy/proxy_config_service_fixed.h"
 #include "net/socket/socket_test_util.h"
+#include "net/spdy/spdy_framer.h"
 #include "net/spdy/spdy_protocol.h"
 #include "testing/platform_test.h"
 
@@ -24,6 +26,21 @@
 
 namespace net {
 
+// NOTE: In GCC, on a Mac, this can't be in an anonymous namespace!
+// This struct holds information used to construct spdy control and data frames.
+struct SpdyHeaderInfo {
+  int kind;
+  spdy::SpdyStreamId id;
+  spdy::SpdyStreamId assoc_id;
+  int priority;
+  spdy::SpdyControlFlags control_flags;
+  bool compressed;
+  int status;
+  const char* data;
+  uint32 data_length;
+  spdy::SpdyDataFlags data_flags;
+};
+
 namespace {
 
 // Helper to manage the lifetimes of the dependencies for a
@@ -88,6 +105,90 @@ MockWrite* ChopFrame(const char* data, int length, int num_chunks) {
   return chunks;
 }
 
+inline char AsciifyHigh(char x) {
+  char nybble = static_cast<char>((x >> 4) & 0x0F);
+  return nybble + ((nybble < 0x0A) ? '0' : 'A' - 10);
+}
+
+inline char AsciifyLow(char x) {
+  char nybble = static_cast<char>((x >> 0) & 0x0F);
+  return nybble + ((nybble < 0x0A) ? '0' : 'A' - 10);
+}
+
+inline char Asciify(char x) {
+  if ((x < 0) || !isprint(x))
+    return '.';
+  return x;
+}
+
+void DumpData(const char* data, int data_len) {
+  if (logging::LOG_INFO < logging::GetMinLogLevel())
+    return;
+  DLOG(INFO) << "Length:  " << data_len;
+  const char* pfx = "Data:    ";
+  if (!data || (data_len <= 0)) {
+    DLOG(INFO) << pfx << "<None>";
+  } else {
+    int i;
+    for (i = 0; i <= (data_len - 4); i += 4) {
+      DLOG(INFO) << pfx
+                 << AsciifyHigh(data[i + 0]) << AsciifyLow(data[i + 0])
+                 << AsciifyHigh(data[i + 1]) << AsciifyLow(data[i + 1])
+                 << AsciifyHigh(data[i + 2]) << AsciifyLow(data[i + 2])
+                 << AsciifyHigh(data[i + 3]) << AsciifyLow(data[i + 3])
+                 << "  '"
+                 << Asciify(data[i + 0])
+                 << Asciify(data[i + 1])
+                 << Asciify(data[i + 2])
+                 << Asciify(data[i + 3])
+                 << "'";
+      pfx = "         ";
+    }
+    // Take care of any 'trailing' bytes, if data_len was not a multiple of 4.
+    switch (data_len - i) {
+      case 3:
+        DLOG(INFO) << pfx
+                   << AsciifyHigh(data[i + 0]) << AsciifyLow(data[i + 0])
+                   << AsciifyHigh(data[i + 1]) << AsciifyLow(data[i + 1])
+                   << AsciifyHigh(data[i + 2]) << AsciifyLow(data[i + 2])
+                   << "    '"
+                   << Asciify(data[i + 0])
+                   << Asciify(data[i + 1])
+                   << Asciify(data[i + 2])
+                   << " '";
+        break;
+      case 2:
+        DLOG(INFO) << pfx
+                   << AsciifyHigh(data[i + 0]) << AsciifyLow(data[i + 0])
+                   << AsciifyHigh(data[i + 1]) << AsciifyLow(data[i + 1])
+                   << "      '"
+                   << Asciify(data[i + 0])
+                   << Asciify(data[i + 1])
+                   << "  '";
+        break;
+      case 1:
+        DLOG(INFO) << pfx
+                   << AsciifyHigh(data[i + 0]) << AsciifyLow(data[i + 0])
+                   << "        '"
+                   << Asciify(data[i + 0])
+                   << "   '";
+        break;
+    }
+  }
+}
+
+void DumpMockRead(const MockRead& r) {
+  if (logging::LOG_INFO < logging::GetMinLogLevel())
+    return;
+  DLOG(INFO) << "Async:   " << r.async;
+  DLOG(INFO) << "Result:  " << r.result;
+  DumpData(r.data, r.data_len);
+  const char* stop = (r.sequence_number & MockRead::STOPLOOP) ? " (STOP)" : "";
+  DLOG(INFO) << "Stage:   " << (r.sequence_number & ~MockRead::STOPLOOP)
+             << stop;
+  DLOG(INFO) << "Time:    " << r.time_stamp.ToInternalValue();
+}
+
 // ----------------------------------------------------------------------------
 
 static const unsigned char kGetSyn[] = {
@@ -95,7 +196,7 @@ static const unsigned char kGetSyn[] = {
   0x01, 0x00, 0x00, 0x49,                                        // FIN, len
   0x00, 0x00, 0x00, 0x01,                                        // stream id
   0x00, 0x00, 0x00, 0x00,                                        // associated
-  0xc0, 0x00, 0x00, 0x03,                                        // 4 headers
+  0xc0, 0x00, 0x00, 0x03,                                        // 3 headers
   0x00, 0x06, 'm', 'e', 't', 'h', 'o', 'd',
   0x00, 0x03, 'G', 'E', 'T',
   0x00, 0x03, 'u', 'r', 'l',
@@ -185,6 +286,292 @@ static const unsigned char kPostBodyFrame[] = {
   'h', 'e', 'l', 'l', 'o', '!',                                  // "hello"
 };
 
+// Adds headers and values to a map.
+// |extra_headers| is an array of { name, value } pairs, arranged as strings
+// where the even entries are the header names, and the odd entries are the
+// header values.
+// |headers| gets filled in from |extra_headers|.
+void AppendHeadersToSpdyFrame(const char* const extra_headers[],
+                              int extra_header_count,
+                              spdy::SpdyHeaderBlock* headers) {
+  std::string this_header;
+  std::string this_value;
+  // Sanity check: Non-NULL header list.
+  DCHECK(NULL != extra_headers) << "NULL header value pair list";
+  // Sanity check: Non-NULL header map.
+  DCHECK(NULL != headers) << "NULL header map";
+  // Copy in the headers.
+  for (int i = 0; i < extra_header_count; i++) {
+    // Sanity check: Non-empty header.
+    DCHECK_NE('\0', *extra_headers[i * 2]) << "Empty header value pair";
+    this_header = extra_headers[i * 2];
+    std::string::size_type header_len = this_header.length();
+    if (!header_len)
+      continue;
+    this_value = extra_headers[1 + (i * 2)];
+    std::string new_value;
+    if (headers->find(this_header) != headers->end()) {
+      // More than one entry in the header.
+      // Don't add the header again, just the append to the value,
+      // separated by a NULL character.
+
+      // Adjust the value.
+      new_value = (*headers)[this_header];
+      // Put in a NULL separator.
+      new_value.append(1, '\0');
+      // Append the new value.
+      new_value += this_value;
+    } else {
+      // Not a duplicate, just write the value.
+      new_value = this_value;
+    }
+    (*headers)[this_header] = new_value;
+  }
+}
+
+// Writes |str| of the given |len| to the buffer pointed to by |buffer_handle|.
+// Uses a template so buffer_handle can be a char* or an unsigned char*.
+// Updates the |*buffer_handle| pointer by |len|
+// Returns the number of bytes written into *|buffer_handle|
+template<class T>
+int AppendToBuffer(const void* str,
+                   int len,
+                   T** buffer_handle,
+                   int* buffer_len_remaining) {
+  if (len <= 0)
+    return 0;
+  DCHECK(NULL != buffer_handle) << "NULL buffer handle";
+  DCHECK(NULL != *buffer_handle) << "NULL pointer";
+  DCHECK(NULL != buffer_len_remaining)
+      << "NULL buffer remainder length pointer";
+  DCHECK_GE(*buffer_len_remaining, len) << "Insufficient buffer size";
+  memcpy(*buffer_handle, str, len);
+  *buffer_handle += len;
+  *buffer_len_remaining -= len;
+  return len;
+}
+
+// Writes |val| to a location of size |len|, in big-endian format.
+// in the buffer pointed to by |buffer_handle|.
+// Updates the |*buffer_handle| pointer by |len|
+// Returns the number of bytes written
+int AppendToBuffer(int val,
+                   int len,
+                   unsigned char** buffer_handle,
+                   int* buffer_len_remaining) {
+  if (len <= 0)
+    return 0;
+  DCHECK((size_t) len <= sizeof(len)) << "Data length too long for data type";
+  DCHECK(NULL != buffer_handle) << "NULL buffer handle";
+  DCHECK(NULL != *buffer_handle) << "NULL pointer";
+  DCHECK(NULL != buffer_len_remaining)
+      << "NULL buffer remainder length pointer";
+  DCHECK_GE(*buffer_len_remaining, len) << "Insufficient buffer size";
+  for (int i = 0; i < len; i++) {
+    int shift = (8 * (len - (i + 1)));
+    unsigned char val_chunk = (val >> shift) & 0x0FF;
+    *(*buffer_handle)++ = val_chunk;
+    *buffer_len_remaining += 1;
+  }
+  return len;
+}
+
+// Construct a SPDY packet.
+// |head| is the start of the packet, up to but not including
+// the header value pairs.
+// |extra_headers| are the extra header-value pairs, which typically
+// will vary the most between calls.
+// |tail| is any (relatively constant) header-value pairs to add.
+// |buffer| is the buffer we're filling in.
+// Returns a SpdFrame.
+spdy::SpdyFrame* ConstructSpdyPacket(const SpdyHeaderInfo* header_info,
+                                     const char* const extra_headers[],
+                                     int extra_header_count,
+                                     const char* const tail[],
+                                     int tail_header_count) {
+  spdy::SpdyFramer framer;
+  spdy::SpdyHeaderBlock headers;
+  // Copy in the extra headers to our map.
+  AppendHeadersToSpdyFrame(extra_headers, extra_header_count, &headers);
+  // Copy in the tail headers to our map.
+  if (tail && tail_header_count)
+    AppendHeadersToSpdyFrame(tail, tail_header_count, &headers);
+  spdy::SpdyFrame* frame = NULL;
+  switch (header_info->kind) {
+    case spdy::SYN_STREAM:
+      frame = framer.CreateSynStream(header_info->id, header_info->assoc_id,
+                                     header_info->priority,
+                                     header_info->control_flags,
+                                     header_info->compressed, &headers);
+      break;
+    case spdy::SYN_REPLY:
+      frame = framer.CreateSynReply(header_info->id, header_info->control_flags,
+                                    header_info->compressed, &headers);
+      break;
+    case spdy::RST_STREAM:
+      frame = framer.CreateRstStream(header_info->id, header_info->status);
+      break;
+    default:
+      frame = framer.CreateDataFrame(header_info->id, header_info->data,
+                                     header_info->data_length,
+                                     header_info->data_flags);
+      break;
+  }
+  return frame;
+}
+
+// Construct an expected SPDY reply string.
+// |extra_headers| are the extra header-value pairs, which typically
+// will vary the most between calls.
+// |buffer| is the buffer we're filling in.
+// Returns the number of bytes written into |buffer|.
+int ConstructSpdyReply(const char* const extra_headers[],
+                       int extra_header_count,
+                       char* buffer,
+                       int buffer_length) {
+  int packet_size = 0;
+  int header_count = 0;
+  char* buffer_write = buffer;
+  int buffer_left = buffer_length;
+  spdy::SpdyHeaderBlock headers;
+  if (!buffer || !buffer_length)
+    return 0;
+  // Copy in the extra headers.
+  AppendHeadersToSpdyFrame(extra_headers, extra_header_count, &headers);
+  header_count = headers.size();
+  // The iterator gets us the list of header/value pairs in sorted order.
+  spdy::SpdyHeaderBlock::iterator next = headers.begin();
+  spdy::SpdyHeaderBlock::iterator last = headers.end();
+  for ( ; next != last; ++next) {
+    // Write the header.
+    int value_len, current_len, offset;
+    const char* header_string = next->first.c_str();
+    packet_size += AppendToBuffer(header_string,
+                                  next->first.length(),
+                                  &buffer_write,
+                                  &buffer_left);
+    packet_size += AppendToBuffer(": ",
+                                  strlen(": "),
+                                  &buffer_write,
+                                  &buffer_left);
+    // Write the value(s).
+    const char* value_string = next->second.c_str();
+    // Check if it's split among two or more values.
+    value_len = next->second.length();
+    current_len = strlen(value_string);
+    offset = 0;
+    // Handle the first N-1 values.
+    while (current_len < value_len) {
+      // Finish this line -- write the current value.
+      packet_size += AppendToBuffer(value_string + offset,
+                                    current_len - offset,
+                                    &buffer_write,
+                                    &buffer_left);
+      packet_size += AppendToBuffer("\n",
+                                    strlen("\n"),
+                                    &buffer_write,
+                                    &buffer_left);
+      // Advance to next value.
+      offset = current_len + 1;
+      current_len += 1 + strlen(value_string + offset);
+      // Start another line -- add the header again.
+      packet_size += AppendToBuffer(header_string,
+                                    next->first.length(),
+                                    &buffer_write,
+                                    &buffer_left);
+      packet_size += AppendToBuffer(": ",
+                                    strlen(": "),
+                                    &buffer_write,
+                                    &buffer_left);
+    }
+    EXPECT_EQ(value_len, current_len);
+    // Copy the last (or only) value.
+    packet_size += AppendToBuffer(value_string + offset,
+                                  value_len - offset,
+                                  &buffer_write,
+                                  &buffer_left);
+    packet_size += AppendToBuffer("\n",
+                                  strlen("\n"),
+                                  &buffer_write,
+                                  &buffer_left);
+  }
+  return packet_size;
+}
+
+// Construct a single SPDY header entry, for validation.
+// |extra_headers| are the extra header-value pairs.
+// |buffer| is the buffer we're filling in.
+// |index| is the index of the header we want.
+// Returns the number of bytes written into |buffer|.
+int ConstructSpdyHeader(const char* const extra_headers[],
+                        int extra_header_count,
+                        char* buffer,
+                        int buffer_length,
+                        int index) {
+  const char* this_header = NULL;
+  const char* this_value = NULL;
+  if (!buffer || !buffer_length)
+    return 0;
+  *buffer = '\0';
+  // Sanity check: Non-empty header list.
+  DCHECK(NULL != extra_headers) << "NULL extra headers pointer";
+  // Sanity check: Index out of range.
+  DCHECK((index >= 0) && (index < extra_header_count))
+      << "Index " << index
+      << " out of range [0, " << extra_header_count << ")";
+  this_header = extra_headers[index * 2];
+  // Sanity check: Non-empty header.
+  if (!*this_header)
+    return 0;
+  std::string::size_type header_len = strlen(this_header);
+  if (!header_len)
+    return 0;
+  this_value = extra_headers[1 + (index * 2)];
+  // Sanity check: Non-empty value.
+  if (!*this_value)
+    this_value = "";
+  int n = base::snprintf(buffer,
+                         buffer_length,
+                         "%s: %s\r\n",
+                         this_header,
+                         this_value);
+  return n;
+}
+
+// Constructs a standard SPDY GET packet.
+// |extra_headers| are the extra header-value pairs, which typically
+// will vary the most between calls.
+// Returns a SpdFrame.
+spdy::SpdyFrame* ConstructSpdyGet(const char* const extra_headers[],
+                                  int extra_header_count) {
+  SpdyHeaderInfo SynStartHeader = {
+    spdy::SYN_STREAM,             // Kind = Syn
+    1,                            // Stream ID
+    0,                            // Associated stream ID
+    3,                            // Priority
+    spdy::CONTROL_FLAG_FIN,       // Control Flags
+    false,                        // Compressed
+    200,                          // Status
+    NULL,                         // Data
+    0,                            // Length
+    spdy::DATA_FLAG_NONE          // Data Flags
+  };
+  static const char* const kStandardGetHeaders[] = {
+    "method",
+    "GET",
+    "url",
+    "http://www.google.com/",
+    "version",
+    "HTTP/1.1"
+  };
+  return ConstructSpdyPacket(
+      &SynStartHeader,
+      extra_headers,
+      extra_header_count,
+      kStandardGetHeaders,
+      arraysize(kStandardGetHeaders) / 2);
+}
+
 }  // namespace
 
 // A DataProvider where the client must write a request before the reads (e.g.
@@ -202,9 +589,9 @@ class DelayedSocketData : public StaticSocketDataProvider,
   DelayedSocketData(int write_delay,
                     MockRead* reads, size_t reads_count,
                     MockWrite* writes, size_t writes_count)
-    : StaticSocketDataProvider(reads, reads_count, writes, writes_count),
-      write_delay_(write_delay),
-      ALLOW_THIS_IN_INITIALIZER_LIST(factory_(this)) {
+      : StaticSocketDataProvider(reads, reads_count, writes, writes_count),
+        write_delay_(write_delay),
+        ALLOW_THIS_IN_INITIALIZER_LIST(factory_(this)) {
     DCHECK_GE(write_delay_, 0);
   }
 
@@ -219,9 +606,9 @@ class DelayedSocketData : public StaticSocketDataProvider,
   DelayedSocketData(const MockConnect& connect, int write_delay,
                     MockRead* reads, size_t reads_count,
                     MockWrite* writes, size_t writes_count)
-    : StaticSocketDataProvider(reads, reads_count, writes, writes_count),
-      write_delay_(write_delay),
-      ALLOW_THIS_IN_INITIALIZER_LIST(factory_(this)) {
+      : StaticSocketDataProvider(reads, reads_count, writes, writes_count),
+        write_delay_(write_delay),
+        ALLOW_THIS_IN_INITIALIZER_LIST(factory_(this)) {
     DCHECK_GE(write_delay_, 0);
     set_connect_data(connect);
   }
@@ -257,6 +644,129 @@ class DelayedSocketData : public StaticSocketDataProvider,
   ScopedRunnableMethodFactory<DelayedSocketData> factory_;
 };
 
+// A DataProvider where the reads are ordered.
+// If a read is requested before its sequence number is reached, we return an
+// ERR_IO_PENDING (that way we don't have to explicitly add a MockRead just to
+// wait).
+// The sequence number is incremented on every read and write operation.
+// The message loop may be interrupted by setting the high bit of the sequence
+// number in the MockRead's sequence number.  When that MockRead is reached,
+// we post a Quit message to the loop.  This allows us to interrupt the reading
+// of data before a complete message has arrived, and provides support for
+// testing server push when the request is issued while the response is in the
+// middle of being received.
+class OrderedSocketData : public StaticSocketDataProvider,
+                          public base::RefCounted<OrderedSocketData> {
+ public:
+  // |reads| the list of MockRead completions.
+  // |writes| the list of MockWrite completions.
+  // Note: All MockReads and MockWrites must be async.
+  // Note: The MockRead and MockWrite lists musts end with a EOF
+  //       e.g. a MockRead(true, 0, 0);
+  OrderedSocketData(MockRead* reads, size_t reads_count,
+                    MockWrite* writes, size_t writes_count)
+      : StaticSocketDataProvider(reads, reads_count, writes, writes_count),
+        sequence_number_(0), loop_stop_stage_(0), callback_(NULL),
+        ALLOW_THIS_IN_INITIALIZER_LIST(factory_(this)) {
+  }
+
+  // |connect| the result for the connect phase.
+  // |reads| the list of MockRead completions.
+  // |writes| the list of MockWrite completions.
+  // Note: All MockReads and MockWrites must be async.
+  // Note: The MockRead and MockWrite lists musts end with a EOF
+  //       e.g. a MockRead(true, 0, 0);
+  OrderedSocketData(const MockConnect& connect,
+                    MockRead* reads, size_t reads_count,
+                    MockWrite* writes, size_t writes_count)
+      : StaticSocketDataProvider(reads, reads_count, writes, writes_count),
+        sequence_number_(0), loop_stop_stage_(0), callback_(NULL),
+        ALLOW_THIS_IN_INITIALIZER_LIST(factory_(this)) {
+    set_connect_data(connect);
+  }
+
+  virtual MockRead GetNextRead() {
+    const MockRead& next_read = StaticSocketDataProvider::PeekRead();
+    if (next_read.sequence_number & MockRead::STOPLOOP)
+      EndLoop();
+    if ((next_read.sequence_number & ~MockRead::STOPLOOP) <=
+        sequence_number_++) {
+      DLOG(INFO) << "  *** " << __FUNCTION__ << "() Stage "
+          << sequence_number_ - 1 << ": Read " << read_index();
+      DumpMockRead(next_read);
+      return StaticSocketDataProvider::GetNextRead();
+    }
+    DLOG(INFO) << "  *** " << __FUNCTION__ << "() Stage "
+        << sequence_number_ - 1 << ": I/O Pending";
+    MockRead result = MockRead(true, ERR_IO_PENDING);
+    DumpMockRead(result);
+    return result;
+  }
+
+  virtual MockWriteResult OnWrite(const std::string& data) {
+    DLOG(INFO) << "  *** " << __FUNCTION__ << "() Stage "
+        << sequence_number_ << ": Write " << write_index();
+    DumpMockRead(PeekWrite());
+    ++sequence_number_;
+    MessageLoop::current()->PostDelayedTask(FROM_HERE,
+      factory_.NewRunnableMethod(&OrderedSocketData::CompleteRead), 100);
+    return StaticSocketDataProvider::OnWrite(data);
+  }
+
+  virtual void Reset() {
+    DLOG(INFO) << "  *** " << __FUNCTION__ << "() Stage "
+        << sequence_number_ << ": Reset()";
+    sequence_number_ = 0;
+    loop_stop_stage_ = 0;
+    set_socket(NULL);
+    factory_.RevokeAll();
+    StaticSocketDataProvider::Reset();
+  }
+
+  void SetCompletionCallback(CompletionCallback* callback) {
+    callback_ = callback;
+  }
+
+  // Posts a quit message to the current message loop, if one is running.
+  void EndLoop() {
+    // If we've already stopped the loop, don't do it again until we've advanced
+    // to the next sequence_number.
+    DLOG(INFO) << "  *** " << __FUNCTION__ << "() Stage "
+        << sequence_number_ << ": EndLoop()";
+    if (loop_stop_stage_ > 0) {
+      const MockRead& next_read = StaticSocketDataProvider::PeekRead();
+      if ((next_read.sequence_number & ~MockRead::STOPLOOP) >
+          loop_stop_stage_) {
+        DLOG(INFO) << "  *** " << __FUNCTION__ << "() Stage "
+            << sequence_number_ << ": Clearing stop index";
+        loop_stop_stage_ = 0;
+      } else {
+        return;
+      }
+    }
+    // Record the sequence_number at which we stopped the loop.
+    DLOG(INFO) << "  *** " << __FUNCTION__ << "() Stage "
+        << sequence_number_ << ": Posting Quit at read " << read_index();
+    loop_stop_stage_ = sequence_number_;
+    if (callback_)
+      callback_->RunWithParams(Tuple1<int>(ERR_IO_PENDING));
+  }
+
+  void CompleteRead() {
+    if (socket()) {
+      DLOG(INFO) << "  *** " << __FUNCTION__ << "() Stage "
+          << sequence_number_;
+      socket()->OnReadComplete(GetNextRead());
+    }
+  }
+
+ private:
+  int sequence_number_;
+  int loop_stop_stage_;
+  CompletionCallback* callback_;
+  ScopedRunnableMethodFactory<OrderedSocketData> factory_;
+};
+
 class SpdyNetworkTransactionTest : public PlatformTest {
  protected:
   virtual void SetUp() {
@@ -434,13 +944,13 @@ static const unsigned char kEmptyPostSyn[] = {
     MockRead(true, reinterpret_cast<const char*>(kPostSynReply),
              arraysize(kPostSynReply)),
     MockRead(true, reinterpret_cast<const char*>(kPostBodyFrame),
-             arraysize(kGetBodyFrame)),
+             arraysize(kPostBodyFrame)),
     MockRead(true, 0, 0)  // EOF
   };
 
   scoped_refptr<DelayedSocketData> data(
-    new DelayedSocketData(1, reads, arraysize(reads),
-                          writes, arraysize(writes)));
+      new DelayedSocketData(1, reads, arraysize(reads),
+                            writes, arraysize(writes)));
 
   TransactionHelperResult out = TransactionHelper(request, data, NULL);
   EXPECT_EQ(OK, out.rv);
@@ -630,6 +1140,188 @@ TEST_F(SpdyNetworkTransactionTest, SynReplyHeaders) {
   }
 }
 
+// Verify that various SynReply headers parse vary fields correctly
+// through the HTTP layer, and the response matches the request.
+TEST_F(SpdyNetworkTransactionTest, SynReplyHeadersVary) {
+  static const SpdyHeaderInfo syn_reply_info = {
+    spdy::SYN_REPLY,                              // Syn Reply
+    1,                                            // Stream ID
+    0,                                            // Associated Stream ID
+    3,                                            // Priority
+    spdy::CONTROL_FLAG_NONE,                      // Control Flags
+    false,                                        // Compressed
+    200,                                          // Status
+    NULL,                                         // Data
+    0,                                            // Data Length
+    spdy::DATA_FLAG_NONE                          // Data Flags
+  };
+  // Modify the following data to change/add test cases:
+  struct SynReplyTests {
+    const SpdyHeaderInfo* syn_reply;
+    bool vary_matches;
+    int num_headers[2];
+    const char* extra_headers[2][16];
+  } test_cases[] = {
+    // Test the case of a multi-valued cookie.  When the value is delimited
+    // with NUL characters, it needs to be unfolded into multiple headers.
+    {
+      &syn_reply_info,
+      true,
+      { 2, 4 },
+      { { "cookie",   "val1",
+          "cookie",   "val2",
+          NULL
+        },
+        { "vary",     "cookie",
+          "status",   "200",
+          "url",      "/index.php",
+          "version",  "HTTP/1.1",
+          NULL
+        }
+      }
+    }, {    // Multiple vary fields.
+      &syn_reply_info,
+      true,
+      { 2, 5 },
+      { { "friend",   "barney",
+          "enemy",    "snaggletooth",
+          NULL
+        },
+        { "vary",     "friend",
+          "vary",     "enemy",
+          "status",   "200",
+          "url",      "/index.php",
+          "version",  "HTTP/1.1",
+          NULL
+        }
+      }
+    }, {    // Test a '*' vary field.
+      &syn_reply_info,
+      false,
+      { 1, 4 },
+      { { "cookie",   "val1,val2",
+          NULL
+        },
+        { "vary",     "*",
+          "status",   "200",
+          "url",      "/index.php",
+          "version",  "HTTP/1.1",
+          NULL
+        }
+      }
+    }, {    // Multiple comma-separated vary fields.
+      &syn_reply_info,
+      true,
+      { 2, 4 },
+      { { "friend",   "barney",
+          "enemy",    "snaggletooth",
+          NULL
+        },
+        { "vary",     "friend,enemy",
+          "status",   "200",
+          "url",      "/index.php",
+          "version",  "HTTP/1.1",
+          NULL
+        }
+      }
+    }
+  };
+
+  for (size_t i = 0; i < ARRAYSIZE_UNSAFE(test_cases); ++i) {
+    char modified_syn_header[64];
+
+    // Construct the request.
+    scoped_ptr<spdy::SpdyFrame> frame_req(
+      ConstructSpdyGet(test_cases[i].extra_headers[0],
+                       test_cases[i].num_headers[0]));
+
+    MockWrite writes[] = {
+      MockWrite(
+          true,
+          frame_req->data(),
+          frame_req->length() + spdy::SpdyFrame::size()),
+    };
+
+    // Construct the reply.
+    scoped_ptr<spdy::SpdyFrame> frame_reply(
+      ConstructSpdyPacket(test_cases[i].syn_reply,
+                          test_cases[i].extra_headers[1],
+                          test_cases[i].num_headers[1],
+                          NULL,
+                          0));
+
+    MockRead reads[] = {
+      MockRead(true,
+               frame_reply->data(),
+               frame_reply->length() + spdy::SpdyFrame::size()),
+      MockRead(true,
+               reinterpret_cast<const char*>(kGetBodyFrame),
+               arraysize(kGetBodyFrame)),
+      MockRead(true, 0, 0)  // EOF
+    };
+
+    HttpRequestInfo request;
+    request.method = "GET";
+    request.url = GURL("http://www.google.com/");
+    request.load_flags = 0;
+
+    // Attach the headers to the request.
+    int hdrCount = test_cases[i].num_headers[0];
+    int len = 0;
+
+    for (int ct = 0; ct < hdrCount; ct++) {
+      len = ConstructSpdyHeader(test_cases[i].extra_headers[0],
+                                test_cases[i].num_headers[0],
+                                modified_syn_header,
+                                64,
+                                ct);
+
+      request.extra_headers.append(modified_syn_header);
+    }
+
+    scoped_refptr<DelayedSocketData> data(
+        new DelayedSocketData(1, reads, arraysize(reads),
+                              writes, arraysize(writes)));
+    TransactionHelperResult out = TransactionHelper(request, data.get(), NULL);
+    EXPECT_EQ(OK, out.rv) << i;
+    EXPECT_EQ("HTTP/1.1 200 OK", out.status_line) << i;
+    EXPECT_EQ("hello!", out.response_data) << i;
+
+    // Test the response information.
+    EXPECT_TRUE(out.response_info.response_time >
+                out.response_info.request_time) << i;
+    base::TimeDelta test_delay = out.response_info.response_time -
+                                 out.response_info.request_time;
+    base::TimeDelta min_expected_delay;
+    min_expected_delay.FromMilliseconds(10);
+    EXPECT_GT(test_delay.InMillisecondsF(),
+              min_expected_delay.InMillisecondsF()) << i;
+    EXPECT_EQ(out.response_info.vary_data.is_valid(),
+              test_cases[i].vary_matches) << i;
+
+    // Check the headers.
+    scoped_refptr<HttpResponseHeaders> headers = out.response_info.headers;
+    ASSERT_TRUE(headers.get() != NULL) << i;
+    void* iter = NULL;
+    std::string name, value, lines;
+    while (headers->EnumerateHeaderLines(&iter, &name, &value)) {
+      lines.append(name);
+      lines.append(": ");
+      lines.append(value);
+      lines.append("\n");
+    }
+
+    // Construct the expected header reply string.
+    char reply_buffer[256] = "";
+    ConstructSpdyReply(test_cases[i].extra_headers[1],
+                       test_cases[i].num_headers[1],
+                       reply_buffer,
+                       256);
+
+    EXPECT_EQ(std::string(reply_buffer), lines) << i;
+  }
+}
+
 // Verify that we don't crash on invalid SynReply responses.
 TEST_F(SpdyNetworkTransactionTest, InvalidSynReply) {
   static const unsigned char kSynReplyMissingStatus[] = {
@@ -739,6 +1431,111 @@ TEST_F(SpdyNetworkTransactionTest, CorruptFrameSessionError) {
   }
 }
 
+// Server push:
+// ------------
+// Client: Send the original SYN request.
+// Server: Receive the SYN request.
+// Server: Send a SYN reply, with X-Associated-Content and URL(s).
+// Server: For each URL, send a SYN_STREAM with the URL and a stream ID,
+//         followed by one or more Data frames (the last one with a FIN).
+// Client: Requests the URL(s).
+// Client: Receives the SYN_STREAMs, and the associated Data frames, and
+//         associates the URLs with the incoming stream IDs.
+//
+// There are three possibilities when the client tries to send the second
+// request (which doesn't make it to the wire):
+//
+// 1. The push data has arrived and is complete.
+// 2. The push data has started arriving, but hasn't finished.
+// 3. The push data has not yet arrived.
+
+// Enum for ServerPush.
+enum TestTypes {
+  // Simulate that the server sends the first request, notifying the client
+  // that it *will* push the second stream.  But the client issues the
+  // request for the second stream before the push data arrives.
+  PUSH_AFTER_REQUEST,
+  // Simulate that the server is sending the pushed stream data before the
+  // client requests it.  The SpdySession will buffer the response and then
+  // deliver the data when the client does make the request.
+  PUSH_BEFORE_REQUEST,
+  // Simulate that the server is sending the pushed stream data before the
+  // client requests it, but the stream has not yet finished when the request
+  // occurs.  The SpdySession will buffer the response and then deliver the
+  // data when the response is complete.
+  PUSH_DURING_REQUEST,
+  DONE
+};
+
+// Creates and processes a SpdyNetworkTransaction for server push, based on
+//   |session|.
+// |data| holds the expected writes, and the reads.
+// |url| is the web page we want.  In pass 2, it contains the resource we expect
+//   to be pushed.
+// |expected_data| is the data we expect to get in response.
+// |test_type| is one of PUSH_AFTER_REQUEST, PUSH_BEFORE_REQUEST, or
+//   PUSH_DURING_REQUEST, indicating the type of test we're running.
+// |pass| is 1 for the first request, and 2 for the request for the push data.
+// |response| is the response information for the request.  It will be used to
+//   verify the response time stamps.
+static void MakeRequest(scoped_refptr<HttpNetworkSession> session,
+                        scoped_refptr<OrderedSocketData> data,
+                        const GURL& url,
+                        const std::string& expected_data,
+                        int test_type,
+                        int pass,
+                        HttpResponseInfo* response) {
+  SpdyNetworkTransaction trans(session.get());
+
+  HttpRequestInfo request;
+  request.method = "GET";
+  request.url = url;
+  request.load_flags = 0;
+  TestCompletionCallback callback;
+
+  // Allows the STOP_LOOP flag to work.
+  data->SetCompletionCallback(&callback);
+  // Sends a request.  In pass 1, this goes on the wire; in pass 2, it is
+  // preempted by the push data.
+  int rv = trans.Start(&request, &callback, NULL);
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+
+  // In the case where we are pushing beforehand, complete the next read now.
+  if ((pass == 2) && (test_type == PUSH_AFTER_REQUEST)) {
+    data->CompleteRead();
+  }
+
+  // Process messages until either a FIN or a STOP_LOOP is encountered.
+  rv = callback.WaitForResult();
+  if ((pass == 2) && (test_type == PUSH_DURING_REQUEST)) {
+    // We should be in the middle of a request, so we're pending.
+    EXPECT_EQ(ERR_IO_PENDING, rv);
+  } else {
+    EXPECT_EQ(OK, rv);
+  }
+
+  // Verify the SYN_REPLY.
+  // Copy the response info, because trans goes away
+  *response = *trans.GetResponseInfo();
+  EXPECT_TRUE(response->headers != NULL);
+  EXPECT_EQ("HTTP/1.1 200 OK", response->headers->GetStatusLine());
+
+  // In the case where we are Complete the next read now.
+  if (((pass == 1) &&
+      ((test_type == PUSH_BEFORE_REQUEST) ||
+          (test_type == PUSH_DURING_REQUEST)))) {
+    data->CompleteRead();
+  }
+
+  // Verify the body.
+  std::string response_data;
+  rv = ReadTransaction(&trans, &response_data);
+  EXPECT_EQ(OK, rv);
+  EXPECT_EQ(expected_data, response_data);
+  // Remove callback, so that if another STOP_LOOP occurs, there is no crash.
+  data->SetCompletionCallback(NULL);
+}
+
 TEST_F(SpdyNetworkTransactionTest, ServerPush) {
   // Reply with the X-Associated-Content header.
   static const unsigned char syn_reply[] = {
@@ -777,123 +1574,174 @@ TEST_F(SpdyNetworkTransactionTest, ServerPush) {
   };
 
   // Body for stream 2
-  static const unsigned char body_frame_2[] = {
-    0x00, 0x00, 0x00, 0x02,
-    0x01, 0x00, 0x00, 0x07,
-    'g', 'o', 'o', 'd', 'b', 'y', 'e',
+  static const unsigned char kPushBodyFrame[] = {
+    0x00, 0x00, 0x00, 0x02,                                      // header, ID
+    0x01, 0x00, 0x00, 0x05,                                      // FIN, length
+    'h', 'e', 'l', 'l', 'o',                                     // "hello"
+  };
+
+  static const unsigned char kPushBodyFrame1[] = {
+    0x00, 0x00, 0x00, 0x02,                                      // header, ID
+    0x01, 0x00, 0x00, 0x1E,                                      // FIN, length
+    'h', 'e', 'l', 'l', 'o',                                     // "hello"
   };
 
+  static const char kPushBodyFrame2[] = " my darling";
+  static const char kPushBodyFrame3[] = " hello";
+  static const char kPushBodyFrame4[] = " my baby";
+
+  const char syn_body_data1[] = "hello";
+  const char syn_body_data2[] = "hello my darling hello my baby";
+  const char* syn_body_data = NULL;
+
   MockWrite writes[] = {
     MockWrite(true, reinterpret_cast<const char*>(kGetSyn),
               arraysize(kGetSyn)),
   };
 
-  MockRead reads[] = {
-    MockRead(true, reinterpret_cast<const char*>(syn_reply),
-             arraysize(syn_reply)),
-    MockRead(true, reinterpret_cast<const char*>(kGetBodyFrame),
-             arraysize(kGetBodyFrame)),
-    MockRead(true, ERR_IO_PENDING),  // Force a pause
-    MockRead(true, reinterpret_cast<const char*>(syn_push),
-             arraysize(syn_push)),
-    MockRead(true, reinterpret_cast<const char*>(body_frame_2),
-             arraysize(body_frame_2)),
-    MockRead(true, ERR_IO_PENDING),  // Force a pause
-    MockRead(true, 0, 0)  // EOF
+  // This array is for request before and after push is received.  The push
+  // body is only one 'packet', to allow the initial transaction to read all
+  // the push data before .
+  MockRead reads1[] = {
+    MockRead(true, reinterpret_cast<const char*>(syn_reply),        // 0
+             arraysize(syn_reply), 2),
+    MockRead(true, reinterpret_cast<const char*>(kGetBodyFrame),    // 1
+             arraysize(kGetBodyFrame), 3),
+    MockRead(true, ERR_IO_PENDING, 4),  // Force a pause            // 2
+    MockRead(true, reinterpret_cast<const char*>(syn_push),         // 3
+             arraysize(syn_push), 5),
+    MockRead(true, reinterpret_cast<const char*>(kPushBodyFrame),   // 4
+             arraysize(kPushBodyFrame), 6),
+    MockRead(true, ERR_IO_PENDING, 7),  // Force a pause            // 5
+    MockRead(true, 0, 0, 8)  // EOF                                 // 6
+  };
+
+  // This array is for request while push is being received.  It extends
+  // the push body so we can 'interrupt' it.
+  MockRead reads2[] = {
+    MockRead(true, reinterpret_cast<const char*>(syn_reply),        // 0
+             arraysize(syn_reply), 2),
+    MockRead(true, reinterpret_cast<const char*>(kGetBodyFrame),    // 1
+             arraysize(kGetBodyFrame), 3),
+    MockRead(true, reinterpret_cast<const char*>(syn_push),         // 2
+             arraysize(syn_push), 4),
+    MockRead(true, reinterpret_cast<const char*>(kPushBodyFrame1),  // 3
+             arraysize(kPushBodyFrame1), 5),
+    // Force a pause by skipping a sequence number.
+    MockRead(true, reinterpret_cast<const char*>(kPushBodyFrame2),  // 4
+             arraysize(kPushBodyFrame2) - 1, 7),
+    MockRead(true, reinterpret_cast<const char*>(kPushBodyFrame3),  // 5
+             arraysize(kPushBodyFrame3) - 1, 8),
+    MockRead(true, reinterpret_cast<const char*>(kPushBodyFrame4),  // 6
+             arraysize(kPushBodyFrame4) - 1, 9),
+    MockRead(true, ERR_IO_PENDING, MockRead::STOPLOOP | 10)         // 7
   };
 
   // We disable SSL for this test.
   SpdySession::SetSSLMode(false);
 
-  enum TestTypes {
-    // Simulate that the server sends the first request, notifying the client
-    // that it *will* push the second stream.  But the client issues the
-    // request for the second stream before the push data arrives.
-    PUSH_AFTER_REQUEST,
-    // Simulate that the server is sending the pushed stream data before the
-    // client requests it.  The SpdySession will buffer the response and then
-    // deliver the data when the client does make the request.
-    PUSH_BEFORE_REQUEST,
-    DONE
-  };
+  base::Time zero_time = base::Time::FromInternalValue(0);
+  for (int test_type = PUSH_AFTER_REQUEST; test_type < DONE; ++test_type) {
+    DLOG(INFO) << "Test " << test_type;
+
+    // Select the data to use.
+    MockRead* reads = NULL;
+    size_t num_reads = 0;
+    size_t num_writes = arraysize(writes);
+    int first_push_data_frame = 0;
+    if (test_type == PUSH_DURING_REQUEST) {
+      reads = reads2;
+      num_reads = arraysize(reads2);
+      syn_body_data = syn_body_data2;
+      first_push_data_frame = 3;
+    } else {
+      reads = reads1;
+      num_reads = arraysize(reads1);
+      syn_body_data = syn_body_data1;
+      first_push_data_frame = 4;
+    }
+    // Clear timestamp data
+    for (size_t w = 0; w < num_writes; ++w) {
+      writes[w].time_stamp = zero_time;
+    }
+    for (size_t r = 0; r < num_reads; ++r) {
+      reads[r].time_stamp = zero_time;
+    }
 
-  for (int test_type = PUSH_AFTER_REQUEST; test_type != DONE; ++test_type) {
     // Setup a mock session.
     SessionDependencies session_deps;
     scoped_refptr<HttpNetworkSession> session(CreateSession(&session_deps));
-    scoped_refptr<DelayedSocketData> data(
-        new DelayedSocketData(1, reads, arraysize(reads),
-                              writes, arraysize(writes)));
+    scoped_refptr<OrderedSocketData> data(
+        new OrderedSocketData(reads, num_reads, writes, num_writes));
     session_deps.socket_factory.AddSocketDataProvider(data.get());
-
-    // Issue the first request
-    {
-      SpdyNetworkTransaction trans(session.get());
-
-      // Issue the first request.
-      HttpRequestInfo request;
-      request.method = "GET";
-      request.url = GURL("http://www.google.com/");
-      request.load_flags = 0;
-      TestCompletionCallback callback;
-      int rv = trans.Start(&request, &callback, NULL);
-      EXPECT_EQ(ERR_IO_PENDING, rv);
-
-      rv = callback.WaitForResult();
-      EXPECT_EQ(rv, OK);
-
-      // Verify the SYN_REPLY.
-      const HttpResponseInfo* response = trans.GetResponseInfo();
-      EXPECT_TRUE(response->headers != NULL);
-      EXPECT_EQ("HTTP/1.1 200 OK", response->headers->GetStatusLine());
-
-      if (test_type == PUSH_BEFORE_REQUEST)
-        data->CompleteRead();
-
-      // Verify the body.
-      std::string response_data;
-      rv = ReadTransaction(&trans, &response_data);
-      EXPECT_EQ(OK, rv);
-      EXPECT_EQ("hello!", response_data);
-    }
+    HttpResponseInfo response1;
+    HttpResponseInfo response2;
+
+    DLOG(INFO) << "Sending request 1";
+
+    // Issue the first request.
+    MakeRequest(session,
+                data,
+                GURL("http://www.google.com/"),
+                "hello!",
+                test_type,
+                1,
+                &response1);
+
+    DLOG(INFO) << "Sending X-Associated-Content request";
+
+    // This value should be set to something later than the one in
+    // 'response1.request_time'.
+    base::Time request1_time = writes[0].time_stamp;
+    // We don't have a |writes| entry for the second request,
+    // so put in Now() as the request time.  It's not as accurate,
+    // but it will work.
+    base::Time request2_time = base::Time::Now();
 
     // Issue a second request for the X-Associated-Content.
-    {
-      SpdyNetworkTransaction trans(session.get());
-
-      HttpRequestInfo request;
-      request.method = "GET";
-      request.url = GURL("http://www.google.com/foo.dat");
-      request.load_flags = 0;
-      TestCompletionCallback callback;
-      int rv = trans.Start(&request, &callback, NULL);
-      EXPECT_EQ(ERR_IO_PENDING, rv);
-
-      // In the case where we are Complete the next read now.
-      if (test_type == PUSH_AFTER_REQUEST)
-        data->CompleteRead();
-
-      rv = callback.WaitForResult();
-      EXPECT_EQ(rv, OK);
-
-      // Verify the SYN_REPLY.
-      const HttpResponseInfo* response = trans.GetResponseInfo();
-      EXPECT_TRUE(response->headers != NULL);
-      EXPECT_EQ("HTTP/1.1 200 OK", response->headers->GetStatusLine());
-
-      // Verify the body.
-      std::string response_data;
-      rv = ReadTransaction(&trans, &response_data);
-      EXPECT_EQ(OK, rv);
-      EXPECT_EQ("goodbye", response_data);
+    MakeRequest(session,
+                data,
+                GURL("http://www.google.com/foo.dat"),
+                syn_body_data,
+                test_type,
+                2,
+                &response2);
+
+    if (test_type != PUSH_DURING_REQUEST) {
+      // Complete the next read now and teardown.
+      data->CompleteRead();
     }
-
-    // Complete the next read now and teardown.
-    data->CompleteRead();
-
     // Verify that we consumed all test data.
     EXPECT_TRUE(data->at_read_eof());
     EXPECT_TRUE(data->at_write_eof());
+
+    // Check the timings
+
+    // Verify that all the time stamps were set.
+    EXPECT_GE(response1.request_time.ToInternalValue(),
+        zero_time.ToInternalValue());
+    EXPECT_GE(response2.request_time.ToInternalValue(),
+        zero_time.ToInternalValue());
+    EXPECT_GE(response1.response_time.ToInternalValue(),
+        zero_time.ToInternalValue());
+    EXPECT_GE(response2.response_time.ToInternalValue(),
+        zero_time.ToInternalValue());
+
+    // Verify that the values make sense.
+    // First request.
+    EXPECT_LE(response1.request_time.ToInternalValue(),
+        request1_time.ToInternalValue());
+    EXPECT_LE(response1.response_time.ToInternalValue(),
+        reads[1].time_stamp.ToInternalValue());
+
+    // Push request.
+    EXPECT_GE(response2.request_time.ToInternalValue(),
+        request2_time.ToInternalValue());
+    // The response time should be between the server push SYN and DATA.
+    EXPECT_GE(response2.response_time.ToInternalValue(),
+      reads[first_push_data_frame - 1].time_stamp.ToInternalValue());
+    EXPECT_LE(response2.response_time.ToInternalValue(),
+      reads[first_push_data_frame].time_stamp.ToInternalValue());
   }
 }
 
@@ -1607,5 +2455,4 @@ TEST_F(SpdyNetworkTransactionTest, BufferedCancelled) {
   MessageLoop::current()->RunAllPending();
 }
 
-
 }  // namespace net
diff --git a/net/spdy/spdy_session.cc b/net/spdy/spdy_session.cc
index d527e4f..4c684cd 100644
--- a/net/spdy/spdy_session.cc
+++ b/net/spdy/spdy_session.cc
@@ -11,6 +11,7 @@
 #include "base/stats_counters.h"
 #include "base/stl_util-inl.h"
 #include "base/string_util.h"
+#include "base/time.h"
 #include "net/base/connection_type_histograms.h"
 #include "net/base/load_flags.h"
 #include "net/base/net_log.h"
@@ -89,6 +90,8 @@ bool SpdyHeadersToHttpResponse(const spdy::SpdyHeaderBlock& headers,
   }
   version = it->second;
 
+  response->response_time = base::Time::Now();
+
   std::string raw_headers(version);
   raw_headers.push_back(' ');
   raw_headers.append(status);
@@ -140,7 +143,7 @@ void CreateSpdyHeadersFromHttpRequest(
       (*headers)[name] = it.values();
     } else {
       std::string new_value = (*headers)[name];
-      new_value += "\0";
+      new_value.append(1, '\0');  // +=() doesn't append 0's
       new_value += it.values();
       (*headers)[name] = new_value;
     }
@@ -298,6 +301,21 @@ scoped_refptr<SpdyStream> SpdySession::GetOrCreateStream(
     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;
     }
@@ -307,11 +325,13 @@ scoped_refptr<SpdyStream> SpdySession::GetOrCreateStream(
   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.
     log.AddEvent(NetLog::TYPE_SPDY_STREAM_ADOPTED_PUSH_STREAM);
     SpdyStream* stream = new SpdyStream(this, 0, true, log);
+    stream->SetRequestInfo(request);
     stream->set_path(path);
     it->second = stream;
     return it->second;
@@ -321,6 +341,7 @@ scoped_refptr<SpdyStream> SpdySession::GetOrCreateStream(
 
   // If we still don't have a stream, activate one now.
   stream = new SpdyStream(this, stream_id, false, log);
+  stream->SetRequestInfo(request);
   stream->set_priority(request.priority);
   stream->set_path(path);
   ActivateStream(stream);
@@ -512,6 +533,7 @@ void SpdySession::OnSSLConnect(int result) {
 }
 
 void SpdySession::OnReadComplete(int bytes_read) {
+  DLOG(INFO) << "  >> " << __FUNCTION__ << "()";
   // Parse a frame.  For now this code requires that the frame fit into our
   // buffer (32KB).
   // TODO(mbelshe): support arbitrarily large frames!
@@ -550,6 +572,7 @@ void SpdySession::OnReadComplete(int bytes_read) {
 }
 
 void SpdySession::OnWriteComplete(int result) {
+  DLOG(INFO) << "  >> " << __FUNCTION__ << "()";
   DCHECK(write_pending_);
   DCHECK(in_flight_write_.size());
   DCHECK(result != 0);  // This shouldn't happen for write.
@@ -845,6 +868,29 @@ void SpdySession::OnStreamFrameData(spdy::SpdyStreamId stream_id,
     DeactivateStream(stream_id);
 }
 
+bool SpdySession::Respond(const spdy::SpdyHeaderBlock& headers,
+                          const scoped_refptr<SpdyStream> 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();
+  if (SpdyHeadersToHttpResponse(headers, &response)) {
+    GetSSLInfo(&response.ssl_info);
+    response.request_time = stream->GetRequestTime();
+    response.vary_data.Init(*stream->GetRequestInfo(), *response.headers);
+    stream->OnResponseReceived(response);
+  } else {
+    const spdy::SpdyStreamId stream_id = stream->stream_id();
+    stream->OnClose(ERR_INVALID_RESPONSE);
+    DeactivateStream(stream_id);
+    return false;
+  }
+  return true;
+}
+
 void SpdySession::OnSyn(const spdy::SpdySynStreamControlFrame& frame,
                         const spdy::SpdyHeaderBlock& headers) {
   spdy::SpdyStreamId stream_id = frame.stream_id();
@@ -917,18 +963,8 @@ void SpdySession::OnSyn(const spdy::SpdySynStreamControlFrame& frame,
 
   stream->set_path(path);
 
-  // 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;
-  if (SpdyHeadersToHttpResponse(headers, &response)) {
-    GetSSLInfo(&response.ssl_info);
-    stream->OnResponseReceived(response);
-  } else {
-    stream->OnClose(ERR_INVALID_RESPONSE);
-    DeactivateStream(stream_id);
+  if (!Respond(headers, stream))
     return;
-  }
 
   LOG(INFO) << "Got pushed stream for " << stream->path();
 
@@ -982,17 +1018,12 @@ void SpdySession::OnSynReply(const spdy::SpdySynReplyControlFrame& frame,
   scoped_refptr<SpdyStream> stream = active_streams_[stream_id];
   CHECK_EQ(stream->stream_id(), stream_id);
   CHECK(!stream->cancelled());
-  HttpResponseInfo response;
-  if (SpdyHeadersToHttpResponse(headers, &response)) {
-    GetSSLInfo(&response.ssl_info);
-    stream->OnResponseReceived(response);
-  } else {
-    stream->OnClose(ERR_INVALID_RESPONSE);
-    DeactivateStream(stream_id);
-  }
+
+  Respond(headers, stream);
 }
 
 void SpdySession::OnControl(const spdy::SpdyControlFrame* frame) {
+  DLOG(INFO) << "  >> " << __FUNCTION__ << "()";
   spdy::SpdyHeaderBlock headers;
   uint32 type = frame->type();
   if (type == spdy::SYN_STREAM || type == spdy::SYN_REPLY) {
@@ -1050,6 +1081,7 @@ void SpdySession::OnFin(const spdy::SpdyRstStreamControlFrame& frame) {
 }
 
 void SpdySession::OnGoAway(const spdy::SpdyGoAwayControlFrame& frame) {
+  DLOG(INFO) << "  >> " << __FUNCTION__ << "()";
   session_->spdy_session_pool()->Remove(this);
 
   // TODO(willchan): Cancel any streams that are past the GoAway frame's
diff --git a/net/spdy/spdy_session.h b/net/spdy/spdy_session.h
index 80124c6..653f193 100644
--- a/net/spdy/spdy_session.h
+++ b/net/spdy/spdy_session.h
@@ -156,6 +156,11 @@ class SpdySession : public base::RefCounted<SpdySession>,
   // list), returns NULL otherwise.
   scoped_refptr<SpdyStream> GetPushStream(const std::string& url);
 
+  // Creates an HttpResponseInfo instance, and calls OnResponseReceived().
+  // Returns true if successful.
+  bool Respond(const spdy::SpdyHeaderBlock& headers,
+               const scoped_refptr<SpdyStream> stream);
+
   void GetSSLInfo(SSLInfo* ssl_info);
 
   // Callbacks for the Spdy session.
diff --git a/net/spdy/spdy_stream.cc b/net/spdy/spdy_stream.cc
index 6b82fa1..c381da1 100644
--- a/net/spdy/spdy_stream.cc
+++ b/net/spdy/spdy_stream.cc
@@ -20,6 +20,7 @@ SpdyStream::SpdyStream(SpdySession* session, spdy::SpdyStreamId stream_id,
       download_finished_(false),
       metrics_(Singleton<BandwidthMetrics>::get()),
       session_(session),
+      request_time_(base::Time::Now()),
       response_(NULL),
       request_body_stream_(NULL),
       response_complete_(false),
@@ -59,6 +60,28 @@ const HttpResponseInfo* SpdyStream::GetResponseInfo() const {
   return response_;
 }
 
+const HttpRequestInfo* SpdyStream::GetRequestInfo() const {
+  return &request_;
+}
+
+void SpdyStream::SetRequestInfo(const HttpRequestInfo& request) {
+  request_ = request;
+}
+
+base::Time SpdyStream::GetRequestTime() const {
+  return request_time_;
+}
+
+void SpdyStream::SetRequestTime(base::Time t) {
+  request_time_ = t;
+
+  // This should only get called in the case of a request occuring
+  // during server push that has already begun but hasn't finished,
+  // so we set the response's request time to be the actual one
+  if (response_)
+    response_->request_time = request_time_;
+}
+
 int SpdyStream::ReadResponseHeaders(CompletionCallback* callback) {
   // Note: The SpdyStream may have already received the response headers, so
   //       this call may complete synchronously.
@@ -128,6 +151,8 @@ int SpdyStream::SendRequest(UploadDataStream* upload_data,
   CHECK(!cancelled_);
   CHECK(response);
 
+  DLOG(INFO) << "  * " << __FUNCTION__ << "()";
+
   if (response_) {
     *response = *response_;
     delete response_;
@@ -169,6 +194,7 @@ void SpdyStream::Cancel() {
 }
 
 void SpdyStream::OnResponseReceived(const HttpResponseInfo& response) {
+  DLOG(INFO) << "  >> " << __FUNCTION__ << "()";
   metrics_.StartStream();
 
   CHECK(!response_->headers);
@@ -200,6 +226,7 @@ void SpdyStream::OnResponseReceived(const HttpResponseInfo& response) {
 }
 
 bool SpdyStream::OnDataReceived(const char* data, int length) {
+  DLOG(INFO) << "  >> " << __FUNCTION__ << "()";
   DCHECK_GE(length, 0);
   LOG(INFO) << "SpdyStream: Data (" << length << " bytes) received for "
             << stream_id_;
@@ -250,6 +277,7 @@ bool SpdyStream::OnDataReceived(const char* data, int length) {
 }
 
 void SpdyStream::OnWriteComplete(int status) {
+  DLOG(INFO) << "  >> " << __FUNCTION__ << "()";
   // TODO(mbelshe): Check for cancellation here.  If we're cancelled, we
   // should discontinue the DoLoop.
 
@@ -260,6 +288,7 @@ void SpdyStream::OnWriteComplete(int status) {
 }
 
 void SpdyStream::OnClose(int status) {
+  DLOG(INFO) << "  >> " << __FUNCTION__ << "()";
   response_complete_ = true;
   response_status_ = status;
   stream_id_ = 0;
@@ -272,6 +301,8 @@ void SpdyStream::OnClose(int status) {
 
 int SpdyStream::DoLoop(int result) {
   do {
+    DLOG(INFO) << "  * " << __FUNCTION__ << "() state = " << io_state_
+        << " result = " << result;
     State state = io_state_;
     io_state_ = STATE_NONE;
     switch (state) {
diff --git a/net/spdy/spdy_stream.h b/net/spdy/spdy_stream.h
index 89cfb18..cf7ea4a 100644
--- a/net/spdy/spdy_stream.h
+++ b/net/spdy/spdy_stream.h
@@ -16,12 +16,12 @@
 #include "net/base/completion_callback.h"
 #include "net/base/io_buffer.h"
 #include "net/base/net_log.h"
+#include "net/http/http_request_info.h"
 #include "net/spdy/spdy_framer.h"
 #include "net/spdy/spdy_protocol.h"
 
 namespace net {
 
-class HttpRequestInfo;
 class HttpResponseInfo;
 class SpdySession;
 class UploadData;
@@ -74,8 +74,6 @@ class SpdyStream : public base::RefCounted<SpdyStream> {
   // Returns the number of bytes uploaded.
   uint64 GetUploadProgress() const;
 
-  const HttpResponseInfo* GetResponseInfo() const;
-
   // Is this stream a pushed stream from the server.
   bool pushed() const { return pushed_; }
 
@@ -92,6 +90,12 @@ class SpdyStream : public base::RefCounted<SpdyStream> {
   int priority() const { return priority_; }
   void set_priority(int priority) { priority_ = priority; }
 
+  const HttpResponseInfo* GetResponseInfo() const;
+  const HttpRequestInfo* GetRequestInfo() const;
+  void SetRequestInfo(const HttpRequestInfo& request);
+  base::Time GetRequestTime() const;
+  void SetRequestTime(base::Time t);
+
   // Called by the SpdySession when a response (e.g. a SYN_REPLY) has been
   // received for this stream.  |path| is the path of the URL for a server
   // initiated stream, otherwise is empty.
@@ -180,6 +184,13 @@ class SpdyStream : public base::RefCounted<SpdyStream> {
 
   scoped_refptr<SpdySession> session_;
 
+  // The request to send.
+  HttpRequestInfo request_;
+
+  // The time at which the request was made that resulted in this response.
+  // For cached responses, this time could be "far" in the past.
+  base::Time request_time_;
+
   HttpResponseInfo* response_;
   scoped_ptr<UploadDataStream> request_body_stream_;
 
diff --git a/net/spdy/spdy_stream_unittest.cc b/net/spdy/spdy_stream_unittest.cc
index 8911d9a..b8c4b7f 100644
--- a/net/spdy/spdy_stream_unittest.cc
+++ b/net/spdy/spdy_stream_unittest.cc
@@ -113,6 +113,7 @@ TEST_F(SpdyStreamTest, SendRequest) {
   HttpResponseInfo response;
 
   scoped_refptr<SpdyStream> stream(new SpdyStream(session, 1, false, NULL));
+  stream->SetRequestInfo(request);
   EXPECT_EQ(ERR_IO_PENDING, stream->SendRequest(NULL, &response, &callback));
 
   // Need to manually remove the spdy session since normally it gets removed on