From 877e1e90a5bc4785e23a4ab23d1ac7410695c145 Mon Sep 17 00:00:00 2001
From: Severyn Kozak <severyn.kozak@gmail.com>
Date: Mon, 4 May 2015 16:45:52 -0400
Subject: [PATCH 1/7] Add an access log middleware.

middleware/access_log.js, package.json
	-Add middleware for printing out access logs.
	-Add necessary dependencies.
---
 app.js                   |  2 ++
 middleware/access_log.js | 14 ++++++++++++++
 package.json             |  2 ++
 3 files changed, 18 insertions(+)
 create mode 100644 middleware/access_log.js

diff --git a/app.js b/app.js
index b0f65801..29897d73 100644
--- a/app.js
+++ b/app.js
@@ -1,6 +1,8 @@
 
 var app = require('express')();
 
+app.use( require( './middleware/access_log' ) );
+
 /** ----------------------- middleware ----------------------- **/
 
 app.use( require('./middleware/headers') );
diff --git a/middleware/access_log.js b/middleware/access_log.js
new file mode 100644
index 00000000..ff79eb00
--- /dev/null
+++ b/middleware/access_log.js
@@ -0,0 +1,14 @@
+/**
+ * Print out access logs.
+ */
+
+'use strict';
+
+var peliasConfig = require( 'pelias-config' ).generate().api;
+var morgan = require( 'morgan' );
+
+module.exports = peliasConfig.accessLog ?
+  morgan( peliasConfig.accessLog ) :
+  function noop(req, res, next){
+    next();
+  };
diff --git a/package.json b/package.json
index ae77f1ae..f64ca731 100644
--- a/package.json
+++ b/package.json
@@ -41,6 +41,8 @@
     "is-object": "^1.0.1",
     "markdown": "0.5.0",
     "pelias-esclient": "0.0.25",
