690416 - Log 503s and bodies from Zeus

Status: VERIFIED FIXED

(Cloud Services :: Operations: Miscellaneous, task)

Description

[Richard Newman [:rnewman]]

> Right on. We do it in some cases already. I'll make sure we do it in all
> cases. That said, if we send out a 503, can't we log that reason as well? Not
> every error bar will be reported by the user, at least until we get Syncorro,
> which will have clients upload logs when they encounter an error. It seems we
> could save the middle man here and just log any error we send out the user in
> the first place.

I think I have an idea on how to do this in Zeus, but I need to check the 503 volume to be sure. Can you file a bug assigned to me under Services / Operations to do this?

Comment 1

[:Atoll]

Attachment: add missing 503 zeus log for DEAD/DISABLED databases

also modify "db lookup failed" log to correctly log *either* "health check not enabled yet" or "db lookup failed", rather than one or both depending.

Comment 2

[:Atoll]

Attachment: rewrite health check logging to contain username, ip for easy lookup later

rewrote logging so we don't have to spend lots of time correlating timestamps between zeus logs and http logs, and can instead just look for the user's sync username and see immediately why we sent them a 503.

includes previous fix for missing 503 log for DEAD/DISABLED databases

Comment 3

[:Atoll]

Note that there is one case where we'll have to actually parse the Zeus HTTP logs, that cannot be handled by this Trafficscript rule.

If all of the web heads are down/unavailable (generally due to a database going down), then Zeus will temporarily return the "255" body that we're all familiar with.  This is logged as a 503 with "node_s:-", rather than some positive floating point seconds value.

There is no way at this time to merge that one instance with this Trafficscript, so we'll still have to look in two places.  But with the revised patch, at least we can simply grep, rather than having to run correlations.

Comment 4

[Richard Newman [:rnewman]]

Comment on attachment 563726 [details] [diff] [review]
rewrite health check logging to contain username, ip for easy lookup later

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

::: stage-db.rule
@@ +9,5 @@
> +  $encuserpasswd = string.skip($authheader, 6);
> +  $userpasswd = string.base64decode($encuserpasswd);
> +  $i = string.find($userpasswd, ":");
> +  # we only need $username for logging purposes
> +  $username = string.substring($userpasswd, 0, $i-1);

Zeus docs don't say what happens if the substring call receives a negative length, but that would be possible if the auth header is malformed.

@@ +15,5 @@
> +}
> +
> +# precreate logging variables so the code below is readable
> +$content_type = "text/html; charset=UTF-8";
> +$log_suffix = " " . "Username: '" . $username . "' Remote-IP: '" . $remoteip . "'";

What's the value in logging the remote IP?

@@ +16,5 @@
> +
> +# precreate logging variables so the code below is readable
> +$content_type = "text/html; charset=UTF-8";
> +$log_suffix = " " . "Username: '" . $username . "' Remote-IP: '" . $remoteip . "'";
> +$log_suffix_useragent = " " . "User-Agent: '" . $useragent . "'";

Seems like you could save yourself a couple of concats here:

  " Username: '"
   ^

