Failed to perform handshake

[woudt]

Handshake now succeeds, but I still cannot connect, even though in the past I have been able to connect at some time.

Debugging output:


Opening device...
[D] Configuring device...
[W] Failed to alter device settings: 22
[D] Creating a socket...
[D] Enabling keep-alives on the socket...
Connecting to server...
[D] Initialising OpenSSL environment...
[D] Allocating SSL context...
[D] Loading personal certificate...
[D] Loading personal certificate key...
[D] Loading CA certificate...
[D] Setting verification mode...
Establishing SSL connection...
[D] Allocating SSL session...
[D] Assigning socket...
Performing SSL handshake...
[D] Initialising SSL state...
[D] Sending handshake...
[D] Server has closed the SSL connection
[D] Shutting down SSL session...
[D] Freeing SSL session...
Establishing SSL connection...
[D] Allocating SSL session...
[D] Assigning socket...
Performing SSL handshake...
[D] Initialising SSL state...
[D] Sending handshake...
Loop started
[D] socket has data
[D] 5 bytes:
[D] 01 03 00 07 FB
[D] socket has data
[D] 5 bytes:
[D] 01 03 00 07 FB
[D] socket has data
[D] 5 bytes:
[D] 01 03 00 07 FB
[D] Server has closed the connection
[E] Socket has gone
Loop ended
[D] Shutting down SSL session...
[D] Freeing SSL session...
[D] Freeing SSL context...

[PoltoS]

Your log clearly says that the stick does not respond. This is usually due to wrong COM port selected.

The server side halts after three attempts to talk with the stick.

[woudt]

I don't think that is the problem:
- I did not change the script from earlier when it did work
- sometimes there is activity in the debug log
- using the same port/device, the test program from open-zwave works fine

My stick is an Aeon Labs Z-Stick series 2 connected to a Mac running OS X Lion.

Script used for Z-Connector:

#!/bin/bash

