Capture more data when instrumenting exceptions

Capture more data when instrumenting exceptions

R=lukechurch@google.com

Committed: https://github.com/dart-lang/sdk/commit/9aa45d4cf0248ae96fd4f664d602517adba590c4

[Brian Wilkerson, 2015-07-31 17:34:13]

brianwilkerson@google.com changed reviewers:
+ lukechurch@google.com

[Brian Wilkerson, 2015-07-31 17:34:13]

This is the approach I'd like to take to get more information captured when
exceptions are instrumented. Note, however, that it requires a change to the
format of logged messages by adding two additional fields. I don't know how well
the server handles this kind of change.

[Brian Wilkerson, 2015-07-31 20:18:57]

brianwilkerson@google.com changed reviewers:
+ danrubel@google.com

[danrubel, 2015-08-03 13:29:20]

On 2015/07/31 17:34:13, Brian Wilkerson wrote:
> This is the approach I'd like to take to get more information captured when
> exceptions are instrumented. Note, however, that it requires a change to the
> format of logged messages by adding two additional fields. I don't know how
well
> the server handles this kind of change.

I don't think this should cause any problems, but I'd like Luke to confirm that.

[lukechurch, 2015-08-03 13:36:14]

Sorry for the delay in looking at this

https://codereview.chromium.org/1257023003/diff/1/pkg/analyzer/lib/instrument...
File pkg/analyzer/lib/instrumentation/instrumentation.dart (right):

