BasicOperationsImagesTest.test_update_image fails with 502 error "UnexpectedContentType"

[Matt Riedemann]

http://logs.openstack.org/96/623596/1/check/grenade-py3/77e4c1b/job-output.txt.gz#_2018-12-08_02_05_43_696072

2018-12-08 02:05:43.696072 | primary | {0} tempest.api.image.v2.test_images.BasicOperationsImagesTest.test_update_image [0.402494s] ... FAILED
2018-12-08 02:05:43.696142 | primary |
2018-12-08 02:05:43.696182 | primary | Captured traceback:
2018-12-08 02:05:43.696207 | primary | ~~~~~~~~~~~~~~~~~~~
2018-12-08 02:05:43.696245 | primary | b'Traceback (most recent call last):'
2018-12-08 02:05:43.696322 | primary | b' File "/opt/stack/new/tempest/tempest/api/image/v2/test_images.py", line 127, in test_update_image'
2018-12-08 02:05:43.696367 | primary | b" self.client.store_image_file(image['id'], image_file)"
2018-12-08 02:05:43.696443 | primary | b' File "/opt/stack/new/tempest/tempest/lib/services/image/v2/images_client.py", line 151, in store_image_file'
2018-12-08 02:05:43.696473 | primary | b' body=data, chunked=True)'
2018-12-08 02:05:43.696534 | primary | b' File "/opt/stack/new/tempest/tempest/lib/common/rest_client.py", line 676, in request'
2018-12-08 02:05:43.696570 | primary | b' self._error_checker(resp, resp_body)'
2018-12-08 02:05:43.696634 | primary | b' File "/opt/stack/new/tempest/tempest/lib/common/rest_client.py", line 767, in _error_checker'
2018-12-08 02:05:43.696656 | primary | b' resp=resp)'
2018-12-08 02:05:43.696712 | primary | b'tempest.lib.exceptions.UnexpectedContentType: Unexpected content type provided'
2018-12-08 02:05:43.696732 | primary | b'Details: 502'
2018-12-08 02:05:43.696746 | primary | b''
2018-12-08 02:05:43.696756 | primary |
2018-12-08 02:05:43.696784 | primary | Captured pythonlogging:
2018-12-08 02:05:43.696812 | primary | ~~~~~~~~~~~~~~~~~~~~~~~
2018-12-08 02:05:43.696932 | primary | b'2018-12-08 02:05:43,353 30223 INFO [tempest.lib.common.rest_client] Request (BasicOperationsImagesTest:test_update_image): 201 POST http://149.202.186.226/image/v2/images 0.063s'
2018-12-08 02:05:43.697076 | primary | b"2018-12-08 02:05:43,353 30223 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'X-Auth-Token': '<omitted>', 'Accept': 'application/json', 'Content-Type': 'application/json'}"
2018-12-08 02:05:43.697168 | primary | b' Body: {"name": "tempest-image-2048852775", "disk_format": "ami", "container_format": "ami", "visibility": "private"}'
2018-12-08 02:05:43.697476 | primary | b" Response - Headers: {'content-length': '631', 'connection': 'close', 'content-type': 'application/json', 'status': '201', 'date': 'Sat, 08 Dec 2018 02:05:43 GMT', 'content-location': 'http://149.202.186.226/image/v2/images', 'location': 'http://127.0.0.1:60999/v2/images/7e73ac4d-508c-405c-af7a-18fdc7e9f8d1', 'openstack-image-import-methods': 'glance-direct,web-download', 'server': 'Apache/2.4.18 (Ubuntu)', 'x-openstack-request-id': 'req-04ed2f99-dc40-4099-b9e0-8e43aae45b42'}"
2018-12-08 02:05:43.697867 | primary | b' Body: b\'{"schema": "/v2/schemas/image", "virtual_size": null, "status": "queued", "os_hash_algo": null, "checksum": null, "os_hash_value": null, "size": null, "min_ram": 0, "created_at": "2018-12-08T02:05:43Z", "os_hidden": false, "container_format": "ami", "id": "7e73ac4d-508c-405c-af7a-18fdc7e9f8d1", "disk_format": "ami", "visibility": "private", "self": "/v2/images/7e73ac4d-508c-405c-af7a-18fdc7e9f8d1", "name": "tempest-image-2048852775", "min_disk": 0, "file": "/v2/images/7e73ac4d-508c-405c-af7a-18fdc7e9f8d1/file", "tags": [], "owner": "c931501accd44e248426947bb35b8fd7", "protected": false, "updated_at": "2018-12-08T02:05:43Z"}\''
2018-12-08 02:05:43.698011 | primary | b'2018-12-08 02:05:43,387 30223 INFO [tempest.lib.common.rest_client] Request (BasicOperationsImagesTest:test_update_image): 204 GET http://149.202.186.226/image/v2/images/7e73ac4d-508c-405c-af7a-18fdc7e9f8d1/file 0.033s'
2018-12-08 02:05:43.698145 | primary | b"2018-12-08 02:05:43,387 30223 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'X-Auth-Token': '<omitted>', 'Accept': 'application/json', 'Content-Type': 'application/json'}"
2018-12-08 02:05:43.698172 | primary | b' Body: None'
2018-12-08 02:05:43.698359 | primary | b" Response - Headers: {'status': '204', 'date': 'Sat, 08 Dec 2018 02:05:43 GMT', 'content-location': 'http://149.202.186.226/image/v2/images/7e73ac4d-508c-405c-af7a-18fdc7e9f8d1/file', 'server': 'Apache/2.4.18 (Ubuntu)', 'x-openstack-request-id': 'req-f16021f8-d829-467d-be30-4e99529a187a', 'connection': 'close'}"
2018-12-08 02:05:43.698413 | primary | b" Body: b''"
2018-12-08 02:05:43.698558 | primary | b'2018-12-08 02:05:43,688 30223 INFO [tempest.lib.common.rest_client] Request (BasicOperationsImagesTest:test_update_image): 502 PUT http://149.202.186.226/image/v2/images/7e73ac4d-508c-405c-af7a-18fdc7e9f8d1/file 0.299s'
2018-12-08 02:05:43.698663 | primary | b"2018-12-08 02:05:43,689 30223 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'X-Auth-Token': '<omitted>', 'Content-Type': 'application/octet-stream'}"
2018-12-08 02:05:43.698721 | primary | b' Body: <callable_iterator object at 0x7f75717dbda0>'
2018-12-08 02:05:43.698914 | primary | b" Response - Headers: {'status': '502', 'date': 'Sat, 08 Dec 2018 02:05:43 GMT', 'content-length': '574', 'content-location': 'http://149.202.186.226/image/v2/images/7e73ac4d-508c-405c-af7a-18fdc7e9f8d1/file', 'content-type': 'text/html; charset=iso-8859-1', 'server': 'Apache/2.4.18 (Ubuntu)', 'connection': 'close'}"
2018-12-08 02:05:43.699377 | primary | b' Body: b\'<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">\\n<html><head>\\n<title>502 Proxy Error</title>\\n</head><body>\\n<h1>Proxy Error</h1>\\n<p>The proxy server received an invalid\\r\\nresponse from an upstream server.<br />\\r\\nThe proxy server could not handle the request <em><a href="/image/v2/images/7e73ac4d-508c-405c-af7a-18fdc7e9f8d1/file">PUT&nbsp;/image/v2/images/7e73ac4d-508c-405c-af7a-18fdc7e9f8d1/file</a></em>.<p>\\nReason: <strong>Error reading from remote server</strong></p></p>\\n<hr>\\n<address>Apache/2.4.18 (Ubuntu) Server at 149.202.186.226 Port 80</address>\\n</body></html>\\n\''
2018-12-08 02:05:43.699413 | primary | b''

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22502%20PUT%5C%22%20AND%20message%3A%5C%22%2Fimage%2Fv2%2Fimages%2F%5C%22%20AND%20message%3A%5C%22%2Ffile%5C%22%20AND%20tags%3A%5C%22console%5C%22&from=7d

