Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

transfer closed with 16467 bytes remaining to read #44

Closed
dup2 opened this issue Apr 9, 2015 · 8 comments · Fixed by #103
Closed

transfer closed with 16467 bytes remaining to read #44

dup2 opened this issue Apr 9, 2015 · 8 comments · Fixed by #103

Comments

@dup2
Copy link
Contributor

dup2 commented Apr 9, 2015

We use mod_zip with nginx 1.6.3 serving zip files with HTTPS (openssl 1.0.1k).

For a list of 3 files, we can reproduce an error where the client does not receive the full zip archive but experiences a timeout with the error above as not all data announced in "Content-Length" is sent by the server.

The response body (as generated by a rails application is)

a6f0fd29 28763 /data/X/200%20NM/200%20NM.xml 200 NM/200 NM.xml
c43dfa28 1386 /data/X/Media/foo.png Media/foo.png
32b4e3ce 1203 /data/X/66C9EB32CB5F4A1B95F3CA1D6BE0C5B4.png 66C9EB32CB5F4A1B95F3CA1D6BE0C5B4.png

The response header is (curl output)

< Date: Thu, 09 Apr 2015 22:51:43 GMT
< Content-Type: application/zip
< Content-Length: 31904
< Connection: keep-alive
< Status: 200 OK
< Content-Disposition: attachment; filename=bulletin-1428619903-7729.zip

The transfer is stalled after 15437 bytes.

The most strange thing is that the size of the second file matters (the 1386 bytes) but not the content. If we reorder the body lines for mod_zip to have "Media/foo.png" at the end, it works without any issues.

When we change the size of the file (by adding random bytes), it works again. When the file size (random data) is between 1285 and 1386 bytes, the transfer is always stalled.

The error log of nginx (even with debugging enabled) does not show errors but in turn complains about the client having timed out (after 60 seconds, the keep-alive timeout) with "client timed out (110: Connection timed out) while sending response to client"

So both client and server seem to wait for each other and then timeout.

@tiff
Copy link

tiff commented May 21, 2015

same issue here, anybody got a workaround for this?

@anthonyryan1
Copy link
Collaborator

I don't have a solution just hypothesizing at the moment.

The file sizes you mentioned strike me as suspiciously close to the default value for postpone_output. If you lower that setting bellow the file size, do you observe a difference?


Having just completed some testing of my own (latest version of mod_zip from git here and nginx 1.9.2), I don't seem to be able to reproduce this issue.

@dup2
Copy link
Contributor Author

dup2 commented Sep 29, 2015

We implemented a workaround for this issue where we create the ZIP archive in the application (instead of through mod_zip) when files within the problematic size range are requested.

However, the very same issue now occurs with different, larger file sizes using nginx 1.9.5 and the latest mod_zip from this repo. We could not nail it down to a size range as before but start to suspect it being a timing/buffer issue again at another level.

The change of postpone_output did not help, in fact when we disable it with "postpone_output 0;", nothing works but a change to the value definitely has an impact.

Anyone another solution here? Or an alternative module for creating zip archives on the fly? Our application delivers up to 3'000 files per request and creating zip archives in the backend is a huge performance and timing issue.

@dup2
Copy link
Contributor Author

dup2 commented Sep 30, 2015

Some more information from the debug log (only related to pieces of mod_zip)

2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: sending pieces, starting with piece 23 of total 46
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: no ranges / sending piece type 2
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: no ranges / sending piece type 0
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: no ranges / sending piece type 1
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: sent 3 pieces, last rc = -2
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: sending pieces, starting with piece 26 of total 46
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: no ranges / sending piece type 2
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: no ranges / sending piece type 0
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: no ranges / sending piece type 1
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: sent 3 pieces, last rc = -2
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: sending pieces, starting with piece 29 of total 46
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: no ranges / sending piece type 2
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: sent 1 pieces, last rc = -2
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: sending pieces, starting with piece 30 of total 46
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: no ranges / sending piece type 0
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: sent 1 pieces, last rc = -2

Afterwards, the response is "stalled" - no more data is sent to the client who suffers from a timeout.

