Improve logging #316

dmfigol · 2019-01-20T21:15:49Z

Fix #302, #230

Better interoperability with native Python logging module
No more duplicate logs
Replace format and f-strings in logs to % strings according to best practices
Improve some logging messages
InitNornir configure_logging parameter is deprecated, replaced with config.logging.enabled

TODO:

Write a separate logging section in docs

dmfigol · 2019-01-20T21:23:14Z

There are two breaking changes:

Removed 'loggers' from the logging config
Renamed 'file' to 'file_path' in the logging config

dbarrosop · 2019-01-23T14:54:56Z

Makefile

@@ -34,7 +34,7 @@ pytest:
 .PHONY: black
 black:
 	${DOCKER_COMPOSE} \
-		run nornir black --check .


why these changes?

The current dockerfile is built in such a way that, it is mapping the whole project dir to the container, which causes the problems for my setup when I run tests... Decided to change to include directories explicitly when black should run.
I can change it back, but I'd strongly advocate to change volume mounting in docker-compose then.

if that's the case let's discuss it in a separate PR to avoid noise

dbarrosop · 2019-01-23T14:59:17Z

nornir/core/deserializer/configuration.py

        description="Logging format",
    )
    to_console: bool = Schema(
        default=False, description="Whether to log to console or not"
    )
-    loggers: List[str] = Schema(default=["nornir"], description="Loggers to configure")


I don't think it was a widely used feature but the idea was to allow users to enable debugging in paramiko/netmiko/others without having to change the code. How do you envision that being done now and why was it removed?

I remove it, because I didn't really understand what problem it solves. If you want to enable logging for other modules, you can do it with standard python logging (basicConfig, dictConfig or programmatically). I can put it back if you want, but I'd vote against it.

Well, the point is that a developer builds a tool, deploys it in a management server and then the neteng folks (or other people) consume that tool, which is installed in the $PATH and don't have access to modify it, how would you enable netmiko's debug then because something is not going as expected? You could have the developer bake it in into its own application, and that'd be a valid answer, however, if there isn't a good reason to remove it at this point (like introducing an insurmountable amount of complexity) I'd gate it until nornir 3.0.0.

You are saying that a neteng would change env var in this case? I don't think it will work for lists (may be I wrong here). Or you are saying that a neteng would need to change config.yaml? If that is the case, how different it is from changing the logging setup in the entrypoint script, if both config.yaml and the application code will be in VCS?
I do think you are onto something here and may be it is a valid use-case, however it needs to be described in our docs, because until you told it, I didn't even think about it.

dbarrosop · 2019-01-23T15:08:14Z

nornir/core/deserializer/configuration.py

    format: str = Schema(
-        default="%(asctime)s - %(name)12s - %(levelname)8s - %(funcName)10s() - %(message)s",
+        default="[%(asctime)s] %(levelname)-8s {%(name)s:%(lineno)d} %(message)s",


breaking change, might break people's logging system

How is it breaking? It's just the format of logs.

dbarrosop · 2019-01-23T15:09:38Z

Replace format and f-strings in logs to % strings according to best practices

which best practices? Mostly want to look at them to remove my f-string comments or not :)

There is a third breaking change, which is the format of the log.

dbarrosop · 2019-01-23T15:10:46Z

I am a bit concerned about this PR introducing so many breaking changes. I think we need to either have very good reasons for them, revert them or delay this to 3.0.0.

@ktbyers thoughts?

dbarrosop · 2019-01-23T15:17:40Z

Ok, read a bit more about it and looks like the "recommended" method is just because it's a lazy evaluator for the string. I don't think we should be concerned about that as that's going to save us 0.0000000001us of execution time and I'd rather have readable strings but to avoid bikeshedding I will let ktbyers chime in and break the tie :)

P.S: Removing the f-string comments for the sake of brevity

ktbyers · 2019-01-23T18:30:46Z

I vote f-strings versus the % strings.

I also vote if they are backwards incompatible that we defer until Nornir 3.0 (or maybe some way to specify new-logging format in Nornir-config that then becomes the default in Nornir 3.0)? Disclaimer: I have mostly been out of the loop on this and only loosely following it.

dmfigol · 2019-01-23T22:30:37Z

Those are not really % strings as % strings are interpolated at declaration time, the syntax is "%s", var (difference: comma). f-strings in logs are not "best practice" and both pylint and pycharm will yell at you unless suppressed. But I also agree that they increase readability so I guess I will change it if my opinion didn't get consensus ;)

I am honestly not sure about "breaking changes" and 3.0:

file -> file_path, we can add warning to "file" being set to something other nornir.log, still use it, but file_path would take precedence
We can add "loggers" back, but honestly I think they are useless. We could add a warning that they are not used anymore. We could make them work back. My take in general is that it is not nornir's job to touch logging. So if we are touching it already, the impact should be minimum. Built-in Python logging module is very powerful.
I don't consider new logging format a breaking change at all.

ktbyers · 2019-01-23T23:06:44Z

Okay, so it really just arguments that are passed to the logging subsystem.

Here is more discussion on pylint doing this (which wasn't very well received):

pylint-dev/pylint#1788

Looks like we can just disable that warning in Pylint.

dbarrosop · 2019-01-24T09:49:26Z

file -> file_path

Why that change? file is not masking any actual global variable.

so I guess I will change it if my opinion didn't get consensus

I still think readability wins over this supposedly perf improvement, specially when the perf improvements is going to be measured in microseconds while nornir's application are mostly going to be bound by IO and measured in ms. So whatever kirk says as he is the one breaking the tie :)

but honestly I think they are useless

I already commented on the reasoning, and I am fine deprecating it in nornir 3 if we decide the benefits don't overweight the complexity but without a very good reason we shouldn't introduce breaking changes as per semver rules

My take in general is that it is not nornir's job to touch logging

I agree, notice it's not nornir who is doing that, it's InitNornir, which is a convenient entrypoint to the framework for people that want convenience. If you want full control you can implement your own InitNornir and instantiate the objects yourself.

I don't consider new logging format a breaking change at all.

For people sending logs to a logging system and parsing the logs to build dashboards it's going to be breaking change.

dbarrosop · 2019-01-24T09:53:22Z

requirements.txt

@@ -7,4 +7,4 @@ future
 requests
 ruamel.yaml
 mypy_extensions
-pydantic
+pydantic==0.16.1


don't forget to rebase as new develop uses poetry :)

dmfigol · 2019-01-24T14:15:52Z

Why that change? file is not masking any actual global variable.

To make it clear that it is not filename it is a path. I will return it back.

I agree, notice it's not nornir who is doing that, it's InitNornir, which is a convenient entrypoint to the framework for people that want convenience. If you want full control you can implement your own InitNornir and instantiate the objects yourself.

We have every single example with InitNornir, we don't even discuss (by discuss I mean docs) the possibility of creating Nornir objects using some other mechanism.

For people sending logs to a logging system and parsing the logs to build dashboards it's going to be breaking change.

The current setup does not add Syslog handler at all... Do you want me to remove it back anyway?
I guess for my projects I will always do logging.enabled = False.

Something that I didn't see in your comments so far. Could you please go through 4 conditions when nornir logging is not configured and confirm that they are all right? I think first two completely make sense, but for the last two where I decide based on the root logger config there can be some disagreement.

dbarrosop · 2019-01-26T10:25:28Z

Could you please go through 4 conditions when nornir logging is not configured and confirm that they are all right?

Yeah, sorry, I was meant to comment on that and lost my train of thought. I don't want to add any logic here. I don't want to have to document under which circumstances the logging subsystem is configured automagically or have to answer support questions about that. So let's recover the old InitNornir flag and let the user decide instead, please. It's also a breaking change.

dmfigol · 2019-01-26T13:40:26Z

So let's recover the old InitNornir flag and let the user decide instead, please. It's also a breaking change.

I can find a way to convert it to a non-breaking change

I don't want to add any logic here. I don't want to have to document under which circumstances the logging subsystem is configured automagically or have to answer support questions about that

If I remove that, what does this PR solve? One of my problems with nornir is that if you do Python logging (using basicConfig or dictConfig) and you don't disable nornir logging, the result will be a mess. It is not documented properly either. One of the things this PR solves is that if you do that, it will not result in a mess.

dbarrosop · 2019-01-28T11:54:14Z

If I remove that, what does this PR solve?

My understanding is that, besides the breaking changes, you are doing some general cleaning and improvements as well. For instance, getting rid of the duplicates.

if you do Python logging (using basicConfig or dictConfig) and you don't disable nornir logging, the result will be a mess

I don't see that as a problem. You have the option today of using either way, we are not forcing anyone to use nornir's logging helper function.

It is not documented properly either

If it's not properly documented let's fix that.

One of the things this PR solves is that if you do that, it will not result in a mess

In general, instead of taking arbitrary decisions (which the user may or may not want), I'd suggest logging warning.

bradh11 · 2019-02-11T22:52:25Z

Does this PR also address the duplicate log entries in the logfile that are poduced??

dmfigol · 2019-02-11T22:53:50Z

@bradh11 yes

dbarrosop · 2019-02-17T10:56:47Z

@dmfigol let us know when this is ready for review again. If we get this one sorted out this week I will release 2.1.

dmfigol · 2019-02-26T00:10:03Z

@dmfigol @ktbyers this is ready for review

dbarrosop · 2019-02-28T09:35:16Z

I will try to find some time during the weekend. Thanks for the work :)

dbarrosop · 2019-03-03T11:53:01Z

docs/howto/handling_connections.ipynb

@@ -73,34 +73,9 @@
  },


did this break?

nornir/core/deserializer/configuration.py

dbarrosop · 2019-03-03T12:01:02Z

Ok, this looks awesome to me. The only comment is related to the notebook that seems to have lost the output. Can you confirm that's expected? Feels broken to me. Once we clear that out I will merge this :)

Awesome work.

Fix nornir-automation#302, nornir-automation#230 * Nornir logging is configured only when no changes have been done to Python logging * No more duplicate logs * Replace format and f-strings in logs to % strings according to best practices * Improved messages for some logs

* Add .ipynb_checkpoints to sphinx ignored list * Run black and pylama on specific folders * Pin pydantic until 0.19.0 is released pydantic/pydantic#254

dmfigol · 2019-03-05T14:32:14Z

@dbarrosop
I've rebased and fixed the notebook. You were right, for some reason this notebook didn't have an output and was not checked by nbval. I've stumbled upon an issue with \r\n and \n, which I didn't find the root cause for, so I had to use nbval sanitization, to make sure that \r\n is converted to \n everywhere.

dbarrosop · 2019-03-06T09:53:38Z

so I had to use nbval sanitization

Good catch :)

dmfigol mentioned this pull request Jan 21, 2019

Duplicate output in nornir.log file #302

Closed

dbarrosop reviewed Jan 23, 2019

View reviewed changes

dbarrosop reviewed Jan 24, 2019

View reviewed changes

dmfigol force-pushed the improve-logging branch from c59a927 to 52b7cd4 Compare February 25, 2019 23:59

dbarrosop reviewed Mar 3, 2019

View reviewed changes

docs/howto/handling_connections.ipynb Outdated

@@ -73,34 +73,9 @@

},

Copy link

Contributor

dbarrosop Mar 3, 2019

Choose a reason for hiding this comment

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

did this break?

dbarrosop reviewed Mar 3, 2019

View reviewed changes

nornir/core/deserializer/configuration.py Show resolved Hide resolved

dmfigol added 4 commits March 5, 2019 15:01

Fix build errors

ed940cd

