Satnogs client keeps running after observation

SatNOGS Software
1

Starting at ~03 UTC today, all observations made by my station failed (no waterfall, nothing). At 18:21:31 UTC the station stopped pulling new observations from the API and started displaying

Your Station is offline. You should make sure it can successfully connect to the Network API.

This is what top looked like when I logged in to check status:

top - 20:35:58 up 11 days, 22:50,  1 user,  load average: 0.49, 0.65, 0.68
Tasks: 131 total,   1 running, 130 sleeping,   0 stopped,   0 zombie
%Cpu(s):  6.7 us,  5.1 sy,  0.0 ni, 86.2 id,  0.0 wa,  0.0 hi,  1.9 si,  0.0 st
MiB Mem :   3906.0 total,   1157.5 free,   2101.6 used,    646.9 buff/cache
MiB Swap:    100.0 total,    100.0 free,      0.0 used.   1559.3 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND
  318 satnogs   20   0  907236 380476  18268 S  24.8   9.5 231:18.03 satnogs-client
  319 hamlib-+  20   0  370660  33308   2884 S  12.9   0.8  79:47.00 rigctld
 1195 satnogs   20   0  389244 121504  52560 S   1.0   3.0   2:12.85 satnogs_cw_deco
 1380 satnogs   20   0  471472 121272  53540 S   1.0   3.0   2:03.86 satnogs_fsk_ax2
 1819 satnogs   20   0  468280 117560  52976 S   1.0   2.9   1:38.80 satnogs_fsk_ax2
 2268 satnogs   20   0  465208 114504  53276 S   1.0   2.9   1:11.62 satnogs_fsk_ax2
 3236 pi        20   0   10324   2944   2512 R   1.0   0.1   0:00.17 top
29089 satnogs   20   0  503092 160292  53396 S   1.0   4.0   8:16.03 satnogs_fsk_ax2
29777 satnogs   20   0  423036 154368  52752 S   1.0   3.9   7:07.94 satnogs_cw_deco
30482 satnogs   20   0  499120 148936  53472 S   1.0   3.7   6:16.35 satnogs_fsk_ax2
30686 satnogs   20   0  498096 146900  53012 S   1.0   3.7   6:04.51 satnogs_fsk_ax2
32202 satnogs   20   0  485688 134212  52916 S   1.0   3.4   4:05.72 satnogs_fsk_ax2
  560 satnogs   20   0  477496 127284  53000 S   0.7   3.2   3:02.15 satnogs_fsk_ax2
  774 satnogs   20   0  393340 125796  52956 S   0.7   3.1   2:43.81 satnogs_cw_deco
 1507 satnogs   20   0  387196 118680  52700 S   0.7   3.0   1:56.14 satnogs_cw_deco
 1659 satnogs   20   0  469304 118692  53252 S   0.7   3.0   1:47.36 satnogs_fsk_ax2
 1935 satnogs   20   0  467376 116924  53144 S   0.7   2.9   1:36.30 satnogs_fsk_ax2
28845 satnogs   20   0  524340 161896  53020 S   0.7   4.0   8:38.01 satnogs_fsk_ax2
30859 satnogs   20   0  454660 146044  53632 S   0.7   3.7   5:43.61 satnogs_bpsk_ax
30994 satnogs   20   0  496048 145232  53396 S   0.7   3.6   5:41.74 satnogs_fsk_ax2
31254 satnogs   20   0  451588 142612  53172 S   0.7   3.6   5:15.83 satnogs_bpsk_ax
31928 satnogs   20   0  445236 136692  53492 S   0.7   3.4   4:18.80 satnogs_bpsk_ax
32375 satnogs   20   0  483760 133376  53292 S   0.7   3.3   3:53.51 satnogs_fsk_ax2
   21 root      20   0       0      0      0 S   0.3   0.0   0:35.42 ksoftirqd/2
    1 root      20   0   33696   7948   6384 S   0.0   0.2   3:38.05 systemd

systemctl status satnogs-client.service showed the following:

● satnogs-client.service - SatNOGS client
   Loaded: loaded (/etc/systemd/system/satnogs-client.service; enabled; vendor preset: enabled)
   Active: active (running) since Sun 2020-04-12 14:00:23 UTC; 1 weeks 6 days ago
 Main PID: 318 (satnogs-client)
    Tasks: 164 (limit: 4915)
   Memory: 2.0G
   CGroup: /system.slice/satnogs-client.service
           ├─  318 /var/lib/satnogs/bin/python3 /var/lib/satnogs/bin/satnogs-client
           ├─  560 /usr/bin/python3 /usr/bin/satnogs_fsk_ax25.py --soapy-rx-device=driver=rtlsdr --samp-rate-rx=2.048e6 --rx-freq=437445000 --file-path=/tmp/.satnogs/data/receiving_satnogs_2096042_2020-04-25T14-53-52.out --waterfall-file-path=/tmp/.satnogs/data/receiving_waterfall_2096042_2020-04-25T14-53-52.dat --baudrate=9600 --rigctl-port=4532 --gain-mode=Overall --gain=48.0 --antenna=RX --enable-iq-dump=1 --iq-file-path=/tmp/.satnogs/iq.raw --decoded-data-file-path=/tmp/.satnogs/data/data_2096042
           ├─  774 /usr/bin/python3 /usr/bin/satnogs_cw_decoder.py --soapy-rx-device=driver=rtlsdr --samp-rate-rx=2.048e6 --rx-freq=437274600 --file-path=/tmp/.satnogs/data/receiving_satnogs_2095697_2020-04-25T15-15-58.out --waterfall-file-path=/tmp/.satnogs/data/receiving_waterfall_2095697_2020-04-25T15-15-58.dat --rigctl-port=4532 --gain-mode=Overall --gain=48.0 --antenna=RX --enable-iq-dump=1 --iq-file-path=/tmp/.satnogs/iq.raw --decoded-data-file-path=/tmp/.satnogs/data/data_2095697
           ├─ 1195 /usr/bin/python3 /usr/bin/satnogs_cw_decoder.py --soapy-rx-device=driver=rtlsdr --samp-rate-rx=2.048e6 --rx-freq=436835820 --file-path=/tmp/.satnogs/data/receiving_satnogs_2096500_2020-04-25T16-15-17.out --waterfall-file-path=/tmp/.satnogs/data/receiving_waterfall_2096500_2020-04-25T16-15-17.dat --rigctl-port=4532 --gain-mode=Overall --gain=48.0 --antenna=RX --enable-iq-dump=1 --iq-file-path=/tmp/.satnogs/iq.raw --decoded-data-file-path=/tmp/.satnogs/data/data_2096500
           ├─ 1380 /usr/bin/python3 /usr/bin/satnogs_fsk_ax25.py --soapy-rx-device=driver=rtlsdr --samp-rate-rx=2.048e6 --rx-freq=437225000 --file-path=/tmp/.satnogs/data/receiving_satnogs_2096574_2020-04-25T16-39-52.out --waterfall-file-path=/tmp/.satnogs/data/receiving_waterfall_2096574_2020-04-25T16-39-52.dat --baudrate=4800 --rigctl-port=4532 --gain-mode=Overall --gain=48.0 --antenna=RX --enable-iq-dump=1 --iq-file-path=/tmp/.satnogs/iq.raw --decoded-data-file-path=/tmp/.satnogs/data/data_2096574
           ├─ 1507 /usr/bin/python3 /usr/bin/satnogs_cw_decoder.py --soapy-rx-device=driver=rtlsdr --samp-rate-rx=2.048e6 --rx-freq=435315700 --file-path=/tmp/.satnogs/data/receiving_satnogs_2096586_2020-04-25T16-52-20.out --waterfall-file-path=/tmp/.satnogs/data/receiving_waterfall_2096586_2020-04-25T16-52-20.dat --rigctl-port=4532 --gain-mode=Overall --gain=48.0 --antenna=RX --enable-iq-dump=1 --iq-file-path=/tmp/.satnogs/iq.raw --decoded-data-file-path=/tmp/.satnogs/data/data_2096586
           ├─ 1659 /usr/bin/python3 /usr/bin/satnogs_fsk_ax25.py --soapy-rx-device=driver=rtlsdr --samp-rate-rx=2.048e6 --rx-freq=438226000 --file-path=/tmp/.satnogs/data/receiving_satnogs_2096600_2020-04-25T17-11-58.out --waterfall-file-path=/tmp/.satnogs/data/receiving_waterfall_2096600_2020-04-25T17-11-58.dat --baudrate=9600 --rigctl-port=4532 --gain-mode=Overall --gain=48.0 --antenna=RX --enable-iq-dump=1 --iq-file-path=/tmp/.satnogs/iq.raw --decoded-data-file-path=/tmp/.satnogs/data/data_2096600
           ├─ 1819 /usr/bin/python3 /usr/bin/satnogs_fsk_ax25.py --soapy-rx-device=driver=rtlsdr --samp-rate-rx=2.048e6 --rx-freq=435925000 --file-path=/tmp/.satnogs/data/receiving_satnogs_2096608_2020-04-25T17-27-05.out --waterfall-file-path=/tmp/.satnogs/data/receiving_waterfall_2096608_2020-04-25T17-27-05.dat --baudrate=9600 --rigctl-port=4532 --gain-mode=Overall --gain=48.0 --antenna=RX --enable-iq-dump=1 --iq-file-path=/tmp/.satnogs/iq.raw --decoded-data-file-path=/tmp/.satnogs/data/data_2096608
           ├─ 1935 /usr/bin/python3 /usr/bin/satnogs_fsk_ax25.py --soapy-rx-device=driver=rtlsdr --samp-rate-rx=2.048e6 --rx-freq=435950000 --file-path=/tmp/.satnogs/data/receiving_satnogs_2096632_2020-04-25T17-36-36.out --waterfall-file-path=/tmp/.satnogs/data/receiving_waterfall_2096632_2020-04-25T17-36-36.dat --baudrate=4800 --rigctl-port=4532 --gain-mode=Overall --gain=48.0 --antenna=RX --enable-iq-dump=1 --iq-file-path=/tmp/.satnogs/iq.raw --decoded-data-file-path=/tmp/.satnogs/data/data_2096632
           ├─ 2268 /usr/bin/python3 /usr/bin/satnogs_fsk_ax25.py --soapy-rx-device=driver=rtlsdr --samp-rate-rx=2.048e6 --rx-freq=437480000 --file-path=/tmp/.satnogs/data/receiving_satnogs_2096648_2020-04-25T18-22-15.out --waterfall-file-path=/tmp/.satnogs/data/receiving_waterfall_2096648_2020-04-25T18-22-15.dat --baudrate=9600 --rigctl-port=4532 --gain-mode=Overall --gain=48.0 --antenna=RX --enable-iq-dump=1 --iq-file-path=/tmp/.satnogs/iq.raw --decoded-data-file-path=/tmp/.satnogs/data/data_2096648
           ├─28845 /usr/bin/python3 /usr/bin/satnogs_fsk_ax25.py --soapy-rx-device=driver=rtlsdr --samp-rate-rx=2.048e6 --rx-freq=437950000 --file-path=/tmp/.satnogs/data/receiving_satnogs_2093915_2020-04-25T05-53-52.out --waterfall-file-path=/tmp/.satnogs/data/receiving_waterfall_2093915_2020-04-25T05-53-52.dat --baudrate=9600 --rigctl-port=4532 --gain-mode=Overall --gain=48.0 --antenna=RX --enable-iq-dump=1 --iq-file-path=/tmp/.satnogs/iq.raw --decoded-data-file-path=/tmp/.satnogs/data/data_2093915
           ├─29089 /usr/bin/python3 /usr/bin/satnogs_fsk_ax25.py --soapy-rx-device=driver=rtlsdr --samp-rate-rx=2.048e6 --rx-freq=437421500 --file-path=/tmp/.satnogs/data/receiving_satnogs_2093514_2020-04-25T06-20-30.out --waterfall-file-path=/tmp/.satnogs/data/receiving_waterfall_2093514_2020-04-25T06-20-30.dat --baudrate=9600 --rigctl-port=4532 --gain-mode=Overall --gain=48.0 --antenna=RX --enable-iq-dump=1 --iq-file-path=/tmp/.satnogs/iq.raw --decoded-data-file-path=/tmp/.satnogs/data/data_2093514
           ├─29777 /usr/bin/python3 /usr/bin/satnogs_cw_decoder.py --soapy-rx-device=driver=rtlsdr --samp-rate-rx=2.048e6 --rx-freq=437505000 --file-path=/tmp/.satnogs/data/receiving_satnogs_2094633_2020-04-25T07-42-26.out --waterfall-file-path=/tmp/.satnogs/data/receiving_waterfall_2094633_2020-04-25T07-42-26.dat --rigctl-port=4532 --gain-mode=Overall --gain=48.0 --antenna=RX --enable-iq-dump=1 --iq-file-path=/tmp/.satnogs/iq.raw --decoded-data-file-path=/tmp/.satnogs/data/data_2094633
           ├─30482 /usr/bin/python3 /usr/bin/satnogs_fsk_ax25.py --soapy-rx-device=driver=rtlsdr --samp-rate-rx=2.048e6 --rx-freq=435950000 --file-path=/tmp/.satnogs/data/receiving_satnogs_2094973_2020-04-25T09-24-23.out --waterfall-file-path=/tmp/.satnogs/data/receiving_waterfall_2094973_2020-04-25T09-24-23.dat --baudrate=4800 --rigctl-port=4532 --gain-mode=Overall --gain=48.0 --antenna=RX --enable-iq-dump=1 --iq-file-path=/tmp/.satnogs/iq.raw --decoded-data-file-path=/tmp/.satnogs/data/data_2094973
           ├─30686 /usr/bin/python3 /usr/bin/satnogs_fsk_ax25.py --soapy-rx-device=driver=rtlsdr --samp-rate-rx=2.048e6 --rx-freq=435700000 --file-path=/tmp/.satnogs/data/receiving_satnogs_2094233_2020-04-25T09-46-00.out --waterfall-file-path=/tmp/.satnogs/data/receiving_waterfall_2094233_2020-04-25T09-46-00.dat --baudrate=4800 --rigctl-port=4532 --gain-mode=Overall --gain=48.0 --antenna=RX --enable-iq-dump=1 --iq-file-path=/tmp/.satnogs/iq.raw --decoded-data-file-path=/tmp/.satnogs/data/data_2094233
           ├─30859 /usr/bin/python3 /usr/bin/satnogs_bpsk_ax25.py --soapy-rx-device=driver=rtlsdr --samp-rate-rx=2.048e6 --rx-freq=437625000 --file-path=/tmp/.satnogs/data/receiving_satnogs_2095300_2020-04-25T10-08-51.out --waterfall-file-path=/tmp/.satnogs/data/receiving_waterfall_2095300_2020-04-25T10-08-51.dat --baudrate=9600 --rigctl-port=4532 --gain-mode=Overall --gain=48.0 --antenna=RX --enable-iq-dump=1 --iq-file-path=/tmp/.satnogs/iq.raw --decoded-data-file-path=/tmp/.satnogs/data/data_2095300
           ├─30994 /usr/bin/python3 /usr/bin/satnogs_fsk_ax25.py --soapy-rx-device=driver=rtlsdr --samp-rate-rx=2.048e6 --rx-freq=437558325 --file-path=/tmp/.satnogs/data/receiving_satnogs_2095371_2020-04-25T10-21-44.out --waterfall-file-path=/tmp/.satnogs/data/receiving_waterfall_2095371_2020-04-25T10-21-44.dat --baudrate=1200 --rigctl-port=4532 --gain-mode=Overall --gain=48.0 --antenna=RX --enable-iq-dump=1 --iq-file-path=/tmp/.satnogs/iq.raw --decoded-data-file-path=/tmp/.satnogs/data/data_2095371
           ├─31254 /usr/bin/python3 /usr/bin/satnogs_bpsk_ax25.py --soapy-rx-device=driver=rtlsdr --samp-rate-rx=2.048e6 --rx-freq=435840000 --file-path=/tmp/.satnogs/data/receiving_satnogs_2095409_2020-04-25T10-55-13.out --waterfall-file-path=/tmp/.satnogs/data/receiving_waterfall_2095409_2020-04-25T10-55-13.dat --baudrate=9600 --rigctl-port=4532 --gain-mode=Overall --gain=48.0 --antenna=RX --enable-iq-dump=1 --iq-file-path=/tmp/.satnogs/iq.raw --decoded-data-file-path=/tmp/.satnogs/data/data_2095409
           ├─31928 /usr/bin/python3 /usr/bin/satnogs_bpsk_ax25.py --soapy-rx-device=driver=rtlsdr --samp-rate-rx=2.048e6 --rx-freq=437126350 --file-path=/tmp/.satnogs/data/receiving_satnogs_2095138_2020-04-25T12-33-07.out --waterfall-file-path=/tmp/.satnogs/data/receiving_waterfall_2095138_2020-04-25T12-33-07.dat --baudrate=1200 --rigctl-port=4532 --gain-mode=Overall --gain=48.0 --antenna=RX --enable-iq-dump=1 --iq-file-path=/tmp/.satnogs/iq.raw --decoded-data-file-path=/tmp/.satnogs/data/data_2095138
           ├─32202 /usr/bin/python3 /usr/bin/satnogs_fsk_ax25.py --soapy-rx-device=driver=rtlsdr --samp-rate-rx=2.048e6 --rx-freq=437445000 --file-path=/tmp/.satnogs/data/receiving_satnogs_2095142_2020-04-25T13-01-26.out --waterfall-file-path=/tmp/.satnogs/data/receiving_waterfall_2095142_2020-04-25T13-01-26.dat --baudrate=9600 --rigctl-port=4532 --gain-mode=Overall --gain=48.0 --antenna=RX --enable-iq-dump=1 --iq-file-path=/tmp/.satnogs/iq.raw --decoded-data-file-path=/tmp/.satnogs/data/data_2095142
           └─32375 /usr/bin/python3 /usr/bin/satnogs_fsk_ax25.py --soapy-rx-device=driver=rtlsdr --samp-rate-rx=2.048e6 --rx-freq=436250000 --file-path=/tmp/.satnogs/data/receiving_satnogs_2095962_2020-04-25T13-23-36.out --waterfall-file-path=/tmp/.satnogs/data/receiving_waterfall_2095962_2020-04-25T13-23-36.dat --baudrate=4800 --rigctl-port=4532 --gain-mode=Overall --gain=48.0 --antenna=RX --enable-iq-dump=1 --iq-file-path=/tmp/.satnogs/iq.raw --decoded-data-file-path=/tmp/.satnogs/data/data_2095962