while [ 1 ]
do
${0%/*}/z-agent --debug -s z-cloud.z-wave.me --cacert ../Certificates/cacert.pem --cert ../Certificates/cert.pem --key ../Certificates/cert.key -d /dev/cu.SLAB_USBtoUART
# substitute /dev/ttyUSB0 by /dev/ttyACM0 or another device depending on the hardware you have

sleep 1 # spare the CPU
done


Command line open-zwave:

MinOZW $ ./test /dev/cu.SLAB_USBtoUART
2012-03-01 02:22:20:037 Added driver for controller /dev/cu.SLAB_USBtoUART
2012-03-01 02:22:20:062 Opening controller /dev/cu.SLAB_USBtoUART
2012-03-01 02:22:20:066 Trying to open serial port /dev/cu.SLAB_USBtoUART (attempt 1)
2012-03-01 02:22:20:128 Serial port /dev/cu.SLAB_USBtoUART opened (attempt 1)
2012-03-01 02:22:20:178 Queuing command: FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2012-03-01 02:22:20:284 Queuing command: FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2012-03-01 02:22:20:341 Queuing command: FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2012-03-01 02:22:20:345 Queuing command: FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb

2012-03-01 02:22:20:362 Sending command (Callback ID=0x00, Expected Reply=0x15) - FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2012-03-01 02:22:20:371 ACK received CallbackId 0x00 Reply 0x15
2012-03-01 02:22:20:371 Received: 0x01, 0x10, 0x01, 0x15, 0x5a, 0x2d, 0x57, 0x61, 0x76, 0x65, 0x20, 0x32, 0x2e, 0x37, 0x38, 0x00, 0x01, 0x9b

2012-03-01 02:22:20:406 Received reply to FUNC_ID_ZW_GET_VERSION:
2012-03-01 02:22:20:410 Static Controller library, version Z-Wave 2.78
2012-03-01 02:22:20:415 Expected reply was received
2012-03-01 02:22:20:430 Message transaction complete


2012-03-01 02:22:20:465 Sending command (Callback ID=0x00, Expected Reply=0x20) - FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2012-03-01 02:22:20:468 ACK received CallbackId 0x00 Reply 0x20
2012-03-01 02:22:20:533 Received: 0x01, 0x08, 0x01, 0x20, 0x01, 0x4d, 0x05, 0x4c, 0x01, 0xd2

2012-03-01 02:22:20:560 Received reply to FUNC_ID_ZW_MEMORY_GET_ID. Home ID = 0x014d054c. Our node ID = 1
2012-03-01 02:22:20:564 Expected reply was received
2012-03-01 02:22:20:578 Message transaction complete


2012-03-01 02:22:20:581 Sending command (Callback ID=0x00, Expected Reply=0x05) - FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2012-03-01 02:22:20:583 ACK received CallbackId 0x00 Reply 0x05
2012-03-01 02:22:20:584 Received: 0x01, 0x04, 0x01, 0x05, 0x1c, 0xe3

2012-03-01 02:22:20:584 Received reply to FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES:
2012-03-01 02:22:20:584 There is a SUC ID Server (SIS) in this network.
2012-03-01 02:22:20:585 The PC controller is an inclusion static update controller (SUC) and was the original primary before the SIS was added.
2012-03-01 02:22:20:587 Expected reply was received
2012-03-01 02:22:20:598 Message transaction complete


2012-03-01 02:22:20:600 Sending command (Callback ID=0x00, Expected Reply=0x07) - FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2012-03-01 02:22:20:606 ACK received CallbackId 0x00 Reply 0x07
2012-03-01 02:22:20:606 Received: 0x01, 0x2b, 0x01, 0x07, 0x03, 0x07, 0x00, 0x86, 0x00, 0x02, 0x00, 0x01, 0xfe, 0x80, 0xfe, 0x88, 0x0f, 0x00, 0x00, 0x00, 0xfb, 0x97, 0x7f, 0x82, 0x07, 0x00, 0x00, 0x80, 0x00, 0x80, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0xc2

2012-03-01 02:22:20:681 Received reply to FUNC_ID_SERIAL_API_GET_CAPABILITIES
2012-03-01 02:22:20:682 Application Version: 3
2012-03-01 02:22:20:682 Application Revision: 7
2012-03-01 02:22:20:683 Manufacturer ID: 0x0086
2012-03-01 02:22:20:683 Product Type: 0x0002
2012-03-01 02:22:20:684 Product ID: 0x0001
2012-03-01 02:22:20:684 Queuing command: FUNC_ID_SERIAL_API_GET_INIT_DATA: 0x01, 0x03, 0x00, 0x02, 0xfe
2012-03-01 02:22:20:684 Expected reply was received
2012-03-01 02:22:20:685 Message transaction complete

etc...


Debug log from Z-Connector with data received:

Opening device...
[D] Configuring device...
[W] Failed to alter device settings: 22
[D] Creating a socket...
[D] Enabling keep-alives on the socket...
Connecting to server...
[D] Initialising OpenSSL environment...
[D] Allocating SSL context...
[D] Loading personal certificate...
[D] Loading personal certificate key...
[D] Loading CA certificate...
[D] Setting verification mode...
Establishing SSL connection...
[D] Allocating SSL session...
[D] Assigning socket...
Performing SSL handshake...
[D] Initialising SSL state...
[D] Sending handshake...
[D] Server has closed the SSL connection
[D] Shutting down SSL session...
[D] Freeing SSL session...
Establishing SSL connection...
[D] Allocating SSL session...
[D] Assigning socket...
Performing SSL handshake...
[D] Initialising SSL state...
[D] Sending handshake...
Loop started
[D] device has data
[D] 39 bytes:
[D] 12 83 D1 12 83 D1 92 83 D1 3E 16 06 FC 92 83 D1
[D] 92 83 D1 92 83 D1 12 43 22 FF 92 83 D1 92 83 51
[D] 92 83 D1 3E 96 06 FE
[D] device has data
[D] 4 bytes:
[D] 12 0A 02 FF
[D] socket has data
[D] 5 bytes:
[D] 01 03 00 07 FB
[D] device has data
[D] 3 bytes:
[D] 92 83 D1
[D] device has data
[D] 3 bytes:
[D] 92 83 D1
[D] socket has data
[D] 5 bytes:
[D] 01 03 00 07 FB
[D] device has data
[D] 4 bytes:
[D] 3E D6 06 FC
[D] device has data
[D] 3 bytes:
[D] 92 83 D1
[D] device has data
[D] 3 bytes:
[D] 92 83 51
[D] device has data
[D] 3 bytes:
[D] 92 83 D1
[D] device has data
[D] 4 bytes:
[D] 12 43 22 FF
[D] device has data
[D] 3 bytes:
[D] 92 83 91
[D] device has data
[D] 3 bytes:
[D] 92 83 D1
[D] device has data
[D] 1 bytes:
[D] 92
[D] device has data
[D] 1 bytes:
[D] 83
[D] device has data
[D] 1 bytes:
[D] D1
[D] device has data
[D] 1 bytes:
[D] 12
[D] device has data
[D] 2 bytes:
[D] 43 22
[D] device has data
[D] 1 bytes:
[D] FF
[D] device has data
[D] 1 bytes:
[D] 92
[D] device has data
[D] 2 bytes:
[D] 83 81
[D] device has data
[D] 3 bytes:
[D] 92 83 D1
[D] device has data
[D] 3 bytes:
[D] 12 83 D1
[D] socket has data
[D] 5 bytes:
[D] 01 03 00 07 FB
[D] device has data
[D] 1 bytes:
[D] 92
[D] device has data
[D] 2 bytes:
[D] 63 22
[D] device has data
[D] 1 bytes:
[D] FF
[D] device has data
[D] 3 bytes:
[D] 92 83 D1
[D] Server has closed the connection
[E] Socket has gone
Loop ended
[D] Shutting down SSL session...
[D] Freeing SSL session...
[D] Freeing SSL context...

[PoltoS]

Ok, I see now different log: the stick answers with data, but wrong data.

We have experienced same problems when the stick had data to be delivered to the PC host. In such case it does not reply immediatelly to our GetSerialAPICapabilities request, but sends us unsolicited data it has in buffer. These data comes for example from reports and Basic Set sent from your devices to the stick after the stick was powered up (pluged in), but no software was running.

Just wait several cycles of Z-Connector connects to purge the buffer of your stick and then (after 1-10 tries) it shall run correctly.

In future wi will probably introduce a buffer purging before starting the software. But this will introduce a delay of several seconds.

[Borik]

Hi there.

Trying to get app to work and i get: Failed to Perform handshake: (null)

Win XP, no Firewall, anything i should check to get this resolved?

Thank you

[PoltoS]

This was a problem on our side. Please try again.

[Borik]

Thank you, now its seems that after handshake its disconnects or stops without any errors/warnings.

Thank you

Borik

[PoltoS]

This usually happens when the port is not the correct one. To detect the port name use Device Manager in Windows.

[Borik]

It seems that my connection get dropped very fast, the longest i had was about 5-7 sec...

Web Site was able to get the list of all of my devices, but that about it...

Borik

[PoltoS]

but it seems that is something on your side... Check your firewall.

Which version do you use? Windows or Mac/Linux?