奇怪的问题，子请求连接超时，访问日志显示200，浏览器显示nginx错误日志。

z329224946 · 2012-10-26T09:35:34+00:00

Hello! 2012/10/25 龚开晖: > Hi, 春哥，我最近在试用nginx lua模块&#x768...

奇怪的问题，子请求连接超时，访问日志显示200，浏览器显示nginx错误日志。

z329224946

我使用local data="">

location /proxy {

internal;

proxy_pass $scheme://$http_host$request_uri;

proxy_set_header Accept-Encoding '';

proxy_redirect off;

}

一天有那么一两次出现如下情况：

访问日志里显示：

192.168.2.208 - - [25/Oct/2012:19:13:40 +0000] "GET /static/images/iphone_switch.png?e9c3fed6aab8 HTTP/1.1" 200 2722 "http://my.xxx.com/my-websites/cloud-

config/yyy.com/" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.1; Trident/4.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729; Media

Center PC 6.0; .NET4.0C)"

错误日志里却显示：

2012/10/25 19:13:40 [error] 10498#0: *383193 connect() failed (110: Connection timed out) while connecting to upstream, client: 192.168.2.208, server: localh

ost, request: "GET /static/images/iphone_switch.png?e9c3fed6aab8 HTTP/1.1", subrequest: "/proxy", upstream: "http://1.1.1.1:80/static/images/iphone_sw

itch.png?e9c3fed6aab8", host: "my.xxx.com", referrer: "http://my.xxx.com/my-websites/cloud-config/yyy.com/"

拓扑结构是这样的：

客户端->varnish->openresty>源服务器

varnish里判断如果openrest返回状态码是504，则返回403给客户端，但是上面这种情况就直接返回了nginx的错误页面：

这里是请求一张图片，图片的大小是 2722,根据访问日志，说明openresty已经正常取得图片内容，而openresty又报了一个连接超时的错误，导致状态码是200，而响应体是nginx的错误页面。

这种情况偶尔出现。

agentzh

Hello!

2012/10/25 朱茂海
>
> 这里是请求一张图片，图片的大小是 2722,根据访问日志，说明openresty已经正常取得图片内容，而openresty又报了一个连接超时的错误，导致状态码是200，而响应体是nginx的错误页面。
>
> 这种情况偶尔出现。
>

请确认：

1. 你没有配置 error_page 指令，把 504 和 502 这样的错误码改写为 200；
2. 你使用的是 ngx_openresty 1.2.3.3 及其以上版本中自带的 nginx 核心。因为只有这些版本所包含的 nginx
核心才修正了 ngx_http_upstream 在许多出错条件下不能返回错误给父请求的 bug（见
https://github.com/agentzh/ngx_openresty/blob/master/patches/nginx-1.2.3-nonbuffered-upstream-truncation.patch
）

Best regards,
-agentzh

z329224946

1、没有配置error_page指令

2、nginx version: ngx_openresty/1.2.4.3

On Friday, October 26, 2012 10:22:42 AM UTC+8, agentzh wrote:

Hello!
2012/10/25 朱茂海
>
> 这里是请求一张图片，图片的大小是 2722,根据访问日志，说明openresty已经正常取得图片内容，而openresty又报了一个连接超时的错误，导致状态码是200，而响应体是nginx的错误页面。
>
> 这种情况偶尔出现。
>
请确认：
1. 你没有配置 error_page 指令，把 504 和 502 这样的错误码改写为 200；
2. 你使用的是 ngx_openresty 1.2.3.3 及其以上版本中自带的 nginx 核心。因为只有这些版本所包含的 nginx
核心才修正了 ngx_http_upstream 在许多出错条件下不能返回错误给父请求的 bug（见
https://github.com/agentzh/ngx_openresty/blob/master/patches/nginx-1.2.3-nonbuffered-upstream-truncation.patch
）
Best regards,
-agentzh

agentzh

Hello!

2012/10/25 朱茂海:
> 1、没有配置error_page指令
> 2、nginx version: ngx_openresty/1.2.4.3
>

你的 Lua 代码具体是如何判断子请求的结果的？