Apr 25 20:30:30 satnogs-fhab-1 satnogs-client[318]: apscheduler.scheduler - WARNING - Execution of job "post_data (trigger: interval[0:02:00], next run at: 2020-04-25 20:30:30 UTC)" skipped: maximum number of running instances reached (1)
Apr 25 20:31:30 satnogs-fhab-1 satnogs-client[318]: apscheduler.scheduler - WARNING - Execution of job "get_jobs (trigger: interval[0:01:00], next run at: 2020-04-25 20:31:30 UTC)" skipped: maximum number of running instances reached (1)
Apr 25 20:32:30 satnogs-fhab-1 satnogs-client[318]: apscheduler.scheduler - WARNING - Execution of job "get_jobs (trigger: interval[0:01:00], next run at: 2020-04-25 20:32:30 UTC)" skipped: maximum number of running instances reached (1)
Apr 25 20:32:30 satnogs-fhab-1 satnogs-client[318]: apscheduler.scheduler - WARNING - Execution of job "post_data (trigger: interval[0:02:00], next run at: 2020-04-25 20:32:30 UTC)" skipped: maximum number of running instances reached (1)
Apr 25 20:33:30 satnogs-fhab-1 satnogs-client[318]: apscheduler.scheduler - WARNING - Execution of job "get_jobs (trigger: interval[0:01:00], next run at: 2020-04-25 20:33:30 UTC)" skipped: maximum number of running instances reached (1)
Apr 25 20:34:30 satnogs-fhab-1 satnogs-client[318]: apscheduler.scheduler - WARNING - Execution of job "get_jobs (trigger: interval[0:01:00], next run at: 2020-04-25 20:34:30 UTC)" skipped: maximum number of running instances reached (1)
Apr 25 20:34:30 satnogs-fhab-1 satnogs-client[318]: apscheduler.scheduler - WARNING - Execution of job "post_data (trigger: interval[0:02:00], next run at: 2020-04-25 20:34:30 UTC)" skipped: maximum number of running instances reached (1)
Apr 25 20:35:30 satnogs-fhab-1 satnogs-client[318]: apscheduler.scheduler - WARNING - Execution of job "get_jobs (trigger: interval[0:01:00], next run at: 2020-04-25 20:35:30 UTC)" skipped: maximum number of running instances reached (1)
Apr 25 20:36:30 satnogs-fhab-1 satnogs-client[318]: apscheduler.scheduler - WARNING - Execution of job "get_jobs (trigger: interval[0:01:00], next run at: 2020-04-25 20:36:30 UTC)" skipped: maximum number of running instances reached (1)
Apr 25 20:36:30 satnogs-fhab-1 satnogs-client[318]: apscheduler.scheduler - WARNING - Execution of job "post_data (trigger: interval[0:02:00], next run at: 2020-04-25 20:36:30 UTC)" skipped: maximum number of running instances reached (1)

Support information:

------------[ copy here ]------------
{
    "versions": {
        "satnogs-client": "1.3.1",
        "satnogs-client-ansible": "202004031132",
        "satnogs-flowgraphs": "1.1.1-1",
        "gr-satnogs": "2.1.2-1",
        "gr-soapy": "2.1.2-1",
        "gnuradio": "3.8.1.0~rc1-2",
        "satnogs-config": "0.10.1"
    },
    "state": {
        "is-applied": true,
        "pending-tags": null
    },
    "system": {
        "distribution": {
            "DESCRIPTION": "Raspbian GNU/Linux 10 (buster)",
            "RELEASE": "10",
            "CODENAME": "buster",
            "ID": "Raspbian"
        },
        "pending-updates": true,
        "platform": {
            "system": "Linux",
            "node": "satnogs-fhab-1",
            "release": "4.19.97-v7l+",
            "version": "#1294 SMP Thu Jan 30 13:21:14 GMT 2020",
            "machine": "armv7l",
            "processor": ""
        },
        "memory": {
            "total": 4095750144,
            "available": 3621396480,
            "percent": 11.6,
            "used": 202539008,
            "free": 3086618624,
            "active": 479145984,
            "inactive": 335114240,
            "buffers": 126664704,
            "cached": 679927808,
            "shared": 127479808,
            "slab": 88653824
        },
        "disk": {
            "total": 30142779392,
            "used": 5157044224,
            "free": 23714934784,
            "percent": 17.9
        }
    },
    "configuration": {
        "enable_iq_dump": true,
        "hamlib_utils_rot_enabled": false,
        "iq_dump_filename": "/tmp/.satnogs/iq.raw",
        "satnogs_antenna": "RX",
        "satnogs_api_token": "[redacted]",
        "satnogs_post_observation_script": "/usr/local/bin/satnogs-post {{ID}} {{FREQ}} {{TLE}}",
        "satnogs_rf_gain": 48.0,
        "satnogs_rx_device": "rtlsdr",
        "satnogs_rx_samp_rate": "2.048e6",
        "satnogs_soapy_rx_device": "driver=rtlsdr",
        "satnogs_station_elev": 67,
        "satnogs_station_id": 1272,
        "satnogs_station_lat": 56.82,
        "satnogs_station_lon": 12.89
    }
}
------------[ copy end ]-------------

Shutting down the service took almost 2 minutes (I ran the stop command at 20:37:35):

pi@satnogs-fhab-1:~ $ sudo systemctl stop satnogs-client.service
pi@satnogs-fhab-1:~ $ systemctl status satnogs-client.service
● satnogs-client.service - SatNOGS client
   Loaded: loaded (/etc/systemd/system/satnogs-client.service; enabled; vendor preset: enabled)
   Active: failed (Result: timeout) since Sat 2020-04-25 20:39:06 UTC; 32s ago
  Process: 318 ExecStart=/var/lib/satnogs/bin/satnogs-client (code=killed, signal=TERM)
 Main PID: 318 (code=killed, signal=TERM)

Apr 25 20:39:06 satnogs-fhab-1 systemd[1]: satnogs-client.service: Killing process 774 (satnogs_cw_deco) with signal SIGKILL.
Apr 25 20:39:06 satnogs-fhab-1 systemd[1]: satnogs-client.service: Killing process 1195 (satnogs_cw_deco) with signal SIGKILL.
Apr 25 20:39:06 satnogs-fhab-1 systemd[1]: satnogs-client.service: Killing process 1380 (satnogs_fsk_ax2) with signal SIGKILL.
Apr 25 20:39:06 satnogs-fhab-1 systemd[1]: satnogs-client.service: Killing process 1507 (satnogs_cw_deco) with signal SIGKILL.
Apr 25 20:39:06 satnogs-fhab-1 systemd[1]: satnogs-client.service: Killing process 1659 (satnogs_fsk_ax2) with signal SIGKILL.
Apr 25 20:39:06 satnogs-fhab-1 systemd[1]: satnogs-client.service: Killing process 1819 (satnogs_fsk_ax2) with signal SIGKILL.
Apr 25 20:39:06 satnogs-fhab-1 systemd[1]: satnogs-client.service: Killing process 1935 (satnogs_fsk_ax2) with signal SIGKILL.
Apr 25 20:39:06 satnogs-fhab-1 systemd[1]: satnogs-client.service: Killing process 2268 (satnogs_fsk_ax2) with signal SIGKILL.
Apr 25 20:39:06 satnogs-fhab-1 systemd[1]: satnogs-client.service: Failed with result 'timeout'.
Apr 25 20:39:06 satnogs-fhab-1 systemd[1]: Stopped SatNOGS client.

The only things that look odd in /var/log/syslog are these:

Apr 25 05:39:26 satnogs-fhab-1 satnogs-client[318]: apscheduler.executors.default - WARNING - Run time of job "get_jobs (trigger: interval[0:01:00], next run at: 2020-04-25 05:39:30 UTC)" was missed by 0:00:55.708387
Apr 25 05:39:26 satnogs-fhab-1 satnogs-client[318]: apscheduler.executors.default - WARNING - Run time of job "post_data (trigger: interval[0:02:00], next run at: 2020-04-25 05:40:30 UTC)" was missed by 0:00:55.709994
Apr 25 06:20:32 satnogs-fhab-1 satnogs-client[318]: usb_claim_interface error -6
Apr 25 06:20:32 satnogs-fhab-1 satnogs-client[318]: usb_claim_interface error -6
Apr 25 06:20:32 satnogs-fhab-1 satnogs-client[318]: [INFO] Using format CF32.
Apr 25 07:42:28 satnogs-fhab-1 satnogs-client[318]: usb_claim_interface error -6
Apr 25 07:42:28 satnogs-fhab-1 satnogs-client[318]: usb_claim_interface error -6
Apr 25 07:42:28 satnogs-fhab-1 satnogs-client[318]: [INFO] Using format CF32.
Apr 25 09:24:25 satnogs-fhab-1 satnogs-client[318]: usb_claim_interface error -6
Apr 25 09:24:25 satnogs-fhab-1 satnogs-client[318]: usb_claim_interface error -6
Apr 25 09:24:25 satnogs-fhab-1 satnogs-client[318]: [INFO] Using format CF32.
Apr 25 09:46:02 satnogs-fhab-1 satnogs-client[318]: usb_claim_interface error -6
Apr 25 09:46:02 satnogs-fhab-1 satnogs-client[318]: usb_claim_interface error -6
Apr 25 09:46:02 satnogs-fhab-1 satnogs-client[318]: [INFO] Using format CF32.
<more of the usb_claim errors>
Apr 25 18:22:17 satnogs-fhab-1 satnogs-client[318]: usb_claim_interface error -6
Apr 25 18:22:17 satnogs-fhab-1 satnogs-client[318]: usb_claim_interface error -6
Apr 25 18:22:17 satnogs-fhab-1 satnogs-client[318]: [INFO] Using format CF32.
Apr 25 18:23:30 satnogs-fhab-1 satnogs-client[318]: apscheduler.scheduler - WARNING - Execution of job "get_jobs (trigger: interval[0:01:00], next run at: 2020-04-25 18:23:30 UTC)" skipped: maximum number of running instances reached (1)
Apr 25 18:24:02 satnogs-fhab-1 CRON[2313]: (pi) CMD (~/upnp.sh)
Apr 25 18:24:02 satnogs-fhab-1 CRON[2309]: (CRON) info (No MTA installed, discarding output)
Apr 25 18:24:30 satnogs-fhab-1 satnogs-client[318]: apscheduler.scheduler - WARNING - Execution of job "get_jobs (trigger: interval[0:01:00], next run at: 2020-04-25 18:24:30 UTC)" skipped: maximum number of running instances reached (1)
Apr 25 18:24:30 satnogs-fhab-1 satnogs-client[318]: apscheduler.scheduler - WARNING - Execution of job "post_data (trigger: interval[0:02:00], next run at: 2020-04-25 18:24:30 UTC)" skipped: maximum number of running instances reached (1)
Apr 25 18:25:01 satnogs-fhab-1 CRON[2328]: (pi) CMD (~/duckdns/duck.sh >/dev/null 2>&1)
Apr 25 18:25:30 satnogs-fhab-1 satnogs-client[318]: apscheduler.scheduler - WARNING - Execution of job "get_jobs (trigger: interval[0:01:00], next run at: 2020-04-25 18:25:30 UTC)" skipped: maximum number of running instances reached (1)
Apr 25 18:26:30 satnogs-fhab-1 satnogs-client[318]: apscheduler.scheduler - WARNING - Execution of job "get_jobs (trigger: interval[0:01:00], next run at: 2020-04-25 18:26:30 UTC)" skipped: maximum number of running instances reached (1)
Apr 25 18:26:30 satnogs-fhab-1 satnogs-client[318]: apscheduler.scheduler - WARNING - Execution of job "post_data (trigger: interval[0:02:00], next run at: 2020-04-25 18:26:30 UTC)" skipped: maximum number of running instances reached (1)
Apr 25 18:27:30 satnogs-fhab-1 satnogs-client[318]: apscheduler.scheduler - WARNING - Execution of job "get_jobs (trigger: interval[0:01:00], next run at: 2020-04-25 18:27:30 UTC)" skipped: maximum number of running instances reached (1)
Apr 25 18:28:30 satnogs-fhab-1 satnogs-client[318]: apscheduler.scheduler - WARNING - Execution of job "get_jobs (trigger: interval[0:01:00], next run at: 2020-04-25 18:28:30 UTC)" skipped: maximum number of running instances reached (1)
Apr 25 18:28:30 satnogs-fhab-1 satnogs-client[318]: apscheduler.scheduler - WARNING - Execution of job "post_data (trigger: interval[0:02:00], next run at: 2020-04-25 18:28:30 UTC)" skipped: maximum number of running instances reached (1)
Apr 25 18:29:30 satnogs-fhab-1 satnogs-client[318]: apscheduler.scheduler - WARNING - Execution of job "get_jobs (trigger: interval[0:01:00], next run at: 2020-04-25 18:29:30 UTC)" skipped: maximum number of running instances reached (1)

After starting the service again, the station came up online according to the dashboard.
Any idea what went wrong? Anything I can do to prevent this from happening again, or at least recover quicker?

2

Update: my station is still online, and performing observations, but uploads no data.

3

The first line in my post observation script logs to a file. That file has not been updated since the problems started, so it seems like the satnogs client never reaches the point where it starts the post observation script:

pi@satnogs-fhab-1:~ $ ls -la /tmp/satnogs-log
-rw-r--r-- 1 satnogs satnogs 97048 Apr 25 05:27 /tmp/satnogs-log

The data directory contains a lot of files:

pi@satnogs-fhab-1:~ $ ls -la /tmp/.satnogs/data/
total 124
drwxr-xr-x 3 satnogs satnogs 1300 Apr 26 06:03 .
drwxrwxrwt 3 root    root     120 Apr 25 05:53 ..
drwxr-xr-x 2 satnogs satnogs   40 Apr 12 14:00 incomplete
-rw-r--r-- 1 satnogs satnogs 4096 Apr 25 06:20 receiving_satnogs_2093514_2020-04-25T06-20-30.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 25 05:53 receiving_satnogs_2093915_2020-04-25T05-53-52.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 25 09:46 receiving_satnogs_2094233_2020-04-25T09-46-00.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 25 07:42 receiving_satnogs_2094633_2020-04-25T07-42-26.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 25 09:24 receiving_satnogs_2094973_2020-04-25T09-24-23.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 25 12:33 receiving_satnogs_2095138_2020-04-25T12-33-07.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 25 13:01 receiving_satnogs_2095142_2020-04-25T13-01-26.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 25 10:08 receiving_satnogs_2095300_2020-04-25T10-08-51.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 25 10:21 receiving_satnogs_2095371_2020-04-25T10-21-44.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 25 10:55 receiving_satnogs_2095409_2020-04-25T10-55-13.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 25 15:16 receiving_satnogs_2095697_2020-04-25T15-15-58.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 25 13:23 receiving_satnogs_2095962_2020-04-25T13-23-36.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 25 14:53 receiving_satnogs_2096042_2020-04-25T14-53-52.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 25 16:15 receiving_satnogs_2096500_2020-04-25T16-15-17.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 25 16:39 receiving_satnogs_2096574_2020-04-25T16-39-52.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 25 16:52 receiving_satnogs_2096586_2020-04-25T16-52-20.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 25 17:12 receiving_satnogs_2096600_2020-04-25T17-11-58.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 25 17:27 receiving_satnogs_2096608_2020-04-25T17-27-05.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 25 17:36 receiving_satnogs_2096632_2020-04-25T17-36-36.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 25 18:22 receiving_satnogs_2096648_2020-04-25T18-22-15.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 25 21:23 receiving_satnogs_2097334_2020-04-25T21-22-58.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 25 23:20 receiving_satnogs_2097951_2020-04-25T23-20-52.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 26 01:57 receiving_satnogs_2098327_2020-04-26T01-56-59.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 26 02:15 receiving_satnogs_2098329_2020-04-26T02-15-29.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 26 02:54 receiving_satnogs_2098331_2020-04-26T02-54-52.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 26 03:59 receiving_satnogs_2098333_2020-04-26T03-59-40.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 26 05:02 receiving_satnogs_2099103_2020-04-26T05-02-33.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 26 05:11 receiving_satnogs_2099104_2020-04-26T05-11-33.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 26 05:50 receiving_satnogs_2099106_2020-04-26T05-50-40.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 26 06:03 receiving_satnogs_2099107_2020-04-26T06-03-53.out
-rw-r--r-- 1 satnogs satnogs 4096 Apr 26 04:50 receiving_satnogs_2099546_2020-04-26T04-50-14.out
-rw-r--r-- 1 satnogs satnogs    0 Apr 25 06:20 receiving_waterfall_2093514_2020-04-25T06-20-30.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 25 05:53 receiving_waterfall_2093915_2020-04-25T05-53-52.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 25 09:46 receiving_waterfall_2094233_2020-04-25T09-46-00.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 25 07:42 receiving_waterfall_2094633_2020-04-25T07-42-26.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 25 09:24 receiving_waterfall_2094973_2020-04-25T09-24-23.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 25 12:33 receiving_waterfall_2095138_2020-04-25T12-33-07.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 25 13:01 receiving_waterfall_2095142_2020-04-25T13-01-26.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 25 10:08 receiving_waterfall_2095300_2020-04-25T10-08-51.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 25 10:21 receiving_waterfall_2095371_2020-04-25T10-21-44.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 25 10:55 receiving_waterfall_2095409_2020-04-25T10-55-13.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 25 15:16 receiving_waterfall_2095697_2020-04-25T15-15-58.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 25 13:23 receiving_waterfall_2095962_2020-04-25T13-23-36.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 25 14:53 receiving_waterfall_2096042_2020-04-25T14-53-52.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 25 16:15 receiving_waterfall_2096500_2020-04-25T16-15-17.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 25 16:39 receiving_waterfall_2096574_2020-04-25T16-39-52.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 25 16:52 receiving_waterfall_2096586_2020-04-25T16-52-20.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 25 17:12 receiving_waterfall_2096600_2020-04-25T17-11-58.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 25 17:27 receiving_waterfall_2096608_2020-04-25T17-27-05.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 25 17:36 receiving_waterfall_2096632_2020-04-25T17-36-36.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 25 18:22 receiving_waterfall_2096648_2020-04-25T18-22-15.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 25 21:23 receiving_waterfall_2097334_2020-04-25T21-22-58.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 25 23:20 receiving_waterfall_2097951_2020-04-25T23-20-52.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 26 01:57 receiving_waterfall_2098327_2020-04-26T01-56-59.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 26 02:15 receiving_waterfall_2098329_2020-04-26T02-15-29.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 26 02:54 receiving_waterfall_2098331_2020-04-26T02-54-52.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 26 03:59 receiving_waterfall_2098333_2020-04-26T03-59-40.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 26 05:02 receiving_waterfall_2099103_2020-04-26T05-02-33.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 26 05:11 receiving_waterfall_2099104_2020-04-26T05-11-33.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 26 05:50 receiving_waterfall_2099106_2020-04-26T05-50-40.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 26 06:03 receiving_waterfall_2099107_2020-04-26T06-03-53.dat
-rw-r--r-- 1 satnogs satnogs    0 Apr 26 04:50 receiving_waterfall_2099546_2020-04-26T04-50-14.dat

rtl_test seems to fail:

pi@satnogs-fhab-1:~ $ rtl_test
Found 1 device(s):
  0:  Realtek, RTL2838UHIDIR, SN: 00000001

Using device 0: Generic RTL2832U OEM
Found Rafael Micro R820T tuner
Supported gain values (29): 0.0 0.9 1.4 2.7 3.7 7.7 8.7 12.5 14.4 15.7 16.6 19.7 20.7 22.9 25.4 28.0 29.7 32.8 33.8 36.4 37.2 38.6 40.2 42.1 43.4 43.9 44.5 48.0 49.6
[R82XX] PLL not locked!
Sampling at 2048000 S/s.

Info: This tool will continuously read from the device, and report if
samples get lost. If you observe no further output, everything is fine.

Reading samples in async mode...
Allocating 15 zero-copy buffers
(wait about 30 seconds)
^CSignal caught, exiting!

User cancel, exiting...
Floating point exception
4

From the logs in your first post it looks like that for some reason rltsdr device couldn’t be available for the script usb_claim_interface error -6 either because was missing or another script used it.

Can you post logs from one of these observations? Do you get the same error as in the first post?

All of the files in data directory are zero size due to the failing scripts, you should remove them.

rtl_test seems ok for me, it finds the device and run without giving you any strange messages until you stop it with Ctrl+C.

It’s still not clear what happens and the process doesn’t stop, which causes other issues like the one with not releasing the sdr usb device.

5

rtl_test is not fine. It is not supposed to crash with a floating point exception. Normally it exits with something like this

Samples per million lost (minimum): 0

My guess is that rtl_test receives 0 samples, and tries to divide by 0 when I press ctrl+c.

Logs from failed observations:

