{Exception log} Saw this in the log

[MDAR]

I don't know what this is.

is it important?

2021-08-25T14:33:53Z velbus-tcp.velbus-tcp[1395]: Exception in thread Thread-4:
2021-08-25T14:33:53Z velbus-tcp.velbus-tcp[1395]: Traceback (most recent call last):
2021-08-25T14:33:53Z velbus-tcp.velbus-tcp[1395]:   File "/snap/velbus-tcp/121/usr/lib/python3.6/threading.py", line 916, in _bootstrap_inner
2021-08-25T14:33:53Z velbus-tcp.velbus-tcp[1395]:     self.run()
2021-08-25T14:33:53Z velbus-tcp.velbus-tcp[1395]:   File "/snap/velbus-tcp/121/usr/lib/python3.6/threading.py", line 864, in run
2021-08-25T14:33:53Z velbus-tcp.velbus-tcp[1395]:     self._target(*self._args, **self._kwargs)
2021-08-25T14:33:53Z velbus-tcp.velbus-tcp[1395]:   File "/snap/velbus-tcp/121/lib/ntp.py", line 61, in __do_ntp
2021-08-25T14:33:53Z velbus-tcp.velbus-tcp[1395]:     until_dst = next(time for time in self.__timezone._utc_transition_times if time > datetime.utcnow())
2021-08-25T14:33:53Z velbus-tcp.velbus-tcp[1395]: AttributeError: 'backports.zoneinfo.ZoneInfo' object has no attribute '_utc_transition_times'

[dukeofphilberg]

The application contains code to automatically update the time on the bus, one part of this is that it tries to find the UTC transition time to precisely sync. If you're not using NTP, you can disable it with snap set velbus-tcp ntp.enabled=false, we'll look into this error

[MDAR]

Arrrr okay.

FYI OpenRemote & openHAB automatically update the bus time, (enabled by default) with the interval being adjustable.

Home-Assistant can update the time, but it's disabled by default.

There is a node set for Node-RED for updating the time.

As far as I know, Control4 will provide time updates.

However, URC-Automation probably won't have the ability to update the bus time, so this feature will be essential if the installers choose to configure timed events.

Crestron & Elan.... Let's see what happens with them

[MDAR]

@pvanloo

Hi Philip

is this the same issue?

