src/main/java/org/onap/aai/babel/logging/LogHelper.java

   1 /**
   2  * ============LICENSE_START=======================================================
   3  * org.onap.aai
   4  * ================================================================================
   5  * Copyright © 2017-2018 AT&T Intellectual Property. All rights reserved.
   6  * Copyright © 2017-2018 European Software Marketing Ltd.
   7  * ================================================================================
   8  * Licensed under the Apache License, Version 2.0 (the "License");
   9  * you may not use this file except in compliance with the License.
  10  * You may obtain a copy of the License at
  11  *
  12  *       http://www.apache.org/licenses/LICENSE-2.0
  13  *
  14  * Unless required by applicable law or agreed to in writing, software
  15  * distributed under the License is distributed on an "AS IS" BASIS,
  16  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  17  * See the License for the specific language governing permissions and
  18  * limitations under the License.
  19  * ============LICENSE_END=========================================================
  20  */
  21 package org.onap.aai.babel.logging;
  22
  23 import static com.att.eelf.configuration.Configuration.MDC_SERVICE_NAME;
  24
  25 import java.io.File;
  26 import java.text.DateFormat;
  27 import java.text.SimpleDateFormat;
  28 import java.util.Date;
  29 import java.util.Optional;
  30 import java.util.function.BiConsumer;
  31 import java.util.function.Consumer;
  32
  33 import javax.servlet.ServletRequest;
  34 import javax.ws.rs.core.HttpHeaders;
  35 import javax.ws.rs.core.Response.Status;
  36
  37 import org.apache.commons.lang3.time.StopWatch;
  38 import org.onap.aai.babel.request.RequestHeaders;
  39 import org.onap.aai.cl.api.LogFields;
  40 import org.onap.aai.cl.api.Logger;
  41 import org.onap.aai.cl.mdc.MdcContext;
  42 import org.onap.aai.cl.mdc.MdcOverride;
  43 import org.onap.aai.restclient.client.Headers;
  44 import org.slf4j.MDC;
  45
  46 import com.att.eelf.configuration.EELFLogger;
  47 import com.att.eelf.configuration.EELFManager;
  48 import com.att.eelf.i18n.EELFResolvableErrorEnum;
  49
  50 import ch.qos.logback.classic.AsyncAppender;
  51 import ch.qos.logback.core.FileAppender;
  52
  53 /*-
  54  * This Log Helper mimics the interface of a Common Logging Logger
  55  * but adds helper methods for audit and metrics logging requirements.
  56  *
  57  * Messages are logged to the appropriate EELF functional logger as described below.
  58  *
  59  * Error Log: INFO/WARN/ERROR/FATAL
  60  * Debug Log: DEBUG/TRACE
  61  * Audit Log: summary view of transaction processing
  62  * Metrics Log: detailed timings of transaction processing interactions
  63  *
  64  * Audit and Metrics log messages record the following fields:
  65  *
  66  * RequestID   - an RFC4122 UUID for the transaction request
  67  * ServiceName - the API provided by this service
  68  * PartnerName - invoker of the API
  69  * ClassName   - name of the class creating the log record
  70  *
  71  * The above list is not exhaustive.
  72  */
  73 public enum LogHelper implements Logger {
  74     INSTANCE; // Joshua Bloch's singleton pattern
  75
  76     @FunctionalInterface
  77     public interface TriConsumer<T, U, V> {
  78         public void accept(T t, U u, V v);
  79     }
  80
  81     /** Audit log message status code values. See {@code MdcParameter.STATUS_CODE} */
  82     public enum StatusCode {
  83         COMPLETE,
  84         ERROR;
  85     }
  86
  87     /**
  88      * Mapped Diagnostic Context parameter names.
  89      *
  90      * <p>
  91      * Note that MdcContext.MDC_START_TIME is used for audit messages, and indicates the start of a transaction.
  92      * Messages in the metrics log record sub-operations of a transaction and thus use different timestamps.
  93      */
  94     public enum MdcParameter {
  95         REQUEST_ID(MdcContext.MDC_REQUEST_ID),
  96         CLASS_NAME("ClassName"),
  97         BEGIN_TIMESTAMP("BeginTimestamp"),
  98         END_TIMESTAMP("EndTimestamp"),
  99         ELAPSED_TIME("ElapsedTime"),
 100         STATUS_CODE("StatusCode"),
 101         RESPONSE_CODE("ResponseCode"),
 102         RESPONSE_DESCRIPTION("ResponseDescription"),
 103         TARGET_ENTITY("TargetEntity"),
 104         TARGET_SERVICE_NAME("TargetServiceName"),
 105         USER("User");
 106
 107         private final String parameterName;
 108
 109         MdcParameter(String parameterName) {
 110             this.parameterName = parameterName;
 111         }
 112
 113         /**
 114          * Get the MDC logging context parameter name as referenced by the logback configuration
 115          *
 116          * @return the MDC parameter name
 117          */
 118         public String value() {
 119             return parameterName;
 120         }
 121     }
 122
 123     /** Our externally advertised service API */
 124     private static final String SERVICE_NAME_VALUE = "AAI-BAS";
 125
 126     private static final EELFLogger errorLogger = EELFManager.getErrorLogger();
 127     private static final EELFLogger debugLogger = EELFManager.getDebugLogger();
 128     private static final EELFLogger auditLogger = EELFManager.getAuditLogger();
 129     private static final EELFLogger metricsLogger = EELFManager.getMetricsLogger();
 130
 131     /** Formatting for timestamps logged as Strings (from the MDC) */
 132     private DateFormat timestampFormat = new SimpleDateFormat("yyyy-MM-dd'T'HH:mm:ss.SSSXXX");
 133
 134     // Records the elapsed time (since the start of servicing a request) for audit logging
 135     private StopWatch auditStopwatch;
 136
 137     /**
 138      * Initialises the MDC (logging context) with default values, to support any logging of messages BEFORE the
 139      * startAudit() method is invoked.
 140      */
 141     private LogHelper() {
 142         setContextValue(MDC_SERVICE_NAME, SERVICE_NAME_VALUE);
 143         // This value is not expected to be used in the default logging configuration
 144         setContextValue(MdcContext.MDC_START_TIME, timestampFormat.format(new Date()));
 145     }
 146
 147     /**
 148      * Begin recording transaction information for a new request. This data is intended for logging purposes. This
 149      * method does not actually write any messages to the log(s).
 150      *
 151      * <p>
 152      * Initialise the MDC logging context for auditing and metrics, using the HTTP request headers. This information
 153      * includes: the correlation ID, local application service name/ID, calling host details and authentication data.
 154      *
 155      * <p>
 156      * The request object is used to find the client details (e.g. IP address)
 157      *
 158      * @param headers raw HTTP headers
 159      * @param servletRequest the request
 160      */
 161     public void startAudit(final HttpHeaders headers, ServletRequest servletRequest) {
 162         auditStopwatch = new StopWatch();
 163         auditStopwatch.start();
 164
 165         Optional<String> requestId = Optional.empty();
 166         String serviceInstanceId = null;
 167         Optional<String> partnerName = Optional.empty();
 168
 169         if (headers != null) {
 170             RequestHeaders requestHeaders = new RequestHeaders(headers);
 171             requestId = Optional.ofNullable(requestHeaders.getCorrelationId());
 172             serviceInstanceId = requestHeaders.getInstanceId();
 173             partnerName = Optional.ofNullable(headers.getHeaderString(Headers.FROM_APP_ID));
 174         }
 175
 176         String clientHost = null;
 177         String clientIPAddress = null;
 178         String user = "<UNKNOWN_USER>";
 179
 180         if (servletRequest != null) {
 181             clientHost = servletRequest.getRemoteHost();
 182             clientIPAddress = servletRequest.getRemoteAddr();
 183
 184             if (!partnerName.isPresent()) {
 185                 partnerName = Optional.ofNullable(clientHost);
 186             }
 187         }
 188
 189         // Populate standard MDC keys - note that the initialize method calls MDC.clear()
 190         MdcContext.initialize(requestId.orElse("missing-request-id"), SERVICE_NAME_VALUE, serviceInstanceId,
 191                 partnerName.orElse("<UNKNOWN_PARTNER>"), clientIPAddress);
 192
 193         setContextValue(MdcParameter.USER, user);
 194         setContextValue(MdcContext.MDC_REMOTE_HOST, clientHost);
 195     }
 196
 197     /**
 198      * Store a value in the current thread's logging context.
 199      *
 200      * @param key non-null parameter name
 201      * @param value the value to store against the key
 202      */
 203     public void setContextValue(String key, String value) {
 204         debug(key + "=" + value);
 205         MDC.put(key, value);
 206     }
 207
 208     /**
 209      * Store a value in the current thread's logging context.
 210      *
 211      * @param param identifier of the context parameter
 212      * @param value the value to store for this parameter
 213      */
 214     public void setContextValue(MdcParameter param, String value) {
 215         setContextValue(param.value(), value);
 216     }
 217
 218     /**
 219      * Set a value in the current thread's logging context, only if this is not already set.
 220      *
 221      * @param key non-null parameter name
 222      * @param value the value to store against the key (only if the current value is null)
 223      */
 224     public void setDefaultContextValue(String key, String value) {
 225         if (MDC.get(key) == null) {
 226             setContextValue(key, value);
 227         }
 228     }
 229
 230     /**
 231      * Set a value in the current thread's logging context, only if this is not already set.
 232      *
 233      * @param param identifier of the context parameter
 234      * @param value the value to store for this parameter (only if the current value is null)
 235      */
 236     public void setDefaultContextValue(MdcParameter param, String value) {
 237         setContextValue(param.value(), value);
 238     }
 239
 240     /** Clear all logging context values. This should be called at start-up only. */
 241     public void clearContext() {
 242         debug("Clearing MDC context");
 243         MDC.clear();
 244     }
 245
 246     /**
 247      * Log an audit message to the audit logger. This method is expected to be called when a response is returned to the
 248      * caller and/or when the processing of the request completes.
 249      *
 250      * @param status status of the service request: COMPLETE/ERROR
 251      * @param responseCode optional application error code
 252      * @param responseDescription human-readable description of the response code
 253      * @param args the argument(s) required to populate the Audit Message log content
 254      */
 255     public void logAudit(StatusCode status, String responseCode, String responseDescription, final String... args) {
 256         if (auditStopwatch == null) {
 257             debug("Unexpected program state: audit stopwatch not started");
 258             auditStopwatch = new StopWatch();
 259             auditStopwatch.start();
 260         }
 261
 262         if (auditLogger.isInfoEnabled()) {
 263             setMdcElapsedTime(auditStopwatch);
 264             setContextValue(MdcParameter.STATUS_CODE, status.toString());
 265             setContextValue(MdcParameter.RESPONSE_CODE, responseCode);
 266             setContextValue(MdcParameter.RESPONSE_DESCRIPTION, responseDescription);
 267             invokeLogger(auditLogger::info, ApplicationMsgs.MESSAGE_AUDIT, args);
 268         }
 269     }
 270
 271     /**
 272      * Log an audit message to the audit logger representing a non-specific processing success message.
 273      *
 274      * @param msg
 275      */
 276     public void logAuditSuccess(String msg) {
 277         Status status = Status.OK;
 278         logAudit(StatusCode.COMPLETE, Integer.toString(status.getStatusCode()), status.getReasonPhrase(), msg);
 279     }
 280
 281     /**
 282      * Log an audit message to the audit logger representing an internal error (e.g. for an exception thrown by the
 283      * implementation). This method is expected to be called when a generic error response is returned to the caller to
 284      * indicate a processing failure.
 285      *
 286      * @param e Exception
 287      */
 288     public void logAuditError(Exception e) {
 289         Status status = Status.INTERNAL_SERVER_ERROR;
 290         logAudit(StatusCode.ERROR, Integer.toString(status.getStatusCode()), status.getReasonPhrase(), e.getMessage());
 291     }
 292
 293     /**
 294      * Log a message to the metrics log.
 295      *
 296      * @param error the log code
 297      * @param args the info messages
 298      */
 299     public void logMetrics(final String... args) {
 300         if (metricsLogger.isInfoEnabled()) {
 301             invokeLogger(metricsLogger::info, ApplicationMsgs.MESSAGE_METRIC, args);
 302         }
 303     }
 304
 305     /**
 306      * @param stopwatch
 307      * @param args
 308      */
 309     public void logMetrics(final StopWatch stopwatch, String... args) {
 310         setMdcElapsedTime(stopwatch);
 311         logMetrics(args);
 312     }
 313
 314     @Override
 315     public String formatMsg(@SuppressWarnings("rawtypes") Enum arg0, String... args) {
 316         throw new UnsupportedOperationException();
 317     }
 318
 319     @Override
 320     public boolean isDebugEnabled() {
 321         return debugLogger != null && debugLogger.isDebugEnabled();
 322     }
 323
 324     @Override
 325     public boolean isErrorEnabled() {
 326         return errorLogger.isErrorEnabled();
 327     }
 328
 329     @Override
 330     public boolean isInfoEnabled() {
 331         return errorLogger.isInfoEnabled();
 332     }
 333
 334     @Override
 335     public boolean isTraceEnabled() {
 336         return debugLogger.isTraceEnabled();
 337     }
 338
 339     @Override
 340     public boolean isWarnEnabled() {
 341         return errorLogger.isWarnEnabled();
 342     }
 343
 344     /**
 345      * Log a DEBUG level message to the debug logger.
 346      *
 347      * @param message the debug message
 348      */
 349     @Override
 350     public void debug(String message) {
 351         if (isDebugEnabled()) {
 352             invokeLogger(debugLogger::debug, message);
 353         }
 354     }
 355
 356     @Override
 357     public void debug(@SuppressWarnings("rawtypes") Enum errorCode, String... args) {
 358         if (isDebugEnabled()) {
 359             invokeErrorCodeLogger(debugLogger::debug, (EELFResolvableErrorEnum) errorCode, args);
 360         }
 361     }
 362
 363     @Override
 364     public void debug(@SuppressWarnings("rawtypes") Enum errorCode, LogFields arg1, String... args) {
 365         throw new UnsupportedOperationException();
 366     }
 367
 368     @Override
 369     public void error(@SuppressWarnings("rawtypes") Enum errorCode, String... args) {
 370         if (isErrorEnabled()) {
 371             invokeErrorCodeLogger(errorLogger::error, (EELFResolvableErrorEnum) errorCode, args);
 372         }
 373     }
 374
 375     @Override
 376     public void error(@SuppressWarnings("rawtypes") Enum errorCode, Throwable t, String... args) {
 377         if (isErrorEnabled()) {
 378             invokeErrorCodeLogger(errorLogger::error, (EELFResolvableErrorEnum) errorCode, t, args);
 379         }
 380     }
 381
 382     @Override
 383     public void error(@SuppressWarnings("rawtypes") Enum errorCode, LogFields arg1, String... args) {
 384         throw new UnsupportedOperationException();
 385     }
 386
 387     @Override
 388     public void error(@SuppressWarnings("rawtypes") Enum errorCode, LogFields arg1, Throwable arg2, String... args) {
 389         throw new UnsupportedOperationException();
 390     }
 391
 392     @Override
 393     public void info(@SuppressWarnings("rawtypes") Enum errorCode, String... args) {
 394         if (isInfoEnabled()) {
 395             invokeErrorCodeLogger(debugLogger::info, (EELFResolvableErrorEnum) errorCode, args);
 396         }
 397     }
 398
 399     @Override
 400     public void info(@SuppressWarnings("rawtypes") Enum arg0, LogFields arg1, String... args) {
 401         throw new UnsupportedOperationException();
 402     }
 403
 404     @Override
 405     public void info(@SuppressWarnings("rawtypes") Enum arg0, LogFields arg1, MdcOverride arg2, String... args) {
 406         throw new UnsupportedOperationException();
 407     }
 408
 409     @Override
 410     public void trace(@SuppressWarnings("rawtypes") Enum errorCode, String... args) {
 411         if (isTraceEnabled()) {
 412             invokeErrorCodeLogger(debugLogger::trace, (EELFResolvableErrorEnum) errorCode, args);
 413         }
 414     }
 415
 416     @Override
 417     public void trace(@SuppressWarnings("rawtypes") Enum arg0, LogFields arg1, String... args) {
 418         throw new UnsupportedOperationException();
 419     }
 420
 421     @Override
 422     public void warn(@SuppressWarnings("rawtypes") Enum errorCode, String... args) {
 423         if (isWarnEnabled()) {
 424             invokeErrorCodeLogger(errorLogger::warn, (EELFResolvableErrorEnum) errorCode, args);
 425         }
 426     }
 427
 428     @Override
 429     public void warn(@SuppressWarnings("rawtypes") Enum arg0, LogFields arg1, String... args) {
 430         throw new UnsupportedOperationException();
 431     }
 432
 433     /**
 434      * Get the method name for a calling method (from the current stack trace)
 435      *
 436      * @param level number of levels for the caller (not including this method)
 437      * @return the class and name of the calling method in the form "class#method"
 438      */
 439     public static String getCallerMethodName(int level) {
 440         StackTraceElement callingMethod = Thread.currentThread().getStackTrace()[level + 2];
 441         return callingMethod.getClassName() + "#" + callingMethod.getMethodName();
 442     }
 443
 444     /**
 445      * Convenience method to be used only for testing purposes.
 446      *
 447      * @return the directory storing the log files
 448      */
 449     public static String getLogDirectory() {
 450         ch.qos.logback.classic.Logger logger =
 451                 (ch.qos.logback.classic.Logger) org.slf4j.LoggerFactory.getLogger("com.att.eelf");
 452         AsyncAppender appender = (AsyncAppender) logger.getAppender("asyncEELF");
 453         FileAppender<?> fileAppender = (FileAppender<?>) appender.getAppender("EELF");
 454         return new File(fileAppender.getFile()).getParent();
 455     }
 456
 457     private void setMdcClassName() {
 458         MDC.put(MdcParameter.CLASS_NAME.value(), getCallerMethodName(3));
 459     }
 460
 461     private void unsetMdcClassName() {
 462         MDC.put(MdcParameter.CLASS_NAME.value(), null);
 463     }
 464
 465     /**
 466      * Set the Begin, End, and Elapsed time values in the MDC context.
 467      *
 468      * @param stopwatch
 469      */
 470     private void setMdcElapsedTime(final StopWatch stopwatch) {
 471         long startTime = stopwatch.getStartTime();
 472         long elapsedTime = stopwatch.getTime();
 473
 474         setContextValue(MdcParameter.BEGIN_TIMESTAMP, timestampFormat.format(startTime));
 475         setContextValue(MdcParameter.END_TIMESTAMP, timestampFormat.format(startTime + elapsedTime));
 476         setContextValue(MdcParameter.ELAPSED_TIME, Long.toString(elapsedTime)); // Milliseconds
 477     }
 478
 479     /**
 480      * @param logMethod the logger method to invoke
 481      * @param message
 482      */
 483     private void invokeLogger(Consumer<String> logMethod, String message) {
 484         setMdcClassName();
 485         logMethod.accept(message);
 486         unsetMdcClassName();
 487     }
 488
 489     /**
 490      * @param logMethod
 491      * @param msg
 492      * @param args
 493      */
 494     private void invokeLogger(BiConsumer<ApplicationMsgs, String[]> logMethod, ApplicationMsgs msg, String[] args) {
 495         setMdcClassName();
 496         logMethod.accept(msg, args);
 497         unsetMdcClassName();
 498     }
 499
 500     /**
 501      * @param logMethod
 502      * @param errorEnum
 503      * @param args
 504      */
 505     private void invokeErrorCodeLogger(BiConsumer<EELFResolvableErrorEnum, String[]> logMethod,
 506             EELFResolvableErrorEnum errorEnum, String[] args) {
 507         setMdcClassName();
 508         logMethod.accept(errorEnum, args);
 509         unsetMdcClassName();
 510     }
 511
 512     /**
 513      * @param logMethod
 514      * @param errorEnum
 515      * @param t a Throwable
 516      * @param args
 517      */
 518     private void invokeErrorCodeLogger(TriConsumer<EELFResolvableErrorEnum, Throwable, String[]> logMethod,
 519             EELFResolvableErrorEnum errorEnum, Throwable t, String[] args) {
 520         setMdcClassName();
 521         logMethod.accept(errorEnum, t, args);
 522         unsetMdcClassName();
 523     }
 524 }