omzlo / nocand Goto Github PK

After a few minutes the nocand -> "nocanc mqtt" ack mechanism stops working reliably and eventually it also stops processing outbound MQTT messages.
I can tell that the data is getting through to the canzero because I programmed the canzero to send a "_received a message" debug message every time a message arrives.

[[mqtt.subscribers]]
channel="node20_c_enable_light"
topic="node20/c_enable_light"

Output from nocand
2021/02/16 13:50:33 DEBUG++ Broadcasting channel update on node20_c_enable_light: "node20/c_enable_light=1"
2021/02/16 13:50:33 DEBUG++ SEND FRAME EXT@9000001e 8: 6e 6f 64 65 32 30 2f 63>
2021/02/16 13:50:33 DEBUG++ SEND FRAME EXT@8000001e 8: 5f 65 6e 61 62 6c 65 5f>
2021/02/16 13:50:33 DEBUG++ SEND FRAME EXT@8010001e 7: 6c 69 67 68 74 3d 31>
2021/02/16 13:50:33 DEBUG ** Received **
2021/02/16 13:50:33 INFO Updated content of channel 'node20_debug' (id=0) to "_received a message"

However the output from "nocanc mqtt" says there is a problem
2021/02/16 13:50:33 WARNING Failed to send 23 byte message for NoCAN channel 'node20_c_enable_light': MsgId mismatch is reponse to request channel-update-event (request MsgId: 2, response MsgId: 3)

Once it prints the first warning it repeats for every susequent subscription message and may also stop the processing of outbound MQTT messages. Sometimes it recovers, sometimes it doesn't.

For example:
2021/02/16 14:40:27 INFO Published 5 bytes from channel '196_s_p_motor_speed' to topic '196_s_p_motor_speed'
2021/02/16 14:40:27 INFO Published 3 bytes from channel '13b_s_p_flow_count' to topic '13b_s_p_flow_count'
2021/02/16 14:40:27 INFO Published 5 bytes from channel '108_s_p_pool_top_temperature' to topic '108_s_p_pool_top_temperature'
2021/02/16 14:40:27 INFO Published 5 bytes from channel '109_s_p_pool_bottom_temperature' to topic '109_s_p_pool_bottom_temperature'
2021/02/16 14:40:27 INFO Published 2 bytes from channel 's_calculated_led_strip_brightness' to topic 's_calculated_led_strip_brightness'
2021/02/16 14:40:28 WARNING Failed to send 23 byte message for NoCAN channel 'node20_c_enable_light': Failed to write 61 bytes for value of encoded event 9, write tcp 127.0.0.1:60888->127.0.0.1:4242: write: broken pipe
2021/02/16 14:40:29 WARNING Failed to send 23 byte message for NoCAN channel 'node20_c_enable_light': Failed to write 61 bytes for value of encoded event 9, write tcp 127.0.0.1:60888->127.0.0.1:4242: write: broken pipe
2021/02/16 14:40:30 WARNING Failed to send 23 byte message for NoCAN channel 'node20_c_enable_light': Failed to write 61 bytes for value of encoded event 9, write tcp 127.0.0.1:60888->127.0.0.1:4242: write: broken pipe
2021/02/16 14:40:31 WARNING Failed to send 23 byte message for NoCAN channel 'node20_c_enable_light': Failed to write 61 bytes for value of encoded event 9, write tcp 127.0.0.1:60888->127.0.0.1:4242: write: broken pipe
2021/02/16 14:40:32 WARNING Failed to send 23 byte message for NoCAN channel 'node20_c_enable_light': Failed to write 61 bytes for value of encoded event 9, write tcp 127.0.0.1:60888->127.0.0.1:4242: write: broken pipe
2021/02/16 14:40:33 WARNING Failed to send 23 byte message for NoCAN channel 'node20_c_enable_light': Failed to write 61 bytes for value of encoded event 9, write tcp 127.0.0.1:60888->127.0.0.1:4242: write: broken pipe
2021/02/16 14:40:34 WARNING Failed to send 23 byte message for NoCAN channel 'node20_c_enable_light': Failed to write 61 bytes for value of encoded event 9, write tcp 127.0.0.1:60888->127.0.0.1:4242: write: broken pipe
2021/02/16 14:40:35 WARNING Failed to send 23 byte message for NoCAN channel 'node20_c_enable_light': Failed to write 61 bytes for value of encoded event 9, write tcp 127.0.0.1:60888->127.0.0.1:4242: write: broken pipe
2021/02/16 14:40:36 WARNING Failed to send 23 byte message for NoCAN channel 'node20_c_enable_light': Failed to write 61 bytes for value of encoded event 9, write tcp 127.0.0.1:60888->127.0.0.1:4242: write: broken pipe
2021/02/16 14:40:37 WARNING Failed to send 23 byte message for NoCAN channel 'node20_c_enable_light': Failed to write 61 bytes for value of encoded event 9, write tcp 127.0.0.1:60888->127.0.0.1:4242: write: broken pipe
2021/02/16 14:40:38 WARNING Failed to send 23 byte message for NoCAN channel 'node20_c_enable_light': Failed to write 61 bytes for value of encoded event 9, write tcp 127.0.0.1:60888->127.0.0.1:4242: write: broken pipe
2021/02/16 14:40:39 WARNING Failed to send 23 byte message for NoCAN channel 'node20_c_enable_light': Failed to write 61 bytes for value of encoded event 9, write tcp 127.0.0.1:60888->127.0.0.1:4242: write: broken pipe

