Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Missing response headers when using LogstashAccessTcpSocketAppender #69

Closed
hntd187 opened this issue Jan 20, 2015 · 12 comments
Closed

Missing response headers when using LogstashAccessTcpSocketAppender #69

hntd187 opened this issue Jan 20, 2015 · 12 comments

Comments

@hntd187
Copy link

hntd187 commented Jan 20, 2015

I've been having this issue, which I can't see to sort out. I've narrowed it down to somewhere in my logback-access.xml, but with no debugging information I have no real idea where to do with this.

<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="true">                                                                                                                                                                                                                  
  <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />
  <appender name="stash" class="net.logstash.logback.appender.LogstashAccessTcpSocketAppender">
    <remoteHost>logstash.coldlight.corp</remoteHost>
    <port>4561</port>
    <encoder class="net.logstash.logback.encoder.LogstashAccessEncoder">
      <fieldNames>
        <fieldsRequestHeaders>@fields.request_headers</fieldsRequestHeaders>
        <fieldsResponseHeaders>@fields.response_headers</fieldsResponseHeaders>
      </fieldNames>
    </encoder>
  </appender>

  <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>access.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>access.%d{yyyy-MM-dd}.log.zip</fileNamePattern>
    </rollingPolicy>
    <encoder>
      <pattern>combined</pattern>
    </encoder>
  </appender>
  <appender-ref ref="stash" />
</configuration>

This is my file, if I comment the part about tcp socket appender the server starts up fine, but other wise it dies miserably

INFO: Starting Servlet Engine: Apache Tomcat/7.0.57
10:24:05,336 |-INFO in ch.qos.logback.access.tomcat.LogbackValve[localhost] - filename property not set. Assuming [/home/scarman/software/tomcat/conf/logback-access.xml]
10:24:05,662 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [net.logstash.logback.appender.LogstashAccessTcpSocketAppender]
10:24:05,690 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [stash]
Jan 20, 2015 10:24:05 AM org.apache.catalina.core.ContainerBase startInternal
SEVERE: A child container failed during start
java.util.concurrent.ExecutionException: org.apache.catalina.LifecycleException: Failed to start component [StandardEngine[Catalina].StandardHost[localhost]]
    at java.util.concurrent.FutureTask.report(FutureTask.java:122)
    at java.util.concurrent.FutureTask.get(FutureTask.java:192)
    at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:1123)
    at org.apache.catalina.core.StandardEngine.startInternal(StandardEngine.java:300)
    at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
    at org.apache.catalina.core.StandardService.startInternal(StandardService.java:443)
    at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
    at org.apache.catalina.core.StandardServer.startInternal(StandardServer.java:739)
    at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
    at org.apache.catalina.startup.Catalina.start(Catalina.java:689)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:321)
    at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:455)
Caused by: org.apache.catalina.LifecycleException: Failed to start component [StandardEngine[Catalina].StandardHost[localhost]]
    at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:154)
    at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1575)
    at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1565)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
Caused by: org.apache.catalina.LifecycleException: Failed to start component [Pipeline[StandardEngine[Catalina].StandardHost[localhost]]]
    at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:154)
    at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:1137)
    at org.apache.catalina.core.StandardHost.startInternal(StandardHost.java:816)
    at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
    ... 6 more
Caused by: org.apache.catalina.LifecycleException: Failed to start component [ch.qos.logback.access.tomcat.LogbackValve[localhost]]
    at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:154)
    at org.apache.catalina.core.StandardPipeline.startInternal(StandardPipeline.java:185)
    at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
    ... 9 more
Caused by: java.lang.NoClassDefFoundError: com/fasterxml/jackson/core/util/ByteArrayBuilder
    at net.logstash.logback.encoder.LogstashAccessEncoder.<init>(LogstashAccessEncoder.java:34)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:408)
    at java.lang.Class.newInstance(Class.java:438)
    at ch.qos.logback.core.joran.action.NestedComplexPropertyIA.begin(NestedComplexPropertyIA.java:122)
    at ch.qos.logback.core.joran.spi.Interpreter.callBeginAction(Interpreter.java:275)
    at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:147)
    at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:129)
    at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:50)
    at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:149)
    at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:135)
    at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:99)
    at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:76)
    at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:68)
    at ch.qos.logback.access.tomcat.LogbackValve.startInternal(LogbackValve.java:138)
    at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
    ... 11 more
