Errors for an hour on dump1090-fa

foxhunter · November 16, 2020, 6:29pm

Today i’ve seen that one of my feeders had issues with dump1090-fa instance.
The graph showed an hour of no data:

CPU load was higher during that time, but it was not from ADS-B:

At the time where the drop started, the syslog is full of entries like these:

Nov 16 10:20:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_dbfs-quart1; value time = 1605518305.500; last cache update = 1605518305.500;
Nov 16 10:20:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_dbfs-median; value time = 1605518305.500; last cache update = 1605518305.500;
Nov 16 10:20:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_dbfs-quart3; value time = 1605518305.500; last cache update = 1605518305.500;
Nov 16 10:20:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_dbfs-peak_signal; value time = 1605518305.500; last cache update = 1605518305.500;
Nov 16 10:20:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_dbfs-min_signal; value time = 1605518305.500; last cache update = 1605518305.500;

This was running until 59 Minutes later:

Nov 16 11:19:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_range-quart1; value time = 1605518305.500; last cache update = 1605518305.500;
Nov 16 11:19:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_range-median; value time = 1605518305.500; last cache update = 1605518305.500;
Nov 16 11:19:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_range-quart3; value time = 1605518305.500; last cache update = 1605518305.500;
Nov 16 11:19:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_range-minimum; value time = 1605518305.500; last cache update = 1605518305.500;
Nov 16 11:19:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_range-max_range; value time = 1605518305.500; last cache update = 1605518305.500;
Nov 16 11:19:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_aircraft-recent; value time = 1605518305.500; last cache update = 1605518305.500;

At 11:20 the process obviously restarted again. Since then it works without further issues.

> Nov 16 11:20:32 Raspi3 systemd[1]: dump1090-fa.service: State 'stop-sigterm' timed out. Killing.
> Nov 16 11:20:32 Raspi3 systemd[1]: dump1090-fa.service: Killing process 786 (dump1090-fa) with signal SIGKILL.
> Nov 16 11:20:32 Raspi3 systemd[1]: dump1090-fa.service: Main process exited, code=killed, status=9/KILL
> Nov 16 11:20:32 Raspi3 systemd[1]: dump1090-fa.service: Failed with result 'timeout'.
> Nov 16 11:20:32 Raspi3 systemd[1]: Stopped dump1090 ADS-B receiver (FlightAware customization).
> Nov 16 11:20:32 Raspi3 systemd[1]: Started dump1090 ADS-B receiver (FlightAware customization).
> Nov 16 11:20:32 Raspi3 dump1090-fa[19638]: Mon Nov 16 11:20:32 2020 CET  dump1090-fa 4.0 starting up.
> Nov 16 11:20:33 Raspi3 dump1090-fa[19638]: rtlsdr: using device #0: Generic RTL2832U (Realtek, RTL2832U, SN 00001000)
> Nov 16 11:20:33 Raspi3 dump1090-fa[19638]: Detached kernel driver
> Nov 16 11:20:33 Raspi3 kernel: [1990614.340991] r820t 12-001a: destroying instance
> Nov 16 11:20:33 Raspi3 kernel: [1990614.341451] dvb_usb_v2: 'Realtek RTL2832U reference design:1-1.3' successfully deinitialized and disconnected
> Nov 16 11:20:33 Raspi3 dump1090-fa[19638]: Found Rafael Micro R820T tuner
> Nov 16 11:20:33 Raspi3 dump1090-fa[19638]: rtlsdr: tuner gain set to 48.0 dB
> Nov 16 11:20:33 Raspi3 tar1090[785]: /usr/local/share/tar1090/tar1090.sh: line 104: /run/dump1090-fa/aircraft.json: No such file or directory
> Nov 16 11:20:33 Raspi3 tar1090[785]: No aircraft.json found in /run/dump1090-fa! Try restarting dump1090 or reinstalling tar1090 if you switched dump1090 to readsb!

Any ideas what caused this?
The device itself is running all the time meanwhile since 28 days and i did not touch it during the time

obj · November 17, 2020, 4:37am

You cut off the interesting bit of the logs immediately before the restart, but my guess would be that the hardware got stuck and piaware restarted dump1090-fa after some time with no data seen.

foxhunter · November 17, 2020, 7:16am

If interested i could provide more details of course
Interesting is that it was exactly one hour.

What does the errors from collectd mean?

obj · November 17, 2020, 7:28am

If you have dump1090 logs from before the restart happened, up to the restart, they are useful.

github.com

flightaware/piaware/blob/515841346eb6783d1bf9553675aef988fe64748b/programs/piaware/config.tcl#L17


      
          # server name is defined and can be overridden in the Itcl class library
          # that handles connections
          
          set serverRetryIntervalSeconds 60
          
          set piawareVersion 4.0
          set piawareVersionFull 4.0
          
          # how many seconds with no messages received from the ADS-B receiver before
          # we will attempt to restart dump1090
          set noMessageActionIntervalSeconds 3600
          
          # perform ADS-B traffic check and report every this-many-seconds
          set adsbTrafficCheckIntervalSeconds 300
          
          # send health information every this many seconds
          set sendHealthInformationIntervalSeconds 300
          
          # number of seconds that no ADS-B producer program (usually) is found running
          # for before we will attempt to start it
          set adsbNoProducerStartDelaySeconds 360

The stats files contain a timestamp that collectd uses, and the timestamp was not advancing.

foxhunter · November 17, 2020, 8:07am

Here we go, filtered on “dump1090”. Before 11:18:54 the entries for dump1090 where the same as in my initial post

Nov 16 11:18:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_cpu-reader; value time = 1605518274.700; last cache update = 1605518274.700;
Nov 16 11:19:02 Raspi3 dump1090-fa[786]: Mon Nov 16 11:19:02 2020 CET  Caught SIGTERM, shutting down..
Nov 16 11:19:02 Raspi3 systemd[1]: Stopping dump1090 ADS-B receiver (FlightAware customization)...
Nov 16 11:19:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_dbfs-noise; value time = 1605518274.700; last cache update = 1605518274.700;
Nov 16 11:19:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_dbfs-quart1; value time = 1605518305.500; last cache update = 1605518305.500;
Nov 16 11:19:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_dbfs-median; value time = 1605518305.500; last cache update = 1605518305.500;
Nov 16 11:19:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_dbfs-quart3; value time = 1605518305.500; last cache update = 1605518305.500;
Nov 16 11:19:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_dbfs-peak_signal; value time = 1605518305.500; last cache update = 1605518305.500;
Nov 16 11:19:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_dbfs-min_signal; value time = 1605518305.500; last cache update = 1605518305.500;
Nov 16 11:19:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_range-quart1; value time = 1605518305.500; last cache update = 1605518305.500;
Nov 16 11:19:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_range-median; value time = 1605518305.500; last cache update = 1605518305.500;
Nov 16 11:19:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_range-quart3; value time = 1605518305.500; last cache update = 1605518305.500;
Nov 16 11:19:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_range-minimum; value time = 1605518305.500; last cache update = 1605518305.500;
Nov 16 11:19:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_range-max_range; value time = 1605518305.500; last cache update = 1605518305.500;
Nov 16 11:19:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_aircraft-recent; value time = 1605518305.500; last cache update = 1605518305.500;
Nov 16 11:19:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_mlat-recent; value time = 1605518305.500; last cache update = 1605518305.500;
Nov 16 11:19:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_tisb-recent; value time = 1605518305.500; last cache update = 1605518305.500;
Nov 16 11:19:54 Raspi3 collectd[841]: uc_update: Value too old: name = localhost/dump1090-localhost/dump1090_gps-recent; value time = 1605518305.500; last cache update = 1605518305.500;
Nov 16 11:20:32 Raspi3 systemd[1]: dump1090-fa.service: State 'stop-sigterm' timed out. Killing.
Nov 16 11:20:32 Raspi3 systemd[1]: dump1090-fa.service: Killing process 786 (dump1090-fa) with signal SIGKILL.
Nov 16 11:20:32 Raspi3 systemd[1]: dump1090-fa.service: Main process exited, code=killed, status=9/KILL
Nov 16 11:20:32 Raspi3 systemd[1]: dump1090-fa.service: Failed with result 'timeout'.
Nov 16 11:20:32 Raspi3 systemd[1]: Stopped dump1090 ADS-B receiver (FlightAware customization).
Nov 16 11:20:32 Raspi3 systemd[1]: Started dump1090 ADS-B receiver (FlightAware customization).
Nov 16 11:20:32 Raspi3 dump1090-fa[19638]: Mon Nov 16 11:20:32 2020 CET  dump1090-fa 4.0 starting up.
Nov 16 11:20:33 Raspi3 dump1090-fa[19638]: rtlsdr: using device #0: Generic RTL2832U (Realtek, RTL2832U, SN 00001000)
Nov 16 11:20:33 Raspi3 dump1090-fa[19638]: Detached kernel driver
Nov 16 11:20:33 Raspi3 dump1090-fa[19638]: Found Rafael Micro R820T tuner
Nov 16 11:20:33 Raspi3 dump1090-fa[19638]: rtlsdr: tuner gain set to 48.0 dB
Nov 16 11:20:33 Raspi3 tar1090[785]: /usr/local/share/tar1090/tar1090.sh: line 104: /run/dump1090-fa/aircraft.json: No such file or directory
Nov 16 11:20:33 Raspi3 tar1090[785]: No aircraft.json found in /run/dump1090-fa! Try restarting dump1090 or reinstalling tar1090 if you switched dump1090 to readsb!