When it looks like this there is no recovery.

The setup is one canzero sending approx 25 messages per second and receiving 1 message per second.

2021/02/12 21:01:22 WARNING Failed to send 23 byte message for NoCAN channel 'everything': Failed to write 50 bytes for value of encoded event 9, write tcp 127.0.0.1:41380->127.0.0.1:4242: write: broken pipe

The message repeats many times.

Possibly related to #5
Multiple topics are matched to a single channel.

The canzero is sending about 20 messages per second and receiving 1 per second from a Windows box.

I can trigger it by sending the following message 2 times in a row from the Rasp Pi.
mosquitto_pub -t 'node20/c_enable_light' -m "node20/c_enable_light=1" -h 127.0.0.1

(The payload looks strange because it contains a copy of the topic.)

from the forum: https://forum.omzlo.com/forum/nocan/nocanc-mqtt-msgid-mismatch-version-0-3-2

MsgId mismatch is reponse to request channel-update-event (request MsgId: 779, response MsgId: 2)

I don't know if this has anything to do with having multiple topics mapping to a single channel. For example

[[mqtt.subscribers]]
channel="everything"
topic="node20/c_enable_light"

[[mqtt.subscribers]]
channel="everything"
topic="front-door-pir-state"

I shall do some more testing.

Cloud is writen and should be Could

from the forum: https://forum.omzlo.com/forum/nocan/nocand-cpu-usage-28-version-0-2-6

On a Ras Pi 4 nocand is using 28%.
Is this normal when processing 30 messages a second?

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 
586 root 20 0 171872 93068 76004 R 57.6 1.2 50:39.67 Xorg 
1079 pi 20 0 177172 55100 38296 S 41.7 0.7 31:30.31 lxterminal 
1676 pi 20 0 900304 10376 5304 R 28.1 0.1 7:00.10 nocand 
534 root 20 0 48896 33064 17592 S 14.2 0.4 30:13.94 vncserver-x11-c 
1716 pi 20 0 803052 11676 6216 S 13.6 0.1 2:38.17 nocanc 
401 pi 25 5 211416 101232 24784 S 11.9 1.3 13:27.86 node-red 
519 influxdb 20 0 1290752 108860 24928 S 7.9 1.3 13:30.96 influxd 
1799 pi 20 0 802796 10632 5848 S 4.6 0.1 0:25.14 nocanc 
1806 pi 20 0 802604 10668 5848 S 4.6 0.1 0:23.98 nocanc

from the forum: nocanc mqtt" doesn't reliably detect when nocand has been terminated (version 0.3.2)

If nocand is terminated then "nocanc mqtt" doesn't flag an error or terminate.
If you restart nocand then I have seen two behaviors:

1. "nocanc mqtt" carries on working,
   or
2. "nocanc mqtt" stays frozen and you have to terminate it and restart it.

from the forum: https://forum.omzlo.com/forum/nocan/is-it-possible-for-the-rasp-pi-shutdown-now-command-to-automatically-generate-a-nocand-power-off-command

Currently if you shutdown the Rasp Pi the CAN bus remains powered.
Would it be possible for the "nocand server" to respond to the SIGHUP by first sending a power-off command before exiting?

from the forum https://forum.omzlo.com/forum/nocan/firmware-update-crc32-mismatch-version-0-3-2

I'm seeing regular firmware upload failures.
Restarting nocand fixes the problem every time.
Prior to the upload the canzero is sending bursts of 20+ messages every second. Perhaps the STM is getting confused due to a backlog of messages it is trying to send from the SAMD?
I can see from Nocan.transmitPending() that I'm trying to send faster than what the system can cope with.

2021/02/12 19:09:44 DEBUG++ SEND FRAME EXT@80241600 8: c0 46 c0 46 c0 46 c0 46>
2021/02/12 19:09:44 DEBUG++ SEND FRAME EXT@80241600 8: c0 46 c0 46 c0 46 c0 46>
2021/02/12 19:09:44 DEBUG++ SEND FRAME EXT@80341600 8: c0 46 c0 46 c0 46 c0 46>
2021/02/12 19:09:44 DEBUG ** Received <nocan-sys-bootloader-write-ack node=1, func=23, param=0, len=0, data=> **
2021/02/12 19:09:44 DEBUG+ ** Sending <nocan-sys-bootloader-write node=1, func=22, param=1, len=4, data=a77c3236> **
2021/02/12 19:09:44 DEBUG++ SEND FRAME EXT@90341601 4: a7 7c 32 36>
2021/02/12 19:09:44 DEBUG ** Received <nocan-sys-bootloader-write-ack node=1, func=23, param=255, len=4, data=fb76b398> **
2021/02/12 19:09:44 WARNING Firmware upload failed: SYS_BOOTLOADER_WRITE failed for node 1 at address=0x0, CRC32 mismatch, expected=a77c3236 go fb76fbfb
2021/02/12 19:09:44 DEBUG++ Deleting client 10 (192.168.0.17:55553), closing channel and socket
2021/02/12 19:09:48 DEBUG+ ** Sending <nocan-sys-node-ping node=2, func=8, param=0, len=0, data=> **
2021/02/12 19:09:48 DEBUG++ SEND FRAME EXT@90540800 0:>
2021/02/12 19:09:48 DEBUG ** Received <nocan-sys-node-ping-ack node=2, func=9, param=0, len=0, data=> **
2021/02/12 19:09:48 DEBUG+ Driver voltage=23.9, current sense=27 (~ 41 mA), reference voltage=3.28, status(40)=+powered.
2021/02/12 19:09:58 DEBUG+ Driver voltage=23.8, current sense=31 (~ 47 mA), reference voltage=3.28, status(40)=+powered.

From the forum: https://forum.omzlo.com/forum/nocan/ping-ack-causes-canzero-firmware-update-to-fail-version-0-3-2

I think I reported a similar issue for the 0.2.6

** Sending <nocan-sys-bootloader-write node=1, func=22, param=1, len=4, data=6a8bfd26> **
2021/02/10 23:26:36 DEBUG++ SEND FRAME EXT@90341601 4: 6a 8b fd 26>
2021/02/10 23:26:36 DEBUG ** Received <nocan-sys-node-ping-ack node=1, func=9, param=0, len=0, data=> **
2021/02/10 23:26:36 WARNING Firmware upload failed: Final SYS_BOOTLOADER_WRITE failed for node 1 at address=0x0, Unexpected system message nocan-sys-node-ping-ack, while expecting nocan-sys-bootloader-write-ack.
2021/02/10 23:26:36 DEBUG++ Deleting client 3 (192.168.0.17:49925), closing channel and socket
2021/02/10 23:26:36 DEBUG ** Received <nocan-sys-bootloader-write-ack node=1, func=23, param=1, len=0, data=> **
2021/02/10 23:26:36 WARNING Message of type nocan-sys-bootloader-write-ack from node N1 (7a:9d:cc:40:9d:a3:f0:a7) was not processed