Bug 936842

Scott: can you please find a resource to assist on this issue? I'll be off for a week, and we should try to not stall this issue for that long

(In reply to Dominique Leuenberger from comment #1)
> Scott: can you please find a resource to assist on this issue? I'll be off
> for a week, and we should try to not stall this issue for that long

Federico is looking into this ...

I'm building an X server with debug info and the ability to stop the server when it is about to create the logfile - that should at least make it debuggable during boot.

linux-7pp9:~ # ps auxwww | grep X
gdm        821  0.0  0.1  49228  2220 tty7     T+   17:47   0:00 /usr/bin/Xorg vt7 -displayfd 3 -auth /run/user/484/gdm/Xauthority -nolisten tcp -background none -noreset -keeptty -verbose 3
root      1485  0.0  0.0   9236   932 pts/0    S+   17:48   0:00 grep --color=auto X


1436222947.550655 --- SIGCONT {si_signo=SIGCONT, si_code=SI_USER, si_pid=1504, si_uid=0} ---
1436222947.550691 stat("/var/log/Xorg.(null).log", 0x7fff56ae3f10) = -1 ENOENT (No such file or directory)
1436222947.550773 open("/var/log/Xorg.(null).log", O_WRONLY|O_CREAT|O_TRUNC, 0666) = -1 EACCES (Permission denied)


This is X when we are first booting.  Xorg runs as user gdm, but tries to create /var/log/Xorg.(null).log and gets EACCESS.

So there are two problems; the permissions one and the (null) one.

I just noticed that in openSUSE 13.2, Xorg runs with "-logfile /dev/null", both for user sessions and for gdm, which a) would "solve" this problem; b) sounds unwise.  No idea yet as to where that comes from.

