Something amiss with classic snaps - EACCES error trying to access /var/lib/snapd/void (specifically node)

lucyllewy · July 15, 2022, 5:14pm

The node snap is unable to run npm install:

$ npm init
This utility will walk you through creating a package.json file.
It only covers the most common items, and tries to guess sensible defaults.

See `npm help init` for definitive documentation on these fields
and exactly what they do.

Use `npm install <pkg>` afterwards to install a package and
save it as a dependency in the package.json file.

Press ^C at any time to quit.
package name: (void) 
version: (1.0.0) 
description: 
entry point: (index.js) 
npm notice 
npm notice New minor version of npm available! 8.13.2 -> 8.14.0
npm notice Changelog: https://github.com/npm/cli/releases/tag/v8.14.0
npm notice Run npm install -g npm@8.14.0 to update!
npm notice 
npm ERR! code EACCES
npm ERR! syscall scandir
npm ERR! path /var/lib/snapd/void
npm ERR! errno -13
npm ERR! Error: EACCES: permission denied, scandir '/var/lib/snapd/void'
npm ERR!  [Error: EACCES: permission denied, scandir '/var/lib/snapd/void'] {
npm ERR!   errno: -13,
npm ERR!   code: 'EACCES',
npm ERR!   syscall: 'scandir',
npm ERR!   path: '/var/lib/snapd/void'
npm ERR! }
npm ERR! 
npm ERR! The operation was rejected by your operating system.
npm ERR! It is likely you do not have the permissions to access this file as the current user
npm ERR! 
npm ERR! If you believe this might be a permissions issue, please double-check the
npm ERR! permissions of the file and its containing directories, or try running
npm ERR! the command again as root/Administrator.

npm ERR! A complete log of this run can be found in:
npm ERR!     /home/dani/.npm/_logs/2022-07-15T17_08_41_197Z-debug-0.log

This is a classic snap so I have no idea why it is having its environment set up by snapd in a way that causes it to think the current working directory is /var/lib/snapd/void - it wouldn’t try to access the project files there otherwise (see this from an already established project where it specifically tries to access the package-lock.json from my project in the void directory):

$ npm install
npm ERR! code EACCES
npm ERR! syscall open
npm ERR! path /var/lib/snapd/void/package-lock.json
npm ERR! errno -13
npm ERR! Error: EACCES: permission denied, open '/var/lib/snapd/void/package-lock.json'
npm ERR!  [Error: EACCES: permission denied, open '/var/lib/snapd/void/package-lock.json'] {
npm ERR!   errno: -13,
npm ERR!   code: 'EACCES',
npm ERR!   syscall: 'open',
npm ERR!   path: '/var/lib/snapd/void/package-lock.json'
npm ERR! }
npm ERR! 
npm ERR! The operation was rejected by your operating system.
npm ERR! It is likely you do not have the permissions to access this file as the current user
npm ERR! 
npm ERR! If you believe this might be a permissions issue, please double-check the
npm ERR! permissions of the file and its containing directories, or try running
npm ERR! the command again as root/Administrator.

npm ERR! A complete log of this run can be found in:
npm ERR!     /home/dani/.npm/_logs/2022-07-15T17_06_43_575Z-debug-0.log

$ snap version
snap    2.56.2
snapd   2.56.2
series  16
ubuntu  22.04
kernel  5.15.0-40-generic

I’ve tried with both 16/stable and 18/stable channels of node and both fail the same way.

ppd · July 15, 2022, 5:23pm

Huh. Interesting. npm install works fine here (installed: 16.16.0 (6488) 29MB classic, 22.04). Does npm install --verbose return anything useful?

lucyllewy · July 15, 2022, 5:33pm

can’t see anything helpful, but others might:

npm timing npm:load:whichnode Completed in 0ms
npm timing config:load:defaults Completed in 0ms
npm timing config:load:file:/snap/node/6512/lib/node_modules/npm/npmrc Completed in 0ms
npm timing config:load:builtin Completed in 0ms
npm timing config:load:cli Completed in 1ms
npm timing config:load:env Completed in 1ms
npm timing config:load:file:/var/lib/snapd/void/.npmrc Completed in 0ms
npm timing config:load:project Completed in 1ms
npm timing config:load:file:/home/dani/.npmrc Completed in 4ms
npm timing config:load:user Completed in 4ms
npm timing config:load:file:/home/dani/.npm-packages/etc/npmrc Completed in 1ms
npm timing config:load:global Completed in 1ms
npm timing config:load:validate Completed in 0ms
npm timing config:load:credentials Completed in 0ms
npm timing config:load:setEnvs Completed in 1ms
npm timing config:load Completed in 10ms
npm timing npm:load:configload Completed in 11ms
npm timing npm:load:mkdirpcache Completed in 0ms
npm timing npm:load:mkdirplogs Completed in 0ms
npm verb title npm install
npm verb argv "install" "--loglevel" "verbose"
npm timing npm:load:setTitle Completed in 0ms
npm timing config:load:flatten Completed in 2ms
npm timing npm:load:display Completed in 5ms
npm verb logfile logs-max:10 dir:/home/dani/.npm/_logs
npm verb logfile /home/dani/.npm/_logs/2022-07-15T17_32_00_884Z-debug-0.log
npm timing npm:load:logFile Completed in 4ms
npm timing npm:load:timers Completed in 0ms
npm timing npm:load:configScope Completed in 0ms
npm timing npm:load Completed in 21ms
npm timing arborist:ctor Completed in 1ms
npm timing arborist:ctor Completed in 0ms
npm timing idealTree:init Completed in 7ms
npm timing idealTree:userRequests Completed in 0ms
npm timing idealTree:#root Completed in 0ms
npm timing idealTree:buildDeps Completed in 1ms
npm timing idealTree:fixDepFlags Completed in 0ms
npm timing idealTree Completed in 8ms
npm timing reify:loadTrees Completed in 10ms
npm timing reify:diffTrees Completed in 0ms
npm timing reify:retireShallow Completed in 1ms
npm timing reify:createSparse Completed in 0ms
npm timing reify:loadBundles Completed in 0ms
npm timing reify:audit Completed in 0ms
npm timing reify:unpack Completed in 0ms
npm timing reify:unretire Completed in 0ms
npm timing build:queue Completed in 0ms
npm timing build:deps Completed in 1ms
npm timing build Completed in 1ms
npm timing reify:build Completed in 1ms
npm timing reify:trash Completed in 0ms
npm timing command:install Completed in 20ms
npm verb stack Error: EACCES: permission denied, open '/var/lib/snapd/void/package-lock.json'
npm verb cwd /var/lib/snapd/void
npm verb Linux 5.15.0-40-generic
npm verb node v18.6.0
npm verb npm  v8.13.2
npm ERR! code EACCES
npm ERR! syscall open
npm ERR! path /var/lib/snapd/void/package-lock.json
npm ERR! errno -13
npm ERR! Error: EACCES: permission denied, open '/var/lib/snapd/void/package-lock.json'
npm ERR!  [Error: EACCES: permission denied, open '/var/lib/snapd/void/package-lock.json'] {
npm ERR!   errno: -13,
npm ERR!   code: 'EACCES',
npm ERR!   syscall: 'open',
npm ERR!   path: '/var/lib/snapd/void/package-lock.json'
npm ERR! }
npm ERR! 
npm ERR! The operation was rejected by your operating system.
npm ERR! It is likely you do not have the permissions to access this file as the current user
npm ERR! 
npm ERR! If you believe this might be a permissions issue, please double-check the
npm ERR! permissions of the file and its containing directories, or try running
npm ERR! the command again as root/Administrator.
npm verb exit -13
npm timing npm Completed in 111ms
npm verb unfinished npm timer reify 1657906320974
npm verb unfinished npm timer reify:save 1657906320992
npm verb code -13

npm ERR! A complete log of this run can be found in:
npm ERR!     /home/dani/.npm/_logs/2022-07-15T17_32_00_884Z-debug-0.log

lucyllewy · July 15, 2022, 5:59pm

just for completeness, this is the working directory path from where I’m executing npm:

$ pwd
/home/dani/Development/sites/isitoutyet-svelte

ppd · July 15, 2022, 6:07pm

There seem to be quite a few bug reports around where snapped apps, e.g. docker, try to access /var/lib/snapd/void if you search around on Google. No obvious solutions though

Anything useful from SNAPD_DEBUG=1 snap run node.npm install?

lucyllewy · July 15, 2022, 6:20pm

There does appear to be an issue with the working directory, specifically these two lines:

DEBUG: cannot open path of the original working directory /dani/Development/sites/isitoutyet-svelte
DEBUG: the process has been placed in the special void directory

it looks like it’s lost the /home prefix?

Full `snap run` output

