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