Merge pull request #123 from pelias/add-logging#8

add logging

README.md

@@ -33,6 +33,13 @@ The API ships with several convenience commands (runnable via `npm`):
   * `npm run docs`: generate API documentation
   * `npm run coverage`: generate code coverage reports
 
+## pelias-config
+The API recognizes the following properties under the top-level `api` key in your `pelias.json` config file:
+
+  * `accessLog`: (*optional*) The name of the format to use for access logs; may be any one of the
+  [predefined values](https://github.com/expressjs/morgan#predefined-formats) in the `morgan` package. Defaults to
+  `"common"`; if set to `false`, or an otherwise falsy value, disables access-logging entirely.
+
 ## Contributing
 
 Please fork and pull request against upstream master on a feature branch. Pretty please; provide unit tests and script

app.js

@@ -1,5 +1,10 @@
 
 var app = require('express')();
+var peliasConfig = require( 'pelias-config' ).generate().api;
+
+if( peliasConfig.accessLog ){
+  app.use( require( './middleware/access_log' )( peliasConfig.accessLog ) );
+}
 
 /** ----------------------- middleware ----------------------- **/
 

middleware/500.js

@@ -1,9 +1,8 @@
-var logger = require( '../src/logger' );
+var logger = require( 'pelias-logger' ).get( 'middleware-500' );
 
 // handle application errors
 function middleware(err, req, res, next) {
-  logger.error( 'Error:', err );
-  logger.error( 'Stack trace:', err.trace );
+  logger.error( 'Error: `%s`. Stack trace: `%s`.', err, err.stack );
   res.header('Cache-Control','no-cache');
   if( res.statusCode < 400 ){ res.status(500); }
   res.json({ error: typeof err === 'string' ? err : 'internal server error' });

middleware/access_log.js

@@ -0,0 +1,20 @@
+/**
+ * Create a middleware that prints access logs via pelias-logger.
+ */
+
+'use strict';
+
+var morgan = require( 'morgan' );
+var through = require( 'through2' );
+var peliasLogger = require( 'pelias-logger' ).get( 'api' );
+
+function createAccessLogger( logFormat ){
+  return morgan( logFormat, {
+    stream: through( function write( ln, _, next ){
+      peliasLogger.info( ln.toString().trim() );
+      next();
+    })
+  });
+}
+
+module.exports = createAccessLogger;

package.json

@@ -41,6 +41,11 @@
     "is-object": "^1.0.1",
     "markdown": "0.5.0",
     "pelias-esclient": "0.0.25",
+    "pelias-logger": "^0.0.8",
+    "through2": "0.6.5",
+    "morgan": "1.5.2",
+    "pelias-config": "^0.1.4",
+    "microtime": "1.4.0",
     "pelias-suggester-pipeline": "2.0.2"
   },
   "devDependencies": {

query/search.js

@@ -1,10 +1,8 @@
 
-var logger = require('../src/logger'),
-    queries = require('geopipes-elasticsearch-backend').queries,
+var queries = require('geopipes-elasticsearch-backend').queries,
     sort = require('../query/sort');
 
 function generate( params ){
-
   var centroid = null;
 
   if ( params.lat && params.lon ){

query/suggest.js

@@ -1,6 +1,5 @@
 
-var logger = require('../src/logger'),
-    get_layers = require('../helper/layers');
+var get_layers = require('../helper/layers');
 
 // Build pelias suggest query
 function generate( params, query_mixer, fuzziness ){
@@ -69,9 +68,8 @@ function generate( params, query_mixer, fuzziness ){
   }
   
   
-  // logger.log( 'cmd', JSON.stringify( cmd.cmd, null, 2 ) );
   return cmd.cmd;
 
 }
 
-module.exports = generate;
+module.exports = generate;

sanitiser/coarse.js

@@ -1,6 +1,5 @@
 
-var logger = require('../src/logger'),
-    _sanitize = require('../sanitiser/_sanitize'),
+var _sanitize = require('../sanitiser/_sanitize'),
     sanitizers = {
       input: require('../sanitiser/_input'),
       size: require('../sanitiser/_size'),
@@ -28,4 +27,4 @@ module.exports.middleware = function( req, res, next ){
     req.clean = clean;
     next();
   });
-};
+};

sanitiser/doc.js

@@ -1,6 +1,5 @@
 
-var logger = require('../src/logger'),
-    _sanitize = require('../sanitiser/_sanitize'),
+var _sanitize = require('../sanitiser/_sanitize'),
     sanitizers = {
       id: require('../sanitiser/_id'),
       details: require('../sanitiser/_details')
@@ -21,4 +20,4 @@ module.exports.middleware = function( req, res, next ){
     req.clean = clean;
     next();
   });
-};
+};

sanitiser/search.js

@@ -1,6 +1,5 @@
 
-var logger = require('../src/logger'),
-    _sanitize = require('../sanitiser/_sanitize'),
+var _sanitize = require('../sanitiser/_sanitize'),
     sanitizers = {
       input: require('../sanitiser/_input'),
       size: require('../sanitiser/_size'),

sanitiser/suggest.js

@@ -1,6 +1,5 @@
 
-var logger = require('../src/logger'),
-    _sanitize = require('../sanitiser/_sanitize'),
+var _sanitize = require('../sanitiser/_sanitize'),
     sanitizers = {
       input: require('../sanitiser/_input'),
       size: require('../sanitiser/_size'),
@@ -27,4 +26,4 @@ module.exports.middleware = function( req, res, next ){
     req.clean = clean;
     next();
   });
-};
+};

service/mget.js

@@ -11,6 +11,9 @@
 
 **/
 
+var peliasLogger = require( 'pelias-logger' ).get( 'service/mget' );
+var microtime = require( 'microtime' );
+
 function service( backend, query, cb ){
 
   // backend command
@@ -20,8 +23,10 @@ function service( backend, query, cb ){
     }
   };
   
+  var startTime = microtime.nowDouble();
   // query new backend
   backend().client.mget( cmd, function( err, data ){
+    peliasLogger.verbose( 'time elasticsearch query took:', microtime.nowDouble() - startTime );
 
     // handle backend errors
     if( err ){ return cb( err ); }
@@ -52,4 +57,4 @@ function service( backend, query, cb ){
 
 }
 
-module.exports = service;
+module.exports = service;

service/search.js

@@ -5,10 +5,15 @@
 
 **/
 
+var peliasLogger = require( 'pelias-logger' ).get( 'service/search' );
+var microtime = require( 'microtime' );
+
 function service( backend, cmd, cb ){
   
+  var startTime = microtime.nowDouble();
   // query new backend
   backend().client.search( cmd, function( err, data ){
+    peliasLogger.verbose( 'time elasticsearch query took:', microtime.nowDouble() - startTime );
 
     // handle backend errors
     if( err ){ return cb( err ); }
@@ -33,4 +38,4 @@ function service( backend, cmd, cb ){
 
 }
 
-module.exports = service;
+module.exports = service;

service/suggest.js

@@ -4,10 +4,15 @@
   cmd can be any valid ES suggest command
 
 **/
+var peliasLogger = require( 'pelias-logger' ).get( 'service/suggest' );
+
+var microtime = require( 'microtime' );
 
 function service( backend, cmd, cb ){
   // query new backend
+  var startTime = microtime.nowDouble();
   backend().client.suggest( cmd, function( err, data ){
+    peliasLogger.verbose( 'time elasticsearch query took:', microtime.nowDouble() - startTime );
     // handle backend errors
     if( err ){ return cb( err ); }
     
@@ -40,4 +45,4 @@ function service( backend, cmd, cb ){
 
 }
 
-module.exports = service;
+module.exports = service;

src/logger.js

@@ -1,5 +0,0 @@
-module.exports = {
-  log: console.log.bind( console ),
-  warn: console.warn.bind( console ),
-  error: console.error.bind( console )
-};