tomcat-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Owens, Stephen (ITD)" <stephen.ow...@state.ma.us>
Subject Question on Http11AprProcessor Error parsing HTTP request header error messages
Date Thu, 05 Mar 2015 19:59:08 GMT
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?

Thanks,

Stephen R. Owens
Senior Software Engineer
Massachusetts Office of Information Technology
Commonwealth of Massachusetts
One Ashburton Place, Room 1601
Boston, MA 02108
Tel:   617-626-4513
Email: Stephen.Owens@state.ma.us<mailto:Stephen.Owens@state.ma.us>


Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message