Bug at status plugin

[gamalan]

Describe the bug
Haraka shutting down when there are error at status plugin

Expected behavior
Should be restarted worker normally

Steps To Reproduce
Haraka worker restarted because others issue then somehow status plugin acting up

System Info:

Haraka	Haraka.js — Version: 2.8.28
Node	v16.18.1
OS	Linux saas-hved-relay01 5.10.0-18-amd64 #1 SMP Debian 5.10.140-1 (2022-09-02) x86_64 GNU/Linux
openssl	OpenSSL 1.1.1n 15 Mar 2022

Additional context
Log

Dec 11 15:18:33 hostname haraka[2610177]: [NOTICE] [-] [core] Shutting down
Dec 11 15:18:33 hostname haraka[2598219]: [NOTICE] [-] [core] worker 387 exited with error code: 1
Dec 11 15:18:33 hostname haraka[2598219]: [NOTICE] [-] [core] worker started worker=392 pid=2610246
Dec 11 15:18:33 hostname haraka[2598219]: [CRIT] [-] [core] Error [ERR_IPC_CHANNEL_CLOSED]: Channel closed
Dec 11 15:18:33 hostname haraka[2598219]: [CRIT] [-] [core]     at new NodeError (node:internal/errors:387:5)
Dec 11 15:18:33 hostname haraka[2598219]: [CRIT] [-] [core]     at ChildProcess.target.send (node:internal/child_process:749:16)
Dec 11 15:18:33 hostname haraka[2598219]: [CRIT] [-] [core]     at Worker.send (node:internal/cluster/worker:48:10)
Dec 11 15:18:33 hostname haraka[2598219]: [CRIT] [-] [core]     at /opt/smtp/haraka/plugins/status.js:178:20
Dec 11 15:18:33 hostname haraka[2598219]: [CRIT] [-] [core]     at /opt/smtp/haraka/node_modules/async/dist/async.js:251:13
Dec 11 15:18:33 hostname haraka[2598219]: [CRIT] [-] [core]     at wrapper (/opt/smtp/haraka/node_modules/async/dist/async.js:271:20)
Dec 11 15:18:33 hostname haraka[2598219]: [CRIT] [-] [core]     at iterateeCallback (/opt/smtp/haraka/node_modules/async/dist/async.js:427:28)
Dec 11 15:18:33 hostname haraka[2598219]: [CRIT] [-] [core]     at /opt/smtp/haraka/node_modules/async/dist/async.js:327:20
Dec 11 15:18:33 hostname haraka[2598219]: [CRIT] [-] [core]     at /opt/smtp/haraka/node_modules/async/dist/async.js:248:17
Dec 11 15:18:33 hostname haraka[2598219]: [CRIT] [-] [core]     at EventEmitter.message_handler (/opt/smtp/haraka/plugins/status.js:235:9)
Dec 11 15:18:33 hostname haraka[2598219]: [CRIT] [-] [core] Error [ERR_IPC_CHANNEL_CLOSED]: Channel closed
Dec 11 15:18:33 hostname haraka[2598219]: [CRIT] [-] [core]     at new NodeError (node:internal/errors:387:5)
Dec 11 15:18:33 hostname haraka[2598219]: [CRIT] [-] [core]     at ChildProcess.target.send (node:internal/child_process:749:16)
Dec 11 15:18:33 hostname haraka[2598219]: [CRIT] [-] [core]     at Worker.send (node:internal/cluster/worker:48:10)
Dec 11 15:18:33 hostname haraka[2598219]: [CRIT] [-] [core]     at /opt/smtp/haraka/plugins/status.js:178:20
Dec 11 15:18:33 hostname haraka[2598219]: [CRIT] [-] [core]     at /opt/smtp/haraka/node_modules/async/dist/async.js:251:13
Dec 11 15:18:33 hostname haraka[2598219]: [CRIT] [-] [core]     at wrapper (/opt/smtp/haraka/node_modules/async/dist/async.js:271:20)
Dec 11 15:18:33 hostname haraka[2598219]: [CRIT] [-] [core]     at iterateeCallback (/opt/smtp/haraka/node_modules/async/dist/async.js:427:28)
Dec 11 15:18:33 hostname haraka[2598219]: [CRIT] [-] [core]     at /opt/smtp/haraka/node_modules/async/dist/async.js:327:20
Dec 11 15:18:33 hostname haraka[2598219]: [CRIT] [-] [core]     at /opt/smtp/haraka/node_modules/async/dist/async.js:248:17
Dec 11 15:18:33 hostname haraka[2598219]: [CRIT] [-] [core]     at EventEmitter.message_handler (/opt/smtp/haraka/plugins/status.js:235:9)
Dec 11 15:18:33 hostname haraka[2598219]: [NOTICE] [-] [core] Shutting down
Dec 11 15:18:33 hostname haraka[2610199]: [NOTICE] [-] [core] Shutting down
Dec 11 15:18:33 hostname haraka[2610222]: [NOTICE] [-] [core] Shutting down
Dec 11 15:18:33 hostname haraka[2610246]: loaded TLD files:
Dec 11 15:18:33 hostname haraka[2610246]:   1=1495
Dec 11 15:18:33 hostname haraka[2610246]:   2=8570
Dec 11 15:18:33 hostname haraka[2610246]:   3=2448
Dec 11 15:18:33 hostname haraka[2610246]: loaded 9192 Public Suffixes
Dec 11 15:18:33 hostname haraka[2610235]: [NOTICE] [-] [core] Shutting down
Dec 11 15:18:33 hostname haraka[2610246]: loglevel: INFO
Dec 11 15:18:33 hostname haraka[2610246]: log format: DEFAULT
Dec 11 15:18:33 hostname haraka[2610246]: Starting up Haraka version 2.8.28
Dec 11 15:18:33 hostname haraka[2610246]: [INFO] [-] [core] Loading plugins
Dec 11 15:18:33 hostname haraka[2610246]: [INFO] [-] [core] Loading plugin: status
Dec 11 15:18:33 hostname haraka[2610246]: [INFO] [-] [core] Loading plugin: **internal plugin**
Dec 11 15:18:33 hostname haraka[2610246]: [INFO] [-] [**internal plugin**] Loading some parameter on **internal plugin**
Dec 11 15:18:33 hostname haraka[2610246]: [INFO] [-] [core] Loading plugin: tls
Dec 11 15:18:33 hostname haraka[2610246]: [INFO] [-] [core] Loading plugin: **internal plugin**
Dec 11 15:18:33 hostname haraka[2610246]: [INFO] [-] [core] Loading plugin: rcpt_to.in_host_list
Dec 11 15:18:33 hostname haraka[2610246]: [INFO] [-] [core] Loading plugin: **internal plugin**
Dec 11 15:18:33 hostname haraka[2610246]: [INFO] [-] [core] Loading plugin: **internal plugin**
Dec 11 15:18:33 hostname haraka[2610246]: [INFO] [-] [core] Loading plugin: **internal plugin**
Dec 11 15:18:33 hostname haraka[2610246]: [INFO] [-] [core] Loading plugin: **internal plugin**
Dec 11 15:18:33 hostname haraka[2610246]: [INFO] [-] [core] Loading plugin: status
Dec 11 15:18:33 hostname haraka[2610246]: [INFO] [-] [core] getting SocketOpts for SMTPS server
Dec 11 15:18:33 hostname haraka[2610246]: [INFO] [-] [core] Creating TLS server on [::0]:465
Dec 11 15:18:33 hostname haraka[2610246]: [CRIT] [-] [core] Error: write EPIPE
Dec 11 15:18:33 hostname haraka[2610246]: [CRIT] [-] [core]     at process.target._send (node:internal/child_process:874:20)
Dec 11 15:18:33 hostname haraka[2610246]: [CRIT] [-] [core]     at process.target._send (node:internal/child_process:874:20)
Dec 11 15:18:33 hostname haraka[2610246]: [CRIT] [-] [core]     at process.target.send (node:internal/child_process:747:19)
Dec 11 15:18:33 hostname haraka[2610246]: [CRIT] [-] [core]     at sendHelper (node:internal/cluster/utils:28:15)
Dec 11 15:18:33 hostname haraka[2610246]: [CRIT] [-] [core]     at send (node:internal/cluster/child:229:10)
Dec 11 15:18:33 hostname haraka[2610246]: [CRIT] [-] [core]     at EventEmitter.cluster._getServer (node:internal/cluster/child:100:3)
Dec 11 15:18:33 hostname haraka[2610246]: [CRIT] [-] [core]     at listenInCluster (node:net:1525:11)
Dec 11 15:18:33 hostname haraka[2610246]: [CRIT] [-] [core]     at doListen (node:net:1660:7)
Dec 11 15:18:33 hostname haraka[2610246]: [CRIT] [-] [core]     at processTicksAndRejections (node:internal/process/task_queues:84:21)
Dec 11 15:18:33 hostname haraka[2610246]: [NOTICE] [-] [core] Shutting down

some context when searching about the error log message
https://stackoverflow.com/questions/68638613/error-err-ipc-channel-closed-channel-closed-when-replacing-backend-service-wi

This happen when not activating ignore_bad_plugin configuration, and currently activating this option, let'see what happen.

[msimerson]

This error message doesn't look to me like the problem is in the status plugin. It looks more like Creating TLS server on [::0]:465 is where things go awry.

[gamalan]

Hmm, I see. So it seems, when a worker restarted it can't access the port it used before? Because I don't use the port other than for the haraka process.

…

On Mon, Dec 12, 2022 at 7:54 AM Matt Simerson ***@***.***> wrote: This error message doesn't look to me like the problem is in the status plugin. It looks more like Creating TLS server on [::0]:465 is where things go awry. — Reply to this email directly, view it on GitHub <#3118 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAIYFEYMINL5BWPNQ6JF23LWMZZUNANCNFSM6AAAAAAS24ROKA> . You are receiving this because you authored the thread.Message ID: ***@***.***>

[gamalan]

But I am still suspecting status plugin because our latest error show this

Dec 12 12:14:39 hostname haraka[2685582]: [INFO] [-] [core] [outbound] Socket [] in pool got FIN
Dec 12 12:14:39 hostname haraka[2685582]: [CRIT] [-] [core] Error: Resource not currently part of this pool
Dec 12 12:14:39 hostname haraka[2685582]: [CRIT] [-] [core]     at Pool.destroy (/opt/smtp/haraka/node_modules/generic-pool/lib/Pool.js:548:9)
Dec 12 12:14:39 hostname haraka[2685582]: [CRIT] [-] [core]     at sockend (/opt/smtp/haraka/outbound/client_pool.js:179:37)
Dec 12 12:14:39 hostname haraka[2685582]: [CRIT] [-] [core]     at pluggableStream.<anonymous> (/opt/smtp/haraka/outbound/client_pool.js:171:9)
Dec 12 12:14:39 hostname haraka[2685582]: [CRIT] [-] [core]     at Object.onceWrapper (node:events:627:28)
Dec 12 12:14:39 hostname haraka[2685582]: [CRIT] [-] [core]     at pluggableStream.emit (node:events:513:28)
Dec 12 12:14:39 hostname haraka[2685582]: [CRIT] [-] [core]     at TLSSocket.<anonymous> (/opt/smtp/haraka/tls_socket.js:79:18)
Dec 12 12:14:39 hostname haraka[2685582]: [CRIT] [-] [core]     at TLSSocket.emit (node:events:525:35)
Dec 12 12:14:39 hostname haraka[2685582]: [CRIT] [-] [core]     at endReadableNT (node:internal/streams/readable:1358:12)
Dec 12 12:14:39 hostname haraka[2685582]: [CRIT] [-] [core]     at processTicksAndRejections (node:internal/process/task_queues:83:21)
Dec 12 12:14:39 hostname haraka[2685582]: [NOTICE] [-] [core] Shutting down
Dec 12 12:14:39 hostname haraka[2684402]: [NOTICE] [-] [core] worker 40 exited with error code: 1
Dec 12 12:14:39 hostname haraka[2684402]: [NOTICE] [-] [core] worker started worker=41 pid=2685603
Dec 12 12:14:39 hostname haraka[2685603]: loaded TLD files:
Dec 12 12:14:39 hostname haraka[2685603]:   1=1495
Dec 12 12:14:39 hostname haraka[2685603]:   2=8570
Dec 12 12:14:39 hostname haraka[2685603]:   3=2448
Dec 12 12:14:39 hostname haraka[2685603]: loaded 9192 Public Suffixes
Dec 12 12:14:40 hostname haraka[2685603]: loglevel: INFO
Dec 12 12:14:40 hostname haraka[2685603]: log format: DEFAULT
Dec 12 12:14:40 hostname haraka[2685603]: Starting up Haraka version 2.8.28
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [-] [core] Loading plugins
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [-] [core] Loading plugin: **internal**_load_my_config
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [-] [**internal**_load_my_config] Loading some parameter on **internal** delivery system.
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [-] [core] Loading plugin: toobusy
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [-] [core] Loading plugin: tls
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [-] [core] loading tls.ini
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [-] [core] Loading plugin: **internal**_auth
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [-] [core] Loading plugin: rcpt_to.in_host_list
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [-] [core] Loading plugin: **internal**_relayall
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [-] [core] Loading plugin: **internal**_data_post
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [-] [core] Loading plugin: **internal**_dkim_sign
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [-] [core] Loading plugin: **internal**_report
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [-] [core] Loading plugin: status
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [-] [core] getting SocketOpts for SMTPS server
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [-] [core] Creating TLS server on [::0]:465
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [-] [core] [outbound] Loading queue for pid: 2685582
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [-] [core] [outbound] Loading outbound queue from /opt/smtp/haraka/queue
Dec 12 12:14:40 hostname haraka[2685603]: [NOTICE] [-] [core] Listening on [::0]:465
Dec 12 12:14:40 hostname haraka[2685603]: [NOTICE] [-] [core] Listening on [::0]:587
Dec 12 12:14:40 hostname haraka[2684402]: [NOTICE] [-] [core] worker 41 listening on [::0]:465
Dec 12 12:14:40 hostname haraka[2685603]: [NOTICE] [-] [core] Listening on [::0]:2525
Dec 12 12:14:40 hostname haraka[2684402]: [NOTICE] [-] [core] worker 41 listening on [::0]:587
Dec 12 12:14:40 hostname haraka[2684402]: [NOTICE] [-] [core] worker 41 listening on [::0]:2525
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [-] [core] [outbound] Grabbing queue files for pid: 2685582
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [-] [core] [outbound] [pid: 2685582] 15 files old PID queue fixed up
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [-] [core] [outbound] [pid: 2685582] 0 files in my delivery queue
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [-] [core] [outbound] [pid: 2685582] 9 files in my load queue
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [-] [core] [outbound] [pid: 2685582] 6 files in my temp fail queue
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [-] [core] loading tls.ini
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [820AB633-47FA-4658-BD85-AA26A200E95A.1.1] [outbound] Looking up A records for: domain
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [C5DE86B1-C49C-48FC-B997-8D72FB7C63AB.1.1] [outbound] Looking up A records for: domain
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [8075990C-789A-4118-9DFE-7C077B8BBC2B.1.1] [outbound] Looking up A records for: domain
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [820AB633-47FA-4658-BD85-AA26A200E95A.1.1] [outbound] Attempting to deliver to: host:25 (0) (6)
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [C5DE86B1-C49C-48FC-B997-8D72FB7C63AB.1.1] [outbound] Attempting to deliver to: host:25 (0) (6)
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [8075990C-789A-4118-9DFE-7C077B8BBC2B.1.1] [outbound] Attempting to deliver to: host:25 (0) (6)
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [DA02CA17-0306-4E86-BAA7-247F524A2A9C.1.1] [outbound] Looking up A records for: domain
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [DA02CA17-0306-4E86-BAA7-247F524A2A9C.1.1] [outbound] Attempting to deliver to: host:25 (0) (6)
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [BA500869-C58B-44A9-9E7D-AFC7550A299E.1.1] [outbound] Attempting to deliver to: host:25 (0) (6)
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [4EFF001B-BEF8-48AE-B39B-AC3FEF909484.1.1] [outbound] Attempting to deliver to: host:25 (0) (6)
Dec 12 12:14:40 hostname haraka[2685603]: [INFO] [E5A3BF7F-4DC0-4761-8010-A0DC5A6EF678.1.1] [outbound] Attempting to deliver to: host:25 (0) (6)
Dec 12 12:14:41 hostname haraka[2685603]: [INFO] [6A882E33-ECDC-4FAE-9BF7-6AA5929F742E.1.1] [outbound] Attempting to deliver to: host:25 (0) (6)
Dec 12 12:14:41 hostname haraka[2685575]: [INFO] [-] [core] [outbound] Socket [] in pool got FIN
Dec 12 12:14:41 hostname haraka[2685575]: [CRIT] [-] [core] Error: Resource not currently part of this pool
Dec 12 12:14:41 hostname haraka[2685575]: [CRIT] [-] [core]     at Pool.destroy (/opt/smtp/haraka/node_modules/generic-pool/lib/Pool.js:548:9)
Dec 12 12:14:41 hostname haraka[2685575]: [CRIT] [-] [core]     at sockend (/opt/smtp/haraka/outbound/client_pool.js:179:37)
Dec 12 12:14:41 hostname haraka[2685575]: [CRIT] [-] [core]     at pluggableStream.<anonymous> (/opt/smtp/haraka/outbound/client_pool.js:171:9)
Dec 12 12:14:41 hostname haraka[2685575]: [CRIT] [-] [core]     at Object.onceWrapper (node:events:627:28)
Dec 12 12:14:41 hostname haraka[2685575]: [CRIT] [-] [core]     at pluggableStream.emit (node:events:513:28)
Dec 12 12:14:41 hostname haraka[2685575]: [CRIT] [-] [core]     at TLSSocket.<anonymous> (/opt/smtp/haraka/tls_socket.js:79:18)
Dec 12 12:14:41 hostname haraka[2685575]: [CRIT] [-] [core]     at TLSSocket.emit (node:events:525:35)
Dec 12 12:14:41 hostname haraka[2685575]: [CRIT] [-] [core]     at endReadableNT (node:internal/streams/readable:1358:12)
Dec 12 12:14:41 hostname haraka[2685575]: [CRIT] [-] [core]     at processTicksAndRejections (node:internal/process/task_queues:83:21)
Dec 12 12:14:41 hostname haraka[2685575]: [NOTICE] [-] [core] Shutting down
Dec 12 12:14:41 hostname haraka[2684402]: [NOTICE] [-] [core] worker 39 exited with error code: 1
Dec 12 12:14:41 hostname haraka[2684402]: [NOTICE] [-] [core] worker started worker=42 pid=2685614
Dec 12 12:14:41 hostname haraka[2685614]: loaded TLD files:
Dec 12 12:14:41 hostname haraka[2685614]:   1=1495
Dec 12 12:14:41 hostname haraka[2685614]:   2=8570
Dec 12 12:14:41 hostname haraka[2685614]:   3=2448
Dec 12 12:14:41 hostname haraka[2685614]: loaded 9192 Public Suffixes
Dec 12 12:14:41 hostname haraka[2685603]: [INFO] [D3F8E22C-A307-454B-9AF9-4DFB6B70D976.1.1] [outbound] Looking up A records for: domain
Dec 12 12:14:41 hostname haraka[2685603]: [INFO] [D3F8E22C-A307-454B-9AF9-4DFB6B70D976.1.1] [outbound] Attempting to deliver to: host:25 (0) (6)
Dec 12 12:14:41 hostname haraka[2685614]: loglevel: INFO
Dec 12 12:14:41 hostname haraka[2685614]: log format: DEFAULT
Dec 12 12:14:41 hostname haraka[2685614]: Starting up Haraka version 2.8.28
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [-] [core] Loading plugins
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [-] [core] Loading plugin: **internal**_load_my_config
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [-] [**internal**_load_my_config] Loading some parameter on **internal** delivery system.
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [-] [core] Loading plugin: toobusy
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [-] [core] Loading plugin: tls
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [-] [core] loading tls.ini
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [-] [core] Loading plugin: **internal**_auth
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [-] [core] Loading plugin: rcpt_to.in_host_list
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [-] [core] Loading plugin: **internal**_relayall
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [-] [core] Loading plugin: **internal**_data_post
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [-] [core] Loading plugin: **internal**_dkim_sign
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [-] [core] Loading plugin: **internal**_report
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [-] [core] Loading plugin: status
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [-] [core] getting SocketOpts for SMTPS server
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [-] [core] Creating TLS server on [::0]:465
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [-] [core] [outbound] Loading queue for pid: 2685575
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [-] [core] [outbound] Loading outbound queue from /opt/smtp/haraka/queue
Dec 12 12:14:41 hostname haraka[2685614]: [NOTICE] [-] [core] Listening on [::0]:465
Dec 12 12:14:41 hostname haraka[2685614]: [NOTICE] [-] [core] Listening on [::0]:587
Dec 12 12:14:41 hostname haraka[2685614]: [NOTICE] [-] [core] Listening on [::0]:2525
Dec 12 12:14:41 hostname haraka[2684402]: [NOTICE] [-] [core] worker 42 listening on [::0]:465
Dec 12 12:14:41 hostname haraka[2684402]: [NOTICE] [-] [core] worker 42 listening on [::0]:587
Dec 12 12:14:41 hostname haraka[2684402]: [NOTICE] [-] [core] worker 42 listening on [::0]:2525
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [-] [core] [outbound] Grabbing queue files for pid: 2685575
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [-] [core] [outbound] [pid: 2685575] 13 files old PID queue fixed up
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [-] [core] [outbound] [pid: 2685575] 0 files in my delivery queue
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [-] [core] [outbound] [pid: 2685575] 9 files in my load queue
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [-] [core] [outbound] [pid: 2685575] 4 files in my temp fail queue
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [-] [core] loading tls.ini
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [9737B42C-0DE0-4236-AD1F-B938DA5028AF.1.1] [outbound] Attempting to deliver to: host:25 (0) (4)
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [B664946E-8620-4B34-888D-7C2C1B5B714E.1.1] [outbound] Looking up A records for: domain
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [9836BE0E-240D-4038-8439-4325366E3317.1.1] [outbound] Looking up A records for: domain
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [B664946E-8620-4B34-888D-7C2C1B5B714E.1.1] [outbound] Attempting to deliver to: host:25 (0) (4)
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [9836BE0E-240D-4038-8439-4325366E3317.1.1] [outbound] Attempting to deliver to: host:25 (0) (4)
Dec 12 12:14:41 hostname haraka[2685553]: [INFO] [-] [core] [outbound] Socket [outbound::25:98.136.96.75:103.229.166.174:50] in pool got FIN
Dec 12 12:14:41 hostname haraka[2685553]: [CRIT] [-] [core] Error: Resource not currently part of this pool
Dec 12 12:14:41 hostname haraka[2685553]: [CRIT] [-] [core]     at Pool.destroy (/opt/smtp/haraka/node_modules/generic-pool/lib/Pool.js:548:9)
Dec 12 12:14:41 hostname haraka[2685553]: [CRIT] [-] [core]     at sockend (/opt/smtp/haraka/outbound/client_pool.js:179:37)
Dec 12 12:14:41 hostname haraka[2685553]: [CRIT] [-] [core]     at pluggableStream.<anonymous> (/opt/smtp/haraka/outbound/client_pool.js:171:9)
Dec 12 12:14:41 hostname haraka[2685553]: [CRIT] [-] [core]     at Object.onceWrapper (node:events:627:28)
Dec 12 12:14:41 hostname haraka[2685553]: [CRIT] [-] [core]     at pluggableStream.emit (node:events:513:28)
Dec 12 12:14:41 hostname haraka[2685553]: [CRIT] [-] [core]     at TLSSocket.<anonymous> (/opt/smtp/haraka/tls_socket.js:79:18)
Dec 12 12:14:41 hostname haraka[2685553]: [CRIT] [-] [core]     at TLSSocket.emit (node:events:525:35)
Dec 12 12:14:41 hostname haraka[2685553]: [CRIT] [-] [core]     at endReadableNT (node:internal/streams/readable:1358:12)
Dec 12 12:14:41 hostname haraka[2685553]: [CRIT] [-] [core]     at processTicksAndRejections (node:internal/process/task_queues:83:21)
Dec 12 12:14:41 hostname haraka[2685553]: [NOTICE] [-] [core] Shutting down
Dec 12 12:14:41 hostname haraka[2684402]: [NOTICE] [-] [core] worker 37 exited with error code: 1
Dec 12 12:14:41 hostname haraka[2684402]: [NOTICE] [-] [core] worker started worker=43 pid=2685625
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [5EA17318-5D7B-4EF8-85EC-DF9520FF9A9A.1.1] [outbound] Attempting to deliver to: host:25 (0) (4)
Dec 12 12:14:41 hostname haraka[2685614]: [INFO] [0483117B-8284-46DF-B531-1C76EA700C8E.1.1] [outbound] Attempting to deliver to: host:25 (0) (4)
Dec 12 12:14:42 hostname haraka[2685625]: loaded TLD files:
Dec 12 12:14:42 hostname haraka[2685625]:   1=1495
Dec 12 12:14:42 hostname haraka[2685625]:   2=8570
Dec 12 12:14:42 hostname haraka[2685625]:   3=2448
Dec 12 12:14:42 hostname haraka[2685625]: loaded 9192 Public Suffixes
Dec 12 12:14:42 hostname haraka[2685614]: [INFO] [A790AC08-CEA1-467D-9BE6-D6A6DCF9087B.1.1] [outbound] Attempting to deliver to: host:25 (0) (4)
Dec 12 12:14:42 hostname haraka[2685614]: [INFO] [26798F4D-0A2C-4F1B-91C4-837622BA46DC.1.1] [outbound] Attempting to deliver to: host:25 (0) (4)
Dec 12 12:14:42 hostname haraka[2685614]: [INFO] [7012500A-CA82-44AD-BE72-D2E113D2CBD1.1.1] [outbound] Attempting to deliver to: host:25 (0) (4)
Dec 12 12:14:42 hostname haraka[2685625]: loglevel: INFO
Dec 12 12:14:42 hostname haraka[2685625]: log format: DEFAULT
Dec 12 12:14:42 hostname haraka[2685625]: Starting up Haraka version 2.8.28
Dec 12 12:14:42 hostname haraka[2685625]: [INFO] [-] [core] Loading plugins
Dec 12 12:14:42 hostname haraka[2685625]: [INFO] [-] [core] Loading plugin: **internal**_load_my_config
Dec 12 12:14:42 hostname haraka[2685625]: [INFO] [-] [**internal**_load_my_config] Loading some parameter on **internal** delivery system.
Dec 12 12:14:42 hostname haraka[2685625]: [INFO] [-] [core] Loading plugin: toobusy
Dec 12 12:14:42 hostname haraka[2685625]: [INFO] [-] [core] Loading plugin: tls
Dec 12 12:14:42 hostname haraka[2685625]: [INFO] [-] [core] loading tls.ini
Dec 12 12:14:42 hostname haraka[2685625]: [INFO] [-] [core] Loading plugin: **internal**_auth
Dec 12 12:14:42 hostname haraka[2685625]: [INFO] [-] [core] Loading plugin: rcpt_to.in_host_list
Dec 12 12:14:42 hostname haraka[2685625]: [INFO] [-] [core] Loading plugin: **internal**_relayall
Dec 12 12:14:42 hostname haraka[2685625]: [INFO] [-] [core] Loading plugin: **internal**_data_post
Dec 12 12:14:42 hostname haraka[2685625]: [INFO] [-] [core] Loading plugin: **internal**_dkim_sign
Dec 12 12:14:42 hostname haraka[2685625]: [INFO] [-] [core] Loading plugin: **internal**_report
Dec 12 12:14:42 hostname haraka[2685625]: [INFO] [-] [core] Loading plugin: status
Dec 12 12:14:42 hostname haraka[2685625]: [INFO] [-] [core] getting SocketOpts for SMTPS server
Dec 12 12:14:42 hostname haraka[2685625]: [INFO] [-] [core] Creating TLS server on [::0]:465
Dec 12 12:14:42 hostname haraka[2685625]: [INFO] [-] [core] [outbound] Loading queue for pid: 2685553
Dec 12 12:14:42 hostname haraka[2685625]: [INFO] [-] [core] [outbound] Loading outbound queue from /opt/smtp/haraka/queue
Dec 12 12:14:42 hostname haraka[2685625]: [NOTICE] [-] [core] Listening on [::0]:465
Dec 12 12:14:42 hostname haraka[2684402]: [NOTICE] [-] [core] worker 43 listening on [::0]:465
Dec 12 12:14:42 hostname haraka[2685625]: [NOTICE] [-] [core] Listening on [::0]:587
Dec 12 12:14:42 hostname haraka[2684402]: [NOTICE] [-] [core] worker 43 listening on [::0]:587
Dec 12 12:14:42 hostname haraka[2685625]: [NOTICE] [-] [core] Listening on [::0]:2525
Dec 12 12:14:42 hostname haraka[2684402]: [NOTICE] [-] [core] worker 43 listening on [::0]:2525
Dec 12 12:14:42 hostname haraka[2685625]: [INFO] [-] [core] [outbound] Grabbing queue files for pid: 2685553
Dec 12 12:14:42 hostname haraka[2685625]: [INFO] [-] [core] [outbound] [pid: 2685553] 11 files old PID queue fixed up
Dec 12 12:14:42 hostname haraka[2685625]: [INFO] [-] [core] [outbound] [pid: 2685553] 0 files in my delivery queue
Dec 12 12:14:42 hostname haraka[2685625]: [INFO] [-] [core] [outbound] [pid: 2685553] 8 files in my load queue
Dec 12 12:14:42 hostname haraka[2685625]: [INFO] [-] [core] [outbound] [pid: 2685553] 3 files in my temp fail queue
Dec 12 12:14:42 hostname haraka[2685625]: [INFO] [-] [core] loading tls.ini
Dec 12 12:14:42 hostname haraka[2684402]: [CRIT] [-] [core] Error [ERR_IPC_CHANNEL_CLOSED]: Channel closed
Dec 12 12:14:42 hostname haraka[2684402]: [CRIT] [-] [core]     at new NodeError (node:internal/errors:387:5)
Dec 12 12:14:42 hostname haraka[2684402]: [CRIT] [-] [core]     at ChildProcess.target.send (node:internal/child_process:749:16)
Dec 12 12:14:42 hostname haraka[2684402]: [CRIT] [-] [core]     at Worker.send (node:internal/cluster/worker:48:10)
Dec 12 12:14:42 hostname haraka[2684402]: [CRIT] [-] [core]     at /opt/smtp/haraka/plugins/status.js:178:20
Dec 12 12:14:42 hostname haraka[2684402]: [CRIT] [-] [core]     at /opt/smtp/haraka/node_modules/async/dist/async.js:251:13
Dec 12 12:14:42 hostname haraka[2684402]: [CRIT] [-] [core]     at wrapper (/opt/smtp/haraka/node_modules/async/dist/async.js:271:20)
Dec 12 12:14:42 hostname haraka[2684402]: [CRIT] [-] [core]     at iterateeCallback (/opt/smtp/haraka/node_modules/async/dist/async.js:427:28)
Dec 12 12:14:42 hostname haraka[2684402]: [CRIT] [-] [core]     at /opt/smtp/haraka/node_modules/async/dist/async.js:327:20
Dec 12 12:14:42 hostname haraka[2684402]: [CRIT] [-] [core]     at /opt/smtp/haraka/node_modules/async/dist/async.js:248:17
Dec 12 12:14:42 hostname haraka[2684402]: [CRIT] [-] [core]     at Timeout._onTimeout (/opt/smtp/haraka/plugins/status.js:240:9)
Dec 12 12:14:42 hostname haraka[2684402]: [NOTICE] [-] [core] Shutting down
Dec 12 12:14:42 hostname haraka[2685603]: [NOTICE] [-] [core] Shutting down
Dec 12 12:14:42 hostname haraka[2685564]: [NOTICE] [-] [core] Shutting down
Dec 12 12:14:42 hostname haraka[2685625]: [NOTICE] [-] [core] Shutting down
Dec 12 12:14:42 hostname haraka[2685614]: [NOTICE] [-] [core] Shutting down

Error: Resource not currently part of this pool are normally happen when socket is being closed, and it doesn't shutting down haraka completely. But ERR_IPC_CHANNEL_CLOSED seems did send shutting down signal.

We use this plugin at other server but didn't have issue, same node and os version too. But this happen, on only 2 of our relay.

[analogic]

Please can you create PR to handle this situation? I am afraid I would not able to reproduce the bug and I can't fix that only with backtrace.

[gamalan]

@analogic problem is, I still don't know how to fix it. Also because it only happen on 2 server, I and my team haven't successfully find what kind of trigger that could reproduce the issue.

[msimerson]

I merged a PR earlier that will solve this problem Resource not currently part of this pool that you were having. That will help some. Try disabling the status plugin and then lets see what kind of errors you are still getting.

[gamalan]

@msimerson so far it haven't happen again. thanks.