After upgrade to IOT v10 CLOCK timers revert to UTC. DateTime timers ok

EricEdberg · January 7, 2020, 3:30pm

I delayed upgrading to IOT v10 after reading issues… Finally downloaded the Docker v10 image and rebooted my Ubuntu host. All legacy Rules that used the built-in “Clock” timer began firing 6 hours late (my TZ is: CST6CDT). Timers that use the DateTime add-on work as expected. I can add new Rules if I program in UTC time.

The Ubuntu server TZ is: America/Chicago (CST, -0600).
The container date is: Tue Jan 7 15:14:23 UTC 2020
The Web Things add-on is configured as: America/Chicago

The container executes in UTC time, which is ok, as long as Clock timers recognized my local TZ CST6.

Any hints on how to configure Clock timers to use CST6 or how to change the TZ of the container?

mstegeman · January 7, 2020, 3:45pm

The clock-based rules all operate based on the gateway’s time zone, which in this case is UTC. We need to be able to set the time zone of the Docker container. I’ll take a look at that today.

EricEdberg · January 7, 2020, 4:09pm

Check out this discussion. For linux, it appears to be a couple easy ways when starting the container. I’ll test the suggested Linux solutions when starting the container later today.

EricEdberg · January 7, 2020, 4:49pm

I just tested passing the TZ variable in the docker run command and it correctly set the TZ of the running container. A new test Clock rule worked as expected. I assume that the method of linking /etc/timzone from the server into the container could work too and will test later today.

portion of my test

docker run -d -e TZ=America/Chicago --device /dev/ttyACM0:/dev/ttyACM0

Updating the Docker instructions to state the IOT container executes in UTC and Clock timers must be used relative to that TZ, and then include instructions about passing in the local TZ is a simple resolution.

When inspecting the log after restarting IOT I noticed numerous errors from DateTime so I cleared the log and rebooted the server.

This is a small portion of the log after reboot:
>
> 2020-01-07 10:42:25.444 INFO : zwave: node4 valueChanged: 4-38-1-0:Level property: on = false
> 2020-01-07 10:42:25.445 INFO : zwave: node4 valueChanged: 4-38-1-0:Level property: level = 0.0% (zw: 0)
> 2020-01-07 10:42:35.494 INFO : zwave: node2 valueChanged: 2-38-1-0:Level property: on = true
> 2020-01-07 10:42:35.500 INFO : zwave: node2 valueChanged: 2-38-1-0:Level property: level = 100.0% (zw: 99)
> 2020-01-07 10:44:32.226 INFO : Failed to import platform utilities for linux-unknown. Network and system configuration features will be disabled.
> 2020-01-07 10:44:33.944 INFO : Opening database: /home/node/.mozilla-iot/log/logs.sqlite3
> 2020-01-07 10:44:35.004 INFO : HTTP server listening on port 8080
> 2020-01-07 10:44:35.650 INFO : migrateThing DateTimeDevice
> 2020-01-07 10:44:35.650 INFO : migrateThing DateTimeDevice
> 2020-01-07 10:44:35.654 ERROR : Error getting value for thingId: DateTimeDevice property: hour
> 2020-01-07 10:44:35.654 ERROR : getProperty: device: DateTimeDevice not found.
> 2020-01-07 10:44:35.655 ERROR : Error getting value for thingId: DateTimeDevice property: minute
> 2020-01-07 10:44:35.655 ERROR : getProperty: device: DateTimeDevice not found.
> 2020-01-07 10:44:35.656 WARN : Rule get failed { code: 500,
> message: ‘getProperty: device: DateTimeDevice not found.’ }
> 2020-01-07 10:44:35.657 WARN : Rule get failed { code: 500,
> message: ‘getProperty: device: DateTimeDevice not found.’ }
> 2020-01-07 10:44:35.657 ERROR : Error getting value for thingId: DateTimeDevice property: hour
> 2020-01-07 10:44:35.658 ERROR : getProperty: device: DateTimeDevice not found.
> 2020-01-07 10:44:35.658 ERROR : Error getting value for thingId: DateTimeDevice property: minute
> 2020-01-07 10:44:35.658 ERROR : getProperty: device: DateTimeDevice not found.

