See <https://builds.apache.org/job/Mesos-Reviewbot/22214/display/redirect>
------------------------------------------ [...truncated 66.69 MB...] I0418 10:38:59.169494 6747 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0418 10:38:59.169550 6747 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0418 10:38:59.169592 6747 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '28f36c3e5664' server FQDN: '28f36c3e5664' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0418 10:38:59.169617 6747 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0418 10:38:59.169636 6747 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0418 10:38:59.169661 6747 authenticator.cpp:318] Authentication success I0418 10:38:59.169785 6746 authenticatee.cpp:299] Authentication success I0418 10:38:59.169836 6749 master.cpp:9221] Successfully authenticated principal 'test-principal' at [email protected]:43112 I0418 10:38:59.169899 6744 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1462)@172.17.0.2:43112 I0418 10:38:59.170202 6747 sched.cpp:501] Successfully authenticated with master [email protected]:43112 I0418 10:38:59.170224 6747 sched.cpp:822] Sending SUBSCRIBE call to [email protected]:43112 I0418 10:38:59.170346 6747 sched.cpp:855] Will retry registration in 1.716017152secs if necessary I0418 10:38:59.170543 6754 master.cpp:2883] Received SUBSCRIBE call for framework 'default' at [email protected]:43112 I0418 10:38:59.170625 6754 master.cpp:2199] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }' I0418 10:38:59.170840 6750 state.cpp:66] Recovering state from '/tmp/ContentType_AgentAPITest_GetExecutors_1_yhL4ZM/meta' I0418 10:38:59.171174 6759 task_status_update_manager.cpp:207] Recovering task status update manager I0418 10:38:59.171267 6756 master.cpp:2964] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ] I0418 10:38:59.171383 6749 containerizer.cpp:675] Recovering containerizer I0418 10:38:59.171506 6756 master.cpp:9412] Adding framework 81c37193-3540-4110-8aac-5478580c687a-0000 (default) at [email protected]:43112 with roles { } suppressed I0418 10:38:59.172081 6756 sched.cpp:749] Framework registered with 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:38:59.172145 6756 sched.cpp:763] Scheduler::registered took 31219ns I0418 10:38:59.172317 6758 hierarchical.cpp:297] Added framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:38:59.172622 6758 hierarchical.cpp:1517] Performed allocation for 0 agents in 114645ns I0418 10:38:59.173131 6753 provisioner.cpp:495] Provisioner recovery complete I0418 10:38:59.173456 6748 slave.cpp:7316] Finished recovery I0418 10:38:59.174298 6756 task_status_update_manager.cpp:181] Pausing sending task status updates I0418 10:38:59.174299 6748 slave.cpp:1264] New master detected at [email protected]:43112 I0418 10:38:59.174494 6748 slave.cpp:1319] Detecting new master I0418 10:38:59.184934 6749 slave.cpp:1346] Authenticating with master [email protected]:43112 I0418 10:38:59.185061 6749 slave.cpp:1355] Using default CRAM-MD5 authenticatee I0418 10:38:59.185417 6744 authenticatee.cpp:121] Creating new client SASL connection I0418 10:38:59.185755 6757 master.cpp:9191] Authenticating slave(800)@172.17.0.2:43112 I0418 10:38:59.185987 6747 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1463)@172.17.0.2:43112 I0418 10:38:59.186272 6759 authenticator.cpp:98] Creating new server SASL connection I0418 10:38:59.186538 6759 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0418 10:38:59.186563 6759 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0418 10:38:59.186672 6754 authenticator.cpp:204] Received SASL authentication start I0418 10:38:59.186758 6754 authenticator.cpp:326] Authentication requires more steps I0418 10:38:59.186870 6754 authenticatee.cpp:259] Received SASL authentication step I0418 10:38:59.187006 6753 authenticator.cpp:232] Received SASL authentication step I0418 10:38:59.187044 6753 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '28f36c3e5664' server FQDN: '28f36c3e5664' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0418 10:38:59.187057 6753 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0418 10:38:59.187098 6753 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0418 10:38:59.187117 6753 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '28f36c3e5664' server FQDN: '28f36c3e5664' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0418 10:38:59.187129 6753 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0418 10:38:59.187139 6753 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0418 10:38:59.187155 6753 authenticator.cpp:318] Authentication success I0418 10:38:59.187243 6750 authenticatee.cpp:299] Authentication success I0418 10:38:59.187336 6746 master.cpp:9221] Successfully authenticated principal 'test-principal' at slave(800)@172.17.0.2:43112 I0418 10:38:59.187407 6750 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1463)@172.17.0.2:43112 I0418 10:38:59.187561 6751 slave.cpp:1438] Successfully authenticated with master [email protected]:43112 I0418 10:38:59.187925 6751 slave.cpp:1881] Will retry registration in 13.771182ms if necessary I0418 10:38:59.188096 6744 master.cpp:6308] Received register agent message from slave(800)@172.17.0.2:43112 (28f36c3e5664) I0418 10:38:59.188320 6744 master.cpp:3815] Authorizing agent providing resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal 'test-principal' I0418 10:38:59.188961 6758 master.cpp:6379] Authorized registration of agent at slave(800)@172.17.0.2:43112 (28f36c3e5664) I0418 10:38:59.189057 6758 master.cpp:6494] Registering agent at slave(800)@172.17.0.2:43112 (28f36c3e5664) with id 81c37193-3540-4110-8aac-5478580c687a-S0 I0418 10:38:59.189625 6754 registrar.cpp:487] Applied 1 operations in 168146ns; attempting to update the registry I0418 10:38:59.190294 6745 registrar.cpp:544] Successfully updated the registry in 599808ns I0418 10:38:59.190500 6748 master.cpp:6542] Admitted agent 81c37193-3540-4110-8aac-5478580c687a-S0 at slave(800)@172.17.0.2:43112 (28f36c3e5664) I0418 10:38:59.191252 6748 master.cpp:6587] Registered agent 81c37193-3540-4110-8aac-5478580c687a-S0 at slave(800)@172.17.0.2:43112 (28f36c3e5664) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0418 10:38:59.191308 6750 slave.cpp:1485] Registered with master [email protected]:43112; given agent ID 81c37193-3540-4110-8aac-5478580c687a-S0 I0418 10:38:59.191421 6744 task_status_update_manager.cpp:188] Resuming sending task status updates I0418 10:38:59.191705 6750 slave.cpp:1505] Checkpointing SlaveInfo to '/tmp/ContentType_AgentAPITest_GetExecutors_1_yhL4ZM/meta/slaves/81c37193-3540-4110-8aac-5478580c687a-S0/slave.info' I0418 10:38:59.191712 6751 hierarchical.cpp:574] Added agent 81c37193-3540-4110-8aac-5478580c687a-S0 (28f36c3e5664) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {}) I0418 10:38:59.192342 6750 slave.cpp:1552] Forwarding agent update {"operations":{},"resource_version_uuid":{"value":"oNh3fmu3RkWGS+QWQoq+\/w=="},"slave_id":{"value":"81c37193-3540-4110-8aac-5478580c687a-S0"},"update_oversubscribed_resources":true} I0418 10:38:59.192787 6755 master.cpp:7528] Received update of agent 81c37193-3540-4110-8aac-5478580c687a-S0 at slave(800)@172.17.0.2:43112 (28f36c3e5664) with total oversubscribed resources {} I0418 10:38:59.193032 6755 master.cpp:7624] Ignoring update on agent 81c37193-3540-4110-8aac-5478580c687a-S0 at slave(800)@172.17.0.2:43112 (28f36c3e5664) as it reports no changes I0418 10:38:59.193177 6751 hierarchical.cpp:1517] Performed allocation for 1 agents in 1.301504ms I0418 10:38:59.193629 6759 master.cpp:9019] Sending 1 offers to framework 81c37193-3540-4110-8aac-5478580c687a-0000 (default) at [email protected]:43112 I0418 10:38:59.194126 6758 sched.cpp:919] Scheduler::resourceOffers took 101816ns I0418 10:38:59.196990 6748 process.cpp:3580] Handling HTTP event for process 'slave(800)' with path: '/slave(800)/api/v1' I0418 10:38:59.198232 6758 http.cpp:1099] HTTP POST for /slave(800)/api/v1 from 172.17.0.2:52816 I0418 10:38:59.198730 6758 http.cpp:1501] Processing GET_EXECUTORS call I0418 10:38:59.202708 6753 master.cpp:10949] Removing offer 81c37193-3540-4110-8aac-5478580c687a-O0 I0418 10:38:59.203111 6753 master.cpp:4304] Processing ACCEPT call for offers: [ 81c37193-3540-4110-8aac-5478580c687a-O0 ] on agent 81c37193-3540-4110-8aac-5478580c687a-S0 at slave(800)@172.17.0.2:43112 (28f36c3e5664) for framework 81c37193-3540-4110-8aac-5478580c687a-0000 (default) at [email protected]:43112 I0418 10:38:59.203223 6753 master.cpp:3527] Authorizing framework principal 'test-principal' to launch task 1 I0418 10:38:59.205297 6754 master.cpp:11669] Adding task 1 with resources cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated: *):[31000-32000] on agent 81c37193-3540-4110-8aac-5478580c687a-S0 at slave(800)@172.17.0.2:43112 (28f36c3e5664) I0418 10:38:59.205744 6754 master.cpp:5077] Launching task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 (default) at [email protected]:43112 with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] on agent 81c37193-3540-4110-8aac-5478580c687a-S0 at slave(800)@172.17.0.2:43112 (28f36c3e5664) on new executor I0418 10:38:59.206945 6749 slave.cpp:2018] Got assigned task '1' for framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:38:59.208192 6749 slave.cpp:2392] Authorizing task '1' for framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:38:59.208254 6749 slave.cpp:8438] Authorizing framework principal 'test-principal' to launch task 1 I0418 10:38:59.210253 6747 slave.cpp:2866] Launching task '1' for framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:38:59.210347 6747 paths.cpp:745] Creating sandbox '/tmp/ContentType_AgentAPITest_GetExecutors_1_yhL4ZM/slaves/81c37193-3540-4110-8aac-5478580c687a-S0/frameworks/81c37193-3540-4110-8aac-5478580c687a-0000/executors/1/runs/505d44e1-5a04-4dae-a621-1a77cefc4a56' for user 'mesos' I0418 10:38:59.211046 6747 slave.cpp:8922] Launching executor '1' of framework 81c37193-3540-4110-8aac-5478580c687a-0000 with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":32.0},"type":"SCALAR"}] in work directory '/tmp/ContentType_AgentAPITest_GetExecutors_1_yhL4ZM/slaves/81c37193-3540-4110-8aac-5478580c687a-S0/frameworks/81c37193-3540-4110-8aac-5478580c687a-0000/executors/1/runs/505d44e1-5a04-4dae-a621-1a77cefc4a56' I0418 10:38:59.211748 6747 slave.cpp:3561] Launching container 505d44e1-5a04-4dae-a621-1a77cefc4a56 for executor '1' of framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:38:59.212311 6747 slave.cpp:3082] Queued task '1' for executor '1' of framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:38:59.212402 6747 slave.cpp:998] Successfully attached '/tmp/ContentType_AgentAPITest_GetExecutors_1_yhL4ZM/slaves/81c37193-3540-4110-8aac-5478580c687a-S0/frameworks/81c37193-3540-4110-8aac-5478580c687a-0000/executors/1/runs/505d44e1-5a04-4dae-a621-1a77cefc4a56' to virtual path '/tmp/ContentType_AgentAPITest_GetExecutors_1_yhL4ZM/slaves/81c37193-3540-4110-8aac-5478580c687a-S0/frameworks/81c37193-3540-4110-8aac-5478580c687a-0000/executors/1/runs/latest' I0418 10:38:59.212466 6747 slave.cpp:998] Successfully attached '/tmp/ContentType_AgentAPITest_GetExecutors_1_yhL4ZM/slaves/81c37193-3540-4110-8aac-5478580c687a-S0/frameworks/81c37193-3540-4110-8aac-5478580c687a-0000/executors/1/runs/505d44e1-5a04-4dae-a621-1a77cefc4a56' to virtual path '/frameworks/81c37193-3540-4110-8aac-5478580c687a-0000/executors/1/runs/latest' I0418 10:38:59.212529 6747 slave.cpp:998] Successfully attached '/tmp/ContentType_AgentAPITest_GetExecutors_1_yhL4ZM/slaves/81c37193-3540-4110-8aac-5478580c687a-S0/frameworks/81c37193-3540-4110-8aac-5478580c687a-0000/executors/1/runs/505d44e1-5a04-4dae-a621-1a77cefc4a56' to virtual path '/tmp/ContentType_AgentAPITest_GetExecutors_1_yhL4ZM/slaves/81c37193-3540-4110-8aac-5478580c687a-S0/frameworks/81c37193-3540-4110-8aac-5478580c687a-0000/executors/1/runs/505d44e1-5a04-4dae-a621-1a77cefc4a56' I0418 10:38:59.212857 6751 containerizer.cpp:1205] Starting container 505d44e1-5a04-4dae-a621-1a77cefc4a56 I0418 10:38:59.213977 6751 containerizer.cpp:1371] Checkpointed ContainerConfig at '/tmp/ContentType_AgentAPITest_GetExecutors_1_LieZXY/containers/505d44e1-5a04-4dae-a621-1a77cefc4a56/config' I0418 10:38:59.214010 6751 containerizer.cpp:2955] Transitioning the state of container 505d44e1-5a04-4dae-a621-1a77cefc4a56 from PROVISIONING to PREPARING I0418 10:38:59.218646 6750 containerizer.cpp:1847] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["mesos-executor","--launcher_dir=\/mesos\/mesos-1.6.0\/_build\/src"],"shell":false,"value":"\/mesos\/mesos-1.6.0\/_build\/src\/mesos-executor"},"environment":{"variables":[{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"172.17.0.2:43112"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"0"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"\/tmp\/ContentType_AgentAPITest_GetExecutors_1_yhL4ZM\/slaves\/81c37193-3540-4110-8aac-5478580c687a-S0\/frameworks\/81c37193-3540-4110-8aac-5478580c687a-0000\/executors\/1\/runs\/505d44e1-5a04-4dae-a621-1a77cefc4a56"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"1"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"81c37193-3540-4110-8aac-5478580c687a-0000"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","type":"VALUE","value":"0"},{"name":"MESOS_SLAVE_ID","type":"VALUE","value":"81c37193-3540-4110-8aac-5478580c687a-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(800)@172.17.0.2:43112"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"\/tmp\/ContentType_AgentAPITest_GetExecutors_1_yhL4ZM\/slaves\/81c37193-3540-4110-8aac-5478580c687a-S0\/frameworks\/81c37193-3540-4110-8aac-5478580c687a-0000\/executors\/1\/runs\/505d44e1-5a04-4dae-a621-1a77cefc4a56"}]},"task_environment":{},"user":"mesos","working_directory":"\/tmp\/ContentType_AgentAPITest_GetExecutors_1_yhL4ZM\/slaves\/81c37193-3540-4110-8aac-5478580c687a-S0\/frameworks\/81c37193-3540-4110-8aac-5478580c687a-0000\/executors\/1\/runs\/505d44e1-5a04-4dae-a621-1a77cefc4a56"}" --pipe_read="24" --pipe_write="26" --runtime_directory="/tmp/ContentType_AgentAPITest_GetExecutors_1_LieZXY/containers/505d44e1-5a04-4dae-a621-1a77cefc4a56" --unshare_namespace_mnt="false"' I0418 10:38:59.223654 6750 launcher.cpp:140] Forked child with pid '14176' for container '505d44e1-5a04-4dae-a621-1a77cefc4a56' I0418 10:38:59.224406 6750 containerizer.cpp:2955] Transitioning the state of container 505d44e1-5a04-4dae-a621-1a77cefc4a56 from PREPARING to ISOLATING I0418 10:38:59.226508 6749 containerizer.cpp:2955] Transitioning the state of container 505d44e1-5a04-4dae-a621-1a77cefc4a56 from ISOLATING to FETCHING I0418 10:38:59.226721 6748 fetcher.cpp:369] Starting to fetch URIs for container: 505d44e1-5a04-4dae-a621-1a77cefc4a56, directory: /tmp/ContentType_AgentAPITest_GetExecutors_1_yhL4ZM/slaves/81c37193-3540-4110-8aac-5478580c687a-S0/frameworks/81c37193-3540-4110-8aac-5478580c687a-0000/executors/1/runs/505d44e1-5a04-4dae-a621-1a77cefc4a56 I0418 10:38:59.227740 6753 containerizer.cpp:2955] Transitioning the state of container 505d44e1-5a04-4dae-a621-1a77cefc4a56 from FETCHING to RUNNING I0418 10:38:59.449472 14189 exec.cpp:162] Version: 1.6.0 I0418 10:38:59.460484 6757 slave.cpp:4831] Got registration for executor '1' of framework 81c37193-3540-4110-8aac-5478580c687a-0000 from executor(1)@172.17.0.2:47242 I0418 10:38:59.463981 6745 slave.cpp:3293] Sending queued task '1' to executor '1' of framework 81c37193-3540-4110-8aac-5478580c687a-0000 at executor(1)@172.17.0.2:47242 I0418 10:38:59.465593 14180 exec.cpp:236] Executor registered on agent 81c37193-3540-4110-8aac-5478580c687a-S0 I0418 10:38:59.469807 14184 executor.cpp:177] Received SUBSCRIBED event I0418 10:38:59.471315 14184 executor.cpp:181] Subscribed executor on 28f36c3e5664 I0418 10:38:59.471505 14184 executor.cpp:177] Received LAUNCH event I0418 10:38:59.473686 14184 executor.cpp:649] Starting task 1 I0418 10:38:59.477198 6750 slave.cpp:5297] Handling status update TASK_STARTING (Status UUID: bc5cd606-eaea-40ba-95bd-33a301ca14df) for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 from executor(1)@172.17.0.2:47242 I0418 10:38:59.479374 6749 task_status_update_manager.cpp:328] Received task status update TASK_STARTING (Status UUID: bc5cd606-eaea-40ba-95bd-33a301ca14df) for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:38:59.479418 6749 task_status_update_manager.cpp:507] Creating StatusUpdate stream for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:38:59.480057 6749 task_status_update_manager.cpp:383] Forwarding task status update TASK_STARTING (Status UUID: bc5cd606-eaea-40ba-95bd-33a301ca14df) for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 to the agent I0418 10:38:59.480245 6745 slave.cpp:5789] Forwarding the update TASK_STARTING (Status UUID: bc5cd606-eaea-40ba-95bd-33a301ca14df) for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 to [email protected]:43112 I0418 10:38:59.480480 6745 slave.cpp:5682] Task status update manager successfully handled status update TASK_STARTING (Status UUID: bc5cd606-eaea-40ba-95bd-33a301ca14df) for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:38:59.480545 6745 slave.cpp:5698] Sending acknowledgement for status update TASK_STARTING (Status UUID: bc5cd606-eaea-40ba-95bd-33a301ca14df) for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 to executor(1)@172.17.0.2:47242 I0418 10:38:59.480732 6752 master.cpp:8059] Status update TASK_STARTING (Status UUID: bc5cd606-eaea-40ba-95bd-33a301ca14df) for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 from agent 81c37193-3540-4110-8aac-5478580c687a-S0 at slave(800)@172.17.0.2:43112 (28f36c3e5664) I0418 10:38:59.480828 6752 master.cpp:8116] Forwarding status update TASK_STARTING (Status UUID: bc5cd606-eaea-40ba-95bd-33a301ca14df) for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:38:59.481149 6752 master.cpp:10431] Updating the state of task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 (latest state: TASK_STARTING, status update state: TASK_STARTING) I0418 10:38:59.481451 6754 sched.cpp:1027] Scheduler::statusUpdate took 118837ns I0418 10:38:59.481945 6758 master.cpp:5940] Processing ACKNOWLEDGE call for status bc5cd606-eaea-40ba-95bd-33a301ca14df for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 (default) at [email protected]:43112 on agent 81c37193-3540-4110-8aac-5478580c687a-S0 I0418 10:38:59.482372 6757 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: bc5cd606-eaea-40ba-95bd-33a301ca14df) for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:38:59.482692 6756 slave.cpp:4545] Task status update manager successfully handled status update acknowledgement (UUID: bc5cd606-eaea-40ba-95bd-33a301ca14df) for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:38:59.493604 14184 executor.cpp:484] Running '/mesos/mesos-1.6.0/_build/src/mesos-containerizer launch <POSSIBLY-SENSITIVE-DATA>' I0418 10:38:59.496079 14184 executor.cpp:662] Forked command at 14195 I0418 10:38:59.500159 6747 slave.cpp:5297] Handling status update TASK_RUNNING (Status UUID: a090bf07-5d7e-4279-8f98-a0fafea37256) for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 from executor(1)@172.17.0.2:47242 I0418 10:38:59.502290 6751 task_status_update_manager.cpp:328] Received task status update TASK_RUNNING (Status UUID: a090bf07-5d7e-4279-8f98-a0fafea37256) for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:38:59.502451 6751 task_status_update_manager.cpp:383] Forwarding task status update TASK_RUNNING (Status UUID: a090bf07-5d7e-4279-8f98-a0fafea37256) for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 to the agent I0418 10:38:59.502704 6757 slave.cpp:5789] Forwarding the update TASK_RUNNING (Status UUID: a090bf07-5d7e-4279-8f98-a0fafea37256) for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 to [email protected]:43112 I0418 10:38:59.502929 6757 slave.cpp:5682] Task status update manager successfully handled status update TASK_RUNNING (Status UUID: a090bf07-5d7e-4279-8f98-a0fafea37256) for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:38:59.502981 6757 slave.cpp:5698] Sending acknowledgement for status update TASK_RUNNING (Status UUID: a090bf07-5d7e-4279-8f98-a0fafea37256) for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 to executor(1)@172.17.0.2:47242 I0418 10:38:59.503171 6756 master.cpp:8059] Status update TASK_RUNNING (Status UUID: a090bf07-5d7e-4279-8f98-a0fafea37256) for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 from agent 81c37193-3540-4110-8aac-5478580c687a-S0 at slave(800)@172.17.0.2:43112 (28f36c3e5664) I0418 10:38:59.503232 6756 master.cpp:8116] Forwarding status update TASK_RUNNING (Status UUID: a090bf07-5d7e-4279-8f98-a0fafea37256) for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:38:59.503417 6756 master.cpp:10431] Updating the state of task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING) I0418 10:38:59.503747 6747 sched.cpp:1027] Scheduler::statusUpdate took 94340ns I0418 10:38:59.504309 6748 master.cpp:5940] Processing ACKNOWLEDGE call for status a090bf07-5d7e-4279-8f98-a0fafea37256 for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 (default) at [email protected]:43112 on agent 81c37193-3540-4110-8aac-5478580c687a-S0 I0418 10:38:59.504765 6744 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: a090bf07-5d7e-4279-8f98-a0fafea37256) for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:38:59.505082 6746 slave.cpp:4545] Task status update manager successfully handled status update acknowledgement (UUID: a090bf07-5d7e-4279-8f98-a0fafea37256) for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:38:59.506930 6757 process.cpp:3580] Handling HTTP event for process 'slave(800)' with path: '/slave(800)/api/v1' I0418 10:38:59.507957 6747 http.cpp:1099] HTTP POST for /slave(800)/api/v1 from 172.17.0.2:52819 I0418 10:38:59.508471 6747 http.cpp:1501] Processing GET_EXECUTORS call I0418 10:38:59.511910 6743 sched.cpp:2007] Asked to stop the driver I0418 10:38:59.512053 6749 sched.cpp:1189] Stopping framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:38:59.512349 6752 master.cpp:9701] Processing TEARDOWN call for framework 81c37193-3540-4110-8aac-5478580c687a-0000 (default) at [email protected]:43112 I0418 10:38:59.512385 6752 master.cpp:9713] Removing framework 81c37193-3540-4110-8aac-5478580c687a-0000 (default) at [email protected]:43112 I0418 10:38:59.512436 6752 master.cpp:3259] Deactivating framework 81c37193-3540-4110-8aac-5478580c687a-0000 (default) at [email protected]:43112 I0418 10:38:59.512615 6747 hierarchical.cpp:405] Deactivated framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:38:59.512684 6752 master.cpp:10431] Updating the state of task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 (latest state: TASK_KILLED, status update state: TASK_KILLED) I0418 10:38:59.512693 6754 slave.cpp:3948] Asked to shut down framework 81c37193-3540-4110-8aac-5478580c687a-0000 by [email protected]:43112 I0418 10:38:59.512748 6754 slave.cpp:3973] Shutting down framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:38:59.512809 6754 slave.cpp:6670] Shutting down executor '1' of framework 81c37193-3540-4110-8aac-5478580c687a-0000 at executor(1)@172.17.0.2:47242 I0418 10:38:59.513686 6752 master.cpp:10530] Removing task 1 with resources cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated: *):[31000-32000] of framework 81c37193-3540-4110-8aac-5478580c687a-0000 on agent 81c37193-3540-4110-8aac-5478580c687a-S0 at slave(800)@172.17.0.2:43112 (28f36c3e5664) I0418 10:38:59.514078 6755 hierarchical.cpp:1192] Recovered cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated: *):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: {}) on agent 81c37193-3540-4110-8aac-5478580c687a-S0 from framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:38:59.514618 14189 exec.cpp:445] Executor asked to shutdown I0418 10:38:59.514663 6751 hierarchical.cpp:344] Removed framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:38:59.514968 14183 executor.cpp:177] Received SHUTDOWN event I0418 10:38:59.515007 14183 executor.cpp:759] Shutting down I0418 10:38:59.515064 14183 executor.cpp:869] Sending SIGTERM to process tree at pid 14195 I0418 10:38:59.518720 14183 executor.cpp:882] Sent SIGTERM to the following process trees: [ --- 14195 mesos-containerizer launch --help=false --launch_info={"command":{"shell":true,"value":"sleep 1000"},"environment":{"variables":[{"name":"PATH","type":"VALUE","value":"\/usr\/local\/sbin:\/usr\/local\/bin:\/usr\/sbin:\/usr\/bin:\/sbin:\/bin"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(800)@172.17.0.2:43112"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","type":"VALUE","value":"0"},{"name":"MESOS_SLAVE_ID","type":"VALUE","value":"81c37193-3540-4110-8aac-5478580c687a-S0"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"172.17.0.2:43112"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"0"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"\/tmp\/ContentType_AgentAPITest_GetExecutors_1_yhL4ZM\/slaves\/81c37193-3540-4110-8aac-5478580c687a-S0\/frameworks\/81c37193-3540-4110-8aac-5478580c687a-0000\/executors\/1\/runs\/505d44e1-5a04-4dae-a621-1a77cefc4a56"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"1"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"81c37193-3540-4110-8aac-5478580c687a-0000"},{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"\/tmp\/ContentType_AgentAPITest_GetExecutors_1_yhL4ZM\/slaves\/81c37193-3540-4110-8aac-5478580c687a-S0\/frameworks\/81c37193-3540-4110-8aac-5478580c687a-0000\/executors\/1\/runs\/505d44e1-5a04-4dae-a621-1a77cefc4a56"}]}} --unshare_namespace_mnt=false ] I0418 10:38:59.518738 14183 executor.cpp:886] Scheduling escalation to SIGKILL in 3secs from now I0418 10:38:59.550200 14187 executor.cpp:944] Command terminated with signal Terminated (pid: 14195) I0418 10:38:59.555824 6746 slave.cpp:5297] Handling status update TASK_KILLED (Status UUID: ab202485-cc4e-4584-8811-397ca2e2e28c) for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 from executor(1)@172.17.0.2:47242 W0418 10:38:59.555918 6746 slave.cpp:5366] Ignoring status update TASK_KILLED (Status UUID: ab202485-cc4e-4584-8811-397ca2e2e28c) for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 for terminating framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:39:00.555408 14194 process.cpp:939] Stopped the socket accept loop I0418 10:39:00.563361 6746 slave.cpp:5921] Got exited event for executor(1)@172.17.0.2:47242 I0418 10:39:00.586576 6749 containerizer.cpp:2794] Container 505d44e1-5a04-4dae-a621-1a77cefc4a56 has exited I0418 10:39:00.586614 6749 containerizer.cpp:2341] Destroying container 505d44e1-5a04-4dae-a621-1a77cefc4a56 in RUNNING state I0418 10:39:00.586630 6749 containerizer.cpp:2955] Transitioning the state of container 505d44e1-5a04-4dae-a621-1a77cefc4a56 from RUNNING to DESTROYING I0418 10:39:00.587010 6749 launcher.cpp:156] Asked to destroy container 505d44e1-5a04-4dae-a621-1a77cefc4a56 I0418 10:39:00.594511 6752 provisioner.cpp:598] Ignoring destroy request for unknown container 505d44e1-5a04-4dae-a621-1a77cefc4a56 I0418 10:39:00.596526 6757 slave.cpp:6319] Executor '1' of framework 81c37193-3540-4110-8aac-5478580c687a-0000 exited with status 0 I0418 10:39:00.596799 6757 slave.cpp:6417] Cleaning up executor '1' of framework 81c37193-3540-4110-8aac-5478580c687a-0000 at executor(1)@172.17.0.2:47242 I0418 10:39:00.597868 6757 slave.cpp:6546] Cleaning up framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:39:00.598073 6753 gc.cpp:90] Scheduling '/tmp/ContentType_AgentAPITest_GetExecutors_1_yhL4ZM/slaves/81c37193-3540-4110-8aac-5478580c687a-S0/frameworks/81c37193-3540-4110-8aac-5478580c687a-0000/executors/1/runs/505d44e1-5a04-4dae-a621-1a77cefc4a56' for gc 6.99999308493037days in the future I0418 10:39:00.598309 6746 task_status_update_manager.cpp:289] Closing task status update streams for framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:39:00.598376 6746 task_status_update_manager.cpp:538] Cleaning up status update stream for task 1 of framework 81c37193-3540-4110-8aac-5478580c687a-0000 I0418 10:39:00.598536 6753 gc.cpp:90] Scheduling '/tmp/ContentType_AgentAPITest_GetExecutors_1_yhL4ZM/slaves/81c37193-3540-4110-8aac-5478580c687a-S0/frameworks/81c37193-3540-4110-8aac-5478580c687a-0000/executors/1' for gc 6.99999308230518days in the future I0418 10:39:00.601243 6748 gc.cpp:90] Scheduling '/tmp/ContentType_AgentAPITest_GetExecutors_1_yhL4ZM/slaves/81c37193-3540-4110-8aac-5478580c687a-S0/frameworks/81c37193-3540-4110-8aac-5478580c687a-0000' for gc 6.99999307485037days in the future I0418 10:39:00.604534 6744 process.cpp:3580] Handling HTTP event for process 'slave(800)' with path: '/slave(800)/api/v1' I0418 10:39:00.605767 6754 http.cpp:1099] HTTP POST for /slave(800)/api/v1 from 172.17.0.2:52820 I0418 10:39:00.606323 6754 http.cpp:1501] Processing GET_EXECUTORS call I0418 10:39:00.613611 6754 slave.cpp:923] Agent terminating I0418 10:39:00.613865 6752 master.cpp:1296] Agent 81c37193-3540-4110-8aac-5478580c687a-S0 at slave(800)@172.17.0.2:43112 (28f36c3e5664) disconnected I0418 10:39:00.613893 6752 master.cpp:3296] Disconnecting agent 81c37193-3540-4110-8aac-5478580c687a-S0 at slave(800)@172.17.0.2:43112 (28f36c3e5664) I0418 10:39:00.613972 6752 master.cpp:3315] Deactivating agent 81c37193-3540-4110-8aac-5478580c687a-S0 at slave(800)@172.17.0.2:43112 (28f36c3e5664) I0418 10:39:00.614147 6753 hierarchical.cpp:766] Agent 81c37193-3540-4110-8aac-5478580c687a-S0 deactivated I0418 10:39:00.623136 6743 master.cpp:1138] Master terminating I0418 10:39:00.624162 6748 hierarchical.cpp:609] Removed agent 81c37193-3540-4110-8aac-5478580c687a-S0 [ OK ] ContentType/AgentAPITest.GetExecutors/1 (1487 ms) [ RUN ] ContentType/AgentAPITest.GetTasks/0 I0418 10:39:00.631391 6743 cluster.cpp:172] Creating default 'local' authorizer I0418 10:39:00.634542 6758 master.cpp:463] Master 1b0dd2cc-ec43-4ed8-8ded-3dceb4d550ea (28f36c3e5664) started on 172.17.0.2:43112 I0418 10:39:00.634593 6758 master.cpp:466] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1000secs" --allocator="HierarchicalDRF" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/ztcEed/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_unreachable_tasks_per_framework="1000" --memory_profiling="false" --port="5050" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --require_agent_domain="false" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-1.6.0/_inst/share/mesos/webui" --work_dir="/tmp/ztcEed/master" --zk_session_timeout="10secs" I0418 10:39:00.635083 6758 master.cpp:515] Master only allowing authenticated frameworks to register I0418 10:39:00.635100 6758 master.cpp:521] Master only allowing authenticated agents to register I0418 10:39:00.635112 6758 master.cpp:527] Master only allowing authenticated HTTP frameworks to register I0418 10:39:00.635123 6758 credentials.hpp:37] Loading credentials for authentication from '/tmp/ztcEed/credentials' I0418 10:39:00.635440 6758 master.cpp:571] Using default 'crammd5' authenticator I0418 10:39:00.635638 6758 http.cpp:959] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' I0418 10:39:00.635810 6758 http.cpp:959] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' I0418 10:39:00.635936 6758 http.cpp:959] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' I0418 10:39:00.636057 6758 master.cpp:652] Authorization enabled I0418 10:39:00.636227 6755 whitelist_watcher.cpp:77] No whitelist given I0418 10:39:00.636270 6757 hierarchical.cpp:175] Initialized hierarchical allocator process I0418 10:39:00.639109 6759 master.cpp:2127] Elected as the leading master! I0418 10:39:00.639142 6759 master.cpp:1683] Recovering from registrar I0418 10:39:00.639307 6756 registrar.cpp:339] Recovering registrar I0418 10:39:00.639981 6756 registrar.cpp:383] Successfully fetched the registry (0B) in 630784ns I0418 10:39:00.640096 6756 registrar.cpp:487] Applied 1 operations in 33606ns; attempting to update the registry I0418 10:39:00.640692 6756 registrar.cpp:544] Successfully updated the registry in 540928ns I0418 10:39:00.640815 6756 registrar.cpp:416] Successfully recovered registrar I0418 10:39:00.641242 6757 master.cpp:1797] Recovered 0 agents from the registry (135B); allowing 10mins for agents to reregister I0418 10:39:00.641338 6745 hierarchical.cpp:213] Skipping recovery of hierarchical allocator: nothing to recover W0418 10:39:00.645503 6743 process.cpp:2821] Attempted to spawn already running process [email protected]:43112 I0418 10:39:00.646328 6743 containerizer.cpp:304] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } W0418 10:39:00.646800 6743 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges W0418 10:39:00.646919 6743 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges I0418 10:39:00.646965 6743 provisioner.cpp:299] Using default backend 'copy' I0418 10:39:00.648833 6743 cluster.cpp:460] Creating default 'local' authorizer I0418 10:39:00.651051 6753 slave.cpp:263] Mesos agent started on (801)@172.17.0.2:43112 W0418 10:39:00.651448 6743 process.cpp:2821] Attempted to spawn already running process [email protected]:43112 I0418 10:39:00.651077 6753 slave.cpp:264] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/ContentType_AgentAPITest_GetTasks_0_TeJiXI/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="false" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/ContentType_AgentAPITest_GetTasks_0_TeJiXI/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_AgentAPITest_GetTasks_0_TeJiXI/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_AgentAPITest_GetTasks_0_TeJiXI/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_command_executor="false" --http_credentials="/tmp/ContentType_AgentAPITest_GetTasks_0_TeJiXI/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/mesos-1.6.0/_build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --memory_profiling="false" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --reconfiguration_policy="equal" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/ContentType_AgentAPITest_GetTasks_0_TeJiXI" --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_AgentAPITest_GetTasks_0_OJSX5s" --zk_session_timeout="10secs" I0418 10:39:00.651659 6753 credentials.hpp:86] Loading credential for authentication from '/tmp/ContentType_AgentAPITest_GetTasks_0_TeJiXI/credential' I0418 10:39:00.651870 6753 slave.cpp:296] Agent using credential for: test-principal I0418 10:39:00.651896 6753 credentials.hpp:37] Loading credentials for authentication from '/tmp/ContentType_AgentAPITest_GetTasks_0_TeJiXI/http_credentials' I0418 10:39:00.652200 6753 http.cpp:959] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' I0418 10:39:00.652427 6743 sched.cpp:232] Version: 1.6.0 I0418 10:39:00.653230 6744 sched.cpp:336] New master detected at [email protected]:43112 I0418 10:39:00.653420 6744 sched.cpp:396] Authenticating with master [email protected]:43112 I0418 10:39:00.653439 6744 sched.cpp:403] Using default CRAM-MD5 authenticatee I0418 10:39:00.653777 6754 authenticatee.cpp:121] Creating new client SASL connection I0418 10:39:00.654062 6755 master.cpp:9191] Authenticating [email protected]:43112 I0418 10:39:00.654229 6756 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1464)@172.17.0.2:43112 I0418 10:39:00.654474 6750 authenticator.cpp:98] Creating new server SASL connection I0418 10:39:00.654696 6751 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0418 10:39:00.654434 6753 slave.cpp:613] 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"}] I0418 10:39:00.654736 6751 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0418 10:39:00.654752 6753 slave.cpp:621] Agent attributes: [ ] I0418 10:39:00.654772 6753 slave.cpp:630] Agent hostname: 28f36c3e5664 I0418 10:39:00.654855 6759 authenticator.cpp:204] Received SASL authentication start I0418 10:39:00.654924 6759 authenticator.cpp:326] Authentication requires more steps I0418 10:39:00.654922 6757 task_status_update_manager.cpp:181] Pausing sending task status updates I0418 10:39:00.655031 6751 authenticatee.cpp:259] Received SASL authentication step I0418 10:39:00.655151 6746 authenticator.cpp:232] Received SASL authentication step I0418 10:39:00.655191 6746 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '28f36c3e5664' server FQDN: '28f36c3e5664' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0418 10:39:00.655213 6746 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0418 10:39:00.655254 6746 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0418 10:39:00.655274 6746 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '28f36c3e5664' server FQDN: '28f36c3e5664' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0418 10:39:00.655289 6746 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
