Log to console what would be sent to the server when raven isn't configured

[benoitg]

It helps a lot with local debugging of applications using raven.js, and allows developpers to see things captured by captureMessage.

Unite tested, and also improves on previous unit tests making sure that no exceptions are thrown when raven isn't configured.

[mattrobenolt]

Can we modify this test then to assert that window.makeRequest wasn't called? Since that's the changed behavior here.

[benoitg]

I wanted to, but I didn't manage to assert the called state on functions indirectly called by the test (maybe I just don't know the sinon test framework well enough, everytime I tried, functions indirectly called asways assert called called false, whether or now they were called). If someone points me in the right direction, I'm quite willing to make the change.

[mattrobenolt]

I mostly like this idea, just not sure I like the implementation. I think there is more value we can get out of this.

So we have this undocumented Raven.debug thing.

What if we added this console.log line into makeRequest instead?

Then we can always do a logDebug('debug', 'sending data', data) inside makeRequest().

I think there's value in being able to log the data being sent regardless of it being configured or not.

Do you have any thoughts on this?

[mattrobenolt]

Also worth noting that logDebug already guards against a browser without window.console accessible.

[benoitg]

No objection to using logDebug per see.

The problem I do have is having this dependent on Raven.debug. Aside from the documentation issue, setting Raven.debug true will spam the console with errors sent by isSetup(), which is called everywhere.

A solution if we don't want to change the output of the rest of the code until the meaning and behaviour of Raven.debug is clearer, I propose to add an override parameter to logDebug that would ignore Raven.debug

As for calling it from makeRequest(), there is essentially not a single line in makeRequest we actually want to run when isSetup() is false. That's why I put the check in send().

Now when isSetup() is true:
a) If you really want to log the value of src, I can move it into makeRequest (making essentially the whole body of makeRequest conditional).
or
b) If logging src isn't important, I'd just change the conditions in send to send to log if either isSetup is false OR Raven.debug is true

Would that work for you?

[benoitg]

@mattrobenolt Ok, I think I made (or obsoleted) most changes discussed.

I don't want to be pushy, but the nature of this patch forced me to rebase 3 times already, with non trivial changes each time, so I'd be most grateful if you could review as quickly as possible.

[benvinegar]

@benoitg: Is the root issue here that you would like to debug your usage of Raven.captureMessage, without sending the data to Sentry?

[benoitg]

@benvinegar The scenario is that when developing (think on localhost) applications that use sentry, you have several issues (in order of decreasing importance):

1. Things like captureException are not totally neutral. When when sentry is operationnal, captureException is like a catch with a log. When sentry isn't configured (which is typically the case locally), it becomes a silent catch that makes exceptions invisible.
2. When using Raven.captureMessage, your logging becomes invisible. You can double log it (console.log + Raven.captureMessage), but can't use console.warn, console.error, etc. as that would still get caught but the console plugin. You end up with 3 lines (one to compose the string, one to console.log it, and one to captureMessage it), instead of one.
3. When coding raven logging, as a developer you can't see if any of the extra data you pass as context is correct without separately logging it, which is cumbersome. Especially important since it will ultimately only be available as strings once in Sentry (I can't count the number of times when a piece of data in my context ended up being [object Object] in actual sentry events.
4. While this is rare, I've had code misbehave only once sentry was actually configured, because most of raven.js's processing wasn't actually executed (can't remember the specific issue, but as raven.js ultimately does things like capture backtraces, it's not surprising that sometimes we can hit corner cases).

[benvinegar]

Okay, thanks for giving me a better understanding. And I appreciate you taking the time to put together this PR and work through it with us.

So, after looking everything over, I kind of agree with @mattrobenolt that this should be enabled by setting Raven.debug to true. I don't like that there's implicit debug logging without enabling it. And it seems like the only blocker to using Raven.debug is that isSetup spams a bunch of redundant log messages when debug mode is enabled.

So how about this ...

• We change isSetup to only output a warning once per page.
• Then we change makeRequest to output what would have been logged, if Raven.debug is true, regardless of whether Raven is configured.

Afterwards, we could encourage users developing locally to always have Raven.debug = true.

