1

I'm trying to log certain events through logback in my Spring4 application. Taken from the logback documentation I have the following UserId Filter

@Component
public class UserIdFilter implements Filter {

    public static final String USERID = "userid";

    @Override
    public void init(FilterConfig filterConfig) throws ServletException {}

    @Override
    public void doFilter(ServletRequest servletRequest, ServletResponse    servletResponse, FilterChain filterChain) throws IOException, ServletException    {
        String userName = AccessLogger.getUserName();
        MDC.put(USERID, userName);
        try {
            filterChain.doFilter(servletRequest, servletResponse);
        } finally {
            MDC.remove(USERID);
        }
    }

    @Override
    public void destroy() {}
}

It sets the Username into the MDC as "userid" on a request basis and correctly adds the user's name to the log output (which is being shipped off to an ELK stack)

<appender name="LOGSTASH" class="ch.qos.logback.classic.sift.SiftingAppender">

    <filter class="de.app.log.PackageFilter">
        <level>de.app</level>
    </filter>

    <discriminator>
        <key>userid</key>
        <defaultValue>unknown</defaultValue>
    </discriminator>
    <sift>
        <appender name="LOGSTASH-SIFT" class="net.logstash.logback.appender.LogstashTcpSocketAppender">
            <destination>elk:5000</destination>
            <encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
                <providers>
                    ...
                    <mdc/> 
                    <logstashMarkers/> 
                </providers>
            </encoder>
        </appender>
    </sift>
</appender>

I am also trying to log successful logins, where the "userid" has not yet been set in the UserIdFilter, but the user goes through a successhandler (configured in the WebSecurityConfigurerAdapter) afterwards:

public class SimpleAuthenticationSuccessHandler implements AuthenticationSuccessHandler {
    private RedirectStrategy redirectStrategy = new DefaultRedirectStrategy();

    private static final Logger LOG = LoggerFactory.getLogger(SimpleAuthenticationSuccessHandler.class);

    @Override
    public void onAuthenticationSuccess(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse, Authentication authentication) throws IOException, ServletException {

        User user = (User) authentication.getPrincipal();
        String username = user.getUsername();
        MDC.put(UserIdFilter.USERID, username);
        LOG.info(LogEvent.LOGIN, user.toString());
        MDC.remove(UserIdFilter.USERID);
        redirectStrategy.sendRedirect(httpServletRequest, httpServletResponse, "/");
    }
}

However the AuthenticationSuccessHandler seems to run into some kind of concurrency issue where it takes the MDC variable from a different user for the log output. The result is, that certain login-events take the userid from an already logged in user. Following log-events, where the MDC is set through the UserIdFilter again, seem to be correct:

June 19th 2018, 15:14:35.602 | User: johndoe | event: submit | message: ChangeRequest submitted
June 19th 2018, 15:14:16.364 | User: johndoe | event: modified | message: Form modified
June 19th 2018, 15:06:47.567 | User: chris | event: login | message: de.app.User@5aa59640: Username: johndoe
June 19th 2018, 14:36:27.221 | User: chris | event: login | message: de.app.User@e7b516eb: Username: chris

-> 3rd line: User johndoe gets chris as userId for the login event through MDC

Does anyone have an idea on how or where to implement/configure this correctly?

empinator
  • 23
  • 5

1 Answers1

0

The above solution works!

We had played around using LogStashMarker instead of MDC in the SuccessHandler and due to branching the MDC-Solution has not been released into production correctly, and Markers where causing the unwanted behaviour. Which also explained why we werent't able to recreate the behaviour in development... duh!

Sorry for taking up your time, but maybe the above code is helpful someone.

empinator
  • 23
  • 5