Initial investigation started because of a report by @-jem- that their jembot webservice was misbehaving.

[20:53]  <    bd808> lots of confusing state in this tool right now jem. $HOME/service.manifest is in a state that would indicate that the tool is down. But it is running. qstat shows the running version to be in 'dr' deleted state (but it is obviously running). The job that is in dr state was started on 2022-04-09 and is running on a Buster node at least.

[20:55]  <    bd808> !log tools.jembot Force deleted stuck webservice job
[20:55]  < stashbot> Logged the message at https://wikitech.wikimedia.org/wiki/Nova_Resource:Tools.jembot/SAL
[20:56]  <    bd808> ummm.... and yet it is still running?
[21:00]  <    bd808> very confused right now about where the webservice is actually running. the grid has lost track, but the front proxy apparently has not.

[21:13]  <    bd808> this is so weird. usually if the front proxy gets confused like this it is possible to fix by starting and then stopping a grid webservice. The start should register a new backend ip/port and then stopping removes it again. I've done that twice now and the front proxy is still pretty obviously pointed at the "lost" job
[21:13] bd808 will keep poking
[21:14] jem supports mentally
[21:33]  <    bd808> !log tools.jembot Found orphan grid job by fetching host and port from front proxy redis. Killed related processes on tools-sgeweblight-10-4

[21:41]  <    bd808> !log tools Updated hiera to use fqdn of 'tools-proxy-06.tools.eqiad1.wikimedia.cloud' for active_redis key
[21:41]  < stashbot> Logged the message at https://wikitech.wikimedia.org/wiki/Nova_Resource:Tools/SAL
[21:48]  <    bd808> puppet is taking approximately forever to run on tools-sgebastion-11 :/
[21:55]  <    bd808> !log tools Updated hiera to use fqdn of 'tools-proxy-06.tools.eqiad1.wikimedia.cloud' for profile::toolforge::active_proxy_host key
[21:55]  < stashbot> Logged the message at https://wikitech.wikimedia.org/wiki/Nova_Resource:Tools/SAL
[21:56]  <    bd808> !log tools Removed legacy "active_proxy_host" hiera setting
[21:56]  < stashbot> Logged the message at https://wikitech.wikimedia.org/wiki/Nova_Resource:Tools/SAL
[22:06] jem is back from dinner
[22:09]  <    bd808> jem: I haven't given up, but things are still mysterious. I found and killed the rogue webservice. I have not yet been able to get a new webservice to start however. The jobs submits but gets stuck in queue wait state.

The "active_redis key" mentioned was a typo and should have been "active_proxy_host" (the one I deleted later).

[22:24] bd808 figures out that tools-sgeweblight-10-1.tools.eqiad1.wikimedia.cloud is sick somehow
[22:26]  <    bd808> !log tools Rebooting tools-sgeweblight-10-1.tools.eqiad1.wikimedia.cloud. Node is full of jobs that are not tracked by grid master and failing to spawn new jobs sent by the scheduler

Not long after this I did the things from https://wikitech.wikimedia.org/wiki/Portal:Toolforge/Admin#Clearing_error_state. When the queues flipped right back to E state I cried for help in -cloud-admin and got @nskaggs involved. Then I started this task.

Noted dpkg was broken, and tools-sgeweblight-10-9 and tools-sgeweblight-10-10 were missing grid service, etc. Fixed dpkg, re-ran puppet to bring back online.

Emails to root@tools.wmflabs.org show that most (all?) of the failed jobs are variations of execvlp(/bin/bash, "-bash" "-c" "/usr/bin/webservice-runner --register-proxy --type lighttpd ") failing which then fires the eplilog to cleanup the proxy registration and that fails as well. Watching on the front proxy with tail -f /var/log/proxylistener I think I see both the registration and the removal happening, but apparently the python processes back on the exec nodes are not seeing the expected acks for those events?

Example log events on the front proxy:

$ grep cobain /var/log/proxylistener |tail -10
2022-06-03 00:08:26,308 Received request from cobain for .* to http://172.16.1.75:60743
2022-06-03 00:08:26,865 Cleaning up request from cobain for .*
2022-06-03 00:08:27,081 Received request from cobain for .* to http://172.16.1.75:33763
2022-06-03 00:08:27,449 Cleaning up request from cobain for .*
2022-06-03 00:08:27,752 Received request from cobain for .* to http://172.16.1.69:56789
2022-06-03 00:08:28,260 Cleaning up request from cobain for .*
2022-06-03 00:08:28,865 Received request from cobain for .* to http://172.16.1.69:34515
2022-06-03 00:08:29,349 Cleaning up request from cobain for .*
2022-06-03 00:08:29,637 Received request from cobain for .* to http://172.16.1.72:58491
2022-06-03 00:08:29,986 Cleaning up request from cobain for .*

tools.bd808-test2@tools-sgewebgen-10-1:~$ /usr/bin/webservice-runner --register-proxy --type lighttpd
Traceback (most recent call last):
  File "/usr/bin/webservice-runner", line 46, in <module>
    proxy.register(port)
  File "/usr/lib/python3/dist-packages/toolsws/proxy.py", line 114, in register
    register_dynamicproxy(port)
  File "/usr/lib/python3/dist-packages/toolsws/proxy.py", line 58, in register_dynamicproxy
    raise ProxyException("Port registration failed!")
toolsws.proxy.ProxyException: Port registration failed!

But on tools-proxy-06:

2022-06-03 00:28:40,686 Received request from bd808-test2 for .* to http://172.16.7.61:38033

Is the ack not getting back to the caller?

Change 802683 had a related patch set uploaded (by BryanDavis; author: Bryan Davis):

[operations/software/tools-webservice@master] proxy: horrible hack for T309821

https://gerrit.wikimedia.org/r/802683

Change 802684 had a related patch set uploaded (by BryanDavis; author: Bryan Davis):

[operations/software/tools-webservice@master] d/changelog: Prepare for 0.85 release

https://gerrit.wikimedia.org/r/802684

Change 802683 merged by jenkins-bot:

[operations/software/tools-webservice@master] proxy: horrible hack for T309821

https://gerrit.wikimedia.org/r/802683

Change 802684 merged by jenkins-bot:

[operations/software/tools-webservice@master] d/changelog: Prepare for 0.85 release

https://gerrit.wikimedia.org/r/802684

Mentioned in SAL (#wikimedia-cloud) [2022-06-03T03:10:37Z] <bd808> publish tools-webservice 0.85 with hack for T309821

Mentioned in SAL (#wikimedia-cloud) [2022-06-03T03:21:45Z] <bd808> Cleared queue error states after deploying new toolforge-webservice package (T309821)

Things are a little better after deploying the hacked version tools-webservice. Many more webservices are running, but certainly not all. Some nodes are still being overloaded too with jobs failing due to "fork failed: Cannot allocate memory" and similar errors.

Mentioned in SAL (#wikimedia-cloud) [2022-06-03T05:05:21Z] <taavi> removing duplicate (there should be only one per tool) web service jobs from the grid T309821

I suspect webservicemonitor somehow caused a lot of tools to have multiple instances running/queued. Removing those duplicates with a simple script:

import requests
import subprocess
import sys
import time

jobs = requests.get("https://sge-status.toolforge.org/api/v1").json()["data"]["attributes"]

tools = []

for host, host_data in jobs.items():
	if "web" not in host:
		continue
	if host_data["jobs"] == []:
		continue
	for job in host_data["jobs"].values():
		if job["job_owner"] in tools:
			print("removing duplicate job for", job["job_owner"])
			subprocess.check_call(
				[
					"/usr/bin/qdel",
					str(job["num"])
				],
				stdout=sys.stdout,
				stderr=sys.stderr,
			)
			time.sleep(1)
			continue

		tools.append(job["job_owner"])

I did a rolling reboot of all the Buster webgrid nodes, and deleted the jobs stuck in 'deleting' state. I /think/ the grid itself is now working properly again, individual web service might need restarts to start working again.

webservicemonitor is still disabled on tools-sgecron-01. Not yet sure what to do about it.

I believe the root cause is that some of the buster webgrid nodes got overloaded causing the sge_execd on that node to freeze. The grid for some reason stopped scheduling new jobs on the webgrid queues after that, and webservicemonitor made the problem worse since it though that the jobs in qw didn't exist and spawned new ones for web services it thought needed to be restarted.

Mentioned in SAL (#wikimedia-cloud) [2022-06-03T12:46:50Z] <taavi> start webservicemonitor on tools-sgecron-01 T309821

Change 802620 had a related patch set uploaded (by BryanDavis; author: BryanDavis):

[operations/software/tools-webservice@master] Revert "proxy: horrible hack for T309821"

https://gerrit.wikimedia.org/r/802620

Change 802620 merged by jenkins-bot:

[operations/software/tools-webservice@master] Revert "proxy: horrible hack for T309821"

https://gerrit.wikimedia.org/r/802620

Change 802773 had a related patch set uploaded (by BryanDavis; author: Bryan Davis):

[operations/software/tools-webservice@master] d/changelog: Prepare for 0.86 release

https://gerrit.wikimedia.org/r/802773

Change 802773 merged by jenkins-bot:

[operations/software/tools-webservice@master] d/changelog: Prepare for 0.86 release

https://gerrit.wikimedia.org/r/802773

Mentioned in SAL (#wikimedia-cloud) [2022-06-03T13:17:52Z] <bd808> publish tools-webservice 0.86 (T309821)

Mentioned in SAL (#wikimedia-cloud) [2022-06-03T13:20:33Z] <bd808> publish tools-webservice 0.86 (T309821)

Mentioned in SAL (#wikimedia-cloud) [2022-06-03T13:25:14Z] <bd808> Upgrading fleet to tools-webservice 0.86 (T309821)

Mentioned in SAL (#wikimedia-cloud) [2022-06-03T15:50:47Z] <balloons> temp add 1.0G swap to sgeweblight hosts T309821

Mentioned in SAL (#wikimedia-cloud) [2022-06-03T15:50:53Z] <balloons> fix fix g3.cores4.ram8.disk20.swap24.ephem20 flavor to include swap. Convert to fix g3.cores4.ram8.disk20.swap8.ephem20 flavor T309821

Upon further review, after the new buster hosts began acting up again, with OOM errors, even though free -m showed memory. After investigation, dcaro noted that there was a 24Mb swap partition on each. Adding temporary 1G swap space seems to have removed the errors.

The 24Mb swap was a typo from the more typical 24G swap found on other hosts. The flavor was updated to use 8G swap and 8G RAM. Nodes will be updated to utilize the new flavor.

Mentioned in SAL (#wikimedia-cloud) [2022-06-03T18:59:59Z] <balloons> depooled old nodes, bringing entirely new grid of nodes online T309821

Mentioned in SAL (#wikimedia-cloud) [2022-06-03T19:51:35Z] <balloons> Scaling webservice nodes to 20, using new 8G swap flavor T309821

We have rebuilt 21 new lighttpd nodes, each with 8G of swap space (via a new flavor.)

Assuming this was an overprovisioning problem and not an invisible-memory-leak problem, things should be better. After a period of peace we can consider removing some of those nodes.