https://datahubproject.io logo
Join Slack
Powered by
:wave: just noticed that our MCE service started ...
# all-things-deployment
h
👋 just noticed that our MCE service started spewing things like
Copy code
2023-04-03 13:21:27,918 [R2 Nio Event Loop-1-1] WARN  c.l.r.t.h.c.c.ChannelPoolLifecycle - Failed to create channel, remote=localhost/127.0.0.1:8080
io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: localhost/127.0.0.1:8080
Caused by: java.net.ConnectException: Connection refused
        at java.base/sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
        at java.base/sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:777)
        at io.netty.channel.socket.nio.NioSocketChannel.doFinishConnect(NioSocketChannel.java:337)
        at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:334)
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:776)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
        at java.base/java.lang.Thread.run(Thread.java:829)
2023-04-03 13:21:27,919 [ThreadPoolTaskExecutor-1] ERROR c.l.m.k.MetadataChangeEventsProcessor - MCE Processor Error
com.linkedin.r2.RemoteInvocationException: com.linkedin.r2.RemoteInvocationException: Failed to get response from server for URI <http://localhost:8080/entities>
----
2023-04-03 13:21:27,919 [ThreadPoolTaskExecutor-1] INFO  c.l.m.k.MetadataChangeEventsProcessor - Error while processing MCE: FailedMetadataChangeEvent - {error=com.linkedin.r2.RemoteInvocationException: com.linkedin.r2.RemoteInvocationException: Failed to get response from server for URI <http://localhost:8080/entities>
Why would the MCE trying to call 
<http://localhost:8080/entities>
? I checked, and GMS_HOST is correct.
📖 1
🔍 1
✅ 2
l
Hey there 👋 I'm The DataHub Community Support bot. I'm here to help make sure the community can best support you with your request. Let's double check a few things first: ✅ There's a lot of good information on our docs site: www.datahubproject.io/docs, Have you searched there for a solution? ✅ It's not uncommon that someone has run into your exact problem before in the community. Have you searched Slack for similar issues? Did you find a solution to your issue? ❌ Sorry you weren't able to find a solution. I'm sending you some tips on info you can provide to help the community troubleshoot. Whenever you feel your issue is solved, please react ✅ to your original message to let us know!
h
1. v0.9.5 2. K8s 3. in opening message 4. see below
here are the env vars for the containers:
Copy code
Environment:
      KAFKA_BOOTSTRAP_SERVER:                                         <removed>
      KAFKA_SCHEMAREGISTRY_URL:                                       <removed>
      SPRING_KAFKA_PROPERTIES_BASIC_AUTH_USER_INFO:                   <set to the key 'SPRING_KAFKA_PROPERTIES_BASIC_AUTH_USER_INFO' in secret 'datahub-mce-static-secrets-40e2f3c14cc7940864930b25efabd577'>  Optional: false
      MCE_CONSUMER_ENABLED:                                           true
      GMS_HOST:                                                       wolt-datahub-gms
      GMS_PORT:                                                       8080
      SPRING_KAFKA_PROPERTIES_SSL_KEYSTORE_PASSWORD:                  <set to the key 'SSL_KEYSTORE_PASSWORD' in secret 'datahub-mce-static-secrets-40e2f3c14cc7940864930b25efabd577'>          Optional: false
      SPRING_KAFKA_PROPERTIES_SSL_TRUSTSTORE_PASSWORD:                <set to the key 'KAFKA_SSL_TRUSTSTORE_PASSWORD' in secret 'datahub-mce-static-secrets-40e2f3c14cc7940864930b25efabd577'>  Optional: false
      SPRING_KAFKA_PROPERTIES_SSL_KEYSTORE_LOCATION:                  /vault/secrets/client.keystore.p12
      SPRING_KAFKA_PROPERTIES_SSL_TRUSTSTORE_LOCATION:                /vault/secrets/client.truststore.jks
      SPRING_KAFKA_PROPERTIES_SECURITY_PROTOCOL:                      SSL
      SPRING_KAFKA_PROPERTIES_KAFKA_SECURITY_PROTOCOL:                SSL
      SPRING_KAFKA_PROPERTIES_SSL_KEYSTORE_TYPE:                      PKCS12
      SPRING_KAFKA_PROPERTIES_SSL_TRUSTSTORE_TYPE:                    JKS
      SPRING_KAFKA_PROPERTIES_SSL_PROTOCOL:                           TLS
      SPRING_KAFKA_PROPERTIES_SSL_ENDPOINT_IDENTIFICATION_ALGORITHM:
      SPRING_KAFKA_PROPERTIES_BASIC_AUTH_CREDENTIALS_SOURCE:          USER_INFO
      ENABLE_PROMETHEUS:                                              true
I can curl the 
http://<GMS_HOST>:8080/entities
(but get a 401) so it’s reachable
o
Are you using custom helm charts? There was an optimization added here where MCE Consumer will skip the round-trip to GMS when running standalone and if you're using custom charts it's possible you're missing some properties. Note this is only relevant when running async mode or emitting events directly to the MCP topic, otherwise this shouldn't have any impact on your event processing.
h
I’m using a homemade manifest (kustomization) based off of the helm chart anno 2021 🙈 I think the issue was this https://github.com/datahub-project/datahub/pull/5451 🤦
Note this is only relevant when running async mode or emitting events directly to the MCP topic, otherwise this shouldn’t have any impact on your event processing.
Is there any documentation on this or a PR I can investigate?
o
https://github.com/datahub-project/datahub/pull/6744 This one 🙂 any relevant configurations should be documented in our helm charts
f
It looks like the GMS service was not properly started when the MCE process made the remote invocation. This happened to us in the last few days too, with 
v0.10.1
. It also happened with some randomness across our deployments, and our solution is to rerun the Helm deployment. @high-hospital-85984 Maybe you could search the logs of datahub-gms and see if there is a root cause which stopped the GMS service from starting? In our case there was an exception, namely 
java.lang.UnsupportedOperationException: Failed to find Typeref schema associated with Config-based Entity
. If that is the case, then maybe redeploying will fix it, like we did. My rough guess is that there is some timing issue between the loading of typeref schema and the starting of the service. I’m pasting the stacktrace in case anyone would like to investigate further.
UnsupportedOperationException.java.stacktrace
a
@orange-night-91387 could someone take a look at this? The GMS pods in all of our clusters went into a crash loop last night with the exception Xuelei posted above. We haven't changed anything in these clusters for more than 10 days. So this is very concerning. FYI @gray-airplane-39227
o
That stacktrace is a red herring coming from a warning log. There should be something else happening
All the above stacktrace is saying is that the legacy MAE was unable to be produced for a purely config based entity that doesn't have a legacy Urn typeref class, this is wrapped in a try-catch and logged for informational purposes.
a
Thank you @orange-night-91387! Every time before GMS restarted, we saw 
WARN c.l.r.t.h.c.c.ChannelPoolLifecycle:139 - Failed to create channel, remote=localhost/127.0.0.1:8080
three times. And then 
ERROR c.d.m.ingestion.IngestionScheduler:244 - Failed to retrieve ingestion sources! Skipping updating schedule cache until next refresh. start: 0, count: 30
Would failure to retrieve ingestion sources cause GMS to crash? I also checked the gms.debug.log in the pod and there doesn't seem to be any new information.
o
IngestionScheduler failing to load shouldn't crash GMS. Are there any messages in the logs like:
Copy code
"Latest system update version: VERSION"
Or:
Copy code
System version is not up to date: VERSION. Waiting for datahub-upgrade to complete..
My guess is GMS is never coming up healthy
a
@orange-night-91387 we ran helm upgrade again with no code change and it seems to have fixed the problem. No, I didn't find any of the two log entries in GMS. I noticed that 
kafka
restarted when all these started happening.
Copy code
[2023-04-18 11:09:35,078] INFO [KafkaServer id=0] shut down completed (kafka.server.KafkaServer)
Oh, 
kafka
has the following log. Does this ring a bell?
Copy code
[2023-04-18 11:09:31,814] INFO Terminating process due to signal SIGTERM (org.apache.kafka.common.utils.LoggingSignalHandler)
o
It doesn't, but if kafka was down then GMS would not have started healthily so that's probably the culprit
a
kafka
restarted itself immediately after this. Is GMS supposed to be able to handle this gracefully when kafka restarts?
o
Oh I figured it was restarted with the helm update, yeah GMS should handle reconnection gracefully. Not sure then thinking
a
Actually GKE automatically recreated 
kafka
when it detected that it was shutdown.
@orange-night-91387 We found that GKE recreated all the nodes and moved the pods to the new nodes due to a maintenance upgrade. So all the pods including the prerequisites were restarted around that period. Could GMS for some reason not being able to handle this properly? From the logs, I can see 
kafka
and all the prerequisites pods restarted successfully and has been healthy.
Copy code
kafka
[2023-04-18 11:14:51,698] INFO Session establishment complete on server prerequisites-zookeeper/10.116.5.208:2181, session id = 0x100000779830001, negotiated timeout = 18000 (org.apache.zookeeper.ClientCnxn)
Also specifically, in this case, 
kafka
was restarted before 
zookeeper
. So there was a period when 
kafka
wasn't able to connect to zk, but eventually it did.
@orange-night-91387 I took more look at this and I think it is related to the thread below. https://datahubspace.slack.com/archives/C029A3M079U/p1679415770758039?thread_ts=1678354501.041149&amp;cid=C029A3M079U So when GKE perform a system update, it will restart all of our pods. But it will not run the system update job because it is not a deployment. Will this cause the GMS not be able to start?
Another data point is that I noticed that GMS bootstrap seems to get stuck at the following step, the name seems to indicate that this is system update.
Copy code
Executing bootstrap step 1/13 with name WaitForSystemUpdateStep...
o
Yes, that could cause an issue if your kafka topics are not persistent or you are updating versions
a
@orange-night-91387 thank you! We didn't modify anything. It was just GKE perform update of the k8s that result in restarting the pods. Wouldn't this be a bug in the design of the GMS's dependency on the system update job? I noticed that for some cluster that were deployed very recently, GMS were able to restart after the GKE pods restart. Is this because the system update message is still there?
o
It's not a bug, GMS expects the system update job to have been run at least once per release. We verify this using a persistent Kafka topic. If the topic is not persisted (seems like the Kafka restart did this in your case?) then system update would need to be run again to produce the message we're looking for. If the backend was not modified then System Update will recognize this and it will essentially be a no-op and produce the message GMS is looking for without making modifications to the indices.
a
Ok, I see. Then the question here is why that topic wasn't persisted through the GKE maintenance update. I see the kafka setup job configures the topic to have infinite retention.
Copy code
sending DataHubUpgradeHistory_v1 --partitions 1 --config <http://retention.ms|retention.ms>=-1 --topic DataHubUpgradeHistory_v1
o
The wait on GMS side is also configurable if this is unmanageable as long as you are cognizant of the fact it could cause errors prior to it actually being executed. Yep! That is a good question and I'm not sure why that would happen 😞
a
Is there anything I can check in kafka to know if it successfully loaded the topic/message after the restart? I saw the following log in kafka after its restart.
Copy code
[2023-04-18 11:12:41,725] INFO Completed load of Log(dir=/bitnami/kafka/data/DataHubUpgradeHistory_v1-0, topicId=OPUSuZLGR4i6YAW5cxeK8Q, topic=DataHubUpgradeHistory_v1, partition=0, highWatermark=3, lastStableOffset=3, logStartOffset=3, logEndOffset=3) with 1 segments in 14ms (59/61 loaded in /bitnami/kafka/data) (kafka.log.LogManager)
o
Should be able to use the kafka consumer cli to read from beginning to check the messages
It's a fairly lightweight topic so shouldn't be hard to look through them and check for the version
a
Thank you! I will take a look. I also found the following logs on the GMS side related to 
DataHubUpgradeHistory_v1
. Do you see anything wrong?
Copy code
2023-04-18 11:13:37,858 [main] INFO  o.a.k.clients.consumer.KafkaConsumer:974 - [Consumer clientId=consumer-datahub-duhe-consumer-job-client-gms-2, groupId=datahub-duhe-consumer-job-client-gms] Subscribed to topic(s): DataHubUpgradeHistory_v1

2023-04-18 11:13:40,071 [ThreadPoolTaskExecutor-1] INFO  o.a.k.c.c.i.ConsumerCoordinator:604 - [Consumer clientId=consumer-datahub-duhe-consumer-job-client-gms-2, groupId=datahub-duhe-consumer-job-client-gms] Finished assignment for group at generation 3: {consumer-datahub-duhe-consumer-job-client-gms-2-8db409fc-86f7-49a7-8932-8291759d0385=Assignment(partitions=[DataHubUpgradeHistory_v1-0])}

2023-04-18 11:13:40,129 [ThreadPoolTaskExecutor-1] INFO  o.a.k.c.c.i.ConsumerCoordinator:273 - [Consumer clientId=consumer-datahub-duhe-consumer-job-client-gms-2, groupId=datahub-duhe-consumer-job-client-gms] Adding newly assigned partitions: DataHubUpgradeHistory_v1-0

2023-04-18 11:13:40,187 [ThreadPoolTaskExecutor-1] INFO  o.a.k.c.c.i.ConsumerCoordinator:1299 - [Consumer clientId=consumer-datahub-duhe-consumer-job-client-gms-2, groupId=datahub-duhe-consumer-job-client-gms] Found no committed offset for partition DataHubUpgradeHistory_v1-0

2023-04-18 11:13:40,331 [ThreadPoolTaskExecutor-1] INFO  o.a.k.c.c.i.SubscriptionState:397 - [Consumer clientId=consumer-datahub-duhe-consumer-job-client-gms-2, groupId=datahub-duhe-consumer-job-client-gms] Resetting offset for partition DataHubUpgradeHistory_v1-0 to offset 3.

2023-04-18 11:13:40,412 [ThreadPoolTaskExecutor-1] INFO  o.a.k.clients.consumer.KafkaConsumer:1603 - [Consumer clientId=consumer-datahub-duhe-consumer-job-client-gms-2, groupId=datahub-duhe-consumer-job-client-gms] Seeking to offset 2 for partition DataHubUpgradeHistory_v1-0

2023-04-18 11:13:40,418 [ThreadPoolTaskExecutor-1] INFO  o.s.k.l.KafkaMessageListenerContainer:292 - datahub-duhe-consumer-job-client-gms: partitions assigned: [DataHubUpgradeHistory_v1-0]

2023-04-18 11:13:40,472 [ThreadPoolTaskExecutor-1] INFO  o.a.k.c.consumer.internals.Fetcher:1274 - [Consumer clientId=consumer-datahub-duhe-consumer-job-client-gms-2, groupId=datahub-duhe-consumer-job-client-gms] Fetch offset 2 is out of range for partition DataHubUpgradeHistory_v1-0, resetting offset

2023-04-18 11:13:40,486 [ThreadPoolTaskExecutor-1] INFO  o.a.k.c.c.i.SubscriptionState:397 - [Consumer clientId=consumer-datahub-duhe-consumer-job-client-gms-2, groupId=datahub-duhe-consumer-job-client-gms] Resetting offset for partition DataHubUpgradeHistory_v1-0 to offset 3.
But there wasn't any log like below after the above logs.
Copy code
2023-04-19 17:30:19,254 [ThreadPoolTaskExecutor-1] INFO  c.l.m.k.b.DataHubUpgradeKafkaListener:82 - Latest system update version: null-4
@orange-night-91387 I ran kafka consumer cli in the pod and the topic has two messages.
Copy code
$ /opt/bitnami/kafka/bin/kafka-console-consumer.sh --topic DataHubUpgradeHistory_v1 --bootstrap-server localhost:9092 --from-beginning

null-4

null-5
Below was the log when the last time GMS was updated and successfully started, which was before the GKE maintenance update.
Copy code
2023-04-07 20:36:38,884 [ThreadPoolTaskExecutor-1] INFO  c.l.m.k.b.DataHubUpgradeKafkaListener:82 - Latest system update version: null-3
So it looks like the message before and including 
null-3
were all lost. Do you have any suggestions on what to look next and how this might have happened?
I noticed that the infinite (
-1
) retention.ms policy for 
DataHubUpgradeHistory_v1
was somehow not honored. When I printed out all the configs for the topic, the retention.ms turned out to be the default 7 days.
Copy code
$ /opt/bitnami/kafka/bin/kafka-configs.sh --entity-type topics --entity-name DataHubUpgradeHistory_v1 --bootstrap-server localhost:9092 --describe --all | grep "<http://retention.ms|retention.ms>"
  <http://retention.ms|retention.ms>=604800000 sensitive=false synonyms={}
  <http://delete.retention.ms|delete.retention.ms>=86400000 sensitive=false synonyms={DEFAULT_CONFIG:<http://log.cleaner.delete.retention.ms|log.cleaner.delete.retention.ms>=86400000}
In comparison, the retention period (30 days) for 
MetadataChangeLog_Timeseries_v1
was honored.
Copy code
$ /opt/bitnami/kafka/bin/kafka-configs.sh --entity-type topics --entity-name MetadataChangeLog_Timeseries_v1 --bootstrap-server localhost:9092 --describe --all | grep "<http://retention.ms|retention.ms>"
  <http://retention.ms|retention.ms>=7776000000 sensitive=false synonyms={DYNAMIC_TOPIC_CONFIG:<http://retention.ms|retention.ms>=7776000000}
  <http://delete.retention.ms|delete.retention.ms>=86400000 sensitive=false synonyms={DEFAULT_CONFIG:<http://log.cleaner.delete.retention.ms|log.cleaner.delete.retention.ms>=86400000}
@brainy-tent-14503 @orange-night-91387 So I figured out the problem. There was a bug in 
kafka-setup.sh
that David fixed two month ago and was released as part of 
v0.10.1
. https://github.com/datahub-project/datahub/commit/b4b3a398291ee6aa2a1bbd7ca04a11eec3eb86f0#diff-49b80548c7d96c9546170e[…]dd67c4cd9f0655736156526R119 As a result, all DH deployed prior to 
v0.10.1
doesn't have the retention set correctly for 
DataHubUpgradeHistory_v1
. And deploying a version 
>= v0.10.1
also doesn't fix the problem because the kafka setup script doesn't create the topic if it already exists. So kafka stuck with the wrong retention setting for that topic. In my opinion this is a pretty serious issue because any such cluster would suddenly stop working if their GMS restarts more than 7 days after their last system update job is run.
@orange-night-91387 @brainy-tent-14503 could you take a look at my last message above and confirm? Thank you!
@orange-night-91387 @brainy-tent-14503 https://github.com/datahub-project/datahub/pull/7883
b
@able-evening-90828 - Merged!
5 Views
Open in Slack
PreviousNext
Powered by