Automation: PBB EVPN sanity test failure (test_mac_learning_subIntf_single_isid)

[Chandra Sekhar Reddy Mallam]

2018-05-02 17:40:47,820 - INFO - Domain Default found not creating
2018-05-02 17:40:48,142 - INFO - Project ctest-TestPbbEvpnMacLearning-47403300 not found, creating it
2018-05-02 17:40:48,454 - INFO - Created Project:ctest-TestPbbEvpnMacLearning-47403300, ID : ea721f84-f660-4db2-8fd2-c6f139dd8576
2018-05-02 17:40:49,626 - INFO - ================================================================================
2018-05-02 17:40:49,626 - INFO - STARTING TEST : test_mac_learning_subIntf_single_isid
2018-05-02 17:40:49,626 - INFO - TEST DESCRIPTION :
            Test MAC learning on I-Component with single isid on sub-interfaces

2018-05-02 17:40:55,276 - DEBUG - Skipping xmpp flap check
2018-05-02 17:40:55,277 - INFO - Initial checks done. Running the testcase now
2018-05-02 17:40:55,277 - INFO -
2018-05-02 17:40:55,277 - DEBUG - Read the existing encap priority
2018-05-02 17:40:55,321 - INFO - Created.UUID is {"global-vrouter-config": {"href": "http://10.10.10.14:8082/global-vrouter-config/c4dc3a02-628e-4b24-8734-6b30bd23330e", "uuid": "c4dc3a02-628e-4b24-8734-6b30bd23330e"}}. MPLSoUDP is the highest priority encap
2018-05-02 17:40:55,496 - DEBUG - Response for create_network : {u'network': {u'status': u'ACTIVE', u'router:external': False, u'subnets': [], u'fq_name': [u'default-domain', u'ctest-TestPbbEvpnMacLearning-47403300', u'vn1'], u'name': u'vn1', u'admin_state_up': True, u'tenant_id': u'ea721f84f6604db28fd2c6f139dd8576', u'created_at': None, u'updated_at': None, u'port_security_enabled': True, u'shared': False, u'project_id': u'ea721f84f6604db28fd2c6f139dd8576', u'id': u'd1e81bb7-b0de-4f2a-9628-343cb907b4e7', u'description': u''}}
2018-05-02 17:40:55,577 - DEBUG - Response for create_subnet : {u'subnet': {u'name': u'', u'enable_dhcp': True, u'network_id': u'd1e81bb7-b0de-4f2a-9628-343cb907b4e7', u'tenant_id': u'ea721f84f6604db28fd2c6f139dd8576', u'created_at': u'2018-05-02T12:10:55.521920', u'dns_nameservers': [], u'updated_at': u'2018-05-02T12:10:55.521920', u'gateway_ip': u'10.10.10.1', u'ipv6_ra_mode': None, u'allocation_pools': [{u'start': u'10.10.10.2', u'end': u'10.10.10.254'}], u'host_routes': [], u'dns_server_address': u'10.10.10.2', u'ip_version': 4, u'ipv6_address_mode': None, u'cidr': u'10.10.10.0/24', u'id': u'31244b9d-e868-47e3-8b3a-d651df20980f'}}
2018-05-02 17:40:55,601 - INFO - Created VN vn1
2018-05-02 17:40:55,609 - DEBUG - VN vn1 UUID is d1e81bb7-b0de-4f2a-9628-343cb907b4e7
2018-05-02 17:40:55,675 - DEBUG - Updating Layer2 control word on VN default-domain:ctest-TestPbbEvpnMacLearning-47403300:vn1 to True
2018-05-02 17:40:55,708 - DEBUG - Requesting: http://10.10.10.14:8082/virtual-network/d1e81bb7-b0de-4f2a-9628-343cb907b4e7
2018-05-02 17:40:55,873 - DEBUG - Response for create_network : {u'network': {u'status': u'ACTIVE', u'router:external': False, u'subnets': [], u'fq_name': [u'default-domain', u'ctest-TestPbbEvpnMacLearning-47403300', u'vn2'], u'name': u'vn2', u'admin_state_up': True, u'tenant_id': u'ea721f84f6604db28fd2c6f139dd8576', u'created_at': None, u'updated_at': None, u'port_security_enabled': True, u'shared': False, u'project_id': u'ea721f84f6604db28fd2c6f139dd8576', u'id': u'2ee88828-bdd6-4b2c-97eb-30f92f8219f7', u'description': u''}}
2018-05-02 17:40:55,949 - DEBUG - Response for create_subnet : {u'subnet': {u'name': u'', u'enable_dhcp': True, u'network_id': u'2ee88828-bdd6-4b2c-97eb-30f92f8219f7', u'tenant_id': u'ea721f84f6604db28fd2c6f139dd8576', u'created_at': u'2018-05-02T12:10:55.894041', u'dns_nameservers': [], u'updated_at': u'2018-05-02T12:10:55.894041', u'gateway_ip': u'1.1.1.1', u'ipv6_ra_mode': None, u'allocation_pools': [{u'start': u'1.1.1.2', u'end': u'1.1.1.254'}], u'host_routes': [], u'dns_server_address': u'1.1.1.2', u'ip_version': 4, u'ipv6_address_mode': None, u'cidr': u'1.1.1.0/24', u'id': u'cf9a72a1-aac5-47e5-b31f-2a4048a7c1fd'}}
2018-05-02 17:40:55,969 - INFO - Created VN vn2
2018-05-02 17:40:55,977 - DEBUG - VN vn2 UUID is 2ee88828-bdd6-4b2c-97eb-30f92f8219f7
2018-05-02 17:40:56,091 - DEBUG - Updating Layer2 control word on VN default-domain:ctest-TestPbbEvpnMacLearning-47403300:vn2 to True
2018-05-02 17:40:56,126 - DEBUG - Requesting: http://10.10.10.14:8082/virtual-network/2ee88828-bdd6-4b2c-97eb-30f92f8219f7
2018-05-02 17:40:56,169 - INFO - Created Bridge Domain [u'default-domain', u'ctest-TestPbbEvpnMacLearning-47403300', u'vn2', u'ctest-bd_ctest-TestPbbEvpnMacLearning-47403300-97907153'], UUID: 4e8848e7-e60e-44ec-8467-30a597a332f9
2018-05-02 17:40:56,169 - DEBUG - Requesting: http://10.10.10.14:8082/bridge-domains
2018-05-02 17:40:56,174 - DEBUG - Requesting: http://10.10.10.14:8082/bridge-domain/4e8848e7-e60e-44ec-8467-30a597a332f9
2018-05-02 17:40:56,182 - INFO - Verifications in API Server 10.10.10.7 for BD ctest-bd_ctest-TestPbbEvpnMacLearning-47403300-97907153 passed
2018-05-02 17:40:56,342 - DEBUG - Response for create_port : {u'port': {u'status': u'DOWN', u'binding:host_id': None, u'name': u'725d6ae5-583d-43d0-a115-ff855498c50b', u'allowed_address_pairs': [], u'admin_state_up': True, u'network_id': u'd1e81bb7-b0de-4f2a-9628-343cb907b4e7', u'tenant_id': u'ea721f84f6604db28fd2c6f139dd8576', u'created_at': u'2018-05-02T12:10:56.240602', u'updated_at': u'2018-05-02T12:10:56.257241', u'binding:vnic_type': u'normal', u'binding:vif_type': u'vrouter', u'device_owner': u'', u'mac_address': u'02:72:5d:6a:e5:58', u'id': u'725d6ae5-583d-43d0-a115-ff855498c50b', u'port_security_enabled': True, u'device_id': u'', u'fixed_ips': [{u'subnet_id': u'31244b9d-e868-47e3-8b3a-d651df20980f', u'ip_address': u'10.10.10.3'}], u'binding:vif_details': {u'port_filter': True}, u'security_groups': [u'9840ac02-6288-4e97-9ecc-e1a0e323be89'], u'description': u''}}
2018-05-02 17:40:56,367 - DEBUG - Created port 725d6ae5-583d-43d0-a115-ff855498c50b
2018-05-02 17:40:56,520 - DEBUG - Response for create_port : {u'port': {u'status': u'DOWN', u'binding:host_id': None, u'name': u'be80e7cf-cd18-469f-94a5-8ca97eb9ee35', u'allowed_address_pairs': [], u'admin_state_up': True, u'network_id': u'd1e81bb7-b0de-4f2a-9628-343cb907b4e7', u'tenant_id': u'ea721f84f6604db28fd2c6f139dd8576', u'created_at': u'2018-05-02T12:10:56.430534', u'updated_at': u'2018-05-02T12:10:56.448042', u'binding:vnic_type': u'normal', u'binding:vif_type': u'vrouter', u'device_owner': u'', u'mac_address': u'02:be:80:e7:cf:cd', u'id': u'be80e7cf-cd18-469f-94a5-8ca97eb9ee35', u'port_security_enabled': True, u'device_id': u'', u'fixed_ips': [{u'subnet_id': u'31244b9d-e868-47e3-8b3a-d651df20980f', u'ip_address': u'10.10.10.4'}], u'binding:vif_details': {u'port_filter': True}, u'security_groups': [u'9840ac02-6288-4e97-9ecc-e1a0e323be89'], u'description': u''}}
2018-05-02 17:40:56,544 - DEBUG - Created port be80e7cf-cd18-469f-94a5-8ca97eb9ee35
2018-05-02 17:40:56,701 - DEBUG - Created port b7122551-f808-475d-a2ae-25ba9e454316
2018-05-02 17:40:56,725 - INFO - Policy DISABLED on VMI b7122551-f808-475d-a2ae-25ba9e454316
2018-05-02 17:40:56,883 - DEBUG - Created port 7986802a-d7de-43c3-9c3e-b0d722f2bcd3
2018-05-02 17:40:56,909 - INFO - Policy DISABLED on VMI 7986802a-d7de-43c3-9c3e-b0d722f2bcd3
2018-05-02 17:40:56,964 - DEBUG - Services list from nova: [<Service: nova-scheduler>, <Service: nova-scheduler>, <Service: nova-scheduler>, <Service: nova-conductor>, <Service: nova-conductor>, <Service: nova-conductor>, <Service: nova-consoleauth>, <Service: nova-consoleauth>, <Service: nova-consoleauth>, <Service: nova-compute>, <Service: nova-compute>, <Service: nova-compute>]
2018-05-02 17:40:56,964 - DEBUG - Hosts: {u'nova': [u'nodem10', u'nodem9', u'nodem8']}
2018-05-02 17:40:57,297 - DEBUG - Check whether image by uuid 6b43ad5c-d477-4710-ac69-c4d0a61c63d1 is active
2018-05-02 17:40:58,547 - INFO - VM ([<Server: ctest-TestPbbEvpnMacLearning-47403300-17874287>]) created on node: (nodem10), Zone: (nova:nodem10)
2018-05-02 17:40:59,281 - DEBUG - Check whether image by uuid 6b43ad5c-d477-4710-ac69-c4d0a61c63d1 is active
2018-05-02 17:41:00,371 - INFO - VM ([<Server: ctest-TestPbbEvpnMacLearning-47403300-36041846>]) created on node: (nodem9), Zone: (nova:nodem9)
2018-05-02 17:41:00,372 - INFO - Waiting for VM ctest-TestPbbEvpnMacLearning-47403300-36041846 to be up..
2018-05-02 17:41:00,534 - DEBUG - VM <Server: ctest-TestPbbEvpnMacLearning-47403300-36041846> is still in BUILD state, Expected: ACTIVE
2018-05-02 17:41:05,788 - DEBUG - VM <Server: ctest-TestPbbEvpnMacLearning-47403300-36041846> is in ACTIVE state now
2018-05-02 17:41:06,029 - DEBUG - VM ctest-TestPbbEvpnMacLearning-47403300-36041846 ID is da971d46-45d2-4545-8848-deeffce439b2
2018-05-02 17:41:06,072 - DEBUG - VM ctest-TestPbbEvpnMacLearning-47403300-36041846 launched on Node nodem9
2018-05-02 17:41:06,568 - DEBUG - Requesting: http://10.10.10.14:8082/virtual-machine/da971d46-45d2-4545-8848-deeffce439b2
2018-05-02 17:41:06,578 - DEBUG - Requesting: http://10.10.10.14:8082/virtual-machine-interface/be80e7cf-cd18-469f-94a5-8ca97eb9ee35
2018-05-02 17:41:06,588 - DEBUG - Requesting: http://10.10.10.14:8082/virtual-machine/da971d46-45d2-4545-8848-deeffce439b2
2018-05-02 17:41:06,595 - DEBUG - Requesting: http://10.10.10.14:8082/virtual-machine-interface/be80e7cf-cd18-469f-94a5-8ca97eb9ee35
2018-05-02 17:41:09,751 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 999ms')
2018-05-02 17:41:09,751 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestPbbEvpnMacLearning-47403300-36041846 failed!
2018-05-02 17:41:09,767 - DEBUG - Gateway for vn default-domain:ctest-TestPbbEvpnMacLearning-47403300:vn1 is 10.10.10.1 and allocation pool is NOT set
2018-05-02 17:41:12,906 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 999ms')
2018-05-02 17:41:12,906 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestPbbEvpnMacLearning-47403300-36041846 failed!
2018-05-02 17:41:12,931 - DEBUG - Gateway for vn default-domain:ctest-TestPbbEvpnMacLearning-47403300:vn1 is 10.10.10.1 and allocation pool is NOT set
2018-05-02 17:41:12,931 - WARNING - VM metadata IP is not 169.254.x.x
2018-05-02 17:41:12,953 - DEBUG - VM ctest-TestPbbEvpnMacLearning-47403300-36041846 does not seem to be fully up
2018-05-02 17:41:14,325 - DEBUG - Console output: [ 0.000000] Initializing cgroup subsys cpuset
[ 0.000000] Initializing cgroup subsys cpu
[ 0.000000] Linux version 3.2.0-35-virtual (buildd@allspice) (gcc version 4.6.3 (Ubuntu/Linaro 4.6.3-1ubuntu5) ) #55-Ubuntu SMP Wed Dec 5 18:02:05 UTC 2012 (Ubuntu 3.2.0-35.55-virtual 3.2.34)
[ 0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-3.2.0-35-virtual root=UUID=02147f18-c4e2-47d4-ba41-a162651517cb ro console=ttyS0 console=tty0 rootdelay=1800
[ 0.000000] KERNEL supported cpus:
[ 0.000000] Intel GenuineIntel
[ 0.000000] AMD AuthenticAMD
[ 0.000000] Centaur CentaurHauls
[ 0.000000] BIOS-provided physical RAM map:
[ 0.000000] BIOS-e820: 0000000000000000 - 000000000009fc00 (usable)
[ 0.000000] BIOS-e820: 000000000009fc00 - 00000000000a0000 (reserved)
[ 0.000000] BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
[ 0.000000] BIOS-e820: 0000000000100000 - 000000003ffe0000 (usable)
[ 0.000000] BIOS-e820: 000000003ffe0000 - 0000000040000000 (reserved)
[ 0.000000] BIOS-e820: 00000000feffc000 - 00000000ff000000 (reserved)
[ 0.000000] BIOS-e820: 00000000fffc0000 - 0000000100000000 (reserved)
[ 0.000000] NX (Execute Disable) protection: active
[ 0.000000] DMI 2.8 present.
[ 0.000000] No AGP bridge found
[ 0.000000] last_pfn = 0x3ffe0 max_arch_pfn = 0x400000000
[ 0.000000] x86 PAT enabled: cpu 0, old 0x7040600070406, new 0x7010600070106
[ 0.000000] found SMP MP-table at [ffff8800000f7300] f7300
[ 0.000000] Using GB pages for direct mapping
[ 0.000000] init_memory_mapping: 0000000000000000-000000003ffe0000
[ 0.000000] RAMDISK: 3776e000 - 37baf000
[ 0.000000] ACPI: RSDP 00000000000f70d0 00014 (v00 BOCHS )
[ 0.000000] ACPI: RSDT 000000003ffe14c9 0002C (v01 BOCHS BXPCRSDT 00000001 BXPC 00000001)
[ 0.000000] ACPI: FACP 000000003ffe13dd 00074 (v01 BOCHS BXPCFACP 00000001 BXPC 00000001)
[ 0.000000] ACPI: DSDT 000000003ffe0040 0139D (v01 BOCHS BXPCDSDT 00000001 BXPC 00000001)
[ 0.000000] ACPI: FACS 000000003ffe0000 00040
[ 0.000000] ACPI: APIC 000000003ffe1451 00078 (v01 BOCHS BXPCAPIC 00000001 BXPC 00000001)
[ 0.000000] No NUMA configuration found
[ 0.000000] Faking a node at 0000000000000000-000000003ffe0000
[ 0.000000] Initmem setup node 0 0000000000000000-000000003ffe0000
[ 0.000000] NODE_DATA [000000003ffdb000 - 000000003ffdffff]
[ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00
[ 0.000000] kvm-clock: cpu 0, msr 0:1cf7681, boot clock
[ 0.000000] Zone PFN ranges:
[ 0.000000] DMA 0x00000010 -> 0x00001000
[ 0.000000] DMA32 0x00001000 -> 0x00100000
[ 0.000000] Normal empty
[ 0.000000] Movable zone start PFN for each node
[ 0.000000] early_node_map[2] active PFN ranges
[ 0.000000] 0: 0x00000010 -> 0x0000009f
[ 0.000000] 0: 0x00000100 -> 0x0003ffe0
[ 0.000000] ACPI: PM-Timer IO Port: 0x608
[ 0.000000] ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
[ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])
[ 0.000000] ACPI: IOAPIC (id[0x00] address[0xfec00000] gsi_base[0])
[ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23
[ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
[ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
[ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
[ 0.000000] Using ACPI (MADT) for SMP configuration information
[ 0.000000] SMP: Allowing 1 CPUs, 0 hotplug CPUs
[ 0.000000] PM: Registered nosave memory: 000000000009f000 - 00000000000a0000
[ 0.000000] PM: Registered nosave memory: 00000000000a0000 - 00000000000f0000
[ 0.000000] PM: Registered nosave memory: 00000000000f0000 - 0000000000100000
[ 0.000000] Allocating PCI resources starting at 40000000 (gap: 40000000:beffc000)
[ 0.000000] Booting paravirtualized kernel on KVM
[ 0.000000] setup_percpu: NR_CPUS:64 nr_cpumask_bits:64 nr_cpu_ids:1 nr_node_ids:1
[ 0.000000] PERCPU: Embedded 28 pages/cpu @ffff88003fc00000 s82880 r8192 d23616 u2097152
[ 0.000000] kvm-clock: cpu 0, msr 0:3fc13681, primary cpu clock
[ 0.000000] KVM setup async PF for cpu 0
[ 0.000000] kvm-stealtime: cpu 0, msr 3fc0dd40
[ 0.000000] Built 1 zonelists in Node order, mobility grouping on. Total pages: 257898
[ 0.000000] Policy zone: DMA32
[ 0.000000] Kernel command line: BOOT_IMAGE=/boot/vmlinuz-3.2.0-35-virtual root=UUID=02147f18-c4e2-47d4-ba41-a162651517cb ro console=ttyS0 console=tty0 rootdelay=1800
[ 0.000000] PID hash table entries: 4096 (order: 3, 32768 bytes)
[ 0.000000] xsave/xrstor: enabled xstate_bv 0x7, cntxt size 0x340
[ 0.000000] Checking aperture...
[ 0.000000] No AGP bridge found
[ 0.000000] Memory: 1011348k/1048448k available (6540k kernel code, 452k absent, 36648k reserved, 6652k data, 924k init)
[ 0.000000] SLUB: Genslabs=15, HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[ 0.000000] Hierarchical RCU implementation.
[ 0.000000] RCU dyntick-idle grace-period acceleration is enabled.
[ 0.000000] NR_IRQS:4352 nr_irqs:256 16
[ 0.000000] Console: colour VGA+ 80x25
[ 0.000000] console [tty0] enabled
[ 0.000000] console [ttyS0] enabled
[ 0.000000] allocated 8388608 bytes of page_cgroup
[ 0.000000] please try 'cgroup_disable=memory' option if you don't want memory cgroups
[ 0.000000] Detected 2199.996 MHz processor.
[ 0.008000] Calibrating delay loop (skipped) preset value.. 4399.99 BogoMIPS (lpj=8799984)
[ 0.008006] pid_max: default: 32768 minimum: 301
[ 0.009491] Security Framework initialized
[ 0.010844] AppArmor: AppArmor initialized
[ 0.012004] Yama: becoming mindful.
[ 0.013292] Dentry cache hash table entries: 131072 (order: 8, 1048576 bytes)
[ 0.015564] Inode-cache hash table entries: 65536 (order: 7, 524288 bytes)
[ 0.016081] Mount-cache hash table entries: 256
[ 0.017625] Initializing cgroup subsys cpuacct
[ 0.020008] Initializing cgroup subsys memory
[ 0.021435] Initializing cgroup subsys devices
[ 0.022862] Initializing cgroup subsys freezer
[ 0.024005] Initializing cgroup subsys blkio
[ 0.025411] Initializing cgroup subsys perf_event
[ 0.028072] CPU: Physical Processor ID: 0
[ 0.030608] mce: CPU supports 10 MCE banks
[ 0.032330] SMP alternatives: switching to UP code
[ 0.050118] Freeing SMP alternatives: 24k freed
[ 0.051799] ACPI: Core revision 20110623
[ 0.052501] ftrace: allocating 27024 entries in 106 pages
[ 0.064269] Enabling x2apic
[ 0.065440] Enabled x2apic
[ 0.068007] Switched APIC routing to physical x2apic.
[ 0.073261] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[ 0.075387] CPU0: Intel Core Processor (Skylake) stepping 03
[ 0.080004] Performance Events: unsupported p6 CPU model 94 no PMU driver, software events only.
[ 0.080004] NMI watchdog disabled (cpu0): hardware events not enabled
[ 0.080016] Brought up 1 CPUs
[ 0.081124] Total of 1 processors activated (4399.99 BogoMIPS).
[ 0.084312] devtmpfs: initialized
[ 0.085945] EVM: security.selinux
[ 0.087222] EVM: security.SMACK64
[ 0.088007] EVM: security.capability
[ 0.089749] print_constraints: dummy:
[ 0.092078] RTC time: 12:11:07, date: 05/02/18
[ 0.093602] NET: Registered protocol family 16
[ 0.095228] ACPI: bus type pci registered
[ 0.096089] PCI: Using configuration type 1 for base access
[ 0.098346] bio: create slab <bio-0> at 0
[ 0.100069] ACPI: Added _OSI(Module Device)
[ 0.101466] ACPI: Added _OSI(Processor Device)
[ 0.102995] ACPI: Added _OSI(3.0 _SCP Extensions)
[ 0.104007] ACPI: Added _OSI(Processor Aggregator Device)
[ 0.108067] ACPI: Interpreter enabled
[ 0.109335] ACPI: (supports S0 S5)
[ 0.110679] ACPI: Using IOAPIC for interrupt routing
[ 0.113305] ACPI: No dock devices found.
[ 0.114639] HEST: Table not found.
[ 0.116009] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[ 0.119299] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
[ 0.120037] pci_root PNP0A03:00: host bridge window [io 0x0000-0x0cf7]
[ 0.122077] pci_root PNP0A03:00: host bridge window [io 0x0d00-0xffff]
[ 0.124009] pci_root PNP0A03:00: host bridge window [mem 0x000a0000-0x000bffff]
[ 0.128009] pci_root PNP0A03:00: host bridge window [mem 0x40000000-0xfebfffff]
[ 0.140433] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI
[ 0.144019] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB
[ 0.201108] pci0000:00: Unable to request _OSC control (_OSC support mask: 0x1e)
[ 0.204808] ACPI: PCI Interrupt Link [LNKA] (IRQs 5 *10 11)
[ 0.207149] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 *10 11)
[ 0.208941] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 10 *11)
[ 0.211346] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 10 *11)
[ 0.212933] ACPI: PCI Interrupt Link [LNKS] (IRQs *9)
[ 0.216095] vgaarb: device added: PCI:0000:00:02.0,decodes=io+mem,owns=io+mem,locks=none
[ 0.218809] vgaarb: loaded
[ 0.220014] vgaarb: bridge control possible 0000:00:02.0
[ 0.221851] i2c-core: driver [aat2870] using legacy suspend method
[ 0.223893] i2c-core: driver [aat2870] using legacy resume method
[ 0.224051] SCSI subsystem initialized
[ 0.225368] usbcore: registered new interface driver usbfs
[ 0.228022] usbcore: registered new interface driver hub
[ 0.229734] usbcore: registered new device driver usb
[ 0.232066] PCI: Using ACPI for IRQ routing
[ 0.233636] NetLabel: Initializing
[ 0.234841] NetLabel: domain hash size = 128
[ 0.236015] NetLabel: protocols = UNLABELED CIPSOv4
[ 0.237592] NetLabel: unlabeled traffic allowed by default
[ 0.240043] Switching to clocksource kvm-clock
[ 0.243509] AppArmor: AppArmor Filesystem Enabled
[ 0.245085] pnp: PnP ACPI init
[ 0.246217] ACPI: bus type pnp registered
[ 0.247949] pnp: PnP ACPI: found 9 devices
[ 0.249342] ACPI: ACPI bus type pnp unregistered
[ 0.256167] NET: Registered protocol family 2
[ 0.257618] IP route cache hash table entries: 32768 (order: 6, 262144 bytes)
[ 0.260816] TCP established hash table entries: 131072 (order: 9, 2097152 bytes)
[ 0.263440] TCP bind hash table entries: 65536 (order: 8, 1048576 bytes)
[ 0.265495] TCP: Hash tables configured (established 131072 bind 65536)
[ 0.267535] TCP reno registered
[ 0.268585] UDP hash table entries: 512 (order: 2, 16384 bytes)
[ 0.270361] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[ 0.272267] NET: Registered protocol family 1
[ 0.273641] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
[ 0.275461] pci 0000:00:01.0: PIIX3: Enabling Passive Release
[ 0.285496] pci 0000:00:01.0: Activating ISA DMA hang workarounds
[ 0.287475] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 11
[ 0.289101] pci 0000:00:01.2: PCI INT D -> Link[LNKD] -> GSI 11 (level, high) -> IRQ 11
[ 0.291768] pci 0000:00:01.2: PCI INT D disabled
[ 0.293360] audit: initializing netlink socket (disabled)
[ 0.294930] type=2000 audit(1525263067.292:1): initialized
[ 0.312717] Trying to unpack rootfs image as initramfs...
[ 0.336154] HugeTLB registered 2 MB page size, pre-allocated 0 pages
[ 0.345361] VFS: Disk quotas dquot_6.5.2
[ 0.346461] Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[ 0.348273] fuse init (API version 7.17)
[ 0.349382] msgmni has been set to 1975
[ 0.368076] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 253)
[ 0.370290] io scheduler noop registered
[ 0.371375] io scheduler deadline registered (default)
[ 0.372652] io scheduler cfq registered
[ 0.373737] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
[ 0.375198] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
[ 0.377483] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0
[ 0.380458] ACPI: Power Button [PWRF]
[ 0.392363] ERST: Table is not found!
[ 0.393682] GHES: HEST is not enabled!
[ 0.395295] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 10
[ 0.397231] virtio-pci 0000:00:03.0: PCI INT A -> Link[LNKC] -> GSI 10 (level, high) -> IRQ 10
[ 0.400682] virtio-pci 0000:00:04.0: PCI INT A -> Link[LNKD] -> GSI 11 (level, high) -> IRQ 11
[ 0.406287] Freeing initrd memory: 4356k freed
[ 0.408384] Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled
[ 0.433859] serial8250: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
[ 0.459367] 00:05: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
[ 0.461271] Linux agpgart interface v0.103
[ 0.463234] brd: module loaded
[ 0.464604] loop: module loaded
[ 0.466347] scsi0 : ata_piix
[ 0.467407] scsi1 : ata_piix
[ 0.468442] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc060 irq 14
[ 0.470581] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc068 irq 15
[ 0.472785] Fixed MDIO Bus: probed
[ 0.473955] tun: Universal TUN/TAP device driver, 1.6
[ 0.475559] tun: (C) 1999-2004 Max Krasnyansky <email address hidden>
[ 0.478901] PPP generic driver version 2.4.2
[ 0.480961] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[ 0.483020] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[ 0.484931] uhci_hcd: USB Universal Host Controller Interface driver
[ 0.486982] uhci_hcd 0000:00:01.2: PCI INT D -> Link[LNKD] -> GSI 11 (level, high) -> IRQ 11
[ 0.490100] uhci_hcd 0000:00:01.2: UHCI Host Controller
[ 0.491784] uhci_hcd 0000:00:01.2: new USB bus registered, assigned bus number 1
[ 0.494306] uhci_hcd 0000:00:01.2: irq 11, io base 0x0000c000
[ 0.496169] hub 1-0:1.0: USB hub found
[ 0.497451] hub 1-0:1.0: 2 ports detected
[ 0.498842] usbcore: registered new interface driver libusual
[ 0.500584] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12
[ 0.503740] serio: i8042 KBD port at 0x60,0x64 irq 1
[ 0.505288] serio: i8042 AUX port at 0x60,0x64 irq 12
[ 0.506939] mousedev: PS/2 mouse device common for all mice
[ 0.508810] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1
[ 0.511629] rtc_cmos 00:01: RTC can wake from S4
[ 0.513235] rtc_cmos 00:01: rtc core: registered rtc_cmos as rtc0
[ 0.515129] rtc0: alarms up to one day, y3k, 114 bytes nvram
[ 0.516858] device-mapper: uevent: version 1.0.3
[ 0.518251] device-mapper: ioctl: 4.22.0-ioctl (2011-10-19) initialised: <email address hidden>
[ 0.520704] cpuidle: using governor ladder
[ 0.521912] cpuidle: using governor menu
[ 0.523087] EFI Variables Facility v0.08 2004-May-17
[ 0.524638] TCP cubic registered
[ 0.525677] NET: Registered protocol family 10
[ 0.527273] NET: Registered protocol family 17
[ 0.528506] Registering the dns_resolver key type
[ 0.529860] registered taskstats version 1
[ 0.533764] Magic number: 2:32:177
[ 0.534842] acpi device:0d: hash matches
[ 0.535960] rtc_cmos 00:01: setting system clock to 2018-05-02 12:11:08 UTC (1525263068)
[ 0.538147] BIOS EDD facility v0.16 2004-Jun-25, 0 devices found
[ 0.539552] EDD information not available.
[ 0.633124] ata1.00: ATA-7: QEMU HARDDISK, 2.5+, max UDMA/100
[ 0.635990] ata1.00: 20971520 sectors, multi 16: LBA48
[ 0.639292] ata1.00: configured for MWDMA2
[ 0.641539] scsi 0:0:0:0: Direct-Access ATA QEMU HARDDISK 2.5+ PQ: 0 ANSI: 5
[ 0.645733] sd 0:0:0:0: [sda] 20971520 512-byte logical blocks: (10.7 GB/10.0 GiB)
[ 0.649493] sd 0:0:0:0: Attached scsi generic sg0 type 0
[ 0.652057] sd 0:0:0:0: [sda] Write Protect is off
[ 0.654354] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 0.659117] sda: sda1
[ 0.660630] sd 0:0:0:0: [sda] Attached SCSI disk
[ 0.664470] Freeing unused kernel memory: 924k freed
[ 0.666842] Write protecting the kernel read-only data: 12288k
[ 0.674752] Freeing unused kernel memory: 1632k freed
[ 0.681118] Freeing unused kernel memory: 1200k freed
[ 0.699539] udevd[83]: starting version 175
[ 0.808052] usb 1-1: new full-speed USB device number 2 using uhci_hcd
[ 0.810919] FDC 0 is a S82078B
[ 0.879686] EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: (null)
[ 1.288636] EXT4-fs (sda1): re-mounted. Opts: (null)
[ 1.292084] Refined TSC clocksource calibration: 2200.079 MHz.
cloud-init start-local running: Wed, 02 May 2018 12:11:10 +0000. up 2.10 seconds
no instance data found in start-local
ci-info: lo : 1 127.0.0.1 255.0.0.0 .
ci-info: eth0 : 1 10.10.10.4 255.255.255.0 02:be:80:e7:cf:cd
ci-info: route-0: 0.0.0.0 10.10.10.1 0.0.0.0 eth0 UG
ci-info: route-1: 10.10.10.0 0.0.0.0 255.255.255.0 eth0 U
cloud-init start running: Wed, 02 May 2018 12:11:11 +0000. up 3.06 seconds
found data source: DataSourceEc2

