systemd-udevd call unshare process when attaching nvme volume

[vincent chen]

env: PRETTY_NAME="Ubuntu 22.04 LTS"
NAME="Ubuntu"
VERSION_ID="22.04"
VERSION="22.04 (Jammy Jellyfish)"
VERSION_CODENAME=jammy

# lsb_release -rd
Description: Ubuntu 22.04 LTS
Release: 22.04

host connect dellemc powerstore with nvme-tcp connection

# nvme list-subsys
nvme-subsys0 - NQN=nqn.1988-11.com.dell:powerstore:00:d42d581e674f2B16F2E2
\
 +- nvme1 tcp traddr=172.16.100.165 trsvcid=4420 live
 +- nvme2 tcp traddr=172.16.200.164 trsvcid=4420 live
 +- nvme3 tcp traddr=172.16.200.165 trsvcid=4420 live
 +- nvme4 tcp traddr=172.16.100.164 trsvcid=4420 live

when attaching new volume to host. systemd-udevd trigger unshare process to run snap import command on new volumes and it fail. volume finally map to host. it doesn't affect volume usage. but some udev rule need to check for this strange behavior.

May 06 08:16:43 e2e-l4-094051 systemd-udevd[33374]: nvme0n234: Process '/usr/bin/unshare -m /usr/bin/snap auto-import --mount=/dev/nvme0n234' failed with exit code 1.
May 06 08:16:43 e2e-l4-094051 systemd-udevd[33371]: nvme0n232: Process '/usr/bin/unshare -m /usr/bin/snap auto-import --mount=/dev/nvme0n232' failed with exit code 1.
May 06 08:16:43 e2e-l4-094051 systemd-udevd[33378]: nvme0n236: Process '/usr/bin/unshare -m /usr/bin/snap auto-import --mount=/dev/nvme0n236' failed with exit code 1.
May 06 08:16:43 e2e-l4-094051 systemd-udevd[33384]: nvme0n239: Process '/usr/bin/unshare -m /usr/bin/snap auto-import --mount=/dev/nvme0n239' failed with exit code 1.
---
ProblemType: Bug
AlsaDevices:
 total 0
 crw-rw---- 1 root audio 116, 1 May 6 08:14 seq
 crw-rw---- 1 root audio 116, 33 May 6 08:14 timer
AplayDevices: Error: [Errno 2] No such file or directory: 'aplay'
ApportVersion: 2.20.11-0ubuntu82
Architecture: amd64
ArecordDevices: Error: [Errno 2] No such file or directory: 'arecord'
AudioDevicesInUse: Error: command ['fuser', '-v', '/dev/snd/seq', '/dev/snd/timer'] failed with exit code 1:
CRDA: N/A
CasperMD5CheckResult: pass
DistroRelease: Ubuntu 22.04
InstallationDate: Installed on 2022-05-04 (2 days ago)
InstallationMedia: Ubuntu-Server 22.04 LTS "Jammy Jellyfish" - Release amd64 (20220421)
IwConfig: Error: [Errno 2] No such file or directory: 'iwconfig'
Lsusb:
 Bus 002 Device 002: ID 8087:8002 Intel Corp. 8 channel internal hub
 Bus 002 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
 Bus 001 Device 003: ID 413c:a001 Dell Computer Corp. Hub
 Bus 001 Device 002: ID 8087:800a Intel Corp. Hub
 Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Lsusb-t:
 /: Bus 02.Port 1: Dev 1, Class=root_hub, Driver=ehci-pci/2p, 480M
     |__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/8p, 480M
 /: Bus 01.Port 1: Dev 1, Class=root_hub, Driver=ehci-pci/2p, 480M
     |__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/6p, 480M
         |__ Port 6: Dev 3, If 0, Class=Hub, Driver=hub/6p, 480M
Package: linux (not installed)
PciMultimedia:

ProcEnviron:
 TERM=xterm
 PATH=(custom, no user)
 XDG_RUNTIME_DIR=<set>
 LANG=en_US.UTF-8
 SHELL=/bin/bash
ProcFB: 0 mgag200drmfb
ProcKernelCmdLine: BOOT_IMAGE=/vmlinuz-5.15.0-27-generic root=/dev/mapper/ubuntu--vg-ubuntu--lv ro
ProcVersionSignature: Ubuntu 5.15.0-27.28-generic 5.15.30
RelatedPackageVersions:
 linux-restricted-modules-5.15.0-27-generic N/A
 linux-backports-modules-5.15.0-27-generic N/A
 linux-firmware 20220329.git681281e4-0ubuntu1
