Use logging instead of print by fox91 · Pull Request #142 · pySTEPS/pysteps · GitHub
Skip to content

Use logging instead of print - #142

Closed
fox91 wants to merge 1 commit into
pySTEPS:masterfrom
fox91:logging
Closed

fox91 wants to merge 1 commit into
pySTEPS:masterfrom
fox91:logging

Conversation

@fox91

@fox91 fox91 commented Mar 5, 2020

Copy link
Copy Markdown

This is the PR with the logging module implemented in the pysteps.nowcasts module.
if it seems okay I can proceed with the rest of the modules.

Fix #140 when is completed.

@fox91 fox91 changed the title Use logging instead of print, fix #140 Use logging instead of print, closes #140 Mar 5, 2020
@fox91 fox91 changed the title Use logging instead of print, closes #140 Use logging instead of print, fix #140 Mar 5, 2020
@fox91 fox91 changed the title Use logging instead of print, fix #140 Use logging instead of print Mar 5, 2020
@dnerini
dnerini requested review from aperezhortal and dnerini March 5, 2020 18:27
@codecov

codecov Bot commented Mar 5, 2020

Copy link
Copy Markdown

Comment thread pysteps/__init__.py
from . import verification as vf
from . import visualization as plt

logging.getLogger(__name__).addHandler(logging.NullHandler())

@aperezhortal aperezhortal Mar 6, 2020

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Maybe we can define the default handler set at INFO level to be equivalent to the print statement.
That is, no additional formatting. _logger.info(msg) equivalent to print(msg)

That will reduce the verbosity of the outputs.

We can add additional information (like time, level, etc) for the DEBUG level.

@dnerini dnerini Mar 7, 2020

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

I agree with @aperezhortal on this, we should try to mimic the current behaviour.

As a rule of thumb, we could also say that we use the INFO level for all print statements that are now unconditionally executed, while DEBUG can be used for those print statements that are currently conditional to a verbose argument or similar (e.g. the measure_time argument in the nowcast.steps() method).

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

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

I'm changing DEBUG to INFO in the next commit, thanks for the clarifications.

@aperezhortal aperezhortal left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Hi @fox91, thanks for the contribution! I really like the addition of the logging module.

I made a few comments about the changes implemented.

About the logging levels, DEBUG can be used to give information about details that are of interest for diagnosing purposes. While INFO to display information about the operation of a program (only high-level things that shows that the program operates normally).

Finally, what do you think if we can start with minimal formatting (especially for INFO levels):

[LEVEL] message

or just

message

Comment thread pysteps/__init__.py

logging.getLogger(__name__).addHandler(logging.NullHandler())

_LOGGER = logging.getLogger(__name__)

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

_LOGGER should be lowercase ("_logger"). Uppercase variables normally used for constants.

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

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

I'm following pylint suggestions but I'm probably wrong.
I'm changing to lowercase with the next commit.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Pylint expects that global variables should be uppercase. However, we try to follow a different naming convention.

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

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

Maybe this can be another issue but: why not implement a pylintrc file in the root of the project, add to travis and enforce all code to use it?
You mention Google’s python style guide: it give you a good start point with pylintrc.

Comment thread pysteps/__init__.py
if not rcparams.get("silent_import", False):
print("Pysteps configuration file found at: " + params_file
+ "\n")
_LOGGER.debug("Pysteps configuration file found at: %s", params_file)

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Here the logic could be:

If silent_import is True:
_logger.debug()
else:
_logger.info() # we want the behavior to be equivalent to print. This is important for runtime information.

If silent_import is True, the

if measure_time:
computation_time = time.time() - start_time
print(f"{computation_time:.2f} seconds.")
_LOGGER.debug("%.2f seconds.", computation_time)

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Better use INFO level here.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Or we could remove the measure_time argument and log the computation time at DEBUG level, what do you think?

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

That's a good point. But we should leave the keyword argument and add a deprecation warning to maintain backward compatibility (at least for a few releases).

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Agreed ;-)

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

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

So a warnings.warn with PendingDeprecationWarning for one versione, DeprecationWarning for the next versione and total remove with the third version?
Or is best to use a DeprecationWarning for the next two version and then remove?

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Good point. According to PEP-565:

  • PendingDeprecationWarning is hidden by default for all code.
  • DeprecationWarning is reported by default for code that runs directly in the __main__ module (as such code is considered relatively unlikely to have a dedicated test suite), but hidden by default for code in other modules.
  • FutureWarning is reported by default for all code. The intended audience is users of applications written in Python, rather than other Python developers

So, since we want to target the users, it seems that FutureWarning is the way to go.

