Welcome! Log In Create A New Profile

Advanced

Regression in 1.14 when following upstream redirects

Posted by 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

_______________________________________________
nginx mailing list
nginx@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx
Hello!

On Mon, May 14, 2018 at 01:22:46PM -0400, vedranf wrote:

> 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:

[...]

From the incomplete configuration and debug log snippets you've
provided it looks like your problem if that requests previously
not cached now successfully extracted from cache.

From the snippets you've provided it is not possible to conclude
if the previous behaviour was buggy and now fixed (and your
previous configuration worked due to a bug), or the new behaviour
is incorrect.

There are at least some fixes in 1.13.x which might affect your
configuration. In particular, this fix in 1.13.6 might be
related:

*) Bugfix: cache control headers were ignored when caching errors
intercepted by error_page.

To further investigate things you may want to provide full
configuration which demonstrates the problem, and full debug logs
for requests in both versions.

Please avoid any modifications to configuration and debug logs.
If you want to keep some information private, consider reproducing
the problem in a sandbox without any private information instead.

--
Maxim Dounin
http://mdounin.ru/
_______________________________________________
nginx mailing list
nginx@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx
Hey,


Maxim Dounin Wrote:
-------------------------------------------------------
> Hello!
>
> On Mon, May 14, 2018 at 01:22:46PM -0400, vedranf wrote:
>
> > 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:
> >
>
> From the incomplete configuration and debug log snippets you've
> provided it looks like your problem if that requests previously
> not cached now successfully extracted from cache.
>
> From the snippets you've provided it is not possible to conclude
> if the previous behaviour was buggy and now fixed (and your
> previous configuration worked due to a bug), or the new behaviour
> is incorrect.
>
> There are at least some fixes in 1.13.x which might affect your
> configuration. In particular, this fix in 1.13.6 might be
> related:
>
> *) Bugfix: cache control headers were ignored when caching errors
> intercepted by error_page.

Right, this seems to be causing it. I was able to replicate it only when 3XX
redirect had Cache-Control set. Please look at the minimal configuration at:
https://pastebin.com/tSqH4YJt
with 1.12 you always get 204 response from 127.0.0.1:8181, with 1.14 first
response is 204, but the subsequent responses are 500 with invalid URL
prefix in "" error because in the second attempt request never goes to
upstream (perhaps it assumes file is supposed to be in cache) and the
variable is empty.

Regards,
Vedran

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

_______________________________________________
nginx mailing list
nginx@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx
Hello!

On Wed, May 16, 2018 at 10:08:23AM -0400, vedranf wrote:

> Hey,
>
>
> Maxim Dounin Wrote:
> -------------------------------------------------------
> > Hello!
> >
> > On Mon, May 14, 2018 at 01:22:46PM -0400, vedranf wrote:
> >
> > > 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:
> > >
> >
> > From the incomplete configuration and debug log snippets you've
> > provided it looks like your problem if that requests previously
> > not cached now successfully extracted from cache.
> >
> > From the snippets you've provided it is not possible to conclude
> > if the previous behaviour was buggy and now fixed (and your
> > previous configuration worked due to a bug), or the new behaviour
> > is incorrect.
> >
> > There are at least some fixes in 1.13.x which might affect your
> > configuration. In particular, this fix in 1.13.6 might be
> > related:
> >
> > *) Bugfix: cache control headers were ignored when caching errors
> > intercepted by error_page.
>
> Right, this seems to be causing it. I was able to replicate it only when 3XX
> redirect had Cache-Control set. Please look at the minimal configuration at:
> https://pastebin.com/tSqH4YJt
> with 1.12 you always get 204 response from 127.0.0.1:8181, with 1.14 first
> response is 204, but the subsequent responses are 500 with invalid URL
> prefix in "" error because in the second attempt request never goes to
> upstream (perhaps it assumes file is supposed to be in cache) and the
> variable is empty.

Ok, thanks you for confirming. So your configuration relied on a
bug which is now fixed. An obvious workaround would be to disable
looking into Cache-Control / Expires headers using the
proxy_ignore_headers directive (http://nginx.org/r/proxy_ignore_headers),
so nginx will cache things only based on proxy_cache_valid.

--
Maxim Dounin
https://xkcd.com/1172/
_______________________________________________
nginx mailing list
nginx@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx
Sorry, only registered users may post in this forum.

Click here to login