CenturyLinkCloud / clc-java-sdk

Apache License 2.0
6 stars 4 forks source link

Server not found after server create #202

Closed steventarver closed 8 years ago

steventarver commented 8 years ago

When creating a server, a database entry for the server is not made until the blueprint is started (brannon). There is no timing guarantee between the server create completion and the blueprint start (hades). The first line of ServerService.postProcessBuildServerResponse()

        ServerMetadata serverInfo = client.findServerByUuid(response.findServerUuid());

throws an exception when the create server api call completes before the blueprint is started. This has worked pretty well for a long time. Last week, something changed that increased the failure frequency; it is happening for us almost every time in VA1. Hades recommends that we poll blueprint status until the blueprint is complete. I see you are doing that in the waitUntilComplete() loop, but the above call happens before entering waitUntilComplete.

Including verbose details in case it helps you locate the fix. We are using the ServerService like this:

    ServerMetadata createdServer = serverService.create(new CreateServerConfig()
                    .name("mysql")
                    .group(group)
                    .template(Template.refByName().dataCenter(dataCenter).name("UBUNTU-14-64-TEMPLATE"))
                    .password(RandomStringUtils.randomAlphabetic(6).toUpperCase() + RandomStringUtils.randomAlphabetic(6).toLowerCase() + RandomStringUtils.randomNumeric(5))
                    .type(ServerType.valueOf(newServer.getServerType().toUpperCase()))
                    .storageType(StorageType.valueOf(newServer.getServerType().toUpperCase()))
                    .machine(new Machine()
                                    .cpuCount(1)
                                    .ram(1)
                                    .disk(new DiskConfig().path("/data").size(1).type(DiskType.PARTITIONED))
                                    .disk(new DiskConfig().path("/backups").size(1).type(DiskType.PARTITIONED))
                    ).network(new NetworkConfig().network(new IdNetworkRef(dataCenter, network.getId())))
    ).waitUntilComplete().getResult();

Which produces this stack trace

org.springframework.amqp.rabbit.listener.exception.ListenerExecutionFailedException: Listener method 'public void io.ctl.dbaas.automation.listener.CreateServerListener.createNewServers(org.springframework.messaging.Message<io.ctl.dbaas.automation.message.ConfigureMysqlMessage>)' threw exception
    org.springframework.amqp.rabbit.listener.adapter.MessagingMessageListenerAdapter.invokeHandler(MessagingMessageListenerAdapter.java:126) ~[spring-rabbit-1.4.5.RELEASE.jar:?]
    org.springframework.amqp.rabbit.listener.adapter.MessagingMessageListenerAdapter.onMessage(MessagingMessageListenerAdapter.java:93) ~[spring-rabbit-1.4.5.RELEASE.jar:?]
    org.springframework.amqp.rabbit.listener.AbstractMessageListenerContainer.doInvokeListener(AbstractMessageListenerContainer.java:756) ~[spring-rabbit-1.4.5.RELEASE.jar:?]
    org.springframework.amqp.rabbit.listener.AbstractMessageListenerContainer.invokeListener(AbstractMessageListenerContainer.java:679) ~[spring-rabbit-1.4.5.RELEASE.jar:?]
    org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.access$001(SimpleMessageListenerContainer.java:83) ~[spring-rabbit-1.4.5.RELEASE.jar:?]
    org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer$1.invokeListener(SimpleMessageListenerContainer.java:170) ~[spring-rabbit-1.4.5.RELEASE.jar:?]
    sun.reflect.GeneratedMethodAccessor2138.invoke(Unknown Source) ~[?:?]
    sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_74]
    java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_74]
    org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:302) ~[spring-aop-4.2.0.RELEASE.jar:?]
    org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190) ~[spring-aop-4.2.0.RELEASE.jar:?]
    org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.2.0.RELEASE.jar:?]
    org.springframework.retry.interceptor.RetryOperationsInterceptor$1.doWithRetry(RetryOperationsInterceptor.java:74) ~[spring-retry-1.1.2.RELEASE.jar:?]
    org.springframework.retry.support.RetryTemplate.doExecute(RetryTemplate.java:263) [spring-retry-1.1.2.RELEASE.jar:?]
    org.springframework.retry.support.RetryTemplate.execute(RetryTemplate.java:168) [spring-retry-1.1.2.RELEASE.jar:?]
    org.springframework.retry.interceptor.RetryOperationsInterceptor.invoke(RetryOperationsInterceptor.java:98) [spring-retry-1.1.2.RELEASE.jar:?]
    org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) [spring-aop-4.2.0.RELEASE.jar:?]
    org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207) [spring-aop-4.2.0.RELEASE.jar:?]
    com.sun.proxy.$Proxy638.invokeListener(Unknown Source) [?:?]
    org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.invokeListener(SimpleMessageListenerContainer.java:1257) [spring-rabbit-1.4.5.RELEASE.jar:?]
    org.springframework.amqp.rabbit.listener.AbstractMessageListenerContainer.executeListener(AbstractMessageListenerContainer.java:660) [spring-rabbit-1.4.5.RELEASE.jar:?]
    org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.doReceiveAndExecute(SimpleMessageListenerContainer.java:1021) [spring-rabbit-1.4.5.RELEASE.jar:?]
    org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.receiveAndExecute(SimpleMessageListenerContainer.java:1005) [spring-rabbit-1.4.5.RELEASE.jar:?]
    org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.access$700(SimpleMessageListenerContainer.java:83) [spring-rabbit-1.4.5.RELEASE.jar:?]
    org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer$AsyncMessageProcessingConsumer.run(SimpleMessageListenerContainer.java:1119) [spring-rabbit-1.4.5.RELEASE.jar:?]
    java.lang.Thread.run(Thread.java:745) [?:1.8.0_74]
