CpuIsolatorTest.ROOT_SystemCpuUsage is flaky

[19:43:35] :	 [Step 10/10] [ RUN      ] IsolationFlag/CpuIsolatorTest.ROOT_SystemCpuUsage/0
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.531028 22316 cluster.cpp:157] Creating default 'local' authorizer
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.534147 22316 leveldb.cpp:174] Opened db in 3.021942ms
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.534540 22316 leveldb.cpp:181] Compacted db in 375570ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.534555 22316 leveldb.cpp:196] Created db iterator in 5012ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.534561 22316 leveldb.cpp:202] Seeked to beginning of db in 646ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.534565 22316 leveldb.cpp:271] Iterated through 0 keys in the db in 323ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.534577 22316 replica.cpp:776] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.534824 22335 recover.cpp:451] Starting replica recovery
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.534878 22335 recover.cpp:477] Replica is in EMPTY status
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.535181 22337 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from __req_res__(8495)@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.535256 22336 recover.cpp:197] Received a recover response from a replica in EMPTY status
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.535358 22337 recover.cpp:568] Updating replica status to STARTING
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.535748 22335 master.cpp:379] Master 52799f65-6873-4d02-9085-d12af2116e05 (ip-172-30-2-7.mesosphere.io) started on 172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.535761 22335 master.cpp:381] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/DXEL4F/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_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --quiet="false" --recovery_agent_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="100secs" --registry_strict="true" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/DXEL4F/master" --zk_session_timeout="10secs"
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.535869 22335 master.cpp:431] Master only allowing authenticated frameworks to register
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.535874 22335 master.cpp:445] Master only allowing authenticated agents to register
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.535877 22335 master.cpp:458] Master only allowing authenticated HTTP frameworks to register
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.535881 22335 credentials.hpp:37] Loading credentials for authentication from '/tmp/DXEL4F/credentials'
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.535956 22335 master.cpp:503] Using default 'crammd5' authenticator
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.535992 22335 http.cpp:883] Using default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.536046 22335 http.cpp:883] Using default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.536077 22335 http.cpp:883] Using default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.536118 22335 master.cpp:583] Authorization enabled
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.536182 22337 whitelist_watcher.cpp:77] No whitelist given
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.536201 22330 hierarchical.cpp:149] Initialized hierarchical allocator process
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.536222 22331 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 826803ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.536233 22331 replica.cpp:320] Persisted replica status to STARTING
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.536300 22337 recover.cpp:477] Replica is in STARTING status
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.536659 22331 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from __req_res__(8496)@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.536731 22335 recover.cpp:197] Received a recover response from a replica in STARTING status
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.536900 22333 master.cpp:1854] Elected as the leading master!
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.536913 22333 master.cpp:1555] Recovering from registrar
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.536942 22332 recover.cpp:568] Updating replica status to VOTING
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.537062 22334 registrar.cpp:332] Recovering registrar
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.537367 22333 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 304298ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.537379 22333 replica.cpp:320] Persisted replica status to VOTING
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.537412 22333 recover.cpp:582] Successfully joined the Paxos group
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.537490 22333 recover.cpp:466] Recover process terminated
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.537609 22330 log.cpp:553] Attempting to start the writer
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.538017 22333 replica.cpp:493] Replica received implicit promise request from __req_res__(8497)@172.30.2.7:45895 with proposal 1
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.538347 22333 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 312830ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.538357 22333 replica.cpp:342] Persisted promised to 1
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.538590 22337 coordinator.cpp:238] Coordinator attempting to fill missing positions
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.538956 22332 replica.cpp:388] Replica received explicit promise request from __req_res__(8498)@172.30.2.7:45895 for position 0 with proposal 2
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.539264 22332 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 291577ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.539279 22332 replica.cpp:708] Persisted action NOP at position 0
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.539614 22330 replica.cpp:537] Replica received write request for position 0 from __req_res__(8499)@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.539644 22330 leveldb.cpp:436] Reading position from leveldb took 13681ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.539954 22330 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 295580ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.539965 22330 replica.cpp:708] Persisted action NOP at position 0
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.540160 22333 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.540500 22333 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 323209ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.540515 22333 replica.cpp:708] Persisted action NOP at position 0
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.540745 22330 log.cpp:569] Writer started with ending position 0
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.541033 22336 leveldb.cpp:436] Reading position from leveldb took 13960ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.541224 22334 registrar.cpp:365] Successfully fetched the registry (0B) in 4.143104ms
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.541265 22334 registrar.cpp:464] Applied 1 operations in 4983ns; attempting to update the registry
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.541430 22335 log.cpp:577] Attempting to append 200 bytes to the log
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.541484 22332 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.541734 22334 replica.cpp:537] Replica received write request for position 1 from __req_res__(8500)@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.542075 22334 leveldb.cpp:341] Persisting action (219 bytes) to leveldb took 324875ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.542086 22334 replica.cpp:708] Persisted action APPEND at position 1
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.542320 22337 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.542644 22337 leveldb.cpp:341] Persisting action (221 bytes) to leveldb took 309674ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.542654 22337 replica.cpp:708] Persisted action APPEND at position 1
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.542835 22334 registrar.cpp:509] Successfully updated the registry in 1.55008ms
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.542914 22334 registrar.cpp:395] Successfully recovered registrar
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.542929 22332 log.cpp:596] Attempting to truncate the log to 1
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.543016 22334 master.cpp:1663] Recovered 0 agents from the registry (161B); allowing 10mins for agents to re-register
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.543063 22333 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.543073 22331 hierarchical.cpp:176] Skipping recovery of hierarchical allocator: nothing to recover
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.543308 22332 replica.cpp:537] Replica received write request for position 2 from __req_res__(8501)@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.543659 22332 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 331650ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.543669 22332 replica.cpp:708] Persisted action TRUNCATE at position 2
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.543905 22331 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.544229 22331 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 311275ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.544248 22331 leveldb.cpp:399] Deleting ~1 keys from leveldb took 9143ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.544255 22331 replica.cpp:708] Persisted action TRUNCATE at position 2
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.544989 22316 containerizer.cpp:217] Using isolation: posix/cpu,filesystem/posix,network/cni
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.548125 22316 linux_launcher.cpp:104] Using /sys/fs/cgroup/freezer as the freezer hierarchy for the Linux launcher
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.549738 22316 cluster.cpp:436] Creating default 'local' authorizer
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.550108 22334 slave.cpp:208] Mesos agent started on (677)@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.550120 22334 slave.cpp:209] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --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/IsolationFlag_CpuIsolatorTest_ROOT_SystemCpuUsage_0_ywtWxd/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" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/mnt/teamcity/temp/buildTmp/IsolationFlag_CpuIsolatorTest_ROOT_SystemCpuUsage_0_ywtWxd/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="true" --hostname_lookup="true" --http_authenticators="basic" --http_command_executor="false" --http_credentials="/mnt/teamcity/temp/buildTmp/IsolationFlag_CpuIsolatorTest_ROOT_SystemCpuUsage_0_ywtWxd/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;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --runtime_dir="/mnt/teamcity/temp/buildTmp/IsolationFlag_CpuIsolatorTest_ROOT_SystemCpuUsage_0_ywtWxd" --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/IsolationFlag_CpuIsolatorTest_ROOT_SystemCpuUsage_0_KLzIFk"
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.550429 22334 credentials.hpp:86] Loading credential for authentication from '/mnt/teamcity/temp/buildTmp/IsolationFlag_CpuIsolatorTest_ROOT_SystemCpuUsage_0_ywtWxd/credential'
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.550477 22334 slave.cpp:346] Agent using credential for: test-principal
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.550487 22334 credentials.hpp:37] Loading credentials for authentication from '/mnt/teamcity/temp/buildTmp/IsolationFlag_CpuIsolatorTest_ROOT_SystemCpuUsage_0_ywtWxd/http_credentials'
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.550542 22334 http.cpp:883] Using default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.550582 22334 http.cpp:883] Using default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.550642 22316 sched.cpp:226] Version: 1.1.0
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.550776 22335 sched.cpp:330] New master detected at master@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.550806 22335 sched.cpp:396] Authenticating with master master@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.550815 22335 sched.cpp:403] Using default CRAM-MD5 authenticatee
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.550863 22334 slave.cpp:529] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.550897 22334 slave.cpp:537] Agent attributes: [  ]
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.550904 22334 slave.cpp:542] Agent hostname: ip-172-30-2-7.mesosphere.io
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.550943 22332 authenticatee.cpp:121] Creating new client SASL connection
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551120 22332 master.cpp:6233] Authenticating scheduler-47bc2772-2dc7-4a91-b8dc-6ef919678f63@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551183 22335 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1273)@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551239 22334 state.cpp:57] Recovering state from '/mnt/teamcity/temp/buildTmp/IsolationFlag_CpuIsolatorTest_ROOT_SystemCpuUsage_0_KLzIFk/meta'
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551254 22333 authenticator.cpp:98] Creating new server SASL connection
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551336 22334 status_update_manager.cpp:203] Recovering status update manager
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551424 22331 containerizer.cpp:578] Recovering containerizer
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551462 22334 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551476 22334 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551504 22334 authenticator.cpp:204] Received SASL authentication start
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551528 22334 authenticator.cpp:326] Authentication requires more steps
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551563 22334 authenticatee.cpp:259] Received SASL authentication step
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551614 22334 authenticator.cpp:232] Received SASL authentication step
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551630 22334 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-7.mesosphere.io' server FQDN: 'ip-172-30-2-7.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551636 22334 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551642 22334 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551647 22334 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-7.mesosphere.io' server FQDN: 'ip-172-30-2-7.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551651 22334 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551654 22334 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551661 22334 authenticator.cpp:318] Authentication success
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551704 22334 authenticatee.cpp:299] Authentication success
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551715 22335 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1273)@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551738 22332 master.cpp:6263] Successfully authenticated principal 'test-principal' at scheduler-47bc2772-2dc7-4a91-b8dc-6ef919678f63@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551867 22336 sched.cpp:502] Successfully authenticated with master master@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551879 22336 sched.cpp:820] Sending SUBSCRIBE call to master@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551920 22336 sched.cpp:853] Will retry registration in 1.131469229secs if necessary
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551970 22330 master.cpp:2428] Received SUBSCRIBE call for framework 'default' at scheduler-47bc2772-2dc7-4a91-b8dc-6ef919678f63@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.551991 22330 master.cpp:1890] Authorizing framework principal 'test-principal' to receive offers for role '*'
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.552091 22331 master.cpp:2504] Subscribing framework default with checkpointing disabled and capabilities [  ]
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.552218 22335 hierarchical.cpp:269] Added framework 52799f65-6873-4d02-9085-d12af2116e05-0000
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.552238 22335 hierarchical.cpp:1675] No allocations performed
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.552244 22335 hierarchical.cpp:1770] No inverse offers to send out!
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.552251 22335 hierarchical.cpp:1271] Performed allocation for 0 agents in 20964ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.552280 22331 sched.cpp:743] Framework registered with 52799f65-6873-4d02-9085-d12af2116e05-0000
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.552312 22331 sched.cpp:757] Scheduler::registered took 20263ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.552413 22333 provisioner.cpp:253] Provisioner recovery complete
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.552523 22335 slave.cpp:5198] Finished recovery
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.552678 22335 slave.cpp:5370] Querying resource estimator for oversubscribable resources
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.552788 22332 slave.cpp:911] New master detected at master@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.552795 22334 status_update_manager.cpp:177] Pausing sending status updates
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.552803 22332 slave.cpp:970] Authenticating with master master@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.552814 22332 slave.cpp:981] Using default CRAM-MD5 authenticatee
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.552842 22332 slave.cpp:943] Detecting new master
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.552878 22332 slave.cpp:5384] Received oversubscribable resources  from the resource estimator
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.552911 22330 authenticatee.cpp:121] Creating new client SASL connection
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.553094 22330 master.cpp:6233] Authenticating slave(677)@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.553143 22333 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1274)@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.553210 22335 authenticator.cpp:98] Creating new server SASL connection
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.553339 22335 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.553351 22335 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.553386 22335 authenticator.cpp:204] Received SASL authentication start
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.553407 22335 authenticator.cpp:326] Authentication requires more steps
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.553439 22335 authenticatee.cpp:259] Received SASL authentication step
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.553493 22331 authenticator.cpp:232] Received SASL authentication step
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.553513 22331 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-7.mesosphere.io' server FQDN: 'ip-172-30-2-7.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.553521 22331 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.553532 22331 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.553544 22331 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-7.mesosphere.io' server FQDN: 'ip-172-30-2-7.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.553549 22331 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.553551 22331 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.553558 22331 authenticator.cpp:318] Authentication success
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.553601 22337 authenticatee.cpp:299] Authentication success
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.553606 22335 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1274)@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.553647 22331 master.cpp:6263] Successfully authenticated principal 'test-principal' at slave(677)@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.553686 22337 slave.cpp:1065] Successfully authenticated with master master@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.553735 22337 slave.cpp:1471] Will retry registration in 13.012583ms if necessary
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.553782 22333 master.cpp:4885] Registering agent at slave(677)@172.30.2.7:45895 (ip-172-30-2-7.mesosphere.io) with id 52799f65-6873-4d02-9085-d12af2116e05-S0
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.553872 22337 registrar.cpp:464] Applied 1 operations in 10873ns; attempting to update the registry
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.554040 22332 log.cpp:577] Attempting to append 384 bytes to the log
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.554075 22332 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.554316 22332 replica.cpp:537] Replica received write request for position 3 from __req_res__(8502)@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.554682 22332 leveldb.cpp:341] Persisting action (403 bytes) to leveldb took 350804ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.554692 22332 replica.cpp:708] Persisted action APPEND at position 3
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.554919 22330 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.555269 22330 leveldb.cpp:341] Persisting action (405 bytes) to leveldb took 331518ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.555280 22330 replica.cpp:708] Persisted action APPEND at position 3
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.555567 22337 registrar.cpp:509] Successfully updated the registry in 1.671168ms
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.555588 22335 log.cpp:596] Attempting to truncate the log to 3
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.555625 22332 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.555788 22331 slave.cpp:4065] Received ping from slave-observer(605)@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.555799 22335 master.cpp:4955] Registered agent 52799f65-6873-4d02-9085-d12af2116e05-S0 at slave(677)@172.30.2.7:45895 (ip-172-30-2-7.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.555850 22331 slave.cpp:1111] Registered with master master@172.30.2.7:45895; given agent ID 52799f65-6873-4d02-9085-d12af2116e05-S0
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.555863 22331 fetcher.cpp:86] Clearing fetcher cache
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.555919 22334 status_update_manager.cpp:184] Resuming sending status updates
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.555918 22333 hierarchical.cpp:476] Added agent 52799f65-6873-4d02-9085-d12af2116e05-S0 (ip-172-30-2-7.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.555979 22330 replica.cpp:537] Replica received write request for position 4 from __req_res__(8503)@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.556038 22331 slave.cpp:1134] Checkpointing SlaveInfo to '/mnt/teamcity/temp/buildTmp/IsolationFlag_CpuIsolatorTest_ROOT_SystemCpuUsage_0_KLzIFk/meta/slaves/52799f65-6873-4d02-9085-d12af2116e05-S0/slave.info'
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.556143 22333 hierarchical.cpp:1770] No inverse offers to send out!
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.556160 22331 slave.cpp:1171] Forwarding total oversubscribed resources 
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.556164 22333 hierarchical.cpp:1294] Performed allocation for agent 52799f65-6873-4d02-9085-d12af2116e05-S0 in 222127ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.556236 22335 master.cpp:6062] Sending 1 offers to framework 52799f65-6873-4d02-9085-d12af2116e05-0000 (default) at scheduler-47bc2772-2dc7-4a91-b8dc-6ef919678f63@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.556296 22335 master.cpp:5339] Received update of agent 52799f65-6873-4d02-9085-d12af2116e05-S0 at slave(677)@172.30.2.7:45895 (ip-172-30-2-7.mesosphere.io) with total oversubscribed resources 
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.556324 22330 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 327511ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.556334 22330 replica.cpp:708] Persisted action TRUNCATE at position 4
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.556385 22334 sched.cpp:917] Scheduler::resourceOffers took 35326ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.556381 22335 hierarchical.cpp:540] Agent 52799f65-6873-4d02-9085-d12af2116e05-S0 (ip-172-30-2-7.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])
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.556426 22335 hierarchical.cpp:1675] No allocations performed
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.556437 22335 hierarchical.cpp:1770] No inverse offers to send out!
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.556448 22335 hierarchical.cpp:1294] Performed allocation for agent 52799f65-6873-4d02-9085-d12af2116e05-S0 in 42268ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.556782 22332 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.556879 22337 master.cpp:3362] Processing ACCEPT call for offers: [ 52799f65-6873-4d02-9085-d12af2116e05-O0 ] on agent 52799f65-6873-4d02-9085-d12af2116e05-S0 at slave(677)@172.30.2.7:45895 (ip-172-30-2-7.mesosphere.io) for framework 52799f65-6873-4d02-9085-d12af2116e05-0000 (default) at scheduler-47bc2772-2dc7-4a91-b8dc-6ef919678f63@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.556901 22337 master.cpp:2984] Authorizing framework principal 'test-principal' to launch task 45f52dd2-2ce4-4d41-b98a-cf7d4a583a34
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.557337 22333 master.cpp:7808] Adding task 45f52dd2-2ce4-4d41-b98a-cf7d4a583a34 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent 52799f65-6873-4d02-9085-d12af2116e05-S0 (ip-172-30-2-7.mesosphere.io)
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.557394 22333 master.cpp:3962] Launching task 45f52dd2-2ce4-4d41-b98a-cf7d4a583a34 of framework 52799f65-6873-4d02-9085-d12af2116e05-0000 (default) at scheduler-47bc2772-2dc7-4a91-b8dc-6ef919678f63@172.30.2.7:45895 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent 52799f65-6873-4d02-9085-d12af2116e05-S0 at slave(677)@172.30.2.7:45895 (ip-172-30-2-7.mesosphere.io)
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.557534 22332 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 738103ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.557561 22332 leveldb.cpp:399] Deleting ~2 keys from leveldb took 15709ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.557572 22332 replica.cpp:708] Persisted action TRUNCATE at position 4
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.557590 22334 slave.cpp:1535] Got assigned task '45f52dd2-2ce4-4d41-b98a-cf7d4a583a34' for framework 52799f65-6873-4d02-9085-d12af2116e05-0000
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.557781 22334 slave.cpp:1692] Launching task '45f52dd2-2ce4-4d41-b98a-cf7d4a583a34' for framework 52799f65-6873-4d02-9085-d12af2116e05-0000
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.557965 22334 paths.cpp:536] Trying to chown '/mnt/teamcity/temp/buildTmp/IsolationFlag_CpuIsolatorTest_ROOT_SystemCpuUsage_0_KLzIFk/slaves/52799f65-6873-4d02-9085-d12af2116e05-S0/frameworks/52799f65-6873-4d02-9085-d12af2116e05-0000/executors/45f52dd2-2ce4-4d41-b98a-cf7d4a583a34/runs/4eed487a-4ff4-4992-ab72-4f97170f0c07' to user 'root'
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.563412 22334 slave.cpp:6090] Launching executor '45f52dd2-2ce4-4d41-b98a-cf7d4a583a34' of framework 52799f65-6873-4d02-9085-d12af2116e05-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/mnt/teamcity/temp/buildTmp/IsolationFlag_CpuIsolatorTest_ROOT_SystemCpuUsage_0_KLzIFk/slaves/52799f65-6873-4d02-9085-d12af2116e05-S0/frameworks/52799f65-6873-4d02-9085-d12af2116e05-0000/executors/45f52dd2-2ce4-4d41-b98a-cf7d4a583a34/runs/4eed487a-4ff4-4992-ab72-4f97170f0c07'
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.563627 22334 slave.cpp:1978] Queued task '45f52dd2-2ce4-4d41-b98a-cf7d4a583a34' for executor '45f52dd2-2ce4-4d41-b98a-cf7d4a583a34' of framework 52799f65-6873-4d02-9085-d12af2116e05-0000
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.563639 22333 containerizer.cpp:846] Starting container 4eed487a-4ff4-4992-ab72-4f97170f0c07 for executor '45f52dd2-2ce4-4d41-b98a-cf7d4a583a34' of framework 52799f65-6873-4d02-9085-d12af2116e05-0000
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.563654 22334 slave.cpp:864] Successfully attached file '/mnt/teamcity/temp/buildTmp/IsolationFlag_CpuIsolatorTest_ROOT_SystemCpuUsage_0_KLzIFk/slaves/52799f65-6873-4d02-9085-d12af2116e05-S0/frameworks/52799f65-6873-4d02-9085-d12af2116e05-0000/executors/45f52dd2-2ce4-4d41-b98a-cf7d4a583a34/runs/4eed487a-4ff4-4992-ab72-4f97170f0c07'
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.564404 22335 containerizer.cpp:1257] Launching 'mesos-containerizer' with flags '--command="{"arguments":["mesos-executor","--launcher_dir=\/mnt\/teamcity\/work\/4240ba9ddd0997c3\/build\/src"],"shell":false,"value":"\/mnt\/teamcity\/work\/4240ba9ddd0997c3\/build\/src\/mesos-executor"}" --help="false" --pipe_read="32" --pipe_write="35" --pre_exec_commands="[]" --unshare_namespace_mnt="false" --user="root" --working_directory="/mnt/teamcity/temp/buildTmp/IsolationFlag_CpuIsolatorTest_ROOT_SystemCpuUsage_0_KLzIFk/slaves/52799f65-6873-4d02-9085-d12af2116e05-S0/frameworks/52799f65-6873-4d02-9085-d12af2116e05-0000/executors/45f52dd2-2ce4-4d41-b98a-cf7d4a583a34/runs/4eed487a-4ff4-4992-ab72-4f97170f0c07"'
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.564471 22335 linux_launcher.cpp:284] Cloning child process with flags = 
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.630311 19474 exec.cpp:162] Version: 1.1.0
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.630821 22334 slave.cpp:3179] Got registration for executor '45f52dd2-2ce4-4d41-b98a-cf7d4a583a34' of framework 52799f65-6873-4d02-9085-d12af2116e05-0000 from executor(1)@172.30.2.7:55758
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.631253 19472 exec.cpp:237] Executor registered on agent 52799f65-6873-4d02-9085-d12af2116e05-S0
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.631430 22330 slave.cpp:2182] Sending queued task '45f52dd2-2ce4-4d41-b98a-cf7d4a583a34' to executor '45f52dd2-2ce4-4d41-b98a-cf7d4a583a34' of framework 52799f65-6873-4d02-9085-d12af2116e05-0000 at executor(1)@172.30.2.7:55758
[19:43:35] :	 [Step 10/10] Received SUBSCRIBED event
[19:43:35] :	 [Step 10/10] Subscribed executor on ip-172-30-2-7.mesosphere.io
[19:43:35] :	 [Step 10/10] Received LAUNCH event
[19:43:35] :	 [Step 10/10] Starting task 45f52dd2-2ce4-4d41-b98a-cf7d4a583a34
[19:43:35] :	 [Step 10/10] /mnt/teamcity/work/4240ba9ddd0997c3/build/src/mesos-containerizer launch --command="{"shell":true,"value":"cat \/dev\/urandom > \/dev\/null & sleep 60"}" --help="false" --unshare_namespace_mnt="false"
[19:43:35] :	 [Step 10/10] Forked command at 19481
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.634115 22337 slave.cpp:3582] Handling status update TASK_RUNNING (UUID: 263645f5-d7a2-43aa-8d4c-f8da0fd9e1ff) for task 45f52dd2-2ce4-4d41-b98a-cf7d4a583a34 of framework 52799f65-6873-4d02-9085-d12af2116e05-0000 from executor(1)@172.30.2.7:55758
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.634580 22336 status_update_manager.cpp:323] Received status update TASK_RUNNING (UUID: 263645f5-d7a2-43aa-8d4c-f8da0fd9e1ff) for task 45f52dd2-2ce4-4d41-b98a-cf7d4a583a34 of framework 52799f65-6873-4d02-9085-d12af2116e05-0000
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.634600 22336 status_update_manager.cpp:500] Creating StatusUpdate stream for task 45f52dd2-2ce4-4d41-b98a-cf7d4a583a34 of framework 52799f65-6873-4d02-9085-d12af2116e05-0000
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.634732 22336 status_update_manager.cpp:377] Forwarding update TASK_RUNNING (UUID: 263645f5-d7a2-43aa-8d4c-f8da0fd9e1ff) for task 45f52dd2-2ce4-4d41-b98a-cf7d4a583a34 of framework 52799f65-6873-4d02-9085-d12af2116e05-0000 to the agent
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.634807 22332 slave.cpp:3983] Forwarding the update TASK_RUNNING (UUID: 263645f5-d7a2-43aa-8d4c-f8da0fd9e1ff) for task 45f52dd2-2ce4-4d41-b98a-cf7d4a583a34 of framework 52799f65-6873-4d02-9085-d12af2116e05-0000 to master@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.634888 22332 slave.cpp:3877] Status update manager successfully handled status update TASK_RUNNING (UUID: 263645f5-d7a2-43aa-8d4c-f8da0fd9e1ff) for task 45f52dd2-2ce4-4d41-b98a-cf7d4a583a34 of framework 52799f65-6873-4d02-9085-d12af2116e05-0000
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.634902 22332 slave.cpp:3893] Sending acknowledgement for status update TASK_RUNNING (UUID: 263645f5-d7a2-43aa-8d4c-f8da0fd9e1ff) for task 45f52dd2-2ce4-4d41-b98a-cf7d4a583a34 of framework 52799f65-6873-4d02-9085-d12af2116e05-0000 to executor(1)@172.30.2.7:55758
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.635000 22333 master.cpp:5474] Status update TASK_RUNNING (UUID: 263645f5-d7a2-43aa-8d4c-f8da0fd9e1ff) for task 45f52dd2-2ce4-4d41-b98a-cf7d4a583a34 of framework 52799f65-6873-4d02-9085-d12af2116e05-0000 from agent 52799f65-6873-4d02-9085-d12af2116e05-S0 at slave(677)@172.30.2.7:45895 (ip-172-30-2-7.mesosphere.io)
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.635030 22333 master.cpp:5536] Forwarding status update TASK_RUNNING (UUID: 263645f5-d7a2-43aa-8d4c-f8da0fd9e1ff) for task 45f52dd2-2ce4-4d41-b98a-cf7d4a583a34 of framework 52799f65-6873-4d02-9085-d12af2116e05-0000
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.635098 22333 master.cpp:7186] Updating the state of task 45f52dd2-2ce4-4d41-b98a-cf7d4a583a34 of framework 52799f65-6873-4d02-9085-d12af2116e05-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.635187 22331 sched.cpp:1025] Scheduler::statusUpdate took 39215ns
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.635296 22337 master.cpp:4597] Processing ACKNOWLEDGE call 263645f5-d7a2-43aa-8d4c-f8da0fd9e1ff for task 45f52dd2-2ce4-4d41-b98a-cf7d4a583a34 of framework 52799f65-6873-4d02-9085-d12af2116e05-0000 (default) at scheduler-47bc2772-2dc7-4a91-b8dc-6ef919678f63@172.30.2.7:45895 on agent 52799f65-6873-4d02-9085-d12af2116e05-S0
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.635431 22336 status_update_manager.cpp:395] Received status update acknowledgement (UUID: 263645f5-d7a2-43aa-8d4c-f8da0fd9e1ff) for task 45f52dd2-2ce4-4d41-b98a-cf7d4a583a34 of framework 52799f65-6873-4d02-9085-d12af2116e05-0000
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.635534 22335 slave.cpp:2929] Status update manager successfully handled status update acknowledgement (UUID: 263645f5-d7a2-43aa-8d4c-f8da0fd9e1ff) for task 45f52dd2-2ce4-4d41-b98a-cf7d4a583a34 of framework 52799f65-6873-4d02-9085-d12af2116e05-0000
[19:43:35] :	 [Step 10/10] ../../src/tests/containerizer/cpu_isolator_tests.cpp:241: Failure
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.845367 22316 sched.cpp:1987] Asked to stop the driver
[19:43:35] :	 [Step 10/10] Expected: (0.125) <= (statistics.cpus_user_time_secs()), actual: 0.125 vs 0.07
[19:43:35] :	 [Step 10/10] Received SHUTDOWN event
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.845443 22331 sched.cpp:1187] Stopping framework 52799f65-6873-4d02-9085-d12af2116e05-0000
[19:43:35] :	 [Step 10/10] Shutting down
[19:43:35] :	 [Step 10/10] Sending SIGTERM to process tree at pid 19481
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.845561 22336 master.cpp:6638] Processing TEARDOWN call for framework 52799f65-6873-4d02-9085-d12af2116e05-0000 (default) at scheduler-47bc2772-2dc7-4a91-b8dc-6ef919678f63@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.845582 22336 master.cpp:6650] Removing framework 52799f65-6873-4d02-9085-d12af2116e05-0000 (default) at scheduler-47bc2772-2dc7-4a91-b8dc-6ef919678f63@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.845645 22336 master.cpp:7186] Updating the state of task 45f52dd2-2ce4-4d41-b98a-cf7d4a583a34 of framework 52799f65-6873-4d02-9085-d12af2116e05-0000 (latest state: TASK_KILLED, status update state: TASK_KILLED)
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.845654 22332 slave.cpp:2497] Asked to shut down framework 52799f65-6873-4d02-9085-d12af2116e05-0000 by master@172.30.2.7:45895
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.845648 22333 hierarchical.cpp:380] Deactivated framework 52799f65-6873-4d02-9085-d12af2116e05-0000
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.845677 22332 slave.cpp:2522] Shutting down framework 52799f65-6873-4d02-9085-d12af2116e05-0000
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.845692 22332 slave.cpp:4786] Shutting down executor '45f52dd2-2ce4-4d41-b98a-cf7d4a583a34' of framework 52799f65-6873-4d02-9085-d12af2116e05-0000 at executor(1)@172.30.2.7:55758
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.845808 22336 master.cpp:7282] Removing task 45f52dd2-2ce4-4d41-b98a-cf7d4a583a34 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 52799f65-6873-4d02-9085-d12af2116e05-0000 on agent 52799f65-6873-4d02-9085-d12af2116e05-S0 at slave(677)@172.30.2.7:45895 (ip-172-30-2-7.mesosphere.io)
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.845890 22337 hierarchical.cpp:1003] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on agent 52799f65-6873-4d02-9085-d12af2116e05-S0 from framework 52799f65-6873-4d02-9085-d12af2116e05-0000
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.846042 19479 exec.cpp:414] Executor asked to shutdown
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.846051 22334 containerizer.cpp:1617] Destroying container 4eed487a-4ff4-4992-ab72-4f97170f0c07
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.846155 22337 hierarchical.cpp:331] Removed framework 52799f65-6873-4d02-9085-d12af2116e05-0000
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.847178 22337 cgroups.cpp:2678] Freezing cgroup /sys/fs/cgroup/freezer/mesos/4eed487a-4ff4-4992-ab72-4f97170f0c07
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.950390 22334 cgroups.cpp:1412] Successfully froze cgroup /sys/fs/cgroup/freezer/mesos/4eed487a-4ff4-4992-ab72-4f97170f0c07 after 103.184128ms
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.951558 22335 cgroups.cpp:2696] Thawing cgroup /sys/fs/cgroup/freezer/mesos/4eed487a-4ff4-4992-ab72-4f97170f0c07
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.952617 22336 cgroups.cpp:1441] Successfully thawed cgroup /sys/fs/cgroup/freezer/mesos/4eed487a-4ff4-4992-ab72-4f97170f0c07 after 1.037312ms
[19:43:35]W:	 [Step 10/10] I0915 19:43:35.953325 22336 slave.cpp:4111] Got exited event for executor(1)@172.30.2.7:55758
[19:43:36]W:	 [Step 10/10] I0915 19:43:36.006680 22330 containerizer.cpp:1841] Executor for container 4eed487a-4ff4-4992-ab72-4f97170f0c07 has exited
[19:43:36]W:	 [Step 10/10] I0915 19:43:36.006695 22330 containerizer.cpp:1613] Destroy has already been initiated for 4eed487a-4ff4-4992-ab72-4f97170f0c07
[19:43:36]W:	 [Step 10/10] I0915 19:43:36.007766 22336 provisioner.cpp:413] Ignoring destroy request for unknown container 4eed487a-4ff4-4992-ab72-4f97170f0c07
[19:43:36]W:	 [Step 10/10] I0915 19:43:36.007889 22337 slave.cpp:4468] Executor '45f52dd2-2ce4-4d41-b98a-cf7d4a583a34' of framework 52799f65-6873-4d02-9085-d12af2116e05-0000 terminated with signal Killed
[19:43:36]W:	 [Step 10/10] I0915 19:43:36.007913 22337 slave.cpp:4572] Cleaning up executor '45f52dd2-2ce4-4d41-b98a-cf7d4a583a34' of framework 52799f65-6873-4d02-9085-d12af2116e05-0000 at executor(1)@172.30.2.7:55758
[19:43:36]W:	 [Step 10/10] I0915 19:43:36.008029 22335 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/IsolationFlag_CpuIsolatorTest_ROOT_SystemCpuUsage_0_KLzIFk/slaves/52799f65-6873-4d02-9085-d12af2116e05-S0/frameworks/52799f65-6873-4d02-9085-d12af2116e05-0000/executors/45f52dd2-2ce4-4d41-b98a-cf7d4a583a34/runs/4eed487a-4ff4-4992-ab72-4f97170f0c07' for gc 6.99999990763852days in the future
[19:43:36]W:	 [Step 10/10] I0915 19:43:36.008049 22337 slave.cpp:4660] Cleaning up framework 52799f65-6873-4d02-9085-d12af2116e05-0000
[19:43:36]W:	 [Step 10/10] I0915 19:43:36.008072 22335 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/IsolationFlag_CpuIsolatorTest_ROOT_SystemCpuUsage_0_KLzIFk/slaves/52799f65-6873-4d02-9085-d12af2116e05-S0/frameworks/52799f65-6873-4d02-9085-d12af2116e05-0000/executors/45f52dd2-2ce4-4d41-b98a-cf7d4a583a34' for gc 6.99999990697778days in the future
[19:43:36]W:	 [Step 10/10] I0915 19:43:36.008100 22331 status_update_manager.cpp:285] Closing status update streams for framework 52799f65-6873-4d02-9085-d12af2116e05-0000
[19:43:36]W:	 [Step 10/10] I0915 19:43:36.008118 22331 status_update_manager.cpp:531] Cleaning up status update stream for task 45f52dd2-2ce4-4d41-b98a-cf7d4a583a34 of framework 52799f65-6873-4d02-9085-d12af2116e05-0000
[19:43:36]W:	 [Step 10/10] I0915 19:43:36.008155 22337 slave.cpp:783] Agent terminating
[19:43:36]W:	 [Step 10/10] I0915 19:43:36.008162 22334 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/IsolationFlag_CpuIsolatorTest_ROOT_SystemCpuUsage_0_KLzIFk/slaves/52799f65-6873-4d02-9085-d12af2116e05-S0/frameworks/52799f65-6873-4d02-9085-d12af2116e05-0000' for gc 6.99999990622815days in the future
[19:43:36]W:	 [Step 10/10] I0915 19:43:36.008219 22330 master.cpp:1253] Agent 52799f65-6873-4d02-9085-d12af2116e05-S0 at slave(677)@172.30.2.7:45895 (ip-172-30-2-7.mesosphere.io) disconnected
[19:43:36]W:	 [Step 10/10] I0915 19:43:36.008235 22330 master.cpp:2788] Disconnecting agent 52799f65-6873-4d02-9085-d12af2116e05-S0 at slave(677)@172.30.2.7:45895 (ip-172-30-2-7.mesosphere.io)
[19:43:36]W:	 [Step 10/10] I0915 19:43:36.008272 22330 master.cpp:2807] Deactivating agent 52799f65-6873-4d02-9085-d12af2116e05-S0 at slave(677)@172.30.2.7:45895 (ip-172-30-2-7.mesosphere.io)
[19:43:36]W:	 [Step 10/10] I0915 19:43:36.008368 22330 hierarchical.cpp:569] Agent 52799f65-6873-4d02-9085-d12af2116e05-S0 deactivated
[19:43:36]W:	 [Step 10/10] I0915 19:43:36.009995 22316 master.cpp:1096] Master terminating
[19:43:36]W:	 [Step 10/10] I0915 19:43:36.010123 22332 hierarchical.cpp:508] Removed agent 52799f65-6873-4d02-9085-d12af2116e05-S0
[19:43:36] :	 [Step 10/10] [  FAILED  ] IsolationFlag/CpuIsolatorTest.ROOT_SystemCpuUsage/0, where GetParam() = "posix/cpu" (481 ms)