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

Reduce log clutter #146

Open
emaxx-google opened this issue Aug 4, 2020 · 0 comments
Open

Reduce log clutter #146

emaxx-google opened this issue Aug 4, 2020 · 0 comments
Assignees

Comments

@emaxx-google
Copy link
Collaborator

Currently, around a half of a typical log line (from both the Smart Card Connector app and a typical smart card middleware app) is effectively non-informative clutter.

For example, from this log message:

[200804 10:20:00.00] [  1.234s] [<background page>.GoogleSmartCard.NaclModule<"nacl_module.nmf">.NaCl] [INFO] [syslog] 00000000 ../../src/src/ifdhandler.c:1961:init_driver() Driver version: 1.4.31

perhaps only the following is useful:

[200804 10:20:00.00] [  1.234s] [NaCl] [INFO] ifdhandler.c:1961:init_driver() Driver version: 1.4.31

The log clutter complicates troubleshooting and increases RAM usage (since some portion of logs is always aggregated).

@emaxx-google emaxx-google self-assigned this Aug 4, 2020
emaxx-google added a commit that referenced this issue Aug 4, 2020
Don't mention the background page in the JavaScript/NaCl log messages -
this information can be inferred from the absence of the HTML page URL.
Given that the majority of log messages come from the background page,
it makes sense to reduce the log clutter (and the RAM usage) by omitting
this part.

This change is part of the effort tracked by issue #146.
emaxx-google added a commit that referenced this issue Aug 6, 2020
Don't mention the background page in the JavaScript/NaCl log messages -
this information can be inferred from the absence of the HTML page URL.
Given that the majority of log messages come from the background page,
it makes sense to reduce the log clutter (and the RAM usage) by omitting
this part.

This change is part of the effort tracked by issue #146.
emaxx-google added a commit that referenced this issue Aug 10, 2020
Stop using the "GoogleSmartCard." prefix in all logger names by default,
since it causes log clutter. The problem that this prefix was solving -
avoiding conflicts with any third-party code that creates its own
loggers - seems to be pretty theoretical, especially now with the
knowledge that the existing developers of middleware extensions don't
really use the Closure Library a lot.

So this commit introduces a parameter that allows to disable this
prefixing, and default-initializes this parameter to "disabled".
Instruction in the example app's makefile describes how to enable the
prefixing back.

The only place where this prefixing is kept enabled is the
"example_js_standalone_smart_card_client_library", which is used across
a bigger variety of apps/extensions that we don't have detailed
knowledge about, so that it's better to be conservative there.

This change is part of the effort tracked by issue #146.
emaxx-google added a commit that referenced this issue Aug 13, 2020
Stop using the "GoogleSmartCard." prefix in all logger names by default,
since it causes log clutter. The problem that this prefix was solving -
avoiding conflicts with any third-party code that creates its own
loggers - seems to be pretty theoretical, especially now with the
knowledge that the existing developers of middleware extensions don't
really use the Closure Library a lot.

So this commit introduces a parameter that allows to disable this
prefixing, and default-initializes this parameter to "disabled".
Instruction in the example app's makefile describes how to enable the
prefixing back.

The only place where this prefixing is kept enabled is the
"example_js_standalone_smart_card_client_library", which is used across
a bigger variety of apps/extensions that we don't have detailed
knowledge about, so that it's better to be conservative there.

This change is part of the effort tracked by issue #146.
emaxx-google added a commit that referenced this issue Sep 30, 2020
Don't adding the '<"nacl_module.nmf">.NaCl' suffix to the logger name
used for NaCl-related log messages. This information about the URL of
the NaCl module is redundant - we don't use multiple NaCl modules
currently.

For the potential case when the detailed logging might be needed, a
boolean flag is kept in the code, allowing to revert to the old
behavior. Currently the flag is always set to false.

This change is part of the effort tracked by issue #146.
emaxx-google added a commit that referenced this issue Sep 30, 2020
Don't adding the '<"nacl_module.nmf">.NaCl' suffix to the logger name
used for NaCl-related log messages. This information about the URL of
the NaCl module is redundant - we don't use multiple NaCl modules
currently.

For the potential case when the detailed logging might be needed, a
boolean flag is kept in the code, allowing to revert to the old
behavior. Currently the flag is always set to false.