Caused by: com.centurylink.cloud.sdk.core.client.errors.ClcHttpClientException: HTTP 404 Not Found

    com.centurylink.cloud.sdk.core.client.errors.ErrorProcessingFilter.filter(ErrorProcessingFilter.java:35) ~[clc-java-sdk-1.2.0.jar:?]
    org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.invoke(ClientInvocation.java:418) ~[resteasy-client-3.0.11.Final.jar:?]
    org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.invoke(ClientInvocation.java:442) ~[resteasy-client-3.0.11.Final.jar:?]
    org.jboss.resteasy.client.jaxrs.internal.ClientInvocationBuilder.get(ClientInvocationBuilder.java:165) ~[resteasy-client-3.0.11.Final.jar:?]
    com.centurylink.cloud.sdk.server.services.client.ServerClient.findServerByUuid(ServerClient.java:99) ~[clc-java-sdk-1.2.0.jar:?]
    com.centurylink.cloud.sdk.server.services.dsl.ServerService.postProcessBuildServerResponse(ServerService.java:169) ~[clc-java-sdk-1.2.0.jar:?]
    com.centurylink.cloud.sdk.server.services.dsl.ServerService.create(ServerService.java:122) ~[clc-java-sdk-1.2.0.jar:?]
    io.ctl.dbaas.automation.listener.CreateServerListener.lambda$createNewServers$42(CreateServerListener.java:68) ~[CreateServerListener.class:?]
    java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184) ~[?:1.8.0_74]
    java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1374) ~[?:1.8.0_74]
    java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481) ~[?:1.8.0_74]
    java.util.stream.ForEachOps$ForEachTask.compute(ForEachOps.java:291) ~[?:1.8.0_74]
    java.util.concurrent.CountedCompleter.exec(CountedCompleter.java:731) ~[?:1.8.0_74]
    java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289) ~[?:1.8.0_74]
    java.util.concurrent.ForkJoinTask.doInvoke(ForkJoinTask.java:401) ~[?:1.8.0_74]
    java.util.concurrent.ForkJoinTask.invoke(ForkJoinTask.java:734) ~[?:1.8.0_74]
    java.util.stream.ForEachOps$ForEachOp.evaluateParallel(ForEachOps.java:160) ~[?:1.8.0_74]
    java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateParallel(ForEachOps.java:174) ~[?:1.8.0_74]
    java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:233) ~[?:1.8.0_74]
    java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:418) ~[?:1.8.0_74]
    java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:583) ~[?:1.8.0_74]
    io.ctl.dbaas.automation.listener.CreateServerListener.createNewServers(CreateServerListener.java:62) ~[CreateServerListener.class:?]
    io.ctl.dbaas.automation.listener.CreateServerListener$$FastClassBySpringCGLIB$$d541606a.invoke(<generated>) ~[spring-core-4.2.0.RELEASE.jar:?]
    org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204) ~[spring-core-4.2.0.RELEASE.jar:?]
    org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:717) ~[spring-aop-4.2.0.RELEASE.jar:?]
    org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.2.0.RELEASE.jar:?]
    org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:97) ~[spring-aop-4.2.0.RELEASE.jar:?]
    io.ctl.dbaas.common.aop.LoggingInterceptor.doLogging(LoggingInterceptor.java:51) ~[common-1.22.jar:?]
    sun.reflect.GeneratedMethodAccessor1770.invoke(Unknown Source) ~[?:?]
    sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_74]
    java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_74]
    org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621) ~[spring-aop-4.2.0.RELEASE.jar:?]
    org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610) ~[spring-aop-4.2.0.RELEASE.jar:?]
    org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:68) ~[spring-aop-4.2.0.RELEASE.jar:?]
    org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.2.0.RELEASE.jar:?]
    org.springframework.aop.aspectj.AspectJAfterThrowingAdvice.invoke(AspectJAfterThrowingAdvice.java:58) ~[spring-aop-4.2.0.RELEASE.jar:?]
    org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.2.0.RELEASE.jar:?]
    org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:52) ~[spring-aop-4.2.0.RELEASE.jar:?]
    org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:168) ~[spring-aop-4.2.0.RELEASE.jar:?]
    org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92) ~[spring-aop-4.2.0.RELEASE.jar:?]
    org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.2.0.RELEASE.jar:?]
    org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:653) ~[spring-aop-4.2.0.RELEASE.jar:?]
    io.ctl.dbaas.automation.listener.CreateServerListener$$EnhancerBySpringCGLIB$$97c221ee.createNewServers(<generated>) ~[spring-core-4.2.0.RELEASE.jar:?]
    sun.reflect.GeneratedMethodAccessor2404.invoke(Unknown Source) ~[?:?]
    sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_74]
    java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_74]
    org.springframework.messaging.handler.invocation.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:185) ~[spring-messaging-4.1.6.RELEASE.jar:?]
    org.springframework.messaging.handler.invocation.InvocableHandlerMethod.invoke(InvocableHandlerMethod.java:104) ~[spring-messaging-4.1.6.RELEASE.jar:?]
    org.springframework.amqp.rabbit.listener.adapter.MessagingMessageListenerAdapter.invokeHandler(MessagingMessageListenerAdapter.java:113) ~[spring-rabbit-1.4.5.RELEASE.jar:?]
