fab Improved logging

Jul 23 '25 15:07 t00sa

I would love to get that added to FabBase

Jul 24 '25 07:07 hiker

Adding a note to remind myself to check whether fab is reporting that it is recompiling items when all it is doing is calling a tool.

Oct 06 '25 16:10 t00sa

I've traced the misleading compilation messages to this section of the compile_pass() function in compile_fortran.py:

# what can we compile next?
compile_next = get_compile_next(compiled, uncompiled)

# compile
logger.info(f"\ncompiling {len(compile_next)} of {len(uncompiled)} "
            f"remaining files")
mp_args = [(fpath, mp_common_args) for fpath in compile_next]
results_this_pass = run_mp(config, items=mp_args, func=process_file)

This generates messages like compiling 10 of 178 remaining files regardless of how many of these files actually need compiling because the decision about whether to compile them is delegated to the process_file function, i.e.

# have we got all the prebuilt artefacts we need to avoid a recompile?
prebuilds_exist = list(map(lambda f: f.exists(),
                           [obj_file_prebuild] + mod_file_prebuilds))
if not all(prebuilds_exist):
    # compile
    try:
        logger.debug(f'CompileFortran compiling {analysed_file.fpath}')
        compile_file(analysed_file.fpath, flags,
                     output_fpath=obj_file_prebuild,
                     mp_common_args=mp_common_args)
    except Exception as err:
        return Exception(f"Error compiling {analysed_file.fpath}:\n"
                         f"{err}"), None

I've got an interim fix that adds an actually_compiled boolean to the return value of process_file(), moves the logging messages in compile_pass() to a point after the compilation attempt has been completed, allowing it to report the number of files checked, the number compiled, and the total number of files outstanding. For example, where everything has already been built:

2025-10-07 20:35:31,191 INFO compiling 178 fortran files
2025-10-07 20:35:31,191 INFO Fortran compiler is Gfortran - gfortran: /data/apps/spack/compilers/install/linux-rhel9-zen2/gcc-11.5.0/gcc-12.2.0-wwyf7gjcun7i6usswde5fnjsyfpsph33/bin/gfortran 12.2.0
2025-10-07 20:35:31,495 INFO checked 10 and built 0 of 178 files
2025-10-07 20:35:31,925 INFO checked 16 and built 0 of 168 files
2025-10-07 20:35:32,236 INFO checked 18 and built 0 of 152 files
2025-10-07 20:35:32,600 INFO checked 21 and built 0 of 134 files
2025-10-07 20:35:32,878 INFO checked 8 and built 0 of 113 files
2025-10-07 20:35:33,287 INFO checked 14 and built 0 of 105 files
2025-10-07 20:35:33,431 INFO checked 3 and built 0 of 91 files
2025-10-07 20:35:33,545 INFO checked 2 and built 0 of 88 files
2025-10-07 20:35:33,754 INFO checked 5 and built 0 of 86 files
2025-10-07 20:35:33,929 INFO checked 4 and built 0 of 81 files
2025-10-07 20:35:34,091 INFO checked 3 and built 0 of 77 files
2025-10-07 20:35:34,304 INFO checked 5 and built 0 of 74 files
2025-10-07 20:35:34,496 INFO checked 5 and built 0 of 69 files
2025-10-07 20:35:34,715 INFO checked 6 and built 0 of 64 files
2025-10-07 20:35:34,905 INFO checked 4 and built 0 of 58 files
2025-10-07 20:35:35,105 INFO checked 5 and built 0 of 54 files
2025-10-07 20:35:35,283 INFO checked 4 and built 0 of 49 files
2025-10-07 20:35:35,519 INFO checked 6 and built 0 of 45 files
2025-10-07 20:35:35,704 INFO checked 4 and built 0 of 39 files
2025-10-07 20:35:35,929 INFO checked 6 and built 0 of 35 files
2025-10-07 20:35:36,224 INFO checked 9 and built 0 of 29 files
2025-10-07 20:35:36,380 INFO checked 3 and built 0 of 20 files
2025-10-07 20:35:36,549 INFO checked 4 and built 0 of 17 files
2025-10-07 20:35:36,702 INFO checked 3 and built 0 of 13 files
2025-10-07 20:35:36,802 INFO checked 1 and built 0 of 10 files
2025-10-07 20:35:36,907 INFO checked 1 and built 0 of 9 files
2025-10-07 20:35:37,006 INFO checked 1 and built 0 of 8 files
2025-10-07 20:35:37,103 INFO checked 1 and built 0 of 7 files
2025-10-07 20:35:37,206 INFO checked 1 and built 0 of 6 files
2025-10-07 20:35:37,355 INFO checked 3 and built 0 of 5 files
2025-10-07 20:35:37,454 INFO checked 1 and built 0 of 2 files
2025-10-07 20:35:37,548 INFO checked 1 and built 0 of 1 files
2025-10-07 20:35:37,548 INFO Fortran compilation complete in 32 passes
2025-10-07 20:35:37,552 INFO compile_fortran completed in 6.367s

This seems to me to be clearer and more obvious than the old behaviour.

Oct 07 '25 19:10 t00sa

That's indeed better. I wonder if we should also add the number of pre-builds found, just to make it more obvious to the user what this means? ATM it sounds a bit like Fab decided not to compile (say) 10 files. What about:

2025-10-07 20:35:31,495 INFO checked 10, built 0 of 178 files, and used 10 prebuilds

Oct 09 '25 23:10 hiker

Additional question, maybe not related to this, but since you are looking at logging. In fab/mo.py I found:

from fab.dep_tree import AnalysedDependent, filter_source_tree, logger

And in dep_tree.py as expected:

logger = logging.getLogger(__name__)

While this works, wouldn't that mean that messages from mo.py would be having incorrect logging information? It probably doesn't matter ;) But I am wondering (since I just touched that file for #502) if I should fix this?

Oct 09 '25 23:10 hiker