File upload stuck/no response if file is larger than 127KB
Added by Oliver Haucke 6 months ago
Hey there,
i'm currently having issues uploading files to Redmine that are larger than 127KB.
$ freebsd-version 14.1-RELEASE-p5 $ pkg version -v | grep apache apache24-2.4.62 rubygem-passenger-apache-6.0.23
Environment: Redmine version 5.1.3.stable Ruby version 3.2.5-p208 (2024-07-26) [amd64-freebsd14] Rails version 6.1.7.8 Environment production Database adapter Mysql2 Mailer queue ActiveJob::QueueAdapters::AsyncAdapter Mailer delivery sendmail Redmine settings: Redmine theme Default SCM: Git 2.46.2 Filesystem Redmine plugins: no plugin installed
Last time, i uploaded a larger file (6MB) was 2024-09-12 14:30:19
.
After a bit of debugging, i figured out that if the file is 127KB or smaller, everything is fine but as soon as the file is 128KB or larger, i do not get any response from the server/the connection timed out.
What i can confirm via setting the LogLevel of apache to trace2 (and 5) + i ran tcpdump on the server:
The HTTP connection gets established and the data are received by the server
[Wed Oct 09 20:19:37.222886 2024] [socache_shmcb:debug] [pid 30309:tid 37622617604352] mod_socache_shmcb.c(545): AH00835: socache_shmcb_retrieve (0x5b -> subcache 27) [Wed Oct 09 20:19:37.222940 2024] [socache_shmcb:debug] [pid 30309:tid 37622617604352] mod_socache_shmcb.c(929): AH00851: shmcb_subcache_retrieve found no match [Wed Oct 09 20:19:37.222980 2024] [socache_shmcb:debug] [pid 30309:tid 37622617604352] mod_socache_shmcb.c(556): AH00836: leaving socache_shmcb_retrieve successfully [Wed Oct 09 20:19:37.222995 2024] [ssl:trace2] [pid 30309:tid 37622617604352] ssl_engine_kernel.c(2058): Inter-Process Session Cache: request=GET status=MISSED id=5b723ed47c62a36002***** (session renewal) [Wed Oct 09 20:19:37.230717 2024] [ssl:trace4] [pid 30309:tid 37622617604352] ssl_engine_io.c(2428): [client 1.2.3.4:41022] OpenSSL: write 3721/3721 bytes to BIO#2237b3826000 [mem: 2237b3842000] [Wed Oct 09 20:19:37.268149 2024] [ssl:trace4] [pid 30309:tid 37622617604352] ssl_engine_io.c(2428): [client 1.2.3.4:41022] OpenSSL: write 5/5 bytes to BIO#2237b38260a0 [mem: 2237b383ba03] ... [Wed Oct 09 20:19:37.268526 2024] [ssl:trace4] [pid 30309:tid 37622617604352] ssl_engine_io.c(2428): [client 1.2.3.4:41022] OpenSSL: write 40/40 bytes to BIO#2237b38260a0 [mem: 2237b383ba08] [Wed Oct 09 20:19:37.268608 2024] [ssl:trace4] [pid 30309:tid 37622617604352] ssl_engine_io.c(2428): [client 1.2.3.4:41022] OpenSSL: write 51/51 bytes to BIO#2237b3826000 [mem: 2237b3842000] [Wed Oct 09 20:19:37.268701 2024] [socache_shmcb:debug] [pid 30309:tid 37622617604352] mod_socache_shmcb.c(508): AH00831: socache_shmcb_store (0xe4 -> subcache 4) [Wed Oct 09 20:19:37.268720 2024] [socache_shmcb:debug] [pid 30309:tid 37622617604352] mod_socache_shmcb.c(860): AH00847: insert happened at idx=0, data=(0:32) [Wed Oct 09 20:19:37.268729 2024] [socache_shmcb:debug] [pid 30309:tid 37622617604352] mod_socache_shmcb.c(863): AH00848: finished insert, subcache: idx_pos/idx_used=0/1, data_pos/data_used=0/209 [Wed Oct 09 20:19:37.268751 2024] [socache_shmcb:debug] [pid 30309:tid 37622617604352] mod_socache_shmcb.c(530): AH00834: leaving socache_shmcb_store successfully [Wed Oct 09 20:19:37.268763 2024] [ssl:trace2] [pid 30309:tid 37622617604352] ssl_engine_kernel.c(2058): Inter-Process Session Cache: request=SET status=OK id=e4037a3268fde276***** timeout=300s (session caching) [Wed Oct 09 20:19:37.306475 2024] [ssl:trace4] [pid 30309:tid 37622617604352] ssl_engine_io.c(2428): [client 1.2.3.4:41022] OpenSSL: write 5/5 bytes to BIO#2237b38260a0 [mem: 2237b383ba03] [Wed Oct 09 20:19:37.306492 2024] [ssl:trace4] [pid 30309:tid 37622617604352] ssl_engine_io.c(2428): [client 1.2.3.4:41022] OpenSSL: write 1519/1519 bytes to BIO#2237b38260a0 [mem: 2237b383ba08] [Wed Oct 09 20:19:37.306549 2024] [ssl:debug] [pid 30309:tid 37622617604352] ssl_engine_kernel.c(415): [client 1.2.3.4:41022] AH02034: Initial (No.1) HTTPS request received for child 215 (server redmine.example.org:443), referer: https://redmine.example.org/issues/1101 [Wed Oct 09 20:19:37.306577 2024] [http:trace4] [pid 30309:tid 37622617604352] http_request.c(435): [client 1.2.3.4:41022] Headers received from client:, referer: https://redmine.example.org/issues/1101 [Wed Oct 09 20:19:37.306595 2024] [http:trace4] [pid 30309:tid 37622617604352] http_request.c(438): [client 1.2.3.4:41022] Accept: application/js, referer: https://redmine.example.org/issues/1101 [Wed Oct 09 20:19:37.306624 2024] [http:trace4] [pid 30309:tid 37622617604352] http_request.c(438): [client 1.2.3.4:41022] Accept-Encoding: gzip, deflate, br, zstd, referer: https://redmine.example.org/issues/1101 [Wed Oct 09 20:19:37.306641 2024] [http:trace4] [pid 30309:tid 37622617604352] http_request.c(438): [client 1.2.3.4:41022] Accept-Language: en-US,en;q=0.9,de-DE;q=0.8,de;q=0.7, referer: https://redmine.example.org/issues/1101 [Wed Oct 09 20:19:37.306656 2024] [http:trace4] [pid 30309:tid 37622617604352] http_request.c(438): [client 1.2.3.4:41022] Connection: keep-alive, referer: https://redmine.example.org/issues/1101 [Wed Oct 09 20:19:37.306686 2024] [http:trace4] [pid 30309:tid 37622617604352] http_request.c(438): [client 1.2.3.4:41022] Content-Length: 131072, referer: https://redmine.example.org/issues/1101 ... [Wed Oct 09 20:19:37.307045 2024] [http:trace4] [pid 30309:tid 37622617604352] http_request.c(438): [client 1.2.3.4:41022] sec-ch-ua-platform: \\"Windows\\", referer: https://redmine.example.org/issues/1101 [Wed Oct 09 20:19:37.307164 2024] [authz_core:debug] [pid 30309:tid 37622617604352] mod_authz_core.c(815): [client 1.2.3.4:41022] AH01626: authorization result of Require all granted: granted, referer: https://redmine.example.org/issues/1101 [Wed Oct 09 20:19:37.307182 2024] [authz_core:debug] [pid 30309:tid 37622617604352] mod_authz_core.c(815): [client 1.2.3.4:41022] AH01626: authorization result of <RequireAny>: granted, referer: https://redmine.example.org/issues/1101 [Wed Oct 09 20:19:37.307222 2024] [core:trace3] [pid 30309:tid 37622617604352] request.c(360): [client 1.2.3.4:41022] request authorized without authentication by access_checker_ex hook: /uploads.js, referer: https://redmine.example.org/issues/1101 [Wed Oct 09 20:19:37.307410 2024] [ssl:trace4] [pid 30309:tid 37622617604352] ssl_engine_io.c(2428): [client 1.2.3.4:41022] OpenSSL: write 5/5 bytes to BIO#2237b38260a0 [mem: 2237b3835f83] [Wed Oct 09 20:19:37.307443 2024] [ssl:trace4] [pid 30309:tid 37622617604352] ssl_engine_io.c(2428): [client 1.2.3.4:41022] OpenSSL: write 1435/16379 bytes to BIO#2237b38260a0 [mem: 2237b3835f88] [Wed Oct 09 20:19:37.307717 2024] [ssl:trace4] [pid 30309:tid 37622617604352] ssl_engine_io.c(2428): [client 1.2.3.4:41022] OpenSSL: write 1440/14944 bytes to BIO#2237b38260a0 [mem: 2237b3836523] [Wed Oct 09 20:19:37.308185 2024] [ssl:trace4] [pid 30309:tid 37622617604352] ssl_engine_io.c(2428): [client 1.2.3.4:41022] OpenSSL: write 1440/13504 bytes to BIO#2237b38260a0 [mem: 2237b3836ac3] [Wed Oct 09 20:19:37.308969 2024] [ssl:trace4] [pid 30309:tid 37622617604352] ssl_engine_io.c(2428): [client 1.2.3.4:41022] OpenSSL: write 1440/12064 bytes to BIO#2237b38260a0 [mem: 2237b3837063] ... [Wed Oct 09 20:19:38.076913 2024] [ssl:trace4] [pid 30309:tid 37622617604352] ssl_engine_io.c(2428): [client 1.2.3.4:41022] OpenSSL: write 5/5 bytes to BIO#2237b38260a0 [mem: 2237b3835f83] [Wed Oct 09 20:19:38.076949 2024] [ssl:trace4] [pid 30309:tid 37622617604352] ssl_engine_io.c(2428): [client 1.2.3.4:41022] OpenSSL: write 256/256 bytes to BIO#2237b38260a0 [mem: 2237b3835f88]
Next thing i checked was the passenger log (i increased the PassengerLogLevel
to 5/debug):
[ D 2024-10-09 20:28:26.0255 33442/Th Ser/Server.h:880 ]: [ServerThr.5] 1 new client(s) accepted; there are now 1 active client(s)
Looks like passenger also gets the request
Next thing i tested was config.log_level = :debug
in config/additional_environment.rb
but nothing related to the request got written in the log.
Just for my sanity (since i also have php available on the server), i tested the same request to a test script and there everything worked fine.
Any idea what could cause the issue or what i can test next to figure it out and solve it?
Regards
Replies (2)
RE: File upload stuck/no response if file is larger than 127KB
-
Added by Oliver Haucke 6 months ago
Many hours later: it looks like a problem with passenger.
If i run `bundle exec rails server -e production` everything works fine
RE: File upload stuck/no response if file is larger than 127KB
-
Added by David Gessel 14 days ago
I have a very similar configuration and the same issue. A few months ago I tried this solution and I'm pretty sure it worked for a while, but it has re-emerged. I figured I'd try the solution from this ticket: https://github.com/phusion/passenger/issues/2569 and it seems to work and should be persistent. My specific mod was to amend the location directive in /usr/local/etc/apache24/extra/httpd-vhosts.conf
with PassengerBufferUpload off
as in:
<Directory "/usr/local/www/redmine/public/"> Allow from all Options -MultiViews Require all granted PassengerBufferUpload off </Directory>
And uploads work. This should be a persistent fix. There's likely some code checking upload progress that is waiting for that data to be made available and with PassengerBufferUpload at the default value of "true," it will not be.