Mac OSX [E] Socket has gone

Discussions about Z-Way software and Z-Wave technology in general
Post Reply
timrule
Posts: 5
Joined: 03 Mar 2012 01:06

Mac OSX [E] Socket has gone

Post by timrule » 22 Apr 2012 16:10

This is similar to other posters but not clear to me if it was resolved. I can't get Z connector to talk to my USB stick and stay connected on OSX.

I am using Aeon USB Z Wave USB adaptor and Mac OSX Lion. I have installed SiLABS USB driver and when inserted the USB stick appears in /dev as cu.SLAB_USBtoUART.

I have compiled z-agent using the make command, and I have edited the Run_Z-agent.su file to reflect the correct device name... I also switched on --debug. Here is the output going through a couple of loops. It appears that the server is sending 01 03 00 07 FB a few times and getting no response then drops. The second loop there is a bunch of data waiting from the USB device. Server responds 06 three times then reverts back to 01 03 00 07 FB three times before closing the connection. This goes on but the server keeps closing the connection. I am guessing that the server isn't getting a response back from the USB device before timing out?

Opening device...
[D] Configuring device...
[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...
Opening device...
[D] Configuring device...
[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...
[I] Establishing SSL connection...
[D] Allocating SSL session...
[D] Assigning socket...
[I] 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...
[I] Establishing SSL connection...
[D] Allocating SSL session...
[D] Assigning socket...
[I] Performing SSL handshake...
[D] Initialising SSL state...
[D] Sending handshake...
[I] Loop started
[D] device has data
[D] 135 bytes:
[D] 01 2B 01 07 03 07 00 86 00 02 00 01 FE 80 FE 88
[D] 0F 00 00 00 FB 97 7F 82 07 00 00 80 00 80 00 00
[D] 00 00 00 00 00 00 00 00 00 00 00 00 C2 01 2B 01
[D] 07 03 07 00 86 00 02 00 01 FE 80 FE 88 0F 00 00
[D] 00 FB 97 7F 82 07 00 00 80 00 80 00 00 00 00 00
[D] 00 00 00 00 00 00 00 00 00 C2 01 2B 01 07 03 07
[D] 00 86 00 02 00 01 FE 80 FE 88 0F 00 00 00 FB 97
[D] 7F 82 07 00 00 80 00 80 00 00 00 00 00 00 00 00
[D] 00 00 00 00 00 00 C2
[D] socket has data
[D] 1 bytes:
[D] 06
[D] socket has data
[D] 1 bytes:
[D] 06
[D] socket has data
[D] 1 bytes:
[D] 06
[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
[I] Loop ended
[D] Shutting down SSL session...
[D] Freeing SSL session...
[D] Freeing SSL context...

timrule
Posts: 5
Joined: 03 Mar 2012 01:06

Tried changing the timeout interval from 1000 to 3000

Post by timrule » 22 Apr 2012 16:10

Just in case it was due to the USB stick responding too slowly I changed the timeout interval in main.c to 3000. Same behaviour so if there is a timing issue it might be on the server side. Every time I run this it seems to be the same.. when the loop runs the first time there is no 06 (ACK) from the device after 3 tries of 01 03 00 07 FB. Server drops. On 2nd attempt there is data from device and server responds 06 (ACK) 3 times before reverting back to 3 tries of 01 03 00 07 FB without response and drops.

User avatar
PoltoS
Posts: 4951
Joined: 26 Jan 2011 19:36

The problem seems to be in

Post by PoltoS » 22 Apr 2012 16:10

The problem seems to be in non-blocking sockets behaviour of OS X. It seems that software bloks on read operations, while it should not. Is it possible for you to send us "ptrace" output for the same connection? Not here in forum (it will be too big), but on info@. Or extrace the part dealing with read/write and post here only this small part.

We are also interrested in the small part where z-agen opens socket and port and set non-bloking options on them.

timrule
Posts: 5
Joined: 03 Mar 2012 01:06

ptrace / strace / dtruss

Post by timrule » 22 Apr 2012 16:10

Ok sorry for the delay I have been trying to educate myself in unix debug tools.

When you ask for "ptrace" output do you mean the list of system calls that usually comes from the strace debug tool in linux? In OSX I think that is dtruss. At the end of this post is the output from the part of the code that creates the socket, sets keep-alives and connects. I actually don't see any part of the code that sets non blocking options. I thought that was done through fcntl().


write_nocancel(0x1, "[D] Creating a socket...
", 0x19) = 25 0
socket(0x2, 0x1, 0x6) = 5 0
write_nocancel(0x1, "[D] Enabling keep-alives on the socket...
", 0x2A) = 42 0
setsockopt(0x5, 0xFFFF, 0x8) = 0 0
write_nocancel(0x1, " Connecting to server...
", 0x1C) = 28 0
__sysctl(0x7FFF6A3120FC, 0x2, 0x7FFF6A3120E8) = 0 0
bsdthread_register(0x7FFF9191EB68, 0x7FFF9191EB78, 0x2000) = 0 0
thread_selfid(0x7FFF9191EB68, 0x7FFF9191EB78, 0x0) = 27134 0
mmap(0x0, 0x2000, 0x3, 0x1002, 0x1000000, 0x4) = 0xA72A000 0
mprotect(0x10A72A000, 0x88, 0x1) = 0 0
mmap(0x0, 0x17000, 0x3, 0x1002, 0x1000000, 0x6) = 0xA72C000 0
mprotect(0x10A72C000, 0x1000, 0x0) = 0 0
mprotect(0x10A742000, 0x1000, 0x0) = 0 0
mmap(0x0, 0x17000, 0x3, 0x1002, 0x1000000, 0x6) = 0xA743000 0
mprotect(0x10A743000, 0x1000, 0x0) = 0 0
mprotect(0x10A759000, 0x1000, 0x0) = 0 0
mmap(0x0, 0x1000, 0x3, 0x1002, 0x1000000, 0x6) = 0xA75A000 0
mprotect(0x10A75A000, 0x1000, 0x1) = 0 0
mprotect(0x10A72A000, 0x88, 0x3) = 0 0
mmap(0x7F81D9400000, 0x200000, 0x3, 0x1002, 0x7000000, 0x6) = 0xA75B000 0
munmap(0x10A75B000, 0xA5000) = 0 0
munmap(0x10A900000, 0x5B000) = 0 0
mprotect(0x10A72A000, 0x88, 0x1) = 0 0
getpid(0x7FFF6A311F34, 0x3, 0x1) = 2590 0
__mac_syscall(0x7FFF91B5C7FE, 0x2, 0x7FFF6A311F80) = 0 0
stat64("/AppleInternal", 0x7FFF6A311FE8, 0x0) = -1 Err#2
audit_session_self(0x7FFF6A311D38, 0xFFFFFFFFFFFFFFFC, 0x4) = 5379 0
geteuid(0x7FFF6A311D38, 0xFFFFFFFFFFFFFFFC, 0x0) = 0 0
getegid(0x7FFF6A311D38, 0xFFFFFFFFFFFFFFFC, 0x0) = 0 0
getaudit_addr(0x7FFF6A311F80, 0x30, 0x0) = 0 0
csops(0xA1E, 0x7, 0x7FFF6A311BB0) = 0 0
mmap(0x0, 0x2000, 0x3, 0x1002, 0x1000000, 0x14) = 0xA75B000 0
mprotect(0x10A75B000, 0x88, 0x1) = 0 0
mmap(0x0, 0x17000, 0x3, 0x1002, 0x1000000, 0x6) = 0xA75D000 0
mprotect(0x10A75D000, 0x1000, 0x0) = 0 0
mprotect(0x10A773000, 0x1000, 0x0) = 0 0
mmap(0x0, 0x17000, 0x3, 0x1002, 0x1000000, 0x6) = 0xA774000 0
mprotect(0x10A774000, 0x1000, 0x0) = 0 0
mprotect(0x10A78A000, 0x1000, 0x0) = 0 0
mprotect(0x10A75A000, 0x1000, 0x3) = 0 0
mprotect(0x10A75A000, 0x1000, 0x1) = 0 0
mprotect(0x10A75B000, 0x88, 0x3) = 0 0
mmap(0x7F81C9400000, 0x200000, 0x3, 0x1002, 0x7000000, 0x7) = 0xC9400000 0
munmap(0x7F81C9500000, 0x100000) = 0 0
mprotect(0x10A75B000, 0x88, 0x1) = 0 0
recvfrom_nocancel(0x5, 0x7FFF6A312470, 0x4) = 4 0
close_nocancel(0x5) = 0 0
kevent(0x3, 0x7FFF6A3126E8, 0x1) = 0 0
kevent(0x3, 0x0, 0x0) = 1 0
kevent(0x3, 0x0, 0x0) = 1 0
recvfrom_nocancel(0x4, 0x7FFF6A312480, 0x1C) = 28 0
recvfrom_nocancel(0x4, 0x10A800E20, 0x2D) = 45 0
select_nocancel(0x5, 0x7FFF6A3124B0, 0x0) = 0 0
kevent(0x3, 0x7FFF6A311F80, 0x1) = 0 0
sendto_nocancel(0x4, 0x10A801440, 0x1C) = 28 0
close_nocancel(0x3) = 0 0
fstat64(0x1, 0x7FFF6A311BB8, 0x7FFF6A311C7C) = 0 0
ioctl(0x1, 0x4004667A, 0x7FFF6A311C54) = 0 0
write_nocancel(0x1, " Opening device...
", 0x16) = 22 0

timrule
Posts: 5
Joined: 03 Mar 2012 01:06

Is this what is needed?

Post by timrule » 22 Apr 2012 16:10

Is this debug output useful? I still can't find the code that makes the socket non-blocking. I have noticed that the handshake response from the server is now taking 15-20 seconds whereas it was just taking a couple of seconds before.

User avatar
PoltoS
Posts: 4951
Joined: 26 Jan 2011 19:36

We were able to reproduce the bug, but not to fix it yet.

Post by PoltoS » 22 Apr 2012 16:10

Do you see "Failed to alter device settings: 22" error on z-agent start?

timrule
Posts: 5
Joined: 03 Mar 2012 01:06

No I don't get that message.

Post by timrule » 22 Apr 2012 16:10

No I don't get that message. The original post shows the messages I get.

User avatar
PoltoS
Posts: 4951
Joined: 26 Jan 2011 19:36

Send us full dump please

Post by PoltoS » 22 Apr 2012 16:10

Would you be so kind to send us full dtruss output on info-at-z-wave.me, please. We are unable to debug it correctly.

User avatar
PoltoS
Posts: 4951
Joined: 26 Jan 2011 19:36

Z-Connector now works on Mac OS X too!

Post by PoltoS » 22 Apr 2012 16:10

Dear Z-Cloud users,

We are happy to announce that Z-Connector now works on Mac OS X too. Not compilation is needed anymore. Just open OSX folder, edit port name in Run_Z-Agent.sh file to something like cu.usbserial (depends on your Z-Wave stick) and execute it (it is good to run it in terminal to see what happens).

Have fun with Z-Cloud!

Post Reply