Aeotec z-stick troubles

I have the Aeotec DSA02203-ZWUS Z-Wave Z-Stick Series 2 USB Dongle that I am using with openHAB on Windows 8.1. The driver installed initially and I used the update tool to install the Silicon Laboratories 6.7.0.0 version driver.

When I am running OpenHAB, it usually connects to the Z-Stick well on the first try. However, sometimes I restart the OpenHAB service and the Z-Stick is unavailable. I get these lines in the zwave log of OpenHAB:

101442 2015-09-03 20:18:23.071 [INFO ] [b.z.i.protocol.ZWaveController:320 ]- Connecting to serial port COM4
101443 2015-09-03 20:18:23.072 [ERROR] [b.z.i.protocol.ZWaveController:342 ]- Serial Error: Port COM4 does not exist

I have tried troubleshooting this, but can not consistently get it to have the error or work regularly. Even unplugging the Z-Stick and plugging it back in does not always put the device in an accessible state. It seems very sporadic. Sometimes restarting the OpenHAB service multiple times will cause it to be available again, but this does not happen consistently . Is there anything I can do to get the Z-Stick to work better? Is it possible that the first instance of openHAB which ends when I restart the process is somehow still holding on to the com port?

If the error is that COM4 doesn’t exist, then it would seem that it’s probably not an issue with the zstick, but maybe a problem with the COM port or computer (or drivers or something)? There are problems with these sticks, but the COM port should always be able to be opened unless there’s something strange going on in the lower levels (ie outside of the binding).

Any idea how to track that down further? It’s strange to me that it works the first time, but then is often not available on the restart of openhab. It feels to me like a process is still holding onto a handle or something, but I’m not sure how to confirm that.

While I would agree with your thinking, normally I would have expected to see a “port in use” error if something else was using the port (the binding distinguishes between ‘in use’ and ‘doesn’t exist’).

You could try running a terminal program to use the port before starting OH the first time, and see what error you get when you start OH. If it gives you a ‘port in use’ error, then that tells you something (although it doesn’t help solve the ultimate problem, but more information is always useful).

Another possibility is that the physical connection via the USB port is flaky. Have you tried a different USB port on your computer ?

There’s a reason that really quality equipment uses non-oxidizing materials for contacts (gold-plated being the high bar here). Depending on the age of your computer and environment (ocean-view==BAD), you may have intermittent electrical contact at the stick-USBport interface which can yield this kind of baffling behavior.

I had my stick on a USB extender from a Pi 2 just because it gets a little crowded on the back of a Pi 2 when you’ve got larger items plugged in. Got bitten by bad/cheap contacts on the extender.

Thanks for the suggestions. I’ve tried them and I’m still having issues.

Aeotec tech support suggested I download the newest driver direct from https://www.silabs.com/products/mcu/Pages/USBtoUARTBridgeVCPDrivers.aspx. It seemed to be the same driver I had already installed, but I downloaded it and installed it. I saw the same behavior as before.

I opened up COM4 with putty. When I started the session, it was a blank terminal screen. I typed random letters in but I did not see any change. I also have an Insteon PLM device which is very similar to the z-stick in that it does a serial port via usb. This was on COM3. I opened it in the same way using putty. When I typed letters into this terminal I saw little block characters get filled in where the cursor had been. This wasn’t much to go on, but it seems that the two devices respond differently so that may be a clue.

I tried switching the physical USB ports that the z-stick and the Insteon PLM were plugged into. The PLM has been working consistently, so I know that physical USB port works. I saw the same results as before. The PLM works perfectly, the z-stick is unavailable after restarting openHAB.

Finally, I tried switching COM ports for the z-stick within the driver settings in the Device Manager. I changed to COM5 and updated my openhab.cfg to point to COM5. I saw the same results, a “COM5 does not exist” error when trying to use the zwave module in openHAB.

Any thoughts on where to go from here?

If you restart the computer, open COM4 with putty, then start openHAB, what error do you see? Is it “COM port doesn’t exist” or “COM port is in use”?

If I understood your original message correctly, it always works first time? If so, the above test might at least help indicate if the port is somehow being left open when OH closes?

Another question - what JVM are you using?

I’m using the Oracle Java JVM, 64 bit, version 8.0.310

Yes, from what I remember, it always works on the first time.

I’ll reboot right now and try your suggestion of opening the COM port before starting openHAB.

Ok, I rebooted, and opened COM4 with putty before starting openHAB. I still did not see any response to my key presses in the terminal when putty was connected to COM4, so I don’t know if putty successfully worked to connect to COM4 or not.

When I started openHAB, I got the following lines in my zwave.log file:

