[logback-user] SyslogAppender retains stack trace when it shouldn't

[Don Faulkner]

Hi all,

New subscriber & user. I'm trying to configure logback as it's used in 
the Shibboleth application (http://shibboleth.internet2.edu/, 
http://wiki.shibboleth.net/). I'm working with version 2.3.6 of their 
SAML Identity Provider (IdP), which uses version 1.0.0 of logback.

Question: How do I configure SyslogAppender to omit stack traces?

I'm attempting to configure the system to send certain messages to 
syslog for a security audit trail (things like authentication 
success/failure). I've located the correct logger, and I've successfully 
configured a SyslogAppender to send the events to syslog, but I'm 
getting an odd bit of  a stack trace in the syslog, even though I think 
I shouldn't.

I think my problem is similar/related to Ingebrigt Berg's issue 
http://mailman.qos.ch/pipermail/logback-user/2012-March/003054.html

When the line gets logged to syslog, I see the first line correctly, but 
that line is followed by a stack trace, except that the beginning of the 
stack trace is replaced with the string "#011". What I want is no stack 
trace at all, which I ought to be able to get with %nopex, except that 
doesn't seem to work. When I dig into the code a bit, I see that the 
SyslogAppender already defines a prefixPattern which has %nopex in it, 
so I may be missing something here.

Relevant bits 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>
<logger name="edu.internet2.middleware.shibboleth.idp.authn" level="DEBUG">
<appender-ref ref="IDP_SYSLOG"/>
</logger>


The syslog output looks like:
Apr 19 10:58:24 idp1 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine: 
DEBUG]  Processing incoming request  from 192.168.56.1
Apr 19 10:58:24 idp1 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine: 
DEBUG]  Beginning user authentication process.  from 192.168.56.1
Apr 19 10:58:24 idp1 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine: 
DEBUG]  Filtering configured LoginHandlers: 
{urn:oasis:names:tc:SAML:2.0:ac:classes:PreviousSession=edu.internet2.middleware.shibboleth.idp.authn.provider.PreviousSessionLoginHandler at 7b8be7, 
urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler at 11e1813}  
from 192.168.56.1
Apr 19 10:58:24 idp1 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine: 
DEBUG]  Filtering out previous session login handler because there is no 
existing IdP session  from 192.168.56.1
Apr 19 10:58:24 idp1 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine: 
DEBUG]  Selecting appropriate login handler from filtered set 
{urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler at 11e1813} 
from 192.168.56.1
Apr 19 10:58:24 idp1 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine: 
DEBUG]  Authenticating user with login handler of type 
edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler 
from 192.168.56.1
Apr 19 10:58:24 idp1 
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler: 
DEBUG]  Redirecting to https://idp1:443/idp/Authn/UserPassword  from 
192.168.56.1
Apr 19 10:58:24 idp1 
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet: 
DEBUG]  Redirecting to login page /login.jsp  from 192.168.56.1
Apr 19 10:58:53 idp1 
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet: 
DEBUG]  Attempting to authenticate user donf  from 192.168.56.1
Apr 19 10:58:55 idp1 
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet: 
DEBUG]  User authentication for donf failed  from 192.168.56.1
Apr 19 10:58:55 idp1 #011at 
edu.vt.middleware.ldap.jaas.LdapLoginModule.login(LdapLoginModule.java:138)
Apr 19 10:58:55 idp1 #011at 
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
Apr 19 10:58:55 idp1 #011at 
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
Apr 19 10:58:55 idp1 #011at 
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Apr 19 10:58:55 idp1 #011at java.lang.reflect.Method.invoke(Method.java:616)
Apr 19 10:58:55 idp1 #011at 
javax.security.auth.login.LoginContext.invoke(LoginContext.java:784)
Apr 19 10:58:55 idp1 #011at 
javax.security.auth.login.LoginContext.access$000(LoginContext.java:203)
[...]

The lines through "user authentication for donf failed" are expected. 
The rest are not. I can do the same thing with a RollingFileAppender and 
it works correctly. Am I missing something?


-- 
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>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.qos.ch/pipermail/logback-user/attachments/20120419/953603c4/attachment.html>