Master should reject calls from previously unresponsive slave hosts

[wjdhollow]

The build state will not be updated if the master thinks the slave disconnected before it is able to post back the status.

The problem that we are seeing is that a slave is working on a build, but when it tries to send a PUT to update the build state, the master responds with a 404 because it loses the record of the slave.

There does not appear to be a correlation with the job, but the problem does seem to occur when the system is under heavy load.

The slave process appears to recover because it reconnects itself to the master through some mechanism.

This particular issue occurred on ip-10-228-91-76.pod.box.net on build 657 and build 684. The problems occurred around 1:38 PM and 2:50 PM June 14, 2017.

Here is a snippet of the load average over time:

01:10:01 PM         4      1126      0.52      0.91      2.51
01:20:01 PM         4      1129      0.77      0.74      1.65
01:30:01 PM        19      1173      8.61      8.04      4.98
01:40:01 PM         2      1108      6.18      8.07      6.57
01:50:01 PM         7      1100      0.79      2.86      4.61
02:00:01 PM        20      1167      6.31      3.85      3.86
02:10:01 PM         6      1109      0.87      3.26      4.08
02:20:01 PM         5      1208     39.92     20.56     11.18
02:30:01 PM        10      1168      4.19     10.34     11.18
02:40:01 PM         3      1164     10.89      9.87     10.15
02:50:01 PM         6      1132     24.95     26.16     17.82
03:00:01 PM         5      1118      0.39      4.23      9.82
03:10:01 PM         6      1165      5.74      4.46      6.98
03:20:01 PM         3      1113      0.43      1.64      4.57

03:20:01 PM   runq-sz  plist-sz   ldavg-1   ldavg-5  ldavg-15
03:30:02 PM         4      1146      3.95      3.14      3.95
03:40:01 PM        10      1124      0.15      0.70      2.30
03:50:01 PM        13      1163      6.63      4.28      3.05
04:00:01 PM         2      1137      0.68      2.97      3.34
04:10:01 PM        14      1157      7.55      6.39      5.09
04:20:01 PM        14      1178      7.12      6.06      5.22
04:30:01 PM         7      1125      0.93      2.14      3.77
Average:            6      1123      3.05      2.98      2.92

The load average at the time of failure for build 657, 1:38 PM, was actually over 11.0. The host has 10 cores, so in both cases the CPU load went over 100%. The IOWAIT and network load were relatively low at those times, so it is my belief that it was caused primarily by CPU.

Here is the stack trace.

[2017-06-14 14:49:41.131] 4362 ERROR   Bld684-Setup    unhandled_excep Unhandled exception handler caught exception.
Traceback (most recent call last):
  File "/home/jenkins/ClusterRunnerBuild/app/util/safe_thread.py", line 18, in run
  File "/usr/local/lib/python3.4/threading.py", line 868, in run
  File "/home/jenkins/ClusterRunnerBuild/app/slave/cluster_slave.py", line 138, in _async_setup_build
  File "/home/jenkins/ClusterRunnerBuild/app/slave/cluster_slave.py", line 326, in _notify_master_of_state_change
  File "/home/jenkins/ClusterRunnerBuild/app/util/network.py", line 95, in put_with_digest
  File "/home/jenkins/ClusterRunnerBuild/app/util/decorators.py", line 38, in function_with_retries
  File "/home/jenkins/ClusterRunnerBuild/app/util/network.py", line 83, in put
  File "/home/jenkins/ClusterRunnerBuild/app/util/network.py", line 150, in _request
app.util.network._RequestFailedError: Request to http://pod4101-automation1024.pod.box.net:43000/v1/slave/259 failed with status_code 404 and response "{"error": "Invalid build id: None."}"

[wjdhollow]

Notice that there were also spikes at 2:20 PM and 2:30 PM but no stack trace. My guess is that the slave did not communicate with the master at that time. Though it may be possible that the master lost track of the slave during that period. I don't know if the master pings the slave for build status.

[josephharrington]

The build state will not be updated if the master thinks the slave disconnected before it is able to post back the status.

This is probably the same issue as #280. The reason the build got stuck is because it was a very small one that would only ever get a single slave, so that single slave is a SPOF for that build. Most builds we run would be allocated multiple slaves so could still complete even if they encountered this issue.

The slave process appears to recover because it reconnects itself to the master through some mechanism.

There is not really any concept of "reconnecting" because all a slave does when it "connects" is tell the master what its service url is. If a slave goes unresponsive temporarily, then the master will mark it offline. Then if the slave later recovers it will continue as if nothing happened, which means it will start sending API requests to the master again.

a slave is working on a build, but when it tries to send a PUT to update the build state, the master responds with a 404 because it loses the record of the slave.

I think it's a bit more subtle than that. Here's what it looks like happened:

1. Master sent a build setup command to the slave.
2. Slave received build setup command. Logged "Executing setup for build 657".
3. Slave froze up before it could spawn the thread to do build setup.
4. Master timed out API request after 30 seconds. Marked slave offline.
   • As part of marking a slave offline, master sets slave.current_build_id to None.
5. Slave recovered after another 40 seconds and started doing setup commands.
6. Once slave completed build setup, it reported SETUP_COMPLETE to master.
7. As part of handling setup success, master did self.get_build(slave.current_build_id) which raised an ItemNotFoundError because slave.current_build_id had been set to None when the slave was marked dead.
8. Master returned a 404 to slave because the build with id of None was not found. Slave shut down because of error_on_failure=True in _notify_master_of_state_change().

(See relevant logs below that illustrate above.)

The end result of all this is that the build is stuck, which is exactly what #280 is about. The way this is different from what we usually see is that the slave didn't go down because setup_build failed; it actually went down because it was temporarily unresponsive.

I actually like the behavior of telling a slave to shut down when it becomes temporarily unresponsive. But it's definitely an accident that we did so in this case. The only thing that made the slave shut down was the somewhat arbitrary choice to set slave.current_build_id = None when marking a slave as dead. If we didn't do that I suspect that we could get into a strange state where a slave is marked dead but the master is still communicating with it.

We should probably make this type of slave shutdown more intentional.

=====

Relevant logs on the master: (no response from setup call to slave, which should be a fast API call)

[2017-06-14 13:37:03.699] 33128 DEBUG   Bld657-Preparat build_fsm       Build 657 transitioned from PREPARING to PREPARED
[2017-06-14 13:37:03.700] 33128 INFO    Bld657-Preparat event_log       Build 657 successfully prepared.
[2017-06-14 13:37:03.700] 33128 INFO    Bld657-Preparat build_request_h Build 657 is waiting for slaves.
[2017-06-14 13:37:03.707] 33128 INFO    SlaveAllocation slave_allocator Allocating <slave #198 - ip-10-228-91-76.pod.box.net:43001> to build 657.
...
[2017-06-14 13:37:33.739] 33128 WARNING SlaveAllocation slave           Setup call to <slave #198 - ip-10-228-91-76.pod.box.net:43001> failed with Timeout: HTTPConnectionPool(host='ip-10-228-91-76.pod.box.net', port=43001): Read timed out. (read timeout=30).
[2017-06-14 13:37:33.740] 33128 WARNING SlaveAllocation slave           <slave #198 - ip-10-228-91-76.pod.box.net:43001> has gone offline. Last build: 657
...
[2017-06-14 13:38:16.788] 33128 ERROR   MasterTornadoTh cluster_master_ Exception occurred during request to /v1/slave/198.
Traceback (most recent call last):
  File "/home/jenkins/.virtualenvs/clusterrunner/lib/python3.4/site-packages/tornado/web.py", line 1346, in _when_complete
    callback()
  File "/home/jenkins/.virtualenvs/clusterrunner/lib/python3.4/site-packages/tornado/web.py", line 1367, in _execute_method
    self._when_complete(method(*self.path_args, **self.path_kwargs),
  File "/home/jenkins/ClusterRunnerBuild/app/util/decorators.py", line 63, in function_with_auth
    return function(self, *args, **kwargs)
  File "<decorator-gen-21>", line 2, in put
  File "/home/jenkins/.virtualenvs/clusterrunner/lib/python3.4/site-packages/prometheus_client/core.py", line 879, in wrapped
    return func(*args, **kwargs)
  File "/home/jenkins/ClusterRunnerBuild/app/web_framework/cluster_master_application.py", line 348, in put
    self._cluster_master.handle_slave_state_update(slave, new_slave_state)
  File "/home/jenkins/ClusterRunnerBuild/app/master/cluster_master.py", line 170, in handle_slave_state_update
    do_transition(slave)
  File "/home/jenkins/ClusterRunnerBuild/app/master/cluster_master.py", line 209, in _handle_setup_success_on_slave
    build = self.get_build(slave.current_build_id)
  File "/home/jenkins/ClusterRunnerBuild/app/master/cluster_master.py", line 295, in get_build
    raise ItemNotFoundError('Invalid build id: {}.'.format(build_id))
app.util.exceptions.ItemNotFoundError: Invalid build id: None.

Relevant logs on the slave: (over one minute delay between first two lines)

[2017-06-14 13:37:03.710] 2483 INFO    SlaveTornadoThr cluster_slave   Executing setup for build 657 (type: git).
[2017-06-14 13:38:15.875] 2483 DEBUG   Bld657-Setup    git             Executing command in project: export PROJECT_DIR="/tmp/clusterrunner_build_symlinks/f197a751-0369-4f60-8e2a-7f5f2ebccea0"; export GIT_ASKPASS="/home/jenkins/.clusterrunner/dist/bin/git_askpass.sh"; export GIT_SSH_ARGS="-o BatchMode=yes -o StrictHostKeyChecking=no"; export GIT_SSH="/home/jenkins/.clusterrunner/dist/bin/git_ssh.sh"; git rev-parse
...
[2017-06-14 13:38:16.784] 2483 INFO    Bld657-Setup    git             Build setup completed successfully.
[2017-06-14 13:38:16.785] 2483 INFO    Bld657-Setup    cluster_slave   Notifying master that build setup is complete for build 657.
[2017-06-14 13:38:16.790] 2483 ERROR   Bld657-Setup    unhandled_excep Unhandled exception handler caught exception.
Traceback (most recent call last):
  File "/home/jenkins/ClusterRunnerBuild/app/util/safe_thread.py", line 18, in run
  File "/usr/local/lib/python3.4/threading.py", line 868, in run
  File "/home/jenkins/ClusterRunnerBuild/app/slave/cluster_slave.py", line 138, in _async_setup_build
  File "/home/jenkins/ClusterRunnerBuild/app/slave/cluster_slave.py", line 326, in _notify_master_of_state_change
  File "/home/jenkins/ClusterRunnerBuild/app/util/network.py", line 95, in put_with_digest
  File "/home/jenkins/ClusterRunnerBuild/app/util/decorators.py", line 38, in function_with_retries
  File "/home/jenkins/ClusterRunnerBuild/app/util/network.py", line 83, in put
  File "/home/jenkins/ClusterRunnerBuild/app/util/network.py", line 150, in _request
app.util.network._RequestFailedError: Request to http://pod4101-automation1024.pod.box.net:43000/v1/slave/198 failed with status_code 404 and response "{"error": "Invalid build id: None."}"

[josephharrington]

Based on the conversation above, this issue could go one of two ways:

• Any time the master receives a request from a slave that has been previously marked dead, reject the request and shut down the slave. Until we fix a few other issues (If slave goes offline while executing a subjob, re-assign subjob #61, When all slaves for a build die, the build becomes immortal #280) this could result in stuck builds.

or

• Maintain state when a slave is marked dead. Resurrect the slave if it recovers and starts making requests to the master again. This could allow builds that might otherwise be stuck to eventually complete (although that may not matter if there are build timeouts).

I vote for the first option because I feel that if we can't assume the master and slave service APIs are responsive then that has significant repercussions throughout the application beyond this specific issue. Feel free to weigh in with other opinions.

[tjlee0909]

@wjdhollow - I posted on this in PE-chat.

My guess for that one is that the master tried to ping that slave about something
[2:46] 
but the slave to was too slow to respond, even though it wasn’t down
and the master gave up on the slave
[2:46] 
and then the slave finally finished build setup, and pinged the master
[2:46] 
but the master had already given up on the slave at that point, and tells the slave to shutdown
[2:47] 
and then the slave shutdown

Which I think aligns with what Joey just said.

[tjlee0909]

So your suggestion regarding:

Any time the master receives a request from a slave that has been previously marked dead, reject the request and shut down the slave.

is different from current behavior right now, because it has the master deliberately ask the slave to shut down, as opposed to the slave shutting itself down due to some error handling logic we have on the slave side?

I think that's fine behavior for now, whether we deliberately ask the slave to shutdown, or if the slave just de-facto shuts down from the current behavior.

[josephharrington]

I didn't mean that we should have the master deliberately ask the slave to shut down. I meant that whenever the master gets a state update call from a slave (ClusterMaster.handle_slave_state_update) we should do an explicit check on slave.is_alive and if it's false we raise a BadRequestError error or something.

I agree that right now the behavior is fine, but I think the logic is very brittle. It's not obvious at all that the current behavior depends on slave.mark_dead() setting slave.current_build_id = None.

[tjlee0909]

I see.

The more think about it, the more I'm unsure about what to do here, because the circumstances that caused the Slave to become unresponsive are mysterious and we don't know if it's temporary or going to be persistent throughout the life of the save.

My inclination is to always raise a BadRequestError, even if the slave is alive (but still log on the master log whether or not that slave is alive), and force us to investigate what happened.

[josephharrington]

I'm not quite sure what you mean by "always raise a BadRequestError, even if the slave is alive" but I suspect we're on the same page. 👯‍♂️

[vartikaz]

Is it possible to identify the slave as a newly resurrected one based on the build_id=None. In this case, we send it a new (or old build) to run but we go through the setup again?

[josephharrington]

Is it possible to identify the slave as a newly resurrected one...

It is possible, but I don't think we should try to add recovery or robustness around unresponsive hosts. To reiterate, I feel that if we can't assume the master and slave service APIs are responsive then that has significant repercussions throughout the application beyond this specific issue.

For example, that mode of detection would be highly dependent on when the slave was unresponsive. If it's unresponsive when the master tries to send a subjob in the middle of a build then yes, we could detect recovery if the slave starts reporting results for other subjobs that it already had. But if it was unresponsive when we first try to assign it to a build, we'll mark it dead and we'll never hear from it again even though it may have somehow recovered.

This could have an effect on any automation that does autoscaling. Once a slave has been marked offline, we should be able to assume that host is safe to destroy. If we have to worry about if it's still working on something or reporting results then it's going to complicate things.

So yeah, my opinion is that if a slave ever goes unresponsive and the master marks it dead then we should consider it offline permanently and explicitly reject any future calls we get from that slave. If a user has problems in this area they can increase the responsiveness timeout in the config.

[tjlee0909]

Agreed @josephharrington

I feel that if we can't assume the master and slave service APIs are responsive then that has significant repercussions throughout the application beyond this specific issue

I really don't want to deal with that in any part of the application. +1, lets keep it simple.

[josephharrington]

Just to summarize what I think we should do about this:

Whenever the master receives an API call from a slave we should do an explicit check on slave.is_alive and if it's false then we raise a BadRequestError error (or something else that will cause the slave to shut down).

In my opinion, the correct way to deal with network flakiness is to raise the timeouts in the config to avoid spuriously marking hosts offline in the first place. I don't think we should try to recover/resurrect any slave hosts that were previously unresponsive and marked offline.

(Also removing duplicate tag since #280 is related but a bit different.)