I can also complete the remaining work to make this happen. Your call.

Thoughts?

[benoitg]

@benvinegar Well, honestly I'd prefer that it depend on a different configuration parameter than Raven.debug (Raven.disableUnconfiguredConsoleOutput) whose default would be false. I believe someone without a server configured, and now wanting a console output to be a bit of a corner case for most applications.

That being said, your proposal does solve my problem also (setting Raven.debug when server in not configured isn't much of a burden for most people, ASSUMING this time we document Raven.debug), so if you disagree with the above, feel free to go ahead with your original proposal.

If you need anything from me, feel free to ask.

[benvinegar]

I believe someone without a server configured, and now wanting a console output to be a bit of a corner case for most applications.

I think my preference is to avoid extra configuration parameters – at least, until we're sure we need it. Right now Raven.debug does so little (literally only affects 2 calls to logDebug), so I think this is fair game.

I'm going to go ahead and make the changes I suggested, but by all means, lets come back to this in the future if it needs additional tweaking.

Thanks @benoitg.

[benvinegar]

Merged as part of #368

[benoitg]

@benvinegar Doesn't seem to be working. Still investigating, but at first glance logDebug error in isSetup seems to stop any further processing.

[benvinegar]

@benoitg I just fired up an example, and it seems to work for me:

<script src="../src/raven.js"></script>
<script>
Raven.captureException('test'); // NOTE: Raven not configured
</script>

I get this on the console:

Raven about to send: Object {project: undefined, logger: "javascript", platform: "javascript", request: Object, message: "hi"…}
Error: Raven has not been configured.

Am I missing something?

[benoitg]

@benvinegar it's not working for me in the real world. Maybe an interaction with raven plugins. I only get "Error: Raven has not been configured." Pull request #369 fixes it for me.

[benvinegar]

Right. But everything I've read suggests that console.error shouldn't interrupt control flow:

http://stackoverflow.com/questions/25377115/what-is-the-difference-between-throw-error-and-console-error
https://developer.mozilla.org/en-US/docs/Web/API/Console/error

I'd rather find the true source of the bug, if possible. Are your pages public anywhere? Or can you try to recreate in a limited example?

[benvinegar]

It's also worth pointing out that this would have absolutely triggered test failures:

it('should log an error message, the first time it is called', function () {
  hasJSON = true;
  globalServer = undefined;
  isSetup();
  isSetup();
  assert.isTrue(window.logDebug.calledWith('error', 'Error: Raven has not been configured.'))
  assert.isTrue(window.logDebug.calledOnce);
});

[benoitg]

@benvinegar The test above wouldn't have caught it. I DID get the error output. But it inhibited further logging by captureMessage

@benvinegar The whole thing is open source (https://github.com/ImaginationForPeople/assembl/) , but making an unreleased version with non-working dependencies is not something I have time to do.

So, while I haven't managed to reduce it to a test case that has the same symptoms, here is one that does fail. Different symptoms, but probably the real source of the problem (in any event, a real bug my patch in #369 does not fix anyway):

<script src="./dist/raven.js"></script>
<script src="./plugins/console.js"></script>

<script>
Raven.debug = true;
console.error("Something");
Raven.captureException('test'); // NOTE: Raven not configured
</script>

It outputs a "Uncaught RangeError: Maximum call stack size exceeded"

If you change to Raven.debug = false, the error is "Something" is correctly output from within Raven's plugin/console.js

I always wondered if that plugin interacted with logDebug, hence my original use of console.log().

I have no clue why in a bigger app I get different symptoms however.

As for the fix, I'd just make logDebug not use levels and use console.log(), which isn't caught by the plugin.

[benvinegar]

@benoitg Awesome – I knew there was a deeper issue here. We are going to put together a patch to address this.

[mattrobenolt]

@benoitg So turns out, this is a symptom of the console plugin. Not many people use that, so it doesn't see much attention. :)

But the console plugin ultimately is patching native console.* calls, and in our case, we're then utilizing console to log our own messages, which turns into a nice recursive thing and causing your stuff to break.

See #370 for the fix.

[benoitg]

Ok, I confirm that #370 fixes the issue, thanks.