Bug 384653 - [zip kioslave] Journal spammed with “kf5.kio.core: error() called twice! Please fix the KIO slave.”
Summary: [zip kioslave] Journal spammed with “kf5.kio.core: error() called twice! Plea...
Status: CONFIRMED
Alias: None
Product: krusader
Classification: Applications
Component: krarc (show other bugs)
Version: 2.6.0
Platform: Gentoo Packages Linux
: NOR minor
Target Milestone: ---
Assignee: Krusader Bugs Distribution List
URL:
Keywords: reproducible, triaged
Depends on:
Blocks:
 
Reported: 2017-09-13 08:52 UTC by Erik Quaeghebeur
Modified: 2019-06-23 08:16 UTC (History)
6 users (show)

See Also:
Latest Commit:
Version Fixed In:


Attachments
Excerpt from my system's journal showing the issue in context (18.97 KB, text/x-log)
2017-09-15 11:28 UTC, Erik Quaeghebeur
Details
dummy zip archive that can trigger the issue by browsing it (319 bytes, application/zip)
2017-10-09 06:23 UTC, Erik Quaeghebeur
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Erik Quaeghebeur 2017-09-13 08:52:45 UTC
My journal is spammed with a very large number of lines such as

kdeinit5[28739]: kf5.kio.core: error() called twice! Please fix the KIO slave.

