Page MenuHomePhabricator

log header in log files is written twice
Open, MediumPublicBUG REPORT

Description

Log header is not written any longer.

def writelogheader():
    """
    Save additional version, system and status info to the log file in use.

    This may help the user to track errors or report bugs.
    """
    # If a http thread is not available, it's too early to print a header
    # that includes version information, which may need to query a server.
    # The http module can't be imported due to circular dependencies.
    http = sys.modules.get('pywikibot.comms.http', None)
    if not http or not hasattr(http, 'threads') or not len(http.threads):
        return

threads has been removed from http with 952665acaa9ab2dd1a78cb4a935f3b5743941913

Event Timeline

Xqt triaged this task as Medium priority.

Change 631826 had a related patch set uploaded (by Xqt; owner: Xqt):
[pywikibot/core@master] [bugfix] print log header

https://gerrit.wikimedia.org/r/631826

Change 631826 merged by jenkins-bot:
[pywikibot/core@master] [bugfix] print log header

https://gerrit.wikimedia.org/r/631826

user@pc:~/python/core {master}$ python
Python 3.8.3 (default, Jul  2 2020, 16:21:59) 
[GCC 7.3.0] :: Anaconda, Inc. on linux
Type "help", "copyright", "credits" or "license" for more information.

>>> import pywikibot
/home/user/python/core/pywikibot/config2.py:1066: UserWarning: 
Configuration variable "oauth_tokens" is defined in your user-
config.py but unknown. It can be a misspelled one or a variable that
is no longer supported.
  warn('\n' + fill('Configuration variable "{0}" is defined in '
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/home/user/python/core/pywikibot/__init__.py", line 36, in <module>
    from pywikibot.data.api import UploadWarning
  File "/home/user/python/core/pywikibot/data/api.py", line 33, in <module>
    from pywikibot.comms import http
  File "/home/user/python/core/pywikibot/comms/http.py", line 68, in <module>
    debug('Loaded cookies from file.', _logger)
  File "/home/user/python/core/pywikibot/logging.py", line 182, in debug
    logoutput(text, decoder, newline, DEBUG, layer, **kwargs)
  File "/home/user/python/core/pywikibot/logging.py", line 78, in logoutput
    _init()
  File "/home/user/python/core/pywikibot/logging.py", line 34, in _init
    init_routine()
  File "/home/user/python/core/pywikibot/bot.py", line 344, in init_handlers
    writelogheader()
  File "/home/user/python/core/pywikibot/bot.py", line 405, in writelogheader
    filename = version.get_module_filename(module)
  File "/home/user/python/core/pywikibot/version.py", line 450, in get_module_filename
    if hasattr(module, '__file__') and os.path.exists(module.__file__):
  File "/home/user/anaconda3/lib/python3.8/genericpath.py", line 19, in exists
    os.stat(path)
TypeError: stat: path should be string, bytes, os.PathLike or integer, not NoneType

Works for me:

Python 3.8.5 (tags/v3.8.5:580fbb0, Jul 20 2020, 15:57:54) [MSC v.1924 64 bit (AMD64)] on win32
Type "help", "copyright", "credits" or "license()" for more information.
>>> import pywikibot

Warning (from warnings module):
  File "C:\pwb\GIT\core\pywikibot\config2.py", line 1066
    warn('\n' + fill('Configuration variable "{0}" is defined in '
UserWarning: 
Configuration variable "oauth_tokens" is defined in your user-
config.py but unknown. It can be a misspelled one or a variable that
is no longer supported.
>>>
2020-10-03 07:56:21             bot.py,  353 in     writelogheader: VERBOSE
2020-10-03 07:56:21             bot.py,  354 in     writelogheader: VERBOSE  === Pywikibot framework v5.0.0.dev0 -- Logging header ===
2020-10-03 07:56:21             bot.py,  358 in     writelogheader: VERBOSE  COMMAND: ['']
2020-10-03 07:56:21             bot.py,  361 in     writelogheader: VERBOSE  DATE: 2020-10-03 05:56:21.062194 UTC
2020-10-03 07:56:21             bot.py,  365 in     writelogheader: VERBOSE  VERSION: [ssh] pywikibot-core (0d1d224, g13245, 2020/10/02, 18:44:32, n/a)
2020-10-03 07:56:21             bot.py,  375 in     writelogheader: VERBOSE  CONFIG FILE DIR: C:\pwb\GIT\core
2020-10-03 07:56:21             bot.py,  391 in     writelogheader: VERBOSE  PACKAGES:
2020-10-03 07:56:21             bot.py,  398 in     writelogheader: VERBOSE    mwparserfromhell: No module named 'mwparserfromhell'
2020-10-03 07:56:21             bot.py,  400 in     writelogheader: VERBOSE    requests (C:\Python38\lib\site-packages\requests\) = 2.24.0
2020-10-03 07:56:21             bot.py,  403 in     writelogheader: VERBOSE  MODULES:
2020-10-03 07:56:21             bot.py,  409 in     writelogheader: VERBOSE    C:\pwb\GIT\core\pywikibot\__init__.py .dev 2020-10-02 17:39:37.802086
2020-10-03 07:56:21             bot.py,  409 in     writelogheader: VERBOSE    C:\pwb\GIT\core\pywikibot\__metadata__.py .dev 2020-10-02 17:39:37.802086
2020-10-03 07:56:21             bot.py,  409 in     writelogheader: VERBOSE    C:\pwb\GIT\core\pywikibot\comms\http.py .dev 2020-10-02 17:39:37.802086
2020-10-03 07:56:21             bot.py,  415 in     writelogheader: VERBOSE  =========================================================

Change 631904 had a related patch set uploaded (by Xqt; owner: Xqt):
[pywikibot/core@master] [bugfix] fix version.get_module_filename()

https://gerrit.wikimedia.org/r/631904

Change 631904 merged by jenkins-bot:
[pywikibot/core@master] [bugfix] fix version.get_module_filename()

https://gerrit.wikimedia.org/r/631904

Now I see it is printed twice.
e.g. see python pwb.py login -debug

strange: pwb prints one whereas pwb -help prints two headers

Xqt renamed this task from log header in log files is not written to log header in log files is written twice.Oct 7 2020, 6:13 AM
(base)user@pc:~/python/core {master}$ python pwb.py

  File "/home/user/python/core/pywikibot/__init__.py", line 1311, in _flush
    debug('_flush() called', _logger)
  File "/home/user/python/core/pywikibot/logging.py", line 182, in debug
    logoutput(text, decoder, newline, DEBUG, layer, **kwargs)
  File "/home/user/python/core/pywikibot/logging.py", line 78, in logoutput
    _init()
  File "/home/user/python/core/pywikibot/logging.py", line 34, in _init
    init_routine()
  File "/home/user/python/core/pywikibot/bot.py", line 345, in init_handlers
    writelogheader()
  File "/home/user/python/core/pywikibot/bot.py", line 354, in writelogheader
    __import__('traceback').print_stack()

(base)user@pc:~/python/core {master}$ python pwb.py -help
  File "pwb.py", line 362, in <module>
    if not main():
  File "pwb.py", line 307, in main
    unknown_args = pwb.handle_args(global_args)
  File "/home/user/python/core/pywikibot/bot.py", line 851, in handle_args
    pywikibot.Site()
  File "/home/user/python/core/pywikibot/tools/__init__.py", line 1451, in wrapper
    return obj(*__args, **__kw)
  File "/home/user/python/core/pywikibot/__init__.py", line 1225, in Site
    debug("Instantiated %s object '%s'"
  File "/home/user/python/core/pywikibot/logging.py", line 182, in debug
    logoutput(text, decoder, newline, DEBUG, layer, **kwargs)
  File "/home/user/python/core/pywikibot/logging.py", line 78, in logoutput
    _init()
  File "/home/user/python/core/pywikibot/logging.py", line 34, in _init
    init_routine()
  File "/home/user/python/core/pywikibot/bot.py", line 345, in init_handlers
    writelogheader()
  File "/home/user/python/core/pywikibot/bot.py", line 354, in writelogheader
    __import__('traceback').print_stack()

  File "pwb.py", line 362, in <module>
    if not main():
  File "pwb.py", line 307, in main
    unknown_args = pwb.handle_args(global_args)
  File "/home/user/python/core/pywikibot/bot.py", line 859, in handle_args
    init_handlers()
  File "/home/user/python/core/pywikibot/bot.py", line 345, in init_handlers
    writelogheader()
  File "/home/user/python/core/pywikibot/bot.py", line 354, in writelogheader
    __import__('traceback').print_stack()

Change 703402 had a related patch set uploaded (by Xqt; author: Xqt):

[pywikibot/core@master] [bugfix] Rewrite init_handlers and RotatingFileHandler

https://gerrit.wikimedia.org/r/703402

Xqt changed the subtype of this task from "Task" to "Bug Report".Jul 6 2021, 11:45 AM