I'm using spring boot 2.3.3.RELEASE with websocket support and RabbitMQ as external broker with stomp support.
The issue is that the client keeps on getting a heartbeat message "\n" every +-15 secs even though the client negotiated the heatbeat as "0, 30000" during the CONNECT request as suggested in this documentation on heart-beat header support with stomp in RabbitMQ. By turning on trace log I was able to find that ExecutorSubscribableChannel has a run() method that gets executed by a ThreadPoolExecutor every +-15 secs, which in turn sends that heartbeat message. I'm not sure if its a bug or I'm missing some configuration on my side. Any help would be appreciated.
Comment From: rstoyanchev
Thanks for getting in touch, but it feels like this is a question that would be better suited to Stack Overflow. As mentioned in the guidelines for contributing, we prefer to use the issue tracker only for bugs and enhancements. Feel free to update this issue with a link to the re-posted question (so that other people can find it) or add some more details if you feel this is a genuine bug.
I suggest taking a look at the logs for the actually negotiated heartbeat settings. Those would be in the CONNECT and CONNECTED frames. The heartbeats are originating from the client and the broker respectively so focus on those. The ExecutorSubscribableChannel is just passing messages through.
Comment From: rstoyanchev
Re-opened in light of the provided further information under #25825 and sample project https://github.com/prinal10/websocketbugdemo.
Comment From: rstoyanchev
@prinal10 from the log pictures under @25825 I do see that the client CONNECT frame asks to receive heartbeats every 30 seconds with [0,30000]. Unfortunately the log picture cuts off the content of the CONNECTED frame and it doesn't show me what the server agreed to do.
Subsequently the logs show that there are two heartbeats coming at 15 seconds apart but those are coming from RabbitMQ. In this case Spring is simply relaying the messages to and from the server. It is not generating the heartbeats.
Comment From: prinal10
@rstoyanchev I apologize for creating a new issue. Im not familiar with filling issues on github. Thanks for your kind feedback. Below are the text logs after the user has send and successfully CONNECTED and SUBCRIBED. Please read further below
2020-09-30 23:46:37.903 DEBUG 17840 --- [93-ClientPoller] org.apache.tomcat.util.net.NioEndpoint : timeout completed: keys processed=0; now=1601531197903; nextExpiration=1601531197902; keyCount=0; hasEvents=false; eval=false
2020-09-30 23:46:38.903 DEBUG 17840 --- [93-ClientPoller] org.apache.tomcat.util.net.NioEndpoint : timeout completed: keys processed=0; now=1601531198903; nextExpiration=1601531198903; keyCount=0; hasEvents=false; eval=false
2020-09-30 23:46:39.904 DEBUG 17840 --- [93-ClientPoller] org.apache.tomcat.util.net.NioEndpoint : timeout completed: keys processed=0; now=1601531199904; nextExpiration=1601531199903; keyCount=0; hasEvents=false; eval=false
2020-09-30 23:46:40.507 DEBUG 17840 --- [o-8093-Acceptor] o.apache.tomcat.util.threads.LimitLatch : Counting up[http-nio-8093-Acceptor] latch=1
2020-09-30 23:46:40.528 DEBUG 17840 --- [nio-8093-exec-1] o.a.coyote.http11.Http11InputBuffer : Before fill(): [true], parsingRequestLine: [true], parsingRequestLinePhase: [0], parsingRequestLineStart: [0], byteBuffer.position() [0]
2020-09-30 23:46:40.528 DEBUG 17840 --- [nio-8093-exec-1] o.a.tomcat.util.net.SocketWrapperBase : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1a36ac3f:org.apache.tomcat.util.net.NioChannel@132b7e4c:java.nio.channels.SocketChannel[connected local=/127.0.0.1:8093 remote=/127.0.0.1:63561]], Read from buffer: [0]
2020-09-30 23:46:40.528 DEBUG 17840 --- [nio-8093-exec-1] org.apache.tomcat.util.net.NioEndpoint : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1a36ac3f:org.apache.tomcat.util.net.NioChannel@132b7e4c:java.nio.channels.SocketChannel[connected local=/127.0.0.1:8093 remote=/127.0.0.1:63561]], Read direct from socket: [198]
2020-09-30 23:46:40.528 DEBUG 17840 --- [nio-8093-exec-1] o.a.coyote.http11.Http11InputBuffer : Received [GET /secured/user HTTP/1.1
User-Agent: websocket-sharp/1.0
Host: localhost:8093
Upgrade: websocket
Connection: Upgrade
Sec-WebSocket-Key: i3kundhrnFEnB/fkfoDFQw==
Sec-WebSocket-Version: 13
]
2020-09-30 23:46:40.540 DEBUG 17840 --- [nio-8093-exec-1] org.apache.tomcat.util.http.Parameters : Set query string encoding to UTF-8
2020-09-30 23:46:40.542 DEBUG 17840 --- [nio-8093-exec-1] o.a.c.authenticator.AuthenticatorBase : Security checking request GET /secured/user
2020-09-30 23:46:40.543 DEBUG 17840 --- [nio-8093-exec-1] org.apache.catalina.realm.RealmBase : No applicable constraints defined
2020-09-30 23:46:40.545 DEBUG 17840 --- [nio-8093-exec-1] o.a.c.a.jaspic.AuthConfigFactoryImpl : Loading persistent provider registrations from [C:\Users\Prinalchandra.Patel\AppData\Local\Temp\tomcat.11803885424770645219.8093\conf\jaspic-providers.xml]
2020-09-30 23:46:40.545 DEBUG 17840 --- [nio-8093-exec-1] o.a.c.authenticator.AuthenticatorBase : Not subject to any constraint
2020-09-30 23:46:40.547 INFO 17840 --- [nio-8093-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring DispatcherServlet 'dispatcherServlet'
2020-09-30 23:46:40.547 INFO 17840 --- [nio-8093-exec-1] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
2020-09-30 23:46:40.547 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'multipartResolver'
2020-09-30 23:46:40.547 TRACE 17840 --- [nio-8093-exec-1] o.s.web.servlet.DispatcherServlet : Detected org.springframework.web.multipart.support.StandardServletMultipartResolver@2601347d
2020-09-30 23:46:40.547 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : No bean named 'localeResolver' found in org.springframework.beans.factory.support.DefaultListableBeanFactory@4052274f: defining beans [org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor,org.springframework.context.event.internalEventListenerProcessor,org.springframework.context.event.internalEventListenerFactory,websocketbugdemoApplication,org.springframework.boot.autoconfigure.internalCachingMetadataReaderFactory,webSocketConfig,org.springframework.web.socket.config.annotation.DelegatingWebSocketMessageBrokerConfiguration,stompWebSocketHandlerMapping,subProtocolWebSocketHandler,webSocketScopeConfigurer,webSocketMessageBrokerStats,clientInboundChannel,clientInboundChannelExecutor,clientOutboundChannel,clientOutboundChannelExecutor,brokerChannel,brokerChannelExecutor,simpAnnotationMethodMessageHandler,simpleBrokerMessageHandler,stompBrokerRelayMessageHandler,userDestinationMessageHandler,userRegistryMessageHandler,messageBrokerTaskScheduler,brokerMessagingTemplate,brokerMessageConverter,userDestinationResolver,userRegistry,org.springframework.boot.autoconfigure.AutoConfigurationPackages,org.springframework.boot.autoconfigure.context.PropertyPlaceholderAutoConfiguration,propertySourcesPlaceholderConfigurer,org.springframework.boot.autoconfigure.websocket.servlet.WebSocketServletAutoConfiguration$TomcatWebSocketConfiguration,websocketServletWebServerCustomizer,org.springframework.boot.autoconfigure.websocket.servlet.WebSocketServletAutoConfiguration,org.springframework.boot.autoconfigure.web.servlet.ServletWebServerFactoryConfiguration$EmbeddedTomcat,tomcatServletWebServerFactory,org.springframework.boot.autoconfigure.web.servlet.ServletWebServerFactoryAutoConfiguration,servletWebServerFactoryCustomizer,tomcatServletWebServerFactoryCustomizer,org.springframework.boot.context.properties.ConfigurationPropertiesBindingPostProcessor,org.springframework.boot.context.internalConfigurationPropertiesBinderFactory,org.springframework.boot.context.internalConfigurationPropertiesBinder,org.springframework.boot.context.properties.BoundConfigurationProperties,org.springframework.boot.context.properties.ConfigurationBeanFactoryMetadata,server-org.springframework.boot.autoconfigure.web.ServerProperties,webServerFactoryCustomizerBeanPostProcessor,errorPageRegistrarBeanPostProcessor,org.springframework.boot.autoconfigure.web.servlet.DispatcherServletAutoConfiguration$DispatcherServletConfiguration,dispatcherServlet,spring.mvc-org.springframework.boot.autoconfigure.web.servlet.WebMvcProperties,org.springframework.boot.autoconfigure.web.servlet.DispatcherServletAutoConfiguration$DispatcherServletRegistrationConfiguration,dispatcherServletRegistration,org.springframework.boot.autoconfigure.web.servlet.DispatcherServletAutoConfiguration,org.springframework.boot.autoconfigure.task.TaskExecutionAutoConfiguration,taskExecutorBuilder,spring.task.execution-org.springframework.boot.autoconfigure.task.TaskExecutionProperties,org.springframework.boot.autoconfigure.web.servlet.error.ErrorMvcAutoConfiguration$WhitelabelErrorViewConfiguration,error,beanNameViewResolver,org.springframework.boot.autoconfigure.web.servlet.error.ErrorMvcAutoConfiguration$DefaultErrorViewResolverConfiguration,conventionErrorViewResolver,org.springframework.boot.autoconfigure.web.servlet.error.ErrorMvcAutoConfiguration,errorAttributes,basicErrorController,errorPageCustomizer,preserveErrorControllerTargetClassPostProcessor,spring.resources-org.springframework.boot.autoconfigure.web.ResourceProperties,org.springframework.boot.autoconfigure.web.servlet.WebMvcAutoConfiguration$EnableWebMvcConfiguration,requestMappingHandlerAdapter,requestMappingHandlerMapping,welcomePageHandlerMapping,mvcConversionService,mvcValidator,mvcContentNegotiationManager,mvcPathMatcher,mvcUrlPathHelper,viewControllerHandlerMapping,beanNameHandlerMapping,routerFunctionMapping,resourceHandlerMapping,mvcResourceUrlProvider,defaultServletHandlerMapping,handlerFunctionAdapter,mvcUriComponentsContributor,httpRequestHandlerAdapter,simpleControllerHandlerAdapter,handlerExceptionResolver,mvcViewResolver,mvcHandlerMappingIntrospector,org.springframework.boot.autoconfigure.web.servlet.WebMvcAutoConfiguration$WebMvcAutoConfigurationAdapter,defaultViewResolver,viewResolver,requestContextFilter,org.springframework.boot.autoconfigure.web.servlet.WebMvcAutoConfiguration,formContentFilter,org.springframework.boot.autoconfigure.jmx.JmxAutoConfiguration,mbeanExporter,objectNamingStrategy,mbeanServer,org.springframework.boot.autoconfigure.admin.SpringApplicationAdminJmxAutoConfiguration,springApplicationAdminRegistrar,org.springframework.boot.autoconfigure.aop.AopAutoConfiguration$ClassProxyingConfiguration,org.springframework.boot.autoconfigure.aop.AopAutoConfiguration,org.springframework.boot.autoconfigure.availability.ApplicationAvailabilityAutoConfiguration,applicationAvailability,org.springframework.boot.autoconfigure.context.ConfigurationPropertiesAutoConfiguration,org.springframework.boot.autoconfigure.context.LifecycleAutoConfiguration,lifecycleProcessor,spring.lifecycle-org.springframework.boot.autoconfigure.context.LifecycleProperties,org.springframework.boot.autoconfigure.jackson.JacksonAutoConfiguration$Jackson2ObjectMapperBuilderCustomizerConfiguration,standardJacksonObjectMapperBuilderCustomizer,spring.jackson-org.springframework.boot.autoconfigure.jackson.JacksonProperties,org.springframework.boot.autoconfigure.jackson.JacksonAutoConfiguration$JacksonObjectMapperBuilderConfiguration,jacksonObjectMapperBuilder,org.springframework.boot.autoconfigure.jackson.JacksonAutoConfiguration$ParameterNamesModuleConfiguration,parameterNamesModule,org.springframework.boot.autoconfigure.jackson.JacksonAutoConfiguration$JacksonObjectMapperConfiguration,jacksonObjectMapper,org.springframework.boot.autoconfigure.jackson.JacksonAutoConfiguration,jsonComponentModule,org.springframework.boot.autoconfigure.http.HttpMessageConvertersAutoConfiguration$StringHttpMessageConverterConfiguration,stringHttpMessageConverter,org.springframework.boot.autoconfigure.http.JacksonHttpMessageConvertersConfiguration$MappingJackson2HttpMessageConverterConfiguration,mappingJackson2HttpMessageConverter,org.springframework.boot.autoconfigure.http.JacksonHttpMessageConvertersConfiguration,org.springframework.boot.autoconfigure.http.HttpMessageConvertersAutoConfiguration,messageConverters,org.springframework.boot.autoconfigure.info.ProjectInfoAutoConfiguration,spring.info-org.springframework.boot.autoconfigure.info.ProjectInfoProperties,org.springframework.boot.autoconfigure.task.TaskSchedulingAutoConfiguration,taskSchedulerBuilder,spring.task.scheduling-org.springframework.boot.autoconfigure.task.TaskSchedulingProperties,org.springframework.boot.autoconfigure.web.client.RestTemplateAutoConfiguration,restTemplateBuilder,org.springframework.boot.autoconfigure.web.embedded.EmbeddedWebServerFactoryCustomizerAutoConfiguration$NettyWebServerFactoryCustomizerConfiguration,nettyWebServerFactoryCustomizer,org.springframework.boot.autoconfigure.web.embedded.EmbeddedWebServerFactoryCustomizerAutoConfiguration$TomcatWebServerFactoryCustomizerConfiguration,tomcatWebServerFactoryCustomizer,org.springframework.boot.autoconfigure.web.embedded.EmbeddedWebServerFactoryCustomizerAutoConfiguration,org.springframework.boot.autoconfigure.web.servlet.HttpEncodingAutoConfiguration,characterEncodingFilter,localeCharsetMappingsCustomizer,org.springframework.boot.autoconfigure.web.servlet.MultipartAutoConfiguration,multipartConfigElement,multipartResolver,spring.servlet.multipart-org.springframework.boot.autoconfigure.web.servlet.MultipartProperties,org.springframework.boot.autoconfigure.websocket.servlet.WebSocketMessagingAutoConfiguration$WebSocketMessageConverterConfiguration,eagerStompWebSocketHandlerMapping,org.springframework.boot.autoconfigure.websocket.servlet.WebSocketMessagingAutoConfiguration,org.springframework.aop.config.internalAutoProxyCreator]; root of factory hierarchy
2020-09-30 23:46:40.548 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Creating instance of bean 'org.springframework.web.servlet.i18n.AcceptHeaderLocaleResolver'
2020-09-30 23:46:40.549 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Finished creating instance of bean 'org.springframework.web.servlet.i18n.AcceptHeaderLocaleResolver'
2020-09-30 23:46:40.549 TRACE 17840 --- [nio-8093-exec-1] o.s.web.servlet.DispatcherServlet : No LocaleResolver 'localeResolver': using default [AcceptHeaderLocaleResolver]
2020-09-30 23:46:40.549 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : No bean named 'themeResolver' found in org.springframework.beans.factory.support.DefaultListableBeanFactory@4052274f: defining beans [org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor,org.springframework.context.event.internalEventListenerProcessor,org.springframework.context.event.internalEventListenerFactory,websocketbugdemoApplication,org.springframework.boot.autoconfigure.internalCachingMetadataReaderFactory,webSocketConfig,org.springframework.web.socket.config.annotation.DelegatingWebSocketMessageBrokerConfiguration,stompWebSocketHandlerMapping,subProtocolWebSocketHandler,webSocketScopeConfigurer,webSocketMessageBrokerStats,clientInboundChannel,clientInboundChannelExecutor,clientOutboundChannel,clientOutboundChannelExecutor,brokerChannel,brokerChannelExecutor,simpAnnotationMethodMessageHandler,simpleBrokerMessageHandler,stompBrokerRelayMessageHandler,userDestinationMessageHandler,userRegistryMessageHandler,messageBrokerTaskScheduler,brokerMessagingTemplate,brokerMessageConverter,userDestinationResolver,userRegistry,org.springframework.boot.autoconfigure.AutoConfigurationPackages,org.springframework.boot.autoconfigure.context.PropertyPlaceholderAutoConfiguration,propertySourcesPlaceholderConfigurer,org.springframework.boot.autoconfigure.websocket.servlet.WebSocketServletAutoConfiguration$TomcatWebSocketConfiguration,websocketServletWebServerCustomizer,org.springframework.boot.autoconfigure.websocket.servlet.WebSocketServletAutoConfiguration,org.springframework.boot.autoconfigure.web.servlet.ServletWebServerFactoryConfiguration$EmbeddedTomcat,tomcatServletWebServerFactory,org.springframework.boot.autoconfigure.web.servlet.ServletWebServerFactoryAutoConfiguration,servletWebServerFactoryCustomizer,tomcatServletWebServerFactoryCustomizer,org.springframework.boot.context.properties.ConfigurationPropertiesBindingPostProcessor,org.springframework.boot.context.internalConfigurationPropertiesBinderFactory,org.springframework.boot.context.internalConfigurationPropertiesBinder,org.springframework.boot.context.properties.BoundConfigurationProperties,org.springframework.boot.context.properties.ConfigurationBeanFactoryMetadata,server-org.springframework.boot.autoconfigure.web.ServerProperties,webServerFactoryCustomizerBeanPostProcessor,errorPageRegistrarBeanPostProcessor,org.springframework.boot.autoconfigure.web.servlet.DispatcherServletAutoConfiguration$DispatcherServletConfiguration,dispatcherServlet,spring.mvc-org.springframework.boot.autoconfigure.web.servlet.WebMvcProperties,org.springframework.boot.autoconfigure.web.servlet.DispatcherServletAutoConfiguration$DispatcherServletRegistrationConfiguration,dispatcherServletRegistration,org.springframework.boot.autoconfigure.web.servlet.DispatcherServletAutoConfiguration,org.springframework.boot.autoconfigure.task.TaskExecutionAutoConfiguration,taskExecutorBuilder,spring.task.execution-org.springframework.boot.autoconfigure.task.TaskExecutionProperties,org.springframework.boot.autoconfigure.web.servlet.error.ErrorMvcAutoConfiguration$WhitelabelErrorViewConfiguration,error,beanNameViewResolver,org.springframework.boot.autoconfigure.web.servlet.error.ErrorMvcAutoConfiguration$DefaultErrorViewResolverConfiguration,conventionErrorViewResolver,org.springframework.boot.autoconfigure.web.servlet.error.ErrorMvcAutoConfiguration,errorAttributes,basicErrorController,errorPageCustomizer,preserveErrorControllerTargetClassPostProcessor,spring.resources-org.springframework.boot.autoconfigure.web.ResourceProperties,org.springframework.boot.autoconfigure.web.servlet.WebMvcAutoConfiguration$EnableWebMvcConfiguration,requestMappingHandlerAdapter,requestMappingHandlerMapping,welcomePageHandlerMapping,mvcConversionService,mvcValidator,mvcContentNegotiationManager,mvcPathMatcher,mvcUrlPathHelper,viewControllerHandlerMapping,beanNameHandlerMapping,routerFunctionMapping,resourceHandlerMapping,mvcResourceUrlProvider,defaultServletHandlerMapping,handlerFunctionAdapter,mvcUriComponentsContributor,httpRequestHandlerAdapter,simpleControllerHandlerAdapter,handlerExceptionResolver,mvcViewResolver,mvcHandlerMappingIntrospector,org.springframework.boot.autoconfigure.web.servlet.WebMvcAutoConfiguration$WebMvcAutoConfigurationAdapter,defaultViewResolver,viewResolver,requestContextFilter,org.springframework.boot.autoconfigure.web.servlet.WebMvcAutoConfiguration,formContentFilter,org.springframework.boot.autoconfigure.jmx.JmxAutoConfiguration,mbeanExporter,objectNamingStrategy,mbeanServer,org.springframework.boot.autoconfigure.admin.SpringApplicationAdminJmxAutoConfiguration,springApplicationAdminRegistrar,org.springframework.boot.autoconfigure.aop.AopAutoConfiguration$ClassProxyingConfiguration,org.springframework.boot.autoconfigure.aop.AopAutoConfiguration,org.springframework.boot.autoconfigure.availability.ApplicationAvailabilityAutoConfiguration,applicationAvailability,org.springframework.boot.autoconfigure.context.ConfigurationPropertiesAutoConfiguration,org.springframework.boot.autoconfigure.context.LifecycleAutoConfiguration,lifecycleProcessor,spring.lifecycle-org.springframework.boot.autoconfigure.context.LifecycleProperties,org.springframework.boot.autoconfigure.jackson.JacksonAutoConfiguration$Jackson2ObjectMapperBuilderCustomizerConfiguration,standardJacksonObjectMapperBuilderCustomizer,spring.jackson-org.springframework.boot.autoconfigure.jackson.JacksonProperties,org.springframework.boot.autoconfigure.jackson.JacksonAutoConfiguration$JacksonObjectMapperBuilderConfiguration,jacksonObjectMapperBuilder,org.springframework.boot.autoconfigure.jackson.JacksonAutoConfiguration$ParameterNamesModuleConfiguration,parameterNamesModule,org.springframework.boot.autoconfigure.jackson.JacksonAutoConfiguration$JacksonObjectMapperConfiguration,jacksonObjectMapper,org.springframework.boot.autoconfigure.jackson.JacksonAutoConfiguration,jsonComponentModule,org.springframework.boot.autoconfigure.http.HttpMessageConvertersAutoConfiguration$StringHttpMessageConverterConfiguration,stringHttpMessageConverter,org.springframework.boot.autoconfigure.http.JacksonHttpMessageConvertersConfiguration$MappingJackson2HttpMessageConverterConfiguration,mappingJackson2HttpMessageConverter,org.springframework.boot.autoconfigure.http.JacksonHttpMessageConvertersConfiguration,org.springframework.boot.autoconfigure.http.HttpMessageConvertersAutoConfiguration,messageConverters,org.springframework.boot.autoconfigure.info.ProjectInfoAutoConfiguration,spring.info-org.springframework.boot.autoconfigure.info.ProjectInfoProperties,org.springframework.boot.autoconfigure.task.TaskSchedulingAutoConfiguration,taskSchedulerBuilder,spring.task.scheduling-org.springframework.boot.autoconfigure.task.TaskSchedulingProperties,org.springframework.boot.autoconfigure.web.client.RestTemplateAutoConfiguration,restTemplateBuilder,org.springframework.boot.autoconfigure.web.embedded.EmbeddedWebServerFactoryCustomizerAutoConfiguration$NettyWebServerFactoryCustomizerConfiguration,nettyWebServerFactoryCustomizer,org.springframework.boot.autoconfigure.web.embedded.EmbeddedWebServerFactoryCustomizerAutoConfiguration$TomcatWebServerFactoryCustomizerConfiguration,tomcatWebServerFactoryCustomizer,org.springframework.boot.autoconfigure.web.embedded.EmbeddedWebServerFactoryCustomizerAutoConfiguration,org.springframework.boot.autoconfigure.web.servlet.HttpEncodingAutoConfiguration,characterEncodingFilter,localeCharsetMappingsCustomizer,org.springframework.boot.autoconfigure.web.servlet.MultipartAutoConfiguration,multipartConfigElement,multipartResolver,spring.servlet.multipart-org.springframework.boot.autoconfigure.web.servlet.MultipartProperties,org.springframework.boot.autoconfigure.websocket.servlet.WebSocketMessagingAutoConfiguration$WebSocketMessageConverterConfiguration,eagerStompWebSocketHandlerMapping,org.springframework.boot.autoconfigure.websocket.servlet.WebSocketMessagingAutoConfiguration,org.springframework.aop.config.internalAutoProxyCreator]; root of factory hierarchy
2020-09-30 23:46:40.550 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Creating instance of bean 'org.springframework.web.servlet.theme.FixedThemeResolver'
2020-09-30 23:46:40.550 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Finished creating instance of bean 'org.springframework.web.servlet.theme.FixedThemeResolver'
2020-09-30 23:46:40.550 TRACE 17840 --- [nio-8093-exec-1] o.s.web.servlet.DispatcherServlet : No ThemeResolver 'themeResolver': using default [FixedThemeResolver]
2020-09-30 23:46:40.550 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'stompWebSocketHandlerMapping'
2020-09-30 23:46:40.550 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'requestMappingHandlerMapping'
2020-09-30 23:46:40.550 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'welcomePageHandlerMapping'
2020-09-30 23:46:40.550 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'viewControllerHandlerMapping'
2020-09-30 23:46:40.550 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'beanNameHandlerMapping'
2020-09-30 23:46:40.550 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'routerFunctionMapping'
2020-09-30 23:46:40.550 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'resourceHandlerMapping'
2020-09-30 23:46:40.550 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'defaultServletHandlerMapping'
2020-09-30 23:46:40.551 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'requestMappingHandlerAdapter'
2020-09-30 23:46:40.551 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'handlerFunctionAdapter'
2020-09-30 23:46:40.551 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'httpRequestHandlerAdapter'
2020-09-30 23:46:40.551 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'simpleControllerHandlerAdapter'
2020-09-30 23:46:40.551 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'errorAttributes'
2020-09-30 23:46:40.551 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'handlerExceptionResolver'
2020-09-30 23:46:40.551 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : No bean named 'viewNameTranslator' found in org.springframework.beans.factory.support.DefaultListableBeanFactory@4052274f: defining beans [org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor,org.springframework.context.event.internalEventListenerProcessor,org.springframework.context.event.internalEventListenerFactory,websocketbugdemoApplication,org.springframework.boot.autoconfigure.internalCachingMetadataReaderFactory,webSocketConfig,org.springframework.web.socket.config.annotation.DelegatingWebSocketMessageBrokerConfiguration,stompWebSocketHandlerMapping,subProtocolWebSocketHandler,webSocketScopeConfigurer,webSocketMessageBrokerStats,clientInboundChannel,clientInboundChannelExecutor,clientOutboundChannel,clientOutboundChannelExecutor,brokerChannel,brokerChannelExecutor,simpAnnotationMethodMessageHandler,simpleBrokerMessageHandler,stompBrokerRelayMessageHandler,userDestinationMessageHandler,userRegistryMessageHandler,messageBrokerTaskScheduler,brokerMessagingTemplate,brokerMessageConverter,userDestinationResolver,userRegistry,org.springframework.boot.autoconfigure.AutoConfigurationPackages,org.springframework.boot.autoconfigure.context.PropertyPlaceholderAutoConfiguration,propertySourcesPlaceholderConfigurer,org.springframework.boot.autoconfigure.websocket.servlet.WebSocketServletAutoConfiguration$TomcatWebSocketConfiguration,websocketServletWebServerCustomizer,org.springframework.boot.autoconfigure.websocket.servlet.WebSocketServletAutoConfiguration,org.springframework.boot.autoconfigure.web.servlet.ServletWebServerFactoryConfiguration$EmbeddedTomcat,tomcatServletWebServerFactory,org.springframework.boot.autoconfigure.web.servlet.ServletWebServerFactoryAutoConfiguration,servletWebServerFactoryCustomizer,tomcatServletWebServerFactoryCustomizer,org.springframework.boot.context.properties.ConfigurationPropertiesBindingPostProcessor,org.springframework.boot.context.internalConfigurationPropertiesBinderFactory,org.springframework.boot.context.internalConfigurationPropertiesBinder,org.springframework.boot.context.properties.BoundConfigurationProperties,org.springframework.boot.context.properties.ConfigurationBeanFactoryMetadata,server-org.springframework.boot.autoconfigure.web.ServerProperties,webServerFactoryCustomizerBeanPostProcessor,errorPageRegistrarBeanPostProcessor,org.springframework.boot.autoconfigure.web.servlet.DispatcherServletAutoConfiguration$DispatcherServletConfiguration,dispatcherServlet,spring.mvc-org.springframework.boot.autoconfigure.web.servlet.WebMvcProperties,org.springframework.boot.autoconfigure.web.servlet.DispatcherServletAutoConfiguration$DispatcherServletRegistrationConfiguration,dispatcherServletRegistration,org.springframework.boot.autoconfigure.web.servlet.DispatcherServletAutoConfiguration,org.springframework.boot.autoconfigure.task.TaskExecutionAutoConfiguration,taskExecutorBuilder,spring.task.execution-org.springframework.boot.autoconfigure.task.TaskExecutionProperties,org.springframework.boot.autoconfigure.web.servlet.error.ErrorMvcAutoConfiguration$WhitelabelErrorViewConfiguration,error,beanNameViewResolver,org.springframework.boot.autoconfigure.web.servlet.error.ErrorMvcAutoConfiguration$DefaultErrorViewResolverConfiguration,conventionErrorViewResolver,org.springframework.boot.autoconfigure.web.servlet.error.ErrorMvcAutoConfiguration,errorAttributes,basicErrorController,errorPageCustomizer,preserveErrorControllerTargetClassPostProcessor,spring.resources-org.springframework.boot.autoconfigure.web.ResourceProperties,org.springframework.boot.autoconfigure.web.servlet.WebMvcAutoConfiguration$EnableWebMvcConfiguration,requestMappingHandlerAdapter,requestMappingHandlerMapping,welcomePageHandlerMapping,mvcConversionService,mvcValidator,mvcContentNegotiationManager,mvcPathMatcher,mvcUrlPathHelper,viewControllerHandlerMapping,beanNameHandlerMapping,routerFunctionMapping,resourceHandlerMapping,mvcResourceUrlProvider,defaultServletHandlerMapping,handlerFunctionAdapter,mvcUriComponentsContributor,httpRequestHandlerAdapter,simpleControllerHandlerAdapter,handlerExceptionResolver,mvcViewResolver,mvcHandlerMappingIntrospector,org.springframework.boot.autoconfigure.web.servlet.WebMvcAutoConfiguration$WebMvcAutoConfigurationAdapter,defaultViewResolver,viewResolver,requestContextFilter,org.springframework.boot.autoconfigure.web.servlet.WebMvcAutoConfiguration,formContentFilter,org.springframework.boot.autoconfigure.jmx.JmxAutoConfiguration,mbeanExporter,objectNamingStrategy,mbeanServer,org.springframework.boot.autoconfigure.admin.SpringApplicationAdminJmxAutoConfiguration,springApplicationAdminRegistrar,org.springframework.boot.autoconfigure.aop.AopAutoConfiguration$ClassProxyingConfiguration,org.springframework.boot.autoconfigure.aop.AopAutoConfiguration,org.springframework.boot.autoconfigure.availability.ApplicationAvailabilityAutoConfiguration,applicationAvailability,org.springframework.boot.autoconfigure.context.ConfigurationPropertiesAutoConfiguration,org.springframework.boot.autoconfigure.context.LifecycleAutoConfiguration,lifecycleProcessor,spring.lifecycle-org.springframework.boot.autoconfigure.context.LifecycleProperties,org.springframework.boot.autoconfigure.jackson.JacksonAutoConfiguration$Jackson2ObjectMapperBuilderCustomizerConfiguration,standardJacksonObjectMapperBuilderCustomizer,spring.jackson-org.springframework.boot.autoconfigure.jackson.JacksonProperties,org.springframework.boot.autoconfigure.jackson.JacksonAutoConfiguration$JacksonObjectMapperBuilderConfiguration,jacksonObjectMapperBuilder,org.springframework.boot.autoconfigure.jackson.JacksonAutoConfiguration$ParameterNamesModuleConfiguration,parameterNamesModule,org.springframework.boot.autoconfigure.jackson.JacksonAutoConfiguration$JacksonObjectMapperConfiguration,jacksonObjectMapper,org.springframework.boot.autoconfigure.jackson.JacksonAutoConfiguration,jsonComponentModule,org.springframework.boot.autoconfigure.http.HttpMessageConvertersAutoConfiguration$StringHttpMessageConverterConfiguration,stringHttpMessageConverter,org.springframework.boot.autoconfigure.http.JacksonHttpMessageConvertersConfiguration$MappingJackson2HttpMessageConverterConfiguration,mappingJackson2HttpMessageConverter,org.springframework.boot.autoconfigure.http.JacksonHttpMessageConvertersConfiguration,org.springframework.boot.autoconfigure.http.HttpMessageConvertersAutoConfiguration,messageConverters,org.springframework.boot.autoconfigure.info.ProjectInfoAutoConfiguration,spring.info-org.springframework.boot.autoconfigure.info.ProjectInfoProperties,org.springframework.boot.autoconfigure.task.TaskSchedulingAutoConfiguration,taskSchedulerBuilder,spring.task.scheduling-org.springframework.boot.autoconfigure.task.TaskSchedulingProperties,org.springframework.boot.autoconfigure.web.client.RestTemplateAutoConfiguration,restTemplateBuilder,org.springframework.boot.autoconfigure.web.embedded.EmbeddedWebServerFactoryCustomizerAutoConfiguration$NettyWebServerFactoryCustomizerConfiguration,nettyWebServerFactoryCustomizer,org.springframework.boot.autoconfigure.web.embedded.EmbeddedWebServerFactoryCustomizerAutoConfiguration$TomcatWebServerFactoryCustomizerConfiguration,tomcatWebServerFactoryCustomizer,org.springframework.boot.autoconfigure.web.embedded.EmbeddedWebServerFactoryCustomizerAutoConfiguration,org.springframework.boot.autoconfigure.web.servlet.HttpEncodingAutoConfiguration,characterEncodingFilter,localeCharsetMappingsCustomizer,org.springframework.boot.autoconfigure.web.servlet.MultipartAutoConfiguration,multipartConfigElement,multipartResolver,spring.servlet.multipart-org.springframework.boot.autoconfigure.web.servlet.MultipartProperties,org.springframework.boot.autoconfigure.websocket.servlet.WebSocketMessagingAutoConfiguration$WebSocketMessageConverterConfiguration,eagerStompWebSocketHandlerMapping,org.springframework.boot.autoconfigure.websocket.servlet.WebSocketMessagingAutoConfiguration,org.springframework.aop.config.internalAutoProxyCreator]; root of factory hierarchy
2020-09-30 23:46:40.551 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Creating instance of bean 'org.springframework.web.servlet.view.DefaultRequestToViewNameTranslator'
2020-09-30 23:46:40.552 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Finished creating instance of bean 'org.springframework.web.servlet.view.DefaultRequestToViewNameTranslator'
2020-09-30 23:46:40.552 TRACE 17840 --- [nio-8093-exec-1] o.s.web.servlet.DispatcherServlet : No RequestToViewNameTranslator 'viewNameTranslator': using default [DefaultRequestToViewNameTranslator]
2020-09-30 23:46:40.552 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'beanNameViewResolver'
2020-09-30 23:46:40.552 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'mvcViewResolver'
2020-09-30 23:46:40.552 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'defaultViewResolver'
2020-09-30 23:46:40.552 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'viewResolver'
2020-09-30 23:46:40.552 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : No bean named 'flashMapManager' found in org.springframework.beans.factory.support.DefaultListableBeanFactory@4052274f: defining beans [org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor,org.springframework.context.event.internalEventListenerProcessor,org.springframework.context.event.internalEventListenerFactory,websocketbugdemoApplication,org.springframework.boot.autoconfigure.internalCachingMetadataReaderFactory,webSocketConfig,org.springframework.web.socket.config.annotation.DelegatingWebSocketMessageBrokerConfiguration,stompWebSocketHandlerMapping,subProtocolWebSocketHandler,webSocketScopeConfigurer,webSocketMessageBrokerStats,clientInboundChannel,clientInboundChannelExecutor,clientOutboundChannel,clientOutboundChannelExecutor,brokerChannel,brokerChannelExecutor,simpAnnotationMethodMessageHandler,simpleBrokerMessageHandler,stompBrokerRelayMessageHandler,userDestinationMessageHandler,userRegistryMessageHandler,messageBrokerTaskScheduler,brokerMessagingTemplate,brokerMessageConverter,userDestinationResolver,userRegistry,org.springframework.boot.autoconfigure.AutoConfigurationPackages,org.springframework.boot.autoconfigure.context.PropertyPlaceholderAutoConfiguration,propertySourcesPlaceholderConfigurer,org.springframework.boot.autoconfigure.websocket.servlet.WebSocketServletAutoConfiguration$TomcatWebSocketConfiguration,websocketServletWebServerCustomizer,org.springframework.boot.autoconfigure.websocket.servlet.WebSocketServletAutoConfiguration,org.springframework.boot.autoconfigure.web.servlet.ServletWebServerFactoryConfiguration$EmbeddedTomcat,tomcatServletWebServerFactory,org.springframework.boot.autoconfigure.web.servlet.ServletWebServerFactoryAutoConfiguration,servletWebServerFactoryCustomizer,tomcatServletWebServerFactoryCustomizer,org.springframework.boot.context.properties.ConfigurationPropertiesBindingPostProcessor,org.springframework.boot.context.internalConfigurationPropertiesBinderFactory,org.springframework.boot.context.internalConfigurationPropertiesBinder,org.springframework.boot.context.properties.BoundConfigurationProperties,org.springframework.boot.context.properties.ConfigurationBeanFactoryMetadata,server-org.springframework.boot.autoconfigure.web.ServerProperties,webServerFactoryCustomizerBeanPostProcessor,errorPageRegistrarBeanPostProcessor,org.springframework.boot.autoconfigure.web.servlet.DispatcherServletAutoConfiguration$DispatcherServletConfiguration,dispatcherServlet,spring.mvc-org.springframework.boot.autoconfigure.web.servlet.WebMvcProperties,org.springframework.boot.autoconfigure.web.servlet.DispatcherServletAutoConfiguration$DispatcherServletRegistrationConfiguration,dispatcherServletRegistration,org.springframework.boot.autoconfigure.web.servlet.DispatcherServletAutoConfiguration,org.springframework.boot.autoconfigure.task.TaskExecutionAutoConfiguration,taskExecutorBuilder,spring.task.execution-org.springframework.boot.autoconfigure.task.TaskExecutionProperties,org.springframework.boot.autoconfigure.web.servlet.error.ErrorMvcAutoConfiguration$WhitelabelErrorViewConfiguration,error,beanNameViewResolver,org.springframework.boot.autoconfigure.web.servlet.error.ErrorMvcAutoConfiguration$DefaultErrorViewResolverConfiguration,conventionErrorViewResolver,org.springframework.boot.autoconfigure.web.servlet.error.ErrorMvcAutoConfiguration,errorAttributes,basicErrorController,errorPageCustomizer,preserveErrorControllerTargetClassPostProcessor,spring.resources-org.springframework.boot.autoconfigure.web.ResourceProperties,org.springframework.boot.autoconfigure.web.servlet.WebMvcAutoConfiguration$EnableWebMvcConfiguration,requestMappingHandlerAdapter,requestMappingHandlerMapping,welcomePageHandlerMapping,mvcConversionService,mvcValidator,mvcContentNegotiationManager,mvcPathMatcher,mvcUrlPathHelper,viewControllerHandlerMapping,beanNameHandlerMapping,routerFunctionMapping,resourceHandlerMapping,mvcResourceUrlProvider,defaultServletHandlerMapping,handlerFunctionAdapter,mvcUriComponentsContributor,httpRequestHandlerAdapter,simpleControllerHandlerAdapter,handlerExceptionResolver,mvcViewResolver,mvcHandlerMappingIntrospector,org.springframework.boot.autoconfigure.web.servlet.WebMvcAutoConfiguration$WebMvcAutoConfigurationAdapter,defaultViewResolver,viewResolver,requestContextFilter,org.springframework.boot.autoconfigure.web.servlet.WebMvcAutoConfiguration,formContentFilter,org.springframework.boot.autoconfigure.jmx.JmxAutoConfiguration,mbeanExporter,objectNamingStrategy,mbeanServer,org.springframework.boot.autoconfigure.admin.SpringApplicationAdminJmxAutoConfiguration,springApplicationAdminRegistrar,org.springframework.boot.autoconfigure.aop.AopAutoConfiguration$ClassProxyingConfiguration,org.springframework.boot.autoconfigure.aop.AopAutoConfiguration,org.springframework.boot.autoconfigure.availability.ApplicationAvailabilityAutoConfiguration,applicationAvailability,org.springframework.boot.autoconfigure.context.ConfigurationPropertiesAutoConfiguration,org.springframework.boot.autoconfigure.context.LifecycleAutoConfiguration,lifecycleProcessor,spring.lifecycle-org.springframework.boot.autoconfigure.context.LifecycleProperties,org.springframework.boot.autoconfigure.jackson.JacksonAutoConfiguration$Jackson2ObjectMapperBuilderCustomizerConfiguration,standardJacksonObjectMapperBuilderCustomizer,spring.jackson-org.springframework.boot.autoconfigure.jackson.JacksonProperties,org.springframework.boot.autoconfigure.jackson.JacksonAutoConfiguration$JacksonObjectMapperBuilderConfiguration,jacksonObjectMapperBuilder,org.springframework.boot.autoconfigure.jackson.JacksonAutoConfiguration$ParameterNamesModuleConfiguration,parameterNamesModule,org.springframework.boot.autoconfigure.jackson.JacksonAutoConfiguration$JacksonObjectMapperConfiguration,jacksonObjectMapper,org.springframework.boot.autoconfigure.jackson.JacksonAutoConfiguration,jsonComponentModule,org.springframework.boot.autoconfigure.http.HttpMessageConvertersAutoConfiguration$StringHttpMessageConverterConfiguration,stringHttpMessageConverter,org.springframework.boot.autoconfigure.http.JacksonHttpMessageConvertersConfiguration$MappingJackson2HttpMessageConverterConfiguration,mappingJackson2HttpMessageConverter,org.springframework.boot.autoconfigure.http.JacksonHttpMessageConvertersConfiguration,org.springframework.boot.autoconfigure.http.HttpMessageConvertersAutoConfiguration,messageConverters,org.springframework.boot.autoconfigure.info.ProjectInfoAutoConfiguration,spring.info-org.springframework.boot.autoconfigure.info.ProjectInfoProperties,org.springframework.boot.autoconfigure.task.TaskSchedulingAutoConfiguration,taskSchedulerBuilder,spring.task.scheduling-org.springframework.boot.autoconfigure.task.TaskSchedulingProperties,org.springframework.boot.autoconfigure.web.client.RestTemplateAutoConfiguration,restTemplateBuilder,org.springframework.boot.autoconfigure.web.embedded.EmbeddedWebServerFactoryCustomizerAutoConfiguration$NettyWebServerFactoryCustomizerConfiguration,nettyWebServerFactoryCustomizer,org.springframework.boot.autoconfigure.web.embedded.EmbeddedWebServerFactoryCustomizerAutoConfiguration$TomcatWebServerFactoryCustomizerConfiguration,tomcatWebServerFactoryCustomizer,org.springframework.boot.autoconfigure.web.embedded.EmbeddedWebServerFactoryCustomizerAutoConfiguration,org.springframework.boot.autoconfigure.web.servlet.HttpEncodingAutoConfiguration,characterEncodingFilter,localeCharsetMappingsCustomizer,org.springframework.boot.autoconfigure.web.servlet.MultipartAutoConfiguration,multipartConfigElement,multipartResolver,spring.servlet.multipart-org.springframework.boot.autoconfigure.web.servlet.MultipartProperties,org.springframework.boot.autoconfigure.websocket.servlet.WebSocketMessagingAutoConfiguration$WebSocketMessageConverterConfiguration,eagerStompWebSocketHandlerMapping,org.springframework.boot.autoconfigure.websocket.servlet.WebSocketMessagingAutoConfiguration,org.springframework.aop.config.internalAutoProxyCreator]; root of factory hierarchy
2020-09-30 23:46:40.553 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Creating instance of bean 'org.springframework.web.servlet.support.SessionFlashMapManager'
2020-09-30 23:46:40.554 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Finished creating instance of bean 'org.springframework.web.servlet.support.SessionFlashMapManager'
2020-09-30 23:46:40.554 TRACE 17840 --- [nio-8093-exec-1] o.s.web.servlet.DispatcherServlet : No FlashMapManager 'flashMapManager': using default [SessionFlashMapManager]
2020-09-30 23:46:40.554 DEBUG 17840 --- [nio-8093-exec-1] o.s.web.servlet.DispatcherServlet : enableLoggingRequestDetails='false': request parameters and headers will be masked to prevent unsafe logging of potentially sensitive data
2020-09-30 23:46:40.554 INFO 17840 --- [nio-8093-exec-1] o.s.web.servlet.DispatcherServlet : Completed initialization in 7 ms
2020-09-30 23:46:40.554 DEBUG 17840 --- [nio-8093-exec-1] o.apache.catalina.core.StandardWrapper : Returning non-STM instance
2020-09-30 23:46:40.559 TRACE 17840 --- [nio-8093-exec-1] o.s.b.w.s.f.OrderedRequestContextFilter : Bound request context to thread: org.apache.catalina.connector.RequestFacade@58bcc1a5
2020-09-30 23:46:40.560 DEBUG 17840 --- [nio-8093-exec-1] org.apache.tomcat.util.http.Parameters : Set encoding to UTF-8
2020-09-30 23:46:40.561 TRACE 17840 --- [nio-8093-exec-1] o.s.web.servlet.DispatcherServlet : GET "/secured/user", parameters={}, headers={masked} in DispatcherServlet 'dispatcherServlet'
2020-09-30 23:46:40.564 TRACE 17840 --- [nio-8093-exec-1] o.s.w.s.s.s.WebSocketHandlerMapping : Mapped to HandlerExecutionChain with [org.springframework.web.socket.server.support.WebSocketHttpRequestHandler@623ebac7] and 1 interceptors
2020-09-30 23:46:40.569 DEBUG 17840 --- [nio-8093-exec-1] o.s.w.s.s.s.WebSocketHttpRequestHandler : GET /secured/user
2020-09-30 23:46:40.571 TRACE 17840 --- [nio-8093-exec-1] o.s.w.s.s.s.DefaultHandshakeHandler : Processing request http://localhost:8093/secured/user with headers=[user-agent:"websocket-sharp/1.0", host:"localhost:8093", upgrade:"websocket", connection:"Upgrade", sec-websocket-key:"i3kundhrnFEnB/fkfoDFQw==", sec-websocket-version:"13"]
2020-09-30 23:46:40.571 TRACE 17840 --- [nio-8093-exec-1] o.s.w.s.s.s.DefaultHandshakeHandler : Upgrading to WebSocket, subProtocol=null, extensions=[]
2020-09-30 23:46:40.583 DEBUG 17840 --- [nio-8093-exec-1] o.a.c.loader.WebappClassLoaderBase : findClass(org.apache.tomcat.util.collections.LocalStrings)
2020-09-30 23:46:40.583 DEBUG 17840 --- [nio-8093-exec-1] o.a.c.loader.WebappClassLoaderBase : findClassInternal(org.apache.tomcat.util.collections.LocalStrings)
2020-09-30 23:46:40.584 DEBUG 17840 --- [nio-8093-exec-1] o.a.c.loader.WebappClassLoaderBase : --> Returning ClassNotFoundException
2020-09-30 23:46:40.584 DEBUG 17840 --- [nio-8093-exec-1] o.a.c.loader.WebappClassLoaderBase : --> Passing on ClassNotFoundException
2020-09-30 23:46:40.584 DEBUG 17840 --- [nio-8093-exec-1] o.a.c.loader.WebappClassLoaderBase : getResource(org/apache/tomcat/util/collections/LocalStrings.properties)
2020-09-30 23:46:40.584 DEBUG 17840 --- [nio-8093-exec-1] o.a.c.loader.WebappClassLoaderBase : Delegating to parent classloader jdk.internal.loader.ClassLoaders$AppClassLoader@368239c8
2020-09-30 23:46:40.584 DEBUG 17840 --- [nio-8093-exec-1] o.a.c.loader.WebappClassLoaderBase : --> Resource not found, returning null
2020-09-30 23:46:40.585 DEBUG 17840 --- [nio-8093-exec-1] o.a.c.loader.WebappClassLoaderBase : findClass(org.apache.tomcat.util.collections.LocalStrings_en)
2020-09-30 23:46:40.585 DEBUG 17840 --- [nio-8093-exec-1] o.a.c.loader.WebappClassLoaderBase : findClassInternal(org.apache.tomcat.util.collections.LocalStrings_en)
2020-09-30 23:46:40.585 DEBUG 17840 --- [nio-8093-exec-1] o.a.c.loader.WebappClassLoaderBase : --> Returning ClassNotFoundException
2020-09-30 23:46:40.585 DEBUG 17840 --- [nio-8093-exec-1] o.a.c.loader.WebappClassLoaderBase : --> Passing on ClassNotFoundException
2020-09-30 23:46:40.585 DEBUG 17840 --- [nio-8093-exec-1] o.a.c.loader.WebappClassLoaderBase : getResource(org/apache/tomcat/util/collections/LocalStrings_en.properties)
2020-09-30 23:46:40.585 DEBUG 17840 --- [nio-8093-exec-1] o.a.c.loader.WebappClassLoaderBase : Delegating to parent classloader jdk.internal.loader.ClassLoaders$AppClassLoader@368239c8
2020-09-30 23:46:40.586 DEBUG 17840 --- [nio-8093-exec-1] o.a.c.loader.WebappClassLoaderBase : --> Resource not found, returning null
2020-09-30 23:46:40.586 DEBUG 17840 --- [nio-8093-exec-1] o.a.c.loader.WebappClassLoaderBase : findClass(org.apache.tomcat.util.collections.LocalStrings_en_US)
2020-09-30 23:46:40.586 DEBUG 17840 --- [nio-8093-exec-1] o.a.c.loader.WebappClassLoaderBase : findClassInternal(org.apache.tomcat.util.collections.LocalStrings_en_US)
2020-09-30 23:46:40.586 DEBUG 17840 --- [nio-8093-exec-1] o.a.c.loader.WebappClassLoaderBase : --> Returning ClassNotFoundException
2020-09-30 23:46:40.586 DEBUG 17840 --- [nio-8093-exec-1] o.a.c.loader.WebappClassLoaderBase : --> Passing on ClassNotFoundException
2020-09-30 23:46:40.587 DEBUG 17840 --- [nio-8093-exec-1] o.a.c.loader.WebappClassLoaderBase : getResource(org/apache/tomcat/util/collections/LocalStrings_en_US.properties)
2020-09-30 23:46:40.587 DEBUG 17840 --- [nio-8093-exec-1] o.a.c.loader.WebappClassLoaderBase : Delegating to parent classloader jdk.internal.loader.ClassLoaders$AppClassLoader@368239c8
2020-09-30 23:46:40.587 DEBUG 17840 --- [nio-8093-exec-1] o.a.c.loader.WebappClassLoaderBase : --> Resource not found, returning null
2020-09-30 23:46:40.589 TRACE 17840 --- [nio-8093-exec-1] o.s.web.servlet.DispatcherServlet : No view rendering, null ModelAndView returned.
2020-09-30 23:46:40.590 DEBUG 17840 --- [nio-8093-exec-1] o.s.web.servlet.DispatcherServlet : Completed 101 SWITCHING_PROTOCOLS, headers={masked}
2020-09-30 23:46:40.590 TRACE 17840 --- [nio-8093-exec-1] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'springApplicationAdminRegistrar'
2020-09-30 23:46:40.590 TRACE 17840 --- [nio-8093-exec-1] o.s.b.w.s.f.OrderedRequestContextFilter : Cleared thread-bound request context: org.apache.catalina.connector.RequestFacade@58bcc1a5
2020-09-30 23:46:40.593 DEBUG 17840 --- [nio-8093-exec-1] o.apache.coyote.http11.Http11Processor : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1a36ac3f:org.apache.tomcat.util.net.NioChannel@132b7e4c:java.nio.channels.SocketChannel[connected local=kubernetes.docker.internal/127.0.0.1:8093 remote=/127.0.0.1:63561]], Status in: [OPEN_READ], State out: [UPGRADING]
2020-09-30 23:46:40.600 DEBUG 17840 --- [nio-8093-exec-1] org.apache.tomcat.websocket.WsSession : Created WebSocket session [0]
2020-09-30 23:46:40.607 DEBUG 17840 --- [nio-8093-exec-1] s.w.s.h.LoggingWebSocketHandlerDecorator : New StandardWebSocketSession[id=3a9ea81b-a50a-ae2b-a571-2db145567753, uri=ws://localhost:8093/secured/user]
2020-09-30 23:46:40.612 DEBUG 17840 --- [nio-8093-exec-1] o.a.t.websocket.server.WsFrameServer : wsFrameServer.onDataAvailable
2020-09-30 23:46:40.612 DEBUG 17840 --- [nio-8093-exec-1] o.a.tomcat.util.net.SocketWrapperBase : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1a36ac3f:org.apache.tomcat.util.net.NioChannel@132b7e4c:java.nio.channels.SocketChannel[connected local=kubernetes.docker.internal/127.0.0.1:8093 remote=/127.0.0.1:63561]], Read from buffer: [0]
2020-09-30 23:46:40.612 DEBUG 17840 --- [nio-8093-exec-1] org.apache.tomcat.util.net.NioEndpoint : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1a36ac3f:org.apache.tomcat.util.net.NioChannel@132b7e4c:java.nio.channels.SocketChannel[connected local=kubernetes.docker.internal/127.0.0.1:8093 remote=/127.0.0.1:63561]], Read direct from socket: [0]
2020-09-30 23:46:40.613 DEBUG 17840 --- [nio-8093-exec-1] o.a.c.h.u.UpgradeProcessorInternal : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1a36ac3f:org.apache.tomcat.util.net.NioChannel@132b7e4c:java.nio.channels.SocketChannel[connected local=kubernetes.docker.internal/127.0.0.1:8093 remote=/127.0.0.1:63561]], Status in: [OPEN_READ], State out: [UPGRADED]
2020-09-30 23:46:40.613 DEBUG 17840 --- [nio-8093-exec-1] org.apache.tomcat.util.net.NioEndpoint : Registered read interest for [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1a36ac3f:org.apache.tomcat.util.net.NioChannel@132b7e4c:java.nio.channels.SocketChannel[connected local=kubernetes.docker.internal/127.0.0.1:8093 remote=/127.0.0.1:63561]]
2020-09-30 23:46:40.617 DEBUG 17840 --- [nio-8093-exec-2] o.a.t.websocket.server.WsFrameServer : wsFrameServer.onDataAvailable
2020-09-30 23:46:40.618 DEBUG 17840 --- [nio-8093-exec-2] o.a.tomcat.util.net.SocketWrapperBase : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1a36ac3f:org.apache.tomcat.util.net.NioChannel@132b7e4c:java.nio.channels.SocketChannel[connected local=kubernetes.docker.internal/127.0.0.1:8093 remote=/127.0.0.1:63561]], Read from buffer: [0]
2020-09-30 23:46:40.618 DEBUG 17840 --- [nio-8093-exec-2] org.apache.tomcat.util.net.NioEndpoint : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1a36ac3f:org.apache.tomcat.util.net.NioChannel@132b7e4c:java.nio.channels.SocketChannel[connected local=kubernetes.docker.internal/127.0.0.1:8093 remote=/127.0.0.1:63561]], Read direct from socket: [6]
2020-09-30 23:46:40.618 DEBUG 17840 --- [nio-8093-exec-2] o.a.t.websocket.server.WsFrameServer : Read [6] bytes into input buffer ready for processing
2020-09-30 23:46:40.618 DEBUG 17840 --- [nio-8093-exec-2] o.a.t.websocket.server.WsFrameServer : WebSocket frame received. fin [true], rsv [0], OpCode [9], payload length [0]
2020-09-30 23:46:40.621 DEBUG 17840 --- [nio-8093-exec-2] o.a.tomcat.util.net.SocketWrapperBase : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1a36ac3f:org.apache.tomcat.util.net.NioChannel@132b7e4c:java.nio.channels.SocketChannel[connected local=kubernetes.docker.internal/127.0.0.1:8093 remote=/127.0.0.1:63561]], Read from buffer: [0]
2020-09-30 23:46:40.621 DEBUG 17840 --- [nio-8093-exec-2] org.apache.tomcat.util.net.NioEndpoint : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1a36ac3f:org.apache.tomcat.util.net.NioChannel@132b7e4c:java.nio.channels.SocketChannel[connected local=kubernetes.docker.internal/127.0.0.1:8093 remote=/127.0.0.1:63561]], Read direct from socket: [0]
2020-09-30 23:46:40.622 DEBUG 17840 --- [nio-8093-exec-2] o.a.c.h.u.UpgradeProcessorInternal : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1a36ac3f:org.apache.tomcat.util.net.NioChannel@132b7e4c:java.nio.channels.SocketChannel[connected local=kubernetes.docker.internal/127.0.0.1:8093 remote=/127.0.0.1:63561]], Status in: [OPEN_READ], State out: [UPGRADED]
2020-09-30 23:46:40.622 DEBUG 17840 --- [nio-8093-exec-2] org.apache.tomcat.util.net.NioEndpoint : Registered read interest for [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1a36ac3f:org.apache.tomcat.util.net.NioChannel@132b7e4c:java.nio.channels.SocketChannel[connected local=kubernetes.docker.internal/127.0.0.1:8093 remote=/127.0.0.1:63561]]
2020-09-30 23:46:41.622 DEBUG 17840 --- [93-ClientPoller] org.apache.tomcat.util.net.NioEndpoint : timeout completed: keys processed=1; now=1601531201622; nextExpiration=1601531200904; keyCount=0; hasEvents=false; eval=false
2020-09-30 23:46:42.623 DEBUG 17840 --- [93-ClientPoller] org.apache.tomcat.util.net.NioEndpoint : timeout completed: keys processed=1; now=1601531202623; nextExpiration=1601531202622; keyCount=0; hasEvents=false; eval=false
2020-09-30 23:46:43.242 DEBUG 17840 --- [nio-8093-exec-3] o.a.t.websocket.server.WsFrameServer : wsFrameServer.onDataAvailable
2020-09-30 23:46:43.242 DEBUG 17840 --- [nio-8093-exec-3] o.a.tomcat.util.net.SocketWrapperBase : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1a36ac3f:org.apache.tomcat.util.net.NioChannel@132b7e4c:java.nio.channels.SocketChannel[connected local=kubernetes.docker.internal/127.0.0.1:8093 remote=/127.0.0.1:63561]], Read from buffer: [0]
2020-09-30 23:46:43.243 DEBUG 17840 --- [nio-8093-exec-3] org.apache.tomcat.util.net.NioEndpoint : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1a36ac3f:org.apache.tomcat.util.net.NioChannel@132b7e4c:java.nio.channels.SocketChannel[connected local=kubernetes.docker.internal/127.0.0.1:8093 remote=/127.0.0.1:63561]], Read direct from socket: [35]
2020-09-30 23:46:43.243 DEBUG 17840 --- [nio-8093-exec-3] o.a.t.websocket.server.WsFrameServer : Read [35] bytes into input buffer ready for processing
2020-09-30 23:46:43.243 DEBUG 17840 --- [nio-8093-exec-3] o.a.t.websocket.server.WsFrameServer : WebSocket frame received. fin [true], rsv [0], OpCode [1], payload length [29]
2020-09-30 23:46:43.244 TRACE 17840 --- [nio-8093-exec-3] s.w.s.h.LoggingWebSocketHandlerDecorator : Handling TextMessage payload=[CONNECT
ac..], byteCount=29, last=true] in StandardWebSocketSession[id=3a9ea81b-a50a-ae2b-a571-2db145567753, uri=ws://localhost:8093/secured/user]
2020-09-30 23:46:43.244 TRACE 17840 --- [nio-8093-exec-3] o.s.messaging.simp.stomp.StompDecoder : Decoded CONNECT {accept-version=[1.2]} session=null
2020-09-30 23:46:43.245 TRACE 17840 --- [nio-8093-exec-3] o.s.w.s.m.StompSubProtocolHandler : From client: CONNECT session=3a9ea81b-a50a-ae2b-a571-2db145567753
2020-09-30 23:46:43.247 DEBUG 17840 --- [nboundChannel-2] o.s.m.s.s.StompBrokerRelayMessageHandler : CONNECT session=3a9ea81b-a50a-ae2b-a571-2db145567753
2020-09-30 23:46:43.247 TRACE 17840 --- [nio-8093-exec-3] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'springApplicationAdminRegistrar'
2020-09-30 23:46:43.247 TRACE 17840 --- [nio-8093-exec-3] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'webSocketConfig'
2020-09-30 23:46:43.247 INFO 17840 --- [nio-8093-exec-3] c.e.w.config.WebSocketConfig : Successfully established ws connection for username: testUser
2020-09-30 23:46:43.247 TRACE 17840 --- [nio-8093-exec-3] o.s.c.e.ApplicationListenerMethodAdapter : No result object given - no result to handle
2020-09-30 23:46:43.247 DEBUG 17840 --- [nio-8093-exec-3] o.a.tomcat.util.net.SocketWrapperBase : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1a36ac3f:org.apache.tomcat.util.net.NioChannel@132b7e4c:java.nio.channels.SocketChannel[connected local=kubernetes.docker.internal/127.0.0.1:8093 remote=/127.0.0.1:63561]], Read from buffer: [0]
2020-09-30 23:46:43.247 DEBUG 17840 --- [nio-8093-exec-3] org.apache.tomcat.util.net.NioEndpoint : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1a36ac3f:org.apache.tomcat.util.net.NioChannel@132b7e4c:java.nio.channels.SocketChannel[connected local=kubernetes.docker.internal/127.0.0.1:8093 remote=/127.0.0.1:63561]], Read direct from socket: [0]
2020-09-30 23:46:43.248 DEBUG 17840 --- [nio-8093-exec-3] o.a.c.h.u.UpgradeProcessorInternal : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1a36ac3f:org.apache.tomcat.util.net.NioChannel@132b7e4c:java.nio.channels.SocketChannel[connected local=kubernetes.docker.internal/127.0.0.1:8093 remote=/127.0.0.1:63561]], Status in: [OPEN_READ], State out: [UPGRADED]
2020-09-30 23:46:43.248 DEBUG 17840 --- [nio-8093-exec-3] org.apache.tomcat.util.net.NioEndpoint : Registered read interest for [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1a36ac3f:org.apache.tomcat.util.net.NioChannel@132b7e4c:java.nio.channels.SocketChannel[connected local=kubernetes.docker.internal/127.0.0.1:8093 remote=/127.0.0.1:63561]]
2020-09-30 23:46:43.249 DEBUG 17840 --- [ient-loop-nio-2] r.n.resources.PooledConnectionProvider : [id: 0x52d32b03] Created a new pooled channel, now 2 active connections and 0 inactive connections
2020-09-30 23:46:43.249 DEBUG 17840 --- [ient-loop-nio-2] reactor.netty.channel.BootstrapHandlers : [id: 0x52d32b03] Initialized pipeline DefaultChannelPipeline{(BootstrapHandlers$BootstrapInitializerHandler#0 = reactor.netty.channel.BootstrapHandlers$BootstrapInitializerHandler), (PooledConnectionProvider$PooledConnectionAllocator$PooledConnectionInitializer#0 = reactor.netty.resources.PooledConnectionProvider$PooledConnectionAllocator$PooledConnectionInitializer), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2020-09-30 23:46:43.250 DEBUG 17840 --- [ient-loop-nio-2] r.n.resources.PooledConnectionProvider : [id: 0x52d32b03, L:/127.0.0.1:63566 - R:/127.0.0.1:61613] Registering pool release on close event for channel
2020-09-30 23:46:43.250 DEBUG 17840 --- [ient-loop-nio-2] r.n.resources.PooledConnectionProvider : [id: 0x52d32b03, L:/127.0.0.1:63566 - R:/127.0.0.1:61613] Channel connected, now 2 active connections and 0 inactive connections
2020-09-30 23:46:43.251 DEBUG 17840 --- [ient-loop-nio-2] r.n.resources.PooledConnectionProvider : [id: 0x52d32b03, L:/127.0.0.1:63566 - R:/127.0.0.1:61613] onStateChange(PooledConnection{channel=[id: 0x52d32b03, L:/127.0.0.1:63566 - R:/127.0.0.1:61613]}, [connected])
2020-09-30 23:46:43.251 DEBUG 17840 --- [ient-loop-nio-2] r.n.resources.PooledConnectionProvider : [id: 0x52d32b03, L:/127.0.0.1:63566 - R:/127.0.0.1:61613] onStateChange(ChannelOperations{PooledConnection{channel=[id: 0x52d32b03, L:/127.0.0.1:63566 - R:/127.0.0.1:61613]}}, [configured])
2020-09-30 23:46:43.251 DEBUG 17840 --- [ient-loop-nio-2] reactor.netty.tcp.TcpClient : [id: 0x52d32b03, L:/127.0.0.1:63566 - R:/127.0.0.1:61613] Handler is being applied: org.springframework.messaging.tcp.reactor.ReactorNettyTcpClient$ReactorNettyHandler@41c89bfd
2020-09-30 23:46:43.251 DEBUG 17840 --- [ient-loop-nio-2] o.s.m.tcp.reactor.ReactorNettyTcpClient : Connected to /127.0.0.1:61613
2020-09-30 23:46:43.251 DEBUG 17840 --- [ient-loop-nio-2] reactor.netty.ReactorNetty : [id: 0x52d32b03, L:/127.0.0.1:63566 - R:/127.0.0.1:61613] Added decoder [StompMessageDecoder] at the end of the user pipeline, full pipeline: [StompMessageDecoder, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2020-09-30 23:46:43.251 DEBUG 17840 --- [ient-loop-nio-2] reactor.netty.channel.FluxReceive : [id: 0x52d32b03, L:/127.0.0.1:63566 - R:/127.0.0.1:61613] FluxReceive{pending=0, cancelled=false, inboundDone=false, inboundError=null}: subscribing inbound receiver
2020-09-30 23:46:43.252 DEBUG 17840 --- [ent-scheduler-5] o.s.m.s.s.StompBrokerRelayMessageHandler : TCP connection opened in session=3a9ea81b-a50a-ae2b-a571-2db145567753
2020-09-30 23:46:43.252 DEBUG 17840 --- [ent-scheduler-5] reactor.netty.ReactorNetty : [id: 0x52d32b03, L:/127.0.0.1:63566 - R:/127.0.0.1:61613] Non Removed handler: reactor.left.onChannelReadIdle, context: null, pipeline: DefaultChannelPipeline{(StompMessageDecoder = org.springframework.messaging.tcp.reactor.ReactorNettyTcpClient$StompMessageDecoder), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2020-09-30 23:46:43.253 DEBUG 17840 --- [ent-scheduler-5] reactor.netty.ReactorNetty : [id: 0x52d32b03, L:/127.0.0.1:63566 - R:/127.0.0.1:61613] Added encoder [reactor.left.onChannelReadIdle] at the beginning of the user pipeline, full pipeline: [reactor.left.onChannelReadIdle, StompMessageDecoder, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2020-09-30 23:46:43.260 TRACE 17840 --- [ent-scheduler-5] o.s.messaging.simp.stomp.StompEncoder : Encoding STOMP CONNECT, headers={accept-version=[1.2], heart-beat=[0,30000], login=[guest], passcode=[PROTECTED], host=[/]}
2020-09-30 23:46:43.279 TRACE 17840 --- [ient-loop-nio-2] o.s.messaging.simp.stomp.StompDecoder : Decoded CONNECTED {server=[RabbitMQ/3.8.8], session=[session-9Eq0l93M-q2jdGtMJaemmw], heart-beat=[30000,0], version=[1.2]} session=null
2020-09-30 23:46:43.279 DEBUG 17840 --- [ent-scheduler-6] o.s.m.s.s.StompBrokerRelayMessageHandler : Received CONNECTED heart-beat=[30000, 0] session=3a9ea81b-a50a-ae2b-a571-2db145567753
2020-09-30 23:46:43.280 TRACE 17840 --- [tboundChannel-1] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'springApplicationAdminRegistrar'
2020-09-30 23:46:43.280 TRACE 17840 --- [tboundChannel-1] o.s.messaging.simp.stomp.StompEncoder : Encoding STOMP CONNECTED, headers={server=[RabbitMQ/3.8.8], session=[session-9Eq0l93M-q2jdGtMJaemmw], heart-beat=[30000,0], version=[1.2]}
2020-09-30 23:46:43.280 TRACE 17840 --- [tboundChannel-1] o.s.w.s.adapter.NativeWebSocketSession : Sending TextMessage payload=[CONNECTED
..], byteCount=104, last=true], StandardWebSocketSession[id=3a9ea81b-a50a-ae2b-a571-2db145567753, uri=ws://localhost:8093/secured/user]
2020-09-30 23:46:43.422 DEBUG 17840 --- [nio-8093-exec-4] o.a.t.websocket.server.WsFrameServer : wsFrameServer.onDataAvailable
2020-09-30 23:46:43.422 DEBUG 17840 --- [nio-8093-exec-4] o.a.tomcat.util.net.SocketWrapperBase : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1a36ac3f:org.apache.tomcat.util.net.NioChannel@132b7e4c:java.nio.channels.SocketChannel[connected local=kubernetes.docker.internal/127.0.0.1:8093 remote=/127.0.0.1:63561]], Read from buffer: [0]
2020-09-30 23:46:43.422 DEBUG 17840 --- [nio-8093-exec-4] org.apache.tomcat.util.net.NioEndpoint : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1a36ac3f:org.apache.tomcat.util.net.NioChannel@132b7e4c:java.nio.channels.SocketChannel[connected local=kubernetes.docker.internal/127.0.0.1:8093 remote=/127.0.0.1:63561]], Read direct from socket: [64]
2020-09-30 23:46:43.422 DEBUG 17840 --- [nio-8093-exec-4] o.a.t.websocket.server.WsFrameServer : Read [64] bytes into input buffer ready for processing
2020-09-30 23:46:43.422 DEBUG 17840 --- [nio-8093-exec-4] o.a.t.websocket.server.WsFrameServer : WebSocket frame received. fin [true], rsv [0], OpCode [1], payload length [52]
2020-09-30 23:46:43.422 TRACE 17840 --- [nio-8093-exec-4] s.w.s.h.LoggingWebSocketHandlerDecorator : Handling TextMessage payload=[SUBSCRIBE
..], byteCount=52, last=true] in StandardWebSocketSession[id=3a9ea81b-a50a-ae2b-a571-2db145567753, uri=ws://localhost:8093/secured/user]
2020-09-30 23:46:43.422 TRACE 17840 --- [nio-8093-exec-4] o.s.messaging.simp.stomp.StompDecoder : Decoded SUBSCRIBE {destination=[/queue/customQueue], id=[C#RSS]} session=null
2020-09-30 23:46:43.422 TRACE 17840 --- [nio-8093-exec-4] o.s.w.s.m.StompSubProtocolHandler : From client: SUBSCRIBE /queue/customQueue id=C#RSS session=3a9ea81b-a50a-ae2b-a571-2db145567753
2020-09-30 23:46:43.423 DEBUG 17840 --- [nboundChannel-5] o.s.m.s.s.StompBrokerRelayMessageHandler : Forwarding SUBSCRIBE /queue/customQueue id=C#RSS session=3a9ea81b-a50a-ae2b-a571-2db145567753
2020-09-30 23:46:43.423 DEBUG 17840 --- [nboundChannel-4] .WebSocketAnnotationMethodMessageHandler : Searching methods to handle SUBSCRIBE /queue/customQueue id=C#RSS session=3a9ea81b-a50a-ae2b-a571-2db145567753, lookupDestination='/queue/customQueue'
2020-09-30 23:46:43.423 TRACE 17840 --- [nio-8093-exec-4] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'springApplicationAdminRegistrar'
2020-09-30 23:46:43.423 DEBUG 17840 --- [nboundChannel-4] .WebSocketAnnotationMethodMessageHandler : No matching message handler methods.
2020-09-30 23:46:43.423 TRACE 17840 --- [nio-8093-exec-4] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'webSocketConfig'
2020-09-30 23:46:43.423 INFO 17840 --- [nio-8093-exec-4] c.e.w.config.WebSocketConfig : Successfully completed subscription for username: testUser
2020-09-30 23:46:43.423 TRACE 17840 --- [nio-8093-exec-4] o.s.c.e.ApplicationListenerMethodAdapter : No result object given - no result to handle
2020-09-30 23:46:43.424 DEBUG 17840 --- [nio-8093-exec-4] o.a.t.websocket.server.WsFrameServer : WebSocket frame received. fin [true], rsv [0], OpCode [9], payload length [0]
2020-09-30 23:46:43.424 DEBUG 17840 --- [nio-8093-exec-4] o.a.tomcat.util.net.SocketWrapperBase : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1a36ac3f:org.apache.tomcat.util.net.NioChannel@132b7e4c:java.nio.channels.SocketChannel[connected local=kubernetes.docker.internal/127.0.0.1:8093 remote=/127.0.0.1:63561]], Read from buffer: [0]
2020-09-30 23:46:43.424 DEBUG 17840 --- [nio-8093-exec-4] org.apache.tomcat.util.net.NioEndpoint : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1a36ac3f:org.apache.tomcat.util.net.NioChannel@132b7e4c:java.nio.channels.SocketChannel[connected local=kubernetes.docker.internal/127.0.0.1:8093 remote=/127.0.0.1:63561]], Read direct from socket: [0]
2020-09-30 23:46:43.424 DEBUG 17840 --- [nio-8093-exec-4] o.a.c.h.u.UpgradeProcessorInternal : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1a36ac3f:org.apache.tomcat.util.net.NioChannel@132b7e4c:java.nio.channels.SocketChannel[connected local=kubernetes.docker.internal/127.0.0.1:8093 remote=/127.0.0.1:63561]], Status in: [OPEN_READ], State out: [UPGRADED]
2020-09-30 23:46:43.424 DEBUG 17840 --- [nio-8093-exec-4] org.apache.tomcat.util.net.NioEndpoint : Registered read interest for [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1a36ac3f:org.apache.tomcat.util.net.NioChannel@132b7e4c:java.nio.channels.SocketChannel[connected local=kubernetes.docker.internal/127.0.0.1:8093 remote=/127.0.0.1:63561]]
2020-09-30 23:46:43.430 TRACE 17840 --- [nboundChannel-5] o.s.messaging.simp.stomp.StompEncoder : Encoding STOMP SUBSCRIBE, headers={destination=[/queue/custom_testuser], id=[testUser], auto-delete=[false], durable=[true], x-expires=[2765000000], x-message-ttl=[2592000000]}
2020-09-30 23:46:43.447 TRACE 17840 --- [ient-loop-nio-1] o.s.messaging.simp.stomp.StompDecoder : Decoded heart-beat
2020-09-30 23:46:43.447 TRACE 17840 --- [ent-scheduler-4] o.s.m.s.s.StompBrokerRelayMessageHandler : Received heart-beat in session _system_
2020-09-30 23:46:43.458 TRACE 17840 --- [ient-loop-nio-1] o.s.messaging.simp.stomp.StompEncoder : Encoding heartbeat
2020-09-30 23:46:44.425 DEBUG 17840 --- [93-ClientPoller] org.apache.tomcat.util.net.NioEndpoint : timeout completed: keys processed=1; now=1601531204425; nextExpiration=1601531203623; keyCount=0; hasEvents=false; eval=false
2020-09-30 23:46:45.425 DEBUG 17840 --- [93-ClientPoller] org.apache.tomcat.util.net.NioEndpoint : timeout completed: keys processed=1; now=1601531205425; nextExpiration=1601531205425; keyCount=0; hasEvents=false; eval=false
On your second suggestion i went in and turned debug on the rabbitmq. Im not familiar with rabbitmq logs but it shows 30 in th heartbeat_sender. From what i can understand in this link, it looks like its setting the timeout as 30 and so the rabbitmq should send heart beat at every timeout. Bleow are the debug logs from rabbitmq after the sending the CONNECTED and SUBSCRIBED requests. Any help would be appreciated.
2020-10-01 06:41:07.150 [debug] <0.1256.0> User 'guest' authenticated successfully by backend rabbit_auth_backend_internal
2020-10-01 06:41:07.155 [debug] <0.1257.0> User 'guest' authenticated successfully by backend rabbit_auth_backend_internal
2020-10-01 06:41:09.813 [debug] <0.1260.0> Supervisor {<0.1260.0>,rabbit_stomp_client_sup} started rabbit_connection_helper_sup:start_link() at pid <0.1261.0>
2020-10-01 06:41:09.814 [debug] <0.1260.0> Supervisor {<0.1260.0>,rabbit_stomp_client_sup} started rabbit_stomp_reader:start_link(<0.1261.0>, {acceptor,{0,0,0,0,0,0,0,0},61613}, {stomp_configuration,<<"guest">>,<<"guest">>,false,false,false}) at pid <0.1262.0>
2020-10-01 06:41:09.814 [info] <0.1262.0> accepting STOMP connection <0.1262.0> (172.17.0.1:37638 -> 172.17.0.2:61613)
2020-10-01 06:41:09.826 [debug] <0.1263.0> Supervisor {<0.1263.0>,amqp_connection_sup} started amqp_connection_type_sup:start_link() at pid <0.1264.0>
2020-10-01 06:41:09.827 [debug] <0.1263.0> Supervisor {<0.1263.0>,amqp_connection_sup} started amqp_gen_connection:start_link(<0.1264.0>, {amqp_params_direct,<<"guest">>,{encrypted,<<"TYWUS4GW68L27WSd+wG+6OIh6HAH9T/O7SfxBi17h7QvIne+GFG7...">>},...}) at pid <0.1265.0>
2020-10-01 06:41:09.831 [debug] <0.1265.0> User 'guest' authenticated successfully by backend rabbit_auth_backend_internal
2020-10-01 06:41:09.832 [debug] <0.1264.0> Supervisor {<0.1264.0>,amqp_connection_type_sup} started amqp_channel_sup_sup:start_link(direct, <0.1265.0>, <<"172.17.0.1:37638 -> 172.17.0.2:61613">>) at pid <0.1266.0>
2020-10-01 06:41:09.832 [debug] <0.1264.0> Supervisor {<0.1264.0>,amqp_connection_type_sup} started amqp_channels_manager:start_link(<0.1265.0>, <<"172.17.0.1:37638 -> 172.17.0.2:61613">>, <0.1266.0>) at pid <0.1267.0>
2020-10-01 06:41:09.832 [debug] <0.1264.0> Supervisor {<0.1264.0>,amqp_connection_type_sup} started rabbit_queue_collector:start_link(<<"172.17.0.1:37638 -> 172.17.0.2:61613">>) at pid <0.1268.0>
2020-10-01 06:41:09.832 [debug] <0.1269.0> Supervisor {<0.1269.0>,amqp_channel_sup} started amqp_gen_consumer:start_link(amqp_selective_consumer, [], {<<"172.17.0.1:37638 -> 172.17.0.2:61613">>,1}) at pid <0.1270.0>
2020-10-01 06:41:09.832 [debug] <0.1269.0> Supervisor {<0.1269.0>,amqp_channel_sup} started amqp_channel:start_link(direct, <0.1265.0>, 1, <0.1270.0>, {<<"172.17.0.1:37638 -> 172.17.0.2:61613">>,1}) at pid <0.1271.0>
2020-10-01 06:41:09.833 [debug] <0.1272.0> Supervisor {<0.1272.0>,rabbit_channel_sup} started rabbit_limiter:start_link({<<"172.17.0.1:37638 -> 172.17.0.2:61613">>,1}) at pid <0.1273.0>
2020-10-01 06:41:09.833 [debug] <0.1272.0> Supervisor {<0.1272.0>,rabbit_channel_sup} started rabbit_channel:start_link(1, <0.1271.0>, <0.1271.0>, <0.1265.0>, <<"172.17.0.1:37638 -> 172.17.0.2:61613">>, rabbit_framing_amqp_0_9_1, {user,<<"guest">>,[administrator],[{rabbit_auth_backend_internal,none}]}, <<"/">>, [{<<"publisher_confirms">>,bool,true},{<<"exchange_exchange_bindings">>,bool,true},{<<"basic.nack">>,...},...], <0.1268.0>, <0.1273.0>, {amqp_params_direct,<<"guest">>,{encrypted,<<"TYWUS4GW68L27WSd+wG+6OIh6HAH9T/O7SfxBi17h7QvIne+GFG7...">>},...}) at pid <0.1274.0>
2020-10-01 06:41:09.834 [debug] <0.1261.0> Supervisor {<0.1261.0>,rabbit_connection_helper_sup} started rabbit_heartbeat:start_heartbeat_sender(#Port<0.80>, 30, #Fun<rabbit_stomp_reader.1.74743013>, {heartbeat_sender,unknown}) at pid <0.1275.0>
2020-10-01 06:41:09.972 [debug] <0.1278.0> Supervisor {<0.1278.0>,rabbit_amqqueue_sup} started rabbit_prequeue:start_link({amqqueue,{resource,<<"/">>,queue,<<"custom_testuser">>},true,false,none,[{<<"x-expires">>,long,...},...],...}, declare, <0.1277.0>) at pid <0.1279.0>
2020-10-01 06:41:12.153 [debug] <0.1283.0> User 'guest' authenticated successfully by backend rabbit_auth_backend_internal
2020-10-01 06:41:12.158 [debug] <0.1284.0> User 'guest' authenticated successfully by backend rabbit_auth_backend_internal
2020-10-01 06:41:17.152 [debug] <0.1290.0> User 'guest' authenticated successfully by backend rabbit_auth_backend_internal
2020-10-01 06:41:17.161 [debug] <0.1291.0> User 'guest' authenticated successfully by backend rabbit_auth_backend_internal
2020-10-01 06:41:22.158 [debug] <0.1297.0> User 'guest' authenticated successfully by backend rabbit_auth_backend_internal
2020-10-01 06:41:22.167 [debug] <0.1298.0> User 'guest' authenticated successfully by backend rabbit_auth_backend_internal
2020-10-01 06:41:27.151 [debug] <0.1304.0> User 'guest' authenticated successfully by backend rabbit_auth_backend_internal
2020-10-01 06:41:27.159 [debug] <0.1305.0> User 'guest' authenticated successfully by backend rabbit_auth_backend_internal
2020-10-01 06:41:32.151 [debug] <0.1311.0> User 'guest' authenticated successfully by backend rabbit_auth_backend_internal
2020-10-01 06:41:32.157 [debug] <0.1312.0> User 'guest' authenticated successfully by backend rabbit_auth_backend_internal
2020-10-01 06:41:37.151 [debug] <0.1319.0> User 'guest' authenticated successfully by backend rabbit_auth_backend_internal
2020-10-01 06:41:37.158 [debug] <0.1320.0> User 'guest' authenticated successfully by backend rabbit_auth_backend_internal
2020-10-01 06:41:38.039 [debug] <0.590.0> Asked to [re-]register this node (rabbit@31579674209a) with epmd...
2020-10-01 06:41:38.163 [debug] <0.590.0> [Re-]registered this node (rabbit@31579674209a) with epmd at port 25672
2020-10-01 06:41:42.158 [debug] <0.1326.0> User 'guest' authenticated successfully by backend rabbit_auth_backend_internal
2020-10-01 06:41:42.175 [debug] <0.1327.0> User 'guest' authenticated successfully by backend rabbit_auth_backend_internal
Comment From: rstoyanchev
Okay so clearly client and broker agree on 30 seconds. However, once again, in the case of an external broker Spring is merely relaying messages between client and server. The heartbeats originate from RabbitMQ and that is where I would focus to understand whether this is expected behavior for RabbitMQ STOMP.
Note that a heartbeat interval of 30 seconds does not necessarily mean heartbeats will be received or sent exactly every 30 seconds as that would be cutting it too close. The spec does say that receivers should use an error of margin, but this is open to some interpretation and implementation differences. For example I think it's quite possible that RabbitMQ publishes heartbeats at a higher frequency based on some formula in order to counter latency. Browsing around I see some indication that may be the case.
You could also experiment to increase the interval to 60 seconds and see what the broker does, or browser the RabbitMQ STOMP plugin code, or ask to find out how it's expected to behave.
Comment From: prinal10
@rstoyanchev, you are right. RabbitMQ does sends the heart-beat frame (message) every heartBeatTimeout/2 secs. I did verified that by setting up the heart-beat to 60 and after that the client started receiving heart-beat every 30secs. It was just confusing because there was no indication in spring logs if the heart-beats where negotiated differently, but i should have also read the documentation in heart-beat carefully. Thank you @rstoyanchev on the feedback.
Comment From: rstoyanchev
No worries.