OH 2.5.0 - zwave error "Request node info not placed on stack due to error."

Add-ons Bindings
1

Hi all,

sometimes some of my zwave devices take a long time to react, or miss a command. I had a look in the log and found error “Request node info not placed on stack due to error.” This happens quite frequently. I wonder if this is related to my problem and how to troubleshot this. As a start below the loglines in question (I use OH 2.5.0 on Windows 10):

2020-02-08 15:39:02.774 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Feb 08 15:39:04 CET 2020 - 1995ms
2020-02-08 15:39:02.774 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=00 
2020-02-08 15:39:02.775 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=00 
2020-02-08 15:39:02.775 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 183: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2020-02-08 15:39:02.776 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2020-02-08 15:39:02.777 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 183: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2020-02-08 15:39:02.777 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=00 
2020-02-08 15:39:02.778 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE
2020-02-08 15:39:02.778 [TRACE] [lmessage.RequestNodeInfoMessageClass] - Handle RequestNodeInfo Response
2020-02-08 15:39:02.780 [ERROR] [lmessage.RequestNodeInfoMessageClass] - Request node info not placed on stack due to error.
2020-02-08 15:39:02.780 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 183: Transaction CANCELLED
2020-02-08 15:39:02.781 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 183: TransactionAdvance ST: CANCELLED
2020-02-08 15:39:02.781 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 183: TransactionAdvance WT: ApplicationUpdate {}
2020-02-08 15:39:02.782 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 183: TransactionAdvance RX: Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=00 
2020-02-08 15:39:02.782 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 183: TransactionAdvance TO: CANCELLED
2020-02-08 15:39:02.783 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer started...
2020-02-08 15:39:02.783 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2020-02-08 15:39:02.784 [TRACE] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer finishing in 250ms
2020-02-08 15:39:02.784 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent

Any help is much appreciated :slight_smile:

with kind regards,
Patrik

2

Any updates here? I see same exact same behavior and entries in my logs. Did not exist in 2.4 Release, explicitly started after 2.5 release.

3

This message was only posted 25 minutes ago - please try and be a little patient.

This issue has not changed from 2.4 or 2.5 - the binding has always done this stage as part of the startup. It’s hard to know what is happening without a debug log, but this possibly means that the stick is busy for some reason.

1 Like
4

Hi @chris,

is it worth to troubleshot at all or is it part of the normal operation of the binding? If it is worth to troubleshot, is DEBUG log enough, or do we need TRACE?

thanks and with kind regards,
Patrik

5

If it does not cause a problem, then I would not worry. The message should be retried anyway and probably this should not be logged as ERROR anyway.

DEBUG is normally fine 99.9% of the time. Thanks.

6

My bad…mixed up the timestamps with other issues I had been reading about…had several issues I was looking into.

7

Hi @chris,

thank you for your replay. Sometimes I have a delay of ~20 seconds until a command is executed. It even happens that a command is not executed at all.

At the moment I only have a log with TRACE:
zwave.zip.log (513.0 KB); hope it will do as well.

with kind reagrds,
Patrik

8

The documentation and developer specifically ask for DEBUG logs.

9

I’ll change the loglevel and collect them again.

1 Like
10

This is the DEBUG log:
zwave.zip.log (680.2 KB)

thank you for your help :slight_smile:

11

Hi Patrik,

Did you resolve your problem?