I'm not aware whether there is any corresponding problem, but it would be nice to get this out of my journal.
Comment 1 Elvis Angelaccio 2017-09-15 10:58:40 UTC
That's just a warning from one of the ioslaves you are using. We need to know which one (sftp? smb? or something else?)
Comment 2 Erik Quaeghebeur 2017-09-15 11:26:43 UTC
(In reply to Elvis Angelaccio from comment #1)
> That's just a warning from one of the ioslaves you are using. We need to
> know which one (sftp? smb? or something else?)

How can I find out?

What I see in the journal preceding (same time up to the second) many, but not all runs of these messages is

plasmashell[1460]: QFileInfo::absolutePath: Constructed with empty filename

Also sometimes (same time up to the second):

kernel: EXT4-fs (sda4): warning: maximal mount count reached, running e2fsck is recommended

(I'll do an fsck, but it seems strange that this would really be related)

I'll attach a more extensive journal excerpt.
Comment 3 Erik Quaeghebeur 2017-09-15 11:28:00 UTC
Created attachment 107868 [details]
Excerpt from my system's journal showing the issue in context

After this run of messages, it starts again 13 seconds later.
Comment 4 Elvis Angelaccio 2017-09-15 12:09:14 UTC
Fair enough, I've made kio more verbose in the debug output: https://phabricator.kde.org/D7837
Comment 5 Elvis Angelaccio 2017-09-15 16:28:15 UTC
Next version of KIO will be more verbose.

In the meantime, you could run

    QT_MESSAGE_PATTERN="%{appname} - %{message}" kdeinit5

from a terminal. That should show you the name of the kioslaves before the "fix the KIO slave" message.
Comment 6 Erik Quaeghebeur 2017-09-27 14:02:34 UTC
(In reply to Elvis Angelaccio from comment #5)
> In the meantime, you could run
> 
>     QT_MESSAGE_PATTERN="%{appname} - %{message}" kdeinit5
> 
> from a terminal. That should show you the name of the kioslaves before the
> "fix the KIO slave" message.
Ok, I tried that, but it didn't seem to work; I got

 - error() called twice! Please fix the KIO slave.

So even less info than before.

However, by trial and error, I found out that the messages come whenever I go into a zip file as a directory (in Krusader, but also in Dolphin). So I guess it's the zip kioslave.
Comment 7 Elvis Angelaccio 2017-09-27 18:10:04 UTC
Thanks for the update.
Comment 8 Christoph Feck 2017-10-04 13:33:18 UTC
It could be caused by Krusader's krarc: slave. Can you check the URL bar of Dolphin if this is the case?
Comment 9 Erik Quaeghebeur 2017-10-04 15:06:19 UTC
(In reply to Christoph Feck from comment #8)
> It could be caused by Krusader's krarc: slave. Can you check the URL bar of
> Dolphin if this is the case?
Indeed. Both in Krusader and in Dolphin, the krarc kioslave is used. Krusader causes multiple "kf5.kio.core: error() called twice! Please fix the KIO slave"-messages, Dolphin just one or (perhaps) two.
Comment 10 Christoph Feck 2017-10-04 22:41:15 UTC
Reassigning to krarc developers.
Comment 11 Martin Kostolný 2017-10-08 20:26:18 UTC
I can see these errors in my past journal (june 2017). But I cannot replicate them anymore. I have Qt 5.9.1, KF 5.38, latest Krusader git.

@Erik, which steps exactly are required to trigger them? Or did you only browse  a zip archive and read some files? Ideally, could you also provide the archive that triggers the errors for you? And please provide your KF and Krusader version.

Thanks!
Comment 12 Erik Quaeghebeur 2017-10-08 20:48:27 UTC
(In reply to Martin Kostolný from comment #11)
> @Erik, which steps exactly are required to trigger them? Or did you only
> browse  a zip archive and read some files?

Yes, I only need to browse a zip file. Entering a directory was enough, no need to read a file. 

> Ideally, could you also provide the archive
> that triggers the errors for you?

I can't share the ones that I've used. I'll have to see whether I can create a dummy.

> And please provide your KF and Krusader version.
KF5.37.0, Krusader 2.6.0.

I'll see if I can test the latest Krusader git.
Comment 13 Erik Quaeghebeur 2017-10-09 06:23:55 UTC
Created attachment 108237 [details]
dummy zip archive that can trigger the issue by browsing it
Comment 14 Erik Quaeghebeur 2017-10-09 06:35:44 UTC
(In reply to Erik Quaeghebeur from comment #12)
> I'll see if I can test the latest Krusader git.
Using latest Krusader git does not fix the issue.
Comment 15 Martin Kostolný 2017-10-09 23:17:13 UTC
Thanks for test archive and info! Unfortunately I still cannot replicate the issue. I even downgraded KIO to version 5.37 but no KIO error showed up in journal. What distribution are you testing on?
Comment 16 Erik Quaeghebeur 2017-10-10 07:14:25 UTC
(In reply to Martin Kostolný from comment #15)
> What distribution are you testing on?
Gentoo, stable.
Comment 17 Martin Kostolný 2017-10-11 19:17:11 UTC
Thanks. That is unfortunately a distribution I currently don't have in my virtualbox. I have several though and tried with Kubuntu 16.10 which has older packages and didn't encounter the issue either. On my native system is Arch btw.

Just a really stupid thought :) - is it possible that you have krarc binaries installed twice in different locations in your system? Can you check in running processes that while browsing archive with krarc protocol, only one kio_krarc.so process is running?

Is there anybody else having these problems?
Comment 18 Erik Quaeghebeur 2017-10-11 20:23:45 UTC
(In reply to Martin Kostolný from comment #17)
> […] is it possible that you have krarc
> binaries installed twice in different locations in your system? Can you
> check in running processes that while browsing archive with krarc protocol,
> only one kio_krarc.so process is running?
Only one instance of krarc on-disk and only one krarc process running.
Comment 19 Nikita Melnichenko 2018-02-18 07:07:44 UTC
I'm using Gentoo and can't confirm the problem on v2.6.0. I tried my own zip files and well as provided by Erik. I'm on =kde-frameworks/kio-5.40.0-r3 now.

@Erik, could you provide exact step-by-step guide how to repro with details: what exactly you enter in which app and what log files you're looking at? Could your logging be set to use debug or near-debug level?
Comment 20 Erik Quaeghebeur 2018-02-18 15:55:08 UTC
(In reply to Nikita Melnichenko from comment #19)
> I'm using Gentoo and can't confirm the problem on v2.6.0. I tried my own zip
> files and well as provided by Erik. I'm on =kde-frameworks/kio-5.40.0-r3 now.

Thanks for chipping in. I'm also on 2.6.0/5.40 now. Things have not changed for me.

> @Erik, could you provide exact step-by-step guide how to repro with details:
> what exactly you enter in which app and what log files you're looking at?

Entering the zip file ‘as a directory’ in Krusader triggers it. So in the address bar I there have krarc:/home/path/to/file.zip/. There is nothing more to it, sorry. I'm looking at the systemd journal.

> Could your logging be set to use debug or near-debug level?

The log I provided is at debug level. There is nothing different now from then.

I understand that you can't do much if you cannot reproduce, but I don't know what further information to provide; w.r.t. krusader, my system is boringly stable and standard. Could it be a config issue? (Unlikely because it happens in both Krusader and Dolphin?) I tried it also with write support disabled, but the issue stays.
Comment 21 Nikita Melnichenko 2018-02-19 22:39:02 UTC
> I'm looking at the systemd journal
Well, I have OpenRC and I'm looking at /var/log/messages, however it should not make a difference. The syslog config does though. Could you share the settings?

> The log I provided is at debug level
Where did you specify that debug level should go to the journal?

> I tried it also with write support disabled, but the issue stays.
Didn't get this.

> I understand that you can't do much if you cannot reproduce
I'm not giving up yet. In contrast, I'm puzzled. :)


Can you try one more thing: run krusader from console and see if those messages output to console or not?
Comment 22 Erik Quaeghebeur 2018-02-20 11:18:29 UTC
(In reply to Nikita Melnichenko from comment #21)
> > I'm looking at the systemd journal
> Well, I have OpenRC and I'm looking at /var/log/messages, however it should
> not make a difference. The syslog config does though. Could you share the
> settings?
I do not know where to look. `locate syslog` does not return any file that seems to be configuration. I assume this is in some file not containing the word syslog. Which?

> > The log I provided is at debug level
> Where did you specify that debug level should go to the journal?
Well, I can specify the level using the ‘-p’ switch to journalctl. I have checked and the lines

kf5.kio.core: error() called twice! Please fix the KIO slave.

are at the ‘warning/4’ level and the lines such as

sep 15 10:09:31 hostname kdeinit5[3515]: "/home/equaeghe/patha/pathb/pathc/pathd/file.zip"
sep 15 10:09:31 hostname kdeinit5[3515]: "file.zip"
sep 15 10:09:31 hostname kdeinit5[3515]: arcType:  "zip"
sep 15 10:09:31 hostname kdeinit5[3515]: "unzip"
sep 15 10:09:31 hostname kdeinit5[3515]: "unzip"
sep 15 10:09:31 hostname kdeinit5[3515]: "unzip"
sep 15 10:09:31 hostname kdeinit5[3515]: "unzip"
sep 15 10:09:31 hostname kdeinit5[3515]: "zip"
sep 15 10:09:31 hostname kdeinit5[3515]: "zip"
sep 15 10:09:31 hostname kdeinit5[3515]: "7za"
sep 15 10:09:31 hostname kdeinit5[3515]: "7za"
sep 15 10:09:31 hostname kdeinit5[3515]: Encrypted:  false

are at the ‘debug/7’ level.

> > I tried it also with write support disabled, but the issue stays.
> Didn't get this.
I meant that when I disable write support in the Krusader configuration of karc, nothing changed to the behavior.

> Can you try one more thing: run krusader from console and see if those
> messages output to console or not?
They do not appear. I only see “Trying to convert empty KLocalizedString to QString.” in the console, which is probably completely unrelated.
Comment 23 Nikita Melnichenko 2018-02-23 07:55:42 UTC
@Erik, are you willing to compile git version, apply patches and test? There are 53 direct error() calls in krarc and who knows how many are hidden. It's hard to say if this function is really called twice or not. I can try to prepare some patches which will activate extensive debug output.

@Elvis, is there a way to redirect these type of messages from KIO to console? I need to sync my debug output with these messages somehow.
Comment 24 Erik Quaeghebeur 2018-02-23 09:03:41 UTC
(In reply to Nikita Melnichenko from comment #23)
> @Erik, are you willing to compile git version, apply patches and test?
That should be possible. I should be able to create a live ebuild from the kde-overlay one and specify the branch with the patches (using EGIT_BRANCH). That should be more convenient than separately applying the patches to the live ebuild (but that is also fine).
Comment 25 Elvis Angelaccio 2018-02-24 12:20:20 UTC
(In reply to Nikita Melnichenko from comment #23)
> @Elvis, is there a way to redirect these type of messages from KIO to
> console? I need to sync my debug output with these messages somehow.

Yes, run kdeinit5 from Konsole and you should see the debug output there.
Comment 26 Nikita Melnichenko 2018-02-25 04:14:25 UTC
Elvis, thanks a lot for the info! Now I'm able to repro the bug. Steps:
1. Run `kdeinit5` - it will launch in a background.
2. Run `krusader` in the same console and go visit a zip file. The output:

kf5.kio.core: Refilling KProtocolInfoFactory cache in the hope to find "mtp"
"/"
""
kf5.kio.core: error() called twice! Please fix the "" KIO slave
"/mnt"
"mnt"
kf5.kio.core: error() called twice! Please fix the "" KIO slave
"/mnt/data"
"data"
kf5.kio.core: error() called twice! Please fix the "" KIO slave
"/mnt/data/temp"
"temp"
kf5.kio.core: error() called twice! Please fix the "" KIO slave
"/mnt/data/temp/downloads"
"downloads"
kf5.kio.core: error() called twice! Please fix the "" KIO slave
"/mnt/data/temp/downloads/test.zip"
"test.zip"
arcType:  "zip"
"unzip"
"unzip"
"unzip"
"unzip"
"zip"
"zip"
"7za"
"7za"
Encrypted:  false
"/mnt/data/temp/downloads/test.zip"
"test.zip"
arcType:  "zip"
"unzip"
"unzip"
"unzip"
"unzip"
"zip"
"zip"
"7za"
"7za"
Encrypted:  false
0
""
"/mnt/data/temp/downloads/test.zip/"
"/mnt/data/temp/downloads/test.zip"
"test.zip"
arcType:  "zip"
"unzip"
"unzip"
"unzip"
"unzip"
"zip"
"zip"
"7za"
"7za"
Encrypted:  false
"/mnt/data/temp/downloads/test.zip"
Comment 27 David Faure 2019-06-23 08:16:17 UTC
Git commit 5e42e49d06e873157ec27657a1eed9067947935f by David Faure.
Committed on 23/06/2019 at 08:15.
Pushed by dfaure into branch 'master'.

Create a QCoreApplication in the kioslave.

This will at least fix the empty name in the warning that says
    Please fix the "" KIO slave

M  +3    -0    krArc/krarc.cpp

https://commits.kde.org/krusader/5e42e49d06e873157ec27657a1eed9067947935f