[bug] semaphore not released on exit/premature

[Tieske]

consider this code:

init_worker_by_lua_block {
  local sema = require("ngx.semaphore").new()

  ngx.timer.at(0, function()
    -- wait for semaphore
    local t = ngx.now()
    local ok, err = sema:wait(45)
    print("sema was released after " .. tostring( ngx.now()-t).." seconds. ".. tostring(ok).." "..tostring(err))
  end)

  ngx.timer.at(30, function(premature)
    -- release semaphore
    if premature then
      print "released prematurely"
    else
      print "released upon expiry"
    end
    sema:post(1000)
  end)
}

Semaphore waits for 45 seconds. A timer posts resources after 30 seconds.

When I run the code and wait more than 30 seconds, I get (as expected) this in the logs:

2021/02/08 15:49:11 [notice] 57184#0: start worker process 57185
2021/02/08 15:49:41 [notice] 57185#0: *3 [lua] resty-test.lua:60: released upon expiry, context: ngx.timer
2021/02/08 15:49:41 [notice] 57185#0: *2 [lua] resty-test.lua:52: sema was released after 29.963999986649 seconds. true nil, context: ngx.timer

After 30 seconds the semaphore is released.

However, when I send a QUIT signal during the first 30 seconds I get this (unexpected) result:

2021/02/08 15:50:07 [notice] 57888#0: start worker process 57889
2021/02/08 15:50:13 [notice] 58011#0: signal process started
2021/02/08 15:50:13 [notice] 57888#0: signal 3 (SIGQUIT) received from 58011, shutting down
2021/02/08 15:50:13 [notice] 57888#0: signal 23 (SIGIO) received from 57889
2021/02/08 15:50:13 [notice] 57889#0: gracefully shutting down
2021/02/08 15:50:13 [notice] 57889#0: *3 [lua] resty-test.lua:58: released prematurely, context: ngx.timer
2021/02/08 15:50:52 [notice] 57889#0: *2 [lua] resty-test.lua:52: sema was released after 45.000999927521 seconds. false timeout, context: ngx.timer
2021/02/08 15:50:52 [notice] 57889#0: exiting
2021/02/08 15:50:52 [notice] 57889#0: exit
2021/02/08 15:50:52 [notice] 57888#0: signal 20 (SIGCHLD) received from 57889
2021/02/08 15:50:52 [notice] 57888#0: worker process 57889 exited with code 0
2021/02/08 15:50:52 [notice] 57888#0: exit

at 15:50:13 the resources are posted, but at 15:50:52 (39 seconds later) the semaphore times out.

Version info:

  resty -v
  resty 0.25
  nginx version: openresty/1.17.8.2
  built with OpenSSL 1.1.1h  22 Sep 2020
  TLS SNI support enabled

[bungle]

I feel like this is a generic issue in OpenResty, not just semaphores. Sleeps (or timers) prevent graceful exit, and they are not woken up on quit/reload. Same issue is with sock:recv, sock:send, semaphore:wait, ngx.sleep as they probably just use same backend constructs.

It would be better to prematurely woke up any sleeps/timers on exit, and then it is up to code to check whether ngx.worker.exiting().

[Tieske]

If, in the above example, I change:

    sema:post(1000)

into

    sema:post(1000)
    ngx.timer.at(0, function()
      ngx.log(ngx.WARN,"please ignore")
    end)

then it works as expected.

ping @javierguerragiraldez

[javierguerragiraldez]

@dndx and I have been doing some cechking on this. in short, as documented, sema:post() will not yield the current light thread. it seems a simple ngx.sleep(0) after the :post() is enough to make it work. i would expect the termination of the timer function should work too, but it doesn't. I see the timer function runs under a "fake request", which does a lot of cleanup when finalized, but apparently doesn't signal the sema:wait() timers on other requests.

[Tieske]

@javierguerragiraldez just tested, and indeed just yielding seems enough. So in the example above this is the simplest fix:

  ngx.timer.at(30, function(premature)
    -- release semaphore
    sema:post(1000)
    if premature then
      print "released prematurely"
      ngx.sleep(0)    -- FIXME: required to properly release the waiting threads
    else
      print "released upon expiry"
    end
  end)

[Tieske]

this seems to have been fixed. Can no longer reproduce on openresty/1.25.3.1.