Logging Unicode characters from Python generates errors

akloeckner · 4 November 2018 13:50

Hi Folks

I’m running your software for quite some while and I’m relly happy with it. Thanks!

Recently I ran into a problem with my home assistant installation. I have it installed in a Python Virtual Enviroment on my Raspi3 OSMC box. At some point in time, it started to generated errors when logging Unicode characters to the journalctl log. I opened the following issue on their ticket system:

github.com/home-assistant/core

Special chars in logs throw errors

opened 05:45PM - 27 Oct 18 UTC

closed 09:35PM - 14 Jul 19 UTC

akloeckner

integration: logger stale

**Home Assistant release with the issue:** 80.3  **Last working Home Assistant release (if known):** 77-point-something (was: *never. But I also didnt switch to debug log before...* but I dicovered new in info in the posts below...) **Operating environment (Hass.io/Docker/Windows/etc.):** virtualenv on osmc on raspberry 3  **Component/platform:** logger?  **Description of problem:** So, I just found this change #16243, because I was missing my `pilight_received` events on the log. I enabled debug logging and now I see these things for some of the log entries: ``` Oct 27 13:37:55 ak-test hass[1547]: 2018-10-27 13:37:55 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: old_state=<state automation.schaltzustande_elro_800_switch_s15=on; friendly_name=Schaltzust\xe4nde elro_800_switch_s15, last_triggered=2018-10-27T13:37:45.753945+02:00, id=elro_800_switch_s15_automation @ 2018-10-27T13:35:46.755944+02:00>, entity_id=automation.schaltzustande_elro_800_switch_s15, new_state=<state automation.schaltzustande_elro_800_switch_s15=on; friendly_name=Schaltzust\xe4nde elro_800_switch_s15, last_triggered=2018-10-27T13:37:55.045185+02:00, id=elro_800_switch_s15_automation @ 2018-10-27T13:35:46.755944+02:00>> Oct 27 13:37:55 ak-test hass[1547]: --- Logging error --- Oct 27 13:37:55 ak-test hass[1547]: Traceback (most recent call last): Oct 27 13:37:55 ak-test hass[1547]: File "/usr/lib/python3.5/logging/__init__.py", line 983, in emit Oct 27 13:37:55 ak-test hass[1547]: stream.write(msg) Oct 27 13:37:55 ak-test hass[1547]: UnicodeEncodeError: 'ascii' codec can't encode character '\xe4' in position 189: ordinal not in range(128) Oct 27 13:37:55 ak-test hass[1547]: Call stack: Oct 27 13:37:55 ak-test hass[1547]: File "/srv/homeassistant/bin/hass", line 11, in <module> Oct 27 13:37:55 ak-test hass[1547]: sys.exit(main()) Oct 27 13:37:55 ak-test hass[1547]: File "/srv/homeassistant/lib/python3.5/site-packages/homeassistant/__main__.py", line 389, in main Oct 27 13:37:55 ak-test hass[1547]: exit_code = asyncio_run(setup_and_run_hass(config_dir, args)) Oct 27 13:37:55 ak-test hass[1547]: File "/srv/homeassistant/lib/python3.5/site-packages/homeassistant/util/async_.py", line 29, in asyncio_run Oct 27 13:37:55 ak-test hass[1547]: return loop.run_until_complete(main) Oct 27 13:37:55 ak-test hass[1547]: File "/usr/lib/python3.5/asyncio/base_events.py", line 454, in run_until_complete Oct 27 13:37:55 ak-test hass[1547]: self.run_forever() Oct 27 13:37:55 ak-test hass[1547]: File "/usr/lib/python3.5/asyncio/base_events.py", line 421, in run_forever Oct 27 13:37:55 ak-test hass[1547]: self._run_once() Oct 27 13:37:55 ak-test hass[1547]: File "/usr/lib/python3.5/asyncio/base_events.py", line 1424, in _run_once Oct 27 13:37:55 ak-test hass[1547]: handle._run() Oct 27 13:37:55 ak-test hass[1547]: File "/usr/lib/python3.5/asyncio/events.py", line 126, in _run Oct 27 13:37:55 ak-test hass[1547]: self._callback(*self._args) Oct 27 13:37:55 ak-test hass[1547]: File "/usr/lib/python3.5/asyncio/tasks.py", line 315, in _wakeup Oct 27 13:37:55 ak-test hass[1547]: self._step() Oct 27 13:37:55 ak-test hass[1547]: File "/usr/lib/python3.5/asyncio/tasks.py", line 239, in _step Oct 27 13:37:55 ak-test hass[1547]: result = coro.send(None) Oct 27 13:37:55 ak-test hass[1547]: File "/srv/homeassistant/lib/python3.5/site-packages/homeassistant/components/automation/__init__.py", line 290, in async_trigger Oct 27 13:37:55 ak-test hass[1547]: await self.async_update_ha_state() Oct 27 13:37:55 ak-test hass[1547]: File "/srv/homeassistant/lib/python3.5/site-packages/homeassistant/helpers/entity.py", line 310, in async_update_ha_state Oct 27 13:37:55 ak-test hass[1547]: self.entity_id, state, attr, self.force_update, self._context) Oct 27 13:37:55 ak-test hass[1547]: File "/srv/homeassistant/lib/python3.5/site-packages/homeassistant/core.py", line 909, in async_set Oct 27 13:37:55 ak-test hass[1547]: }, EventOrigin.local, context) Oct 27 13:37:55 ak-test hass[1547]: File "/srv/homeassistant/lib/python3.5/site-packages/homeassistant/core.py", line 530, in async_fire Oct 27 13:37:55 ak-test hass[1547]: _LOGGER.debug("Bus:Handling %s", event) Oct 27 13:37:55 ak-test hass[1547]: Message: 'Bus:Handling %s' Oct 27 13:37:55 ak-test hass[1547]: Arguments: (<Event state_changed[L]: old_state=<state automation.schaltzustande_elro_800_switch_s15=on; friendly_name=Schaltzust\xe4nde elro_800_switch_s15, last_triggered=2018-10-27T13:37:45.753945+02:00, id=elro_800_switch_s15_automation @ 2018-10-27T13:35:46.755944+02:00>, entity_id=automation.schaltzustande_elro_800_switch_s15, new_state=<state automation.schaltzustande_elro_800_switch_s15=on; friendly_name=Schaltzust\xe4nde elro_800_switch_s15, last_triggered=2018-10-27T13:37:55.045185+02:00, id=elro_800_switch_s15_automation @ 2018-10-27T13:35:46.755944+02:00>>,) ``` Is this caused by above mentioned change? Or have I now just discovered the error, because I have enabled debug logging (and the error was hiding there all the time)? However, this seems like bug to me, so here goes the report to find out if this supicion is correct... **Problem-relevant `configuration.yaml` entries and (fill out even if it seems unimportant):** ```yaml logger: detail: debug ``` **Traceback (if applicable):** ``` ``` **Additional information:**

I have found a solution to either pass on a Unicode string to the logging system, or to strip Unicode characters before sending it to the logging system. The former seems the more elegant way, but it throws the same error just within the logging system. The latter way seems a bit bulky.

Now, I am unsure, how to proceed with this and would like to ask your opinion: Should the underlying logging system (i.e. OSMC, journalctl, Python) be able to log Unicode characters? Or is there one (or more) bottleneck(s), which do(es) not support Unicode characters? If so: Where is the bottleneck?

Thanks for your support!

Andreas

sam_nazarko · 4 November 2018 15:33

Log data can even contain binary data. Try passing —all to journalctl

akloeckner · 6 November 2018 22:12

Thanks, Sam!

The error occurs when writing to the log already. But since journalctl should be able to handle UTF log entries, we’ll have to search for the bottleneck elsewhere.