See <https://builds.apache.org/job/Mesos-Reviewbot/21522/display/redirect>
------------------------------------------ [...truncated 17.66 MB...] I0204 21:07:35.085636 6607 authenticator.cpp:232] Received SASL authentication step I0204 21:07:35.085667 6607 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2e50cf33c8bc' server FQDN: '2e50cf33c8bc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0204 21:07:35.085685 6607 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0204 21:07:35.085721 6607 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0204 21:07:35.085743 6607 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2e50cf33c8bc' server FQDN: '2e50cf33c8bc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0204 21:07:35.085759 6607 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0204 21:07:35.085772 6607 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0204 21:07:35.085793 6607 authenticator.cpp:318] Authentication success I0204 21:07:35.085886 6594 authenticatee.cpp:299] Authentication success I0204 21:07:35.085959 6605 master.cpp:9008] Successfully authenticated principal 'test-principal' at slave(397)@172.17.0.2:42561 I0204 21:07:35.086019 6607 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(828)@172.17.0.2:42561 I0204 21:07:35.086205 6594 slave.cpp:1320] Successfully authenticated with master [email protected]:42561 I0204 21:07:35.086576 6594 slave.cpp:1766] Will retry registration in 17.832597ms if necessary I0204 21:07:35.086740 6610 master.cpp:6013] Received register agent message from slave(397)@172.17.0.2:42561 (2e50cf33c8bc) I0204 21:07:35.087061 6610 master.cpp:3793] Authorizing agent providing resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal 'test-principal' I0204 21:07:35.087630 6611 master.cpp:6084] Authorized registration of agent at slave(397)@172.17.0.2:42561 (2e50cf33c8bc) I0204 21:07:35.087731 6611 master.cpp:6195] Registering agent at slave(397)@172.17.0.2:42561 (2e50cf33c8bc) with id 3d1962e4-db12-47b9-9254-dcc55c23e392-S0 I0204 21:07:35.088281 6596 registrar.cpp:495] Applied 1 operations in 151698ns; attempting to update the registry I0204 21:07:35.088984 6596 registrar.cpp:552] Successfully updated the registry in 0ns I0204 21:07:35.089196 6597 master.cpp:6243] Admitted agent 3d1962e4-db12-47b9-9254-dcc55c23e392-S0 at slave(397)@172.17.0.2:42561 (2e50cf33c8bc) I0204 21:07:35.089928 6595 slave.cpp:1367] Registered with master [email protected]:42561; given agent ID 3d1962e4-db12-47b9-9254-dcc55c23e392-S0 I0204 21:07:35.089964 6597 master.cpp:6292] Registered agent 3d1962e4-db12-47b9-9254-dcc55c23e392-S0 at slave(397)@172.17.0.2:42561 (2e50cf33c8bc) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0204 21:07:35.090042 6592 task_status_update_manager.cpp:188] Resuming sending task status updates I0204 21:07:35.090294 6595 slave.cpp:1387] Checkpointing SlaveInfo to '/tmp/ReconciliationTest_ReconcileStatusUpdateTaskState_483rrf/meta/slaves/3d1962e4-db12-47b9-9254-dcc55c23e392-S0/slave.info' I0204 21:07:35.090294 6609 hierarchical.cpp:574] Added agent 3d1962e4-db12-47b9-9254-dcc55c23e392-S0 (2e50cf33c8bc) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {}) I0204 21:07:35.090826 6595 slave.cpp:1434] Forwarding agent update {"operations":{},"resource_version_uuid":{"value":"1Zh17XSQRkicdvPgMWpFqg=="},"slave_id":{"value":"3d1962e4-db12-47b9-9254-dcc55c23e392-S0"},"update_oversubscribed_resources":true} I0204 21:07:35.091364 6598 master.cpp:7235] Received update of agent 3d1962e4-db12-47b9-9254-dcc55c23e392-S0 at slave(397)@172.17.0.2:42561 (2e50cf33c8bc) with total oversubscribed resources {} I0204 21:07:35.091647 6598 master.cpp:7329] Ignoring update on agent 3d1962e4-db12-47b9-9254-dcc55c23e392-S0 at slave(397)@172.17.0.2:42561 (2e50cf33c8bc) as it reports no changes I0204 21:07:35.091995 6609 hierarchical.cpp:1517] Performed allocation for 1 agents in 1.530165ms I0204 21:07:35.092552 6606 master.cpp:8808] Sending 1 offers to framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 (default) at [email protected]:42561 I0204 21:07:35.094022 6608 sched.cpp:921] Scheduler::resourceOffers took 989894ns I0204 21:07:35.095422 6606 master.cpp:10716] Removing offer 3d1962e4-db12-47b9-9254-dcc55c23e392-O0 I0204 21:07:35.095868 6606 master.cpp:4220] Processing ACCEPT call for offers: [ 3d1962e4-db12-47b9-9254-dcc55c23e392-O0 ] on agent 3d1962e4-db12-47b9-9254-dcc55c23e392-S0 at slave(397)@172.17.0.2:42561 (2e50cf33c8bc) for framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 (default) at [email protected]:42561 I0204 21:07:35.095980 6606 master.cpp:3505] Authorizing framework principal 'test-principal' to launch task 0 W0204 21:07:35.098048 6607 validation.cpp:1386] 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. W0204 21:07:35.098085 6607 validation.cpp:1398] 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. I0204 21:07:35.098511 6607 master.cpp:11518] Adding task 0 with resources cpus(allocated: *):2; mem(allocated: *):1024 on agent 3d1962e4-db12-47b9-9254-dcc55c23e392-S0 at slave(397)@172.17.0.2:42561 (2e50cf33c8bc) I0204 21:07:35.098783 6607 master.cpp:4964] Launching task 0 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 (default) at [email protected]:42561 with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}] on agent 3d1962e4-db12-47b9-9254-dcc55c23e392-S0 at slave(397)@172.17.0.2:42561 (2e50cf33c8bc) I0204 21:07:35.099591 6603 slave.cpp:1879] Got assigned task '0' for framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 I0204 21:07:35.099951 6610 hierarchical.cpp:1192] Recovered ports(allocated: *):[31000-32000]; disk(allocated: *):1024 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: cpus(allocated: *):2; mem(allocated: *):1024) on agent 3d1962e4-db12-47b9-9254-dcc55c23e392-S0 from framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 I0204 21:07:35.100028 6610 hierarchical.cpp:1238] Framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 filtered agent 3d1962e4-db12-47b9-9254-dcc55c23e392-S0 for 5secs I0204 21:07:35.100337 6603 slave.cpp:2149] Authorizing task '0' for framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 I0204 21:07:35.100400 6603 slave.cpp:7955] Authorizing framework principal 'test-principal' to launch task 0 I0204 21:07:35.101253 6590 slave.cpp:2542] Launching task '0' for framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 I0204 21:07:35.101332 6590 paths.cpp:727] Creating sandbox '/tmp/ReconciliationTest_ReconcileStatusUpdateTaskState_483rrf/slaves/3d1962e4-db12-47b9-9254-dcc55c23e392-S0/frameworks/3d1962e4-db12-47b9-9254-dcc55c23e392-0000/executors/default/runs/f935a391-cb5c-40c5-9819-b5c80d9238bc' for user 'mesos' I0204 21:07:35.101976 6590 slave.cpp:8429] Launching executor 'default' of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 with resources [] in work directory '/tmp/ReconciliationTest_ReconcileStatusUpdateTaskState_483rrf/slaves/3d1962e4-db12-47b9-9254-dcc55c23e392-S0/frameworks/3d1962e4-db12-47b9-9254-dcc55c23e392-0000/executors/default/runs/f935a391-cb5c-40c5-9819-b5c80d9238bc' I0204 21:07:35.102545 6590 slave.cpp:3102] Launching container f935a391-cb5c-40c5-9819-b5c80d9238bc for executor 'default' of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 I0204 21:07:35.103103 6590 slave.cpp:2628] Queued task '0' for executor 'default' of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 I0204 21:07:35.103206 6590 slave.cpp:1006] Successfully attached '/tmp/ReconciliationTest_ReconcileStatusUpdateTaskState_483rrf/slaves/3d1962e4-db12-47b9-9254-dcc55c23e392-S0/frameworks/3d1962e4-db12-47b9-9254-dcc55c23e392-0000/executors/default/runs/f935a391-cb5c-40c5-9819-b5c80d9238bc' to virtual path '/tmp/ReconciliationTest_ReconcileStatusUpdateTaskState_483rrf/slaves/3d1962e4-db12-47b9-9254-dcc55c23e392-S0/frameworks/3d1962e4-db12-47b9-9254-dcc55c23e392-0000/executors/default/runs/latest' I0204 21:07:35.103255 6590 slave.cpp:1006] Successfully attached '/tmp/ReconciliationTest_ReconcileStatusUpdateTaskState_483rrf/slaves/3d1962e4-db12-47b9-9254-dcc55c23e392-S0/frameworks/3d1962e4-db12-47b9-9254-dcc55c23e392-0000/executors/default/runs/f935a391-cb5c-40c5-9819-b5c80d9238bc' to virtual path '/frameworks/3d1962e4-db12-47b9-9254-dcc55c23e392-0000/executors/default/runs/latest' I0204 21:07:35.103312 6590 slave.cpp:1006] Successfully attached '/tmp/ReconciliationTest_ReconcileStatusUpdateTaskState_483rrf/slaves/3d1962e4-db12-47b9-9254-dcc55c23e392-S0/frameworks/3d1962e4-db12-47b9-9254-dcc55c23e392-0000/executors/default/runs/f935a391-cb5c-40c5-9819-b5c80d9238bc' to virtual path '/tmp/ReconciliationTest_ReconcileStatusUpdateTaskState_483rrf/slaves/3d1962e4-db12-47b9-9254-dcc55c23e392-S0/frameworks/3d1962e4-db12-47b9-9254-dcc55c23e392-0000/executors/default/runs/f935a391-cb5c-40c5-9819-b5c80d9238bc' W0204 21:07:35.105600 6596 process.cpp:2795] Attempted to spawn already running process [email protected]:42561 I0204 21:07:35.105814 6596 exec.cpp:162] Version: 1.6.0 I0204 21:07:35.106097 6602 exec.cpp:212] Executor started at: executor(118)@172.17.0.2:42561 with pid 6588 I0204 21:07:35.106407 6602 slave.cpp:4352] Got registration for executor 'default' of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 from executor(118)@172.17.0.2:42561 I0204 21:07:35.106825 6592 exec.cpp:236] Executor registered on agent 3d1962e4-db12-47b9-9254-dcc55c23e392-S0 I0204 21:07:35.106956 6592 exec.cpp:248] Executor::registered took 30854ns I0204 21:07:35.107820 6608 slave.cpp:2833] Sending queued task '0' to executor 'default' of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 at executor(118)@172.17.0.2:42561 I0204 21:07:35.108217 6608 exec.cpp:330] Executor asked to run task '0' I0204 21:07:35.108314 6608 exec.cpp:339] Executor::launchTask took 71712ns I0204 21:07:35.108422 6608 exec.cpp:581] Executor sending status update TASK_RUNNING (Status UUID: f01a3d08-4f48-4603-8772-4d3648ead670) for task 0 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 I0204 21:07:35.108727 6608 slave.cpp:4809] Handling status update TASK_RUNNING (Status UUID: f01a3d08-4f48-4603-8772-4d3648ead670) for task 0 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 from executor(118)@172.17.0.2:42561 I0204 21:07:35.109323 6607 task_status_update_manager.cpp:328] Received task status update TASK_RUNNING (Status UUID: f01a3d08-4f48-4603-8772-4d3648ead670) for task 0 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 I0204 21:07:35.109375 6607 task_status_update_manager.cpp:507] Creating StatusUpdate stream for task 0 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 I0204 21:07:35.109903 6607 task_status_update_manager.cpp:383] Forwarding task status update TASK_RUNNING (Status UUID: f01a3d08-4f48-4603-8772-4d3648ead670) for task 0 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 to the agent I0204 21:07:35.110093 6610 slave.cpp:5291] Forwarding the update TASK_RUNNING (Status UUID: f01a3d08-4f48-4603-8772-4d3648ead670) for task 0 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 to [email protected]:42561 I0204 21:07:35.110302 6610 slave.cpp:5184] Task status update manager successfully handled status update TASK_RUNNING (Status UUID: f01a3d08-4f48-4603-8772-4d3648ead670) for task 0 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 I0204 21:07:35.110384 6610 slave.cpp:5200] Sending acknowledgement for status update TASK_RUNNING (Status UUID: f01a3d08-4f48-4603-8772-4d3648ead670) for task 0 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 to executor(118)@172.17.0.2:42561 I0204 21:07:35.110656 6610 exec.cpp:398] Executor received status update acknowledgement f01a3d08-4f48-4603-8772-4d3648ead670 for task 0 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 I0204 21:07:35.110986 6604 exec.cpp:581] Executor sending status update TASK_FINISHED (Status UUID: f9ae7bf9-f7e2-4bb6-b41a-1f46df68b7d0) for task 0 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 I0204 21:07:35.111325 6593 slave.cpp:4809] Handling status update TASK_FINISHED (Status UUID: f9ae7bf9-f7e2-4bb6-b41a-1f46df68b7d0) for task 0 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 from executor(118)@172.17.0.2:42561 I0204 21:07:35.112139 6591 task_status_update_manager.cpp:328] Received task status update TASK_FINISHED (Status UUID: f9ae7bf9-f7e2-4bb6-b41a-1f46df68b7d0) for task 0 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 I0204 21:07:35.112383 6596 slave.cpp:5184] Task status update manager successfully handled status update TASK_FINISHED (Status UUID: f9ae7bf9-f7e2-4bb6-b41a-1f46df68b7d0) for task 0 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 I0204 21:07:35.112435 6596 slave.cpp:5200] Sending acknowledgement for status update TASK_FINISHED (Status UUID: f9ae7bf9-f7e2-4bb6-b41a-1f46df68b7d0) for task 0 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 to executor(118)@172.17.0.2:42561 I0204 21:07:35.112643 6592 exec.cpp:398] Executor received status update acknowledgement f9ae7bf9-f7e2-4bb6-b41a-1f46df68b7d0 for task 0 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 I0204 21:07:35.112948 6602 master.cpp:1149] Master terminating W0204 21:07:35.113111 6602 master.cpp:10289] Removing task 0 with resources cpus(allocated: *):2; mem(allocated: *):1024 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 on agent 3d1962e4-db12-47b9-9254-dcc55c23e392-S0 at slave(397)@172.17.0.2:42561 (2e50cf33c8bc) in non-terminal state TASK_STAGING I0204 21:07:35.113617 6602 master.cpp:10332] Removing executor 'default' with resources [] of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 on agent 3d1962e4-db12-47b9-9254-dcc55c23e392-S0 at slave(397)@172.17.0.2:42561 (2e50cf33c8bc) I0204 21:07:35.113770 6598 hierarchical.cpp:609] Removed agent 3d1962e4-db12-47b9-9254-dcc55c23e392-S0 I0204 21:07:35.114670 6610 slave.cpp:5423] Got exited event for [email protected]:42561 W0204 21:07:35.114697 6610 slave.cpp:5428] Master disconnected! Waiting for a new master to be elected I0204 21:07:35.115712 6598 hierarchical.cpp:344] Removed framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 I0204 21:07:35.120733 6588 cluster.cpp:172] Creating default 'local' authorizer I0204 21:07:35.124601 6598 master.cpp:458] Master a05e67da-13f5-46d0-9738-dee10381c5fa (2e50cf33c8bc) started on 172.17.0.2:42561 I0204 21:07:35.124627 6598 master.cpp:460] 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/p7WLTD/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" --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/p7WLTD/master" --zk_session_timeout="10secs" I0204 21:07:35.124989 6598 master.cpp:509] Master only allowing authenticated frameworks to register I0204 21:07:35.125010 6598 master.cpp:515] Master only allowing authenticated agents to register I0204 21:07:35.125020 6598 master.cpp:521] Master only allowing authenticated HTTP frameworks to register I0204 21:07:35.125030 6598 credentials.hpp:37] Loading credentials for authentication from '/tmp/p7WLTD/credentials' I0204 21:07:35.125320 6598 master.cpp:565] Using default 'crammd5' authenticator I0204 21:07:35.125514 6598 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' I0204 21:07:35.125836 6598 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' I0204 21:07:35.126003 6598 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' I0204 21:07:35.126160 6598 master.cpp:644] Authorization enabled I0204 21:07:35.126313 6595 hierarchical.cpp:175] Initialized hierarchical allocator process I0204 21:07:35.126456 6610 whitelist_watcher.cpp:77] No whitelist given I0204 21:07:35.130048 6598 master.cpp:2133] Elected as the leading master! I0204 21:07:35.130156 6598 master.cpp:1692] Recovering from registrar I0204 21:07:35.130479 6606 registrar.cpp:347] Recovering registrar I0204 21:07:35.131335 6606 registrar.cpp:391] Successfully fetched the registry (0B) in 0ns I0204 21:07:35.131577 6606 registrar.cpp:495] Applied 1 operations in 41720ns; attempting to update the registry I0204 21:07:35.132522 6606 registrar.cpp:552] Successfully updated the registry in 0ns I0204 21:07:35.132771 6606 registrar.cpp:424] Successfully recovered registrar I0204 21:07:35.133323 6589 hierarchical.cpp:213] Skipping recovery of hierarchical allocator: nothing to recover I0204 21:07:35.133404 6612 master.cpp:1806] Recovered 0 agents from the registry (135B); allowing 10mins for agents to re-register I0204 21:07:35.134275 6608 sched.cpp:330] Scheduler::disconnected took 22843ns I0204 21:07:35.134302 6608 sched.cpp:336] New master detected at [email protected]:42561 I0204 21:07:35.134425 6608 sched.cpp:396] Authenticating with master [email protected]:42561 I0204 21:07:35.134449 6608 sched.cpp:403] Using default CRAM-MD5 authenticatee I0204 21:07:35.134770 6610 authenticatee.cpp:121] Creating new client SASL connection I0204 21:07:35.135269 6609 master.cpp:8978] Authenticating [email protected]:42561 I0204 21:07:35.135411 6591 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(829)@172.17.0.2:42561 I0204 21:07:35.135671 6601 authenticator.cpp:98] Creating new server SASL connection I0204 21:07:35.135896 6599 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0204 21:07:35.135927 6599 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0204 21:07:35.136054 6597 authenticator.cpp:204] Received SASL authentication start I0204 21:07:35.136111 6597 authenticator.cpp:326] Authentication requires more steps I0204 21:07:35.136221 6594 authenticatee.cpp:259] Received SASL authentication step I0204 21:07:35.136339 6594 authenticator.cpp:232] Received SASL authentication step I0204 21:07:35.136374 6594 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2e50cf33c8bc' server FQDN: '2e50cf33c8bc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0204 21:07:35.136394 6594 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0204 21:07:35.136438 6594 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0204 21:07:35.136464 6594 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2e50cf33c8bc' server FQDN: '2e50cf33c8bc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0204 21:07:35.136508 6594 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0204 21:07:35.136523 6594 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0204 21:07:35.136545 6594 authenticator.cpp:318] Authentication success I0204 21:07:35.136706 6600 authenticatee.cpp:299] Authentication success I0204 21:07:35.136775 6594 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(829)@172.17.0.2:42561 I0204 21:07:35.136771 6603 master.cpp:9008] Successfully authenticated principal 'test-principal' at [email protected]:42561 I0204 21:07:35.137019 6600 sched.cpp:502] Successfully authenticated with master [email protected]:42561 I0204 21:07:35.137045 6600 sched.cpp:824] Sending SUBSCRIBE call to [email protected]:42561 I0204 21:07:35.137184 6600 sched.cpp:857] Will retry registration in 725.839229ms if necessary I0204 21:07:35.137394 6589 master.cpp:2869] Received SUBSCRIBE call for framework 'default' at [email protected]:42561 I0204 21:07:35.137481 6589 master.cpp:2198] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }' I0204 21:07:35.137979 6612 master.cpp:2949] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ] I0204 21:07:35.138160 6612 master.cpp:9199] Adding framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 (default) with roles { } suppressed I0204 21:07:35.138365 6612 master.cpp:7165] Updating framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 (default) with roles { } suppressed I0204 21:07:35.138720 6595 hierarchical.cpp:297] Added framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 I0204 21:07:35.138766 6595 hierarchical.cpp:405] Deactivated framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 I0204 21:07:35.138778 6612 sched.cpp:751] Framework registered with 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 I0204 21:07:35.138878 6612 sched.cpp:765] Scheduler::registered took 63809ns I0204 21:07:35.138933 6595 hierarchical.cpp:371] Activated framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 I0204 21:07:35.139168 6595 hierarchical.cpp:1517] Performed allocation for 0 agents in 80821ns I0204 21:07:35.139655 6599 task_status_update_manager.cpp:181] Pausing sending task status updates I0204 21:07:35.139668 6597 slave.cpp:1146] New master detected at [email protected]:42561 I0204 21:07:35.139873 6597 slave.cpp:1201] Detecting new master I0204 21:07:35.145205 6611 slave.cpp:1228] Authenticating with master [email protected]:42561 I0204 21:07:35.145284 6611 slave.cpp:1237] Using default CRAM-MD5 authenticatee I0204 21:07:35.145550 6598 authenticatee.cpp:121] Creating new client SASL connection I0204 21:07:35.145875 6598 master.cpp:8978] Authenticating slave(397)@172.17.0.2:42561 I0204 21:07:35.146020 6590 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(830)@172.17.0.2:42561 I0204 21:07:35.146280 6593 authenticator.cpp:98] Creating new server SASL connection I0204 21:07:35.146492 6606 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0204 21:07:35.146525 6606 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0204 21:07:35.146653 6594 authenticator.cpp:204] Received SASL authentication start I0204 21:07:35.146713 6594 authenticator.cpp:326] Authentication requires more steps I0204 21:07:35.146821 6600 authenticatee.cpp:259] Received SASL authentication step I0204 21:07:35.146950 6589 authenticator.cpp:232] Received SASL authentication step I0204 21:07:35.146989 6589 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2e50cf33c8bc' server FQDN: '2e50cf33c8bc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0204 21:07:35.147009 6589 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0204 21:07:35.147047 6589 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0204 21:07:35.147073 6589 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2e50cf33c8bc' server FQDN: '2e50cf33c8bc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0204 21:07:35.147090 6589 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0204 21:07:35.147102 6589 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0204 21:07:35.147120 6589 authenticator.cpp:318] Authentication success I0204 21:07:35.147208 6592 authenticatee.cpp:299] Authentication success I0204 21:07:35.147339 6592 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(830)@172.17.0.2:42561 I0204 21:07:35.147502 6604 master.cpp:9008] Successfully authenticated principal 'test-principal' at slave(397)@172.17.0.2:42561 I0204 21:07:35.147676 6589 slave.cpp:1320] Successfully authenticated with master [email protected]:42561 I0204 21:07:35.148530 6589 slave.cpp:1766] Will retry registration in 8.29998ms if necessary I0204 21:07:35.148934 6609 master.cpp:6371] Received re-register agent message from agent 3d1962e4-db12-47b9-9254-dcc55c23e392-S0 at slave(397)@172.17.0.2:42561 (2e50cf33c8bc) I0204 21:07:35.149340 6609 master.cpp:3793] Authorizing agent providing resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal 'test-principal' I0204 21:07:35.149950 6607 master.cpp:6467] Authorized re-registration of agent 3d1962e4-db12-47b9-9254-dcc55c23e392-S0 at slave(397)@172.17.0.2:42561 (2e50cf33c8bc) I0204 21:07:35.150053 6607 master.cpp:6620] Consulting registry about agent 3d1962e4-db12-47b9-9254-dcc55c23e392-S0 at slave(397)@172.17.0.2:42561(2e50cf33c8bc) W0204 21:07:35.150512 6607 registry_operations.cpp:182] Allowing UNKNOWN agent to reregister: hostname: "2e50cf33c8bc" resources { name: "cpus" type: SCALAR scalar { value: 2 } } resources { name: "mem" type: SCALAR scalar { value: 1024 } } resources { name: "disk" type: SCALAR scalar { value: 1024 } } resources { name: "ports" type: RANGES ranges { range { begin: 31000 end: 32000 } } } id { value: "3d1962e4-db12-47b9-9254-dcc55c23e392-S0" } checkpoint: true port: 42561 I0204 21:07:35.150918 6607 registrar.cpp:495] Applied 1 operations in 439638ns; attempting to update the registry I0204 21:07:35.151602 6607 registrar.cpp:552] Successfully updated the registry in 615168ns I0204 21:07:35.151773 6590 master.cpp:6676] Re-admitted agent 3d1962e4-db12-47b9-9254-dcc55c23e392-S0 at slave(397)@172.17.0.2:42561 (2e50cf33c8bc) I0204 21:07:35.151968 6590 master.cpp:7901] Sending status update TASK_FINISHED for task 0 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 'Unknown agent re-registered' GMOCK WARNING: Uninteresting mock function call - returning directly. Function call: statusUpdate(0x7fff8db64210, @0x2b69864ab350 136-byte object <D0-31 68-7C 69-2B 00-00 00-00 00-00 00-00 00-00 9A-E8 00-00 00-00 00-00 58-A0 9C-7C 69-2B 00-00 B0-78 00-9C 69-2B 00-00 58-A0 9C-7C 69-2B 00-00 D0-AD 00-9C 69-2B 00-00 D0-56 02-9C 69-2B 00-00 ... 00-00 00-00 00-00 00-00 70-57 02-9C 69-2B 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 C4-5A D7-F7 73-A9 D6-41 00-00 00-00 00-00 00-00 20-00 00-00 02-00 00-00>) NOTE: You can safely ignore the above warning unless this call should not happen. Do not suppress it by blindly adding an EXPECT_CALL() if you don't mean to enforce the call. See https://github.com/google/googletest/blob/master/googlemock/docs/CookBook.md#knowing-when-to-expect for details. I0204 21:07:35.152364 6593 sched.cpp:1029] Scheduler::statusUpdate took 70504ns I0204 21:07:35.152529 6590 master.cpp:11518] Adding task 0 with resources cpus(allocated: *):2; mem(allocated: *):1024 on agent 3d1962e4-db12-47b9-9254-dcc55c23e392-S0 at slave(397)@172.17.0.2:42561 (2e50cf33c8bc) I0204 21:07:35.153167 6590 master.cpp:6860] Re-registered agent 3d1962e4-db12-47b9-9254-dcc55c23e392-S0 at slave(397)@172.17.0.2:42561 (2e50cf33c8bc) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0204 21:07:35.153365 6596 slave.cpp:1471] Re-registered with master [email protected]:42561 I0204 21:07:35.153560 6592 task_status_update_manager.cpp:188] Resuming sending task status updates I0204 21:07:35.153574 6596 slave.cpp:1516] Forwarding agent update {"operations":{},"resource_version_uuid":{"value":"1Zh17XSQRkicdvPgMWpFqg=="},"slave_id":{"value":"3d1962e4-db12-47b9-9254-dcc55c23e392-S0"},"update_oversubscribed_resources":true} I0204 21:07:35.153703 6600 hierarchical.cpp:574] Added agent 3d1962e4-db12-47b9-9254-dcc55c23e392-S0 (2e50cf33c8bc) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {}) W0204 21:07:35.153759 6592 task_status_update_manager.cpp:195] Resending task status update TASK_RUNNING (Status UUID: f01a3d08-4f48-4603-8772-4d3648ead670) for task 0 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 I0204 21:07:35.153842 6592 task_status_update_manager.cpp:383] Forwarding task status update TASK_RUNNING (Status UUID: f01a3d08-4f48-4603-8772-4d3648ead670) for task 0 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 to the agent I0204 21:07:35.153985 6589 master.cpp:8367] Performing implicit task state reconciliation for framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 (default) at [email protected]:42561 I0204 21:07:35.154079 6589 master.cpp:8417] Sending implicit reconciliation state TASK_RUNNING for task 0 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 (default) at [email protected]:42561 I0204 21:07:35.154440 6599 sched.cpp:1029] Scheduler::statusUpdate took 81833ns I0204 21:07:35.154706 6611 master.cpp:7235] Received update of agent 3d1962e4-db12-47b9-9254-dcc55c23e392-S0 at slave(397)@172.17.0.2:42561 (2e50cf33c8bc) with total oversubscribed resources {} I0204 21:07:35.154799 6588 sched.cpp:2009] Asked to stop the driver I0204 21:07:35.154892 6596 slave.cpp:3625] Updating info for framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 with pid updated to [email protected]:42561 I0204 21:07:35.155040 6611 master.cpp:7329] Ignoring update on agent 3d1962e4-db12-47b9-9254-dcc55c23e392-S0 at slave(397)@172.17.0.2:42561 (2e50cf33c8bc) as it reports no changes I0204 21:07:35.155042 6596 slave.cpp:5291] Forwarding the update TASK_RUNNING (Status UUID: f01a3d08-4f48-4603-8772-4d3648ead670) for task 0 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 to [email protected]:42561 I0204 21:07:35.155133 6611 sched.cpp:1191] Stopping framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 I0204 21:07:35.155268 6596 task_status_update_manager.cpp:188] Resuming sending task status updates W0204 21:07:35.155360 6596 task_status_update_manager.cpp:195] Resending task status update TASK_RUNNING (Status UUID: f01a3d08-4f48-4603-8772-4d3648ead670) for task 0 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 I0204 21:07:35.155447 6596 task_status_update_manager.cpp:383] Forwarding task status update TASK_RUNNING (Status UUID: f01a3d08-4f48-4603-8772-4d3648ead670) for task 0 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 to the agent I0204 21:07:35.155489 6605 master.cpp:9488] Processing TEARDOWN call for framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 (default) at [email protected]:42561 I0204 21:07:35.155539 6605 master.cpp:9500] Removing framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 (default) at [email protected]:42561 I0204 21:07:35.155560 6605 master.cpp:3239] Deactivating framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 (default) at [email protected]:42561 I0204 21:07:35.155649 6600 hierarchical.cpp:1517] Performed allocation for 1 agents in 1.754144ms I0204 21:07:35.155709 6605 master.cpp:10204] Updating the state of task 0 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 (latest state: TASK_FINISHED, status update state: TASK_KILLED) I0204 21:07:35.155731 6590 slave.cpp:5291] Forwarding the update TASK_RUNNING (Status UUID: f01a3d08-4f48-4603-8772-4d3648ead670) for task 0 of framework 3d1962e4-db12-47b9-9254-dcc55c23e392-0000 to [email protected]:42561 Process leaked file descriptors. See https://jenkins.io/redirect/troubleshooting/process-leaked-file-descriptors for more information Build step 'Execute shell' marked build as failure
