Spring boot interceptor getting called multiple time

Question

For each request interceptor is getting called almost about 10 to 15 times. here is the code...

@Component
public class CommonInterceptor implements HandlerInterceptor {
    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler)
            throws Exception {
        if (request.getDispatcherType().name().equals(DispatcherType.REQUEST.name()))
            System.out.println("Pre Handle method is Calling");
        return true;
    }

    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler,
            ModelAndView modelAndView) throws Exception {

        System.out.println("Post Handle method is Calling");
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler,
            Exception exception) throws Exception {

        System.out.println("Request and Response is completed");
    }
}

    @Configuration
public class CommonInterceptorAppConfig implements WebMvcConfigurer 
{
    @Autowired
    CommonInterceptor commonInterceptor;

    @Override
    public void addInterceptors(InterceptorRegistry registry) 
    {
        registry.addInterceptor(commonInterceptor);
    }
}

And I have normal rest controllers... This is the 1st time i'm adding question on stack overflow, so if there is any issue with indentation or anything... please ignore and do not roast me in the comments...

at the end of logs you'll see it has been called multiple time.... while login, prehandler method got printed then my authentication line got printed and at last same prehandler method got call multiple time...

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.1.3.RELEASE)

2020-03-20 23:36:49.861  INFO 4676 --- [  restartedMain] com.eps.Test       : Starting Test on DESKTOP-I6G5DLE with PID 4676 (started by rocky in E:\SpringBoot Project\eps)
2020-03-20 23:36:49.865  INFO 4676 --- [  restartedMain] com.eps.Test       : No active profile set, falling back to default profiles: default
2020-03-20 23:36:49.919  INFO 4676 --- [  restartedMain] .e.DevToolsPropertyDefaultsPostProcessor : Devtools property defaults active! Set 'spring.devtools.add-properties' to 'false' to disable
2020-03-20 23:36:49.919  INFO 4676 --- [  restartedMain] .e.DevToolsPropertyDefaultsPostProcessor : For additional web related logging consider setting the 'logging.level.web' property to 'DEBUG'
2020-03-20 23:36:50.810  INFO 4676 --- [  restartedMain] .s.d.r.c.RepositoryConfigurationDelegate : Multiple Spring Data modules found, entering strict repository configuration mode!
2020-03-20 23:36:50.811  INFO 4676 --- [  restartedMain] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data repositories in DEFAULT mode.
2020-03-20 23:36:50.830  INFO 4676 --- [  restartedMain] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 7ms. Found 0 repository interfaces.
2020-03-20 23:36:51.047  INFO 4676 --- [  restartedMain] .s.d.r.c.RepositoryConfigurationDelegate : Multiple Spring Data modules found, entering strict repository configuration mode!
2020-03-20 23:36:51.048  INFO 4676 --- [  restartedMain] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data repositories in DEFAULT mode.
2020-03-20 23:36:51.217  INFO 4676 --- [  restartedMain] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 167ms. Found 13 repository interfaces.
2020-03-20 23:36:51.224  INFO 4676 --- [  restartedMain] .s.d.r.c.RepositoryConfigurationDelegate : Multiple Spring Data modules found, entering strict repository configuration mode!
2020-03-20 23:36:51.224  INFO 4676 --- [  restartedMain] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data repositories in DEFAULT mode.
2020-03-20 23:36:51.238  INFO 4676 --- [  restartedMain] .RepositoryConfigurationExtensionSupport : Spring Data Redis - Could not safely identify store assignment for repository candidate interface com.eps.repositories.ActionMstRepository.
2020-03-20 23:36:51.239  INFO 4676 --- [  restartedMain] .RepositoryConfigurationExtensionSupport : Spring Data Redis - Could not safely identify store assignment for repository candidate interface com.eps.repositories.ChapterMstRepository.
2020-03-20 23:36:51.239  INFO 4676 --- [  restartedMain] .RepositoryConfigurationExtensionSupport : Spring Data Redis - Could not safely identify store assignment for repository candidate interface com.eps.repositories.CollegeMstRepository.
2020-03-20 23:36:51.240  INFO 4676 --- [  restartedMain] .RepositoryConfigurationExtensionSupport : Spring Data Redis - Could not safely identify store assignment for repository candidate interface com.eps.repositories.MediumMstRepository.
2020-03-20 23:36:51.240  INFO 4676 --- [  restartedMain] .RepositoryConfigurationExtensionSupport : Spring Data Redis - Could not safely identify store assignment for repository candidate interface com.eps.repositories.MenuMstRepository.
2020-03-20 23:36:51.240  INFO 4676 --- [  restartedMain] .RepositoryConfigurationExtensionSupport : Spring Data Redis - Could not safely identify store assignment for repository candidate interface com.eps.repositories.OrganisationMstRepository.
2020-03-20 23:36:51.241  INFO 4676 --- [  restartedMain] .RepositoryConfigurationExtensionSupport : Spring Data Redis - Could not safely identify store assignment for repository candidate interface com.eps.repositories.RoleMstRepository.
2020-03-20 23:36:51.241  INFO 4676 --- [  restartedMain] .RepositoryConfigurationExtensionSupport : Spring Data Redis - Could not safely identify store assignment for repository candidate interface com.eps.repositories.StandardMstRepository.
2020-03-20 23:36:51.243  INFO 4676 --- [  restartedMain] .RepositoryConfigurationExtensionSupport : Spring Data Redis - Could not safely identify store assignment for repository candidate interface com.eps.repositories.SubjectMstRepository.
2020-03-20 23:36:51.244  INFO 4676 --- [  restartedMain] .RepositoryConfigurationExtensionSupport : Spring Data Redis - Could not safely identify store assignment for repository candidate interface com.eps.repositories.UniversityMstRepository.
2020-03-20 23:36:51.244  INFO 4676 --- [  restartedMain] .RepositoryConfigurationExtensionSupport : Spring Data Redis - Could not safely identify store assignment for repository candidate interface com.eps.repositories.UserMenuRepository.
2020-03-20 23:36:51.246  INFO 4676 --- [  restartedMain] .RepositoryConfigurationExtensionSupport : Spring Data Redis - Could not safely identify store assignment for repository candidate interface com.eps.repositories.UserRepository.
2020-03-20 23:36:51.256  INFO 4676 --- [  restartedMain] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 31ms. Found 1 repository interfaces.
2020-03-20 23:36:51.819  INFO 4676 --- [  restartedMain] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration' of type [org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration$$EnhancerBySpringCGLIB$$fc51ac80] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-03-20 23:36:52.365  INFO 4676 --- [  restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8082 (http)
2020-03-20 23:36:52.404  INFO 4676 --- [  restartedMain] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2020-03-20 23:36:52.404  INFO 4676 --- [  restartedMain] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.16]
2020-03-20 23:36:52.412  INFO 4676 --- [  restartedMain] o.a.catalina.core.AprLifecycleListener   : The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: [C:\Program Files\Java\jre1.8.0_211\bin;C:\WINDOWS\Sun\Java\bin;C:\WINDOWS\system32;C:\WINDOWS;C:/Program Files/Java/jre1.8.0_211/bin/server;C:/Program Files/Java/jre1.8.0_211/bin;C:/Program Files/Java/jre1.8.0_211/lib/amd64;C:\Program Files (x86)\Common Files\Oracle\Java\javapath;C:\ProgramData\Oracle\Java\javapath;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\WINDOWS\System32\WindowsPowerShell\v1.0\;C:\Program Files (x86)\ATI Technologies\ATI.ACE\Core-Static;C:\Program Files (x86)\CrSSL\bin;C:\WINDOWS\System32\OpenSSH\;E:\apache-maven-3.6.0\bin;C:\Program Files\Git\cmd;C:\Program Files\nodejs\;C:\Users\rocky\AppData\Local\Microsoft\WindowsApps;C:\Program Files\Java\jdk1.8.0_211\bin;C:\Users\rocky\AppData\Local\Programs\Microsoft VS Code\bin;"C:\WINDOWS\system32;";C:\Users\rocky\AppData\Roaming\npm;;E:\Software\sts-4.2.1.RELEASE;;.]
2020-03-20 23:36:52.792  INFO 4676 --- [  restartedMain] org.apache.jasper.servlet.TldScanner     : At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
2020-03-20 23:36:52.798  INFO 4676 --- [  restartedMain] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2020-03-20 23:36:52.798  INFO 4676 --- [  restartedMain] o.s.web.context.ContextLoader            : Root WebApplicationContext: initialization completed in 2879 ms
2020-03-20 23:36:53.106  INFO 4676 --- [  restartedMain] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Starting...
2020-03-20 23:36:53.233  INFO 4676 --- [  restartedMain] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Start completed.
2020-03-20 23:36:53.300  INFO 4676 --- [  restartedMain] o.hibernate.jpa.internal.util.LogHelper  : HHH000204: Processing PersistenceUnitInfo [
    name: default
    ...]