@@ +45,5 @@
>  $host = http.getHeader("Host");
>  $db = "";
>  if ($host == "") {
> +   log.warn("server issue: host lookup failed (retry-after)" . $log_suffix);
> +   http.sendResponse("503 Database unavailable", $content_type, "server issue: host header not received from client ", $retry_after);

Missing single quotes around 'server issue...'.

Comment 5

[:Atoll]

(In reply to Richard Newman [:rnewman] from comment #4)
> > +  $i = string.find($userpasswd, ":");
> > +  # we only need $username for logging purposes
> > +  $username = string.substring($userpasswd, 0, $i-1);
> 
> Zeus docs don't say what happens if the substring call receives a negative
> length, but that would be possible if the auth header is malformed.

I cookie cutter'd that code from the Zeus 7.3 traffic script docs, but will add a check for $i being something valid and file a bug with them about the missing docs.

> > +$log_suffix = " " . "Username: '" . $username . "' Remote-IP: '" . $remoteip . "'";
> 
> What's the value in logging the remote IP?

I was thinking about removing it from *most* logs as well, and making it custom to the one we care about logging it for (bad Host header, same as User-Agent).  will alter.

> > +$log_suffix = " " . "Username: '" . $username . "' Remote-IP: '" . $remoteip . "'";
> > +$log_suffix_useragent = " " . "User-Agent: '" . $useragent . "'";
> 
> Seems like you could save yourself a couple of concats here:
> 
>   " Username: '"
>    ^

Yeah, in theory. Doing it this way prevents human error situations, but in retrospect there's no risk to error here.  Will alter.

> @@ +45,5 @@
> Missing single quotes around 'server issue...'.

Ah, JSON string inconsistency.  Will fix all sendResponse calls to be ( ..., '"json string"', ... )

Comment 6

[:Atoll]

Attachment: jsonify all response bodies, remove most ip logging, check string.find result, clean up concats, clear all copies of auth header (which includes user password) after trying to extract username

addresses all issues noted in comment #4, also takes special care to wipe out every copy of the user auth header so we never accidentally expose a user password

Comment 7

[Richard Newman [:rnewman]]

Comment on attachment 563750 [details] [diff] [review]
jsonify all response bodies, remove most ip logging, check string.find result, clean up concats, clear all copies of auth header (which includes user password) after trying to extract username

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

::: stage-db.rule
@@ +16,5 @@
> +if (string.startsWith($auth, "Basic ")) {
> +  $encuserpasswd = string.skip($authheader, 6);
> +  $userpasswd = string.base64decode($encuserpasswd);
> +  $i = string.find($userpasswd, ":");
> +  if ($i > -1) {

This will break if the string starts with a colon (implying an empty username). In this case, you should test for > 0.

Comment 8

[:Atoll]

(In reply to Richard Newman [:rnewman] from comment #7)
> This will break if the string starts with a colon (implying an empty
> username). In this case, you should test for > 0.

if no username is found, then the username defaults to "-".  Whether that's because there's no Basic auth header or because the user provided a blank username is of no concern to 503 logging, and I don't think we can differentiate that in the Zeus or nginx access logs either, so I'm good with it as written.

Comment 9

[Richard Newman [:rnewman]]

(In reply to Richard Soderberg [:atoll] from comment #8)
 
> if no username is found, then the username defaults to "-".  Whether that's
> because there's no Basic auth header or because the user provided a blank
> username is of no concern to 503 logging, and I don't think we can
> differentiate that in the Zeus or nginx access logs either, so I'm good with
> it as written.

That's not what I meant.

+$auth = http.getHeader("Authorization");

$auth is now "Basic foobar="

+if (string.startsWith($auth, "Basic ")) {
+  $encuserpasswd = string.skip($authheader, 6);
+  $userpasswd = string.base64decode($encuserpasswd);

$userpasswd is now ":trolled". Note that the username is missing from the Basic Auth header, but you assume that it's present (i.e., that $i > 0).

+  $i = string.find($userpasswd, ":");

$i is now 0.

+  if ($i > -1) {

True.

+    $username = string.substring($userpasswd, 0, $i-1);

You just called string.substring(":trolled", 0, -1), which is probably not what you meant to do.

Your test should be "are there characters before and after a colon?", not "is there a colon in this string?".

Comment 10

[:Atoll]

(In reply to Richard Newman [:rnewman] from comment #9)
> (In reply to Richard Soderberg [:atoll] from comment #8)
>  
> > if no username is found, then the username defaults to "-".  Whether that's
> > because there's no Basic auth header or because the user provided a blank
> > username is of no concern to 503 logging, and I don't think we can
> > differentiate that in the Zeus or nginx access logs either, so I'm good with
> > it as written.
> 
> That's not what I meant.

> $userpasswd is now ":trolled". Note that the username is missing from the
> Basic Auth header, but you assume that it's present (i.e., that $i > 0).
> 
> +  $i = string.find($userpasswd, ":");
> 
> $i is now 0.
> 
> +  if ($i > -1) {
> 
> True.

Makes sense.

> +    $username = string.substring($userpasswd, 0, $i-1);
> 
> You just called string.substring(":trolled", 0, -1), which is probably not
> what you meant to do.

I think this is safe, and will return a null username, but I'd rather not find out one way or the other.  So it should be avoided.

> Your test should be "are there characters before and after a colon?", not
> "is there a colon in this string?".

Okay, so $i >= 1, eg. "Is the first colon at string position 1 or greater?", would be a correct test?  (Usernames are forbidden from containing colons by the http spec.)

Comment 11

[Richard Newman [:rnewman]]

(In reply to Richard Soderberg [:atoll] from comment #10)

> Okay, so $i >= 1, eg. "Is the first colon at string position 1 or greater?",
> would be a correct test?  (Usernames are forbidden from containing colons by
> the http spec.)

Correct. Either $i > 0 or $i >= 1 is fine.

Comment 12

[Pete Fritchman [:petef]]

Comment on attachment 563750 [details] [diff] [review]
jsonify all response bodies, remove most ip logging, check string.find result, clean up concats, clear all copies of auth header (which includes user password) after trying to extract username

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

lgtm. is this rolled out in stage? i can kick off a quick loadtest and generate some 503s.

Comment 13

[:Atoll]

It hasn't been tested at all yet, so I will coordinate with you to push to stage and test it and then handover for loadtest.

Comment 14

[James Bonacci [:jbonacci]]

Let me know when you want QA to test this out in Stage.
I have seen enough 503s lately...

Comment 15

[:Atoll]

Committed to sysadmins/svc/health/zlb/stage-db.rule as r21470 and pushing out to stage to do initial "does it still work" testing right now.  You are welcome to begin testing in an hour, or after I say "ready" on IRC in #services.

Props to Philipp for requesting improved server-side logging in lieu of client changes, since that's something we can do immediately for all clients, Firefox or otherwise.  It seems obvious in retrospect, which means it's an especially good idea.

Note that this will not reduce 503s in any way.  It just lets us analyze them more effectively.  So that we can graph 503s broken apart by *why* they happened.  Or find a given sync username in the 503 list to explain why they had a sync error.  Or detect misconfigurations and fire off alarms when they occur.  And so forth.

Comment 16

[:Atoll]

Fixed a typo in the script.

Verified that every 401 and 503 condition related to databases works as expected and returns the predicted result, per below output.

ACTIVE migrating=1, is the result of setting weave.available_nodes.migrating=1 for the node.  This produces the expected 401 result.

DRAINING unknown, is the result of setting the database node to Draining in Zeus, which is not yet supported and thus has no effect whatsoever.  This is the same as before, and will be improved as part of bug 667532 in the future.


22:44 host stage-sync74.services.mozilla.com db 10.14.216.17 status DISABLED unhealthy (retry-after) Username: 'bizjxvymfxhqtlrk2y72ggjx5t2pdl3y'
22:50 db 10.14.216.17 status DEAD unhealthy (retry-after) Username: 'bizjxvymfxhq
22:55 db lookup of 'stage-sync (database) 63.245.209.232' failed (retry-after) Username: '-' User-Agent: 'curl/7.21.4 (universal-apple-darwin11.0) libcurl/7.21.4 OpenSSL/0.9.8r zlib/1.2.5' Remote-IP: '70.36.176.234'
23:08 host stage-sync74.services.mozilla.com downed=1 (retry-after) Username: 'bizjxvymfxhqtlrk2y72ggjx5t2pdl3y'
23:09 host stage-sync74.services.mozilla.com db 10.14.216.17 status ACTIVE migrating=1 (node-reassignment) Username: 'bizjxvymfxhqtlrk2y72ggjx5t2pdl3y'
23:11 host stage-sync74.services.mozilla.com db 10.14.216.17 status NOTINPOOL not in pool (retry-after) Username: 'bizjxvymfxhqtlrk2y72ggjx5t2pdl3y
23:13 host stage-sync74.services.mozilla.com db 10.14.216.17 status DRAINING unknown (NO retry-after) Username:
23:15 host stage-sync74.services.mozilla.com db 10.14.216.17 status DEAD unhealthy (retry-after) Username: 'bizjxvymfxhqtlrk2y72ggjx5t2pdl3y'

Comment 17

[:Atoll]

Over to Petef for load testing.  Jbonacci, how would you like to QA this?

Comment 18

[James Bonacci [:jbonacci]]

Reading your Comment 15, I am not sure there is really any need for QA after all. We could verify the new log entries, I suppose. But, it sounds like OPs would need to "force" DB errors on nodes/accounts that QA is testing with?

Comment 19

[:Atoll]

(In reply to James Bonacci [:jbonacci] from comment #18)
> Reading your Comment 15, I am not sure there is really any need for QA after
> all. We could verify the new log entries, I suppose. But, it sounds like OPs
> would need to "force" DB errors on nodes/accounts that QA is testing with?

For the purposes of server testing, I forced a variety of database and backend issues in staging to generate the above-listed error logs, among others stopping mysql and editing available_nodes data.  It sounds like I ran the tests that you would have.  Is there additional information I can provide to confirm that my testing meets your expectations for the changes?

For the purposes of client Testing, I would want to verify that the client reacts as expected to the new 503 errors - it SHOULD have no impact.  I had Aurora open for an hour doing sync now over and over again, but I am not familiar with how it is expected to react to 503s, so I focused only on the server logs in my tests.

Comment 20

[Richard Newman [:rnewman]]

(In reply to Richard Soderberg [:atoll] from comment #19)

> For the purposes of client Testing, I would want to verify that the client
> reacts as expected to the new 503 errors - it SHOULD have no impact.  I had
> Aurora open for an hour doing sync now over and over again, but I am not
> familiar with how it is expected to react to 503s, so I focused only on the
> server logs in my tests.

The expected client behavior for 503 + Retry After is to *not* immediately show an error bar.

Comment 21

[Philipp von Weitershausen [:philikon]]

Firefox 9 (currently Aurora) and later will not display an error due to 503 + Retry-After unless you forced a sync via "Sync Now" from the menu.

Comment 22

[James Bonacci [:jbonacci]]

atoll: Saw your Comment 19.
For the client-side (Comments 20 and 21), QA should probably sanity test this in Stage before any scheduled deployment of the changes to Production.

Comment 23

[:Atoll]

Okay, it's ready in Stage to be sanity tested. Please coordinate with Pete.

Comment 24

[James Bonacci [:jbonacci]]

(Wow, just getting this bug email update now (22:08 PDT) )
OK. Thanks.
I will work with Pete on this tomorrow (Tuesday)...

Comment 25

[Pete Fritchman [:petef]]

atoll rolled this out to production.

Comment 26

[James Bonacci [:jbonacci]]

QA verified this in Prod