TTP logger duplicating my project logging?

[jeremyschulman]

I've noticed that when I create a logger for my application, the TTP logger is also duplicating my logs, for example:

2020-07-18 10:31:20,016 DEBUG: Waiting 60s before next collection
07/18/2020 10:31:20.16 [TTP DEBUG] 165; Waiting 60s before next collection

I see from looking at the code that ttp uses logging.basicConfig https://github.com/dmulyalin/ttp/blob/42cb4bc6bbc5598ffb48ba0fe5005aea89e1e241/ttp/ttp.py#L2482

Which by default is set at the WARNING level: https://github.com/dmulyalin/ttp/blob/42cb4bc6bbc5598ffb48ba0fe5005aea89e1e241/ttp/ttp.py#L136

So I am perplexed as to why TTP is shadowing my DEBUG messages.

As a workaround, I am setting log_level="none" explicitly when I instantiate a ttp object.

I appreciate your time to assist me with this question.

[dmulyalin]

Thanks for reporting that issue.

Was not able to recreate logs duplicates, but found in logging library docs:

logging.basicConfig(**kwargs)
Does basic configuration for the logging system by creating a StreamHandler with a default Formatter and adding it to the root logger...

probably somehow root logger got updated with second StreamHandler instance, hence the duplicates, not sure to be honest.

Modified logging_config function to not call basicConfig if TTP used as a module.

Could you try to test changes in commit 0b97d7c0587abb415a91022fe7a3ac29e917c792 in your application by installing TTP from master branch?

[jeremyschulman]

I will try this out tomorrow, thank you!

[dmulyalin]

if possible, please test with latest commit - 81ca86fbad034ebee73d3e421f5ad979517a23a3

Noticed that with change in 0b97d7c TTP logging got completely disabled in case if its used as a module (imported) and parent module does not have logging setup, 81ca86fbad034ebee73d3e421f5ad979517a23a3 commit is to rectify that behaviour

[jeremyschulman]

Will do today, thank you!

On Mon, Jul 20, 2020 at 7:11 AM dmulyalin notifications@github.com wrote:

if possible, please test with latest commit - 81ca86f https://github.com/dmulyalin/ttp/commit/81ca86fbad034ebee73d3e421f5ad979517a23a3

Noticed that with change in 0b97d7c https://github.com/dmulyalin/ttp/commit/0b97d7c0587abb415a91022fe7a3ac29e917c792 TTP logging got completely disabled in case if its used as a module (imported) and parent module does not have logging setup, 81ca86f https://github.com/dmulyalin/ttp/commit/81ca86fbad034ebee73d3e421f5ad979517a23a3 commit is to rectify that behaviour

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/dmulyalin/ttp/issues/14#issuecomment-660962961, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAT4WVA3YVHAVGUIY36YLN3R4QQ7BANCNFSM4O77NGNA .

[jeremyschulman]

@dmulyalin - I installed the code from master (showing version 0.3.0), and I continue to observe the duplicate logs:

2020-07-21 11:46:29,292 DEBUG: sears21: InfluxDB POST status 204
07/21/2020 11:46:29.292 [TTP DEBUG] 81; sears21: InfluxDB POST status 204

I am also observing this:

/home/kentik02/Projects/ttp/ttp/ttp.py:152: SyntaxWarning: "is not" with a literal. Did you mean "!="?
  if data is not '':
/home/kentik02/Projects/ttp/ttp/ttp.py:155: SyntaxWarning: "is not" with a literal. Did you mean "!="?
  if template is not '':
/home/kentik02/Projects/ttp/ttp/ttp.py:1426: SyntaxWarning: "is not" with a literal. Did you mean "!="?
  if self.group.default is not "_Not_Given_":
/home/kentik02/Projects/ttp/ttp/ttp.py:1848: SyntaxWarning: "is not" with a literal. Did you mean "!="?
  if e is not -1:

I failed to mention that I am using Python3.8; should that information be helpful.

[jeremyschulman]

Ok, I did a bit of debugging, and what I have discovered is that this code: https://github.com/dmulyalin/ttp/blob/81ca86fbad034ebee73d3e421f5ad979517a23a3/ttp/ttp.py#L2487

Is reached, and ttp is using basicConfig. I do not yet understand why the use of basicConfig at log level WARNING is duplicating my app logs of log level DEBUG. I have a theory that I will test out.

Might I suggest that rather than using basicConfig you setup a logger using __name__?

[dmulyalin]

Rolled back to not call basic config if TTP used as a module. Also modified code to fix py3.8 warnings.

Could you please test code from master?

Might I suggest that rather than using basicConfig you setup a logger using name? - yeah, think that always was the case: https://github.com/dmulyalin/ttp/blob/f5f96ba2b7ec06295a7a040f35a0184df0275b25/ttp/ttp.py#L14

I do not yet understand why the use of basicConfig at log level WARNING is duplicating my app logs - probably because basicconfig automatically creates streamhandler instance, but I was not able to replicate duplicates behaviour :

logging.basicConfig(**kwargs)
Does basic configuration for the logging system by creating a StreamHandler with a default Formatter and adding it to the root logger..

[jeremyschulman]

My apologies for the delay responding on this issue. I will test this today and report back shortly.

[jeremyschulman]

So the good news is that I no longer see the duplicate log messages. The bad news is that when I try to setup a ttp for creating debug logs I do not see them, for example:

 parser = ttp(data=parse_text, template=_TEMPLATE, log_level="DEBUG", log_file="/tmp/ttp.txt")

There is no logfile in "/tmp/ttp.txt".

When I run my program, it is an infinite loop type system; meaning for me to exit it I hit Ctrl-C. I am wondering if the ttp log file is not flushed to disk because of the nature of my program. What do you think?

[jeremyschulman]

I do see that the logger is set to DEBUG, however:

(Pdb) from ttp.ttp import log
(Pdb) log.name
'ttp.ttp'
(Pdb) log
<Logger ttp.ttp (DEBUG)>

From what I can tell from the code, it appears that there is a global logger instance in the ttp.ttp module; but when I create a TTP instance it affects that global variable. If I have multiple ttp instances, each trying to set the logger settings, I believe there will be "trampling elephant" issue.

Might I suggest that each ttp instance maintains a unique logger instance as a attribute to avoid this issue?

[dmulyalin]

TTP now will produce logs only in these cases: 1 - TTP used as CLI tool e.g. ttp <options?; log_level and log_file will be honoured as TTP instantiates root logger 2 - TTP called as a script e.g.python /path/to/ttp.py <options>; log_level and log_file will be honoured as TTP instantiates root logger 3 - Parent program (program where you import ttp in) has logging handler attached; log_level will be honoured, TTP has child logger

Above is done with idea in mind, that if TTP used as a module (imported in your program), it will be up to parent program owner to setup required logging and TTP will no longer call logging.basicConfig method a it will affect root/parent logger settings.

Sample code for case 3:

import logging
from ttp import ttp

# setup parent module logging, log file should be configured here as well:
logging.basicConfig(level=logging.DEBUG, filename="./my_file.txt")

# instantiate parsers with required log level:
parser_1 = ttp(log_level="DEBUG")
parser_2 = ttp(log_level="ERROR")

do staff...

As far as I understood - logging module forms hierarchy of loggers, meaning parent program has root logger, imported modules can have child loggers, all child loggers will propagate events to root logger. This should not lead to any interference between child loggers.

Official docs Logging Flow description

[jeremyschulman]

Hi @dmulyalin - your explanation is perfect, thank you. I believe we can close this issue; if you agree, please do so.