2018-05-02 17:41:19,620 - DEBUG - VM <Server: ctest-TestPbbEvpnMacLearning-47403300-36041846> is in ACTIVE state now
2018-05-02 17:41:19,848 - DEBUG - VM ctest-TestPbbEvpnMacLearning-47403300-36041846 ID is da971d46-45d2-4545-8848-deeffce439b2
2018-05-02 17:41:19,848 - DEBUG - VM ctest-TestPbbEvpnMacLearning-47403300-36041846 launched on Node nodem9
2018-05-02 17:41:20,077 - DEBUG - Requesting: http://10.10.10.14:8082/virtual-machine/da971d46-45d2-4545-8848-deeffce439b2
2018-05-02 17:41:20,085 - DEBUG - Requesting: http://10.10.10.14:8082/virtual-machine-interface/be80e7cf-cd18-469f-94a5-8ca97eb9ee35
2018-05-02 17:41:21,275 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n64 bytes from 169.254.0.3: icmp_seq=1 ttl=63 time=0.483 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=0.180 ms\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 2 received, 0% packet loss, time 999ms\r\nrtt min/avg/max/mdev = 0.180/0.331/0.483/0.152 ms')
2018-05-02 17:41:21,275 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-TestPbbEvpnMacLearning-47403300-36041846 passed
2018-05-02 17:41:21,306 - DEBUG - Waiting to SSH to VM ctest-TestPbbEvpnMacLearning-47403300-36041846, IP 10.10.10.4, Port 22
2018-05-02 17:41:26,527 - DEBUG - VM ctest-TestPbbEvpnMacLearning-47403300-36041846 is ready for SSH connections
2018-05-02 17:41:26,527 - INFO - Waiting for VM ctest-TestPbbEvpnMacLearning-47403300-17874287 to be up..
2018-05-02 17:41:26,756 - DEBUG - VM <Server: ctest-TestPbbEvpnMacLearning-47403300-17874287> is in ACTIVE state now
2018-05-02 17:41:26,991 - DEBUG - VM ctest-TestPbbEvpnMacLearning-47403300-17874287 ID is 0b5d6857-72ef-40f1-8062-0be148ed0866
2018-05-02 17:41:26,991 - DEBUG - VM ctest-TestPbbEvpnMacLearning-47403300-17874287 launched on Node nodem10
2018-05-02 17:41:27,435 - DEBUG - Requesting: http://10.10.10.14:8082/virtual-machine/0b5d6857-72ef-40f1-8062-0be148ed0866
2018-05-02 17:41:27,445 - DEBUG - Requesting: http://10.10.10.14:8082/virtual-machine-interface/725d6ae5-583d-43d0-a115-ff855498c50b
2018-05-02 17:41:27,455 - DEBUG - Requesting: http://10.10.10.14:8082/virtual-machine/0b5d6857-72ef-40f1-8062-0be148ed0866
2018-05-02 17:41:27,462 - DEBUG - Requesting: http://10.10.10.14:8082/virtual-machine-interface/725d6ae5-583d-43d0-a115-ff855498c50b
2018-05-02 17:41:28,657 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n64 bytes from 169.254.0.3: icmp_seq=1 ttl=63 time=0.558 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=0.167 ms\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 2 received, 0% packet loss, time 1000ms\r\nrtt min/avg/max/mdev = 0.167/0.362/0.558/0.196 ms')
2018-05-02 17:41:28,658 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-TestPbbEvpnMacLearning-47403300-17874287 passed
2018-05-02 17:41:28,688 - DEBUG - Waiting to SSH to VM ctest-TestPbbEvpnMacLearning-47403300-17874287, IP 10.10.10.3, Port 22
2018-05-02 17:41:33,909 - DEBUG - VM ctest-TestPbbEvpnMacLearning-47403300-17874287 is ready for SSH connections
2018-05-02 17:41:34,851 - DEBUG - Running remote_cmd, Cmd : echo "10.10.10.4 ctest-TestPbbEvpnMacLearning-47403300-36041846" >> /etc/hosts, host_string: ubuntu@169.254.0.3, password: ubuntugateway: root@10.204.216.98, gateway password: c0ntrail123
2018-05-02 17:41:34,851 - DEBUG - echo "10.10.10.4 ctest-TestPbbEvpnMacLearning-47403300-36041846" >> /etc/hosts
2018-05-02 17:41:38,657 - DEBUG - None
2018-05-02 17:41:38,689 - DEBUG - Running remote_cmd, Cmd : echo "10.10.10.3 ctest-TestPbbEvpnMacLearning-47403300-17874287" >> /etc/hosts, host_string: ubuntu@169.254.0.3, password: ubuntugateway: root@10.204.216.99, gateway password: c0ntrail123
2018-05-02 17:41:38,690 - DEBUG - echo "10.10.10.3 ctest-TestPbbEvpnMacLearning-47403300-17874287" >> /etc/hosts
2018-05-02 17:41:42,754 - DEBUG - None
2018-05-02 17:41:42,754 - DEBUG - Updating PBB EVPN on VN default-domain:ctest-TestPbbEvpnMacLearning-47403300:vn2 to True
2018-05-02 17:41:42,803 - DEBUG - Requesting: http://10.10.10.14:8082/virtual-network/2ee88828-bdd6-4b2c-97eb-30f92f8219f7
2018-05-02 17:41:42,817 - DEBUG - Updating PBB etree on VN default-domain:ctest-TestPbbEvpnMacLearning-47403300:vn2 to False
2018-05-02 17:41:42,857 - DEBUG - Requesting: http://10.10.10.14:8082/virtual-network/2ee88828-bdd6-4b2c-97eb-30f92f8219f7
2018-05-02 17:41:42,907 - INFO - Setting flood_unknown_unicast flag of VN vn2 to True
2018-05-02 17:41:42,908 - DEBUG - Updating MAC Learning on VN default-domain:ctest-TestPbbEvpnMacLearning-47403300:vn2 to True
2018-05-02 17:41:42,943 - DEBUG - Requesting: http://10.10.10.14:8082/virtual-network/2ee88828-bdd6-4b2c-97eb-30f92f8219f7
2018-05-02 17:41:42,953 - DEBUG - Updating MAC Limit control on VN default-domain:ctest-TestPbbEvpnMacLearning-47403300:vn2 to mac_limit = 1024, mac_limit_action = log
2018-05-02 17:41:42,986 - DEBUG - Requesting: http://10.10.10.14:8082/virtual-network/2ee88828-bdd6-4b2c-97eb-30f92f8219f7
2018-05-02 17:41:42,996 - DEBUG - Updating MAC Move on VN default-domain:ctest-TestPbbEvpnMacLearning-47403300:vn2 to mac_move_limit = 1024, mac_move_time_window = 30, mac_move_limit_action = log
2018-05-02 17:41:43,031 - DEBUG - Requesting: http://10.10.10.14:8082/virtual-network/2ee88828-bdd6-4b2c-97eb-30f92f8219f7
2018-05-02 17:41:43,042 - DEBUG - Updating MAC Aging on VN default-domain:ctest-TestPbbEvpnMacLearning-47403300:vn2 to 300
2018-05-02 17:41:43,075 - DEBUG - Requesting: http://10.10.10.14:8082/virtual-network/2ee88828-bdd6-4b2c-97eb-30f92f8219f7
2018-05-02 17:41:43,087 - DEBUG - Updating PBB EVPN on VN default-domain:ctest-TestPbbEvpnMacLearning-47403300:vn1 to True
2018-05-02 17:41:43,119 - DEBUG - Requesting: http://10.10.10.14:8082/virtual-network/d1e81bb7-b0de-4f2a-9628-343cb907b4e7
2018-05-02 17:41:43,130 - DEBUG - Updating PBB etree on VN default-domain:ctest-TestPbbEvpnMacLearning-47403300:vn1 to False
2018-05-02 17:41:43,163 - DEBUG - Requesting: http://10.10.10.14:8082/virtual-network/d1e81bb7-b0de-4f2a-9628-343cb907b4e7
2018-05-02 17:41:43,209 - INFO - Setting flood_unknown_unicast flag of VN vn1 to True
2018-05-02 17:41:43,209 - DEBUG - Updating MAC Learning on VN default-domain:ctest-TestPbbEvpnMacLearning-47403300:vn1 to True
2018-05-02 17:41:43,242 - DEBUG - Requesting: http://10.10.10.14:8082/virtual-network/d1e81bb7-b0de-4f2a-9628-343cb907b4e7
2018-05-02 17:41:43,253 - DEBUG - Updating MAC Limit control on VN default-domain:ctest-TestPbbEvpnMacLearning-47403300:vn1 to mac_limit = 1024, mac_limit_action = log
2018-05-02 17:41:43,286 - DEBUG - Requesting: http://10.10.10.14:8082/virtual-network/d1e81bb7-b0de-4f2a-9628-343cb907b4e7
2018-05-02 17:41:43,298 - DEBUG - Updating MAC Move on VN default-domain:ctest-TestPbbEvpnMacLearning-47403300:vn1 to mac_move_limit = 1024, mac_move_time_window = 30, mac_move_limit_action = log
2018-05-02 17:41:43,459 - DEBUG - Requesting: http://10.10.10.14:8082/virtual-network/d1e81bb7-b0de-4f2a-9628-343cb907b4e7
2018-05-02 17:41:43,472 - DEBUG - Updating MAC Aging on VN default-domain:ctest-TestPbbEvpnMacLearning-47403300:vn1 to 300
2018-05-02 17:41:43,507 - DEBUG - Requesting: http://10.10.10.14:8082/virtual-network/d1e81bb7-b0de-4f2a-9628-343cb907b4e7
2018-05-02 17:41:43,518 - INFO - Adding Bridge Domain 4e8848e7-e60e-44ec-8467-30a597a332f9 to VMI b7122551-f808-475d-a2ae-25ba9e454316
2018-05-02 17:41:43,560 - INFO - Verification for Bridge Domain uuid 4e8848e7-e60e-44ec-8467-30a597a332f9 for VMI b7122551-f808-475d-a2ae-25ba9e454316 passed in agent 10.204.216.99
2018-05-02 17:41:43,598 - INFO - Verifications in Agent 10.204.216.99 for BD ctest-bd_ctest-TestPbbEvpnMacLearning-47403300-97907153 for VN info passed
2018-05-02 17:41:43,599 - INFO - Adding Bridge Domain 4e8848e7-e60e-44ec-8467-30a597a332f9 to VMI 7986802a-d7de-43c3-9c3e-b0d722f2bcd3
2018-05-02 17:41:43,650 - INFO - Verification for Bridge Domain uuid 4e8848e7-e60e-44ec-8467-30a597a332f9 for VMI 7986802a-d7de-43c3-9c3e-b0d722f2bcd3 passed in agent 10.204.216.98
2018-05-02 17:41:43,680 - INFO - Verifications in Agent 10.204.216.98 for BD ctest-bd_ctest-TestPbbEvpnMacLearning-47403300-97907153 for VN info passed
2018-05-02 17:41:43,826 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 2 -W 1 10.10.10.3, host_string: ubuntu@169.254.0.3, password: ubuntugateway: root@10.204.216.98, gateway password: c0ntrail123
2018-05-02 17:41:43,826 - DEBUG - ping -s 56 -c 2 -W 1 10.10.10.3
2018-05-02 17:41:55,439 - DEBUG - PING 10.10.10.3 (10.10.10.3) 56(84) bytes of data.
64 bytes from 10.10.10.3: icmp_req=1 ttl=64 time=1.69 ms
64 bytes from 10.10.10.3: icmp_req=2 ttl=64 time=0.636 ms

