Page MenuHomePhabricator

Restbase logging indexing conflict on 'res' and 'body' logging fields
Closed, ResolvedPublic

Description

Got these indexing failures from restbase today while API was slow:

[2019-11-25T11:35:17,571][WARN ][logstash.outputs.elasticsearch] Could not index event to Elasticsearch. {:status=>400, :action=>["index", {:_id=>nil, :_index=>"logstash-restbase-2019.11.25", :_type=>"restbase", :_routing=>nil}, 2019-11-25T11:35:17.195Z restbase2013 503: http_error], :response=>{"index"=>{"_index"=>"logstash-restbase-2019.11.25", "_type"=>"restbase", "_id"=>"AW6iWCpDarkxubcmNpxo", "status"=>400, "error"=>{"type"=>"mapper_parsing_exception", "reason"=>"object mapping for [res.body] tried to parse field [body] as object, but found a concrete value"}}}}

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

{
  "_index": "logstash-restbase-2019.11.25",
  "_type": "restbase",
  "_id": "AW6iXidmarkxubcmN-mu",
  "_score": 1,
  "_source": {
    "res": {
      "name": "HTTPError",
      "headers": {
        "x-request-id": "8e2c9500-0f78-11ea-b73b-974fc939a41f",
        "server": "restbase1021",
        "x-webkit-csp": "default-src 'none'; frame-ancestors 'none'",
        "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-content-type-options": "nosniff",
        "x-xss-protection": "1; mode=block",
        "x-content-security-policy": "default-src 'none'; frame-ancestors 'none'",
        "referrer-policy": "origin-when-cross-origin",
        "content-location": "https://en.wikipedia.org/api/rest_v1/page/summary/crusted%20buttercream%20icing",
        "content-type": "application/problem+json",
        "cache-control": "private, max-age=0, s-maxage=0, must-revalidate"
      },
      "message": "ETIMEDOUT",
      "body": {
        "internalErr": "ETIMEDOUT",
        "internalURI": "https://api-rw.discovery.wmnet/w/api.php",
        "internalMethod": "post",
        "detail": "ETIMEDOUT",
        "type": "internal_http_error",
        "internalStack": "Error: ETIMEDOUT\n    at Timeout.setTimeout (/srv/deployment/restbase/deploy-cache/revs/b98706885857b8c2621271e987e59274aa231ff5/node_modules/preq/index.js:15:27)\n    at ontimeout (timers.js:386:14)\n    at tryOnTimeout (timers.js:250:5)\n    at Timer.listOnTimeout (timers.js:214:5)"
      },
      "status": 504
...

Note that we've seen conflicts happening on both res and body in T240667 namely:

"object mapping for [res.body] tried to parse field [body] as object, but found a concrete value"
"failed to parse field [res.body] of type [text] in document"
"object mapping for [err.body] tried to parse field [body] as object, but found a concrete value"
"Can't merge a non object mapping [res.body] with an object mapping [res.body]"

Event Timeline

Some more details, afaict it is errors from mobileapps and graphoid that fail to be emitted and parsed correctly

[2019-12-13T08:54:45,218][WARN ][logstash.outputs.elasticsearch] Could not index event to Elasticsearch. {:status=>400, :action=>["index", {:_id=>nil, :_index=>"logstash-restbase-2019.12.13", :_type=>"_doc", :routing=>nil}, #<LogStash::Event:0x3101768f>], :response=>{"index"=>{"_index"=>"logstash-restbase-2019.12.13", "_type"=>"_doc", "_id"=>"SvN3_m4Bjuy0cAYEqC9T", "status"=>400, "error"=>{"type"=>"mapper_parsing_exception", "reason"=>"failed to parse field [res.body] of type [text] in document with id 'SvN3_m4Bjuy0cAYEqC9T'. Preview of field's value: '{method=get, internalURI=http://mobileapps.discovery.wmnet:8888/zh.wikipedia.org/v1/page/summary/%E5%93%88%E5%88%A9%E6%B3%A2%E7%89%B9%E8%A7%92%E8%89%B2%E5%88%97%E8%A1%A8, internalMethod=get, detail=500: https://mediawiki.org/wiki/HyperSwitch/errors/unknown_error, type=https://mediawiki.org/wiki/HyperSwitch/errors/unknown_error, uri=/zh.wikipedia.org/v1/page/html/%E5%93%88%E5%88%A9%E6%B3%A2%E7%89%B9%E8%A7%92%E8%89%B2%E5%88%97%E8%A1%A8, status=500}'", "caused_by"=>{"type"=>"illegal_state_exception", "reason"=>"Can't get text on a START_OBJECT at 1:4052"}}}}}
	[2019-12-13T08:54:29,665][WARN ][logstash.outputs.elasticsearch] Could not index event to Elasticsearch. {:status=>400, :action=>["index", {:_id=>nil, :_index=>"logstash-restbase-2019.12.13", :_type=>"_doc", :routing=>nil}, #<LogStash::Event:0x262fee0c>], :response=>{"index"=>{"_index"=>"logstash-restbase-2019.12.13", "_type"=>"_doc", "_id"=>"t6F3_m4BG1tY0Cara0hE", "status"=>400, "error"=>{"type"=>"mapper_parsing_exception", "reason"=>"failed to parse field [res.body] of type [text] in document with id 't6F3_m4BG1tY0Cara0hE'. Preview of field's value: '{description=TypeError: Cannot read property 'body' of undefined, type=internal_error}'", "caused_by"=>{"type"=>"illegal_state_exception", "reason"=>"Can't get text on a START_OBJECT at 1:4251"}}}}}
[2019-12-13T08:54:15,943][WARN ][logstash.outputs.elasticsearch] Could not index event to Elasticsearch. {:status=>400, :action=>["index", {:_id=>nil, :_index=>"logstash-restbase-2019.12.13", :_type=>"_doc", :routing=>nil}, #<LogStash::Event:0x363ee611>], :response=>{"index"=>{"_index"=>"logstash-restbase-2019.12.13", "_type"=>"_doc", "_id"=>"tgZ3_m4Bi2xgrm1BNSjq", "status"=>400, "error"=>{"type"=>"mapper_parsing_exception", "reason"=>"failed to parse field [res.body] of type [text] in document with id 'tgZ3_m4Bi2xgrm1BNSjq'. Preview of field's value: '{method=get, internalURI=http://mobileapps.discovery.wmnet:8888/zh.wikipedia.org/v1/page/summary/MIXNINE, internalMethod=get, detail=500: https://mediawiki.org/wiki/HyperSwitch/errors/unknown_error, type=https://mediawiki.org/wiki/HyperSwitch/errors/unknown_error, uri=/zh.wikipedia.org/v1/page/html/MIXNINE, status=500}'", "caused_by"=>{"type"=>"illegal_state_exception", "reason"=>"Can't get text on a START_OBJECT at 1:1069"}}}}}

After getting a little more perspective in T240667 it seems that indeed res and body are sometimes sent as strings and sometimes as nested objects.

fgiunchedi renamed this task from Restbase logging indexing conflict to Restbase logging indexing conflict on 'res' and 'body' logging fields.Dec 13 2019, 2:07 PM
fgiunchedi updated the task description. (Show Details)

Change 576908 had a related patch set uploaded (by Cwhite; owner: Cwhite):
[operations/puppet@production] profile: add restbase filter and coerce err key to string

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

Change 576908 abandoned by Cwhite:
profile: add restbase filter and coerce err key to string

Reason:
handled by es7 template

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

@fgiunchedi can you update the priority for this task?

Certainly, IMHO 'high'

daniel lowered the priority of this task from High to Medium.May 8 2020, 11:20 AM
colewhite subscribed.

This was resolved with the migration to ECS a little while back.