Kiwirecorder sessions terminated at 06:25

rrobinet

I have observed that while recording from 3 Kiwis that the sessions on the 2 Kiwis with 8 recorder clients are terminated each day at 06:25 with these messages in /var/log/messages:

Oct 10 06:25:37 kiwisdr kiwid: 5d:14:08:28.175 01234567 1 GEOLOC: geoloc_task:P2:T33((50.000 msec) TaskSleep)
Oct 10 06:25:37 kiwisdr kiwid: 5d:14:08:28.345 01234567 0 GEOLOC: geoloc_task:P2:T32((50.000 msec) TaskSleep)
Oct 11 03:28:05 kiwisdr kiwid: 6d:11:10:55.589 01234567 UPDATE: check scheduled
Oct 11 06:25:10 kiwisdr rsyslogd: [origin software="rsyslogd" swVersion="8.4.2" x-pid="427" x-info="http://www.rsyslog.com"] rsyslogd was HUPed
Oct 11 06:25:11 kiwisdr kiwid: 6d:14:08:01.990 01234.67 5 7040.05 kHz usb z0 "kiwirecorder.py" 10.14.70.85 Point Reyes Station, California, USA (LEAVING after 23:59:55)
Oct 11 06:25:11 kiwisdr kiwid: 6d:14:08:02.003 01.34.67 2 10140.15 kHz usb z0 "kiwirecorder.py" 10.14.70.85 Point Reyes Station, California, USA (LEAVING after 23:59:56)
Oct 11 06:25:11 kiwisdr kiwid: 6d:14:08:02.008 0..34.67 1 28126.05 kHz usb z0 "kiwirecorder.py" 10.14.70.85 Point Reyes Station, California, USA (LEAVING after 23:59:56)
Oct 11 06:25:11 kiwisdr kiwid: 6d:14:08:02.017 0..34..7 6 3570.05 kHz usb z0 "kiwirecorder.py" 10.14.70.85 Point Reyes Station, California, USA (LEAVING after 23:59:56)
....

The third Kiwi is shared with normal listeners and its three recorder clients never terminate, and I see only this message each day at 06:25:
root@kiwisdr:~# grep 06:25 /var/log/messages
Oct 7 06:25:12 kiwisdr rsyslogd: [origin software="rsyslogd" swVersion="8.4.2" x-pid="423" x-info="http://www.rsyslog.com"] rsyslogd was HUPed
Oct 8 06:25:10 kiwisdr rsyslogd: [origin software="rsyslogd" swVersion="8.4.2" x-pid="423" x-info="http://www.rsyslog.com"] rsyslogd was HUPed
Oct 9 06:25:11 kiwisdr rsyslogd: [origin software="rsyslogd" swVersion="8.4.2" x-pid="423" x-info="http://www.rsyslog.com"] rsyslogd was HUPed
Oct 10 06:25:10 kiwisdr rsyslogd: [origin software="rsyslogd" swVersion="8.4.2" x-pid="423" x-info="http://www.rsyslog.com"] rsyslogd was HUPed
Oct 11 06:25:10 kiwisdr rsyslogd: [origin software="rsyslogd" swVersion="8.4.2" x-pid="423" x-info="http://www.rsyslog.com"] rsyslogd was HUPed
Oct 12 06:25:10 kiwisdr rsyslogd: [origin software="rsyslogd" swVersion="8.4.2" x-pid="423" x-info="http://www.rsyslog.com"] rsyslogd was HUPed
root@kiwisdr:~#

All three Kiwis have been configured to *not* check or install updates after I manually updated to v1.237 last week.
So it appears that even when disabled, the update check disrupts kiwirecorder sessions

WA2ZKD

I reported the update interruption to John after finding it still did it even though "not", just like you have found

jks

A little detective work shows these lines in the stock /etc/crontab (for Beagle Debian at least)

# m h dom mon dow user	command
25 6	* * *	root	test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily )

So there’s your 06:25 event: the daily cron activities being run. One of the file in /etc/cron.daily is logrotate and a “man logrotate” shows it sends a SIGHUP to the logging process(s) if necessary (e.g. rsyslogd). So that’s why you’re seeing the messages:

Oct 12 06:25:10 kiwisdr rsyslogd: [origin software="rsyslogd" swVersion="8.4.2" x-pid="423" x-info="http://www.rsyslog.com"] rsyslogd was HUPed

So this sequence of events is entirely normal.

Yes, at 03:28 you get the message "UPDATE: check scheduled”. But that does NOT mean an update is subsequently occurring. It means what it says, that a check has been scheduled (and in this case postponed because there are active connections). If your admin “updates disabled” setting was being incorrectly ignored you would have seen an update proceed after the disconnections at 06:25. But you don’t. The only real flaw here is that I don’t print a message saying the update check will be skipped because it has been disabled by the admin. And I have now added that. A message is already printed if the update check is enabled but the actual installation is disabled (the other option in the update tab on the admin page).

