Bug 388611 - log polluted w/ 'Empty filename passed to function'
Summary: log polluted w/ 'Empty filename passed to function'
Status: RESOLVED FIXED
Alias: None
Product: dolphin
Classification: Applications
Component: general (show other bugs)
Version: unspecified
Platform: openSUSE Linux
: NOR minor
Target Milestone: ---
Assignee: Dolphin Bug Assignee
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2018-01-06 10:54 UTC by Michael Heidelbach
Modified: 2019-06-23 08:18 UTC (History)
3 users (show)

See Also:
Latest Commit:
Version Fixed In:
Sentry Crash Report:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Michael Heidelbach 2018-01-06 10:54:48 UTC
$ cat .local/share/sddm/xorg-session.log | wc -l
692
$ cat .local/share/sddm/xorg-session.log | grep 'Empty filename passed to function' | wc -l
92

100 * 92 / 692 > 13%
Comment 1 Christoph Feck 2018-01-09 02:17:05 UTC
Could you tell us which component issues this message? I couldn't find this string in KDE sources, but I only checked common repositories.
Comment 2 Michael Heidelbach 2018-01-09 10:16:28 UTC
While watching with
 tail -f .local/share/sddm/xorg-session.log

* every folder change in dolphin generates around 4 consecutive lines of this message.
* expanding a folder in treeview mode within the files panel
    - expand => sometimes 4 messages
    - collapse => no messages
    - expand again => always 4 messages
* closing dolphin generates around 20 consecutive messages

* 2 messages appear while hovering over *some* icons (mostly but not all home-made .desktop-files) in plasma toolbar panel.

This is just a rough sketch it did not bother to count exactly. Once the console is completely filled with 'Empty filename passed to function' one cannot easily identify new lines.


A few days ago tumbleweed updated Qt (from ??? to 5.10.???) and it is only since then I see these messages. (I wasn't aware of that when I filed this bug.)
Comment 3 Christoph Feck 2018-01-09 22:51:54 UTC
Thanks for the update; reassigning to Dolphin developers for inspection. It might be a message from Qt, but maybe Dolphin or KIO are really passing wrong information to a Qt function.
Comment 4 null 2018-01-10 00:13:45 UTC
Can confirm, the same happens in Gwenview when switching to "View" mode (but only the first time doing so).

> A few days ago tumbleweed updated Qt (from ??? to 5.10.???)
> and it is only since then I see these messages.
Yep, with Qt 5.10.0 / KF 5.40 I see it, but it isn't there with Qt 5.9.3 / KF 5.40.

The error message was introduced here:
https://code.qt.io/cgit/qt/qtbase.git/commit/?id=0dee566e98f5ff4f224e596de1c04de4f9685df4

Still, the fix might not be in Qt.
Comment 5 null 2018-01-11 21:49:42 UTC
The problem in Gwenview and some of the Dolphin problems (I could not reproduce all of those in Comment 2 in the first place) are fixed in KIO 5.41 (549fc81e8e8a in particular).

@Michael: Could you upgrade to 5.41 (Tumbleweed should have it really soon™) and observe the situation a bit? I suspect the fallout from the change in Qt still has to be fixed in a couple more places. It would be nice to make a list.

E.g. there is Bug 388389, which triggers the error output in plasmashell via RSIBreak. Hovering over custom icons in the panel is still broken, too.
Comment 6 Michael Heidelbach 2018-01-12 08:58:51 UTC
$ kded5 --version
kded5 5.41.0
$ ls -l /usr/bin/kded5
-rwxr-xr-x 1 root root 6,2K Jan  9 21:41 /usr/bin/kded5
$ /usr/bin/dolphin /tmp
Trying to convert empty KLocalizedString to QString.
qt.accessibility.core: Cannot create accessible child interface for object:  PlacesView(0x55a0d141d020)  index:  19
inotify_add_watch("/lost+found") failed: "Permission denied"
inotify_add_watch("/tmp/systemd-private-0e95805ffca54249af9d1ff11c5639f8-rtkit-daemon.service-4vt8Id") failed: "Permission denied"
inotify_add_watch("/root") failed: "Permission denied"
(navigate $HOME)
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
(quit)
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Comment 7 Michael Heidelbach 2018-01-12 09:06:58 UTC
Previous comment was for
$ /usr/bin/dolphin --version
dolphin 17.12.0
--------
$ dolphin --version
dolphin 17.12.1
dolphin /tmp
Trying to convert empty KLocalizedString to QString.
org.kde.dolphin: Ignore KIO url: QUrl("timeline:/lastmonth")
org.kde.dolphin: Ignore KIO url: QUrl("timeline:/thismonth")
org.kde.dolphin: Ignore KIO url: QUrl("timeline:/yesterday")
org.kde.dolphin: Ignore KIO url: QUrl("timeline:/today")
org.kde.dolphin: Ignore KIO url: QUrl("search:/images")
org.kde.dolphin: Ignore KIO url: QUrl("search:/documents")
org.kde.dolphin: Ignore KIO url: QUrl("search:/videos")
org.kde.dolphin: Ignore KIO url: QUrl("search:/audio")
org.kde.dolphin: Ignore KIO url: QUrl("timeline:/lastmonth")
org.kde.dolphin: Ignore KIO url: QUrl("timeline:/thismonth")
org.kde.dolphin: Ignore KIO url: QUrl("timeline:/yesterday")
org.kde.dolphin: Ignore KIO url: QUrl("timeline:/today")
org.kde.dolphin: Ignore KIO url: QUrl("search:/images")
org.kde.dolphin: Ignore KIO url: QUrl("search:/documents")
org.kde.dolphin: Ignore KIO url: QUrl("search:/videos")
org.kde.dolphin: Ignore KIO url: QUrl("search:/audio")
qt.accessibility.core: Cannot create accessible child interface for object:  PlacesView(0x2beec50)  index:  18
inotify_add_watch("/lost+found") failed: "Permission denied"
inotify_add_watch("/tmp/systemd-private-0e95805ffca54249af9d1ff11c5639f8-rtkit-daemon.service-4vt8Id") failed: "Permission denied"
inotify_add_watch("/root") failed: "Permission denied"
(navigate $HOME)
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
inotify_add_watch("/home/jdownloader") failed: "Permission denied"
(quit)
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Comment 8 Michael Heidelbach 2018-01-14 12:10:42 UTC
Closing kate (17.12.0)
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Empty filename passed to function
Comment 9 null 2018-01-14 20:02:49 UTC
I have worked on fixes for plasma-framework and kinit, will post them for review in the next days. I think those will prevent the Plasma and startup related occurrences.

@Michael: I'm not sure why you still get the error in Dolphin and Kate after upgrading to KF 5.42. Did you relogin after your latest "zypper dup"? Does it also occur on a fresh user account without any custom settings?

Try setting a breakpoint on QMessageLogger::warning in gdb and obtain a backtrace, so we get an idea where it still fails for you. (Let me know if you need help with that.)
Comment 10 Michael Heidelbach 2018-01-15 11:07:54 UTC
Even after yesterdays update it is still
$ kded5 --version
kded5 5.41.0

I noticed an increasing tendency of opensuse to test before deployment :)
So let's wait a couple of days.
Comment 11 Michael Heidelbach 2018-01-15 11:16:40 UTC
(In reply to Henrik Fehlauer from comment #9)
> Try setting a breakpoint on QMessageLogger::warning in gdb and obtain a
> backtrace, so we get an idea where it still fails for you. (Let me know if
> you need help with that.)

Yes I do, definitely!
1) Do I need Qt sources for that? I only have the headers from *-devel packages.
2) I've never cared for backtraces. I can propably figure out how to produce them. But: Long time ago ( can't remember how) I disallowed coredumps. Please don't tell me I have to re-enable them.
Comment 12 null 2018-01-15 23:35:36 UTC
> Even after yesterdays update it is still [...] 5.41.0