84523 2015-09-06 15:10:51.527 [DEBUG] [.zwave.internal.ZWaveActivator:36  ]- Z-Wave binding started. Version 1.8.0.201508211938
84524 2015-09-06 15:10:51.551 [DEBUG] [.z.internal.ZWaveActiveBinding:175 ]- ConverterHandler not initialised. Polling disabled.
84525 2015-09-06 15:10:52.254 [INFO ] [.z.internal.ZWaveActiveBinding:325 ]- Update config, port = COM4
84526 2015-09-06 15:10:52.254 [INFO ] [.z.internal.ZWaveActiveBinding:384 ]- Update config, softReset = false
84527 2015-09-06 15:10:52.254 [INFO ] [.z.internal.ZWaveActiveBinding:393 ]- Update config, masterController = true
84528 2015-09-06 15:10:52.254 [DEBUG] [.z.internal.ZWaveActiveBinding:282 ]- Initialising zwave binding
84529 2015-09-06 15:10:52.264 [INFO ] [b.z.i.protocol.ZWaveController:146 ]- Starting Z-Wave controller
84530 2015-09-06 15:10:52.264 [INFO ] [b.z.i.protocol.ZWaveController:154 ]- Z-Wave timeout is set to 5000ms. Soft reset is false.
84531 2015-09-06 15:10:52.265 [INFO ] [b.z.i.protocol.ZWaveController:320 ]- Connecting to serial port COM4
84532 2015-09-06 15:10:52.265 [ERROR] [b.z.i.protocol.ZWaveController:342 ]- Serial Error: Port COM4 does not exist

These lines appear identical to the error I got when restarting the already running openHAB service in my original post.

I’m going to restart again and start openHAB immediately after reboot to see if it works on the first attempt without opening the port in putty.

UPDATE: I rebooted again and started openHAB immediately. The zwave binding started correctly. Here are the results of that zwave.log file.

84526 2015-09-06 15:18:53.369 [DEBUG] [.zwave.internal.ZWaveActivator:36  ]- Z-Wave binding started. Version 1.8.0.201508211938
84527 2015-09-06 15:18:53.387 [DEBUG] [.z.internal.ZWaveActiveBinding:175 ]- ConverterHandler not initialised. Polling disabled.
84528 2015-09-06 15:18:53.388 [INFO ] [.z.internal.ZWaveActiveBinding:325 ]- Update config, port = COM4
84529 2015-09-06 15:18:53.388 [INFO ] [.z.internal.ZWaveActiveBinding:384 ]- Update config, softReset = false
84530 2015-09-06 15:18:53.388 [INFO ] [.z.internal.ZWaveActiveBinding:393 ]- Update config, masterController = true
84531 2015-09-06 15:18:53.388 [DEBUG] [.z.internal.ZWaveActiveBinding:282 ]- Initialising zwave binding
84532 2015-09-06 15:18:53.406 [INFO ] [b.z.i.protocol.ZWaveController:146 ]- Starting Z-Wave controller
84533 2015-09-06 15:18:53.407 [INFO ] [b.z.i.protocol.ZWaveController:154 ]- Z-Wave timeout is set to 5000ms. Soft reset is false.
84534 2015-09-06 15:18:53.407 [INFO ] [b.z.i.protocol.ZWaveController:320 ]- Connecting to serial port COM4
84535 2015-09-06 15:18:53.904 [DEBUG] [eController$ZWaveReceiveThread:1373]- Starting Z-Wave thread: Receive
84536 2015-09-06 15:18:53.905 [DEBUG] [WaveController$ZWaveSendThread:1157]- Starting Z-Wave thread: Send
84537 2015-09-06 15:18:53.905 [INFO ] [b.z.i.protocol.ZWaveController:340 ]- Serial port is initialized
84538 2015-09-06 15:18:53.905 [DEBUG] [b.z.i.protocol.ZWaveController:1114]- Starting Z-Wave thread: Input
84539 2015-09-06 15:18:56.906 [DEBUG] [veController$WatchDogTimerTask:176 ]- Initialising network
84540 2015-09-06 15:18:56.908 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = GetVersion (0x15), type = Request (0x00)
84541 2015-09-06 15:18:56.909 [DEBUG] [b.z.i.protocol.ZWaveController:580 ]- Enqueueing message. Queue length = 1
84542 2015-09-06 15:18:56.909 [DEBUG] [WaveController$ZWaveSendThread:1171]- Took message from queue for sending. Queue length = 0
84543 2015-09-06 15:18:56.909 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = MemoryGetId (0x20), type = Request (0x00)
84544 2015-09-06 15:18:56.909 [DEBUG] [b.z.i.protocol.ZWaveController:580 ]- Enqueueing message. Queue length = 1
84545 2015-09-06 15:18:56.909 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 15 E9
84546 2015-09-06 15:18:56.910 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = SerialApiGetCapabilities (0x07), type = Request (0x00)
84547 2015-09-06 15:18:56.910 [DEBUG] [WaveController$ZWaveSendThread:1228]- NODE 255: Sending REQUEST Message = 01 03 00 15 E9
84548 2015-09-06 15:18:56.910 [DEBUG] [b.z.i.protocol.ZWaveController:580 ]- Enqueueing message. Queue length = 2
84549 2015-09-06 15:18:56.911 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = SerialApiSetTimeouts (0x06), type = Request (0x00)
84550 2015-09-06 15:18:56.911 [DEBUG] [b.z.i.protocol.ZWaveController:580 ]- Enqueueing message. Queue length = 3
84551 2015-09-06 15:18:56.912 [DEBUG] [i.p.s.GetSucNodeIdMessageClass:30  ]- Get SUC NodeID
84552 2015-09-06 15:18:56.912 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = GetSucNodeId (0x56), type = Request (0x00)
84553 2015-09-06 15:18:56.912 [DEBUG] [b.z.i.protocol.ZWaveController:580 ]- Enqueueing message. Queue length = 4
84554 2015-09-06 15:18:56.914 [DEBUG] [eController$ZWaveReceiveThread:1441]- Receive Message = 01 10 01 15 5A 2D 57 61 76 65 20 32 2E 37 38 00 01 9B
84555 2015-09-06 15:18:56.915 [DEBUG] [eController$ZWaveReceiveThread:1365]- Receive queue ADD: Length=1
84556 2015-09-06 15:18:56.915 [DEBUG] [b.z.i.protocol.ZWaveController:1123]- Receive queue TAKE: Length=0

