outbound: get_mx overhaul, logging improvements (#3322)

Fixes #3314

Conceptually, the big changes in this PR do the following:

1. outsource outbound DNS to haraka-net-utils
2. improve outbound logging by using logger in *only* 2 common ways:
`logger.info(obj, message)` or `this.loginfo(self, msg...)`
3. In outbound, the control flow is much more linear:
    - run get_mx hooks
    - if no plugin offered a MX, get from net_utils.get_mx (which now
includes implicit MX)
    - pass list of MXes to found_mx, which sorts the MXes
    - net_utils resolves all MX hostnames to IPs (IPv4, IPv6, all at once, for speed)
    - each MX IP is tried in turn until one succeeds or the list is exhausted
4. Injecting logging functions into classes (Connection, Plugin, HMailItem) is now done via logger.add_log_methods

## Changes:

- outbound: minor es6 updates
- outbound: logging improvements
- was: [-] [core] [outbound] Failed to get socket: Outbound connection
error: Error: connect ECONNREFUSED 172.16.16.14:25
- now: [A63B62DF-F...] [outbound] Failed to get socket: connect
ECONNREFUSED 172.16.16.14:25
  - outbound: remove log prefixes of `[outbound] `, no longer needed
  - shorter logger syntax: logger.loginfo -> logger.info
- logger(connection, plugins, hmail), refactor copying in log functions
- logger: don't load outbound (race condition). Instead, set name
property
- outbound: delete try_deliver_host. Use net_utils to resolve MX hosts
to IPs
- outbound: remove config setting ipv6_enabled
- fix(logger): refactor add_log_methods, don't set extra `loglog*` names
- doc(connection): update rfc7001 URL

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

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);
         }
     }

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

config/outbound.ini

@@ -11,8 +11,6 @@
 
 ; maxTempFailures (default: 13)
 
-; ipv6_enabled (default: false)
-
 ; load_pid_queue
 ; flush_queue
 

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<l; i++) {
-                args.push(arguments[i]);
-            }
-            logger[level].apply(logger, args);
-        };
-    })(key);
-}
+logger.add_log_methods(Connection)

docs/Logging.md

@@ -17,20 +17,13 @@ Logging conventions within Haraka
 
 This section pertains to the built in logging. For log plugins like ([haraka-plugin-syslog](https://github.com/haraka/haraka-plugin-syslog)), refer to the plugin's docs.
 
-See also
-------------------
-[https://github.com/haraka/Haraka/pull/119](https://github.com/haraka/Haraka/pull/119)
-
 The logline by default will be in the form of:
 
     [level] [uuid] [origin] message
 
-Where origin is "core" or the name of the plugin which
-triggered the message, and "uuid" is the ID of the
-connection associated with the message.
+Where origin is "core" or the name of the plugin which triggered the message, and "uuid" is the ID of the connection associated with the message.
 
-When calling a log method on logger, you should provide the
-plugin object and the connection object anywhere in the arguments
+When calling a log method on logger, you should provide the plugin object and the connection object anywhere in the arguments
 to the log method.
 
     logger.logdebug("i like turtles", plugin, connection);
@@ -39,27 +32,21 @@ Will yield, for example,
 
     [DEBUG] [7F1C820F-DC79-4192-9AA6-5307354B20A6] [dnsbl] i like turtles
 
-If you call the log method on the connection object, you can
-forego the connection as argument:
+If you call the log method on the connection object, you can forego the connection as argument:
 
     connection.logdebug("turtles all the way down", plugin);
 
 and similarly for the log methods on the plugin object:
 
     plugin.logdebug("he just really likes turtles", connection);
 
-failing to provide a connection and/or plugin object will leave
-the default values in the log (currently "core").
+failing to provide a connection and/or plugin object will leavethe default values in the log (currently "core").
 
-This is implemented by testing for argument type in
-the logger.js log\* method. objects-as-arguments are then sniffed
-to try to determine if they're a connection or plugin instance.
+This is implemented by testing for argument type in the logger.js log\* method. objects-as-arguments are then sniffed to try to determine if they're a connection or plugin instance.
 
 ### Log formats
 
-Apart from the default log format described above, Haraka also supports logging
-as [`logfmt`](https://brandur.org/logfmt) and JSON. These can be used by
-changing the `format` attribute in `log.ini` to the desired format, e.g.:
+Apart from the default log format described above, Haraka also supports logging as [`logfmt`](https://brandur.org/logfmt) and JSON. These can be used by changing the `format` attribute in `log.ini` to the desired format, e.g.:
 
 ```ini
 ; format=default
@@ -77,8 +64,7 @@ And the same line formatted as JSON:
 {"level":"PROTOCOL","uuid":"9FF7F70E-5D57-435A-AAD9-EA069B6159D9.1","source":"core","message":"S: 354 go ahead, make my day"}
 ```
 
-Any objects passed to the log methods will also have their properties included
-in the log line. For example, using `logfmt`:
+Any objects passed to the log methods will also have their properties included in the log line. For example, using `logfmt`:
 
     level=NOTICE uuid=9FF7F70E-5D57-435A-AAD9-EA069B6159D9.1 source=core message=disconnect ip=127.0.0.1 rdns=Unknown helo=3h2dnz8a0if relay=N early=N esmtp=N tls=N pipe=N errors=0 txns=1 rcpts=1/0/0 msgs=1/0/0 bytes=222 lr="" time=0.052
 

docs/Outbound.md

@@ -49,11 +49,6 @@ Within `tls.ini` you can specify global options for the values `ciphers`, `minVe
 ciphers=!DES
 ```
 
-* `ipv6_enabled`
-
-When this has a "true" value inside (usually a `1`), it defaults to an 'AAAA'
-lookup first for each MX record, and uses those hosts to send email via.
-
 * `always_split`
 
 Default: false. By default, Haraka groups message recipients by domain so that

docs/plugins/bounce.md

@@ -9,6 +9,7 @@ section of `config/bounce.ini`:
 
 Some features can have rejections disabled in the [reject] section.
 
+    ```ini
     [check]
     reject_all=false
     single_recipient=true
@@ -22,6 +23,7 @@ Some features can have rejections disabled in the [reject] section.
     empty_return_path=true
     bounce_spf=false
     non_local_msgid=false
+    ```
 
 ## Features
 

haraka.js

@@ -30,10 +30,10 @@ exports.version = JSON.parse(
 
 process.on('uncaughtException', err => {
     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();
 });
 

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];