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)/4483/display/redirect>
------------------------------------------ [...truncated 25.74 MB...] 3: I1121 09:34:45.800346 15998 registrar.cpp:495] Applied 1 operations in 22420ns; attempting to update the registry 3: I1121 09:34:45.800997 15998 registrar.cpp:552] Successfully updated the registry in 573952ns 3: I1121 09:34:45.801177 15998 registrar.cpp:424] Successfully recovered registrar 3: I1121 09:34:45.801530 16013 master.cpp:1808] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register 3: I1121 09:34:45.801573 15997 hierarchical.cpp:211] Skipping recovery of hierarchical allocator: nothing to recover 3: W1121 09:34:45.806228 15991 process.cpp:2756] Attempted to spawn already running process [email protected]:41974 3: I1121 09:34:45.807088 15991 containerizer.cpp:301] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } 3: W1121 09:34:45.807593 15991 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges 3: W1121 09:34:45.807698 15991 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges 3: I1121 09:34:45.807726 15991 provisioner.cpp:259] Using default backend 'copy' 3: I1121 09:34:45.809533 15991 cluster.cpp:448] Creating default 'local' authorizer 3: I1121 09:34:45.811511 15997 slave.cpp:262] Mesos agent started on (689)@172.17.0.5:41974 3: I1121 09:34:45.811532 15997 slave.cpp:263] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/ContentType_MasterAPITest_GetAgentsFiltering_0_1yrBmg/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/ContentType_MasterAPITest_GetAgentsFiltering_0_1yrBmg/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_GetAgentsFiltering_0_1yrBmg/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/ContentType_MasterAPITest_GetAgentsFiltering_0_1yrBmg/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_GetAgentsFiltering_0_1yrBmg/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(muggle):1;cpus(*):2;gpus(*):0;mem(muggle):1024;mem(*):1024;disk(muggle):1024;disk(*):1024;ports(muggle):[30000-30999];ports(*):[31000-32000]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/ContentType_MasterAPITest_GetAgentsFiltering_0_1yrBmg" --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_GetAgentsFiltering_0_2qyGXe" --zk_session_timeout="10secs" 3: I1121 09:34:45.811877 15997 credentials.hpp:86] Loading credential for authentication from '/tmp/ContentType_MasterAPITest_GetAgentsFiltering_0_1yrBmg/credential' 3: I1121 09:34:45.812019 15997 slave.cpp:295] Agent using credential for: test-principal 3: I1121 09:34:45.812037 15997 credentials.hpp:37] Loading credentials for authentication from '/tmp/ContentType_MasterAPITest_GetAgentsFiltering_0_1yrBmg/http_credentials' 3: I1121 09:34:45.812240 15997 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' 3: I1121 09:34:45.812372 15997 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite' 3: I1121 09:34:45.814910 15997 slave.cpp:593] Agent resources: [{"name":"cpus","reservations":[{"role":"muggle","type":"STATIC"}],"scalar":{"value":1.0},"type":"SCALAR"},{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","reservations":[{"role":"muggle","type":"STATIC"}],"scalar":{"value":1024.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","reservations":[{"role":"muggle","type":"STATIC"}],"scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":30000,"end":30999}]},"reservations":[{"role":"muggle","type":"STATIC"}],"type":"RANGES"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] 3: I1121 09:34:45.815407 15997 slave.cpp:601] Agent attributes: [ ] 3: I1121 09:34:45.815418 15997 slave.cpp:610] Agent hostname: 5cd14b7e5105 3: I1121 09:34:45.815553 16011 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I1121 09:34:45.817394 16000 state.cpp:64] Recovering state from '/tmp/ContentType_MasterAPITest_GetAgentsFiltering_0_2qyGXe/meta' 3: I1121 09:34:45.817836 15998 task_status_update_manager.cpp:207] Recovering task status update manager 3: I1121 09:34:45.818081 16008 containerizer.cpp:668] Recovering containerizer 3: I1121 09:34:45.819715 16003 provisioner.cpp:455] Provisioner recovery complete 3: I1121 09:34:45.820080 16011 slave.cpp:6443] Finished recovery 3: I1121 09:34:45.820842 15997 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I1121 09:34:45.820853 16007 slave.cpp:1007] New master detected at [email protected]:41974 3: I1121 09:34:45.820940 16007 slave.cpp:1042] Detecting new master 3: I1121 09:34:45.823289 16000 slave.cpp:1069] Authenticating with master [email protected]:41974 3: I1121 09:34:45.823356 16000 slave.cpp:1078] Using default CRAM-MD5 authenticatee 3: I1121 09:34:45.823683 16006 authenticatee.cpp:121] Creating new client SASL connection 3: I1121 09:34:45.824184 15998 master.cpp:8306] Authenticating slave(689)@172.17.0.5:41974 3: I1121 09:34:45.824342 15992 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1332)@172.17.0.5:41974 3: I1121 09:34:45.824559 16004 authenticator.cpp:98] Creating new server SASL connection 3: I1121 09:34:45.824786 16012 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1121 09:34:45.824808 16012 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1121 09:34:45.824899 16012 authenticator.cpp:204] Received SASL authentication start 3: I1121 09:34:45.824949 16012 authenticator.cpp:326] Authentication requires more steps 3: I1121 09:34:45.825055 16009 authenticatee.cpp:259] Received SASL authentication step 3: I1121 09:34:45.825176 16013 authenticator.cpp:232] Received SASL authentication step 3: I1121 09:34:45.825204 16013 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '5cd14b7e5105' server FQDN: '5cd14b7e5105' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1121 09:34:45.825217 16013 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1121 09:34:45.825245 16013 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1121 09:34:45.825263 16013 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '5cd14b7e5105' server FQDN: '5cd14b7e5105' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1121 09:34:45.825273 16013 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1121 09:34:45.825278 16013 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1121 09:34:45.825289 16013 authenticator.cpp:318] Authentication success 3: I1121 09:34:45.825371 16008 authenticatee.cpp:299] Authentication success 3: I1121 09:34:45.825423 15999 master.cpp:8336] Successfully authenticated principal 'test-principal' at slave(689)@172.17.0.5:41974 3: I1121 09:34:45.825475 16010 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1332)@172.17.0.5:41974 3: I1121 09:34:45.825690 16014 slave.cpp:1161] Successfully authenticated with master [email protected]:41974 3: I1121 09:34:45.825930 16014 slave.cpp:1682] Will retry registration in 8.009589ms if necessary 3: I1121 09:34:45.826205 16003 master.cpp:6036] Received register agent message from slave(689)@172.17.0.5:41974 (5cd14b7e5105) 3: I1121 09:34:45.826339 16003 master.cpp:3872] Authorizing agent with principal 'test-principal' 3: I1121 09:34:45.827002 16011 master.cpp:6098] Authorized registration of agent at slave(689)@172.17.0.5:41974 (5cd14b7e5105) 3: I1121 09:34:45.827142 16011 master.cpp:6191] Registering agent at slave(689)@172.17.0.5:41974 (5cd14b7e5105) with id 590149c1-4db8-4780-a82a-39a87559d9e0-S0 3: I1121 09:34:45.827569 15994 registrar.cpp:495] Applied 1 operations in 62157ns; attempting to update the registry 3: I1121 09:34:45.828053 15994 registrar.cpp:552] Successfully updated the registry in 434176ns 3: I1121 09:34:45.828246 16000 master.cpp:6240] Admitted agent 590149c1-4db8-4780-a82a-39a87559d9e0-S0 at slave(689)@172.17.0.5:41974 (5cd14b7e5105) 3: I1121 09:34:45.829277 15998 slave.cpp:1207] Registered with master [email protected]:41974; given agent ID 590149c1-4db8-4780-a82a-39a87559d9e0-S0 3: I1121 09:34:45.829427 16009 task_status_update_manager.cpp:188] Resuming sending task status updates 3: I1121 09:34:45.829033 16000 master.cpp:6273] Registered agent 590149c1-4db8-4780-a82a-39a87559d9e0-S0 at slave(689)@172.17.0.5:41974 (5cd14b7e5105) with [{"name":"cpus","reservations":[{"role":"muggle","type":"STATIC"}],"scalar":{"value":1.0},"type":"SCALAR"},{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","reservations":[{"role":"muggle","type":"STATIC"}],"scalar":{"value":1024.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","reservations":[{"role":"muggle","type":"STATIC"}],"scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":30000,"end":30999}]},"reservations":[{"role":"muggle","type":"STATIC"}],"type":"RANGES"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] 3: I1121 09:34:45.829589 15998 slave.cpp:1227] Checkpointing SlaveInfo to '/tmp/ContentType_MasterAPITest_GetAgentsFiltering_0_2qyGXe/meta/slaves/590149c1-4db8-4780-a82a-39a87559d9e0-S0/slave.info' 3: I1121 09:34:45.829782 15992 hierarchical.cpp:600] Added agent 590149c1-4db8-4780-a82a-39a87559d9e0-S0 (5cd14b7e5105) with cpus(reservations: [(STATIC,muggle)]):1; cpus:2; mem(reservations: [(STATIC,muggle)]):1024; mem:1024; disk(reservations: [(STATIC,muggle)]):1024; disk:1024; ports(reservations: [(STATIC,muggle)]):[30000-30999]; ports:[31000-32000] (allocated: {}) 3: I1121 09:34:45.829993 15998 slave.cpp:1295] Forwarding total oversubscribed resources {} 3: I1121 09:34:45.830168 15999 master.cpp:7085] Received update of agent 590149c1-4db8-4780-a82a-39a87559d9e0-S0 at slave(689)@172.17.0.5:41974 (5cd14b7e5105) with total oversubscribed resources {} 3: I1121 09:34:45.830173 15992 hierarchical.cpp:1457] Performed allocation for 1 agents in 188754ns 3: I1121 09:34:45.830466 15999 master.cpp:7103] Ignoring update on agent 590149c1-4db8-4780-a82a-39a87559d9e0-S0 at slave(689)@172.17.0.5:41974 (5cd14b7e5105) as it reports no changes 3: I1121 09:34:45.831758 16003 process.cpp:3503] Handling HTTP event for process 'master' with path: '/master/reserve' 3: I1121 09:34:45.833181 16007 http.cpp:1185] HTTP POST for /master/reserve from 172.17.0.5:36020 3: I1121 09:34:45.834170 16007 master.cpp:3657] Authorizing principal 'test-principal' to reserve resources '[{"name":"cpus","reservations":[{"principal":"test-principal","role":"superhero","type":"DYNAMIC"}],"scalar":{"value":1.0},"type":"SCALAR"},{"name":"mem","reservations":[{"principal":"test-principal","role":"superhero","type":"DYNAMIC"}],"scalar":{"value":12.0},"type":"SCALAR"}]' 3: I1121 09:34:45.839368 16013 master.cpp:9990] Sending updated checkpointed resources cpus(reservations: [(DYNAMIC,superhero,test-principal)]):1; mem(reservations: [(DYNAMIC,superhero,test-principal)]):12 to agent 590149c1-4db8-4780-a82a-39a87559d9e0-S0 at slave(689)@172.17.0.5:41974 (5cd14b7e5105) 3: I1121 09:34:45.840593 15998 slave.cpp:3587] Updated checkpointed resources from {} to cpus(reservations: [(DYNAMIC,superhero,test-principal)]):1; mem(reservations: [(DYNAMIC,superhero,test-principal)]):12 3: I1121 09:34:45.842092 16003 process.cpp:3503] Handling HTTP event for process 'master' with path: '/master/api/v1' 3: I1121 09:34:45.843480 16004 http.cpp:1185] HTTP POST for /master/api/v1 from 172.17.0.5:36022 3: I1121 09:34:45.843613 16004 http.cpp:673] Processing call GET_AGENTS 3: I1121 09:34:45.847630 15998 process.cpp:3503] Handling HTTP event for process 'master' with path: '/master/api/v1' 3: I1121 09:34:45.848915 15997 http.cpp:1185] HTTP POST for /master/api/v1 from 172.17.0.5:36024 3: I1121 09:34:45.849053 15997 http.cpp:673] Processing call GET_AGENTS 3: I1121 09:34:45.852840 15991 slave.cpp:883] Agent terminating 3: I1121 09:34:45.853024 15997 master.cpp:1311] Agent 590149c1-4db8-4780-a82a-39a87559d9e0-S0 at slave(689)@172.17.0.5:41974 (5cd14b7e5105) disconnected 3: I1121 09:34:45.853049 15997 master.cpp:3370] Disconnecting agent 590149c1-4db8-4780-a82a-39a87559d9e0-S0 at slave(689)@172.17.0.5:41974 (5cd14b7e5105) 3: I1121 09:34:45.853106 15997 master.cpp:3389] Deactivating agent 590149c1-4db8-4780-a82a-39a87559d9e0-S0 at slave(689)@172.17.0.5:41974 (5cd14b7e5105) 3: I1121 09:34:45.853271 16013 hierarchical.cpp:697] Agent 590149c1-4db8-4780-a82a-39a87559d9e0-S0 deactivated 3: I1121 09:34:45.858248 15991 master.cpp:1153] Master terminating 3: I1121 09:34:45.860453 16011 hierarchical.cpp:633] Removed agent 590149c1-4db8-4780-a82a-39a87559d9e0-S0 3: [ OK ] ContentType/MasterAPITest.GetAgentsFiltering/0 (72 ms) 3: [ RUN ] ContentType/MasterAPITest.GetAgentsFiltering/1 3: I1121 09:34:45.865167 15991 cluster.cpp:162] Creating default 'local' authorizer 3: I1121 09:34:45.868821 15995 master.cpp:448] Master ce14ca8c-325e-4fc4-bc3f-3909df366818 (5cd14b7e5105) started on 172.17.0.5:41974 3: I1121 09:34:45.868842 15995 master.cpp:450] Flags at startup: --acls="view_roles { 3: principals { 3: values: "test-principal" 3: } 3: roles { 3: values: "superhero" 3: } 3: } 3: view_roles { 3: principals { 3: values: "test-principal" 3: } 3: roles { 3: type: NONE 3: } 3: } 3: view_roles { 3: principals { 3: values: "test-principal-2" 3: } 3: roles { 3: values: "muggle" 3: } 3: } 3: view_roles { 3: principals { 3: values: "test-principal-2" 3: } 3: roles { 3: type: NONE 3: } 3: } 3: " --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/PK0Mim/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/PK0Mim/master" --zk_session_timeout="10secs" 3: I1121 09:34:45.869202 15995 master.cpp:499] Master only allowing authenticated frameworks to register 3: I1121 09:34:45.869210 15995 master.cpp:505] Master only allowing authenticated agents to register 3: I1121 09:34:45.869215 15995 master.cpp:511] Master only allowing authenticated HTTP frameworks to register 3: I1121 09:34:45.869220 15995 credentials.hpp:37] Loading credentials for authentication from '/tmp/PK0Mim/credentials' 3: I1121 09:34:45.869472 15995 master.cpp:555] Using default 'crammd5' authenticator 3: I1121 09:34:45.869611 15995 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' 3: I1121 09:34:45.869746 15995 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' 3: I1121 09:34:45.869864 15995 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' 3: I1121 09:34:45.869971 15995 master.cpp:634] Authorization enabled 3: I1121 09:34:45.870100 16006 hierarchical.cpp:173] Initialized hierarchical allocator process 3: I1121 09:34:45.870121 15999 whitelist_watcher.cpp:77] No whitelist given 3: I1121 09:34:45.872800 16015 master.cpp:2215] Elected as the leading master! 3: I1121 09:34:45.872828 16015 master.cpp:1695] Recovering from registrar 3: I1121 09:34:45.872997 15993 registrar.cpp:347] Recovering registrar 3: I1121 09:34:45.873575 15993 registrar.cpp:391] Successfully fetched the registry (0B) in 541952ns 3: I1121 09:34:45.873670 15993 registrar.cpp:495] Applied 1 operations in 25765ns; attempting to update the registry 3: I1121 09:34:45.874258 15993 registrar.cpp:552] Successfully updated the registry in 450048ns 3: I1121 09:34:45.874369 15993 registrar.cpp:424] Successfully recovered registrar 3: I1121 09:34:45.874737 15992 master.cpp:1808] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register 3: I1121 09:34:45.874756 16001 hierarchical.cpp:211] Skipping recovery of hierarchical allocator: nothing to recover 3: W1121 09:34:45.879329 15991 process.cpp:2756] Attempted to spawn already running process [email protected]:41974 3: I1121 09:34:45.880198 15991 containerizer.cpp:301] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } 3: W1121 09:34:45.880764 15991 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges 3: W1121 09:34:45.880868 15991 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges 3: I1121 09:34:45.880898 15991 provisioner.cpp:259] Using default backend 'copy' 3: I1121 09:34:45.882656 15991 cluster.cpp:448] Creating default 'local' authorizer 3: I1121 09:34:45.884572 16002 slave.cpp:262] Mesos agent started on (690)@172.17.0.5:41974 3: I1121 09:34:45.884591 16002 slave.cpp:263] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/ContentType_MasterAPITest_GetAgentsFiltering_1_VQOpsp/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/ContentType_MasterAPITest_GetAgentsFiltering_1_VQOpsp/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_GetAgentsFiltering_1_VQOpsp/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/ContentType_MasterAPITest_GetAgentsFiltering_1_VQOpsp/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_GetAgentsFiltering_1_VQOpsp/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(muggle):1;cpus(*):2;gpus(*):0;mem(muggle):1024;mem(*):1024;disk(muggle):1024;disk(*):1024;ports(muggle):[30000-30999];ports(*):[31000-32000]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/ContentType_MasterAPITest_GetAgentsFiltering_1_VQOpsp" --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_GetAgentsFiltering_1_8RWASn" --zk_session_timeout="10secs" 3: I1121 09:34:45.884959 16002 credentials.hpp:86] Loading credential for authentication from '/tmp/ContentType_MasterAPITest_GetAgentsFiltering_1_VQOpsp/credential' 3: I1121 09:34:45.885102 16002 slave.cpp:295] Agent using credential for: test-principal 3: I1121 09:34:45.885119 16002 credentials.hpp:37] Loading credentials for authentication from '/tmp/ContentType_MasterAPITest_GetAgentsFiltering_1_VQOpsp/http_credentials' 3: I1121 09:34:45.885324 16002 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' 3: I1121 09:34:45.885457 16002 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite' 3: I1121 09:34:45.887948 16002 slave.cpp:593] Agent resources: [{"name":"cpus","reservations":[{"role":"muggle","type":"STATIC"}],"scalar":{"value":1.0},"type":"SCALAR"},{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","reservations":[{"role":"muggle","type":"STATIC"}],"scalar":{"value":1024.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","reservations":[{"role":"muggle","type":"STATIC"}],"scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":30000,"end":30999}]},"reservations":[{"role":"muggle","type":"STATIC"}],"type":"RANGES"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] 3: I1121 09:34:45.888445 16002 slave.cpp:601] Agent attributes: [ ] 3: I1121 09:34:45.888456 16002 slave.cpp:610] Agent hostname: 5cd14b7e5105 3: I1121 09:34:45.888630 15994 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I1121 09:34:45.890048 16011 state.cpp:64] Recovering state from '/tmp/ContentType_MasterAPITest_GetAgentsFiltering_1_8RWASn/meta' 3: I1121 09:34:45.890375 15993 task_status_update_manager.cpp:207] Recovering task status update manager 3: I1121 09:34:45.890549 16004 containerizer.cpp:668] Recovering containerizer 3: I1121 09:34:45.892027 16009 provisioner.cpp:455] Provisioner recovery complete 3: I1121 09:34:45.892335 15994 slave.cpp:6443] Finished recovery 3: I1121 09:34:45.893009 16002 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I1121 09:34:45.893043 16007 slave.cpp:1007] New master detected at [email protected]:41974 3: I1121 09:34:45.893170 16007 slave.cpp:1042] Detecting new master 3: I1121 09:34:45.902454 16013 slave.cpp:1069] Authenticating with master [email protected]:41974 3: I1121 09:34:45.902521 16013 slave.cpp:1078] Using default CRAM-MD5 authenticatee 3: I1121 09:34:45.902771 16008 authenticatee.cpp:121] Creating new client SASL connection 3: I1121 09:34:45.903144 15993 master.cpp:8306] Authenticating slave(690)@172.17.0.5:41974 3: I1121 09:34:45.903312 16012 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1333)@172.17.0.5:41974 3: I1121 09:34:45.903539 16006 authenticator.cpp:98] Creating new server SASL connection 3: I1121 09:34:45.903766 16003 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1121 09:34:45.903792 16003 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1121 09:34:45.903910 16005 authenticator.cpp:204] Received SASL authentication start 3: I1121 09:34:45.903970 16005 authenticator.cpp:326] Authentication requires more steps 3: I1121 09:34:45.904070 16001 authenticatee.cpp:259] Received SASL authentication step 3: I1121 09:34:45.904189 15999 authenticator.cpp:232] Received SASL authentication step 3: I1121 09:34:45.904218 15999 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '5cd14b7e5105' server FQDN: '5cd14b7e5105' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1121 09:34:45.904232 15999 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1121 09:34:45.904263 15999 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1121 09:34:45.904281 15999 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '5cd14b7e5105' server FQDN: '5cd14b7e5105' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1121 09:34:45.904289 15999 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1121 09:34:45.904294 15999 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1121 09:34:45.904305 15999 authenticator.cpp:318] Authentication success 3: I1121 09:34:45.904383 15992 authenticatee.cpp:299] Authentication success 3: I1121 09:34:45.904444 16004 master.cpp:8336] Successfully authenticated principal 'test-principal' at slave(690)@172.17.0.5:41974 3: I1121 09:34:45.904503 16010 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1333)@172.17.0.5:41974 3: I1121 09:34:45.904701 16014 slave.cpp:1161] Successfully authenticated with master [email protected]:41974 3: I1121 09:34:45.904940 16014 slave.cpp:1682] Will retry registration in 3.368264ms if necessary 3: I1121 09:34:45.905171 15996 master.cpp:6036] Received register agent message from slave(690)@172.17.0.5:41974 (5cd14b7e5105) 3: I1121 09:34:45.905300 15996 master.cpp:3872] Authorizing agent with principal 'test-principal' 3: I1121 09:34:45.905689 16000 master.cpp:6098] Authorized registration of agent at slave(690)@172.17.0.5:41974 (5cd14b7e5105) 3: I1121 09:34:45.905795 16000 master.cpp:6191] Registering agent at slave(690)@172.17.0.5:41974 (5cd14b7e5105) with id ce14ca8c-325e-4fc4-bc3f-3909df366818-S0 3: I1121 09:34:45.906198 15997 registrar.cpp:495] Applied 1 operations in 59713ns; attempting to update the registry 3: I1121 09:34:45.906684 15997 registrar.cpp:552] Successfully updated the registry in 434944ns 3: I1121 09:34:45.906899 16008 master.cpp:6240] Admitted agent ce14ca8c-325e-4fc4-bc3f-3909df366818-S0 at slave(690)@172.17.0.5:41974 (5cd14b7e5105) 3: I1121 09:34:45.907858 16012 slave.cpp:1207] Registered with master [email protected]:41974; given agent ID ce14ca8c-325e-4fc4-bc3f-3909df366818-S0 3: I1121 09:34:45.907963 15992 task_status_update_manager.cpp:188] Resuming sending task status updates 3: I1121 09:34:45.908146 16012 slave.cpp:1227] Checkpointing SlaveInfo to '/tmp/ContentType_MasterAPITest_GetAgentsFiltering_1_8RWASn/meta/slaves/ce14ca8c-325e-4fc4-bc3f-3909df366818-S0/slave.info' 3: I1121 09:34:45.907691 16008 master.cpp:6273] Registered agent ce14ca8c-325e-4fc4-bc3f-3909df366818-S0 at slave(690)@172.17.0.5:41974 (5cd14b7e5105) with [{"name":"cpus","reservations":[{"role":"muggle","type":"STATIC"}],"scalar":{"value":1.0},"type":"SCALAR"},{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","reservations":[{"role":"muggle","type":"STATIC"}],"scalar":{"value":1024.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","reservations":[{"role":"muggle","type":"STATIC"}],"scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":30000,"end":30999}]},"reservations":[{"role":"muggle","type":"STATIC"}],"type":"RANGES"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] 3: I1121 09:34:45.908522 16012 slave.cpp:1295] Forwarding total oversubscribed resources {} 3: I1121 09:34:45.908550 16006 hierarchical.cpp:600] Added agent ce14ca8c-325e-4fc4-bc3f-3909df366818-S0 (5cd14b7e5105) with cpus(reservations: [(STATIC,muggle)]):1; cpus:2; mem(reservations: [(STATIC,muggle)]):1024; mem:1024; disk(reservations: [(STATIC,muggle)]):1024; disk:1024; ports(reservations: [(STATIC,muggle)]):[30000-30999]; ports:[31000-32000] (allocated: {}) 3: I1121 09:34:45.908730 16015 master.cpp:7085] Received update of agent ce14ca8c-325e-4fc4-bc3f-3909df366818-S0 at slave(690)@172.17.0.5:41974 (5cd14b7e5105) with total oversubscribed resources {} 3: I1121 09:34:45.909010 16006 hierarchical.cpp:1457] Performed allocation for 1 agents in 231960ns 3: I1121 09:34:45.909202 16015 master.cpp:7103] Ignoring update on agent ce14ca8c-325e-4fc4-bc3f-3909df366818-S0 at slave(690)@172.17.0.5:41974 (5cd14b7e5105) as it reports no changes 3: I1121 09:34:45.910488 16014 process.cpp:3503] Handling HTTP event for process 'master' with path: '/master/reserve' 3: I1121 09:34:45.911736 16013 http.cpp:1185] HTTP POST for /master/reserve from 172.17.0.5:36026 3: I1121 09:34:45.912390 16013 master.cpp:3657] Authorizing principal 'test-principal' to reserve resources '[{"name":"cpus","reservations":[{"principal":"test-principal","role":"superhero","type":"DYNAMIC"}],"scalar":{"value":1.0},"type":"SCALAR"},{"name":"mem","reservations":[{"principal":"test-principal","role":"superhero","type":"DYNAMIC"}],"scalar":{"value":12.0},"type":"SCALAR"}]' 3: I1121 09:34:45.919219 15992 master.cpp:9990] Sending updated checkpointed resources cpus(reservations: [(DYNAMIC,superhero,test-principal)]):1; mem(reservations: [(DYNAMIC,superhero,test-principal)]):12 to agent ce14ca8c-325e-4fc4-bc3f-3909df366818-S0 at slave(690)@172.17.0.5:41974 (5cd14b7e5105) 3: I1121 09:34:45.920274 15992 slave.cpp:3587] Updated checkpointed resources from {} to cpus(reservations: [(DYNAMIC,superhero,test-principal)]):1; mem(reservations: [(DYNAMIC,superhero,test-principal)]):12 3: I1121 09:34:45.921337 16007 process.cpp:3503] Handling HTTP event for process 'master' with path: '/master/api/v1' 3: I1121 09:34:45.922523 16005 http.cpp:1185] HTTP POST for /master/api/v1 from 172.17.0.5:36028 3: I1121 09:34:45.922662 16005 http.cpp:673] Processing call GET_AGENTS 3: I1121 09:34:45.929505 16014 process.cpp:3503] Handling HTTP event for process 'master' with path: '/master/api/v1' 3: I1121 09:34:45.930857 16011 http.cpp:1185] HTTP POST for /master/api/v1 from 172.17.0.5:36030 3: I1121 09:34:45.930953 16011 http.cpp:673] Processing call GET_AGENTS 3: I1121 09:34:45.938333 16007 slave.cpp:883] Agent terminating 3: I1121 09:34:45.938499 15997 master.cpp:1311] Agent ce14ca8c-325e-4fc4-bc3f-3909df366818-S0 at slave(690)@172.17.0.5:41974 (5cd14b7e5105) disconnected 3: I1121 09:34:45.938525 15997 master.cpp:3370] Disconnecting agent ce14ca8c-325e-4fc4-bc3f-3909df366818-S0 at slave(690)@172.17.0.5:41974 (5cd14b7e5105) 3: I1121 09:34:45.938578 15997 master.cpp:3389] Deactivating agent ce14ca8c-325e-4fc4-bc3f-3909df366818-S0 at slave(690)@172.17.0.5:41974 (5cd14b7e5105) 3: I1121 09:34:45.938705 16006 hierarchical.cpp:697] Agent ce14ca8c-325e-4fc4-bc3f-3909df366818-S0 deactivated 3: I1121 09:34:45.944052 16010 master.cpp:1153] Master terminating 3: I1121 09:34:45.946041 16009 hierarchical.cpp:633] Removed agent ce14ca8c-325e-4fc4-bc3f-3909df366818-S0 3: [ OK ] ContentType/MasterAPITest.GetAgentsFiltering/1 (85 ms) 3: [ RUN ] ContentType/MasterAPITest.GetRecoveredAgents/0 3: I1121 09:34:45.951022 15991 cluster.cpp:162] Creating default 'local' authorizer 3: I1121 09:34:45.958523 15991 leveldb.cpp:174] Opened db in 7.167774ms 3: I1121 09:34:45.960103 15991 leveldb.cpp:181] Compacted db in 1.520048ms 3: I1121 09:34:45.960145 15991 leveldb.cpp:196] Created db iterator in 7122ns 3: I1121 09:34:45.960156 15991 leveldb.cpp:202] Seeked to beginning of db in 1151ns 3: I1121 09:34:45.960163 15991 leveldb.cpp:271] Iterated through 0 keys in the db in 573ns 3: I1121 09:34:45.960220 15991 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned 3: I1121 09:34:45.961067 15997 recover.cpp:451] Starting replica recovery 3: I1121 09:34:45.961316 16012 recover.cpp:477] Replica is in EMPTY status 3: I1121 09:34:45.962352 16014 replica.cpp:676] Replica in EMPTY status received a broadcasted recover request from __req_res__(1747)@172.17.0.5:41974 3: I1121 09:34:45.962785 15994 recover.cpp:197] Received a recover response from a replica in EMPTY status 3: I1121 09:34:45.963182 16013 recover.cpp:568] Updating replica status to STARTING 3: I1121 09:34:45.964409 15997 master.cpp:448] Master 57ba372b-1f8f-4e3d-87e1-64085df2c87b (5cd14b7e5105) started on 172.17.0.5:41974 3: I1121 09:34:45.964424 16009 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.134668ms 3: I1121 09:34:45.964452 16009 replica.cpp:322] Persisted replica status to STARTING 3: I1121 09:34:45.964707 16015 recover.cpp:477] Replica is in STARTING status write /dev/stdout: resource temporarily unavailable + docker rmi mesos-1511254725-17208 Build step 'Execute shell' marked build as failure
