strange Christian,
I checked the code and the only thing I can think of is that creating
a DB lock fails.
if (_ipAddressDao.lockRow(possibleAddr.getId(), true) != null) {
final IPAddressVO userIp = _ipAddressDao.findById(possibleAddr.getId());
if (userIp.getState() == State.Free) {
possibleAddr.setState(State.Allocating);
if (_ipAddressDao.update(possibleAddr.getId(), possibleAddr)) {
finalAddress = possibleAddr;
break;
}
}
}
Unfortunately, no further logging can be turned on to investigate.
is this a persistent error (i.e. remains after restarting system
components like the MS and the DB)?
On Wed, Nov 15, 2023 at 5:52 PM <cristian.c@istream.today> wrote:
>
>
> Hello,
>
>
>
> Today, I tried to deploy new VMs, but I encountered the following error:
> failed to fetch any free public IP address. This is incorrect, as even on
> the dashboard, I can see 12/22 for Public and 172/212 for Shared. For this
> deployment, I used the Shared/guest network. I also checked the database and
> saw 41 free IPs for this zone.
>
>
> Any suggestions?
>
>
> 2023-11-15 11:18:53,441 INFO [c.c.h.v.m.VirtualMachineMO]
> (DirectAgent-19:ctx-a91068e2 usa-nyc-001.test.host, cmd:
> GetVolumeStatsCommand) (logid:851b339a) Look for disk device info from
> volume : ROOT-6215_2.vmdk with base name: ROOT-6215_2
>
> 2023-11-15 11:18:53,441 INFO [c.c.h.v.m.VirtualMachineMO]
> (DirectAgent-19:ctx-a91068e2 usa-nyc-001.test.host, cmd:
> GetVolumeStatsCommand) (logid:851b339a) Test against disk device, controller
> key: 1000, unit number: 0
>
> 2023-11-15 11:18:53,441 INFO [c.c.h.v.m.VirtualMachineMO]
> (DirectAgent-19:ctx-a91068e2 usa-nyc-001.test.host, cmd:
> GetVolumeStatsCommand) (logid:851b339a) Test against disk backing : [nyc001]
> i-2-6215-VMAMS/ROOT-6215_2.vmdk
>
> 2023-11-15 11:18:53,441 INFO [c.c.h.v.m.VirtualMachineMO]
> (DirectAgent-19:ctx-a91068e2 usa-nyc-001.test.host, cmd:
> GetVolumeStatsCommand) (logid:851b339a) Disk backing : [nyc001]
> i-2-6215-VMAMS/ROOT-6215_2.vmdk matches ==> scsi0:0
>
> 2023-11-15 11:18:54,194 INFO [c.c.n.NetworkModelImpl]
> (qtp1444635922-323:ctx-a813b819 ctx-3b16875f) (logid:2b3f6d9b) Checking
> permission for account admin (17274c5e-d492-11e5-86c3-000c298715c8) on
> network TestHost-Public-NYC (1bece1dc-d9c1-4bff-b5aa-67333a6830ae)
>
> 2023-11-15 11:18:54,309 INFO [c.c.v.VirtualMachineManagerImpl]
> (qtp1444635922-323:ctx-a813b819 ctx-3b16875f) (logid:2b3f6d9b) allocating
> virtual machine from template:391d4eab-1506-44be-b743-5ae7bd0f4ad7 with
> hostname:i-2-6262-VMAMS and 1 networks
>
> 2023-11-15 11:18:54,325 ERROR [c.c.n.IpAddressManagerImpl]
> (qtp1444635922-323:ctx-a813b819 ctx-3b16875f) (logid:2b3f6d9b) Failed to
> fetch any free
>
> public IP address
>
> 2023-11-15 11:18:54,340 ERROR [c.c.a.ApiServer]
> (qtp1444635922-323:ctx-a813b819 ctx-3b16875f) (logid:2b3f6d9b) unhandled
> exception executing api command: [Ljava.lang.String;@4a8c9f6c
>
> com.cloud.utils.exception.CloudRuntimeException: Failed to fetch any free
> public IP address
>
> at
> com.cloud.network.IpAddressManagerImpl.lambda$assignAndAllocateIpAddressEntr
> y$0(IpAddressManagerImpl.java:374)
>
> at com.cloud.utils.db.Transaction.execute(Transaction.java:40)
>
> at
> com.cloud.network.IpAddressManagerImpl.assignAndAllocateIpAddressEntry(IpAdd
> ressManagerImpl.java:339)
>
> at
> com.cloud.network.IpAddressManagerImpl.fetchNewPublicIp(IpAddressManagerImpl
> .java:821)
>
> at
> com.cloud.network.IpAddressManagerImpl.fetchNewPublicIp(IpAddressManagerImpl
> .java:810)
>
> at
> com.cloud.network.IpAddressManagerImpl.assignPublicIpAddress(IpAddressManage
> rImpl.java:778)
>
> at
> com.cloud.network.IpAddressManagerImpl$10.doInTransactionWithoutResult(IpAdd
> ressManagerImpl.java:2240)
>
> at
> com.cloud.utils.db.TransactionCallbackWithExceptionNoReturn.doInTransaction(
> TransactionCallbackWithExceptionNoReturn.java:25)
>
> at
> com.cloud.utils.db.TransactionCallbackWithExceptionNoReturn.doInTransaction(
> TransactionCallbackWithExceptionNoReturn.java:21)
>
> at com.cloud.utils.db.Transaction.execute(Transaction.java:40)
>
> at
> com.cloud.network.IpAddressManagerImpl.allocateDirectIp(IpAddressManagerImpl
> .java:2220)
>
> at
> com.cloud.network.guru.DirectNetworkGuru$1.doInTransactionWithoutResult(Dire
> ctNetworkGuru.java:324)
>
> at
> com.cloud.utils.db.TransactionCallbackWithExceptionNoReturn.doInTransaction(
> TransactionCallbackWithExceptionNoReturn.java:25)
>
> at
> com.cloud.utils.db.TransactionCallbackWithExceptionNoReturn.doInTransaction(
> TransactionCallbackWithExceptionNoReturn.java:21)
>
> at com.cloud.utils.db.Transaction.execute(Transaction.java:40)
>
> at
> com.cloud.network.guru.DirectNetworkGuru.allocateDirectIp(DirectNetworkGuru.
> java:317)
>
> at
> com.cloud.network.guru.DirectNetworkGuru.allocate(DirectNetworkGuru.java:290
> )
>
> at
> org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.allocateNic(N
> etworkOrchestrator.java:1025)
>
> at
> org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.addRequestedN
> icToNicListWithDeviceNumberAndRetrieveDefaultDevice(NetworkOrchestrator.java
> :877)
>
> at
> org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.allocate(Netw
> orkOrchestrator.java:850)
>
> at
> com.cloud.vm.VirtualMachineManagerImpl.allocate(VirtualMachineManagerImpl.ja
> va:491)
>
> at
> org.apache.cloudstack.engine.orchestration.CloudOrchestrator.createVirtualMa
> chine(CloudOrchestrator.java:255)
>
> at
> com.cloud.vm.UserVmManagerImpl.commitUserVm(UserVmManagerImpl.java:4527)
>
> at
> com.cloud.vm.UserVmManagerImpl.commitUserVm(UserVmManagerImpl.java:4630)
>
> at
> com.cloud.vm.UserVmManagerImpl.getUncheckedUserVmResource(UserVmManagerImpl.
> java:4261)
>
> at
> com.cloud.vm.UserVmManagerImpl.getCheckedUserVmResource(UserVmManagerImpl.ja
> va:3972)
>
> at
> com.cloud.vm.UserVmManagerImpl.createVirtualMachine(UserVmManagerImpl.java:3
> 955)
>
> at
> com.cloud.vm.UserVmManagerImpl.createAdvancedVirtualMachine(UserVmManagerImp
> l.java:3729)
>
> at
> com.cloud.vm.UserVmManagerImpl.createVirtualMachine(UserVmManagerImpl.java:5
> 937)
>
> at
> java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native
> Method)
>
> at
> java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodA
> ccessorImpl.java:62)
>
> at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Delegatin
> gMethodAccessorImpl.java:43)
>
> at java.base/java.lang.reflect.Method.invoke(Method.java:566)
>
> at
> org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopU
> tils.java:344)
>
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint
> (ReflectiveMethodInvocation.java:198)
>
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(Reflect
> iveMethodInvocation.java:163)
>
> at
> org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(Expos
> eInvocationInterceptor.java:97)
>
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(Reflect
> iveMethodInvocation.java:186)
>
> at
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopPro
> xy.java:215)
>
> at com.sun.proxy.$Proxy185.createVirtualMachine(Unknown Source)
>
> at
> org.apache.cloudstack.api.command.user.vm.DeployVMCmd.create(DeployVMCmd.jav
> a:793)
>
> at
> com.cloud.api.dispatch.CommandCreationWorker.handle(CommandCreationWorker.ja
> va:47)
>
> at
> com.cloud.api.dispatch.DispatchChain.dispatch(DispatchChain.java:37)
>
> at
> com.cloud.api.ApiDispatcher.dispatchCreateCmd(ApiDispatcher.java:88)
>
> at com.cloud.api.ApiServer.queueCommand(ApiServer.java:703)
>
> at com.cloud.api.ApiServer.handleRequest(ApiServer.java:603)
>
> at
> com.cloud.api.ApiServlet.processRequestInContext(ApiServlet.java:347)
>
> at com.cloud.api.ApiServlet$1.run(ApiServlet.java:154)
>
> at
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(Defa
> ultManagedContext.java:55)
>
> at
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithCon
> text(DefaultManagedContext.java:102)
>
> at
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithCont
> ext(DefaultManagedContext.java:52)
>
> at com.cloud.api.ApiServlet.processRequest(ApiServlet.java:151)
>
> at com.cloud.api.ApiServlet.doGet(ApiServlet.java:105)
>
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:645)
>
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:750)
>
> at
> org.eclipse.jetty.servlet.ServletHolder$NotAsync.service(ServletHolder.java:
> 1450)
>
> at
> org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799)
>
> at
> org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:554)
>
> at
> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143
> )
>
> at
> org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:600)
>
> at
> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:1
> 27)
>
> at
> org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java
> :235)
>
> at
> org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java
> :1624)
>
> at
> org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java
> :233)
>
> at
> org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java
> :1440)
>
> at
> org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:
> 188)
>
> at
> org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:505)
>
> at
> org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:
> 1594)
>
> at
> org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:
> 186)
>
> at
> org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:
> 1355)
>
> at
> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141
> )
>
> at
> org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:77
> 2)
>
> at
> org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.
> java:146)
>
> at
> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:1
> 27)
>
> at org.eclipse.jetty.server.Server.handle(Server.java:516)
>
> at
> org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487)
>
> at
> org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732)
>
> at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479)
>
> at
> org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277)
>
> at
> org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConne
> ction.java:311)
>
> at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
>
> at
> org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConne
> ction.java:555)
>
> at
> org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:410)
>
> at
> org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:164)
>
> at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
>
> at
> org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
>
> at
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill
> .java:338)
>
> at
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKi
> ll.java:315)
>
> at
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouK
> ill.java:173)
>
> at
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.jav
> a:131)
>
> at
> org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(Rese
> rvedThreadExecutor.java:409)
>
> at
> org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:
> 883)
>
> at
> org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.j
> ava:1034)
>
> at java.base/java.lang.Thread.run(Thread.java:829)
>
> 2023-11-15 11:18:54,406 WARN [c.c.a.m.AgentManagerImpl]
> (AgentManager-Handler-1:null) (logid:) Throwing away a request because it
> came through as
>
> the first command on a connect: null
>
>
>
> Regards,
>
> Cristian
>
--
Daan