Comment thread pysteps/nowcasts/sseps.py
)

print("Estimating nowcast parameters...", end="")
_LOGGER.debug("Estimating nowcast parameters...")

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

INFO level. This is indicating that the program is running correctly.

Comment thread pysteps/nowcasts/sseps.py

if measure_time:
print("%.2f seconds." % (time.time() - starttime))
_LOGGER.debug("%.2f seconds.", time.time() - starttime)

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

INFO level. This is indicating that the program is running correctly.

@@ -8,187 +8,215 @@

"""

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Maybe is a good idea to leave the examples untouched before merging the PR. In that way they show the default behavior of the library.

But this was very useful to see how the logging module worked. 👍 Perhaps, we can add a new short example showing how the logging module can be used.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

I also support the idea of a dedicated example script showing how to use the logging module.

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

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

Using the logging module instead of print you don't see any output in the console if you don't add the proper config inside the example.
I can revert the improvements (ex: main function) but at minimum I need to add the logging.basicConfig at the top of the examples.

@aperezhortal aperezhortal Mar 8, 2020

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

We can define a default configuration in the pysteps.__init__.py that prints the INFO messages by default and add a set_loglevel function to pysteps as in matplotlib.

This is an example using matplotlib's logging implementation that logs the info messages by default. I was thinking of something along those lines.

@fox91 fox91 Mar 8, 2020

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

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

About that there is an open issue: matplotlib/matplotlib#13264 and a PR: matplotlib/matplotlib#13275
Personally I dislike and I'm not sure it's a good way to do the work.

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

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

I have not found any other library that uses logging like matplotlib.
It's also true that I don't find any library that uses so many output messages like pySTEPS to be able to compare the code and evaluate how they implement the output during a normal run.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Although it is not the same as matplotlib, TensorFlow seems to implement a default handler and an interface to control the logging level.

https://github.com/tensorflow/tensorflow/blob/e5bf8de410005de06a7ff5393fafdf832ef1d4ad/tensorflow/python/platform/tf_logging.py#L93-L143

import logging
logger = tf.get_logger()
logger.setLevel(logging.ERROR)

# sphinx_gallery_thumbnail_number = 5


if __name__ == '__main__':

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Avoid using if name == 'main' if possible. The examples should run sequentially as a script.

This will be useful in the future if we use jupyter notebooks for the examples.

Comment thread pysteps/nowcasts/utils.py


def print_ar_params(PHI):
def log_ar_params(PHI):

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Just in case, in addition to the log_ar_params function, leave the print_ar_params for backward compatibility. We can inform to the users with a Deprecation Warning that this function will be removed in a future release.

Comment thread pysteps/nowcasts/utils.py


def print_corrcoefs(GAMMA):
def log_corrcoefs(GAMMA):

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Just in case, in addition to the log_corrcoefs function, leave the print_corrcoefs for backward compatibility. We can inform to the users with a Deprecation Warning that this function will be removed in a future release.

)

# sphinx_gallery_thumbnail_number = 5
logging.getLogger('matplotlib').setLevel(logging.WARNING)

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Just out of curiosity, do you know what happens if you remove this line? Does matplotlib clutters the output with debug messages?

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

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

In this specific example about a ten debug lines only related to internal matplotlib. Not too many but useless, so I preferred to hide them.

@dnerini dnerini left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

I am also really happy about the implementation of the logging module in pysteps, thank you @fox91 for this really nice contribution!

I don't have much to add on top of what @aperezhortal already mentioned. I would say that
now we mainly need to find out the right setup that we can use for all modules.

@dnerini dnerini added the enhancement New feature or request label Apr 14, 2020
@dnerini

dnerini commented May 1, 2020

Copy link
Copy Markdown
Member

Hi @fox91, do you plan to work on this PR again ? I think it would make an excellent contribution to pysteps!

@fox91

fox91 commented May 2, 2020

Copy link
Copy Markdown
Author

Hi @dnerini,
in the last period I have moved on to other projects.
In the meantime I came up with ideas on how to solve the problems highlighted by @aperezhortal.
I should be able to get back on this project in the coming weeks.

@dnerini

dnerini commented May 4, 2020

Copy link
Copy Markdown
Member

Very glad to hear that you'll be able to continue on this, @fox91, thanks a lot!

@dnerini dnerini added the help wanted Extra attention is needed label Oct 22, 2020
@dnerini

dnerini commented Jul 25, 2021

Copy link
Copy Markdown
Member

@dnerini dnerini closed this Jul 25, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

enhancement New feature or request help wanted Extra attention is needed

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Use logging instead of print

3 participants