1089577 - Debug logs should include displayed message

Status: RESOLVED FIXED

(Chat Core :: Security: OTR, defect)

Description

[aleth [:aleth]]

Especially when incoming messages are encrypted, debug logs are hard to read unless they also include the displayed version of messages.

It may be necessary to use a separate this.DEBUG call for this, but that doesn't matter as long as it's clear which already logged (encrypted) message that refers to.

You can add a pref if you'd like to turn this off by default for Tor.

Comment 1

[arlolra]

Attachment: debug.patch

Comment 2

[aleth [:aleth]]

Comment on attachment 8571673 [details] [diff] [review]
debug.patch

Review of attachment 8571673 [details] [diff] [review]:
-----------------------------------------------------------------

Just checking you've tested this works as expected with OTR installed?

::: chat/components/src/imConversations.js
@@ +441,5 @@
>    // UIConversation. This happens when this.systemMessage() is called. The
>    // conversation for the message is set as the UIConversation.
> +  prepareForDisplaying: function(aMsg) {
> +    if (aMsg.displayMessage !== aMsg.message)
> +      this.DEBUG("Displaying:\n" + aMsg.displayMessage + "\nFor:\n" + aMsg.message);

I'm not sure this one makes sense as is:
- is this.DEBUG even defined here?
- messages added by the UI don't appear in prpl debug logs anyway, do they?
- under what circumstances would a message passing through here have displayMessage != message?

::: chat/modules/jsProtoHelper.jsm
@@ +484,5 @@
>    prepareForSending: function(aOutgoingMessage, aCount) null,
> +  prepareForDisplaying: function(aImMessage) {
> +    if (aImMessage.displayMessage !== aImMessage.message)
> +      this.DEBUG("Displaying:\n" + aImMessage.displayMessage + "\nFor:\n" +
> +                 aImMessage.message);

If it's ensured this appears in the debug log directly after the incoming message, you likely don't need to include the 'raw' message a second time, and can simply say "Displayed as:". Or is there something async about this?

::: chat/protocols/irc/irc.js
@@ +132,5 @@
>             this._account.countBytes(baseMessage);
>    },
>    // Apply CTCP formatting before displaying.
>    prepareForDisplaying: function(aMsg) {
>      aMsg.displayMessage = ctcpFormatToHTML(aMsg.displayMessage);

Ask clokep whether we care about logging if displayMessage != message solely due to this ctcp call.

@@ +134,5 @@
>    // Apply CTCP formatting before displaying.
>    prepareForDisplaying: function(aMsg) {
>      aMsg.displayMessage = ctcpFormatToHTML(aMsg.displayMessage);
> +    if (aMsg.displayMessage !== aMsg.message)
> +      this.DEBUG("Displaying:\n" + aMsg.displayMessage + "\nFor:\n" + aMsg.message);

Instead of duplicating this code, call the prepareForDisplaying from jsProtoHelper.

Comment 3

[arlolra]

Comment on attachment 8571673 [details] [diff] [review]
debug.patch

Review of attachment 8571673 [details] [diff] [review]:
-----------------------------------------------------------------

> Just checking you've tested this works as expected with OTR installed?

Yes, I have on IRC with OTR enabled.

Thanks for the quick review.

::: chat/components/src/imConversations.js
@@ +441,5 @@
>    // UIConversation. This happens when this.systemMessage() is called. The
>    // conversation for the message is set as the UIConversation.
> +  prepareForDisplaying: function(aMsg) {
> +    if (aMsg.displayMessage !== aMsg.message)
> +      this.DEBUG("Displaying:\n" + aMsg.displayMessage + "\nFor:\n" + aMsg.message);

Good point. Part of the reason I duplicated this code in all the prpls was because DEBUG wasn't available in the uiConv and going through uiConv.account.logDebugMessage was cumbersome.

Silly that I then went and did this. Anyways, yes, removing.

::: chat/modules/jsProtoHelper.jsm
@@ +484,5 @@
>    prepareForSending: function(aOutgoingMessage, aCount) null,
> +  prepareForDisplaying: function(aImMessage) {
> +    if (aImMessage.displayMessage !== aImMessage.message)
> +      this.DEBUG("Displaying:\n" + aImMessage.displayMessage + "\nFor:\n" +
> +                 aImMessage.message);

The incoming path is probably sync. But outgoing isn't ...

::: chat/protocols/irc/irc.js
@@ +132,5 @@
>             this._account.countBytes(baseMessage);
>    },
>    // Apply CTCP formatting before displaying.
>    prepareForDisplaying: function(aMsg) {
>      aMsg.displayMessage = ctcpFormatToHTML(aMsg.displayMessage);

I suspect we don't.

@@ +134,5 @@
>    // Apply CTCP formatting before displaying.
>    prepareForDisplaying: function(aMsg) {
>      aMsg.displayMessage = ctcpFormatToHTML(aMsg.displayMessage);
> +    if (aMsg.displayMessage !== aMsg.message)
> +      this.DEBUG("Displaying:\n" + aMsg.displayMessage + "\nFor:\n" + aMsg.message);

Ok.

Comment 4

[arlolra]

Attachment: debug.patch from comment 3

Comment 5

[aleth [:aleth]]

Comment on attachment 8572112 [details] [diff] [review]
debug.patch from comment 3

Review of attachment 8572112 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks!

Comment 6

[aleth [:aleth]]

https://hg.mozilla.org/comm-central/rev/fb222d0daf7c

Comment 7

[Kent James (:rkent)]

Please back this out until the test is fixed.

Comment 8

[Florian Quèze [:florian]]

Backed out: https://hg.mozilla.org/comm-central/rev/635555c60eb2

Comment 9

[arlolra]

Attachment: debug.patch from comment 8

Ugh, so embarrassing. Sorry everyone.

The fake account in test_conversation.js needed a no-op DEBUG method.

Comment 10

[aleth [:aleth]]

https://hg.mozilla.org/comm-central/rev/dd2d7974c1ee

Comment 11

[aleth [:aleth]]

Please add the reviewer to the commit message next time! Thanks.