PluginNotReadyException

#1

Dear all,

am new to Entando and trying with
1.https://dev.entando.org/v6.3/tutorials/backend-developers/generate-microservices-and-micro-frontends.html#overview

followed by

https://dev.entando.org/v6.3/tutorials/ecr/publish-project-bundle.html#build-docker-image-for-microservices

while installing at the App Builder, its giving following error. Unable to understand why and how to fix it.

: Installable ‘jeffpower-test-project’ has errors: org.entando.kubernetes.exception.k8ssvc.PluginNotReadyException: Plugin jeffpower-test-project not ready after predefined timeout

java.util.concurrent.CompletionException: org.entando.kubernetes.exception.k8ssvc.PluginNotReadyException: Plugin jeffpower-test-project not ready after predefined timeout
at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:314) ~[na:na]
at java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:319) ~[na:na]
at java.base/java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1739) ~[na:na]
at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]
Caused by: org.entando.kubernetes.exception.k8ssvc.PluginNotReadyException: Plugin jeffpower-test-project not ready after predefined timeout
at org.entando.kubernetes.service.KubernetesService.linkPluginAndWaitForSuccess(KubernetesService.java:101) ~[classes!/:6.2.39]
at org.entando.kubernetes.model.bundle.installable.PluginInstallable.lambda$install$0(PluginInstallable.java:37) ~[classes!/:6.2.39]
at java.base/java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1736) ~[na:na]
… 1 common frames omitted

2021-02-20 08:53:52.620 ERROR 1 — [ Thread-8] o.e.k.s.d.j.EntandoBundleInstallService : An error occurred during component installation

org.entando.kubernetes.exception.EntandoComponentManagerException: testproject-bundle install can’t proceed due to an error with one of the components
at org.entando.kubernetes.service.digitalexchange.job.EntandoBundleInstallService.lambda$submitInstallAsync$5(EntandoBundleInstallService.java:198) ~[classes!/:6.2.39]
at java.base/java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1736) ~[na:na]
at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]

2021-02-20 08:53:52.620 WARN 1 — [ Thread-8] o.e.k.s.d.j.EntandoBundleInstallService : Rolling installation of bundle testproject-bundle@v0.0.1
2021-02-20 08:53:52.625 INFO 1 — [ Thread-10] o.e.k.m.b.installable.PluginInstallable : Removing link to plugin jeffpower-test-project
2021-02-20 08:53:52.969 INFO 1 — [ Thread-8] o.e.k.s.d.j.EntandoBundleInstallService : Rollback operation completed successful

#2

Hey, @jeffpowers.

Welcome to Entando! Ideally it would go more smoothly but we can help figure it out.

A few thoughts for you. Those look like the quickstart-server de-container logs which is exactly the place to start checking for errors. In this case it looks like your plugin didn’t come up healthy in time so you’d want to look at your plugin logs next. You should have a pod named after your plugin and you can check the logs in the server-container to see what happened when your plugin started up. Occasionally we’ve seen hypervisor issues if there are resource constraints so you could also check your hypervisor for errors. The quickstart defaults to 5GB RAM which is plenty for an initial bundle and plugin but if you ran a few you would need to give it more resources.

If your test bundle git repo and docker image are public and you’re willing to share, one of us could also give it a try and see if we can reproduce the issue.

Hope that helps,
Nathan

#3

Many thanks Nathan.

Please find the git repo ->https://github.com/josephgeorgek/mfetest and docker image - https://hub.docker.com/r/josephgeorgek/test-project

also kindly advice on the plug logs… am not able locate the plugin pod
get pods --namespace entando
NAME READY STATUS RESTARTS AGE
quickstart-kc-deployer-kkvkpgzj2c 0/1 Completed 0 3d13h
quickstart-eci-deployer-fmgeb4u3yh 0/1 Completed 0 3d13h
quickstart-deployer-lb1ae70sur 0/1 Completed 0 3d13h
std-demo-customer-server-db-job-138a 0/1 Completed 0 3d13h
std-demo-customer-deployer-jx65etnqod 0/1 Completed 0 3d13h
std-demo-customer-apl-deployer-duqvxrgfvv 0/1 Completed 0 3d13h
standard-demo-banking-server-db-job-85c4 0/1 Completed 0 3d13h
standard-demo-banking-deployer-v60kvdjyo9 0/1 Completed 0 3d13h
standard-demo-banking-apl-deployer-wk7vrftjp5 0/1 Completed 0 3d13h
quickstart-composite-app-deployer-czamfqrcdg 0/1 Completed 0 3d13h
standard-demo-banking-server-deployment-6cd4d9956c-fzqvk 2/2 Running 4 3d13h
std-demo-customer-server-deployment-cfc79948f-w5mlf 2/2 Running 4 3d13h
quickstart-kc-server-deployment-6cc78db4d5-dn9p7 1/1 Running 1 3d13h
quickstart-operator-74595789c8-r8vjb 1/1 Running 1 3d13h
quickstart-eci-k8s-svc-deployment-57c84c69dd-ct9dd 1/1 Running 4 3d13h
quickstart-server-deployment-565884448-vr252 3/3 Running 5 3d13h

