Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Celery timezone use default UTC timezone ignoring settings. #4842

Open
1 of 2 tasks
trianglesis opened this issue Jun 22, 2018 · 22 comments · May be fixed by #8385
Open
1 of 2 tasks

Celery timezone use default UTC timezone ignoring settings. #4842

trianglesis opened this issue Jun 22, 2018 · 22 comments · May be fixed by #8385

Comments

@trianglesis
Copy link

trianglesis commented Jun 22, 2018

Checklist

Celery 4.2.0

  • I have included the output of celery -A proj report in the issue.
    (if you are not able to do this, then at least specify the Celery
    version affected).
  • I have verified that the issue exists against the master branch of Celery.

Steps to reproduce

Use any TZ settings in celery settings or Django

    app.conf.timezone   = 'Europe/London'
    app.conf.enable_utc   = True

Celery will ignore those settings, and set time equal to London -1 hour (just like winter time)

Expected behavior

Celery should use TZ as it was set in settings.

Actual behavior

Celery use UTC default instead.

Related:
#2649
#4006

Steps to possible fix:

Firstly, this probably should be the datetime.now instance, not datetime.utcnow(), because why would we decide to UTC already an UTC?

def to_utc(dt):
    """Convert naive :class:`~datetime.datetime` to UTC."""
    return make_aware(dt, timezone.utc)It now allows me to set London time everywhere:
<=Celery App Base=> timezone_func conf.timezone: Europe/London
<=Celery App Base=> timezone_func timezone.get_timezone(conf.timezone): Europe/London
<=Celery Schedules=> now -> self.nowfun() 2018-06-22 14:11:03.625825+01:00
<=Utils Time=> to_utc -> What is dt_utc: 2018-06-22 14:11:03.626616
<=Utils Time=> remaining -> now 2018-06-22 14:11:03.629900+01:00
<=Celery Schedules=> now -> self.nowfun() 2018-06-22 14:11:03.630299+01:00

<=Utils Time=> make_aware -> _localize(dt, is_dst=None) 2018-06-22 14:11:03.630514+00:00
<=Utils Time=> to_utc -> make_aware(dt_utc, timezone.utc): 2018-06-22 14:11:03.630514+00:00
<=Utils Time=> make_aware -> What is dt: 2018-06-22 14:11:03.630514

But still task recieved in older time:

Received | 2018-06-22 13:05:02.712443 UTC
-- | --
Sent | 2018-06-22 13:05:02.707066 UTC
Started | 2018-06-22 13:05:02.716835 UTC
Succeeded | 2018-06-22 13:05:03.029372 UTC
Retries | 0
Timestamp | 2018-06-22 13:05:03.029372 UTC

I'm still struggling with actual task time, which is use UTC time, but inspecting task obj content doesn't show me anything:

[2018-06-22 14:38:03,737: ERROR/MainProcess] Received task: message, 
	on_ack=<promise@0x7f4147022ee8 --> <bound method Consumer.call_soon of <Consumer: w_perforce@HOST (running)>>>, 
	on_reject=<promise@0x7f4147022dc8 --> <bound method Consumer.call_soon of <Consumer: w_perforce@HOST (running)>>>, 
	app=<Celery octo at 0x7f41496cea20>, 
	hostname=w_perforce@HOST, 
	eventer=<celery.events.dispatcher.EventDispatcher object at 0x7f414700fa20>, 
	task=<@task: works.tasks.task_p4_info of octo at 0x7f41496cea20>, 
	connection_errors=(<class 'amqp.exceptions.ConnectionError'>, <class 'OSError'>, <class 'OSError'>, <class 'OSError'>), 
	body=b'\x80\x02]q\x00}q\x01(X\x06\x00\x00\x00branchq\x02X\x08\x00\x00\x00tkn_mainq\x03X\t\x00\x00\x00user_nameq\x04X\t\x00\x00\x00DEV_ADMINq\x05X\x03\x00\x00\x00runq\x06X\x07\x00\x00\x00p4_infoq\x07ua}q\x08}q\t(X\x05\x00\x00\x00chainq\nNX\t\x00\x00\x00callbacksq\x0bNX\x08\x00\x00\x00errbacksq\x0cNX\x05\x00\x00\x00chordq\rNu\x87q\x0e.', 
	headers={'parent_id': None, 'retries': 0, 'id': '77c56aa8-eee1-404f-942e-3c850dc960ea', 'expires': None, 'reply_to': '5db87f93-e390-3679-b2ab-e7a0aaf48510', 'delivery_info': {'exchange': '', 'priority': None, 'redelivered': False, 'routing_key': 'perforce'}, 'argsrepr': "[{'branch': 'tkn_main', 'user_name': 'DEV_ADMIN', 'run': 'p4_info'}]", 'correlation_id': '77c56aa8-eee1-404f-942e-3c850dc960ea', 'kwargsrepr': '{}', 'root_id': '77c56aa8-eee1-404f-942e-3c850dc960ea', 'timelimit': [None, None], 'lang': 'py', 'task': 'works.tasks.task_p4_info', 'shadow': None, 'origin': 'gen31414@HOST', 'eta': None, 'group': None}, 
	decoded=False, 
	utc=False

