Xubuntu: (not really an error at all) ERROR:dbus.proxies:Introspect error on org.bluez:/org/bluez: dbus.exceptions.DBusException: org.freedesktop.DBus.Error.TimedOut: Failed to activate service 'org.bluez': timed out (service_start_timeout=25000ms)

[Kev Bowring]

Xubuntu seeing long first time boot to desktop from login.

Also causing the long time to desktop from try/install livesession dialogue.

Including xsession-errors from the first time boot on installed system.

ProblemType: Bug
DistroRelease: Ubuntu 18.04
Package: bluez 5.48-0ubuntu3
ProcVersionSignature: Ubuntu 4.15.0-10.11-generic 4.15.3
Uname: Linux 4.15.0-10-generic x86_64
ApportVersion: 2.20.8-0ubuntu10
Architecture: amd64
CurrentDesktop: XFCE
Date: Sat Mar 10 11:32:59 2018
InstallationDate: Installed on 2018-03-08 (1 days ago)
InstallationMedia: Xubuntu 18.04 LTS "Bionic Beaver" - Alpha amd64 (20180306.1)
InterestingModules: bluetooth
MachineType: NOVATECH LTD MBB-44608
ProcKernelCmdLine: BOOT_IMAGE=/boot/vmlinuz-4.15.0-10-generic root=UUID=8d9f054a-4c7a-481f-966e-fc2cd6f51aca ro quiet splash
SourcePackage: bluez
UpgradeStatus: No upgrade log present (probably fresh install)
dmi.bios.date: 06/19/2014
dmi.bios.vendor: American Megatrends Inc.
dmi.bios.version: F5
dmi.board.asset.tag: To be filled by O.E.M.
dmi.board.name: H81M-DS2V
dmi.board.vendor: Gigabyte Technology Co., Ltd.
dmi.board.version: To be filled by O.E.M.
dmi.chassis.asset.tag: 7383241-001
dmi.chassis.type: 3
dmi.chassis.vendor: NOVATECH LTD
dmi.chassis.version: V1.0
dmi.modalias: dmi:bvnAmericanMegatrendsInc.:bvrF5:bd06/19/2014:svnNOVATECHLTD:pnMBB-44608:pvrV1.0:rvnGigabyteTechnologyCo.,Ltd.:rnH81M-DS2V:rvrTobefilledbyO.E.M.:cvnNOVATECHLTD:ct3:cvrV1.0:
dmi.product.family: AMI PLATFORM
dmi.product.name: MBB-44608
dmi.product.version: V1.0
dmi.sys.vendor: NOVATECH LTD
hciconfig:

rfkill:

syslog: Mar 10 11:30:16 test-MBB-44608 NetworkManager[679]: <info> [1520681416.8951] Loaded device plugin: NMBluezManager (/usr/lib/x86_64-linux-gnu/NetworkManager/libnm-device-plugin-bluetooth.so)

[Kev Bowring (flocculant)]

live session xsession-errors

[Alistair Buxton (a-j-buxton)]

The same messages are logged on the live image boot.

[Daniel van Vugt (vanvugt)]

The 25 second delay is a standard dbus timeout. I assume you're talking about:

Mar 10 11:30:25 username-MBB-44608 pulseaudio[1308]: [pulseaudio] pid.c: Daemon already running.
Mar 10 11:30:49 username-MBB-44608 pulseaudio[1150]: [pulseaudio] bluez5-util.c: GetManagedObjects() failed: org.freedesktop.DBus.Error.TimedOut: Failed to activate service 'org.bluez': timed out (service_start_timeout=25000ms)

It sounds like maybe your system is launching too many instances of pulseaudio. The first works and the second fails. I'm not sure how Xubuntu differs in this respect but I don't think we see the same bug in standard Ubuntu.

[Alistair Buxton (a-j-buxton)]

No, we are talking about the errors in xsession-errors.txt:

ERROR:dbus.proxies:Introspect error on org.bluez:/: dbus.exceptions.DBusException: org.freedesktop.DBus.Error.TimedOut: Failed to activate service 'org.bluez': timed out (service_start_timeout=25000ms)
ERROR:dbus.proxies:Introspect error on org.bluez:/org/bluez: dbus.exceptions.DBusException: org.freedesktop.DBus.Error.TimedOut: Failed to activate service 'org.bluez': timed out (service_start_timeout=25000ms)
ERROR:dbus.proxies:Introspect error on org.bluez:/: dbus.exceptions.DBusException: org.freedesktop.DBus.Error.TimedOut: Failed to activate service 'org.bluez': timed out (service_start_timeout=25000ms)

