Yes I could see a design issue in the logic which tries to acquire locks in the Topology Manager. The problem is that it does not create lock objects on demand, rather locks are pre-created. As a result there is a possibility of raising following errors/warning if lock object is not found:
[2015-01-31 17:54:01,089] WARN {org.apache.stratos.messaging.message.receiver.topology.TopologyManager} - Topology lock not found for Cluster php1.tomcat.domain [2015-01-31 17:54:01,089] DEBUG {org.apache.stratos.autoscaler.util.AutoscalerUtil} - [Cluster] php1.tomcat.domain is not found in the Topology [2015-01-31 17:54:01,090] WARN {org.apache.stratos.messaging.message.receiver.topology.TopologyManager} - Topology lock not found for Cluster php1.tomcat.domain Ideally this should never happen. Thanks On Sat, Jan 31, 2015 at 6:02 PM, Chamila De Alwis <chami...@wso2.com> wrote: > Hi, > > When testing the single-cartridge sample for OpenStack, there were several > occasions of instances not being spawned on the IaaS, without showing any > errors on the logs. The log output contains "Application deployed > successfully", however there are few warning messages related acquiring the > lock on the topology. Other than those entries there are no errors on the > logs, and even after 10-15 minutes, the OpenStack dashboard shows no > spawned instances. > > > [2015-01-31 17:53:49,922] DEBUG > {org.apache.stratos.autoscaler.applications.parser.DefaultApplicationParser} > - Payload :: > APPLICATION_ID=single-cartridge-app,GROUP_NAME=null,SERVICE_NAME=tomcat,HOST_NAME= > php1.isuruh.lk > ,MULTITENANT=false,TENANT_ID=-1234,TENANT_RANGE=*,CARTRIDGE_ALIAS=php1,CLUSTER_ID=php1.tomcat.domain,CARTRIDGE_KEY=oMVzlTBZTAXBaA8m,DEPLOYMENT=default,REPO_URL= > https://github.com/imesh/stratos-tomcat-applications.git,PORTS=22,PROVIDER=apache,PUPPET_IP=192.168.30.96,PUPPET_HOSTNAME=puppet.chamilad.org,PUPPET_DNS_AVAILABLE=null,PUPPET_ENV=null,,,DEPENDENCY_CLUSTER_IDS=,EXPORT_METADATA_KEYS=php1-null,IMPORT_METADATA_KEYS=,TOKEN=eyJhbGciOiJSUzI1NiJ9.eyJleHAiOjEwNzY0NTQ4NDksInN1YiI6ImFkbWluIiwiYXpwIjoiX1dmR2JvZkd3X09DTEZSbEF0QXg2YlE1emFBYSIsImFwcElkIjoic2luZ2xlLWNhcnRyaWRnZS1hcHAiLCJhdWQiOlsiX1dmR2JvZkd3X09DTEZSbEF0QXg2YlE1emFBYSJdLCJpc3MiOiJodHRwczpcL1wvbG9jYWxob3N0Ojk0NDNcL29hdXRoMmVuZHBvaW50c1wvdG9rZW4iLCJpYXQiOjEwNzI4NTQ4NTB9.QSrh9wNeiAxOgDf79h4My-rr4RwwBW29C4aTGmRAP5MvHjZ0SxR8418hLGry9mFqHLXc51WkPiFZSH-1r33sRoAZMVsVheCMy0ZeZoxL5-3-L6cQZ-_m1bp4iZOtblm1bJc105uhBpNeNq7R_GRPVfO08lhDsLn10XkDpirqiC8 > [2015-01-31 17:53:49,922] DEBUG > {org.apache.stratos.autoscaler.applications.parser.DefaultApplicationParser} > - Application parsed successfully: [application-id] single-cartridge-app > [2015-01-31 17:53:50,002] DEBUG > {org.apache.stratos.autoscaler.registry.RegistryManager} - Application [ > single-cartridge-app ] persisted successfully in the Autoscaler Registry > [2015-01-31 17:53:50,059] DEBUG > {org.apache.stratos.autoscaler.registry.RegistryManager} - Application > context [single-cartridge-app] persisted successfully in the Autoscaler > Registry > [2015-01-31 17:53:50,059] INFO > {org.apache.stratos.autoscaler.services.impl.AutoscalerServiceImpl} - > Application added successfully: [application-id] single-cartridge-app > [2015-01-31 17:53:50,099] DEBUG > {org.apache.stratos.manager.registry.RegistryManager} - Persisting > resource in registry: [resource-path] /stratos.manager/data > [2015-01-31 17:53:50,150] DEBUG > {org.apache.stratos.manager.registry.RegistryManager} - Resource persisted > successfully in registry: [resource-path] /stratos.manager/data > [2015-01-31 17:53:55,211] INFO > {org.apache.stratos.rest.endpoint.api.StratosApiV41Utils} - Starting to > deploy application: [application-id] single-cartridge-app > [2015-01-31 17:53:55,306] DEBUG > {org.apache.stratos.autoscaler.applications.topic.ApplicationBuilder} - > Handling application creation event: [application-id] single-cartridge-app > [2015-01-31 17:53:55,312] INFO > {org.apache.stratos.messaging.domain.application.locking.ApplicationLockHierarchy} > - Added lock for Application single-cartridge-app > [2015-01-31 17:53:55,313] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationHolder} - Trying to > retrieve Applications from registry > [2015-01-31 17:53:55,313] WARN > {org.apache.stratos.autoscaler.applications.topic.ApplicationBuilder} - > Application already exists: [application-id] single-cartridge-app > [2015-01-31 17:53:55,343] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationHolder} - Read lock > acquired > [2015-01-31 17:53:55,343] INFO > {org.apache.stratos.autoscaler.client.CloudControllerClient} - Validating > partitions of policy via cloud controller: [cartridge-type] tomcat > [2015-01-31 17:53:55,352] DEBUG > {org.apache.stratos.cloud.controller.services.impl.CloudControllerServiceImpl} > - Deployment policy validation started for cartridge type: tomcat > [2015-01-31 17:53:55,353] DEBUG > {org.apache.stratos.cloud.controller.concurrent.PartitionValidatorCallable} > - Partition validation started for Partition [id=P1, description=null, > isPublic=false, provider=openstack, partitionMin=0, partitionMax=0, > properties=Properties [properties=[Property [name=region, > value=RegionOne]]]] of Cartridge [type=tomcat, hostName=isuruh.lk, > provider=apache, version=7, multiTenant=false, > defaultAutoscalingPolicy=null, defaultDeploymentPolicy=null, > serviceGroup=null, properties={}, partitionToIaasProvider={}] > [2015-01-31 17:53:55,357] DEBUG > {org.apache.stratos.cloud.controller.iaases.openstack.OpenstackIaas} - > Openstack networking provider is nova. Hence trying to instanstiate > org.apache.stratos.cloud.controller.iaases.openstack.networking.NovaNetworkingApi > [2015-01-31 17:53:57,781] DEBUG > {org.apache.stratos.cloud.controller.iaases.openstack.OpenstackIaas} - > Found a matching region: RegionOne > [2015-01-31 17:53:57,782] DEBUG > {org.apache.stratos.cloud.controller.iaases.openstack.OpenstackIaas} - > Openstack networking provider is nova. Hence trying to instanstiate > org.apache.stratos.cloud.controller.iaases.openstack.networking.NovaNetworkingApi > [2015-01-31 17:54:01,010] DEBUG > {org.apache.stratos.manager.components.ApplicationSignUpHandler} - Reading > application signups > [2015-01-31 17:54:01,011] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationSynchronizeTask} - > Applications Complete Event publisher task has been started... > [2015-01-31 17:54:01,011] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationSynchronizeTask} - > Executing topology synchronization task > [2015-01-31 17:54:01,011] DEBUG > {org.apache.stratos.autoscaler.applications.topic.ApplicationBuilder} - > Handling complete application event > [2015-01-31 17:54:01,012] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationHolder} - Read lock > acquired > [2015-01-31 17:54:01,018] DEBUG > {org.apache.stratos.cloud.controller.messaging.publisher.TopologySynchronizerTask} > - Executing topology synchronization task > [2015-01-31 17:54:01,018] DEBUG > {org.apache.stratos.cloud.controller.messaging.publisher.TopologyEventPublisher} > - Publishing complete topology event > [2015-01-31 17:54:01,020] DEBUG > {org.apache.stratos.manager.messaging.publisher.synchronizer.TenantSynzhronizerTask} > - Publishing complete tenant event > [2015-01-31 17:54:01,045] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationHolder} - Read lock > released > [2015-01-31 17:54:01,086] INFO > {org.apache.stratos.messaging.message.processor.topology.CompleteTopologyMessageProcessor} > - Topology initialized > [2015-01-31 17:54:01,088] INFO > {org.apache.stratos.messaging.message.processor.topology.CompleteTopologyMessageProcessor} > - Topology initialized > [2015-01-31 17:54:01,089] INFO > {org.apache.stratos.autoscaler.event.receiver.topology.AutoscalerTopologyEventReceiver} > - [CompleteTopologyEvent] Received: class > org.apache.stratos.messaging.event.topology.CompleteTopologyEvent > [2015-01-31 17:54:01,089] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationHolder} - Read lock > acquired > [2015-01-31 17:54:01,089] WARN > {org.apache.stratos.messaging.message.receiver.topology.TopologyManager} - > Topology lock not found for Cluster php1.tomcat.domain > [2015-01-31 17:54:01,089] DEBUG > {org.apache.stratos.autoscaler.util.AutoscalerUtil} - [Cluster] > php1.tomcat.domain is not found in the Topology > [2015-01-31 17:54:01,090] WARN > {org.apache.stratos.messaging.message.receiver.topology.TopologyManager} - > Topology lock not found for Cluster php1.tomcat.domain > [2015-01-31 17:54:01,090] ERROR > {org.apache.stratos.autoscaler.event.receiver.topology.AutoscalerTopologyEventReceiver} > - Complete Topology is not consistent with the applications which got > persisted > [2015-01-31 17:54:01,090] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationHolder} - Read lock > released > [2015-01-31 17:54:01,090] INFO > {org.apache.stratos.cep.extension.CEPTopologyEventReceiver} - Complete > topology event received to fault handling window processor. > [2015-01-31 17:54:01,091] INFO > {org.apache.stratos.cep.extension.FaultHandlingWindowProcessor} - Member > timestamps were successfully loaded from the topology > [2015-01-31 17:54:05,109] DEBUG > {org.apache.stratos.cloud.controller.iaases.openstack.OpenstackPartitionValidator} > - Added property region to the IaasProvider. > [2015-01-31 17:54:05,109] DEBUG > {org.apache.stratos.cloud.controller.concurrent.PartitionValidatorCallable} > - Partition Partition [id=P1, description=null, isPublic=false, > provider=openstack, partitionMin=0, partitionMax=0, properties=Properties > [properties=[Property [name=region, value=RegionOne]]]] is validated > successfully against the Cartridge: tomcat > [2015-01-31 17:54:05,110] DEBUG > {org.apache.stratos.cloud.controller.services.impl.CloudControllerServiceImpl} > - Partition P1 added to the cache against cartridge: [cartridge-type] > tomcat > [2015-01-31 17:54:05,111] DEBUG > {org.apache.stratos.cloud.controller.domain.Cartridge} - Partition map > updated for the Cartridge: -868128941. Current Partition List: [P1] > [2015-01-31 17:54:05,111] DEBUG > {org.apache.stratos.cloud.controller.registry.RegistryManager} - > Persisting resource in registry: [resource-path] /cloud.controller/data > [2015-01-31 17:54:05,154] DEBUG > {org.apache.stratos.cloud.controller.registry.RegistryManager} - Resource > persisted successfully in registry: [resource-path] /cloud.controller/data > [2015-01-31 17:54:05,154] INFO > {org.apache.stratos.cloud.controller.services.impl.CloudControllerServiceImpl} > - All partitions [P1] were validated successfully, against the Cartridge: > tomcat > [2015-01-31 17:54:05,163] DEBUG > {org.apache.stratos.autoscaler.client.CloudControllerClient} - Service > call validateDeploymentPolicy() returned in 9820ms > [2015-01-31 17:54:05,163] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationHolder} - Read lock > released > [2015-01-31 17:54:05,163] DEBUG > {org.apache.stratos.autoscaler.pojo.policy.PolicyManager} - Adding > deployment policy: [application-id] single-cartridge-app > [2015-01-31 17:54:05,221] DEBUG > {org.apache.stratos.autoscaler.registry.RegistryManager} - Deployment > policy written to registry: Deployment Policy [applicationId] > single-cartridge-app Description null isPublic false [partitions] > [Partition [id=P1, description=null, isPublic=false, provider=openstack, > properties=Properties [properties=[Property [name=region, > value=RegionOne]]]]] > [2015-01-31 17:54:05,221] INFO > {org.apache.stratos.autoscaler.pojo.policy.PolicyManager} - Deployment > policy is added successfully: [application-id] single-cartridge-app > [2015-01-31 17:54:05,221] INFO > {org.apache.stratos.autoscaler.services.impl.AutoscalerServiceImpl} - > Adding application signup: [application-id] single-cartridge-app > [2015-01-31 17:54:05,230] INFO > {org.apache.stratos.manager.components.ApplicationSignUpHandler} - Adding > application signup: [application-id] single-cartridge-app [tenant-id] -1234 > [2015-01-31 17:54:05,234] DEBUG > {org.apache.stratos.manager.registry.RegistryManager} - Persisting > resource in registry: [resource-path] > /stratos.manager/application.signups/single-cartridge-app-tenant--1234 > [2015-01-31 17:54:05,446] DEBUG > {org.apache.stratos.manager.registry.RegistryManager} - Resource persisted > successfully in registry: [resource-path] > /stratos.manager/application.signups/single-cartridge-app-tenant--1234 > [2015-01-31 17:54:05,461] INFO > {org.apache.stratos.manager.components.ApplicationSignUpHandler} - > Application signup added successfully: [application-id] > single-cartridge-app [tenant-id] -1234 > [2015-01-31 17:54:05,462] INFO > {org.apache.stratos.autoscaler.services.impl.AutoscalerServiceImpl} - > Application signup added successfully: [application-id] > single-cartridge-app > [2015-01-31 17:54:05,496] DEBUG > {org.apache.stratos.autoscaler.registry.RegistryManager} - Application > context [single-cartridge-app] persisted successfully in the Autoscaler > Registry > [2015-01-31 17:54:05,496] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationHolder} - Read lock > acquired > [2015-01-31 17:54:05,496] WARN > {org.apache.stratos.messaging.message.receiver.topology.TopologyManager} - > Topology lock not found for Cluster php1.tomcat.domain > [2015-01-31 17:54:05,496] DEBUG > {org.apache.stratos.autoscaler.util.AutoscalerUtil} - [Cluster] > php1.tomcat.domain is not found in the Topology > [2015-01-31 17:54:05,497] WARN > {org.apache.stratos.messaging.message.receiver.topology.TopologyManager} - > Topology lock not found for Cluster php1.tomcat.domain > [2015-01-31 17:54:05,497] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationHolder} - Read lock > released > [2015-01-31 17:54:05,497] INFO > {org.apache.stratos.autoscaler.services.impl.AutoscalerServiceImpl} - The > application clusters are not yet created. Waiting for them to be created > [2015-01-31 17:54:05,499] INFO > {org.apache.stratos.rest.endpoint.api.StratosApiV41Utils} - Application > deployed successfully: [application-id] single-cartridge-app > [2015-01-31 17:55:01,001] DEBUG > {org.apache.stratos.manager.components.ApplicationSignUpHandler} - Reading > application signups > [2015-01-31 17:55:01,003] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationSynchronizeTask} - > Applications Complete Event publisher task has been started... > [2015-01-31 17:55:01,003] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationSynchronizeTask} - > Executing topology synchronization task > [2015-01-31 17:55:01,003] DEBUG > {org.apache.stratos.autoscaler.applications.topic.ApplicationBuilder} - > Handling complete application event > [2015-01-31 17:55:01,003] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationHolder} - Read lock > acquired > [2015-01-31 17:55:01,004] DEBUG > {org.apache.stratos.manager.messaging.publisher.synchronizer.TenantSynzhronizerTask} > - Publishing complete tenant event > [2015-01-31 17:55:01,004] DEBUG > {org.apache.stratos.cloud.controller.messaging.publisher.TopologySynchronizerTask} > - Executing topology synchronization task > [2015-01-31 17:55:01,004] DEBUG > {org.apache.stratos.cloud.controller.messaging.publisher.TopologyEventPublisher} > - Publishing complete topology event > [2015-01-31 17:55:01,030] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationHolder} - Read lock > released > [2015-01-31 17:56:01,001] DEBUG > {org.apache.stratos.manager.components.ApplicationSignUpHandler} - Reading > application signups > [2015-01-31 17:56:01,002] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationSynchronizeTask} - > Applications Complete Event publisher task has been started... > [2015-01-31 17:56:01,003] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationSynchronizeTask} - > Executing topology synchronization task > [2015-01-31 17:56:01,003] DEBUG > {org.apache.stratos.autoscaler.applications.topic.ApplicationBuilder} - > Handling complete application event > [2015-01-31 17:56:01,003] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationHolder} - Read lock > acquired > [2015-01-31 17:56:01,004] DEBUG > {org.apache.stratos.manager.messaging.publisher.synchronizer.TenantSynzhronizerTask} > - Publishing complete tenant event > [2015-01-31 17:56:01,004] DEBUG > {org.apache.stratos.cloud.controller.messaging.publisher.TopologySynchronizerTask} > - Executing topology synchronization task > [2015-01-31 17:56:01,006] DEBUG > {org.apache.stratos.cloud.controller.messaging.publisher.TopologyEventPublisher} > - Publishing complete topology event > [2015-01-31 17:56:01,037] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationHolder} - Read lock > released > [2015-01-31 17:57:01,001] DEBUG > {org.apache.stratos.manager.components.ApplicationSignUpHandler} - Reading > application signups > [2015-01-31 17:57:01,004] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationSynchronizeTask} - > Applications Complete Event publisher task has been started... > [2015-01-31 17:57:01,004] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationSynchronizeTask} - > Executing topology synchronization task > [2015-01-31 17:57:01,005] DEBUG > {org.apache.stratos.autoscaler.applications.topic.ApplicationBuilder} - > Handling complete application event > [2015-01-31 17:57:01,005] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationHolder} - Read lock > acquired > [2015-01-31 17:57:01,005] DEBUG > {org.apache.stratos.manager.messaging.publisher.synchronizer.TenantSynzhronizerTask} > - Publishing complete tenant event > [2015-01-31 17:57:01,006] DEBUG > {org.apache.stratos.cloud.controller.messaging.publisher.TopologySynchronizerTask} > - Executing topology synchronization task > [2015-01-31 17:57:01,006] DEBUG > {org.apache.stratos.cloud.controller.messaging.publisher.TopologyEventPublisher} > - Publishing complete topology event > [2015-01-31 17:57:01,053] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationHolder} - Read lock > released > [2015-01-31 17:58:01,001] DEBUG > {org.apache.stratos.manager.components.ApplicationSignUpHandler} - Reading > application signups > [2015-01-31 17:58:01,003] DEBUG > {org.apache.stratos.manager.messaging.publisher.synchronizer.TenantSynzhronizerTask} > - Publishing complete tenant event > [2015-01-31 17:58:01,003] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationSynchronizeTask} - > Applications Complete Event publisher task has been started... > [2015-01-31 17:58:01,003] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationSynchronizeTask} - > Executing topology synchronization task > [2015-01-31 17:58:01,003] DEBUG > {org.apache.stratos.cloud.controller.messaging.publisher.TopologySynchronizerTask} > - Executing topology synchronization task > [2015-01-31 17:58:01,003] DEBUG > {org.apache.stratos.cloud.controller.messaging.publisher.TopologyEventPublisher} > - Publishing complete topology event > [2015-01-31 17:58:01,003] DEBUG > {org.apache.stratos.autoscaler.applications.topic.ApplicationBuilder} - > Handling complete application event > [2015-01-31 17:58:01,004] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationHolder} - Read lock > acquired > [2015-01-31 17:58:01,054] DEBUG > {org.apache.stratos.autoscaler.applications.ApplicationHolder} - Read lock > released > > Regards, > Chamila de Alwis > Software Engineer | WSO2 | +94772207163 > Blog: code.chamiladealwis.com > > > -- Imesh Gunaratne Technical Lead, WSO2 Committer & PMC Member, Apache Stratos