I wouldn’t read too much into this - different devices will do different things. I have no idea what the plex does, but zwave sticks don’t echo data back - they might send CAN bytes, but these might not be printable at all…

Interesting - so maybe something is staying alive… After you close OH, can you run up task manager and see if there’s still a JVM machine running and try and kill it if it is?

Otherwise, I’m afraid I don’t know what’s up - I’ve not seen this before. (sorry).

Haha, yeah. I tend to find the problems that nobody else has run into before so it’s impossible to google…

So I’ve tried restarting the service or stopping and starting the service with a pause in between numerous times just now. Most of the times when I do “restart”, the “Serial Error: Port COM4 does not exist” error happens. If I stop it, wait for a minute, and then start it, it usually does not get the error. However, neither of these is 100%. Sometimes the opposite response will happen in both cases.

As I watched the running processes, there is one instance of java.exe and nssm.exe (The service manager I use to run the openHAB service). When I stop openHAB service, both of those processes stop immediately. When I start it, they both start immediately. This is exactly as I would expect.

When I restart the service, the process ID’s of both java.exe and nssm.exe change, indicating to me that they both ended and a new instance of both processes has begun. I would think that this would cause both applications to release and file/COM handles they are holding onto, but I don’t know that for certain.

While experimenting, I stumbled upon a workaround (I guess you could call it that). If I kill the java process while the openhab is running through nssm and showing the z-stick COM4 error, nssm automatically restarts the openHAB service. Most of the time, the restarted process can access COM4 and the zwave binding works. Sometimes it doesn’t, so it’s not a consistent fix. Not exactly sure where to go from here, but making a little progress I think…

Thanks for all your help!

Process Explorer https://technet.microsoft.com/en-au/sysinternals/bb896653.aspx

It will show you what process is holding any open handle to files, folders and com ports.

It might be helpful…

@jonathan1 what are the settings on the port speed? Have tou disabled soft reset for this controller? Is this a master controller in OH?

The port settings are the defaults from when the driver was installed:
Speed: 9600
Data Bits: 8
Parity: None
Stop Bits: 1
Flow Control: None

Is there a proper setting? I left it at the defaults as I assumed that would be correct and I never saw instructions anywhere to change them.

Soft Reset has been disabled this entire time. I have the z-stick S2. I saw that the z-stick Gen 5 doesn’t work with soft reset. I think these are different devices, but I have it disabled anyways.

@peter, I tried using that as one of my first steps, I didn’t find anything unusual. I couldn’t see any files or ports that were held open by openHAB after stopping it.

I had no issues with this controller on windows 8.1. Now I am using it on windows 10. I have the speed set to 38400 bps with the rest at their defaults.
The driver version is 0.0.4.0 dated 6/10/2013 (Sigma Designs). If all else fails try a different controller/ PC.

I’m not sure what you mean when you talk about changing the speed - this can not be changed! It is set when the port opens and is fixed.

Soft reset works fine with the S2 - it’s just the Gen 5 versions that don’t like the reset.

Chris

There is a dropdown in the device details window in device manager. It allows me to change the speed setting. Not sure if it does anything, but I can change it in this window!

Setting the speed (etc) here won’t do anything. The port configuration is always set by the binding when the binding opens the port.

Good to know.

I’m not sure what else to do at this point. I might have to try and get the debugger up and running and see if I can step through and determine what is happening…

hey @jonnydev13, did you manage to get it working?

I’m using openhab 1.7 and it works “perfect” but wanted to move to openhab 2.
So I downloaded it :slight_smile:
However, habmin always complains “Serial Error: Port 3 does not exist”.
This works fine in 1.7 with binding 1.9.
Both computer and openhab restarted several times.

When using openhab, I installed both habmin and bindning via paperUI.

Any ideas @chris and have you seen it more now than back last year?