update TransactionUtis for MDC logging and add unique OA identifier as additional MDC variable

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://&lt;host&gt;:&lt;port&gt;/egiz-configuration-webapp/</pre>
   <h5><a name="webservice_basisinstallation_logging_format" id="webservice_basisinstallation_logging_format"></a>2.1.3.1 Format der Log-Meldungen</h5>
       <p> Anhand einer konkreten Log-Meldung wird das Format der MOA SP/SS Log-Meldungen erl&auml;utert:      </p>
       <pre>
-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
 </pre>
 <p>    Der Wert <code>INFO</code> besagt, dass die Log-Meldung im Log-Level <code>INFO</code> entstanden ist. Folgende Log-Levels existieren:</p>
     <ul>
@@ -257,7 +257,10 @@ INFO | 01 21:25:26,540 | Thread-3 | TID=1049225059594-100 NID=node1
       </li>
     </ul>
     <p>Der n&auml;chste Wert <code>01 21:25:26,540</code> gibt den Zeitpunkt an, zu dem die Log-Meldung generiert wurde (in diesem Fall den 1. Tag im aktuellen Monat, sowie die genaue Uhrzeit). </p>
-    <p>      Der Wert <code>Thread-3</code> bezeichnet den Thread, von dem die Anfrage bearbeitet wird.</p>
+    <p>Der Wert <code>SID-7947921060553739539</code> bezeichnet die SessionID, welche diesem Request zugeordnet wurde. Eine SessionID ist innerhalb einer SSO auch &uuml;ber mehrere Authentifizierungsrequests eindeutig. Das Loggen der SessionID kann mittels <code>%X{sessionId}</code> in der log4j Konfiguration gesetzt werden</p>
+  <p>Der Wert <code>TID-4708232418268334030</code> bezeichnet die TransactionsID, welche diesem Request zugeordnet wurde. Eine TransactionsID ist innerhalb eines Authentifizierungsrequests eindeutig. Das Loggen der TransactionsID kann mittels <code>%X{transactionId}</code> in der log4j Konfiguration gesetzt werden</p>
+    <p>Der Wert <code>https://sso.demosp.at/handysignatur</code> bezeichnet die Online Applikation (eindeutiger Identifier dieses Service Providers) f&uuml;r welchen dieser Authentifizierungsrequest durchgef&uuml;hrt wird. Das Loggen des OA Identifiers kann mittels <code>%X{oaId}</code> in der log4j Konfiguration gesetzt werden</p>
+    <p>Der Wert <code>ajp-nio-28109-exec-7</code> bezeichnet den Thread, von dem die Anfrage bearbeitet wird.</p>
     <p>      Der Rest der Zeile einer Log-Meldung ist der eigentliche Text, mit dem das System bestimmte Informationen anzeigt. Im Fehlerfall ist h&auml;ufig ein Java Stack-Trace angef&uuml;gt, der eine genauere Ursachen-Forschung erm&ouml;glicht.</p>
 <h5>      <a name="webservice_basisinstallation_logging_messages" id="webservice_basisinstallation_logging_messages"></a>2.1.3.2 Wichtige Log-Meldungen</h5>
     <p>      Neben den im Abschnitt <a href="#webservice_basisinstallation_installation_tomcatstartstop_verify">2.1.2.4.3</a> beschriebenen Log-Meldungen, die anzeigen, ob das Service ordnungsgem&auml;&szlig; gestartet wurde, geben nachfolgenden Log-Meldungen Aufschluss &uuml;ber die Abarbeitung von Anfragen. </p>
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<br>
+	 * 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