This change is part of the effort tracked by issue #146.
emaxx-google added a commit that referenced this issue Mar 31, 2021
Replace the "PC/SC-Lite client handler for ..." text in log messages
with just "PC/SC from ...". This makes the log messages shorter a bit
while preserving all information, which helps readability.

This contributes to the logging improvements tracked by #146.
emaxx-google added a commit that referenced this issue Mar 31, 2021
Stop printing relative times (like "[  0.007s]") in the JavaScript logs.
These times aren't really necessary now that we're printing absolute
times since #108, so it was just log clutter.

This change contributes to the logging improvements tracked
by #146.
emaxx-google added a commit that referenced this issue Apr 1, 2021
Delete the "[syslog]" prefix printed in every log message that's created
via the syslog() call. This prefix is not really useful - the original
idea was to visually disambiguate the logs printed by C++ code from the
logs emitted by third-party C code that uses syslog. In reality, there's
not much ambiguity there, so this prefix was just cluttering the logs.

This change contributes to the logging improvements tracked
by #146.
emaxx-google added a commit that referenced this issue Apr 1, 2021
Stop printing the "MultiString" word in front of multi-string variable
debug dumps, e.g. in the following dump:

  SCardListReaders: returning 0x00000000 ["Command successful."],
  mszReaders=MultiString["ReaderFoo 00 00"]

This prefix wasn't really useful, since it's anyway clear from the
context.

This change contributes to the logging improvements tracked
by #146.
emaxx-google added a commit that referenced this issue Apr 1, 2021
Replace the "PC/SC-Lite client handler for ..." text in log messages
with just "PC/SC from ...". This makes the log messages shorter a bit
while preserving all information, which helps readability.

This change contributes to the logging improvements tracked
by #146.
emaxx-google added a commit that referenced this issue Apr 1, 2021
Delete the "[syslog]" prefix printed in every log message that's created
via the syslog() call. This prefix is not really useful - the original
idea was to visually disambiguate the logs printed by C++ code from the
logs emitted by third-party C code that uses syslog. In reality, there's
not much ambiguity there, so this prefix was just cluttering the logs.

This change contributes to the logging improvements tracked
by #146.
emaxx-google added a commit that referenced this issue Apr 6, 2021
Stop printing structure names in PC/SC logs, in cases where the
type is already clear from the context. Also remove some unneeded
extra braces.

Example of changes:
* BEFORE: SCardListReaders: returning 0x00000000 ["Command successful."], mszReaders=MultiString["Foo 00 00"]
* AFTER: SCardListReaders: returning 0x00000000 ["Command successful."], mszReaders=["Foo 00 00"]
* BEFORE: SCardGetStatusChange(hContext=0x595DF1EC, dwTimeout=60000, rgReaderStates=0xFEB403D8([SCARD_READERSTATE(szReader="Foo 00 00", pvUserData=0x00000001, dwCurrentState=SCARD_STATE_CHANGED|SCARD_STATE_PRESENT|SCARD_STATE_INUSE)]))
* AFTER: SCardGetStatusChange(hContext=0x595DF1EC, dwTimeout=60000, rgReaderStates=0xFEB403D8[{szReader="Foo 00 00", pvUserData=0x00000001, dwCurrentState=SCARD_STATE_CHANGED|SCARD_STATE_PRESENT|SCARD_STATE_INUSE}])

This change contributes to the logging improvements tracked
by #146.
emaxx-google added a commit that referenced this issue Apr 6, 2021
Stop printing relative times (like "[ 0.007s]") in the JavaScript logs.
These times aren't really necessary now that we're printing absolute
times since #108.

The only remaining benefit of relative times was that they allowed
to distinguish logs from multiple instances in case they work
concurrently and their logs are squashed together. However, in
practice this was only relevant in a specific scenario (reading
Chrome OS system logs from a device that is locked and has the
NaCl-based smart card applications installed both in-session
and on the Login Screen). Assuming this a rare scenario that will
anyway disappear with the NaCl deprecation, it seems fine to
reduce the log clutter by removing the relative times.

This change contributes to the logging improvements tracked
by #146.
emaxx-google added a commit that referenced this issue Aug 24, 2022
Shorten some log messages printed by the JavaScript client-handler and
request-receiver code. Downgrade some of them to "info" or "fine" levels
to avoid spamming the log dumps with spurious errors and stop confusing
users who see "errors" displayed at chrome://extensions.

This commit contributes to the log clutter reduction tracked by #146.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

1 participant