2020-03-20 23:36:53.377  INFO 4676 --- [  restartedMain] org.hibernate.Version                    : HHH000412: Hibernate Core {5.3.7.Final}
2020-03-20 23:36:53.381  INFO 4676 --- [  restartedMain] org.hibernate.cfg.Environment            : HHH000206: hibernate.properties not found
2020-03-20 23:36:53.559  INFO 4676 --- [  restartedMain] o.hibernate.annotations.common.Version   : HCANN000001: Hibernate Commons Annotations {5.0.4.Final}
2020-03-20 23:36:54.234  INFO 4676 --- [  restartedMain] org.hibernate.dialect.Dialect            : HHH000400: Using dialect: org.hibernate.dialect.MySQL5Dialect
2020-03-20 23:36:55.199  INFO 4676 --- [  restartedMain] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
2020-03-20 23:36:55.863  INFO 4676 --- [  restartedMain] o.s.b.d.a.OptionalLiveReloadServer       : LiveReload server is running on port 35729
2020-03-20 23:36:56.192  INFO 4676 --- [  restartedMain] o.s.s.web.DefaultSecurityFilterChain     : Creating filter chain: any request, [org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter@6c46a704, org.springframework.security.web.context.SecurityContextPersistenceFilter@432fd22b, org.springframework.security.web.header.HeaderWriterFilter@1fb4d30b, org.springframework.security.web.authentication.logout.LogoutFilter@5e9dcc85, org.springframework.security.web.authentication.UsernamePasswordAuthenticationFilter@5738e034, org.springframework.security.web.savedrequest.RequestCacheAwareFilter@436619c, org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter@5d8e8d49, org.springframework.security.web.authentication.AnonymousAuthenticationFilter@754b7f0, org.springframework.security.web.session.SessionManagementFilter@53bfc5e4, org.springframework.security.web.access.ExceptionTranslationFilter@601e128d, org.springframework.security.web.access.intercept.FilterSecurityInterceptor@5e5ccd5c]
2020-03-20 23:36:56.390  INFO 4676 --- [  restartedMain] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService 'applicationTaskExecutor'
2020-03-20 23:36:56.427  WARN 4676 --- [  restartedMain] aWebConfiguration$JpaWebMvcConfiguration : spring.jpa.open-in-view is enabled by default. Therefore, database queries may be performed during view rendering. Explicitly configure spring.jpa.open-in-view to disable this warning
2020-03-20 23:36:57.696  INFO 4676 --- [  restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8082 (http) with context path ''
2020-03-20 23:36:57.699  INFO 4676 --- [  restartedMain] com.eps.Test       : Started Test in 8.334 seconds (JVM running for 9.851)
2020-03-20 23:42:10.598  INFO 11544 --- [nio-8082-exec-2] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2020-03-20 23:42:10.598  INFO 11544 --- [nio-8082-exec-2] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2020-03-20 23:42:10.614  INFO 11544 --- [nio-8082-exec-2] o.s.web.servlet.DispatcherServlet        : Completed initialization in 16 ms
2020-03-20 23:42:10.793  INFO 11544 --- [nio-8082-exec-2] o.h.h.i.QueryTranslatorFactoryInitiator  : HHH000397: Using ASTQueryTranslatorFactory
Pre Handle method is Calling
inside dashboard username = com.eps.helper.UserPrincipal@7f5b0017 --- 1001 password = null
Pre Handle method is Calling
Pre Handle method is Calling
Pre Handle method is Calling
Pre Handle method is Calling
Pre Handle method is Calling
Pre Handle method is Calling
Pre Handle method is Calling
Pre Handle method is Calling
Pre Handle method is Calling
Pre Handle method is Calling
Pre Handle method is Calling
Pre Handle method is Calling
Pre Handle method is Calling
Pre Handle method is Calling
Pre Handle method is Calling
Pre Handle method is Calling
Pre Handle method is Calling
Pre Handle method is Calling
Pre Handle method is Calling
Pre Handle method is Calling
Pre Handle method is Calling

Concur

Can you put some logs of your application here? It will be easier to understand. – Fairhaired

@RajanPrasad...as you can see in the log.. while login, prehandler method got printed then my authentication line got printed and at last same prehandler method got call multiple time... – Concur

try printing details of the HttpServeletRequest , like request.getRequestURI() and others. You will get an idea which endpoint is being hit again and again. I have a feeling you might have a health check agent running on your machine. @rakesh prajapati – Fairhaired

Answer 1

It was getting called for each and every js and css files... So by adding my application url prefix in addPathPatterns, it is getting call only once.

@Configuration
public class CommonInterceptorAppConfig implements WebMvcConfigurer 
{
    @Autowired
    CommonInterceptor commonInterceptor;

    @Override
    public void addInterceptors(InterceptorRegistry registry) 
    {
        registry.addInterceptor(commonInterceptor).addPathPatterns("/application/**");
    }
}

Concur

Answer 2

I solved this issue by the following approach, avoiding the double interceptor registation:

import lombok.extern.slf4j.Slf4j;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.stereotype.Component;
import org.springframework.web.servlet.config.annotation.InterceptorRegistry;
import org.springframework.web.servlet.config.annotation.WebMvcConfigurer;

@Slf4j
@Component
public class JwtConfiguration implements WebMvcConfigurer {

    private static boolean alreadyRegistered = false;

    @Autowired
    private JwtInterceptor jwtInterceptor;

    @Override
    public void addInterceptors(InterceptorRegistry registry) {

        if (alreadyRegistered) {

            if (log.isWarnEnabled()) {
                log.warn("JWT interceptor already registered. Skipped.");
            }

        } else {

            alreadyRegistered = true;
            registry.addInterceptor(jwtInterceptor);

            if (log.isInfoEnabled()) {
                log.info("JWT interceptor registered.");
            }

        }
      
    }

}

Albers