Z-way server goes down spontaneously

Discussions about Z-Way software and Z-Wave technology in general
User avatar
PoltoS
Posts: 7565
Joined: 26 Jan 2011 19:36

Re: Z-way server goes down spontaneously

Post by PoltoS »

Do you mean using some self-signed certificate and just accessing https://localhost will lead to crashes?
User avatar
GokMasE
Posts: 59
Joined: 13 Mar 2016 01:04
Location: Sweden

Re: Z-way server goes down spontaneously

Post by GokMasE »

Sorry for another late reply...
PoltoS wrote:
04 Nov 2019 01:52
If you don't use HTTPDevice module, how do you execute the HTTP Get request? Via some piece of code made by yourself? Can you share it?
Yes, the HTTP Get request is handled within my own application. My application is basically doing two things:

1) Keeping one listening socket open (for port # 1025 which is what I configured HTTPGet module to send the status updates to). When those requests are read from the socket, I evaluate the query strings and store the dev id and level data locally, and immediately reply with the exact same "200 OK" msg back to the z-wave server every time. When this reply has finished sending (sent with no errors reported) the socket is closed. After that, a new listening socket is opened.

2) Sending occasional request for switching devices on/off to the z-wave server by creating a socket on port 8083 and sending commands through the JSON API.

From the looks of the test sessions I have ran (and from my point of view) it seems like the z-wave server is crashing somewhere right between the moment where the HTTPGet module has successfully sent a http request (with query strings containing device level update data), and the moment where my "200 OK" reply should be received (and thus also logged in z-wave-server.log). I would expect a line saying something like

Code: Select all

"[yyyy-mm-dd hh:mm:ss:fff] [I] Request was successful"
However, for the last http get request in the log there is no such acknowledgement of the reply logged unless I am mistaken.

Here is the end part of the z-wave-server.log from the time of latest crash:

Code: Select all

[2019-12-31 03:41:57.290] [D] [zway] RECEIVED: ( 01 10 00 04 00 06 0A 32 02 21 34 00 00 00 03 00 00 C1 )
[2019-12-31 03:41:57.290] [D] [zway] SENT ACK
[2019-12-31 03:41:57.291] [D] [zway] SETDATA devices.6.data.lastReceived = 0 (0x00000000)
[2019-12-31 03:41:57.291] [D] [zway] SETDATA devices.6.instances.0.commandClasses.50.data.2.val = 0.300000
[2019-12-31 03:41:57.291] [D] [zway] SETDATA devices.6.instances.0.commandClasses.50.data.2.delta = 0 (0x00000000)
[2019-12-31 03:41:57.291] [D] [zway] SETDATA devices.6.instances.0.commandClasses.50.data.2.ratetype = 1 (0x00000001)
[2019-12-31 03:41:57.291] [D] [zway] SETDATA devices.6.instances.0.commandClasses.50.data.2 = Empty
[2019-12-31 03:41:57.292] [I] [core] http://192.168.1.3:1025/ZWave?Cmd=CBck&Dev=%DEVICE%&Lev=%VALUE% : ZWayVDev_zway_6-0-50-2 : 0.3 : http://192.168.1.3:1025/ZWave?Cmd=CBck&Dev=ZWayVDev_zway_6-0-50-2&Lev=0.3
[2019-12-31 03:41:57.515] [I] [core] Request was successful
[2019-12-31 03:41:58.072] [D] [zway] Job 0x13: deleted from queue
[2019-12-31 03:41:58.307] [D] [zway] RECEIVED: ( 01 14 00 04 00 06 0E 60 0D 01 00 32 02 21 34 00 00 00 08 00 00 A6 )
[2019-12-31 03:41:58.307] [D] [zway] SENT ACK
[2019-12-31 03:41:58.307] [D] [zway] SETDATA devices.6.data.lastReceived = 0 (0x00000000)
[2019-12-31 03:41:58.307] [D] [zway] SETDATA devices.6.instances.1.commandClasses.50.data.2.val = 0.800000
[2019-12-31 03:41:58.307] [D] [zway] SETDATA devices.6.instances.1.commandClasses.50.data.2.delta = 0 (0x00000000)
[2019-12-31 03:41:58.307] [D] [zway] SETDATA devices.6.instances.1.commandClasses.50.data.2.ratetype = 1 (0x00000001)
[2019-12-31 03:41:58.307] [D] [zway] SETDATA devices.6.instances.1.commandClasses.50.data.2 = Empty
[2019-12-31 03:41:58.315] [I] [core] http://192.168.1.3:1025/ZWave?Cmd=CBck&Dev=%DEVICE%&Lev=%VALUE% : ZWayVDev_zway_6-1-50-2 : 0.8 : http://192.168.1.3:1025/ZWave?Cmd=CBck&Dev=ZWayVDev_zway_6-1-50-2&Lev=0.8
[2019-12-31 03:41:58.372] [I] [core] Request was successful
[2019-12-31 03:42:01.312] [D] [zway] RECEIVED: ( 01 10 00 04 00 06 0A 32 02 21 34 00 00 00 10 00 00 D2 )
[2019-12-31 03:42:01.312] [D] [zway] SENT ACK
[2019-12-31 03:42:01.312] [D] [zway] SETDATA devices.6.data.lastReceived = 0 (0x00000000)
[2019-12-31 03:42:01.313] [D] [zway] SETDATA devices.6.instances.0.commandClasses.50.data.2.val = 1.600000
[2019-12-31 03:42:01.313] [D] [zway] SETDATA devices.6.instances.0.commandClasses.50.data.2.delta = 0 (0x00000000)
[2019-12-31 03:42:01.313] [D] [zway] SETDATA devices.6.instances.0.commandClasses.50.data.2.ratetype = 1 (0x00000001)
[2019-12-31 03:42:01.313] [D] [zway] SETDATA devices.6.instances.0.commandClasses.50.data.2 = Empty
[2019-12-31 03:42:01.319] [I] [core] http://192.168.1.3:1025/ZWave?Cmd=CBck&Dev=%DEVICE%&Lev=%VALUE% : ZWayVDev_zway_6-0-50-2 : 1.6 : http://192.168.1.3:1025/ZWave?Cmd=CBck&Dev=ZWayVDev_zway_6-0-50-2&Lev=1.6
I had a go at running GDB and this is an excerpt from the log when the z-wave-server is crashing:

Code: Select all


[New Thread 0x6fbff450 (LWP 28448)]
[Thread 0x6fbff450 (LWP 28448) exited]
[New Thread 0x6fbff450 (LWP 28449)]
[Thread 0x6fbff450 (LWP 28449) exited]
[New Thread 0x6fbff450 (LWP 28450)]
[Thread 0x6fbff450 (LWP 28450) exited]
[New Thread 0x6fbff450 (LWP 28451)]
[Thread 0x6fbff450 (LWP 28451) exited]
[New Thread 0x6fbff450 (LWP 28452)]
[Thread 0x6fbff450 (LWP 28452) exited]
[New Thread 0x6fbff450 (LWP 28453)]
[Thread 0x6fbff450 (LWP 28453) exited]
[New Thread 0x6fbff450 (LWP 28454)]
[Thread 0x6fbff450 (LWP 28454) exited]
[New Thread 0x6fbff450 (LWP 28455)]
[Thread 0x6fbff450 (LWP 28455) exited]
[New Thread 0x6fbff450 (LWP 28456)]
[Thread 0x6fbff450 (LWP 28456) exited]
[New Thread 0x6fbff450 (LWP 28457)]
[Thread 0x6fbff450 (LWP 28457) exited]
[New Thread 0x6fbff450 (LWP 28458)]
[Thread 0x6fbff450 (LWP 28458) exited]
[New Thread 0x6fbff450 (LWP 28459)]
[Thread 0x6fbff450 (LWP 28459) exited]
[New Thread 0x6fbff450 (LWP 28460)]
[Thread 0x6fbff450 (LWP 28460) exited]
[New Thread 0x6fbff450 (LWP 28461)]
[Thread 0x6fbff450 (LWP 28461) exited]

Thread 7 "zway/core" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x737cb450 (LWP 1981)]
0x76c03e5c in v8::internal::GlobalHandles::Create(v8::internal::Object*) ()
   from libs/libv8.so
(gdb)
Continuing.
Unable to fetch general registers.: No such process.
Unable to fetch general registers.: No such process.
Unable to fetch general registers.: No such process.
(gdb) [Thread 0x711fd450 (LWP 1986) exited]
[Thread 0x719fe450 (LWP 1985) exited]
[Thread 0x721ff450 (LWP 1984) exited]
[Thread 0x737dc450 (LWP 1980) exited]
[Thread 0x737ed450 (LWP 1979) exited]
[Thread 0x737fe450 (LWP 1978) exited]
[Thread 0x75282450 (LWP 1977) exited]
[Thread 0x73fff450 (LWP 1976) exited]
[Thread 0x76ff5000 (LWP 1948) exited]

