Log http(s) requests for non-client library #51

BrunoBernardino · 2017-10-19T14:41:46Z

This provides more logging even if z.request isn't used (like when SDKs are used), by patching the http library in node.

This was tested with Dropbox and the interpreter "full test" app (with different non-client http/request libraries).

Relevant Trello Card.

What this changes

Logs requests (safely) for any http(s) request happening, outside of z.request.
Uses the user-agent: Zapier http header to differentiate from client requests and non-client ones.
Adds the ability to test logging locally in other apps, via process.env.LOGGING_TOKEN.
Adds a request_via_client: Boolean data property for GL, to differentiate from the different logs.
Doesn't log the requests that are made to GL
Adds a couple of tests test for the user-agent header

Log

Log http(s) requests for non-client library (f9111da)

Fixes https://trello.com/c/uUo9ZCoU/193-cli-track-all-outgoing-requests-whatever-library-is-used

This also adds a "user-agent: Zapier" header, which is used to differentiate from client requests and non-client ones.

It also adds the ability to test logging locally in other apps, via the process.env.LOGGING_TOKEN

Removing memory leak and adding more tests (c84f6d9)

Don't set encoding. (f846d6e)

Fixes https://trello.com/c/uUo9ZCoU/193-cli-track-all-outgoing-requests-whatever-library-is-used This also adds a "user-agent: Zapier" header, which is used to differentiate from client requests and non-client ones. It also adds the ability to test logging locally in other apps, via the `process.env.LOGGING_TOKEN`

FokkeZB · 2017-10-19T16:04:37Z

src/http-middlewares/before/prepare-request.js

@@ -17,6 +17,7 @@ const sugarBody = (req) => {
  // move into the body as raw, set headers for coerce, merge to work

  req.headers = req.headers || {};
+  req.headers['user-agent'] = 'Zapier';


The user is able to override this right?

Yes, but I'll add that to the headers merging test just to make sure.

FokkeZB · 2017-10-19T16:05:44Z

src/tools/create-lambda-handler.js

+    // Adds logging for _all_ kinds of http(s) requests, no matter the library
+    const httpPatch = createHttpPatch(event);
+    httpPatch(require('http'));
+    // httpPatch(require('https')); // NOTE: This was double-logging


Yup, uses http under the hood.

Guess just nuke it then!

bcooksey

Interesting take on this @BrunoBernardino, I like it!

As part of this effort, it might make sense to add some documentation on how devs can get logging working on their own. Basically show off what tooling we provide and how they might hook into it. My thought is that this is a great start, and could end up covering lots of use cases. I could see some though where it's not an http protocol, or doesn't use the node standard lib, or maybe a dev wants to wire in great logging to an SDK and overwrite our default one. I think it would only take a code snippet or two and a bit of explanation to show what logging call to make to do that.

bcooksey · 2017-10-19T20:54:44Z

src/tools/create-http-patch.js

+            request_url: requestUrl,
+            request_method: options.method || 'GET',
+            request_headers: requestHeaders.join('\n'),
+            request_data: options.body || '',


Might make sense to check if this was a file and do something like instead of the full body.

I didn't want to do it here because the createLogger takes care of truncating and similar "cleaning" (like obfuscating sensitive data), so it'd effectively be almost duplicating work in a very quick sequential way.

If you think it's still a nice improvement, I'm happy to add it here.

Nope, if it is covered elsewhere that is fine

bcooksey · 2017-10-19T20:55:09Z

src/tools/create-lambda-handler.js

+    // Adds logging for _all_ kinds of http(s) requests, no matter the library
+    const httpPatch = createHttpPatch(event);
+    httpPatch(require('http'));
+    // httpPatch(require('https')); // NOTE: This was double-logging


Guess just nuke it then!

BrunoBernardino · 2017-10-20T07:22:58Z

Thanks @bcooksey ! Can you please elaborate on that logging thought?

As a dev, I can require a logging lib and call it before/after requests, or at specific parts of the app. We don't expose our logger (especially because it's specific to our needs and logging tools), and if we did, I can see how that'd be more confusing (to create a logger instance with some ENV data, then log in a specific format), rather than just using their own logging lib.

Or are you asking for me to add such snippets to the CLI README (with an external logging tool like papertrail, not using/overriding our own logging)?

FokkeZB · 2017-10-20T14:52:12Z

@BrunoBernardino why wouldn't we log these requests to Graylog?

BrunoBernardino · 2017-10-20T14:55:57Z

@FokkeZB to avoid circular/infinite loops 😄

bcooksey · 2017-10-20T15:03:36Z

@BrunoBernardino I was actually thinking about exposing our logger. So essentially, there would be three options:

Use z.requests - logged automatically
Use a library that uses Node's http lib - logged automatically

Docs to show devs how they can do something like:

const logger = require('zapier-logger'); // I didn't look to see what the actual package is
logger.log('Sending note to Evernote via Thrift', {noteSize: 1322, notebookId: 3})

Would that third option make sense?

BrunoBernardino · 2017-10-20T15:25:13Z

I see... How is that different from z.console.log()? I don't think we should expose that "without any bundle/z info" because then it can't do the obfuscation, though it wouldn't happen with an external logging library as well.

bcooksey · 2017-10-20T18:55:25Z

@BrunoBernardino Ah right. I was thinking we blocked those logs for public apps, but they get through, so that would be enough!

bcooksey

Some things to consider with how we tap into the response.

bcooksey · 2017-10-20T18:57:31Z

src/tools/create-http-patch.js

