During my initial work with NSX-v I was running various 6.0.x Builds together with vCD 5.5.2 and vCenter/ESXi 5.5 without issue. When NSX 6.1 was released I decided to clone off my base Production Environment to test a fresh deployment of 6.1.2 into a mature vCloud Director 5.5.2 instance that had vCNS running a VSM version of 5.5.3. When it came time to deploy the first Controller I received the following error from the Networking & Security section of the Web Client:
1 |
<error><details>PreparedStatementCallback; SQL [insert into key_value_store( context, name, value ) values ( ?, ?, ? )]; ERROR: value too long for type character varying(255); nested exception is org.postgresql.util.PSQLException: ERROR: value too long for type character varying(255)</details> <errorCode>100</errorCode></error> |
Looking through the NSX Manager Logs the corresponding System Log Message looked like this:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 |
2014-11-24 19:51:17.139 WST ERROR http-nio-127.0.0.1-7441-exec-5 MessageBrokerHandlerAdapter:95 - Received invalid request for endpoint path '/api/1.0/endpointsecurity/status'. 2014-11-24 19:51:17.747 WST INFO http-nio-127.0.0.1-7441-exec-7 ControllerServiceImpl:658 - about to create controller: controller-64 IP=172.17.0.200 2014-11-24 19:51:17.753 WST INFO http-nio-127.0.0.1-7441-exec-7 AuditingServiceImpl:143 - [AuditLog] UserName:'vsphere.local\administrator', ModuleName:'VdnNvpController', Operation:'CREATE', Resource:'null', Time:'Mon Nov 24 19:51:17.751 WST 2014' 2014-11-24 19:51:18.601 WST WARN http-nio-127.0.0.1-7441-exec-7 TransactionRetryAspect:76 - failure detected in method Controller com.vmware.vshield.vsm.vdn.nvpcontroller.service.impl.ControllerServiceImpl.prepareControllerDeployment(ControllerSpec, String, HashMap) , calling the method again 2014-11-24 19:51:18.602 WST ERROR http-nio-127.0.0.1-7441-exec-7 TransactionRetryAspect:82 - could not resolve concurrency failure in method Controller com.vmware.vshield.vsm.vdn.nvpcontroller.service.impl.ControllerServiceImpl.prepareControllerDeployment(ControllerSpec, String, HashMap) even after 3 retries, are you doing something crazy in code ?? org.springframework.dao.DataIntegrityViolationException: PreparedStatementCallback; SQL [insert into key_value_store( context, name, value ) values ( ?, ?, ? )]; ERROR: value too long for type character varying(255); nested exception is org.postgresql.util.PSQLException: ERROR: value too long for type character varying(255) at org.springframework.jdbc.support.SQLStateSQLExceptionTranslator.doTranslate(SQLStateSQLExceptionTranslator.java:101) at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:72) at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:80) at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:80) at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:602) at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:811) at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:867) at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:875) at org.springframework.jdbc.core.simple.SimpleJdbcTemplate.update(SimpleJdbcTemplate.java:249) at com.vmware.vshield.vsm.utils.DatabaseKeyValueStore._putProperty(DatabaseKeyValueStore.java:94) at com.vmware.vshield.vsm.utils.DatabaseKeyValueStore.putProperty(DatabaseKeyValueStore.java:111) at com.vmware.vshield.vsm.vdn.nvpcontroller.service.impl.ControllerServiceImpl.saveApiKeys(ControllerServiceImpl.java:458) at com.vmware.vshield.vsm.vdn.nvpcontroller.service.impl.ControllerServiceImpl.prepareControllerDeployment_aroundBody0(ControllerServiceImpl.java:683) at com.vmware.vshield.vsm.vdn.nvpcontroller.service.impl.ControllerServiceImpl$AjcClosure1.run(ControllerServiceImpl.java:1) at org.aspectj.runtime.reflect.JoinPointImpl.proceed(JoinPointImpl.java:149) at com.vmware.vshield.vsm.aspects.transaction.TransactionRetryAspect.handleConcurrentTransaction(TransactionRetryAspect.java:57) at com.vmware.vshield.vsm.vdn.nvpcontroller.service.impl.ControllerServiceImpl.prepareControllerDeployment(ControllerServiceImpl.java:531) at com.vmware.vshield.vsm.vdn.nvpcontroller.service.impl.ControllerServiceImpl.createController(ControllerServiceImpl.java:843) at com.vmware.vshield.vsm.vdn.nvpcontroller.facade.ControllerFacadeImpl.createController(ControllerFacadeImpl.java:95) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.lang.reflect.Method.invoke(Unknown Source) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150) at org.springframework.remoting.support.RemoteInvocationTraceInterceptor.invoke(RemoteInvocationTraceInterceptor.java:77) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202) at com.sun.proxy.$Proxy393.createController(Unknown Source) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.lang.reflect.Method.invoke(Unknown Source) at org.springframework.remoting.support.RemoteInvocation.invoke(RemoteInvocation.java:205) at org.springframework.remoting.support.DefaultRemoteInvocationExecutor.invoke(DefaultRemoteInvocationExecutor.java:38) at org.springframework.remoting.support.RemoteInvocationBasedExporter.invoke(RemoteInvocationBasedExporter.java:78) at org.springframework.remoting.support.RemoteInvocationBasedExporter.invokeAndCreateResult(RemoteInvocationBasedExporter.java:114) at org.springframework.remoting.httpinvoker.HttpInvokerServiceExporter.handleRequest(HttpInvokerServiceExporter.java:73) at org.springframework.web.servlet.mvc.HttpRequestHandlerAdapter.handle(HttpRequestHandlerAdapter.java:49) at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:790) at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:719) at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:669) at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:585) at javax.servlet.http.HttpServlet.service(HttpServlet.java:647) at javax.servlet.http.HttpServlet.service(HttpServlet.java:728) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:369) at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:109) at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:83) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:381) at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:97) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:381) at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:100) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:381) at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:78) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:381) at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:54) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:381) at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:35) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:381) at com.vmware.vshield.vsm.security.utils.VsmSSOBasicAuthenticationFilter.doFilter(VsmSSOBasicAuthenticationFilter.java:200) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:381) at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:187) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:381) at org.springframework.security.web.authentication.preauth.AbstractPreAuthenticatedProcessingFilter.doFilter(AbstractPreAuthenticatedProcessingFilter.java:89) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:381) at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:105) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:381) at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:79) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:381) at org.springframework.security.web.session.ConcurrentSessionFilter.doFilter(ConcurrentSessionFilter.java:109) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:381) at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:168) at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:237) at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:167) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) at com.bluelane.em.filter.GenericOperationsOnRequestFilter.doFilter(GenericOperationsOnRequestFilter.java:97) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:222) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:123) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:99) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:407) at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1004) at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:589) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1680) at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Unknown Source) Caused by: org.postgresql.util.PSQLException: ERROR: value too long for type character varying(255) at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2120) at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1853) at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:260) at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:513) at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:389) at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:335) at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105) at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105) at org.springframework.jdbc.core.JdbcTemplate$2.doInPreparedStatement(JdbcTemplate.java:817) at org.springframework.jdbc.core.JdbcTemplate$2.doInPreparedStatement(JdbcTemplate.java:1) at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:586) ... 89 more |
The Issue:
While the error it’s self is fairly straight forward to understand in that the a value being entered into the database table was not of the right type…the reasons behind why it had shown up in the 6.1.1 and 6.1.2 releases after having no such issue working with the 6.0.x releases stumped everyone involved in the ensuing Support Case. In fact it seemed like this was the only/first instance (at the time) of this error in all global NSX-v installs.
The Fix:
NOTE: This can only be performed by VMware Support via an SR.
The fix is a simple SQL Query to alter the KEY_VALUE_STORE referenced in the error…however this can only done done by VMware Support as it requires special access to the NSX Manager Operating System to commit the changes. A word of warning…If you happen to have the secret password to get into the back door of the NSX Manager and apply these changes…your support for NSX could become null and void!
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 |
en default st e -Enter Secret Root Password- -Stop NSX Manager /etc/rc.d/init.d/bluelane-manager stop -Login postgres query shell psql -U secureall secureall=# -Execute the following Queries ALTER TABLE key_value_store ALTER COLUMN value Type text; ALTER TABLE key_value_store ALTER COLUMN value SET DEFAULT NULL; -Start NSX Manager /etc/rc.d/init.d/bluelane-manager start |
Once that’s been committed and the NSX Manager Service restarted Controllers can be successfully deployed…again, the fix needs to be applied by VMware Support.
The RCA:
In regards to the RCA of this issue, the customers having a long upgrade history (5.0 onwards) will hit the issue, since there was a db migration happening from 5.0 to 5.1.x upgrade the alter table script for KEY_VALUE_STORE was missing. As per VMware engineering a new upgrade on NSX Manager is not going to override the DB schema change, since there is no such script to alter table on the upgrade path.
There was no indication of this being fixed in subsequent NSX Releases and no real explanation as to why it didn’t happen in 6.0.x but that aside the fix works and can be actioned in 5 minutes.
This was a fairly unique situation that contributed to this bug being exposed…my environment was a a vCNS 5.1 -> 5.5 -> 5.5.2 -> 5.5.3.1 -> NSX 6.1 -> 6.1.1 -> 6.1.2 replica of one of our Production vCloud Zone that sits in our lab. Previously I’d been able to fully deploy NSX end to end using the same base systems which sat side by side in working order in a separate #NestedESXi Lab…but that was vCNS 5.5.2 upgraded to NSX 6.0.5 which was upgraded to 6.1.2.
So due to not too many deployments of NSX-v the issue only manifested in mature vCNS environments that where upgraded to 6.1.1 or 6.1.2. Something to look out for if you are looking at doing an NSX vCloud Retrofit. If you have a green fields site you will not come across the same issue.
Further Reading:
http://anthonyspiteri.net/nsx-bites-nsx-controller-deployment-issues/
This blog series extends my NSX Bytes Blog Posts to include a more detailed look at how to deploy NSX 6.1.x into an existing vCloud Director Environment. Initially we will be working with vCD 5.5.x which is the non SP Fork of vCD, but as soon as an upgrade path for 5.5.2 -> 5.6.x is released I’ll be including the NSX related improvements in that release.