• 10 dec 2017: forum version update. In case of issues use this topic.
  • 30 nov 2017: pilight moved servers. In case of issues use this topic.
Hello There, Guest! Login Register


Thread Rating:
  • 0 Vote(s) - 0 Average
  • 1
  • 2
  • 3
  • 4
  • 5
Time based calculations
#1
Since some time I monitor the complains about inconsistencies in the date time values used/reported, mainly caused by the fact that sometimes UTC time is reported while at other occasions system time / local time is used.
Besides afrementioned issue there is another subject that requires attention, commenly known as Segal's law:
A man with a watch knows what time it is.
A man with two watches is never sure.

Why do I rise the issue?
Well first my wife noticed that the moment the lights turned on/off (based on sunrise/sunset) did not match up with ambient light conditions, and when I checked those time events i detected that they did not match up with the sunrise/sunset time reported independently on my weatherstation either.

So I went into the details and noticed, that the datetime time clock values did not match up with the system time.
To verify the issue:
1. Define datetime in config.json
2. Define a ntp server in the settings section
3. Have pilight running for 2 or 3 days.
4. Stop the service
5. Read /etc/pilight/config.json and check the time in the datetime protocol
Code:
{
        "devices": {
                "zeit": {
                        "protocol": [ "datetime" ],
                        "id": [{
                                "longitude": 10.5594,
                                "latitude": 52.2443
                        }],
                        "year": 2016,
                        "month": 3,
                        "day": 17,
                        "hour": 9,
                        "minute": 27,
                        "second": 52,
                        "weekday": 5,
                        "dst": 0
                },
6. Start the pilight service
7. Stop the pilight service
8. Read /etc/pilight/config.json again:
Code:
{
    "devices": {
        "zeit": {
            "protocol": [ "datetime" ],
            "id": [{
                "longitude": 10.5594,
                "latitude": 52.2443
            }],
            "year": 2016,
            "month": 3,
            "day": 17,
            "hour": 9,
            "minute": 5,
            "second": 13,
            "weekday": 5,
            "dst": 0
        },

As you can see, on my Pi2 the minutes for the datetime protocol went back in time, actually upon start/restart of the pilight service they were synchronized with the systemtime. The update happens, whenever pilight starts using the function gmtime_r in /pilight/libs/pilight/protocols/API/datetime.c.

In my opinion, gmtime_r updates the local structure only, and those values get incremented.
Other modules have their own local structure as well.
I think we do need one global structure for pilight, updated by a central instance.

There is another issue, gettimeofday() is not MONOTONIC, e.q. it can jump in time, but there are certain instances (for example the computation of pulse durations) for which this behaviour is undesirable.
 
Reply
#2
Quote:In my opinion, gmtime_r updates the local structure only, and those values get incremented.
Other modules have their own local structure as well.
I think we do need one global structure for pilight, updated by a central instance.

sounds good. is there any chance about getting a callback for time changes? (ntp or manual)
if not 1 second or up to 1 minute polling would be fine i think?

Quote:There is another issue, gettimeofday() is not MONOTONIC, e.q. it can jump in time, but there are certain instances (for example the computation of pulse durations) for which this behaviour is undesirable.

you are definitely right. i noticed this issue while implementing csma/cd and fixed it in my fork. (source)

off topic: i really like that the receiving process is kept in the hardware code in the rewrite!
 
Reply
#3
What currently happens is that indeed the gmtime_r is used in datetime and sunriseset. I would assume that because gmtime_r calculates UTC time all instances would generate the same time. Then there are some global NTP functions.

After the gmtime_r, the code increases the time with the timezone and when necessary with the global NTP time difference. This should in theory all generate the same time. As said, gmtime_r is locally called but should generate UTC, NTP and timezones are global numbers that also should be the same for all functions.

https://github.com/pilight/pilight/blob/...#L137-L158
 
Reply
#4
pilight Time on my Pi2 is out of sync again.
At the time in question I created an image for my new Pi3 using the Pi2 USB ports, that has triggered a hard reboot.

sde1/sde2 are the partitions on the sd card.
Code:
Mar 18 14:22:49 pi_65 kernel: [408862.651568]  sde: sde1 sde2
Mar 18 14:22:49 pi_65 kernel: [408862.667758] sd 2:0:0:4: [sde] Attached SCSI removable disk
Mar 18 14:25:50 pi_65 kernel: [409043.689144]  sde: sde1 sde2
Mar 18 14:27:12 pi_65 kernel: [409126.412359] usb 1-1.3: USB disconnect, device number 6

Upon reboot the system time has changed.
Code:
Mar 18 14:17:04 pi_65 rsyslogd: [origin software="rsyslogd" swVersion="8.4.2" x-pid="393" x-info="http://www.rsyslog.com"] start
Mar 18 14:17:04 pi_65 systemd-modules-load[83]: Inserted module 'i2c_dev'
Mar 18 14:17:04 pi_65 systemd[1]: Mounted Configuration File System.
Mar 18 14:17:04 pi_65 systemd[1]: Started Apply Kernel Variables.
Mar 18 14:17:04 pi_65 systemd[1]: Started Create Static Device Nodes in /dev.
Mar 18 14:17:04 pi_65 kernel: [    0.000000] Booting Linux on physical CPU 0xf00
Mar 18 14:17:04 pi_65 systemd[1]: Starting udev Kernel Device Manager...
Mar 18 14:17:04 pi_65 kernel: [    0.000000] Initializing cgroup subsys cpuset
Mar 18 14:17:04 pi_65 kernel: [    0.000000] Initializing cgroup subsys cpu
Mar 18 14:17:04 pi_65 systemd[1]: Started udev Kernel Device Manager.
Mar 18 14:17:04 pi_65 kernel: [    0.000000] Initializing cgroup subsys cpuacct
Mar 18 14:17:04 pi_65 kernel: [    0.000000] Linux version 4.1.19-v7+ (dc4@dc4-XPS13-9333) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611) ) #851 SMP Sat Mar 5 22:58:42 GMT 2016
Mar 18 14:17:04 pi_65 kernel: [    0.000000] CPU: ARMv7 Processor [410fc075] revision 5 (ARMv7), cr=10c5387d
Mar 18 14:17:04 pi_65 kernel: [    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
Mar 18 14:17:04 pi_65 systemd[1]: Starting Copy rules generated while the root was ro...

.... ....
.... ....

Mar 18 14:17:12 pi_65 systemd[1]: Started Serial Getty on ttyAMA0.
Mar 18 14:17:12 pi_65 systemd[1]: Starting Login Prompts.
Mar 18 14:17:12 pi_65 systemd[1]: Reached target Login Prompts.

The NTP daemon starts up
Code:
Mar 18 14:17:12 pi_65 systemd[1]: Started LSB: Start NTP daemon.
Mar 18 14:17:12 pi_65 ntpd[547]: Listen and drop on 1 v6wildcard :: UDP 123
Mar 18 14:17:12 pi_65 ntpd[547]: Listen normally on 2 lo 127.0.0.1 UDP 123
Mar 18 14:17:12 pi_65 ntpd[547]: Listen normally on 3 eth0 192.168.0.89 UDP 123
Mar 18 14:17:12 pi_65 ntpd[547]: Listen normally on 4 lo ::1 UDP 123
Mar 18 14:17:12 pi_65 ntpd[547]: Listen normally on 5 eth0 fe80::ec9b:940e:3305:2408 UDP 123
Mar 18 14:17:12 pi_65 ntpd[547]: peers refreshed
Mar 18 14:17:12 pi_65 ntpd[547]: Listening on routing socket on fd #22 for interface updates

The pilight service starts up
Code:
Mar 18 14:17:12 pi_65 pilight[530]: Starting : pilight.
Mar 18 14:17:12 pi_65 systemd[1]: Started LSB: Starts pilight-daemon.
Mar 18 14:17:12 pi_65 systemd[1]: Starting Multi-User System.
Mar 18 14:17:12 pi_65 systemd[1]: Reached target Multi-User System.
Mar 18 14:17:12 pi_65 systemd[1]: Starting Graphical Interface.
Mar 18 14:17:12 pi_65 systemd[1]: Reached target Graphical Interface.
Mar 18 14:17:12 pi_65 systemd[1]: Starting Update UTMP about System Runlevel Changes...
Mar 18 14:17:12 pi_65 kernel: [   15.533534] random: nonblocking pool is initialized
Mar 18 14:17:12 pi_65 systemd[1]: Started Update UTMP about System Runlevel Changes.
Mar 18 14:17:12 pi_65 systemd[1]: Startup finished in 2.582s (kernel) + 12.780s (userspace) = 15.362s.

NTP updates the system time, time difference is 56 minutes.
Code:
Mar 18 15:13:35 pi_65 systemd[1]: Time has been changed
Mar 18 15:13:36 pi_65 dhcpcd[525]: eth0: no IPv6 Routers available

pilight time is now 56 minutes ahead of system time.
timestamp values before stopping pilight service
Code:
[{"type":8,"devices":["zeit"],"values":{"timestamp":1458336856,"dst":0,"second":32,"minute":30,"hour":23,"weekday":6,"day":18,"month":3,"year":2016}},{"type":3,"devices":["sunshine"],"values":{"timestamp":1458318824,"sun":"set","sunset":18.30,"sunrise":6.24}},{"type":14,"devices":["IPcheckTV"],"values":{"timestamp":1458322615,"state":"connected"}},{"type":1,"devices":["TVState"],"values":{"timestamp":0,"state":"on"}},{"type":1,"devices":["TVBeleuchtung"],"values":{"timestamp":0,"state":"on"}},{"type":1,"devices":["TVAutomatic"],"values":{"timestamp":0,"state":"on"}},{"type":1,"devices":["LampenZeitschaltUhr"],"values":{"timestamp":1458323024,"state":"on"}},{"type":1,"devices":["Trigger_EG_Buero"],"values":{"timestamp":0,"state":"on"}},{"type":1,"devices":["Trigger_EG_Flur"],"values":{"timestamp":0,"state":"on"}},{"type":1,"devices":["Trigger_OG_Klavier"],"values":{"timestamp":0,"state":"on"}},{"type":1,"devices":["Trigger_OG_Tisch"],"values":{"timestamp":0,"state":"on"}},{"type":3,"devices":["TH_Anbau"],"values":{"timestamp":1458336760,"battery":1,"humidity":73.00,"temperature":9.83}},{"type":3,"devices":["TH_Keller"],"values":{"timestamp":1458336810,"battery":0,"humidity":48.00,"temperature":14.72}},{"type":3,"devices":["TH_Aussen"],"values":{"timestamp":1458336808,"battery":1,"humidity":80.00,"temperature":5.50}},{"type":3,"devices":["TH_Bad"],"values":{"timestamp":1458336821,"battery":1,"humidity":36.00,"temperature":18.88}},{"type":3,"devices":["TH_SZimmer"],"values":{"timestamp":1458336838,"battery":1,"humidity":41.00,"temperature":16.77}},{"type":15,"devices":["LBL_TH_Anbau"],"values":{"timestamp":1458336709,"color":"black","label":"18.03.2016 23:28"}},{"type":15,"devices":["LBL_TH_Keller"],"values":{"timestamp":1458336810,"color":"black","label":"18.03.2016 23:29"}},{"type":15,"devices":["LBL_TH_Aussen"],"values":{"timestamp":1458336709,"color":"black","label":"18.03.2016 23:28"}},{"type":15,"devices":["LBL_TH_Bad"],"values":{"timestamp":1458336709,"color":"black","label":"18.03.2016 23:28"}},{"type":15,"devices":["LBL_TH_SZimmer"],"values":{"timestamp":1458336837,"color":"black","label":"18.03.2016 23:30"}},{"type":1,"devices":["EG_Buero"],"values":{"timestamp":1458323024,"state":"on"}},{"type":1,"devices":["EG_Flur"],"values":{"timestamp":1458323025,"state":"on"}},{"type":1,"devices":["OG_Klavier"],"values":{"timestamp":1458323026,"state":"on"}},{"type":1,"devices":["OG_Tisch"],"values":{"timestamp":1458323025,"state":"on"}}]

timestamp values immediately after restart of pilight service
Code:
[{"type":8,"devices":["zeit"],"values":{"timestamp":1458336872,"dst":0,"second":32,"minute":34,"hour":22,"weekday":6,"day":18,"month":3,"year":2016}},{"type":3,"devices":["sunshine"],"values":{"timestamp":1458336868,"sun":"set","sunset":18.30,"sunrise":6.24}},{"type":14,"devices":["IPcheckTV"],"values":{"timestamp":0,"state":"connected"}},{"type":1,"devices":["TVState"],"values":{"timestamp":0,"state":"on"}},{"type":1,"devices":["TVBeleuchtung"],"values":{"timestamp":0,"state":"on"}},{"type":1,"devices":["TVAutomatic"],"values":{"timestamp":0,"state":"on"}},{"type":1,"devices":["LampenZeitschaltUhr"],"values":{"timestamp":0,"state":"on"}},{"type":1,"devices":["Trigger_EG_Buero"],"values":{"timestamp":0,"state":"on"}},{"type":1,"devices":["Trigger_EG_Flur"],"values":{"timestamp":0,"state":"on"}},{"type":1,"devices":["Trigger_OG_Klavier"],"values":{"timestamp":0,"state":"on"}},{"type":1,"devices":["Trigger_OG_Tisch"],"values":{"timestamp":0,"state":"on"}},{"type":3,"devices":["TH_Anbau"],"values":{"timestamp":0,"battery":1,"humidity":74.00,"temperature":9.83}},{"type":3,"devices":["TH_Keller"],"values":{"timestamp":0,"battery":0,"humidity":48.00,"temperature":14.72}},{"type":3,"devices":["TH_Aussen"],"values":{"timestamp":0,"battery":1,"humidity":80.00,"temperature":5.50}},{"type":3,"devices":["TH_Bad"],"values":{"timestamp":0,"battery":1,"humidity":36.00,"temperature":18.88}},{"type":3,"devices":["TH_SZimmer"],"values":{"timestamp":0,"battery":1,"humidity":41.00,"temperature":16.77}},{"type":15,"devices":["LBL_TH_Anbau"],"values":{"timestamp":0,"color":"black","label":"18.03.2016 23:30"}},{"type":15,"devices":["LBL_TH_Keller"],"values":{"timestamp":0,"color":"black","label":"18.03.2016 23:29"}},{"type":15,"devices":["LBL_TH_Aussen"],"values":{"timestamp":0,"color":"black","label":"18.03.2016 23:30"}},{"type":15,"devices":["LBL_TH_Bad"],"values":{"timestamp":0,"color":"black","label":"18.03.2016 23:30"}},{"type":15,"devices":["LBL_TH_SZimmer"],"values":{"timestamp":0,"color":"black","label":"18.03.2016 23:30"}},{"type":1,"devices":["EG_Buero"],"values":{"timestamp":0,"state":"on"}},{"type":1,"devices":["EG_Flur"],"values":{"timestamp":0,"state":"on"}},{"type":1,"devices":["OG_Klavier"],"values":{"timestamp":0,"state":"on"}},{"type":1,"devices":["OG_Tisch"],"values":{"timestamp":0,"state":"on"}}]
 
Reply
#5
But what does pilight say when syncing itself with NTP?
 
Reply
#6
Unfortunately by the time i detected the issue the earliest entry in pilight.log.old was after 16:00.
What should i expect ?

I assume the following happens:

(core) ntp.c detects that the time is off and sets -diff (in seconds) and the isntpsynced flag
(core) ntp.c provides several function calls to access those local variables.

(API) datetime.c calculates the time offset to UTC
(API) datetime.c detects that (core) ntpdiff is true and adds that ntp offset to UTC.
- by the time this happens that is not necessarily any longer the case.

I was unable to identify a semaphore ensuring that (core) ntp.c diff value is always kept in sync with the systemclock (in particular the function calls getntpdiff() and isntpsynced() ).

In my opinion it could be that (API) datetime.c reads an updated systemtime and adds an outdated (core) diff value to it. For all future calls (core) ntp is in sync with the system clock, therefore the diff value is zero, and the clock values in pilight remain not in sync with the systemclock.
 
Reply
#7
When you configured the ntp servers you should see this message:
https://github.com/pilight/pilight/blob/...ntp.c#L164
 
Reply
#8
The oldest pilight.log.old entry is from 1600, so i have no entry for the time period 1400 to 1600 anymore. I have turned of all other pilight instances and rebooted the machine properly for preparation of another test in a day or two.

Update: After reboot the difference in time was 14 seconds.
Code:
Mar 19 01:25:04 pi_65 kernel: [   15.610772] random: nonblocking pool is initialized
Mar 19 01:25:18 pi_65 systemd[1]: Time has been changed
Mar 19 01:25:19 pi_65 dhcpcd[525]: eth0: no IPv6 Routers available

Systemtime and timestamp information (webgui) are off by 7 seconds
The calculated time offset is -7 seconds
Code:
root@pi_65:/var/log# cat pilight.log | grep offset
[Mar 19 00:25:04:369924] pilight-daemon: INFO: rule #22 Rule_TH_Bad was parsed in 0.001151 seconds
[Mar 19 00:25:04:371191] pilight-daemon: INFO: rule #23 Rule_TH_SZimmer was parsed in 0.001205 seconds
[Mar 19 00:25:04:386099] pilight-daemon: INFO: version v5.0-411-ga3f1764
[Mar 19 00:25:04:486496] pilight-daemon: INFO: no pilight daemon found, daemonizing
[Mar 19 00:25:04:487558] pilight-daemon: INFO: daemon listening to port: 41016
[Mar 19 00:25:04:504434] pilight-daemon: INFO: new client, ip: 127.0.0.1, port: 51755
[Mar 19 00:25:04:594312] pilight-daemon: INFO: time offset found of -7 seconds
[Mar 19 00:25:04:617115] pilight-daemon: INFO: new client, ip: 192.168.0.89, port: 42367
[Mar 19 00:25:04:617303] pilight-daemon: INFO: new client, ip: 192.168.0.89, port: 42366
[Mar 19 00:25:04:945278] pilight-daemon: INFO: datetime #1 10.559400:52.244300 seems to be in timezone: Europe/Berlin
[Mar 19 00:25:19:791489] pilight-daemon: INFO: executed rule: Rule_TH_SZimmer
[Mar 19 00:25:19:791523] pilight-daemon: INFO: started "label" action for device "LBL_TH_SZimmer"
[Mar 19 00:25:19:792036] pilight-daemon: INFO: stopped "label" action for device "LBL_TH_SZimmer"
root@pi_65:/var/log#

Stopping and starting the service again fixes the problem.
Code:
root@pi_65:/var/log# service pilight stop
root@pi_65:/var/log# service pilight start
root@pi_65:/var/log# cat pilight.log | grep offset
[Mar 19 00:41:18:332606] pilight-daemon: INFO: time offset found of 0 seconds
root@pi_65:/var/log#
 
Reply
  


Possibly Related Threads...
Thread Author Replies Views Last Post
  Sunrise and daylight saving time issue apartmedia 21 2,917 04-22-2018, 07:44 PM
Last Post: curlymo
  Rule based sending ot reliable Alex 7 1,510 12-03-2017, 11:09 AM
Last Post: Alex
Bug Full cpu usage after random time andiwand 4 2,034 05-01-2016, 09:05 PM
Last Post: andiwand
  [Solved] Time Stamp Information wo_rasp 5 2,187 03-05-2016, 11:29 PM
Last Post: curlymo

Forum Jump:


Browsing: 1 Guest(s)