[MESOS-4946] ProvisionerDockerPullerTest.ROOT_INTERNET_CURL_ShellCommand flaky on Debian 8 - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Duplicate
Affects Version/s: None
Fix Version/s: None
Component/s: containerization, test
Labels:
- flaky
- flaky-test
Environment:

Debian 8 (VM)
Kernel version: 3.18.27

Description

While testing 0.28.1-rc2, this test fails when running as root on my debian 8 EC2 instance.

Verbose log:

https://gist.github.com/zhitaoli/95436f4ea2df13c4b137

root@zhitao-mesos1:/home/uber/mesos-0.28.0-rc2/build# GTEST_FILTER="ProvisionerDockerRegistryPullerTest.ROOT_INTERNET_CURL_ShellCommand" GLOG_v=2 ./bin/mesos-tests.sh --verbose 
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0314 22:44:12.986397 125940 process.cpp:2484] Spawned process __gc__@127.0.0.1:47773
I0314 22:44:12.986500 125964 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:12.986407168+00:00
I0314 22:44:12.986644 125940 process.cpp:2484] Spawned process help@127.0.0.1:47773
I0314 22:44:12.986696 125940 process.cpp:2484] Spawned process logging@127.0.0.1:47773
I0314 22:44:12.986732 125940 process.cpp:2484] Spawned process profiler@127.0.0.1:47773
I0314 22:44:12.986794 125940 process.cpp:2484] Spawned process system@127.0.0.1:47773
I0314 22:44:12.986843 125966 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:12.986818048+00:00
I0314 22:44:12.986915 125940 process.cpp:2484] Spawned process AuthenticationRouter(1)@127.0.0.1:47773
I0314 22:44:12.986989 125940 process.cpp:2484] Spawned process metrics@127.0.0.1:47773
I0314 22:44:12.987190 125940 process.cpp:2484] Spawned process __processes__@127.0.0.1:47773
I0314 22:44:12.987205 125940 process.cpp:986] libprocess is initialized on 127.0.0.1:47773 for 8 cpus
I0314 22:44:12.987226 125940 logging.cpp:193] Logging to STDERR
I0314 22:44:12.987390 125966 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:12.987382784+00:00
I0314 22:44:12.987553 125966 process.cpp:2494] Resuming logging@127.0.0.1:47773 at 2016-03-14 22:44:12.987546880+00:00
I0314 22:44:12.987679 125966 process.cpp:2494] Resuming profiler@127.0.0.1:47773 at 2016-03-14 22:44:12.987670016+00:00
I0314 22:44:12.987792 125966 process.cpp:2494] Resuming system@127.0.0.1:47773 at 2016-03-14 22:44:12.987787008+00:00
I0314 22:44:12.987941 125966 process.cpp:2494] Resuming AuthenticationRouter(1)@127.0.0.1:47773 at 2016-03-14 22:44:12.987932928+00:00
I0314 22:44:12.987962 125966 process.cpp:2494] Resuming metrics@127.0.0.1:47773 at 2016-03-14 22:44:12.987960064+00:00
I0314 22:44:12.988261 125967 process.cpp:2494] Resuming __processes__@127.0.0.1:47773 at 2016-03-14 22:44:12.988236032+00:00
I0314 22:44:12.988301 125968 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:12.988289024+00:00
Source directory: /home/uber/mesos-0.28.0-rc2
Build directory: /home/uber/mesos-0.28.0-rc2/build
-------------------------------------------------------------
We cannot run any cgroups tests that require mounting
hierarchies because you have the following hierarchies mounted:
/sys/fs/cgroup/blkio, /sys/fs/cgroup/cpu,cpuacct, /sys/fs/cgroup/cpuset, /sys/fs/cgroup/devices, /sys/fs/cgroup/freezer, /sys/fs/cgroup/hugetlb, /sys/fs/cgroup/memory, /sys/fs/cgroup/net_cls,net_prio, /sys/fs/cgroup/perf_event, /sys/fs/cgroup/systemd
We'll disable the CgroupsNoHierarchyTest test fixture for now.
-------------------------------------------------------------
/usr/bin/curl
I0314 22:44:13.039890 125940 process.cpp:2484] Spawned process reaper(1)@127.0.0.1:47773
I0314 22:44:13.041033 125969 process.cpp:2494] Resuming reaper(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.040216064+00:00
I0314 22:44:13.043113 125940 process.cpp:2484] Spawned process __latch__(1)@127.0.0.1:47773
I0314 22:44:13.043148 125970 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.043127040+00:00
I0314 22:44:13.043198 125940 process.cpp:2484] Spawned process __waiter__(1)@127.0.0.1:47773
I0314 22:44:13.043293 125970 process.cpp:2494] Resuming __latch__(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.043287040+00:00
I0314 22:44:13.043298 125940 process.cpp:2795] Donating thread to __waiter__(1)@127.0.0.1:47773 while waiting
I0314 22:44:13.043362 125940 process.cpp:2494] Resuming __waiter__(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.043356928+00:00
I0314 22:44:13.142611 125970 process.cpp:2494] Resuming reaper(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.142596096+00:00
I0314 22:44:13.143919 125971 process.cpp:2494] Resuming __latch__(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.143886080+00:00
I0314 22:44:13.143965 125971 process.cpp:2599] Cleaning up __latch__(1)@127.0.0.1:47773
I0314 22:44:13.144060 125970 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.144052992+00:00
I0314 22:44:13.144213 125967 process.cpp:2494] Resuming __waiter__(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.144200960+00:00
I0314 22:44:13.144366 125965 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.144324096+00:00
I0314 22:44:13.144492 125967 process.cpp:2599] Cleaning up __waiter__(1)@127.0.0.1:47773
I0314 22:44:13.144559 125970 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.144550144+00:00
PING google.com (216.58.193.174) 56(84) bytes of data.
64 bytes from sea09s15-in-f14.1e100.net (216.58.193.174): icmp_seq=1 ttl=52 time=7.60 ms

--- google.com ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 7.608/7.608/7.608/0.000 ms
/usr/sbin/logrotate
/bin/nc
-------------------------------------------------------------
We cannot run any overlayfs tests because:
Overlayfs is not supported on your systems
-------------------------------------------------------------
/usr/bin/perf: line 24: exec: perf_3.18: not found
E: linux-tools-3.18 is not installed.
-------------------------------------------------------------
The 'perf' command wasn't found so tests using it
to sample the 'cpu-cycles' hardware event will not be run.
-------------------------------------------------------------
/usr/bin/perf: line 24: exec: perf_3.18: not found
E: linux-tools-3.18 is not installed.
-------------------------------------------------------------
No 'perf' command found so no 'perf' tests will be run
-------------------------------------------------------------
Note: Google Test filter = ProvisionerDockerRegistryPullerTest.ROOT_INTERNET_CURL_ShellCommand-HierarchicalAllocator_BENCHMARK_Test.DeclineOffers:HierarchicalAllocator_BENCHMARK_Test.ResourceLabels:MesosContainerizerSlaveRecoveryTest.CGROUPS_ROOT_PerfRollForward:PerfEventIsolatorTest.ROOT_CGROUPS_Sample:UserCgroupIsolatorTest/0.ROOT_CGROUPS_UserCgroup:UserCgroupIsolatorTest/1.ROOT_CGROUPS_UserCgroup:UserCgroupIsolatorTest/2.ROOT_CGROUPS_UserCgroup:OverlayBackendTest.ROOT_OVERLAYFS_OverlayFSBackend:CgroupsNoHierarchyTest.ROOT_CGROUPS_NOHIERARCHY_MountUnmountHierarchy:CgroupsAnyHierarchyWithPerfEventTest.ROOT_CGROUPS_Perf:PerfTest.ROOT_Events:PerfTest.ROOT_Sample:PerfTest.Parse:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/0:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/1:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/2:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/3:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/4:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/5:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/6:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/7:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/8:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/9:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/10:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/11:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/12:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/13:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/14:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/15:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/16:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/17:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/18:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/19:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/20:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/21:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/22:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/23:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/24:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/25:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/26:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/27:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/28:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/29:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/30:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/31:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/32:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/33:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/34:SlaveAndFrameworkCount/HierarchicalAllocator_BENCHMARK_Test.AddAndUpdateSlave/35:SlaveCount/Registrar_BENCHMARK_Test.Performance/0:SlaveCount/Registrar_BENCHMARK_Test.Performance/1:SlaveCount/Registrar_BENCHMARK_Test.Performance/2:SlaveCount/Registrar_BENCHMARK_Test.Performance/3
[==========] Running 1 test from 1 test case.
[----------] Global test environment set-up.
[----------] 1 test from ProvisionerDockerRegistryPullerTest
[ RUN      ] ProvisionerDockerRegistryPullerTest.ROOT_INTERNET_CURL_ShellCommand
I0314 22:44:13.240097 125940 process.cpp:2484] Spawned process files@127.0.0.1:47773
I0314 22:44:13.240142 125971 process.cpp:2494] Resuming files@127.0.0.1:47773 at 2016-03-14 22:44:13.240122112+00:00
I0314 22:44:13.240447 125971 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.240435968+00:00
I0314 22:44:13.244557 125971 process.cpp:2494] Resuming reaper(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.244542976+00:00
I0314 22:44:13.249128 125967 process.cpp:2494] Resuming metrics@127.0.0.1:47773 at 2016-03-14 22:44:13.249114112+00:00
I0314 22:44:13.249145 125965 process.cpp:2494] Resuming (1)@127.0.0.1:47773 at 2016-03-14 22:44:13.249125120+00:00
I0314 22:44:13.249191 125940 process.cpp:2484] Spawned process (1)@127.0.0.1:47773
I0314 22:44:13.258237 125940 leveldb.cpp:174] Opened db in 8.905967ms
I0314 22:44:13.259546 125940 leveldb.cpp:181] Compacted db in 1.264333ms
I0314 22:44:13.259637 125940 leveldb.cpp:196] Created db iterator in 50683ns
I0314 22:44:13.259670 125940 leveldb.cpp:202] Seeked to beginning of db in 3404ns
I0314 22:44:13.259682 125940 leveldb.cpp:271] Iterated through 0 keys in the db in 493ns
I0314 22:44:13.259794 125940 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0314 22:44:13.261009 125940 process.cpp:2484] Spawned process log-replica(1)@127.0.0.1:47773
I0314 22:44:13.261023 125965 process.cpp:2494] Resuming log-replica(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.261014016+00:00
I0314 22:44:13.261227 125940 process.cpp:2484] Spawned process (2)@127.0.0.1:47773
I0314 22:44:13.261255 125968 process.cpp:2494] Resuming (2)@127.0.0.1:47773 at 2016-03-14 22:44:13.261238016+00:00
I0314 22:44:13.261330 125940 process.cpp:2484] Spawned process log(1)@127.0.0.1:47773
I0314 22:44:13.261355 125964 process.cpp:2494] Resuming log(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.261342976+00:00
I0314 22:44:13.261482 125940 process.cpp:2484] Spawned process log-reader(1)@127.0.0.1:47773
I0314 22:44:13.261513 125966 process.cpp:2494] Resuming log-reader(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.261497856+00:00
I0314 22:44:13.261571 125964 process.cpp:2484] Spawned process log-recover(1)@127.0.0.1:47773
I0314 22:44:13.261584 125940 process.cpp:2484] Spawned process log-writer(1)@127.0.0.1:47773
I0314 22:44:13.261620 125966 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.261614080+00:00
I0314 22:44:13.261715 125966 process.cpp:2494] Resuming log-recover(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.261709056+00:00
I0314 22:44:13.261732 125966 recover.cpp:447] Starting replica recovery
I0314 22:44:13.261783 125940 process.cpp:2484] Spawned process (3)@127.0.0.1:47773
I0314 22:44:13.261915 125964 process.cpp:2494] Resuming log-writer(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.261907968+00:00
I0314 22:44:13.261970 125964 process.cpp:2494] Resuming metrics@127.0.0.1:47773 at 2016-03-14 22:44:13.261964032+00:00
I0314 22:44:13.262040 125940 process.cpp:2484] Spawned process registrar(1)@127.0.0.1:47773
I0314 22:44:13.262097 125964 process.cpp:2494] Resuming (3)@127.0.0.1:47773 at 2016-03-14 22:44:13.262085888+00:00
I0314 22:44:13.262115 125940 process.cpp:2484] Spawned process standalone-master-detector(1)@127.0.0.1:47773
I0314 22:44:13.262140 125970 process.cpp:2494] Resuming registrar(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.262135040+00:00
I0314 22:44:13.262182 125966 process.cpp:2494] Resuming standalone-master-detector(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.262174976+00:00
I0314 22:44:13.262192 125940 process.cpp:2484] Spawned process authorizer(1)@127.0.0.1:47773
I0314 22:44:13.262220 125966 process.cpp:2494] Resuming authorizer(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.262216192+00:00
I0314 22:44:13.262365 125970 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.262355200+00:00
I0314 22:44:13.262120 125964 process.cpp:2494] Resuming log-replica(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.262116864+00:00
I0314 22:44:13.262630 125966 process.cpp:2494] Resuming log-recover(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.262622208+00:00
I0314 22:44:13.262660 125966 recover.cpp:473] Replica is in EMPTY status
I0314 22:44:13.262900 125966 process.cpp:2484] Spawned process log-recover-protocol(1)@127.0.0.1:47773
I0314 22:44:13.262945 125964 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.262938112+00:00
I0314 22:44:13.263041 125964 process.cpp:2494] Resuming log-recover-protocol(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.263034112+00:00
I0314 22:44:13.263097 125964 recover.cpp:129] Starting to wait for enough quorum of replicas before running recovery protocol, expected quroum size: 1
I0314 22:44:13.263115 125966 process.cpp:2494] Resuming metrics@127.0.0.1:47773 at 2016-03-14 22:44:13.263108864+00:00
I0314 22:44:13.263600 125964 process.cpp:2484] Spawned process __latch__(2)@127.0.0.1:47773
I0314 22:44:13.263964 125964 process.cpp:2494] Resuming (2)@127.0.0.1:47773 at 2016-03-14 22:44:13.263956992+00:00
I0314 22:44:13.264097 125964 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.264089088+00:00
I0314 22:44:13.264113 125966 process.cpp:2494] Resuming __latch__(2)@127.0.0.1:47773 at 2016-03-14 22:44:13.264102912+00:00
I0314 22:44:13.264137 125966 process.cpp:2494] Resuming log-recover-protocol(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.264132864+00:00
I0314 22:44:13.264181 125966 recover.cpp:143] Broadcasting recover request to all replicas
I0314 22:44:13.264369 125970 process.cpp:2494] Resuming (2)@127.0.0.1:47773 at 2016-03-14 22:44:13.264358912+00:00
I0314 22:44:13.264516 125970 process.cpp:2484] Spawned process (4)@127.0.0.1:47773
I0314 22:44:13.264544 125966 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.264537088+00:00
I0314 22:44:13.264619 125966 process.cpp:2494] Resuming (4)@127.0.0.1:47773 at 2016-03-14 22:44:13.264614144+00:00
I0314 22:44:13.264844 125966 process.cpp:2494] Resuming log-recover-protocol(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.264837120+00:00
I0314 22:44:13.264844 125970 process.cpp:2494] Resuming log-replica(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.264834048+00:00
I0314 22:44:13.264879 125966 recover.cpp:152] Broadcast request completed
I0314 22:44:13.264930 125970 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (4)@127.0.0.1:47773
I0314 22:44:13.265156 125970 process.cpp:2494] Resuming (4)@127.0.0.1:47773 at 2016-03-14 22:44:13.265149184+00:00
I0314 22:44:13.265326 125970 process.cpp:2599] Cleaning up (4)@127.0.0.1:47773
I0314 22:44:13.265532 125970 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.265523968+00:00
I0314 22:44:13.265571 125969 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.265561088+00:00
I0314 22:44:13.265732 125966 recover.cpp:193] Received a recover response from a replica in EMPTY status
I0314 22:44:13.266311 125966 process.cpp:2599] Cleaning up log-recover-protocol(1)@127.0.0.1:47773
I0314 22:44:13.266427 125966 process.cpp:2494] Resuming __latch__(2)@127.0.0.1:47773 at 2016-03-14 22:44:13.266419968+00:00
I0314 22:44:13.266461 125966 process.cpp:2599] Cleaning up __latch__(2)@127.0.0.1:47773
I0314 22:44:13.266549 125966 process.cpp:2494] Resuming log-recover(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.266542848+00:00
I0314 22:44:13.266621 125966 recover.cpp:564] Updating replica status to STARTING
I0314 22:44:13.266916 125965 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.266907904+00:00
I0314 22:44:13.266984 125966 process.cpp:2494] Resuming log-replica(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.266977024+00:00
I0314 22:44:13.266947 125968 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.266942976+00:00
I0314 22:44:13.267212 125940 process.cpp:2484] Spawned process master@127.0.0.1:47773
I0314 22:44:13.267232 125968 process.cpp:2494] Resuming standalone-master-detector(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.267225088+00:00
I0314 22:44:13.267303 125940 process.cpp:2484] Spawned process __latch__(3)@127.0.0.1:47773
I0314 22:44:13.267321 125969 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.267312128+00:00
I0314 22:44:13.267359 125940 process.cpp:2484] Spawned process __waiter__(2)@127.0.0.1:47773
I0314 22:44:13.267271 125965 process.cpp:2494] Resuming master@127.0.0.1:47773 at 2016-03-14 22:44:13.267267840+00:00
I0314 22:44:13.267400 125967 process.cpp:2494] Resuming __waiter__(2)@127.0.0.1:47773 at 2016-03-14 22:44:13.267396864+00:00
I0314 22:44:13.267376 125968 process.cpp:2494] Resuming __latch__(3)@127.0.0.1:47773 at 2016-03-14 22:44:13.267368960+00:00
I0314 22:44:13.267416 125965 master.cpp:375] Master 470202dd-1d5c-40dc-b187-6bf18dead3e2 (localhost) started on 127.0.0.1:47773
I0314 22:44:13.267495 125965 master.cpp:377] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_http="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/9W0qPD/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="100secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/9W0qPD/master" --zk_session_timeout="10secs"
W0314 22:44:13.268380 125965 master.cpp:380] 
**************************************************
Master bound to loopback interface! Cannot communicate with remote schedulers or slaves. You might want to set '--ip' flag to a routable IP address.
**************************************************
I0314 22:44:13.268441 125965 master.cpp:422] Master only allowing authenticated frameworks to register
I0314 22:44:13.268455 125965 master.cpp:427] Master only allowing authenticated slaves to register
I0314 22:44:13.268468 125965 credentials.hpp:35] Loading credentials for authentication from '/tmp/9W0qPD/credentials'
I0314 22:44:13.268934 125965 master.cpp:467] Using default 'crammd5' authenticator
I0314 22:44:13.269047 125966 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.970373ms
I0314 22:44:13.269120 125965 authenticator.cpp:518] Initializing server SASL
I0314 22:44:13.269162 125966 replica.cpp:320] Persisted replica status to STARTING
I0314 22:44:13.269394 125968 process.cpp:2494] Resuming log-recover(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.269385984+00:00
I0314 22:44:13.269672 125967 process.cpp:2494] Resuming log-recover(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.269665024+00:00
I0314 22:44:13.269795 125967 recover.cpp:473] Replica is in STARTING status
I0314 22:44:13.269897 125967 process.cpp:2484] Spawned process log-recover-protocol(2)@127.0.0.1:47773
I0314 22:44:13.269976 125967 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.269965824+00:00
I0314 22:44:13.270078 125967 process.cpp:2494] Resuming log-recover-protocol(2)@127.0.0.1:47773 at 2016-03-14 22:44:13.270072064+00:00
I0314 22:44:13.270117 125967 recover.cpp:129] Starting to wait for enough quorum of replicas before running recovery protocol, expected quroum size: 1
I0314 22:44:13.270267 125967 process.cpp:2484] Spawned process __latch__(4)@127.0.0.1:47773
I0314 22:44:13.270401 125967 process.cpp:2494] Resuming (2)@127.0.0.1:47773 at 2016-03-14 22:44:13.270390016+00:00
I0314 22:44:13.270517 125967 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.270510080+00:00
I0314 22:44:13.270620 125967 process.cpp:2494] Resuming __latch__(4)@127.0.0.1:47773 at 2016-03-14 22:44:13.270614016+00:00
I0314 22:44:13.270651 125967 process.cpp:2494] Resuming log-recover-protocol(2)@127.0.0.1:47773 at 2016-03-14 22:44:13.270648832+00:00
I0314 22:44:13.270685 125967 recover.cpp:143] Broadcasting recover request to all replicas
I0314 22:44:13.270786 125967 process.cpp:2494] Resuming (2)@127.0.0.1:47773 at 2016-03-14 22:44:13.270778880+00:00
I0314 22:44:13.270911 125967 process.cpp:2484] Spawned process (5)@127.0.0.1:47773
I0314 22:44:13.271394 125967 process.cpp:2494] Resuming log-recover-protocol(2)@127.0.0.1:47773 at 2016-03-14 22:44:13.271383040+00:00
I0314 22:44:13.271458 125967 recover.cpp:152] Broadcast request completed
I0314 22:44:13.271234 125970 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.271224064+00:00
I0314 22:44:13.271258 125971 process.cpp:2494] Resuming (5)@127.0.0.1:47773 at 2016-03-14 22:44:13.271255040+00:00
I0314 22:44:13.272106 125966 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (5)@127.0.0.1:47773
I0314 22:44:13.272303 125969 process.cpp:2494] Resuming (5)@127.0.0.1:47773 at 2016-03-14 22:44:13.272294912+00:00
I0314 22:44:13.272486 125965 auxprop.cpp:71] Initialized in-memory auxiliary property plugin
I0314 22:44:13.272574 125969 process.cpp:2599] Cleaning up (5)@127.0.0.1:47773
I0314 22:44:13.272591 125965 process.cpp:2484] Spawned process crammd5_authenticator(1)@127.0.0.1:47773
I0314 22:44:13.272635 125965 master.cpp:536] Using default 'basic' HTTP authenticator
I0314 22:44:13.276204 125967 process.cpp:2494] Resuming log-recover-protocol(2)@127.0.0.1:47773 at 2016-03-14 22:44:13.276195072+00:00
I0314 22:44:13.276258 125967 recover.cpp:193] Received a recover response from a replica in STARTING status
I0314 22:44:13.276434 125970 process.cpp:2494] Resuming crammd5_authenticator(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.276424960+00:00
I0314 22:44:13.276437 125971 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.276431104+00:00
I0314 22:44:13.276593 125964 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.276582912+00:00
I0314 22:44:13.276710 125965 process.cpp:2484] Spawned process (6)@127.0.0.1:47773
I0314 22:44:13.276723 125968 process.cpp:2494] Resuming (6)@127.0.0.1:47773 at 2016-03-14 22:44:13.276717056+00:00
I0314 22:44:13.276818 125965 master.cpp:570] Authorization enabled
I0314 22:44:13.276974 125967 process.cpp:2599] Cleaning up log-recover-protocol(2)@127.0.0.1:47773
I0314 22:44:13.277006 125968 process.cpp:2494] Resuming __latch__(4)@127.0.0.1:47773 at 2016-03-14 22:44:13.277000960+00:00
I0314 22:44:13.277091 125968 process.cpp:2599] Cleaning up __latch__(4)@127.0.0.1:47773
I0314 22:44:13.277040 125971 process.cpp:2494] Resuming log-recover(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.277038080+00:00
I0314 22:44:13.277178 125971 recover.cpp:564] Updating replica status to VOTING
I0314 22:44:13.277216 125968 process.cpp:2494] Resuming whitelist(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.277210112+00:00
I0314 22:44:13.277251 125968 whitelist_watcher.cpp:77] No whitelist given
I0314 22:44:13.277274 125968 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.277270016+00:00
I0314 22:44:13.277288 125971 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.277283072+00:00
I0314 22:44:13.277339 125968 process.cpp:2494] Resuming log-replica(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.277332992+00:00
I0314 22:44:13.277104 125966 process.cpp:2494] Resuming (1)@127.0.0.1:47773 at 2016-03-14 22:44:13.277099008+00:00
I0314 22:44:13.277449 125966 hierarchical.cpp:144] Initialized hierarchical allocator process
I0314 22:44:13.277523 125971 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.277517056+00:00
I0314 22:44:13.277026 125970 process.cpp:2494] Resuming AuthenticationRouter(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.277022976+00:00
I0314 22:44:13.277693 125966 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.277684992+00:00
I0314 22:44:13.277091 125965 process.cpp:2484] Spawned process whitelist(1)@127.0.0.1:47773
I0314 22:44:13.277986 125968 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 586760ns
I0314 22:44:13.278015 125968 replica.cpp:320] Persisted replica status to VOTING
I0314 22:44:13.278098 125967 process.cpp:2494] Resuming log-recover(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.278088192+00:00
I0314 22:44:13.278161 125967 recover.cpp:578] Successfully joined the Paxos group
I0314 22:44:13.278322 125967 recover.cpp:462] Recover process terminated
I0314 22:44:13.278365 125967 process.cpp:2599] Cleaning up log-recover(1)@127.0.0.1:47773
I0314 22:44:13.278322 125968 process.cpp:2494] Resuming log(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.278315008+00:00
I0314 22:44:13.278471 125967 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.278465024+00:00
I0314 22:44:13.278506 125964 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.278501120+00:00
I0314 22:44:13.278458 125968 log.cpp:356] Log recovery completed
I0314 22:44:13.278908 125971 process.cpp:2494] Resuming log-reader(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.278897920+00:00
I0314 22:44:13.278980 125968 process.cpp:2494] Resuming log-writer(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.278973184+00:00
I0314 22:44:13.282517 125971 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.282509056+00:00
I0314 22:44:13.283694 125970 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.283684096+00:00
I0314 22:44:13.284561 125967 process.cpp:2494] Resuming standalone-master-detector(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.284552192+00:00
I0314 22:44:13.284889 125968 process.cpp:2494] Resuming master@127.0.0.1:47773 at 2016-03-14 22:44:13.284881152+00:00
I0314 22:44:13.284972 125968 master.cpp:1711] The newly elected leader is master@127.0.0.1:47773 with id 470202dd-1d5c-40dc-b187-6bf18dead3e2
I0314 22:44:13.285004 125968 master.cpp:1724] Elected as the leading master!
I0314 22:44:13.285028 125968 master.cpp:1469] Recovering from registrar
I0314 22:44:13.285167 125964 process.cpp:2494] Resuming registrar(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.285159168+00:00
I0314 22:44:13.285228 125964 registrar.cpp:307] Recovering registrar
I0314 22:44:13.285395 125968 process.cpp:2494] Resuming standalone-master-detector(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.285388032+00:00
I0314 22:44:13.285604 125968 process.cpp:2494] Resuming (3)@127.0.0.1:47773 at 2016-03-14 22:44:13.285597184+00:00
I0314 22:44:13.285625 125964 process.cpp:2484] Spawned process __latch__(5)@127.0.0.1:47773
I0314 22:44:13.285733 125968 log.cpp:240] Starting the writer
I0314 22:44:13.286145 125964 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.286137088+00:00
I0314 22:44:13.286264 125964 process.cpp:2494] Resuming __latch__(5)@127.0.0.1:47773 at 2016-03-14 22:44:13.286257920+00:00
I0314 22:44:13.286289 125968 process.cpp:2494] Resuming log-writer(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.286277888+00:00
I0314 22:44:13.286720 125968 process.cpp:2484] Spawned process log-coordinator(1)@127.0.0.1:47773
I0314 22:44:13.286739 125964 process.cpp:2494] Resuming log-coordinator(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.286732032+00:00
I0314 22:44:13.286751 125968 log.cpp:659] Attempting to start the writer
I0314 22:44:13.286967 125971 process.cpp:2494] Resuming log-coordinator(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.286951936+00:00
I0314 22:44:13.287267 125968 process.cpp:2494] Resuming log-replica(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.287259136+00:00
I0314 22:44:13.287978 125971 process.cpp:2484] Spawned process log-implicit-promise(1)@127.0.0.1:47773
I0314 22:44:13.287991 125969 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.287981056+00:00
I0314 22:44:13.287997 125967 process.cpp:2494] Resuming log-implicit-promise(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.287991040+00:00
I0314 22:44:13.288178 125968 process.cpp:2494] Resuming (2)@127.0.0.1:47773 at 2016-03-14 22:44:13.288144128+00:00
I0314 22:44:13.288303 125971 process.cpp:2494] Resuming log-implicit-promise(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.288294912+00:00
I0314 22:44:13.288538 125968 process.cpp:2494] Resuming (2)@127.0.0.1:47773 at 2016-03-14 22:44:13.288530176+00:00
I0314 22:44:13.288663 125968 process.cpp:2484] Spawned process (7)@127.0.0.1:47773
I0314 22:44:13.288689 125966 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.288678912+00:00
I0314 22:44:13.288694 125971 process.cpp:2494] Resuming (7)@127.0.0.1:47773 at 2016-03-14 22:44:13.288687104+00:00
I0314 22:44:13.288893 125971 process.cpp:2494] Resuming log-replica(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.288887040+00:00
I0314 22:44:13.288920 125966 process.cpp:2494] Resuming log-implicit-promise(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.288912896+00:00
I0314 22:44:13.288991 125971 replica.cpp:493] Replica received implicit promise request from (7)@127.0.0.1:47773 with proposal 1
I0314 22:44:13.289546 125971 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 518152ns
I0314 22:44:13.289578 125971 replica.cpp:342] Persisted promised to 1
I0314 22:44:13.289654 125971 process.cpp:2494] Resuming (7)@127.0.0.1:47773 at 2016-03-14 22:44:13.289647104+00:00
I0314 22:44:13.289809 125971 process.cpp:2599] Cleaning up (7)@127.0.0.1:47773
I0314 22:44:13.289813 125968 process.cpp:2494] Resuming log-implicit-promise(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.289801984+00:00
I0314 22:44:13.289897 125970 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.289884160+00:00
I0314 22:44:13.289930 125971 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.289925120+00:00
I0314 22:44:13.290009 125971 process.cpp:2494] Resuming log-coordinator(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.290002944+00:00
I0314 22:44:13.290091 125968 process.cpp:2599] Cleaning up log-implicit-promise(1)@127.0.0.1:47773
I0314 22:44:13.290177 125970 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.290164992+00:00
I0314 22:44:13.290248 125970 process.cpp:2494] Resuming log-replica(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.290242048+00:00
I0314 22:44:13.290580 125971 coordinator.cpp:238] Coordinator attempting to fill missing positions
I0314 22:44:13.290818 125971 process.cpp:2484] Spawned process log-bulk-catch-up(1)@127.0.0.1:47773
I0314 22:44:13.290839 125968 process.cpp:2494] Resuming log-bulk-catch-up(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.290829824+00:00
I0314 22:44:13.290906 125965 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.290210048+00:00
I0314 22:44:13.291018 125968 process.cpp:2484] Spawned process log-catch-up(1)@127.0.0.1:47773
I0314 22:44:13.291038 125967 process.cpp:2494] Resuming log-catch-up(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.291028992+00:00
I0314 22:44:13.291138 125968 process.cpp:2494] Resuming log-replica(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.291131904+00:00
I0314 22:44:13.291260 125968 process.cpp:2494] Resuming log-catch-up(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.291252992+00:00
I0314 22:44:13.291409 125968 process.cpp:2484] Spawned process log-fill(1)@127.0.0.1:47773
I0314 22:44:13.291429 125967 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.291420928+00:00
I0314 22:44:13.291524 125968 process.cpp:2494] Resuming log-fill(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.291516928+00:00
I0314 22:44:13.291693 125968 process.cpp:2484] Spawned process log-explicit-promise(1)@127.0.0.1:47773
I0314 22:44:13.291733 125970 process.cpp:2494] Resuming log-explicit-promise(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.291728128+00:00
I0314 22:44:13.291705 125967 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.291697920+00:00
I0314 22:44:13.291879 125971 process.cpp:2494] Resuming (2)@127.0.0.1:47773 at 2016-03-14 22:44:13.291868928+00:00
I0314 22:44:13.292001 125971 process.cpp:2494] Resuming log-explicit-promise(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.291994112+00:00
I0314 22:44:13.292137 125970 process.cpp:2494] Resuming (2)@127.0.0.1:47773 at 2016-03-14 22:44:13.292126976+00:00
I0314 22:44:13.292250 125970 process.cpp:2484] Spawned process (8)@127.0.0.1:47773
I0314 22:44:13.292271 125971 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.292262912+00:00
I0314 22:44:13.292284 125964 process.cpp:2494] Resuming (8)@127.0.0.1:47773 at 2016-03-14 22:44:13.292276992+00:00
I0314 22:44:13.292361 125968 process.cpp:2494] Resuming log-explicit-promise(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.292354048+00:00
I0314 22:44:13.292397 125964 process.cpp:2494] Resuming log-replica(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.292391168+00:00
I0314 22:44:13.292513 125964 replica.cpp:388] Replica received explicit promise request from (8)@127.0.0.1:47773 for position 0 with proposal 2
I0314 22:44:13.293098 125964 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 532211ns
I0314 22:44:13.293135 125964 replica.cpp:712] Persisted action at 0
I0314 22:44:13.293228 125964 process.cpp:2494] Resuming (8)@127.0.0.1:47773 at 2016-03-14 22:44:13.293221888+00:00
I0314 22:44:13.293352 125964 process.cpp:2599] Cleaning up (8)@127.0.0.1:47773
I0314 22:44:13.293352 125968 process.cpp:2494] Resuming log-explicit-promise(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.293345024+00:00
I0314 22:44:13.293495 125964 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.293489920+00:00
I0314 22:44:13.293551 125966 process.cpp:2494] Resuming log-fill(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.293543168+00:00
I0314 22:44:13.293540 125970 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.293531904+00:00
I0314 22:44:13.293715 125966 process.cpp:2484] Spawned process log-write(1)@127.0.0.1:47773
I0314 22:44:13.293740 125969 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.293731840+00:00
I0314 22:44:13.293751 125967 process.cpp:2494] Resuming log-write(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.293745152+00:00
I0314 22:44:13.293524 125968 process.cpp:2599] Cleaning up log-explicit-promise(1)@127.0.0.1:47773
I0314 22:44:13.293882 125967 process.cpp:2494] Resuming (2)@127.0.0.1:47773 at 2016-03-14 22:44:13.293875968+00:00
I0314 22:44:13.293964 125968 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.293957888+00:00
I0314 22:44:13.293985 125967 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.293978880+00:00
I0314 22:44:13.294035 125968 process.cpp:2494] Resuming log-write(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.294029824+00:00
I0314 22:44:13.294232 125967 process.cpp:2494] Resuming (2)@127.0.0.1:47773 at 2016-03-14 22:44:13.294225920+00:00
I0314 22:44:13.294363 125967 process.cpp:2484] Spawned process (9)@127.0.0.1:47773
I0314 22:44:13.294376 125968 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.294369024+00:00
I0314 22:44:13.294397 125970 process.cpp:2494] Resuming (9)@127.0.0.1:47773 at 2016-03-14 22:44:13.294391040+00:00
I0314 22:44:13.294622 125968 process.cpp:2494] Resuming log-write(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.294615040+00:00
I0314 22:44:13.294735 125970 process.cpp:2494] Resuming log-replica(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.294728960+00:00
I0314 22:44:13.294822 125970 replica.cpp:537] Replica received write request for position 0 from (9)@127.0.0.1:47773
I0314 22:44:13.294899 125970 leveldb.cpp:436] Reading position from leveldb took 41567ns
I0314 22:44:13.295459 125970 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 489854ns
I0314 22:44:13.295492 125970 replica.cpp:712] Persisted action at 0
I0314 22:44:13.295575 125970 process.cpp:2494] Resuming (9)@127.0.0.1:47773 at 2016-03-14 22:44:13.295568896+00:00
I0314 22:44:13.295711 125970 process.cpp:2599] Cleaning up (9)@127.0.0.1:47773
I0314 22:44:13.295711 125964 process.cpp:2494] Resuming log-write(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.295703040+00:00
I0314 22:44:13.295830 125970 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.295824128+00:00
I0314 22:44:13.295892 125964 process.cpp:2599] Cleaning up log-write(1)@127.0.0.1:47773
I0314 22:44:13.295919 125970 process.cpp:2494] Resuming log-fill(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.295915008+00:00
I0314 22:44:13.296000 125964 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.295995904+00:00
I0314 22:44:13.296097 125966 process.cpp:2494] Resuming (2)@127.0.0.1:47773 at 2016-03-14 22:44:13.296088064+00:00
I0314 22:44:13.295866 125967 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.295862016+00:00
I0314 22:44:13.296222 125964 process.cpp:2494] Resuming log-replica(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.296212992+00:00
I0314 22:44:13.296298 125967 process.cpp:2494] Resuming log-fill(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.296289024+00:00
I0314 22:44:13.296304 125964 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
I0314 22:44:13.296442 125966 process.cpp:2494] Resuming log-catch-up(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.296435200+00:00
I0314 22:44:13.296444 125967 process.cpp:2599] Cleaning up log-fill(1)@127.0.0.1:47773
I0314 22:44:13.296526 125970 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.296519168+00:00
I0314 22:44:13.296612 125966 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.296603904+00:00
I0314 22:44:13.296913 125964 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 547372ns
I0314 22:44:13.296941 125964 replica.cpp:712] Persisted action at 0
I0314 22:44:13.296964 125964 replica.cpp:697] Replica learned NOP action at position 0
I0314 22:44:13.297055 125964 process.cpp:2494] Resuming log-catch-up(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.297049088+00:00
I0314 22:44:13.297158 125967 process.cpp:2494] Resuming log-bulk-catch-up(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.297150976+00:00
I0314 22:44:13.297165 125964 process.cpp:2599] Cleaning up log-catch-up(1)@127.0.0.1:47773
I0314 22:44:13.297274 125969 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.297265920+00:00
I0314 22:44:13.297314 125970 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.297307136+00:00
I0314 22:44:13.297380 125964 process.cpp:2494] Resuming log-coordinator(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.297372160+00:00
I0314 22:44:13.297433 125967 process.cpp:2599] Cleaning up log-bulk-catch-up(1)@127.0.0.1:47773
I0314 22:44:13.297633 125968 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.297626112+00:00
I0314 22:44:13.297678 125966 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.297671168+00:00
I0314 22:44:13.297818 125967 process.cpp:2494] Resuming log-writer(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.297810944+00:00
I0314 22:44:13.297878 125967 log.cpp:675] Writer started with ending position 0
I0314 22:44:13.298056 125964 process.cpp:2494] Resuming (3)@127.0.0.1:47773 at 2016-03-14 22:44:13.298050048+00:00
I0314 22:44:13.298122 125964 log.cpp:261] Writer got elected at position 
I0314 22:44:13.298277 125967 process.cpp:2494] Resuming log-reader(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.298269952+00:00
I0314 22:44:13.298863 125970 process.cpp:2494] Resuming log-replica(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.298854144+00:00
I0314 22:44:13.299129 125969 process.cpp:2494] Resuming (3)@127.0.0.1:47773 at 2016-03-14 22:44:13.299101952+00:00
I0314 22:44:13.299311 125970 process.cpp:2494] Resuming log-reader(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.299303168+00:00
I0314 22:44:13.299845 125969 process.cpp:2494] Resuming log-replica(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.299837184+00:00
I0314 22:44:13.299906 125969 replica.cpp:222] Starting read from '0' to '0'
I0314 22:44:13.299981 125969 leveldb.cpp:436] Reading position from leveldb took 24310ns
I0314 22:44:13.300323 125967 process.cpp:2494] Resuming log-reader(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.300312064+00:00
I0314 22:44:13.300598 125969 process.cpp:2494] Resuming (3)@127.0.0.1:47773 at 2016-03-14 22:44:13.300589056+00:00
I0314 22:44:13.300663 125969 log.cpp:303] Applying operations (0 entries)
I0314 22:44:13.302175 125970 process.cpp:2494] Resuming __latch__(5)@127.0.0.1:47773 at 2016-03-14 22:44:13.302164992+00:00
I0314 22:44:13.302214 125970 process.cpp:2599] Cleaning up __latch__(5)@127.0.0.1:47773
I0314 22:44:13.302269 125966 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.302260992+00:00
I0314 22:44:13.302322 125967 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.302313216+00:00
I0314 22:44:13.302392 125967 process.cpp:2494] Resuming registrar(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.302386944+00:00
I0314 22:44:13.302464 125967 registrar.cpp:340] Successfully fetched the registry (0B) in 17.185024ms
I0314 22:44:13.302675 125967 registrar.cpp:439] Applied 1 operations in 65787ns; attempting to update the 'registry'
I0314 22:44:13.304577 125970 process.cpp:2494] Resuming (3)@127.0.0.1:47773 at 2016-03-14 22:44:13.304567040+00:00
I0314 22:44:13.304823 125967 process.cpp:2484] Spawned process __latch__(6)@127.0.0.1:47773
I0314 22:44:13.304860 125964 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.304850176+00:00
I0314 22:44:13.304968 125964 process.cpp:2494] Resuming __latch__(6)@127.0.0.1:47773 at 2016-03-14 22:44:13.304961792+00:00
I0314 22:44:13.305320 125964 process.cpp:2494] Resuming log-writer(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.305310976+00:00
I0314 22:44:13.305374 125964 log.cpp:683] Attempting to append 160 bytes to the log
I0314 22:44:13.305462 125970 process.cpp:2494] Resuming log-coordinator(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.305448960+00:00
I0314 22:44:13.305526 125970 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I0314 22:44:13.305685 125970 process.cpp:2484] Spawned process log-write(2)@127.0.0.1:47773
I0314 22:44:13.305706 125964 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.305697792+00:00
I0314 22:44:13.305717 125968 process.cpp:2494] Resuming log-write(2)@127.0.0.1:47773 at 2016-03-14 22:44:13.305710080+00:00
I0314 22:44:13.306012 125966 process.cpp:2494] Resuming (2)@127.0.0.1:47773 at 2016-03-14 22:44:13.306003968+00:00
I0314 22:44:13.306143 125966 process.cpp:2494] Resuming log-write(2)@127.0.0.1:47773 at 2016-03-14 22:44:13.306135040+00:00
I0314 22:44:13.306272 125968 process.cpp:2494] Resuming (2)@127.0.0.1:47773 at 2016-03-14 22:44:13.306262016+00:00
I0314 22:44:13.306396 125968 process.cpp:2484] Spawned process (10)@127.0.0.1:47773
I0314 22:44:13.306417 125966 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.306408960+00:00
I0314 22:44:13.306494 125971 process.cpp:2494] Resuming log-write(2)@127.0.0.1:47773 at 2016-03-14 22:44:13.306483968+00:00
I0314 22:44:13.306449 125964 process.cpp:2494] Resuming (10)@127.0.0.1:47773 at 2016-03-14 22:44:13.306444032+00:00
I0314 22:44:13.306633 125968 process.cpp:2494] Resuming log-replica(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.306624000+00:00
I0314 22:44:13.306706 125968 replica.cpp:537] Replica received write request for position 1 from (10)@127.0.0.1:47773
I0314 22:44:13.307262 125968 leveldb.cpp:341] Persisting action (179 bytes) to leveldb took 518157ns
I0314 22:44:13.307292 125968 replica.cpp:712] Persisted action at 1
I0314 22:44:13.307364 125968 process.cpp:2494] Resuming (10)@127.0.0.1:47773 at 2016-03-14 22:44:13.307357184+00:00
I0314 22:44:13.307483 125968 process.cpp:2599] Cleaning up (10)@127.0.0.1:47773
I0314 22:44:13.307490 125964 process.cpp:2494] Resuming log-write(2)@127.0.0.1:47773 at 2016-03-14 22:44:13.307482880+00:00
I0314 22:44:13.307591 125965 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.307581952+00:00
I0314 22:44:13.307628 125968 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.307621120+00:00
I0314 22:44:13.307668 125970 process.cpp:2494] Resuming log-coordinator(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.307662848+00:00
I0314 22:44:13.307736 125964 process.cpp:2599] Cleaning up log-write(2)@127.0.0.1:47773
I0314 22:44:13.307884 125971 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.307878144+00:00
I0314 22:44:13.307924 125967 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.307915008+00:00
I0314 22:44:13.308017 125964 process.cpp:2494] Resuming (2)@127.0.0.1:47773 at 2016-03-14 22:44:13.308006912+00:00
I0314 22:44:13.308305 125971 process.cpp:2494] Resuming log-replica(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.308296960+00:00
I0314 22:44:13.308367 125971 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
I0314 22:44:13.308367 125964 process.cpp:2494] Resuming log-coordinator(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.308360192+00:00
I0314 22:44:13.308966 125971 leveldb.cpp:341] Persisting action (181 bytes) to leveldb took 570958ns
I0314 22:44:13.309000 125971 replica.cpp:712] Persisted action at 1
I0314 22:44:13.309023 125971 replica.cpp:697] Replica learned APPEND action at position 1
I0314 22:44:13.309171 125964 process.cpp:2494] Resuming log-coordinator(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.309163008+00:00
I0314 22:44:13.309406 125971 process.cpp:2494] Resuming (3)@127.0.0.1:47773 at 2016-03-14 22:44:13.309398016+00:00
I0314 22:44:13.309984 125969 process.cpp:2494] Resuming __latch__(6)@127.0.0.1:47773 at 2016-03-14 22:44:13.309969920+00:00
I0314 22:44:13.310024 125969 process.cpp:2599] Cleaning up __latch__(6)@127.0.0.1:47773
I0314 22:44:13.310088 125964 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.310080000+00:00
I0314 22:44:13.310134 125969 process.cpp:2494] Resuming registrar(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.310127872+00:00
I0314 22:44:13.310161 125964 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.310155008+00:00
I0314 22:44:13.310354 125969 registrar.cpp:484] Successfully updated the 'registry' in 7.48288ms
I0314 22:44:13.310461 125964 process.cpp:2494] Resuming log-writer(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.310451968+00:00
I0314 22:44:13.310513 125969 registrar.cpp:370] Successfully recovered registrar
I0314 22:44:13.310525 125964 log.cpp:702] Attempting to truncate the log to 1
I0314 22:44:13.310727 125964 process.cpp:2494] Resuming log-coordinator(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.310718976+00:00
I0314 22:44:13.310786 125964 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I0314 22:44:13.310801 125969 process.cpp:2494] Resuming master@127.0.0.1:47773 at 2016-03-14 22:44:13.310791936+00:00
I0314 22:44:13.310892 125964 process.cpp:2484] Spawned process log-write(3)@127.0.0.1:47773
I0314 22:44:13.311024 125964 process.cpp:2494] Resuming __latch__(3)@127.0.0.1:47773 at 2016-03-14 22:44:13.311016192+00:00
I0314 22:44:13.311049 125969 master.cpp:1521] Recovered 0 slaves from the Registry (122B) ; allowing 10mins for slaves to re-register
I0314 22:44:13.311108 125971 process.cpp:2494] Resuming (1)@127.0.0.1:47773 at 2016-03-14 22:44:13.311099136+00:00
I0314 22:44:13.311175 125971 hierarchical.cpp:171] Skipping recovery of hierarchical allocator: nothing to recover
I0314 22:44:13.311108 125964 process.cpp:2599] Cleaning up __latch__(3)@127.0.0.1:47773
I0314 22:44:13.311059 125966 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.311054080+00:00
I0314 22:44:13.311265 125969 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.311256832+00:00
I0314 22:44:13.311084 125970 process.cpp:2494] Resuming log-write(3)@127.0.0.1:47773 at 2016-03-14 22:44:13.311078912+00:00
I0314 22:44:13.311312 125968 process.cpp:2494] Resuming __waiter__(2)@127.0.0.1:47773 at 2016-03-14 22:44:13.311304960+00:00
I0314 22:44:13.311460 125970 process.cpp:2494] Resuming (2)@127.0.0.1:47773 at 2016-03-14 22:44:13.311453184+00:00
I0314 22:44:13.311475 125968 process.cpp:2599] Cleaning up __waiter__(2)@127.0.0.1:47773
I0314 22:44:13.311568 125970 process.cpp:2494] Resuming log-write(3)@127.0.0.1:47773 at 2016-03-14 22:44:13.311561216+00:00
I0314 22:44:13.311599 125968 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.311593984+00:00
I0314 22:44:13.311673 125967 process.cpp:2494] Resuming (2)@127.0.0.1:47773 at 2016-03-14 22:44:13.311665920+00:00
I0314 22:44:13.311686 125940 clock.cpp:331] Clock paused at 0x4214cb0
I0314 22:44:13.311877 125967 clock.cpp:435] Clock of (11)@127.0.0.1:47773 updated to 2016-03-14 22:44:13.311672832+00:00
I0314 22:44:13.311975 125967 process.cpp:2484] Spawned process (11)@127.0.0.1:47773
I0314 22:44:13.311997 125970 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.311672832+00:00
I0314 22:44:13.312084 125967 process.cpp:2494] Resuming log-write(3)@127.0.0.1:47773 at 2016-03-14 22:44:13.311672832+00:00
I0314 22:44:13.312026 125964 process.cpp:2494] Resuming (11)@127.0.0.1:47773 at 2016-03-14 22:44:13.311672832+00:00
I0314 22:44:13.312242 125970 process.cpp:2494] Resuming log-replica(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.311672832+00:00
I0314 22:44:13.312309 125970 replica.cpp:537] Replica received write request for position 2 from (11)@127.0.0.1:47773
I0314 22:44:13.312891 125970 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 547013ns
I0314 22:44:13.312921 125970 replica.cpp:712] Persisted action at 2
I0314 22:44:13.312990 125970 process.cpp:2494] Resuming (11)@127.0.0.1:47773 at 2016-03-14 22:44:13.311672832+00:00
I0314 22:44:13.313092 125970 process.cpp:2599] Cleaning up (11)@127.0.0.1:47773
I0314 22:44:13.313097 125964 process.cpp:2494] Resuming log-write(3)@127.0.0.1:47773 at 2016-03-14 22:44:13.311672832+00:00
I0314 22:44:13.313163 125968 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.311672832+00:00
I0314 22:44:13.313201 125970 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.311672832+00:00
I0314 22:44:13.313235 125966 process.cpp:2494] Resuming log-coordinator(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.311672832+00:00
I0314 22:44:13.313325 125964 process.cpp:2599] Cleaning up log-write(3)@127.0.0.1:47773
I0314 22:44:13.313437 125964 process.cpp:2494] Resuming (2)@127.0.0.1:47773 at 2016-03-14 22:44:13.311672832+00:00
I0314 22:44:13.313480 125966 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.311672832+00:00
I0314 22:44:13.313549 125966 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.311672832+00:00
I0314 22:44:13.313607 125964 process.cpp:2494] Resuming log-replica(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.311672832+00:00
I0314 22:44:13.313627 125966 process.cpp:2494] Resuming log-coordinator(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.311672832+00:00
I0314 22:44:13.313671 125964 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
I0314 22:44:13.314225 125964 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 524004ns
I0314 22:44:13.314285 125964 leveldb.cpp:399] Deleting ~1 keys from leveldb took 29177ns
I0314 22:44:13.314316 125964 replica.cpp:712] Persisted action at 2
I0314 22:44:13.314343 125964 replica.cpp:697] Replica learned TRUNCATE action at position 2
I0314 22:44:13.314455 125966 process.cpp:2494] Resuming log-coordinator(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.311672832+00:00
I0314 22:44:13.314671 125968 process.cpp:2494] Resuming (3)@127.0.0.1:47773 at 2016-03-14 22:44:13.311672832+00:00
I0314 22:44:13.321938 125940 clock.cpp:361] Clock resumed at 0x42152e0
I0314 22:44:13.324904 125940 process.cpp:2484] Spawned process fetcher(1)@127.0.0.1:47773
I0314 22:44:13.324928 125965 process.cpp:2494] Resuming fetcher(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.324915968+00:00
I0314 22:44:13.325103 125940 containerizer.cpp:149] Using isolation: docker/runtime,filesystem/linux
I0314 22:44:13.325198 125940 process.cpp:2484] Spawned process (12)@127.0.0.1:47773
I0314 22:44:13.325238 125970 process.cpp:2494] Resuming (12)@127.0.0.1:47773 at 2016-03-14 22:44:13.325229824+00:00
I0314 22:44:13.345549 125967 process.cpp:2494] Resuming reaper(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.345536000+00:00
I0314 22:44:13.446249 125964 process.cpp:2494] Resuming reaper(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.446213888+00:00
I0314 22:44:13.456987 125940 linux_launcher.cpp:101] Using /sys/fs/cgroup/freezer as the freezer hierarchy for the Linux launcher
I0314 22:44:13.458051 125940 process.cpp:2484] Spawned process (13)@127.0.0.1:47773
I0314 22:44:13.458076 125971 process.cpp:2494] Resuming (13)@127.0.0.1:47773 at 2016-03-14 22:44:13.458061824+00:00
E0314 22:44:13.460105 125940 shell.hpp:93] Command 'hadoop version 2>&1' failed; this is the output:
sh: 1: hadoop: not found
E0314 22:44:13.460185 125940 fetcher.cpp:59] Failed to create URI fetcher plugin 'hadoop': Failed to create HDFS client: Failed to execute 'hadoop version 2>&1'; the command was either not found or exited with a non-zero exit status: 127
I0314 22:44:13.460520 125940 registry_puller.cpp:111] Creating registry puller with docker registry 'https://registry-1.docker.io'
I0314 22:44:13.460666 125940 process.cpp:2484] Spawned process (14)@127.0.0.1:47773
I0314 22:44:13.460703 125966 process.cpp:2494] Resuming (14)@127.0.0.1:47773 at 2016-03-14 22:44:13.460686080+00:00
I0314 22:44:13.461055 125940 process.cpp:2484] Spawned process (15)@127.0.0.1:47773
I0314 22:44:13.461077 125969 process.cpp:2494] Resuming (15)@127.0.0.1:47773 at 2016-03-14 22:44:13.461062912+00:00
I0314 22:44:13.461375 125940 process.cpp:2484] Spawned process (16)@127.0.0.1:47773
I0314 22:44:13.461396 125966 process.cpp:2494] Resuming (16)@127.0.0.1:47773 at 2016-03-14 22:44:13.461388032+00:00
I0314 22:44:13.462051 125940 process.cpp:2484] Spawned process (17)@127.0.0.1:47773
I0314 22:44:13.462069 125966 process.cpp:2494] Resuming (17)@127.0.0.1:47773 at 2016-03-14 22:44:13.462060032+00:00
I0314 22:44:13.462363 125964 process.cpp:2494] Resuming metrics@127.0.0.1:47773 at 2016-03-14 22:44:13.462348032+00:00
I0314 22:44:13.462393 125940 process.cpp:2484] Spawned process (18)@127.0.0.1:47773
I0314 22:44:13.462406 125969 process.cpp:2494] Resuming (18)@127.0.0.1:47773 at 2016-03-14 22:44:13.462398976+00:00
I0314 22:44:13.462724 125969 process.cpp:2494] Resuming metrics@127.0.0.1:47773 at 2016-03-14 22:44:13.462716160+00:00
I0314 22:44:13.462738 125940 process.cpp:2484] Spawned process (19)@127.0.0.1:47773
I0314 22:44:13.462752 125966 process.cpp:2494] Resuming (19)@127.0.0.1:47773 at 2016-03-14 22:44:13.462744832+00:00
I0314 22:44:13.463157 125940 process.cpp:2484] Spawned process (20)@127.0.0.1:47773
I0314 22:44:13.463178 125966 process.cpp:2494] Resuming (20)@127.0.0.1:47773 at 2016-03-14 22:44:13.463170048+00:00
I0314 22:44:13.463287 125940 linux.cpp:81] Making '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_Nh3m1O' a shared mount
I0314 22:44:13.509795 125968 process.cpp:2494] Resuming metrics@127.0.0.1:47773 at 2016-03-14 22:44:13.509774080+00:00
I0314 22:44:13.510196 125967 process.cpp:2494] Resuming (21)@127.0.0.1:47773 at 2016-03-14 22:44:13.510183936+00:00
I0314 22:44:13.510313 125940 process.cpp:2484] Spawned process (21)@127.0.0.1:47773
I0314 22:44:13.511698 125971 process.cpp:2494] Resuming metrics@127.0.0.1:47773 at 2016-03-14 22:44:13.511683840+00:00
I0314 22:44:13.511809 125967 process.cpp:2494] Resuming (22)@127.0.0.1:47773 at 2016-03-14 22:44:13.511801088+00:00
I0314 22:44:13.511708 125940 process.cpp:2484] Spawned process (22)@127.0.0.1:47773
I0314 22:44:13.512455 125940 process.cpp:2484] Spawned process standalone-master-detector(2)@127.0.0.1:47773
I0314 22:44:13.512465 125971 process.cpp:2494] Resuming standalone-master-detector(2)@127.0.0.1:47773 at 2016-03-14 22:44:13.512457984+00:00
I0314 22:44:13.512774 125940 process.cpp:2484] Spawned process (23)@127.0.0.1:47773
I0314 22:44:13.512806 125966 process.cpp:2494] Resuming (23)@127.0.0.1:47773 at 2016-03-14 22:44:13.512794880+00:00
I0314 22:44:13.513280 125940 process.cpp:2484] Spawned process (24)@127.0.0.1:47773
I0314 22:44:13.513298 125964 process.cpp:2494] Resuming (24)@127.0.0.1:47773 at 2016-03-14 22:44:13.513287168+00:00
I0314 22:44:13.513870 125969 process.cpp:2494] Resuming metrics@127.0.0.1:47773 at 2016-03-14 22:44:13.513856000+00:00
I0314 22:44:13.514529 125940 process.cpp:2484] Spawned process __limiter__(1)@127.0.0.1:47773
I0314 22:44:13.514611 125940 process.cpp:2484] Spawned process monitor@127.0.0.1:47773
I0314 22:44:13.514714 125940 process.cpp:2484] Spawned process slave(1)@127.0.0.1:47773
I0314 22:44:13.514931 125967 process.cpp:2494] Resuming __limiter__(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.514919936+00:00
I0314 22:44:13.514973 125967 process.cpp:2494] Resuming monitor@127.0.0.1:47773 at 2016-03-14 22:44:13.514967808+00:00
I0314 22:44:13.515209 125969 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.515202048+00:00
I0314 22:44:13.515249 125969 slave.cpp:193] Slave started on 1)@127.0.0.1:47773
I0314 22:44:13.515251 125967 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.515240960+00:00
I0314 22:44:13.515259 125969 slave.cpp:194] Flags at startup: --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_Nh3m1O/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_Nh3m1O/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_providers="docker" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="docker/runtime,filesystem/linux" --launcher_dir="/home/uber/mesos-0.28.0-rc2/build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_Nh3m1O"
W0314 22:44:13.515763 125969 slave.cpp:197] 
**************************************************
Slave bound to loopback interface! Cannot communicate with remote master(s). You might want to set '--ip' flag to a routable IP address.
**************************************************
I0314 22:44:13.515799 125969 credentials.hpp:83] Loading credential for authentication from '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_Nh3m1O/credential'
I0314 22:44:13.516017 125969 slave.cpp:324] Slave using credential for: test-principal
I0314 22:44:13.516136 125969 process.cpp:2484] Spawned process (25)@127.0.0.1:47773
I0314 22:44:13.516163 125967 process.cpp:2494] Resuming (25)@127.0.0.1:47773 at 2016-03-14 22:44:13.516154112+00:00
I0314 22:44:13.516264 125969 process.cpp:2484] Spawned process (26)@127.0.0.1:47773
I0314 22:44:13.516283 125967 process.cpp:2494] Resuming (26)@127.0.0.1:47773 at 2016-03-14 22:44:13.516273920+00:00
I0314 22:44:13.516362 125969 resources.cpp:572] Parsing resources as JSON failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
Trying semicolon-delimited string format instead
W0314 22:44:13.516609 125940 sched.cpp:1642] 
**************************************************
Scheduler driver bound to loopback interface! Cannot communicate with remote master(s). You might want to set 'LIBPROCESS_IP' environment variable to use a routable IP address.
**************************************************
I0314 22:44:13.516716 125940 process.cpp:2484] Spawned process version@127.0.0.1:47773
I0314 22:44:13.516767 125970 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.516752128+00:00
I0314 22:44:13.516834 125966 process.cpp:2494] Resuming __latch__(7)@127.0.0.1:47773 at 2016-03-14 22:44:13.516828160+00:00
I0314 22:44:13.516800 125940 process.cpp:2484] Spawned process __latch__(7)@127.0.0.1:47773
I0314 22:44:13.516808 125971 process.cpp:2494] Resuming version@127.0.0.1:47773 at 2016-03-14 22:44:13.516803072+00:00
I0314 22:44:13.517158 125971 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.517148928+00:00
I0314 22:44:13.517997 125969 slave.cpp:464] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0314 22:44:13.518097 125969 slave.cpp:472] Slave attributes: [  ]
I0314 22:44:13.518126 125969 slave.cpp:477] Slave hostname: localhost
I0314 22:44:13.518151 125940 pid.cpp:93] Attempting to parse 'master@127.0.0.1:47773' into a PID
I0314 22:44:13.518280 125965 process.cpp:2494] Resuming (24)@127.0.0.1:47773 at 2016-03-14 22:44:13.518265856+00:00
I0314 22:44:13.518328 125940 process.cpp:2484] Spawned process standalone-master-detector(3)@127.0.0.1:47773
I0314 22:44:13.518358 125968 process.cpp:2494] Resuming standalone-master-detector(3)@127.0.0.1:47773 at 2016-03-14 22:44:13.518351104+00:00
I0314 22:44:13.518834 125965 process.cpp:2494] Resuming metrics@127.0.0.1:47773 at 2016-03-14 22:44:13.518824192+00:00
I0314 22:44:13.518918 125940 sched.cpp:222] Version: 0.28.0
I0314 22:44:13.518977 125940 process.cpp:2484] Spawned process scheduler-c577e1f5-4b58-41dd-bd3e-5b286e042a26@127.0.0.1:47773
I0314 22:44:13.518998 125965 process.cpp:2494] Resuming scheduler-c577e1f5-4b58-41dd-bd3e-5b286e042a26@127.0.0.1:47773 at 2016-03-14 22:44:13.518991872+00:00
I0314 22:44:13.519083 125940 process.cpp:2484] Spawned process __latch__(8)@127.0.0.1:47773
I0314 22:44:13.519083 125967 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.519074816+00:00
I0314 22:44:13.519152 125940 process.cpp:2484] Spawned process __waiter__(3)@127.0.0.1:47773
I0314 22:44:13.519100 125968 process.cpp:2494] Resuming __latch__(8)@127.0.0.1:47773 at 2016-03-14 22:44:13.519098880+00:00
I0314 22:44:13.519206 125968 process.cpp:2494] Resuming __waiter__(3)@127.0.0.1:47773 at 2016-03-14 22:44:13.519200000+00:00
I0314 22:44:13.519659 125965 process.cpp:2494] Resuming standalone-master-detector(3)@127.0.0.1:47773 at 2016-03-14 22:44:13.519653120+00:00
I0314 22:44:13.519868 125968 process.cpp:2494] Resuming scheduler-c577e1f5-4b58-41dd-bd3e-5b286e042a26@127.0.0.1:47773 at 2016-03-14 22:44:13.519860992+00:00
I0314 22:44:13.519939 125968 sched.cpp:326] New master detected at master@127.0.0.1:47773
I0314 22:44:13.519960 125968 pid.cpp:93] Attempting to parse 'master@127.0.0.1:47773' into a PID
I0314 22:44:13.520033 125968 sched.cpp:382] Authenticating with master master@127.0.0.1:47773
I0314 22:44:13.520056 125968 sched.cpp:389] Using default CRAM-MD5 authenticatee
I0314 22:44:13.520090 125968 pid.cpp:93] Attempting to parse 'master@127.0.0.1:47773' into a PID
I0314 22:44:13.520200 125968 process.cpp:2484] Spawned process crammd5_authenticatee(1)@127.0.0.1:47773
I0314 22:44:13.520246 125965 process.cpp:2494] Resuming crammd5_authenticatee(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.520236032+00:00
I0314 22:44:13.520383 125968 process.cpp:2494] Resuming standalone-master-detector(3)@127.0.0.1:47773 at 2016-03-14 22:44:13.520376832+00:00
I0314 22:44:13.520519 125968 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.520512000+00:00
I0314 22:44:13.520526 125965 authenticatee.cpp:97] Initializing client SASL
I0314 22:44:13.521070 125965 authenticatee.cpp:121] Creating new client SASL connection
I0314 22:44:13.521174 125966 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.521167872+00:00
I0314 22:44:13.521581 125969 process.cpp:2484] Spawned process __async_executor__(1)@127.0.0.1:47773
I0314 22:44:13.521652 125965 process.cpp:2494] Resuming master@127.0.0.1:47773 at 2016-03-14 22:44:13.521639168+00:00
I0314 22:44:13.521807 125965 pid.cpp:93] Attempting to parse 'scheduler-c577e1f5-4b58-41dd-bd3e-5b286e042a26@127.0.0.1:47773' into a PID
I0314 22:44:13.521706 125967 process.cpp:2494] Resuming __async_executor__(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.521698048+00:00
I0314 22:44:13.521888 125965 master.cpp:5495] Authenticating scheduler-c577e1f5-4b58-41dd-bd3e-5b286e042a26@127.0.0.1:47773
I0314 22:44:13.521894 125967 state.cpp:58] Recovering state from '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_Nh3m1O/meta'
I0314 22:44:13.522004 125971 process.cpp:2494] Resuming crammd5_authenticator(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.521996032+00:00
I0314 22:44:13.522058 125971 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(1)@127.0.0.1:47773
I0314 22:44:13.522166 125971 process.cpp:2484] Spawned process crammd5_authenticator_session(1)@127.0.0.1:47773
I0314 22:44:13.522212 125967 process.cpp:2599] Cleaning up __async_executor__(1)@127.0.0.1:47773
I0314 22:44:13.522245 125966 process.cpp:2494] Resuming crammd5_authenticator_session(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.522237952+00:00
I0314 22:44:13.521693 125964 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.521688832+00:00
I0314 22:44:13.522277 125970 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.522274048+00:00
I0314 22:44:13.522606 125966 authenticator.cpp:98] Creating new server SASL connection
I0314 22:44:13.522214 125965 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.522209024+00:00
I0314 22:44:13.522786 125967 process.cpp:2494] Resuming crammd5_authenticatee(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.522778112+00:00
I0314 22:44:13.522894 125967 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
I0314 22:44:13.522817 125968 process.cpp:2494] Resuming (24)@127.0.0.1:47773 at 2016-03-14 22:44:13.522813952+00:00
I0314 22:44:13.522935 125967 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
I0314 22:44:13.522963 125968 status_update_manager.cpp:200] Recovering status update manager
I0314 22:44:13.523006 125967 process.cpp:2494] Resuming crammd5_authenticator_session(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.523000064+00:00
I0314 22:44:13.523062 125966 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.523049216+00:00
I0314 22:44:13.523079 125967 authenticator.cpp:203] Received SASL authentication start
I0314 22:44:13.523178 125968 process.cpp:2494] Resuming (22)@127.0.0.1:47773 at 2016-03-14 22:44:13.523170048+00:00
I0314 22:44:13.523241 125968 containerizer.cpp:407] Recovering containerizer
I0314 22:44:13.523208 125967 authenticator.cpp:325] Authentication requires more steps
I0314 22:44:13.523349 125967 process.cpp:2494] Resuming crammd5_authenticatee(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.523341824+00:00
I0314 22:44:13.523416 125967 authenticatee.cpp:258] Received SASL authentication step
I0314 22:44:13.523486 125967 process.cpp:2494] Resuming crammd5_authenticator_session(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.523480064+00:00
I0314 22:44:13.523545 125967 authenticator.cpp:231] Received SASL authentication step
I0314 22:44:13.523574 125967 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'zhitao-mesos1.dev.uber.com' server FQDN: 'zhitao-mesos1.dev.uber.com' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0314 22:44:13.523593 125967 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
I0314 22:44:13.523697 125967 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0314 22:44:13.523730 125967 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'zhitao-mesos1.dev.uber.com' server FQDN: 'zhitao-mesos1.dev.uber.com' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0314 22:44:13.523744 125967 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0314 22:44:13.523753 125967 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0314 22:44:13.523771 125967 authenticator.cpp:317] Authentication success
I0314 22:44:13.523829 125971 process.cpp:2494] Resuming crammd5_authenticatee(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.523820032+00:00
I0314 22:44:13.523897 125971 authenticatee.cpp:298] Authentication success
I0314 22:44:13.523993 125971 process.cpp:2494] Resuming master@127.0.0.1:47773 at 2016-03-14 22:44:13.523984896+00:00
I0314 22:44:13.524016 125967 process.cpp:2494] Resuming scheduler-c577e1f5-4b58-41dd-bd3e-5b286e042a26@127.0.0.1:47773 at 2016-03-14 22:44:13.524008960+00:00
I0314 22:44:13.524298 125967 process.cpp:2795] Donating thread to crammd5_authenticatee(1)@127.0.0.1:47773 while waiting
I0314 22:44:13.524045 125971 master.cpp:5525] Successfully authenticated principal 'test-principal' at scheduler-c577e1f5-4b58-41dd-bd3e-5b286e042a26@127.0.0.1:47773
I0314 22:44:13.524405 125967 process.cpp:2494] Resuming crammd5_authenticatee(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.524399104+00:00
I0314 22:44:13.524514 125967 process.cpp:2599] Cleaning up crammd5_authenticatee(1)@127.0.0.1:47773
I0314 22:44:13.524636 125971 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.524628992+00:00
I0314 22:44:13.524704 125971 process.cpp:2494] Resuming crammd5_authenticator_session(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.524699904+00:00
I0314 22:44:13.524727 125967 sched.cpp:471] Successfully authenticated with master master@127.0.0.1:47773
I0314 22:44:13.524827 125967 sched.cpp:776] Sending SUBSCRIBE call to master@127.0.0.1:47773
I0314 22:44:13.524930 125967 pid.cpp:93] Attempting to parse 'master@127.0.0.1:47773' into a PID
I0314 22:44:13.525101 125967 sched.cpp:809] Will retry registration in 1.095445681secs if necessary
I0314 22:44:13.524046 125964 process.cpp:2494] Resuming crammd5_authenticator(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.524043008+00:00
I0314 22:44:13.525310 125964 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(1)@127.0.0.1:47773
I0314 22:44:13.525390 125964 process.cpp:2795] Donating thread to crammd5_authenticator_session(1)@127.0.0.1:47773 while waiting
I0314 22:44:13.525418 125964 process.cpp:2494] Resuming crammd5_authenticator_session(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.525413888+00:00
I0314 22:44:13.525445 125964 process.cpp:2599] Cleaning up crammd5_authenticator_session(1)@127.0.0.1:47773
I0314 22:44:13.525548 125964 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.525542912+00:00
I0314 22:44:13.525158 125970 process.cpp:2494] Resuming master@127.0.0.1:47773 at 2016-03-14 22:44:13.525149952+00:00
I0314 22:44:13.526201 125970 master.cpp:2231] Received SUBSCRIBE call for framework 'default' at scheduler-c577e1f5-4b58-41dd-bd3e-5b286e042a26@127.0.0.1:47773
I0314 22:44:13.526314 125970 master.cpp:1750] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0314 22:44:13.526432 125964 process.cpp:2494] Resuming authorizer(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.526423808+00:00
I0314 22:44:13.526628 125971 process.cpp:2494] Resuming master@127.0.0.1:47773 at 2016-03-14 22:44:13.526618112+00:00
I0314 22:44:13.526701 125971 master.cpp:2302] Subscribing framework default with checkpointing disabled and capabilities [  ]
I0314 22:44:13.527202 125966 process.cpp:2494] Resuming (1)@127.0.0.1:47773 at 2016-03-14 22:44:13.527193088+00:00
I0314 22:44:13.527329 125964 process.cpp:2494] Resuming metrics@127.0.0.1:47773 at 2016-03-14 22:44:13.527321088+00:00
I0314 22:44:13.527449 125967 process.cpp:2494] Resuming scheduler-c577e1f5-4b58-41dd-bd3e-5b286e042a26@127.0.0.1:47773 at 2016-03-14 22:44:13.527443968+00:00
I0314 22:44:13.527568 125967 pid.cpp:93] Attempting to parse 'master@127.0.0.1:47773' into a PID
I0314 22:44:13.527653 125966 hierarchical.cpp:265] Added framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:13.527673 125967 sched.cpp:703] Framework registered with 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:13.527797 125967 sched.cpp:717] Scheduler::registered took 48415ns
I0314 22:44:13.527842 125966 hierarchical.cpp:1453] No resources available to allocate!
I0314 22:44:13.527987 125966 hierarchical.cpp:1548] No inverse offers to send out!
I0314 22:44:13.528054 125966 hierarchical.cpp:1130] Performed allocation for 0 slaves in 373698ns
I0314 22:44:13.537250 125971 process.cpp:2494] Resuming (21)@127.0.0.1:47773 at 2016-03-14 22:44:13.537234944+00:00
I0314 22:44:13.537318 125968 process.cpp:2484] Spawned process (27)@127.0.0.1:47773
I0314 22:44:13.537267 125964 process.cpp:2494] Resuming (20)@127.0.0.1:47773 at 2016-03-14 22:44:13.537257984+00:00
I0314 22:44:13.537420 125964 process.cpp:2494] Resuming (27)@127.0.0.1:47773 at 2016-03-14 22:44:13.537414912+00:00
I0314 22:44:13.537551 125969 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.537341952+00:00
I0314 22:44:13.549006 125964 process.cpp:2494] Resuming reaper(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.548999168+00:00
I0314 22:44:13.586443 125968 process.cpp:2494] Resuming (27)@127.0.0.1:47773 at 2016-03-14 22:44:13.586425088+00:00
I0314 22:44:13.586650 125971 process.cpp:2494] Resuming (22)@127.0.0.1:47773 at 2016-03-14 22:44:13.586639872+00:00
I0314 22:44:13.586668 125968 process.cpp:2599] Cleaning up (27)@127.0.0.1:47773
I0314 22:44:13.586855 125964 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.586844928+00:00
I0314 22:44:13.586936 125964 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.586930944+00:00
I0314 22:44:13.587013 125970 process.cpp:2494] Resuming (19)@127.0.0.1:47773 at 2016-03-14 22:44:13.586999808+00:00
I0314 22:44:13.587538 125964 process.cpp:2494] Resuming (16)@127.0.0.1:47773 at 2016-03-14 22:44:13.587528960+00:00
I0314 22:44:13.587579 125970 process.cpp:2484] Spawned process (28)@127.0.0.1:47773
I0314 22:44:13.587666 125964 process.cpp:2494] Resuming (15)@127.0.0.1:47773 at 2016-03-14 22:44:13.587657984+00:00
I0314 22:44:13.587870 125970 process.cpp:2484] Spawned process (29)@127.0.0.1:47773
I0314 22:44:13.587972 125967 process.cpp:2494] Resuming (29)@127.0.0.1:47773 at 2016-03-14 22:44:13.587960832+00:00
I0314 22:44:13.587638 125965 process.cpp:2494] Resuming (28)@127.0.0.1:47773 at 2016-03-14 22:44:13.587629056+00:00
I0314 22:44:13.588024 125964 metadata_manager.cpp:235] Successfully loaded image 'library/alpine'
I0314 22:44:13.588057 125964 metadata_manager.cpp:238] Successfully loaded 1 Docker images
I0314 22:44:13.588135 125971 process.cpp:2494] Resuming (28)@127.0.0.1:47773 at 2016-03-14 22:44:13.588112128+00:00
I0314 22:44:13.587612 125966 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.587606016+00:00
I0314 22:44:13.588266 125967 process.cpp:2494] Resuming (29)@127.0.0.1:47773 at 2016-03-14 22:44:13.588259072+00:00
I0314 22:44:13.588616 125967 provisioner.cpp:245] Provisioner recovery complete
I0314 22:44:13.588732 125968 process.cpp:2494] Resuming (22)@127.0.0.1:47773 at 2016-03-14 22:44:13.588722944+00:00
I0314 22:44:13.588860 125967 process.cpp:2599] Cleaning up (29)@127.0.0.1:47773
I0314 22:44:13.588904 125968 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.588894976+00:00
I0314 22:44:13.589042 125969 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.589033984+00:00
I0314 22:44:13.589193 125964 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.589185024+00:00
I0314 22:44:13.589264 125968 slave.cpp:4565] Finished recovery
I0314 22:44:13.589582 125968 slave.cpp:4737] Querying resource estimator for oversubscribable resources
I0314 22:44:13.589587 125965 process.cpp:2494] Resuming standalone-master-detector(2)@127.0.0.1:47773 at 2016-03-14 22:44:13.589577984+00:00
I0314 22:44:13.589742 125966 process.cpp:2494] Resuming (25)@127.0.0.1:47773 at 2016-03-14 22:44:13.589732864+00:00
I0314 22:44:13.589925 125968 pid.cpp:93] Attempting to parse 'master@127.0.0.1:47773' into a PID
I0314 22:44:13.589979 125971 process.cpp:2599] Cleaning up (28)@127.0.0.1:47773
I0314 22:44:13.590086 125968 slave.cpp:796] New master detected at master@127.0.0.1:47773
I0314 22:44:13.590138 125969 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.590130944+00:00
I0314 22:44:13.590173 125968 slave.cpp:859] Authenticating with master master@127.0.0.1:47773
I0314 22:44:13.590185 125968 slave.cpp:864] Using default CRAM-MD5 authenticatee
I0314 22:44:13.590279 125966 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.590269952+00:00
I0314 22:44:13.590294 125968 process.cpp:2484] Spawned process crammd5_authenticatee(2)@127.0.0.1:47773
I0314 22:44:13.590313 125964 process.cpp:2494] Resuming crammd5_authenticatee(2)@127.0.0.1:47773 at 2016-03-14 22:44:13.590307072+00:00
I0314 22:44:13.590402 125968 slave.cpp:832] Detecting new master
I0314 22:44:13.590421 125964 authenticatee.cpp:121] Creating new client SASL connection
I0314 22:44:13.590499 125966 process.cpp:2494] Resuming standalone-master-detector(2)@127.0.0.1:47773 at 2016-03-14 22:44:13.590490112+00:00
I0314 22:44:13.590533 125968 slave.cpp:4751] Received oversubscribable resources  from the resource estimator
I0314 22:44:13.589931 125965 process.cpp:2494] Resuming (24)@127.0.0.1:47773 at 2016-03-14 22:44:13.589921024+00:00
I0314 22:44:13.592234 125965 status_update_manager.cpp:174] Pausing sending status updates
I0314 22:44:13.592267 125965 process.cpp:2494] Resuming master@127.0.0.1:47773 at 2016-03-14 22:44:13.592262144+00:00
I0314 22:44:13.592346 125965 pid.cpp:93] Attempting to parse 'slave(1)@127.0.0.1:47773' into a PID
I0314 22:44:13.592389 125965 master.cpp:5495] Authenticating slave(1)@127.0.0.1:47773
I0314 22:44:13.592464 125969 process.cpp:2494] Resuming crammd5_authenticator(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.592456960+00:00
I0314 22:44:13.592507 125969 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(2)@127.0.0.1:47773
I0314 22:44:13.592582 125969 process.cpp:2484] Spawned process crammd5_authenticator_session(2)@127.0.0.1:47773
I0314 22:44:13.592604 125965 process.cpp:2494] Resuming crammd5_authenticator_session(2)@127.0.0.1:47773 at 2016-03-14 22:44:13.592596992+00:00
I0314 22:44:13.592731 125965 authenticator.cpp:98] Creating new server SASL connection
I0314 22:44:13.592906 125969 process.cpp:2494] Resuming crammd5_authenticatee(2)@127.0.0.1:47773 at 2016-03-14 22:44:13.592897792+00:00
I0314 22:44:13.592969 125969 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
I0314 22:44:13.592984 125969 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
I0314 22:44:13.593039 125969 process.cpp:2494] Resuming crammd5_authenticator_session(2)@127.0.0.1:47773 at 2016-03-14 22:44:13.593031936+00:00
I0314 22:44:13.593089 125969 authenticator.cpp:203] Received SASL authentication start
I0314 22:44:13.593123 125969 authenticator.cpp:325] Authentication requires more steps
I0314 22:44:13.593173 125969 process.cpp:2494] Resuming crammd5_authenticatee(2)@127.0.0.1:47773 at 2016-03-14 22:44:13.593168128+00:00
I0314 22:44:13.593214 125969 authenticatee.cpp:258] Received SASL authentication step
I0314 22:44:13.593269 125969 process.cpp:2494] Resuming crammd5_authenticator_session(2)@127.0.0.1:47773 at 2016-03-14 22:44:13.593265152+00:00
I0314 22:44:13.593308 125969 authenticator.cpp:231] Received SASL authentication step
I0314 22:44:13.593332 125969 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'zhitao-mesos1.dev.uber.com' server FQDN: 'zhitao-mesos1.dev.uber.com' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0314 22:44:13.593340 125969 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
I0314 22:44:13.593376 125969 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0314 22:44:13.593392 125969 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'zhitao-mesos1.dev.uber.com' server FQDN: 'zhitao-mesos1.dev.uber.com' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0314 22:44:13.593400 125969 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0314 22:44:13.593405 125969 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0314 22:44:13.593418 125969 authenticator.cpp:317] Authentication success
I0314 22:44:13.593472 125965 process.cpp:2494] Resuming crammd5_authenticatee(2)@127.0.0.1:47773 at 2016-03-14 22:44:13.593462016+00:00
I0314 22:44:13.593518 125965 authenticatee.cpp:298] Authentication success
I0314 22:44:13.593518 125964 process.cpp:2494] Resuming master@127.0.0.1:47773 at 2016-03-14 22:44:13.593508096+00:00
I0314 22:44:13.593539 125969 process.cpp:2494] Resuming crammd5_authenticator(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.593532160+00:00
I0314 22:44:13.593559 125964 master.cpp:5525] Successfully authenticated principal 'test-principal' at slave(1)@127.0.0.1:47773
I0314 22:44:13.593582 125969 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(2)@127.0.0.1:47773
I0314 22:44:13.593588 125965 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.593581824+00:00
I0314 22:44:13.593621 125964 process.cpp:2494] Resuming crammd5_authenticator_session(2)@127.0.0.1:47773 at 2016-03-14 22:44:13.593614080+00:00
I0314 22:44:13.593646 125964 process.cpp:2599] Cleaning up crammd5_authenticator_session(2)@127.0.0.1:47773
I0314 22:44:13.593668 125965 process.cpp:2795] Donating thread to crammd5_authenticatee(2)@127.0.0.1:47773 while waiting
I0314 22:44:13.593729 125965 process.cpp:2494] Resuming crammd5_authenticatee(2)@127.0.0.1:47773 at 2016-03-14 22:44:13.593725952+00:00
I0314 22:44:13.593755 125965 process.cpp:2599] Cleaning up crammd5_authenticatee(2)@127.0.0.1:47773
I0314 22:44:13.593703 125970 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.593692928+00:00
I0314 22:44:13.593864 125964 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.593856000+00:00
I0314 22:44:13.593899 125965 slave.cpp:927] Successfully authenticated with master master@127.0.0.1:47773
I0314 22:44:13.594071 125966 process.cpp:2494] Resuming master@127.0.0.1:47773 at 2016-03-14 22:44:13.594063104+00:00
I0314 22:44:13.594071 125965 slave.cpp:1321] Will retry registration in 16.572431ms if necessary
I0314 22:44:13.594339 125966 master.cpp:4206] Registering slave at slave(1)@127.0.0.1:47773 (localhost) with id 470202dd-1d5c-40dc-b187-6bf18dead3e2-S0
I0314 22:44:13.594566 125970 process.cpp:2494] Resuming registrar(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.594557952+00:00
I0314 22:44:13.594934 125970 registrar.cpp:439] Applied 1 operations in 53488ns; attempting to update the 'registry'
I0314 22:44:13.596197 125965 process.cpp:2494] Resuming (3)@127.0.0.1:47773 at 2016-03-14 22:44:13.596188160+00:00
I0314 22:44:13.596415 125970 process.cpp:2484] Spawned process __latch__(9)@127.0.0.1:47773
I0314 22:44:13.596624 125970 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.596613888+00:00
I0314 22:44:13.596741 125970 process.cpp:2494] Resuming __latch__(9)@127.0.0.1:47773 at 2016-03-14 22:44:13.596733184+00:00
I0314 22:44:13.596782 125965 process.cpp:2494] Resuming log-writer(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.596772864+00:00
I0314 22:44:13.596829 125965 log.cpp:683] Attempting to append 327 bytes to the log
I0314 22:44:13.596915 125970 process.cpp:2494] Resuming log-coordinator(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.596905984+00:00
I0314 22:44:13.596971 125970 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
I0314 22:44:13.597100 125970 process.cpp:2484] Spawned process log-write(4)@127.0.0.1:47773
I0314 22:44:13.597121 125965 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.597110016+00:00
I0314 22:44:13.597127 125964 process.cpp:2494] Resuming log-write(4)@127.0.0.1:47773 at 2016-03-14 22:44:13.597118976+00:00
I0314 22:44:13.597334 125966 process.cpp:2494] Resuming (2)@127.0.0.1:47773 at 2016-03-14 22:44:13.597316096+00:00
I0314 22:44:13.597434 125966 process.cpp:2494] Resuming log-write(4)@127.0.0.1:47773 at 2016-03-14 22:44:13.597428992+00:00
I0314 22:44:13.597560 125964 process.cpp:2494] Resuming (2)@127.0.0.1:47773 at 2016-03-14 22:44:13.597552128+00:00
I0314 22:44:13.597684 125964 process.cpp:2484] Spawned process (30)@127.0.0.1:47773
I0314 22:44:13.597693 125966 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.597687040+00:00
I0314 22:44:13.597765 125966 process.cpp:2494] Resuming (30)@127.0.0.1:47773 at 2016-03-14 22:44:13.597761024+00:00
I0314 22:44:13.597793 125964 process.cpp:2494] Resuming log-write(4)@127.0.0.1:47773 at 2016-03-14 22:44:13.597785088+00:00
I0314 22:44:13.597836 125966 process.cpp:2494] Resuming log-replica(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.597830912+00:00
I0314 22:44:13.597877 125966 replica.cpp:537] Replica received write request for position 3 from (30)@127.0.0.1:47773
I0314 22:44:13.598467 125966 leveldb.cpp:341] Persisting action (346 bytes) to leveldb took 570751ns
I0314 22:44:13.598503 125966 replica.cpp:712] Persisted action at 3
I0314 22:44:13.598568 125966 process.cpp:2494] Resuming (30)@127.0.0.1:47773 at 2016-03-14 22:44:13.598563072+00:00
I0314 22:44:13.598673 125966 process.cpp:2599] Cleaning up (30)@127.0.0.1:47773
I0314 22:44:13.598688 125964 process.cpp:2494] Resuming log-write(4)@127.0.0.1:47773 at 2016-03-14 22:44:13.598679040+00:00
I0314 22:44:13.598754 125968 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.598742016+00:00
I0314 22:44:13.598798 125966 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.598790912+00:00
I0314 22:44:13.598814 125968 process.cpp:2494] Resuming log-coordinator(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.598808064+00:00
I0314 22:44:13.598875 125964 process.cpp:2599] Cleaning up log-write(4)@127.0.0.1:47773
I0314 22:44:13.598985 125964 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.598978048+00:00
I0314 22:44:13.598995 125970 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.598985984+00:00
I0314 22:44:13.599050 125964 process.cpp:2494] Resuming (2)@127.0.0.1:47773 at 2016-03-14 22:44:13.599044096+00:00
I0314 22:44:13.599131 125967 process.cpp:2494] Resuming log-replica(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.599122944+00:00
I0314 22:44:13.599189 125966 process.cpp:2494] Resuming log-coordinator(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.599181824+00:00
I0314 22:44:13.599189 125967 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
I0314 22:44:13.599854 125967 leveldb.cpp:341] Persisting action (348 bytes) to leveldb took 525129ns
I0314 22:44:13.599884 125967 replica.cpp:712] Persisted action at 3
I0314 22:44:13.599910 125967 replica.cpp:697] Replica learned APPEND action at position 3
I0314 22:44:13.600033 125964 process.cpp:2494] Resuming log-coordinator(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.600024064+00:00
I0314 22:44:13.600275 125969 process.cpp:2494] Resuming (3)@127.0.0.1:47773 at 2016-03-14 22:44:13.600264960+00:00
I0314 22:44:13.600769 125967 process.cpp:2494] Resuming __latch__(9)@127.0.0.1:47773 at 2016-03-14 22:44:13.600670976+00:00
I0314 22:44:13.600816 125967 process.cpp:2599] Cleaning up __latch__(9)@127.0.0.1:47773
I0314 22:44:13.600963 125967 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.600955904+00:00
I0314 22:44:13.601040 125967 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.601033984+00:00
I0314 22:44:13.601120 125967 process.cpp:2494] Resuming log-writer(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.601114112+00:00
I0314 22:44:13.600847 125966 process.cpp:2494] Resuming registrar(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.600840960+00:00
I0314 22:44:13.601182 125967 log.cpp:702] Attempting to truncate the log to 3
I0314 22:44:13.601258 125966 registrar.cpp:484] Successfully updated the 'registry' in 6.244864ms
I0314 22:44:13.601323 125967 process.cpp:2494] Resuming log-coordinator(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.601316096+00:00
I0314 22:44:13.601380 125967 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
I0314 22:44:13.601480 125967 process.cpp:2484] Spawned process log-write(5)@127.0.0.1:47773
I0314 22:44:13.601516 125966 process.cpp:2494] Resuming master@127.0.0.1:47773 at 2016-03-14 22:44:13.601506048+00:00
I0314 22:44:13.601626 125967 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.601618944+00:00
I0314 22:44:13.601670 125968 process.cpp:2494] Resuming log-write(5)@127.0.0.1:47773 at 2016-03-14 22:44:13.601663232+00:00
I0314 22:44:13.601811 125968 process.cpp:2494] Resuming (2)@127.0.0.1:47773 at 2016-03-14 22:44:13.601804032+00:00
I0314 22:44:13.601989 125968 process.cpp:2494] Resuming log-write(5)@127.0.0.1:47773 at 2016-03-14 22:44:13.601980928+00:00
I0314 22:44:13.602123 125965 process.cpp:2494] Resuming (2)@127.0.0.1:47773 at 2016-03-14 22:44:13.602110976+00:00
I0314 22:44:13.602216 125966 process.cpp:2484] Spawned process slave-observer(1)@127.0.0.1:47773
I0314 22:44:13.602241 125965 process.cpp:2484] Spawned process (31)@127.0.0.1:47773
I0314 22:44:13.602252 125968 process.cpp:2494] Resuming slave-observer(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.602243840+00:00
I0314 22:44:13.602324 125970 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.602312192+00:00
I0314 22:44:13.602372 125968 process.cpp:2494] Resuming (31)@127.0.0.1:47773 at 2016-03-14 22:44:13.602366976+00:00
I0314 22:44:13.602489 125970 process.cpp:2494] Resuming log-write(5)@127.0.0.1:47773 at 2016-03-14 22:44:13.602482944+00:00
I0314 22:44:13.602514 125968 process.cpp:2494] Resuming (1)@127.0.0.1:47773 at 2016-03-14 22:44:13.602507008+00:00
I0314 22:44:13.602519 125966 master.cpp:4274] Registered slave 470202dd-1d5c-40dc-b187-6bf18dead3e2-S0 at slave(1)@127.0.0.1:47773 (localhost) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0314 22:44:13.602382 125965 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.602375936+00:00
I0314 22:44:13.602649 125965 slave.cpp:3482] Received ping from slave-observer(1)@127.0.0.1:47773
I0314 22:44:13.602756 125968 hierarchical.cpp:473] Added slave 470202dd-1d5c-40dc-b187-6bf18dead3e2-S0 (localhost) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
I0314 22:44:13.602769 125966 process.cpp:2494] Resuming slave-observer(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.602760960+00:00
I0314 22:44:13.602809 125965 slave.cpp:971] Registered with master master@127.0.0.1:47773; given slave ID 470202dd-1d5c-40dc-b187-6bf18dead3e2-S0
I0314 22:44:13.602838 125965 fetcher.cpp:81] Clearing fetcher cache
I0314 22:44:13.602931 125966 process.cpp:2494] Resuming (24)@127.0.0.1:47773 at 2016-03-14 22:44:13.602923008+00:00
I0314 22:44:13.602977 125966 status_update_manager.cpp:181] Resuming sending status updates
I0314 22:44:13.603037 125965 slave.cpp:994] Checkpointing SlaveInfo to '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_Nh3m1O/meta/slaves/470202dd-1d5c-40dc-b187-6bf18dead3e2-S0/slave.info'
I0314 22:44:13.603250 125968 hierarchical.cpp:1427] Allocating cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 470202dd-1d5c-40dc-b187-6bf18dead3e2-S0 to framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:13.603281 125965 slave.cpp:1030] Forwarding total oversubscribed resources 
I0314 22:44:13.603370 125965 process.cpp:2494] Resuming master@127.0.0.1:47773 at 2016-03-14 22:44:13.603363072+00:00
I0314 22:44:13.603513 125965 master.cpp:4618] Received update of slave 470202dd-1d5c-40dc-b187-6bf18dead3e2-S0 at slave(1)@127.0.0.1:47773 (localhost) with total oversubscribed resources 
I0314 22:44:13.603567 125968 hierarchical.cpp:1548] No inverse offers to send out!
I0314 22:44:13.603611 125968 hierarchical.cpp:1150] Performed allocation for slave 470202dd-1d5c-40dc-b187-6bf18dead3e2-S0 in 808519ns
I0314 22:44:13.603701 125966 process.cpp:2494] Resuming (1)@127.0.0.1:47773 at 2016-03-14 22:44:13.603691008+00:00
I0314 22:44:13.603881 125966 hierarchical.cpp:531] Slave 470202dd-1d5c-40dc-b187-6bf18dead3e2-S0 (localhost) updated with oversubscribed resources  (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
I0314 22:44:13.603976 125966 hierarchical.cpp:1453] No resources available to allocate!
I0314 22:44:13.604007 125966 hierarchical.cpp:1548] No inverse offers to send out!
I0314 22:44:13.604024 125966 hierarchical.cpp:1150] Performed allocation for slave 470202dd-1d5c-40dc-b187-6bf18dead3e2-S0 in 112468ns
I0314 22:44:13.604123 125965 master.cpp:5324] Sending 1 offers to framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 (default) at scheduler-c577e1f5-4b58-41dd-bd3e-5b286e042a26@127.0.0.1:47773
I0314 22:44:13.602573 125970 process.cpp:2494] Resuming log-replica(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.602569216+00:00
I0314 22:44:13.604238 125970 replica.cpp:537] Replica received write request for position 4 from (31)@127.0.0.1:47773
I0314 22:44:13.604336 125969 process.cpp:2494] Resuming scheduler-c577e1f5-4b58-41dd-bd3e-5b286e042a26@127.0.0.1:47773 at 2016-03-14 22:44:13.604308992+00:00
I0314 22:44:13.604511 125969 pid.cpp:93] Attempting to parse 'master@127.0.0.1:47773' into a PID
I0314 22:44:13.604542 125969 sched.cpp:849] Received 1 offers
I0314 22:44:13.604552 125969 pid.cpp:93] Attempting to parse 'slave(1)@127.0.0.1:47773' into a PID
I0314 22:44:13.604715 125969 sched.cpp:873] Scheduler::resourceOffers took 81816ns
I0314 22:44:13.604737 125965 process.cpp:2494] Resuming __latch__(8)@127.0.0.1:47773 at 2016-03-14 22:44:13.604727040+00:00
I0314 22:44:13.604785 125965 process.cpp:2599] Cleaning up __latch__(8)@127.0.0.1:47773
I0314 22:44:13.604843 125970 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 578445ns
I0314 22:44:13.604856 125969 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.604849152+00:00
I0314 22:44:13.604900 125968 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.604892928+00:00
I0314 22:44:13.604902 125965 process.cpp:2494] Resuming __waiter__(3)@127.0.0.1:47773 at 2016-03-14 22:44:13.604896000+00:00
I0314 22:44:13.604874 125970 replica.cpp:712] Persisted action at 4
I0314 22:44:13.605010 125965 process.cpp:2599] Cleaning up __waiter__(3)@127.0.0.1:47773
I0314 22:44:13.605056 125970 process.cpp:2494] Resuming (31)@127.0.0.1:47773 at 2016-03-14 22:44:13.605047040+00:00
I0314 22:44:13.605101 125965 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.605094912+00:00
I0314 22:44:13.605134 125940 resources.cpp:572] Parsing resources as JSON failed: cpus:1;mem:128
Trying semicolon-delimited string format instead
I0314 22:44:13.605569 125940 process.cpp:2484] Spawned process __latch__(10)@127.0.0.1:47773
I0314 22:44:13.605641 125940 process.cpp:2484] Spawned process __waiter__(4)@127.0.0.1:47773
I0314 22:44:13.605690 125940 process.cpp:2795] Donating thread to __waiter__(4)@127.0.0.1:47773 while waiting
I0314 22:44:13.605725 125940 process.cpp:2494] Resuming __waiter__(4)@127.0.0.1:47773 at 2016-03-14 22:44:13.605718016+00:00
I0314 22:44:13.605891 125965 process.cpp:2494] Resuming scheduler-c577e1f5-4b58-41dd-bd3e-5b286e042a26@127.0.0.1:47773 at 2016-03-14 22:44:13.605884160+00:00
I0314 22:44:13.605928 125966 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.605922048+00:00
I0314 22:44:13.605953 125967 process.cpp:2494] Resuming __latch__(10)@127.0.0.1:47773 at 2016-03-14 22:44:13.605943808+00:00
I0314 22:44:13.605988 125964 process.cpp:2494] Resuming log-write(5)@127.0.0.1:47773 at 2016-03-14 22:44:13.605982976+00:00
I0314 22:44:13.606155 125964 process.cpp:2599] Cleaning up log-write(5)@127.0.0.1:47773
I0314 22:44:13.606199 125965 pid.cpp:93] Attempting to parse 'master@127.0.0.1:47773' into a PID
I0314 22:44:13.605897 125970 process.cpp:2599] Cleaning up (31)@127.0.0.1:47773
I0314 22:44:13.606271 125964 process.cpp:2494] Resuming log-coordinator(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.606264064+00:00
I0314 22:44:13.606333 125970 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.606326016+00:00
I0314 22:44:13.606389 125967 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.606381056+00:00
I0314 22:44:13.606456 125970 process.cpp:2494] Resuming (2)@127.0.0.1:47773 at 2016-03-14 22:44:13.606447872+00:00
I0314 22:44:13.606659 125967 process.cpp:2494] Resuming log-replica(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.606651136+00:00
I0314 22:44:13.606705 125966 process.cpp:2494] Resuming log-coordinator(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.606696960+00:00
I0314 22:44:13.606828 125967 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
I0314 22:44:13.606752 125965 process.cpp:2494] Resuming master@127.0.0.1:47773 at 2016-03-14 22:44:13.606742016+00:00
I0314 22:44:13.607794 125965 master.cpp:3104] Processing ACCEPT call for offers: [ 470202dd-1d5c-40dc-b187-6bf18dead3e2-O0 ] on slave 470202dd-1d5c-40dc-b187-6bf18dead3e2-S0 at slave(1)@127.0.0.1:47773 (localhost) for framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 (default) at scheduler-c577e1f5-4b58-41dd-bd3e-5b286e042a26@127.0.0.1:47773
I0314 22:44:13.607882 125965 master.cpp:2776] Authorizing framework principal 'test-principal' to launch task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac as user 'root'
I0314 22:44:13.608000 125964 process.cpp:2494] Resuming authorizer(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.607991040+00:00
I0314 22:44:13.608357 125965 process.cpp:2484] Spawned process (32)@127.0.0.1:47773
I0314 22:44:13.608402 125968 process.cpp:2494] Resuming (32)@127.0.0.1:47773 at 2016-03-14 22:44:13.608397056+00:00
I0314 22:44:13.607849 125967 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 990111ns
I0314 22:44:13.608654 125967 leveldb.cpp:399] Deleting ~2 keys from leveldb took 39349ns
I0314 22:44:13.608674 125967 replica.cpp:712] Persisted action at 4
I0314 22:44:13.608693 125967 replica.cpp:697] Replica learned TRUNCATE action at position 4
I0314 22:44:13.608803 125966 process.cpp:2494] Resuming log-coordinator(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.608797184+00:00
I0314 22:44:13.608372 125964 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.608364032+00:00
I0314 22:44:13.608883 125968 process.cpp:2599] Cleaning up (32)@127.0.0.1:47773
I0314 22:44:13.608803 125970 process.cpp:2494] Resuming master@127.0.0.1:47773 at 2016-03-14 22:44:13.608793856+00:00
I0314 22:44:13.609002 125968 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.608995072+00:00
I0314 22:44:13.609066 125968 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.609059072+00:00
I0314 22:44:13.609354 125968 process.cpp:2494] Resuming (3)@127.0.0.1:47773 at 2016-03-14 22:44:13.609345024+00:00
I0314 22:44:13.609921 125970 master.hpp:177] Adding task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac with resources cpus(*):1; mem(*):128 on slave 470202dd-1d5c-40dc-b187-6bf18dead3e2-S0 (localhost)
I0314 22:44:13.609997 125970 master.cpp:3589] Launching task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 (default) at scheduler-c577e1f5-4b58-41dd-bd3e-5b286e042a26@127.0.0.1:47773 with resources cpus(*):1; mem(*):128 on slave 470202dd-1d5c-40dc-b187-6bf18dead3e2-S0 at slave(1)@127.0.0.1:47773 (localhost)
I0314 22:44:13.610147 125966 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.610137856+00:00
I0314 22:44:13.610239 125970 process.cpp:2494] Resuming (1)@127.0.0.1:47773 at 2016-03-14 22:44:13.610228992+00:00
I0314 22:44:13.610327 125966 pid.cpp:93] Attempting to parse 'scheduler-c577e1f5-4b58-41dd-bd3e-5b286e042a26@127.0.0.1:47773' into a PID
I0314 22:44:13.610378 125966 slave.cpp:1361] Got assigned task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac for framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:13.610613 125970 hierarchical.cpp:890] Recovered cpus(*):1; mem(*):896; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):128) on slave 470202dd-1d5c-40dc-b187-6bf18dead3e2-S0 from framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:13.610692 125966 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
Trying semicolon-delimited string format instead
I0314 22:44:13.610688 125970 hierarchical.cpp:927] Framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 filtered slave 470202dd-1d5c-40dc-b187-6bf18dead3e2-S0 for 5secs
I0314 22:44:13.611297 125966 slave.cpp:1480] Launching task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac for framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:13.611378 125966 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
Trying semicolon-delimited string format instead
I0314 22:44:13.612838 125966 paths.cpp:528] Trying to chown '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_Nh3m1O/slaves/470202dd-1d5c-40dc-b187-6bf18dead3e2-S0/frameworks/470202dd-1d5c-40dc-b187-6bf18dead3e2-0000/executors/1b4f7496-87f0-4a38-b4e6-5b1b161f49ac/runs/42151d8b-eb47-4d52-9c90-194e8e0ff778' to user 'root'
I0314 22:44:13.620630 125966 slave.cpp:5367] Launching executor 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_Nh3m1O/slaves/470202dd-1d5c-40dc-b187-6bf18dead3e2-S0/frameworks/470202dd-1d5c-40dc-b187-6bf18dead3e2-0000/executors/1b4f7496-87f0-4a38-b4e6-5b1b161f49ac/runs/42151d8b-eb47-4d52-9c90-194e8e0ff778'
I0314 22:44:13.620873 125964 process.cpp:2494] Resuming files@127.0.0.1:47773 at 2016-03-14 22:44:13.620860160+00:00
I0314 22:44:13.621150 125968 process.cpp:2494] Resuming (22)@127.0.0.1:47773 at 2016-03-14 22:44:13.621131776+00:00
I0314 22:44:13.621279 125968 containerizer.cpp:666] Starting container '42151d8b-eb47-4d52-9c90-194e8e0ff778' for executor '1b4f7496-87f0-4a38-b4e6-5b1b161f49ac' of framework '470202dd-1d5c-40dc-b187-6bf18dead3e2-0000'
I0314 22:44:13.621384 125966 slave.cpp:1698] Queuing task '1b4f7496-87f0-4a38-b4e6-5b1b161f49ac' for executor '1b4f7496-87f0-4a38-b4e6-5b1b161f49ac' of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:13.621407 125968 process.cpp:2484] Spawned process (33)@127.0.0.1:47773
I0314 22:44:13.621686 125966 slave.cpp:749] Successfully attached file '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_Nh3m1O/slaves/470202dd-1d5c-40dc-b187-6bf18dead3e2-S0/frameworks/470202dd-1d5c-40dc-b187-6bf18dead3e2-0000/executors/1b4f7496-87f0-4a38-b4e6-5b1b161f49ac/runs/42151d8b-eb47-4d52-9c90-194e8e0ff778'
I0314 22:44:13.621726 125966 process.cpp:2494] Resuming (33)@127.0.0.1:47773 at 2016-03-14 22:44:13.621721088+00:00
I0314 22:44:13.621758 125966 process.cpp:2494] Resuming (19)@127.0.0.1:47773 at 2016-03-14 22:44:13.621753856+00:00
I0314 22:44:13.622045 125968 process.cpp:2484] Spawned process (34)@127.0.0.1:47773
I0314 22:44:13.622339 125968 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.622328064+00:00
I0314 22:44:13.622336 125966 process.cpp:2494] Resuming (16)@127.0.0.1:47773 at 2016-03-14 22:44:13.622326016+00:00
I0314 22:44:13.622460 125968 process.cpp:2494] Resuming (34)@127.0.0.1:47773 at 2016-03-14 22:44:13.622452992+00:00
I0314 22:44:13.622680 125968 process.cpp:2494] Resuming (15)@127.0.0.1:47773 at 2016-03-14 22:44:13.622672128+00:00
I0314 22:44:13.622740 125968 metadata_manager.cpp:159] Looking for image 'library/alpine'
I0314 22:44:13.624389 125968 process.cpp:2494] Resuming (19)@127.0.0.1:47773 at 2016-03-14 22:44:13.624378880+00:00
I0314 22:44:13.625488 125968 provisioner.cpp:285] Provisioning image rootfs '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_Nh3m1O/provisioner/containers/42151d8b-eb47-4d52-9c90-194e8e0ff778/backends/copy/rootfses/2d6bc517-ec01-452b-827e-17bbd1603652' for container 42151d8b-eb47-4d52-9c90-194e8e0ff778
I0314 22:44:13.625730 125966 process.cpp:2494] Resuming (17)@127.0.0.1:47773 at 2016-03-14 22:44:13.625710080+00:00
I0314 22:44:13.626127 125966 process.cpp:2484] Spawned process (35)@127.0.0.1:47773
I0314 22:44:13.626158 125967 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.626141952+00:00
I0314 22:44:13.626240 125966 copy.cpp:127] Copying layer path '/tmp/mesos/store/docker/layers/2a250d324882b789296fa2ce98083ed9685e6b5ed9afdb397648aed9b6cf04a4/rootfs' to rootfs '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_Nh3m1O/provisioner/containers/42151d8b-eb47-4d52-9c90-194e8e0ff778/backends/copy/rootfses/2d6bc517-ec01-452b-827e-17bbd1603652'
I0314 22:44:13.626277 125967 process.cpp:2494] Resuming (35)@127.0.0.1:47773 at 2016-03-14 22:44:13.626270976+00:00
I0314 22:44:13.626955 125967 process.cpp:2494] Resuming reaper(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.626921984+00:00
I0314 22:44:13.650053 125964 process.cpp:2494] Resuming reaper(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.650033920+00:00
I0314 22:44:13.650347 125967 process.cpp:2494] Resuming (35)@127.0.0.1:47773 at 2016-03-14 22:44:13.650337024+00:00
I0314 22:44:13.651031 125964 process.cpp:2494] Resuming (34)@127.0.0.1:47773 at 2016-03-14 22:44:13.651022848+00:00
I0314 22:44:13.651176 125967 process.cpp:2599] Cleaning up (35)@127.0.0.1:47773
I0314 22:44:13.651355 125967 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.651348224+00:00
I0314 22:44:13.651427 125965 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.651386880+00:00
I0314 22:44:13.652367 125968 process.cpp:2494] Resuming (21)@127.0.0.1:47773 at 2016-03-14 22:44:13.652348160+00:00
I0314 22:44:13.653733 125964 process.cpp:2599] Cleaning up (34)@127.0.0.1:47773
I0314 22:44:13.653879 125964 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.653872128+00:00
I0314 22:44:13.653960 125964 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.653953024+00:00
I0314 22:44:13.654131 125971 process.cpp:2494] Resuming (20)@127.0.0.1:47773 at 2016-03-14 22:44:13.654115840+00:00
I0314 22:44:13.654569 125970 process.cpp:2494] Resuming (22)@127.0.0.1:47773 at 2016-03-14 22:44:13.654553856+00:00
I0314 22:44:13.655182 125971 process.cpp:2494] Resuming (12)@127.0.0.1:47773 at 2016-03-14 22:44:13.655172096+00:00
I0314 22:44:13.694308 125970 linux_launcher.cpp:304] Cloning child process with flags = CLONE_NEWNS
I0314 22:44:13.717579 125971 process.cpp:2494] Resuming reaper(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.717487104+00:00
I0314 22:44:13.733368 125971 process.cpp:2494] Resuming reaper(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.733353984+00:00
I0314 22:44:13.734220 125968 process.cpp:2494] Resuming (21)@127.0.0.1:47773 at 2016-03-14 22:44:13.734172160+00:00
I0314 22:44:13.734388 125970 process.cpp:2484] Spawned process (36)@127.0.0.1:47773
I0314 22:44:13.734623 125968 process.cpp:2494] Resuming (20)@127.0.0.1:47773 at 2016-03-14 22:44:13.734615040+00:00
I0314 22:44:13.734733 125968 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.734728192+00:00
I0314 22:44:13.734807 125970 process.cpp:2494] Resuming (36)@127.0.0.1:47773 at 2016-03-14 22:44:13.734791936+00:00
I0314 22:44:13.735051 125968 process.cpp:2494] Resuming (22)@127.0.0.1:47773 at 2016-03-14 22:44:13.735043072+00:00
I0314 22:44:13.735110 125970 process.cpp:2599] Cleaning up (36)@127.0.0.1:47773
I0314 22:44:13.735213 125966 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.735187968+00:00
I0314 22:44:13.735237 125970 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.735230976+00:00
I0314 22:44:13.735585 125968 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.735572992+00:00
I0314 22:44:13.735888 125968 process.cpp:2494] Resuming (22)@127.0.0.1:47773 at 2016-03-14 22:44:13.735878912+00:00
I0314 22:44:13.752418 125966 process.cpp:2494] Resuming reaper(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.752405760+00:00
+ /home/uber/mesos-0.28.0-rc2/build/src/mesos-containerizer mount --help=false --operation=make-rslave --path=/
+ grep -E /tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_Nh3m1O/.+ /proc/self/mountinfo
+ grep -v 42151d8b-eb47-4d52-9c90-194e8e0ff778
+ + xargscut --no-run-if-empty -d  umount -f5 -l

I0314 22:44:13.853250 125968 process.cpp:2494] Resuming reaper(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.853234176+00:00
+ mount -n --rbind /tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_Nh3m1O/provisioner/containers/42151d8b-eb47-4d52-9c90-194e8e0ff778/backends/copy/rootfses/2d6bc517-ec01-452b-827e-17bbd1603652 /tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_Nh3m1O/slaves/470202dd-1d5c-40dc-b187-6bf18dead3e2-S0/frameworks/470202dd-1d5c-40dc-b187-6bf18dead3e2-0000/executors/1b4f7496-87f0-4a38-b4e6-5b1b161f49ac/runs/42151d8b-eb47-4d52-9c90-194e8e0ff778/.rootfs
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0314 22:44:13.919315 126058 process.cpp:2484] Spawned process __gc__@127.0.0.1:57130
I0314 22:44:13.919394 126122 process.cpp:2494] Resuming __gc__@127.0.0.1:57130 at 2016-03-14 22:44:13.919311104+00:00
I0314 22:44:13.919659 126058 process.cpp:2484] Spawned process help@127.0.0.1:57130
I0314 22:44:13.919689 126123 process.cpp:2494] Resuming __gc__@127.0.0.1:57130 at 2016-03-14 22:44:13.919665152+00:00
I0314 22:44:13.919736 126058 process.cpp:2484] Spawned process logging@127.0.0.1:57130
I0314 22:44:13.919788 126058 process.cpp:2484] Spawned process profiler@127.0.0.1:57130
I0314 22:44:13.919889 126058 process.cpp:2484] Spawned process system@127.0.0.1:57130
I0314 22:44:13.920048 126058 process.cpp:2484] Spawned process AuthenticationRouter(1)@127.0.0.1:57130
I0314 22:44:13.920114 126123 process.cpp:2494] Resuming help@127.0.0.1:57130 at 2016-03-14 22:44:13.920108032+00:00
I0314 22:44:13.920171 126058 process.cpp:2484] Spawned process metrics@127.0.0.1:57130
I0314 22:44:13.920222 126124 process.cpp:2494] Resuming logging@127.0.0.1:57130 at 2016-03-14 22:44:13.920196096+00:00
I0314 22:44:13.920271 126125 process.cpp:2494] Resuming profiler@127.0.0.1:57130 at 2016-03-14 22:44:13.920253952+00:00
I0314 22:44:13.920470 126122 process.cpp:2494] Resuming __processes__@127.0.0.1:57130 at 2016-03-14 22:44:13.920461824+00:00
I0314 22:44:13.920553 126124 process.cpp:2494] Resuming help@127.0.0.1:57130 at 2016-03-14 22:44:13.920545024+00:00
I0314 22:44:13.920584 126058 process.cpp:2484] Spawned process __processes__@127.0.0.1:57130
I0314 22:44:13.920620 126058 process.cpp:986] libprocess is initialized on 127.0.0.1:57130 for 8 cpus
I0314 22:44:13.920302 126126 process.cpp:2494] Resuming system@127.0.0.1:57130 at 2016-03-14 22:44:13.920286976+00:00
I0314 22:44:13.920717 126123 process.cpp:2494] Resuming (1)@127.0.0.1:57130 at 2016-03-14 22:44:13.920711168+00:00
I0314 22:44:13.920331 126127 process.cpp:2494] Resuming AuthenticationRouter(1)@127.0.0.1:57130 at 2016-03-14 22:44:13.920317952+00:00
I0314 22:44:13.920403 126128 process.cpp:2494] Resuming metrics@127.0.0.1:57130 at 2016-03-14 22:44:13.920346880+00:00
I0314 22:44:13.920910 126126 process.cpp:2494] Resuming help@127.0.0.1:57130 at 2016-03-14 22:44:13.920898816+00:00
I0314 22:44:13.921536 126058 process.cpp:2484] Spawned process (1)@127.0.0.1:57130
I0314 22:44:13.921952 126128 process.cpp:2494] Resuming __latch__(1)@127.0.0.1:57130 at 2016-03-14 22:44:13.921947904+00:00
I0314 22:44:13.921952 126126 process.cpp:2494] Resuming __gc__@127.0.0.1:57130 at 2016-03-14 22:44:13.921943808+00:00
I0314 22:44:13.921933 126058 process.cpp:2484] Spawned process __latch__(1)@127.0.0.1:57130
I0314 22:44:13.922121 126058 logging.cpp:193] Logging to STDERR
I0314 22:44:13.922238 126125 process.cpp:2494] Resuming __gc__@127.0.0.1:57130 at 2016-03-14 22:44:13.922231040+00:00
I0314 22:44:13.922382 126058 process.cpp:2484] Spawned process version@127.0.0.1:57130
I0314 22:44:13.922402 126122 process.cpp:2494] Resuming version@127.0.0.1:57130 at 2016-03-14 22:44:13.922393088+00:00
I0314 22:44:13.922474 126058 pid.cpp:93] Attempting to parse 'slave(1)@127.0.0.1:47773' into a PID
I0314 22:44:13.922543 126122 process.cpp:2494] Resuming help@127.0.0.1:57130 at 2016-03-14 22:44:13.922534912+00:00
I0314 22:44:13.923779 126058 exec.cpp:143] Version: 0.28.0
I0314 22:44:13.929811 126058 process.cpp:2484] Spawned process executor(1)@127.0.0.1:57130
I0314 22:44:13.929832 126127 process.cpp:2494] Resuming executor(1)@127.0.0.1:57130 at 2016-03-14 22:44:13.929824000+00:00
I0314 22:44:13.929939 126127 exec.cpp:193] Executor started at: executor(1)@127.0.0.1:57130 with pid 126058
I0314 22:44:13.931499 125972 pid.cpp:93] Attempting to parse 'executor(1)@127.0.0.1:57130' into a PID
I0314 22:44:13.931637 125972 process.cpp:612] Parsed message name 'mesos.internal.RegisterExecutorMessage' for slave(1)@127.0.0.1:47773 from executor(1)@127.0.0.1:57130
I0314 22:44:13.931949 125972 process.cpp:2484] Spawned process __http__(1)@127.0.0.1:47773
I0314 22:44:13.932076 125967 process.cpp:2494] Resuming __http__(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.932054016+00:00
I0314 22:44:13.932165 125967 process.cpp:2484] Spawned process (37)@127.0.0.1:47773
I0314 22:44:13.932202 125971 process.cpp:2494] Resuming (37)@127.0.0.1:47773 at 2016-03-14 22:44:13.932188928+00:00
I0314 22:44:13.932001 125969 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.931981056+00:00
I0314 22:44:13.932376 125969 slave.cpp:2643] Got registration for executor '1b4f7496-87f0-4a38-b4e6-5b1b161f49ac' of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 from executor(1)@127.0.0.1:57130
I0314 22:44:13.933568 125964 process.cpp:2494] Resuming (22)@127.0.0.1:47773 at 2016-03-14 22:44:13.933532928+00:00
I0314 22:44:13.932042 125965 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.932028928+00:00
I0314 22:44:13.933728 125965 process.cpp:2494] Resuming (21)@127.0.0.1:47773 at 2016-03-14 22:44:13.933721088+00:00
I0314 22:44:13.933768 125971 process.cpp:2494] Resuming (20)@127.0.0.1:47773 at 2016-03-14 22:44:13.933760000+00:00
I0314 22:44:13.933812 125964 process.cpp:2484] Spawned process (38)@127.0.0.1:47773
I0314 22:44:13.933851 125965 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.933844992+00:00
I0314 22:44:13.933856 125971 process.cpp:2494] Resuming (38)@127.0.0.1:47773 at 2016-03-14 22:44:13.933847808+00:00
I0314 22:44:13.934113 125970 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.934096128+00:00
I0314 22:44:13.934137 125971 process.cpp:2599] Cleaning up (38)@127.0.0.1:47773
I0314 22:44:13.934284 125971 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.934277888+00:00
I0314 22:44:13.934322 125966 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.934313984+00:00
I0314 22:44:13.934396 125970 slave.cpp:1863] Sending queued task '1b4f7496-87f0-4a38-b4e6-5b1b161f49ac' to executor '1b4f7496-87f0-4a38-b4e6-5b1b161f49ac' of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 at executor(1)@127.0.0.1:57130
I0314 22:44:13.934989 126130 pid.cpp:93] Attempting to parse 'slave(1)@127.0.0.1:47773' into a PID
I0314 22:44:13.935055 126130 process.cpp:612] Parsed message name 'mesos.internal.ExecutorRegisteredMessage' for executor(1)@127.0.0.1:57130 from slave(1)@127.0.0.1:47773
I0314 22:44:13.935144 126122 process.cpp:2494] Resuming executor(1)@127.0.0.1:57130 at 2016-03-14 22:44:13.935133952+00:00
I0314 22:44:13.935247 126130 process.cpp:2484] Spawned process __http__(1)@127.0.0.1:57130
I0314 22:44:13.935268 126124 process.cpp:2494] Resuming __gc__@127.0.0.1:57130 at 2016-03-14 22:44:13.935259136+00:00
I0314 22:44:13.935488 126122 exec.cpp:217] Executor registered on slave 470202dd-1d5c-40dc-b187-6bf18dead3e2-S0
I0314 22:44:13.935302 126123 process.cpp:2494] Resuming __http__(1)@127.0.0.1:57130 at 2016-03-14 22:44:13.935275008+00:00
I0314 22:44:13.935605 126123 process.cpp:2484] Spawned process (2)@127.0.0.1:57130
I0314 22:44:13.935628 126126 process.cpp:2494] Resuming (2)@127.0.0.1:57130 at 2016-03-14 22:44:13.935620096+00:00
I0314 22:44:13.935508 126130 pid.cpp:93] Attempting to parse 'slave(1)@127.0.0.1:47773' into a PID
I0314 22:44:13.935889 126130 process.cpp:612] Parsed message name 'mesos.internal.RunTaskMessage' for executor(1)@127.0.0.1:57130 from slave(1)@127.0.0.1:47773
I0314 22:44:13.937369 126122 exec.cpp:229] Executor::registered took 442521ns
I0314 22:44:13.937657 126128 process.cpp:2494] Resuming (1)@127.0.0.1:57130 at 2016-03-14 22:44:13.937648896+00:00
I0314 22:44:13.937669 126122 exec.cpp:304] Executor asked to run task '1b4f7496-87f0-4a38-b4e6-5b1b161f49ac'
Registered executor on localhost
I0314 22:44:13.937829 126122 exec.cpp:313] Executor::launchTask took 85533ns
I0314 22:44:13.937832 126125 process.cpp:2494] Resuming (1)@127.0.0.1:57130 at 2016-03-14 22:44:13.937825792+00:00
Starting task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac
I0314 22:44:13.954149 125964 process.cpp:2494] Resuming reaper(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.954135040+00:00
Forked command at 126136
I0314 22:44:13.963091 126125 process.cpp:2484] Spawned process reaper(1)@127.0.0.1:57130
I0314 22:44:13.963157 126126 process.cpp:2494] Resuming reaper(1)@127.0.0.1:57130 at 2016-03-14 22:44:13.963126016+00:00
I0314 22:44:13.964468 126125 process.cpp:2494] Resuming executor(1)@127.0.0.1:57130 at 2016-03-14 22:44:13.964454912+00:00
I0314 22:44:13.966416 126125 exec.cpp:526] Executor sending status update TASK_RUNNING (UUID: bae2a191-4241-427e-91e7-014006a22ba2) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:13.967195 125972 pid.cpp:93] Attempting to parse 'executor(1)@127.0.0.1:57130' into a PID
I0314 22:44:13.967252 125972 process.cpp:612] Parsed message name 'mesos.internal.StatusUpdateMessage' for slave(1)@127.0.0.1:47773 from executor(1)@127.0.0.1:57130
I0314 22:44:13.967330 125968 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.967319040+00:00
I0314 22:44:13.967512 125968 pid.cpp:93] Attempting to parse 'executor(1)@127.0.0.1:57130' into a PID
I0314 22:44:13.967577 125968 slave.cpp:3002] Handling status update TASK_RUNNING (UUID: bae2a191-4241-427e-91e7-014006a22ba2) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 from executor(1)@127.0.0.1:57130
I0314 22:44:13.967857 125967 process.cpp:2494] Resuming (22)@127.0.0.1:47773 at 2016-03-14 22:44:13.967848960+00:00
I0314 22:44:13.968026 125967 containerizer.cpp:1367] Serializing status request for container: 42151d8b-eb47-4d52-9c90-194e8e0ff778
I0314 22:44:13.968233 125965 process.cpp:2494] Resuming (33)@127.0.0.1:47773 at 2016-03-14 22:44:13.968222976+00:00
I0314 22:44:13.968060 125966 process.cpp:2494] Resuming (20)@127.0.0.1:47773 at 2016-03-14 22:44:13.968052992+00:00
I0314 22:44:13.968570 125965 process.cpp:2484] Spawned process (39)@127.0.0.1:47773
I0314 22:44:13.968600 125966 process.cpp:2494] Resuming (39)@127.0.0.1:47773 at 2016-03-14 22:44:13.968596992+00:00
I0314 22:44:13.968580 125969 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.968570112+00:00
I0314 22:44:13.968061 125971 process.cpp:2494] Resuming (21)@127.0.0.1:47773 at 2016-03-14 22:44:13.968050944+00:00
I0314 22:44:13.969110 125966 process.cpp:2494] Resuming (39)@127.0.0.1:47773 at 2016-03-14 22:44:13.969101056+00:00
I0314 22:44:13.969272 125966 containerizer.cpp:1344] Aggregating status for container: 42151d8b-eb47-4d52-9c90-194e8e0ff778
I0314 22:44:13.969457 125971 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.969448192+00:00
I0314 22:44:13.969529 125966 process.cpp:2599] Cleaning up (39)@127.0.0.1:47773
I0314 22:44:13.969686 125966 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.969680128+00:00
I0314 22:44:13.969758 125966 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.969752064+00:00
I0314 22:44:13.969939 125966 process.cpp:2494] Resuming (24)@127.0.0.1:47773 at 2016-03-14 22:44:13.969929984+00:00
I0314 22:44:13.969995 125966 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: bae2a191-4241-427e-91e7-014006a22ba2) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:13.970063 125966 status_update_manager.cpp:497] Creating StatusUpdate stream for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:13.970588 125966 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: bae2a191-4241-427e-91e7-014006a22ba2) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 to the slave
I0314 22:44:13.970955 125966 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.970941184+00:00
I0314 22:44:13.971062 125966 slave.cpp:3400] Forwarding the update TASK_RUNNING (UUID: bae2a191-4241-427e-91e7-014006a22ba2) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 to master@127.0.0.1:47773
I0314 22:44:13.971251 125971 process.cpp:2494] Resuming master@127.0.0.1:47773 at 2016-03-14 22:44:13.971243008+00:00
I0314 22:44:13.971251 125966 slave.cpp:3294] Status update manager successfully handled status update TASK_RUNNING (UUID: bae2a191-4241-427e-91e7-014006a22ba2) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:13.971454 125971 pid.cpp:93] Attempting to parse 'slave(1)@127.0.0.1:47773' into a PID
I0314 22:44:13.971460 125966 slave.cpp:3310] Sending acknowledgement for status update TASK_RUNNING (UUID: bae2a191-4241-427e-91e7-014006a22ba2) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 to executor(1)@127.0.0.1:57130
I0314 22:44:13.971544 125971 master.cpp:4763] Status update TASK_RUNNING (UUID: bae2a191-4241-427e-91e7-014006a22ba2) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 from slave 470202dd-1d5c-40dc-b187-6bf18dead3e2-S0 at slave(1)@127.0.0.1:47773 (localhost)
I0314 22:44:13.971592 125971 master.cpp:4811] Forwarding status update TASK_RUNNING (UUID: bae2a191-4241-427e-91e7-014006a22ba2) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:13.971747 125966 process.cpp:2494] Resuming scheduler-c577e1f5-4b58-41dd-bd3e-5b286e042a26@127.0.0.1:47773 at 2016-03-14 22:44:13.971739136+00:00
II0314 22:44:13.971783 125971 master.cpp:6421] Updating the state of task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
0314 22:44:13.972046 126130 pid.cpp:93] Attempting to parse 'slave(1)@127.0.0.1:47773' into a PID
I0314 22:44:13.972187 126130 process.cpp:612] Parsed message name 'mesos.internal.StatusUpdateAcknowledgementMessage' for executor(1)@127.0.0.1:57130 from slave(1)@127.0.0.1:47773
I0314 22:44:13.972295 126122 process.cpp:2494] Resuming executor(1)@127.0.0.1:57130 at 2016-03-14 22:44:13.972279040+00:00
I0314 22:44:13.972501 126122 exec.cpp:350] Executor received status update acknowledgement bae2a191-4241-427e-91e7-014006a22ba2 for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:13.972143 125966 pid.cpp:93] Attempting to parse 'slave(1)@127.0.0.1:47773' into a PID
I0314 22:44:13.972676 125966 pid.cpp:93] Attempting to parse 'master@127.0.0.1:47773' into a PID
I0314 22:44:13.972705 125966 sched.cpp:942] Received status update TASK_RUNNING (UUID: bae2a191-4241-427e-91e7-014006a22ba2) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 from slave(1)@127.0.0.1:47773
I0314 22:44:13.972864 125966 sched.cpp:981] Scheduler::statusUpdate took 91703ns
I0314 22:44:13.972915 125966 sched.cpp:1000] Sending ACK for status update TASK_RUNNING (UUID: bae2a191-4241-427e-91e7-014006a22ba2) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 to master@127.0.0.1:47773
I0314 22:44:13.972882 125968 process.cpp:2494] Resuming __latch__(10)@127.0.0.1:47773 at 2016-03-14 22:44:13.972871168+00:00
I0314 22:44:13.973011 125968 process.cpp:2599] Cleaning up __latch__(10)@127.0.0.1:47773
I0314 22:44:13.972975 125966 pid.cpp:93] Attempting to parse 'master@127.0.0.1:47773' into a PID
I0314 22:44:13.973314 125966 process.cpp:2494] Resuming master@127.0.0.1:47773 at 2016-03-14 22:44:13.973304064+00:00
I0314 22:44:13.973132 125969 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.973128192+00:00
I0314 22:44:13.973151 125964 process.cpp:2494] Resuming __waiter__(4)@127.0.0.1:47773 at 2016-03-14 22:44:13.973145856+00:00
I0314 22:44:13.973108 125965 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.973096960+00:00
I0314 22:44:13.973583 125964 process.cpp:2599] Cleaning up __waiter__(4)@127.0.0.1:47773
I0314 22:44:13.973685 125964 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:13.973680128+00:00
I0314 22:44:13.973775 125940 process.cpp:2484] Spawned process __latch__(11)@127.0.0.1:47773
I0314 22:44:13.973847 125940 process.cpp:2484] Spawned process __waiter__(5)@127.0.0.1:47773
I0314 22:44:13.973865 125966 master.cpp:3918] Processing ACKNOWLEDGE call bae2a191-4241-427e-91e7-014006a22ba2 for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 (default) at scheduler-c577e1f5-4b58-41dd-bd3e-5b286e042a26@127.0.0.1:47773 on slave 470202dd-1d5c-40dc-b187-6bf18dead3e2-S0
I0314 22:44:13.973901 125940 process.cpp:2795] Donating thread to __waiter__(5)@127.0.0.1:47773 while waiting
I0314 22:44:13.973906 125969 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:13.973900032+00:00
I0314 22:44:13.973966 125940 process.cpp:2494] Resuming __waiter__(5)@127.0.0.1:47773 at 2016-03-14 22:44:13.973961216+00:00
I0314 22:44:13.973925 125968 process.cpp:2494] Resuming __latch__(11)@127.0.0.1:47773 at 2016-03-14 22:44:13.973920000+00:00
I0314 22:44:13.974179 125966 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.974170880+00:00
I0314 22:44:13.974429 125964 process.cpp:2494] Resuming (24)@127.0.0.1:47773 at 2016-03-14 22:44:13.974419968+00:00
I0314 22:44:13.974483 125964 status_update_manager.cpp:392] Received status update acknowledgement (UUID: bae2a191-4241-427e-91e7-014006a22ba2) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:13.974706 125967 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:13.974695936+00:00
I0314 22:44:13.974762 125967 slave.cpp:2412] Status update manager successfully handled status update acknowledgement (UUID: bae2a191-4241-427e-91e7-014006a22ba2) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
Failed to change user to 'root': Failed to getgid: unknown user
I0314 22:44:14.055397 125964 process.cpp:2494] Resuming reaper(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.055376128+00:00
I0314 22:44:14.064918 126126 process.cpp:2494] Resuming reaper(1)@127.0.0.1:57130 at 2016-03-14 22:44:14.064902912+00:00
I0314 22:44:14.065284 126127 process.cpp:2494] Resuming (1)@127.0.0.1:57130 at 2016-03-14 22:44:14.065270016+00:00
Command terminated with signal Aborted (pid: 126136)
I0314 22:44:14.065564 126124 process.cpp:2494] Resuming executor(1)@127.0.0.1:57130 at 2016-03-14 22:44:14.065551104+00:00
I0314 22:44:14.066886 126124 exec.cpp:526] Executor sending status update TASK_FAILED (UUID: 5ec25dcb-3259-4e47-8fad-d2a82ac061c1) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:14.067512 125972 pid.cpp:93] Attempting to parse 'executor(1)@127.0.0.1:57130' into a PID
I0314 22:44:14.067570 125972 process.cpp:612] Parsed message name 'mesos.internal.StatusUpdateMessage' for slave(1)@127.0.0.1:47773 from executor(1)@127.0.0.1:57130
I0314 22:44:14.067657 125967 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.067648000+00:00
I0314 22:44:14.067787 125967 pid.cpp:93] Attempting to parse 'executor(1)@127.0.0.1:57130' into a PID
I0314 22:44:14.067881 125967 slave.cpp:3002] Handling status update TASK_FAILED (UUID: 5ec25dcb-3259-4e47-8fad-d2a82ac061c1) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 from executor(1)@127.0.0.1:57130
I0314 22:44:14.068075 125965 process.cpp:2494] Resuming (22)@127.0.0.1:47773 at 2016-03-14 22:44:14.068065792+00:00
I0314 22:44:14.068249 125967 process.cpp:2494] Resuming (21)@127.0.0.1:47773 at 2016-03-14 22:44:14.068235008+00:00
I0314 22:44:14.068279 125964 process.cpp:2494] Resuming (20)@127.0.0.1:47773 at 2016-03-14 22:44:14.068273152+00:00
I0314 22:44:14.068258 125965 containerizer.cpp:1367] Serializing status request for container: 42151d8b-eb47-4d52-9c90-194e8e0ff778
I0314 22:44:14.068398 125967 process.cpp:2494] Resuming (33)@127.0.0.1:47773 at 2016-03-14 22:44:14.068391168+00:00
I0314 22:44:14.068599 125967 process.cpp:2484] Spawned process (40)@127.0.0.1:47773
I0314 22:44:14.068620 125965 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.068610816+00:00
I0314 22:44:14.068630 125968 process.cpp:2494] Resuming (40)@127.0.0.1:47773 at 2016-03-14 22:44:14.068624128+00:00
I0314 22:44:14.068929 125968 containerizer.cpp:1344] Aggregating status for container: 42151d8b-eb47-4d52-9c90-194e8e0ff778
I0314 22:44:14.069066 125970 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.069051904+00:00
I0314 22:44:14.069200 125968 process.cpp:2599] Cleaning up (40)@127.0.0.1:47773
I0314 22:44:14.069216 125970 slave.cpp:5677] Terminating task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac
I0314 22:44:14.069355 125968 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.069348096+00:00
I0314 22:44:14.069437 125968 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.069430016+00:00
I0314 22:44:14.069599 125968 process.cpp:2494] Resuming (22)@127.0.0.1:47773 at 2016-03-14 22:44:14.069586944+00:00
I0314 22:44:14.069717 125969 process.cpp:2494] Resuming (21)@127.0.0.1:47773 at 2016-03-14 22:44:14.069708032+00:00
I0314 22:44:14.069773 125971 process.cpp:2494] Resuming (20)@127.0.0.1:47773 at 2016-03-14 22:44:14.069761024+00:00
I0314 22:44:14.069807 125968 process.cpp:2484] Spawned process (41)@127.0.0.1:47773
I0314 22:44:14.069828 125969 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.069821952+00:00
I0314 22:44:14.069845 125971 process.cpp:2494] Resuming (41)@127.0.0.1:47773 at 2016-03-14 22:44:14.069839104+00:00
I0314 22:44:14.070106 125968 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.070096128+00:00
I0314 22:44:14.070116 125971 process.cpp:2599] Cleaning up (41)@127.0.0.1:47773
I0314 22:44:14.070207 125969 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.070199040+00:00
I0314 22:44:14.070255 125971 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.070246912+00:00
I0314 22:44:14.070327 125969 process.cpp:2494] Resuming (24)@127.0.0.1:47773 at 2016-03-14 22:44:14.070308864+00:00
I0314 22:44:14.070360 125969 status_update_manager.cpp:320] Received status update TASK_FAILED (UUID: 5ec25dcb-3259-4e47-8fad-d2a82ac061c1) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:14.070518 125969 status_update_manager.cpp:374] Forwarding update TASK_FAILED (UUID: 5ec25dcb-3259-4e47-8fad-d2a82ac061c1) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 to the slave
I0314 22:44:14.070694 125971 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.070684928+00:00
I0314 22:44:14.070796 125971 slave.cpp:3400] Forwarding the update TASK_FAILED (UUID: 5ec25dcb-3259-4e47-8fad-d2a82ac061c1) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 to master@127.0.0.1:47773
I0314 22:44:14.070941 125969 process.cpp:2494] Resuming master@127.0.0.1:47773 at 2016-03-14 22:44:14.070925056+00:00
I0314 22:44:14.070948 125971 slave.cpp:3294] Status update manager successfully handled status update TASK_FAILED (UUID: 5ec25dcb-3259-4e47-8fad-d2a82ac061c1) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:14.070986 125971 slave.cpp:3310] Sending acknowledgement for status update TASK_FAILED (UUID: 5ec25dcb-3259-4e47-8fad-d2a82ac061c1) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 to executor(1)@127.0.0.1:57130
I0314 22:44:14.071048 125969 pid.cpp:93] Attempting to parse 'slave(1)@127.0.0.1:47773' into a PID
I0314 22:44:14.071116 125969 master.cpp:4763] Status update TASK_FAILED (UUID: 5ec25dcb-3259-4e47-8fad-d2a82ac061c1) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 from slave 470202dd-1d5c-40dc-b187-6bf18dead3e2-S0 at slave(1)@127.0.0.1:47773 (localhost)
I0314 22:44:14.071148 125969 master.cpp:4811] Forwarding status update TASK_FAILED (UUID: 5ec25dcb-3259-4e47-8fad-d2a82ac061c1) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:14.071296 125969 master.cpp:6421] Updating the state of task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 (latest state: TASK_FAILED, status update state: TASK_FAILED)
I0314 22:44:14.071344 125967 process.cpp:2494] Resuming scheduler-c577e1f5-4b58-41dd-bd3e-5b286e042a26@127.0.0.1:47773 at 2016-03-14 22:44:14.071333888+00:00
I0314 22:44:14.071449 125967 pid.cpp:93] Attempting to parse 'slave(1)@127.0.0.1:47773' into a PID
I0314 22:44:14.071493 125967 pid.cpp:93] Attempting to parse 'master@127.0.0.1:47773' into a PID
I0314 22:44:14.071518 125967 sched.cpp:942] Received status update TASK_FAILED (UUID: 5ec25dcb-3259-4e47-8fad-d2a82ac061c1) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 from slave(1)@127.0.0.1:47773
I0314 22:44:14.071538 125969 process.cpp:2494] Resuming (1)@127.0.0.1:47773 at 2016-03-14 22:44:14.071528960+00:00
I0314 22:44:14.071681 125967 sched.cpp:981] Scheduler::statusUpdate took 94473ns
I0314 22:44:14.071712 125967 sched.cpp:1000] Sending ACK for status update TASK_FAILED (UUID: 5ec25dcb-3259-4e47-8fad-d2a82ac061c1) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 to master@127.0.0.1:47773
I0314 22:44:14.071759 125967 pid.cpp:93] Attempting to parse 'master@127.0.0.1:47773' into a PID
I0314 22:44:14.071810 125969 hierarchical.cpp:890] Recovered cpus(*):1; mem(*):128 (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave 470202dd-1d5c-40dc-b187-6bf18dead3e2-S0 from framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
II0314 22:44:14.071841 125967 process.cpp:2494] Resuming __latch__(11)@127.0.0.1:47773 at 2016-03-14 22:44:14.071834112+00:00
I0314 22:44:14.071876 125970 process.cpp:2494] Resuming master@127.0.0.1:47773 at 2016-03-14 22:44:14.071866112+00:00
I0314 22:44:14.072070 125967 process.cpp:2599] Cleaning up __latch__(11)@127.0.0.1:47773
I0314 22:44:14.072227 125967 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.072220160+00:00
I0314 22:44:14.072259 125964 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.072253952+00:00
I0314 22:44:14.072299 125967 process.cpp:2494] Resuming __waiter__(5)@127.0.0.1:47773 at 2016-03-14 22:44:14.072293120+00:00
I0314 22:44:14.072224 125970 master.cpp:3918] Processing ACKNOWLEDGE call 5ec25dcb-3259-4e47-8fad-d2a82ac061c1 for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 (default) at scheduler-c577e1f5-4b58-41dd-bd3e-5b286e042a26@127.0.0.1:47773 on slave 470202dd-1d5c-40dc-b187-6bf18dead3e2-S0
0314 22:44:14.072018 126130 pid.cpp:93] Attempting to parse 'slave(1)@127.0.0.1:47773' into a PID
I0314 22:44:14.072358 125967 process.cpp:2599] Cleaning up __waiter__(5)@127.0.0.1:47773
I0314 22:44:14.072412 125970 master.cpp:6487] Removing task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac with resources cpus(*):1; mem(*):128 of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 on slave 470202dd-1d5c-40dc-b187-6bf18dead3e2-S0 at slave(1)@127.0.0.1:47773 (localhost)
I0314 22:44:14.072505 126130 process.cpp:612] Parsed message name 'mesos.internal.StatusUpdateAcknowledgementMessage' for executor(1)@127.0.0.1:57130 from slave(1)@127.0.0.1:47773
I0314 22:44:14.072782 126126 process.cpp:2494] Resuming executor(1)@127.0.0.1:57130 at 2016-03-14 22:44:14.072772096+00:00
../../src/tests/containerizer/provisioner_docker_tests.cpp:379: Failure
Value of: statusFinished->state()
  Actual: TASK_FAILED
Expected: TASK_FINISHED
I0314 22:44:14.072458 125967 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.072453120+00:00
I0314 22:44:14.072918 125940 sched.cpp:1903] Asked to stop the driver
I0314 22:44:14.072973 125967 process.cpp:2494] Resuming scheduler-c577e1f5-4b58-41dd-bd3e-5b286e042a26@127.0.0.1:47773 at 2016-03-14 22:44:14.072964864+00:00
I0314 22:44:14.072851 125970 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.072843008+00:00
I0314 22:44:14.073041 125967 sched.cpp:1143] Stopping framework '470202dd-1d5c-40dc-b187-6bf18dead3e2-0000'
I0314 22:44:14.073088 125967 pid.cpp:93] Attempting to parse 'master@127.0.0.1:47773' into a PID
I0314 22:44:14.073154 125967 process.cpp:2599] Cleaning up scheduler-c577e1f5-4b58-41dd-bd3e-5b286e042a26@127.0.0.1:47773
I0314 22:44:14.073186 125964 process.cpp:2494] Resuming master@127.0.0.1:47773 at 2016-03-14 22:44:14.073184000+00:00
I0314 22:44:14.073273 125964 master.cpp:5897] Processing TEARDOWN call for framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 (default) at scheduler-c577e1f5-4b58-41dd-bd3e-5b286e042a26@127.0.0.1:47773
I0314 22:44:14.073307 125965 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.073303040+00:00
I0314 22:44:14.073313 125964 master.cpp:5909] Removing framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 (default) at scheduler-c577e1f5-4b58-41dd-bd3e-5b286e042a26@127.0.0.1:47773
I0314 22:44:14.073385 125969 process.cpp:2494] Resuming (1)@127.0.0.1:47773 at 2016-03-14 22:44:14.073376768+00:00
I0314 22:44:14.073472 125969 hierarchical.cpp:375] Deactivated framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:14.072862 126126 exec.cpp:350] Executor received status update acknowledgement 5ec25dcb-3259-4e47-8fad-d2a82ac061c1 for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:14.073465 125968 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.073452032+00:00
I0314 22:44:14.073284 125967 process.cpp:2494] Resuming __latch__(7)@127.0.0.1:47773 at 2016-03-14 22:44:14.073278976+00:00
I0314 22:44:14.073603 125967 process.cpp:2599] Cleaning up __latch__(7)@127.0.0.1:47773
I0314 22:44:14.073631 125968 slave.cpp:2079] Asked to shut down framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 by master@127.0.0.1:47773
I0314 22:44:14.073668 125968 slave.cpp:2104] Shutting down framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:14.073725 125967 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.073719040+00:00
I0314 22:44:14.073787 125967 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.073783040+00:00
I0314 22:44:14.073848 125967 process.cpp:2494] Resuming metrics@127.0.0.1:47773 at 2016-03-14 22:44:14.073842176+00:00
I0314 22:44:14.073870 125968 slave.cpp:4198] Shutting down executor '1b4f7496-87f0-4a38-b4e6-5b1b161f49ac' of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 at executor(1)@127.0.0.1:57130
I0314 22:44:14.073891 125964 process.cpp:2494] Resuming (1)@127.0.0.1:47773 at 2016-03-14 22:44:14.073884928+00:00
I0314 22:44:14.074246 126130 pid.cpp:93] Attempting to parse 'slave(1)@127.0.0.1:47773' into a PID
I0314 22:44:14.074260 125968 process.cpp:2494] Resuming AuthenticationRouter(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.074249984+00:00
I0314 22:44:14.074342 126130 process.cpp:612] Parsed message name 'mesos.internal.ShutdownExecutorMessage' for executor(1)@127.0.0.1:57130 from slave(1)@127.0.0.1:47773
I0314 22:44:14.074448 125964 hierarchical.cpp:326] Removed framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:14.073163 125970 process.cpp:2494] Resuming (24)@127.0.0.1:47773 at 2016-03-14 22:44:14.073154816+00:00
I0314 22:44:14.074512 125970 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 5ec25dcb-3259-4e47-8fad-d2a82ac061c1) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:14.074517 126122 process.cpp:2494] Resuming executor(1)@127.0.0.1:57130 at 2016-03-14 22:44:14.074498816+00:00
I0314 22:44:14.074579 126122 exec.cpp:390] Executor asked to shutdown
I0314 22:44:14.074633 125970 status_update_manager.cpp:528] Cleaning up status update stream for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:14.074647 126122 process.cpp:2484] Spawned process (3)@127.0.0.1:57130
I0314 22:44:14.074678 126122 exec.cpp:405] Executor::shutdown took 7755ns
I0314 22:44:14.074699 126122 process.cpp:2494] Resuming __gc__@127.0.0.1:57130 at 2016-03-14 22:44:14.074695936+00:00
I0314 22:44:14.074785 126122 process.cpp:2494] Resuming (3)@127.0.0.1:57130 at 2016-03-14 22:44:14.074779904+00:00
I0314 22:44:14.074807 126122 exec.cpp:87] Scheduling shutdown of the executor in 5secs
I0314 22:44:14.074475 125968 process.cpp:2795] Donating thread to (6)@127.0.0.1:47773 while waiting
I0314 22:44:14.074908 125968 process.cpp:2494] Resuming (6)@127.0.0.1:47773 at 2016-03-14 22:44:14.074899968+00:00
I0314 22:44:14.074934 125968 process.cpp:2599] Cleaning up (6)@127.0.0.1:47773
I0314 22:44:14.074982 125970 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.074973952+00:00
I0314 22:44:14.075078 125970 slave.cpp:2412] Status update manager successfully handled status update acknowledgement (UUID: 5ec25dcb-3259-4e47-8fad-d2a82ac061c1) for task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:14.075125 125970 slave.cpp:5718] Completing task 1b4f7496-87f0-4a38-b4e6-5b1b161f49ac
I0314 22:44:14.074265 125940 process.cpp:2795] Donating thread to master@127.0.0.1:47773 while waiting
I0314 22:44:14.075187 125940 process.cpp:2494] Resuming master@127.0.0.1:47773 at 2016-03-14 22:44:14.075182080+00:00
I0314 22:44:14.075209 125940 master.cpp:1026] Master terminating
I0314 22:44:14.075289 125966 process.cpp:2494] Resuming (1)@127.0.0.1:47773 at 2016-03-14 22:44:14.075268864+00:00
I0314 22:44:14.075418 125940 process.cpp:2795] Donating thread to slave-observer(1)@127.0.0.1:47773 while waiting
I0314 22:44:14.075472 125940 process.cpp:2494] Resuming slave-observer(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.075465984+00:00
I0314 22:44:14.075498 125940 process.cpp:2599] Cleaning up slave-observer(1)@127.0.0.1:47773
I0314 22:44:14.075608 125966 hierarchical.cpp:505] Removed slave 470202dd-1d5c-40dc-b187-6bf18dead3e2-S0
I0314 22:44:14.075765 125940 process.cpp:2795] Donating thread to whitelist(1)@127.0.0.1:47773 while waiting
I0314 22:44:14.075798 125940 process.cpp:2494] Resuming whitelist(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.075793920+00:00
I0314 22:44:14.075820 125940 process.cpp:2599] Cleaning up whitelist(1)@127.0.0.1:47773
I0314 22:44:14.075920 125940 process.cpp:2795] Donating thread to crammd5_authenticator(1)@127.0.0.1:47773 while waiting
I0314 22:44:14.075955 125940 process.cpp:2494] Resuming crammd5_authenticator(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.075952128+00:00
I0314 22:44:14.075978 125940 process.cpp:2599] Cleaning up crammd5_authenticator(1)@127.0.0.1:47773
I0314 22:44:14.076144 125940 process.cpp:2599] Cleaning up master@127.0.0.1:47773
I0314 22:44:14.076321 125971 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.076308992+00:00
I0314 22:44:14.076360 125968 process.cpp:2494] Resuming metrics@127.0.0.1:47773 at 2016-03-14 22:44:14.076348928+00:00
I0314 22:44:14.076380 125971 slave.cpp:3528] master@127.0.0.1:47773 exited
W0314 22:44:14.076401 125971 slave.cpp:3531] Master disconnected! Waiting for a new master to be elected
I0314 22:44:14.075037 125964 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.075031040+00:00
I0314 22:44:14.077600 125940 process.cpp:2795] Donating thread to (1)@127.0.0.1:47773 while waiting
I0314 22:44:14.077764 125940 process.cpp:2494] Resuming (1)@127.0.0.1:47773 at 2016-03-14 22:44:14.077754880+00:00
I0314 22:44:14.077798 125940 process.cpp:2599] Cleaning up (1)@127.0.0.1:47773
I0314 22:44:14.077882 125965 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.077858048+00:00
I0314 22:44:14.077924 125969 process.cpp:2494] Resuming metrics@127.0.0.1:47773 at 2016-03-14 22:44:14.077913088+00:00
I0314 22:44:14.077944 125940 process.cpp:2795] Donating thread to authorizer(1)@127.0.0.1:47773 while waiting
I0314 22:44:14.077981 125940 process.cpp:2494] Resuming authorizer(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.077976832+00:00
I0314 22:44:14.078004 125940 process.cpp:2599] Cleaning up authorizer(1)@127.0.0.1:47773
I0314 22:44:14.078055 125967 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.078046976+00:00
I0314 22:44:14.078131 125965 process.cpp:2494] Resuming standalone-master-detector(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.078124032+00:00
I0314 22:44:14.078161 125965 process.cpp:2599] Cleaning up standalone-master-detector(1)@127.0.0.1:47773
I0314 22:44:14.078225 125965 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.078223104+00:00
I0314 22:44:14.078302 125940 process.cpp:2451] Dropping event for process master@127.0.0.1:47773
I0314 22:44:14.078418 125940 process.cpp:2451] Dropping event for process master@127.0.0.1:47773
I0314 22:44:14.078501 125970 process.cpp:2494] Resuming registrar(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.078490112+00:00
I0314 22:44:14.078541 125970 process.cpp:2599] Cleaning up registrar(1)@127.0.0.1:47773
I0314 22:44:14.078609 125964 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.078603008+00:00
I0314 22:44:14.078832 125970 process.cpp:2494] Resuming metrics@127.0.0.1:47773 at 2016-03-14 22:44:14.078823936+00:00
I0314 22:44:14.078866 125965 process.cpp:2494] Resuming (3)@127.0.0.1:47773 at 2016-03-14 22:44:14.078861056+00:00
I0314 22:44:14.078912 125965 process.cpp:2599] Cleaning up (3)@127.0.0.1:47773
I0314 22:44:14.079008 125965 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.079001856+00:00
I0314 22:44:14.079094 125969 process.cpp:2494] Resuming log-writer(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.079087104+00:00
I0314 22:44:14.079180 125969 process.cpp:2795] Donating thread to log-coordinator(1)@127.0.0.1:47773 while waiting
I0314 22:44:14.079224 125969 process.cpp:2494] Resuming log-coordinator(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.079219200+00:00
I0314 22:44:14.079262 125969 process.cpp:2599] Cleaning up log-coordinator(1)@127.0.0.1:47773
I0314 22:44:14.079335 125965 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.079328000+00:00
I0314 22:44:14.079367 125969 process.cpp:2599] Cleaning up log-writer(1)@127.0.0.1:47773
I0314 22:44:14.079452 125964 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.079442944+00:00
I0314 22:44:14.079591 125965 process.cpp:2494] Resuming log-reader(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.079582976+00:00
I0314 22:44:14.079632 125965 process.cpp:2599] Cleaning up log-reader(1)@127.0.0.1:47773
I0314 22:44:14.079699 125971 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.079688192+00:00
I0314 22:44:14.079759 125971 process.cpp:2494] Resuming log(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.079755008+00:00
I0314 22:44:14.079864 125971 process.cpp:2484] Spawned process __latch__(12)@127.0.0.1:47773
I0314 22:44:14.079886 125965 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.079878144+00:00
I0314 22:44:14.079897 125964 process.cpp:2494] Resuming __latch__(12)@127.0.0.1:47773 at 2016-03-14 22:44:14.079889920+00:00
I0314 22:44:14.079937 125971 process.cpp:2795] Donating thread to (2)@127.0.0.1:47773 while waiting
I0314 22:44:14.079942 125964 process.cpp:2599] Cleaning up __latch__(12)@127.0.0.1:47773
I0314 22:44:14.079991 125971 process.cpp:2494] Resuming (2)@127.0.0.1:47773 at 2016-03-14 22:44:14.079983872+00:00
I0314 22:44:14.080019 125971 process.cpp:2599] Cleaning up (2)@127.0.0.1:47773
I0314 22:44:14.080055 125969 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.080046848+00:00
I0314 22:44:14.080086 125965 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.080081920+00:00
I0314 22:44:14.080255 125964 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.080247040+00:00
I0314 22:44:14.080369 125971 process.cpp:2484] Spawned process __latch__(13)@127.0.0.1:47773
I0314 22:44:14.080386 125970 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.080378112+00:00
I0314 22:44:14.080474 125971 process.cpp:2795] Donating thread to log-replica(1)@127.0.0.1:47773 while waiting
I0314 22:44:14.080513 125971 process.cpp:2494] Resuming log-replica(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.080506112+00:00
I0314 22:44:14.080543 125971 process.cpp:2599] Cleaning up log-replica(1)@127.0.0.1:47773
I0314 22:44:14.080615 125970 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.080606976+00:00
I0314 22:44:14.080809 125971 process.cpp:2599] Cleaning up log(1)@127.0.0.1:47773
I0314 22:44:14.080895 125965 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.080887040+00:00
I0314 22:44:14.080401 125967 process.cpp:2494] Resuming __latch__(13)@127.0.0.1:47773 at 2016-03-14 22:44:14.080396032+00:00
I0314 22:44:14.080961 125967 process.cpp:2599] Cleaning up __latch__(13)@127.0.0.1:47773
I0314 22:44:14.081065 125967 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.081059840+00:00
I0314 22:44:14.081131 125967 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.081125888+00:00
I0314 22:44:14.081198 125967 process.cpp:2494] Resuming (22)@127.0.0.1:47773 at 2016-03-14 22:44:14.081192960+00:00
I0314 22:44:14.081255 125940 process.cpp:2484] Spawned process __latch__(14)@127.0.0.1:47773
I0314 22:44:14.081351 125940 process.cpp:2484] Spawned process __waiter__(6)@127.0.0.1:47773
I0314 22:44:14.081399 125940 process.cpp:2795] Donating thread to __waiter__(6)@127.0.0.1:47773 while waiting
I0314 22:44:14.081431 125940 process.cpp:2494] Resuming __waiter__(6)@127.0.0.1:47773 at 2016-03-14 22:44:14.081427200+00:00
I0314 22:44:14.081498 125967 process.cpp:2494] Resuming __latch__(14)@127.0.0.1:47773 at 2016-03-14 22:44:14.081491968+00:00
I0314 22:44:14.081292 125964 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.081286912+00:00
I0314 22:44:14.081538 125967 process.cpp:2599] Cleaning up __latch__(14)@127.0.0.1:47773
I0314 22:44:14.081614 125964 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.081607936+00:00
I0314 22:44:14.081668 125967 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.081661952+00:00
I0314 22:44:14.081683 125964 process.cpp:2494] Resuming __waiter__(6)@127.0.0.1:47773 at 2016-03-14 22:44:14.081679104+00:00
I0314 22:44:14.081763 125964 process.cpp:2599] Cleaning up __waiter__(6)@127.0.0.1:47773
I0314 22:44:14.081846 125966 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.081833984+00:00
I0314 22:44:14.081915 125966 process.cpp:2494] Resuming (22)@127.0.0.1:47773 at 2016-03-14 22:44:14.081910016+00:00
I0314 22:44:14.081954 125940 process.cpp:2484] Spawned process __latch__(15)@127.0.0.1:47773
I0314 22:44:14.081985 125969 process.cpp:2494] Resuming __latch__(15)@127.0.0.1:47773 at 2016-03-14 22:44:14.081981952+00:00
I0314 22:44:14.081959 125971 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.081952000+00:00
I0314 22:44:14.082028 125940 process.cpp:2484] Spawned process __waiter__(7)@127.0.0.1:47773
I0314 22:44:14.082077 125966 containerizer.cpp:1392] Destroying container '42151d8b-eb47-4d52-9c90-194e8e0ff778'
I0314 22:44:14.082053 125964 process.cpp:2494] Resuming __waiter__(7)@127.0.0.1:47773 at 2016-03-14 22:44:14.082048000+00:00
I0314 22:44:14.108803 125966 process.cpp:2484] Spawned process (42)@127.0.0.1:47773
I0314 22:44:14.108841 125968 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.108825088+00:00
I0314 22:44:14.108847 125971 process.cpp:2494] Resuming (42)@127.0.0.1:47773 at 2016-03-14 22:44:14.108838912+00:00
I0314 22:44:14.108918 125966 process.cpp:2484] Spawned process __latch__(16)@127.0.0.1:47773
I0314 22:44:14.109078 125971 process.cpp:2484] Spawned process (43)@127.0.0.1:47773
I0314 22:44:14.109246 125971 process.cpp:2484] Spawned process (44)@127.0.0.1:47773
I0314 22:44:14.109268 125970 process.cpp:2494] Resuming (44)@127.0.0.1:47773 at 2016-03-14 22:44:14.109260032+00:00
I0314 22:44:14.109117 125969 process.cpp:2494] Resuming (43)@127.0.0.1:47773 at 2016-03-14 22:44:14.109111040+00:00
I0314 22:44:14.109431 125969 cgroups.cpp:2427] Freezing cgroup /sys/fs/cgroup/freezer/mesos/42151d8b-eb47-4d52-9c90-194e8e0ff778
I0314 22:44:14.109088 125967 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.109081856+00:00
I0314 22:44:14.109527 125969 process.cpp:2484] Spawned process (45)@127.0.0.1:47773
I0314 22:44:14.109544 125968 process.cpp:2494] Resuming (45)@127.0.0.1:47773 at 2016-03-14 22:44:14.109534976+00:00
I0314 22:44:14.109623 125969 process.cpp:2484] Spawned process __latch__(17)@127.0.0.1:47773
I0314 22:44:14.109737 125967 process.cpp:2494] Resuming __latch__(17)@127.0.0.1:47773 at 2016-03-14 22:44:14.109731072+00:00
I0314 22:44:14.108933 125965 process.cpp:2494] Resuming __latch__(16)@127.0.0.1:47773 at 2016-03-14 22:44:14.108925952+00:00
I0314 22:44:14.155272 125968 cgroups.cpp:1409] Successfully froze cgroup /sys/fs/cgroup/freezer/mesos/42151d8b-eb47-4d52-9c90-194e8e0ff778 after 45.780736ms
I0314 22:44:14.155519 125968 process.cpp:2599] Cleaning up (45)@127.0.0.1:47773
I0314 22:44:14.155676 125968 process.cpp:2494] Resuming __latch__(17)@127.0.0.1:47773 at 2016-03-14 22:44:14.155670016+00:00
I0314 22:44:14.155720 125968 process.cpp:2599] Cleaning up __latch__(17)@127.0.0.1:47773
I0314 22:44:14.155803 125968 process.cpp:2494] Resuming (43)@127.0.0.1:47773 at 2016-03-14 22:44:14.155798016+00:00
I0314 22:44:14.155884 125969 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.155875840+00:00
I0314 22:44:14.155882 125967 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.155872000+00:00
I0314 22:44:14.156499 125969 process.cpp:2494] Resuming reaper(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.156475136+00:00
I0314 22:44:14.171064 125965 process.cpp:2494] Resuming reaper(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.171053056+00:00
I0314 22:44:14.200669 125968 cgroups.cpp:2445] Thawing cgroup /sys/fs/cgroup/freezer/mesos/42151d8b-eb47-4d52-9c90-194e8e0ff778
I0314 22:44:14.200781 125968 process.cpp:2484] Spawned process (46)@127.0.0.1:47773
I0314 22:44:14.200808 125965 process.cpp:2494] Resuming (46)@127.0.0.1:47773 at 2016-03-14 22:44:14.200800768+00:00
I0314 22:44:14.200803 125967 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.200793088+00:00
I0314 22:44:14.235239 125965 cgroups.cpp:1438] Successfullly thawed cgroup /sys/fs/cgroup/freezer/mesos/42151d8b-eb47-4d52-9c90-194e8e0ff778 after 34.497024ms
I0314 22:44:14.235410 125968 process.cpp:2494] Resuming (43)@127.0.0.1:47773 at 2016-03-14 22:44:14.235398912+00:00
I0314 22:44:14.235584 125968 process.cpp:2484] Spawned process (47)@127.0.0.1:47773
I0314 22:44:14.235608 125965 process.cpp:2599] Cleaning up (46)@127.0.0.1:47773
I0314 22:44:14.235604 125967 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.235595008+00:00
I0314 22:44:14.235693 125970 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.235685120+00:00
I0314 22:44:14.235869 125971 process.cpp:2494] Resuming (47)@127.0.0.1:47773 at 2016-03-14 22:44:14.235627008+00:00
I0314 22:44:14.252521 125968 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.252510976+00:00
I0314 22:44:14.252606 125968 slave.cpp:3528] executor(1)@127.0.0.1:57130 exited
I0314 22:44:14.252837 125967 process.cpp:2494] Resuming __http__(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.252829184+00:00
I0314 22:44:14.252866 125967 process.cpp:2599] Cleaning up __http__(1)@127.0.0.1:47773
I0314 22:44:14.252956 125967 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.252950784+00:00
I0314 22:44:14.253010 125967 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.253006848+00:00
I0314 22:44:14.253100 125967 process.cpp:2795] Donating thread to (37)@127.0.0.1:47773 while waiting
I0314 22:44:14.253118 125967 process.cpp:2494] Resuming (37)@127.0.0.1:47773 at 2016-03-14 22:44:14.253114880+00:00
I0314 22:44:14.253134 125967 process.cpp:2599] Cleaning up (37)@127.0.0.1:47773
I0314 22:44:14.253255 125967 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.253249024+00:00
I0314 22:44:14.257190 125967 process.cpp:2494] Resuming reaper(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.257180928+00:00
I0314 22:44:14.257371 125964 process.cpp:2494] Resuming (47)@127.0.0.1:47773 at 2016-03-14 22:44:14.257360896+00:00
I0314 22:44:14.257527 125964 process.cpp:2599] Cleaning up (47)@127.0.0.1:47773
I0314 22:44:14.257527 125967 process.cpp:2494] Resuming (22)@127.0.0.1:47773 at 2016-03-14 22:44:14.257522176+00:00
I0314 22:44:14.257594 125967 containerizer.cpp:1608] Executor for container '42151d8b-eb47-4d52-9c90-194e8e0ff778' has exited
I0314 22:44:14.257630 125967 process.cpp:2494] Resuming (43)@127.0.0.1:47773 at 2016-03-14 22:44:14.257623808+00:00
I0314 22:44:14.257647 125964 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.257640960+00:00
I0314 22:44:14.257696 125964 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.257692160+00:00
I0314 22:44:14.267269 125964 process.cpp:2494] Resuming (44)@127.0.0.1:47773 at 2016-03-14 22:44:14.267260928+00:00
I0314 22:44:14.267277 125967 process.cpp:2599] Cleaning up (43)@127.0.0.1:47773
I0314 22:44:14.267400 125967 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.267393024+00:00
I0314 22:44:14.267400 125969 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.267376896+00:00
I0314 22:44:14.267462 125965 process.cpp:2494] Resuming (42)@127.0.0.1:47773 at 2016-03-14 22:44:14.267448832+00:00
I0314 22:44:14.267470 125964 process.cpp:2599] Cleaning up (44)@127.0.0.1:47773
I0314 22:44:14.267577 125971 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.267566848+00:00
I0314 22:44:14.267611 125970 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.267601920+00:00
I0314 22:44:14.267923 125964 process.cpp:2494] Resuming __latch__(16)@127.0.0.1:47773 at 2016-03-14 22:44:14.267913984+00:00
I0314 22:44:14.267956 125964 process.cpp:2599] Cleaning up __latch__(16)@127.0.0.1:47773
I0314 22:44:14.268040 125971 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.268029952+00:00
I0314 22:44:14.268066 125967 process.cpp:2494] Resuming (22)@127.0.0.1:47773 at 2016-03-14 22:44:14.268017920+00:00
I0314 22:44:14.268044 125969 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.268039936+00:00
I0314 22:44:14.268277 125965 process.cpp:2599] Cleaning up (42)@127.0.0.1:47773
I0314 22:44:14.268461 125965 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.268454912+00:00
I0314 22:44:14.268535 125965 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.268528896+00:00
I0314 22:44:14.268790 125965 process.cpp:2494] Resuming (20)@127.0.0.1:47773 at 2016-03-14 22:44:14.268784128+00:00
I0314 22:44:14.268860 125967 process.cpp:2484] Spawned process (48)@127.0.0.1:47773
I0314 22:44:14.268867 125965 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.268861952+00:00
I0314 22:44:14.268968 125965 process.cpp:2494] Resuming (48)@127.0.0.1:47773 at 2016-03-14 22:44:14.268963072+00:00
I0314 22:44:14.269213 125965 process.cpp:2599] Cleaning up (48)@127.0.0.1:47773
I0314 22:44:14.269291 125965 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.269287168+00:00
I0314 22:44:14.269353 125965 process.cpp:2494] Resuming (21)@127.0.0.1:47773 at 2016-03-14 22:44:14.269349120+00:00
I0314 22:44:14.269366 125967 process.cpp:2484] Spawned process (49)@127.0.0.1:47773
I0314 22:44:14.269526 125967 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.269517056+00:00
I0314 22:44:14.269556 125970 process.cpp:2494] Resuming (49)@127.0.0.1:47773 at 2016-03-14 22:44:14.269548800+00:00
I0314 22:44:14.269289 125966 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.269280000+00:00
I0314 22:44:14.278504 125972 process.cpp:2451] Dropping event for process (1)@127.0.0.1:47773
I0314 22:44:14.293824 125965 linux.cpp:814] Ignoring unmounting sandbox/work directory for container 42151d8b-eb47-4d52-9c90-194e8e0ff778
I0314 22:44:14.294621 125965 process.cpp:2494] Resuming (49)@127.0.0.1:47773 at 2016-03-14 22:44:14.294610944+00:00
I0314 22:44:14.294838 125971 process.cpp:2494] Resuming (22)@127.0.0.1:47773 at 2016-03-14 22:44:14.294828032+00:00
I0314 22:44:14.294864 125965 process.cpp:2599] Cleaning up (49)@127.0.0.1:47773
I0314 22:44:14.294965 125965 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.294960128+00:00
I0314 22:44:14.295022 125965 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.295015168+00:00
I0314 22:44:14.295073 125971 process.cpp:2494] Resuming (19)@127.0.0.1:47773 at 2016-03-14 22:44:14.295066112+00:00
I0314 22:44:14.295194 125971 provisioner.cpp:330] Destroying container rootfs at '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_Nh3m1O/provisioner/containers/42151d8b-eb47-4d52-9c90-194e8e0ff778/backends/copy/rootfses/2d6bc517-ec01-452b-827e-17bbd1603652' for container 42151d8b-eb47-4d52-9c90-194e8e0ff778
I0314 22:44:14.295277 125965 process.cpp:2494] Resuming (17)@127.0.0.1:47773 at 2016-03-14 22:44:14.295269120+00:00
I0314 22:44:14.295394 125971 process.cpp:2484] Spawned process (50)@127.0.0.1:47773
I0314 22:44:14.296169 125970 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.295421952+00:00
I0314 22:44:14.296298 125969 process.cpp:2494] Resuming (50)@127.0.0.1:47773 at 2016-03-14 22:44:14.295429888+00:00
I0314 22:44:14.297312 125964 process.cpp:2494] Resuming reaper(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.297275136+00:00
I0314 22:44:14.358111 125968 process.cpp:2494] Resuming reaper(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.358076160+00:00
I0314 22:44:14.358516 125971 process.cpp:2494] Resuming (50)@127.0.0.1:47773 at 2016-03-14 22:44:14.358501888+00:00
I0314 22:44:14.358829 125971 process.cpp:2599] Cleaning up (50)@127.0.0.1:47773
I0314 22:44:14.359009 125971 process.cpp:2494] Resuming (19)@127.0.0.1:47773 at 2016-03-14 22:44:14.359002112+00:00
I0314 22:44:14.359410 125971 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.359400960+00:00
I0314 22:44:14.359467 125971 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.359462912+00:00
I0314 22:44:14.359561 125971 process.cpp:2494] Resuming (22)@127.0.0.1:47773 at 2016-03-14 22:44:14.359555840+00:00
I0314 22:44:14.359884 125971 process.cpp:2795] Donating thread to (33)@127.0.0.1:47773 while waiting
I0314 22:44:14.359905 125971 process.cpp:2494] Resuming (33)@127.0.0.1:47773 at 2016-03-14 22:44:14.359901952+00:00
I0314 22:44:14.359922 125971 process.cpp:2599] Cleaning up (33)@127.0.0.1:47773
I0314 22:44:14.360069 125971 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.360061952+00:00
I0314 22:44:14.360133 125971 slave.cpp:3886] Executor '1b4f7496-87f0-4a38-b4e6-5b1b161f49ac' of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 terminated with signal Killed
I0314 22:44:14.360203 125969 process.cpp:2494] Resuming __latch__(15)@127.0.0.1:47773 at 2016-03-14 22:44:14.360194816+00:00
I0314 22:44:14.360226 125969 process.cpp:2599] Cleaning up __latch__(15)@127.0.0.1:47773
I0314 22:44:14.360224 125970 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.360208896+00:00
I0314 22:44:14.360302 125970 process.cpp:2494] Resuming __waiter__(7)@127.0.0.1:47773 at 2016-03-14 22:44:14.360296960+00:00
I0314 22:44:14.360357 125964 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.360349952+00:00
I0314 22:44:14.360436 125970 process.cpp:2599] Cleaning up __waiter__(7)@127.0.0.1:47773
I0314 22:44:14.360466 125971 slave.cpp:3990] Cleaning up executor '1b4f7496-87f0-4a38-b4e6-5b1b161f49ac' of framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000 at executor(1)@127.0.0.1:57130
I0314 22:44:14.360509 125970 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.360505088+00:00
I0314 22:44:14.360594 125970 process.cpp:2494] Resuming (22)@127.0.0.1:47773 at 2016-03-14 22:44:14.360587008+00:00
I0314 22:44:14.360666 125940 process.cpp:2484] Spawned process __latch__(18)@127.0.0.1:47773
I0314 22:44:14.360729 125940 process.cpp:2484] Spawned process __waiter__(8)@127.0.0.1:47773
I0314 22:44:14.360751 125970 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.360743936+00:00
I0314 22:44:14.360772 125940 process.cpp:2795] Donating thread to __waiter__(8)@127.0.0.1:47773 while waiting
I0314 22:44:14.360790 125940 process.cpp:2494] Resuming __waiter__(8)@127.0.0.1:47773 at 2016-03-14 22:44:14.360784896+00:00
I0314 22:44:14.360899 125971 slave.cpp:4078] Cleaning up framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:14.360923 125970 process.cpp:2494] Resuming __latch__(18)@127.0.0.1:47773 at 2016-03-14 22:44:14.360918016+00:00
I0314 22:44:14.360941 125970 process.cpp:2599] Cleaning up __latch__(18)@127.0.0.1:47773
I0314 22:44:14.361006 125969 process.cpp:2494] Resuming (23)@127.0.0.1:47773 at 2016-03-14 22:44:14.361001984+00:00
I0314 22:44:14.361032 125964 process.cpp:2494] Resuming (24)@127.0.0.1:47773 at 2016-03-14 22:44:14.361024000+00:00
I0314 22:44:14.361053 125970 process.cpp:2494] Resuming __gc__@127.0.0.1:47773 at 2016-03-14 22:44:14.361049856+00:00
I0314 22:44:14.361037 125965 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.361024000+00:00
I0314 22:44:14.361050 125969 gc.cpp:55] Scheduling '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_Nh3m1O/slaves/470202dd-1d5c-40dc-b187-6bf18dead3e2-S0/frameworks/470202dd-1d5c-40dc-b187-6bf18dead3e2-0000/executors/1b4f7496-87f0-4a38-b4e6-5b1b161f49ac/runs/42151d8b-eb47-4d52-9c90-194e8e0ff778' for gc 6.99999582584593days in the future
I0314 22:44:14.361081 125964 status_update_manager.cpp:282] Closing status update streams for framework 470202dd-1d5c-40dc-b187-6bf18dead3e2-0000
I0314 22:44:14.361110 125965 process.cpp:2494] Resuming __waiter__(8)@127.0.0.1:47773 at 2016-03-14 22:44:14.361104896+00:00
I0314 22:44:14.361155 125965 process.cpp:2599] Cleaning up __waiter__(8)@127.0.0.1:47773
I0314 22:44:14.361233 125964 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.361224960+00:00
I0314 22:44:14.361294 125969 gc.cpp:55] Scheduling '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_Nh3m1O/slaves/470202dd-1d5c-40dc-b187-6bf18dead3e2-S0/frameworks/470202dd-1d5c-40dc-b187-6bf18dead3e2-0000/executors/1b4f7496-87f0-4a38-b4e6-5b1b161f49ac' for gc 6.99999582408593days in the future
I0314 22:44:14.361526 125971 process.cpp:2494] Resuming (23)@127.0.0.1:47773 at 2016-03-14 22:44:14.361517056+00:00
I0314 22:44:14.361567 125940 process.cpp:2795] Donating thread to slave(1)@127.0.0.1:47773 while waiting
I0314 22:44:14.361580 125971 gc.cpp:55] Scheduling '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_Nh3m1O/slaves/470202dd-1d5c-40dc-b187-6bf18dead3e2-S0/frameworks/470202dd-1d5c-40dc-b187-6bf18dead3e2-0000' for gc 6.99999582201481days in the future
I0314 22:44:14.361594 125940 process.cpp:2494] Resuming slave(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.361588992+00:00
I0314 22:44:14.361614 125940 slave.cpp:668] Slave terminating
I0314 22:44:14.361701 125940 process.cpp:2599] Cleaning up slave(1)@127.0.0.1:47773
I0314 22:44:14.361765 125971 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.361757952+00:00
I0314 22:44:14.361802 125940 process.cpp:2795] Donating thread to monitor@127.0.0.1:47773 while waiting
I0314 22:44:14.361817 125940 process.cpp:2494] Resuming monitor@127.0.0.1:47773 at 2016-03-14 22:44:14.361815040+00:00
I0314 22:44:14.361829 125940 process.cpp:2599] Cleaning up monitor@127.0.0.1:47773
I0314 22:44:14.361871 125965 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.361861888+00:00
I0314 22:44:14.361922 125940 process.cpp:2795] Donating thread to __limiter__(1)@127.0.0.1:47773 while waiting
I0314 22:44:14.361946 125940 process.cpp:2494] Resuming __limiter__(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.361942016+00:00
I0314 22:44:14.361959 125940 process.cpp:2599] Cleaning up __limiter__(1)@127.0.0.1:47773
I0314 22:44:14.362016 125969 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.362009088+00:00
I0314 22:44:14.362067 125969 process.cpp:2494] Resuming metrics@127.0.0.1:47773 at 2016-03-14 22:44:14.362063872+00:00
I0314 22:44:14.362601 125940 process.cpp:2795] Donating thread to (22)@127.0.0.1:47773 while waiting
I0314 22:44:14.362622 125940 process.cpp:2494] Resuming (22)@127.0.0.1:47773 at 2016-03-14 22:44:14.362617088+00:00
I0314 22:44:14.362632 125940 process.cpp:2599] Cleaning up (22)@127.0.0.1:47773
I0314 22:44:14.362718 125940 process.cpp:2795] Donating thread to (21)@127.0.0.1:47773 while waiting
I0314 22:44:14.362733 125940 process.cpp:2494] Resuming (21)@127.0.0.1:47773 at 2016-03-14 22:44:14.362729984+00:00
I0314 22:44:14.362743 125940 process.cpp:2599] Cleaning up (21)@127.0.0.1:47773
I0314 22:44:14.362911 125940 process.cpp:2795] Donating thread to (20)@127.0.0.1:47773 while waiting
I0314 22:44:14.362929 125940 process.cpp:2494] Resuming (20)@127.0.0.1:47773 at 2016-03-14 22:44:14.362926080+00:00
I0314 22:44:14.362964 125964 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.362960128+00:00
I0314 22:44:14.363109 125940 process.cpp:2599] Cleaning up (20)@127.0.0.1:47773
I0314 22:44:14.363188 125968 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.363174912+00:00
I0314 22:44:14.363288 125970 process.cpp:2494] Resuming (19)@127.0.0.1:47773 at 2016-03-14 22:44:14.363276032+00:00
I0314 22:44:14.363317 125970 process.cpp:2599] Cleaning up (19)@127.0.0.1:47773
I0314 22:44:14.363379 125968 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.363374080+00:00
I0314 22:44:14.363435 125968 process.cpp:2494] Resuming metrics@127.0.0.1:47773 at 2016-03-14 22:44:14.363430912+00:00
I0314 22:44:14.363484 125970 process.cpp:2494] Resuming (18)@127.0.0.1:47773 at 2016-03-14 22:44:14.363475968+00:00
I0314 22:44:14.363526 125970 process.cpp:2599] Cleaning up (18)@127.0.0.1:47773
I0314 22:44:14.363581 125965 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.363569920+00:00
I0314 22:44:14.363669 125968 process.cpp:2494] Resuming metrics@127.0.0.1:47773 at 2016-03-14 22:44:14.363663872+00:00
I0314 22:44:14.363708 125940 process.cpp:2795] Donating thread to (17)@127.0.0.1:47773 while waiting
I0314 22:44:14.363744 125940 process.cpp:2494] Resuming (17)@127.0.0.1:47773 at 2016-03-14 22:44:14.363737088+00:00
I0314 22:44:14.363790 125940 process.cpp:2599] Cleaning up (17)@127.0.0.1:47773
I0314 22:44:14.363862 125968 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.363856128+00:00
I0314 22:44:14.363901 125940 process.cpp:2795] Donating thread to (16)@127.0.0.1:47773 while waiting
I0314 22:44:14.363935 125940 process.cpp:2494] Resuming (16)@127.0.0.1:47773 at 2016-03-14 22:44:14.363929088+00:00
I0314 22:44:14.363970 125940 process.cpp:2599] Cleaning up (16)@127.0.0.1:47773
I0314 22:44:14.364032 125968 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.364026112+00:00
I0314 22:44:14.364081 125968 process.cpp:2494] Resuming (14)@127.0.0.1:47773 at 2016-03-14 22:44:14.364078080+00:00
I0314 22:44:14.364114 125968 process.cpp:2599] Cleaning up (14)@127.0.0.1:47773
I0314 22:44:14.364198 125965 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.364190208+00:00
I0314 22:44:14.364276 125965 process.cpp:2494] Resuming (13)@127.0.0.1:47773 at 2016-03-14 22:44:14.364270080+00:00
I0314 22:44:14.364318 125965 process.cpp:2599] Cleaning up (13)@127.0.0.1:47773
I0314 22:44:14.364383 125968 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.364377856+00:00
I0314 22:44:14.364480 125967 process.cpp:2494] Resuming (15)@127.0.0.1:47773 at 2016-03-14 22:44:14.364466944+00:00
I0314 22:44:14.364534 125967 process.cpp:2599] Cleaning up (15)@127.0.0.1:47773
I0314 22:44:14.364601 125964 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.364592128+00:00
I0314 22:44:14.364929 125940 process.cpp:2795] Donating thread to (12)@127.0.0.1:47773 while waiting
I0314 22:44:14.364956 125940 process.cpp:2494] Resuming (12)@127.0.0.1:47773 at 2016-03-14 22:44:14.364950784+00:00
I0314 22:44:14.364974 125940 process.cpp:2599] Cleaning up (12)@127.0.0.1:47773
I0314 22:44:14.365031 125970 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.365021952+00:00
I0314 22:44:14.365345 125967 process.cpp:2494] Resuming standalone-master-detector(2)@127.0.0.1:47773 at 2016-03-14 22:44:14.365339136+00:00
I0314 22:44:14.365391 125967 process.cpp:2599] Cleaning up standalone-master-detector(2)@127.0.0.1:47773
I0314 22:44:14.365458 125970 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.365448960+00:00
I0314 22:44:14.365593 125940 process.cpp:2451] Dropping event for process slave(1)@127.0.0.1:47773
I0314 22:44:14.365697 125970 process.cpp:2494] Resuming (23)@127.0.0.1:47773 at 2016-03-14 22:44:14.365691904+00:00
I0314 22:44:14.365726 125970 process.cpp:2599] Cleaning up (23)@127.0.0.1:47773
I0314 22:44:14.365784 125970 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.365782016+00:00
I0314 22:44:14.366106 125970 process.cpp:2494] Resuming (24)@127.0.0.1:47773 at 2016-03-14 22:44:14.366099968+00:00
I0314 22:44:14.366142 125970 process.cpp:2599] Cleaning up (24)@127.0.0.1:47773
I0314 22:44:14.366212 125970 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.366209024+00:00
I0314 22:44:14.366376 125940 process.cpp:2795] Donating thread to fetcher(1)@127.0.0.1:47773 while waiting
I0314 22:44:14.366403 125940 process.cpp:2494] Resuming fetcher(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.366398976+00:00
I0314 22:44:14.366421 125940 process.cpp:2599] Cleaning up fetcher(1)@127.0.0.1:47773
I0314 22:44:14.366489 125970 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.366483968+00:00
I0314 22:44:14.366578 125967 process.cpp:2494] Resuming (26)@127.0.0.1:47773 at 2016-03-14 22:44:14.366574080+00:00
I0314 22:44:14.366629 125967 process.cpp:2599] Cleaning up (26)@127.0.0.1:47773
I0314 22:44:14.366693 125964 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.366683904+00:00
I0314 22:44:14.366827 125970 process.cpp:2494] Resuming (25)@127.0.0.1:47773 at 2016-03-14 22:44:14.366821120+00:00
I0314 22:44:14.366863 125970 process.cpp:2599] Cleaning up (25)@127.0.0.1:47773
I0314 22:44:14.366930 125970 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.366926080+00:00
I0314 22:44:14.367102 125970 process.cpp:2494] Resuming metrics@127.0.0.1:47773 at 2016-03-14 22:44:14.367098112+00:00
I0314 22:44:14.367183 125940 process.cpp:2795] Donating thread to standalone-master-detector(3)@127.0.0.1:47773 while waiting
I0314 22:44:14.367213 125940 process.cpp:2494] Resuming standalone-master-detector(3)@127.0.0.1:47773 at 2016-03-14 22:44:14.367207936+00:00
I0314 22:44:14.367231 125940 process.cpp:2599] Cleaning up standalone-master-detector(3)@127.0.0.1:47773
I0314 22:44:14.367285 125970 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.367280128+00:00
I0314 22:44:14.367318 125940 process.cpp:2451] Dropping event for process scheduler-c577e1f5-4b58-41dd-bd3e-5b286e042a26@127.0.0.1:47773
I0314 22:44:14.367838 125970 process.cpp:2494] Resuming AuthenticationRouter(1)@127.0.0.1:47773 at 2016-03-14 22:44:14.367832832+00:00
I0314 22:44:14.367861 125940 process.cpp:2795] Donating thread to files@127.0.0.1:47773 while waiting
I0314 22:44:14.367884 125940 process.cpp:2494] Resuming files@127.0.0.1:47773 at 2016-03-14 22:44:14.367880192+00:00
I0314 22:44:14.367900 125940 process.cpp:2599] Cleaning up files@127.0.0.1:47773
I0314 22:44:14.367950 125971 process.cpp:2494] Resuming help@127.0.0.1:47773 at 2016-03-14 22:44:14.367937024+00:00
[  FAILED  ] ProvisionerDockerRegistryPullerTest.ROOT_INTERNET_CURL_ShellCommand (1129 ms)
[----------] 1 test from ProvisionerDockerRegistryPullerTest (1129 ms total)

