Hi,
I did some debugging on the server side.
Even with loglevel trace5 and also different TLS versions (I tested 1.1,
1.2 and 1.3) I didn't find the root cause.
In the attachment you'll find the export of the Apache error log with
loglevel trace5. Maybe it's helpfull for the libressl developers.
On the client side I just did an pkg_add -v bash
Best regards,
Sven
On 1/31/20 9:24 PM, Sven Wolf wrote:
Hi,
I run current. After I run sysupgrade today (GENERIC.MP #626 build Jan
30) it's not possible to run pkd_add. I always get the error
TLS connect failure: failed to set session
signify: gzheader truncated
The error is reproducible on two machines and didn't occur until build
#616 (Jan 21).
/etc/installurl points to an internal mirror server. This mirror server
runs on Debian/Apache and has a letsencrypt certificate. Maybe the
letsencrypt certificate is the root cause.
When I switch /etc/installurl to an official OpenBSD mirror (e.g.
https://artfiles.org/openbsd/) the error doesn't occur.
Also when /etc/installurl points to the internal mirror server using the
http instead of the https protocol then there is also no error.
sysupgrade runs without errors against the internal mirror server via
https. Also an wget of a package (e.g atk-2.34.1p1) via the https
protocol shows no error.
I compared the atk-2.34.1p1 package against an official mirror. There is
no difference in the md5sum.
Maybe the pkg_add error has something in common with
https://marc.info/?t=157996435100001&r=1&w=2
If there is something I should test/change, please let me know.
Thanks and best regards,
Sven
[Sat Feb 01 12:36:57.605934 2020] [ssl:trace3] [pid 4837] ssl_engine_init.c(579): Creating new SSL context (protocols: TLSv1.1)
[Sat Feb 01 12:36:57.606388 2020] [ssl:trace1] [pid 4837] ssl_engine_init.c(915): Configuring permitted SSL ciphers [HIGH:!aNULL:!aNULL:!eNULL:!EXP]
[Sat Feb 01 12:36:57.606877 2020] [ssl:debug] [pid 4837] ssl_engine_init.c(1111): AH01904: Configuring server certificate chain (1 CA certificate)
[Sat Feb 01 12:36:57.606894 2020] [ssl:debug] [pid 4837] ssl_engine_init.c(479): AH01893: Configuring TLS extension handling
[Sat Feb 01 12:36:57.607477 2020] [ssl:trace3] [pid 4837] ssl_util_ssl.c(465): [mirror.somedomain.de:443] modssl_X509_match_name: expecting name 'mirror.somedomain.de', matched by ID 'mirror.somedomain.de'
[Sat Feb 01 12:36:57.607569 2020] [ssl:debug] [pid 4837] ssl_util_ssl.c(476): AH02412: [mirror.somedomain.de:443] Cert matches for name 'mirror.somedomain.de' [subject: CN=mirror.somedomain.de / issuer: CN=Let's Encrypt Authority X3,O=Let's Encrypt,C=US / serial: 03D026E69E436EA8EF822C5DE8B359B40DE5 / notbefore: Jan 31 01:25:56 2020 GMT / notafter: Apr 30 01:25:56 2020 GMT]
[Sat Feb 01 12:36:57.607587 2020] [ssl:info] [pid 4837] AH02568: Certificate and private key mirror.somedomain.de:443:0 configured from /etc/letsencrypt/live/mirror.somedomain.de/cert.pem and /etc/letsencrypt/live/mirror.somedomain.de/privkey.pem
[Sat Feb 01 12:36:57.611517 2020] [mpm_prefork:notice] [pid 4837] AH00163: Apache/2.4.38 (Raspbian) OpenSSL/1.1.1d configured -- resuming normal operations
[Sat Feb 01 12:36:57.611601 2020] [core:notice] [pid 4837] AH00094: Command line: '/usr/sbin/apache2'
[Sat Feb 01 12:37:02.227125 2020] [ssl:trace4] [pid 4924] ssl_engine_io.c(2214): [client 192.168.1.103:34913] OpenSSL: write 3137/3137 bytes to BIO#9e95a8 [mem: af8250]
[Sat Feb 01 12:37:02.234666 2020] [ssl:trace4] [pid 4924] ssl_engine_io.c(2214): [client 192.168.1.103:34913] OpenSSL: read 5/5 bytes from BIO#a65fc0 [mem: af23db]
[Sat Feb 01 12:37:02.234828 2020] [ssl:trace4] [pid 4924] ssl_engine_io.c(2214): [client 192.168.1.103:34913] OpenSSL: read 69/69 bytes from BIO#a65fc0 [mem: af23e0]
[Sat Feb 01 12:37:02.235645 2020] [socache_shmcb:debug] [pid 4924] mod_socache_shmcb.c(495): AH00831: socache_shmcb_store (0xe2 -> subcache 2)
[Sat Feb 01 12:37:02.235809 2020] [socache_shmcb:debug] [pid 4924] mod_socache_shmcb.c(849): AH00847: insert happened at idx=0, data=(0:32)
[Sat Feb 01 12:37:02.235865 2020] [socache_shmcb:debug] [pid 4924] mod_socache_shmcb.c(854): AH00848: finished insert, subcache: idx_pos/idx_used=0/1, data_pos/data_used=0/214
[Sat Feb 01 12:37:02.235915 2020] [socache_shmcb:debug] [pid 4924] mod_socache_shmcb.c(516): AH00834: leaving socache_shmcb_store successfully
[Sat Feb 01 12:37:02.236010 2020] [ssl:trace2] [pid 4924] ssl_engine_kernel.c(2042): Inter-Process Session Cache: request=SET status=OK id=e259e8e5b9da7257ddb9c78cc0f212faa03132eebedb0b9f8b4afe5b2d1a36ac timeout=300s (session caching)
[Sat Feb 01 12:37:02.236172 2020] [ssl:trace4] [pid 4924] ssl_engine_io.c(2214): [client 192.168.1.103:34913] OpenSSL: write 303/303 bytes to BIO#9e95a8 [mem: af8250]
[Sat Feb 01 12:37:02.236841 2020] [socache_shmcb:debug] [pid 4924] mod_socache_shmcb.c(495): AH00831: socache_shmcb_store (0x5b -> subcache 27)
[Sat Feb 01 12:37:02.236992 2020] [socache_shmcb:debug] [pid 4924] mod_socache_shmcb.c(849): AH00847: insert happened at idx=0, data=(0:32)
[Sat Feb 01 12:37:02.237050 2020] [socache_shmcb:debug] [pid 4924] mod_socache_shmcb.c(854): AH00848: finished insert, subcache: idx_pos/idx_used=0/1, data_pos/data_used=0/213
[Sat Feb 01 12:37:02.237126 2020] [socache_shmcb:debug] [pid 4924] mod_socache_shmcb.c(516): AH00834: leaving socache_shmcb_store successfully
[Sat Feb 01 12:37:02.237185 2020] [ssl:trace2] [pid 4924] ssl_engine_kernel.c(2042): Inter-Process Session Cache: request=SET status=OK id=5b58f1568e8ae0e039af729d30562a5cf72a46ee93eba6015ed3e3ea090eb947 timeout=300s (session caching)
[Sat Feb 01 12:37:02.237344 2020] [ssl:trace4] [pid 4924] ssl_engine_io.c(2214): [client 192.168.1.103:34913] OpenSSL: write 303/303 bytes to BIO#9e95a8 [mem: af8250]
[Sat Feb 01 12:37:02.238499 2020] [ssl:trace4] [pid 4924] ssl_engine_io.c(2214): [client 192.168.1.103:34913] OpenSSL: read 5/5 bytes from BIO#a65fc0 [mem: ae9b3b]
[Sat Feb 01 12:37:02.238610 2020] [ssl:trace4] [pid 4924] ssl_engine_io.c(2214): [client 192.168.1.103:34913] OpenSSL: read 141/141 bytes from BIO#a65fc0 [mem: ae9b40]
[Sat Feb 01 12:37:02.238949 2020] [ssl:debug] [pid 4924] ssl_engine_kernel.c(383): [client 192.168.1.103:34913] AH02034: Initial (No.1) HTTPS request received for child 0 (server mirror.somedomain.de:443)
[Sat Feb 01 12:37:02.239123 2020] [http:trace4] [pid 4924] http_request.c(437): [client 192.168.1.103:34913] Headers received from client:
[Sat Feb 01 12:37:02.239205 2020] [http:trace4] [pid 4924] http_request.c(441): [client 192.168.1.103:34913] Connection: close
[Sat Feb 01 12:37:02.239257 2020] [http:trace4] [pid 4924] http_request.c(441): [client 192.168.1.103:34913] Host: mirror.somedomain.de
[Sat Feb 01 12:37:02.239379 2020] [http:trace4] [pid 4924] http_request.c(441): [client 192.168.1.103:34913] User-Agent: OpenBSD ftp
[Sat Feb 01 12:37:02.239832 2020] [authz_core:debug] [pid 4924] mod_authz_core.c(820): [client 192.168.1.103:34913] AH01626: authorization result of Require all granted: granted
[Sat Feb 01 12:37:02.239978 2020] [authz_core:debug] [pid 4924] mod_authz_core.c(820): [client 192.168.1.103:34913] AH01626: authorization result of <RequireAny>: granted
[Sat Feb 01 12:37:02.240072 2020] [core:trace3] [pid 4924] request.c(312): [client 192.168.1.103:34913] request authorized without authentication by access_checker_ex hook: /openbsd/snapshots/packages/amd64/
[Sat Feb 01 12:37:02.240757 2020] [authz_core:debug] [pid 4924] mod_authz_core.c(820): [client 192.168.1.103:34913] AH01626: authorization result of Require all granted: granted
[Sat Feb 01 12:37:02.240857 2020] [authz_core:debug] [pid 4924] mod_authz_core.c(820): [client 192.168.1.103:34913] AH01626: authorization result of <RequireAny>: granted
[Sat Feb 01 12:37:02.240910 2020] [core:trace3] [pid 4924] request.c(312): [client 192.168.1.103:34913] request authorized without authentication by access_checker_ex hook: /openbsd/snapshots/packages/amd64/index.php
[Sat Feb 01 12:37:03.057905 2020] [filter:trace4] [pid 4924] mod_filter.c(169): [client 192.168.1.103:34913] Content-Type 'text/html;charset=UTF-8' ...
[Sat Feb 01 12:37:03.058102 2020] [filter:trace4] [pid 4924] mod_filter.c(181): [client 192.168.1.103:34913] ... did not match 'application/xml'
[Sat Feb 01 12:37:03.058157 2020] [filter:trace2] [pid 4924] mod_filter.c(188): [client 192.168.1.103:34913] Content-Type condition for 'deflate' did not match
[Sat Feb 01 12:37:03.058205 2020] [filter:trace4] [pid 4924] mod_filter.c(169): [client 192.168.1.103:34913] Content-Type 'text/html;charset=UTF-8' ...
[Sat Feb 01 12:37:03.058252 2020] [filter:trace4] [pid 4924] mod_filter.c(181): [client 192.168.1.103:34913] ... did not match 'application/rss+xml'
[Sat Feb 01 12:37:03.058297 2020] [filter:trace2] [pid 4924] mod_filter.c(188): [client 192.168.1.103:34913] Content-Type condition for 'deflate' did not match
[Sat Feb 01 12:37:03.058342 2020] [filter:trace4] [pid 4924] mod_filter.c(169): [client 192.168.1.103:34913] Content-Type 'text/html;charset=UTF-8' ...
[Sat Feb 01 12:37:03.058437 2020] [filter:trace4] [pid 4924] mod_filter.c(181): [client 192.168.1.103:34913] ... did not match 'application/x-javascript'
[Sat Feb 01 12:37:03.058486 2020] [filter:trace4] [pid 4924] mod_filter.c(181): [client 192.168.1.103:34913] ... did not match 'application/javascript'
[Sat Feb 01 12:37:03.058551 2020] [filter:trace4] [pid 4924] mod_filter.c(181): [client 192.168.1.103:34913] ... did not match 'application/ecmascript'
[Sat Feb 01 12:37:03.058726 2020] [filter:trace2] [pid 4924] mod_filter.c(188): [client 192.168.1.103:34913] Content-Type condition for 'deflate' did not match
[Sat Feb 01 12:37:03.058833 2020] [filter:trace4] [pid 4924] mod_filter.c(169): [client 192.168.1.103:34913] Content-Type 'text/html;charset=UTF-8' ...
[Sat Feb 01 12:37:03.058965 2020] [filter:trace4] [pid 4924] mod_filter.c(175): [client 192.168.1.103:34913] ... matched 'text/html'
[Sat Feb 01 12:37:03.059037 2020] [filter:trace2] [pid 4924] mod_filter.c(188): [client 192.168.1.103:34913] Content-Type condition for 'deflate' matched
[Sat Feb 01 12:37:03.059363 2020] [http:trace3] [pid 4924] http_filters.c(1128): [client 192.168.1.103:34913] Response sent with status 200, headers:
[Sat Feb 01 12:37:03.059487 2020] [http:trace5] [pid 4924] http_filters.c(1135): [client 192.168.1.103:34913] Date: Sat, 01 Feb 2020 11:37:02 GMT
[Sat Feb 01 12:37:03.059538 2020] [http:trace5] [pid 4924] http_filters.c(1138): [client 192.168.1.103:34913] Server: Apache
[Sat Feb 01 12:37:03.059590 2020] [http:trace4] [pid 4924] http_filters.c(957): [client 192.168.1.103:34913] Vary: Accept-Encoding
[Sat Feb 01 12:37:03.059659 2020] [http:trace4] [pid 4924] http_filters.c(957): [client 192.168.1.103:34913] Connection: close
[Sat Feb 01 12:37:03.059724 2020] [http:trace4] [pid 4924] http_filters.c(957): [client 192.168.1.103:34913] Transfer-Encoding: chunked
[Sat Feb 01 12:37:03.059785 2020] [http:trace4] [pid 4924] http_filters.c(957): [client 192.168.1.103:34913] Content-Type: text/html;charset=UTF-8
[Sat Feb 01 12:37:03.060173 2020] [ssl:trace4] [pid 4924] ssl_engine_io.c(2214): [client 192.168.1.103:34913] OpenSSL: write 209/209 bytes to BIO#9e95a8 [mem: ae9b3b]
[Sat Feb 01 12:37:03.060850 2020] [ssl:trace4] [pid 4924] ssl_engine_io.c(2214): [client 192.168.1.103:34913] OpenSSL: write 8015/8015 bytes to BIO#9e95a8 [mem: ae9b3b]
...
[Sat Feb 01 12:37:03.575790 2020] [ssl:trace4] [pid 4924] ssl_engine_io.c(2214): [client 192.168.1.103:34913] OpenSSL: write 24/24 bytes to BIO#9e95a8 [mem: ae9b3b]
[Sat Feb 01 12:37:03.575871 2020] [ssl:debug] [pid 4924] ssl_engine_io.c(1106): [client 192.168.1.103:34913] AH02001: Connection closed to child 0 with standard shutdown (server mirror.somedomain.de:443)
