[BUG] virgin installs of plugin don't launch python code until next boot

geeksville commented 1 year ago

Please confirm

[X] I have searched existing issues
[X] This issue is not a duplicate of an existing one
[X] I have checked the common issues section in the readme file
[X] I have attached logs to this bug report (failure to include logs will mean your issue will not be responded too).

Bug Report Description

hmm - I don't think the plugin python startup code (i.e. Plugin._main()) is getting invoked for virgin installs from the store (i.e. when user didn't previously have that plugin).

Steps to repro:

Uninstall the plugin using the decky menus
Go delete the directories used for the plugin and its datafiles (manually) - to simulate a virgin install
Install a plugin (I tried a couple) via the testing store
Look at the logs for that plugin and see none of the log messages the plugin usually prints
Not until the python daemon is restarted (for normal users this is via restart the computer?) does the python Plugin._main() get run.

Is this expected behavior? If not (and you want me to poke around) is the first step to debugging this running PluginLoader from a shell instead so I can see if it is getting whacked from JS to launch the new plugin daemon?

Expected Behaviour

It should run Plugin._main() etc

SteamOS version

steamos 3.4.4 stable

Selected Update Channel

Prerelease

Have you modified the read-only filesystem at any point?

yes

Logs

I'm actively debugging this and will post more info as a comment. Do not bother debugging until I update the bug.

journalctl -f -u plugin_loader.service

When uninstalling a plugin from the JS everything looks fine:

Mar 04 17:56:14 steamdeck PluginLoader[1165]: [browser][INFO]: uninstalling Steamback
Mar 04 17:56:14 steamdeck PluginLoader[1165]: [browser][INFO]:  at dir /home/deck/homebrew/plugins/Steamback

But then when you go install a plugin from the store:

Mar 04 17:56:36 steamdeck PluginLoader[1165]: [browser][INFO]: Installing Steamback (Version: 0.3.3-4799b55)
Mar 04 17:56:37 steamdeck PluginLoader[1165]: [base_events][ERROR]: Unclosed client session
Mar 04 17:56:37 steamdeck PluginLoader[1165]: client_session: <aiohttp.client.ClientSession object at 0x7f44714a5300>
Mar 04 17:56:37 steamdeck PluginLoader[1165]: [browser][INFO]: Installed Steamback (Version: 0.3.3-4799b55)
Mar 04 17:56:38 steamdeck PluginLoader[1165]: ======== Running on http://127.0.0.1:1337 ========
Mar 04 17:56:38 steamdeck PluginLoader[1165]: (Press CTRL+C to quit)
Mar 04 17:56:38 steamdeck PluginLoader[1165]: [loader][INFO]: Loaded Steamback
Mar 04 17:56:38 steamdeck PluginLoader[2959]: Failed to start Steamback!
Mar 04 17:56:38 steamdeck PluginLoader[2959]: Traceback (most recent call last):
Mar 04 17:56:38 steamdeck PluginLoader[2959]:   File "plugin.py", line 89, in _init
Mar 04 17:56:38 steamdeck PluginLoader[2959]:   File "<frozen importlib._bootstrap_external>", line 883, in exec_module
Mar 04 17:56:38 steamdeck PluginLoader[2959]:   File "<frozen importlib._bootstrap>", line 241, in _call_with_frames_removed
Mar 04 17:56:38 steamdeck PluginLoader[2959]:   File "/home/deck/homebrew/plugins/Steamback/main.py", line 14, in <module>
Mar 04 17:56:38 steamdeck PluginLoader[2959]:     import decky_plugin
Mar 04 17:56:38 steamdeck PluginLoader[2959]:   File "/tmp/_MEIquDnQM/plugin/decky_plugin.py", line 195, in <module>
Mar 04 17:56:38 steamdeck PluginLoader[2959]:     logging.basicConfig(filename=DECKY_PLUGIN_LOG,
Mar 04 17:56:38 steamdeck PluginLoader[2959]:   File "logging/__init__.py", line 2040, in basicConfig
Mar 04 17:56:38 steamdeck PluginLoader[2959]:   File "logging/__init__.py", line 1169, in __init__
Mar 04 17:56:38 steamdeck PluginLoader[2959]:   File "logging/__init__.py", line 1201, in _open
Mar 04 17:56:38 steamdeck PluginLoader[2959]: PermissionError: [Errno 13] Permission denied: '/home/deck/homebrew/plugins/Steamback/plugin.log'

So I looked at the permissions for the just created Steamback directory:

(deck@steamdeck homebrew)$ ls -l /home/deck/homebrew/plugins
total 8
dr-xr-xr-x 3 deck deck 4096 Mar  1 09:31 protondb-decky
dr-xr-xr-x 4 deck deck 4096 Mar  4 17:56 Steamback

Owner doesn't have write permission - which is fine normally, but notice that the loader is trying to write a plugin.log file to that directory. Which seems incorrect. Investigating...

geeksville commented 1 year ago

update 1: If I then reboot the steamdeck, the plugin loader (this time) uses the correct directory for log files and doesn't get a permission error:

Mar 04 18:09:31 steamdeck systemd[1]: Stopping SteamDeck Plugin Loader...
Mar 04 18:09:31 steamdeck systemd[1]: plugin_loader.service: Main process exited, code=killed, status=9/KILL
Mar 04 18:09:31 steamdeck systemd[1]: plugin_loader.service: Failed with result 'signal'.
Mar 04 18:09:31 steamdeck systemd[1]: Stopped SteamDeck Plugin Loader.
Mar 04 18:09:31 steamdeck systemd[1]: plugin_loader.service: Consumed 1.301s CPU time.
-- Boot ce078a0b5f8e413ba6ae2ec9a2bee809 --
Mar 04 18:09:50 steamdeck systemd[1]: Started SteamDeck Plugin Loader.
Mar 04 18:09:51 steamdeck PluginLoader[1161]: [loader][INFO]: plugin_path: /home/deck/homebrew/plugins
Mar 04 18:09:51 steamdeck PluginLoader[1161]: [updater][INFO]: Current branch is not set, determining branch from version...
Mar 04 18:09:51 steamdeck PluginLoader[1161]: [updater][INFO]: Current version determined to be stable
Mar 04 18:09:51 steamdeck PluginLoader[1161]: [loader][INFO]: import plugins from /home/deck/homebrew/plugins
Mar 04 18:09:51 steamdeck PluginLoader[1161]: [loader][INFO]: found plugin: Steamback
Mar 04 18:09:51 steamdeck PluginLoader[1161]: [loader][INFO]: Loaded Steamback
Mar 04 18:09:51 steamdeck PluginLoader[1161]: [loader][INFO]: found plugin: protondb-decky
Mar 04 18:09:51 steamdeck PluginLoader[1161]: [loader][INFO]: Plugin ProtonDB Badges is passive
Mar 04 18:09:51 steamdeck PluginLoader[1161]: [loader][INFO]: Loaded ProtonDB Badges
Mar 04 18:10:01 steamdeck PluginLoader[1161]: [loader][INFO]: Hot reload enabled
Mar 04 18:10:06 steamdeck PluginLoader[1161]: [main][INFO]: Loading Decky frontend!
Mar 04 18:10:21 steamdeck PluginLoader[1161]: [updater][INFO]: Current branch is not set, determining branch from version...
Mar 04 18:10:21 steamdeck PluginLoader[1161]: [updater][INFO]: Current version determined to be stable
Mar 04 18:10:21 steamdeck PluginLoader[1161]: [updater][INFO]: Updated remote version information

geeksville commented 1 year ago

update 2 (moved to separate issue #392)

geeksville commented 1 year ago

update 4: the problem is that import_plugin (when being invoked in the install case) is being provided an incorrect plugin_directory. Though that variable is called plugin_directory in all other usages it is actually the name of the plugin.

That directory in this usage is /home/deck/homebrew/dev/plugins/Steamback (instead of the correct Steamback). And since that is an absolute path later when the DECKY_... envion vars are set:

environ["DECKY_PLUGIN_LOG_DIR"] = path.join(environ["DECKY_HOME"], "logs", self.plugin_directory)
etc...

They get incorrect environment vars because an absolute path as the last argument of path.join effectively discards everything that precedes it.

I'm working on a clean fix now.

Log goo with nasty extra temp debug messages added:

[browser][INFO]: Installed Steamback (Version: 0.3.3-4799b55)
[loader][DEBUG]: file modified: /home/deck/homebrew/dev/plugins/Steamback/dist/index.js
[loader][DEBUG]: file modified: /home/deck/homebrew/dev/plugins/Steamback/main.py
[loader][WARNING]: Importing with plugindir /home/deck/homebrew/dev/plugins/Steamback
======== Running on http://127.0.0.1:1337 ========
(Press CTRL+C to quit)
[loader][INFO]: Loaded Steamback
[selector_events][DEBUG]: Using selector: EpollSelector
[base_events][ERROR]: Unclosed client session
client_session: <aiohttp.client.ClientSession object at 0x7f83f1617df0>
[plugin][WARNING]: Initial environ:
[plugin][WARNING]:   SHELL: /bin/bash
[plugin][WARNING]:   LOG_LEVEL: DEBUG
[plugin][WARNING]:   PWD: /home/deck/homebrew/services
[plugin][WARNING]:   LOGNAME: root
[plugin][WARNING]:   XDG_SESSION_TYPE: tty
[plugin][WARNING]:   MOTD_SHOWN: pam
[plugin][WARNING]:   HOME: /home/deck
[plugin][WARNING]:   SSH_CONNECTION: 192.168.86.20 39724 192.168.86.112 22
[plugin][WARNING]:   CHOWN_PLUGIN_PATH: 0
[plugin][WARNING]:   XDG_SESSION_CLASS: user
[plugin][WARNING]:   USER: root
[plugin][WARNING]:   SHLVL: 0
[plugin][WARNING]:   XDG_SESSION_ID: 37
[plugin][WARNING]:   XDG_RUNTIME_DIR: /run/user/1000
[plugin][WARNING]:   SSH_CLIENT: 192.168.86.20 39724 22
[plugin][WARNING]:   PATH: /usr/local/sbin:/usr/local/bin:/usr/bin
[plugin][WARNING]:   DBUS_SESSION_BUS_ADDRESS: unix:path=/run/user/1000/bus
[plugin][WARNING]:   MAIL: /var/spool/mail/deck
[plugin][WARNING]:   PLUGIN_PATH: /home/deck/homebrew/dev/plugins
[plugin][WARNING]:   OLDPWD: /home/deck
[plugin][WARNING]:   _: /usr/bin/sudo
[plugin][WARNING]:   TERM: unknown
[plugin][WARNING]:   SUDO_COMMAND: /usr/bin/python3 /home/deck/homebrew/dev/pluginloader/backend/main.py
[plugin][WARNING]:   SUDO_USER: deck
[plugin][WARNING]:   SUDO_UID: 1000
[plugin][WARNING]:   SUDO_GID: 1000
[plugin][WARNING]:   LC_CTYPE: C.UTF-8
[plugin][WARNING]: Unset logdir: None
[base_events][ERROR]: Unclosed client session
client_session: <aiohttp.client.ClientSession object at 0x7f83f1617df0>
[inotify_buffer][DEBUG]: in-event <InotifyEvent: src_path=b'/home/deck/homebrew/dev/plugins', wd=1, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=>
[inotify_buffer][DEBUG]: in-event <InotifyEvent: src_path=b'/home/deck/homebrew/dev/plugins/Steamback', wd=1, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=Steamback>
[inotify_buffer][DEBUG]: in-event <InotifyEvent: src_path=b'/home/deck/homebrew/dev/plugins/Steamback', wd=6, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=>
[plugin][WARNING]: Initial deckhome: /home/deck/homebrew and plugin dir /home/deck/homebrew/dev/plugins/Steamback 
[plugin][WARNING]: Initial logdir: /home/deck/homebrew/dev/plugins/Steamback
[inotify_buffer][DEBUG]: in-event <InotifyEvent: src_path=b'/home/deck/homebrew/dev/plugins', wd=1, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=>
[inotify_buffer][DEBUG]: in-event <InotifyEvent: src_path=b'/home/deck/homebrew/dev/plugins/Steamback', wd=1, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=Steamback>
[inotify_buffer][DEBUG]: in-event <InotifyEvent: src_path=b'/home/deck/homebrew/dev/plugins/Steamback', wd=6, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=>
[inotify_buffer][DEBUG]: in-event <InotifyEvent: src_path=b'/home/deck/homebrew/dev/plugins', wd=1, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=>
[inotify_buffer][DEBUG]: in-event <InotifyEvent: src_path=b'/home/deck/homebrew/dev/plugins/Steamback', wd=1, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=Steamback>
[inotify_buffer][DEBUG]: in-event <InotifyEvent: src_path=b'/home/deck/homebrew/dev/plugins/Steamback', wd=6, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=>
[plugin][WARNING]: KEVINH running module, syspath ['/home/deck/homebrew/dev/pluginloader/backend', '/usr/lib/python310.zip', '/usr/lib/python3.10', '/usr/lib/python3.10/lib-dynload', '/home/deck/.local/lib/python3.10/site-packages', '/usr/lib/python3.10/site-packages', '/home/deck/homebrew/dev/pluginloader/plugin', '/home/deck/homebrew/dev/plugins/Steamback/py_modules', '/usr/lib/python310.zip', '/usr/lib/python3.10', '/usr/lib/python3.10/lib-dynload', '/home/deck/.local/lib/python3.10/site-packages', '/usr/lib/python3.10/site-packages'] cwd /home/deck/homebrew/services
[plugin][WARNING]: Using environ:
[plugin][WARNING]:   SHELL: /bin/bash
[plugin][WARNING]:   LOG_LEVEL: DEBUG
[plugin][WARNING]:   PWD: /home/deck/homebrew/services
[plugin][WARNING]:   LOGNAME: root
[plugin][WARNING]:   XDG_SESSION_TYPE: tty
[plugin][WARNING]:   MOTD_SHOWN: pam
[plugin][WARNING]:   HOME: /home/deck
[plugin][WARNING]:   SSH_CONNECTION: 192.168.86.20 39724 192.168.86.112 22
[plugin][WARNING]:   CHOWN_PLUGIN_PATH: 0
[plugin][WARNING]:   XDG_SESSION_CLASS: user
[plugin][WARNING]:   USER: deck
[plugin][WARNING]:   SHLVL: 0
[plugin][WARNING]:   XDG_SESSION_ID: 37
[plugin][WARNING]:   XDG_RUNTIME_DIR: /run/user/1000
[plugin][WARNING]:   SSH_CLIENT: 192.168.86.20 39724 22
[plugin][WARNING]:   PATH: /usr/local/sbin:/usr/local/bin:/usr/bin
[plugin][WARNING]:   DBUS_SESSION_BUS_ADDRESS: unix:path=/run/user/1000/bus
[plugin][WARNING]:   MAIL: /var/spool/mail/deck
[plugin][WARNING]:   PLUGIN_PATH: /home/deck/homebrew/dev/plugins
[plugin][WARNING]:   OLDPWD: /home/deck
[plugin][WARNING]:   _: /usr/bin/sudo
[plugin][WARNING]:   TERM: unknown
[plugin][WARNING]:   SUDO_COMMAND: /usr/bin/python3 /home/deck/homebrew/dev/pluginloader/backend/main.py
[plugin][WARNING]:   SUDO_USER: deck
[plugin][WARNING]:   SUDO_UID: 1000
[plugin][WARNING]:   SUDO_GID: 1000
[plugin][WARNING]:   LC_CTYPE: C.UTF-8
[plugin][WARNING]:   DECKY_VERSION: v2.6.2
[plugin][WARNING]:   DECKY_USER: deck
[plugin][WARNING]:   DECKY_USER_HOME: /home/deck
[plugin][WARNING]:   DECKY_HOME: /home/deck/homebrew
[plugin][WARNING]:   DECKY_PLUGIN_SETTINGS_DIR: /home/deck/homebrew/dev/plugins/Steamback
[plugin][WARNING]:   DECKY_PLUGIN_RUNTIME_DIR: /home/deck/homebrew/dev/plugins/Steamback
[plugin][WARNING]:   DECKY_PLUGIN_LOG_DIR: /home/deck/homebrew/dev/plugins/Steamback
[plugin][WARNING]:   DECKY_PLUGIN_DIR: /home/deck/homebrew/dev/plugins/Steamback
[plugin][WARNING]:   DECKY_PLUGIN_NAME: Steamback
[plugin][WARNING]:   DECKY_PLUGIN_VERSION: 0.3.3-4799b55
[plugin][WARNING]:   DECKY_PLUGIN_AUTHOR: geeksville
Failed to start Steamback!
Traceback (most recent call last):
  File "/home/deck/homebrew/dev/pluginloader/backend/plugin.py", line 105, in _init
    spec.loader.exec_module(module)
  File "<frozen importlib._bootstrap_external>", line 883, in exec_module
  File "<frozen importlib._bootstrap>", line 241, in _call_with_frames_removed
  File "/home/deck/homebrew/dev/plugins/Steamback/main.py", line 14, in <module>
    import decky_plugin
  File "/home/deck/homebrew/dev/pluginloader/plugin/decky_plugin.py", line 195, in <module>
    logging.basicConfig(filename=DECKY_PLUGIN_LOG,
  File "/usr/lib/python3.10/logging/__init__.py", line 2040, in basicConfig
    h = FileHandler(filename, mode,
  File "/usr/lib/python3.10/logging/__init__.py", line 1169, in __init__
    StreamHandler.__init__(self, self._open())
  File "/usr/lib/python3.10/logging/__init__.py", line 1201, in _open
    return open_func(self.baseFilename, self.mode,
PermissionError: [Errno 13] Permission denied: '/home/deck/homebrew/dev/plugins/Steamback/plugin.log'

geeksville commented 1 year ago

ok - fix pr coming in a second. Please review I think it is a possibly serious problem.

SteamDeckHomebrew / decky-loader