Page MenuHomePhabricator

Exception: Invalid ETag returned by handler: Expected """ at 69
Closed, ResolvedPublicPRODUCTION ERROR

Description

Error
normalized_message
[{reqId}] {exception_url}   Exception: Invalid ETag returned by handler: Expected """ at 69
exception.trace
from /srv/mediawiki/php-1.42.0-wmf.4/includes/Rest/ConditionalHeaderUtil.php(62)
#0 /srv/mediawiki/php-1.42.0-wmf.4/includes/Rest/Handler.php(271): MediaWiki\Rest\ConditionalHeaderUtil->checkPreconditions(MediaWiki\Rest\RequestFromGlobals)
#1 /srv/mediawiki/php-1.42.0-wmf.4/includes/Rest/Router.php(530): MediaWiki\Rest\Handler->checkPreconditions()
#2 /srv/mediawiki/php-1.42.0-wmf.4/includes/Rest/Router.php(441): MediaWiki\Rest\Router->executeHandler(MediaWiki\Rest\Handler\PageHTMLHandler)
#3 /srv/mediawiki/php-1.42.0-wmf.4/includes/Rest/EntryPoint.php(195): MediaWiki\Rest\Router->execute(MediaWiki\Rest\RequestFromGlobals)
#4 /srv/mediawiki/php-1.42.0-wmf.4/includes/Rest/EntryPoint.php(135): MediaWiki\Rest\EntryPoint->execute()
#5 /srv/mediawiki/php-1.42.0-wmf.4/rest.php(31): MediaWiki\Rest\EntryPoint::main()
#6 /srv/mediawiki/w/rest.php(3): require(string)
#7 {main}
Impact

REST API on zh-yuewiki, about 17 times in the last hour.

Notes

Details

Request URL
https://zh-yue.wikipedia.org/w/rest.php/v1/page/%E5%9D%A6%E5%99%B6%E5%B0%BC%E5%96%80/with_html

Related Objects

Event Timeline

thcipriani subscribed.

Unsure the right tags for this one, tagging in MediaWiki-Platform-Team — please correct if that's wrong.

Updated stack trace:

Error
normalized_message
[{reqId}] {exception_url}   Exception: Invalid ETag returned by handler: Expected """ at 68
exception.trace
from /srv/mediawiki/php-1.42.0-wmf.9/includes/Rest/ConditionalHeaderUtil.php(62)
#0 /srv/mediawiki/php-1.42.0-wmf.9/includes/Rest/Handler.php(273): MediaWiki\Rest\ConditionalHeaderUtil->checkPreconditions(MediaWiki\Rest\RequestFromGlobals)
#1 /srv/mediawiki/php-1.42.0-wmf.9/includes/Rest/Router.php(555): MediaWiki\Rest\Handler->checkPreconditions()
#2 /srv/mediawiki/php-1.42.0-wmf.9/includes/Rest/Router.php(452): MediaWiki\Rest\Router->executeHandler(MediaWiki\Rest\Handler\PageHTMLHandler)
#3 /srv/mediawiki/php-1.42.0-wmf.9/includes/Rest/EntryPoint.php(195): MediaWiki\Rest\Router->execute(MediaWiki\Rest\RequestFromGlobals)
#4 /srv/mediawiki/php-1.42.0-wmf.9/includes/Rest/EntryPoint.php(135): MediaWiki\Rest\EntryPoint->execute()
#5 /srv/mediawiki/php-1.42.0-wmf.9/rest.php(31): MediaWiki\Rest\EntryPoint::main()
#6 /srv/mediawiki/w/rest.php(3): require(string)
#7 {main}

Seems like this started around picking up with wmf/1.42.0-wmf.3. Now we get about 10 of these an hour and it's been constant since then.

Mostly on Chinese language Wikipedias. A handful on Italian Wikipedia.

This is always at the top of our list of most-frequent messages, so it would be nice to mitigate/investigate.

Tgr subscribed.

API Platform is already tagged and they seem like the best team to triage this.

I guess the immediate improvement would be to use a NormalizedException in ConditionalHeaderUtil and log the offending ETag.

Change 994195 had a related patch set uploaded (by Jforrester; author: Jforrester):

[mediawiki/core@master] Rest/HeaderParser: Give full context rather than simply `Expected """`

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

Change 994195 merged by jenkins-bot:

[mediawiki/core@master] Rest/HeaderParser: Give full context rather than simply `Expected """`

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

Noting to self and @brennen that we should expect to see a difference in how these Invalid ETag returned by handler errors appear in logspam-watch as the 1.42.0-wmf.17 train rolls out this week.

OK, updated error:

Invalid ETag returned by handler: `Expected """ to be a substring of ""1925948/d7b8bda5-b6a9-11ee-84f1-1f6a6e99b228/view/with_html+lang:ru, uk;q=0.8, be;q=0.8, en;q=0.7, *;q=0.01"" from position "69" at 69`

There indeed is no additional " inside the ETag after position 69 (which is the first post-comma position in the string); is there meant to be? This comes from HeaderParserBase::consumeString() via IfNoneMatch::consumeTag().

As of wmf.18, this has not observably decreased and remains fairly noisy in logspam-watch.

Something is definitly wrong with the processing of the etag, I am guessing it doesn't like the spaces. That should be fixed, but there is another issue here:

That ETAg seems to contain the full Accept-Language header sent by the client! It should only contain the variant that we actually end up matching.

Change rMW10065651086b had a related patch set uploaded (by Daniel Kinzler; author: Daniel Kinzler):

[mediawiki/core@master] Rest: extract target variant from accept-language header

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

Change rMW10065651086b merged by jenkins-bot:

[mediawiki/core@master] Rest: extract target variant from accept-language header

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

daniel claimed this task.

Nothing in the log since Feb 15.