diff --git a/lib/cli.js b/lib/cli.js index c56d5ec8d..b99267753 100644 --- a/lib/cli.js +++ b/lib/cli.js @@ -1,10 +1,13 @@ #!/usr/bin/env node +var logger = require('./logger'); +logger.setup(); // default setup + var pkg_file = '../package.yaml'; var fs = require('fs'); var yaml = require('js-yaml'); var commander = require('commander'); -var server = require('../lib/index'); +var server = require('./index'); var crypto = require('crypto'); var pkg = require(pkg_file); @@ -64,12 +67,8 @@ try { } } } catch(err) { - if (err.code === 'ENOENT') { - console.error('ERROR: cannot open configuration file "'+config_path+'", file not found'); - process.exit(1); - } else { - throw err; - } + logger.logger.fatal({file: config_path, err: err}, 'cannot open config file @{file}: @{!err.message}'); + process.exit(1); } if (!have_question) afterConfigLoad(); @@ -94,7 +93,7 @@ function afterConfigLoad() { var hostport = get_hostport(); server(config).listen(hostport[1], hostport[0]); - console.log('Server is listening on http://%s:%s/', hostport[0], hostport[1]); + logger.logger.warn({addr: 'http://'+hostport[0]+':'+hostport[1]+'/'}, 'Server is listening on @{addr}'); // undocumented stuff for tests if (typeof(process.send) === 'function') { diff --git a/lib/config.js b/lib/config.js index 61f069107..00079f12b 100644 --- a/lib/config.js +++ b/lib/config.js @@ -26,10 +26,10 @@ function Config(config) { assert(this.storage, 'CONFIG: storage path not defined'); - var users = {all:true, anonymous:true, owner:true, none:true}; + var users = {all:true, anonymous:true, 'undefined':true, owner:true, none:true}; var check_user_or_uplink = function(arg) { - assert(arg !== 'all' || arg !== 'owner' || arg !== 'anonymous' || arg !== 'none', 'CONFIG: reserved user/uplink name: ' + arg); + assert(arg !== 'all' || arg !== 'owner' || arg !== 'anonymous' || arg !== 'undefined' || arg !== 'none', 'CONFIG: reserved user/uplink name: ' + arg); assert(!arg.match(/\s/), 'CONFIG: invalid user name: ' + arg); assert(users[arg] == null, 'CONFIG: duplicate user/uplink name: ' + arg); users[arg] = true; diff --git a/lib/config_def.yaml b/lib/config_def.yaml index 5211ccbb9..96f47194a 100644 --- a/lib/config_def.yaml +++ b/lib/config_def.yaml @@ -21,7 +21,7 @@ packages: '*': # allow all users to read packages ('all' is a keyword) - # this includes non-authenticated (anonymous) users + # this includes non-authenticated users allow_access: all # allow 'admin' to publish packages @@ -43,3 +43,14 @@ packages: # you can specify listen address (or simply a port) #listen: localhost:4873 +# type: file | stdout | stderr +# level: trace | debug | info | http (default) | warn | error | fatal +# +# parameters for file: name is filename +# {type: 'file', path: 'sinopia.log', level: 'debug'}, +# +# parameters for stdout and stderr: format: json | pretty +# {type: 'stdout', format: 'pretty', level: 'debug'}, +log: + - {type: stdout, format: pretty, level: http} + #- {type: file, path: sinopia.log, level: info} diff --git a/lib/index.js b/lib/index.js index d037cf8eb..deabb9e1b 100644 --- a/lib/index.js +++ b/lib/index.js @@ -4,11 +4,11 @@ var utils = require('./utils'); var Storage = require('./storage'); var Config = require('./config'); var UError = require('./error').UserError; -var basic_auth = require('./middleware').basic_auth; -var validate_name = require('./middleware').validate_name; -var media = require('./middleware').media; -var etagify = require('./middleware').etagify; -var expect_json = require('./middleware').expect_json; +var Middleware = require('./middleware'); +var basic_auth = Middleware.basic_auth; +var validate_name = Middleware.validate_name; +var media = Middleware.media; +var expect_json = Middleware.expect_json; module.exports = function(config_hash) { var config = new Config(config_hash); @@ -19,7 +19,7 @@ module.exports = function(config_hash) { if (config['allow_'+action](req.params.package, req.remoteUser)) { next(); } else { - if (req.remoteUser === 'anonymous') { + if (!req.remoteUser) { next(new UError({ status: 403, msg: "can't "+action+" restricted package without auth, did you forget 'npm set always-auth true'?", @@ -35,8 +35,7 @@ module.exports = function(config_hash) { }; var app = express(); - app.use(express.logger()); - app.use(etagify); + app.use(Middleware.log_and_etagify); app.use(basic_auth(function(user, pass) { return config.authenticate(user, pass); })); diff --git a/lib/logger.js b/lib/logger.js new file mode 100644 index 000000000..621fe174b --- /dev/null +++ b/lib/logger.js @@ -0,0 +1,144 @@ +var Logger = require('bunyan'); +var Stream = require('stream'); + +function getlvl(x) { + if (x < 15) { + return 'trace'; + } else if (x < 25) { + return 'debug'; + } else if (x < 35) { + return 'info'; + } else if (x == 35) { + return 'http'; + } else if (x < 45) { + return 'warn'; + } else if (x < 55) { + return 'error'; + } else { + return 'fatal'; + } +} + +module.exports.setup = function(logs) { + var streams = []; + if (!logs) logs = [{ type: 'stdout', format: 'pretty', level: 'http' }]; + + logs.forEach(function(target) { + var stream = new Stream(); + stream.writable = true; + + if (target.type === 'stdout' || target.type === 'stderr') { + // destination stream + var dest = target.type === 'stdout' ? process.stdout : process.stderr; + + if (target.format === 'pretty') { + // making fake stream for prettypritting + stream.write = function(obj) { + dest.write(print(obj.level, obj.msg, obj) + "\n"); + } + } else { + stream.write = function(obj) { + obj = log_filter(obj); + dest.write(JSON.stringify(obj, Logger.safeCycles()) + "\n"); + } + } + } else if (target.type === 'file') { + var dest = require('fs').createWriteStream(target.path, {flags: 'a', encoding: 'utf8'}); + dest.on('error', function (err) { + Logger.emit('error', err); + }); + stream.write = function(obj) { + obj = log_filter(obj); + dest.write(JSON.stringify(obj, Logger.safeCycles()) + "\n"); + } + } else { + throw new Error('wrong target type for a log'); + } + + if (target.level === 'http') target.level = 35; + streams.push({ + type: "raw", + level: target.level || 35, + stream: stream, + }); + }); + + var logger = new Logger({ + name: 'sinopia', + streams: streams, + serializers: { + err: Logger.stdSerializers.err, + req: Logger.stdSerializers.req, + res: Logger.stdSerializers.res, + }, + }); + + module.exports.logger = logger; +} + +// adopted from socket.io +// this part was converted to coffee-script and back again over the years, +// so it might look weird + +// level to color +var levels = { + fatal: 31, + error: 31, + warn: 33, + http: 35, + info: 36, + debug: 90, + trace: 90, +}; + +var max = 0; +for (var l in levels) { + max = Math.max(max, l.length); +} + +function pad(str) { + if (str.length < max) return str + new Array(max - str.length + 1).join(' '); + return str; +}; + +var subsystems = { + in: '\x1b[32m<--\x1b[39m', + out: '\x1b[33m-->\x1b[39m', + fs: '\x1b[37m-*-\x1b[39m', + default: '\x1b[34m---\x1b[39m', +}; + +function print(type, msg, obj) { + if (typeof type === 'number') type = getlvl(type); + var finalmsg = msg.replace(/@{(!?[$A-Za-z_][$0-9A-Za-z\._]*)}/g, function(_, name) { + var str = obj, is_error; + if (name[0] === '!') { + name = name.substr(1); + is_error = true; + } + + var _ref = name.split('.'); + for (var _i = 0; _i < _ref.length; _i++) { + var id = _ref[_i]; + if (typeof str === 'object') { + str = str[id]; + } else { + str = void 0; + } + } + + if (typeof(str) === 'string') { + if (is_error) { + return '\x1b[31m' + str + '\x1b[39m'; + } else { + return '\x1b[32m' + str + '\x1b[39m'; + } + } else { + return require('util').inspect(str, void 0, void 0, true); + } + }); + var sub = subsystems[obj.sub] || subsystems.default; + + return " \x1b[" + levels[type] + "m" + (pad(type)) + "\x1b[39m " + sub + " " + finalmsg; +}; + diff --git a/lib/middleware.js b/lib/middleware.js index ea4f8cbc5..b296845f0 100644 --- a/lib/middleware.js +++ b/lib/middleware.js @@ -1,6 +1,7 @@ var crypto = require('crypto'); var utils = require('./utils'); var UError = require('./error').UserError; +var Logger = require('./logger'); module.exports.validate_name = function validate_name(req, res, next, value, name) { if (utils.validate_name(req.params.package)) { @@ -43,7 +44,7 @@ module.exports.basic_auth = function basic_auth(callback) { if (req.user) return next(); if (authorization == null) { - req.user = req.remoteUser = 'anonymous'; + req.user = req.remoteUser = undefined; return next(); } @@ -85,14 +86,24 @@ function md5sum(data) { return crypto.createHash('md5').update(data).digest('hex'); } -// using it for json only right now -module.exports.etagify = function(req, res, next) { +module.exports.log_and_etagify = function(req, res, next) { + // logger + req.log = Logger.logger.child({sub: 'in'}); + req.log.info({req: req, ip: req.ip}, '@{ip} requested \'@{req.method} @{req.url}\''); + + var bytesin = 0; + req.on('data', function(chunk){ bytesin += chunk.length }); + var _send = res.send; res.send = function(body) { + var error; if (typeof(body) === 'string' || typeof(body) === 'object') { res.header('Content-type', 'application/json'); - if (typeof(body) === 'object') { + if (typeof(body) === 'object' && body != null) { + if (body.error) { + error = body.error; + } body = JSON.stringify(body, undefined, '\t'); } @@ -100,7 +111,27 @@ module.exports.etagify = function(req, res, next) { } else { // send(null), send(204), etc. } - _send.call(res, body); + + var msg = '@{status}, user: @{user}, req: \'@{request.method} @{request.url}\''; + if (error) { + msg += ', error: @{!error}'; + } else { + msg += ', bytes: @{bytes.in}/@{bytes.out}'; + } + req.log.warn({ + request: {method: req.method, url: req.url}, + level: 35, // http + user: req.user, + status: res.statusCode, + error: error, + bytes: { + in: bytesin, + out: body.length, + } + }, msg); + + res.send = _send; + res.send(body); }; next(); } diff --git a/lib/up-storage.js b/lib/up-storage.js index eeda2abc4..d1e162aaa 100644 --- a/lib/up-storage.js +++ b/lib/up-storage.js @@ -2,6 +2,7 @@ var URL = require('url'); var request = require('request'); var UError = require('./error').UserError; var mystreams = require('./streams'); +var Logger = require('./logger'); // // Implements Storage interface @@ -13,6 +14,7 @@ function Storage(config, mainconfig) { this.is_alive = false; this.userAgent = mainconfig.user_agent; this.ca = config.ca; + this.logger = Logger.logger.child({sub: 'out'}); this.url = URL.parse(this.config.url); if (this.url.hostname === 'registry.npmjs.org') { @@ -35,16 +37,61 @@ Storage.prototype.request = function(options, cb) { var headers = options.headers || {}; headers.accept = headers.accept || 'application/json'; headers['user-agent'] = headers['user-agent'] || this.userAgent; - var req = request({ - url: options.uri_full || (this.config.url + options.uri), - method: options.method || 'GET', + + var method = options.method || 'GET'; + var uri = options.uri_full || (this.config.url + options.uri); + var method = options.method || 'GET'; + self.logger.info({ + method: method, headers: headers, - json: options.json || true, + uri: uri, + }, "making request: '@{method} @{uri}'"); + + if (typeof(options.json) === 'object' && options.json != null) { + var json = JSON.stringify(options.json); + } + + var req = request({ + url: uri, + method: method, + headers: headers, + body: json, ca: this.ca, - }, function(err) { + }, function(err, res, body) { + var res_length = body.length; + if (options.json) { + try { + body = JSON.parse(body); + } catch(err) { + return cb(err); + } + } + + if (typeof(body) === 'object' && body != null) { + if (body.error) { + var error = body.error; + } + } + + var msg = '@{status}, req: \'@{request.method} @{request.url}\''; + if (error) { + msg += ', error: @{!error}'; + } else { + msg += ', bytes: @{bytes.in}/@{bytes.out}'; + } + self.logger.warn({ + request: {method: method, url: uri}, + level: 35, // http + status: res.statusCode, + error: error, + bytes: { + in: json ? json.length : 0, + out: res_length, + } + }, msg); if (cb) cb.apply(self, arguments); }); - req.on('response', function() { + req.on('response', function(res) { self.status_check(true); }); req.on('error', function() { @@ -172,7 +219,7 @@ Storage.prototype.get_url = function(url) { uri_full: url, encoding: null, }); - + rstream.on('response', function(res) { if (res.statusCode === 404) { return stream.emit('error', new UError({ diff --git a/package.yaml b/package.yaml index a82a263e7..82608479f 100644 --- a/package.yaml +++ b/package.yaml @@ -26,6 +26,7 @@ dependencies: async: '*' semver: '*' minimatch: '*' + bunyan: '>= 0.16.4' devDependencies: rimraf: '*'