JokoSecurity escribe una excepcion cuando un token expira

[danicricco]

Cuando un token expira Joko security escribe una excepción como la siguiente:

2017-11-29 10:02:43.044 DEBUG 23946 --- [nio-8080-exec-2] i.g.j.s.springex.JokoSecurityFilter      : /api/clients/1542561/feeds/2017/11 from User-Agent: okhttp/3.3.1 Unable to authenticate class io.jsonwebtoken.ExpiredJwtException: JWT expired at 2017-11-28T22:17:26-0300. Current time: 2017-11-29T10:02:43-0300
2017-11-29 10:02:43.044 DEBUG 23946 --- [nio-8080-exec-1] i.g.j.s.springex.JokoSecurityFilter      : /api/clients/1542561/budget/2017/11 from User-Agent: okhttp/3.3.1 Unable to authenticate class io.jsonwebtoken.ExpiredJwtException: JWT expired at 2017-11-28T22:17:26-0300. Current time: 2017-11-29T10:02:43-0300
2017-11-29 10:02:43.045 TRACE 23946 --- [nio-8080-exec-2] i.g.j.s.springex.JokoSecurityFilter      : Token received: eyJhbGciOiJIUzUxMiJ9.eyJzdWIiOiIxMDE1NTM2NDY3OTQyMTcxNSIsImV4cCI6MTUxMTkxODI0NiwiaWF0IjoxNTExOTA3NDQ2LCJqdGkiOiJVSkFDRUg3Sk1VSFk1N0JIU1FNUSIsImpva28iOnsidHlwZSI6IkFDQ0VTUyIsInJvbGVzIjpbIkVORF9VU0VSIl0sInByb2ZpbGUiOiJERUZBVUxUIn19.DrT4lsQfJXxVavm5joIDvp29DLeMmrYWiRzRuhjWEmr78_JKMxj1arrxDHgxVLxChTu4oeYBxDFPdd6HB_GoJw
2017-11-29 10:02:43.045 TRACE 23946 --- [nio-8080-exec-1] i.g.j.s.springex.JokoSecurityFilter      : Token received: eyJhbGciOiJIUzUxMiJ9.eyJzdWIiOiIxMDE1NTM2NDY3OTQyMTcxNSIsImV4cCI6MTUxMTkxODI0NiwiaWF0IjoxNTExOTA3NDQ2LCJqdGkiOiJVSkFDRUg3Sk1VSFk1N0JIU1FNUSIsImpva28iOnsidHlwZSI6IkFDQ0VTUyIsInJvbGVzIjpbIkVORF9VU0VSIl0sInByb2ZpbGUiOiJERUZBVUxUIn19.DrT4lsQfJXxVavm5joIDvp29DLeMmrYWiRzRuhjWEmr78_JKMxj1arrxDHgxVLxChTu4oeYBxDFPdd6HB_GoJw
2017-11-29 10:02:43.046 ERROR 23946 --- [nio-8080-exec-2] i.g.j.s.springex.JokoSecurityFilter      : Error validando el token.

io.jsonwebtoken.ExpiredJwtException: JWT expired at 2017-11-28T22:17:26-0300. Current time: 2017-11-29T10:02:43-0300
	at io.jsonwebtoken.impl.DefaultJwtParser.parse(DefaultJwtParser.java:365)
	at io.jsonwebtoken.impl.DefaultJwtParser.parse(DefaultJwtParser.java:458)
	at io.jsonwebtoken.impl.DefaultJwtParser.parseClaimsJws(DefaultJwtParser.java:518)
	at io.github.jokoframework.security.util.SecurityUtils.parseToken(SecurityUtils.java:227)
	at io.github.jokoframework.security.services.impl.TokenServiceImpl.parse(TokenServiceImpl.java:322)
	at io.github.jokoframework.security.services.impl.TokenServiceImpl$$FastClassBySpringCGLIB$$b683a18c.invoke(<generated>)
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:738)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
	at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:282)
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673)
	at io.github.jokoframework.security.services.impl.TokenServiceImpl$$EnhancerBySpringCGLIB$$8e6ca5e7.parse(<generated>)
	at io.github.jokoframework.security.springex.JokoSecurityFilter.validateToken(JokoSecurityFilter.java:97)
	at io.github.jokoframework.security.springex.JokoSecurityFilter.doFilter(JokoSecurityFilter.java:55)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
	at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:64)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
	at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
	at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:177)
	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:347)
	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:263)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:108)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:81)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:478)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1459)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:748)

Esto resulta muy inconveniente, puesto que no es un error y el log se va llenando de estas excepciones.

Evaluación de la causa

Examinando el código de Joko-security nos encontramos que en la clase JokoSecurityFilter (linea 72) se encuentra esta porción de código:

            } catch (IllegalArgumentException | JwtException var7) {
                String uri = httpRequest.getRequestURI();
                String userAgent = httpRequest.getHeader("User-Agent");
                LOGGER.debug(uri + " from User-Agent: " + userAgent + " Unable to authenticate " + var7.getClass() + ": " + var7.getMessage());
                LOGGER.trace("Token received: " + token);
                LOGGER.error("Error validando el token.", var7);
                return null;
            }

Como se puede ver la lina que imprime la excepción (var7) es la causante del problema. En mi opinión esto no debería de escribirse con un nivel tan alto de LOG (error actualmente) puesto que realmente no es un comportamiento erróneo del sistema, sino algo que naturalmente puede pasar. Esta excepción podría escribirse como máximo en TRACE.

Versiones afectadas

Todas, desde la actual (0.1.8) hacía atrás.