https://datahubproject.io logo
Join Slack
Powered by
hi, I’ve gotten past the sso issues (thanks!), but...
# troubleshoot
d
hi, I’ve gotten past the sso issues (thanks!), but on to the next problem. Basically datahub-frontend is receiving 503s when it tries to talk to gms, and gms is unavailable because of this cryptic error:
Copy code
18:01:33 [pool-7-thread-1] ERROR c.d.authorization.DataHubAuthorizer - Failed to retrieve policy urns! Skipping updating policy cache until next refresh. start: 0, count: 30
com.datahub.util.exception.ESQueryException: Search query failed:
	at com.linkedin.metadata.search.elasticsearch.query.ESSearchDAO.executeAndExtract(ESSearchDAO.java:73)
	at com.linkedin.metadata.search.elasticsearch.query.ESSearchDAO.search(ESSearchDAO.java:100)
	at com.linkedin.metadata.search.elasticsearch.ElasticSearchService.search(ElasticSearchService.java:97)
	at com.linkedin.metadata.client.JavaEntityClient.search(JavaEntityClient.java:300)
	at com.datahub.authorization.PolicyFetcher.fetchPolicies(PolicyFetcher.java:50)
	at com.datahub.authorization.PolicyFetcher.fetchPolicies(PolicyFetcher.java:42)
	at com.datahub.authorization.DataHubAuthorizer$PolicyRefreshRunnable.run(DataHubAuthorizer.java:223)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.lang.RuntimeException: Request cannot be executed; I/O reactor status: STOPPED
	at org.elasticsearch.client.RestClient.extractAndWrapCause(RestClient.java:857)
	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:259)
	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:246)
	at org.elasticsearch.client.RestHighLevelClient.internalPerformRequest(RestHighLevelClient.java:1613)
	at org.elasticsearch.client.RestHighLevelClient.performRequest(RestHighLevelClient.java:1583)
	at org.elasticsearch.client.RestHighLevelClient.performRequestAndParseEntity(RestHighLevelClient.java:1553)
	at org.elasticsearch.client.RestHighLevelClient.search(RestHighLevelClient.java:1069)
	at com.linkedin.metadata.search.elasticsearch.query.ESSearchDAO.executeAndExtract(ESSearchDAO.java:60)
	... 12 common frames omitted
Caused by: java.lang.IllegalStateException: Request cannot be executed; I/O reactor status: STOPPED
	at org.apache.http.util.Asserts.check(Asserts.java:46)
	at org.apache.http.impl.nio.client.CloseableHttpAsyncClientBase.ensureRunning(CloseableHttpAsyncClientBase.java:90)
	at org.apache.http.impl.nio.client.InternalHttpAsyncClient.execute(InternalHttpAsyncClient.java:123)
	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:255)
	... 18 common frames omitted
I’ve made sure that container can talk to elasticsearch, so I don’t think it’s connection related
the only other thing in the logs that might be useful is:
Copy code
05:23:25 [main] INFO  c.l.m.s.e.i.ESIndexBuilder - There's diff between new mappings (left) and old mappings (right): not equal: value differences={runId=({type=text, fields={keyword={ignore_above=256, type=keyword}}}, {type=keyword})}
05:23:25 [main] INFO  c.l.m.s.e.i.ESIndexBuilder - Index dataset_datasetusagestatisticsaspect_v1_1671773005835 does not exist. Creating
05:23:25 [main] INFO  c.l.m.s.e.i.ESIndexBuilder - Created index dataset_datasetusagestatisticsaspect_v1_1671773005835
05:23:25 [main] INFO  c.l.m.s.e.i.ESIndexBuilder - Reindexing from dataset_datasetusagestatisticsaspect_v1 to dataset_datasetusagestatisticsaspect_v1_1671773005835 in progress...
05:23:30 [main] INFO  c.l.m.s.e.i.ESIndexBuilder - Reindexing from dataset_datasetusagestatisticsaspect_v1 to dataset_datasetusagestatisticsaspect_v1_1671773005835 in progress...
05:23:35 [main] INFO  c.l.m.s.e.i.ESIndexBuilder - Reindexing from dataset_datasetusagestatisticsaspect_v1 to dataset_datasetusagestatisticsaspect_v1_1671773005835 in progress...
05:23:40 [main] INFO  c.l.m.s.e.i.ESIndexBuilder - Reindexing from dataset_datasetusagestatisticsaspect_v1 to dataset_datasetusagestatisticsaspect_v1_1671773005835 in progress...
05:23:46 [main] INFO  c.l.m.s.e.i.ESIndexBuilder - Reindexing from dataset_datasetusagestatisticsaspect_v1 to dataset_datasetusagestatisticsaspect_v1_1671773005835 in progress...
05:23:51 [main] INFO  c.l.m.s.e.i.ESIndexBuilder - Reindexing from dataset_datasetusagestatisticsaspect_v1 to dataset_datasetusagestatisticsaspect_v1_1671773005835 in progress...
05:23:56 [main] INFO  c.l.m.s.e.i.ESIndexBuilder - Reindexing from dataset_datasetusagestatisticsaspect_v1 to dataset_datasetusagestatisticsaspect_v1_1671773005835 in progress...
05:24:01 [main] INFO  c.l.m.s.e.i.ESIndexBuilder - Reindexing from dataset_datasetusagestatisticsaspect_v1 to dataset_datasetusagestatisticsaspect_v1_1671773005835 in progress...
05:24:01 [main] INFO  c.l.m.s.e.i.ESIndexBuilder - Reindexing dataset_datasetusagestatisticsaspect_v1 to dataset_datasetusagestatisticsaspect_v1_1671773005835 task has completed, will now check if reindex was successful
05:24:04 [main] INFO  c.l.m.s.e.i.ESIndexBuilder - Post-reindex document count is different, source_doc_count: 233077 reindex_doc_count: 211330
05:24:06 [main] INFO  c.l.r.t.h.c.c.AbstractNettyClient - Shutdown requested
Copy code
05:24:06 [R2 Nio Event Loop-1-4] INFO  c.l.r.t.h.c.c.ChannelPoolManagerImpl - Shutdown complete
05:24:07 [main] INFO  o.a.k.clients.producer.KafkaProducer - [Producer clientId=producer-1] Closing the Kafka producer with timeoutMillis = 9223372036854775807 ms.
05:25:33 [pool-7-thread-1] ERROR c.l.m.s.e.query.ESSearchDAO - Search query failed
it’s unclear whether reindexing failed and caused components to shut down
b
It looks like we are having a shutdown post a reindexing. If you restart the datahub-gms container, does the same thing occur? cc @brainy-tent-14503
Is this a new quickstart of the most recent version? Or something else? Are you deployed on helm?
b
The reindexing is definitely a process that needs work and is being worked on. In this case we have a failing reindex due to document count differences 
Post-reindex document count is different, source_doc_count: 233077 reindex_doc_count: 211330
, this can happen if the mappings change based on the pegasus models.
o
Can you grep the logs for something like this?:
Copy code
org.apache.http.nio.reactor.IOReactorException: I/O dispatch worker terminated abnormally
b
Differences in document counts can be caused by incompatible documents vs the new mapping. There should be some logs around the differences between the old and new mapping earlier in the log.
The reindex could have been interrupted or running from multiple GMS/MAE instances too.
o
This seems to be happening not due to an issue in the reindex, but due to an interruption from:
Copy code
Caused by: java.lang.IllegalStateException: Request cannot be executed; I/O reactor status: STOPPED
The RestHighLevelClient probably lost connection during the reindex which would result in an incorrect document count
The typical cause for this is an OOM error on the pod
We added defenses against this for most exceptions, but Java system errors will still result in the I/O reactor killing itself and never restarting, requiring a restart of the pod.
b
Could be a possibility. I’ve definitely seen on working instances with 
18:01:33 [pool-7-thread-1] ERROR c.d.authorization.DataHubAuthorizer - Failed to retrieve policy urns! Skipping updating policy cache until next refresh. start: 0, count: 30
b
This can be safely ignored at boot up
b
I wonder though if the error is before or after the reindexing
The detected change is 
value differences={runId=({type=text, fields={keyword={ignore_above=256, type=keyword}}}, {type=keyword})}
in 
dataset_datasetusagestatistics
and it looks like a 256 character limit is being applied. Let me see if I can find where that’s being generated from. It should merely discard the runIds and not the entire document on reindex unless perhaps that was the only field.
Can you provide a bit more information? What is the version of Elasticsearch and what is the original and destination release version?
d
hey sorry I had to step away
Elasticsearch: we used the aws managed opensearch 1.1, which looks like is cut from elasticsearch 7.1
b
No problem, which datahub version are you updating from?
d
If you restart the datahub-gms container, does the same thing occur?
yea I’ve tried a couple times to restart that service
we upgraded successfully from 0.8.45 -> 0.9.3, then a few weeks in, we got hit with the SSO issue, and so now I upgraded to 0.9.4
b
Interesting, I am surprised to see that the reindex is on 0.9.3 to 4 and not on the earlier update. Let me look at the diff for .3 vs .4
d
Can you grep the logs for something like this?:
Copy code
org.apache.http.nio.reactor.IOReactorException: I/O dispatch worker terminated abnormally
just grepped (case insensitive) for ‘terminated’, ‘ioreactor’, and nothing came up. The only two lines that have the word reactor in them are:
Copy code
java.lang.RuntimeException: Request cannot be executed; I/O reactor status: STOPPED
Caused by: java.lang.IllegalStateException: Request cannot be executed; I/O reactor status: STOPPED
Is this a new quickstart of the most recent version? Or something else? Are you deployed on helm?
it’s an upgrade to 0.9.4 (with the sso fix). We don’t use kubernetes, we’re using Nomad, so we basically converted the deployment from that to nomad
b
So @orange-night-91387 suggested that we’re seeing an index here that has documents ingested with dynamic mapping (at least for the tagId) field. This means that at some point documents were being indexed before the application’s mappings were applied. This likely means that at least some of the documents indexed in at least that one index have an incompatibility with the actual mappings. This is assuming that the reindex process isn’t being interrupted somehow before it completes. The final count comparison should be after a successful reindex.
d
ok, what would that mean in terms of what we would need to do to get this running again?
b
Are you able to run manual requests against the opensearch rest api?
d
yea
b
Let me check the code to see if it keeps the partial index. Or not. I’d start by backing up the original index with the clone api.
d
one question here: if we’re just ingesting data every day anyway and not generating content within datahub, could we just delete some things to start fresh?
b
yeah, that’s certainly easier. i would remove all documents from the problem index and then see what happens.
I am hoping it’s just one index or maybe a few. It will depend on the index whether we should be deleting documents.
In this first one at least, its ok, 
dataset_datasetusagestatisticsaspect
FYI - Release v0.9.5 is out (both cli and server). This PR includes bug fixes for OIDC, most notably
d
Sorry my damn dog turned my laptop off, waiting to spin back up
And awesome re: 0.9.5
b
Well, 0.9.5 is building but its tagged at least
d
ok i deleted 
dataset_datasetusagestatisticsaspect_v1
, I’ll restart gms and see what happens
sweet it’s working
I suppose there’s still the mystery of how the index got into an irregular state. Would it at all be related to what the datahub cron jobs for cleanup and restoring indices?
b
It is possible, but this seems more like some of the records were written at an odd time with regard to perhaps an in progress upgrade
o
Basically ElasticSearch will set a default field mapping if one does not exist, if a record came in before the index was set up then it's possible you had been running for awhile with an "incorrect" mapping that happened whenever the instance was set up. In this case since the field type is the same, it just has truncation, it wouldn't have caused any issues, but when upgrading we added code to detect changes in field mappings which then detected the inconsistency and tried to rectify it.
d
Ok cool, we’ll thanks guys, appreciate you helping me out
Have a good holidays
o
We set up the index configuration when the MAE Consumer starts up so it would have had to sneak in between GMS starting up and MAE coming up or possibly a not fully defined mapping from an old version. You too! 😄
a
hey all, just an fyi for anyone who stumbles on this thread in the future, we hit this same thing on a different index (we’ve been running v0.9.5 for a while) and same fix of deleting the problematic ES index + restarting gms fixed for us as well
s
Hi @abundant-airport-72599, @orange-night-91387 i am also facing exact same issue while upgrading datahub from 0.8.4 to 0.9.5 but in my case same error i got before any reindexing so unable to locate problematic ES index to delete.. given below the error which i got in systemupdate pod
error.log
i see some error in GMS regarding document missing in some indexes [9]: index [dataprocessinstanceindex_v2], type [_doc], id [urn%3Ali%3AdataProcessInstance%3Ac5ba1f4534bb47844882fc37968a9150], message [[dataprocessinstanceindex_v2/pnsSn0DDTDewfErNw64Dtw][[dataprocessinstanceindex_v2][0]] OpenSearchException[OpenSearch exception [type=document_missing_exception, reason=[_doc][urn%3Ali%3AdataProcessInstance%3Ac5ba1f4534bb47844882fc37968a9150]: document missing]]] [1]: index [dataprocessinstanceindex_v2], type [_doc], id [urn%3Ali%3AdataProcessInstance%3A8f184a6c8eaa3ed035174c4733b8c054], message [[dataprocessinstanceindex_v2/pnsSn0DDTDewfErNw64Dtw][[dataprocessinstanceindex_v2][0]] OpenSearchException[OpenSearch exception [type=document_missing_exception, reason=[_doc][urn%3Ali%3AdataProcessInstance%3A8f184a6c8eaa3ed035174c4733b8c054]: document missing]]]
o
The first error you posted indicates you are using a v0.10.x helm chart with v0.9.x. SystemUpdate was added in v0.10 and shouldn't be executed on v0.9.5.
131 Views
Open in Slack
PreviousNext
Powered by