New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[core] aborting disconnect hook #2167

Closed
analogic opened this Issue Oct 2, 2017 · 5 comments

Comments

Projects
None yet
4 participants
@analogic
Contributor

analogic commented Oct 2, 2017

Hello,

due

if (client_disconnected(object)) {

it seems that plugin hooks to disconnect event are not executed.

Is it expected behaviour and hook_disconnect should not be really used in production or am I missing something?

...
2017-10-02 15:14:01.164201500  [DEBUG] [A1AD977B-E3A7-4F46-84F8-73C3355FA8FD.1] [core] running reset_transaction hook in karma plugin
2017-10-02 15:14:01.165534500  [INFO] [A1AD977B-E3A7-4F46-84F8-73C3355FA8FD.1] [karma] score: -2, good: 0, bad: 0, connections: 59, history: 0, awards: 012,013, fail:rfc5321.MailFrom, rfc5321.RcptTo
2017-10-02 15:14:01.166130500  [DEBUG] [A1AD977B-E3A7-4F46-84F8-73C3355FA8FD.1] [core]  hook=reset_transaction plugin=karma function=hook_reset_transaction params="" retval=CONT msg=""
2017-10-02 15:14:01.176696500  [INFO] [A1AD977B-E3A7-4F46-84F8-73C3355FA8FD.1] [core] client [172.20.0.1] half closed connection
2017-10-02 15:14:01.178321500  [DEBUG] [A1AD977B-E3A7-4F46-84F8-73C3355FA8FD.1] [core] client has disconnected
2017-10-02 15:14:01.178669500  [DEBUG] [A1AD977B-E3A7-4F46-84F8-73C3355FA8FD.1] [core] aborting disconnect hook

system info

Haraka Haraka.js — Version: 2.8.16
Node v8.6.0
OS Linux 3c3555e2d998 4.10.0-041000-generic #201702191831 SMP Sun Feb 19 23:33:19 UTC 2017 x86_64 GNU/Linux
openssl OpenSSL 1.1.0f 25 May 2017
@smfreegard

This comment has been minimized.

Collaborator

smfreegard commented Oct 2, 2017

Is it expected behaviour

No - hook_disconnect() should always run on disconnect. This looks very much like a bug.

@KingNoosh KingNoosh added the Bug label Oct 2, 2017

@analogic

This comment has been minimized.

Contributor

analogic commented Oct 3, 2017

Strange thing is that 2.8.14 with 8.4 node in production works ok

2017-10-03 07:22:20.709802500  [PROTOCOL] [BF0CCEEE-75C9-48E2-82CA-FD96F21C0AF7.1] [core] C: QUIT state=1
2017-10-03 07:22:20.709881500  [DEBUG] [BF0CCEEE-75C9-48E2-82CA-FD96F21C0AF7.1] [core] running quit hooks
2017-10-03 07:22:20.710090500  [PROTOCOL] [BF0CCEEE-75C9-48E2-82CA-FD96F21C0AF7.1] [core] S: 221 .... closing connection. Have a jolly good day.
2017-10-03 07:22:20.711155500  [DEBUG] [BF0CCEEE-75C9-48E2-82CA-FD96F21C0AF7.1] [core] hook=disconnect plugin=log_transaction function=log_connection_end params="" retval=CONT msg=""
2017-10-03 07:22:20.711308500  [DEBUG] [BF0CCEEE-75C9-48E2-82CA-FD96F21C0AF7.1] [core] running disconnect hook in tls plugin
2017-10-03 07:22:20.711465500  [DEBUG] [BF0CCEEE-75C9-48E2-82CA-FD96F21C0AF7.1] [core] hook=disconnect plugin=tls function=hook_disconnect params="" retval=CONT msg=""
2017-10-03 07:22:20.711675500  [NOTICE] [BF0CCEEE-75C9-48E2-82CA-FD96F21C0AF7.1] [core] disconnect ip=172.17.0.1 rdns="NXDOMAIN" helo="localhost" relay=Y early=N esmtp=Y tls=Y pipe=N errors=0 txns=1 rcpts=1/0/0 msgs=1/0/0 bytes=44164 lr="" time=0.619

But exactly same send email script with 2.8.16 and Node 8.6 tested localy produces this

2017-10-03 07:30:45.434047500  [PROTOCOL] [2E19F1D6-556D-42F6-B229-667AE1429212.1] [core] C: QUIT state=1
2017-10-03 07:30:45.434490500  [DEBUG] [2E19F1D6-556D-42F6-B229-667AE1429212.1] [core] running quit hooks
2017-10-03 07:30:45.435040500  [PROTOCOL] [2E19F1D6-556D-42F6-B229-667AE1429212.1] [core] S: 221 ... closing connection. Have a jolly good day.
2017-10-03 07:30:45.435737500  [DEBUG] [2E19F1D6-556D-42F6-B229-667AE1429212.1] [core] client has disconnected
2017-10-03 07:30:45.435857500  [DEBUG] [2E19F1D6-556D-42F6-B229-667AE1429212.1] [core] aborting disconnect hook

I can't find any changes affecting connection handling between those versions

@smfreegard smfreegard added the Blocker label Oct 4, 2017

@smfreegard

This comment has been minimized.

Collaborator

smfreegard commented Oct 4, 2017

I've just hit this bug. It's totally broken in the current version for some reason. I'm just tracking it down now.

smfreegard added a commit to smfreegard/Haraka that referenced this issue Oct 4, 2017

smfreegard added a commit to smfreegard/Haraka that referenced this issue Oct 4, 2017

@smfreegard

This comment has been minimized.

Collaborator

smfreegard commented Oct 4, 2017

@analogic - if you can try #2184, that would be a great help.

@msimerson

This comment has been minimized.

Member

msimerson commented Oct 4, 2017

I think I have a clue. When I did the connection state constants change, I found this chunk of code that referenced a non-existing constant. I raised that issue in #2121 noting that I fixed that. I think that explains the change in behavior.

smfreegard added a commit that referenced this issue Oct 5, 2017

Fix disconnect hooks (#2184)
* Fixes #2167

* I hate ESLint

atheken added a commit to wildbit/Haraka that referenced this issue Oct 5, 2017

gramakri added a commit to cloudron-io/Haraka that referenced this issue Oct 29, 2017

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment