Problem: No decodes after complete reinstall

[Ulli]

Hi,
The whole problem starts, when yesterday I found out, that the raspberry didn't follow the rule to change bands for nighttime operation as coded in the wsprdaemon.conf file.  It just did not switch to the new bands for the nighttime and stayed on the old daytime setting.... and uploads only noise-graph but there where no decodes at all...

It turns out, that for some reason there was no synchronisation of the system time any more and the raspberry system time was way off....

Rather than fiddling arround with no real idea what to do, I decided to make a complete reset and reinstall of everything:
- downloaded and installed the latest Raspberry pi OS (= the standard as recommended on the official RP-website)
- downloaded and followed the installation steps of the github site for Wsprdaemon 2.9g

Now - I have already did this twice - it turns out - no change of the behaviour - systemtime is still  about 15sec off.
Although wsprdaemon starts and runs (kiwi channels running also) no decodes.
monitoring the uploads.log (tail -f) says no spots detected in the written decodingfiles
I believe that it is because the system time of raspberry pi is wrong

When I reinstalled for the second time everything and after install of fresh Raspberrypi OS, I did:
$ timedatectl status
at this state ntp-server was running and active...

then I followed all steps at github wsprdaemon website to install wd 2.9g
After I had installed everything I checked again:
$ timedatectl status
ntp server inactive (dead)

Comparing time shows again about 15sec lagging system time on the raspberry...
Again running newly installed wd 2.9g results with wsprd could not decode any stations...

So:
- What should I do, to get the systemtime of raspberrypi correct ?
- Is the difference in systemtime the real problem, or is there anything else with the software, which I may have overlooked ? (still noise graphs will be uploaded, but no spots decoded)

Note: trying to start ntp service and checking it's status the response suggests that there is a different service blocking the ntp service so ntp needs to exit immediately.

Any suggestions ? Thanks

Ulli, ON5KQ

[cathalferris]

