https://issues.shibboleth.net/jira/browse/SSPCPP-349
authorScott Cantor <cantor.2@osu.edu>
Sun, 30 Oct 2011 21:36:19 +0000 (21:36 +0000)
committerScott Cantor <cantor.2@osu.edu>
Sun, 30 Oct 2011 21:36:19 +0000 (21:36 +0000)
27 files changed:
adfs/adfs.cpp
configs/shibd.logger.in
schemas/shibboleth-2.0-native-sp-config.xsd
shibsp/Makefile.am
shibsp/SPConfig.cpp
shibsp/SPConfig.h
shibsp/SessionCache.h
shibsp/TransactionLog.h
shibsp/handler/AssertionConsumerService.h
shibsp/handler/LogoutHandler.h
shibsp/handler/SessionInitiator.h
shibsp/handler/impl/AssertionConsumerService.cpp
shibsp/handler/impl/LocalLogoutInitiator.cpp
shibsp/handler/impl/LogoutHandler.cpp
shibsp/handler/impl/SAML1Consumer.cpp
shibsp/handler/impl/SAML2Consumer.cpp
shibsp/handler/impl/SAML2Logout.cpp
shibsp/handler/impl/SAML2LogoutInitiator.cpp
shibsp/handler/impl/SAML2NameIDMgmt.cpp
shibsp/handler/impl/SAML2SessionInitiator.cpp
shibsp/handler/impl/SessionInitiator.cpp
shibsp/handler/impl/Shib1SessionInitiator.cpp
shibsp/impl/StorageServiceSessionCache.cpp
shibsp/impl/TransactionLog.cpp [new file with mode: 0644]
shibsp/impl/XMLServiceProvider.cpp
shibsp/shibsp.vcxproj
shibsp/shibsp.vcxproj.filters

index e14330c..c282eab 100644 (file)
@@ -45,6 +45,7 @@
 #include <shibsp/SessionCache.h>
 #include <shibsp/SPConfig.h>
 #include <shibsp/SPRequest.h>
+#include <shibsp/TransactionLog.h>
 #include <shibsp/handler/AssertionConsumerService.h>
 #include <shibsp/handler/LogoutInitiator.h>
 #include <shibsp/handler/SessionInitiator.h>
@@ -510,6 +511,14 @@ pair<bool,long> ADFSSessionInitiator::doRequest(
 
     preserveRelayState(app, httpResponse, relayState);
 
+    auto_ptr<AuthnRequestEvent> ar_event(newAuthnRequestEvent(app, httpRequest));
+    if (ar_event.get()) {
+        ar_event->m_binding = WSFED_NS;
+        ar_event->m_protocol = WSFED_NS;
+        ar_event->m_peer = entity.first;
+        app.getServiceProvider().getTransactionLog()->write(*ar_event);
+    }
+
     // UTC timestamp
     time_t epoch=time(nullptr);
 #ifndef HAVE_GMTIME_R
@@ -769,7 +778,9 @@ void ADFSConsumer::implementProtocol(
         tokens.insert(tokens.end(), ctx->getResolvedAssertions().begin(), ctx->getResolvedAssertions().end());
     }
 
+    string session_id;
     application.getServiceProvider().getSessionCache()->insert(
+        session_id,
         application,
         httpRequest,
         httpResponse,
@@ -784,6 +795,20 @@ void ADFSConsumer::implementProtocol(
         &tokens,
         ctx.get() ? &ctx->getResolvedAttributes() : nullptr
         );
+
+    auto_ptr<LoginEvent> login_event(newLoginEvent(application, httpRequest));
+    if (login_event.get()) {
+        login_event->m_sessionID = session_id.c_str();
+        login_event->m_peer = entity;
+        login_event->m_protocol = WSFED_NS;
+        login_event->m_binding = WSFED_NS;
+        login_event->m_saml1AuthnStatement = saml1statement;
+        login_event->m_nameID = (saml1name ? nameid.get() : saml2name);
+        login_event->m_saml2AuthnStatement = saml2statement;
+        if (ctx.get())
+            login_event->m_attributes = &ctx->getResolvedAttributes();
+        application.getServiceProvider().getTransactionLog()->write(*login_event);
+    }
 }
 
 #endif
@@ -813,7 +838,6 @@ pair<bool,long> ADFSLogoutInitiator::run(SPRequest& request, bool isHandler) con
         return make_pair(false,0L);
     }
 
-    string entityID(session->getEntityID());
     session->unlock();
 
     if (SPConfig::getConfig().isEnabled(SPConfig::OutOfProcess)) {
@@ -824,6 +848,7 @@ pair<bool,long> ADFSLogoutInitiator::run(SPRequest& request, bool isHandler) con
         // When not out of process, we remote the request.
         session->unlock();
         vector<string> headers(1,"Cookie");
+        headers.push_back("User-Agent");
         DDF out,in = wrap(request,&headers);
         DDFJanitor jin(in), jout(out);
         out=request.getServiceProvider().getListenerService()->send(in);
@@ -872,9 +897,9 @@ void ADFSLogoutInitiator::receive(DDF& in, ostream& out)
             doRequest(*app, *req.get(), *resp.get(), session);
         }
         else {
-             m_log.error("no issuing entityID found in session");
-             session->unlock();
-             app->getServiceProvider().getSessionCache()->remove(*app, *req.get(), resp.get());
+            m_log.error("no issuing entityID found in session");
+            session->unlock();
+            app->getServiceProvider().getSessionCache()->remove(*app, *req.get(), resp.get());
         }
     }
     out << ret;
@@ -890,6 +915,13 @@ pair<bool,long> ADFSLogoutInitiator::doRequest(
     // Do back channel notification.
     vector<string> sessions(1, session->getID());
     if (!notifyBackChannel(application, httpRequest.getRequestURL(), sessions, false)) {
+#ifndef SHIBSP_LITE
+        auto_ptr<LogoutEvent> logout_event(newLogoutEvent(application, &httpRequest, session));
+        if (logout_event.get()) {
+            logout_event->m_logoutType = LogoutEvent::LOGOUT_EVENT_PARTIAL;
+            application.getServiceProvider().getTransactionLog()->write(*logout_event);
+        }
+#endif
         session->unlock();
         application.getServiceProvider().getSessionCache()->remove(application, httpRequest, &httpResponse);
         return sendLogoutPage(application, httpRequest, httpResponse, "partial");
@@ -925,6 +957,13 @@ pair<bool,long> ADFSLogoutInitiator::doRequest(
                 );
         }
 
+        // Log the request.
+        auto_ptr<LogoutEvent> logout_event(newLogoutEvent(application, &httpRequest, session));
+        if (logout_event.get()) {
+            logout_event->m_logoutType = LogoutEvent::LOGOUT_EVENT_UNKNOWN;
+            application.getServiceProvider().getTransactionLog()->write(*logout_event);
+        }
+
         const URLEncoder* urlenc = XMLToolingConfig::getConfig().getURLEncoder();
         const char* returnloc = httpRequest.getParameter("return");
         auto_ptr_char dest(ep->getLocation());
@@ -933,16 +972,23 @@ pair<bool,long> ADFSLogoutInitiator::doRequest(
             req += "&wreply=" + urlenc->encode(returnloc);
         ret.second = httpResponse.sendRedirect(req.c_str());
         ret.first = true;
+
+        if (session) {
+            session->unlock();
+            session = nullptr;
+            application.getServiceProvider().getSessionCache()->remove(application, httpRequest, &httpResponse);
+        }
+    }
+    catch (MetadataException& mex) {
+        // Less noise for IdPs that don't support logout
+        m_log.info("unable to issue ADFS logout request: %s", mex.what());
     }
     catch (exception& ex) {
         m_log.error("error issuing ADFS logout request: %s", ex.what());
     }
 
-    if (session) {
+    if (session)
         session->unlock();
-        session = nullptr;
-        application.getServiceProvider().getSessionCache()->remove(application, httpRequest, &httpResponse);
-    }
 
     return ret;
 #else
index d2e8473..7c6e32e 100644 (file)
@@ -33,6 +33,10 @@ log4j.additivity.XMLTooling.Signature.Debugger=false
 # Level should be left at INFO for this category
 log4j.category.Shibboleth-TRANSACTION=INFO, tran_log
 log4j.additivity.Shibboleth-TRANSACTION=false
+# uncomment to suppress particular event types
+#log4j.category.Shibboleth-TRANSACTION.AuthnRequest=WARN
+#log4j.category.Shibboleth-TRANSACTION.Login=WARN
+#log4j.category.Shibboleth-TRANSACTION.Logout=WARN
 
 # define the appenders
 
index f77966b..f48b748 100644 (file)
       <any namespace="##other" processContents="lax" minOccurs="0" maxOccurs="unbounded"/>
     </sequence>
     <attribute name="logger" type="anyURI"/>
+    <attribute name="tranLogFormat" type="conf:string"/>
+    <attribute name="tranLogFiller" type="conf:string"/>
     <attribute name="catchAll" type="boolean"/>
     <anyAttribute namespace="##other" processContents="lax"/>
   </complexType>
index e87a7e8..0170384 100644 (file)
@@ -214,6 +214,7 @@ libshibsp_la_SOURCES = \
        attribute/resolver/impl/XMLAttributeExtractor.cpp \
        binding/impl/ArtifactResolver.cpp \
        binding/impl/SOAPClient.cpp \
+       impl/TransactionLog.cpp \
        impl/XMLSecurityPolicyProvider.cpp \
        metadata/DynamicMetadataProvider.cpp \
        metadata/MetadataExtImpl.cpp \
index 12c7a20..189ea3c 100644 (file)
@@ -45,7 +45,6 @@
 #include "ServiceProvider.h"
 #include "SessionCache.h"
 #include "SPConfig.h"
-#include "TransactionLog.h"
 #include "attribute/Attribute.h"
 #include "binding/ProtocolProvider.h"
 #include "handler/LogoutInitiator.h"
@@ -299,6 +298,9 @@ bool SPConfig::init(const char* catalog_path, const char* inst_prefix)
         registerAttributeFilters();
         registerMatchFunctors();
     }
+    if (isEnabled(Logging)) {
+        registerEvents();
+    }
     registerSecurityPolicyProviders();
 #endif
 
@@ -352,6 +354,9 @@ void SPConfig::term()
 
 #ifndef SHIBSP_LITE
     SecurityPolicyProviderManager.deregisterFactories();
+    if (isEnabled(Logging)) {
+        EventManager.deregisterFactories();
+    }
     if (isEnabled(AttributeResolution)) {
         MatchFunctorManager.deregisterFactories();
         AttributeFilterManager.deregisterFactories();
@@ -488,24 +493,3 @@ void SPInternalConfig::term()
 
     SPConfig::term();
 }
-
-
-TransactionLog::TransactionLog() : log(logging::Category::getInstance(SHIBSP_TX_LOGCAT)), m_lock(Mutex::create())
-{
-}
-
-TransactionLog::~TransactionLog()
-{
-    delete m_lock;
-}
-
-Lockable* TransactionLog::lock()
-{
-    m_lock->lock();
-    return this;
-}
-
-void TransactionLog::unlock()
-{
-    m_lock->unlock();
-}
index f7119f5..2c80561 100644 (file)
@@ -31,6 +31,7 @@
 
 #include <string>
 #ifndef SHIBSP_LITE
+# include <shibsp/TransactionLog.h>
 # include <saml/binding/MessageDecoder.h>
 # include <saml/binding/MessageEncoder.h>
 #endif
