Low success rate on HA environment

[mbeaton]

Low success rate on HA environment

[lainie-ftw]

@rgordill, I had the same issue using OpenShift 4.3 on AWS infrastructure and your solution fixed it. Thanks!

[rgordill]

Check if there is any resource limit on the project (example):

oc get limitrange quay-enterprise-core-resource-limits

If so, delete the resource limit, as it is pretty low for Quay

[thomasmckay]

Can you try bumping the health check delay to longer delay? I had similar issues where the pods were taking longer to spin up than the health time / number of checks were allowing.

[mbeaton]

Sure. I assume you're referring to the delay specified in the QuayEcosystem CRD? If so, could you kindly guide me to which one(s) specifically. There are a bunch in there. thanks!

[scouturier]

You could edit the deployment yaml directly, but recently this was added as a setting in the CR too.

Example:

  quay:
    imagePullSecretName: redhat-pull-secret
    livenessProbe:
      initialDelaySeconds: 120
      httpGet:
        path: /health/instance
        port: 8443
        scheme: HTTPS
    readinessProbe:
      initialDelaySeconds: 10
      httpGet:
        path: /health/instance
        port: 8443
        scheme: HTTPS

You could increase the initialDelaySeconds.

[mbeaton]

I updated the example-quayecosystem-quay deployment yaml directly but did not see any difference. I played with various initialDelaySecond values. The last one I tried was 60 and 240. Any other suggestions?

   - resources: {}
      readinessProbe:
        httpGet:
          path: /health/instance
          port: 8443
          scheme: HTTPS
        initialDelaySeconds: 60
        timeoutSeconds: 1
        periodSeconds: 10
        successThreshold: 1
        failureThreshold: 3
      terminationMessagePath: /dev/termination-log
      name: quay-enterprise-app
      livenessProbe:
        httpGet:
          path: /health/instance
          port: 8443
          scheme: HTTPS
        initialDelaySeconds: 240
        timeoutSeconds: 5
        periodSeconds: 10
        successThreshold: 1
        failureThreshold: 3

[mbeaton]

I dug through the quay app pod logs a little further, and compared to the logs of my sandbox env that seems to work every time. They are similar to start, but then they diverge quickly.

In the HA cluster, I see multiple attempts to start forward/reverse proxy, following by about 3-4 pages of these 'Permission denied' messages:

time="2019-09-25T13:42:19Z" level=info msg="Starting reverse proxy (Listening on "unix:/tmp/jwtproxy_secscan.sock")"
2019/09/25 13:42:18 [alert] 222#0: setpriority(-10) failed (13: Permission denied)
nginx stdout | 2019/09/25 13:42:18 [alert] 215#0: setpriority(-10) failed (13: Permission denied)
2019/09/25 13:42:18 [alert] 216#0: setpriority(-10) failed (13: Permission denied)
2019/09/25 13:42:18 [alert] 217#0: setpriority(-10) failed (13: Permission denied)
2019/09/25 13:42:18 [alert] 219#0: setpriority(-10) failed (13: Permission denied)
time="2019-09-25T13:42:19Z" level=info msg="Starting forward proxy (Listening on ":8081")"
2019/09/25 13:42:18 [alert] 224#0: setpriority(-10) failed (13: Permission denied)
2019/09/25 13:42:18 [alert] 225#0: setpriority(-10) failed (13: Permission denied)
jwtproxy stderr | time="2019-09-25T13:42:19Z" level=info msg="No claims verifiers specified, upstream should be configured to verify authorization"
time="2019-09-25T13:42:19Z" level=info msg="Starting reverse proxy (Listening on "unix:/tmp/jwtproxy_secscan.sock")"
2019/09/25 13:42:18 [alert] 226#0: setpriority(-10) failed (13: Permission denied)
2019/09/25 13:42:18 [alert] 227#0: setpriority(-10) failed (13: Permission denied)
nginx stdout | 2019/09/25 13:42:18 [alert] 222#0: setpriority(-10) failed (13: Permission denied)
2019/09/25 13:42:18 [alert] 229#0: setpriority(-10) failed (13: Permission denied)
2019/09/25 13:42:18 [alert] 228#0: setpriority(-10) failed (13: Permission denied)
2019/09/25 13:42:18 [alert] 232#0: setpriority(-10) failed (13: Permission denied)
2019/09/25 13:42:18 [alert] 233#0: setpriority(-10) failed (13: Permission denied)
jwtproxy stderr | time="2019-09-25T13:42:19Z" level=info msg="Starting forward proxy (Listening on ":8081")"
2019/09/25 13:42:18 [alert] 234#0: setpriority(-10) failed (13: Permission denied)
2019/09/25 13:42:18 [alert] 230#0: setpriority(-10) failed (13: Permission denied)

Then I see a 3-4 pages of these 'spawned/exited' messages:

2019-09-25 13:42:37,513 INFO exited: labelbackfillworker (terminated by SIGKILL; not expected)
2019-09-25 13:42:38,615 INFO spawned: 'labelbackfillworker' with pid 281
2019-09-25 13:42:39,113 INFO exited: queuecleanupworker (terminated by SIGKILL; not expected)
2019-09-25 13:42:40,214 INFO spawned: 'queuecleanupworker' with pid 284
2019-09-25 13:42:40,214 INFO success: labelbackfillworker entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2019-09-25 13:42:41,313 INFO success: queuecleanupworker entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2019-09-25 13:42:42,013 INFO exited: gunicorn-verbs (terminated by SIGKILL; not expected)
2019-09-25 13:42:43,313 INFO spawned: 'gunicorn-verbs' with pid 286
2019-09-25 13:42:43,614 INFO exited: tagbackfillworker (terminated by SIGKILL; not expected)
2019-09-25 13:42:44,814 INFO spawned: 'tagbackfillworker' with pid 287
2019-09-25 13:42:44,815 INFO success: gunicorn-verbs entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2019-09-25 13:42:44,815 INFO exited: expiredappspecifictokenworker (terminated by SIGKILL; not expected)
2019-09-25 13:42:45,014 INFO spawned: 'expiredappspecifictokenworker' with pid 290
2019-09-25 13:42:46,113 INFO success: tagbackfillworker entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2019-09-25 13:42:46,213 INFO success: expiredappspecifictokenworker entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2019-09-25 13:42:46,213 INFO exited: securityworker (terminated by SIGKILL; not expected)
2019-09-25 13:42:46,513 INFO spawned: 'securityworker' with pid 294
2019-09-25 13:42:47,713 INFO success: securityworker entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2019-09-25 13:42:47,714 INFO exited: namespacegcworker (terminated by SIGKILL; not expected)
2019-09-25 13:42:49,013 INFO spawned: 'namespacegcworker' with pid 298
2019-09-25 13:42:49,213 INFO exited: repositoryactioncounter (terminated by SIGKILL; not expected)
2019-09-25 13:42:50,314 INFO spawned: 'repositoryactioncounter' with pid 302
2019-09-25 13:42:50,315 INFO success: namespacegcworker entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2019-09-25 13:42:50,716 INFO exited: blobuploadcleanupworker (terminated by SIGKILL; not expected)
2019-09-25 13:42:51,613 INFO success: repositoryactioncounter entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2019-09-25 13:42:51,713 INFO spawned: 'blobuploadcleanupworker' with pid 304
2019-09-25 13:42:51,813 INFO exited: builder (terminated by SIGKILL; not expected)
2019-09-25 13:42:52,713 INFO success: blobuploadcleanupworker entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2019-09-25 13:42:52,813 INFO spawned: 'builder' with pid 305
2019-09-25 13:42:52,913 INFO exited: teamsyncworker (terminated by SIGKILL; not expected)
2019-09-25 13:42:53,415 INFO spawned: 'teamsyncworker' with pid 307
2019-09-25 13:42:53,416 INFO exited: gcworker (terminated by SIGKILL; not expected)
2019-09-25 13:42:54,813 INFO spawned: 'gcworker' with pid 309
2019-09-25 13:42:54,913 INFO success: teamsyncworker entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2019-09-25 13:42:54,913 INFO success: builder entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2019-09-25 13:42:54,914 INFO exited: ip-resolver-update-worker (terminated by SIGKILL; not expected)
2019-09-25 13:42:54,916 INFO spawned: 'ip-resolver-update-worker' with pid 310
2019-09-25 13:42:56,013 INFO success: gcworker entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2019-09-25 13:42:56,013 INFO success: ip-resolver-update-worker entered RUNNING state, process

