Fail to create template from Volumes after upgrade 4.15

[levindecaro]

• Bug Report

COMPONENT NAME

Template

CLOUDSTACK VERSION

4.15

CONFIGURATION

N/A

OS / ENVIRONMENT

centos 7.8.2003

SUMMARY

Fail to create template from Volumes after upgrade 4.15, 530 errors shown in UI.

SQL insert fail with NULL data.

INSERT INTO vm_template_details (vm_template_details.template_id, vm_template_details.name, vm_template_details.value, vm_template_details.display) VALUES (267, _binary'kvm.vnc.address', null, 1)

Full Error Log

Jan 28 14:37:32 cloudstack-1 java: ERROR [c.c.a.ApiServer] (qtp1965237677-733:ctx-d817420e ctx-2ce56665) (logid:37eb575c) unhandled exception executing api command: [Ljava.lang.String;@30ebaa54
Jan 28 14:37:32 cloudstack-1 java: com.cloud.utils.exception.CloudRuntimeException: DB Exception on: com.mysql.cj.jdbc.ClientPreparedStatement: INSERT INTO vm_template_details (vm_template_details.template_id, vm_template_details.name, vm_template_details.value, vm_template_details.display) VALUES (267, _binary'kvm.vnc.address', null, 1)
Jan 28 14:37:32 cloudstack-1 java: at com.cloud.utils.db.GenericDaoBase.persist(GenericDaoBase.java:1450)
Jan 28 14:37:32 cloudstack-1 java: at org.apache.cloudstack.resourcedetail.ResourceDetailsDaoBase.saveDetails(ResourceDetailsDaoBase.java:147)
Jan 28 14:37:32 cloudstack-1 java: at jdk.internal.reflect.GeneratedMethodAccessor1232.invoke(Unknown Source)
Jan 28 14:37:32 cloudstack-1 java: at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Jan 28 14:37:32 cloudstack-1 java: at java.base/java.lang.reflect.Method.invoke(Method.java:566)
Jan 28 14:37:32 cloudstack-1 java: at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)
Jan 28 14:37:32 cloudstack-1 java: at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)
Jan 28 14:37:32 cloudstack-1 java: at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
Jan 28 14:37:32 cloudstack-1 java: at com.cloud.utils.db.TransactionContextInterceptor.invoke(TransactionContextInterceptor.java:34)
Jan 28 14:37:32 cloudstack-1 java: at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
Jan 28 14:37:32 cloudstack-1 java: at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:95)
Jan 28 14:37:32 cloudstack-1 java: at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
Jan 28 14:37:32 cloudstack-1 java: at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
Jan 28 14:37:32 cloudstack-1 java: at com.sun.proxy.$Proxy82.saveDetails(Unknown Source)
Jan 28 14:37:32 cloudstack-1 java: at com.cloud.storage.dao.VMTemplateDaoImpl.saveDetails(VMTemplateDaoImpl.java:459)
Jan 28 14:37:32 cloudstack-1 java: at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
Jan 28 14:37:32 cloudstack-1 java: at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
Jan 28 14:37:32 cloudstack-1 java: at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Jan 28 14:37:32 cloudstack-1 java: at java.base/java.lang.reflect.Method.invoke(Method.java:566)
Jan 28 14:37:32 cloudstack-1 java: at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)
Jan 28 14:37:32 cloudstack-1 java: at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)
Jan 28 14:37:32 cloudstack-1 java: at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
Jan 28 14:37:32 cloudstack-1 java: at com.cloud.utils.db.TransactionContextInterceptor.invoke(TransactionContextInterceptor.java:34)
Jan 28 14:37:32 cloudstack-1 java: at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
Jan 28 14:37:32 cloudstack-1 java: at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:95)
Jan 28 14:37:32 cloudstack-1 java: at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
Jan 28 14:37:32 cloudstack-1 java: at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
Jan 28 14:37:32 cloudstack-1 java: at com.sun.proxy.$Proxy101.saveDetails(Unknown Source)
Jan 28 14:37:32 cloudstack-1 java: at com.cloud.template.TemplateManagerImpl.createPrivateTemplateRecord(TemplateManagerImpl.java:1949)
Jan 28 14:37:32 cloudstack-1 java: at com.cloud.template.TemplateManagerImpl.createPrivateTemplateRecord(TemplateManagerImpl.java:208)
Jan 28 14:37:32 cloudstack-1 java: at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
Jan 28 14:37:32 cloudstack-1 java: at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
Jan 28 14:37:32 cloudstack-1 java: at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Jan 28 14:37:32 cloudstack-1 java: at java.base/java.lang.reflect.Method.invoke(Method.java:566)
Jan 28 14:37:32 cloudstack-1 java: at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)
Jan 28 14:37:32 cloudstack-1 java: at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)
Jan 28 14:37:32 cloudstack-1 java: at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
Jan 28 14:37:32 cloudstack-1 java: at org.apache.cloudstack.network.contrail.management.EventUtils$EventInterceptor.invoke(EventUtils.java:107)
Jan 28 14:37:32 cloudstack-1 java: at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
Jan 28 14:37:32 cloudstack-1 java: at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:51)
Jan 28 14:37:32 cloudstack-1 java: at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
Jan 28 14:37:32 cloudstack-1 java: at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:95)
Jan 28 14:37:32 cloudstack-1 java: at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
Jan 28 14:37:32 cloudstack-1 java: at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
Jan 28 14:37:32 cloudstack-1 java: at com.sun.proxy.$Proxy198.createPrivateTemplateRecord(Unknown Source)
Jan 28 14:37:32 cloudstack-1 java: at org.apache.cloudstack.api.command.user.template.CreateTemplateCmd.create(CreateTemplateCmd.java:291)
Jan 28 14:37:32 cloudstack-1 java: at com.cloud.api.dispatch.CommandCreationWorker.handle(CommandCreationWorker.java:47)
Jan 28 14:37:32 cloudstack-1 java: at com.cloud.api.dispatch.DispatchChain.dispatch(DispatchChain.java:37)
Jan 28 14:37:32 cloudstack-1 java: at com.cloud.api.ApiDispatcher.dispatchCreateCmd(ApiDispatcher.java:88)
Jan 28 14:37:32 cloudstack-1 java: at com.cloud.api.ApiServer.queueCommand(ApiServer.java:688)
Jan 28 14:37:32 cloudstack-1 java: at com.cloud.api.ApiServer.handleRequest(ApiServer.java:588)
Jan 28 14:37:32 cloudstack-1 java: at com.cloud.api.ApiServlet.processRequestInContext(ApiServlet.java:321)
Jan 28 14:37:32 cloudstack-1 java: at com.cloud.api.ApiServlet$1.run(ApiServlet.java:134)
Jan 28 14:37:32 cloudstack-1 java: at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
Jan 28 14:37:32 cloudstack-1 java: at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
Jan 28 14:37:32 cloudstack-1 java: at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
Jan 28 14:37:32 cloudstack-1 java: at com.cloud.api.ApiServlet.processRequest(ApiServlet.java:131)
Jan 28 14:37:32 cloudstack-1 java: at com.cloud.api.ApiServlet.doGet(ApiServlet.java:93)
Jan 28 14:37:32 cloudstack-1 java: at javax.servlet.http.HttpServlet.service(HttpServlet.java:645)
Jan 28 14:37:32 cloudstack-1 java: at javax.servlet.http.HttpServlet.service(HttpServlet.java:750)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1386)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:755)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:590)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1610)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1300)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1580)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1215)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:767)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.server.Server.handle(Server.java:500)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:547)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:543)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:398)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:161)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
Jan 28 14:37:32 cloudstack-1 java: at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
Jan 28 14:37:32 cloudstack-1 java: at java.base/java.lang.Thread.run(Thread.java:834)
Jan 28 14:37:32 cloudstack-1 java: Caused by: java.sql.SQLIntegrityConstraintViolationException: Column 'value' cannot be null
Jan 28 14:37:32 cloudstack-1 java: at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:117)
Jan 28 14:37:32 cloudstack-1 java: at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97)
Jan 28 14:37:32 cloudstack-1 java: at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:122)
Jan 28 14:37:32 cloudstack-1 java: ... 106 more

STEPS TO REPRODUCE

Upgrade from 4.14 to 4.15

EXPECTED RESULTS

Create template from volume successfully.

ACTUAL RESULTS

530 error, create template failed.

[weizhouapache]

Column 'value' cannot be null

[levindecaro]

Column 'value' cannot be null

yes, but it shouldn't be, the problematic VM was created since 4.14.

[DaanHoogland]

@levindecaro can you deduce what kind of value shoud have been in that field, and then fill it as workaround?
if this is indeed due to upgrade issue a default value should have been inserted for this details table.
Having said that the field value in table vm_template_details is nullable in my local db, can you check that?

[levindecaro]

the original VM has the following option preset, when i try to create a template from this VM's Volume, it tried to inject kvm.vnc.address and kvm.vnc.port into vm_template_details, however it failed to inject kvm.vnc.address with NULL, so i changed the value field to NULLABLE to workaround this problem, but not sure it is expected behaviour or due to the upgrade.

memoryOvercommitRatio
1.0
Message.ReservedCapacityFreed.Flag
true
cpuOvercommitRatio
12
rootDiskController
scsi

[DaanHoogland]

double checked and they are supposed to be not nullable. no idea why this is happening, yet.