Bugzilla

The GCP logs are in the taskcluster-prod project of firefox.gcp.mozilla.com, and can be viewed with this query in Logs Explorer:

```
resource.type="k8s_container"
resource.labels.project_id="moz-fx-taskcluster-prod-4b87"
resource.labels.cluster_name="taskcluster-firefoxcitc-v1"
resource.labels.namespace_name="firefoxcitc-taskcluster"
labels.k8s-pod/app_kubernetes_io/component="taskcluster-worker-manager-provisioner"
labels.k8s-pod/app_kubernetes_io/instance="firefoxcitc-taskcluster-taskcluster-1"
labels.k8s-pod/app_kubernetes_io/name="taskcluster-worker-manager"
labels.k8s-pod/app_kubernetes_io/part-of="taskcluster"
```

It is useful to add ``jsonPayload``.``type`` to the summary line to see the log types. Also, GCP seems to have no mechanism for sharing log views or copying.

The log entries are steady at Oct 8, 11 PM GMT, but quickly fall off:

* Last ``simple-estimate`` notice at 23:00:54.323. These stop during the incident. Previously, several a second
* Last ``worker-pool-provisioned`` notice at 23:00:54.323. Previously, several a second, directly after a ``simple-estimate``. These stop during the incident.
* ``monitor.periodic`` notice at 23:00:54.323, then an ``monitor.periodic`` error 6 minutes later at 23:06:04.342, followed by the ``monitor.error`` warning of ``Error: Iteration exceeded maximum time allowed at Timeout``. Before the incident, they are 4 times a minute, and after they are 6 times a minute.
* Last ``db-function-call`` notice at 23:01:04.566. Previously, there are about 20 a minute
* There is a ``dp-pool-counts`` notice at 23:05:47.619, after a sequence of 10. The next message is the ``monitor.periodic`` error. These continue at their normal rate of 2 a minute after the incident.
* The `loop-interference` notice begins at 23:06:24.366 (during the incident) and continues at a rate of 6 per minute

I think we can say the incident began at 23:01 GMT.

The `loop-interference` log message only appeared during this incident from Oct 1 to Oct 11. It is generated by this code:

https://github.com/taskcluster/taskcluster/blob/66941613e4242d69dd2aff3fb560359eb633d59c/services/worker-manager/src/provisioner.js#L66-L68

```python
  async provision() {
    if (this.provisioningLoopAlive) {
      this.monitor.notice('loop-interference', {});
      return;
    }
```

This code should prevent two ``provision()`` loops from running at the same time, but appears to have gotten stuck. Restarting the pod reset it.

The last ``loop-interference`` notice was at 2021-10-09 02:11:46.465 GMT.

There were three incidences of the ``monitor.periodic`` error followed by the ``monitor.error`` warning from Oct 1 to Oct 11:

* 2021-10-07 11:14:31 GMT. No ``loop-interference`` notices. I do not recall any reported break in provisioning.
* 2021-10-08 23:06:04 GMT. Followed by many ``loop-interference`` notices.
* 2021-10-09 02:09.06 GMT. Followed by ``loop-interference`` notices for 2 minutes, which then stopped. It is possible the ``loop-interference`` messages were from the terminating pod.

I focused on these by adding this query term:
```
(jsonPayload.Type=("monitor.error" OR "loop-interference")) OR (jsonPayload.Type="monitor.periodic" AND severity=ERROR)
```

The GCP logs are in the taskcluster-prod project of firefox.gcp.mozilla.com, and can be viewed with this query in Logs Explorer:

```
resource.type="k8s_container"
resource.labels.project_id="moz-fx-taskcluster-prod-4b87"
resource.labels.cluster_name="taskcluster-firefoxcitc-v1"
resource.labels.namespace_name="firefoxcitc-taskcluster"
labels.k8s-pod/app_kubernetes_io/component="taskcluster-worker-manager-provisioner"
labels.k8s-pod/app_kubernetes_io/instance="firefoxcitc-taskcluster-taskcluster-1"
labels.k8s-pod/app_kubernetes_io/name="taskcluster-worker-manager"
labels.k8s-pod/app_kubernetes_io/part-of="taskcluster"
```

It is useful to add ``jsonPayload``.``type`` to the summary line to see the log types. Also, GCP seems to have no mechanism for sharing log views or copying.

The log entries are steady at Oct 8, 11 PM GMT, but quickly fall off:

* Last ``simple-estimate`` notice at 23:00:54.323. These stop during the incident. Previously, several a second
* Last ``worker-pool-provisioned`` notice at 23:00:54.323. Previously, several a second, directly after a ``simple-estimate``. These stop during the incident.
* ``monitor.periodic`` notice at 23:00:54.323, then an ``monitor.periodic`` error 6 minutes later at 23:06:04.342, followed by the ``monitor.error`` warning of ``Error: Iteration exceeded maximum time allowed at Timeout``. Before the incident, they are 4 times a minute, and after they are 6 times a minute.
* Last ``db-function-call`` notice at 23:01:04.566. Previously, there are about 20 a minute
* There is a ``db-pool-counts`` notice at 23:05:47.619, after a sequence of 10. The next message is the ``monitor.periodic`` error. These continue at their normal rate of 2 a minute after the incident.
* The `loop-interference` notice begins at 23:06:24.366 (during the incident) and continues at a rate of 6 per minute

I think we can say the incident began at 23:01 GMT.

The `loop-interference` log message only appeared during this incident from Oct 1 to Oct 11. It is generated by this code:

https://github.com/taskcluster/taskcluster/blob/66941613e4242d69dd2aff3fb560359eb633d59c/services/worker-manager/src/provisioner.js#L66-L68

```python
  async provision() {
    if (this.provisioningLoopAlive) {
      this.monitor.notice('loop-interference', {});
      return;
    }
```

This code should prevent two ``provision()`` loops from running at the same time, but appears to have gotten stuck. Restarting the pod reset it.

The last ``loop-interference`` notice was at 2021-10-09 02:11:46.465 GMT.

There were three incidences of the ``monitor.periodic`` error followed by the ``monitor.error`` warning from Oct 1 to Oct 11:

* 2021-10-07 11:14:31 GMT. No ``loop-interference`` notices. I do not recall any reported break in provisioning.
* 2021-10-08 23:06:04 GMT. Followed by many ``loop-interference`` notices.
* 2021-10-09 02:09.06 GMT. Followed by ``loop-interference`` notices for 2 minutes, which then stopped. It is possible the ``loop-interference`` messages were from the terminating pod.

I focused on these by adding this query term:
```
(jsonPayload.Type=("monitor.error" OR "loop-interference")) OR (jsonPayload.Type="monitor.periodic" AND severity=ERROR)
```