What is even more weird is that according to our "topologylistener", the Complete Topology Events on the message bus indicate the "broken" subscription's VM is Active. So in summary:
* The second subscription is stuck until the third one is attempted * When it gets unstuck, the launched VM is never marked as active, even though the logs and the message bus say it is active From: Shaheedur Haque (shahhaqu) Sent: Tuesday, March 17, 2015 3:40 PM To: [email protected] Cc: Ryan Du Plessis (rdupless) Subject: RE: Only one of two single-VM applications coming up in 30 minutes OK, so I have proved that while the second subscription is in the "stuck" state, if I launch a third subscription, the log for the bad one shows all the "missing" created/activated events as if the third subscription "unblocks" the second. However, the second never goes active *even though the third one does go active*: $ ./bin/orchestration stratos-login --admin describe-application-runtime third Application: third {"multiTenant":false,"status":"Active"} Please advise, Thanks, Shaheed From: Shaheedur Haque (shahhaqu) Sent: Tuesday, March 17, 2015 12:33 PM To: [email protected]<mailto:[email protected]> Cc: Ryan Du Plessis (rdupless) Subject: Only one of two single-VM applications coming up in 30 minutes Hi all, I'm working with Stratos 4.1, updated very recently and am trying to spin up two single-VM applications. I can see only one of the two go active: $ ./bin/orchestration stratos-login --admin describe-application-runtime cartridge-proxy Application: cartridge-proxy {"multiTenant":false,"status":"Inactive"} $ ./bin/orchestration stratos-login --admin describe-application-runtime cisco-sample-vm Application: cisco-sample-vm {"multiTenant":false,"status":"Active"} When I look at the logs, the broken one reports no errors, but also never logs messages like the good one about getting allocated IP addresses. The differences start here (good log): TID: [0] [STRATOS] [2015-03-17 08:46:38,547] INFO {org.apache.stratos.autoscaler.util.AutoscalerUtil} - Monitor started successfully: [application] cisco-sample-vm [dependents] cisco-sample-vm.cisco-sample-vm.cisco-sample-vm.domain [startup-time] 0 seconds TID: [0] [STRATOS] [2015-03-17 08:46:39,890] INFO {org.apache.stratos.cloud.controller.services.impl.CloudControllerServiceImpl} - All partitions [whole-region] were validated successfully, against the Cartridge: cisco-sample-vm TID: [0] [STRATOS] [2015-03-17 08:46:40,358] INFO {org.apache.stratos.cloud.controller.messaging.publisher.TopologyEventPublisher} - Publishing cluster instance created event: [service-name] cisco-sample-vm [cluster-id] cisco-sample-vm.cisco-sample-vm.cisco-sample-vm.domain in [network-partition-id] null [instance-id] cisco-sample-vm-1 TID: [0] [STRATOS] [2015-03-17 08:46:40,401] INFO {org.apache.stratos.autoscaler.monitor.MonitorFactory} - ClusterMonitor created: ClusterMonitor [clusterId=cisco-sample-vm.cisco-sample-vm.cisco-sample-vm.domain, hasPrimary=false And the bad log seemingly ends here: TID: [0] [STRATOS] [2015-03-17 08:46:38,019] INFO {org.apache.stratos.autoscaler.util.AutoscalerUtil} - Monitor started successfully: [application] cartridge-proxy [dependents] cartridge-proxy.cartridge-proxy.cartridge-proxy.domain [startup-time] 0 seconds TID: [0] [STRATOS] [2015-03-17 08:46:38,986] INFO {org.apache.stratos.cloud.controller.services.impl.CloudControllerServiceImpl} - All partitions [whole-region] were validated successfully, against the Cartridge: cartridge-proxy At first, I thought that the bad application never gets launched, but it does in fact, about 30 minutes later: TID: [0] [STRATOS] [2015-03-17 09:13:00,560] INFO {org.apache.stratos.cloud.controller.messaging.topology.TopologyBuilder} - Application Cluster system.cartridge-proxy.cartridge-proxy.domain created in CC topology TID: [0] [STRATOS] [2015-03-17 09:13:00,584] INFO {org.apache.stratos.messaging.message.processor.topology.ApplicationClustersCreatedMessageProcessor} - Cluster created: [serviceName=cartridge-proxy, clusterId=system.cartridge-proxy.cartridge-proxy.domain, autoscalePolicyName=economyPolicy, deploymentPolicyName=static-1, hostNames=[system.cartridge-proxy.qmog.cisco.com], tenantRange=*, loadBalanceAlgorithmName=null, appId=system, parentId=null, accessUrls=null, kubernetesServices=[]] TID: [0] [STRATOS] [2015-03-17 09:13:00,690] INFO {org.apache.stratos.autoscaler.monitor.component.ParentComponentMonitor} - Starting dependent monitor: [application] system [component] system.cartridge-proxy.cartridge-proxy.domain TID: [0] [STRATOS] [2015-03-17 09:13:00,691] INFO {org.apache.stratos.autoscaler.monitor.component.ParentComponentMonitor} - Monitor scheduled: [type] cluster [component] system.cartridge-proxy.cartridge-proxy.domain TID: [0] [STRATOS] [2015-03-17 09:13:00,691] INFO {org.apache.stratos.autoscaler.monitor.component.ParentComponentMonitor} - Starting monitor: [type] cluster [component] system.cartridge-proxy.cartridge-proxy.domain TID: [0] [STRATOS] [2015-03-17 09:13:00,691] INFO {org.apache.stratos.autoscaler.util.AutoscalerUtil} - Monitor started successfully: [application] system [dependents] system.cartridge-proxy.cartridge-proxy.domain [startup-time] 0 seconds TID: [0] [STRATOS] [2015-03-17 09:13:00,724] INFO {org.apache.stratos.cloud.controller.services.impl.CloudControllerServiceImpl} - All partitions [whole-region] were validated successfully, against the Cartridge: cartridge-proxy TID: [0] [STRATOS] [2015-03-17 09:13:01,078] INFO {org.apache.stratos.cloud.controller.messaging.publisher.TopologyEventPublisher} - Publishing cluster instance created event: [service-name] cartridge-proxy [cluster-id] system.cartridge-proxy.cartridge-proxy.domain in [network-partition-id] null [instance-id] system-1 TID: [0] [STRATOS] [2015-03-17 09:13:01,102] INFO {org.apache.stratos.autoscaler.monitor.MonitorFactory} - ClusterMonitor created: ClusterMonitor [clusterId=system.cartridge-proxy.cartridge-proxy.domain, hasPrimary=false ] TID: [0] [STRATOS] [2015-03-17 09:13:01,103] INFO {org.apache.stratos.autoscaler.monitor.component.ParentComponentMonitor} - Monitor started successfully: [type] cluster [component] system.cartridge-proxy.cartridge-proxy.domain [dependents] none [startup-time] 0 seconds TID: [0] [STRATOS] [2015-03-17 09:13:01,125] INFO {org.apache.stratos.autoscaler.event.receiver.topology.AutoscalerTopologyEventReceiver} - Monitoring task for Cluster Monitor with cluster id system.cartridge-proxy.cartridge-proxy.domain started successfully TID: [0] [STRATOS] [2015-03-17 09:13:01,131] INFO {org.apache.stratos.autoscaler.rule.RuleLog} - [min-check] Partition available, hence trying to spawn an instance to fulfil minimum count! [cluster] system.cartridge-proxy.cartridge-proxy.domain TID: [0] [STRATOS] [2015-03-17 09:13:01,132] INFO {org.apache.stratos.autoscaler.client.CloudControllerClient} - Trying to spawn an instance via cloud controller: [cluster] system.cartridge-proxy.cartridge-proxy.domain [partition] whole-region [network-partition-id] RegionOne TID: [0] [STRATOS] [2015-03-17 09:13:01,150] INFO {org.apache.stratos.cloud.controller.messaging.publisher.TopologyEventPublisher} - Publishing member created event: [service-name] cartridge-proxy [cluster-id] system.cartridge-proxy.cartridge-proxy.domain [cluster-instance-id] system-1 [member-id] system.cartridge-proxy.cartridge-proxy.domain7eac63b9-d106-42f9-95c6-ec97041062e1 [instance-id] null [network-partition-id] RegionOne [partition-id] whole-region [lb-cluster-id] null TID: [0] [STRATOS] [2015-03-17 09:13:01,159] INFO {org.apache.stratos.messaging.message.processor.topology.MemberCreatedMessageProcessor} - Member created: [service-name] cartridge-proxy [cluster-id] system.cartridge-proxy.cartridge-proxy.domain [member-id] system.cartridge-proxy.cartridge-proxy.domain7eac63b9-d106-42f9-95c6-ec97041062e1 [cluster-instance-id] system-1 TID: [0] [STRATOS] [2015-03-17 09:13:11,539] INFO {org.apache.stratos.cloud.controller.services.impl.InstanceCreator} - Instance started successfully: [cartridge-type] cartridge-proxy [cluster-id] system.cartridge-proxy.cartridge-proxy.domain [instance-id] RegionOne/8ea88f5f-23be-4045-962d-c8c43eaa3596 [default-private-ip] null [default-public-ip] null TID: [0] [STRATOS] [2015-03-17 09:13:11,540] INFO {org.apache.stratos.cloud.controller.iaases.JcloudsIaas} - Allocating IP addresses for member: [cartridge-type] cartridge-proxy [member-id] system.cartridge-proxy.cartridge-proxy.domain7eac63b9-d106-42f9-95c6-ec97041062e1 TID: [0] [STRATOS] [2015-03-17 09:13:11,611] INFO {org.apache.stratos.cloud.controller.iaases.JcloudsIaas} - Retrieving private IP addresses MemberContext [applicationId=system, cartridgeType=cartridge-proxy, clusterId=system.cartridge-proxy.cartridge-proxy.domain, memberId=system.cartridge-proxy.cartridge-proxy.domain7eac63b9-d106-42f9-95c6-ec97041062e1, instanceId=RegionOne/8ea88f5f-23be-4045-962d-c8c43eaa3596, partition=Partition [id=whole-region, description=null, isPublic=false, provider=Core, properties=Properties [properties=[Property [name=region, value=RegionOne]]]], defaultPrivateIP=172.16.180.22, defaultPublicIP=null, allocatedIPs=null, publicIPs=[], privateIPs=[172.16.180.22], initTime=1426583581140, lbClusterId=null, networkPartitionId=RegionOne, kubernetesPodId=null, kubernetesPodLabel=null, loadBalancingIPType=Private, instanceMetadata=org.apache.stratos.cloud.controller.domain.InstanceMetadata@14612b31<mailto:instanceMetadata=org.apache.stratos.cloud.controller.domain.InstanceMetadata@14612b31>, properties=Properties [properties=[Property [name=PRIMARY, value=false], Property [name=MIN_COUNT, value=1]]]] TID: [0] [STRATOS] [2015-03-17 09:13:11,621] INFO {org.apache.stratos.cloud.controller.messaging.publisher.TopologyEventPublisher} - Publishing member initialized event: [service-name] cartridge-proxy [cluster-id] system.cartridge-proxy.cartridge-proxy.domain [cluster-instance-id] system-1 [member-id] system.cartridge-proxy.cartridge-proxy.domain7eac63b9-d106-42f9-95c6-ec97041062e1 [instance-id] RegionOne/8ea88f5f-23be-4045-962d-c8c43eaa3596 [network-partition-id] RegionOne [partition-id] whole-region [lb-cluster-id] null TID: [0] [STRATOS] [2015-03-17 09:13:11,629] INFO {org.apache.stratos.messaging.message.processor.topology.MemberInitializedMessageProcessor} - Member initialized: [service] cartridge-proxy [cluster] system.cartridge-proxy.cartridge-proxy.domain [member] system.cartridge-proxy.cartridge-proxy.domain7eac63b9-d106-42f9-95c6-ec97041062e1 TID: [0] [STRATOS] [2015-03-17 09:15:01,579] INFO {org.apache.stratos.manager.messaging.receiver.StratosManagerInstanceStatusEventReceiver} - Instance started event received: [application-id] system [cartridge-type] cartridge-proxy [member-id] system.cartridge-proxy.cartridge-proxy.domain7eac63b9-d106-42f9-95c6-ec97041062e1 TID: [0] [STRATOS] [2015-03-17 09:15:01,590] INFO {org.apache.stratos.cloud.controller.messaging.publisher.TopologyEventPublisher} - Publishing member started event: [service-name] cartridge-proxy [cluster-id] system.cartridge-proxy.cartridge-proxy.domain [cluster-instance-id] system-1 [member-id] system.cartridge-proxy.cartridge-proxy.domain7eac63b9-d106-42f9-95c6-ec97041062e1 [network-partition-id] RegionOne [partition-id] whole-region TID: [0] [STRATOS] [2015-03-17 09:15:01,597] INFO {org.apache.stratos.messaging.message.processor.topology.MemberStartedMessageProcessor} - Member started: [service] cartridge-proxy [cluster] system.cartridge-proxy.cartridge-proxy.domain [member] system.cartridge-proxy.cartridge-proxy.domain7eac63b9-d106-42f9-95c6-ec97041062e1 TID: [0] [STRATOS] [2015-03-17 09:15:01,604] INFO {org.apache.stratos.manager.components.ArtifactDistributionCoordinator} - Artifact updated event published: [application-id] system [tenant-id] -1234 [cartridge-type] cartridge-proxy [alias] cartridge-proxy [repo-url] http://octl.qmog.cisco.com:10080/git/default.git TID: [0] [STRATOS] [2015-03-17 09:15:07,297] INFO {org.apache.stratos.cloud.controller.messaging.publisher.TopologyEventPublisher} - Publishing member activated event: [service-name] cartridge-proxy [cluster-id] system.cartridge-proxy.cartridge-proxy.domain [cluster-instance-id] system-1 [member-id] system.cartridge-proxy.cartridge-proxy.domain7eac63b9-d106-42f9-95c6-ec97041062e1 [network-partition-id] RegionOne [partition-id] whole-region TID: [0] [STRATOS] [2015-03-17 09:15:07,307] INFO {org.apache.stratos.messaging.message.processor.topology.MemberActivatedMessageProcessor} - Member activated: [service] cartridge-proxy [cluster] system.cartridge-proxy.cartridge-proxy.domain [member] system.cartridge-proxy.cartridge-proxy.domain7eac63b9-d106-42f9-95c6-ec97041062e1 TID: [0] [STRATOS] [2015-03-17 09:15:07,307] INFO {org.apache.stratos.cep.extension.CEPTopologyEventReceiver} - Member [member id] system.cartridge-proxy.cartridge-proxy.domain7eac63b9-d106-42f9-95c6-ec97041062e1 was added to the time stamp map. TID: [0] [STRATOS] [2015-03-17 09:15:07,308] INFO {org.apache.stratos.autoscaler.status.processor.cluster.ClusterStatusActiveProcessor} - Publishing cluster activated event for [application]: system [cluster]: system.cartridge-proxy.cartridge-proxy.domain However, despite the Member activated event, the instance is still marked as Inactive: $ ./bin/orchestration stratos-login --admin describe-application-runtime cartridge-proxy Application: cartridge-proxy {"multiTenant":false,"status":"Inactive"} Note, between 08:46 and 09:13, I was doing other things (trying to get a multi-VM application launched), but nothing that should have interfered with this activity. Thanks, Shaheed
