[logback-dev] [JIRA] Created: (LBACCESS-18) NPE is case of desrialized AccessEvent

[Denis Bazhenov (JIRA)]

NPE is case of desrialized AccessEvent
--------------------------------------

                 Key: LBACCESS-18
                 URL: http://jira.qos.ch/browse/LBACCESS-18
             Project: logback-access
          Issue Type: Bug
    Affects Versions: 0.9.26
         Environment: Sun Java HotSpot(TM) 64-Bit Server VM (build 16.2-b04, mixed mode)
CentOS Linux 2.6.18-164.el5 #1 SMP Thu Sep 3 03:28:30 EDT 2009 x86_64 x86_64 x86_64 GNU/Linux
            Reporter: Denis Bazhenov
            Assignee: Logback dev list


I'm trying to use SimpleSocketServer (from logback-access) for remote logging of AccessEvent's. The problem I faced is following. When object get deserialized in SocketNode on line 64 it has no httpRequest (it's simply null). There is debugger dump of event:

event = instance of ch.qos.logback.access.spi.AccessEvent(id=932)
Thread-1[1] dump event
 event = {
    serialVersionUID: 866718993618836343
    NA: "-"
    NA_STRING_ARRAY: instance of java.lang.String[1] (id=914)
    EMPTY: ""
    SENTINEL: -1
    httpRequest: null
    httpResponse: null
    requestURI: "/"
    requestURL: "GET / HTTP/1.1"
    remoteHost: "192.168.20.179"
    remoteUser: null
    remoteAddr: "192.168.20.179"
    protocol: "HTTP/1.1"
    method: "GET"
    serverName: "jetty-test"
    requestContent: ""
    responseContent: ""
    requestHeaderMap: instance of java.util.TreeMap(id=938)
    requestParameterMap: instance of java.util.HashMap(id=939)
    responseHeaderMap: instance of java.util.HashMap(id=940)
    contentLength: 1288
    statusCode: 503
    localPort: 8080
    serverAdapter: null
    timeStamp: 1291621192027
}

So later this gives me NPE in AccessEvent.buildRequestHeaderMap().

I have following logback-access.xml for client

<configuration debug="true">
  <appender name="SOCKET" class="ch.qos.logback.access.net.SocketAppender">
    <remoteHost>logs.vfarm.loc</remoteHost>
    <port>6000</port>
    <reconnectionDelay>100</reconnectionDelay>
    <includeCallerData>true</includeCallerData>
  </appender>

  <appender name="FILE"
    class="ch.qos.logback.core.rolling.RollingFileAppender">
    <File>/var/log/jetty/access.log</File>
    <rollingPolicy
      class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <FileNamePattern>access.%d{yyyy-MM-dd}.log.zip</FileNamePattern>
    </rollingPolicy>

    <layout class="ch.qos.logback.access.PatternLayout">
      <Pattern>combined</Pattern>
    </layout>
  </appender>

  <appender-ref ref="FILE" />
  <appender-ref ref="SOCKET" />
</configuration>

So logs are written locally (sucessfully) and sent over network to logs.vfarm.loc. On logs.vfarm.loc I have running SimpleSocketServer:

java -cp jetty-6.1.24.jar:\
  servlet-api-2.5.jar:\
  logback-access-0.9.26.jar:\
  slf4j-api-1.6.1.jar:\
  logback-core-0.9.26.jar \
  ch.qos.logback.access.net.SimpleSocketServer 6000 access.xml

with following access.xml

<configuration debug="true">
  <!--<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 class="ch.qos.logback.access.PatternLayoutEncoder">
      <Pattern>combined</Pattern>
    </encoder>
  </appender>-->

  <appender name="STDOUT"
    class="ch.qos.logback.core.ConsoleAppender">
    <encoder class="ch.qos.logback.access.PatternLayoutEncoder">
      <Pattern>combined</Pattern>
    </encoder>
  </appender>

  <appender-ref ref="STDOUT" />
  <!--<appender-ref ref="FILE" />-->
</configuration>

I think this issue is closely related to LBACCESS-6, but it's still reproducible. 

-- 
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira