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 <[email protected]> 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
