I did a quick search but cannot find a way this could happen. If you
can reproduce the situation please let us know Cristian
On Thu, Nov 16, 2023 at 5:30 PM <cristian.c@istream.today> wrote:
>
> After I executed :
>
> select * from cloud.user_ip_address where removed is null and allocated is
> null and state !='Free';
>
> I saw this (export as insert):
>
> INSERT INTO cloud.user_ip_address
> (uuid,account_id,domain_id,public_ip_address,data_center_id,source_nat,allocated,vlan_db_id,one_to_one_nat,vm_id,state,mac_address,source_network_id,network_id,physical_network_id,is_system,vpc_id,dnat_vmip,is_portable,display,removed,created,rule_state,forsystemvms)
> VALUES
>
> ('fd4a170b-127e-444d-bf7d-b6ad5529122b',NULL,NULL,'217.xx.2xx.12',7,0,NULL,63,0,NULL,'Allocated',1163,247,NULL,213,0,NULL,NULL,0,1,NULL,NULL,NULL,0);
>
> There was no date for Allocated, it was with NULL.
>
> Thank you,
> Cristian
>
>
>
> -----Original Message-----
> From: Daan Hoogland <daan.hoogl...@gmail.com>
> Sent: Thursday, November 16, 2023 5:33 PM
> To: users@cloudstack.apache.org
> Subject: Re: Failed to fetch any free - False - ACS 4.18.1
>
> just to recap Christian,
> You had one with state free and removed null and now it works again?
> Even though there where free IP before? that should not have been a problem.
> I think that is a bug. Can you exact how you fixed it?
>
> On Thu, Nov 16, 2023 at 4:26 PM <cristian.c@istream.today> wrote:
> >
> > Hi Wei,
> >
> > Thank you for this! There was 1 IP with removed null and state free. I
> > fixed.
> >
> >
> > Regards,
> > Cristian
> >
> >
> >
> > -----Original Message-----
> > From: Wei ZHOU <ustcweiz...@gmail.com>
> > Sent: Thursday, November 16, 2023 12:49 PM
> > To: users@cloudstack.apache.org
> > Subject: Re: Failed to fetch any free - False - ACS 4.18.1
> >
> > Is it possible that an IP is not allocated but the state is not Free ?
> >
> > The sql query below should return empty results.
> >
> > select * from cloud.user_ip_address where removed is null and
> > allocated is null and state !='Free';
> >
> > -Wei
> >
> >
> > On Thu, 16 Nov 2023 at 10:11, Daan Hoogland <daan.hoogl...@gmail.com> wrote:
> >
> > > 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$assignAndAllocateIpAdd
> > > re
> > > ssEntr
> > > > y$0(IpAddressManagerImpl.java:374)
> > > >
> > > > at
> > > > com.cloud.utils.db.Transaction.execute(Transaction.java:40)
> > > >
> > > > at
> > > >
> > > com.cloud.network.IpAddressManagerImpl.assignAndAllocateIpAddressEnt
> > > ry
> > > (IpAdd
> > > > ressManagerImpl.java:339)
> > > >
> > > > at
> > > >
> > > com.cloud.network.IpAddressManagerImpl.fetchNewPublicIp(IpAddressMan
> > > ag
> > > erImpl
> > > > .java:821)
> > > >
> > > > at
> > > >
> > > com.cloud.network.IpAddressManagerImpl.fetchNewPublicIp(IpAddressMan
> > > ag
> > > erImpl
> > > > .java:810)
> > > >
> > > > at
> > > >
> > > com.cloud.network.IpAddressManagerImpl.assignPublicIpAddress(IpAddre
> > > ss
> > > Manage
> > > > rImpl.java:778)
> > > >
> > > > at
> > > >
> > > com.cloud.network.IpAddressManagerImpl$10.doInTransactionWithoutResu
> > > lt
> > > (IpAdd
> > > > ressManagerImpl.java:2240)
> > > >
> > > > at
> > > >
> > > com.cloud.utils.db.TransactionCallbackWithExceptionNoReturn.doInTran
> > > sa
> > > ction(
> > > > TransactionCallbackWithExceptionNoReturn.java:25)
> > > >
> > > > at
> > > >
> > > com.cloud.utils.db.TransactionCallbackWithExceptionNoReturn.doInTran
> > > sa
> > > ction(
> > > > TransactionCallbackWithExceptionNoReturn.java:21)
> > > >
> > > > at
> > > > com.cloud.utils.db.Transaction.execute(Transaction.java:40)
> > > >
> > > > at
> > > >
> > > com.cloud.network.IpAddressManagerImpl.allocateDirectIp(IpAddressMan
> > > ag
> > > erImpl
> > > > .java:2220)
> > > >
> > > > at
> > > >
> > > com.cloud.network.guru.DirectNetworkGuru$1.doInTransactionWithoutRes
> > > ul
> > > t(Dire
> > > > ctNetworkGuru.java:324)
> > > >
> > > > at
> > > >
> > > com.cloud.utils.db.TransactionCallbackWithExceptionNoReturn.doInTran
> > > sa
> > > ction(
> > > > TransactionCallbackWithExceptionNoReturn.java:25)
> > > >
> > > > at
> > > >
> > > com.cloud.utils.db.TransactionCallbackWithExceptionNoReturn.doInTran
> > > sa
> > > ction(
> > > > 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.
> > > ja
> > > va:290
> > > > )
> > > >
> > > > at
> > > >
> > > org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.alloc
> > > at
> > > eNic(N
> > > > etworkOrchestrator.java:1025)
> > > >
> > > > at
> > > >
> > > org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.addRe
> > > qu
> > > estedN
> > > >
> > > icToNicListWithDeviceNumberAndRetrieveDefaultDevice(NetworkOrchestra
> > > to
> > > r.java
> > > > :877)
> > > >
> > > > at
> > > >
> > > org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.alloc
> > > at
> > > e(Netw
> > > > orkOrchestrator.java:850)
> > > >
> > > > at
> > > >
> > > com.cloud.vm.VirtualMachineManagerImpl.allocate(VirtualMachineManage
> > > rI
> > > mpl.ja
> > > > va:491)
> > > >
> > > > at
> > > >
> > > org.apache.cloudstack.engine.orchestration.CloudOrchestrator.createV
> > > ir
> > > tualMa
> > > > chine(CloudOrchestrator.java:255)
> > > >
> > > > at
> > > > com.cloud.vm.UserVmManagerImpl.commitUserVm(UserVmManagerImpl.java
> > > > :4
> > > > 527)
> > > >
> > > > at
> > > > com.cloud.vm.UserVmManagerImpl.commitUserVm(UserVmManagerImpl.java
> > > > :4
> > > > 630)
> > > >
> > > > at
> > > >
> > > com.cloud.vm.UserVmManagerImpl.getUncheckedUserVmResource(UserVmManagerImpl.
> > > > java:4261)
> > > >
> > > > at
> > > >
> > > com.cloud.vm.UserVmManagerImpl.getCheckedUserVmResource(UserVmManage
> > > rI
> > > mpl.ja
> > > > va:3972)
> > > >
> > > > at
> > > >
> > > com.cloud.vm.UserVmManagerImpl.createVirtualMachine(UserVmManagerImpl.
> > > java:3
> > > > 955)
> > > >
> > > > at
> > > >
> > > com.cloud.vm.UserVmManagerImpl.createAdvancedVirtualMachine(UserVmMa
> > > na
> > > gerImp
> > > > l.java:3729)
> > > >
> > > > at
> > > >
> > > com.cloud.vm.UserVmManagerImpl.createVirtualMachine(UserVmManagerImpl.
> > > java:5
> > > > 937)
> > > >
> > > > at
> > > > java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Na
> > > > ti
> > > > ve
> > > > Method)
> > > >
> > > > at
> > > >
> > > java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Nativ
> > > eM
> > > ethodA
> > > > ccessorImpl.java:62)
> > > >
> > > > at
> > > >
> > > java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(D
> > > el
> > > egatin
> > > > gMethodAccessorImpl.java:43)
> > > >
> > > > at
> > > > java.base/java.lang.reflect.Method.invoke(Method.java:566)
> > > >
> > > > at
> > > >
> > > org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflect
> > > io
> > > n(AopU
> > > > tils.java:344)
> > > >
> > > > at
> > > >
> > > org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJ
> > > oi
> > > npoint
> > > > (ReflectiveMethodInvocation.java:198)
> > > >
> > > > at
> > > >
> > > org.springframework.aop.framework.ReflectiveMethodInvocation.proceed
> > > (R
> > > eflect
> > > > iveMethodInvocation.java:163)
> > > >
> > > > at
> > > >
> > > org.springframework.aop.interceptor.ExposeInvocationInterceptor.invo
> > > ke
> > > (Expos
> > > > eInvocationInterceptor.java:97)
> > > >
> > > > at
> > > >
> > > org.springframework.aop.framework.ReflectiveMethodInvocation.proceed
> > > (R
> > > eflect
> > > > iveMethodInvocation.java:186)
> > > >
> > > > at
> > > >
> > > org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynam
> > > ic
> > > AopPro
> > > > xy.java:215)
> > > >
> > > > at com.sun.proxy.$Proxy185.createVirtualMachine(Unknown
> > > > Source)
> > > >
> > > > at
> > > >
> > > org.apache.cloudstack.api.command.user.vm.DeployVMCmd.create(DeployV
> > > MC
> > > md.jav
> > > > a:793)
> > > >
> > > > at
> > > >
> > > com.cloud.api.dispatch.CommandCreationWorker.handle(CommandCreationW
> > > or
> > > ker.ja
> > > > va:47)
> > > >
> > > > at
> > > > com.cloud.api.dispatch.DispatchChain.dispatch(DispatchChain.java:3
> > > > 7)
> > > >
> > > > at
> > > > com.cloud.api.ApiDispatcher.dispatchCreateCmd(ApiDispatcher.java:8
> > > > 8)
> > > >
> > > > 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:3
> > > > 47
> > > > )
> > > >
> > > > at com.cloud.api.ApiServlet$1.run(ApiServlet.java:154)
> > > >
> > > > at
> > > >
> > > org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.c
> > > al
> > > l(Defa
> > > > ultManagedContext.java:55)
> > > >
> > > > at
> > > >
> > > org.apache.cloudstack.managed.context.impl.DefaultManagedContext.cal
> > > lW
> > > ithCon
> > > > text(DefaultManagedContext.java:102)
> > > >
> > > > at
> > > >
> > > org.apache.cloudstack.managed.context.impl.DefaultManagedContext.run
> > > Wi
> > > thCont
> > > > 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:
> > > > 79
> > > > 9)
> > > >
> > > > at
> > > >
> > > org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:
> > > 554)
> > > >
> > > > at
> > > >
> > > org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.
> > > ja
> > > va:143
> > > > )
> > > >
> > > > at
> > > >
> > > org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.ja
> > > va
> > > :600)
> > > >
> > > > at
> > > >
> > > org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.
> > > java:1
> > > > 27)
> > > >
> > > > at
> > > >
> > > org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHand
> > > le
> > > r.java
> > > > :235)
> > > >
> > > > at
> > > >
> > > org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHand
> > > le
> > > r.java
> > > > :1624)
> > > >
> > > > at
> > > >
> > > org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHand
> > > le
> > > r.java
> > > > :233)
> > > >
> > > > at
> > > >
> > > org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHand
> > > le
> > > r.java
> > > > :1440)
> > > >
> > > > at
> > > >
> > > org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:
> > > > 188)
> > > >
> > > > at
> > > > org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.ja
> > > > va
> > > > :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.
> > > ja
> > > va:141
> > > > )
> > > >
> > > > at
> > > >
> > > org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler
> > > .j
> > > ava: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.ja
> > > va
> > > :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(
> > > Ss
> > > lConne
> > > > ction.java:555)
> > > >
> > > > at
> > > > org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.ja
> > > > va
> > > > :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:10
> > > > 4)
> > > >
> > > > at
> > > >
> > > org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWha
> > > tY
> > > ouKill
> > > > .java:338)
> > > >
> > > > at
> > > >
> > > org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatW
> > > ha
> > > tYouKi
> > > > ll.java:315)
> > > >
> > > > at
> > > >
> > > org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(Eat
> > > Wh
> > > atYouK
> > > > ill.java:173)
> > > >
> > > > at
> > > >
> > > org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYou
> > > Ki
> > > ll.jav
> > > > a:131)
> > > >
> > > > at
> > > >
> > > org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.
> > > ru
> > > n(Rese
> > > > rvedThreadExecutor.java:409)
> > > >
> > > > at
> > > >
> > > org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:
> > > > 883)
> > > >
> > > > at
> > > >
> > > org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThre
> > > ad
> > > Pool.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
> > >
> >
>
>
> --
> Daan
>
--
Daan