+            request_url: requestUrl,
+            request_method: options.method || 'GET',
+            request_headers: requestHeaders.join('\n'),
+            request_data: options.body || '',


Nope, if it is covered elsewhere that is fine

bcooksey · 2017-10-20T20:59:01Z

src/tools/create-http-patch.js

+        response.setEncoding('utf8');
+        response.on('data', (chunk) => responseBody.push(chunk));
+        response.on('end', logResponse);
+        response.on('error', logResponse);


I don't think we can safely attach all of these. I wrote a gist to demonstrate some behaviors and found this:

setEncoding() swaps the incoming values to the data listener from buffers to strings, which is probably not a nice thing to do to devs

setEncoding() will, obviously, encode the data, so if binary data being transferred, devs would have to decode it to get back to what they want

Adding a data handler swaps the stream mode from paused to flowing. This can cause .read() to return no data. As far as how much we should care, seems like an app will end up doing a .pipe() or something and get it into flow mode anyway, but it is a nasty edge to force on folks. If we knew consuming data via .read() was rare, I'd be fine ignoring this point.

Wow, nice catches! I'll see if I can tap into that without changing data (will use your gist).

If I can't, I'll remove that and we'll log without the response content (still better than nothing). If it becomes something we really want, we can then try to look into ways of tapping into it more safely, maybe.

You may also want to look into how NewRelic wraps http.request and friends. Pretty sure they've made sure not to break it: https://github.com/newrelic/node-newrelic/blob/master/lib/instrumentation/core/http.js#L579-L606

Thanks @FokkeZB. After looking through it and trying it out for a while, it seems their wrapper libraries/methods are very complex and generic (and the request/response parts use the agent and eventemitters, which, while probably better, seem like a major overkill for what we're going for here).

I was able to confirm no app in CLI is currently calling anything .read(), so I think we're safe on @bcooksey 's third concern. I ditched the setEncoding and that seems to still be working fine (worst case scenario we might have some encoding issues on GL, and we can try to tweak that if so, later).

Let me know if that works fine.

bcooksey

Alright, I think this is looking good now. I'm still a bit unsure on the use of read(). It's not in app code, but what about sdk's? However, Node docs push folks to use .pipe. If we do run into an issue, we may be able to have an app declare it wants to disable the http patch some way.

bcooksey · 2017-10-25T16:30:34Z

src/tools/create-http-patch.js

+          logger(`${logData.response_status_code} ${logData.request_method} ${logData.request_url}`, logData);
+        };
+
+        response.on('data', (chunk) => responseBody.push(chunk.toString()));


Cool, this way we'll still get utf8 strings being logged, but it won't mess with any other listeners on the 'data' event.

BrunoBernardino added the enhancement label Oct 19, 2017

BrunoBernardino self-assigned this Oct 19, 2017

BrunoBernardino requested a review from bcooksey October 19, 2017 14:41

FokkeZB reviewed Oct 19, 2017

View reviewed changes

FokkeZB approved these changes Oct 19, 2017

View reviewed changes

bcooksey reviewed Oct 19, 2017

View reviewed changes

Removing memory leak and adding more tests

c84f6d9

bcooksey suggested changes Oct 20, 2017

View reviewed changes

Don't set encoding.

f846d6e

bcooksey approved these changes Oct 25, 2017

View reviewed changes

BrunoBernardino merged commit 94fed1e into master Oct 25, 2017

BrunoBernardino deleted the feature-add-global-logging branch October 25, 2017 18:17

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Log http(s) requests for non-client library #51

Log http(s) requests for non-client library #51

BrunoBernardino commented Oct 19, 2017 •

edited

Loading

FokkeZB Oct 19, 2017

BrunoBernardino Oct 20, 2017

FokkeZB Oct 19, 2017

bcooksey Oct 19, 2017

bcooksey left a comment

bcooksey Oct 19, 2017

BrunoBernardino Oct 20, 2017 •

edited

Loading

bcooksey Oct 20, 2017

bcooksey Oct 19, 2017

BrunoBernardino commented Oct 20, 2017 •

edited

Loading

FokkeZB commented Oct 20, 2017

BrunoBernardino commented Oct 20, 2017

bcooksey commented Oct 20, 2017

BrunoBernardino commented Oct 20, 2017 •

edited

Loading

bcooksey commented Oct 20, 2017

bcooksey left a comment

bcooksey Oct 20, 2017

bcooksey Oct 20, 2017

BrunoBernardino Oct 23, 2017

FokkeZB Oct 23, 2017

BrunoBernardino Oct 24, 2017

bcooksey left a comment

bcooksey Oct 25, 2017

Log http(s) requests for non-client library #51

Log http(s) requests for non-client library #51

Conversation

BrunoBernardino commented Oct 19, 2017 • edited Loading

What this changes

Log

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bcooksey left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

BrunoBernardino Oct 20, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

BrunoBernardino commented Oct 20, 2017 • edited Loading

FokkeZB commented Oct 20, 2017

BrunoBernardino commented Oct 20, 2017

bcooksey commented Oct 20, 2017

BrunoBernardino commented Oct 20, 2017 • edited Loading

bcooksey commented Oct 20, 2017

bcooksey left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bcooksey left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

BrunoBernardino commented Oct 19, 2017 •

edited

Loading

BrunoBernardino Oct 20, 2017 •

edited

Loading

BrunoBernardino commented Oct 20, 2017 •

edited

Loading

BrunoBernardino commented Oct 20, 2017 •

edited

Loading