ProtocolException: Expected ':status' header not present

[swankjesse]

I got this attempting to reach https://twitter.com.

[swankjesse]

I think it's twitter's fault.
https://twitter.com/jessewilson/status/443570142320939009

[swankjesse]

This looks like a bug in our HPACK decoder. Or possibly a bug in Twitter's HPACK encoder. (FYI @jpinner).

Fetching https://twitter.com 10 times on the same connection reliably yields a missing :status header. I'll see if OkHttp suffers this problem talking to other http/2 hosts.

[swankjesse]

Looks like this is an HPACK problem. I'm still trying to isolate the cause. I've got a reproducible test case: https://gist.github.com/swankjesse/9567930

[jpinner]

@swankjesse I'll try to find some time to debug this today. Are you all using Twitter's HPACK encoder/decoder?

[codefromthecrypt]

We are using twitter's huffman codec for our own hpack.

[swankjesse]

Thanks @jpinner. I'm not yet sure whether it's a bug in our client or your server.

[codefromthecrypt]

So, I just ran ExternalHttp2Example changing the url to https://twitter.com, and put a break point at SpdyStream line 275 (receiveHeaders)

Seems :status is reporting ok for me at least..

[:status: 200, cache-control: no-cache, no-store, must-revalidate, pre-check=0, post-check=0, content-encoding: gzip, content-length: 10711, content-type: text/html;charset=utf-8, date: Sat, 15 Mar 2014 16:49:42 GMT, expires: Tue, 31 Mar 1981 05:00:00 GMT, last-modified: Sat, 15 Mar 2014 16:49:42 GMT, ms: S, pragma: no-cache, server: tfe, set-cookie: _twitter_sess=REDACTED; Path=/; Domain=.twitter.com; Secure; HTTPOnly�guest_id=v1%3A139490218274927656; Domain=.twitter.com; Path=/; Expires=Mon, 14-Mar-2016 16:49:42 UTC, status: 200 OK, strict-transport-security: max-age=631138519, x-content-type-options: nosniff, x-frame-options: SAMEORIGIN, x-transaction: 0f31d7f58d0841c0, x-ua-compatible: IE=edge,chrome=1, x-xss-protection: 1; mode=block]

[codefromthecrypt]

And here's for spdy 3

[:status: 200 OK, :version: HTTP/1.1, cache-control: no-cache, no-store, must-revalidate, pre-check=0, post-check=0, content-encoding: gzip, content-length: 11087, content-type: text/html;charset=utf-8, date: Sat, 15 Mar 2014 16:52:24 GMT, expires: Tue, 31 Mar 1981 05:00:00 GMT, last-modified: Sat, 15 Mar 2014 16:52:24 GMT, ms: S, pragma: no-cache, server: tfe, set-cookie: _twitter_sess=REDACTED; Path=/; Domain=.twitter.com; Secure; HTTPOnly�guest_id=v1%3A139490234481338438; Domain=.twitter.com; Path=/; Expires=Mon, 14-Mar-2016 16:52:24 UTC, status: 200 OK, strict-transport-security: max-age=631138519, x-content-type-options: nosniff, x-frame-options: SAMEORIGIN, x-transaction: a7923cdb7585ddd1, x-ua-compatible: IE=edge,chrome=1, x-xss-protection: 1; mode=block]

[codefromthecrypt]

in both cases, I'm running with the following JVM arg

-Xbootclasspath/p:/Users/adrian/.m2/repository/org/mortbay/jetty/npn/npn-boot/8.1.2.v20120308/npn-boot-8.1.2.v20120308.jar 

[codefromthecrypt]

now, I'll try running 10 times on the same connection..

[jpinner]

I ran the test case through our HPACK decoder and in all 6 responses decoded the ":status" header. My initial guess is that your decoder is evicting it from the table early.

[codefromthecrypt]

I am reliably getting a missing :status error on the 6th attempt below:

  public static void main(String[] args) throws Exception {
    OkHttpClient client = new OkHttpClient().setProtocols(Protocol.HTTP2_AND_HTTP_11);
    URL url = new URL("https://twitter.com");
    for (int i = 0; i < 10; i++) {
      HttpURLConnection connection = client.open(url);
      connection.setRequestMethod("HEAD");
      int responseCode = connection.getResponseCode();
      System.out.println(responseCode);
    }
  }

[codefromthecrypt]

@jpinner I'll check into eviction.. good idea!

[jpinner]

For comparison, Twitter's HPACK decoder has the following table sizes and removals after processing each header set:

Current Header Table Size: 1558
Current Header Table Size: 2298
Current Header Table Size: 2899
Current Header Table Size: 3449
Current Header Table Size: 3999
REMOVING ENTRY
Removed :status: 200
REMOVING ENTRY
Removed cache-control: no-cache, no-store, must-revalidate, pre-check=0, post-check=0
REMOVING ENTRY
Removed content-encoding: gzip
REMOVING ENTRY
Removed content-length: 10715
REMOVING ENTRY
Removed content-type: text/html;charset=utf-8
REMOVING ENTRY
Removed date: Sat, 15 Mar 2014 13:52:14 GMT
REMOVING ENTRY
Removed expires: Tue, 31 Mar 1981 05:00:00 GMT
REMOVING ENTRY
Removed last-modified: Sat, 15 Mar 2014 13:52:14 GMT
Current Header Table Size: 4074

So while processing the 6th response, ":status" is evicted from the table. If there is a bug in which entries the OkHttp decoder is evicting, it will not index the ":status" header correctly to re-emit.

[jpinner]

@adriancole can you run similar debugging output where you print the header table size after each header set is processed and print out whenever an entry is evicted from the table

[codefromthecrypt]

OK here's the run

Header table is 1506bytes
200
200
Header table is 2060bytes
Header table is 2614bytes
200
200
Header table is 3168bytes
200
Header table is 3783bytes
Need to recover: 250byes to add set-cookie: _twitter_sess=REDACTED; Path=/; Domain=.twitter.com; Secure; HTTPOnly�guest_id=v1%3A139490419702518726; Domain=.twitter.com; Path=/; Expires=Mon, 14-Mar-2016 17:23:17 UTC
Evicting :status: 200 which recovers 42bytes
Evicting cache-control: no-cache, no-store, must-revalidate, pre-check=0, post-check=0 which recovers 107bytes
Evicting content-length: 43303 which recovers 51bytes
Evicting content-type: text/html;charset=utf-8 which recovers 67bytes
Need to recover: 44byes to add x-transaction: 02fad4a8c79c2e68
Evicting date: Sat, 15 Mar 2014 17:23:16 GMT which recovers 65bytes
Header table is 4075bytes

