[Bug Report] Nodes Keep Disconnecting

[zero77]

Describe the bug:

The remote nodes are periodically dropping off.
Sometimes they reconnect and sometimes I need to manually restart the nodes service or UI.

• OpenSnitch version: 1.7.2 Node and GUI
• OS: Debian
• OS version: Both Sid and Stable
• Window Manager: I3 and Headless
• Kernel version: 6.17.7+deb14+1-amd64 and 6.12.48+deb13-amd64

To Reproduce:

Steps to reproduce the behavior:
install GUI and configure remote node to connect to the GUI.
Leave VMs Connected and powered on

Post error logs:

When checking the surface which has not crashed I get lots of the following errors:

sudo service opensnitch status

opensnitchd[1204]: Timed out while sending packet to queue channel 1313700632
opensnitchd[1204]: Timed out while sending packet to queue channel 1313700632
opensnitchd[1204]: Timed out while sending packet to queue channel 1313700632

cat /var/log/opensnitchd.log

WAR  Error while pinging UI service: rpc error: code = DeadlineExceeded desc = context deadline exceeded, state: READY
WAR  Error while pinging UI service: rpc error: code = DeadlineExceeded desc = context deadline exceeded, state: READY
WAR  Error while pinging UI service: rpc error: code = DeadlineExceeded desc = context deadline exceeded, state: READY
WAR  Error while pinging UI service: rpc error: code = DeadlineExceeded desc = context deadline exceeded, state: READY
WAR  Error while pinging UI service: rpc error: code = DeadlineExceeded desc = context deadline exceeded, state: READY
ERR  Subscribing to GUI rpc error: code = DeadlineExceeded desc = context deadline exceeded
ERR  Connection to the UI service lost.
IMP  UI connected, dispathing queued alerts: 0
getting notifications: rpc error: code = Unavailable desc = transport is closing <nil>
Connection to the UI service lost.
UI connected, dispathing queued alerts: 0
getting notifications: rpc error: code = Unavailable desc = transport is closing <nil>
Connection to the UI service lost.
UI connected, dispathing queued alerts: 0

Screenshots:

Additional context:

[gustavo-iniguez-goya]

hi @zero77 ,

I cannot tell what's going on with these logs, I'll have to try to reproduce it.

"Error while pinging UI service" could mean that the GUI is receiving too many events, Change "Refresh interval" to something greater than 0, and see if the situation improves.

"Subscribing to GUI rpc error:" There's a hardcoded timeout of 10 seconds when connecting to the GUI, which should be more than enough. So I'd monitor what's the GUI doing. Is it stuck for some reason, consuming all the CPU?

[zero77]

Most of the time it is using very little CPU though I have not checked its CPU usage when the nodes drop off although, I don't always notice until I go into the UI that the nodes have dropped off.

I have set the refresh rate to two seconds, but I can increase it.
Let me know if you want more logs or for me to do any testing.

[gustavo-iniguez-goya]

ok, I'll try to reproduce it, maybe we have some deadlocks when working with multiple nodes.

[gustavo-iniguez-goya]

I think I've reproduced this behaviour. It seems that when the system loses and regains network connectivity, we subscribe correctly to the GUI but the channel to send data to the GUI is not established. That explains the Error while pinging UI service.* error.

I'll try to fix this behaviour.

[zero77]

Thank you for looking into this. Just to clarify, is this the same issue for the remote nodes as well as the node running on the same device as the UI?

Also, would it be possible to implement some kind of retry in case something like this happens again in the future?

[gustavo-iniguez-goya]

I don't think so. What's the issue of a node running on the same device? I've got 7 remote VMs with the daemon running, and a laptop with the GUI + a daemon.

On the other hand, yes, we have several retrying mechanisms. Mainly the ones provided by the gRPC library. And on top of this, when the connection is in a transient weird state, we force a disconnection, to force a reconnection.

The issue I reproduced was with v1.7.2 (compiled on Arch), and it happened when the GUI stopped responding (for example when I suspend the laptop, but the remote nodes keep running). However I've tested it with with latest sources, v1.8.0 (compiled on my machine), and I can no longer reproduced it no matter what I do.

So I was wondering if the gRPC versions GUI<->daemons has something to do with this behaviour.

opensnitchd[1204]: Timed out while sending packet to queue channel 1313700632

By the way, these errors are normal if they're sporadic. If they're continuous then it indicates an issue with the daemon.

[zero77]

It's the same issue with both the local and remote node, but the remote nodes have this problem a lot more regularly. Did all nodes disconnect together and did you find that the node would reconnect automatically when you opened the laptop lid or did you also have to restart the Demon or UI to fix this?

Because I am finding that all nodes have this problem, but not all at once.

[gustavo-iniguez-goya]

I've found 2 issues:

1. Sometimes changing manually the Server Address in the default-configuration.json file doesn't work, and you have to change it one more time. This is not related to this bug report.
2. After opening the laptop lid and restore the system, which is where the GUI is running, the nodes reconnect but it seems that we're not accepting the connection on the GUI. So we don't update the status of the nodes.

But I haven't reproduced exactly what you describe. Could you set the log level to DEBUG at least in one of those machines, to see more in detail the connection behaviour to the GUI?

In any case, I'm using this opportunity to improve the management of multiple nodes.

[zero77]

I turned on debugging and waited until the node disconnected.
This is just some of the logs that have the same error with debugging, as it filled up quickly to over 100 MB.

https://pastebin.com/CXNEVXxX

[gustavo-iniguez-goya]

Unfortunately there isn't much information inthe logs :/
I'll have to keep trying to reproduce it.

[zero77]

I wasn't able to identify when exactly the node disconnected. So I just provided the logs that had the same errors as last time. I can have another look through to see if I can get any more information from the logs.

[gustavo-iniguez-goya]

I reproduce the warning Error while pinging UI service ... DeadlineExceeded in a LXC container with low resources (1core,cpu + 512mb).

The thing is, when sending the events to the GUI, we're not only measuring how long the post to the GUI takes, but also the collection of the stats before sending them. So in some scenarios, this can affect the deadline.
We should only measure the network post.

Let's see if I can fix at least the warning I've reproduced.

[gustavo-iniguez-goya]

After some debugging, these errors may occur if the GUI is under load, such as deleting old records from the DB in background.
The GUI seems to stop responding for a short time, not much, but enough to trigger the deadline of 1 second of the daemon.

This behaviour can also be reproduced by forcing the GUI to execute CPU intensive tasks, such as monitoring listening sockets (Netstat tab) or monitoring a PID (Process dialog). Again, those tasks briefly block the GUI, but it's enough to meet the deadline of the daemon.

If there's more than one node connected to the GUI, I guess this behaviour will occur more often.
It's not related to how much stats the daemon has in memory.

Given that these warnings seems to be normal at least in this scenario, maybe we could change the log level to Debug.