Details
-
Bug
-
Resolution: Unresolved
-
Major
-
None
-
1.1.7, 1.1.8
-
None
Description
Hi,
I have a project where all access logs are sent to ELK. logstash-logback-encoder is used to rename default access fields to custom one like this (Elasticsearch doesn't support '.' in fields):
"@fields.remote_host" => "0:0:0:0:0:0:0:1" -> "remote_host" => "0:0:0:0:0:0:0:1".
To rename default fields under <nestedField> tag I need to extend AccessEventJsonProviders:
package net.logstash.logback.composite.accessevent; public class AccessEventJsonProviders extends JsonProviders<IAccessEvent> { ... public void addNestedField(AccessEventNestedJsonProvider provider) { addProvider(provider); } }
with custom one:
public class CustomAccessEventJsonProviders extends AccessEventJsonProviders { public void addNestedField(CustomAccessEventNestedJsonProvider provider) { addProvider(provider); } }
logback-access.xml example:
<appender name="LOGSTASH" class="net.logstash.logback.appender.LogstashAccessTcpSocketAppender"> <destination>${LOGSTASH_HOST}:${LOGSTASH_PORT}</destination> <encoder class="com.mycompany.CustomEncoder"> <fieldNames class="com.mycompany.CustomFieldNames"> <message>message</message> <fieldsMethod>method</fieldsMethod> <fieldsProtocol>protocol</fieldsProtocol> <fieldsStatusCode>status_code</fieldsStatusCode> <fieldsRequestedUrl>requested_url</fieldsRequestedUrl> <fieldsRequestedUri>requested_uri</fieldsRequestedUri> <fieldsRemoteHost>remote_host</fieldsRemoteHost> <fieldsHostname>hostname</fieldsHostname> <fieldsRemoteUser>remote_user</fieldsRemoteUser> <fieldsContentLength>content_length</fieldsContentLength> <fieldsElapsedTime>elapsed_time</fieldsElapsedTime> <fieldsRequestHeaders>request_headers</fieldsRequestHeaders> <fieldsResponseHeaders>response_headers</fieldsResponseHeaders> </fieldNames> <providers class="com.mycompany.CustomAccessEventJsonProviders"> <timestamp/> <version/> <accessMessage/> <nestedField> <fieldName>access</fieldName> <providers class="com.mycompany.CustomAccessEventJsonProviders"> <remoteHost/> <protocol/> <method/> <requestedUri/> <requestedUrl/> <statusCode/> <contentLength/> </providers> </nestedField> </providers> </encoder> </appender>
Dependencies
compile 'org.springframework.boot:spring-boot-starter:1.4.3.RELEASE' compile 'ch.qos.logback:logback-core:1.1.8' compile 'ch.qos.logback:logback-access:1.1.8' compile 'ch.qos.logback:logback-classic:1.1.8' compile 'net.logstash.logback:logstash-logback-encoder:4.8'
Problem
In logback-core 1.1.7 was introduced ch.qos.logback.core.joran.util.beans.BeanDescriptionFactory which maps propertyName to java method (see ch.qos.logback.core.joran.util.beans.BeanDescriptionFactory#create).
Result of java.lang.Class#getMethods is not ordered and not sorted and in my case first returned method addNestedField will be from parent class AccessEventJsonProviders and stored to propertyNameToAdder map and for the overriden method it will be skipped due to implementation.
With such implementation it breaks current functionality because my class CustomAccessEventJsonProviders is not invoked.
Possible solution
One of possible solution is to map property name with multiple adders/setters/getters to method from the leaf class.
String propertyName = BeanUtil.getPropertyName(method); Method oldAdder = propertyNameToAdder.get(propertyName); if (oldAdder != null) { Class<?> oldAdderClz = oldAdder.getDeclaringClass(); Class<?> currentAdderClz = method.getDeclaringClass(); String message = "Class '%s' contains multiple adders for the same property '%s' but will use from the latest successor '%s'"; if (oldAdderClz.isAssignableFrom(currentAdderClz)) { message = String.format(message, clazz.getCanonicalName(), propertyName, currentAdderClz.getCanonicalName()); propertyNameToAdder.put(propertyName, method); } else { message = String.format(message, clazz.getCanonicalName(), propertyName, oldAdderClz.getCanonicalName()); } addWarn(message); } else { propertyNameToAdder.put(propertyName, method); }
What do you think guys?
Steps to reproduce
1. Download Logstash and unzip it.
2. Run Logstash with such configuration:
./logstash -e "input { tcp { port => 4560 codec => json } } output { stdout { codec => rubydebug } }"
3. Download attached project logback_bug_1243.zip and unzip it.
4. Import it into your favorite IDE and run com.moleksyuk.LogbackBug1243Application.
5. Query rest service by such url: http://localhost:8080/ping (method GET)
Actual result:
{
"access" => {
"@fields.remote_host" => "0:0:0:0:0:0:0:1",
"@fields.protocol" => "HTTP/1.1",
"@fields.method" => "GET",
"@fields.requested_uri" => "/ping",
"@fields.requested_url" => "GET /ping HTTP/1.1",
"@fields.status_code" => 200,
"@fields.content_length" => 2,
"@fields.elapsed_time" => 59
},
"@version" => "1",
"@timestamp" => "2016-12-30T13:28:09.823Z",
"host" => "127.0.0.1",
"port" => 54317
}
Expected result:
{
"access" => {
"remote_host" => "0:0:0:0:0:0:0:1",
"protocol" => "HTTP/1.1",
"method" => "GET",
"requested_uri" => "/ping",
"requested_url" => "GET /ping HTTP/1.1",
"status_code" => 200,
"content_length" => 2,
"elapsed_time" => 64
},
"@version" => "1",
"@timestamp" => "2016-12-30T13:20:58.832Z",
"host" => "127.0.0.1",
"port" => 54076
}
As I mentioned above, this issue was introduced in 1.1.7. To check this just go to build.gradle file and uncomment this section:
configurations.all {
resolutionStrategy.eachDependency { DependencyResolveDetails details ->
if (details.requested.group == 'ch.qos.logback') {
details.useVersion '1.1.6'
}
}
}
This configuration forses gradle to import logback:1.1.6 and you will see expected result.