Comment 3 for bug 1803689

Revision history for this message
Virsacer (virsacer) wrote :

When setting LogLevel to debug, I get something:

root@Ubuntu /var/log/apache2 $ tail -fn 0 access.log error.log
==> access.log <==

==> error.log <==
[Tue Nov 20 22:05:03.543044 2018] [ssl:debug] [pid 3115:tid 139645123802880] ssl_engine_kernel.c(1584): [client 10.0.2.2:55646] AH02275: Certificate Verification, depth 2, CRL checking mode: none (0) [subject: CN=xxxxxxxxxxxxxx CA - G2,O=xxxxxxxxxxxx,C=CH / issuer: CN=xxxxxxxxxxxxxx CA - G2,O=xxxxxxxxxxxx,C=CH / serial: xxxxxxxxxxxxxxxx / notbefore: xxxxxxxxxxxxxxx 2006 GMT / notafter: xxxxxxxxxxxxxxx 2036 GMT]
[Tue Nov 20 22:05:03.543249 2018] [ssl:debug] [pid 3115:tid 139645123802880] ssl_engine_kernel.c(1584): [client 10.0.2.2:55646] AH02275: Certificate Verification, depth 1, CRL checking mode: none (0) [subject: CN=xxxxxxxxxxxxxxxxxxxxxxx CA 2014 - G22,O=xxxxxxxxxxxx,C=CH / issuer: CN=xxxxxxxxxxxxxx CA - G2,O=xxxxxxxxxxxx,C=CH / serial: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxx / notbefore: xxxxxxxxxxxxxxx 2014 GMT / notafter: xxxxxxxxxxxxxxx 2029 GMT]
[Tue Nov 20 22:05:03.543325 2018] [ssl:debug] [pid 3115:tid 139645123802880] ssl_engine_kernel.c(1584): [client 10.0.2.2:55646] AH02275: Certificate Verification, depth 0, CRL checking mode: none (0) [subject: CN=xxxxxxxxxxxxxxxx,emailAddress=xxxxxxxxxxxxxxxxxxxxx / issuer: CN=xxxxxxxxxxxxxxxxxxxxxxx CA 2014 - G22,O=xxxxxxxxxxxx,C=CH / serial: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx / notbefore: xxxxxxxxxxxxxxx 2017 GMT / notafter: xxxxxxxxxxxxxxx 2020 GMT]
[Tue Nov 20 22:05:03.543663 2018] [socache_shmcb:debug] [pid 3115:tid 139645123802880] mod_socache_shmcb.c(495): AH00831: socache_shmcb_store (0x23 -> subcache 3)
[Tue Nov 20 22:05:03.543690 2018] [socache_shmcb:debug] [pid 3115:tid 139645123802880] mod_socache_shmcb.c(849): AH00847: insert happened at idx=0, data=(0:32)
[Tue Nov 20 22:05:03.543694 2018] [socache_shmcb:debug] [pid 3115:tid 139645123802880] mod_socache_shmcb.c(854): AH00848: finished insert, subcache: idx_pos/idx_used=0/1, data_pos/data_used=0/1977
[Tue Nov 20 22:05:03.543697 2018] [socache_shmcb:debug] [pid 3115:tid 139645123802880] mod_socache_shmcb.c(516): AH00834: leaving socache_shmcb_store successfully
[Tue Nov 20 22:05:03.543705 2018] [ssl:debug] [pid 3115:tid 139645123802880] ssl_engine_kernel.c(2069): [client 10.0.2.2:55646] AH02041: Protocol: TLSv1.2, Cipher: ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
[Tue Nov 20 22:07:03.569091 2018] [authz_core:debug] [pid 3115:tid 139645123802880] mod_authz_core.c(820): [client 10.0.2.2:55646] AH01626: authorization result of Require valid-user : denied (no authenticated user yet)
[Tue Nov 20 22:07:03.569169 2018] [authz_core:debug] [pid 3115:tid 139645123802880] mod_authz_core.c(820): [client 10.0.2.2:55646] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet)
[Tue Nov 20 22:07:03.571000 2018] [authz_core:debug] [pid 3115:tid 139645123802880] mod_authz_core.c(820): [client 10.0.2.2:55646] AH01626: authorization result of Require valid-user : denied (no authenticated user yet)
[Tue Nov 20 22:07:03.579805 2018] [authz_core:debug] [pid 3115:tid 139645123802880] mod_authz_core.c(820): [client 10.0.2.2:55646] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet)
[Tue Nov 20 22:07:03.580154 2018] [authz_core:debug] [pid 3115:tid 139645123802880] mod_authz_core.c(820): [client 10.0.2.2:55646] AH01626: authorization result of Require valid-user : denied (no authenticated user yet)
[Tue Nov 20 22:07:03.580191 2018] [authz_core:debug] [pid 3115:tid 139645123802880] mod_authz_core.c(820): [client 10.0.2.2:55646] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet)
[Tue Nov 20 22:07:03.580227 2018] [authz_core:debug] [pid 3115:tid 139645123802880] mod_authz_core.c(820): [client 10.0.2.2:55646] AH01626: authorization result of Require all granted: granted
[Tue Nov 20 22:07:03.580233 2018] [authz_core:debug] [pid 3115:tid 139645123802880] mod_authz_core.c(820): [client 10.0.2.2:55646] AH01626: authorization result of <RequireAny>: granted
[Tue Nov 20 22:07:03.581097 2018] [ssl:debug] [pid 3115:tid 139645123802880] ssl_engine_kernel.c(757): [client 10.0.2.2:55646] AH02255: Changed client verification type will force renegotiation
[Tue Nov 20 22:07:03.581127 2018] [ssl:info] [pid 3115:tid 139645123802880] [client 10.0.2.2:55646] AH02221: Requesting connection re-negotiation
[Tue Nov 20 22:07:03.581148 2018] [ssl:debug] [pid 3115:tid 139645123802880] ssl_engine_kernel.c(987): [client 10.0.2.2:55646] AH02260: Performing full renegotiation: complete handshake protocol (client does support secure renegotiation)
[Tue Nov 20 22:07:03.581274 2018] [ssl:debug] [pid 3115:tid 139645123802880] ssl_engine_kernel.c(2069): [client 10.0.2.2:55646] AH02041: Protocol: TLSv1.2, Cipher: ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
[Tue Nov 20 22:07:03.581316 2018] [ssl:info] [pid 3115:tid 139645123802880] [client 10.0.2.2:55646] AH02226: Awaiting re-negotiation handshake
[Tue Nov 20 22:07:03.581803 2018] [ssl:debug] [pid 3115:tid 139645123802880] ssl_engine_kernel.c(2196): [client 10.0.2.2:55646] AH02645: Server name not provided via TLS extension (using default/first virtual host)
[Tue Nov 20 22:07:03.581853 2018] [ssl:debug] [pid 3115:tid 139645123802880] ssl_util_stapling.c(761): AH01951: stapling_cb: OCSP Stapling callback called
[Tue Nov 20 22:07:03.581859 2018] [ssl:info] [pid 3115:tid 139645123802880] AH01926: stapling_get_certinfo: stapling not supported for certificate
[Tue Nov 20 22:07:03.970096 2018] [ssl:debug] [pid 3115:tid 139645123802880] ssl_engine_kernel.c(1584): [client 10.0.2.2:55646] AH02275: Certificate Verification, depth 2, CRL checking mode: none (0) [subject: CN=xxxxxxxxxxxxxx CA - G2,O=xxxxxxxxxxxx,C=CH / issuer: CN=xxxxxxxxxxxxxx CA - G2,O=xxxxxxxxxxxx,C=CH / serial: xxxxxxxxxxxxxxxx / notbefore: xxxxxxxxxxxxxxx 2006 GMT / notafter: xxxxxxxxxxxxxxx 2036 GMT]
[Tue Nov 20 22:07:03.970260 2018] [ssl:debug] [pid 3115:tid 139645123802880] ssl_engine_kernel.c(1584): [client 10.0.2.2:55646] AH02275: Certificate Verification, depth 1, CRL checking mode: none (0) [subject: CN=xxxxxxxxxxxxxxxxxxxxxxx CA 2014 - G22,O=xxxxxxxxxxxx,C=CH / issuer: CN=xxxxxxxxxxxxxx CA - G2,O=xxxxxxxxxxxx,C=CH / serial: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxx / notbefore: xxxxxxxxxxxxxxx 2014 GMT / notafter: xxxxxxxxxxxxxxx 2029 GMT]
[Tue Nov 20 22:07:03.970345 2018] [ssl:debug] [pid 3115:tid 139645123802880] ssl_engine_kernel.c(1584): [client 10.0.2.2:55646] AH02275: Certificate Verification, depth 0, CRL checking mode: none (0) [subject: CN=xxxxxxxxxxxxxxxx,emailAddress=xxxxxxxxxxxxxxxxxxxxx / issuer: CN=xxxxxxxxxxxxxxxxxxxxxxx CA 2014 - G22,O=xxxxxxxxxxxx,C=CH / serial: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx / notbefore: xxxxxxxxxxxxxxx 2017 GMT / notafter: xxxxxxxxxxxxxxx 2020 GMT]
[Tue Nov 20 22:07:03.970979 2018] [socache_shmcb:debug] [pid 3115:tid 139645123802880] mod_socache_shmcb.c(495): AH00831: socache_shmcb_store (0xee -> subcache 14)
[Tue Nov 20 22:07:03.971003 2018] [socache_shmcb:debug] [pid 3115:tid 139645123802880] mod_socache_shmcb.c(849): AH00847: insert happened at idx=0, data=(0:32)
[Tue Nov 20 22:07:03.971006 2018] [socache_shmcb:debug] [pid 3115:tid 139645123802880] mod_socache_shmcb.c(854): AH00848: finished insert, subcache: idx_pos/idx_used=0/1, data_pos/data_used=0/1977
[Tue Nov 20 22:07:03.971008 2018] [socache_shmcb:debug] [pid 3115:tid 139645123802880] mod_socache_shmcb.c(516): AH00834: leaving socache_shmcb_store successfully
[Tue Nov 20 22:07:03.971025 2018] [ssl:debug] [pid 3115:tid 139645123802880] ssl_engine_kernel.c(2069): [client 10.0.2.2:55646] AH02041: Protocol: TLSv1.2, Cipher: ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
[Tue Nov 20 22:09:04.005919 2018] [authz_core:debug] [pid 3115:tid 139645123802880] mod_authz_core.c(820): [client 10.0.2.2:55646] AH01626: authorization result of Require valid-user : denied (no authenticated user yet)
[Tue Nov 20 22:09:04.005998 2018] [authz_core:debug] [pid 3115:tid 139645123802880] mod_authz_core.c(820): [client 10.0.2.2:55646] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet)
[Tue Nov 20 22:09:04.006096 2018] [authz_core:debug] [pid 3115:tid 139645123802880] mod_authz_core.c(820): [client 10.0.2.2:55646] AH01626: authorization result of Require valid-user : denied (no authenticated user yet)
[Tue Nov 20 22:09:04.006127 2018] [authz_core:debug] [pid 3115:tid 139645123802880] mod_authz_core.c(820): [client 10.0.2.2:55646] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet)
[Tue Nov 20 22:09:04.006158 2018] [headers:debug] [pid 3115:tid 139645123802880] mod_headers.c(900): AH01503: headers: ap_headers_error_filter()

==> access.log <==
[20/Nov/2018:22:04:50 +0100] 10.0.2.2 - - "GET / HTTP/1.1" 401 5367 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:64.0) Gecko/20100101 Firefox/64.0"

==> error.log <==
[Tue Nov 20 22:09:09.012135 2018] [ssl:debug] [pid 3115:tid 139645115410176] ssl_engine_io.c(1103): [client 10.0.2.2:55646] AH02001: Connection closed to child 9 with standard shutdown (server Apache:443)