https://flink.apache.org/ logo
Join Slack
Powered by
[Flink Operator v 1.1.0] Has anyone seen this erro...
# troubleshooting
k
[Flink Operator v 1.1.0] Has anyone seen this error? Perhaps related to race condition when deploying multiple flink applications.
Copy code
Message: Forbidden!Configured service account doesn't have access. Service account may have been revoked. deployments.extensions "eventlogger-pipeline-v0" is forbidden: User "system:serviceaccount:eventlogger-pipeline-staging:flink" cannot get resource "deployments" in API group "extensions" in the namespace "eventlogger-pipeline-staging"
[Context] Two flinkdeployments, 
eventlogger-pipeline-v0
and 
eventlogger-pipeline-v0-1
attempt to be deployed, but one fails with this exception, and the other goes through. More logs in the thread ->
Logs indicate something related to either access or insufficient resources.
Copy code
2023-02-08 01:42:34,726 WARN  org.apache.flink.runtime.resourcemanager.active.ActiveResourceManager [] - Failed requesting worker with resource spec WorkerResourceSpec {cpuCores=6.0, taskHeapSize=537.600mb (563714445 bytes), taskOffHeapSize=0 bytes, networkMemSize=158.720mb (166429984 bytes), managedMemSize=634.880mb (665719939 bytes), numSlots=12}, current pending count: 3
java.util.concurrent.CompletionException: io.fabric8.kubernetes.client.KubernetesClientException: Failure executing: GET at: <https://172.20.0.1/apis/apps/v1/namespaces/eventlogger-pipeline-staging/deployments/gantry-eventlogger-pipeline-v0>. Message: Forbidden!Configured service account doesn't have access. Service account may have been revoked. deployments.extensions "gantry-eventlogger-pipeline-v0" is forbidden: User "system:serviceaccount:eventlogger-pipeline-staging:flink" cannot get resource "deployments" in API group "extensions" in the namespace "eventlogger-pipeline-staging".
	at java.util.concurrent.CompletableFuture.encodeThrowable(Unknown Source) ~[?:?]
	at java.util.concurrent.CompletableFuture.completeThrowable(Unknown Source) ~[?:?]
	at java.util.concurrent.CompletableFuture$AsyncRun.run(Unknown Source) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[?:?]
	at java.lang.Thread.run(Unknown Source) ~[?:?]
