Repository: rollbar/pyrollbar

Issue:
Meaningless message reported on HttpResponseBadRequest
`pyrollbar` reports ` %s: %s (/Library/Frameworks/Python.framework/Versions/*/lib/python*/site-packages/django/utils/log.py:log_response)` when the `HttpResponseBadRequest` is returned from the view in Django projects.

Discussion:
rokob: They are purposefully left unformatted for grouping. Usually the stuff that gets interpolated into the string varies per request but the actual reason for the error/message is more closely associated with the generic format string. So if you had `some error occurred @ %d` and you put in the current timestamp, grouping works better on that format string rather than `some error occurred @ 180948384`. Sometimes this doesn't work as well, but most of the time the raw format string is what you want as the message.

@brianr can probably explain better
ArturMoczulski: @brianr this was motivated by an issue escalated to the support team. The user didn't like having such meaningless items messages but it sounds like this actually what we need for grouping. What do you think?

I'd say being able to provide grouping is vital but at the same time having `%s: %s` items in the account dashboard is not ideal.

A cool idea would be to send the formatted messages additionally in the payload. Use the current message content to do grouping but then display the formatted message from the last or the first occurrence in the UI with some indicator `and there are X messages like this as well`. So:
1. We keep sending messages to Rollbar unformatted like `%s: %s` and do the grouping as it is
2. However, we also add `formatted_message` to the payload and use that to display the item name in the UI with an annotation that there are other messages grouped under this format that appear similar
ArturMoczulski: I believe the same could be achieved as well without sending `formatted_message` and just doing the placeholder replacement using already existing `body.message.body` and `body.args` specifically for Python messages
ArturMoczulski: @brianr any thoughts on this
arpadtamasi: Sure

> On Apr 25, 2019, at 7:42 AM, Artur Moczulski <notifications@github.com> wrote:
> 
> fix #311 <https://github.com/rollbar/pyrollbar/issues/311>
> Invoke logger formatters on the LogRecord to construct the Rollbar message.
> 
> Reason
> In Django HttpResponseBadRequest and other 400+ status code responses are logged using log_response("%s: %s", args). There are other calls to log_response in Django code of the same nature.
> 
> This results in items in Rollbar account like:
> #667 %s: %s (/lib/python*/site-packages/django/utils/log.py:log_response)
> #666 "%s" %s %s (/lib/python*/site-packages/django/core/servers/basehttp.py:log_message)
> 
> After applying the fromatter the messages become much more meaningful:
> #676 Bad Request: /rollbar/ (/lib/python*/site-packages/django/utils/log.py:log_response)
> #675 "GET /rollbar/ HTTP/1.1" 400 22 (/lib/python*/site-packages/django/core/servers/basehttp.py:log_message)
> 
> @rokob <https://github.com/rokob> is there a reason why messages were sent unformatted before? There was even a test for it. I'm not sure if I'm missing something here
> 
> You can view, comment on, or merge this pull request online at:
> 
>   https://github.com/rollbar/pyrollbar/pull/312 <https://github.com/rollbar/pyrollbar/pull/312>
> Commit Summary
> 
> fix(logging messages): apply logger formatting to Rollbar messages
> File Changes
> 
> M rollbar/logger.py <https://github.com/rollbar/pyrollbar/pull/312/files#diff-0> (2)
> M rollbar/test/test_loghandler.py <https://github.com/rollbar/pyrollbar/pull/312/files#diff-1> (4)
> Patch Links:
> 
> https://github.com/rollbar/pyrollbar/pull/312.patch <https://github.com/rollbar/pyrollbar/pull/312.patch>
> https://github.com/rollbar/pyrollbar/pull/312.diff <https://github.com/rollbar/pyrollbar/pull/312.diff>
> —
> You are receiving this because you are subscribed to this thread.
> Reply to this email directly, view it on GitHub <https://github.com/rollbar/pyrollbar/pull/312>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAC7XJKC65UELXLXAGCUPTDPSFAFBANCNFSM4HIJ4O5Q>.
> 


arpadtamasi: > They are purposefully left unformatted for grouping. Usually the stuff that gets interpolated into the string varies per request but the actual reason for the error/message is more closely associated with the generic format string. So if you had `some error occurred @ %d` and you put in the current timestamp, grouping works better on that format string rather than `some error occurred @ 180948384`. Sometimes this doesn't work as well, but most of the time the raw format string is what you want as the message.

I think it is a great idea to help grouping with sending the template that generated the message. Sending it instead of the message doesn't sound that great, however. It confuses the users and throws away possibly important information based on assumptions. (Example: A large amount of  the overgrouping reports come about messages where we ignored numbers and those numbers are actually HTTP error statuses. I don't have stats yet but working on it.)

The target audience is the user, not the grouping team so this is what I would prefer: send in the stack trace in a way that helps the app team to show it exactly the same way as it appears in the user's console (as a Scala user I don't get it now btw). Send the template only if we have access to it in a considerable amount of cases. My concern is that we don't and need to do NLP anyway.

@rokob I still like the idea that the SDK should help grouping, thanks for considering it.

ArturMoczulski: Thanks @arpadtamasi for your thoughts.

I also believe we can do better, especially when we have users directly saying this is confusing. 

@brianr @rokob this is just one pyrollbar example. Do you guys know of any other cases where we send a template instead of an actual message?

I think a better solution could be introduced where we provide both the template and the actual message. The template can be used by the grouping algos and the actual message of the last occurrence of an items could be displayed in the dashboard UI. What do you guys think?
ArturMoczulski: We just had another user bring up this problem. That's the second one this week.
pembo13: I'm one of those users, and this is what the error meessages looks like in Rollbar from Django (a supported web framework)

`#542 %s: %s (/****/****/lib*/python*/site-packages/django/utils/log.py:log_response)`

Reading the code, this a very generic log invocation point, grouping all these errors together would not make sense.

In this case, the args are:

`["Bad Request", "/campaigns/2/view"]`






ArturMoczulski: As a quick action, we decided to provide more meaningful messages in the occurrence description for now.

More long term, we will investigate the impact of not grouping this kind of messages at all.
ArturMoczulski: @pembo13 just to keep you updated, our Grouping team will be working on providing better messaging in the next sprint. It's not clear if we will be merging this PR actually, as they might be able to use the current code as is
pembo13: @ArturMoczulski thanks
mihow: Is there any resolution to this? We are seeing thousands of these reported as well. Thanks!
waltjones: Given @arpadtamasi's comments, and that not formatting the strings can cause overgrouping, I'm inclined to merge. As far as I know, none of the other SDKs leave messages unformatted like this.

Patch:
diff --git a/rollbar/logger.py b/rollbar/logger.py
index f646151..4b47241 100644
--- a/rollbar/logger.py
+++ b/rollbar/logger.py
@@ -139,7 +139,7 @@ class RollbarHandler(logging.Handler):
                                                extra_data=extra_data,
                                                payload_data=payload_data)
             else:
-                uuid = rollbar.report_message(record.msg,
+                uuid = rollbar.report_message(record.getMessage(),
                                               level=level,
                                               request=request,
                                               extra_data=extra_data,


Test patch:
diff --git a/rollbar/test/test_loghandler.py b/rollbar/test/test_loghandler.py
index b830713..5c3cf1c 100644
--- a/rollbar/test/test_loghandler.py
+++ b/rollbar/test/test_loghandler.py
@@ -42,13 +42,13 @@ class LogHandlerTest(BaseTest):
         return logger
 
     @mock.patch('rollbar.send_payload')
-    def test_message_stays_unformatted(self, send_payload):
+    def test_message_gets_formatted(self, send_payload):
         logger = self._create_logger()
         logger.warning("Hello %d %s", 1, 'world')
 
         payload = send_payload.call_args[0][0]
 
-        self.assertEqual(payload['data']['body']['message']['body'], "Hello %d %s")
+        self.assertEqual(payload['data']['body']['message']['body'], "Hello 1 world")
         self.assertEqual(payload['data']['body']['message']['args'], (1, 'world'))
         self.assertEqual(payload['data']['body']['message']['record']['name'], __name__)