Apr 26 01:57:01 satnogs-fhab-1 satnogs-client[5022]: usb_claim_interface error -6
Apr 26 01:57:01 satnogs-fhab-1 satnogs-client[5022]: usb_claim_interface error -6
Apr 26 01:57:01 satnogs-fhab-1 satnogs-client[5022]: [INFO] Using format CF32.
Apr 26 02:15:31 satnogs-fhab-1 satnogs-client[5022]: usb_claim_interface error -6
Apr 26 02:15:31 satnogs-fhab-1 satnogs-client[5022]: usb_claim_interface error -6
Apr 26 02:15:31 satnogs-fhab-1 satnogs-client[5022]: [INFO] Using format CF32.
Apr 26 02:54:54 satnogs-fhab-1 satnogs-client[5022]: usb_claim_interface error -6
Apr 26 02:54:54 satnogs-fhab-1 satnogs-client[5022]: usb_claim_interface error -6
Apr 26 02:54:54 satnogs-fhab-1 satnogs-client[5022]: [INFO] Using format CF32.
Apr 26 03:59:42 satnogs-fhab-1 satnogs-client[5022]: usb_claim_interface error -6
Apr 26 03:59:42 satnogs-fhab-1 satnogs-client[5022]: usb_claim_interface error -6
Apr 26 03:59:42 satnogs-fhab-1 satnogs-client[5022]: [INFO] Using format CF32.
Apr 26 04:50:16 satnogs-fhab-1 satnogs-client[5022]: usb_claim_interface error -6
Apr 26 04:50:16 satnogs-fhab-1 satnogs-client[5022]: usb_claim_interface error -6
Apr 26 04:50:16 satnogs-fhab-1 satnogs-client[5022]: [INFO] Using format CF32.
Apr 26 05:02:35 satnogs-fhab-1 satnogs-client[5022]: usb_claim_interface error -6
Apr 26 05:02:35 satnogs-fhab-1 satnogs-client[5022]: usb_claim_interface error -6
Apr 26 05:02:35 satnogs-fhab-1 satnogs-client[5022]: [INFO] Using format CF32.
Apr 26 05:11:35 satnogs-fhab-1 satnogs-client[5022]: usb_claim_interface error -6
Apr 26 05:11:35 satnogs-fhab-1 satnogs-client[5022]: usb_claim_interface error -6
Apr 26 05:11:35 satnogs-fhab-1 satnogs-client[5022]: [INFO] Using format CF32.
Apr 26 05:50:43 satnogs-fhab-1 satnogs-client[5022]: usb_claim_interface error -6
Apr 26 05:50:43 satnogs-fhab-1 satnogs-client[5022]: usb_claim_interface error -6
Apr 26 05:50:43 satnogs-fhab-1 satnogs-client[5022]: [INFO] Using format CF32.
Apr 26 06:03:55 satnogs-fhab-1 satnogs-client[5022]: usb_claim_interface error -6
Apr 26 06:03:55 satnogs-fhab-1 satnogs-client[5022]: usb_claim_interface error -6
Apr 26 06:03:55 satnogs-fhab-1 satnogs-client[5022]: [INFO] Using format CF32.

I have rebooted the Raspberry Pi and that solved the problem (for now at least). Unfortunately rebooting also means that I destroyed some of the evidence, so troubleshooting is harder. I have upped the satnogs-client log level to DEBUG so hopefully we’ll have more detailed information if the problem occurs again.

6

I seem to have the same symptoms as described in Bugs with Satnogs client?

7

For some reason the scripts did not exit. There is an open issue in satnogs-client related to this. Unfortunately, I have no way to reproduce it.

8

BTW, you have some pending updates. Could you please hit Update in satnogs-setup?

9

The issue link seems broken (points to http://•••••••••••/ )

Interesting that there are updates. I ran the update yesterday. I’ll run it again after the current observation is done (iirc, running the update will destroy any ongoing observation)

10

It should be fixed now.

1 Like
11

Thanks!
I’ve completed the update.

12

I’ve pulled back the logging level to INFO. Looks like my Pi isn’t capable of handling the 3,000 lines per minute generated during an observation.

13

My station has been working well for 2 weeks, but now it is in a state where all observations fail again, with the same error message as before.

May 11 11:40:53 satnogs-fhab-1 satnogs-client[346]: usb_claim_interface error -6
May 11 11:40:53 satnogs-fhab-1 satnogs-client[346]: usb_claim_interface error -6
May 11 12:18:59 satnogs-fhab-1 satnogs-client[346]: usb_claim_interface error -6
May 11 12:18:59 satnogs-fhab-1 satnogs-client[346]: usb_claim_interface error -6
May 11 13:02:59 satnogs-fhab-1 satnogs-client[346]: usb_claim_interface error -6
May 11 13:02:59 satnogs-fhab-1 satnogs-client[346]: usb_claim_interface error -6
May 11 13:20:10 satnogs-fhab-1 satnogs-client[346]: usb_claim_interface error -6
May 11 13:20:10 satnogs-fhab-1 satnogs-client[346]: usb_claim_interface error -6
May 11 14:52:34 satnogs-fhab-1 satnogs-client[346]: usb_claim_interface error -6
May 11 14:52:34 satnogs-fhab-1 satnogs-client[346]: usb_claim_interface error -6
May 11 15:04:03 satnogs-fhab-1 satnogs-client[346]: usb_claim_interface error -6
May 11 15:04:03 satnogs-fhab-1 satnogs-client[346]: usb_claim_interface error -6
May 11 15:15:26 satnogs-fhab-1 satnogs-client[346]: usb_claim_interface error -6
May 11 15:15:26 satnogs-fhab-1 satnogs-client[346]: usb_claim_interface error -6
May 11 17:48:57 satnogs-fhab-1 satnogs-client[346]: usb_claim_interface error -6
May 11 17:48:57 satnogs-fhab-1 satnogs-client[346]: usb_claim_interface error -6