Apache Mod_JK – Fixing Sporadic Client Errors When Uploading Large Files

apache-2.4curlfile-transfermod-jktomcat8

Note: There is a TL;DR at the end of this question.

I have a nightly backup script that has been working reliably for 6 years, and two months ago, it began to fail to upload to my archive server (only about 1 in 4 attempts succeed). This started to happen once the size of the backup file surpassed about 440MB (successful uploads take 20-40 seconds to complete). Other, smaller files (>200MB) are uploading successfully every time. The start of the failures did not coincide with any configuration changes or updates to the servers in question.

Here are the details of the file I am uploading:

-rw-r--r-- 1 backup backup 486948951 Jun 12 13:20 snapshot-20190612.zip

These files are uploaded to my server with a curl PUT (see command below). The source server is an Amazon Linux instance in Virginia, and the destination server is an Amazon Linux instance in the Ohio (both are in the US East region).

The web service that handles the upload is an Apache HTTPD 2.4.39 + mod24_ssl/OpenSSL 1.0.2k -> mod_jk 1.2.42 -> Apache Tomcat 8.5.40 -> Artifactory 5.3.2 instance.

I captured the jk_status page before and after one of these errors occurs (before/after are in an animated GIF to highlight the differences). The error is being interpreted as a Client Error by mod_jk.

jk_status before and after error

My mod/jk workers.properties file:

worker.list=main_ajp13_worker
# Set properties for main_ajp13_worker (ajp13)
worker.main_ajp13_worker.type=ajp13
worker.main_ajp13_worker.host=localhost
worker.main_ajp13_worker.port=8009

The following are the console output (authorization details scrubbed) from a failed upload, followed immediately by a successful upload:

-bash-4.2$ curl -v -k -u backup:PASSWORD -H X-Checksum-Sha1:6b9525bf9bb572ec7f70d0d474cb6533e0091bd3 -H X-Checksum-Md5:6da0c444ad1b53dc1cf06784e204cb10 -T snapshot-20190612.zip https://repo.mydomain.org/resource-snapshot/snapshot/20190612/snapshot-20190612.zip
*   Trying 123.222.100.132...
* TCP_NODELAY set
* Connected to repo.mydomain.org (123.222.100.132) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* Cipher selection: ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH
* successfully set certificate verify locations:
*   CAfile: /etc/pki/tls/certs/ca-bundle.crt
  CApath: none
