search

konqi / roborock-bridge

Bridge between a local mqtt broker and your roborock vaccuum through the vendor apis
MIT License
5 stars 2 forks source link

SpringApplication Application run failed after requesting cleanup routine #81

Open robin0793 opened 1 month ago

robin0793 commented 1 month ago

I got an issue when I trigger a cleanup routine via mqtt (which routine doesn't matter). The routine does trigger, but the bridge shuts down with the following error.

Device is a Roborock QRevo Pro. Issue is fully reproducible

2024-08-18T19:16:07.949+02:00  INFO 17422 --- [           main] d.k.r.RoborockBridgeApplicationKt        : Starting RoborockBridgeApplicationKt v0.0.7-SNAPSHOT using Java 17.0.11 with PID 17422 (/opt/roborock-bridge/roborock-bridge.jar started by openhabian in /opt/roborock-bridge)
2024-08-18T19:16:07.966+02:00  INFO 17422 --- [           main] d.k.r.RoborockBridgeApplicationKt        : The following 1 profile is active: "bridge"
2024-08-18T19:16:12.521+02:00  INFO 17422 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data JPA repositories in DEFAULT mode.
2024-08-18T19:16:12.833+02:00  INFO 17422 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 278 ms. Found 5 JPA repository interfaces.
2024-08-18T19:16:15.322+02:00  INFO 17422 --- [           main] o.hibernate.jpa.internal.util.LogHelper  : HHH000204: Processing PersistenceUnitInfo [name: default]
2024-08-18T19:16:15.656+02:00  INFO 17422 --- [           main] org.hibernate.Version                    : HHH000412: Hibernate ORM core version 6.4.4.Final
2024-08-18T19:16:15.851+02:00  INFO 17422 --- [           main] o.h.c.internal.RegionFactoryInitiator    : HHH000026: Second-level cache disabled
2024-08-18T19:16:17.282+02:00  INFO 17422 --- [           main] o.s.o.j.p.SpringPersistenceUnitInfo      : No LoadTimeWeaver setup: ignoring JPA class transformer
2024-08-18T19:16:17.433+02:00  INFO 17422 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Starting...
2024-08-18T19:16:18.122+02:00  INFO 17422 --- [           main] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection conn0: url=jdbc:h2:mem:h2 user=SA
2024-08-18T19:16:18.131+02:00  INFO 17422 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Start completed.
2024-08-18T19:16:23.359+02:00  INFO 17422 --- [           main] o.h.e.t.j.p.i.JtaPlatformInitiator       : HHH000489: No JTA platform available (set 'hibernate.transaction.jta.platform' to enable JTA platform integration)
2024-08-18T19:16:23.682+02:00  INFO 17422 --- [           main] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
2024-08-18T19:16:26.640+02:00  INFO 17422 --- [           main] o.s.d.j.r.query.QueryEnhancerFactory     : Hibernate is in classpath; If applicable, HQL parser will be used.
2024-08-18T19:16:28.644+02:00  INFO 17422 --- [           main] d.k.r.remote.RoborockCredentials         : clientId not configured. Using auto-generated clientId 5Q2+aXjtO5qukg7yEoWu1Q==.
2024-08-18T19:16:32.075+02:00  INFO 17422 --- [           main] d.k.r.RoborockBridgeApplicationKt        : Started RoborockBridgeApplicationKt in 26.25 seconds (process running for 28.366)
2024-08-18T19:16:34.710+02:00  INFO 17422 --- [           main] d.k.roborockbridge.remote.rest.UserApi   : ok true
2024-08-18T19:16:35.077+02:00  INFO 17422 --- [           main] d.k.roborockbridge.bridge.BridgeMqtt     : Announcing new home with id '3659986'
2024-08-18T19:16:35.171+02:00  INFO 17422 --- [           main] d.k.roborockbridge.bridge.BridgeMqtt     : Announcing new robot with id '782w1Nhd37ltwdVbn1xc6O'
2024-08-18T19:16:35.534+02:00  INFO 17422 --- [           main] d.k.roborockbridge.bridge.BridgeMqtt     : Announcing 6 rooms.
2024-08-18T19:16:35.848+02:00  WARN 17422 --- [           main] d.k.r.remote.rest.dto.UnknownFieldsImpl  : ParamsForZonedCleanup: Found unknown extra property "auto_dry" with value: 1
2024-08-18T19:16:35.849+02:00  WARN 17422 --- [           main] d.k.r.remote.rest.dto.UnknownFieldsImpl  : ParamsForZonedCleanup: Found unknown extra property "auto_dustCollection" with value: 1
2024-08-18T19:16:35.849+02:00  WARN 17422 --- [           main] d.k.r.remote.rest.dto.UnknownFieldsImpl  : ParamsForZonedCleanup: Found unknown extra property "region_num" with value: 0
2024-08-18T19:16:35.854+02:00  WARN 17422 --- [           main] d.k.r.remote.rest.dto.UnknownFieldsImpl  : UserSceneParam: Found unknown extra property "tagId" with value: "1002"
2024-08-18T19:16:35.878+02:00  WARN 17422 --- [           main] d.k.r.remote.rest.dto.UnknownFieldsImpl  : ScenesAppStartParam: Found unknown extra property "auto_dustCollection" with value: 1
2024-08-18T19:16:35.879+02:00  WARN 17422 --- [           main] d.k.r.remote.rest.dto.UnknownFieldsImpl  : UserSceneParam: Found unknown extra property "tagId" with value: "1005"
2024-08-18T19:16:35.881+02:00  WARN 17422 --- [           main] d.k.r.remote.rest.dto.UnknownFieldsImpl  : ScenesAppStartParam: Found unknown extra property "auto_dustCollection" with value: 1
2024-08-18T19:16:35.883+02:00  WARN 17422 --- [           main] d.k.r.remote.rest.dto.UnknownFieldsImpl  : UserSceneParam: Found unknown extra property "tagId" with value: "1003"
2024-08-18T19:16:35.933+02:00  INFO 17422 --- [           main] d.k.roborockbridge.bridge.BridgeMqtt     : Announcing 3 schemas.
2024-08-18T19:16:36.571+02:00  INFO 17422 --- [       Thread-1] d.k.r.remote.mqtt.RoborockMqtt           : connected
2024-08-18T19:16:36.573+02:00  INFO 17422 --- [       Thread-1] d.k.r.remote.mqtt.RoborockMqtt           : Subscribing to topic rr/m/o/AbPEVCD9fOfam8Isumhyf/52163555/#
2024-08-18T19:16:37.493+02:00  INFO 17422 --- [           main] d.k.r.remote.mqtt.RoborockMqtt           : connected
2024-08-18T19:16:37.495+02:00  INFO 17422 --- [           main] d.k.r.remote.mqtt.RoborockMqtt           : Subscribing to topic rr/m/o/AbPEVCD9fOfam8Isumhyf/52163555/#
2024-08-18T19:16:37.498+02:00  WARN 17422 --- [Rec: rrb_POPa0n] d.k.r.remote.mqtt.RoborockMqtt           : Connection lost
2024-08-18T19:16:38.502+02:00  INFO 17422 --- [           main] d.k.r.remote.mqtt.RoborockMqtt           : Published 'get_room_mapping' request via topic 'rr/m/i/AbPEVCD9fOfam8Isumhyf/52163555/782w1Nhd37ltwdVbn1xc6O'.
2024-08-18T19:16:38.609+02:00  INFO 17422 --- [all: rrb_POPa0n] d.k.r.remote.mqtt.RoborockMqtt           : Lambda: New message for topic 'rr/m/o/AbPEVCD9fOfam8Isumhyf/52163555/782w1Nhd37ltwdVbn1xc6O' 0
2024-08-18T19:16:38.884+02:00  INFO 17422 --- [all: rrb_POPa0n] d.k.r.remote.mqtt.MessageDecoder         : Received response to request 1 with method 'GET_ROOM_MAPPING'.
2024-08-18T19:16:39.203+02:00  INFO 17422 --- [           main] d.k.roborockbridge.bridge.BridgeMqtt     : Announcing 6 rooms.
2024-08-18T19:17:32.132+02:00  INFO 17422 --- [   scheduling-1] d.k.r.remote.mqtt.RoborockMqtt           : disconnecting since bus idle
2024-08-18T19:17:32.180+02:00  INFO 17422 --- [   scheduling-1] d.k.r.remote.mqtt.RoborockMqtt           : disconnected
2024-08-18T19:17:39.248+02:00  INFO 17422 --- [           main] de.konqi.roborockbridge.BridgeService    : Requesting cleanup routine '3358614' via rest api.
2024-08-18T19:17:39.567+02:00 ERROR 17422 --- [           main] o.s.boot.SpringApplication               : Application run failed

org.hibernate.LazyInitializationException: failed to lazily initialize a collection of role: de.konqi.roborockbridge.persistence.entity.Routine.triggeredDeviceIds: could not initialize proxy - no Session
        at org.hibernate.collection.spi.AbstractPersistentCollection.throwLazyInitializationException(AbstractPersistentCollection.java:634) ~[hibernate-core-6.4.4.Final.jar!/:6.4.4.Final]
        at org.hibernate.collection.spi.AbstractPersistentCollection.withTemporarySessionIfNeeded(AbstractPersistentCollection.java:217) ~[hibernate-core-6.4.4.Final.jar!/:6.4.4.Final]
        at org.hibernate.collection.spi.AbstractPersistentCollection.initialize(AbstractPersistentCollection.java:613) ~[hibernate-core-6.4.4.Final.jar!/:6.4.4.Final]
        at org.hibernate.collection.spi.AbstractPersistentCollection.read(AbstractPersistentCollection.java:136) ~[hibernate-core-6.4.4.Final.jar!/:6.4.4.Final]
        at org.hibernate.collection.spi.PersistentSet.iterator(PersistentSet.java:169) ~[hibernate-core-6.4.4.Final.jar!/:6.4.4.Final]
        at de.konqi.roborockbridge.BridgeService.bridgeMqttProcessingLoop$lambda$16(BridgeService.kt:442) ~[!/:0.0.7-SNAPSHOT]
        at de.konqi.roborockbridge.BridgeService.bridgeMqttProcessingLoop$lambda$17(BridgeService.kt:295) ~[!/:0.0.7-SNAPSHOT]
        at java.base/java.util.Optional.ifPresent(Optional.java:178) ~[na:na]
        at de.konqi.roborockbridge.BridgeService.bridgeMqttProcessingLoop(BridgeService.kt:295) ~[!/:0.0.7-SNAPSHOT]
        at de.konqi.roborockbridge.BridgeService.worker(BridgeService.kt:130) ~[!/:0.0.7-SNAPSHOT]
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[na:na]
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
        at java.base/java.lang.reflect.Method.invoke(Method.java:568) ~[na:na]
        at org.springframework.context.event.ApplicationListenerMethodAdapter.doInvoke(ApplicationListenerMethodAdapter.java:365) ~[spring-context-6.1.6.jar!/:6.1.6]
        at org.springframework.context.event.ApplicationListenerMethodAdapter.processEvent(ApplicationListenerMethodAdapter.java:237) ~[spring-context-6.1.6.jar!/:6.1.6]
        at org.springframework.context.event.ApplicationListenerMethodAdapter.onApplicationEvent(ApplicationListenerMethodAdapter.java:168) ~[spring-context-6.1.6.jar!/:6.1.6]
        at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:185) ~[spring-context-6.1.6.jar!/:6.1.6]
        at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:178) ~[spring-context-6.1.6.jar!/:6.1.6]
        at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:156) ~[spring-context-6.1.6.jar!/:6.1.6]
        at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:451) ~[spring-context-6.1.6.jar!/:6.1.6]
        at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:384) ~[spring-context-6.1.6.jar!/:6.1.6]
        at org.springframework.boot.context.event.EventPublishingRunListener.ready(EventPublishingRunListener.java:109) ~[spring-boot-3.2.5.jar!/:3.2.5]
        at org.springframework.boot.SpringApplicationRunListeners.lambda$ready$6(SpringApplicationRunListeners.java:80) ~[spring-boot-3.2.5.jar!/:3.2.5]
        at java.base/java.lang.Iterable.forEach(Iterable.java:75) ~[na:na]
        at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:118) ~[spring-boot-3.2.5.jar!/:3.2.5]
        at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:112) ~[spring-boot-3.2.5.jar!/:3.2.5]
        at org.springframework.boot.SpringApplicationRunListeners.ready(SpringApplicationRunListeners.java:80) ~[spring-boot-3.2.5.jar!/:3.2.5]
        at org.springframework.boot.SpringApplication.run(SpringApplication.java:348) ~[spring-boot-3.2.5.jar!/:3.2.5]
        at de.konqi.roborockbridge.RoborockBridgeApplicationKt.main(RoborockBridgeApplication.kt:38) ~[!/:0.0.7-SNAPSHOT]
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[na:na]
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
        at java.base/java.lang.reflect.Method.invoke(Method.java:568) ~[na:na]
        at org.springframework.boot.loader.launch.Launcher.launch(Launcher.java:91) ~[roborock-bridge.jar:0.0.7-SNAPSHOT]
        at org.springframework.boot.loader.launch.Launcher.launch(Launcher.java:53) ~[roborock-bridge.jar:0.0.7-SNAPSHOT]
        at org.springframework.boot.loader.launch.JarLauncher.main(JarLauncher.java:58) ~[roborock-bridge.jar:0.0.7-SNAPSHOT]

2024-08-18T19:17:39.630+02:00  INFO 17422 --- [           main] de.konqi.roborockbridge.BridgeService    : Shutting down bridge service
2024-08-18T19:17:39.650+02:00  INFO 17422 --- [           main] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2024-08-18T19:17:39.657+02:00  INFO 17422 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown initiated...
2024-08-18T19:17:39.663+02:00  INFO 17422 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown completed.
robin0793 commented 1 month ago

Just saw version 0.0.8 is out, but the issue does still occur.