Failed to perform handshake

Discussions about Z-Way software and Z-Wave technology in general
woudt
Posts: 5
Joined: 12 Feb 2012 16:52

Same problem again

Post by 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...
User avatar
PoltoS
Posts: 7565
Joined: 26 Jan 2011 19:36

Check port number!

Post by 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
Posts: 5
Joined: 12 Feb 2012 16:52

Port number should be ok

Post by 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...
User avatar
PoltoS
Posts: 7565
Joined: 26 Jan 2011 19:36

This happens dometimes due to stick sending unsolicited data

Post by 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
Posts: 7
Joined: 13 Sep 2012 19:01

Failed to Perform handshake: (null)

Post by 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
User avatar
PoltoS
Posts: 7565
Joined: 26 Jan 2011 19:36

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

Post by PoltoS »

This was a problem on our side. Please try again.
Borik
Posts: 7
Joined: 13 Sep 2012 19:01

Thank you, now its seems that

Post by Borik »

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

Thank you

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

Please check the com port you have chosen.

Post by PoltoS »

This usually happens when the port is not the correct one. To detect the port name use Device Manager in Windows.
Borik
Posts: 7
Joined: 13 Sep 2012 19:01

Correct Port, connection Last at most 5 sec.

Post by 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
User avatar
PoltoS
Posts: 7565
Joined: 26 Jan 2011 19:36

We don't see any reason for your diconnects

Post by PoltoS »

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

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