Users randomly getting logged out of their machines

[Andrei Hornoiu]

Hello,

I'm a sysadmin and have gotten multiple reports recently from users of them randomly getting logged out of their machines. From what I can tell from the journalctl printout this appears immediately after either bluetoothd or pulsaudio crashes.

This is happening multiple time each day for each user. It doesn't happen to all users, but the reports seem to be getting more frequent by the day. From what I have noticed there recently was an update for pulseaudio and its bluetooth integration.

Here is the journalctl printout:
Apr 25 10:50:53 ESS-PC26 bluetoothd[1168]: Endpoint registered: sender=:1.219 path=/MediaEndpoint/A2DPSource
Apr 25 10:50:53 ESS-PC26 bluetoothd[1168]: Endpoint registered: sender=:1.219 path=/MediaEndpoint/A2DPSink
Apr 25 10:50:53 ESS-PC26 pulseaudio[8026]: [pulseaudio] backend-ofono.c: Failed to register as a handsfree audio agent with ofono: org.freedesktop.DBus.Error.ServiceUnknown: The name org.ofono was not provided by any .service files
Apr 25 10:50:53 ESS-PC26 rtkit-daemon[1515]: Successfully made thread 8042 of process 8042 (n/a) owned by '108' high priority at nice level -11.
Apr 25 10:50:53 ESS-PC26 rtkit-daemon[1515]: Supervising 5 threads of 2 processes of 1 users.
Apr 25 10:50:53 ESS-PC26 pulseaudio[8042]: [pulseaudio] pid.c: Daemon already running.
Apr 25 10:51:00 ESS-PC26 org.gtk.vfs.Daemon[7931]: A connection to the bus can't be made
Apr 25 10:51:00 ESS-PC26 lightdm[7915]: pam_unix(lightdm-greeter:session): session closed for user lightdm

We are running Ubuntu 16.04 LTS with the latest updated.

