Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add hidden 'debug-detail' preference, to allow disabling packet dumps #1357

Open
wants to merge 4 commits into
base: main
Choose a base branch
from

Conversation

ferdnyc
Copy link
Member

@ferdnyc ferdnyc commented May 20, 2022

When attempting to debug GSConnect operations, I often find my journal overwhelmed by the massive contents of the packets being sent back and forth between the local system and my device, particularly the kdeconnect.contacts.request_vcards_by_uid, kdeconnect.sms.messages, and kdeconnect.contacts.response_uids_timestamps messages. When testing with a "real-world" device containing hundreds of contacts and an SMS history many hundreds of messages deep, the formatted dumps of the packet contents can be thousands of lines. And most of the time, the actual contents of the packet is of no interest to me.

So, this PR adds a hidden setting 'debug-detail' (only accessible via dconf-editor or the gsettings / dconf command-line tools) which controls whether packet dumps are included in the debug output from _readLoop() and sendPacket(). It defaults to true (the current behavior), but when set to false only the packet.type will be logged for each packet, not the entire contents.

Result? Journal messages that look like this:

May 20 19:32:37 org.gnome.Shell.Extensions.GSConnect[749788]: [/service/device.js:sendPacket:455]: SM-A536U1: "kdeconnect.systemvolume"
May 20 19:32:37 org.gnome.Shell.Extensions.GSConnect[749788]: [/service/device.js:_readLoop:344]: SM-A536U1: "kdeconnect.contacts.response_uids_timestamps"
May 20 19:32:37 org.gnome.Shell.Extensions.GSConnect[749788]: [/service/device.js:sendPacket:455]: SM-A536U1: "kdeconnect.contacts.request_vcards_by_uid"
May 20 19:32:38 org.gnome.Shell.Extensions.GSConnect[749788]: [/service/device.js:_readLoop:344]: SM-A536U1: "kdeconnect.sms.messages"
May 20 19:32:38 org.gnome.Shell.Extensions.GSConnect[749788]: [/service/plugins/sms.js:_handleDigest:229]: SM-A536U1: cache is not iterable
                                                              _handleDigest@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/service/plugins/sms.js:229:35
                                                              _handleMessages@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/service/plugins/sms.js:331:22
                                                              handlePacket@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/service/plugins/sms.js:199:22
                                                              handlePacket@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/service/device.js:421:25
                                                              _readLoop@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/service/device.js:345:22
                                                              async*setChannel@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/service/device.js:323:18
                                                              _onChannel@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/service/manager.js:225:20
                                                              channel@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/service/core.js:448:19
                                                              _onIncomingChannel@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/service/backends/lan.js:216:18
                                                              Async*@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/service/daemon.js:727:17
May 20 19:32:42 org.gnome.Shell.Extensions.GSConnect[749788]: [/service/backends/lan.js:accept:779]: "lan://192.168.12.109:1716 (731765a6-cd92-4e97-a71e-5635980db65b)"
May 20 19:32:42 org.gnome.Shell.Extensions.GSConnect[749788]: [/service/core.js:readPacket/</<:236]: SM-A536U1: End of stream
                                                              readPacket/</<@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/service/core.js:236:35
                                                              @/home/ferd/.local/share/gnome-shell/extensions/[email protected]/service/daemon.js:727:17
May 20 19:32:42 org.gnome.Shell.Extensions.GSConnect[749788]: [/service/backends/lan.js:close:820]: "lan://192.168.12.109:1716 (98ed0687-4772-49dd-91a3-f58afe4216eb)"
May 20 19:32:42 org.gnome.Shell.Extensions.GSConnect[749788]: [/service/device.js:_readLoop:344]: SM-A536U1: "kdeconnect.battery"
May 20 19:32:42 org.gnome.Shell.Extensions.GSConnect[749788]: [/service/device.js:sendPacket:455]: SM-A536U1: "kdeconnect.battery.request"
May 20 19:32:42 org.gnome.Shell.Extensions.GSConnect[749788]: [/service/device.js:sendPacket:455]: SM-A536U1: "kdeconnect.connectivity_report.request"
May 20 19:32:42 org.gnome.Shell.Extensions.GSConnect[749788]: [/service/device.js:sendPacket:455]: SM-A536U1: "kdeconnect.contacts.request_all_uids_timestamps"
May 20 19:32:42 org.gnome.Shell.Extensions.GSConnect[749788]: [/service/device.js:sendPacket:455]: SM-A536U1: "kdeconnect.mousepad.keyboardstate"
May 20 19:32:42 org.gnome.Shell.Extensions.GSConnect[749788]: [/service/device.js:sendPacket:455]: SM-A536U1: "kdeconnect.mpris.request"
May 20 19:32:42 org.gnome.Shell.Extensions.GSConnect[749788]: [/service/device.js:sendPacket:455]: SM-A536U1: "kdeconnect.mpris"
May 20 19:32:42 org.gnome.Shell.Extensions.GSConnect[749788]: [/service/device.js:sendPacket:455]: SM-A536U1: "kdeconnect.notification.request"
May 20 19:32:42 org.gnome.Shell.Extensions.GSConnect[749788]: [/service/device.js:_readLoop:344]: SM-A536U1: "kdeconnect.connectivity_report"

