multiscreen logging

[David Kahles]

Hi,

Am Mittwoch, 27. Juli 2016 22:44:38 CEST schrieb Mark Gaiser:
> On Tue, Jul 26, 2016 at 3:09 PM, Mark Gaiser <markg85 at gmail.com> wrote:
>
>> On Tue, Jul 26, 2016 at 2:03 PM, Sebastian Kügler <sebas at kde.org> wrote:
>> 
>>> Hey,
>>> 
>>> [Please keep both lists addressed.]
>>> 
>>> Debugging multiscreen issues is a nightmare:
>>> 
>>> - there are at least 4 different processes involved (kded, kcmshell /
>>>   systemsettings, kscreen_backend_launcher and plasmashell)
>>> - some are critical during log in
>>> - they IPC with each other
>>> - especially the backend launcher's debug is really hard to get at
>>> 
>>> This means that:
>>> - it's hard (almost impossible) for users to get us good and useful logs
>>> - it's hard for ourselves to debug and find out what's exactly going on,
>>> especially when multiple components need to play in tune
>>> 
>>> Yesternight, after debugging the so-many-th issue, it occurred to me that
>>> we
>>> need to make this way easier to debug. Q(C)Debug falls short in that we
>>> get
>>> logs of individual components, if we're lucky. If we're really lucky, we
>>> get
>>> timestamps, so we can get a rough idea of what is going down when.
>>> 
>>> All of these problems can be solved with a relatively simple, shared log
>>> file.
>>> 
>>> So I'd like to switch most of (lib)kscreen's debug output to logging to a
>>> file. The files has then logs from multiple processes and will be much
>>> easier
>>> to go through.
>>> 
>>> API-wise, my main thing is having log messages and a bit of context, so
>>> it'd
>>> look like this:
>>> 
>>> Log::instance()->setContext("handling resume event");
>>> // ...
>>> Log::log("Enabled output" + output->name());
>>> 
>>> In the log, we'd then get
>>> 
>>> [TIMESTAMP] (kded: handling resume event) Enabled output eDP-1
>>> 
>>> 
>>> The key here is that we get a mostly correct sequence of things, that all
>>> the
>>> info is there right away, and that it's easier for the user to annotate
>>> the
>>> log ("Now plugging in my external display as HDMI-2").
>>> 
>>> The file is simple enough that even plasmashell could log to the file (at
>>> least until we've fixed the interaction between screen handling and
>>> plasmashell), so we get the full picture.
>>> 
>>> libkscreen[sebas/log] has a basic implementation. It's incomplete in the
>>> sense
>>> that it needs a bit of autotesting (just haven't gotten to it yet),
>>> review and
>>> then switching over the code-base. (For now it's on by 
>>> default, but can be
>>> disabled using a env var.)
>>> 
>>> I hope that this makes it much more straight-forward for us (and even
>>> users)
>>> to figure out where their multiscreen headaches are coming from, and that
>>> it
>>> gives us a one-stop shop (pretty much) to tell users what info we need to
>>> fix
>>> their bugs. ("Just send me the logfile in ~/.local/share/kscreen.log").
>>> 
>>> What do you think? If you like the idea, I'll polish up my 
>>> branch and will
>>> post it for review, so we can discuss the actual implementation.
>>> 
>>> Cheers,
>>> --
>>> sebas
>>> 
>>> http://www.kde.org | http://vizZzion.org
>>> _______________________________________________
>>> Plasma-devel mailing list
>>> Plasma-devel at kde.org
>>> https://mail.kde.org/mailman/listinfo/plasma-devel
>>> 
>> 
>> Hi,
>> 
>> Just a quick idea that might help you.
>> 
>> I'm not sure if the logging of those applications is already visible in
>> journalctl, but if it is then you can do something like this:
>> journalctl -u <unit> -u <another unit> -u <third one> -u <etc...> -f
>> 
>> -u would be the "units". Like plasmashell i guess.
>> -f means following the log (new entries appear on your screen).
>> 
>> Lastly, i would suggest to use a second pc independent of the one that
>> you're debugging. On that second machine just ssh into the one you're
>> debugging and execute the logging command from above.
>> 
>> This all obviously only works if you everything is already visible in
>> journalctl.
>> 
>> Good luck!
>> I hope this makes logging and debugging easier for you.
>> 
>> Cheers,
>> Mark
>> 
>
> This idea was not an option?
>
> It seems - to me, but i'm biased since i proposed it.. - like an idea with
> minimal effort and probably gets the job done, no?
>
>

I think the problem with this approach is, that most (or even all?) of
these processes aren't units but simple processes.
A better approach using the power of journald would be something like:

journalctl -b --user _COMM=plasmashell + _COMM=kded5 QT_CATEGORY=kscreen + 
                              _COMM=systemsettings5 + _COMM=kscreen_backend

which filters all logs based on the executable names, the current user
and the current boot. We can also search for specific qt logging categories
(e.g. we're searching for all kded5 logs in category "kscreen").

See "man 1 journalctl" and "man 7 systemd.journal-fields" for more 
information.
I think this is a simple and powerful solution, which doesn't require more 
code,
and doesn't have the race condition problems mentioned in the review 
request
for the new code.

Cheers,
David