Regression in 1.14 when following upstream redirects

[vedranf]

Hello,

There is a problem when nginx is configured to try to follow redirects (301)
from upstream server in order to cache responses being directed to, rather
than the short redirect itself. This worked in 1.12 and earlier releases.
Here is the simplified configuration I use and which used to work:

server { proxy_cache something;
location / { proxy_pass http://upstream; }
location @handle3XX {
  proxy_cache_key ...;
  set $target $upstream_http_location;
  proxy_pass $target;
  proxy_redirect off;
  internal;
}}

With 1.12 this would cause nginx to follow the redirect and return the
response after the (absolute) redirect. With 1.14 something weird is going
on, it returns 301 back to the client and upstream_cache_status variable is
set to HIT (even though 3XX aren't configured to be cached at all). If I
repeat the request, I get 500 with "invalid URL prefix in" because $target
is now empty as it didn't connect to the upstream at all.

Debug logs for the critical part show this below (trimmed). Common for both
nginx versions:

2018/05/14 16:06:20 [debug] 6280#6280: *1728 http upstream request: "/path"
2018/05/14 16:06:20 [debug] 6280#6280: *1728 http upstream process header
2018/05/14 16:06:20 [debug] 6280#6280: *1728 http proxy status 301 "301
Moved Permanently"
2018/05/14 16:06:20 [debug] 6280#6280: *1728 http proxy header: "Date: Mon,
14 May 2018 16:06:20 GMT"
2018/05/14 16:06:20 [debug] 6280#6280: *1728 http proxy header done
2018/05/14 16:06:20 [debug] 6280#6280: *1728 http file cache free, fd: -1
2018/05/14 16:06:20 [debug] 6280#6280: *1728 finalize http upstream request:
301
2018/05/14 16:06:20 [debug] 6280#6280: *1728 finalize http proxy request
2018/05/14 16:06:20 [debug] 6280#6280: *1728 free keepalive peer
2018/05/14 16:06:20 [debug] 6280#6280: *1728 free rr peer 2 0
2018/05/14 16:06:20 [debug] 6280#6280: *1728 close http upstream connection:
393
2018/05/14 16:06:20 [debug] 6280#6280: *1728 http finalize request: 301,
"/path" a:1, c:1
2018/05/14 16:06:20 [debug] 6280#6280: *1728 http special response: 301,
"/path"
2018/05/14 16:06:20 [debug] 6280#6280: *1728 test location: "@handle3XX"
2018/05/14 16:06:20 [debug] 6280#6280: *1728 using location: @handle3XX
"/path"
2018/05/14 16:06:20 [debug] 6280#6280: *1728 http script complex value
2018/05/14 16:06:20 [debug] 6280#6280: *1728 http script var:
"https://site.com/path
2018/05/14 16:06:20 [debug] 6280#6280: *1728 http script set $target
2018/05/14 16:06:20 [debug] 6280#6280: *1728 http script var:
"https://site.com/path"
2018/05/14 16:06:20 [debug] 6280#6280: *1728 http init upstream, client
timer: 0
2018/05/14 16:06:20 [debug] 6280#6280: *1728 http script var: "/path"
2018/05/14 16:06:20 [debug] 6280#6280: *1728 http cache key: "..."

Now it starts to differ, 1.12:

2018/05/14 16:06:20 [debug] 6280#6280: *1728 add cleanup: 000000000B922848
2018/05/14 16:06:20 [debug] 6280#6280: *1728 http file cache exists: -5 e:0
2018/05/14 16:06:20 [debug] 6280#6280: *1728 cache file:
"/home/cache/63/67/e/1fb991ad8a2289a3c617c43166ae6763"
2018/05/14 16:06:20 [debug] 6280#6280: *1728 add cleanup: 000000000B922860
2018/05/14 16:06:20 [debug] 6280#6280: *1728 http file cache lock u:1 wt:0
2018/05/14 16:06:20 [debug] 6280#6280: *1728 http upstream cache: -5
2018/05/14 16:06:20 [debug] 6280#6280: *1728 http proxy header:
"GET /path HTTP/1.1
Host: site.com
Connection: close
Accept: */*
"
2018/05/14 16:06:20 [debug] 6280#6280: *1728 http cleanup add:
0000000003F06B58
2018/05/14 16:06:20 [debug] 6280#6280: *1728 http upstream resolve: "/path"
2018/05/14 16:06:20 [debug] 6280#6280: *1728 name was resolved to x.x.x.x
and now goes on to proxy request to new upstream from the location response
header ...

while on 1.14:

2018/05/14 16:19:08 [debug] 8112#8112: *45398 add cleanup: 000000000D97C620
2018/05/14 16:19:08 [debug] 8112#8112: *45398 http file cache exists: 0 e:0
2018/05/14 16:19:08 [debug] 8112#8112: *45398 http upstream cache: 301
2018/05/14 16:19:08 [debug] 8112#8112: *45398 http finalize request: 301,
"/path" a:1, c:3
2018/05/14 16:19:08 [debug] 8112#8112: *45398 http special response: 301,
"/path"
2018/05/14 16:19:08 [debug] 8112#8112: *45398 http script var: "HIT"
2018/05/14 16:19:08 [debug] 8112#8112: *45398 HTTP/1.1 301 Moved
Permanently
2018/05/14 16:19:08 [debug] 8112#8112: *45398 write new buf t:1 f:0
000000000E02B938, pos 000000000E02B938, size: 348 file: 0, size: 0
2018/05/14 16:19:08 [debug] 8112#8112: *45398 http write filter: l:1 f:0
s:348
2018/05/14 16:19:08 [debug] 8112#8112: *45398 http write filter limit
16777216
2018/05/14 16:19:08 [debug] 8112#8112: *45398 writev: 348 of 348
2018/05/14 16:19:08 [debug] 8112#8112: *45398 http write filter
0000000000000000
2018/05/14 16:19:08 [debug] 8112#8112: *45398 http finalize request: 0,
"/path" a:1, c:3
2018/05/14 16:19:08 [debug] 8112#8112: *45398 http request count:3 blk:0
2018/05/14 16:19:08 [debug] 8112#8112: *45398 http finalize request: -4,
"/path" a:1, c:2
2018/05/14 16:19:08 [debug] 8112#8112: *45398 http request count:2 blk:0
2018/05/14 16:19:08 [debug] 8112#8112: *45398 http finalize request: -4,
"/path" a:1, c:1
and it basically never proxies to new upstream server ...

1.12 eventually responds with 200 or 404 from where the first upstream
redirected nginx to, while 1.14 just passes 301 from the first upstream.
Configurations when testing were the same, only nginx binary was different.

Regards,
Vedran

Posted at Nginx Forum: https://forum.nginx.org/read.php?2,279787,279787#msg-279787