--- 10.10.10.3 ping statistics ---
2 packets transmitted, 2 received, 0% packet loss, time 1001ms
rtt min/avg/max/mdev = 0.636/1.164/1.692/0.528 ms
2018-05-02 17:41:55,440 - INFO - Ping to IP 10.10.10.3 from VM ctest-TestPbbEvpnMacLearning-47403300-36041846 passed
2018-05-02 17:41:55,479 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 2 -W 1 10.10.10.4, host_string: ubuntu@169.254.0.3, password: ubuntugateway: root@10.204.216.98, gateway password: c0ntrail123
2018-05-02 17:41:55,479 - DEBUG - ping -s 56 -c 2 -W 1 10.10.10.4
2018-05-02 17:42:07,092 - DEBUG - PING 10.10.10.4 (10.10.10.4) 56(84) bytes of data.
64 bytes from 10.10.10.4: icmp_req=1 ttl=64 time=0.028 ms
64 bytes from 10.10.10.4: icmp_req=2 ttl=64 time=0.019 ms

--- 10.10.10.4 ping statistics ---
2 packets transmitted, 2 received, 0% packet loss, time 999ms
rtt min/avg/max/mdev = 0.019/0.023/0.028/0.006 ms
2018-05-02 17:42:07,093 - INFO - Ping to IP 10.10.10.4 from VM ctest-TestPbbEvpnMacLearning-47403300-36041846 passed
2018-05-02 17:42:07,132 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 2 -W 1 1.1.1.3, host_string: ubuntu@169.254.0.3, password: ubuntugateway: root@10.204.216.98, gateway password: c0ntrail123
2018-05-02 17:42:07,132 - DEBUG - ping -s 56 -c 2 -W 1 1.1.1.3
2018-05-02 17:42:19,822 - DEBUG - PING 1.1.1.3 (1.1.1.3) 56(84) bytes of data.

