From ee51412e4b6336bb4912544d8628a436e5021ea3 Mon Sep 17 00:00:00 2001
From: Julian Smith <julian.smith@artifex.com>
Date: Fri, 22 Sep 2023 22:14:18 +0100
Subject: [PATCH 1/5] pipcl.py: use global log level.

Instead of passing `verbose` args between fns, we now have a global `g_verbose`
and fns log0(), log1(), log2(). log1() only outputs if g_verbose >= 1 etc.

Command-line `--verbose` increments `g_verbose`.
---
 pipcl.py | 248 ++++++++++++++++++++++++++++---------------------------
 1 file changed, 126 insertions(+), 122 deletions(-)

diff --git a/pipcl.py b/pipcl.py
index 2f28768a8..c94d84d87 100644
--- a/pipcl.py
+++ b/pipcl.py
@@ -142,7 +142,7 @@ class Package:
     module into root `pipcl_test/install`.
 
         >>> _ = subprocess.run(
-        ...         f'cd pipcl_test && {sys.executable} setup.py --verbose --root install install',
+        ...         f'cd pipcl_test && {sys.executable} setup.py --root install install',
         ...         shell=1, check=1)
 
     The actual install directory depends on `sysconfig.get_path('platlib')`:
@@ -185,42 +185,43 @@ class Package:
     check that the sdist and wheel actually work.
 
         >>> _ = subprocess.run(
-        ...         f'cd pipcl_test && {sys.executable} setup.py --verbose sdist',
+        ...         f'cd pipcl_test && {sys.executable} setup.py sdist',
         ...         shell=1, check=1)
 
         >>> _ = subprocess.run(
-        ...         f'cd pipcl_test && {sys.executable} setup.py --verbose bdist_wheel',
+        ...         f'cd pipcl_test && {sys.executable} setup.py bdist_wheel',
         ...         shell=1, check=1)
     
     Check that rebuild does nothing.
     
         >>> t0 = os.path.getmtime('pipcl_test/build/foo.py')
         >>> _ = subprocess.run(
-        ...         f'cd pipcl_test && {sys.executable} setup.py --verbose bdist_wheel',
+        ...         f'cd pipcl_test && {sys.executable} setup.py bdist_wheel',
         ...         shell=1, check=1)
         >>> t = os.path.getmtime('pipcl_test/build/foo.py')
-        >>> t == t0
-        True
+        >>> assert t == t0
         
     Check that touching bar.i forces rebuild.
     
         >>> os.utime('pipcl_test/bar.i')
         >>> _ = subprocess.run(
-        ...         f'cd pipcl_test && {sys.executable} setup.py --verbose bdist_wheel',
+        ...         f'cd pipcl_test && {sys.executable} setup.py bdist_wheel',
         ...         shell=1, check=1)
         >>> t = os.path.getmtime('pipcl_test/build/foo.py')
-        >>> t > t0
-        True
+        >>> assert t > t0
     
-    Check that touching foo.i.cpp forces rebuild.
+    Check that touching foo.i.cpp does not run swig, but does recompile/link.
     
+        >>> t0 = time.time()
         >>> os.utime('pipcl_test/build/foo.i.cpp')
         >>> _ = subprocess.run(
-        ...         f'cd pipcl_test && {sys.executable} setup.py --verbose bdist_wheel',
+        ...         f'cd pipcl_test && {sys.executable} setup.py bdist_wheel',
         ...         shell=1, check=1)
-        >>> t = os.path.getmtime('pipcl_test/build/foo.py')
-        >>> t > t0
-        True
+        >>> assert os.path.getmtime('pipcl_test/build/foo.py') <= t0
+        >>> so = glob.glob('pipcl_test/build/*.so')
+        >>> assert len(so) == 1
+        >>> so = so[0]
+        >>> assert os.path.getmtime(so) > t0
     
     Wheels and sdists
     
@@ -509,16 +510,15 @@ def build_wheel(self,
             wheel_directory,
             config_settings=None,
             metadata_directory=None,
-            verbose=False,
             ):
         '''
-        A PEP-517 `build_wheel()` function, with extra optional `verbose` arg.
+        A PEP-517 `build_wheel()` function.
 
         Also called by `handle_argv()` to handle the `bdist_wheel` command.
 
         Returns leafname of generated wheel within `wheel_directory`.
         '''
