opensearch-java icon indicating copy to clipboard operation
opensearch-java copied to clipboard

[BUG] UnexpectedJsonEventException reading task that failed

Open uriofferup opened this issue 2 years ago • 12 comments

What is the bug?

Failed to serialize JSON response when reading a task that failed to execute.

How can one reproduce the bug?

Run any operation using waitForCompletiong(false) that fail to execute (for example due to versioning issue). Then read the taskId returned:

GetTasksRequest getTasksRequest = GetTasksRequest.of(t -> t.taskId(osTask.getTaskId()));
GetTasksResponse getTasksResponse = openSearchClient.tasks().get(getTasksRequest);

What is the expected behavior?

Deserialize the response into the GetTasksResponse object.

What is your host/environment?

AWS Lambda ElasticSearch 7.10

Do you have any screenshots?

Executing /_tasks/ Gets this:

{
  "completed": true,
  "task": {
    "node": "xjAO-PN5TKarvcLhJmHfcA",
    "id": 47102523527,
    "type": "transport",
    "action": "indices:data/write/update/byquery",
    "status": {
      "total": 152,
      "updated": 151,
      "created": 0,
      "deleted": 0,
      "batches": 6,
      "version_conflicts": 1,
      "noops": 0,
      "retries": {
        "bulk": 0,
        "search": 0
      },
      "throttled_millis": 0,
      "requests_per_second": -1,
      "throttled_until_millis": 0,
      "slices": [
        {
          "slice_id": 0,
          "total": 26,
          "updated": 26,
          "created": 0,
          "deleted": 0,
          "batches": 1,
          "version_conflicts": 0,
          "noops": 0,
          "retries": {
            "bulk": 0,
            "search": 0
          },
          "throttled_millis": 0,
          "requests_per_second": -1,
          "throttled_until_millis": 0
        },
        {
          "slice_id": 1,
          "total": 23,
          "updated": 23,
          "created": 0,
          "deleted": 0,
          "batches": 1,
          "version_conflicts": 0,
          "noops": 0,
          "retries": {
            "bulk": 0,
            "search": 0
          },
          "throttled_millis": 0,
          "requests_per_second": -1,
          "throttled_until_millis": 0
        },
        {
          "slice_id": 2,
          "total": 29,
          "updated": 29,
          "created": 0,
          "deleted": 0,
          "batches": 1,
          "version_conflicts": 0,
          "noops": 0,
          "retries": {
            "bulk": 0,
            "search": 0
          },
          "throttled_millis": 0,
          "requests_per_second": -1,
          "throttled_until_millis": 0
        },
        {
          "slice_id": 3,
          "total": 19,
          "updated": 18,
          "created": 0,
          "deleted": 0,
          "batches": 1,
          "version_conflicts": 1,
          "noops": 0,
          "retries": {
            "bulk": 0,
            "search": 0
          },
          "throttled_millis": 0,
          "requests_per_second": -1,
          "throttled_until_millis": 0
        },
        {
          "slice_id": 4,
          "total": 30,
          "updated": 30,
          "created": 0,
          "deleted": 0,
          "batches": 1,
          "version_conflicts": 0,
          "noops": 0,
          "retries": {
            "bulk": 0,
            "search": 0
          },
          "throttled_millis": 0,
          "requests_per_second": -1,
          "throttled_until_millis": 0
        },
        {
          "slice_id": 5,
          "total": 25,
          "updated": 25,
          "created": 0,
          "deleted": 0,
          "batches": 1,
          "version_conflicts": 0,
          "noops": 0,
          "retries": {
            "bulk": 0,
            "search": 0
          },
          "throttled_millis": 0,
          "requests_per_second": -1,
          "throttled_until_millis": 0
        }
      ]
    },
    "description": "update-by-query [phoenix-2023-07-01-all_categories] updated with Script{type=inline, lang='painless', idOrCode='ctx._source.owner=[\"last_active\":params.last_active];', options={}, params={last_active=2023-10-10T21:14:20Z}}",
    "start_time_in_millis": 1697057871665,
    "running_time_in_nanos": 75386100,
    "cancellable": true,
    "headers": {}
  },
  "response": {
    "took": 73,
    "timed_out": false,
    "total": 152,
    "updated": 151,
    "created": 0,
    "deleted": 0,
    "batches": 6,
    "version_conflicts": 1,
    "noops": 0,
    "retries": {
      "bulk": 0,
      "search": 0
    },
    "throttled": "0s",
    "throttled_millis": 0,
    "requests_per_second": -1,
    "throttled_until": "0s",
    "throttled_until_millis": 0,
    "slices": [
      {
        "slice_id": 0,
        "total": 26,
        "updated": 26,
        "created": 0,
        "deleted": 0,
        "batches": 1,
        "version_conflicts": 0,
        "noops": 0,
        "retries": {
          "bulk": 0,
          "search": 0
        },
        "throttled": "0s",
        "throttled_millis": 0,
        "requests_per_second": -1,
        "throttled_until": "0s",
        "throttled_until_millis": 0
      },
      {
        "slice_id": 1,
        "total": 23,
        "updated": 23,
        "created": 0,
        "deleted": 0,
        "batches": 1,
        "version_conflicts": 0,
        "noops": 0,
        "retries": {
          "bulk": 0,
          "search": 0
        },
        "throttled": "0s",
        "throttled_millis": 0,
        "requests_per_second": -1,
        "throttled_until": "0s",
        "throttled_until_millis": 0
      },
      {
        "slice_id": 2,
        "total": 29,
        "updated": 29,
        "created": 0,
        "deleted": 0,
        "batches": 1,
        "version_conflicts": 0,
        "noops": 0,
        "retries": {
          "bulk": 0,
          "search": 0
        },
        "throttled": "0s",
        "throttled_millis": 0,
        "requests_per_second": -1,
        "throttled_until": "0s",
        "throttled_until_millis": 0
      },
      {
        "slice_id": 3,
        "total": 19,
        "updated": 18,
        "created": 0,
        "deleted": 0,
        "batches": 1,
        "version_conflicts": 1,
        "noops": 0,
        "retries": {
          "bulk": 0,
          "search": 0
        },
        "throttled": "0s",
        "throttled_millis": 0,
        "requests_per_second": -1,
        "throttled_until": "0s",
        "throttled_until_millis": 0
      },
      {
        "slice_id": 4,
        "total": 30,
        "updated": 30,
        "created": 0,
        "deleted": 0,
        "batches": 1,
        "version_conflicts": 0,
        "noops": 0,
        "retries": {
          "bulk": 0,
          "search": 0
        },
        "throttled": "0s",
        "throttled_millis": 0,
        "requests_per_second": -1,
        "throttled_until": "0s",
        "throttled_until_millis": 0
      },
      {
        "slice_id": 5,
        "total": 25,
        "updated": 25,
        "created": 0,
        "deleted": 0,
        "batches": 1,
        "version_conflicts": 0,
        "noops": 0,
        "retries": {
          "bulk": 0,
          "search": 0
        },
        "throttled": "0s",
        "throttled_millis": 0,
        "requests_per_second": -1,
        "throttled_until": "0s",
        "throttled_until_millis": 0
      }
    ],
    "failures": [
      {
        "index": "phoenix-2023-07-01-all_categories",
        "type": "_doc",
        "id": "050aecc6-55d2-3ff4-9c6a-7672b8c31e8e",
        "cause": {
          "type": "version_conflict_engine_exception",
          "reason": "[050aecc6-55d2-3ff4-9c6a-7672b8c31e8e]: version conflict, required seqNo [392388470], primary term [1]. current document has seqNo [399875031] and primary term [1]",
          "index_uuid": "jOv6Zv19Td-EY0IJBE09qw",
          "shard": "3",
          "index": "phoenix-2023-07-01-all_categories"
        },
        "status": 409
      }
    ]
  }
}

Error Obtained is:

org.opensearch.client.json.UnexpectedJsonEventException: Unexpected JSON event 'START_OBJECT' instead of '[KEY_NAME, VALUE_STRING, VALUE_NUMBER, VALUE_TRUE, VALUE_FALSE]'
	at org.opensearch.client.json.JsonpUtils.ensureAccepts(JsonpUtils.java:82) ~[task/:?]
	at org.opensearch.client.json.JsonpDeserializerBase$ArrayDeserializer.deserialize(JsonpDeserializerBase.java:352) ~[task/:?]
	at org.opensearch.client.json.JsonpDeserializerBase$ArrayDeserializer.deserialize(JsonpDeserializerBase.java:322) ~[task/:?]
	at org.opensearch.client.json.JsonpDeserializer.deserialize(JsonpDeserializer.java:88) ~[task/:?]
	at org.opensearch.client.json.ObjectDeserializer$FieldObjectDeserializer.deserialize(ObjectDeserializer.java:85) ~[task/:?]
	at org.opensearch.client.json.ObjectDeserializer.deserialize(ObjectDeserializer.java:189) ~[task/:?]
	at org.opensearch.client.json.ObjectDeserializer.deserialize(ObjectDeserializer.java:150) ~[task/:?]
	at org.opensearch.client.json.JsonpDeserializer.deserialize(JsonpDeserializer.java:88) ~[task/:?]
	at org.opensearch.client.json.ObjectBuilderDeserializer.deserialize(ObjectBuilderDeserializer.java:92) ~[task/:?]
	at org.opensearch.client.json.DelegatingDeserializer$SameType.deserialize(DelegatingDeserializer.java:56) ~[task/:?]
	at org.opensearch.client.json.ObjectDeserializer$FieldObjectDeserializer.deserialize(ObjectDeserializer.java:85) ~[task/:?]
	at org.opensearch.client.json.ObjectDeserializer.deserialize(ObjectDeserializer.java:189) ~[task/:?]
	at org.opensearch.client.json.ObjectDeserializer.deserialize(ObjectDeserializer.java:150) ~[task/:?]
	at org.opensearch.client.json.JsonpDeserializer.deserialize(JsonpDeserializer.java:88) ~[task/:?]
	at org.opensearch.client.json.ObjectBuilderDeserializer.deserialize(ObjectBuilderDeserializer.java:92) ~[task/:?]
	at org.opensearch.client.json.DelegatingDeserializer$SameType.deserialize(DelegatingDeserializer.java:56) ~[task/:?]
	at org.opensearch.client.transport.rest_client.RestClientTransport.decodeResponse(RestClientTransport.java:325) ~[task/:?]
	at org.opensearch.client.transport.rest_client.RestClientTransport.getHighLevelResponse(RestClientTransport.java:291) ~[task/:?]
	at org.opensearch.client.transport.rest_client.RestClientTransport.performRequest(RestClientTransport.java:144) ~[task/:?]
	at org.opensearch.client.opensearch.tasks.OpenSearchTasksClient.get(OpenSearchTasksClient.java:123) ~[task/:?]

Do you have any additional context?

Object org.opensearch.client.opensearch.tasks.Status has a field failures defined as a String[].

uriofferup avatar Oct 13 '23 20:10 uriofferup

Without looking at the underlying implementation - which version of the client is this? I also see that you're using the OpenSearch client against ElasticSearch 7.10, please try OpenSearch 1.x and 2.x. If you can reproduce this against OpenSearch 2.x try implementing a YAML REST test?

dblock avatar Oct 16 '23 15:10 dblock

We are using version 2.6.0 of OpenSearch Java Client. I will try to repro this in OpenSearch Server. Thank you.

uriofferup avatar Oct 16 '23 19:10 uriofferup

We are experiencing the exact same thing. We are trying to get task with a task id. Most of the time it works but sometimes it fails with the exact same stack trace. We have not yet found the root cause of the issue but this report will help us where to look. We are also using opensearch-java:2.6.0 and we can reproduce this issue when running Opensearch in docker with the image image: opensearchproject/opensearch:2.7.0

olamelin avatar Nov 01 '23 15:11 olamelin

And as @uriofferup mentioned the task that fails contains an array of json objects and not strings as it is defined in the failures in the response. This is the json of a task that fails the parsing acquired by calling GET _tasks/-EGpqKfgRNydv1V6yc09vg:298365. Trying to get the same task via the java client the exception is thrown

{
  "completed": true,
  "task": {
    "node": "-EGpqKfgRNydv1V6yc09vg",
    "id": 298365,
    "type": "transport",
    "action": "indices:data/write/update/byquery",
    "status": {
      "total": 1,
      "updated": 0,
      "created": 0,
      "deleted": 0,
      "batches": 1,
      "version_conflicts": 1,
      "noops": 0,
      "retries": {
        "bulk": 0,
        "search": 0
      },
      "throttled_millis": 0,
      "requests_per_second": -1,
      "throttled_until_millis": 0
    },
    "description": """redacted""",
    "start_time_in_millis": 1698853787531,
    "running_time_in_nanos": 13688917,
    "cancellable": true,
    "cancelled": false,
    "headers": {}
  },
  "response": {
    "took": 13,
    "timed_out": false,
    "total": 1,
    "updated": 0,
    "created": 0,
    "deleted": 0,
    "batches": 1,
    "version_conflicts": 1,
    "noops": 0,
    "retries": {
      "bulk": 0,
      "search": 0
    },
    "throttled": "0s",
    "throttled_millis": 0,
    "requests_per_second": -1,
    "throttled_until": "0s",
    "throttled_until_millis": 0,
    "failures": [
      {
        "index": "redacted",
        "id": "43da0a67-2750-459d-bd4a-b403b8010425",
        "cause": {
          "type": "version_conflict_engine_exception",
          "reason": "[43da0a67-2750-459d-bd4a-b403b8010425]: version conflict, required seqNo [315295], primary term [1]. current document has seqNo [315331] and primary term [1]",
          "index": "redacted",
          "shard": "0",
          "index_uuid": "uB06NblRQ-OtGtCttxtgnA"
        },
        "status": 409
      }
    ]
  }
}

For completeness the exception stack trace

org.opensearch.client.json.UnexpectedJsonEventException: Unexpected JSON event 'START_OBJECT' instead of '[KEY_NAME, VALUE_STRING, VALUE_NUMBER, VALUE_TRUE, VALUE_FALSE]'
	at org.opensearch.client.json.JsonpUtils.ensureAccepts(JsonpUtils.java:82)
	at org.opensearch.client.json.JsonpDeserializerBase$ArrayDeserializer.deserialize(JsonpDeserializerBase.java:352)
	at org.opensearch.client.json.JsonpDeserializerBase$ArrayDeserializer.deserialize(JsonpDeserializerBase.java:322)
	at org.opensearch.client.json.JsonpDeserializer.deserialize(JsonpDeserializer.java:88)
	at org.opensearch.client.json.ObjectDeserializer$FieldObjectDeserializer.deserialize(ObjectDeserializer.java:85)
	at org.opensearch.client.json.ObjectDeserializer.deserialize(ObjectDeserializer.java:189)
	at org.opensearch.client.json.ObjectDeserializer.deserialize(ObjectDeserializer.java:150)
	at org.opensearch.client.json.JsonpDeserializer.deserialize(JsonpDeserializer.java:88)
	at org.opensearch.client.json.ObjectBuilderDeserializer.deserialize(ObjectBuilderDeserializer.java:92)
	at org.opensearch.client.json.DelegatingDeserializer$SameType.deserialize(DelegatingDeserializer.java:56)
	at org.opensearch.client.json.ObjectDeserializer$FieldObjectDeserializer.deserialize(ObjectDeserializer.java:85)
	at org.opensearch.client.json.ObjectDeserializer.deserialize(ObjectDeserializer.java:189)
	at org.opensearch.client.json.ObjectDeserializer.deserialize(ObjectDeserializer.java:150)
	at org.opensearch.client.json.JsonpDeserializer.deserialize(JsonpDeserializer.java:88)
	at org.opensearch.client.json.ObjectBuilderDeserializer.deserialize(ObjectBuilderDeserializer.java:92)
	at org.opensearch.client.json.DelegatingDeserializer$SameType.deserialize(DelegatingDeserializer.java:56)
	at org.opensearch.client.transport.rest_client.RestClientTransport.decodeResponse(RestClientTransport.java:325)
	at org.opensearch.client.transport.rest_client.RestClientTransport.getHighLevelResponse(RestClientTransport.java:291)
	at org.opensearch.client.transport.rest_client.RestClientTransport.performRequest(RestClientTransport.java:144)
	at org.opensearch.client.opensearch.tasks.OpenSearchTasksClient.get(OpenSearchTasksClient.java:123)
	at org.opensearch.client.opensearch.tasks.OpenSearchTasksClient.get(OpenSearchTasksClient.java:137)

olamelin avatar Nov 01 '23 16:11 olamelin

Looks like a task with this error can't be parsed. Try to turn this into a (failing) unit test?

dblock avatar Nov 01 '23 21:11 dblock

We started encountering this on the 2.8.0 client as well. It looks to be because the failures are trying to be deserialized as strings, but they contain an TaskFailure object. I have put this into a PR if you want to check it out https://github.com/opensearch-project/opensearch-java/pull/727

Bfindlay avatar Nov 15 '23 11:11 Bfindlay

Thanks for the PR! Do you know whether this was a bug introduced in 2.8.0, or an unexpected server-side change?

dblock avatar Nov 15 '23 12:11 dblock

@dblock We just migrated from high level client and so far have only tested with 2.7.0 and 2.8.0 and the issue existed in both versions. I am not sure where the original bug was introduced.

Bfindlay avatar Nov 15 '23 12:11 Bfindlay

I found the issue using version 2.6.0 of OpenSearch Java Client.

uriofferup avatar Nov 15 '23 17:11 uriofferup

Thanks @Bfindlay for the PR.

uriofferup avatar Nov 15 '23 17:11 uriofferup

@Bfindlay want to finish https://github.com/opensearch-project/opensearch-java/pull/727?

dblock avatar Dec 04 '23 15:12 dblock

@dblock Yeah I will get to it sometime this week or next week.

Bfindlay avatar Dec 04 '23 22:12 Bfindlay