[snap] chromium times out connecting document portal with NFS home

That workaround is dangerous, please don't do that (I'm removing it from the description to prevent people from trying that without fully understanding what it does).

Integration with the password keyring is controlled by the the password-manager-service interface, which should have been auto-connected when you upgraded the chromium-browser package. It could be that the connection failed though. Can you please share the output of the following command?

    snap connections chromium | grep password

and attach the files /var/log/apt/history.log and /var/log/apt/term.log ?

Thanks!

I'm also marking snapd affected, since the timeout when activating org.freedesktop.portal.Documents doesn't seem chromium-specific.

Thank you for removing the workaround. I was just coming back to remove it myself when it didn't seem to be a stable solution for some reason.

Here is your answer to a command:
XXX@koira:~$ snap connections chromium | grep password
password-manager-service chromium:password-manager-service - -

history.log as requested

term.log as requested

And to be precise with my wordings, I'm not actually using a separate password manager. I'm storing the passwords to Chromium. And the passwords are on a sqlite db that is stored under my NFS shared /home.

Right, chromium now always stores its saved passwords in a sqlite database in the profile directory, but if available it uses the system's keyring to store the key used to encrypt the contents of that database.
Please run the following command:

    sudo snap connect chromium:password-manager-service

and restart chromium. Do you get your saved passwords now?

