improve logging for kscreen
ClosedPublic

Authored by sebas on Jul 27 2016, 2:36 AM.

Details

Summary

Debugging kscreen is generally really hard since it's spread across different
processes, not all of which are easy to look into.

With this change, we collect all of kscreen's debug output (from kcm, kded
and backendlauncher) and write them to a log file.

This means that we can look into one log file, and see exactly what's going
on, and in which component. It makes collecting debug info much easier.

This is implemented in the form of a QMessageHandler, hooking into the
qCDebug calls. This is a pretty neat solution, since:

  • we can make use of the stream operators from qDebug
  • we don't need to rewrite all the debug statements
  • normal debug is otherwise still working

The general idea is that we cache file names and initialization from the
env vars on first creation, allow subsequent context changes. The log file
is opened and closed right away, since other processes may want to also
write to it.

We don't do any file-locking to keep things simple. The logging isn't
mission-critical, but rather a debugging tool for users. If we end up
with corrupt logs, that's bad luck (but can happen due to multi-process
race conditions). More advanced multi-process locking and delayed
writing is just going to give us headaches, so we avoid that at the
price of logs not being 100% reliably formatted.

Also:

  • disable logging for most autotests
  • all messages are then passed to the previously installed messagehandler.
Test Plan

new code comes with autotests

Diff Detail

Repository
R110 KScreen Library
Lint
Automatic diff as part of commit; lint not applicable.
Unit
Automatic diff as part of commit; unit tests not applicable.
sebas updated this revision to Diff 5513.Jul 27 2016, 2:36 AM
sebas retitled this revision from to improve logging for kscreen.
sebas updated this object.
sebas edited the test plan for this revision. (Show Details)
sebas added a reviewer: Plasma.
Restricted Application added a project: Plasma. · View Herald TranscriptJul 27 2016, 2:36 AM
Restricted Application added a subscriber: plasma-devel. · View Herald Transcript
sebas updated this revision to Diff 5514.Jul 27 2016, 2:41 AM
  • Fix copyright
bshah accepted this revision.Jul 28 2016, 10:43 AM
bshah added a reviewer: bshah.
bshah added a subscriber: bshah.
bshah added inline comments.
autotests/testlog.cpp
88

nitpick - cAPs. ;-)

This revision is now accepted and ready to land.Jul 28 2016, 10:43 AM
davidedmundson added inline comments.
src/log.cpp
31 ↗(On Diff #5538)

why have it separate instead of a member of log?

36 ↗(On Diff #5538)

QLatin1String.

47 ↗(On Diff #5538)

Question:
What's the threading policy on libkscreen?

This isn't reentrant (which might be fine)

72 ↗(On Diff #5538)

you probably want to manually force the logging category to enable itself if this env var is set.

or get rid of this env var, and just check if the logging category is enabled.

137 ↗(On Diff #5538)

why call instance() from inside a member function?
it'll always return this.

138 ↗(On Diff #5538)

You're going to need a file lock round this aren't you?
The entire point is that two processes will be writing in here at the same time.

sebas added inline comments.Jul 28 2016, 10:49 AM
autotests/testlog.cpp
88

It's a test, this way it covers strange capitalization. :)

src/log.cpp
47 ↗(On Diff #5538)

No threads in libkscreen. It'll probably blow up in many other cases already.

72 ↗(On Diff #5538)

Good point. I'll check if it's needed (I was kind of assuming that the policy checks are handled in the default handler, so we're not even bothered.)

138 ↗(On Diff #5538)

It's actually complexity I want to avoid. If the logs are messed up, bad luck, but introducing wait locks and the likes brings in so much complexity, I think it's better to avoid here until it becomes a problem.

src/log.cpp
47 ↗(On Diff #5538)

It doesn't matter if there are threads *in* kscreen.

The question is: Can a kscreen class be used *in* another thread by $app.

138 ↗(On Diff #5538)

It's one QLockFile line...

src/log.cpp
138 ↗(On Diff #5538)

Edit: Some googling suggests this is fine as-is.

O_APPEND writes are atomic on local filesystems, and will lock between updating the offset and the end of the write.

Providing Qt does everything as one write() which it probably will for lines less than ~512bytes or so.

sebas added inline comments.Jul 28 2016, 12:19 PM
src/log.cpp
47 ↗(On Diff #5538)

That's what I meant, it's not designed to be thread-safe at all. The backends have static members, too, so this pattern isn't exclusive to this class at all.

138 ↗(On Diff #5538)

Cool. Thanks for checking this.

sebas added inline comments.Jul 28 2016, 12:53 PM
src/log.cpp
31 ↗(On Diff #5538)

I just tried making it a member, but running into problems.

QtMessageHandler is a typedef'ed function pointer, not a class. If I add a static member in my Log class for it, it screws up my header.

I think we need to keep this as is (which arguably is nicer, anyway, since it keeps QtMessageHandler outside of the header, and thus the API.

sebas updated this revision to Diff 5538.Jul 28 2016, 1:23 PM
sebas marked 2 inline comments as done.
sebas edited edge metadata.
  • Address comments from David's review
sebas added inline comments.Jul 28 2016, 1:30 PM
src/log.cpp
137 ↗(On Diff #5538)

Log::log(...) is static.

This revision was automatically updated to reflect the committed changes.
sebas marked an inline comment as done.