Created
September 16, 2016 10:04
-
-
Save haosdent/76994f838e18184376b6b77aa6c1e11a to your computer and use it in GitHub Desktop.
MESOS-6165_stderr
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| [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]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]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]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: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 |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment