Frequent blackscreen after login, then KDE starts later, but another unrecoverable blackscreen after some time

[fishBone000]

Symptom

Frequently, after the moment I enter the password, there would be a 30 sec blackscreen with a cursor flashing at the top left corner of my screen. After that KDE starts up and the desktop gets loaded. But some time later, the screen would go black again, and never go back to normal.

Software in use

sddm: 0.21.0
KDE Plasma 6
Arch Linux
Xorg 21.1.13

Troubleshooting I have done

Before I submit this issue I made a help wanted post on Arch BBS.
You can go check it out for more, but I will summarize it here so reading the post shouldn't be necessary.

When the login is successful without any problem, the journal would look like this:

May 09 01:50:44 pootos sddm[643]: Authentication for user  "fishbone"  successful
...
May 09 01:50:46 pootos sddm[643]: Session started true

But if the problem occurs, it will look like this:

May 09 01:15:01 pootos sddm[641]: Authentication for user  "fishbone"  successful
...
May 09 01:15:33 pootos sddm[641]: Session started false
...
May 09 01:16:33 pootos sddm-helper[765]: [PAM] Closing session
May 09 01:16:33 pootos kactivitymanagerd[965]: The X11 connection broke (error 1). Did the X11 server die?

There should be a

Starting X11 session: "/usr/bin/X -nolisten tcp -background none -seat seat0 -noreset -keeptty -novtswitch -verbose 3" "/usr/share/sddm/scripts/Xsession \"/usr/bin/startplasma-x11\""

below the Authentication for user "fishbone" successful. I didn't put it in the code block because the code block was copy pasted from the post.
Note the 30 sec interval between "Authentication for user..." and "Session started false".

I and seth have tried to rule out some possibilities:

• Tried OpenBox, problem persists
• Tried ly, problem gone
• Tried to disable kwallet, problem persists

I also tried to modify sddm's code to add some more debug messages. From reading the code, what I understand is:

• Function UserSession::start will start sddm-helper-start-x11user with QProcess, which starts the X Server.
• UserSession::start will also call QProcess::waitForStarted, which has a timeout of 30 sec.
• Then the result will be returned.

So then I tried to add some debug messages:

• connect QProcess::errorOccured and QProcess::stateChanged to log the signal.
• print QProcess::state() after the waitForStarted function call.
• print debug message at the beginning and the end of main of HelperStartX11User.cpp
  • There are 2 messages at the beginning of main, but the first one is swallowed, how strange

Now the journal goes like this:

May 13 11:39:40 pootos sddm-helper[817]: Starting X11 session: "/usr/bin/X -nolisten tcp -background none -seat seat0 -noreset -keeptty -novtswitch -verbose 3" "/usr/share/sddm/scripts/Xsession \"/usr/bin/startplasma-x11\""
...
May 13 11:40:05 pootos sddm-helper[817]: das helper-start state QProcess::Starting exit status QProcess::NormalExit exit code 0
May 13 11:40:05 pootos sddm[667]: Session started false
May 13 11:40:05 pootos sddm-helper[817]: das State changed to QProcess::Running
May 13 11:40:05 pootos sddm-helper-start-x11user[852]: Detected locale "C" with character encoding "ANSI_X3.4-1968", which is not UTF-8.
                                                       Qt depends on a UTF-8 locale, and has switched to "C.UTF-8" instead.
                                                       If this causes problems, reconfigure your locale. See the locale(1) manual
                                                       for more information.