Looks like this is relatively new, 22 hits in 48 hours, all failures, check and gate.

[Matt Riedemann (mriedem)]

Clark Boylan has a fix here: https://review.openstack.org/#/c/623597/

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/623597
Committed: https://git.openstack.org/cgit/openstack-dev/devstack/commit/?id=e344c97c0eb93e1d96ca8ebe250bb08d227ef5ac
Submitter: Zuul
Branch: master

commit e344c97c0eb93e1d96ca8ebe250bb08d227ef5ac
Author: Clark Boylan <email address hidden>
Date: Fri Dec 7 14:49:15 2018 -0800

    Set apache proxy-initial-not-pooled env var

    We've run into what appears to be a race with apache trying to reuse a
    pooled connection to a backend when that pool connection is closing.
    This leads to errors like:

      [Fri Dec 07 21:44:10.752362 2018] [proxy_http:error] [pid 19073:tid 139654393218816] (20014)Internal error (specific information not available): [client 104.130.127.213:45408] AH01102: error reading status line from remote server 127.0.0.1:60999
      [Fri Dec 07 21:44:10.752405 2018] [proxy:error] [pid 19073:tid 139654393218816] [client 104.130.127.213:45408] AH00898: Error reading from remote server returned by /image/v2/images/ec31a4fd-e22b-4e97-8c6c-1ef330823fc1/file

    According to the internets this can be addressed (at the cost of some
    performance) by setting the proxy-initial-not-pooled env var for mod
    proxy. From the mod_proxy docs:

      If this variable is set, no pooled connection will be reused if the client
      request is the initial request on the frontend connection. This avoids the
      "proxy: error reading status line from remote server" error message caused
      by the race condition that the backend server closed the pooled connection
      after the connection check by the proxy and before data sent by the proxy
      reached the backend. It has to be kept in mind that setting this variable
      downgrades performance, especially with HTTP/1.0 clients.

    Closes-Bug: #1807518

    Change-Id: I374deddefaa033de858b7bc15f893bf731ad7ff2

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/rocky
Review: https://review.openstack.org/624499

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/624499
Committed: https://git.openstack.org/cgit/openstack-dev/devstack/commit/?id=3e8cd1b67d2ae93e9f11f852907d66d78bcfcefa
Submitter: Zuul
Branch: stable/rocky

commit 3e8cd1b67d2ae93e9f11f852907d66d78bcfcefa
Author: Clark Boylan <email address hidden>
Date: Fri Dec 7 14:49:15 2018 -0800

    Set apache proxy-initial-not-pooled env var

    We've run into what appears to be a race with apache trying to reuse a
    pooled connection to a backend when that pool connection is closing.
    This leads to errors like:

      [Fri Dec 07 21:44:10.752362 2018] [proxy_http:error] [pid 19073:tid 139654393218816] (20014)Internal error (specific information not available): [client 104.130.127.213:45408] AH01102: error reading status line from remote server 127.0.0.1:60999
      [Fri Dec 07 21:44:10.752405 2018] [proxy:error] [pid 19073:tid 139654393218816] [client 104.130.127.213:45408] AH00898: Error reading from remote server returned by /image/v2/images/ec31a4fd-e22b-4e97-8c6c-1ef330823fc1/file

    According to the internets this can be addressed (at the cost of some
    performance) by setting the proxy-initial-not-pooled env var for mod
    proxy. From the mod_proxy docs:

      If this variable is set, no pooled connection will be reused if the client
      request is the initial request on the frontend connection. This avoids the
      "proxy: error reading status line from remote server" error message caused
      by the race condition that the backend server closed the pooled connection
      after the connection check by the proxy and before data sent by the proxy
      reached the backend. It has to be kept in mind that setting this variable
      downgrades performance, especially with HTTP/1.0 clients.

    Closes-Bug: #1807518

    Change-Id: I374deddefaa033de858b7bc15f893bf731ad7ff2
    (cherry picked from commit e344c97c0eb93e1d96ca8ebe250bb08d227ef5ac)

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/624986

[Matt Riedemann (mriedem)]

I don't think change I374deddefaa033de858b7bc15f893bf731ad7ff2 is having an effect for at least nova/cinder because those aren't running the start_tls_proxy function, only keystone, swift, glance and neutron call that function during devstack setup in at least the tempest-full job.

Cinder will only call that if CINDER_USE_MOD_WSGI is False, but it defaults to True. Similarly, nova will only set it if NOVA_USE_MOD_WSGI is False but it defaults to True.

Neutron has a similar flag but defaults to call start_tls_proxy.

[Matt Riedemann (mriedem)]

Looks like this is fixed, and coincides with this fix in glance:

https://review.openstack.org/#/c/625086/

Because the hits in logstash dropped off since that merged:

http://status.openstack.org/elastic-recheck/#1807518

[OpenStack Infra (hudson-openstack)]

Change abandoned by Jens Harbott (frickler) (<email address hidden>) on branch: master
Review: https://review.openstack.org/624986