Bug 405444 - ksplashqml hits its hard timeout of 30 seconds because of failing qdbus call kinit
Summary: ksplashqml hits its hard timeout of 30 seconds because of failing qdbus call ...
Status: RESOLVED FIXED
Alias: None
Product: ksplash
Classification: Plasma
Component: general (show other bugs)
Version: 5.14.5
Platform: Debian testing Linux
: NOR normal
Target Milestone: ---
Assignee: Unassigned bugs mailing-list
URL:
Keywords:
: 405446 (view as bug list)
Depends on:
Blocks:
 
Reported: 2019-03-13 18:23 UTC by Bernhard Übelacker
Modified: 2019-06-18 22:01 UTC (History)
4 users (show)

See Also:
Latest Commit:
Version Fixed In:


Attachments
ksplashqml: Retry in start script if dbus interface is not yet up. (1.59 KB, patch)
2019-03-13 18:23 UTC, Bernhard Übelacker
Details
ksplashqml: Add some logging to get details when stages were reached. (2.17 KB, patch)
2019-03-15 21:50 UTC, Bernhard Übelacker
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Bernhard Übelacker 2019-03-13 18:23:14 UTC
Created attachment 118780 [details]
ksplashqml: Retry in start script if dbus interface is not yet up.

When /usr/bin/startkde starts it first executes ksplashqml around line 134.
Later around line 297 is a call "qdbus ... kinit" to increase the
stage in ksplashqml.

Unfortunately it looks like on fast enough systems the qdbus call is faster
reached as ksplashqml has opened the dbus interface.

This results in the message in .xsession-errors:

    Cannot find 'org.kde.KSplash.setStage' in object /KSplash at org.kde.KSplash

Therefore ksplashqml seems to never reach setStage(6) to finish
its execution and therefore runs into the hard limit of 30 seconds.

Attached patch tries to retry the qdus call when it returns not success.
Unfortunately the overhead of the loop might be already enough to have
the dbus interface already up, because I did never see the logging when
doing a retry.


Operating System: Debian GNU/Linux 
KDE Plasma Version: 5.14.5
Qt Version: 5.11.3
KDE Frameworks Version: 5.54.0
Kernel Version: 4.19.0-2-amd64
OS Type: 64-bit
Processors: 16 × AMD Ryzen 7 1700 Eight-Core Processor
Memory: 15.5 GiB of RAM
Comment 1 Kai Uwe Broulik 2019-03-14 14:47:58 UTC
Do you use a fancy splash screen theme? Are you running Wayland?

Can you give the patch https://phabricator.kde.org/D19753 a try?
Comment 2 Bernhard Übelacker 2019-03-14 22:54:35 UTC
Hello Kai Uwe Broulik,
thanks for your time.

> Do you use a fancy splash screen theme? Are you running Wayland?
No fancy splash that I am aware of - visually equal to a current standard
debian buster installation - just the black screen with logo in the middle
and the "circling circle". ("ksplashqml Breeze --pid")
Also not running Wayland - I am still on Xorg with AMD graphics drivers.

> Can you give the patch https://phabricator.kde.org/D19753 a try?
I will rebuild a package with just that change and report back.

Kind regards,
Bernhard
Comment 3 Bernhard Übelacker 2019-03-15 21:50:27 UTC
Hello Kai Uwe Broulik,

> > Can you give the patch https://phabricator.kde.org/D19753 a try?
> I will rebuild a package with just that change and report back.

I build the package with D19753 applied and the first some boots did not
show these "Cannot find 'org.kde.KSplash.setStage' ..." messages anymore.

Additional I had modified my logging patch and now I also get the
"kcminit" stage even before the "kinit".

Might the "kcminit" also just got lost because the
dbus interface was not yet up?

Kind regards,
Bernhard


2019-03-15 22:34:12.728 SplashApp::setStage("initial")
2019-03-15 22:34:12.728 SplashApp::setStage("initial"): m_stages.count==1
2019-03-15 22:34:12.728 SplashApp::setStage(1), m_stage==0
2019-03-15 22:34:12.803 SplashApp::setStage("kcminit")
2019-03-15 22:34:12.803 SplashApp::setStage("kcminit"): m_stages.count==2
2019-03-15 22:34:12.803 SplashApp::setStage(2), m_stage==1
2019-03-15 22:34:12.811 SplashApp::setStage("kinit")
2019-03-15 22:34:12.811 SplashApp::setStage("kinit"): m_stages.count==3
2019-03-15 22:34:12.811 SplashApp::setStage(3), m_stage==2
2019-03-15 22:34:12.891 SplashApp::setStage("ksmserver")
2019-03-15 22:34:12.891 SplashApp::setStage("ksmserver"): m_stages.count==4
2019-03-15 22:34:12.891 SplashApp::setStage(4), m_stage==3
2019-03-15 22:34:13.119 SplashApp::setStage("ready")
2019-03-15 22:34:13.119 SplashApp::setStage("ready"): m_stages.count==5
2019-03-15 22:34:13.119 SplashApp::setStage(5), m_stage==4
2019-03-15 22:34:13.440 SplashApp::setStage("wm")
2019-03-15 22:34:13.440 SplashApp::setStage("wm"): m_stages.count==6
2019-03-15 22:34:13.440 SplashApp::setStage(6), m_stage==5
2019-03-15 22:34:15.841 SplashApp::setStage("desktop")
2019-03-15 22:34:15.841 SplashApp::setStage("desktop"): m_stages.count==7
2019-03-15 22:34:15.841 SplashApp::setStage(7), m_stage==6
2019-03-15 22:34:15.841 SplashApp::setStage() before exit
Comment 4 Bernhard Übelacker 2019-03-15 21:50:47 UTC
Created attachment 118829 [details]
ksplashqml: Add some logging to get details when stages were reached.
Comment 5 Kai Uwe Broulik 2019-03-16 09:16:31 UTC
> Might the "kcminit" also just got lost because the
> dbus interface was not yet up?

Very likely, so I suppose bug 405444 and 405446 are probably the same root cause, will mark as duplicate.
Thanks a lot for your help and testing, much appreciated!
Comment 6 Kai Uwe Broulik 2019-03-16 09:16:38 UTC
*** Bug 405446 has been marked as a duplicate of this bug. ***
Comment 7 Kai Uwe Broulik 2019-03-16 11:26:28 UTC
Git commit 9a4bb220c162f031b4d45ed04f9e156b6d0b852e by Kai Uwe Broulik.
Committed on 16/03/2019 at 11:24.
Pushed by broulik into branch 'Plasma/5.15'.

[KSplashQML] Register DBus before loading the splash theme

Loading the theme and setting everything up can take a while.
Ensure that we catch all setStage calls that might have been emitted before we were fully up.

CHANGELOG: Reduced likelihood of KSplash not being dismissed properly and only timing out after 30s

Differential Revision: https://phabricator.kde.org/D19753

M  +4    -4    ksplash/ksplashqml/splashapp.cpp

https://commits.kde.org/plasma-workspace/9a4bb220c162f031b4d45ed04f9e156b6d0b852e
Comment 8 David Edmundson 2019-06-18 22:01:33 UTC
Please reopen if it's still an issue