Wrong logging time when executing tasks

[yerrysherry]

Hallo,

We have same problems with time when a task is started. The time is 2 hours in the future. We don't have any clue why.

$ semaphore version
v2.9.2

$ timedatectl
               Local time: Thu 2023-09-07 13:24:30 CEST
           Universal time: Thu 2023-09-07 11:24:30 UTC
                 RTC time: Thu 2023-09-07 11:24:30
                Time zone: Europe/Brussels (CEST, +0200)
System clock synchronized: yes
              NTP service: active
          RTC in local TZ: no

we are using postgres on another server.

$ timedatectl
               Local time: do 2023-09-07 13:54:00 CEST
           Universal time: do 2023-09-07 11:54:00 UTC
                 RTC time: do 2023-09-07 11:54:00
                Time zone: Europe/Brussels (CEST, +0200)
System clock synchronized: yes
              NTP service: active
          RTC in local TZ: no

$ psql
psql (14.9)
Type "help" for help.

# select * from task where id=85;
-[ RECORD 1 ]--+---------------------------
id             | 85
template_id    | 1
status         | success
playbook       |
environment    | {}
debug          | f
created        | 2023-09-07 13:29:34.600115
start          | 2023-09-07 13:29:36.050935
end            | 2023-09-07 13:29:44.970984
user_id        | 1
dry_run        | f
project_id     | 1
message        |
version        | (null)
commit_hash    | (null)
commit_message |
build_task_id  | (null)
arguments      | (null)
hosts_limit    |
diff           | f

# select * from task__output where task_id=85;
-[ RECORD 1 ]-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
------------
id      | 6686
task_id | 85
task    |
time    | 2023-09-07 13:29:44.758184
output  | \x1B[0;32m            "ff02::2 ip6-allrouters",\x1B[0m
-[ RECORD 2 ]-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
------------
id      | 6687
task_id | 85
task    |
time    | 2023-09-07 13:29:44.758234
output  | \x1B[0;32m            "ff02::3 ip6-allhosts"\x1B[0m
-[ RECORD 3 ]-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
------------
id      | 6688
task_id | 85
task    |
time    | 2023-09-07 13:29:44.758257
output  | \x1B[0;32m        ]\x1B[0m

Regularly, when starting a task, the time is wrong. It's start wrong and then it is correct.

3:29:34 PM Task 85 added to queue
1:29:36 PM Started: 85
1:29:36 PM Run TaskRunner with template: cat
1:29:36 PM Preparing: 85
1:29:36 PM installing static inventory
1:29:36 PM No collections/requirements.yml file found. Skip galaxy install process.
1:29:36 PM No roles/requirements.yml file found. Skip galaxy install process.
1:29:37 PM
1:29:37 PM PLAY [all] *********************************************************************
1:29:37 PM
1:29:37 PM TASK [Gathering Facts] *********************************************************

After we refresh the task in our browser or look back when the task is finished. The time is 2 hours in our future.

3:29:34 PM Task 85 added to queue
3:29:36 PM Started: 85
3:29:36 PM Run TaskRunner with template: cat
3:29:36 PMPreparing: 85
3:29:36 PM installing static inventory
3:29:36 PM No collections/requirements.yml file found. Skip galaxy install process.
3:29:36 PM No roles/requirements.yml file found. Skip galaxy install process.
3:29:37 PM
3:29:37 PM
PLAY [all] *********************************************************************

Looking at the dashboard:

#85 | — | Success | semaphore | in 2 hours | a few seconds |  

The task was a Success in the future.

When we look at the database, the time is correct but when we use the dashboard the time is wrong.

Regards, Gerrit

[miversen33]

I'm seeing the same behavior but in the past. For us, our start time is always "6 hours ago" and I have no idea why

[pawelp29]

I am having the same issue on the latest v2.9.48-beta release running with Docker, which added support for setting the timezone with the TZ env variable. I think this commit was supposed to fix the problem, but it is still not included in any release.

This is a serious issue for me as it makes the log dates hard to understand and thus unreliable. The only solution is to set the timezone back to UTC, but then Cron schedules need to be defined in UTC as well, which makes things even worse (having to change it every half a year for all tasks when there is a summer/winter time change in my country).

[benisdev-py]

same Problem for me with the standalone Version direct on RHEL9 installed and issues with the cron jobs and timezone :(

[blackfeather9]

I'm having the same issue. Reporting in the UI is wrong. Here is an example of me running a task manually. The first timestamp is in the wrong timezone -- the rest are correct.

On the dashboard, even though I just ran the job, it looks like this on completion:

Strangely, cron actually works as desired -- the system is running in the correct time zone, even though it reports otherwise in the UI. A cron job set for 0 7 * * * runs daily at 7AM even though the UI says it was 3AM. Confusing but glad it works when I want it to.

The problem for me is that somewhere the system thinks it's using UTC time. I'm running semaphore:latest w/ postgresql in Docker. I mount the following into both containers:

      - /etc/timezone:/etc/timezone:ro
      - /etc/localtime:/etc/localtime:ro

I am also using the TZ= environment variable on both. When I docker exec in the container and run date, the time is correct. My postgresql.conf also has the correct timezone specified in all areas. Somehow it still thinks it's UTC.

I created a test project and built a fresh semaphore stack with my settings, and confirmed everything was getting the correct timezone by default. But when I created a project and ran my first job, it was still reporting in UTC!

Semaphore is otherwise working great. Happy to test changes or troubleshooting suggestions in a test environment, let me know what I can do to help get this fixed.

[isaacblum]

same issue here

[Ovsyank]

Good afternoon. Same problem. I specified TZ variables for docker containers, and also mounted the /etc/localtime file from the host machine. These options help when starting a task, but when refreshing the page after a completed task, the time is again displayed incorrectly.

[Enissay]

I have setup both TZ variable as well as mounted those files mentionned by @blackfeather9, I checked in the container, the time is correct and synced! however in the UI, it is wrong!

Below sample of a task I just ran shown as yet to be ran in 2 hrs. Worth noting my time is UTC/GMT +2 hours! So my guess it stores it in postgres as GMT, then when read, it adapts it to my TZ. I have not validated in the DB though!

[lug-gh]

In the latest beta (maybe even in an earlier beta) the time is displayed correct: https://github.com/semaphoreui/semaphore/releases/tag/v2.10.26-beta

[blackfeather9]

@lug-gh I just pulled the newest docker image, it shows that it's now running version 2.10.30-865d0e5-1728986347. This should be ahead of the beta you had linked?

I manually kicked off a task and it's showing the correct time now! The task history entries from before I updated the docker image still show incorrect however. I'll monitor my nightly update jobs and confirm new entries at least are in the right time zone now. Now I'm curious what the potential fix was.

[pawelp29]

@blackfeather9 seems like this commit was the fix for this bug - all dates are saved in the database in the UTC timezone now and are displayed in the user's local timezone in the UI (so the fix has been present since v2.10.24-beta). Before that, dates were saved using the local timezone in the database, and then the UI interpreted it as UTC, which caused the time difference to be doubled.

Old tasks from the history still show incorrect time, because they were saved in the database with local timezone - I think the only way to fix it would be to manually convert all the old records to UTC.