Forward errors from gcd.sh

[ajkannan]

Fixes #38

[ajkannan]

Note: this will forward errors from gcd.sh even if the operation is retried and it succeeds. For example, when I run DatastoreTests using these changes, I get some "SEVERE" level errors from gcd.sh ("too much contention on entities" errors that are probably caused by repeatedly adding/removing the same entities in a very short amount of time) that are then retried and fine. Do we think it's alright to forward this kind of message along to the user?

[aozarov]

I get some "SEVERE" level errors from gcd.sh ("too much contention on entities" errors that are probably caused by repeatedly adding/removing the same entities in a very short amount of time) that are then retried and fine

@eddavisson any reason for this messages? When we start gcd.sh in our tests we would like to re-direct
any real errors but rather avoid such noise if possible.

[eddavisson]

The local v1 service recently added some internal retry logic for non-transactional commits. The logging code (somewhere in ApiProxy?) doesn't know if the error will be propagated to the user or caught and retried. In the latter case, the user doesn't need to worry about the errors; in the former, they do (though of course, it'll be sent back to the client in that case).

[aozarov]

@eddavisson I am not sure why we ever log it. If we retry and it is not a real-issue then we shouldn't log (especially not as SEVERE) and if we propagate the user will know about the error (and may log it too).

Any plans to change that? If not, any advice on what we should "filter" in our code. When we start the gcd.sh using our utility we would like to capture and log "real" errors.

[eddavisson]

I looked at this again, and I think it's actually the app we run inside of gcd.sh that's doing the logging. That's happens a few layers above our internal retries, so I would expect any error logged to be returned to the client. @ajkannan, were you seeing errors logged that weren't returned to the client?

@pcostell is working on a new version of gcd that doesn't use an internal app, so it'll be a lot easier to make the logging do exactly what we want. Until then, we can remove the SEVERE log, but we will still log any error at INFO level.

[ajkannan]

@eddavisson I did indeed see some errors logged that weren't returned to the client, for example some of those SEVERE errors complaining about "too much contention on entities." I could just ignore SEVERE logs, but I sometimes get the "too much contention on entities" error at the INFO level as well. Maybe the INFO-level errors show up when datastore gives up and our library retries? (I can do some investigating here)

[eddavisson]

We have some duplicate INFO/SEVERE logging; I will send you a CL shortly to resolve that. When you say "weren't returned to the client", is that because gcloud-java retries or because gcd is doing an internal retry? Are you seeing logging from classes other than com.google.apphosting.client.serviceapp.BaseApiServlet?

[ajkannan]

All the logs I see are indeed from com.google.apphosting.client.serviceapp.BaseApiServlet. Just to clarify what I meant by "weren't returned to the client," I was seeing some severe-level log messages without an accompanying error/stack trace being output. (If that isn't what you weren't talking about, let me know). Now that I look at them again, those log messages do indeed look like duplicates of INFO-level logs.

After digging a bit deeper, in all my test runs thus far, I'm only getting the "too much contention on entities" error when the request is aborted by the datastore and subsequently retried by gcloud-java. So it looks like the extra errors problem is something we'll have to handle on the gcloud-java end.

Thanks for your help!

[ajkannan]

@aozarov Since the only error I've come across that we don't want to forward to the user is the "too much contention" error, I can check for that and not print to stderr if so. I can imagine edge cases where the user may want to know about contention (maybe for performance reasons), but I imagine they can figure that information out from setting the retry parameters and watching for/handling exceptions using the gcloud-java libraries. What's your opinion?

Also (somewhat unrelated), in DatastoreTests, we purposely incite exceptions (i.e. adding an entity that already exists in the datastore). Those show up as in the stderr output when running DatastoreTests using LocalGcdHelper. We don't release our unit tests via Maven artifact, but if users happen to download and use the Github project, they would see those errors if they were to run the unit tests. I don't necessarily think it's a problem to fix, but what's your opinion on this?

In terms of the actual output, I plan on printing the "INFO: ..." error lines from gcd.sh, followed by the first line of the stack trace (which contains the more helpful information, for example "entity already exists"). The rest of the stack trace is long and doesn't really provide much information, so I think we should leave that out. Does that sound okay?

[aozarov]

After @eddavisson fix will we still see the contention warnings as CRITICAL?

Did you consider trying to parse the lines and, when you can detect redirect to the logger using the same level that was detected (and would be nice if you remove the level, so it would not be printed twice and maybe prefix the message with GCD or something like that).

That way a user would be able to filter any undesired messages by using the desired log level to this class.

[ajkannan]

I think @eddavisson's fix logs contention errors at INFO level, like all other errors logged by gcd (correct me if I'm wrong).

Also the logging idea sgtm, I'll implement that.

[aozarov]

Ok, re-edited my comment to say "we we still see"...
Good, then I think with that fix and with log redirecting we are good.
let me know if you see any more [potential] issues...

[ajkannan]

Oh, I see what your question was asking originally. I think we will still see SEVERE level duplicate logs until the next gcd version is released.

[ajkannan]

@aozarov logging is implemented and ready for review.

[ajkannan]

@aozarov Comments addressed, ready for another round of review.