Adapt and improve the debug logging system
Needs ReviewPublic

Authored by asensi on Jul 5 2018, 3:46 PM.

Details

Reviewers
None
Group Reviewers
Krusader
Summary

After Alex Bikadorov added a -d parameter that to Krusader, after reading what Jan Lepper wrote in https://bugs.kde.org/show_bug.cgi?id=281917#c7, and after reading the comments of "Bug 384653 - [zip kioslave] Journal spammed with “kf5.kio.core: error() called twice! Please fix the KIO slave”: The KrDebugLogger system was adapted and improved, and some related changes were made.

Two use cases:

a) Alice has made some changes in krarc.cpp, and because debugging a kioslave is difficult, at least she can execute:
export KDE_FORK_SLAVES=true; krusader -d
press the right arrow on an archive, and see in the command line that error messages appear before finishing kio_krarcProtocol::stat():

[...]
11:23:18.046-debug default unknown@0 # key event= QKeyEvent(KeyPress, Key_Right)
[...]
trying to load "/usr/lib/x86_64-linux-gnu/qt5/plugins/kio_krarc.so" from "/usr/lib/x86_64-linux-gnu/qt5/plugins/kio_krarc.so"
Pid:30112 ┏kio_krarcProtocol(147)
Pid:30112 ┗kio_krarcProtocol
Pid:30112 ┏stat(664)
Pid:30112     stat(665): /
Pid:30112     ┏setArcFile(877)
Pid:30112         setArcFile(878):
Pid:30112     ┗setArcFile
kf5.kio.core: error() called twice! Please fix the "" KIO slave
Pid:30112 ┗stat
Pid:30112 ┏stat(664)
Pid:30112     stat(665): /media
Pid:30112     ┏setArcFile(877)
Pid:30112         setArcFile(878): media
Pid:30112     ┗setArcFile
kf5.kio.core: error() called twice! Please fix the "" KIO slave
Pid:30112 ┗stat
[...]

With that information, Alice can add more code so that more messages are written in the trace log.

b) Bob has made changes to kiso.cpp, and he has inspected his code, but Bob wants to compare the working of the new code with the working of the old one. To help himself, he creates a trace log of a session working with the old code, and a trace log of a session working with the new code, and compares those trace logs:

$ # Note: To compare compare two trace logs: it's better not to write some data to the trace logs (because otherwise a lot of false positives would be seen)
$ export KRDEBUG_BRIEF=true
$
$ export KDE_FORK_SLAVES=true; krusader -d > traceNewCode.txt 2>&1
$ [...]
$ kompare traceNewCode.txt traceOldCode.txt


Finally, Bob sees that, using the new code, KIso::readParams() has not been used (but previously it was), and so Bob realizes that there's a problem.

Test Plan

With a Krusader that does not include the code of the present code review, execute:

export KDE_FORK_SLAVES=true; krusader -d

press the right arrow on an archive, and in the command line check that structured debug messages like

Pid:30112 ┏kio_krarcProtocol(147)
Pid:30112 ┗kio_krarcProtocol
Pid:30112 ┏stat(664)
Pid:30112     stat(665): /
Pid:30112     ┏setArcFile(877)
Pid:30112         setArcFile(878):
Pid:30112     ┗setArcFile

are *not* seen.

Build Krusader, execute sudo make install, etc. Execute:

export KDE_FORK_SLAVES=true; krusader -d

press the right arrow on an archive, and in the command line check that structured debug messages like

Pid:30112 ┏kio_krarcProtocol(147)
Pid:30112 ┗kio_krarcProtocol
Pid:30112 ┏stat(664)
Pid:30112     stat(665): /
Pid:30112     ┏setArcFile(877)
Pid:30112         setArcFile(878):
Pid:30112     ┗setArcFile

are seen, therefore showing a trace log.

Execute from the command line:

env KRDEBUG_BRIEF=true KDE_FORK_SLAVES=true krusader -d

press the right arrow on an archive, and see in the command line that structured debug messages like

┏kio_krarcProtocol
┗kio_krarcProtocol
┏stat
    stat: /
    ┏setArcFile
        setArcFile:
    ┗setArcFile

are seen, not showing information like process identifiers, consequently making trace logs more suitable to be compared with similar ones (for example the result of another experiment).

More advanced tests that I performed:

  • Add KRDEBUG lines and KRFUNC lines to the code of Krusader, and also to the code of the iso and krarc kioslaves, compile and execute Krusader, and watch what is written to the trace log. Create trace logs using env KRDEBUG_BRIEF=false KDE_FORK_SLAVES=true krusader -d and compare those trace logs, etc.

Diff Detail

Repository
R167 Krusader
Lint
Lint Skipped
Unit
Unit Tests Skipped
asensi requested review of this revision.Jul 5 2018, 3:46 PM
asensi created this revision.
asensi edited the summary of this revision. (Show Details)
asensi edited the summary of this revision. (Show Details)Jul 5 2018, 3:49 PM
asensi edited the summary of this revision. (Show Details)Jul 5 2018, 3:51 PM
asensi edited the test plan for this revision. (Show Details)
asensi edited the summary of this revision. (Show Details)
asensi edited the summary of this revision. (Show Details)Jul 5 2018, 3:54 PM
asensi edited the summary of this revision. (Show Details)Jul 5 2018, 3:57 PM
asensi edited the test plan for this revision. (Show Details)
asensi edited the summary of this revision. (Show Details)Jul 5 2018, 4:03 PM
nmel added a subscriber: nmel.Jul 8 2018, 6:16 AM

Toni, this sounds like a great change! Thanks for working on this!

Quick question: during testing we also need to install Krusader to a standard location, otherwise the app will load old kiso and krarc modules, correct?

I'll try to find some time to understand the change and the Krusader debug system soon.

asensi added a comment.Jul 8 2018, 8:37 PM

Thanks, Nikita. I'm not aware of a way to choose the kioslave modules that are going to be used, if it may help: to debug a kioslave what I did was using a virtual machine, where I was able to use the standard places for Krusader.

nmel added a comment.Jul 24 2018, 7:30 AM

Thanks, Nikita. I'm not aware of a way to choose the kioslave modules that are going to be used, if it may help: to debug a kioslave what I did was using a virtual machine, where I was able to use the standard places for Krusader.

I remember about this CR, however my VM is currently crashing on restore. I need to figure out what's wrong.

asensi updated this revision to Diff 82887.Thu, May 14, 10:53 PM
asensi retitled this revision from Adapt and improve the debug logging system. Some related changes to Adapt and improve the debug logging system.
asensi edited the summary of this revision. (Show Details)
asensi edited the test plan for this revision. (Show Details)

Adapted the proposal to the current code base, with minor improvements.

nmel added a comment.Thu, May 28, 7:46 AM

@asensi , would you like to rebase the change in your fork and create a pull request on GitLab? My VM is working now and it's a useful change - I could help to review and test it.