The question still remains why kiwirecorder sessions are disconnected around the same time. I ran kiwirecorder on the same Beagle as the Kiwi and also on another Beagle. Then forced the cron.daily to run by placing another entry in /etc/crontab with a time a few minutes in the future. The kiwirecorder session was not disconnected in either case. We really need to determine if kiwirecorder itself is getting terminated on the host it’s running on rather than the Kiwi simply disconnecting. To do that you’d have to run kiwirecorder in a foreground shell window, maybe with “—log-level=info” and try to see if it’s being sent a terminating signal by someone or getting another error.

rrobinet

The same kiwiwspr daemon running on a Pi has been running 19 kiwirecorder sessions to 3 Kiwis for the last week: Kiwi72,75,76
The 8 sessions to each of 75 and 76 terminate each day at 06:25, but the sessions to 72 have been running for over 3 days.
72 differs from 75 and 76 in that 72 is used by only 3 kiwirecorder sessions (and public listeners) while 75 and 76 have 8 kiwirecorder clients at all times and thus no other listeners
So I think that proves that the disconnection is initiated by the Kiwi, not the client on the Pi.
But what about 72 that keeps its clients alive eludes me.

Christoph

I was able to trigger kiwirecorder disconnects by starting a process like recompiling kiwi.bin on the beaglebone or setting the update rate of 'top' to 0. Logrotate compresses old log files and this may use enough CPU to trigger websocket client disconnects. In these cases the client disconnect was initiated by mongoose (line 4886 in mongoose.cpp).

jks

Hmm. I can do a full Kiwi recompile and 4 instances of "stress-ng --cpu" in parallel and not have a remote kiwirecorder connection get dropped.
When you use the "dog" alias do you get output similar to this?

root@www:~/Beagle_SDR_GPS# dog
Debian 8.5
BeagleBoard.org Debian Image 2016-05-13
Linux www 4.4.9-ti-r25 #1 SMP Thu May 5 23:08:13 UTC 2016 armv7l GNU/Linux

rrobinet

'dog' reports the same OS on Kiwi72 as on Kiwi76 which terminates at 06:25:

======================================
pi@KPH-Pi2:/tmp/kiwi-captures/KPH_HF_3/20 $ skw76
Debian GNU/Linux 8

BeagleBoard.org Debian Image 2016-05-13

Support/FAQ: http://elinux.org/Beagleboard:BeagleBoneBlack_Debian

default username:password is [debian:temppwd]

Last login: Fri Oct 12 16:28:02 2018 from 10.14.70.85
root@kiwisdr:~# dog
Debian 8.5
BeagleBoard.org Debian Image 2016-05-13
Linux kiwisdr 4.4.9-ti-r25 #1 SMP Thu May 5 23:08:13 UTC 2016 armv7l GNU/Linux
root@kiwisdr:~# logout
Connection to 10.14.70.76 closed.


===================================
pi@KPH-Pi2:/tmp/kiwi-captures/KPH_HF_3/20 $ skw72
Debian GNU/Linux 8

BeagleBoard.org Debian Image 2016-05-13

Support/FAQ: http://elinux.org/Beagleboard:BeagleBoneBlack_Debian

default username:password is [debian:temppwd]

Last login: Fri Oct 12 16:18:09 2018 from 10.14.70.85
root@kiwisdr:~# dog
Debian 8.5
BeagleBoard.org Debian Image 2016-05-13
Linux kiwisdr 4.4.9-ti-r25 #1 SMP Thu May 5 23:08:13 UTC 2016 armv7l GNU/Linux
root@kiwisdr:~#

Christoph

Hi John,

I confirm that there are no disconnects in 4-channel mode when there is a high CPU load from other programs. But when the KiwiSDR is in 8-channel mode these disconnects do appear.

rrobinet

All three of my Kiwis 72/75/76 are in 8 channel mode. 75/76 have 8 active listeners, while 72 has 3 active kiwirecorder clients and 0-(maybe never) 5 normal listeners

Christoph

... in 8-channel mode the recorders work reliably with extra CPU load up to including 5 kiwirecorders

rrobinet

Hi Christoph,
Since the Pi76 system is completely error free for 4 days since 9 Oct and the 06:25 terminations are the only remaining issue, shall I modify the schedule so that it runs only 7 jobs on Kiwi75?
I will password protect the free channel(s) and decrease the number of recorders one day at a time so that we can see if there is a threshold below which 06:25 terminations stop.

Christoph

Hi Rob,
even with the restarts at 6:25 you will miss only one out of 720 2-minute intervals per day. So I am not sure if it is worth to password protect channels. My tests (to be confirmed by John) indicate that for up to 5 clients there are no disconnects. It looks like something changes qualitatively for 6 or more clients.

WA2ZKD

I run 8-ch of kiwirecorder here on my non-public kiwi, haven't see the 0625-7 thing in awhile that I am aware of

rrobinet

Kiwi72 with 6 clients didn't terminate last night while kiwis 75 and 76 with 8 client did terminate. I agree with Christoph that we can suspend further investigations
Thanks to all