Upstream bug has attachment.

Proposed as a Blocker for 31-final by Fedora user chrismurphy using the blocker tracking app because:

 "All elements of the default panel (or equivalent) configuration in all release-blocking desktops must function correctly in typical use. "

Created attachment 1610647 [details]
journal

Note this journal is a full continuation of the one I attached upstream. So I set gdm debugging, isolated multi-user.target, then graphical.target. 

[ 7903.182052]  gdm is now up with debugging enabled, I see the graphical login.

I login and press some backlight keys, [ 7950.056942], and then log out ~ [ 7958.857656]  and I never get to graphical gdm again, just a black screen with a bunch of @@@@'s which eventually give way to a black screen (backlight stays on)

The section starting with this looks interesting
[ 7948.796479] fmac.local gdm[6861]: GdmCommon: process (pid:6929) done (status:0)

I do still have a running gdm process PID 6861.

[ 7966.416603] fmac.local gdm-password][7308]: GdmSessionWorker: jumping to VT 1


At this point I've discovered possible dup bug 1745554.

Created attachment 1610662 [details]
journalctl -b -o short-monotonic

Clean boot. Login. Logout - fail. gdm debugging is enabled.

Created attachment 1610663 [details]
journalctl -b -o short-monotonic, with log_level debug

OK, it doesn't always happens. Yet another new boot, this time with systemd.log_level=debug set.

login, logout - this works, I see graphical gdm
login, logout - this fails, no gdm, I see text on screen 
[ 109.   ]
[  117.577471] fmac.local systemd[1]: systemd-journald.service: Got notification message from PID 592 (WATCHDOG=1)

And also I see in the journal an entry for the last time I pressed a brightness key, [   99.245937], right before logging out. So it's those ten seconds between [   99.245937] and 109 that contain whatever is going wrong.

