Logging errors in tests

[astrojuanlu]

These don't break the test runs (I believe?) but I have observed numerous instances of things like:

--- Logging error ---
Traceback (most recent call last):
  File "/home/circleci/.pyenv/versions/3.8.12/lib/python3.8/logging/__init__.py", line 1085, in emit
    msg = self.format(record)
  File "/home/circleci/.pyenv/versions/3.8.12/lib/python3.8/logging/__init__.py", line 929, in format
    return fmt.format(record)
  File "/home/circleci/.pyenv/versions/3.8.12/lib/python3.8/logging/__init__.py", line 668, in format
    record.message = record.getMessage()
  File "/home/circleci/.pyenv/versions/3.8.12/lib/python3.8/logging/__init__.py", line 373, in getMessage
    msg = msg % self.args
TypeError: must be real number, not str
Call stack:
  File "/home/circleci/project/.tox/py36/bin/pytest", line 8, in <module>
    sys.exit(console_main())
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/_pytest/config/__init__.py", line 185, in console_main
    code = main()
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/_pytest/config/__init__.py", line 162, in main
    ret: Union[ExitCode, int] = config.hook.pytest_cmdline_main(
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/pluggy/_hooks.py", line 265, in __call__
    return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/pluggy/_manager.py", line 80, in _hookexec
    return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/pluggy/_callers.py", line 39, in _multicall
    res = hook_impl.function(*args)
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/_pytest/main.py", line 316, in pytest_cmdline_main
    return wrap_session(config, _main)
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/_pytest/main.py", line 269, in wrap_session
    session.exitstatus = doit(config, session) or 0
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/_pytest/main.py", line 323, in _main
    config.hook.pytest_runtestloop(session=session)
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/pluggy/_hooks.py", line 265, in __call__
    return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/pluggy/_manager.py", line 80, in _hookexec
    return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/pluggy/_callers.py", line 39, in _multicall
    res = hook_impl.function(*args)
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/_pytest/main.py", line 348, in pytest_runtestloop
    item.config.hook.pytest_runtest_protocol(item=item, nextitem=nextitem)
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/pluggy/_hooks.py", line 265, in __call__
    return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/pluggy/_manager.py", line 80, in _hookexec
    return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/pluggy/_callers.py", line 39, in _multicall
    res = hook_impl.function(*args)
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/_pytest/runner.py", line 109, in pytest_runtest_protocol
    runtestprotocol(item, nextitem=nextitem)
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/_pytest/runner.py", line 126, in runtestprotocol
    reports.append(call_and_report(item, "call", log))
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/_pytest/runner.py", line 215, in call_and_report
    call = call_runtest_hook(item, when, **kwds)
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/_pytest/runner.py", line 254, in call_runtest_hook
    return CallInfo.from_call(
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/_pytest/runner.py", line 311, in from_call
    result: Optional[TResult] = func()
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/_pytest/runner.py", line 255, in <lambda>
    lambda: ihook(item=item, **kwds), when=when, reraise=reraise
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/pluggy/_hooks.py", line 265, in __call__
    return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/pluggy/_manager.py", line 80, in _hookexec
    return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/pluggy/_callers.py", line 39, in _multicall
    res = hook_impl.function(*args)
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/_pytest/runner.py", line 162, in pytest_runtest_call
    item.runtest()
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/pytest_django/plugin.py", line 490, in non_debugging_runtest
    self._testcase(result=self)
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/django/test/testcases.py", line 271, in __call__
    super().__call__(result)
  File "/home/circleci/.pyenv/versions/3.8.12/lib/python3.8/unittest/case.py", line 736, in __call__
    return self.run(*args, **kwds)
  File "/home/circleci/.pyenv/versions/3.8.12/lib/python3.8/unittest/case.py", line 676, in run
    self._callTestMethod(testMethod)
  File "/home/circleci/.pyenv/versions/3.8.12/lib/python3.8/unittest/case.py", line 633, in _callTestMethod
    method()
  File "/home/circleci/.pyenv/versions/3.8.12/lib/python3.8/unittest/mock.py", line 1325, in patched
    return func(*newargs, **newkeywargs)
  File "/home/circleci/project/readthedocs/rtd_tests/tests/test_celery.py", line 577, in test_build_tools
    result = tasks.update_docs_task.delay(
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/celery/app/task.py", line 422, in delay
    return self.apply_async(args, kwargs)
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/celery/app/task.py", line 569, in apply_async
    return self.apply(args, kwargs, task_id=task_id or uuid(),
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/celery/app/task.py", line 790, in apply
    ret = tracer(task_id, args, kwargs, request)
  File "/home/circleci/project/.tox/py36/lib/python3.8/site-packages/celery/app/trace.py", line 450, in trace_task
    R = retval = fun(*args, **kwargs)
  File "/home/circleci/project/readthedocs/projects/tasks.py", line 456, in update_docs_task
    return step.run(version_pk, *args, **kwargs)
  File "/home/circleci/project/readthedocs/projects/tasks.py", line 604, in run
    self.run_build(record=record)
  File "/home/circleci/project/readthedocs/projects/tasks.py", line 795, in run_build
    self.setup_build()
  File "/home/circleci/project/readthedocs/projects/tasks.py", line 1181, in setup_build
    self.setup_python_environment()
  File "/home/circleci/project/readthedocs/projects/tasks.py", line 1203, in setup_python_environment
    self.python_env.install_build_tools()
  File "/home/circleci/project/readthedocs/doc_builder/python_environments.py", line 133, in install_build_tools
    log.debug(
Message: 'Cached version for tool not found. os=%s tool=%s version=% filename=%s'
Arguments: ('ubuntu-20.04', 'nodejs', '16.9.1', 'ubuntu-20.04-nodejs-16.9.1.tar.gz')

I suppose this is just a problem with the tests, but I'm not 100 % sure.

[humitos]

Good catch! There is a typo in version=%, that should have an s. I don't think this will exist anymore after merging #8705, tho.