See <https://builds.apache.org/job/Mesos-Buildbot/BUILDTOOL=cmake,COMPILER=clang,CONFIGURATION=--verbose%20--disable-libtool-wrappers%20--enable-libevent%20--enable-ssl,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=ubuntu%3A14.04,label_exp=(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23)/4490/display/redirect>
------------------------------------------ [...truncated 18.37 MB...] 3: I1122 10:24:48.834164 18356 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '77c4efb8cc5d' server FQDN: '77c4efb8cc5d' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1122 10:24:48.834179 18356 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1122 10:24:48.834193 18356 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1122 10:24:48.834213 18356 authenticator.cpp:318] Authentication success 3: I1122 10:24:48.834321 18368 authenticatee.cpp:299] Authentication success 3: I1122 10:24:48.834370 18359 master.cpp:8336] Successfully authenticated principal 'test-principal' at slave(444)@172.17.0.4:35588 3: I1122 10:24:48.834456 18365 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(920)@172.17.0.4:35588 3: I1122 10:24:48.834617 18368 slave.cpp:1161] Successfully authenticated with master [email protected]:35588 3: I1122 10:24:48.834813 18368 slave.cpp:1685] Will retry registration in 9.470018ms if necessary 3: I1122 10:24:48.835094 18363 master.cpp:6036] Received register agent message from slave(444)@172.17.0.4:35588 (77c4efb8cc5d) 3: I1122 10:24:48.835204 18363 master.cpp:3872] Authorizing agent with principal 'test-principal' 3: I1122 10:24:48.835587 18361 master.cpp:6098] Authorized registration of agent at slave(444)@172.17.0.4:35588 (77c4efb8cc5d) 3: I1122 10:24:48.835680 18361 master.cpp:6191] Registering agent at slave(444)@172.17.0.4:35588 (77c4efb8cc5d) with id 6b250867-4f78-4f5f-9341-641322579a76-S0 3: I1122 10:24:48.836001 18360 registrar.cpp:495] Applied 1 operations in 74903ns; attempting to update the registry 3: I1122 10:24:48.836529 18360 registrar.cpp:552] Successfully updated the registry in 466944ns 3: I1122 10:24:48.836753 18370 master.cpp:6240] Admitted agent 6b250867-4f78-4f5f-9341-641322579a76-S0 at slave(444)@172.17.0.4:35588 (77c4efb8cc5d) 3: I1122 10:24:48.837505 18354 slave.cpp:1207] Registered with master [email protected]:35588; given agent ID 6b250867-4f78-4f5f-9341-641322579a76-S0 3: I1122 10:24:48.837371 18370 master.cpp:6273] Registered agent 6b250867-4f78-4f5f-9341-641322579a76-S0 at slave(444)@172.17.0.4:35588 (77c4efb8cc5d) 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: I1122 10:24:48.837625 18366 task_status_update_manager.cpp:188] Resuming sending task status updates 3: I1122 10:24:48.837736 18369 hierarchical.cpp:600] Added agent 6b250867-4f78-4f5f-9341-641322579a76-S0 (77c4efb8cc5d) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {}) 3: I1122 10:24:48.837810 18354 slave.cpp:1227] Checkpointing SlaveInfo to '/tmp/TaskGroupValidationTest_TaskUsesDifferentExecutor_qIF0L5/meta/slaves/6b250867-4f78-4f5f-9341-641322579a76-S0/slave.info' 3: I1122 10:24:48.838219 18354 slave.cpp:1298] Forwarding total oversubscribed resources {} 3: I1122 10:24:48.838402 18356 master.cpp:7085] Received update of agent 6b250867-4f78-4f5f-9341-641322579a76-S0 at slave(444)@172.17.0.4:35588 (77c4efb8cc5d) with total oversubscribed resources {} 3: I1122 10:24:48.838569 18356 master.cpp:7103] Ignoring update on agent 6b250867-4f78-4f5f-9341-641322579a76-S0 at slave(444)@172.17.0.4:35588 (77c4efb8cc5d) as it reports no changes 3: I1122 10:24:48.839000 18369 hierarchical.cpp:1457] Performed allocation for 1 agents in 1.128866ms 3: I1122 10:24:48.839572 18357 master.cpp:8136] Sending 1 offers to framework Test_Framework (default) at [email protected]:35588 3: I1122 10:24:48.840406 18359 sched.cpp:921] Scheduler::resourceOffers took 207613ns 3: I1122 10:24:48.842595 18372 master.cpp:10045] Removing offer 6b250867-4f78-4f5f-9341-641322579a76-O0 3: I1122 10:24:48.842793 18372 master.cpp:4230] Processing ACCEPT call for offers: [ 6b250867-4f78-4f5f-9341-641322579a76-O0 ] on agent 6b250867-4f78-4f5f-9341-641322579a76-S0 at slave(444)@172.17.0.4:35588 (77c4efb8cc5d) for framework Test_Framework (default) at [email protected]:35588 3: I1122 10:24:48.842911 18372 master.cpp:3599] Authorizing framework principal 'test-principal' to launch task 1 3: I1122 10:24:48.843119 18372 master.cpp:3599] Authorizing framework principal 'test-principal' to launch task 2 3: I1122 10:24:48.847282 18375 master.cpp:7325] Sending status update TASK_ERROR for task 1 of framework Test_Framework 'The `ExecutorInfo` of task '1' is different from executor 'default'' 3: I1122 10:24:48.847506 18375 master.cpp:7325] Sending status update TASK_ERROR for task 2 of framework Test_Framework 'The `ExecutorInfo` of task '1' is different from executor 'default'' 3: I1122 10:24:48.847723 18358 sched.cpp:1029] Scheduler::statusUpdate took 99629ns 3: I1122 10:24:48.848091 18358 sched.cpp:1029] Scheduler::statusUpdate took 104392ns 3: I1122 10:24:48.848186 18351 sched.cpp:2009] Asked to stop the driver 3: I1122 10:24:48.848328 18357 sched.cpp:1191] Stopping framework Test_Framework 3: I1122 10:24:48.848563 18359 master.cpp:8813] Processing TEARDOWN call for framework Test_Framework (default) at [email protected]:35588 3: I1122 10:24:48.848608 18359 master.cpp:8825] Removing framework Test_Framework (default) at [email protected]:35588 3: I1122 10:24:48.848618 18359 master.cpp:3333] Deactivating framework Test_Framework (default) at [email protected]:35588 3: I1122 10:24:48.848721 18353 hierarchical.cpp:1132] Recovered cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated: *):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: {}) on agent 6b250867-4f78-4f5f-9341-641322579a76-S0 from framework Test_Framework 3: I1122 10:24:48.848793 18353 hierarchical.cpp:1178] Framework Test_Framework filtered agent 6b250867-4f78-4f5f-9341-641322579a76-S0 for 5secs 3: I1122 10:24:48.848819 18374 slave.cpp:3270] Asked to shut down framework Test_Framework by [email protected]:35588 3: I1122 10:24:48.848850 18374 slave.cpp:3285] Cannot shut down unknown framework Test_Framework 3: I1122 10:24:48.849000 18353 hierarchical.cpp:419] Deactivated framework Test_Framework 3: I1122 10:24:48.849210 18353 hierarchical.cpp:358] Removed framework Test_Framework 3: I1122 10:24:48.850208 18351 slave.cpp:883] Agent terminating 3: I1122 10:24:48.850378 18367 master.cpp:1311] Agent 6b250867-4f78-4f5f-9341-641322579a76-S0 at slave(444)@172.17.0.4:35588 (77c4efb8cc5d) disconnected 3: I1122 10:24:48.850416 18367 master.cpp:3370] Disconnecting agent 6b250867-4f78-4f5f-9341-641322579a76-S0 at slave(444)@172.17.0.4:35588 (77c4efb8cc5d) 3: I1122 10:24:48.850459 18367 master.cpp:3389] Deactivating agent 6b250867-4f78-4f5f-9341-641322579a76-S0 at slave(444)@172.17.0.4:35588 (77c4efb8cc5d) 3: I1122 10:24:48.850594 18352 hierarchical.cpp:697] Agent 6b250867-4f78-4f5f-9341-641322579a76-S0 deactivated 3: I1122 10:24:48.857148 18351 master.cpp:1153] Master terminating 3: I1122 10:24:48.857777 18359 hierarchical.cpp:633] Removed agent 6b250867-4f78-4f5f-9341-641322579a76-S0 3: [ OK ] TaskGroupValidationTest.TaskUsesDifferentExecutor (63 ms) 3: [ RUN ] TaskGroupValidationTest.ExecutorEnvironmentInvalid 3: I1122 10:24:48.864477 18351 cluster.cpp:162] Creating default 'local' authorizer 3: I1122 10:24:48.867415 18361 master.cpp:448] Master 6d6696e2-d8e3-407b-b435-ff2e9fbe2c2f (77c4efb8cc5d) started on 172.17.0.4:35588 3: I1122 10:24:48.867463 18361 master.cpp:450] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/Ijst3v/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/Ijst3v/master" --zk_session_timeout="10secs" 3: I1122 10:24:48.867736 18361 master.cpp:499] Master only allowing authenticated frameworks to register 3: I1122 10:24:48.867744 18361 master.cpp:505] Master only allowing authenticated agents to register 3: I1122 10:24:48.867748 18361 master.cpp:511] Master only allowing authenticated HTTP frameworks to register 3: I1122 10:24:48.867753 18361 credentials.hpp:37] Loading credentials for authentication from '/tmp/Ijst3v/credentials' 3: I1122 10:24:48.868012 18361 master.cpp:555] Using default 'crammd5' authenticator 3: I1122 10:24:48.868156 18361 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' 3: I1122 10:24:48.868306 18361 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' 3: I1122 10:24:48.868429 18361 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' 3: I1122 10:24:48.868546 18361 master.cpp:634] Authorization enabled 3: I1122 10:24:48.868729 18362 hierarchical.cpp:173] Initialized hierarchical allocator process 3: I1122 10:24:48.868753 18374 whitelist_watcher.cpp:77] No whitelist given 3: I1122 10:24:48.871280 18368 master.cpp:2215] Elected as the leading master! 3: I1122 10:24:48.871304 18368 master.cpp:1695] Recovering from registrar 3: I1122 10:24:48.871454 18353 registrar.cpp:347] Recovering registrar 3: I1122 10:24:48.872063 18353 registrar.cpp:391] Successfully fetched the registry (0B) in 569088ns 3: I1122 10:24:48.872198 18353 registrar.cpp:495] Applied 1 operations in 41653ns; attempting to update the registry 3: I1122 10:24:48.872897 18353 registrar.cpp:552] Successfully updated the registry in 635904ns 3: I1122 10:24:48.873046 18353 registrar.cpp:424] Successfully recovered registrar 3: I1122 10:24:48.873549 18375 master.cpp:1808] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register 3: I1122 10:24:48.873620 18370 hierarchical.cpp:211] Skipping recovery of hierarchical allocator: nothing to recover 3: W1122 10:24:48.877902 18351 process.cpp:2756] Attempted to spawn already running process [email protected]:35588 3: I1122 10:24:48.878736 18351 containerizer.cpp:301] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } 3: W1122 10:24:48.879242 18351 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges 3: W1122 10:24:48.879348 18351 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges 3: I1122 10:24:48.879377 18351 provisioner.cpp:259] Using default backend 'copy' 3: I1122 10:24:48.881075 18351 cluster.cpp:448] Creating default 'local' authorizer 3: I1122 10:24:48.882948 18355 slave.cpp:262] Mesos agent started on (445)@172.17.0.4:35588 3: I1122 10:24:48.882977 18355 slave.cpp:263] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/TaskGroupValidationTest_ExecutorEnvironmentInvalid_mXDzoe/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/TaskGroupValidationTest_ExecutorEnvironmentInvalid_mXDzoe/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/TaskGroupValidationTest_ExecutorEnvironmentInvalid_mXDzoe/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/TaskGroupValidationTest_ExecutorEnvironmentInvalid_mXDzoe/executor_secret_key" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/TaskGroupValidationTest_ExecutorEnvironmentInvalid_mXDzoe/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/TaskGroupValidationTest_ExecutorEnvironmentInvalid_mXDzoe/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/TaskGroupValidationTest_ExecutorEnvironmentInvalid_mXDzoe" --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/TaskGroupValidationTest_ExecutorEnvironmentInvalid_BM50dS" --zk_session_timeout="10secs" 3: I1122 10:24:48.883399 18355 credentials.hpp:86] Loading credential for authentication from '/tmp/TaskGroupValidationTest_ExecutorEnvironmentInvalid_mXDzoe/credential' 3: W1122 10:24:48.883467 18351 process.cpp:2756] Attempted to spawn already running process [email protected]:35588 3: I1122 10:24:48.883532 18355 slave.cpp:295] Agent using credential for: test-principal 3: I1122 10:24:48.883548 18355 credentials.hpp:37] Loading credentials for authentication from '/tmp/TaskGroupValidationTest_ExecutorEnvironmentInvalid_mXDzoe/http_credentials' 3: I1122 10:24:48.883793 18355 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-executor' 3: I1122 10:24:48.883920 18355 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-executor' 3: I1122 10:24:48.884110 18355 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' 3: I1122 10:24:48.884207 18355 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readonly' 3: I1122 10:24:48.884330 18351 sched.cpp:232] Version: 1.5.0 3: I1122 10:24:48.884377 18355 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite' 3: I1122 10:24:48.884472 18355 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readwrite' 3: I1122 10:24:48.884842 18371 sched.cpp:336] New master detected at [email protected]:35588 3: I1122 10:24:48.884958 18371 sched.cpp:396] Authenticating with master [email protected]:35588 3: I1122 10:24:48.884976 18371 sched.cpp:403] Using default CRAM-MD5 authenticatee 3: I1122 10:24:48.885211 18370 authenticatee.cpp:121] Creating new client SASL connection 3: I1122 10:24:48.885480 18374 master.cpp:8306] Authenticating [email protected]:35588 3: I1122 10:24:48.885606 18362 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(921)@172.17.0.4:35588 3: I1122 10:24:48.885838 18363 authenticator.cpp:98] Creating new server SASL connection 3: I1122 10:24:48.886081 18361 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1122 10:24:48.886111 18361 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1122 10:24:48.885959 18355 slave.cpp:593] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] 3: I1122 10:24:48.886173 18355 slave.cpp:601] Agent attributes: [ ] 3: I1122 10:24:48.886184 18355 slave.cpp:610] Agent hostname: 77c4efb8cc5d 3: I1122 10:24:48.886214 18369 authenticator.cpp:204] Received SASL authentication start 3: I1122 10:24:48.886270 18369 authenticator.cpp:326] Authentication requires more steps 3: I1122 10:24:48.886363 18369 authenticatee.cpp:259] Received SASL authentication step 3: I1122 10:24:48.886382 18368 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I1122 10:24:48.886512 18373 authenticator.cpp:232] Received SASL authentication step 3: I1122 10:24:48.886562 18373 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '77c4efb8cc5d' server FQDN: '77c4efb8cc5d' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1122 10:24:48.886575 18373 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1122 10:24:48.886602 18373 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1122 10:24:48.886620 18373 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '77c4efb8cc5d' server FQDN: '77c4efb8cc5d' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1122 10:24:48.886633 18373 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1122 10:24:48.886643 18373 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1122 10:24:48.886658 18373 authenticator.cpp:318] Authentication success 3: I1122 10:24:48.886747 18352 authenticatee.cpp:299] Authentication success 3: I1122 10:24:48.886834 18372 master.cpp:8336] Successfully authenticated principal 'test-principal' at [email protected]:35588 3: I1122 10:24:48.886849 18366 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(921)@172.17.0.4:35588 3: I1122 10:24:48.887006 18359 sched.cpp:502] Successfully authenticated with master [email protected]:35588 3: I1122 10:24:48.887030 18359 sched.cpp:824] Sending SUBSCRIBE call to [email protected]:35588 3: I1122 10:24:48.887145 18359 sched.cpp:857] Will retry registration in 295.541414ms if necessary 3: I1122 10:24:48.887356 18358 master.cpp:2963] Received SUBSCRIBE call for framework 'default' at [email protected]:35588 3: I1122 10:24:48.887377 18358 master.cpp:2280] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }' 3: I1122 10:24:48.887789 18375 state.cpp:64] Recovering state from '/tmp/TaskGroupValidationTest_ExecutorEnvironmentInvalid_BM50dS/meta' 3: I1122 10:24:48.887980 18360 master.cpp:3043] Subscribing framework default with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT ] 3: I1122 10:24:48.888094 18371 task_status_update_manager.cpp:207] Recovering task status update manager 3: I1122 10:24:48.888310 18362 containerizer.cpp:668] Recovering containerizer 3: I1122 10:24:48.888336 18360 master.cpp:6988] Updating info for framework Test_Framework 3: I1122 10:24:48.888598 18371 hierarchical.cpp:306] Added framework Test_Framework 3: I1122 10:24:48.888630 18371 hierarchical.cpp:419] Deactivated framework Test_Framework 3: I1122 10:24:48.888813 18368 sched.cpp:751] Framework registered with Test_Framework 3: I1122 10:24:48.888878 18368 sched.cpp:765] Scheduler::registered took 47167ns 3: I1122 10:24:48.889020 18371 hierarchical.cpp:385] Activated framework Test_Framework 3: I1122 10:24:48.889194 18371 hierarchical.cpp:1457] Performed allocation for 0 agents in 74984ns 3: I1122 10:24:48.889828 18355 provisioner.cpp:455] Provisioner recovery complete 3: I1122 10:24:48.890122 18356 slave.cpp:6449] Finished recovery 3: I1122 10:24:48.890913 18374 slave.cpp:1007] New master detected at [email protected]:35588 3: I1122 10:24:48.890950 18364 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I1122 10:24:48.891000 18374 slave.cpp:1042] Detecting new master 3: I1122 10:24:48.895300 18360 slave.cpp:1069] Authenticating with master [email protected]:35588 3: I1122 10:24:48.895408 18360 slave.cpp:1078] Using default CRAM-MD5 authenticatee 3: I1122 10:24:48.895726 18352 authenticatee.cpp:121] Creating new client SASL connection 3: I1122 10:24:48.895984 18352 master.cpp:8306] Authenticating slave(445)@172.17.0.4:35588 3: I1122 10:24:48.896149 18367 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(922)@172.17.0.4:35588 3: I1122 10:24:48.896445 18372 authenticator.cpp:98] Creating new server SASL connection 3: I1122 10:24:48.896698 18357 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1122 10:24:48.896749 18357 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1122 10:24:48.896903 18357 authenticator.cpp:204] Received SASL authentication start 3: I1122 10:24:48.896983 18357 authenticator.cpp:326] Authentication requires more steps 3: I1122 10:24:48.897115 18357 authenticatee.cpp:259] Received SASL authentication step 3: I1122 10:24:48.897298 18362 authenticator.cpp:232] Received SASL authentication step 3: I1122 10:24:48.897336 18362 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '77c4efb8cc5d' server FQDN: '77c4efb8cc5d' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1122 10:24:48.897349 18362 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1122 10:24:48.897377 18362 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1122 10:24:48.897423 18362 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '77c4efb8cc5d' server FQDN: '77c4efb8cc5d' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1122 10:24:48.897433 18362 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1122 10:24:48.897438 18362 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1122 10:24:48.897449 18362 authenticator.cpp:318] Authentication success 3: I1122 10:24:48.897568 18373 authenticatee.cpp:299] Authentication success 3: I1122 10:24:48.897631 18371 master.cpp:8336] Successfully authenticated principal 'test-principal' at slave(445)@172.17.0.4:35588 3: I1122 10:24:48.897701 18368 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(922)@172.17.0.4:35588 3: I1122 10:24:48.897919 18373 slave.cpp:1161] Successfully authenticated with master [email protected]:35588 3: I1122 10:24:48.898110 18373 slave.cpp:1685] Will retry registration in 6.279033ms if necessary 3: I1122 10:24:48.898344 18355 master.cpp:6036] Received register agent message from slave(445)@172.17.0.4:35588 (77c4efb8cc5d) 3: I1122 10:24:48.898401 18355 master.cpp:3872] Authorizing agent with principal 'test-principal' 3: I1122 10:24:48.899050 18356 master.cpp:6098] Authorized registration of agent at slave(445)@172.17.0.4:35588 (77c4efb8cc5d) 3: I1122 10:24:48.899250 18356 master.cpp:6191] Registering agent at slave(445)@172.17.0.4:35588 (77c4efb8cc5d) with id 6d6696e2-d8e3-407b-b435-ff2e9fbe2c2f-S0 3: I1122 10:24:48.899708 18353 registrar.cpp:495] Applied 1 operations in 74474ns; attempting to update the registry 3: I1122 10:24:48.900363 18353 registrar.cpp:552] Successfully updated the registry in 574976ns 3: I1122 10:24:48.900583 18360 master.cpp:6240] Admitted agent 6d6696e2-d8e3-407b-b435-ff2e9fbe2c2f-S0 at slave(445)@172.17.0.4:35588 (77c4efb8cc5d) 3: I1122 10:24:48.901681 18352 slave.cpp:1207] Registered with master [email protected]:35588; given agent ID 6d6696e2-d8e3-407b-b435-ff2e9fbe2c2f-S0 3: I1122 10:24:48.901482 18360 master.cpp:6273] Registered agent 6d6696e2-d8e3-407b-b435-ff2e9fbe2c2f-S0 at slave(445)@172.17.0.4:35588 (77c4efb8cc5d) 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: I1122 10:24:48.901845 18365 task_status_update_manager.cpp:188] Resuming sending task status updates 3: I1122 10:24:48.902009 18352 slave.cpp:1227] Checkpointing SlaveInfo to '/tmp/TaskGroupValidationTest_ExecutorEnvironmentInvalid_BM50dS/meta/slaves/6d6696e2-d8e3-407b-b435-ff2e9fbe2c2f-S0/slave.info' 3: I1122 10:24:48.902086 18367 hierarchical.cpp:600] Added agent 6d6696e2-d8e3-407b-b435-ff2e9fbe2c2f-S0 (77c4efb8cc5d) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {}) 3: I1122 10:24:48.902438 18352 slave.cpp:1298] Forwarding total oversubscribed resources {} 3: I1122 10:24:48.902623 18369 master.cpp:7085] Received update of agent 6d6696e2-d8e3-407b-b435-ff2e9fbe2c2f-S0 at slave(445)@172.17.0.4:35588 (77c4efb8cc5d) with total oversubscribed resources {} 3: I1122 10:24:48.902781 18369 master.cpp:7103] Ignoring update on agent 6d6696e2-d8e3-407b-b435-ff2e9fbe2c2f-S0 at slave(445)@172.17.0.4:35588 (77c4efb8cc5d) as it reports no changes 3: I1122 10:24:48.903563 18367 hierarchical.cpp:1457] Performed allocation for 1 agents in 1.271704ms 3: I1122 10:24:48.904042 18366 master.cpp:8136] Sending 1 offers to framework Test_Framework (default) at [email protected]:35588 3: I1122 10:24:48.904619 18362 sched.cpp:921] Scheduler::resourceOffers took 120584ns 3: I1122 10:24:48.906877 18375 master.cpp:10045] Removing offer 6d6696e2-d8e3-407b-b435-ff2e9fbe2c2f-O0 3: I1122 10:24:48.907212 18375 master.cpp:4230] Processing ACCEPT call for offers: [ 6d6696e2-d8e3-407b-b435-ff2e9fbe2c2f-O0 ] on agent 6d6696e2-d8e3-407b-b435-ff2e9fbe2c2f-S0 at slave(445)@172.17.0.4:35588 (77c4efb8cc5d) for framework Test_Framework (default) at [email protected]:35588 3: I1122 10:24:48.907416 18375 master.cpp:3599] Authorizing framework principal 'test-principal' to launch task 1 3: I1122 10:24:48.907678 18375 master.cpp:3599] Authorizing framework principal 'test-principal' to launch task 2 3: I1122 10:24:48.910285 18374 master.cpp:7325] Sending status update TASK_ERROR for task 1 of framework Test_Framework 'Executor's `CommandInfo` is invalid: Environment variable 'ENV_VAR_KEY' of type 'VALUE' must have a value set' 3: I1122 10:24:48.910495 18374 master.cpp:7325] Sending status update TASK_ERROR for task 2 of framework Test_Framework 'Executor's `CommandInfo` is invalid: Environment variable 'ENV_VAR_KEY' of type 'VALUE' must have a value set' 3: I1122 10:24:48.910682 18353 sched.cpp:1029] Scheduler::statusUpdate took 86929ns 3: I1122 10:24:48.910881 18353 sched.cpp:1029] Scheduler::statusUpdate took 39464ns 3: I1122 10:24:48.911527 18367 master.cpp:7724] Performing implicit task state reconciliation for framework Test_Framework (default) at [email protected]:35588 3: I1122 10:24:48.911775 18360 hierarchical.cpp:1132] Recovered cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated: *):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: {}) on agent 6d6696e2-d8e3-407b-b435-ff2e9fbe2c2f-S0 from framework Test_Framework 3: I1122 10:24:48.911847 18360 hierarchical.cpp:1178] Framework Test_Framework filtered agent 6d6696e2-d8e3-407b-b435-ff2e9fbe2c2f-S0 for 5secs 3: I1122 10:24:48.912021 18351 sched.cpp:2009] Asked to stop the driver 3: I1122 10:24:48.912135 18371 sched.cpp:1191] Stopping framework Test_Framework 3: I1122 10:24:48.912405 18354 master.cpp:8813] Processing TEARDOWN call for framework Test_Framework (default) at [email protected]:35588 3: I1122 10:24:48.912431 18354 master.cpp:8825] Removing framework Test_Framework (default) at [email protected]:35588 3: I1122 10:24:48.912441 18354 master.cpp:3333] Deactivating framework Test_Framework (default) at [email protected]:35588 3: I1122 10:24:48.912554 18355 hierarchical.cpp:419] Deactivated framework Test_Framework 3: I1122 10:24:48.912638 18368 slave.cpp:3270] Asked to shut down framework Test_Framework by [email protected]:35588 3: I1122 10:24:48.912669 18368 slave.cpp:3285] Cannot shut down unknown framework Test_Framework 3: I1122 10:24:48.912982 18364 hierarchical.cpp:358] Removed framework Test_Framework 3: I1122 10:24:48.914600 18351 slave.cpp:883] Agent terminating 3: I1122 10:24:48.914860 18363 master.cpp:1311] Agent 6d6696e2-d8e3-407b-b435-ff2e9fbe2c2f-S0 at slave(445)@172.17.0.4:35588 (77c4efb8cc5d) disconnected 3: I1122 10:24:48.914891 18363 master.cpp:3370] Disconnecting agent 6d6696e2-d8e3-407b-b435-ff2e9fbe2c2f-S0 at slave(445)@172.17.0.4:35588 (77c4efb8cc5d) 3: I1122 10:24:48.914948 18363 master.cpp:3389] Deactivating agent 6d6696e2-d8e3-407b-b435-ff2e9fbe2c2f-S0 at slave(445)@172.17.0.4:35588 (77c4efb8cc5d) 3: I1122 10:24:48.915067 18365 hierarchical.cpp:697] Agent 6d6696e2-d8e3-407b-b435-ff2e9fbe2c2f-S0 deactivated 3: I1122 10:24:48.921164 18351 master.cpp:1153] Master terminating 3: I1122 10:24:48.921844 18358 hierarchical.cpp:633] Removed agent 6d6696e2-d8e3-407b-b435-ff2e9fbe2c2f-S0 3: [ OK ] TaskGroupValidationTest.ExecutorEnvironmentInvalid (63 ms) 3: [ RUN ] TaskGroupValidationTest.TaskEnvironmentInvalid 3: I1122 10:24:48.928159 18351 cluster.cpp:162] Creating default 'local' authorizer 3: I1122 10:24:48.931116 18372 master.cpp:448] Master 28121275-7df6-4330-ba54-dcdfaf0ae458 (77c4efb8cc5d) started on 172.17.0.4:35588 3: I1122 10:24:48.931164 18372 master.cpp:450] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/v2XI7i/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/v2XI7i/master" --zk_session_timeout="10secs" 3: I1122 10:24:48.931428 18372 master.cpp:499] Master only allowing authenticated frameworks to register 3: I1122 10:24:48.931435 18372 master.cpp:505] Master only allowing authenticated agents to register 3: I1122 10:24:48.931439 18372 master.cpp:511] Master only allowing authenticated HTTP frameworks to register 3: I1122 10:24:48.931443 18372 credentials.hpp:37] Loading credentials for authentication from '/tmp/v2XI7i/credentials' 3: I1122 10:24:48.931748 18372 master.cpp:555] Using default 'crammd5' authenticator 3: I1122 10:24:48.931885 18372 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' 3: I1122 10:24:48.932030 18372 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' 3: I1122 10:24:48.932150 18372 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' 3: I1122 10:24:48.932255 18372 master.cpp:634] Authorization enabled 3: I1122 10:24:48.932399 18359 whitelist_watcher.cpp:77] No whitelist given 3: I1122 10:24:48.932420 18369 hierarchical.cpp:173] Initialized hierarchical allocator process 3: I1122 10:24:48.934710 18372 master.cpp:2215] Elected as the leading master! 3: I1122 10:24:48.934726 18372 master.cpp:1695] Recovering from registrar 3: I1122 10:24:48.934823 18360 registrar.cpp:347] Recovering registrar 3: I1122 10:24:48.935286 18360 registrar.cpp:391] Successfully fetched the registry (0B) in 434944ns 3: I1122 10:24:48.935385 18360 registrar.cpp:495] Applied 1 operations in 42285ns; attempting to update the registry 3: I1122 10:24:48.935811 18360 registrar.cpp:552] Successfully updated the registry in 378880ns 3: I1122 10:24:48.935919 18360 registrar.cpp:424] Successfully recovered registrar 3: I1122 10:24:48.936267 18374 master.cpp:1808] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register 3: I1122 10:24:48.936288 18367 hierarchical.cpp:211] Skipping recovery of hierarchical allocator: nothing to recover 3: W1122 10:24:48.940470 18351 process.cpp:2756] Attempted to spawn already running process [email protected]:35588 3: I1122 10:24:48.941377 18351 containerizer.cpp:301] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } 3: W1122 10:24:48.941864 18351 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges 3: W1122 10:24:48.941974 18351 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges 3: I1122 10:24:48.942004 18351 provisioner.cpp:259] Using default backend 'copy' 3: I1122 10:24:48.943783 18351 cluster.cpp:448] Creating default 'local' authorizer write /dev/stdout: resource temporarily unavailable + docker rmi mesos-1511344666-8281 Build step 'Execute shell' marked build as failure Not sending mail to unregistered user [email protected]
