See <https://builds.apache.org/job/Mesos-Ubuntu-distcheck/109/changes>
Changes: [vinod] Hid "acls" flag from master's flags. ------------------------------------------ [...truncated 24936 lines...] sh -c 'sleep 10' I0530 22:35:36.924428 16567 exec.cpp:524] Executor sending status update TASK_RUNNING (UUID: 1b8fac7c-7395-437a-90c0-a4d6792dcaa4) for task bd359984-02d1-4b2d-aa66-78f67c8df47f of framework 20140530-223535-160088899-42594-15528-0000 I0530 22:35:36.924839 15628 slave.cpp:2018] Handling status update TASK_RUNNING (UUID: 1b8fac7c-7395-437a-90c0-a4d6792dcaa4) for task bd359984-02d1-4b2d-aa66-78f67c8df47f of framework 20140530-223535-160088899-42594-15528-0000 from executor(1)@67.195.138.9:39538 I0530 22:35:36.925050 15625 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 1b8fac7c-7395-437a-90c0-a4d6792dcaa4) for task bd359984-02d1-4b2d-aa66-78f67c8df47f of framework 20140530-223535-160088899-42594-15528-0000 I0530 22:35:36.925072 15625 status_update_manager.cpp:499] Creating StatusUpdate stream for task bd359984-02d1-4b2d-aa66-78f67c8df47f of framework 20140530-223535-160088899-42594-15528-0000 I0530 22:35:36.925299 15625 status_update_manager.hpp:342] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 1b8fac7c-7395-437a-90c0-a4d6792dcaa4) for task bd359984-02d1-4b2d-aa66-78f67c8df47f of framework 20140530-223535-160088899-42594-15528-0000 I0530 22:35:36.981915 15628 hierarchical_allocator_process.hpp:687] Performed allocation for 1 slaves in 50733ns I0530 22:35:36.992493 15625 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 1b8fac7c-7395-437a-90c0-a4d6792dcaa4) for task bd359984-02d1-4b2d-aa66-78f67c8df47f of framework 20140530-223535-160088899-42594-15528-0000 to [email protected]:42594 I0530 22:35:36.992753 15626 slave.cpp:2139] Status update manager successfully handled status update TASK_RUNNING (UUID: 1b8fac7c-7395-437a-90c0-a4d6792dcaa4) for task bd359984-02d1-4b2d-aa66-78f67c8df47f of framework 20140530-223535-160088899-42594-15528-0000 I0530 22:35:36.992768 15626 slave.cpp:2145] Sending acknowledgement for status update TASK_RUNNING (UUID: 1b8fac7c-7395-437a-90c0-a4d6792dcaa4) for task bd359984-02d1-4b2d-aa66-78f67c8df47f of framework 20140530-223535-160088899-42594-15528-0000 to executor(1)@67.195.138.9:39538 I0530 22:35:36.992949 15631 process.cpp:1098] Socket closed while receiving I0530 22:35:36.993010 15629 master.cpp:2628] Status update TASK_RUNNING (UUID: 1b8fac7c-7395-437a-90c0-a4d6792dcaa4) for task bd359984-02d1-4b2d-aa66-78f67c8df47f of framework 20140530-223535-160088899-42594-15528-0000 from slave 20140530-223535-160088899-42594-15528-0 at slave(82)@67.195.138.9:42594 (vesta.apache.org) I0530 22:35:36.993057 15628 sched.cpp:625] Scheduler::statusUpdate took 18395ns I0530 22:35:36.993227 15626 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 1b8fac7c-7395-437a-90c0-a4d6792dcaa4) for task bd359984-02d1-4b2d-aa66-78f67c8df47f of framework 20140530-223535-160088899-42594-15528-0000 I0530 22:35:36.993247 15626 status_update_manager.hpp:342] Checkpointing ACK for status update TASK_RUNNING (UUID: 1b8fac7c-7395-437a-90c0-a4d6792dcaa4) for task bd359984-02d1-4b2d-aa66-78f67c8df47f of framework 20140530-223535-160088899-42594-15528-0000 I0530 22:35:36.993377 16572 process.cpp:1037] Socket closed while receiving I0530 22:35:36.993381 16566 exec.cpp:338] Executor received status update acknowledgement 1b8fac7c-7395-437a-90c0-a4d6792dcaa4 for task bd359984-02d1-4b2d-aa66-78f67c8df47f of framework 20140530-223535-160088899-42594-15528-0000 I0530 22:35:37.016734 15629 slave.cpp:1604] Status update manager successfully handled status update acknowledgement (UUID: 1b8fac7c-7395-437a-90c0-a4d6792dcaa4) for task bd359984-02d1-4b2d-aa66-78f67c8df47f of framework 20140530-223535-160088899-42594-15528-0000 I0530 22:35:37.017132 15528 slave.cpp:425] Slave terminating I0530 22:35:37.017220 15625 master.cpp:712] Slave 20140530-223535-160088899-42594-15528-0 at slave(82)@67.195.138.9:42594 (vesta.apache.org) disconnected I0530 22:35:37.017246 15625 master.cpp:1344] Disconnecting slave 20140530-223535-160088899-42594-15528-0 I0530 22:35:37.017410 15625 hierarchical_allocator_process.hpp:483] Slave 20140530-223535-160088899-42594-15528-0 disconnected I0530 22:35:37.064326 15528 mesos_containerizer.cpp:124] Using isolation: posix/cpu,posix/mem I0530 22:35:37.064714 15631 process.cpp:1037] Socket closed while receiving I0530 22:35:37.066308 15627 slave.cpp:143] Slave started on 83)@67.195.138.9:42594 I0530 22:35:37.066320 15627 credentials.hpp:35] Loading credentials for authentication from '/tmp/SlaveRecoveryTest_0_ReconcileTasksMissingFromSlave_9HpjFF/credential' I0530 22:35:37.066393 15627 slave.cpp:242] Slave using credential for: test-principal I0530 22:35:37.066495 15627 slave.cpp:255] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0530 22:35:37.066542 15627 slave.cpp:283] Slave hostname: vesta.apache.org I0530 22:35:37.066550 15627 slave.cpp:284] Slave checkpoint: true I0530 22:35:37.067015 15625 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_ReconcileTasksMissingFromSlave_9HpjFF/meta' I0530 22:35:37.067486 15626 status_update_manager.cpp:193] Recovering status update manager I0530 22:35:37.067735 15626 mesos_containerizer.cpp:281] Recovering containerizer I0530 22:35:37.068133 15628 slave.cpp:3018] Finished recovery I0530 22:35:37.068502 15628 slave.cpp:536] New master detected at [email protected]:42594 I0530 22:35:37.068537 15628 slave.cpp:612] Authenticating with master [email protected]:42594 I0530 22:35:37.068570 15625 status_update_manager.cpp:167] New master detected at [email protected]:42594 I0530 22:35:37.068609 15628 slave.cpp:585] Detecting new master I0530 22:35:37.068650 15630 authenticatee.hpp:128] Creating new client SASL connection I0530 22:35:37.068831 15623 master.cpp:2986] Authenticating slave(83)@67.195.138.9:42594 I0530 22:35:37.068945 15628 authenticator.hpp:156] Creating new server SASL connection I0530 22:35:37.069028 15630 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I0530 22:35:37.069041 15630 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I0530 22:35:37.069087 15630 authenticator.hpp:262] Received SASL authentication start I0530 22:35:37.069136 15630 authenticator.hpp:384] Authentication requires more steps I0530 22:35:37.069164 15630 authenticatee.hpp:265] Received SASL authentication step I0530 22:35:37.069207 15630 authenticator.hpp:290] Received SASL authentication step I0530 22:35:37.069221 15630 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0530 22:35:37.069250 15630 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I0530 22:35:37.069259 15630 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0530 22:35:37.069268 15630 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0530 22:35:37.069274 15630 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0530 22:35:37.069279 15630 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0530 22:35:37.069288 15630 authenticator.hpp:376] Authentication success I0530 22:35:37.069324 15628 authenticatee.hpp:305] Authentication success I0530 22:35:37.069344 15630 master.cpp:3026] Successfully authenticated principal 'test-principal' at slave(83)@67.195.138.9:42594 I0530 22:35:37.069458 15628 slave.cpp:669] Successfully authenticated with master [email protected]:42594 I0530 22:35:37.069517 15628 slave.cpp:902] Will retry registration in 6.102081ms if necessary W0530 22:35:37.069603 15626 master.cpp:2417] Slave at slave(83)@67.195.138.9:42594 (vesta.apache.org) is being allowed to re-register with an already in use id (20140530-223535-160088899-42594-15528-0) W0530 22:35:37.069641 15626 master.cpp:3155] Sending TASK_LOST for task bd359984-02d1-4b2d-aa66-78f67c8df47f of framework 20140530-223535-160088899-42594-15528-0000 unknown to the slave 20140530-223535-160088899-42594-15528-0 at slave(83)@67.195.138.9:42594 (vesta.apache.org) I0530 22:35:37.069680 15627 slave.cpp:753] Re-registered with master [email protected]:42594 I0530 22:35:37.070652 15626 master.cpp:2628] Status update TASK_LOST (UUID: a2f0e845-5883-4288-8334-9e3009e4cb93) for task bd359984-02d1-4b2d-aa66-78f67c8df47f of framework 20140530-223535-160088899-42594-15528-0000 from slave 20140530-223535-160088899-42594-15528-0 at slave(83)@67.195.138.9:42594 (vesta.apache.org) I0530 22:35:37.070714 15627 sched.cpp:625] Scheduler::statusUpdate took 31402ns I0530 22:35:37.070739 15626 master.hpp:673] Removing task bd359984-02d1-4b2d-aa66-78f67c8df47f with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140530-223535-160088899-42594-15528-0 (vesta.apache.org) I0530 22:35:37.071010 15626 hierarchical_allocator_process.hpp:636] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20140530-223535-160088899-42594-15528-0 from framework 20140530-223535-160088899-42594-15528-0000 I0530 22:35:37.071112 15626 hierarchical_allocator_process.hpp:497] Slave 20140530-223535-160088899-42594-15528-0 reconnected I0530 22:35:37.071230 15626 hierarchical_allocator_process.hpp:751] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140530-223535-160088899-42594-15528-0 to framework 20140530-223535-160088899-42594-15528-0000 I0530 22:35:37.071348 15626 hierarchical_allocator_process.hpp:687] Performed allocation for 1 slaves in 159949ns I0530 22:35:37.071383 15627 master.hpp:683] Adding offer 20140530-223535-160088899-42594-15528-1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140530-223535-160088899-42594-15528-0 (vesta.apache.org) I0530 22:35:37.071430 15627 master.cpp:2933] Sending 1 offers to framework 20140530-223535-160088899-42594-15528-0000 I0530 22:35:37.071547 15626 sched.cpp:534] Scheduler::resourceOffers took 13241ns I0530 22:35:37.091078 15627 sched.cpp:730] Stopping framework '20140530-223535-160088899-42594-15528-0000' I0530 22:35:37.091133 15528 master.cpp:574] Master terminating I0530 22:35:37.091176 15528 master.hpp:693] Removing offer 20140530-223535-160088899-42594-15528-1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140530-223535-160088899-42594-15528-0 (vesta.apache.org) I0530 22:35:37.091469 15624 slave.cpp:2224] [email protected]:42594 exited W0530 22:35:37.091485 15624 slave.cpp:2227] Master disconnected! Waiting for a new master to be elected I0530 22:35:37.093132 15528 slave.cpp:425] Slave terminating [ OK ] SlaveRecoveryTest/0.ReconcileTasksMissingFromSlave (1202 ms) [ RUN ] SlaveRecoveryTest/0.RestartBeforeContainerizerLaunch Using temporary directory '/tmp/SlaveRecoveryTest_0_RestartBeforeContainerizerLaunch_CWmb34' I0530 22:35:37.259887 15528 leveldb.cpp:176] Opened db in 164.845092ms I0530 22:35:37.269042 15528 leveldb.cpp:183] Compacted db in 9.1357ms I0530 22:35:37.269057 15528 leveldb.cpp:198] Created db iterator in 3320ns I0530 22:35:37.269064 15528 leveldb.cpp:204] Seeked to beginning of db in 472ns I0530 22:35:37.269070 15528 leveldb.cpp:273] Iterated through 0 keys in the db in 277ns I0530 22:35:37.269083 15528 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0530 22:35:37.269400 15624 recover.cpp:425] Starting replica recovery I0530 22:35:37.269639 15626 recover.cpp:451] Replica is in EMPTY status I0530 22:35:37.270166 15626 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request I0530 22:35:37.270334 15626 recover.cpp:188] Received a recover response from a replica in EMPTY status I0530 22:35:37.270575 15626 recover.cpp:542] Updating replica status to STARTING I0530 22:35:37.270822 15627 master.cpp:272] Master 20140530-223537-160088899-42594-15528 (vesta.apache.org) started on 67.195.138.9:42594 I0530 22:35:37.270838 15627 master.cpp:309] Master only allowing authenticated frameworks to register I0530 22:35:37.270843 15627 master.cpp:314] Master only allowing authenticated slaves to register I0530 22:35:37.270850 15627 credentials.hpp:35] Loading credentials for authentication from '/tmp/SlaveRecoveryTest_0_RestartBeforeContainerizerLaunch_CWmb34/credentials' I0530 22:35:37.270905 15627 master.cpp:340] Master enabling authorization I0530 22:35:37.271201 15629 master.cpp:108] No whitelist given. Advertising offers for all slaves I0530 22:35:37.271250 15623 hierarchical_allocator_process.hpp:301] Initializing hierarchical allocator process with master : [email protected]:42594 I0530 22:35:37.271708 15624 master.cpp:957] The newly elected leader is [email protected]:42594 with id 20140530-223537-160088899-42594-15528 I0530 22:35:37.271747 15624 master.cpp:970] Elected as the leading master! I0530 22:35:37.271755 15624 master.cpp:788] Recovering from registrar I0530 22:35:37.271888 15629 registrar.cpp:313] Recovering registrar I0530 22:35:37.311610 15626 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 40.979916ms I0530 22:35:37.311645 15626 replica.cpp:320] Persisted replica status to STARTING I0530 22:35:37.311724 15626 recover.cpp:451] Replica is in STARTING status I0530 22:35:37.312145 15629 replica.cpp:638] Replica in STARTING status received a broadcasted recover request I0530 22:35:37.312260 15630 recover.cpp:188] Received a recover response from a replica in STARTING status I0530 22:35:37.312497 15628 recover.cpp:542] Updating replica status to VOTING I0530 22:35:37.320689 15625 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 8.105259ms I0530 22:35:37.320727 15625 replica.cpp:320] Persisted replica status to VOTING I0530 22:35:37.320801 15628 recover.cpp:556] Successfully joined the Paxos group I0530 22:35:37.320904 15628 recover.cpp:440] Recover process terminated I0530 22:35:37.321146 15626 log.cpp:656] Attempting to start the writer I0530 22:35:37.321776 15628 replica.cpp:474] Replica received implicit promise request with proposal 1 I0530 22:35:37.328634 15628 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 6.835237ms I0530 22:35:37.328649 15628 replica.cpp:342] Persisted promised to 1 I0530 22:35:37.328991 15626 coordinator.cpp:230] Coordinator attemping to fill missing position I0530 22:35:37.329620 15628 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2 I0530 22:35:37.336604 15628 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 6.972213ms I0530 22:35:37.336621 15628 replica.cpp:676] Persisted action at 0 I0530 22:35:37.337178 15623 replica.cpp:508] Replica received write request for position 0 I0530 22:35:37.337198 15623 leveldb.cpp:438] Reading position from leveldb took 10793ns I0530 22:35:37.344571 15623 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 7.360222ms I0530 22:35:37.344588 15623 replica.cpp:676] Persisted action at 0 I0530 22:35:37.344897 15627 replica.cpp:655] Replica received learned notice for position 0 I0530 22:35:37.352548 15627 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 7.623291ms I0530 22:35:37.352573 15627 replica.cpp:676] Persisted action at 0 I0530 22:35:37.352584 15627 replica.cpp:661] Replica learned NOP action at position 0 I0530 22:35:37.352852 15624 log.cpp:672] Writer started with ending position 0 I0530 22:35:37.353328 15627 leveldb.cpp:438] Reading position from leveldb took 12712ns I0530 22:35:37.354663 15624 registrar.cpp:346] Successfully fetched the registry (0B) I0530 22:35:37.354681 15624 registrar.cpp:422] Attempting to update the 'registry' I0530 22:35:37.355970 15628 log.cpp:680] Attempting to append 134 bytes to the log I0530 22:35:37.356057 15626 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1 I0530 22:35:37.356566 15629 replica.cpp:508] Replica received write request for position 1 I0530 22:35:37.368485 15629 leveldb.cpp:343] Persisting action (153 bytes) to leveldb took 11.89699ms I0530 22:35:37.368516 15629 replica.cpp:676] Persisted action at 1 I0530 22:35:37.368901 15628 replica.cpp:655] Replica received learned notice for position 1 I0530 22:35:37.376446 15628 leveldb.cpp:343] Persisting action (155 bytes) to leveldb took 7533us I0530 22:35:37.376466 15628 replica.cpp:676] Persisted action at 1 I0530 22:35:37.376489 15628 replica.cpp:661] Replica learned APPEND action at position 1 I0530 22:35:37.376866 15630 registrar.cpp:479] Successfully updated 'registry' I0530 22:35:37.376934 15630 registrar.cpp:372] Successfully recovered registrar I0530 22:35:37.377035 15630 log.cpp:699] Attempting to truncate the log to 1 I0530 22:35:37.377053 15627 master.cpp:815] Recovered 0 slaves from the Registry (97B) ; allowing 10mins for slaves to re-register I0530 22:35:37.377143 15626 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2 I0530 22:35:37.377547 15627 replica.cpp:508] Replica received write request for position 2 I0530 22:35:37.380218 15624 slave.cpp:143] Slave started on 84)@67.195.138.9:42594 I0530 22:35:37.380236 15624 credentials.hpp:35] Loading credentials for authentication from '/tmp/SlaveRecoveryTest_0_RestartBeforeContainerizerLaunch_YYhQcv/credential' I0530 22:35:37.380303 15624 slave.cpp:242] Slave using credential for: test-principal I0530 22:35:37.380414 15624 slave.cpp:255] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0530 22:35:37.380460 15624 slave.cpp:283] Slave hostname: vesta.apache.org I0530 22:35:37.380467 15624 slave.cpp:284] Slave checkpoint: true I0530 22:35:37.381114 15626 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_RestartBeforeContainerizerLaunch_YYhQcv/meta' I0530 22:35:37.381279 15626 status_update_manager.cpp:193] Recovering status update manager I0530 22:35:37.381476 15624 slave.cpp:3018] Finished recovery I0530 22:35:37.381790 15626 slave.cpp:536] New master detected at [email protected]:42594 I0530 22:35:37.381814 15626 slave.cpp:612] Authenticating with master [email protected]:42594 I0530 22:35:37.381860 15630 status_update_manager.cpp:167] New master detected at [email protected]:42594 I0530 22:35:37.381883 15626 slave.cpp:585] Detecting new master I0530 22:35:37.381898 15624 authenticatee.hpp:128] Creating new client SASL connection I0530 22:35:37.382061 15626 master.cpp:2986] Authenticating slave(84)@67.195.138.9:42594 I0530 22:35:37.382148 15625 authenticator.hpp:156] Creating new server SASL connection I0530 22:35:37.382284 15629 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I0530 22:35:37.382307 15629 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I0530 22:35:37.382346 15629 authenticator.hpp:262] Received SASL authentication start I0530 22:35:37.382414 15528 sched.cpp:126] Version: 0.20.0 I0530 22:35:37.382421 15629 authenticator.hpp:384] Authentication requires more steps I0530 22:35:37.382484 15629 authenticatee.hpp:265] Received SASL authentication step I0530 22:35:37.382549 15629 authenticator.hpp:290] Received SASL authentication step I0530 22:35:37.382581 15629 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0530 22:35:37.382588 15629 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I0530 22:35:37.382596 15626 sched.cpp:222] New master detected at [email protected]:42594 I0530 22:35:37.382598 15629 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0530 22:35:37.382623 15626 sched.cpp:273] Authenticating with master [email protected]:42594 I0530 22:35:37.382634 15629 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0530 22:35:37.382642 15629 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0530 22:35:37.382647 15629 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0530 22:35:37.382658 15629 authenticator.hpp:376] Authentication success I0530 22:35:37.382709 15624 authenticatee.hpp:305] Authentication success I0530 22:35:37.382717 15625 master.cpp:3026] Successfully authenticated principal 'test-principal' at slave(84)@67.195.138.9:42594 I0530 22:35:37.382800 15628 authenticatee.hpp:128] Creating new client SASL connection I0530 22:35:37.382958 15626 slave.cpp:669] Successfully authenticated with master [email protected]:42594 I0530 22:35:37.382973 15625 master.cpp:2986] Authenticating scheduler(91)@67.195.138.9:42594 I0530 22:35:37.383011 15626 slave.cpp:902] Will retry registration in 13.173488ms if necessary I0530 22:35:37.383064 15630 authenticator.hpp:156] Creating new server SASL connection I0530 22:35:37.383139 15625 master.cpp:2302] Registering slave at slave(84)@67.195.138.9:42594 (vesta.apache.org) with id 20140530-223537-160088899-42594-15528-0 I0530 22:35:37.383152 15629 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I0530 22:35:37.383174 15629 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I0530 22:35:37.383224 15629 authenticator.hpp:262] Received SASL authentication start I0530 22:35:37.383270 15629 authenticator.hpp:384] Authentication requires more steps I0530 22:35:37.383317 15629 authenticatee.hpp:265] Received SASL authentication step I0530 22:35:37.383348 15630 registrar.cpp:422] Attempting to update the 'registry' I0530 22:35:37.383369 15629 authenticator.hpp:290] Received SASL authentication step I0530 22:35:37.383391 15629 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0530 22:35:37.383397 15629 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I0530 22:35:37.383404 15629 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0530 22:35:37.383412 15629 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0530 22:35:37.383419 15629 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0530 22:35:37.383424 15629 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0530 22:35:37.383431 15629 authenticator.hpp:376] Authentication success I0530 22:35:37.383491 15626 authenticatee.hpp:305] Authentication success I0530 22:35:37.383509 15629 master.cpp:3026] Successfully authenticated principal 'test-principal' at scheduler(91)@67.195.138.9:42594 I0530 22:35:37.383640 15626 sched.cpp:347] Successfully authenticated with master [email protected]:42594 I0530 22:35:37.383652 15626 sched.cpp:466] Sending registration request to [email protected]:42594 I0530 22:35:37.383723 15628 master.cpp:1041] Received registration request from scheduler(91)@67.195.138.9:42594 I0530 22:35:37.383769 15628 master.cpp:1059] Registering framework 20140530-223537-160088899-42594-15528-0000 at scheduler(91)@67.195.138.9:42594 I0530 22:35:37.383858 15626 sched.cpp:397] Framework registered with 20140530-223537-160088899-42594-15528-0000 I0530 22:35:37.383883 15626 sched.cpp:411] Scheduler::registered took 8400ns I0530 22:35:37.383899 15625 hierarchical_allocator_process.hpp:331] Added framework 20140530-223537-160088899-42594-15528-0000 I0530 22:35:37.383915 15625 hierarchical_allocator_process.hpp:725] No resources available to allocate! I0530 22:35:37.383920 15625 hierarchical_allocator_process.hpp:687] Performed allocation for 0 slaves in 5916ns I0530 22:35:37.384403 15627 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 6.841763ms I0530 22:35:37.384418 15627 replica.cpp:676] Persisted action at 2 I0530 22:35:37.384695 15630 replica.cpp:655] Replica received learned notice for position 2 I0530 22:35:37.392371 15630 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 7.662762ms I0530 22:35:37.392398 15630 leveldb.cpp:401] Deleting ~1 keys from leveldb took 11657ns I0530 22:35:37.392408 15630 replica.cpp:676] Persisted action at 2 I0530 22:35:37.392431 15630 replica.cpp:661] Replica learned TRUNCATE action at position 2 I0530 22:35:37.397300 15628 slave.cpp:902] Will retry registration in 24.357255ms if necessary I0530 22:35:37.397349 15624 master.cpp:2290] Ignoring register slave message from slave(84)@67.195.138.9:42594 (vesta.apache.org) as admission is already in progress I0530 22:35:38.272331 15625 hierarchical_allocator_process.hpp:725] No resources available to allocate! I0530 22:35:42.272203 15629 master.cpp:108] No whitelist given. Advertising offers for all slaves E0530 22:35:42.385763 15627 registrar.cpp:500] Registrar aborting: Failed to update 'registry': Failed to perform store within 5secs I0530 22:35:47.258424 15625 hierarchical_allocator_process.hpp:687] Performed allocation for 0 slaves in 8.986081229secs F0530 22:35:47.258705 15624 master.cpp:2324] Failed to admit slave 20140530-223537-160088899-42594-15528-0 at slave(84)@67.195.138.9:42594 (vesta.apache.org): Failed to update 'registry': Failed to perform store within 5secs *** Check failure stack trace: *** I0530 22:35:47.283717 15625 slave.cpp:902] Will retry registration in 73.730093ms if necessary @ 0x2aafdb3e20fd google::LogMessage::Fail() @ 0x2aafdb3e418f google::LogMessage::SendToLog() @ 0x2aafdb3e1cec google::LogMessage::Flush() @ 0x2aafdb3e49fd google::LogMessageFatal::~LogMessageFatal() @ 0x2aafdaed06db mesos::internal::master::Master::_registerSlave() @ 0x4dfe05 std::tr1::_Function_handler<>::_M_invoke() @ 0x2aafdb31339c process::ProcessManager::resume() @ 0x2aafdb313fac process::schedule() @ 0x2aafdce27e9a start_thread @ 0x2aafdd1323fd (unknown) make[4]: *** [check-local] Aborted make[4]: Leaving directory `/home/hudson/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.20.0/_build/src' make[3]: *** [check-am] Error 2 make[3]: Leaving directory `/home/hudson/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.20.0/_build/src' make[2]: *** [check] Error 2 make[2]: Leaving directory `/home/hudson/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.20.0/_build/src' make[1]: *** [check-recursive] Error 1 make[1]: Leaving directory `/home/hudson/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.20.0/_build' make: *** [distcheck] Error 1 Process leaked file descriptors. See http://wiki.jenkins-ci.org/display/JENKINS/Spawning+processes+from+build for more information Build step 'Execute shell' marked build as failure
