See <https://builds.apache.org/job/Mesos-Buildbot/BUILDTOOL=cmake,COMPILER=gcc,CONFIGURATION=--verbose%20--disable-libtool-wrappers%20--enable-libevent%20--enable-ssl,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=centos%3A7,label_exp=(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23)/4473/display/redirect?page=changes>
Changes: [bmahler] Added a Future constructor for Try<Future<T>>. ------------------------------------------ [...truncated 26.27 MB...] 3: I1120 01:14:38.734169 17518 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1120 01:14:38.734199 17518 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1120 01:14:38.734334 17517 authenticator.cpp:204] Received SASL authentication start 3: I1120 01:14:38.734395 17517 authenticator.cpp:326] Authentication requires more steps 3: I1120 01:14:38.734515 17523 authenticatee.cpp:259] Received SASL authentication step 3: I1120 01:14:38.734669 17512 authenticator.cpp:232] Received SASL authentication step 3: I1120 01:14:38.734714 17512 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '6c3408add39c' server FQDN: '6c3408add39c' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1120 01:14:38.734733 17512 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1120 01:14:38.734771 17512 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1120 01:14:38.734800 17512 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '6c3408add39c' server FQDN: '6c3408add39c' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1120 01:14:38.734817 17512 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1120 01:14:38.734828 17512 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1120 01:14:38.734849 17512 authenticator.cpp:318] Authentication success 3: I1120 01:14:38.734941 17519 authenticatee.cpp:299] Authentication success 3: I1120 01:14:38.735072 17511 master.cpp:8315] Successfully authenticated principal 'test-principal' at slave(688)@172.17.0.2:45437 3: I1120 01:14:38.735162 17519 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1336)@172.17.0.2:45437 3: I1120 01:14:38.735285 17514 slave.cpp:1161] Successfully authenticated with master master@172.17.0.2:45437 3: I1120 01:14:38.735484 17514 slave.cpp:1682] Will retry registration in 5.026273ms if necessary 3: I1120 01:14:38.735685 17516 master.cpp:6032] Received register agent message from slave(688)@172.17.0.2:45437 (6c3408add39c) 3: I1120 01:14:38.735807 17516 master.cpp:3870] Authorizing agent with principal 'test-principal' 3: I1120 01:14:38.736238 17515 master.cpp:6092] Authorized registration of agent at slave(688)@172.17.0.2:45437 (6c3408add39c) 3: I1120 01:14:38.736351 17515 master.cpp:6185] Registering agent at slave(688)@172.17.0.2:45437 (6c3408add39c) with id 4d448e15-f8cf-4e33-98b2-12bef7d28b78-S0 3: I1120 01:14:38.736855 17522 registrar.cpp:495] Applied 1 operations in 62541ns; attempting to update the registry 3: I1120 01:14:38.737457 17522 registrar.cpp:552] Successfully updated the registry in 537856ns 3: I1120 01:14:38.737697 17513 master.cpp:6232] Admitted agent 4d448e15-f8cf-4e33-98b2-12bef7d28b78-S0 at slave(688)@172.17.0.2:45437 (6c3408add39c) 3: I1120 01:14:38.738541 17508 slave.cpp:1207] Registered with master master@172.17.0.2:45437; given agent ID 4d448e15-f8cf-4e33-98b2-12bef7d28b78-S0 3: I1120 01:14:38.738651 17519 status_update_manager.cpp:184] Resuming sending status updates 3: I1120 01:14:38.738389 17513 master.cpp:6263] Registered agent 4d448e15-f8cf-4e33-98b2-12bef7d28b78-S0 at slave(688)@172.17.0.2:45437 (6c3408add39c) with [{"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: I1120 01:14:38.738818 17511 hierarchical.cpp:600] Added agent 4d448e15-f8cf-4e33-98b2-12bef7d28b78-S0 (6c3408add39c) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {}) 3: I1120 01:14:38.738898 17508 slave.cpp:1227] Checkpointing SlaveInfo to '/tmp/ContentType_MasterAPITest_ReserveResources_1_IfoQje/meta/slaves/4d448e15-f8cf-4e33-98b2-12bef7d28b78-S0/slave.info' 3: I1120 01:14:38.739346 17508 slave.cpp:1295] Forwarding total oversubscribed resources {} 3: I1120 01:14:38.739555 17508 master.cpp:7064] Received update of agent 4d448e15-f8cf-4e33-98b2-12bef7d28b78-S0 at slave(688)@172.17.0.2:45437 (6c3408add39c) with total oversubscribed resources {} 3: I1120 01:14:38.739742 17508 master.cpp:7082] Ignoring update on agent 4d448e15-f8cf-4e33-98b2-12bef7d28b78-S0 at slave(688)@172.17.0.2:45437 (6c3408add39c) as it reports no changes 3: I1120 01:14:38.740419 17511 hierarchical.cpp:1457] Performed allocation for 1 agents in 1.393359ms 3: I1120 01:14:38.740973 17516 master.cpp:8115] Sending 1 offers to framework 4d448e15-f8cf-4e33-98b2-12bef7d28b78-0000 (default) at scheduler-210762e9-9890-48bf-b101-62c506898e73@172.17.0.2:45437 3: I1120 01:14:38.741552 17521 sched.cpp:921] Scheduler::resourceOffers took 118359ns 3: I1120 01:14:38.744834 17519 process.cpp:3932] Handling HTTP event for process 'master' with path: '/master/api/v1' 3: I1120 01:14:38.746502 17518 http.cpp:1185] HTTP POST for /master/api/v1 from 172.17.0.2:34785 3: I1120 01:14:38.747292 17518 http.cpp:673] Processing call RESERVE_RESOURCES 3: I1120 01:14:38.747627 17518 master.cpp:3655] Authorizing principal 'test-principal' to reserve resources '[{"name":"cpus","reservations":[{"principal":"test-principal","role":"role","type":"DYNAMIC"}],"scalar":{"value":1.0},"type":"SCALAR"},{"name":"mem","reservations":[{"principal":"test-principal","role":"role","type":"DYNAMIC"}],"scalar":{"value":512.0},"type":"SCALAR"}]' 3: I1120 01:14:38.749274 17523 master.cpp:10024] Removing offer 4d448e15-f8cf-4e33-98b2-12bef7d28b78-O0 3: I1120 01:14:38.749454 17510 sched.cpp:947] Rescinded offer 4d448e15-f8cf-4e33-98b2-12bef7d28b78-O0 3: I1120 01:14:38.749539 17510 sched.cpp:958] Scheduler::offerRescinded took 30927ns 3: I1120 01:14:38.749868 17512 hierarchical.cpp:1132] Recovered cpus(allocated: role):2; mem(allocated: role):1024; disk(allocated: role):1024; ports(allocated: role):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: {}) on agent 4d448e15-f8cf-4e33-98b2-12bef7d28b78-S0 from framework 4d448e15-f8cf-4e33-98b2-12bef7d28b78-0000 3: I1120 01:14:38.749943 17512 hierarchical.cpp:1178] Framework 4d448e15-f8cf-4e33-98b2-12bef7d28b78-0000 filtered agent 4d448e15-f8cf-4e33-98b2-12bef7d28b78-S0 for 5secs 3: I1120 01:14:38.753548 17520 master.cpp:9969] Sending updated checkpointed resources cpus(reservations: [(DYNAMIC,role,test-principal)]):1; mem(reservations: [(DYNAMIC,role,test-principal)]):512 to agent 4d448e15-f8cf-4e33-98b2-12bef7d28b78-S0 at slave(688)@172.17.0.2:45437 (6c3408add39c) 3: I1120 01:14:38.754621 17520 slave.cpp:3587] Updated checkpointed resources from {} to cpus(reservations: [(DYNAMIC,role,test-principal)]):1; mem(reservations: [(DYNAMIC,role,test-principal)]):512 3: I1120 01:14:38.754686 17518 master.cpp:5537] Processing REVIVE call for framework 4d448e15-f8cf-4e33-98b2-12bef7d28b78-0000 (default) at scheduler-210762e9-9890-48bf-b101-62c506898e73@172.17.0.2:45437 3: I1120 01:14:38.754870 17523 hierarchical.cpp:1279] Revived offers for roles { role } of framework 4d448e15-f8cf-4e33-98b2-12bef7d28b78-0000 3: I1120 01:14:38.756960 17523 hierarchical.cpp:1457] Performed allocation for 1 agents in 1.943462ms 3: I1120 01:14:38.757791 17512 master.cpp:8115] Sending 1 offers to framework 4d448e15-f8cf-4e33-98b2-12bef7d28b78-0000 (default) at scheduler-210762e9-9890-48bf-b101-62c506898e73@172.17.0.2:45437 3: I1120 01:14:38.758448 17512 sched.cpp:921] Scheduler::resourceOffers took 140635ns 3: I1120 01:14:38.759022 17507 sched.cpp:2009] Asked to stop the driver 3: I1120 01:14:38.759184 17516 sched.cpp:1191] Stopping framework 4d448e15-f8cf-4e33-98b2-12bef7d28b78-0000 3: I1120 01:14:38.759482 17508 master.cpp:8792] Processing TEARDOWN call for framework 4d448e15-f8cf-4e33-98b2-12bef7d28b78-0000 (default) at scheduler-210762e9-9890-48bf-b101-62c506898e73@172.17.0.2:45437 3: I1120 01:14:38.759518 17508 master.cpp:8804] Removing framework 4d448e15-f8cf-4e33-98b2-12bef7d28b78-0000 (default) at scheduler-210762e9-9890-48bf-b101-62c506898e73@172.17.0.2:45437 3: I1120 01:14:38.759533 17508 master.cpp:3331] Deactivating framework 4d448e15-f8cf-4e33-98b2-12bef7d28b78-0000 (default) at scheduler-210762e9-9890-48bf-b101-62c506898e73@172.17.0.2:45437 3: I1120 01:14:38.759676 17521 hierarchical.cpp:419] Deactivated framework 4d448e15-f8cf-4e33-98b2-12bef7d28b78-0000 3: I1120 01:14:38.760525 17521 slave.cpp:883] Agent terminating 3: I1120 01:14:38.760818 17508 master.cpp:10024] Removing offer 4d448e15-f8cf-4e33-98b2-12bef7d28b78-O1 3: I1120 01:14:38.761391 17508 master.cpp:1309] Agent 4d448e15-f8cf-4e33-98b2-12bef7d28b78-S0 at slave(688)@172.17.0.2:45437 (6c3408add39c) disconnected 3: I1120 01:14:38.761423 17508 master.cpp:3368] Disconnecting agent 4d448e15-f8cf-4e33-98b2-12bef7d28b78-S0 at slave(688)@172.17.0.2:45437 (6c3408add39c) 3: I1120 01:14:38.761493 17508 master.cpp:3387] Deactivating agent 4d448e15-f8cf-4e33-98b2-12bef7d28b78-S0 at slave(688)@172.17.0.2:45437 (6c3408add39c) 3: I1120 01:14:38.761914 17510 hierarchical.cpp:1132] Recovered cpus(allocated: role):1; mem(allocated: role):512; disk(allocated: role):1024; ports(allocated: role):[31000-32000]; cpus(allocated: role)(reservations: [(DYNAMIC,role,test-principal)]):1; mem(allocated: role)(reservations: [(DYNAMIC,role,test-principal)]):512 (total: cpus:1; mem:512; disk:1024; ports:[31000-32000]; cpus(reservations: [(DYNAMIC,role,test-principal)]):1; mem(reservations: [(DYNAMIC,role,test-principal)]):512, allocated: {}) on agent 4d448e15-f8cf-4e33-98b2-12bef7d28b78-S0 from framework 4d448e15-f8cf-4e33-98b2-12bef7d28b78-0000 3: I1120 01:14:38.762382 17510 hierarchical.cpp:358] Removed framework 4d448e15-f8cf-4e33-98b2-12bef7d28b78-0000 3: I1120 01:14:38.762476 17510 hierarchical.cpp:697] Agent 4d448e15-f8cf-4e33-98b2-12bef7d28b78-S0 deactivated 3: I1120 01:14:38.768106 17507 master.cpp:1151] Master terminating 3: I1120 01:14:38.769188 17508 hierarchical.cpp:633] Removed agent 4d448e15-f8cf-4e33-98b2-12bef7d28b78-S0 3: [ OK ] ContentType/MasterAPITest.ReserveResources/1 (81 ms) 3: [ RUN ] ContentType/MasterAPITest.UnreserveResources/0 3: I1120 01:14:38.775504 17507 cluster.cpp:162] Creating default 'local' authorizer 3: I1120 01:14:38.777947 17513 master.cpp:448] Master 67fc8282-ffa5-4180-9795-334b974e8fea (6c3408add39c) started on 172.17.0.2:45437 3: I1120 01:14:38.777966 17513 master.cpp:450] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1000secs" --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/pXsy5M/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/pXsy5M/master" --zk_session_timeout="10secs" 3: I1120 01:14:38.778199 17513 master.cpp:499] Master only allowing authenticated frameworks to register 3: I1120 01:14:38.778206 17513 master.cpp:505] Master only allowing authenticated agents to register 3: I1120 01:14:38.778210 17513 master.cpp:511] Master only allowing authenticated HTTP frameworks to register 3: I1120 01:14:38.778214 17513 credentials.hpp:37] Loading credentials for authentication from '/tmp/pXsy5M/credentials' 3: I1120 01:14:38.778440 17513 master.cpp:555] Using default 'crammd5' authenticator 3: I1120 01:14:38.778565 17513 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' 3: I1120 01:14:38.778693 17513 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' 3: I1120 01:14:38.778808 17513 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' 3: I1120 01:14:38.778916 17513 master.cpp:634] Authorization enabled 3: I1120 01:14:38.779124 17511 whitelist_watcher.cpp:77] No whitelist given 3: I1120 01:14:38.779153 17509 hierarchical.cpp:173] Initialized hierarchical allocator process 3: I1120 01:14:38.782359 17521 master.cpp:2213] Elected as the leading master! 3: I1120 01:14:38.782390 17521 master.cpp:1693] Recovering from registrar 3: I1120 01:14:38.782635 17520 registrar.cpp:347] Recovering registrar 3: I1120 01:14:38.783246 17520 registrar.cpp:391] Successfully fetched the registry (0B) in 564992ns 3: I1120 01:14:38.783349 17520 registrar.cpp:495] Applied 1 operations in 29496ns; attempting to update the registry 3: I1120 01:14:38.783983 17523 registrar.cpp:552] Successfully updated the registry in 569088ns 3: I1120 01:14:38.784121 17523 registrar.cpp:424] Successfully recovered registrar 3: I1120 01:14:38.784560 17509 master.cpp:1806] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register 3: I1120 01:14:38.784631 17521 hierarchical.cpp:211] Skipping recovery of hierarchical allocator: nothing to recover 3: W1120 01:14:38.788868 17507 process.cpp:3185] Attempted to spawn already running process files@172.17.0.2:45437 3: I1120 01:14:38.789934 17507 containerizer.cpp:301] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } 3: W1120 01:14:38.790544 17507 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges 3: W1120 01:14:38.790670 17507 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges 3: I1120 01:14:38.790705 17507 provisioner.cpp:255] Using default backend 'copy' 3: I1120 01:14:38.792853 17507 cluster.cpp:448] Creating default 'local' authorizer 3: I1120 01:14:38.795382 17511 slave.cpp:262] Mesos agent started on (689)@172.17.0.2:45437 3: I1120 01:14:38.795405 17511 slave.cpp:263] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/ContentType_MasterAPITest_UnreserveResources_0_pS2xrC/store/appc" --authenticate_http_executors="true" --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/ContentType_MasterAPITest_UnreserveResources_0_pS2xrC/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/ContentType_MasterAPITest_UnreserveResources_0_pS2xrC/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_secret_key="/tmp/ContentType_MasterAPITest_UnreserveResources_0_pS2xrC/executor_secret_key" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/ContentType_MasterAPITest_UnreserveResources_0_pS2xrC/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/ContentType_MasterAPITest_UnreserveResources_0_pS2xrC/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/ContentType_MasterAPITest_UnreserveResources_0_pS2xrC" --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/ContentType_MasterAPITest_UnreserveResources_0_Y1JxLH" --zk_session_timeout="10secs" 3: I1120 01:14:38.795938 17511 credentials.hpp:86] Loading credential for authentication from '/tmp/ContentType_MasterAPITest_UnreserveResources_0_pS2xrC/credential' 3: I1120 01:14:38.796108 17511 slave.cpp:295] Agent using credential for: test-principal 3: I1120 01:14:38.796128 17511 credentials.hpp:37] Loading credentials for authentication from '/tmp/ContentType_MasterAPITest_UnreserveResources_0_pS2xrC/http_credentials' 3: I1120 01:14:38.796535 17511 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-executor' 3: I1120 01:14:38.796679 17511 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-executor' 3: I1120 01:14:38.796955 17511 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' 3: I1120 01:14:38.797085 17511 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readonly' 3: I1120 01:14:38.797351 17511 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite' 3: I1120 01:14:38.797477 17511 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readwrite' 3: I1120 01:14:38.799273 17511 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: I1120 01:14:38.799571 17511 slave.cpp:601] Agent attributes: [ ] 3: I1120 01:14:38.799582 17511 slave.cpp:610] Agent hostname: 6c3408add39c 3: I1120 01:14:38.799716 17523 status_update_manager.cpp:177] Pausing sending status updates 3: I1120 01:14:38.801371 17509 state.cpp:64] Recovering state from '/tmp/ContentType_MasterAPITest_UnreserveResources_0_Y1JxLH/meta' 3: I1120 01:14:38.801769 17512 status_update_manager.cpp:203] Recovering status update manager 3: I1120 01:14:38.801981 17512 containerizer.cpp:662] Recovering containerizer 3: I1120 01:14:38.803582 17514 provisioner.cpp:416] Provisioner recovery complete 3: I1120 01:14:38.804004 17514 slave.cpp:6441] Finished recovery 3: I1120 01:14:38.804764 17508 status_update_manager.cpp:177] Pausing sending status updates 3: I1120 01:14:38.804783 17517 slave.cpp:1007] New master detected at master@172.17.0.2:45437 3: I1120 01:14:38.804854 17517 slave.cpp:1042] Detecting new master 3: I1120 01:14:38.805984 17523 slave.cpp:1069] Authenticating with master master@172.17.0.2:45437 3: I1120 01:14:38.806063 17523 slave.cpp:1078] Using default CRAM-MD5 authenticatee 3: I1120 01:14:38.806365 17512 authenticatee.cpp:121] Creating new client SASL connection 3: I1120 01:14:38.806676 17512 master.cpp:8285] Authenticating slave(689)@172.17.0.2:45437 3: I1120 01:14:38.806825 17522 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1337)@172.17.0.2:45437 3: I1120 01:14:38.807149 17513 authenticator.cpp:98] Creating new server SASL connection 3: I1120 01:14:38.807411 17511 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1120 01:14:38.807440 17511 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1120 01:14:38.807552 17511 authenticator.cpp:204] Received SASL authentication start 3: I1120 01:14:38.807610 17511 authenticator.cpp:326] Authentication requires more steps 3: I1120 01:14:38.807772 17509 authenticatee.cpp:259] Received SASL authentication step 3: I1120 01:14:38.807976 17509 authenticator.cpp:232] Received SASL authentication step 3: I1120 01:14:38.808027 17509 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '6c3408add39c' server FQDN: '6c3408add39c' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1120 01:14:38.808043 17509 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1120 01:14:38.808076 17509 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1120 01:14:38.808095 17509 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '6c3408add39c' server FQDN: '6c3408add39c' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1120 01:14:38.808105 17509 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1120 01:14:38.808111 17509 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1120 01:14:38.808126 17509 authenticator.cpp:318] Authentication success 3: I1120 01:14:38.808224 17514 authenticatee.cpp:299] Authentication success 3: I1120 01:14:38.808323 17515 master.cpp:8315] Successfully authenticated principal 'test-principal' at slave(689)@172.17.0.2:45437 3: I1120 01:14:38.808356 17509 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1337)@172.17.0.2:45437 3: I1120 01:14:38.808750 17514 slave.cpp:1161] Successfully authenticated with master master@172.17.0.2:45437 3: I1120 01:14:38.808995 17514 slave.cpp:1682] Will retry registration in 4.519116ms if necessary 3: I1120 01:14:38.809265 17523 master.cpp:6032] Received register agent message from slave(689)@172.17.0.2:45437 (6c3408add39c) 3: I1120 01:14:38.809389 17523 master.cpp:3870] Authorizing agent with principal 'test-principal' 3: I1120 01:14:38.809844 17516 master.cpp:6092] Authorized registration of agent at slave(689)@172.17.0.2:45437 (6c3408add39c) 3: I1120 01:14:38.809973 17516 master.cpp:6185] Registering agent at slave(689)@172.17.0.2:45437 (6c3408add39c) with id 67fc8282-ffa5-4180-9795-334b974e8fea-S0 3: I1120 01:14:38.810431 17522 registrar.cpp:495] Applied 1 operations in 58559ns; attempting to update the registry 3: I1120 01:14:38.811103 17518 registrar.cpp:552] Successfully updated the registry in 600832ns 3: I1120 01:14:38.811384 17510 master.cpp:6232] Admitted agent 67fc8282-ffa5-4180-9795-334b974e8fea-S0 at slave(689)@172.17.0.2:45437 (6c3408add39c) 3: I1120 01:14:38.812263 17519 slave.cpp:1207] Registered with master master@172.17.0.2:45437; given agent ID 67fc8282-ffa5-4180-9795-334b974e8fea-S0 3: I1120 01:14:38.812423 17512 status_update_manager.cpp:184] Resuming sending status updates 3: I1120 01:14:38.812163 17510 master.cpp:6263] Registered agent 67fc8282-ffa5-4180-9795-334b974e8fea-S0 at slave(689)@172.17.0.2:45437 (6c3408add39c) with [{"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: I1120 01:14:38.812561 17519 slave.cpp:1227] Checkpointing SlaveInfo to '/tmp/ContentType_MasterAPITest_UnreserveResources_0_Y1JxLH/meta/slaves/67fc8282-ffa5-4180-9795-334b974e8fea-S0/slave.info' 3: I1120 01:14:38.812659 17517 hierarchical.cpp:600] Added agent 67fc8282-ffa5-4180-9795-334b974e8fea-S0 (6c3408add39c) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {}) 3: I1120 01:14:38.812911 17519 slave.cpp:1295] Forwarding total oversubscribed resources {} 3: I1120 01:14:38.812916 17517 hierarchical.cpp:1457] Performed allocation for 1 agents in 120054ns 3: I1120 01:14:38.813078 17519 master.cpp:7064] Received update of agent 67fc8282-ffa5-4180-9795-334b974e8fea-S0 at slave(689)@172.17.0.2:45437 (6c3408add39c) with total oversubscribed resources {} 3: I1120 01:14:38.813215 17519 master.cpp:7082] Ignoring update on agent 67fc8282-ffa5-4180-9795-334b974e8fea-S0 at slave(689)@172.17.0.2:45437 (6c3408add39c) as it reports no changes 3: I1120 01:14:38.814867 17518 process.cpp:3932] Handling HTTP event for process 'master' with path: '/master/api/v1' 3: I1120 01:14:38.816550 17517 http.cpp:1185] HTTP POST for /master/api/v1 from 172.17.0.2:34786 3: I1120 01:14:38.816774 17517 http.cpp:673] Processing call RESERVE_RESOURCES 3: I1120 01:14:38.817134 17517 master.cpp:3655] Authorizing principal 'test-principal' to reserve resources '[{"name":"cpus","reservations":[{"principal":"test-principal","role":"role","type":"DYNAMIC"}],"scalar":{"value":1.0},"type":"SCALAR"},{"name":"mem","reservations":[{"principal":"test-principal","role":"role","type":"DYNAMIC"}],"scalar":{"value":512.0},"type":"SCALAR"}]' 3: I1120 01:14:38.821315 17513 master.cpp:9969] Sending updated checkpointed resources cpus(reservations: [(DYNAMIC,role,test-principal)]):1; mem(reservations: [(DYNAMIC,role,test-principal)]):512 to agent 67fc8282-ffa5-4180-9795-334b974e8fea-S0 at slave(689)@172.17.0.2:45437 (6c3408add39c) 3: I1120 01:14:38.822337 17513 slave.cpp:3587] Updated checkpointed resources from {} to cpus(reservations: [(DYNAMIC,role,test-principal)]):1; mem(reservations: [(DYNAMIC,role,test-principal)]):512 3: W1120 01:14:38.822381 17507 process.cpp:3185] Attempted to spawn already running process version@172.17.0.2:45437 3: I1120 01:14:38.823140 17507 sched.cpp:232] Version: 1.5.0 3: I1120 01:14:38.823773 17508 sched.cpp:336] New master detected at master@172.17.0.2:45437 3: I1120 01:14:38.823880 17508 sched.cpp:396] Authenticating with master master@172.17.0.2:45437 3: I1120 01:14:38.823920 17508 sched.cpp:403] Using default CRAM-MD5 authenticatee 3: I1120 01:14:38.824178 17511 authenticatee.cpp:121] Creating new client SASL connection 3: I1120 01:14:38.824501 17511 master.cpp:8285] Authenticating scheduler-6487611d-8844-44fc-bae7-d38006226e70@172.17.0.2:45437 3: I1120 01:14:38.824637 17523 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1338)@172.17.0.2:45437 3: I1120 01:14:38.824951 17520 authenticator.cpp:98] Creating new server SASL connection 3: I1120 01:14:38.825206 17520 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1120 01:14:38.825232 17520 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1120 01:14:38.825350 17509 authenticator.cpp:204] Received SASL authentication start 3: I1120 01:14:38.825410 17509 authenticator.cpp:326] Authentication requires more steps 3: I1120 01:14:38.825546 17513 authenticatee.cpp:259] Received SASL authentication step 3: I1120 01:14:38.825686 17512 authenticator.cpp:232] Received SASL authentication step 3: I1120 01:14:38.825716 17512 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '6c3408add39c' server FQDN: '6c3408add39c' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1120 01:14:38.825727 17512 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1120 01:14:38.825757 17512 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1120 01:14:38.825774 17512 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '6c3408add39c' server FQDN: '6c3408add39c' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1120 01:14:38.825789 17512 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1120 01:14:38.825796 17512 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1120 01:14:38.825810 17512 authenticator.cpp:318] Authentication success 3: I1120 01:14:38.825911 17515 authenticatee.cpp:299] Authentication success 3: I1120 01:14:38.825956 17516 master.cpp:8315] Successfully authenticated principal 'test-principal' at scheduler-6487611d-8844-44fc-bae7-d38006226e70@172.17.0.2:45437 3: I1120 01:14:38.826004 17512 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1338)@172.17.0.2:45437 3: I1120 01:14:38.826258 17521 sched.cpp:502] Successfully authenticated with master master@172.17.0.2:45437 3: I1120 01:14:38.826283 17521 sched.cpp:824] Sending SUBSCRIBE call to master@172.17.0.2:45437 3: I1120 01:14:38.826411 17521 sched.cpp:857] Will retry registration in 1.044062431secs if necessary 3: I1120 01:14:38.826620 17508 master.cpp:2961] Received SUBSCRIBE call for framework 'default' at scheduler-6487611d-8844-44fc-bae7-d38006226e70@172.17.0.2:45437 3: I1120 01:14:38.826709 17508 master.cpp:2278] Authorizing framework principal 'test-principal' to receive offers for roles '{ role }' 3: I1120 01:14:38.827239 17511 master.cpp:3041] Subscribing framework default with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT ] 3: I1120 01:14:38.827903 17520 sched.cpp:751] Framework registered with 67fc8282-ffa5-4180-9795-334b974e8fea-0000 3: I1120 01:14:38.827950 17520 sched.cpp:765] Scheduler::registered took 21192ns 3: I1120 01:14:38.828055 17523 hierarchical.cpp:306] Added framework 67fc8282-ffa5-4180-9795-334b974e8fea-0000 3: I1120 01:14:38.830143 17523 hierarchical.cpp:1457] Performed allocation for 1 agents in 1.931921ms 3: I1120 01:14:38.831073 17513 master.cpp:8115] Sending 1 offers to framework 67fc8282-ffa5-4180-9795-334b974e8fea-0000 (default) at scheduler-6487611d-8844-44fc-bae7-d38006226e70@172.17.0.2:45437 3: I1120 01:14:38.831794 17519 sched.cpp:921] Scheduler::resourceOffers took 140141ns 3: I1120 01:14:38.834790 17514 process.cpp:3932] Handling HTTP event for process 'master' with path: '/master/api/v1' 3: I1120 01:14:38.836408 17519 http.cpp:1185] HTTP POST for /master/api/v1 from 172.17.0.2:34787 3: I1120 01:14:38.836694 17519 http.cpp:673] Processing call UNRESERVE_RESOURCES 3: I1120 01:14:38.837083 17519 master.cpp:3723] Authorizing principal 'test-principal' to unreserve resources '[{"name":"cpus","reservations":[{"principal":"test-principal","role":"role","type":"DYNAMIC"}],"scalar":{"value":1.0},"type":"SCALAR"},{"name":"mem","reservations":[{"principal":"test-principal","role":"role","type":"DYNAMIC"}],"scalar":{"value":512.0},"type":"SCALAR"}]' 3: I1120 01:14:38.839236 17522 master.cpp:10024] Removing offer 67fc8282-ffa5-4180-9795-334b974e8fea-O0 3: I1120 01:14:38.839396 17512 sched.cpp:947] Rescinded offer 67fc8282-ffa5-4180-9795-334b974e8fea-O0 3: I1120 01:14:38.839468 17512 sched.cpp:958] Scheduler::offerRescinded took 23054ns 3: I1120 01:14:38.840306 17518 hierarchical.cpp:1132] Recovered cpus(allocated: role):1; mem(allocated: role):512; disk(allocated: role):1024; ports(allocated: role):[31000-32000]; cpus(allocated: role)(reservations: [(DYNAMIC,role,test-principal)]):1; mem(allocated: role)(reservations: [(DYNAMIC,role,test-principal)]):512 (total: cpus:1; mem:512; disk:1024; ports:[31000-32000]; cpus(reservations: [(DYNAMIC,role,test-principal)]):1; mem(reservations: [(DYNAMIC,role,test-principal)]):512, allocated: {}) on agent 67fc8282-ffa5-4180-9795-334b974e8fea-S0 from framework 67fc8282-ffa5-4180-9795-334b974e8fea-0000 3: I1120 01:14:38.840414 17518 hierarchical.cpp:1178] Framework 67fc8282-ffa5-4180-9795-334b974e8fea-0000 filtered agent 67fc8282-ffa5-4180-9795-334b974e8fea-S0 for 5secs 3: I1120 01:14:38.843775 17521 master.cpp:9969] Sending updated checkpointed resources {} to agent 67fc8282-ffa5-4180-9795-334b974e8fea-S0 at slave(689)@172.17.0.2:45437 (6c3408add39c) 3: I1120 01:14:38.844386 17521 slave.cpp:3587] Updated checkpointed resources from cpus(reservations: [(DYNAMIC,role,test-principal)]):1; mem(reservations: [(DYNAMIC,role,test-principal)]):512 to {} 3: I1120 01:14:38.844939 17519 master.cpp:5537] Processing REVIVE call for framework 67fc8282-ffa5-4180-9795-334b974e8fea-0000 (default) at scheduler-6487611d-8844-44fc-bae7-d38006226e70@172.17.0.2:45437 3: I1120 01:14:38.845130 17519 hierarchical.cpp:1279] Revived offers for roles { role } of framework 67fc8282-ffa5-4180-9795-334b974e8fea-0000 3: I1120 01:14:38.846447 17519 hierarchical.cpp:1457] Performed allocation for 1 agents in 1.174587ms 3: I1120 01:14:38.847090 17518 master.cpp:8115] Sending 1 offers to framework 67fc8282-ffa5-4180-9795-334b974e8fea-0000 (default) at scheduler-6487611d-8844-44fc-bae7-d38006226e70@172.17.0.2:45437 3: I1120 01:14:38.847626 17518 sched.cpp:921] Scheduler::resourceOffers took 108767ns 3: I1120 01:14:38.848134 17507 sched.cpp:2009] Asked to stop the driver 3: I1120 01:14:38.848278 17513 sched.cpp:1191] Stopping framework 67fc8282-ffa5-4180-9795-334b974e8fea-0000 3: I1120 01:14:38.848567 17521 master.cpp:8792] Processing TEARDOWN call for framework 67fc8282-ffa5-4180-9795-334b974e8fea-0000 (default) at scheduler-6487611d-8844-44fc-bae7-d38006226e70@172.17.0.2:45437 3: I1120 01:14:38.848605 17521 master.cpp:8804] Removing framework 67fc8282-ffa5-4180-9795-334b974e8fea-0000 (default) at scheduler-6487611d-8844-44fc-bae7-d38006226e70@172.17.0.2:45437 3: I1120 01:14:38.848629 17521 master.cpp:3331] Deactivating framework 67fc8282-ffa5-4180-9795-334b974e8fea-0000 (default) at scheduler-6487611d-8844-44fc-bae7-d38006226e70@172.17.0.2:45437 3: I1120 01:14:38.848896 17517 hierarchical.cpp:419] Deactivated framework 67fc8282-ffa5-4180-9795-334b974e8fea-0000 3: I1120 01:14:38.849371 17521 master.cpp:10024] Removing offer 67fc8282-ffa5-4180-9795-334b974e8fea-O1 3: I1120 01:14:38.849617 17508 slave.cpp:3267] Asked to shut down framework 67fc8282-ffa5-4180-9795-334b974e8fea-0000 by master@172.17.0.2:45437 3: I1120 01:14:38.849658 17508 slave.cpp:3282] Cannot shut down unknown framework 67fc8282-ffa5-4180-9795-334b974e8fea-0000 3: I1120 01:14:38.849982 17517 hierarchical.cpp:1132] Recovered cpus(allocated: role):2; mem(allocated: role):1024; disk(allocated: role):1024; ports(allocated: role):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: {}) on agent 67fc8282-ffa5-4180-9795-334b974e8fea-S0 from framework 67fc8282-ffa5-4180-9795-334b974e8fea-0000 3: I1120 01:14:38.850340 17517 hierarchical.cpp:358] Removed framework 67fc8282-ffa5-4180-9795-334b974e8fea-0000 3: I1120 01:14:38.850481 17521 slave.cpp:883] Agent terminating 3: I1120 01:14:38.850711 17521 master.cpp:1309] Agent 67fc8282-ffa5-4180-9795-334b974e8fea-S0 at slave(689)@172.17.0.2:45437 (6c3408add39c) disconnected 3: I1120 01:14:38.850736 17521 master.cpp:3368] Disconnecting agent 67fc8282-ffa5-4180-9795-334b974e8fea-S0 at slave(689)@172.17.0.2:45437 (6c3408add39c) 3: I1120 01:14:38.850788 17521 master.cpp:3387] Deactivating agent 67fc8282-ffa5-4180-9795-334b974e8fea-S0 at slave(689)@172.17.0.2:45437 (6c3408add39c) 3: I1120 01:14:38.851004 17509 hierarchical.cpp:697] Agent 67fc8282-ffa5-4180-9795-334b974e8fea-S0 deactivated 3: I1120 01:14:38.857700 17507 master.cpp:1151] Master terminating 3: I1120 01:14:38.858497 17523 hierarchical.cpp:633] Removed agent 67fc8282-ffa5-4180-9795-334b974e8fea-S0 3: [ OK ] ContentType/MasterAPITest.UnreserveResources/0 (89 ms) 3: [ RUN ] ContentType/MasterAPITest.UnreserveResources/1 3: I1120 01:14:38.866351 17507 cluster.cpp:162] Creating default 'local' authorizer 3: I1120 01:14:38.869380 17510 master.cpp:448] Master d5dc85ef-7eb8-44ec-9473-f62d2b34204b (6c3408add39c) started on 172.17.0.2:45437 3: I1120 01:14:38.869405 17510 master.cpp:450] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1000secs" --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/ZEL4nc/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/ZEL4nc/master" --zk_session_timeout="10secs" 3: I1120 01:14:38.869796 17510 master.cpp:499] Master only allowing authenticated frameworks to register 3: I1120 01:14:38.869807 17510 master.cpp:505] Master only allowing authenticated agents to register 3: I1120 01:14:38.869813 17510 master.cpp:511] Master only allowing authenticated HTTP frameworks to register 3: I1120 01:14:38.869820 17510 credentials.hpp:37] Loading credentials for authentication from '/tmp/ZEL4nc/credentials' Build step 'Execute shell' marked build as failure