Program terminated with signal SIGSEGV, Segmentation fault.
The program no longer exists.
(gdb) Quit

I am not sure if this is useful information or not, but if there is some way to retrieve more detailed information on the segmentation fault reported by GDB, I would happily look into it more closely.

It does seem like one thing that is a catalyst for this crash, is the Qubino device mentioned earlier in this thread. When the switch is set to ON, its built-in energy meter is at times producing a steady stream of HTTP get requests.


Regards,

/Joakim
User avatar
PoltoS
Posts: 7565
Joined: 26 Jan 2011 19:36

Re: Z-way server goes down spontaneously

Post by PoltoS »

Please do in gdb "info thr" and "bt". But for me it looks like the reason is memory exhausted. Can you run top from time to time to monitor how much Z-Way is using?
User avatar
PoltoS
Posts: 7565
Joined: 26 Jan 2011 19:36

Re: Z-way server goes down spontaneously

Post by PoltoS »

Looks we have found the issue in concurrent threads in OpenSSL used in cURL used in Z-Way. We are checking it.
User avatar
PoltoS
Posts: 7565
Joined: 26 Jan 2011 19:36

Re: Z-way server goes down spontaneously

Post by PoltoS »

Please try https://storage.z-wave.me/z-way-serverz ... _armhf.deb (works on stretch - not yet tested on buster)

This version has just updated dependencies on cURL, OpenSSL and LibWebsockets to use OpenSSL 1.1.0 - it is much more stable in multi threaded environment,
User avatar
GokMasE
Posts: 59
Joined: 13 Mar 2016 01:04
Location: Sweden

Re: Z-way server goes down spontaneously

Post by GokMasE »

PoltoS wrote:
01 Jan 2020 23:43
Please do in gdb "info thr" and "bt". But for me it looks like the reason is memory exhausted. Can you run top from time to time to monitor how much Z-Way is using?
I will keep gdb running and make sure to include log data through "info thr" and "bt" on any future crash.

PoltoS wrote:
02 Jan 2020 22:40
Looks we have found the issue in concurrent threads in OpenSSL used in cURL used in Z-Way. We are checking it.
PoltoS wrote:
05 Jan 2020 04:41
Please try https://storage.z-wave.me/z-way-serverz ... _armhf.deb (works on stretch - not yet tested on buster)

This version has just updated dependencies on cURL, OpenSSL and LibWebsockets to use OpenSSL 1.1.0 - it is much more stable in multi threaded environment,
Very nice to hear that issues related to server crashing have been located! Will the found issue with OpenSSL only impact https connections or could it potentially affect connections using plain http as well?


Regards,

/Joakim
User avatar
PoltoS
Posts: 7565
Joined: 26 Jan 2011 19:36

Re: Z-way server goes down spontaneously

Post by PoltoS »

Plain http should not be affected. In fact, Z-Way code has not changed at all - we have just rebuilt it with the new cURL built against OpenSSL 1.1.0 as the current cURL in Raspbian still depends on the old 1.0.2 which is not very thread safe
User avatar
GokMasE
Posts: 59
Joined: 13 Mar 2016 01:04
Location: Sweden

Re: Z-way server goes down spontaneously

Post by GokMasE »

PoltoS wrote:
06 Jan 2020 03:20
Plain http should not be affected. In fact, Z-Way code has not changed at all - we have just rebuilt it with the new cURL built against OpenSSL 1.1.0 as the current cURL in Raspbian still depends on the old 1.0.2 which is not very thread safe
Ok, so I guess it should not affect the crashes I have been seeing then. I can install the updated package just in case though.
User avatar
PoltoS
Posts: 7565
Joined: 26 Jan 2011 19:36

Re: Z-way server goes down spontaneously

Post by PoltoS »

Hm, indeed, you used plain HTTP. But please try it and if it crashes, please report backtrace and threads info
User avatar
GokMasE
Posts: 59
Joined: 13 Mar 2016 01:04
Location: Sweden

Re: Z-way server goes down spontaneously

Post by GokMasE »