Note that each one of these errors is a separate time out, so the total delay is 75 seconds. This delay blocks the desktop from starting during boot and first login.

The delay can be reproduced any time on the live session by attempting to start blueman-applet from the terminal - it will produce the same errors and then give up after 75 seconds.

The computer under test has no bluetooth hardware and blueman is not running. A patch was added to 16.04 because this situation led to blueman outright crashing there. Now in 18.04 instead of crashing it delays boot up by 75 seconds instead.

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Alistair Buxton (a-j-buxton)]

There is more stuff in syslog too. It looks like pulseaudio is trying and failing to start blueman.

[Sean Davis (bluesabre)]

This might be related to the undocumented addition of pulseaudio-module-bluetooth to blueman 2.0.5-1

http://launchpadlibrarian.net/345214644/blueman_2.0.4-1ubuntu3_2.0.5-1ubuntu1.diff.gz

diff -Nru blueman-2.0.4/debian/control blueman-2.0.5/debian/control
--- blueman-2.0.4/debian/control 2016-03-30 04:43:33.000000000 +0000
+++ blueman-2.0.5/debian/control 2017-11-10 10:13:52.000000000 +0000
@@ -19,7 +19,7 @@
          libpulse-mainloop-glib0, gir1.2-gtk-3.0, gir1.2-gdkpixbuf-2.0,
          gir1.2-glib-2.0, gir1.2-pango-1.0, gir1.2-notify-0.7, python3-cairo,
          python3-gi-cairo, gir1.2-appindicator3-0.1
-Recommends: policykit-1
+Recommends: policykit-1, pulseaudio-module-bluetooth
 Description: Graphical bluetooth manager
  Blueman is a GTK+ bluetooth management utility for GNOME using bluez D-Bus

[Kev Bowring (flocculant)]

Don't appear to be able to find the appropriate log in Ubuntu - however grepping journalctl there for blue* gives me:

journalctl |grep blue*
Mar 14 17:51:27 ubuntu NetworkManager[985]: <info> [1521049887.5999] Loaded device plugin: NMBluezManager (/usr/lib/x86_64-linux-gnu/NetworkManager/libnm-device-plugin-bluetooth.so)
Mar 14 17:51:33 ubuntu dbus-daemon[949]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service' requested by ':1.36' (uid=999 pid=1532 comm="/usr/bin/pulseaudio --start --log-target=syslog " label="unconfined")
Mar 14 17:51:58 ubuntu dbus-daemon[949]: [system] Failed to activate service 'org.bluez': timed out (service_start_timeout=25000ms)
Mar 14 17:51:58 ubuntu pulseaudio[1532]: [pulseaudio] bluez5-util.c: GetManagedObjects() failed: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.

[Ubuntu QA Website (ubuntuqa)]

This bug has been reported on the Ubuntu ISO testing tracker.

A list of all reports related to this bug can be found here:
http://iso.qa.ubuntu.com/qatracker/reports/bugs/1754836

[Kev Bowring (flocculant)]

Ubuntu Mate - 75 second timeout noted in .xsession-errors

[Sean Davis (bluesabre)]

Turned up the importance for this bug. For a user, a 75-second wait time when they are used to 0-10 would be an indication there is a serious bug and the software (Xubuntu, Ubuntu MATE, and anything else yet unidentified) does not run on their system.

[Alistair Buxton (a-j-buxton)]

On the current daily ISO this now hangs for 50 seconds instead of 75, and the blueman/bluetooth messages are completely gone from xsession-errors.

[Alistair Buxton (a-j-buxton)]

Since this only happens on first login, I ran a diff on the full home directory before/after login:

https://paste.ubuntu.com/p/SJ2nNx7WfP/

I don't see anything obvious in there. The pulse cookie and a blueman settings file (empty) were created. The rest seems to be Thunar/desktop defaults and example files.

[Alistair Buxton (a-j-buxton)]

I tried to log in over ssh and run top so I could watch which processes were running but this caused the delay to disappear.

[Kev Bowring (flocculant)]

Daily 1st April:

ERROR:dbus.proxies:Introspect error on org.bluez:/org/bluez: dbus.exceptions.DBusException: org.freedesktop.DBus.Error.TimedOut: Failed to activate service 'org.bluez': timed out (service_start_timeout=25000ms)
ERROR:dbus.proxies:Introspect error on org.bluez:/: dbus.exceptions.DBusException: org.freedesktop.DBus.Error.TimedOut: Failed to activate service 'org.bluez': timed out (service_start_timeout=25000ms)
ERROR:dbus.proxies:Introspect error on org.bluez:/: dbus.exceptions.DBusException: org.freedesktop.DBus.Error.TimedOut: Failed to activate service 'org.bluez': timed out (service_start_timeout=25000ms)

[Sean Davis (bluesabre)]

Since it seemed like this issue was coming from bluez or blueman, I did some package removal tests and was surprised by the results. These were done in order, which all packages removed in the previous step still removed in the following step.

1. Remove pulseaudio-module-bluetooth, no change.
2. Remove blueman, no change.
3. Remove bluez, bluez-cups, bluez-obexd, no change.
4. Autoremoved libbluetooth3 (brltty brltty-x11 libbluetooth3 network-manager network-manager-gnome network-manager-pptp network-manager-pptp-gnome), and still no change.

[Sean Davis (bluesabre)]

If this bug does not affect Ubuntu directly, this is a list of shared differences that Ubuntu MATE and Xubuntu have with Ubuntu. Hopefully this can help identify where the issue exists.

[TJ (tj)]

The Dbus bluze system config doesn't run, it has "Exec=/bin/false" -- /usr/share/dbus-1/system-services/org.bluez.service It's left to systemd to activate it via /lib/systemd/system/bluetooth.service

[Unit]
Description=Bluetooth service
Documentation=man:bluetoothd(8)
ConditionPathIsDirectory=/sys/class/bluetooth

[Service]
Type=dbus
BusName=org.bluez
ExecStart=/usr/lib/bluetooth/bluetoothd
NotifyAccess=main
#WatchdogSec=10
#Restart=on-failure
CapabilityBoundingSet=CAP_NET_ADMIN CAP_NET_BIND_SERVICE
LimitNPROC=1
ProtectHome=true
ProtectSystem=full

[Install]
WantedBy=bluetooth.target
Alias=dbus-org.bluez.service

I would suspect if there are no BT hci devices then bluetooth.service won't run.

So the question is, are the other flavours doing something to allow a 'dummy' BT device so bluetooth service runs and org.bluez is available or is it that their Bluetooth tooling isn't calling the DBus interface at all (using libbluetooth directly maybe) ?

[TJ (tj)]

This is a command-line that is useful for manually exercising the org.bluez DBus activiation. It might reproduce the timeout or otherwise give useful clues. Command should be all on one line (ignore Launchpad line wrapping):

dbus-send --system --print-reply --dest=org.bluez / org.freedesktop.DBus.ObjectManager.GetManagedObjects

I won't reproduce the entire output here but this is the initial part when a BT hci device is available:

method return time=1522790434.404190 sender=:1.2 -> destination=:1.399 serial=821 reply_serial=2
   array [
      dict entry(
         object path "/org/bluez"
         array [
            dict entry(
               string "org.freedesktop.DBus.Introspectable"
               array [
               ]
            )
            dict entry(
               string "org.bluez.AgentManager1"
               array [
               ]
            )
            dict entry(
               string "org.bluez.ProfileManager1"
               array [
               ]
            )
         ]
      )
      dict entry(
         object path "/org/bluez/hci0"

[Alistair Buxton (a-j-buxton)]

As far as the original bug with delayed login goes... it seems that the Bluetooth stuff is a red herring.

Since it only happens on first login, I deleted the contents of ~ and relogged. The delay came back, so I bisected the files until I arrived at the single file which needs to be deleted in order for the delay to happen. And that file is:

   ~/.cache/fontconfig/9b89f8e3dae116d678bbf48e5f21f69b-le32d4.cache-7

This cache file is associated with the Noto CJK fonts at:

    /usr/share/fonts/opentype/noto

(You can see this by running strings on it.)

Deleting this file while the user is not logged in causes the next login to take 60 seconds.

[Alistair Buxton (a-j-buxton)]

seems related: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=845058

[Alistair Buxton (a-j-buxton)]

Another piece of the puzzle: if you run:

    sudo fc-cache -fv

this will rebuild the system font cache in /var/cache/fontconfig

If you then delete the user's cache in ~/.cache/fontconfig and re-log, there is no delay... and the user's font cache will NOT be rebuilt.

After a delayed login, user's cache and the system cache appear to contain the same files.

So it looks as if something thinks the system cache is out of date and wants to rebuild it. Whatever it is only has user permissions, so rebuilds the font cache in the user's .cache

[Alistair Buxton (a-j-buxton)]

Some more: touching the system cache files doesn't make it work.

Binary diff on the cache files before and after running fc-cache shows this:

63 c7 c3 5a 00 00 00 00 47 72 ce 15 00 00 00 00
63 c7 c3 5a 00 00 00 00 00 00 00 00 00 00 00 00

Before, at offset 0x38, the "bad" cache files have a non-zero 32 bit number. The number is different in every "bad" cache file. It is always zero in the "good" files. This is the only difference. The rest of each file is identical.

I don't know what this field represents. Need a fontconfig expert to look at this.

[Alistair Buxton (a-j-buxton)]

One final thing: this does not affect Ubuntu desktop after install. But it does affect the Ubuntu live image, which takes an extra minute or so to boot. It seems that the Ubuntu desktop installer rebuilds the system font cache during install.

[Sebastien Bacher (seb128)]

the issue sounds like https://bugs.freedesktop.org/show_bug.cgi?id=103652 / https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=880574

"fontconfig now requires nano second mtime precision on files in order to
validate their freshness. squashfs does not seem to support nano second
mtime precision causing any Desktop ISO's made with live-build to regenrate
the font cache at the desktop startup leading to a very slow time to desktop."

[Jean-Baptiste Lallement (jibel)]

For reference, the lp report tracking the fontconfig issue is bug 1749546

[Daniel van Vugt (vanvugt)]

OK, let's track this in bug 1749546 unless/until the fix for that proves to not help with this one.

[Daniel van Vugt (vanvugt)]

The font cache issue is apparently fixed. Can anyone confirm (with the latest daily image) if this issue still occurs? If so, which image?

[Kev Bowring (flocculant)]

Yep - checked with image I built for us Saturday morning. Was fixed then.

[Alistair Buxton (a-j-buxton)]

The Bluez timeout errors still show up in ~/.xsession-errors at least on hardware without Bluetooth. However, it seems to be harmless.

[Kev Bowring (flocculant)]

On 09/04/18 19:09, Alistair Buxton wrote:
> *** This bug is a duplicate of bug 1749546 ***
> https://bugs.launchpad.net/bugs/1749546
>
> The Bluez timeout errors still show up in ~/.xsession-errors at least on
> hardware without Bluetooth. However, it seems to be harmless.
>
I don't see it - checked on vm and hardware.

[Daniel van Vugt (vanvugt)]

I set up Xubuntu last night just to check this but couldn't find it. I guess I forgot you need a machine _without_ Bluetooth.

However Alistair's comment #33 seems to confirm my suspicion -- that the log message is nothing to worry about and the delay everyone (including regular Ubuntu) was experiencing was in fact bug 1749546.

So we can reopen this bug if anyone wants, but it would probably become low priority/wishlist, since it's just about a log message and no behavioural problems any more.

[Daniel van Vugt (vanvugt)]

It's also worth pointing out that a timeout is probably expected and correct on machines without Bluetooth. So it's just slightly suboptimal design to go logging messages that look like errors when in fact they are expected outcomes.

[Bill Dietrich (billdietri123)]

Similar happens in Linux Mint 19 system with no Bluetooth devices.

In Settings/Bluetooth, I have no Bluetooth devices and all settings are set to "off".
In output of journalctl, I see this while booting:

pulseaudio[2770]: [pulseaudio] bluez5-util.c: GetManagedObjects() failed: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. P...
dbus-daemon[853]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service' requested by ':1.157' (uid=1000)
dbus-daemon[853]: [system] Failed to activate service 'org.bluez': timed out (service_start_timeout=25000ms)

and the last two lines are repeated occasionally as the system runs.

Boot log contains:

Linux version 4.15.0-38-generic (buildd@lcy01-amd64-023) (gcc version 7.3.0 (Ubuntu 7.3.0-16ubuntu3)) #41-Ubuntu SMP Wed Oct 10 10:59:38 UTC 2018 (Ubuntu 4.15.0-38.41-generic 4.15.18)

[Tero Gusto (tero-gusto)]

I have no use for Bluetooth, and disable it in 20.04.1 by removing these packages via Synaptic:
bluez
bluez-cups
bluez-obexd
gnome-bluetooth
pulseaudio-module-bluetooth