pass exc_info along when logging exs, dont split and log tb separately

[bninja]

ends up looking like this now as single log msg:

2014-09-30 07:03:06,891 : ERROR : paramiko.transport : 16813 : Thread-2 : Exception: Error reading SSH protocol banner
Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/paramiko/transport.py", line 1582, in run
    self._check_banner()
  File "/usr/local/lib/python2.7/dist-packages/paramiko/transport.py", line 1707, in _check_banner
    raise SSHException('Error reading SSH protocol banner' + str(e))
SSHException: Error reading SSH protocol banner

closes #405

[lndbrg]

I think this was done to get nicely formatted log messages. The only mention of it is in the old changelog about adding it.

If we want to do this, we should remove all usages of tb_strings and the function:

$ ag tb_strings
ChangeLog.1
2855:    also i put bit_length into util and a tb_strings function which gets stack

paramiko/server.py
652:            self.__transport._log(ERROR, util.tb_strings())

paramiko/sftp_server.py
106:                self._log(DEBUG, util.tb_strings())
114:                self._log(DEBUG, util.tb_strings())

paramiko/util.py
142:def tb_strings():

paramiko/transport.py
1634:                self._log(ERROR, util.tb_strings())
1638:                #self._log(DEBUG, util.tb_strings())
1652:                self._log(ERROR, util.tb_strings())

[bitprophet]

Good catch @lndbrg. I'm still +1 on moving forward with it (see my comments on the original ticket #405) but open to counterarguments. I just don't see what good it does any actual log consumers to have each TB line as its own log event :)

[lndbrg]

I agree, I read those comments before hand. :)

While I do think that the log locks nicer with the exceptions logged line for line, it's not really that usable. I'm also +1, if we remove the rest of the calls to that function.

[bninja]

removed util.tb_strings and replaced w/ exc_info=

[bitprophet]

Thanks, that looks okay. I'd like a test for this; either @bninja can do it or I can do it whenever I merge. (No ETA on the 2.0 feature milestone right now but probably sometime this month, hopefully sooner.)

[exhuma]

Small improvment on the PR: You can simply use exc_info=True instead of exc_info=sys.exc_info().

Also, is there any update on this? We've been struggling with this on our ELK stack as the splitting causes log-entries for every single line in the traceback. But what's worse, it make log entries not searchable. I was writing up a bug report but did not see that there was already #405 until I finished writing it and GitHub pointing out the similarity to me ;)

I had written down a detail on it, and even though it is redundant with everything said in #405 I will copy/paste it below anyway, because it contains screenshots from how this affects ELK:

---

In some exceptions, the traceback is split into lines and each line is logged separately. For example:

• paramiko/paramiko/transport.py

  Line 2130 in ca304fe

  self._log(ERROR, util.tb_strings())

• paramiko/paramiko/transport.py

  Line 2147 in ca304fe

  self._log(ERROR, util.tb_strings())

The lines pass the traceback to util.tb_strings which has a return-type of List[str]. That return-value is passed to Transport._log which then logs each element of that list as a separate log line.

Fragmenting the traceback-message like this makes it almost impossible to search for log messages in a solution like an ELK stack. It also artificially inflates the count of error-messages considerably (which we monitor). See the following screenshot for example:

With messages like these, I cannot apply any useful filtering because if I do, I get only a fragment of the traceback. If I add a filter for SSHConnectionError, I get the following search result which is only one line of the traceback, and not having the full traceback is really problematic.

A better solution would be to use exc_info=True (or exc_info=the_exception_instance) in the log-statements. This will properly log the exception traceback as one field to an ELK stack, and also log it to the console, as mentioned in logging.Formatter.format:

[...] If there is exception information, it is formatted using formatException() and appended to the message. [...]

A quick "grep" around the code-base also shows that util.tb_strings is only used in logging of exceptions, so making use of exc_info=True in the log-statements would make this function redundant.