diff --git a/.eslintrc.yml b/.eslintrc.yml new file mode 100644 index 0000000..29496bb --- /dev/null +++ b/.eslintrc.yml @@ -0,0 +1,3 @@ +extends: fullstack +rules: + semi: [1, never] diff --git a/.gitignore b/.gitignore new file mode 100644 index 0000000..bf3a802 --- /dev/null +++ b/.gitignore @@ -0,0 +1,23 @@ +# installed packages (better: `npm install` / `bower install`) +node_modules +bower_components + +# OS-generated files +.DS_Store +.DS_Store? +._* +.Spotlight-V100 +.Trashes +ehthumbs.db +Thumbs.db + +# Logs and databases +*.log +*.sqlite + +# Vim swap files +*.sw? + +# IDE files +.idea +.vscode diff --git a/LICENSE b/LICENSE new file mode 100644 index 0000000..1a05c87 --- /dev/null +++ b/LICENSE @@ -0,0 +1,21 @@ +The MIT License (MIT) + +Copyright (c) 2016 Gabriel Lebec + +Permission is hereby granted, free of charge, to any person obtaining a copy +of this software and associated documentation files (the "Software"), to deal +in the Software without restriction, including without limitation the rights +to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +copies of the Software, and to permit persons to whom the Software is +furnished to do so, subject to the following conditions: + +The above copyright notice and this permission notice shall be included in +all copies or substantial portions of the Software. + +THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN +THE SOFTWARE. diff --git a/README.md b/README.md new file mode 100644 index 0000000..5c9d902 --- /dev/null +++ b/README.md @@ -0,0 +1,59 @@ +# 🏐 Volleyball + +### Small Express HTTP logger for debugging asynchronous requests and responses + +```js +const app = require('express')() +const volleyball = require('volleyball') + +app.use(volleyball) +``` + +Volleyball is a minimal Connect-style middleware function which logs incoming requests and outgoing responses as separate events. It optionally supports the [`debug`](https://github.com/visionmedia/debug#readme) module. + +## Motivation + +Logging HTTP cycles can be approached in several ways, each with its own drawbacks: + +* Log only upon **request**. Drawback: we cannot log the corresponding response, which happens later (if at all). +* Log only upon **response**, attaching the request. Drawback A: if the server never sends a response, e.g. due to a bug, the request will not be logged either. Drawback B: two temporally distinct events are conflated, misleadingly. +* Log both upon **request** and **response**. Drawback: it is not necessarily clear which responses are for which requests. + +Volleyball takes the last approach, and assigns randomly-generated ids to label request-response pairs. It is designed for student project development, teaching beginning programmers how HTTP servers and asynchronicity work. It may also be useful as a low-configuration debug tool. + +## Usage + +### `volleyball` + +The `volleyball` module can be used directly as demonstrated in the first example. The module defaults to using `process.stdout` for output. + +### `volleyball.custom(config)` + +A customized logging middleware can be generated by calling `custom` with a configuration object: + +```js +const logger = volleyball.custom({ debug: true }) // default namespace 'http' +// const logger = volleyball.custom({ debug: 'custom-namespace' }) +// const logger = volleyball.custom({ debug: debugInstance }) + +app.use(logger) +``` + +The `debug` property logs using the [`debug`](https://github.com/visionmedia/debug#readme) module. It supports the following values: + +value | result +----|---- +`true` | uses a new debug instance with a default namespace of `'http'` +string | uses a new debug instance with a custom namespace +function | uses any function, such as a pre-generated debug instance. Note that the function will be called with colorized strings. + +## Related and Alternatives + +For more powerful, configurable, and compatible logging needs, check out: + +* [debug](https://github.com/visionmedia/debug#readme) +* [morgan](https://github.com/expressjs/morgan#readme) +* [morgan-debug](https://github.com/ChiperSoft/morgan-debug#readme) +* [winston](https://github.com/winstonjs/winston#readme) +* [express-winston](https://github.com/bithavoc/express-winston#readme) +* [node-bunyan](https://github.com/trentm/node-bunyan/#readme) diff --git a/lib/id.js b/lib/id.js new file mode 100644 index 0000000..61e7653 --- /dev/null +++ b/lib/id.js @@ -0,0 +1,21 @@ +'use strict'; // eslint-disable-line semi + +const chalk = require('chalk') + +const nextColor = (function () { + const colors = ['red', 'green', 'yellow', 'cyan', 'magenta'] + let i = 0 + return function () { + return colors[i++ % colors.length] + } +}()) + +const CHARS = 'ABCDEFGHIJKLMNOPQRSTUVWXYZabcdefghijklmnopqrstuvwxyz0123456789' +const LEN = 4 + +module.exports = function makeId () { + const color = nextColor() + let id = '', i = LEN + while (i--) id += CHARS.substr(Math.random() * CHARS.length, 1) + return chalk.dim[color](id) +} diff --git a/lib/volleyball.js b/lib/volleyball.js new file mode 100644 index 0000000..f6fa39d --- /dev/null +++ b/lib/volleyball.js @@ -0,0 +1,97 @@ +'use strict'; // eslint-disable-line semi + +const http = require('http') +const debug = require('debug') +const chalk = require('chalk') +const filesize = require('filesize') +const makeId = require('./id') + +const sp = ' ' + +module.exports = new Volleyball() + +function Volleyball (config = {}) { + const logger = getLogger(config.debug) + + function volleyball (req, res, next) { + const shared = { + logger: logger, + id: makeId(), + time: process.hrtime() + } + + logReq(req, shared) + + res.on('finish', () => logRes(res, shared)) + res.on('close', () => logClose(res, shared)) + + next() + } + volleyball.custom = volleyballFactory + + return volleyball +} + +function volleyballFactory (...args) { + return new Volleyball(...args) +} + +function getLogger (debugChoice) { + if (!debugChoice) return defaultLogger + if (debugChoice === true) return debug('http') + if (typeof debugChoice === 'string') return debug(debugChoice) + if (typeof debugChoice === 'function') return debugChoice +} + +function defaultLogger (str) { + process.stdout.write(str + '\n') +} + +function logReq (req, shared) { + const bytes = +req.headers['content-length'] + const type = req.headers['content-type'] + + let reqLine = chalk.dim('<-') + ` ${shared.id} ` + reqLine += `${chalk.bold.underline(req.method)} ${req.url} ` + if (bytes) reqLine += chalk.blue(filesize(bytes)) + sp + if (type) reqLine += chalk.blue.dim(type) + + shared.logger(reqLine) +} + +function logRes (res, shared) { + const status = res.statusCode + const meaning = http.STATUS_CODES[status] + const bytes = +res.getHeader('content-length') + const type = res.getHeader('content-type') + + let statusColor + if (status >= 500) statusColor = 'red' + else if (status >= 400) statusColor = 'yellow' + else if (status >= 300) statusColor = 'cyan' + else if (status >= 200) statusColor = 'green' + else statusColor = 'reset' + + let resLine = ` ${shared.id} ` + chalk.dim('->') + sp + resLine += chalk[statusColor](`${status} ${meaning}`) + sp + if (bytes) resLine += chalk.blue(filesize(bytes)) + sp + if (type) resLine += chalk.blue.dim(type) + sp + resLine += chalk.dim(`(<-> ${msDiff(shared.time)} ms)`) + + shared.logger(resLine) +} + +function logClose (res, shared) { + let closeLine = `${chalk.dim('><')} ${shared.id} ${chalk.dim('><')} ` + closeLine += chalk.red('connection closed before res end/flush') + + shared.logger(closeLine) +} + +function msDiff (time) { + var diff = process.hrtime(time) + const seconds = diff[0] + const nanoseconds = diff[1] + const ms = (seconds * 1e9 + nanoseconds) / 1e6 + return ms.toFixed(1) +} diff --git a/package.json b/package.json new file mode 100644 index 0000000..38e8450 --- /dev/null +++ b/package.json @@ -0,0 +1,41 @@ +{ + "name": "volleyball", + "version": "1.0.0", + "description": "🏐 Tiny HTTP logger for Express showing asynchronous requests and responses", + "homepage": "https://github.com/glebec/volleyball", + "main": "lib/volleyball.js", + "scripts": { + "test": "DEBUG=http,custom mocha", + "lint": "eslint **/*.js --ignore-pattern node_modules" + }, + "author": "Gabriel Lebec (https://github.com/glebec)", + "license": "MIT", + "devDependencies": { + "chai": "^3.5.0", + "eslint": "^3.3.0", + "eslint-config-fullstack": "^1.4.1", + "express": "^4.14.0", + "mocha": "^3.0.2", + "supertest": "^2.0.0" + }, + "dependencies": { + "chalk": "^1.1.3", + "debug": "^2.2.0", + "filesize": "^3.3.0" + }, + "repository": { + "type": "git", + "url": "https://github.com/glebec/volleyball.git" + }, + "bugs": "https://github.com/glebec/volleyball/issues", + "keywords": [ + "HTTP", + "logging", + "logger", + "log", + "middleware", + "async", + "req", + "res" + ] +} diff --git a/test/test.js b/test/test.js new file mode 100644 index 0000000..e60f952 --- /dev/null +++ b/test/test.js @@ -0,0 +1,77 @@ +'use strict'; // eslint-disable-line semi +const supertest = require('supertest') +const expect = require('chai').expect +const express = require('express') +const chalk = require('chalk') +const debug = require('debug') +debug.log = console.log.bind(console) +const volleyball = require('../lib/volleyball') + +describe('volleyball', function () { + + it('is middleware', function () { + expect(volleyball).to.be.a('function') + expect(volleyball).to.have.length(3) + }) + +}) + +describe('An Express app', function () { + + const originalWrite = process.stdout.write + let app, client, record + beforeEach(function () { + record = '' + process.stdout.write = function (str) { + record += chalk.stripColor(str) + originalWrite.call(process.stdout, str) + } + app = express() + client = supertest(app) + }) + + afterEach(function () { + process.stdout.write = originalWrite + }) + + function test (done) { + client.get('/') + .expect(404) + .end(function (err) { + if (err) return done(err) + expect(record).to.match(/GET \/[\s\S]+404 Not Found/gm) + done() + }) + } + + describe('using volleyball', function () { + + beforeEach(function () { + app.use(volleyball) + }) + + it('logs requests and responses', test) + + }) + + describe('using volleyball with debug true', function () { + + beforeEach(function () { + app.use(volleyball.custom({debug: true})) + }) + + it('logs requests and responses', test) + + }) + + describe('using volleyball with debug custom', function () { + + beforeEach(function () { + app.use(volleyball.custom({debug: 'custom'})) + }) + + it('logs requests and responses', test) + + }) + +})