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=ubuntu%3A14.04,label_exp=(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23)/4562/display/redirect?page=changes>
Changes: [gregorywmann] Renamed the resource provider PUBLISH event to PUBLISH_RESOURCES. [gregorywmann] Renamed a resource provider call to UPDATE_PUBLISH_RESOURCES_STATUS. [gregorywmann] Changed the resource provider OPERATION event to APPLY_OFFER_OPERATION. ------------------------------------------ [...truncated 13.68 MB...] 3: I1208 15:21:23.688980 17438 master.cpp:507] Master only allowing authenticated frameworks to register 3: I1208 15:21:23.688990 17438 master.cpp:513] Master only allowing authenticated agents to register 3: I1208 15:21:23.688995 17438 master.cpp:519] Master only allowing authenticated HTTP frameworks to register 3: I1208 15:21:23.689002 17438 credentials.hpp:37] Loading credentials for authentication from '/tmp/KSTEpS/credentials' 3: I1208 15:21:23.689381 17438 master.cpp:563] Using default 'crammd5' authenticator 3: I1208 15:21:23.689610 17438 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' 3: I1208 15:21:23.689851 17438 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' 3: I1208 15:21:23.690043 17438 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' 3: I1208 15:21:23.690240 17438 master.cpp:642] Authorization enabled 3: I1208 15:21:23.690544 17430 hierarchical.cpp:175] Initialized hierarchical allocator process 3: I1208 15:21:23.690613 17436 whitelist_watcher.cpp:77] No whitelist given 3: I1208 15:21:23.694710 17433 master.cpp:2214] Elected as the leading master! 3: I1208 15:21:23.694748 17433 master.cpp:1694] Recovering from registrar 3: I1208 15:21:23.694993 17432 registrar.cpp:347] Recovering registrar 3: I1208 15:21:23.695778 17432 registrar.cpp:391] Successfully fetched the registry (0B) in 0ns 3: I1208 15:21:23.695893 17432 registrar.cpp:495] Applied 1 operations in 34035ns; attempting to update the registry 3: I1208 15:21:23.696578 17432 registrar.cpp:552] Successfully updated the registry in 0ns 3: I1208 15:21:23.696715 17432 registrar.cpp:424] Successfully recovered registrar 3: I1208 15:21:23.697294 17423 master.cpp:1807] Recovered 0 agents from the registry (135B); allowing 10mins for agents to re-register 3: I1208 15:21:23.697312 17440 hierarchical.cpp:213] Skipping recovery of hierarchical allocator: nothing to recover 3: W1208 15:21:23.703959 17421 process.cpp:2756] Attempted to spawn already running process [email protected]:39478 3: I1208 15:21:23.704329 17421 cluster.cpp:460] Creating default 'local' authorizer 3: I1208 15:21:23.707327 17431 slave.cpp:258] Mesos agent started on (317)@172.17.0.2:39478 3: I1208 15:21:23.707351 17431 slave.cpp:259] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/MasterAllocatorTest_1_NestedRoles_s4VKeq/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/MasterAllocatorTest_1_NestedRoles_s4VKeq/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/MasterAllocatorTest_1_NestedRoles_s4VKeq/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/MasterAllocatorTest_1_NestedRoles_s4VKeq/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/MasterAllocatorTest_1_NestedRoles_s4VKeq/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" --reconfiguration_policy="equal" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;mem:1024" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/MasterAllocatorTest_1_NestedRoles_s4VKeq" --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/MasterAllocatorTest_1_NestedRoles_ZIjckE" --zk_session_timeout="10secs" 3: I1208 15:21:23.707778 17431 credentials.hpp:86] Loading credential for authentication from '/tmp/MasterAllocatorTest_1_NestedRoles_s4VKeq/credential' 3: I1208 15:21:23.707950 17431 slave.cpp:291] Agent using credential for: test-principal 3: I1208 15:21:23.707972 17431 credentials.hpp:37] Loading credentials for authentication from '/tmp/MasterAllocatorTest_1_NestedRoles_s4VKeq/http_credentials' 3: W1208 15:21:23.708014 17421 process.cpp:2756] Attempted to spawn already running process [email protected]:39478 3: I1208 15:21:23.708240 17431 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' 3: I1208 15:21:23.708421 17431 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite' 3: I1208 15:21:23.709761 17421 sched.cpp:232] Version: 1.5.0 3: I1208 15:21:23.710038 17431 slave.cpp:590] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":367463.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] 3: I1208 15:21:23.710310 17428 hierarchical.cpp:1513] Performed allocation for 0 agents in 56773ns 3: I1208 15:21:23.710321 17431 slave.cpp:598] Agent attributes: [ ] 3: I1208 15:21:23.710355 17431 slave.cpp:607] Agent hostname: 2b0fbe914a69 3: I1208 15:21:23.710551 17442 sched.cpp:336] New master detected at [email protected]:39478 3: I1208 15:21:23.710613 17436 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I1208 15:21:23.710739 17442 sched.cpp:396] Authenticating with master [email protected]:39478 3: I1208 15:21:23.710765 17442 sched.cpp:403] Using default CRAM-MD5 authenticatee 3: I1208 15:21:23.711191 17426 authenticatee.cpp:121] Creating new client SASL connection 3: I1208 15:21:23.711639 17435 master.cpp:8830] Authenticating [email protected]:39478 3: I1208 15:21:23.711864 17424 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(629)@172.17.0.2:39478 3: I1208 15:21:23.712321 17433 authenticator.cpp:98] Creating new server SASL connection 3: I1208 15:21:23.712604 17437 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1208 15:21:23.712637 17437 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1208 15:21:23.712822 17427 state.cpp:66] Recovering state from '/tmp/MasterAllocatorTest_1_NestedRoles_ZIjckE/meta' 3: I1208 15:21:23.712851 17437 authenticator.cpp:204] Received SASL authentication start 3: I1208 15:21:23.712914 17437 authenticator.cpp:326] Authentication requires more steps 3: I1208 15:21:23.713076 17441 authenticatee.cpp:259] Received SASL authentication step 3: I1208 15:21:23.713289 17439 task_status_update_manager.cpp:207] Recovering task status update manager 3: I1208 15:21:23.713309 17441 authenticator.cpp:232] Received SASL authentication step 3: I1208 15:21:23.713340 17441 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2b0fbe914a69' server FQDN: '2b0fbe914a69' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1208 15:21:23.713356 17441 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1208 15:21:23.713405 17441 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1208 15:21:23.713429 17441 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2b0fbe914a69' server FQDN: '2b0fbe914a69' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1208 15:21:23.713438 17441 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1208 15:21:23.713444 17441 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1208 15:21:23.713462 17441 authenticator.cpp:318] Authentication success 3: I1208 15:21:23.713594 17438 authenticatee.cpp:299] Authentication success 3: I1208 15:21:23.713748 17423 master.cpp:8860] Successfully authenticated principal 'test-principal' at [email protected]:39478 3: I1208 15:21:23.713853 17438 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(629)@172.17.0.2:39478 3: I1208 15:21:23.713990 17443 slave.cpp:6696] Finished recovery 3: I1208 15:21:23.714025 17436 sched.cpp:502] Successfully authenticated with master [email protected]:39478 3: I1208 15:21:23.714046 17436 sched.cpp:824] Sending SUBSCRIBE call to [email protected]:39478 3: I1208 15:21:23.714201 17436 sched.cpp:857] Will retry registration in 267.230861ms if necessary 3: I1208 15:21:23.714494 17424 master.cpp:2962] Received SUBSCRIBE call for framework 'default' at [email protected]:39478 3: I1208 15:21:23.714608 17424 master.cpp:2279] Authorizing framework principal 'test-principal' to receive offers for roles '{ a/b }' 3: I1208 15:21:23.714998 17442 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I1208 15:21:23.715004 17431 slave.cpp:1031] New master detected at [email protected]:39478 3: I1208 15:21:23.715116 17431 slave.cpp:1086] Detecting new master 3: I1208 15:21:23.715278 17437 master.cpp:3042] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ] 3: I1208 15:21:23.715538 17437 master.cpp:9051] Adding framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 (default) at [email protected]:39478 with roles { } suppressed 3: I1208 15:21:23.716220 17422 sched.cpp:751] Framework registered with ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 3: I1208 15:21:23.716272 17422 sched.cpp:765] Scheduler::registered took 23892ns 3: I1208 15:21:23.716365 17432 slave.cpp:1113] Authenticating with master [email protected]:39478 3: I1208 15:21:23.716437 17445 hierarchical.cpp:297] Added framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 3: I1208 15:21:23.716444 17432 slave.cpp:1122] Using default CRAM-MD5 authenticatee 3: I1208 15:21:23.716666 17445 hierarchical.cpp:1513] Performed allocation for 0 agents in 76846ns 3: I1208 15:21:23.716725 17440 authenticatee.cpp:121] Creating new client SASL connection 3: I1208 15:21:23.717003 17430 master.cpp:8830] Authenticating slave(317)@172.17.0.2:39478 3: I1208 15:21:23.717118 17423 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(630)@172.17.0.2:39478 3: I1208 15:21:23.717401 17441 authenticator.cpp:98] Creating new server SASL connection 3: I1208 15:21:23.717650 17426 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1208 15:21:23.717674 17426 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1208 15:21:23.717819 17425 authenticator.cpp:204] Received SASL authentication start 3: I1208 15:21:23.717885 17425 authenticator.cpp:326] Authentication requires more steps 3: I1208 15:21:23.718001 17435 authenticatee.cpp:259] Received SASL authentication step 3: I1208 15:21:23.718137 17438 authenticator.cpp:232] Received SASL authentication step 3: I1208 15:21:23.718168 17438 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2b0fbe914a69' server FQDN: '2b0fbe914a69' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1208 15:21:23.718180 17438 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1208 15:21:23.718204 17438 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1208 15:21:23.718230 17438 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2b0fbe914a69' server FQDN: '2b0fbe914a69' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1208 15:21:23.718242 17438 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1208 15:21:23.718248 17438 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1208 15:21:23.718261 17438 authenticator.cpp:318] Authentication success 3: I1208 15:21:23.718351 17436 authenticatee.cpp:299] Authentication success 3: I1208 15:21:23.718425 17443 master.cpp:8860] Successfully authenticated principal 'test-principal' at slave(317)@172.17.0.2:39478 3: I1208 15:21:23.718533 17424 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(630)@172.17.0.2:39478 3: I1208 15:21:23.718694 17433 slave.cpp:1205] Successfully authenticated with master [email protected]:39478 3: I1208 15:21:23.718973 17433 slave.cpp:1748] Will retry registration in 19.926607ms if necessary 3: I1208 15:21:23.719223 17444 master.cpp:6084] Received register agent message from slave(317)@172.17.0.2:39478 (2b0fbe914a69) 3: I1208 15:21:23.719419 17444 master.cpp:3871] Authorizing agent with principal 'test-principal' 3: I1208 15:21:23.720008 17429 master.cpp:6160] Authorized registration of agent at slave(317)@172.17.0.2:39478 (2b0fbe914a69) 3: I1208 15:21:23.720134 17429 master.cpp:6253] Registering agent at slave(317)@172.17.0.2:39478 (2b0fbe914a69) with id ec2a4715-88b5-4d62-95f3-be96a6f88f90-S0 3: I1208 15:21:23.720965 17439 registrar.cpp:495] Applied 1 operations in 161197ns; attempting to update the registry 3: I1208 15:21:23.722055 17439 registrar.cpp:552] Successfully updated the registry in 0ns 3: I1208 15:21:23.722472 17440 master.cpp:6302] Admitted agent ec2a4715-88b5-4d62-95f3-be96a6f88f90-S0 at slave(317)@172.17.0.2:39478 (2b0fbe914a69) 3: I1208 15:21:23.723672 17440 master.cpp:6338] Registered agent ec2a4715-88b5-4d62-95f3-be96a6f88f90-S0 at slave(317)@172.17.0.2:39478 (2b0fbe914a69) with cpus:2; mem:1024; disk:367463; ports:[31000-32000] 3: I1208 15:21:23.723757 17423 slave.cpp:1251] Registered with master [email protected]:39478; given agent ID ec2a4715-88b5-4d62-95f3-be96a6f88f90-S0 3: I1208 15:21:23.723964 17425 task_status_update_manager.cpp:188] Resuming sending task status updates 3: I1208 15:21:23.724416 17423 slave.cpp:1271] Checkpointing SlaveInfo to '/tmp/MasterAllocatorTest_1_NestedRoles_ZIjckE/meta/slaves/ec2a4715-88b5-4d62-95f3-be96a6f88f90-S0/slave.info' 3: I1208 15:21:23.724562 17441 hierarchical.cpp:572] Added agent ec2a4715-88b5-4d62-95f3-be96a6f88f90-S0 (2b0fbe914a69) with cpus:2; mem:1024; disk:367463; ports:[31000-32000] (allocated: {}) 3: I1208 15:21:23.725064 17423 slave.cpp:1350] Forwarding total oversubscribed resources {} 3: I1208 15:21:23.725318 17436 master.cpp:7245] Received update of agent ec2a4715-88b5-4d62-95f3-be96a6f88f90-S0 at slave(317)@172.17.0.2:39478 (2b0fbe914a69) with total oversubscribed resources {} 3: I1208 15:21:23.725535 17436 master.cpp:7288] Ignoring update on agent ec2a4715-88b5-4d62-95f3-be96a6f88f90-S0 at slave(317)@172.17.0.2:39478 (2b0fbe914a69) as it reports no changes 3: I1208 15:21:23.726424 17441 hierarchical.cpp:1513] Performed allocation for 1 agents in 1.615852ms 3: I1208 15:21:23.727022 17438 master.cpp:8660] Sending 1 offers to framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 (default) at [email protected]:39478 3: I1208 15:21:23.728726 17443 sched.cpp:921] Scheduler::resourceOffers took 1.19847ms 3: I1208 15:21:23.730278 17434 master.cpp:10580] Removing offer ec2a4715-88b5-4d62-95f3-be96a6f88f90-O0 3: I1208 15:21:23.730461 17434 master.cpp:4278] Processing ACCEPT call for offers: [ ec2a4715-88b5-4d62-95f3-be96a6f88f90-O0 ] on agent ec2a4715-88b5-4d62-95f3-be96a6f88f90-S0 at slave(317)@172.17.0.2:39478 (2b0fbe914a69) for framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 (default) at [email protected]:39478 3: I1208 15:21:23.730573 17434 master.cpp:3598] Authorizing framework principal 'test-principal' to launch task 0 3: W1208 15:21:23.732872 17427 validation.cpp:1388] Executor 'default' for task '0' uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases. 3: W1208 15:21:23.732924 17427 validation.cpp:1400] Executor 'default' for task '0' uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases. 3: I1208 15:21:23.733517 17427 master.cpp:11332] Adding task 0 with resources cpus(allocated: a/b):2; mem(allocated: a/b):1024 on agent ec2a4715-88b5-4d62-95f3-be96a6f88f90-S0 at slave(317)@172.17.0.2:39478 (2b0fbe914a69) 3: I1208 15:21:23.733871 17427 master.cpp:5026] Launching task 0 of framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 (default) at [email protected]:39478 with resources [{"allocation_info":{"role":"a\/b"},"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"allocation_info":{"role":"a\/b"},"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}] on agent ec2a4715-88b5-4d62-95f3-be96a6f88f90-S0 at slave(317)@172.17.0.2:39478 (2b0fbe914a69) 3: I1208 15:21:23.734766 17433 slave.cpp:1869] Got assigned task '0' for framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 3: I1208 15:21:23.735707 17433 slave.cpp:2137] Authorizing task '0' for framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 3: I1208 15:21:23.735800 17433 slave.cpp:7617] Authorizing framework principal 'test-principal' to launch task 0 3: I1208 15:21:23.735865 17444 hierarchical.cpp:1188] Recovered ports(allocated: a/b):[31000-32000]; disk(allocated: a/b):367463 (total: cpus:2; mem:1024; disk:367463; ports:[31000-32000], allocated: cpus(allocated: a/b):2; mem(allocated: a/b):1024) on agent ec2a4715-88b5-4d62-95f3-be96a6f88f90-S0 from framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 3: I1208 15:21:23.735975 17444 hierarchical.cpp:1234] Framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 filtered agent ec2a4715-88b5-4d62-95f3-be96a6f88f90-S0 for 5secs 3: I1208 15:21:23.736850 17422 slave.cpp:2305] Launching task '0' for framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 3: I1208 15:21:23.737376 17422 paths.cpp:702] Trying to chown '/tmp/MasterAllocatorTest_1_NestedRoles_ZIjckE/slaves/ec2a4715-88b5-4d62-95f3-be96a6f88f90-S0/frameworks/ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000/executors/default/runs/89a8de5a-b3cd-4a55-b1a5-34f3f01e0ba1' to user 'mesos' 3: I1208 15:21:23.737623 17422 slave.cpp:8091] Launching executor 'default' of framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 with resources [] in work directory '/tmp/MasterAllocatorTest_1_NestedRoles_ZIjckE/slaves/ec2a4715-88b5-4d62-95f3-be96a6f88f90-S0/frameworks/ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000/executors/default/runs/89a8de5a-b3cd-4a55-b1a5-34f3f01e0ba1' 3: I1208 15:21:23.738117 17422 slave.cpp:2999] Launching container 89a8de5a-b3cd-4a55-b1a5-34f3f01e0ba1 for executor 'default' of framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 3: I1208 15:21:23.738592 17422 slave.cpp:2533] Queued task '0' for executor 'default' of framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 3: I1208 15:21:23.738678 17422 slave.cpp:982] Successfully attached '/tmp/MasterAllocatorTest_1_NestedRoles_ZIjckE/slaves/ec2a4715-88b5-4d62-95f3-be96a6f88f90-S0/frameworks/ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000/executors/default/runs/89a8de5a-b3cd-4a55-b1a5-34f3f01e0ba1' to virtual path '/tmp/MasterAllocatorTest_1_NestedRoles_ZIjckE/slaves/ec2a4715-88b5-4d62-95f3-be96a6f88f90-S0/frameworks/ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000/executors/default/runs/latest' 3: I1208 15:21:23.738718 17422 slave.cpp:982] Successfully attached '/tmp/MasterAllocatorTest_1_NestedRoles_ZIjckE/slaves/ec2a4715-88b5-4d62-95f3-be96a6f88f90-S0/frameworks/ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000/executors/default/runs/89a8de5a-b3cd-4a55-b1a5-34f3f01e0ba1' to virtual path '/frameworks/ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000/executors/default/runs/latest' 3: I1208 15:21:23.738749 17422 slave.cpp:982] Successfully attached '/tmp/MasterAllocatorTest_1_NestedRoles_ZIjckE/slaves/ec2a4715-88b5-4d62-95f3-be96a6f88f90-S0/frameworks/ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000/executors/default/runs/89a8de5a-b3cd-4a55-b1a5-34f3f01e0ba1' to virtual path '/tmp/MasterAllocatorTest_1_NestedRoles_ZIjckE/slaves/ec2a4715-88b5-4d62-95f3-be96a6f88f90-S0/frameworks/ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000/executors/default/runs/89a8de5a-b3cd-4a55-b1a5-34f3f01e0ba1' 3: W1208 15:21:23.741449 17430 process.cpp:2756] Attempted to spawn already running process [email protected]:39478 3: I1208 15:21:23.741658 17430 exec.cpp:162] Version: 1.5.0 3: I1208 15:21:23.741991 17440 exec.cpp:212] Executor started at: executor(113)@172.17.0.2:39478 with pid 17421 3: I1208 15:21:23.742223 17425 slave.cpp:4244] Got registration for executor 'default' of framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 from executor(113)@172.17.0.2:39478 3: I1208 15:21:23.742640 17435 exec.cpp:237] Executor registered on agent ec2a4715-88b5-4d62-95f3-be96a6f88f90-S0 3: I1208 15:21:23.742694 17435 exec.cpp:249] Executor::registered took 30696ns 3: I1208 15:21:23.743599 17438 slave.cpp:2738] Sending queued task '0' to executor 'default' of framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 at executor(113)@172.17.0.2:39478 3: I1208 15:21:23.744009 17443 exec.cpp:331] Executor asked to run task '0' 3: I1208 15:21:23.744117 17443 exec.cpp:340] Executor::launchTask took 86935ns 3: I1208 15:21:23.744269 17443 exec.cpp:571] Executor sending status update TASK_RUNNING (Status UUID: 9926eb15-89a6-48dc-9796-8c7da129fa37) for task 0 of framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 3: I1208 15:21:23.744700 17431 slave.cpp:4701] Handling status update TASK_RUNNING (Status UUID: 9926eb15-89a6-48dc-9796-8c7da129fa37) for task 0 of framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 from executor(113)@172.17.0.2:39478 3: I1208 15:21:23.745757 17424 task_status_update_manager.cpp:328] Received task status update TASK_RUNNING (Status UUID: 9926eb15-89a6-48dc-9796-8c7da129fa37) for task 0 of framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 3: I1208 15:21:23.745832 17424 task_status_update_manager.cpp:507] Creating StatusUpdate stream for task 0 of framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 3: I1208 15:21:23.746438 17424 task_status_update_manager.cpp:383] Forwarding task status update TASK_RUNNING (Status UUID: 9926eb15-89a6-48dc-9796-8c7da129fa37) for task 0 of framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 to the agent 3: I1208 15:21:23.746733 17427 slave.cpp:5184] Forwarding the update TASK_RUNNING (Status UUID: 9926eb15-89a6-48dc-9796-8c7da129fa37) for task 0 of framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 to [email protected]:39478 3: I1208 15:21:23.747095 17427 slave.cpp:5077] Task status update manager successfully handled status update TASK_RUNNING (Status UUID: 9926eb15-89a6-48dc-9796-8c7da129fa37) for task 0 of framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 3: I1208 15:21:23.747175 17427 slave.cpp:5093] Sending acknowledgement for status update TASK_RUNNING (Status UUID: 9926eb15-89a6-48dc-9796-8c7da129fa37) for task 0 of framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 to executor(113)@172.17.0.2:39478 3: I1208 15:21:23.747314 17444 master.cpp:7753] Status update TASK_RUNNING (Status UUID: 9926eb15-89a6-48dc-9796-8c7da129fa37) for task 0 of framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 from agent ec2a4715-88b5-4d62-95f3-be96a6f88f90-S0 at slave(317)@172.17.0.2:39478 (2b0fbe914a69) 3: I1208 15:21:23.747398 17444 master.cpp:7809] Forwarding status update TASK_RUNNING (Status UUID: 9926eb15-89a6-48dc-9796-8c7da129fa37) for task 0 of framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 3: I1208 15:21:23.747431 17429 exec.cpp:388] Executor received status update acknowledgement 9926eb15-89a6-48dc-9796-8c7da129fa37 for task 0 of framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 3: I1208 15:21:23.747678 17444 master.cpp:10056] Updating the state of task 0 of framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING) 3: I1208 15:21:23.747997 17433 sched.cpp:1029] Scheduler::statusUpdate took 94268ns 3: I1208 15:21:23.748423 17437 master.cpp:5841] Processing ACKNOWLEDGE call 9926eb15-89a6-48dc-9796-8c7da129fa37 for task 0 of framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 (default) at [email protected]:39478 on agent ec2a4715-88b5-4d62-95f3-be96a6f88f90-S0 3: I1208 15:21:23.748843 17432 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: 9926eb15-89a6-48dc-9796-8c7da129fa37) for task 0 of framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 3: I1208 15:21:23.749177 17445 slave.cpp:3979] Task status update manager successfully handled status update acknowledgement (UUID: 9926eb15-89a6-48dc-9796-8c7da129fa37) for task 0 of framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0000 3: W1208 15:21:23.749817 17421 process.cpp:2756] Attempted to spawn already running process [email protected]:39478 3: I1208 15:21:23.750828 17421 sched.cpp:232] Version: 1.5.0 3: I1208 15:21:23.751543 17430 sched.cpp:336] New master detected at [email protected]:39478 3: I1208 15:21:23.751641 17430 sched.cpp:396] Authenticating with master [email protected]:39478 3: I1208 15:21:23.751657 17430 sched.cpp:403] Using default CRAM-MD5 authenticatee 3: I1208 15:21:23.751909 17435 authenticatee.cpp:121] Creating new client SASL connection 3: I1208 15:21:23.752243 17436 master.cpp:8830] Authenticating [email protected]:39478 3: I1208 15:21:23.752377 17425 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(631)@172.17.0.2:39478 3: I1208 15:21:23.752615 17441 authenticator.cpp:98] Creating new server SASL connection 3: I1208 15:21:23.752821 17438 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1208 15:21:23.752848 17438 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1208 15:21:23.752970 17443 authenticator.cpp:204] Received SASL authentication start 3: I1208 15:21:23.753018 17443 authenticator.cpp:326] Authentication requires more steps 3: I1208 15:21:23.753160 17431 authenticatee.cpp:259] Received SASL authentication step 3: I1208 15:21:23.753334 17431 authenticator.cpp:232] Received SASL authentication step 3: I1208 15:21:23.753371 17431 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2b0fbe914a69' server FQDN: '2b0fbe914a69' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1208 15:21:23.753386 17431 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1208 15:21:23.753427 17431 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1208 15:21:23.753455 17431 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2b0fbe914a69' server FQDN: '2b0fbe914a69' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1208 15:21:23.753465 17431 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1208 15:21:23.753473 17431 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1208 15:21:23.753490 17431 authenticator.cpp:318] Authentication success 3: I1208 15:21:23.753625 17442 authenticatee.cpp:299] Authentication success 3: I1208 15:21:23.753720 17424 master.cpp:8860] Successfully authenticated principal 'test-principal' at [email protected]:39478 3: I1208 15:21:23.753792 17427 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(631)@172.17.0.2:39478 3: I1208 15:21:23.754107 17429 sched.cpp:502] Successfully authenticated with master [email protected]:39478 3: I1208 15:21:23.754135 17429 sched.cpp:824] Sending SUBSCRIBE call to [email protected]:39478 3: I1208 15:21:23.754276 17429 sched.cpp:857] Will retry registration in 1.790929901secs if necessary 3: I1208 15:21:23.754511 17428 master.cpp:2962] Received SUBSCRIBE call for framework 'default' at [email protected]:39478 3: I1208 15:21:23.754607 17428 master.cpp:2279] Authorizing framework principal 'test-principal' to receive offers for roles '{ a/c }' 3: I1208 15:21:23.755182 17445 master.cpp:3042] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ] 3: I1208 15:21:23.755415 17445 master.cpp:9051] Adding framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0001 (default) at [email protected]:39478 with roles { } suppressed 3: I1208 15:21:23.755961 17426 sched.cpp:751] Framework registered with ec2a4715-88b5-4d62-95f3-be96a6f88f90-0001 3: I1208 15:21:23.756026 17426 sched.cpp:765] Scheduler::registered took 32500ns 3: I1208 15:21:23.756147 17439 hierarchical.cpp:297] Added framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0001 3: I1208 15:21:23.756449 17439 hierarchical.cpp:1513] Performed allocation for 1 agents in 143060ns 3: W1208 15:21:23.756980 17421 process.cpp:2756] Attempted to spawn already running process [email protected]:39478 3: I1208 15:21:23.757915 17421 sched.cpp:232] Version: 1.5.0 3: I1208 15:21:23.758426 17425 sched.cpp:336] New master detected at [email protected]:39478 3: I1208 15:21:23.758510 17425 sched.cpp:396] Authenticating with master [email protected]:39478 3: I1208 15:21:23.758527 17425 sched.cpp:403] Using default CRAM-MD5 authenticatee 3: I1208 15:21:23.758745 17441 authenticatee.cpp:121] Creating new client SASL connection 3: I1208 15:21:23.758978 17443 master.cpp:8830] Authenticating [email protected]:39478 3: I1208 15:21:23.759158 17434 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(632)@172.17.0.2:39478 3: I1208 15:21:23.759501 17431 authenticator.cpp:98] Creating new server SASL connection 3: I1208 15:21:23.759804 17442 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1208 15:21:23.759835 17442 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1208 15:21:23.759975 17424 authenticator.cpp:204] Received SASL authentication start 3: I1208 15:21:23.760040 17424 authenticator.cpp:326] Authentication requires more steps 3: I1208 15:21:23.760234 17433 authenticatee.cpp:259] Received SASL authentication step 3: I1208 15:21:23.760393 17444 authenticator.cpp:232] Received SASL authentication step 3: I1208 15:21:23.760426 17444 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2b0fbe914a69' server FQDN: '2b0fbe914a69' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1208 15:21:23.760440 17444 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1208 15:21:23.760469 17444 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1208 15:21:23.760495 17444 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2b0fbe914a69' server FQDN: '2b0fbe914a69' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1208 15:21:23.760505 17444 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1208 15:21:23.760511 17444 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1208 15:21:23.760527 17444 authenticator.cpp:318] Authentication success 3: I1208 15:21:23.760624 17437 authenticatee.cpp:299] Authentication success 3: I1208 15:21:23.760715 17427 master.cpp:8860] Successfully authenticated principal 'test-principal' at [email protected]:39478 3: I1208 15:21:23.760797 17429 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(632)@172.17.0.2:39478 3: I1208 15:21:23.761023 17428 sched.cpp:502] Successfully authenticated with master [email protected]:39478 3: I1208 15:21:23.761045 17428 sched.cpp:824] Sending SUBSCRIBE call to [email protected]:39478 3: I1208 15:21:23.761174 17428 sched.cpp:857] Will retry registration in 1.017494173secs if necessary 3: I1208 15:21:23.761389 17440 master.cpp:2962] Received SUBSCRIBE call for framework 'default' at [email protected]:39478 3: I1208 15:21:23.761476 17440 master.cpp:2279] Authorizing framework principal 'test-principal' to receive offers for roles '{ b/x }' 3: I1208 15:21:23.761957 17430 master.cpp:3042] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ] 3: I1208 15:21:23.762104 17430 master.cpp:9051] Adding framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0002 (default) at [email protected]:39478 with roles { } suppressed 3: I1208 15:21:23.762495 17435 sched.cpp:751] Framework registered with ec2a4715-88b5-4d62-95f3-be96a6f88f90-0002 3: I1208 15:21:23.762544 17435 sched.cpp:765] Scheduler::registered took 25049ns 3: I1208 15:21:23.762670 17423 hierarchical.cpp:297] Added framework ec2a4715-88b5-4d62-95f3-be96a6f88f90-0002 3: I1208 15:21:23.762943 17423 hierarchical.cpp:1513] Performed allocation for 1 agents in 134312ns 3: W1208 15:21:23.769358 17421 process.cpp:2756] Attempted to spawn already running process [email protected]:39478 3: I1208 15:21:23.769731 17421 cluster.cpp:460] Creating default 'local' authorizer 3: I1208 15:21:23.772976 17444 slave.cpp:258] Mesos agent started on (318)@172.17.0.2:39478 3: I1208 15:21:23.773000 17444 slave.cpp:259] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/MasterAllocatorTest_1_NestedRoles_px3Sgw/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/MasterAllocatorTest_1_NestedRoles_px3Sgw/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/MasterAllocatorTest_1_NestedRoles_px3Sgw/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/MasterAllocatorTest_1_NestedRoles_px3Sgw/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/MasterAllocatorTest_1_NestedRoles_px3Sgw/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" --reconfiguration_policy="equal" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:1;mem:512" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/MasterAllocatorTest_1_NestedRoles_px3Sgw" --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/MasterAllocatorTest_1_NestedRoles_N2F1cK" --zk_session_timeout="10secs" 3: I1208 15:21:23.773463 17444 credentials.hpp:86] Loading credential for authentication from '/tmp/MasterAllocatorTest_1_NestedRoles_px3Sgw/credential' 3: I1208 15:21:23.773653 17444 slave.cpp:291] Agent using credential for: test-principal 3: I1208 15:21:23.773674 17444 credentials.hpp:37] Loading credentials for authentication from '/tmp/MasterAllocatorTest_1_NestedRoles_px3Sgw/http_credentials' 3: I1208 15:21:23.773954 17444 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' 3: I1208 15:21:23.774184 17444 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite' 3: I1208 15:21:23.775152 17425 hierarchical.cpp:1513] Performed allocation for 1 agents in 206376ns write /dev/stdout: resource temporarily unavailable + docker rmi mesos-1512743303-8932 Build step 'Execute shell' marked build as failure Not sending mail to unregistered user [email protected]
