Skip to content
This repository has been archived by the owner on May 10, 2019. It is now read-only.

Issue 3529 02 metrics squashed #3939

Merged
merged 25 commits into from
Oct 10, 2013
Merged

Issue 3529 02 metrics squashed #3939

merged 25 commits into from
Oct 10, 2013

Conversation

shane-tomlinson
Copy link

@6a68 - yo man. Here is round two. The last remaining item is to convert cef logging, but I want to talk to jedp, yvan, and francois before doing so.

Shane Tomlinson added 22 commits September 25, 2013 10:48
* Add a file transport
* Add a statsd transport
* Add a heka transport

All logging except for cef logging goes through these. statsd stats go through these.
* custom_logger
* cef_logger
* metrics
* logging

update the tests for the file change locations
* Revert changes that removed statsd.increment and replaced it with a logging message.
* In statsd.js, trigger winston messages with the statsd. prefix.
* In winston-statsd, listen for statsd. messages, and do the right thing.
* Try to get the host/port out of statsdConfig, not statsdOptions
* Make sure the metrics logs are written in the same format as before.
* Add metrics->kpiggybank config options.
* Add an HttpMock so no requests are made to a kpiggybank.
* Add basic tests for store to make sure no blowups occur and data is sent.
* Add basic tests to make sure metrics are sent to kpiggybank in batches.
* Clean up the kpi_data.js module.
* Rename the transport filenames to be more descriptive
* Rename the transports that were called *Logger to *Transport
* Clean up the statsd code
* use `const` for every include
* Let the metrics transport pull out events it is interested in.
* Add a metricsMiddleware that logs `/sign_in` requests.
* Split off the metrics message filter into its own file to be shared across metrics transports.
* Listen for various timing and increment messages and do the right thing.
* Add a statsd mock for testing.
* No longer call statsd.*, ship all messages over Winston.
* Get rid of metrics.report. Update tests to use listened for messages.
* Move logging middleware related functionality to logging/middleware
* formatting
@shane-tomlinson
Copy link
Author

There are two ephemeral instances set up to test with:

Persona: https://logging-shane.personatest.org
KPiggybank: https://kpiggy-shane.personatest.org

@jaredhirsch
Copy link
Member

@shane-tomlinson this code looks phenomenal, really nice work. We have a clear pathway to adding Heka in the future, logging calls inside the app are simplified, and the new code is very nicely factored. R+.

Comments/optional suggestions:

I don't understand why lib/kpi-data exists, it seems like we could reuse the kpiggybank transport and move the other stuff into a filter (like fuzzing times and dropping certain fields). However, this branch is already big and has been open for a while--I'd understand if you'd rather leave it for now, open a bug, and come back to it later.

There might be an argument for namespacing logged events--either magically, by prepending the name of the calling process along with an ISO timestamp, or manually, by inserting, eg, 'browserid.' in front of everything logged inside bin/browserid. No reason we can't put that off till later and see how readable the current output turns out to be.

Ditto for the way the filters/transports/configs are sliced up, I think that a couple months of use will point out places where the abstractions could be refined. This is an excellent starting point.

Love the mocks, btw. So simple, gets the job done. <3

So, summarizing: tests are passing, high-level looks good (only biggish thing is the kpi-data file, and that's optional IMO), initial read through looks good syntactically.

Things I haven't done: poke at the ephemeral instances, run through DDT tests locally. I'll see how much I can get done tonight, and I'm out tomorrow, but I'm confident that you will exercise the code a ton before merging in, so: don't block on me, merge at your leisure. 🍻

@@ -80,7 +79,7 @@ function bcryptPassword(password, cb) {
var startTime = new Date();
bcrypt.encrypt(config.get('bcrypt_work_factor'), password, function() {
var reqTime = new Date() - startTime;
statsd.timing('bcrypt.encrypt_time', reqTime);
logger.log('bcrypt.encrypt_time', reqTime);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Unless you overwrote it in a file up above, this is missing the logging level arguments. winston.Logger.log(level, msg, args...)

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ahha, thanks @seanmonstar.

Shane Tomlinson added 2 commits October 8, 2013 12:11
No need to call `statsd.setupMiddleware`, just call `app.use(statsd());`

If statsd is configured, statsd() will return a middleware to send responses
to statsd. If statsd is not configured, an empty middleware that calls `next()`
is returned. This allows users of the middleware to not worry about whether statsd
is configured before adding the middleware.
…user agent type to the backend in metrics related KPI data.
@shane-tomlinson
Copy link
Author

@6a68 and @seanmonstar - thanks for the ongoing review and the issues caught. I have updated the logger.logs to be logger.info and logger.warn. doh.

Answering other questions:

I don't understand why lib/kpi-data exists, it seems like we could reuse the kpiggybank transport and move the other stuff into a filter (like fuzzing times and dropping certain fields). However, this branch is already big and has been open for a while--I'd understand if you'd rather leave it for now, open a bug, and come back to it later.

I thought the same, and started to get touchy about the size of this PR. It's a great follow on. By making all KPIs use the KPI transport, we can also send normal KPIs in batches.

There might be an argument for namespacing logged events--either magically, by prepending the name of the calling process along with an ISO timestamp, or manually, by inserting, eg, 'browserid.' in front of everything logged inside bin/browserid. No reason we can't put that off till later and see how readable the current output turns out to be.

The log files (normal and metrics) are all separated by process. We could add this pretty easily, but I'm not sure it would add value until we start aggregating into a single file &| transport (thinking Heka and Rabbit), at which time we could prevent process names onto the event name.

Ditto for the way the filters/transports/configs are sliced up, I think that a couple months of use will point out places where the abstractions could be refined. This is an excellent starting point.

Thank you!

New metrics related KPI data sent to the KPI server (if enabled in config):

The first type is signin data. We log every time "/signin" is displayed to the user.

[{"type":"signin","user_agent":{"os":"Windows NT 6.1","browser":"Firefox","version":22},"timestamp":1381231200000},{"type":"signin","user_agent":{"os":"Windows NT 6.1","browser":"Firefox","version":22},"timestamp":1381231200000},{"type":"signin","user_agent":{"os":"Windows NT 6.1","browser":"Firefox","version":22},"timestamp":1381231200000},...]

The second type is verification data, we log every time a request comes to the verifier:

[{"type":"verify","timestamp":1381231200000},{"type":"verify","timestamp":1381231200000},{"type":"verify","timestamp":1381231200000},{"type":"verify","timestamp":1381231200000}]

To enable metrics KPI logging, the appropriate config file must be updated. First, change kpi_backend_db_url to a kpiggybank instance.. Next, set kpi_send_metrics to true

e.g.:

diff --git a/config/aws.json b/config/aws.json
index fd786ce..5a546a9 100644
--- a/config/aws.json
+++ b/config/aws.json
@@ -21,12 +21,13 @@
   },
   "proxy": { "bind_to": { "port": 10006 } },
   "router": { "bind_to": { "port": 8080 } },
-  "kpi_backend_db_url" : "https://kpiggybank-dev.personatest.org/wsapi/interaction_data",
+  "kpi_backend_db_url" : "https://kpiggy-shane.personatest.org/wsapi/interaction_data",
+  "kpi_send_metrics" : true,
   // whether to show the development menu.
   "enable_development_menu": true,
  // explicitly undefine public_static_url and firefoxos_url, as the configuration will 
  // then fallback to public_url.  Because these values are dynamic in ephemeral 

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants