See <https://builds.apache.org/job/Mesos-Buildbot/BUILDTOOL=cmake,COMPILER=gcc,CONFIGURATION=--verbose%20--disable-libtool-wrappers,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=centos%3A7,label_exp=(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23)/4492/display/redirect?page=changes>
Changes: [bmahler] Optimized resources logging in master. ------------------------------------------ [...truncated 15.29 MB...] 3: I1122 21:51:08.135820 15992 leveldb.cpp:202] Seeked to beginning of db in 7814ns 3: I1122 21:51:08.135896 15992 leveldb.cpp:271] Iterated through 3 keys in the db in 66340ns 3: I1122 21:51:08.135936 15992 replica.cpp:779] Replica recovered with log positions 3 -> 4 with 0 holes and 0 unlearned 3: I1122 21:51:08.136298 16011 recover.cpp:451] Starting replica recovery 3: I1122 21:51:08.136497 16008 recover.cpp:477] Replica is in VOTING status 3: I1122 21:51:08.136658 16008 recover.cpp:466] Recover process terminated 3: I1122 21:51:08.138620 16012 master.cpp:448] Master 2a0a582c-e80c-45c8-a626-e94fb0e53007 (4e991857a158) started on 172.17.0.7:35299 3: I1122 21:51:08.138634 16012 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/WHndWI/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="replicated_log" --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/WHndWI/master" --zk_session_timeout="10secs" 3: I1122 21:51:08.138856 16012 master.cpp:499] Master only allowing authenticated frameworks to register 3: I1122 21:51:08.138862 16012 master.cpp:505] Master only allowing authenticated agents to register 3: I1122 21:51:08.138866 16012 master.cpp:511] Master only allowing authenticated HTTP frameworks to register 3: I1122 21:51:08.138870 16012 credentials.hpp:37] Loading credentials for authentication from '/tmp/WHndWI/credentials' 3: I1122 21:51:08.139086 16012 master.cpp:555] Using default 'crammd5' authenticator 3: I1122 21:51:08.139196 16012 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' 3: I1122 21:51:08.139308 16012 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' 3: I1122 21:51:08.139415 16012 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' 3: I1122 21:51:08.139511 16012 master.cpp:634] Authorization enabled 3: I1122 21:51:08.139622 16014 hierarchical.cpp:173] Initialized hierarchical allocator process 3: I1122 21:51:08.139655 16008 whitelist_watcher.cpp:77] No whitelist given 3: I1122 21:51:08.141793 15993 master.cpp:2215] Elected as the leading master! 3: I1122 21:51:08.141813 15993 master.cpp:1695] Recovering from registrar 3: I1122 21:51:08.141913 16013 registrar.cpp:347] Recovering registrar 3: I1122 21:51:08.142361 16005 log.cpp:536] Attempting to start the writer 3: I1122 21:51:08.143216 16008 replica.cpp:496] Replica received implicit promise request from __req_res__(1064)@172.17.0.7:35299 with proposal 2 3: I1122 21:51:08.144443 16008 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.203865ms 3: I1122 21:51:08.144465 16008 replica.cpp:344] Persisted promised to 2 3: I1122 21:51:08.144888 16015 coordinator.cpp:238] Coordinator attempting to fill missing positions 3: I1122 21:51:08.145133 15999 log.cpp:552] Writer started with ending position 4 3: I1122 21:51:08.146231 15994 leveldb.cpp:436] Reading position from leveldb took 36500ns 3: I1122 21:51:08.146298 15994 leveldb.cpp:436] Reading position from leveldb took 24113ns 3: I1122 21:51:08.147130 16006 registrar.cpp:391] Successfully fetched the registry (298B) in 5.178112ms 3: I1122 21:51:08.147236 16006 registrar.cpp:495] Applied 1 operations in 44405ns; attempting to update the registry 3: I1122 21:51:08.147737 16004 log.cpp:560] Attempting to append 337 bytes to the log 3: I1122 21:51:08.147825 15995 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 5 3: I1122 21:51:08.148342 16014 replica.cpp:540] Replica received write request for position 5 from __req_res__(1065)@172.17.0.7:35299 3: I1122 21:51:08.149195 16014 leveldb.cpp:341] Persisting action (356 bytes) to leveldb took 824701ns 3: I1122 21:51:08.149214 16014 replica.cpp:711] Persisted action APPEND at position 5 3: I1122 21:51:08.149638 15994 replica.cpp:694] Replica received learned notice for position 5 from log-network(58)@172.17.0.7:35299 3: I1122 21:51:08.150913 15994 leveldb.cpp:341] Persisting action (358 bytes) to leveldb took 1.253303ms 3: I1122 21:51:08.150935 15994 replica.cpp:711] Persisted action APPEND at position 5 3: I1122 21:51:08.151602 16006 registrar.cpp:552] Successfully updated the registry in 4.324864ms 3: I1122 21:51:08.151711 16006 registrar.cpp:424] Successfully recovered registrar 3: I1122 21:51:08.151736 16002 log.cpp:579] Attempting to truncate the log to 5 3: I1122 21:51:08.151824 16004 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 6 3: I1122 21:51:08.152216 15999 hierarchical.cpp:211] Skipping recovery of hierarchical allocator: nothing to recover 3: I1122 21:51:08.152215 16009 master.cpp:1808] Recovered 1 agents from the registry (298B); allowing 10mins for agents to re-register 3: I1122 21:51:08.152390 15998 replica.cpp:540] Replica received write request for position 6 from __req_res__(1066)@172.17.0.7:35299 3: I1122 21:51:08.153333 15998 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 910077ns 3: I1122 21:51:08.153357 15998 replica.cpp:711] Persisted action TRUNCATE at position 6 3: I1122 21:51:08.153794 16001 replica.cpp:694] Replica received learned notice for position 6 from log-network(58)@172.17.0.7:35299 3: I1122 21:51:08.154564 16001 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 750195ns 3: I1122 21:51:08.154613 16001 leveldb.cpp:399] Deleting ~2 keys from leveldb took 31598ns 3: I1122 21:51:08.154630 16001 replica.cpp:711] Persisted action TRUNCATE at position 6 3: W1122 21:51:08.155614 15992 process.cpp:2756] Attempted to spawn already running process [email protected]:35299 3: I1122 21:51:08.156347 15992 sched.cpp:232] Version: 1.5.0 3: I1122 21:51:08.156738 16016 sched.cpp:336] New master detected at [email protected]:35299 3: I1122 21:51:08.156814 16016 sched.cpp:396] Authenticating with master [email protected]:35299 3: I1122 21:51:08.156827 16016 sched.cpp:403] Using default CRAM-MD5 authenticatee 3: I1122 21:51:08.157002 15999 authenticatee.cpp:121] Creating new client SASL connection 3: I1122 21:51:08.157220 16014 master.cpp:8312] Authenticating [email protected]:35299 3: I1122 21:51:08.157300 15993 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(745)@172.17.0.7:35299 3: I1122 21:51:08.157490 16013 authenticator.cpp:98] Creating new server SASL connection 3: I1122 21:51:08.157690 15998 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1122 21:51:08.157707 15998 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1122 21:51:08.157819 16007 authenticator.cpp:204] Received SASL authentication start 3: I1122 21:51:08.157883 16007 authenticator.cpp:326] Authentication requires more steps 3: I1122 21:51:08.157968 15994 authenticatee.cpp:259] Received SASL authentication step 3: I1122 21:51:08.158120 15997 authenticator.cpp:232] Received SASL authentication step 3: I1122 21:51:08.158149 15997 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '4e991857a158' server FQDN: '4e991857a158' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1122 21:51:08.158164 15997 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1122 21:51:08.158197 15997 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1122 21:51:08.158229 15997 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '4e991857a158' server FQDN: '4e991857a158' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1122 21:51:08.158244 15997 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1122 21:51:08.158251 15997 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1122 21:51:08.158263 15997 authenticator.cpp:318] Authentication success 3: I1122 21:51:08.158335 16011 authenticatee.cpp:299] Authentication success 3: I1122 21:51:08.158396 16000 master.cpp:8342] Successfully authenticated principal 'test-principal' at [email protected]:35299 3: I1122 21:51:08.158453 16002 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(745)@172.17.0.7:35299 3: I1122 21:51:08.158566 16005 sched.cpp:502] Successfully authenticated with master [email protected]:35299 3: I1122 21:51:08.158582 16005 sched.cpp:824] Sending SUBSCRIBE call to [email protected]:35299 3: I1122 21:51:08.158674 16005 sched.cpp:857] Will retry registration in 1.930550429secs if necessary 3: I1122 21:51:08.158812 16008 master.cpp:2963] Received SUBSCRIBE call for framework 'default' at [email protected]:35299 3: I1122 21:51:08.158881 16008 master.cpp:2280] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }' 3: I1122 21:51:08.159234 16015 master.cpp:3043] Subscribing framework default with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT ] 3: I1122 21:51:08.159772 16003 sched.cpp:751] Framework registered with 2a0a582c-e80c-45c8-a626-e94fb0e53007-0000 3: I1122 21:51:08.159838 16003 sched.cpp:765] Scheduler::registered took 45086ns 3: I1122 21:51:08.159886 16012 hierarchical.cpp:306] Added framework 2a0a582c-e80c-45c8-a626-e94fb0e53007-0000 3: I1122 21:51:08.160079 16012 hierarchical.cpp:1457] Performed allocation for 0 agents in 81559ns 3: I1122 21:51:08.161619 16007 hierarchical.cpp:1457] Performed allocation for 0 agents in 43383ns 3: I1122 21:51:08.161727 16000 master.cpp:2002] Scheduling removal of agent dd07bfbd-0bdd-475a-9af8-269df4bc98bd-S0 (4e991857a158); did not re-register within 10mins after master failover 3: W1122 21:51:08.164067 15992 process.cpp:2756] Attempted to spawn already running process [email protected]:35299 3: I1122 21:51:08.164840 15992 containerizer.cpp:301] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } 3: W1122 21:51:08.165235 15992 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges 3: W1122 21:51:08.165341 15992 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges 3: I1122 21:51:08.165369 15992 provisioner.cpp:259] Using default backend 'copy' 3: I1122 21:51:08.167027 15992 cluster.cpp:448] Creating default 'local' authorizer 3: I1122 21:51:08.169004 16001 slave.cpp:262] Mesos agent started on (362)@172.17.0.7:35299 3: I1122 21:51:08.169018 16001 slave.cpp:263] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/MasterTest_CancelRecoveredSlaveRemoval_XQ26JS/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/MasterTest_CancelRecoveredSlaveRemoval_XQ26JS/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/MasterTest_CancelRecoveredSlaveRemoval_XQ26JS/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/MasterTest_CancelRecoveredSlaveRemoval_XQ26JS/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/MasterTest_CancelRecoveredSlaveRemoval_XQ26JS/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/MasterTest_CancelRecoveredSlaveRemoval_XQ26JS" --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/MasterTest_CancelRecoveredSlaveRemoval_U0I9Pi" --zk_session_timeout="10secs" 3: I1122 21:51:08.169344 16001 credentials.hpp:86] Loading credential for authentication from '/tmp/MasterTest_CancelRecoveredSlaveRemoval_XQ26JS/credential' 3: I1122 21:51:08.169474 16001 slave.cpp:295] Agent using credential for: test-principal 3: I1122 21:51:08.169490 16001 credentials.hpp:37] Loading credentials for authentication from '/tmp/MasterTest_CancelRecoveredSlaveRemoval_XQ26JS/http_credentials' 3: I1122 21:51:08.169679 16001 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' 3: I1122 21:51:08.169823 16001 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite' 3: I1122 21:51:08.171098 16001 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: I1122 21:51:08.171300 16001 slave.cpp:601] Agent attributes: [ ] 3: I1122 21:51:08.171310 16001 slave.cpp:610] Agent hostname: 4e991857a158 3: I1122 21:51:08.171425 16010 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I1122 21:51:08.172752 15999 state.cpp:64] Recovering state from '/tmp/MasterTest_CancelRecoveredSlaveRemoval_U0I9Pi/meta' 3: I1122 21:51:08.172803 15999 state.cpp:722] No committed checkpointed resources found at '/tmp/MasterTest_CancelRecoveredSlaveRemoval_U0I9Pi/meta/resources/resources.info' 3: I1122 21:51:08.173769 15994 task_status_update_manager.cpp:207] Recovering task status update manager 3: I1122 21:51:08.173960 15998 containerizer.cpp:668] Recovering containerizer 3: I1122 21:51:08.175216 16015 provisioner.cpp:455] Provisioner recovery complete 3: I1122 21:51:08.175477 16016 slave.cpp:6449] Finished recovery 3: I1122 21:51:08.176044 15999 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I1122 21:51:08.176055 16001 slave.cpp:1007] New master detected at [email protected]:35299 3: I1122 21:51:08.176129 16001 slave.cpp:1042] Detecting new master 3: I1122 21:51:08.177310 16012 slave.cpp:1069] Authenticating with master [email protected]:35299 3: I1122 21:51:08.177359 16012 slave.cpp:1078] Using default CRAM-MD5 authenticatee 3: I1122 21:51:08.177543 16013 authenticatee.cpp:121] Creating new client SASL connection 3: I1122 21:51:08.177757 15994 master.cpp:8312] Authenticating slave(362)@172.17.0.7:35299 3: I1122 21:51:08.177852 15997 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(746)@172.17.0.7:35299 3: I1122 21:51:08.178063 16006 authenticator.cpp:98] Creating new server SASL connection 3: I1122 21:51:08.178228 16000 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1122 21:51:08.178246 16000 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1122 21:51:08.178334 16011 authenticator.cpp:204] Received SASL authentication start 3: I1122 21:51:08.178375 16011 authenticator.cpp:326] Authentication requires more steps 3: I1122 21:51:08.178464 16007 authenticatee.cpp:259] Received SASL authentication step 3: I1122 21:51:08.178580 15995 authenticator.cpp:232] Received SASL authentication step 3: I1122 21:51:08.178602 15995 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '4e991857a158' server FQDN: '4e991857a158' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1122 21:51:08.178617 15995 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1122 21:51:08.178649 15995 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1122 21:51:08.178668 15995 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '4e991857a158' server FQDN: '4e991857a158' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1122 21:51:08.178681 15995 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1122 21:51:08.178688 15995 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1122 21:51:08.178705 15995 authenticator.cpp:318] Authentication success 3: I1122 21:51:08.178783 15996 authenticatee.cpp:299] Authentication success 3: I1122 21:51:08.178833 15998 master.cpp:8342] Successfully authenticated principal 'test-principal' at slave(362)@172.17.0.7:35299 3: I1122 21:51:08.178879 16004 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(746)@172.17.0.7:35299 3: I1122 21:51:08.179006 16002 slave.cpp:1161] Successfully authenticated with master [email protected]:35299 3: I1122 21:51:08.179184 16002 slave.cpp:1685] Will retry registration in 9.700009ms if necessary 3: I1122 21:51:08.179442 16003 master.cpp:6365] Received re-register agent message from agent dd07bfbd-0bdd-475a-9af8-269df4bc98bd-S0 at slave(362)@172.17.0.7:35299 (4e991857a158) 3: I1122 21:51:08.179592 16003 master.cpp:3872] Authorizing agent with principal 'test-principal' 3: I1122 21:51:08.179952 16009 master.cpp:6436] Authorized re-registration of agent dd07bfbd-0bdd-475a-9af8-269df4bc98bd-S0 at slave(362)@172.17.0.7:35299 (4e991857a158) 3: I1122 21:51:08.180009 16009 master.cpp:6618] Re-registering agent dd07bfbd-0bdd-475a-9af8-269df4bc98bd-S0 at slave(362)@172.17.0.7:35299 (4e991857a158) 3: I1122 21:51:08.180027 16009 master.cpp:6625] Re-admitting recovered agent dd07bfbd-0bdd-475a-9af8-269df4bc98bd-S0 at slave(362)@172.17.0.7:35299 (4e991857a158) 3: I1122 21:51:08.180042 16009 master.cpp:6690] Re-admitted agent dd07bfbd-0bdd-475a-9af8-269df4bc98bd-S0 at slave(362)@172.17.0.7:35299 (4e991857a158) 3: I1122 21:51:08.180630 16009 master.cpp:6873] Re-registered agent dd07bfbd-0bdd-475a-9af8-269df4bc98bd-S0 at slave(362)@172.17.0.7:35299 (4e991857a158) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] 3: I1122 21:51:08.180794 15999 slave.cpp:1343] Re-registered with master [email protected]:35299 3: I1122 21:51:08.180862 16012 task_status_update_manager.cpp:188] Resuming sending task status updates 3: I1122 21:51:08.180855 16001 hierarchical.cpp:600] Added agent dd07bfbd-0bdd-475a-9af8-269df4bc98bd-S0 (4e991857a158) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {}) 3: I1122 21:51:08.180886 15999 slave.cpp:1400] Forwarding total oversubscribed resources {} 3: I1122 21:51:08.181033 16013 master.cpp:7091] Received update of agent dd07bfbd-0bdd-475a-9af8-269df4bc98bd-S0 at slave(362)@172.17.0.7:35299 (4e991857a158) with total oversubscribed resources {} 3: I1122 21:51:08.181179 16013 master.cpp:7109] Ignoring update on agent dd07bfbd-0bdd-475a-9af8-269df4bc98bd-S0 at slave(362)@172.17.0.7:35299 (4e991857a158) as it reports no changes 3: I1122 21:51:08.181895 16001 hierarchical.cpp:1457] Performed allocation for 1 agents in 884125ns 3: I1122 21:51:08.182232 15994 master.cpp:8142] Sending 1 offers to framework 2a0a582c-e80c-45c8-a626-e94fb0e53007-0000 (default) at [email protected]:35299 3: I1122 21:51:08.182576 15997 sched.cpp:921] Scheduler::resourceOffers took 17626ns 3: I1122 21:51:08.182729 16006 master.cpp:2027] Canceling transition of agent dd07bfbd-0bdd-475a-9af8-269df4bc98bd-S0 (4e991857a158) to unreachable because it re-registered 3: I1122 21:51:08.182813 15992 sched.cpp:2009] Asked to stop the driver 3: I1122 21:51:08.182883 16000 sched.cpp:1191] Stopping framework 2a0a582c-e80c-45c8-a626-e94fb0e53007-0000 3: I1122 21:51:08.183071 16011 master.cpp:8819] Processing TEARDOWN call for framework 2a0a582c-e80c-45c8-a626-e94fb0e53007-0000 (default) at [email protected]:35299 3: I1122 21:51:08.183094 16011 master.cpp:8831] Removing framework 2a0a582c-e80c-45c8-a626-e94fb0e53007-0000 (default) at [email protected]:35299 3: I1122 21:51:08.183104 16011 master.cpp:3333] Deactivating framework 2a0a582c-e80c-45c8-a626-e94fb0e53007-0000 (default) at [email protected]:35299 3: I1122 21:51:08.183192 15996 hierarchical.cpp:419] Deactivated framework 2a0a582c-e80c-45c8-a626-e94fb0e53007-0000 3: I1122 21:51:08.183523 16011 master.cpp:10057] Removing offer 2a0a582c-e80c-45c8-a626-e94fb0e53007-O0 3: I1122 21:51:08.183679 16003 slave.cpp:3270] Asked to shut down framework 2a0a582c-e80c-45c8-a626-e94fb0e53007-0000 by [email protected]:35299 3: I1122 21:51:08.183708 16003 slave.cpp:3285] Cannot shut down unknown framework 2a0a582c-e80c-45c8-a626-e94fb0e53007-0000 3: I1122 21:51:08.183967 16008 hierarchical.cpp:1132] Recovered cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated: *):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: {}) on agent dd07bfbd-0bdd-475a-9af8-269df4bc98bd-S0 from framework 2a0a582c-e80c-45c8-a626-e94fb0e53007-0000 3: I1122 21:51:08.184195 16008 hierarchical.cpp:358] Removed framework 2a0a582c-e80c-45c8-a626-e94fb0e53007-0000 3: I1122 21:51:08.184356 16013 slave.cpp:883] Agent terminating 3: I1122 21:51:08.184507 15994 master.cpp:1311] Agent dd07bfbd-0bdd-475a-9af8-269df4bc98bd-S0 at slave(362)@172.17.0.7:35299 (4e991857a158) disconnected 3: I1122 21:51:08.184530 15994 master.cpp:3370] Disconnecting agent dd07bfbd-0bdd-475a-9af8-269df4bc98bd-S0 at slave(362)@172.17.0.7:35299 (4e991857a158) 3: I1122 21:51:08.184571 15994 master.cpp:3389] Deactivating agent dd07bfbd-0bdd-475a-9af8-269df4bc98bd-S0 at slave(362)@172.17.0.7:35299 (4e991857a158) 3: I1122 21:51:08.184634 16000 hierarchical.cpp:697] Agent dd07bfbd-0bdd-475a-9af8-269df4bc98bd-S0 deactivated 3: I1122 21:51:08.189196 15993 master.cpp:1153] Master terminating 3: I1122 21:51:08.189730 16014 hierarchical.cpp:633] Removed agent dd07bfbd-0bdd-475a-9af8-269df4bc98bd-S0 3: [ OK ] MasterTest.CancelRecoveredSlaveRemoval (140 ms) 3: [ RUN ] MasterTest.RecoveredSlaveReregisters 3: I1122 21:51:08.196454 15992 cluster.cpp:162] Creating default 'local' authorizer 3: I1122 21:51:08.198814 16008 master.cpp:448] Master 413121f0-d3b3-42c5-9570-5ccdc4624a26 (4e991857a158) started on 172.17.0.7:35299 3: I1122 21:51:08.198829 16008 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/yIQ2Uc/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/yIQ2Uc/master" --zk_session_timeout="10secs" 3: I1122 21:51:08.199048 16008 master.cpp:499] Master only allowing authenticated frameworks to register 3: I1122 21:51:08.199059 16008 master.cpp:505] Master only allowing authenticated agents to register 3: I1122 21:51:08.199061 16008 master.cpp:511] Master only allowing authenticated HTTP frameworks to register 3: I1122 21:51:08.199066 16008 credentials.hpp:37] Loading credentials for authentication from '/tmp/yIQ2Uc/credentials' 3: I1122 21:51:08.199280 16008 master.cpp:555] Using default 'crammd5' authenticator 3: I1122 21:51:08.199393 16008 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' 3: I1122 21:51:08.199506 16008 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' 3: I1122 21:51:08.199609 16008 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' 3: I1122 21:51:08.199712 16008 master.cpp:634] Authorization enabled 3: I1122 21:51:08.199815 15998 hierarchical.cpp:173] Initialized hierarchical allocator process 3: I1122 21:51:08.199852 16011 whitelist_watcher.cpp:77] No whitelist given 3: I1122 21:51:08.202116 16012 master.cpp:2215] Elected as the leading master! 3: I1122 21:51:08.202137 16012 master.cpp:1695] Recovering from registrar 3: I1122 21:51:08.202232 16010 registrar.cpp:347] Recovering registrar 3: I1122 21:51:08.202713 16010 registrar.cpp:391] Successfully fetched the registry (0B) in 450048ns 3: I1122 21:51:08.202801 16010 registrar.cpp:495] Applied 1 operations in 28381ns; attempting to update the registry 3: I1122 21:51:08.203230 16010 registrar.cpp:552] Successfully updated the registry in 389888ns 3: I1122 21:51:08.203328 16010 registrar.cpp:424] Successfully recovered registrar 3: I1122 21:51:08.203596 15994 master.cpp:1808] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register 3: I1122 21:51:08.203613 16007 hierarchical.cpp:211] Skipping recovery of hierarchical allocator: nothing to recover 3: W1122 21:51:08.207481 15992 process.cpp:2756] Attempted to spawn already running process [email protected]:35299 3: I1122 21:51:08.208225 15992 containerizer.cpp:301] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } 3: W1122 21:51:08.208654 15992 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges 3: W1122 21:51:08.208756 15992 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges 3: I1122 21:51:08.208784 15992 provisioner.cpp:259] Using default backend 'copy' 3: I1122 21:51:08.210300 15992 cluster.cpp:448] Creating default 'local' authorizer 3: I1122 21:51:08.212025 15994 slave.cpp:262] Mesos agent started on (363)@172.17.0.7:35299 3: I1122 21:51:08.212038 15994 slave.cpp:263] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/MasterTest_RecoveredSlaveReregisters_reqMhn/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/MasterTest_RecoveredSlaveReregisters_reqMhn/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/MasterTest_RecoveredSlaveReregisters_reqMhn/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/MasterTest_RecoveredSlaveReregisters_reqMhn/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/MasterTest_RecoveredSlaveReregisters_reqMhn/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/MasterTest_RecoveredSlaveReregisters_reqMhn" --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/MasterTest_RecoveredSlaveReregisters_SFbp6M" --zk_session_timeout="10secs" 3: I1122 21:51:08.212342 15994 credentials.hpp:86] Loading credential for authentication from '/tmp/MasterTest_RecoveredSlaveReregisters_reqMhn/credential' 3: I1122 21:51:08.212460 15994 slave.cpp:295] Agent using credential for: test-principal 3: I1122 21:51:08.212476 15994 credentials.hpp:37] Loading credentials for authentication from '/tmp/MasterTest_RecoveredSlaveReregisters_reqMhn/http_credentials' 3: I1122 21:51:08.212656 15994 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' 3: I1122 21:51:08.212771 15994 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite' 3: I1122 21:51:08.213979 15994 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: I1122 21:51:08.214179 15994 slave.cpp:601] Agent attributes: [ ] 3: I1122 21:51:08.214190 15994 slave.cpp:610] Agent hostname: 4e991857a158 3: I1122 21:51:08.214282 16016 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I1122 21:51:08.215473 15997 state.cpp:64] Recovering state from '/tmp/MasterTest_RecoveredSlaveReregisters_SFbp6M/meta' 3: I1122 21:51:08.215678 16013 task_status_update_manager.cpp:207] Recovering task status update manager 3: I1122 21:51:08.215842 15996 containerizer.cpp:668] Recovering containerizer 3: I1122 21:51:08.216872 16012 provisioner.cpp:455] Provisioner recovery complete 3: I1122 21:51:08.217089 16016 slave.cpp:6449] Finished recovery 3: I1122 21:51:08.217612 15994 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I1122 21:51:08.217622 16006 slave.cpp:1007] New master detected at [email protected]:35299 3: I1122 21:51:08.217694 16006 slave.cpp:1042] Detecting new master 3: I1122 21:51:08.221910 16000 slave.cpp:1069] Authenticating with master [email protected]:35299 3: I1122 21:51:08.221961 16000 slave.cpp:1078] Using default CRAM-MD5 authenticatee 3: I1122 21:51:08.222134 16010 authenticatee.cpp:121] Creating new client SASL connection 3: I1122 21:51:08.222347 16013 master.cpp:8312] Authenticating slave(363)@172.17.0.7:35299 3: I1122 21:51:08.222430 15995 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(747)@172.17.0.7:35299 3: I1122 21:51:08.222615 16002 authenticator.cpp:98] Creating new server SASL connection 3: I1122 21:51:08.222786 16007 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1122 21:51:08.222805 16007 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1122 21:51:08.222892 16015 authenticator.cpp:204] Received SASL authentication start 3: I1122 21:51:08.222939 16015 authenticator.cpp:326] Authentication requires more steps 3: I1122 21:51:08.223031 16005 authenticatee.cpp:259] Received SASL authentication step 3: I1122 21:51:08.223147 16003 authenticator.cpp:232] Received SASL authentication step 3: I1122 21:51:08.223170 16003 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '4e991857a158' server FQDN: '4e991857a158' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1122 21:51:08.223179 16003 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1122 21:51:08.223203 16003 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1122 21:51:08.223218 16003 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '4e991857a158' server FQDN: '4e991857a158' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1122 21:51:08.223227 16003 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1122 21:51:08.223232 16003 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1122 21:51:08.223242 16003 authenticator.cpp:318] Authentication success 3: I1122 21:51:08.223302 16011 authenticatee.cpp:299] Authentication success 3: I1122 21:51:08.223351 15996 master.cpp:8342] Successfully authenticated principal 'test-principal' at slave(363)@172.17.0.7:35299 3: I1122 21:51:08.223387 16004 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(747)@172.17.0.7:35299 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
