Skip to content

Commit

Permalink
Improve logging format
Browse files Browse the repository at this point in the history
- timestamp field now ts in compliant format
- request/response logs now contain an explicit path to enable filtering
- includes request_id field
- uses incoming x-request-id field if present else generates transaction count

Addresses: #12 and part of  epimorphics/hmlr-ansible-deployment#76
  • Loading branch information
der committed Apr 28, 2022
1 parent 78d2ee9 commit ee6cdc6
Show file tree
Hide file tree
Showing 6 changed files with 111 additions and 32 deletions.
6 changes: 3 additions & 3 deletions .github/workflows/publish-deploy.yml
Original file line number Diff line number Diff line change
Expand Up @@ -9,7 +9,7 @@ jobs:
publish:
uses: "epimorphics/github-workflows/.github/workflows/publish.yml@reusable"
secrets:
# Repostory specific
# Repository specific
aws_access_key_id: "${{ secrets.BUILD_HMLR_AWS_ACCESS_KEY_ID }}"
aws_secret_access_key: "${{ secrets.BUILD_HMLR_AWS_SECRET_ACCESS_KEY }}"
# Fixed
Expand All @@ -18,7 +18,7 @@ jobs:
needs: "publish"
uses: "epimorphics/github-workflows/.github/workflows/deploy.yml@reusable"
with:
# Repostory specific
# Repository specific
ansible_repo: epimorphics/hmlr-ansible-deployment
ansible_repo_ref: master
host_prefix: hmlr
Expand All @@ -27,7 +27,7 @@ jobs:
key: "${{ needs.publish.outputs.key }}"
tag: "${{ needs.publish.outputs.tag }}"
secrets:
# Repostory specific
# Repository specific
ansible_vault_password: "${{ secrets.HMLR_ANSIBLE_VAULT_PASSWORD }}"
aws_access_key_id: "${{ secrets.BUILD_HMLR_AWS_ACCESS_KEY_ID }}"
aws_secret_access_key: "${{ secrets.BUILD_HMLR_AWS_SECRET_ACCESS_KEY }}"
Expand Down
24 changes: 6 additions & 18 deletions pom.xml
Original file line number Diff line number Diff line change
Expand Up @@ -17,7 +17,7 @@
<project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
<micrometer.version>1.7.5</micrometer.version>
<logback.version>1.2.6</logback.version>
<logback-json.version>0.1.5</logback-json.version>
<logback-json.version>6.6</logback-json.version>
</properties>

<repositories>
Expand Down Expand Up @@ -118,21 +118,21 @@
<groupId>org.apache.tomcat.embed</groupId>
<artifactId>tomcat-embed-core</artifactId>
<version>7.0.107</version>
<scope>provided</scope>
<!-- <scope>provided</scope>-->
</dependency>

<dependency>
<groupId>org.apache.tomcat.embed</groupId>
<artifactId>tomcat-embed-logging-log4j</artifactId>
<version>7.0.64</version>
<scope>provided</scope>
<!-- <scope>provided</scope>-->
</dependency>

<dependency>
<groupId>org.apache.tomcat.embed</groupId>
<artifactId>tomcat-embed-jasper</artifactId>
<version>7.0.64</version>
<scope>provided</scope>
<!-- <scope>provided</scope>-->
</dependency>

<dependency>
Expand Down Expand Up @@ -175,23 +175,11 @@
</dependency>

<dependency>
<groupId>ch.qos.logback.contrib</groupId>
<artifactId>logback-json-classic</artifactId>
<groupId>net.logstash.logback</groupId>
<artifactId>logstash-logback-encoder</artifactId>
<version>${logback-json.version}</version>
</dependency>

<dependency>
<groupId>ch.qos.logback.contrib</groupId>
<artifactId>logback-jackson</artifactId>
<version>${logback-json.version}</version>
</dependency>

<dependency>
<groupId>com.fasterxml.jackson.core</groupId>
<artifactId>jackson-databind</artifactId>
<version>2.9.10.8</version>
</dependency>

</dependencies>

<build>
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,81 @@
package com.epimorphics.standardReports.webapi;

import java.io.IOException;
import java.util.concurrent.atomic.AtomicLong;

import javax.servlet.Filter;
import javax.servlet.FilterChain;
import javax.servlet.FilterConfig;
import javax.servlet.ServletException;
import javax.servlet.ServletRequest;
import javax.servlet.ServletResponse;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import javax.ws.rs.core.Response.Status;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import com.epimorphics.appbase.webapi.WebApiException;
import com.epimorphics.util.NameUtils;
import org.slf4j.MDC;

