772716 - log user id and request processing time for each sync server request

Status: VERIFIED FIXED

(Cloud Services Graveyard :: Server: Sync, defect)

Description

[Rob Miller [:rmiller]]

We want to be able to spot users who are sucking up inordinate server resources, this adds request processing time tracking by user on sync 1.1. Will be output through metlog to HDFS and then aggregated; we won't keep the fine granularity data.

Comment 1

[Rob Miller [:rmiller]]

Attachment: server-core patch sending request processing time w/ user id to metlog

Comment 2

[Rob Miller [:rmiller]]

Attachment: test that user id and elapsed time is being pushed through metlog

It's a bad code smell that changes in server-core lead to test changes in server-storage (and not in server-core) but no new software is being developed on the server-core stack so I'm not going to worry about it too much.

Comment 3

[Ryan Kelly [:rfkelly]]

Comment on attachment 640928 [details] [diff] [review]
server-core patch sending request processing time w/ user id to metlog

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

LGTM.  I assume there are no privacy issues with this since the userid is already logged as part of the URL?

::: services/baseapp.py
@@ +142,5 @@
>                  if ((method is not None) and
>                      (not hasattr(controller_instance, wrapped_name))):
>                      # add wrapped method
> +                    wrapped = send_services_data(incr_count(
> +                        svc_timeit(method)))

Hmm, line-wrapping nested function calls is never pretty.  Consider something like this for clarity?

   wrapped = svc_timeit(method)
   wrapped = incr_count(wrapped)
   wrapped = send_services_data(wrapped)

No big deal either way, just a thought.

Comment 4

[Ryan Kelly [:rfkelly]]

Comment on attachment 640929 [details] [diff] [review]
test that user id and elapsed time is being pushed through metlog

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

::: syncstorage/tests/test_metlog.py
@@ +96,1 @@
>          wrapped_method._fn._fn._fn = orig_inner

Wow that's a lot of _fn chaining.  Just want to double-check whether there should be one more _fn on here due to the extra decorator?

Comment 5

[Toby Elliott [:telliott]]

(In reply to Ryan Kelly [:rfkelly] from comment #3)
> Comment on attachment 640928 [details] [diff] [review]
> server-core patch sending request processing time w/ user id to metlog
> 
> Review of attachment 640928 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> LGTM.  I assume there are no privacy issues with this since the userid is
> already logged as part of the URL?

Use cases for this are in abuse detection and systems improvement, and we'll be aggregating across fairly large (per-day-level) time periods, so it's not really a privacy issue.

Comment 6

[Rob Miller [:rmiller]]

Comment on attachment 640929 [details] [diff] [review]
test that user id and elapsed time is being pushed through metlog

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

::: syncstorage/tests/test_metlog.py
@@ +96,1 @@
>          wrapped_method._fn._fn._fn = orig_inner

Yeah, it's ugly. In non-test code we'd recurse up until there was no more `_fn` attribute instead of assuming we knew how many times we'd been decorated, but the test is specifically ensuring that things are as we expect. And no, there shouldn't be one more; we changed `timeit` to `svc_timeit`, but there are still the same number of decorators as before (3).

Comment 7

[Ryan Kelly [:rfkelly]]

Comment on attachment 640929 [details] [diff] [review]
test that user id and elapsed time is being pushed through metlog

well then, LGTM :-)

Comment 8

[Ryan Kelly [:rfkelly]]

It looks like these were committed, are we OK to close out this bug?

Comment 9

[Rob Miller [:rmiller]]

Yes, I think so.

Comment 10

[Ryan Kelly [:rfkelly]]

Needs QA, we should be able to check that it's working by looking in the logs.  Will defer to :RaFromBRC for most appropriate way to verify.

Comment 11

[Rob Miller [:rmiller]]

This can be verified by the existence of records in the metrics_hdfs.log file with a 'type' value of 'services' and a 'fields' value that contains both 'userid' and 'req_time' keys. For example, the following record from metrics_hdfs.log on sync2.web...

{"severity":6,"timestamp":"2012-08-31T01:12:03.955928","metlog_hostname":"sync2.web.scl2.stage.svc.mozilla.com","fields":{"req_time":1,"userid":"847520"},"metlog_pid":24250,"logger":"syncstorage","type":"services","payload":"","env_version":"0.8"}

...has a 'services' type value, and a 'fields' value of {"req_time":1,"userid":"847520"}, which contains both of the required keys. This is a positive indicator.

Comment 12

[James Bonacci [:jbonacci]]

OK. So, looking at file metrics_hdfs.log=2012-08-31.gz on sync1

Verified that there were many instance of the above records.