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.