* Add .ipynb_checkpoints to sphinx ignored list * Run black and pylama on specific folders * Pin pydantic until 0.19.0 is released pydantic/pydantic#254

Add backwards compatibility and address comments

a5c7f7b

Fix handling_connections notebook validation

67f44db

Add nbval sanitization to Makefile

594e335

dmfigol force-pushed the improve-logging branch from 52b7cd4 to 594e335 Compare March 5, 2019 14:17

dbarrosop merged commit 344fa4e into nornir-automation:develop Mar 6, 2019

dmfigol mentioned this pull request Mar 7, 2019

Nornir is hijacking logger #230

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Improve logging #316

Improve logging #316

dmfigol commented Jan 20, 2019 •

edited

Loading

dmfigol commented Jan 20, 2019

dbarrosop Jan 23, 2019

dmfigol Jan 23, 2019

dbarrosop Jan 24, 2019

dbarrosop Jan 23, 2019 •

edited

Loading

dmfigol Jan 23, 2019

dbarrosop Jan 24, 2019

dmfigol Jan 24, 2019

dbarrosop Jan 23, 2019

dmfigol Jan 23, 2019

dbarrosop commented Jan 23, 2019 •

edited

Loading

dbarrosop commented Jan 23, 2019

dbarrosop commented Jan 23, 2019 •

edited

Loading

ktbyers commented Jan 23, 2019

dmfigol commented Jan 23, 2019 •

edited

Loading

ktbyers commented Jan 23, 2019 •

edited

Loading

dbarrosop commented Jan 24, 2019

dbarrosop Jan 24, 2019

dmfigol commented Jan 24, 2019

dbarrosop commented Jan 26, 2019 •

edited

Loading

dmfigol commented Jan 26, 2019 •

edited

Loading

dbarrosop commented Jan 28, 2019

bradh11 commented Feb 11, 2019

dmfigol commented Feb 11, 2019

dbarrosop commented Feb 17, 2019

dmfigol commented Feb 26, 2019

dbarrosop commented Feb 28, 2019

dbarrosop Mar 3, 2019

dbarrosop commented Mar 3, 2019

dmfigol commented Mar 5, 2019

dbarrosop commented Mar 6, 2019

Improve logging #316

Improve logging #316

Conversation

dmfigol commented Jan 20, 2019 • edited Loading

dmfigol commented Jan 20, 2019

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dbarrosop Jan 23, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dbarrosop commented Jan 23, 2019 • edited Loading

dbarrosop commented Jan 23, 2019

dbarrosop commented Jan 23, 2019 • edited Loading

ktbyers commented Jan 23, 2019

dmfigol commented Jan 23, 2019 • edited Loading

ktbyers commented Jan 23, 2019 • edited Loading

dbarrosop commented Jan 24, 2019

Choose a reason for hiding this comment

dmfigol commented Jan 24, 2019

dbarrosop commented Jan 26, 2019 • edited Loading

dmfigol commented Jan 26, 2019 • edited Loading

dbarrosop commented Jan 28, 2019

bradh11 commented Feb 11, 2019

dmfigol commented Feb 11, 2019

dbarrosop commented Feb 17, 2019

dmfigol commented Feb 26, 2019

dbarrosop commented Feb 28, 2019

Choose a reason for hiding this comment

dbarrosop commented Mar 3, 2019

dmfigol commented Mar 5, 2019

dbarrosop commented Mar 6, 2019

dmfigol commented Jan 20, 2019 •

edited

Loading

dbarrosop Jan 23, 2019 •

edited

Loading

dbarrosop commented Jan 23, 2019 •

edited

Loading

dbarrosop commented Jan 23, 2019 •

edited

Loading

dmfigol commented Jan 23, 2019 •

edited

Loading

ktbyers commented Jan 23, 2019 •

edited

Loading

dbarrosop commented Jan 26, 2019 •

edited

Loading

dmfigol commented Jan 26, 2019 •

edited

Loading