From 22ccfa1baf256635268a3a65ac59d5a415d19356 Mon Sep 17 00:00:00 2001 From: Thomas Lenz Date: Tue, 19 Sep 2017 14:28:36 +0200 Subject: update TransactionUtis for MDC logging and add unique OA identifier as additional MDC variable --- id/server/data/deploy/conf/moa-id/log4j.properties | 7 ++-- id/server/doc/handbook/install/install.html | 9 +++-- .../moa/id/advancedlogging/TransactionIDUtils.java | 45 +++++++++++++++++++--- .../moa/id/auth/AuthenticationSessionCleaner.java | 14 +++++-- .../moa/id/auth/servlet/AbstractController.java | 7 ++-- .../AbstractProcessEngineSignalController.java | 9 +---- .../UniqueSessionIdentifierInterceptor.java | 6 +-- .../moa/id/data/ExceptionContainer.java | 24 ++++++++++-- .../moa/id/moduls/AuthenticationManager.java | 15 +++++--- .../egovernment/moa/id/moduls/RequestStorage.java | 5 +-- .../moa/id/commons/MOAIDAuthConstants.java | 2 + 11 files changed, 102 insertions(+), 41 deletions(-) diff --git a/id/server/data/deploy/conf/moa-id/log4j.properties b/id/server/data/deploy/conf/moa-id/log4j.properties index d83e8e550..f37100a5b 100644 --- a/id/server/data/deploy/conf/moa-id/log4j.properties +++ b/id/server/data/deploy/conf/moa-id/log4j.properties @@ -19,8 +19,7 @@ log4j.logger.at.gv.egovernment.moa.id.configuration=info,CONFIGTOOL # configure the stdout appender log4j.appender.stdout=org.apache.log4j.ConsoleAppender log4j.appender.stdout.layout=org.apache.log4j.PatternLayout -#log4j.appender.stdout.layout.ConversionPattern=%5p | %d{dd HH:mm:ss,SSS} | %X{transactionId} | %20c | %10t | %m%n -log4j.appender.stdout.layout.ConversionPattern=%5p | %d{dd HH:mm:ss,SSS} | %X{transactionId} |%20.20c | %10t | %m%n +log4j.appender.stdout.layout.ConversionPattern=%5p | %d{dd HH:mm:ss,SSS} | %X{sessionId} | %X{transactionId} | %X{oaId} |%20.20c | %10t | %m%n # configure the rolling file appender (R) log4j.appender.R=org.apache.log4j.RollingFileAppender @@ -28,7 +27,7 @@ log4j.appender.R.File=${catalina.base}/logs/moa-id.log log4j.appender.R.MaxFileSize=10000KB log4j.appender.R.MaxBackupIndex=1 log4j.appender.R.layout=org.apache.log4j.PatternLayout -log4j.appender.R.layout.ConversionPattern=%5p | %d{dd HH:mm:ss,SSS} | %X{transactionId} | %t | %m%n +log4j.appender.R.layout.ConversionPattern=%5p | %d{dd HH:mm:ss,SSS} | %X{sessionId} | %X{transactionId} | %X{oaId} | %t | %m%n # configure the rolling file appender (R) log4j.appender.CONFIGTOOL=org.apache.log4j.RollingFileAppender @@ -36,4 +35,4 @@ log4j.appender.CONFIGTOOL.File=${catalina.base}/logs/moa-id-webgui.log log4j.appender.CONFIGTOOL.MaxFileSize=10000KB log4j.appender.CONFIGTOOL.MaxBackupIndex=1 log4j.appender.CONFIGTOOL.layout=org.apache.log4j.PatternLayout -log4j.appender.CONFIGTOOL.layout.ConversionPattern=%5p | %d{dd HH:mm:ss,SSS} | %X{transactionId} | %t | %m%n \ No newline at end of file +log4j.appender.CONFIGTOOL.layout.ConversionPattern=%5p | %d{dd HH:mm:ss,SSS} | %X{sessionId} | %X{transactionId} | %X{oaId} | %t | %m%n \ No newline at end of file diff --git a/id/server/doc/handbook/install/install.html b/id/server/doc/handbook/install/install.html index aa4114539..db96cda3c 100644 --- a/id/server/doc/handbook/install/install.html +++ b/id/server/doc/handbook/install/install.html @@ -235,8 +235,8 @@ https://<host>:<port>/egiz-configuration-webapp/
2.1.3.1 Format der Log-Meldungen

