debugging "writev() failed (32: Broken pipe)"?

[Jim Robinson]

I've got an openresty based proxy application that is periodically emitting an error that indicates its having trouble completing processing for a request.

  With debug logging on what I think I'm seeing here is a 'writev() failed' error that ends up returning an "nginx output filter error" error to my code.

I'm having a hard time understanding whether this error is originating due to a bug in my code or if it's due to something like the socket getting closed by the client.  I was wondering if anyone here might be able to provide some advice on narrowing down the source of the error.

The block of LUA code I see referenced at the start of the operation that ends in the writev error is:

ngx.log(ngx.DEBUG, "streamRange: streaming mode: send(chunk)")

ok, err = send(chunk)

if err ~= nil then

        return ok, err

end

where send() is:

-- send calls ngx.print with buf and then calls ngx.flush

-- an ngx.flush err of 'buffering' is ignored

local function send(buf)

        local ok, err = ngx.print(buf)

        if err ~= nil then

                return ok, err

        end

        ok, err = ngx.flush(true)

        if err ~= nil then

                if err == "buffering" then

                        ok = 1

                        err = nil

                end

        end

        return ok, err

end

The relevant portion of the log appears to be this portion:

2019/05/31 15:06:10 [debug] 31353#0: *12592 [lua] ranges.lua:718: stream(): streamRange: chunk: start:8185, stop:8541, rstart:nil, rstop:nil

2019/05/31 15:06:10 [debug] 31353#0: *12592 [lua] ranges.lua:723: stream(): streamRange: streaming mode: send(chunk)

2019/05/31 15:06:10 [debug] 31353#0: *12592 lua reuse free buf memory 8184 >= 357, cl:0000000000934C28, p:000000000097D970

2019/05/31 15:06:10 [debug] 31353#0: *12592 lua print response

2019/05/31 15:06:10 [debug] 31353#0: *12592 http output filter "/50c2ad00-83f8-11e9-aae4-7831c1d65d4a.atom"

2019/05/31 15:06:10 [debug] 31353#0: *12592 http copy filter: "/50c2ad00-83f8-11e9-aae4-7831c1d65d4a.atom"

2019/05/31 15:06:10 [debug] 31353#0: *12592 lua capture body filter, uri "/50c2ad00-83f8-11e9-aae4-7831c1d65d4a.atom"

2019/05/31 15:06:10 [debug] 31353#0: *12592 http postpone filter "/50c2ad00-83f8-11e9-aae4-7831c1d65d4a.atom" 0000000000934C28

2019/05/31 15:06:10 [debug] 31353#0: *12592 http chunk: 357

2019/05/31 15:06:10 [debug] 31353#0: *12592 write new buf t:1 f:0 0000000000968258, pos 0000000000968258, size: 5 file: 0, size: 0

2019/05/31 15:06:10 [debug] 31353#0: *12592 write new buf t:1 f:0 000000000097D970, pos 000000000097D970, size: 357 file: 0, size: 0

2019/05/31 15:06:10 [debug] 31353#0: *12592 write new buf t:0 f:0 00000000009681B0, pos 00000000005049FD, size: 2 file: 0, size: 0

2019/05/31 15:06:10 [debug] 31353#0: *12592 http write filter: l:0 f:0 s:364

2019/05/31 15:06:10 [debug] 31353#0: *12592 http copy filter: 0 "/50c2ad00-83f8-11e9-aae4-7831c1d65d4a.atom"

2019/05/31 15:06:10 [debug] 31353#0: *12592 lua allocate new chainlink and new buf of size 0, cl:00000000009680C8

2019/05/31 15:06:10 [debug] 31353#0: *12592 http output filter "/50c2ad00-83f8-11e9-aae4-7831c1d65d4a.atom"

2019/05/31 15:06:10 [debug] 31353#0: *12592 http copy filter: "/50c2ad00-83f8-11e9-aae4-7831c1d65d4a.atom"