#4

Hi, @jeffpowers.

Well, it’s not an obvious problem with your bundle. I was able to install it successfully into one of my quickstart environments. The de-container logs finish with this and it took about 3 minutes to warm up:

2021-02-22 14:07:47.857 INFO 1 --- [ Thread-27] o.e.k.m.bundle.installable.Installable : Creating widget conference-form-widget
2021-02-22 14:07:48.014 INFO 1 --- [ Thread-2] o.e.k.s.d.j.EntandoBundleInstallService : Component josephgeorge registered as installed in the system
2021-02-22 14:07:48.014 INFO 1 --- [ Thread-2] o.e.k.s.d.j.EntandoBundleInstallService : Bundle installed correctly

The pods use the following naming, by default, DOCKER NAME/ORGANIZATION + PROJECT NAME + pod type, etc. so in my cluster I see these pods listed, where the first two are run to completion jobs.

josephgeorgek-test-project-server-db-job-5e24
josephgeorgek-test-project-deployer-dkh2vhdl4r
josephgeorgek-test-project-db-deployment-5ddf9b6db4-gl6hv 
josephgeorgek-test-project-server-deployment-564b84ccbf-v6mxk

I don’t see any evidence of those plugins in your list so something failed pretty early in the process. Another place you can look is in the logs for quickstart-eci-k8s-svc-deployment and see if there’s anything informative there. If you’d like to attach the full logs for that as well as the de-container, we can take a look. Or reach out on our slack and we could do this a bit more interactively. :slight_smile:

One more idea, at first I thought you were running a plain quickstart env but it looks like you installed the Standard Demo per https://dev.entando.org/v6.3/tutorials/samples/install-standard-demo.html? Our instructions include giving that VM 8GB RAM so that should be enough to add another plugin like you’re doing but one possibility is that you have hit resource constraints. You might want to glance at the hypervisor event logs to see if there are any errors. If you hit the ceiling, it’s difficult to tell from within the VM/Kubernetes itself, which is typical for virtualized servers.

Hope this helps,
Nathan

#5

Thanks again Nathan. Much appreciated

Saw a warning…no permissions to create CRD’s. from deployment/quickstart-eci-k8s-svc-deployment logs … am running with sudo i.e. sudo kubectl apply -f example-bundle.yaml -n entando

.EntandoCustomResourceResolver : User does not have permissions to create CRD’s. Assuming CRD’s have already been deployed. Loading entandodebundles.entando.org CRD from classpath.

#6

full log:
2021-02-22 22:15:42.166 INFO 1 — [ main] o.s.s.web.DefaultSecurityFilterChain : Creating filter chain: any request, [org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter@432038ec, org.springframework.security.web.context.SecurityContextPersistenceFilter@3f67593e, org.springframework.security.web.header.HeaderWriterFilter@5454d35e, org.springframework.security.web.authentication.logout.LogoutFilter@8e50104, org.springframework.security.oauth2.client.web.OAuth2AuthorizationRequestRedirectFilter@51549490, org.springframework.security.oauth2.server.resource.web.BearerTokenAuthenticationFilter@50de186c, org.springframework.security.web.savedrequest.RequestCacheAwareFilter@41ab013, org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter@82ea68c, org.springframework.security.web.authentication.AnonymousAuthenticationFilter@7daa0fbd, org.springframework.security.oauth2.client.web.OAuth2AuthorizationCodeGrantFilter@73d983ea, org.springframework.security.web.session.SessionManagementFilter@455b6df1, org.springframework.security.web.access.ExceptionTranslationFilter@71329995, org.springframework.security.web.access.intercept.FilterSecurityInterceptor@7393222f]
2021-02-22 22:15:42.191 INFO 1 — [ main] o.s.s.web.DefaultSecurityFilterChain : Creating filter chain: any request, [org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter@36cda2c2, org.springframework.security.web.context.SecurityContextPersistenceFilter@16eccb2e, org.springframework.security.web.header.HeaderWriterFilter@17d88132, org.springframework.security.web.csrf.CsrfFilter@6f44a157, org.springframework.security.web.authentication.logout.LogoutFilter@4671115f, org.springframework.security.web.savedrequest.RequestCacheAwareFilter@5ef5c734, org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter@d771cc9, org.springframework.security.web.authentication.AnonymousAuthenticationFilter@3697186, org.springframework.security.web.session.SessionManagementFilter@5ddcc487, org.springframework.security.web.access.ExceptionTranslationFilter@291f18]
2021-02-22 22:15:43.087 INFO 1 — [ main] o.s.s.concurrent.ThreadPoolTaskExecutor : Initializing ExecutorService ‘applicationTaskExecutor’
2021-02-22 22:15:45.792 INFO 1 — [ main] o.s.b.a.e.web.EndpointLinksResolver : Exposing 2 endpoint(s) beneath base path ‘/actuator’
2021-02-22 22:15:45.913 INFO 1 — [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8084 (http) with context path ‘/k8s’
2021-02-22 22:15:45.917 INFO 1 — [ main] o.e.k.EntandoKubernetesJavaApplication : Started EntandoKubernetesJavaApplication in 12.104 seconds (JVM running for 13.096)
2021-02-22 22:16:07.732 INFO 1 — [nio-8084-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/k8s] : Initializing Spring DispatcherServlet ‘dispatcherServlet’
2021-02-22 22:16:07.733 INFO 1 — [nio-8084-exec-1] o.s.web.servlet.DispatcherServlet : Initializing Servlet ‘dispatcherServlet’
2021-02-22 22:16:07.747 INFO 1 — [nio-8084-exec-1] o.s.web.servlet.DispatcherServlet : Completed initialization in 14 ms
2021-02-22 22:24:25.092 INFO 1 — [nio-8084-exec-9] o.e.k.c.EntandoDeBundleController : Listing available digital-exchange bundles
2021-02-22 22:24:25.092 INFO 1 — [nio-8084-exec-8] o.e.k.c.EntandoDeBundleController : Listing available digital-exchange bundles
2021-02-22 22:24:25.576 WARN 1 — [ Thread-4] o.e.k.m.EntandoCustomResourceResolver : User does not have permissions to create CRD’s. Assuming CRD’s have already been deployed. Loading entandodebundles.entando .org CRD from classpath.
2021-02-22 22:24:35.830 INFO 1 — [nio-8084-exec-4] o.e.k.c.EntandoDeBundleController : Listing available digital-exchange bundles
2021-02-22 22:24:35.921 INFO 1 — [nio-8084-exec-5] o.e.k.c.EntandoDeBundleController : Getting entando-de-bundle with name mfetest2 in observed namespaces
2021-02-22 22:24:41.705 INFO 1 — [nio-8084-exec-8] o.e.k.controller.EntandoAppController : Listing apps from all observed namespaces
2021-02-22 22:24:41.720 WARN 1 — [ Thread-7] o.e.k.m.EntandoCustomResourceResolver : User does not have permissions to create CRD’s. Assuming CRD’s have already been deployed. Loading entandoapps.entando. org CRD from classpath.
2021-02-22 22:24:42.150 INFO 1 — [nio-8084-exec-9] o.e.k.service.EntandoPluginService : Deploying (createOrReplace) plugin josephgeorgek-mfetest-2 in namespace entando
2021-02-22 22:24:42.164 WARN 1 — [nio-8084-exec-9] o.e.k.m.EntandoCustomResourceResolver : User does not have permissions to create CRD’s. Assuming CRD’s have already been deployed. Loading entandoplugins.entando.org CRD from classpath.
2021-02-22 22:24:42.296 INFO 1 — [nio-8084-exec-9] o.e.k.service.EntandoLinkService : Link creation between EntandoApp quickstart on namespace entando and EntandoPlugin josephgeorgek-mfetest-2 on namespace entando
2021-02-22 22:24:42.302 WARN 1 — [nio-8084-exec-9] o.e.k.m.EntandoCustomResourceResolver : User does not have permissions to create CRD’s. Assuming CRD’s have already been deployed. Loading entandoapppluginlinks.entando.org CRD from classpath.
2021-02-22 22:29:46.351 INFO 1 — [nio-8084-exec-9] o.e.k.controller.EntandoLinksController : Removing link associated plugin josephgeorgek-mfetest-2 as it’s deployment phase is not SUCCESSFUL
2021-02-22 22:29:46.351 INFO 1 — [nio-8084-exec-9] o.e.k.service.EntandoPluginService : Delete plugin josephgeorgek-mfetest-2 from observed namespaces
2021-02-22 22:29:46.399 INFO 1 — [nio-8084-exec-9] o.e.k.service.EntandoLinkService : Deleting link between EntandoApp quickstart on namespace entando and EntandoPlugin josephgeorgek-mfetest-2 on namespace entando

#7

Hey, @jeffpowers.

Let’s try something else. If you shell into your VM you can use the ent diag command to collect all of the diagnostics (version, config, logs, etc. ) into a tgz file. It shouldn’t be too large for your environment so if you want to send it my way I can take a look at a few things. That will probably be more efficient than going back and forth this way, with timezones and all. You can slack it to me or email n.shaw AT entando.com if you’d rather not upload it here.

Cheers,
Nathan

#8

Just to complete the story a bit here, @jeffpowers and I switched to slack to sort this out and it ended up being a resource issue at the virtualization level. The CRD permission message is actually normal so that was a bit misleading. This is a good reminder to check your hypervisor if you see unusual behavior at the VM level. This can definitely happen in a small cluster like a local quickstart env if you add to it over time. The ent diag command and checking kubectl get events can also be helpful when something like this happens.