--- 1.1.1.3 ping statistics ---
2 packets transmitted, 0 received, 100% packet loss, time 999ms
2018-05-02 17:42:19,822 - WARNING - Ping to IP 1.1.1.3 from VM ctest-TestPbbEvpnMacLearning-47403300-36041846 failed
2018-05-02 17:42:20,945 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 2 -W 1 1.1.1.3, host_string: ubuntu@169.254.0.3, password: ubuntugateway: root@10.204.216.98, gateway password: c0ntrail123
2018-05-02 17:42:20,946 - DEBUG - ping -s 56 -c 2 -W 1 1.1.1.3
2018-05-02 17:42:33,630 - DEBUG - PING 1.1.1.3 (1.1.1.3) 56(84) bytes of data.

--- 1.1.1.3 ping statistics ---
2 packets transmitted, 0 received, 100% packet loss, time 1006ms
2018-05-02 17:42:33,630 - WARNING - Ping to IP 1.1.1.3 from VM ctest-TestPbbEvpnMacLearning-47403300-36041846 failed
2018-05-02 17:42:34,754 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 2 -W 1 1.1.1.3, host_string: ubuntu@169.254.0.3, password: ubuntugateway: root@10.204.216.98, gateway password: c0ntrail123
2018-05-02 17:42:34,754 - DEBUG - ping -s 56 -c 2 -W 1 1.1.1.3
2018-05-02 17:42:47,441 - DEBUG - PING 1.1.1.3 (1.1.1.3) 56(84) bytes of data.

--- 1.1.1.3 ping statistics ---
2 packets transmitted, 0 received, 100% packet loss, time 999ms
2018-05-02 17:42:47,441 - WARNING - Ping to IP 1.1.1.3 from VM ctest-TestPbbEvpnMacLearning-47403300-36041846 failed
2018-05-02 17:42:48,588 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 2 -W 1 1.1.1.3, host_string: ubuntu@169.254.0.3, password: ubuntugateway: root@10.204.216.98, gateway password: c0ntrail123
2018-05-02 17:42:48,588 - DEBUG - ping -s 56 -c 2 -W 1 1.1.1.3
2018-05-02 17:43:01,353 - DEBUG - PING 1.1.1.3 (1.1.1.3) 56(84) bytes of data.

--- 1.1.1.3 ping statistics ---
2 packets transmitted, 0 received, 100% packet loss, time 1008ms
2018-05-02 17:43:01,353 - WARNING - Ping to IP 1.1.1.3 from VM ctest-TestPbbEvpnMacLearning-47403300-36041846 failed
2018-05-02 17:43:02,472 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 2 -W 1 1.1.1.3, host_string: ubuntu@169.254.0.3, password: ubuntugateway: root@10.204.216.98, gateway password: c0ntrail123
2018-05-02 17:43:02,472 - DEBUG - ping -s 56 -c 2 -W 1 1.1.1.3
2018-05-02 17:43:15,142 - DEBUG - PING 1.1.1.3 (1.1.1.3) 56(84) bytes of data.