Which can be a hell of a lot easier to follow, at times when you don't need the packet contents.

@ferdnyc ferdnyc requested a review from andyholmes May 22, 2022 16:01
Comment on lines 341 to 344
debug(packet, this.name);
if (globalThis.debugDetail)
debug(packet, this.name);
else
debug(packet.type, this.name);
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this check would be better only done once (ie. swapping the callback when the setting changes), but this is good enough for now. It can always be changed later.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmm, that could be tricky because only those two debug calls should be abbreviated. I suppose I could add a separate debugging call that only those two functions use, which would either be the same callback as debug() (when details are enabled), or an abbreviating version (when they aren't). That makes sense, and it's easy enough. (Then I won't need to expose debugDetail via globalThis, either.)

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@andyholmes Sorted, hopefully, though the changes are significant enough that I wouldn't say no to a second look.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@andyholmes Whoops, hopefully you hadn't looked (again) yet, because the code wasn't done. (Forgot to save in VSCode. Argh.) Now it is.

@andyholmes
Copy link
Collaborator

Seems like a useful option. Go ahead and merge if you're ready, although since GSettings are tricky to change later if there's anything else we might want we could make this a "u" type bitmask of flags. Just a thought.

@ferdnyc
Copy link
Member Author

ferdnyc commented May 22, 2022

since GSettings are tricky to change later if there's anything else we might want we could make this a "u" type bitmask of flags. Just a thought.

Hmm. "u" is just an unsigned int, right? How would that work with dconf-editor or the command line tools, in terms of interface? Would you just have to work out the value of OPTION_A | OPTION_B | OPTION_D for yourself, and then use 11 for the settings value? I intended this to be a hidden setting, sure, but I'm not a sadist. 🤣

I _had_thought about defining debug contexts that could be activated/deactivated separately, so that (for instance) you could enable debugging just for one particular plugin or service. But,

  1. That would probably be best configured via a string (or array of strings). Particularly for future-proofing, because who's gonna assign bitmask values for all of the plugins? (Never mind actually using them.)
  2. By the time we get to that point, there's a strong argument for adopting an actual debugging library from Node or w/e, rather than ad-hocing it.
  3. The whole idea is probably massive overkill.

@daniellandau
Copy link
Member

If we want more flags, we can add more keys. The GNOME calculator app does actually make it super easy to get an integer by assigning bits one by one, but still not maybe a most user friendly option and definitely not something we want to find ourselves guiding users to do.

@ferdnyc
Copy link
Member Author

ferdnyc commented May 22, 2022

If we want more flags, we can add more keys. The GNOME calculator app does actually make it super easy to get an integer by assigning bits one by one, but still not maybe a most user friendly option and definitely not something we want to find ourselves guiding users to do.

Hes-right-you

src/service/__init__.js Outdated Show resolved Hide resolved
This settings (which defaults to 'true') controls whether packet
dumps are included in the debug output from _readLoop() and
sendPacket(). If it is set to 'false', only 'packet.type' will
be logged for each packet when debugging, not the entire contents.
@andyholmes
Copy link
Collaborator

LGTM, go ahead and merge when you're ready.

@andyholmes andyholmes added the needs review A contribution that needs code review label Aug 5, 2022
@andyholmes
Copy link
Collaborator

@ferdnyc was this one ready to merge (after rebasing)?

@andyholmes andyholmes added needs info An issue that needs more information and removed needs review A contribution that needs code review labels Oct 11, 2022
@github-actions github-actions bot added the conflicts Pull requests with merge conflicts that need to be resolved label Feb 20, 2024
Copy link

This pull request has conflicts, please resolve those so that the changes can be evaluated.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
conflicts Pull requests with merge conflicts that need to be resolved needs info An issue that needs more information
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

3 participants