Одно из наших приложений с весенней загрузкой, использующее верблюд, зависает при запуске в течение от 1 до 5 минут, но не всегда.
Производственная среда, в которой запускается приложение, - это raspberry pi, на котором работает openJDK. Мы не можем воспроизвести проблему на машинах для разработки.
Даже на PIS, однако, проблема чрезвычайно редкая и, кажется, возникает только на некоторых. Фактически, в настоящее время у нас есть только один в этой области, где это постоянная проблема, но там это несколько критическая проблема из-за того, что она работает на солнечной энергии. Проблема наблюдалась однажды на другом Пи, где она не была критической и не на 100% непротиворечивой, и через некоторое время снова исчезла. К сожалению, мы не можем проверить пи на аппаратные проблемы. Командировочные расходы были бы значительными, поэтому, прежде чем у нас не останется другого выбора, мы не можем позволить себе пойти и заменить его возможностью, что даже это не решит проблему. Кроме того, системный журнал pis не показывает никаких подозрительных действий вообще во время и после того, как произойдет зависание.
Это просто, чтобы объяснить, почему я отправляю вопрос, даже если проблема с оборудованием не может быть исключена на 100% в данный момент. Нам просто нужно сначала исключить все остальное.
Теперь по актуальному вопросу: вот полный след (log.level.root = TRACE) приложения во время зависания. Я могу предоставить полную информацию о стартапе, но не думаю, что спам, содержащий тысячи строк журналов, очень поможет. Меня больше всего интересует, видите ли вы что-нибудь подозрительное. Я просматривал эти записи в течение некоторого времени и не вижу никакого намека на причину зависания, но мой опыт внутренней жизни пружинного башмака очень ограничен.
2019-10-30 08:28:16.090 DEBUG 456 --- [main] o.s.b.f.s.DefaultListableBeanFactory : Eagerly caching bean 'org.springframework.context.annotation.internalScheduledAnnotationProcessor' to allow for resolving potential circular references
2019-10-30 08:28:16.091 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Getting BeanInfo for class [org.springframework.scheduling.annotation.ScheduledAnnotationBeanPostProcessor]
2019-10-30 08:28:16.106 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Caching PropertyDescriptors for class [org.springframework.scheduling.annotation.ScheduledAnnotationBeanPostProcessor]
2019-10-30 08:28:16.107 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'applicationContext' of type [org.springframework.context.ApplicationContext]
2019-10-30 08:28:16.107 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'beanFactory' of type [org.springframework.beans.factory.BeanFactory]
2019-10-30 08:28:16.107 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'beanName' of type [java.lang.String]
2019-10-30 08:28:16.107 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'class' of type [java.lang.Class]
2019-10-30 08:28:16.108 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'embeddedValueResolver' of type [org.springframework.util.StringValueResolver]
2019-10-30 08:28:16.109 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'order' of type [int]
2019-10-30 08:28:16.109 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'scheduledTasks' of type [java.util.Set]
2019-10-30 08:28:16.109 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'scheduler' of type [java.lang.Object]
2019-10-30 08:28:16.185 DEBUG 456 --- [main] o.s.b.f.s.DefaultListableBeanFactory : Finished creating instance of bean 'org.springframework.context.annotation.internalScheduledAnnotationProcessor'
2019-10-30 08:28:16.186 DEBUG 456 --- [main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'persistenceExceptionTranslationPostProcessor'
2019-10-30 08:28:16.186 DEBUG 456 --- [main] o.s.b.f.s.DefaultListableBeanFactory : Creating instance of bean 'persistenceExceptionTranslationPostProcessor'
2019-10-30 08:28:16.370 DEBUG 456 --- [main] o.s.b.f.s.DefaultListableBeanFactory : Returning cached instance of singleton bean 'environment'
2019-10-30 08:28:16.375 DEBUG 456 --- [main] o.s.b.f.s.DefaultListableBeanFactory : Autowiring by type from bean name 'persistenceExceptionTranslationPostProcessor' via factory method to bean named 'environment'
2019-10-30 08:28:16.379 TRACE 456 --- [main] o.s.c.e.PropertySourcesPropertyResolver : Searching for key 'spring.aop.proxy-target-class' in PropertySource 'configurationProperties'
2019-10-30 08:28:16.381 TRACE 456 --- [main] o.s.c.e.PropertySourcesPropertyResolver : Searching for key 'spring.aop.proxy-target-class' in PropertySource 'commandLineArgs'
2019-10-30 08:28:16.381 TRACE 456 --- [main] o.s.c.e.PropertySourcesPropertyResolver : Searching for key 'spring.aop.proxy-target-class' in PropertySource 'systemProperties'
2019-10-30 08:28:16.381 TRACE 456 --- [main] o.s.c.e.PropertySourcesPropertyResolver : Searching for key 'spring.aop.proxy-target-class' in PropertySource 'systemEnvironment'
2019-10-30 08:28:16.381 TRACE 456 --- [main] o.s.c.e.PropertySourcesPropertyResolver : Searching for key 'spring.aop.proxy-target-class' in PropertySource 'random'
2019-10-30 08:28:16.381 TRACE 456 --- [main] o.s.c.e.PropertySourcesPropertyResolver : Searching for key 'spring.aop.proxy-target-class' in PropertySource 'applicationConfig: [file:./application.properties]'
2019-10-30 08:28:16.381 TRACE 456 --- [main] o.s.c.e.PropertySourcesPropertyResolver : Searching for key 'spring.aop.proxy-target-class' in PropertySource 'applicationConfig: [classpath:/application.properties]'
2019-10-30 08:28:16.381 DEBUG 456 --- [main] o.s.c.e.PropertySourcesPropertyResolver : Could not find key 'spring.aop.proxy-target-class' in any property source
2019-10-30 08:28:16.398 DEBUG 456 --- [main] o.s.b.f.s.DefaultListableBeanFactory : Eagerly caching bean 'persistenceExceptionTranslationPostProcessor' to allow for resolving potential circular references
2019-10-30 08:28:16.399 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Getting BeanInfo for class [org.springframework.dao.annotation.PersistenceExceptionTranslationPostProcessor]
2019-10-30 08:28:16.437 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Caching PropertyDescriptors for class [org.springframework.dao.annotation.PersistenceExceptionTranslationPostProcessor]
2019-10-30 08:28:16.437 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'beanClassLoader' of type [java.lang.ClassLoader]
2019-10-30 08:28:16.437 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'beanFactory' of type [org.springframework.beans.factory.BeanFactory]
2019-10-30 08:28:16.437 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'beforeExistingAdvisors' of type [boolean]
2019-10-30 08:28:16.438 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'class' of type [java.lang.Class]
2019-10-30 08:28:16.438 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'exposeProxy' of type [boolean]
2019-10-30 08:28:16.439 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'frozen' of type [boolean]
2019-10-30 08:28:16.440 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'opaque' of type [boolean]
2019-10-30 08:28:16.440 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'optimize' of type [boolean]
2019-10-30 08:28:16.441 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'order' of type [int]
2019-10-30 08:28:16.441 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'proxyClassLoader' of type [java.lang.ClassLoader]
2019-10-30 08:28:16.441 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'proxyTargetClass' of type [boolean]
2019-10-30 08:28:16.442 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'repositoryAnnotationType' of type [java.lang.Class]
2019-10-30 08:28:16.507 DEBUG 456 --- [main] o.s.b.f.s.DefaultListableBeanFactory : Finished creating instance of bean 'persistenceExceptionTranslationPostProcessor'
2019-10-30 08:28:16.507 DEBUG 456 --- [main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'dataSourceInitializerPostProcessor'
2019-10-30 08:28:16.507 DEBUG 456 --- [main] o.s.b.f.s.DefaultListableBeanFactory : Creating instance of bean 'dataSourceInitializerPostProcessor'
2019-10-30 08:28:16.522 DEBUG 456 --- [main] o.s.b.f.annotation.InjectionMetadata : Registered injected element on class [org.springframework.boot.autoconfigure.jdbc.DataSourceInitializerPostProcessor]: AutowiredFieldElement for private org.springframework.beans.factory.BeanFactory org.springframework.boot.autoconfigure.jdbc.DataSourceInitializerPostProcessor.beanFactory
2019-10-30 08:28:16.522 DEBUG 456 --- [main] o.s.b.f.s.DefaultListableBeanFactory : Eagerly caching bean 'dataSourceInitializerPostProcessor' to allow for resolving potential circular references
2019-10-30 08:28:16.522 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Getting BeanInfo for class [org.springframework.boot.autoconfigure.jdbc.DataSourceInitializerPostProcessor]
2019-10-30 08:28:16.532 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Caching PropertyDescriptors for class [org.springframework.boot.autoconfigure.jdbc.DataSourceInitializerPostProcessor]
2019-10-30 08:28:16.533 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'class' of type [java.lang.Class]
2019-10-30 08:28:16.533 TRACE 456 --- [main] o.s.beans.CachedIntrospectionResults : Found bean property 'order' of type [int]
// Note the significant time jump!
2019-10-30 08:30:16.087 TRACE 454 --- [main] org.apache.sshd.client.SshClient : addSessionListener(SshClient[f66866])[org.apache.sshd.common.session.helpers.SessionTimeoutListener@b50150] registered
2019-10-30 08:30:16.088 TRACE 454 --- [main] .a.s.c.u.t.ThreadUtils$SshdThreadFactory : newThread(java.lang.ThreadGroup[name=main,maxpri=10])[sshd-SshClient[f66866]-timer-thread-1] runnable=java.util.concurrent.ThreadPoolExecutor$Worker@1b986cd[State = -1, empty queue]
2019-10-30 08:30:16.161 TRACE 454 --- [main] o.a.sshd.common.io.nio2.Nio2Connector : Creating Nio2Connector
2019-10-30 08:30:16.162 DEBUG 454 --- [main] o.a.camel.component.ssh.SshProducer : Starting producer: Producer[ssh://root:xxxxxx@192.168.1.1]
2019-10-30 08:30:16.162 TRACE 454 --- [main] org.apache.camel.support.ServiceSupport : Starting service
2019-10-30 08:30:16.162 DEBUG 454 --- [main] o.a.camel.component.exec.ExecProducer : Starting producer: Producer[exec://sudo]
2019-10-30 08:30:16.162 TRACE 454 --- [main] org.apache.camel.support.ServiceSupport : Starting service
2019-10-30 08:30:16.162 DEBUG 454 --- [main] o.a.camel.component.exec.ExecProducer : Starting producer: Producer[exec://sudo]
2019-10-30 08:30:16.162 TRACE 454 --- [main] org.apache.camel.support.ServiceSupport : Starting service
2019-10-30 08:30:16.162 DEBUG 454 --- [main] o.a.c.c.direct.DirectBlockingProducer : Starting producer: Producer[direct://switch-off-camera]
2019-10-30 08:30:16.162 TRACE 454 --- [main] org.apache.camel.support.ServiceSupport : Starting service
2019-10-30 08:30:16.163 DEBUG 454 --- [main] o.a.camel.component.seda.SedaProducer : Starting producer: Producer[seda://capture-image]
2019-10-30 08:30:16.163 TRACE 454 --- [main] org.apache.camel.support.ServiceSupport : Starting service
2019-10-30 08:30:16.163 DEBUG 454 --- [main] o.a.c.c.direct.DirectBlockingProducer : Starting producer: Producer[direct://switch-off-camera]
2019-10-30 08:30:16.163 TRACE 454 --- [main] org.apache.camel.support.ServiceSupport : Starting service
2019-10-30 08:30:16.163 DEBUG 454 --- [main] o.a.camel.component.seda.SedaProducer : Starting producer: Producer[seda://image-queue]
2019-10-30 08:30:16.163 TRACE 454 --- [main] org.apache.camel.support.ServiceSupport : Starting service
2019-10-30 08:30:16.163 DEBUG 454 --- [main] o.a.c.c.direct.DirectBlockingProducer : Starting producer: Producer[direct://failed-upload]
2019-10-30 08:30:16.163 TRACE 454 --- [main] org.apache.camel.support.ServiceSupport : Starting service
2019-10-30 08:30:16.163 DEBUG 454 --- [main] o.a.c.c.direct.DirectBlockingProducer : Starting producer: Producer[direct://switch-off-camera]
2019-10-30 08:30:16.163 TRACE 454 --- [main] org.apache.camel.support.ServiceSupport : Starting service
2019-10-30 08:30:16.164 TRACE 454 --- [main] org.apache.camel.support.ServiceSupport : Starting service
2019-10-30 08:30:16.164 DEBUG 454 --- [main] o.a.camel.component.seda.SedaProducer : Starting producer: Producer[seda://capture-command]
2019-10-30 08:30:16.164 DEBUG 454 --- [main] o.a.camel.spring.SpringCamelContext : Route: route1 >>> EventDrivenConsumerRoute[seda://start-deepsleep -> Pipeline[[Channel[Log(route1)[Starting deep sleep for ${body} seconds]], Channel[SetBody(Simple: sh -c '(sleep 15; io set out0 1; sleep 2; lpm -i ${body})' </dev/null >/dev/null 2>&1 &)], Channel[Log(route1)[Executing SSH command: ${body}]], C
2019-10-30 08:30:16.165 DEBUG 454 --- [main] o.a.camel.spring.SpringCamelContext : Starting consumer (order: 1000) on route: route1
2019-10-30 08:30:16.165 TRACE 454 --- [main] a.c.m.DefaultManagementLifecycleStrategy : Checking whether to register SedaConsumer[seda://start-deepsleep] from route: EventDrivenConsumerRoute[seda://start-deepsleep -> Pipeline[[Channel[Log(route1)[Starting deep sleep for ${body} seconds]], Channel[SetBody(Simple: sh -c '(sleep 15; io set out0 1; sleep 2; lpm -i ${body})' </dev/null >/dev/null 2>&1
2019-10-30 08:30:16.166 DEBUG 454 --- [main] javax.management.mbeanserver : name = org.apache.camel:context=camel-1,type=consumers,name=SedaConsumer(0x1f22f18)
2019-10-30 08:30:16.167 DEBUG 454 --- [main] javax.management.mbeanserver : name = org.apache.camel:context=camel-1,type=consumers,name=SedaConsumer(0x1f22f18)
2019-10-30 08:30:16.167 TRACE 454 --- [main] o.a.c.management.DefaultManagementAgent : Registering MBean with ObjectName: org.apache.camel:context=camel-1,type=consumers,name=SedaConsumer(0x1f22f18)
2019-10-30 08:30:16.168 TRACE 454 --- [main] o.a.c.m.DefaultManagementMBeanAssembler : Assembling MBeanInfo for: org.apache.camel:context=camel-1,type=consumers,name=SedaConsumer(0x1f22f18) from @ManagedResource object: org.apache.camel.management.mbean.ManagedConsumer@8572f0
2019-10-30 08:30:16.168 TRACE 454 --- [main] o.a.camel.management.MBeanInfoAssembler : Extracting attributes and operations from class: class org.apache.camel.management.mbean.ManagedConsumer
2019-10-30 08:30:16.174 TRACE 454 --- [main] o.a.camel.management.MBeanInfoAssembler : Extracting attributes and operations from method: public java.lang.Integer org.apache.camel.management.mbean.ManagedConsumer.getInflightExchanges()
2019-10-30 08:30:16.175 TRACE 454 --- [main] o.a.camel.management.MBeanInfoAssembler : Extracting attributes and operations from method: public org.apache.camel.Consumer org.apache.camel.management.mbean.ManagedConsumer.getConsumer()
2019-10-30 08:30:16.175 TRACE 454 --- [main] o.a.camel.management.MBeanInfoAssembler : Extracting attributes and operations from method: public java.lang.String org.apache.camel.management.mbean.ManagedConsumer.getEndpointUri()
2019-10-30 08:30:16.175 TRACE 454 --- [main] o.a.camel.management.MBeanInfoAssembler : Extracting attributes and operations from sub class: class org.apache.camel.management.mbean.ManagedService
2019-10-30 08:30:16.176 TRACE 454 --- [main] o.a.camel.management.MBeanInfoAssembler : Extracting attributes and operations from class: class org.apache.camel.management.mbean.ManagedService
2019-10-30 08:30:16.180 TRACE 454 --- [ForkJoinPool.commonPool-worker-2] org.apache.camel.util.LRUCache : onRemoval class org.apache.camel.management.mbean.ManagedService -> null
2019-10-30 08:30:16.180 TRACE 454 --- [ForkJoinPool.commonPool-worker-3] org.apache.camel.util.LRUCache : onRemoval interface org.apache.camel.api.management.mbean.ManagedServiceMBean -> null
2019-10-30 08:30:16.180 TRACE 454 --- [main] o.a.camel.management.MBeanInfoAssembler : Extracting attributes and operations from method: public java.lang.String org.apache.camel.management.mbean.ManagedService.getServiceType()
2019-10-30 08:30:16.180 TRACE 454 --- [ForkJoinPool.commonPool-worker-2] org.apache.camel.util.LRUCache : onRemoval class org.apache.camel.management.mbean.ManagedProducer -> null
2019-10-30 08:30:16.181 TRACE 454 --- [ForkJoinPool.commonPool-worker-3] org.apache.camel.util.LRUCache : onRemoval interface org.apache.camel.api.management.mbean.ManagedProducerMBean -> null
2019-10-30 08:30:16.181 TRACE 454 --- [main] o.a.camel.management.MBeanInfoAssembler : Extracting attributes and operations from method: public boolean org.apache.camel.management.mbean.ManagedService.isSupportSuspension()
2019-10-30 08:30:16.182 TRACE 454 --- [ForkJoinPool.commonPool-worker-3] org.apache.camel.util.LRUCache : onRemoval interface org.apache.camel.api.management.ManagedInstance -> null
2019-10-30 08:30:16.182 TRACE 454 --- [main] o.a.camel.management.MBeanInfoAssembler : Extracting attributes and operations from method: public boolean org.apache.camel.management.mbean.ManagedService.isStaticService()
2019-10-30 08:30:16.182 TRACE 454 --- [main] o.a.camel.management.MBeanInfoAssembler : Extracting attributes and operations from method: public void org.apache.camel.management.mbean.ManagedService.setRoute(org.apache.camel.Route)
2019-10-30 08:30:16.182 TRACE 454 --- [main] o.a.camel.management.MBeanInfoAssembler : Extracting attributes and operations from method: public java.lang.String org.apache.camel.management.mbean.ManagedService.getCamelManagementName()
Я отметилразрыв во времени, когда кажется, что ничего не происходит. Теперь есть несколько записей, которые я вынул. Кварцевое хранилище заданий работает с базой данных h2, и запланированное задание одной из наших служб уже запущено. Никаких подозрительных вещей, и нам удалось полностью исключить их в некоторых тестовых прогонах, но это показывает, что система в целом не застопорилась. Spring-boot просто, кажется, ждет что-то , прежде чем продолжить.
Я надеялся, что кто-то еще дома с весенней загрузкой может сказать мне, что ждет весенняя загрузка в то время на основе этих журналов.
Мы также исключили возможность неправильнойвремя регистрации (то есть, что зависание на самом деле отсутствует, вместо этого скачки часов), тем более что это пи.
Может быть примечательно, что зависание происходит между верблюдом, создающим экземпляры конечных точек, и верблюдомначиная маршруты. Обычно это всего лишь второе приложение, но я ожидаю увидеть некоторые признаки проблемы в журнале, если произойдет зависание с этим.