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)
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
Would you please search your um.log for
VM instanceUuid is missing.
Thanks.
Dave Briccetti
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
Thanks for that info. This will be fixed in 2.3.2, coming soon.
OK, thanks.
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.