"Operation not permitted: '/dev/ttyACM0'" since upgrading to 2022.11.5

DanielBaulig commented 1 year ago

The problem

I just upgraded to 2022.11.5 and since then ZHA fails to setup correctly. Note, I'm not 100% convinced that this was actually related to the upgrade, but there was a ZHA dependency update in 11.5, so maybe it is.

Logs:

Logger: homeassistant.config_entries
Source: components/zha/core/gateway.py:172
First occurred: 2:14:15 PM (2 occurrences)
Last logged: 2:15:55 PM

Error setting up entry ConBee II, s/n: DE2197609 - dresden elektronik ingenieurtechnik GmbH for zha
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/serial/serialposix.py", line 322, in open
    self.fd = os.open(self.portstr, os.O_RDWR | os.O_NOCTTY | os.O_NONBLOCK)
PermissionError: [Errno 1] Operation not permitted: '/dev/ttyACM0'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 365, in async_setup
    result = await component.async_setup_entry(hass, self)
  File "/usr/src/homeassistant/homeassistant/components/zha/__init__.py", line 112, in async_setup_entry
    await zha_gateway.async_initialize()
  File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 185, in async_initialize
    raise exc
  File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 172, in async_initialize
    self.application_controller = await app_controller_cls.new(
  File "/usr/local/lib/python3.10/site-packages/zigpy/application.py", line 144, in new
    await app.startup(auto_form=auto_form)
  File "/usr/local/lib/python3.10/site-packages/zigpy/application.py", line 124, in startup
    await self.connect()
  File "/usr/local/lib/python3.10/site-packages/zigpy_deconz/zigbee/application.py", line 81, in connect
    await api.connect()
  File "/usr/local/lib/python3.10/site-packages/zigpy_deconz/api.py", line 275, in connect
    self._uart = await zigpy_deconz.uart.connect(self._config, self)
  File "/usr/local/lib/python3.10/site-packages/zigpy_deconz/uart.py", line 134, in connect
    _, protocol = await zigpy.serial.create_serial_connection(
  File "/usr/local/lib/python3.10/site-packages/zigpy/serial.py", line 37, in create_serial_connection
    transport, protocol = await pyserial_asyncio.create_serial_connection(
  File "/usr/local/lib/python3.10/site-packages/serial_asyncio/__init__.py", line 448, in create_serial_connection
    serial_instance = serial.serial_for_url(*args, **kwargs)
  File "/usr/local/lib/python3.10/site-packages/serial/__init__.py", line 90, in serial_for_url
    instance.open()
  File "/usr/local/lib/python3.10/site-packages/serial/serialposix.py", line 325, in open
    raise SerialException(msg.errno, "could not open port {}: {}".format(self._port, msg))
serial.serialutil.SerialException: [Errno 1] could not open port /dev/ttyACM0: [Errno 1] Operation not permitted: '/dev/ttyACM0'

What version of Home Assistant Core has the issue?

2022.11.5

What was the last working version of Home Assistant Core?

2022.11.4

What type of installation are you running?

Home Assistant Container

Integration causing the issue

ZHA

Link to integration documentation on our website

https://www.home-assistant.io/integrations/zha

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

Logger: homeassistant.config_entries
Source: components/zha/core/gateway.py:172
First occurred: 2:14:15 PM (2 occurrences)
Last logged: 2:15:55 PM

Error setting up entry ConBee II, s/n: DE2197609 - dresden elektronik ingenieurtechnik GmbH for zha
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/serial/serialposix.py", line 322, in open
    self.fd = os.open(self.portstr, os.O_RDWR | os.O_NOCTTY | os.O_NONBLOCK)
PermissionError: [Errno 1] Operation not permitted: '/dev/ttyACM0'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 365, in async_setup
    result = await component.async_setup_entry(hass, self)
  File "/usr/src/homeassistant/homeassistant/components/zha/__init__.py", line 112, in async_setup_entry
    await zha_gateway.async_initialize()
  File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 185, in async_initialize
    raise exc
  File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 172, in async_initialize
    self.application_controller = await app_controller_cls.new(
  File "/usr/local/lib/python3.10/site-packages/zigpy/application.py", line 144, in new
    await app.startup(auto_form=auto_form)
  File "/usr/local/lib/python3.10/site-packages/zigpy/application.py", line 124, in startup
    await self.connect()
  File "/usr/local/lib/python3.10/site-packages/zigpy_deconz/zigbee/application.py", line 81, in connect
    await api.connect()
  File "/usr/local/lib/python3.10/site-packages/zigpy_deconz/api.py", line 275, in connect
    self._uart = await zigpy_deconz.uart.connect(self._config, self)
  File "/usr/local/lib/python3.10/site-packages/zigpy_deconz/uart.py", line 134, in connect
    _, protocol = await zigpy.serial.create_serial_connection(
  File "/usr/local/lib/python3.10/site-packages/zigpy/serial.py", line 37, in create_serial_connection
    transport, protocol = await pyserial_asyncio.create_serial_connection(
  File "/usr/local/lib/python3.10/site-packages/serial_asyncio/__init__.py", line 448, in create_serial_connection
    serial_instance = serial.serial_for_url(*args, **kwargs)
  File "/usr/local/lib/python3.10/site-packages/serial/__init__.py", line 90, in serial_for_url
    instance.open()
  File "/usr/local/lib/python3.10/site-packages/serial/serialposix.py", line 325, in open
    raise SerialException(msg.errno, "could not open port {}: {}".format(self._port, msg))
serial.serialutil.SerialException: [Errno 1] could not open port /dev/ttyACM0: [Errno 1] Operation not permitted: '/dev/ttyACM0'

Logger: homeassistant.components.zha.core.gateway
Source: components/zha/core/gateway.py:172
Integration: Zigbee Home Automation (documentation, issues)
First occurred: 2:14:06 PM (6 occurrences)
Last logged: 2:15:55 PM

Couldn't start deCONZ = dresden elektronik deCONZ protocol: ConBee I/II, RaspBee I/II coordinator (attempt 1 of 3)
Couldn't start deCONZ = dresden elektronik deCONZ protocol: ConBee I/II, RaspBee I/II coordinator (attempt 2 of 3)
Couldn't start deCONZ = dresden elektronik deCONZ protocol: ConBee I/II, RaspBee I/II coordinator (attempt 3 of 3)
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/serial/serialposix.py", line 322, in open
    self.fd = os.open(self.portstr, os.O_RDWR | os.O_NOCTTY | os.O_NONBLOCK)
PermissionError: [Errno 1] Operation not permitted: '/dev/ttyACM0'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 172, in async_initialize
    self.application_controller = await app_controller_cls.new(
  File "/usr/local/lib/python3.10/site-packages/zigpy/application.py", line 144, in new
    await app.startup(auto_form=auto_form)
  File "/usr/local/lib/python3.10/site-packages/zigpy/application.py", line 124, in startup
    await self.connect()
  File "/usr/local/lib/python3.10/site-packages/zigpy_deconz/zigbee/application.py", line 81, in connect
    await api.connect()
  File "/usr/local/lib/python3.10/site-packages/zigpy_deconz/api.py", line 275, in connect
    self._uart = await zigpy_deconz.uart.connect(self._config, self)
  File "/usr/local/lib/python3.10/site-packages/zigpy_deconz/uart.py", line 134, in connect
    _, protocol = await zigpy.serial.create_serial_connection(
  File "/usr/local/lib/python3.10/site-packages/zigpy/serial.py", line 37, in create_serial_connection
    transport, protocol = await pyserial_asyncio.create_serial_connection(
  File "/usr/local/lib/python3.10/site-packages/serial_asyncio/__init__.py", line 448, in create_serial_connection
    serial_instance = serial.serial_for_url(*args, **kwargs)
  File "/usr/local/lib/python3.10/site-packages/serial/__init__.py", line 90, in serial_for_url
    instance.open()
  File "/usr/local/lib/python3.10/site-packages/serial/serialposix.py", line 325, in open
    raise SerialException(msg.errno, "could not open port {}: {}".format(self._port, msg))
serial.serialutil.SerialException: [Errno 1] could not open port /dev/ttyACM0: [Errno 1] Operation not permitted: '/dev/ttyACM0'

Additional information

I tried restarting the Docker container.
I unplugged and replugged the Zigbee stick.
Restarted the Raspberry Pi
sudo apt-get update && sudo apt-get upgrade

I've verified that my docker-compose file creates a mapping for the ZHA stick:

volumes:
  [...]
  - "/dev/serial/by-id/usb-dresden_elektronik_ingenieurtechnik_GmbH_ConBee_II_DE2197609-if00:/dev/ttyACM0"

The by-id path exists and links to /dev/ttyACM0 on the host

# ls -lisa /dev/serial/by-id/usb-dresden_elektronik_ingenieurtechnik_GmbH_ConBee_II_DE2197609-if00
965 0 lrwxrwxrwx 1 root root 13 Dec  4 14:26 /dev/serial/by-id/usb-dresden_elektronik_ingenieurtechnik_GmbH_ConBee_II_DE2197609-if00 -> ../../ttyACM0

On a thread in the Dresden Elektronik Github I found a mention of updating the USB stick firmware, but I wasn't able to follow the instructions I found successfully. I only found a GCFFlasher binary (not a GCFFlasher_internal binary) and that binary didn't show any devices when listing with GCFFlasher -l.

home-assistant[bot] commented 1 year ago

Hey there @dmulcahey, @adminiuga, @puddly, mind taking a look at this issue as it has been labeled with an integration (zha) you are listed as a code owner for? Thanks!

Code owner commands

Code owners of `zha` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Change the title of the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign zha` Removes the current integration label and assignees on the issue, add the integration domain after the command.

_{^{(message by CodeOwnersMention)}}

zha documentation zha source _{^{(message by IssueLinks)}}

Adminiuga commented 1 year ago

ZHA can't open the port. There were no changes related to the serial module in zha.

What is the host? Check permission on the serial port and make sure docker instance has access to it. Run a shell inside the container to confirm UID of the ha core can read/write serial port.

DanielBaulig commented 1 year ago

Thank you for helping out.

Host is raspbian on a Raspberry Pi 4 Model B.

On host

# ls -lisa /dev/ttyACM0
442 0 crw-rw---- 1 root dialout 166, 0 Dec  4 15:43 /dev/ttyACM0

# docker exec -it home-assistant /bin/bash
bash-5.1# ls -lisa /dev/ttyACM0
    442      0 crw-rw----    1 root     dialout   166,   0 Dec  4 15:43 /dev/ttyACM0
bash-5.1# id -u $(whoami)
0
bash-5.1# ls -lisan /dev/ttyACM0
    442      0 crw-rw----    1 0        20        166,   0 Dec  4 15:43 /dev/ttyACM0

HA runs as root in the container:

bash-5.1# ps -a
PID   USER     TIME  COMMAND
    1 root      0:00 /package/admin/s6/command/s6-svscan -d4 -- /run/service
   12 root      0:00 /bin/bash
   33 root      0:00 s6-supervise s6-linux-init-shutdownd
   35 root      0:00 /package/admin/s6-linux-init/command/s6-linux-init-shutdownd -c /run/s6/basedir -g 3000 -C -B
   42 root      0:00 s6-supervise s6rc-oneshot-runner
   43 root      0:00 s6-supervise s6rc-fdholder
   51 root      0:00 /package/admin/s6/command/s6-ipcserverd -1 -- /package/admin/s6/command/s6-ipcserver-access -v0 -E -l0 -i data/rules -- /package/admin/s6/command/s6-sudod -t 30000 -- /package/admin/s6-rc/command/s6-rc-oneshot-run -l ../..
   79 root      0:00 s6-supervise home-assistant
   81 root      3:26 python3 -m homeassistant --config /config
  325 root      0:00 ps -a

However, when I try the following I also get a Operation not permitted error.

bash-5.1# cat /dev/ttyACM0
cat: can't open '/dev/ttyACM0': Operation not permitted

Running the same on the host seems to work though:

# cat /dev/ttyACM0                                                                                                                                                                                                              
e^C

Note that I tried chmoddingo+rw to /dev/ttyACM0 just in case and that didn't change anything either.

DanielBaulig commented 1 year ago

Adding

  privileged: True

to the home-assistant service in my docker-compose.yaml file seems to resolve the issue. It's not entirely clear to me how this differs from how I invoked it before or why this suddenly became necessary though.

Adminiuga commented 1 year ago

Does downgrading to 2022.11.4 fixes it?

Adminiuga commented 1 year ago

      - "/dev/serial/by-id/usb-dresden_elektronik_ingenieurtechnik_GmbH_ConBee_II_DE2197609-if00:/dev/ttyAMA0

Did this work before? I'm not positive it is going to work, mounted as a volume. This should be a device mapping. Or map devices ttyAMA0 to ttyAMA0 and mount dev serial as a volume.

DanielBaulig commented 1 year ago

Does downgrading to 2022.11.4 fixes it?

Haven't tried yet. I'll give it a shot.

 - "/dev/serial/by-id/usb-dresden_elektronik_ingenieurtechnik_GmbH_ConBee_II_DE2197609-if00:/dev/ttyAMA0
Did this work before? I'm not positive it is going to work, mounted as a volume. This should be a device mapping. Or map devices ttyAMA0 to ttyAMA0 and mount dev serial as a volume.

Yes it did. I've been using this compose file for years. But now that you mention it, I'm realizing that I recently changed some lines above that particular line and added some more volume mappings. I remember vaguely that I fumbled in vim and did some accidental edits that I undid. Maybe I didn't cleanly undo them and removed the device: line that may have separated that particular line from the volumes: block.

To my own disgrace I do not have the yaml file in source control, so I can no longer reconstruct if that may have been the case or not. But it seems to be making sense.

Adminiuga commented 1 year ago

The above line is a valid device mapping line for a container, but would not work as a volume mapping, because you are trying to open a device file. It would not work unless it is a fully privileged container as you found out.

I'm closing this as this is not a zha issue.

DanielBaulig commented 1 year ago

@Adminiuga I (re-?) added the devices: block and moved the serial device mapping into it and it is working again as expected.

Appreciate you taking the time help me debug this even though it wasn't a ZHA issue. Is there a way for me to buy you a coffee or beer?

Adminiuga commented 1 year ago

I appreciate the offer, but I'm fine. Thank you though 🤝

home-assistant / core