mikeits
Contributor
Contributor

Repeat collections in usage meter v2.3

Occasionally we have a usage meter v2.3 collection that appears to both fail and succeed at the same time; I will receive both a 'Collection OK' and 'Collection failed' email at the same time.  When this happens, the usage meter will retry 5 minutes later and either will just succeed or will succeed and fail at the same time again.  This results in having more than 24 collections in a single day, inflating our vRAM usage numbers.  All of the failures have the same error (below), and when I run a billing report and compare it to the report from our v2.2 usage meter for the same vCenter server the v2.3 meter reports higher usage by about the amount from these repeat collections.

---------

Usage Meter will wait 300 seconds and retry up to 2 more times.

java.util.NoSuchElementException: key not found: VmKey(1,null)

scala.collection.MapLike$class.default(MapLike.scala:224)

scala.collection.immutable.HashMap.default(HashMap.scala:36)

scala.collection.MapLike$class.apply(MapLike.scala:135)

scala.collection.immutable.HashMap.apply(HashMap.scala:36)

com.vmware.cloud.usgmtr.custvm.CustomerVmLinker$$anonfun$link$1$$anonfun$apply$3.apply(CustomerVmLinker.scala:34)

com.vmware.cloud.usgmtr.custvm.CustomerVmLinker$$anonfun$link$1$$anonfun$apply$3.apply(CustomerVmLinker.scala:31)

scala.collection.TraversableLike$WithFilter$$anonfun$map$2.apply(TraversableLike.scala:661)

scala.collection.Iterator$class.foreach(Iterator.scala:660)

org.squeryl.dsl.AbstractQuery$$anon$1.foreach(AbstractQuery.scala:156)

scala.collection.IterableLike$class.foreach(IterableLike.scala:73)

org.squeryl.dsl.AbstractQuery.foreach(AbstractQuery.scala:27)

scala.collection.TraversableLike$WithFilter.map(TraversableLike.scala:660)

com.vmware.cloud.usgmtr.custvm.CustomerVmLinker$$anonfun$link$1.apply(CustomerVmLinker.scala:31)

com.vmware.cloud.usgmtr.custvm.CustomerVmLinker$$anonfun$link$1.apply(CustomerVmLinker.scala:30)

scala.collection.LinearSeqOptimized$class.foreach(LinearSeqOptimized.scala:59)

scala.collection.immutable.List.foreach(List.scala:45)

com.vmware.cloud.usgmtr.custvm.CustomerVmLinker$.link(CustomerVmLinker.scala:30)

com.vmware.cloud.usgmtr.collect.Collector$.collectAndSaveSamples(Collector.scala:76)

com.vmware.cloud.usgmtr.collect.Collector$$anonfun$collectAll$2$$anonfun$apply$1.apply$mcV$sp(Collector.scala:30)

com.vmware.cloud.usgmtr.collect.Collector$$anonfun$collectAll$2$$anonfun$apply$1.apply(Collector.scala:29)

com.vmware.cloud.usgmtr.collect.Collector$$anonfun$collectAll$2$$anonfun$apply$1.apply(Collector.scala:29)

org.squeryl.dsl.QueryDsl$class._using(QueryDsl.scala:46)

org.squeryl.dsl.QueryDsl$class._executeTransactionWithin(QueryDsl.scala:114)

org.squeryl.dsl.QueryDsl$class.transaction(QueryDsl.scala:78)

org.squeryl.PrimitiveTypeMode$.transaction(PrimitiveTypeMode.scala:40)

com.vmware.cloud.usgmtr.collect.Collector$$anonfun$collectAll$2.apply(Collector.scala:28)

com.vmware.cloud.usgmtr.collect.Collector$$anonfun$collectAll$2.apply(Collector.scala:28)

com.vmware.cloud.usgmtr.commons.Parallelizer$$anonfun$2$$anon$1.call(Parallelizer.scala:18)

java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)

java.util.concurrent.FutureTask.run(FutureTask.java:138)

java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)

java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

java.lang.Thread.run(Thread.java:662)

Labels (1)
Tags (3)
0 Kudos
6 Replies
dbriccetti
Hot Shot
Hot Shot

Thanks for the report, and sorry about the problem. Are you working with GSS on this? I’d love to see your /var/log/usgmtr/um.log. It seems you have a VM with a missing instance UUID causing a failure in the customer rules application, which is incorrectly triggering a retry of the collection.

Dave Briccetti

0 Kudos
dbriccetti
Hot Shot
Hot Shot

Would you please search your um.log for

VM instanceUuid is missing.

Thanks.

Dave Briccetti

mikeits
Contributor
Contributor

I had this issue again today, and when I searched the um.log it does list instanceUuid is missing for a VM that was in the process of being deployed from a template.  It looks like the previous instances of the happening were also for VMs that were being deployed from template at the time of the collection.

2012-04-12 16:07:13,815 ERROR [pool-1037-thread-1] collect.Vms$: VM instanceUuid is missing. vm-297509 VMNAME

0 Kudos
dbriccetti
Hot Shot
Hot Shot

Thanks for that info. This will be fixed in 2.3.2, coming soon.

0 Kudos
mikeits
Contributor
Contributor

OK, thanks.

0 Kudos
Damester
Contributor
Contributor

Hi, we are having the same issue with usage meter v2.3.

But I have found no records of "VM instanceUuid is missing" in our logs:

We are planning to upgrade to the latest version soon but would like to confirm the issue and if the upgrade is likely to resolve it.

2013-10-09 05:10:06,836 ERROR [pool-1828-thread-1] collect.Collector$: A collection from servermgt03.domain.local, begun at 2013-10-09 05:10:04, failed at 2013-10-09 05:10:06.

java.util.NoSuchElementException: key not found: VmKey(1,null)
at scala.collection.MapLike$class.default(MapLike.scala:224)
at scala.collection.immutable.HashMap.default(HashMap.scala:36)
at scala.collection.MapLike$class.apply(MapLike.scala:135)
at scala.collection.immutable.HashMap.apply(HashMap.scala:36)
at com.vmware.cloud.usgmtr.custvm.CustomerVmLinker$$anonfun$link$1$$anonfun$apply$3.apply(CustomerVmLinker.scala:34)
at com.vmware.cloud.usgmtr.custvm.CustomerVmLinker$$anonfun$link$1$$anonfun$apply$3.apply(CustomerVmLinker.scala:31)
at scala.collection.TraversableLike$WithFilter$$anonfun$map$2.apply(TraversableLike.scala:661)
at scala.collection.Iterator$class.foreach(Iterator.scala:660)
at org.squeryl.dsl.AbstractQuery$$anon$1.foreach(AbstractQuery.scala:156)
at scala.collection.IterableLike$class.foreach(IterableLike.scala:73)
at org.squeryl.dsl.AbstractQuery.foreach(AbstractQuery.scala:27)
at scala.collection.TraversableLike$WithFilter.map(TraversableLike.scala:660)
at com.vmware.cloud.usgmtr.custvm.CustomerVmLinker$$anonfun$link$1.apply(CustomerVmLinker.scala:31)
at com.vmware.cloud.usgmtr.custvm.CustomerVmLinker$$anonfun$link$1.apply(CustomerVmLinker.scala:30)
at scala.collection.LinearSeqOptimized$class.foreach(LinearSeqOptimized.scala:59)
at scala.collection.immutable.List.foreach(List.scala:45)
at com.vmware.cloud.usgmtr.custvm.CustomerVmLinker$.link(CustomerVmLinker.scala:30)
at com.vmware.cloud.usgmtr.collect.Collector$.collectAndSaveSamples(Collector.scala:76)
at com.vmware.cloud.usgmtr.collect.Collector$.collectAndSaveSamples(Collector.scala:99)
at com.vmware.cloud.usgmtr.collect.Collector$$anonfun$collectAll$2$$anonfun$apply$1.apply$mcV$sp(Collector.scala:30)
at com.vmware.cloud.usgmtr.collect.Collector$$anonfun$collectAll$2$$anonfun$apply$1.apply(Collector.scala:29)
at com.vmware.cloud.usgmtr.collect.Collector$$anonfun$collectAll$2$$anonfun$apply$1.apply(Collector.scala:29)
at org.squeryl.dsl.QueryDsl$class._using(QueryDsl.scala:46)
at org.squeryl.dsl.QueryDsl$class._executeTransactionWithin(QueryDsl.scala:114)
at org.squeryl.dsl.QueryDsl$class.transaction(QueryDsl.scala:78)
at org.squeryl.PrimitiveTypeMode$.transaction(PrimitiveTypeMode.scala:40)
at com.vmware.cloud.usgmtr.collect.Collector$$anonfun$collectAll$2.apply(Collector.scala:28)
at com.vmware.cloud.usgmtr.collect.Collector$$anonfun$collectAll$2.apply(Collector.scala:28)
at com.vmware.cloud.usgmtr.commons.Parallelizer$$anonfun$2$$anon$1.call(Parallelizer.scala:18)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)
2013-10-09 05:10:06,986  INFO [pool-1828-thread-1] collect.Collector$: Waiting 300 seconds before retrying collection
2013-10-09 05:15:07,203  INFO [pool-1828-thread-1] collect.VCenterCollectorCaller: Connected to VMware vCenter Server 5.0.0 build-913577 at servermgt03.domain.local
2013-10-09 05:15:07,477  INFO [pool-1832-thread-1] vc.VCenterCollector: Fetching type ResourcePool from servermgt03.domain.local
2013-10-09 05:15:07,477  INFO [pool-1832-thread-2] vc.VCenterCollector: Fetching type VirtualMachine from servermgt03.domain.local
2013-10-09 05:15:07,477  INFO [pool-1832-thread-3] vc.VCenterCollector: Fetching type HostSystem from servermgt03.domain.local
2013-10-09 05:15:07,478  INFO [pool-1832-thread-4] vc.VCenterCollector: Fetching type ComputeResource from servermgt03.domain.local
2013-10-09 05:15:07,478  INFO [pool-1832-thread-5] vc.VCenterCollector: Fetching type Folder from servermgt03.domain.local
2013-10-09 05:15:07,488  INFO [pool-1832-thread-6] vc.VCenterCollector: Fetching type Datacenter from servermgt03.domain.local
2013-10-09 05:15:08,140  INFO [pool-1832-thread-4] vc.VCenterCollector: Fetched type ComputeResource in 662 ms
2013-10-09 05:15:08,156  INFO [pool-1832-thread-1] vc.VCenterCollector: Fetched type ResourcePool in 679 ms
2013-10-09 05:15:08,168  INFO [pool-1832-thread-6] vc.VCenterCollector: Fetched type Datacenter in 680 ms
2013-10-09 05:15:08,170  INFO [pool-1832-thread-5] vc.VCenterCollector: Fetched type Folder in 692 ms
2013-10-09 05:15:08,293  INFO [pool-1832-thread-3] vc.VCenterCollector: Fetched type HostSystem in 816 ms
2013-10-09 05:15:08,687  INFO [pool-1832-thread-2] vc.VCenterCollector: Fetched type VirtualMachine in 1,210 ms
2013-10-09 05:15:08,688  INFO [pool-1828-thread-1] vc.VCenterCollector: Found 4 resource pools/vApps
2013-10-09 05:15:08,699  INFO [pool-1828-thread-1] vc.VCenterCollector: Found 222 VMs
2013-10-09 05:15:08,699  INFO [pool-1828-thread-1] vc.VCenterCollector: Found 16 hosts
2013-10-09 05:15:09,250  INFO [pool-1828-thread-1] vc.VCenterCollector: Found 2 clusters with 2 + 14 hosts
2013-10-09 05:15:09,251  INFO [pool-1828-thread-1] vc.VCenterCollector: Found 46 folders
2013-10-09 05:15:09,251  INFO [pool-1828-thread-1] vc.VCenterCollector: Found 1 datacenters
2013-10-09 05:15:09,471  INFO [pool-1828-thread-1] collect.Hosts$: Updating host host-36 serveresx24.domain.local
2013-10-09 05:15:09,472  INFO [pool-1828-thread-1] collect.Hosts$: Updating host host-541 serveresx04.domain.local
2013-10-09 05:15:09,473  INFO [pool-1828-thread-1] collect.Hosts$: Updating host host-546 serveresx05.domain.local
2013-10-09 05:15:09,473  INFO [pool-1828-thread-1] collect.Hosts$: Updating host host-566 serveresx11.domain.local
2013-10-09 05:15:09,474  INFO [pool-1828-thread-1] collect.Hosts$: Updating host host-48 serveresx27.domain.local
2013-10-09 05:15:09,474  INFO [pool-1828-thread-1] collect.Hosts$: Updating host host-32 serveresx23.domain.local
2013-10-09 05:15:09,475  INFO [pool-1828-thread-1] collect.Hosts$: Updating host host-562 serveresx10.domain.local
2013-10-09 05:15:09,475  INFO [pool-1828-thread-1] collect.Hosts$: Updating host host-44 serveresx26.domain.local
2013-10-09 05:15:09,476  INFO [pool-1828-thread-1] collect.Hosts$: Updating host host-558 serveresx09.domain.local
2013-10-09 05:15:09,476  INFO [pool-1828-thread-1] collect.Hosts$: Updating host host-40 serveresx25.domain.local
2013-10-09 05:15:09,477  INFO [pool-1828-thread-1] collect.Hosts$: Updating host host-554 serveresx08.domain.local
2013-10-09 05:15:09,477  INFO [pool-1828-thread-1] collect.Hosts$: Updating host host-28 serveresx22.domain.local
2013-10-09 05:15:09,478  INFO [pool-1828-thread-1] collect.Hosts$: Updating host host-23 serveresx21.domain.local
2013-10-09 05:15:09,478  INFO [pool-1828-thread-1] collect.Hosts$: Updating host host-570 serveresx12.domain.local
2013-10-09 05:15:09,479  INFO [pool-1828-thread-1] collect.Hosts$: Updating host host-52 serveresx28.domain.local
2013-10-09 05:15:09,479  INFO [pool-1828-thread-1] collect.Hosts$: Updating host host-550 serveresx07.domain.local
2013-10-09 05:15:09,496  INFO [pool-1828-thread-1] collect.SampleCreator: resgroup-16658 LanierDEV (0be834a8-016b-4cc7-8619-f000ba8f4ec3) contains 0 reportable VMs
2013-10-09 05:15:09,496  INFO [pool-1828-thread-1] collect.SampleCreator: resgroup-3098 System vDC (405656a4-fc14-442e-be3d-deb6577e8ce5) contains 2 reportable VMs
2013-10-09 05:15:09,497  INFO [pool-1828-thread-1] collect.SampleCreator: resgroup-5644 Resources contains 32 reportable VMs
2013-10-09 05:15:09,497  INFO [pool-1828-thread-1] collect.SampleCreator: resgroup-92 Resources contains 159 reportable VMs
2013-10-09 05:15:09,880 ERROR [pool-1828-thread-1] collect.Collector$: A collection from servermgt03.domain.local, begun at 2013-10-09 05:15:06, failed at 2013-10-09 05:15:09.

0 Kudos