shibsp/impl/TransactionLog.cpp

   1 /**
   2  * Licensed to the University Corporation for Advanced Internet
   3  * Development, Inc. (UCAID) under one or more contributor license
   4  * agreements. See the NOTICE file distributed with this work for
   5  * additional information regarding copyright ownership.
   6  *
   7  * UCAID licenses this file to you under the Apache License,
   8  * Version 2.0 (the "License"); you may not use this file except
   9  * in compliance with the License. You may obtain a copy of the
  10  * License at
  11  *
  12  * http://www.apache.org/licenses/LICENSE-2.0
  13  *
  14  * Unless required by applicable law or agreed to in writing,
  15  * software distributed under the License is distributed on an
  16  * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND,
  17  * either express or implied. See the License for the specific
  18  * language governing permissions and limitations under the License.
  19  */
  20
  21 /**
  22  * TransactionLog.cpp
  23  *
  24  * Formatted event record logging.
  25  */
  26
  27 #include "internal.h"
  28
  29 #if defined(XMLTOOLING_LOG4SHIB)
  30 # ifndef SHIBSP_LOG4SHIB
  31 #  error "Logging library mismatch (XMLTooling is using log4shib)."
  32 # endif
  33 #elif defined(XMLTOOLING_LOG4CPP)
  34 # ifndef SHIBSP_LOG4CPP
  35 #  error "Logging library mismatch (XMLTooling is using log4cpp)."
  36 # endif
  37 #else
  38 # error "No supported logging library."
  39 #endif
  40
  41 #include "Application.h"
  42 #include "SessionCache.h"
  43 #include "TransactionLog.h"
  44 #include "attribute/Attribute.h"
  45
  46 #include <saml/saml1/core/Assertions.h>
  47 #include <saml/saml1/core/Protocols.h>
  48 #include <saml/saml2/core/Protocols.h>
  49 #include <saml/saml2/metadata/Metadata.h>
  50 #include <xmltooling/util/Threads.h>
  51
  52 using namespace shibsp;
  53 using namespace opensaml::saml1;
  54 using namespace opensaml::saml2;
  55 using namespace opensaml;
  56 using namespace xmltooling;
  57 using namespace std;
  58
  59 namespace shibsp {
  60     TransactionLog::Event* SHIBSP_DLLLOCAL LoginEventFactory(void* const &)
  61     {
  62         return new LoginEvent();
  63     }
  64
  65     TransactionLog::Event* SHIBSP_DLLLOCAL LogoutEventFactory(void* const &)
  66     {
  67         return new LogoutEvent();
  68     }
  69
  70     TransactionLog::Event* SHIBSP_DLLLOCAL AuthnRequestEventFactory(void* const &)
  71     {
  72         return new AuthnRequestEvent();
  73     }
  74 };
  75
  76 void SHIBSP_API shibsp::registerEvents()
  77 {
  78     SPConfig& conf=SPConfig::getConfig();
  79     conf.EventManager.registerFactory(LOGIN_EVENT, LoginEventFactory);
  80     conf.EventManager.registerFactory(LOGOUT_EVENT, LogoutEventFactory);
  81     conf.EventManager.registerFactory(AUTHNREQUEST_EVENT, AuthnRequestEventFactory);
  82 }
  83
  84 TransactionLog::TransactionLog(const char* fmt, const char* absent)
  85     : log(logging::Category::getInstance(SHIBSP_TX_LOGCAT)), m_lock(Mutex::create()), m_absent(absent ? absent : "")
  86 {
  87     // Split the formatting string into named '%' parameter tokens, and "other stuff" to be echoed
  88     // literally in log messages.
  89
  90     bool in_token = false;
  91     m_formatting.push_back(string());
  92     vector<string>::iterator field = m_formatting.begin();
  93     while (fmt && *fmt) {
  94         if (in_token) {
  95             if (!isalnum(*fmt) && *fmt != '-' && *fmt != '%') {
  96                 m_formatting.push_back(string());
  97                 field = m_formatting.begin() + m_formatting.size() - 1;
  98                 in_token = false;
  99             }
 100         }
 101         else if (*fmt == '%') {
 102             if (!field->empty()) {
 103                 m_formatting.push_back(string());
 104                 field = m_formatting.begin() + m_formatting.size() - 1;
 105             }
 106             in_token = true;
 107         }
 108         *field += *fmt++;
 109     }
 110     if (!m_formatting.empty() && m_formatting.back().empty())
 111         m_formatting.pop_back();
 112 }
 113
 114 TransactionLog::~TransactionLog()
 115 {
 116 }
 117
 118 Lockable* TransactionLog::lock()
 119 {
 120     m_lock->lock();
 121     return this;
 122 }
 123
 124 void TransactionLog::unlock()
 125 {
 126     m_lock->unlock();
 127 }
 128
 129 void TransactionLog::write(const TransactionLog::Event& e)
 130 {
 131     if (m_formatting.empty()) {
 132         // For compatibility, we support the old transaction log format, ugly though it may be.
 133         // The session log line would be easy to emulate, but the old attribute logging isn't
 134         // easy to represent with a formatting string.
 135
 136         ostringstream os;
 137
 138         const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
 139         if (login) {
 140             os << "New session (ID: ";
 141             login->write(os, "%s", nullptr);
 142             os << ") with (applicationId: ";
 143             login->write(os, "%app", nullptr);
 144             os << ") for principal from (IdP: ";
 145             login->write(os, "%IDP", "none");
 146             os << ") at (ClientAddress: ";
 147             login->write(os, "%a", nullptr);
 148             os << ") with (NameIdentifier: ";
 149             login->write(os, "%n", "none");
 150             os << ") using (Protocol: ";
 151             login->write(os, "%p", "none");
 152             os << ") from (AssertionID: ";
 153             login->write(os, "%i", nullptr);
 154             os << ")";
 155
 156             Locker locker(this);
 157             log.info(os.str());
 158             os.str("");
 159
 160             os << "Cached the following attributes with session (ID: ";
 161             login->write(os, "%s", nullptr);
 162             os << ") for (applicationId: ";
 163             login->write(os, "%app", nullptr);
 164             os << ") {";
 165             log.info(os.str());
 166
 167             if (login->m_attributes) {
 168                 for (vector<Attribute*>::const_iterator a=login->m_attributes->begin(); a != login->m_attributes->end(); ++a)
 169                     log.infoStream() << "\t" << (*a)->getId() << " (" << (*a)->valueCount() << " values)";
 170             }
 171
 172             log.info("}");
 173             return;
 174         }
 175
 176         const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
 177         if (logout && (logout->m_sessionID || logout->m_session || !logout->m_sessions.empty())) {
 178             os << "Destroyed session (applicationId: ";
 179             logout->write(os, "%app", nullptr);
 180             os << ") (ID: ";
 181             logout->write(os, "%s", nullptr);
 182             os << ")";
 183             log.info(os.str());
 184             return;
 185         }
 186     }
 187     else {
 188         ostringstream os;
 189         for (vector<string>::const_iterator i = m_formatting.begin(); i != m_formatting.end() && !i->empty(); ++i) {
 190             if ((*i)[0] != '%' || !e.write(os, i->c_str(), m_absent.c_str())) {
 191                 os << *i;
 192             }
 193         }
 194         Category::getInstance(string(SHIBSP_TX_LOGCAT) + "." + e.getType()).info(os.str());
 195     }
 196 }
 197
 198 namespace {
 199     bool _URL(const TransactionLog::Event& e, ostream& os) {
 200         const HTTPRequest* http = dynamic_cast<const HTTPRequest*>(e.m_request);
 201         if (http) {
 202             os << http->getRequestURL();
 203             return true;
 204         }
 205         return false;
 206     }
 207
 208     bool _URI(const TransactionLog::Event& e, ostream& os) {
 209         const HTTPRequest* http = dynamic_cast<const HTTPRequest*>(e.m_request);
 210         if (http) {
 211             os << http->getRequestURI();
 212             return true;
 213         }
 214         return false;
 215     }
 216
 217     bool _Header(const TransactionLog::Event& e, ostream& os, const char* name) {
 218         const HTTPRequest* http = dynamic_cast<const HTTPRequest*>(e.m_request);
 219         if (http) {
 220             string s = http->getHeader(name);
 221             if (!s.empty()) {
 222                 os << s;
 223                 return true;
 224             }
 225         }
 226         return false;
 227     }
 228
 229     bool _ExceptionMessage(const TransactionLog::Event& e, ostream& os) {
 230         if (e.m_exception && e.m_exception->what()) {
 231             os << e.m_exception->what();
 232             return true;
 233         }
 234         return false;
 235     }
 236
 237     bool _ExceptionType(const TransactionLog::Event& e, ostream& os) {
 238         const XMLToolingException* x = dynamic_cast<const XMLToolingException*>(e.m_exception);
 239         if (x) {
 240             os << x->getClassName();
 241             return true;
 242         }
 243         return false;
 244     }
 245
 246     bool _AssertionID(const TransactionLog::Event& e, ostream& os) {
 247         const XMLCh* id = nullptr;
 248         const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
 249         if (login) {
 250             if (login->m_saml2AuthnStatement) {
 251                 const saml2::Assertion* a = dynamic_cast<const saml2::Assertion*>(login->m_saml2AuthnStatement->getParent());
 252                 if (a)
 253                     id = a->getID();
 254             }
 255             else if (login->m_saml1AuthnStatement) {
 256                 const saml1::Assertion* a = dynamic_cast<const saml1::Assertion*>(login->m_saml1AuthnStatement->getParent());
 257                 if (a)
 258                     id = a->getAssertionID();
 259             }
 260         }
 261         if (id && *id) {
 262             auto_ptr_char temp(id);
 263             os << temp.get();
 264             return true;
 265         }
 266         return false;
 267     }
 268
 269     bool _ProtocolID(const TransactionLog::Event& e, ostream& os) {
 270         const XMLCh* id = nullptr;
 271         const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
 272         if (login) {
 273             if (login->m_saml2Response)
 274                 id = login->m_saml2Response->getID();
 275             else if (login->m_saml1Response)
 276                 id = login->m_saml1Response->getResponseID();
 277         }
 278         else {
 279             const AuthnRequestEvent* request = dynamic_cast<const AuthnRequestEvent*>(&e);
 280             if (request) {
 281                 if (request->m_saml2Request)
 282                     id = request->m_saml2Request->getID();
 283             }
 284             else {
 285                 const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
 286                 if (logout) {
 287                     if (logout->m_saml2Request)
 288                         id = logout->m_saml2Request->getID();
 289                     else if (logout->m_saml2Response)
 290                         id = logout->m_saml2Response->getID();
 291                 }
 292             }
 293         }
 294         if (id && *id) {
 295             auto_ptr_char temp(id);
 296             os << temp.get();
 297             return true;
 298         }
 299         return false;
 300     }
 301
 302     bool _InResponseTo(const TransactionLog::Event& e, ostream& os) {
 303         const XMLCh* id = nullptr;
 304         const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
 305         if (login) {
 306             if (login->m_saml2Response)
 307                 id = login->m_saml2Response->getInResponseTo();
 308             else if (login->m_saml1Response)
 309                 id = login->m_saml1Response->getInResponseTo();
 310         }
 311         else {
 312             const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
 313             if (logout && logout->m_saml2Response) {
 314                 id = logout->m_saml2Response->getInResponseTo();
 315             }
 316         }
 317         if (id && *id) {
 318             auto_ptr_char temp(id);
 319             os << temp.get();
 320             return true;
 321         }
 322         return false;
 323     }
 324
 325     bool _StatusCode(const TransactionLog::Event& e, ostream& os) {
 326         const saml1p::Status* s1 = nullptr;
 327         const saml2p::Status* s2 = nullptr;
 328         const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
 329         if (login) {
 330             if (login->m_saml2Response)
 331                 s2 = login->m_saml2Response->getStatus();
 332             else if (login->m_saml1Response)
 333                 s1 = login->m_saml1Response->getStatus();
 334         }
 335         else {
 336             const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
 337             if (logout && logout->m_saml2Response)
 338                 s2 = logout->m_saml2Response->getStatus();
 339         }
 340
 341         if (s2 && s2->getStatusCode() && s2->getStatusCode()->getValue()) {
 342             auto_ptr_char temp(s2->getStatusCode()->getValue());
 343             if (temp.get() && *temp.get()) {
 344                 os << temp.get();
 345                 return true;
 346             }
 347         }
 348         else if (s1 && s1->getStatusCode() && s1->getStatusCode()->getValue()) {
 349             os << s1->getStatusCode()->getValue()->toString();
 350             return true;
 351         }
 352
 353         const XMLToolingException* x = dynamic_cast<const XMLToolingException*>(e.m_exception);
 354         if (x) {
 355             const char* s = x->getProperty("statusCode");
 356             if (s && *s) {
 357                 os << s;
 358                 return true;
 359             }
 360         }
 361         return false;
 362     }
 363
 364     bool _SubStatusCode(const TransactionLog::Event& e, ostream& os) {
 365         const saml1p::Status* s1 = nullptr;
 366         const saml2p::Status* s2 = nullptr;
 367         const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
 368         if (login) {
 369             if (login->m_saml2Response)
 370                 s2 = login->m_saml2Response->getStatus();
 371             else if (login->m_saml1Response)
 372                 s1 = login->m_saml1Response->getStatus();
 373         }
 374         else {
 375             const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
 376             if (logout && logout->m_saml2Response)
 377                 s2 = logout->m_saml2Response->getStatus();
 378         }
 379
 380         if (s2 && s2->getStatusCode() && s2->getStatusCode()->getStatusCode()) {
 381             auto_ptr_char temp(s2->getStatusCode()->getStatusCode()->getValue());
 382             if (temp.get() && *temp.get()) {
 383                 os << temp.get();
 384                 return true;
 385             }
 386         }
 387         else if (s1 && s1->getStatusCode() && s1->getStatusCode()->getStatusCode()) {
 388             if (s1->getStatusCode()->getStatusCode()->getValue()) {
 389                 os << s1->getStatusCode()->getValue()->toString();
 390                 return true;
 391             }
 392         }
 393
 394         const XMLToolingException* x = dynamic_cast<const XMLToolingException*>(e.m_exception);
 395         if (x) {
 396             const char* s = x->getProperty("statusCode2");
 397             if (s && *s) {
 398                 os << s;
 399                 return true;
 400             }
 401         }
 402         return false;
 403     }
 404
 405     bool _StatusMessage(const TransactionLog::Event& e, ostream& os) {
 406         const XMLCh* msg = nullptr;
 407         const saml1p::Status* s1 = nullptr;
 408         const saml2p::Status* s2 = nullptr;
 409         const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
 410         if (login) {
 411             if (login->m_saml2Response)
 412                 s2 = login->m_saml2Response->getStatus();
 413             else if (login->m_saml1Response)
 414                 s1 = login->m_saml1Response->getStatus();
 415         }
 416         else {
 417             const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
 418             if (logout && logout->m_saml2Response)
 419                 s2 = logout->m_saml2Response->getStatus();
 420         }
 421
 422         if (s2 && s2->getStatusMessage())
 423             msg = s2->getStatusMessage()->getMessage();
 424         else if (s1 && s1->getStatusMessage())
 425             msg = s1->getStatusMessage()->getMessage();
 426
 427         if (msg) {
 428             auto_ptr_char temp(msg);
 429             if (temp.get() && *temp.get()) {
 430                 os << temp.get();
 431                 return true;
 432             }
 433         }
 434         else {
 435             const XMLToolingException* x = dynamic_cast<const XMLToolingException*>(e.m_exception);
 436             if (x) {
 437                 const char* s = x->getProperty("statusMessage");
 438                 if (s && *s) {
 439                     os << s;
 440                     return true;
 441                 }
 442             }
 443         }
 444
 445         return false;
 446     }
 447
 448     bool _AssertionIssueInstant(const TransactionLog::Event& e, ostream& os) {
 449         time_t t = 0;
 450         const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
 451         if (login) {
 452             if (login->m_saml2AuthnStatement) {
 453                 const saml2::Assertion* a = dynamic_cast<const saml2::Assertion*>(login->m_saml2AuthnStatement->getParent());
 454                 if (a && a->getIssueInstant())
 455                     t = a->getIssueInstantEpoch();
 456             }
 457             else if (login->m_saml1AuthnStatement) {
 458                 const saml1::Assertion* a = dynamic_cast<const saml1::Assertion*>(login->m_saml1AuthnStatement->getParent());
 459                 if (a && a->getIssueInstant())
 460                     t = a->getIssueInstantEpoch();
 461             }
 462         }
 463         if (t == 0)
 464             return false;
 465 #ifndef HAVE_GMTIME_R
 466         struct tm* ptime=localtime(&t);
 467 #else
 468         struct tm res;
 469         struct tm* ptime=localtime_r(&t, &res);
 470 #endif
 471         char timebuf[32];
 472         strftime(timebuf,32,"%Y-%m-%dT%H:%M:%S",ptime);
 473         os << timebuf;
 474         return true;
 475     }
 476
 477     bool _ProtocolIssueInstant(const TransactionLog::Event& e, ostream& os) {
 478         time_t t = 0;
 479         const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
 480         if (login) {
 481             if (login->m_saml2Response && login->m_saml2Response->getIssueInstant())
 482                 t = login->m_saml2Response->getIssueInstantEpoch();
 483             else if (login->m_saml1Response && login->m_saml1Response->getIssueInstant())
 484                 t = login->m_saml1Response->getIssueInstantEpoch();
 485         }
 486         else {
 487             const AuthnRequestEvent* request = dynamic_cast<const AuthnRequestEvent*>(&e);
 488             if (request) {
 489                 if (request->m_saml2Request && request->m_saml2Request->getIssueInstant())
 490                     t = request->m_saml2Request->getIssueInstantEpoch();
 491             }
 492             else {
 493                 const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
 494                 if (logout) {
 495                     if (logout->m_saml2Request && logout->m_saml2Request->getIssueInstant())
 496                         t = logout->m_saml2Request->getIssueInstantEpoch();
 497                     else if (logout->m_saml2Response && logout->m_saml2Response->getIssueInstant())
 498                         t = logout->m_saml2Response->getIssueInstantEpoch();
 499                 }
 500             }
 501         }
 502         if (t == 0)
 503             return false;
 504 #ifndef HAVE_GMTIME_R
 505         struct tm* ptime=localtime(&t);
 506 #else
 507         struct tm res;
 508         struct tm* ptime=localtime_r(&t, &res);
 509 #endif
 510         char timebuf[32];
 511         strftime(timebuf,32,"%Y-%m-%dT%H:%M:%S",ptime);
 512         os << timebuf;
 513         return true;
 514     }
 515
 516     bool _AuthnInstant(const TransactionLog::Event& e, ostream& os) {
 517         time_t t = 0;
 518         const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
 519         if (login) {
 520             if (login->m_saml2AuthnStatement && login->m_saml2AuthnStatement->getAuthnInstant())
 521                 t = login->m_saml2AuthnStatement->getAuthnInstantEpoch();
 522             else if (login->m_saml1AuthnStatement && login->m_saml1AuthnStatement->getAuthenticationInstant())
 523                 t = login->m_saml1AuthnStatement->getAuthenticationInstantEpoch();
 524         }
 525         if (t == 0)
 526             return false;
 527 #ifndef HAVE_GMTIME_R
 528         struct tm* ptime=localtime(&t);
 529 #else
 530         struct tm res;
 531         struct tm* ptime=localtime_r(&t, &res);
 532 #endif
 533         char timebuf[32];
 534         strftime(timebuf,32,"%Y-%m-%dT%H:%M:%S",ptime);
 535         os << timebuf;
 536         return true;
 537     }
 538
 539     bool _SessionIndex(const TransactionLog::Event& e, ostream& os) {
 540         const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
 541         if (login) {
 542             if (login->m_saml2AuthnStatement && login->m_saml2AuthnStatement->getSessionIndex()) {
 543                 auto_ptr_char ix(login->m_saml2AuthnStatement->getSessionIndex());
 544                 if (ix.get() && *ix.get()) {
 545                     os << ix.get();
 546                     return true;
 547                 }
 548             }
 549         }
 550         else {
 551             const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
 552             if (logout && logout->m_saml2Request && !logout->m_saml2Request->getSessionIndexs().empty()) {
 553                 const vector<saml2p::SessionIndex*>& indexes = logout->m_saml2Request->getSessionIndexs();
 554                 for (vector<saml2p::SessionIndex*>::const_iterator i = indexes.begin(); i != indexes.end(); ++i) {
 555                     auto_ptr_char ix((*i)->getSessionIndex());
 556                     if (ix.get() && *ix.get()) {
 557                         if (i != indexes.begin())
 558                             os << ',';
 559                         os << ix.get();
 560                     }
 561                 }
 562                 return true;
 563             }
 564         }
 565         return false;
 566     }
 567
 568     bool _SessionID(const TransactionLog::Event& e, ostream& os) {
 569         const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
 570         if (logout) {
 571             if (!logout->m_sessions.empty()) {
 572                 for (vector<string>::const_iterator s = logout->m_sessions.begin(); s != logout->m_sessions.end(); ++s) {
 573                     if (s != logout->m_sessions.begin())
 574                         os << ',';
 575                     os << *s;
 576                 }
 577                 return true;
 578             }
 579             else if (logout->m_session) {
 580                 os << logout->m_session->getID();
 581                 return true;
 582             }
 583         }
 584         else if (e.m_sessionID) {
 585             os << e.m_sessionID;
 586             return true;
 587         }
 588         return false;
 589     }
 590
 591     bool _REMOTE_USER(const TransactionLog::Event& e, ostream& os) {
 592         const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
 593         const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
 594         if (e.m_app && ((login && login->m_attributes) || (logout && logout->m_session))) {
 595             const vector<string>& ids = e.m_app->getRemoteUserAttributeIds();
 596             const vector<shibsp::Attribute*>& attrs = (login ? *login->m_attributes : logout->m_session->getAttributes());
 597             for (vector<string>::const_iterator id = ids.begin(); id != ids.end(); ++id) {
 598                 for (vector<shibsp::Attribute*>::const_iterator a = attrs.begin(); a != attrs.end(); ++a) {
 599                     if (*id == (*a)->getId() && (*a)->valueCount() > 0) {
 600                         os << (*a)->getSerializedValues().front();
 601                         return true;
 602                     }
 603                 }
 604             }
 605         }
 606         return false;
 607     }
 608
 609     bool _REMOTE_ADDR(const TransactionLog::Event& e, ostream& os) {
 610         if (e.m_request) {
 611             string s = e.m_request->getRemoteAddr();
 612             if (!s.empty()) {
 613                 os << s;
 614                 return true;
 615             }
 616         }
 617         return false;
 618     }
 619
 620     bool _AuthnContext(const TransactionLog::Event& e, ostream& os) {
 621         const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
 622         if (login) {
 623             if (login->m_saml2AuthnStatement && login->m_saml2AuthnStatement->getAuthnContext()) {
 624                 const AuthnContext* ctx = login->m_saml2AuthnStatement->getAuthnContext();
 625                 if (ctx->getAuthnContextClassRef()) {
 626                     auto_ptr_char ref(ctx->getAuthnContextClassRef()->getReference());
 627                     if (ref.get()) {
 628                         os << ref.get();
 629                         return true;
 630                     }
 631                 }
 632                 else if (ctx->getAuthnContextDeclRef()) {
 633                     auto_ptr_char ref(ctx->getAuthnContextDeclRef()->getReference());
 634                     if (ref.get()) {
 635                         os << ref.get();
 636                         return true;
 637                     }
 638                 }
 639                 else if (ctx->getAuthnContextDecl()) {
 640                     os << "(full declaration)";
 641                     return true;
 642                 }
 643             }
 644             else if (login->m_saml1AuthnStatement && login->m_saml1AuthnStatement->getAuthenticationMethod()) {
 645                 auto_ptr_char ac(login->m_saml1AuthnStatement->getAuthenticationMethod());
 646                 if (ac.get()) {
 647                     os << ac.get();
 648                     return true;
 649                 }
 650             }
 651         }
 652         return false;
 653     }
 654
 655     bool _UserAgent(const TransactionLog::Event& e, ostream& os) {
 656         return _Header(e, os, "User-Agent");
 657     }
 658
 659     bool _ApplicationID(const TransactionLog::Event& e, ostream& os) {
 660         if (e.m_app) {
 661             os << e.m_app->getId();
 662             return true;
 663         }
 664         return false;
 665     }
 666
 667     bool _SP_(const TransactionLog::Event& e, ostream& os) {
 668         if (e.m_app) {
 669             const PropertySet* props = e.m_app->getRelyingParty(e.m_peer);
 670             if (props) {
 671                 pair<bool,const char*> entityid = props->getString("entityID");
 672                 if (entityid.first) {
 673                     os << entityid.second;
 674                     return true;
 675                 }
 676             }
 677         }
 678         return false;
 679     }
 680
 681     bool _IDP(const TransactionLog::Event& e, ostream& os) {
 682         if (e.m_peer) {
 683             auto_ptr_char entityid(e.m_peer->getEntityID());
 684             if (entityid.get()) {
 685                 os << entityid.get();
 686                 return true;
 687             }
 688         }
 689
 690         const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
 691         if (logout && logout->m_session) {
 692             os << logout->m_session->getEntityID();
 693             return true;
 694         }
 695
 696         return false;
 697     }
 698
 699     bool _Protocol(const TransactionLog::Event& e, ostream& os) {
 700         if (e.m_protocol) {
 701             os << e.m_protocol;
 702             return true;
 703         }
 704         return false;
 705     }
 706
 707     bool _Binding(const TransactionLog::Event& e, ostream& os) {
 708         if (e.m_binding) {
 709             os << e.m_binding;
 710             return true;
 711         }
 712         return false;
 713     }
 714
 715     bool _NameID(const TransactionLog::Event& e, ostream& os) {
 716         if (e.m_nameID && e.m_nameID->getName()) {
 717             auto_ptr_char temp(e.m_nameID->getName());
 718             if (temp.get() && *temp.get()) {
 719                 os << temp.get();
 720                 return true;
 721             }
 722         }
 723         else {
 724             const AuthnRequestEvent* request = dynamic_cast<const AuthnRequestEvent*>(&e);
 725             if (request) {
 726                 if (request->m_saml2Request && request->m_saml2Request->getSubject()) {
 727                     const saml2::NameID* n = request->m_saml2Request->getSubject()->getNameID();
 728                     if (n) {
 729                         auto_ptr_char temp(n->getName());
 730                         if (temp.get() && *temp.get()) {
 731                             os << temp.get();
 732                             return true;
 733                         }
 734                     }
 735                 }
 736             }
 737             else {
 738                 const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
 739                 if (logout) {
 740                     const saml2::NameID* n = nullptr;
 741                     if (logout->m_session)
 742                         n = logout->m_session->getNameID();
 743                     else if (logout->m_saml2Request)
 744                         n = logout->m_saml2Request->getNameID();
 745                     if (n) {
 746                         auto_ptr_char temp(n->getName());
 747                         if (temp.get() && *temp.get()) {
 748                             os << temp.get();
 749                             return true;
 750                         }
 751                     }
 752                 }
 753             }
 754         }
 755         return false;
 756     }
 757
 758     bool _Attributes(const TransactionLog::Event& e, ostream& os) {
 759         const vector<shibsp::Attribute*>* attrs = nullptr;
 760         const LoginEvent* login = dynamic_cast<const LoginEvent*>(&e);
 761         if (login) {
 762             attrs = login->m_attributes;
 763         }
 764         else {
 765             const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
 766             if (logout && logout->m_session)
 767                 attrs = &logout->m_session->getAttributes();
 768         }
 769         if (attrs && !attrs->empty()) {
 770             map<string,size_t> valcounts;
 771             for (vector<shibsp::Attribute*>::const_iterator a = attrs->begin(); a != attrs->end(); ++a) {
 772                 valcounts[(*a)->getId()] += (*a)->valueCount();
 773             }
 774             for (map<string,size_t>::const_iterator c = valcounts.begin(); c != valcounts.end(); ++c) {
 775                 if (c != valcounts.begin())
 776                     os << ',';
 777                 os << c->first << '(' << c->second << ')';
 778             }
 779             return true;
 780         }
 781         return false;
 782     }
 783
 784     bool _Logout(const TransactionLog::Event& e, ostream& os) {
 785         const LogoutEvent* logout = dynamic_cast<const LogoutEvent*>(&e);
 786         if (logout) {
 787             switch (logout->m_logoutType) {
 788                 case LogoutEvent::LOGOUT_EVENT_INVALID:
 789                     os << "invalid";
 790                     return true;
 791                 case LogoutEvent::LOGOUT_EVENT_LOCAL:
 792                     os << "local";
 793                     return true;
 794                 case LogoutEvent::LOGOUT_EVENT_GLOBAL:
 795                     os << "global";
 796                     return true;
 797                 case LogoutEvent::LOGOUT_EVENT_PARTIAL:
 798                     os << "partial";
 799                     return true;
 800             }
 801         }
 802         return false;
 803     }
 804 };
 805
 806 TransactionLog::Event::Event()
 807     : m_exception(nullptr),
 808       m_request(nullptr),
 809       m_app(nullptr),
 810       m_sessionID(nullptr),
 811       m_peer(nullptr),
 812       m_protocol(nullptr),
 813       m_binding(nullptr),
 814       m_nameID(nullptr)
 815 {
 816     m_handlers["e"] = _ExceptionMessage;
 817     m_handlers["E"] = _ExceptionType;
 818     m_handlers["S"] = _StatusCode;
 819     m_handlers["SS"] = _SubStatusCode;
 820     m_handlers["SM"] = _StatusMessage;
 821     m_handlers["URL"] = _URL;
 822     m_handlers["URI"] = _URI;
 823     m_handlers["s"] = _SessionID;
 824     m_handlers["a"] = _REMOTE_ADDR;
 825     m_handlers["UA"] = _UserAgent;
 826     m_handlers["app"] = _ApplicationID;
 827     m_handlers["SP"] = _SP_;
 828     m_handlers["IDP"] = _IDP;
 829     m_handlers["p"] = _Protocol;
 830     m_handlers["b"] = _Binding;
 831     m_handlers["n"] = _NameID;
 832 }
 833
 834 TransactionLog::Event::~Event()
 835 {
 836 }
 837
 838 bool TransactionLog::Event::write(ostream& out, const char* field, const char* absent) const
 839 {
 840     if (!field || *field++ != '%') {
 841         return false;
 842     }
 843
 844     if (*field == '%' || *field == '\0') {
 845         out << '%';
 846     }
 847     else {
 848         map<string,handler_fn>::const_iterator h = m_handlers.find(field);
 849         if ((h != m_handlers.end() && !h->second(*this, out)) || (h == m_handlers.end() && !_Header(*this, out, field))) {
 850             if (absent)
 851                 out << absent;
 852         }
 853     }
 854     return true;
 855 }
 856
 857 LoginEvent::LoginEvent()
 858     : m_saml2AuthnStatement(nullptr),
 859       m_saml2Response(nullptr),
 860       m_saml1AuthnStatement(nullptr),
 861       m_saml1Response(nullptr),
 862       m_attributes(nullptr)
 863 {
 864     m_handlers["u"] = _REMOTE_USER;
 865     m_handlers["i"] = _AssertionID;
 866     m_handlers["I"] = _ProtocolID;
 867     m_handlers["II"] = _InResponseTo;
 868     m_handlers["d"] = _AssertionIssueInstant;
 869     m_handlers["D"] = _ProtocolIssueInstant;
 870     m_handlers["t"] = _AuthnInstant;
 871     m_handlers["x"] = _SessionIndex;
 872     m_handlers["ac"] = _AuthnContext;
 873     m_handlers["attr"] = _Attributes;
 874 }
 875
 876 const char* LoginEvent::getType() const
 877 {
 878     return "Login";
 879 }
 880
 881 LoginEvent::~LoginEvent()
 882 {
 883 }
 884
 885 LogoutEvent::LogoutEvent()
 886     : m_logoutType(LOGOUT_EVENT_UNKNOWN),
 887       m_saml2Request(nullptr),
 888       m_saml2Response(nullptr),
 889       m_session(nullptr)
 890 {
 891     m_handlers["L"] = _Logout;
 892     m_handlers["u"] = _REMOTE_USER;
 893     m_handlers["I"] = _ProtocolID;
 894     m_handlers["II"] = _InResponseTo;
 895     m_handlers["D"] = _ProtocolIssueInstant;
 896     m_handlers["x"] = _SessionIndex;
 897 }
 898
 899 LogoutEvent::~LogoutEvent()
 900 {
 901 }
 902
 903 const char* LogoutEvent::getType() const
 904 {
 905     if (m_saml2Request)
 906         return "Logout.Request";
 907     else if (m_saml2Response)
 908         return "Logout.Response";
 909     return "Logout";
 910 }
 911
 912 AuthnRequestEvent::AuthnRequestEvent() : m_saml2Request(nullptr)
 913 {
 914     m_handlers["I"] = _ProtocolID;
 915     m_handlers["D"] = _ProtocolIssueInstant;
 916 }
 917
 918 AuthnRequestEvent::~AuthnRequestEvent()
 919 {
 920 }
 921
 922 const char* AuthnRequestEvent::getType() const
 923 {
 924     return "AuthnRequest";
 925 }