I am running into a problem and wondering what might be wrong.
Problem
Huey task is not running when called from web view. But when called from shell command from same VM it runs fine. The task is registering fine with huey. The task in question is handshake.
Setup
I am running an application in docker. Running two instances of same image with exactly same settings connecting to same redis and same postgres. I have verified that both instances are connected to same Redis.
The two instances are:
web.1: Running gunicorn web application in normal thread mode.worker.1: Running python manage.py run_hueySettings
INSTALLED_APPS += ['huey.contrib.djhuey']
HUEY = {
'name': 'myapp', # Use db name for huey.
'results': True, # Store return values of tasks.
'store_none': False, # If a task returns None, do not save to results.
'utc': True, # Use UTC for all times internally.
'blocking': True, # Perform blocking pop rather than poll Redis.
'consumer': {
'workers': 2,
'worker_type': 'thread',
'initial_delay': 0.1, # Smallest polling interval, same as -d.
'backoff': 1.15, # Exponential backoff using this rate, -b.
'max_delay': 10.0, # Max possible polling interval, -m.
'scheduler_interval': 1, # Check schedule every second, -s.
'periodic': True, # Enable crontab feature.
'check_worker_health': True, # Enable worker health checks.
'health_check_interval': 1, # Check worker health every second.
},
}
# HUEY Overrides
HUEY['name'] = env("USER", default="myapp")
HUEY['immediate_use_memory'] = True
HUEY['immediate'] = False
HUEY['url'] = REDIS_LOCATION
Task
@huey.db_task()
def handshake(name: str):
log = logging.getLogger(f"{__name__}::handshake")
reply = f"Handshaked: {name}"
log.info(reply)
return reply
Here's output of run_huey that shows task is registered (removed some lines for clarity).
2020-11-07T06:19:35.325436058Z app[worker.1]: [2020-11-07 11:49:35,325] INFO:huey.consumer:MainThread:Huey consumer started with 2 thread, PID 9 at 2020-11-07 06:19:35.325065
2020-11-07T06:19:35.325476428Z app[worker.1]: INFO 2020-11-07 11:49:35,325 consumer [9:139911526389568] - [-] - '-' - Huey consumer started with 2 thread, PID 9 at 2020-11-07 06:19:35.325065
2020-11-07T06:19:35.325939210Z app[worker.1]: [2020-11-07 11:49:35,325] INFO:huey.consumer:MainThread:Scheduler runs every 1 second(s).
2020-11-07T06:19:35.325952911Z app[worker.1]: INFO 2020-11-07 11:49:35,325 consumer [9:139911526389568] - [-] - '-' - Scheduler runs every 1 second(s).
2020-11-07T06:19:35.326318603Z app[worker.1]: [2020-11-07 11:49:35,326] INFO:huey.consumer:MainThread:Periodic tasks are enabled.
2020-11-07T06:19:35.326439763Z app[worker.1]: INFO 2020-11-07 11:49:35,326 consumer [9:139911526389568] - [-] - '-' - Periodic tasks are enabled.
2020-11-07T06:19:35.326648104Z app[worker.1]: [2020-11-07 11:49:35,326] INFO:huey.consumer:MainThread:The following commands are available:
2020-11-07T06:19:35.326662944Z app[worker.1]: + app.wms.tasks.generate_report_task
2020-11-07T06:19:35.326666544Z app[worker.1]: + app.wms.tasks.handshake
2020-11-07T06:19:35.326669924Z app[worker.1]: + app.orders.tasks.process_pending_bulk_orders
2020-11-07T06:19:35.326698025Z app[worker.1]: + app.returns.tasks.email_return_report
2020-11-07T06:19:35.326739964Z app[worker.1]: INFO 2020-11-07 11:49:35,326 consumer [9:139911526389568] - [-] - '-' - The following commands are available:
2020-11-07T06:19:35.326755324Z app[worker.1]: + app.wms.tasks.generate_report_task
2020-11-07T06:19:35.326758854Z app[worker.1]: + app.wms.tasks.handshake
2020-11-07T06:19:35.326762154Z app[worker.1]: + app.orders.tasks.process_pending_bulk_orders
2020-11-07T06:19:35.326799605Z app[worker.1]: + app.returns.tasks.email_return_report
Test 1: Webpage that calls handshake
from .tasks import handshake
def hello(request):
r = handshake("Sam")
val = r(blocking=True, timeout=20)
return HttpResponse(f'Hello there: {val}')
Output in web logs:
2020-11-07T06:24:46.400137244Z app[web.1]: ERROR 2020-11-07 11:54:46,398 log [9:140443373860608] - [-] - '-' - Internal Server Error: /hello/
2020-11-07T06:24:46.400196084Z app[web.1]: Traceback (most recent call last):
2020-11-07T06:24:46.400205324Z app[web.1]: File "/usr/local/lib/python3.8/site-packages/django/core/handlers/exception.py", line 34, in inner
2020-11-07T06:24:46.400212074Z app[web.1]: response = get_response(request)
2020-11-07T06:24:46.400217884Z app[web.1]: File "/usr/local/lib/python3.8/site-packages/django/core/handlers/base.py", line 115, in _get_response
2020-11-07T06:24:46.400223805Z app[web.1]: response = self.process_exception_by_middleware(e, request)
2020-11-07T06:24:46.400228945Z app[web.1]: File "/usr/local/lib/python3.8/site-packages/django/core/handlers/base.py", line 113, in _get_response
2020-11-07T06:24:46.400234465Z app[web.1]: response = wrapped_callback(request, *callback_args, **callback_kwargs)
2020-11-07T06:24:46.400239975Z app[web.1]: File "/usr/local/lib/python3.8/contextlib.py", line 75, in inner
2020-11-07T06:24:46.400244945Z app[web.1]: return func(*args, **kwds)
2020-11-07T06:24:46.400249615Z app[web.1]: File "/app/app/wms/views.py", line 79, in hello
2020-11-07T06:24:46.400255115Z app[web.1]: val = r(blocking=True, timeout=20)
2020-11-07T06:24:46.400260144Z app[web.1]: File "/usr/local/lib/python3.8/site-packages/huey/api.py", line 854, in __call__
2020-11-07T06:24:46.400265304Z app[web.1]: return self.get(*args, **kwargs)
2020-11-07T06:24:46.400270114Z app[web.1]: File "/usr/local/lib/python3.8/site-packages/huey/api.py", line 893, in get
2020-11-07T06:24:46.400301634Z app[web.1]: result = self.get_raw_result(blocking, timeout, backoff, max_delay,
2020-11-07T06:24:46.400309535Z app[web.1]: File "/usr/local/lib/python3.8/site-packages/huey/api.py", line 882, in get_raw_result
2020-11-07T06:24:46.400314785Z app[web.1]: raise HueyException('timed out waiting for result')
2020-11-07T06:24:46.400319575Z app[web.1]: huey.exceptions.HueyException: timed out waiting for result
Nothing is recorded in worker logs.
Test 2: Django Shell calling handshake from same instance where web is running
django@c2fcbcf604cd:/app$ python manage.py shell
(InteractiveConsole)
>>> from app.wms.tasks import handshake
>>> val = handshake('John')
>>> val
<Result: task 736642f1-0a91-4dff-9376-eca1af9ef00e>
>>> val()
'Handshaked: John'
>>>
In worker logs:
2020-11-07T06:30:30.742538291Z app[worker.1]: [2020-11-07 12:00:30,742] INFO:huey:Worker-2:Executing app.wms.tasks.handshake: 736642f1-0a91-4dff-9376-eca1af9ef00e
2020-11-07T06:30:30.742663981Z app[worker.1]: INFO 2020-11-07 12:00:30,742 api [9:139911356086016] - [-] - '-' - Executing app.wms.tasks.handshake: 736642f1-0a91-4dff-9376-eca1af9ef00e
2020-11-07T06:30:30.743246684Z app[worker.1]: INFO 2020-11-07 12:00:30,743 tasks [9:139911356086016] - [-] - '-' - Handshaked: John
2020-11-07T06:30:30.743518145Z app[worker.1]: INFO 2020-11-07 12:00:30,743 tasks [9:139911356086016] - [-] - '-' - Handshaked: John
2020-11-07T06:30:30.744054668Z app[worker.1]: [2020-11-07 12:00:30,743] INFO:huey:Worker-2:app.wms.tasks.handshake: 736642f1-0a91-4dff-9376-eca1af9ef00e executed in 0.001s
2020-11-07T06:30:30.744117379Z app[worker.1]: INFO 2020-11-07 12:00:30,743 api [9:139911356086016] - [-] - '-' - app.wms.tasks.handshake: 736642f1-0a91-4dff-9376-eca1af9ef00e executed in 0.001s
So what am I missing? Do I need to add some code to App config to load the task?
I even tried running the run_huey on the web.1 instance but same problem. So it is not environment, not redis. It has something to do with web not connecting to redis I guess.
If you can, please help. I am just not sure what I am missing.
Thanks Amit
Answering myself. After reply from Charles (Author) I was able to solve this by using a hard-coded name.