Caused by: java.lang.ClassNotFoundException: com.fasterxml.jackson.core.util.ByteArrayBuilder
    at java.net.URLClassLoader$1.run(URLClassLoader.java:372)
    at java.net.URLClassLoader$1.run(URLClassLoader.java:361)
    at java.security.AccessController.doPrivileged(Native Method)
    at java.net.URLClassLoader.findClass(URLClassLoader.java:360)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
    ... 29 more

Jan 20, 2015 10:24:05 AM org.apache.catalina.startup.Catalina start
SEVERE: The required Server component failed to start so Tomcat is unable to start.
org.apache.catalina.LifecycleException: Failed to start component [StandardServer[8005]]
    at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:154)
    at org.apache.catalina.startup.Catalina.start(Catalina.java:689)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:321)
    at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:455)
Caused by: org.apache.catalina.LifecycleException: Failed to start component [StandardService[Catalina]]
    at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:154)
    at org.apache.catalina.core.StandardServer.startInternal(StandardServer.java:739)
    at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
    ... 7 more
Caused by: org.apache.catalina.LifecycleException: Failed to start component [StandardEngine[Catalina]]
    at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:154)
    at org.apache.catalina.core.StandardService.startInternal(StandardService.java:443)
    at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
    ... 9 more
Caused by: org.apache.catalina.LifecycleException: A child container failed during start
    at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:1131)
    at org.apache.catalina.core.StandardEngine.startInternal(StandardEngine.java:300)
    at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
    ... 11 more

Does anyone have any insight into what is causing this?

Also my server.xml if that helps

<?xml version='1.0' encoding='utf-8'?>
<Server port="8005" shutdown="SHUTDOWN">
  <Listener className="org.apache.catalina.startup.VersionLoggerListener" />
  <Listener className="org.apache.catalina.core.AprLifecycleListener" SSLEngine="on" />
  <Listener className="org.apache.catalina.core.JasperListener" />
  <Listener className="org.apache.catalina.core.JreMemoryLeakPreventionListener" />
  <Listener className="org.apache.catalina.mbeans.GlobalResourcesLifecycleListener" />
  <Listener className="org.apache.catalina.core.ThreadLocalLeakPreventionListener" />
  <GlobalNamingResources>
    <Resource name="UserDatabase" auth="Container"
              type="org.apache.catalina.UserDatabase"
              description="User database that can be updated and saved"
              factory="org.apache.catalina.users.MemoryUserDatabaseFactory"
              pathname="conf/tomcat-users.xml" />
  </GlobalNamingResources>
  <Service name="Catalina">
    <Connector port="8080" protocol="HTTP/1.1"
               connectionTimeout="20000"
               redirectPort="8443" />
    <Connector port="8009" protocol="AJP/1.3" redirectPort="8443" />
    <Engine name="Catalina" defaultHost="localhost">
      <Host name="localhost"  appBase="webapps" unpackWARs="true" autoDeploy="true">
        <Valve className="ch.qos.logback.access.tomcat.LogbackValve"/>
      </Host>
    </Engine>
  </Service>
</Server>
@neilprosser
Copy link
Contributor

This line: Caused by: java.lang.NoClassDefFoundError: com/fasterxml/jackson/core/util/ByteArrayBuilder makes me think that perhaps you have clashing versions of Jackson on your classpath.

Could you possibly dump out a list of your dependencies? It might highlight the issue.

@hntd187
Copy link
Author

hntd187 commented Jan 20, 2015

@neilprosser I am not very well java versed, how would I do that?

@neilprosser
Copy link
Contributor

If you use Maven I think you can do mvn dependency:tree. I'm not sure off the top of my head how to generate a dependency tree from Gradle or others.

@hntd187
Copy link
Author

hntd187 commented Jan 20, 2015 

