View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0000738 | Apache 2.x | Bug | public | 2021-07-15 04:33 | 2022-02-19 21:27 |
| Reporter | Steven Levine | Assigned To | Steven Levine | ||
| Priority | normal | Severity | major | Reproducibility | always |
| Status | resolved | Resolution | fixed | ||
| Platform | OS2/eCS | OS | OS/2 or eComstation | OS Version | 1.x 2.x or 4.5 |
| Product Version | 2.4.x | ||||
| Summary | 0000738: Accessing large files via wget or a browser results in a truncated file. | ||||
| Description | This occurs for httpd 2.4.48 ( httpd-2.4.48-os2-20210619-debug.zip), but there's not yet any reason to believe it does not occur for earlier builds. GET requests for files smaller than some as yet unknown limit succeed without errors. GET requests for larger files end early for example, idebug-small-20200707.zip is 3.4MB. wget http://www.warpcave.com/betas/idebug-small-20200707.zip gets into a retry loop because it detects that the entire file has not been received and requests more of the file. Firefox 45.9 reports no errors, but only receives the first 40,490 or so of the file. The logs show that only a portion of the file has been sent. 74.101.171.114 - - [13/Jul/2021:15:02:11 +0000] www.warpcave.com "GET /betas/idebug-small-20200707.zip HTTP/1.1" 200 40490 "http://www.warpcave.com/betas/" "Mozilla/5.0 (OS/2; Warp 4.5; rv:38.0) Gecko/20100101 Firefox/38.0 SeaMonkey/2.35" | ||||
| Tags | No tags attached. | ||||
|
|
In case it's of any help in correlating log files, this is a wget attempt (no proxy) which ultimately succeeded (local time is -0400 EDT): --2021-07-18 15:06:12-- http://www.warpcave.com/betas/TestDosGetDateTimeTzSetAndRuntime-20210718.zip Resolving www.warpcave.com (www.warpcave.com)... 64.60.60.121 Connecting to www.warpcave.com (www.warpcave.com)|64.60.60.121|:80... connected. HTTP request sent, awaiting response... 200 OK Length: 74865 (73K) [application/zip] Saving to: 'TestDosGetDateTimeTzSetAndRuntime-20210718.zip' TestDosGetDateTimeT 48%[========> ] 35.67K 31.5KB/s in 1.1s 2021-07-18 15:06:13 (31.5 KB/s) - Connection closed at byte 36527. Retrying. --2021-07-18 15:06:14-- (try: 2) http://www.warpcave.com/betas/TestDosGetDateTimeTzSetAndRuntime-20210718.zip Connecting to www.warpcave.com (www.warpcave.com)|64.60.60.121|:80... connected. HTTP request sent, awaiting response... 206 Partial Content Length: 74865 (73K), 38338 (37K) remaining [application/zip] Saving to: 'TestDosGetDateTimeTzSetAndRuntime-20210718.zip' TestDosGetDateTimeT 97%[+++++++++=========> ] 71.29K 29.2KB/s in 1.2s 2021-07-18 15:06:15 (29.2 KB/s) - Connection closed at byte 73001. Retrying. --2021-07-18 15:06:17-- (try: 3) http://www.warpcave.com/betas/TestDosGetDateTimeTzSetAndRuntime-20210718.zip Connecting to www.warpcave.com (www.warpcave.com)|64.60.60.121|:80... connected. HTTP request sent, awaiting response... 206 Partial Content Length: 74865 (73K), 1864 (1.8K) remaining [application/zip] Saving to: 'TestDosGetDateTimeTzSetAndRuntime-20210718.zip' TestDosGetDateTimeT 100%[+++++++++++++++++++>] 73.11K --.-KB/s in 0s 2021-07-18 15:06:18 (36.4 KB/s) - 'TestDosGetDateTimeTzSetAndRuntime-20210718.zip' saved [74865/74865] I'll compare the above to Hawking's wget pull for the FTP mirror to see if the chunk sizes are the same (the update pass is not scheduled for another 11 hours or so). |
|
|
This issue is mostly resolved with the current libcx from netlabs-exp. However, some wget requests still restart intermittently, so we are not yet ready to say the issue is resolved. |
|
|
Status update... The cause to that truncated GET requests has been isolated to the select statement at network_io\os2\sendrecv.c:138 fds = sock->socketdes; rv = select(&fds, 0, 1, 0, sock->timeout >= 0 ? sock->timeout/1000 : -1); This is in our apr_socket_sendv implementation. Other platforms do not use select. As the code is currently written, the select is not expected to fail with no sockets ready to send, but it can because the socket is configured as non-blocking. The no sockets ready is a false positive probably because the stack is busy. The result is that APR_TIMEUP is returned to the caller. This is a problem because it is not treated as an error and the client believes that the GET request completed without errors. This is likely the case because, if the stack is busy with other operations, the number of truncated GET requests seems to increase. The fix will be a patch to retry to failing selects, as we have need to do elsewhere, and to ensure that real time outs result in reporting an error to the caller. |
|
|
Here's a copy of the diff I passed to Paul on the apache2 list. sendrecv.c.diff (815 bytes)
diff --git a/network_io/os2/sendrecv.c b/network_io/os2/sendrecv.c
index 06e725a..4d7e108 100644
--- a/network_io/os2/sendrecv.c
+++ b/network_io/os2/sendrecv.c
@@ -118,6 +118,7 @@ APR_DECLARE(apr_status_t) apr_socket_sendv(apr_socket_t *sock,
struct iovec *tmpvec;
int fds, err = 0;
int nv_tosend, total = 0;
+ int retries = 0;
#ifndef __INNOTEK_LIBC__
/* Make sure writev() only gets fed 64k at a time */
@@ -143,6 +144,10 @@ APR_DECLARE(apr_status_t) apr_socket_sendv(apr_socket_t *sock,
err = sock_errno();
if (rv == 0) {
+ if (err == SOCEWOULDBLOCK && ++retries < 10) {
+ apr_sleep(100 * 1000); /* 100 mSec */
+ continue; /* Retry select */
+ }
return APR_TIMEUP;
}
|
|
|
Corrected in https://smedley.id.au/tmp/httpd-2.4.52-os2-20211228-debug.zip |
| Date Modified | Username | Field | Change |
|---|---|---|---|
| 2021-07-15 04:33 | Steven Levine | New Issue | |
| 2021-07-15 04:33 | Steven Levine | Status | new => assigned |
| 2021-07-15 04:33 | Steven Levine | Assigned To | => Steven Levine |
| 2021-07-15 04:38 | Steven Levine | Issue cloned: 0000739 | |
| 2021-07-18 19:15 | LewisR | Note Added: 0003826 | |
| 2021-08-22 15:41 | Steven Levine | Note Added: 0003888 | |
| 2021-11-09 18:47 | Steven Levine | Note Added: 0003900 | |
| 2021-12-27 01:02 | Steven Levine | Note Added: 0003901 | |
| 2021-12-27 01:02 | Steven Levine | File Added: sendrecv.c.diff | |
| 2022-02-19 21:27 | Steven Levine | Status | assigned => resolved |
| 2022-02-19 21:27 | Steven Levine | Resolution | open => fixed |
| 2022-02-19 21:27 | Steven Levine | Note Added: 0003918 |
