On 2015-12-08 11:16, Stefan Sperling wrote:
please try raising HTTPD's LogLevel to "Debug" or higher. See
http://httpd.apache.org/docs/2.4/mod/core.html#loglevel Perhaps that
will shed more light on the problem.
Hi All.
I appreciate the time you guys are taking to help me. Thank you.
Here is the output of the *Apache2 error.log* after setting the level to
*DEBUG* and re-running the test.
*Here is the output from a shell prompt on the Subversion server:*
myself@myserver:~/Folder$ svn checkout
https://myserver/svn/repository/dev/trunk --username myself dev
Passphrase for '/home/myself/Folder/myself.p12': ***************
A dev/code
A dev/code/provider
A dev/code/provider/Investor
A dev/code/provider/Investor/Properties
A dev/code/provider/Plugin
A dev/code/provider/Plugin/Properties
A dev/code/provider/Client
A dev/code/provider/Client/Properties
A dev/code/provider/ClientInstitutional
A dev/code/provider/Client/Price-wrapper.xml
A dev/code/provider/Client/Account.xsd
A dev/code/provider/Client/History-sample.xml
A dev/code/provider/ClientInstitutional/migrate.xml
svn: E175002: Unexpected HTTP status 400 'Bad request' on
'/svn/repository/!svn/rvr/3062/dev/trunk/code/provider/Investor/Investor.cs'
myself@myserver:~/Folder$
*Most of the Apache2 error.log on the server is filled with GET requests
(2,198 of them). Each of the GET requests is made up of 4 lines that
look like this:**
*
[Fri Dec 11 17:40:07.405190 2015] [authz_core:debug] [pid 9390]
mod_authz_core.c(809): [client 127.0.0.1:46222] AH01626: authorization
result of Require valid-user : denied (no authenticated user yet)
[Fri Dec 11 17:40:07.405199 2015] [authz_core:debug] [pid 9390]
mod_authz_core.c(809): [client 127.0.0.1:46222] AH01626: authorization
result of <RequireAny>: denied (no authenticated user yet)
[Fri Dec 11 17:40:07.405490 2015] [authz_svn:debug] [pid 9390]
mod_authz_svn.c(450): [client 127.0.0.1:46222] Path to authz file is
/root/subversion/.apache-auth
[Fri Dec 11 17:40:07.405502 2015] [authz_svn:info] [pid 9390] [client
127.0.0.1:46222] Access granted: 'myself' *GET repository:/dev*
*The first few requests are OPTIONS and PROPFIND, the rest are all GET
requests. Here are the first few (imagine each being made up of the 4
lines above):**
*
... OPTIONS repository:/dev/trunk
... OPTIONS repository:/dev/trunk
... OPTIONS repository:/dev/trunk
... PROPFIND repository:/dev/trunk
... OPTIONS repository:/dev/trunk
... REPORT repository:/dev/trunk
... GET repository:/dev
... GET repository:/
... REPORT repository:
... GET repository:/dev/trunk
... GET repository:/dev/trunk/code
... GET repository:/dev/trunk/code/provider
... GET repository:/dev/trunk/code/provider/Investor
... GET repository:/dev/trunk/code/provider/Investor/Investor.cs
... GET
repository:/dev/trunk/code/provider/Investor/provider.Investor.csproj
... GET repository:/dev/trunk/code/provider/Investor/migrate.xml
... GET repository:/dev/trunk/code/provider/Investor/transform.xml
... GET repository:/dev/trunk/code/provider/Investor/data.cs
... GET repository:/dev/trunk/code/provider/Investor/data.xml
... GET repository:/dev/trunk/code/provider/Investor/Properties
... GET
repository:/dev/trunk/code/provider/Investor/Properties/AssemblyInfo.cs
... (continues on for 2,198 requests)
*
**After removing all the GET requests, here is what remains in the
Apache2 error.log file:**
*
[Fri Dec 11 17:40:02.071015 2015] [ssl:info] [pid 9390] [client
127.0.0.1:46222] AH01964: Connection to child 0 established (server
my.server.org:443)
[Fri Dec 11 17:40:02.071400 2015] [ssl:debug] [pid 9390]
ssl_engine_kernel.c(1940): [client 127.0.0.1:46222] AH02044: No matching
SSL virtual host for servername myserver found (using default/first
virtual host)
[Fri Dec 11 17:40:07.368155 2015] [ssl:debug] [pid 9390]
ssl_engine_kernel.c(1397): [client 127.0.0.1:46222] AH02275: Certificate
Verification, depth 1, CRL checking mode: none [subject:
CN=CertificateAuthority,OU=Development,O=MyCompany,L=MyTown,ST=MyState,C=CA
/ issuer:
CN=CertificateAuthority,OU=Development,O=MyCompany,L=MyTown,ST=MyState,C=CA
/ serial: D8F3B73A249AB90D / notbefore: Dec 7 04:48:38 2011 GMT /
notafter: Dec 4 04:48:38 2021 GMT]
[Fri Dec 11 17:40:07.368283 2015] [ssl:debug] [pid 9390]
ssl_engine_kernel.c(1397): [client 127.0.0.1:46222] AH02275: Certificate
Verification, depth 0, CRL checking mode: none [subject:
CN=myself,OU=Development,O=MyCompany,ST=MyState,C=CA / issuer:
CN=CertificateAuthority,OU=Development,O=MyCompany,L=MyTown,ST=MyState,C=CA
/ serial: 100124 / notbefore: Dec 7 04:53:34 2011 GMT / notafter: Dec
4 04:53:34 2021 GMT]
[Fri Dec 11 17:40:07.368923 2015] [ssl:debug] [pid 9390]
ssl_engine_kernel.c(1860): [client 127.0.0.1:46222] AH02041: Protocol:
TLSv1.2, Cipher: ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
[Fri Dec 11 17:40:07.369230 2015] [ssl:debug] [pid 9390]
ssl_engine_kernel.c(245): [client 127.0.0.1:46222] AH02034: Initial
(No.1) HTTPS request received for child 0 (server my.server.org:443)
[Fri Dec 11 17:40:07.369363 2015] [authz_svn:debug] [pid 9390]
mod_authz_svn.c(450): [client 127.0.0.1:46222] Path to authz file is
/root/subversion/.apache-auth
[Fri Dec 11 17:40:07.369528 2015] [authz_core:debug] [pid 9390]
mod_authz_core.c(809): [client 127.0.0.1:46222] AH01626: authorization
result of Require valid-user : denied (no authenticated user yet)
[Fri Dec 11 17:40:07.369539 2015] [authz_core:debug] [pid 9390]
mod_authz_core.c(809): [client 127.0.0.1:46222] AH01626: authorization
result of <RequireAny>: denied (no authenticated user yet)
[Fri Dec 11 17:40:07.390500 2015] [ssl:debug] [pid 9390]
ssl_engine_kernel.c(245): [client 127.0.0.1:46222] AH02034: Subsequent
(No.2) HTTPS request received for child 0 (server my.server.org:443)
[Fri Dec 11 17:40:07.393411 2015] [deflate:debug] [pid 9390]
mod_deflate.c(853): [client 127.0.0.1:46222] AH01384: Zlib: Compressed
190 to 129 : URL /svn/repository/dev/trunk
[Fri Dec 11 17:40:07.393917 2015] [ssl:debug] [pid 9390]
ssl_engine_kernel.c(245): [client 127.0.0.1:46222] AH02034: Subsequent
(No.3) HTTPS request received for child 0 (server my.server.org:443)
[Fri Dec 11 17:40:07.394409 2015] [deflate:debug] [pid 9390]
mod_deflate.c(853): [client 127.0.0.1:46222] AH01384: Zlib: Compressed
97 to 78 : URL /svn/repository/dev/trunk
[Fri Dec 11 17:40:07.394691 2015] [ssl:debug] [pid 9390]
ssl_engine_kernel.c(245): [client 127.0.0.1:46222] AH02034: Subsequent
(No.4) HTTPS request received for child 0 (server my.server.org:443)
[Fri Dec 11 17:40:07.395170 2015] [deflate:debug] [pid 9390]
mod_deflate.c(853): [client 127.0.0.1:46222] AH01384: Zlib: Compressed
190 to 129 : URL /svn/repository/dev/trunk
[Fri Dec 11 17:40:07.395536 2015] [ssl:debug] [pid 9390]
ssl_engine_kernel.c(245): [client 127.0.0.1:46222] AH02034: Subsequent
(No.5) HTTPS request received for child 0 (server my.server.org:443)
[Fri Dec 11 17:40:07.403352 2015] [ssl:debug] [pid 9390]
ssl_engine_kernel.c(245): [client 127.0.0.1:46222] AH02034: Subsequent
(No.6) HTTPS request received for child 0 (server my.server.org:443)
[Fri Dec 11 17:40:07.404040 2015] [deflate:debug] [pid 9390]
mod_deflate.c(853): [client 127.0.0.1:46222] AH01384: Zlib: Compressed
190 to 129 : URL /svn/repository/dev/trunk
[Fri Dec 11 17:40:07.404672 2015] [ssl:debug] [pid 9390]
ssl_engine_kernel.c(245): [client 127.0.0.1:46222] AH02034: Subsequent
(No.7) HTTPS request received for child 0 (server my.server.org:443)
[Fri Dec 11 17:40:07.405938 2015] [deflate:debug] [pid 9390]
mod_deflate.c(853): [client 127.0.0.1:46222] AH01384: Zlib: Compressed
124 to 103 : URL /svn/repository/!svn/rvr/3066/dev/trunk
[Fri Dec 11 17:40:07.406577 2015] [ssl:debug] [pid 9390]
ssl_engine_kernel.c(245): [client 127.0.0.1:46222] AH02034: Subsequent
(No.8) HTTPS request received for child 0 (server my.server.org:443)
[Fri Dec 11 17:40:07.635617 2015] [ssl:info] [pid 9394] [client
127.0.0.1:46224] AH01964: Connection to child 4 established (server
my.server.org:443)
[Fri Dec 11 17:40:07.635662 2015] [ssl:info] [pid 9393] [client
127.0.0.1:46226] AH01964: Connection to child 3 established (server
my.server.org:443)
[Fri Dec 11 17:40:07.635759 2015] [ssl:info] [pid 9409] [client
127.0.0.1:46228] AH01964: Connection to child 5 established (server
my.server.org:443)
[Fri Dec 11 17:40:07.635926 2015] [ssl:debug] [pid 9394]
ssl_engine_kernel.c(1940): [client 127.0.0.1:46224] AH02044: No matching
SSL virtual host for servername myserver found (using default/first
virtual host)
[Fri Dec 11 17:40:07.635968 2015] [ssl:debug] [pid 9393]
ssl_engine_kernel.c(1940): [client 127.0.0.1:46226] AH02044: No matching
SSL virtual host for servername myserver found (using default/first
virtual host)
[Fri Dec 11 17:40:07.635972 2015] [ssl:debug] [pid 9409]
ssl_engine_kernel.c(1940): [client 127.0.0.1:46228] AH02044: No matching
SSL virtual host for servername myserver found (using default/first
virtual host)
[Fri Dec 11 17:40:07.655133 2015] [ssl:debug] [pid 9394]
ssl_engine_kernel.c(1397): [client 127.0.0.1:46224] AH02275: Certificate
Verification, depth 1, CRL checking mode: none [subject:
CN=CertificateAuthority,OU=Development,O=MyCompany,L=MyTown,ST=MyState,C=CA
/ issuer:
CN=CertificateAuthority,OU=Development,O=MyCompany,L=MyTown,ST=MyState,C=CA
/ serial: D8F3B73A249AB90D / notbefore: Dec 7 04:48:38 2011 GMT /
notafter: Dec 4 04:48:38 2021 GMT]
[Fri Dec 11 17:40:07.655187 2015] [ssl:debug] [pid 9409]
ssl_engine_kernel.c(1397): [client 127.0.0.1:46228] AH02275: Certificate
Verification, depth 1, CRL checking mode: none [subject:
CN=CertificateAuthority,OU=Development,O=MyCompany,L=MyTown,ST=MyState,C=CA
/ issuer:
CN=CertificateAuthority,OU=Development,O=MyCompany,L=MyTown,ST=MyState,C=CA
/ serial: D8F3B73A249AB90D / notbefore: Dec 7 04:48:38 2011 GMT /
notafter: Dec 4 04:48:38 2021 GMT]
[Fri Dec 11 17:40:07.655205 2015] [ssl:debug] [pid 9393]
ssl_engine_kernel.c(1397): [client 127.0.0.1:46226] AH02275: Certificate
Verification, depth 1, CRL checking mode: none [subject:
CN=CertificateAuthority,OU=Development,O=MyCompany,L=MyTown,ST=MyState,C=CA
/ issuer:
CN=CertificateAuthority,OU=Development,O=MyCompany,L=MyTown,ST=MyState,C=CA
/ serial: D8F3B73A249AB90D / notbefore: Dec 7 04:48:38 2011 GMT /
notafter: Dec 4 04:48:38 2021 GMT]
[Fri Dec 11 17:40:07.655219 2015] [ssl:debug] [pid 9394]
ssl_engine_kernel.c(1397): [client 127.0.0.1:46224] AH02275: Certificate
Verification, depth 0, CRL checking mode: none [subject:
CN=myself,OU=Development,O=MyCompany,ST=MyState,C=CA / issuer:
CN=CertificateAuthority,OU=Development,O=MyCompany,L=MyTown,ST=MyState,C=CA
/ serial: 100124 / notbefore: Dec 7 04:53:34 2011 GMT / notafter: Dec
4 04:53:34 2021 GMT]
[Fri Dec 11 17:40:07.655306 2015] [ssl:debug] [pid 9409]
ssl_engine_kernel.c(1397): [client 127.0.0.1:46228] AH02275: Certificate
Verification, depth 0, CRL checking mode: none [subject:
CN=myself,OU=Development,O=MyCompany,ST=MyState,C=CA / issuer:
CN=CertificateAuthority,OU=Development,O=MyCompany,L=MyTown,ST=MyState,C=CA
/ serial: 100124 / notbefore: Dec 7 04:53:34 2011 GMT / notafter: Dec
4 04:53:34 2021 GMT]
[Fri Dec 11 17:40:07.655329 2015] [ssl:debug] [pid 9393]
ssl_engine_kernel.c(1397): [client 127.0.0.1:46226] AH02275: Certificate
Verification, depth 0, CRL checking mode: none [subject:
CN=myself,OU=Development,O=MyCompany,ST=MyState,C=CA / issuer:
CN=CertificateAuthority,OU=Development,O=MyCompany,L=MyTown,ST=MyState,C=CA
/ serial: 100124 / notbefore: Dec 7 04:53:34 2011 GMT / notafter: Dec
4 04:53:34 2021 GMT]
[Fri Dec 11 17:40:07.655807 2015] [ssl:debug] [pid 9394]
ssl_engine_kernel.c(1860): [client 127.0.0.1:46224] AH02041: Protocol:
TLSv1.2, Cipher: ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
[Fri Dec 11 17:40:07.655992 2015] [ssl:debug] [pid 9394]
ssl_engine_kernel.c(245): [client 127.0.0.1:46224] AH02034: Initial
(No.1) HTTPS request received for child 4 (server my.server.org:443)
[Fri Dec 11 17:40:07.656001 2015] [ssl:debug] [pid 9409]
ssl_engine_kernel.c(1860): [client 127.0.0.1:46228] AH02041: Protocol:
TLSv1.2, Cipher: ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
[Fri Dec 11 17:40:07.656095 2015] [ssl:debug] [pid 9393]
ssl_engine_kernel.c(1860): [client 127.0.0.1:46226] AH02041: Protocol:
TLSv1.2, Cipher: ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
[Fri Dec 11 17:40:07.656270 2015] [ssl:debug] [pid 9409]
ssl_engine_kernel.c(245): [client 127.0.0.1:46228] AH02034: Initial
(No.1) HTTPS request received for child 5 (server my.server.org:443)
[Fri Dec 11 17:40:07.657170 2015] [ssl:debug] [pid 9393]
ssl_engine_kernel.c(245): [client 127.0.0.1:46226] AH02034: Initial
(No.1) HTTPS request received for child 3 (server my.server.org:443)
[Fri Dec 11 17:40:07.659118 2015] [deflate:debug] [pid 9394]
mod_deflate.c(853): [client 127.0.0.1:46224] AH01384: Zlib: Compressed
1212 to 451 : URL
/svn/repository/!svn/rvr/1729/dev/trunk/code/provider/Client/Price-wrapper.xml
[Fri Dec 11 17:40:07.659482 2015] [ssl:debug] [pid 9394]
ssl_engine_kernel.c(245): [client 127.0.0.1:46224] AH02034: Subsequent
(No.2) HTTPS request received for child 4 (server my.server.org:443)
[Fri Dec 11 17:40:07.660781 2015] [deflate:debug] [pid 9394]
mod_deflate.c(853): [client 127.0.0.1:46224] AH01384: Zlib: Compressed
3937 to 907 : URL
/svn/repository/!svn/rvr/1710/dev/trunk/code/provider/Client/Account.xsd
[Fri Dec 11 17:40:07.660922 2015] [ssl:debug] [pid 9394]
ssl_engine_kernel.c(245): [client 127.0.0.1:46224] AH02034: Subsequent
(No.3) HTTPS request received for child 4 (server my.server.org:443)
[Fri Dec 11 17:40:07.745767 2015] [deflate:debug] [pid 9394]
mod_deflate.c(853): [client 127.0.0.1:46224] AH01384: Zlib: Compressed
4167011 to 103774 : URL
/svn/repository/!svn/rvr/1710/dev/trunk/code/provider/Client/History-sample.xml
[Fri Dec 11 17:40:07.746614 2015] [ssl:debug] [pid 9394]
ssl_engine_kernel.c(245): [client 127.0.0.1:46224] AH02034: Subsequent
(No.4) HTTPS request received for child 4 (server my.server.org:443)
[Fri Dec 11 17:40:07.748365 2015] [deflate:debug] [pid 9394]
mod_deflate.c(853): [client 127.0.0.1:46224] AH01384: Zlib: Compressed
331 to 202 : URL
/svn/repository/!svn/rvr/3042/dev/trunk/code/provider/ClientInstitutional/migrate.xml
[Fri Dec 11 17:40:08.131029 2015] [ssl:debug] [pid 9409]
ssl_engine_io.c(1007): [client 127.0.0.1:46228] AH02001: Connection
closed to child 5 with standard shutdown (server my.server.org:443)
[Fri Dec 11 17:40:08.147313 2015] [ssl:info] [pid 9394] (70014)End of
file found: [client 127.0.0.1:46224] AH01991: SSL input filter read failed.
[Fri Dec 11 17:40:08.147401 2015] [ssl:debug] [pid 9394]
ssl_engine_io.c(1007): [client 127.0.0.1:46224] AH02001: Connection
closed to child 4 with standard shutdown (server my.server.org:443)
[Fri Dec 11 17:40:08.437594 2015] [ssl:debug] [pid 9393]
ssl_engine_io.c(1007): [client 127.0.0.1:46226] AH02001: Connection
closed to child 3 with standard shutdown (server my.server.org:443)
[Fri Dec 11 17:40:10.974588 2015] [ssl:info] [pid 9390] (32)Broken pipe:
[client 127.0.0.1:46222] AH01993: SSL output filter write failed.
[Fri Dec 11 17:40:10.974735 2015] [dav:error] [pid 9390] [client
127.0.0.1:46222] Provider encountered an error while streaming a REPORT
response. [500, #0]
[Fri Dec 11 17:40:10.974743 2015] [dav:error] [pid 9390] [client
127.0.0.1:46222] A failure occurred while driving the update report
editor [500, #32]
[Fri Dec 11 17:40:10.974747 2015] [dav:error] [pid 9390] [client
127.0.0.1:46222] Broken pipe [500, #32]
[Fri Dec 11 17:40:10.974756 2015] [deflate:debug] [pid 9390]
mod_deflate.c(853): [client 127.0.0.1:46222] AH01384: Zlib: Compressed
1358663 to 138938 : URL /svn/repository/!svn/me
*The log file ends just like that - part way through a message. The rest
of the path never gets added to the error.log file.**
*
Does any of this explain what is going wrong or do I need to debug
Subversion itself?
Thanks.