(this should have been done automatically when upgrading the chromium-browser package, not sure why it didn't happen)

Yes, indeed the stored passwords inside chromiums sqlite file are encrypted. I didn't try to decrypt those, I didn't know where the key was. After seeking there are keys in the seahorse-application (it has a title "keyring") for chromium (and also chrome separately). Another key looks like a dummy and another one seems to be the actual login and password key.

I did execute the "sudo snap connect chromium:password-manager-service" and it was executed seemingly successfully with no messages displayed on command line. (I also tried for "chromium-browser", that returns an error, so I guess the exact command was ok then.)

After starting chromium-browser I'm still seeing the same message:
019/10/19 11:31:47.504721 cmd_run.go:893: WARNING: cannot start document portal: Failed to activate service 'org.freedesktop.portal.Documents': timed out (service_start_timeout=120000ms)

I also tried rebooting. And after all that the connection between chromium and password-maager seems to be existing:
XXX@koira:~$ snap connections chromium | grep password
password-manager-service chromium:password-manager-service :password-manager-service manual

Oh, wait! Chromium remembers my passwords now. The pain is now a slow start of 12000 ms timeout! Thank you for solving my problem.

Or to be exact, a 120000ms timeout.

Anyway I suspect the chromium and password manager connection might have failed due to headless custom made auto-update script that is run from cron.daily. You can see it working in my term.log on lines 20685-20713. It seems to be unable to find the snapd running, even though it was installed way before and I keep this workstation turned off every night.

Should we continue solving the timeout problem in this issue? It was actually in the header from the beginning and password manager nuance can be removed from the description.

Do you have any apparmor denials in the system log when you observe this slowdown? (run journalctl, look for 'apparmor=DENIED'?

(for what it is worth chromium snap starts just fine for me on fresh 18.04 and 19.10 systems, but I reckon NFS may be a key here, and I don't have it).

> I suspect the chromium and password manager connection might have failed
> due to headless custom made auto-update script that is run from cron.daily

No, the connection to the password-manager-service interface wasn't even attempted, but that's a separate bug, which is being fixed (bug #1849160).

> Should we continue solving the timeout problem in this issue?

Yes, let's do that. What do you mean by a 120000ms timeout, does the chromium window take 2 whole minutes to appear when you launch it?

>> Should we continue solving the timeout problem in this issue?

> Yes, let's do that. What do you mean by a 120000ms timeout, does the chromium window take 2 whole minutes to appear when you launch it?

Yes it does wait for 2 minutes before showing a window. It's a pain and makes the chromium practically useless on an NFS-homed workstation that is shutdown every time after it has been used.

Ack, that's pretty bad. As requested by Paweł in comment #13, could you check whether you get apparmor denials when starting chromium? You can run the following command in a terminal, then launch chromium:

    journalctl -f | grep DEN

Please attach the output after the chromium window has appeared. Thanks!

With journalctl -f | grep DEN these messages appear to the console after waiting the 120000ms timeout:
loka 24 20:56:42 koira audit[12568]: AVC apparmor="DENIED" operation="file_mmap" profile="/snap/snapd/4992/usr/lib/snapd/snap-confine" name="/usr/lib/x86_64-linux-gnu/libgtk3-nocsd.so.0" pid=12568 comm="snap-confine" requested_mask="m" denied_mask="m" fsuid=0 ouid=0
loka 24 20:56:42 koira kernel: audit: type=1400 audit(1571939802.361:56): apparmor="DENIED" operation="file_mmap" profile="/snap/snapd/4992/usr/lib/snapd/snap-confine" name="/usr/lib/x86_64-linux-gnu/libgtk3-nocsd.so.0" pid=12568 comm="snap-confine" requested_mask="m" denied_mask="m" fsuid=0 ouid=0
loka 24 20:56:42 koira audit[1068]: USER_AVC pid=1068 uid=105 auid=4294967295 ses=4294967295 msg='apparmor="DENIED" operation="dbus_method_call" bus="system" path="/" interface="org.freedesktop.DBus.ObjectManager" member="GetManagedObjects" mask="send" name="org.bluez" pid=12568 label="snap.chromium.chromium"
loka 24 20:56:42 koira kernel: audit: type=1107 audit(1571939802.915:57): pid=1068 uid=105 auid=4294967295 ses=4294967295 msg='apparmor="DENIED" operation="dbus_method_call" bus="system" path="/" interface="org.freedesktop.DBus.ObjectManager" member="GetManagedObjects" mask="send" name="org.bluez" pid=12568 label="snap.chromium.chromium"

Hello there.

loka 24 20:56:42 koira audit[12568]: AVC apparmor="DENIED" operation="file_mmap" profile="/snap/snapd/4992/usr/lib/snapd/snap-confine" name="/usr/lib/x86_64-linux-gnu/libgtk3-nocsd.so.0" pid=12568 comm="snap-confine" requested_mask="m" denied_mask="m" fsuid=0 ouid=0

I'm very curious how this can happen. I can only suspect an LD_LIBRARY_PATH or LD_PRELOAD variables is set and snap-confine is actually honouring it somehow, despite that not normally affecting AT_SECURE binaries

loka 24 20:56:42 koira audit[1068]: USER_AVC pid=1068 uid=105 auid=4294967295 ses=4294967295 msg='apparmor="DENIED" operation="dbus_method_call" bus="system" path="/" interface="org.freedesktop.DBus.ObjectManager" member="GetManagedObjects" mask="send" name="org.bluez" pid=12568 label="snap.chromium.chromium"

This denial is fro the chromium snap and could probably be resolved by connecting the "bluez" interface to chromium.

Neither of those explain why NFS is slow in this specific case that you are trying. I wonder if this is some sort of remote side logging that fails because of LAN not providing reverse IP mapping information.

Did you perhaps look at the NFS server logs?

There does not seem to be anything relevant in the server NFS logs. I can try harder, I can try to add verbose and check that the logs are actually being produced, if this does not seem to lead us to the problem source:

With "journalctl -f" only, I can get the following messages. A lot of them seem to be related to document portal. I checked the file flatbak/db/documents and it does not seem to exist.

loka 29 19:44:23 koira dbus-daemon[4642]: [session uid=1000 pid=4642] Activating via systemd: service name='org.freedesktop.portal.Documents' unit='xdg-document-portal.service' requested by ':1.196' (uid=1000 pid=14113 comm="/snap/bin/chromium " label="unconfined")
loka 29 19:44:23 koira systemd[4622]: Starting flatpak document portal service...
loka 29 19:44:23 koira xdg-document-portal[14171]: error: Failed to load db: Error opening file /home/XXX/.local/share/flatpak/db/documents: No such file or directory
loka 29 19:44:23 koira systemd[4622]: xdg-document-portal.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
loka 29 19:44:23 koira systemd[4622]: xdg-document-portal.service: Failed with result 'exit-code'.
loka 29 19:44:23 koira systemd[4622]: Failed to start flatpak document portal service.
loka 29 19:44:39 koira xdg-desktop-por[4802]: Failed to get application states: GDBus.Error:org.freedesktop.portal.Error.Failed: Could not get window list: GDBus.Error:org.freedesktop.DBus.Error.AccessDenied: App introspection not allowed
loka 29 19:45:39 koira xdg-desktop-por[4802]: Failed to get application states: GDBus.Error:org.freedesktop.portal.Error.Failed: Could not get window list: GDBus.Error:org.freedesktop.DBus.Error.AccessDenied: App introspection not allowed
loka 29 19:46:23 koira dbus-daemon[4642]: [session uid=1000 pid=4642] Failed to activate service 'org.freedesktop.portal.Documents': timed out (service_start_timeout=120000ms)
loka 29 19:46:24 koira audit[1013]: USER_AVC pid=1013 uid=105 auid=4294967295 ses=4294967295 msg='apparmor="DENIED" operation="dbus_method_call" bus="system" path="/" interface="org.freedesktop.DBus.ObjectManager" member="GetManagedObjects" mask="send" name="org.bluez" pid=14113 label="snap.chromium.chromium"
                                     exe="/usr/bin/dbus-daemon" sauid=105 hostname=? addr=? terminal=?'
loka 29 19:46:24 koira kernel: audit: type=1107 audit(1572371184.015:58): pid=1013 uid=105 auid=4294967295 ses=4294967295 msg='apparmor="DENIED" operation="dbus_method_call" bus="system" path="/" interface="org.freedesktop.DBus.ObjectManager" member="GetManagedObjects" mask="send" name="org.bluez" pid=14113 label="snap.chromium.chromium"
                                exe="/usr/bin/dbus-daemon" sauid=105 hostname=? addr=? terminal=?'
loka 29 19:46:24 koira audit[14113]: AVC apparmor="DENIED" operation="open" profile="snap.chromium.chromium" name="/var/lib/snapd/desktop/icons/" pid=14113 comm="chrome" requested_mask="r" denied_mask="r" fsuid=1000 ouid=0
loka 29 19:46:24 koira kernel: audit: type=1400 audit(1572371184.832:59): apparmor="DENIED" operation="open" profile="snap.chromium.chromium" name="/var/lib/snapd/desktop/icons/" pid=14113 comm="chrome" requested_mask="r" denied_mask...

It seems that loka 29 20:02:33 koira xdg-document-portal[16225]: error: Failed to load db: invalid gvdb header
 is relevant. I wonder if the database, whatever the format, is somehow corrupt.

As I tried to decsribe, that was only after I created an empty db with executing "touch /home/XXX/.local/share/flatpak/db/documents". Please ignore that.

Ah, forgive me.

I think this bug requires someone to sit down and attempt to reproduce it in a controlled environment. I cannot commit to do that anytime soon as we have a number of open bugs, features we promised to deliver and a handful of people working on the project.

I'd like to keep the bug open for the next pass of bug review that will be done by another engineer. We are working towards reducing the number of NEW, INPROGRESS and finally OPEN bugs so that we can devote more attention to particular cases and work on debugging them properly.