winston out, intel in #4045

seanmonstar · 2013-12-09T19:25:32Z

So, this replaces our usage of winston with intel. Why?

We get names for our loggers, so that each message has more context as to where it's coming from.
Much of the logging moves to configuration, making it easier to test different environments.
My super-basic-dont-rely-on benchmarks indicate 2x faster than winston.
Uses WritableStream's internal buffering, instead of drain events: https://github.com/seanmonstar/intel/blob/master/lib/handlers/stream.js#L22
Because ❤️

shane-tomlinson · 2013-12-10T11:18:59Z

@seanmonstar - travis keeps failing. :(

seanmonstar · 2013-12-10T17:02:35Z

I restarted the failed jobs. Looks green now.

shane-tomlinson · 2013-12-13T13:40:06Z

Can you update the /bin directory?

[app@ip-10-244-99-124 bin]$ ./load_gen
UNCLE: Error: Cannot find module 'winston'
    at Function.Module._resolveFilename (module.js:338:15)
    at Function.Module._load (module.js:280:25)
    at Module.require (module.js:364:17)
    at require (module.js:380:17)
    at Object.<anonymous> (/home/app/code/bin/load_gen:14:17)
    at Module._compile (module.js:456:26)
    at Object.Module._extensions..js (module.js:474:10)
    at Module.load (module.js:356:32)
    at Function.Module._load (module.js:312:12)
    at Function.Module.runMain (module.js:497:10)
[app@ip-10-244-99-124 bin]$

shane-tomlinson · 2013-12-13T13:42:56Z

lib/logging/cef_logger.js

@@ -38,6 +38,14 @@ var Logger = function(options) {
 *              transactions.
 */

+const SEVERITY_MAP = {
+  // cef => intel
+  info: 'info',


I did this with winston at one point too, the reason I didn't change CEF logging over is because of a comment somewhere that said "we want to see CEF logs distinct from normal logs". I like this way more.

yea, this still has cef being used explicitly, but everything sent to cef is also passed back to us as a normal log.

Cool, I like it.

shane-tomlinson · 2013-12-13T15:20:27Z

@seanmonstar - intel is a nice lib! All of my concerns are inline in comments already, I have not yet load tested this to see how it performs. I am seeing a substantial number of Selenium failures and am unsure whether they are caused by this PR or by something else.

shane-tomlinson · 2013-12-13T15:24:09Z

When running the selenium tests locally, this is the error I see:

Caused by: org.openqa.selenium.remote.ErrorHandler$UnknownServerException: Unable to locate element: {"method":"css selector","selector":"#login"}
Build info: version: '2.26.0', revision: '18041', time: '2012-11-01 19:33:38'
System info: os.name: 'Mac OS X', os.arch: 'x86_64', os.version: '10.9', java.version: '1.7.0_40'
Driver info: driver.version: unknown
    at <anonymous class>.<anonymous method>(file:///var/folders/x6/zd3bzsyd08v932ymg7t283rc0000gn/T/anonymous6389230538218104218webdriver-profile/extensions/[email protected]/components/driver_component.js:8319)
    at <anonymous class>.<anonymous method>(file:///var/folders/x6/zd3bzsyd08v932ymg7t283rc0000gn/T/anonymous6389230538218104218webdriver-profile/extensions/[email protected]/components/driver_component.js:8328)
    at <anonymous class>.<anonymous method>(file:///var/folders/x6/zd3bzsyd08v932ymg7t283rc0000gn/T/anonymous6389230538218104218webdriver-profile/extensions/[email protected]/components/command_processor.js:10337)
    at <anonymous class>.<anonymous method>(file:///var/folders/x6/zd3bzsyd08v932ymg7t283rc0000gn/T/anonymous6389230538218104218webdriver-profile/extensions/[email protected]/components/command_processor.js:10342)
    at <anonymous class>.<anonymous method>(file:///var/folders/x6/zd3bzsyd08v932ymg7t283rc0000gn/T/anonymous6389230538218104218webdriver-profile/extensions/[email protected]/components/command_processor.js:10282)
15:22:59.550 WARN - Exception: Unable to locate element: {"method":"css selector","selector":"#login"}
Command duration or timeout: 32 milliseconds
For documentation on this error, please visit: http://seleniumhq.org/exceptions/no_such_element.html
Build info: version: '2.26.0', revision: '18041', time: '2012-11-01 19:33:38'
System info: os.name: 'Mac OS X', os.arch: 'x86_64', os.version: '10.9', java.version: '1.7.0_40'
Driver info: driver.version: EventFiringWebDriver
Session ID: f93008e5-18ca-3249-91a8-d14810b88532
15:23:00.113 INFO - Executing: [find element: By.selector: #login] at URL: /session/1386948151112/element)
15:23:00.644 WARN - Exception thrown

jrgm · 2013-12-13T17:57:22Z

@shane-tomlinson actually, the ssl cert for testidp.org has expired, so a lot of selenium tests are failing at the moment.

seanmonstar · 2013-12-14T00:51:52Z

@shane-tomlinson you rock!

seanmonstar · 2013-12-14T02:08:54Z

@shane-tomlinson I rebased in fixes for many of the comments. Some I left questions back for you.

I have some work in intel@master that will allow me to remove several of the filters from lib/logging/filters and have them be in the config, removing more files and long live config!

shane-tomlinson · 2013-12-16T10:16:10Z

@seanmonstar - can you add this diff?

diff --git a/lib/logging/filters/statsd-increment.js b/lib/logging/filters/statsd-increment.js
index 6f6fd10..cedf569 100644
--- a/lib/logging/filters/statsd-increment.js
+++ b/lib/logging/filters/statsd-increment.js
@@ -12,8 +12,6 @@ var IncrementRegExpMatches = [
   /^wsapi\./
 ];

-uncaught_exceptions
-
 exports.test = function(msg) {
   for (var i = 0, regExp; regExp = IncrementRegExpMatches[i]; ++i) {
     if (regExp.test(msg)) return true;

shane-tomlinson · 2013-12-16T10:43:55Z

@seanmonstar - looking manually through the logs on a test instance, the entire configuration is printed when the processes start, meaning SMTP, database & other secret info is placed in the logs. Can this be filtered for production environments?

shane-tomlinson · 2013-12-16T10:45:21Z

#4045 (comment) remove more files!

shane-tomlinson · 2013-12-16T10:52:38Z

@seanmonstar - When attempting to run the load tests, I am seeing 503s when creating the initial users. This happened before, but I was able to complete the user creation ~50% of the time before, now I cannot at all. Quite possibly user error on my part.

[app@ip-10-105-2-239 bin]$ BROWSERID_FAKE_VERIFICATION=true ./load_gen -s https://intel-shane.personatest.org

jrgm · 2013-12-16T17:08:00Z

@seanmonstar - looking manually through the logs on a test instance, the entire configuration is printed when the processes start, meaning SMTP, database & other secret info is placed in the logs. Can this be filtered for production environments?

Not sure which you are asking to have turned off. Previously, it would put the config in the log on production environments, but not bother annoying the user in dev where it would have also been put in the console. I want the production dump to stay as-is.

seanmonstar · 2013-12-17T00:36:29Z

woops, I left in that uncaught_exception syntax error so I'd notice before commiting. Didn't do much good.

seanmonstar · 2013-12-17T01:00:38Z

@shane-tomlinson I had goofed on the uncaught_exception stuff. I had pulled it out, and was going to log ALL logged exceptions, but realized that wouldn't tell us which ones were uncaught. So, I've split them into separate statsd counters, and all should be right in the world.

shane-tomlinson · 2013-12-17T10:22:07Z

Thanks for the feedback about the production dump @jrgm.

shane-tomlinson · 2013-12-17T11:42:27Z

Thanks for the changes @seanmonstar!

From a dev standpoint, I am good with this PR as it is. Doing local load testing, I am seeing a slight performance regression from the current dev. Method:

3 windows & a stopwatch needed.

Window 1:
sudo htop, then sort by TIME+

Window 2:

BROWSERID_FAKE_VERIFICATION=1 NODE_ENV=test_mysql npm start

Stopwatch:
Set to count down 1:30.

Window 3:

bin/load_gen -s http://127.0.0.1:10002 -m 250000

Start the stopwatch and load_gen at the same time.

In the window with htop, keep track of the TIME+ of the router.

Stop load_gen when the stopwatch completes at 1:30.

With the current dev, the router uses ~0:00.17
With intel, the router uses ~0:00.20

@jrgm - you have far more fu at load testing than I, could you give this a whirl and see what you think?

shane-tomlinson · 2013-12-17T11:46:03Z

@seanmonstar - I am seeing failures when running the backend tests locally:

tests/statsd-test.js
Setting NODE_ENV to test_json to test with the local JSON database
To test with a local mysql database, setup mysql and set NODE_ENV to test_mysql
····✗·✗·✗·✗··················


    assertion_failure - increments
      ✗ and reports to statsd
        »
        actual expected

        browserid.vows.assertion_failure { field: 'value' }
         // statsd-test.js:52

    wsapi_code_mismatch.wsapi_url - increments
      ✗ and reports to statsd
        »
        actual expected

        browserid.vows.wsapi_code_mismatch.wsapi_url { field: 'value' }
         // statsd-test.js:52

    wsapi.wsapi_url - increments
      ✗ and reports to statsd
        »
        actual expected

        browserid.vows.wsapi.wsapi_url { field: 'value' }
         // statsd-test.js:52

    uncaught_exception - increments
      ✗ and reports to statsd
        »
        actual expected

        browserid.vows.uncaught_exception { field: 'value' }
         // statsd-test.js:52
  ✗ Broken » 25 honored ∙ 4 broken (3.650s)
  %                                                                                 [~PERSONA_ROOT]

seanmonstar · 2014-01-09T19:08:55Z

@callahad fixed @shane-tomlinson latest comment.

only other thing i'd point out, is that the json is likely a little different than what winston output. is that terrible?

jaredhirsch · 2014-03-08T17:59:40Z

@seanmonstar this was the thing that killed the 10.23 release, right? Perf regressions with toobusy and logging? Looking at the code, doubt I'll get the review done today (been a while...)

Still seeing unit test errors locally for me, might be my setup?


  tests/email-throttling-test.js
·····dbwriter (28355): ERROR bid.cef: Throttling email staging request { signature: 'EMAIL_LOAD',
········  

  tests/stalled-mysql-test.js
·········browserid (27970): ERROR bid.cef: emailKnown failed { signature: 'DB_FAILURE',
·······························

jaredhirsch · 2014-03-08T18:00:12Z

@seanmonstar ah yup, looks like travis is fine. mind rebasing?

seanmonstar · 2014-03-08T21:50:59Z

rebased!

jaredhirsch · 2014-03-10T04:11:50Z

lib/primary.js

@@ -320,7 +320,7 @@ exports.getPublicKey = function(domain, cb) {
 // Is issuingDomain allowed to issue certifications for emails from
 // emailDomain.
 exports.delegatesAuthority = function (emailDomain, issuingDomain, cb) {
-  exports.checkSupport(emailDomain, function(err, r) {
+  exports.checkSupport(emailDomain, function onSupportChecked(err, r) {


yay function names 🍻

jaredhirsch · 2014-03-10T04:16:59Z

@seanmonstar Do you know anything about toobusy load testing for this patch? Been a while, I could use some help getting going. Maybe we can fill out the infamous empty section of the load_gen documentation that explains how to use the tool. paging @jrgm and/or @jbonacci :-)

shane-tomlinson reviewed Dec 13, 2013
View reviewed changes

seanmonstar mentioned this pull request Feb 11, 2014

First pass metrics logging mozilla/fxa-auth-server#372

Closed

winston out, intel in

e635952

jaredhirsch reviewed Mar 10, 2014
View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

winston out, intel in #4045

winston out, intel in #4045

seanmonstar commented Dec 9, 2013

shane-tomlinson commented Dec 10, 2013

seanmonstar commented Dec 10, 2013

shane-tomlinson commented Dec 13, 2013

shane-tomlinson Dec 13, 2013

seanmonstar Dec 14, 2013

shane-tomlinson Dec 17, 2013

shane-tomlinson commented Dec 13, 2013

shane-tomlinson commented Dec 13, 2013

jrgm commented Dec 13, 2013

seanmonstar commented Dec 14, 2013

seanmonstar commented Dec 14, 2013

shane-tomlinson commented Dec 16, 2013

shane-tomlinson commented Dec 16, 2013

shane-tomlinson commented Dec 16, 2013

shane-tomlinson commented Dec 16, 2013

jrgm commented Dec 16, 2013

seanmonstar commented Dec 17, 2013

seanmonstar commented Dec 17, 2013

shane-tomlinson commented Dec 17, 2013

shane-tomlinson commented Dec 17, 2013

shane-tomlinson commented Dec 17, 2013

seanmonstar commented Jan 9, 2014

jaredhirsch commented Mar 8, 2014

jaredhirsch commented Mar 8, 2014

seanmonstar commented Mar 8, 2014

jaredhirsch Mar 10, 2014

jaredhirsch commented Mar 10, 2014

winston out, intel in #4045

Are you sure you want to change the base?

winston out, intel in #4045

Conversation

seanmonstar commented Dec 9, 2013

shane-tomlinson commented Dec 10, 2013

seanmonstar commented Dec 10, 2013

shane-tomlinson commented Dec 13, 2013

shane-tomlinson Dec 13, 2013

Choose a reason for hiding this comment

seanmonstar Dec 14, 2013

Choose a reason for hiding this comment

shane-tomlinson Dec 17, 2013

Choose a reason for hiding this comment

shane-tomlinson commented Dec 13, 2013

shane-tomlinson commented Dec 13, 2013

jrgm commented Dec 13, 2013

seanmonstar commented Dec 14, 2013

seanmonstar commented Dec 14, 2013

shane-tomlinson commented Dec 16, 2013

shane-tomlinson commented Dec 16, 2013

shane-tomlinson commented Dec 16, 2013

shane-tomlinson commented Dec 16, 2013

jrgm commented Dec 16, 2013

seanmonstar commented Dec 17, 2013

seanmonstar commented Dec 17, 2013

shane-tomlinson commented Dec 17, 2013

shane-tomlinson commented Dec 17, 2013

shane-tomlinson commented Dec 17, 2013

seanmonstar commented Jan 9, 2014

jaredhirsch commented Mar 8, 2014

jaredhirsch commented Mar 8, 2014

seanmonstar commented Mar 8, 2014

jaredhirsch Mar 10, 2014

Choose a reason for hiding this comment

jaredhirsch commented Mar 10, 2014