2019/05/31 15:06:10 [debug] 31353#0: *12592 lua capture body filter, uri "/50c2ad00-83f8-11e9-aae4-7831c1d65d4a.atom"

2019/05/31 15:06:10 [debug] 31353#0: *12592 http postpone filter "/50c2ad00-83f8-11e9-aae4-7831c1d65d4a.atom" 00000000009680C8

2019/05/31 15:06:10 [debug] 31353#0: *12592 http chunk: 0

2019/05/31 15:06:10 [debug] 31353#0: *12592 write old buf t:1 f:0 0000000000968258, pos 0000000000968258, size: 5 file: 0, size: 0

2019/05/31 15:06:10 [debug] 31353#0: *12592 write old buf t:1 f:0 000000000097D970, pos 000000000097D970, size: 357 file: 0, size: 0

2019/05/31 15:06:10 [debug] 31353#0: *12592 write old buf t:0 f:0 00000000009681B0, pos 00000000005049FD, size: 2 file: 0, size: 0

2019/05/31 15:06:10 [debug] 31353#0: *12592 write new buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0

2019/05/31 15:06:10 [debug] 31353#0: *12592 http write filter: l:0 f:1 s:364

2019/05/31 15:06:10 [debug] 31353#0: *12592 http write filter limit 0

2019/05/31 15:06:10 [debug] 31353#0: *12592 writev: -1 of 364

2019/05/31 15:06:10 [info] 31353#0: *12592 writev() failed (32: Broken pipe), client: 10.220.55.250, server: opscache-prod-nginx.example.org, request: "GET /50c2ad00-83f8-11e9-aae4-7831c1d65d4a.atom HTTP/1.1", host: "test-cache.example.org"

2019/05/31 15:06:10 [debug] 31353#0: *12592 http write filter FFFFFFFFFFFFFFFF

2019/05/31 15:06:10 [debug] 31353#0: *12592 http copy filter: -1 "/50c2ad00-83f8-11e9-aae4-7831c1d65d4a.atom"

2019/05/31 15:06:10 [warn] 31353#0: *12592 [lua] ngx_proxy.lua:1410: pass(): ranges.stream error: nginx output filter error, client: 10.220.55.250, server: opscache-prod-nginx.example.org, request: "GET /50c2ad00-83f8-11e9-aae4-7831c1d65d4a.atom HTTP/1.1", host: "test-cache.example.org"

2019/05/31 15:06:10 [info] 31353#0: *12592 [lua] ngx_proxy.lua:411: cleanup(): released proxy lock opscache:1:01a5f049900fa18c59d4fe08b78fde25 at 1559340370, client: 10.220.55.250, server: opscache-prod-nginx.example.org, request: "GET /50c2ad00-83f8-11e9-aae4-7831c1d65d4a.atom HTTP/1.1", host: "test-cache.example.org"

The full session from the debug log is at https://drive.google.com/file/d/1A2gCPa8bcNeVtp_sIwkfCRSymkOrGFAK/view?usp=sharing if that's more useful.

[tokers]

Hello!

The debugging log is self-explained, so a "Broken pipe" error was occurred on your socket.

Maybe you can observe packets on this tcp connection through tcpdump to find the essential reasons 

causing this issue.

Basically calling ngx.print or ngx.say on such a high land doesn't influence the underlying tcp connection,

so I don't believe it's your code's bug.

[Jim Robinson]

Hello,

Ok, thank you.  I had been reluctant to start using the wire sniffing tools as the first choice, since the service in question deals with hundreds of megabytes of requests per second.

Based on your advice I've run tcpdump until I saw one of the errors.  What I see is the proxy sending back a chunked response and client returning two packets, an "ACK" followed immediately by a "FIN, ACK" indicating the client is closing the socket from their end.

From what I can see the response that got cut off is well formed (the chunks are the correct size and end in \r per spec), the client just terminated the socket before all the chunks were sent.