请尝试下面这个测试子请求连接超时的例子：

    location /t {
        content_by_lua '
            local res = ngx.location.capture("/proxy")
            ngx.say("status = ", res.status)
        ';
    }

    location /proxy {
        proxy_connect_timeout 100ms;
        proxy_pass http://www.google.com:1234;
    }

在我这里访问 /t 可以得到期望的结果

    $ curl localhost:8080/t
    status = 502

错误日志中也是期望的错误：

    [error] 19692\#0: *1 upstream timed out (110: Connection timed
out) while connecting to upstream

你可以在你本地尝试一下这个例子。

Best regards,
-agentzh

z329224946

是返回502，但是连接超时的返回状态码不是504吗？

还有我上面说的问题是偶尔出现，这个挺难重现的。

On Friday, October 26, 2012 9:35:33 AM UTC+8, 朱茂海 wrote:

我使用local data="">proxy")取得内容，/proxy是反向代理：
location /proxy {
internal;
proxy_pass $scheme://$http_host$request_uri;
proxy_set_header Accept-Encoding '';
proxy_redirect off;
}

一天有那么一两次出现如下情况：
访问日志里显示：
192.168.2.208 - - [25/Oct/2012:19:13:40 +0000] "GET /static/images/iphone_switch.png?e9c3fed6aab8 HTTP/1.1" 200 2722 "http://my.xxx.com/my-websites/cloud-
config/yyy.com/" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.1; Trident/4.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729; Media
Center PC 6.0; .NET4.0C)"

错误日志里却显示：
2012/10/25 19:13:40 [error] 10498#0: *383193 connect() failed (110: Connection timed out) while connecting to upstream, client: 192.168.2.208, server: localh
ost, request: "GET /static/images/iphone_switch.png?e9c3fed6aab8 HTTP/1.1", subrequest: "/proxy", upstream: "http://1.1.1.1:80/static/images/iphone_sw
itch.png?e9c3fed6aab8", host: "my.xxx.com", referrer: "http://my.xxx.com/my-websites/cloud-config/yyy.com/"

拓扑结构是这样的：
客户端->varnish->openresty>源服务器

varnish里判断如果openrest返回状态码是504，则返回403给客户端，但是上面这种情况就直接返回了nginx的错误页面：
这里是请求一张图片，图片的大小是 2722,根据访问日志，说明openresty已经正常取得图片内容，而openresty又报了一个连接超时的错误，导致状态码是200，而响应体是nginx的错误页面。
这种情况偶尔出现。

agentzh

Hello!

2012/10/25 朱茂海
>
> 是返回502，但是连接超时的返回状态码不是504吗？
> 还有我上面说的问题是偶尔出现，这个挺难重现的。
>

Nginx 核心中的 ngx_http_upstream 在这里就是返回 502，对此它并没有针对 NGX_ETIMEDOUT 错误区别对待。

刚刚又在我本地摸似出了和你得到的一模一样的错误消息：

    [error] 26093\#0: *1 connect() failed (110: Connection timed out)
while connecting to upstream

访问上封邮件中给出的那个示例接口，我得到的输出依然是

    status = 502

这个错误消息只有 ngx_http_upstream_test_connect
函数才会产生，所以我觉得我这里走的代码路径应该和你的一致。这个代码路径确实不太容易直接走到。

你还没有回答我上封邮件提出的那个问题：“你的 Lua 代码具体是如何判断子请求的结果的？”请确认你的
ngx.location.capture() 调用返回的 res.status 的值。

Best regards,
-agentzh

z329224946

local data="">

if data.status == 200 then

ngx.say(data.body);

else

ngx.exec("/proxy");

end

On Friday, October 26, 2012 11:46:28 AM UTC+8, agentzh wrote:

Hello!
2012/10/25 朱茂海
>
> 是返回502，但是连接超时的返回状态码不是504吗？
> 还有我上面说的问题是偶尔出现，这个挺难重现的。
>
Nginx 核心中的 ngx_http_upstream 在这里就是返回 502，对此它并没有针对 NGX_ETIMEDOUT 错误区别对待。
刚刚又在我本地摸似出了和你得到的一模一样的错误消息：
[error] 26093\#0: *1 connect() failed (110: Connection timed out)
while connecting to upstream
访问上封邮件中给出的那个示例接口，我得到的输出依然是
status = 502
这个错误消息只有 ngx_http_upstream_test_connect
函数才会产生，所以我觉得我这里走的代码路径应该和你的一致。这个代码路径确实不太容易直接走到。
你还没有回答我上封邮件提出的那个问题：“你的 Lua 代码具体是如何判断子请求的结果的？”请确认你的
ngx.location.capture() 调用返回的 res.status 的值。
Best regards,
-agentzh

agentzh

Hello!

2012/10/25 朱茂海:
> local data=ngx.location.capture("/proxy")
> if data.status == 200 then
>           ngx.say(data.body);
> else
>           ngx.exec("/proxy");
> end
>

你能开启 log_subrequest 配置指令么？

    http://wiki.nginx.org/HttpCoreModule#log_subrequest

或者你在 else 之后加入一行 ngx.log() 语句打一行日志。我需要确认子请求的响应状态码 :)

由于你在另一个代码分支中使用了 ngx.exec() 发起了内部跳转，所以请你确认你得到的 nginx 出错页响应是第一个代码分支的
ngx.say() 生成的，而不是第二个代码分支产生的。

Best regards,
-agentzh

z329224946

这个问题目前无法重现，原因可以肯定的是，是由于有人大量扫描varnish的ip，然后这个ip的请求转发给nginx，nginx再转发请求，导致出现大量的connetion timeout的错误，这一大量的connetion timeout，致使nginx处理已经从后端正常返回请求体的时候误判。

On Friday, October 26, 2012 12:10:30 PM UTC+8, agentzh wrote:

Hello!
2012/10/25 朱茂海:
> local data="">proxy")
> if data.status == 200 then
> ngx.say(data.body);
> else
> ngx.exec("/proxy");
> end
>
你能开启 log_subrequest 配置指令么？
http://wiki.nginx.org/HttpCoreModule#log_subrequest
或者你在 else 之后加入一行 ngx.log() 语句打一行日志。我需要确认子请求的响应状态码 :)
由于你在另一个代码分支中使用了 ngx.exec() 发起了内部跳转，所以请你确认你得到的 nginx 出错页响应是第一个代码分支的
ngx.say() 生成的，而不是第二个代码分支产生的。
Best regards,
-agentzh

z329224946

现在已经在varnish层屏蔽掉了这个ip的请求。

On Friday, October 26, 2012 12:47:22 PM UTC+8, 朱茂海 wrote:

这个问题目前无法重现，原因可以肯定的是，是由于有人大量扫描varnish的ip，然后这个ip的请求转发给nginx，nginx再转发请求，导致出现大量的connetion timeout的错误，这一大量的connetion timeout，致使nginx处理已经从后端正常返回请求体的时候误判。

On Friday, October 26, 2012 12:10:30 PM UTC+8, agentzh wrote:
Hello!
2012/10/25 朱茂海:
> local data="">proxy")
> if data.status == 200 then
> ngx.say(data.body);
> else
> ngx.exec("/proxy");
> end
>
你能开启 log_subrequest 配置指令么？
http://wiki.nginx.org/HttpCoreModule#log_subrequest
或者你在 else 之后加入一行 ngx.log() 语句打一行日志。我需要确认子请求的响应状态码 :)
由于你在另一个代码分支中使用了 ngx.exec() 发起了内部跳转，所以请你确认你得到的 nginx 出错页响应是第一个代码分支的
ngx.say() 生成的，而不是第二个代码分支产生的。
Best regards,
-agentzh

z329224946

子请求的响应状态码是200，响应体却是错误页面。

On Friday, October 26, 2012 12:10:30 PM UTC+8, agentzh wrote:

Hello!
2012/10/25 朱茂海:
> local data="">proxy")
> if data.status == 200 then
> ngx.say(data.body);
> else
> ngx.exec("/proxy");
> end
>
你能开启 log_subrequest 配置指令么？
http://wiki.nginx.org/HttpCoreModule#log_subrequest
或者你在 else 之后加入一行 ngx.log() 语句打一行日志。我需要确认子请求的响应状态码 :)
由于你在另一个代码分支中使用了 ngx.exec() 发起了内部跳转，所以请你确认你得到的 nginx 出错页响应是第一个代码分支的
ngx.say() 生成的，而不是第二个代码分支产生的。
Best regards,
-agentzh