LinuxFilesystemIsolatorTest.ROOT_ChangeRootFilesystemCommandExecutor is flaky.

[18:03:58] :	 [Step 10/10] [ RUN      ] LinuxFilesystemIsolatorTest.ROOT_ChangeRootFilesystemCommandExecutor
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.584962   642 cluster.cpp:149] Creating default 'local' authorizer
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.597232   642 leveldb.cpp:174] Opened db in 12.195009ms
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.598534   642 leveldb.cpp:181] Compacted db in 1.266907ms
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.598558   642 leveldb.cpp:196] Created db iterator in 5704ns
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.598565   642 leveldb.cpp:202] Seeked to beginning of db in 703ns
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.598570   642 leveldb.cpp:271] Iterated through 0 keys in the db in 272ns
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.598585   642 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.598815   663 recover.cpp:447] Starting replica recovery
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.598927   663 recover.cpp:473] Replica is in EMPTY status
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.599241   663 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (17941)@172.30.2.229:48705
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.599323   663 recover.cpp:193] Received a recover response from a replica in EMPTY status
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.599472   657 recover.cpp:564] Updating replica status to STARTING
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.600092   661 master.cpp:382] Master 7e239aa6-d964-4f11-95a8-ba808ad23f4e (ip-172-30-2-229.mesosphere.io) started on 172.30.2.229:48705
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.600105   661 master.cpp:384] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_http="true" --authenticate_http_frameworks="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/XRr1Iz/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_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/XRr1Iz/master" --zk_session_timeout="10secs"
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.600225   661 master.cpp:433] Master only allowing authenticated frameworks to register
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.600231   661 master.cpp:439] Master only allowing authenticated agents to register
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.600234   661 master.cpp:445] Master only allowing authenticated HTTP frameworks to register
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.600239   661 credentials.hpp:37] Loading credentials for authentication from '/tmp/XRr1Iz/credentials'
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.600371   661 master.cpp:489] Using default 'crammd5' authenticator
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.600410   661 master.cpp:560] Using default 'basic' HTTP authenticator
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.600461   661 master.cpp:640] Using default 'basic' HTTP framework authenticator
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.600525   661 master.cpp:687] Authorization enabled
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.600590   656 whitelist_watcher.cpp:77] No whitelist given
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.600610   660 hierarchical.cpp:142] Initialized hierarchical allocator process
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.600883   659 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.350635ms
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.600904   659 replica.cpp:320] Persisted replica status to STARTING
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.601029   659 recover.cpp:473] Replica is in STARTING status
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.601161   657 master.cpp:1932] The newly elected leader is master@172.30.2.229:48705 with id 7e239aa6-d964-4f11-95a8-ba808ad23f4e
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.601176   657 master.cpp:1945] Elected as the leading master!
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.601181   657 master.cpp:1632] Recovering from registrar
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.601227   661 registrar.cpp:331] Recovering registrar
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.601291   660 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (17944)@172.30.2.229:48705
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.601460   656 recover.cpp:193] Received a recover response from a replica in STARTING status
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.601572   663 recover.cpp:564] Updating replica status to VOTING
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.602798   663 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.178644ms
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.602814   663 replica.cpp:320] Persisted replica status to VOTING
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.602845   663 recover.cpp:578] Successfully joined the Paxos group
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.602881   663 recover.cpp:462] Recover process terminated
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.603023   656 log.cpp:524] Attempting to start the writer
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.603399   663 replica.cpp:493] Replica received implicit promise request from (17945)@172.30.2.229:48705 with proposal 1
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.604593   663 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.178393ms
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.604607   663 replica.cpp:342] Persisted promised to 1
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.604833   662 coordinator.cpp:238] Coordinator attempting to fill missing positions
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.605226   660 replica.cpp:388] Replica received explicit promise request from (17946)@172.30.2.229:48705 for position 0 with proposal 2
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.606335   660 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 1.088746ms
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.606351   660 replica.cpp:712] Persisted action at 0
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.606735   661 replica.cpp:537] Replica received write request for position 0 from (17947)@172.30.2.229:48705
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.606767   661 leveldb.cpp:436] Reading position from leveldb took 13169ns
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.608047   661 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 1.264327ms
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.608062   661 replica.cpp:712] Persisted action at 0
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.608309   657 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.609447   657 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.122608ms
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.609462   657 replica.cpp:712] Persisted action at 0
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.609467   657 replica.cpp:697] Replica learned NOP action at position 0
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.609609   657 log.cpp:540] Writer started with ending position 0
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.609887   661 leveldb.cpp:436] Reading position from leveldb took 8414ns
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.610115   661 registrar.cpp:364] Successfully fetched the registry (0B) in 8.865024ms
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.610144   661 registrar.cpp:463] Applied 1 operations in 4077ns; attempting to update the 'registry'
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.610333   659 log.cpp:548] Attempting to append 210 bytes to the log
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.610385   656 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.610631   663 replica.cpp:537] Replica received write request for position 1 from (17948)@172.30.2.229:48705
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.611784   663 leveldb.cpp:341] Persisting action (229 bytes) to leveldb took 1.132676ms
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.611799   663 replica.cpp:712] Persisted action at 1
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.612002   662 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.613100   662 leveldb.cpp:341] Persisting action (231 bytes) to leveldb took 1.077829ms
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.613114   662 replica.cpp:712] Persisted action at 1
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.613121   662 replica.cpp:697] Replica learned APPEND action at position 1
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.613335   659 registrar.cpp:508] Successfully updated the 'registry' in 3.173888ms
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.613402   657 log.cpp:567] Attempting to truncate the log to 1
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.613420   659 registrar.cpp:394] Successfully recovered registrar
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.613545   663 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.613566   656 master.cpp:1740] Recovered 0 agents from the Registry (171B) ; allowing 10mins for agents to re-register
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.613679   659 hierarchical.cpp:169] Skipping recovery of hierarchical allocator: nothing to recover
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.613807   660 replica.cpp:537] Replica received write request for position 2 from (17949)@172.30.2.229:48705
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.615124   660 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.299877ms
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.615140   660 replica.cpp:712] Persisted action at 2
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.615324   657 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.616408   657 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 1.067973ms
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.616437   657 leveldb.cpp:399] Deleting ~1 keys from leveldb took 14275ns
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.616446   657 replica.cpp:712] Persisted action at 2
[18:03:58]W:	 [Step 10/10] I0425 18:03:58.616451   657 replica.cpp:697] Replica learned TRUNCATE action at position 2
[18:03:59]W:	 [Step 10/10] I0425 18:03:59.601456   662 hierarchical.cpp:1488] No resources available to allocate!
[18:03:59]W:	 [Step 10/10] I0425 18:03:59.601508   662 hierarchical.cpp:1139] Performed allocation for 0 agents in 90519ns
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.326802   642 linux.cpp:81] Making '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj' a shared mount
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.339643   642 linux_launcher.cpp:101] Using /sys/fs/cgroup/freezer as the freezer hierarchy for the Linux launcher
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.340358   642 cluster.cpp:398] Creating default 'local' authorizer
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.340817   658 slave.cpp:204] Agent started on 458)@172.30.2.229:48705
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.340831   658 slave.cpp:205] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true" --authenticatee="crammd5" --authorizer="local" --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="/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/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="/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_command_executor="false" --http_credentials="/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/http_credentials" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mnt/teamcity/work/4240ba9ddd0997c3/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="/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj"
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.341024   658 credentials.hpp:86] Loading credential for authentication from '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/credential'
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.341190   658 slave.cpp:342] Agent using credential for: test-principal
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.341203   658 credentials.hpp:37] Loading credentials for authentication from '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/http_credentials'
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.341292   658 slave.cpp:394] Using default 'basic' HTTP authenticator
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.341378   658 resources.cpp:572] Parsing resources as JSON failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
[18:04:00]W:	 [Step 10/10] Trying semicolon-delimited string format instead
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.341543   642 sched.cpp:224] Version: 0.29.0
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.341552   658 slave.cpp:593] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.341583   658 slave.cpp:601] Agent attributes: [  ]
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.341591   658 slave.cpp:606] Agent hostname: ip-172-30-2-229.mesosphere.io
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.341683   660 sched.cpp:328] New master detected at master@172.30.2.229:48705
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.341712   660 sched.cpp:384] Authenticating with master master@172.30.2.229:48705
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.341722   660 sched.cpp:391] Using default CRAM-MD5 authenticatee
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.341886   661 authenticatee.cpp:121] Creating new client SASL connection
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.341940   658 state.cpp:57] Recovering state from '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/meta'
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.342118   658 status_update_manager.cpp:200] Recovering status update manager
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.342120   662 master.cpp:5803] Authenticating scheduler-46c11828-a1c6-4ea0-8ec2-2ffb638437ba@172.30.2.229:48705
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.342188   661 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(932)@172.30.2.229:48705
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.342308   660 containerizer.cpp:444] Recovering containerizer
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.342308   657 authenticator.cpp:98] Creating new server SASL connection
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.342531   657 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.342551   657 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.342634   659 authenticator.cpp:203] Received SASL authentication start
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.342669   659 authenticator.cpp:325] Authentication requires more steps
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.342701   659 authenticatee.cpp:258] Received SASL authentication step
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.342789   656 authenticator.cpp:231] Received SASL authentication step
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.342808   656 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-229.mesosphere.io' server FQDN: 'ip-172-30-2-229.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.342814   656 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.342825   656 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.342833   656 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-229.mesosphere.io' server FQDN: 'ip-172-30-2-229.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.342836   656 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.342840   656 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.342849   656 authenticator.cpp:317] Authentication success
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.342896   659 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(932)@172.30.2.229:48705
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.342897   662 authenticatee.cpp:298] Authentication success
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.342916   656 master.cpp:5833] Successfully authenticated principal 'test-principal' at scheduler-46c11828-a1c6-4ea0-8ec2-2ffb638437ba@172.30.2.229:48705
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.343030   663 sched.cpp:474] Successfully authenticated with master master@172.30.2.229:48705
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.343044   663 sched.cpp:783] Sending SUBSCRIBE call to master@172.30.2.229:48705
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.343091   663 sched.cpp:816] Will retry registration in 485.223658ms if necessary
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.343134   656 master.cpp:2465] Received SUBSCRIBE call for framework 'default' at scheduler-46c11828-a1c6-4ea0-8ec2-2ffb638437ba@172.30.2.229:48705
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.343152   656 master.cpp:1971] Authorizing framework principal 'test-principal' to receive offers for role '*'
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.343235   656 master.cpp:2541] Subscribing framework default with checkpointing disabled and capabilities [  ]
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.343372   657 hierarchical.cpp:264] Added framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.343391   657 hierarchical.cpp:1488] No resources available to allocate!
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.343400   657 hierarchical.cpp:1583] No inverse offers to send out!
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.343417   657 hierarchical.cpp:1139] Performed allocation for 0 agents in 32147ns
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.343487   656 sched.cpp:710] Framework registered with 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.343518   656 sched.cpp:724] Scheduler::registered took 20476ns
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.344192   659 provisioner.cpp:245] Provisioner recovery complete
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.344338   663 slave.cpp:4826] Finished recovery
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.344614   663 slave.cpp:4998] Querying resource estimator for oversubscribable resources
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.344729   659 slave.cpp:953] New master detected at master@172.30.2.229:48705
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.344738   662 status_update_manager.cpp:174] Pausing sending status updates
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.344745   659 slave.cpp:1016] Authenticating with master master@172.30.2.229:48705
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.344753   659 slave.cpp:1021] Using default CRAM-MD5 authenticatee
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.344786   659 slave.cpp:989] Detecting new master
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.344811   656 authenticatee.cpp:121] Creating new client SASL connection
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.344854   659 slave.cpp:5012] Received oversubscribable resources  from the resource estimator
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.344982   656 master.cpp:5803] Authenticating slave(458)@172.30.2.229:48705
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.345024   656 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(933)@172.30.2.229:48705
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.345121   660 authenticator.cpp:98] Creating new server SASL connection
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.345310   660 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.345327   660 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.345374   660 authenticator.cpp:203] Received SASL authentication start
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.345408   660 authenticator.cpp:325] Authentication requires more steps
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.345450   660 authenticatee.cpp:258] Received SASL authentication step
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.345540   658 authenticator.cpp:231] Received SASL authentication step
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.345553   658 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-229.mesosphere.io' server FQDN: 'ip-172-30-2-229.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.345558   658 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.345566   658 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.345571   658 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-229.mesosphere.io' server FQDN: 'ip-172-30-2-229.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.345576   658 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.345578   658 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.345585   658 authenticator.cpp:317] Authentication success
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.345640   659 master.cpp:5833] Successfully authenticated principal 'test-principal' at slave(458)@172.30.2.229:48705
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.345652   657 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(933)@172.30.2.229:48705
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.345666   661 authenticatee.cpp:298] Authentication success
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.345746   661 slave.cpp:1086] Successfully authenticated with master master@172.30.2.229:48705
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.345789   661 slave.cpp:1482] Will retry registration in 19.872252ms if necessary
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.345850   659 master.cpp:4514] Registering agent at slave(458)@172.30.2.229:48705 (ip-172-30-2-229.mesosphere.io) with id 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.345944   657 registrar.cpp:463] Applied 1 operations in 15436ns; attempting to update the 'registry'
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.346144   659 log.cpp:548] Attempting to append 396 bytes to the log
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.346197   658 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.346508   658 replica.cpp:537] Replica received write request for position 3 from (17965)@172.30.2.229:48705
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.347267   658 leveldb.cpp:341] Persisting action (415 bytes) to leveldb took 736349ns
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.347286   658 replica.cpp:712] Persisted action at 3
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.347520   659 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.348105   659 leveldb.cpp:341] Persisting action (417 bytes) to leveldb took 565502ns
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.348116   659 replica.cpp:712] Persisted action at 3
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.348121   659 replica.cpp:697] Replica learned APPEND action at position 3
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.348390   658 registrar.cpp:508] Successfully updated the 'registry' in 2.422784ms
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.348438   663 log.cpp:567] Attempting to truncate the log to 3
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.348547   656 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.348604   659 master.cpp:4582] Registered agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 at slave(458)@172.30.2.229:48705 (ip-172-30-2-229.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.348654   656 slave.cpp:3701] Received ping from slave-observer(423)@172.30.2.229:48705
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.348670   660 hierarchical.cpp:473] Added agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 (ip-172-30-2-229.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.348711   656 slave.cpp:1130] Registered with master master@172.30.2.229:48705; given agent ID 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.348726   656 fetcher.cpp:81] Clearing fetcher cache
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.348769   659 replica.cpp:537] Replica received write request for position 4 from (17966)@172.30.2.229:48705
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.348834   660 hierarchical.cpp:1583] No inverse offers to send out!
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.348858   660 hierarchical.cpp:1162] Performed allocation for agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 in 160800ns
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.348888   660 status_update_manager.cpp:181] Resuming sending status updates
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.348994   660 master.cpp:5632] Sending 1 offers to framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 (default) at scheduler-46c11828-a1c6-4ea0-8ec2-2ffb638437ba@172.30.2.229:48705
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.348999   656 slave.cpp:1153] Checkpointing SlaveInfo to '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/meta/slaves/7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0/slave.info'
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.349146   660 sched.cpp:880] Scheduler::resourceOffers took 40293ns
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.349184   656 slave.cpp:1190] Forwarding total oversubscribed resources 
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.349258   656 master.cpp:4926] Received update of agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 at slave(458)@172.30.2.229:48705 (ip-172-30-2-229.mesosphere.io) with total oversubscribed resources 
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.349381   656 hierarchical.cpp:531] Agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 (ip-172-30-2-229.mesosphere.io) updated with oversubscribed resources  (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.349417   659 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 632584ns
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.349428   659 replica.cpp:712] Persisted action at 4
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.349427   656 hierarchical.cpp:1488] No resources available to allocate!
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.349441   656 hierarchical.cpp:1583] No inverse offers to send out!
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.349454   656 hierarchical.cpp:1162] Performed allocation for agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 in 44061ns
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.349580   660 master.cpp:3412] Processing ACCEPT call for offers: [ 7e239aa6-d964-4f11-95a8-ba808ad23f4e-O0 ] on agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 at slave(458)@172.30.2.229:48705 (ip-172-30-2-229.mesosphere.io) for framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 (default) at scheduler-46c11828-a1c6-4ea0-8ec2-2ffb638437ba@172.30.2.229:48705
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.349602   660 master.cpp:3015] Authorizing framework principal 'test-principal' to launch task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 as user 'root'
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.349720   661 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.350009   659 master.hpp:177] Adding task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 (ip-172-30-2-229.mesosphere.io)
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.350044   659 master.cpp:3897] Launching task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 (default) at scheduler-46c11828-a1c6-4ea0-8ec2-2ffb638437ba@172.30.2.229:48705 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 at slave(458)@172.30.2.229:48705 (ip-172-30-2-229.mesosphere.io)
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.350181   658 slave.cpp:1522] Got assigned task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 for framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.350261   658 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
[18:04:00]W:	 [Step 10/10] Trying semicolon-delimited string format instead
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.350317   661 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 575979ns
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.350348   661 leveldb.cpp:399] Deleting ~2 keys from leveldb took 16773ns
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.350361   661 replica.cpp:712] Persisted action at 4
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.350369   661 replica.cpp:697] Replica learned TRUNCATE action at position 4
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.350391   658 slave.cpp:1641] Launching task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 for framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.350428   658 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
[18:04:00]W:	 [Step 10/10] Trying semicolon-delimited string format instead
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.350800   658 paths.cpp:528] Trying to chown '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/slaves/7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0/frameworks/7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000/executors/52bf3e3e-f9e2-417c-a66d-24c5f8ec2898/runs/57198894-8507-4f3e-8c9b-428c1cdeb9bb' to user 'root'
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.355469   658 slave.cpp:5646] Launching executor 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/slaves/7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0/frameworks/7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000/executors/52bf3e3e-f9e2-417c-a66d-24c5f8ec2898/runs/57198894-8507-4f3e-8c9b-428c1cdeb9bb'
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.355728   658 slave.cpp:1867] Queuing task '52bf3e3e-f9e2-417c-a66d-24c5f8ec2898' for executor '52bf3e3e-f9e2-417c-a66d-24c5f8ec2898' of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.355738   662 containerizer.cpp:703] Starting container '57198894-8507-4f3e-8c9b-428c1cdeb9bb' for executor '52bf3e3e-f9e2-417c-a66d-24c5f8ec2898' of framework '7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000'
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.355782   658 slave.cpp:906] Successfully attached file '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/slaves/7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0/frameworks/7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000/executors/52bf3e3e-f9e2-417c-a66d-24c5f8ec2898/runs/57198894-8507-4f3e-8c9b-428c1cdeb9bb'
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.356014   661 provisioner.cpp:285] Provisioning image rootfs '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/provisioner/containers/57198894-8507-4f3e-8c9b-428c1cdeb9bb/backends/copy/rootfses/264fec60-6476-4aab-94af-d459a15c2448' for container 57198894-8507-4f3e-8c9b-428c1cdeb9bb
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.356412   657 copy.cpp:128] Copying layer path '/tmp/XRr1Iz/test_image' to rootfs '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/provisioner/containers/57198894-8507-4f3e-8c9b-428c1cdeb9bb/backends/copy/rootfses/264fec60-6476-4aab-94af-d459a15c2448'
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.602272   656 hierarchical.cpp:1488] No resources available to allocate!
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.602299   656 hierarchical.cpp:1583] No inverse offers to send out!
[18:04:00]W:	 [Step 10/10] I0425 18:04:00.602319   656 hierarchical.cpp:1139] Performed allocation for 1 agents in 123386ns
[18:04:01]W:	 [Step 10/10] I0425 18:04:01.603039   659 hierarchical.cpp:1488] No resources available to allocate!
[18:04:01]W:	 [Step 10/10] I0425 18:04:01.603067   659 hierarchical.cpp:1583] No inverse offers to send out!
[18:04:01]W:	 [Step 10/10] I0425 18:04:01.603086   659 hierarchical.cpp:1139] Performed allocation for 1 agents in 138139ns
[18:04:02]W:	 [Step 10/10] I0425 18:04:02.603773   657 hierarchical.cpp:1488] No resources available to allocate!
[18:04:02]W:	 [Step 10/10] I0425 18:04:02.603811   657 hierarchical.cpp:1583] No inverse offers to send out!
[18:04:02]W:	 [Step 10/10] I0425 18:04:02.603828   657 hierarchical.cpp:1139] Performed allocation for 1 agents in 113145ns
[18:04:03]W:	 [Step 10/10] I0425 18:04:03.604910   660 hierarchical.cpp:1488] No resources available to allocate!
[18:04:03]W:	 [Step 10/10] I0425 18:04:03.604938   660 hierarchical.cpp:1583] No inverse offers to send out!
[18:04:03]W:	 [Step 10/10] I0425 18:04:03.604954   660 hierarchical.cpp:1139] Performed allocation for 1 agents in 126355ns
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.346846   661 linux_launcher.cpp:281] Cloning child process with flags = CLONE_NEWNS
[18:04:04]W:	 [Step 10/10] + /mnt/teamcity/work/4240ba9ddd0997c3/build/src/mesos-containerizer mount --help=false --operation=make-rslave --path=/
[18:04:04]W:	 [Step 10/10] + grep -E /mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/.+ /proc/self/mountinfo
[18:04:04]W:	 [Step 10/10] + grep -v 57198894-8507-4f3e-8c9b-428c1cdeb9bb
[18:04:04]W:	 [Step 10/10] + cut '-d ' -f5
[18:04:04]W:	 [Step 10/10] + xargs --no-run-if-empty umount -l
[18:04:04]W:	 [Step 10/10] + mount -n --rbind /mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/provisioner/containers/57198894-8507-4f3e-8c9b-428c1cdeb9bb/backends/copy/rootfses/264fec60-6476-4aab-94af-d459a15c2448 /mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/slaves/7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0/frameworks/7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000/executors/52bf3e3e-f9e2-417c-a66d-24c5f8ec2898/runs/57198894-8507-4f3e-8c9b-428c1cdeb9bb/.rootfs
[18:04:04]W:	 [Step 10/10] WARNING: Logging before InitGoogleLogging() is written to STDERR
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.457139 15601 process.cpp:991] libprocess is initialized on 172.30.2.229:48674 with 8 worker threads
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.457484 15601 logging.cpp:195] Logging to STDERR
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.458220 15601 exec.cpp:150] Version: 0.29.0
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.459712 15648 exec.cpp:200] Executor started at: executor(1)@172.30.2.229:48674 with pid 15601
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.460300   656 slave.cpp:2862] Got registration for executor '52bf3e3e-f9e2-417c-a66d-24c5f8ec2898' of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 from executor(1)@172.30.2.229:48674
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.460985   660 slave.cpp:2032] Sending queued task '52bf3e3e-f9e2-417c-a66d-24c5f8ec2898' to executor '52bf3e3e-f9e2-417c-a66d-24c5f8ec2898' of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 at executor(1)@172.30.2.229:48674
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.461005 15647 exec.cpp:225] Executor registered on agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.461822 15647 exec.cpp:237] Executor::registered took 101939ns
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.462000 15647 exec.cpp:312] Executor asked to run task '52bf3e3e-f9e2-417c-a66d-24c5f8ec2898'
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.462044 15647 exec.cpp:321] Executor::launchTask took 30183ns
[18:04:04] :	 [Step 10/10] Registered executor on ip-172-30-2-229.mesosphere.io
[18:04:04] :	 [Step 10/10] Starting task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.463605 15647 exec.cpp:535] Executor sending status update TASK_RUNNING (UUID: b38791ab-d91d-4906-9a86-af476b83924e) for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
[18:04:04] :	 [Step 10/10] Forked command at 15656
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.464066   656 slave.cpp:3221] Handling status update TASK_RUNNING (UUID: b38791ab-d91d-4906-9a86-af476b83924e) for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 from executor(1)@172.30.2.229:48674
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.464565   658 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: b38791ab-d91d-4906-9a86-af476b83924e) for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
[18:04:04] :	 [Step 10/10] sh -c 'test -d /mnt/mesos/sandbox'
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.464589   658 status_update_manager.cpp:497] Creating StatusUpdate stream for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.464783   658 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: b38791ab-d91d-4906-9a86-af476b83924e) for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 to the agent
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.464893   661 slave.cpp:3619] Forwarding the update TASK_RUNNING (UUID: b38791ab-d91d-4906-9a86-af476b83924e) for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 to master@172.30.2.229:48705
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.464998   661 slave.cpp:3513] Status update manager successfully handled status update TASK_RUNNING (UUID: b38791ab-d91d-4906-9a86-af476b83924e) for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.465014   661 slave.cpp:3529] Sending acknowledgement for status update TASK_RUNNING (UUID: b38791ab-d91d-4906-9a86-af476b83924e) for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 to executor(1)@172.30.2.229:48674
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.465016   658 master.cpp:5071] Status update TASK_RUNNING (UUID: b38791ab-d91d-4906-9a86-af476b83924e) for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 from agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 at slave(458)@172.30.2.229:48705 (ip-172-30-2-229.mesosphere.io)
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.465035   658 master.cpp:5119] Forwarding status update TASK_RUNNING (UUID: b38791ab-d91d-4906-9a86-af476b83924e) for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.465086   658 master.cpp:6727] Updating the state of task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.465193   661 sched.cpp:988] Scheduler::statusUpdate took 56656ns
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.465309   657 master.cpp:4226] Processing ACKNOWLEDGE call b38791ab-d91d-4906-9a86-af476b83924e for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 (default) at scheduler-46c11828-a1c6-4ea0-8ec2-2ffb638437ba@172.30.2.229:48705 on agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.465338 15652 exec.cpp:358] Executor received status update acknowledgement b38791ab-d91d-4906-9a86-af476b83924e for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.465440   657 status_update_manager.cpp:392] Received status update acknowledgement (UUID: b38791ab-d91d-4906-9a86-af476b83924e) for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.465507   658 slave.cpp:2631] Status update manager successfully handled status update acknowledgement (UUID: b38791ab-d91d-4906-9a86-af476b83924e) for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
[18:04:04] :	 [Step 10/10] Command exited with status 0 (pid: 15656)
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.565306 15648 exec.cpp:535] Executor sending status update TASK_FINISHED (UUID: 244979d6-35e7-4a28-875e-31c5289240d3) for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.565690   657 slave.cpp:3221] Handling status update TASK_FINISHED (UUID: 244979d6-35e7-4a28-875e-31c5289240d3) for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 from executor(1)@172.30.2.229:48674
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.566062   662 slave.cpp:5966] Terminating task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.566371   662 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: 244979d6-35e7-4a28-875e-31c5289240d3) for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.566422   662 status_update_manager.cpp:374] Forwarding update TASK_FINISHED (UUID: 244979d6-35e7-4a28-875e-31c5289240d3) for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 to the agent
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.566495   660 slave.cpp:3619] Forwarding the update TASK_FINISHED (UUID: 244979d6-35e7-4a28-875e-31c5289240d3) for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 to master@172.30.2.229:48705
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.566575   660 slave.cpp:3513] Status update manager successfully handled status update TASK_FINISHED (UUID: 244979d6-35e7-4a28-875e-31c5289240d3) for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.566589   660 slave.cpp:3529] Sending acknowledgement for status update TASK_FINISHED (UUID: 244979d6-35e7-4a28-875e-31c5289240d3) for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 to executor(1)@172.30.2.229:48674
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.566658   659 master.cpp:5071] Status update TASK_FINISHED (UUID: 244979d6-35e7-4a28-875e-31c5289240d3) for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 from agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 at slave(458)@172.30.2.229:48705 (ip-172-30-2-229.mesosphere.io)
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.566684   659 master.cpp:5119] Forwarding status update TASK_FINISHED (UUID: 244979d6-35e7-4a28-875e-31c5289240d3) for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.566733   659 master.cpp:6727] Updating the state of task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 (latest state: TASK_FINISHED, status update state: TASK_FINISHED)
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.566829 15650 exec.cpp:358] Executor received status update acknowledgement 244979d6-35e7-4a28-875e-31c5289240d3 for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.566850   661 sched.cpp:988] Scheduler::statusUpdate took 41212ns
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.566905   662 hierarchical.cpp:891] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 from framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.566972   661 master.cpp:4226] Processing ACKNOWLEDGE call 244979d6-35e7-4a28-875e-31c5289240d3 for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 (default) at scheduler-46c11828-a1c6-4ea0-8ec2-2ffb638437ba@172.30.2.229:48705 on agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.566990   661 master.cpp:6793] Removing task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 on agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 at slave(458)@172.30.2.229:48705 (ip-172-30-2-229.mesosphere.io)
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.567018   642 sched.cpp:1911] Asked to stop the driver
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.567078   659 sched.cpp:1150] Stopping framework '7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000'
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.567165   661 master.cpp:6200] Processing TEARDOWN call for framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 (default) at scheduler-46c11828-a1c6-4ea0-8ec2-2ffb638437ba@172.30.2.229:48705
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.567178   661 master.cpp:6212] Removing framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 (default) at scheduler-46c11828-a1c6-4ea0-8ec2-2ffb638437ba@172.30.2.229:48705
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.567196   663 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 244979d6-35e7-4a28-875e-31c5289240d3) for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.567248   663 status_update_manager.cpp:528] Cleaning up status update stream for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.567271   656 slave.cpp:2252] Asked to shut down framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 by master@172.30.2.229:48705
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.567288   656 slave.cpp:2277] Shutting down framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.567302   656 slave.cpp:4451] Shutting down executor '52bf3e3e-f9e2-417c-a66d-24c5f8ec2898' of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 at executor(1)@172.30.2.229:48674
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.567414   656 slave.cpp:2631] Status update manager successfully handled status update acknowledgement (UUID: 244979d6-35e7-4a28-875e-31c5289240d3) for task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.567435   656 slave.cpp:6007] Completing task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.567548   657 hierarchical.cpp:375] Deactivated framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.567594 15647 exec.cpp:399] Executor asked to shutdown
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.567625   657 hierarchical.cpp:326] Removed framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.567633 15647 exec.cpp:414] Executor::shutdown took 4162ns
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.567662 15647 exec.cpp:91] Scheduling shutdown of the executor in 5secs
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.567800   661 containerizer.cpp:1481] Destroying container '57198894-8507-4f3e-8c9b-428c1cdeb9bb'
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.569454   657 cgroups.cpp:2676] Freezing cgroup /sys/fs/cgroup/freezer/mesos/57198894-8507-4f3e-8c9b-428c1cdeb9bb
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.570904   661 cgroups.cpp:1409] Successfully froze cgroup /sys/fs/cgroup/freezer/mesos/57198894-8507-4f3e-8c9b-428c1cdeb9bb after 1.430016ms
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.572533   663 cgroups.cpp:2694] Thawing cgroup /sys/fs/cgroup/freezer/mesos/57198894-8507-4f3e-8c9b-428c1cdeb9bb
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.574110   657 cgroups.cpp:1438] Successfully thawed cgroup /sys/fs/cgroup/freezer/mesos/57198894-8507-4f3e-8c9b-428c1cdeb9bb after 1.55776ms
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.575166   661 slave.cpp:3747] executor(1)@172.30.2.229:48674 exited
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.605558   661 hierarchical.cpp:1488] No resources available to allocate!
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.605597   661 hierarchical.cpp:1139] Performed allocation for 1 agents in 82646ns
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.646847   661 containerizer.cpp:1717] Executor for container '57198894-8507-4f3e-8c9b-428c1cdeb9bb' has exited
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.648252   663 linux.cpp:822] Ignoring unmounting sandbox/work directory for container 57198894-8507-4f3e-8c9b-428c1cdeb9bb
[18:04:04]W:	 [Step 10/10] I0425 18:04:04.648402   657 provisioner.cpp:338] Destroying container rootfs at '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/provisioner/containers/57198894-8507-4f3e-8c9b-428c1cdeb9bb/backends/copy/rootfses/264fec60-6476-4aab-94af-d459a15c2448' for container 57198894-8507-4f3e-8c9b-428c1cdeb9bb
[18:04:05]W:	 [Step 10/10] I0425 18:04:05.606057   660 hierarchical.cpp:1488] No resources available to allocate!
[18:04:05]W:	 [Step 10/10] I0425 18:04:05.606106   660 hierarchical.cpp:1139] Performed allocation for 1 agents in 125175ns
[18:04:06]W:	 [Step 10/10] I0425 18:04:06.606617   662 hierarchical.cpp:1488] No resources available to allocate!
[18:04:06]W:	 [Step 10/10] I0425 18:04:06.606653   662 hierarchical.cpp:1139] Performed allocation for 1 agents in 94758ns
[18:04:07]W:	 [Step 10/10] I0425 18:04:07.607285   658 hierarchical.cpp:1488] No resources available to allocate!
[18:04:07]W:	 [Step 10/10] I0425 18:04:07.607324   658 hierarchical.cpp:1139] Performed allocation for 1 agents in 104606ns
[18:04:08]W:	 [Step 10/10] I0425 18:04:08.607969   656 hierarchical.cpp:1488] No resources available to allocate!
[18:04:08]W:	 [Step 10/10] I0425 18:04:08.608006   656 hierarchical.cpp:1139] Performed allocation for 1 agents in 87577ns
[18:04:09]W:	 [Step 10/10] I0425 18:04:09.568349   657 slave.cpp:4524] Killing executor '52bf3e3e-f9e2-417c-a66d-24c5f8ec2898' of framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 at executor(1)@172.30.2.229:48674
[18:04:09]W:	 [Step 10/10] I0425 18:04:09.608618   661 hierarchical.cpp:1488] No resources available to allocate!
[18:04:09]W:	 [Step 10/10] I0425 18:04:09.608666   661 hierarchical.cpp:1139] Performed allocation for 1 agents in 107807ns
[18:04:10]W:	 [Step 10/10] I0425 18:04:10.609025   656 hierarchical.cpp:1488] No resources available to allocate!
[18:04:10]W:	 [Step 10/10] I0425 18:04:10.609067   656 hierarchical.cpp:1139] Performed allocation for 1 agents in 76953ns
[18:04:11]W:	 [Step 10/10] I0425 18:04:11.609622   662 hierarchical.cpp:1488] No resources available to allocate!
[18:04:11]W:	 [Step 10/10] I0425 18:04:11.609657   662 hierarchical.cpp:1139] Performed allocation for 1 agents in 85763ns
[18:04:12]W:	 [Step 10/10] I0425 18:04:12.610268   659 hierarchical.cpp:1488] No resources available to allocate!
[18:04:12]W:	 [Step 10/10] I0425 18:04:12.610303   659 hierarchical.cpp:1139] Performed allocation for 1 agents in 98315ns
[18:04:13]W:	 [Step 10/10] I0425 18:04:13.610864   663 hierarchical.cpp:1488] No resources available to allocate!
[18:04:13]W:	 [Step 10/10] I0425 18:04:13.610908   663 hierarchical.cpp:1139] Performed allocation for 1 agents in 136620ns
[18:04:14]W:	 [Step 10/10] I0425 18:04:14.611521   662 hierarchical.cpp:1488] No resources available to allocate!
[18:04:14]W:	 [Step 10/10] I0425 18:04:14.611557   662 hierarchical.cpp:1139] Performed allocation for 1 agents in 82004ns
[18:04:15]W:	 [Step 10/10] I0425 18:04:15.345278   658 slave.cpp:4998] Querying resource estimator for oversubscribable resources
[18:04:15]W:	 [Step 10/10] I0425 18:04:15.345414   657 slave.cpp:5012] Received oversubscribable resources  from the resource estimator
[18:04:15]W:	 [Step 10/10] I0425 18:04:15.349479   659 slave.cpp:3701] Received ping from slave-observer(423)@172.30.2.229:48705
[18:04:15]W:	 [Step 10/10] I0425 18:04:15.612602   662 hierarchical.cpp:1488] No resources available to allocate!
[18:04:15]W:	 [Step 10/10] I0425 18:04:15.612638   662 hierarchical.cpp:1139] Performed allocation for 1 agents in 81616ns
[18:04:16]W:	 [Step 10/10] I0425 18:04:16.613032   656 hierarchical.cpp:1488] No resources available to allocate!
[18:04:16]W:	 [Step 10/10] I0425 18:04:16.613067   656 hierarchical.cpp:1139] Performed allocation for 1 agents in 80321ns
[18:04:17]W:	 [Step 10/10] I0425 18:04:17.613535   660 hierarchical.cpp:1488] No resources available to allocate!
[18:04:17]W:	 [Step 10/10] I0425 18:04:17.613569   660 hierarchical.cpp:1139] Performed allocation for 1 agents in 74160ns
[18:04:18]W:	 [Step 10/10] I0425 18:04:18.614146   657 hierarchical.cpp:1488] No resources available to allocate!
[18:04:18]W:	 [Step 10/10] I0425 18:04:18.614181   657 hierarchical.cpp:1139] Performed allocation for 1 agents in 84861ns
[18:04:19]W:	 [Step 10/10] I0425 18:04:19.568646   642 slave.cpp:825] Agent terminating
[18:04:19] :	 [Step 10/10] ../../src/tests/cluster.cpp:500: Failure
[18:04:19] :	 [Step 10/10] Failed to wait 15secs for wait
[18:04:19]W:	 [Step 10/10] I0425 18:04:19.568676   642 slave.cpp:2252] Asked to shut down framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 by @0.0.0.0:0
[18:04:19]W:	 [Step 10/10] W0425 18:04:19.568694   642 slave.cpp:2273] Ignoring shutdown framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 because it is terminating
[18:04:19]W:	 [Step 10/10] I0425 18:04:19.568778   658 master.cpp:1336] Agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 at slave(458)@172.30.2.229:48705 (ip-172-30-2-229.mesosphere.io) disconnected
[18:04:19]W:	 [Step 10/10] I0425 18:04:19.568796   658 master.cpp:2825] Disconnecting agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 at slave(458)@172.30.2.229:48705 (ip-172-30-2-229.mesosphere.io)
[18:04:19]W:	 [Step 10/10] I0425 18:04:19.568825   658 master.cpp:2844] Deactivating agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 at slave(458)@172.30.2.229:48705 (ip-172-30-2-229.mesosphere.io)
[18:04:19]W:	 [Step 10/10] I0425 18:04:19.568877   659 hierarchical.cpp:560] Agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 deactivated
[18:04:19]W:	 [Step 10/10] I0425 18:04:19.614851   656 hierarchical.cpp:1488] No resources available to allocate!
[18:04:19]W:	 [Step 10/10] I0425 18:04:19.614899   656 hierarchical.cpp:1139] Performed allocation for 1 agents in 81590ns
[18:04:20]W:	 [Step 10/10] I0425 18:04:20.203956   642 master.cpp:1189] Master terminating
[18:04:20]W:	 [Step 10/10] I0425 18:04:20.204100   661 hierarchical.cpp:505] Removed agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0
[18:04:20] :	 [Step 10/10] [  FAILED  ] LinuxFilesystemIsolatorTest.ROOT_ChangeRootFilesystemCommandExecutor (21627 ms)