tomcat-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From André Warnier ...@ice-sa.com>
Subject Re: Question on Http11AprProcessor Error parsing HTTP request header error messages
Date Thu, 05 Mar 2015 21:31:44 GMT
Owens, Stephen (ITD) wrote:
> Hi,
> 
> I'm testing Tomcat 8.0.20 on Red Hat Enterprise Linux Server release 6.6.
> Tomcat 8.0.20 was compiled with jdk1.8.0_31, openssl-1.0.2, apr-1.5.1, and apr-util-1.5.4.
> 
> The relevant portions of the server.xml file are:
> <Server port="-1">
>    ...
>   <!--APR library loader. Documentation at /docs/apr.html -->
>   ...
> <Service name="Catalina">
>    <Executor name="tomcatThreadPool" namePrefix="catalina-exec-"  maxThreads="150"
minSpareThreads="4"/>
>    ...
>    <Connector port="50880" protocol="org.apache.coyote.http11.Http11AprProtocol"
>                scheme="http"
>                secure="false"
>                connectionTimeout="3600000"
>                maxHttpHeaderSize="32768"
>                enableLookups="false"
>                redirectPort="50881" />
> ...
>   <Connector port="50881" protocol="org.apache.coyote.http11.Http11AprProtocol"
>                maxThreads="200" scheme="https" secure="true"
>                connectionTimeout="3600000"
>                maxHttpHeaderSize="32768"
>                enableLookups="false"
>                SSLEnabled="true"
>                SSLProtocol="TLSv1.2"
>                SSLCertificateFile="${catalina.home}/keys/xxx"
>                SSLCertificateKeyFile="${catalina.home}/keys/xxx"
>                SSLCipherSuite="TLSv1.2:!aNULL:!eNULL:+RSA:+aDH"
>                SSLVerifyClient="none"
>                SSLHonorCipherOrder="true" />
>        ...
>       <Engine name="Catalina" defaultHost="localhost">
>       ...
>       <Host name="localhost"  appBase="webapps"  unpackWARs="false" autoDeploy="false">
>       ...
>       </Host>
>     </Engine>
>   </Service>
> </Server>
> 
> Tomcat was run under the jsvc daemon process with the below options
> export JAVA_HOME="/app/java"
> export CATALINA_HOME="/app/tomcat"
> export OPENSSL_CONF="${CATALINA_HOME}/etc/ssl/openssl.cnf"
> export CATALINA_BASE="${CATALINA_HOME}"
> export CATALINA_OUT="${CATALINA_BASE}/logs/catalina.out"
> export CATALINA_TMP="${CATALINA_BASE}/temp"
> export CATALINA_ERR="${CATALINA_BASE}/logs/catalina.err"
> export JAVA_OPTS="-Xms1g -Xmx1g -XX:+HeapDumpOnOutOfMemoryError -XX:-UsePerfData -DLog4j.debug=true"
> export CATALINA_PID="${CATALINA_BASE}/logs/tomcat.pid"
> export LOGGING_CONFIG="-DLog4j.debug=true -Dlog4j.configuration=log4j.properties"
> export LOGGING_MANAGER="-Dorg.apache.juli.logging.impl.Log4JLogger"
> TOMCAT_USER="tomcat"
> 
> CLASSPATH=${CATALINA_HOME}/bin/commons-daemon.jar:\
> ${JAVA_HOME}/lib/tools.jar:\
> ${CATALINA_HOME}/bin/bootstrap.jar:\
> ${CATALINA_HOME}/bin/tomcat-juli.jar:\
> ${CATALINA_HOME}/lib/tomcat-juli-adapters.jar:\
> ${CATALINA_HOME}/lib/commons-logging-1.1.3.jar:\
> ${CATALINA_HOME}/lib/commons-logging-adapters-1.1.3.jar:\
> ${CATALINA_HOME}/lib/avalon-framework-4.1.5.jar:\
> ${CATALINA_HOME}/lib/logkit-1.0.1.jar:\
> ${CATALINA_HOME}/lib/log4j-1.2.17.jar:\
> ${CATALINA_HOME}/xsd:\
> ${CATALINA_HOME}/lib
> 
>   ${CATALINA_HOME}/bin/jsvc \
>     -java-home "${JAVA_HOME}" \
>     -jvm ${JVM} \
>     -cwd ${CATALINA_HOME}/bin \
>     -user ${TOMCAT_USER} \
>     -Dcatalina.home=${CATALINA_HOME} \
>     -Dcatalina.base=${CATALINA_BASE} \
>     -Djava.io.tmpdir=${CATALINA_TMP} \
>     ${LOGGING_MANAGER} \
>     ${LOGGING_CONFIG} \
>     -wait ${WAIT_TO_START} \
>     -pidfile ${CATALINA_PID} \
>     -outfile ${CATALINA_OUT} \
>     -errfile ${CATALINA_ERR} \
>     ${JAVA_OPTS} \
>     ${CATALINA_OPTS} \
>     -classpath ${CLASSPATH} \
>     -debug \
>     org.apache.catalina.startup.Bootstrap
> 
> The tomcat webapps directory has only the tomcat default applications
> host-manager
> manager
> ROOT
> 
> The Tomcat server is using Log4j.
> Excerpts from log4j.properties file are below:
> log4j.rootLogger = DEBUG, CATALINA
> 
> # Define all the appenders
> log4j.appender.CATALINA = org.apache.log4j.DailyRollingFileAppender
> log4j.appender.CATALINA.File = ${catalina.base}/logs/catalina.log
> log4j.appender.CATALINA.Append = true
> log4j.appender.CATALINA.Encoding = UTF-8
> # Roll-over the log once per day
> log4j.appender.CATALINA.DatePattern = '.'yyyy-MM-dd'.log'
> log4j.appender.CATALINA.layout = org.apache.log4j.PatternLayout
> log4j.appender.CATALINA.layout.ConversionPattern = %d{ISO8601} [%t] %-5p %c- %m%n
> ...
> # Configure which loggers log to which appenders
> log4j.logger.org.apache.catalina.core.ContainerBase.[Catalina].[localhost] = DEBUG, LOCALHOST
> log4j.logger.org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/manager]
= DEBUG, MANAGER
> log4j.logger.org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/host-manager]
= DEBUG, HOST-MANAGER
> 
> log4j.logger.org.apache.catalina.session=INFO
> log4j.logger.org.apache.catalina.loader=INFO
> log4j.logger.org.apache.catalina.startup=INFO
> log4j.logger.org.apache.catalina.util=INFO
> log4j.logger.org.apache.catalina.connector=INFO
> log4j.logger.org.apache.commons=INFO
> log4j.logger.org.apache.jasper=INFO
> log4j.logger.org.apache.tomcat.util=INFO
> 
> 
> 
> Using chrome Version 41.0.2272.76 m, I connected to the default tomcat web app and in
the logs (the request-dumper filter is setup in web.xml) I see:
> 2015-03-05 13:41:20,412 [http-apr-50881-exec-10] DEBUG org.apache.coyote.http11.Http11AprProtocol-
Socket: [org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper@451eda77:43325392], Status
in: [OPEN_READ], State out: [CLOSED]
> 2015-03-05 13:41:20,560 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8 START TIME        =05-Mar-2015 13:41:20
> 2015-03-05 13:41:20,562 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8         requestURI=/
> 2015-03-05 13:41:20,562 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8           authType=null
> 2015-03-05 13:41:20,562 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8  characterEncoding=null
> 2015-03-05 13:41:20,562 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8      contentLength=-1
> 2015-03-05 13:41:20,562 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8        contentType=null
> 2015-03-05 13:41:20,562 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8        contextPath=
> 2015-03-05 13:41:20,565 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8             cookie=_ga=GA1.3.1837063901.1395922286
> 2015-03-05 13:41:20,569 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8             header=host=xxx:50881
> 2015-03-05 13:41:20,569 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8             header=connection=keep-alive
> 2015-03-05 13:41:20,569 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8             header=accept=text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
> 2015-03-05 13:41:20,569 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8             header=user-agent=Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36
(KHTML, like Gecko) Chrome/41.0.2272.76 Safari/537.36
> 2015-03-05 13:41:20,569 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8             header=accept-encoding=gzip, deflate, sdch
> 2015-03-05 13:41:20,572 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8             header=accept-language=en-US,en;q=0.8
> 2015-03-05 13:41:20,572 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8             header=cookie=_ga=GA1.3.1837063901.1395922286
> 2015-03-05 13:41:20,575 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8             locale=en_US
> 2015-03-05 13:41:20,575 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8             method=GET
> 2015-03-05 13:41:20,576 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8           pathInfo=null
> 2015-03-05 13:41:20,576 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8           protocol=HTTP/1.1
> 2015-03-05 13:41:20,576 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8        queryString=null
> 2015-03-05 13:41:20,580 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8         remoteAddr=xxx
> 2015-03-05 13:41:20,583 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8         remoteHost=xxx
> 2015-03-05 13:41:20,583 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8         remoteUser=null
> 2015-03-05 13:41:20,583 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8 requestedSessionId=null
> 2015-03-05 13:41:20,583 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8             scheme=https
> 2015-03-05 13:41:20,583 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8         serverName=xxx
> 2015-03-05 13:41:20,583 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8         serverPort=50881
> 2015-03-05 13:41:20,583 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8        servletPath=/index.jsp
> 2015-03-05 13:41:20,583 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8           isSecure=true
> 2015-03-05 13:41:20,583 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8 ------------------=--------------------------------------------
> 2015-03-05 13:41:20,768 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8 ------------------=--------------------------------------------
> 2015-03-05 13:41:20,768 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8           authType=null
> 2015-03-05 13:41:20,768 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8        contentType=text/html;charset=UTF-8
> 2015-03-05 13:41:20,769 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8         remoteUser=null
> 2015-03-05 13:41:20,769 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8             status=200
> 2015-03-05 13:41:20,769 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8 END TIME          =05-Mar-2015 13:41:20
> 2015-03-05 13:41:20,769 [http-apr-50881-exec-8] INFO  org.apache.catalina.filters.RequestDumperFilter-
http-apr-50881-exec-8 ===============================================================
> 2015-03-05 13:41:20,781 [http-apr-50881-exec-8] DEBUG org.apache.coyote.http11.Http11AprProtocol-
Socket: [org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper@1ce9af7:41253648], Status
in: [OPEN_READ], State out: [OPEN]
> 2015-03-05 13:41:20,977 [http-apr-50881-exec-6] DEBUG org.apache.coyote.http11.Http11AprProcessor-
Error parsing HTTP request header
> java.io.EOFException: Unexpected EOF read on the socket
>         at org.apache.coyote.http11.InternalAprInputBuffer.parseRequestLine(InternalAprInputBuffer.java:141)
>         at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1000)
>         at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:659)
>         at org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler.process(Http11AprProtocol.java:285)
>         at org.apache.tomcat.util.net.AprEndpoint$SocketWithOptionsProcessor.run(AprEndpoint.java:2376)
>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>         at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
>         at java.lang.Thread.run(Thread.java:745)
> 2015-03-05 13:41:20,977 [http-apr-50881-exec-6] DEBUG org.apache.coyote.http11.Http11AprProtocol-
Socket: [org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper@3ef766eb:37493472], Status
in: [OPEN_READ], State out: [CLOSED]
> 
> Are the DEBUG org.apache.coyote.http11.Http11AprProcessor- Error parsing HTTP request
header signs of a problem or just messages popping up because the log4j level is DEBUG?
> 

If it happened once, the latter.
If it happens all the time, you may want to investigate why the client(s) is/are sending 
incomplete requests.

And thanks for the very complete info.
This being said, it is not usual nor recommended to run with a loglevel DEBUG unless you 
are trying to track down some real issue.

---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org


Mime
View raw message