@@ -223,6 +224,11 @@ namespace shibsp {
         xmltooling::PluginManager<AttributeResolver,std::string,const xercesc::DOMElement*> AttributeResolverManager;
 
         /**
+         * Manages factories for Event plugins.
+         */
+        xmltooling::PluginManager<TransactionLog::Event,std::string,void*> EventManager;
+
+        /**
          * Manages factories for MatchFunctor plugins.
          */
         xmltooling::PluginManager< MatchFunctor,xmltooling::QName,std::pair<const FilterPolicyContext*,const xercesc::DOMElement*> > MatchFunctorManager;
index b00d427..5ac74d3 100644 (file)
@@ -228,6 +228,7 @@ namespace shibsp {
 
 #ifndef SHIBSP_LITE
         /**
+         * @deprecated
          * Inserts a new session into the cache and binds the session to the outgoing
          * client response.
          *
@@ -264,6 +265,46 @@ namespace shibsp {
             )=0;
 
         /**
+         * Inserts a new session into the cache and binds the session to the outgoing
+         * client response.
+         *
+         * <p>The newly created session ID is placed into the first parameter.
+         *
+         * <p>The SSO tokens and Attributes remain owned by the caller and are copied by the cache.
+         *
+         * @param sessionID         reference to string to capture newly inserted session ID
+         * @param application       reference to Application that owns the Session
+         * @param httpRequest       request that initiated session
+         * @param httpResponse      current response to client
+         * @param expires           expiration time of session
+         * @param issuer            issuing metadata of assertion issuer, if known
+         * @param protocol          protocol family used to initiate the session
+         * @param nameid            principal identifier, normalized to SAML 2, if any
+         * @param authn_instant     UTC timestamp of authentication at IdP, if known
+         * @param session_index     index of session between principal and IdP, if any
+         * @param authncontext_class    method/category of authentication event, if known
+         * @param authncontext_decl specifics of authentication event, if known
+         * @param tokens            assertions to cache with session, if any
+         * @param attributes        optional array of resolved Attributes to cache with session
+         */
+        virtual void insert(
+            std::string& sessionID,
+            const Application& application,
+            const xmltooling::HTTPRequest& httpRequest,
+            xmltooling::HTTPResponse& httpResponse,
+            time_t expires,
+            const opensaml::saml2md::EntityDescriptor* issuer=nullptr,
+            const XMLCh* protocol=nullptr,
+            const opensaml::saml2::NameID* nameid=nullptr,
+            const XMLCh* authn_instant=nullptr,
+            const XMLCh* session_index=nullptr,
+            const XMLCh* authncontext_class=nullptr,
+            const XMLCh* authncontext_decl=nullptr,
+            const std::vector<const opensaml::Assertion*>* tokens=nullptr,
+            const std::vector<Attribute*>* attributes=nullptr
+            );
+
+        /**
          * Determines whether the Session bound to a client request matches a set of input criteria.
          *
          * @param application   reference to Application that owns the Session
index 0fc1bf5..a168b68 100644 (file)
 /**
  * @file shibsp/TransactionLog.h
  * 
- * Interface to a synchronized logging object.
+ * Formatted event record logging.
  */
 
-#ifndef __shibsp_txlog_h__
+#if !defined (__shibsp_txlog_h__) && !defined(SHIBSP_LITE)
 #define __shibsp_txlog_h__
 
 #include <shibsp/base.h>
 #include <xmltooling/logging.h>
 #include <xmltooling/Lockable.h>
+#include <xmltooling/io/GenericRequest.h>
+
+#include <map>
+#include <vector>
+#include <iostream>
 
 namespace xmltooling {
     class XMLTOOL_API Mutex;
 };
 
+namespace opensaml {
+    namespace saml1 {
+        class SAML_API AuthenticationStatement;
+    };
+
+    namespace saml1p {
+        class SAML_API Response;
+    };
+
+    namespace saml2 {
+        class SAML_API AuthnStatement;
+        class SAML_API NameID;
+    };
+
+    namespace saml2p {
+        class SAML_API AuthnRequest;
+        class SAML_API LogoutRequest;
+        class SAML_API LogoutResponse;
+        class SAML_API StatusResponseType;
+    };
+
+    namespace saml2md {
+        class SAML_API EntityDescriptor;
+    };
+};
+
 namespace shibsp {
+    class SHIBSP_API Application;
+    class SHIBSP_API Attribute;
+    class SHIBSP_API Session;
+
     /**
-     * Interface to a synchronized logging object.
+     * Interface to a synchronized event/audit logging object.
      * 
-     * <p>This is platform/logging specific, but we can at least hide the details here.
+     * <p>For backward compatibility, we expose a logging object directly, but
+     * new applications should rely on the Event callback API.
      */
     class SHIBSP_API TransactionLog : public virtual xmltooling::Lockable
     {
         MAKE_NONCOPYABLE(TransactionLog);
     public:
-        TransactionLog();
+        /**
+         * Constructor.
+         *
+         * @param fmt       formatting string for events
+         * @param absent    string to output when a field is empty
+         */
+        TransactionLog(const char* fmt=nullptr, const char* absent=nullptr);
 
         virtual ~TransactionLog();
         
         xmltooling::Lockable* lock();
-
         void unlock();
 
-        /** Logging object. */
+        /** @deprecated Logging object. */
         xmltooling::logging::Category& log;
 
+        /**
+         * Callback interface that outputs an event record to a stream using formatting tokens.
+         */
+        class SHIBSP_API Event {
+            MAKE_NONCOPYABLE(Event);
+        protected:
+            /** Function that handles a formatting token. */
+            typedef bool (*handler_fn)(const Event& e, std::ostream&);
+
+            /** Map of tokens to handlers. */
+            std::map<std::string, handler_fn> m_handlers;
+
+            /**
+             * Constructor.
+             */
+            Event();
+
+        public:
+            virtual ~Event();
+
+            /**
+             * Returns a type string to be used for the log category in the event log.
+             *
+             * @return  type or category for the event
+             */
+            virtual const char* getType() const=0;
+
+            /** Exception */
+            const std::exception* m_exception;
+
+            /** Request object associated with event. */
+            const xmltooling::GenericRequest* m_request;
+
+            /** Application object associated with event. */
+            const Application* m_app;
+
+            /** Session identifier. */
+            const char* m_sessionID;
+
+            /** Peer entity associated with event. */
+            const opensaml::saml2md::EntityDescriptor* m_peer;
+
+            /** Protocol associated with event. */
+            const char* m_protocol;
+
+            /** Protocol binding associated with event. */
+            const char* m_binding;
+
+            /** SAML 2.0 NameID. */
+            const opensaml::saml2::NameID* m_nameID;
+
+            /**
+             * Outputs an event record to a stream based on the defined formatting string.
+             *
+             * @param out       stream to use
+             * @param field     field to output
+             * @param absent    string to output if the field is empty
+             * @return  true iff the field was recognized and substituted
+             */
+            virtual bool write(std::ostream& out, const char* field, const char* absent) const;
+        };
+
+        /**
+         * Write a formatted event record to the log.
+         * <p>This method is internally synchronized and the caller does <strong>NOT</strong>
+         * need to explicitly lock and unlock the object.
+         *
+         * @param e event to log
+         */
+        virtual void write(const Event& e);
+
     private:
         xmltooling::Mutex* m_lock;
+        std::string m_absent;
+        std::vector<std::string> m_formatting;
+    };
+
+    class SHIBSP_API LoginEvent : public TransactionLog::Event
+    {
+    public:
+        /**
+         * Constructor.
+         */
+        LoginEvent();
+
+        virtual ~LoginEvent();
+
+        const char* getType() const;
+
+        /** SAML 2.0 AuthnStatement. */
+        const opensaml::saml2::AuthnStatement* m_saml2AuthnStatement;
+
+        /** SAML 2.0 Response. */
+        const opensaml::saml2p::StatusResponseType* m_saml2Response;
+
+        /** SAML 1.x AuthnStatement. */
+        const opensaml::saml1::AuthenticationStatement* m_saml1AuthnStatement;
+
+        /** SAML 1.x Response. */
+        const opensaml::saml1p::Response* m_saml1Response;
+
+        /** Attributes associated with event. */
+        const std::vector<Attribute*>* m_attributes;
+    };
+
+    class SHIBSP_API LogoutEvent : public TransactionLog::Event
+    {
+    public:
+        /**
+         * Constructor.
+         */
+        LogoutEvent();
+
+        virtual ~LogoutEvent();
+
+        const char* getType() const;
+
+        /** Result of logout (local, global, partial). */
+        enum logout_type_t {
+            LOGOUT_EVENT_UNKNOWN,
+            LOGOUT_EVENT_INVALID,
+            LOGOUT_EVENT_LOCAL,
+            LOGOUT_EVENT_GLOBAL,
+            LOGOUT_EVENT_PARTIAL
+        } m_logoutType;
+
+        /** SAML 2.0 Request. */
+        const opensaml::saml2p::LogoutRequest* m_saml2Request;
+
+        /** SAML 2.0 Response. */
+        const opensaml::saml2p::LogoutResponse* m_saml2Response;
+
+        /** Primary session associated with event. */
+        const Session* m_session;
+
+        /** All sessions associated with event. */
+        std::vector<std::string> m_sessions;
+    };
+
+    class SHIBSP_API AuthnRequestEvent : public TransactionLog::Event
+    {
+    public:
+        /**
+         * Constructor.
+         */
+        AuthnRequestEvent();
+
+        virtual ~AuthnRequestEvent();
+
+        const char* getType() const;
+
+        /** SAML 2.0 Request. */
+        const opensaml::saml2p::AuthnRequest* m_saml2Request;
     };
+
+    /**
+     * Registers Event classes into the runtime.
+     */
+    void SHIBSP_API registerEvents();
+
+    /** Login event. */
+    #define LOGIN_EVENT         "Login"
+
+    /** Logout event. */
+    #define LOGOUT_EVENT        "Logout"
+
+    /** AuthnRequest event. */
+    #define AUTHNREQUEST_EVENT  "AuthnRequest"
 };
 
 #endif /* __shibsp_txlog_h__ */
index 3d452b9..579149f 100644 (file)
@@ -51,6 +51,7 @@ namespace opensaml {
 namespace shibsp {
 
     class SHIBSP_API Attribute;
+    class SHIBSP_API LoginEvent;
     class SHIBSP_API ResolutionContext;
 
 #if defined (_MSC_VER)
@@ -180,7 +181,6 @@ namespace shibsp {
             ) const;
 
         /**
-         * @deprecated
          * Attempt SSO-initiated attribute resolution using the supplied information,
          * including NameID and token extraction and filtering followed by
          * secondary resolution.
@@ -191,7 +191,9 @@ namespace shibsp {
          * @param issuer                source of SSO tokens
          * @param protocol              SSO protocol used
          * @param v1nameid              identifier of principal in SAML 1.x form, if any
+         * @param v1statement           SAML 1.x authentication statement, if any
          * @param nameid                identifier of principal in SAML 2.0 form
+         * @param statement             SAML 2.0 authentication statement, if any
          * @param authncontext_class    method/category of authentication event, if known
          * @param authncontext_decl     specifics of authentication event, if known
          * @param tokens                available assertions, if any
@@ -209,6 +211,15 @@ namespace shibsp {
             const std::vector<const opensaml::Assertion*>* tokens=nullptr
             ) const;
 
+        /**
+         * Creates a new AuthnRequestEvent for the event log.
+         *
+         * @param application   the Application associated with the event
+         * @param request       the HTTP client request associated with the event
+         * @return  a fresh LoginEvent, prepopulated by the input parameters, or nullptr if an error occurs
+         */
+        virtual LoginEvent* newLoginEvent(const Application& application, const xmltooling::HTTPRequest& request) const;
+
     public:
         const char* getType() const;
         const XMLCh* getProtocolFamily() const;
index b9e2d06..02a4862 100644 (file)
 
 namespace shibsp {
 
+#ifndef SHIBSP_LITE
+    class SHIBSP_API LogoutEvent;
+#endif
+
 #if defined (_MSC_VER)
     #pragma warning( push )
     #pragma warning( disable : 4251 )
@@ -141,6 +145,22 @@ namespace shibsp {
             xmltooling::HTTPResponse& response,
             const char* type
             ) const;
+
+#ifndef SHIBSP_LITE
+        /**
+         * Creates a new LogoutEvent for the event log.
+         *
+         * @param application   the Application associated with the event
+         * @param request       the HTTP client request associated with the event, or nullptr
+         * @param session       the user session associated with the event, or nullptr
+         * @return  a fresh LogoutEvent, prepopulated by the input parameters, or nullptr if an error occurs
+         */
+        virtual LogoutEvent* newLogoutEvent(
+            const Application& application,
+            const xmltooling::HTTPRequest* request=nullptr,
+            const Session* session=nullptr
+            ) const;
+#endif
     };
 
 #if defined (_MSC_VER)
index a2c53ad..3643aef 100644 (file)
@@ -35,6 +35,8 @@
 
 namespace shibsp {
 
+    class SHIBSP_API AuthnRequestEvent;
+
     /**
      * Pluggable runtime functionality that handles initiating sessions.
      *
@@ -65,6 +67,19 @@ namespace shibsp {
          */
         bool checkCompatibility(SPRequest& request, bool isHandler) const;
 
+#ifndef SHIBSP_LITE
+        /**
+         * Creates a new AuthnRequestEvent for the event log.
+         *
+         * @param application   the Application associated with the event
+         * @param request       the HTTP client request associated with the event, or nullptr
+         * @return  a fresh AuthnRequestEvent, prepopulated by the input parameters, or nullptr if an error occurs
+         */
+        virtual AuthnRequestEvent* newAuthnRequestEvent(
+            const Application& application, const xmltooling::HTTPRequest* request=nullptr
+            ) const;
+#endif
+
     public:
         virtual ~SessionInitiator();
 
index 81807a3..e0e9396 100644 (file)
@@ -46,6 +46,8 @@
 # include <saml/exceptions.h>
 # include <saml/SAMLConfig.h>
 # include <saml/saml1/core/Assertions.h>
+# include <saml/saml1/core/Protocols.h>
+# include <saml/saml2/core/Protocols.h>
 # include <saml/saml2/metadata/Metadata.h>
 # include <saml/util/CommonDomainCookie.h>
 using namespace samlconstants;
@@ -105,6 +107,7 @@ pair<bool,long> AssertionConsumerService::run(SPRequest& request, bool isHandler
     else {
         // When not out of process, we remote all the message processing.
         vector<string> headers(1, "Cookie");
+        headers.push_back("User-Agent");
         DDF out,in = wrap(request, &headers);
         DDFJanitor jin(in), jout(out);
         out=request.getServiceProvider().getListenerService()->send(in);
@@ -158,11 +161,13 @@ pair<bool,long> AssertionConsumerService::processMessage(
 
     string relayState;
     bool relayStateOK = true;
+    auto_ptr<XMLObject> msg(nullptr);
     try {
         // Decode the message and process it in a protocol-specific way.
-        auto_ptr<XMLObject> msg(m_decoder->decode(relayState, httpRequest, *(policy.get())));
-        if (!msg.get())
+        auto_ptr<XMLObject> msg2(m_decoder->decode(relayState, httpRequest, *(policy.get())));
+        if (!msg2.get())
             throw BindingException("Failed to decode an SSO protocol response.");
+        msg = msg2; // save off to allow access from within exception handler.
         DDF postData = recoverPostData(application, httpRequest, httpResponse, relayState.c_str());
         DDFJanitor postjan(postData);
         recoverRelayState(application, httpRequest, httpResponse, relayState);
@@ -200,6 +205,33 @@ pair<bool,long> AssertionConsumerService::processMessage(
         }
         if (!relayState.empty())
             ex.addProperty("RelayState", relayState.c_str());
+
+        // Log the error.
+        try {
+            auto_ptr<TransactionLog::Event> event(SPConfig::getConfig().EventManager.newPlugin(LOGIN_EVENT, nullptr));
+            LoginEvent* error_event = dynamic_cast<LoginEvent*>(event.get());
+            if (error_event) {
+                error_event->m_exception = &ex;
+                error_event->m_request = &httpRequest;
+                error_event->m_app = &application;
+                if (policy->getIssuerMetadata())
+                    error_event->m_peer = dynamic_cast<const EntityDescriptor*>(policy->getIssuerMetadata()->getParent());
+                auto_ptr_char prot(getProtocolFamily());
+                error_event->m_protocol = prot.get();
+                error_event->m_binding = getString("Binding").second;
+                error_event->m_saml2Response = dynamic_cast<const saml2p::StatusResponseType*>(msg.get());
+                if (!error_event->m_saml2Response)
+                    error_event->m_saml1Response = dynamic_cast<const saml1p::Response*>(msg.get());
+                application.getServiceProvider().getTransactionLog()->write(*error_event);
+            }
+            else {
+                m_log.warn("unable to audit event, log event object was of an incorrect type");
+            }
+        }
+        catch (exception& ex) {
+            m_log.warn("exception auditing event: %s", ex.what());
+        }
+
         throw;
     }
 #else
@@ -500,6 +532,30 @@ void AssertionConsumerService::extractMessageDetails(const Assertion& assertion,
     }
 }
 
+LoginEvent* AssertionConsumerService::newLoginEvent(const Application& application, const xmltooling::HTTPRequest& request) const
+{
+    if (!SPConfig::getConfig().isEnabled(SPConfig::Logging))
+        return nullptr;
+    try {
+        auto_ptr<TransactionLog::Event> event(SPConfig::getConfig().EventManager.newPlugin(LOGIN_EVENT, nullptr));
+        LoginEvent* login_event = dynamic_cast<LoginEvent*>(event.get());
+        if (login_event) {
+            login_event->m_request = &request;
+            login_event->m_app = &application;
+            login_event->m_binding = getString("Binding").second;
+            event.release();
+            return login_event;
+        }
+        else {
+            m_log.warn("unable to audit event, log event object was of an incorrect type");
+        }
+    }
+    catch (exception& ex) {
+        m_log.warn("exception auditing event: %s", ex.what());
+    }
+    return nullptr;
+}
+
 #endif
 
 void AssertionConsumerService::maintainHistory(
index 5e3085e..34cd2db 100644 (file)
@@ -25,6 +25,7 @@
  */
 
 #include "internal.h"
+#include "exceptions.h"
 #include "Application.h"
 #include "ServiceProvider.h"
 #include "SessionCache.h"
@@ -50,9 +51,14 @@ namespace shibsp {
         virtual ~LocalLogoutInitiator() {}
         
         void setParent(const PropertySet* parent);
+        void receive(DDF& in, ostream& out);
         pair<bool,long> run(SPRequest& request, bool isHandler=true) const;
 
     private:
+        pair<bool,long> doRequest(
+            const Application& application, const HTTPRequest& request, HTTPResponse& httpResponse, Session* session
+            ) const;
+
         string m_appId;
     };
 
@@ -96,22 +102,95 @@ pair<bool,long> LocalLogoutInitiator::run(SPRequest& request, bool isHandler) co
     if (ret.first)
         return ret;
 
-    const Application& app = request.getApplication();
-    string session_id = app.getServiceProvider().getSessionCache()->active(app, request);
-    if (!session_id.empty()) {
+    if (SPConfig::getConfig().isEnabled(SPConfig::OutOfProcess)) {
+        // When out of process, we run natively.
+        Session* session = nullptr;
+        try {
+            session = request.getSession(false, true, false);  // don't cache it and ignore all checks
+        }
+        catch (exception& ex) {
+            m_log.error("error accessing current session: %s", ex.what());
+        }
+        return doRequest(request.getApplication(), request, request, session);
+    }
+    else {
+        // When not out of process, we remote the request.
+        vector<string> headers(1,"Cookie");
+        DDF out,in = wrap(request,&headers);
+        DDFJanitor jin(in), jout(out);
+        out=request.getServiceProvider().getListenerService()->send(in);
+        return unwrap(request, out);
+    }
+}
+
+void LocalLogoutInitiator::receive(DDF& in, ostream& out)
+{
+#ifndef SHIBSP_LITE
+    // Defer to base class for back channel notifications
+    if (in["notify"].integer() == 1)
+        return LogoutHandler::receive(in, out);
+
+    // Find application.
+    const char* aid=in["application_id"].string();
+    const Application* app=aid ? SPConfig::getConfig().getServiceProvider()->getApplication(aid) : nullptr;
+    if (!app) {
+        // Something's horribly wrong.
+        m_log.error("couldn't find application (%s) for logout", aid ? aid : "(missing)");
+        throw ConfigurationException("Unable to locate application for logout, deleted?");
+    }
+
+    // Unpack the request.
+    auto_ptr<HTTPRequest> req(getRequest(in));
+
+    // Set up a response shim.
+    DDF ret(nullptr);
+    DDFJanitor jout(ret);
+    auto_ptr<HTTPResponse> resp(getResponse(ret));
+
+    Session* session = nullptr;
+    try {
+         session = app->getServiceProvider().getSessionCache()->find(*app, *req.get(), nullptr, nullptr);
+    }
+    catch (exception& ex) {
+        m_log.error("error accessing current session: %s", ex.what());
+    }
+
+    // This is the "last chance" handler so even without a session, we "complete" the logout.
+    doRequest(*app, *req.get(), *resp.get(), session);
+
+    out << ret;
+#else
+    throw ConfigurationException("Cannot perform logout using lite version of shibsp library.");
+#endif
+}
+
+pair<bool,long> LocalLogoutInitiator::doRequest(
+    const Application& application, const HTTPRequest& httpRequest, HTTPResponse& httpResponse, Session* session
+    ) const
+{
+    if (session) {
         // Do back channel notification.
-        vector<string> sessions(1, session_id);
-        bool result = notifyBackChannel(app, request.getRequestURL(), sessions, true);
-        app.getServiceProvider().getSessionCache()->remove(app, request, &request);
+        bool result;
+        vector<string> sessions(1, session->getID());
+        result = notifyBackChannel(application, httpRequest.getRequestURL(), sessions, true);
+#ifndef SHIBSP_LITE
+        auto_ptr<LogoutEvent> logout_event(newLogoutEvent(application, &httpRequest, session));
+        if (logout_event.get()) {
+            logout_event->m_logoutType = result ? LogoutEvent::LOGOUT_EVENT_LOCAL : LogoutEvent::LOGOUT_EVENT_PARTIAL;
+            application.getServiceProvider().getTransactionLog()->write(*logout_event);
+        }
+#endif
+        session->unlock();
+        application.getServiceProvider().getSessionCache()->remove(application, httpRequest, &httpResponse);
         if (!result)
-            return sendLogoutPage(app, request, request, "partial");
+            return sendLogoutPage(application, httpRequest, httpResponse, "partial");
     }
 
     // Route back to return location specified, or use the local template.
-    const char* dest = request.getParameter("return");
+    const char* dest = httpRequest.getParameter("return");
     if (dest) {
-        limitRelayState(m_log, app, request, dest);
-        return make_pair(true, request.sendRedirect(dest));
+        limitRelayState(m_log, application, httpRequest, dest);
+        return make_pair(true, httpResponse.sendRedirect(dest));
     }
-    return sendLogoutPage(app, request, request, "local");
+    return sendLogoutPage(application, httpRequest, httpResponse, "local");
 }
index 253bde1..2b9d7a3 100644 (file)
@@ -30,6 +30,7 @@
 #include "ServiceProvider.h"
 #include "SessionCache.h"
 #include "SPRequest.h"
+#include "TransactionLog.h"
 #include "handler/LogoutHandler.h"
 #include "util/TemplateParameters.h"
 
@@ -283,3 +284,38 @@ bool LogoutHandler::notifyBackChannel(
     out=application.getServiceProvider().getListenerService()->send(in);
     return (out.integer() == 1);
 }
+
+#ifndef SHIBSP_LITE
+
+LogoutEvent* LogoutHandler::newLogoutEvent(
+    const Application& application, const xmltooling::HTTPRequest* request, const Session* session
+    ) const
+{
+    if (!SPConfig::getConfig().isEnabled(SPConfig::Logging))
+        return nullptr;
+    try {
+        auto_ptr<TransactionLog::Event> event(SPConfig::getConfig().EventManager.newPlugin(LOGOUT_EVENT, nullptr));
+        LogoutEvent* logout_event = dynamic_cast<LogoutEvent*>(event.get());
+        if (logout_event) {
+            logout_event->m_request = request;
+            logout_event->m_app = &application;
+            logout_event->m_binding = getString("Binding").second;
+            logout_event->m_session = session;
+            if (session) {
+                logout_event->m_nameID = session->getNameID();
+                logout_event->m_sessions.push_back(session->getID());
+            }
+            event.release();
+            return logout_event;
+        }
+        else {
+            Category::getInstance(SHIBSP_LOGCAT".Logout").warn("unable to audit event, log event object was of an incorrect type");
+        }
+    }
+    catch (exception& ex) {
+        Category::getInstance(SHIBSP_LOGCAT".Logout").warn("exception auditing event: %s", ex.what());
+    }
+    return nullptr;
+}
+
+#endif
index adeebf3..b8f7471 100644 (file)
@@ -31,6 +31,7 @@
 # include "Application.h"
 # include "ServiceProvider.h"
 # include "SessionCache.h"
+# include "TransactionLog.h"
 # include "attribute/resolver/ResolutionContext.h"
 # include <saml/exceptions.h>
 # include <saml/SAMLConfig.h>
@@ -317,7 +318,9 @@ void SAML1Consumer::implementProtocol(
     // Now merge in bad tokens for caching.
     tokens.insert(tokens.end(), badtokens.begin(), badtokens.end());
 
+    string session_id;
     application.getServiceProvider().getSessionCache()->insert(
+        session_id,
         application,
         httpRequest,
         httpResponse,
@@ -333,6 +336,23 @@ void SAML1Consumer::implementProtocol(
         &tokens,
         ctx.get() ? &ctx->getResolvedAttributes() : nullptr
         );
+
+    auto_ptr<LoginEvent> login_event(newLoginEvent(application, httpRequest));
+    if (login_event.get()) {
+        login_event->m_sessionID = session_id.c_str();
+        login_event->m_peer = entity;
+        auto_ptr_char prot(
+            (!response->getMinorVersion().first || response->getMinorVersion().second==1) ?
+                samlconstants::SAML11_PROTOCOL_ENUM : samlconstants::SAML10_PROTOCOL_ENUM
+            );
+        login_event->m_protocol = prot.get();
+        login_event->m_nameID = nameid.get();
+        login_event->m_saml1AuthnStatement = ssoStatement;
+        login_event->m_saml1Response = response;
+        if (ctx.get())
+            login_event->m_attributes = &ctx->getResolvedAttributes();
+        application.getServiceProvider().getTransactionLog()->write(*login_event);
+    }
 }
 
 #endif
index ad8fcdc..47ebc4f 100644 (file)
@@ -31,6 +31,7 @@
 # include "Application.h"
 # include "ServiceProvider.h"
 # include "SessionCache.h"
+# include "TransactionLog.h"
 # include "attribute/resolver/ResolutionContext.h"
 # include <saml/exceptions.h>
 # include <saml/SAMLConfig.h>
@@ -436,7 +437,9 @@ void SAML2Consumer::implementProtocol(
         // Now merge in bad tokens for caching.
         tokens.insert(tokens.end(), badtokens.begin(), badtokens.end());
 
+        string session_id;
         application.getServiceProvider().getSessionCache()->insert(
+            session_id,
             application,
             httpRequest,
             httpResponse,
@@ -452,6 +455,29 @@ void SAML2Consumer::implementProtocol(
             ctx.get() ? &ctx->getResolvedAttributes() : nullptr
             );
 
+        try {
+            auto_ptr<TransactionLog::Event> event(newLoginEvent(application, httpRequest));
+            LoginEvent* login_event = dynamic_cast<LoginEvent*>(event.get());
+            if (login_event) {
+                login_event->m_sessionID = session_id.c_str();
+                login_event->m_peer = entity;
+                auto_ptr_char prot(getProtocolFamily());
+                login_event->m_protocol = prot.get();
+                login_event->m_nameID = ssoName;
+                login_event->m_saml2AuthnStatement = ssoStatement;
+                login_event->m_saml2Response = response;
+                if (ctx.get())
+                    login_event->m_attributes = &ctx->getResolvedAttributes();
+                application.getServiceProvider().getTransactionLog()->write(*login_event);
+            }
+            else {
+                m_log.warn("unable to audit event, log event object was of an incorrect type");
+            }
+        }
+        catch (exception& ex) {
+            m_log.warn("exception auditing event: %s", ex.what());
+        }
+
         if (ownedName)
             delete ssoName;
         for_each(ownedtokens.begin(), ownedtokens.end(), xmltooling::cleanup<saml2::Assertion>());
index 927013c..5a77bbe 100644 (file)
@@ -111,6 +111,7 @@ namespace shibsp {
 
 #ifndef SHIBSP_LITE
         pair<bool,long> sendResponse(
+            LogoutEvent* logoutEvent,
             const XMLCh* requestID,
             const XMLCh* code,
             const XMLCh* subcode,
@@ -122,11 +123,21 @@ namespace shibsp {
             bool front
             ) const;
 
+        LogoutEvent* newLogoutEvent(
+            const Application& application, const HTTPRequest* request=nullptr, const Session* session=nullptr
+            ) const {
+            LogoutEvent* e = LogoutHandler::newLogoutEvent(application, request, session);
+            if (e)
+                e->m_protocol = m_protocol.get();
+            return e;
+        }
+
         xmltooling::QName m_role;
         MessageDecoder* m_decoder;
         XMLCh* m_outgoing;
         vector<const XMLCh*> m_bindings;
         map<const XMLCh*,MessageEncoder*> m_encoders;
+        auto_ptr_char m_protocol;
 #endif
     };
 
@@ -143,7 +154,7 @@ namespace shibsp {
 SAML2Logout::SAML2Logout(const DOMElement* e, const char* appId)
     : AbstractHandler(e, Category::getInstance(SHIBSP_LOGCAT".Logout.SAML2"))
 #ifndef SHIBSP_LITE
-        ,m_role(samlconstants::SAML20MD_NS, IDPSSODescriptor::LOCAL_NAME), m_decoder(nullptr), m_outgoing(nullptr)
+        ,m_role(samlconstants::SAML20MD_NS, IDPSSODescriptor::LOCAL_NAME), m_decoder(nullptr), m_outgoing(nullptr), m_protocol(samlconstants::SAML20P_NS)
 #endif
 {
     m_initiator = false;
@@ -235,6 +246,7 @@ pair<bool,long> SAML2Logout::run(SPRequest& request, bool isHandler) const
     else {
         // When not out of process, we remote all the message processing.
         vector<string> headers(1,"Cookie");
+        headers.push_back("User-Agent");
         DDF out,in = wrap(request, &headers, true);
         DDFJanitor jin(in), jout(out);
         out=request.getServiceProvider().getListenerService()->send(in);
@@ -276,6 +288,10 @@ pair<bool,long> SAML2Logout::doRequest(const Application& application, const HTT
     SessionCacheEx* cacheex = dynamic_cast<SessionCacheEx*>(cache);
     string session_id = cache->active(application, request);
 
+    auto_ptr<LogoutEvent> logout_event(newLogoutEvent(application, &request));
+    if (logout_event.get() && !session_id.empty())
+        logout_event->m_sessions.push_back(session_id);
+
     if (!strcmp(request.getMethod(),"GET") && request.getParameter("notifying")) {
         // This is returning from a front-channel notification, so we have to do the back-channel and then
         // respond. To do that, we need state from the original request.
@@ -304,11 +320,14 @@ pair<bool,long> SAML2Logout::doRequest(const Application& application, const HTT
         // We need metadata to issue a response.
         MetadataProvider* m = application.getMetadataProvider();
         Locker metadataLocker(m);
-        MetadataProviderCriteria mc(application, request.getParameter("entityID"), &IDPSSODescriptor::ELEMENT_QNAME, samlconstants::SAML20P_NS);
+        MetadataProviderCriteria mc(
+            application, request.getParameter("entityID"), &IDPSSODescriptor::ELEMENT_QNAME, samlconstants::SAML20P_NS
+            );
         pair<const EntityDescriptor*,const RoleDescriptor*> entity = m->getEntityDescriptor(mc);
         if (!entity.first) {
             throw MetadataException(
-                "Unable to locate metadata for identity provider ($entityID)", namedparams(1, "entityID", request.getParameter("entityID"))
+                "Unable to locate metadata for identity provider ($entityID)",
+                namedparams(1, "entityID", request.getParameter("entityID"))
                 );
         }
         else if (!entity.second) {
@@ -321,12 +340,22 @@ pair<bool,long> SAML2Logout::doRequest(const Application& application, const HTT
         auto_ptr_XMLCh reqid(request.getParameter("ID"));
         if (worked1 && worked2) {
             // Successful LogoutResponse. Has to be front-channel or we couldn't be here.
+            if (logout_event.get())
+                logout_event->m_logoutType = LogoutEvent::LOGOUT_EVENT_GLOBAL;
             return sendResponse(
-                reqid.get(), StatusCode::SUCCESS, nullptr, nullptr, request.getParameter("RelayState"), entity.second, application, response, true
+                logout_event.get(),
+                reqid.get(),
+                StatusCode::SUCCESS, nullptr, nullptr,
+                request.getParameter("RelayState"),
+                entity.second,
+                application,
+                response,
+                true
                 );
         }
 
         return sendResponse(
+            logout_event.get(),
             reqid.get(),
             StatusCode::RESPONDER, nullptr, "Unable to fully destroy principal's session.",
             request.getParameter("RelayState"),
@@ -360,12 +389,21 @@ pair<bool,long> SAML2Logout::doRequest(const Application& application, const HTT
         if (!policy->isAuthenticated())
             throw SecurityPolicyException("Security of LogoutRequest not established.");
 
+        if (logout_event.get()) {
+            logout_event->m_saml2Request = logoutRequest;
+            if (policy->getIssuerMetadata())
+                logout_event->m_peer = dynamic_cast<const EntityDescriptor*>(policy->getIssuerMetadata()->getParent());
+            application.getServiceProvider().getTransactionLog()->write(*logout_event);
+            logout_event->m_saml2Request = nullptr;
+        }
+
         // Message from IdP to logout one or more sessions.
 
         // If this is front-channel, we have to have a session_id to use already.
         if (m_decoder->isUserAgentPresent() && session_id.empty()) {
             m_log.error("no active session");
             return sendResponse(
+                logout_event.get(),
                 logoutRequest->getID(),
                 StatusCode::REQUESTER, StatusCode::UNKNOWN_PRINCIPAL, "No active session found in request.",
                 relayState.c_str(),
@@ -417,6 +455,7 @@ pair<bool,long> SAML2Logout::doRequest(const Application& application, const HTT
             // No NameID, so must respond with an error.
             m_log.error("NameID not found in request");
             return sendResponse(
+                logout_event.get(),
                 logoutRequest->getID(),
                 StatusCode::REQUESTER, StatusCode::UNKNOWN_PRINCIPAL, "NameID not found in request.",
                 relayState.c_str(),
@@ -443,6 +482,7 @@ pair<bool,long> SAML2Logout::doRequest(const Application& application, const HTT
         if (!session_id.empty()) {
             if (!cache->matches(application, request, entity, *nameid, &indexes)) {
                 return sendResponse(
+                    logout_event.get(),
                     logoutRequest->getID(),
                     StatusCode::REQUESTER, StatusCode::REQUEST_DENIED, "Active session did not match logout request.",
                     relayState.c_str(),
@@ -477,7 +517,13 @@ pair<bool,long> SAML2Logout::doRequest(const Application& application, const HTT
         }
         catch (exception& ex) {
             m_log.error("error while logging out matching sessions: %s", ex.what());
+            if (logout_event.get()) {
+                logout_event->m_nameID = nameid;
+                logout_event->m_sessions = sessions;
+                logout_event->m_logoutType = LogoutEvent::LOGOUT_EVENT_PARTIAL;
+            }
             return sendResponse(
+                logout_event.get(),
                 logoutRequest->getID(),
                 StatusCode::RESPONDER, nullptr, ex.what(),
                 relayState.c_str(),
@@ -518,7 +564,13 @@ pair<bool,long> SAML2Logout::doRequest(const Application& application, const HTT
             }
         }
 
+        if (logout_event.get()) {
+            logout_event->m_nameID = nameid;
+            logout_event->m_sessions = sessions;
+            logout_event->m_logoutType = (worked1 && worked2) ? LogoutEvent::LOGOUT_EVENT_PARTIAL : LogoutEvent::LOGOUT_EVENT_GLOBAL;
+        }
         return sendResponse(
+            logout_event.get(),
             logoutRequest->getID(),
             (worked1 && worked2) ? StatusCode::SUCCESS : StatusCode::RESPONDER,
             (worked1 && worked2) ? nullptr : StatusCode::PARTIAL_LOGOUT,
@@ -540,7 +592,24 @@ pair<bool,long> SAML2Logout::doRequest(const Application& application, const HTT
                 annotateException(&ex, policy->getIssuerMetadata()); // throws it
             ex.raise();
         }
-        checkError(logoutResponse, policy->getIssuerMetadata()); // throws if Status doesn't look good...
+        if (logout_event.get()) {
+            logout_event->m_logoutType = LogoutEvent::LOGOUT_EVENT_PARTIAL;
+            logout_event->m_saml2Response = logoutResponse;
+            if (policy->getIssuerMetadata())
+                logout_event->m_peer = dynamic_cast<const EntityDescriptor*>(policy->getIssuerMetadata()->getParent());
+        }
+
+        try {
+            checkError(logoutResponse, policy->getIssuerMetadata()); // throws if Status doesn't look good...
+        }
+        catch (exception& ex) {
+            if (logout_event.get()) {
+                logout_event->m_exception = &ex;
+                application.getServiceProvider().getTransactionLog()->write(*logout_event);
+            }
+            throw;
+        }
 
         // If relay state is set, recover the original return URL.
         if (!relayState.empty())
@@ -549,8 +618,16 @@ pair<bool,long> SAML2Logout::doRequest(const Application& application, const HTT
         // Check for partial logout.
         const StatusCode* sc = logoutResponse->getStatus() ? logoutResponse->getStatus()->getStatusCode() : nullptr;
         sc = sc ? sc->getStatusCode() : nullptr;
-        if (sc && XMLString::equals(sc->getValue(), StatusCode::PARTIAL_LOGOUT))
+        if (sc && XMLString::equals(sc->getValue(), StatusCode::PARTIAL_LOGOUT)) {
+            if (logout_event.get())
+                application.getServiceProvider().getTransactionLog()->write(*logout_event);
             return sendLogoutPage(application, request, response, "partial");
+        }
+
+        if (logout_event.get()) {
+            logout_event->m_logoutType = LogoutEvent::LOGOUT_EVENT_GLOBAL;
+            application.getServiceProvider().getTransactionLog()->write(*logout_event);
+        }
 
         if (!relayState.empty()) {
             limitRelayState(m_log, application, request, relayState.c_str());
@@ -574,6 +651,7 @@ pair<bool,long> SAML2Logout::doRequest(const Application& application, const HTT
 #ifndef SHIBSP_LITE
 
 pair<bool,long> SAML2Logout::sendResponse(
+    LogoutEvent* logoutEvent,
     const XMLCh* requestID,
     const XMLCh* code,
     const XMLCh* subcode,
@@ -622,9 +700,16 @@ pair<bool,long> SAML2Logout::sendResponse(
     logout->setIssuer(issuer);
     issuer->setName(application.getRelyingParty(dynamic_cast<EntityDescriptor*>(role->getParent()))->getXMLString("entityID").second);
     fillStatus(*logout.get(), code, subcode, msg);
+    logout->setID(SAMLConfig::getConfig().generateIdentifier());
+    logout->setIssueInstant(time(nullptr));
 
-    auto_ptr_char dest(logout->getDestination());
+    if (logoutEvent) {
+        logoutEvent->m_peer = dynamic_cast<EntityDescriptor*>(role->getParent());
+        logoutEvent->m_saml2Response = logout.get();
+        application.getServiceProvider().getTransactionLog()->write(*logoutEvent);
+    }
 
+    auto_ptr_char dest(logout->getDestination());
     long ret = sendMessage(*encoder, logout.get(), relayState, dest.get(), role, application, httpResponse);
     logout.release();  // freed by encoder
     return make_pair(true,ret);
index a4a1115..12a0d3c 100644 (file)
@@ -96,6 +96,15 @@ namespace shibsp {
             const Application& application, const Session& session, const RoleDescriptor& role, const MessageEncoder* encoder=nullptr
             ) const;
 
+        LogoutEvent* newLogoutEvent(
+            const Application& application, const HTTPRequest* request=nullptr, const Session* session=nullptr
+            ) const {
+            LogoutEvent* e = LogoutHandler::newLogoutEvent(application, request, session);
+            if (e)
+                e->m_protocol = m_protocol.get();
+            return e;
+        }
+
         XMLCh* m_outgoing;
         vector<const XMLCh*> m_bindings;
         map<const XMLCh*,MessageEncoder*> m_encoders;
@@ -275,9 +284,9 @@ void SAML2LogoutInitiator::receive(DDF& in, ostream& out)
             doRequest(*app, *req.get(), *resp.get(), session);
         }
         else {
-             m_log.log(getParent() ? Priority::WARN : Priority::ERROR, "bypassing SAML 2.0 logout, no NameID or issuing entityID found in session");
-             session->unlock();
-             app->getServiceProvider().getSessionCache()->remove(*app, *req.get(), resp.get());
+            m_log.log(getParent() ? Priority::WARN : Priority::ERROR, "bypassing SAML 2.0 logout, no NameID or issuing entityID found in session");
+            session->unlock();
+            app->getServiceProvider().getSessionCache()->remove(*app, *req.get(), resp.get());
         }
     }
     out << ret;
@@ -290,9 +299,19 @@ pair<bool,long> SAML2LogoutInitiator::doRequest(
     const Application& application, const HTTPRequest& httpRequest, HTTPResponse& httpResponse, Session* session
     ) const
 {
+#ifndef SHIBSP_LITE
+    auto_ptr<LogoutEvent> logout_event(newLogoutEvent(application, &httpRequest, session));
+#endif
+
     // Do back channel notification.
     vector<string> sessions(1, session->getID());
     if (!notifyBackChannel(application, httpRequest.getRequestURL(), sessions, false)) {
+#ifndef SHIBSP_LITE
+        if (logout_event.get()) {
+            logout_event->m_logoutType = LogoutEvent::LOGOUT_EVENT_PARTIAL;
+            application.getServiceProvider().getTransactionLog()->write(*logout_event);
+        }
+#endif
         session->unlock();
         application.getServiceProvider().getSessionCache()->remove(application, httpRequest, &httpResponse);
         return sendLogoutPage(application, httpRequest, httpResponse, "partial");
@@ -349,8 +368,15 @@ pair<bool,long> SAML2LogoutInitiator::doRequest(
                     if (!XMLString::equals((*epit)->getBinding(),binding.get()))
                         continue;
                     LogoutRequest* msg = buildRequest(application, *session, *role);
-                    auto_ptr_char dest((*epit)->getLocation());
 
+                    // Log the request.
+                    if (logout_event.get()) {
+                        logout_event->m_logoutType = LogoutEvent::LOGOUT_EVENT_UNKNOWN;
+                        logout_event->m_saml2Request = msg;
+                        application.getServiceProvider().getTransactionLog()->write(*logout_event);
+                    }
+
+                    auto_ptr_char dest((*epit)->getLocation());
                     SAML2SOAPClient client(soaper, false);
                     client.sendSAML(msg, application.getId(), mcc, dest.get());
                     StatusResponseType* srt = client.receiveSAML();
@@ -371,6 +397,13 @@ pair<bool,long> SAML2LogoutInitiator::doRequest(
                     m_log.info("IdP doesn't support single logout protocol over a compatible binding");
                 else
                     m_log.warn("IdP didn't respond to logout request");
+
+                // Log the end result.
+                if (logout_event.get()) {
+                    logout_event->m_logoutType = LogoutEvent::LOGOUT_EVENT_PARTIAL;
+                    application.getServiceProvider().getTransactionLog()->write(*logout_event);
+                }
+
                 ret = sendLogoutPage(application, httpRequest, httpResponse, "partial");
             }
             else {
@@ -381,6 +414,14 @@ pair<bool,long> SAML2LogoutInitiator::doRequest(
                     // Success, but still need to check for partial.
                     partial = XMLString::equals(sc->getStatusCode()->getValue(), StatusCode::PARTIAL_LOGOUT);
                 }
+
+                // Log the end result.
+                if (logout_event.get()) {
+                    logout_event->m_logoutType = partial ? LogoutEvent::LOGOUT_EVENT_PARTIAL : LogoutEvent::LOGOUT_EVENT_GLOBAL;
+                    logout_event->m_saml2Response = logoutResponse;
+                    application.getServiceProvider().getTransactionLog()->write(*logout_event);
+                }
+
                 delete logoutResponse;
                 if (partial)
                     ret = sendLogoutPage(application, httpRequest, httpResponse, "partial");
@@ -414,27 +455,40 @@ pair<bool,long> SAML2LogoutInitiator::doRequest(
         }
 
         auto_ptr<LogoutRequest> msg(buildRequest(application, *session, *role, encoder));
-
         msg->setDestination(ep->getLocation());
+
+        // Log the request.
+        if (logout_event.get()) {
+            logout_event->m_logoutType = LogoutEvent::LOGOUT_EVENT_UNKNOWN;
+            logout_event->m_saml2Request = msg.get();
+            application.getServiceProvider().getTransactionLog()->write(*logout_event);
+        }
+
         auto_ptr_char dest(ep->getLocation());
         ret.second = sendMessage(*encoder, msg.get(), relayState.c_str(), dest.get(), role, application, httpResponse);
         ret.first = true;
         msg.release();  // freed by encoder
+
+        if (session) {
+            session->unlock();
+            session = nullptr;
+            application.getServiceProvider().getSessionCache()->remove(application, httpRequest, &httpResponse);
+        }
+    }
+    catch (MetadataException& mex) {
+        // Less noise for IdPs that don't support logout (i.e. most)
+        m_log.info("unable to issue SAML 2.0 logout request: %s", mex.what());
     }
     catch (exception& ex) {
         m_log.error("error issuing SAML 2.0 logout request: %s", ex.what());
     }
 
-    if (session) {
+    if (session)
         session->unlock();
-        session = nullptr;
-        application.getServiceProvider().getSessionCache()->remove(application, httpRequest, &httpResponse);
-    }
-
     return ret;
 #else
-    session->unlock();
-    application.getServiceProvider().getSessionCache()->remove(application, httpRequest, &httpResponse);
+    if (session)
+        session->unlock();
     throw ConfigurationException("Cannot perform logout using lite version of shibsp library.");
 #endif
 }
@@ -477,6 +531,9 @@ LogoutRequest* SAML2LogoutInitiator::buildRequest(
         msg->setNameID(nameid->cloneNameID());
     }
 
+    msg->setID(SAMLConfig::getConfig().generateIdentifier());
+    msg->setIssueInstant(time(nullptr));
+
     return msg.release();
 }
 
index eb4caeb..4f03005 100644 (file)
@@ -225,6 +225,7 @@ pair<bool,long> SAML2NameIDMgmt::run(SPRequest& request, bool isHandler) const
     else {
         // When not out of process, we remote all the message processing.
         vector<string> headers(1,"Cookie");
+        headers.push_back("User-Agent");
         DDF out,in = wrap(request, &headers, true);
         DDFJanitor jin(in), jout(out);
         out=request.getServiceProvider().getListenerService()->send(in);
index 75e6ef0..7dc1b8c 100644 (file)
@@ -740,6 +740,20 @@ pair<bool,long> SAML2SessionInitiator::doRequest(
         }
     }
 
+    req->setID(SAMLConfig::getConfig().generateIdentifier());
+    req->setIssueInstant(time(nullptr));
+
+    auto_ptr<AuthnRequestEvent> ar_event(newAuthnRequestEvent(app, httpRequest));
+    if (ar_event.get()) {
+        auto_ptr_char b(ep ? ep->getBinding() : nullptr);
+        ar_event->m_binding = b.get() ? b.get() : samlconstants::SAML20_BINDING_SOAP;
+        auto_ptr_char prot(getProtocolFamily());
+        ar_event->m_protocol = prot.get();
+        ar_event->m_peer = entity.first;
+        ar_event->m_saml2Request = req.get();
+        app.getServiceProvider().getTransactionLog()->write(*ar_event);
+    }
+
     auto_ptr_char dest(ep ? ep->getLocation() : nullptr);
 
     if (httpRequest) {
index 50413bd..ac145a2 100644 (file)
@@ -201,3 +201,30 @@ pair<bool,long> SessionInitiator::run(SPRequest& request, bool isHandler) const
         throw;
     }
 }
+
+#ifndef SHIBSP_LITE
+
+AuthnRequestEvent* SessionInitiator::newAuthnRequestEvent(const Application& application, const xmltooling::HTTPRequest* request) const
+{
+    if (!SPConfig::getConfig().isEnabled(SPConfig::Logging))
+        return nullptr;
+    try {
+        auto_ptr<TransactionLog::Event> event(SPConfig::getConfig().EventManager.newPlugin(AUTHNREQUEST_EVENT, nullptr));
+        AuthnRequestEvent* ar_event = dynamic_cast<AuthnRequestEvent*>(event.get());
+        if (ar_event) {
+            ar_event->m_request = request;
+            ar_event->m_app = &application;
+            event.release();
+            return ar_event;
+        }
+        else {
+            Category::getInstance(SHIBSP_LOGCAT".SessionInitiator").warn("unable to audit event, log event object was of an incorrect type");
+        }
+    }
+    catch (exception& ex) {
+        Category::getInstance(SHIBSP_LOGCAT".SessionInitiator").warn("exception auditing event: %s", ex.what());
+    }
+    return nullptr;
+}
+
+#endif
index 3367e1c..0b9962d 100644 (file)
@@ -303,6 +303,16 @@ pair<bool,long> Shib1SessionInitiator::doRequest(
 
     preserveRelayState(app, httpResponse, relayState);
 
+    auto_ptr<AuthnRequestEvent> ar_event(newAuthnRequestEvent(app, httpRequest));
+    if (ar_event.get()) {
+        auto_ptr_char prot(getProtocolFamily());
+        ar_event->m_protocol = prot.get();
+        auto_ptr_char b(shibspconstants::SHIB1_AUTHNREQUEST_PROFILE_URI);
+        ar_event->m_binding = b.get();
+        ar_event->m_peer = entity.first;
+        app.getServiceProvider().getTransactionLog()->write(*ar_event);
+    }
+
     // Shib 1.x requires a target value.
     if (relayState.empty())
         relayState = "default";
index 1f8dc0d..65ac383 100644 (file)
@@ -81,7 +81,7 @@ namespace shibsp {
     {
     public:
         SSCache(const DOMElement* e);
-        ~SSCache();
+        virtual ~SSCache();
 
 #ifndef SHIBSP_LITE
         void receive(DDF& in, ostream& out);
@@ -91,7 +91,28 @@ namespace shibsp {
             const HTTPRequest& httpRequest,
             HTTPResponse& httpResponse,
             time_t expires,
-            const saml2md::EntityDescriptor* issuer=nullptr,
+            const EntityDescriptor* issuer=nullptr,
+            const XMLCh* protocol=nullptr,
+            const saml2::NameID* nameid=nullptr,
+            const XMLCh* authn_instant=nullptr,
+            const XMLCh* session_index=nullptr,
+            const XMLCh* authncontext_class=nullptr,
+            const XMLCh* authncontext_decl=nullptr,
+            const vector<const Assertion*>* tokens=nullptr,
+            const vector<Attribute*>* attributes=nullptr
+            ) {
+            string dummy;
+            insert(dummy, app, httpRequest, httpResponse, expires, issuer, protocol, nameid,
+                    authn_instant, session_index, authncontext_class, authncontext_decl, tokens, attributes);
+        }
+
+        void insert(
+            string& sessionID,
+            const Application& app,
+            const HTTPRequest& httpRequest,
+            HTTPResponse& httpResponse,
+            time_t expires,
+            const EntityDescriptor* issuer=nullptr,
             const XMLCh* protocol=nullptr,
             const saml2::NameID* nameid=nullptr,
             const XMLCh* authn_instant=nullptr,
@@ -103,7 +124,7 @@ namespace shibsp {
             );
         vector<string>::size_type logout(
             const Application& app,
-            const saml2md::EntityDescriptor* issuer,
+            const EntityDescriptor* issuer,
             const saml2::NameID& nameid,
             const set<string>* indexes,
             time_t expires,
@@ -112,7 +133,7 @@ namespace shibsp {
         bool matches(
             const Application& app,
             const HTTPRequest& request,
-            const saml2md::EntityDescriptor* issuer,
+            const EntityDescriptor* issuer,
             const saml2::NameID& nameid,
             const set<string>* indexes
             );
@@ -180,6 +201,7 @@ namespace shibsp {
         // maintain back-mappings of NameID/SessionIndex -> session key
         void insert(const char* key, time_t expires, const char* name, const char* index);
         bool stronglyMatches(const XMLCh* idp, const XMLCh* sp, const saml2::NameID& n1, const saml2::NameID& n2) const;
+        LogoutEvent* newLogoutEvent(const Application& app) const;
 
         bool m_cacheAssertions;
 #endif
@@ -585,18 +607,6 @@ void StoredSession::addAttributes(const vector<Attribute*>& attributes)
         }
     } while (ver < 0);  // negative indicates a sync issue so we retry
 
-    TransactionLog* xlog = SPConfig::getConfig().getServiceProvider()->getTransactionLog();
-    Locker locker(xlog);
-    xlog->log.infoStream() <<
-        "Added the following attributes to session (ID: " <<
-            getID() <<
-        ") for (applicationId: " <<
-            m_obj["application_id"].string() <<
-        ") {";
-    for (vector<Attribute*>::const_iterator a=attributes.begin(); a!=attributes.end(); ++a)
-        xlog->log.infoStream() << "\t" << (*a)->getId() << " (" << (*a)->valueCount() << " values)";
-    xlog->log.info("}");
-
     // We own them now, so clean them up.
     for_each(attributes.begin(), attributes.end(), xmltooling::cleanup<Attribute>());
 }
@@ -720,13 +730,6 @@ void StoredSession::addAssertion(Assertion* assertion)
 
     m_ids.clear();
     delete assertion;
-
-    TransactionLog* xlog = SPConfig::getConfig().getServiceProvider()->getTransactionLog();
-    Locker locker(xlog);
-    xlog->log.info(
-        "Added assertion (ID: %s) to session for (applicationId: %s) with (ID: %s)",
-        id.get(), m_obj["application_id"].string(), getID()
-        );
 }
 
 #endif
@@ -739,6 +742,30 @@ SessionCache::~SessionCache()
 {
 }
 
+#ifndef SHIBSP_LITE
+
+void SessionCache::insert(
+    string& sessionID,
+    const Application& app,
+    const HTTPRequest& httpRequest,
+    HTTPResponse& httpResponse,
+    time_t expires,
+    const EntityDescriptor* issuer,
+    const XMLCh* protocol,
+    const saml2::NameID* nameid,
+    const XMLCh* authn_instant,
+    const XMLCh* session_index,
+    const XMLCh* authncontext_class,
+    const XMLCh* authncontext_decl,
+    const vector<const Assertion*>* tokens,
+    const vector<Attribute*>* attributes
+    ) {
+    return insert(app, httpRequest, httpResponse, expires, issuer, protocol, nameid,
+            authn_instant, session_index, authncontext_class, authncontext_decl, tokens, attributes);
+}
+
+#endif
+
 SessionCacheEx::SessionCacheEx()
 {
 }
@@ -922,6 +949,7 @@ void SSCache::insert(const char* key, time_t expires, const char* name, const ch
 }
 
 void SSCache::insert(
+    string& sessionID,
     const Application& app,
     const HTTPRequest& httpRequest,
     HTTPResponse& httpResponse,
@@ -1085,47 +1113,6 @@ void SSCache::insert(
     m_log.info("new session created: ID (%s) IdP (%s) Protocol(%s) Address (%s)",
         key.get(), pid ? pid : "none", prot ? prot : "none", httpRequest.getRemoteAddr().c_str());
 
-    // Transaction Logging
-    string primaryAssertionID("none");
-    if (m_cacheAssertions) {
-        if (tokens)
-            primaryAssertionID = obj["assertions"].first().string();
-    }
-    else if (tokens) {
-        auto_ptr_char tokenid(tokens->front()->getID());
-        primaryAssertionID = tokenid.get();
-    }
-    TransactionLog* xlog = app.getServiceProvider().getTransactionLog();
-    Locker locker(xlog);
-    xlog->log.infoStream() <<
-        "New session (ID: " <<
-            key.get() <<
-        ") with (applicationId: " <<
-            app.getId() <<
-        ") for principal from (IdP: " <<
-            (pid ? pid : "none") <<
-        ") at (ClientAddress: " <<
-            httpRequest.getRemoteAddr() <<
-        ") with (NameIdentifier: " <<
-            (nameid ? name.get() : "none") <<
-        ") using (Protocol: " <<
-            (prot ? prot : "none") <<
-        ") from (AssertionID: " <<
-            primaryAssertionID <<
-        ")";
-
-    if (attributes) {
-        xlog->log.infoStream() <<
-            "Cached the following attributes with session (ID: " <<
-                key.get() <<
-            ") for (applicationId: " <<
-                app.getId() <<
-            ") {";
-        for (vector<Attribute*>::const_iterator a=attributes->begin(); a!=attributes->end(); ++a)
-            xlog->log.infoStream() << "\t" << (*a)->getId() << " (" << (*a)->valueCount() << " values)";
-        xlog->log.info("}");
-    }
-
     if (!m_outboundHeader.empty())
         httpResponse.setResponseHeader(m_outboundHeader.c_str(), key.get());
 
@@ -1147,6 +1134,7 @@ void SSCache::insert(
     }
 
     httpResponse.setCookie(shib_cookie.first.c_str(), k.c_str());
+    sessionID = key.get();
 }
 
 bool SSCache::matches(
@@ -1371,6 +1359,28 @@ bool SSCache::stronglyMatches(const XMLCh* idp, const XMLCh* sp, const saml2::Na
     return true;
 }
 
+LogoutEvent* SSCache::newLogoutEvent(const Application& app) const
+{
+    if (!SPConfig::getConfig().isEnabled(SPConfig::Logging))
+        return nullptr;
+    try {
+        auto_ptr<TransactionLog::Event> event(SPConfig::getConfig().EventManager.newPlugin(LOGOUT_EVENT, nullptr));
+        LogoutEvent* logout_event = dynamic_cast<LogoutEvent*>(event.get());
+        if (logout_event) {
+            logout_event->m_app = &app;
+            event.release();
+            return logout_event;
+        }
+        else {
+            m_log.warn("unable to audit event, log event object was of an incorrect type");
+        }
+    }
+    catch (exception& ex) {
+        m_log.warn("exception auditing event: %s", ex.what());
+    }
+    return nullptr;
+}
+
 #endif
 
 Session* SSCache::find(const Application& app, const char* key, const char* client_addr, time_t* timeout)
@@ -1462,6 +1472,12 @@ Session* SSCache::find(const Application& app, const char* key, const char* clie
 
             if (timeout && *timeout > 0 && now - lastAccess >= *timeout) {
                 m_log.info("session timed out (ID: %s)", key);
+                auto_ptr<LogoutEvent> logout_event(newLogoutEvent(app));
+                if (logout_event.get()) {
+                    logout_event->m_logoutType = LogoutEvent::LOGOUT_EVENT_INVALID;
+                    logout_event->m_sessions.push_back(key);
+                    app.getServiceProvider().getTransactionLog()->write(*logout_event);
+                }
                 remove(app, key);
                 const char* eid = obj["entity_id"].string();
                 if (!eid) {
@@ -1520,6 +1536,15 @@ Session* SSCache::find(const Application& app, const char* key, const char* clie
         session->validate(app, client_addr, timeout);
     }
     catch (...) {
+#ifndef SHIBSP_LITE
+        auto_ptr<LogoutEvent> logout_event(newLogoutEvent(app));
+        if (logout_event.get()) {
+            logout_event->m_logoutType = LogoutEvent::LOGOUT_EVENT_INVALID;
+            logout_event->m_session = session;
+            logout_event->m_sessions.push_back(session->getID());
+            app.getServiceProvider().getTransactionLog()->write(*logout_event);
+        }
+#endif
         session->unlock();
         remove(app, key);
         throw;
@@ -1601,10 +1626,6 @@ void SSCache::remove(const Application& app, const char* key)
 #ifndef SHIBSP_LITE
         m_storage->deleteContext(key);
         m_log.info("removed session (%s)", key);
-
-        TransactionLog* xlog = app.getServiceProvider().getTransactionLog();
-        Locker locker(xlog);
-        xlog->log.info("Destroyed session (applicationId: %s) (ID: %s)", app.getId(), key);
 #else
         throw ConfigurationException("SessionCache removal requires a StorageService.");
 #endif
@@ -1770,6 +1791,12 @@ void SSCache::receive(DDF& in, ostream& out)
 
             if (timeout > 0 && now - lastAccess >= timeout) {
                 m_log.info("session timed out (ID: %s)", key);
+                auto_ptr<LogoutEvent> logout_event(newLogoutEvent(*app));
+                if (logout_event.get()) {
+                    logout_event->m_logoutType = LogoutEvent::LOGOUT_EVENT_INVALID;
+                    logout_event->m_sessions.push_back(key);
+                    app->getServiceProvider().getTransactionLog()->write(*logout_event);
+                }
                 remove(*app, key);
                 throw RetryableProfileException("Your session has expired, and you must re-authenticate.");
             }
diff --git a/shibsp/impl/TransactionLog.cpp b/shibsp/impl/TransactionLog.cpp
new file mode 100644 (file)
index 0000000..7a8799f
--- /dev/null
@@ -0,0 +1,926 @@
+/**
+ * Licensed to the University Corporation for Advanced Internet
+ * Development, Inc. (UCAID) under one or more contributor license
+ * agreements. See the NOTICE file distributed with this work for
+ * additional information regarding copyright ownership.
+ *
+ * UCAID licenses this file to you under the Apache License,
+ * Version 2.0 (the "License"); you may not use this file except
+ * in compliance with the License. You may obtain a copy of the
+ * License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND,
+ * either express or implied. See the License for the specific
+ * language governing permissions and limitations under the License.
+ */
+
+/**
+ * TransactionLog.cpp
+ *
+ * Formatted event record logging.
+ */
+
+#include "internal.h"
+
+#if defined(XMLTOOLING_LOG4SHIB)
+# ifndef SHIBSP_LOG4SHIB
+#  error "Logging library mismatch (XMLTooling is using log4shib)."
+# endif
+#elif defined(XMLTOOLING_LOG4CPP)
+# ifndef SHIBSP_LOG4CPP
+#  error "Logging library mismatch (XMLTooling is using log4cpp)."
+# endif
+#else
+# error "No supported logging library."
+#endif
+
+#include "Application.h"
+#include "SessionCache.h"
+#include "TransactionLog.h"
+#include "attribute/Attribute.h"
+
+#include <saml/saml1/core/Assertions.h>
+#include <saml/saml1/core/Protocols.h>
+#include <saml/saml2/core/Protocols.h>
+#include <saml/saml2/metadata/Metadata.h>
+#include <xmltooling/util/Threads.h>
+
+using namespace shibsp;
+using namespace opensaml::saml1;
+using namespace opensaml::saml2;
+using namespace opensaml;
+using namespace xmltooling;
+using namespace std;
+
+namespace shibsp {
+    TransactionLog::Event* SHIBSP_DLLLOCAL LoginEventFactory(void* const &)
+    {
+        return new LoginEvent();
+    }
+
+    TransactionLog::Event* SHIBSP_DLLLOCAL LogoutEventFactory(void* const &)
+    {
+        return new LogoutEvent();
+    }
+
+    TransactionLog::Event* SHIBSP_DLLLOCAL AuthnRequestEventFactory(void* const &)
+    {
+        return new AuthnRequestEvent();
+    }
+};
+
+void SHIBSP_API shibsp::registerEvents()
+{
+    SPConfig& conf=SPConfig::getConfig();
+    conf.EventManager.registerFactory(LOGIN_EVENT, LoginEventFactory);
+    conf.EventManager.registerFactory(LOGOUT_EVENT, LogoutEventFactory);
+    conf.EventManager.registerFactory(AUTHNREQUEST_EVENT, AuthnRequestEventFactory);
+}
+
+TransactionLog::TransactionLog(const char* fmt, const char* absent)
+    : log(logging::Category::getInstance(SHIBSP_TX_LOGCAT)), m_lock(Mutex::create()), m_absent(absent ? absent : "")
+{
+    // Split the formatting string into named '%' parameter tokens, and "other stuff" to be echoed
+    // literally in log messages.
+
+    bool in_token = false;
+    m_formatting.push_back(string());
+    vector<string>::iterator field = m_formatting.begin();
+    while (fmt && *fmt) {
+        if (in_token) {
+            if (!isalnum(*fmt) && *fmt != '-' && *fmt != '%') {
+                m_formatting.push_back(string());
+                field = m_formatting.begin() + m_formatting.size() - 1;
+                in_token = false;
+            }
+        }
+        else if (*fmt == '%') {
+            if (!field->empty()) {
+                m_formatting.push_back(string());
+                field = m_formatting.begin() + m_formatting.size() - 1;
+            }
+            in_token = true;
+        }
+        *field += *fmt++;
+    }
+    if (!m_formatting.empty() && m_formatting.back().empty())
+        m_formatting.pop_back();
+}
+
+TransactionLog::~TransactionLog()
+{
+    delete m_lock;
+}
+
+Lockable* TransactionLog::lock()
+{
+    m_lock->lock();
+    return this;
+}
+
+void TransactionLog::unlock()
+{
+    m_lock->unlock();
+}
+
+void TransactionLog::write(const TransactionLog::Event& e)
+{
+    if (m_formatting.empty()) {
+        // For compatibility, we support the old transaction log format, ugly though it may be.
+        // The session log line would be easy to emulate, but the old attribute logging isn't
+        // easy to represent with a formatting string.
+
+        ostringstream os;
+
+        const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
+        if (login) {
+            os << "New session (ID: ";
+            login->write(os, "%s", nullptr);
+            os << ") with (applicationId: ";
+            login->write(os, "%app", nullptr);
+            os << ") for principal from (IdP: ";
+            login->write(os, "%IDP", "none");
+            os << ") at (ClientAddress: ";
+            login->write(os, "%a", nullptr);
+            os << ") with (NameIdentifier: ";
+            login->write(os, "%n", "none");
+            os << ") using (Protocol: ";
+            login->write(os, "%p", "none");
+            os << ") from (AssertionID: ";
+            login->write(os, "%i", nullptr);
+            os << ")";
+
+            Locker locker(this);
+            log.info(os.str());
+            os.str("");
+
+            os << "Cached the following attributes with session (ID: ";
+            login->write(os, "%s", nullptr);
+            os << ") for (applicationId: ";
+            login->write(os, "%app", nullptr);
+            os << ") {";
+            log.info(os.str());
+
+            if (login->m_attributes) {
+                for (vector<Attribute*>::const_iterator a=login->m_attributes->begin(); a != login->m_attributes->end(); ++a)
+                    log.infoStream() << "\t" << (*a)->getId() << " (" << (*a)->valueCount() << " values)";
+            }
+
+            log.info("}");
+            return;
+        }
+
+        const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
+        if (logout && (logout->m_sessionID || logout->m_session || !logout->m_sessions.empty())) {
+            os << "Destroyed session (applicationId: ";
+            logout->write(os, "%app", nullptr);
+            os << ") (ID: ";
+            logout->write(os, "%s", nullptr);
+            os << ")";
+            log.info(os.str());
+            return;
+        }
+    }
+    else {
+        ostringstream os;
+        for (vector<string>::const_iterator i = m_formatting.begin(); i != m_formatting.end() && !i->empty(); ++i) {
+            if ((*i)[0] != '%' || !e.write(os, i->c_str(), m_absent.c_str())) {
+                os << *i;
+            }
+        }
+        Category::getInstance(string(SHIBSP_TX_LOGCAT) + "." + e.getType()).info(os.str());
+    }
+}
+
+namespace {
+    bool _URL(const TransactionLog::Event& e, ostream& os) {
+        const HTTPRequest* http = dynamic_cast<const HTTPRequest*>(e.m_request);
+        if (http) {
+            os << http->getRequestURL();
+            return true;
+        }
+        return false;
+    }
+
+    bool _URI(const TransactionLog::Event& e, ostream& os) {
+        const HTTPRequest* http = dynamic_cast<const HTTPRequest*>(e.m_request);
+        if (http) {
+            os << http->getRequestURI();
+            return true;
+        }
+        return false;
+    }
+
+    bool _Header(const TransactionLog::Event& e, ostream& os, const char* name) {
+        const HTTPRequest* http = dynamic_cast<const HTTPRequest*>(e.m_request);
+        if (http) {
+            string s = http->getHeader(name);
+            if (!s.empty()) {
+                os << s;
+                return true;
+            }
+        }
+        return false;
+    }
+
+    bool _ExceptionMessage(const TransactionLog::Event& e, ostream& os) {
+        if (e.m_exception && e.m_exception->what()) {
+            os << e.m_exception->what();
+            return true;
+        }
+        return false;
+    }
+
+    bool _ExceptionType(const TransactionLog::Event& e, ostream& os) {
+        const XMLToolingException* x = dynamic_cast<const XMLToolingException*>(e.m_exception);
+        if (x) {
+            os << x->getClassName();
+            return true;
+        }
+        return false;
+    }
+
+    bool _AssertionID(const TransactionLog::Event& e, ostream& os) {
+        const XMLCh* id = nullptr;
+        const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
+        if (login) {
+            if (login->m_saml2AuthnStatement) {
+                const saml2::Assertion* a = dynamic_cast<const saml2::Assertion*>(login->m_saml2AuthnStatement->getParent());
+                if (a)
+                    id = a->getID();
+            }
+            else if (login->m_saml1AuthnStatement) {
+                const saml1::Assertion* a = dynamic_cast<const saml1::Assertion*>(login->m_saml1AuthnStatement->getParent());
+                if (a)
+                    id = a->getAssertionID();
+            }
+        }
+        if (id && *id) {
+            auto_ptr_char temp(id);
+            os << temp.get();
+            return true;
+        }
+        return false;
+    }
+
+    bool _ProtocolID(const TransactionLog::Event& e, ostream& os) {
+        const XMLCh* id = nullptr;
+        const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
+        if (login) {
+            if (login->m_saml2Response)
+                id = login->m_saml2Response->getID();
+            else if (login->m_saml1Response)
+                id = login->m_saml1Response->getResponseID();
+        }
+        else {
+            const AuthnRequestEvent* request = dynamic_cast<const AuthnRequestEvent*>(&e);
+            if (request) {
+                if (request->m_saml2Request)
+                    id = request->m_saml2Request->getID();
+            }
+            else {
+                const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
+                if (logout) {
+                    if (logout->m_saml2Request)
+                        id = logout->m_saml2Request->getID();
+                    else if (logout->m_saml2Response)
+                        id = logout->m_saml2Response->getID();
+                }
+            }
+        }
+        if (id && *id) {
+            auto_ptr_char temp(id);
+            os << temp.get();
+            return true;
+        }
+        return false;
+    }
+
+    bool _InResponseTo(const TransactionLog::Event& e, ostream& os) {
+        const XMLCh* id = nullptr;
+        const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
+        if (login) {
+            if (login->m_saml2Response)
+                id = login->m_saml2Response->getInResponseTo();
+            else if (login->m_saml1Response)
+                id = login->m_saml1Response->getInResponseTo();
+        }
+        else {
+            const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
+            if (logout && logout->m_saml2Response) {
+                id = logout->m_saml2Response->getInResponseTo();
+            }
+        }
+        if (id && *id) {
+            auto_ptr_char temp(id);
+            os << temp.get();
+            return true;
+        }
+        return false;
+    }
+
+    bool _StatusCode(const TransactionLog::Event& e, ostream& os) {
+        const saml1p::Status* s1 = nullptr;
+        const saml2p::Status* s2 = nullptr;
+        const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
+        if (login) {
+            if (login->m_saml2Response)
+                s2 = login->m_saml2Response->getStatus();
+            else if (login->m_saml1Response)
+                s1 = login->m_saml1Response->getStatus();
+        }
+        else {
+            const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
+            if (logout && logout->m_saml2Response)
+                s2 = logout->m_saml2Response->getStatus();
+        }
+
+        if (s2 && s2->getStatusCode() && s2->getStatusCode()->getValue()) {
+            auto_ptr_char temp(s2->getStatusCode()->getValue());
+            if (temp.get() && *temp.get()) {
+                os << temp.get();
+                return true;
+            }
+        }
+        else if (s1 && s1->getStatusCode() && s1->getStatusCode()->getValue()) {
+            os << s1->getStatusCode()->getValue()->toString();
+            return true;
+        }
+
+        const XMLToolingException* x = dynamic_cast<const XMLToolingException*>(e.m_exception);
+        if (x) {
+            const char* s = x->getProperty("statusCode");
+            if (s && *s) {
+                os << s;
+                return true;
+            }
+        }
+        return false;
+    }
+
+    bool _SubStatusCode(const TransactionLog::Event& e, ostream& os) {
+        const saml1p::Status* s1 = nullptr;
+        const saml2p::Status* s2 = nullptr;
+        const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
+        if (login) {
+            if (login->m_saml2Response)
+                s2 = login->m_saml2Response->getStatus();
+            else if (login->m_saml1Response)
+                s1 = login->m_saml1Response->getStatus();
+        }
+        else {
+            const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
+            if (logout && logout->m_saml2Response)
+                s2 = logout->m_saml2Response->getStatus();
+        }
+
+        if (s2 && s2->getStatusCode() && s2->getStatusCode()->getStatusCode()) {
+            auto_ptr_char temp(s2->getStatusCode()->getStatusCode()->getValue());
+            if (temp.get() && *temp.get()) {
+                os << temp.get();
+                return true;
+            }
+        }
+        else if (s1 && s1->getStatusCode() && s1->getStatusCode()->getStatusCode()) {
+            if (s1->getStatusCode()->getStatusCode()->getValue()) {
+                os << s1->getStatusCode()->getValue()->toString();
+                return true;
+            }
+        }
+
+        const XMLToolingException* x = dynamic_cast<const XMLToolingException*>(e.m_exception);
+        if (x) {
+            const char* s = x->getProperty("statusCode2");
+            if (s && *s) {
+                os << s;
+                return true;
+            }
+        }
+        return false;
+    }
+
+    bool _StatusMessage(const TransactionLog::Event& e, ostream& os) {
+        const XMLCh* msg = nullptr;
+        const saml1p::Status* s1 = nullptr;
+        const saml2p::Status* s2 = nullptr;
+        const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
+        if (login) {
+            if (login->m_saml2Response)
+                s2 = login->m_saml2Response->getStatus();
+            else if (login->m_saml1Response)
+                s1 = login->m_saml1Response->getStatus();
+        }
+        else {
+            const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
+            if (logout && logout->m_saml2Response)
+                s2 = logout->m_saml2Response->getStatus();
+        }
+
+        if (s2 && s2->getStatusMessage())
+            msg = s2->getStatusMessage()->getMessage();
+        else if (s1 && s1->getStatusMessage())
+            msg = s1->getStatusMessage()->getMessage();
+
+        if (msg) {
+            auto_ptr_char temp(msg);
+            if (temp.get() && *temp.get()) {
+                os << temp.get();
+                return true;
+            }
+        }
+        else {
+            const XMLToolingException* x = dynamic_cast<const XMLToolingException*>(e.m_exception);
+            if (x) {
+                const char* s = x->getProperty("statusMessage");
+                if (s && *s) {
+                    os << s;
+                    return true;
+                }
+            }
+        }
+
+        return false;
+    }
+
+    bool _AssertionIssueInstant(const TransactionLog::Event& e, ostream& os) {
+        time_t t = 0;
+        const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
+        if (login) {
+            if (login->m_saml2AuthnStatement) {
+                const saml2::Assertion* a = dynamic_cast<const saml2::Assertion*>(login->m_saml2AuthnStatement->getParent());
+                if (a && a->getIssueInstant())
+                    t = a->getIssueInstantEpoch();
+            }
+            else if (login->m_saml1AuthnStatement) {
+                const saml1::Assertion* a = dynamic_cast<const saml1::Assertion*>(login->m_saml1AuthnStatement->getParent());
+                if (a && a->getIssueInstant())
+                    t = a->getIssueInstantEpoch();
+            }
+        }
+        if (t == 0)
+            return false;
+#ifndef HAVE_GMTIME_R
+        struct tm* ptime=localtime(&t);
+#else
+        struct tm res;
+        struct tm* ptime=localtime_r(&t, &res);
+#endif
+        char timebuf[32];
+        strftime(timebuf,32,"%Y-%m-%dT%H:%M:%S",ptime);
+        os << timebuf;
+        return true;
+    }
+
+    bool _ProtocolIssueInstant(const TransactionLog::Event& e, ostream& os) {
+        time_t t = 0;
+        const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
+        if (login) {
+            if (login->m_saml2Response && login->m_saml2Response->getIssueInstant())
+                t = login->m_saml2Response->getIssueInstantEpoch();
+            else if (login->m_saml1Response && login->m_saml1Response->getIssueInstant())
+                t = login->m_saml1Response->getIssueInstantEpoch();
+        }
+        else {
+            const AuthnRequestEvent* request = dynamic_cast<const AuthnRequestEvent*>(&e);
+            if (request) {
+                if (request->m_saml2Request && request->m_saml2Request->getIssueInstant())
+                    t = request->m_saml2Request->getIssueInstantEpoch();
+            }
+            else {
+                const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
+                if (logout) {
+                    if (logout->m_saml2Request && logout->m_saml2Request->getIssueInstant())
+                        t = logout->m_saml2Request->getIssueInstantEpoch();
+                    else if (logout->m_saml2Response && logout->m_saml2Response->getIssueInstant())
+                        t = logout->m_saml2Response->getIssueInstantEpoch();
+                }
+            }
+        }
+        if (t == 0)
+            return false;
+#ifndef HAVE_GMTIME_R
+        struct tm* ptime=localtime(&t);
+#else
+        struct tm res;
+        struct tm* ptime=localtime_r(&t, &res);
+#endif
+        char timebuf[32];
+        strftime(timebuf,32,"%Y-%m-%dT%H:%M:%S",ptime);
+        os << timebuf;
+        return true;
+    }
+
+    bool _AuthnInstant(const TransactionLog::Event& e, ostream& os) {
+        time_t t = 0;
+        const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
+        if (login) {
+            if (login->m_saml2AuthnStatement && login->m_saml2AuthnStatement->getAuthnInstant())
+                t = login->m_saml2AuthnStatement->getAuthnInstantEpoch();
+            else if (login->m_saml1AuthnStatement && login->m_saml1AuthnStatement->getAuthenticationInstant())
+                t = login->m_saml1AuthnStatement->getAuthenticationInstantEpoch();
+        }
+        if (t == 0)
+            return false;
+#ifndef HAVE_GMTIME_R
+        struct tm* ptime=localtime(&t);
+#else
+        struct tm res;
+        struct tm* ptime=localtime_r(&t, &res);
+#endif
+        char timebuf[32];
+        strftime(timebuf,32,"%Y-%m-%dT%H:%M:%S",ptime);
+        os << timebuf;
+        return true;
+    }
+
+    bool _SessionIndex(const TransactionLog::Event& e, ostream& os) {
+        const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
+        if (login) {
+            if (login->m_saml2AuthnStatement && login->m_saml2AuthnStatement->getSessionIndex()) {
+                auto_ptr_char ix(login->m_saml2AuthnStatement->getSessionIndex());
+                if (ix.get() && *ix.get()) {
+                    os << ix.get();
+                    return true;
+                }
+            }
+        }
+        else {
+            const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
+            if (logout && logout->m_saml2Request && !logout->m_saml2Request->getSessionIndexs().empty()) {
+                const vector<saml2p::SessionIndex*>& indexes = logout->m_saml2Request->getSessionIndexs();
+                for (vector<saml2p::SessionIndex*>::const_iterator i = indexes.begin(); i != indexes.end(); ++i) {
+                    auto_ptr_char ix((*i)->getSessionIndex());
+                    if (ix.get() && *ix.get()) {
+                        if (i != indexes.begin())
+                            os << ',';
+                        os << ix.get();
+                    }
+                }
+                return true;
+            }
+        }
+        return false;
+    }
+
+    bool _SessionID(const TransactionLog::Event& e, ostream& os) {
+        const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
+        if (logout) {
+            if (!logout->m_sessions.empty()) {
+                for (vector<string>::const_iterator s = logout->m_sessions.begin(); s != logout->m_sessions.end(); ++s) {
+                    if (s != logout->m_sessions.begin())
+                        os << ',';
+                    os << *s;
+                }
+                return true;
+            }
+            else if (logout->m_session) {
+                os << logout->m_session->getID();
+                return true;
+            }
+        }
+        else if (e.m_sessionID) {
+            os << e.m_sessionID;
+            return true;
+        }
+        return false;
+    }
+
+    bool _REMOTE_USER(const TransactionLog::Event& e, ostream& os) {
+        const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
+        const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
+        if (e.m_app && ((login && login->m_attributes) || (logout && logout->m_session))) {
+            const vector<string>& ids = e.m_app->getRemoteUserAttributeIds();
+            const vector<shibsp::Attribute*>& attrs = (login ? *login->m_attributes : logout->m_session->getAttributes());
+            for (vector<string>::const_iterator id = ids.begin(); id != ids.end(); ++id) {
+                for (vector<shibsp::Attribute*>::const_iterator a = attrs.begin(); a != attrs.end(); ++a) {
+                    if (*id == (*a)->getId() && (*a)->valueCount() > 0) {
+                        os << (*a)->getSerializedValues().front();
+                        return true;
+                    }
+                }
+            }
+        }
+        return false;
+    }
+
+    bool _REMOTE_ADDR(const TransactionLog::Event& e, ostream& os) {
+        if (e.m_request) {
+            string s = e.m_request->getRemoteAddr();
+            if (!s.empty()) {
+                os << s;
+                return true;
+            }
+        }
+        return false;
+    }
+
+    bool _AuthnContext(const TransactionLog::Event& e, ostream& os) {
+        const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
+        if (login) {
+            if (login->m_saml2AuthnStatement && login->m_saml2AuthnStatement->getAuthnContext()) {
+                const AuthnContext* ctx = login->m_saml2AuthnStatement->getAuthnContext();
+                if (ctx->getAuthnContextClassRef()) {
+                    auto_ptr_char ref(ctx->getAuthnContextClassRef()->getReference());
+                    if (ref.get()) {
+                        os << ref.get();
+                        return true;
+                    }
+                }
+                else if (ctx->getAuthnContextDeclRef()) {
+                    auto_ptr_char ref(ctx->getAuthnContextDeclRef()->getReference());
+                    if (ref.get()) {
+                        os << ref.get();
+                        return true;
+                    }
+                }
+                else if (ctx->getAuthnContextDecl()) {
+                    os << "(full declaration)";
+                    return true;
+                }
+            }
+            else if (login->m_saml1AuthnStatement && login->m_saml1AuthnStatement->getAuthenticationMethod()) {
+                auto_ptr_char ac(login->m_saml1AuthnStatement->getAuthenticationMethod());
+                if (ac.get()) {
+                    os << ac.get();
+                    return true;
+                }
+            }
+        }
+        return false;
+    }
+
+    bool _UserAgent(const TransactionLog::Event& e, ostream& os) {
+        return _Header(e, os, "User-Agent");
+    }
+
+    bool _ApplicationID(const TransactionLog::Event& e, ostream& os) {
+        if (e.m_app) {
+            os << e.m_app->getId();
+            return true;
+        }
+        return false;
+    }
+
+    bool _SP_(const TransactionLog::Event& e, ostream& os) {
+        if (e.m_app) {
+            const PropertySet* props = e.m_app->getRelyingParty(e.m_peer);
+            if (props) {
+                pair<bool,const char*> entityid = props->getString("entityID");
+                if (entityid.first) {
+                    os << entityid.second;
+                    return true;
+                }
+            }
+        }
+        return false;
+    }
+
+    bool _IDP(const TransactionLog::Event& e, ostream& os) {
+        if (e.m_peer) {
+            auto_ptr_char entityid(e.m_peer->getEntityID());
+            if (entityid.get()) {
+                os << entityid.get();
+                return true;
+            }
+        }
+        
+        const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
+        if (logout && logout->m_session) {
+            os << logout->m_session->getEntityID();
+            return true;
+        }
+
+        return false;
+    }
+
+    bool _Protocol(const TransactionLog::Event& e, ostream& os) {
+        if (e.m_protocol) {
+            os << e.m_protocol;
+            return true;
+        }
+        return false;
+    }
+
+    bool _Binding(const TransactionLog::Event& e, ostream& os) {
+        if (e.m_binding) {
+            os << e.m_binding;
+            return true;
+        }
+        return false;
+    }
+
+    bool _NameID(const TransactionLog::Event& e, ostream& os) {
+        if (e.m_nameID && e.m_nameID->getName()) {
+            auto_ptr_char temp(e.m_nameID->getName());
+            if (temp.get() && *temp.get()) {
+                os << temp.get();
+                return true;
+            }
+        }
+        else {
+            const AuthnRequestEvent* request = dynamic_cast<const AuthnRequestEvent*>(&e);
+            if (request) {
+                if (request->m_saml2Request && request->m_saml2Request->getSubject()) {
+                    const saml2::NameID* n = request->m_saml2Request->getSubject()->getNameID();
+                    if (n) {
+                        auto_ptr_char temp(n->getName());
+                        if (temp.get() && *temp.get()) {
+                            os << temp.get();
+                            return true;
+                        }
+                    }
+                }
+            }
+            else {
+                const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
+                if (logout) {
+                    const saml2::NameID* n = nullptr;
+                    if (logout->m_session)
+                        n = logout->m_session->getNameID();
+                    else if (logout->m_saml2Request)
+                        n = logout->m_saml2Request->getNameID();
+                    if (n) {
+                        auto_ptr_char temp(n->getName());
+                        if (temp.get() && *temp.get()) {
+                            os << temp.get();
+                            return true;
+                        }
+                    }
+                }
+            }
+        }
+        return false;
+    }
+
+    bool _Attributes(const TransactionLog::Event& e, ostream& os) {
+        const vector<shibsp::Attribute*>* attrs = nullptr;
+        const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
+        if (login) {
+            attrs = login->m_attributes;
+        }
+        else {
+            const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
+            if (logout && logout->m_session)
+                attrs = &logout->m_session->getAttributes();
+        }
+        if (attrs && !attrs->empty()) {
+            map<string,size_t> valcounts;
+            for (vector<shibsp::Attribute*>::const_iterator a = attrs->begin(); a != attrs->end(); ++a) {
+                valcounts[(*a)->getId()] += (*a)->valueCount();
+            }
+            for (map<string,size_t>::const_iterator c = valcounts.begin(); c != valcounts.end(); ++c) {
+                if (c != valcounts.begin())
+                    os << ',';
+                os << c->first << '(' << c->second << ')';
+            }
+            return true;
+        }
+        return false;
+    }
+
+    bool _Logout(const TransactionLog::Event& e, ostream& os) {
+        const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
+        if (logout) {
+            switch (logout->m_logoutType) {
+                case LogoutEvent::LOGOUT_EVENT_INVALID:
+                    os << "invalid";
+                    return true;
+                case LogoutEvent::LOGOUT_EVENT_LOCAL:
+                    os << "local";
+                    return true;
+                case LogoutEvent::LOGOUT_EVENT_GLOBAL:
+                    os << "global";
+                    return true;
+                case LogoutEvent::LOGOUT_EVENT_PARTIAL:
+                    os << "partial";
+                    return true;
+            }
+        }
+        return false;
+    }
+};
+
+TransactionLog::Event::Event()
+    : m_exception(nullptr),
+      m_request(nullptr),
+      m_app(nullptr),
+      m_sessionID(nullptr),
+      m_peer(nullptr),
+      m_protocol(nullptr),
+      m_binding(nullptr),
+      m_nameID(nullptr)
+{
+    m_handlers["e"] = _ExceptionMessage;
+    m_handlers["E"] = _ExceptionType;
+    m_handlers["S"] = _StatusCode;
+    m_handlers["SS"] = _SubStatusCode;
+    m_handlers["SM"] = _StatusMessage;
+    m_handlers["URL"] = _URL;
+    m_handlers["URI"] = _URI;
+    m_handlers["s"] = _SessionID;
+    m_handlers["a"] = _REMOTE_ADDR;
+    m_handlers["UA"] = _UserAgent;
+    m_handlers["app"] = _ApplicationID;
+    m_handlers["SP"] = _SP_;
+    m_handlers["IDP"] = _IDP;
+    m_handlers["p"] = _Protocol;
+    m_handlers["b"] = _Binding;
+    m_handlers["n"] = _NameID;
+}
+
+TransactionLog::Event::~Event()
+{
+}
+
+bool TransactionLog::Event::write(ostream& out, const char* field, const char* absent) const
+{
+    if (!field || *field++ != '%') {
+        return false;
+    }
+    
+    if (*field == '%' || *field == '\0') {
+        out << '%';
+    }
+    else {
+        map<string,handler_fn>::const_iterator h = m_handlers.find(field);
+        if ((h != m_handlers.end() && !h->second(*this, out)) || (h == m_handlers.end() && !_Header(*this, out, field))) {
+            if (absent)
+                out << absent;
+        }
+    }
+    return true;
+}
+
+LoginEvent::LoginEvent()
+    : m_saml2AuthnStatement(nullptr),
+      m_saml2Response(nullptr),
+      m_saml1AuthnStatement(nullptr),
+      m_saml1Response(nullptr),
+      m_attributes(nullptr)
+{
+    m_handlers["u"] = _REMOTE_USER;
+    m_handlers["i"] = _AssertionID;
+    m_handlers["I"] = _ProtocolID;
+    m_handlers["II"] = _InResponseTo;
+    m_handlers["d"] = _AssertionIssueInstant;
+    m_handlers["D"] = _ProtocolIssueInstant;
+    m_handlers["t"] = _AuthnInstant;
+    m_handlers["x"] = _SessionIndex;
+    m_handlers["ac"] = _AuthnContext;
+    m_handlers["attr"] = _Attributes;
+}
+
+const char* LoginEvent::getType() const
+{
+    return "Login";
+}
+
+LoginEvent::~LoginEvent()
+{
+}
+
+LogoutEvent::LogoutEvent()
+    : m_logoutType(LOGOUT_EVENT_UNKNOWN),
+      m_saml2Request(nullptr),
+      m_saml2Response(nullptr),
+      m_session(nullptr)
+{
+    m_handlers["L"] = _Logout;
+    m_handlers["u"] = _REMOTE_USER;
+    m_handlers["I"] = _ProtocolID;
+    m_handlers["II"] = _InResponseTo;
+    m_handlers["D"] = _ProtocolIssueInstant;
+    m_handlers["x"] = _SessionIndex;
+}
+
+LogoutEvent::~LogoutEvent()
+{
+}
+
+const char* LogoutEvent::getType() const
+{
+    if (m_saml2Request)
+        return "Logout.Request";
+    else if (m_saml2Response)
+        return "Logout.Response";
+    return "Logout";
+}
+
+AuthnRequestEvent::AuthnRequestEvent() : m_saml2Request(nullptr)
+{
+    m_handlers["I"] = _ProtocolID;
+    m_handlers["D"] = _ProtocolIssueInstant;
+}
+
+AuthnRequestEvent::~AuthnRequestEvent()
+{
+}
+
+const char* AuthnRequestEvent::getType() const
+{
+    return "AuthnRequest";
+}
index b4a4628..fbf6e43 100644 (file)
@@ -60,7 +60,6 @@
 #include <xmltooling/util/XMLHelper.h>
 
 #ifndef SHIBSP_LITE
-# include "TransactionLog.h"
 # include "attribute/filtering/AttributeFilter.h"
 # include "attribute/resolver/AttributeExtractor.h"
 # include "attribute/resolver/AttributeResolver.h"
@@ -281,6 +280,7 @@ namespace {
         RequestMapper* m_requestMapper;
         map<string,Application*> m_appmap;
 #ifndef SHIBSP_LITE
+        TransactionLog* m_tranLog;
         SecurityPolicyProvider* m_policy;
         vector< pair< string, pair<string,string> > > m_transportOptions;
 #endif
@@ -313,11 +313,7 @@ namespace {
     {
     public:
         XMLConfig(const DOMElement* e) : ReloadableXMLFile(e, Category::getInstance(SHIBSP_LOGCAT".Config")),
-            m_impl(nullptr), m_listener(nullptr), m_sessionCache(nullptr)
-#ifndef SHIBSP_LITE
-            , m_tranLog(nullptr)
-#endif
-        {
+            m_impl(nullptr), m_listener(nullptr), m_sessionCache(nullptr) {
         }
 
         void init() {
@@ -330,7 +326,6 @@ namespace {
             delete m_sessionCache;
             delete m_listener;
 #ifndef SHIBSP_LITE
-            delete m_tranLog;
             SAMLConfig::getConfig().setArtifactMap(nullptr);
             XMLToolingConfig::getConfig().setReplayCache(nullptr);
             for_each(m_storage.begin(), m_storage.end(), cleanup_pair<string,StorageService>());
@@ -370,8 +365,8 @@ namespace {
         void receive(DDF& in, ostream& out);
 
         TransactionLog* getTransactionLog() const {
-            if (m_tranLog)
-                return m_tranLog;
+            if (m_impl->m_tranLog)
+                return m_impl->m_tranLog;
             throw ConfigurationException("No TransactionLog available.");
         }
 
@@ -447,7 +442,6 @@ namespace {
         ListenerService* m_listener;
         SessionCache* m_sessionCache;
 #ifndef SHIBSP_LITE
-        TransactionLog* m_tranLog;
         map<string,StorageService*> m_storage;
 #endif
     };
@@ -504,6 +498,8 @@ namespace {
     static const XMLCh SSO[] =                  UNICODE_LITERAL_3(S,S,O);
     static const XMLCh _StorageService[] =      UNICODE_LITERAL_14(S,t,o,r,a,g,e,S,e,r,v,i,c,e);
     static const XMLCh TCPListener[] =          UNICODE_LITERAL_11(T,C,P,L,i,s,t,e,n,e,r);
+    static const XMLCh tranLogFiller[] =        UNICODE_LITERAL_13(t,r,a,n,L,o,g,F,i,l,l,e,r);
+    static const XMLCh tranLogFormat[] =        UNICODE_LITERAL_13(t,r,a,n,L,o,g,F,o,r,m,a,t);
     static const XMLCh TransportOption[] =      UNICODE_LITERAL_15(T,r,a,n,s,p,o,r,t,O,p,t,i,o,n);
     static const XMLCh _TrustEngine[] =         UNICODE_LITERAL_11(T,r,u,s,t,E,n,g,i,n,e);
     static const XMLCh _type[] =                UNICODE_LITERAL_4(t,y,p,e);
@@ -746,27 +742,27 @@ void XMLApplication::doAttributeInfo()
         }
     }
 
+    pair<bool,const char*> attributes = getString("REMOTE_USER");
+    if (attributes.first) {
+        char* dup = strdup(attributes.second);
+        char* pos;
+        char* start = dup;
+        while (start && *start) {
+            while (*start && isspace(*start))
+                start++;
+            if (!*start)
+                break;
+            pos = strchr(start,' ');
+            if (pos)
+                *pos=0;
+            m_remoteUsers.push_back(start);
+            start = pos ? pos+1 : nullptr;
+        }
+        free(dup);
+    }
+
     // Load attribute ID lists for REMOTE_USER and header clearing.
     if (SPConfig::getConfig().isEnabled(SPConfig::InProcess)) {
-        pair<bool,const char*> attributes = getString("REMOTE_USER");
-        if (attributes.first) {
-            char* dup = strdup(attributes.second);
-            char* pos;
-            char* start = dup;
-            while (start && *start) {
-                while (*start && isspace(*start))
-                    start++;
-                if (!*start)
-                    break;
-                pos = strchr(start,' ');
-                if (pos)
-                    *pos=0;
-                m_remoteUsers.push_back(start);
-                start = pos ? pos+1 : nullptr;
-            }
-            free(dup);
-        }
-
         attributes = getString("unsetHeaders");
         if (attributes.first) {
             string transformedprefix(m_attributePrefix.second);
@@ -1847,6 +1843,7 @@ void XMLConfigImpl::doCaching(const DOMElement* e, XMLConfig* conf, Category& lo
 XMLConfigImpl::XMLConfigImpl(const DOMElement* e, bool first, XMLConfig* outer, Category& log)
     : m_requestMapper(nullptr),
 #ifndef SHIBSP_LITE
+        m_tranLog(nullptr),
         m_policy(nullptr),
 #endif
         m_document(nullptr)
@@ -1886,8 +1883,10 @@ XMLConfigImpl::XMLConfigImpl(const DOMElement* e, bool first, XMLConfig* outer,
             }
 
 #ifndef SHIBSP_LITE
-            if (first)
-                outer->m_tranLog = new TransactionLog();
+            m_tranLog = new TransactionLog(
+                XMLHelper::getAttrString(SHAR, nullptr, tranLogFormat).c_str(),
+                XMLHelper::getAttrString(SHAR, nullptr, tranLogFiller).c_str()
+                );
 #endif
         }
 
@@ -2123,6 +2122,8 @@ void XMLConfigImpl::cleanup()
 #ifndef SHIBSP_LITE
     delete m_policy;
     m_policy = nullptr;
+    delete m_tranLog;
+    m_tranLog = nullptr;
 #endif
     delete m_requestMapper;
     m_requestMapper = nullptr;
index 0912a36..20fe70e 100644 (file)
     <ClCompile Include="remoting\impl\TCPListener.cpp" />\r
     <ClCompile Include="impl\ChainingAccessControl.cpp" />\r
     <ClCompile Include="impl\StorageServiceSessionCache.cpp" />\r
+    <ClCompile Include="impl\TransactionLog.cpp" />\r
     <ClCompile Include="impl\XMLAccessControl.cpp" />\r
     <ClCompile Include="impl\XMLRequestMapper.cpp" />\r
     <ClCompile Include="impl\XMLServiceProvider.cpp" />\r
index 0b2f624..8ffb26b 100644 (file)
     <ClCompile Include="impl\StorageServiceSessionCache.cpp">\r
       <Filter>Source Files\impl</Filter>\r
     </ClCompile>\r
+    <ClCompile Include="impl\TransactionLog.cpp">\r
+      <Filter>Source Files\impl</Filter>\r
+    </ClCompile>\r
     <ClCompile Include="impl\XMLAccessControl.cpp">\r
       <Filter>Source Files\impl</Filter>\r
     </ClCompile>\r