RfKill: Error: [Errno 2] No such file or directory: 'rfkill'
Tags: jammy uec-images
Uname: Linux 5.15.0-27-generic x86_64
UpgradeStatus: No upgrade log present (probably fresh install)
UserGroups: N/A
_MarkForUpload: True
dmi.bios.date: 05/14/2021
dmi.bios.release: 2.13
dmi.bios.version: 2.13.0
dmi.board.name: 072T6D
dmi.board.version: A01
dmi.chassis.type: 23
dmi.modalias: dmi:bvn:bvr2.13.0:bd05/14/2021:br2.13:svn:pn:pvr:rvn:rn072T6D:rvrA01:cvn:ct23:cvr:skuSKU=NotProvided;ModelName=:
dmi.product.sku: SKU=NotProvided;ModelName=

[Ubuntu Kernel Bot (ubuntu-kernel-bot)]

This bug is missing log files that will aid in diagnosing the problem. While running an Ubuntu kernel (not a mainline or third-party kernel) please enter the following command in a terminal window:

apport-collect 1971955

and then change the status of the bug to 'Confirmed'.

If, due to the nature of the issue you have encountered, you are unable to run this command, please add a comment stating that fact and change the bug status to 'Confirmed'.

This change has been made by an automated script, maintained by the Ubuntu Kernel Team.

[vincent chen (cheny38)]

apport information

[vincent chen (cheny38)]

apport information

[vincent chen (cheny38)]

apport information

[vincent chen (cheny38)]

apport information

[vincent chen (cheny38)]

apport information

[vincent chen (cheny38)]

apport information

[vincent chen (cheny38)]

apport information

[vincent chen (cheny38)]

apport information

[vincent chen (cheny38)]

apport information

[vincent chen (cheny38)]

apport information

[vincent chen (cheny38)]

apport information

[Mauricio Faria de Oliveira (mfo)]

Hi Vincent,

Thanks for the bug report.

> when attaching new volume to host. systemd-udevd trigger
> unshare process to run snap import command on new volumes and it fail.
> volume finally map to host. it doesn't affect volume usage.
> but some udev rule need to check for this strange behavior.

Please correct me if I'm wrong, but it seems the issue is only
a concern about the command failure status logged, and there's
no functional issue; is that correct?

[Mauricio Faria de Oliveira (mfo)]

Reassigning to package snapd per ownership of rules file.

$ grep -r 'snap auto-import' /lib/udev/rules.d/
/lib/udev/rules.d/66-snapd-autoimport.rules:3: RUN+="/usr/bin/unshare -m /usr/bin/snap auto-import --mount=/dev/%k"

$ dpkg -S /lib/udev/rules.d/66-snapd-autoimport.rules
snapd: /lib/udev/rules.d/66-snapd-autoimport.rules

[vincent chen (cheny38)]

Mauricio,
you are right, there is no function issue. just concern about the annoying snap log entries

[vincent chen (cheny38)]

@snapd team, could someone take look at this issue?

[Alberto Mardegan (mardy)]

Hi Vincent, thanks for reporting this. There should be some message printed by the "snap auto-import" command when it fails.

Can you please try to manually run (as root) the command

    /usr/bin/unshare -m /usr/bin/snap auto-import --mount=/dev/nvme0n239

and paste here the output?

[vincent chen (cheny38)]

Hi, Alberto,

from the output below, auto-import is disabled. what this function is used for？

# /usr/bin/unshare -m /usr/bin/snap auto-import --mount=/dev/nvme0n10
auto-import is disabled on classic

[Alberto Mardegan (mardy)]

Hi Vincent, if I understand it correctly, this command scans the inserted media for snapd assertions and imports them.

It's still not clear to me what's happening: even if you are running on a classic system, the "auto-import is disabled on classic" is just a notification and not an error: the program still exits with a 0 exist status. Yet, in the logs you provided, it appears as if the exist status is 1. Could it be that the error is not coming from "snap auto-import", but rather from the "unshare" command?

Can you please try to manually edit the file (after making a copy of it!) and change the RUN line into

    RUN+="/usr/bin/unshare -m /bin/echo hello"

and see if you still get those errors in the log?

[vincent chen (cheny38)]

Alberto,
there still have error. yes. the log report exist status 1.

May 13 12:45:43 e2e-l4-094051 kernel: nvme nvme1: rescanning namespaces.
May 13 12:45:44 e2e-l4-094051 kernel: nvme nvme4: rescanning namespaces.
May 13 12:46:23 e2e-l4-094051 kernel: nvme nvme3: rescanning namespaces.
May 13 12:46:23 e2e-l4-094051 kernel: nvme nvme2: rescanning namespaces.
May 13 12:46:23 e2e-l4-094051 kernel: nvme nvme4: rescanning namespaces.
May 13 12:46:23 e2e-l4-094051 kernel: nvme nvme1: rescanning namespaces.
May 13 12:46:27 e2e-l4-094051 kernel: nvme nvme3: rescanning namespaces.
May 13 12:46:27 e2e-l4-094051 kernel: nvme nvme4: rescanning namespaces.
May 13 12:46:27 e2e-l4-094051 kernel: nvme nvme1: rescanning namespaces.
May 13 12:46:27 e2e-l4-094051 kernel: nvme nvme2: rescanning namespaces.
May 13 12:46:28 e2e-l4-094051 systemd-udevd[131706]: nvme0n32: Process '/usr/bin/unshare -m /bin/echo hello' failed with exit code 1.
May 13 12:46:28 e2e-l4-094051 systemd-udevd[131704]: nvme0n31: Process '/usr/bin/unshare -m /bin/echo hello' failed with exit code 1.
May 13 12:46:32 e2e-l4-094051 systemd-udevd[131721]: nvme0n35: Process '/usr/bin/unshare -m /bin/echo hello' failed with exit code 1.
May 13 12:46:33 e2e-l4-094051 systemd-udevd[131718]: nvme0n33: Process '/usr/bin/unshare -m /bin/echo hello' failed with exit code 1.
May 13 12:46:33 e2e-l4-094051 systemd-udevd[131719]: nvme0n34: Process '/usr/bin/unshare -m /bin/echo hello' failed with exit code 1.

[Maciej Borzecki (maciek-borzecki)]

For the record, does /usr/bin/unshare exist in your system? Can you run the command that Alberto provided in the console?

[vincent chen (cheny38)]

Maciej, please check the result. manually run the command has no problem. the exist code is 0.

root@e2e-l4-094051:~# which unshare
/usr/bin/unshare

root@e2e-l4-094051:~# /usr/bin/unshare -m /bin/echo hello
hello
root@e2e-l4-094051:~# echo $?
0

[Maciej Borzecki (maciek-borzecki)]

Can you attach the contents of /etc/os-release?

[Alberto Mardegan (mardy)]

Vincent, maybe the udev rules are running under a user lacking some privileges?

Can you please try changing the rule to

    RUN+="/bin/bash -c 'id > /tmp/id.log'"

and then paste here the output of id.log? (hopefully I didn't mess up the quoting in the command :-) )

[vincent chen (cheny38)]

root@e2e-l4-094051:~# cat /etc/os-release
PRETTY_NAME="Ubuntu 22.04 LTS"
NAME="Ubuntu"
VERSION_ID="22.04"
VERSION="22.04 (Jammy Jellyfish)"
VERSION_CODENAME=jammy
ID=ubuntu
ID_LIKE=debian
HOME_URL="https://www.ubuntu.com/"
SUPPORT_URL="https://help.ubuntu.com/"
BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/"
PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy"
UBUNTU_CODENAME=jammy

@Alberto Mardegan,

root@e2e-l4-094051:~# cat /tmp/id.log
uid=0(root) gid=0(root) groups=0(root)

[Alberto Mardegan (mardy)]

Mmm... I'm running out of ideas! Mayve it's something with the environment?

Vincent, can you try changing the rule to

    RUN+="/bin/bash -c 'set > /tmp/set.log'"

and attach set.log here?

[vincent chen (cheny38)]

Alberto,

here it is

# cat /tmp/set.log
ACTION=add
BASH=/bin/bash
BASHOPTS=checkwinsize:cmdhist:complete_fullquote:extquote:force_fignore:globasciiranges:hostcomplete:interactive_comments:progcomp:promptvars:sourcepath
BASH_ALIASES=()
BASH_ARGC=()
BASH_ARGV=()
BASH_CMDS=()
BASH_EXECUTION_STRING='set > /tmp/set.log'
BASH_LINENO=()
BASH_SOURCE=()
BASH_VERSINFO=([0]="5" [1]="1" [2]="16" [3]="1" [4]="release" [5]="x86_64-pc-linux-gnu")
BASH_VERSION='5.1.16(1)-release'
CURRENT_TAGS=:systemd:
DEVLINKS='/dev/disk/by-id/nvme-dellemc-powerstore_803ZX23 /dev/disk/by-id/nvme-eui.b376afea395e91ae8ccf096800c3f03f'
DEVNAME=/dev/nvme0n32
DEVPATH=/devices/virtual/nvme-subsystem/nvme-subsys0/nvme0n32
DEVTYPE=disk
DIRSTACK=()
DISKSEQ=195
DM_MULTIPATH_DEVICE_PATH=0
EUID=0
GROUPS=()
HOSTNAME=e2e-l4-094051
HOSTTYPE=x86_64
ID_FS_TYPE=
ID_MODEL=dellemc-powerstore
ID_REVISION=3.0.0.0
ID_SERIAL=dellemc-powerstore_803ZX23
ID_SERIAL_SHORT=803ZX23
ID_WWN=eui.b376afea395e91ae8ccf096800c3f03f
IFS=$' \t\n'
MACHTYPE=x86_64-pc-linux-gnu
MAJOR=259
MINOR=161
MPATH_SBIN_PATH=/sbin
OPTERR=1
OPTIND=1
OSTYPE=linux-gnu
PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
PPID=64699
PS4='+ '
PWD=/
SEQNUM=84566
SHELL=/bin/bash
SHELLOPTS=braceexpand:hashall:interactive-comments
SHLVL=1
SUBSYSTEM=block
TAGS=:systemd:
TERM=dumb
UID=0
USEC_INITIALIZED=11055413784
_=/bin/bash

[korese (korese)]

Alberto,

I have exactly the same bug as Vincent on multiple Ubuntu 22.04 machines, so if there is anything I can provide you with to fix this issue let me know!

[Alberto Mardegan (mardy)]

Thanks Vincent. I think I got some hints: I downloaded the package from Jammy, I unpacked it and then ran a diff on the systemd unit file for the udev service (since in the documentation of udev[1] it's written that programs are executed in a sandbox) from the version in Focal:

==========
--- /lib/systemd/system/systemd-udevd.service 2022-04-21 15:54:39.000000000 +0300
+++ lib/systemd/system/systemd-udevd.service 2022-04-07 22:28:15.000000000 +0300
@@ -1,4 +1,4 @@
-# SPDX-License-Identifier: LGPL-2.1+
+# SPDX-License-Identifier: LGPL-2.1-or-later
 #
 # This file is part of systemd.
 #
@@ -8,7 +8,7 @@
 # (at your option) any later version.

 [Unit]
-Description=udev Kernel Device Manager
+Description=Rule-based Manager for Device Events and Files
 Documentation=man:systemd-udevd.service(8) man:udev(7)
 DefaultDependencies=no
 After=systemd-sysusers.service systemd-hwdb-update.service
@@ -16,8 +16,10 @@
 ConditionPathIsReadWrite=/sys

 [Service]
+DeviceAllow=block-* rwm
+DeviceAllow=char-* rwm
 Type=notify
-# Note that udev also adjusts the OOM score internally and will reset the value internally for its workers
+# Note that udev will reset the value internally for its workers
 OOMScoreAdjust=-1000
 Sockets=systemd-udevd-control.socket systemd-udevd-kernel.socket
 Restart=always
@@ -27,11 +29,14 @@
 KillMode=mixed
 TasksMax=infinity
 PrivateMounts=yes
+ProtectClock=yes
 ProtectHostname=yes
 MemoryDenyWriteExecute=yes
 RestrictAddressFamilies=AF_UNIX AF_NETLINK AF_INET AF_INET6
 RestrictRealtime=yes
 RestrictSUIDSGID=yes
+SystemCallFilter=@system-service @module @raw-io bpf
+SystemCallErrorNumber=EPERM
 LockPersonality=yes
 IPAddressDeny=any
 WatchdogSec=3min
==========

I need to double-check, but I suspect that the SystemCallFilterAddition might be causing problems.

Vince, can you please make a backup copy of /lib/systemd/system/systemd-udevd.service, then remove the two SystemCallFilter and SystemCallErrorNumber lines, reboot and see if the errors are gone?

If they are, then please restore the original file, and try adding "@process" to the SystemCallFilter list; then reboot and see if it helped. Or you can have a look at the possible values here [2] and try understanding which ones are necessary. Though if you don't have time, don't worry too much with this: it's something that we should be able to determine ourselves.

[1]: https://www.freedesktop.org/software/systemd/man/udev.html
[2]: https://www.freedesktop.org/software/systemd/man/systemd.exec.html#SystemCallFilter=

[Alberto Mardegan (mardy)]

Hi again Vincent :-)
  Please ignore the part about adding more attributes to the SystemCallFilter list; I don't think it's a road we want to follow.

What would be more important for me to know, is whether things work if you change the RUN line to just

    RUN+="/usr/bin/snap auto-import --mount=/dev/%k"

Please let me know if this works. :-)

[vincent chen (cheny38)]

Alberto,
there don't see the error anymore after applying latest change.

[Nick Rosbrook (enr0n)]

I think this a duplicate of, or closely related to bug 1966203.

[Alberto Mardegan (mardy)]

Thanks Nick, indeed! I'm closing this since 1966203 was reported first.