diff --git a/Changes.md b/Changes.md index 2f7b55e5c..42fb50d16 100644 --- a/Changes.md +++ b/Changes.md @@ -16,16 +16,35 @@ - when using message-stream, don't send default options #3290 - auth_base: enable disabling constrain_sender at runtime #3298 - auth_base: skip constrain_sender when auth user has no domain #3319 +- rcpt_to.host_list: add connection ID to log messages #3322 - connection: support IPv6 when setting remote.is_private #3295 - in setTLS, replace forEach with for...of - NOTE: remove a handful of 3.0 sunset property names #3315 - outbound/mx_lookup: make it async/await +- outbound/mx_lookup: deleted. Logic moved into net_utils #3322 - outbound: emit log message when ignoring local MX #3285 - outbound: pass in config when initiating txn #3315 -- outbound: minor es6 updates #3315 +- outbound: minor es6 updates #3315, #3322 +- outbound: logging improvements #3322 + - was: [-] [core] [outbound] Failed to get socket: Outbound connection error: Error: connect ECONNREFUSED 172.16.16.14:25 + - now: [A63B62DF-F3B8-4096-8996-8CE83494A188.1.1] [outbound] Failed to get socket: connect ECONNREFUSED 172.16.16.14:25 + - shorter logger syntax: logger.loginfo -> logger.info + - outbound: remove log prefixes of `[outbound] `, no longer needed +- logger: don't load outbound (race condition). Instead, set name property #3322 +- logger: extend add_log_methods to Classes (connection, plugins, hmail) #3322 +- logger: when logging via `logger` methods, use short names #3322 +- outbound: delete try_deliver_host. Use net_utils to resolve MX hosts to IPs #3322 +- outbound: remove config setting ipv6_enabled #3322 +- outbound: remove undocumented use of send_email with arity of 2. #3322 +- outbound: encapsulate force_tls logic into get_force_tls #3322 +- queue/lmtp: refactored for DRY and improved readability #3322 +- mail_from.resolvable: refactored, leaning on improved net_utils #3322 + - fixes haraka/haraka-net-utils#88 #### Fixed +- fix(logger): refactor add_log_methods, don't set extra `loglog*` names +- doc(connection): update rfc7001 URL - fix(bin/haraka): list NPM installed plugin #3310 - fix(bin/haraka): get hook list from doc/Plugins #3306 - fix(outbound): call cb even if no MX is found #3294 diff --git a/bin/haraka b/bin/haraka index aef2f3816..98b73c85c 100755 --- a/bin/haraka +++ b/bin/haraka @@ -396,7 +396,7 @@ else if (parsed.test) { msg = fs.readFileSync(parsed.message); } catch (e) { - logger.logcrit(e.message); + logger.crit(e.message); logger.dump_logs(1); } } diff --git a/config/mail_from.is_resolvable.ini b/config/mail_from.is_resolvable.ini index 4e7c34f33..06f719d24 100644 --- a/config/mail_from.is_resolvable.ini +++ b/config/mail_from.is_resolvable.ini @@ -1,4 +1,6 @@ timeout=29 -allow_mx_ip=0 -reject_no_mx=1 +allow_mx_ip=false re_bogus_ip=^(?:0\.0\.0\.0|255\.255\.255\.255|127\.) + +[reject] +no_mx=true diff --git a/config/outbound.ini b/config/outbound.ini index b6b4376d3..3dfb87509 100644 --- a/config/outbound.ini +++ b/config/outbound.ini @@ -11,8 +11,6 @@ ; maxTempFailures (default: 13) -; ipv6_enabled (default: false) - ; load_pid_queue ; flush_queue diff --git a/connection.js b/connection.js index af631c7fc..4f29e265d 100644 --- a/connection.js +++ b/connection.js @@ -1454,7 +1454,7 @@ class Connection { return received_header; } auth_results (message) { - // http://tools.ietf.org/search/rfc7001 + // https://datatracker.ietf.org/doc/rfc7001/ const has_tran = !!((this.transaction?.notes)); // initialize connection note @@ -1784,7 +1784,7 @@ class Connection { }); break; default: - outbound.send_email(this.transaction, (retval2, msg2) => { + outbound.send_trans_email(this.transaction, (retval2, msg2) => { if (!msg2) msg2 = this.queue_msg(retval2, msg); switch (retval2) { case constants.ok: @@ -1895,17 +1895,4 @@ exports.createConnection = (client, server, cfg) => { return new Connection(client, server, cfg); } -// add logger methods to Connection: -for (const key in logger) { - if (!/^log\w/.test(key)) continue; - Connection.prototype[key] = (function (level) { - return function () { - // pass the connection instance to logger - const args = [ this ]; - for (let i=0, l=arguments.length; i { if (err.stack) { - err.stack.split("\n").forEach(line => logger.logcrit(line)); + err.stack.split("\n").forEach(line => logger.crit(line)); } else { - logger.logcrit(`Caught exception: ${JSON.stringify(err)}`); + logger.crit(`Caught exception: ${JSON.stringify(err)}`); } logger.dump_and_exit(1); }); @@ -52,7 +52,7 @@ signals.forEach((sig) => { const [, filename] = process.argv; process.title = path.basename(filename, '.js'); - logger.lognotice(`${sig} received`); + logger.notice(`${sig} received`); logger.dump_and_exit(() => { if (server.cluster?.isMaster) { server.performShutdown(); @@ -65,7 +65,7 @@ signals.forEach((sig) => { }); process.on('SIGHUP', () => { - logger.lognotice('Flushing the temp fail queue'); + logger.notice('Flushing the temp fail queue'); server.flushQueue(); }); @@ -74,7 +74,7 @@ process.on('exit', code => { const [, filename] = process.argv; process.title = path.basename(filename, '.js'); - logger.lognotice('Shutting down'); + logger.notice('Shutting down'); logger.dump_logs(); }); diff --git a/host_pool.js b/host_pool.js index e3f27cb94..15dd8987d 100644 --- a/host_pool.js +++ b/host_pool.js @@ -61,7 +61,7 @@ class HostPool { self.dead_hosts[key] = true; function cb_if_still_dead () { - logger.logwarn(`${host} ${key} is still dead, will retry in ${self.retry_secs} secs`); + logger.warn(`${host} ${key} is still dead, will retry in ${self.retry_secs} secs`); self.dead_hosts[key] = true; // console.log(1); setTimeout(() => { @@ -71,7 +71,7 @@ class HostPool { function cb_if_alive () { // console.log(2); - logger.loginfo(`${host} ${key} is back! adding back into pool`); + logger.info(`${host} ${key} is back! adding back into pool`); delete self.dead_hosts[key]; } @@ -90,7 +90,7 @@ class HostPool { probe_dead_host ( host, port, cb_if_still_dead, cb_if_alive ){ - logger.loginfo(`probing dead host ${host}:${port}`); + logger.info(`probing dead host ${host}:${port}`); const connect_timeout_ms = 200; // keep it snappy let s; @@ -162,7 +162,7 @@ class HostPool { return host; } else { - logger.logwarn( + logger.warn( `no working hosts found, retrying a dead one, config (probably from smtp_forward.forwarding_host_pool) is '${this.hostports_str}'`); this.last_i = first_i; return this.hosts[first_i]; diff --git a/logger.js b/logger.js index 37b9091c7..c54ad9b3c 100644 --- a/logger.js +++ b/logger.js @@ -8,8 +8,6 @@ const config = require('haraka-config'); const constants = require('haraka-constants'); let plugins; -let connection; -let outbound; const regex = /(^$|[ ="\\])/; const escape_replace_regex = /["\\]/g; @@ -48,6 +46,7 @@ logger.levels = { ALERT: 1, EMERG: 0, } +const level_names = Object.keys(logger.levels) for (const le in logger.levels) { logger.levels[`LOG${le}`] = logger.levels[le]; @@ -64,6 +63,7 @@ logger.loglevel = logger.levels.WARN; logger.format = logger.formats.DEFAULT; logger.timestamps = false; logger.deferred_logs = []; +logger.name = 'logger' logger.colors = { "DATA" : "green", @@ -235,14 +235,16 @@ logger._init_timestamps = function () { logger._init(); -logger.log_if_level = (level, key, plugin) => function () { - if (logger.loglevel < logger[key]) { return; } +logger.log_if_level = (level, key, origin) => function () { + if (logger.loglevel < logger[key]) return; + let logobj = { level, uuid: '-', - origin: (plugin || 'core'), + origin: (origin || 'core'), message: '' }; + for (const data of arguments) { if (typeof data !== 'object') { logobj.message += (data); @@ -251,24 +253,16 @@ logger.log_if_level = (level, key, plugin) => function () { if (!data) continue; // if the object is a connection, add the connection id - if (data instanceof connection.Connection) { + if (data.constructor?.name === 'Connection') { logobj.uuid = data.uuid; if (data.tran_count > 0) logobj.uuid += `.${data.tran_count}`; } else if (data instanceof plugins.Plugin) { logobj.origin = data.name; } - else if (data.name) { + else if (Object.hasOwn(data, 'name')) { // outbound logobj.origin = data.name; - } - else if (data instanceof outbound.HMailItem) { - logobj.origin = 'outbound'; - if (data.todo) { - if (data.todo.uuid) logobj.uuid = data.todo.uuid; - if (data.todo.client_uuid) { // dirty hack - logobj.origin = `outbound] [${data.todo.client_uuid}`; - } - } + if (data.todo?.uuid) logobj.uuid = data.todo.uuid; // outbound/hmail } else if ( logger.format === logger.formats.LOGFMT && data.constructor === Object) { @@ -278,7 +272,7 @@ logger.log_if_level = (level, key, plugin) => function () { logger.format === logger.formats.JSON && data.constructor === Object) { logobj = Object.assign(logobj, data); } - else if (typeof data === 'object' && Object.prototype.hasOwnProperty.call(data, "uuid")) { + else if (Object.hasOwn(data, 'uuid')) { logobj.uuid = data.uuid; } else if (data.constructor === Object) { @@ -313,14 +307,35 @@ logger.log_if_level = (level, key, plugin) => function () { return true; } -logger.add_log_methods = (object, plugin) => { - if (!object) return; - if (typeof(object) !== 'object') return; +logger.add_log_methods = (object, logName) => { + if (!object) return + + if (typeof object === 'function') { + // add logging methods to class prototypes (Connection, Plugin, etc.) + + for (const level of level_names.map(l => l.toLowerCase())) { + object.prototype[`log${level}`] = (function (level) { + return function () { + logger[level].apply(logger, [ this, ...arguments ]); + }; + })(`log${level}`); + } + } + else if (typeof object === 'object') { + // add logging methods to objects + + for (const level of level_names) { + // objects gets log function names: loginfo, logwarn, logdebug, ... + const fnNames = [`log${level.toLowerCase()}`] - for (const level in logger.levels) { - const fname = `log${level.toLowerCase()}`; - if (object[fname]) continue; // already added - object[fname] = logger.log_if_level(level, `LOG${level}`, plugin); + // logger also gets short names + if (object.name === 'logger') fnNames.push(level.toLowerCase()) + + for (const fnName of fnNames) { + if (object[fnName]) continue; // already added + object[fnName] = logger.log_if_level(level, `LOG${level}`, logName); + } + } } } @@ -328,5 +343,3 @@ logger.add_log_methods(logger); // load these down here so it sees all the logger methods compiled above plugins = require('./plugins'); -connection = require('./connection'); -outbound = require('./outbound'); diff --git a/outbound/client_pool.js b/outbound/client_pool.js index 1ee8ab753..2374f890c 100644 --- a/outbound/client_pool.js +++ b/outbound/client_pool.js @@ -7,42 +7,45 @@ const logger = require('../logger'); const obc = require('./config'); -function _create_socket (name, port, host, local_addr, is_unix_socket, callback) { +exports.name = 'outbound' - const socket = is_unix_socket ? sock.connect({path: host}) : sock.connect({port, host, localAddress: local_addr}); - socket.name = name; +// Get a socket for the given attributes. +exports.get_client = function (port = 25, host = 'localhost', localAddress, is_unix_socket, callback) { + + const socketArgs = is_unix_socket ? {path: host} : {port, host, localAddress}; + const socket = sock.connect(socketArgs); + + socket.name = `outbound::${port}:${host}:${localAddress}`; socket.__uuid = utils.uuid(); socket.setTimeout(obc.cfg.connect_timeout * 1000); - logger.logdebug(`[outbound] created. host: ${host} port: ${port}`, { uuid: socket.__uuid }); + + logger.debug(exports, `created. host: ${host} port: ${port}`, { uuid: socket.__uuid }); + socket.once('connect', () => { socket.removeAllListeners('error'); // these get added after callback socket.removeAllListeners('timeout'); callback(null, socket); - }); + }) + socket.once('error', err => { socket.end(); socket.removeAllListeners(); socket.destroy(); - callback(`Outbound connection error: ${err}`, null); - }); + callback(err.message, null); + }) + socket.once('timeout', () => { socket.end(); socket.removeAllListeners(); socket.destroy(); - callback(`Outbound connection timed out to ${host}:${port}`, null); - }); -} - - -// Get a socket for the given attributes. -exports.get_client = (port = 25, host = 'localhost', local_addr, is_unix_socket, callback) => { - const name = `outbound::${port}:${host}:${local_addr}`; - - _create_socket(name, port, host, local_addr, is_unix_socket, callback) + callback(`connection timed out to ${host}:${port}`, null); + }) } exports.release_client = (socket, port, host, local_addr, error) => { - logger.logdebug(`[outbound] release_client: ${socket.__uuid} ${host}:${port} to ${local_addr}`); + let logMsg = `release_client: ${socket.__uuid} ${host}:${port}` + if (local_addr) logMsg += ` from ${local_addr}` + logger.debug(exports, logMsg); socket.removeAllListeners(); socket.destroy(); } diff --git a/outbound/config.js b/outbound/config.js index d9e620c29..5ee1044be 100644 --- a/outbound/config.js +++ b/outbound/config.js @@ -3,13 +3,14 @@ const config = require('haraka-config'); const logger = require('../logger'); +exports.name = 'outbound/config' + function load_config () { const cfg = exports.cfg = config.get('outbound.ini', { booleans: [ '-disabled', '-always_split', '+enable_tls', - '-ipv6_enabled', '-local_mx_ok', ], }, () => { @@ -35,9 +36,6 @@ function load_config () { if (!cfg.connect_timeout) { cfg.connect_timeout = 30; } - if (!cfg.ipv6_enabled && config.get('outbound.ipv6_enabled')) { - cfg.ipv6_enabled = true; - } if (!cfg.received_header) { cfg.received_header = config.get('outbound.received_header') || 'Haraka outbound'; } @@ -64,8 +62,8 @@ exports.set_temp_fail_intervals = function () { // Helpful error function in case of parsing failure function error (i, msg) { - logger.logerror(`outbound temp_fail_intervals syntax error parsing element ${i}: ${msg}`); - logger.logwarn('Setting outbound temp_fail_intervals to old defaults because of previous error'); + logger.error(exports, `temp_fail_intervals syntax error parsing element ${i}: ${msg}`); + logger.warn(exports, 'Setting outbound temp_fail_intervals to old defaults'); set_old_defaults(); } diff --git a/outbound/fsync_writestream.js b/outbound/fsync_writestream.js index 768d6a589..99eff2664 100644 --- a/outbound/fsync_writestream.js +++ b/outbound/fsync_writestream.js @@ -1,6 +1,6 @@ 'use strict'; -const fs = require('fs'); +const fs = require('fs'); class FsyncWriteStream extends fs.WriteStream { constructor (path, options) { diff --git a/outbound/hmail.js b/outbound/hmail.js index 5f15131af..1954d2714 100644 --- a/outbound/hmail.js +++ b/outbound/hmail.js @@ -20,7 +20,6 @@ const plugins = require('../plugins'); const client_pool = require('./client_pool'); const _qfile = require('./qfile'); -const mx_lookup = require('./mx_lookup'); const outbound = require('./index'); const obtls = require('./tls'); @@ -50,6 +49,9 @@ class HMailItem extends events.EventEmitter { const parts = _qfile.parts(filename); if (!parts) throw new Error(`Bad filename: ${filename}`); + this.cfg = obc.cfg; + this.obtls = obtls; + this.name = 'outbound'; this.path = filePath; this.filename = filename; this.next_process = parts.next_attempt; @@ -210,140 +212,89 @@ class HMailItem extends events.EventEmitter { mx_list = [{priority: 0, exchange: matches[1], port: matches[3]}]; } this.logdebug(`Got a MX from Plugin: ${this.todo.domain} => 0 ${JSON.stringify(mx)}`); - return this.found_mx(null, mx_list); + return this.found_mx(mx_list); } case constants.deny: this.logwarn(`get_mx plugin returned DENY: ${mx}`); - this.todo.rcpt_to.forEach(rcpt => { + for (const rcpt of this.todo.rcpt_to) { this.extend_rcpt_with_dsn(rcpt, DSN.addr_bad_dest_system(`No MX for ${this.todo.domain}`)); - }); + } return this.bounce(`No MX for ${this.todo.domain}`); case constants.denysoft: this.logwarn(`get_mx plugin returned DENYSOFT: ${mx}`); - this.todo.rcpt_to.forEach(rcpt => { + for (const rcpt of this.todo.rcpt_to) { this.extend_rcpt_with_dsn(rcpt, DSN.addr_bad_dest_system(`Temporary MX lookup error for ${this.todo.domain}`, 450)); - }); + } return this.temp_fail(`Temporary MX lookup error for ${this.todo.domain}`); } - // if none of the above return codes, drop through to this... - mx_lookup.lookup_mx(this.todo.domain, (err, mxs) => { - if (mxs) mxs.forEach(m => { m.from_dns = true; }); - - this.found_mx (err, mxs) - }) - } - - found_mx (err, mxs) { - if (err) { - this.lognotice(`MX Lookup for ${this.todo.domain} failed: ${err}`); - if (err.code === dns.NXDOMAIN || err.code === dns.NOTFOUND) { - this.todo.rcpt_to.forEach(rcpt => { - this.extend_rcpt_with_dsn(rcpt, DSN.addr_bad_dest_system(`No Such Domain: ${this.todo.domain}`)); - }); - this.bounce(`No Such Domain: ${this.todo.domain}`); + // none of the above return codes, drop through to DNS + net_utils.get_mx(this.todo.domain).then(exchanges => { + if (exchanges.length) { + this.found_mx(this.sort_mx(exchanges)) } - else if (err.code === 'NOMX') { - this.todo.rcpt_to.forEach(rcpt => { + else { + for (const rcpt of this.todo.rcpt_to) { this.extend_rcpt_with_dsn(rcpt, DSN.addr_bad_dest_system(`Nowhere to deliver mail to for domain: ${this.todo.domain}`)); - }); + } this.bounce(`Nowhere to deliver mail to for domain: ${this.todo.domain}`); } - else { - // every other error is transient - this.todo.rcpt_to.forEach(rcpt => { - this.extend_rcpt_with_dsn(rcpt, DSN.addr_unspecified(`DNS lookup failure: ${this.todo.domain}`)); - }); - this.temp_fail(`DNS lookup failure: ${err}`); + }) + .catch(this.get_mx_err) + } + + get_mx_error (err) { + this.lognotice(`MX Lookup for ${this.todo.domain} failed: ${err}`); + + if (err.code === dns.NXDOMAIN || err.code === dns.NOTFOUND) { + for (const rcpt of this.todo.rcpt_to) { + this.extend_rcpt_with_dsn(rcpt, DSN.addr_bad_dest_system(`No Such Domain: ${this.todo.domain}`)); } + this.bounce(`No Such Domain: ${this.todo.domain}`); } else { - // got MXs - const mxlist = sort_mx(mxs); - // support draft-delany-nullmx-02 - if (mxlist.length === 1 && mxlist[0].priority === 0 && mxlist[0].exchange === '') { - this.todo.rcpt_to.forEach(rcpt => { - this.extend_rcpt_with_dsn(rcpt, DSN.addr_bad_dest_system(`Domain ${this.todo.domain} sends and receives no email (NULL MX)`)); - }); - return this.bounce(`Domain ${this.todo.domain} sends and receives no email (NULL MX)`); + // every other error is transient + for (const rcpt of this.todo.rcpt_to) { + this.extend_rcpt_with_dsn(rcpt, DSN.addr_unspecified(`DNS lookup failure: ${this.todo.domain}`)); } - // duplicate each MX for each ip address family - this.mxlist = []; - for (const mx in mxlist) { - // Handle UNIX sockets for LMTP - if (mxlist[mx].path) { - this.mxlist.push(mxlist[mx]); - } - else { - if (obc.cfg.ipv6_enabled) { - this.mxlist.push(Object.assign({}, mxlist[mx], { family: 'AAAA' })); - } - this.mxlist.push(Object.assign({}, mxlist[mx], { family: 'A' })); - } + this.temp_fail(`DNS lookup failure: ${err}`); + } + } + + async found_mx (mxs) { + + // support draft-delany-nullmx-02 + if (mxs.length === 1 && mxs[0].priority === 0 && mxs[0].exchange === '') { + for (const rcpt of this.todo.rcpt_to) { + this.extend_rcpt_with_dsn(rcpt, DSN.addr_bad_dest_system(`Domain ${this.todo.domain} sends and receives no email (NULL MX)`)); } - this.try_deliver(); + return this.bounce(`Domain ${this.todo.domain} sends and receives no email (NULL MX)`); } + + // resolves the MX hostnames into IPs + this.mxlist = await net_utils.resolve_mx_hosts(mxs); + + this.try_deliver(); } async try_deliver () { - // check if there are any MXs left + // are any MXs left? if (this.mxlist.length === 0) { - this.todo.rcpt_to.forEach(rcpt => { + for (const rcpt of this.todo.rcpt_to) { this.extend_rcpt_with_dsn(rcpt, DSN.addr_bad_dest_system(`Tried all MXs ${this.todo.domain}`)); - }); + } return this.temp_fail("Tried all MXs"); } const mx = this.mxlist.shift(); - const host = mx.exchange; - if (!obc.cfg.local_mx_ok && mx.from_dns && await net_utils.is_local_host(host)) { - this.loginfo(`MX ${host} is local, skipping since local_mx_ok=false`) + if (!obc.cfg.local_mx_ok && mx.from_dns && await net_utils.is_local_host(mx.exchange)) { + this.loginfo(`MX ${mx.exchange} is local, skipping since local_mx_ok=false`) return this.try_deliver(); // try next MX } - this.force_tls = this.todo.force_tls; - if (!this.force_tls) { - if (net_utils.ip_in_list(obtls.cfg.force_tls_hosts, host)) { - this.logdebug(`Forcing TLS for host ${host}`); - this.force_tls = true; - } - if (net_utils.ip_in_list(obtls.cfg.force_tls_hosts, this.todo.domain)) { - this.logdebug(`Forcing TLS for domain ${this.todo.domain}`); - this.force_tls = true; - } - - // IP or IP:port - if (net.isIP(host)) { - this.hostlist = [ host ]; - return this.try_deliver_host(mx); - } - } - - // we have a host, look up the addresses for the host - // and try each in order they appear - dns.resolve(host, mx.family, (err, addresses) => { - if (err) { - this.lognotice(`DNS (${mx.family}) for ${host} failed: ${err}`); - return this.try_deliver(); // try next MX - } - if (addresses.length === 0) { - // NODATA or empty host list - this.lognotice(`DNS (${mx.family}) for ${host} resulted in no data`); - return this.try_deliver(); // try next MX - } - this.logdebug(`DNS (${mx.family}) for ${host} -> ${addresses.join(',')}`); - this.hostlist = addresses; - this.try_deliver_host(mx); - }); - } - - try_deliver_host (mx) { - - if (this.hostlist.length === 0) { - return this.try_deliver(); // try next MX - } + this.force_tls = this.get_force_tls(mx) // Allow transaction notes to set outbound IP if (!mx.bind && this.todo.notes.outbound_ip) { @@ -360,24 +311,20 @@ class HMailItem extends events.EventEmitter { } } - let host = this.hostlist.shift(); + const host = mx.path ? mx.path : mx.exchange; const port = mx.port || 25; - if (mx.path) { - host = mx.path; - } - this.logdebug(`delivering from: ${mx.bind_helo} to: ${host}:${port}${mx.using_lmtp ? " using LMTP" : ""}${mx.from_dns ? " (via DNS)" : ""} (${delivery_queue.length()}) (${temp_fail_queue.length()})`) client_pool.get_client(port, host, mx.bind, !!mx.path, (err, socket) => { if (err) { if (/connection timed out|connect ECONNREFUSED/.test(err)) { - logger.lognotice(`[outbound] Failed to get socket: ${err}`); + logger.notice(this, `Failed to get socket: ${err}`); } else { - logger.logerror(`[outbound] Failed to get socket: ${err}`); + logger.error(this, `Failed to get socket: ${err}`); } - // try next host - return this.try_deliver_host(mx); + + return this.try_deliver(); // try next MX } this.try_deliver_host_on_socket(mx, host, port, socket); }); @@ -404,9 +351,8 @@ class HMailItem extends events.EventEmitter { processing_mail = false; client_pool.release_client(socket, port, host, mx.bind, true); if (err.source === 'tls') // exception thrown from tls_socket during tls upgrade - return obtls.mark_tls_nogo(host, () => { return self.try_deliver_host(mx); }); - // try the next MX - self.try_deliver_host(mx); + return obtls.mark_tls_nogo(host, () => { return self.try_deliver(); }); + self.try_deliver(); // try the next MX }) socket.once('close', () => { @@ -415,7 +361,7 @@ class HMailItem extends events.EventEmitter { self.logerror(`Remote end ${host}:${port} closed connection while we were processing mail. Trying next MX.`); processing_mail = false; client_pool.release_client(socket, port, host, mx.bind, true); - self.try_deliver_host(mx); + self.try_deliver(); }); let fin_sent = false; @@ -454,7 +400,7 @@ class HMailItem extends events.EventEmitter { if (processing_mail) { processing_mail = false; client_pool.release_client(socket, port, host, mx.bind, true); - return self.try_deliver_host(mx); + return self.try_deliver(); } return; } @@ -942,9 +888,9 @@ class HMailItem extends events.EventEmitter { }); if (socket.__fromPool) { - logger.logdebug('[outbound] got socket, trying to deliver'); + logger.debug(this, 'got socket, trying to deliver'); secured = socket.isEncrypted(); - logger.logdebug(`[outbound] got ${secured ? 'TLS ' : '' }socket, trying to deliver`); + logger.debug(this, `got ${secured ? 'TLS ' : '' }socket, trying to deliver`); send_command('MAIL', get_reverse_path_with_params()); } } @@ -1349,7 +1295,7 @@ class HMailItem extends events.EventEmitter { } temp_fail (err, extra) { - logger.logdebug(`Temp fail for: ${err}`); + logger.debug(this, `Temp fail for: ${err}`); this.num_failures++; // Test for max failures which is configurable. @@ -1394,7 +1340,7 @@ class HMailItem extends events.EventEmitter { }); } - // The following handler has an impact on outgoing mail. It does remove the queue file. + // The following handler impacts outgoing mail. It removes the queue file. delivered_respond (retval, msg) { if (retval !== constants.cont && retval !== constants.ok) { this.logwarn( @@ -1405,6 +1351,51 @@ class HMailItem extends events.EventEmitter { this.discard(); } + get_force_tls (mx) { + if (!mx.exchange) return false + if (!obtls.cfg.force_tls_hosts) return false + + if (net_utils.ip_in_list(obtls.cfg.force_tls_hosts, mx.exchange)) { + this.logdebug(`Forcing TLS for host ${mx.exchange}`); + return true; + } + + if (mx.from_dns) { + // the MX was looked up in DNS and already resolved to IP(s). + // This checks the hostname. + if (net_utils.ip_in_list(obtls.cfg.force_tls_hosts, mx.from_dns)) { + this.logdebug(`Forcing TLS for host ${mx.from_dns}`); + return true; + } + } + + if (net_utils.ip_in_list(obtls.cfg.force_tls_hosts, this.todo.domain)) { + this.logdebug(`Forcing TLS for domain ${this.todo.domain}`); + return true; + } + + return false + } + + sort_mx (mx_list) { + // MXs must be sorted by priority. + const sorted = mx_list.sort((a,b) => a.priority - b.priority); + + // Matched priorities must be randomly shuffled. + // This isn't a very good shuffle but it'll do for now. + for (let i=0,l=sorted.length-1; i { hmail.extend_rcpt_with_dsn(rcpt, DSN.sys_unspecified(`Error splitting to new recipients: ${err}`)); }); @@ -1454,7 +1445,7 @@ class HMailItem extends events.EventEmitter { } ws.on('error', err => { - logger.logerror(`[outbound] Unable to write queue file (${fname}): ${err}`); + logger.error(this, `Unable to write queue file (${fname}): ${err}`); ws.destroy(); hmail.todo.rcpt_to.forEach(rcpt => { hmail.extend_rcpt_with_dsn(rcpt, DSN.sys_unspecified(`Error re-queueing some recipients: ${err}`)); @@ -1471,20 +1462,7 @@ class HMailItem extends events.EventEmitter { module.exports = HMailItem; module.exports.obtls = obtls; -// copy logger methods into HMailItem: -for (const key in logger) { - if (!/^log\w/.test(key)) continue; - HMailItem.prototype[key] = (function (level) { - return function () { - // pass the HMailItem instance to logger - const args = [ this ]; - for (let i=0, l=arguments.length; i { return; } if (msg.event === 'outbound.shutdown') { - logger.loginfo("[outbound] Shutting down temp fail queue"); + logger.info(exports, "Shutting down temp fail queue"); temp_fail_queue.shutdown(); return; } @@ -60,25 +61,18 @@ process.on('message', msg => { exports.send_email = function (from, to, contents, next, options = {}) { - if (arguments.length === 2) { - logger.logdebug("[outbound] Sending email as a transaction"); - return this.send_trans_email(arguments[0], arguments[1]); - } - const dot_stuffed = options.dot_stuffed ?? false; const notes = options.notes ?? null; - const origin = options.origin ?? null; + const origin = options.origin ?? exports; - logger.loginfo("[outbound] Sending email via params", origin); + logger.info("Sending email via params", origin); const transaction = trans.createTransaction(null, smtp_ini); - logger.loginfo(`[outbound] Created transaction: ${transaction.uuid}`, origin); + logger.info(`Created transaction: ${transaction.uuid}`, origin); // Adding notes passed as parameter - if (notes) { - transaction.notes = notes; - } + if (notes) transaction.notes = notes; // set MAIL FROM address, and parse if it's not an Address object if (from instanceof Address) { @@ -95,10 +89,7 @@ exports.send_email = function (from, to, contents, next, options = {}) { } // Make sure to is an array - if (!(Array.isArray(to))) { - // turn into an array - to = [ to ]; - } + if (!(Array.isArray(to))) to = [ to ]; if (to.length === 0) { return next(constants.deny, "No recipients for email"); @@ -192,10 +183,10 @@ function get_deliveries (transaction) { const deliveries = []; if (obc.cfg.always_split) { - logger.logdebug({name: "outbound"}, "always split"); - transaction.rcpt_to.forEach(rcpt => { + logger.debug(exports, "always split"); + for (const rcpt of transaction.rcpt_to) { deliveries.push({domain: rcpt.host, rcpts: [ rcpt ]}); - }); + } return deliveries; } @@ -216,16 +207,16 @@ exports.send_trans_email = function (transaction, next) { // add potentially missing headers if (!transaction.header.get_all('Message-Id').length) { - logger.loginfo("[outbound] Adding missing Message-Id header"); + logger.info(exports, "Adding missing Message-Id header"); transaction.add_header('Message-Id', `<${transaction.uuid}@${net_utils.get_primary_host_name()}>`); } if (transaction.header.get('Message-Id') === '<>') { - logger.loginfo("[outbound] Replacing empty Message-Id header"); + logger.info(exports, "Replacing empty Message-Id header"); transaction.remove_header('Message-Id'); transaction.add_header('Message-Id', `<${transaction.uuid}@${net_utils.get_primary_host_name()}>`); } if (!transaction.header.get_all('Date').length) { - logger.loginfo("[outbound] Adding missing Date header"); + logger.info(exports, "Adding missing Date header"); transaction.add_header('Date', utils.date_to_str(new Date())); } @@ -237,7 +228,7 @@ exports.send_trans_email = function (transaction, next) { logger.add_log_methods(connection); if (!transaction.results) { - logger.logdebug('adding results store'); + logger.debug(exports, 'adding results store'); transaction.results = new ResultStore(connection); } @@ -279,7 +270,7 @@ exports.send_trans_email = function (transaction, next) { } exports.process_delivery = function (ok_paths, todo, hmails, cb) { - logger.loginfo(`[outbound] Transaction delivery for domain: ${todo.domain}`); + logger.info(exports, `Transaction delivery for domain: ${todo.domain}`); const fname = _qfile.name(); const tmp_path = path.join(queue_dir, `${_qfile.platformDOT}${fname}`); const ws = new FsyncWriteStream(tmp_path, { flags: constants.WRITE_EXCL }); @@ -288,7 +279,7 @@ exports.process_delivery = function (ok_paths, todo, hmails, cb) { const dest_path = path.join(queue_dir, fname); fs.rename(tmp_path, dest_path, err => { if (err) { - logger.logerror(`[outbound] Unable to rename tmp file!: ${err}`); + logger.error(exports, `Unable to rename tmp file!: ${err}`); fs.unlink(tmp_path, () => {}); cb("Queue error"); } @@ -301,7 +292,7 @@ exports.process_delivery = function (ok_paths, todo, hmails, cb) { }) ws.on('error', err => { - logger.logerror(`[outbound] Unable to write queue file (${fname}): ${err}`); + logger.error(exports, `Unable to write queue file (${fname}): ${err}`); ws.destroy(); fs.unlink(tmp_path, () => {}); cb("Queueing failed"); @@ -344,5 +335,3 @@ function exclude_from_json (key, value) { exports.TODOItem = TODOItem; exports.HMailItem = HMailItem; - -exports.lookup_mx = require('./mx_lookup').lookup_mx; diff --git a/outbound/mx_lookup.js b/outbound/mx_lookup.js deleted file mode 100644 index 6575ad0fb..000000000 --- a/outbound/mx_lookup.js +++ /dev/null @@ -1,65 +0,0 @@ -"use strict"; - -const dns = require('node:dns').promises; -const net_utils = require('haraka-net-utils') - -exports.lookup_mx = async function lookup_mx (domain, cb) { - const mxs = []; - - try { - const addresses = await net_utils.get_mx(domain) - for (const a of addresses) { - mxs.push(a); - } - if (mxs.length) { - if (cb) return cb(null, mxs) - return mxs - } - } - catch (err) { - - // Possible DNS errors - // NODATA - // FORMERR - // BADRESP - // NOTFOUND - // BADNAME - // TIMEOUT - // CONNREFUSED - // NOMEM - // DESTRUCTION - // NOTIMP - // EREFUSED - // SERVFAIL - - switch (err.code) { - case 'ENODATA': - case 'ENOTFOUND': - // likely a hostname with no MX record, drop through - break - default: - if (cb) return cb(err, mxs) - throw err - } - } - - // No MX record, try resolving A record - - // wrap addresses with "priority" and "exchange" keys - const wrap_mx = a => ({priority:0,exchange:a}); - - const addresses = await dns.resolve(domain) - for (const a of addresses) { - mxs.push(wrap_mx(a)); - } - - if (mxs.length) { - if (cb) return cb(null, mxs) - return mxs - } - - const err = new Error("Found nowhere to deliver to"); - err.code = 'NOMX'; - if (cb) return cb(err) - throw err -} diff --git a/outbound/queue.js b/outbound/queue.js index 537827ba5..23e00ec21 100644 --- a/outbound/queue.js +++ b/outbound/queue.js @@ -15,6 +15,8 @@ const obc = require('./config'); const _qfile = require('./qfile'); const obtls = require('./tls'); +exports.name = 'outbound/queue'; + let queue_dir; if (config.get('queue_dir')) { queue_dir = path.resolve(config.get('queue_dir')); @@ -78,18 +80,18 @@ exports.load_queue = pid => { exports.delete_dot_files(); exports._load_cur_queue(pid, exports._add_file, () => { - logger.loginfo(`[outbound] [pid: ${pid}] ${delivery_queue.length()} files in my delivery queue`); - logger.loginfo(`[outbound] [pid: ${pid}] ${load_queue.length()} files in my load queue`); - logger.loginfo(`[outbound] [pid: ${pid}] ${temp_fail_queue.length()} files in my temp fail queue`); + logger.info(exports, `[pid: ${pid}] ${delivery_queue.length()} files in my delivery queue`); + logger.info(exports, `[pid: ${pid}] ${load_queue.length()} files in my load queue`); + logger.info(exports, `[pid: ${pid}] ${temp_fail_queue.length()} files in my temp fail queue`); }); } exports._load_cur_queue = (pid, iteratee, cb) => { const self = exports; - logger.loginfo("[outbound] Loading outbound queue from ", queue_dir); + logger.info(exports, "Loading outbound queue from ", queue_dir); fs.readdir(queue_dir, (err, files) => { if (err) { - return logger.logerror(`[outbound] Failed to load queue directory (${queue_dir}): ${err}`); + return logger.error(exports, `Failed to load queue directory (${queue_dir}): ${err}`); } self.cur_time = new Date(); // set once so we're not calling it a lot @@ -100,18 +102,18 @@ exports._load_cur_queue = (pid, iteratee, cb) => { exports.read_parts = file => { if (file.indexOf(_qfile.platformDOT) === 0) { - logger.logwarn(`[outbound] 'Skipping' dot-file in queue folder: ${file}`); + logger.warn(exports, `'Skipping' dot-file in queue folder: ${file}`); return false; } if (file.startsWith('error.')) { - logger.logwarn(`[outbound] 'Skipping' error file in queue folder: ${file}`); + logger.warn(exports, `'Skipping' error file in queue folder: ${file}`); return false; } const parts = _qfile.parts(file); if (!parts) { - logger.logerror(`[outbound] Unrecognized file in queue folder: ${file}`); + logger.error(exports, `Unrecognized file in queue folder: ${file}`); return false; } @@ -141,11 +143,11 @@ exports._add_file = (file, cb) => { const parts = _qfile.parts(file); if (parts.next_attempt <= self.cur_time) { - logger.logdebug(`[outbound] File ${file} needs processing now`); + logger.debug(exports, `File ${file} needs processing now`); load_queue.push(file); } else { - logger.logdebug(`[outbound] File ${file} needs processing later: ${parts.next_attempt - self.cur_time}ms`); + logger.debug(exports, `File ${file} needs processing later: ${parts.next_attempt - self.cur_time}ms`); temp_fail_queue.add(file, parts.next_attempt - self.cur_time, () => { load_queue.push(file);}); } @@ -160,10 +162,10 @@ exports.load_queue_files = (pid, input_files, iteratee, callback = function () { let stat_loaded = 0; if (searchPid) { - logger.loginfo(`[outbound] Grabbing queue files for pid: ${pid}`); + logger.info(exports, `Grabbing queue files for pid: ${pid}`); } else { - logger.loginfo("[outbound] Loading the queue..."); + logger.info(exports, "Loading the queue..."); } async.map(input_files, (file, cb) => { @@ -175,7 +177,7 @@ exports.load_queue_files = (pid, input_files, iteratee, callback = function () { self.rename_to_actual_pid(file, parts, (error, renamed_file) => { if (error) { - logger.logerror(`[outbound] ${error}`); + logger.error(exports, `${error}`); return cb(); } @@ -190,9 +192,9 @@ exports.load_queue_files = (pid, input_files, iteratee, callback = function () { } }, (err, results) => { - if (err) logger.logerr(`[outbound] [pid: ${pid}] ${err}`); - if (searchPid) logger.loginfo(`[outbound] [pid: ${pid}] ${stat_renamed} files old PID queue fixed up`); - logger.logdebug(`[outbound] [pid: ${pid}] ${stat_loaded} files loaded`); + if (err) logger.err(exports, `[pid: ${pid}] ${err}`); + if (searchPid) logger.info(exports, `[pid: ${pid}] ${stat_renamed} files old PID queue fixed up`); + logger.debug(exports, `[pid: ${pid}] ${stat_loaded} files loaded`); async.map(results.filter((i) => i), iteratee, callback); }); @@ -244,7 +246,7 @@ exports._list_file = (file, cb) => { exports.flush_queue = (domain, pid) => { if (domain) { exports.list_queue((err, qlist) => { - if (err) return logger.logerror(`[outbound] Failed to load queue: ${err}`); + if (err) return logger.error(exports, `Failed to load queue: ${err}`); qlist.forEach(todo => { if (todo.domain.toLowerCase() != domain.toLowerCase()) return; if (pid && todo.pid != pid) return; @@ -259,7 +261,7 @@ exports.flush_queue = (domain, pid) => { } exports.load_pid_queue = pid => { - logger.loginfo(`[outbound] Loading queue for pid: ${pid}`); + logger.info(exports, `Loading queue for pid: ${pid}`); exports.load_queue(pid); } @@ -268,7 +270,7 @@ exports.ensure_queue_dir = () => { // this code is only run at start-up. if (fs.existsSync(queue_dir)) return; - logger.logdebug(`[outbound] Creating queue directory ${queue_dir}`); + logger.debug(exports, `Creating queue directory ${queue_dir}`); try { fs.mkdirSync(queue_dir, 493); // 493 == 0755 const cfg = config.get('smtp.ini'); @@ -285,21 +287,19 @@ exports.ensure_queue_dir = () => { } catch (err) { if (err.code !== 'EEXIST') { - logger.logerror(`[outbound] Error creating queue directory: ${err}`); + logger.error(exports, `Error creating queue directory: ${err}`); throw err; } } } exports.delete_dot_files = () => { - const files = fs.readdirSync(queue_dir); - - files.forEach(file => { + for (const file of fs.readdirSync(queue_dir)) { if (file.indexOf(_qfile.platformDOT) === 0) { - logger.logwarn(`[outbound] Removing left over dot-file: ${file}`); + logger.warn(exports, `Removing left over dot-file: ${file}`); return fs.unlinkSync(path.join(queue_dir, file)); } - }); + } } exports._add_hmail = hmail => { @@ -323,16 +323,16 @@ exports.scan_queue_pids = cb => { fs.readdir(queue_dir, (err, files) => { if (err) { - logger.logerror(`[outbound] Failed to load queue directory (${queue_dir}): ${err}`); + logger.error(exports, `Failed to load queue directory (${queue_dir}): ${err}`); return cb(err); } const pids = {}; - files.forEach(file => { + for (const file of files) { const parts = self.read_parts(file); if (parts) pids[parts.pid] = true; - }); + } return cb(null, Object.keys(pids)); }); diff --git a/outbound/timer_queue.js b/outbound/timer_queue.js index c3bac506e..d16b46e10 100644 --- a/outbound/timer_queue.js +++ b/outbound/timer_queue.js @@ -71,7 +71,7 @@ class TimerQueue { } drain () { - logger.logdebug(`Draining ${this.queue.length} items from the queue`); + logger.debug({ name: 'outbound/timer_queue'}, `Draining ${this.queue.length} items from the queue`); while (this.queue.length) { const to_run = this.queue.shift(); if (to_run.cb) to_run.cb(); @@ -84,4 +84,3 @@ class TimerQueue { } module.exports = TimerQueue; - diff --git a/outbound/tls.js b/outbound/tls.js index 138e13b82..09be865e4 100644 --- a/outbound/tls.js +++ b/outbound/tls.js @@ -64,15 +64,23 @@ class OutboundTLS { this.load_config(); // changing this var in-flight won't work if (this.cfg.redis && !this.cfg.redis.disable_for_failed_hosts) return cb(); - logger.logdebug(this, 'Will disable outbound TLS for failing TLS hosts'); + logger.debug(this, 'Will disable outbound TLS for failing TLS hosts'); Object.assign(this, hkredis); this.merge_redis_ini(); this.init_redis_plugin(cb); } get_tls_options (mx) { - if (net.isIP(mx.exchange)) return this.cfg - return Object.assign(this.cfg, {servername: mx.exchange}); + // do NOT set servername to an IP address + if (net.isIP(mx.exchange)) { + // when mx.exchange looked up in DNS, from_dns has the hostname + if (mx.from_dns) return { ...this.cfg, servername: mx.from_dns } + return { ...this.cfg } + } + else { + // mx.exchange is a hostname + return { ...this.cfg, servername: mx.exchange } + } } // Check for if host is prohibited from TLS negotiation @@ -85,7 +93,7 @@ class OutboundTLS { dbr ? cb_nogo(dbr) : cb_ok(); }) .catch(err => { - this.logdebug(this, `Redis returned error: ${err}`); + logger.debug(this, `Redis returned error: ${err}`); cb_ok(); }) } @@ -96,12 +104,12 @@ class OutboundTLS { if (!this.cfg.redis.disable_for_failed_hosts) return cb(); - logger.lognotice(this, `TLS connection failed. Marking ${host} as non-TLS for ${expiry} seconds`); + logger.notice(this, `TLS connection failed. Marking ${host} as non-TLS for ${expiry} seconds`); this.db.setEx(dbkey, expiry, (new Date()).toISOString()) .then(cb) .catch(err => { - logger.logerror(this, `Redis returned error: ${err}`); + logger.error(this, `Redis returned error: ${err}`); }) } } diff --git a/package.json b/package.json index 12d399b02..f857cb2fd 100644 --- a/package.json +++ b/package.json @@ -35,7 +35,7 @@ "haraka-dsn": "^1.0.5", "haraka-email-message": "^1.2.2", "haraka-message-stream": "^1.2.1", - "haraka-net-utils": "^1.5.4", + "haraka-net-utils": "^1.6.0", "haraka-notes": "^1.0.7", "haraka-plugin-attachment": "^1.1.2", "haraka-plugin-dkim": "^1.0.2", diff --git a/plugins.js b/plugins.js index da71d155a..da0504c62 100644 --- a/plugins.js +++ b/plugins.js @@ -128,7 +128,7 @@ class Plugin { this.hooks[hook_name] = this.hooks[hook_name] || []; this.hooks[hook_name].push(method_name); - logger.logdebug(`registered hook ${hook_name} to ${this.name}.` + + logger.debug(`registered hook ${hook_name} to ${this.name}.` + `${method_name} priority ${priority}`); } @@ -195,7 +195,7 @@ class Plugin { } catch (err) { if (exports.config.get('smtp.ini').main.ignore_bad_plugins) { - logger.logcrit(`Loading plugin ${this.name} failed: ${err}`); + logger.crit(`Loading plugin ${this.name} failed: ${err}`); return; } throw `Loading plugin ${this.name} failed: ${err}`; @@ -231,9 +231,9 @@ class Plugin { vm.runInNewContext(code, sandbox, pp); } catch (err) { - logger.logcrit(`Compiling plugin: ${this.name} failed`); + logger.crit(`Compiling plugin: ${this.name} failed`); if (exports.config.get('smtp.ini').main.ignore_bad_plugins) { - logger.logcrit(`Loading plugin ${this.name} failed: `, + logger.crit(`Loading plugin ${this.name} failed: `, `${err.message} - will skip this plugin and continue`); return; } @@ -254,7 +254,7 @@ exports.shutdown_plugins = () => { process.on('message', msg => { if (msg.event && msg.event == 'plugins.shutdown') { - logger.loginfo("[plugins] Shutting down plugins"); + logger.info("[plugins] Shutting down plugins"); exports.shutdown_plugins(); } }); @@ -270,39 +270,26 @@ function plugin_search_paths (prefix, name) { function get_timeout (name) { let timeout = parseFloat((exports.config.get(`${name}.timeout`))); if (isNaN(timeout)) { - logger.logdebug(`no timeout in ${name}.timeout`); + logger.debug(`no timeout in ${name}.timeout`); timeout = parseFloat(exports.config.get('plugin_timeout')); } if (isNaN(timeout)) { - logger.logdebug('no timeout in plugin_timeout'); + logger.debug('no timeout in plugin_timeout'); timeout = 30; } - logger.logdebug(`plugin ${name} timeout is: ${timeout}s`); + logger.debug(`plugin ${name} timeout is: ${timeout}s`); return timeout; } -// copy logger methods into Plugin: -for (const key in logger) { - if (!/^log\w/.test(key)) continue; - // console.log(`adding Plugin.${key} method`); - Plugin.prototype[key] = (function (lev) { - return function () { - const args = [this]; - for (let i=0, l=arguments.length; i { - logger.loginfo('Loading plugins'); + logger.info('Loading plugins'); let plugin_list; if (override) { if (!Array.isArray(override)) override = [ override ]; @@ -315,7 +302,7 @@ plugins.load_plugins = override => { for (let plugin of plugin_list) { if (plugin.startsWith('haraka-plugin-')) plugin = plugin.substr(14) if (plugins.deprecated[plugin]) { - logger.lognotice(`the plugin ${plugin} has been replaced by '${plugins.deprecated[plugin]}'. Please update config/plugins`) + logger.notice(`the plugin ${plugin} has been replaced by '${plugins.deprecated[plugin]}'. Please update config/plugins`) plugins.load_plugin(plugins.deprecated[plugin]); } else { @@ -374,7 +361,7 @@ plugins.deprecated = { } plugins.load_plugin = name => { - logger.loginfo(`Loading plugin: ${name}`); + logger.info(`Loading plugin: ${name}`); const plugin = plugins._load_and_compile_plugin(name); if (plugin) { @@ -394,7 +381,7 @@ plugins._load_and_compile_plugin = name => { if (!plugin.plugin_path) { const err = `Loading plugin ${plugin.name} failed: No plugin with this name found`; if (exports.config.get('smtp.ini').main.ignore_bad_plugins) { - logger.logcrit(err); + logger.crit(err); return; } throw err; diff --git a/plugins/mail_from.is_resolvable.js b/plugins/mail_from.is_resolvable.js index c8c123172..b59b0d32e 100644 --- a/plugins/mail_from.is_resolvable.js +++ b/plugins/mail_from.is_resolvable.js @@ -1,7 +1,6 @@ 'use strict'; // Check MAIL FROM domain is resolvable to an MX -const dns = require('dns'); const net = require('net'); const net_utils = require('haraka-net-utils'); @@ -14,12 +13,17 @@ exports.load_ini = function () { this.cfg = this.config.get('mail_from.is_resolvable.ini', { booleans: [ '-main.allow_mx_ip', - '+main.reject_no_mx', + '+reject.no_mx', ], }, () => { this.load_ini(); }); + // compat. Sunset 4.0 + if (this.cfg.main.reject_no_mx) { + this.cfg.reject.no_mx = this.cfg.main.reject_no_mx + } + if (isNaN(this.cfg.main.timeout)) { this.cfg.main.timeout = 29; } @@ -40,163 +44,89 @@ exports.hook_mail = function (next, connection, params) { const mail_from = params[0]; const txn = connection?.transaction; if (!txn) return next(); - const { results } = txn; + const { results } = txn; - // Check for MAIL FROM without an @ first - ignore those here + // ignore MAIL FROM without an @ if (!mail_from.host) { results.add(plugin, {skip: 'null host'}); return next(); } let called_next = 0; - const domain = mail_from.host; - const c = plugin.cfg.main; - const timeout_id = setTimeout(() => { - // DNS answer didn't return (UDP) - connection.loginfo(plugin, `timed out resolving MX for ${domain}`); + const domain = mail_from.host; + const timeout_id = setTimeout(() => { + connection.logdebug(plugin, `DNS timeout resolving MX for ${domain}`); called_next++; if (txn) results.add(plugin, {err: `timeout(${domain})`}); next(DENYSOFT, 'Temporary resolver error (timeout)'); - }, c.timeout * 1000); + }, this.cfg.main.timeout * 1000); function mxDone (code, reply) { if (called_next) return; clearTimeout(timeout_id); called_next++; - next(code, reply); + next(...arguments); } - // IS: IPv6 compatible - net_utils.get_mx(domain, (err, addresses) => { - if (!txn) return; - if (err && plugin.mxErr(connection, domain, 'MX', err, mxDone)) return; + function mxErr (err) { + if (!connection.transaction) return; + results.add(this, {err: `${domain}:${err.message}`}); + mxDone(DENYSOFT, `Temp. resolver error (${err.code})`); + } - if (!addresses || !addresses.length) { - // Check for implicit MX 0 record - return plugin.implicit_mx(connection, domain, mxDone); - } + connection.logdebug(plugin, `resolving MX for domain ${domain}`) - // Verify that the MX records resolve to valid addresses - let records = {}; - let pending_queries = 0; - function check_results () { - if (pending_queries !== 0) return; - - records = Object.keys(records); - if (records?.length) { - connection.logdebug(plugin, `${domain}: ${records}`); - results.add(plugin, {pass: 'has_fwd_dns'}); - return mxDone(); - } - results.add(plugin, {fail: 'has_fwd_dns'}); - return mxDone(((c.reject_no_mx) ? DENY : DENYSOFT), - 'MX without A/AAAA records'); - } + net_utils + .get_mx(domain) + .then((exchanges) => { + if (!txn) return; - addresses.forEach(addr => { - // Handle MX records that are IP addresses - // This is invalid - but a lot of MTAs allow it. - if (net_utils.get_ipany_re('^\\[','\\]$','').test(addr.exchange)) { - connection.logwarn(plugin, `${domain}: invalid MX ${addr.exchange}`); - if (c.allow_mx_ip) { - records[addr.exchange] = 1; - } - return; + connection.logdebug(plugin, `${domain}: MX => ${JSON.stringify(exchanges)}`) + + if (!exchanges || !exchanges.length) { + results.add(this, {fail: 'has_fwd_dns'}); + return mxDone( + ((this.cfg.reject.no_mx) ? DENY : DENYSOFT), + 'No MX for your FROM address' + ); } - pending_queries++; - net_utils.get_ips_by_host(addr.exchange, (err2, addresses2) => { - pending_queries--; - if (!txn) return; - if (err2 && err2.length === 2) { - results.add(plugin, {msg: err2[0].message}); - connection.logdebug(plugin, `${domain}: MX ${addr.priority} ${addr.exchange} => ${err2[0].message}`); - check_results(); - return; - } - connection.logdebug(plugin, `${domain}: MX ${addr.priority} ${addr.exchange} => ${addresses2}`); - for (const element of addresses2) { - // Ignore anything obviously bogus - if (net.isIPv4(element)){ - if (plugin.re_bogus_ip.test(element)) { - connection.logdebug(plugin, `${addr.exchange}: discarding ${element}`); - continue; - } + + if (this.cfg.main.allow_mx_ip) { + for (const mx of exchanges) { + if (net.isIPv4(mx.exchange) && !this.re_bogus_ip.test(mx.exchange)) { + txn.results.add(this, {pass: 'implicit_mx', emit: true}); + return mxDone() } - if (net.isIPv6(element)){ - if (net_utils.ipv6_bogus(element)) { - connection.logdebug(plugin, `${addr.exchange}: discarding ${element}`); - continue; - } + if (net.isIPv6(mx.exchange) && !net_utils.ipv6_bogus(mx.exchange)) { + txn.results.add(this, {pass: 'implicit_mx', emit: true}); + return mxDone() } - records[element] = 1; - } - check_results(); - }); - }); - // In case we don't run any queries - check_results(); - }); -} - -exports.mxErr = function (connection, domain, type, err, mxDone) { - - const txn = connection?.transaction; - if (!txn) return; - - txn.results.add(this, {msg: `${domain}:${type}:${err.message}`}); - connection.logdebug(this, `${domain}:${type} => ${err.message}`); - switch (err.code) { - case dns.NXDOMAIN: - case dns.NOTFOUND: - case dns.NODATA: - // Ignore - break; - default: - mxDone(DENYSOFT, `Temp. resolver error (${err.code})`); - return true; - } - return false; -} - -// IS: IPv6 compatible -exports.implicit_mx = function (connection, domain, mxDone) { - const txn = connection?.transaction; - if (!txn) return; - - net_utils.get_ips_by_host(domain, (err, addresses) => { - if (!txn) return; - if (!addresses || !addresses.length) { - txn.results.add(this, {fail: 'has_fwd_dns'}); - return mxDone(((this.cfg.main.reject_no_mx) ? DENY : DENYSOFT), - 'No MX for your FROM address'); - } - - connection.logdebug(this, `${domain}: A/AAAA => ${addresses}`); - let records = {}; - for (const addr of addresses) { - // Ignore anything obviously bogus - if (net.isIPv4(addr)) { - if (this.re_bogus_ip.test(addr)) { - connection.logdebug(this, `${domain}: discarding ${addr}`); - continue; - } - } - if (net.isIPv6(addr)) { - if (net_utils.ipv6_bogus(addr)) { - connection.logdebug(this, `${domain}: discarding ${addr}`); - continue; } } - records[addr] = true; - } - records = Object.keys(records); - if (records?.length) { - txn.results.add(this, {pass: 'implicit_mx'}); - return mxDone(); - } + // filter out the implicit MX and resolve the MX hostnames + net_utils + .resolve_mx_hosts(exchanges.filter(a => !net.isIP(a.exchange))) + .then(resolved => { + connection.logdebug(plugin, `resolved MX => ${JSON.stringify(resolved)}`); - txn.results.add(this, {fail: `implicit_mx(${domain})`}); - return mxDone(); - }); + for (const mx of resolved) { + if (net.isIPv4(mx.exchange) && !this.re_bogus_ip.test(mx.exchange)) { + txn.results.add(this, {pass: 'has_fwd_dns', emit: true}); + return mxDone() + } + if (net.isIPv6(mx.exchange) && !net_utils.ipv6_bogus(mx.exchange)) { + txn.results.add(this, {pass: 'has_fwd_dns', emit: true}); + return mxDone() + } + } + + mxDone( + ((this.cfg.main.reject_no_mx) ? DENY : DENYSOFT), + 'No valid MX for your FROM address' + ); + }) + .catch(mxErr) + }) + .catch(mxErr) } diff --git a/plugins/queue/deliver.js b/plugins/queue/deliver.js index 0a069b2fa..830273785 100644 --- a/plugins/queue/deliver.js +++ b/plugins/queue/deliver.js @@ -1,13 +1,12 @@ -// This plugin is now entirely redundant. The core will queue outbound mails +// This plugin is entirely redundant. The core will queue outbound mails // automatically just like this. It is kept here for backwards compatibility // purposes only. const outbound = require('./outbound'); exports.hook_queue_outbound = (next, connection) => { - if (!connection?.relaying) { - return next(); // we're not relaying so don't deliver outbound - } + // if not relaying, don't deliver outbound + if (!connection?.relaying) return next(); - outbound.send_email(connection?.transaction, next); + outbound.send_trans_email(connection?.transaction, next); } diff --git a/plugins/queue/lmtp.js b/plugins/queue/lmtp.js index 500905a6b..fad398cdd 100644 --- a/plugins/queue/lmtp.js +++ b/plugins/queue/lmtp.js @@ -19,29 +19,26 @@ exports.hook_get_mx = function (next, hmail, domain) { if (!hmail.todo.notes.using_lmtp) return next(); - const mx = { using_lmtp: true, priority: 0, exchange: '127.0.0.1' }; - const section = this.cfg[domain] || this.cfg.main; - if (section.path) { - Object.assign(mx, { path: section.path }); - return next(OK, mx); - } - Object.assign(mx, { - exchange: section.host || '127.0.0.1', - port: section.port || 24, - }); + const mx = { + using_lmtp: true, + priority: 0, + exchange: section.host ?? '127.0.0.1', + port: section.port ?? 24, + }; + + if (section.path) mx.path = section.path; - return next(OK, mx); + next(OK, mx); } exports.hook_queue = (next, connection) => { const txn = connection?.transaction; if (!txn) return next(); - const q_wants = txn.notes.get('queue.wants'); - if (q_wants && q_wants !== 'lmtp') return next(); + if (txn.notes.get('queue.wants') !== 'lmtp') return next(); txn.notes.using_lmtp = true; - outbound.send_email(txn, next); + outbound.send_trans_email(txn, next); } diff --git a/plugins/queue/rabbitmq.js b/plugins/queue/rabbitmq.js index b12c1e25a..8367607ff 100644 --- a/plugins/queue/rabbitmq.js +++ b/plugins/queue/rabbitmq.js @@ -1,5 +1,4 @@ const amqp = require('amqp'); -const logger = require('./logger'); let rabbitqueue; let exchangeName; @@ -12,41 +11,41 @@ exports.exchangeMapping = {} //This method registers the hook and try to initialize the connection to rabbitmq server for later use. exports.register = function () { - logger.logdebug("About to connect and initialize queue object"); + this.logdebug("About to connect and initialize queue object"); this.init_rabbitmq_server(); - logger.logdebug(`Finished initiating : ${exports.exchangeMapping[exchangeName + queueName]}`); + this.logdebug(`Finished initiating : ${exports.exchangeMapping[exchangeName + queueName]}`); } //Actual magic of publishing message to rabbit when email comes happen here. -exports.hook_queue = (next, connection) => { +exports.hook_queue = function (next, connection) { if (!connection?.transaction) return next(); //Calling the get_data method and when it gets the data on callback, publish the message to queue with routing key. connection.transaction.message_stream.get_data(buffere => { const exchangeData = exports.exchangeMapping[exchangeName + queueName] - logger.logdebug(`Sending the data: ${ queueName} Routing : ${exchangeData} exchange :${connExchange_}`); + this.logdebug(`Sending the data: ${ queueName} Routing : ${exchangeData} exchange :${connExchange_}`); if (connExchange_ && routing_) { //This is publish function of rabbitmq amqp library, currently direct queue is configured and routing is fixed. //Needs to be changed. connExchange_.publish(routing_, buffere,{deliveryMode}, error => { if (error) { //There was some error while sending the email to queue. - logger.logdebug("queueFailure: #{JSON.stringify(error)}"); + this.logdebug("queueFailure: #{JSON.stringify(error)}"); exports.init_rabbitmq_server(); - return next(); + next(); } else { //Queueing was successful, send ok as reply - logger.logdebug( "queueSuccess"); - return next(OK,"Successfully Queued! in rabbitmq"); + this.logdebug( "queueSuccess"); + next(OK,"Successfully Queued! in rabbitmq"); } }); } else { //Seems like connExchange is not defined , lets create one for next call exports.init_rabbitmq_server(); - return next(); + next(); } }); } @@ -88,18 +87,18 @@ exports.init_rabbitmq_server = function () { //Create connection to the rabbitmq server - logger.logdebug("About to Create connection with server"); + this.logdebug("About to Create connection with server"); rabbitqueue = amqp.createConnection(options); //Declaring listerner on error on connection. rabbitqueue.on('error', error => { - logger.logdebug(`There was some error on the connection : ${error}`); + this.logerror(`There was some error on the connection : ${error}`); }); //Declaring listerner on close on connection. rabbitqueue.on('close', close => { - logger.logdebug(` Connection is beingclosed : ${close}`); + this.logdebug(` Connection is being closed : ${close}`); }); @@ -111,16 +110,16 @@ exports.init_rabbitmq_server = function () { */ rabbitqueue.on('ready', () => { - logger.logdebug("Connection is ready, will try making exchange"); + this.logdebug("Connection is ready, will try making exchange"); // Now connection is ready will try to open exchange with config data. rabbitqueue.exchange(exchangeName, { type: exchangeType, confirm, durable }, connExchange => { - logger.logdebug(`connExchange with server ${connExchange} autoDelete : ${autoDelete}`); + this.logdebug(`connExchange with server ${connExchange} autoDelete : ${autoDelete}`); //Exchange is now open, will try to open queue. return rabbitqueue.queue(queueName,{autoDelete, durable }, connQueue => { - logger.logdebug(`connQueue with server ${connQueue}`); + this.logdebug(`connQueue with server ${connQueue}`); //Creating the Routing key to bind the queue and exchange. const routing = `${queueName}Routing`; @@ -142,7 +141,7 @@ exports.init_rabbitmq_server = function () { routing : routing_, queueName }); - logger.logdebug(`exchange: ${exchangeName}, queue: ${queueName} exchange : ${connExchange_} queue : ${connQueue_}` ); + this.logdebug(`exchange: ${exchangeName}, queue: ${queueName} exchange : ${connExchange_} queue : ${connQueue_}` ); }); }); }); diff --git a/plugins/rcpt_to.host_list_base.js b/plugins/rcpt_to.host_list_base.js index 8aeb2fcc4..e85cbd9f6 100644 --- a/plugins/rcpt_to.host_list_base.js +++ b/plugins/rcpt_to.host_list_base.js @@ -40,7 +40,7 @@ exports.hook_mail = function (next, connection, params) { const anti_spoof = this.config.get('host_list.anti_spoof') || false; - if (this.in_host_list(domain) || this.in_host_regex(domain)) { + if (this.in_host_list(domain, connection) || this.in_host_regex(domain, connection)) { if (anti_spoof && !connection.relaying) { txn.results.add(this, {fail: 'mail_from.anti_spoof'}); return next(DENY, `Mail from domain '${domain}' is not allowed from your host`); @@ -54,16 +54,16 @@ exports.hook_mail = function (next, connection, params) { return next(); } -exports.in_host_list = function (domain) { - this.logdebug(`checking ${domain} in config/host_list`); +exports.in_host_list = function (domain, connection) { + this.logdebug(connection, `checking ${domain} in config/host_list`); return !!(this.host_list[domain]); } -exports.in_host_regex = function (domain) { +exports.in_host_regex = function (domain, connection) { if (!this.host_list_regex) return false; if (!this.host_list_regex.length) return false; - this.logdebug(`checking ${domain} against config/host_list_regex `); + this.logdebug(connection, `checking ${domain} against config/host_list_regex `); return !!(this.hl_re.test(domain)); } diff --git a/plugins/rcpt_to.in_host_list.js b/plugins/rcpt_to.in_host_list.js index a595b12df..56f3e74d2 100644 --- a/plugins/rcpt_to.in_host_list.js +++ b/plugins/rcpt_to.in_host_list.js @@ -32,12 +32,12 @@ exports.hook_rcpt = function (next, connection, params) { const domain = rcpt.host.toLowerCase(); - if (this.in_host_list(domain)) { + if (this.in_host_list(domain, connection)) { txn.results.add(this, {pass: 'rcpt_to'}); return next(OK); } - if (this.in_host_regex(domain)) { + if (this.in_host_regex(domain, connection)) { txn.results.add(this, {pass: 'rcpt_to'}); return next(OK); } diff --git a/server.js b/server.js index 444bbcfc8..e2efa70c6 100644 --- a/server.js +++ b/server.js @@ -45,7 +45,7 @@ Server.load_smtp_ini = () => { }); if (Server.cfg.main.nodes === undefined) { - logger.logwarn(`smtp.ini.nodes unset, using 1, see https://github.com/haraka/Haraka/wiki/Performance-Tuning`) + logger.warn(`smtp.ini.nodes unset, using 1, see https://github.com/haraka/Haraka/wiki/Performance-Tuning`) } const defaults = { @@ -62,7 +62,7 @@ Server.load_smtp_ini = () => { const strict_ext = Server.config.get('strict_rfc1869'); if (Server.cfg.main.strict_rfc1869 === false && strict_ext) { - logger.logwarn(`legacy config config/strict_rfc1869 is overriding smtp.ini`) + logger.warn(`legacy config config/strict_rfc1869 is overriding smtp.ini`) Server.cfg.main.strict_rfc1869 = strict_ext; } @@ -93,7 +93,7 @@ Server.daemonize = function () { // Remove process.on('exit') listeners otherwise // we get a spurious 'Exiting' log entry. process.removeAllListeners('exit'); - logger.lognotice('Daemonizing...'); + logger.notice('Daemonizing...'); } const log_fd = fs.openSync(c.daemon_log_file, 'a'); @@ -105,7 +105,7 @@ Server.daemonize = function () { npid.create(c.daemon_pid_file).removeOnExit(); } catch (err) { - logger.logerror(err.message); + logger.error(err.message); logger.dump_and_exit(1); } } @@ -128,7 +128,7 @@ Server.gracefulRestart = () => { } Server.stopListeners = () => { - logger.loginfo('Shutting down listeners'); + logger.info('Shutting down listeners'); Server.listeners.forEach(server => { server.close(); }); @@ -139,7 +139,7 @@ Server.performShutdown = () => { if (Server.cfg.main.graceful_shutdown) { return Server.gracefulShutdown(); } - logger.loginfo("Shutting down."); + logger.info("Shutting down."); process.exit(0); } @@ -147,7 +147,7 @@ Server.gracefulShutdown = () => { Server.stopListeners(); Server._graceful(() => { // log(); - logger.loginfo("Failed to shutdown naturally. Exiting."); + logger.info("Failed to shutdown naturally. Exiting."); process.exit(0); }); } @@ -162,7 +162,7 @@ Server._graceful = shutdown => { } if (gracefull_in_progress) { - logger.lognotice("Restart currently in progress - ignoring request"); + logger.notice("Restart currently in progress - ignoring request"); return; } @@ -178,7 +178,7 @@ Server._graceful = shutdown => { let limit = worker_ids.length - 1; if (limit < 2) limit = 1; async.eachLimit(worker_ids, limit, (id, cb) => { - logger.lognotice(`Killing node: ${id}`); + logger.notice(`Killing node: ${id}`); const worker = cluster.workers[id]; ['outbound', 'cfreader', 'plugins'].forEach(module => { worker.send({event: `${module }.shutdown`}); @@ -187,18 +187,18 @@ Server._graceful = shutdown => { let disconnect_received = false; const disconnect_timer = setTimeout(() => { if (!disconnect_received) { - logger.logcrit("Disconnect never received by worker. Killing."); + logger.crit("Disconnect never received by worker. Killing."); worker.kill(); } }, disconnect_timeout * 1000); worker.once("disconnect", () => { clearTimeout(disconnect_timer); disconnect_received = true; - logger.lognotice("Disconnect complete"); + logger.notice("Disconnect complete"); let dead = false; const timer = setTimeout(() => { if (!dead) { - logger.logcrit(`Worker ${id} failed to shutdown. Killing.`); + logger.crit(`Worker ${id} failed to shutdown. Killing.`); worker.kill(); } }, exit_timeout * 1000); @@ -211,7 +211,7 @@ Server._graceful = shutdown => { if (shutdown) return; const newWorker = cluster.fork(); newWorker.once("listening", () => { - logger.lognotice("Replacement worker online."); + logger.notice("Replacement worker online."); newWorker.on('exit', (code, signal) => { cluster_exit_listener(newWorker, code, signal); }); @@ -219,9 +219,9 @@ Server._graceful = shutdown => { }); }, err => { // err can basically never happen, but fuckit... - if (err) logger.logerror(err); + if (err) logger.error(err); if (shutdown) { - logger.loginfo("Workers closed. Shutting down master process subsystems"); + logger.info("Workers closed. Shutting down master process subsystems"); ['outbound', 'cfreader', 'plugins'].forEach(module => { process.emit('message', {event: `${module }.shutdown`}); }) @@ -229,7 +229,7 @@ Server._graceful = shutdown => { return t2.unref(); } gracefull_in_progress = false; - logger.lognotice(`Reload complete, workers: ${JSON.stringify(Object.keys(cluster.workers))}`); + logger.notice(`Reload complete, workers: ${JSON.stringify(Object.keys(cluster.workers))}`); }); } @@ -250,7 +250,7 @@ Server.sendToMaster = (command, params) => { Server.receiveAsMaster = (command, params) => { if (!Server[command]) { - logger.logerror(`Invalid command: ${command}`); + logger.error(`Invalid command: ${command}`); return; } Server[command].apply(Server, params); @@ -338,7 +338,7 @@ Server.createServer = params => { Server.load_default_tls_config = done => { // this fn exists solely for testing if (Server.config.root_path != tls_socket.config.root_path) { - logger.loginfo(`resetting tls_config.config path to ${Server.config.root_path}`); + logger.info(`resetting tls_config.config path to ${Server.config.root_path}`); tls_socket.config = tls_socket.config.module_config(path.dirname(Server.config.root_path)); } tls_socket.getSocketOpts('*', (opts) => { @@ -367,9 +367,9 @@ Server.get_smtp_server = (ep, inactivity_timeout, done) => { } if (ep.port === parseInt(Server.cfg.main.smtps_port, 10)) { - logger.loginfo('getting SocketOpts for SMTPS server'); + logger.info('getting SocketOpts for SMTPS server'); tls_socket.getSocketOpts('*', opts => { - logger.loginfo(`Creating TLS server on ${ep}`); + logger.info(`Creating TLS server on ${ep}`); opts.rejectUnauthorized = tls_socket.get_rejectUnauthorized(opts.rejectUnauthorized, ep.port, tls_socket.cfg.main.requireAuthorized) @@ -377,7 +377,7 @@ Server.get_smtp_server = (ep, inactivity_timeout, done) => { tls_socket.addOCSP(server); server.has_tls=true; server.on('resumeSession', (id, rsDone) => { - logger.loginfo('client requested TLS resumeSession'); + logger.info('client requested TLS resumeSession'); rsDone(null, null); }) Server.listeners.push(server); @@ -414,11 +414,11 @@ Server.setup_smtp_listeners = (plugins2, type, inactivity_timeout) => { server .on('listening', function () { const addr = this.address(); - logger.lognotice(`Listening on ${endpoint(addr)}`); + logger.notice(`Listening on ${endpoint(addr)}`); listenerDone(); }) .on('close', () => { - logger.loginfo(`Listener ${ep} stopped`); + logger.info(`Listener ${ep} stopped`); }) .on('error', e => { if (e.code !== 'EAFNOSUPPORT') return listenerDone(e); @@ -436,7 +436,7 @@ Server.setup_smtp_listeners = (plugins2, type, inactivity_timeout) => { }, function runInitHooks (err) { if (err) { - logger.logerror(`Failed to setup listeners: ${err.message}`); + logger.error(`Failed to setup listeners: ${err.message}`); return logger.dump_and_exit(-1); } Server.listening(); @@ -454,17 +454,17 @@ Server.setup_http_listeners = () => { try { Server.http.express = require('express'); - logger.loginfo('express loaded at Server.http.express'); + logger.info('express loaded at Server.http.express'); } catch (err) { - logger.logerror('express failed to load. No http server. ' + + logger.error('express failed to load. No http server. ' + ' Try installing express with: npm install -g express'); return; } const app = Server.http.express(); Server.http.app = app; - logger.loginfo('express app is at Server.http.app'); + logger.info('express app is at Server.http.app'); function setupListener (listen_address, cb) { const ep = endpoint(listen_address, 80); @@ -487,12 +487,12 @@ Server.setup_http_listeners = () => { Server.http.server.on('listening', function () { const addr = this.address(); - logger.lognotice(`Listening on ${endpoint(addr)}`); + logger.notice(`Listening on ${endpoint(addr)}`); cb(); }); Server.http.server.on('error', e => { - logger.logerror(e); + logger.error(e); cb(e); }); @@ -501,7 +501,7 @@ Server.setup_http_listeners = () => { function registerRoutes (err) { if (err) { - logger.logerror(`Failed to setup http routes: ${err.message}`); + logger.error(`Failed to setup http routes: ${err.message}`); } Server.plugins.run_hooks('init_http', Server); @@ -547,13 +547,13 @@ Server.init_master_respond = (retval, msg) => { .send({event: 'outbound.load_pid_queue', data: pids[j]}); } cluster.on('online', worker => { - logger.lognotice( + logger.notice( 'worker started', { worker: worker.id, pid: worker.process.pid } ); }); cluster.on('listening', (worker, address) => { - logger.lognotice(`worker ${worker.id} listening on ${endpoint(address)}`); + logger.notice(`worker ${worker.id} listening on ${endpoint(address)}`); }); cluster.on('exit', cluster_exit_listener); }); @@ -561,10 +561,10 @@ Server.init_master_respond = (retval, msg) => { function cluster_exit_listener (worker, code, signal) { if (signal) { - logger.lognotice(`worker ${worker.id} killed by signal ${signal}`); + logger.notice(`worker ${worker.id} killed by signal ${signal}`); } else if (code !== 0) { - logger.lognotice(`worker ${worker.id} exited with error code: ${code}`); + logger.notice(`worker ${worker.id} exited with error code: ${code}`); } if (signal || code !== 0) { // Restart worker @@ -618,36 +618,36 @@ Server.listening = () => { } Server.init_http_respond = () => { - logger.loginfo('init_http_respond'); + logger.info('init_http_respond'); let WebSocketServer; try { WebSocketServer = require('ws').Server; } catch (e) { - logger.logerror(`unable to load ws.\n did you: npm install -g ws?`); + logger.error(`unable to load ws.\n did you: npm install -g ws?`); return; } if (!WebSocketServer) { - logger.logerror('ws failed to load'); + logger.error('ws failed to load'); return; } Server.http.wss = new WebSocketServer({ server: Server.http.server }); - logger.loginfo('Server.http.wss loaded'); + logger.info('Server.http.wss loaded'); Server.plugins.run_hooks('init_wss', Server); } Server.init_wss_respond = () => { - logger.loginfo('init_wss_respond'); - // logger.logdebug(arguments); + logger.info('init_wss_respond'); + // logger.debug(arguments); } Server.get_http_docroot = () => { if (Server.http.cfg.docroot) return Server.http.cfg.docroot; Server.http.cfg.docroot = path.join( (process.env.HARAKA || __dirname), '/html'); - logger.loginfo(`using html docroot: ${Server.http.cfg.docroot}`); + logger.info(`using html docroot: ${Server.http.cfg.docroot}`); return Server.http.cfg.docroot; } diff --git a/smtp_client.js b/smtp_client.js index 396d8191c..2fb8f710d 100644 --- a/smtp_client.js +++ b/smtp_client.js @@ -66,7 +66,7 @@ class SMTPClient extends events.EventEmitter { if (cont !== ' ') return; if (client.command === 'auth' || client.authenticating) { - logger.loginfo(`SERVER RESPONSE, CLIENT ${client.command}, authenticating=${client.authenticating},code=${code},cont=${cont},msg=${msg}`); + logger.info(`SERVER RESPONSE, CLIENT ${client.command}, authenticating=${client.authenticating},code=${code},cont=${cont},msg=${msg}`); if (/^3/.test(code) && ( msg === 'VXNlcm5hbWU6' || msg === 'dXNlcm5hbWU6' // Workaround ill-mannered SMTP servers (namely smtp.163.com) @@ -79,7 +79,7 @@ class SMTPClient extends events.EventEmitter { return; } if (/^2/.test(code) && client.authenticating) { - logger.loginfo('AUTHENTICATED'); + logger.info('AUTHENTICATED'); client.authenticating = false; client.authenticated = true; client.emit('auth'); @@ -155,7 +155,7 @@ class SMTPClient extends events.EventEmitter { client.socket.setTimeout((opts.idle_timeout || 300) * 1000); if (!client.socket.remoteAddress) { // "Value may be undefined if the socket is destroyed" - logger.logdebug('socket.remoteAddress undefined'); + logger.debug('socket.remoteAddress undefined'); return; } client.remote_ip = ipaddr.process(client.socket.remoteAddress).toString(); @@ -184,7 +184,7 @@ class SMTPClient extends events.EventEmitter { default: } - logger.logdebug(`[smtp_client] ${errMsg} (state=${client.state})`); + logger.debug(`[smtp_client] ${errMsg} (state=${client.state})`); } } @@ -220,7 +220,7 @@ class SMTPClient extends events.EventEmitter { release () { if (this.state === STATE.DESTROYED) return; - logger.logdebug(`[smtp_client] ${this.uuid} releasing, state=${this.state}`); + logger.debug(`[smtp_client] ${this.uuid} releasing, state=${this.state}`); [ 'auth', 'bad_code', 'capabilities', 'client_protocol', 'connection-error', @@ -243,7 +243,7 @@ class SMTPClient extends events.EventEmitter { upgrade (tls_options) { this.socket.upgrade(tls_options, (verified, verifyError, cert, cipher) => { - logger.loginfo(`secured:${ + logger.info(`secured:${ (cipher) ? ` cipher=${cipher.name} version=${cipher.version}` : '' } verified=${verified}${ @@ -271,7 +271,7 @@ exports.smtp_client = SMTPClient; // used only in testing exports.get_client = (server, callback, opts = {}) => { const smtp_client = new SMTPClient(opts) - logger.logdebug(`[smtp_client] uuid=${smtp_client.uuid} host=${opts.host} port=${opts.port} created`) + logger.debug(`[smtp_client] uuid=${smtp_client.uuid} host=${opts.host} port=${opts.port} created`) callback(smtp_client) } @@ -336,7 +336,7 @@ exports.get_client_plugin = (plugin, connection, c, callback) => { const hostport = get_hostport(connection, connection.server, c); const smtp_client = new SMTPClient(hostport) - logger.loginfo(`[smtp_client] uuid=${smtp_client.uuid} host=${hostport.host} port=${hostport.port} created`); + logger.info(`[smtp_client] uuid=${smtp_client.uuid} host=${hostport.host} port=${hostport.port} created`); connection.logdebug(plugin, `Got smtp_client: ${smtp_client.uuid}`); @@ -400,7 +400,7 @@ exports.get_client_plugin = (plugin, connection, c, callback) => { if (!c.auth.user || !c.auth.pass) { throw new Error("Must include auth.user and auth.pass for PLAIN auth."); } - logger.logdebug(`[smtp_client] uuid=${smtp_client.uuid} authenticating as "${c.auth.user}"`); + logger.debug(`[smtp_client] uuid=${smtp_client.uuid} authenticating as "${c.auth.user}"`); smtp_client.send_command('AUTH', `PLAIN ${utils.base64(`${c.auth.user}\0${c.auth.user}\0${c.auth.pass}`)}`); break; case 'cram-md5': @@ -429,7 +429,7 @@ exports.get_client_plugin = (plugin, connection, c, callback) => { // these are the errors thrown when the connection is dead smtp_client.on('connection-error', (error) => { // error contains e.g. "Error: connect ECONNREFUSE" - logger.logerror(`backend failure: ${smtp_client.host}:${smtp_client.port} - ${error}`); + logger.error(`backend failure: ${smtp_client.host}:${smtp_client.port} - ${error}`); const { host_pool } = connection.server.notes; // only exists for if forwarding_host_pool is set in the config if (host_pool) { @@ -465,12 +465,12 @@ function get_hostport (connection, server, cfg) { const host = server.notes.host_pool.get_host(); if (host) return host; // { host: 1.2.3.4, port: 567 } - logger.logerror('[smtp_client] no backend hosts in pool!'); + logger.error('[smtp_client] no backend hosts in pool!'); throw new Error("no backend hosts found in pool!"); } if (cfg.host && cfg.port) return { host: cfg.host, port: cfg.port }; - logger.logwarn("[smtp_client] forwarding_host_pool or host and port were not found in config file"); + logger.warn("[smtp_client] forwarding_host_pool or host and port were not found in config file"); throw new Error("You must specify either forwarding_host_pool or host and port"); } diff --git a/tests/fixtures/util_hmailitem.js b/tests/fixtures/util_hmailitem.js index 659a9d718..5a1302a39 100644 --- a/tests/fixtures/util_hmailitem.js +++ b/tests/fixtures/util_hmailitem.js @@ -38,7 +38,7 @@ exports.newMockHMailItem = (outbound_context, test, options, callback) => { /** * Creates a HMailItem instance for testing purpose * - * @param outbound_context: The context of the outbound.js, e.g. from require('nodeunit').utils.sandbox("outbound.js") + * @param outbound_context: The context of outbound, e.g. from require('outbound/index.js') * @param options * @param callback(err, hmail) */ diff --git a/tests/outbound/hmail.js b/tests/outbound/hmail.js index 754bdd699..f6ba48f17 100644 --- a/tests/outbound/hmail.js +++ b/tests/outbound/hmail.js @@ -1,12 +1,11 @@ +const assert = require('assert') const fs = require('fs') const path = require('path') const Hmail = require('../../outbound/hmail'); const outbound = require('../../outbound/index'); -// const fixtures = path.resolve('tests', 'fixtures'); - exports.HMailItem = { 'normal queue file' (test) { test.expect(1); @@ -72,7 +71,7 @@ exports.HMailItem = { test.done(); }) this.hmail.on('error', (err) => { - console.log(err); + console.error(err); test.ok(err); test.done(); }) @@ -110,3 +109,37 @@ exports.HMailItem = { }) }, } + +exports.hmail = { + setUp: function (done) { + this.hmail = new Hmail('1508455115683_1508455115683_0_90253_9Q4o4V_1_haraka', 'tests/queue/1508455115683_1508455115683_0_90253_9Q4o4V_1_haraka', {}); + done() + }, + 'sort_mx' (test) { + const sorted = this.hmail.sort_mx([ + { exchange: 'mx2.example.com', priority: 5 }, + { exchange: 'mx1.example.com', priority: 6 }, + ]) + assert.equal(sorted[0].exchange, 'mx2.example.com') + test.done() + }, + 'sort_mx, shuffled' (test) { + const sorted = this.hmail.sort_mx([ + { exchange: 'mx2.example.com', priority: 5 }, + { exchange: 'mx1.example.com', priority: 6 }, + { exchange: 'mx3.example.com', priority: 6 }, + ]) + assert.equal(sorted[0].exchange, 'mx2.example.com') + assert.ok(sorted[1].exchange == 'mx3.example.com' || sorted[1].exchange == 'mx1.example.com') + test.done() + }, + 'force_tls' (test) { + this.hmail.todo = { domain: 'miss.example.com' } + this.hmail.obtls.cfg = { force_tls_hosts: ['1.2.3.4', 'hit.example.com'] } + assert.equal(this.hmail.get_force_tls({ exchange: '1.2.3.4' }), true) + assert.equal(this.hmail.get_force_tls({ exchange: '1.2.3.5' }), false) + this.hmail.todo = { domain: 'hit.example.com' } + assert.equal(this.hmail.get_force_tls({ exchange: '1.2.3.5' }), true) + test.done() + } +} \ No newline at end of file diff --git a/tests/outbound/index.js b/tests/outbound/index.js index f5e261040..1ecbf6035 100644 --- a/tests/outbound/index.js +++ b/tests/outbound/index.js @@ -20,7 +20,7 @@ exports.outbound = { 'converts \\n and \\r\\n line endings to \\r\\n' : test => { test.expect(2); - ['\n', '\r\n'].forEach(ending => { + for (const ending of ['\n', '\r\n']) { let contents = lines.join(ending); let result = ''; @@ -39,17 +39,18 @@ exports.outbound = { } test.deepEqual(lines.join('\r\n'), result); - }); + } test.done(); }, 'log_methods added': test => { - test.expect(Object.keys(logger.levels).length); + const levels = ['DATA','PROTOCOL','DEBUG','INFO','NOTICE','WARN','ERROR','CRIT','ALERT','EMERG'] + test.expect(levels.length); const HMailItem = require('../../outbound/hmail'); - Object.keys(logger.levels).forEach(level => { + for (const level of levels) { test.ok(HMailItem.prototype[`log${level.toLowerCase()}`], `Log method for level: ${level}`); - }); + } test.done(); }, 'set_temp_fail_intervals coverage': test => { diff --git a/tests/outbound/mx_lookup.js b/tests/outbound/mx_lookup.js deleted file mode 100644 index c64edcf4e..000000000 --- a/tests/outbound/mx_lookup.js +++ /dev/null @@ -1,61 +0,0 @@ - -const mx = require('../../outbound/mx_lookup'); - -exports.lookup_mx = { - 'MX records for example.com (await)': async test => { - test.expect(1) - const r = await mx.lookup_mx('example.com'); - test.deepEqual(r, [ { exchange: '', priority: 0 }]) - test.done() - }, - 'MX records for example.com (cb)': test => { - test.expect(1) - mx.lookup_mx('example.com', (err, r) => { - test.deepEqual(r, [ { exchange: '', priority: 0 }]) - test.done() - }); - }, - 'MX records for tnpi.net (await)': async test => { - test.expect(1) - const r = await mx.lookup_mx('tnpi.net'); - test.deepEqual(r, [ { exchange: 'mail.theartfarm.com', priority: 10 }]) - test.done() - }, - 'MX records for tnpi.net (cb)': test => { - test.expect(1) - mx.lookup_mx('tnpi.net', (err, r) => { - test.deepEqual(r, [ { exchange: 'mail.theartfarm.com', priority: 10 }]) - test.done() - }); - }, - 'MX records for gmail.com (await)': async test => { - test.expect(1) - const r = await mx.lookup_mx('gmail.com'); - // console.log(r) - test.ok(r.length) - test.done() - }, - 'MX records for gmail.com (callback)': test => { - test.expect(1) - mx.lookup_mx('gmail.com', (err, r) => { - test.ok(r.length) - test.done() - }); - }, - 'MX records for no-mx.tnpi.net (await)': async test => { - test.expect(2) - const r = await mx.lookup_mx('no-mx.tnpi.net'); - // console.log(r) - test.equal(r.length, 1) // the A record - test.equal(r[0].exchange, '192.0.99.5') - test.done() - }, - 'MX records for no-mx.tnpi.net (callback)': test => { - test.expect(2) - mx.lookup_mx('no-mx.tnpi.net', (err, r) => { - test.equal(r.length, 1) // the A record - test.equal(r[0].exchange, '192.0.99.5') - test.done() - }); - }, -} diff --git a/tests/outbound_bounce_net_errors.js b/tests/outbound_bounce_net_errors.js index cac5f9124..2711000b5 100644 --- a/tests/outbound_bounce_net_errors.js +++ b/tests/outbound_bounce_net_errors.js @@ -32,12 +32,7 @@ exports.bounce_3464 = { done(); } else { - fs.mkdir(queue_dir, err => { - if (err) { - return done(err); - } - done(); - }); + fs.mkdir(queue_dir, done) } }); }, @@ -55,11 +50,8 @@ exports.bounce_3464 = { const curPath = path.resolve(queue_dir, file); fs.unlinkSync(curPath); }); - done(); - } - else { - done(); } + done(); }); }, 'test get-mx-deny triggers bounce(...)': test => { @@ -104,38 +96,24 @@ exports.bounce_3464 = { util_hmailitem.newMockHMailItem(outbound_context, test, {}, mock_hmail => { const orig_bounce = HMailItem.prototype.bounce; HMailItem.prototype.bounce = function (err, opts) { - test.ok(true, 'found_mx({code: dns.NXDOMAIN}): bounce function called'); - test.equal('5.1.2', this.todo.rcpt_to[0].dsn_status, 'found_mx({code: dns.NXDOMAIN}: dsn status = 5.1.2'); + test.ok(true, 'get_mx_error({code: dns.NXDOMAIN}): bounce function called'); + test.equal('5.1.2', this.todo.rcpt_to[0].dsn_status, 'get_mx_error({code: dns.NXDOMAIN}: dsn status = 5.1.2'); }; - HMailItem.prototype.found_mx.apply(mock_hmail, [{code: dns.NXDOMAIN}, {}]); + HMailItem.prototype.get_mx_error.apply(mock_hmail, [{code: dns.NXDOMAIN}]); HMailItem.prototype.bounce = orig_bounce; test.done(); }); }, - 'test found_mx({code:\'NOMX\'}) triggers bounce(...)': test => { - test.expect(2); - - util_hmailitem.newMockHMailItem(outbound_context, test, {}, mock_hmail => { - const orig_bounce = HMailItem.prototype.bounce; - HMailItem.prototype.bounce = function (err, opts) { - test.ok(true, 'found_mx({code: "NOMX"}): bounce function called'); - test.equal('5.1.2', this.todo.rcpt_to[0].dsn_status, 'found_mx({code: "NOMX"}: dsn status = 5.1.2'); - }; - HMailItem.prototype.found_mx.apply(mock_hmail, [{code: 'NOMX'}, {}]); - HMailItem.prototype.bounce = orig_bounce; - test.done(); - }); - }, - 'test found_mx({code:\'SOME-OTHER-ERR\'}) triggers temp_fail(...)': test => { + 'test get_mx_error({code:\'SOME-OTHER-ERR\'}) triggers temp_fail(...)': test => { test.expect(2); util_hmailitem.newMockHMailItem(outbound_context, test, {}, mock_hmail => { const orig_temp_fail = HMailItem.prototype.temp_fail; HMailItem.prototype.temp_fail = function (err, opts) { - test.ok(true, 'found_mx({code: "SOME-OTHER-ERR"}): temp_fail function called'); - test.equal('4.1.0', this.todo.rcpt_to[0].dsn_status, 'found_mx({code: "SOME-OTHER-ERR"}: dsn status = 4.1.0'); + test.ok(true, 'get_mx_error({code: "SOME-OTHER-ERR"}): temp_fail function called'); + test.equal('4.1.0', this.todo.rcpt_to[0].dsn_status, 'get_mx_error({code: "SOME-OTHER-ERR"}: dsn status = 4.1.0'); }; - HMailItem.prototype.found_mx.apply(mock_hmail, [{code: 'SOME-OTHER-ERR'}, {}]); + HMailItem.prototype.get_mx_error.apply(mock_hmail, [{code: 'SOME-OTHER-ERR'}, {}]); HMailItem.prototype.temp_fail = orig_temp_fail; test.done(); }); @@ -143,14 +121,13 @@ exports.bounce_3464 = { 'test found_mx(null, [{priority:0,exchange:\'\'}]) triggers bounce(...)': test => { test.expect(2); - util_hmailitem.newMockHMailItem(outbound_context, test, {}, mock_hmail => { const orig_bounce = HMailItem.prototype.bounce; HMailItem.prototype.bounce = function (err, opts) { test.ok(true, 'found_mx(null, [{priority:0,exchange:""}]): bounce function called'); test.equal('5.1.2', this.todo.rcpt_to[0].dsn_status, 'found_mx(null, [{priority:0,exchange:""}]): dsn status = 5.1.2'); }; - HMailItem.prototype.found_mx.apply(mock_hmail, [null, [{priority:0,exchange:''}]]); + HMailItem.prototype.found_mx.apply(mock_hmail, [[{priority:0,exchange:''}]]); HMailItem.prototype.bounce = orig_bounce; test.done(); }); diff --git a/tests/plugins/mail_from.is_resolvable.js b/tests/plugins/mail_from.is_resolvable.js index 992b6fead..a4a5dd7df 100644 --- a/tests/plugins/mail_from.is_resolvable.js +++ b/tests/plugins/mail_from.is_resolvable.js @@ -1,7 +1,8 @@ 'use strict'; -const fixtures = require('haraka-test-fixtures'); -const dns = require('dns'); +const fixtures = require('haraka-test-fixtures'); +const dns = require('dns'); +const Address = require('address-rfc2821').Address const _set_up = function (done) { @@ -9,108 +10,23 @@ const _set_up = function (done) { this.plugin.register(); this.connection = fixtures.connection.createConnection(); - - this.connection.transaction = { - notes: {}, - results: new fixtures.results(this.plugin), - }; + this.connection.init_transaction() done(); } -exports.mxErr = { +exports.hook_mail = { setUp : _set_up, 'any.com, no err code' (test) { - test.expect(3); - const txn = this.connection.transaction; - const err = new Error('oops'); - err.code = null; - let called = false; - function cb () { called = true; } - const r = this.plugin.mxErr(this.connection, 'any.com', 'MX', err, cb); - test.equal(r, true); - test.equal(called, true); - const mf = txn.results.get('mail_from.is_resolvable'); - test.equal(mf.msg[0], 'any.com:MX:oops'); - test.done(); - }, - 'any.com, bypass err code' (test) { - test.expect(3); - const txn = this.connection.transaction; - const err = new Error('oops'); - err.code=dns.NOTFOUND; - let called = false; - function cb () { called = true; } - const r = this.plugin.mxErr(this.connection, 'any.com', 'MX', err, cb); - test.equal(r, false); - test.equal(called, false); - const mf = txn.results.get('mail_from.is_resolvable'); - test.equal(mf.msg[0], 'any.com:MX:oops'); - test.done(); - } -} - -exports.implicit_mx = { - setUp : _set_up, - 'tnpi.net' (test) { - test.expect(2); - const txn = this.connection.transaction; - this.plugin.implicit_mx(this.connection, 'tnpi.net', err => { - test.equal(err, undefined); - const mf = txn.results.get('mail_from.is_resolvable'); - test.equal(mf.pass.length, 1); - test.done(); - }); - }, - 'harakamail.com' (test) { - test.expect(1); - const txn = this.connection.transaction; - this.plugin.implicit_mx(this.connection, 'harakamail.com', () => { - // console.log(arguments); - const mf = txn.results.get('mail_from.is_resolvable'); - // console.log(mf); - test.equal(mf.pass.length, 1); - test.done(); - }); - }, - 'mx.theartfarm.com' (test) { - test.expect(1); - const txn = this.connection.transaction; - this.plugin.implicit_mx(this.connection, 'mx.theartfarm.com', () => { - const mf = txn.results.get('mail_from.is_resolvable'); - // console.log(mf); - test.equal(mf.fail.length, 1); - test.done(); - }); - }, - 'resolve-fail-definitive.josef-froehle.de' (test) { - test.expect(1); - const txn = this.connection.transaction; - this.plugin.implicit_mx(this.connection, 'resolve-fail-definitive.josef-froehle.de', () => { - const mf = txn.results.get('mail_from.is_resolvable'); - //console.log(mf); - test.equal(mf.fail.length, 1); - test.done(); - }); - }, - 'resolve-fail-a.josef-froehle.de' (test) { - test.expect(1); - const txn = this.connection.transaction; - this.plugin.implicit_mx(this.connection, 'resolve-fail-a.josef-froehle.de', () => { - const mf = txn.results.get('mail_from.is_resolvable'); - //console.log(mf); - test.equal(mf.fail.length, 1); - test.done(); - }); - }, - 'resolve-fail-aaaa.josef-froehle.de' (test) { test.expect(1); const txn = this.connection.transaction; - this.plugin.implicit_mx(this.connection, 'resolve-fail-aaaa.josef-froehle.de', () => { - const mf = txn.results.get('mail_from.is_resolvable'); - //console.log(mf); - test.equal(mf.fail.length, 1); + this.plugin.hook_mail((code, msg) => { + console.log() + test.deepEqual(txn.results.get('mail_from.is_resolvable').pass, ['has_fwd_dns']); test.done(); - }); + }, + this.connection, + [new Address('')] + ); }, } diff --git a/tls_socket.js b/tls_socket.js index f82e1ffa6..b4884c46d 100644 --- a/tls_socket.js +++ b/tls_socket.js @@ -173,13 +173,13 @@ exports.parse_x509_names = string => { // of names extracted from the Subject CN and the v3 Subject Alternate Names const names_found = []; - // log.loginfo(string); + // log.info(string); let match = /Subject:.*?CN=([^/\s]+)/.exec(string); if (match) { - // log.loginfo(match[0]); + // log.info(match[0]); if (match[1]) { - // log.loginfo(match[1]); + // log.info(match[1]); names_found.push(match[1]); } } @@ -189,7 +189,7 @@ exports.parse_x509_names = string => { let dns_name; const re = /DNS:([^,]+)[,\n]/g; while ((dns_name = re.exec(match[0])) !== null) { - // log.loginfo(dns_name); + // log.info(dns_name); if (names_found.includes(dns_name[1])) continue; // ignore dupes names_found.push(dns_name[1]); } @@ -203,7 +203,7 @@ exports.parse_x509_expire = (file, string) => { const dateMatch = /Not After : (.*)/.exec(string); if (!dateMatch) return; - // log.loginfo(dateMatch[1]); + // log.info(dateMatch[1]); return new Date(dateMatch[1]); } @@ -224,7 +224,7 @@ exports.parse_x509 = string => { exports.load_tls_ini = (opts) => { - log.loginfo(`loading tls.ini`); // from ${this.config.root_path}`); + log.info(`loading tls.ini`); // from ${this.config.root_path}`); const cfg = exports.config.get('tls.ini', { booleans: [ @@ -253,18 +253,18 @@ exports.load_tls_ini = (opts) => { if (cfg.mutual_auth_hosts_exclude === undefined) cfg.mutual_auth_hosts_exclude = {}; if (cfg.main.enableOCSPStapling !== undefined) { - log.logerror('deprecated setting enableOCSPStapling in tls.ini'); + log.error('deprecated setting enableOCSPStapling in tls.ini'); cfg.main.requestOCSP = cfg.main.enableOCSPStapling; } if (ocsp === undefined && cfg.main.requestOCSP) { try { ocsp = require('ocsp'); - log.logdebug('ocsp loaded'); + log.debug('ocsp loaded'); ocspCache = new ocsp.Cache(); } catch (ignore) { - log.lognotice("OCSP Stapling not available."); + log.notice("OCSP Stapling not available."); } } @@ -357,12 +357,12 @@ exports.load_default_opts = () => { const cfg = certsByHost['*']; if (cfg.dhparam && typeof cfg.dhparam === 'string') { - log.logdebug(`loading dhparams from ${cfg.dhparam}`); + log.debug(`loading dhparams from ${cfg.dhparam}`); this.saveOpt('*', 'dhparam', this.config.get(cfg.dhparam, 'binary')); } if (cfg.ca && typeof cfg.ca === 'string') { - log.loginfo(`loading CA certs from ${cfg.ca}`); + log.info(`loading CA certs from ${cfg.ca}`); this.saveOpt('*', 'ca', this.config.get(cfg.ca, 'binary')); } @@ -371,7 +371,7 @@ exports.load_default_opts = () => { if (!(Array.isArray(cfg.cert))) cfg.cert = [cfg.cert]; if (cfg.key.length != cfg.cert.length) { - log.logerror(`number of keys (${cfg.key.length}) not equal to certs (${cfg.cert.length}).`); + log.error(`number of keys (${cfg.key.length}) not equal to certs (${cfg.cert.length}).`); } // if key file has already been loaded, it'll be a Buffer. @@ -381,7 +381,7 @@ exports.load_default_opts = () => { if (!keyFileName) return; const key = this.config.get(keyFileName, 'binary'); if (!key) { - log.logerror(`tls key ${path.join(this.config.root_path, keyFileName)} could not be loaded.`); + log.error(`tls key ${path.join(this.config.root_path, keyFileName)} could not be loaded.`); } return key; }) @@ -393,7 +393,7 @@ exports.load_default_opts = () => { if (!certFileName) return; const cert = this.config.get(certFileName, 'binary'); if (!cert) { - log.logerror(`tls cert ${path.join(this.config.root_path, certFileName)} could not be loaded.`); + log.error(`tls cert ${path.join(this.config.root_path, certFileName)} could not be loaded.`); } return cert; }) @@ -411,7 +411,7 @@ exports.load_default_opts = () => { } function SNICallback (servername, sniDone) { - log.logdebug(`SNI servername: ${servername}`); + log.debug(`SNI servername: ${servername}`); if (ctxByHost[servername] === undefined) servername = '*'; @@ -443,13 +443,13 @@ exports.get_certs_dir = (tlsDir, done) => { openssl('x509', parsed.cert, x509args, (e, as_str) => { if (e) { - log.logerror(`BAD TLS in ${file.path}`); - log.logerror(e); + log.error(`BAD TLS in ${file.path}`); + log.error(e); } const expire = this.parse_x509_expire(file, as_str); if (expire && expire < new Date()) { - log.logerror(`${file.path} expired on ${expire}`); + log.error(`${file.path} expired on ${expire}`); } iter_done(null, { @@ -464,22 +464,22 @@ exports.get_certs_dir = (tlsDir, done) => { }, (finalErr, certs) => { - if (finalErr) log.logerror(finalErr); + if (finalErr) log.error(finalErr); if (!certs || !certs.length) { - log.loginfo('found 0 TLS certs in config/tls'); + log.info('found 0 TLS certs in config/tls'); return done(null, certs); } - log.loginfo(`found ${certs.length} TLS certs in config/tls`); + log.info(`found ${certs.length} TLS certs in config/tls`); certs.forEach(cert => { if (undefined === cert) return; if (cert.err) { - log.logerror(`${cert.file} had error: ${cert.err.message}`); + log.error(`${cert.file} had error: ${cert.err.message}`); return; } - // log.logdebug(cert); // DANGER: Also logs private key! + // log.debug(cert); // DANGER: Also logs private key! cert.names.forEach(name => { this.applySocketOpts(name); @@ -495,7 +495,7 @@ exports.get_certs_dir = (tlsDir, done) => { }) }) - // log.loginfo(exports.certsByHost); + // log.info(exports.certsByHost); done(null, exports.certsByHost); }) }) @@ -508,10 +508,10 @@ exports.getSocketOpts = (name, done) => { this.get_certs_dir('tls', () => { if (certsByHost[name]) { - // log.logdebug(certsByHost[name]); + // log.debug(certsByHost[name]); return done(certsByHost[name]); } - // log.logdebug(certsByHost['*']); + // log.debug(certsByHost['*']); done(certsByHost['*']); }); } @@ -543,12 +543,12 @@ exports.ensureDhparams = done => { const filePath = this.cfg.main.dhparam || 'dhparams.pem'; const fpResolved = path.resolve(exports.config.root_path, filePath); - log.loginfo(`Generating a 2048 bit dhparams file at ${fpResolved}`); + log.info(`Generating a 2048 bit dhparams file at ${fpResolved}`); const o = spawn('openssl', ['dhparam', '-out', `${fpResolved}`, '2048']); o.stdout.on('data', data => { // normally empty output - log.logdebug(data); + log.debug(data); }) o.stderr.on('data', data => { @@ -560,7 +560,7 @@ exports.ensureDhparams = done => { return done(`Error code: ${code}`); } - log.loginfo(`Saved to ${fpResolved}`); + log.info(`Saved to ${fpResolved}`); const content = this.config.get(filePath, 'binary'); this.saveOpt('*', 'dhparam', content); @@ -570,20 +570,20 @@ exports.ensureDhparams = done => { exports.addOCSP = server => { if (!ocsp) { - log.logdebug('addOCSP: not available'); + log.debug('addOCSP: not available'); return; } if (server.listenerCount('OCSPRequest') > 0) { - log.logdebug('OCSPRequest already listening'); + log.debug('OCSPRequest already listening'); return; } - log.logdebug('adding OCSPRequest listener'); + log.debug('adding OCSPRequest listener'); server.on('OCSPRequest', (cert, issuer, ocr_cb) => { - log.logdebug(`OCSPRequest: ${cert}`); + log.debug(`OCSPRequest: ${cert}`); ocsp.getOCSPURI(cert, (err, uri) => { - log.logdebug(`OCSP Request, URI: ${uri }, err=${ err}`); + log.debug(`OCSP Request, URI: ${uri }, err=${ err}`); if (err) return ocr_cb(err); if (uri === null) return ocr_cb(); // not working OCSP server @@ -594,7 +594,7 @@ exports.addOCSP = server => { if (err2) return ocr_cb(err2); if (cached) { - log.logdebug(`OCSP cache: ${util.inspect(cached)}`); + log.debug(`OCSP cache: ${util.inspect(cached)}`); return ocr_cb(err2, cached.response); } @@ -603,7 +603,7 @@ exports.addOCSP = server => { ocsp: req.data }; - log.logdebug(`OCSP req:${util.inspect(req)}`); + log.debug(`OCSP req:${util.inspect(req)}`); ocspCache.request(req.id, options, ocr_cb); }) }) @@ -615,7 +615,7 @@ exports.shutdown = () => { } function cleanOcspCache () { - log.logdebug(`Cleaning ocspCache. How many keys? ${Object.keys(ocspCache.cache).length}`); + log.debug(`Cleaning ocspCache. How many keys? ${Object.keys(ocspCache.cache).length}`); Object.keys(ocspCache.cache).forEach((key) => { clearTimeout(ocspCache.cache[key].timer); }); @@ -640,7 +640,7 @@ function createServer (cb) { exports.addOCSP(server); socket.upgrade = cb2 => { - log.logdebug('Upgrading to TLS'); + log.debug('Upgrading to TLS'); socket.clean(); @@ -661,7 +661,7 @@ function createServer (cb) { socket.emit('error', exception); }) .on('secure', () => { - log.logdebug('TLS secured.'); + log.debug('TLS secured.'); socket.emit('secure'); const cipher = cleartext.getCipher(); cipher.version = cleartext.getProtocol(); @@ -739,12 +739,12 @@ function connect (port, host) { cleartext.on('error', err => { if (err.reason) { - log.logerror(`client TLS error: ${err}`); + log.error(`client TLS error: ${err}`); } }) cleartext.once('secureConnect', () => { - log.logdebug('client TLS secured.'); + log.debug('client TLS secured.'); const cipher = cleartext.getCipher(); cipher.version = cleartext.getProtocol(); if (cb2) cb2( @@ -765,7 +765,7 @@ function connect (port, host) { socket.attach(socket.cleartext); - log.logdebug('client TLS upgrade in progress, awaiting secured.'); + log.debug('client TLS upgrade in progress, awaiting secured.'); } return socket;