(In reply to Fedora Blocker Bugs Application from comment #2)
> Proposed as a Blocker for 31-final by Fedora user chrismurphy using the
> blocker tracking app because:
> 
>  "All elements of the default panel (or equivalent) configuration in all
> release-blocking desktops must function correctly in typical use. "

+1 blocker

Clever choice of blocker criterion. We've previously rejected having a blocker criterion for logout or switch users functionality, but I've never agreed with such pessimism that we can't expect basic desktop features to work properly. We surely can. And the functionality is indeed exposed via the default panel, so it should be covered.

Created attachment 1611014 [details]
journal4

I'm going to focus this bug on the failure at gdm during blanking, rather than the logout. Monotonic times based on this attached journal.


screen goes blank (expected)

[  315.801361] fmac.local gnome-session-binary[1086]: gnome-session-binary[1086]: DEBUG(+): GsmPresence: setting idle: 1



Tap trackpad button and keys to wake it up - I see a text screen, I never see gdm

[  473.223349] fmac.local gnome-session-binary[1086]: gnome-session-binary[1086]: DEBUG(+): GsmPresence: setting idle: 0


What is this?
[  474.502461] fmac.local kernel: gnome-shell[1102]: segfault at 58 ip 00007f7daff6aa5a sp 00007ffca978ebb0 error 4 in libmutter-5.so.0.0.0[7f7dafe7b000+fa000]


[chris@fmac ~]$ sudo coredumpctl
No coredumps found.
[chris@fmac ~]$ sudo abrt-cli list
No problems

The auto-reporting feature is disabled. Please consider enabling it by issuing “abrt-auto-reporting enabled” as a user with root privileges.
[chris@fmac ~]$ 

Why no coredump collected?

[chris@fmac ~]$ systemctl list-unit-files | grep core
abrt-journal-core.service                    enabled        
abrt-vmcore.service                          enabled        
systemd-coredump@.service                    static         
systemd-coredump.socket                      static         
[chris@fmac ~]$ systemctl list-unit-files | grep abrt
abrt-ccpp.service                            disabled       
abrt-journal-core.service                    enabled        
abrt-oops.service                            enabled        
abrt-pstoreoops.service                      disabled       
abrt-vmcore.service                          enabled        
abrt-xorg.service                            enabled        
abrtd.service                                enabled        
[chris@fmac ~]$

Arguably I've narrowed this incorrectly, the failure to come back to GDM is a bad bug to ship in a beta; where the failure to logout is a bad bug to ship in final. I'm gonna stop talking and let adamw sort out the mess :P

(In reply to Chris Murphy from comment #7) 
> Why no coredump collected?

Yeah, WTF. :( The gnome-shell crash is definitely the problem here and the gnome-shell developers can't debug it without a core dump. (The login screen that you see has been gnome-shell for nearly a decade now, not the gdm process.)

Darn, and gnome-shell doesn't always segfault. So far it always fails to cover from blanking when I touch trackpad or key, but there are two failures: segfault or this:


[  474.401408] fmac.local gnome-session-binary[1084]: gnome-session-binary[1084]: DEBUG(+): GsmPresence: setting idle: 0
[  474.401408] fmac.local gnome-session-binary[1084]: gnome-session-binary[1084]: DEBUG(+): Updating systemd idle status: 0
[  474.406159] fmac.local gnome-session-binary[1084]: DEBUG(+): GsmPresence: setting idle: 0
[  474.406421] fmac.local systemd[1]: systemd-journald.service: Got notification message from PID 593 (WATCHDOG=1)
[  474.407597] fmac.local gnome-session-binary[1084]: gnome-session-binary[1084]: DEBUG(+): GsmPresence: setting non-idle status 0
[  474.407718] fmac.local gnome-session-binary[1084]: DEBUG(+): Updating systemd idle status: 0
[  474.407909] fmac.local systemd-logind[974]: Got message type=method_call sender=:1.36 destination=org.freedesktop.login1 path=/org/freedesktop/login1/session/c1 interface=org.freedesktop.login1.Session member=SetIdleHint cookie=26 reply_cookie=0 signature=b error-name=n/a error-message=n/a
[  474.408982] fmac.local gnome-session-binary[1084]: DEBUG(+): GsmPresence: setting non-idle status 0
[  474.409168] fmac.local systemd-logind[974]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=GetConnectionUnixUser cookie=158 reply_cookie=0 signature=s error-name=n/a error-message=n/a
[  474.409510] fmac.local systemd-logind[974]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.26 path=n/a interface=n/a member=n/a cookie=4294967295 reply_cookie=158 signature=u error-name=n/a error-message=n/a
[  474.409870] fmac.local systemd-logind[974]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/login1/session/c1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=159 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
[  474.410149] fmac.local systemd-logind[974]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/login1/seat/seat0 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=160 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
[  474.410393] fmac.local systemd-logind[974]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/login1/user/_42 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=161 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
[  474.410628] fmac.local systemd-logind[974]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/login1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=162 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
[  474.414594] fmac.local gnome-shell[1101]: (../src/backends/native/meta-renderer-native.c:2211):meta_onscreen_native_swap_buffers_with_damage: runtime check failed: (onscreen_native->gbm.next_fb == NULL)
[  474.421171] fmac.local pkexec[1527]: gdm: The value for the SHELL variable was not found the /etc/shells file [USER=root] [TTY=unknown] [CWD=/var/lib/gdm] [COMMAND=/usr/libexec/gsd-backlight-helper /sys/devices/pnp0/00:03/backlight/gmux_backlight 54605]
[  474.422599] fmac.local gsd-power[1182]: The value for the SHELL variable was not found the /etc/shells file
[  474.422599] fmac.local gsd-power[1182]: This incident has been reported.
[  474.423549] fmac.local gsd-power[1182]: Error executing backlight helper: Child process stopped by signal 0
[  474.471264] fmac.local gnome-shell[1101]: (../src/backends/native/meta-renderer-native.c:2211):meta_onscreen_native_swap_buffers_with_damage: runtime check failed: (onscreen_native->gbm.next_fb == NULL)
[  475.235402] fmac.local pkexec[1528]: gdm: The value for the SHELL variable was not found the /etc/shells file [USER=root] [TTY=unknown] [CWD=/var/lib/gdm] [COMMAND=/usr/libexec/gsd-backlight-helper /sys/devices/pnp0/00:03/backlight/gmux_backlight 48900]
[  475.236254] fmac.local gsd-power[1182]: The value for the SHELL variable was not found the /etc/shells file
[  475.236254] fmac.local gsd-power[1182]: This incident has been reported.
[  475.237166] fmac.local gsd-power[1182]: Error executing backlight helper: Child process stopped by signal 0


In the case of segfault, I see text on the screen instead of graphical login. In the case of no crash (above), I see a frozen mouse pointer but an otherwise black screen. I'd like to reproduce a crash while systemd.log_level=debug so I can file a bug against systemd for not capturing the coredump, but I'm not certain of the coredump mechanism either.

"process segfaults but systemd-coredump does not capture it" - bug 1748145

This happens while logged in too, not just as the login screen. While logged in, if I change Settings>Power>Blank screen, to 1 minute, let it blank the screen, then tap a key or touch the touchpad, the graphical session does not resume. I see a black screen with a frozen mouse pointer. This is all that's recorded.

(screen blanks)

Sep 03 12:18:50 fmac.local gnome-session-binary[1581]: gnome-session-binary[1581]: DEBUG(+): GsmManager: CanShutdown called
Sep 03 12:18:50 fmac.local gnome-session-binary[1581]: DEBUG(+): GsmManager: CanShutdown called
Sep 03 12:18:56 fmac.local systemd[1]: Starting Hostname Service...
Sep 03 12:18:56 fmac.local audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Sep 03 12:18:56 fmac.local systemd[1]: Started Hostname Service.
Sep 03 12:19:01 fmac.local gnome-session-binary[1581]: gnome-session-binary[1581]: DEBUG(+): GsmPresence: adding idle watch (1) for 60 secs
Sep 03 12:19:01 fmac.local gnome-session-binary[1581]: DEBUG(+): GsmPresence: adding idle watch (1) for 60 secs
Sep 03 12:19:36 fmac.local systemd[1]: systemd-hostnamed.service: Succeeded.
Sep 03 12:19:36 fmac.local audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Sep 03 12:20:08 fmac.local gnome-session-binary[1581]: gnome-session-binary[1581]: DEBUG(+): GsmPresence: setting idle: 1
Sep 03 12:20:08 fmac.local gnome-session-binary[1581]: DEBUG(+): GsmPresence: setting idle: 1
Sep 03 12:20:08 fmac.local gnome-session-binary[1581]: gnome-session-binary[1581]: DEBUG(+): Updating systemd idle status: 1
Sep 03 12:20:08 fmac.local gnome-session-binary[1581]: DEBUG(+): Updating systemd idle status: 1
Sep 03 12:20:08 fmac.local gnome-session-binary[1581]: gnome-session-binary[1581]: DEBUG(+): GsmPresence: setting idle: 1
Sep 03 12:20:08 fmac.local gnome-session-binary[1581]: gnome-session-binary[1581]: DEBUG(+): GsmPresence: already idle, ignoring
Sep 03 12:20:08 fmac.local gnome-session-binary[1581]: DEBUG(+): GsmPresence: setting idle: 1
Sep 03 12:20:08 fmac.local gnome-session-binary[1581]: DEBUG(+): GsmPresence: already idle, ignoring
Sep 03 12:20:08 fmac.local gnome-shell[1595]: (../src/backends/native/meta-renderer-native.c:2211):meta_onscreen_native_swap_buffers_with_damage: runtime check failed: (onscreen_native->gbm.next_fb == NULL)



(touch trackpad and keyboard keys)

Sep 03 12:20:34 fmac.local gnome-session-binary[1581]: gnome-session-binary[1581]: DEBUG(+): GsmPresence: setting idle: 0
Sep 03 12:20:34 fmac.local gnome-session-binary[1581]: gnome-session-binary[1581]: DEBUG(+): Updating systemd idle status: 0
Sep 03 12:20:34 fmac.local gnome-session-binary[1581]: gnome-session-binary[1581]: DEBUG(+): GsmPresence: setting non-idle status 0
Sep 03 12:20:34 fmac.local gnome-session-binary[1581]: DEBUG(+): GsmPresence: setting idle: 0
Sep 03 12:20:34 fmac.local gnome-session-binary[1581]: DEBUG(+): Updating systemd idle status: 0
Sep 03 12:20:34 fmac.local gnome-session-binary[1581]: DEBUG(+): GsmPresence: setting non-idle status 0
Sep 03 12:20:34 fmac.local gnome-shell[1595]: (../src/backends/native/meta-renderer-native.c:2211):meta_onscreen_native_swap_buffers_with_damage: runtime check failed: (onscreen_native->gbm.next_fb == NULL)



Is there a way to attach gdb to gnome-shell and get anything useful? When would I attach it?

Sorry!

Created attachment 1611261 [details]
gdb stacktrace of hanging gnome-shell

Starting off at the hung state in comment 12, I did

$ sudo gdb -p 1595
(gdb) thread apply all bt full


Full output of that is attached.

Following bug 174554, updated systemd with these rpms https://koji.fedoraproject.org/koji/taskinfo?taskID=37436968 which has this https://github.com/systemd/systemd/pull/13454 

And now I can't reproduce this bug either.

Spoke too soon, just got a failure;  meaning it's not as reproducible as I thought. I will test mutter-3.33.91-2.fc31 a few times and report back.

mutter-3.33.91-2.fc31 has fixed this; 5 for 5 blanks and successful wake up at login screen; and 5 for 5 while logged in and blanking set for 1 minute.

Discussed during the 2019-09-03 blocker review meeting: [1]

The decision to classify this bug as a "RejectedBlocker" and an "AcceptedFreezeException" was made as we believe it violates the Blocker criterion in comment 2 and is encountered immediately after install, so cannot be fixed with an update.

[1] https://meetbot.fedoraproject.org/fedora-blocker-review/2019-09-03/f31-blocker-review.2019-09-03-16.01.txt

FEDORA-2019-18f7fc4f08 has been submitted as an update to Fedora 31. https://bodhi.fedoraproject.org/updates/FEDORA-2019-18f7fc4f08

A later build of mutter is in the mega-update, so I've tagged the mega-update as fixing this.

accerciser-3.33.92-1.fc31, at-spi2-atk-2.33.92-1.fc31, at-spi2-core-2.33.92-1.fc31, atomix-3.33.92-1.fc31, bijiben-3.33.92-1.fc31, epiphany-3.33.92-1.fc31, evolution-3.33.92-1.fc31, evolution-data-server-3.33.92-1.fc31, evolution-ews-3.33.92-1.fc31, four-in-a-row-3.33.92-1.fc31, gdm-3.33.92-1.fc31, geary-3.33.90-1.fc31, gedit-3.33.92-1.fc31, gedit-plugins-3.33.92-1.fc31, gjs-1.57.92-1.fc31, glib-networking-2.61.92-1.fc31, glib2-2.61.3-1.fc31, gnome-builder-3.33.92-1.fc31, gnome-calculator-3.33.92-1.fc31, gnome-contacts-3.33.92-1.fc31, gnome-desktop3-3.33.92.1-1.fc31, gnome-disk-utility-3.33.92-1.fc31, gnome-maps-3.33.92-1.fc31, gnome-mines-3.33.92-1.fc31, gnome-music-3.33.92-1.fc31, gnome-online-accounts-3.33.92-1.fc31, gnome-online-miners-3.33.92-1.fc31, gnome-session-3.33.92-1.fc31, gnome-shell-3.33.92-1.fc31, gnome-shell-extensions-3.33.92-1.fc31, gnome-terminal-3.33.90-1.fc31, gtk3-3.24.11-1.fc31, gtksourceview4-4.3.92-1.fc31, hitori-3.34.0-1.fc31, iagno-3.33.92-1.fc31, libgnome-games-support-1.4.4-1.fc31, libgweather-3.33.92-1.fc31, libpeas-1.23.92-1.fc31, librsvg2-2.45.92-1.fc31, libsoup-2.67.93-1.fc31, lightsoff-3.33.92-1.fc31, mutter-3.33.92-1.fc31, orca-3.33.91-1.fc31, pango-1.44.6-1.fc31, polari-3.33.92-1.fc31, pyatspi-2.33.92-1.fc31, simple-scan-3.33.92-1.fc31, swell-foop-3.33.92-1.fc31, sysprof-3.33.92-1.fc31, template-glib-3.33.92-1.fc31, yelp-3.33.92-1.fc31, yelp-xsl-3.33.92-1.fc31 has been pushed to the Fedora 31 stable repository. If problems still persist, please make note of it in this bug report.