mod_zip zipping >1000 files - mod_zip does not release file handle

[dudemeister]

Hi there,

just hunted down a very annoying bug. One of our users started downloading and zipping large folders and the downloads were mysteriously failing with

  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
 58 1621M   58  953M    0    78  6966k      0  0:03:58  0:02:20  0:01:38 6139k
curl: (18) transfer closed with 701326567 bytes remaining to read

The debug log was showing:

2021-01-15_07:30:39.90128 2021/01/15 08:30:39 [debug] 15374#15374: *38 mod_zip: subrequest for "/files/folders/1073/files/02_CUT/Tim/Prompts_B_Tim/B_#1578_geschnitten.wav?" done, result 0
2021-01-15_07:30:39.90178 2021/01/15 08:30:39 [debug] 15374#15374: *38 mod_zip: entering main request body filter
2021-01-15_07:30:39.90185 2021/01/15 08:30:39 [debug] 15374#15374: *38 mod_zip: restarting subrequests
2021-01-15_07:30:39.90195 2021/01/15 08:30:39 [debug] 15374#15374: *38 mod_zip: sending pieces, starting with piece 2987 of total 5044
2021-01-15_07:30:39.90202 2021/01/15 08:30:39 [debug] 15374#15374: *38 mod_zip: no ranges / sending piece type 2
2021-01-15_07:30:39.90205 2021/01/15 08:30:39 [debug] 15374#15374: *38 mod_zip: finalized CRC-32 (0D4806EF -> F2B7F910)
2021-01-15_07:30:39.90213 2021/01/15 08:30:39 [debug] 15374#15374: *38 mod_zip: no ranges / sending piece type 0
2021-01-15_07:30:39.90225 2021/01/15 08:30:39 [debug] 15374#15374: *38 mod_zip: no ranges / sending piece type 1
2021-01-15_07:30:39.90227 2021/01/15 08:30:39 [debug] 15374#15374: *38 mod_zip: subrequest for "/files/folders/1073/files/02_CUT/Tim/Prompts_B_Tim/B_#1591_geschnitten.wav?"
2021-01-15_07:30:39.90230 2021/01/15 08:30:39 [debug] 15374#15374: *38 mod_zip: have a wait context for "/files/folders/1073/files/02_CUT/Tim/Prompts_B_Tim/B_#1578_geschnitten.wav?"
2021-01-15_07:30:39.90233 2021/01/15 08:30:39 [debug] 15374#15374: *38 mod_zip: wait "/files/folders/1073/files/02_CUT/Tim/Prompts_B_Tim/B_#1578_geschnitten.wav?" done
2021-01-15_07:30:39.90246 2021/01/15 08:30:39 [debug] 15374#15374: *38 mod_zip: subrequest for "/files/folders/1073/files/02_CUT/Tim/Prompts_B_Tim/B_#1591_geschnitten.wav?" initiated, result 0
2021-01-15_07:30:39.90248 2021/01/15 08:30:39 [debug] 15374#15374: *38 mod_zip: sent 3 pieces, last rc = -2
2021-01-15_07:30:39.90414 2021/01/15 08:30:39 [debug] 15374#15374: *38 mod_zip: subrequest for "/files/folders/1073/files/02_CUT/Tim/Prompts_B_Tim/B_#1591_geschnitten.wav?" done, result 500
2021-01-15_07:30:39.90643 2021/01/15 08:30:39 [debug] 15374#15374: *38 mod_zip: subrequest for "/files/folders/1073/files/02_CUT/Tim/Prompts_B_Tim/B_#1591_geschnitten.wav?" done, result 500
2021-01-15_07:30:39.90654 2021/01/15 08:30:39 [debug] 15374#15374: *38 mod_zip: entering header filter
2021-01-15_07:30:39.90659 2021/01/15 08:30:39 [error] 15374#15374: *38 mod_zip: a subrequest returned 500, aborting..., client: 127.0.0.1, server: protonet, request: "POST /owner_files/zip_download HTTP/1.1", subrequest: "/50x.html", host: "78.47.23.239"
2021-01-15_07:30:39.90678 2021/01/15 08:30:39 [debug] 15374#15374: *38 mod_zip: subrequest for "/files/folders/1073/files/02_CUT/Tim/Prompts_B_Tim/B_#1591_geschnitten.wav?" done, result -1

It wouldn't always fail on the same file but always around the ~1000-1150th file.

Lot's of digging and ended up reducing nginx to one worker and checking the open files of the process with watch "lsof -p NGINXWORKERPID | wc -l" and lo and behold the process would crash whenever it would hit the 1024 max open file limit.

nginx was being run by runit so that would override the system wide max open file setting.

Anyways - why would mod_zip need to keep those files (handles) open after having streamed them to the client?

Thanks! Ali

[mdineen]

I'm also experiencing this issue. Although we can increase ulimts, that doesn't scale and shouldn't be necessary.