Thanks for explanation where this hour comes from.

wiedehopf · November 17, 2020, 8:54am

That’s not filtered for dump1090, use this command:
Debug commands · wiedehopf/adsb-wiki Wiki · GitHub

foxhunter · November 17, 2020, 9:11am

-- Logs begin at Sun 2020-11-15 01:30:02 CET, end at Tue 2020-11-17 10:11:05 CET. --
Nov 16 11:19:02 Raspi3 dump1090-fa[786]: Mon Nov 16 11:19:02 2020 CET  Caught SIGTERM, shutting down..
Nov 16 11:19:02 Raspi3 systemd[1]: Stopping dump1090 ADS-B receiver (FlightAware customization)...
Nov 16 11:20:32 Raspi3 systemd[1]: dump1090-fa.service: State 'stop-sigterm' timed out. Killing.
Nov 16 11:20:32 Raspi3 systemd[1]: dump1090-fa.service: Killing process 786 (dump1090-fa) with signal SIGKILL.
Nov 16 11:20:32 Raspi3 systemd[1]: dump1090-fa.service: Main process exited, code=killed, status=9/KILL
Nov 16 11:20:32 Raspi3 systemd[1]: dump1090-fa.service: Failed with result 'timeout'.
Nov 16 11:20:32 Raspi3 systemd[1]: Stopped dump1090 ADS-B receiver (FlightAware customization).
Nov 16 11:20:32 Raspi3 systemd[1]: Started dump1090 ADS-B receiver (FlightAware customization).
Nov 16 11:20:32 Raspi3 dump1090-fa[19638]: Mon Nov 16 11:20:32 2020 CET  dump1090-fa 4.0 starting up.
Nov 16 11:20:33 Raspi3 dump1090-fa[19638]: rtlsdr: using device #0: Generic RTL2832U (Realtek, RTL2832U, SN 00001000)
Nov 16 11:20:33 Raspi3 dump1090-fa[19638]: Detached kernel driver
Nov 16 11:20:33 Raspi3 dump1090-fa[19638]: Found Rafael Micro R820T tuner
Nov 16 11:20:33 Raspi3 dump1090-fa[19638]: rtlsdr: tuner gain set to 48.0 dB

obj · November 17, 2020, 10:46am

Thanks. That implies that the main thread is wedged, which is an unusual failure mode I haven’t seen before. If it happens again it’s probably worth trying to catch in the act to track down further.

(I’m slightly suspicious of the pthread_cond_timedwait error path in fifo_dequeue; there’s conflicting information on how to handle error returns & the resulting state of the mutex; I wonder if we’re hitting the error path and the mutex is unexpectedly locked and then we self-deadlock trying to reacquire it)

foxhunter · November 17, 2020, 10:57am

Whatever i can deliver as data, let me know.
The device is the first one i have built more than a year ago. I’ve never seen such a fault before on that.

obj · November 17, 2020, 12:03pm

I stared at the fifo code for a while and I think I found one path where it could fail and get stuck. It is, literally, a one-in-a-billion chance (which triggers the bug described in this second commit) but that code is called a lot so it’s plausible that it could happen from time to time. (This code is new in 4.0)

Do let me know if you see the failure again, maybe we can get you onto the dev branch code in that case to see if it helps.

foxhunter · November 17, 2020, 12:50pm

Ok, what did i win now?

Sure! But it can take a while. It’s the first time i saw this since 4.0 is installed.

system · November 17, 2021, 12:50pm

This topic was automatically closed 365 days after the last reply. New replies are no longer allowed.

Topic		Replies	Views
FA time anomaly and dump mutability last update off ADS-B Flight Tracking	0	1077	August 23, 2015
Data Feed/Feeder Check-in not updated correctly? ADS-B Flight Tracking	15	4740	June 3, 2015
One hour outage and recovery of Dump1090 ADS-B Flight Tracking	2	2163	October 10, 2015
HELP, dump1090 Stops several times per day... ADS-B Flight Tracking	16	5765	April 11, 2015
Help Problem fetching data from dump1090 ADS-B Flight Tracking	3	1167	September 9, 2019

Errors for an hour on dump1090-fa

Related Topics