ODK Central download all sub with media throws error ERR_STREAM_PREMATURE_CLOSE

Support
1

1. What is the problem? Be very detailed.

  • When I use the UI to download all submissions for forms with media, I get ERR_STREAM_PREMATURE_CLOSE.
  • Notably, the smallest failing form has only 8 submissions. The error happens with other forms with some 100s of submissions too.
  • The timeout happens after about 14 seconds in a form with 330-odd submissions (with media), so it's not the 60 seconds nginx timeout found here.
  • The export without media works fine.
  • Opening individual media files through UI works fine.
  • Download via ruODK::odata_submission_get worked including media, but took several minutes (normally seconds).
  • This is where it gets wild - ruODK::submission_export downloads the ZIP including media within seconds for some forms, but fails with the same timeout for others (leaving a broken ZIP archive).
    • Form 1 with 8 submissions - exports fine via ruODK::submission_export, but downloads via ruODK::odata_submission_get extremely slowly
    • Form 2 with 300 odd sub - fails after 14 seconds with end of stream timeout, 54kB ZIP
    • Form 2 via ruODK::odata_submission_get downloads fine and quickly, media download individually fine
    • Form 3 with 300 odd sub - fails after 40 seconds with timeout, 400-600MB zip, downloads fine via via ruODK::odata_submission_get, but downloading media files (one by one through ruODK::odata_submission_get) slows down and leaks memory.
    • All forms preview fine in Enketo (so it's not an obvious form definition error).
    • AFAICT there are no broken media uploads, resulting in "74 kB" non-images (containing an error message on file not found).

2. What app or server are you using and on what device and operating system? Include version numbers.
ODK Central Versions:

e16b79530756bbd825f68275b3b6e53951409474
 70ec99f02885a06e37709db6319bfdf96fac84eb client (v1.2.2)
 59556ecea91f0a25678cd6da0084adb7e66ca099 server (v1.2.1)
  • SSL: selfsigned
  • Database: Postgres hosted on Azure, connected via SSL
  • DNS: nginx as reverse proxy (maintained by core IT outside of my direct control)
  • Database is from an old ODK Central 0.6, now migrated to 1.2.2
  • Is the varnish cache on my IT's end? Could that be the problem?

3. What you have you tried to fix the problem?

  • Tried different forms on same server. All same error with media but fine without.

4. What steps can we take to reproduce the problem?

  • Download all submissions with media from my server. (given an account)

5. Anything else we should know or have? If you have a test form or screenshots or logs, attach below.
Server logs when exporting through GUI:

service_1             | ::ffff:172.19.0.7 - - [03/Aug/2021:05:27:44 +0000] "GET /v1/projects/27/forms/FORMID/submissions.csv.zip HTTP/1.0" 200 -
service_1             | Error [ERR_STREAM_PREMATURE_CLOSE]: Premature close
service_1             |     at ServerResponse.onclose (internal/streams/end-of-stream.js:65:15)
service_1             |     at ServerResponse.emit (events.js:208:15)
service_1             |     at ServerResponse.EventEmitter.emit (domain.js:494:23)
service_1             |     at Socket.onServerResponseClose (_http_server.js:184:44)
service_1             |     at Socket.emit (events.js:208:15)
service_1             |     at Socket.EventEmitter.emit (domain.js:471:20)
service_1             |     at TCP.<anonymous> (net.js:588:12)

Browser response:

Error 503 Response object too large

Response object too large
Guru Mediation:

Details: cache-per12627-PER 1627968742 2291186297

Varnish cache server

I wasn't aware my browser has a Guru but OK.
None of the error messages come up searching the forum.

htop shows the server bumbling along at ~ 2GB RAM and up to 70% CPU during the failed exports.
However, exporting the 600MB+ form and downloading the media files individually, I can see memory use creeping slowly (5GB used of 8GB).

image
image1632×514 144 KB

How can I further debug this performance degradation?

Maybe the core team has seen the trace before (ServerResponse.onclose (internal/streams/end-of-stream.js:65:15))?

2

Hi @Florian_May! ERR_STREAM_PREMATURE_CLOSE is an error that can be difficult to track down. I checked with @issa, and while it's not clear what the issue is, we have some things that you could try.

One thing is that I'm pretty sure that Varnish isn't part of Central. I don't recognize that error 503. If there's a caching layer in front of Central that could be returning that 503, that'd be worth looking into.

That said, when we've encountered ERR_STREAM_PREMATURE_CLOSE in the past, it's usually been due to a bug in Central. For example, there was a case in the past where Central would show this error after encountering a valid submission that wasn't structured as expected.

How consistent is the ERR_STREAM_PREMATURE_CLOSE? For a failing form, does trying to download the .csv.zip with media always result in this error? Is it about the same amount of time before the error each time?

One test that would be interesting is increasing the amount of RAM. Does downloading the .csv.zip with media work if you temporarily double the amount of RAM?

We're not sure whether the memory usage pattern you're observing is a memory leak. Are you able to tell whether the memory is eventually reclaimed? Either way, @issa thinks that it's probably not related to the ERR_STREAM_PREMATURE_CLOSE (though definitely also good to know about).

1 Like