diff --git a/app.js b/app.js index 10261bfb1..bf0719ab0 100755 --- a/app.js +++ b/app.js @@ -99,6 +99,8 @@ process.on('SIGHUP', function() { global.logger = global.log4js.getLogger(); console.log('Log files reloaded'); }); + + server.batch.logger.reopenFileStreams(); }); process.on('SIGTERM', function () { diff --git a/app/server.js b/app/server.js index 1513f7ed6..1deeba761 100644 --- a/app/server.js +++ b/app/server.js @@ -209,7 +209,7 @@ function App() { var isBatchProcess = process.argv.indexOf('--no-batch') === -1; if (global.settings.environment !== 'test' && isBatchProcess) { - app.batch = batchFactory(metadataBackend, redisConfig, statsd_client); + app.batch = batchFactory(metadataBackend, redisConfig, statsd_client, global.settings.batch_log_filename); app.batch.start(); } diff --git a/batch/batch-logger.js b/batch/batch-logger.js new file mode 100644 index 000000000..02f4f9517 --- /dev/null +++ b/batch/batch-logger.js @@ -0,0 +1,25 @@ +'use strict'; + +var bunyan = require('bunyan'); +var fs = require('fs'); + +function BatchLogger (path) { + this.path = path; + this.logger = bunyan.createLogger({ + name: 'batch-queries', + streams: [{ + level: 'info', + stream: path ? fs.createWriteStream(path, { flags: 'a', encoding: 'utf8' }) : process.stdout + }] + }); +} + +module.exports = BatchLogger; + +BatchLogger.prototype.log = function (job) { + return job.log(this.logger); +}; + +BatchLogger.prototype.reopenFileStreams = function () { + this.logger.reopenFileStreams(); +}; diff --git a/batch/batch.js b/batch/batch.js index 3edcec0fb..76ea6b39b 100644 --- a/batch/batch.js +++ b/batch/batch.js @@ -7,12 +7,13 @@ var forever = require('./util/forever'); var queue = require('queue-async'); var jobStatus = require('./job_status'); -function Batch(jobSubscriber, jobQueuePool, jobRunner, jobService) { +function Batch(jobSubscriber, jobQueuePool, jobRunner, jobService, logger) { EventEmitter.call(this); this.jobSubscriber = jobSubscriber; this.jobQueuePool = jobQueuePool; this.jobRunner = jobRunner; this.jobService = jobService; + this.logger = logger; } util.inherits(Batch, EventEmitter); @@ -90,6 +91,8 @@ Batch.prototype._consumeJobs = function (host, queue, callback) { debug('Job %s %s in %s', job_id, job.data.status, host); } + self.logger.log(job); + self.emit('job:' + job.data.status, job_id); callback(); diff --git a/batch/index.js b/batch/index.js index afe9ea00a..53a0e4792 100644 --- a/batch/index.js +++ b/batch/index.js @@ -1,6 +1,5 @@ 'use strict'; - var RedisPool = require('redis-mpool'); var _ = require('underscore'); var JobRunner = require('./job_runner'); @@ -14,9 +13,10 @@ var JobPublisher = require('./job_publisher'); var JobQueue = require('./job_queue'); var JobBackend = require('./job_backend'); var JobService = require('./job_service'); +var BatchLogger = require('./batch-logger'); var Batch = require('./batch'); -module.exports = function batchFactory (metadataBackend, redisConfig, statsdClient) { +module.exports = function batchFactory (metadataBackend, redisConfig, statsdClient, loggerPath) { var redisPoolSubscriber = new RedisPool(_.extend(redisConfig, { name: 'batch-subscriber'})); var redisPoolPublisher = new RedisPool(_.extend(redisConfig, { name: 'batch-publisher'})); var queueSeeker = new QueueSeeker(metadataBackend); @@ -30,6 +30,7 @@ module.exports = function batchFactory (metadataBackend, redisConfig, statsdClie var jobCanceller = new JobCanceller(userDatabaseMetadataService); var jobService = new JobService(jobBackend, jobCanceller); var jobRunner = new JobRunner(jobService, jobQueue, queryRunner, statsdClient); + var logger = new BatchLogger(loggerPath); - return new Batch(jobSubscriber, jobQueuePool, jobRunner, jobService); + return new Batch(jobSubscriber, jobQueuePool, jobRunner, jobService, logger); }; diff --git a/batch/models/job_base.js b/batch/models/job_base.js index ab6da063c..b2143ac08 100644 --- a/batch/models/job_base.js +++ b/batch/models/job_base.js @@ -111,3 +111,7 @@ JobBase.prototype.serialize = function () { return data; }; + +JobBase.prototype.log = function(/*logger*/) { + return false; +}; diff --git a/batch/models/job_fallback.js b/batch/models/job_fallback.js index 6117cb727..83d579058 100644 --- a/batch/models/job_fallback.js +++ b/batch/models/job_fallback.js @@ -7,6 +7,9 @@ var QueryFallback = require('./query/query_fallback'); var MainFallback = require('./query/main_fallback'); var QueryFactory = require('./query/query_factory'); +var JobUtils = require('./job_state_machine'); +var jobUtils = new JobUtils(); + function JobFallback(jobDefinition) { JobBase.call(this, jobDefinition); @@ -206,3 +209,68 @@ JobFallback.prototype.getLastFinishedStatus = function () { return this.isFinalStatus(status) ? status : lastFinished; }.bind(this), jobStatus.DONE); }; + +JobFallback.prototype.log = function(logger) { + if (!isFinished(this)) { + return false; + } + + var queries = this.data.query.query; + + for (var i = 0; i < queries.length; i++) { + var query = queries[i]; + + var output = { + time: query.started_at, + endtime: query.ended_at, + username: this.data.user, + job: this.data.job_id, + elapsed: elapsedTime(query.started_at, query.ended_at) + }; + + var queryId = query.id; + + if (queryId) { + output.query_id = queryId; + + var node = parseQueryId(queryId); + if (node) { + output.analysis = node.analysisId; + output.node = node.nodeId; + output.type = node.nodeType; + } + } + + logger.info(output); + } + + return true; +}; + +function isFinished (job) { + return jobUtils.isFinalStatus(job.data.status) && + (!job.data.fallback_status || jobUtils.isFinalStatus(job.data.fallback_status)); +} + +function parseQueryId (queryId) { + var data = queryId.split(':'); + + if (data.length === 3) { + return { + analysisId: data[0], + nodeId: data[1], + nodeType: data[2] + }; + } + return null; +} + +function elapsedTime (started_at, ended_at) { + if (!started_at || !ended_at) { + return; + } + + var start = new Date(started_at); + var end = new Date(ended_at); + return end.getTime() - start.getTime(); +} diff --git a/config/environments/development.js.example b/config/environments/development.js.example index 6eae01456..3303c71e3 100644 --- a/config/environments/development.js.example +++ b/config/environments/development.js.example @@ -30,6 +30,7 @@ module.exports.db_host = 'localhost'; module.exports.db_port = '5432'; module.exports.db_batch_port = '5432'; module.exports.finished_jobs_ttl_in_seconds = 2 * 3600; // 2 hours +module.exports.batch_log_filename = 'logs/batch-queries.log'; // Max database connections in the pool // Subsequent connections will wait for a free slot. // NOTE: not used by OGR-mediated accesses diff --git a/config/environments/production.js.example b/config/environments/production.js.example index 96683a513..6e5ba0806 100644 --- a/config/environments/production.js.example +++ b/config/environments/production.js.example @@ -31,6 +31,7 @@ module.exports.db_host = 'localhost'; module.exports.db_port = '6432'; module.exports.db_batch_port = '5432'; module.exports.finished_jobs_ttl_in_seconds = 2 * 3600; // 2 hours +module.exports.batch_log_filename = 'logs/batch-queries.log'; // Max database connections in the pool // Subsequent connections will wait for a free slot.i // NOTE: not used by OGR-mediated accesses diff --git a/config/environments/staging.js.example b/config/environments/staging.js.example index 123e56fde..ce31b032b 100644 --- a/config/environments/staging.js.example +++ b/config/environments/staging.js.example @@ -31,6 +31,7 @@ module.exports.db_host = 'localhost'; module.exports.db_port = '6432'; module.exports.db_batch_port = '5432'; module.exports.finished_jobs_ttl_in_seconds = 2 * 3600; // 2 hours +module.exports.batch_log_filename = 'logs/batch-queries.log'; // Max database connections in the pool // Subsequent connections will wait for a free slot. // NOTE: not used by OGR-mediated accesses diff --git a/config/environments/test.js.example b/config/environments/test.js.example index d0ef22362..01df1ebc5 100644 --- a/config/environments/test.js.example +++ b/config/environments/test.js.example @@ -28,6 +28,7 @@ module.exports.db_host = 'localhost'; module.exports.db_port = '5432'; module.exports.db_batch_port = '5432'; module.exports.finished_jobs_ttl_in_seconds = 2 * 3600; // 2 hours +module.exports.batch_log_filename = 'logs/batch-queries.log'; // Max database connections in the pool // Subsequent connections will wait for a free slot. // NOTE: not used by OGR-mediated accesses diff --git a/npm-shrinkwrap.json b/npm-shrinkwrap.json index 6b0dbadcf..a501d2349 100644 --- a/npm-shrinkwrap.json +++ b/npm-shrinkwrap.json @@ -2,6 +2,131 @@ "name": "cartodb_sql_api", "version": "1.35.1", "dependencies": { + "bunyan": { + "version": "1.8.1", + "from": "bunyan@1.8.1", + "resolved": "https://registry.npmjs.org/bunyan/-/bunyan-1.8.1.tgz", + "dependencies": { + "dtrace-provider": { + "version": "0.6.0", + "from": "dtrace-provider@>=0.6.0 <0.7.0", + "resolved": "https://registry.npmjs.org/dtrace-provider/-/dtrace-provider-0.6.0.tgz", + "dependencies": { + "nan": { + "version": "2.4.0", + "from": "nan@>=2.0.8 <3.0.0", + "resolved": "https://registry.npmjs.org/nan/-/nan-2.4.0.tgz" + } + } + }, + "mv": { + "version": "2.1.1", + "from": "mv@>=2.0.0 <3.0.0", + "resolved": "https://registry.npmjs.org/mv/-/mv-2.1.1.tgz", + "dependencies": { + "mkdirp": { + "version": "0.5.1", + "from": "mkdirp@>=0.5.1 <0.6.0", + "resolved": "https://registry.npmjs.org/mkdirp/-/mkdirp-0.5.1.tgz", + "dependencies": { + "minimist": { + "version": "0.0.8", + "from": "minimist@0.0.8", + "resolved": "https://registry.npmjs.org/minimist/-/minimist-0.0.8.tgz" + } + } + }, + "ncp": { + "version": "2.0.0", + "from": "ncp@>=2.0.0 <2.1.0", + "resolved": "https://registry.npmjs.org/ncp/-/ncp-2.0.0.tgz" + }, + "rimraf": { + "version": "2.4.5", + "from": "rimraf@>=2.4.0 <2.5.0", + "resolved": "https://registry.npmjs.org/rimraf/-/rimraf-2.4.5.tgz", + "dependencies": { + "glob": { + "version": "6.0.4", + "from": "glob@>=6.0.1 <7.0.0", + "resolved": "https://registry.npmjs.org/glob/-/glob-6.0.4.tgz", + "dependencies": { + "inflight": { + "version": "1.0.5", + "from": "inflight@>=1.0.4 <2.0.0", + "resolved": "https://registry.npmjs.org/inflight/-/inflight-1.0.5.tgz", + "dependencies": { + "wrappy": { + "version": "1.0.2", + "from": "wrappy@>=1.0.0 <2.0.0", + "resolved": "https://registry.npmjs.org/wrappy/-/wrappy-1.0.2.tgz" + } + } + }, + "inherits": { + "version": "2.0.3", + "from": "inherits@>=2.0.0 <3.0.0", + "resolved": "https://registry.npmjs.org/inherits/-/inherits-2.0.3.tgz" + }, + "minimatch": { + "version": "3.0.3", + "from": "minimatch@>=2.0.0 <3.0.0||>=3.0.0 <4.0.0", + "resolved": "https://registry.npmjs.org/minimatch/-/minimatch-3.0.3.tgz", + "dependencies": { + "brace-expansion": { + "version": "1.1.6", + "from": "brace-expansion@>=1.0.0 <2.0.0", + "resolved": "https://registry.npmjs.org/brace-expansion/-/brace-expansion-1.1.6.tgz", + "dependencies": { + "balanced-match": { + "version": "0.4.2", + "from": "balanced-match@>=0.4.1 <0.5.0", + "resolved": "https://registry.npmjs.org/balanced-match/-/balanced-match-0.4.2.tgz" + }, + "concat-map": { + "version": "0.0.1", + "from": "concat-map@0.0.1", + "resolved": "https://registry.npmjs.org/concat-map/-/concat-map-0.0.1.tgz" + } + } + } + } + }, + "once": { + "version": "1.4.0", + "from": "once@>=1.3.0 <2.0.0", + "resolved": "https://registry.npmjs.org/once/-/once-1.4.0.tgz", + "dependencies": { + "wrappy": { + "version": "1.0.2", + "from": "wrappy@>=1.0.0 <2.0.0", + "resolved": "https://registry.npmjs.org/wrappy/-/wrappy-1.0.2.tgz" + } + } + }, + "path-is-absolute": { + "version": "1.0.0", + "from": "path-is-absolute@>=1.0.0 <2.0.0", + "resolved": "https://registry.npmjs.org/path-is-absolute/-/path-is-absolute-1.0.0.tgz" + } + } + } + } + } + } + }, + "safe-json-stringify": { + "version": "1.0.3", + "from": "safe-json-stringify@>=1.0.0 <2.0.0", + "resolved": "https://registry.npmjs.org/safe-json-stringify/-/safe-json-stringify-1.0.3.tgz" + }, + "moment": { + "version": "2.15.1", + "from": "moment@>=2.10.6 <3.0.0", + "resolved": "https://registry.npmjs.org/moment/-/moment-2.15.1.tgz" + } + } + }, "cartodb-psql": { "version": "0.6.1", "from": "cartodb-psql@>=0.6.0 <0.7.0", @@ -240,7 +365,7 @@ }, "yargs": { "version": "5.0.0", - "from": "yargs@>=5.0.0 <6.0.0", + "from": "yargs@>=5.0.0 <5.1.0", "resolved": "https://registry.npmjs.org/yargs/-/yargs-5.0.0.tgz", "dependencies": { "cliui": { @@ -341,9 +466,9 @@ "resolved": "https://registry.npmjs.org/load-json-file/-/load-json-file-1.1.0.tgz", "dependencies": { "graceful-fs": { - "version": "4.1.6", + "version": "4.1.9", "from": "graceful-fs@>=4.1.2 <5.0.0", - "resolved": "https://registry.npmjs.org/graceful-fs/-/graceful-fs-4.1.6.tgz" + "resolved": "https://registry.npmjs.org/graceful-fs/-/graceful-fs-4.1.9.tgz" }, "parse-json": { "version": "2.2.0", @@ -454,9 +579,9 @@ "resolved": "https://registry.npmjs.org/path-type/-/path-type-1.1.0.tgz", "dependencies": { "graceful-fs": { - "version": "4.1.6", + "version": "4.1.9", "from": "graceful-fs@>=4.1.2 <5.0.0", - "resolved": "https://registry.npmjs.org/graceful-fs/-/graceful-fs-4.1.6.tgz" + "resolved": "https://registry.npmjs.org/graceful-fs/-/graceful-fs-4.1.9.tgz" }, "pify": { "version": "2.3.0", diff --git a/package.json b/package.json index 7650cbe0a..6c9747133 100644 --- a/package.json +++ b/package.json @@ -17,6 +17,7 @@ "Sandro Santilli " ], "dependencies": { + "bunyan": "1.8.1", "cartodb-psql": "~0.6.0", "cartodb-query-tables": "0.2.0", "cartodb-redis": "0.13.1",