-        _log(
+        log2(
                 f' wheel_directory={wheel_directory!r}'
                 f' config_settings={config_settings!r}'
                 f' metadata_directory={metadata_directory!r}'
@@ -563,7 +563,7 @@ def build_wheel(self,
             m = re.match( '^(macosx_[0-9]+)(_[^0-9].+)$', tag_platform)
             if m:
                 tag_platform2 = f'{m.group(1)}_0{m.group(2)}'
-                _log( f'Changing from {tag_platform!r} to {tag_platform2!r}')
+                log2( f'Changing from {tag_platform!r} to {tag_platform2!r}')
                 tag_platform = tag_platform2
 
         # Final tag is, for example, 'cp39-none-win32', 'cp39-none-win_amd64'
@@ -579,18 +579,18 @@ def build_wheel(self,
         if self.fn_build:
             items = self._call_fn_build(config_settings)
 
-        _log(f'Creating wheel: {path}')
+        log2(f'Creating wheel: {path}')
         os.makedirs(wheel_directory, exist_ok=True)
         record = _Record()
         with zipfile.ZipFile(path, 'w', self.wheel_compression, self.wheel_compresslevel) as z:
 
             def add_file(from_, to_):
                 z.write(from_, to_)
-                record.add_file(from_, to_, verbose=verbose)
+                record.add_file(from_, to_)
 
             def add_str(content, to_):
                 z.writestr(to_, content)
-                record.add_content(content, to_, verbose=verbose)
+                record.add_content(content, to_)
 
             dist_info_dir = self._dist_info_dir()
             
@@ -623,11 +623,12 @@ def add_str(content, to_):
             z.writestr(f'{dist_info_dir}/RECORD', record.get(f'{dist_info_dir}/RECORD'))
 
         st = os.stat(path)
-        _log( f'Have created wheel size={st.st_size}: {path}')
-        with zipfile.ZipFile(path, compression=self.wheel_compression) as z:
-            _log(f'Contents are:')
-            for zi in sorted(z.infolist(), key=lambda z: z.filename):
-                _log(f'    {zi.file_size: 10d} {zi.filename}')
+        log1( f'Have created wheel size={st.st_size}: {path}')
+        if g_verbose >= 2:
+            with zipfile.ZipFile(path, compression=self.wheel_compression) as z:
+                _log2(f'Contents are:')
+                for zi in sorted(z.infolist(), key=lambda z: z.filename):
+                    _log2(f'    {zi.file_size: 10d} {zi.filename}')
         
         return os.path.basename(path)
 
@@ -636,16 +637,15 @@ def build_sdist(self,
             sdist_directory,
             formats,
             config_settings=None,
-            verbose=False,
             ):
         '''
-        A PEP-517 `build_sdist()` function, with extra optional `verbose` arg.
+        A PEP-517 `build_sdist()` function.
 
         Also called by `handle_argv()` to handle the `sdist` command.
 
         Returns leafname of generated archive within `sdist_directory`.
         '''
-        _log(
+        log2(
                 f' sdist_directory={sdist_directory!r}'
                 f' formats={formats!r}'
                 f' config_settings={config_settings!r}'
@@ -672,8 +672,7 @@ def add_content(tar, name, contents):
             Adds item called `name` to `tarfile.TarInfo` `tar`, containing
             `contents`. If contents is a string, it is encoded using utf8.
             '''
-            if verbose:
-                _log( f'Adding: {name}')
+            log2( f'Adding: {name}')
             if isinstance(contents, str):
                 contents = contents.encode('utf8')
             check_name(name)
@@ -683,15 +682,13 @@ def add_content(tar, name, contents):
             tar.addfile(ti, io.BytesIO(contents))
         
         def add_file(tar, path_abs, name):
-            if verbose:
-                _log( f'Adding file: {os.path.relpath(path_abs)} => {name}')
+            log2( f'Adding file: {os.path.relpath(path_abs)} => {name}')
             check_name(name)
             tar.add( path_abs, f'{prefix}/{name}', recursive=False)
 
         os.makedirs(sdist_directory, exist_ok=True)
         tarpath = f'{sdist_directory}/{prefix}.tar.gz'
-        if verbose:
-            _log(f'Creating sdist: {tarpath}')
+        log2(f'Creating sdist: {tarpath}')
         with tarfile.open(tarpath, 'w:gz') as tar:
             found_pyproject_toml = False
             for path in paths:
@@ -708,24 +705,24 @@ def add_file(tar, path_abs, name):
                 add_file( tar, path_abs, path_rel)
                 manifest.append(path_rel)
             if not found_pyproject_toml:
-                _log(f'Warning: no pyproject.toml specified.')
+                log0(f'Warning: no pyproject.toml specified.')
             
             # Always add a PKG-INFO file.
             add_content(tar, f'PKG-INFO', self._metainfo())
 
             if self.license:
                 if 'COPYING' in names_in_tar:
-                    _log(f'Not writing .license because file already in sdist: COPYING')
+                    log2(f'Not writing .license because file already in sdist: COPYING')
                 else:
                     add_content(tar, f'COPYING', self.license)
             
-        _log( f'Have created sdist: {tarpath}')
+        log1( f'Have created sdist: {tarpath}')
         return os.path.basename(tarpath)
 
 
     def _call_fn_build( self, config_settings=None):
         assert self.fn_build
-        _log(f'calling self.fn_build={self.fn_build}')
+        log2(f'calling self.fn_build={self.fn_build}')
         if inspect.signature(self.fn_build).parameters:
             ret = self.fn_build(config_settings)
         else:
@@ -751,16 +748,15 @@ def _argv_clean(self, all_):
                 path = os.path.abspath(path)
                 assert path.startswith(self.root+os.sep), \
                         f'path={path!r} does not start with root={self.root+os.sep!r}'
-                _log(f'Removing: {path}')
+                log2(f'Removing: {path}')
                 shutil.rmtree(path, ignore_errors=True)
 
 
-    def install(self, record_path=None, root=None, verbose=False):
+    def install(self, record_path=None, root=None):
         '''
         Called by `handle_argv()` to handle `install` command..
         '''
-        if verbose:
-            _log( f'{record_path=} {root=}')
+        log2( f'{record_path=} {root=}')
         
         # Do a build and get list of files to install.
         #
@@ -769,10 +765,9 @@ def install(self, record_path=None, root=None, verbose=False):
             items = self._call_fn_build( dict())
         
         root2 = install_dir(root)
-        if verbose:
-            _log( f'{root2=}')
+        log2( f'{root2=}')
         
-        _log( f'Installing into: {root2!r}')
+        log1( f'Installing into: {root2!r}')
         dist_info_dir = self._dist_info_dir()
         
         if not record_path:
@@ -780,15 +775,13 @@ def install(self, record_path=None, root=None, verbose=False):
         record = _Record()
         
         def add_file(from_abs, from_rel, to_abs, to_rel):
-            if verbose:
-                _log(f'Copying from {from_rel} to {to_abs}')
+            log2(f'Copying from {from_rel} to {to_abs}')
             os.makedirs( os.path.dirname( to_abs), exist_ok=True)
             shutil.copy2( from_abs, to_abs)
             record.add_file(from_rel, to_rel)
 
         def add_str(content, to_abs, to_rel):
-            if verbose:
-                _log( f'Writing to: {to_abs}')
+            log2( f'Writing to: {to_abs}')
             os.makedirs( os.path.dirname( to_abs), exist_ok=True)
             with open( to_abs, 'w') as f:
                 f.write( content)
@@ -801,13 +794,11 @@ def add_str(content, to_abs, to_rel):
         
         add_str( self._metainfo(), f'{root2}/{dist_info_dir}/METADATA', f'{dist_info_dir}/METADATA')
 
-        if verbose:
-            _log( f'Writing to: {record_path}')
+        log2( f'Writing to: {record_path}')
         with open(record_path, 'w') as f:
             f.write(record.get())
 
-        if verbose:
-            _log(f'Finished.')
+        log2(f'Finished.')
 
 
     def _argv_dist_info(self, root):
@@ -840,7 +831,7 @@ def _write_info(self, dirpath=None):
         '''
         if dirpath is None:
             dirpath = self.root
-        _log(f'Creating files in directory {dirpath}')
+        log2(f'Creating files in directory {dirpath}')
         os.makedirs(dirpath, exist_ok=True)
         with open(os.path.join(dirpath, 'PKG-INFO'), 'w') as f:
             f.write(self._metainfo())
@@ -865,7 +856,8 @@ def handle_argv(self, argv):
 
         This is partial support at best.
         '''
-        #_log(f'argv: {argv}')
+        global g_verbose
+        #log2(f'argv: {argv}')
 
         class ArgsRaise:
             pass
@@ -896,7 +888,6 @@ def next( self, eof=ArgsRaise):
         opt_install_headers = None
         opt_record = None
         opt_root = None
-        opt_verbose = False
         
         args = Args(argv[1:])
 
@@ -906,7 +897,7 @@ def next( self, eof=ArgsRaise):
                 break
 
             elif arg in ('-h', '--help', '--help-commands'):
-                _log(textwrap.dedent('''
+                log0(textwrap.dedent('''
                         Usage:
                             [<options>...] <command> [<options>...]
                         Commands:
@@ -975,7 +966,7 @@ def next( self, eof=ArgsRaise):
             elif arg == '--record':                             opt_record = args.next()
             elif arg == '--root':                               opt_root = args.next()
             elif arg == '--single-version-externally-managed':  pass
-            elif arg == '--verbose' or arg == '-v':             opt_verbose = True
+            elif arg == '--verbose' or arg == '-v':             g_verbose += 1
             
             elif arg == 'windows-vs':
                 command = arg
@@ -988,17 +979,16 @@ def next( self, eof=ArgsRaise):
 
         assert command, 'No command specified'
 
-        _log(f'Handling command={command}')
+        log1(f'Handling command={command}')
         if 0:   pass
-        elif command == 'bdist_wheel':  self.build_wheel(opt_dist_dir, verbose=opt_verbose)
+        elif command == 'bdist_wheel':  self.build_wheel(opt_dist_dir)
         elif command == 'clean':        self._argv_clean(opt_all)
         elif command == 'dist_info':    self._argv_dist_info(opt_egg_base)
         elif command == 'egg_info':     self._argv_egg_info(opt_egg_base)
-        elif command == 'install':      self.install(opt_record, opt_root, opt_verbose)
-        elif command == 'sdist':        self.build_sdist(opt_dist_dir, opt_formats, verbose=opt_verbose)
+        elif command == 'install':      self.install(opt_record, opt_root)
+        elif command == 'sdist':        self.build_sdist(opt_dist_dir, opt_formats)
         
         elif command == 'windows-python':
-            verbose = False
             version = None
             while 1:
                 arg = args.next(None)
@@ -1007,15 +997,14 @@ def next( self, eof=ArgsRaise):
                 elif arg == '-v':
                     version = args.next()
                 elif arg == '--verbose':
-                    verbose = True
+                    g_verbose += 1
                 else:
                     assert 0, f'Unrecognised {arg=}'
-            python = wdev.WindowsPython(version=version, verbose=verbose)
+            python = wdev.WindowsPython(version=version)
             print(f'Python is:\n{python.description_ml("    ")}')
             
         elif command == 'windows-vs':
             grade = None
-            verbose = False
             version = None
             year = None
             while 1:
@@ -1029,16 +1018,16 @@ def next( self, eof=ArgsRaise):
                 elif arg == '-y':
                     year = args.next()
                 elif arg == '--verbose':
-                    verbose = True
+                    g_verbose += 1
                 else:
                     assert 0, f'Unrecognised {arg=}'
-            vs = wdev.WindowsVS(year=year, grade=grade, version=version, verbose=verbose)
+            vs = wdev.WindowsVS(year=year, grade=grade, version=version)
             print(f'Visual Studio is:\n{vs.description_ml("    ")}')
         
         else:
             assert 0, f'Unrecognised command: {command}'
 
-        _log(f'Finished handling command: {command}')
+        log2(f'Finished handling command: {command}')
 
 
     def __str__(self):
@@ -1462,7 +1451,7 @@ def build_extension(
             #   emcc: warning: ignoring unsupported linker flag: `-rpath` [-Wlinkflags]
             #   wasm-ld: error: unknown -z value: origin
             #
-            _log(f'## pyodide(): PEP-3149 suffix untested, so omitting. {_so_suffix()=}.')
+            log0(f'## pyodide(): PEP-3149 suffix untested, so omitting. {_so_suffix()=}.')
             path_so_leaf = f'_{name}.so'
             path_so = f'{outdir}/{path_so_leaf}'
             
@@ -1552,11 +1541,11 @@ def build_extension(
                         sublibraries.append( found[0])
                         break
                 else:
-                    _log(f'Warning: can not find path of lib={lib!r} in libpaths={libpaths}')
+                    log2(f'Warning: can not find path of lib={lib!r} in libpaths={libpaths}')
             macos_patch( path_so, *sublibraries)
 
-        run(f'ls -l {path_so}', check=0)
-        run(f'file {path_so}', check=0)
+        #run(f'ls -l {path_so}', check=0)
+        #run(f'file {path_so}', check=0)
     
     return path_so_leaf
 
@@ -1677,15 +1666,15 @@ def git_items( directory, submodules=False):
         # within submodules.
         #
         if not os.path.exists(path2):
-            _log(f'*** Ignoring git ls-files item that does not exist: {path2}')
+            log2(f'Ignoring git ls-files item that does not exist: {path2}')
         elif os.path.isdir(path2):
-            _log(f'*** Ignoring git ls-files item that is actually a directory: {path2}')
+            log2(f'Ignoring git ls-files item that is actually a directory: {path2}')
         else:
             ret.append(path)
     return ret
 
 
-def run( command, verbose=1, capture=False, check=1):
+def run( command, capture=False, check=1):
     '''
     Runs a command using `subprocess.run()`.
     
@@ -1700,18 +1689,14 @@ def run( command, verbose=1, capture=False, check=1):
 
             When running the command, on Windows newlines are replaced by
             spaces; otherwise each line is terminated by a backslash character.
-        verbose:
-            If true, outputs diagnostic describing the command before running
-            it.
         capture:
             If true, we return output from command.
     Returns:
         None on success, otherwise raises an exception.
     '''
     lines = _command_lines( command)
-    if verbose:
-        nl = '\n'
-        _log( f'Running: {nl.join(lines)}')
+    nl = '\n'
+    log2( f'Running: {nl.join(lines)}')
     sep = ' ' if windows() else '\\\n'
     command2 = sep.join( lines)
     if capture:
@@ -1760,13 +1745,13 @@ def __init__(self):
             self.ldflags = f'/LIBPATH:"{wp.root}\\libs"'
         
         elif pyodide():
-            _log(f'PythonFlags: Pyodide.')
             _include_dir = os.environ[ 'PYO3_CROSS_INCLUDE_DIR']
             _lib_dir = os.environ[ 'PYO3_CROSS_LIB_DIR']
-            _log( f'    {_include_dir=}')
-            _log( f'    {_lib_dir=}')
             self.includes = f'-I {_include_dir}'
             self.ldflags = f'-L {_lib_dir}'
+            log2(f'PythonFlags: Pyodide.')
+            log2( f'    {_include_dir=}')
+            log2( f'    {_lib_dir=}')
         
         else:
             # We use python-config which appears to work better than pkg-config
@@ -1789,7 +1774,7 @@ def __init__(self):
                         f'{sys.executable} {sysconfig.get_config_var("srcdir")}/python-config.py',
                         f'python3-config',
                         ):
-                    #_log(f'Trying: {pc=}')
+                    log2(f'Trying: {pc=}')
                     e = subprocess.run(
                             f'{pc} --includes',
                             shell=1,
@@ -1797,7 +1782,7 @@ def __init__(self):
                             stderr=subprocess.DEVNULL,
                             check=0,
                             ).returncode
-                    #_log(f'{e=}')
+                    log2(f'{e=}')
                     if e == 0:
                         python_config = pc
                 assert python_config, f'Cannot find python-config'
@@ -1816,11 +1801,11 @@ def __init__(self):
                 #
                 ldflags2 = self.ldflags.replace(' -lcrypt ', ' ')
                 if ldflags2 != self.ldflags:
-                    _log(f'### Have removed `-lcrypt` from ldflags: {self.ldflags!r} -> {ldflags2!r}')
+                    log2(f'### Have removed `-lcrypt` from ldflags: {self.ldflags!r} -> {ldflags2!r}')
                     self.ldflags = ldflags2
         
-        _log(f'{self.includes=}')
-        _log(f'{self.ldflags=}')
+        log2(f'{self.includes=}')
+        log2(f'{self.ldflags=}')
 
 
 def macos_add_cross_flags(command):
@@ -1834,7 +1819,7 @@ def macos_add_cross_flags(command):
         archflags = os.environ.get( 'ARCHFLAGS')
         if archflags:
             command = f'{command} {archflags}'
-            _log(f'Appending ARCHFLAGS to command: {command}')
+            log2(f'Appending ARCHFLAGS to command: {command}')
             return command
     return command
 
@@ -1851,7 +1836,7 @@ def macos_patch( library, *sublibraries):
         List of paths of shared libraries; these have typically been
         specified with `-l` when `library` was created.
     '''
-    _log( f'macos_patch(): library={library}  sublibraries={sublibraries}')
+    log2( f'macos_patch(): library={library}  sublibraries={sublibraries}')
     if not darwin():
         return
     subprocess.run( f'otool -L {library}', shell=1, check=1)
@@ -1872,11 +1857,11 @@ def macos_patch( library, *sublibraries):
         leaf = os.path.basename(name)
         m = re.match('^(.+[.]((so)|(dylib)))[0-9.]*$', leaf)
         assert m
-        _log(f'Changing {leaf=} to {m.group(1)}')
+        log2(f'Changing {leaf=} to {m.group(1)}')
         leaf = m.group(1)
         command += f' -change {name} @rpath/{leaf}'
     command += f' {library}'
-    _log( f'Running: {command}')
+    log2( f'Running: {command}')
     subprocess.run( command, shell=1, check=1)
     subprocess.run( f'otool -L {library}', shell=1, check=1)
 
@@ -1914,7 +1899,7 @@ def _cpu_name():
     return f'x{32 if sys.maxsize == 2**31 - 1 else 64}'
 
 
-def run_if( command, out, *prerequisites, verbose=True):
+def run_if( command, out, *prerequisites):
     '''
     Runs a command only if the output file is not up to date.
     
@@ -1939,29 +1924,30 @@ def run_if( command, out, *prerequisites, verbose=True):
         >>> out = 'run_if_test_out'
         >>> if os.path.exists( out):
         ...     os.remove( out)
-        >>> run_if( f'touch {out}', out, verbose=0)
+        >>> run_if( f'touch {out}', out)
         True
     
     If we repeat, the output file will be up to date so the command is not run:
     
-        >>> run_if( f'touch {out}', out, verbose=0)
+        >>> run_if( f'touch {out}', out)
     
     If we change the command, the command is run:
     
-        >>> run_if( f'touch  {out}', out, verbose=0)
+        >>> run_if( f'touch  {out}', out)
         True
     
     If we add a prerequisite that is newer than the output, the command is run:
     
         >>> prerequisite = 'run_if_test_prerequisite'
-        >>> run( f'touch {prerequisite}', verbose=0)
-        >>> run_if( f'touch {out}', out, prerequisite, verbose=0)
+        >>> run( f'touch {prerequisite}')
+        >>> run_if( f'touch {out}', out, prerequisite)
         True
     
     If we repeat, the output will be newer than the prerequisite, so the
     command is not run:
     
-        >>> run_if( f'touch {out}', out, prerequisite, verbose=1)
+        >>> verbose_set(2)
+        >>> run_if( f'touch {out}', out, prerequisite)
         pipcl.py: run_if(): Not running command because up to date: 'run_if_test_out'
     '''    
     doit = False
@@ -1995,9 +1981,9 @@ def _make_prerequisites(p):
         for p in prerequisites:
             prerequisites_all += _make_prerequisites( p)
         if 0:
-            _log( 'prerequisites_all:')
+            log2( 'prerequisites_all:')
             for i in  prerequisites_all:
-                _log( f'    {i!r}')
+                log2( f'    {i!r}')
         pre_mtime = 0
         pre_path = None
         for prerequisite in prerequisites_all:
@@ -2023,21 +2009,19 @@ def _make_prerequisites(p):
             os.remove( cmd_path)
         except Exception:
             pass
-        if verbose:
-            _log( f'Running command because: {doit}')
+        log2( f'Running command because: {doit}')
         
-        run( command, verbose=verbose)
+        run( command)
         
         # Write the command we ran, into `cmd_path`.
         with open( cmd_path, 'w') as f:
             f.write( command)
         return True
     else:
-        if verbose:
-            _log( f'Not running command because up to date: {out!r}')
+        log2( f'Not running command because up to date: {out!r}')
         
     if 0:
-        _log( f'out_mtime={time.ctime(out_mtime)} pre_mtime={time.ctime(pre_mtime)}.'
+        log2( f'out_mtime={time.ctime(out_mtime)} pre_mtime={time.ctime(pre_mtime)}.'
                 f' pre_path={pre_path!r}: returning {ret!r}.'
                 )
 
@@ -2100,14 +2084,36 @@ def _fs_mtime( filename, default=0):
     except OSError:
         return default
 
-def _log(text=''):
+g_verbose = 1
+
+def verbose(level=None):
+    '''
+    Sets verbose level if `level` is not None.
+    Returns verbose level.
+    '''
+    global g_verbose
+    if level is not None:
+        g_verbose = level
+    return g_verbose
+
+def log0(text=''):
+        _log(text, 1)
+
+def log1(text=''):
+        _log(text, 1)
+
+def log2(text=''):
+        _log(text, 2)
+
+def _log(text, level):
     '''
     Logs lines with prefix.
     '''
-    caller = inspect.stack()[1].function
-    for line in text.split('\n'):
-        print(f'pipcl.py: {caller}(): {line}')
-    sys.stdout.flush()
+    if g_verbose >= level:
+        caller = inspect.stack()[2].function
+        for line in text.split('\n'):
+            print(f'pipcl.py: {caller}(): {line}')
+        sys.stdout.flush()
 
 
 def _so_suffix():
@@ -2164,7 +2170,7 @@ class _Record:
     def __init__(self):
         self.text = ''
 
-    def add_content(self, content, to_, verbose=False):
+    def add_content(self, content, to_):
         if isinstance(content, str):
             content = content.encode('utf8')
         
@@ -2179,15 +2185,13 @@ def add_content(self, content, to_, verbose=False):
         digest = digest.decode('utf8')
         
         self.text += f'{to_},sha256={digest},{len(content)}\n'
-        if verbose:
-            _log(f'Adding {to_}')
+        log2(f'Adding {to_}')
 
-    def add_file(self, from_, to_, verbose=False):
+    def add_file(self, from_, to_):
         with open(from_, 'rb') as f:
             content = f.read()
-        self.add_content(content, to_, verbose=False)
-        if verbose:
-            _log(f'Adding file: {os.path.relpath(from_)} => {to_}')
+        self.add_content(content, to_)
+        log2(f'Adding file: {os.path.relpath(from_)} => {to_}')
 
     def get(self, record_path=None):
         '''

From ea89804ee1334e8f9b0d31e0b3a93264279ded1e Mon Sep 17 00:00:00 2001
From: Julian Smith <julian.smith@artifex.com>
Date: Tue, 26 Sep 2023 17:16:11 +0100
Subject: [PATCH 2/5] pipcl.py: fix for wheel creation and multi-line license
 text.

---
 pipcl.py | 35 ++++++++++++++++++++++-------------
 1 file changed, 22 insertions(+), 13 deletions(-)

diff --git a/pipcl.py b/pipcl.py
index c94d84d87..26109b0c2 100644
--- a/pipcl.py
+++ b/pipcl.py
@@ -314,7 +314,9 @@ def __init__(self,
             maintainer_email:
                 Maintainer email.
             license:
-                A string containing the license text.
+                A string containing the license text. Written into metadata
+                file `COPYING`. Is also written into metadata itself if not
+                multi-line.
             classifier:
                 A string or list of strings. Also see:
 
@@ -626,9 +628,9 @@ def add_str(content, to_):
         log1( f'Have created wheel size={st.st_size}: {path}')
         if g_verbose >= 2:
             with zipfile.ZipFile(path, compression=self.wheel_compression) as z:
-                _log2(f'Contents are:')
+                log2(f'Contents are:')
                 for zi in sorted(z.infolist(), key=lambda z: z.filename):
-                    _log2(f'    {zi.file_size: 10d} {zi.filename}')
+                    log2(f'    {zi.file_size: 10d} {zi.filename}')
         
         return os.path.basename(path)
 
@@ -1078,15 +1080,22 @@ def _metainfo(self):
         #
         ret = ['']
         def add(key, value):
-            if value is not None:
-                if isinstance( value, (tuple, list)):
-                    for v in value:
-                        add( key, v)
-                else:
-                    assert '\n' not in value, f'key={key} value contains newline: {value!r}'
-                    if key == 'Project-URL':
-                        assert value.count(',') == 1, f'For {key=}, should have one comma in {value!r}.'
-                    ret[0] += f'{key}: {value}\n'
+            if value is None:
+                return
+            if isinstance( value, (tuple, list)):
+                for v in value:
+                    add( key, v)
+                return
+            if key == 'License' and '\n' in value:
+                # This is ok because we write `self.license` into
+                # *.dist-info/COPYING.
+                #
+                log1( f'Omitting license because contains newline(s).')
+                return
+            assert '\n' not in value, f'key={key} value contains newline: {value!r}'
+            if key == 'Project-URL':
+                assert value.count(',') == 1, f'For {key=}, should have one comma in {value!r}.'
+            ret[0] += f'{key}: {value}\n'
         #add('Description', self.description)
         add('Metadata-Version', '2.1')
         
@@ -2084,7 +2093,7 @@ def _fs_mtime( filename, default=0):
     except OSError:
         return default
 
-g_verbose = 1
+g_verbose = int(os.environ.get('PIPCL_VERBOSE', '2'))
 
 def verbose(level=None):
     '''

From ef86acd86fcfe8772b2c2e8f5a388343a443b63a Mon Sep 17 00:00:00 2001
From: Julian Smith <julian.smith@artifex.com>
Date: Tue, 26 Sep 2023 17:17:03 +0100
Subject: [PATCH 3/5] setup.py: use pipcl.git_items() instead of local code.

---
 setup.py | 39 +++------------------------------------
 1 file changed, 3 insertions(+), 36 deletions(-)

diff --git a/setup.py b/setup.py
index ddd5c557a..d748085a7 100755
--- a/setup.py
+++ b/setup.py
@@ -166,10 +166,12 @@
 
 import pipcl
 
+
 _log_prefix = None
 def log( text):
     global _log_prefix
     if not _log_prefix:
+        # This typically sets _log_prefix to `PyMuPDF/setup.py`.
         p = os.path.abspath( __file__)
         p, p1 = os.path.split( p)
         p, p0 = os.path.split( p)
@@ -329,41 +331,6 @@ def tar_extract(path, mode='r:gz', prefix=None, exists='raise'):
     return prefix_actual
 
 
-def get_gitfiles( directory, submodules=False):
-    '''
-    Returns list of all files known to git in <directory>; <directory> must be
-    somewhere within a git checkout.
-
-    Returned names are all relative to <directory>.
-
-    If <directory>.git exists we use git-ls-files and write list of files to
-    <directory>/jtest-git-files.
-
-    Otherwise we require that <directory>/jtest-git-files already exists.
-    '''
-    def is_within_git_checkout( d):
-        while 1:
-            #log( 'd={d!r}')
-            if not d:
-                break
-            if os.path.isdir( f'{d}/.git'):
-                return True
-            d = os.path.dirname( d)
-
-    if is_within_git_checkout( directory):
-        command = 'cd ' + directory + ' && git ls-files'
-        if submodules:
-            command += ' --recurse-submodules'
-        command += ' > jtest-git-files'
-        log( f'Running: {command}')
-        subprocess.run( command, shell=True, check=True)
-
-    with open( '%s/jtest-git-files' % directory, 'r') as f:
-        text = f.read()
-    ret = text.strip().split( '\n')
-    return ret
-
-
 def get_git_id( directory):
     '''
     Returns `(sha, comment, diff, branch)`, all items are str or None if not
@@ -453,7 +420,7 @@ def get_mupdf_tgz():
         log( f'Creating .tgz from git files in: {mupdf_local}')
         _fs_remove( mupdf_tgz)
         with tarfile.open( mupdf_tgz, 'w:gz') as f:
-            for name in get_gitfiles( mupdf_local, submodules=True):
+            for name in pipcl.git_items( mupdf_local, submodules=True):
                 path = os.path.join( mupdf_local, name)
                 if os.path.isfile( path):
                     f.add( path, f'mupdf/{name}', recursive=False)

From 8920a000dd8c215309296e5f3fc61dcb2da3d7dc Mon Sep 17 00:00:00 2001
From: Julian Smith <julian.smith@artifex.com>
Date: Tue, 26 Sep 2023 17:18:38 +0100
Subject: [PATCH 4/5] Added tests/test_insertimage.py:test_compress() and fix
 in rebased.

src/__init__.py: fixed _insert_image() in do_process_pixmap. Also made `log()`
show file:line:function().
---
 src/__init__.py           | 15 ++++++++++-----
 tests/test_insertimage.py | 20 ++++++++++++++++++++
 2 files changed, 30 insertions(+), 5 deletions(-)

diff --git a/src/__init__.py b/src/__init__.py
index cf4e3db75..5fd1e7710 100644
--- a/src/__init__.py
+++ b/src/__init__.py
@@ -14,8 +14,13 @@
 import zipfile
 
 
-def log( text):
-    print( f'mupdfpy: {text}', file=sys.stdout)
+def log( text, caller=1):
+    import inspect
+    frame_record = inspect.stack( context=0)[ caller]
+    filename    = frame_record.filename
+    line        = frame_record.lineno
+    function    = frame_record.function
+    print( f'{filename}:{line}:{function}: {text}', file=sys.stdout)
     sys.stdout.flush()
 
 # Try to detect if we are being used with current directory set to a mupdfpy/
@@ -7524,8 +7529,8 @@ def _insert_image(self,
             #log( 'do_process_pixmap')
             # process pixmap ---------------------------------
             arg_pix = pixmap.this
-            w = arg_pix.w
-            h = arg_pix.h
+            w = arg_pix.w()
+            h = arg_pix.h()
             digest = mupdf.fz_md5_pixmap2(arg_pix)
             md5_py = digest
             temp = digests.get(md5_py, None)
@@ -7538,7 +7543,7 @@ def _insert_image(self,
                 do_have_image = 0
             else:
                 if arg_pix.alpha() == 0:
-                    image = mupdf.fz_new_image_from_pixmap(arg_pix, mupdf.FzImage(0))
+                    image = mupdf.fz_new_image_from_pixmap(arg_pix, mupdf.FzImage())
                 else:
                     pm = mupdf.fz_convert_pixmap(
                             arg_pix,
diff --git a/tests/test_insertimage.py b/tests/test_insertimage.py
index 45f522547..8142448d4 100644
--- a/tests/test_insertimage.py
+++ b/tests/test_insertimage.py
@@ -25,3 +25,23 @@ def test_insert():
     bbox2 = fitz.Rect(info_list[1]["bbox"])
     assert bbox1 in r1
     assert bbox2 in r2
+
+def test_compress():
+    document = fitz.open(f'{scriptdir}/resources/2.pdf')
+    document_new = fitz.open()
+    for page in document:
+        pixmap = page.get_pixmap(
+                colorspace=fitz.csRGB,
+                dpi=72,
+                annots=False,
+                )
+        page_new = document_new.new_page(-1)
+        page_new.insert_image(rect=page_new.bound(), pixmap=pixmap)
+    document_new.save(
+            f'{scriptdir}/resources/2.pdf.compress.pdf',
+            garbage=3,
+            deflate=True,
+            deflate_images=True,
+            deflate_fonts=True,
+            pretty=True,
+            )

From 9d3f3ab598e11c7efe43b941ad97d92b64864c43 Mon Sep 17 00:00:00 2001
From: Julian Smith <julian.smith@artifex.com>
Date: Tue, 26 Sep 2023 17:39:36 +0100
Subject: [PATCH 5/5] Added test_2692() and fix rebase implementation.

Changed `fz_identity` to `mupdf.FzMatrix()` and use `mupdf.FzCookie()` instead
of `None.
---
 src/__init__.py       |  8 ++++----
 tests/test_general.py | 12 ++++++++++++
 2 files changed, 16 insertions(+), 4 deletions(-)

diff --git a/src/__init__.py b/src/__init__.py
index 5fd1e7710..9ce793b8d 100644
--- a/src/__init__.py
+++ b/src/__init__.py
@@ -13723,9 +13723,9 @@ def JM_pixmap_from_page(doc, page, ctm, cs, alpha, annots, clip):
 
     dev = mupdf.fz_new_draw_device(matrix, pix)
     if annots:
-        mupdf.fz_run_page(page, dev, fz_identity, NULL);
+        mupdf.fz_run_page(page, dev, mupdf.FzMatrix(), NULL);
     else:
-        fz_run_page_contents(ctx, page, dev, fz_identity, mupdf.FzCookie())
+        fz_run_page_contents(ctx, page, dev, mupdf.FzMatrix(), mupdf.FzCookie())
     mupdf.fz_close_device(dev)
     return pix
 
@@ -16236,7 +16236,7 @@ def JM_pixmap_from_display_list(
 
     if not mupdf.fz_is_infinite_rect(rclip):
         dev = mupdf.fz_new_draw_device_with_bbox(matrix, pix, irect)
-        mupdf.fz_run_display_list(list_, dev, fz_identity, rclip, None)
+        mupdf.fz_run_display_list(list_, dev, mupdf.FzMatrix(), rclip, mupdf.FzCookie())
     else:
         dev = mupdf.fz_new_draw_device(matrix, pix)
         mupdf.fz_run_display_list(list_, dev, mupdf.FzMatrix(), mupdf.FzRect(mupdf.FzRect.Fixed_INFINITE), mupdf.FzCookie())
@@ -20518,7 +20518,7 @@ def _derotate_matrix(page):
         if isinstance(page, mupdf.PdfPage):
             return JM_py_from_matrix(JM_derotate_page_matrix(page))
         else:
-            return JM_py_from_matrix(fz_identity)
+            return JM_py_from_matrix(mupdf.FzMatrix())
 
     @staticmethod
     def _fill_widget(annot, widget):
diff --git a/tests/test_general.py b/tests/test_general.py
index b1409dd74..797ce64bf 100644
--- a/tests/test_general.py
+++ b/tests/test_general.py
@@ -511,3 +511,15 @@ def test_2430():
     font = fitz.Font("helv")
     for i in range(1000):
         _ = font.flags
+
+def test_2692():
+    document = fitz.Document(f'{scriptdir}/resources/2.pdf')
+    for page in document:
+        pix = pix = page.get_pixmap(clip=fitz.Rect(0,0,10,10))
+        dl = page.get_displaylist(annots=True)
+        pix = dl.get_pixmap(
+                matrix=fitz.Identity,
+                colorspace=fitz.csRGB,
+                alpha=False,
+                clip=fitz.Rect(0,0,10,10),
+                )