[----------] Global test environment tear-down
[==========] 1 test from 1 test case ran. (1175 ms total)
[  PASSED  ] 0 tests.
[  FAILED  ] 1 test, listed below:
[  FAILED  ] ProvisionerDockerRegistryPullerTest.ROOT_INTERNET_CURL_ShellCommand




System configuration:

root@zhitao-mesos1:/home/uber/mesos-0.28.0-rc2/build# uname -a
Linux zhitao-mesos1 3.18.27 #1 SMP Wed Feb 17 01:14:23 UTC 2016 x86_64 GNU/Linux
root@zhitao-mesos1:/home/uber/mesos-0.28.0-rc2/build# mount | grep cgroup
tmpfs on /sys/fs/cgroup type tmpfs (ro,nosuid,nodev,noexec,mode=755)
cgroup on /sys/fs/cgroup/systemd type cgroup (rw,nosuid,nodev,noexec,relatime,xattr,release_agent=/lib/systemd/systemd-cgroups-agent,name=systemd)
cgroup on /sys/fs/cgroup/cpuset type cgroup (rw,nosuid,nodev,noexec,relatime,cpuset)
cgroup on /sys/fs/cgroup/cpu,cpuacct type cgroup (rw,nosuid,nodev,noexec,relatime,cpu,cpuacct)
cgroup on /sys/fs/cgroup/memory type cgroup (rw,nosuid,nodev,noexec,relatime,memory)
cgroup on /sys/fs/cgroup/devices type cgroup (rw,nosuid,nodev,noexec,relatime,devices)
cgroup on /sys/fs/cgroup/freezer type cgroup (rw,nosuid,nodev,noexec,relatime,freezer)
cgroup on /sys/fs/cgroup/net_cls,net_prio type cgroup (rw,nosuid,nodev,noexec,relatime,net_cls,net_prio)
cgroup on /sys/fs/cgroup/blkio type cgroup (rw,nosuid,nodev,noexec,relatime,blkio)
cgroup on /sys/fs/cgroup/perf_event type cgroup (rw,nosuid,nodev,noexec,relatime,perf_event)
cgroup on /sys/fs/cgroup/hugetlb type cgroup (rw,nosuid,nodev,noexec,relatime,hugetlb)

It seems like the second call to os::su() in src/launcher/executor.cpp failed:

        if (user.isSome()) {
          Try<Nothing> su = os::su(user.get());
          if (su.isError()) {
            cerr << "Failed to change user to '" << user.get() << "': "
                 << su.error() << endl;
            abort();
          }
        }

Additional debug logging suggests that getpwnam_r(3) failed with errno ENOENT in os::getgid. Not sure what could the cause.

Attachments

Issue Links

is duplicated by

MESOS-4810 ProvisionerDockerPullerTest.ROOT_INTERNET_CURL_ShellCommand fails.

Resolved

Activity

People

Assignee:: Unassigned

Reporter:: Zhitao Li

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 15/Mar/16 05:54

Updated:: 01/Jun/17 17:49

Resolved:: 01/Jun/17 17:49