May 13 11:40:05 pootos sddm-helper-start-x11user[852]: das Arguments are: QList("/usr/lib/sddm/sddm-helper-start-x11user", "/usr/bin/X -nolisten tcp -background none -se>
May 13 11:40:05 pootos sddm-helper-start-x11user[852]: Xauthority path: "/run/user/1000/xauth_exOKcg"
May 13 11:40:05 pootos sddm-helper-start-x11user[852]: Running server: /usr/bin/X -nolisten tcp -background none -seat seat0 -noreset -keeptty -novtswitch -verbose 3 -au>
May 13 11:40:07 pootos sddm-helper-start-x11user[852]: X11 display: :0
May 13 11:40:07 pootos sddm-helper-start-x11user[852]: starting XOrg Greeter... ":0"
May 13 11:40:07 pootos sddm-helper-start-x11user[852]: Writing cookie to "/run/user/1000/xauth_exOKcg"
May 13 11:40:07 pootos sddm-helper-start-x11user[852]: Setting default cursor...
May 13 11:40:07 pootos sddm-helper-start-x11user[852]: Running display setup script: /usr/share/sddm/scripts/Xsetup
May 13 11:40:07 pootos sddm-helper-start-x11user[852]: das Quitting sddm-helper-start-x11user

I added "das" to the beginning of my debug messages to distinguish them.
I added 25000 to waitForStarted() to see if the late start up of sddm-helper-start-x11user is related to the timeout. As you can see in the journal it's indeed related.

Here's a successful login journal: http://0x0.st/X8nW.txt
And a failed one: http://0x0.st/X82u.txt
Journal after I added debug messages: http://0x0.st/XK49.txt

[fishBone000]

Diff of what I did to the source code

diff --git a/src/helper/HelperStartX11User.cpp b/src/helper/HelperStartX11User.cpp
index d77b78c..7aa1024 100644
--- a/src/helper/HelperStartX11User.cpp
+++ b/src/helper/HelperStartX11User.cpp
@@ -39,8 +39,11 @@ void X11UserHelperMessageHandler(QtMsgType type, const QMessageLogContext &conte
 
 int main(int argc, char** argv)
 {
+    qDebug() << "Starting sddm-helper-start-x11user";
+
     qInstallMessageHandler(X11UserHelperMessageHandler);
     QCoreApplication app(argc, argv);
+    qDebug() << "das" << "Arguments are:" << app.arguments();
     SDDM::SignalHandler s;
     QObject::connect(&s, &SDDM::SignalHandler::sigtermReceived, &app, [] {
         QCoreApplication::instance()->exit(-1);
@@ -72,5 +75,7 @@ int main(int argc, char** argv)
     });
 
     helper.start(app.arguments()[1]);
+
+    qDebug() << "das" << "Quitting sddm-helper-start-x11user";
     return app.exec();
 }
diff --git a/src/helper/UserSession.cpp b/src/helper/UserSession.cpp
index 860f165..b295a46 100644
--- a/src/helper/UserSession.cpp
+++ b/src/helper/UserSession.cpp
@@ -54,6 +54,13 @@ namespace SDDM {
     }
 
     bool UserSession::start() {
+      connect(this, &QProcess::errorOccurred, [](QProcess::ProcessError error){
+          qDebug() << "das" << "Error occured" << error;
+      });
+      connect(this, &QProcess::stateChanged, [](QProcess::ProcessState state){
+          qDebug() << "das" << "State changed to" << state;
+      });
+
         auto helper = qobject_cast<HelperApp*>(parent());
         QProcessEnvironment env = processEnvironment();
 
@@ -131,7 +138,8 @@ namespace SDDM {
             qCritical() << "Unable to run user session: unknown session type";
         }
 
-        const bool started = waitForStarted();
+        const bool started = waitForStarted(25000);
+        qDebug() << "das" << "helper-start" << "state" << state() << "exit status" << exitStatus() << "exit code" << exitCode();
         m_cachedProcessId = processId();
         if (started) {
             return true;

[Vogtinator]

What's the full journal from start of sddm until end of timeout?

I guess there is somehow still a session online, otherwise May 09 01:16:33 pootos kactivitymanagerd[965]: The X11 connection broke (error 1). Did the X11 server die? shouldn't happen.

[fishBone000]

What's the full journal from start of sddm until end of timeout?

It's at the end of the issue description, three full journals.

I guess there is somehow still a session online, otherwise May 09 01:16:33 pootos kactivitymanagerd[965]: The X11 connection broke (error 1). Did the X11 server die? shouldn't happen.

Yes, after the timeout KDE kicks in and the session is loaded. I can see the wallpaper, and the taskbar. Later after that the screen goes black, changing VT via CTRL-ALT-Fx won't help. This is exactly when X11 connection broke shows up.
So to sum up, there's actually 2 blackscreens:

1. The 30 sec timeout after I enter the password, the screen is black with a terminal cursor flashing
2. The blackscreen after KDE is loaded. This one isn't recoverable, I will have to reboot.

And also note that in the third journal, I used some trick to make a successful login:
If the timeout occurs, I logout ASAP before the 2nd blackscreen, then login again from sddm and hope there won't be a timeout again (otherwise there will be another second blackscreen)

[Vogtinator]

I guess the shutdown of the greeter + display server somehow breaks the startup of the user session + display server.

The log looks fairly normal until suddenly

May 09 01:16:33 pootos sddm-helper[765]: [PAM] Closing session
May 09 01:16:33 pootos kactivitymanagerd[965]: The X11 connection broke (error 1). Did the X11 server die?
May 09 01:16:33 pootos sddm-helper[765]: pam_unix(sddm:session): session closed for user fishbone

i.e. the x11 user helper exited somehow?

[fishBone000]

I don't think that's the point.
I think the point is the sddm-helper-start-x11user binary is mysteriously not started until right after the timeout, so UserSession thought it failed to start, causing later problems.
Though what exactly happens after that, the 60 sec between "Session failed to start" and "[PAM] Closing session", I don't know about this, I didn't read that much of code yet.
Should I ask about this problem to QT? I have a feeling that it's something more related to QT, just that I chose to ask here because it happens inside sddm.

[fishBone000]

Recently I modified the code from:

const bool started = waitForStarted();

to

        const int interval_ms = 1000;
        const int timeout = 30000;
        int elapsed = 0;
        while (state() == QProcess::Starting && elapsed < timeout) {
            waitForStarted(interval_ms);
            elapsed += interval_ms;
        }
        const bool started = state() == QProcess::Running;

in order to hope that:

1. the helper will start after waitForStarted returns
2. in case the helper isn't actually loaded due to my slow laptop, just wait for another 1000ms

However I found that it doesn't work, the helper still starts after timeout (30000 ms). Diving deeper into the sddm code shows that sddm almost immediately exits after that.
To confirm the what caused the helper to start, I added sleep(5) before exit(Auth::HELPER_SESSION_ERROR);. Journal shows that the helper starts right after the exit.
I thought it's the return of waitForStarted that caused the child helper process to actually start, but this finding indicates it's the exit of the parent process.