Patched _proxy_log to be more useful

[j0yu]

Problem

If proxy messages fail to log, the exception message logged does very little to help debug erroneous message formatting i.e. typically just be something like:

TypeError: not all arguments converted during string formatting
# or
TypeError: not enough arguments for format string

which unfortunately, is find for where error occured but terrible for figuring out how or what caused the error without jumping into a debugger to figure out the exact values of msg or *args:

1. When msg parameter in is not a string and gets erroneously expanded

   >>> msg = ("hello", "there")
   >>> "[PROXY] %s" % msg
   Traceback (most recent call last):
     File "<stdin>", line 1, in <module>
   TypeError: not all arguments converted during string formatting

2. Bad amounts of *args passed in for the final, "PROXY" pre-pended msg

   >>> import logging
   
   >>> logging.warn("[PROXY] %s", "more", "than", "1")
   Traceback (most recent call last):
     File "/usr/lib64/python2.7/logging/__init__.py", line 851, in emit
       msg = self.format(record)
     File "/usr/lib64/python2.7/logging/__init__.py", line 724, in format
       return fmt.format(record)
     File "/usr/lib64/python2.7/logging/__init__.py", line 464, in format
       record.message = record.getMessage()
     File "/usr/lib64/python2.7/logging/__init__.py", line 328, in getMessage
       msg = msg % self.args
   TypeError: not all arguments converted during string formatting
   Logged from file <stdin>, line 1
   
   >>> logging.warn("[PROXY] %s %s %s %s", "not enough")
   Traceback (most recent call last):
     File "/usr/lib64/python2.7/logging/__init__.py", line 851, in emit
       msg = self.format(record)
     File "/usr/lib64/python2.7/logging/__init__.py", line 724, in format
       return fmt.format(record)
     File "/usr/lib64/python2.7/logging/__init__.py", line 464, in format
       record.message = record.getMessage()
     File "/usr/lib64/python2.7/logging/__init__.py", line 328, in getMessage
       msg = msg % self.args
   TypeError: not enough arguments for format string
   Logged from file <stdin>, line 1

Because these are proxy messages, they tend to hide which Shotgun app/engine/framework is causing the error.

Changed

• Report level, message and arguments when logging proxy message log failures

Fixed

• Prepend [PROXY] using str.format instead of % to avoid potential expansion of msg
• args to be *args so when single, iterable argument is passed in, it doesn't get unnecessarily expanded e.g. a dict

[jfboismenu]

Hi,
Could you give an example of a situation where this muting of the error caused issues? I think this fix was introduced originally because an error was raised by the logger because the inputs weren't valid. Trying to serialize the parameters would likely rethrow the error.

[j0yu]

Sure! This patch is basically to make error messages more easy to debug bad msg or *args, which would typically just be something like:

TypeError: not all arguments converted during string formatting
# or
TypeError: not enough arguments for format string

which unfortunately, is find for where error occured but terrible for figuring out how or what caused the error without jumping into a debugger to figure out the exact values of msg or *args:

1. When msg parameter in is not a string and gets erroneously expanded

   >>> msg = ("hello", "there")
   >>> "[PROXY] %s" % msg
   Traceback (most recent call last):
     File "<stdin>", line 1, in <module>
   TypeError: not all arguments converted during string formatting

2. Bad amounts of *args passed in for the final, "PROXY" pre-pended msg

   >>> import logging
   
   >>> logging.warn("[PROXY] %s", "more", "than", "1")
   Traceback (most recent call last):
     File "/usr/lib64/python2.7/logging/__init__.py", line 851, in emit
       msg = self.format(record)
     File "/usr/lib64/python2.7/logging/__init__.py", line 724, in format
       return fmt.format(record)
     File "/usr/lib64/python2.7/logging/__init__.py", line 464, in format
       record.message = record.getMessage()
     File "/usr/lib64/python2.7/logging/__init__.py", line 328, in getMessage
       msg = msg % self.args
   TypeError: not all arguments converted during string formatting
   Logged from file <stdin>, line 1
   
   >>> logging.warn("[PROXY] %s %s %s %s", "not enough")
   Traceback (most recent call last):
     File "/usr/lib64/python2.7/logging/__init__.py", line 851, in emit
       msg = self.format(record)
     File "/usr/lib64/python2.7/logging/__init__.py", line 724, in format
       return fmt.format(record)
     File "/usr/lib64/python2.7/logging/__init__.py", line 464, in format
       record.message = record.getMessage()
     File "/usr/lib64/python2.7/logging/__init__.py", line 328, in getMessage
       msg = msg % self.args
   TypeError: not enough arguments for format string
   Logged from file <stdin>, line 1

[j0yu]

Because these are proxy messages, they tend to hide which Shotgun app/engine/framework is causing the error.

I guess you could also just add the full stack trace to after except Exception:, it would work too as you can the files leading up to the error but it might be fairly long and still won't show the values of the arguments that contributes the error