So, the questions is -
Where do Celery's task take this time?

@trianglesis
Copy link
Author

trianglesis commented Jun 22, 2018

Here is really detailed log with references where we can see TZ was set and now it's London summer time .

celery_tz_debug.log
task_tz_debug.log

But task is still UTC default.

@trianglesis
Copy link
Author

trianglesis commented Jun 22, 2018

Ok. I found the issue just right for London timezone and day saving options:
The problem is here in time -> utcoffset
It tries to get the real timezone for UTC with day saving, but delta is too different for actual time.
return -3

So if manually set it to int(-3) we can get the real time of London. I'l try to use different options here to avoid overlapping of time zones.

==================

import time as _time
if tm_isdst_v:
    time_altzone = _time.altzone // 3600
    debug("time_altzone day savetime delta: %s", time_altzone)
time_timezone = _time.timezone // 3600
debug("time_timezone not day savetime delta: %s", time_timezone)

Result: 'Europe/Kiev' same for 'Europe/London'

611 MainThread  2018-06-22 18:55:16,406 DEBUG   date_times          <module>              L:43    time_altzone day savetime delta: -3
611 MainThread  2018-06-22 18:55:16,406 DEBUG   date_times          <module>              L:45    time_timezone not day savetime delta: -2

But in Celery time:
[2018-06-22 17:07:06,550: INFO/MainProcess] time_altzone day savetime delta: -1
[2018-06-22 17:07:06,551: INFO/MainProcess] time_timezone not day savetime delta: 0

Why so?
Hm yes, this is usual diff for UTC of London and UTC+2 of Kyiv

But when I change celery zone - app.conf.timezone = 'Europe/Kiev'
It still uses:

time_altzone day savetime delta: -1
time_timezone not day savetime delta: 0

@trianglesis
Copy link
Author

So the problem is probably in:

Time which used in utcoffset is the system time, which always show you the time when task was actually executed (based on server time), but the time used to plan task can be different - based on app.conf.timezone = 'Europe/Kiev'

In this case we have two different realities:

  • the time we want to use in Celery as time when to schedule tasks (when server in London, but we want to execute based on Kyiv for example)
  • the time we actually have in our system, which used to understand when task were fired on system - which is different from point 1

How to avoid this?
I don't know, from my perspective I have only bug with daily time saving settings, where system time is 16:00, Kyiv time is 18:00, but Celery (when use all TZ settings) time is 15:00!!!

It should use ONLY the actual system time everywhere, but only in utcoffset use timezone we set in celery setting. In this case we'll have all times equal to system time, but only task execution time will be set to settings timezone. IMHO

@trianglesis
Copy link
Author

Looks like I was wrong, this is flower change time of execution, DB and real time of task is still 1 hr in the past from actual London time.

@trianglesis
Copy link
Author

Next step:
Hardcode time.py ->
@cached_property def utc(self): get_tz = pytz_timezone('Europe/London')

Flower Tasks board:

2018-06-22 19:53:51.785 | 2018-06-22 19:53:51.789
-- | --

Flower "Advanced task options"

Received | 2018-06-22 20:53:51.785712 BST
-- | --
Sent | 2018-06-22 20:53:51.781479 BST
Started | 2018-06-22 20:53:51.789844 BST
Succeeded | 2018-06-22 20:53:52.139911 BST

django_celery_results_taskresult

2018-06-22 19:53:52.124279

This is total mess with dates in code, no idea how to find all declarations and make them somehow dynamic.

@trianglesis
Copy link
Author

trianglesis commented Jun 23, 2018

