dbus and swapping systemd targets.

Wed May 17 01:42:59 UTC 2017

On 05/17/2017 12:21 AM, Simon McVittie wrote:
> On Fri, 12 May 2017 at 12:31:08 +0930, Simon Lees wrote:
>> test at linux-gruo:~> journalctl
>> Hint: You are currently not seeing messages from other users and the system.
>>       Users in the 'systemd-journal' group can see all messages. Pass -q to
>>       turn off this notice.
> 
> Please use a privileged user to read the log when you are debugging
> system-level problems. Doing debugging as a uid that is not sufficiently
> privileged to have access to all the facts is a waste of time.
> 

My apologies that should have been obvious... here is a complete log
from the point the first tty becomes active, I can go back further if
needed. (Hostname and date have been slightly trimmed).

1. ssh in and run dbus-monitor
2. systemctl isolate graphical.target
3. attempt graphical login and run dbus monitor from ssh session again.

11:03:30 l-g systemd[1]: Started Getty on tty1.
11:03:30 l-g systemd[1]: Reached target Login Prompts.
11:03:30 l-g systemd[1]: Started /etc/init.d/after.local Compatibility.
11:03:30 l-g systemd[1]: Started Terminate Plymouth Boot Screen.
11:03:30 l-g systemd[1]: Started Login and scanning of iSCSI devices.
11:03:30 l-g ntpd[1314]: ntpd 4.2.8p9 at 1.3265-o Wed Mar 22 03:02:47 UTC
2017 (1): Starting
11:03:30 l-g ntpd[1314]: Command line: /usr/sbin/ntpd -p
/var/run/ntp/ntpd.pid -g -u ntp:ntp -c /etc/ntp.conf
11:03:30 l-g systemd[1]: Started OpenSSH Daemon.
11:03:30 l-g ntpd[1315]: proto: precision = 0.084 usec (-23)
11:03:31 l-g start-ntpd[1295]: Starting network time protocol daemon
(NTPD)sntp 4.2.8p9 at 1.3265-o Wed Mar 22 03:02
11:03:30 l-g ntpd[1315]: switching logging to file /var/log/ntp
11:03:31 l-g sntp[1320]: sntp 4.2.8p9 at 1.3265-o Wed Mar 22 03:02:40 UTC
2017 (1)
11:03:31 l-g sntp[1320]: 2017-05-17 11:03:31.081529 (+0930) +2.082076
+/- 1.532673 172.16.0.255 s3 no-leap
11:03:33 l-g start-ntpd[1295]: 2017-05-17 11:03:31.081529 (+0930)
+2.082076 +/- 1.532673 172.16.0.255 s3 no-leap
11:03:33 l-g systemd[1]: Time has been changed
11:03:33 l-g sshd[1316]: Server listening on 0.0.0.0 port 22.
11:03:33 l-g sshd[1316]: Server listening on :: port 22.
11:03:33 l-g /usr/sbin/start-ntpd[1325]: runtime configuration: server
172.16.0.255
11:03:33 l-g systemd[1]: Started NTP Server Daemon.
11:03:33 l-g systemd[1]: Reached target System Time Synchronized.
11:03:33 l-g systemd[1]: Starting Postfix Mail Transport Agent...
11:03:33 l-g systemd[1]: Started Daily rotation of log files.
11:03:33 l-g systemd[1]: Started Discard unused blocks once a week.
11:03:33 l-g systemd[1]: Reached target Timers.
11:03:33 l-g systemd[1]: Starting Rotate log files...
11:03:33 l-g echo[1326]: Starting mail service (Postfix)
11:03:33 l-g systemd[1]: Started Rotate log files.
11:03:34 l-g postfix/postfix-script[1394]: warning: group or other
writable: /etc/postfix/./ssl/cacerts
11:03:34 l-g postfix/postfix-script[1406]: starting the Postfix mail system
11:03:34 l-g postfix/master[1408]: daemon started -- version 3.2.0,
configuration /etc/postfix
11:03:34 l-g systemd[1]: Started Postfix Mail Transport Agent.
11:03:34 l-g systemd[1]: Started Command Scheduler.
11:03:34 l-g systemd[1]: Reached target Multi-User System.
11:03:34 l-g systemd[1]: Starting Update UTMP about System Runlevel
Changes...
11:03:34 l-g systemd[1]: Started Update UTMP about System Runlevel Changes.
11:03:34 l-g cron[1421]: (CRON) INFO (RANDOM_DELAY will be scaled with
factor 70% if used.)
11:03:34 l-g systemd[1]: Startup finished in 1.337s (kernel) + 4.531s
(initrd) + 27.037s (userspace) = 32.905s.
11:03:34 l-g cron[1421]: (CRON) INFO (running with inotify support)
11:03:42 l-g sshd[1426]: Accepted keyboard-interactive/pam for test from
172.16.0.101 port 55848 ssh2
11:03:42 l-g sshd[1426]: pam_unix(sshd:session): session opened for user
test by (uid=0)
11:03:42 l-g systemd-logind[897]: New session 1 of user test.
11:03:42 l-g systemd[1]: Created slice User Slice of test.
11:03:42 l-g systemd[1]: Starting User Manager for UID 1001...
11:03:42 l-g systemd[1]: Started Session 1 of user test.
11:03:42 l-g systemd[1429]: pam_unix(systemd-user:session): session
opened for user test by (uid=0)
11:03:42 l-g systemd[1429]: Reached target Timers.
11:03:42 l-g systemd[1429]: Starting D-Bus User Message Bus Socket.
11:03:42 l-g systemd[1429]: Reached target Paths.
11:03:42 l-g systemd[1429]: Listening on D-Bus User Message Bus Socket.
11:03:42 l-g systemd[1429]: Reached target Sockets.
11:03:42 l-g systemd[1429]: Reached target Basic System.
11:03:42 l-g systemd[1429]: Reached target Default.
11:03:42 l-g systemd[1429]: Startup finished in 48ms.
11:03:42 l-g systemd[1]: Started User Manager for UID 1001.
11:03:47 l-g systemd[1429]: Started D-Bus User Message Bus.
11:03:47 l-g dbus-daemon[1478]: Connection :1.1 (uid=1001 pid=1477
comm="dbus-monitor ") became a monitor.
11:03:50 l-g dbus-daemon[1478]: Monitoring connection :1.1 closed.
11:04:15 l-g login[1304]: pam_unix(login:auth): authentication failure;
logname=LOGIN uid=0 euid=0 tty=tty1 ruser
11:04:18 l-g login[1304]: FAILED LOGIN 1 FROM tty1 FOR root,
Authentication failure
11:04:21 l-g login[1304]: pam_unix(login:session): session opened for
user test by LOGIN(uid=0)
11:04:21 l-g systemd-logind[897]: New session 2 of user test.
11:04:21 l-g systemd[1]: Started Session 2 of user test.
11:04:21 l-g login[1304]: LOGIN ON tty1 BY test
11:04:53 l-g su[1517]: (to root) test on tty1
11:04:53 l-g su[1517]: pam_unix(su-l:session): session opened for user
root by test(uid=1001)
11:04:53 l-g su[1517]: pam_systemd(su-l:session): Cannot create session:
Already running in a session
11:04:59 l-g systemd[1]: Starting Generate issue file for login session...
11:04:59 l-g systemd[1]: Starting Setup Virtual Console...
11:04:59 l-g systemd[1429]: Stopping D-Bus User Message Bus...
11:04:59 l-g systemd[1429]: Stopped target Default.
11:04:59 l-g systemd[1429]: Stopped D-Bus User Message Bus.
11:04:59 l-g systemd[1429]: Stopped target Basic System.
11:04:59 l-g systemd[1429]: Stopped target Paths.
11:04:59 l-g systemd[1429]: Stopped target Timers.
11:04:59 l-g systemd[1429]: Stopped target Sockets.
11:04:59 l-g systemd[1429]: Closed D-Bus User Message Bus Socket.
11:04:59 l-g systemd[1429]: Reached target Shutdown.
11:04:59 l-g systemd[1]: Stopping User Manager for UID 1001...
11:04:59 l-g systemd[1]: Starting Tell Plymouth To Write Out Runtime Data...
11:04:59 l-g systemd[1429]: Starting Exit the Session...
11:04:59 l-g systemd[1]: Started irqbalance daemon.
11:04:59 l-g /usr/sbin/irqbalance[1567]: Balancing is ineffective on
systems with a single cpu.  Shutting down
11:04:59 l-g systemd[1]: Stopped target Sound Card.
11:04:59 l-g systemd[1429]: Received SIGRTMIN+24 from PID 1566 (kill).
11:04:59 l-g systemd[1430]: pam_unix(systemd-user:session): session
closed for user test
11:04:59 l-g systemd[1]: Stopped User Manager for UID 1001.
11:04:59 l-g systemd[1]: Started Tell Plymouth To Write Out Runtime Data.
11:04:59 l-g systemd[1]: Started Generate issue file for login session.
11:04:59 l-g systemd[1]: Started Setup Virtual Console.
11:04:59 l-g systemd[1]: Starting Show Plymouth Boot Screen...
11:04:59 l-g systemd[1]: Started Show Plymouth Boot Screen.
11:04:59 l-g systemd[1]: Starting X Display Manager...
11:04:59 l-g systemd[1]: Received SIGRTMIN+21 from PID 1587 (plymouthd).
11:05:00 l-g root[1603]: /etc/init.d/xdm: No changes for
/etc/X11/xdm/Xservers
11:05:00 l-g root[1603]: /etc/init.d/xdm: No changes for
/etc/X11/xdm/xdm-config
11:05:00 l-g dbus[857]: [system] Activating via systemd: service
name='org.freedesktop.Accounts' unit='accounts-d
11:05:00 l-g systemd[1]: Starting Accounts Service...
11:05:00 l-g dbus[857]: [system] Activating via systemd: service
name='org.freedesktop.PolicyKit1' unit='polkit.s
11:05:00 l-g systemd[1]: Starting Authorization Manager...
11:05:00 l-g polkitd[1649]: Started polkitd version 0.113
11:05:00 l-g polkitd[1649]: Loading rules from directory
/etc/polkit-1/rules.d
11:05:00 l-g polkitd[1649]: Loading rules from directory
/usr/share/polkit-1/rules.d
11:05:00 l-g display-manager[1591]: Starting service lightdm..done
11:05:00 l-g systemd[1]: Started X Display Manager.
11:05:00 l-g systemd[1]: Reached target Graphical Interface.
11:05:00 l-g systemd[1]: Starting Update UTMP about System Runlevel
Changes...
11:05:00 l-g systemd[1]: Started Update UTMP about System Runlevel Changes.
11:05:00 l-g polkitd[1649]: Finished loading, compiling and executing 4
rules
11:05:00 l-g dbus[857]: [system] Successfully activated service
'org.freedesktop.PolicyKit1'
11:05:00 l-g systemd[1]: Started Authorization Manager.
11:05:00 l-g polkitd[1649]: Acquired the name org.freedesktop.PolicyKit1
on the system bus
11:05:00 l-g accounts-daemon[1645]: started daemon version 0.6.43
11:05:00 l-g dbus[857]: [system] Successfully activated service
'org.freedesktop.Accounts'
11:05:00 l-g systemd[1]: Started Accounts Service.
11:05:02 l-g lightdm[1639]: g_object_unref: assertion 'G_IS_OBJECT
(object)' failed
11:05:03 l-g lightdm[1665]: pam_unix(lightdm-greeter:session): session
opened for user lightdm by (uid=0)
11:05:03 l-g systemd-logind[897]: New session 3 of user lightdm.
11:05:03 l-g systemd[1]: Created slice User Slice of lightdm.
11:05:03 l-g systemd[1]: Starting User Manager for UID 485...
11:05:03 l-g systemd[1]: Started Session 3 of user lightdm.
11:05:03 l-g systemd[1675]: pam_unix(systemd-user:session): session
opened for user lightdm by (uid=0)
11:05:03 l-g systemd[1675]: Reached target Paths.
11:05:03 l-g systemd[1675]: Reached target Timers.
11:05:03 l-g systemd[1675]: Starting D-Bus User Message Bus Socket.
11:05:03 l-g systemd[1675]: Listening on D-Bus User Message Bus Socket.
11:05:03 l-g systemd[1675]: Reached target Sockets.
11:05:03 l-g systemd[1675]: Reached target Basic System.
11:05:03 l-g systemd[1675]: Reached target Default.
11:05:03 l-g systemd[1675]: Startup finished in 56ms.
11:05:03 l-g systemd[1]: Started User Manager for UID 485.
11:05:05 l-g systemd[1675]: Started D-Bus User Message Bus.
11:05:05 l-g dbus-daemon[1682]: Activating via systemd: service
name='org.gtk.vfs.Daemon' unit='gvfs-daemon.servi
11:05:05 l-g systemd[1675]: Starting Virtual filesystem service...
11:05:05 l-g dbus-daemon[1682]: Successfully activated service
'org.gtk.vfs.Daemon'
11:05:05 l-g systemd[1675]: Started Virtual filesystem service.
11:05:05 l-g kernel: fuse init (API version 7.26)
11:05:05 l-g systemd[1]: Mounting FUSE Control File System...
11:05:05 l-g systemd[1]: Mounted FUSE Control File System.
11:05:18 l-g systemd[1]: session-3.scope: Killing process 1665 (lightdm)
with signal SIGTERM.
11:05:18 l-g systemd[1]: session-3.scope: Killing process 1680
(lightdm-gtk-gre) with signal SIGTERM.
11:05:18 l-g systemd[1]: Stopping Session 3 of user lightdm.
11:05:18 l-g lightdm[1665]: pam_unix(lightdm-greeter:session): session
closed for user lightdm
11:05:18 l-g systemd[1]: Stopped Session 3 of user lightdm.
11:05:18 l-g systemd-logind[897]: Removed session 3.
11:05:18 l-g systemd[1675]: Stopped target Default.
11:05:18 l-g systemd[1675]: Stopping Virtual filesystem service...
11:05:18 l-g systemd[1675]: Stopping D-Bus User Message Bus...
11:05:18 l-g systemd[1675]: Stopped D-Bus User Message Bus.
11:05:18 l-g systemd[1]: Stopping User Manager for UID 485...
11:05:18 l-g systemd[1675]: Stopped Virtual filesystem service.
11:05:18 l-g systemd[1675]: Stopped target Basic System.
11:05:18 l-g systemd[1675]: Stopped target Paths.
11:05:18 l-g systemd[1675]: Stopped target Sockets.
11:05:18 l-g systemd[1675]: Closed D-Bus User Message Bus Socket.
11:05:18 l-g systemd[1675]: Reached target Shutdown.
11:05:18 l-g systemd[1675]: Starting Exit the Session...
11:05:18 l-g systemd[1675]: Stopped target Timers.
11:05:18 l-g systemd[1675]: Received SIGRTMIN+24 from PID 1724 (kill).
11:05:18 l-g systemd[1676]: pam_unix(systemd-user:session): session
closed for user lightdm
11:05:18 l-g systemd[1]: Stopped User Manager for UID 485.
11:05:18 l-g systemd[1]: Removed slice User Slice of lightdm.
11:05:18 l-g lightdm[1639]: g_object_unref: assertion 'G_IS_OBJECT
(object)' failed
11:05:18 l-g lightdm[1707]: pam_unix(lightdm:session): session opened
for user test by (uid=0)
11:05:18 l-g systemd[1]: Started Session 4 of user test.
11:05:18 l-g systemd-logind[897]: New session 4 of user test.
11:05:20 l-g lightdm[1707]: pam_unix(lightdm:session): session closed
for user test
11:05:21 l-g lightdm[1639]: g_object_unref: assertion 'G_IS_OBJECT
(object)' failed
11:05:21 l-g lightdm[1836]: pam_unix(lightdm-greeter:session): session
opened for user lightdm by (uid=0)
11:05:21 l-g systemd-logind[897]: New session 5 of user lightdm.
11:05:21 l-g systemd[1]: Created slice User Slice of lightdm.
11:05:21 l-g systemd[1]: Starting User Manager for UID 485...
11:05:21 l-g systemd[1]: Started Session 5 of user lightdm.
11:05:21 l-g systemd[1846]: pam_unix(systemd-user:session): session
opened for user lightdm by (uid=0)
11:05:21 l-g systemd[1846]: Reached target Timers.
11:05:21 l-g systemd[1846]: Starting D-Bus User Message Bus Socket.
11:05:21 l-g systemd[1846]: Reached target Paths.
11:05:21 l-g systemd[1846]: Listening on D-Bus User Message Bus Socket.
11:05:21 l-g systemd[1846]: Reached target Sockets.
11:05:21 l-g systemd[1846]: Reached target Basic System.
11:05:21 l-g systemd[1846]: Reached target Default.
11:05:21 l-g systemd[1846]: Startup finished in 25ms.
11:05:21 l-g systemd[1]: Started User Manager for UID 485.
11:05:21 l-g systemd[1846]: Started D-Bus User Message Bus.
11:05:21 l-g dbus-daemon[1853]: Activating via systemd: service
name='org.gtk.vfs.Daemon' unit='gvfs-daemon.servi
11:05:21 l-g systemd[1846]: Starting Virtual filesystem service...
11:05:21 l-g dbus-daemon[1853]: Successfully activated service
'org.gtk.vfs.Daemon'
11:05:21 l-g systemd[1846]: Started Virtual filesystem service.
11:05:29 l-g sudo[1875]:     test : TTY=pts/0 ; PWD=/home/test ;
USER=root ; COMMAND=/usr/bin/journalctl
11:05:29 l-g sudo[1875]: pam_unix(sudo:session): session opened for user
root by test(uid=0)
11:05:29 l-g sudo[1875]: pam_systemd(sudo:session): Cannot create
session: Already running in a session

-- 

Simon Lees (Simotek)                            http://simotek.net

Emergency Update Team                           keybase.io/simotek
SUSE Linux                           Adelaide Australia, UTC+10:30
GPG Fingerprint: 5B87 DB9D 88DC F606 E489 CEC5 0922 C246 02F0 014B

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 488 bytes
Desc: OpenPGP digital signature
URL: <https://lists.freedesktop.org/archives/dbus/attachments/20170517/597275e0/attachment-0001.sig>