Storing Shibboleth IDP Logs in a Database with IP Addresses
Shibboleth’s IDP can store audit logs that indicate when people authenticate against the IDP web application. These files are written to disk by default using the settings in the logging.xml configuration file. This tutorial will show how audit logs can be placed in a MS SQL database and also include the IP addresses of the connecting clients.
Shibboleth uses the SLF4J, a logging library that is a front end for a variety of backend loggers. By default, it uses logback to handle process audit logs. SLF4J supports a DBAppender. Unlike the RollingFileAppender, the DBAppender doesn’t support encoder/Pattern configuration. It places all logging messages in a standard database schema which can be found in the logback-0.9.28\logback-classic\src\main\java\ch\qos\logback\classic\db\dialect directory of the logback source code.
Note that in version 0.9.28 of logback, there is a bug in the MS SQL schema where all the event_id fields have an invalid type of DECIMAL(40). These must be changed to DECIMAL(38). This tutorial assume the use of an MS SQL database. Other databases will work, but the triggers and schema will need to be adjusted for those dialects accordingly.
In the Shibboleth logging.xml configuration file, start by adding the following appender:
<appender name="IDP_DB_APPENDER" class="ch.qos.logback.classic.db.DBAppender">
<connectionSource class="ch.qos.logback.core.db.DataSourceConnectionSource">
<dataSource class="com.jolbox.bonecp.BoneCPDataSource">
<driverClass>com.microsoft.sqlserver.jdbc.SQLServerDriver</driverClass>
<jdbcUrl>jdbc:sqlserver://dbserver.example.edu:5555;databaseName=ShibAudit</jdbcUrl>
<username>someUsername</username>
<password>somePassword</password>
</dataSource>
</connectionSource>
</appender>
Replace the database name, server, usernames and passwords respectively.
For the above example, the BoneCP connectionSource is used for connection pooling. The BoneCP libraries will be available if uApprove has been installed. Additional configuration options can be specified for tweaking connection counts and partitions within the pool.
An alternative to BoneCP is the c3p0 connection pool library. This library comes with Shibboleth and requires no extra jar files:
<appender name="IDP_DB_APPENDER" class="ch.qos.logback.classic.db.DBAppender">
<connectionSource class="ch.qos.logback.core.db.DataSourceConnectionSource">
<dataSource class="com.mchange.v2.c3p0.ComboPooledDataSource">
<driverClass>com.microsoft.sqlserver.jdbc.SQLServerDriver</driverClass>
<jdbcUrl>jdbc:sqlserver://dbserver.example.edu:5555;databaseName=ShibAudit</jdbcUrl>
<user>someUser</user>
<password>somePassword</password>
</dataSource>
</connectionSource>
</appender>
Again, replace the database name, server, usernames and passwords respectively. Next, the new appender needs to be attached to the audit logger:
<logger name="Shibboleth-Audit" level="ALL">
<appender-ref ref="IDP_AUDIT" />
<appender-ref ref="IDP_DB_APPENDER" />
</logger>
At this point, Shibboleth IDP can be restarted and attempts to authenticate with the IDP should result in log entries in the database. Make sure this is working. If not, check the idp-process.log as well as Tomcat’s cataline.out log file to determine if there were errors creating the DBAppender object.
Shibboleth 2.2.1 places its audit logs in a pipe delimited format that can easily be parsed. Rather than let the logger store this long pipe delimited string in our database, it would be beneficial to convert these logs into structure that’s easier to query. Start by creating the following table in the same database the DBAppender writes to:
CREATE TABLE audit_log ( logtime datetime, remoteAddr VARCHAR(255), requestbinding VARCHAR(100), requestId VARCHAR(50), relayingPartyId VARCHAR(255), messageProfileId VARCHAR(100), assertingPartyId VARCHAR(255), responseBinding VARCHAR(100), responseId VARCHAR(50), principalName VARCHAR(8), authNMethod VARCHAR(100), releasedAttributeIds VARCHAR(255), nameIdentifier VARCHAR(100), assertionIDs VARCHAR(100) );
Now, a trigger will be added to the logging_event table so that whenever a row is inserted, it will be parsed and placed into the new tables.
SET ANSI_NULLS ON
GO
SET QUOTED_IDENTIFIER ON
GO
CREATE TRIGGER [dbo].[parseLog]
ON [dbo].[logging_event]
AFTER INSERT
AS
BEGIN
SET NOCOUNT ON;
DECLARE @data VARCHAR(4000)
DECLARE @xml XML
DECLARE @unixTimestamp datetime
--Convert UNIX timestamp, with ms, to mssql datetime
SET @unixTimestamp = (SELECT dateadd(ms,CAST(RIGHT(timestmp,3) AS INT),dateadd(ss,CAST(timestmp AS BIGINT)/1000,'01/01/1970')) FROM INSERTED)
--Data as XML for easy parsing
SET @data = (SELECT formatted_message FROM INSERTED)
SET @xml = '<Cols><Col>' + REPLACE(@data,'|','</Col><Col>') + '</Col></Cols>'
--Different Tables for different logger types
DECLARE @type AS VARCHAR(254)
SET @type = (SELECT logger_name FROM INSERTED)
IF @type = 'Shibboleth-Audit'
BEGIN
--Fields to parse
DECLARE @requestbinding AS VARCHAR(100)
DECLARE @requestId AS VARCHAR(50)
DECLARE @relayingPartyId AS VARCHAR(255)
DECLARE @messageProfileId AS VARCHAR(100)
DECLARE @assertingPartyId AS VARCHAR(255)
DECLARE @responseBinding AS VARCHAR(100)
DECLARE @responseId AS VARCHAR(50)
DECLARE @principalName AS VARCHAR(8)
DECLARE @authNMethod AS VARCHAR(100)
DECLARE @releasedAttributeIds AS VARCHAR(255)
DECLARE @nameIdentifier AS VARCHAR(100)
DECLARE @assertionIDs AS VARCHAR(100)
--Store the event_id in the IP address. The event_property trigger
-- will replace this with the real IP
DECLARE @eventId AS DECIMAL(38,0)
SET @eventId = (SELECT event_id FROM INSERTED)
SELECT
@requestBinding = x.d.value('Col[2]', 'VARCHAR(100)'),
@requestId = x.d.value('Col[3]', 'VARCHAR(50)'),
@relayingPartyId = x.d.value('Col[4]', 'VARCHAR(255)'),
@messageProfileId = x.d.value('Col[5]', 'VARCHAR(100)'),
@assertingPartyId = x.d.value('Col[6]', 'VARCHAR(255)'),
@responseBinding = x.d.value('Col[7]', 'VARCHAR(100)'),
@responseId = x.d.value('Col[8]', 'VARCHAR(50)'),
@principalName = x.d.value('Col[9]', 'VARCHAR(8)'),
@authNMethod = x.d.value('Col[10]', 'VARCHAR(100)'),
@releasedAttributeIds = x.d.value('Col[11]', 'VARCHAR(255)'),
@nameIdentifier = x.d.value('Col[12]', 'VARCHAR(100)'),
@assertionIDs = x.d.value('Col[13]', 'VARCHAR(100)')
FROM @xml.nodes('/Cols') x(d)
INSERT INTO audit_log (logtime, remoteAddr,requestbinding,requestId,relayingPartyId,messageProfileId,assertingPArtyId,
responseBinding,responseId,principalName,authNMethod,releasedAttributeIds, nameIdentifier, assertionIds)
VALUES(@unixTimeStamp,@eventId, @requestBinding,@requestId,@relayingPartyId,
@messageProfileId,@assertingPartyId,@responseBinding,@responseId,@principalName,
@authNMethod,@releasedAttributeIds,@nameIdentifier,@assertionIDs)
END
END
GO
Since MS SQL has no built-in function for splitting fields on a delimiter, the above function replaces the pipe symbols with opening and closing XML tags so that MS SQL’s built-in XPath engine can be used to parse the field. A conversion must also be done to translate the UNIX timestamp to an MS SQL datetime type. Finally, the event_id is used as a placeholder in the field containing the client’s IP address. This is because by default, Shibboleth’s audit logs do not contain IP information. This can be added however using a custom servlet filter with SLF4J.
SLF4J supports a MDC which allows for values to be mapped to a logger for a given thread instance. Since only one thread in a Java servlet container is used per connection at any given time, this can be used to hold items such as the connecting client’s IP address for logging. The DBAppender inserts these properties in the logging_event_property table. A custom filter can be written to create these properties, but SLF4J comes with the MDCInsertingServletFilter which injects certain common attributes into the MDC such as user-agent, remote host, query string, etc.
In the idp.war, add the following filter to the web.xml.
<filter>
<filter-name>MDCInsertingServletFilter</filter-name>
<filter-class>
ch.qos.logback.classic.helpers.MDCInsertingServletFilter
</filter-class>
</filter>
<filter-mapping>
<filter-name>MDCInsertingServletFilter</filter-name>
<url-pattern>/*</url-pattern>
</filter-mapping>
The SLF4J documentation recommended adding the MDC as the first filter, but unless attributes are needed for logging within other filters from what the MDC injects, this isn’t always necessary. For the database audit logging, the filter can be placed at the end of the idp.war‘s web.xml file.
Finally, a trigger must be added to handle the properties that are inserted, namely the remote IP address, and update the record of the original log entry.
SET ANSI_NULLS ON
GO
SET QUOTED_IDENTIFIER ON
GO
CREATE TRIGGER [dbo].[setLogIP]
ON [dbo].[logging_event_property]
AFTER INSERT
AS
BEGIN
IF (SELECT mapped_key FROM INSERTED) = 'req.remoteHost'
BEGIN
UPDATE audit_log SET remoteAddr = (SELECT mapped_value FROM INSERTED)
WHERE remoteAddr = CONVERT(varchar(255),(SELECT event_id FROM INSERTED))
END
END
GO
The DBAppender is transaction based, so if any triggers or query statements fail (e.g. if permissions are not setup correctly for the database user), the entire logging transaction will be rolled back and no results will appear in the database table. It is best to implement this is stages, starting with getting the DBAppender working and then adding the new table and triggers.
Since the standard text based log files do not include an IP address, it is best to include this new attribute in the original files as well. This can be done by modifying the RollingFileAppender for the audit log. The following example adds the IP address and also sets the rollover for the log file to 1 year (365 days). This should be adjusted to the retention requirements of the institution’s legal department.
<appender name="IDP_AUDIT" class="ch.qos.logback.core.rolling.RollingFileAppender">
<File>/opt/shibboleth-idp/logs/idp-audit.log</File>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<FileNamePattern>/opt/shibboleth-idp/logs/idp-audit-%d{yyyy-MM-dd}.log</FileNamePattern>
<maxHistory>365</maxHistory>
</rollingPolicy>
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<charset>UTF-8</charset>
<Pattern>%X{req.remoteHost}|%msg%n</Pattern>
</encoder>
</appender>
Having audit logs in a database makes it convenient to aggregate Shibboleth authentication requests for reports, as well as retrieve information quickly for legal and security requests. It is recommended to also keep the RollingFileAppender to use as a backup in case of problems with the database connection.