Kohei Nozaki's blog 

Recently I'm getting "javax.servlet.ServletException: Security Violation" 1 or 2 times per day from Roller (the blog engine this blog running on) and lost some unsaved paragraphs every time. I tried to back in such case, Safari and Firefox said the page has expired, and I couldn't take back my unsaved paragraphs. it's annoying so I started to find what the cause is.

Looking at stacktrace and I found that it comes from ValidateSaltFilter, and its related caching classes such as ExpiringLRUCacheFactoryImpl, but it's hard to reproduce, so I added some logging configuration and logging procedure to Roller to acquire more information.

Users can configure log4j which is logging framework Roller used at roller-custom.properties. I added following:

# Appender definition

log4j.appender.roller-debug=org.apache.log4j.DailyRollingFileAppender
log4j.appender.roller-debug.File=/Users/kyle/tmp/roller511/rollerdata/roller-debug.log
log4j.appender.roller-debug.layout=org.apache.log4j.PatternLayout
log4j.appender.roller-debug.layout.ConversionPattern=%-5p %d{yyyy-MM-dd HH:mm:ss,SSS} %C{1}:%M - %m%n
log4j.appender.roller-debug.Threshold=DEBUG

# Assign loggers to the appender which defined at the preceding.
# log4j.additivity means that stopping propagate to parent logger.

log4j.logger.org.apache.roller.weblogger.util.cache=DEBUG, roller-debug
log4j.additivity.org.apache.roller.weblogger.util.cache=false

log4j.logger.org.apache.roller.weblogger.ui.rendering.util.cache=DEBUG, roller-debug
log4j.additivity.org.apache.roller.weblogger.ui.rendering.util.cache=false

log4j.logger.org.apache.roller.weblogger.ui.core.filters.ValidateSaltFilter=DEBUG, roller-debug
log4j.additivity.org.apache.roller.weblogger.ui.core.filters.ValidateSaltFilter=false

     public void doFilter(ServletRequest request, ServletResponse response,
            FilterChain chain) throws IOException, ServletException {
        HttpServletRequest httpReq = (HttpServletRequest) request;

        // note enctype="multipart/form-data" does not send parameters (see
        // ROL-1956) requests of this type are stored in salt.ignored.urls in
        // roller.properties
        if (httpReq.getMethod().equals("POST")
                && !isIgnoredURL(httpReq.getServletPath())) {

            String salt = httpReq.getParameter("salt");
            SaltCache saltCache = SaltCache.getInstance();

            if (log.isDebugEnabled()) {

                try {
                    final Field contentCache = SaltCache.class.getDeclaredField("contentCache");
                    contentCache.setAccessible(true);
                    Object contentCacheValue = contentCache.get(saltCache);
                    
                    final Field cache = LRUCacheImpl.class.getDeclaredField("cache");
                    cache.setAccessible(true);
                    Object cacheValue = cache.get(contentCacheValue);
                    
                    Map cacheMap = (Map) cacheValue;
                    final Set set = cacheMap.keySet();
                    
                    log.debug("Salt which is just received: " + salt);
                    for (Object o : set) {
                        log.debug("Salt in the map: " + o);
                    }
                    
                } catch (NoSuchFieldException e) {
                    throw new RuntimeException(e);
                } catch (IllegalAccessException e) {
                    throw new RuntimeException(e);
                }

                if (salt == null) {
                    log.debug("salt == null");
                }
                else if (saltCache.get(salt) == null) {
                    log.debug("saltCache.get(salt) == null. salt=" + salt);
                }
                else if (saltCache.get(salt).equals(false)) {
                    log.debug("saltCache.get(salt).equals(false). salt=" + salt);
                }
            }

            if (salt == null || saltCache.get(salt) == null
                    || saltCache.get(salt).equals(false)) {

                if (log.isDebugEnabled()) {
                    log.debug("Salt value not found on POST to URL : "
                            + httpReq.getServletPath());
                }

                throw new ServletException("Security Violation");
            }
        }

        chain.doFilter(request, response);
    }

I added all of additional procedures inside if (log.isDebugEnabled()) so I won't need to remove these procedures after investigation. all I need will that just edit roller-custom.properties and reload Roller.

Now I can see how all of salts are creating, removing and be judged which was hit or miss from the log, so I'll take a look it when the problem occurred again.

UPDATE: I think I found the cause. see JIRA.