PoltoS wrote:
06 Jan 2020 22:53
Hm, indeed, you used plain HTTP. But please try it and if it crashes, please report backtrace and threads info
Certainly, I installed v3.0.3-13-g771b1d7 last night, and got this logged through PuTTY/gdb tonight:

Code: Select all

[New Thread 0x6c1f9450 (LWP 5451)]
[Thread 0x6c1f9450 (LWP 5451) exited]
[New Thread 0x6c1f9450 (LWP 5452)]
[Thread 0x6c1f9450 (LWP 5452) exited]
[New Thread 0x6c1f9450 (LWP 5453)]
[New Thread 0x6c9fa450 (LWP 5454)]
[Thread 0x6c1f9450 (LWP 5453) exited]
[Thread 0x6c9fa450 (LWP 5454) exited]
[New Thread 0x6c9fa450 (LWP 5455)]
[Thread 0x6c9fa450 (LWP 5455) exited]
[New Thread 0x6c9fa450 (LWP 5456)]
[Thread 0x6c9fa450 (LWP 5456) exited]
[New Thread 0x6c9fa450 (LWP 5457)]
[Thread 0x6c9fa450 (LWP 5457) exited]
[New Thread 0x6c9fa450 (LWP 5458)]
[New Thread 0x6c1f9450 (LWP 5459)]
[New Thread 0x705ff450 (LWP 5460)]
[New Thread 0x6fbfe450 (LWP 5461)]
[Thread 0x705ff450 (LWP 5460) exited]
[Thread 0x6fbfe450 (LWP 5461) exited]
[Thread 0x6c1f9450 (LWP 5459) exited]

Thread 7 "zway/core" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x73539450 (LWP 1821)]
0x76c03e5c in v8::internal::GlobalHandles::Create(v8::internal::Object*) ()
   from libs/libv8.so
(gdb)) Quit
(gdb) i thr
  Id   Target Id         Frame
  1    Thread 0x76ff6140 (LWP 1812) "z-way-server" 0x76350030 in nanosleep ()
    at ../sysdeps/unix/syscall-template.S:84
  2    Thread 0x73d6d450 (LWP 1816) "OptimizingCompi" 0x765f6068 in futex_abstim                    ed_wait_cancelable (private=0, abstime=0x0, expected=1, futex_word=0x59eac)
    at ../sysdeps/unix/sysv/linux/futex-internal.h:205
  3    Thread 0x7405b450 (LWP 1817) "v8:SweeperThrea" 0x765f6068 in futex_abstim                    ed_wait_cancelable (private=0, abstime=0x0, expected=1, futex_word=0x5a00c)
    at ../sysdeps/unix/sysv/linux/futex-internal.h:205
  4    Thread 0x7356c450 (LWP 1818) "v8:SweeperThrea" 0x765f6068 in futex_abstim                    ed_wait_cancelable (private=0, abstime=0x0, expected=1, futex_word=0x5a12c)
    at ../sysdeps/unix/sysv/linux/futex-internal.h:205
  5    Thread 0x7355b450 (LWP 1819) "v8:SweeperThrea" 0x765f6068 in futex_abstim                    ed_wait_cancelable (private=0, abstime=0x0, expected=1, futex_word=0x5a24c)
    at ../sysdeps/unix/sysv/linux/futex-internal.h:205
  6    Thread 0x7354a450 (LWP 1820) "v8:SweeperThrea" 0x765f6068 in futex_abstim                    ed_wait_cancelable (private=0, abstime=0x0, expected=1, futex_word=0x5a36c)
    at ../sysdeps/unix/sysv/linux/futex-internal.h:205
* 7    Thread 0x73539450 (LWP 1821) "zway/core" 0x76c03e5c in v8::internal::Glob                    alHandles::Create(v8::internal::Object*) () from libs/libv8.so
  8    Thread 0x727ff450 (LWP 1824) "zway/webserver" 0x7637e674 in select ()
    at ../sysdeps/unix/syscall-template.S:84
  9    Thread 0x71ffe450 (LWP 1825) "zway/timers" 0x76350030 in nanosleep ()
---Type <return> to continue, or q <return> to quit---
---Type <return> to continue, or q <return> to quit---Quit
(gdb) Quit
(gdb) bt
#0  0x76c03e5c in v8::internal::GlobalHandles::Create(v8::internal::Object*) () from libs/libv8.so
#1  0x76b50c1c in v8::V8::GlobalizeReference(v8::internal::Isolate*, v8::internal::Object**) ()
   from libs/libv8.so
