[
https://issues.apache.org/jira/browse/MESOS-6167?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Anand Mazumdar updated MESOS-6167:
----------------------------------
Fix Version/s: 1.1.0
> CgroupsIsolatorTest.ROOT_CGROUPS_RevocableCpu is flaky
> ------------------------------------------------------
>
> Key: MESOS-6167
> URL: https://issues.apache.org/jira/browse/MESOS-6167
> Project: Mesos
> Issue Type: Bug
> Components: cgroups, tests
> Environment: CentOS 6, both with and without libevent/SSL
> Reporter: Greg Mann
> Assignee: haosdent
> Labels: cgroups, mesosphere, tests
> Fix For: 1.1.0
>
>
> Observed in our internal CI, multiple times on CentOS 6:
> {code}
> [01:41:46] : [Step 10/10] [ RUN ]
> CgroupsIsolatorTest.ROOT_CGROUPS_RevocableCpu
> [01:41:46]W: [Step 10/10] I0915 01:41:46.975854 25527 leveldb.cpp:174]
> Opened db in 9.389579ms
> [01:41:46]W: [Step 10/10] I0915 01:41:46.978809 25527 leveldb.cpp:181]
> Compacted db in 2.935597ms
> [01:41:46]W: [Step 10/10] I0915 01:41:46.978832 25527 leveldb.cpp:196]
> Created db iterator in 5187ns
> [01:41:46]W: [Step 10/10] I0915 01:41:46.978838 25527 leveldb.cpp:202]
> Seeked to beginning of db in 727ns
> [01:41:46]W: [Step 10/10] I0915 01:41:46.978842 25527 leveldb.cpp:271]
> Iterated through 0 keys in the db in 390ns
> [01:41:46]W: [Step 10/10] I0915 01:41:46.978854 25527 replica.cpp:776]
> Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> [01:41:46]W: [Step 10/10] I0915 01:41:46.979041 25545 recover.cpp:451]
> Starting replica recovery
> [01:41:46]W: [Step 10/10] I0915 01:41:46.979174 25544 recover.cpp:477]
> Replica is in EMPTY status
> [01:41:46]W: [Step 10/10] I0915 01:41:46.979537 25545 replica.cpp:673]
> Replica in EMPTY status received a broadcasted recover request from
> __req_res__(5795)@172.30.2.185:53570
> [01:41:46]W: [Step 10/10] I0915 01:41:46.979641 25548 recover.cpp:197]
> Received a recover response from a replica in EMPTY status
> [01:41:46]W: [Step 10/10] I0915 01:41:46.979759 25547 recover.cpp:568]
> Updating replica status to STARTING
> [01:41:46]W: [Step 10/10] I0915 01:41:46.980183 25548 master.cpp:380]
> Master c98a98bf-e3b7-4de1-8b1f-19182ae60bfa (ip-172-30-2-185.mesosphere.io)
> started on 172.30.2.185:53570
> [01:41:46]W: [Step 10/10] I0915 01:41:46.980197 25548 master.cpp:382] 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/rADn1G/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/rADn1G/master" --zk_session_timeout="10secs"
> [01:41:46]W: [Step 10/10] I0915 01:41:46.980334 25548 master.cpp:432]
> Master only allowing authenticated frameworks to register
> [01:41:46]W: [Step 10/10] I0915 01:41:46.980340 25548 master.cpp:446]
> Master only allowing authenticated agents to register
> [01:41:46]W: [Step 10/10] I0915 01:41:46.980345 25548 master.cpp:459]
> Master only allowing authenticated HTTP frameworks to register
> [01:41:46]W: [Step 10/10] I0915 01:41:46.980348 25548 credentials.hpp:37]
> Loading credentials for authentication from '/tmp/rADn1G/credentials'
> [01:41:46]W: [Step 10/10] I0915 01:41:46.980433 25548 master.cpp:504] Using
> default 'crammd5' authenticator
> [01:41:46]W: [Step 10/10] I0915 01:41:46.980473 25548 http.cpp:883] Using
> default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
> [01:41:46]W: [Step 10/10] I0915 01:41:46.980532 25548 http.cpp:883] Using
> default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
> [01:41:46]W: [Step 10/10] I0915 01:41:46.980581 25548 http.cpp:883] Using
> default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
> [01:41:46]W: [Step 10/10] I0915 01:41:46.980640 25548 master.cpp:584]
> Authorization enabled
> [01:41:46]W: [Step 10/10] I0915 01:41:46.980725 25546 hierarchical.cpp:149]
> Initialized hierarchical allocator process
> [01:41:46]W: [Step 10/10] I0915 01:41:46.980748 25542
> whitelist_watcher.cpp:77] No whitelist given
> [01:41:46]W: [Step 10/10] I0915 01:41:46.981350 25543 master.cpp:1855]
> Elected as the leading master!
> [01:41:46]W: [Step 10/10] I0915 01:41:46.981362 25543 master.cpp:1556]
> Recovering from registrar
> [01:41:46]W: [Step 10/10] I0915 01:41:46.981426 25544 registrar.cpp:332]
> Recovering registrar
> [01:41:46]W: [Step 10/10] I0915 01:41:46.982399 25545 leveldb.cpp:304]
> Persisting metadata (8 bytes) to leveldb took 2.601407ms
> [01:41:46]W: [Step 10/10] I0915 01:41:46.982415 25545 replica.cpp:320]
> Persisted replica status to STARTING
> [01:41:46]W: [Step 10/10] I0915 01:41:46.982460 25545 recover.cpp:477]
> Replica is in STARTING status
> [01:41:46]W: [Step 10/10] I0915 01:41:46.982777 25547 replica.cpp:673]
> Replica in STARTING status received a broadcasted recover request from
> __req_res__(5796)@172.30.2.185:53570
> [01:41:46]W: [Step 10/10] I0915 01:41:46.982880 25542 recover.cpp:197]
> Received a recover response from a replica in STARTING status
> [01:41:46]W: [Step 10/10] I0915 01:41:46.983052 25545 recover.cpp:568]
> Updating replica status to VOTING
> [01:41:46]W: [Step 10/10] I0915 01:41:46.985255 25542 leveldb.cpp:304]
> Persisting metadata (8 bytes) to leveldb took 2.167305ms
> [01:41:46]W: [Step 10/10] I0915 01:41:46.985270 25542 replica.cpp:320]
> Persisted replica status to VOTING
> [01:41:46]W: [Step 10/10] I0915 01:41:46.985301 25542 recover.cpp:582]
> Successfully joined the Paxos group
> [01:41:46]W: [Step 10/10] I0915 01:41:46.985340 25542 recover.cpp:466]
> Recover process terminated
> [01:41:46]W: [Step 10/10] I0915 01:41:46.985468 25544 log.cpp:553]
> Attempting to start the writer
> [01:41:46]W: [Step 10/10] I0915 01:41:46.985865 25545 replica.cpp:493]
> Replica received implicit promise request from
> __req_res__(5797)@172.30.2.185:53570 with proposal 1
> [01:41:46]W: [Step 10/10] I0915 01:41:46.988029 25545 leveldb.cpp:304]
> Persisting metadata (8 bytes) to leveldb took 2.144324ms
> [01:41:46]W: [Step 10/10] I0915 01:41:46.988044 25545 replica.cpp:342]
> Persisted promised to 1
> [01:41:46]W: [Step 10/10] I0915 01:41:46.988252 25545 coordinator.cpp:238]
> Coordinator attempting to fill missing positions
> [01:41:46]W: [Step 10/10] I0915 01:41:46.988731 25545 replica.cpp:388]
> Replica received explicit promise request from
> __req_res__(5798)@172.30.2.185:53570 for position 0 with proposal 2
> [01:41:46]W: [Step 10/10] I0915 01:41:46.990911 25545 leveldb.cpp:341]
> Persisting action (8 bytes) to leveldb took 2.158608ms
> [01:41:46]W: [Step 10/10] I0915 01:41:46.990926 25545 replica.cpp:708]
> Persisted action NOP at position 0
> [01:41:46]W: [Step 10/10] I0915 01:41:46.991277 25544 replica.cpp:537]
> Replica received write request for position 0 from
> __req_res__(5799)@172.30.2.185:53570
> [01:41:46]W: [Step 10/10] I0915 01:41:46.991310 25544 leveldb.cpp:436]
> Reading position from leveldb took 12182ns
> [01:41:46]W: [Step 10/10] I0915 01:41:46.993629 25544 leveldb.cpp:341]
> Persisting action (14 bytes) to leveldb took 2.303151ms
> [01:41:46]W: [Step 10/10] I0915 01:41:46.993644 25544 replica.cpp:708]
> Persisted action NOP at position 0
> [01:41:46]W: [Step 10/10] I0915 01:41:46.993862 25549 replica.cpp:691]
> Replica received learned notice for position 0 from @0.0.0.0:0
> [01:41:46]W: [Step 10/10] I0915 01:41:46.996341 25549 leveldb.cpp:341]
> Persisting action (16 bytes) to leveldb took 2.461925ms
> [01:41:46]W: [Step 10/10] I0915 01:41:46.996356 25549 replica.cpp:708]
> Persisted action NOP at position 0
> [01:41:46]W: [Step 10/10] I0915 01:41:46.996515 25547 log.cpp:569] Writer
> started with ending position 0
> [01:41:46]W: [Step 10/10] I0915 01:41:46.996832 25544 leveldb.cpp:436]
> Reading position from leveldb took 11662ns
> [01:41:46]W: [Step 10/10] I0915 01:41:46.997043 25548 registrar.cpp:365]
> Successfully fetched the registry (0B) in 15.593984ms
> [01:41:46]W: [Step 10/10] I0915 01:41:46.997077 25548 registrar.cpp:464]
> Applied 1 operations in 4425ns; attempting to update the registry
> [01:41:46]W: [Step 10/10] I0915 01:41:46.997217 25542 log.cpp:577]
> Attempting to append 209 bytes to the log
> [01:41:46]W: [Step 10/10] I0915 01:41:46.997285 25549 coordinator.cpp:348]
> Coordinator attempting to write APPEND action at position 1
> [01:41:46]W: [Step 10/10] I0915 01:41:46.997540 25544 replica.cpp:537]
> Replica received write request for position 1 from
> __req_res__(5800)@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:46.999812 25544 leveldb.cpp:341]
> Persisting action (228 bytes) to leveldb took 2.252148ms
> [01:41:47]W: [Step 10/10] I0915 01:41:46.999828 25544 replica.cpp:708]
> Persisted action APPEND at position 1
> [01:41:47]W: [Step 10/10] I0915 01:41:47.000066 25544 replica.cpp:691]
> Replica received learned notice for position 1 from @0.0.0.0:0
> [01:41:47]W: [Step 10/10] I0915 01:41:47.002373 25544 leveldb.cpp:341]
> Persisting action (230 bytes) to leveldb took 2.29147ms
> [01:41:47]W: [Step 10/10] I0915 01:41:47.002389 25544 replica.cpp:708]
> Persisted action APPEND at position 1
> [01:41:47]W: [Step 10/10] I0915 01:41:47.002601 25542 registrar.cpp:509]
> Successfully updated the registry in 5.501952ms
> [01:41:47]W: [Step 10/10] I0915 01:41:47.002660 25542 registrar.cpp:395]
> Successfully recovered registrar
> [01:41:47]W: [Step 10/10] I0915 01:41:47.002683 25546 log.cpp:596]
> Attempting to truncate the log to 1
> [01:41:47]W: [Step 10/10] I0915 01:41:47.002754 25543 coordinator.cpp:348]
> Coordinator attempting to write TRUNCATE action at position 2
> [01:41:47]W: [Step 10/10] I0915 01:41:47.002761 25542 master.cpp:1664]
> Recovered 0 agents from the registry (170B); allowing 10mins for agents to
> re-register
> [01:41:47]W: [Step 10/10] I0915 01:41:47.002820 25549 hierarchical.cpp:176]
> Skipping recovery of hierarchical allocator: nothing to recover
> [01:41:47]W: [Step 10/10] I0915 01:41:47.003136 25548 replica.cpp:537]
> Replica received write request for position 2 from
> __req_res__(5801)@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.005607 25548 leveldb.cpp:341]
> Persisting action (16 bytes) to leveldb took 2.450189ms
> [01:41:47]W: [Step 10/10] I0915 01:41:47.005622 25548 replica.cpp:708]
> Persisted action TRUNCATE at position 2
> [01:41:47]W: [Step 10/10] I0915 01:41:47.005844 25548 replica.cpp:691]
> Replica received learned notice for position 2 from @0.0.0.0:0
> [01:41:47]W: [Step 10/10] I0915 01:41:47.008133 25548 leveldb.cpp:341]
> Persisting action (18 bytes) to leveldb took 2.270316ms
> [01:41:47]W: [Step 10/10] I0915 01:41:47.008162 25548 leveldb.cpp:399]
> Deleting ~1 keys from leveldb took 13976ns
> [01:41:47]W: [Step 10/10] I0915 01:41:47.008170 25548 replica.cpp:708]
> Persisted action TRUNCATE at position 2
> [01:41:47]W: [Step 10/10] I0915 01:41:47.009004 25527
> containerizer.cpp:217] Using isolation:
> cgroups/cpu,filesystem/posix,network/cni
> [01:41:47]W: [Step 10/10] I0915 01:41:47.011858 25527
> linux_launcher.cpp:104] Using /cgroup/freezer as the freezer hierarchy for
> the Linux launcher
> [01:41:47]W: [Step 10/10] I0915 01:41:47.017704 25527 cluster.cpp:436]
> Creating default 'local' authorizer
> [01:41:47]W: [Step 10/10] I0915 01:41:47.018116 25545 slave.cpp:208] Mesos
> agent started on (494)@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.018126 25545 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/CgroupsIsolatorTest_ROOT_CGROUPS_RevocableCpu_kmJO9J/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/CgroupsIsolatorTest_ROOT_CGROUPS_RevocableCpu_kmJO9J/fetch"
> --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
> --gc_disk_headroom="0.1" --hadoop_home="" --help="false"
> --hostname_lookup="true" --http_authenticators="basic"
> --http_command_executor="false"
> --http_credentials="/mnt/teamcity/temp/buildTmp/CgroupsIsolatorTest_ROOT_CGROUPS_RevocableCpu_kmJO9J/http_credentials"
> --image_provisioner_backend="copy" --initialize_driver_logging="true"
> --isolation="cgroups/cpu"
> --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/CgroupsIsolatorTest_ROOT_CGROUPS_RevocableCpu_kmJO9J"
> --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/CgroupsIsolatorTest_ROOT_CGROUPS_RevocableCpu_5CNAAI"
> [01:41:47]W: [Step 10/10] I0915 01:41:47.018337 25545 credentials.hpp:86]
> Loading credential for authentication from
> '/mnt/teamcity/temp/buildTmp/CgroupsIsolatorTest_ROOT_CGROUPS_RevocableCpu_kmJO9J/credential'
> [01:41:47]W: [Step 10/10] I0915 01:41:47.018401 25545 slave.cpp:346] Agent
> using credential for: test-principal
> [01:41:47]W: [Step 10/10] I0915 01:41:47.018411 25545 credentials.hpp:37]
> Loading credentials for authentication from
> '/mnt/teamcity/temp/buildTmp/CgroupsIsolatorTest_ROOT_CGROUPS_RevocableCpu_kmJO9J/http_credentials'
> [01:41:47]W: [Step 10/10] I0915 01:41:47.018522 25545 http.cpp:883] Using
> default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
> [01:41:47]W: [Step 10/10] I0915 01:41:47.018556 25545 http.cpp:883] Using
> default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
> [01:41:47]W: [Step 10/10] I0915 01:41:47.018857 25545 slave.cpp:529] Agent
> resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> [01:41:47]W: [Step 10/10] I0915 01:41:47.018872 25527 sched.cpp:226]
> Version: 1.1.0
> [01:41:47]W: [Step 10/10] I0915 01:41:47.018890 25545 slave.cpp:537] Agent
> attributes: [ ]
> [01:41:47]W: [Step 10/10] I0915 01:41:47.018913 25545 slave.cpp:542] Agent
> hostname: ip-172-30-2-185.mesosphere.io
> [01:41:47]W: [Step 10/10] I0915 01:41:47.019067 25549 sched.cpp:330] New
> master detected at master@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.019166 25549 sched.cpp:396]
> Authenticating with master master@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.019179 25549 sched.cpp:403] Using
> default CRAM-MD5 authenticatee
> [01:41:47]W: [Step 10/10] I0915 01:41:47.019249 25543 state.cpp:57]
> Recovering state from
> '/mnt/teamcity/temp/buildTmp/CgroupsIsolatorTest_ROOT_CGROUPS_RevocableCpu_5CNAAI/meta'
> [01:41:47]W: [Step 10/10] I0915 01:41:47.019332 25549
> status_update_manager.cpp:203] Recovering status update manager
> [01:41:47]W: [Step 10/10] I0915 01:41:47.019350 25548
> authenticatee.cpp:121] Creating new client SASL connection
> [01:41:47]W: [Step 10/10] I0915 01:41:47.019414 25549
> containerizer.cpp:578] Recovering containerizer
> [01:41:47]W: [Step 10/10] I0915 01:41:47.019508 25545 master.cpp:6234]
> Authenticating
> scheduler-e2e93805-14bc-4f61-9e65-2910e9caad23@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.019563 25542
> authenticator.cpp:414] Starting authentication session for
> crammd5-authenticatee(1010)@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.019668 25545 authenticator.cpp:98]
> Creating new server SASL connection
> [01:41:47]W: [Step 10/10] I0915 01:41:47.019745 25545
> authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> [01:41:47]W: [Step 10/10] I0915 01:41:47.019762 25545
> authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> [01:41:47]W: [Step 10/10] I0915 01:41:47.019822 25548
> authenticator.cpp:204] Received SASL authentication start
> [01:41:47]W: [Step 10/10] I0915 01:41:47.019865 25548
> authenticator.cpp:326] Authentication requires more steps
> [01:41:47]W: [Step 10/10] I0915 01:41:47.019896 25548
> authenticatee.cpp:259] Received SASL authentication step
> [01:41:47]W: [Step 10/10] I0915 01:41:47.019942 25548
> authenticator.cpp:232] Received SASL authentication step
> [01:41:47]W: [Step 10/10] I0915 01:41:47.019961 25548 auxprop.cpp:109]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-185' server FQDN: 'ip-172-30-2-185' SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> [01:41:47]W: [Step 10/10] I0915 01:41:47.019968 25548 auxprop.cpp:181]
> Looking up auxiliary property '*userPassword'
> [01:41:47]W: [Step 10/10] I0915 01:41:47.019975 25548 auxprop.cpp:181]
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [01:41:47]W: [Step 10/10] I0915 01:41:47.019982 25548 auxprop.cpp:109]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-185' server FQDN: 'ip-172-30-2-185' SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> [01:41:47]W: [Step 10/10] I0915 01:41:47.019989 25548 auxprop.cpp:131]
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [01:41:47]W: [Step 10/10] I0915 01:41:47.019996 25548 auxprop.cpp:131]
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since
> SASL_AUXPROP_AUTHZID == true
> [01:41:47]W: [Step 10/10] I0915 01:41:47.020010 25548
> authenticator.cpp:318] Authentication success
> [01:41:47]W: [Step 10/10] I0915 01:41:47.020051 25549
> authenticatee.cpp:299] Authentication success
> [01:41:47]W: [Step 10/10] I0915 01:41:47.020076 25546
> authenticator.cpp:432] Authentication session cleanup for
> crammd5-authenticatee(1010)@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.020153 25547 master.cpp:6264]
> Successfully authenticated principal 'test-principal' at
> scheduler-e2e93805-14bc-4f61-9e65-2910e9caad23@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.020289 25549 sched.cpp:502]
> Successfully authenticated with master master@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.020299 25549 sched.cpp:820]
> Sending SUBSCRIBE call to master@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.020380 25549 sched.cpp:853] Will
> retry registration in 850.25694ms if necessary
> [01:41:47]W: [Step 10/10] I0915 01:41:47.020431 25547 master.cpp:2429]
> Received SUBSCRIBE call for framework 'default' at
> scheduler-e2e93805-14bc-4f61-9e65-2910e9caad23@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.020455 25547 master.cpp:1891]
> Authorizing framework principal 'test-principal' to receive offers for role
> '*'
> [01:41:47]W: [Step 10/10] I0915 01:41:47.020567 25548 master.cpp:2505]
> Subscribing framework default with checkpointing disabled and capabilities [
> REVOCABLE_RESOURCES ]
> [01:41:47]W: [Step 10/10] I0915 01:41:47.020776 25545 hierarchical.cpp:269]
> Added framework c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000
> [01:41:47]W: [Step 10/10] I0915 01:41:47.020792 25545
> hierarchical.cpp:1675] No allocations performed
> [01:41:47]W: [Step 10/10] I0915 01:41:47.020803 25545
> hierarchical.cpp:1770] No inverse offers to send out!
> [01:41:47]W: [Step 10/10] I0915 01:41:47.020812 25545
> hierarchical.cpp:1271] Performed allocation for 0 agents in 24665ns
> [01:41:47]W: [Step 10/10] I0915 01:41:47.020915 25548 sched.cpp:743]
> Framework registered with c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000
> [01:41:47]W: [Step 10/10] I0915 01:41:47.020941 25548 sched.cpp:757]
> Scheduler::registered took 10902ns
> [01:41:47]W: [Step 10/10] I0915 01:41:47.021178 25546 provisioner.cpp:253]
> Provisioner recovery complete
> [01:41:47]W: [Step 10/10] I0915 01:41:47.021313 25547 slave.cpp:5197]
> Finished recovery
> [01:41:47]W: [Step 10/10] I0915 01:41:47.021505 25547 slave.cpp:5369]
> Querying resource estimator for oversubscribable resources
> [01:41:47]W: [Step 10/10] I0915 01:41:47.021590 25546
> status_update_manager.cpp:177] Pausing sending status updates
> [01:41:47]W: [Step 10/10] I0915 01:41:47.021638 25547 slave.cpp:911] New
> master detected at master@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.021649 25547 slave.cpp:970]
> Authenticating with master master@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.021659 25547 slave.cpp:981] Using
> default CRAM-MD5 authenticatee
> [01:41:47]W: [Step 10/10] I0915 01:41:47.021718 25547 slave.cpp:943]
> Detecting new master
> [01:41:47]W: [Step 10/10] I0915 01:41:47.021772 25543
> authenticatee.cpp:121] Creating new client SASL connection
> [01:41:47]W: [Step 10/10] I0915 01:41:47.021891 25543 master.cpp:6234]
> Authenticating slave(494)@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.021941 25543
> authenticator.cpp:414] Starting authentication session for
> crammd5-authenticatee(1011)@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.022004 25543 authenticator.cpp:98]
> Creating new server SASL connection
> [01:41:47]W: [Step 10/10] I0915 01:41:47.022076 25543
> authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> [01:41:47]W: [Step 10/10] I0915 01:41:47.022089 25543
> authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> [01:41:47]W: [Step 10/10] I0915 01:41:47.022128 25543
> authenticator.cpp:204] Received SASL authentication start
> [01:41:47]W: [Step 10/10] I0915 01:41:47.022162 25543
> authenticator.cpp:326] Authentication requires more steps
> [01:41:47]W: [Step 10/10] I0915 01:41:47.022198 25543
> authenticatee.cpp:259] Received SASL authentication step
> [01:41:47]W: [Step 10/10] I0915 01:41:47.022258 25547
> authenticator.cpp:232] Received SASL authentication step
> [01:41:47]W: [Step 10/10] I0915 01:41:47.022281 25547 auxprop.cpp:109]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-185' server FQDN: 'ip-172-30-2-185' SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> [01:41:47]W: [Step 10/10] I0915 01:41:47.022289 25547 auxprop.cpp:181]
> Looking up auxiliary property '*userPassword'
> [01:41:47]W: [Step 10/10] I0915 01:41:47.022294 25547 auxprop.cpp:181]
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [01:41:47]W: [Step 10/10] I0915 01:41:47.022300 25547 auxprop.cpp:109]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-185' server FQDN: 'ip-172-30-2-185' SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> [01:41:47]W: [Step 10/10] I0915 01:41:47.022305 25547 auxprop.cpp:131]
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [01:41:47]W: [Step 10/10] I0915 01:41:47.022308 25547 auxprop.cpp:131]
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since
> SASL_AUXPROP_AUTHZID == true
> [01:41:47]W: [Step 10/10] I0915 01:41:47.022316 25547
> authenticator.cpp:318] Authentication success
> [01:41:47]W: [Step 10/10] I0915 01:41:47.022354 25547
> authenticatee.cpp:299] Authentication success
> [01:41:47]W: [Step 10/10] I0915 01:41:47.022380 25543
> authenticator.cpp:432] Authentication session cleanup for
> crammd5-authenticatee(1011)@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.022408 25544 master.cpp:6264]
> Successfully authenticated principal 'test-principal' at
> slave(494)@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.022521 25547 slave.cpp:1065]
> Successfully authenticated with master master@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.022572 25547 slave.cpp:1471] Will
> retry registration in 19.13939ms if necessary
> [01:41:47]W: [Step 10/10] I0915 01:41:47.022620 25548 master.cpp:4886]
> Registering agent at slave(494)@172.30.2.185:53570
> (ip-172-30-2-185.mesosphere.io) with id
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0
> [01:41:47]W: [Step 10/10] I0915 01:41:47.022719 25542 registrar.cpp:464]
> Applied 1 operations in 10929ns; attempting to update the registry
> [01:41:47]W: [Step 10/10] I0915 01:41:47.022927 25549 log.cpp:577]
> Attempting to append 395 bytes to the log
> [01:41:47]W: [Step 10/10] I0915 01:41:47.022964 25549 coordinator.cpp:348]
> Coordinator attempting to write APPEND action at position 3
> [01:41:47]W: [Step 10/10] I0915 01:41:47.023308 25549 replica.cpp:537]
> Replica received write request for position 3 from
> __req_res__(5802)@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.025555 25549 leveldb.cpp:341]
> Persisting action (414 bytes) to leveldb took 2.229274ms
> [01:41:47]W: [Step 10/10] I0915 01:41:47.025570 25549 replica.cpp:708]
> Persisted action APPEND at position 3
> [01:41:47]W: [Step 10/10] I0915 01:41:47.025784 25546 replica.cpp:691]
> Replica received learned notice for position 3 from @0.0.0.0:0
> [01:41:47]W: [Step 10/10] I0915 01:41:47.028024 25546 leveldb.cpp:341]
> Persisting action (416 bytes) to leveldb took 2.222023ms
> [01:41:47]W: [Step 10/10] I0915 01:41:47.028040 25546 replica.cpp:708]
> Persisted action APPEND at position 3
> [01:41:47]W: [Step 10/10] I0915 01:41:47.028332 25542 registrar.cpp:509]
> Successfully updated the registry in 5.581056ms
> [01:41:47]W: [Step 10/10] I0915 01:41:47.028391 25545 log.cpp:596]
> Attempting to truncate the log to 3
> [01:41:47]W: [Step 10/10] I0915 01:41:47.028453 25543 coordinator.cpp:348]
> Coordinator attempting to write TRUNCATE action at position 4
> [01:41:47]W: [Step 10/10] I0915 01:41:47.028506 25548 master.cpp:4956]
> Registered agent c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0 at
> slave(494)@172.30.2.185:53570 (ip-172-30-2-185.mesosphere.io) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> [01:41:47]W: [Step 10/10] I0915 01:41:47.028548 25543 slave.cpp:4064]
> Received ping from slave-observer(456)@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.028564 25545 hierarchical.cpp:476]
> Added agent c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0
> (ip-172-30-2-185.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000] (allocated: )
> [01:41:47]W: [Step 10/10] I0915 01:41:47.028632 25543 slave.cpp:1111]
> Registered with master master@172.30.2.185:53570; given agent ID
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0
> [01:41:47]W: [Step 10/10] I0915 01:41:47.028647 25543 fetcher.cpp:86]
> Clearing fetcher cache
> [01:41:47]W: [Step 10/10] I0915 01:41:47.028710 25547
> status_update_manager.cpp:184] Resuming sending status updates
> [01:41:47]W: [Step 10/10] I0915 01:41:47.028714 25549 replica.cpp:537]
> Replica received write request for position 4 from
> __req_res__(5803)@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.028733 25545
> hierarchical.cpp:1770] No inverse offers to send out!
> [01:41:47]W: [Step 10/10] I0915 01:41:47.028759 25545
> hierarchical.cpp:1294] Performed allocation for agent
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0 in 173200ns
> [01:41:47]W: [Step 10/10] I0915 01:41:47.028836 25547 master.cpp:6063]
> Sending 1 offers to framework c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000
> (default) at scheduler-e2e93805-14bc-4f61-9e65-2910e9caad23@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.028877 25543 slave.cpp:1134]
> Checkpointing SlaveInfo to
> '/mnt/teamcity/temp/buildTmp/CgroupsIsolatorTest_ROOT_CGROUPS_RevocableCpu_5CNAAI/meta/slaves/c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0/slave.info'
> [01:41:47]W: [Step 10/10] I0915 01:41:47.029042 25547 sched.cpp:917]
> Scheduler::resourceOffers took 34048ns
> [01:41:47]W: [Step 10/10] I0915 01:41:47.029269 25545 slave.cpp:5383]
> Received oversubscribable resources cpus(*){REV}:1 from the resource estimator
> [01:41:47]W: [Step 10/10] I0915 01:41:47.029289 25545 slave.cpp:5412]
> Forwarding total oversubscribed resources cpus(*){REV}:1
> [01:41:47]W: [Step 10/10] I0915 01:41:47.029357 25547 master.cpp:5340]
> Received update of agent c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0 at
> slave(494)@172.30.2.185:53570 (ip-172-30-2-185.mesosphere.io) with total
> oversubscribed resources cpus(*){REV}:1
> [01:41:47]W: [Step 10/10] I0915 01:41:47.029462 25547 hierarchical.cpp:540]
> Agent c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0 (ip-172-30-2-185.mesosphere.io)
> updated with oversubscribed resources cpus(*){REV}:1 (total: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]; cpus(*){REV}:1, allocated:
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
> [01:41:47]W: [Step 10/10] I0915 01:41:47.029570 25547
> hierarchical.cpp:1770] No inverse offers to send out!
> [01:41:47]W: [Step 10/10] I0915 01:41:47.029584 25547
> hierarchical.cpp:1294] Performed allocation for agent
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0 in 97376ns
> [01:41:47]W: [Step 10/10] I0915 01:41:47.029636 25545 master.cpp:6063]
> Sending 1 offers to framework c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000
> (default) at scheduler-e2e93805-14bc-4f61-9e65-2910e9caad23@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.029808 25545 sched.cpp:917]
> Scheduler::resourceOffers took 27223ns
> [01:41:47]W: [Step 10/10] I0915 01:41:47.030189 25546 master.cpp:3363]
> Processing ACCEPT call for offers: [ c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-O1
> ] on agent c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0 at
> slave(494)@172.30.2.185:53570 (ip-172-30-2-185.mesosphere.io) for framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000 (default) at
> scheduler-e2e93805-14bc-4f61-9e65-2910e9caad23@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.030233 25546 master.cpp:2985]
> Authorizing framework principal 'test-principal' to launch task
> d1f9bb28-c156-4b55-aa94-e9731e87e58c
> [01:41:47]W: [Step 10/10] I0915 01:41:47.030532 25546 master.cpp:7809]
> Adding task d1f9bb28-c156-4b55-aa94-e9731e87e58c with resources
> cpus(*){REV}:1 on agent c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0
> (ip-172-30-2-185.mesosphere.io)
> [01:41:47]W: [Step 10/10] I0915 01:41:47.030555 25546 master.cpp:3963]
> Launching task d1f9bb28-c156-4b55-aa94-e9731e87e58c of framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000 (default) at
> scheduler-e2e93805-14bc-4f61-9e65-2910e9caad23@172.30.2.185:53570 with
> resources cpus(*){REV}:1 on agent c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0 at
> slave(494)@172.30.2.185:53570 (ip-172-30-2-185.mesosphere.io)
> [01:41:47]W: [Step 10/10] I0915 01:41:47.030808 25543 slave.cpp:1535] Got
> assigned task 'd1f9bb28-c156-4b55-aa94-e9731e87e58c' for framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000
> [01:41:47]W: [Step 10/10] I0915 01:41:47.030908 25549 leveldb.cpp:341]
> Persisting action (16 bytes) to leveldb took 2.17411ms
> [01:41:47]W: [Step 10/10] I0915 01:41:47.030923 25549 replica.cpp:708]
> Persisted action TRUNCATE at position 4
> [01:41:47]W: [Step 10/10] I0915 01:41:47.031059 25543 slave.cpp:1692]
> Launching task 'd1f9bb28-c156-4b55-aa94-e9731e87e58c' for framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000
> [01:41:47]W: [Step 10/10] I0915 01:41:47.031173 25548 replica.cpp:691]
> Replica received learned notice for position 4 from @0.0.0.0:0
> [01:41:47]W: [Step 10/10] I0915 01:41:47.031497 25543 paths.cpp:536] Trying
> to chown
> '/mnt/teamcity/temp/buildTmp/CgroupsIsolatorTest_ROOT_CGROUPS_RevocableCpu_5CNAAI/slaves/c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0/frameworks/c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000/executors/d1f9bb28-c156-4b55-aa94-e9731e87e58c/runs/3a86b14d-e130-4894-9cf3-b37aefd009b6'
> to user 'root'
> [01:41:47]W: [Step 10/10] I0915 01:41:47.033741 25548 leveldb.cpp:341]
> Persisting action (18 bytes) to leveldb took 2.359834ms
> [01:41:47]W: [Step 10/10] I0915 01:41:47.033802 25548 leveldb.cpp:399]
> Deleting ~2 keys from leveldb took 28425ns
> [01:41:47]W: [Step 10/10] I0915 01:41:47.033815 25548 replica.cpp:708]
> Persisted action TRUNCATE at position 4
> [01:41:47]W: [Step 10/10] I0915 01:41:47.036911 25543 slave.cpp:6089]
> Launching executor 'd1f9bb28-c156-4b55-aa94-e9731e87e58c' of framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000 with resources cpus(*):0.1;
> mem(*):32 in work directory
> '/mnt/teamcity/temp/buildTmp/CgroupsIsolatorTest_ROOT_CGROUPS_RevocableCpu_5CNAAI/slaves/c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0/frameworks/c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000/executors/d1f9bb28-c156-4b55-aa94-e9731e87e58c/runs/3a86b14d-e130-4894-9cf3-b37aefd009b6'
> [01:41:47]W: [Step 10/10] I0915 01:41:47.037107 25548
> containerizer.cpp:846] Starting container
> 3a86b14d-e130-4894-9cf3-b37aefd009b6 for executor
> 'd1f9bb28-c156-4b55-aa94-e9731e87e58c' of framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000
> [01:41:47]W: [Step 10/10] I0915 01:41:47.037117 25543 slave.cpp:1978]
> Queued task 'd1f9bb28-c156-4b55-aa94-e9731e87e58c' for executor
> 'd1f9bb28-c156-4b55-aa94-e9731e87e58c' of framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000
> [01:41:47]W: [Step 10/10] I0915 01:41:47.037142 25543 slave.cpp:864]
> Successfully attached file
> '/mnt/teamcity/temp/buildTmp/CgroupsIsolatorTest_ROOT_CGROUPS_RevocableCpu_5CNAAI/slaves/c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0/frameworks/c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000/executors/d1f9bb28-c156-4b55-aa94-e9731e87e58c/runs/3a86b14d-e130-4894-9cf3-b37aefd009b6'
> [01:41:47]W: [Step 10/10] I0915 01:41:47.037482 25547 cgroups.cpp:375]
> Creating cgroup at '/cgroup/cpu/mesos/3a86b14d-e130-4894-9cf3-b37aefd009b6'
> for container 3a86b14d-e130-4894-9cf3-b37aefd009b6
> [01:41:47]W: [Step 10/10] I0915 01:41:47.038218 25547 cgroups.cpp:431]
> Chown the cgroup at '/cgroup/cpu/mesos/3a86b14d-e130-4894-9cf3-b37aefd009b6'
> to user 'root' for container 3a86b14d-e130-4894-9cf3-b37aefd009b6
> [01:41:47]W: [Step 10/10] I0915 01:41:47.038257 25547 cgroups.cpp:375]
> Creating cgroup at
> '/cgroup/cpuacct/mesos/3a86b14d-e130-4894-9cf3-b37aefd009b6' for container
> 3a86b14d-e130-4894-9cf3-b37aefd009b6
> [01:41:47]W: [Step 10/10] I0915 01:41:47.038872 25547 cgroups.cpp:431]
> Chown the cgroup at
> '/cgroup/cpuacct/mesos/3a86b14d-e130-4894-9cf3-b37aefd009b6' to user 'root'
> for container 3a86b14d-e130-4894-9cf3-b37aefd009b6
> [01:41:47]W: [Step 10/10] I0915 01:41:47.039438 25544 cpu.cpp:103] Updated
> 'cpu.shares' to 11 (cpus 1.1) for container
> 3a86b14d-e130-4894-9cf3-b37aefd009b6
> [01:41:47]W: [Step 10/10] I0915 01:41:47.039939 25547
> 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="20" --pipe_write="24" --pre_exec_commands="[]"
> --unshare_namespace_mnt="false" --user="root"
> --working_directory="/mnt/teamcity/temp/buildTmp/CgroupsIsolatorTest_ROOT_CGROUPS_RevocableCpu_5CNAAI/slaves/c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0/frameworks/c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000/executors/d1f9bb28-c156-4b55-aa94-e9731e87e58c/runs/3a86b14d-e130-4894-9cf3-b37aefd009b6"'
> [01:41:47]W: [Step 10/10] I0915 01:41:47.039995 25547
> linux_launcher.cpp:284] Cloning child process with flags =
> [01:41:47]W: [Step 10/10] I0915 01:41:47.105628 13622 exec.cpp:162]
> Version: 1.1.0
> [01:41:47]W: [Step 10/10] I0915 01:41:47.106247 25547 slave.cpp:3178] Got
> registration for executor 'd1f9bb28-c156-4b55-aa94-e9731e87e58c' of framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000 from executor(1)@172.30.2.185:47894
> [01:41:47]W: [Step 10/10] I0915 01:41:47.106824 13623 exec.cpp:237]
> Executor registered on agent c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0
> [01:41:47]W: [Step 10/10] I0915 01:41:47.107231 25544 cpu.cpp:103] Updated
> 'cpu.shares' to 11 (cpus 1.1) for container
> 3a86b14d-e130-4894-9cf3-b37aefd009b6
> [01:41:47]W: [Step 10/10] I0915 01:41:47.107523 25548 slave.cpp:2182]
> Sending queued task 'd1f9bb28-c156-4b55-aa94-e9731e87e58c' to executor
> 'd1f9bb28-c156-4b55-aa94-e9731e87e58c' of framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000 at executor(1)@172.30.2.185:47894
> [01:41:47] : [Step 10/10] Received SUBSCRIBED event
> [01:41:47] : [Step 10/10] Subscribed executor on
> ip-172-30-2-185.mesosphere.io
> [01:41:47] : [Step 10/10] Received LAUNCH event
> [01:41:47] : [Step 10/10] Starting task d1f9bb28-c156-4b55-aa94-e9731e87e58c
> [01:41:47] : [Step 10/10]
> /mnt/teamcity/work/4240ba9ddd0997c3/build/src/mesos-containerizer launch
> --command="{"shell":true,"value":"sleep 120"}" --help="false"
> --unshare_namespace_mnt="false"
> [01:41:47] : [Step 10/10] Forked command at 13627
> [01:41:47]W: [Step 10/10] I0915 01:41:47.111286 25546 slave.cpp:3581]
> Handling status update TASK_RUNNING (UUID:
> 5aec8de6-3014-44d1-8a2e-fabfc762ce6e) for task
> d1f9bb28-c156-4b55-aa94-e9731e87e58c of framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000 from executor(1)@172.30.2.185:47894
> [01:41:47]W: [Step 10/10] I0915 01:41:47.111793 25549
> status_update_manager.cpp:323] Received status update TASK_RUNNING (UUID:
> 5aec8de6-3014-44d1-8a2e-fabfc762ce6e) for task
> d1f9bb28-c156-4b55-aa94-e9731e87e58c of framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000
> [01:41:47]W: [Step 10/10] I0915 01:41:47.111811 25549
> status_update_manager.cpp:500] Creating StatusUpdate stream for task
> d1f9bb28-c156-4b55-aa94-e9731e87e58c of framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000
> [01:41:47]W: [Step 10/10] I0915 01:41:47.111989 25549
> status_update_manager.cpp:377] Forwarding update TASK_RUNNING (UUID:
> 5aec8de6-3014-44d1-8a2e-fabfc762ce6e) for task
> d1f9bb28-c156-4b55-aa94-e9731e87e58c of framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000 to the agent
> [01:41:47]W: [Step 10/10] I0915 01:41:47.112062 25547 slave.cpp:3982]
> Forwarding the update TASK_RUNNING (UUID:
> 5aec8de6-3014-44d1-8a2e-fabfc762ce6e) for task
> d1f9bb28-c156-4b55-aa94-e9731e87e58c of framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000 to master@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.112174 25547 slave.cpp:3876]
> Status update manager successfully handled status update TASK_RUNNING (UUID:
> 5aec8de6-3014-44d1-8a2e-fabfc762ce6e) for task
> d1f9bb28-c156-4b55-aa94-e9731e87e58c of framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000
> [01:41:47]W: [Step 10/10] I0915 01:41:47.112190 25547 slave.cpp:3892]
> Sending acknowledgement for status update TASK_RUNNING (UUID:
> 5aec8de6-3014-44d1-8a2e-fabfc762ce6e) for task
> d1f9bb28-c156-4b55-aa94-e9731e87e58c of framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000 to executor(1)@172.30.2.185:47894
> [01:41:47]W: [Step 10/10] I0915 01:41:47.112231 25548 master.cpp:5475]
> Status update TASK_RUNNING (UUID: 5aec8de6-3014-44d1-8a2e-fabfc762ce6e) for
> task d1f9bb28-c156-4b55-aa94-e9731e87e58c of framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000 from agent
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0 at slave(494)@172.30.2.185:53570
> (ip-172-30-2-185.mesosphere.io)
> [01:41:47]W: [Step 10/10] I0915 01:41:47.112251 25548 master.cpp:5537]
> Forwarding status update TASK_RUNNING (UUID:
> 5aec8de6-3014-44d1-8a2e-fabfc762ce6e) for task
> d1f9bb28-c156-4b55-aa94-e9731e87e58c of framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000
> [01:41:47]W: [Step 10/10] I0915 01:41:47.112298 25548 master.cpp:7187]
> Updating the state of task d1f9bb28-c156-4b55-aa94-e9731e87e58c of framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000 (latest state: TASK_RUNNING, status
> update state: TASK_RUNNING)
> [01:41:47]W: [Step 10/10] I0915 01:41:47.112529 25543 sched.cpp:1025]
> Scheduler::statusUpdate took 41499ns
> [01:41:47]W: [Step 10/10] I0915 01:41:47.112686 25542 master.cpp:4598]
> Processing ACKNOWLEDGE call 5aec8de6-3014-44d1-8a2e-fabfc762ce6e for task
> d1f9bb28-c156-4b55-aa94-e9731e87e58c of framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000 (default) at
> scheduler-e2e93805-14bc-4f61-9e65-2910e9caad23@172.30.2.185:53570 on agent
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0
> [01:41:47]W: [Step 10/10] I0915 01:41:47.112833 25545
> status_update_manager.cpp:395] Received status update acknowledgement (UUID:
> 5aec8de6-3014-44d1-8a2e-fabfc762ce6e) for task
> d1f9bb28-c156-4b55-aa94-e9731e87e58c of framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000
> [01:41:47] : [Step 10/10]
> ../../src/tests/containerizer/cgroups_isolator_tests.cpp:327: Failure
> [01:41:47] : [Step 10/10] cgroups::cpu::shares(cpuHierarchy, cpuCgroup):
> '/sys/fs/cgroup/cpu' is not a valid hierarchy
> [01:41:47]W: [Step 10/10] I0915 01:41:47.112934 25543 slave.cpp:2928]
> Status update manager successfully handled status update acknowledgement
> (UUID: 5aec8de6-3014-44d1-8a2e-fabfc762ce6e) for task
> d1f9bb28-c156-4b55-aa94-e9731e87e58c of framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000
> [01:41:47]W: [Step 10/10] I0915 01:41:47.112973 25527 sched.cpp:1987] Asked
> to stop the driver
> [01:41:47]W: [Step 10/10] I0915 01:41:47.113019 25548 sched.cpp:1187]
> Stopping framework c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000
> [01:41:47]W: [Step 10/10] I0915 01:41:47.113159 25544 master.cpp:6639]
> Processing TEARDOWN call for framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000 (default) at
> scheduler-e2e93805-14bc-4f61-9e65-2910e9caad23@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.113181 25544 master.cpp:6651]
> Removing framework c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000 (default) at
> scheduler-e2e93805-14bc-4f61-9e65-2910e9caad23@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.113255 25544 master.cpp:7187]
> Updating the state of task d1f9bb28-c156-4b55-aa94-e9731e87e58c of framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000 (latest state: TASK_KILLED, status
> update state: TASK_KILLED)
> [01:41:47]W: [Step 10/10] I0915 01:41:47.113268 25545 slave.cpp:2496] Asked
> to shut down framework c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000 by
> master@172.30.2.185:53570
> [01:41:47]W: [Step 10/10] I0915 01:41:47.113284 25545 slave.cpp:2521]
> Shutting down framework c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000
> [01:41:47]W: [Step 10/10] I0915 01:41:47.113293 25545 slave.cpp:4785]
> Shutting down executor 'd1f9bb28-c156-4b55-aa94-e9731e87e58c' of framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000 at executor(1)@172.30.2.185:47894
> [01:41:47]W: [Step 10/10] I0915 01:41:47.113351 25544 master.cpp:7283]
> Removing task d1f9bb28-c156-4b55-aa94-e9731e87e58c with resources
> cpus(*){REV}:1 of framework c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000 on
> agent c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0 at
> slave(494)@172.30.2.185:53570 (ip-172-30-2-185.mesosphere.io)
> [01:41:47]W: [Step 10/10] I0915 01:41:47.113382 25542 hierarchical.cpp:380]
> Deactivated framework c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000
> [01:41:47]W: [Step 10/10] I0915 01:41:47.113468 25542
> hierarchical.cpp:1003] Recovered cpus(*){REV}:1 (total: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]; cpus(*){REV}:1, allocated:
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on agent
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0 from framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000
> [01:41:47] : [Step 10/10] Received SHUTDOWN event
> [01:41:47] : [Step 10/10] Shutting down
> [01:41:47]W: [Step 10/10] I0915 01:41:47.113581 13619 exec.cpp:414]
> Executor asked to shutdown
> [01:41:47] : [Step 10/10] Sending SIGTERM to process tree at pid 13627
> [01:41:47]W: [Step 10/10] I0915 01:41:47.113659 25542
> hierarchical.cpp:1003] Recovered cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]; cpus(*){REV}:1, allocated: ) on agent
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0 from framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000
> [01:41:47]W: [Step 10/10] I0915 01:41:47.113785 25542 hierarchical.cpp:331]
> Removed framework c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000
> [01:41:47]W: [Step 10/10] I0915 01:41:47.114156 25543
> containerizer.cpp:1617] Destroying container
> 3a86b14d-e130-4894-9cf3-b37aefd009b6
> [01:41:47]W: [Step 10/10] I0915 01:41:47.115097 25543 cgroups.cpp:2678]
> Freezing cgroup /cgroup/freezer/mesos/3a86b14d-e130-4894-9cf3-b37aefd009b6
> [01:41:47]W: [Step 10/10] I0915 01:41:47.218070 25547 cgroups.cpp:1412]
> Successfully froze cgroup
> /cgroup/freezer/mesos/3a86b14d-e130-4894-9cf3-b37aefd009b6 after 102.954752ms
> [01:41:47]W: [Step 10/10] I0915 01:41:47.219043 25543 cgroups.cpp:2696]
> Thawing cgroup /cgroup/freezer/mesos/3a86b14d-e130-4894-9cf3-b37aefd009b6
> [01:41:47]W: [Step 10/10] I0915 01:41:47.220002 25544 cgroups.cpp:1441]
> Successfully thawed cgroup
> /cgroup/freezer/mesos/3a86b14d-e130-4894-9cf3-b37aefd009b6 after 939008ns
> [01:41:47]W: [Step 10/10] I0915 01:41:47.220759 25547 slave.cpp:4110] Got
> exited event for executor(1)@172.30.2.185:47894
> [01:41:47]W: [Step 10/10] I0915 01:41:47.265169 25542
> containerizer.cpp:1841] Executor for container
> 3a86b14d-e130-4894-9cf3-b37aefd009b6 has exited
> [01:41:47]W: [Step 10/10] I0915 01:41:47.265188 25542
> containerizer.cpp:1613] Destroy has already been initiated for
> 3a86b14d-e130-4894-9cf3-b37aefd009b6
> [01:41:47]W: [Step 10/10] I0915 01:41:47.268550 25546 provisioner.cpp:413]
> Ignoring destroy request for unknown container
> 3a86b14d-e130-4894-9cf3-b37aefd009b6
> [01:41:47]W: [Step 10/10] I0915 01:41:47.268652 25547 slave.cpp:4467]
> Executor 'd1f9bb28-c156-4b55-aa94-e9731e87e58c' of framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000 terminated with signal Killed
> [01:41:47]W: [Step 10/10] I0915 01:41:47.268674 25547 slave.cpp:4571]
> Cleaning up executor 'd1f9bb28-c156-4b55-aa94-e9731e87e58c' of framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000 at executor(1)@172.30.2.185:47894
> [01:41:47]W: [Step 10/10] I0915 01:41:47.268916 25542 gc.cpp:55] Scheduling
> '/mnt/teamcity/temp/buildTmp/CgroupsIsolatorTest_ROOT_CGROUPS_RevocableCpu_5CNAAI/slaves/c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0/frameworks/c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000/executors/d1f9bb28-c156-4b55-aa94-e9731e87e58c/runs/3a86b14d-e130-4894-9cf3-b37aefd009b6'
> for gc 6.99999688941037days in the future
> [01:41:47]W: [Step 10/10] I0915 01:41:47.268965 25547 slave.cpp:4659]
> Cleaning up framework c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000
> [01:41:47]W: [Step 10/10] I0915 01:41:47.268978 25542 gc.cpp:55] Scheduling
> '/mnt/teamcity/temp/buildTmp/CgroupsIsolatorTest_ROOT_CGROUPS_RevocableCpu_5CNAAI/slaves/c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0/frameworks/c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000/executors/d1f9bb28-c156-4b55-aa94-e9731e87e58c'
> for gc 6.9999968871763days in the future
> [01:41:47]W: [Step 10/10] I0915 01:41:47.269069 25548
> status_update_manager.cpp:285] Closing status update streams for framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000
> [01:41:47]W: [Step 10/10] I0915 01:41:47.269078 25547 slave.cpp:783] Agent
> terminating
> [01:41:47]W: [Step 10/10] I0915 01:41:47.269088 25548
> status_update_manager.cpp:531] Cleaning up status update stream for task
> d1f9bb28-c156-4b55-aa94-e9731e87e58c of framework
> c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000
> [01:41:47]W: [Step 10/10] I0915 01:41:47.269091 25543 gc.cpp:55] Scheduling
> '/mnt/teamcity/temp/buildTmp/CgroupsIsolatorTest_ROOT_CGROUPS_RevocableCpu_5CNAAI/slaves/c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0/frameworks/c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-0000'
> for gc 6.99999688612444days in the future
> [01:41:47]W: [Step 10/10] I0915 01:41:47.269129 25546 master.cpp:1254]
> Agent c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0 at
> slave(494)@172.30.2.185:53570 (ip-172-30-2-185.mesosphere.io) disconnected
> [01:41:47]W: [Step 10/10] I0915 01:41:47.269148 25546 master.cpp:2789]
> Disconnecting agent c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0 at
> slave(494)@172.30.2.185:53570 (ip-172-30-2-185.mesosphere.io)
> [01:41:47]W: [Step 10/10] I0915 01:41:47.269166 25546 master.cpp:2808]
> Deactivating agent c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0 at
> slave(494)@172.30.2.185:53570 (ip-172-30-2-185.mesosphere.io)
> [01:41:47]W: [Step 10/10] I0915 01:41:47.269235 25544 hierarchical.cpp:569]
> Agent c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0 deactivated
> [01:41:47]W: [Step 10/10] I0915 01:41:47.270730 25527 master.cpp:1097]
> Master terminating
> [01:41:47]W: [Step 10/10] I0915 01:41:47.271019 25549 hierarchical.cpp:508]
> Removed agent c98a98bf-e3b7-4de1-8b1f-19182ae60bfa-S0
> [01:41:47] : [Step 10/10] [ FAILED ]
> CgroupsIsolatorTest.ROOT_CGROUPS_RevocableCpu (308 ms)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