EDIT: Worth mentioning, this error happens with both Unity and Gnome as desktop environments.
---
ApportVersion: 2.20.1-0ubuntu2.16
Architecture: amd64
AudioDevicesInUse: Error: command ['fuser', '-v', '/dev/snd/hwC1D0', '/dev/snd/pcmC1D9p', '/dev/snd/pcmC1D8p', '/dev/snd/hwC2D0', '/dev/snd/pcmC2D9p', '/dev/snd/pcmC1D7p', '/dev/snd/pcmC1D3p', '/dev/snd/pcmC2D8p', '/dev/snd/pcmC2D7p', '/dev/snd/controlC1', '/dev/snd/pcmC2D3p', '/dev/snd/controlC2', '/dev/snd/by-path', '/dev/snd/hwC0D0', '/dev/snd/pcmC0D2c', '/dev/snd/pcmC0D1p', '/dev/snd/pcmC0D0c', '/dev/snd/pcmC0D0p', '/dev/snd/controlC0', '/dev/snd/seq', '/dev/snd/timer'] failed with exit code 1:
DistroRelease: Ubuntu 16.04
NonfreeKernelModules: nvidia_uvm nvidia_drm nvidia_modeset nvidia
Package: pulseaudio 1:8.0-0ubuntu3.9
PackageArchitecture: amd64
ProcVersionSignature: Ubuntu 4.13.0-39.44~16.04.1-generic 4.13.16
PulseList: Error: command ['pacmd', 'list'] failed with exit code 1: No PulseAudio daemon running, or not running as session daemon.
Tags: xenial
Uname: Linux 4.13.0-39-generic x86_64
UpgradeStatus: No upgrade log present (probably fresh install)
UserGroups: adm cdrom dip lpadmin plugdev sambashare sudo
_MarkForUpload: True
dmi.bios.date: 03/07/2018
dmi.bios.vendor: American Megatrends Inc.
dmi.bios.version: 1301
dmi.board.asset.tag: Default string
dmi.board.name: PRIME X299-DELUXE
dmi.board.vendor: ASUSTeK COMPUTER INC.
dmi.board.version: Rev 1.xx
dmi.chassis.asset.tag: Default string
dmi.chassis.type: 3
dmi.chassis.vendor: Default string
dmi.chassis.version: Default string
dmi.modalias: dmi:bvnAmericanMegatrendsInc.:bvr1301:bd03/07/2018:svnSystemmanufacturer:pnSystemProductName:pvrSystemVersion:rvnASUSTeKCOMPUTERINC.:rnPRIMEX299-DELUXE:rvrRev1.xx:cvnDefaultstring:ct3:cvrDefaultstring:
dmi.product.family: To be filled by O.E.M.
dmi.product.name: System Product Name
dmi.product.version: System Version
dmi.sys.vendor: System manufacturer
---
ApportVersion: 2.20.1-0ubuntu2.16
Architecture: amd64
AudioDevicesInUse: Error: command ['fuser', '-v', '/dev/snd/hwC2D0', '/dev/snd/pcmC2D9p', '/dev/snd/pcmC2D8p', '/dev/snd/hwC1D0', '/dev/snd/pcmC1D9p', '/dev/snd/pcmC2D7p', '/dev/snd/pcmC2D3p', '/dev/snd/pcmC1D8p', '/dev/snd/pcmC1D7p', '/dev/snd/controlC2', '/dev/snd/pcmC1D3p', '/dev/snd/controlC1', '/dev/snd/by-path', '/dev/snd/hwC0D0', '/dev/snd/pcmC0D2c', '/dev/snd/pcmC0D1p', '/dev/snd/pcmC0D0c', '/dev/snd/pcmC0D0p', '/dev/snd/controlC0', '/dev/snd/seq', '/dev/snd/timer'] failed with exit code 1:
DistroRelease: Ubuntu 16.04
NonfreeKernelModules: nvidia_uvm nvidia_drm nvidia_modeset nvidia
Package: pulseaudio 1:8.0-0ubuntu3.9
PackageArchitecture: amd64
ProcVersionSignature: Ubuntu 4.13.0-39.44~16.04.1-generic 4.13.16
PulseList: Error: command ['pacmd', 'list'] failed with exit code 1: No PulseAudio daemon running, or not running as session daemon.
Tags: xenial
Uname: Linux 4.13.0-39-generic x86_64
UpgradeStatus: No upgrade log present (probably fresh install)
UserGroups: adm cdrom dip lpadmin plugdev sambashare sudo
_MarkForUpload: True
dmi.bios.date: 03/07/2018
dmi.bios.vendor: American Megatrends Inc.
dmi.bios.version: 1301
dmi.board.asset.tag: Default string
dmi.board.name: PRIME X299-DELUXE
dmi.board.vendor: ASUSTeK COMPUTER INC.
dmi.board.version: Rev 1.xx
dmi.chassis.asset.tag: Default string
dmi.chassis.type: 3
dmi.chassis.vendor: Default string
dmi.chassis.version: Default string
dmi.modalias: dmi:bvnAmericanMegatrendsInc.:bvr1301:bd03/07/2018:svnSystemmanufacturer:pnSystemProductName:pvrSystemVersion:rvnASUSTeKCOMPUTERINC.:rnPRIMEX299-DELUXE:rvrRev1.xx:cvnDefaultstring:ct3:cvrDefaultstring:
dmi.product.family: To be filled by O.E.M.
dmi.product.name: System Product Name
dmi.product.version: System Version
dmi.sys.vendor: System manufacturer

[Daniel van Vugt (vanvugt)]

If there's a crash then we will need a formal crash report. To generate one, please:

1. Apply the workaround from bug 994921.
2. Reproduce the problem.
3. Look in /var/crash for crash files and upload them by running:
   ubuntu-bug /var/crash/YOURFILE.crash
4. Let us know the ID of the new bug created.

P.S. Please don't attach crash files to existing bugs. They must be uploaded by the 'ubuntu-bug' command.

[Andrei Hornoiu (titelsin)]

Went, did step 1 and 2, looked in /var/crash and there was nothing.

There are no crash logs in that location for the event that just happened.

Attached another printout of journalctl. From what I can tell the system went in full shutdown mode and logged the user out.

[Andrei Hornoiu (titelsin)]

Update,

I noticed the pattern so far and turning off pulseaudio seems to have stopped the behaviour. I obviously can't leave the system without sound, so I'm still looking for a permanent fix.

The pattern is allways like this:
Apr 26 15:06:07 ESS-PC26 bluetoothd[11243]: Endpoint registered: sender=:1.445 path=/MediaEndpoint/A2DPSource
Apr 26 15:06:07 ESS-PC26 bluetoothd[11243]: Endpoint registered: sender=:1.445 path=/MediaEndpoint/A2DPSink
Apr 26 15:06:07 ESS-PC26 pulseaudio[12799]: [pulseaudio] backend-ofono.c: Failed to register as a handsfree audio agent with ofono: org.freedesktop.DBus.Error.ServiceUnknown: The name org.of
Apr 26 15:06:07 ESS-PC26 bluetoothd[11243]: RFCOMM server failed for Headset Voice gateway: rfcomm_bind: Address already in use (98)
Apr 26 15:06:07 ESS-PC26 rtkit-daemon[1524]: Successfully made thread 12829 of process 12829 (n/a) owned by '108' high priority at nice level -11.
Apr 26 15:06:07 ESS-PC26 rtkit-daemon[1524]: Supervising 9 threads of 3 processes of 2 users.
Apr 26 15:06:07 ESS-PC26 pulseaudio[12829]: [pulseaudio] pid.c: Daemon already running.
Apr 26 15:06:14 ESS-PC26 org.gtk.vfs.Daemon[12708]: A connection to the bus can't be made

Bluetooth tries to register a device or something, pulse fails and system loggs out. My current workaround is to completely turn off pulseaudio by creating a ~/.pulse/client.conf file with autospawn=no inside.

As I've already mentioned before, pulseaudio crashing leves no crash log. How an I get this fixed/debugged?

[Daniel van Vugt (vanvugt)]

Please also run this command to automatically attach more system information:

  apport-collect 1767065

P.S. Ubuntu 18.04 was released a few hours ago :) https://www.ubuntu.com/

[Andrei Hornoiu (titelsin)]

Another update. After truning off pulseaudio yesterday, the system didn't crash as fast as before, but it did eventually lock up a couple of times. The logs seems similar even without pulse, still beginning with the bluetooth service.

After this I completely turned off bluetooth from the BIOS of the machine. This seemed to have solved the issue until a few moments ago when the bluetoothservice tried to start something again. I have now disabled the bluetooth service. I hope it doesn't do anything more.

Here's how the system locks-up now:

Apr 27 09:37:26 ESS-PC26 dbus[1187]: [system] Failed to activate service 'org.bluez': timed out
Apr 27 09:37:26 ESS-PC26 pulseaudio[2214]: [pulseaudio] bluez5-util.c: GetManagedObjects() failed: org.freedesktop.DBus.Error.TimedOut: Failed to activate service 'org.bluez': timed out
Apr 27 09:37:26 ESS-PC26 pulseaudio[1521]: [pulseaudio] bluez5-util.c: GetManagedObjects() failed: org.freedesktop.DBus.Error.TimedOut: Failed to activate service 'org.bluez': timed out

The system freezes for multiple seconds then recovers.

I've now run apport-collect and authorized it for one week. Hope this helps.

[Andrei Hornoiu (titelsin)]

apport information

[Andrei Hornoiu (titelsin)]

apport information

[Andrei Hornoiu (titelsin)]

apport information

[Andrei Hornoiu (titelsin)]

apport information

[Andrei Hornoiu (titelsin)]

apport information

[Andrei Hornoiu (titelsin)]

apport information

[Andrei Hornoiu (titelsin)]

apport information

[Andrei Hornoiu (titelsin)]

apport information

[Daniel van Vugt (vanvugt)]

If the problem is caused by pulseaudio 1:8.0-0ubuntu3.9 then please try installing packages from the previous version:

https://launchpad.net/ubuntu/+source/pulseaudio/1:8.0-0ubuntu3.8/+build/14353783

And tell us if that resolves the issue.

[Andrei Hornoiu (titelsin)]

Now this is something really weird. I said for the hell of it to try and see if this would fix the issue. I was thinking that to save energy maybe the system tried to power down wifi/bluetooth and such during idle times.

I added intel_idle.max_cstate=1 to the kernel start options in the grub config. The main person I'm testing with hasn't reported any forced logouts since this change.

Based on this solution: https://askubuntu.com/questions/761706/ubuntu-15-10-and-16-04-keep-freezing-randomly

Is the CPU/ ACPI calls going into a lower state causing problems with the login/logout state of the machine? This might not have anything to do with pulse, but it opens an entire new can of worms.

[Daniel van Vugt (vanvugt)]

I was thinking this bug might not be related to Pulse. But if it is am happy to keep it open.

I suggest taking log message with a pinch of salt. In most cases the log messages you see actually have nothing to do with external buggy behaviours observed around the same time. That would be too easy...

[Andrei Hornoiu (titelsin)]

Spoke too soon, it happened again. Seems to be from pulse and bluetooth. Why is systemd still trying to start bluetooth when it is off in the bios and the service is disabled. I really don't understand what I can try more to debug.