Oops, in my comment I meant 5.41, not 5.42 – sorry for the confusion.

>> Let me know if you need help with that.
> Yes I do, definitely!

Great, I'll try to post a follow-along how I arrived at the Plasma fix and what you need to install for that on Tumbleweed. Until that is done, you could read a bit on Wikipedia and Stackoverflow about gdb, breakpoints and the difference between a coredump and a backtrace, because I'll probably not be able to explain all of those in detail in a comment on Bugzilla ;)
Comment 13 null 2018-01-19 00:39:45 UTC
Someone else already posted the patch for plasma-framework, not sure whether taking advantage of my analysis or not. That's what I get from helping others instead of cleaning up my own patches in time :(

> I'll try to post a follow-along how I arrived at the Plasma fix
Here we go:

1. Establish which binary we can attach gdb to: That required a bit of intuition, because the xorg-session.log does not provide the source a message is coming from (journald would be better in that regard, because it shows binary and PID, see https://bugs.kde.org/show_bug.cgi?id=388389#c0). Looking at the bugs, it became pretty obvious there where different sources the message came from (Dolphin and something Plasma related which could be triggered via RSIBreak or hovering over a custom panel entry).

For the next steps, let's focus on plasmashell, because we see the errors appearing in the output when starting a standalone plasmashell (after killing the original).

2. Think about what we are looking for: Essentially we need to find the source of the error message first, to be able to trace back where it was triggered in a second step, so that place can be fixed in the end. In comment 4 I already linked the commit adding the error message to Qt, but searching for "Empty filename passed to function" in qtbase is another way to lead us to https://code.woboq.org/qt5/qtbase/src/corelib/io/qfilesystemengine_unix.cpp.html#110 (code.woboq.org is an excellent site for interactively browsing through Qt and KDE sources, BTW).

Sadly, emptyFileEntryWarning_() is a very simple static function, meaning with the usual compiler optimizations enabled in a stock Qt build we cannot set a breakpoint on it. As a workaround, we can set a breakpoint on something inside this function (this took me quite a while to realize, haha), in this case QMessageLogger::warning. Note that now a breakpoint could be triggered more often, i.e. also when other functions issue a warning, which we would need to ignore then.

3. Get a backtrace with gdb:
- $ killall plasmashell
- $ gdb plasmashell
- $ run (or "r")
- ctrl-c to interrupt program flow
- $ break QMessageLogger::warning (or "b")
- $ continue (or "c")
- Move mouse over custom icon in panel, breakpoint should be hit.
- $ backtrace (or "bt")
- Verify that the warning was indeed triggered by something also appearing in qfilesystemengine_unix.cpp and thus belonging to emptyFileEntryWarning().
- Repeat continue + backtrace until we are at the right place.
- ctrl-d to stop the debugger

Note that at this point there are still some pieces missing in the backtrace, so we go to the next step to fix this.

4. Prepare debug symbols: On openSUSE, packages are split into multiple RPMs. The oss repo has the binaries and -devel packages (needed to run something and to be able to #include headers when developing, respectively). The debug repo has -debuginfo packages, those are important if you submit a backtrace to Bugzilla for example, giving you more complete backtraces. The debug repo also provides -debugsource packages, those contain the complete source code of functions, so you could step through every single line in a debugger and see where you are.

Note that those packages are for system provided binaries, if you execute code compiled by yourself you'd just have to make sure to compile in debug mode (you'd still need -debuginfo packages for libraries you use).

(For completeness: There is also the source repo containing .src.rpms, which include a .tar.gz of the upstream source and a spec file to build all of the other types of RPMs I mentioned from this, but that's not relevant here. If you are interested, use rpm2cpio and cpio to extract those RPMs and see what they contain.)

Here, we perform the following steps:
- Note the filename in the backtrace for lines you want to know more about.
- Install corresponding debuginfo package using one of the following methods (make sure to have the debug repo enabled):
  - rpm -qf /usr/lib64/libQt5Core.so.5 (to get the package name), zypper in /usr/lib64/libQt5Core.so.5
  - ctrl-shift-f search in your konsole history for the file to find complaints about the missing debuginfo, zypper install -C "debuginfo(build-id)=474186faf16585c4703a404a4fdc1bac4c03ea00"

Trigger the breakpoint again, now some of the "()" should be replaced by actual function names. Repeat for more packages as needed, e.g. plasma-framework-debuginfo.

Next, we want line numbers, so we need -debugsource packages. On openSUSE, for larger projects a single source RPM can be split into multiple binary/debuginfo RPMs. With "rpm -qi libQt5Core5" we get the name of the source RPM (libqt5-qtbase), so the package name would be "libqt5-qtbase-debugsource". As we are interested in fixing the lines concering plasma, we issue "zypper in plasma-framework-debugsource". Now we see the line number in the backtrace (svg.cpp:254 in my case).

5. Start hacking:
- $ git clone kde:plasma-framework
- $ $EDITOR plasma-framework/src/plasma/svg.cpp:254


Hope this makes some sense to you, feel free to post any follow-up questions you might have. I'd encourage you to try those steps for yourself with Dolphin, so we can determine why you are still getting those errors.
Comment 14 Dominik Haumann 2018-09-15 20:37:44 UTC
Git commit 88be459559448d9d30b33f33b3ffd31fc41327c7 by Dominik Haumann, on behalf of Henrik Fehlauer.
Committed on 15/09/2018 at 20:37.
Pushed by dhaumann into branch 'master'.

Lessen log spam by not checking for existence of file with empty name

Summary:
Calls to `QFile::exists()` while starting a Plasma session
resulted in `Empty filename passed to function` being logged
since Qt 5.10 (0dee566e98f5 in qtbase).

This can be avoided by skipping the check for empty filenames, which
would have returned `false` in any case. Similarly to what was done in
R241:549fc81e8e8a, also port to the faster `QFileInfo::exists()`.

Note this does not simply hide a deeper issue, i.e. the actual cause
resulting in the empty variable, because `libpath.isEmpty()` will be
handled explicitly later on. In the case under investigation
`/usr/lib64/libexec/org_kde_powerdevil` did not match
`/usr/lib64/libexec/kf5`, but even if it was in that subfolder there
would have been no corresponding `libkdeinit5_` anyway.

Test Plan:
Grep session log for "Empty filename passed to function" after
restarting the Plasma session and compare before/after.

Reviewers: #frameworks

Subscribers: dfaure, kde-frameworks-devel, dhaumann

Tags: #frameworks

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

M  +2    -1    src/kdeinit/kinit.cpp

https://commits.kde.org/kinit/88be459559448d9d30b33f33b3ffd31fc41327c7
Comment 15 David Faure 2019-06-23 08:18:10 UTC
Dominik: your commit fixes this bug, right? I'm closing it, please reopen if that was wrong.