However, the service account should have access to everything. There should also be sufficient resource because when the failed deployment gets rolled back, the exact same jobmanager and task manager pods get created. Interestingly, when I manually change the 
job.state
to 
suspended
and back to 
running
, the deployment completes successfully.
Hmm, interesting. I see that even a flinkdeployment that was successfully assigned all of the resources are shutting down suddenly with 
UNKNOWN
reason. pods created
Copy code
2023-02-08 02:53:46,297 INFO  org.apache.flink.kubernetes.KubernetesResourceManagerDriver  [] - Pod eventlogger-pipeline-v0-1-taskmanager-1-1 is created.
2023-02-08 02:53:46,321 INFO  org.apache.flink.kubernetes.KubernetesResourceManagerDriver  [] - Pod eventlogger-pipeline-v0-1-taskmanager-1-3 is created.
2023-02-08 02:53:46,323 INFO  org.apache.flink.kubernetes.KubernetesResourceManagerDriver  [] - Pod eventlogger-pipeline-v0-1-taskmanager-1-2 is created.
… taskmanagers registered
Copy code
2023-02-08 02:54:11,348 INFO  org.apache.flink.runtime.resourcemanager.active.ActiveResourceManager [] - Worker eventlogger-pipeline-v0-1-taskmanager-1-1 is registered.
2023-02-08 02:54:11,349 INFO  org.apache.flink.runtime.resourcemanager.active.ActiveResourceManager [] - Worker eventlogger-pipeline-v0-1-taskmanager-1-1 with resource spec WorkerResourceSpec {cpuCores=6.0, taskHeapSize=537.600mb (563714445 bytes), taskOffHeapSize=0 bytes, networkMemSize=158.720mb (166429984 bytes), managedMemSize=634.880mb (665719939 bytes), numSlots=8} was requested in current attempt. Current pending count after registering: 2.
2023-02-08 02:54:11,351 INFO  org.apache.flink.runtime.resourcemanager.active.ActiveResourceManager [] - Worker eventlogger-pipeline-v0-1-taskmanager-1-3 is registered.
2023-02-08 02:54:11,351 INFO  org.apache.flink.runtime.resourcemanager.active.ActiveResourceManager [] - Worker eventlogger-pipeline-v0-1-taskmanager-1-3 with resource spec WorkerResourceSpec {cpuCores=6.0, taskHeapSize=537.600mb (563714445 bytes), taskOffHeapSize=0 bytes, networkMemSize=158.720mb (166429984 bytes), managedMemSize=634.880mb (665719939 bytes), numSlots=8} was requested in current attempt. Current pending count after registering: 1.
2023-02-08 02:54:11,352 INFO  org.apache.flink.runtime.resourcemanager.active.ActiveResourceManager [] - Worker eventlogger-pipeline-v0-1-taskmanager-1-2 is registered.
2023-02-08 02:54:11,352 INFO  org.apache.flink.runtime.resourcemanager.active.ActiveResourceManager [] - Worker eventlogger-pipeline-v0-1-taskmanager-1-2 with resource spec WorkerResourceSpec {cpuCores=6.0, taskHeapSize=537.600mb (563714445 bytes), taskOffHeapSize=0 bytes, networkMemSize=158.720mb (166429984 bytes), managedMemSize=634.880mb (665719939 bytes), numSlots=8} was requested in current attempt. Current pending count after registering: 0.
… worker shutting down
Copy code
2023-02-08 02:54:18,060 INFO  org.apache.flink.runtime.resourcemanager.active.ActiveResourceManager [] - Stopping worker eventlogger-pipeline-v0-1-taskmanager-1-3.
2023-02-08 02:54:18,060 INFO  org.apache.flink.kubernetes.KubernetesResourceManagerDriver  [] - Stopping TaskManager pod eventlogger-pipeline-v0-1-taskmanager-1-3.
… good bye…
Copy code
2023-02-08 02:54:18,067 INFO  org.apache.flink.runtime.entrypoint.ClusterEntrypoint        [] - RECEIVED SIGNAL 15: SIGTERM. Shutting down as requested.
2023-02-08 02:54:18,072 INFO  org.apache.flink.runtime.entrypoint.ClusterEntrypoint        [] - Shutting KubernetesApplicationClusterEntrypoint down with application status UNKNOWN. Diagnostics Cluster entrypoint has been closed externally..
2023-02-08 02:54:18,073 INFO  org.apache.flink.runtime.blob.BlobServer                     [] - Stopped BLOB server at 0.0.0.0:6124
2023-02-08 02:54:19,114 INFO  akka.remote.RemoteActorRefProvider$RemotingTerminator        [] - Remote daemon shut down; proceeding with flushing remote transports.
g
this is access issue, connect with your infra team, it is related to service account
k
@Gaurav Miglani I don’t think it’s related only to the permissions of the service account. The service account 
flink
has full access. As stated in my comments, the deployment succeeds randomly, only failing one of the two flinkdeployments. And thus, I suspect this isn’t related to the service account’s access.
g
then maybe its ec2 issue, 1 node is working, and other node is working
k
@Gaurav Miglani It could be, but I wonder what about EC2 has gone wrong. I have done additional troubleshooting. Some job manager is shut down even after some successful checkpointing completion, and gets rolled back to a previous spec.
Copy code
023-02-08 03:26:58,987 INFO  org.apache.flink.runtime.checkpoint.CheckpointCoordinator    [] - Triggering checkpoint 298939 (type=CheckpointType{name='Checkpoint', sharingFilesStrategy=FORWARD_BACKWARD}) @ 1675826818972 for job 00000000000000000000000000000000.
2023-02-08 03:26:59,333 INFO  org.apache.flink.fs.s3.common.writer.S3Committer             [] - Committing checkpoints/00000000000000000000000000000000/chk-298939/_metadata with MPU ID 0QjfkTVOV_knr4uMBrbZp2Kh6BFJVqlU.QhrORLj5fkVHAzdVmWZW6zyX3kCzy9O1kqwWh9BPDh2aRhE52AdaQKJ1b2WMA1TzctR.LUufSoOf5mEhRUYMVnF0p0bUw4yuKtO.EpMx330FjPY9SUsug9hbku7DOKUUw4.RLwXOfI-
2023-02-08 03:26:59,806 INFO  org.apache.flink.runtime.checkpoint.CheckpointCoordinator    [] - Completed checkpoint 298939 for job 00000000000000000000000000000000 (46580 bytes, checkpointDuration=499 ms, finalizationTime=335 ms).
2023-02-08 03:27:08,986 INFO  org.apache.flink.runtime.checkpoint.CheckpointCoordinator    [] - Triggering checkpoint 298940 (type=CheckpointType{name='Checkpoint', sharingFilesStrategy=FORWARD_BACKWARD}) @ 1675826828972 for job 00000000000000000000000000000000.
2023-02-08 03:27:09,294 INFO  org.apache.flink.fs.s3.common.writer.S3Committer             [] - Committing checkpoints/00000000000000000000000000000000/chk-298940/_metadata with MPU ID 6oKjUz84hn3..WFk0a09Aqm.ei0mwrhM2.KwCnokjTf6V86SPrhxPRhkSzWCGHIuPU6eb57s3yeva1BBjKttYdsBAgjSpxKK_tTAkgRL9BLexSxBkCHHX10IkNevarxAvdf6o8PRSHHnWa05_8scMGbxmObfJgUAczCK0yIhYOQ-
2023-02-08 03:27:09,765 INFO  org.apache.flink.runtime.checkpoint.CheckpointCoordinator    [] - Completed checkpoint 298940 for job 00000000000000000000000000000000 (46580 bytes, checkpointDuration=472 ms, finalizationTime=321 ms).
2023-02-08 03:27:16,601 INFO  org.apache.flink.runtime.entrypoint.ClusterEntrypoint        [] - RECEIVED SIGNAL 15: SIGTERM. Shutting down as requested.
2023-02-08 03:27:16,605 INFO  org.apache.flink.runtime.entrypoint.ClusterEntrypoint        [] - Shutting KubernetesApplicationClusterEntrypoint down with application status UNKNOWN. Diagnostics Cluster entrypoint has been closed externally..
2023-02-08 03:27:16,606 INFO  org.apache.flink.runtime.blob.BlobServer                     [] - Stopped BLOB server at 0.0.0.0:6124
2023-02-08 03:27:16,820 INFO  akka.remote.RemoteActorRefProvider$RemotingTerminator        [] - Shutting down remote daemon.
2023-02-08 03:27:16,820 INFO  akka.remote.RemoteActorRefProvider$RemotingTerminator        [] - Shutting down remote daemon.
2023-02-08 03:27:16,821 INFO  akka.remote.RemoteActorRefProvider$RemotingTerminator        [] - Remote daemon shut down; proceeding with flushing remote transports.
2023-02-08 03:27:16,821 INFO  akka.remote.RemoteActorRefProvider$RemotingTerminator        [] - Remote daemon shut down; proceeding with flushing remote transports.
2023-02-08 03:27:16,832 INFO  akka.remote.RemoteActorRefProvider$RemotingTerminator        [] - Remoting shut down.
2023-02-08 03:27:16,832 INFO  akka.remote.RemoteActorRefProvider$RemotingTerminator        [] - Remoting shut down.
@Gyula Fóra Is there a possibility that this is a bug in 
flink-operator
?
g
Anything that happens with the Flink jobs after the operator submitted them is unlikely to be related to the operator
Unless you see in the operator logs that the operator is restarting / shutting down the job
In this case if the shutdown due to rollback then it can possibly be caused by the operator yes
The stability conditions in the rollback logic would really need some improvements :) currently it only looks at running state. I wonder why it did not think your job was “running”
k
Right. From the flink-operator’s log, I see a rollback is triggered by 
AbstractFlinkResourceReconciler
Copy code
2023-02-08 06:08:18,495 o.a.f.k.o.o.d.ApplicationObserver [INFO ][eventlogger-pipeline-staging/gantry-eventlogger-pipeline-v0-1] JobManager deployment is ready
2023-02-08 06:08:18,495 o.a.f.k.o.o.JobStatusObserver  [INFO ][eventlogger-pipeline-staging/gantry-eventlogger-pipeline-v0-1] Observing job status
2023-02-08 06:08:18,541 o.a.f.k.o.o.JobStatusObserver  [INFO ][eventlogger-pipeline-staging/gantry-eventlogger-pipeline-v0-1] Job status changed from RECONCILING to CREATED
2023-02-08 06:08:18,580 o.a.f.k.o.r.d.AbstractFlinkResourceReconciler [INFO ][eventlogger-pipeline-staging/gantry-eventlogger-pipeline-v0-1] Resource fully reconciled, nothing to do...
2023-02-08 06:08:18,580 o.a.f.k.o.c.FlinkDeploymentController [INFO ][eventlogger-pipeline-staging/gantry-eventlogger-pipeline-v0-1] End of reconciliation
2023-02-08 06:08:26,433 o.a.f.k.o.c.FlinkDeploymentController [INFO ][eventlogger-pipeline-staging/gantry-eventlogger-pipeline-v0] Starting reconciliation
2023-02-08 06:08:26,434 o.a.f.k.o.o.JobStatusObserver  [INFO ][eventlogger-pipeline-staging/gantry-eventlogger-pipeline-v0] Observing job status
2023-02-08 06:08:26,441 o.a.f.k.o.o.JobStatusObserver  [INFO ][eventlogger-pipeline-staging/gantry-eventlogger-pipeline-v0] Job status (CREATED) unchanged
2023-02-08 06:08:26,453 o.a.f.k.o.r.d.AbstractFlinkResourceReconciler [WARN ][eventlogger-pipeline-staging/gantry-eventlogger-pipeline-v0] Preparing to roll back to last stable spec.
2023-02-08 06:08:26,453 o.a.f.k.o.c.FlinkDeploymentController [INFO ][eventlogger-pipeline-staging/gantry-eventlogger-pipeline-v0] End of reconciliation
2023-02-08 06:08:26,467 o.a.f.k.o.c.FlinkDeploymentController [INFO ][eventlogger-pipeline-staging/gantry-eventlogger-pipeline-v0] Starting reconciliation
2023-02-08 06:08:26,467 o.a.f.k.o.r.d.AbstractFlinkResourceReconciler [WARN ][eventlogger-pipeline-staging/gantry-eventlogger-pipeline-v0] Rolling back failed deployment.
2023-02-08 06:08:26,520 o.a.f.k.o.u.FlinkUtils         [INFO ][eventlogger-pipeline-staging/gantry-eventlogger-pipeline-v0] Deleting JobManager deployment while preserving HA metadata.
And, this is after the task manager pod was created. I wonder what conditions are checking whether to mark a deployment is successful or not. Is there an interval that I can configure so the flink operator waits longer before deciding to mark as a failed deployment?
g
Yes that is very important let me get the config
🙌 1
kubernetes.operator.deployment.readiness.timeout
🙌 1
The default 1m may be very small on real environments
k
yeah 1 minute is very small.
let me try updating this to a higher value, and see if this still occurs. Otherwise, I am out of ideas lol.
g
If this solves this for you can you please open a small PR to amend the default to 5m maybe? :)
✅ 1
k
That will be great!! A sweet first PR and more contributions 😆
😄 1
I have confirmed that increasing 
kubernetes.operator.deployment.readiness.timeout
to a higher value did resolve the issue.
🎉 1
Updated the default value for 
kubernetes.operator.deployment.readiness.timeout
to 5 minutes. @Gyula Fóra https://github.com/apache/flink-kubernetes-operator/pull/528
🙌 1
2 Views
Open in Slack
PreviousNext
Powered by