Please, can anybody say me where do Celery get the time?
This is just unbelievable, I totally changed the Celery time representation, it now use London time in Beat and logging everything in right timezone, BUT!!!

Flower Tasks page shows me: Recieved - 2018-06-23 12:06:07.285 (this is -1 hr from London)
Flower TasK page, for one separate task shows me: All time according to 2018-06-23 13:06:07.285740 BST (This is the right London time!)
AND MySQL table django_celery_results_taskresult shows me - 2018-06-23 12:06:07.091785

How can it be possible?
Where else Celery can get time? Or this is also a bug in Flower and Django Celery module?

@trianglesis
Copy link
Author

So, the issue still is unclear.
The code itself tries to do a proper work and set time zone depend on difference between UTC and TZ user set in celery setting, but it sometimes get wrong time from "raw" UTC without any corrections, and this is why task record in Flower and MySQL had a wrong time - not the real server or TZ time.

I feel really unhappy with this, because it affect even MySQL-Django auto_datetime value, so in my system I can see the task were executed 1 hr before the real time.

If anyone want to fix this with me, and can find the place where this wrong time is set - please reply.
In other words - I spent about 4 days to understand this mechanism in Celery and see some kind of bugs, but I have no much free time to support this by my own.

Thanks,

@trianglesis
Copy link
Author

Keep collecting here related stuff. This issue is wide enough not for celery itself:
celery/django-celery#222

@trianglesis
Copy link
Author

Also: django_celery_results_taskresult uses this option:
date_done = models.DateTimeField(_('done at'), auto_now=True
This is why task were saved with UTC.

This is not correct and it's better to use:

from django.utils import timezone
date_done = models.DateTimeField(_('done at'), default=timezone.now)

Maybe

@auvipy
Copy link
Member

auvipy commented Jul 6, 2019

I hope this is fixed with newer releases

@auvipy auvipy closed this as completed Jul 6, 2019
@liziwl
Copy link

liziwl commented Oct 19, 2019

I have the same problem that date_done always using UTC when I have set

cel_app.conf.timezone = 'Asia/Shanghai'
cel_app.conf.enable_utc = True

on v4.3.0 installed by pip and redis, so the problem is fixed or not?

@snstanton
Copy link

I'm seeing the same thing when I have one worker on a system where UTC is the timezone and another worker has a different timezone (e.g. PST). From what I can tell, the issue is with event_from_message attempting to localize a timestamp that is in UTC already. It's ignoring all settings and blindly calling adjust_timestamp, which is a no-op as long as all workers are in the same timezone, but incorrectly "localizes" the timestamp if there is an offset. event_from_message takes an optional localize parameter that defaults to True. Since the parameter doesn't seem to be passed from the caller, it's always attempting to localize a value that should remain in UTC.

@auvipy auvipy added this to the 4.4.x milestone Jan 4, 2020
@fabiopiovam
Copy link

+1

@clovis1122
Copy link

I'm also having this issue, is there any fix/workaround?

@liushouxiang
Copy link

+1

2 similar comments
@lyf2000
Copy link

lyf2000 commented May 26, 2020

+1

@nellochen
Copy link

+1

@auvipy
Copy link
Member

auvipy commented May 29, 2020

fixes are welcome with a test.

@LutfiZakaria
Copy link

+1

@auvipy auvipy modified the milestones: 4.4.x, 5.1.0 Dec 19, 2020
@polarAli
Copy link

+1

themanifold added a commit to themanifold/celery that referenced this issue Jan 4, 2021
@thedrow thedrow added this to To do in Celery 5.1.0 Feb 24, 2021
@auvipy auvipy modified the milestones: 5.1.0, 5.2 Mar 22, 2021
@auvipy auvipy removed this from To do in Celery 5.1.0 Mar 22, 2021
@auvipy auvipy modified the milestones: 5.2, 5.2.x Oct 30, 2021
@mpaccione
Copy link

+1

@auvipy
Copy link
Member

auvipy commented May 15, 2022

workaround themanifold@1d5673d

@auvipy auvipy modified the milestones: 5.2.x, 5.3.x Jun 29, 2022
CodeSik added a commit to FKgk/celery that referenced this issue Jul 21, 2023
@FKgk FKgk linked a pull request Jul 21, 2023 that will close this issue
FKgk added a commit to FKgk/celery that referenced this issue Jul 21, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.