Adds a custom log4js format function to log sql query from POST requests

Tokens in log4js are not provided with request/response for context,
using a custom format function allow to access them

In the case of express logger token functions receive request/response
for context so it uses a custom token

Closes #206

app/controllers/app.js

@@ -74,16 +74,45 @@ var tableCache = LRU({
   maxAge: global.settings.tableCacheMaxAge || 1000*60*10
 });
 
-var loggerOpts = {
-    buffer: true,
-    format: global.settings.log_format ||
-            ':remote-addr :method :req[Host]:url :status :response-time ms -> :res[Content-Type]'
+// Size based on https://github.com/CartoDB/cartodb.js/blob/3.15.2/src/geo/layer_definition.js#L72
+var SQL_QUERY_BODY_LOG_MAX_LENGTH = 2000;
+app.getSqlQueryFromRequestBody = function(req) {
+    var sqlQuery = req.body && req.body.q;
+    if (!sqlQuery) {
+        return '';
+    }
+
+    if (sqlQuery.length > SQL_QUERY_BODY_LOG_MAX_LENGTH) {
+        sqlQuery = sqlQuery.substring(0, SQL_QUERY_BODY_LOG_MAX_LENGTH) + ' [...]';
+    }
+    return JSON.stringify({q: sqlQuery});
 };
 
 if ( global.log4js ) {
+    var loggerOpts = {
+        buffer: true,
+        // log4js provides a tokens solution as expess but in does not provide the request/response in the callback.
+        // Thus it is not possible to extract relevant information from them.
+        // This is a workaround to be able to access request/response.
+        format: function(req, res, format) {
+            var logFormat = global.settings.log_format ||
+                ':remote-addr :method :req[Host]:url :status :response-time ms -> :res[Content-Type]';
+
+            logFormat = logFormat.replace(/:sql/, app.getSqlQueryFromRequestBody(req));
+            return format(logFormat);
+        }
+    };
     app.use(global.log4js.connectLogger(global.log4js.getLogger(), _.defaults(loggerOpts, {level:'info'})));
 } else {
-  app.use(express.logger(loggerOpts));
+    // Express logger uses tokens as described here: http://www.senchalabs.org/connect/logger.html
+    express.logger.token('sql', function(req) {
+        return app.getSqlQueryFromRequestBody(req);
+    });
+    app.use(express.logger({
+        buffer: true,
+        format: global.settings.log_format ||
+            ':remote-addr :method :req[Host]:url :status :response-time ms -> :res[Content-Type]'
+    }));
 }
 
 // Initialize statsD client if requested

test/acceptance/logging.js

@@ -0,0 +1,141 @@
+require('../helper');
+
+var app = require(global.settings.app_root + '/app/controllers/app');
+var assert = require('../support/assert');
+var qs = require('querystring');
+var log4js = require('log4js');
+
+describe('Logging SQL query on POST requests', function() {
+
+    var SQL_QUERY = "SELECT 'wadus'";
+    var API_KEY = 1234;
+    var BODY_PAYLOAD = {
+        q: SQL_QUERY,
+        api_key: API_KEY
+    };
+
+    var RESPONSE_OK = {
+        statusCode: 200
+    };
+
+    var server;
+    before(function() {
+        global.settings.log_format = ':method :req[Host]:url :status :sql';
+        global.log4js = log4js;
+        global.log4js.configure({
+            appenders: [
+                {
+                    type: "console",
+                    layout: {
+                        type:'basic'
+                    }
+                }
+            ]
+        });
+        server = app();
+    });
+
+    after(function() {
+        global.log4js = null;
+        delete global.log4js;
+    });
+
+    function createPostRequest(body, contentType, getParams) {
+        var url = '/api/v1/sql';
+        if (getParams) {
+            url += '?' + qs.stringify(getParams);
+        }
+        return {
+            method: 'POST',
+            url: url,
+            data: body,
+            headers: {
+                host: 'vizzuality.cartodb.com',
+                'Content-Type': contentType
+            }
+        };
+    }
+
+    var postScenariosRequests = [
+        {
+            desc: 'should return json string for application/x-www-form-urlencoded',
+            request: createPostRequest(
+                qs.stringify(BODY_PAYLOAD), 'application/x-www-form-urlencoded'
+            )
+        },
+        {
+            desc: 'should return json string for application/x-www-form-urlencoded, with API key in GET param',
+            request: createPostRequest(
+                qs.stringify({q: SQL_QUERY}), 'application/x-www-form-urlencoded', {api_key: API_KEY}
+            )
+        },
+        {
+            desc: 'should return json string for application/json',
+            request: createPostRequest(
+                JSON.stringify(BODY_PAYLOAD), 'application/json'
+            )
+        },
+        {
+            desc: 'should return json string for application/json, with API key in GET param',
+            request: createPostRequest(
+                JSON.stringify({q: SQL_QUERY}), 'application/json', {api_key: API_KEY}
+            )
+        }
+    ];
+
+    postScenariosRequests.forEach(function(scenario) {
+        it(scenario.desc, function(done) {
+            var called = 0;
+
+            var getSqlQueryFromRequestBodyFn = server.getSqlQueryFromRequestBody;
+
+            server.getSqlQueryFromRequestBody = function(req) {
+                called++;
+                var result = getSqlQueryFromRequestBodyFn(req);
+                assert.deepEqual(JSON.parse(result), {q: SQL_QUERY});
+                return result;
+            };
+
+            assert.response(server, scenario.request, RESPONSE_OK, function(res, err) {
+                assert.ok(!err);
+                assert.equal(called, 1);
+
+                server.getSqlQueryFromRequestBody = getSqlQueryFromRequestBodyFn;
+
+                done();
+            });
+        });
+    });
+
+    it('should not log sql query in GET requests', function(done) {
+        var called = 0;
+
+        var getSqlQueryFromRequestBodyFn = server.getSqlQueryFromRequestBody;
+
+        server.getSqlQueryFromRequestBody = function(req) {
+            called++;
+            var result = getSqlQueryFromRequestBodyFn(req);
+            assert.equal(result, '');
+            return result;
+        };
+
+        assert.response(server,
+            {
+                method: 'GET',
+                url: '/api/v1/sql?' + qs.stringify(BODY_PAYLOAD),
+                headers: {
+                    host: 'vizzuality.cartodb.com'
+                }
+            },
+            RESPONSE_OK,
+            function(res, err) {
+                assert.ok(!err);
+                assert.equal(called, 1);
+
+                server.getSqlQueryFromRequestBody = getSqlQueryFromRequestBodyFn;
+
+                done();
+            }
+        );
+    });
+});