/**
* A Filter that can be added to filter chain to log all incoming requests and
* the corresponding response (with response code and execution time). Assigns a
* simple request number to each request and includes that in the response headers
* for diagnosis. Not robust against restarts but easier to work with than UUIDs.
*/
public class LogRequestFilter implements Filter {
public static final String TRANSACTION_ATTRIBUTE = "transaction";
public static final String START_TIME_ATTRIBUTE = "startTime";
public static final String RESPONSE_ID_HEADER = "X-Response-ID";
public static final String REQUEST_ID_HEADER = "X-Request-ID";

static final Logger log = LoggerFactory.getLogger( LogRequestFilter.class );

protected static AtomicLong transactionCount = new AtomicLong(0);

@Override
public void init(FilterConfig filterConfig) throws ServletException {
}

@Override
public void doFilter(ServletRequest request, ServletResponse response,
FilterChain chain) throws IOException, ServletException {
HttpServletRequest httpRequest = (HttpServletRequest)request;
HttpServletResponse httpResponse = (HttpServletResponse)response;
String path = httpRequest.getRequestURI();
String query = httpRequest.getQueryString();
String requestID = httpRequest.getHeader(REQUEST_ID_HEADER);
if (requestID == null || requestID.isEmpty()) {
requestID = Long.toString(transactionCount.incrementAndGet());
}
MDC.put("request_id", requestID);
long start = System.currentTimeMillis();

String fullpath = path + (query == null ? "" : ("?" + query));
MDC.put("path", fullpath);
log.info( String.format("Request [%s] : %s", requestID, fullpath) );
httpResponse.addHeader(RESPONSE_ID_HEADER, requestID);
chain.doFilter(request, response);
log.info( String.format("Response [%s] : %d (%s)", requestID, httpResponse.getStatus(),
NameUtils.formatDuration(System.currentTimeMillis() - start)) );
}

@Override
public void destroy() {
}

public static WebApiException badRequestException(String message) {
log.warn("Bad request: " + message);
return new WebApiException(Status.BAD_REQUEST, message);
}

public static WebApiException serverErrorException(String message) {
log.warn("Server error: " + message);
return new WebApiException(Status.INTERNAL_SERVER_ERROR, message);
}

}

26 changes: 18 additions & 8 deletions src/main/resources/logback.xml
Original file line number Diff line number Diff line change
@@ -1,15 +1,25 @@
<configuration>
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
<layout class="ch.qos.logback.contrib.json.classic.JsonLayout">
<jsonFormatter class="ch.qos.logback.contrib.jackson.JacksonJsonFormatter"/>
<appendLineSeparator>true</appendLineSeparator>
<timestampFormat>yyyy-MM-dd'T'HH:mm:ss.SSSZ</timestampFormat>
</layout>
<appender name="jsonstdout" class="ch.qos.logback.core.ConsoleAppender">
<encoder class="net.logstash.logback.encoder.LogstashEncoder">
<excludeMdcKeyName>X-B3-SpanId</excludeMdcKeyName>
<excludeMdcKeyName>X-B3-TraceId</excludeMdcKeyName>
<excludeMdcKeyName>X-Span-Export</excludeMdcKeyName>
<excludeMdcKeyName>spanExportable</excludeMdcKeyName>
<timeZone>UTC</timeZone>
<fieldNames>
<timestamp>ts</timestamp>
<version>version</version>
</fieldNames>
<throwableConverter class="net.logstash.logback.stacktrace.ShortenedThrowableConverter">
<maxDepthPerThrowable>30</maxDepthPerThrowable>
<maxLength>2048</maxLength>
<shortenedClassNameLength>20</shortenedClassNameLength>
<rootCauseFirst>true</rootCauseFirst>
</throwableConverter>
</encoder>
</appender>

<root level="info">
<appender-ref ref="STDOUT" />
<appender-ref ref="jsonstdout" />
</root>
</configuration>
4 changes: 2 additions & 2 deletions src/main/webapp/WEB-INF/app.conf
Original file line number Diff line number Diff line change
Expand Up @@ -31,8 +31,8 @@ reportManager.workDir = /tmp/sr-workspace

# Data source
ssource = com.epimorphics.appbase.data.impl.RemoteSparqlSource
ssource.endpoint = http://localhost:3030/landregistry_to/query
#ssource.endpoint = http://landregistry.data.gov.uk/landregistry/query
#ssource.endpoint = http://localhost:3030/landregistry_to/query
ssource.endpoint = http://landregistry.data.gov.uk/landregistry/query
ssource.connectTimeout = 10000
ssource.remoteTimeout = 3600000

Expand Down
2 changes: 1 addition & 1 deletion src/main/webapp/WEB-INF/web.xml
Original file line number Diff line number Diff line change
Expand Up @@ -64,7 +64,7 @@ xsi:schemaLocation="http://java.sun.com/xml/ns/javaee http://java.sun.com/xml/ns

<filter>
<filter-name>LogRequestFilter</filter-name>
<filter-class>com.epimorphics.simpleAPI.webapi.LogRequestFilter</filter-class>
<filter-class>com.epimorphics.standardReports.webapi.LogRequestFilter</filter-class>
</filter>

<filter-mapping>
Expand Down

0 comments on commit ee6cdc6

Please sign in to comment.