[
https://issues.apache.org/jira/browse/MESOS-6180?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15495213#comment-15495213
]
Jie Yu commented on MESOS-6180:
-------------------------------
This test looks suspicious to me. The log interleaving starts from there. The
TASK_LOST is not expected.
{noformat}
[23:32:52] : [Step 10/10] [ RUN ]
MesosContainerizerSlaveRecoveryTest.CGROUPS_ROOT_PidNamespaceForward
[23:32:52]W: [Step 10/10] I0915 23:32:52.347380 29518 cluster.cpp:157]
Creating default 'local' authorizer
[23:32:52]W: [Step 10/10] I0915 23:32:52.350111 29518 leveldb.cpp:174]
Opened db in 2.618094ms
[23:32:52]W: [Step 10/10] I0915 23:32:52.350518 29518 leveldb.cpp:181]
Compacted db in 390273ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.350536 29518 leveldb.cpp:196]
Created db iterator in 3479ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.350543 29518 leveldb.cpp:202]
Seeked to beginning of db in 464ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.350548 29518 leveldb.cpp:271]
Iterated through 0 keys in the db in 364ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.350558 29518 replica.cpp:776]
Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
[23:32:52]W: [Step 10/10] I0915 23:32:52.350740 29532 recover.cpp:451]
Starting replica recovery
[23:32:52]W: [Step 10/10] I0915 23:32:52.350931 29533 recover.cpp:477]
Replica is in EMPTY status
[23:32:52]W: [Step 10/10] I0915 23:32:52.351176 29536 replica.cpp:673]
Replica in EMPTY status received a broadcasted recover request from
__req_res__(4863)@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.351282 29534 recover.cpp:197]
Received a recover response from a replica in EMPTY status
[23:32:52]W: [Step 10/10] I0915 23:32:52.351387 29537 recover.cpp:568]
Updating replica status to STARTING
[23:32:52]W: [Step 10/10] I0915 23:32:52.351835 29535 master.cpp:380]
Master b8554850-0e42-40dd-aaaa-58d6c6f19074
(ip-172-30-2-144.ec2.internal.mesosphere.io) started on 172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.351847 29535 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/8wMNif/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/8wMNif/master" --zk_session_timeout="10secs"
[23:32:52]W: [Step 10/10] I0915 23:32:52.351948 29535 master.cpp:432]
Master only allowing authenticated frameworks to register
[23:32:52]W: [Step 10/10] I0915 23:32:52.351954 29535 master.cpp:446]
Master only allowing authenticated agents to register
[23:32:52]W: [Step 10/10] I0915 23:32:52.351958 29535 master.cpp:459]
Master only allowing authenticated HTTP frameworks to register
[23:32:52]W: [Step 10/10] I0915 23:32:52.351963 29535 credentials.hpp:37]
Loading credentials for authentication from '/tmp/8wMNif/credentials'
[23:32:52]W: [Step 10/10] I0915 23:32:52.352077 29535 master.cpp:504] Using
default 'crammd5' authenticator
[23:32:52]W: [Step 10/10] I0915 23:32:52.352133 29535 http.cpp:883] Using
default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
[23:32:52]W: [Step 10/10] I0915 23:32:52.352217 29535 http.cpp:883] Using
default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
[23:32:52]W: [Step 10/10] I0915 23:32:52.352254 29535 http.cpp:883] Using
default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
[23:32:52]W: [Step 10/10] I0915 23:32:52.352289 29535 master.cpp:584]
Authorization enabled
[23:32:52]W: [Step 10/10] I0915 23:32:52.352322 29537 leveldb.cpp:304]
Persisting metadata (8 bytes) to leveldb took 841411ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.352339 29537 replica.cpp:320]
Persisted replica status to STARTING
[23:32:52]W: [Step 10/10] I0915 23:32:52.352345 29533
whitelist_watcher.cpp:77] No whitelist given
[23:32:52]W: [Step 10/10] I0915 23:32:52.352377 29539 hierarchical.cpp:149]
Initialized hierarchical allocator process
[23:32:52]W: [Step 10/10] I0915 23:32:52.352435 29536 recover.cpp:477]
Replica is in STARTING status
[23:32:52]W: [Step 10/10] I0915 23:32:52.352718 29534 replica.cpp:673]
Replica in STARTING status received a broadcasted recover request from
__req_res__(4864)@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.352818 29539 recover.cpp:197]
Received a recover response from a replica in STARTING status
[23:32:52]W: [Step 10/10] I0915 23:32:52.352946 29535 master.cpp:1855]
Elected as the leading master!
[23:32:52]W: [Step 10/10] I0915 23:32:52.352962 29535 master.cpp:1556]
Recovering from registrar
[23:32:52]W: [Step 10/10] I0915 23:32:52.352964 29539 recover.cpp:568]
Updating replica status to VOTING
[23:32:52]W: [Step 10/10] I0915 23:32:52.353029 29534 registrar.cpp:332]
Recovering registrar
[23:32:52]W: [Step 10/10] I0915 23:32:52.353334 29533 leveldb.cpp:304]
Persisting metadata (8 bytes) to leveldb took 276712ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.353348 29533 replica.cpp:320]
Persisted replica status to VOTING
[23:32:52]W: [Step 10/10] I0915 23:32:52.353422 29533 recover.cpp:582]
Successfully joined the Paxos group
[23:32:52]W: [Step 10/10] I0915 23:32:52.353466 29533 recover.cpp:466]
Recover process terminated
[23:32:52]W: [Step 10/10] I0915 23:32:52.353574 29538 log.cpp:553]
Attempting to start the writer
[23:32:52]W: [Step 10/10] I0915 23:32:52.353921 29538 replica.cpp:493]
Replica received implicit promise request from
__req_res__(4865)@172.30.2.144:39560 with proposal 1
[23:32:52]W: [Step 10/10] I0915 23:32:52.354185 29538 leveldb.cpp:304]
Persisting metadata (8 bytes) to leveldb took 241695ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.354197 29538 replica.cpp:342]
Persisted promised to 1
[23:32:52]W: [Step 10/10] I0915 23:32:52.354403 29535 coordinator.cpp:238]
Coordinator attempting to fill missing positions
[23:32:52]W: [Step 10/10] I0915 23:32:52.354935 29532 replica.cpp:388]
Replica received explicit promise request from
__req_res__(4866)@172.30.2.144:39560 for position 0 with proposal 2
[23:32:52]W: [Step 10/10] I0915 23:32:52.355221 29532 leveldb.cpp:341]
Persisting action (8 bytes) to leveldb took 261112ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.355233 29532 replica.cpp:708]
Persisted action NOP at position 0
[23:32:52]W: [Step 10/10] I0915 23:32:52.355562 29533 replica.cpp:537]
Replica received write request for position 0 from
__req_res__(4867)@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.355592 29533 leveldb.cpp:436]
Reading position from leveldb took 9995ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.355866 29533 leveldb.cpp:341]
Persisting action (14 bytes) to leveldb took 258772ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.355880 29533 replica.cpp:708]
Persisted action NOP at position 0
[23:32:52]W: [Step 10/10] I0915 23:32:52.356092 29534 replica.cpp:691]
Replica received learned notice for position 0 from @0.0.0.0:0
[23:32:52]W: [Step 10/10] I0915 23:32:52.356403 29534 leveldb.cpp:341]
Persisting action (16 bytes) to leveldb took 292696ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.356416 29534 replica.cpp:708]
Persisted action NOP at position 0
[23:32:52]W: [Step 10/10] I0915 23:32:52.356580 29537 log.cpp:569] Writer
started with ending position 0
[23:32:52]W: [Step 10/10] I0915 23:32:52.356859 29533 leveldb.cpp:436]
Reading position from leveldb took 9902ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.357069 29533 registrar.cpp:365]
Successfully fetched the registry (0B) in 4.018944ms
[23:32:52]W: [Step 10/10] I0915 23:32:52.357100 29533 registrar.cpp:464]
Applied 1 operations in 3619ns; attempting to update the registry
[23:32:52]W: [Step 10/10] I0915 23:32:52.357313 29535 log.cpp:577]
Attempting to append 235 bytes to the log
[23:32:52]W: [Step 10/10] I0915 23:32:52.357365 29532 coordinator.cpp:348]
Coordinator attempting to write APPEND action at position 1
[23:32:52]W: [Step 10/10] I0915 23:32:52.357627 29535 replica.cpp:537]
Replica received write request for position 1 from
__req_res__(4868)@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.357926 29535 leveldb.cpp:341]
Persisting action (254 bytes) to leveldb took 278163ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.357939 29535 replica.cpp:708]
Persisted action APPEND at position 1
[23:32:52]W: [Step 10/10] I0915 23:32:52.358194 29537 replica.cpp:691]
Replica received learned notice for position 1 from @0.0.0.0:0
[23:32:52]W: [Step 10/10] I0915 23:32:52.358490 29537 leveldb.cpp:341]
Persisting action (256 bytes) to leveldb took 278561ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.358505 29537 replica.cpp:708]
Persisted action APPEND at position 1
[23:32:52]W: [Step 10/10] I0915 23:32:52.358711 29533 registrar.cpp:509]
Successfully updated the registry in 1.59104ms
[23:32:52]W: [Step 10/10] I0915 23:32:52.358765 29533 registrar.cpp:395]
Successfully recovered registrar
[23:32:52]W: [Step 10/10] I0915 23:32:52.358783 29534 log.cpp:596]
Attempting to truncate the log to 1
[23:32:52]W: [Step 10/10] I0915 23:32:52.358836 29536 coordinator.cpp:348]
Coordinator attempting to write TRUNCATE action at position 2
[23:32:52]W: [Step 10/10] I0915 23:32:52.359000 29533 master.cpp:1664]
Recovered 0 agents from the registry (196B); allowing 10mins for agents to
re-register
[23:32:52]W: [Step 10/10] I0915 23:32:52.359045 29535 hierarchical.cpp:176]
Skipping recovery of hierarchical allocator: nothing to recover
[23:32:52]W: [Step 10/10] I0915 23:32:52.359244 29536 replica.cpp:537]
Replica received write request for position 2 from
__req_res__(4869)@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.359552 29536 leveldb.cpp:341]
Persisting action (16 bytes) to leveldb took 288248ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.359565 29536 replica.cpp:708]
Persisted action TRUNCATE at position 2
[23:32:52]W: [Step 10/10] I0915 23:32:52.359802 29539 replica.cpp:691]
Replica received learned notice for position 2 from @0.0.0.0:0
[23:32:52]W: [Step 10/10] I0915 23:32:52.360102 29539 leveldb.cpp:341]
Persisting action (18 bytes) to leveldb took 280047ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.360122 29539 leveldb.cpp:399]
Deleting ~1 keys from leveldb took 8059ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.360131 29539 replica.cpp:708]
Persisted action TRUNCATE at position 2
[23:32:52]W: [Step 10/10] I0915 23:32:52.360944 29518
containerizer.cpp:217] Using isolation:
cgroups/cpu,cgroups/mem,filesystem/posix,network/cni
[23:32:52]W: [Step 10/10] I0915 23:32:52.366111 29518
linux_launcher.cpp:104] Using /sys/fs/cgroup/freezer as the freezer hierarchy
for the Linux launcher
[23:32:52]W: [Step 10/10] I0915 23:32:52.382885 29518 cluster.cpp:436]
Creating default 'local' authorizer
[23:32:52]W: [Step 10/10] I0915 23:32:52.383322 29533 slave.cpp:208] Mesos
agent started on (400)@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.383337 29533 slave.cpp:209] Flags
at startup: --acls="" --agent_subsystems=""
--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_test_62e4d3a2-29cc-4d57-9c07-e392f07e058c"
--container_disk_watch_interval="15secs" --containerizers="mesos"
--credential="/mnt/teamcity/temp/buildTmp/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_X0TUZu/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/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_X0TUZu/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/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_X0TUZu/http_credentials"
--image_provisioner_backend="copy" --initialize_driver_logging="true"
--isolation="cgroups/cpu,cgroups/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/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_X0TUZu"
--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/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_Tg5l9R"
--xfs_project_range="[5000-10000]"
[23:32:52]W: [Step 10/10] I0915 23:32:52.383549 29533 credentials.hpp:86]
Loading credential for authentication from
'/mnt/teamcity/temp/buildTmp/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_X0TUZu/credential'
[23:32:52]W: [Step 10/10] I0915 23:32:52.383618 29533 slave.cpp:346] Agent
using credential for: test-principal
[23:32:52]W: [Step 10/10] I0915 23:32:52.383635 29533 credentials.hpp:37]
Loading credentials for authentication from
'/mnt/teamcity/temp/buildTmp/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_X0TUZu/http_credentials'
[23:32:52]W: [Step 10/10] I0915 23:32:52.383690 29533 http.cpp:883] Using
default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
[23:32:52]W: [Step 10/10] I0915 23:32:52.383729 29533 http.cpp:883] Using
default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
[23:32:52]W: [Step 10/10] I0915 23:32:52.383908 29518 sched.cpp:226]
Version: 1.1.0
[23:32:52]W: [Step 10/10] I0915 23:32:52.384027 29534 sched.cpp:330] New
master detected at master@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.384063 29534 sched.cpp:396]
Authenticating with master master@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.384070 29534 sched.cpp:403] Using
default CRAM-MD5 authenticatee
[23:32:52]W: [Step 10/10] I0915 23:32:52.384068 29533 slave.cpp:529] Agent
resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
[23:32:52]W: [Step 10/10] I0915 23:32:52.384094 29533 slave.cpp:537] Agent
attributes: [ ]
[23:32:52]W: [Step 10/10] I0915 23:32:52.384099 29533 slave.cpp:542] Agent
hostname: ip-172-30-2-144.ec2.internal.mesosphere.io
[23:32:52]W: [Step 10/10] I0915 23:32:52.384179 29536
authenticatee.cpp:121] Creating new client SASL connection
[23:32:52]W: [Step 10/10] I0915 23:32:52.384280 29536 master.cpp:6234]
Authenticating scheduler-0a63c05f-da63-4c18-a2dc-f729f0fc4384@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.384356 29536
authenticator.cpp:414] Starting authentication session for
crammd5-authenticatee(838)@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.384421 29535 authenticator.cpp:98]
Creating new server SASL connection
[23:32:52]W: [Step 10/10] I0915 23:32:52.384443 29533 state.cpp:57]
Recovering state from
'/mnt/teamcity/temp/buildTmp/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_Tg5l9R/meta'
[23:32:52]W: [Step 10/10] I0915 23:32:52.384490 29535
authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
[23:32:52]W: [Step 10/10] I0915 23:32:52.384508 29535
authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
[23:32:52]W: [Step 10/10] I0915 23:32:52.384570 29536
authenticator.cpp:204] Received SASL authentication start
[23:32:52]W: [Step 10/10] I0915 23:32:52.384577 29537
status_update_manager.cpp:203] Recovering status update manager
[23:32:52]W: [Step 10/10] I0915 23:32:52.384604 29536
authenticator.cpp:326] Authentication requires more steps
[23:32:52]W: [Step 10/10] I0915 23:32:52.384654 29536
containerizer.cpp:578] Recovering containerizer
[23:32:52]W: [Step 10/10] I0915 23:32:52.384680 29538
authenticatee.cpp:259] Received SASL authentication step
[23:32:52]W: [Step 10/10] I0915 23:32:52.384742 29538
authenticator.cpp:232] Received SASL authentication step
[23:32:52]W: [Step 10/10] I0915 23:32:52.384763 29538 auxprop.cpp:109]
Request to lookup properties for user: 'test-principal' realm:
'ip-172-30-2-144.ec2.internal' server FQDN: 'ip-172-30-2-144.ec2.internal'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
[23:32:52]W: [Step 10/10] I0915 23:32:52.384773 29538 auxprop.cpp:181]
Looking up auxiliary property '*userPassword'
[23:32:52]W: [Step 10/10] I0915 23:32:52.384786 29538 auxprop.cpp:181]
Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[23:32:52]W: [Step 10/10] I0915 23:32:52.384799 29538 auxprop.cpp:109]
Request to lookup properties for user: 'test-principal' realm:
'ip-172-30-2-144.ec2.internal' server FQDN: 'ip-172-30-2-144.ec2.internal'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
[23:32:52]W: [Step 10/10] I0915 23:32:52.384807 29538 auxprop.cpp:131]
Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[23:32:52]W: [Step 10/10] I0915 23:32:52.384814 29538 auxprop.cpp:131]
Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID
== true
[23:32:52]W: [Step 10/10] I0915 23:32:52.384829 29538
authenticator.cpp:318] Authentication success
[23:32:52]W: [Step 10/10] I0915 23:32:52.384896 29538
authenticatee.cpp:299] Authentication success
[23:32:52]W: [Step 10/10] I0915 23:32:52.384899 29532
authenticator.cpp:432] Authentication session cleanup for
crammd5-authenticatee(838)@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.384920 29534 master.cpp:6264]
Successfully authenticated principal 'test-principal' at
scheduler-0a63c05f-da63-4c18-a2dc-f729f0fc4384@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.385002 29537 sched.cpp:502]
Successfully authenticated with master master@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.385016 29537 sched.cpp:820]
Sending SUBSCRIBE call to master@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.385052 29537 sched.cpp:853] Will
retry registration in 645.053737ms if necessary
[23:32:52]W: [Step 10/10] I0915 23:32:52.385095 29535 master.cpp:2429]
Received SUBSCRIBE call for framework 'default' at
scheduler-0a63c05f-da63-4c18-a2dc-f729f0fc4384@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.385113 29535 master.cpp:1891]
Authorizing framework principal 'test-principal' to receive offers for role '*'
[23:32:52]W: [Step 10/10] I0915 23:32:52.385227 29535 master.cpp:2505]
Subscribing framework default with checkpointing enabled and capabilities [ ]
[23:32:52]W: [Step 10/10] I0915 23:32:52.385393 29535 sched.cpp:743]
Framework registered with b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:52]W: [Step 10/10] I0915 23:32:52.385416 29535 sched.cpp:757]
Scheduler::registered took 10845ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.385447 29532 hierarchical.cpp:269]
Added framework b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:52]W: [Step 10/10] I0915 23:32:52.385473 29532
hierarchical.cpp:1675] No allocations performed
[23:32:52]W: [Step 10/10] I0915 23:32:52.385480 29532
hierarchical.cpp:1770] No inverse offers to send out!
[23:32:52]W: [Step 10/10] I0915 23:32:52.385488 29532
hierarchical.cpp:1271] Performed allocation for 0 agents in 24242ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.386932 29537 provisioner.cpp:253]
Provisioner recovery complete
[23:32:52]W: [Step 10/10] I0915 23:32:52.387071 29537 slave.cpp:5203]
Finished recovery
[23:32:52]W: [Step 10/10] I0915 23:32:52.387235 29537 slave.cpp:5375]
Querying resource estimator for oversubscribable resources
[23:32:52]W: [Step 10/10] I0915 23:32:52.387336 29532 slave.cpp:911] New
master detected at master@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.387341 29537
status_update_manager.cpp:177] Pausing sending status updates
[23:32:52]W: [Step 10/10] I0915 23:32:52.387361 29532 slave.cpp:970]
Authenticating with master master@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.387380 29532 slave.cpp:981] Using
default CRAM-MD5 authenticatee
[23:32:52]W: [Step 10/10] I0915 23:32:52.387415 29532 slave.cpp:943]
Detecting new master
[23:32:52]W: [Step 10/10] I0915 23:32:52.387444 29536
authenticatee.cpp:121] Creating new client SASL connection
[23:32:52]W: [Step 10/10] I0915 23:32:52.387464 29532 slave.cpp:5389]
Received oversubscribable resources from the resource estimator
[23:32:52]W: [Step 10/10] I0915 23:32:52.387512 29532 master.cpp:6234]
Authenticating slave(400)@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.387550 29532
authenticator.cpp:414] Starting authentication session for
crammd5-authenticatee(839)@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.387594 29534 authenticator.cpp:98]
Creating new server SASL connection
[23:32:52]W: [Step 10/10] I0915 23:32:52.387653 29534
authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
[23:32:52]W: [Step 10/10] I0915 23:32:52.387666 29534
authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
[23:32:52]W: [Step 10/10] I0915 23:32:52.387697 29537
authenticator.cpp:204] Received SASL authentication start
[23:32:52]W: [Step 10/10] I0915 23:32:52.387732 29537
authenticator.cpp:326] Authentication requires more steps
[23:32:52]W: [Step 10/10] I0915 23:32:52.387766 29537
authenticatee.cpp:259] Received SASL authentication step
[23:32:52]W: [Step 10/10] I0915 23:32:52.387804 29537
authenticator.cpp:232] Received SASL authentication step
[23:32:52]W: [Step 10/10] I0915 23:32:52.387822 29537 auxprop.cpp:109]
Request to lookup properties for user: 'test-principal' realm:
'ip-172-30-2-144.ec2.internal' server FQDN: 'ip-172-30-2-144.ec2.internal'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
[23:32:52]W: [Step 10/10] I0915 23:32:52.387833 29537 auxprop.cpp:181]
Looking up auxiliary property '*userPassword'
[23:32:52]W: [Step 10/10] I0915 23:32:52.387843 29537 auxprop.cpp:181]
Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[23:32:52]W: [Step 10/10] I0915 23:32:52.387850 29537 auxprop.cpp:109]
Request to lookup properties for user: 'test-principal' realm:
'ip-172-30-2-144.ec2.internal' server FQDN: 'ip-172-30-2-144.ec2.internal'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
[23:32:52]W: [Step 10/10] I0915 23:32:52.387856 29537 auxprop.cpp:131]
Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[23:32:52]W: [Step 10/10] I0915 23:32:52.387859 29537 auxprop.cpp:131]
Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID
== true
[23:32:52]W: [Step 10/10] I0915 23:32:52.387867 29537
authenticator.cpp:318] Authentication success
[23:32:52]W: [Step 10/10] I0915 23:32:52.387907 29537
authenticatee.cpp:299] Authentication success
[23:32:52]W: [Step 10/10] I0915 23:32:52.387931 29536
authenticator.cpp:432] Authentication session cleanup for
crammd5-authenticatee(839)@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.387956 29534 master.cpp:6264]
Successfully authenticated principal 'test-principal' at
slave(400)@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.388059 29532 slave.cpp:1065]
Successfully authenticated with master master@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.388109 29532 slave.cpp:1471] Will
retry registration in 13.771224ms if necessary
[23:32:52]W: [Step 10/10] I0915 23:32:52.388164 29538 master.cpp:4886]
Registering agent at slave(400)@172.30.2.144:39560
(ip-172-30-2-144.ec2.internal.mesosphere.io) with id
b8554850-0e42-40dd-aaaa-58d6c6f19074-S0
[23:32:52]W: [Step 10/10] I0915 23:32:52.388265 29532 registrar.cpp:464]
Applied 1 operations in 10697ns; attempting to update the registry
[23:32:52]W: [Step 10/10] I0915 23:32:52.388470 29533 log.cpp:577]
Attempting to append 434 bytes to the log
[23:32:52]W: [Step 10/10] I0915 23:32:52.388531 29534 coordinator.cpp:348]
Coordinator attempting to write APPEND action at position 3
[23:32:52]W: [Step 10/10] I0915 23:32:52.388811 29532 replica.cpp:537]
Replica received write request for position 3 from
__req_res__(4870)@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.389127 29532 leveldb.cpp:341]
Persisting action (453 bytes) to leveldb took 293164ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.389140 29532 replica.cpp:708]
Persisted action APPEND at position 3
[23:32:52]W: [Step 10/10] I0915 23:32:52.389386 29539 replica.cpp:691]
Replica received learned notice for position 3 from @0.0.0.0:0
[23:32:52]W: [Step 10/10] I0915 23:32:52.389681 29539 leveldb.cpp:341]
Persisting action (455 bytes) to leveldb took 277323ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.389695 29539 replica.cpp:708]
Persisted action APPEND at position 3
[23:32:52]W: [Step 10/10] I0915 23:32:52.389950 29535 registrar.cpp:509]
Successfully updated the registry in 1.648896ms
[23:32:52]W: [Step 10/10] I0915 23:32:52.390000 29537 log.cpp:596]
Attempting to truncate the log to 3
[23:32:52]W: [Step 10/10] I0915 23:32:52.390041 29534 coordinator.cpp:348]
Coordinator attempting to write TRUNCATE action at position 4
[23:32:52]W: [Step 10/10] I0915 23:32:52.390132 29538 master.cpp:4956]
Registered agent b8554850-0e42-40dd-aaaa-58d6c6f19074-S0 at
slave(400)@172.30.2.144:39560 (ip-172-30-2-144.ec2.internal.mesosphere.io) with
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
[23:32:52]W: [Step 10/10] I0915 23:32:52.390167 29537 slave.cpp:4070]
Received ping from slave-observer(380)@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.390197 29532 hierarchical.cpp:476]
Added agent b8554850-0e42-40dd-aaaa-58d6c6f19074-S0
(ip-172-30-2-144.ec2.internal.mesosphere.io) with cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000] (allocated: )
[23:32:52]W: [Step 10/10] I0915 23:32:52.390221 29537 slave.cpp:1111]
Registered with master master@172.30.2.144:39560; given agent ID
b8554850-0e42-40dd-aaaa-58d6c6f19074-S0
[23:32:52]W: [Step 10/10] I0915 23:32:52.390236 29537 fetcher.cpp:86]
Clearing fetcher cache
[23:32:52]W: [Step 10/10] I0915 23:32:52.390317 29539
status_update_manager.cpp:184] Resuming sending status updates
[23:32:52]W: [Step 10/10] I0915 23:32:52.390329 29535 replica.cpp:537]
Replica received write request for position 4 from
__req_res__(4871)@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.390367 29532
hierarchical.cpp:1770] No inverse offers to send out!
[23:32:52]W: [Step 10/10] I0915 23:32:52.390394 29532
hierarchical.cpp:1294] Performed allocation for agent
b8554850-0e42-40dd-aaaa-58d6c6f19074-S0 in 167797ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.390458 29537 slave.cpp:1134]
Checkpointing SlaveInfo to
'/mnt/teamcity/temp/buildTmp/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_Tg5l9R/meta/slaves/b8554850-0e42-40dd-aaaa-58d6c6f19074-S0/slave.info'
[23:32:52]W: [Step 10/10] I0915 23:32:52.390461 29538 master.cpp:6063]
Sending 1 offers to framework b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
(default) at scheduler-0a63c05f-da63-4c18-a2dc-f729f0fc4384@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.390584 29538 sched.cpp:917]
Scheduler::resourceOffers took 34535ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.390594 29537 slave.cpp:1171]
Forwarding total oversubscribed resources
[23:32:52]W: [Step 10/10] I0915 23:32:52.390642 29535 leveldb.cpp:341]
Persisting action (16 bytes) to leveldb took 294839ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.390642 29532 master.cpp:5340]
Received update of agent b8554850-0e42-40dd-aaaa-58d6c6f19074-S0 at
slave(400)@172.30.2.144:39560 (ip-172-30-2-144.ec2.internal.mesosphere.io) with
total oversubscribed resources
[23:32:52]W: [Step 10/10] I0915 23:32:52.390669 29535 replica.cpp:708]
Persisted action TRUNCATE at position 4
[23:32:52]W: [Step 10/10] I0915 23:32:52.390733 29532 hierarchical.cpp:540]
Agent b8554850-0e42-40dd-aaaa-58d6c6f19074-S0
(ip-172-30-2-144.ec2.internal.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])
[23:32:52]W: [Step 10/10] I0915 23:32:52.390777 29532
hierarchical.cpp:1675] No allocations performed
[23:32:52]W: [Step 10/10] I0915 23:32:52.390790 29532
hierarchical.cpp:1770] No inverse offers to send out!
[23:32:52]W: [Step 10/10] I0915 23:32:52.390805 29532
hierarchical.cpp:1294] Performed allocation for agent
b8554850-0e42-40dd-aaaa-58d6c6f19074-S0 in 43485ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.391124 29536 replica.cpp:691]
Replica received learned notice for position 4 from @0.0.0.0:0
[23:32:52]W: [Step 10/10] I0915 23:32:52.391124 29535 master.cpp:3363]
Processing ACCEPT call for offers: [ b8554850-0e42-40dd-aaaa-58d6c6f19074-O0 ]
on agent b8554850-0e42-40dd-aaaa-58d6c6f19074-S0 at
slave(400)@172.30.2.144:39560 (ip-172-30-2-144.ec2.internal.mesosphere.io) for
framework b8554850-0e42-40dd-aaaa-58d6c6f19074-0000 (default) at
scheduler-0a63c05f-da63-4c18-a2dc-f729f0fc4384@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.391175 29535 master.cpp:2985]
Authorizing framework principal 'test-principal' to launch task
725c46ae-bc78-41a4-bfd4-2f6903b03518
[23:32:52]W: [Step 10/10] I0915 23:32:52.391526 29536 leveldb.cpp:341]
Persisting action (18 bytes) to leveldb took 374940ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.391553 29536 leveldb.cpp:399]
Deleting ~2 keys from leveldb took 12933ns
[23:32:52]W: [Step 10/10] I0915 23:32:52.391577 29536 replica.cpp:708]
Persisted action TRUNCATE at position 4
[23:32:52]W: [Step 10/10] I0915 23:32:52.391553 29535 master.cpp:7809]
Adding task 725c46ae-bc78-41a4-bfd4-2f6903b03518 with resources cpus(*):0.5;
mem(*):128 on agent b8554850-0e42-40dd-aaaa-58d6c6f19074-S0
(ip-172-30-2-144.ec2.internal.mesosphere.io)
[23:32:52]W: [Step 10/10] I0915 23:32:52.391603 29535 master.cpp:3963]
Launching task 725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000 (default) at
scheduler-0a63c05f-da63-4c18-a2dc-f729f0fc4384@172.30.2.144:39560 with
resources cpus(*):0.5; mem(*):128 on agent
b8554850-0e42-40dd-aaaa-58d6c6f19074-S0 at slave(400)@172.30.2.144:39560
(ip-172-30-2-144.ec2.internal.mesosphere.io)
[23:32:52]W: [Step 10/10] I0915 23:32:52.391829 29538 slave.cpp:1535] Got
assigned task '725c46ae-bc78-41a4-bfd4-2f6903b03518' for framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:52]W: [Step 10/10] I0915 23:32:52.391880 29533
hierarchical.cpp:1003] Recovered cpus(*):1.5; mem(*):896; disk(*):1024;
ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000], allocated: cpus(*):0.5; mem(*):128) on agent
b8554850-0e42-40dd-aaaa-58d6c6f19074-S0 from framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:52]W: [Step 10/10] I0915 23:32:52.391896 29538 slave.cpp:6015]
Checkpointing FrameworkInfo to
'/mnt/teamcity/temp/buildTmp/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_Tg5l9R/meta/slaves/b8554850-0e42-40dd-aaaa-58d6c6f19074-S0/frameworks/b8554850-0e42-40dd-aaaa-58d6c6f19074-0000/framework.info'
[23:32:52]W: [Step 10/10] I0915 23:32:52.391906 29533
hierarchical.cpp:1040] Framework b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
filtered agent b8554850-0e42-40dd-aaaa-58d6c6f19074-S0 for 5secs
[23:32:52]W: [Step 10/10] I0915 23:32:52.392058 29538 slave.cpp:6026]
Checkpointing framework pid
'scheduler-0a63c05f-da63-4c18-a2dc-f729f0fc4384@172.30.2.144:39560' to
'/mnt/teamcity/temp/buildTmp/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_Tg5l9R/meta/slaves/b8554850-0e42-40dd-aaaa-58d6c6f19074-S0/frameworks/b8554850-0e42-40dd-aaaa-58d6c6f19074-0000/framework.pid'
[23:32:52]W: [Step 10/10] I0915 23:32:52.392256 29538 slave.cpp:1692]
Launching task '725c46ae-bc78-41a4-bfd4-2f6903b03518' for framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:52]W: [Step 10/10] I0915 23:32:52.392530 29538 paths.cpp:536] Trying
to chown
'/mnt/teamcity/temp/buildTmp/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_Tg5l9R/slaves/b8554850-0e42-40dd-aaaa-58d6c6f19074-S0/frameworks/b8554850-0e42-40dd-aaaa-58d6c6f19074-0000/executors/725c46ae-bc78-41a4-bfd4-2f6903b03518/runs/23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4'
to user 'root'
[23:32:52]W: [Step 10/10] I0915 23:32:52.397115 29538 slave.cpp:6480]
Checkpointing ExecutorInfo to
'/mnt/teamcity/temp/buildTmp/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_Tg5l9R/meta/slaves/b8554850-0e42-40dd-aaaa-58d6c6f19074-S0/frameworks/b8554850-0e42-40dd-aaaa-58d6c6f19074-0000/executors/725c46ae-bc78-41a4-bfd4-2f6903b03518/executor.info'
[23:32:52]W: [Step 10/10] I0915 23:32:52.397444 29538 slave.cpp:6095]
Launching executor '725c46ae-bc78-41a4-bfd4-2f6903b03518' of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000 with resources cpus(*):0.1; mem(*):32
in work directory
'/mnt/teamcity/temp/buildTmp/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_Tg5l9R/slaves/b8554850-0e42-40dd-aaaa-58d6c6f19074-S0/frameworks/b8554850-0e42-40dd-aaaa-58d6c6f19074-0000/executors/725c46ae-bc78-41a4-bfd4-2f6903b03518/runs/23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4'
[23:32:52]W: [Step 10/10] I0915 23:32:52.397658 29533
containerizer.cpp:846] Starting container 23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
for executor '725c46ae-bc78-41a4-bfd4-2f6903b03518' of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:52]W: [Step 10/10] I0915 23:32:52.397686 29538 slave.cpp:6503]
Checkpointing TaskInfo to
'/mnt/teamcity/temp/buildTmp/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_Tg5l9R/meta/slaves/b8554850-0e42-40dd-aaaa-58d6c6f19074-S0/frameworks/b8554850-0e42-40dd-aaaa-58d6c6f19074-0000/executors/725c46ae-bc78-41a4-bfd4-2f6903b03518/runs/23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4/tasks/725c46ae-bc78-41a4-bfd4-2f6903b03518/task.info'
[23:32:52]W: [Step 10/10] I0915 23:32:52.397876 29538 slave.cpp:1978]
Queued task '725c46ae-bc78-41a4-bfd4-2f6903b03518' for executor
'725c46ae-bc78-41a4-bfd4-2f6903b03518' of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:52]W: [Step 10/10] I0915 23:32:52.397914 29538 slave.cpp:864]
Successfully attached file
'/mnt/teamcity/temp/buildTmp/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_Tg5l9R/slaves/b8554850-0e42-40dd-aaaa-58d6c6f19074-S0/frameworks/b8554850-0e42-40dd-aaaa-58d6c6f19074-0000/executors/725c46ae-bc78-41a4-bfd4-2f6903b03518/runs/23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4'
[23:32:52]W: [Step 10/10] I0915 23:32:52.398061 29539 cgroups.cpp:375]
Creating cgroup at
'/sys/fs/cgroup/cpu,cpuacct/mesos_test_62e4d3a2-29cc-4d57-9c07-e392f07e058c/23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4'
for container 23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
[23:32:52]W: [Step 10/10] I0915 23:32:52.399155 29539 cgroups.cpp:431]
Chown the cgroup at
'/sys/fs/cgroup/cpu,cpuacct/mesos_test_62e4d3a2-29cc-4d57-9c07-e392f07e058c/23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4'
to user 'root' for container 23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
[23:32:52]W: [Step 10/10] I0915 23:32:52.399199 29539 cgroups.cpp:375]
Creating cgroup at
'/sys/fs/cgroup/memory/mesos_test_62e4d3a2-29cc-4d57-9c07-e392f07e058c/23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4'
for container 23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
[23:32:52]W: [Step 10/10] I0915 23:32:52.400183 29539 cgroups.cpp:431]
Chown the cgroup at
'/sys/fs/cgroup/memory/mesos_test_62e4d3a2-29cc-4d57-9c07-e392f07e058c/23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4'
to user 'root' for container 23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
[23:32:52]W: [Step 10/10] I0915 23:32:52.400655 29539 memory.cpp:447]
Started listening for OOM events for container
23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
[23:32:52]W: [Step 10/10] I0915 23:32:52.401139 29539 memory.cpp:564]
Started listening on 'low' memory pressure events for container
23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
[23:32:52]W: [Step 10/10] I0915 23:32:52.401623 29539 memory.cpp:564]
Started listening on 'medium' memory pressure events for container
23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
[23:32:52]W: [Step 10/10] I0915 23:32:52.402096 29539 memory.cpp:564]
Started listening on 'critical' memory pressure events for container
23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
[23:32:52]W: [Step 10/10] I0915 23:32:52.402837 29537 memory.cpp:193]
Updated 'memory.soft_limit_in_bytes' to 160MB for container
23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
[23:32:52]W: [Step 10/10] I0915 23:32:52.403664 29537 memory.cpp:246]
Updated 'memory.limit_in_bytes' to 160MB for container
23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
[23:32:52]W: [Step 10/10] I0915 23:32:52.404079 29537 cpu.cpp:103] Updated
'cpu.shares' to 614 (cpus 0.6) for container
23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
[23:32:52]W: [Step 10/10] I0915 23:32:52.404551 29537
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="27" --pipe_write="32" --pre_exec_commands="[]"
--unshare_namespace_mnt="false" --user="root"
--working_directory="/mnt/teamcity/temp/buildTmp/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_Tg5l9R/slaves/b8554850-0e42-40dd-aaaa-58d6c6f19074-S0/frameworks/b8554850-0e42-40dd-aaaa-58d6c6f19074-0000/executors/725c46ae-bc78-41a4-bfd4-2f6903b03518/runs/23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4"'
[23:32:52]W: [Step 10/10] I0915 23:32:52.404605 29537
linux_launcher.cpp:284] Cloning child process with flags =
[23:32:52]W: [Step 10/10] I0915 23:32:52.415534 29537
containerizer.cpp:1292] Checkpointing executor's forked pid 11060 to
'/mnt/teamcity/temp/buildTmp/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_Tg5l9R/meta/slaves/b8554850-0e42-40dd-aaaa-58d6c6f19074-S0/frameworks/b8554850-0e42-40dd-aaaa-58d6c6f19074-0000/executors/725c46ae-bc78-41a4-bfd4-2f6903b03518/runs/23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4/pids/forked.pid'
[23:32:52]W: [Step 10/10] I0915 23:32:52.478912 11094 exec.cpp:162]
Version: 1.1.0
[23:32:52]W: [Step 10/10] I0915 23:32:52.479475 29538 slave.cpp:3184] Got
registration for executor '725c46ae-bc78-41a4-bfd4-2f6903b03518' of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000 from executor(1)@172.30.2.144:40649
[23:32:52]W: [Step 10/10] I0915 23:32:52.479698 29538 slave.cpp:3270]
Checkpointing executor pid 'executor(1)@172.30.2.144:40649' to
'/mnt/teamcity/temp/buildTmp/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_Tg5l9R/meta/slaves/b8554850-0e42-40dd-aaaa-58d6c6f19074-S0/frameworks/b8554850-0e42-40dd-aaaa-58d6c6f19074-0000/executors/725c46ae-bc78-41a4-bfd4-2f6903b03518/runs/23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4/pids/libprocess.pid'
[23:32:52]W: [Step 10/10] I0915 23:32:52.480031 29538 slave.cpp:783] Agent
terminating
[23:32:52]W: [Step 10/10] I0915 23:32:52.480105 29533 master.cpp:1254]
Agent b8554850-0e42-40dd-aaaa-58d6c6f19074-S0 at slave(400)@172.30.2.144:39560
(ip-172-30-2-144.ec2.internal.mesosphere.io) disconnected
[23:32:52]W: [Step 10/10] I0915 23:32:52.480129 29533 master.cpp:2789]
Disconnecting agent b8554850-0e42-40dd-aaaa-58d6c6f19074-S0 at
slave(400)@172.30.2.144:39560 (ip-172-30-2-144.ec2.internal.mesosphere.io)
[23:32:52]W: [Step 10/10] I0915 23:32:52.480134 11091 exec.cpp:237]
Executor registered on agent b8554850-0e42-40dd-aaaa-58d6c6f19074-S0
[23:32:52] : [Step 10/10] Received SUBSCRIBED event
[23:32:52]W: [Step 10/10] I0915 23:32:52.480213 29533 master.cpp:2808]
Deactivating agent b8554850-0e42-40dd-aaaa-58d6c6f19074-S0 at
slave(400)@172.30.2.144:39560 (ip-172-30-2-144.ec2.internal.mesosphere.io)
[23:32:52] : [Step 10/10] Subscribed executor on
ip-172-30-2-144.ec2.internal.mesosphere.io
[23:32:52]W: [Step 10/10] I0915 23:32:52.480305 29532 hierarchical.cpp:569]
Agent b8554850-0e42-40dd-aaaa-58d6c6f19074-S0 deactivated
[23:32:52]W: [Step 10/10] I0915 23:32:52.480358 29518
containerizer.cpp:217] Using isolation:
cgroups/cpu,cgroups/mem,namespaces/pid,filesystem/posix,network/cni
[23:32:52]W: [Step 10/10] I0915 23:32:52.481001 29535 memory.cpp:193]
Updated 'memory.soft_limit_in_bytes' to 160MB for container
23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
[23:32:52]W: [Step 10/10] I0915 23:32:52.482372 29535 cpu.cpp:103] Updated
'cpu.shares' to 614 (cpus 0.6) for container
23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
[23:32:52]W: [Step 10/10] I0915 23:32:52.485743 29518
linux_launcher.cpp:104] Using /sys/fs/cgroup/freezer as the freezer hierarchy
for the Linux launcher
[23:32:52]W: [Step 10/10] I0915 23:32:52.505461 29518 cluster.cpp:436]
Creating default 'local' authorizer
[23:32:52]W: [Step 10/10] I0915 23:32:52.505899 29534 slave.cpp:208] Mesos
agent started on (401)@172.30.2.144:39560
[23:32:52]W: [Step 10/10] I0915 23:32:52.505916 29534 slave.cpp:209] Flags
at startup: --acls="" --agent_subsystems=""
--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_test_62e4d3a2-29cc-4d57-9c07-e392f07e058c"
--container_disk_watch_interval="15secs" --containerizers="mesos"
--credential="/mnt/teamcity/temp/buildTmp/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_X0TUZu/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/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_X0TUZu/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/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_X0TUZu/http_credentials"
--image_provisioner_backend="copy" --initialize_driver_logging="true"
--isolation="cgroups/cpu,cgroups/mem,namespaces/pid"
--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/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_X0TUZu"
--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/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_Tg5l9R"
--xfs_project_range="[5000-10000]"
[23:32:52]W: [Step 10/10] I0915 23:32:52.506199 29534 credentials.hpp:86]
Loading credential for authentication from
'/mnt/teamcity/temp/buildTmp/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_X0TUZu/credential'
[23:32:52]W: [Step 10/10] I0915 23:32:52.506259 29534 slave.cpp:346] Agent
using credential for: test-principal
[23:32:52]W: [Step 10/10] I0915 23:32:52.506296 29534 credentials.hpp:37]
Loading credentials for authentication from
'/mnt/teamcity/temp/buildTmp/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_X0TUZu/http_credentials'
[23:32:52]W: [Step 10/10] I0915 23:32:52.506377 29534 http.cpp:883] Using
default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
[23:32:52]W: [Step 10/10] I0915 23:32:52.506433 29534 http.cpp:883] Using
default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
[23:32:52]W: [Step 10/10] I0915 23:32:52.506727 29534 slave.cpp:529] Agent
resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
[23:32:52]W: [Step 10/10] I0915 23:32:52.506763 29534 slave.cpp:537] Agent
attributes: [ ]
[23:32:52]W: [Step 10/10] I0915 23:32:52.506769 29534 slave.cpp:542] Agent
hostname: ip-172-30-2-144.ec2.internal.mesosphere.io
[23:32:52]W: [Step 10/10] I0915 23:32:52.507050 29533 state.cpp:57]
Recovering state from
'/mnt/teamcity/temp/buildTmp/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_Tg5l9R/meta'
[23:32:52]W: [Step 10/10] I0915 23:32:52.507079 29533 state.cpp:698] No
committed checkpointed resources found at
'/mnt/teamcity/temp/buildTmp/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_Tg5l9R/meta/resources/resources.info'
[23:32:52]W: [Step 10/10] W0915 23:32:52.507553 29533 state.cpp:606] Failed
to find status updates file
'/mnt/teamcity/temp/buildTmp/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_Tg5l9R/meta/slaves/b8554850-0e42-40dd-aaaa-58d6c6f19074-S0/frameworks/b8554850-0e42-40dd-aaaa-58d6c6f19074-0000/executors/725c46ae-bc78-41a4-bfd4-2f6903b03518/runs/23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4/tasks/725c46ae-bc78-41a4-bfd4-2f6903b03518/task.updates'
[23:32:52]W: [Step 10/10] I0915 23:32:52.507949 29534 fetcher.cpp:86]
Clearing fetcher cache
[23:32:52]W: [Step 10/10] I0915 23:32:52.507985 29534 slave.cpp:5291]
Recovering framework b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:52]W: [Step 10/10] I0915 23:32:52.508004 29534 slave.cpp:6245]
Recovering executor '725c46ae-bc78-41a4-bfd4-2f6903b03518' of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:52]W: [Step 10/10] I0915 23:32:52.508182 29535
status_update_manager.cpp:203] Recovering status update manager
[23:32:52]W: [Step 10/10] I0915 23:32:52.508194 29535
status_update_manager.cpp:211] Recovering executor
'725c46ae-bc78-41a4-bfd4-2f6903b03518' of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:52]W: [Step 10/10] W0915 23:32:52.508213 29535
status_update_manager.cpp:250] No updates found for task
725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:52]W: [Step 10/10] I0915 23:32:52.508411 29532
containerizer.cpp:578] Recovering containerizer
[23:32:52]W: [Step 10/10] I0915 23:32:52.508435 29532
containerizer.cpp:634] Recovering container
23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4 for executor
'725c46ae-bc78-41a4-bfd4-2f6903b03518' of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:52]W: [Step 10/10] I0915 23:32:52.510902 29537 memory.cpp:447]
Started listening for OOM events for container
23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
[23:32:52]W: [Step 10/10] I0915 23:32:52.511402 29537 memory.cpp:564]
Started listening on 'low' memory pressure events for container
23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
[23:32:52]W: [Step 10/10] I0915 23:32:52.511945 29537 memory.cpp:564]
Started listening on 'medium' memory pressure events for container
23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
[23:32:52]W: [Step 10/10] I0915 23:32:52.512513 29537 memory.cpp:564]
Started listening on 'critical' memory pressure events for container
23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
[23:32:52]W: [Step 10/10] I0915 23:32:52.514281 29537 provisioner.cpp:253]
Provisioner recovery complete
[23:32:52]W: [Step 10/10] I0915 23:32:52.514574 29536 slave.cpp:5143]
Sending reconnect request to executor '725c46ae-bc78-41a4-bfd4-2f6903b03518' of
framework b8554850-0e42-40dd-aaaa-58d6c6f19074-0000 at
executor(1)@172.30.2.144:40649
[23:32:52]W: [Step 10/10] I0915 23:32:52.514755 11090 exec.cpp:283]
Received reconnect request from agent b8554850-0e42-40dd-aaaa-58d6c6f19074-S0
[23:32:52]W: [Step 10/10] I0915 23:32:52.514950 29534 slave.cpp:3374]
Re-registering executor '725c46ae-bc78-41a4-bfd4-2f6903b03518' of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:52]W: [Step 10/10] I0915 23:32:52.515035 29534 slave.cpp:3460]
Transitioning STAGED task 725c46ae-bc78-41a4-bfd4-2f6903b03518 to LOST because
it is unknown to the executor '725c46ae-bc78-41a4-bfd4-2f6903b03518'
[23:32:52]W: [Step 10/10] I0915 23:32:52.515069 29534 slave.cpp:3587]
Handling status update TASK_LOST (UUID: 96abf6bb-e72e-419d-8583-2cf169710082)
for task 725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000 from @0.0.0.0:0
[23:32:52]W: [Step 10/10] I0915 23:32:52.515156 11089 exec.cpp:260]
Executor re-registered on agent b8554850-0e42-40dd-aaaa-58d6c6f19074-S0
[23:32:52]W: [Step 10/10] I0915 23:32:52.515647 29537 memory.cpp:193]
Updated 'memory.soft_limit_in_bytes' to 160MB for container
23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
[23:32:52] : [Step 10/10] Received SUBSCRIBED event
[23:32:52] : [Step 10/10] Subscribed executor on
ip-172-30-2-144.ec2.internal.mesosphere.io
[23:32:52]W: [Step 10/10] I0915 23:32:52.516659 29537 cpu.cpp:103] Updated
'cpu.shares' to 614 (cpus 0.6) for container
23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
[23:32:52]W: [Step 10/10] I0915 23:32:52.517642 29538 memory.cpp:193]
Updated 'memory.soft_limit_in_bytes' to 32MB for container
23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
[23:32:52]W: [Step 10/10] I0915 23:32:52.518455 29538 cpu.cpp:103] Updated
'cpu.shares' to 102 (cpus 0.1) for container
23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
[23:32:52]W: [Step 10/10] I0915 23:32:52.518770 29536
status_update_manager.cpp:323] Received status update TASK_LOST (UUID:
96abf6bb-e72e-419d-8583-2cf169710082) for task
725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:52]W: [Step 10/10] I0915 23:32:52.518795 29536
status_update_manager.cpp:500] Creating StatusUpdate stream for task
725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:52]W: [Step 10/10] I0915 23:32:52.518990 29536
status_update_manager.cpp:832] Checkpointing UPDATE for status update TASK_LOST
(UUID: 96abf6bb-e72e-419d-8583-2cf169710082) for task
725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:52]W: [Step 10/10] I0915 23:32:52.519067 29536
status_update_manager.cpp:377] Forwarding update TASK_LOST (UUID:
96abf6bb-e72e-419d-8583-2cf169710082) for task
725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000 to the agent
[23:32:52]W: [Step 10/10] W0915 23:32:52.519145 29537 slave.cpp:3934]
Dropping status update TASK_LOST (UUID: 96abf6bb-e72e-419d-8583-2cf169710082)
for task 725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000 sent by status update manager because
the agent is in RECOVERING state
[23:32:52]W: [Step 10/10] I0915 23:32:52.519176 29537 slave.cpp:3882]
Status update manager successfully handled status update TASK_LOST (UUID:
96abf6bb-e72e-419d-8583-2cf169710082) for task
725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:53]W: [Step 10/10] I0915 23:32:53.353025 29536
hierarchical.cpp:1675] No allocations performed
[23:32:53]W: [Step 10/10] I0915 23:32:53.353045 29536
hierarchical.cpp:1770] No inverse offers to send out!
[23:32:53]W: [Step 10/10] I0915 23:32:53.353063 29536
hierarchical.cpp:1271] Performed allocation for 1 agents in 73203ns
[23:32:54]W: [Step 10/10] I0915 23:32:54.353688 29538
hierarchical.cpp:1675] No allocations performed
[23:32:54]W: [Step 10/10] I0915 23:32:54.353713 29538
hierarchical.cpp:1770] No inverse offers to send out!
[23:32:54]W: [Step 10/10] I0915 23:32:54.353726 29538
hierarchical.cpp:1271] Performed allocation for 1 agents in 82946ns
[23:32:54]W: [Step 10/10] I0915 23:32:54.515225 29537 slave.cpp:3527]
Cleaning up un-reregistered executors
[23:32:54]W: [Step 10/10] I0915 23:32:54.515256 29537 slave.cpp:5203]
Finished recovery
[23:32:54]W: [Step 10/10] I0915 23:32:54.515542 29537 slave.cpp:5375]
Querying resource estimator for oversubscribable resources
[23:32:54]W: [Step 10/10] I0915 23:32:54.515661 29537
status_update_manager.cpp:177] Pausing sending status updates
[23:32:54]W: [Step 10/10] I0915 23:32:54.515688 29533 slave.cpp:911] New
master detected at master@172.30.2.144:39560
[23:32:54]W: [Step 10/10] I0915 23:32:54.515707 29533 slave.cpp:970]
Authenticating with master master@172.30.2.144:39560
[23:32:54]W: [Step 10/10] I0915 23:32:54.515722 29533 slave.cpp:981] Using
default CRAM-MD5 authenticatee
[23:32:54]W: [Step 10/10] I0915 23:32:54.515765 29533 slave.cpp:943]
Detecting new master
[23:32:54]W: [Step 10/10] I0915 23:32:54.515810 29539
authenticatee.cpp:121] Creating new client SASL connection
[23:32:54]W: [Step 10/10] I0915 23:32:54.515836 29533 slave.cpp:5389]
Received oversubscribable resources from the resource estimator
[23:32:54]W: [Step 10/10] I0915 23:32:54.515888 29533 master.cpp:6234]
Authenticating slave(401)@172.30.2.144:39560
[23:32:54]W: [Step 10/10] I0915 23:32:54.515944 29536
authenticator.cpp:414] Starting authentication session for
crammd5-authenticatee(840)@172.30.2.144:39560
[23:32:54]W: [Step 10/10] I0915 23:32:54.516011 29539 authenticator.cpp:98]
Creating new server SASL connection
[23:32:54]W: [Step 10/10] I0915 23:32:54.516088 29536
authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
[23:32:54]W: [Step 10/10] I0915 23:32:54.516105 29536
authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
[23:32:54]W: [Step 10/10] I0915 23:32:54.516135 29536
authenticator.cpp:204] Received SASL authentication start
[23:32:54]W: [Step 10/10] I0915 23:32:54.516176 29536
authenticator.cpp:326] Authentication requires more steps
[23:32:54]W: [Step 10/10] I0915 23:32:54.516223 29537
authenticatee.cpp:259] Received SASL authentication step
[23:32:54]W: [Step 10/10] I0915 23:32:54.516273 29537
authenticator.cpp:232] Received SASL authentication step
[23:32:54]W: [Step 10/10] I0915 23:32:54.516288 29537 auxprop.cpp:109]
Request to lookup properties for user: 'test-principal' realm:
'ip-172-30-2-144.ec2.internal' server FQDN: 'ip-172-30-2-144.ec2.internal'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
[23:32:54]W: [Step 10/10] I0915 23:32:54.516294 29537 auxprop.cpp:181]
Looking up auxiliary property '*userPassword'
[23:32:54]W: [Step 10/10] I0915 23:32:54.516304 29537 auxprop.cpp:181]
Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[23:32:54]W: [Step 10/10] I0915 23:32:54.516312 29537 auxprop.cpp:109]
Request to lookup properties for user: 'test-principal' realm:
'ip-172-30-2-144.ec2.internal' server FQDN: 'ip-172-30-2-144.ec2.internal'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
[23:32:54]W: [Step 10/10] I0915 23:32:54.516322 29537 auxprop.cpp:131]
Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[23:32:54]W: [Step 10/10] I0915 23:32:54.516331 29537 auxprop.cpp:131]
Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID
== true
[23:32:54]W: [Step 10/10] I0915 23:32:54.516346 29537
authenticator.cpp:318] Authentication success
[23:32:54]W: [Step 10/10] I0915 23:32:54.516407 29536
authenticatee.cpp:299] Authentication success
[23:32:54]W: [Step 10/10] I0915 23:32:54.516424 29537 master.cpp:6264]
Successfully authenticated principal 'test-principal' at
slave(401)@172.30.2.144:39560
[23:32:54]W: [Step 10/10] I0915 23:32:54.516448 29532
authenticator.cpp:432] Authentication session cleanup for
crammd5-authenticatee(840)@172.30.2.144:39560
[23:32:54]W: [Step 10/10] I0915 23:32:54.516557 29536 slave.cpp:1065]
Successfully authenticated with master master@172.30.2.144:39560
[23:32:54]W: [Step 10/10] I0915 23:32:54.516660 29536 slave.cpp:1471] Will
retry registration in 5.509684ms if necessary
[23:32:54]W: [Step 10/10] I0915 23:32:54.516744 29539 master.cpp:5050]
Re-registering agent b8554850-0e42-40dd-aaaa-58d6c6f19074-S0 at
slave(400)@172.30.2.144:39560 (ip-172-30-2-144.ec2.internal.mesosphere.io)
[23:32:54]W: [Step 10/10] I0915 23:32:54.516821 29533 slave.cpp:1213]
Re-registered with master master@172.30.2.144:39560
[23:32:54]W: [Step 10/10] I0915 23:32:54.516829 29538 hierarchical.cpp:557]
Agent b8554850-0e42-40dd-aaaa-58d6c6f19074-S0 reactivated
[23:32:54]W: [Step 10/10] I0915 23:32:54.516822 29539 master.cpp:5278]
Sending updated checkpointed resources to agent
b8554850-0e42-40dd-aaaa-58d6c6f19074-S0 at slave(401)@172.30.2.144:39560
(ip-172-30-2-144.ec2.internal.mesosphere.io)
[23:32:54]W: [Step 10/10] I0915 23:32:54.516863 29533 slave.cpp:1249]
Forwarding total oversubscribed resources
[23:32:54]W: [Step 10/10] I0915 23:32:54.516891 29534
status_update_manager.cpp:184] Resuming sending status updates
[23:32:54]W: [Step 10/10] W0915 23:32:54.516906 29534
status_update_manager.cpp:191] Resending status update TASK_LOST (UUID:
96abf6bb-e72e-419d-8583-2cf169710082) for task
725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:54]W: [Step 10/10] I0915 23:32:54.516927 29533 slave.cpp:2671]
Updating framework b8554850-0e42-40dd-aaaa-58d6c6f19074-0000 pid to
scheduler-0a63c05f-da63-4c18-a2dc-f729f0fc4384@172.30.2.144:39560
[23:32:54]W: [Step 10/10] I0915 23:32:54.516938 29536 master.cpp:5340]
Received update of agent b8554850-0e42-40dd-aaaa-58d6c6f19074-S0 at
slave(401)@172.30.2.144:39560 (ip-172-30-2-144.ec2.internal.mesosphere.io) with
total oversubscribed resources
[23:32:54]W: [Step 10/10] I0915 23:32:54.516927 29534
status_update_manager.cpp:377] Forwarding update TASK_LOST (UUID:
96abf6bb-e72e-419d-8583-2cf169710082) for task
725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000 to the agent
[23:32:54]W: [Step 10/10] I0915 23:32:54.516968 29533 slave.cpp:2687]
Checkpointing framework pid
'scheduler-0a63c05f-da63-4c18-a2dc-f729f0fc4384@172.30.2.144:39560' to
'/mnt/teamcity/temp/buildTmp/MesosContainerizerSlaveRecoveryTest_CGROUPS_ROOT_PidNamespaceForward_Tg5l9R/meta/slaves/b8554850-0e42-40dd-aaaa-58d6c6f19074-S0/frameworks/b8554850-0e42-40dd-aaaa-58d6c6f19074-0000/framework.pid'
[23:32:54]W: [Step 10/10] I0915 23:32:54.517014 29536 hierarchical.cpp:540]
Agent b8554850-0e42-40dd-aaaa-58d6c6f19074-S0
(ip-172-30-2-144.ec2.internal.mesosphere.io) updated with oversubscribed
resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000], allocated: cpus(*):0.5; mem(*):128)
[23:32:54]W: [Step 10/10] I0915 23:32:54.517105 29536
hierarchical.cpp:1861] Filtered offer with cpus(*):1.5; mem(*):896;
disk(*):1024; ports(*):[31000-32000] on agent
b8554850-0e42-40dd-aaaa-58d6c6f19074-S0 for framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:54]W: [Step 10/10] I0915 23:32:54.517122 29536
hierarchical.cpp:1675] No allocations performed
[23:32:54]W: [Step 10/10] I0915 23:32:54.517127 29536
hierarchical.cpp:1770] No inverse offers to send out!
[23:32:54]W: [Step 10/10] I0915 23:32:54.517138 29536
hierarchical.cpp:1294] Performed allocation for agent
b8554850-0e42-40dd-aaaa-58d6c6f19074-S0 in 91974ns
[23:32:54]W: [Step 10/10] I0915 23:32:54.517164 29533 slave.cpp:2734]
Ignoring new checkpointed resources identical to the current version:
[23:32:54]W: [Step 10/10] I0915 23:32:54.517173 29536
status_update_manager.cpp:184] Resuming sending status updates
[23:32:54]W: [Step 10/10] W0915 23:32:54.517180 29536
status_update_manager.cpp:191] Resending status update TASK_LOST (UUID:
96abf6bb-e72e-419d-8583-2cf169710082) for task
725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:54]W: [Step 10/10] I0915 23:32:54.517189 29536
status_update_manager.cpp:377] Forwarding update TASK_LOST (UUID:
96abf6bb-e72e-419d-8583-2cf169710082) for task
725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000 to the agent
[23:32:54]W: [Step 10/10] I0915 23:32:54.517204 29533 slave.cpp:3988]
Forwarding the update TASK_LOST (UUID: 96abf6bb-e72e-419d-8583-2cf169710082)
for task 725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000 to master@172.30.2.144:39560
[23:32:54]W: [Step 10/10] I0915 23:32:54.517307 29533 slave.cpp:3988]
Forwarding the update TASK_LOST (UUID: 96abf6bb-e72e-419d-8583-2cf169710082)
for task 725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000 to master@172.30.2.144:39560
[23:32:54]W: [Step 10/10] I0915 23:32:54.517339 29536 master.cpp:5475]
Status update TASK_LOST (UUID: 96abf6bb-e72e-419d-8583-2cf169710082) for task
725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000 from agent
b8554850-0e42-40dd-aaaa-58d6c6f19074-S0 at slave(401)@172.30.2.144:39560
(ip-172-30-2-144.ec2.internal.mesosphere.io)
[23:32:54]W: [Step 10/10] I0915 23:32:54.517359 29536 master.cpp:5537]
Forwarding status update TASK_LOST (UUID: 96abf6bb-e72e-419d-8583-2cf169710082)
for task 725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:54]W: [Step 10/10] I0915 23:32:54.517403 29536 master.cpp:7187]
Updating the state of task 725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000 (latest state: TASK_LOST, status
update state: TASK_LOST)
[23:32:54]W: [Step 10/10] I0915 23:32:54.517469 29539 sched.cpp:1025]
Scheduler::statusUpdate took 12921ns
[23:32:54]W: [Step 10/10] I0915 23:32:54.517540 29538
hierarchical.cpp:1003] Recovered cpus(*):0.5; mem(*):128 (total: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on agent
b8554850-0e42-40dd-aaaa-58d6c6f19074-S0 from framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:54]W: [Step 10/10] I0915 23:32:54.517575 29536 master.cpp:5475]
Status update TASK_LOST (UUID: 96abf6bb-e72e-419d-8583-2cf169710082) for task
725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000 from agent
b8554850-0e42-40dd-aaaa-58d6c6f19074-S0 at slave(401)@172.30.2.144:39560
(ip-172-30-2-144.ec2.internal.mesosphere.io)
[23:32:54]W: [Step 10/10] I0915 23:32:54.517601 29536 master.cpp:5537]
Forwarding status update TASK_LOST (UUID: 96abf6bb-e72e-419d-8583-2cf169710082)
for task 725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:54]W: [Step 10/10] I0915 23:32:54.517647 29536 master.cpp:7187]
Updating the state of task 725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000 (latest state: TASK_LOST, status
update state: TASK_LOST)
[23:32:54]W: [Step 10/10] I0915 23:32:54.517689 29536 master.cpp:4598]
Processing ACKNOWLEDGE call 96abf6bb-e72e-419d-8583-2cf169710082 for task
725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000 (default) at
scheduler-0a63c05f-da63-4c18-a2dc-f729f0fc4384@172.30.2.144:39560 on agent
b8554850-0e42-40dd-aaaa-58d6c6f19074-S0
[23:32:54]W: [Step 10/10] I0915 23:32:54.517698 29537 sched.cpp:1025]
Scheduler::statusUpdate took 6224ns
[23:32:54]W: [Step 10/10] I0915 23:32:54.517704 29536 master.cpp:7283]
Removing task 725c46ae-bc78-41a4-bfd4-2f6903b03518 with resources cpus(*):0.5;
mem(*):128 of framework b8554850-0e42-40dd-aaaa-58d6c6f19074-0000 on agent
b8554850-0e42-40dd-aaaa-58d6c6f19074-S0 at slave(401)@172.30.2.144:39560
(ip-172-30-2-144.ec2.internal.mesosphere.io)
[23:32:54]W: [Step 10/10] I0915 23:32:54.517783 29536 master.cpp:4598]
Processing ACKNOWLEDGE call 96abf6bb-e72e-419d-8583-2cf169710082 for task
725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000 (default) at
scheduler-0a63c05f-da63-4c18-a2dc-f729f0fc4384@172.30.2.144:39560 on agent
b8554850-0e42-40dd-aaaa-58d6c6f19074-S0
[23:32:54]W: [Step 10/10] I0915 23:32:54.517845 29536
status_update_manager.cpp:395] Received status update acknowledgement (UUID:
96abf6bb-e72e-419d-8583-2cf169710082) for task
725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:54]W: [Step 10/10] I0915 23:32:54.517882 29536
status_update_manager.cpp:832] Checkpointing ACK for status update TASK_LOST
(UUID: 96abf6bb-e72e-419d-8583-2cf169710082) for task
725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:54]W: [Step 10/10] I0915 23:32:54.517920 29536
status_update_manager.cpp:531] Cleaning up status update stream for task
725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:54]W: [Step 10/10] I0915 23:32:54.518014 29536
status_update_manager.cpp:395] Received status update acknowledgement (UUID:
96abf6bb-e72e-419d-8583-2cf169710082) for task
725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:54]W: [Step 10/10] I0915 23:32:54.518043 29535 slave.cpp:2934]
Status update manager successfully handled status update acknowledgement (UUID:
96abf6bb-e72e-419d-8583-2cf169710082) for task
725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:54]W: [Step 10/10] I0915 23:32:54.518061 29535 slave.cpp:6459]
Completing task 725c46ae-bc78-41a4-bfd4-2f6903b03518
[23:32:54]W: [Step 10/10] E0915 23:32:54.518082 29535 slave.cpp:2927]
Failed to handle status update acknowledgement (UUID:
96abf6bb-e72e-419d-8583-2cf169710082) for task
725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000: Cannot find the status update stream
for task 725c46ae-bc78-41a4-bfd4-2f6903b03518 of framework
b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
[23:32:55]W: [Step 10/10] I0915 23:32:55.354341 29536
hierarchical.cpp:1770] No inverse offers to send out!
[23:32:55] : [Step 10/10] [ OK ]
MesosContainerizerSlaveRecoveryTest.CGROUPS_ROOT_PidNamespaceForward (3086 ms)
[23:32:55] : [Step 10/10] [ RUN ]
MesosContainerizerSlaveRecoveryTest.CGROUPS_ROOT_PidNamespaceBackward
[23:32:55] : [Step 10/10] Executing pre-exec command
'{"shell":true,"value":"mount -n --bind \/var\/empty\/mesos
\/var\/run\/mesos\/pidns"}'
[23:32:55] : [Step 10/10] Executing pre-exec command
'{"shell":true,"value":"mount none \/proc --make-private -o rec"}'
[23:32:55] : [Step 10/10] Executing pre-exec command
'{"shell":true,"value":"mount -n -t proc proc \/proc -o nosuid,noexec,nodev"}'
[23:32:55] : [Step 10/10] Received SUBSCRIBED event
[23:32:55] : [Step 10/10] Subscribed executor on
ip-172-30-2-144.ec2.internal.mesosphere.io
[23:32:55] : [Step 10/10] Received SUBSCRIBED event
[23:32:55] : [Step 10/10] Subscribed executor on
ip-172-30-2-144.ec2.internal.mesosphere.io
[23:33:10] : [Step 10/10] ../../src/tests/slave_recovery_tests.cpp:4220:
Failure
[23:33:10] : [Step 10/10] Failed to wait 15secs for offers2
[23:33:10] : [Step 10/10] ../../src/tests/slave_recovery_tests.cpp:4213:
Failure
[23:33:10] : [Step 10/10] Actual function call count doesn't match
EXPECT_CALL(sched, resourceOffers(_, _))...
[23:33:10] : [Step 10/10] Expected: to be called at least once
[23:33:10] : [Step 10/10] Actual: never called - unsatisfied and
active
[23:33:25] : [Step 10/10] ../../src/tests/cluster.cpp:560: Failure
[23:33:25] : [Step 10/10] Failed to wait 15secs for wait
[23:34:42]W: [Step 10/10] I0915 23:32:55.354369 29536
hierarchical.cpp:1271] Performed allocation for 1 agents in 173915ns
[23:34:42]W: [Step 10/10] I0915 23:32:55.354411 29534 master.cpp:6063]
Sending 1 offers to framework b8554850-0e42-40dd-aaaa-58d6c6f19074-0000
(default) at scheduler-0a63c05f-da63-4c18-a2dc-f729f0fc4384@172.30.2.144:39560
[23:34:42]W: [Step 10/10] I0915 23:32:55.354534 29534 sched.cpp:917]
Scheduler::resourceOffers took 34437ns
[23:34:42]W: [Step 10/10] I0915 23:32:55.354732 29535
containerizer.cpp:1617] Destroying container
23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
[23:34:42]W: [Step 10/10] I0915 23:32:55.356585 29538 cgroups.cpp:2678]
Freezing cgroup
/sys/fs/cgroup/freezer/mesos_test_62e4d3a2-29cc-4d57-9c07-e392f07e058c/23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
[23:34:42]W: [Step 10/10] I0915 23:32:55.357972 29533 cgroups.cpp:1412]
Successfully froze cgroup
/sys/fs/cgroup/freezer/mesos_test_62e4d3a2-29cc-4d57-9c07-e392f07e058c/23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
after 1.359872ms
[23:34:42]W: [Step 10/10] I0915 23:32:55.359447 29533 cgroups.cpp:2696]
Thawing cgroup
/sys/fs/cgroup/freezer/mesos_test_62e4d3a2-29cc-4d57-9c07-e392f07e058c/23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
[23:34:42]W: [Step 10/10] I0915 23:32:55.360864 29536 cgroups.cpp:1441]
Successfully thawed cgroup
/sys/fs/cgroup/freezer/mesos_test_62e4d3a2-29cc-4d57-9c07-e392f07e058c/23fb2ad6-8cd0-45d8-b3d3-d144acb47ef4
after 1.391872ms
{noformat}
> Several tests are flaky, with futures timing out early
> ------------------------------------------------------
>
> Key: MESOS-6180
> URL: https://issues.apache.org/jira/browse/MESOS-6180
> Project: Mesos
> Issue Type: Bug
> Components: tests
> Reporter: Greg Mann
> Assignee: haosdent
> Labels: mesosphere, tests
> Attachments: CGROUPS_ROOT_PidNamespaceBackward.log,
> CGROUPS_ROOT_PidNamespaceForward.log, FetchAndStoreAndStoreAndFetch.log
>
>
> Following the merging of a large patch chain, it was noticed on our internal
> CI that several tests had become flaky, with a similar pattern in the
> failures: the tests fail early when a future times out. Often, this occurs
> when a test cluster is being spun up and one of the offer futures times out.
> This has been observed in the following tests:
> * MesosContainerizerSlaveRecoveryTest.CGROUPS_ROOT_PidNamespaceForward
> * MesosContainerizerSlaveRecoveryTest.CGROUPS_ROOT_PidNamespaceBackward
> * ZooKeeperStateTest.FetchAndStoreAndStoreAndFetch
> * RoleTest.ImplicitRoleRegister
> * SlaveRecoveryTest/0.MultipleFrameworks
> * SlaveRecoveryTest/0.ReconcileShutdownFramework
> * SlaveTest.ContainerizerUsageFailure
> * MesosSchedulerDriverTest.ExplicitAcknowledgements
> * SlaveRecoveryTest/0.ReconnectHTTPExecutor (MESOS-6164)
> * ResourceOffersTest.ResourcesGetReofferedAfterTaskInfoError (MESOS-6165)
> * SlaveTest.CommandTaskWithKillPolicy (MESOS-6166)
> See the linked JIRAs noted above for individual tickets addressing a couple
> of these.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
