Skip to content

Verbose logging for http connection #3

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
AntonShanyuk wants to merge 3 commits into
base: master
Choose a base branch
from
Open

Verbose logging for http connection #3

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
1fb1331
Increased logging for start proxying
AntonShanyuk Dec 13, 2019
c855707
Added http connection logging
AntonShanyuk Dec 17, 2019
eae0b97
Added logging into error handlers
AntonShanyuk Dec 19, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
65 changes: 45 additions & 20 deletions index.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -63,38 +63,63 @@ class HttpProxy {

handle() {
return ((req, res, next) => {
this.logger.debug(`Proxying ${req.url}`);
this.logger.info(`Proxying ${req.url}`);

const options = Object.assign({}, this.options, {
path: this.createProxyUrl(req),
method: req.method
});

const proxyReq = this.http.request(options, (proxyRes) => {
res.status(proxyRes.statusCode);
this.copyResponseHeaders(
res,
this.filterResponseHeaders(req, proxyRes.headers)
);
proxyRes.pipe(res, {
try {
const proxyReq = this.http.request(options, (proxyRes) => {
res.status(proxyRes.statusCode);
this.copyResponseHeaders(
res,
this.filterResponseHeaders(req, proxyRes.headers)
);
proxyRes.pipe(res, {
end: true
});
});

proxyReq.once("timeout", () => {
next(new Error(`Upstream timeout for ${req.url}, requestId: ${requestId}`));
});

proxyReq.once("error", (err) => {
this.logger.error(`Async error while proxying ${req.url}: ${err}`);
next(err);
});

this.copyRequestHeaders(req, proxyReq);
this.processRequestHeaders(req, proxyReq);
const requestId = proxyReq.getHeader("x-sl-requestid");
this.logRequestEvents(proxyReq, this.logger.child({ requestId }));

req.pipe(proxyReq, {
end: true
});
});
} catch (error) {
this.logger.error(`Synchronous error while proxying ${req.url}: ${error}`);
throw error;
}
});
}

proxyReq.once("timeout", () => {
next(new Error(`Upstream timeout for ${req.url}`));
logRequestEvents(req, logger) {
logger.info("Listening for request events");
req.once("socket", (socket) => {
logger.info("Socket created");
socket.once("lookup", () => {
logger.info("DNS Lookup finished");
});

proxyReq.once("error", (err) => {
next(err);
socket.once("connect", () => {
logger.info("Connection established");
});

this.copyRequestHeaders(req, proxyReq);
this.processRequestHeaders(req, proxyReq);
req.pipe(proxyReq, {
end: true
socket.once("secureConnect", () => {
logger.info("TLS handshake completed");
});
});
})
}
}

Expand Down
72 changes: 66 additions & 6 deletions test/proxy-spec.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -19,56 +19,89 @@ const HttpProxy = require("../index");
const test = require("blue-tape");
const fetch = require("node-fetch");
const FormData = require("form-data");
const EventEmitter = require("events");

let backend;
let app;
const info = message => ({ message, level: "info" });
const debug = message => ({ message, level: "debug" });
const error = message => ({ message, level: "error" });
const logger = {
setStorage: (storage) => { logger.storage = storage; },
info: message => logger.storage.push(info(message)),
debug: message => logger.storage.push(debug(message)),
error: message => logger.storage.push(error(message)),
child: () => logger
};

test("setup", (t) => {
logger.setStorage([]);
backend = new BackendApp();
app = new App(new HttpProxy({
hostname: "localhost",
protocol: "http:",
port: backend.port
}));
}, logger));
t.end();
});

test("Should proxy a get route", (t) => {
t.plan(1);
t.plan(2);
const logs = [];
logger.setStorage(logs);
return fetch(`http://localhost:${app.port}/proxy/foo`)
.then(res => res.json())
.then((body) => {
t.equal(body.message, "foobar");
t.deepEqual(logs, [
info('Proxying /foo'),
info('Listening for request events'),
info('Socket created'),
info('DNS Lookup finished'),
info('Connection established')
]);
})
.catch((err) => {
t.fail(err);
});
});

test("Should proxy get with query string", (t) => {
t.plan(2);
t.plan(3);
const foo = "aFoo";
const bar = "aBar";
const logs = [];
logger.setStorage(logs);
return fetch(`http://localhost:${app.port}/proxy/query?foo=${foo}&bar=${bar}`)
.then(res => res.json())
.then((body) => {
t.equal(body.foo, foo);
t.equal(body.bar, bar);
t.deepEqual(logs, [
info('Proxying /query?foo=aFoo&bar=aBar'),
info('Listening for request events'),
info('Socket created'),
info('DNS Lookup finished'),
info('Connection established')
]);
})
.catch((err) => {
t.fail(err);
});
});

test("Should proxy post with mutlipart form data", (t) => {
t.plan(2);
t.plan(3);
const form = new FormData();
const foo = "aFoo";
const bar = "aBar";

form.append("foo", foo);
form.append("bar", bar);

const logs = [];
logger.setStorage(logs);

return fetch(`http://localhost:${app.port}/proxy/multipart-form-upload`, {
method: "POST",
body: form,
Expand All @@ -78,18 +111,28 @@ test("Should proxy post with mutlipart form data", (t) => {
.then((body) => {
t.equal(body.foo, foo, "Posted field foo should be echoed back");
t.equal(body.bar, bar, "Posted field bar should be echoed back");
t.deepEqual(logs, [
info('Proxying /multipart-form-upload'),
info('Listening for request events'),
info('Socket created'),
info('DNS Lookup finished'),
info('Connection established')
]);
})
.catch((err) => {
t.fail(err);
});
});

test("Should proxy post with url-encoded form data", (t) => {
t.plan(2);
t.plan(3);
const foo = "aFoo";
const bar = "aBar";
const form = `foo=${foo}&bar=${bar}`;

const logs = [];
logger.setStorage(logs);

return fetch(`http://localhost:${app.port}/proxy/urlencoded-form-upload`, {
method: "POST",
body: form,
Expand All @@ -102,21 +145,38 @@ test("Should proxy post with url-encoded form data", (t) => {
.then((body) => {
t.equal(body.foo, foo, "Posted field foo should be echoed back");
t.equal(body.bar, bar, "Posted field bar should be echoed back");
t.deepEqual(logs, [
info('Proxying /urlencoded-form-upload'),
info('Listening for request events'),
info('Socket created'),
info('DNS Lookup finished'),
info('Connection established')
]);
})
.catch((err) => {
t.fail(err);
});
});

test("Should handle upstream hangup", (t) => {
t.plan(2);
t.plan(3);
const logs = [];
logger.setStorage(logs);
return fetch(`http://localhost:${app.port}/proxy/file`)
.then((res) => {
t.equal(502, res.status);
return res.json();
})
.then((body) => {
t.equal("socket hang up", body.error, "Expected socket hang up");
t.deepEqual(logs, [
info('Proxying /file'),
info('Listening for request events'),
info('Socket created'),
info('DNS Lookup finished'),
info('Connection established'),
error('Async error while proxying /file: Error: socket hang up')
]);
})
.catch((err) => {
t.fail(err);
Expand Down
Loading