Назад | Перейти на главную страницу

Спорадические ошибки клиента mod_jk при загрузке больших файлов

Примечание: В конце этого вопроса стоит TL; DR.

У меня есть сценарий ночного резервного копирования, который надежно работает в течение 6 лет, а два месяца назад он начал отказывать при загрузке на мой архивный сервер (только примерно 1 из 4 попыток была успешной). Это начало происходить, когда размер файла резервной копии превысил 440 МБ (успешная загрузка занимает 20-40 секунд). Другие файлы меньшего размера (> 200 МБ) успешно загружаются каждый раз. Начало сбоев не совпало с какими-либо изменениями конфигурации или обновлениями рассматриваемых серверов.

Вот подробности загружаемого мной файла:

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

Эти файлы загружаются на мой сервер с помощью curl PUT (см. команду ниже). Исходный сервер - это экземпляр Amazon Linux в Вирджинии, а целевой сервер - это экземпляр Amazon Linux в Огайо (оба находятся в Восточном регионе США).

Веб-сервис, обрабатывающий загрузку, является Apache HTTPD 2.4.39 + mod24_ssl / OpenSSL 1.0.2k -> mod_jk 1.2.42 -> Apache Tomcat 8.5.40 -> Артефактор 5.3.2 пример.

Я захватил jk_status страница до и после возникновения одной из этих ошибок (до и после находятся в анимированном GIF-файле, чтобы выделить различия). Ошибка интерпретируется как Ошибка клиента по mod_jk.

Мой мод / jk worker.properties файл:

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

Ниже приведены выходные данные консоли (данные авторизации очищены) неудачной загрузки, за которой сразу следует успешная загрузка:

-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

При второй (или часто третьей или четвертой) попытке загрузки в конечном итоге это удается:

-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
}

Журналы сервера не особо информативны. Вот соответствующие журналы при сбое загрузки:

/ 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

Нет записей в журнале.

/var/log/httpd/mod_jk.log

Это журналы, когда уровень журнала mod / jk установлен на Информация:

[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

И вот соответствующая часть 2,4 миллиона записей журнала mod_jk на отлаживать уровень, начиная с HTTP 100 Continue и показывая самое начало загрузки файла (вы можете увидеть магический номер zip-файла, 50 4Б 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

Глядя на Документация AJPv3 мы видим объяснение кусков 8k:

Контейнер запрашивает дополнительные данные из запроса (если тело было слишком большим, чтобы поместиться в первый отправленный пакет, или когда запрос разбит на части). Сервер отправит основной пакет обратно с объемом данных, который является минимумом из request_length, максимального размера тела отправки (8186 (8 Кбайт - 6)) и количества байтов, фактически оставшихся для отправки из тела запроса. Если в теле больше нет данных (т. Е. Контейнер сервлета пытается прочитать за пределами конца тела), сервер отправит обратно «пустой» пакет, который представляет собой основной пакет с длиной полезной нагрузки 0. ( 0x12,0x34,0x00,0x00)

В приведенных выше журналах я подсчитал, сколько раз был повторно заполнен буфер размером 8 КБ (36 856 раз), и обнаружил, что 301 703 216 байт (287 МБ, или 62%) файла были переданы до возникновения ошибки. При повторных попытках этот процент сильно меняется, но обычно превышает 300 МБ, а иногда успешно завершает все 440 МБ.

Моя интерпретация приведенных выше журналов

Рукопожатие SSL проходит успешно, и ошибка возникает после HTTP 100 Continue, поэтому я подозреваю, что файл был частично отправлен до следующих сообщений в mod_jk.log:

Поскольку в catalina.out, и mod_jk жалуется на ошибку чтения клиента, я считаю, что это исключает сам Tomcat (и веб-приложение, Artifactory).

Большинство из Комментарии Я вижу с поиск Гугл в приведенных выше сообщениях mod_jk указано, что это временные сетевые ошибки, но я не верю в это, поскольку это передача файлов между экземплярами EC2 в одном регионе. Я также интерпретирую это как не имеющее ничего общего с тайм-аутом соединения, поскольку это (я думаю) привело бы к появлению "Время ожидания соединения истекло через n миллисекунд"сообщение.

Изменение конфигураций mod_jk и Tomcat

Дополнительные вещи, которые я пробовал (эти изменения являются кумулятивными, без заметных изменений в результатах):

Примечание. Разделение рабочих, по крайней мере, отделило сообщения рабочих, поэтому теперь я знаю, что ошибка возникает полностью в веб-службе репо, а не в веб-службе доступа к репо:

[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

Смена клиента HTTP (S)

Мне удалось воспроизвести проблему с помощью wget вместо curl, что означает, что это не какая-то эзотерическая проблема с клиентским программным обеспечением:

-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.

Тестирование на localhost

Я тестировал загрузку с localhost на архивный сервер (https: // локальный: 443 /), что требует добавления -k чтобы пропустить проверку имени хоста сертификата, и загрузка будет успешной каждый раз (11 секунд). Однако добавление --limit-rate 20M приводит к сбою загрузки каждый раз (работает с --limit-rate 25M).

Обход Apache HTTPD, mod_jk и SSL работает

Загрузка всегда проходит успешно, если я обхожу Apache HTTPD, mod_jk и SSL и иду напрямую через порт 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
...

В обход Только SSL терпит неудачу

Проходя через Apache HTTPD + mod_jk без SSL, я все еще могу воспроизвести проблему. Это означает, что проблема не связана с 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

Обход HTTPD и mod_jk

Я попытался обойти Apache HTTPD и mod_jk, загрузив его напрямую в Tomcat через порт 8443 (все еще используя SSL). Эти запросы каждый раз выполнялись успешно. Это заставляет меня думать, что проблема связана с Apache HTTPD и / или mod_jk, а не из-за «временных сетевых ошибок» или брандмауэра.

TL; DR

Сбои при загрузке происходят только при прохождении HTTPD + mod_jk, а не при непосредственном общении с Tomcat. SSL был исключен как потенциальный источник проблемы. Это не проблема сети, потому что ошибка воспроизводится при загрузке с localhost. Проблема, похоже, связана только с количеством времени, которое требуется для передачи файла, а не с размером файла.

Мой вопрос

Есть ли какие-либо параметры конфигурации, которые я должен изучить для HTTPD и / или mod_jk, worker.properties или даже Кот устранить эти проблемы?

В качестве альтернативы, есть ли способ узнать mod_jk попытаться обработать эти неудачные повторные заполнения буфера отказоустойчивым способом, чтобы загрузка могла успешно завершиться?

Вы пытались понизить версию Apache / modSSL до 2.4.38?

После обновления до 2.4.39 у нас были проблемы с загрузкой файлов.