Verify that it's the crappy SystemD attempt at an NTP daemon that is hogging the port/
Lines with "#" starting are commands to be run as root, either by "sudo bash" to get an escalated-privilege shell, or by logging in as root on the Pi. (don't type the "# " at the start of the line..)

Check to see what process is open on port 123 (extra grep is to filter out the grep command as that will show up otherwise):
# netstat -planet | grep- v grep | grep :123

Check the status of the systemd attempt at an NTP daemon, see if it's running:
# systemctl status systemd-timesyncd

I would always suggest running a real NTP server instead of a systemd service - that goes across the board no matter what the service is. The reasons are many, but I don't really want to get into that kind of a religious discussion on here ;)

Stop the systemd time daemon:
# systemctl disable systemd-timesyncd

Now it should be possible to start the real ntp server, verify that it's running, then after a while, verifiy the current state of NTP's performance

# service ntp start
# service ntp status

After a while, run this and see if it makes sense:
# ntpq -p

Hopefully this helps..

[Rob]

I have just performed a complete installation on my 4GB Pi 4 from the latest Raspios buster:
2020-05-27-raspios-buster-full-armhf
After the 20 minutes of OS update during installation, I cloned the latest WD which is V2.9h
WD installed many libraries among them ntp.
After installation, without making any changes to the Pi SW, only setting up the wsprdaemon.conf file, WD starts fine.
Also, ntp was installed and is running fine without any changes.
So for me the installation and run was clean.



pi@Berk-Pi4b-90:~/wsprdaemon $ ntpq -p
     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
 0.debian.pool.n .POOL.          16 p    -   64    0    0.000    0.000   0.001
 1.debian.pool.n .POOL.          16 p    -   64    0    0.000    0.000   0.001
 2.debian.pool.n .POOL.          16 p    -   64    0    0.000    0.000   0.001
 3.debian.pool.n .POOL.          16 p    -   64    0    0.000    0.000   0.001
+173.0.48.220 (1 43.77.130.254    3 u   50   64   37   40.430   -3.725   7.093
+ntp.netviscom.c 152.2.133.55     2 u   47   64   37   65.434   -2.842   7.419
-tick.chi1.ntfo. 206.55.64.77     3 u   52   64   17   64.686   -0.811   2.581
+44.190.6.254    127.67.113.92    2 u   51   64   37   17.404   -4.932   9.131
-clock.xmission. 132.163.96.3     2 u   50   64   37   37.398    5.229   6.279
-ntp.ihost.md    216.239.35.4     2 u   46   64   37  209.339   -3.415   9.561
+208.67.72.43    128.227.205.3    2 u   47   64   37   85.549   -4.091   7.290
+lithium.constan 216.218.254.202  2 u   51   64   37   89.119   -1.845   5.744
*ntp.xtom.com    127.67.113.92    2 u   46   64   37   15.597   -4.645   9.642
pi@Berk-Pi4b-90:~/wsprdaemon $

[Ulli]

Rob,
I re-installed the Raspberry pi OS once more and also re-installed the wd 2.9h
I did this in my lab, where I have monitor, mouse, and keyboard.

When WD2.9h install was finished, I started 'wsprdaemon.sh -a'....
All OK - spots where uploaded ok...

Perfect!

HOWEVER !!!
After that I needed to relocate the Raspberry from the Lab to the final place here in the house in the Internet router and Network switcher rack. So I closed with 'wsprdaemon.sh -z' and logged out the raspberry user pi and shut it down. Then I relocated the hardware...

After power-on at the final location, wsprdaemon started automatically (nice feature!)....

I checked system time of the raspberry pi now after 2min power off...

I used the following website for the time comparison, by simply surfing with raspberry browser to:
https://time.is

Your clock is x minutes behind....

So it seems that after power-off, there is still a ntp issue after a longer time power-off of the raspberry hardware.

How to fix this time difference now ?
I have remotedesktop installed on the rp so I can control it from my windows machine.

Ulli, ON5KQ
 

[Ulli]

I manually set the system-time of the raspberry pi running WD2.9h now, to get online again...
'sudo timedatectl set-time 'hh:mm:ss'
I managed to get as close as only 0.3sec difference to the exact time with manual time-setting...

At this moment spotting works, as time-lag didn't get bigger in the last half hour. I changed the ntp server adresses to the pool ntp-servers here in Belgium and crossed out the debian pool adresses.
My windows host (internal IP: 192.168.1.112) is connected to the remote RP via remote desktop. I checked ntp situation now, after setting manual time - however I still get this - note the ntp process is exited:
---
pi@raspberrypi:~ $ sudo ntpq -p
     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
 ntp.cybertu.be  .INIT.          16 u    -   64    0    0.000    0.000   0.000
 51.38.2.120 (va .INIT.          16 u    -   64    0    0.000    0.000   0.000
 94-224-67-24.ac .INIT.          16 u    -   64    0    0.000    0.000   0.000
 ntp.devrandom.b .INIT.          16 u    -   64    0    0.000    0.000   0.000
pi@raspberrypi:~ $ sudo service ntp status
● ntp.service - Network Time Service
   Loaded: loaded (/lib/systemd/system/ntp.service; enabled; vendor preset: enabled)
   Active: active (running) since Mon 2020-07-27 13:32:12 CEST; 3min 10s ago
     Docs: man:ntpd(8)
  Process: 14759 ExecStart=/usr/lib/ntp/ntp-systemd-wrapper (code=exited, status=0/SUCCESS)
 Main PID: 14771 (ntpd)
    Tasks: 2 (limit: 4915)
   CGroup: /system.slice/ntp.service
           └─14771 /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 111:117

Jul 27 13:32:12 raspberrypi ntpd[14771]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2020-12-28T00:00:00Z last=2017-01-
Jul 27 13:32:12 raspberrypi ntpd[14771]: Listen and drop on 0 v6wildcard [::]:123
Jul 27 13:32:12 raspberrypi ntpd[14771]: Listen and drop on 1 v4wildcard 0.0.0.0:123
Jul 27 13:32:12 raspberrypi ntpd[14771]: Listen normally on 2 lo 127.0.0.1:123
Jul 27 13:32:12 raspberrypi ntpd[14771]: Listen normally on 3 eth0 192.168.1.112:123
Jul 27 13:32:12 raspberrypi ntpd[14771]: Listen normally on 4 lo [::1]:123
Jul 27 13:32:12 raspberrypi ntpd[14771]: Listen normally on 5 eth0 [fe80::8a3:c5c:c521:3f97%2]:123
Jul 27 13:32:12 raspberrypi ntpd[14771]: Listening on routing socket on fd #22 for interface updates
Jul 27 13:32:12 raspberrypi ntpd[14771]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized
Jul 27 13:32:12 raspberrypi ntpd[14771]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized

pi@raspberrypi:~ $

----------

I still have not found out what blocks ntp service to run properly - here is the situation:

pi@raspberrypi:~ $ sudo netstat -planet |grep -v grep | grep :123
pi@raspberrypi:~ $ sudo netstat -planet
Active Internet connections (servers and established)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       User       Inode      PID/Program name    
tcp        0      0 127.0.0.1:5432          0.0.0.0:*               LISTEN      112        16167      639/postgres        
tcp        0      0 127.0.0.1:25            0.0.0.0:*               LISTEN      0          18065      950/exim4          
tcp        0     76 192.168.1.112:47560     192.168.1.102:8073      ESTABLISHED 1000       138564     4081/python        
tcp        0    209 192.168.1.112:60718     192.168.1.113:8073      ESTABLISHED 1000       138570     4120/python        
tcp        0     76 192.168.1.112:47540     192.168.1.102:8073      ESTABLISHED 1000       135728     3373/python        
tcp        0      0 192.168.1.112:60988     192.168.1.113:8073      TIME_WAIT   0          0          -                  
tcp        0      0 192.168.1.112:60978     192.168.1.113:8073      TIME_WAIT   0          0          -                  
tcp        0      0 192.168.1.112:47532     192.168.1.102:8073      ESTABLISHED 1000       137419     2974/python        
tcp        0     38 192.168.1.112:60698     192.168.1.113:8073      ESTABLISHED 1000       138398     3587/python        
tcp        0     19 192.168.1.112:60714     192.168.1.113:8073      ESTABLISHED 1000       138491     3968/python        
tcp        0     19 192.168.1.112:47544     192.168.1.102:8073      ESTABLISHED 1000       137200     3623/python        
tcp        0      0 192.168.1.112:60980     192.168.1.113:8073      TIME_WAIT   0          0          -                  
tcp        0      0 192.168.1.112:42724     50.235.87.130:80        TIME_WAIT   0          0          -                  
tcp        0    323 192.168.1.112:47556     192.168.1.102:8073      ESTABLISHED 1000       136003     3978/python        
tcp        0     57 192.168.1.112:47552     192.168.1.102:8073      ESTABLISHED 1000       138466     3920/python        
tcp        0      0 192.168.1.112:47820     192.168.1.102:8073      TIME_WAIT   0          0          -                  
tcp        0      0 192.168.1.112:60986     192.168.1.113:8073      TIME_WAIT   0          0          -                  
tcp        0    266 192.168.1.112:60710     192.168.1.113:8073      ESTABLISHED 1000       139459     3962/python        
tcp        0     76 192.168.1.112:60704     192.168.1.113:8073      ESTABLISHED 1000       137986     3739/python        
tcp        0      0 192.168.1.112:47826     192.168.1.102:8073      TIME_WAIT   0          0          -                  
tcp        0   1463 192.168.1.112:60694     192.168.1.113:8073      ESTABLISHED 1000       136998     3280/python        
tcp        0      0 192.168.1.112:56028     167.99.168.121:22081    TIME_WAIT   0          0          -                  
tcp        0      0 192.168.1.112:47818     192.168.1.102:8073      TIME_WAIT   0          0          -                  
tcp        0      0 192.168.1.112:45470     167.99.168.121:22083    TIME_WAIT   0          0          -                  
tcp        0     19 192.168.1.112:60690     192.168.1.113:8073      ESTABLISHED 1000       135673     3084/python        
tcp        0      0 192.168.1.112:47828     192.168.1.102:8073      TIME_WAIT   0          0          -                  
tcp        0     19 192.168.1.112:60702     192.168.1.113:8073      ESTABLISHED 1000       138426     3679/python        
tcp        0     19 192.168.1.112:47550     192.168.1.102:8073      ESTABLISHED 1000       139436     3866/python        
tcp        0    190 192.168.1.112:47536     192.168.1.102:8073      ESTABLISHED 1000       135704     3261/python        
tcp6       0      0 :::80                   :::*                    LISTEN      0          16122      572/apache2        
tcp6       0      0 ::1:3350                :::*                    LISTEN      0          15045      518/xrdp-sesman    
tcp6       0      0 ::1:5432                :::*                    LISTEN      112        16166      639/postgres        
tcp6       0      0 ::1:25                  :::*                    LISTEN      0          18066      950/exim4          
tcp6       0      0 :::3389                 :::*                    LISTEN      113        16190      538/xrdp            
tcp6       0   1099 192.168.1.112:3389      192.168.1.111:51982     ESTABLISHED 113        23640      1925/xrdp          
pi@raspberrypi:~ $
--------------

Ulli, ON5KQ

P.S.: 192.168.1.102 and 192.168.1.113 are my two kiwis running...
I run a different NTP service on my host windows PC, as I occasional do some tests with experimental antennas and my ELAD-SDR rx using wsjt-x

[Rob]

Hi Ulli,

I'm sorry for your problems, but none of the other six beta test Pi 3/4s have any NTP problems, and WD did only 'sudo apt install ntp' to get it running on them.

So if 'ntpq -p' shows no lock, I suggest you explore the Raspberry Pi forums for help.

Rob

[Ulli]

Ok Rob, I will do so...
For the moment wd is spotting fine and slight difference of system-time (well below 1sec!) does not change further  from when I set it manually a few hours ago. However ntp errors still persist according to the ntp status report...

I must send compliments anyway, because you finally found the reason for the parsing errors. It was strange, sometimes they happen more often than other times. I haven't seen any with vers. 2.9h - excellent! Incredible you found the reason for this strange behavour... Afterwords it sounds logical, but finding it, is a completely different thing...hi

Unfortunately I couldn't help with searching for it as I was not available a few days...

My raspberry running very hot - so I wonder this may be a reason - SD-card failures ?
I have ordered a different case so it runs cooler soon - at the moment temp is between 65 and 80c all the time...

Ulli, ON5MQ

[Rob]

check to see if your Pi's fan is running.

i use the passive heat sink metal cases for my Pis

On Mon, Jul 27, 2020 at 8:26 AM Ulli [via wsprdaemon] <[hidden email]> wrote:

Ok Rob, I will do so...
For the moment wd is spotting fine and slight difference of system-time (well below 1sec!) does not change further  from when I set it manually a few hours ago. However ntp errors still persist according to the ntp status report...

I must send compliments anyway, because you finally found the reason for the parsing errors. It was strange, sometimes they happen more often than other times. I haven't seen any with vers. 2.9h - excellent! Incredible you found the reason for this strange behavour... Afterwords it sounds logical, but finding it, is a completely different thing...hi

Unfortunately I couldn't help with searching for it as I was not available a few days...

My raspberry running very hot - so I wonder this may be a reason - SD-card failures ?
I have ordered a different case so it runs cooler soon - at the moment temp is between 65 and 80c all the time...

Ulli, ON5MQ

---

If you reply to this email, your message will be added to the discussion below:

http://wsprdaemon.224604.n8.nabble.com/Problem-No-decodes-after-complete-reinstall-tp132p138.html

To start a new topic under wsprdaemon, email [hidden email]
To unsubscribe from wsprdaemon, click here.
NAML

--

[Ulli]

The whole time synchonization problem is solved !
It turns out a LAN-switch caused the error

The old HP procurve switcher blocks NTP on the network (and many other services) when Auto DoS  funcionality is enabled. This is certainly not the intended 'feature' - so I consider it a bug.
After I have found the flaw, I also find a lot written on the Internet forums ...

I disabled the function in the switcher menu and now ntp synchonization works fine...


Ulli