[INFO]                                                                         
[INFO] ------------------------------------------------------------------------
[INFO] Building Logstash Logback Encoder 3.5-SNAPSHOT
[INFO] ------------------------------------------------------------------------
[INFO] 
[INFO] --- maven-dependency-plugin:2.8:tree (default-cli) @ logstash-logback-encoder ---
[INFO] net.logstash.logback:logstash-logback-encoder:jar:3.5-SNAPSHOT
[INFO] +- ch.qos.logback:logback-core:jar:1.1.2:compile
[INFO] +- ch.qos.logback:logback-classic:jar:1.1.2:compile
[INFO] |  \- org.slf4j:slf4j-api:jar:1.7.6:compile
[INFO] +- ch.qos.logback:logback-access:jar:1.1.2:compile
[INFO] +- javax.servlet:servlet-api:jar:2.5:provided
[INFO] +- com.fasterxml.jackson.core:jackson-databind:jar:2.4.0:compile
[INFO] |  +- com.fasterxml.jackson.core:jackson-annotations:jar:2.4.0:compile
[INFO] |  \- com.fasterxml.jackson.core:jackson-core:jar:2.4.0:compile
[INFO] +- commons-io:commons-io:jar:2.4:compile
[INFO] +- commons-lang:commons-lang:jar:2.6:compile
[INFO] +- junit:junit:jar:4.11:test
[INFO] +- org.hamcrest:hamcrest-core:jar:1.3:test
[INFO] +- org.hamcrest:hamcrest-library:jar:1.3:test
[INFO] \- org.mockito:mockito-all:jar:1.9.5:test
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 7.213 s
[INFO] Finished at: 2015-01-20T12:22:21-05:00
[INFO] Final Memory: 15M/236M
[INFO] ------------------------------------------------------------------------

@hntd187
Copy link
Author

hntd187 commented Jan 20, 2015

@neilprosser I added the jackson Jars to the lib directory of tomcat and it works now, but isn't this not supposed to happen?

@hntd187
Copy link
Author

hntd187 commented Jan 20, 2015

Now, is there a way to format these logs? I'd like to add user agent and headers. The examples provided don't work and looking at the code it seems to force the log events to one specific format. Is there anyway to override this?

@neilprosser
Copy link
Contributor

Ah ok. I didn't realise you were building the encoder for yourself and dropping it into Tomcat rather than adding it as a dependency on your project. If you add it as a dependency and package it up with the artifact you deploy to your container it should pull in all the dependencies it needs (currently the JAR file excludes Logback, SLF4J, Jackson and some Commons libraries to avoid clashes).

In terms of headers, I think those examples are based on functionality introduced in the last couple of days and only released on Monday. I'd make sure you're using at least version 3.6 and have another go.

For formatting, if you want a format other than JSON you would need to write your own ch.qos.logback.core.encoder.EncoderBase implementation. You can then switch it using the encoder tag in your configuration.

@hntd187
Copy link
Author

hntd187 commented Jan 21, 2015

@neilprosser Well the request headers come in fine, but the response headers don't seem to be there, maybe because that's not how it works? The outline gives an example for request and response headers, so I'd ideally like to include both or format the access log a bit if possible. Is there anyway? I'm fine with the JSON format, I just wanna include more information.

@neilprosser
Copy link
Contributor

I'm going ping @philsttr into this conversation and see whether he's got any idea why the response headers are missing. From what I can see your configuration matches the documentation.

@philsttr
Copy link
Collaborator

Hi @hntd187,

In my testing, I can see the response headers in the output when I set the fieldsResponseHeaders field name as you have done.

There is even a unit test for this particular case.

It is possible that the logback IAccessEvent does not have the response headers populated before reaching the LogstashAccessTcpSocketAppender. Therefore, the appender has no response headers to log.

You can check for this case by temporarily configuring your RollingFileAppender to use the pattern similar to the following: %h %l %u [%t] "%r" %s %b "%i{Referer}" "%i{User-Agent}" %responseHeader{SomeHeaderThatYouCareAbout} instead of combined. You can then check to see if the response header that you specified is logged. If it is logged, then it should be logged by the LogstashAccessTcpSocketAppender as well. If it is not logged, then the LogstashAccessTcpSocketAppender won't log it either.

@philsttr philsttr changed the title Issue with AccessTcp Socket Appender crashing tomcat Missing response headers when using LogstashAccessTcpSocketAppender Jan 29, 2015
@philsttr
Copy link
Collaborator

Updating the issue title to reflect the current problem.

Also, please ensure that you have the following on the classpath:

  • jackson-databind / jackson-core / jackson-annotations
  • logback-core
  • logback-access (required for logging AccessEvents)
  • slf4j-api

@philsttr
Copy link
Collaborator

Closing. Please open a new issue if you have any problems with v4.3

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@neilprosser @hntd187 @philsttr