fix(#5180): close secondary bindings after primary is closed by metcoder95 · Pull Request #5201 · fastify/fastify

metcoder95 · 2023-12-10T17:10:55Z

I tried to add a small test to reproduce it, it does covers the case but open to any suggestion to improve it.

Checklist

run npm run test and npm run benchmark
tests and/or benchmarks are included
documentation is changed or added
commit message and code follows the Developer's Certification of Origin
and the Code of conduct

Uzlopak

LGTM

tchapacan · 2023-12-11T14:21:53Z

Hello, sorry I’m quite new to the ecosystem (few weeks) but on my spare time I try follow some issues here and there and would be happy to help if needed.

Following initial work on this fix, after pulling this branch and playing arround, it seems the issue is still present using the reproduction example https://github.com/kingston/fastify-websocket-repro

Even after the fix I still encounter the issue :

Without connection: (still OK)

Closing main server
NET 35039: SERVER _emitCloseIfDrained
NET 35039: SERVER: emit close
Closing secondary server
NET 35039: SERVER _emitCloseIfDrained
NET 35039: SERVER: emit close

With connection: (KO)

Closing main server
NET 34756: destroy
NET 34756: close
NET 34756: close handle
NET 34756: has server
NET 34756: SERVER _emitCloseIfDrained
NET 34756: SERVER handle? true   connections? 1
NET 34756: SERVER _emitCloseIfDrained
NET 34756: SERVER handle? false   connections? 1
NET 34756: emit close
HTTP 34756: server socket close

If seems that in the callback function of the preClose, not all statement are evaluated using the else if causing the first true to be resolved and exit.
As far as I have understand (sorry I'm really new and don't manage all the codebase), to properly close the server we need absolutely all connection to be terminated before, so switching to multiple if statement might solved the issue ? 

Before :

fastify/fastify.js

Lines 434 to 452 in 71385a7

    
           if (fastify[kState].listening) { 
        
             /* istanbul ignore next: Cannot test this without Node.js core support */ 
        
             if (forceCloseConnections === 'idle') { 
        
               // Not needed in Node 19 
        
               instance.server.closeIdleConnections() 
        
             /* istanbul ignore next: Cannot test this without Node.js core support */ 
        
             } else if (serverHasCloseAllConnections && forceCloseConnections) { 
        
               instance.server.closeAllConnections() 
        
             } else if (forceCloseConnections === true) { 
        
               for (const conn of fastify[kKeepAliveConnections]) { 
        
                 // We must invoke the destroy method instead of merely unreffing 
        
                 // the sockets. If we only unref, then the callback passed to 
        
                 // `fastify.close` will never be invoked; nor will any of the 
        
                 // registered `onClose` hooks. 
        
                 conn.destroy() 
        
                 fastify[kKeepAliveConnections].delete(conn) 
        
               } 
        
             } 
        
           }

After (one possible proposition) :

if (fastify[kState].listening) {
    /* istanbul ignore next: Cannot test this without Node.js core support */
    if (forceCloseConnections === 'idle') {
      // Not needed in Node 19instance.server.closeIdleConnections()
      instance.server.closeIdleConnections()
    }
    if (serverHasCloseAllConnections && forceCloseConnections) {
      instance.server.closeAllConnections()
    }
    if (forceCloseConnections === true) {
      for (const conn of fastify[kKeepAliveConnections]) {
        // We must invoke the destroy method instead of merely unreffing
        // the sockets. If we only unref, then the callback passed to
        // `fastify.close` will never be invoked; nor will any of the
        // registered `onClose` hooks.
        conn.destroy()
        fastify[kKeepAliveConnections].delete(conn)
      }
    }
  }

Now it seems connection are properly close and server as well :

Closing main server
NET 35164: destroy
NET 35164: close
NET 35164: close handle
NET 35164: has server
NET 35164: SERVER _emitCloseIfDrained
NET 35164: SERVER handle? true   connections? 1
NET 35164: destroy
NET 35164: close
NET 35164: close handle
NET 35164: has server
NET 35164: SERVER _emitCloseIfDrained
NET 35164: SERVER handle? true   connections? 0
NET 35164: SERVER _emitCloseIfDrained
NET 35164: SERVER: emit close
Closing secondary server
NET 35164: SERVER _emitCloseIfDrained
NET 35164: SERVER: emit close

Does it seems correct to you ?

I can pull and push on top of this branch if needed or I can let you handle and update the code (test seems to pass on my local env)

mcollina

lgtm

metcoder95 · 2023-12-12T08:58:18Z

With connection: (KO)

It seems the log for the secondary server is missing, it never triggered in order.

tchapacan · 2023-12-12T09:43:15Z

Here logging for the failed scenario : (with some console.log at some keepoint in the logic)

$ NODE_DEBUG=net,http,timers node index.js
...
{"level":30,"time":1702373258116,"pid":1713,"hostname":"lalala","msg":"Received SIGINT signal. Shutting down..."}
start closing main server
start flushing idle connection
NET 1713: destroy
NET 1713: close
NET 1713: close handle
NET 1713: has server
NET 1713: SERVER _emitCloseIfDrained
NET 1713: SERVER handle? true   connections? 1
end flushing idle connection
NET 1713: SERVER _emitCloseIfDrained
NET 1713: SERVER handle? false   connections? 1
NET 1713: emit close
HTTP 1713: server socket close
{"level":50,"time":1702373263118,"pid":1713,"hostname":"lalala","err":{"type":"Error","message":"Shutdown timed out","stack":"Error: Shutdown timed out\n    at Timeout._onTimeout (/Users/lalalala/nodejourney/fastify-websocket-repro/index.js:25:23)\n    at listOnTimeout (node:internal/timers:573:17)\n    at process.processTimers (node:internal/timers:514:7)"},"msg":"Shutdown timed out"}

Here logging after proposition of modify the else if into a multiple if statement in the preClose callback function

$ NODE_DEBUG=net,http,timers node index.js
...
{"level":30,"time":1702373627585,"pid":1985,"hostname":"lalalala","msg":"Received SIGINT signal. Shutting down..."}
start closing main server
start flushing idle connection
NET 1985: destroy
NET 1985: close
NET 1985: close handle
NET 1985: has server
NET 1985: SERVER _emitCloseIfDrained
NET 1985: SERVER handle? true   connections? 1
end flushing idle connection
start flushing all connection
NET 1985: destroy
NET 1985: close
NET 1985: close handle
NET 1985: has server
NET 1985: SERVER _emitCloseIfDrained
NET 1985: SERVER handle? true   connections? 0
end flushing all connection
NET 1985: SERVER _emitCloseIfDrained
NET 1985: SERVER: emit close
start closing secoundary server
NET 1985: SERVER _emitCloseIfDrained
start flushing connection
end closing secoundary server
end closing main server
NET 1985: SERVER: emit close

I was suspecting that all connection wasn't properly flushed before closing the main server, causing the timeout in the first scenario. And the secondary server to never being properly close ? The else if statement was my suspect here :

fastify/fastify.js

Lines 434 to 452 in 71385a7

    
           if (fastify[kState].listening) { 
        
             /* istanbul ignore next: Cannot test this without Node.js core support */ 
        
             if (forceCloseConnections === 'idle') { 
        
               // Not needed in Node 19 
        
               instance.server.closeIdleConnections() 
        
             /* istanbul ignore next: Cannot test this without Node.js core support */ 
        
             } else if (serverHasCloseAllConnections && forceCloseConnections) { 
        
               instance.server.closeAllConnections() 
        
             } else if (forceCloseConnections === true) { 
        
               for (const conn of fastify[kKeepAliveConnections]) { 
        
                 // We must invoke the destroy method instead of merely unreffing 
        
                 // the sockets. If we only unref, then the callback passed to 
        
                 // `fastify.close` will never be invoked; nor will any of the 
        
                 // registered `onClose` hooks. 
        
                 conn.destroy() 
        
                 fastify[kKeepAliveConnections].delete(conn) 
        
               } 
        
             } 
        
           }

But if you aren't able to reproduce it anymore with your fix then it might be my local setup maybe sorry!

Note that i try to reproduce the scenario here https://github.com/kingston/fastify-websocket-repro and i close the server immediately after having established a session with the browser, i don't let the socket die by entering in timeout

Uzlopak · 2023-12-12T10:25:04Z

@metcoder95 What about the remark of @tchapacan ?

CI is green. Ready to merge?

metcoder95 · 2023-12-12T19:29:31Z

But if you aren't able to reproduce it anymore with your fix then it might be my local setup maybe sorry!

No worries @tchapacan, nothing to worry about it is helpful what you provide so I can thoroughly test the fix. Sadly I couldn't reproduce the problem it after this fix, and it behave exactly the same as we were deleting the else/if from your xample:

node index.js
closing primary
secondary server closed

Using DEBUG:

NET 20920: setupListenHandle ::1 3000 6 0 undefined <- primary
NET 20920: setupListenHandle: create a handle
NET 20920: bind to ::1
NET 20920: setupListenHandle 127.0.0.1 3000 4 0 undefined <- secondary
NET 20920: setupListenHandle: create a handle
NET 20920: bind to 127.0.0.1
NET 20920: onconnection
NET 20920: _read
NET 20920: Socket._handle.readStart
HTTP 20920: SERVER new http connection
(node:20920) Warning: Setting the NODE_DEBUG environment variable to 'http' can expose sensitive data (such as passwords, tokens and authentication headers) in the resulting log.
(Use `node --trace-warnings ...` to show where the warning was created)
HTTP 20920: SERVER socketOnParserExecute 533
HTTP 20920: SERVER upgrade or connect GET
HTTP 20920: SERVER have listener for upgrade
^Chello world! undefined
NET 20920: SERVER _emitCloseIfDrained
NET 20920: SERVER handle? false   connections? 1
NET 20920: _final: not ended, call shutdown()
NET 20920: _read
NET 20920: afterShutdown destroyed=false
NET 20920: destroy
NET 20920: close
NET 20920: close handle
NET 20920: has server
NET 20920: SERVER _emitCloseIfDrained <- primary
NET 20920: SERVER: emit close
NET 20920: SERVER _emitCloseIfDrained <- secondary
NET 20920: SERVER: emit close

I believe the PR should be okay to go for now, we can always open a new issue if we face the same happening.

github-actions · 2024-12-14T00:29:23Z

This pull request has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.

fix(#5180): close secondary bindings after primary is closed

71385a7

Uzlopak approved these changes Dec 11, 2023

View reviewed changes

test: handle ipv6 correctly

6aa329a

mcollina approved these changes Dec 12, 2023

View reviewed changes

Uzlopak merged commit cd84d13 into main Dec 12, 2023

Uzlopak deleted the fix/5180 branch December 12, 2023 19:54

github-actions bot locked as resolved and limited conversation to collaborators Dec 14, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

fix(#5180): close secondary bindings after primary is closed#5201

fix(#5180): close secondary bindings after primary is closed#5201
Uzlopak merged 2 commits intomainfrom
fix/5180

metcoder95 commented Dec 10, 2023 •

edited

Loading

Uh oh!

Uzlopak left a comment

Uh oh!

tchapacan commented Dec 11, 2023 •

edited

Loading

Uh oh!

mcollina left a comment

Uh oh!

metcoder95 commented Dec 12, 2023

Uh oh!

tchapacan commented Dec 12, 2023 •

edited

Loading

Uh oh!

Uzlopak commented Dec 12, 2023

Uh oh!

metcoder95 commented Dec 12, 2023

Uh oh!

github-actions bot commented Dec 14, 2024

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

Uh oh!

Conversation

metcoder95 commented Dec 10, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Checklist

Uh oh!

Uzlopak left a comment

Choose a reason for hiding this comment

Uh oh!

tchapacan commented Dec 11, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

mcollina left a comment

Choose a reason for hiding this comment

Uh oh!

metcoder95 commented Dec 12, 2023

Uh oh!

tchapacan commented Dec 12, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Uzlopak commented Dec 12, 2023

Uh oh!

metcoder95 commented Dec 12, 2023

Uh oh!

github-actions bot commented Dec 14, 2024

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

metcoder95 commented Dec 10, 2023 •

edited

Loading

tchapacan commented Dec 11, 2023 •

edited

Loading

tchapacan commented Dec 12, 2023 •

edited

Loading