SIGTERM to a busy daemon has no impact

[Caleb Tennis]

This problem also manifests with object-expirer as detailed here:

http://paste.openstack.org/show/483518/

Original notes:

During some testing Paul Luse and I found that swift-init stop on some nodes in a cluster was failing repeatedly. It is sending a SIGTERM to all swift processes, but the reconstructor wasn't stopping and after 15 seconds it times out. Multiple attempts also failed.

stracing the reconstructor it was chugging away doing operations. Concurrency on the reconstructor may have been set fairly high.

It seems likely it's batched some jobs and is waiting for them to complete before it acknowledges the HUP and eventually shuts down, but it felt like it was on the order of many minutes if not longer before it would get to that point. Perhaps there's some room to be more graceful here, otherwise folks are just going to start using swift-init kill more frequently.

[clayg (clay-gerrard)]

I updated this bug s/SIGHUP/SIGTERM/ after confirming that in all cases (reload, stop, restart) swift *daemons* receive signal number 15 (not 1 like proxy and other graceful shutdown servers support).

I think Caleb was seeing a busy reconstructor not shutting down after receiving SIGTERM - which is just as bad.

In dev the reconstructor shuts down responsively to `swift-init object-reconstructor stop` (the console output confirms signal # 15). Both reload and restart also use signal 15, and the reconstructor responds appropriately and responsively. So this is not a trivial/obvious issue.

The reconstructor (and all swift daemons) do install a signal handler for SIGTERM [1] in order to ensure the TERM is forwarded to the progress group to kill any forked children if they have any. It's possible that this signal handler isn't doing the right thing - but more likely that the reconstructor had just gotten itself into some uninterruptible state.

It maybe be simple to reproduce by loading some data into a development environment and getting reconstructors going then trying to stop them. If that doesn't work we'll have to set to incomplete and get some more information (e.g. when you kill (default is SIGTERM to just the parent pid) from the command line is the behavior different? Maybe the process group SIGTERM (you can do process group kill from the command line by making the pid negative, i believe) is less good for the reconstructor/pyeclib? If you SIGKILL (-9) do they die or become zombies?

1. swift.common.daemon.Daemon.run

[Caleb Tennis (ctennis)]

I'll update: in my testing this past week, using "swift-init stop object-reconstructor" operated quickly and it shutdown fine. So my hunch is that this behavior of it ignoring sigterm must be in the middle of some long running job.

[paul luse (paul-e-luse)]

so its still happening on the 15 node EC perf cluster here. Hard to describe exact steps to repro as we run into it when we finish a 48 hour per run and want to clean the cluster before the next run. Our process is to stop Swiftstack node daemon (we use Swiftstack here of course) on all nodes, use swift-init stop all on all nodes, rm -rf everything from the device dirs on down. It can take 6-8 hours to delete everything following a complete run and 90% of the time there are still 100-200 objects left on each node and at that time the EC recon is still showing as an active process. For now we've just scripted a reboot following the long delete and then its a very quick delete to cleanup the remaining files following reboot.

So, unclear just how 'busy' the EC recon needs to be or whether its a function of the size of hashes.pkl or something else?

[clayg (clay-gerrard)]

Possible fix:

https://review.openstack.org/#/c/259347/1

[Hisashi Osanai (osanai-hisashi)]

Do you have logs when it happens?

The following log should be outputted :
https://github.com/openstack/swift/blob/master/swift/common/middleware/catch_errors.py#L43

[clayg (clay-gerrard)]

Using the scripts in the paste:

http://paste.openstack.org/show/483518/

I found it helpful to reduce my frequency tunables in my expirer.conf:

[object-expirer]
interval = 1
report_interval = 10
concurrency = 10

I was able to reproduce:

May 2 19:27:07 saio swift: Error: An error occurred:
Traceback (most recent call last):
  File "/vagrant/swift/swift/common/middleware/catch_errors.py", line 41, in handle_request
    resp = self._app_call(env)
  File "/vagrant/swift/swift/common/wsgi.py", line 1042, in _app_call
    resp = self.app(env, self._start_response)
  File "/vagrant/swift/swift/common/middleware/memcache.py", line 109, in __call__
    return self.app(env, start_response)
  File "/vagrant/swift/swift/proxy/server.py", line 307, in __call__
    return self.handle_request(req)(env, start_response)
  File "/vagrant/swift/swift/proxy/server.py", line 411, in handle_request
    return handler(req)
  File "/vagrant/swift/swift/proxy/controllers/base.py", line 264, in wrapped
    return func(*a, **kw)
  File "/vagrant/swift/swift/proxy/controllers/container.py", line 217, in DELETE
    req.swift_entity_path, headers)
  File "/vagrant/swift/swift/proxy/controllers/base.py", line 1472, in make_requests
    for resp in pile:
  File "/vagrant/swift/swift/common/utils.py", line 2578, in next
    rv = self._responses.get()
  File "/usr/local/lib/python2.7/dist-packages/eventlet/queue.py", line 313, in get
    return waiter.wait()
  File "/usr/local/lib/python2.7/dist-packages/eventlet/queue.py", line 141, in wait
    return get_hub().switch()
  File "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 294, in switch
    return self.greenlet.switch()
  File "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 336, in run
    self.fire_timers(self.clock())
  File "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 457, in fire_timers
    timer()
  File "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/timer.py", line 58, in __call__
    cb(*args, **kw)
  File "/usr/local/lib/python2.7/dist-packages/eventlet/greenthread.py", line 214, in main
    result = function(*args, **kwargs)
  File "/vagrant/swift/swift/common/utils.py", line 2522, in _run_func
    self._responses.put(func(*args, **kwargs))
  File "/vagrant/swift/swift/proxy/controllers/base.py", line 1418, in _make_request
    headers=headers, query_string=query)
  File "/vagrant/swift/swift/common/bufferedhttp.py", line 214, in http_connect
    ipaddr, port, method, path, headers, query_string, ssl)
  File "/vagrant/swift/swift/common/bufferedhttp.py", line 246, in http_connect_raw
    conn.endheaders()
  File "/usr/lib/python2.7/httplib.py", line 975, in endheaders
    self._send_output(message_body)
  File "/usr/lib/python2.7/httplib.py", line 835, in _send_output
    self.send(msg)
  File "/usr/lib/python2.7/httplib.py", line 797, in send
    self.connect()
  File "/vagrant/swift/swift/common/bufferedhttp.py", line 158, in connect
    ret = HTTPConnection.connect(self)
  File "/usr/lib/python2.7/httplib.py", line 778, in connect
    self.timeout, self.source_address)
  File "/usr/local/lib/python2.7/dist-packages/eventlet/green/socket...

[clayg (clay-gerrard)]

Interesting to note, when catch_errors "handles" the SystemExit - the user of internal_client recognizes it as a 503 and continues doing it's normal operation (not locked up, not dead) - but *additional* SIGTERM has no effect.

Note that the daemon SIGTERM handler sets the behavior of SIGTERM to SIG_IGN when it receives TERM before raising SystemExit (doh!)

[Darrell Bishop (darrellb)]

FWIW, here's an strace while the container-reconciler ignored my SIGTERM (15)

...
sendto(5, "<134>container-reconciler: sleep"..., 60, 0, NULL, 0) = 60
select(0, NULL, NULL, NULL, {30, 0}) = ? ERESTARTNOHAND (To be restarted if no handler)
--- SIGTERM {si_signo=SIGTERM, si_code=SI_USER, si_pid=34764, si_uid=0} ---
select(0, NULL, NULL, NULL, {22, 896221}) = 0 (Timeout)
read(10, "~X+`-\274jm_\353fhqSvO", 16) = 16
...

[Darrell Bishop (darrellb)]

With a SIGTERM, I see

select(0, NULL, NULL, NULL, {11, 716422}
) = ? ERESTARTNOHAND (To be restarted if no handler)
--- SIGINT {si_signo=SIGINT, si_code=SI_USER, si_pid=34764, si_uid=0} ---
rt_sigreturn() = -1 EINTR (Interrupted system call)
sendto(5, "<134>container-reconciler: User "..., 37, 0, NULL, 0) = 37
sendto(5, "<134>container-reconciler: Exite"..., 34, 0, NULL, 0) = 34
close(3) = 0
...
[shutdown completes straightforwardly]

[clayg (clay-gerrard)]

Worth noting that once you discover this issue swift-init has native support to track down the pid and do the brutal:

ubuntu@saio:~$ swift-init container-reconciler kill --kill-after-timeout --kill-wait=1
Signal container-reconciler pid: 11855 signal: 15
Waited 1 seconds for container-reconciler to die; killing
Signal container-reconciler pid: 11855 signal: 9
No container-reconciler running

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/259347
Committed: https://git.openstack.org/cgit/openstack/swift/commit/?id=c2ce92acd6fa25706e271dc2b1504a8db54bd2ae
Submitter: Jenkins
Branch: master

commit c2ce92acd6fa25706e271dc2b1504a8db54bd2ae
Author: Clay Gerrard <email address hidden>
Date: Tue Oct 11 13:23:11 2016 -0700

    Fix signal handling for daemons with InternalClient

    The intentional use of "bare except" handling in catch_errors and some
    daemons to prevent propagation on unexpected errors that do not
    inherit from Exception (like eventlet.Timeout) or even BaseException
    (like old-style classes) has the side effect of spuriously "handling"
    *expected* errors like when a signal handler raises SystemExit.

    The signal handler installed in our Daemon is intended to ensure first
    that the entire process group and any forked processes (like rsync's)
    receive the SIGTERM signal and also that the process itself
    terminates.

    The use of sys.exit was not a concious grandiose plans for graceful
    shutdown (like the running[0] = False trick that wsgi server parent
    process do) - the desired behavior for SIGTERM is to stop - hard.

    This change ensures the original goals and intentions of our signal
    handler are fulfilled without the undesirable side effect that can
    cause our daemons to confusingly log an expected message to stop as an
    unexpected error, and start ignoring additional SIGTERM messages;
    forcing our kind operators to resort to brutal process murder.

    Closes-Bug: #1489209
    Change-Id: I9d2886611f6db2498cd6a8f81a58f2a611f40905

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/newton
Review: https://review.openstack.org/399533

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/swift 2.11.0 release.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/399533
Committed: https://git.openstack.org/cgit/openstack/swift/commit/?id=1f07ccb9bc015f030b5a50d0bf8d63423c7af029
Submitter: Jenkins
Branch: stable/newton

commit 1f07ccb9bc015f030b5a50d0bf8d63423c7af029
Author: Clay Gerrard <email address hidden>
Date: Tue Oct 11 13:23:11 2016 -0700

    Fix signal handling for daemons with InternalClient

    The intentional use of "bare except" handling in catch_errors and some
    daemons to prevent propagation on unexpected errors that do not
    inherit from Exception (like eventlet.Timeout) or even BaseException
    (like old-style classes) has the side effect of spuriously "handling"
    *expected* errors like when a signal handler raises SystemExit.

    The signal handler installed in our Daemon is intended to ensure first
    that the entire process group and any forked processes (like rsync's)
    receive the SIGTERM signal and also that the process itself
    terminates.

    The use of sys.exit was not a concious grandiose plans for graceful
    shutdown (like the running[0] = False trick that wsgi server parent
    process do) - the desired behavior for SIGTERM is to stop - hard.

    This change ensures the original goals and intentions of our signal
    handler are fulfilled without the undesirable side effect that can
    cause our daemons to confusingly log an expected message to stop as an
    unexpected error, and start ignoring additional SIGTERM messages;
    forcing our kind operators to resort to brutal process murder.

    Closes-Bug: #1489209
    Change-Id: I9d2886611f6db2498cd6a8f81a58f2a611f40905
    (cherry picked from commit c2ce92a)

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: feature/hummingbird
Review: https://review.openstack.org/400985

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/400985
Committed: https://git.openstack.org/cgit/openstack/swift/commit/?id=0c3f8f87104af8717115c5badffd243dbaa1c430
Submitter: Jenkins
Branch: feature/hummingbird

commit 2d25fe6ad3573b2a06b6b3e5e66493d7b0c55693
Author: Tim Burke <email address hidden>
Date: Mon Jul 25 15:06:23 2016 -0700

    Reduce backend requests for SLO If-Match / HEAD requests

    ... by storing SLO Etag and size in sysmeta.

    Previously, we had to GET the manifest for every HEAD or conditional
    request to an SLO. Worse, since SLO PUTs require that we HEAD every
    segment, we'd GET all included sub-SLO manifests. This was necessary so
    we could recompute the large object's Etag and content-length.

    Since we already know both of those during PUT, we'll now store it in
    object sysmeta. This allows us to:

     * satisfy HEAD requests based purely off of the manifest's HEAD
       response, and
     * perform the If-(None-)Match comparison on the object server, without
       any additional subrequests.

    Note that the large object content-length can't just be parsed from
    content-type -- with fast-POST enabled, the content-type coming out of
    the object-server won't necessarily include swift_bytes.

    Also note that we must still fall back to GETting the manifest if the
    sysmeta headers were not found. Otherwise, we'd break existing large
    objects.

    Change-Id: Ia6ad32354105515560b005cea750aa64a88c96f9

commit ae7dddd801e28217d7dc46bd45cd6b621f29340c
Author: Ondřej Nový <email address hidden>
Date: Mon Nov 21 22:13:11 2016 +0100

    Added comment for "user" option in drive-audit config

    Change-Id: I24362826bee85ac3304e9b63504c9465da673014

commit c3e1d847f4b9d6cc6212aae4dc1b1e6dff45fb40
Author: Thiago da Silva <email address hidden>
Date: Thu Nov 17 17:17:00 2016 -0500

    breaking down tests.py into smaller pieces

    tests.py is currently at ~5500 lines of code, it's
    time to break it down into smaller files.

    I started with an easy middleware set of tests
    (i.e., versioned writes, ~600 lines of code ) so I can get
    some feedback. There are more complicated tests that cover
    multiple middlewares for example, it is not so clear where
    those should go.

    Change-Id: I2aa6c18ee5b68d0aae73cc6add8cac6fbf7f33da
    Signed-off-by: Thiago da Silva <email address hidden>

commit 5d7a3a4172f0f11ab870252eec784cf24b247dea
Author: Ondřej Nový <email address hidden>
Date: Sat Nov 19 23:24:30 2016 +0100

    Removed "in-process-" from func env tox name

    This shorten shebang in infra, because we are hitting 128 bytes limit.

    Change-Id: I02477d81b836df71780942189d37d616944c4dce

commit 9ea340256996a03c8c744201297b47a0e91fe65b
Author: Kota Tsuyuzaki <email address hidden>
Date: Fri Nov 18 01:50:11 2016 -0800

    Don't overwrite built-in 'id'

    This is a follow up for https://review.openstack.org/#/c/399237

    'id' is assigned as a builtin function so that we should not use 'id'
    for the local variable name.

    Change-Id: Ic27460d49e68f6cd50bda1d5b3810e01ccb07a37

commit bf...

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/swift 2.10.1 release.