$ SNAPD_DEBUG=1 snap run node.npm install
2022/07/15 19:18:43.137670 tool_linux.go:204: DEBUG: restarting into "/snap/snapd/current/usr/bin/snap"
2022/07/15 19:18:43.298296 cmd_run.go:1035: DEBUG: executing snap-confine from /snap/snapd/16292/usr/lib/snapd/snap-confine
2022/07/15 19:18:43.299937 cmd_run.go:438: DEBUG: SELinux not enabled
2022/07/15 19:18:43.300051 tracking.go:46: DEBUG: creating transient scope snap.node.npm
2022/07/15 19:18:43.300875 tracking.go:186: DEBUG: using session bus
2022/07/15 19:18:43.302107 tracking.go:319: DEBUG: create transient scope job: /org/freedesktop/systemd1/job/2788
2022/07/15 19:18:43.302867 tracking.go:419: DEBUG: job result is "done"
2022/07/15 19:18:43.302880 tracking.go:426: DEBUG: transient scope snap.node.npm.6ace7a0b-79a4-48b4-ae88-de438ad65cbe.scope created
2022/07/15 19:18:43.303110 tracking.go:146: DEBUG: waited 2.147245ms for tracking
DEBUG: umask reset, old umask was   02
DEBUG: security tag: snap.node.npm
DEBUG: executable:   /snap/snapd/16292/usr/lib/snapd/snap-exec
DEBUG: confinement:  classic
DEBUG: base snap:    core20
DEBUG: ruid: 1000, euid: 0, suid: 0
DEBUG: rgid: 1000, egid: 1000, sgid: 1000
DEBUG: apparmor label on snap-confine is: /snap/snapd/16292/usr/lib/snapd/snap-confine
DEBUG: apparmor mode is: enforce
DEBUG: creating lock directory /run/snapd/lock (if missing)
DEBUG: set_effective_identity uid:0 (change: no), gid:0 (change: yes)
DEBUG: opening lock directory /run/snapd/lock
DEBUG: set_effective_identity uid:0 (change: no), gid:1000 (change: yes)
DEBUG: opening lock file: /run/snapd/lock/.lock
DEBUG: set_effective_identity uid:0 (change: no), gid:0 (change: yes)
DEBUG: set_effective_identity uid:0 (change: no), gid:1000 (change: yes)
DEBUG: sanity timeout initialized and set for 30 seconds
DEBUG: acquiring exclusive lock (scope (global), uid 0)
DEBUG: sanity timeout reset and disabled
DEBUG: ensuring that snap mount directory is shared
DEBUG: unsharing snap namespace directory
DEBUG: set_effective_identity uid:0 (change: no), gid:0 (change: yes)
DEBUG: set_effective_identity uid:0 (change: no), gid:1000 (change: yes)
DEBUG: (experimental) ensuring snap mount and data directories are mount points
DEBUG: releasing lock 5
DEBUG: preparing classic execution environment
DEBUG: (experimental) unsharing the mount namespace (per-classic-snap)
DEBUG: set_effective_identity uid:1000 (change: yes), gid:1000 (change: yes)
DEBUG: creating user data directory: /home/dani/snap/node/6512
DEBUG: requesting changing of apparmor profile on next exec to snap.node.npm
DEBUG: ruid: 1000, euid: 1000, suid: 0
DEBUG: setting capabilities bounding set
DEBUG: regaining SYS_ADMIN
DEBUG: loading bpf program for security tag snap.node.npm
DEBUG: read 14 bytes from /var/lib/snapd/seccomp/bpf//snap.node.npm.bin
DEBUG: clearing SYS_ADMIN
DEBUG: execv(/snap/snapd/16292/usr/lib/snapd/snap-exec, /snap/snapd/16292/usr/lib/snapd/snap-exec...)
DEBUG:  argv[1] = node.npm
DEBUG:  argv[2] = install
DEBUG: umask restored to   02
DEBUG: working directory restored to /home/dani/Development/sites/isitoutyet-svelte
2022/07/15 19:18:43.452950 tool_linux.go:204: DEBUG: restarting into "/snap/snapd/current/usr/bin/snap"
2022/07/15 19:18:43.465268 cmd_run.go:1035: DEBUG: executing snap-confine from /snap/snapd/16292/usr/lib/snapd/snap-confine
2022/07/15 19:18:43.466442 cmd_run.go:438: DEBUG: SELinux not enabled
2022/07/15 19:18:43.466515 tracking.go:46: DEBUG: creating transient scope snap.node.node
2022/07/15 19:18:43.467222 tracking.go:186: DEBUG: using session bus
2022/07/15 19:18:43.468140 tracking.go:319: DEBUG: create transient scope job: /org/freedesktop/systemd1/job/2792
2022/07/15 19:18:43.468717 tracking.go:419: DEBUG: job result is "done"
2022/07/15 19:18:43.468727 tracking.go:426: DEBUG: transient scope snap.node.node.b34799bd-fdc3-4c9f-93fd-4ae261c8a1e5.scope created
2022/07/15 19:18:43.468996 tracking.go:146: DEBUG: waited 1.72604ms for tracking
DEBUG: umask reset, old umask was   02
DEBUG: security tag: snap.node.node
DEBUG: executable:   /snap/snapd/16292/usr/lib/snapd/snap-exec
DEBUG: confinement:  classic
DEBUG: base snap:    core20
DEBUG: ruid: 1000, euid: 0, suid: 0
DEBUG: rgid: 1000, egid: 1000, sgid: 1000
DEBUG: apparmor label on snap-confine is: /snap/snapd/16292/usr/lib/snapd/snap-confine
DEBUG: apparmor mode is: enforce
DEBUG: moving to mount namespace of pid 1
DEBUG: creating lock directory /run/snapd/lock (if missing)
DEBUG: set_effective_identity uid:0 (change: no), gid:0 (change: yes)
DEBUG: opening lock directory /run/snapd/lock
DEBUG: set_effective_identity uid:0 (change: no), gid:1000 (change: yes)
DEBUG: opening lock file: /run/snapd/lock/.lock
DEBUG: set_effective_identity uid:0 (change: no), gid:0 (change: yes)
DEBUG: set_effective_identity uid:0 (change: no), gid:1000 (change: yes)
DEBUG: sanity timeout initialized and set for 30 seconds
DEBUG: acquiring exclusive lock (scope (global), uid 0)
DEBUG: sanity timeout reset and disabled
DEBUG: ensuring that snap mount directory is shared
DEBUG: unsharing snap namespace directory
DEBUG: set_effective_identity uid:0 (change: no), gid:0 (change: yes)
DEBUG: set_effective_identity uid:0 (change: no), gid:1000 (change: yes)
DEBUG: (experimental) ensuring snap mount and data directories are mount points
DEBUG: releasing lock 5
DEBUG: preparing classic execution environment
DEBUG: (experimental) unsharing the mount namespace (per-classic-snap)
DEBUG: set_effective_identity uid:1000 (change: yes), gid:1000 (change: yes)
DEBUG: creating user data directory: /home/dani/snap/node/6512
DEBUG: requesting changing of apparmor profile on next exec to snap.node.node
DEBUG: ruid: 1000, euid: 1000, suid: 0
DEBUG: setting capabilities bounding set
DEBUG: regaining SYS_ADMIN
DEBUG: loading bpf program for security tag snap.node.node
DEBUG: read 14 bytes from /var/lib/snapd/seccomp/bpf//snap.node.node.bin
DEBUG: clearing SYS_ADMIN
DEBUG: execv(/snap/snapd/16292/usr/lib/snapd/snap-exec, /snap/snapd/16292/usr/lib/snapd/snap-exec...)
DEBUG:  argv[1] = node
DEBUG:  argv[2] = /snap/node/6512/bin/npm
DEBUG:  argv[3] = install
DEBUG: umask restored to   02
DEBUG: cannot open path of the original working directory /dani/Development/sites/isitoutyet-svelte
DEBUG: the process has been placed in the special void directory

