Failed observations

mfalkvidd · January 30, 2020, 9:51pm

My station fails to perform observations sometimes.

https://network.satnogs.org/observations/1620504/ should have happened between 2020-01-30 17:17:59 and 2020-01-30 17:24:40. But /var/log/syslog does not contain anything that look interesting at that time. Note that the “ERROR - Cannot connect to socket” message is a known problem with stations that don’t have a rotor.

Jan 30 16:15:08 satnogs-fhab-1 satnogs-client[26158]: Allocating 32 zero-copy buffers
Jan 30 16:15:15 satnogs-fhab-1 CRON[581]: (CRON) info (No MTA installed, discarding output)
Jan 30 16:17:02 satnogs-fhab-1 CRON[635]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Jan 30 16:30:12 satnogs-fhab-1 CRON[684]: (pi) CMD (~/satnogs-auto-scheduler/schedule_single_station.py -s 1272 -d 0.5 -m 80)
Jan 30 16:30:20 satnogs-fhab-1 CRON[680]: (CRON) info (No MTA installed, discarding output)
Jan 30 16:45:12 satnogs-fhab-1 CRON[714]: (pi) CMD (~/satnogs-auto-scheduler/schedule_single_station.py -s 1272 -d 0.5 -m 80)
Jan 30 16:45:21 satnogs-fhab-1 CRON[710]: (CRON) info (No MTA installed, discarding output)
Jan 30 17:00:12 satnogs-fhab-1 CRON[733]: (pi) CMD (~/satnogs-auto-scheduler/schedule_single_station.py -s 1272 -d 0.5 -m 80)
Jan 30 17:00:21 satnogs-fhab-1 CRON[729]: (CRON) info (No MTA installed, discarding output)
Jan 30 17:15:07 satnogs-fhab-1 CRON[751]: (pi) CMD (~/satnogs-auto-scheduler/schedule_single_station.py -s 1272 -d 0.5 -m 80)
Jan 30 17:15:21 satnogs-fhab-1 CRON[747]: (CRON) info (No MTA installed, discarding output)
Jan 30 17:17:12 satnogs-fhab-1 CRON[764]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Jan 30 17:30:07 satnogs-fhab-1 CRON[782]: (pi) CMD (~/satnogs-auto-scheduler/schedule_single_station.py -s 1272 -d 0.5 -m 80)
Jan 30 17:30:20 satnogs-fhab-1 CRON[778]: (CRON) info (No MTA installed, discarding output)
Jan 30 17:38:53 satnogs-fhab-1 satnogs-client[26158]: 2020-01-30 17:38:53,131 - satnogsclient.observer.commsocket - ERROR - Cannot connect to socket 127.0.0.1:4533

https://network.satnogs.org/observations/1617705/ should have happened between 2020-01-30 04:41:02 and 2020-01-30 04:46:51. /var/log/syslog doesn’t have anything during that time:

Jan 30 03:23:11 satnogs-fhab-1 satnogs-client[26158]: Allocating 32 zero-copy buffers
Jan 30 04:17:12 satnogs-fhab-1 CRON[30345]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Jan 30 05:16:59 satnogs-fhab-1 satnogs-client[26158]: 2020-01-30 05:16:59,108 - satnogsclient.observer.commsocket - ERROR - Cannot connect to socket 127.0.0.1:4533

For normal observations, this is what /var/log/syslog looks like (so logging seems to work):

Jan 30 08:40:39 satnogs-fhab-1 systemd[1]: Removed slice User Slice of UID 1000.
Jan 30 08:45:13 satnogs-fhab-1 CRON[31135]: (pi) CMD (~/satnogs-auto-scheduler/schedule_single_station.py -s 1272 -d 0.5 -m 75)
Jan 30 08:45:20 satnogs-fhab-1 CRON[31131]: (CRON) info (No MTA installed, discarding output)
Jan 30 09:00:12 satnogs-fhab-1 CRON[31153]: (pi) CMD (~/satnogs-auto-scheduler/schedule_single_station.py -s 1272 -d 0.5 -m 75)
Jan 30 09:00:19 satnogs-fhab-1 CRON[31149]: (CRON) info (No MTA installed, discarding output)
--------START OF NEW OBSERVATION
Jan 30 09:11:24 satnogs-fhab-1 satnogs-client[26158]: 2020-01-30 09:11:24,302 - satnogsclient.observer.commsocket - ERROR - Cannot connect to socket 127.0.0.1:4533
Jan 30 09:11:24 satnogs-fhab-1 satnogs-client[26158]: 2020-01-30 09:11:24,304 - satnogsclient.observer.commsocket - ERROR - Cannot connect to socket 127.0.0.1:4533
Jan 30 09:11:24 satnogs-fhab-1 satnogs-client[26158]: 2020-01-30 09:11:24,305 - satnogsclient.observer.commsocket - ERROR - Cannot send to socket 127.0.0.1:4533
Jan 30 09:11:24 satnogs-fhab-1 satnogs-client[26158]: Exception in thread Thread-89:
Jan 30 09:11:24 satnogs-fhab-1 satnogs-client[26158]: Traceback (most recent call last):
Jan 30 09:11:24 satnogs-fhab-1 satnogs-client[26158]:   File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
Jan 30 09:11:24 satnogs-fhab-1 satnogs-client[26158]:     self.run()
Jan 30 09:11:24 satnogs-fhab-1 satnogs-client[26158]:   File "/usr/lib/python2.7/threading.py", line 754, in run
Jan 30 09:11:24 satnogs-fhab-1 satnogs-client[26158]:     self.__target(*self.__args, **self.__kwargs)
Jan 30 09:11:24 satnogs-fhab-1 satnogs-client[26158]:   File "/var/lib/satnogs/local/lib/python2.7/site-packages/satnogsclient/observer/worker.py", line 112, in _communicate_tracking_info
Jan 30 09:11:24 satnogs-fhab-1 satnogs-client[26158]:     self.send_to_socket(pin, sock)
Jan 30 09:11:24 satnogs-fhab-1 satnogs-client[26158]:   File "/var/lib/satnogs/local/lib/python2.7/site-packages/satnogsclient/observer/worker.py", line 198, in send_to_socket
Jan 30 09:11:24 satnogs-fhab-1 satnogs-client[26158]:     position = sock.send("p\n").split('\n')
Jan 30 09:11:24 satnogs-fhab-1 satnogs-client[26158]:   File "/var/lib/satnogs/local/lib/python2.7/site-packages/satnogsclient/observer/commsocket.py", line 81, in send
Jan 30 09:11:24 satnogs-fhab-1 satnogs-client[26158]:     response = self.sock.recv(self._tasks_buffer_size).decode('ascii')
Jan 30 09:11:24 satnogs-fhab-1 satnogs-client[26158]: error: [Errno 107] Transport endpoint is not connected
Jan 30 09:11:25 satnogs-fhab-1 satnogs-client[26158]: gr-osmosdr 0.1.4 (0.1.4) gnuradio 3.7.13.4
Jan 30 09:11:25 satnogs-fhab-1 satnogs-client[26158]: built-in source types: file osmosdr fcd rtl rtl_tcp uhd miri hackrf bladerf rfspace airspy airspyhf soapy redpitaya freesrp
Jan 30 09:11:25 satnogs-fhab-1 satnogs-client[26158]: Using device #0 Realtek RTL2838UHIDIR SN: 00000001
Jan 30 09:11:25 satnogs-fhab-1 satnogs-client[26158]: Using 32 buffers of size 16384.
Jan 30 09:11:25 satnogs-fhab-1 satnogs-client[26158]: Found Rafael Micro R820T tuner
Jan 30 09:11:25 satnogs-fhab-1 satnogs-client[26158]: [R82XX] PLL not locked!
Jan 30 09:11:25 satnogs-fhab-1 satnogs-client[26158]: Exact sample rate is: 1000000.026491 Hz
Jan 30 09:11:25 satnogs-fhab-1 satnogs-client[26158]: [R82XX] PLL not locked!
Jan 30 09:11:26 satnogs-fhab-1 satnogs-client[26158]: Allocating 32 zero-copy buffers
Jan 30 09:15:02 satnogs-fhab-1 CRON[31207]: (pi) CMD (~/satnogs-auto-scheduler/schedule_single_station.py -s 1272 -d 0.5 -m 75)
Jan 30 09:15:10 satnogs-fhab-1 CRON[31203]: (CRON) info (No MTA installed, discarding output)
Jan 30 09:17:04 satnogs-fhab-1 CRON[31233]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
--------START OF NEW OBSERVATION
Jan 30 09:17:17 satnogs-fhab-1 satnogs-client[26158]: 2020-01-30 09:17:17,036 - satnogsclient.observer.commsocket - ERROR - Cannot connect to socket 127.0.0.1:4533
Jan 30 09:17:17 satnogs-fhab-1 satnogs-client[26158]: 2020-01-30 09:17:17,038 - satnogsclient.observer.commsocket - ERROR - Cannot connect to socket 127.0.0.1:4533
Jan 30 09:17:17 satnogs-fhab-1 satnogs-client[26158]: 2020-01-30 09:17:17,038 - satnogsclient.observer.commsocket - ERROR - Cannot send to socket 127.0.0.1:4533
Jan 30 09:17:17 satnogs-fhab-1 satnogs-client[26158]: Exception in thread Thread-91:
Jan 30 09:17:17 satnogs-fhab-1 satnogs-client[26158]: Traceback (most recent call last):
Jan 30 09:17:17 satnogs-fhab-1 satnogs-client[26158]:   File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
Jan 30 09:17:17 satnogs-fhab-1 satnogs-client[26158]:     self.run()
Jan 30 09:17:17 satnogs-fhab-1 satnogs-client[26158]:   File "/usr/lib/python2.7/threading.py", line 754, in run
Jan 30 09:17:17 satnogs-fhab-1 satnogs-client[26158]:     self.__target(*self.__args, **self.__kwargs)
Jan 30 09:17:17 satnogs-fhab-1 satnogs-client[26158]:   File "/var/lib/satnogs/local/lib/python2.7/site-packages/satnogsclient/observer/worker.py", line 112, in _communicate_tracking_info
Jan 30 09:17:17 satnogs-fhab-1 satnogs-client[26158]:     self.send_to_socket(pin, sock)
Jan 30 09:17:17 satnogs-fhab-1 satnogs-client[26158]:   File "/var/lib/satnogs/local/lib/python2.7/site-packages/satnogsclient/observer/worker.py", line 198, in send_to_socket
Jan 30 09:17:17 satnogs-fhab-1 satnogs-client[26158]:     position = sock.send("p\n").split('\n')
Jan 30 09:17:17 satnogs-fhab-1 satnogs-client[26158]:   File "/var/lib/satnogs/local/lib/python2.7/site-packages/satnogsclient/observer/commsocket.py", line 81, in send
Jan 30 09:17:17 satnogs-fhab-1 satnogs-client[26158]:     response = self.sock.recv(self._tasks_buffer_size).decode('ascii')
Jan 30 09:17:17 satnogs-fhab-1 satnogs-client[26158]: error: [Errno 107] Transport endpoint is not connected
Jan 30 09:17:18 satnogs-fhab-1 satnogs-client[26158]: gr-osmosdr 0.1.4 (0.1.4) gnuradio 3.7.13.4
Jan 30 09:17:18 satnogs-fhab-1 satnogs-client[26158]: built-in source types: file osmosdr fcd rtl rtl_tcp uhd miri hackrf bladerf rfspace airspy airspyhf soapy redpitaya freesrp
Jan 30 09:17:18 satnogs-fhab-1 satnogs-client[26158]: Using device #0 Realtek RTL2838UHIDIR SN: 00000001
Jan 30 09:17:18 satnogs-fhab-1 satnogs-client[26158]: Using 32 buffers of size 16384.
Jan 30 09:17:18 satnogs-fhab-1 satnogs-client[26158]: Found Rafael Micro R820T tuner
Jan 30 09:17:18 satnogs-fhab-1 satnogs-client[26158]: [R82XX] PLL not locked!
Jan 30 09:17:18 satnogs-fhab-1 satnogs-client[26158]: Exact sample rate is: 1000000.026491 Hz
Jan 30 09:17:18 satnogs-fhab-1 satnogs-client[26158]: [R82XX] PLL not locked!
Jan 30 09:17:18 satnogs-fhab-1 satnogs-client[26158]: Allocating 32 zero-copy buffers
Jan 30 09:30:12 satnogs-fhab-1 CRON[31327]: (pi) CMD (~/satnogs-auto-scheduler/schedule_single_station.py -s 1272 -d 0.5 -m 75)