* TLSv1.2 (OUT), TLS header, Certificate Status (22):
* TLSv1.2 (OUT), TLS handshake, Client hello (1):
* TLSv1.2 (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS change cipher, Change cipher spec (1):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-RSA-AES128-GCM-SHA256
* ALPN, server accepted to use http/1.1
* Server certificate:
*  subject: OU=Domain Control Validated; OU=PositiveSSL Wildcard; CN=*.mydomain.org
*  start date: May 28 00:00:00 2019 GMT
*  expire date: May 27 23:59:59 2021 GMT
*  issuer: C=GB; ST=Greater Manchester; L=Salford; O=Sectigo Limited; CN=Sectigo RSA Domain Validation Secure Server CA
*  SSL certificate verify ok.
* Server auth using Basic with user 'backup'
> PUT /resource-snapshot/snapshot/20190612/snapshot-20190612.zip HTTP/1.1
> Host: repo.mydomain.org
> Authorization: Basic DELETED_TOKEN
> User-Agent: curl/7.61.1
> Accept: */*
> X-Checksum-Sha1:6b9525bf9bb572ec7f70d0d474cb6533e0091bd3
> X-Checksum-Md5:6da0c444ad1b53dc1cf06784e204cb10
> Content-Length: 486948951
> Expect: 100-continue
>
< HTTP/1.1 100 Continue
* OpenSSL SSL_read: SSL_ERROR_SYSCALL, errno 104
* Closing connection 0
curl: (56) OpenSSL SSL_read: SSL_ERROR_SYSCALL, errno 104

-bash-4.2$ curl -v -u backup:PASSWORD -H X-Checksum-Sha1:6b9525bf9bb572ec7f70d0d474cb6533e0091bd3 -H X-Checksum-Md5:6da0c444ad1b53dc1cf06784e204cb10 -T snapshot-20190612.zip https://repo.mydomain.org/resource-snapshot/snapshot/20190612/snapshot-20190612.zip
*   Trying 123.222.100.132...
* TCP_NODELAY set
* Connected to repo.mydomain.org (123.222.100.132) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* Cipher selection: ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH
* successfully set certificate verify locations:
*   CAfile: /etc/pki/tls/certs/ca-bundle.crt
  CApath: none
* TLSv1.2 (OUT), TLS header, Certificate Status (22):
* TLSv1.2 (OUT), TLS handshake, Client hello (1):
* TLSv1.2 (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS change cipher, Change cipher spec (1):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-RSA-AES128-GCM-SHA256
* ALPN, server accepted to use http/1.1
* Server certificate:
*  subject: OU=Domain Control Validated; OU=PositiveSSL Wildcard; CN=*.mydomain.org
*  start date: May 28 00:00:00 2019 GMT
*  expire date: May 27 23:59:59 2021 GMT
*  issuer: C=GB; ST=Greater Manchester; L=Salford; O=Sectigo Limited; CN=Sectigo RSA Domain Validation Secure Server CA
*  SSL certificate verify ok.
* Server auth using Basic with user 'backup'
> PUT /resource-snapshot/snapshot/20190612/snapshot-20190612.zip HTTP/1.1
> Host: repo.mydomain.org
> Authorization: Basic DELETED_TOKEN
> User-Agent: curl/7.61.1
> Accept: */*
> X-Checksum-Sha1:6b9525bf9bb572ec7f70d0d474cb6533e0091bd3
> X-Checksum-Md5:6da0c444ad1b53dc1cf06784e204cb10
> Content-Length: 486948951
> Expect: 100-continue
>
< HTTP/1.1 100 Continue
* OpenSSL SSL_read: SSL_ERROR_SYSCALL, errno 104
* Closing connection 0
curl: (56) OpenSSL SSL_read: SSL_ERROR_SYSCALL, errno 104

With a second (or often third or fourth) attempt of the upload, it eventually succeeds:

-bash-4.2$ curl -v -u backup:PASSWORD -H X-Checksum-Sha1:6b9525bf9bb572ec7f70d0d474cb6533e0091bd3 -H X-Checksum-Md5:6da0c444ad1b53dc1cf06784e204cb10 -T snapshot-20190612.zip https://repo.mydomain.org/resource-snapshot/snapshot/20190612/snapshot-20190612.zip
*   Trying 123.222.100.132...
* TCP_NODELAY set
* Connected to repo.mydomain.org (123.222.100.132) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* Cipher selection: ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH
* successfully set certificate verify locations:
*   CAfile: /etc/pki/tls/certs/ca-bundle.crt
  CApath: none
* TLSv1.2 (OUT), TLS header, Certificate Status (22):
* TLSv1.2 (OUT), TLS handshake, Client hello (1):
* TLSv1.2 (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS change cipher, Change cipher spec (1):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-RSA-AES128-GCM-SHA256
* ALPN, server accepted to use http/1.1
* Server certificate:
*  subject: OU=Domain Control Validated; OU=PositiveSSL Wildcard; CN=*.mydomain.org
*  start date: May 28 00:00:00 2019 GMT
*  expire date: May 27 23:59:59 2021 GMT
*  issuer: C=GB; ST=Greater Manchester; L=Salford; O=Sectigo Limited; CN=Sectigo RSA Domain Validation Secure Server CA
*  SSL certificate verify ok.
* Server auth using Basic with user 'backup'
> PUT /resource-snapshot/snapshot/20190612/snapshot-20190612.zip HTTP/1.1
> Host: repo.mydomain.org
> Authorization: Basic DELETED_TOKEN
> User-Agent: curl/7.61.1
> Accept: */*
> X-Checksum-Sha1:6b9525bf9bb572ec7f70d0d474cb6533e0091bd3
> X-Checksum-Md5:6da0c444ad1b53dc1cf06784e204cb10
> Content-Length: 486948951
> Expect: 100-continue
>
< HTTP/1.1 100 Continue
* We are completely uploaded and fine
< HTTP/1.1 201 201
< Date: Wed, 12 Jun 2019 13:22:46 GMT
< Server: Apache
< Strict-Transport-Security: max-age=15768000
< X-Artifactory-Id: 9e49bf90cd4b7700:7ba45cf1:16b1db56e4d:-8000
< Location: https://repo.mydomain.org/resource-snapshot/snapshot/20190612/snapshot-20190612.zip
< Transfer-Encoding: chunked
< Content-Type: application/vnd.org.jfrog.artifactory.storage.itemcreated+json;charset=ISO-8859-1
<
{
  "repo" : "resource-snapshot",
  "path" : "/snapshot/20190612/snapshot-20190612.zip",
  "created" : "2019-06-12T13:23:05.805Z",
  "createdBy" : "backup",
  "downloadUri" : "https://repo.mydomain.org/resource-snapshot/snapshot/20190612/snapshot-20190612.zip",
  "mimeType" : "application/zip",
  "size" : "486948951",
  "checksums" : {
    "sha1" : "6b9525bf9bb572ec7f70d0d474cb6533e0091bd3",
    "md5" : "6da0c444ad1b53dc1cf06784e204cb10"
  },
  "originalChecksums" : {
    "sha1" : "6b9525bf9bb572ec7f70d0d474cb6533e0091bd3",
    "md5" : "6da0c444ad1b53dc1cf06784e204cb10"
  },
  "uri" : "https://repo.mydomain.org/resource-snapshot/snapshot/20190612/snapshot-20190612.zip"
* Connection #0 to host repo.mydomain.org left intact
}

The server logs aren't particularly informative. Here are the relevant logs when an upload fails:

/var/log/httpd/ssl_request_log

[24/Jun/2019:12:17:45 +0000] 52.1.100.190 TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256 "PUT /resource-snapshot/snapshot/20190612/snapshot-20190612.zip HTTP/1.1" -

/var/log/httpd/repo.mydomain.org-ssl_access_log

140.1.100.101 - - [24/Jun/2019:12:17:45 +0000] "PUT /resource-snapshot/snapshot/20190612/snapshot-20190612.zip HTTP/1.1" 400 -

catalina.out

No log entries.

/var/log/httpd/mod_jk.log

These are the logs when the mod/jk log level is set to info:

[Mon Jun 24 12:18:05 2019] [15679:140534117611584] [info] ajp_read_into_msg_buff::jk_ajp_common.c (1553): (main_ajp13_worker) receiving data from client failed. Connection aborted or network problems
[Mon Jun 24 12:18:05 2019] [15679:140534117611584] [info] ajp_process_callback::jk_ajp_common.c (2105): (main_ajp13_worker) Reading from client aborted or client network problems
[Mon Jun 24 12:18:05 2019] [15679:140534117611584] [info] ajp_service::jk_ajp_common.c (2778): (main_ajp13_worker) sending request to tomcat failed (unrecoverable), because of client read error (attempt=1)
[Mon Jun 24 12:18:05 2019] [15679:140534117611584] [info] jk_handler::mod_jk.c (2988): Aborting connection for worker=main_ajp13_worker

And here is the relevant part of the 2.4 million mod_jk log entries at the debug level, starting right at the HTTP 100 Continue and showing the very start of the file upload (you can see the magic number of the zip file, 50 4B 03 04):

[Mon Jun 24 14:37:08 2019] [17826:139891516274752] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 0160    32 65 32 00 A0 08 00 09 34 39 36 32 37 38 36 30  - 2e2.....49627860
[Mon Jun 24 14:37:08 2019] [17826:139891516274752] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 0170    33 00 00 06 45 78 70 65 63 74 00 00 0C 31 30 30  - 3...Expect...100
[Mon Jun 24 14:37:08 2019] [17826:139891516274752] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 0180    2D 63 6F 6E 74 69 6E 75 65 00 0A 00 0F 41 4A 50  - -continue....AJP
[Mon Jun 24 14:37:08 2019] [17826:139891516274752] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 0190    5F 52 45 4D 4F 54 45 5F 50 4F 52 54 00 00 05 33  - _REMOTE_PORT...3
[Mon Jun 24 14:37:08 2019] [17826:139891516274752] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 01a0    32 39 37 30 00 0A 00 0E 41 4A 50 5F 4C 4F 43 41  - 2970....AJP_LOCA
[Mon Jun 24 14:37:08 2019] [17826:139891516274752] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 01b0    4C 5F 41 44 44 52 00 00 0C 31 37 32 2E 33 31 2E  - L_ADDR...172.31.
[Mon Jun 24 14:37:08 2019] [17826:139891516274752] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 01c0    31 33 2E 39 36 00 0A 00 10 4A 4B 5F 4C 42 5F 41  - 13.96....JK_LB_A
[Mon Jun 24 14:37:08 2019] [17826:139891516274752] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 01d0    43 54 49 56 41 54 49 4F 4E 00 00 03 41 43 54 00  - CTIVATION...ACT.
[Mon Jun 24 14:37:08 2019] [17826:139891516274752] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 01e0    0A 00 0F 53 53 4C 5F 43 4C 49 45 4E 54 5F 43 45  - ...SSL_CLIENT_CE
[Mon Jun 24 14:37:08 2019] [17826:139891516274752] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 01f0    52 54 00 00 0F 53 53 4C 5F 43 4C 49 45 4E 54 5F  - RT...SSL_CLIENT_
[Mon Jun 24 14:37:08 2019] [17826:139891516274752] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 0200    43 45 52 54 00 FF 00 00 00 00 00 00 00 00 00 00  - CERT............
[Mon Jun 24 14:37:08 2019] [17826:139891516274752] [debug] ajp_send_request::jk_ajp_common.c (1782): (main_ajp13_worker) request body to send 496278603 - request body to resend 0
[Mon Jun 24 14:37:08 2019] [17826:139891516274752] [debug] ajp_send_request::jk_ajp_common.c (1886): (main_ajp13_worker) sending 8186 bytes of request body
[Mon Jun 24 14:37:08 2019] [17826:139891516274752] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): sending to ajp13 pos=4 len=8192 max=8192
[Mon Jun 24 14:37:08 2019] [17826:139891516274752] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 0000    12 34 1F FC 1F FA 50 4B 03 04 14 00 00 00 08 00  - .4....PK........
[Mon Jun 24 14:37:08 2019] [17826:139891516274752] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 0010    84 61 D8 4E 73 67 93 AF 7C 0A 00 00 E0 B0 00 00  - .a.Nsg..|.......
[Mon Jun 24 14:37:08 2019] [17826:139891516274752] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 0020    0A 00 1C 00 62 61 63 6B 75 70 2E 6C 6F 67 55 54  - ....backup.logUT
[Mon Jun 24 14:37:08 2019] [17826:139891516274752] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 0030    09 00 03 18 BE 10 5D 90 BD 10 5D 75 78 0B 00 01  - ......]...]ux...
[Mon Jun 24 14:37:08 2019] [17826:139891516274752] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 0040    04 1A 00 00 00 04 1A 00 00 00 ED 5C 4D 6F DC C8  - ...........\Mo..
[Mon Jun 24 14:37:08 2019] [17826:139891516274752] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 0050    11 BD E7 57 34 74 4A 80 D8 80 77 17 8B 45 80 1C  - ...W4tJ...w..E..

.... [lots of encoded data trimmed out here, the next part shows re-filling the 8k buffer] ....

[Mon Jun 24 14:37:08 2019] [17826:139891516274752] [debug] ajp_connection_tcp_get_message::jk_ajp_common.c (1462): received from ajp13 pos=0 len=3 max=8192E D7 E9 E6 DD BB  - 8...U?.er.>.....
[Mon Jun 24 14:37:08 2019] [17826:139891516274752] [debug] ajp_connection_tcp_get_message::jk_ajp_common.c (1462): 00000   06 1F FA 00 00 00 00 00 00 00 00 00 00 00 00 00  - .................
[Mon Jun 24 14:37:08 2019] [17826:139891516274752] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): sending to ajp13 pos=4 len=8192 max=8192 2E 40 41 4C 94  - ..$z~YW.?1G.@AL.
[Mon Jun 24 14:37:08 2019] [17826:139891516274752] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 0000    12 34 1F FC 1F FA C9 62 3E 48 C5 70 E9 05 E1 8D  - .4.....b>H.p....

.... [lots of encoded data trimmed out here, the next part shows where re-filling the 8k buffer fails] ....

[Mon Jun 24 14:37:28 2019] [17826:139891516274752] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 03e0    2D E5 36 F3 8C 12 8C 51 69 66 21 AE A5 58 BE 6E  - -.6....Qif!..X.n
[Mon Jun 24 14:37:28 2019] [17826:139891516274752] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 03f0    57 F3 F4 EC CB E9 49 9B 59 44 AB FE 66 6E 67 DC  - W.....I.YD..fng.
[Mon Jun 24 14:37:28 2019] [17826:139891516274752] [debug] ajp_connection_tcp_get_message::jk_ajp_common.c (1462): received from ajp13 pos=0 len=3 max=8192
[Mon Jun 24 14:37:28 2019] [17826:139891516274752] [debug] ajp_connection_tcp_get_message::jk_ajp_common.c (1462): 0000   06 1F FA 00 00 00 00 00 00 00 00 00 00 00 00 00  - ................
[Mon Jun 24 14:37:28 2019] [17826:139891516274752] [info] ajp_read_into_msg_buff::jk_ajp_common.c (1553): (main_ajp13_worker) receiving data from client failed. Connection aborted or network problems
[Mon Jun 24 14:37:28 2019] [17826:139891516274752] [info] ajp_process_callback::jk_ajp_common.c (2105): (main_ajp13_worker) Reading from client aborted or client network problems
[Mon Jun 24 14:37:28 2019] [17826:139891516274752] [info] ajp_service::jk_ajp_common.c (2778): (main_ajp13_worker) sending request to tomcat failed (unrecoverable), because of client read error (attempt=1)
[Mon Jun 24 14:37:28 2019] [17826:139891516274752] [debug] ajp_reset_endpoint::jk_ajp_common.c (851): (main_ajp13_worker) resetting endpoint with socket 24 (socket shutdown)
[Mon Jun 24 14:37:28 2019] [17826:139891516274752] [debug] ajp_abort_endpoint::jk_ajp_common.c (821): (main_ajp13_worker) aborting endpoint with socket 24
[Mon Jun 24 14:37:28 2019] [17826:139891516274752] [debug] jk_shutdown_socket::jk_connect.c (932): About to shutdown socket 24 [127.0.0.1:38678 -> 127.0.0.1:8009]
[Mon Jun 24 14:37:28 2019] [17826:139891516274752] [debug] jk_shutdown_socket::jk_connect.c (1005): shutting down the read side of socket 24 [127.0.0.1:38678 -> 127.0.0.1:8009]
[Mon Jun 24 14:37:28 2019] [17826:139891516274752] [debug] jk_shutdown_socket::jk_connect.c (1016): Shutdown socket 24 [127.0.0.1:38678 -> 127.0.0.1:8009] and read 265 lingering bytes in 0 sec.
[Mon Jun 24 14:37:28 2019] [17826:139891516274752] [debug] ajp_done::jk_ajp_common.c (3287): recycling connection pool for worker main_ajp13_worker and socket -1
[Mon Jun 24 14:37:28 2019] [17826:139891516274752] [info] jk_handler::mod_jk.c (2988): Aborting connection for worker=main_ajp13_worker
[Mon Jun 24 14:38:24 2019] [17825:139891516274752] [debug] wc_shutdown::jk_worker.c (390): Shutting down worker main_ajp13_worker
[Mon Jun 24 14:38:24 2019] [17825:139891516274752] [debug] jk_shm_close::jk_shm.c (745): Closed shared memory /var/log/httpd/mod_jk.shm.17823 childs=9
[Mon Jun 24 14:38:24 2019] [17877:139891516274752] [debug] wc_shutdown::jk_worker.c (390): Shutting down worker main_ajp13_worker

Looking at the AJPv3 documentation we see an explanation of the 8k chunks:

The container asks for more data from the request (If the body was too
large to fit in the first packet sent over or when the request is
chuncked). The server will send a body packet back with an amount of
data which is the minimum of the request_length, the maximum send body
size (8186 (8 Kbytes – 6)), and the number of bytes actually left to
send from the request body. If there is no more data in the body (i.e.
the servlet container is trying to read past the end of the body), the
server will send back an "empty" packet, which is a body packet with a
payload length of 0. (0x12,0x34,0x00,0x00)

In the above logs, I counted the number of times the 8k buffer was re-filled (36,856 times), and found that 301,703,216 bytes (287 MB, or 62%) of the file was transferred before the error occurred. On repeated attempts, this percentage varies wildly, but is usually over 300MB, and sometimes completes all 440MB successfully.

My interpretation of the above logs

The SSL handshake is succeeding, and the error occurs after the HTTP 100 Continue, so I suspect that the file has been partially sent prior to the following messages in mod_jk.log:

  • receiving data from client failed. Connection aborted or network problems
  • sending request to tomcat failed (unrecoverable), because of client read error (attempt=1)

Since there are no errors in catalina.out, and mod_jk is complaining about a client read error, I believe this rules out Tomcat itself (and the web application, Artifactory).

Most of the comments I see with a Google search on the above mod_jk messages state that they are transient network errors, but I'm not buying that since these are file transfers between to EC2 instances in the same region. I am also interpreting this as not having anything to do with a connection timeout, as that would (I think) produce a "Connection timed out after n milliseconds" message.

Changing the mod_jk and Tomcat configurations

Additional things I tried (these changes are cumulative, with no observable change in results):

  • upgraded mod_jk to the latest version (1.2.46)
  • increased worker packet size from 8,196 (default) to 16,384
  • increased worker packet size from 16,384 to 32,768
  • increased JkShmSize from 1kB (default) to 1GB (oops, value is specified in kB)
  • decreased JkShmSize from 1GB to 1MB
  • returned worker JkShmSize to default
  • returned worker packet size to default
  • increased worker retries from 2 (default) to 5
  • decreased reply_timeout from forever (default) to 1000ms (this actually caused some issues with the underlying service during successful uploads)
  • returned worker retries to default
  • returned reply_timeout to default
  • changed socket_keepalive from false (default) to true
  • returned socket_keepalive to default
  • changed Connector protocol from org.apache.coyote.http11.Http11NioProtocol to org.apache.coyote.http11.Http11Nio2Protocol
  • increased Tomcat connectionTimeout from 20 seconds (20000) to 60 seconds (60000)
  • set Tomcat connectionUploadTimeout to 60 seconds (60000)
  • set Tomcat disableUploadTimeout to false
  • returned connectionUploadTimeout and disableUploadTimeout to defaults
  • Forced chunked transfer via -H "Transfer-Encoding:chunked"
  • Set worker properties to: retries=2,socket_timeout=100,reply_timeout=30000
  • Reverted worker properties to defaults.
  • Added +DisableReuse to JkOptions.
  • Reverted JkOptions to defaults.
  • Created separate workers for the repo and repo-access virtual hosts.
  • Removed the non-SSL vhost entries, leaving only the two SSL virtual hosts.

Note: Separating the workers at least segregated the worker messages, so I know now that the error is occurring entirely on the repo web service, and not the repo-access web service:

[Sat Jun 29 16:16:55 2019] [6174:139690136819776] [info] ajp_read_into_msg_buff::jk_ajp_common.c (1550): (repo) receiving data from client failed. Connection aborted or network problems
[Sat Jun 29 16:16:55 2019] [6174:139690136819776] [info] ajp_process_callback::jk_ajp_common.c (2102): (repo) Reading from client aborted or client network problems
[Sat Jun 29 16:16:55 2019] [6174:139690136819776] [info] ajp_service::jk_ajp_common.c (2775): (repo) sending request to tomcat failed (unrecoverable), because of client read error (attempt=1)
[Sat Jun 29 16:16:55 2019] [6174:139690136819776] [info] jk_handler::mod_jk.c (2984): Aborting connection for worker=repo

Changing the HTTP(S) Client

I was able to reproduce the problem using wget instead of curl, which means that this isn't some esoteric issue with the client software:

-bash-4.2$ wget -v --tries=1 --user=backup --password=PASSWORD --header=X-Checksum-Sha1:6b9525bf9bb572ec7f70d0d474cb6533e0091bd3 --header=X-Checksum-Md5:6da0c444ad1b53dc1cf06784e204cb10 --method=PUT --body-file=snapshot-20190612.zip https://repo.mydomain.org/resource-snapshot/snapshot/20190612/snapshot-20190612.zip

--2019-06-24 19:59:16--  https://repo.mydomain.org/resource-snapshot/snapshot/20190612/snapshot-20190612.zip
Resolving repo.mydomain.org (repo.mydomain.org)... 123.222.100.132
Connecting to repo.mydomain.org (repo.mydomain.org)|123.222.100.132|:443... connected.
HTTP request sent, awaiting response... 401 401
Authentication selected: Basic realm="Artifactory Realm"
Reusing existing connection to repo.mydomain.org:443.
Giving up.

Testing on localhost

I've tested uploading from localhost on the archive server (https://localhost:443/), which requires adding the -k flag to curl in order to skip certificate hostname validation, and the upload succeeds every time (11 seconds). However, adding --limit-rate 20M causes the upload to fail every time (it works with --limit-rate 25M).

Bypassing Apache HTTPD, mod_jk and SSL works

Uploads always succeed if I bypass Apache HTTPD, mod_jk and SSL and go directly through port 8080:

[ec2-user@repo ~]$ curl -v -k --limit-rate 1024K -u backup:PASSWORD -H X-Checksum-Sha1:6b9525bf9bb572ec7f70d0d474cb6533e0091bd3 -H X-Checksum-Md5:6da0c444ad1b53dc1cf06784e204cb10 -T snapshot-20190612.zip http://localhost:8080/resource-snapshot/snapshot/20190612/snapshot-20190612.zip
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 8080 (#0)
* Server auth using Basic with user 'backup'
> PUT /resource-snapshot/snapshot/20190612/snapshot-20190612.zip HTTP/1.1
> Host: localhost:8080
> Authorization: Basic DELETED_TOKEN
> User-Agent: curl/7.61.1
> Accept: */*
> X-Checksum-Sha1:6b9525bf9bb572ec7f70d0d474cb6533e0091bd3
> X-Checksum-Md5:6da0c444ad1b53dc1cf06784e204cb10
> Content-Length: 496278603
> Expect: 100-continue
>
< HTTP/1.1 100
* We are completely uploaded and fine
< HTTP/1.1 201
< Server: Artifactory/5.3.2
...

Bypassing SSL only fails

Going through Apache HTTPD + mod_jk without SSL, I am still able to replicate the problem. This means that the problem has nothing to do with SSL.

[ec2-user@repo ~]$ curl -v -k --limit-rate 1024K -u backup:PASSWORD -H X-Checksum-Sha1:6b9525bf9bb572ec7f70d0d474cb6533e0091bd3 -H X-Checksum-Md5:6da0c444ad1b53dc1cf06784e204cb10 -T snapshot-20190612.zip http://localhost/resource-snapshot/snapshot/20190612/snapshot-20190612.zip
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 8080 (#0)
* Server auth using Basic with user 'backup'
> PUT /resource-snapshot/snapshot/20190612/snapshot-20190612.zip HTTP/1.1
> Host: localhost:8080
> Authorization: Basic DELETED_TOKEN
> User-Agent: curl/7.61.1
> Accept: */*
> X-Checksum-Sha1:6b9525bf9bb572ec7f70d0d474cb6533e0091bd3
> X-Checksum-Md5:6da0c444ad1b53dc1cf06784e204cb10
> Content-Length: 496278603
> Expect: 100-continue
>
< HTTP/1.1 100 Continue
* Recv failure: Connection reset by peer
* Closing connection 0
curl: (56) Recv failure: Connection reset by peer

Bypassing HTTPD and mod_jk

I tried bypassing Apache HTTPD and mod_jk by uploading directly to Tomcat via port 8443 (still using SSL). These requests succeeded every time. This leads me to believe that the problem is with Apache HTTPD and/or mod_jk, and is not caused by "transient network errors" or a firewall.

TL;DR

The upload failures only occur when going through HTTPD + mod_jk, not when communicating with Tomcat directly. SSL has been eliminated as a potential source of the problem. This is not a network problem because the error is reproducible when uploading from localhost. The issue appears to be related only to the amount of time it takes to transfer the file, not the size of the file.

My Question

Are there any configuration options that I should look into for HTTPD and/or mod_jk, workers.properties or even Tomcat to eliminate these problems?

Alternatively, is there any way to tell mod_jk to attempt to handle these failed buffer re-fills in a fault tolerant way, so that the uploads can successfully complete?

Best Answer

Have you tried to downgrade Apache/modSSL to 2.4.38?

We had file upload issues since we upgraded to 2.4.39.

Related Topic