#2  0x74109cb0 in zwjs::DHWrapper::Setup(v8::Isolate*, v8::Handle<v8::Object>) ()
   from ./modules/moddhs.so
#3  0x740feb38 in zwjs::DataHolder::New(zwjs::Environment*, zwjs::DHWrapper*) ()
   from ./modules/moddhs.so
#4  0x740fe180 in zwjs::DataHolder::New(zwjs::Environment*, _ZDataHolder*) ()
   from ./modules/moddhs.so
#5  0x741027cc in zwjs::DataHolder::NamedPropertyGetter(v8::Local<v8::String>, v8::PropertyCallbackInfo<v8::Value> const&) () from ./modules/moddhs.so
#6  0x76b70e78 in v8::internal::PropertyCallbackArguments::Call(void (*)(v8::Local<v8::String>, v8::PropertyCallbackInfo<v8::Value> const&), v8::Local<v8::String>) () from libs/libv8.so
#7  0x76de04c4 in v8::internal::LoadWithInterceptor(v8::internal::Arguments*, PropertyAttributes*)
    () from libs/libv8.so
#8  0x76de159c in v8::internal::LoadPropertyWithInterceptorForLoad(int, v8::internal::Object**, v8::internal::Isolate*) () from libs/libv8.so
#9  0x59e0a3a8 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb)



This was the end snippet of the data in z-way-server.log at the time of the crash:

Code: Select all