Here is part of the debug log (github refuses this data as file attachment...):

2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: sending pieces, starting with piece 26 of total 46
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: no ranges / sending piece type 2
2015/09/30 09:48:46 [debug] 32152#0: *32 http postpone filter "/fe055d1333ae252bc11c33fb191f4259c1e74e59a52bd38a34/download.json?app=cargo-request-test&fc=15" 0000000002473028
2015/09/30 09:48:46 [debug] 32152#0: *32 write new buf t:0 f:0 0000000000000000, pos 0000000002473098, size: 16 file: 0, size: 0
2015/09/30 09:48:46 [debug] 32152#0: *32 http write filter: l:0 f:0 s:16
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: no ranges / sending piece type 0
2015/09/30 09:48:46 [debug] 32152#0: *32 http postpone filter "/fe055d1333ae252bc11c33fb191f4259c1e74e59a52bd38a34/download.json?app=cargo-request-test&fc=15" 00000000024612E0
2015/09/30 09:48:46 [debug] 32152#0: *32 write old buf t:0 f:0 0000000000000000, pos 0000000002473098, size: 16 file: 0, size: 0
2015/09/30 09:48:46 [debug] 32152#0: *32 write new buf t:0 f:0 0000000000000000, pos 00000000024730F8, size: 90 file: 0, size: 0
2015/09/30 09:48:46 [debug] 32152#0: *32 http write filter: l:0 f:0 s:106
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: no ranges / sending piece type 1
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: subrequest for "/data/users/test/Room1/__Configuration__E-Mail.png?"
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: have a wait context for "/data/users/test/Room1/corporate/staffpics/abr.jpg?"
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: wait "/data/users/test/Room1/corporate/staffpics/abr.jpg?" done
2015/09/30 09:48:46 [debug] 32152#0: *32 posix_memalign: 000000000247B650:4096 @16
2015/09/30 09:48:46 [debug] 32152#0: *32 http subrequest "/data/users/test/Room1/__Configuration__E-Mail.png?"
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: subrequest for "/data/users/test/Room1/__Configuration__E-Mail.png?" result 0, allocating some mem on main request's pool
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: subrequest for "/data/users/test/Room1/__Configuration__E-Mail.png?" result 0
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: sent 3 pieces, last rc = -2
2015/09/30 09:48:46 [debug] 32152#0: *32 http copy filter: -2 "/fe055d1333ae252bc11c33fb191f4259c1e74e59a52bd38a34/download.json?app=cargo-request-test&fc=15"
2015/09/30 09:48:46 [debug] 32152#0: *32 http writer output filter: -2, "/fe055d1333ae252bc11c33fb191f4259c1e74e59a52bd38a34/download.json?app=cargo-request-test&fc=15"
2015/09/30 09:48:46 [debug] 32152#0: *32 event timer: 5, old: 1443599386042, new: 1443599386042
2015/09/30 09:48:46 [debug] 32152#0: *32 http posted request: "/data/users/test/Room1/__Configuration__E-Mail.png?"
2015/09/30 09:48:46 [debug] 32152#0: *32 rewrite phase: 1
2015/09/30 09:48:46 [debug] 32152#0: *32 test location: "/"
2015/09/30 09:48:46 [debug] 32152#0: *32 test location: "cargolinks"
2015/09/30 09:48:46 [debug] 32152#0: *32 test location: "internal_downloads/"
2015/09/30 09:48:46 [debug] 32152#0: *32 test location: "data/"
2015/09/30 09:48:46 [debug] 32152#0: *32 using configuration "/data/"
2015/09/30 09:48:46 [debug] 32152#0: *32 http cl:745 max:5368709120
2015/09/30 09:48:46 [debug] 32152#0: *32 rewrite phase: 3
2015/09/30 09:48:46 [debug] 32152#0: *32 rewrite phase: 4
2015/09/30 09:48:46 [debug] 32152#0: *32 post rewrite phase: 5
2015/09/30 09:48:46 [debug] 32152#0: *32 generic phase: 6
2015/09/30 09:48:46 [debug] 32152#0: *32 generic phase: 7
2015/09/30 09:48:46 [debug] 32152#0: *32 generic phase: 8
2015/09/30 09:48:46 [debug] 32152#0: *32 try files phase: 12
2015/09/30 09:48:46 [debug] 32152#0: *32 content phase: 13
2015/09/30 09:48:46 [debug] 32152#0: *32 content phase: 14
2015/09/30 09:48:46 [debug] 32152#0: *32 content phase: 15
2015/09/30 09:48:46 [debug] 32152#0: *32 http filename: "/data/users/test/Room1/__Configuration__E-Mail.png"
2015/09/30 09:48:46 [debug] 32152#0: *32 add cleanup: 00000000024733D0
2015/09/30 09:48:46 [debug] 32152#0: *32 http static fd: 20
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: entering header filter
2015/09/30 09:48:46 [debug] 32152#0: *32 headers more header filter, uri "/data/users/test/Room1/__Configuration__E-Mail.png"
2015/09/30 09:48:46 [debug] 32152#0: *32 uploadprogress error-tracker error: 0
2015/09/30 09:48:46 [debug] 32152#0: *32 charset: "" > "utf-8"
2015/09/30 09:48:46 [debug] 32152#0: *32 http output filter "/data/users/test/Room1/__Configuration__E-Mail.png?"
2015/09/30 09:48:46 [debug] 32152#0: *32 http copy filter: "/data/users/test/Room1/__Configuration__E-Mail.png?"
2015/09/30 09:48:46 [debug] 32152#0: *32 malloc: 000000000247C660:32768
2015/09/30 09:48:46 [debug] 32152#0: *32 read: 20, 000000000247C660, 32768, 0
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: entering subrequest body filter
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: No range for subrequest to satisfy
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: updating CRC-32
2015/09/30 09:48:46 [debug] 32152#0: *32 http postpone filter "/data/users/test/Room1/__Configuration__E-Mail.png?" 000000000247BF68
2015/09/30 09:48:46 [debug] 32152#0: *32 write old buf t:0 f:0 0000000000000000, pos 0000000002473098, size: 16 file: 0, size: 0
2015/09/30 09:48:46 [debug] 32152#0: *32 write old buf t:0 f:0 0000000000000000, pos 00000000024730F8, size: 90 file: 0, size: 0
2015/09/30 09:48:46 [debug] 32152#0: *32 write new buf t:1 f:1 000000000247C660, pos 000000000247C660, size: 32768 file: 0, size: 32768
2015/09/30 09:48:46 [debug] 32152#0: *32 http write filter: l:0 f:1 s:32874
2015/09/30 09:48:46 [debug] 32152#0: *32 http write filter limit 0
2015/09/30 09:48:46 [debug] 32152#0: *32 SSL buf copy: 16
2015/09/30 09:48:46 [debug] 32152#0: *32 SSL buf copy: 90
2015/09/30 09:48:46 [debug] 32152#0: *32 SSL buf copy: 9585
2015/09/30 09:48:46 [debug] 32152#0: *32 SSL to write: 16384
2015/09/30 09:48:46 [debug] 32152#0: *32 SSL_write: 16384
2015/09/30 09:48:46 [debug] 32152#0: *32 SSL buf copy: 16384
2015/09/30 09:48:46 [debug] 32152#0: *32 SSL to write: 16384
2015/09/30 09:48:46 [debug] 32152#0: *32 SSL_write: 16384
2015/09/30 09:48:46 [debug] 32152#0: *32 SSL buf copy: 6799
2015/09/30 09:48:46 [debug] 32152#0: *32 http write filter 0000000000000000
2015/09/30 09:48:46 [debug] 32152#0: *32 read: 20, 000000000247C660, 29874, 32768
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: entering subrequest body filter
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: No range for subrequest to satisfy
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: updating CRC-32
2015/09/30 09:48:46 [debug] 32152#0: *32 http postpone filter "/data/users/test/Room1/__Configuration__E-Mail.png?" 000000000247BF68
2015/09/30 09:48:46 [debug] 32152#0: *32 write new buf t:1 f:1 000000000247C660, pos 000000000247C660, size: 29874 file: 32768, size: 29874
2015/09/30 09:48:46 [debug] 32152#0: *32 http write filter: l:0 f:1 s:29874
2015/09/30 09:48:46 [debug] 32152#0: *32 http write filter limit 0
2015/09/30 09:48:46 [debug] 32152#0: *32 SSL buf copy: 9585
2015/09/30 09:48:46 [debug] 32152#0: *32 SSL to write: 16384
2015/09/30 09:48:46 [debug] 32152#0: *32 SSL_write: 16384
2015/09/30 09:48:46 [debug] 32152#0: *32 SSL buf copy: 16384
2015/09/30 09:48:46 [debug] 32152#0: *32 SSL to write: 16384
2015/09/30 09:48:46 [debug] 32152#0: *32 SSL_write: -1
2015/09/30 09:48:46 [debug] 32152#0: *32 SSL_get_error: 3
2015/09/30 09:48:46 [debug] 32152#0: *32 http write filter 000000000247BF78
2015/09/30 09:48:46 [debug] 32152#0: *32 http copy filter: -2 "/data/users/test/Room1/__Configuration__E-Mail.png?"
2015/09/30 09:48:46 [debug] 32152#0: *32 http finalize request: -2, "/data/users/test/Room1/__Configuration__E-Mail.png?" a:1, c:2
2015/09/30 09:48:46 [debug] 32152#0: *32 http wake parent request: "/fe055d1333ae252bc11c33fb191f4259c1e74e59a52bd38a34/download.json?app=cargo-request-test&fc=15"
2015/09/30 09:48:46 [debug] 32152#0: *32 http posted request: "/fe055d1333ae252bc11c33fb191f4259c1e74e59a52bd38a34/download.json?app=cargo-request-test&fc=15"
2015/09/30 09:48:46 [debug] 32152#0: *32 http writer handler: "/fe055d1333ae252bc11c33fb191f4259c1e74e59a52bd38a34/download.json?app=cargo-request-test&fc=15"
2015/09/30 09:48:46 [debug] 32152#0: *32 http output filter "/fe055d1333ae252bc11c33fb191f4259c1e74e59a52bd38a34/download.json?app=cargo-request-test&fc=15"
2015/09/30 09:48:46 [debug] 32152#0: *32 http copy filter: "/fe055d1333ae252bc11c33fb191f4259c1e74e59a52bd38a34/download.json?app=cargo-request-test&fc=15"
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: entering main request body filter
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: restarting subrequests
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: sending pieces, starting with piece 29 of total 46
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: no ranges / sending piece type 2
2015/09/30 09:48:46 [debug] 32152#0: *32 http postpone filter "/fe055d1333ae252bc11c33fb191f4259c1e74e59a52bd38a34/download.json?app=cargo-request-test&fc=15" 0000000002473158
2015/09/30 09:48:46 [debug] 32152#0: *32 write old buf t:1 f:1 000000000247C660, pos 0000000002482BD1, size: 3905 file: 32768, size: 29874
2015/09/30 09:48:46 [debug] 32152#0: *32 write new buf t:0 f:0 0000000000000000, pos 000000000247BFE8, size: 16 file: 0, size: 0
2015/09/30 09:48:46 [debug] 32152#0: *32 http write filter: l:0 f:1 s:3921
2015/09/30 09:48:46 [debug] 32152#0: *32 http write filter limit 0
2015/09/30 09:48:46 [debug] 32152#0: *32 SSL to write: 16384
2015/09/30 09:48:46 [debug] 32152#0: *32 SSL_write: -1
2015/09/30 09:48:46 [debug] 32152#0: *32 SSL_get_error: 3
2015/09/30 09:48:46 [debug] 32152#0: *32 http write filter 000000000247BF78
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: sent 1 pieces, last rc = -2
2015/09/30 09:48:46 [debug] 32152#0: *32 http copy filter: -2 "/fe055d1333ae252bc11c33fb191f4259c1e74e59a52bd38a34/download.json?app=cargo-request-test&fc=15"
2015/09/30 09:48:46 [debug] 32152#0: *32 http writer output filter: -2, "/fe055d1333ae252bc11c33fb191f4259c1e74e59a52bd38a34/download.json?app=cargo-request-test&fc=15"
2015/09/30 09:48:46 [debug] 32152#0: *32 event timer: 5, old: 1443599386042, new: 1443599386042
2015/09/30 09:48:46 [debug] 32152#0: timer delta: 71
2015/09/30 09:48:46 [debug] 32152#0: worker cycle
2015/09/30 09:48:46 [debug] 32152#0: epoll timer: 60000
2015/09/30 09:48:46 [debug] 32152#0: epoll: fd:5 ev:0004 d:00007FC8FC0F61C1
2015/09/30 09:48:46 [debug] 32152#0: *32 http run request: "/fe055d1333ae252bc11c33fb191f4259c1e74e59a52bd38a34/download.json?app=cargo-request-test&fc=15"
2015/09/30 09:48:46 [debug] 32152#0: *32 http writer handler: "/fe055d1333ae252bc11c33fb191f4259c1e74e59a52bd38a34/download.json?app=cargo-request-test&fc=15"
2015/09/30 09:48:46 [debug] 32152#0: *32 http output filter "/fe055d1333ae252bc11c33fb191f4259c1e74e59a52bd38a34/download.json?app=cargo-request-test&fc=15"
2015/09/30 09:48:46 [debug] 32152#0: *32 http copy filter: "/fe055d1333ae252bc11c33fb191f4259c1e74e59a52bd38a34/download.json?app=cargo-request-test&fc=15"
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: entering main request body filter
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: restarting subrequests
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: sending pieces, starting with piece 30 of total 46
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: no ranges / sending piece type 0
2015/09/30 09:48:46 [debug] 32152#0: *32 http postpone filter "/fe055d1333ae252bc11c33fb191f4259c1e74e59a52bd38a34/download.json?app=cargo-request-test&fc=15" 000000000247BFF8
2015/09/30 09:48:46 [debug] 32152#0: *32 write old buf t:1 f:1 000000000247C660, pos 0000000002482BD1, size: 3905 file: 32768, size: 29874
2015/09/30 09:48:46 [debug] 32152#0: *32 write old buf t:0 f:0 0000000000000000, pos 000000000247BFE8, size: 16 file: 0, size: 0
2015/09/30 09:48:46 [debug] 32152#0: *32 write new buf t:0 f:0 0000000000000000, pos 000000000247C058, size: 89 file: 0, size: 0
2015/09/30 09:48:46 [debug] 32152#0: *32 http write filter: l:0 f:1 s:4010
2015/09/30 09:48:46 [debug] 32152#0: *32 http write filter limit 0
2015/09/30 09:48:46 [debug] 32152#0: *32 SSL to write: 16384
2015/09/30 09:48:46 [debug] 32152#0: *32 SSL_write: 16384
2015/09/30 09:48:46 [debug] 32152#0: *32 SSL buf copy: 3905
2015/09/30 09:48:46 [debug] 32152#0: *32 SSL buf copy: 16
2015/09/30 09:48:46 [debug] 32152#0: *32 SSL buf copy: 89
2015/09/30 09:48:46 [debug] 32152#0: *32 http write filter 0000000000000000
2015/09/30 09:48:46 [debug] 32152#0: *32 mod_zip: sent 1 pieces, last rc = -2
2015/09/30 09:48:46 [debug] 32152#0: *32 http copy filter: -2 "/fe055d1333ae252bc11c33fb191f4259c1e74e59a52bd38a34/download.json?app=cargo-request-test&fc=15"
2015/09/30 09:48:46 [debug] 32152#0: *32 http writer output filter: -2, "/fe055d1333ae252bc11c33fb191f4259c1e74e59a52bd38a34/download.json?app=cargo-request-test&fc=15"
2015/09/30 09:48:46 [debug] 32152#0: *32 event timer: 5, old: 1443599386042, new: 1443599386056
2015/09/30 09:48:46 [debug] 32152#0: timer delta: 14
2015/09/30 09:48:46 [debug] 32152#0: worker cycle
2015/09/30 09:48:46 [debug] 32152#0: epoll timer: 59986
2015/09/30 09:49:15 [debug] 32152#0: epoll: fd:5 ev:2005 d:00007FC8FC0F61C1
2015/09/30 09:49:15 [debug] 32152#0: *32 http run request: "/fe055d1333ae252bc11c33fb191f4259c1e74e59a52bd38a34/download.json?app=cargo-request-test&fc=15"
2015/09/30 09:49:15 [debug] 32152#0: *32 http test reading
2015/09/30 09:49:15 [info] 32152#0: *32 client prematurely closed connection while sending response to client, client: 192.168.123.1, server: _, request: "POST /fe055d1333ae252bc11c33fb191f4259c1e74e59a52bd38a34/download.json?app=cargo-request-test&fc=15 HTTP/1.1", upstream: "http://unix:/var/run/cargo/unicorn.socket/fe055d1333ae252bc11c33fb191f4259c1e74e59a52bd38a34/download.json?app=cargo-request-test&fc=15", host: "192.168.123.123"
2015/09/30 09:49:15 [debug] 32152#0: *32 http finalize request: 499, "/fe055d1333ae252bc11c33fb191f4259c1e74e59a52bd38a34/download.json?app=cargo-request-test&fc=15" a:1, c:1
2015/09/30 09:49:15 [debug] 32152#0: *32 http terminate request count:1
2015/09/30 09:49:15 [debug] 32152#0: *32 http terminate cleanup count:1 blk:0
2015/09/30 09:49:15 [debug] 32152#0: *32 http posted request: "/fe055d1333ae252bc11c33fb191f4259c1e74e59a52bd38a34/download.json?app=cargo-request-test&fc=15"
2015/09/30 09:49:15 [debug] 32152#0: *32 http terminate handler count:1
2015/09/30 09:49:15 [debug] 32152#0: *32 http request count:1 blk:0
2015/09/30 09:49:15 [debug] 32152#0: *32 http close request
2015/09/30 09:49:15 [debug] 32152#0: *32 http log handler
2015/09/30 09:49:15 [debug] 32152#0: *32 run cleanup: 00000000024733D0
2015/09/30 09:49:15 [debug] 32152#0: *32 file cleanup: fd:20
2015/09/30 09:49:15 [debug] 32152#0: *32 run cleanup: 000000000246A478
2015/09/30 09:49:15 [debug] 32152#0: *32 file cleanup: fd:19
2015/09/30 09:49:15 [debug] 32152#0: *32 run cleanup: 0000000002461548
2015/09/30 09:49:15 [debug] 32152#0: *32 file cleanup: fd:18
2015/09/30 09:49:15 [debug] 32152#0: *32 run cleanup: 0000000002458580
2015/09/30 09:49:15 [debug] 32152#0: *32 file cleanup: fd:17
2015/09/30 09:49:15 [debug] 32152#0: *32 run cleanup: 0000000002458030
2015/09/30 09:49:15 [debug] 32152#0: *32 file cleanup: fd:16
2015/09/30 09:49:15 [debug] 32152#0: *32 run cleanup: 000000000244F0F8
2015/09/30 09:49:15 [debug] 32152#0: *32 file cleanup: fd:15
2015/09/30 09:49:15 [debug] 32152#0: *32 run cleanup: 0000000002416710
2015/09/30 09:49:15 [debug] 32152#0: *32 file cleanup: fd:14
2015/09/30 09:49:15 [debug] 32152#0: *32 run cleanup: 00000000024157C8
2015/09/30 09:49:15 [debug] 32152#0: *32 file cleanup: fd:13
2015/09/30 09:49:15 [debug] 32152#0: *32 run cleanup: 00000000024148A8
2015/09/30 09:49:15 [debug] 32152#0: *32 file cleanup: fd:12
2015/09/30 09:49:15 [debug] 32152#0: *32 run cleanup: 0000000002423EA8
2015/09/30 09:49:15 [debug] 32152#0: *32 file cleanup: fd:11
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 000000000247C660
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 0000000002473640
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 000000000246A620
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 0000000002461600
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 00000000024585E0
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 000000000244F5C0
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 00000000024465A0
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 000000000243C6E0
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 0000000002432CE0
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 0000000002425C40
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 0000000002420EC0
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 00000000023A7990, unused: 1
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 000000000241FEB0, unused: 3
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 0000000002421ED0, unused: 0
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 0000000002422EE0, unused: 2
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 0000000002411A90, unused: 0
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 0000000002412AA0, unused: 2
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 0000000002413AB0, unused: 2
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 0000000002414AC0, unused: 2
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 0000000002415AD0, unused: 0
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 000000000244E5B0, unused: 5
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 00000000024575D0, unused: 0
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 00000000024605F0, unused: 2
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 0000000002469610, unused: 8
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 0000000002472630, unused: 0
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 000000000247B650, unused: 1106
2015/09/30 09:49:15 [debug] 32152#0: *32 close http connection: 5
2015/09/30 09:49:15 [debug] 32152#0: *32 SSL_shutdown: 1
2015/09/30 09:49:15 [debug] 32152#0: *32 event timer del: 5: 1443599386042
2015/09/30 09:49:15 [debug] 32152#0: *32 reusable connection: 0
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 000000000242ECD0
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 0000000002424510
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 00000000023D7610, unused: 8
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 00000000023D4A50, unused: 8
2015/09/30 09:49:15 [debug] 32152#0: *32 free: 00000000023B23A0, unused: 128
2015/09/30 09:49:15 [debug] 32152#0: timer delta: 29910
2015/09/30 09:49:15 [debug] 32152#0: worker cycle
2015/09/30 09:49:15 [debug] 32152#0: epoll timer: -1

@dup2
Copy link
Contributor Author

dup2 commented Oct 4, 2015

Just in case anyone has the same issues...

It seems to be related to SSL - when using plain HTTP no such issues arise. We suspect a buffering issue in combination with SSL.

Our current workaround is to have another server section without SSL in nginx listening only to localhost for this purpose. The outward facing server section will proxy the zip archive requests there. This creates a double proxy situation (our backend application creates the mod_zip special response body) but at least we have a working mod_zip.

avodaniel pushed a commit to avodaniel/mod_zip that referenced this issue Jan 17, 2016
evanmiller added a commit that referenced this issue Jan 27, 2016
Flush file header under SSL. Fixes #44
@Dragoonwings
Copy link
Contributor

Got same issue here with file size in 1444-1459 bytes and without CRC in file list. It seems that nginx waits for data to fit postpone size, but this module wait nginx to send it to the client. Fixed this with b->flush=1 in ngx_http_zip_data_descriptor_chain_link. But it's not good solution.

@Dragoonwings
Copy link
Contributor

Dragoonwings commented Jan 19, 2023

I have debugged issue with 1444-1459 file size via SSL in nginx-1.22.1 and found that this size is lower than postpone_output(1460) so it is not send by nginx and becomes postponed. Function ngx_http_write_filter(src/http/ngx_http_write_filter_module.c:220) returns NGX_OK to mod_zip and module try to send next piece - trailer_piece(16bytes), now buffer is not lower than postpone_output(1444+16) and ngx_http_write_filter starts sending it in "chain = c->send_chain(c, r->out, limit);" (src/http/ngx_http_write_filter_module.c:294). But this size is still cannot be send, because it is lower than SSL_buffer (16 kbytes) and connection became buffered: "c->buffered |= NGX_SSL_BUFFERED;"(src/event/ngx_event_openssl.c:2705). Call returns in ngx_http_write_filter (src/http/ngx_http_write_filter_module.c:348), but trailer_piece request is not postponed, unlike file_piece, so ngx_http_write_filter returns NGX_AGAIN to mod_zip. Module ends its run and returns NGX_AGAIN to upper level, but with empty chain. Nginx process returns to waiting for events, but there is no events in the chain and connection becomes stalled.

@Dragoonwings
Copy link
Contributor

@evanmiller could you help me with that issue or you need more technical information?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants