Failed to upload observation data (timeout)

SatNOGS
1

Hi,

I’ve just realised that during the last 3 observations from our station, the station failed to post the observation data, waterfall and audio to SatNogs. No changes have been made to the Raspberry Pi prior to this issues.

The tracking and recording ran as normal.

Can anyone help with this?

Thanks.

Log gives the following error:

Jun 17 10:04:54 itrpi4 satnogs-client[352]: 2020-06-17 10:04:54,825 - satnogsclient.scheduler.tasks - INFO - Trying to PUT observation data for id: 2394564
Jun 17 10:05:40 itrpi4 satnogs-client[352]: 2020-06-17 10:05:40,228 - apscheduler.executors.default - ERROR - Job “get_jobs (trigger: interval[0:01:00], next run at: 2020-06-17 10:05:54 UTC)” raised an exception
Jun 17 10:05:40 itrpi4 satnogs-client[352]: Traceback (most recent call last):
Jun 17 10:05:40 itrpi4 satnogs-client[352]: File “/usr/lib/python3/dist-packages/urllib3/connectionpool.py”, line 343, in _make_request
Jun 17 10:05:40 itrpi4 satnogs-client[352]: self._validate_conn(conn)
Jun 17 10:05:40 itrpi4 satnogs-client[352]: File “/usr/lib/python3/dist-packages/urllib3/connectionpool.py”, line 841, in validate_conn
Jun 17 10:05:40 itrpi4 satnogs-client[352]: conn.connect()
Jun 17 10:05:40 itrpi4 satnogs-client[352]: File “/usr/lib/python3/dist-packages/urllib3/connection.py”, line 344, in connect
Jun 17 10:05:40 itrpi4 satnogs-client[352]: ssl_context=context)
Jun 17 10:05:40 itrpi4 satnogs-client[352]: File "/usr/lib/python3/dist-packages/urllib3/util/ssl.py", line 344, in ssl_wrap_socket
Jun 17 10:05:40 itrpi4 satnogs-client[352]: return context.wrap_socket(sock, server_hostname=server_hostname)
Jun 17 10:05:40 itrpi4 satnogs-client[352]: File “/usr/lib/python3.7/ssl.py”, line 412, in wrap_socket
Jun 17 10:05:40 itrpi4 satnogs-client[352]: session=session
Jun 17 10:05:40 itrpi4 satnogs-client[352]: File “/usr/lib/python3.7/ssl.py”, line 853, in _create
Jun 17 10:05:40 itrpi4 satnogs-client[352]: self.do_handshake()
Jun 17 10:05:40 itrpi4 satnogs-client[352]: File “/usr/lib/python3.7/ssl.py”, line 1117, in do_handshake
Jun 17 10:05:40 itrpi4 satnogs-client[352]: self._sslobj.do_handshake()
Jun 17 10:05:40 itrpi4 satnogs-client[352]: socket.timeout: _ssl.c:1039: The handshake operation timed out
Jun 17 10:05:40 itrpi4 satnogs-client[352]: During handling of the above exception, another exception occurred:
Jun 17 10:05:40 itrpi4 satnogs-client[352]: Traceback (most recent call last):
Jun 17 10:05:40 itrpi4 satnogs-client[352]: File “/usr/lib/python3/dist-packages/requests/adapters.py”, line 449, in send
Jun 17 10:05:40 itrpi4 satnogs-client[352]: timeout=timeout
Jun 17 10:05:40 itrpi4 satnogs-client[352]: File “/usr/lib/python3/dist-packages/urllib3/connectionpool.py”, line 638, in urlopen
Jun 17 10:05:40 itrpi4 satnogs-client[352]: _stacktrace=sys.exc_info()[2])
Jun 17 10:05:40 itrpi4 satnogs-client[352]: File “/usr/lib/python3/dist-packages/urllib3/util/retry.py”, line 367, in increment
Jun 17 10:05:40 itrpi4 satnogs-client[352]: raise six.reraise(type(error), error, _stacktrace)
Jun 17 10:05:40 itrpi4 satnogs-client[352]: File “/usr/lib/python3/dist-packages/six.py”, line 693, in reraise
Jun 17 10:05:40 itrpi4 satnogs-client[352]: raise value
Jun 17 10:05:40 itrpi4 satnogs-client[352]: File “/usr/lib/python3/dist-packages/urllib3/connectionpool.py”, line 600, in urlopen
Jun 17 10:05:40 itrpi4 satnogs-client[352]: chunked=chunked)
Jun 17 10:05:40 itrpi4 satnogs-client[352]: File “/usr/lib/python3/dist-packages/urllib3/connectionpool.py”, line 346, in _make_request
Jun 17 10:05:40 itrpi4 satnogs-client[352]: self._raise_timeout(err=e, url=url, timeout_value=conn.timeout)
Jun 17 10:05:40 itrpi4 satnogs-client[352]: File “/usr/lib/python3/dist-packages/urllib3/connectionpool.py”, line 306, in _raise_timeout
Jun 17 10:05:40 itrpi4 satnogs-client[352]: raise ReadTimeoutError(self, url, “Read timed out. (read timeout=%s)” % timeout_value)
Jun 17 10:05:40 itrpi4 satnogs-client[352]: urllib3.exceptions.ReadTimeoutError: HTTPSConnectionPool(host=‘network.satnogs.org’, port=443): Read timed out. (read timeout=45)
Jun 17 10:05:40 itrpi4 satnogs-client[352]: During handling of the above exception, another exception occurred:
Jun 17 10:05:40 itrpi4 satnogs-client[352]: Traceback (most recent call last):
Jun 17 10:05:40 itrpi4 satnogs-client[352]: File “/usr/lib/python3/dist-packages/apscheduler/executors/base.py”, line 125, in run_job
Jun 17 10:05:40 itrpi4 satnogs-client[352]: retval = job.func(*job.args, **job.kwargs)
Jun 17 10:05:40 itrpi4 satnogs-client[352]: File “/var/lib/satnogs/lib/python3.7/site-packages/satnogsclient/scheduler/tasks.py”, line 177, in get_jobs
Jun 17 10:05:40 itrpi4 satnogs-client[352]: timeout=45)
Jun 17 10:05:40 itrpi4 satnogs-client[352]: File “/usr/lib/python3/dist-packages/requests/api.py”, line 75, in get
Jun 17 10:05:40 itrpi4 satnogs-client[352]: return request(‘get’, url, params=params, **kwargs)
Jun 17 10:05:40 itrpi4 satnogs-client[352]: File “/usr/lib/python3/dist-packages/requests/api.py”, line 60, in request
Jun 17 10:05:40 itrpi4 satnogs-client[352]: return session.request(method=method, url=url, **kwargs)
Jun 17 10:05:40 itrpi4 satnogs-client[352]: File “/usr/lib/python3/dist-packages/requests/sessions.py”, line 533, in request
Jun 17 10:05:40 itrpi4 satnogs-client[352]: resp = self.send(prep, **send_kwargs)
Jun 17 10:05:40 itrpi4 satnogs-client[352]: File “/usr/lib/python3/dist-packages/requests/sessions.py”, line 646, in send
Jun 17 10:05:40 itrpi4 satnogs-client[352]: r = adapter.send(request, **kwargs)
Jun 17 10:05:40 itrpi4 satnogs-client[352]: File “/usr/lib/python3/dist-packages/requests/adapters.py”, line 529, in send
Jun 17 10:05:40 itrpi4 satnogs-client[352]: raise ReadTimeout(e, request=request)
Jun 17 10:05:40 itrpi4 satnogs-client[352]: requests.exceptions.ReadTimeout: HTTPSConnectionPool(host=‘network.satnogs.org’, port=443): Read timed out. (read timeout=45)
Jun 17 10:05:54 itrpi4 satnogs-client[352]: 2020-06-17 10:05:54,813 - satnogsclient.scheduler.tasks - INFO - Trying to GET observation jobs from the network
Jun 17 10:06:54 itrpi4 satnogs-client[352]: 2020-06-17 10:06:54,810 - satnogsclient.scheduler.tasks - INFO - Trying to GET observation jobs from the network
Jun 17 10:06:54 itrpi4 satnogs-client[352]: 2020-06-17 10:06:54,819 - apscheduler.scheduler - WARNING - Execution of job “post_data (trigger: interval[0:02:00], next run at: 2020-06-17 10:06:54 UTC)” skipped: maximum number of running instances reached (1)

2

After monitoring a few passes, it seems that the data, waterfall, and audio eventually get uploaded, but only after many timeout and retries.

Any reason why this is happening?

3

Fyi, I’ve updated the satnogs client (1.3.2) and still having the same issues:

Jun 17 13:31:38 itrpi4 satnogs-client[1433]: Traceback (most recent call last):
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3/dist-packages/urllib3/connectionpool.py”, line 343, in _make_request
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: self._validate_conn(conn)
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3/dist-packages/urllib3/connectionpool.py”, line 841, in validate_conn
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: conn.connect()
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3/dist-packages/urllib3/connection.py”, line 344, in connect
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: ssl_context=context)
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File "/usr/lib/python3/dist-packages/urllib3/util/ssl.py", line 344, in ssl_wrap_socket
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: return context.wrap_socket(sock, server_hostname=server_hostname)
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3.7/ssl.py”, line 412, in wrap_socket
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: session=session
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3.7/ssl.py”, line 853, in _create
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: self.do_handshake()
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3.7/ssl.py”, line 1117, in do_handshake
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: self._sslobj.do_handshake()
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: socket.timeout: _ssl.c:1039: The handshake operation timed out
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: During handling of the above exception, another exception occurred:
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: Traceback (most recent call last):
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3/dist-packages/requests/adapters.py”, line 449, in send
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: timeout=timeout
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3/dist-packages/urllib3/connectionpool.py”, line 638, in urlopen
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: _stacktrace=sys.exc_info()[2])
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3/dist-packages/urllib3/util/retry.py”, line 367, in increment
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: raise six.reraise(type(error), error, _stacktrace)
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3/dist-packages/six.py”, line 693, in reraise
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: raise value
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3/dist-packages/urllib3/connectionpool.py”, line 600, in urlopen
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: chunked=chunked)
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3/dist-packages/urllib3/connectionpool.py”, line 346, in _make_request
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: self._raise_timeout(err=e, url=url, timeout_value=conn.timeout)
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3/dist-packages/urllib3/connectionpool.py”, line 306, in _raise_timeout
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: raise ReadTimeoutError(self, url, “Read timed out. (read timeout=%s)” % timeout_value)
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: urllib3.exceptions.ReadTimeoutError: HTTPSConnectionPool(host=‘network.satnogs.org’, port=443): Read timed out. (read timeout=1800)
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: During handling of the above exception, another exception occurred:
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: Traceback (most recent call last):
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/var/lib/satnogs/lib/python3.7/site-packages/satnogsclient/scheduler/tasks.py”, line 112, in post_data
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: timeout=settings.SATNOGS_NETWORK_API_TIMEOUT)
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3/dist-packages/requests/api.py”, line 131, in put
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: return request(‘put’, url, data=data, **kwargs)
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3/dist-packages/requests/api.py”, line 60, in request
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: return session.request(method=method, url=url, **kwargs)
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3/dist-packages/requests/sessions.py”, line 533, in request
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: resp = self.send(prep, **send_kwargs)
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3/dist-packages/requests/sessions.py”, line 646, in send
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: r = adapter.send(request, **kwargs)
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3/dist-packages/requests/adapters.py”, line 529, in send
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: raise ReadTimeout(e, request=request)
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: requests.exceptions.ReadTimeout: HTTPSConnectionPool(host=‘network.satnogs.org’, port=443): Read timed out. (read timeout=1800)
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: During handling of the above exception, another exception occurred:
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: Traceback (most recent call last):
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3.7/logging/init.py”, line 1034, in emit
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: msg = self.format(record)
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3.7/logging/init.py”, line 880, in format
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: return fmt.format(record)
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3.7/logging/init.py”, line 619, in format
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: record.message = record.getMessage()
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3.7/logging/init.py”, line 380, in getMessage
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: msg = msg % self.args
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: TypeError: %i format: a number is required, not str
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: Call stack:
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3.7/threading.py”, line 885, in _bootstrap
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: self._bootstrap_inner()
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3.7/threading.py”, line 917, in _bootstrap_inner
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: self.run()
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3.7/threading.py”, line 865, in run
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: self._target(*self._args, **self._kwargs)
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3.7/concurrent/futures/thread.py”, line 80, in _worker
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: work_item.run()
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3.7/concurrent/futures/thread.py”, line 57, in run
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: result = self.fn(*self.args, **self.kwargs)
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/usr/lib/python3/dist-packages/apscheduler/executors/base.py”, line 125, in run_job
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: retval = job.func(*job.args, **job.kwargs)
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: File “/var/lib/satnogs/lib/python3.7/site-packages/satnogsclient/scheduler/tasks.py”, line 120, in post_data
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: ‘due to timeout.’, fil, observation_id)
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: Message: ‘Upload of %s for observation %i failed due to timeout.’
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: Arguments: (‘data_2395464_2020-06-17T11-27-40’, ‘2395464’)
Jun 17 13:31:38 itrpi4 satnogs-client[1433]: satnogsclient.scheduler.tasks - INFO - Trying to PUT observation data for id: 2395464
Jun 17 13:32:24 itrpi4 satnogs-client[1433]: satnogsclient.scheduler.tasks - INFO - Trying to GET observation jobs from the network
Jun 17 13:33:24 itrpi4 satnogs-client[1433]: satnogsclient.scheduler.tasks - INFO - Trying to GET observation jobs from the network
Jun 17 13:34:24 itrpi4 satnogs-client[1433]: satnogsclient.scheduler.tasks - INFO - Trying to GET observation jobs from the network
Jun 17 13:34:24 itrpi4 satnogs-client[1433]: apscheduler.scheduler - WARNING - Execution of job “post_data (trigger: interval[0:03:00], next run at: 2020-06-17 13:34:24 UTC)” skipped: maximum number of running instances reached (1)
Jun 17 13:35:24 itrpi4 satnogs-client[1433]: satnogsclient.scheduler.tasks - INFO - Trying to GET observation jobs from the network
Jun 17 13:36:24 itrpi4 satnogs-client[1433]: satnogsclient.scheduler.tasks - INFO - Trying to GET observation jobs from the network
Jun 17 13:37:24 itrpi4 satnogs-client[1433]: satnogsclient.scheduler.tasks - INFO - Trying to GET observation jobs from the network
Jun 17 13:37:24 itrpi4 satnogs-client[1433]: apscheduler.scheduler - WARNING - Execution of job “post_data (trigger: interval[0:03:00], next run at: 2020-06-17 13:37:24 UTC)” skipped: maximum number of running instances reached (1)
Jun 17 13:38:25 itrpi4 satnogs-client[1433]: satnogsclient.scheduler.tasks - INFO - Trying to GET observation jobs from the network
Jun 17 13:39:25 itrpi4 satnogs-client[1433]: satnogsclient.scheduler.tasks - INFO - Trying to GET observation jobs from the network
Jun 17 13:40:24 itrpi4 satnogs-client[1433]: satnogsclient.scheduler.tasks - INFO - Trying to GET observation jobs from the network
Jun 17 13:40:24 itrpi4 satnogs-client[1433]: apscheduler.scheduler - WARNING - Execution of job “post_data (trigger: interval[0:03:00], next run at: 2020-06-17 13:40:24 UTC)” skipped: maximum number of running instances reached (1)
Jun 17 13:41:24 itrpi4 satnogs-client[1433]: satnogsclient.scheduler.tasks - INFO - Trying to GET observation jobs from the network
Jun 17 13:42:24 itrpi4 satnogs-client[1433]: satnogsclient.scheduler.tasks - INFO - Trying to GET observation jobs from the network
Jun 17 13:43:24 itrpi4 satnogs-client[1433]: satnogsclient.scheduler.tasks - INFO - Trying to GET observation jobs from the network
Jun 17 13:43:24 itrpi4 satnogs-client[1433]: apscheduler.scheduler - WARNING - Execution of job “post_data (trigger: interval[0:03:00], next run at: 2020-06-17 13:43:24 UTC)” skipped: maximum number of running instances reached (1)
Jun 17 13:44:24 itrpi4 satnogs-client[1433]: satnogsclient.scheduler.tasks - INFO - Trying to GET observation job

4

I guess the thing to try initially is to try and run something like:
curl https://network.satnogs.org/

from the machine itself, and make sure the website is actually reachable. There may be some odd network issue going on. The other errors shown seem to be a result of the code not handling the timeout error correctly.

5

Hi everybody,
today my node 311 ( vers. 1.3.4 ) has experienced same issues, looking at logs.
Unfortunately in this moment I’m unable to paste here logs ( I’m on vacation…) but seems that there’s a problem with timeouts getting jobs.
After a programmed reboot ( tnx cron :wink: ) operations resumed normally.
Tnx for attention,
de I3VFJ, Victor