Page MenuHomePhabricator

Mediawiki logging indexing conflict
Closed, ResolvedPublic

Description

Got these indexing failures from mediawiki today while restbase was returning HTTP 429:

[2019-11-29T08:54:20,945][WARN ][logstash.outputs.elasticsearch] Could not index event to Elasticsearch. {:status=>400, :action=>["index", {:_id=>nil, :_index=>"logstash-mediawiki-2019.11.29", :_type=>"mediawiki", :_routing=>nil}, 2019-11-29T08:54:15.943Z mw1314 ApiVisualEditor::requestRestbase: Received HTTP 429 from RESTBase], :response=>{"index"=>{"_index"=>"logstash-mediawiki-2019.11.29", "_type"=>"mediawiki", "_id"=>"AW62Xj7-h3Uj6x1zpnRh", "status"=>400, "error"=>{"type"=>"mapper_parsing_exception", "reason"=>"object mapping for [response] tried to parse field [response] as object, but found a concrete value"}}}}

I am assuming that's because response has been sent as a string in the offending log while normally (?) it is a nested object, like this and the JSON below.

Note that we've come across this before in T238344: MediaWiki Math invalid JSON in logs on Restbase server error, and it seems different subsystems in MW log errors in different ways

{
  "_index": "logstash-mediawiki-2019.11.29",
  "_type": "mediawiki",
  "_id": "AW62BVb6KWrIH1QRI5hs",
  "_version": 1,
  "_score": null,
  "_source": {
    "server": "vi.wikipedia.org",
    "request": {
      "method": "GET",
      "url": "...",
    },
    "phpversion": "7.2.24-1+0~20191026.31+debian9~1.gbpbbacde+wmf1",
    "wiki": "viwiki",
    "channel": "Math",
    "program": "mediawiki",
    "type": "mediawiki",
    "http_method": "GET",
    "host": "mw1244",
    "@version": 1,
    "shard": "s7",
    "timestamp": "2019-11-29T07:17:10+00:00",
    "severity": "err",
    "math_type": "mml",
    "unique_id": "XeDF9gpAME8AAJrhiuwAAAAK",
    "level": "ERROR",
    "tex": "{\\displaystyle  T\\emph{recoil} = \\frac{E\\emph{recoil}}{k_{B}} = \\frac{\\hbar \\;^2k_{L}^2}{2mk_{B}}  }",
    "ip": "10.64.48.79",
    "mwversion": "1.35.0-wmf.5",
    "logsource": "mw1244",
    "message": "Restbase math server problem:",
    "normalized_message": "Restbase math server problem:",
    "url": "/wiki/Ph%C6%B0%C6%A1ng_ph%C3%A1p_l%C3%A0m_l%E1%BA%A1nh_Doppler",
    "reqId": "XeDF9gpAME8AAJrhiuwAAAAK",
    "tags": [
      "input-kafka-rsyslog-udp-localhost",
      "rsyslog-udp-localhost",
      "kafka",
      "es"
    ],
    "@timestamp": "2019-11-29T07:17:10.660Z",
    "response": {
      "reason": "",
      "headers": {
        "date": "Fri, 29 Nov 2019 07:17:10 GMT",
        "x-request-id": "42508490-1278-11ea-9cbe-c9c7a8fdb43a",
        "server": "restbase1018",
        "content-length": "188",
        "x-webkit-csp": "default-src 'none'; frame-ancestors 'none'",
        "vary": "Accept-Encoding",
        "access-control-allow-headers": "accept, content-type, content-length, cache-control, accept-language, api-user-agent, if-match, if-modified-since, if-none-match, dnt, accept-encoding",
        "x-frame-options": "SAMEORIGIN",
        "access-control-allow-methods": "GET,HEAD",
        "access-control-expose-headers": "etag",
        "access-control-allow-origin": "*",
        "content-security-policy": "default-src 'none'; frame-ancestors 'none'",
        "x-xss-protection": "1; mode=block",
        "x-content-type-options": "nosniff",
        "x-content-security-policy": "default-src 'none'; frame-ancestors 'none'",
        "referrer-policy": "origin-when-cross-origin",
        "content-location": "https://vi.wikipedia.org/api/rest_v1/media/math/render/mml/4eb208d9a4be15b5d36c6b0d62090a0b9627728f",
        "content-type": "application/problem+json",
        "connection": "keep-alive",
        "cache-control": "private, max-age=0, s-maxage=0, must-revalidate"
      },
      "code": 400,
      "body": "{\"type\":\"https://mediawiki.org/wiki/HyperSwitch/errors/bad_request\",\"title\":\"Bad Request\",\"method\":\"POST\",\"detail\":[\"TeX parse error: Undefined control sequence \\\\emph\"],\"uri\":\"/complete\"}",
      "error": ""
...

Event Timeline

Similar message but for errors

[2019-12-03T11:19:08,013][WARN ][logstash.outputs.elasticsearch] Could not index event to Elasticsearch. {:status=>400, :action=>["index", {:_id=>nil, :_index=>"logstash-mediawiki-2019.12.03", :_type=>"mediawiki", :_routing=>nil}, 2019-12-03T11:19:04.575Z mw1319 Got permission errors for user XXXX attempting action "reply".], :response=>{"index"=>{"_index"=>"logstash-mediawiki-2019.12.03", "_type"=>"mediawiki", "_id"=>"AW7LfDyrhDZ45bSMZEVM", "status"=>400, "error"=>{"type"=>"mapper_parsing_exception", "reason"=>"object mapping for [errors] tried to parse field [errors] as object, but found a concrete value"}}}}

Change 576910 had a related patch set uploaded (by Cwhite; owner: Cwhite):
[operations/puppet@production] profile: coerce mediawiki user_id field to string in logstash

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

Change 576910 abandoned by Cwhite:
profile: coerce mediawiki user_id field to string in logstash

Reason:
handled by es7 template

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

JTannerWMF moved this task from To Triage to Triaged on the VisualEditor board.
JTannerWMF subscribed.

There doesn't appear to be an action for the Editing Team at this time.

Change 736903 had a related patch set uploaded (by Cwhite; author: Cwhite):

[mediawiki/extensions/VisualEditor@master] log restbase response body as attribute of response object

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

Change 736903 merged by jenkins-bot:

[mediawiki/extensions/VisualEditor@master] log restbase response body as attribute of response object

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

colewhite closed this task as Resolved.EditedNov 17 2021, 10:29 PM
colewhite claimed this task.
colewhite subscribed.

This error is no longer manifesting. Still an issue, it appears. Waiting on 1.38.0-wmf.9 deployment.

Change 742832 had a related patch set uploaded (by Cwhite; author: Cwhite):

[mediawiki/extensions/Echo@master] Pass entire response object to response attribute

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

Change 742832 merged by jenkins-bot:

[mediawiki/extensions/Echo@master] Pass entire response object to response attribute

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

No instances in the last two days. Will reopen if it comes back.