diff --git a/okhttp/src/main/java/com/squareup/okhttp/internal/spdy/HpackDraft05.java b/okhttp/src/main/java/com/squareup/okhttp/internal/spdy/HpackDraft05.java
index f125711..a409720 100644
--- a/okhttp/src/main/java/com/squareup/okhttp/internal/spdy/HpackDraft05.java
+++ b/okhttp/src/main/java/com/squareup/okhttp/internal/spdy/HpackDraft05.java
@@ -162,6 +162,7 @@ final class HpackDraft05 {
       if (bytesToRecover > 0) {
         // determine how many headers need to be evicted.
         for (int j = headerTable.length - 1; j >= nextHeaderIndex && bytesToRecover > 0; j--) {
+          System.err.printf("Evicting %s which recovers %sbytes%n", headerTable[j], headerTable[j].hpackSize);
           bytesToRecover -= headerTable[j].hpackSize;
           headerTableByteCount -= headerTable[j].hpackSize;
           headerCount--;
@@ -204,6 +205,7 @@ final class HpackDraft05 {
           }
         }
       }
+      System.err.printf("Header table is %sbytes%n", headerTableByteCount);
     }

     private void clearReferenceSet() {
@@ -306,6 +308,9 @@ final class HpackDraft05 {

       // Evict headers to the required length.
       int bytesToRecover = (headerTableByteCount + delta) - maxHeaderTableByteCount;
+      if (bytesToRecover > 0) {
+        System.err.printf("Need to recover: %sbyes to add %s%n", bytesToRecover, entry);
+      }
       int entriesEvicted = evictToRecoverBytes(bytesToRecover);

       if (index == -1) {

[jpinner]

@adriancole is that run against https://gist.github.com/swankjesse/9567930 ?

[codefromthecrypt]

I suspect one issue might be that we are not taking into account huffman when doing length calculations..

[codefromthecrypt]

doing header table size calculations I mean

[codefromthecrypt]

no I was running against twitter directly.. lemme try against that data.

[codefromthecrypt]

@jpinner

Here's the output on that.

Header table is 1558bytes
Header table is 2298bytes
Header table is 2899bytes
Header table is 3449bytes
[:status: 200, cache-control: no-cache, no-store, must-revalidate, pre-check=0, post-check=0, content-encoding: gzip, content-length: 10715, content-type: text/html;charset=utf-8, date: Sat, 15 Mar 2014 13:52:14 GMT, expires: Tue, 31 Mar 1981 05:00:00 GMT, last-modified: Sat, 15 Mar 2014 13:52:14 GMT, ms: A, pragma: no-cache, server: tfe, set-cookie: _twitter_sess=BAh7CSIKZmxhc2hJQzonQWN0aW9uQ29udHJvbGxlcjo6Rmxhc2g6OkZsYXNo%250ASGFzaHsABjoKQHVzZWR7ADoHaWQiJWQ1YTFkOWM3Nzk0ZDQ1YjBiNjI3YTll%250AN2Y1MDk2ZjBmOgxjc3JmX2lkIiViYjllNDI1MWI3YWRmNjEyZjVkNjg0Yzg1%250ANDBlOThkNjoPY3JlYXRlZF9hdGwrCCmyA8ZEAQ%253D%253D--89231da03e8640f33b0e9757a465fe43e393adaa; Path=/; Domain=.twitter.com; Secure; HTTPOnly�guest_id=v1%3A139489153488638631; Domain=.twitter.com; Path=/; Expires=Mon, 14-Mar-2016 13:52:14 UTC, status: 200 OK, strict-transport-security: max-age=631138519, x-content-type-options: nosniff, x-frame-options: SAMEORIGIN, x-transaction: 6858e08857742d51, x-ua-compatible: IE=edge,chrome=1, x-xss-protection: 1; mode=block]
[:status: 200, cache-control: no-cache, no-store, must-revalidate, pre-check=0, post-check=0, content-encoding: gzip, content-type: text/html;charset=utf-8, expires: Tue, 31 Mar 1981 05:00:00 GMT, ms: A, pragma: no-cache, server: tfe, status: 200 OK, strict-transport-security: max-age=631138519, x-content-type-options: nosniff, x-frame-options: SAMEORIGIN, x-ua-compatible: IE=edge,chrome=1, x-xss-protection: 1; mode=block, content-length: 10712, date: Sat, 15 Mar 2014 13:52:15 GMT, last-modified: Sat, 15 Mar 2014 13:52:15 GMT, set-cookie: _twitter_sess=BAh7CToHaWQiJTNhNGY3ODkxYjVlYTM3YThhZjkyYTE0N2IwY2MwYTU1Igpm%250AbGFzaElDOidBY3Rpb25Db250cm9sbGVyOjpGbGFzaDo6Rmxhc2hIYXNoewAG%250AOgpAdXNlZHsAOg9jcmVhdGVkX2F0bCsIMLMDxkQBOgxjc3JmX2lkIiU2M2Mw%250AZTM5OTY4MmJjNmRlOGVmZGJlMTMxNDE2YTU5MQ%253D%253D--a9cda668f5cb1673fee586967633d5fab3bcda4e; Path=/; Domain=.twitter.com; Secure; HTTPOnly�guest_id=v1%3A139489153515074887; Domain=.twitter.com; Path=/; Expires=Mon, 14-Mar-2016 13:52:15 UTC, x-transaction: dd6ba36a13733998]
[:status: 200, cache-control: no-cache, no-store, must-revalidate, pre-check=0, post-check=0, content-encoding: gzip, content-type: text/html;charset=utf-8, expires: Tue, 31 Mar 1981 05:00:00 GMT, ms: A, pragma: no-cache, server: tfe, status: 200 OK, strict-transport-security: max-age=631138519, x-content-type-options: nosniff, x-frame-options: SAMEORIGIN, x-ua-compatible: IE=edge,chrome=1, x-xss-protection: 1; mode=block, date: Sat, 15 Mar 2014 13:52:15 GMT, last-modified: Sat, 15 Mar 2014 13:52:15 GMT, content-length: 10713, set-cookie: _twitter_sess=BAh7CSIKZmxhc2hJQzonQWN0aW9uQ29udHJvbGxlcjo6Rmxhc2g6OkZsYXNo%250ASGFzaHsABjoKQHVzZWR7ADoMY3NyZl9pZCIlYTgwZTk4NTQ4NTI3Y2ExMjU1%250ANjYxZWNjYWMxYWE5MmQ6B2lkIiVlZDJlOWI5ZDdiNDkyY2RhMWMxN2I5OGZi%250AMzAzZTljMjoPY3JlYXRlZF9hdGwrCKOzA8ZEAQ%253D%253D--4ca493dde00db627e9bd56df8385f1f638095263; Path=/; Domain=.twitter.com; Secure; HTTPOnly�guest_id=v1%3A139489153526624262; Domain=.twitter.com; Path=/; Expires=Mon, 14-Mar-2016 13:52:15 UTC, x-transaction: 8b9ea5ea2d32b4d6]
[:status: 200, cache-control: no-cache, no-store, must-revalidate, pre-check=0, post-check=0, content-encoding: gzip, content-type: text/html;charset=utf-8, expires: Tue, 31 Mar 1981 05:00:00 GMT, ms: A, pragma: no-cache, server: tfe, status: 200 OK, strict-transport-security: max-age=631138519, x-content-type-options: nosniff, x-frame-options: SAMEORIGIN, x-ua-compatible: IE=edge,chrome=1, x-xss-protection: 1; mode=block, content-length: 10712, date: Sat, 15 Mar 2014 13:52:15 GMT, last-modified: Sat, 15 Mar 2014 13:52:15 GMT, set-cookie: _twitter_sess=BAh7CToHaWQiJTA4YzQ1MjQ0NWUxNzJmNzZhMmE0NzczMGNmMmFlYjk2Igpm%250AbGFzaElDOidBY3Rpb25Db250cm9sbGVyOjpGbGFzaDo6Rmxhc2hIYXNoewAG%250AOgpAdXNlZHsAOg9jcmVhdGVkX2F0bCsIE7QDxkQBOgxjc3JmX2lkIiU1YTFh%250AYjVjYjYyZDFjM2MzNDk5MTM3ZDEzZWE1ZWE4OA%253D%253D--96cfd8839cc1d52aebbe8cdee39112c6c55d1046; Path=/; Domain=.twitter.com; Secure; HTTPOnly�guest_id=v1%3A139489153537781783; Domain=.twitter.com; Path=/; Expires=Mon, 14-Mar-2016 13:52:15 UTC, x-transaction: 98d7571cd56f5857]
[:status: 200, cache-control: no-cache, no-store, must-revalidate, pre-check=0, post-check=0, content-encoding: gzip, content-length: 10715, content-type: text/html;charset=utf-8, expires: Tue, 31 Mar 1981 05:00:00 GMT, ms: A, pragma: no-cache, server: tfe, status: 200 OK, strict-transport-security: max-age=631138519, x-content-type-options: nosniff, x-frame-options: SAMEORIGIN, x-ua-compatible: IE=edge,chrome=1, x-xss-protection: 1; mode=block, date: Sat, 15 Mar 2014 13:52:15 GMT, last-modified: Sat, 15 Mar 2014 13:52:15 GMT, set-cookie: _twitter_sess=BAh7CSIKZmxhc2hJQzonQWN0aW9uQ29udHJvbGxlcjo6Rmxhc2g6OkZsYXNo%250ASGFzaHsABjoKQHVzZWR7ADoMY3NyZl9pZCIlMDhmYzExMjI0MTZlZTI2YzRi%250ANGE5YzVkYzQzNTIyMzQ6B2lkIiUxNjZlMGMzODBhYTZkNmEwZjc0ZGVlMzZh%250AODhmZjNjODoPY3JlYXRlZF9hdGwrCNW0A8ZEAQ%253D%253D--9b417ea19bf43b2b505ddfb18eec866bbd7c6282; Path=/; Domain=.twitter.com; Secure; HTTPOnly�guest_id=v1%3A139489153555868034; Domain=.twitter.com; Path=/; Expires=Mon, 14-Mar-2016 13:52:15 UTC, x-transaction: 7a85bfec974c4b90]
Header table is 3999bytes
Need to recover: 443byes to add set-cookie: _twitter_sess=BAh7CSIKZmxhc2hJQzonQWN0aW9uQ29udHJvbGxlcjo6Rmxhc2g6OkZsYXNo%250ASGFzaHsABjoKQHVzZWR7ADoHaWQiJWFmMzI3OTBkYzhmMTBmMzU1MTQ1NGJj%250ANmEwMTkwMzJmOg9jcmVhdGVkX2F0bCsIQrUDxkQBOgxjc3JmX2lkIiU1ZjAw%250ANjAxY2I3OTcxN2Q4OTcyN2I1ZWFmNjhkY2U2YQ%253D%253D--c2993aafa80007aee98055fb7a22d56a18f5d989; Path=/; Domain=.twitter.com; Secure; HTTPOnly�guest_id=v1%3A139489153567956965; Domain=.twitter.com; Path=/; Expires=Mon, 14-Mar-2016 13:52:15 UTC
Evicting :status: 200 which recovers 42bytes
Evicting cache-control: no-cache, no-store, must-revalidate, pre-check=0, post-check=0 which recovers 107bytes
Evicting content-encoding: gzip which recovers 52bytes
Evicting content-length: 10715 which recovers 51bytes
Evicting content-type: text/html;charset=utf-8 which recovers 67bytes
Evicting date: Sat, 15 Mar 2014 13:52:14 GMT which recovers 65bytes
Evicting expires: Tue, 31 Mar 1981 05:00:00 GMT which recovers 68bytes
Need to recover: 52byes to add x-transaction: 82612e2a36a5f04d
Evicting last-modified: Sat, 15 Mar 2014 13:52:14 GMT which recovers 74bytes
Header table is 4074bytes
[ms: A, pragma: no-cache, server: tfe, status: 200 OK, strict-transport-security: max-age=631138519, x-content-type-options: nosniff, x-frame-options: SAMEORIGIN, x-ua-compatible: IE=edge,chrome=1, x-xss-protection: 1; mode=block, date: Sat, 15 Mar 2014 13:52:15 GMT, last-modified: Sat, 15 Mar 2014 13:52:15 GMT, content-length: 10711, set-cookie: _twitter_sess=BAh7CSIKZmxhc2hJQzonQWN0aW9uQ29udHJvbGxlcjo6Rmxhc2g6OkZsYXNo%250ASGFzaHsABjoKQHVzZWR7ADoHaWQiJWFmMzI3OTBkYzhmMTBmMzU1MTQ1NGJj%250ANmEwMTkwMzJmOg9jcmVhdGVkX2F0bCsIQrUDxkQBOgxjc3JmX2lkIiU1ZjAw%250ANjAxY2I3OTcxN2Q4OTcyN2I1ZWFmNjhkY2U2YQ%253D%253D--c2993aafa80007aee98055fb7a22d56a18f5d989; Path=/; Domain=.twitter.com; Secure; HTTPOnly�guest_id=v1%3A139489153567956965; Domain=.twitter.com; Path=/; Expires=Mon, 14-Mar-2016 13:52:15 UTC, x-transaction: 82612e2a36a5f04d]

[codefromthecrypt]

scratch my suspicion about huffman lengths. looks like we indeed should use the non-encoded lengths. That's not to say there's no problem around huffman.

 The lengths are measured on the non-encoded entry name and entry
   value (for the case when a Huffman encoding is used to transmit
   string values).

[codefromthecrypt]

I have a loop running with 1000 streams against https://http2.iijplus.jp/push/test1 It is evicting in a way that isn't dropping status or causing errors. That's again, not to say there's no bug here, just there's only a couple servers running http/2 :P

[jpinner]

I'll decode the opcodes for the last response to see what the encoder thinks is going on.

[jpinner]

The first opcode emits a new huffman-encoded Content-Length (10711) using incremental indexing (0x078321988b).
The second pair of opcodes emits ":status" (at index 32) by toggeling it out of and back into the reference set (0xa0a0).

[jpinner]

@adriancole -- btw the above happens before inserting set-cookie so nothing should have been evicted from the table yet.

[jpinner]

@adriancole @swankjesse
I think I found the bug:

https://github.com/square/okhttp/blob/master/okhttp/src/main/java/com/squareup/okhttp/internal/spdy/HpackDraft05.java#L246

At that line you toggle headers into and out of the reference set, but I think you are missing a call to emittedHeaders.add() if the header was added to the reference set.

From http://tools.ietf.org/html/draft-ietf-httpbis-header-compression-05#section-3.2.1 -- if the indexed entry is in the header table and not in the reference set, it is first emitted, then added to the reference set.

[codefromthecrypt]

actually we do emit the reference set already after toggling. Needs a deeper look.

[codefromthecrypt]

While true that emitting at the line where toggle occurs works, the :status header is a added twice.

looks like the central area to look at is emitReferenceSet() vs readIndexedHeader where toggle occurs.

Gotta run, but hope this helps!

[jpinner]

I don't see where you emit after toggling -- line 189 calls read indexed header where the toggling occurs on line 246.

The header isn't added twice, what happens is that the encoder sees that we are about to evict a header that was in the header set but not emitted because it was already in the reference set. In order to make sure it gets emitted before evicting from the table, it indexes the header twice (once to remove it from the reference set which does not emit it, and then a second time to re-add it to the reference set which emits it immediately). Thus once the header is evicted from the table, it has already been emitted so we no longer need to track it.

[jpinner]

@adriancole to be more specific, it is important that the emission of the header happens immediately in case the header is evicted.

Also it looks like there is a second bug in emitRefernceSet() -- according to the spec, only headers in the reference set that have not already been emitted in this header block should emitted, not all headers in the reference set.

[codefromthecrypt]

@jpinner so I was talking about if I added emission where you mentioned, emitReferenceSet() would emit it a second time, so I think we are saying the same thing. Thanks for clarifying the behavior as it seems to be the info I need to fix this!

[jpinner]

Happy to help. Shameless plug: you could always just use https://github.com/twitter/hpack (v0.5.2 for hpack-draft-05) ;)

[codefromthecrypt]

#652

[swankjesse]

Thanks @adriancole and @jpinner!

[Bajranghudda]

How to solve this in a production app, I am using retrofit 1.9

[Ahmedfir]

I am getting the same issue with OkHttp3. Does anyone have a solution?

[andre-paraense]

I am experiencing the same issue with OkHTTP 3.10.0 and nginx 1.13.12. When we disable http/2, it works. Any solution? Can we help with more information?

[yschimke]

@andre-paraense @Ahmedfir have you got a test server or real url we can test against?