scottdensmore commented 8 years ago

The problem is the ServerService postProcessBuildServerResponse line 168. When you get the response back from CreateServer, the self link is not valid until the blueprint completes. Since you try and add the public ip at the same time (which I would recommend we not do), you try and get the server info that doesn't exist. At some point we broke the self link.

push1st1k commented 8 years ago

@steventarver As you mentioned, this issue appeared in VA1, but for example in DE1 it works well. The possible solution will be to wait until ServerMetadata serverInfo = client.findServerByUuid(response.findServerUuid()); will return a valid response with server metadata. But in this case some server operations (create, clone, import) won't be completely asynchronous, because the SDK should wait some time to retrieve the server metadata. For example, if you would like to create a server and don't wait the result, now you have to wait until the API will return a server metadata. But if you are planning to operate with this server later and call .waitUntilComplete(), it will work the same way as before.

@scottdensmore Maybe you have an idea, why it worked well before and even now in other DCs (DE1)? Something was changed in API? It would be great, if the method findServerByUuid responded with server ID immediately and the method create returns this information. Actually, the public IP is added only after the server returns status 'active', not at the same time. I'm going to fix it with adding a logic, that will send requests to the endpoint until it will return server metadata, so it won't be failing. But the delay of getting a server by UUID should be fixed at server side.

PR #203 was created.

steventarver commented 8 years ago

Would deferring the ServerMetadata fetch until it is needed be a better solution? That allows retaining a fast, async api, but looks like more refactoring.

We are using this method (create) synchronously, so either solution works for us. And your fast fix is a blessing; saves us some manual maintenance because most creates() are failing.

steventarver commented 8 years ago

@push1st1k Clarifyiing my previous comment: If the blueprint queue is full, the number of requests exceeds the number of executors, you could be waiting minutes for the server meta data to be created.

It seems, that to cover all cases, one would have to wait to fetch and use ServerMetaData until the blueprint completes successfully.

steventarver commented 8 years ago

@push1st1k When will you be cutting a release with this fix? I need to schedule a release - this fixes production issues for us.

push1st1k commented 8 years ago

This process isn't so fast, but I'll do my best to release as soon as I can.

push1st1k commented 8 years ago

The SDK v1.2.4 was successfully released.