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 added a subscriber: JTannerWMF.

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 added a subscriber: colewhite.

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.