Splitted logs from paramiko.transport

[shtoltz]

Original issue from 2014 - #405

when transport catches exceptions it splits tb into multiple strings:

paramiko/paramiko/transport.py

Lines 1633 to 1634 in 1af8db2

	self._log(ERROR, 'Exception: ' + str(e))
	self._log(ERROR, util.tb_strings())

which are then logged separately:

paramiko/paramiko/transport.py

Lines 1423 to 1428 in 1af8db2

	def _log(self, level, msg, *args):
	if issubclass(type(msg), list):
	for m in msg:
	self.logger.log(level, m)
	else:
	self.logger.log(level, msg, *args)

making it hard to e.g. filter a specific "error" in server mode.

would it make sense to just pass along whatever exc_info is being handled to logging and let it do formatting as a single msg?

This issue is closed although the linked PR was not merged.
Issue is still actual, especially with custom logging handlers or Sentry.

Examples:

1. Logging in json format

{"timestamp": "2022-05-17T18:50:23.269787Z", "level": "ERROR", "name": "paramiko.transport", "message": "Exception: Error reading SSH protocol banner"}
{"timestamp": "2022-05-17T18:50:23.272036Z", "level": "ERROR", "name": "paramiko.transport", "message": "Traceback (most recent call last):"}
{"timestamp": "2022-05-17T18:50:23.272207Z", "level": "ERROR", "name": "paramiko.transport", "message": "  File \"/home/shtoltz/work/paramiko_test/venv/lib/python3.9/site-packages/paramiko/transport.py\", line 2046, in run"}
{"timestamp": "2022-05-17T18:50:23.272354Z", "level": "ERROR", "name": "paramiko.transport", "message": "    self._check_banner()"}
{"timestamp": "2022-05-17T18:50:23.272497Z", "level": "ERROR", "name": "paramiko.transport", "message": "  File \"/home/shtoltz/work/paramiko_test/venv/lib/python3.9/site-packages/paramiko/transport.py\", line 2211, in _check_banner"}
{"timestamp": "2022-05-17T18:50:23.272676Z", "level": "ERROR", "name": "paramiko.transport", "message": "    raise SSHException("}
{"timestamp": "2022-05-17T18:50:23.272833Z", "level": "ERROR", "name": "paramiko.transport", "message": "paramiko.ssh_exception.SSHException: Error reading SSH protocol banner"}
{"timestamp": "2022-05-17T18:50:23.273012Z", "level": "ERROR", "name": "paramiko.transport", "message": ""}

should be:

{"timestamp": "2022-05-17T18:50:23.269787Z", "level": "ERROR", "name": "paramiko.transport", "message": "Exception: Error reading SSH protocol banner", "exc_info": "Traceback (most recent call last):\n  File \"/home/shtoltz/work/paramiko_test/venv/lib/python3.9/site-packages/paramiko/transport.py\", line 2046, in run\n    self._check_banner()\n  File \"/home/shtoltz/work/paramiko_test/venv/lib/python3.9/site-packages/paramiko/transport.py\", line 2211, in _check_banner\n    raise SSHException(\nparamiko.ssh_exception.SSHException: Error reading SSH protocol banner"}

2. Sentry
   

There are several PRs for this issue:

• pass exc_info along when logging exs, dont split and log tb separately #406 (2014, for original issue can transport log not split up error tracebacks? #405)
• pass exc_info along when logging exs, dont split and log tb separately (version 2) #1737 (2020)
• Create a single log entry when logging exceptions #1970 (2022)

Last PR (#1970) looks fine and AFAICS must work with supported python versions (2.7 and 3)
Can you please merge it or tell what needs to be fix?

[bskinn]

Triaged, thanks for the bump on this!

[SogoKato]

Hello,

Is the review for #1970 is scheduled? I would be happy if it would be released :)

[bskinn]

Yes, the PR is flagged for bitprophet to review when he gets a chance.

Unfortunately, I can't provide a timeline for a review on this, as bitprophet is in the middle of a modernization of his OSS projects, focused on dropping Python 2 and updating to modern Sphinx. We will get to it; I just can't say when.

[allanlewis]

This is causing a lot of noise in my exception handling tooling as it sees multiple errors when it should see only 1. Is anyone able to provide an update on this? It looks like the solution is well-described.

[allanlewis]

Sentry users might want to try ignoring the paramiko.transport logger.

[dolfinus]

Any updates here?