{"action":"created","issue":{"url":"https://api.github.com/repos/haraka/Haraka/issues/1384","repository_url":"https://api.github.com/repos/haraka/Haraka","labels_url":"https://api.github.com/repos/haraka/Haraka/issues/1384/labels{/name}","comments_url":"https://api.github.com/repos/haraka/Haraka/issues/1384/comments","events_url":"https://api.github.com/repos/haraka/Haraka/issues/1384/events","html_url":"https://github.com/haraka/Haraka/pull/1384","id":140033110,"number":1384,"title":"Remove exit module","user":{"login":"smfreegard","id":550490,"avatar_url":"https://avatars.githubusercontent.com/u/550490?v=3","gravatar_id":"","url":"https://api.github.com/users/smfreegard","html_url":"https://github.com/smfreegard","followers_url":"https://api.github.com/users/smfreegard/followers","following_url":"https://api.github.com/users/smfreegard/following{/other_user}","gists_url":"https://api.github.com/users/smfreegard/gists{/gist_id}","starred_url":"https://api.github.com/users/smfreegard/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/smfreegard/subscriptions","organizations_url":"https://api.github.com/users/smfreegard/orgs","repos_url":"https://api.github.com/users/smfreegard/repos","events_url":"https://api.github.com/users/smfreegard/events{/privacy}","received_events_url":"https://api.github.com/users/smfreegard/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/haraka/Haraka/labels/Bug%20Fix","name":"Bug Fix","color":"f7c6c7"}],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":10,"created_at":"2016-03-10T22:55:46Z","updated_at":"2016-03-11T12:22:02Z","closed_at":null,"pull_request":{"url":"https://api.github.com/repos/haraka/Haraka/pulls/1384","html_url":"https://github.com/haraka/Haraka/pull/1384","diff_url":"https://github.com/haraka/Haraka/pull/1384.diff","patch_url":"https://github.com/haraka/Haraka/pull/1384.patch"},"body":"Remove the exit module as it's caused me multiple nasty issues.\r\n\r\nThe latest issue I've had was extremely hard to diagnose (it required strace) which caused the cluster master to be unable to respawn a crashed child process:\r\n\r\n````\r\nwrite(2, \"events.js:141\r\n      throw er; // Unhandled 'error' event            \r\nError: This socket is closed.\r\n    at Socket._writeGeneric (net.js:625:19)\r\n    at Socket._write (net.js:678:8)\r\n    at doWrite (_stream_writable.js:291:12)\r\n    at writeOrBuffer (_stream_writable.js:278:5)\r\n    at Socket.Writable.write (_stream_writable.js:206:11)\r\n    at Socket.write (net.js:603:40)\r\n    at /usr/lib/node_modules/Haraka/node_modules/exit/lib/exit.js:25:14\r\n    at Array.forEach (native)\r\n    at exit (/usr/lib/node_modules/Haraka/node_modules/exit/lib/exit.js:20:11)\r\n    at process.<anonymous> (/usr/lib/node_modules/Haraka/haraka.js:41:5)\r\n\", 622) = -1 EPIPE (Broken pipe)\r\n--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=19697, si_uid=0} ---\r\n````\r\n\r\nIt looks like what happened is that exit() somehow manages to close stdin/stdout/stderr in the master process when one of the children hit an unhandled exception and this prevented all future children spawned by master from inheriting them and therefore at start-up when they attempted to write to the console, they immediately hit an EPIPE exception and would then crash out again.   Rinse repeat."},"comment":{"url":"https://api.github.com/repos/haraka/Haraka/issues/comments/195346811","html_url":"https://github.com/haraka/Haraka/pull/1384#issuecomment-195346811","issue_url":"https://api.github.com/repos/haraka/Haraka/issues/1384","id":195346811,"user":{"login":"smfreegard","id":550490,"avatar_url":"https://avatars.githubusercontent.com/u/550490?v=3","gravatar_id":"","url":"https://api.github.com/users/smfreegard","html_url":"https://github.com/smfreegard","followers_url":"https://api.github.com/users/smfreegard/followers","following_url":"https://api.github.com/users/smfreegard/following{/other_user}","gists_url":"https://api.github.com/users/smfreegard/gists{/gist_id}","starred_url":"https://api.github.com/users/smfreegard/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/smfreegard/subscriptions","organizations_url":"https://api.github.com/users/smfreegard/orgs","repos_url":"https://api.github.com/users/smfreegard/repos","events_url":"https://api.github.com/users/smfreegard/events{/privacy}","received_events_url":"https://api.github.com/users/smfreegard/received_events","type":"User","site_admin":false},"created_at":"2016-03-11T12:22:02Z","updated_at":"2016-03-11T12:22:02Z","body":"Ok - I've spent some more time on this today.   I was able to reproduce #1296 on iojs 1.8.4 - I only get the full output some of the time:\r\n\r\n`````\r\n[smf@dmxscan1 Haraka]$ node haraka.js \r\nloaded TLD files: 1=1233 2=5914 3=2315\r\nloaded 7847 Public Suffixes\r\nloglevel: LOGPROTOCOL\r\nStarting up Haraka version 2.8.0-alpha.7\r\n[INFO] [-] [core] Loading plugins\r\n[INFO] [-] [core] Loading plugin: access\r\n[DEBUG] [-] [core] no timeout in access.timeout\r\n[DEBUG] [-] [core] no timeout in plugin_timeout\r\n[DEBUG] [-] [core] plugin access timeout is: 30s\r\n[INFO] [-] [access] skipping helo.checks.regexps\r\n[DEBUG] [-] [core] registered hook connect to access.rdns_access priority 0\r\n[DEBUG] [-] [core] registered hook mail to access.mail_from_access priority 0\r\n[DEBUG] [-] [core] registered hook rcpt to access.rcpt_to_access priority 0\r\n[DEBUG] [-] [core] registered hook connect to access.any priority 0\r\n[DEBUG] [-] [core] registered hook helo to access.any priority 0\r\n[DEBUG] [-] [core] registered hook ehlo to access.any priority 0\r\n[DEBUG] [-] [core] registered hook mail to access.any priority 0\r\n[DEBUG] [-] [core] registered hook rcpt to access.any priority 0\r\n[DEBUG] [-] [core] registered hook data_post to access.data_any priority 0\r\n[INFO] [-] [core] Loading plugin: dnsbl\r\n[DEBUG] [-] [core] no timeout in dnsbl.timeout\r\n[DEBUG] [-] [core] no timeout in plugin_timeout\r\n[DEBUG] [-] [core] plugin dnsbl timeout is: 30s\r\n[DEBUG] [-] [core] no timeout in dns_list_base.timeout\r\n[DEBUG] [-] [core] no timeout in plugin_timeout\r\n[DEBUG] [-] [core] plugin dns_list_base timeout is: 30s\r\n[DEBUG] [-] [core] Returning boolean true for main.reject=true\r\n[DEBUG] [-] [dnsbl] looking up: 1.0.0.127.zen.spamhaus.org.\r\n[DEBUG] [-] [dnsbl] will re-test list zones every 30 minutes\r\n[DEBUG] [-] [core] registered hook connect to dnsbl.connect_first priority 0\r\n[INFO] [-] [core] Loading plugin: helo.checks\r\n[DEBUG] [-] [core] no timeout in helo.checks.timeout\r\n[DEBUG] [-] [core] no timeout in plugin_timeout\r\n[DEBUG] [-] [core] plugin helo.checks timeout is: 30s\r\n[DEBUG] [-] [core] Returning boolean true for check.match_re=true\r\n[DEBUG] [-] [core] Returning boolean true for check.bare_ip=true\r\n[DEBUG] [-] [core] Returning boolean true for check.dynamic=true\r\n[DEBUG] [-] [core] Returning boolean true for check.big_company=true\r\n[DEBUG] [-] [core] Returning boolean true for check.valid_hostname=true\r\n[DEBUG] [-] [core] Returning boolean true for check.forward_dns=true\r\n[DEBUG] [-] [core] Returning boolean true for check.rdns_match=true\r\n[DEBUG] [-] [core] Returning boolean true for check.mismatch=true\r\n[DEBUG] [-] [core] Returning boolean true for check.proto_mismatch=true\r\n[DEBUG] [-] [core] Returning boolean true for reject.mismatch=true\r\n[DEBUG] [-] [core] Returning boolean false for reject.proto_mismatch=false\r\n[DEBUG] [-] [core] Returning boolean false for reject.rdns_match=false\r\n[DEBUG] [-] [core] Returning boolean false for reject.dynamic=false\r\n[DEBUG] [-] [core] Returning boolean false for reject.bare_ip=false\r\n[DEBUG] [-] [core] Returning boolean false for reject.literal_mismatch=false\r\n[DEBUG] [-] [core] Returning boolean false for reject.valid_hostname=false\r\n[DEBUG] [-] [core] Returning boolean false for reject.forward_dns=false\r\n[DEBUG] [-] [core] Returning boolean true for reject.big_company=true\r\n[DEBUG] [-] [core] Returning boolean true for skip.private_ip=true\r\n[DEBUG] [-] [core] Returning boolean true for skip.relaying=true\r\n[DEBUG] [-] [core] registered hook helo to helo.checks.proto_mismatch_smtp priority 0\r\n[DEBUG] [-] [core] registered hook ehlo to helo.checks.proto_mismatch_esmtp priority 0\r\n[DEBUG] [-] [core] registered hook helo to helo.checks.init priority 0\r\n[DEBUG] [-] [core] registered hook ehlo to helo.checks.init priority 0\r\n[DEBUG] [-] [core] registered hook helo to helo.checks.match_re priority 0\r\n[DEBUG] [-] [core] registered hook ehlo to helo.checks.match_re priority 0\r\n[DEBUG] [-] [core] registered hook helo to helo.checks.bare_ip priority 0\r\n[DEBUG] [-] [core] registered hook ehlo to helo.checks.bare_ip priority 0\r\n[DEBUG] [-] [core] registered hook helo to helo.checks.dynamic priority 0\r\n[DEBUG] [-] [core] registered hook ehlo to helo.checks.dynamic priority 0\r\n[DEBUG] [-] [core] registered hook helo to helo.checks.big_company priority 0\r\n[DEBUG] [-] [core] registered hook ehlo to helo.checks.big_company priority 0\r\n[DEBUG] [-] [core] registered hook helo to helo.checks.literal_mismatch priority 0\r\n[DEBUG] [-] [core] registered hook ehlo to helo.checks.literal_mismatch priority 0\r\n[DEBUG] [-] [core] registered hook helo to helo.checks.valid_hostname priority 0\r\n[DEBUG] [-] [core] registered hook ehlo to helo.checks.valid_hostname priority 0\r\n[DEBUG] [-] [core] registered hook helo to helo.checks.rdns_match priority 0\r\n[DEBUG] [-] [core] registered hook ehlo to helo.checks.rdns_match priority 0\r\n[DEBUG] [-] [core] registered hook helo to helo.checks.forward_dns priority 0\r\n[DEBUG] [-] [core] registered hook ehlo to helo.checks.forward_dns priority 0\r\n[INFO] [-] [core] Loading plugin: mail_from.is_resolvable\r\n[DEBUG] [-] [core] no timeout in mail_from.is_resolvable.timeout\r\n[DEBUG] [-] [core] no timeout in plugin_timeout\r\n[DEBUG] [-] [core] plugin mail_from.is_resolvable timeout is: 30s\r\n[DEBUG] [-] [core] Returning boolean false for main.allow_mx_ip=0\r\n[DEBUG] [-] [core] Returning boolean true for main.reject_no_mx=1\r\n[DEBUG] [-] [core] registered hook mail to mail_from.is_resolvable.hook_mail priority 0\r\n[INFO] [-] [core] Loading plugin: rcpt_to.in_host_list\r\n[DEBUG] [-] [core] no timeout in rcpt_to.in_host_list.timeout\r\n[DEBUG] [-] [core] no timeout in plugin_timeout\r\n[DEBUG] [-] [core] plugin rcpt_to.in_host_list timeout is: 30s\r\n[DEBUG] [-] [core] no timeout in rcpt_to.host_list_base.timeout\r\n[DEBUG] [-] [core] no timeout in plugin_timeout\r\n[DEBUG] [-] [core] plugin rcpt_to.host_list_base timeout is: 30s\r\n[DEBUG] [-] [core] registered hook rcpt to rcpt_to.in_host_list.hook_rcpt priority 0\r\n[DEBUG] [-] [core] registered hook mail to rcpt_to.in_host_list.hook_mail priority 0\r\n[INFO] [-] [core] Loading plugin: data.headers\r\n[DEBUG] [-] [core] no timeout in data.headers.timeout\r\n[DEBUG] [-] [core] no timeout in plugin_timeout\r\n[DEBUG] [-] [core] plugin data.headers timeout is: 30s\r\n[DEBUG] [-] [core] registered hook data_post to data.headers.duplicate_singular priority 0\r\n[DEBUG] [-] [core] registered hook data_post to data.headers.missing_required priority 0\r\n[DEBUG] [-] [core] registered hook data_post to data.headers.invalid_date priority 0\r\n[DEBUG] [-] [core] registered hook data_post to data.headers.invalid_return_path priority 0\r\n[DEBUG] [-] [core] registered hook data_post to data.headers.user_agent priority 0\r\n[DEBUG] [-] [core] registered hook data_post to data.headers.direct_to_mx priority 0\r\n[DEBUG] [-] [core] registered hook data_post to data.headers.from_match priority 0\r\n[DEBUG] [-] [core] registered hook data_post to data.headers.delivered_to priority 0\r\n[DEBUG] [-] [core] registered hook data_post to data.headers.mailing_list priority 0[smf@dmxscan1 Haraka]$\r\n`````\r\n\r\nThe workaround is to pipe to cat (which highlights a bug in logger.dump_logs()):\r\n\r\n`````\r\n[smf@dmxscan1 Haraka]$ node haraka.js  | cat\r\nloaded TLD files: 1=1233 2=5914 3=2315\r\nloaded 7847 Public Suffixes\r\n[ERROR] [-] [core] Failed to setup listeners: listen EACCES ::0:25\r\n[NOTICE] [-] [core] Shutting down\r\n`````\r\n\r\nThe \"missing\" output in the latter is because logger.dump_logs only dumps the logs when process.stdout.isTTY is true, which looks very much like a bug to me.\r\n\r\n> If we decide to revisit this, it seems one option might be: if (I am a cluster child) process.exit() else library_exit()\r\n\r\nTrue, but in my case this all blew up in haraka.js, so we'd have to use environment variables to detect if we're parent or child.  My concern would be what other bugs lay down that route, I couldn't reliably reproduce the conditions that caused my crashes which is why it took so long to find it.\r\n\r\nI was able to reliably get all log output without any pipes of workarounds by doing this:\r\n\r\n`````\r\nlogger.dump_logs = function (cb) {\r\n    while (logger.deferred_logs.length > 0) {\r\n        var log_item = logger.deferred_logs.shift();\r\n        var color = logger.colors[log_item.level];\r\n        if (color && stdout_is_tty) {\r\n            console.log(logger.colorize(color,log_item.data));\r\n        }\r\n    }\r\n    // Run callback function once everything has been written\r\n    if (cb) {\r\n        process.stdout.write('', cb);\r\n    }\r\n    return true;\r\n};\r\n`````\r\n\r\nAnd then changing the calls to it like so:\r\n`````\r\n            logger.logerror(\"Failed to setup listeners: \" + err.message);\r\n            logger.dump_logs(function () {\r\n                process.exit(1);\r\n            });\r\n            return;\r\n`````\r\n\r\nI admit I don't really understand why that works See https://github.com/nodejs/node/issues/2972#issuecomment-146078649 \r\n\r\nIf that's an acceptable workaround, then I'd rather do it this way than to use exit()."}}