Logging Developer Guide

Owned by Michael O'Brien
Last updated: Aug 16, 2019 by michael
9 min read

Originally in the logging specification ONAP Application Logging Specification v1.2 (Casablanca) - but will be cross specification releases - so a separate guide.

See additional developer/deployment oriented details on ONAP Development

@Luke Parker has added a logging library and example project that exposes a 3rd party jar in nexus.onap.org at 

https://nexus.onap.org/service/local/repositories/snapshots/content/org/onap/logging-analytics/logging-slf4j/

Do we need to use this library?  good question – you have 4 options (unchanged, do your own code changes/library, use the SLF4J library from Luke (includes MDC/Marker support) or use the AOP (WIP) wrapper on the SLF4J library – it uses aspects to (so-far) add ENTRY/EXIT marker (labelled) logs for each function call in scope.  Using the library is optional – the goal is to reduce the amount of work teams need to do to adhere to the new MDC/Marker specification for Casablanca.

https://nexus.onap.org/service/local/repositories/snapshots/content/org/onap/logging-analytics/logging-library/

    There are developer details on using the libraries (pom.xml edits, spring AOP additions) and how to deploy the logdemo pod alongside onap that demos using the libraries

https://lf-onap.atlassian.net/wiki/pages/viewpage.action?pageId=16278511#ONAPApplicationLoggingSpecificationv1.2(Casablanca)-DeveloperGuide

    The code is ready for use as we finish the library (java is most up to date for now, python is in progress)

https://git.onap.org/logging-analytics/tree/reference

The demo RI stack

oom kubernetes chart

https://git.onap.org/logging-analytics/tree/reference/logging-kubernetes

docker build

https://git.onap.org/logging-analytics/tree/reference/logging-docker-root/logging-docker-demo

war

https://git.onap.org/logging-analytics/tree/reference/logging-demo

aop library

https://git.onap.org/logging-analytics/tree/reference/logging-library

slf4j library

https://git.onap.org/logging-analytics/tree/reference/logging-slf4j

Overall Logging and ELK Architecture

Log Locations and Volumes







Adding Filebeat to an ONAP Kubernetes POD

See commit https://gerrit.onap.org/r/#/c/57171/ for LOG-137: Logging RI: Code OOM kubernetes template/values yamls for RI microservice and filebeat containerClosed for reference

Artifacts

Consumed

Logging Library JAR
Logging Library AOP wrapper JAR
logback.xml
filebeat.yml

Produced

Microservice WAR - using the Logging Library AOP JAR
DockerFile
Helm Charts for Kubernetes





Python: pylog Library

https://lists.onap.org/g/onap-discuss/topic/logging_python_logging/25307286?p=,,,20,0,0,0::recentpostdate%2Fsticky,,,20,2,0,25307286

JAVA: Adding Logging to a WAR Project

Logback.xml

place in src/main/java/resources

based off https://git.onap.org/logging-analytics/tree/reference/logging-slf4j/src/test/resources/logback.xml

But don't use this file yet until it is finished testing and the indexing is modified on the ELK side - https://gerrit.onap.org/r/#/c/57171/

Until then you can continue to use the same logback.xml used by other components that already log like portal/policy/aai/vid/clamp

https://gerrit.onap.org/r/#/c/62405

#20180925 <!-- MDC and MARKER specific for Cassablanca --> <property name="LogTimestamp" value="%d{&quot;yyyy-MM-dd'T'HH:mm:ss.SSSXXX&quot;, UTC}"/> <property name="Level" value="%.-5level"/> <property name="Logger" value="%logger"/> <property name="Mdc" value="%replace(%replace(%mdc){'\t','\\\\t'}){'\n','\\\\n'}"/> <property name="Message" value="%replace(%replace(%msg){'\t','\\\\t'}){'\n','\\\\n'}"/> <property name="RootException" value="%replace(%replace(%rootException){'\t', '\\\\t'}){'\n','\\\\n'}"/> <property name="Marker" value="%replace(%replace(%marker){'\t','\\\\t'}){'\n','\\\\n'}"/> <property name="Thread" value="%thread"/> <!-- indexed --> <!-- for Casablanca we support both position dependent pipe delimited - and position independent KVP MDCs --> <property name="p_1_LogTimestamp" value="${LogTimestamp}" /> <property name="p_2_EntryTimestamp" value="%X{EntryTimestamp}" /> <property name="p_3_InvokeTimestamp" value="%X{InvokeTimestamp}" /> <property name="p_4_RequestID" value="%X{RequestId}" /> <property name="p_5_InvocationID" value="%X{InvocationId}" /> <property name="p_6_InstanceID" value="%X{InstanceUUID}" /> <!-- previously InstanceUUID --> <property name="p_7_ServiceInstanceID" value="%X{ServiceInstanceId}" /> <property name="p_8_thread" value="${Thread}" /> <property name="p_9_ServiceName" value="%X{ServiceName}" /> <property name="p_10_PartnerName" value="%X{PartnerName}" /> <property name="p_11_StatusCode" value="%X{StatusCode}" /> <property name="p_12_ResponseCode" value="%X{ResponseCode}" /> <property name="p_13_ResponseDesc" value="%X{ResponseDesc}" /> <property name="p_14_level" value="${Level}" /> <property name="p_15_Severity" value="%X{Severity}" /> <property name="p_16_ServerIPAddress" value="%X{ServerIPAddress}" /> <property name="p_17_ElapsedTime" value="%X{ElapsedTime}" /> <property name="p_18_ServerFQDN" value="%X{ServerFQDN}" /> <property name="p_19_ClientIPAddress" value="%X{ClientIPAddress}" /> <property name="p_20_VirtualServerName" value="%X{VirtualServerName}" /> <property name="p_21_ContextName" value="%X{ContextName}" /> <property name="p_22_TargetEntity" value="%X{TargetEntity}" /> <property name="p_23_TargetServiceName" value="%X{TargetServiceName}" /> <property name="p_24_TargetElement" value="%X{TargetElement}" /> <property name="p_25_User" value="%X{User}" /> <property name="p_26_logger" value="${Logger}" /> <property name="p_27_mdc" value="${Mdc}" /> <property name="p_28_message" value="${Message}" /> <property name="p_29_marker" value="${Marker}" /> <property name="pattern" value="%nopexception${p_1_LogTimestamp}|${p_2_EntryTimestamp}|${p_3_InvokeTimestamp}|${p_4_RequestID}|${p_5_InvocationID}|${p_6_InstanceID}|${p_7_ServiceInstanceID}|${p_8_thread}|${p_9_ServiceName}|${p_10_PartnerName}|${p_11_StatusCode}|${p_12_ResponseCode}|${p_13_ResponseDesc}|${p_14_level}|${p_15_Severity}|${p_16_ServerIPAddress}|${p_17_ElapsedTime}|${p_18_ServerFQDN}|${p_19_ClientIPAddress}|${p_20_VirtualServerName}|${p_21_ContextName}|${p_22_TargetEntity}|${p_23_TargetServiceName}|${p_24_TargetElement}|${p_25_User}|${p_26_logger}|${p_27_mdc}|${p_28_message}|${p_29_marker}%n" />

spring.xml

<aop:aspectj-autoproxy /> <beans> <bean class="org.onap.demo.logging.LoggingAspect" /> <!-- required even though we annotate with @Aspect --> </beans>

pom.xml

Add the following

<logback.version>1.2.3</logback.version> <dependency> <groupId>ch.qos.logback</groupId> <artifactId>logback-core</artifactId> <version>${logback.version}</version> </dependency> <dependency> <groupId>ch.qos.logback</groupId> <artifactId>logback-classic</artifactId> <version>${logback.version}</version> </dependency> <dependency> <groupId>org.springframework</groupId> <artifactId>spring-aop</artifactId> <version>${spring.version}</version> </dependency> # add the logging library pom (soon to be 1.2.2) <dependency> <groupId>org.onap.logging-analytics</groupId> <artifactId>logging-slf4j</artifactId> <version>1.2.0-SNAPSHOT</version> </dependency>

Logging With AOP

LOG-135: Logging RI: Code example microservice war with a minimal REST API using the logging libraryClosed

Class under Test

Prototyped AOP advice around Luke's library - minimal client changes - just an aspect bean and annotations required



Aspect References

Logging Demo REST API 



Logging Results

Use Case: Single REST call - with ENTRY/EXIT Markers around in-method log

The key here is that you get logs for free - the entry/exit lines are generated - the line in the middle is from java application code





AOP Stacktrace - logBefore()

Deployment

Deploying demo pod

Helm Deployment

also as of 20180918 use @Mike Elliott s plugin - https://gerrit.onap.org/r/#/c/67071/  at OOM Helm (un)Deploy plugins





FAQ / Workarounds

Issue: Logs not appearing in the ELK stack

Check that your volumeMounts are correct in both your application container and filebeat container - for example there must be a /var/log/onap in both



Issue: DNS error pushing logs from filebeat to logstash

Check that your config section in values.yaml either at the helm root or subchart level define the service name and port

ELK Configuration

Logstash

Grok

LOG-490: LOG Pipeline Integrity: Logstash to Elasticsearch - specifically shards/indexesClosed

ElasticSearch

Kibana

Design Issues

DI 8: Log Collection

Currently log collection occurs via the filebeat sidecar container.  There is 1 container per pod that pushes logs from the emptydir PV volume to logstash.

DI 8: LOG-587: Refactoring filebeat to run as a per VM DaemonSet deployment

There is an optimization that can be prototyped where we instead push logs directly from each cluster VM right from the kubelet logs containing the PV's for each container on that VM - via a DaemonSet filebeat container (1 per VM instead of 1 per microservice)

The logstash container was recently changed to a DaemonSet deployment - use this as a chart reference

Example of where logs are put for the emptyDir PV

under the following

LOG-587: Refactor Filebeat per uService sidecar as per VM DaemonSetClosed

Logstash is already a DaemonSet – you can use that as the deployment part of the example (small change) – the larger piece will be to point filebeat to a subset of the emptyDir PV directory or target individual pod PVs on that VM for log shipping.

for example you will need to correlate the PV UUID on the VM with the kubernetes deployment pod id to map the correct pod to it’s emptyDir pv – or just push everything appearing in the kubelet dir.

I am hoping that a switch of the service to a DaemonSet – a one line change and blind pushing of all or a subset (minus the kubernetes/rancher/Grafana pods) of the volumes/kubernetes.io~empty-dir would be sufficient.

https://lists.onap.org/g/onap-discuss/topic/understanding_daemonset_in/24142759?p=,,,20,0,0,0::recentpostdate%2Fsticky,,,20,2,0,24142759