[
https://issues.apache.org/jira/browse/MESOS-6176?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Greg Mann updated MESOS-6176:
-----------------------------
Affects Version/s: 1.0.1
Environment: Fedora 23, Ubuntu 12/14, Debian 8, CentOS 6/7
Labels: mesosphere tests (was: )
Description:
Observed on our internal CI, on several different Linux distros, both with and
without SSL/libevent:
{code}
[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 [email protected]:45895
[19:43:35]W: [Step 10/10] I0915 19:43:35.550806 22335 sched.cpp:396]
Authenticating with master [email protected]: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 [email protected]: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
[email protected]:45895
[19:43:35]W: [Step 10/10] I0915 19:43:35.551867 22336 sched.cpp:502]
Successfully authenticated with master [email protected]:45895
[19:43:35]W: [Step 10/10] I0915 19:43:35.551879 22336 sched.cpp:820]
Sending SUBSCRIBE call to [email protected]: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
[email protected]: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 [email protected]: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 [email protected]: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 [email protected]: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 [email protected]: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 [email protected]: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
[email protected]: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
[email protected]: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 [email protected]: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
[email protected]: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
[email protected]: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
[email protected]: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
[email protected]: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)
{code}
Component/s: tests
Summary: CpuIsolatorTest.ROOT_SystemCpuUsage is flaky (was:
cpuisolatortest)
> CpuIsolatorTest.ROOT_SystemCpuUsage is flaky
> --------------------------------------------
>
> Key: MESOS-6176
> URL: https://issues.apache.org/jira/browse/MESOS-6176
> Project: Mesos
> Issue Type: Bug
> Components: tests
> Affects Versions: 1.0.1
> Environment: Fedora 23, Ubuntu 12/14, Debian 8, CentOS 6/7
> Reporter: Greg Mann
> Labels: mesosphere, tests
>
> Observed on our internal CI, on several different Linux distros, both with
> and without SSL/libevent:
> {code}
> [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 [email protected]:45895
> [19:43:35]W: [Step 10/10] I0915 19:43:35.550806 22335 sched.cpp:396]
> Authenticating with master [email protected]: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 [email protected]: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
> [email protected]:45895
> [19:43:35]W: [Step 10/10] I0915 19:43:35.551867 22336 sched.cpp:502]
> Successfully authenticated with master [email protected]:45895
> [19:43:35]W: [Step 10/10] I0915 19:43:35.551879 22336 sched.cpp:820]
> Sending SUBSCRIBE call to [email protected]: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
> [email protected]: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 [email protected]: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 [email protected]: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 [email protected]: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 [email protected]: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 [email protected]: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
> [email protected]: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
> [email protected]: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 [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]: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)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