--- 1.1.1.3 ping statistics ---
2 packets transmitted, 0 received, 100% packet loss, time 1007ms
2018-05-02 17:43:15,143 - WARNING - Ping to IP 1.1.1.3 from VM ctest-TestPbbEvpnMacLearning-47403300-36041846 failed
2018-05-02 17:43:16,258 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 2 -W 1 1.1.1.3, host_string: ubuntu@169.254.0.3, password: ubuntugateway: root@10.204.216.98, gateway password: c0ntrail123
2018-05-02 17:43:16,259 - DEBUG - ping -s 56 -c 2 -W 1 1.1.1.3
2018-05-02 17:43:28,989 - DEBUG - PING 1.1.1.3 (1.1.1.3) 56(84) bytes of data.

--- 1.1.1.3 ping statistics ---
2 packets transmitted, 0 received, 100% packet loss, time 999ms
2018-05-02 17:43:28,990 - WARNING - Ping to IP 1.1.1.3 from VM ctest-TestPbbEvpnMacLearning-47403300-36041846 failed
2018-05-02 17:43:30,137 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 2 -W 1 1.1.1.3, host_string: ubuntu@169.254.0.3, password: ubuntugateway: root@10.204.216.98, gateway password: c0ntrail123
2018-05-02 17:43:30,137 - DEBUG - ping -s 56 -c 2 -W 1 1.1.1.3
2018-05-02 17:43:42,798 - DEBUG - PING 1.1.1.3 (1.1.1.3) 56(84) bytes of data.

