src/ tests/: added support for using Python's logging module.

Addresses #3914.

src/__init__.py

@@ -103,8 +103,51 @@ def message(text=''):
  '''
  For user messages.
  '''
- print(text, file=_g_out_message)
- _g_out_message.flush()
+ print(text, file=_g_out_message, flush=1)
+
+
+def use_python_logging(logger=None, fn_message=None, fn_log=None):
+ '''
+ Uses Python's `logging` module for PyMuPDF messages and logs.
+
+ Args:
+ logger:
+ If None we use `logging.getLogger('pymupdf')`.
+ fn_message:
+ Function that is called with PyMuPDF message text. If None we
+ use `logger.warning()`.
+ fn_logs:
+ Function that is called with PyMuPDF log text. If None we
+ use `logger.error()`.
+
+ If environment variable PYMUPDF_USE_PYTHON_LOGGING is '1', this function is
+ called with default args when PyMuPDF is first imported.
+ '''
+ import logging
+
+ if not logger:
+ logger = logging.getLogger('pymupdf')
+
+ class Out:
+ def __init__(self, fn):
+ self.fn = fn
+ def write(self, text):
+ # `logging` module appends newlines, but so does the `print()`
+ # functions in our caller message() and log() fns, so we need to
+ # remove them here.
+ text = text.rstrip('\n')
+ if text:
+ self.fn(text)
+ def flush(self):
+ pass
+ global _g_out_message
+ global _g_out_log
+ _g_out_message = Out(fn_message or logger.warning)
+ _g_out_log = Out(fn_log or logger.error)
+
+
+if os.environ.get('PYMUPDF_USE_PYTHON_LOGGING') == '1':
+ use_python_logging()
 
 
 def exception_info():

tests/test_general.py

@@ -12,6 +12,9 @@
 import pickle
 import platform
 import re
+import subprocess
+import sys
+import textwrap
 import time
 
 import gentle_compare
@@ -1016,6 +1019,32 @@ def test_cli():
  import subprocess
  subprocess.run(f'pymupdf -h', shell=1, check=1)
 
