Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

caplog fails on getting caplog.messages with str.format() log record #3397

Closed
gurobokum opened this issue Feb 25, 2020 · 3 comments · Fixed by #3487
Closed

caplog fails on getting caplog.messages with str.format() log record #3397

gurobokum opened this issue Feb 25, 2020 · 3 comments · Fixed by #3487
Assignees
Labels
bug Did we break something? p1-important Important, aka current backlog of things to do testing Related to the tests and the testing infrastructure

Comments

@gurobokum
Copy link
Contributor

Description

In dvc we can use logger.info as

logger.info("{} in str.format()", "log")

because of the custom formatter
but caplog uses default LogRecord.getMessage()

if self.args:
      msg = msg % self.args 

and fails in tests on getting caplog.messages

Steps to reproduce

Create a file with content

def test_caplog(caplog):
    import logging
    logger = logging.getLogger()

    with caplog.at_level(logging.INFO):
        logger.info("This shouldn't fail {}", 1)

    assert len(caplog.messages) == 1

Run it

pytest test_caplog

Produces an error like

test_caplog.py:8:                                                                                                                                      
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
../../../.pyenv/versions/3.7.6/envs/dvc/lib/python3.7/site-packages/_pytest/logging.py:387: in messages                                                
    return [r.getMessage() for r in self.records]                                                                                                      
../../../.pyenv/versions/3.7.6/envs/dvc/lib/python3.7/site-packages/_pytest/logging.py:387: in <listcomp>                                              
    return [r.getMessage() for r in self.records]   
....
>           msg = msg % self.args                                                                                           
E           TypeError: not all arguments converted during string formatting                                                 
                                                                                                                           
../../../.pyenv/versions/3.7.6/lib/python3.7/logging/__init__.py:369: TypeError

Info

$ dvc --version
0.86.2+002dd8.mod
@triage-new-issues triage-new-issues bot added the triage Needs to be triaged label Feb 25, 2020
@efiop efiop added bug Did we break something? p1-important Important, aka current backlog of things to do labels Feb 28, 2020
@triage-new-issues triage-new-issues bot removed the triage Needs to be triaged label Feb 28, 2020
@efiop
Copy link
Contributor

efiop commented Feb 28, 2020

Most likely related to our handler using a special non-default format for lazy logging. Need to switch to the default one, to be compatible with default handlers.

@efiop efiop added the testing Related to the tests and the testing infrastructure label Feb 28, 2020
@skshetry
Copy link
Member

Need to switch to the default one, to be compatible with default handlers.

You mean, to move to percent-formatted strings?

@efiop
Copy link
Contributor

efiop commented Mar 12, 2020

@skshetry Yeah, probably would do that to avoid messing around with different loggers. Could use their version of {} too though.

@efiop efiop self-assigned this Mar 16, 2020
efiop added a commit to efiop/dvc that referenced this issue Mar 16, 2020
Unfortunately overriding `format` is not enough in order to use our own
custom formatting in logger. `Record` uses percent formatting that is
hardcoded inside, so we would also have to override it, which is just
way too much effort that will inevitably break as we discover other
methods that are not ready for non-% formatting. So we are just giving
up and sticking to default %-formatting for lazy log messages.

Fixes iterative#3397
efiop added a commit that referenced this issue Mar 16, 2020
Unfortunately overriding `format` is not enough in order to use our own
custom formatting in logger. `Record` uses percent formatting that is
hardcoded inside, so we would also have to override it, which is just
way too much effort that will inevitably break as we discover other
methods that are not ready for non-% formatting. So we are just giving
up and sticking to default %-formatting for lazy log messages.

Fixes #3397
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Did we break something? p1-important Important, aka current backlog of things to do testing Related to the tests and the testing infrastructure
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants