diff --git a/README.md b/README.md index dd40c599..e94c4b24 100644 --- a/README.md +++ b/README.md @@ -103,6 +103,64 @@ logger.info('hello winston') ``` +### Using as an express middleware (winston 3.1+) + +***NOTE: this feature is experimental. The API may change in a backwards +incompatible way until this is deemed stable. Please provide us feedback so +that we can better refine this express integration.*** + +We provide a middleware that can be used in an express application. Apart from +being easy to use, this enables some more powerful features of Stackdriver +Logging: request bundling. Any application logs emitted on behalf of a specific +request will be shown nested inside the request log as you see in this +screenshot: + +![Request Bundling Example](https://raw.githubusercontent.com/googleapis/nodejs-logging-winston/master/doc/images/request-bundling.png) + +This middleware adds a `winston`-style log function to the `request` object. +You can use this wherever you have access to the `request` object (`req` in the +sample below). All log entries that are made on behalf of a specific request are +shown bundled together in the Stackdriver Logging UI. + +```javascript +const lw = require('@google-cloud/logging-winston'); + +// Import express module and create an http server. +const express = require('express'); + +async function main() { + const {logger, mw} = await lw.express.middleware(); + const app = express(); + + // Install the logging middleware. This ensures that a Winston-style `log` + // function is available on the `request` object. Attach this as one of the + // earliest middleware to make sure that the log function is available in all + // subsequent middleware and routes. + app.use(mw); + + // Setup an http route and a route handler. + app.get('/', (req, res) => { + // `req.log` can be used as a winston style log method. All logs generated + // using `req.log` use the current request context. That is, all logs + // corresponding to a specific request will be bundled in the Stackdriver + // UI. + req.log.info('this is an info log message'); + res.send('hello world'); + }); + + // `logger` can be used as a global logger, one not correlated to any specific + // request. + logger.info('bonjour'); + + // Start listening on the http server. + app.listen(8080, () => { + logger.info('http server listening on port 8080'); + }); +} + +main(); +``` + ### Error Reporting Any `Error` objects you log at severity `error` or higher can automatically be picked up by [Stackdriver Error Reporting][error-reporting] if you have specified a `serviceContext.service` when instantiating a `LoggingWinston` instance: diff --git a/doc/images/request-bundling.png b/doc/images/request-bundling.png new file mode 100644 index 00000000..e81e2be3 Binary files /dev/null and b/doc/images/request-bundling.png differ diff --git a/package-lock.json b/package-lock.json index bc86c5de..52447826 100644 --- a/package-lock.json +++ b/package-lock.json @@ -2098,12 +2098,6 @@ "integrity": "sha1-qEq8glpV70yysCi9dOIFpluaSZY=", "dev": true }, - "caller": { - "version": "1.0.1", - "resolved": "https://registry.npmjs.org/caller/-/caller-1.0.1.tgz", - "integrity": "sha1-uFGGD3Dhlds9J3OVqhp+I+ow7PU=", - "dev": true - }, "caller-callsite": { "version": "2.0.0", "resolved": "https://registry.npmjs.org/caller-callsite/-/caller-callsite-2.0.0.tgz", @@ -4450,8 +4444,7 @@ "ansi-regex": { "version": "2.1.1", "bundled": true, - "dev": true, - "optional": true + "dev": true }, "aproba": { "version": "1.2.0", @@ -4472,14 +4465,12 @@ "balanced-match": { "version": "1.0.0", "bundled": true, - "dev": true, - "optional": true + "dev": true }, "brace-expansion": { "version": "1.1.11", "bundled": true, "dev": true, - "optional": true, "requires": { "balanced-match": "^1.0.0", "concat-map": "0.0.1" @@ -4494,20 +4485,17 @@ "code-point-at": { "version": "1.1.0", "bundled": true, - "dev": true, - "optional": true + "dev": true }, "concat-map": { "version": "0.0.1", "bundled": true, - "dev": true, - "optional": true + "dev": true }, "console-control-strings": { "version": "1.1.0", "bundled": true, - "dev": true, - "optional": true + "dev": true }, "core-util-is": { "version": "1.0.2", @@ -4624,8 +4612,7 @@ "inherits": { "version": "2.0.3", "bundled": true, - "dev": true, - "optional": true + "dev": true }, "ini": { "version": "1.3.5", @@ -4637,7 +4624,6 @@ "version": "1.0.0", "bundled": true, "dev": true, - "optional": true, "requires": { "number-is-nan": "^1.0.0" } @@ -4652,7 +4638,6 @@ "version": "3.0.4", "bundled": true, "dev": true, - "optional": true, "requires": { "brace-expansion": "^1.1.7" } @@ -4660,14 +4645,12 @@ "minimist": { "version": "0.0.8", "bundled": true, - "dev": true, - "optional": true + "dev": true }, "minipass": { "version": "2.3.5", "bundled": true, "dev": true, - "optional": true, "requires": { "safe-buffer": "^5.1.2", "yallist": "^3.0.0" @@ -4686,7 +4669,6 @@ "version": "0.5.1", "bundled": true, "dev": true, - "optional": true, "requires": { "minimist": "0.0.8" } @@ -4767,8 +4749,7 @@ "number-is-nan": { "version": "1.0.1", "bundled": true, - "dev": true, - "optional": true + "dev": true }, "object-assign": { "version": "4.1.1", @@ -4780,7 +4761,6 @@ "version": "1.4.0", "bundled": true, "dev": true, - "optional": true, "requires": { "wrappy": "1" } @@ -4866,8 +4846,7 @@ "safe-buffer": { "version": "5.1.2", "bundled": true, - "dev": true, - "optional": true + "dev": true }, "safer-buffer": { "version": "2.1.2", @@ -4903,7 +4882,6 @@ "version": "1.0.2", "bundled": true, "dev": true, - "optional": true, "requires": { "code-point-at": "^1.0.0", "is-fullwidth-code-point": "^1.0.0", @@ -4923,7 +4901,6 @@ "version": "3.0.1", "bundled": true, "dev": true, - "optional": true, "requires": { "ansi-regex": "^2.0.0" } @@ -4967,14 +4944,12 @@ "wrappy": { "version": "1.0.2", "bundled": true, - "dev": true, - "optional": true + "dev": true }, "yallist": { "version": "3.0.3", "bundled": true, - "dev": true, - "optional": true + "dev": true } } }, @@ -9880,15 +9855,6 @@ "integrity": "sha1-jGStX9MNqxyXbiNE/+f3kqam30I=", "dev": true }, - "require-inject": { - "version": "1.4.4", - "resolved": "https://registry.npmjs.org/require-inject/-/require-inject-1.4.4.tgz", - "integrity": "sha512-5Y5ctRN84+I4iOZO61gm+48tgP/6Hcd3VZydkaEM3MCuOvnHRsTJYQBOc01faI/Z9at5nsCAJVHhlfPA6Pc0Og==", - "dev": true, - "requires": { - "caller": "^1.0.1" - } - }, "require-main-filename": { "version": "2.0.0", "resolved": "https://registry.npmjs.org/require-main-filename/-/require-main-filename-2.0.0.tgz", diff --git a/package.json b/package.json index 1a2caa5d..ec60de54 100644 --- a/package.json +++ b/package.json @@ -78,18 +78,18 @@ "eslint-plugin-prettier": "^3.0.0", "gts": "^0.9.0", "intelli-espower-loader": "^1.0.1", + "linkinator": "^1.1.2", "mocha": "^6.0.0", "post-install-check": "0.0.1", "prettier": "^1.13.6", - "require-inject": "^1.4.3", + "proxyquire": "^2.1.0", "source-map-support": "^0.5.6", "teeny-request": "^3.6.0", "typescript": "^3.0.0", "uuid": "^3.3.2", - "winston": "^3.1.0", - "linkinator": "^1.1.2" + "winston": "^3.1.0" }, "peerDependencies": { - "winston": "3.x" + "winston": ">=3.1.0" } } diff --git a/src/common.ts b/src/common.ts index 4f53b816..defe9fd4 100644 --- a/src/common.ts +++ b/src/common.ts @@ -13,7 +13,6 @@ * See the License for the specific language governing permissions and * limitations under the License. */ - import * as util from 'util'; import * as types from './types/core'; diff --git a/src/index.ts b/src/index.ts index d3645e2f..3e4e35b4 100644 --- a/src/index.ts +++ b/src/index.ts @@ -2,8 +2,12 @@ import * as TransportStream from 'winston-transport'; import {LOGGING_TRACE_KEY as COMMON_TRACE_KEY, LoggingCommon} from './common'; +import * as express from './middleware/express'; import * as types from './types/core'; +// Export the express middleware as 'express'. +export {express}; + type Callback = (err: Error, apiResponse: {}) => void; /** diff --git a/system-test/logging-winston.ts b/system-test/logging-winston.ts index 9a71697c..175f23d6 100644 --- a/system-test/logging-winston.ts +++ b/system-test/logging-winston.ts @@ -21,7 +21,7 @@ import * as types from '../src/types/core'; import {ErrorsApiTransport} from './errors-transport'; -const inject = require('require-inject'); +const proxyquire = require('proxyquire'); const winston = require('winston'); @@ -109,9 +109,7 @@ describe('LoggingWinston', function() { ] as TestData[]); const LOG_NAME = logName('logging_winston_system_tests'); - const LoggingWinston = inject('../src/index', { - winston, - }).LoggingWinston; + const LoggingWinston = proxyquire('../src/index', {winston}).LoggingWinston; const logger = winston.createLogger({ transports: [new LoggingWinston({logName: LOG_NAME})], @@ -143,9 +141,8 @@ describe('LoggingWinston', function() { it('reports errors', async () => { const start = Date.now(); const service = `logging-winston-system-test-winston3-${UUID}`; - const LoggingWinston = inject('../src/index', { - winston, - }).LoggingWinston; + const LoggingWinston = + proxyquire('../src/index', {winston}).LoggingWinston; const logger = winston.createLogger({ transports: [new LoggingWinston( diff --git a/system-test/test-middleware-express.ts b/system-test/test-middleware-express.ts new file mode 100644 index 00000000..84fa71ce --- /dev/null +++ b/system-test/test-middleware-express.ts @@ -0,0 +1,80 @@ +/*! + * Copyright 2018 Google LLC + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +import * as assert from 'assert'; +import delay from 'delay'; +import * as uuid from 'uuid'; +import {express as elb} from '../src/index'; + +const {Logging} = require('@google-cloud/logging'); +const logging = new Logging(); + +const WRITE_CONSISTENCY_DELAY_MS = 20 * 1000; +const TEST_TIMEOUT = WRITE_CONSISTENCY_DELAY_MS + (10 * 1000); +const LOG_NAME = `winston-system-test-${uuid.v4()}`; + +describe(__filename, () => { + // tslint:disable-next-line:no-any + let logger: any; + // tslint:disable-next-line:no-any + let mw: any; + + before(async () => { + ({logger, mw} = await elb.middleware({logName: LOG_NAME, level: 'info'})); + }); + + describe('global logger', () => { + it('should properly write log entries', async () => { + const LOG_MESSAGE = `unique log message ${uuid.v4()}`; + logger.info(LOG_MESSAGE); + + await delay(WRITE_CONSISTENCY_DELAY_MS); + + const log = logging.log(`${LOG_NAME}_applog`); + const entries = (await log.getEntries({pageSize: 1}))[0]; + assert.strictEqual(entries.length, 1); + assert.strictEqual(LOG_MESSAGE, entries[0].data.message); + }).timeout(TEST_TIMEOUT); + }); + + describe('request logging middleware', () => { + it('should write request correlated log entries', (done) => { + const LOG_MESSAGE = `correlated log message ${uuid.v4()}`; + const fakeRequest = {headers: {fake: 'header'}}; + const fakeResponse = {}; + const next = async () => { + // At this point fakeRequest.log should have been installed. + // tslint:disable-next-line:no-any + (fakeRequest as any).log.info(LOG_MESSAGE); + + await delay(WRITE_CONSISTENCY_DELAY_MS); + + const log = logging.log(`${LOG_NAME}_applog`); + const entries = (await log.getEntries({pageSize: 1}))[0]; + assert.strictEqual(entries.length, 1); + const entry = entries[0]; + assert.strictEqual(LOG_MESSAGE, entry.data.message); + assert(entry.metadata.trace, 'should have a trace property'); + assert(entry.metadata.trace.match(/projects\/.*\/traces\/.*/)); + done(); + }; + + // Call middleware with mocks. + // tslint:disable-next-line:no-any + mw(fakeRequest as any, fakeResponse as any, next); + }).timeout(TEST_TIMEOUT); + }); +}); \ No newline at end of file diff --git a/test/common.ts b/test/common.ts index a1da4734..ebeb13e8 100644 --- a/test/common.ts +++ b/test/common.ts @@ -18,7 +18,7 @@ import * as assert from 'assert'; import * as nodeutil from 'util'; import * as types from '../src/types/core'; -const inject = require('require-inject'); +const proxyquire = require('proxyquire'); describe('logging-common', () => { let fakeLogInstance: types.StackdriverLogging; @@ -51,7 +51,7 @@ describe('logging-common', () => { Transport: FakeTransport, }; - const loggingCommonLib = inject('../src/common', { + const loggingCommonLib = proxyquire('../src/common', { '@google-cloud/logging': { Logging: fakeLogging, }, diff --git a/test/index.ts b/test/index.ts index d9b0cdea..739eb5a8 100644 --- a/test/index.ts +++ b/test/index.ts @@ -19,7 +19,7 @@ import * as TransportStream from 'winston-transport'; import * as types from '../src/types/core'; -const inject = require('require-inject'); +const proxyquire = require('proxyquire'); describe('logging-winston', () => { let fakeLoggingOptions_: types.Options|null; @@ -51,9 +51,9 @@ describe('logging-winston', () => { Transport: FakeTransport, }; - const loggingWinstonLib = inject( + const loggingWinstonLib = proxyquire( '../src/index', - {'../src/common': {LoggingCommon: FakeLogging}, winston: fakeWinston}); + {'./common': {LoggingCommon: FakeLogging}, 'winston': fakeWinston}); // loggingWinston is LoggingWinston namespace which cannot be determined type. // tslint:disable-next-line:no-any let loggingWinston: any; @@ -75,9 +75,6 @@ describe('logging-winston', () => { }); describe('instantiation/options', () => { - const loggingWinstonLib = - inject('../src/index', {'../src/common': {LoggingCommon: FakeLogging}}); - it('should inherit from winston-transport.TransportStream', () => { const loggingWinston = new loggingWinstonLib.LoggingWinston(OPTIONS); assert.ok(loggingWinston instanceof TransportStream); @@ -135,10 +132,6 @@ describe('logging-winston', () => { const MESSAGE = 'message'; const METADATA = {a: 1}; - const loggingWinstonLib = inject( - '../src/index', - {'../src/common': {LoggingCommon: FakeLogging}, winston: fakeWinston}); - const loggingWinston = new loggingWinstonLib.LoggingWinston(); beforeEach(() => { diff --git a/test/middleware/express.ts b/test/middleware/express.ts index 7783d982..20daaa9f 100644 --- a/test/middleware/express.ts +++ b/test/middleware/express.ts @@ -19,9 +19,9 @@ import {GCPEnv} from 'google-auth-library'; import {LogEntry} from 'winston'; import * as TransportStream from 'winston-transport'; -const inject = require('require-inject'); +const proxyquire = require('proxyquire'); -// types-only import. Actual require is done through require-inject below. +// types-only import. Actual require is done through proxyquire below. import {MiddlewareOptions} from '../../src/middleware/express'; const FAKE_PROJECT_ID = 'project-🦄'; @@ -71,11 +71,12 @@ function fakeMakeMiddleware( return FAKE_GENERATED_MIDDLEWARE; } -const {middleware, APP_LOG_SUFFIX} = inject('../../src/middleware/express', { - '../../src/index': {LoggingWinston: FakeLoggingWinston}, - '@google-cloud/logging': - {middleware: {express: {makeMiddleware: fakeMakeMiddleware}}} -}); +const {middleware, APP_LOG_SUFFIX} = + proxyquire('../../src/middleware/express', { + '../index': {LoggingWinston: FakeLoggingWinston}, + '@google-cloud/logging': + {middleware: {express: {makeMiddleware: fakeMakeMiddleware}}} + }); describe('middleware/express', () => { beforeEach(() => { diff --git a/test/winston-2/package-lock.json b/test/winston-2/package-lock.json deleted file mode 100644 index 7aba4c8e..00000000 --- a/test/winston-2/package-lock.json +++ /dev/null @@ -1,51 +0,0 @@ -{ - "name": "winston-holder", - "version": "1.0.0", - "lockfileVersion": 1, - "requires": true, - "dependencies": { - "async": { - "version": "1.0.0", - "resolved": "https://registry.npmjs.org/async/-/async-1.0.0.tgz", - "integrity": "sha1-+PwEyjoTeErenhZBr5hXjPvWR6k=" - }, - "colors": { - "version": "1.0.3", - "resolved": "https://registry.npmjs.org/colors/-/colors-1.0.3.tgz", - "integrity": "sha1-BDP0TYCWgP3rYO0mDxsMJi6CpAs=" - }, - "cycle": { - "version": "1.0.3", - "resolved": "https://registry.npmjs.org/cycle/-/cycle-1.0.3.tgz", - "integrity": "sha1-IegLK+hYD5i0aPN5QwZisEbDStI=" - }, - "eyes": { - "version": "0.1.8", - "resolved": "https://registry.npmjs.org/eyes/-/eyes-0.1.8.tgz", - "integrity": "sha1-Ys8SAjTGg3hdkCNIqADvPgzCC8A=" - }, - "isstream": { - "version": "0.1.2", - "resolved": "https://registry.npmjs.org/isstream/-/isstream-0.1.2.tgz", - "integrity": "sha1-R+Y/evVa+m+S4VAOaQ64uFKcCZo=" - }, - "stack-trace": { - "version": "0.0.10", - "resolved": "https://registry.npmjs.org/stack-trace/-/stack-trace-0.0.10.tgz", - "integrity": "sha1-VHxws0fo0ytOEI6hoqFZ5f3eGcA=" - }, - "winston": { - "version": "2.4.4", - "resolved": "https://registry.npmjs.org/winston/-/winston-2.4.4.tgz", - "integrity": "sha512-NBo2Pepn4hK4V01UfcWcDlmiVTs7VTB1h7bgnB0rgP146bYhMxX0ypCz3lBOfNxCO4Zuek7yeT+y/zM1OfMw4Q==", - "requires": { - "async": "~1.0.0", - "colors": "1.0.x", - "cycle": "1.0.x", - "eyes": "0.1.x", - "isstream": "0.1.x", - "stack-trace": "0.0.x" - } - } - } -}