Page MenuHomePhabricator

Restbase logging indexing conflict on 'res' and 'body' logging fields
Open, Needs TriagePublic

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

Restricted Application added subscribers: Liuxinyu970226, Aklapper. · View Herald TranscriptNov 25 2019, 11:50 AM

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)