log_file_format does not default to log_format

[schaetzc]

Problem

Pytest's documentation states (emphasis mine)

specify --log-cli-format and --log-cli-date-format which mirror and default to --log-format and --log-date-format if not provided, but are applied only to the console logging handler
[...]
--log-file-format and --log-file-date-format which are equal to --log-format and --log-date-format but are applied to the log file logging handler

This works as intended with the --log-cli-... options: When I have a pytest.ini file with log_cli = true and run pytest --log-format "%(message)s" the console uses the specified format, even though I did not specify --log-cli-format, but the more general --log-format.
For the --log-file-... options, I interpreted the wording "equal" just the same as I interpreted "mirror and default to", so I was very surprised that pytest --log-file log.txt --log-format "%(message)s" did not change the log format of log.txt.

I debugged into _pytest and found that the option is queried using log_file_format = get_option_ini(config, "log_file_format", "log_format") which indicates that my interpretation of the documentation is the intended behavior. However, contrary to log_cli_format, the log_file_format option is defined with a default=DEFAULT_LOG_FORMAT. This causes get_option_ini to return the default for log_file_format in every case. The additionally specified fallback log_format is never checked.

From git blame it seems the commit "Merge the pytest-catchlog plugin" introduced the bug (?) 6 years ago, affecting every version from 3.3.0 till today (). But as the name suggests, that commit did not really change the code, but only directly included it into the _pytest project. So the bug is even older than that.

Minimal Reproducible Example

Here is a minimal script reproduce the unexpected behavior. I used Python 3.9 on Windows 10, but that should be irrelevant here.

Create an empty directory and add a file test_logging.py with content

import logging
def test_format():
    logging.error('my message')

Then run this powershell script in that directory. You should be able to run this script with minimal changes in a posix sh shell on Linux too (e.g. python3 instead of python and source venv/bin/activate instead of venv/Scripts/activate).

python -m venv venv
venv\Scripts\activate
pip install pytest
pip freeze
pytest --log-file log.txt --log-format "%(message)s"
type log.txt

This is the relevant output from pytest freeze

colorama==0.4.6
exceptiongroup==1.1.3
iniconfig==2.0.0
packaging==23.1
pluggy==1.2.0
pytest==7.4.0
tomli==2.0.1

and type log.txt:

ERROR    root:test_logging.py:3 my message

As you can see, the custom log format wasn't used for the file. Instead, pytest's DEFAULT_LOG_FORMAT was used.
When I specify --log-file-format "%(message)s instead, I get the expected log.txt:

my message

Solution

Remove the default value for --log-file-format so that it falls back to --log-format and only uses the default format if neither of them are defined. Same for --log-file-date-format.
_{If you want to do it like this, I can create a pull request for you. I only created this issue first, in case you wanted to keep the behavior; see below:}

Alternative: officially declare the bug as a feature, update the documentation, and remove the dead fallbacks to the general log_format/log_date_format options from the code.
_{I would be really sad if you went with the latter option. But it would be understandable, because the bug is ancient and I couldn't find any complains about this yet.}

[Zac-HD]

Hi @schaetzc - thanks for your detailed investigation and writeup! Your proposed solution sounds great, and I'd be happy to receive a PR for it 🤩 Due to the age of the problem I've tagged this as an enhancement rather than a bugfix, but looking forward to the patch either way.

[SharadNair7]

Hi @schaetzc - are you still working on this fix / enhancement? If not, maybe i can pitch in to fix this if that's ok.

Regards

[schaetzc]

Hello @SharadNair7, thank you for the offer, that would be a huge help!

I wanted to create the pull request for a while now, but never found the time to work on it. I didn't even start yet. This will probably go on for the next weeks, so I'm really happy that you can pitch in.

Looking forward to your pull request :)

[SharadNair7]

Thank you @schaetzc, for your response. I will work on this issue then.

Regards

[SharadNair7]

Hello @Zac-HD , @schaetzc,

I have create a PR (#11444) for resolving this issue. While fixing this, i noticed that the generic log_level option is also ignored as a fallback by file logging. The PR has details about the fix and a concern that i noticed in one of the test cases.

Regards
Sharad

[Zac-HD]

Closed by #11444 🎉