Page MenuHomePhabricator

Pywikibot suppresses some log lines in debug mode
Open, LowPublic

Description

Example: one of the two lines here should be logged on every request when -debug is used, but that doesn't happen (even though it does enable a bunch of other logging, and the debug command is definitely called).

Event Timeline

Xqt triaged this task as Low priority.Aug 23 2020, 10:43 AM

I remember debug log logs to a file. Do you have some steps to reproduce this?

Run python3 pwb.py login -debug. (Specifically I noticed while testing T261066: Pywikibot bot password login failure.) There should be a log line saying Loaded cookies from file. but isn't, neither on stdout or in the logs directory.

Ah I see what is happening.

With diff:

diff --git a/pywikibot/bot.py b/pywikibot/bot.py
index 7e01efe83..96cbc887c 100644
--- a/pywikibot/bot.py
+++ b/pywikibot/bot.py
@@ -783,6 +783,7 @@ def handle_args(args=None, do_help=True):
     @return: list of arguments not recognised globally
     @rtype: list of str
     """
+    __import__('traceback').print_stack()
     if pywikibot._sites:
         warn('Site objects have been created before arguments were handled',
              UserWarning)
diff --git a/pywikibot/comms/http.py b/pywikibot/comms/http.py
index 848a0b1dc..310707f7a 100644
--- a/pywikibot/comms/http.py
+++ b/pywikibot/comms/http.py
@@ -60,6 +60,7 @@ cookie_file_path = config.datafilepath('pywikibot.lwp')
 file_mode_checker(cookie_file_path, create=True)
 cookie_jar = cookiejar.LWPCookieJar(cookie_file_path)
 try:
+    __import__('traceback').print_stack()
     cookie_jar.load()
 except cookiejar.LoadError:
     debug('Loading cookies failed.', _logger)

The linked debug() calls happen at:

File "pwb.py", line 199, in <module>
  import pywikibot as pwb
File "<frozen importlib._bootstrap>", line 983, in _find_and_load
File "<frozen importlib._bootstrap>", line 967, in _find_and_load_unlocked
File "<frozen importlib._bootstrap>", line 677, in _load_unlocked
File "<frozen importlib._bootstrap_external>", line 728, in exec_module
File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
File "/home/zhuyifei1999/mw-dev/pywikibot-core/pywikibot/__init__.py", line 35, in <module>
  from pywikibot.data.api import UploadWarning
File "<frozen importlib._bootstrap>", line 983, in _find_and_load
File "<frozen importlib._bootstrap>", line 967, in _find_and_load_unlocked
File "<frozen importlib._bootstrap>", line 677, in _load_unlocked
File "<frozen importlib._bootstrap_external>", line 728, in exec_module
File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
File "/home/zhuyifei1999/mw-dev/pywikibot-core/pywikibot/data/api.py", line 31, in <module>
  from pywikibot.comms import http
File "<frozen importlib._bootstrap>", line 1035, in _handle_fromlist
File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
File "<frozen importlib._bootstrap>", line 983, in _find_and_load
File "<frozen importlib._bootstrap>", line 967, in _find_and_load_unlocked
File "<frozen importlib._bootstrap>", line 677, in _load_unlocked
File "<frozen importlib._bootstrap_external>", line 728, in exec_module
File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
File "/home/zhuyifei1999/mw-dev/pywikibot-core/pywikibot/comms/http.py", line 63, in <module>
  __import__('traceback').print_stack()

but this is much earlier than the loglevel being initialized in:

File "/home/zhuyifei1999/mw-dev/pywikibot-core/pywikibot/comms/http.py", line 63, in <module>
  __import__('traceback').print_stack()
File "pwb.py", line 360, in <module>
  if not main():
File "pwb.py", line 355, in main
  file_package)
File "pwb.py", line 74, in run_python_file
  main_mod.__dict__)
File "./scripts/login.py", line 185, in <module>
  main()
File "./scripts/login.py", line 121, in main
  for arg in pywikibot.handle_args(args):
File "/home/zhuyifei1999/mw-dev/pywikibot-core/pywikibot/bot.py", line 786, in handle_args
  __import__('traceback').print_stack()

So this is a chicken and egg problem. Ideas for a workaround?

@zhuyifei1999, @Tgr
Initializing of log Level was rewritten in rPWBC0d1d224d. Also some circular Imports were solved with rPWBC7a57bdf170a
Is this problem probably solved with them in current master?