--- 1.1.1.3 ping statistics ---
2 packets transmitted, 0 received, 100% packet loss, time 1000ms
2018-05-02 17:43:42,798 - WARNING - Ping to IP 1.1.1.3 from VM ctest-TestPbbEvpnMacLearning-47403300-36041846 failed
2018-05-02 17:43:43,945 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 2 -W 1 1.1.1.3, host_string: ubuntu@169.254.0.3, password: ubuntugateway: root@10.204.216.98, gateway password: c0ntrail123
2018-05-02 17:43:43,945 - DEBUG - ping -s 56 -c 2 -W 1 1.1.1.3
2018-05-02 17:43:56,661 - DEBUG - PING 1.1.1.3 (1.1.1.3) 56(84) bytes of data.

--- 1.1.1.3 ping statistics ---
2 packets transmitted, 0 received, 100% packet loss, time 1007ms
2018-05-02 17:43:56,661 - WARNING - Ping to IP 1.1.1.3 from VM ctest-TestPbbEvpnMacLearning-47403300-36041846 failed
2018-05-02 17:43:57,808 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 2 -W 1 1.1.1.3, host_string: ubuntu@169.254.0.3, password: ubuntugateway: root@10.204.216.98, gateway password: c0ntrail123
2018-05-02 17:43:57,808 - DEBUG - ping -s 56 -c 2 -W 1 1.1.1.3
2018-05-02 17:44:10,546 - DEBUG - PING 1.1.1.3 (1.1.1.3) 56(84) bytes of data.

--- 1.1.1.3 ping statistics ---
2 packets transmitted, 0 received, 100% packet loss, time 1006ms
2018-05-02 17:44:10,546 - WARNING - Ping to IP 1.1.1.3 from VM ctest-TestPbbEvpnMacLearning-47403300-36041846 failed
2018-05-02 17:44:11,665 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 2 -W 1 1.1.1.3, host_string: ubuntu@169.254.0.3, password: ubuntugateway: root@10.204.216.98, gateway password: c0ntrail123
2018-05-02 17:44:11,665 - DEBUG - ping -s 56 -c 2 -W 1 1.1.1.3
2018-05-02 17:44:24,279 - DEBUG - PING 1.1.1.3 (1.1.1.3) 56(84) bytes of data.

--- 1.1.1.3 ping statistics ---
2 packets transmitted, 0 received, 100% packet loss, time 1000ms
2018-05-02 17:44:24,279 - WARNING - Ping to IP 1.1.1.3 from VM ctest-TestPbbEvpnMacLearning-47403300-36041846 failed
2018-05-02 17:44:25,397 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 2 -W 1 1.1.1.3, host_string: ubuntu@169.254.0.3, password: ubuntugateway: root@10.204.216.98, gateway password: c0ntrail123
2018-05-02 17:44:25,398 - DEBUG - ping -s 56 -c 2 -W 1 1.1.1.3
2018-05-02 17:44:38,114 - DEBUG - PING 1.1.1.3 (1.1.1.3) 56(84) bytes of data.