os/utils.c:736 - ProcessCommandLine():
        else if (strcmp(argv[i], "-displayfd") == 0) {
            if (++i < argc) {
                displayfd = atoi(argv[i]);
                display = NULL;

We *do* use -displayfd.  Printing "(null)" is a bug in the logging code.

I'm tracking down the -displayfd option and its ramifications.

In openSUSE 13.2, gdm is hardcoded to do this (gdm/daemon/gdm-server.c:301):

#ifdef ENABLE_SYSTEMD_JOURNAL
        /* For systemd, we don't have a log file but instead log to stdout,
           so set it to the xserver's built-in default verbosity */
        if (debug)
            verbosity = "7 -logfile /dev/null";
        else
            verbosity = "3 -logfile /dev/null";
#endif

which gets put after a "-verbose" option.

In openSUSE:42:Factory-Copies, we have gdm/daemon/gdm-x-session.c:225 instead.  That one uses -displayfd specify a file descriptor, and runs xorg in user mode, not as root:

        g_subprocess_launcher_setenv (launcher, "XORG_RUN_AS_USER_OK", "1", TRUE);
        g_subprocess_launcher_take_fd (launcher, pipe_fds[1], DISPLAY_FILENO);

        if (g_getenv ("XDG_VTNR") != NULL) {
                int vt;

                vt = atoi (g_getenv ("XDG_VTNR"));

                if (vt > 0 && vt < 64) {
                        vt_string = g_strdup_printf ("vt%d", vt);
                }
        }

        display_fd_string = g_strdup_printf ("%d", DISPLAY_FILENO);

        g_ptr_array_add (arguments, X_SERVER);

        if (vt_string != NULL) {
                g_ptr_array_add (arguments, vt_string);
        }

        g_ptr_array_add (arguments, "-displayfd");
        g_ptr_array_add (arguments, display_fd_string);

However, there is nothing about a -logfile argument.

What *does* have the -logfile argument is gdm/daemon/gdm-session.c as before.  However, Xorg is launched from the new gdm-x-session helper now.  I'll ask to see if not adding -logfile is just an oversight.

Some very helpful comments from Ray Strode at Red Hat:

> Interesting, it shouldn't be trying to write the log file to /var/log but to
~gdm/.local/share/xorg/Xorg.0.log

> So the reason the -logfile /dev/null got removed is, we now start the X session as the user instead of as root, and Xorg doesn't allow -logfile to be specified in that case (since in some cases, Xorg runs setuid root, and giving the user control of filenames has security implications).  Xorg could probably be improved to accept /dev/null in this case, or to add a -nologfile or something, but I never followed up to make that happen.

>Still it should be going to /var/lib/gdm/.local/share/xorg/Xorg.0.log or something like that.

> Make sure the X server is built with logind support. failing that, maybe the Xwrapper config has needs_root_rights=yes and that's somehow gunking up the works? Not sure, but i'd start by looking at the X server code and see what conditions the config file gets written to ~/.local/share/xorg and see why those aren't being met for you.

I'm backporting commit 9d65c515d83d2158b5949e249777ca2a02b31901 to xorg-x11-server; it's where upstream added support for logging to the home directory.

(This version, 1.15.2, doesn't support logind yet; no idea how that plays out with the new gdm.)

Created attachment 640536 [details]
u_log-to-xdg-data-home.patch

Backported commit that adds support for logging to the user's home directory when Xorg is not being run as root.

is gnome starting now? If so, submit it to openSUSE:42

To fix this problem I suggest moving to at least X.org 1.16 (Factory is at 1.17.2) and enable logind support to run without root permissions.

(The build service wasn't building this yesterday; it's succeeded now...)

At least it fails differently now :)  I get

  Cannot open log file "/var/lib/gdm/.local/share/xorg//var/log/Xorg.(null).log"

I'll keep digging.

Created attachment 640656 [details]
u_log-to-xdg-data-home.patch

Argh, I had missed one commit which modifies configure.ac to set the #defines for log directories correctly.

This updated version fixes that; it still has the "(null)" problem, which is not catastrophic.

Now it fails like this:

(EE): xf86OpenConsole: Server must be suid root for option "KeepTTY"

I'll look for what causes that.  Another missing commit?

Why do we have xorg-x11-server version 1.15.2?  Indeed Factory has a much newer one.

Note to self: look at upstream commit 701b7ab34984b0f9f0c357b0ff8b53c5132c6324 - that's the removal of the KeepTTY error, but there are commits close by that fiddle with TTYs.

Stefan, could you please take a quick look at commit 6b79f28f5cb259f2168ecc3034fe2161e969bf7d which happened right after that one?  I don't understand the implications of "Don't detach from controlling tty when it is our vt" - I'm not sure if we need that commit in addition to the one that removes the KeepTTY error.

there is a related bug 937351

Created attachment 640780 [details]
u_run_xserver-as-non-root.patch

Patch with additional backported commits for the KeepTTY error.

Now it fails with

(EE) xf86OpenConsole: Cannot open virtual console 7 (Permission denied)

What about updating xorg-server for openSUSE:42 instead? I've prepared a project 
X11:XOrg:42, which updates the whole X driver stack for sle12.

--> https://build.opensuse.org/project/show/X11:XOrg:42

(In reply to Stefan Dirsch from comment #18)
> What about updating xorg-server for openSUSE:42 instead? I've prepared a
> project 
> X11:XOrg:42, which updates the whole X driver stack for sle12.
> 
> --> https://build.opensuse.org/project/show/X11:XOrg:42

Thats what I suggested it in comment #12 and I think thats the perfect way forward.

Upgrading the X stack would be definitely better :)

(In reply to Federico Mena Quintero from comment #20)
> Upgrading the X stack would be definitely better :)

Which just happened yesterday and today in openSUSE:42 project. Hope things become easier now or we see different issues. ;-)

We now have an updated X-stack in openSUSE 42; unfortunately, GNOME Still has its share of issues starting up.

From the journal, I extracted a part of the log that might be interesting:


(II) glamor: EGL version 1.4 (DRI2)
EGL_MESA_drm_image required
(EE) modeset(o): glamor initialization failed

is that possibly a simple case of missing recompiles?

(In reply to Dominique Leuenberger from comment #22)
> We now have an updated X-stack in openSUSE 42; unfortunately, GNOME Still
> has its share of issues starting up.
> 
> From the journal, I extracted a part of the log that might be interesting:
> 
> (II) glamor: EGL version 1.4 (DRI2)
> EGL_MESA_drm_image required
> (EE) modeset(o): glamor initialization failed

So we don't see the issue on factory/tumbleweed? Are you sure?

(In reply to Stephan Kulow from comment #23)
> is that possibly a simple case of missing recompiles?

I don't thihnk so.

Are you testing with qemu (cirrus KMS driver)? Is this reproducable on e.g. Intel graphics (i915 KMS driver) when using modesetting driver? Setting AccelMethod option for modesetting driver to "none" may help.

Please provide the complete X logfile!

Created attachment 641132 [details]
A full Xorg.log from my VM, where I see about the same as openQA by now

So indeed no fatal error. X appears to come up perfectly fine! If GNONME session cannot be started, we need to look at the session startup logfile - wherever this is located now.

I get a crash on the vboxvideo_drv.so from the X server when running under VirtualBox.  Will try gnome-boxes (which uses qemu, I think) next, or a real machine.

Yeah. As far as I remember virtualbox X driver needed an update in factory/tumbleweed for the new xorg-server version as well. Testing on real hardawre would be really appreciated! I'm sure with qemu you'll run into the same issue as Dominique above before.

(In reply to Stefan Dirsch from comment #31)
> Yeah. As far as I remember virtualbox X driver needed an update in
> factory/tumbleweed for the new xorg-server version as well. Testing on real
> hardawre would be really appreciated! I'm sure with qemu you'll run into the
> same issue as Dominique above before.

Dumb question - the openSUSE-42-Staging_A-Staging2-DVD-x86_64-Build58.1-Media.iso from openQA doesn't seem to have a boot sector.  It works fine for a VM, but I can't boot it on real hardware... what's the thing to do here?

not a dumb question, but I only have as answer: by using legacy boot, not UEFI

The latest issues seem to be based on systemd user session tracking issues.

* if I don't set X to setuid, I don't have permissions on /dev/input/*
* gnome-shell.desktop fails to register before timeout (either dbus or logind)

So I think we are missing something quite basic... that even permissions are that messed up.

Federico, are you still looking into this?

(In reply to Dominique Leuenberger from comment #34)
> The latest issues seem to be based on systemd user session tracking issues.
> 
> * if I don't set X to setuid, I don't have permissions on /dev/input/*

xdm and sddm start Xorg as root, causing this not to be an issue there.
On Tumbleweed, we also start Xorg as non-privileged user, so 'this works' - but we are lacking some integration pieces in Leap 42.1

I got the image to boot by burning it on a physical DVD - it wouldn't boot from an USB stick.

The installation works.

The first boot after installation goes like this:

1. Turn on the machine.

2. After GRUB, the green-wavy background appears.  I hit Esc to get to the text console log.

3. Boot finishes; I get to the text login screen

  Welcome ot openSUSE 20150714 "Tumbleweed" - Kernel 4.1.1-1-desktop (tty2).


  torta login:

4. The screen flickers but remains the same.  GDM and X want to start up.

At this point, the contents of the text screen remain the same (in "login:"), but the text cursor disappears and everything seems frozen.  I can't do anything except hit Ctrl-Alt-F1 to switch to a text console.  In there, I get the login text properly and I can log in.

I'll attach the systemd journal and GDM's X log.  I haven't read them ultra-closely, but everything *seems* okay.  No idea why the actual screen doesn't show anything useful.

Created attachment 641618 [details]
journalctl -b

Created attachment 641619 [details]
Xorg.0.log from GDM

Okay, I got this now

[   120.351] (II) AIGLX: Loaded and initialized i965
[   120.351] (II) GLX: Initialized DRI2 GL provider for screen 0
[   120.354] (II) intel(0): switch to mode 1366x768@60.0 on LVDS1 using pipe 0, position (0, 0), rotation normal, reflection none
[   120.356] (EE) intel(0): failed to set mode: Permission denied [13]
[   120.360] (WW) intel(0): failed to restore desired modes on VT switch
[   120.360] (EE) intel(0): sna_mode_check: invalid state found on pipe 0, disabling CRTC:20

So it's a permissions problem.

Created attachment 641620 [details]
strace of X

This is an strace of starting up the X server.

Here we receive the fd; it gets duped to be fd number 8:

1961  1437519314.560377 recvmsg(6, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1\10\0\0\0h\1\0\0005\0\0\0\5\1u\0\5\0\0\0\6\1s\0\5\0\0\0"..., 2048}], msg_controllen=24, [{cmsg_len=20, cmsg_level=SOL_SOCKET, cmsg_type=SCM_RIGHTS, [7]}], msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 80
1961  1437519314.560405 fcntl(7, F_GETFD) = 0x1 (flags FD_CLOEXEC)
1961  1437519314.560426 fcntl(7, F_SETFD, FD_CLOEXEC) = 0
1961  1437519314.560454 recvmsg(6, 0x7ffddbb923b0, MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
1961  1437519314.560478 fcntl(7, F_DUPFD_CLOEXEC, 3) = 8
1961  1437519314.560503 write(0, "[   474.876] ", 13) = 13
1961  1437519314.560530 write(0, "(II) systemd-logind: got fd for "..., 67) = 67
1961  1437519314.560555 close(7)        = 0
1961  1437519314.560578 ioctl(8, DRM_IOCTL_SET_VERSION, 0x7ffddbb926c0) = 0
1961  1437519314.560603 ioctl(8, DRM_IOCTL_GET_UNIQUE, 0x7ffddbb926b0) = 0
1961  1437519314.560624 ioctl(8, DRM_IOCTL_GET_UNIQUE, 0x7ffddbb926b0) = 0
1961  1437519314.560647 ioctl(8, DRM_IOCTL_VERSION, 0x150c9b0) = 0
1961  1437519314.560666 ioctl(8, DRM_IOCTL_VERSION, 0x150c9b0) = 0

And here we fail to ioctl()

1961  1437519314.625075 write(0, "[   474.940] ", 13) = 13
1961  1437519314.625123 write(0, "(II) intel(0): switch to mode 13"..., 117) = 117
1961  1437519314.625151 ioctl(8, DRM_IOCTL_MODE_SETGAMMA, 0x7ffddbb923f0) = -1 EACCES (Permission denied)
1961  1437519314.625217 ioctl(8, DRM_IOCTL_MODE_SETCRTC, 0x7ffddbb92370) = -1 EACCES (Permission denied)
1961  1437519314.625249 ioctl(8, DRM_IOCTL_I915_GEM_CREATE, 0x7ffddbb92160) = 0
1961  1437519314.625281 ioctl(8, DRM_IOCTL_I915_GEM_SET_TILING, 0x7ffddbb92090) = 0
1961  1437519314.625304 ioctl(8, DRM_IOCTL_I915_GEM_SET_CACHING, 0x7ffddbb92090) = 0
1961  1437519314.625327 ioctl(8, DRM_IOCTL_I915_GEM_MMAP_GTT, 0x7ffddbb92050) = 0
1961  1437519314.625350 mmap(NULL, 4325376, PROT_READ|PROT_WRITE, MAP_SHARED, 8, 0x100420000) = 0x7f09da8eb000
1961  1437519314.625381 rt_sigprocmask(SIG_BLOCK, NULL, [], 8) = 0
1961  1437519314.626910 ioctl(8, DRM_IOCTL_MODE_ADDFB, 0x7ffddbb920a0) = 0
1961  1437519314.626966 ioctl(8, DRM_IOCTL_I915_GEM_BUSY, 0x7ffddbb92100) = 0
1961  1437519314.626993 ioctl(8, DRM_IOCTL_I915_GEM_EXECBUFFER2, 0x7ffddbb92150) = 0
1961  1437519314.627029 ioctl(8, DRM_IOCTL_I915_GEM_BUSY, 0x7ffddbb92100) = 0
1961  1437519314.627054 ioctl(8, DRM_IOCTL_MODE_SETCRTC, 0x7ffddbb92370) = -1 EACCES (Permission denied)
1961  1437519314.627127 write(0, "[   474.943] ", 13) = 13
1961  1437519314.627176 write(0, "(EE) intel(0): failed to set mod"..., 58) = 58

Any ideas on why that DRM_IOCTL_MODE_SETCRTC fails?

This is an X server that I ran as root from the console, not gdm's non-root one.

I think we still might have some logind integration issues. Enabling gdm debugging and booting I see this in the journal log

display-manager[3834]: GdmManager: GDM starting to manage displays
display-manager[3834]: GdmLocalDisplayFactory: Adding display on seat seat0
display-manager[3834]: GdmDisplay: id: (null)
display-manager[3834]: GdmDisplay: seat id: (null)

Enabling debugging on a working box yields
display-manager[5499]: GdmManager: GDM starting to manage displays
display-manager[5499]: GdmLocalDisplayFactory: Adding display on seat seat0
display-manager[5499]: GdmLocalDisplayFactory: Reserving X display: 0
display-manager[5499]: GdmDisplayStore: Adding display /org/gnome/DisplayManager/Displays/_0 to store
display-manager[5499]: GdmDisplay: Managing display: /org/gnome/DisplayManager/Displays/_0
display-manager[5499]: GdmDisplay: manage display
display-manager[5499]: GdmDisplay: Preparing display: /org/gnome/DisplayManager/Displays/_0

That one maybe?

http://unix.stackexchange.com/questions/149283/xorg-with-kernel-mode-settings-wont-work-with-other-tty

(In reply to Stefan Dirsch from comment #44)
> That one maybe?
> 
> http://unix.stackexchange.com/questions/149283/xorg-with-kernel-mode-
> settings-wont-work-with-other-tty

should not be : active tty during boot is vt7 (thanks to plymouth) - and gdm fires up on tty7 too.

> [   120.356] (EE) intel(0): failed to set mode: Permission denied [13]
is one we randomly see on Tumbleweed testing as well (rarely though)

On my qemu/kvm, I got a bit different logs: X obviously starts (but doesn't show anything).

But there I see that the cirrus driver can't load due to a kernel module occupying the device already - then it falls back to fbdev... (any trick for this setup?)

But I also see permission issues when opening /dev/input/* devices - so not much working once X started (with a black screen only)

(In reply to Dominique Leuenberger from comment #45)
> (In reply to Stefan Dirsch from comment #44)
> > That one maybe?
> > 
> > http://unix.stackexchange.com/questions/149283/xorg-with-kernel-mode-
> > settings-wont-work-with-other-tty
> 
> should not be : active tty during boot is vt7 (thanks to plymouth) - and gdm
> fires up on tty7 too.

Please leave gdm out of the game for now and try with a pure Xserver started as root, i.e.

  Xorg -retro -verbose 7 -logverbose 7

> > [   120.356] (EE) intel(0): failed to set mode: Permission denied [13]
> is one we randomly see on Tumbleweed testing as well (rarely though)

Ok. That's news for me. Possibly it fails for everyone testing on real
hardware? I wouldn't be surprised ...

> On my qemu/kvm, I got a bit different logs: X obviously starts (but doesn't
> show anything).
> 
> But there I see that the cirrus driver can't load due to a kernel module
> occupying the device already - then it falls back to fbdev... (any trick for
> this setup?)

cirrus X driver cannot work, if a Cirrus KMS is loaded (which is meanehile the default). Fallback should be modesetting X driver though. Now integrated into
X server ("modeset" in the logfile). fbdev would be the last resort. So there is something wrong.

> But I also see permission issues when opening /dev/input/* devices - so not
> much working once X started (with a black screen only)

Again related to gdm I guess.

(In reply to Stefan Dirsch from comment #46)

> > > [   120.356] (EE) intel(0): failed to set mode: Permission denied [13]
> > is one we randomly see on Tumbleweed testing as well (rarely though)
> 
> Ok. That's news for me. Possibly it fails for everyone testing on real
> hardware? I wouldn't be surprised ...

unlikely - as that would imply not a single TW install on real HW, including mine - would work. this is clearly not what we see. In openQA it seems a bit random and appears to be a racing condition (but not debugged yet - and to be handled in a different bug)

Created attachment 641656 [details]
Xorg.log, X started manually without any DM

result was a black screen with a blinking cursor topleft

Ok. Whatever. What I did now was that I've updated a regular SLES12 system with intel graphics card with X11:XOrg:42 repo. I noticed that I also needed to update xf86-input-evdev driver (probably no issue for openSUSE:42, if this got recompiled with the new X input API version). 

Bare Xserver then shows me:

# grep EE /var/log/Xorg.0.log
        (WW) warning, (EE) error, (NI) not implemented, (??) unknown.
[ 10669.875] (EE) systemd-logind: failed to take device /dev/dri/card0: Operation not permitted
[ 10670.013] (EE) systemd-logind: failed to take device /dev/input/event5: Operation not permitted
[ 10670.023] (EE) systemd-logind: failed to take device /dev/input/event4: Operation not permitted
[ 10670.024] (EE) systemd-logind: failed to take device /dev/input/event0: Operation not permitted
[ 10670.025] (EE) systemd-logind: failed to take device /dev/input/event1: Operation not permitted
[ 10670.026] (EE) systemd-logind: failed to take device /dev/input/event2: Operation not permitted
[ 10670.027] (EE) systemd-logind: failed to take device /dev/input/event6: Operation not permitted

But everything works AFAICS. Same applies to X started via gdm.

# grep EE /var/log/gdm/:0.log
        (WW) warning, (EE) error, (NI) not implemented, (??) unknown.
(EE) systemd-logind: failed to get session: PID 2702 does not belong to any known session

GNOME session works fine though. 

So currently I believe we need an update for systemd-logind. And the GNOME update broke something in addition ...

i got my 'rootless X' to finally accept keyboard inputs: openSUSE:42 still comes with xf86-input-evdev 2.8.x, but 'server managed fds' appeared only in 2.9 (which means: logind could not pass permissions down to the driver).

There might be more such subtle errors in the system... 

With this setup, I am now able to
* spawn gdm with autologin into an icewm session, which is still controllable.

GNOME still fails to register the session though (which should also be integration with systemd-logind)

Ah. Interesting. With xorg-server built with 

  --disable-systemd-logind \
  --with-systemd-daemon="no" \

I no longer see the error messages about permission problems with
systemd-logind. I will submitrequest this change and the udpated input drivers.
Possibly this helps.

(In reply to Stefan Dirsch from comment #51)
> Ah. Interesting. With xorg-server built with 
> 
>   --disable-systemd-logind \
>   --with-systemd-daemon="no" \

No way: or we have to reintroduce consolekit as session manager - which is no longer supported in GNOME 3.16.


> I no longer see the error messages about permission problems with
> systemd-logind. I will submitrequest this change and the udpated input
> drivers.
> Possibly this helps.

I updated the evdev input driver on my box to 2.9.2 and that made all evdev permissions (/dev/input/*) go away and I can control X at least now.. I can get you an up-to-date journal from the last boot.

Created attachment 641703 [details]
Full boot journal - post update of xf86-input-evdev to 2.9.2

No more permission errors to get X up (gnome still not firing up..)

Created attachment 641704 [details]
The Xorg.0.log of a boot post xf86-input-evdev 2.9.2 update

This is an autogenerated message for OBS integration:
This bug (936842) was mentioned in
https://build.opensuse.org/request/show/317934 42 / xorg-x11-server

The issue for GNOME Session registration is found: libXi < 1.7.4 is to be blamed.

Updated to 1.7.4 and my gnome session starts up (with Xorg having systemd integration enabled - and evdev updated to 2.9.2)

Created attachment 641714 [details]
GNOME 3.16.2 running on top of openSUSE Leap 42.1 - Milestone 1

Ok. I've reverted xorg-server changes and submitrequested an update libXi 1.7.4.
SR#317958 and SR#317967.

This is an autogenerated message for OBS integration:
This bug (936842) was mentioned in
https://build.opensuse.org/request/show/317958 42 / xorg-x11-server
https://build.opensuse.org/request/show/317967 42 / libXi

Seems this all is still completely broken. See bnc#939455, bnc#939571, bnc#939594.

Build0022 works fine for me on a real laptop.  Build0009 was the one that didn't work.

Can we close this bug now, and take care of the other bugs?

Sure, Federico. As you wish. I've reassigned all the 3 mentioned bugs in comment#60 to GNOME component and added you to Cc. So these won't get lost. Thanks for your help!