Use logging instead of print #142

fox91 · 2020-03-05T17:52:54Z

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.

codecov · 2020-03-05T18:40:24Z

Codecov Report

Merging #142 into master will decrease coverage by 0.49%.
The diff coverage is n/a.

@@            Coverage Diff             @@
##           master     #142      +/-   ##
==========================================
- Coverage   72.40%   71.90%   -0.50%     
==========================================
  Files          98       98              
  Lines        7809     7828      +19     
==========================================
- Hits         5654     5629      -25     
- Misses       2155     2199      +44

Impacted Files	Coverage Δ
pysteps/nowcasts/utils.py	`34.42% <0.00%> (-65.58%)`	⬇️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update dce3b8e...d533203. Read the comment docs.

aperezhortal · 2020-03-06T20:32:34Z

pysteps/__init__.py

@@ -21,6 +21,10 @@
 from . import verification as vf
 from . import visualization as plt

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


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.

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).

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

aperezhortal

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

aperezhortal · 2020-03-06T20:33:30Z

pysteps/__init__.py

@@ -21,6 +21,10 @@
 from . import verification as vf
 from . import visualization as plt

+logging.getLogger(__name__).addHandler(logging.NullHandler())
+
+_LOGGER = logging.getLogger(__name__)


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

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

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

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.

aperezhortal · 2020-03-06T20:37:10Z

pysteps/__init__.py

@@ -149,8 +153,7 @@ def __getitem__(self, key):
        rcparams = json.loads(jsmin(f.read()))

    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)


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

aperezhortal · 2020-03-06T20:38:00Z

pysteps/nowcasts/extrapolation.py

@@ -79,7 +81,7 @@ def forecast(precip, velocity, num_timesteps,

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


Better use INFO level here.

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

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).

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?

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.

aperezhortal · 2020-03-06T20:39:32Z

pysteps/nowcasts/sseps.py

@@ -346,7 +349,7 @@ def forecast(
        }
    )

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


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

aperezhortal · 2020-03-06T20:39:46Z

pysteps/nowcasts/sseps.py

@@ -516,9 +519,9 @@ def estimator(R, parsglob=None, idxm=None, idxn=None):
        pars = None

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


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

aperezhortal · 2020-03-06T20:45:16Z

examples/plot_steps_nowcast.py

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

 """


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.

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

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.

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.

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.

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.

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)

aperezhortal · 2020-03-06T20:46:32Z

examples/plot_steps_nowcast.py

+    # sphinx_gallery_thumbnail_number = 5
+
+
+if __name__ == '__main__':


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.

aperezhortal · 2020-03-06T20:48:47Z

pysteps/nowcasts/utils.py


-def print_ar_params(PHI):
+def log_ar_params(PHI):


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.

aperezhortal · 2020-03-06T20:49:57Z

pysteps/nowcasts/utils.py



-def print_corrcoefs(GAMMA):
+def log_corrcoefs(GAMMA):


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.

aperezhortal · 2020-03-06T20:52:19Z

examples/plot_steps_nowcast.py


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


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

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

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 · 2020-05-01T16:26:08Z

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

fox91 · 2020-05-02T08:10:21Z

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 · 2020-05-04T11:08:19Z

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

dnerini · 2021-07-25T13:51:06Z

Im eventually closing this PR as stale, but the linked issue (#140) has been included to the pystepsV2 project.

Setup logging into nowcasts module

d533203

fox91 changed the title ~~Use logging instead of print, fix #140~~ Use logging instead of print, closes #140 Mar 5, 2020

fox91 changed the title ~~Use logging instead of print, closes #140~~ Use logging instead of print, fix #140 Mar 5, 2020

fox91 changed the title ~~Use logging instead of print, fix #140~~ Use logging instead of print Mar 5, 2020

dnerini requested review from aperezhortal and dnerini March 5, 2020 18:27

aperezhortal reviewed Mar 6, 2020

View reviewed changes

aperezhortal requested changes Mar 6, 2020

View reviewed changes

dnerini requested changes Mar 7, 2020

View reviewed changes

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

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

dnerini added this to To do in pysteps-v2 Jul 24, 2021

dnerini removed this from To do in pysteps-v2 Jul 25, 2021

dnerini closed this Jul 25, 2021

		# sphinx_gallery_thumbnail_number = 5


		if __name__ == '__main__':


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

Use logging instead of print #142

Use logging instead of print #142

Conversation

fox91 commented Mar 5, 2020 • edited

codecov bot commented Mar 5, 2020 • edited

Codecov Report

aperezhortal Mar 6, 2020 • edited

Choose a reason for hiding this comment

dnerini Mar 7, 2020 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

aperezhortal left a 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

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

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

aperezhortal Mar 8, 2020 • edited

Choose a reason for hiding this comment

fox91 Mar 8, 2020 • edited

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

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dnerini left a comment

Choose a reason for hiding this comment

dnerini commented May 1, 2020

fox91 commented May 2, 2020

dnerini commented May 4, 2020

dnerini commented Jul 25, 2021

fox91 commented Mar 5, 2020 •

edited

codecov bot commented Mar 5, 2020 •

edited

aperezhortal Mar 6, 2020 •

edited

dnerini Mar 7, 2020 •

edited

aperezhortal Mar 8, 2020 •

edited

fox91 Mar 8, 2020 •

edited