Configurable log levels (e.g. for systems redirecting console to syslog)

[Behrooz Nobakht]

Thanks for this great tool!

Variety logs to /var/log/syslog which is a common log for many apps and services.
When variety is configured with a schedule of changing backgrounds, the amount of
logging in the syslog seems to be more of match for 'DEBUG' level logging. For example,
at every trigger, one can see a sequence of regular_change_thread(), prepare_thread(),
set_wallpaper(). They are indeed informative but not always necessary to be visible in
syslog.

Please allow the user to configure log levels of the application. Common practices
usually include TRACE, DEBUG, INFO, WARN, ERROR, and maybe CRITICAL. It can be argued
that all levels above INFO *must* always be logged into syslog but lower is depending
on the user configuration.

Thanks!

[James Lu (jlu5)]

Hi,

On Variety 0.6.3 on Debian Unstable, I don't see any syslog output for variety. Nor do I see an option to configure verbosity for syslog. Am I missing something?

[Behrooz Nobakht (nobeh)]

My setup is on GNOME 3.24 and Ubuntu 17.04.

I am able to see the following log lines in /var/log/syslog every 3 mins (which is my Variety preference set). Attached to this comment.

What I was able to figure out from source:

- `VarietyWindow.parse_options` defines a `verbose` parameter which is by default 1.
- Variety `__init__` reads the `verbose` flag and passes to `lib/helpers.set_up_logging`
- `Helpers.set_up_logging` uses `verbose` to set the logging level for the logger instance that obtained from `logging.getLogger()`. Note that only `addHandler` is used which seems to be why log messages also show up in syslog.

Now, if `verbose` could be also supported at `variety.conf` as well such that:

- verbose == 0 > ERROR
- verbose == 1 > INFO
- verbose == 2 > DEBUG

Then it might be a lot clearer log for tracing and trouble shooting as well. Default
is now 1 with INFO level.

Thanks.

[James Lu (jlu5)]

Actually, this looks like bug
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=773752

In short, gdm3 (GNOME's display manager) seems to redirect console
output for all programs it starts to syslog. Variety isn't directly
writing to syslog in this case; it's GNOME's that's filling it with
console clutter...

As a workaround, you can run these commands to drop messages from
programs you start (from
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=773752#29):
$ echo 'user.* stop' > /etc/rsyslog.d/drop-user-messages.conf
$ systemctl restart rsyslog.service

On 20/04/17 10:24 PM, Behrooz Nobakht wrote:
> My setup is on GNOME 3.24 and Ubuntu 17.04.
>
> I am able to see the following log lines in /var/log/syslog every 3 mins
> (which is my Variety preference set). Attached to this comment.
>
> What I was able to figure out from source:
>
> - `VarietyWindow.parse_options` defines a `verbose` parameter which is by default 1.
> - Variety `__init__` reads the `verbose` flag and passes to `lib/helpers.set_up_logging`
> - `Helpers.set_up_logging` uses `verbose` to set the logging level for the logger instance that obtained from `logging.getLogger()`. Note that only `addHandler` is used which seems to be why log messages also show up in syslog.
>
> Now, if `verbose` could be also supported at `variety.conf` as well such
> that:
>
> - verbose == 0 > ERROR
> - verbose == 1 > INFO
> - verbose == 2 > DEBUG
>
> Then it might be a lot clearer log for tracing and trouble shooting as well. Default
> is now 1 with INFO level.
>
> Thanks.
>
> ** Attachment added: "variety-syslog.log"
> https://bugs.launchpad.net/variety/+bug/1685003/+attachment/4865901/+files/variety-syslog.log
>

[Peter Levi (peterlevi)]

Great hunting job, James, thanks! I also hadn't been able to reproduce this same complaint before (there was a previous bugreport for the same that I can't find right now).

[James Lu (jlu5)]

Bumping the severity because this also affects ~/.xsession-errors on many desktops if Variety is configured to autostart.

[James Lu (jlu5)]

There were some bugs in the logging code such as verbosity being enabled by default; I went and fixed this in http://bazaar.launchpad.net/~variety/variety/trunk/revision/610

Specifically, the default setup without any -v arguments leaves stderr as warning and about only, while variety.log is kept at INFO.

The commit details:

- Fix options.verbose defaulting to 1 (equivalent of -v)
- Don't spam INFO to stderr unless at least one -v is given, as many systems forward this to ~/.xsession-errors and/or syslog
   - However, leave variety.log at INFO-level to aid us in debugging.
   - This fixes https://bugs.launchpad.net/variety/+bug/1685003
- Fix debug logging for VarietyWindow, ThumbsManager, and ThumbsWindow requiring -vvv or -vvvv to enable (decrease these by one)

[James Lu (jlu5)]

Clarification: the default setup *with that commit* and no -v arguments leaves stderr at log level warning and variety.log at INFO.

[Peter Levi (peterlevi)]

James, there was a deliberate reason for the default logging being verbose - a big part of the bugreports are useless without the log, and users often have issues running Variety in verbose mode. Basically the easier it is to make a useful bugreport, the better, and verbose-by-default strips one difficult step from the process, as the instructions can simply say - "go and take the variety.log file". Ideally we would be able to continue logging verbosely to variety.log, but reduce the loglevel that ends up in ~/.xsession-errors and various other system logs. Any idea if this is possible?

[Peter Levi (peterlevi)]

(To clarify: it used to be non-verbose by default, I deliberately made it this way at one point when I got tired of nagging bug reporters again and again "Please run in verbose mode and THEN attach the log")

[James Lu (jlu5)]

What you're saying is exactly what I did:

- Without -v, only variety.log logs verbosely (at loglevel INFO). The console output only displays warning messages and higher priority.
- With -v, both the console and variety.log are verbose at loglevel INFO.

Regarding making one logger more verbose than the other, this is possible (and how I implemented it) by calling setLevel on not just the root logger[1] but the individual handlers[2] as well.

[1]: https://docs.python.org/2/howto/logging.html#loggers
[2]: https://docs.python.org/2/howto/logging.html#handlers