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

Question

Спорадические ошибки клиента 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 (см. команду ниже). server - это экземпляр Amazon Linux в Вирджинии, а целевой сервер - это экземпляр Amazon Linux в Огайо (b другие находятся в Восточном регионе США).

Веб-служба, которая обрабатывает загрузку, представляет собой 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 .

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

Мой файл mod / 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 установлен на 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

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

Просматривая документацию AJPv3 , мы видим объяснение 8-килобайтных блоков:

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

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

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

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

не удалось получить данные от клиента. Соединение прервано или сетевые проблемы
не удалось отправить запрос на tomcat (невозможно восстановить) из-за ошибки чтения клиента (попытка = 1)

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

Большинство комментариев я вижу с помощью поиска Google в вышеприведенных сообщениях mod_jk говорится, что они являются временными сетевыми ошибками, но я не верю, что это передача файлов между экземплярами EC2 в одном регионе. Я также интерпретирую это как не имеющее ничего общего с тайм-аутом соединения, поскольку это (я думаю) приведет к появлению сообщения « Connection timed out after n milliseconds ».

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

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

обновил mod_jk до последней версии (1.2.46)
увеличил размер рабочего пакета с 8196 (по умолчанию) до 16384
увеличен размер рабочего пакета с 16 384 до 32 768
увеличен JkShmSize с 1 КБ (по умолчанию) до 1 ГБ (ой, значение указано в КБ)
уменьшен размер JkShmSize с 1 ГБ до 1 МБ
возвращен рабочий JkShmSize по умолчанию
вернул размер рабочего пакета по умолчанию
увеличил количество повторений рабочего с 2 (по умолчанию) до 5
уменьшил reply_timeout с навсегда (по умолчанию) до 1000 мс (это фактически вызвало некоторые проблемы с базовой службой во время успешной загрузки)
возвращено работник повторяет попытки по умолчанию
вернул репутацию ly_timeout по умолчанию
изменено socket_keepalive с false (по умолчанию) на true
возвращено socket_keepalive по умолчанию
изменен протокол соединителя с org.apache.coyote.http11.Http11NioProtocol на org.apache.coyote.http11.Http11Nio2Protocol
] увеличил Tomcat connectionTimeout с 20 секунд (20000) до 60 секунд (60000)
установил Tomcat connectionUploadTimeout на 60 секунд (60000)
установил Tomcat disableUploadTimeout на false
вернул connectionUploadTimeout и disableUploadTimeout на значения по умолчанию
Принудительно разбит на части передача через -H "Transfer-Encoding: chunked"
Установить для свойств рабочего процесса значение: retries = 2, socket_timeout = 100, reply_timeout = 30000
Свойства рабочего процесса возвращены к значениям по умолчанию.
Добавлено + DisableReuse в JkOptions.
Восстановлены параметры JkOptions по умолчанию.
Созданы отдельные рабочие процессы для виртуальных хостов репо и репо-доступа.
Удалены записи виртуальных хостов без SSL, оставлены только два виртуальных хоста SSL.

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

[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: // localhost : 443 / ), что требует добавления флага -k для curl, чтобы пропустить проверку имени хоста сертификата, и загрузка выполняется каждый раз успешно (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 или даже Tomcat для устранения этих проблем?

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

0

apache-2.4 curl file-transfer mod-jk tomcat8

задан vallismortis 31 July 2019 в 19:06

Ссылка

1 ответ

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

Теги

Похожие вопросы