Uploaded image for project: 'Picard'
  1. Picard
  2. PICARD-809

Picard logs a 200 HTTP code on Service Unavailable error

    • Icon: Bug Bug
    • Resolution: Fixed
    • Icon: Normal Normal
    • None
    • None
    • None
    • None

      In Picard debug log:

      E: 22:44:13 Network request error for https://musicbrainz.org:443/ws/2/release/81209d47-16cc-4e81-96bb-54e66925255a?inc=release-groups+media+recordings+artist-credits+artists+aliases+labels+isrcs+collections+artist-rels+release-rels+url-rels+recording-rels+work-rels+recording-level-rels+work-level-rels+tags: Error downloading https://musicbrainz.org:443/ws/2/release/81209d47-16cc-4e81-96bb-54e66925255a?inc=release-groups+media+recordings+artist-credits+artists+aliases+labels+isrcs+collections+artist-rels+release-rels+url-rels+recording-rels+work-rels+recording-level-rels+work-level-rels+tags - server replied: Service Unavailable (QT code 301, HTTP code 200)

      On ernie nginx log:

      1460407452.771 90.125.158.144 "GET /ws/2/release/81209d47-16cc-4e81-96bb-54e66925255a?inc=release-groups+media+recordings+artist-credits+artists+aliases+labels+isrcs+collections+artist-rels+release-rels+url-rels+recording-rels+work-rels+recording-level-rels+work-level-rels+tags HTTP/1.1" 503 535 z=- up=10.1.1.29:80 ms=0.032 ums=0.032 ol=- h=musicbrainz.org:443

      So the server is returning a 503 but Picard logs a 200 ... something very wrong here.

          [PICARD-809] Picard logs a 200 HTTP code on Service Unavailable error

          This seems to be a QT issue, it is currently handled in picard as qt error code 403

          see https://github.com/metabrainz/picard/commit/49fb9bcd004bd8ff930ec923ab4bf5a8a2eef827

          Sambhav Kothari added a comment - This seems to be a QT issue, it is currently handled in picard as qt error code 403 see https://github.com/metabrainz/picard/commit/49fb9bcd004bd8ff930ec923ab4bf5a8a2eef827

          Investigated this a bit more, along with the headers that are sent.

          So it seems QT does log a 503 code when getting a rate limiting reply from search server but not from api.

          The headers in case of search server are -

          E: 15:44:35 [(PyQt5.QtCore.QByteArray(b'Server'), PyQt5.QtCore.QByteArray(b'openresty')), (PyQt5.QtCore.QByteArray(b'Date'), PyQt5.QtCore.QByteArray(b'Fri, 21 Jul 2017 10:14:35 GMT')), (PyQt5.QtCore.QByteArray(b'Content-Type'), PyQt5.QtCore.QByteArray(b'application/json')), (PyQt5.QtCore.QByteArray(b'Transfer-Encoding'), PyQt5.QtCore.QByteArray(b'chunked')), (PyQt5.QtCore.QByteArray(b'Connection'), PyQt5.QtCore.QByteArray(b'keep-alive')), (PyQt5.QtCore.QByteArray(b'Keep-Alive'), PyQt5.QtCore.QByteArray(b'timeout=15')), (PyQt5.QtCore.QByteArray(b'Retry-After'), PyQt5.QtCore.QByteArray(b'3')), (PyQt5.QtCore.QByteArray(b'X-RateLimit-Zone'), PyQt5.QtCore.QByteArray(b'per-rl-ua')), (PyQt5.QtCore.QByteArray(b'X-MB-Rate-Limiter'), PyQt5.QtCore.QByteArray(b'lua'))]

          and in case of a 200 (which is what qt logs a 503 from api as)

          E: 15:44:45 [(PyQt5.QtCore.QByteArray(b'Transfer-Encoding'), PyQt5.QtCore.QByteArray(b'chunked')), (PyQt5.QtCore.QByteArray(b'Connection'), PyQt5.QtCore.QByteArray(b'keep-alive')), (PyQt5.QtCore.QByteArray(b'Keep-Alive'), PyQt5.QtCore.QByteArray(b'timeout=15')), (PyQt5.QtCore.QByteArray(b'Retry-After'), PyQt5.QtCore.QByteArray(b'3')), (PyQt5.QtCore.QByteArray(b'X-RateLimit-Zone'), PyQt5.QtCore.QByteArray(b'per-rl-ua')), (PyQt5.QtCore.QByteArray(b'X-MB-Rate-Limiter'), PyQt5.QtCore.QByteArray(b'lua')), (PyQt5.QtCore.QByteArray(b'Date'), PyQt5.QtCore.QByteArray(b'Fri, 21 Jul 2017 10:13:46 GMT')), (PyQt5.QtCore.QByteArray(b'Content-Type'), PyQt5.QtCore.QByteArray(b'application/json; charset=utf-8')), (PyQt5.QtCore.QByteArray(b'Vary'), PyQt5.QtCore.QByteArray(b'Accept-Encoding')), (PyQt5.QtCore.QByteArray(b'X-RateLimit-Limit'), PyQt5.QtCore.QByteArray(b'1200')), (PyQt5.QtCore.QByteArray(b'X-RateLimit-Remaining'), PyQt5.QtCore.QByteArray(b'755')), (PyQt5.QtCore.QByteArray(b'X-RateLimit-Reset'), PyQt5.QtCore.QByteArray(b'1500632026')), (PyQt5.QtCore.QByteArray(b'Server'), PyQt5.QtCore.QByteArray(b'Plack::Handler::Starlet')), (PyQt5.QtCore.QByteArray(b'ETag'), PyQt5.QtCore.QByteArray(b'W/"fe79eba9e409a4c0d59fb489f4105b36"')), (PyQt5.QtCore.QByteArray(b'Access-Control-Allow-Origin'), PyQt5.QtCore.QByteArray(b'*')), (PyQt5.QtCore.QByteArray(b'Content-Encoding'), PyQt5.QtCore.QByteArray(b'gzip'))]

          Sambhav Kothari added a comment - Investigated this a bit more, along with the headers that are sent. So it seems QT does log a 503 code when getting a rate limiting reply from search server but not from api. The headers in case of search server are - E: 15:44:35 [(PyQt5.QtCore.QByteArray(b'Server'), PyQt5.QtCore.QByteArray(b'openresty')), (PyQt5.QtCore.QByteArray(b'Date'), PyQt5.QtCore.QByteArray(b'Fri, 21 Jul 2017 10:14:35 GMT')), (PyQt5.QtCore.QByteArray(b'Content-Type'), PyQt5.QtCore.QByteArray(b'application/json')), (PyQt5.QtCore.QByteArray(b'Transfer-Encoding'), PyQt5.QtCore.QByteArray(b'chunked')), (PyQt5.QtCore.QByteArray(b'Connection'), PyQt5.QtCore.QByteArray(b'keep-alive')), (PyQt5.QtCore.QByteArray(b'Keep-Alive'), PyQt5.QtCore.QByteArray(b'timeout=15')), (PyQt5.QtCore.QByteArray(b'Retry-After'), PyQt5.QtCore.QByteArray(b'3')), (PyQt5.QtCore.QByteArray(b'X-RateLimit-Zone'), PyQt5.QtCore.QByteArray(b'per-rl-ua')), (PyQt5.QtCore.QByteArray(b'X-MB-Rate-Limiter'), PyQt5.QtCore.QByteArray(b'lua'))] and in case of a 200 (which is what qt logs a 503 from api as) E: 15:44:45 [(PyQt5.QtCore.QByteArray(b'Transfer-Encoding'), PyQt5.QtCore.QByteArray(b'chunked')), (PyQt5.QtCore.QByteArray(b'Connection'), PyQt5.QtCore.QByteArray(b'keep-alive')), (PyQt5.QtCore.QByteArray(b'Keep-Alive'), PyQt5.QtCore.QByteArray(b'timeout=15')), (PyQt5.QtCore.QByteArray(b'Retry-After'), PyQt5.QtCore.QByteArray(b'3')), (PyQt5.QtCore.QByteArray(b'X-RateLimit-Zone'), PyQt5.QtCore.QByteArray(b'per-rl-ua')), (PyQt5.QtCore.QByteArray(b'X-MB-Rate-Limiter'), PyQt5.QtCore.QByteArray(b'lua')), (PyQt5.QtCore.QByteArray(b'Date'), PyQt5.QtCore.QByteArray(b'Fri, 21 Jul 2017 10:13:46 GMT')), (PyQt5.QtCore.QByteArray(b'Content-Type'), PyQt5.QtCore.QByteArray(b'application/json; charset=utf-8')), (PyQt5.QtCore.QByteArray(b'Vary'), PyQt5.QtCore.QByteArray(b'Accept-Encoding')), (PyQt5.QtCore.QByteArray(b'X-RateLimit-Limit'), PyQt5.QtCore.QByteArray(b'1200')), (PyQt5.QtCore.QByteArray(b'X-RateLimit-Remaining'), PyQt5.QtCore.QByteArray(b'755')), (PyQt5.QtCore.QByteArray(b'X-RateLimit-Reset'), PyQt5.QtCore.QByteArray(b'1500632026')), (PyQt5.QtCore.QByteArray(b'Server'), PyQt5.QtCore.QByteArray(b'Plack::Handler::Starlet')), (PyQt5.QtCore.QByteArray(b'ETag'), PyQt5.QtCore.QByteArray(b'W/"fe79eba9e409a4c0d59fb489f4105b36"')), (PyQt5.QtCore.QByteArray(b'Access-Control-Allow-Origin'), PyQt5.QtCore.QByteArray(b'*')), (PyQt5.QtCore.QByteArray(b'Content-Encoding'), PyQt5.QtCore.QByteArray(b'gzip'))]

          Sophist added a comment -

          A bug in Qt / PyQt I suspect. Or perhaps two bugs. Something triggers the Qt error, and as a consequence it supplies the default HTTP status of 200 rather than something else. I bet if we look we will find usage details which say we should check the Qt error code before relying on the HTTP status code.

          Sophist added a comment - A bug in Qt / PyQt I suspect. Or perhaps two bugs. Something triggers the Qt error, and as a consequence it supplies the default HTTP status of 200 rather than something else. I bet if we look we will find usage details which say we should check the Qt error code before relying on the HTTP status code.

          The Qt bug I linked to above only fixed the return code of QNetworkReply's error() method, this still doesn't explain why its HttpStatusCodeAttribute is 200.

          Wieland Hoffmann added a comment - The Qt bug I linked to above only fixed the return code of QNetworkReply's error() method, this still doesn't explain why its HttpStatusCodeAttribute is 200.

          Sophist added a comment -

          Qt
          Qt bug was fixed in Jan 14, so presumably now included in current version.

          Is the Qt bug also in PyQt? And if so has it been fixed there?

          Do we need to move the min version to Qt so that we include this fix?

          Picard
          Does Qt give a 301 error in success circumstances?
          Do we need to check for Qt errors as well as HTTP non-200 status codes?

          Sophist added a comment - Qt Qt bug was fixed in Jan 14, so presumably now included in current version. Is the Qt bug also in PyQt? And if so has it been fixed there? Do we need to move the min version to Qt so that we include this fix? Picard Does Qt give a 301 error in success circumstances? Do we need to check for Qt errors as well as HTTP non-200 status codes?

          I can reproduce this quite often by switching the port to 443.

          Wieland Hoffmann added a comment - I can reproduce this quite often by switching the port to 443.

          Zas added a comment -

          After reviewing and testing the code, i didn't find a good reason for this to happen, it doesn't always happen:
          sometimes the server returns a 503 and Picard logs a 503, sometimes Picard logs a 200...
          I still don't know if the bug is on our side or on PyQt or even Qt side.

          When the server returns a 503:

          reply.errorString() contains "Service Temporarily Unavailable"
          reply.error() is set to 301
          reply.attribute(QtNetwork.QNetworkRequest.HttpStatusCodeAttribute) is set to 200

          Zas added a comment - After reviewing and testing the code, i didn't find a good reason for this to happen, it doesn't always happen: sometimes the server returns a 503 and Picard logs a 503, sometimes Picard logs a 200... I still don't know if the bug is on our side or on PyQt or even Qt side. When the server returns a 503: reply.errorString() contains "Service Temporarily Unavailable" reply.error() is set to 301 reply.attribute(QtNetwork.QNetworkRequest.HttpStatusCodeAttribute) is set to 200

          No, the 301 code is just normal Qt behaviour (https://bugreports.qt.io/browse/QTBUG-30880).

          Wieland Hoffmann added a comment - No, the 301 code is just normal Qt behaviour ( https://bugreports.qt.io/browse/QTBUG-30880 ).

          Zas added a comment -

          The QT code 301 looks suspicious too, it means QNetworkReply.ProtocolUnknownError, prolly related to https

          Zas added a comment - The QT code 301 looks suspicious too, it means QNetworkReply.ProtocolUnknownError, prolly related to https

            samj1912 Sambhav Kothari
            zas Zas
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated:
              Resolved:

                Version Package