The only thing I’m able to find in the logs that looks a bit suspicious is this (but it has only happened once):

Jan 30 05:24:59 satnogs-fhab-1 satnogs-client[26158]: 2020-01-30 05:24:59,251 - satnogsclient.scheduler.tasks - ERROR - Bad status code: 400

Any idea how I can troubleshoot this?

mfalkvidd · January 31, 2020, 7:02am

How often are new observations fetched by / pushed to the client? Could it be that the failed observations were scheduled too late, so the client didn’t have time to get them before the time they should start?

Btw, I see that observations scheduled by Dimitris also fail, it is not only my own observations.

jebba · January 31, 2020, 5:39pm

I don’t think it is that they were scheduled too late.

I just had a huge batch of fails after not checking for a few days. I haven’t nailed it down, but I think these issues are more likely caused by USB.

The scripts that are powering off/on USB for observations look like a potentially good solution.

mfalkvidd · February 2, 2020, 9:03pm

If the problem is with USB, shouldn’t the satnogs client still log something? For successful observations, satnogs-client logs several things before it seems to start up the SDR.

Another failed observation with nothing in the logs: https://network.satnogs.org/observations/1629894/

mfalkvidd · February 4, 2020, 8:28am

one more failed: https://network.satnogs.org/observations/1642098/