User id isn't shown in log message for some errors

[php-coder]

There at least 2 cases when userId isn't logged for logged in user:

1. when we trigger an error like this: //404 In this case we got RequestRejectedException (that shouldn't be there actually, see RequestRejectedExceptions pollute logs #1068)

Example:

2019-07-29 00:23:56.694 [user:   ]  WARN 11130 --- [qtp335915908-34] o.eclipse.jetty.servlet.ServletHandler   : //404

org.springframework.security.web.firewall.RequestRejectedException: The request was rejected because the URL was not normalized.
	at org.springframework.security.web.firewall.StrictHttpFirewall.getFirewalledRequest(StrictHttpFirewall.java:248) ~[spring-security-web-4.2.12.RELEASE.jar:4.2.12.RELEASE]
	at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:193) ~[spring-security-web-4.2.12.RELEASE.jar:4.2.12.RELEASE]
	at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:177) ~[spring-security-web-4.2.12.RELEASE.jar:4.2.12.RELEASE]
	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:347) ~[spring-web-4.3.24.RELEASE.jar:4.3.24.RELEASE]
	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:263) ~[spring-web-4.3.24.RELEASE.jar:4.3.24.RELEASE]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652) ~[jetty-servlet-9.2.28.v20190418.jar:9.2.28.v20190418]
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99) ~[spring-web-4.3.24.RELEASE.jar:4.3.24.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.24.RELEASE.jar:4.3.24.RELEASE]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652) ~[jetty-servlet-9.2.28.v20190418.jar:9.2.28.v20190418]
	at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:109) ~[spring-web-4.3.24.RELEASE.jar:4.3.24.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.24.RELEASE.jar:4.3.24.RELEASE]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652) ~[jetty-servlet-9.2.28.v20190418.jar:9.2.28.v20190418]
	at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:93) ~[spring-web-4.3.24.RELEASE.jar:4.3.24.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.24.RELEASE.jar:4.3.24.RELEASE]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652) ~[jetty-servlet-9.2.28.v20190418.jar:9.2.28.v20190418]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:585) [jetty-servlet-9.2.28.v20190418.jar:9.2.28.v20190418]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) [jetty-server-9.2.28.v20190418.jar:9.2.28.v20190418]
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:577) [jetty-security-9.2.28.v20190418.jar:9.2.28.v20190418]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:223) [jetty-server-9.2.28.v20190418.jar:9.2.28.v20190418]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127) [jetty-server-9.2.28.v20190418.jar:9.2.28.v20190418]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515) [jetty-servlet-9.2.28.v20190418.jar:9.2.28.v20190418]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) [jetty-server-9.2.28.v20190418.jar:9.2.28.v20190418]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061) [jetty-server-9.2.28.v20190418.jar:9.2.28.v20190418]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [jetty-server-9.2.28.v20190418.jar:9.2.28.v20190418]
	at org.eclipse.jetty.servlets.gzip.GzipHandler.handle(GzipHandler.java:479) [jetty-servlets-9.2.28.v20190418.jar:9.2.28.v20190418]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) [jetty-server-9.2.28.v20190418.jar:9.2.28.v20190418]
	at org.eclipse.jetty.server.Server.handle(Server.java:499) [jetty-server-9.2.28.v20190418.jar:9.2.28.v20190418]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311) [jetty-server-9.2.28.v20190418.jar:9.2.28.v20190418]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:258) [jetty-server-9.2.28.v20190418.jar:9.2.28.v20190418]
	at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544) [jetty-io-9.2.28.v20190418.jar:9.2.28.v20190418]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635) [jetty-util-9.2.28.v20190418.jar:9.2.28.v20190418]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555) [jetty-util-9.2.28.v20190418.jar:9.2.28.v20190418]
	at java.lang.Thread.run(Thread.java:748) [na:1.8.0_202]

2. in another case, we got 404 error for a long URL. In this case, we able to get userId and even saves it to database, but a log message doesn't include it.

Example:

2019-07-29 22:04:13.364 [user:  ] DEBUG 12600 --- [tp1108322555-34] r.m.w.s.s.s.CustomUserDetailsService     : Find user by login 'admin'
2019-07-29 22:04:13.367 [user:  ] DEBUG 12600 --- [tp1108322555-34] r.m.w.s.s.s.CustomUserDetailsService     : User 'admin' found
2019-07-29 22:04:37.621 [user:  ]  WARN 12600 --- [cTaskExecutor-2] r.m.web.feature.site.SiteServiceImpl     : Length of '/testtesttest/testtesttest/testtesttest/testtesttest/testtesttest/testtesttest/testtesttest/testtesttest/testtesttest/testtesttest/testtesttest/testtesttest/testtesttest/testtesttest/testtesttest/testtesttest/testtesttest/testtesttest/testtesttest/testtesttest/testtesttest/testtesttest/testtesttest/testtesttest/testtesttest/testtesttest/testtesttest/testtesttest/testtesttest' exceeds max length for 'page' field: 377 > 100

