Logger set to 'ascii' instead of 'utf-8': UnicodeDecodeError 'ascii' #5144
Description
Checklist
Report:
software -> celery:4.2.1 (windowlicker) kombu:4.2.1 py:3.6.5
billiard:3.5.0.4 py-amqp:2.3.2
platform -> system:Linux arch:64bit imp:CPython
loader -> celery.loaders.app.AppLoader
settings -> transport:amqp results:indicore.celery_app:Backend
broker_url: 'amqp://indico:********@rabbitmq:5672//'
task_serializer: 'msgpack-numpy'
result_serializer: 'msgpack-numpy'
enable_utc: True
worker_send_task_events: True
result_expires: 86400
task_always_eager: False
accept_content: ['application/x-msgpack']
result_backend: 'indicore.celery_app:Backend'
redis_port: 6379
redis_host: 'celery-redis'
redis_max_connections: 1000
broker_transport_options: {
'confirm_publish': True}
broker_heartbeat: 20
broker_connection_max_retries: None
task_queue_ha_policy: 'all'
Steps to reproduce
Celery is logging the success result of a task that includes characters outside ascii encoding.
Expected behavior
I expect the celery logger to use 'utf-8' encoding rather than ascii. I haven't touched the celery logging, nor do I have a python logging setup separately at the moment. I am using Python3.
Actual behavior
I receive the following traceback:
[2018-10-24 15:35:00,541: WARNING/ForkPoolWorker-7] --- Logging error ---
[2018-10-24 15:35:00,541: WARNING/ForkPoolWorker-7] Traceback (most recent call last):
[2018-10-24 15:35:00,541: WARNING/ForkPoolWorker-7] File "/usr/lib/python3.6/logging/__init__.py", line 994, in emit
stream.write(msg)
[2018-10-24 15:35:00,541: WARNING/ForkPoolWorker-7] UnicodeEncodeError: 'ascii' codec can't encode characters in position 923-928: ordinal not in range(128)
[2018-10-24 15:35:00,541: WARNING/ForkPoolWorker-7] Call stack:
[2018-10-24 15:35:00,542: WARNING/ForkPoolWorker-7] File "/usr/lib/python3.6/runpy.py", line 193, in _run_module_as_main
"__main__", mod_spec)
[2018-10-24 15:35:00,542: WARNING/ForkPoolWorker-7] File "/usr/lib/python3.6/runpy.py", line 85, in _run_code
exec(code, run_globals)
[2018-10-24 15:35:00,542: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/celery/__main__.py", line 20, in <module>
main()
[2018-10-24 15:35:00,542: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/celery/__main__.py", line 16, in main
_main()
[2018-10-24 15:35:00,542: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/celery/bin/celery.py", line 322, in main
cmd.execute_from_commandline(argv)
[2018-10-24 15:35:00,542: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/celery/bin/celery.py", line 496, in execute_from_commandline
super(CeleryCommand, self).execute_from_commandline(argv)))
[2018-10-24 15:35:00,542: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/celery/bin/base.py", line 275, in execute_from_commandline
return self.handle_argv(self.prog_name, argv[1:])
[2018-10-24 15:35:00,542: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/celery/bin/celery.py", line 488, in handle_argv
return self.execute(command, argv)
[2018-10-24 15:35:00,542: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/celery/bin/celery.py", line 420, in execute
).run_from_argv(self.prog_name, argv[1:], command=argv[0])
[2018-10-24 15:35:00,542: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/celery/bin/worker.py", line 223, in run_from_argv
return self(*args, **options)
[2018-10-24 15:35:00,543: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/celery/bin/base.py", line 238, in __call__
ret = self.run(*args, **kwargs)
[2018-10-24 15:35:00,543: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/celery/bin/worker.py", line 258, in run
worker.start()
[2018-10-24 15:35:00,543: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/celery/worker/worker.py", line 205, in start
self.blueprint.start(self)
[2018-10-24 15:35:00,543: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/celery/bootsteps.py", line 119, in start
step.start(parent)
[2018-10-24 15:35:00,543: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/celery/bootsteps.py", line 369, in start
return self.obj.start()
[2018-10-24 15:35:00,543: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/celery/concurrency/base.py", line 131, in start
self.on_start()
[2018-10-24 15:35:00,543: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/celery/concurrency/prefork.py", line 112, in on_start
**self.options)
[2018-10-24 15:35:00,543: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/celery/concurrency/asynpool.py", line 432, in __init__
super(AsynPool, self).__init__(processes, *args, **kwargs)
[2018-10-24 15:35:00,543: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/billiard/pool.py", line 1007, in __init__
self._create_worker_process(i)
[2018-10-24 15:35:00,543: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/celery/concurrency/asynpool.py", line 449, in _create_worker_process
return super(AsynPool, self)._create_worker_process(i)
[2018-10-24 15:35:00,543: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/billiard/pool.py", line 1116, in _create_worker_process
w.start()
[2018-10-24 15:35:00,543: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/billiard/process.py", line 124, in start
self._popen = self._Popen(self)
[2018-10-24 15:35:00,543: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/billiard/context.py", line 333, in _Popen
return Popen(process_obj)
[2018-10-24 15:35:00,543: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/billiard/popen_fork.py", line 24, in __init__
self._launch(process_obj)
[2018-10-24 15:35:00,543: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/billiard/popen_fork.py", line 79, in _launch
code = process_obj._bootstrap()
[2018-10-24 15:35:00,543: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/billiard/process.py", line 327, in _bootstrap
self.run()
[2018-10-24 15:35:00,543: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/billiard/process.py", line 114, in run
self._target(*self._args, **self._kwargs)
[2018-10-24 15:35:00,543: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/billiard/pool.py", line 289, in __call__
sys.exit(self.workloop(pid=pid))
[2018-10-24 15:35:00,544: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/billiard/pool.py", line 358, in workloop
result = (True, prepare_result(fun(*args, **kwargs)))
[2018-10-24 15:35:00,544: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/celery/app/trace.py", line 549, in _fast_trace_task
uuid, args, kwargs, request,
[2018-10-24 15:35:00,544: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/celery/app/trace.py", line 458, in trace_task
'runtime': T,
[2018-10-24 15:35:00,544: WARNING/ForkPoolWorker-7] File "/usr/local/lib/python3.6/dist-packages/celery/app/trace.py", line 124, in info
logger.info(fmt, context, extra={'data': context})
Additional Info
- I ran
sys.getdefaultencoding()before beforecelery/app/trace.pyline 124 and the value is "utf-8" as I expected. - I do have the LANG set up properly in the machine
- the machine's default locale is also set the same
- I also added the LANG in front of the celery bin in celeryd.
- I can manually print
contextonce I've decoded it "utf-8", which is successfully redirected to the celery logger from what I can see.