ozwdaemon stuck after restart with 100% cpu load

[oeiber]

Hi, after importing my about 40 node zwave network, ozwdaemon stuck with 100% cpu load on my pi 4. I waked up all my battery devices and all nodes where shown correctly in ozwadmin, exept one. After clicking "refresh node", ozwdaemon crashed and I'm unable to access ozwdaemon using ozwadmin.

Here are the latest log entries:

2021-02-02 16:10:26.674917506 [20210202 16:10:26.674 CET] [ozw.mqtt.publisher] [debug]: Removing CommandClass Topic for 10 1 112 2021-02-02 16:10:30.531050573 [20210202 16:10:30.530 CET] [ozw.values] [debug]: delValue: Removing Value QVariant(QString, "Humidity Differential Report") QVariant(qulonglong, 6473924642340881) 0 2021-02-02 16:10:30.533176772 [20210202 16:10:30.532 CET] [ozw.notifications] [debug]: Notification pvt_valueRemoved: 1970325010792468 Thread: 0x7fb7b2a690 2021-02-02 16:10:38.271925013 [20210202 16:10:38.271 CET] [ozw.values] [debug]: delValue: Removing Value QVariant(QString, "Home Security") QVariant(qulonglong, 1970325010792468) 0 2021-02-02 16:10:38.273902436 [20210202 16:10:38.273 CET] [ozw.notifications] [debug]: Notification pvt_valueRemoved: 72057594211745809 Thread: 0x7fb7b2a690 2021-02-02 16:10:42.158934491 [20210202 16:10:42.158 CET] [ozw.mqtt.publisher] [debug]: Removing CommandClass Topic for 10 1 113 2021-02-02 16:10:46.019550279 [20210202 16:10:46.019 CET] [ozw.values] [debug]: delValue: Removing Value QVariant(QString, "Previous Event Cleared") QVariant(qulonglong, 72057594211745809) 0 2021-02-02 16:10:46.021505332 [20210202 16:10:46.021 CET] [ozw.notifications] [debug]: Notification pvt_valueRemoved: 182222867 Thread: 0x7fb7b2a690 2021-02-02 16:10:53.755667719 [20210202 16:10:53.755 CET] [ozw.values] [debug]: delValue: Removing Value QVariant(QString, "Loaded Config Revision") QVariant(qulonglong, 182222867) 0 2021-02-02 16:10:53.757619957 [20210202 16:10:53.757 CET] [ozw.notifications] [debug]: Notification pvt_valueRemoved: 281475158933523 Thread: 0x7fb7b2a690 2021-02-02 16:11:01.469804662 [20210202 16:11:01.469 CET] [ozw.values] [debug]: delValue: Removing Value QVariant(QString, "Config File Revision") QVariant(qulonglong, 281475158933523) 0 2021-02-02 16:11:01.471900749 [20210202 16:11:01.471 CET] [ozw.notifications] [debug]: Notification pvt_valueRemoved: 562950135644179 Thread: 0x7fb7b2a690 2021-02-02 16:11:09.125958236 [20210202 16:11:09.125 CET] [ozw.values] [debug]: delValue: Removing Value QVariant(QString, "Latest Available Config File Revision") QVariant(qulonglong, 562950135644179) 0 2021-02-02 16:11:09.128040824 [20210202 16:11:09.127 CET] [ozw.notifications] [debug]: Notification pvt_valueRemoved: 1125900089065495 Thread: 0x7fb7b2a690 2021-02-02 16:11:12.955877916 [20210202 16:11:12.955 CET] [ozw.mqtt.publisher] [debug]: Removing CommandClass Topic for 10 1 114 2021-02-02 16:11:16.793692945 [20210202 16:11:16.793 CET] [ozw.values] [debug]: delValue: Removing Value QVariant(QString, "Serial Number") QVariant(qulonglong, 1125900089065495) 0 2021-02-02 16:11:16.795765812 [20210202 16:11:16.795 CET] [ozw.notifications] [debug]: Notification pvt_valueRemoved: 182239252 Thread: 0x7fb7b2a690 2021-02-02 16:11:24.429036711 [20210202 16:11:24.428 CET] [ozw.values] [debug]: delValue: Removing Value QVariant(QString, "Powerlevel") QVariant(qulonglong, 182239252) 0 2021-02-02 16:11:24.431127762 [20210202 16:11:24.430 CET] [ozw.notifications] [debug]: Notification pvt_valueRemoved: 281475158949905 Thread: 0x7fb7b2a690 2021-02-02 16:11:32.055926021 [20210202 16:11:32.055 CET] [ozw.values] [debug]: delValue: Removing Value QVariant(QString, "Timeout") QVariant(qulonglong, 281475158949905) 0 2021-02-02 16:11:32.057953666 [20210202 16:11:32.057 CET] [ozw.notifications] [debug]: Notification pvt_valueRemoved: 562950135660568 Thread: 0x7fb7b2a690

It seems to me ozwdaemon is stil inizializing the network after startup, but this is very slow because of the cpu load.

After a fresh restart:

2021-02-02 16:19:19.111388600 [20210202 16:19:19.111 CET] [ozw.mqtt.publisher] [debug]: MQTT State Change "Disconnected" 2021-02-02 16:19:19.111735263 [20210202 16:19:19.111 CET] [ozw.mqtt.publisher] [warning]: Exiting on Failure 2021-02-02 16:19:19.112060112 [20210202 16:19:19.111 CET] [ozw.mqtt.publisher] [warning]: MQTT Client Disconnnected 2021-02-02 16:19:19.112355813 [20210202 16:19:19.112 CET] [ozw.mqtt.publisher] [warning]: MQTT Client Error "Transport Invalid" 2021-02-02 16:19:19.112771550 [20210202 16:19:19.112 CET] [ozw.library] [info]: Info - Node: 0 mgr, Driver for controller /dev/ttyACM0 pending removal 2021-02-02 16:19:19.113156528 [20210202 16:19:19.113 CET] [ozw.library] [debug]: Detail - Node: 0 Notification: DriverRemoved 2021-02-02 16:19:19.113447914 [20210202 16:19:19.113 CET] [ozw.logging] [debug]: Increasing Logging Capacity to 9000 2021-02-02 16:19:19.115729486 [20210202 16:19:19.115 CET] [ozw.notifications] [debug]: Notification pvt_driverRemoved 3875077655 Thread: 0xf4cda010 2021-02-02 16:19:19.116078112 [20210202 16:19:19.115 CET] [ozw.notifications] [debug]: Notification pvt_nodeRemoved 1 Thread: 0xf4cda010 2021-02-02 16:19:19.116417109 [20210202 16:19:19.116 CET] [ozw.notifications] [debug]: Notification pvt_valueRemoved: 17301521 Thread: 0xf4cda010 2021-02-02 16:19:24.832432601 [20210202 16:19:24.832 CET] [ozw.library] [debug]: Detail - Node: 48 Received: 0x01, 0x18, 0x00, 0x13, 0x33, 0x01, 0x03, 0xaf, 0x00, 0x7f, 0x7f, 0x7f, 0x7f, 0x7f, 0x00, 0x01, 0x07, 0x00, 0x00, 0x00, 0x00, 0x02, 0x0f, 0x22, 0x30, 0x0c 2021-02-02 16:19:24.832949485 [20210202 16:19:24.832 CET] [ozw.library] [debug]: Detail - Node: 48 ZW_SEND_DATA Request with callback ID 0x33 received (expected 0x33) 2021-02-02 16:19:24.833368537 [20210202 16:19:24.833 CET] [ozw.library] [debug]: Detail - Node: 48 Extended TxStatus: Time: 9430, Hops: 0, Rssi: --- --- --- --- ---, AckChannel: 0, TxChannel: 1, RouteScheme: Explorer Route, Route: 0 0 0 0, RouteSpeed: 40K, RouteTries: 15, FailedLinkFrom: 34, FailedLinkTo: 48 2021-02-02 16:19:24.833711459 [20210202 16:19:24.833 CET] [ozw.library] [info]: Info - Node: 48 WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep. 2021-02-02 16:19:24.834026345 [20210202 16:19:24.833 CET] [ozw.library] [info]: Info - Node: 48 Node 48 has been marked as asleep 2021-02-02 16:19:24.834348676 [20210202 16:19:24.834 CET] [ozw.library] [info]: Info - Node: 48 Node not responding - moving QueryStageComplete command to Wake-Up queue 2021-02-02 16:19:24.834665469 [20210202 16:19:24.834 CET] [ozw.library] [warning]: Warning - Node: 0 CheckCompletedNodeQueries m_allNodesQueried=0 m_awakeNodesQueried=0 2021-02-02 16:19:24.834980503 [20210202 16:19:24.834 CET] [ozw.library] [warning]: Warning - Node: 0 CheckCompletedNodeQueries all=0, deadFound=0 sleepingOnly=0 2021-02-02 16:19:24.835345815 [20210202 16:19:24.835 CET] [ozw.library] [info]: Info - Node: 0 Saving Cache 2021-02-02 16:19:24.835966865 [20210202 16:19:24.835 CET] [ozw.library] [info]: Info - Node: 1 Cache Save for Node 1 as its QueryStage_CacheLoad 2021-02-02 16:19:24.838390954 [20210202 16:19:24.838 CET] [ozw.library] [info]: Info - Node: 2 Cache Save for Node 2 as its QueryStage_CacheLoad 2021-02-02 16:19:24.839420481 [20210202 16:19:24.839 CET] [ozw.library] [info]: Info - Node: 3 Cache Save for Node 3 as its QueryStage_CacheLoad 2021-02-02 16:19:24.840462434 [20210202 16:19:24.840 CET] [ozw.library] [info]: Info - Node: 4 Cache Save for Node 4 as its QueryStage_CacheLoad 2021-02-02 16:19:24.841484777 [20210202 16:19:24.841 CET] [ozw.library] [info]: Info - Node: 5 Cache Save for Node 5 as its QueryStage_CacheLoad 2021-02-02 16:19:24.842366065 [20210202 16:19:24.842 CET] [ozw.library] [info]: Info - Node: 6 Cache Save for Node 6 as its QueryStage_CacheLoad 2021-02-02 16:19:24.843548665 [20210202 16:19:24.843 CET] [ozw.library] [info]: Info - Node: 7 Cache Save for Node 7 as its QueryStage_CacheLoad 2021-02-02 16:19:24.844676711 [20210202 16:19:24.844 CET] [ozw.library] [info]: Info - Node: 8 Cache Save for Node 8 as its QueryStage_CacheLoad 2021-02-02 16:19:24.845250205 [20210202 16:19:24.845 CET] [ozw.library] [info]: Info - Node: 9 Cache Save for Node 9 as its QueryStage_CacheLoad 2021-02-02 16:19:24.846385676 [20210202 16:19:24.846 CET] [ozw.library] [info]: Info - Node: 10 Cache Save for Node 10 as its QueryStage_CacheLoad 2021-02-02 16:19:24.848043346 [20210202 16:19:24.847 CET] [ozw.library] [info]: Info - Node: 11 Cache Save for Node 11 as its QueryStage_CacheLoad 2021-02-02 16:19:24.849226261 [20210202 16:19:24.849 CET] [ozw.library] [info]: Info - Node: 12 Cache Save for Node 12 as its QueryStage_CacheLoad 2021-02-02 16:19:24.851198206 [20210202 16:19:24.850 CET] [ozw.library] [info]: Info - Node: 13 Cache Save for Node 13 as its QueryStage_CacheLoad 2021-02-02 16:19:24.852091142 [20210202 16:19:24.851 CET] [ozw.library] [info]: Info - Node: 16 Cache Save for Node 16 as its QueryStage_CacheLoad 2021-02-02 16:19:24.852975301 [20210202 16:19:24.852 CET] [ozw.library] [info]: Info - Node: 17 Cache Save for Node 17 as its QueryStage_CacheLoad 2021-02-02 16:19:24.853825182 [20210202 16:19:24.853 CET] [ozw.library] [info]: Info - Node: 18 Cache Save for Node 18 as its QueryStage_CacheLoad 2021-02-02 16:19:24.854829302 [20210202 16:19:24.854 CET] [ozw.library] [info]: Info - Node: 19 Cache Save for Node 19 as its QueryStage_CacheLoad 2021-02-02 16:19:24.855846700 [20210202 16:19:24.855 CET] [ozw.library] [info]: Info - Node: 20 Cache Save for Node 20 as its QueryStage_CacheLoad 2021-02-02 16:19:24.856878080 [20210202 16:19:24.856 CET] [ozw.library] [info]: Info - Node: 21 Cache Save for Node 21 as its QueryStage_CacheLoad 2021-02-02 16:19:24.857868460 [20210202 16:19:24.857 CET] [ozw.library] [info]: Info - Node: 22 Cache Save for Node 22 as its QueryStage_CacheLoad 2021-02-02 16:19:24.858879210 [20210202 16:19:24.858 CET] [ozw.library] [info]: Info - Node: 23 Cache Save for Node 23 as its QueryStage_CacheLoad 2021-02-02 16:19:24.859881145 [20210202 16:19:24.859 CET] [ozw.library] [info]: Info - Node: 24 Cache Save for Node 24 as its QueryStage_CacheLoad 2021-02-02 16:19:24.861830108 [20210202 16:19:24.861 CET] [ozw.library] [info]: Info - Node: 25 Cache Save for Node 25 as its QueryStage_CacheLoad 2021-02-02 16:19:24.863863127 [20210202 16:19:24.863 CET] [ozw.library] [info]: Info - Node: 26 Cache Save for Node 26 as its QueryStage_CacheLoad 2021-02-02 16:19:24.865840516 [20210202 16:19:24.865 CET] [ozw.library] [info]: Info - Node: 27 Cache Save for Node 27 as its QueryStage_CacheLoad 2021-02-02 16:19:24.866359937 [20210202 16:19:24.866 CET] [ozw.library] [info]: Info - Node: 28 Cache Save for Node 28 as its QueryStage_CacheLoad 2021-02-02 16:19:24.868316697 [20210202 16:19:24.868 CET] [ozw.library] [info]: Info - Node: 29 Cache Save for Node 29 as its QueryStage_CacheLoad 2021-02-02 16:19:24.870290568 [20210202 16:19:24.870 CET] [ozw.library] [info]: Info - Node: 30 Cache Save for Node 30 as its QueryStage_CacheLoad 2021-02-02 16:19:24.872268475 [20210202 16:19:24.872 CET] [ozw.library] [info]: Info - Node: 31 Cache Save for Node 31 as its QueryStage_CacheLoad 2021-02-02 16:19:24.874210328 [20210202 16:19:24.873 CET] [ozw.library] [info]: Info - Node: 32 Cache Save for Node 32 as its QueryStage_CacheLoad 2021-02-02 16:19:24.876256309 [20210202 16:19:24.876 CET] [ozw.library] [info]: Info - Node: 33 Cache Save for Node 33 as its QueryStage_CacheLoad 2021-02-02 16:19:24.878223032 [20210202 16:19:24.877 CET] [ozw.library] [info]: Info - Node: 34 Cache Save for Node 34 as its QueryStage_CacheLoad 2021-02-02 16:19:24.880190884 [20210202 16:19:24.879 CET] [ozw.library] [info]: Info - Node: 35 Cache Save for Node 35 as its QueryStage_CacheLoad 2021-02-02 16:19:24.882237273 [20210202 16:19:24.881 CET] [ozw.library] [info]: Info - Node: 36 Cache Save for Node 36 as its QueryStage_CacheLoad 2021-02-02 16:19:24.884237940 [20210202 16:19:24.883 CET] [ozw.library] [info]: Info - Node: 37 Cache Save for Node 37 as its QueryStage_CacheLoad 2021-02-02 16:19:24.886078441 [20210202 16:19:24.885 CET] [ozw.library] [info]: Info - Node: 39 Cache Save for Node 39 as its QueryStage_CacheLoad 2021-02-02 16:19:24.887993849 [20210202 16:19:24.887 CET] [ozw.library] [info]: Info - Node: 41 Cache Save for Node 41 as its QueryStage_CacheLoad 2021-02-02 16:19:24.889108876 [20210202 16:19:24.888 CET] [ozw.library] [info]: Info - Node: 43 Cache Save for Node 43 as its QueryStage_CacheLoad 2021-02-02 16:19:24.891246116 [20210202 16:19:24.890 CET] [ozw.library] [info]: Info - Node: 44 Cache Save for Node 44 as its QueryStage_CacheLoad 2021-02-02 16:19:24.892386198 [20210202 16:19:24.892 CET] [ozw.library] [info]: Info - Node: 45 Cache Save for Node 45 as its QueryStage_CacheLoad 2021-02-02 16:19:24.893274949 [20210202 16:19:24.893 CET] [ozw.library] [info]: Info - Node: 46 Cache Save for Node 46 as its QueryStage_CacheLoad 2021-02-02 16:19:24.893788333 [20210202 16:19:24.893 CET] [ozw.library] [info]: Info - Node: 47 Cache Save for Node 47 as its QueryStage_CacheLoad 2021-02-02 16:19:24.894819750 [20210202 16:19:24.894 CET] [ozw.library] [info]: Info - Node: 48 Cache Save for Node 48 as its QueryStage_CacheLoad 2021-02-02 16:19:24.895934647 [20210202 16:19:24.895 CET] [ozw.library] [info]: Info - Node: 49 Cache Save for Node 49 as its QueryStage_CacheLoad 2021-02-02 16:19:24.897381985 [20210202 16:19:24.897 CET] [ozw.library] [info]: Info - Node: 50 Cache Save for Node 50 as its QueryStage_CacheLoad 2021-02-02 16:19:24.899288690 [20210202 16:19:24.899 CET] [ozw.library] [info]: Info - Node: 51 Cache Save for Node 51 as its QueryStage_CacheLoad 2021

Should I also post the ozwcache file?

Thank you for your help!

Oliver

[oeiber]

Update: Using docker image firstof9/qt-ozwdaemon with configurable mqtt timeout did the trick: https://github.com/OpenZWave/qt-openzwave/issues/140#issuecomment-741507039

Is it possible to adopt this also to this branch?