replace prints with logging module

[flaviovs]

This resolves #1378.
Here's what this PR does:

• Replace ordinary debug/info/warnings/error messages using print() with proper logger.XXXX() calls.
• Replace deprecation warnings issued with print() with proper Python warnings using the warnings module.

NOTE: Some print() calls were guarded by if debug: tests. This PR does not change those, because debug is toggled on/off inside the library sometimes, so there's some logic involved that I am not fully aware of. Ideally this internal debug flag should be removed altogether, and the logic replaced with logger.debug() calls. I can provide a PR for that if desired.

[asafravid]

You sometimes use logger.warning() and sometimes warning.warn() - can you elaborate why?

[flaviovs]

@asafravid, logger.warning() (from the logging module) and warnings.warn() serve two different purposes.

Logging and logger.*() calls are geared towards end users, who can configure the logging system in the app to handle log messages issued by libraries in several ways. For example, they can set warnings and errors to go to stderr, info and debug to stdout, also log warnings or above to a file, etc.). The app can even silence log messages from specific libraries/levels.

Conceptually, logger.*() is used to tell the user what is going on in the library at runtime. In the context of this PR, logger.warning() is just logging messages at warning level.

On the other hand, warnings.warn() (from the warnings module) is geared towards developers. These warnings are totally unrelated to the logging system. There's no way to redirect warnings, and to silence them, other than the developer explicitly filtering them out (which is an indication that they know what they're doing — at least in theory 😉).

Conceptually warnings.warn() is used to tell the developer what is going on with the code.

In this PR, for example, I used warnings.warn() with DeprecationWarning to replace print() calls warning about deprecated calls in yfinance. This is the precise use case for warnings.warn(..., DeprecationWarning).

Let me know if that does not answer your question.

[asafravid]

@asafravid, logger.warning() (from the logging module) and warnings.warn() serve two different purposes.

Logging and logger.*() calls are geared towards end users, who can configure the logging system in the app to handle log messages issued by libraries in several ways. For example, they can set warnings and errors to go to stderr, info and debug to stdout, also log warnings or above to a file, etc.). The app can even silence log messages from specific libraries/levels.

Conceptually, logger.*() is used to tell the user what is going on in the library at runtime. In the context of this PR, logger.warning() is just logging messages at warning level.

On the other hand, warnings.warn() (from the warnings module) is geared towards developers. These warnings are totally unrelated to the logging system. There's no way to redirect warnings, and to silence them, other than the developer explicitly filtering them out (which is an indication that they know what they're doing — at least in theory 😉).

Conceptually warnings.warn() is used to tell the developer what is going on with the code.

In this PR, for example, I used warnings.warn() with DeprecationWarning to replace print() calls warning about deprecated calls in yfinance. This is the precise use case for warnings.warn(..., DeprecationWarning).

Let me know if that does not answer your question.

Thanks for the details

[asafravid]

LGTM

[ValueRaider]

I haven't looked through code yet, just want to say: rebase to dev then change target to dev. #1084

[ValueRaider]

This doesn't work for me. @asafravid did you actually run this?

I put this at top of base.py:

logger.setLevel(logging.DEBUG)

... then nothing prints.

If instead I put this at top, everything prints when only CRITICAL should print (according to their documentation)

logging.basicConfig(level=logging.CRITICAL)

[asafravid]

@ValueRaider Try this: https://stackoverflow.com/questions/41796934/turn-on-debug-logging-in-python

[ValueRaider]

@asafravid That SO answer is fine if I want to print everything (or nothing), but not if I want to reduce verbosity to e.g. CRITICAL or ERROR. As I explained already. Have you successfully restricted logger output to above DEBUG? Logging levels

[flaviovs]

This doesn't work for me. @asafravid did you actually run this?

I put this at top of base.py:

logger.setLevel(logging.DEBUG)

... then nothing prints.

If instead I put this at top, everything prints when only CRITICAL should print (according to their documentation)

logging.basicConfig(level=logging.CRITICAL)

@ValueRaider if you put logger.setLevel(logging.DEBUG) at the top of base.py then you'll be changing only the yfinance.base logger.

However, I strongly advise against adding setLevel() calls in modules, because this hinder the possibility of app users to control debug levels on the app using yfinance.

Notice that the distinction between module and app calls is important in the logging module context. I'm not sure what your use case is, but if you're just trying to enable DEBUG+ in yfinance only, while perhaps seeing WARNING+ from other libraries too (e.g. urllib), the you can do this on your script:

import logging

# Basic configuration to log everything at WARNING, ERROR and CRITICAL
# to stderr. This will print WARNING+ messages from **all** modules (not
# only yfinance).
logging.basicConfig(level=logging.WARNING)

# Now configure yfinance logger to display DEBUG and above messages.
logger = logging.getLogger('yfinance')
logger.propagate = False 
handler = logging.StreamHandler()
handler.setFormatter(logging.Formatter('%(levelname)s:%(name)s:%(message)s'))
logger.addHandler(handler)
logger.setLevel(logging.DEBUG)

A simplified version of the above that logs DEBUG+ from all modules was added already to test_finance.py.

All that said, I want to remind you guys that I did not replace debugging print()s with logger.debug() calls. The reason as I stated in the PR is because the print()s are guarded by if debug: logic, and I didn't want to go out of scope in this PR by changing programming logic.

[ValueRaider]

Thanks @flaviovs , I think I understand now.

I did not replace debugging print()s with logger.debug() calls

That's fine but I think these are in scope so I want to replace these too, logging should be able to replace that logic. I can handle this.

And reminder: you need to rebase to dev. Should solve that merge conflict below, don't waste time on it.

[flaviovs]

And reminder: you need to rebase to dev. Should solve that merge conflict below, don't waste time on it.

@ValueRaider, I just did it (no conflicts).

Let me know if you need any more help with the PR.

[ValueRaider]

I've converted more prints to logging - those wrapped in a if debug: - and adjusted some levels. Anything you disagree with?

[ValueRaider]

@flaviovs I have a request: does loggingenable printing a specific message only once? I.e. it remembers? This will be useful for warning about deprecated arguments, most users run yfinance in a loop and don't need to see same message many times.

[asafravid]

@ValueRaider possibly we can insert this statefulness per logging message within the yfinance code (if not possible via the logging infrastructure)
Otherwise there’s a hack which can be used as here: https://stackoverflow.com/questions/31953272/logging-print-message-only-once

[flaviovs]

@flaviovs I have a request: does loggingenable printing a specific message only once? I.e. it remembers? This will be useful for warning about deprecated arguments, most users run yfinance in a loop and don't need to see same message many times.

Hi @ValueRaider, logging does not "remember". I think you can find (or develop) a log handler that does that but, as far as I know, it does not that by default.

However, I think that for this particular use case (deprecation), you want warnings.warn(MESSAGE, DeprecationWarning) . This is the correct tool for the job and it indeed does suppress repeated messages. From https://docs.python.org/3/library/warnings.html:

Repetitions of a particular warning for the same source location are typically suppressed.

[ValueRaider]

@flaviovs Thanks for suggestion but warnings repeat suppression doesn't work, even if using "once" filter. I'm not alone in having trouble.

@asafravid LRU cache idea works perfect.

[flaviovs]

@flaviovs Thanks for suggestion but warnings repeat suppression doesn't work, even if using "once" filter. I'm not alone in having trouble.

That's interesting. I've never depended on this behaviour so actually never tested it. Thanks for bringing me awareness to this.

@asafravid LRU cache idea works perfect.

I'm glad to hear that you guys found a solution.

Let me know if I can help with anything else.