Anhand einer konkreten Log-Meldung wird das Format der MOA SP/SS Log-Meldungen erläutert: 

-INFO | 01 21:25:26,540 | Thread-3 | TID=1049225059594-100 NID=node1 
-  MSG=Starte neue Transaktion: TID=1049225059594-100, Service=SignatureVerification
+ INFO | 2017-09-18 10:29:22,904 | SID-7947921060553739539 | TID-4708232418268334030 | https://sso.demosp.at/handysignatur 
+      | ajp-nio-28109-exec-7 | No SSO Session cookie found

Der Wert INFO besagt, dass die Log-Meldung im Log-Level INFO entstanden ist. Folgende Log-Levels existieren:

Der nächste Wert 01 21:25:26,540 gibt den Zeitpunkt an, zu dem die Log-Meldung generiert wurde (in diesem Fall den 1. Tag im aktuellen Monat, sowie die genaue Uhrzeit).

-

Der Wert Thread-3 bezeichnet den Thread, von dem die Anfrage bearbeitet wird.

+

Der Wert SID-7947921060553739539 bezeichnet die SessionID, welche diesem Request zugeordnet wurde. Eine SessionID ist innerhalb einer SSO auch über mehrere Authentifizierungsrequests eindeutig. Das Loggen der SessionID kann mittels %X{sessionId} in der log4j Konfiguration gesetzt werden

+

Der Wert TID-4708232418268334030 bezeichnet die TransactionsID, welche diesem Request zugeordnet wurde. Eine TransactionsID ist innerhalb eines Authentifizierungsrequests eindeutig. Das Loggen der TransactionsID kann mittels %X{transactionId} in der log4j Konfiguration gesetzt werden

+

Der Wert https://sso.demosp.at/handysignatur bezeichnet die Online Applikation (eindeutiger Identifier dieses Service Providers) für welchen dieser Authentifizierungsrequest durchgeführt wird. Das Loggen des OA Identifiers kann mittels %X{oaId} in der log4j Konfiguration gesetzt werden

+

Der Wert ajp-nio-28109-exec-7 bezeichnet den Thread, von dem die Anfrage bearbeitet wird.

Der Rest der Zeile einer Log-Meldung ist der eigentliche Text, mit dem das System bestimmte Informationen anzeigt. Im Fehlerfall ist häufig ein Java Stack-Trace angefügt, der eine genauere Ursachen-Forschung ermöglicht.

2.1.3.2 Wichtige Log-Meldungen

Neben den im Abschnitt 2.1.2.4.3 beschriebenen Log-Meldungen, die anzeigen, ob das Service ordnungsgemäß gestartet wurde, geben nachfolgenden Log-Meldungen Aufschluss über die Abarbeitung von Anfragen.