[2020-01-08 00:20:00.569] [I] [zway] Job 0x13 (Nonce Get): Delivered
[2020-01-08 00:20:00.569] [D] [zway] SendData Response with callback 0x46 received: received by recipient
[2020-01-08 00:20:00.569] [D] [zway] SETDATA devices.10.data.lastSendInternal = **********
[2020-01-08 00:20:00.569] [D] [zway] SETDATA devices.10.data.lastSend = 622048 (0x00097de0)
[2020-01-08 00:20:00.569] [D] [zway] Job 0x13 (Nonce Get): success
[2020-01-08 00:20:00.569] [D] [zway] SETDATA devices.10.instances.0.commandClasses.152.data.rNonceAckWait = **********
[2020-01-08 00:20:00.569] [D] [zway] SETDATA devices.10.data.lastNonceGet = 622048 (0x00097de0)
[2020-01-08 00:20:00.570] [I] [zway] Waiting for job reply: Nonce Get
[2020-01-08 00:20:00.570] [D] [zway] SENDING (cb 0x47): ( 01 18 00 13 0C 11 9F 03 E8 00 75 04 B8 49 F7 84 68 AA 51 A8 F5 B7 2A 25 47 5F )
[2020-01-08 00:20:00.570] [D] [zway] Secure payload: ( 71 04 00 09 00 )
[2020-01-08 00:20:00.579] [D] [zway] RECEIVED ACK
[2020-01-08 00:20:00.579] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2020-01-08 00:20:00.579] [D] [zway] SENT ACK
[2020-01-08 00:20:00.579] [I] [zway] Job 0x13 (Security S2 Encapsulation (S2 Unauthenticated), Alarm Get (v3)): Response received - transfered to encapsulated jobs
[2020-01-08 00:20:00.579] [D] [zway] Delivered to Z-Wave stack
[2020-01-08 00:20:00.579] [D] [zway] Delivered to Z-Wave stack
[2020-01-08 00:20:00.620] [D] [zway] RECEIVED: ( 01 14 00 04 00 06 0E 60 0D 01 00 32 02 21 34 00 00 00 09 00 00 A7 )
[2020-01-08 00:20:00.620] [D] [zway] SENT ACK
[2020-01-08 00:20:00.620] [D] [zway] SETDATA devices.6.data.lastReceived = 0 (0x00000000)
[2020-01-08 00:20:00.620] [D] [zway] SETDATA devices.6.instances.1.commandClasses.50.data.2.val = 0.900000
[2020-01-08 00:20:00.620] [D] [zway] SETDATA devices.6.instances.1.commandClasses.50.data.2.delta = 0 (0x00000000)
[2020-01-08 00:20:00.620] [D] [zway] SETDATA devices.6.instances.1.commandClasses.50.data.2.ratetype = 1 (0x00000001)
[2020-01-08 00:20:00.620] [D] [zway] SETDATA devices.6.instances.1.commandClasses.50.data.2 = Empty
[2020-01-08 00:20:00.661] [D] [zway] RECEIVED: ( 01 07 00 13 47 00 00 07 AB )
[2020-01-08 00:20:00.661] [D] [zway] SENT ACK
[2020-01-08 00:20:00.661] [I] [zway] Job 0x13 (Security S2 Encapsulation (S2 Unauthenticated), Alarm Get (v3)): Callback received - transfered to encapsulated jobs
[2020-01-08 00:20:00.661] [I] [zway] Job 0x13 (Alarm Get (v3)): Delivered
[2020-01-08 00:20:00.661] [D] [zway] SendData Response with callback 0x47 received: received by recipient
[2020-01-08 00:20:00.661] [D] [zway] Job 0x13 (Alarm Get (v3)): success
[2020-01-08 00:20:00.661] [I] [zway] Waiting for job reply: Alarm Get (v3)
[2020-01-08 00:20:00.661] [I] [zway] Job 0x13 (Security S2 Encapsulation (S2 Unauthenticated), Alarm Get (v3)): Delivered
[2020-01-08 00:20:00.661] [D] [zway] SendData Response with callback 0x47 received: received by recipient
[2020-01-08 00:20:00.661] [D] [zway] SETDATA devices.12.data.lastSendInternal = **********
[2020-01-08 00:20:00.661] [D] [zway] SETDATA devices.12.data.lastSend = 622057 (0x00097de9)
[2020-01-08 00:20:00.661] [D] [zway] Job 0x13 (Security S2 Encapsulation (S2 Unauthenticated), Alarm Get (v3)): success
[2020-01-08 00:20:00.661] [I] [zway] Removing job: Security S2 Encapsulation (S2 Unauthenticated), Alarm Get (v3)
[2020-01-08 00:20:00.762] [D] [zway] RECEIVED: ( 01 10 00 04 00 0A 0A 98 80 55 CD 1D FE E3 BF A1 91 E4 )
[2020-01-08 00:20:00.762] [D] [zway] SENT ACK
[2020-01-08 00:20:00.762] [D] [zway] SETDATA devices.10.data.lastReceived = 0 (0x00000000)
[2020-01-08 00:20:00.762] [D] [zway] Received reply on job (Nonce Get)
[2020-01-08 00:20:00.762] [D] [zway] SETDATA devices.10.instances.0.commandClasses.152.data.rNonceAckWait = **********
[2020-01-08 00:20:00.762] [D] [zway] SETDATA devices.10.data.lastNonceGet = 622067 (0x00097df3)
[2020-01-08 00:20:00.762] [I] [zway] Node 10:0 CC Security: received Nonce Report
[2020-01-08 00:20:00.762] [D] [zway] SETDATA devices.10.instances.0.commandClasses.152.data.rNonce = **********
[2020-01-08 00:20:00.762] [I] [zway] Node 10:0 CC Security: Sending a secure message
[2020-01-08 00:20:00.762] [I] [zway] Node 10:0 CC Security: sending encrypted packet: SensorMultilevel V5 Get
[2020-01-08 00:20:00.762] [D] [zway] SETDATA devices.10.instances.0.commandClasses.152.data.toFollow = False
[2020-01-08 00:20:00.762] [D] [zway] SETDATA devices.10.data.lastNonceGet = Empty
[2020-01-08 00:20:00.762] [I] [zway] Adding job: Security, SensorMultilevel V5 Get
[2020-01-08 00:20:00.763] [D] [zway] SENDING (cb 0x48): ( 01 1F 00 13 0A 18 98 81 9A 84 28 09 38 3F 9A 15 FB EA 32 54 4C 55 8C 0B 1D 5B 89 D5 59 86 25 48 0E )
[2020-01-08 00:20:00.763] [D] [zway] Secure payload: ( 31 04 01 00 )
[2020-01-08 00:20:00.772] [D] [zway] RECEIVED ACK
[2020-01-08 00:20:00.772] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2020-01-08 00:20:00.772] [D] [zway] SENT ACK
[2020-01-08 00:20:00.772] [I] [zway] Job 0x13 (Security, SensorMultilevel V5 Get): Response received - transfered to encapsulated jobs
[2020-01-08 00:20:00.772] [D] [zway] Delivered to Z-Wave stack
[2020-01-08 00:20:00.772] [D] [zway] Delivered to Z-Wave stack
[2020-01-08 00:20:00.783] [D] [zway] RECEIVED: ( 01 1B 00 04 00 0C 15 9F 03 4A 00 EE 91 A4 E1 E7 FF 36 70 5C 4B 2A 87 9D 27 3A 51 4E 6E )
[2020-01-08 00:20:00.783] [D] [zway] SENT ACK
[2020-01-08 00:20:00.783] [D] [zway] SETDATA devices.12.data.lastReceived = 0 (0x00000000)
[2020-01-08 00:20:00.783] [I] [zway] Node 12:0 CC SecurityS2: passing S2 Unauthenticated decrypted packet to application level: [ 71 05 00 00 00 ff 09 00 00 ]
[2020-01-08 00:20:00.783] [D] [zway] Received reply on job (Alarm Get (v3))
[2020-01-08 00:20:00.783] [D] [zway] SETDATA devices.12.instances.0.commandClasses.113.data.9.eventParameters = byte[0]
[2020-01-08 00:20:00.783] [D] [zway]   ( zero-length buffer )
[2020-01-08 00:20:00.783] [D] [zway] SETDATA devices.12.instances.0.commandClasses.113.data.9.event = 0 (0x00000000)
[2020-01-08 00:20:00.784] [D] [zway] SETDATA devices.12.instances.0.commandClasses.113.data.9.eventString = ""
[2020-01-08 00:20:00.784] [D] [zway] SETDATA devices.12.instances.0.commandClasses.113.data.9.status = 255 (0x000000ff)
[2020-01-08 00:20:00.784] [D] [zway] SETDATA devices.12.instances.0.commandClasses.113.data.9 = Empty
[2020-01-08 00:20:00.824] [D] [zway] RECEIVED: ( 01 07 00 13 48 00 00 05 A6 )
[2020-01-08 00:20:00.824] [D] [zway] SENT ACK
[2020-01-08 00:20:00.824] [I] [zway] Job 0x13 (Security, SensorMultilevel V5 Get): Callback received - transfered to encapsulated jobs
[2020-01-08 00:20:00.824] [I] [zway] Job 0x13 (SensorMultilevel V5 Get): Delivered
[2020-01-08 00:20:00.824] [D] [zway] SendData Response with callback 0x48 received: received by recipient
[2020-01-08 00:20:00.824] [D] [zway] Job 0x13 (SensorMultilevel V5 Get): success
[2020-01-08 00:20:00.824] [I] [zway] Waiting for job reply: SensorMultilevel V5 Get
[2020-01-08 00:20:00.824] [I] [zway] Job 0x13 (Security, SensorMultilevel V5 Get): Delivered
[2020-01-08 00:20:00.824] [D] [zway] SendData Response with callback 0x48 received: received by recipient
[2020-01-08 00:20:00.824] [D] [zway] SETDATA devices.10.data.lastSendInternal = **********
[2020-01-08 00:20:00.824] [D] [zway] SETDATA devices.10.data.lastSend = 622073 (0x00097df9)
[2020-01-08 00:20:00.825] [D] [zway] Job 0x13 (Security, SensorMultilevel V5 Get): success
[2020-01-08 00:20:00.825] [I] [zway] Removing job: Security, SensorMultilevel V5 Get
[2020-01-08 00:20:00.844] [D] [zway] RECEIVED: ( 01 08 00 04 00 0A 02 98 40 23 )
[2020-01-08 00:20:00.844] [D] [zway] SENT ACK
[2020-01-08 00:20:00.844] [D] [zway] SETDATA devices.10.data.lastReceived = 0 (0x00000000)
[2020-01-08 00:20:00.844] [I] [zway] Node 10:0 CC Security: sending Nonce Report
[2020-01-08 00:20:00.844] [W] [zway] Can not detect if this is a request or set/report - don't expect a reply
[2020-01-08 00:20:00.844] [I] [zway] Adding job: Nonce Report
[2020-01-08 00:20:00.865] [D] [zway] SENDING (cb 0x49): ( 01 11 00 13 0A 0A 98 80 69 B0 E0 7C 2B 3D 9A C3 25 49 83 )
[2020-01-08 00:20:00.867] [D] [zway] RECEIVED ACK
[2020-01-08 00:20:00.871] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2020-01-08 00:20:00.871] [D] [zway] SENT ACK
[2020-01-08 00:20:00.871] [D] [zway] Delivered to Z-Wave stack
[2020-01-08 00:20:00.895] [D] [zway] RECEIVED: ( 01 07 00 13 49 00 00 02 A0 )
[2020-01-08 00:20:00.895] [D] [zway] SENT ACK
[2020-01-08 00:20:00.895] [I] [zway] Job 0x13 (Nonce Report): Delivered
[2020-01-08 00:20:00.895] [D] [zway] SendData Response with callback 0x49 received: received by recipient
[2020-01-08 00:20:00.895] [D] [zway] SETDATA devices.10.data.lastSendInternal = **********
[2020-01-08 00:20:00.895] [D] [zway] SETDATA devices.10.data.lastSend = 622080 (0x00097e00)
[2020-01-08 00:20:00.895] [D] [zway] Job 0x13 (Nonce Report): success
[2020-01-08 00:20:00.895] [I] [zway] Removing job: Nonce Report
[2020-01-08 00:20:00.926] [D] [zway] RECEIVED: ( 01 20 00 04 00 0A 1A 98 81 6C 2D 7E CE 1B 58 83 11 5E 7E 8F 78 09 17 5D 69 AD CF 59 7C E9 A4 00 A5 A0 )
[2020-01-08 00:20:00.926] [D] [zway] SENT ACK
[2020-01-08 00:20:00.926] [D] [zway] SETDATA devices.10.data.lastReceived = 0 (0x00000000)
[2020-01-08 00:20:00.926] [I] [zway] Node 10:0 CC Security: Received a secure message
[2020-01-08 00:20:00.926] [D] [zway] SETDATA devices.10.instances.0.commandClasses.152.data.firstPart = **********
[2020-01-08 00:20:00.926] [I] [zway] Node 10:0 CC Security: passing decrypted packet to application level: [ 31 05 01 22 01 3d ]
[2020-01-08 00:20:00.926] [D] [zway] Received reply on job (SensorMultilevel V5 Get)
[2020-01-08 00:20:00.926] [D] [zway] SETDATA devices.10.instances.0.commandClasses.49.data.1.deviceScale = 0 (0x00000000)
[2020-01-08 00:20:00.927] [D] [zway] SETDATA devices.10.instances.0.commandClasses.49.data.1.scaleString = "°C"
[2020-01-08 00:20:00.927] [D] [zway] SETDATA devices.10.instances.0.commandClasses.49.data.1.val = 31.700001
[2020-01-08 00:20:00.927] [D] [zway] SETDATA devices.10.instances.0.commandClasses.49.data.1 = Empty
[2020-01-08 00:20:02.410] [I] [core] http://192.168.1.3:1025/ZWave?Cmd=CBck&Dev=%DEVICE%&Lev=%VALUE% : ZWayVDev_zway_11-2-48-1 : on : http://192.168.1.3:1025/ZWave?Cmd=CBck&Dev=ZWayVDev_zway_11-2-48-1&Lev=on
[2020-01-08 00:20:02.439] [I] [core] http://192.168.1.3:1025/ZWave?Cmd=CBck&Dev=%DEVICE%&Lev=%VALUE% : ZWayVDev_zway_6-0-50-0 : 1 : http://192.168.1.3:1025/ZWave?Cmd=CBck&Dev=ZWayVDev_zway_6-0-50-0&Lev=1
[2020-01-08 00:20:02.473] [I] [core] http://192.168.1.3:1025/ZWave?Cmd=CBck&Dev=%DEVICE%&Lev=%VALUE% : ZWayVDev_zway_6-1-50-2 : 0.9 : http://192.168.1.3:1025/ZWave?Cmd=CBck&Dev=ZWayVDev_zway_6-1-50-2&Lev=0.9
[2020-01-08 00:20:02.517] [I] [core] http://192.168.1.3:1025/ZWave?Cmd=CBck&Dev=%DEVICE%&Lev=%VALUE% : ZWayVDev_zway_12-0-113-9-7-A : off : http://192.168.1.3:1025/ZWave?Cmd=CBck&Dev=ZWayVDev_zway_12-0-113-9-7-A&Lev=off
[2020-01-08 00:20:02.540] [D] [zway] Job 0x13: deleted from queue
[2020-01-08 00:20:02.550] [D] [zway] RECEIVED: ( 01 10 00 04 00 06 0A 32 02 21 34 00 00 00 0D 00 00 CF )
[2020-01-08 00:20:02.551] [D] [zway] SENT ACK

Hopefully these logs can offer some additional clues as to what is going wrong.

Thanks in advance.


Regards,

/Joakim
Post Reply