http2_push not pushing the file

[thexeos@…]

Using http2_push directive in location block doesn't push resources. Using Link header (via add_header directive or supplied by backend) makes the browser issue a GET (preload) request, which is not the same.

Configuration file:

listen 127.0.0.1:80 http2;

server_name example.com;
root /var/www;
index index.php index.html;
error_page 404 = @notfound;
http2_push_preload on;

location = /manifest.json {
    expires 30d;
    http2_push /logos/logo.png;
    add_header Link "</logos/logo-2x.png>; rel=preload; as=image";
}

(There are many more location blocks, some with regex, some with prefix matching. Except those, there are no other directives in server{} block.)

http{} block has these, plus all the "standard" stuff.

sendfile on;
tcp_nopush on;
tcp_nodelay on;
keepalive_timeout 120;
types_hash_max_size 2048;

server_tokens off;

server_names_hash_bucket_size 64;
server_name_in_redirect off;

Debug log of making request to URL:

...
2019/12/30 16:52:19 [debug] 78078#78078: *22556 using configuration "=/manifest.json"
...
2019/12/30 16:52:19 [debug] 78078#78078: *22556 http filename: "/var/www/manifest.json"
...
2019/12/30 16:52:19 [debug] 78078#78078: *22556 http2 header filter
2019/12/30 16:52:19 [debug] 78078#78078: *22556 http2 output header: ":status: 304"
2019/12/30 16:52:19 [debug] 78078#78078: *22556 http2 output header: "server: nginx"
2019/12/30 16:52:19 [debug] 78078#78078: *22556 http2 output header: "date: Mon, 30 Dec 2019 21:52:19 GMT"
2019/12/30 16:52:19 [debug] 78078#78078: *22556 http2 output header: "last-modified: Thu, 26 Dec 2019 18:53:16 GMT"
2019/12/30 16:52:19 [debug] 78078#78078: *22556 http2 output header: "etag: "5e05019c-390""
2019/12/30 16:52:19 [debug] 78078#78078: *22556 http2 output header: "expires: Wed, 29 Jan 2020 21:52:19 GMT"
2019/12/30 16:52:19 [debug] 78078#78078: *22556 http2 output header: "cache-control: max-age=2592000"
2019/12/30 16:52:19 [debug] 78078#78078: *22556 http2 output header: "link: </logos/logo-2x.png>; rel=preload; as=image"
2019/12/30 16:52:19 [debug] 78078#78078: *22556 http2:1 create HEADERS frame 00005571CFBACBA0: len:164 fin:1
2019/12/30 16:52:19 [debug] 78078#78078: *22556 http cleanup add: 00005571CFBACCA8
2019/12/30 16:52:19 [debug] 78078#78078: *22556 http2 frame out: 00005571CFBACBA0 sid:1 bl:1 len:164
2019/12/30 16:52:19 [debug] 78078#78078: *22556 writev: 173 of 173
2019/12/30 16:52:19 [debug] 78078#78078: *22556 http2:1 HEADERS frame 00005571CFBACBA0 was sent
2019/12/30 16:52:19 [debug] 78078#78078: *22556 http2 frame sent: 00005571CFBACBA0 sid:1 bl:1 len:164
2019/12/30 16:52:19 [debug] 78078#78078: *22556 http finalize request: 0, "/manifest.json?" a:1, c:1
2019/12/30 16:52:19 [debug] 78078#78078: *22556 http request count:1 blk:0
2019/12/30 16:52:19 [debug] 78078#78078: *22556 http2 close stream 1, queued 0, processing 1, pushing 0
...
2019/12/30 16:52:19 [debug] 78078#78078: *22556 http2 HEADERS frame sid:3 depends on 0 excl:0 weight:16
...
2019/12/30 16:52:19 [debug] 78078#78078: *22556 http2 table add: ":path: /logos/logo-2x.png"
...

(observation: 'http2 preload' is not appearing after 'http2 header filter' in debug log)

[Ruslan Ermilov]

Works for me:

2019/12/31 08:31:04 [debug] 69530#24016936: *1 using configuration "=/manifest.json"
...
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http filename: "./html/manifest.json"
...
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 header filter
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 push resources
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 push resource
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 pushing:0 limit:10
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 push header: ":method: GET"
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 push header: ":path: /logos/logo.png"
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 push header: ":scheme: http"
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 push header: ":authority: 127.1:8001"
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 push header: "accept-encoding: gzip, deflate"
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 push header: "user-agent: nghttp2/1.37.0"
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2:13 create PUSH_PROMISE frame 000060600001EAA0: sid:2 len:52
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 push stream sid:2 depends on 13 excl:0 weight:16
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http uri: "/logos/logo.png"
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http args: ""
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http exten: "png"
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 parse link: "</logos/logo-2x.png>; rel=preload; as=image"
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 push resource
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 pushing:1 limit:10
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 push header: ":method: GET"
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 push header: ":path: /logos/logo-2x.png"
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 push header: ":scheme: http"
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 push header: ":authority: 127.1:8001"
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 push header: "accept-encoding: gzip, deflate"
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 push header: "user-agent: nghttp2/1.37.0"
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2:13 create PUSH_PROMISE frame 000060600001EB00: sid:4 len:54
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 push stream sid:4 depends on 13 excl:0 weight:16
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http uri: "/logos/logo-2x.png"
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http args: ""
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http exten: "png"
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 output header: ":status: 304"
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 output header: "server: nginx/1.17.7"
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 output header: "date: Tue, 31 Dec 2019 05:31:04 GMT"
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 output header: "last-modified: Tue, 31 Dec 2019 05:25:41 GMT"
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 output header: "etag: "5e0adbd5-0""
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 output header: "expires: Thu, 30 Jan 2020 05:31:04 GMT"
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 output header: "cache-control: max-age=2592000"
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2 output header: "link: </logos/logo-2x.png>; rel=preload; as=image"
2019/12/31 08:31:04 [debug] 69530#24016936: *1 http2:13 create HEADERS frame 000060600001EB60: len:168 fin:1

[Ruslan Ermilov]

There are no http2 preload debug messages in nginx, search for http2 push resource and strings above and below it instead.

[thexeos@…]

grepping through the debug logs, there are no mentions of word push anywhere. I'll provide more insight into the setup, I think that might be the cause of this: there is HAProxy listening on public port receiving HTTP/2 over TLS. It performs offloading and routes requests to local or remote (same rack, over TCP) nginx instances exclusively with "proto h2" options (meaning no ALPN used, no SSL verification, practically making it h2c). On production system, there is an application running (fastcgi), which is reading custom headers set by HAProxy to determine if HTTP/2 was used by the client, and if so it adds the Link header to response.

In debug log, there is http2 header: ":scheme: https", so I am wondering if there is mismatch between :scheme and nginx receiving h2c? And if so, what is the correct solution here?

[Ruslan Ermilov]

If the client has not disabled "pushes" via the SETTINGS frame, and it wasn't a HEAD request, and given that the debug log excerpts correspond to the provided nginx's configuration snippet, the debug log should at least have the string http2 push resources from ngx_http_v2_push_resources().

The :scheme issue seems to be an already fixed bug in HAProxy, but it looks irrelevant anyway.

If this problem is still actual, please provide a full debug log of the request with the given configuration. It's really hard to tell what's going on without the full debug log.

[Ruslan Ermilov]

Feedback timeout.

If the problem persists, please provide the requested debug log.