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