Later, DateTime seems to be reporting normally:

2020-01-07 10:44:49.588 INFO   : date-time: config.py:20 INFO config {'timezone': 'America/Chicago', 'lat': '41.790506', 'lng': '-88.192503', 'horizon': '-0:34', 'log_level': '
INFO'}
2020-01-07 10:44:49.589 INFO   : date-time: date_adapter.py:28 INFO START Pairing
2020-01-07 10:44:49.589 INFO   : date-time: date_adapter.py:35 INFO Log level 10
2020-01-07 10:44:49.797 INFO   : date-time: util.py:89 INFO CALC_SUNRISE today.utc: 2020/1/7 16:44:50 sunrise: 2020/1/8 13:19:57 sunrise_local: 2020-01-08 07:19:57.087320-06:00
2020-01-07 10:44:49.798 INFO   : date-time: util.py:103 INFO CALC_SUNSET today.utc: 2020/1/7 16:44:50 sunset: 2020/1/7 22:37:59 sunset_local: 2020-01-07 16:37:58.867794-06:00
2020-01-07 10:44:49.798 INFO   : date-time: util.py:17 INFO DTS lat: 41.790506 lng: -88.192503
2020-01-07 10:44:49.798 INFO   : date-time: util.py:89 INFO CALC_SUNRISE today.utc: 2020/1/7 16:44:50 sunrise: 2020/1/8 13:19:57 sunrise_local: 2020-01-08 07:19:57.087320-06:00
2020-01-07 10:44:49.798 INFO   : date-time: util.py:103 INFO CALC_SUNSET today.utc: 2020/1/7 16:44:50 sunset: 2020/1/7 22:37:59 sunset_local: 2020-01-07 16:37:58.867794-06:00
2020-01-07 10:44:49.799 INFO   : date-time: date_device.py:73 INFO sunset: 2020-01-07 16:37:58.867794-06:00 sunrise: 2020-01-08 07:19:57.087320-06:00
2020-01-07 10:44:49.799 INFO   : date-time: date_device.py:41 INFO poll START for DateTime
2020-01-07 10:44:49.799 INFO   : date-time: date_device.py:31 INFO DateTimeDevice started
2020-01-07 10:44:49.799 INFO   : date-time: AddonManagerProxy: handle_device_added: DateTimeDevice
2020-01-07 10:44:49.800 INFO   : date-time: date_adapter.py:47 INFO END Pairing
2020-01-07 10:44:53.064 INFO   : getValue for property weekend for: DateTime returning false
2020-01-07 10:44:53.064 INFO   : getValue for property even_hour for: DateTime returning true
2020-01-07 10:44:53.065 INFO   : getValue for property even for: DateTime returning true
2020-01-07 10:44:53.065 INFO   : getValue for property dark for: DateTime returning false
2020-01-07 10:44:53.065 INFO   : getValue for property hour for: DateTime returning 10
2020-01-07 10:44:53.065 INFO   : getValue for property minute for: DateTime returning 44
2020-01-07 10:44:53.066 INFO   : getValue for property minutes5 for: DateTime returning 40
2020-01-07 10:44:53.066 INFO   : getValue for property weekday for: DateTime returning Tuesday

I’ll need to test some more…

riccardo.cossu · January 7, 2020, 4:53pm

The easiest way to solve this is to use docker-compose and add something like that:

volumes:
  - /my/path:/home/node/.mozilla-iot
  - /etc/timezone:/etc/timezone:ro
  - /etc/localtime:/etc/localtime:ro

This will sync the timezone with the one set in the host; works for me

EricEdberg · January 7, 2020, 5:00pm

Thanks,
I’ll try that next which was the second solution I was going to test.
May be using the volume solution will resolve the DateTime errors I’m now seeing.

Wonder why Clock was not confused when running IOT 9.2…

EricEdberg · January 7, 2020, 5:27pm

Restarted using volumes overriding /etc/timezone volume worked ok but /etc/localtime is a symlink which still points to UTC in the container

docker run -d -v /etc/timezone:/etc/timezone:ro -v /etc/localtime:/etc/localtime:ro

Inside the container:

lrwxrwxrwx 1 root root 27 Dec 23 18:00 /etc/localtime -> /usr/share/zoneinfo/Etc/UTC

Will need to research why DateTime addon is complaining. DateTime timers do work ok which is good.

Will continue debugging later today when I get more time.

mstegeman · January 7, 2020, 6:50pm

@EricEdberg I’ve updated the README for the Docker image with instructions to set the time zone. Thanks for testing things.

The DateTime errors are just normal startup things, nothing to worry about.

And, things work differently since 0.10. Timers used to be all in UTC, but now respect the gateway’s time zone.

sandandsnow · January 7, 2020, 7:26pm

Hi. I encountered some temporary time mismatch issues too, but it seems to be okay now. However, in trying to figure out why a time-based rule wasn’t working, I observed that the Pi was in the right time zone, the gateway localization settings were set to same time, but the logs were in UTC. So, I suspected that the gateway actually thought it was UTC. At that point, I thought “wouldn’t it be nice if the gateway UI told me what time the gateway was actually using”, e.g. under network settings (or somewhere more logical)

riccardo.cossu · January 8, 2020, 8:36am

I tried following the new instructions on docker image, but I am not sure it’s working ok: the gateway seems to use the correct timezone, but /etc/timezone still points to UTC.
For the time being I will keep on mounting my own /etc/timezone to be sure; it’s a “production” instance, meaning I count on it for my confort, so I staying safe

EricEdberg · January 8, 2020, 2:14pm

When setting TZ using an environmental variable on the docker command line (-e TZ=xxx), /etc/timezone inside a container remains the default. It only physically changes when using a volume to overload it. In either case, the Gateway starts using the specified timezone.

Setting TZ in the environment before starting a process is common for docker programs to initialize or overload options in containers processes. In this case, it is not a guarantee other processes that start inside the container (manually or otherwise) won’t have issues as Riccardo frets about.

What: Overloading /etc/localtime using a volume:

To be complete, I tried again to mount a volume to overload /etc/localtime in the container referencing the physical file /etc/localtime points to using this docker option:

-v /usr/share/zoneinfo/America/Chicago:/etc/localtime:ro

The volume failed to overload the symlink: /etc/localtime, inside the container which still is linked to a local physical file …ETC/UTC. Probably related to volumes overloading symlinks and my Ubuntu server.

root@elelinux:/home/node# ls -l /etc/localtime
lrwxrwxrwx 1 root root 27 Dec 23 18:00 /etc/localtime -> /usr/share/zoneinfo/Etc/UTC

Thanks for updating the instructions on the Docker readme.

Note that I will attempt to debug the DateTime errors next. Hopefully they will disappear over a day or 3 and a restart or 2 Could they be dangling/orphaned timer events linked to removed things?

Note 2: My log also spouts errors about deleted/removed add-ons that did not clean up and remove themselves properly, but I digress for now and will leave that for later.

Eric L. Edberg

riccardo.cossu · January 8, 2020, 2:40pm

Ok thanks for the infos; I will stay with /etc/timezone mount, it seems safer and I see no real drawback in it. I could also use a different file other than the system one, to decouple host and container TZs, but I see no real reason to do so at present.
I also use Ubuntu server and overwriting /etc/localtime symlink doesn’t seem to work either.

mstegeman · January 8, 2020, 4:52pm

You’re both right. I just made a change to fully set the time zone, based on the TZ environment variable, so that should take care of everything. I’ll be rebuilding the images shortly.

@EricEdberg As I said, the DateTime messages you’re seeing are expected. The rules engine starts up very early in the gateway’s startup process, before any devices are detected, so those messages occur. They’re not an issue.

riccardo.cossu · January 8, 2020, 6:28pm

great news, I checked out your change and that should definitely do the trick; it’s the best part of both approaches and it makes the mount options useless.
Thanks again, looking forward for the updated image

EricEdberg · January 10, 2020, 1:45pm

I’ll take your expert word that it’s an initialization dependency issue. Seeing errors in the log that are not really errors is an issue though that one can live with I guess… Thanks again for the followup.