#423 Some weird Copr Backend tracebacks
Closed 5 years ago Opened 5 years ago by praiskup.

Is this familiar to anyone? I have a feeling that the "even" CustomFilter is broken, but I need to analyze more. Btw. the /var/log/copr-backend/logger.log is empty on our coprbe.

Sep 27 08:41:31 coprbe.devel.redhat.com copr_run_logger.py[16189]: --- Logging error ---
Sep 27 08:41:31 coprbe.devel.redhat.com copr_run_logger.py[16189]: Traceback (most recent call last):
Sep 27 08:41:31 coprbe.devel.redhat.com copr_run_logger.py[16189]:   File "/usr/lib64/python3.6/logging/__init__.py", line 993, in emit
Sep 27 08:41:31 coprbe.devel.redhat.com copr_run_logger.py[16189]:     msg = self.format(record)
Sep 27 08:41:31 coprbe.devel.redhat.com copr_run_logger.py[16189]:   File "/usr/lib64/python3.6/logging/__init__.py", line 839, in format
Sep 27 08:41:31 coprbe.devel.redhat.com copr_run_logger.py[16189]:     return fmt.format(record)
Sep 27 08:41:31 coprbe.devel.redhat.com copr_run_logger.py[16189]:   File "/usr/lib64/python3.6/logging/__init__.py", line 576, in format
Sep 27 08:41:31 coprbe.devel.redhat.com copr_run_logger.py[16189]:     record.message = record.getMessage()
Sep 27 08:41:31 coprbe.devel.redhat.com copr_run_logger.py[16189]:   File "/usr/lib64/python3.6/logging/__init__.py", line 338, in getMessage
Sep 27 08:41:31 coprbe.devel.redhat.com copr_run_logger.py[16189]:     msg = msg % self.args
Sep 27 08:41:31 coprbe.devel.redhat.com copr_run_logger.py[16189]: TypeError: not enough arguments for format string
Sep 27 08:41:31 coprbe.devel.redhat.com copr_run_logger.py[16189]: Call stack:
Sep 27 08:41:31 coprbe.devel.redhat.com copr_run_logger.py[16189]:   File "/usr/bin/copr_run_logger.py", line 15, in <module>
Sep 27 08:41:31 coprbe.devel.redhat.com copr_run_logger.py[16189]:     main()
Sep 27 08:41:31 coprbe.devel.redhat.com copr_run_logger.py[16189]:   File "/usr/bin/copr_run_logger.py", line 11, in main
Sep 27 08:41:31 coprbe.devel.redhat.com copr_run_logger.py[16189]:     handler.run()
Sep 27 08:41:31 coprbe.devel.redhat.com copr_run_logger.py[16189]:   File "/usr/share/copr/backend/daemons/log.py", line 130, in run
Sep 27 08:41:31 coprbe.devel.redhat.com copr_run_logger.py[16189]:     self.handle_msg(raw)
Sep 27 08:41:31 coprbe.devel.redhat.com copr_run_logger.py[16189]:   File "/usr/share/copr/backend/daemons/log.py", line 115, in handle_msg
Sep 27 08:41:31 coprbe.devel.redhat.com copr_run_logger.py[16189]:     self.router_logger.log(level, msg, extra={"event": event})
Sep 27 08:41:31 coprbe.devel.redhat.com copr_run_logger.py[16189]: Message: 'VM terminated %s, time elapsed: %s '
Sep 27 08:41:31 coprbe.devel.redhat.com copr_run_logger.py[16189]: Arguments: [{'ip': '10.8.254.15', 'vm_name': '501'}, 2.3099896907806396]

This is the problem:

>>> json.loads(json.dumps(()))
[]

That said, since we now use the lazy logging string evaluation, we have to manually convert args from string to tuple, otherwise the python's "%s %s" % [1, 2] doesn't work.

Metadata Update from @praiskup:
- Issue status updated to: Closed (was: Open)

5 years ago

Login to comment on this ticket.

Metadata
Related Pull Requests
  • #424 Merged 5 years ago