See <https://builds.apache.org/job/Mesos-Reviewbot/22273/display/redirect>
------------------------------------------ [...truncated 23.08 MB...] I0425 00:42:01.335551 5321 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0425 00:42:01.335741 5321 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0425 00:42:01.335825 5321 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '460e3269f71a' server FQDN: '460e3269f71a' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0425 00:42:01.335912 5321 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0425 00:42:01.336084 5321 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0425 00:42:01.336141 5321 authenticator.cpp:318] Authentication success I0425 00:42:01.336385 5320 authenticatee.cpp:299] Authentication success I0425 00:42:01.336632 5322 master.cpp:9324] Successfully authenticated principal 'test-principal' at slave(574)@172.17.0.2:42416 I0425 00:42:01.336829 5321 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1138)@172.17.0.2:42416 I0425 00:42:01.337182 5320 slave.cpp:1434] Successfully authenticated with master [email protected]:42416 I0425 00:42:01.337631 5320 slave.cpp:1877] Will retry registration in 6.381429ms if necessary I0425 00:42:01.337926 5322 master.cpp:6308] Received register agent message from slave(574)@172.17.0.2:42416 (460e3269f71a) I0425 00:42:01.338397 5322 master.cpp:3815] Authorizing agent providing resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal 'test-principal' I0425 00:42:01.339625 5316 master.cpp:6379] Authorized registration of agent at slave(574)@172.17.0.2:42416 (460e3269f71a) I0425 00:42:01.340055 5316 master.cpp:6494] Registering agent at slave(574)@172.17.0.2:42416 (460e3269f71a) with id 00b97720-da15-46bc-b467-dd58eb040d18-S0 I0425 00:42:01.340857 5321 registrar.cpp:487] Applied 1 operations in 205452ns; attempting to update the registry I0425 00:42:01.341989 5320 registrar.cpp:544] Successfully updated the registry in 1.028096ms I0425 00:42:01.342417 5319 master.cpp:6542] Admitted agent 00b97720-da15-46bc-b467-dd58eb040d18-S0 at slave(574)@172.17.0.2:42416 (460e3269f71a) I0425 00:42:01.343431 5319 master.cpp:6587] Registered agent 00b97720-da15-46bc-b467-dd58eb040d18-S0 at slave(574)@172.17.0.2:42416 (460e3269f71a) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0425 00:42:01.344040 5321 hierarchical.cpp:574] Added agent 00b97720-da15-46bc-b467-dd58eb040d18-S0 (460e3269f71a) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {}) I0425 00:42:01.343910 5316 slave.cpp:1481] Registered with master [email protected]:42416; given agent ID 00b97720-da15-46bc-b467-dd58eb040d18-S0 I0425 00:42:01.344579 5322 task_status_update_manager.cpp:188] Resuming sending task status updates I0425 00:42:01.344916 5316 slave.cpp:1501] Checkpointing SlaveInfo to '/tmp/SlaveTest_UnregisterThenUnreachableRace_FaBhXY/meta/slaves/00b97720-da15-46bc-b467-dd58eb040d18-S0/slave.info' I0425 00:42:01.345896 5316 slave.cpp:1548] Forwarding agent update {"operations":{},"resource_version_uuid":{"value":"JGMPB3RORz67UYQaZaZLyA=="},"slave_id":{"value":"00b97720-da15-46bc-b467-dd58eb040d18-S0"},"update_oversubscribed_resources":true} I0425 00:42:01.346390 5321 hierarchical.cpp:1517] Performed allocation for 1 agents in 1.800386ms I0425 00:42:01.346813 5316 master.cpp:7528] Received update of agent 00b97720-da15-46bc-b467-dd58eb040d18-S0 at slave(574)@172.17.0.2:42416 (460e3269f71a) with total oversubscribed resources {} I0425 00:42:01.347211 5316 master.cpp:7624] Ignoring update on agent 00b97720-da15-46bc-b467-dd58eb040d18-S0 at slave(574)@172.17.0.2:42416 (460e3269f71a) as it reports no changes I0425 00:42:01.347968 5316 master.cpp:9122] Sending 1 offers to framework 00b97720-da15-46bc-b467-dd58eb040d18-0000 (default) at [email protected]:42416 I0425 00:42:01.348839 5323 sched.cpp:919] Scheduler::resourceOffers took 151885ns I0425 00:42:01.354238 5318 master.cpp:10204] Removing agent 00b97720-da15-46bc-b467-dd58eb040d18-S0 at slave(574)@172.17.0.2:42416 (460e3269f71a): the agent unregistered I0425 00:42:01.357409 5323 hierarchical.cpp:1517] Performed allocation for 1 agents in 591248ns I0425 00:42:01.360162 5320 hierarchical.cpp:1517] Performed allocation for 1 agents in 466602ns I0425 00:42:01.362956 5323 hierarchical.cpp:1517] Performed allocation for 1 agents in 530998ns I0425 00:42:01.365262 5316 slave.cpp:6800] Current disk usage 14.56%. Max allowed age: 5.280723619460880days I0425 00:42:01.365830 5320 hierarchical.cpp:1517] Performed allocation for 1 agents in 653221ns W0425 00:42:01.368427 5322 master.cpp:8408] Skipping transition of agent 00b97720-da15-46bc-b467-dd58eb040d18-S0 (460e3269f71a) to unreachable because it is being removed I0425 00:42:01.368438 5318 hierarchical.cpp:1517] Performed allocation for 1 agents in 484835ns I0425 00:42:01.369360 5320 registrar.cpp:487] Applied 1 operations in 92968ns; attempting to update the registry I0425 00:42:01.370291 5320 registrar.cpp:544] Successfully updated the registry in 0ns I0425 00:42:01.370699 5319 master.cpp:10246] Removed agent 00b97720-da15-46bc-b467-dd58eb040d18-S0 at slave(574)@172.17.0.2:42416 (460e3269f71a): the agent unregistered I0425 00:42:01.371515 5319 master.cpp:11069] Removing offer 00b97720-da15-46bc-b467-dd58eb040d18-O0 I0425 00:42:01.371556 5322 hierarchical.cpp:609] Removed agent 00b97720-da15-46bc-b467-dd58eb040d18-S0 I0425 00:42:01.371660 5318 sched.cpp:945] Rescinded offer 00b97720-da15-46bc-b467-dd58eb040d18-O0 I0425 00:42:01.371860 5318 sched.cpp:956] Scheduler::offerRescinded took 23718ns I0425 00:42:01.372323 5319 master.cpp:2044] Notifying framework 00b97720-da15-46bc-b467-dd58eb040d18-0000 (default) at [email protected]:42416 of lost agent 00b97720-da15-46bc-b467-dd58eb040d18-S0 (460e3269f71a) I0425 00:42:01.372754 5319 sched.cpp:1089] Lost agent 00b97720-da15-46bc-b467-dd58eb040d18-S0 I0425 00:42:01.372979 5319 sched.cpp:1100] Scheduler::slaveLost took 93720ns I0425 00:42:01.373580 5315 sched.cpp:2007] Asked to stop the driver I0425 00:42:01.373852 5323 sched.cpp:1189] Stopping framework 00b97720-da15-46bc-b467-dd58eb040d18-0000 I0425 00:42:01.374392 5320 master.cpp:9817] Processing TEARDOWN call for framework 00b97720-da15-46bc-b467-dd58eb040d18-0000 (default) at [email protected]:42416 I0425 00:42:01.374449 5320 master.cpp:9829] Removing framework 00b97720-da15-46bc-b467-dd58eb040d18-0000 (default) at [email protected]:42416 I0425 00:42:01.374480 5320 master.cpp:3259] Deactivating framework 00b97720-da15-46bc-b467-dd58eb040d18-0000 (default) at [email protected]:42416 I0425 00:42:01.374830 5319 hierarchical.cpp:405] Deactivated framework 00b97720-da15-46bc-b467-dd58eb040d18-0000 I0425 00:42:01.375493 5321 hierarchical.cpp:344] Removed framework 00b97720-da15-46bc-b467-dd58eb040d18-0000 I0425 00:42:01.376431 5315 slave.cpp:919] Agent terminating I0425 00:42:01.394621 5315 master.cpp:1138] Master terminating [ OK ] SlaveTest.UnregisterThenUnreachableRace (126 ms) [ RUN ] SlaveTest.KillTaskBetweenRunTaskParts I0425 00:42:01.404479 5315 cluster.cpp:172] Creating default 'local' authorizer I0425 00:42:01.408032 5322 master.cpp:463] Master 131c1447-5056-4a03-8772-1bf430a55277 (460e3269f71a) started on 172.17.0.2:42416 I0425 00:42:01.408090 5322 master.cpp:466] 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/QwfD5Y/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" --memory_profiling="false" --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" --require_agent_domain="false" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/tmp/SRC/build/mesos-1.6.0/_inst/share/mesos/webui" --work_dir="/tmp/QwfD5Y/master" --zk_session_timeout="10secs" I0425 00:42:01.408563 5322 master.cpp:515] Master only allowing authenticated frameworks to register I0425 00:42:01.408592 5322 master.cpp:521] Master only allowing authenticated agents to register I0425 00:42:01.408610 5322 master.cpp:527] Master only allowing authenticated HTTP frameworks to register I0425 00:42:01.408663 5322 credentials.hpp:37] Loading credentials for authentication from '/tmp/QwfD5Y/credentials' I0425 00:42:01.409325 5322 master.cpp:571] Using default 'crammd5' authenticator I0425 00:42:01.409711 5322 http.cpp:959] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' I0425 00:42:01.410153 5322 http.cpp:959] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' I0425 00:42:01.410521 5322 http.cpp:959] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' I0425 00:42:01.410861 5322 master.cpp:652] Authorization enabled I0425 00:42:01.411309 5323 hierarchical.cpp:175] Initialized hierarchical allocator process I0425 00:42:01.411454 5323 whitelist_watcher.cpp:77] No whitelist given I0425 00:42:01.415055 5323 master.cpp:2127] Elected as the leading master! I0425 00:42:01.415102 5323 master.cpp:1683] Recovering from registrar I0425 00:42:01.415583 5323 registrar.cpp:339] Recovering registrar I0425 00:42:01.416661 5323 registrar.cpp:383] Successfully fetched the registry (0B) in 1.020928ms I0425 00:42:01.416822 5323 registrar.cpp:487] Applied 1 operations in 42549ns; attempting to update the registry I0425 00:42:01.417625 5323 registrar.cpp:544] Successfully updated the registry in 696320ns I0425 00:42:01.417798 5323 registrar.cpp:416] Successfully recovered registrar I0425 00:42:01.418468 5323 master.cpp:1797] Recovered 0 agents from the registry (135B); allowing 10mins for agents to reregister I0425 00:42:01.418578 5316 hierarchical.cpp:213] Skipping recovery of hierarchical allocator: nothing to recover W0425 00:42:01.424293 5315 process.cpp:2821] Attempted to spawn already running process [email protected]:42416 I0425 00:42:01.424829 5315 cluster.cpp:460] Creating default 'local' authorizer I0425 00:42:01.428056 5319 slave.cpp:261] Mesos agent started on (575)@172.17.0.2:42416 I0425 00:42:01.428105 5319 slave.cpp:262] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/SlaveTest_KillTaskBetweenRunTaskParts_8TIxyZ/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="false" --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/SlaveTest_KillTaskBetweenRunTaskParts_8TIxyZ/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/SlaveTest_KillTaskBetweenRunTaskParts_8TIxyZ/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/SlaveTest_KillTaskBetweenRunTaskParts_8TIxyZ/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_command_executor="false" --http_credentials="/tmp/SlaveTest_KillTaskBetweenRunTaskParts_8TIxyZ/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/tmp/SRC/build/mesos-1.6.0/_build/sub/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --memory_profiling="false" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --reconfiguration_policy="equal" --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/SlaveTest_KillTaskBetweenRunTaskParts_8TIxyZ" --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/SlaveTest_KillTaskBetweenRunTaskParts_em04ju" --zk_session_timeout="10secs" I0425 00:42:01.428599 5319 credentials.hpp:86] Loading credential for authentication from '/tmp/SlaveTest_KillTaskBetweenRunTaskParts_8TIxyZ/credential' W0425 00:42:01.428609 5315 process.cpp:2821] Attempted to spawn already running process [email protected]:42416 I0425 00:42:01.429008 5319 slave.cpp:294] Agent using credential for: test-principal I0425 00:42:01.429056 5319 credentials.hpp:37] Loading credentials for authentication from '/tmp/SlaveTest_KillTaskBetweenRunTaskParts_8TIxyZ/http_credentials' I0425 00:42:01.429507 5319 http.cpp:959] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' I0425 00:42:01.430184 5315 sched.cpp:232] Version: 1.6.0 I0425 00:42:01.430188 5319 disk_profile_adaptor.cpp:80] Creating default disk profile adaptor module I0425 00:42:01.431826 5319 slave.cpp:609] 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"}] I0425 00:42:01.432070 5319 slave.cpp:617] Agent attributes: [ ] I0425 00:42:01.432101 5319 slave.cpp:626] Agent hostname: 460e3269f71a I0425 00:42:01.433281 5321 task_status_update_manager.cpp:181] Pausing sending task status updates I0425 00:42:01.433354 5317 sched.cpp:336] New master detected at [email protected]:42416 I0425 00:42:01.433912 5317 sched.cpp:396] Authenticating with master [email protected]:42416 I0425 00:42:01.433954 5317 sched.cpp:403] Using default CRAM-MD5 authenticatee I0425 00:42:01.434612 5317 authenticatee.cpp:121] Creating new client SASL connection I0425 00:42:01.435070 5320 master.cpp:9294] Authenticating [email protected]:42416 I0425 00:42:01.435413 5323 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1139)@172.17.0.2:42416 I0425 00:42:01.435823 5316 authenticator.cpp:98] Creating new server SASL connection I0425 00:42:01.436254 5316 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0425 00:42:01.436298 5316 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0425 00:42:01.436597 5316 authenticator.cpp:204] Received SASL authentication start I0425 00:42:01.436772 5316 authenticator.cpp:326] Authentication requires more steps I0425 00:42:01.437069 5316 authenticatee.cpp:259] Received SASL authentication step I0425 00:42:01.437355 5321 state.cpp:66] Recovering state from '/tmp/SlaveTest_KillTaskBetweenRunTaskParts_em04ju/meta' I0425 00:42:01.437367 5317 authenticator.cpp:232] Received SASL authentication step I0425 00:42:01.437532 5317 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '460e3269f71a' server FQDN: '460e3269f71a' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0425 00:42:01.437563 5317 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0425 00:42:01.437630 5317 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0425 00:42:01.437669 5317 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '460e3269f71a' server FQDN: '460e3269f71a' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0425 00:42:01.437692 5317 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0425 00:42:01.437713 5317 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0425 00:42:01.437764 5317 authenticator.cpp:318] Authentication success I0425 00:42:01.438236 5322 authenticatee.cpp:299] Authentication success I0425 00:42:01.438447 5320 master.cpp:9324] Successfully authenticated principal 'test-principal' at [email protected]:42416 I0425 00:42:01.438534 5322 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1139)@172.17.0.2:42416 I0425 00:42:01.438889 5316 task_status_update_manager.cpp:207] Recovering task status update manager I0425 00:42:01.442389 5320 slave.cpp:7262] Finished recovery I0425 00:42:01.442446 5317 sched.cpp:501] Successfully authenticated with master [email protected]:42416 I0425 00:42:01.442487 5317 sched.cpp:822] Sending SUBSCRIBE call to [email protected]:42416 I0425 00:42:01.442730 5317 sched.cpp:855] Will retry registration in 266.829026ms if necessary I0425 00:42:01.442926 5322 master.cpp:2883] Received SUBSCRIBE call for framework 'default' at [email protected]:42416 I0425 00:42:01.443110 5322 master.cpp:2199] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }' I0425 00:42:01.443780 5322 task_status_update_manager.cpp:181] Pausing sending task status updates I0425 00:42:01.443847 5320 slave.cpp:1260] New master detected at [email protected]:42416 I0425 00:42:01.444006 5320 slave.cpp:1315] Detecting new master I0425 00:42:01.444164 5317 master.cpp:2964] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ] I0425 00:42:01.444481 5317 master.cpp:9515] Adding framework 131c1447-5056-4a03-8772-1bf430a55277-0000 (default) at [email protected]:42416 with roles { } suppressed I0425 00:42:01.445333 5317 sched.cpp:749] Framework registered with 131c1447-5056-4a03-8772-1bf430a55277-0000 I0425 00:42:01.445425 5317 sched.cpp:763] Scheduler::registered took 39509ns I0425 00:42:01.445335 5323 hierarchical.cpp:297] Added framework 131c1447-5056-4a03-8772-1bf430a55277-0000 I0425 00:42:01.445938 5323 hierarchical.cpp:1517] Performed allocation for 0 agents in 98035ns I0425 00:42:01.452069 5320 slave.cpp:1342] Authenticating with master [email protected]:42416 I0425 00:42:01.452240 5320 slave.cpp:1351] Using default CRAM-MD5 authenticatee I0425 00:42:01.452806 5322 authenticatee.cpp:121] Creating new client SASL connection I0425 00:42:01.453197 5322 master.cpp:9294] Authenticating slave(575)@172.17.0.2:42416 I0425 00:42:01.453469 5317 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1140)@172.17.0.2:42416 I0425 00:42:01.453934 5323 authenticator.cpp:98] Creating new server SASL connection I0425 00:42:01.454365 5323 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0425 00:42:01.454404 5323 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0425 00:42:01.454529 5323 authenticator.cpp:204] Received SASL authentication start I0425 00:42:01.454687 5323 authenticator.cpp:326] Authentication requires more steps I0425 00:42:01.455047 5321 authenticatee.cpp:259] Received SASL authentication step I0425 00:42:01.455416 5320 authenticator.cpp:232] Received SASL authentication step I0425 00:42:01.455474 5320 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '460e3269f71a' server FQDN: '460e3269f71a' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0425 00:42:01.455505 5320 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0425 00:42:01.455564 5320 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0425 00:42:01.455615 5320 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '460e3269f71a' server FQDN: '460e3269f71a' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0425 00:42:01.455646 5320 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0425 00:42:01.455670 5320 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0425 00:42:01.455705 5320 authenticator.cpp:318] Authentication success I0425 00:42:01.455930 5322 authenticatee.cpp:299] Authentication success I0425 00:42:01.456034 5317 master.cpp:9324] Successfully authenticated principal 'test-principal' at slave(575)@172.17.0.2:42416 I0425 00:42:01.456231 5320 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1140)@172.17.0.2:42416 I0425 00:42:01.456619 5322 slave.cpp:1434] Successfully authenticated with master [email protected]:42416 I0425 00:42:01.457120 5322 slave.cpp:1877] Will retry registration in 17.320985ms if necessary I0425 00:42:01.457545 5319 master.cpp:6308] Received register agent message from slave(575)@172.17.0.2:42416 (460e3269f71a) I0425 00:42:01.458003 5319 master.cpp:3815] Authorizing agent providing resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal 'test-principal' I0425 00:42:01.459046 5321 master.cpp:6379] Authorized registration of agent at slave(575)@172.17.0.2:42416 (460e3269f71a) I0425 00:42:01.459362 5321 master.cpp:6494] Registering agent at slave(575)@172.17.0.2:42416 (460e3269f71a) with id 131c1447-5056-4a03-8772-1bf430a55277-S0 I0425 00:42:01.460422 5318 registrar.cpp:487] Applied 1 operations in 306948ns; attempting to update the registry I0425 00:42:01.461328 5318 registrar.cpp:544] Successfully updated the registry in 777984ns I0425 00:42:01.461685 5317 master.cpp:6542] Admitted agent 131c1447-5056-4a03-8772-1bf430a55277-S0 at slave(575)@172.17.0.2:42416 (460e3269f71a) I0425 00:42:01.462519 5317 master.cpp:6587] Registered agent 131c1447-5056-4a03-8772-1bf430a55277-S0 at slave(575)@172.17.0.2:42416 (460e3269f71a) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0425 00:42:01.462685 5317 slave.cpp:1481] Registered with master [email protected]:42416; given agent ID 131c1447-5056-4a03-8772-1bf430a55277-S0 I0425 00:42:01.463644 5323 hierarchical.cpp:574] Added agent 131c1447-5056-4a03-8772-1bf430a55277-S0 (460e3269f71a) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {}) I0425 00:42:01.463788 5317 slave.cpp:1501] Checkpointing SlaveInfo to '/tmp/SlaveTest_KillTaskBetweenRunTaskParts_em04ju/meta/slaves/131c1447-5056-4a03-8772-1bf430a55277-S0/slave.info' I0425 00:42:01.463798 5322 task_status_update_manager.cpp:188] Resuming sending task status updates I0425 00:42:01.464691 5317 slave.cpp:1548] Forwarding agent update {"operations":{},"resource_version_uuid":{"value":"qiYEndbYTdSvP7T7nXlfZQ=="},"slave_id":{"value":"131c1447-5056-4a03-8772-1bf430a55277-S0"},"update_oversubscribed_resources":true} I0425 00:42:01.465415 5316 master.cpp:7528] Received update of agent 131c1447-5056-4a03-8772-1bf430a55277-S0 at slave(575)@172.17.0.2:42416 (460e3269f71a) with total oversubscribed resources {} I0425 00:42:01.465802 5316 master.cpp:7624] Ignoring update on agent 131c1447-5056-4a03-8772-1bf430a55277-S0 at slave(575)@172.17.0.2:42416 (460e3269f71a) as it reports no changes I0425 00:42:01.466683 5323 hierarchical.cpp:1517] Performed allocation for 1 agents in 2.733148ms I0425 00:42:01.467550 5321 master.cpp:9122] Sending 1 offers to framework 131c1447-5056-4a03-8772-1bf430a55277-0000 (default) at [email protected]:42416 I0425 00:42:01.468354 5320 sched.cpp:919] Scheduler::resourceOffers took 167059ns I0425 00:42:01.470528 5317 master.cpp:11069] Removing offer 131c1447-5056-4a03-8772-1bf430a55277-O0 I0425 00:42:01.471072 5317 master.cpp:4304] Processing ACCEPT call for offers: [ 131c1447-5056-4a03-8772-1bf430a55277-O0 ] on agent 131c1447-5056-4a03-8772-1bf430a55277-S0 at slave(575)@172.17.0.2:42416 (460e3269f71a) for framework 131c1447-5056-4a03-8772-1bf430a55277-0000 (default) at [email protected]:42416 I0425 00:42:01.471216 5317 master.cpp:3527] Authorizing framework principal 'test-principal' to launch task 1 W0425 00:42:01.473218 5319 validation.cpp:1404] Executor 'default' for task '1' uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases. W0425 00:42:01.473268 5319 validation.cpp:1416] Executor 'default' for task '1' uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases. I0425 00:42:01.474037 5319 master.cpp:11789] Adding task 1 with resources cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated: *):[31000-32000] on agent 131c1447-5056-4a03-8772-1bf430a55277-S0 at slave(575)@172.17.0.2:42416 (460e3269f71a) I0425 00:42:01.474714 5319 master.cpp:5077] Launching task 1 of framework 131c1447-5056-4a03-8772-1bf430a55277-0000 (default) at [email protected]:42416 with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] on agent 131c1447-5056-4a03-8772-1bf430a55277-S0 at slave(575)@172.17.0.2:42416 (460e3269f71a) on new executor I0425 00:42:01.478653 5316 slave.cpp:2014] Got assigned task '1' for framework 131c1447-5056-4a03-8772-1bf430a55277-0000 I0425 00:42:01.482880 5318 master.cpp:5736] Processing KILL call for task '1' of framework 131c1447-5056-4a03-8772-1bf430a55277-0000 (default) at [email protected]:42416 I0425 00:42:01.483633 5318 master.cpp:5814] Telling agent 131c1447-5056-4a03-8772-1bf430a55277-S0 at slave(575)@172.17.0.2:42416 (460e3269f71a) to kill task 1 of framework 131c1447-5056-4a03-8772-1bf430a55277-0000 (default) at [email protected]:42416 I0425 00:42:01.484405 5316 slave.cpp:3613] Asked to kill task 1 of framework 131c1447-5056-4a03-8772-1bf430a55277-0000 W0425 00:42:01.484505 5316 slave.cpp:3656] Killing task 1 of framework 131c1447-5056-4a03-8772-1bf430a55277-0000 before it was launched I0425 00:42:01.484741 5316 slave.cpp:5243] Handling status update TASK_KILLED (Status UUID: 1537751c-4ff5-4828-a79b-a05d494859b0) for task 1 of framework 131c1447-5056-4a03-8772-1bf430a55277-0000 from @0.0.0.0:0 I0425 00:42:01.484967 5316 slave.cpp:6492] Cleaning up framework 131c1447-5056-4a03-8772-1bf430a55277-0000 E0425 00:42:01.485196 5316 slave.cpp:7432] Failed to find the mtime of '/tmp/SlaveTest_KillTaskBetweenRunTaskParts_em04ju/slaves/131c1447-5056-4a03-8772-1bf430a55277-S0/frameworks/131c1447-5056-4a03-8772-1bf430a55277-0000': Failed to stat '/tmp/SlaveTest_KillTaskBetweenRunTaskParts_em04ju/slaves/131c1447-5056-4a03-8772-1bf430a55277-S0/frameworks/131c1447-5056-4a03-8772-1bf430a55277-0000': No such file or directory W0425 00:42:01.485477 5316 slave.cpp:5358] Could not find the executor for status update TASK_KILLED (Status UUID: 1537751c-4ff5-4828-a79b-a05d494859b0) for task 1 of framework 131c1447-5056-4a03-8772-1bf430a55277-0000 I0425 00:42:01.485857 5316 task_status_update_manager.cpp:289] Closing task status update streams for framework 131c1447-5056-4a03-8772-1bf430a55277-0000 I0425 00:42:01.485985 5316 task_status_update_manager.cpp:328] Received task status update TASK_KILLED (Status UUID: 1537751c-4ff5-4828-a79b-a05d494859b0) for task 1 of framework 131c1447-5056-4a03-8772-1bf430a55277-0000 I0425 00:42:01.486068 5316 task_status_update_manager.cpp:507] Creating StatusUpdate stream for task 1 of framework 131c1447-5056-4a03-8772-1bf430a55277-0000 I0425 00:42:01.486905 5316 task_status_update_manager.cpp:383] Forwarding task status update TASK_KILLED (Status UUID: 1537751c-4ff5-4828-a79b-a05d494859b0) for task 1 of framework 131c1447-5056-4a03-8772-1bf430a55277-0000 to the agent I0425 00:42:01.487637 5318 slave.cpp:5735] Forwarding the update TASK_KILLED (Status UUID: 1537751c-4ff5-4828-a79b-a05d494859b0) for task 1 of framework 131c1447-5056-4a03-8772-1bf430a55277-0000 to [email protected]:42416 I0425 00:42:01.488049 5316 task_status_update_manager.cpp:328] Received task status update TASK_KILLED (Status UUID: 1537751c-4ff5-4828-a79b-a05d494859b0) for task 1 of framework 131c1447-5056-4a03-8772-1bf430a55277-0000 W0425 00:42:01.488829 5316 task_status_update_manager.cpp:746] Ignoring duplicate task status update TASK_KILLED (Status UUID: 1537751c-4ff5-4828-a79b-a05d494859b0) for task 1 of framework 131c1447-5056-4a03-8772-1bf430a55277-0000 I0425 00:42:01.489696 5322 master.cpp:8060] Status update TASK_KILLED (Status UUID: 1537751c-4ff5-4828-a79b-a05d494859b0) for task 1 of framework 131c1447-5056-4a03-8772-1bf430a55277-0000 from agent 131c1447-5056-4a03-8772-1bf430a55277-S0 at slave(575)@172.17.0.2:42416 (460e3269f71a) I0425 00:42:01.489768 5322 master.cpp:8117] Forwarding status update TASK_KILLED (Status UUID: 1537751c-4ff5-4828-a79b-a05d494859b0) for task 1 of framework 131c1447-5056-4a03-8772-1bf430a55277-0000 I0425 00:42:01.490126 5322 master.cpp:10547] Updating the state of task 1 of framework 131c1447-5056-4a03-8772-1bf430a55277-0000 (latest state: TASK_KILLED, status update state: TASK_KILLED) I0425 00:42:01.490674 5320 sched.cpp:1027] Scheduler::statusUpdate took 103989ns W0425 00:42:01.491082 5318 slave.cpp:2327] Ignoring running task '1' because the framework 131c1447-5056-4a03-8772-1bf430a55277-0000 does not exist I0425 00:42:01.491590 5315 sched.cpp:2007] Asked to stop the driver I0425 00:42:01.491801 5322 master.cpp:5940] Processing ACKNOWLEDGE call for status 1537751c-4ff5-4828-a79b-a05d494859b0 for task 1 of framework 131c1447-5056-4a03-8772-1bf430a55277-0000 (default) at [email protected]:42416 on agent 131c1447-5056-4a03-8772-1bf430a55277-S0 I0425 00:42:01.491631 5323 hierarchical.cpp:1192] 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 131c1447-5056-4a03-8772-1bf430a55277-S0 from framework 131c1447-5056-4a03-8772-1bf430a55277-0000 I0425 00:42:01.492066 5319 sched.cpp:1189] Stopping framework 131c1447-5056-4a03-8772-1bf430a55277-0000 I0425 00:42:01.492144 5322 master.cpp:10646] Removing task 1 with resources cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated: *):[31000-32000] of framework 131c1447-5056-4a03-8772-1bf430a55277-0000 on agent 131c1447-5056-4a03-8772-1bf430a55277-S0 at slave(575)@172.17.0.2:42416 (460e3269f71a) I0425 00:42:01.492615 5322 master.cpp:9817] Processing TEARDOWN call for framework 131c1447-5056-4a03-8772-1bf430a55277-0000 (default) at [email protected]:42416 I0425 00:42:01.492661 5322 master.cpp:9829] Removing framework 131c1447-5056-4a03-8772-1bf430a55277-0000 (default) at [email protected]:42416 I0425 00:42:01.492689 5322 master.cpp:3259] Deactivating framework 131c1447-5056-4a03-8772-1bf430a55277-0000 (default) at [email protected]:42416 I0425 00:42:01.492969 5317 hierarchical.cpp:405] Deactivated framework 131c1447-5056-4a03-8772-1bf430a55277-0000 I0425 00:42:01.493283 5322 master.cpp:10675] Removing executor 'default' with resources [] of framework 131c1447-5056-4a03-8772-1bf430a55277-0000 on agent 131c1447-5056-4a03-8772-1bf430a55277-S0 at slave(575)@172.17.0.2:42416 (460e3269f71a) I0425 00:42:01.495280 5323 hierarchical.cpp:344] Removed framework 131c1447-5056-4a03-8772-1bf430a55277-0000 I0425 00:42:01.496100 5322 master.cpp:1138] Master terminating E0425 00:42:01.496959 5318 process.cpp:3960] **** DEADLOCK DETECTED! **** You are waiting on process slave(575)@172.17.0.2:42416 that it is currently executing. I0425 00:42:01.497347 5323 hierarchical.cpp:609] Removed agent 131c1447-5056-4a03-8772-1bf430a55277-S0 [ OK ] SlaveTest.KillTaskBetweenRunTaskParts (102 ms) [ RUN ] SlaveTest.KillMultiplePendingTasks I0425 00:42:01.507256 5315 cluster.cpp:172] Creating default 'local' authorizer I0425 00:42:01.510188 5320 master.cpp:463] Master 51cb8f07-fb33-4d45-8445-ded6da835d11 (460e3269f71a) started on 172.17.0.2:42416 I0425 00:42:01.510244 5320 master.cpp:466] 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/RT2CCv/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" --memory_profiling="false" --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" --require_agent_domain="false" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/tmp/SRC/build/mesos-1.6.0/_inst/share/mesos/webui" --work_dir="/tmp/RT2CCv/master" --zk_session_timeout="10secs" I0425 00:42:01.510794 5320 master.cpp:515] Master only allowing authenticated frameworks to register I0425 00:42:01.510885 5320 master.cpp:521] Master only allowing authenticated agents to register I0425 00:42:01.510934 5320 master.cpp:527] Master only allowing authenticated HTTP frameworks to register I0425 00:42:01.510984 5320 credentials.hpp:37] Loading credentials for authentication from '/tmp/RT2CCv/credentials' I0425 00:42:01.511365 5320 master.cpp:571] Using default 'crammd5' authenticator I0425 00:42:01.511696 5320 http.cpp:959] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' I0425 00:42:01.512078 5320 http.cpp:959] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' I0425 00:42:01.512384 5320 http.cpp:959] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' I0425 00:42:01.512744 5320 master.cpp:652] Authorization enabled I0425 00:42:01.513059 5317 hierarchical.cpp:175] Initialized hierarchical allocator process I0425 00:42:01.513077 5322 whitelist_watcher.cpp:77] No whitelist given I0425 00:42:01.517086 5321 master.cpp:2127] Elected as the leading master! I0425 00:42:01.517280 5321 master.cpp:1683] Recovering from registrar I0425 00:42:01.517856 5320 registrar.cpp:339] Recovering registrar I0425 00:42:01.518936 5320 registrar.cpp:383] Successfully fetched the registry (0B) in 990208ns I0425 00:42:01.519225 5320 registrar.cpp:487] Applied 1 operations in 36388ns; attempting to update the registry I0425 00:42:01.520373 5317 registrar.cpp:544] Successfully updated the registry in 983040ns I0425 00:42:01.520643 5317 registrar.cpp:416] Successfully recovered registrar I0425 00:42:01.522246 5321 hierarchical.cpp:213] Skipping recovery of hierarchical allocator: nothing to recover I0425 00:42:01.522737 5316 master.cpp:1797] Recovered 0 agents from the registry (135B); allowing 10mins for agents to reregister Build timed out (after 180 minutes). Marking the build as failed. Build was aborted
