Only logs for a short bit before stalling

[courtarro]

The script starts well, but eventually it stops reporting anything to telegraf. There's no indication that the BaseStation connection is down.

Here are the logs from the container:

[s6-init] making user provided files available at /var/run/s6/etc...exited 0.
[s6-init] ensuring user provided files have correct perms...exited 0.
[fix-attrs.d] applying ownership & permissions fixes...
[fix-attrs.d] done.
[cont-init.d] executing container initialization scripts...
[cont-init.d] 01-piaware2influx: executing... 
[cont-init.d] 01-piaware2influx: exited 0.
[cont-init.d] done.
[services.d] starting services
[services.d] done.
[telegraf] 2020-11-23T18:25:41Z I! Starting Telegraf 1.16.2
[telegraf] 2020-11-23T18:25:41Z I! Loaded inputs: influxdb_listener
[telegraf] 2020-11-23T18:25:41Z I! Loaded aggregators: 
[telegraf] 2020-11-23T18:25:41Z I! Loaded processors: 
[telegraf] 2020-11-23T18:25:41Z I! Loaded outputs: influxdb
[telegraf] 2020-11-23T18:25:41Z I! Tags enabled: 
[telegraf] 2020-11-23T18:25:41Z I! [agent] Config: Interval:10s, Quiet:false, Hostname:"", Flush Interval:10s
[telegraf] 2020-11-23T18:25:41Z D! [agent] Initializing plugins
[telegraf] 2020-11-23T18:25:41Z D! [agent] Connecting outputs
[telegraf] 2020-11-23T18:25:41Z D! [agent] Attempting connection to [outputs.influxdb]
[telegraf] 2020-11-23T18:25:42Z W! [outputs.influxdb] When writing to [http://REDACTED:8086]: database "piaware" creation failed: 403 Forbidden
[telegraf] 2020-11-23T18:25:42Z D! [agent] Successfully connected to outputs.influxdb
[telegraf] 2020-11-23T18:25:42Z D! [agent] Starting service inputs
[telegraf] 2020-11-23T18:25:42Z I! [inputs.influxdb_listener] Started HTTP listener service on :8186
[piaware2influx] Namespace(dump1090_port='30003', dump1090_server='dump1090', telegraf_url='http://127.0.0.1:8186/write', verbose=False)
[piaware2influx] piaware2influx.py version 2020-06-05
[piaware2influx] 2020-11-23 13:25:42 [RX: 0, TX: 0, V: 0] CONNECT: Connecting to dump1090:30003 to receive dump1090 TCP BaseStation output data
[piaware2influx] 2020-11-23 13:25:42 [RX: 0, TX: 0, V: 0] CONNECT: Could not connect, retrying
[piaware2influx] 2020-11-23 13:25:43 [RX: 0, TX: 0, V: 0] CONNECT: Could not connect, retrying
[piaware2influx] 2020-11-23 13:25:44 [RX: 0, TX: 0, V: 0] CONNECT: Connected OK, receiving data
[piaware2influx] 2020-11-23 13:25:48 [RX: 1, TX: 0, V: 1] [Ident: A7C849] Now receiving from this vessel
[piaware2influx] 2020-11-23 13:25:48 [RX: 4, TX: 1, V: 2] [Ident: A18DE7] Now receiving from this vessel
[piaware2influx] 2020-11-23 13:25:48 [RX: 12, TX: 2, V: 3] [Ident: A34F53] Now receiving from this vessel
...
[piaware2influx] 2020-11-23 13:26:22 [RX: 5597, TX: 3603, V: 82] [Ident: A997AA] Now receiving from this vessel
[piaware2influx] 2020-11-23 13:26:26 [RX: 6251, TX: 4004, V: 83] [Ident: ADE6F5] Now receiving from this vessel
[telegraf] 2020-11-23T18:26:31Z D! [outputs.influxdb] Wrote batch of 1000 metrics in 39.706893ms
[telegraf] 2020-11-23T18:26:31Z D! [outputs.influxdb] Buffer fullness: 3 / 10000 metrics
[telegraf] 2020-11-23T18:26:32Z D! [outputs.influxdb] Wrote batch of 26 metrics in 9.237822ms
[telegraf] 2020-11-23T18:26:32Z D! [outputs.influxdb] Buffer fullness: 1 / 10000 metrics
[piaware2influx] 2020-11-23 13:26:32 [RX: 7358, TX: 4660, V: 84] [Ident: ADFDBA] Now receiving from this vessel
[piaware2influx] 2020-11-23 13:26:32 [RX: 7387, TX: 4678, V: 85] [Ident: AB5DB8] Now receiving from this vessel
[piaware2influx] 2020-11-23 13:26:39 [RX: 8656, TX: 5411, V: 86] [Ident: ADFE87] Now receiving from this vessel
[telegraf] 2020-11-23T18:26:41Z D! [outputs.influxdb] Wrote batch of 1000 metrics in 43.548168ms
[telegraf] 2020-11-23T18:26:41Z D! [outputs.influxdb] Buffer fullness: 4 / 10000 metrics
[telegraf] 2020-11-23T18:26:42Z D! [outputs.influxdb] Wrote batch of 10 metrics in 12.081038ms
[telegraf] 2020-11-23T18:26:42Z D! [outputs.influxdb] Buffer fullness: 0 / 10000 metrics
[telegraf] 2020-11-23T18:26:52Z D! [outputs.influxdb] Wrote batch of 584 metrics in 41.284684ms
[telegraf] 2020-11-23T18:26:52Z D! [outputs.influxdb] Buffer fullness: 0 / 10000 metrics
[telegraf] 2020-11-23T18:27:02Z D! [outputs.influxdb] Buffer fullness: 0 / 10000 metrics
[telegraf] 2020-11-23T18:27:12Z D! [outputs.influxdb] Buffer fullness: 0 / 10000 metrics
[telegraf] 2020-11-23T18:27:22Z D! [outputs.influxdb] Buffer fullness: 0 / 10000 metrics
[telegraf] 2020-11-23T18:27:32Z D! [outputs.influxdb] Buffer fullness: 0 / 10000 metrics
[telegraf] 2020-11-23T18:27:42Z D! [outputs.influxdb] Buffer fullness: 0 / 10000 metrics

Note that I'm running the FlightAware version of dump1090 on the other end. There is no sign from dump1090's console output that anything is wrong, nor does it stop reporting to the adsbx container or the other feed services. Restarting piaware2influx makes it start working again, albeit for a pretty short time. I will continue debugging as I have time.

[courtarro]

End of logs with VERBOSE_LOGGING turned on:

[piaware2influx] 2020-11-23 13:51:03 [RX: 5528, TX: 3226, V: 93] ========== START PROCESSING MESSAGE ==========
[piaware2influx] 2020-11-23 13:51:03 [RX: 5528, TX: 3226, V: 93] <is_message_valid> Message is valid
[piaware2influx] 2020-11-23 13:51:03 [RX: 5528, TX: 3226, V: 93] <process_message> Message contents: '['MSG', '3', '333', '109', 'A6A748', '209', '2020/11/23', '13:50:37.071', '2020/11/23', '13:50:37.071', '', '22000', '', '', '33.28317', '-83.96626', '', '', '0', '0', '0', '0']'
[piaware2influx] 2020-11-23 13:51:03 [RX: 5528, TX: 3226, V: 93] <datetime_msg_generated> Datetime '2020-11-23 13:50:37.071000-05:00' generated from string '2020/11/23T13:50:37.071'.
[piaware2influx] 2020-11-23 13:51:03 [RX: 5528, TX: 3226, V: 93] <update_vessel_in_db> Updating lastseen for 'A6A748' to '2020-11-23 13:50:37.071000-05:00'
[piaware2influx] 2020-11-23 13:51:03 [RX: 5528, TX: 3226, V: 93] <process_message> Message type 3, will process.
[piaware2influx] 2020-11-23 13:51:03 [RX: 5528, TX: 3226, V: 93] [Ident: A6A748 Callsign: N528GM] Alt: 22000, Lat: 33.28317, Long: -83.96626
[piaware2influx] 2020-11-23 13:51:03 [RX: 5528, TX: 3226, V: 93] <send_data> Data to send: '[{'current_altitude': '22000', 'current_latitude': '33.28317', 'current_longitude': '-83.96626', 'datetime': datetime.datetime(2020, 11, 23, 13, 50, 37, 71000, tzinfo=tzfile('/usr/share/zoneinfo/America/New_York'))}]'
[piaware2influx] 2020-11-23 13:51:03 [RX: 5528, TX: 3226, V: 93] <send_data> Callsign / Squawk: ''N528GM''/''3772''
[piaware2influx] 2020-11-23 13:51:03 [RX: 5528, TX: 3226, V: 93] <prepare_line_protocol> Line protocol 'piaware,hexident=A6A748,callsign=N528GM,squawk=3772 current_altitude=22000,current_latitude=33.28317,current_longitude=-83.96626 1606157437071000064', is valid: 'True'
[piaware2influx] 2020-11-23 13:51:03 [RX: 5528, TX: 3226, V: 93] Sending line protocol: ''piaware,hexident=A6A748,callsign=N528GM,squawk=3772 current_altitude=22000,current_latitude=33.28317,current_longitude=-83.96626 1606157437071000064''
[piaware2influx] 2020-11-23 13:51:03 [RX: 5528, TX: 3227, V: 93] ========== FINISH PROCESSING MESSAGE ==========
[piaware2influx] 2020-11-23 13:51:03 [RX: 5529, TX: 3227, V: 93] ========== START PROCESSING MESSAGE ==========
[piaware2influx] 2020-11-23 13:51:03 [RX: 5529, TX: 3227, V: 93] <is_message_valid> Message is valid
[piaware2influx] 2020-11-23 13:51:03 [RX: 5529, TX: 3227, V: 93] <process_message> Message contents: '['MSG', '6', '333', '137', 'A6AEB4', '237', '2020/11/23', '13:50:37.071', '2020/11/23', '13:50:37.071', '', '17200', '', '', '', '', '', '5156', '0', '0', '0', '0']'
[piaware2influx] 2020-11-23 13:51:03 [RX: 5529, TX: 3227, V: 93] <datetime_msg_generated> Datetime '2020-11-23 13:50:37.071000-05:00' generated from string '2020/11/23T13:50:37.071'.
[piaware2influx] 2020-11-23 13:51:03 [RX: 5529, TX: 3227, V: 93] <update_vessel_in_db> Updating lastseen for 'A6AEB4' to '2020-11-23 13:50:37.071000-05:00'
[piaware2influx] 2020-11-23 13:51:03 [RX: 5529, TX: 3227, V: 93] <process_message> Message type 6, will process.
[piaware2influx] 2020-11-23 13:51:03 [RX: 5529, TX: 3227, V: 93] [Ident: A6AEB4 Callsign: N53GK] Alt: 17200
[piaware2influx] 2020-11-23 13:51:03 [RX: 5529, TX: 3227, V: 93] <send_data> Data to send: '[{'current_altitude': '17200', 'datetime': datetime.datetime(2020, 11, 23, 13, 50, 37, 71000, tzinfo=tzfile('/usr/share/zoneinfo/America/New_York'))}]'
[piaware2influx] 2020-11-23 13:51:03 [RX: 5529, TX: 3227, V: 93] <send_data> Callsign / Squawk: ''N53GK''/''5156''
[piaware2influx] 2020-11-23 13:51:03 [RX: 5529, TX: 3227, V: 93] <prepare_line_protocol> Line protocol 'piaware,hexident=A6AEB4,callsign=N53GK,squawk=5156 current_altitude=17200 1606157437071000064', is valid: 'True'
[piaware2influx] 2020-11-23 13:51:03 [RX: 5529, TX: 3227, V: 93] Sending line protocol: ''piaware,hexident=A6AEB4,callsign=N53GK,squawk=5156 current_altitude=17200 1606157437071000064''
[piaware2influx] 2020-11-23 13:51:03 [RX: 5529, TX: 3228, V: 93] ========== FINISH PROCESSING MESSAGE ==========
[telegraf] 2020-11-23T18:51:07Z D! [outputs.influxdb] Wrote batch of 456 metrics in 48.760029ms
[telegraf] 2020-11-23T18:51:07Z D! [outputs.influxdb] Buffer fullness: 0 / 10000 metrics
[telegraf] 2020-11-23T18:51:17Z D! [outputs.influxdb] Buffer fullness: 0 / 10000 metrics
[telegraf] 2020-11-23T18:51:27Z D! [outputs.influxdb] Buffer fullness: 0 / 10000 metrics

[courtarro]

What's happening is that the s.recv(1024) call is timing out. I'm at a site with extremely high aircraft activity with a good antenna setup, and the CPU usage by piaware2influx.py is maxing out a core. My current theory is that it gets behind in requesting data from the socket and dump1090 stops sending to the socket after it times out once.

[mikenye]

Hi @courtarro, yes, this script is pretty inefficient. This is mostly due to:

• The script processing every single ADS-B message it receives
• The script is written in Python (and not a compiled language like C)

For your purposes, I'd recommend abandoning this, and instead using mikenye/adsb-to-influxdb. This uses readsb to collect the data and perform state management, then send a digest through to readsb every 5 seconds (tweakable) via telegraf.

You should find that mikenye/adsb-to-influxdb uses significantly less CPU and performs much better.

[courtarro]

I saw the other one, and I'm interested, but I also like the idea of logging every single message. Once I get a look at the disk usage by InfluxDB, I'll reevaluate. On the plus side, the threading change in the pull request has helped so far. I'll leave it running tonight and see if it can avoid the timeout problem.

[mikenye]

I really like the work you've done in the PR and I've approved it (images just finished building and are now in docker hub).

I was thinking another future enhancement may be to set a high watermark on the python script's "buffer" thread (similar to how Telegraf has a default limit of 10,000) to prevent it consuming too much memory, and perhaps dropping the oldest items in the buffer if this happens...

Let me know how you fare.

[courtarro]

We made it further but when the aircraft traffic picked up again this morning, the script conked out again. Interestingly, while the data feed cut off at 8:48am, the Telegraf instance continued writing data to Influx for nearly an hour afterward. So it's possible that the wifi bandwidth between my RPi and my InfluxDB server is insufficient to keep up with the traffic and when the write queue gets backed up enough, the read buffer still overflows.

In any case, I think my particular setup can't handle this approach, so I'm going to switch to your other tool that's less CPU and bandwidth intensive. Still, I'm curious how to make this script deal with the problem more gracefully.

[mikenye]

Thanks for the information. I wonder if we could move to a concept of listeners/workers, then we could take advantage of multiprocessing... Ultimately though if your InfluxDB can’t keep up, I think the only solution would be to downsample the data...

[courtarro]

Closing since I'm no longer dealing with this issue.