Issue 766876  has been merged into this issue.

Is it possible that virtual-file-provider is being created at boot but after dbus starts? Does restarting twice fix this issue?

Is there a workaround for right now until you fix this issue?

#2: /etc/passwd is on the readonly partition, so no, I don't think so. Not sure about restarting twice.

#3: Try "killall -HUP dbus-daemon" as root, as described above. You should be able to SSH to your device as root ~30 seconds after it gives up on the UI job. (First time through, it may reboot automatically.)

derat@: When do I run that command? Right before I run deploy_chrome?

I tried to repro this locally by doing the following:

a) Comment out the "<allow own="org.chromium.KioskAppService"/>" line in /opt/google/chrome/dbus/org.chromium.KioskAppService.conf.
b) Reboot; Chrome aborts on startup as expected.
c) Uncomment the line and reboot.

Chrome happily started up, though, implying that dbus-daemon loaded the updated config.

#5: After you run deploy_chrome and see the problem. (Run it on the Chrome OS device.)

 Issue 767107  has been merged into this issue.

If SIGHUP works for others, I'm interested in knowing that! I'm still poking around in the dbus-daemon source, but as a quick fix, maybe we could update deploy_chrome to send SIGHUP instead of or in addition to rebooting.

I'm not at all familiar with the dbus-daemon codebase, but here are some initial notes (https://cgit.freedesktop.org/dbus/dbus/, tag dbus-1.10.12):

main calls bus_context_new, which calls (among other things) bus_config_load, process_config_first_time_only, process_config_every_time, and process_config_postinit.

SIGHUP (and also ReloadConfig D-Bus calls) call bus_context_reload_config, which calls _dbus_flush_caches, bus_config_load, process_config_every_time, and process_config_postinit.

I don't see anything interesting in process_config_first_time_only. _dbus_flush_caches is maybe marginally more interesting, but it looks like it only clears some in-memory hash tables that are presumably empty when the process starts. I'm not aware of any data that's cached on-disk.

It looks like dbus-daemon also contains support for using inotify to watch config files and/or dirs. That may be complicating things, but I don't know if we're using it, or whether it's used to reload policies vs. activation files or something else.

If someone finds a way to reliably reproduce this issue, it'd be good to figure out whether it was just a fluke that SIGHUP cleared this up on Mike's machine or if it's actually doing something different from rebooting. Maybe config files get reloaded in an arbitrary order each time, for instance. I don't see anything that could be blocking the chronos "allow own" directives if it's loaded after it, though.

Our D-Bus configs are pretty ugly and it's quite easy to accidentally break unrelated services. I see a bunch of unnecessary deny directives, for instance.

Resist the temptation to append --syslog-only to the dbus-daemon command in /etc/init/dbus.conf. I think that it was only added in a later version of D-Bus than what we're using, and if you add it dbus-daemon will fail to start and your system will reboot continually until you recover from USB.

Just FYI, I hit the same exact error a second time after rebuilding and redeploying.
It was just once amid several redeploys, and "killall -HUP dbus-daemon" helped.

If/when you see it again, and if it's still easy for you to test, would you mind doing a bit more experimentation to check how reliable the SIGHUP is for fixing it? For example, after it first shows up:

a) Does the problem persist even after you manually reboot a few times?
b) If you're able to fix it with SIGHUP, does it stay fixed if you reboot again after that?

I still have no idea why SIGHUP would fix things if rebooting doesn't. :-/

I may have had to hard reset once as well, when the ui wouldn't start...
I'll definitely ping you and try to answer those qs if I see it again.

IIUC dbus-deamon is already outputting the log to /var/log/messages like this:
  2017-09-21T17:15:26.918257+09:00 NOTICE dbus[565]: [system] Reloaded configuration

The SIGHUP quick fix suggested in comment #9 sounds good, provided this issue only affects developers who use deploy_chrome.
Otherwise, we can add code to deploy_chrome which detects if chrome is not running after reboot, and print a message which encourages the user to paste relevant logs to this bug.

