ZWAY server fails at 03:00 regularly

Discussions about RaZberry - Z-Wave board for Raspberry computer
seattleneil
Posts: 172
Joined: 02 Mar 2020 22:41

Re: ZWAY server fails at 03:00 regularly

Post by seattleneil »

The output from the commands all look normal.

As best as I can tell, you confirmed the problem is not software related. Instead of cloning your old SD card onto your new SD card, you might want to backup your Z-Way using the smarthome and expert UI, do a virgin install of Z-Way onto your new SD card (see: https: //z-wave.me/z-way/download-z-way/), and then restore your Z-Way. I have some concern that data on your old SD card might be corrupted and doing a clean install will provide a known starting point.

If the new SD card doesn't solve the problem, there are some lower-level diagnostics, such as seeing if the kernel has logged any SD card problems (run: dmesg | egrep 'mmc|sdhc') and running strace on a disk-write command (run: time strace dd if=/dev/zero of=/home/pi/test.file bs=64M count=1 oflag=dsync).

If the new SD card solves the problem, it might encourage someone at Z-Wave.me to recommend Pi hardware. For example, I primarily use a Pi 4 with a USB 3.1 240 GB SSD instead of an SD card ($40 at Amazom - https: //www.amazon.com/gp/product/B07PXCYCX1). When I ran the dd command, the times are as follows:
real 0m0.686s
user 0m0.004s
sys 0m0.567s

On a Pi 3 using an SD card, the dd times are as follows:
real 0m4.279s
user 0m0.019s
sys 0m1.318s

Yup, file writes using an SD card were 6 times slower.

Good luck.
User avatar
PoltoS
Posts: 7562
Joined: 26 Jan 2011 19:36

Re: ZWAY server fails at 03:00 regularly

Post by PoltoS »

I'm worried about the "Dropping packet to myself (node 1)" - why do you try to send a command to the device #1?

Try to manually run Z-Way in gdb and check the error it reports.

Code: Select all

cd /opt/z-way-server
LD_LIBRARY_PATH=$LD_LIBRARY_PATH:./libs:./modules gdb ./z-way-server
handle SIGPIPE nostop
handle SIGILL nostop
handle SIGHUP nostop
run
ScotsDon
Posts: 50
Joined: 28 Jul 2015 20:55

Re: ZWAY server fails at 03:00 regularly

Post by ScotsDon »

Thanks people, it's late in the evening! I will look tomorrow.

As regards sending to Device #1, I didn't think I did. I start with Device No 2 Inst 1. And why would this only happen at 03:00? My process is exactly the same every time. Is there a way I can check for this? Don't forget I have run this process for 7 years on the pi-1 with an earlier version of ZWay. What's changed is the faster Pi-3, a newer version of ZWay, Bullseye, and a crappy SD Card (Class 6 by the way). The Python error report confirms it fails on Device #2. Here is the full report, emailed to me at 03::00 on 11 Jan:

Traceback (most recent call last):
File "/usr/lib/python3.9/urllib/request.py", line 1346, in do_open
h.request(req.get_method(), req.selector, req.data, headers,
File "/usr/lib/python3.9/http/client.py", line 1255, in request
self._send_request(method, url, body, headers, encode_chunked)
File "/usr/lib/python3.9/http/client.py", line 1301, in _send_request
self.endheaders(body, encode_chunked=encode_chunked)
File "/usr/lib/python3.9/http/client.py", line 1250, in endheaders
self._send_output(message_body, encode_chunked=encode_chunked)
File "/usr/lib/python3.9/http/client.py", line 1010, in _send_output
self.send(msg)
File "/usr/lib/python3.9/http/client.py", line 950, in send
self.connect()
File "/usr/lib/python3.9/http/client.py", line 921, in connect
self.sock = self._create_connection(
File "/usr/lib/python3.9/socket.py", line 843, in create_connection
raise err
File "/usr/lib/python3.9/socket.py", line 831, in create_connection
sock.connect(sa)
ConnectionRefusedError: [Errno 111] Connection refused

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/home/pi/Documents/Code_Control_Heating_by_ZWave.py", line 657, in <module>
Action = ActionRelayCommands(Device = '2', DeviceName = "UFH", DevInst = '1', DevInstName = 'Zone A', DevState = State, DevStateName = StateName)
File "/home/pi/Documents/Code_Control_Heating_by_ZWave.py", line 110, in ActionRelayCommands
responseAction = urllib.request.urlopen('http://localhost:8083/ZWaveAPI/Run/devices[' + Device + '].instances[' + DevInst+ '].commandClasses.SwitchBinary.Get()')
File "/usr/lib/python3.9/urllib/request.py", line 214, in urlopen
return opener.open(url, data, timeout)
File "/usr/lib/python3.9/urllib/request.py", line 517, in open
response = self._open(req, data)
File "/usr/lib/python3.9/urllib/request.py", line 534, in _open
result = self._call_chain(self.handle_open, protocol, protocol +
File "/usr/lib/python3.9/urllib/request.py", line 494, in _call_chain
result = func(*args)
File "/usr/lib/python3.9/urllib/request.py", line 1375, in http_open
return self.do_open(http.client.HTTPConnection, req)
File "/usr/lib/python3.9/urllib/request.py", line 1349, in do_open
raise URLError(err)
urllib.error.URLError: <urlopen error [Errno 111] Connection refused>
User avatar
PoltoS
Posts: 7562
Joined: 26 Jan 2011 19:36

Re: ZWAY server fails at 03:00 regularly

Post by PoltoS »

Sorry, forgot. Run it under root
ScotsDon
Posts: 50
Joined: 28 Jul 2015 20:55

Re: ZWAY server fails at 03:00 regularly

Post by ScotsDon »

With the new SD card, it still fails at 03:00 exactly as before. I copied the image of the old card to the new card but first I had to shrink the image because the new card was a little bit smaller than the old card, which was time consuming. I had never done that before so I took time to find out how to get it right. I used another PC with Linux on it.
ScotsDon
Posts: 50
Joined: 28 Jul 2015 20:55

Re: ZWAY server fails at 03:00 regularly

Post by ScotsDon »

seattleneil wrote:
11 Jan 2022 19:32

If the new SD card doesn't solve the problem, there are some lower-level diagnostics, such as seeing if the kernel has logged any SD card problems (run: dmesg | egrep 'mmc|sdhc') and running strace on a disk-write command (run: time strace dd if=/dev/zero of=/home/pi/test.file bs=64M count=1 oflag=dsync).

The result of the dmesg command was:
pi@raspberrypi-3:~ $ dmesg | egrep 'mmc|sdhc'
[ 3.005732] sdhci: Secure Digital Host Controller Interface driver
[ 3.005748] sdhci: Copyright(c) Pierre Ossman
[ 3.006391] mmc-bcm2835 3f300000.mmcnr: could not get clk, deferring probe
[ 3.007102] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe
[ 3.007342] sdhci-pltfm: SDHCI platform and OF driver helper
[ 3.033639] mmc-bcm2835 3f300000.mmcnr: mmc_debug:0 mmc_debug2:0
[ 3.033656] mmc-bcm2835 3f300000.mmcnr: DMA channel allocated
[ 3.097463] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[ 3.099142] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[ 3.100823] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[ 3.103833] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[ 3.108857] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[ 3.225624] mmc0: host does not support reading read-only switch, assuming write-enable
[ 3.228938] mmc0: new high speed SDHC card at address 59b4
[ 3.229932] mmcblk0: mmc0:59b4 USD 7.28 GiB
[ 3.232912] mmcblk0: p1 p2
[ 3.253876] mmc1: new high speed SDIO card at address 0001
[ 3.266405] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[ 6.134551] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
pi@raspberrypi-3:~ $

Looks OK to me. I use an 8GB card because the .img file is small (well, 8GB) and it should take less time to read/write the image. But suitable 8GB cards are becoming thin on the ground. I have 2.5GB spare space., and this pi is not used for any otheer purpose.
seattleneil
Posts: 172
Joined: 02 Mar 2020 22:41

Re: ZWAY server fails at 03:00 regularly

Post by seattleneil »

The mystery continues...

At this point, you've confirmed the z-way-server process died (evidenced by the log file stopping at 3:00, port 8083 being closed and your python traceback reporting the connection to Z-Way fails which is logical since port 8083 is closed), but the cause remains unknown. The log entry before the z-way-server process died is unexpected - [2022-01-11 03:00:00.606] [E] [zway] Dropping packet to myself (node 1).

@PoltoS wrote: I'm worried about the "Dropping packet to myself (node 1)" - why do you try to send a command to the device #1?

@PoltoS has access to the z-way-server source code and has suggested you run z-way-server under the debugger (gdb) as user root to investigate the log entry. He's definitely the expert, so I would follow his suggestion.

If gdb doesn't reveal the cause, then you might want to do a clean install of Z-Way onto your new SD card (see: https: //z-wave.me/z-way/download-z-way/), and then restore your Z-Way configuration from a backup.
ScotsDon
Posts: 50
Joined: 28 Jul 2015 20:55

Re: ZWAY server fails at 03:00 regularly

Post by ScotsDon »

Just trying PoltoS's suggestion, but
sudo cd /opt/z-way-server
gives
sudo: cd: command not found
whereas without sudo it works. But if I do the run with sudo, what folder is it cd'd to?
I will give it a go anyway.
ScotsDon
Posts: 50
Joined: 28 Jul 2015 20:55

Re: ZWAY server fails at 03:00 regularly

Post by ScotsDon »

The biggest clue is:
[2022-01-10 03:00:00.875] [E] [zway] Dropping packet to myself (node 1)
What generates that and why?
ScotsDon
Posts: 50
Joined: 28 Jul 2015 20:55

Re: ZWAY server fails at 03:00 regularly

Post by ScotsDon »

Running PoloS's suggestion, which I hope I got right (I don't understand it), here is the result:

pi@raspberrypi-3:~ $ cd /opt/z-way-server
pi@raspberrypi-3:/opt/z-way-server $ sudo LD_LIBRARY_PATH=$LD_LIBRARY_PATH:./libs:./modules gdb ./z-way-server
GNU gdb (Raspbian 10.1-1.7) 10.1.90.20210103-git
Copyright (C) 2021 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "arm-linux-gnueabihf".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from ./z-way-server...
(No debugging symbols found in ./z-way-server)
(gdb) handle SIGPIPE nostop
Signal Stop Print Pass to program Description
SIGPIPE No Yes Yes Broken pipe
(gdb) handle SIGILL nostop
Signal Stop Print Pass to program Description
SIGILL No Yes Yes Illegal instruction
(gdb) handle SIGHUP nostop
Signal Stop Print Pass to program Description
SIGHUP No Yes Yes Hangup
(gdb) run
Starting program: /opt/z-way-server/z-way-server
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/arm-linux-gnueabihf/libthread_db.so.1".
Z-Way version v3.2.2 from 2021-11-29 15:40:21 +0300 (build 101045968be0f00797fdc4d1a70e2955271fe4e7)
Looking for modules in ./modules
Module modzbw.so loaded
Module modcrypto.so loaded
Module modhomekit.so loaded
Module modiconinstaller.so loaded
Module modsockets.so loaded
Module modws.so loaded
Module modskininstaller.so loaded
Module modzwave.so loaded
Module moddhs.so loaded
Module modenocean.so loaded
Module modmqtt.so loaded
Module modinstaller.so loaded
Module modhttp.so loaded
Module modnotification2ext.so loaded
Using default configuration file config.xml
Error: 'debug-port' number is out of range. Skipping it.
[New Thread 0x730ab440 (LWP 1356)]
[New Thread 0x769d2440 (LWP 1357)]
[New Thread 0x728aa440 (LWP 1358)]
[New Thread 0x72899440 (LWP 1359)]
[New Thread 0x72888440 (LWP 1360)]
[New Thread 0x72877440 (LWP 1361)]


The normal command line has not returned, so what do I do now?
Post Reply