+
+def check_lines(expected_regexes, actual):
+ '''
+ Checks lines in <actual> match regexes in <expected_regexes>.
+ '''
+ print(f'check_lines():', flush=1)
+ print(f'{expected_regexes=}', flush=1)
+ print(f'{actual=}', flush=1)
+ def str_to_list(s):
+ if isinstance(s, str):
+ return s.split('\n') if s else list()
+ return s
+ expected_regexes = str_to_list(expected_regexes)
+ actual = str_to_list(actual)
+ if expected_regexes and expected_regexes[-1]:
+ expected_regexes.append('') # Always expect a trailing empty line.
+ # Remove `None` regexes and make all regexes match entire lines.
+ expected_regexes = [f'^{i}$' for i in expected_regexes if i is not None]
+ print(f'{expected_regexes=}', flush=1)
+ for expected_regex_line, actual_line in zip(expected_regexes, actual):
+ print(f' {expected_regex_line=}', flush=1)
+ print(f' {actual_line=}', flush=1)
+ assert re.match(expected_regex_line, actual_line)
+ assert len(expected_regexes) == len(actual), \
+ f'expected/actual lines mismatch: {len(expected_regexes)=} {len(actual)=}.'
+
 def test_cli_out():
  '''
  Check redirection of messages and log diagnostics with environment
@@ -1031,36 +1060,32 @@ def test_cli_out():
  if os.environ.get('PYMUPDF_USE_EXTRA') == '0':
  log_prefix = f'.+Using non-default setting from PYMUPDF_USE_EXTRA: \'0\''
 
- def check_lines(expected_regex, actual):
- if isinstance(expected_regex, str):
- expected_regex = expected_regex.split('\n')
- if isinstance(actual, str):
- actual = actual.split('\n')
- if expected_regex[-1]:
- expected_regex.append('') # Always expect a trailing newline.
- # Remove `None` lines and make all regexes match entire lines.
- expected_regex = [f'^{i}$' for i in expected_regex if i is not None]
- for expected_regex_line, actual_line in zip(expected_regex, actual):
- print(f' {expected_regex_line=}')
- print(f' {actual_line=}')
- assert re.match(expected_regex_line, actual_line)
- assert len(expected_regex) == len(actual), \
- f'expected/actual lines mismatch: {len(expected_regex)=} {len(actual)=}.'
-
- def check(expect_out, expect_err, message=None, log=None, ):
+ def check(
+ expect_out,
+ expect_err,
+ message=None,
+ log=None,
+ verbose=0,
+ ):
  '''
  Sets PYMUPDF_MESSAGE to `message` and PYMUPDF_LOG to `log`, runs
  `pymupdf internal`, and checks lines stdout and stderr match regexes in
  `expect_out` and `expect_err`. Note that we enclose regexes in `^...$`.
  '''
- env = os.environ.copy()
+ env = dict()
  if log:
  env['PYMUPDF_LOG'] = log
  if message:
  env['PYMUPDF_MESSAGE'] = message
- print(f'Running `pymupdf internal`. {env.get("PATH")=}.')
+ env = os.environ | env
+ print(f'Running with {env=}: pymupdf internal', flush=1)
  cp = subprocess.run(f'pymupdf internal', shell=1, check=1, capture_output=1, env=env, text=True)
 
+ if verbose:
+ #print(f'{cp.stdout=}.', flush=1)
+ #print(f'{cp.stderr=}.', flush=1)
+ sys.stdout.write(f'stdout:\n{textwrap.indent(cp.stdout, " ")}')
+ sys.stdout.write(f'stderr:\n{textwrap.indent(cp.stderr, " ")}')
  check_lines(expect_out, cp.stdout)
  check_lines(expect_err, cp.stderr)
 
@@ -1105,8 +1130,146 @@ def read(path):
  ],
  'fd:1',
  'fd:2',
+ )
+
+
+def test_use_python_logging():
+ '''
+ Checks pymupdf.use_python_logging().
+ '''
+ log_prefix = None
+ if os.environ.get('PYMUPDF_USE_EXTRA') == '0':
+ log_prefix = f'.+Using non-default setting from PYMUPDF_USE_EXTRA: \'0\''
+
+ def check(
+ code,
+ regexes_stdout,
+ regexes_stderr,
+ env = None,
+ ):
+ code = textwrap.dedent(code)
+ path = os.path.abspath(f'{__file__}/../../tests/resources_test_logging.py')
+ with open(path, 'w') as f:
+ f.write(code)
+ command = f'{sys.executable} {path}'
+ if env:
+ print(f'{env=}.')
+ env = os.environ | env
+ print(f'Running: {command}', flush=1)
+ try:
+ cp = subprocess.run(command, shell=1, check=1, capture_output=1, text=True, env=env)
+ except Exception as e:
+ print(f'Command failed: {command}.', flush=1)
+ print(f'Stdout\n{textwrap.indent(e.stdout, " ")}', flush=1)
+ print(f'Stderr\n{textwrap.indent(e.stderr, " ")}', flush=1)
+ raise
+ check_lines(regexes_stdout, cp.stdout)
+ check_lines(regexes_stderr, cp.stderr)
+
+ print(f'## Basic use of `logging` sends output to stderr instead of default stdout.')
+ check(
+ '''
+ import pymupdf
+ pymupdf.message('this is pymupdf.message()')
+ pymupdf.log('this is pymupdf.log()')
+ pymupdf.use_python_logging()
+ pymupdf.message('this is pymupdf.message() 2')
+ pymupdf.log('this is pymupdf.log() 2')
+ ''',
+ [
+ log_prefix,
+ 'this is pymupdf.message[(][)]',
+ '.+this is pymupdf.log[(][)]',
+ ],
+ [
+ 'this is pymupdf.message[(][)] 2',
+ '.+this is pymupdf.log[(][)] 2',
+ ],
+ )
+
+ print(f'## Calling logging.basicConfig() makes logging output contain <LEVEL>:<name> prefixes.')
+ check(
+ '''
+ import pymupdf
+ 
+ import logging
+ logging.basicConfig()
+ pymupdf.use_python_logging()
+ 
+ pymupdf.message('this is pymupdf.message()')
+ pymupdf.log('this is pymupdf.log()')
+ ''',
+ [
+ log_prefix,
+ ],
+ [
+ 'WARNING:pymupdf:this is pymupdf.message[(][)]',
+ 'ERROR:pymupdf:.+this is pymupdf.log[(][)]',
+ ],
+ )
+
+ print(f'## Setting PYMUPDF_USE_PYTHON_LOGGING=1 makes PyMuPDF use logging on startup.')
+ check(
+ '''
+ import pymupdf
+ pymupdf.message('this is pymupdf.message()')
+ pymupdf.log('this is pymupdf.log()')
+ ''',
+ '',
+ [
+ log_prefix,
+ 'this is pymupdf.message[(][)]',
+ '.+this is pymupdf.log[(][)]',
+ ],
+ env = dict(PYMUPDF_USE_PYTHON_LOGGING='1'),
+ )
+
+ print(f'## Pass explicit logger to pymupdf.use_python_logging().')
+ check(
+ '''
+ import pymupdf
+ 
+ import logging
+ logging.basicConfig()
+ 
+ logger = logging.getLogger('foo')
+ pymupdf.use_python_logging(logger)
+ 
+ pymupdf.message('this is pymupdf.message()')
+ pymupdf.log('this is pymupdf.log()')
+ ''',
+ [
+ log_prefix,
+ ],
+ [
+ 'WARNING:foo:this is pymupdf.message[(][)]',
+ 'ERROR:foo:.+this is pymupdf.log[(][)]',
+ ],
+ )
 
+ print(f'## Check pymupdf.use_python_logging() fn_message and fn_log args.')
+ check(
+ '''
+ import pymupdf
+ 
+ import logging
+ logging.basicConfig(level=logging.DEBUG)
+ logger = logging.getLogger('pymupdf')
+ 
+ pymupdf.use_python_logging(None, logger.critical, logger.info)
+ 
+ pymupdf.message('this is pymupdf.message()')
+ pymupdf.log('this is pymupdf.log()')
+ ''',
+ [
+ log_prefix,
+ ],
+ [
+ 'CRITICAL:pymupdf:this is pymupdf.message[(][)]',
+ 'INFO:pymupdf:.+this is pymupdf.log[(][)]',
+ ],
  )
+
 
 def relpath(path, start=None):
  '''