Running 'tbprerun -e 167 xen5vnode.ns'
Beginning pre run for testbed/xen5vnode. 08:12:47:763570
Running parser ... 08:12:48:016391
Parser done! 08:12:50:971132
Precomputing visualization ...
Image rendering proceeding in background mode ...
Setting up static routes (if requested) ...
Generating topomap ...
Doing a pre-assign: '/usr/testbed/bin/vtopgen -p testbed xen5vnode' ...
Checking for feature LibVtopTest.
Minimum nodes = 0
Maximum nodes = 0
Virtual nodes = 5
Writing environment strings ...
Setting up additional program agent support ...
Setting up additional network agent support ...
Writing program agent info ...
Pre run finished. 08:12:53:147389
Running 'tbswap in testbed xen5vnode'
Beginning swap-in for testbed/xen5vnode (167). 03/15/2019 08:12:53
TIMESTAMP: 08:12:53:558598 tbswap in started
Checking for feature SyncVlans.
Checking with Admission Control ...
Checking for feature ExternalNodeManagement.
Allocating public addresses...
Mapping to physical reality ...
TIMESTAMP: 08:12:53:958558 mapper wrapper started
Checking for feature OldMapper.
Checking for feature NewAssign.
Checking for feature ControlNetVlans.
Checking for feature LibVtopTest.
Starting the new and improved mapper wrapper.
Minimum nodes = 0
Maximum nodes = 0
Virtual nodes = 5
Clearing physical state before updating.
Mapper loop 1
ptopargs: '-p testbed -e xen5vnode -v '
assign command: 'assign -uod -c .75 -H 3 -P -f text testbed-xen5vnode-2877.ptop testbed-xen5vnode-2877.vtop'
Reading assign results.
pc10
pc2
TIMESTAMP: 08:12:58:129747 mapper wrapper finished
Mapped to physical reality!
Fetching tarballs and RPMs (if any) ...
TIMESTAMP: 08:12:58:134776 tarfiles_setup started
TIMESTAMP: 08:12:58:534943 tarfiles_setup finished
Creating dynamic blobs.
Locking down arp entries
TIMESTAMP: 08:12:58:621181 arplockdown started
TIMESTAMP: 08:12:58:801740 arplockdown finished
Setting up mountpoints.
TIMESTAMP: 08:12:58:803390 mountpoints started
TIMESTAMP: 08:13:01:271937 mountpoints finished
TIMESTAMP: 08:13:01:273085 named started
Setting up named maps.
TIMESTAMP: 08:13:01:632644 named finished
TIMESTAMP: 08:13:01:634469 gentopofile started
Generating ltmap (again) ...
TIMESTAMP: 08:13:01:998186 gentopofile finished
getTrunksForVlan: 5507: huawei2
mapVlansToSwitches: huawei2
Resetting OS and rebooting.
TIMESTAMP: 08:13:03:954719 launching os_setup
Checking for feature OldOsSetup.
Setting up VLANs.
TIMESTAMP: 08:13:03:959593 snmpit started
TIMESTAMP: 08:13:04:398135 os_setup started
Adding pcvm2-1 to type object pcvm
pcvm2-1 - [OS 10015:0 emulab-ops,UBUNTU14-64-STD]
osload: Using [Image 10015:0 emulab-ops,UBUNTU14-64-STD] for pcvm2-1
osload (pcvm2-1): Changing default OS to [OS 10015:0 emulab-ops,UBUNTU14-64-STD]
Setting up reload for pcvm2-1 (mode: Frisbee)
TIMESTAMP: 08:13:04:480918 osload: database setup done
osload: Done! There were 0 failures.
Adding pcvm2-2 to type object pcvm
pcvm2-2 - [OS 10018:0 emulab-ops,FBSD102-64-STD]
osload: Using [Image 10018:0 emulab-ops,FBSD102-64-STD] for pcvm2-2
osload (pcvm2-2): Changing default OS to [OS 10018:0 emulab-ops,FBSD102-64-STD]
Setting up reload for pcvm2-2 (mode: Frisbee)
TIMESTAMP: 08:13:04:500539 osload: database setup done
osload: Done! There were 0 failures.
Adding pcvm2-3 to type object pcvm
pcvm2-3 - [OS 10016:0 emulab-ops,CENTOS71-64-STD]
osload: Using [Image 10016:0 emulab-ops,CENTOS71-64-STD] for pcvm2-3
osload (pcvm2-3): Changing default OS to [OS 10016:0 emulab-ops,CENTOS71-64-STD]
Setting up reload for pcvm2-3 (mode: Frisbee)
TIMESTAMP: 08:13:04:519272 osload: database setup done
osload: Done! There were 0 failures.
Adding pcvm10-1 to type object pcvm
pcvm10-1 - [OS 10015:0 emulab-ops,UBUNTU14-64-STD]
osload: Using [Image 10015:0 emulab-ops,UBUNTU14-64-STD] for pcvm10-1
osload (pcvm10-1): Changing default OS to [OS 10015:0 emulab-ops,UBUNTU14-64-STD]
Setting up reload for pcvm10-1 (mode: Frisbee)
TIMESTAMP: 08:13:04:537828 osload: database setup done
osload: Done! There were 0 failures.
Adding pcvm2-4 to type object pcvm
pcvm2-4 - [OS 10015:0 emulab-ops,UBUNTU14-64-STD]
osload: Using [Image 10015:0 emulab-ops,UBUNTU14-64-STD] for pcvm2-4
osload (pcvm2-4): Changing default OS to [OS 10015:0 emulab-ops,UBUNTU14-64-STD]
Setting up reload for pcvm2-4 (mode: Frisbee)
TIMESTAMP: 08:13:04:556590 osload: database setup done
osload: Done! There were 0 failures.
Adding pc10 to type object pc
pc10 - [OS 10021:0 emulab-ops,XEN44-64-STD]
Adding pc2 to type object pc
pc2 - [OS 10021:0 emulab-ops,XEN44-64-STD]
Asking [pcvm] for volunteers
Skipping pcvm2-2 this time around
Skipping pcvm2-3 this time around
Skipping pcvm2-1 this time around
Skipping pcvm10-1 this time around
Skipping pcvm2-4 this time around
Asking [pc] for volunteers
[pc] returns volunteers: [Node: pc2] [Node: pc10]
Lighting up nodes in parallel ...
getTrunksForVlan: 5507: huawei2
mapVlansToSwitches: huawei2
Enabling equal trunking (tagging) on pc2:2.1
Enabling equal trunking (tagging) on pc10:3.1
Creating VLAN 5507 as VLAN #21 on stack Experiment ...
Creating VLAN 21 desc 5507 on huawei2 ...
Lighting up nodes: [Node: pc2] [Node: pc10]
pc2 will be reloaded with [Image 10021:0 emulab-ops,XEN44-64-STD]
pc10 will be reloaded with [Image 10021:0 emulab-ops,XEN44-64-STD]
osload: Using [Image 10021:0 emulab-ops,XEN44-64-STD] for pc10
osload (pc10): Changing default OS to [OS 10021:0 emulab-ops,XEN44-64-STD]
Setting up reload for pc10 (mode: Frisbee)
osload: Using [Image 10021:0 emulab-ops,XEN44-64-STD] for pc2
osload (pc2): Changing default OS to [OS 10021:0 emulab-ops,XEN44-64-STD]
Setting up reload for pc2 (mode: Frisbee)
TIMESTAMP: 08:13:05:699872 osload: database setup done
osload: Issuing reboot for pc10 pc2 and then waiting ...
TIMESTAMP: 08:13:05:702261 osload: event handler enabled
reboot: no privs; invoking real nodereboot script!
getTrunksForVlan: 5507: huawei2
Succeeded
reboot: Running in pipemode (27).
BATCH: rebooting pc10 pc2
reboot (pc10): Attempting to reboot ...
pc10: in PXEWAIT, sending PXEWAKEUP
reboot (pc2): Attempting to reboot ...
pc2: in PXEWAIT, sending PXEWAKEUP
reboot (pc10): Successful!
reboot (pc2): Successful!
reboot: Done. There were 0 failures.
reboot (pc2): child returned 0 status.
reboot (pc10): child returned 0 status.
Waiting for pc10 pc2 to finish reloading
Fri Mar 15 08:13:06 CST 2019
TIMESTAMP: 08:13:06:056263 osload: starting reload-done wait
*** ERROR: tbswap: Failed to set up VLANs.
Cleaning up after errors.
Waiting for os_setup to finish
osload: eventhandler: pc2 => RELOADSETUP @ 1552608821
got 1 events
osload: eventhandler: pc10 => RELOADSETUP @ 1552608826
osload: eventhandler: pc2 => RELOADING @ 1552608826
got 2 events
osload: eventhandler: pc10 => RELOADING @ 1552608831
got 1 events
osload (pc10): still waiting; it has been 1 minute(s)
osload (pc10): still waiting; it has been 2 minute(s)
osload (pc10): left reloading mode at Fri Mar 15 08:15:36 CST 2019
osload (pc2): left reloading mode at Fri Mar 15 08:15:36 CST 2019
osload: Done! There were 0 failures.
reload (pc2): child returned 0 status.
reload (pc10): child returned 0 status.
Waiting for nodes ...
*** os_setup: Still waiting for pc2 (BOOTING) - it's been 1 minute(s).
pc2 has reported state ISUP
pc2 is alive and well
pc10 has reported state ISUP
pc10 is alive and well
Asking [pcvm] for volunteers
pcvm2-2 will boot up with pc2
pcvm2-3 will boot up with pc2
pcvm2-1 will boot up with pc2
pcvm10-1 will boot up with pc10
pcvm2-4 will boot up with pc2
[pcvm] returns volunteers: [Node: pcvm2-2] [Node: pcvm2-3] [Node: pcvm2-1] [Node: pcvm10-1] [Node: pcvm2-4]
Asking [pc] for volunteers
Lighting up nodes in parallel ...
Lighting up nodes: [Node: pcvm2-2] [Node: pcvm2-3] [Node: pcvm2-1] [Node: pcvm10-1] [Node: pcvm2-4]
*** os_setup: Setting up virtual testbed nodes ...
TIMESTAMP: 08:17:43:146713 vnode_setup starting
pcvm2-2 is already setting up on local node pc2
pcvm2-3 is already setting up on local node pc2
pcvm2-1 is already setting up on local node pc2
pcvm10-1 is already setting up on local node pc10
pcvm2-4 is already setting up on local node pc2
vnode_setup running at parallelization: 10 wait_time: 3000
Vnode setup initiated on all nodes ...
TIMESTAMP: 08:17:44:459606 vnode_setup done
Waiting for nodes ...
*** os_setup: Still waiting for pcvm2-2 (RELOADING) - it's been 1 minute(s).
*** os_setup: Still waiting for pcvm2-2 (RELOADING) - it's been 2 minute(s).
*** os_setup: Still waiting for pcvm2-2 (RELOADING) - it's been 3 minute(s).
pcvm10-1 has reported state ISUP
pcvm10-1 is alive and well
*** os_setup: Still waiting for pcvm2-2 (RELOADING) - it's been 4 minute(s).
*** os_setup: Still waiting for pcvm2-2 (BOOTING) - it's been 5 minute(s).
pcvm2-2 has reported state ISUP
pcvm2-2 is alive and well
*** os_setup: Still waiting for pcvm2-3 (RELOADING) - it's been 6 minute(s).
pcvm2-1 has reported state ISUP
pcvm2-1 is alive and well
pcvm2-4 has reported state ISUP
pcvm2-4 is alive and well
*** os_setup: Still waiting for pcvm2-3 (BOOTING) - it's been 7 minute(s).
pcvm2-3 has reported state ISUP
pcvm2-3 is alive and well
Asking [pcvm] for volunteers
Asking [pc] for volunteers
No virt info for node pc10 (vhost-0)
No virt info for node pc2 (vhost-1)
TIMESTAMP: 08:25:26:608071 os_setup finished
Stopping the event system
Checking for feature NewEventScheduler.
Closing TCP proxy ports...
Releasing public address pools...
TIMESTAMP: 08:25:28:315508 snmpit started
Removing VLANs.
getTrunksForVlan: 5507: huawei2
mapVlansToSwitches: huawei2
Disabling trunking (tagging) on port pc10:3.1 ...
Disabling trunking (tagging) on port pc2:2.1 ...
*** ERROR: tbswap: Failed to reset VLANs
TIMESTAMP: 08:25:30:569717 snmpit finished
Removing stale vlans 5507
Using internal experiment emulab-ops/vlan-holding for operations
getTrunksForVlan: 5507: huawei2
mapVlansToSwitches: huawei2
Deleting VLAN [VLan 5507:21: testbed/xen5vnode/link2] from [Stack Experiment] ...
getExperimentTrunksForVlan: 5507: huawei2
Removing VLAN # 21 ... Removed VLAN 21 on switch huawei2.
VLAN deletion on [Stack Experiment] succeeded.
Removing dynamic blobs.
Clearing shared port vlans.
Tearing down virtual nodes.
TIMESTAMP: 08:25:32:433763 vnode_setup -k started
pcvm2-1 will teardown with local node pc2.
pcvm2-2 will teardown with local node pc2.
pcvm2-3 will teardown with local node pc2.
pcvm10-1 will teardown with local node pc10.
pcvm2-4 will teardown with local node pc2.
vnode_setup running at parallelization: 10 wait_time: 3000
Vnode teardown finished.
TIMESTAMP: 08:25:33:738951 vnode_setup finished
Removing logical wires.
Freeing nodes.
TIMESTAMP: 08:25:33:741921 nfree started
Releasing all nodes from experiment [Experiment: testbed/xen5vnode].
Moving [Node: pc10] to [Experiment: emulab-ops/reloadpending]
Moving [Node: pc2] to [Experiment: emulab-ops/reloadpending]
TIMESTAMP: 08:25:34:445431 nfree finished
Resetting DB.
Failingly finished swap-in for testbed/xen5vnode. 08:25:34:476210
TIMESTAMP: 08:25:34:476805 tbswap in finished (failed)
*** ERROR: batchexp: tbswap in failed!
Cleaning up and exiting with status 1 ...
Running 'tbend -f -e 167'
Beginning cleanup for testbed/xen5vnode. 08:25:34:717650
Clearing out virtual state.
Removing visualization data...
Cleanup finished! 08:25:35:037771
**** Experimental information, please ignore ****
Session ID = 59141
Likely Cause of the Problem:
Failed to set up VLANs.
Cause: unknown
Confidence: 0.7
Script: tbswap
**** End experimental information ****
SENDMAIL: Could not finish sendmail:
Removing experiment directories ...
