search

Orange-OpenSource / its-client

This Intelligent Transportation Systems (ITS) MQTT client based on the JSon ETSI specification transcription provides a ready to connect project for the mobility (connected and autonomous vehicles, road side units, vulnerable road users,...). Let's connect your device or application to our Intelligent Transport Systems (ITS) platform!
MIT License
7 stars 8 forks source link

python/its-client: stalls when losing the MQTT connection (somehow?) #75

Closed ymorin-orange closed 1 year ago

ymorin-orange commented 1 year ago

Currently, the its-client randomly stalls.

We suspect a bad interaction between the gps polling, the RoI computation, and the MQTT session, as can be seen and inferred from this trace:

Mar 02 12:59:26 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:26,094 DEBUG: Polling gps
Mar 02 12:59:26 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:26,095 DEBUG: location received: lon 1.3752354, lat 43.6350036
Mar 02 12:59:26 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:26,096 DEBUG: altitude received:153.175
Mar 02 12:59:26 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:26,096 DEBUG: movement received:{'speed': 0.702, 'track': 160.4381, 'climb': -0.282}
Mar 02 12:59:26 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:26,096 DEBUG: time received:2023-03-02 12:59:27
Mar 02 12:59:26 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:26,097 WARNING: the position time is 902.948 ms in the past
Mar 02 12:59:26 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:26,097 DEBUG: current speed: 0.702 km/h
Mar 02 12:59:26 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:26,097 DEBUG: we compute the station id for ora_car_XXXXXXXX
Mar 02 12:59:26 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:26,099 DEBUG: we update the Region Of Interest
Mar 02 12:59:26 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:26,101 DEBUG: MQTTClient[ora_car_XXXXXXXX]::publish publishing payload: {"type": "cam", "origin": "self", "version": "1.1.1", "source_uuid": "ora_car_XXXXXXXX", "timestamp": 1677761966097, "message": {"protocol_version": 1, "station_id": XXXXXXX, "generation_delta_time": 19353, "basic_container": {"station_type": 5, "reference_position": {"latitude": 436350036, "longitude": 13752354, "altitude": 15318}, "confidence": {"position_confidence_ellipse": {"semi_major_confidence": 10, "semi_minor_confidence": 50, "semi_major_orientation": 1}, "altitude": 1}}, "high_frequency_container": {"heading": 1604, "speed": 70, "longitudinal_acceleration": 0, "drive_direction": 0, "vehicle_length": 40, "vehicle_width": 20, "confidence": {"heading": 2, "speed": 3, "vehicle_length": 0}}, "low_freq_container": {"vehicle_role": 2}}}
Mar 02 12:59:26 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:26,101 INFO: message sent on topic XXXXXXX/inQueue/v2x/cam/ora_car_XXXXXXXX/1/2/0/2/2/2/0/2/1/3/3/3/1/0/3/0/0/3/0/1/1/2
Mar 02 12:59:26 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:26,302 DEBUG: gps value calling
Mar 02 12:59:26 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:26,303 DEBUG: Polling gps
Mar 02 12:59:26 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:26,303 DEBUG: location received: lon 1.375233, lat 43.6350032
Mar 02 12:59:26 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:26,306 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_socket_close  called for None with None
Mar 02 12:59:26 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:26,308 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_disconnect  called for None with None
Mar 02 12:59:26 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:26,310 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_disconnect  called for None with None
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,361 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_socket_open  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,364 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_socket_register_write  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,404 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_connect  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None and {'session present': 0}
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,404 INFO: connected to mqtt broker
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,406 DEBUG: MQTTClient[ora_car_XXXXXXXX]::subscribe subscribing to XXXXXXX/outQueue/info/broker...
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,409 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_socket_register_write  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,409 INFO: we subscribed on topic XXXXXXX/outQueue/info/broker
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,412 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_socket_register_write  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,415 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_socket_register_write  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,418 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_socket_register_write  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None
--snip--
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,678 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_socket_register_write  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,681 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_socket_register_write  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,684 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_socket_register_write  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,687 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_subscribe  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,687 INFO: message received on topic XXXXXXX/outQueue/info/broker
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,689 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_message mid: 0, payload: b'{"type":"broker","instance_id":"ora_broker_XXXX","running":true,"timestamp":1677761600000,"validity_duration":610,"version":"1.1.0","public_ip_address":["XXXXXXXXXXXXX"],"mqtt_ip":["XXXXXXXXXXXXX:11883"],"mqtt_tls_ip":["XXXXXXXXXXXXX:18883"],"ntp_servers":["0.debian.pool.ntp.org","1.debian.pool.ntp.org"],"domain_name_servers":["1.1.1.1","XXXXXXXXXXXXX"],"gelf_loggers":["XXXXXXXXXXXXX:12201"],"udp_loggers":["XXXXXXXXXXXXX:12202"],"tcp_loggers":["XXXXXXXXXXXXX:12204"],"fbeat_loggers":["XXXXXXXXXXXXX:12203"],"server_type":"cloud","instance_type":"central","service_area":{"type":"point","coordinates":[46.630869,1.850482],"radius":544000}}'
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,690 DEBUG: mid: 0: forwarding to mirror broker
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,693 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_message Instance id: ora_broker_XXXX
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,695 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_publish  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,697 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_publish  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,700 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_publish  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,702 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_publish  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None
--snip--
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,918 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_publish  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,921 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_publish  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,923 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_publish  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None
Mar 02 12:59:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 12:59:27,926 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_publish  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None
Mar 02 13:00:27 v2x-XXXXXXXX its-client[1505]: 2023-03-02 13:00:27,998 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_socket_register_write  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None
Mar 02 13:01:28 v2x-XXXXXXXX its-client[1505]: 2023-03-02 13:01:28,107 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_socket_register_write  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None
Mar 02 13:02:28 v2x-XXXXXXXX its-client[1505]: 2023-03-02 13:02:28,260 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_socket_register_write  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None
Mar 02 13:03:18 v2x-XXXXXXXX its-client[1505]: 2023-03-02 13:03:18,104 INFO: message received on topic XXXXXXX/outQueue/info/broker
Mar 02 13:03:18 v2x-XXXXXXXX its-client[1505]: 2023-03-02 13:03:18,106 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_message mid: 0, payload: b'{"type":"broker","instance_id":"ora_broker_XXXX","running":true,"timestamp":1677762198000,"validity_duration":610,"version":"1.1.0","public_ip_address":["XXXXXXXXXXXXX"],"mqtt_ip":["XXXXXXXXXXXXX:11883"],"mqtt_tls_ip":["XXXXXXXXXXXXX:18883"],"ntp_servers":["0.debian.pool.ntp.org","1.debian.pool.ntp.org"],"domain_name_servers":["1.1.1.1","XXXXXXXXXXXXX"],"gelf_loggers":["XXXXXXXXXXXXX:12201"],"udp_loggers":["XXXXXXXXXXXXX:12202"],"tcp_loggers":["XXXXXXXXXXXXX:12204"],"fbeat_loggers":["XXXXXXXXXXXXX:12203"],"server_type":"cloud","instance_type":"central","service_area":{"type":"point","coordinates":[46.630869,1.850482],"radius":544000}}'
Mar 02 13:03:18 v2x-XXXXXXXX its-client[1505]: 2023-03-02 13:03:18,107 DEBUG: mid: 0: forwarding to mirror broker
Mar 02 13:03:18 v2x-XXXXXXXX its-client[1505]: 2023-03-02 13:03:18,110 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_message Instance id: ora_broker_XXXX
Mar 02 13:03:29 v2x-XXXXXXXX its-client[1505]: 2023-03-02 13:03:29,124 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_socket_register_write  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None
Mar 02 13:04:29 v2x-XXXXXXXX its-client[1505]: 2023-03-02 13:04:29,244 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_socket_register_write  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None
Mar 02 13:05:29 v2x-XXXXXXXX its-client[1505]: 2023-03-02 13:05:29,353 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_socket_register_write  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None
Mar 02 13:08:29 v2x-XXXXXXXX its-client[1505]: 2023-03-02 13:08:29,862 DEBUG: MQTTClient[ora_car_XXXXXXXX]::on_socket_register_write  called for <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.248.100.41', 40259), raddr=('XXXXXXXXXXXXX', 11883)> with None
--snip--
ymorin-orange commented 1 year ago

The its-client is EOL, with a planned rewrite from scratch. The current use-case is to run it as a systemd unit, so the trivial workaround is to just abort whenever we detect that situation, and systemd will just restart the client...

That's not nice, but fixing that ssue does not look too easy, and given there's a rewrite in progress, it does not make much sense investigating too much.

@tigroo @nbuffon FYI.