+    "morgan": "1.5.2",
+    "pelias-config": "^0.1.4",
     "pelias-suggester-pipeline": "2.0.2"
   },
   "devDependencies": {

From a007af3572731cd50c41425f812bd9702c69d9f7 Mon Sep 17 00:00:00 2001
From: Severyn Kozak <severyn.kozak@gmail.com>
Date: Tue, 5 May 2015 09:51:03 -0400
Subject: [PATCH 2/7] Replace src/logger with pelias-logger.

(query, query)/*.js
	-Remove unused `../src/logger` `require()`s.

src/logger.js, package.json
	-Remove `src/logger` in favor of using `pelias-logger` for all
	logging, since it's the Pelias standard.

middleware/500.js
	-Replace usage of `src/logger` with pelias-logger.
---
 middleware/500.js    | 4 ++--
 package.json         | 1 +
 query/search.js      | 6 ++----
 query/suggest.js     | 6 ++----
 sanitiser/coarse.js  | 5 ++---
 sanitiser/doc.js     | 5 ++---
 sanitiser/search.js  | 3 +--
 sanitiser/suggest.js | 5 ++---
 src/logger.js        | 5 -----
 9 files changed, 14 insertions(+), 26 deletions(-)
 delete mode 100644 src/logger.js

diff --git a/middleware/500.js b/middleware/500.js
index 47895552..0b957bb9 100644
--- a/middleware/500.js
+++ b/middleware/500.js
@@ -1,8 +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( err );
   logger.error( 'Stack trace:', err.trace );
   res.header('Cache-Control','no-cache');
   if( res.statusCode < 400 ){ res.status(500); }
diff --git a/package.json b/package.json
index f64ca731..67a809a1 100644
--- a/package.json
+++ b/package.json
@@ -41,6 +41,7 @@
     "is-object": "^1.0.1",
     "markdown": "0.5.0",
     "pelias-esclient": "0.0.25",
+    "pelias-logger": "^0.0.8",
     "morgan": "1.5.2",
     "pelias-config": "^0.1.4",
     "pelias-suggester-pipeline": "2.0.2"
diff --git a/query/search.js b/query/search.js
index 65551cde..2c9a697e 100644
--- a/query/search.js
+++ b/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 ){
@@ -50,4 +48,4 @@ function generate( params ){
   return query;
 }
 
-module.exports = generate;
\ No newline at end of file
+module.exports = generate;
diff --git a/query/suggest.js b/query/suggest.js
index 249f7c38..16cd7b28 100644
--- a/query/suggest.js
+++ b/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;
\ No newline at end of file
+module.exports = generate;
diff --git a/sanitiser/coarse.js b/sanitiser/coarse.js
index 2d75f68f..8bd6a940 100644
--- a/sanitiser/coarse.js
+++ b/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();
   });
-};
\ No newline at end of file
+};
diff --git a/sanitiser/doc.js b/sanitiser/doc.js
index cb3276ca..07f07aa1 100644
--- a/sanitiser/doc.js
+++ b/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();
   });
-};
\ No newline at end of file
+};
diff --git a/sanitiser/search.js b/sanitiser/search.js
index df6af152..d226dbd9 100644
--- a/sanitiser/search.js
+++ b/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'),
diff --git a/sanitiser/suggest.js b/sanitiser/suggest.js
index db363ebf..3741f3c4 100644
--- a/sanitiser/suggest.js
+++ b/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();
   });
-};
\ No newline at end of file
+};
diff --git a/src/logger.js b/src/logger.js
deleted file mode 100644
index 205313c0..00000000
--- a/src/logger.js
+++ /dev/null
@@ -1,5 +0,0 @@
-module.exports = {
-  log: console.log.bind( console ),
-  warn: console.warn.bind( console ),
-  error: console.error.bind( console )
-};
\ No newline at end of file

From 157734b8d6f1c481d887cd30ef6162f20acf0a47 Mon Sep 17 00:00:00 2001
From: Severyn Kozak <severyn.kozak@gmail.com>
Date: Tue, 5 May 2015 09:55:17 -0400
Subject: [PATCH 3/7] Emit access-logs via pelias-logger.

(app, middleware/access_log).js
	-Move the logic that determines whether access logging is
	necessary to app.js, since that allows us to maintain the style
	of `app.use(require(/* desired middleware module */))` inside
	`app.js` without returning a "noop" middleware from
	`middleware/access_log.js` in the case that it's unnecessary.
---
 app.js                   |  5 ++++-
 middleware/access_log.js | 20 +++++++++++++-------
 package.json             |  1 +
 3 files changed, 18 insertions(+), 8 deletions(-)

diff --git a/app.js b/app.js
index 29897d73..e0a8591f 100644
--- a/app.js
+++ b/app.js
@@ -1,7 +1,10 @@
 
 var app = require('express')();
+var peliasConfig = require( 'pelias-config' ).generate().api;
 
-app.use( require( './middleware/access_log' ) );
+if( peliasConfig.accessLog ){
+  app.use( require( './middleware/access_log' )( peliasConfig.accessLog ) );
+}
 
 /** ----------------------- middleware ----------------------- **/
 
diff --git a/middleware/access_log.js b/middleware/access_log.js
index ff79eb00..812a8849 100644
--- a/middleware/access_log.js
+++ b/middleware/access_log.js
@@ -1,14 +1,20 @@
 /**
- * Print out access logs.
+ * Create a middleware that prints access logs via pelias-logger.
  */
 
 'use strict';
 
-var peliasConfig = require( 'pelias-config' ).generate().api;
 var morgan = require( 'morgan' );
+var through = require( 'through2' );
+var peliasLogger = require( 'pelias-logger' ).get( 'api' );
 
-module.exports = peliasConfig.accessLog ?
-  morgan( peliasConfig.accessLog ) :
-  function noop(req, res, next){
-    next();
-  };
+function createAccessLogger( logFormat ){
+  return morgan( logFormat, {
+    stream: through( function write( ln, _, next ){
+      peliasLogger.info( ln.toString().trim() );
+      next();
+    })
+  });
+}
+
+module.exports = createAccessLogger;
diff --git a/package.json b/package.json
index 67a809a1..ece2b7e2 100644
--- a/package.json
+++ b/package.json
@@ -42,6 +42,7 @@
     "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",
     "pelias-suggester-pipeline": "2.0.2"

From 0b8220cbf396063f5554e742c59c22212e2c18c7 Mon Sep 17 00:00:00 2001
From: Severyn Kozak <severyn.kozak@gmail.com>
Date: Tue, 5 May 2015 14:40:53 -0400
Subject: [PATCH 4/7] Log only once per error.

middleware/500.js
	-Make one log call per error rather than two, to reduce
	clutter/noise.
---
 middleware/500.js | 3 +--
 1 file changed, 1 insertion(+), 2 deletions(-)

diff --git a/middleware/500.js b/middleware/500.js
index 0b957bb9..ecd2ee1d 100644
--- a/middleware/500.js
+++ b/middleware/500.js
@@ -2,8 +2,7 @@ var logger = require( 'pelias-logger' ).get( 'middleware-500' );
 
 // handle application errors
 function middleware(err, req, res, next) {
-  logger.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' });

From 51ed1507df67f64c4092e4d66e635017f93213eb Mon Sep 17 00:00:00 2001
From: Severyn Kozak <severyn.kozak@gmail.com>
Date: Tue, 5 May 2015 14:46:17 -0400
Subject: [PATCH 5/7] Log the time spent in each elasticsearch query.

---
 service/mget.js    | 7 ++++++-
 service/search.js  | 7 ++++++-
 service/suggest.js | 7 ++++++-
 3 files changed, 18 insertions(+), 3 deletions(-)

diff --git a/service/mget.js b/service/mget.js
index cfc79ca3..936ec8bd 100644
--- a/service/mget.js
+++ b/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;
\ No newline at end of file
+module.exports = service;
diff --git a/service/search.js b/service/search.js
index efe10cea..d0882170 100644
--- a/service/search.js
+++ b/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;
\ No newline at end of file
+module.exports = service;
diff --git a/service/suggest.js b/service/suggest.js
index f27b67c9..c5bf2c1f 100644
--- a/service/suggest.js
+++ b/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;
\ No newline at end of file
+module.exports = service;

From bd2c65a7985c85df35d0da9849737713d22e8c65 Mon Sep 17 00:00:00 2001
From: Severyn Kozak <severyn.kozak@gmail.com>
Date: Tue, 5 May 2015 14:56:42 -0400
Subject: [PATCH 6/7] Document the pelias-config accessLog option.

README.md
	-Add a section documenting all of the pelias-config options
	recognized by the API.
	-Document the `accessLog` option.
---
 README.md | 7 +++++++
 1 file changed, 7 insertions(+)

diff --git a/README.md b/README.md
index 42de6622..ac172d59 100644
--- a/README.md
+++ b/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

From 35467d0c60d8f782d1b17349094bcd937d5a4ae4 Mon Sep 17 00:00:00 2001
From: Severyn Kozak <severyn.kozak@gmail.com>
Date: Tue, 5 May 2015 15:08:07 -0400
Subject: [PATCH 7/7] package.json: add microtime dependency.

Was mistakenly left out earlier and broke a Travis build.
---
 package.json | 1 +
 1 file changed, 1 insertion(+)

diff --git a/package.json b/package.json
index ece2b7e2..abc8a854 100644
--- a/package.json
+++ b/package.json
@@ -45,6 +45,7 @@
     "through2": "0.6.5",
     "morgan": "1.5.2",
     "pelias-config": "^0.1.4",
+    "microtime": "1.4.0",
     "pelias-suggester-pipeline": "2.0.2"
   },
   "devDependencies": {