search

OpenZWave / qt-openzwave

QT5 Wrapper for OpenZWave
GNU Lesser General Public License v3.0
105 stars 30 forks source link

Crash during startup v0.5.2 #175

Open abmantis opened 4 years ago

abmantis commented 4 years ago

A lot of times during startup, OZW will crash. This is specially annoying since the network takes 40+ minutes to startup :/ I'm using this in HA with the hass.io plugin.

Here are the last few lines from the log:

[20201003 22:09:24.037 WEST] [ozw.mqtt.publisher] [debug]: Publishing Event valueChanged: 12947851136729108 
[20201003 22:09:24.050 WEST] [ozw.library] [debug]: Detail - Node: 131   Received: 0x01, 0x0b, 0x00, 0x04, 0x00, 0x83, 0x05, 0x70, 0x06, 0x30, 0x01, 0x00, 0x31 
[20201003 22:09:24.050 WEST] [ozw.logging] [debug]: popping Log Mesages 
[20201003 22:09:24.051 WEST] [ozw.library] [info]: Info - Node: 131 Response RTT 35 Average Response RTT 35 
[20201003 22:09:24.051 WEST] [ozw.logging] [debug]: popping Log Mesages 
[20201003 22:09:24.051 WEST] [ozw.library] [debug]: Detail - Node: 131 Initial read of value 
[20201003 22:09:24.052 WEST] [ozw.logging] [debug]: popping Log Mesages 
[20201003 22:09:24.052 WEST] [ozw.library] [info]: Info - Node: 131 Received Configuration report: Parameter=48, Value=0 
[20201003 22:09:24.052 WEST] [ozw.logging] [debug]: popping Log Mesages 
[20201003 22:09:24.053 WEST] [ozw.library] [debug]: Detail - Node: 131 Notification: ValueChanged CC: COMMAND_CLASS_CONFIGURATION Instance: 1 Index: 48 
[20201003 22:09:24.053 WEST] [ozw.logging] [debug]: popping Log Mesages 
[20201003 22:09:24.054 WEST] [ozw.notifications] [debug]: Notification pvt_valueChanged:  13510801090150426 Thread:  0x7fe2b8f29d48 
[20201003 22:09:24.067 WEST] [ozw.mqtt.publisher.value] [warning]: Bitset is Missing Position or Value Members, or Incorrect Types:  "{\n    \"Label\": \"Enable/disable to send a report on Threshold\",\n    \"Value\": [],\n    \"Units\": \"\",\n    \"ValueSet\": false,\n    \"ValuePolled\": false,\n    \"ChangeVerified\": false,\n    \"Min\": 0,\n    \"Max\": 0,\n    \"Type\": \"BitSet\",\n    \"Instance\": 1,\n    \"CommandClass\": \"COMMAND_CLASS_CONFIGURATION\",\n    \"Index\": 48,\n    \"Node\": 131,\n    \"Genre\": \"Config\",\n    \"Help\": \"Enable/disable to send a report when the measurement is more than the upper limit value or less than the lower limit value. Note: If USB power, the Sensor will check the limit every 10 seconds. If battery power, the Sensor will check the limit when it is waken up.\",\n    \"ValueIDKey\": 13510801090150426,\n    \"ReadOnly\": false,\n    \"WriteOnly\": false,\n    \"Event\": \"valueAdded\",\n    \"TimeStamp\": 1601756805\n}" 
[20201003 22:09:24.067 WEST] [ozw.mqtt.publisher.value] [warning]: Bitset is Missing Position or Value Members, or Incorrect Types:  "{\n    \"Label\": \"Enable/disable to send a report on Threshold\",\n    \"Value\": [],\n    \"Units\": \"\",\n    \"ValueSet\": false,\n    \"ValuePolled\": false,\n    \"ChangeVerified\": false,\n    \"Min\": 0,\n    \"Max\": 0,\n    \"Type\": \"BitSet\",\n    \"Instance\": 1,\n    \"CommandClass\": \"COMMAND_CLASS_CONFIGURATION\",\n    \"Index\": 48,\n    \"Node\": 131,\n    \"Genre\": \"Config\",\n    \"Help\": \"Enable/disable to send a report when the measurement is more than the upper limit value or less than the lower limit value. Note: If USB power, the Sensor will check the limit every 10 seconds. If battery power, the Sensor will check the limit when it is waken up.\",\n    \"ValueIDKey\": 13510801090150426,\n    \"ReadOnly\": false,\n    \"WriteOnly\": false,\n    \"Event\": \"valueAdded\",\n    \"TimeStamp\": 1601756805\n}" 
[20201003 22:09:24.067 WEST] [ozw.mqtt.publisher.value] [warning]: Bitset is Missing Position or Value Members, or Incorrect Types:  "{\n    \"Label\": \"Enable/disable to send a report on Threshold\",\n    \"Value\": [],\n    \"Units\": \"\",\n    \"ValueSet\": false,\n    \"ValuePolled\": false,\n    \"ChangeVerified\": false,\n    \"Min\": 0,\n    \"Max\": 0,\n    \"Type\": \"BitSet\",\n    \"Instance\": 1,\n    \"CommandClass\": \"COMMAND_CLASS_CONFIGURATION\",\n    \"Index\": 48,\n    \"Node\": 131,\n    \"Genre\": \"Config\",\n    \"Help\": \"Enable/disable to send a report when the measurement is more than the upper limit value or less than the lower limit value. Note: If USB power, the Sensor will check the limit every 10 seconds. If battery power, the Sensor will check the limit when it is waken up.\",\n    \"ValueIDKey\": 13510801090150426,\n    \"ReadOnly\": false,\n    \"WriteOnly\": false,\n    \"Event\": \"valueAdded\",\n    \"TimeStamp\": 1601756805\n}" 
[20201003 22:09:24.068 WEST] [ozw.mqtt.publisher.value] [warning]: Bitset is Missing Position or Value Members, or Incorrect Types:  "{\n    \"Label\": \"Enable/disable to send a report on Threshold\",\n    \"Value\": [],\n    \"Units\": \"\",\n    \"ValueSet\": false,\n    \"ValuePolled\": false,\n    \"ChangeVerified\": false,\n    \"Min\": 0,\n    \"Max\": 0,\n    \"Type\": \"BitSet\",\n    \"Instance\": 1,\n    \"CommandClass\": \"COMMAND_CLASS_CONFIGURATION\",\n    \"Index\": 48,\n    \"Node\": 131,\n    \"Genre\": \"Config\",\n    \"Help\": \"Enable/disable to send a report when the measurement is more than the upper limit value or less than the lower limit value. Note: If USB power, the Sensor will check the limit every 10 seconds. If battery power, the Sensor will check the limit when it is waken up.\",\n    \"ValueIDKey\": 13510801090150426,\n    \"ReadOnly\": false,\n    \"WriteOnly\": false,\n    \"Event\": \"valueAdded\",\n    \"TimeStamp\": 1601756805\n}" 
[20201003 22:09:24.068 WEST] [ozw.mqtt.publisher.value] [warning]: Bitset is Missing Position or Value Members, or Incorrect Types:  "{\n    \"Label\": \"Enable/disable to send a report on Threshold\",\n    \"Value\": [],\n    \"Units\": \"\",\n    \"ValueSet\": false,\n    \"ValuePolled\": false,\n    \"ChangeVerified\": false,\n    \"Min\": 0,\n    \"Max\": 0,\n    \"Type\": \"BitSet\",\n    \"Instance\": 1,\n    \"CommandClass\": \"COMMAND_CLASS_CONFIGURATION\",\n    \"Index\": 48,\n    \"Node\": 131,\n    \"Genre\": \"Config\",\n    \"Help\": \"Enable/disable to send a report when the measurement is more than the upper limit value or less than the lower limit value. Note: If USB power, the Sensor will check the limit every 10 seconds. If battery power, the Sensor will check the limit when it is waken up.\",\n    \"ValueIDKey\": 13510801090150426,\n    \"ReadOnly\": false,\n    \"WriteOnly\": false,\n    \"Event\": \"valueAdded\",\n    \"TimeStamp\": 1601756805\n}" 
[20201003 22:09:24.068 WEST] [ozw.mqtt.publisher.value] [warning]: Bitset is Missing Position or Value Members, or Incorrect Types:  "{\n    \"Label\": \"Enable/disable to send a report on Threshold\",\n    \"Value\": [],\n    \"Units\": \"\",\n    \"ValueSet\": false,\n    \"ValuePolled\": false,\n    \"ChangeVerified\": false,\n    \"Min\": 0,\n    \"Max\": 0,\n    \"Type\": \"BitSet\",\n    \"Instance\": 1,\n    \"CommandClass\": \"COMMAND_CLASS_CONFIGURATION\",\n    \"Index\": 48,\n    \"Node\": 131,\n    \"Genre\": \"Config\",\n    \"Help\": \"Enable/disable to send a report when the measurement is more than the upper limit value or less than the lower limit value. Note: If USB power, the Sensor will check the limit every 10 seconds. If battery power, the Sensor will check the limit when it is waken up.\",\n    \"ValueIDKey\": 13510801090150426,\n    \"ReadOnly\": false,\n    \"WriteOnly\": false,\n    \"Event\": \"valueAdded\",\n    \"TimeStamp\": 1601756805\n}" 
[20201003 22:09:24.068 WEST] [ozw.mqtt.publisher.value] [warning]: Bitset is Missing Position or Value Members, or Incorrect Types:  "{\n    \"Label\": \"Enable/disable to send a report on Threshold\",\n    \"Value\": [],\n    \"Units\": \"\",\n    \"ValueSet\": false,\n    \"ValuePolled\": false,\n    \"ChangeVerified\": false,\n    \"Min\": 0,\n    \"Max\": 0,\n    \"Type\": \"BitSet\",\n    \"Instance\": 1,\n    \"CommandClass\": \"COMMAND_CLASS_CONFIGURATION\",\n    \"Index\": 48,\n    \"Node\": 131,\n    \"Genre\": \"Config\",\n    \"Help\": \"Enable/disable to send a report when the measurement is more than the upper limit value or less than the lower limit value. Note: If USB power, the Sensor will check the limit every 10 seconds. If battery power, the Sensor will check the limit when it is waken up.\",\n    \"ValueIDKey\": 13510801090150426,\n    \"ReadOnly\": false,\n    \"WriteOnly\": false,\n    \"Event\": \"valueAdded\",\n    \"TimeStamp\": 1601756805\n}" 
[20201003 22:09:24.076 WEST] [ozw.mqtt.publisher] [debug]: Publishing Event valueChanged: 13510801090150426 
[20201003 22:09:24.090 WEST] [ozw.library] [debug]: Detail - Node: 131   Received: 0x01, 0x07, 0x00, 0x13, 0xbc, 0x00, 0x00, 0x07, 0x50 
[20201003 22:09:24.090 WEST] [ozw.logging] [debug]: popping Log Mesages 
[20201003 22:09:24.091 WEST] [ozw.library] [debug]: Detail - Node: 131   ZW_SEND_DATA Request with callback ID 0xbc received (expected 0xbc) 
[20201003 22:09:24.091 WEST] [ozw.logging] [debug]: popping Log Mesages 
[20201003 22:09:24.092 WEST] [ozw.library] [info]: Info - Node: 131 Request RTT 77 Average Request RTT 51 
[20201003 22:09:24.092 WEST] [ozw.logging] [debug]: popping Log Mesages 
[20201003 22:09:24.093 WEST] [ozw.library] [debug]: Detail - Node: 131   Expected callbackId was received 
[20201003 22:09:24.093 WEST] [ozw.logging] [debug]: popping Log Mesages 
[20201003 22:09:24.102 WEST] [ozw.library] [debug]: Detail - Node: 131   Received: 0x01, 0x0b, 0x00, 0x04, 0x00, 0x83, 0x05, 0x70, 0x06, 0x30, 0x01, 0x00, 0x31 
[20201003 22:09:24.102 WEST] [ozw.logging] [debug]: popping Log Mesages 
[20201003 22:09:24.103 WEST] [ozw.library] [info]: Info - Node: 131 Response RTT 87 Average Response RTT 61 
[20201003 22:09:24.103 WEST] [ozw.logging] [debug]: popping Log Mesages 
[20201003 22:09:24.103 WEST] [ozw.library] [debug]: Detail - Node: 131 Value Updated: old value=0, new value=0, type=bitset 
[20201003 22:09:24.103 WEST] [ozw.logging] [debug]: popping Log Mesages 
[20201003 22:09:24.104 WEST] [ozw.library] [debug]: Detail - Node: 131 Changes to this value are not verified 
[20201003 22:09:24.104 WEST] [ozw.logging] [debug]: popping Log Mesages 
[20201003 22:09:24.105 WEST] [ozw.daemon] [warning]: ============================= 
[20201003 22:09:24.105 WEST] [ozw.daemon] [warning]: CRASH!!! - Dumping Backtrace: 
[20201003 22:09:24.105 WEST] [ozw.daemon] [warning]: ============================= 
[20201003 22:09:24.105 WEST] [ozw.daemon] [warning]: #1  0x00007fe2b8eda27d sp=0x00007fe2b5ec5c80 sigwaitinfo + 0x8 
[20201003 22:09:24.105 WEST] [ozw.daemon] [warning]: #2  0xb5ec627000307001 sp=0x00007fe2b5ec5c90  + 0x8 
[20201003 22:09:24.105 WEST] [default] [warning]: Exiting.... 
1601759364: Socket error on client qt-openzwave-1, disconnecting.
In exit
Terminating child 557
Terminating child 558
Process Process-2:
Traceback (most recent call last):
  File "/usr/lib/python3.8/multiprocessing/process.py", line 315, in _bootstrap
    self.run()
  File "/usr/lib/python3.8/multiprocessing/process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib/python3.8/site-packages/websockify/websockifyserver.py", line 691, in top_new_client
    client = self.do_handshake(startsock, address)
  File "/usr/lib/python3.8/site-packages/websockify/websockifyserver.py", line 619, in do_handshake
    self.RequestHandlerClass(retsock, address, self)
  File "/usr/lib/python3.8/site-packages/websockify/websockifyserver.py", line 99, in __init__
    SimpleHTTPRequestHandler.__init__(self, req, addr, server)
  File "/usr/lib/python3.8/http/server.py", line 647, in __init__
    super().__init__(*args, **kwargs)
  File "/usr/lib/python3.8/socketserver.py", line 720, in __init__
    self.handle()
  File "/usr/lib/python3.8/site-packages/websockify/websockifyserver.py", line 315, in handle
    SimpleHTTPRequestHandler.handle(self)
  File "/usr/lib/python3.8/http/server.py", line 429, in handle
    self.handle_one_request()
  File "/usr/lib/python3.8/site-packages/websockify/websocketserver.py", line 47, in handle_one_request
    super(WebSocketRequestHandlerMixIn, self).handle_one_request()
  File "/usr/lib/python3.8/http/server.py", line 395, in handle_one_request
    self.raw_requestline = self.rfile.readline(65537)
  File "/usr/lib/python3.8/socket.py", line 669, in readinto
    return self._sock.recv_into(b)
  File "/usr/lib/python3.8/site-packages/websockify/websockifyserver.py", line 683, in do_SIGTERM
    self.terminate()
  File "/usr/lib/python3.8/site-packages/websockify/websockifyserver.py", line 656, in terminate
    raise self.Terminate()
websockify.websockifyserver.WebSockifyServer.Terminate
Process Process-1:
Traceback (most recent call last):
  File "/usr/lib/python3.8/multiprocessing/process.py", line 315, in _bootstrap
    self.run()
  File "/usr/lib/python3.8/multiprocessing/process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib/python3.8/site-packages/websockify/websockifyserver.py", line 691, in top_new_client
    client = self.do_handshake(startsock, address)
  File "/usr/lib/python3.8/site-packages/websockify/websockifyserver.py", line 619, in do_handshake
    self.RequestHandlerClass(retsock, address, self)
  File "/usr/lib/python3.8/site-packages/websockify/websockifyserver.py", line 99, in __init__
    SimpleHTTPRequestHandler.__init__(self, req, addr, server)
  File "/usr/lib/python3.8/http/server.py", line 647, in __init__
    super().__init__(*args, **kwargs)
  File "/usr/lib/python3.8/socketserver.py", line 720, in __init__
    self.handle()
  File "/usr/lib/python3.8/site-packages/websockify/websockifyserver.py", line 315, in handle
    SimpleHTTPRequestHandler.handle(self)
  File "/usr/lib/python3.8/http/server.py", line 429, in handle
    self.handle_one_request()
  File "/usr/lib/python3.8/site-packages/websockify/websocketserver.py", line 47, in handle_one_request
    super(WebSocketRequestHandlerMixIn, self).handle_one_request()
  File "/usr/lib/python3.8/http/server.py", line 395, in handle_one_request
    self.raw_requestline = self.rfile.readline(65537)
  File "/usr/lib/python3.8/socket.py", line 669, in readinto
    return self._sock.recv_into(b)
  File "/usr/lib/python3.8/site-packages/websockify/websockifyserver.py", line 683, in do_SIGTERM
    self.terminate()
  File "/usr/lib/python3.8/site-packages/websockify/websockifyserver.py", line 656, in terminate
    raise self.Terminate()
websockify.websockifyserver.WebSockifyServer.Terminate
[cont-finish.d] executing container finish scripts...
[cont-finish.d] mqtt.sh: executing... 
1601759364: mosquitto version 1.6.8 terminating
1601759364: Saving in-memory database to /data/mosquitto.db.
[22:09:24] INFO: Ensure upstream MQTT server has the correct OZW status
[cont-finish.d] mqtt.sh: exited 0.
[cont-finish.d] done.
[s6-finish] waiting for services.
[s6-finish] sending all processes the TERM signal.
[s6-finish] sending all processes the KILL signal and exiting.

Not sure if related, but node 131 is a Aeotec Multisensor.

abmantis commented 4 years ago

Maybe related or duplicate of https://github.com/OpenZWave/qt-openzwave/issues/129 Seems like the same issue, also with aeotec multisensor.