diff --git a/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/advancedlogging/TransactionIDUtils.java b/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/advancedlogging/TransactionIDUtils.java index 6d53fd510..0b066f3b9 100644 --- a/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/advancedlogging/TransactionIDUtils.java +++ b/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/advancedlogging/TransactionIDUtils.java @@ -23,10 +23,8 @@ package at.gv.egovernment.moa.id.advancedlogging; -import java.util.Date; - import at.gv.egovernment.moa.id.commons.MOAIDAuthConstants; -import at.gv.egovernment.moa.util.MiscUtil; +import at.gv.egovernment.moa.id.commons.api.IRequest; /** * @author tlenz @@ -34,6 +32,43 @@ import at.gv.egovernment.moa.util.MiscUtil; */ public class TransactionIDUtils { + /** + * Set all MDC variables from pending request to this threat context
+ * These includes SessionID, TransactionID, and unique service-provider identifier + * + * @param pendingRequest + */ + public static void setAllLoggingVariables(IRequest pendingRequest) { + setTransactionId(pendingRequest.getUniqueTransactionIdentifier()); + setSessionId(pendingRequest.getUniqueSessionIdentifier()); + setServiceProviderId(pendingRequest.getOnlineApplicationConfiguration().getPublicURLPrefix()); + + } + + /** + * Remove all MDC variables from this threat context + * + */ + public static void removeAllLoggingVariables() { + removeSessionId(); + removeTransactionId(); + removeServiceProviderId(); + + } + + + public static void setServiceProviderId(String oaUniqueId) { + org.apache.log4j.MDC.put(MOAIDAuthConstants.MDC_SERVICEPROVIDER_ID, oaUniqueId); + org.slf4j.MDC.put(MOAIDAuthConstants.MDC_SERVICEPROVIDER_ID, oaUniqueId); + + } + + public static void removeServiceProviderId() { + org.apache.log4j.MDC.remove(MOAIDAuthConstants.MDC_SERVICEPROVIDER_ID); + org.slf4j.MDC.remove(MOAIDAuthConstants.MDC_SERVICEPROVIDER_ID); + + } + public static void setTransactionId(String pendingRequestID) { org.apache.log4j.MDC.put(MOAIDAuthConstants.MDC_TRANSACTION_ID, "TID-" + pendingRequestID); @@ -50,9 +85,9 @@ public class TransactionIDUtils { public static void setSessionId(String uniqueSessionId) { org.apache.log4j.MDC.put(MOAIDAuthConstants.MDC_SESSION_ID, - "TID-" + uniqueSessionId); + "SID-" + uniqueSessionId); org.slf4j.MDC.put(MOAIDAuthConstants.MDC_SESSION_ID, - "TID-" + uniqueSessionId); + "SID-" + uniqueSessionId); } diff --git a/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/auth/AuthenticationSessionCleaner.java b/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/auth/AuthenticationSessionCleaner.java index bbb322a4f..34d0d4be1 100644 --- a/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/auth/AuthenticationSessionCleaner.java +++ b/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/auth/AuthenticationSessionCleaner.java @@ -74,20 +74,26 @@ public class AuthenticationSessionCleaner implements Runnable { ExceptionContainer exContainer = (ExceptionContainer) entry; if (exContainer.getExceptionThrown() != null) { - //add session and transaction ID to log if exists + //add session, transaction, and service-provider IDs into logging context if exists if (MiscUtil.isNotEmpty(exContainer.getUniqueTransactionID())) TransactionIDUtils.setTransactionId(exContainer.getUniqueTransactionID()); if (MiscUtil.isNotEmpty(exContainer.getUniqueSessionID())) TransactionIDUtils.setSessionId(exContainer.getUniqueSessionID()); + if (MiscUtil.isNotEmpty(exContainer.getUniqueServiceProviderId())) + TransactionIDUtils.setServiceProviderId(exContainer.getUniqueServiceProviderId()); + //log exception to technical log logExceptionToTechnicalLog(exContainer.getExceptionThrown()); //remove session and transaction ID from thread - TransactionIDUtils.removeSessionId(); - TransactionIDUtils.removeTransactionId(); - } + TransactionIDUtils.removeAllLoggingVariables(); + + } else { + Logger.warn("Receive an ExceptionContainer that includes no 'Exception' object. Somethinge is suspect!!!!!"); + + } } } catch (Exception e) { diff --git a/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/auth/servlet/AbstractController.java b/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/auth/servlet/AbstractController.java index 1431911a3..353261085 100644 --- a/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/auth/servlet/AbstractController.java +++ b/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/auth/servlet/AbstractController.java @@ -33,6 +33,7 @@ import org.springframework.beans.factory.annotation.Autowired; import org.springframework.web.bind.annotation.ExceptionHandler; import com.google.common.net.MediaType; + import at.gv.egovernment.moa.id.advancedlogging.IStatisticLogger; import at.gv.egovernment.moa.id.advancedlogging.MOAIDEventConstants; import at.gv.egovernment.moa.id.advancedlogging.MOAReversionLogger; @@ -139,13 +140,11 @@ public abstract class AbstractController extends MOAIDAuthConstants { if (pendingReq != null) { revisionsLogger.logEvent(pendingReq, MOAIDEventConstants.TRANSACTION_ERROR); transactionStorage.put(key, - new ExceptionContainer(pendingReq.getUniqueSessionIdentifier(), - pendingReq.getUniqueTransactionIdentifier(), loggedException),-1); + new ExceptionContainer(pendingReq, loggedException),-1); } else { transactionStorage.put(key, - new ExceptionContainer(null, - null, loggedException),-1); + new ExceptionContainer(null, loggedException),-1); } diff --git a/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/auth/servlet/AbstractProcessEngineSignalController.java b/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/auth/servlet/AbstractProcessEngineSignalController.java index 0ce7b0050..32f103ca7 100644 --- a/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/auth/servlet/AbstractProcessEngineSignalController.java +++ b/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/auth/servlet/AbstractProcessEngineSignalController.java @@ -45,11 +45,7 @@ public abstract class AbstractProcessEngineSignalController extends AbstractCont //change pending-request ID requestStorage.changePendingRequestID(pendingReq); pendingRequestID = pendingReq.getRequestID(); - - //add transactionID and unique sessionID to Logger - TransactionIDUtils.setSessionId(pendingReq.getUniqueSessionIdentifier()); - TransactionIDUtils.setTransactionId(pendingReq.getUniqueTransactionIdentifier()); - + // process instance is mandatory if (pendingReq.getProcessInstanceId() == null) { throw new MOAIllegalStateException("process.03", new Object[]{"MOA session does not provide process instance id."}); @@ -64,8 +60,7 @@ public abstract class AbstractProcessEngineSignalController extends AbstractCont } finally { //MOASessionDBUtils.closeSession(); - TransactionIDUtils.removeTransactionId(); - TransactionIDUtils.removeSessionId(); + TransactionIDUtils.removeAllLoggingVariables(); } diff --git a/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/auth/servlet/interceptor/UniqueSessionIdentifierInterceptor.java b/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/auth/servlet/interceptor/UniqueSessionIdentifierInterceptor.java index bedc67513..466364adb 100644 --- a/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/auth/servlet/interceptor/UniqueSessionIdentifierInterceptor.java +++ b/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/auth/servlet/interceptor/UniqueSessionIdentifierInterceptor.java @@ -57,8 +57,8 @@ public class UniqueSessionIdentifierInterceptor implements HandlerInterceptor { String uniqueSessionIdentifier = ssomanager.getUniqueSessionIdentifier(ssoId); if (MiscUtil.isEmpty(uniqueSessionIdentifier)) uniqueSessionIdentifier = Random.nextRandom(); - TransactionIDUtils.setSessionId(uniqueSessionIdentifier); + TransactionIDUtils.setSessionId(uniqueSessionIdentifier); request.setAttribute(MOAIDConstants.UNIQUESESSIONIDENTIFIER, uniqueSessionIdentifier); return true; @@ -79,8 +79,8 @@ public class UniqueSessionIdentifierInterceptor implements HandlerInterceptor { @Override public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception { - // TODO Auto-generated method stub - + TransactionIDUtils.removeAllLoggingVariables(); + } } diff --git a/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/data/ExceptionContainer.java b/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/data/ExceptionContainer.java index 1c6fdcb65..4820b6fdc 100644 --- a/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/data/ExceptionContainer.java +++ b/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/data/ExceptionContainer.java @@ -24,6 +24,8 @@ package at.gv.egovernment.moa.id.data; import java.io.Serializable; +import at.gv.egovernment.moa.id.commons.api.IRequest; + /** * @author tlenz * @@ -34,13 +36,21 @@ public class ExceptionContainer implements Serializable { private Throwable exceptionThrown = null; private String uniqueSessionID = null; private String uniqueTransactionID = null; + private String uniqueServiceProviderId = null; /** * */ - public ExceptionContainer(String uniqueSessionID, String uniqueTransactionID, Throwable exception) { - this.uniqueSessionID = uniqueSessionID; - this.uniqueTransactionID = uniqueTransactionID; + public ExceptionContainer(IRequest pendingReq, Throwable exception) { + if (pendingReq != null) { + this.uniqueSessionID = pendingReq.getUniqueSessionIdentifier(); + this.uniqueTransactionID = pendingReq.getUniqueTransactionIdentifier(); + + if (pendingReq.getOnlineApplicationConfiguration() != null) + this.uniqueServiceProviderId = pendingReq.getOnlineApplicationConfiguration().getPublicURLPrefix(); + + } + this.exceptionThrown = exception; } @@ -62,6 +72,14 @@ public class ExceptionContainer implements Serializable { public String getUniqueTransactionID() { return uniqueTransactionID; } + + /** + * @return the uniqueServiceProviderId + */ + public String getUniqueServiceProviderId() { + return uniqueServiceProviderId; + } + diff --git a/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/moduls/AuthenticationManager.java b/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/moduls/AuthenticationManager.java index ab0a1ec40..60b8b31de 100644 --- a/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/moduls/AuthenticationManager.java +++ b/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/moduls/AuthenticationManager.java @@ -47,6 +47,7 @@ import org.springframework.stereotype.Service; import at.gv.egovernment.moa.id.advancedlogging.MOAIDEventConstants; import at.gv.egovernment.moa.id.advancedlogging.MOAReversionLogger; +import at.gv.egovernment.moa.id.advancedlogging.TransactionIDUtils; import at.gv.egovernment.moa.id.auth.data.AuthenticationSession; import at.gv.egovernment.moa.id.auth.data.AuthenticationSessionExtensions; import at.gv.egovernment.moa.id.auth.exception.InvalidProtocolRequestException; @@ -202,6 +203,14 @@ public class AuthenticationManager extends MOAIDAuthConstants { public AuthenticationSession doAuthentication(HttpServletRequest httpReq, HttpServletResponse httpResp, RequestImpl pendingReq) throws MOADatabaseException, ServletException, IOException, MOAIDException { + //load OA configuration from pending request + IOAAuthParameters oaParam = pendingReq.getOnlineApplicationConfiguration(); + + //set logging context and log unique OA identifier to revision log + TransactionIDUtils.setServiceProviderId(pendingReq.getOnlineApplicationConfiguration().getPublicURLPrefix()); + revisionsLogger.logEvent(oaParam, + pendingReq, MOAIDEventConstants.AUTHPROCESS_SERVICEPROVIDER, pendingReq.getOAURL()); + //generic authentication request validation if (pendingReq.isPassiv() && pendingReq.forceAuth()) { @@ -236,12 +245,8 @@ public class AuthenticationManager extends MOAIDAuthConstants { boolean isValidSSOSession = ssoManager.isValidSSOSession(ssoId, pendingReq); // check if Service-Provider allows SSO sessions - IOAAuthParameters oaParam = pendingReq.getOnlineApplicationConfiguration(); boolean useSSOOA = oaParam.useSSO() || oaParam.isInderfederationIDP(); - - revisionsLogger.logEvent(oaParam, - pendingReq, MOAIDEventConstants.AUTHPROCESS_SERVICEPROVIDER, pendingReq.getOAURL()); - + //if a legacy request is used SSO should not be allowed in case of mandate authentication boolean isUseMandateRequested = LegacyHelper.isUseMandateRequested(httpReq); diff --git a/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/moduls/RequestStorage.java b/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/moduls/RequestStorage.java index eec48e0f3..90ccb3c27 100644 --- a/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/moduls/RequestStorage.java +++ b/id/server/idserverlib/src/main/java/at/gv/egovernment/moa/id/moduls/RequestStorage.java @@ -52,9 +52,8 @@ public class RequestStorage implements IRequestStorage{ } //set transactionID and sessionID to Logger - TransactionIDUtils.setTransactionId(pendingRequest.getUniqueTransactionIdentifier()); - TransactionIDUtils.setSessionId(pendingRequest.getUniqueSessionIdentifier()); - + TransactionIDUtils.setAllLoggingVariables(pendingRequest); + return pendingRequest; } catch (MOADatabaseException | NullPointerException e) { diff --git a/id/server/moa-id-commons/src/main/java/at/gv/egovernment/moa/id/commons/MOAIDAuthConstants.java b/id/server/moa-id-commons/src/main/java/at/gv/egovernment/moa/id/commons/MOAIDAuthConstants.java index b16941f51..d8d3dbeee 100644 --- a/id/server/moa-id-commons/src/main/java/at/gv/egovernment/moa/id/commons/MOAIDAuthConstants.java +++ b/id/server/moa-id-commons/src/main/java/at/gv/egovernment/moa/id/commons/MOAIDAuthConstants.java @@ -171,8 +171,10 @@ public class MOAIDAuthConstants extends MOAIDConstants{ public static final String REGEX_PATTERN_TARGET = "^[A-Za-z]{2}(-.*)?$"; + //MDC variables for logging public static final String MDC_TRANSACTION_ID = "transactionId"; public static final String MDC_SESSION_ID = "sessionId"; + public static final String MDC_SERVICEPROVIDER_ID = "oaId"; //AuthnRequest IssueInstant validation public static final int TIME_JITTER = 5; //all 5 minutes time jitter -- cgit v1.2.3