https://codereview.chromium.org/1257023003/diff/1/pkg/analyzer/lib/instrument...
pkg/analyzer/lib/instrumentation/instrumentation.dart:153: void
logLogEntry(String level, DateTime time, String message, Object exception,
StackTrace stackTrace) {
This feels a bit strange to me - why are the exception and stacktrace mandatory
objects rather than optional parameters?

Given that the implementation is not safe if exception or stackTrace are null -
they really do need to be instances. What is the expectation of what they will
hold in non-error conditions?

Is this a standard pattern from the logging library?

[Brian Wilkerson, 2015-08-03 14:07:41]

https://codereview.chromium.org/1257023003/diff/1/pkg/analyzer/lib/instrument...
File pkg/analyzer/lib/instrumentation/instrumentation.dart (right):

https://codereview.chromium.org/1257023003/diff/1/pkg/analyzer/lib/instrument...
pkg/analyzer/lib/instrumentation/instrumentation.dart:153: void
logLogEntry(String level, DateTime time, String message, Object exception,
StackTrace stackTrace) {
> This feels a bit strange to me - why are the exception and stacktrace
mandatory
> objects rather than optional parameters?

This is only called from the logger, and it didn't seem worth making them
optional. Also, there's no way to express that they should either both be given
or both be absent, so the semantics would be equally strange if they were
optional.

> Given that the implementation is not safe if exception or stackTrace are null
-
> they really do need to be instances. What is the expectation of what they will
> hold in non-error conditions?

I'm not sure why you say that. "null.toString()" is perfectly valid and produces
"null", which is what we'll send to the instrumentation server if they are not
provided.

> Is this a standard pattern from the logging library?

I assume this is part of the previous question and not a separate question. If I
misunderstood, let me know.

[lukechurch, 2015-08-03 14:26:09]

On 2015/08/03 14:07:41, Brian Wilkerson wrote:
>
https://codereview.chromium.org/1257023003/diff/1/pkg/analyzer/lib/instrument...
> File pkg/analyzer/lib/instrumentation/instrumentation.dart (right):
> 
>
https://codereview.chromium.org/1257023003/diff/1/pkg/analyzer/lib/instrument...
> pkg/analyzer/lib/instrumentation/instrumentation.dart:153: void
> logLogEntry(String level, DateTime time, String message, Object exception,
> StackTrace stackTrace) {
> > This feels a bit strange to me - why are the exception and stacktrace
> mandatory
> > objects rather than optional parameters?
> 
> This is only called from the logger, and it didn't seem worth making them
> optional. Also, there's no way to express that they should either both be
given
> or both be absent, so the semantics would be equally strange if they were
> optional.

I don't really agree that that would be equally bizarre. 
I have never seen a logging system that had mandatory arguments for exceptions
on normal log messages, I have seen ones that need both exceptions and stack
traces. But this is internal to the Analysis Server so I don't mind too much.

> > Given that the implementation is not safe if exception or stackTrace are
null
> -
> > they really do need to be instances. What is the expectation of what they
will
> > hold in non-error conditions?
> 
> I'm not sure why you say that. "null.toString()" is perfectly valid and
produces
> "null", 

So it does. I learn something new about Dart every day. Any reason to not use
string continuations?

> which is what we'll send to the instrumentation server if they are not
> provided.

So every message that is ok is going to have 'null null' on the back of it? That
seems a little strange, but it's
probably not fatal. I think I'd prefer them to be prefixed before the message
rather than after it, it'll be a bit
more resilient. 

lgtm I guess, but without a huge degree of enthusiasm.

[Brian Wilkerson, 2015-08-03 15:35:21]

> I have never seen a logging system that had mandatory arguments for exceptions
> on normal log messages, I have seen ones that need both exceptions and stack
> traces. But this is internal to the Analysis Server so I don't mind too much.

Note that this is *not* a logging system. This is an instrumentation system that
is capturing the data sent to the logging system. The logging system doesn't
require passing in either the exception or the stack trace for exactly the
reason you gave. But this method should never be called by anything other than
the logging system. Hence part of my lack of concern about whether they are
optional or not.

> Any reason to not use string continuations?

I don't know what you mean by "string continuations". Please clarify.

> So every message that is ok is going to have 'null null' on the back of it?
That
> seems a little strange, but it's probably not fatal.

I think of it like optional fields in a database record. It's normal for the
record to have a fixed length and for the "optional" fields to have a "not
provided" value. Hence the rest of my lack of concern about whether the
parameters are optional. I think the record should have those fields anyway, and
making them required parameters only serves to make it clear that some value
will be passed in.

> I think I'd prefer them to be prefixed before the message rather than after
it,
> it'll be a bit more resilient. 

Wouldn't that be a breaking change? The code that processes the recorded data
would have to special case to determine where to find the message. As it is, new
code that looks for the exception and stack trace will need to test to see
whether they were included because they weren't included in older data. But I'm
hoping that if they're added at the end then the code that processes the data
will simply ignore them if it hasn't been updated to allow for their existence.

And if next month we decide we need to add two new optional fields (named "foo"
and "baz"), and decided to stick them somewhere in the middle of the record,
then we'd need potentially complex and error-prone logic to try to determine
which fields were included and where they are in the structure. That seems like
a nightmare compared to having fixed sized records whose structure never changes
(except by being appended to).

So, why do you think it would be more resilient? What am I missing?

> lgtm I guess, but without a huge degree of enthusiasm.

I'd like to understand your objections better before committing.

[Brian Wilkerson, 2015-08-05 17:00:21]

ping

[lukechurch, 2015-08-05 18:10:22]

On 2015/08/03 15:35:21, Brian Wilkerson wrote:
> > I have never seen a logging system that had mandatory arguments for
exceptions
> > on normal log messages, I have seen ones that need both exceptions and stack
> > traces. But this is internal to the Analysis Server so I don't mind too
much.
> 
> Note that this is *not* a logging system. This is an instrumentation system
that
> is capturing the data sent to the logging system. The logging system doesn't
> require passing in either the exception or the stack trace for exactly the
> reason you gave. But this method should never be called by anything other than
> the logging system. Hence part of my lack of concern about whether they are
> optional or not.
> 
> > Any reason to not use string continuations?
> 
> I don't know what you mean by "string continuations". Please clarify.

Sorry I meant 'String interpolations'. Aka "$theseThings"

> > So every message that is ok is going to have 'null null' on the back of it?
> That
> > seems a little strange, but it's probably not fatal.
> 
> I think of it like optional fields in a database record. It's normal for the
> record to have a fixed length and for the "optional" fields to have a "not
> provided" value. 

OK. This is good, I see where our different models come from. The
instrumentation infrastructure is designed to avoid fixing a schema wherever
possible. This comes from lessons building systems like this over time, and the
rationale is much too long a description to put here. But at least I understand
the difference in views. 

> Hence the rest of my lack of concern about whether the
> parameters are optional. I think the record should have those fields anyway, 

yeah, this is the difference in opinions. In general, I think the vast majority
of the schema should be optional, so messages that don't use this structure
don't have to pay for them.
Otherwise, considering the previous version of instrumentation, we had in excess
of 2k different fields in the datastore, most of which were unused for a given
message.

For this case, I'm ok to go ahead, but IMHO adding in mandatory fields for
messages should not be the standard way of adding in new data. If we're doing a
lot of this, we might consider using a JSON map instead.

> > I think I'd prefer them to be prefixed before the message rather than after
> it,
> > it'll be a bit more resilient. 
> 
> Wouldn't that be a breaking change? The code that processes the recorded data
> would have to special case to determine where to find the message. As it is,
new
> code that looks for the exception and stack trace will need to test to see
> whether they were included because they weren't included in older data. But
I'm
> hoping that if they're added at the end then the code that processes the data
> will simply ignore them if it hasn't been updated to allow for their
existence.

Sorry, I misread the join code, I thought it was using a string join, rather a
join with the separator marker.
I withdraw my suggestion to put them at the front. Thanks for the clarification.

Putting them at the end is fine for now, but as above, if we find ourselves
using a lot of optional arguments, lets consider encoding them in a map.

> And if next month we decide we need to add two new optional fields (named
"foo"
> and "baz"), and decided to stick them somewhere in the middle of the record,
> then we'd need potentially complex and error-prone logic to try to determine
> which fields were included and where they are in the structure. That seems
like
> a nightmare compared to having fixed sized records whose structure never
changes
> (except by being appended to).

I believe using a map would also address these concerns? 

I certainly don't want to be doing structure guessing, but as a rule of thumb I
would propose that if we think that 75% of messages for the rest of the life of
the system are going to have something to say in a field we put it in a fixed
size entry, otherwise we put it in a mapped field.
  
> > lgtm I guess, but without a huge degree of enthusiasm.
> 
> I'd like to understand your objections better before committing.

I think it largely comes down to ensure we pay O(n) data costs where n is
proportional to the number of fields in use, not the number of potential fields.
Previous experience indicates to me that this is required in the longer term for
the system to function efficiently. 

With the use of _join, which I overlooked, lgtm with more enthusiasm.

[Brian Wilkerson, 2015-08-06 15:50:44]

Committed patchset #1 (id:1) manually as
9aa45d4cf0248ae96fd4f664d602517adba590c4 (presubmit successful).