--- 1.1.1.3 ping statistics ---
2 packets transmitted, 0 received, 100% packet loss, time 1007ms
2018-05-02 17:44:38,114 - WARNING - Ping to IP 1.1.1.3 from VM ctest-TestPbbEvpnMacLearning-47403300-36041846 failed
2018-05-02 17:44:38,118 - INFO - Detaching port be80e7cf-cd18-469f-94a5-8ca97eb9ee35 from VM ctest-TestPbbEvpnMacLearning-47403300-36041846
2018-05-02 17:44:38,222 - INFO - Deleting VM ctest-TestPbbEvpnMacLearning-47403300-36041846
2018-05-02 17:44:38,459 - INFO - Detaching port 725d6ae5-583d-43d0-a115-ff855498c50b from VM ctest-TestPbbEvpnMacLearning-47403300-17874287
2018-05-02 17:44:38,586 - INFO - Deleting VM ctest-TestPbbEvpnMacLearning-47403300-17874287
2018-05-02 17:44:38,952 - INFO - Deleted port 7986802a-d7de-43c3-9c3e-b0d722f2bcd3
2018-05-02 17:44:39,118 - INFO - Deleted port b7122551-f808-475d-a2ae-25ba9e454316
2018-05-02 17:44:39,248 - DEBUG - Response for delete_port : ()
2018-05-02 17:44:39,248 - INFO - Deleted port be80e7cf-cd18-469f-94a5-8ca97eb9ee35
2018-05-02 17:44:39,467 - DEBUG - Response for delete_port : ()
2018-05-02 17:44:39,467 - INFO - Deleted port 725d6ae5-583d-43d0-a115-ff855498c50b
2018-05-02 17:44:39,490 - INFO - Deleted Bridge Domain 4e8848e7-e60e-44ec-8467-30a597a332f9
2018-05-02 17:44:39,494 - INFO - Bridge Domain ctest-bd_ctest-TestPbbEvpnMacLearning-47403300-97907153 is removed from Agent 10.204.216.99
2018-05-02 17:44:39,499 - INFO - Bridge Domain ctest-bd_ctest-TestPbbEvpnMacLearning-47403300-97907153 is removed from Agent 10.204.216.98
2018-05-02 17:44:39,503 - INFO - Bridge Domain ctest-bd_ctest-TestPbbEvpnMacLearning-47403300-97907153 is removed from Agent 10.204.216.97
2018-05-02 17:44:39,504 - DEBUG - Deleting RT for VN vn2
2018-05-02 17:44:39,553 - INFO - Deleting VN vn2
2018-05-02 17:44:39,669 - DEBUG - Response for deleting network ()
2018-05-02 17:44:39,670 - INFO - Deleting VN vn1
2018-05-02 17:44:39,777 - DEBUG - Response for deleting network ()
2018-05-02 17:44:46,353 - ERROR - <type 'exceptions.AssertionError'>
Python 2.7.5: /usr/bin/python
Wed May 2 17:44:38 2018

A problem occurred in a Python script. Here is the sequence of
function calls leading up to the error, in the order they occurred.

 /contrail-test/tcutils/wrappers.py in wrapper(self=<serial_scripts.pbb_evpn.test_pbb_evpn.TestPbbEv...bIntf_single_isid[cb_sanity,sanity] id=0x75634d0>, *args=(), **kwargs={})
   76 log.info('Initial checks done. Running the testcase now')
   77 log.info('')
   78 result = function(self, *args, **kwargs)
   79 except KeyboardInterrupt:
   80 raise
result = None
function = <function test_mac_learning_subIntf_single_isid>
self = <serial_scripts.pbb_evpn.test_pbb_evpn.TestPbbEv...bIntf_single_isid[cb_sanity,sanity] id=0x75634d0>
args = ()
kwargs = {}

 /contrail-test/serial_scripts/pbb_evpn/test_pbb_evpn.py in test_mac_learning_subIntf_single_isid(self=<serial_scripts.pbb_evpn.test_pbb_evpn.TestPbbEv...bIntf_single_isid[cb_sanity,sanity] id=0x75634d0>)
  124 except Exception as e:
  125 vmi_ip = vmi_fixture.obj['fixed_ips'][1]['ip_address']
  126 assert src_vm_fixture.ping_with_certainty(vmi_ip, count=2)
  127
  128 # Send Traffic
src_vm_fixture = <VMFixture: ctest-TestPbbEvpnMacLearning-47403300-36041846>
src_vm_fixture.ping_with_certainty = <bound method VMFixture.f_retry of <VMFixture: ctest-TestPbbEvpnMacLearning-47403300-36041846>>
vmi_ip = u'1.1.1.3'
count undefined
<type 'exceptions.AssertionError'>:
    __class__ = <type 'exceptions.AssertionError'>
    __delattr__ = <method-wrapper '__delattr__' of exceptions.AssertionError object>
    __dict__ = {}
    __doc__ = 'Assertion failed.'
    __format__ = <built-in method __format__ of exceptions.AssertionError object>
    __getattribute__ = <method-wrapper '__getattribute__' of exceptions.AssertionError object>
    __getitem__ = <method-wrapper '__getitem__' of exceptions.AssertionError object>
    __getslice__ = <method-wrapper '__getslice__' of exceptions.AssertionError object>
    __hash__ = <method-wrapper '__hash__' of exceptions.AssertionError object>
    __init__ = <method-wrapper '__init__' of exceptions.AssertionError object>
    __new__ = <built-in method __new__ of type object>
    __reduce__ = <built-in method __reduce__ of exceptions.AssertionError object>
    __reduce_ex__ = <built-in method __reduce_ex__ of exceptions.AssertionError object>
    __repr__ = <method-wrapper '__repr__' of exceptions.AssertionError object>
    __setattr__ = <method-wrapper '__setattr__' of exceptions.AssertionError object>
    __setstate__ = <built-in method __setstate__ of exceptions.AssertionError object>
    __sizeof__ = <built-in method __sizeof__ of exceptions.AssertionError object>
    __str__ = <method-wrapper '__str__' of exceptions.AssertionError object>
    __subclasshook__ = <built-in method __subclasshook__ of type object>
    __unicode__ = <built-in method __unicode__ of exceptions.AssertionError object>
    args = ()
    message = ''

The above is a description of an error in a Python program. Here is
the original traceback:

Traceback (most recent call last):
  File "tcutils/wrappers.py", line 78, in wrapper
    result = function(self, *args, **kwargs)
  File "serial_scripts/pbb_evpn/test_pbb_evpn.py", line 126, in test_mac_learning_subIntf_single_isid
    assert src_vm_fixture.ping_with_certainty(vmi_ip, count=2)
AssertionError

2018-05-02 17:44:46,355 - DEBUG - Skipping xmpp flap check
2018-05-02 17:44:46,355 - INFO -
2018-05-02 17:44:46,355 - INFO - END TEST : test_mac_learning_subIntf_single_isid : FAILED[0:03:57]
2018-05-02 17:44:46,355 - INFO - --------------------------------------------------------------------------------
2018-05-02 17:44:46,820 - INFO - Deleted project: ctest-TestPbbEvpnMacLearning-47403300, ID : ea721f84-f660-4db2-8fd2-c6f139dd8576

[OpenContrail Admin (ci-admin-f)]

Review in progress for https://review.opencontrail.org/42724
Submitter: Chandra Sekhar Reddy Mallam (<email address hidden>)

[OpenContrail Admin (ci-admin-f)]

Review in progress for https://review.opencontrail.org/42747
Submitter: Chandra Sekhar Reddy Mallam (<email address hidden>)

[OpenContrail Admin (ci-admin-f)]

Reviewed: https://review.opencontrail.org/42724
Committed: http://github.com/Juniper/contrail-test/commit/6feb4a082fb1cf191f64720caaf003281a3a94e1
Submitter: Zuul v3 CI (<email address hidden>)
Branch: master

commit 6feb4a082fb1cf191f64720caaf003281a3a94e1
Author: Mallam Chandra Sekhar Reddy <email address hidden>
Date: Thu May 3 14:38:24 2018 +0530

Adding extra check before pinging sub-interfaces

Adding extra check to verify whether vlan sub-interfaces are
created properly or not before pinging vlan sub interfaces.

Also, enabling single isid test as sanity instead of vlan
sub interfaces isid test

Change-Id: Id6cc49b07dfa418ec72f8af58fc029ddd23dd8cc
Closes-Bug: #1768729

[OpenContrail Admin (ci-admin-f)]

Reviewed: https://review.opencontrail.org/42747
Committed: http://github.com/Juniper/contrail-test/commit/7301c8d88950c117bed746a32e94b4fcc696696e
Submitter: Zuul v3 CI (<email address hidden>)
Branch: R5.0

commit 7301c8d88950c117bed746a32e94b4fcc696696e
Author: Mallam Chandra Sekhar Reddy <email address hidden>
Date: Thu May 3 14:38:24 2018 +0530

Adding extra check before pinging sub-interfaces

Adding extra check to verify whether vlan sub-interfaces are
created properly or not before pinging vlan sub interfaces.

Also, enabling single isid test as sanity instead of vlan
sub interfaces isid test

Change-Id: Id6cc49b07dfa418ec72f8af58fc029ddd23dd8cc
Closes-Bug: #1768729