After pages of ^^, the health check attempts and 502's, following by a stack:

  File "/opt/rh/python27/root/usr/lib/python2.7/site-packages/pkg_resources/__init__.py", line 2592, in from_location
    py_version=py_version, platform=platform, **kw
  File "/opt/rh/python27/root/usr/lib/python2.7/site-packages/pkg_resources/__init__.py", line 2994, in _reload_version
    md_version = self._get_version()
  File "/opt/rh/python27/root/usr/lib/python2.7/site-packages/pkg_resources/__init__.py", line 2772, in _get_version
gunicorn-registry stderr |     root, entry, metadata, precedence=DEVELOP_DIST,
  File "/opt/rh/python27/root/usr/lib/python2.7/site-packages/pkg_resources/__init__.py", line 2592, in from_location
    py_version=py_version, platform=platform, **kw
  File "/opt/rh/python27/root/usr/lib/python2.7/site-packages/pkg_resources/__init__.py", line 2994, in _reload_version
    md_version = self._get_version()
  File "/opt/rh/python27/root/usr/lib/python2.7/site-packages/pkg_resources/__init__.py", line 2772, in _get_version
    version = _version_from_file(lines)
  File "/opt/rh/python27/root/usr/lib/python2.7/site-packages/pkg_resources/__init__.py", line 2556, in _version_from_file
    line = next(iter(version_lines), '')
  File "/opt/rh/python27/root/usr/lib/python2.7/site-packages/pkg_resources/__init__.py", line 2767, in _get_metadata
gunicorn-registry stderr |     version = _version_from_file(lines)
  File "/opt/rh/python27/root/usr/lib/python2.7/site-packages/pkg_resources/__init__.py", line 2556, in _version_from_file
    line = next(iter(version_lines), '')
  File "/opt/rh/python27/root/usr/lib/python2.7/site-packages/pkg_resources/__init__.py", line 2767, in _get_metadata
    for line in self.get_metadata_lines(name):
  File "/opt/rh/python27/root/usr/lib/python2.7/site-packages/pkg_resources/__init__.py", line 1432, in get_metadata_lines
gunicorn-registry stderr |     for line in self.get_metadata_lines(name):
  File "/opt/rh/python27/root/usr/lib/python2.7/site-packages/pkg_resources/__init__.py", line 1432, in get_metadata_lines
    return yield_lines(self.get_metadata(name))
  File "/opt/rh/python27/root/usr/lib/python2.7/site-packages/pkg_resources/__init__.py", line 1420, in get_metadata
    value = self._get(path)
  File "/opt/rh/python27/root/usr/lib/python2.7/site-packages/pkg_resources/__init__.py", line 1617, in _get
gunicorn-registry stderr |     return yield_lines(self.get_metadata(name))
  File "/opt/rh/python27/root/usr/lib/python2.7/site-packages/pkg_resources/__init__.py", line 1420, in get_metadata
    value = self._get(path)
  File "/opt/rh/python27/root/usr/lib/python2.7/site-packages/pkg_resources/__init__.py", line 1617, in _get
    return stream.read()
IOError: [Errno 14] Bad address
gunicorn-registry stderr |     return stream.read()
IOError: [Errno 14] Bad address

The successful rollout on the sandbox env didn't have any of this noise. If you would like a copy of the full log let me know.

[sabre1041]

@mbeaton are you still seeing issues?

[ricardomaraschini]

Due to inactivity I am closing this issue. Feel free to reopen if necessary.