Apr 30 11:31:09 ESS-PC26 org.gtk.vfs.AfcVolumeMonitor[8928]: Volume monitor alive
Apr 30 11:31:10 ESS-PC26 org.gnome.ScreenSaver[8928]: ** Message: Lost the name, shutting down.
Apr 30 11:31:16 ESS-PC26 rtkit-daemon[1501]: Supervising 7 threads of 2 processes of 2 users.
Apr 30 11:31:16 ESS-PC26 rtkit-daemon[1501]: Successfully made thread 9456 of process 9266 (n/a) owned by '1001' RT at priority 5.
Apr 30 11:31:16 ESS-PC26 rtkit-daemon[1501]: Supervising 8 threads of 2 processes of 2 users.
Apr 30 11:31:16 ESS-PC26 rtkit-daemon[1501]: Successfully made thread 9458 of process 9458 (n/a) owned by '1001' high priority at nice level -11.
Apr 30 11:31:16 ESS-PC26 rtkit-daemon[1501]: Supervising 9 threads of 3 processes of 2 users.
Apr 30 11:31:16 ESS-PC26 pulseaudio[9458]: [pulseaudio] pid.c: Daemon already running.
Apr 30 11:31:16 ESS-PC26 rtkit-daemon[1501]: Successfully made thread 9460 of process 9460 (n/a) owned by '1001' high priority at nice level -11.
Apr 30 11:31:16 ESS-PC26 rtkit-daemon[1501]: Supervising 9 threads of 3 processes of 2 users.
Apr 30 11:31:16 ESS-PC26 pulseaudio[9460]: [pulseaudio] pid.c: Daemon already running.
Apr 30 11:31:16 ESS-PC26 dbus[1148]: [system] Activating via systemd: service name='org.freedesktop.locale1' unit='dbus-org.freedesktop.locale1.service'
Apr 30 11:31:16 ESS-PC26 gnome-session[9150]: (uint32 1,)
Apr 30 11:31:16 ESS-PC26 systemd[1]: Starting Locale Service...
Apr 30 11:31:16 ESS-PC26 gnome-session-binary[9150]: Entering running state
Apr 30 11:31:16 ESS-PC26 gnome-session[9150]: (process:9493): indicator-application-service-WARNING **: Unable to get watcher name 'org.kde.StatusNotifierWatcher'
Apr 30 11:31:16 ESS-PC26 gnome-session[9150]: (process:9493): indicator-application-service-WARNING **: Name Lost
Apr 30 11:31:16 ESS-PC26 polkitd(authority=local)[1278]: Registered Authentication Agent for unix-session:c4 (system bus name :1.181 [/usr/lib/policykit-1-gnome/polkit-gnome-authentication-a
Apr 30 11:31:16 ESS-PC26 dbus[1148]: [system] Successfully activated service 'org.freedesktop.locale1'
Apr 30 11:31:16 ESS-PC26 systemd[1]: Started Locale Service.
Apr 30 11:31:22 ESS-PC26 dbus[1148]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service'
Apr 30 11:31:22 ESS-PC26 dbus[1148]: [system] Activation via systemd failed for unit 'dbus-org.bluez.service': Unit dbus-org.bluez.service not found.

[Daniel van Vugt (vanvugt)]

Pulseaudio or bluetoothd crashing would not log you out. At most only audio would stop working, but usually it will automatically restart and you not notice anything at all.

Pulseaudio or bluetoothd crashing would leave files in /var/crash. So that's further evidence that they are not crashing in this case. So I think you may be looking in the wrong place. I certainly don't see any evidence of pulseaudio or bluetooth crashing in the above log. The session always trying to enable bluetooth and failing when it can't is not an error, it's just an informational log message.

Try looking for other parts of the system failing, which would better explain all the symptoms you see.

[Daniel van Vugt (vanvugt)]

Can you please reproduce the problem again, and then immediately after send us copies of the machine's files:

  /var/log/Xorg*.log

?

[Hui Wang (hui.wang)]

In the alsa-info.txt, I found some unusual info, I have no idea why those commands failed, I never met this situation before. Why alsa commands can't work on this machine?

!!Aplay/Arecord output
!!------------

APLAY

aplay: device_list:268: no soundcards found...

ARECORD

arecord: device_list:268: no soundcards found...

!!Amixer output
!!-------------

!!-------Mixer controls for card 0 [PCH]

Invalid card number.
Usage: amixer <options> [command]

Available options:
  -h,--help this help
  -c,--card N select the card
  -D,--device N select the device, default 'default'
  -d,--debug debug mode
  -n,--nocheck do not perform range checking
  -v,--version print version of this program
  -q,--quiet be quiet
  -i,--inactive show also inactive controls
  -a,--abstract L select abstraction level (none or basic)
  -s,--stdin Read and execute commands from stdin sequentially
  -R,--raw-volume Use the raw value (default)
  -M,--mapped-volume Use the mapped volume

Available commands:
  scontrols show all mixer simple controls
  scontents show contents of all mixer simple controls (default command)
  sset sID P set contents for one mixer simple control
  sget sID get contents for one mixer simple control
  controls show all controls for given card
  contents show contents of all controls for given card
  cset cID P set control contents for one control
  cget cID get control contents for one control
Invalid card number.
Usage: amixer <options> [command]

Available options:
  -h,--help this help
  -c,--card N select the card
  -D,--device N select the device, default 'default'
  -d,--debug debug mode
  -n,--nocheck do not perform range checking
  -v,--version print version of this program
  -q,--quiet be quiet
  -i,--inactive show also inactive controls
  -a,--abstract L select abstraction level (none or basic)
  -s,--stdin Read and execute commands from stdin sequentially
  -R,--raw-volume Use the raw value (default)
  -M,--mapped-volume Use the mapped volume

Available commands:
  scontrols show all mixer simple controls
  scontents show contents of all mixer simple controls (default command)
  sset sID P set contents for one mixer simple control
  sget sID get contents for one mixer simple control
  controls show all controls for given card
  contents show contents of all controls for given card
  cset cID P set control contents for one control
  cget cID get control contents for one control

!!-------Mixer controls for card 1 [NVidia_1]

Invalid card number.
Usage: amixer <options> [command]

Available options:
  -h,--help this help
  -c,--card N select the card
  -D,--device N select the device, default 'default'
  -d,--debug debug mode
  -n,--nocheck do not perform range checking
  -v,--version print version of this program
  -q,--quiet be quiet
  -i,--inactive show also inactive controls
  -a,--abstract L select abstraction level (none or basic)
  -s,--stdin Read and execute commands from stdin sequentially
  -R,--raw-volume Use the raw value (defau...

[Launchpad Janitor (janitor)]

[Expired for pulseaudio (Ubuntu) because there has been no activity for 60 days.]