See <https://builds.apache.org/job/Mesos-Buildbot/BUILDTOOL=cmake,COMPILER=clang,CONFIGURATION=--verbose%20--disable-libtool-wrappers,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=ubuntu%3A14.04,label_exp=(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23)/4594/display/redirect?page=changes>
Changes: [bmahler] Added tests for quota enforcement with unallocated reservations. ------------------------------------------ [...truncated 3.83 MB...] 3: I1213 22:04:57.623236 16059 sched.cpp:232] Version: 1.5.0 3: I1213 22:04:57.624176 16082 sched.cpp:336] New master detected at [email protected]:43266 3: I1213 22:04:57.624318 16082 sched.cpp:396] Authenticating with master [email protected]:43266 3: I1213 22:04:57.624343 16082 sched.cpp:403] Using default CRAM-MD5 authenticatee 3: I1213 22:04:57.624680 16079 authenticatee.cpp:121] Creating new client SASL connection 3: I1213 22:04:57.625109 16064 master.cpp:8932] Authenticating [email protected]:43266 3: I1213 22:04:57.625277 16069 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(149)@172.17.0.2:43266 3: I1213 22:04:57.625628 16076 authenticator.cpp:98] Creating new server SASL connection 3: I1213 22:04:57.626019 16070 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1213 22:04:57.626060 16070 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1213 22:04:57.626231 16081 authenticator.cpp:204] Received SASL authentication start 3: I1213 22:04:57.626319 16081 authenticator.cpp:326] Authentication requires more steps 3: I1213 22:04:57.626471 16081 authenticatee.cpp:259] Received SASL authentication step 3: I1213 22:04:57.626657 16060 authenticator.cpp:232] Received SASL authentication step 3: I1213 22:04:57.626716 16060 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'c5dae00a322c' server FQDN: 'c5dae00a322c' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1213 22:04:57.626746 16060 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1213 22:04:57.626811 16060 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1213 22:04:57.626865 16060 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'c5dae00a322c' server FQDN: 'c5dae00a322c' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1213 22:04:57.626888 16060 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1213 22:04:57.626904 16060 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1213 22:04:57.626942 16060 authenticator.cpp:318] Authentication success 3: I1213 22:04:57.627097 16061 authenticatee.cpp:299] Authentication success 3: I1213 22:04:57.627272 16063 master.cpp:8962] Successfully authenticated principal 'test-principal' at [email protected]:43266 3: I1213 22:04:57.627365 16074 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(149)@172.17.0.2:43266 3: I1213 22:04:57.627539 16078 sched.cpp:502] Successfully authenticated with master [email protected]:43266 3: I1213 22:04:57.627574 16078 sched.cpp:824] Sending SUBSCRIBE call to [email protected]:43266 3: I1213 22:04:57.627739 16078 sched.cpp:857] Will retry registration in 121.343401ms if necessary 3: I1213 22:04:57.627993 16071 master.cpp:2957] Received SUBSCRIBE call for framework 'default' at [email protected]:43266 3: I1213 22:04:57.628032 16071 master.cpp:2274] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }' 3: I1213 22:04:57.628813 16080 master.cpp:3037] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ] 3: I1213 22:04:57.629086 16080 master.cpp:9153] Adding framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 (default) at [email protected]:43266 with roles { } suppressed 3: I1213 22:04:57.629773 16066 sched.cpp:751] Framework registered with 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.629899 16066 sched.cpp:765] Scheduler::registered took 94393ns 3: I1213 22:04:57.629967 16075 hierarchical.cpp:297] Added framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.632078 16075 hierarchical.cpp:1517] Performed allocation for 1 agents in 1.868598ms 3: I1213 22:04:57.632743 16081 master.cpp:8762] Sending 1 offers to framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 (default) at [email protected]:43266 3: I1213 22:04:57.634553 16061 sched.cpp:921] Scheduler::resourceOffers took 1.22475ms 3: I1213 22:04:57.636242 16060 master.cpp:10683] Removing offer 26960d04-8209-40fb-beba-cb1a3b166af7-O0 3: I1213 22:04:57.636440 16060 master.cpp:4273] Processing ACCEPT call for offers: [ 26960d04-8209-40fb-beba-cb1a3b166af7-O0 ] on agent 26960d04-8209-40fb-beba-cb1a3b166af7-S0 at slave(66)@172.17.0.2:43266 (c5dae00a322c) for framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 (default) at [email protected]:43266 3: I1213 22:04:57.636608 16060 master.cpp:3593] Authorizing framework principal 'test-principal' to launch task 0 3: W1213 22:04:57.639133 16062 validation.cpp:1387] Executor 'default' for task '0' uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases. 3: W1213 22:04:57.639183 16062 validation.cpp:1399] Executor 'default' for task '0' uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases. 3: I1213 22:04:57.639727 16062 master.cpp:11438] Adding task 0 with resources cpus(allocated: *):2; mem(allocated: *):1024 on agent 26960d04-8209-40fb-beba-cb1a3b166af7-S0 at slave(66)@172.17.0.2:43266 (c5dae00a322c) 3: I1213 22:04:57.640076 16062 master.cpp:5024] Launching task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 (default) at [email protected]:43266 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 26960d04-8209-40fb-beba-cb1a3b166af7-S0 at slave(66)@172.17.0.2:43266 (c5dae00a322c) 3: I1213 22:04:57.640827 16074 slave.cpp:1807] Got assigned task '0' for framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.641595 16078 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 26960d04-8209-40fb-beba-cb1a3b166af7-S0 from framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.641691 16078 hierarchical.cpp:1238] Framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 filtered agent 26960d04-8209-40fb-beba-cb1a3b166af7-S0 for 5secs 3: I1213 22:04:57.641717 16074 slave.cpp:2077] Authorizing task '0' for framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.641806 16074 slave.cpp:7755] Authorizing framework principal 'test-principal' to launch task 0 3: I1213 22:04:57.643190 16077 slave.cpp:2471] Launching task '0' for framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.643965 16077 paths.cpp:702] Trying to chown '/tmp/GarbageCollectorIntegrationTest_DiskUsage_qOWqCc/slaves/26960d04-8209-40fb-beba-cb1a3b166af7-S0/frameworks/26960d04-8209-40fb-beba-cb1a3b166af7-0000/executors/default/runs/1b23e0d3-bf31-4899-9703-b3758ef0fa3b' to user 'mesos' 3: I1213 22:04:57.644320 16077 slave.cpp:8229] Launching executor 'default' of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 with resources [] in work directory '/tmp/GarbageCollectorIntegrationTest_DiskUsage_qOWqCc/slaves/26960d04-8209-40fb-beba-cb1a3b166af7-S0/frameworks/26960d04-8209-40fb-beba-cb1a3b166af7-0000/executors/default/runs/1b23e0d3-bf31-4899-9703-b3758ef0fa3b' 3: I1213 22:04:57.645083 16077 slave.cpp:3023] Launching container 1b23e0d3-bf31-4899-9703-b3758ef0fa3b for executor 'default' of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.645774 16077 slave.cpp:2557] Queued task '0' for executor 'default' of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.645931 16077 slave.cpp:984] Successfully attached '/tmp/GarbageCollectorIntegrationTest_DiskUsage_qOWqCc/slaves/26960d04-8209-40fb-beba-cb1a3b166af7-S0/frameworks/26960d04-8209-40fb-beba-cb1a3b166af7-0000/executors/default/runs/1b23e0d3-bf31-4899-9703-b3758ef0fa3b' to virtual path '/tmp/GarbageCollectorIntegrationTest_DiskUsage_qOWqCc/slaves/26960d04-8209-40fb-beba-cb1a3b166af7-S0/frameworks/26960d04-8209-40fb-beba-cb1a3b166af7-0000/executors/default/runs/latest' 3: I1213 22:04:57.646000 16077 slave.cpp:984] Successfully attached '/tmp/GarbageCollectorIntegrationTest_DiskUsage_qOWqCc/slaves/26960d04-8209-40fb-beba-cb1a3b166af7-S0/frameworks/26960d04-8209-40fb-beba-cb1a3b166af7-0000/executors/default/runs/1b23e0d3-bf31-4899-9703-b3758ef0fa3b' to virtual path '/frameworks/26960d04-8209-40fb-beba-cb1a3b166af7-0000/executors/default/runs/latest' 3: I1213 22:04:57.646054 16077 slave.cpp:984] Successfully attached '/tmp/GarbageCollectorIntegrationTest_DiskUsage_qOWqCc/slaves/26960d04-8209-40fb-beba-cb1a3b166af7-S0/frameworks/26960d04-8209-40fb-beba-cb1a3b166af7-0000/executors/default/runs/1b23e0d3-bf31-4899-9703-b3758ef0fa3b' to virtual path '/tmp/GarbageCollectorIntegrationTest_DiskUsage_qOWqCc/slaves/26960d04-8209-40fb-beba-cb1a3b166af7-S0/frameworks/26960d04-8209-40fb-beba-cb1a3b166af7-0000/executors/default/runs/1b23e0d3-bf31-4899-9703-b3758ef0fa3b' 3: W1213 22:04:57.649987 16069 process.cpp:2756] Attempted to spawn already running process [email protected]:43266 3: I1213 22:04:57.650266 16069 exec.cpp:162] Version: 1.5.0 3: I1213 22:04:57.650712 16068 exec.cpp:212] Executor started at: executor(15)@172.17.0.2:43266 with pid 16059 3: I1213 22:04:57.651015 16068 slave.cpp:4298] Got registration for executor 'default' of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 from executor(15)@172.17.0.2:43266 3: I1213 22:04:57.651617 16070 exec.cpp:237] Executor registered on agent 26960d04-8209-40fb-beba-cb1a3b166af7-S0 3: I1213 22:04:57.651681 16070 exec.cpp:249] Executor::registered took 42227ns 3: I1213 22:04:57.652781 16061 slave.cpp:2762] Sending queued task '0' to executor 'default' of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 at executor(15)@172.17.0.2:43266 3: I1213 22:04:57.653302 16063 exec.cpp:331] Executor asked to run task '0' 3: I1213 22:04:57.653446 16063 exec.cpp:340] Executor::launchTask took 120129ns 3: I1213 22:04:57.653610 16063 exec.cpp:571] Executor sending status update TASK_RUNNING (Status UUID: b07f0d5f-b725-40e8-b459-9338aac472a0) for task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.654049 16063 slave.cpp:4755] Handling status update TASK_RUNNING (Status UUID: b07f0d5f-b725-40e8-b459-9338aac472a0) for task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 from executor(15)@172.17.0.2:43266 3: I1213 22:04:57.654889 16067 task_status_update_manager.cpp:328] Received task status update TASK_RUNNING (Status UUID: b07f0d5f-b725-40e8-b459-9338aac472a0) for task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.654953 16067 task_status_update_manager.cpp:507] Creating StatusUpdate stream for task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.655617 16067 task_status_update_manager.cpp:383] Forwarding task status update TASK_RUNNING (Status UUID: b07f0d5f-b725-40e8-b459-9338aac472a0) for task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 to the agent 3: I1213 22:04:57.655915 16062 slave.cpp:5238] Forwarding the update TASK_RUNNING (Status UUID: b07f0d5f-b725-40e8-b459-9338aac472a0) for task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 to [email protected]:43266 3: I1213 22:04:57.656215 16062 slave.cpp:5131] Task status update manager successfully handled status update TASK_RUNNING (Status UUID: b07f0d5f-b725-40e8-b459-9338aac472a0) for task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.656286 16062 slave.cpp:5147] Sending acknowledgement for status update TASK_RUNNING (Status UUID: b07f0d5f-b725-40e8-b459-9338aac472a0) for task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 to executor(15)@172.17.0.2:43266 3: I1213 22:04:57.656512 16065 exec.cpp:388] Executor received status update acknowledgement b07f0d5f-b725-40e8-b459-9338aac472a0 for task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.656493 16078 master.cpp:7855] Status update TASK_RUNNING (Status UUID: b07f0d5f-b725-40e8-b459-9338aac472a0) for task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 from agent 26960d04-8209-40fb-beba-cb1a3b166af7-S0 at slave(66)@172.17.0.2:43266 (c5dae00a322c) 3: I1213 22:04:57.656585 16078 master.cpp:7911] Forwarding status update TASK_RUNNING (Status UUID: b07f0d5f-b725-40e8-b459-9338aac472a0) for task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.656844 16078 master.cpp:10158] Updating the state of task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING) 3: I1213 22:04:57.657220 16074 sched.cpp:1029] Scheduler::statusUpdate took 137281ns 3: I1213 22:04:57.657703 16066 master.cpp:5842] Processing ACKNOWLEDGE call b07f0d5f-b725-40e8-b459-9338aac472a0 for task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 (default) at [email protected]:43266 on agent 26960d04-8209-40fb-beba-cb1a3b166af7-S0 3: I1213 22:04:57.658172 16076 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: b07f0d5f-b725-40e8-b459-9338aac472a0) for task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.658393 16073 slave.cpp:5370] Got exited event for executor(15)@172.17.0.2:43266 3: I1213 22:04:57.658483 16073 slave.cpp:4033] Task status update manager successfully handled status update acknowledgement (UUID: b07f0d5f-b725-40e8-b459-9338aac472a0) for task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.658746 16081 slave.cpp:5779] Executor 'default' of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 exited with status 0 3: I1213 22:04:57.658892 16081 slave.cpp:4755] Handling status update TASK_FAILED (Status UUID: 6335bba9-c2ef-4ae6-9595-440822c0a600) for task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 from @0.0.0.0:0 3: I1213 22:04:57.659447 16072 master.cpp:8089] Executor 'default' of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 on agent 26960d04-8209-40fb-beba-cb1a3b166af7-S0 at slave(66)@172.17.0.2:43266 (c5dae00a322c): exited with status 0 3: I1213 22:04:57.659525 16072 master.cpp:10293] Removing executor 'default' with resources [] of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 on agent 26960d04-8209-40fb-beba-cb1a3b166af7-S0 at slave(66)@172.17.0.2:43266 (c5dae00a322c) 3: I1213 22:04:57.660066 16062 task_status_update_manager.cpp:328] Received task status update TASK_FAILED (Status UUID: 6335bba9-c2ef-4ae6-9595-440822c0a600) for task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.660118 16060 sched.cpp:1131] Executor default on agent 26960d04-8209-40fb-beba-cb1a3b166af7-S0 exited with status 0 3: I1213 22:04:57.660207 16060 sched.cpp:1142] Scheduler::executorLost took 49173ns 3: I1213 22:04:57.660238 16062 task_status_update_manager.cpp:383] Forwarding task status update TASK_FAILED (Status UUID: 6335bba9-c2ef-4ae6-9595-440822c0a600) for task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 to the agent 3: I1213 22:04:57.660512 16065 slave.cpp:5238] Forwarding the update TASK_FAILED (Status UUID: 6335bba9-c2ef-4ae6-9595-440822c0a600) for task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 to [email protected]:43266 3: I1213 22:04:57.660878 16065 slave.cpp:5131] Task status update manager successfully handled status update TASK_FAILED (Status UUID: 6335bba9-c2ef-4ae6-9595-440822c0a600) for task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.661092 16078 master.cpp:7855] Status update TASK_FAILED (Status UUID: 6335bba9-c2ef-4ae6-9595-440822c0a600) for task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 from agent 26960d04-8209-40fb-beba-cb1a3b166af7-S0 at slave(66)@172.17.0.2:43266 (c5dae00a322c) 3: I1213 22:04:57.661175 16078 master.cpp:7911] Forwarding status update TASK_FAILED (Status UUID: 6335bba9-c2ef-4ae6-9595-440822c0a600) for task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.661463 16078 master.cpp:10158] Updating the state of task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 (latest state: TASK_FAILED, status update state: TASK_FAILED) 3: I1213 22:04:57.661758 16080 sched.cpp:1029] Scheduler::statusUpdate took 40223ns 3: I1213 22:04:57.662400 16078 master.cpp:5842] Processing ACKNOWLEDGE call 6335bba9-c2ef-4ae6-9595-440822c0a600 for task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 (default) at [email protected]:43266 on agent 26960d04-8209-40fb-beba-cb1a3b166af7-S0 3: I1213 22:04:57.662498 16071 hierarchical.cpp:1192] Recovered cpus(allocated: *):2; mem(allocated: *):1024 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: {}) on agent 26960d04-8209-40fb-beba-cb1a3b166af7-S0 from framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.662541 16078 master.cpp:10264] Removing task 0 with resources cpus(allocated: *):2; mem(allocated: *):1024 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 on agent 26960d04-8209-40fb-beba-cb1a3b166af7-S0 at slave(66)@172.17.0.2:43266 (c5dae00a322c) 3: I1213 22:04:57.663204 16064 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: 6335bba9-c2ef-4ae6-9595-440822c0a600) for task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.663339 16064 task_status_update_manager.cpp:538] Cleaning up status update stream for task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.663729 16066 slave.cpp:4033] Task status update manager successfully handled status update acknowledgement (UUID: 6335bba9-c2ef-4ae6-9595-440822c0a600) for task 0 of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.663779 16066 slave.cpp:8834] Completing task 0 3: I1213 22:04:57.663808 16066 slave.cpp:5883] Cleaning up executor 'default' of framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 at executor(15)@172.17.0.2:43266 3: I1213 22:04:57.664111 16077 gc.cpp:90] Scheduling '/tmp/GarbageCollectorIntegrationTest_DiskUsage_qOWqCc/slaves/26960d04-8209-40fb-beba-cb1a3b166af7-S0/frameworks/26960d04-8209-40fb-beba-cb1a3b166af7-0000/executors/default/runs/1b23e0d3-bf31-4899-9703-b3758ef0fa3b' for gc 6.99999238784593days in the future 3: I1213 22:04:57.664297 16066 slave.cpp:5990] Cleaning up framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.664297 16077 gc.cpp:90] Scheduling '/tmp/GarbageCollectorIntegrationTest_DiskUsage_qOWqCc/slaves/26960d04-8209-40fb-beba-cb1a3b166af7-S0/frameworks/26960d04-8209-40fb-beba-cb1a3b166af7-0000/executors/default' for gc 6.99999238784593days in the future 3: I1213 22:04:57.664446 16075 task_status_update_manager.cpp:289] Closing task status update streams for framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.664536 16075 gc.cpp:90] Scheduling '/tmp/GarbageCollectorIntegrationTest_DiskUsage_qOWqCc/slaves/26960d04-8209-40fb-beba-cb1a3b166af7-S0/frameworks/26960d04-8209-40fb-beba-cb1a3b166af7-0000' for gc 6.99999238784593days in the future 3: I1213 22:04:57.664944 16076 slave.cpp:6298] Current disk usage 90.00%. Max allowed age: 0ns 3: I1213 22:04:57.665096 16073 gc.cpp:263] Pruning directories with remaining removal time 6.99998081377185days 3: I1213 22:04:57.665343 16068 gc.cpp:208] Deleting /tmp/GarbageCollectorIntegrationTest_DiskUsage_qOWqCc/slaves/26960d04-8209-40fb-beba-cb1a3b166af7-S0/frameworks/26960d04-8209-40fb-beba-cb1a3b166af7-0000/executors/default/runs/1b23e0d3-bf31-4899-9703-b3758ef0fa3b 3: I1213 22:04:57.665585 16068 gc.cpp:218] Deleted '/tmp/GarbageCollectorIntegrationTest_DiskUsage_qOWqCc/slaves/26960d04-8209-40fb-beba-cb1a3b166af7-S0/frameworks/26960d04-8209-40fb-beba-cb1a3b166af7-0000/executors/default/runs/1b23e0d3-bf31-4899-9703-b3758ef0fa3b' 3: I1213 22:04:57.665717 16068 gc.cpp:208] Deleting /tmp/GarbageCollectorIntegrationTest_DiskUsage_qOWqCc/slaves/26960d04-8209-40fb-beba-cb1a3b166af7-S0/frameworks/26960d04-8209-40fb-beba-cb1a3b166af7-0000/executors/default 3: I1213 22:04:57.666046 16068 gc.cpp:218] Deleted '/tmp/GarbageCollectorIntegrationTest_DiskUsage_qOWqCc/slaves/26960d04-8209-40fb-beba-cb1a3b166af7-S0/frameworks/26960d04-8209-40fb-beba-cb1a3b166af7-0000/executors/default' 3: I1213 22:04:57.666188 16068 gc.cpp:208] Deleting /tmp/GarbageCollectorIntegrationTest_DiskUsage_qOWqCc/slaves/26960d04-8209-40fb-beba-cb1a3b166af7-S0/frameworks/26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.666450 16068 gc.cpp:218] Deleted '/tmp/GarbageCollectorIntegrationTest_DiskUsage_qOWqCc/slaves/26960d04-8209-40fb-beba-cb1a3b166af7-S0/frameworks/26960d04-8209-40fb-beba-cb1a3b166af7-0000' 3: I1213 22:04:57.667996 16063 hierarchical.cpp:1517] Performed allocation for 1 agents in 1.475544ms 3: I1213 22:04:57.668787 16060 master.cpp:8762] Sending 1 offers to framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 (default) at [email protected]:43266 3: I1213 22:04:57.669479 16062 sched.cpp:921] Scheduler::resourceOffers took 45679ns 3: I1213 22:04:57.672726 16074 process.cpp:3503] Handling HTTP event for process 'files' with path: '/files/browse' 3: I1213 22:04:57.675462 16075 http.cpp:1185] HTTP GET for /files/browse?path=%2Ftmp%2FGarbageCollectorIntegrationTest_DiskUsage_qOWqCc%2Fslaves%2F26960d04-8209-40fb-beba-cb1a3b166af7-S0%2Fframeworks%2F26960d04-8209-40fb-beba-cb1a3b166af7-0000%2Fexecutors%2Fdefault from 172.17.0.2:52322 3: I1213 22:04:57.680717 16059 sched.cpp:2009] Asked to stop the driver 3: I1213 22:04:57.680892 16083 sched.cpp:1191] Stopping framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.681236 16061 master.cpp:9442] Processing TEARDOWN call for framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 (default) at [email protected]:43266 3: I1213 22:04:57.681269 16061 master.cpp:9454] Removing framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 (default) at [email protected]:43266 3: I1213 22:04:57.681282 16061 master.cpp:3327] Deactivating framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 (default) at [email protected]:43266 3: I1213 22:04:57.681413 16068 hierarchical.cpp:405] Deactivated framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.681954 16061 master.cpp:10683] Removing offer 26960d04-8209-40fb-beba-cb1a3b166af7-O1 3: I1213 22:04:57.682183 16065 slave.cpp:3375] Asked to shut down framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 by [email protected]:43266 3: I1213 22:04:57.682219 16065 slave.cpp:3390] Cannot shut down unknown framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.682255 16065 slave.cpp:909] Agent terminating 3: I1213 22:04:57.682679 16061 master.cpp:1305] Agent 26960d04-8209-40fb-beba-cb1a3b166af7-S0 at slave(66)@172.17.0.2:43266 (c5dae00a322c) disconnected 3: I1213 22:04:57.682716 16061 master.cpp:3364] Disconnecting agent 26960d04-8209-40fb-beba-cb1a3b166af7-S0 at slave(66)@172.17.0.2:43266 (c5dae00a322c) 3: I1213 22:04:57.682797 16061 master.cpp:3383] Deactivating agent 26960d04-8209-40fb-beba-cb1a3b166af7-S0 at slave(66)@172.17.0.2:43266 (c5dae00a322c) 3: I1213 22:04:57.682862 16067 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 26960d04-8209-40fb-beba-cb1a3b166af7-S0 from framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.683367 16067 hierarchical.cpp:344] Removed framework 26960d04-8209-40fb-beba-cb1a3b166af7-0000 3: I1213 22:04:57.683495 16067 hierarchical.cpp:766] Agent 26960d04-8209-40fb-beba-cb1a3b166af7-S0 deactivated 3: I1213 22:04:57.689623 16059 master.cpp:1147] Master terminating 3: I1213 22:04:57.690546 16080 hierarchical.cpp:609] Removed agent 26960d04-8209-40fb-beba-cb1a3b166af7-S0 3: [ OK ] GarbageCollectorIntegrationTest.DiskUsage (134 ms) 3: [ RUN ] GarbageCollectorIntegrationTest.Unschedule 3: I1213 22:04:57.699126 16059 cluster.cpp:172] Creating default 'local' authorizer 3: I1213 22:04:57.703938 16074 master.cpp:456] Master 2c5737a1-4805-4b50-9491-42888a2ce9aa (c5dae00a322c) started on 172.17.0.2:43266 3: I1213 22:04:57.703999 16074 master.cpp:458] 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/WDgdqV/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/WDgdqV/master" --zk_session_timeout="10secs" 3: I1213 22:04:57.704434 16074 master.cpp:507] Master only allowing authenticated frameworks to register 3: I1213 22:04:57.704447 16074 master.cpp:513] Master only allowing authenticated agents to register 3: I1213 22:04:57.704454 16074 master.cpp:519] Master only allowing authenticated HTTP frameworks to register 3: I1213 22:04:57.704463 16074 credentials.hpp:37] Loading credentials for authentication from '/tmp/WDgdqV/credentials' 3: I1213 22:04:57.704911 16074 master.cpp:563] Using default 'crammd5' authenticator 3: I1213 22:04:57.705152 16074 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' 3: I1213 22:04:57.705396 16074 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' 3: I1213 22:04:57.705607 16074 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' 3: I1213 22:04:57.705804 16074 master.cpp:642] Authorization enabled 3: I1213 22:04:57.706043 16083 hierarchical.cpp:175] Initialized hierarchical allocator process 3: I1213 22:04:57.706120 16076 whitelist_watcher.cpp:77] No whitelist given 3: I1213 22:04:57.710386 16061 master.cpp:2209] Elected as the leading master! 3: I1213 22:04:57.710422 16061 master.cpp:1689] Recovering from registrar 3: I1213 22:04:57.710604 16066 registrar.cpp:347] Recovering registrar 3: I1213 22:04:57.711573 16066 registrar.cpp:391] Successfully fetched the registry (0B) in 921088ns 3: I1213 22:04:57.711740 16066 registrar.cpp:495] Applied 1 operations in 61245ns; attempting to update the registry 3: I1213 22:04:57.712550 16066 registrar.cpp:552] Successfully updated the registry in 732928ns 3: I1213 22:04:57.712725 16066 registrar.cpp:424] Successfully recovered registrar 3: I1213 22:04:57.713313 16062 master.cpp:1802] Recovered 0 agents from the registry (135B); allowing 10mins for agents to re-register 3: I1213 22:04:57.713382 16077 hierarchical.cpp:213] Skipping recovery of hierarchical allocator: nothing to recover 3: W1213 22:04:57.720679 16059 process.cpp:2756] Attempted to spawn already running process [email protected]:43266 3: I1213 22:04:57.721117 16059 cluster.cpp:460] Creating default 'local' authorizer 3: I1213 22:04:57.724521 16079 slave.cpp:258] Mesos agent started on (67)@172.17.0.2:43266 3: I1213 22:04:57.724577 16079 slave.cpp:259] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/GarbageCollectorIntegrationTest_Unschedule_mtFdfi/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/GarbageCollectorIntegrationTest_Unschedule_mtFdfi/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/GarbageCollectorIntegrationTest_Unschedule_mtFdfi/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/GarbageCollectorIntegrationTest_Unschedule_mtFdfi/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/GarbageCollectorIntegrationTest_Unschedule_mtFdfi/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --reconfiguration_policy="equal" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/GarbageCollectorIntegrationTest_Unschedule_mtFdfi" --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/GarbageCollectorIntegrationTest_Unschedule_a7OHP6" --zk_session_timeout="10secs" 3: I1213 22:04:57.725167 16079 credentials.hpp:86] Loading credential for authentication from '/tmp/GarbageCollectorIntegrationTest_Unschedule_mtFdfi/credential' 3: I1213 22:04:57.725410 16079 slave.cpp:291] Agent using credential for: test-principal 3: I1213 22:04:57.725441 16079 credentials.hpp:37] Loading credentials for authentication from '/tmp/GarbageCollectorIntegrationTest_Unschedule_mtFdfi/http_credentials' 3: I1213 22:04:57.725781 16079 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' 3: I1213 22:04:57.726013 16079 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite' 3: I1213 22:04:57.728549 16079 slave.cpp:590] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] 3: I1213 22:04:57.728904 16079 slave.cpp:598] Agent attributes: [ ] 3: I1213 22:04:57.728921 16079 slave.cpp:607] Agent hostname: c5dae00a322c 3: I1213 22:04:57.729132 16078 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I1213 22:04:57.731673 16076 state.cpp:66] Recovering state from '/tmp/GarbageCollectorIntegrationTest_Unschedule_a7OHP6/meta' 3: I1213 22:04:57.732161 16076 task_status_update_manager.cpp:207] Recovering task status update manager 3: I1213 22:04:57.732681 16061 slave.cpp:6747] Finished recovery 3: I1213 22:04:57.733752 16080 slave.cpp:1033] New master detected at [email protected]:43266 3: I1213 22:04:57.733762 16067 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I1213 22:04:57.733893 16080 slave.cpp:1088] Detecting new master 3: I1213 22:04:57.738328 16068 slave.cpp:1115] Authenticating with master [email protected]:43266 3: I1213 22:04:57.738448 16068 slave.cpp:1124] Using default CRAM-MD5 authenticatee 3: I1213 22:04:57.738888 16081 authenticatee.cpp:121] Creating new client SASL connection 3: I1213 22:04:57.739411 16071 master.cpp:8932] Authenticating slave(67)@172.17.0.2:43266 3: I1213 22:04:57.739645 16066 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(150)@172.17.0.2:43266 3: I1213 22:04:57.740140 16065 authenticator.cpp:98] Creating new server SASL connection 3: I1213 22:04:57.740640 16063 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1213 22:04:57.740700 16063 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1213 22:04:57.740933 16078 authenticator.cpp:204] Received SASL authentication start 3: I1213 22:04:57.741034 16078 authenticator.cpp:326] Authentication requires more steps 3: I1213 22:04:57.741279 16082 authenticatee.cpp:259] Received SASL authentication step 3: I1213 22:04:57.741508 16062 authenticator.cpp:232] Received SASL authentication step 3: I1213 22:04:57.741555 16062 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'c5dae00a322c' server FQDN: 'c5dae00a322c' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1213 22:04:57.741576 16062 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1213 22:04:57.741649 16062 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1213 22:04:57.741703 16062 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'c5dae00a322c' server FQDN: 'c5dae00a322c' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1213 22:04:57.741724 16062 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1213 22:04:57.741734 16062 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1213 22:04:57.741755 16062 authenticator.cpp:318] Authentication success 3: I1213 22:04:57.741914 16069 authenticatee.cpp:299] Authentication success 3: I1213 22:04:57.742105 16077 master.cpp:8962] Successfully authenticated principal 'test-principal' at slave(67)@172.17.0.2:43266 3: I1213 22:04:57.742199 16079 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(150)@172.17.0.2:43266 3: I1213 22:04:57.742430 16069 slave.cpp:1207] Successfully authenticated with master [email protected]:43266 3: I1213 22:04:57.742802 16069 slave.cpp:1684] Will retry registration in 7.916076ms if necessary 3: I1213 22:04:57.743119 16064 master.cpp:6077] Received register agent message from slave(67)@172.17.0.2:43266 (c5dae00a322c) 3: I1213 22:04:57.743199 16064 master.cpp:3866] Authorizing agent with principal 'test-principal' 3: I1213 22:04:57.743968 16061 master.cpp:6147] Authorized registration of agent at slave(67)@172.17.0.2:43266 (c5dae00a322c) 3: I1213 22:04:57.744115 16061 master.cpp:6240] Registering agent at slave(67)@172.17.0.2:43266 (c5dae00a322c) with id 2c5737a1-4805-4b50-9491-42888a2ce9aa-S0 3: I1213 22:04:57.744899 16075 registrar.cpp:495] Applied 1 operations in 166866ns; attempting to update the registry 3: I1213 22:04:57.745734 16068 registrar.cpp:552] Successfully updated the registry in 722944ns 3: I1213 22:04:57.746047 16071 master.cpp:6288] Admitted agent 2c5737a1-4805-4b50-9491-42888a2ce9aa-S0 at slave(67)@172.17.0.2:43266 (c5dae00a322c) 3: I1213 22:04:57.747174 16071 master.cpp:6337] Registered agent 2c5737a1-4805-4b50-9491-42888a2ce9aa-S0 at slave(67)@172.17.0.2:43266 (c5dae00a322c) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] 3: I1213 22:04:57.747611 16065 slave.cpp:1253] Registered with master [email protected]:43266; given agent ID 2c5737a1-4805-4b50-9491-42888a2ce9aa-S0 3: I1213 22:04:57.747792 16062 task_status_update_manager.cpp:188] Resuming sending task status updates 3: I1213 22:04:57.747805 16066 hierarchical.cpp:574] Added agent 2c5737a1-4805-4b50-9491-42888a2ce9aa-S0 (c5dae00a322c) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {}) 3: I1213 22:04:57.748167 16065 slave.cpp:1273] Checkpointing SlaveInfo to '/tmp/GarbageCollectorIntegrationTest_Unschedule_a7OHP6/meta/slaves/2c5737a1-4805-4b50-9491-42888a2ce9aa-S0/slave.info' 3: I1213 22:04:57.748282 16066 hierarchical.cpp:1517] Performed allocation for 1 agents in 253482ns 3: W1213 22:04:57.748677 16059 process.cpp:2756] Attempted to spawn already running process [email protected]:43266 3: I1213 22:04:57.748987 16065 slave.cpp:1330] Forwarding agent update {"offer_operations":{},"resource_categories":{"oversubscribed":true},"resource_version_uuid":"88NG16TxQC+1SxZBXoAECA==","slave_id":{"value":"2c5737a1-4805-4b50-9491-42888a2ce9aa-S0"}} 3: I1213 22:04:57.749423 16065 master.cpp:7270] Received update of agent 2c5737a1-4805-4b50-9491-42888a2ce9aa-S0 at slave(67)@172.17.0.2:43266 (c5dae00a322c) with total oversubscribed resources {} 3: I1213 22:04:57.749799 16065 master.cpp:7368] Ignoring update on agent 2c5737a1-4805-4b50-9491-42888a2ce9aa-S0 at slave(67)@172.17.0.2:43266 (c5dae00a322c) as it reports no changes 3: I1213 22:04:57.750788 16059 sched.cpp:232] Version: 1.5.0 3: I1213 22:04:57.751775 16075 sched.cpp:336] New master detected at [email protected]:43266 3: I1213 22:04:57.751906 16075 sched.cpp:396] Authenticating with master [email protected]:43266 3: I1213 22:04:57.751929 16075 sched.cpp:403] Using default CRAM-MD5 authenticatee 3: I1213 22:04:57.752300 16072 authenticatee.cpp:121] Creating new client SASL connection 3: I1213 22:04:57.752770 16067 master.cpp:8932] Authenticating [email protected]:43266 3: I1213 22:04:57.753042 16068 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(151)@172.17.0.2:43266 3: I1213 22:04:57.753429 16063 authenticator.cpp:98] Creating new server SASL connection 3: I1213 22:04:57.753785 16071 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1213 22:04:57.753829 16071 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1213 22:04:57.754007 16078 authenticator.cpp:204] Received SASL authentication start 3: I1213 22:04:57.754094 16078 authenticator.cpp:326] Authentication requires more steps 3: I1213 22:04:57.754271 16078 authenticatee.cpp:259] Received SASL authentication step 3: I1213 22:04:57.754477 16082 authenticator.cpp:232] Received SASL authentication step 3: I1213 22:04:57.754523 16082 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'c5dae00a322c' server FQDN: 'c5dae00a322c' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1213 22:04:57.754540 16082 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1213 22:04:57.754585 16082 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1213 22:04:57.754639 16082 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'c5dae00a322c' server FQDN: 'c5dae00a322c' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1213 22:04:57.754662 16082 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1213 22:04:57.754678 16082 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1213 22:04:57.754709 16082 authenticator.cpp:318] Authentication success Build step 'Execute shell' marked build as failure Not sending mail to unregistered user [email protected]
