See <https://builds.apache.org/job/Mesos-Buildbot/BUILDTOOL=cmake,COMPILER=clang,CONFIGURATION=--verbose%20--disable-libtool-wrappers,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=ubuntu%3A14.04,label_exp=(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23)/4494/display/redirect>
------------------------------------------ [...truncated 13.81 MB...] 3: I1123 07:52:38.162331 16003 master.cpp:1311] Agent 3886dddc-4e88-4edb-bee4-ad0d1f723138-S0 at slave(304)@172.17.0.4:33453 (87696d373764) disconnected 3: I1123 07:52:38.162349 16003 master.cpp:3370] Disconnecting agent 3886dddc-4e88-4edb-bee4-ad0d1f723138-S0 at slave(304)@172.17.0.4:33453 (87696d373764) 3: I1123 07:52:38.162390 16003 master.cpp:3389] Deactivating agent 3886dddc-4e88-4edb-bee4-ad0d1f723138-S0 at slave(304)@172.17.0.4:33453 (87696d373764) 3: I1123 07:52:38.162485 16011 registrar.cpp:495] Applied 1 operations in 76527ns; attempting to update the registry 3: I1123 07:52:38.162490 16019 hierarchical.cpp:697] Agent 3886dddc-4e88-4edb-bee4-ad0d1f723138-S0 deactivated 3: I1123 07:52:38.162928 16011 registrar.cpp:552] Successfully updated the registry in 391168ns 3: I1123 07:52:38.163106 16010 master.cpp:9237] Removed agent 3886dddc-4e88-4edb-bee4-ad0d1f723138-S0 at slave(304)@172.17.0.4:33453 (87696d373764): the agent unregistered 3: I1123 07:52:38.163439 16010 master.cpp:2132] Notifying framework 3886dddc-4e88-4edb-bee4-ad0d1f723138-0000 (default) at [email protected]:33453 of lost agent 3886dddc-4e88-4edb-bee4-ad0d1f723138-S0 (87696d373764) 3: I1123 07:52:38.163614 16009 sched.cpp:1091] Lost agent 3886dddc-4e88-4edb-bee4-ad0d1f723138-S0 3: I1123 07:52:38.163667 16009 sched.cpp:1102] Scheduler::slaveLost took 27276ns 3: I1123 07:52:38.163710 16022 hierarchical.cpp:633] Removed agent 3886dddc-4e88-4edb-bee4-ad0d1f723138-S0 3: I1123 07:52:38.166199 16007 master.cpp:7331] Sending status update TASK_LOST for task dce0b83f-20e2-4b7e-88ce-2a6d90d98f0f of framework 3886dddc-4e88-4edb-bee4-ad0d1f723138-0000 'Agent removed' 3: I1123 07:52:38.166537 16008 sched.cpp:1029] Scheduler::statusUpdate took 75597ns 3: I1123 07:52:38.169142 16024 process.cpp:3503] Handling HTTP event for process 'metrics' with path: '/metrics/snapshot' 3: I1123 07:52:38.180532 16020 master.cpp:7730] Performing implicit task state reconciliation for framework 3886dddc-4e88-4edb-bee4-ad0d1f723138-0000 (default) at [email protected]:33453 3: I1123 07:52:38.180718 16001 sched.cpp:2009] Asked to stop the driver 3: I1123 07:52:38.180848 16016 sched.cpp:1191] Stopping framework 3886dddc-4e88-4edb-bee4-ad0d1f723138-0000 3: I1123 07:52:38.181082 16019 master.cpp:8819] Processing TEARDOWN call for framework 3886dddc-4e88-4edb-bee4-ad0d1f723138-0000 (default) at [email protected]:33453 3: I1123 07:52:38.181116 16019 master.cpp:8831] Removing framework 3886dddc-4e88-4edb-bee4-ad0d1f723138-0000 (default) at [email protected]:33453 3: I1123 07:52:38.181141 16019 master.cpp:3333] Deactivating framework 3886dddc-4e88-4edb-bee4-ad0d1f723138-0000 (default) at [email protected]:33453 3: I1123 07:52:38.181260 16017 hierarchical.cpp:419] Deactivated framework 3886dddc-4e88-4edb-bee4-ad0d1f723138-0000 3: I1123 07:52:38.181650 16012 hierarchical.cpp:358] Removed framework 3886dddc-4e88-4edb-bee4-ad0d1f723138-0000 3: I1123 07:52:38.182260 16001 master.cpp:1153] Master terminating 3: [ OK ] MasterAuthorizationTest.SlaveRemovedLost (59 ms) 3: [ RUN ] MasterAuthorizationTest.SlaveRemovedDropped 3: I1123 07:52:38.191227 16003 master.cpp:448] Master 37379cd9-97d6-4a8b-8b4a-e710310ad0c5 (87696d373764) started on 172.17.0.4:33453 3: I1123 07:52:38.191262 16003 master.cpp:450] 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/3NJZoS/credentials" --filter_gpu_resources="true" --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" --max_unreachable_tasks_per_framework="1000" --port="5050" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/3NJZoS/master" --zk_session_timeout="10secs" 3: I1123 07:52:38.191519 16003 master.cpp:499] Master only allowing authenticated frameworks to register 3: I1123 07:52:38.191526 16003 master.cpp:505] Master only allowing authenticated agents to register 3: I1123 07:52:38.191530 16003 master.cpp:511] Master only allowing authenticated HTTP frameworks to register 3: I1123 07:52:38.191535 16003 credentials.hpp:37] Loading credentials for authentication from '/tmp/3NJZoS/credentials' 3: I1123 07:52:38.191792 16003 master.cpp:555] Using default 'crammd5' authenticator 3: I1123 07:52:38.191926 16003 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' 3: I1123 07:52:38.192059 16003 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' 3: I1123 07:52:38.192174 16003 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' 3: I1123 07:52:38.192282 16003 master.cpp:634] Authorization enabled 3: I1123 07:52:38.192411 16015 hierarchical.cpp:173] Initialized hierarchical allocator process 3: I1123 07:52:38.192457 16012 whitelist_watcher.cpp:77] No whitelist given 3: I1123 07:52:38.194931 16002 master.cpp:2215] Elected as the leading master! 3: I1123 07:52:38.194949 16002 master.cpp:1695] Recovering from registrar 3: I1123 07:52:38.195080 16010 registrar.cpp:347] Recovering registrar 3: I1123 07:52:38.195569 16010 registrar.cpp:391] Successfully fetched the registry (0B) in 455936ns 3: I1123 07:52:38.195657 16010 registrar.cpp:495] Applied 1 operations in 32425ns; attempting to update the registry 3: I1123 07:52:38.196079 16010 registrar.cpp:552] Successfully updated the registry in 378112ns 3: I1123 07:52:38.196178 16010 registrar.cpp:424] Successfully recovered registrar 3: I1123 07:52:38.196488 16016 master.cpp:1808] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register 3: I1123 07:52:38.196552 16020 hierarchical.cpp:211] Skipping recovery of hierarchical allocator: nothing to recover 3: W1123 07:52:38.200827 16001 process.cpp:2756] Attempted to spawn already running process [email protected]:33453 3: I1123 07:52:38.201126 16001 cluster.cpp:448] Creating default 'local' authorizer 3: I1123 07:52:38.203840 16022 slave.cpp:262] Mesos agent started on (305)@172.17.0.4:33453 3: I1123 07:52:38.203872 16022 slave.cpp:263] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/MasterAuthorizationTest_SlaveRemovedDropped_BCO2H1/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/MasterAuthorizationTest_SlaveRemovedDropped_BCO2H1/credential" --default_role="*" --disallow_sharing_agent_pid_namespace="false" --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/MasterAuthorizationTest_SlaveRemovedDropped_BCO2H1/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/MasterAuthorizationTest_SlaveRemovedDropped_BCO2H1/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_command_executor="false" --http_credentials="/tmp/MasterAuthorizationTest_SlaveRemovedDropped_BCO2H1/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --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="/tmp/MasterAuthorizationTest_SlaveRemovedDropped_BCO2H1" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/MasterAuthorizationTest_SlaveRemovedDropped_g5Kv3r" --zk_session_timeout="10secs" 3: I1123 07:52:38.204300 16022 credentials.hpp:86] Loading credential for authentication from '/tmp/MasterAuthorizationTest_SlaveRemovedDropped_BCO2H1/credential' 3: W1123 07:52:38.204380 16001 process.cpp:2756] Attempted to spawn already running process [email protected]:33453 3: I1123 07:52:38.204442 16022 slave.cpp:295] Agent using credential for: test-principal 3: I1123 07:52:38.204454 16022 credentials.hpp:37] Loading credentials for authentication from '/tmp/MasterAuthorizationTest_SlaveRemovedDropped_BCO2H1/http_credentials' 3: I1123 07:52:38.204690 16022 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' 3: I1123 07:52:38.204833 16022 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite' 3: I1123 07:52:38.205313 16001 sched.cpp:232] Version: 1.5.0 3: I1123 07:52:38.205757 16015 sched.cpp:336] New master detected at [email protected]:33453 3: I1123 07:52:38.205853 16015 sched.cpp:396] Authenticating with master [email protected]:33453 3: I1123 07:52:38.205873 16015 sched.cpp:403] Using default CRAM-MD5 authenticatee 3: I1123 07:52:38.206117 16011 authenticatee.cpp:121] Creating new client SASL connection 3: I1123 07:52:38.206193 16022 slave.cpp:593] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] 3: I1123 07:52:38.206408 16022 slave.cpp:601] Agent attributes: [ ] 3: I1123 07:52:38.206416 16022 slave.cpp:610] Agent hostname: 87696d373764 3: I1123 07:52:38.206420 16011 master.cpp:8312] Authenticating [email protected]:33453 3: I1123 07:52:38.206560 16023 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(638)@172.17.0.4:33453 3: I1123 07:52:38.206579 16003 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I1123 07:52:38.206755 16009 authenticator.cpp:98] Creating new server SASL connection 3: I1123 07:52:38.206984 16007 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1123 07:52:38.207012 16007 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1123 07:52:38.207139 16007 authenticator.cpp:204] Received SASL authentication start 3: I1123 07:52:38.207195 16007 authenticator.cpp:326] Authentication requires more steps 3: I1123 07:52:38.207296 16008 authenticatee.cpp:259] Received SASL authentication step 3: I1123 07:52:38.207423 16025 authenticator.cpp:232] Received SASL authentication step 3: I1123 07:52:38.207449 16025 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '87696d373764' server FQDN: '87696d373764' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1123 07:52:38.207458 16025 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1123 07:52:38.207489 16025 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1123 07:52:38.207505 16025 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '87696d373764' server FQDN: '87696d373764' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1123 07:52:38.207512 16025 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1123 07:52:38.207517 16025 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1123 07:52:38.207530 16025 authenticator.cpp:318] Authentication success 3: I1123 07:52:38.207648 16006 authenticatee.cpp:299] Authentication success 3: I1123 07:52:38.207672 16010 master.cpp:8342] Successfully authenticated principal 'test-principal' at [email protected]:33453 3: I1123 07:52:38.207708 16018 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(638)@172.17.0.4:33453 3: I1123 07:52:38.207883 16017 sched.cpp:502] Successfully authenticated with master [email protected]:33453 3: I1123 07:52:38.207901 16017 sched.cpp:824] Sending SUBSCRIBE call to [email protected]:33453 3: I1123 07:52:38.208003 16017 sched.cpp:857] Will retry registration in 267.230861ms if necessary 3: I1123 07:52:38.208108 16019 state.cpp:64] Recovering state from '/tmp/MasterAuthorizationTest_SlaveRemovedDropped_g5Kv3r/meta' 3: I1123 07:52:38.208184 16012 master.cpp:2963] Received SUBSCRIBE call for framework 'default' at [email protected]:33453 3: I1123 07:52:38.208205 16012 master.cpp:2280] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }' 3: I1123 07:52:38.208364 16019 task_status_update_manager.cpp:207] Recovering task status update manager 3: I1123 07:52:38.208498 16012 master.cpp:3043] Subscribing framework default with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT, PARTITION_AWARE ] 3: I1123 07:52:38.208732 16023 slave.cpp:6493] Finished recovery 3: I1123 07:52:38.209064 16013 sched.cpp:751] Framework registered with 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-0000 3: I1123 07:52:38.209122 16013 sched.cpp:765] Scheduler::registered took 40608ns 3: I1123 07:52:38.209131 16009 hierarchical.cpp:306] Added framework 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-0000 3: I1123 07:52:38.209319 16009 hierarchical.cpp:1457] Performed allocation for 0 agents in 79408ns 3: I1123 07:52:38.209334 16010 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I1123 07:52:38.209334 16006 slave.cpp:1007] New master detected at [email protected]:33453 3: I1123 07:52:38.209424 16006 slave.cpp:1042] Detecting new master 3: I1123 07:52:38.210747 16016 slave.cpp:1069] Authenticating with master [email protected]:33453 3: I1123 07:52:38.210801 16016 slave.cpp:1078] Using default CRAM-MD5 authenticatee 3: I1123 07:52:38.210978 16018 authenticatee.cpp:121] Creating new client SASL connection 3: I1123 07:52:38.211218 16020 master.cpp:8312] Authenticating slave(305)@172.17.0.4:33453 3: I1123 07:52:38.211295 16017 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(639)@172.17.0.4:33453 3: I1123 07:52:38.211470 16022 authenticator.cpp:98] Creating new server SASL connection 3: I1123 07:52:38.211630 16004 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1123 07:52:38.211652 16004 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1123 07:52:38.211732 16004 authenticator.cpp:204] Received SASL authentication start 3: I1123 07:52:38.211766 16004 authenticator.cpp:326] Authentication requires more steps 3: I1123 07:52:38.211843 16004 authenticatee.cpp:259] Received SASL authentication step 3: I1123 07:52:38.211949 16024 authenticator.cpp:232] Received SASL authentication step 3: I1123 07:52:38.211974 16024 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '87696d373764' server FQDN: '87696d373764' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1123 07:52:38.211984 16024 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1123 07:52:38.212007 16024 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1123 07:52:38.212021 16024 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '87696d373764' server FQDN: '87696d373764' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1123 07:52:38.212030 16024 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1123 07:52:38.212035 16024 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1123 07:52:38.212046 16024 authenticator.cpp:318] Authentication success 3: I1123 07:52:38.212116 16019 authenticatee.cpp:299] Authentication success 3: I1123 07:52:38.212167 16011 master.cpp:8342] Successfully authenticated principal 'test-principal' at slave(305)@172.17.0.4:33453 3: I1123 07:52:38.212198 16003 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(639)@172.17.0.4:33453 3: I1123 07:52:38.212347 16024 slave.cpp:1161] Successfully authenticated with master [email protected]:33453 3: I1123 07:52:38.212543 16024 slave.cpp:1685] Will retry registration in 19.926607ms if necessary 3: I1123 07:52:38.212736 16023 master.cpp:6036] Received register agent message from slave(305)@172.17.0.4:33453 (87696d373764) 3: I1123 07:52:38.212769 16023 master.cpp:3872] Authorizing agent with principal 'test-principal' 3: I1123 07:52:38.213011 16023 master.cpp:6098] Authorized registration of agent at slave(305)@172.17.0.4:33453 (87696d373764) 3: I1123 07:52:38.213099 16023 master.cpp:6191] Registering agent at slave(305)@172.17.0.4:33453 (87696d373764) with id 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-S0 3: I1123 07:52:38.213399 16008 registrar.cpp:495] Applied 1 operations in 59675ns; attempting to update the registry 3: I1123 07:52:38.213872 16008 registrar.cpp:552] Successfully updated the registry in 424960ns 3: I1123 07:52:38.214076 16021 master.cpp:6240] Admitted agent 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-S0 at slave(305)@172.17.0.4:33453 (87696d373764) 3: I1123 07:52:38.214632 16021 master.cpp:6276] Registered agent 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-S0 at slave(305)@172.17.0.4:33453 (87696d373764) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] 3: I1123 07:52:38.214704 16018 slave.cpp:1207] Registered with master [email protected]:33453; given agent ID 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-S0 3: I1123 07:52:38.214776 16021 task_status_update_manager.cpp:188] Resuming sending task status updates 3: I1123 07:52:38.214921 16020 hierarchical.cpp:600] Added agent 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-S0 (87696d373764) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {}) 3: I1123 07:52:38.215031 16018 slave.cpp:1227] Checkpointing SlaveInfo to '/tmp/MasterAuthorizationTest_SlaveRemovedDropped_g5Kv3r/meta/slaves/37379cd9-97d6-4a8b-8b4a-e710310ad0c5-S0/slave.info' 3: I1123 07:52:38.215432 16018 slave.cpp:1298] Forwarding total oversubscribed resources {} 3: I1123 07:52:38.215629 16018 master.cpp:7091] Received update of agent 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-S0 at slave(305)@172.17.0.4:33453 (87696d373764) with total oversubscribed resources {} 3: I1123 07:52:38.215806 16018 master.cpp:7109] Ignoring update on agent 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-S0 at slave(305)@172.17.0.4:33453 (87696d373764) as it reports no changes 3: I1123 07:52:38.215987 16020 hierarchical.cpp:1457] Performed allocation for 1 agents in 940475ns 3: I1123 07:52:38.216392 16004 master.cpp:8142] Sending 1 offers to framework 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-0000 (default) at [email protected]:33453 3: I1123 07:52:38.216905 16012 sched.cpp:921] Scheduler::resourceOffers took 116675ns 3: I1123 07:52:38.218768 16024 master.cpp:10063] Removing offer 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-O0 3: I1123 07:52:38.218912 16024 master.cpp:4230] Processing ACCEPT call for offers: [ 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-O0 ] on agent 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-S0 at slave(305)@172.17.0.4:33453 (87696d373764) for framework 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-0000 (default) at [email protected]:33453 3: I1123 07:52:38.219009 16024 master.cpp:3599] Authorizing framework principal 'test-principal' to launch task d791aff3-eaa0-4f84-930b-60c197cb4934 3: I1123 07:52:38.219352 16008 slave.cpp:920] Unregistering and shutting down 3: I1123 07:52:38.219403 16008 slave.cpp:883] Agent terminating 3: I1123 07:52:38.219518 16024 master.cpp:9195] Removing agent 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-S0 at slave(305)@172.17.0.4:33453 (87696d373764): the agent unregistered 3: I1123 07:52:38.219722 16024 master.cpp:1311] Agent 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-S0 at slave(305)@172.17.0.4:33453 (87696d373764) disconnected 3: I1123 07:52:38.219741 16024 master.cpp:3370] Disconnecting agent 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-S0 at slave(305)@172.17.0.4:33453 (87696d373764) 3: I1123 07:52:38.219789 16024 master.cpp:3389] Deactivating agent 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-S0 at slave(305)@172.17.0.4:33453 (87696d373764) 3: I1123 07:52:38.219885 16018 hierarchical.cpp:697] Agent 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-S0 deactivated 3: I1123 07:52:38.219930 16021 registrar.cpp:495] Applied 1 operations in 92279ns; attempting to update the registry 3: I1123 07:52:38.220350 16021 registrar.cpp:552] Successfully updated the registry in 370944ns 3: I1123 07:52:38.220499 16009 master.cpp:9237] Removed agent 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-S0 at slave(305)@172.17.0.4:33453 (87696d373764): the agent unregistered 3: I1123 07:52:38.220831 16009 master.cpp:2132] Notifying framework 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-0000 (default) at [email protected]:33453 of lost agent 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-S0 (87696d373764) 3: I1123 07:52:38.221009 16015 sched.cpp:1091] Lost agent 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-S0 3: I1123 07:52:38.221058 16010 hierarchical.cpp:633] Removed agent 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-S0 3: I1123 07:52:38.221063 16015 sched.cpp:1102] Scheduler::slaveLost took 26153ns 3: I1123 07:52:38.223276 16010 master.cpp:7331] Sending status update TASK_DROPPED for task d791aff3-eaa0-4f84-930b-60c197cb4934 of framework 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-0000 'Agent removed' 3: I1123 07:52:38.223573 16012 sched.cpp:1029] Scheduler::statusUpdate took 68472ns 3: I1123 07:52:38.225540 16007 process.cpp:3503] Handling HTTP event for process 'metrics' with path: '/metrics/snapshot' 3: I1123 07:52:38.236861 16017 master.cpp:7730] Performing implicit task state reconciliation for framework 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-0000 (default) at [email protected]:33453 3: I1123 07:52:38.237002 16001 sched.cpp:2009] Asked to stop the driver 3: I1123 07:52:38.237130 16002 sched.cpp:1191] Stopping framework 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-0000 3: I1123 07:52:38.237349 16023 master.cpp:8819] Processing TEARDOWN call for framework 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-0000 (default) at [email protected]:33453 3: I1123 07:52:38.237380 16023 master.cpp:8831] Removing framework 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-0000 (default) at [email protected]:33453 3: I1123 07:52:38.237397 16023 master.cpp:3333] Deactivating framework 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-0000 (default) at [email protected]:33453 3: I1123 07:52:38.237534 16007 hierarchical.cpp:419] Deactivated framework 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-0000 3: I1123 07:52:38.237920 16008 hierarchical.cpp:358] Removed framework 37379cd9-97d6-4a8b-8b4a-e710310ad0c5-0000 3: I1123 07:52:38.238482 16001 master.cpp:1153] Master terminating 3: [ OK ] MasterAuthorizationTest.SlaveRemovedDropped (55 ms) 3: [ RUN ] MasterAuthorizationTest.FrameworkRemoved 3: I1123 07:52:38.247108 16019 master.cpp:448] Master 8471c6b4-22a3-473f-b98c-0ff3f0c696d9 (87696d373764) started on 172.17.0.4:33453 3: I1123 07:52:38.247176 16019 master.cpp:450] 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/gVh0PK/credentials" --filter_gpu_resources="true" --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" --max_unreachable_tasks_per_framework="1000" --port="5050" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/gVh0PK/master" --zk_session_timeout="10secs" 3: I1123 07:52:38.247614 16019 master.cpp:499] Master only allowing authenticated frameworks to register 3: I1123 07:52:38.247627 16019 master.cpp:505] Master only allowing authenticated agents to register 3: I1123 07:52:38.247635 16019 master.cpp:511] Master only allowing authenticated HTTP frameworks to register 3: I1123 07:52:38.247654 16019 credentials.hpp:37] Loading credentials for authentication from '/tmp/gVh0PK/credentials' 3: I1123 07:52:38.247997 16019 master.cpp:555] Using default 'crammd5' authenticator 3: I1123 07:52:38.248183 16019 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' 3: I1123 07:52:38.248386 16019 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' 3: I1123 07:52:38.248535 16019 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' 3: I1123 07:52:38.248704 16019 master.cpp:634] Authorization enabled 3: I1123 07:52:38.248842 16014 hierarchical.cpp:173] Initialized hierarchical allocator process 3: I1123 07:52:38.248873 16023 whitelist_watcher.cpp:77] No whitelist given 3: I1123 07:52:38.251402 16012 master.cpp:2215] Elected as the leading master! 3: I1123 07:52:38.251420 16012 master.cpp:1695] Recovering from registrar 3: I1123 07:52:38.251552 16010 registrar.cpp:347] Recovering registrar 3: I1123 07:52:38.252022 16010 registrar.cpp:391] Successfully fetched the registry (0B) in 440064ns 3: I1123 07:52:38.252109 16010 registrar.cpp:495] Applied 1 operations in 31529ns; attempting to update the registry 3: I1123 07:52:38.252540 16010 registrar.cpp:552] Successfully updated the registry in 390144ns 3: I1123 07:52:38.252650 16010 registrar.cpp:424] Successfully recovered registrar 3: I1123 07:52:38.252981 16003 master.cpp:1808] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register 3: I1123 07:52:38.253002 16009 hierarchical.cpp:211] Skipping recovery of hierarchical allocator: nothing to recover 3: W1123 07:52:38.257369 16001 process.cpp:2756] Attempted to spawn already running process [email protected]:33453 3: I1123 07:52:38.257673 16001 cluster.cpp:448] Creating default 'local' authorizer 3: I1123 07:52:38.259649 16012 slave.cpp:262] Mesos agent started on (306)@172.17.0.4:33453 3: I1123 07:52:38.259682 16012 slave.cpp:263] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/MasterAuthorizationTest_FrameworkRemoved_6Q1SpU/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/MasterAuthorizationTest_FrameworkRemoved_6Q1SpU/credential" --default_role="*" --disallow_sharing_agent_pid_namespace="false" --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/MasterAuthorizationTest_FrameworkRemoved_6Q1SpU/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/MasterAuthorizationTest_FrameworkRemoved_6Q1SpU/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_command_executor="false" --http_credentials="/tmp/MasterAuthorizationTest_FrameworkRemoved_6Q1SpU/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --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="/tmp/MasterAuthorizationTest_FrameworkRemoved_6Q1SpU" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/MasterAuthorizationTest_FrameworkRemoved_xfcWCk" --zk_session_timeout="10secs" 3: I1123 07:52:38.260236 16012 credentials.hpp:86] Loading credential for authentication from '/tmp/MasterAuthorizationTest_FrameworkRemoved_6Q1SpU/credential' 3: W1123 07:52:38.260273 16001 process.cpp:2756] Attempted to spawn already running process [email protected]:33453 3: I1123 07:52:38.260403 16012 slave.cpp:295] Agent using credential for: test-principal 3: I1123 07:52:38.260426 16012 credentials.hpp:37] Loading credentials for authentication from '/tmp/MasterAuthorizationTest_FrameworkRemoved_6Q1SpU/http_credentials' 3: I1123 07:52:38.260725 16012 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' 3: I1123 07:52:38.260876 16012 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite' 3: I1123 07:52:38.261366 16001 sched.cpp:232] Version: 1.5.0 3: I1123 07:52:38.261833 16023 sched.cpp:336] New master detected at [email protected]:33453 3: I1123 07:52:38.261920 16023 sched.cpp:396] Authenticating with master [email protected]:33453 3: I1123 07:52:38.261935 16023 sched.cpp:403] Using default CRAM-MD5 authenticatee 3: I1123 07:52:38.262152 16014 authenticatee.cpp:121] Creating new client SASL connection 3: I1123 07:52:38.262418 16019 master.cpp:8312] Authenticating [email protected]:33453 3: I1123 07:52:38.262507 16006 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(640)@172.17.0.4:33453 3: I1123 07:52:38.262470 16012 slave.cpp:593] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] 3: I1123 07:52:38.262678 16012 slave.cpp:601] Agent attributes: [ ] 3: I1123 07:52:38.262691 16012 slave.cpp:610] Agent hostname: 87696d373764 3: I1123 07:52:38.262799 16015 authenticator.cpp:98] Creating new server SASL connection 3: I1123 07:52:38.262850 16025 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I1123 07:52:38.263170 16022 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1123 07:52:38.263204 16022 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1123 07:52:38.263326 16022 authenticator.cpp:204] Received SASL authentication start 3: I1123 07:52:38.263383 16022 authenticator.cpp:326] Authentication requires more steps 3: I1123 07:52:38.263484 16022 authenticatee.cpp:259] Received SASL authentication step 3: I1123 07:52:38.263625 16004 authenticator.cpp:232] Received SASL authentication step 3: I1123 07:52:38.263669 16004 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '87696d373764' server FQDN: '87696d373764' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1123 07:52:38.263679 16004 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1123 07:52:38.263707 16004 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1123 07:52:38.263723 16004 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '87696d373764' server FQDN: '87696d373764' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1123 07:52:38.263731 16004 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1123 07:52:38.263734 16004 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1123 07:52:38.263751 16004 authenticator.cpp:318] Authentication success 3: I1123 07:52:38.263803 16020 authenticatee.cpp:299] Authentication success 3: I1123 07:52:38.263895 16002 master.cpp:8342] Successfully authenticated principal 'test-principal' at [email protected]:33453 3: I1123 07:52:38.263942 16021 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(640)@172.17.0.4:33453 3: I1123 07:52:38.264168 16010 sched.cpp:502] Successfully authenticated with master [email protected]:33453 3: I1123 07:52:38.264194 16010 sched.cpp:824] Sending SUBSCRIBE call to [email protected]:33453 3: I1123 07:52:38.264295 16008 state.cpp:64] Recovering state from '/tmp/MasterAuthorizationTest_FrameworkRemoved_xfcWCk/meta' 3: I1123 07:52:38.264297 16010 sched.cpp:857] Will retry registration in 1.790929901secs if necessary 3: I1123 07:52:38.264513 16017 master.cpp:2963] Received SUBSCRIBE call for framework 'default' at [email protected]:33453 3: I1123 07:52:38.264534 16016 task_status_update_manager.cpp:207] Recovering task status update manager 3: I1123 07:52:38.264533 16017 master.cpp:2280] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }' 3: I1123 07:52:38.264808 16017 master.cpp:3043] Subscribing framework default with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT ] 3: I1123 07:52:38.264870 16006 slave.cpp:6493] Finished recovery 3: I1123 07:52:38.265350 16017 sched.cpp:751] Framework registered with 8471c6b4-22a3-473f-b98c-0ff3f0c696d9-0000 3: I1123 07:52:38.265395 16017 sched.cpp:765] Scheduler::registered took 29300ns 3: I1123 07:52:38.265420 16025 hierarchical.cpp:306] Added framework 8471c6b4-22a3-473f-b98c-0ff3f0c696d9-0000 3: I1123 07:52:38.265519 16017 slave.cpp:1007] New master detected at [email protected]:33453 Process leaked file descriptors. See https://jenkins.io/redirect/troubleshooting/process-leaked-file-descriptors for more information Build step 'Execute shell' marked build as failure
