diff --git a/app/controllers/app.js b/app/controllers/app.js index d5efb5b6..158b2827 100755 --- a/app/controllers/app.js +++ b/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 ) { - app.use(global.log4js.connectLogger(global.log4js.getLogger(), _.defaults(loggerOpts, {level:'info'}))); + 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 diff --git a/test/acceptance/logging.js b/test/acceptance/logging.js new file mode 100644 index 00000000..25e7d099 --- /dev/null +++ b/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(); + } + ); + }); +});