#14: It logs that message, but I believe it doesn't log much else. The NEWS file says that dbus-daemon was fixed to send warnings to syslog in 1.11.6; we're on 1.10.12.

I'll spend some more time trying to repro this today.

FWIW dbus-daemon's busconfig supports <syslog> element, and /usr/share/dbus-1/system.conf already includes it.
https://dbus.freedesktop.org/doc/dbus-daemon.1.html

Also, you can avoid bricking your device by removing "reboot" from the post-stop part of /etc/init/dbus.conf when tweaking dbus-daemon's config.

Mike just mentioned that he's been passing "--target-dir=/usr/local/chrome --mount-dir=/opt/google/chrome" to deploy_chrome, which might explain the problem. deploy_chrome displays a warning in that case: https://cs.corp.google.com/chromeos_public/chromite/scripts/deploy_chrome.py?q=%22Detected+change+in+D-Bus+service+files%22&sq=package:%5Echromeos_(internal%7Cpublic)$&l=287

"WARNING: Detected change in D-Bus service files, but target dir is not /opt/google/chrome. D-Bus changes will not be picked up by dbus-daemon at boot time."

dbus-daemon is only configured to look in /opt/google/chrome/dbus, so it's not going to pick up new configs after rebooting if they're deployed elsewhere. I didn't think to check if /opt/google/chrome was bind-mounted when I investigated his system, but if it was, that'd probably explain why the files looked older than the boot time but still hadn't been loaded.

Maybe we should make deploy_chrome always copy configs to the real /opt/google/chrome/dbus directory, even if it's going to bind-mount over it later. We could make it reboot the system like normal in that case, although the developer may need to still run deploy_chrome again to redo the mount.

Even simpler, maybe we can just make deploy_chrome send SIGHUP to dbus-daemon instead of rebooting. Assuming that dbus-daemon reopens /opt/google/chrome/dbus, that'd hopefully be enough to get it to pick up the new configs.

probably should do both since they shouldn't be too hard to pull

Uploaded https://crrev.com/c/691356 to switch to SIGHUP. I think we actually don't want to overwrite the original files from /opt/google/chrome/dbus when we're using a bind mount, since that would cause issues after rebooting if the new, deployed policy is more restrictive than the old one.

now that you say that out loud, that makes a lot of sense

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/chromite/+/0fce5bf64aadeadac2d66b4cb64c81176c020fa3

commit 0fce5bf64aadeadac2d66b4cb64c81176c020fa3
Author: Daniel Erat <derat@chromium.org>
Date: Fri Sep 29 06:26:27 2017

chromite: Make deploy_chrome send SIGHUP to dbus-daemon.

Send SIGHUP to dbus-daemon to tell it to reload the policies
from /opt/google/chrome/dbus. This handles the case where a
bind mount has been used to deploy an unstripped Chrome
binary, and it also falls back gracefully to the original
policies when the system is later rebooted.

Also removed the previous code to reboot the system when
policies change.

BUG= chromium:767216 
TEST=added a new service name to one of chrome's d-bus
     policy files, ran deploy_chrome.py with --target-dir
     and --mount-dir, and checked that i was immediately
     able to take ownership of the name as chronos using
     python-dbus. rebooted and was no longer able to take
     ownership of it

Change-Id: Iaf0ccbd79c27d9d607a2cd980dc4f13c6fec4acd
Reviewed-on: https://chromium-review.googlesource.com/691356
Commit-Ready: Dan Erat <derat@chromium.org>
Tested-by: Dan Erat <derat@chromium.org>
Reviewed-by: Justin TerAvest <teravest@chromium.org>

[modify] https://crrev.com/0fce5bf64aadeadac2d66b4cb64c81176c020fa3/scripts/deploy_chrome.py

chromite DEPS roll is at https://crrev.com/c/693318.