lucyllewy · July 15, 2022, 6:25pm

This seems to be due to chaining from npm into node executables which are causing interactions with confinement (even though both are classic, and within the same snap).

The first exec succeeds and restores the right working directory though:

DEBUG: execv(/snap/snapd/16292/usr/lib/snapd/snap-exec, /snap/snapd/16292/usr/lib/snapd/snap-exec...)
DEBUG:  argv[1] = node.npm
DEBUG:  argv[2] = install

While the second exec call with these arguments is the one that is failing to have the working directory restored:

DEBUG: execv(/snap/snapd/16292/usr/lib/snapd/snap-exec, /snap/snapd/16292/usr/lib/snapd/snap-exec...)
DEBUG:  argv[1] = node
DEBUG:  argv[2] = /snap/node/6512/bin/npm
DEBUG:  argv[3] = install

ppd · July 15, 2022, 7:12pm

Yes, very strange. Obviously, it cannot restore to a non-existent path. In any case, it’s very good material for a bug report.

lucyllewy · July 15, 2022, 7:45pm

Bug report for this issue: https://bugs.launchpad.net/snapd/+bug/1981858

shakeelansari63 · October 1, 2023, 9:16am

Looks like the issue still exist. No update on snapd bug report either. Has anyone found any solution or workaround.