idp logging to syslog retains stack trace when it shouldn't
Don Faulkner
donf at uark.edu
Wed Apr 18 22:59:28 BST 2012
First, let me explain my ultimate goal. If there's a better way, please
enlighten me. :)
I want to record an audit log of successful and unsuccessful
authentication attempts against the IdP. Ideally, I'd like to see the
following in the log:
timestamp idp_host source severity (success|failure) userid passwd_hash
clientIP
so, something close to this, which I've already achieved:
Apr 18 16:34:47 idp1
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:
DEBUG] Attempting to authenticate user donf from 192.168.56.1
Apr 18 16:34:47 idp1
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:
DEBUG] User authentication for donf failed from 192.168.56.1
Apr 18 16:34:47 idp1
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:
DEBUG] Successfully authenticated user donf from 192.168.56.1
I got most of this to work, except for the hashed password, using both a
RollingFileAppender and a SyslogAppender (above example). There appears
to be a problem with the SyslogAppender though.
While I see all of the above, I also see a mangled stack trace in the
syslog output, this is despite adding %nopex to the pattern. When I add
%nopex to the RollingFileAppender pattern, the stack trace is correctly
omitted. This is not the case with the SyslogAppender. Looking at
logback's code, it looks like I shouldn't have to specify %nopex for the
SyslogAppender anyway, since it's in the prefixPattern (to which the
SuffixPattern is appended). No matter what I do a strangely truncated
(from the left side of each line) stack trace is present in syslog.
I'm going to ask a similar question over at the logback project, too.
(I'm sure someone's going to ask about my wanting that hashed password
in the log. My goal is to use that as a non-reversible way to look for
the same password repeated on one account, or across multiple accounts.
I'm hoping to combat a couple of different attack scenarios this way.)
Here are the relevant parts of my logging.xml:
<appender name="IDP_SYSLOG"
class="ch.qos.logback.classic.net.SyslogAppender">
<SyslogHost>localhost</SyslogHost>
<Port>514</Port>
<Facility>AUTH</Facility>
<SuffixPattern>[%logger:%level] %msg %mdc{idpSessionId} from
%mdc{clientIP}%nopex</SuffixPattern>
</appender>
<appender name="IDP_LOGIN_ONLY"
class="ch.qos.logback.core.rolling.RollingFileAppender">
<File>/opt/shibboleth-idp/logs/idp-login.log</File>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<FileNamePattern>/opt/shibboleth-idp/logs/idp-access-%d{yyyy-MM-dd}.log</FileNamePattern>
</rollingPolicy>
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<charset>UTF-8</charset>
<Pattern>%msg %mdc{idpSessionId} from %mdc{clientIP}%n%nopex</Pattern>
</encoder>
</appender>
<logger name="edu.internet2.middleware.shibboleth.idp.authn" level="DEBUG">
<appender-ref ref="IDP_SYSLOG"/>
<appender-ref ref="IDP_LOGIN_ONLY"/>
</logger>
Here's a sample from my idp-login.log:
Attempting to authenticate user donf from 192.168.56.1
User authentication for donf failed from 192.168.56.1
Redirecting to login page /login.jsp from 192.168.56.1
And here's what syslog looks like for the same attempt:
Apr 18 16:17:06 idp1
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:
DEBUG] Attempting to authenticate user donf from 192.168.56.1
Apr 18 16:17:07 idp1
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:
DEBUG] User authentication for donf failed from 192.168.56.1
Apr 18 16:17:07 idp1 #011at
edu.vt.middleware.ldap.jaas.LdapLoginModule.login(LdapLoginModule.java:138)
Apr 18 16:17:07 idp1 #011at
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
Apr 18 16:17:07 idp1 #011at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
Apr 18 16:17:07 idp1 #011at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Apr 18 16:17:07 idp1 #011at java.lang.reflect.Method.invoke(Method.java:616)
Apr 18 16:17:07 idp1 #011at
javax.security.auth.login.LoginContext.invoke(LoginContext.java:784)
Apr 18 16:17:07 idp1 #011at
javax.security.auth.login.LoginContext.access$000(LoginContext.java:203)
Apr 18 16:17:07 idp1 #011at
javax.security.auth.login.LoginContext$4.run(LoginContext.java:698)
Apr 18 16:17:07 idp1 #011at
javax.security.auth.login.LoginContext$4.run(LoginContext.java:696)
Apr 18 16:17:07 idp1 #011at
java.security.AccessController.doPrivileged(Native Method)
Apr 18 16:17:07 idp1 #011at
javax.security.auth.login.LoginContext.invokePriv(LoginContext.java:695)
Apr 18 16:17:07 idp1 #011at
javax.security.auth.login.LoginContext.login(LoginContext.java:594)
Apr 18 16:17:07 idp1 #011at
edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet.authenticateUser(UsernamePasswordLoginServlet.java:177)
Apr 18 16:17:07 idp1 #011at
edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet.service(UsernamePasswordLoginServlet.java:123)
Apr 18 16:17:07 idp1 #011at
javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
Apr 18 16:17:07 idp1 #011at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
Apr 18 16:17:07 idp1 #011at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
Apr 18 16:17:07 idp1 #011at
edu.internet2.middleware.shibboleth.idp.util.NoCacheFilter.doFilter(NoCacheFilter.java:50)
Apr 18 16:17:07 idp1 #011at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
Apr 18 16:17:07 idp1 #011at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
Apr 18 16:17:07 idp1 #011at
edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter.doFilter(IdPSessionFilter.java:81)
Apr 18 16:17:07 idp1 #011at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
Apr 18 16:17:07 idp1 #011at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
Apr 18 16:17:07 idp1 #011at
edu.internet2.middleware.shibboleth.common.log.SLF4JMDCCleanupFilter.doFilter(SLF4JMDCCleanupFilter.java:52)
Apr 18 16:17:07 idp1 #011at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
Apr 18 16:17:07 idp1 #011at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
Apr 18 16:17:07 idp1 #011at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
Apr 18 16:17:07 idp1 #011at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
Apr 18 16:17:07 idp1 #011at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
Apr 18 16:17:07 idp1 #011at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
Apr 18 16:17:07 idp1 #011at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
Apr 18 16:17:07 idp1 #011at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:300)
Apr 18 16:17:07 idp1 #011at
org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:859)
Apr 18 16:17:07 idp1 #011at
org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:588)
Apr 18 16:17:07 idp1 #011at
org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
Apr 18 16:17:07 idp1 #011at java.lang.Thread.run(Thread.java:679)
Apr 18 16:17:07 idp1
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:
DEBUG] Redirecting to login page /login.jsp from 192.168.56.1
--
me Don Faulkner, CISSP | IT Security <http://its.uark.edu/> at the
University of Arkansas <http://www.uark.edu/>
contact>> donf at uark.edu <mailto:donf at uark.edu> | +1 (479) 575-2905
connect>> uarkITS on Facebook <http://www.facebook.com/uarkITS> | @uaits
<http://twitter.com/uaits> | @dfaulkner <http://twitter.com/dfaulkner>
More information about the users
mailing list