Tech debt for: 742ca80 (#1102)

[php-coder]

The first case doesn't work because Spring Security filters are being executed before UserMdcLoggingFilter, so the request is being rejected on a stage earlier.

But it's not clear why the second case isn't work either. As far I understand, not found page is generated by Spring servlet that should be executed after our filter and should have MDC already. I've tried to print stacktrace in this case and I saw that it was executed on another thread. So, it seems that this is related to ASYNC processing. Also, it's related to ERROR pages. I've tried to map a filter to such dispatcher types, but without luck. Here is my attempt, for history and next attempts:

--- src/main/java/ru/mystamps/web/support/spring/security/SecurityConfig.java
+++ src/main/java/ru/mystamps/web/support/spring/security/SecurityConfig.java
@@ -54,6 +54,7 @@ import ru.mystamps.web.feature.series.importing.sale.SeriesSalesImportUrl;
 import ru.mystamps.web.feature.site.SiteService;
 import ru.mystamps.web.feature.site.SiteUrl;

+import javax.servlet.DispatcherType;
 import javax.servlet.Filter;
 import java.util.Collections;

@@ -209,6 +210,7 @@ public class SecurityConfig extends WebSecurityConfigurerAdapter {
                        new UserMdcLoggingFilter()
                );
                bean.addUrlPatterns("/*");
+               bean.setDispatcherTypes(DispatcherType.REQUEST, DispatcherType.ERROR, DispatcherType.FORWARD, DispatcherType.INCLUDE, DispatcherType.ASYNC);
                return bean;
        }

diff --git src/main/java/ru/mystamps/web/support/spring/security/UserMdcLoggingFilter.java src/main/java/ru/mystamps/web/support/spring/security/UserMdcLoggingFilter.java
index 72475630..5a30e6a5 100644
--- src/main/java/ru/mystamps/web/support/spring/security/UserMdcLoggingFilter.java
+++ src/main/java/ru/mystamps/web/support/spring/security/UserMdcLoggingFilter.java
@@ -48,4 +48,14 @@ public class UserMdcLoggingFilter extends OncePerRequestFilter {
                }
        }

+       @Override
+       protected boolean shouldNotFilterAsyncDispatch() {
+               return false;
+       }
+
+       @Override
+       protected boolean shouldNotFilterErrorDispatch() {
+               return false;
+       }
+
 }

[php-coder]

More cases (perhaps, they are different):

2020-02-01 01:52:40.017 [user:2 ]  INFO 28919 --- [tp1205445235-16] r.m.w.f.s.sale.SeriesSalesServiceImpl    : Sale for series #237 has been added by user #2
2020-02-01 01:52:41.046 [user:  ] DEBUG 28919 --- [tp1205445235-17] r.m.w.f.image.TimedImagePreviewStrategy  : Image preview has been generated in 90 msecs: 103499 -> 9546 bytes
2020-02-01 01:52:41.055 [user:  ]  INFO 28919 --- [tp1205445235-17] w.f.i.FilesystemImagePersistenceStrategy : Image preview data has been written into file /data/preview/303.jpeg

Because an image preview is generated on another thread, the user id is missing.

[php-coder]

Another case: duplicate key exception after a series creation

2020-02-22 01:03:35.512 [user:2 ] INFO 26210 --- [tp1276709283-45] o.s.b.f.xml.XmlBeanDefinitionReader : Loading XML bean definitions from class path resource [org/springframework/jdbc/support/sql-error-codes.xml]
2020-02-22 01:03:35.689 [user: ] WARN 26210 --- [tp1276709283-45] org.eclipse.jetty.server.HttpChannel : /series/import/request/56
org.springframework.web.util.NestedServletException: Request processing failed; nested exception is org.springframework.dao.DuplicateKeyException: PreparedStatementCallback; SQL [INSERT INTO transaction_participants ( name , url , is_buyer , is_seller , group_id ) VALUES ( ? , ? , ? , ? , ? )]; Duplicate entry 'xxx-http://xxx' for key 'uc_transaction_participants_name_url'; nested exception is com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException: Duplicate entry 'xxx-http://xxx' for key 'uc_transaction_participants_name_url'