2021-08-26T05:22:47Z velbus-tcp.velbus-tcp[1395]: Traceback (most recent call last):
2021-08-26T05:22:47Z velbus-tcp.velbus-tcp[1395]:   File "/snap/velbus-tcp/121/lib/connection/network.py", line 97, in __accept_sockets
2021-08-26T05:22:47Z velbus-tcp.velbus-tcp[1395]:     connection = self.__context.wrap_socket(connection, server_side=True)
2021-08-26T05:22:47Z velbus-tcp.velbus-tcp[1395]:   File "/snap/velbus-tcp/121/usr/lib/python3.6/ssl.py", line 407, in wrap_socket
2021-08-26T05:22:47Z velbus-tcp.velbus-tcp[1395]:     _context=self, _session=session)
2021-08-26T05:22:47Z velbus-tcp.velbus-tcp[1395]:   File "/snap/velbus-tcp/121/usr/lib/python3.6/ssl.py", line 817, in __init__
2021-08-26T05:22:47Z velbus-tcp.velbus-tcp[1395]:     self.do_handshake()
2021-08-26T05:22:47Z velbus-tcp.velbus-tcp[1395]:   File "/snap/velbus-tcp/121/usr/lib/python3.6/ssl.py", line 1077, in do_handshake
2021-08-26T05:22:47Z velbus-tcp.velbus-tcp[1395]:     self._sslobj.do_handshake()
2021-08-26T05:22:47Z velbus-tcp.velbus-tcp[1395]:   File "/snap/velbus-tcp/121/usr/lib/python3.6/ssl.py", line 689, in do_handshake
2021-08-26T05:22:47Z velbus-tcp.velbus-tcp[1395]:     self._sslobj.do_handshake()
2021-08-26T05:22:47Z velbus-tcp.velbus-tcp[1395]: ConnectionResetError: [Errno 104] Connection reset by peer
2021-08-26T05:22:47Z velbus-tcp.velbus-tcp[1395]: 2021-08-26 06:22:47,727 - INFO - network - TCP connection from ('74.120.xxx.xxx', 42192)
2021-08-26T05:22:48Z velbus-tcp.velbus-tcp[1395]: 2021-08-26 06:22:48,956 - INFO - network - TCP connection closed ('74.120.xxx.xxx', 42192) [auth failed] - {this was the Control4 Dev getting the SSL and Authentication setup}
2021-08-26T05:22:49Z velbus-tcp.velbus-tcp[1395]: 2021-08-26 06:22:49,153 - INFO - network - TCP connection from ('74.120.xxx.xxx', 36308)
2021-08-26T05:22:49Z velbus-tcp.velbus-tcp[1395]: Exception in thread Receive from client thread:
2021-08-26T05:22:49Z velbus-tcp.velbus-tcp[1395]: Traceback (most recent call last):
2021-08-26T05:22:49Z velbus-tcp.velbus-tcp[1395]:   File "/snap/velbus-tcp/121/usr/lib/python3.6/threading.py", line 916, in _bootstrap_inner
2021-08-26T05:22:49Z velbus-tcp.velbus-tcp[1395]:     self.run()
2021-08-26T05:22:49Z velbus-tcp.velbus-tcp[1395]:   File "/snap/velbus-tcp/121/usr/lib/python3.6/threading.py", line 864, in run
2021-08-26T05:22:49Z velbus-tcp.velbus-tcp[1395]:     self._target(*self._args, **self._kwargs)
2021-08-26T05:22:49Z velbus-tcp.velbus-tcp[1395]:   File "/snap/velbus-tcp/121/lib/connection/client.py", line 134, in __recv
2021-08-26T05:22:49Z velbus-tcp.velbus-tcp[1395]:     self.stop()
2021-08-26T05:22:49Z velbus-tcp.velbus-tcp[1395]:   File "/snap/velbus-tcp/121/lib/connection/client.py", line 49, in stop
2021-08-26T05:22:49Z velbus-tcp.velbus-tcp[1395]:     self.__connection.shutdown(socket.SHUT_RDWR)
2021-08-26T05:22:49Z velbus-tcp.velbus-tcp[1395]:   File "/snap/velbus-tcp/121/usr/lib/python3.6/ssl.py", line 1050, in shutdown
2021-08-26T05:22:49Z velbus-tcp.velbus-tcp[1395]:     socket.shutdown(self, how)
2021-08-26T05:22:49Z velbus-tcp.velbus-tcp[1395]: OSError: [Errno 107] Transport endpoint is not connected
2021-08-26T05:22:49Z velbus-tcp.velbus-tcp[1395]: 2021-08-26 06:22:49,484 - INFO - network - TCP connection from ('74.120.xxx.xxx', 41538)
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]: 2021-08-26 06:22:50,484 - ERROR - network - Couldn't wrap socket
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]: 2021-08-26 06:22:50,485 - ERROR - network - Couldn't accept socket
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]: 2021-08-26 06:22:50,486 - ERROR - network - [SSL: HTTP_REQUEST] http request (_ssl.c:852)
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]: Traceback (most recent call last):
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]:   File "/snap/velbus-tcp/121/lib/connection/network.py", line 101, in __accept_sockets
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]:     raise e
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]:   File "/snap/velbus-tcp/121/lib/connection/network.py", line 97, in __accept_sockets
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]:     connection = self.__context.wrap_socket(connection, server_side=True)
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]:   File "/snap/velbus-tcp/121/usr/lib/python3.6/ssl.py", line 407, in wrap_socket
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]:     _context=self, _session=session)
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]:   File "/snap/velbus-tcp/121/usr/lib/python3.6/ssl.py", line 817, in __init__
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]:     self.do_handshake()
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]:   File "/snap/velbus-tcp/121/usr/lib/python3.6/ssl.py", line 1077, in do_handshake
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]:     self._sslobj.do_handshake()
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]:   File "/snap/velbus-tcp/121/usr/lib/python3.6/ssl.py", line 689, in do_handshake
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]:     self._sslobj.do_handshake()
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]: ssl.SSLError: [SSL: HTTP_REQUEST] http request (_ssl.c:852)
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]: 2021-08-26 06:22:50,682 - INFO - network - TCP connection from ('74.120.xxx.xxx', 60974)
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]: 2021-08-26 06:22:50,686 - ERROR - network - Couldn't accept socket
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]: 2021-08-26 06:22:50,686 - ERROR - network - [Errno 104] Connection reset by peer
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]: Traceback (most recent call last):
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]:   File "/snap/velbus-tcp/121/lib/connection/network.py", line 97, in __accept_sockets
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]:     connection = self.__context.wrap_socket(connection, server_side=True)
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]:   File "/snap/velbus-tcp/121/usr/lib/python3.6/ssl.py", line 407, in wrap_socket
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]:     _context=self, _session=session)
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]:   File "/snap/velbus-tcp/121/usr/lib/python3.6/ssl.py", line 817, in __init__
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]:     self.do_handshake()
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]:   File "/snap/velbus-tcp/121/usr/lib/python3.6/ssl.py", line 1077, in do_handshake
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]:     self._sslobj.do_handshake()
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]:   File "/snap/velbus-tcp/121/usr/lib/python3.6/ssl.py", line 689, in do_handshake
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]:     self._sslobj.do_handshake()
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]: ConnectionResetError: [Errno 104] Connection reset by peer

[dukeofphilberg]

is this the same issue?

No, the person trying to connect to a TLS/SSL secured endpoint is not using the right protocol, as noted by

2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]: 2021-08-26 06:22:50,484 - ERROR - network - Couldn't wrap socket
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]: 2021-08-26 06:22:50,485 - ERROR - network - Couldn't accept socket
2021-08-26T05:22:50Z velbus-tcp.velbus-tcp[1395]: 2021-08-26 06:22:50,486 - ERROR - network - [SSL: HTTP_REQUEST] http request (_ssl.c:852)

This should be the default TLS protocol and not SSL as that is considered insecure.

Reference material:

https://github.com/velbus/python-velbustcp/blob/master/lib/connection/network.py#L162 https://docs.python.org/3/library/ssl.html#ssl.create_default_context

[MDAR]

Thanks.

Great to know the logging captures such things.

He has connected since then and is happy with the data through put.

He says he'll look at the C4 output rate in order to avoid overloading the buffer