See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2301/changes>
Changes: [yujie.jay] Fixed a bug in slave when launching container. ------------------------------------------ [...truncated 25049 lines...] I0807 17:30:36.786521 690 authenticator.hpp:156] Creating new server SASL connection I0807 17:30:36.786612 690 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I0807 17:30:36.786628 690 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I0807 17:30:36.786650 690 authenticator.hpp:262] Received SASL authentication start I0807 17:30:36.786680 690 authenticator.hpp:384] Authentication requires more steps I0807 17:30:36.786705 690 authenticatee.hpp:265] Received SASL authentication step I0807 17:30:36.786734 690 authenticator.hpp:290] Received SASL authentication step I0807 17:30:36.786748 690 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0807 17:30:36.786754 690 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I0807 17:30:36.786763 690 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0807 17:30:36.786772 690 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0807 17:30:36.786777 690 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0807 17:30:36.786782 690 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0807 17:30:36.786792 690 authenticator.hpp:376] Authentication success I0807 17:30:36.786814 690 authenticatee.hpp:305] Authentication success I0807 17:30:36.786835 690 master.cpp:3645] Successfully authenticated principal 'test-principal' at slave(78)@140.211.11.27:53862 I0807 17:30:36.786896 690 slave.cpp:720] Successfully authenticated with master master@140.211.11.27:53862 I0807 17:30:36.786928 690 slave.cpp:971] Will retry registration in 12.118386ms if necessary I0807 17:30:36.786988 690 master.cpp:2827] Registering slave at slave(78)@140.211.11.27:53862 (hemera.apache.org) with id 20140807-173036-453759884-53862-403-0 I0807 17:30:36.787086 690 registrar.cpp:422] Attempting to update the 'registry' I0807 17:30:36.788794 690 log.cpp:680] Attempting to append 328 bytes to the log I0807 17:30:36.788843 690 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3 I0807 17:30:36.789048 403 sched.cpp:139] Version: 0.20.0 I0807 17:30:36.789103 690 replica.cpp:508] Replica received write request for position 3 I0807 17:30:36.789425 694 sched.cpp:235] New master detected at master@140.211.11.27:53862 I0807 17:30:36.789446 694 sched.cpp:285] Authenticating with master master@140.211.11.27:53862 I0807 17:30:36.789535 694 authenticatee.hpp:128] Creating new client SASL connection I0807 17:30:36.789729 714 master.cpp:3605] Authenticating scheduler-64da95a6-74b8-438f-b973-b9de8c8351fe@140.211.11.27:53862 I0807 17:30:36.789819 714 authenticator.hpp:156] Creating new server SASL connection I0807 17:30:36.789908 714 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I0807 17:30:36.789923 714 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I0807 17:30:36.789948 714 authenticator.hpp:262] Received SASL authentication start I0807 17:30:36.789985 714 authenticator.hpp:384] Authentication requires more steps I0807 17:30:36.790009 714 authenticatee.hpp:265] Received SASL authentication step I0807 17:30:36.790040 714 authenticator.hpp:290] Received SASL authentication step I0807 17:30:36.790053 714 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0807 17:30:36.790060 714 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I0807 17:30:36.790069 714 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0807 17:30:36.790078 714 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0807 17:30:36.790084 714 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0807 17:30:36.790089 714 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0807 17:30:36.790101 714 authenticator.hpp:376] Authentication success I0807 17:30:36.790124 714 authenticatee.hpp:305] Authentication success I0807 17:30:36.790144 714 master.cpp:3645] Successfully authenticated principal 'test-principal' at scheduler-64da95a6-74b8-438f-b973-b9de8c8351fe@140.211.11.27:53862 I0807 17:30:36.790210 714 sched.cpp:359] Successfully authenticated with master master@140.211.11.27:53862 I0807 17:30:36.790220 714 sched.cpp:478] Sending registration request to master@140.211.11.27:53862 I0807 17:30:36.790261 714 master.cpp:1305] Received registration request from scheduler-64da95a6-74b8-438f-b973-b9de8c8351fe@140.211.11.27:53862 I0807 17:30:36.790278 714 master.cpp:1265] Authorizing framework principal 'test-principal' to receive offers for role '*' I0807 17:30:36.790380 714 master.cpp:1364] Registering framework 20140807-173036-453759884-53862-403-0000 at scheduler-64da95a6-74b8-438f-b973-b9de8c8351fe@140.211.11.27:53862 I0807 17:30:36.790473 714 sched.cpp:409] Framework registered with 20140807-173036-453759884-53862-403-0000 I0807 17:30:36.790493 714 sched.cpp:423] Scheduler::registered took 9519ns I0807 17:30:36.790526 714 hierarchical_allocator_process.hpp:326] Added framework 20140807-173036-453759884-53862-403-0000 I0807 17:30:36.790534 714 hierarchical_allocator_process.hpp:688] No resources available to allocate! I0807 17:30:36.790539 714 hierarchical_allocator_process.hpp:650] Performed allocation for 0 slaves in 5946ns I0807 17:30:36.805169 694 slave.cpp:971] Will retry registration in 12.417387ms if necessary I0807 17:30:36.805233 694 master.cpp:2815] Ignoring register slave message from slave(78)@140.211.11.27:53862 (hemera.apache.org) as admission is already in progress I0807 17:30:36.805675 690 leveldb.cpp:343] Persisting action (347 bytes) to leveldb took 16.495309ms I0807 17:30:36.805701 690 replica.cpp:676] Persisted action at 3 I0807 17:30:36.805896 690 replica.cpp:655] Replica received learned notice for position 3 I0807 17:30:36.821661 690 leveldb.cpp:343] Persisting action (349 bytes) to leveldb took 15.749773ms I0807 17:30:36.821760 690 replica.cpp:676] Persisted action at 3 I0807 17:30:36.821801 671 slave.cpp:971] Will retry registration in 17.196934ms if necessary I0807 17:30:36.821817 690 replica.cpp:661] Replica learned APPEND action at position 3 I0807 17:30:36.821873 671 master.cpp:2815] Ignoring register slave message from slave(78)@140.211.11.27:53862 (hemera.apache.org) as admission is already in progress I0807 17:30:36.822265 709 registrar.cpp:479] Successfully updated 'registry' I0807 17:30:36.822342 694 log.cpp:699] Attempting to truncate the log to 3 I0807 17:30:36.822438 709 master.cpp:2867] Registered slave 20140807-173036-453759884-53862-403-0 at slave(78)@140.211.11.27:53862 (hemera.apache.org) I0807 17:30:36.822453 694 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4 I0807 17:30:36.822455 709 master.cpp:4078] Adding slave 20140807-173036-453759884-53862-403-0 at slave(78)@140.211.11.27:53862 (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0807 17:30:36.822751 694 slave.cpp:754] Registered with master master@140.211.11.27:53862; given slave ID 20140807-173036-453759884-53862-403-0 I0807 17:30:36.822796 694 slave.cpp:2324] Received ping from slave-observer(69)@140.211.11.27:53862 I0807 17:30:36.822898 709 hierarchical_allocator_process.hpp:439] Added slave 20140807-173036-453759884-53862-403-0 (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available) I0807 17:30:36.822968 709 hierarchical_allocator_process.hpp:714] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140807-173036-453759884-53862-403-0 to framework 20140807-173036-453759884-53862-403-0000 I0807 17:30:36.823096 709 hierarchical_allocator_process.hpp:670] Performed allocation for slave 20140807-173036-453759884-53862-403-0 in 157195ns I0807 17:30:36.823163 709 master.hpp:847] Adding offer 20140807-173036-453759884-53862-403-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140807-173036-453759884-53862-403-0 (hemera.apache.org) I0807 17:30:36.823220 709 master.cpp:3552] Sending 1 offers to framework 20140807-173036-453759884-53862-403-0000 I0807 17:30:36.823344 709 sched.cpp:546] Scheduler::resourceOffers took 25958ns I0807 17:30:36.823503 692 replica.cpp:508] Replica received write request for position 4 I0807 17:30:36.827436 709 master.hpp:857] Removing offer 20140807-173036-453759884-53862-403-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140807-173036-453759884-53862-403-0 (hemera.apache.org) I0807 17:30:36.827512 709 master.cpp:2189] Processing reply for offers: [ 20140807-173036-453759884-53862-403-0 ] on slave 20140807-173036-453759884-53862-403-0 at slave(78)@140.211.11.27:53862 (hemera.apache.org) for framework 20140807-173036-453759884-53862-403-0000 I0807 17:30:36.827560 709 master.cpp:2275] Authorizing framework principal 'test-principal' to launch task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a as user 'jenkins' I0807 17:30:36.827962 709 master.hpp:819] Adding task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140807-173036-453759884-53862-403-0 (hemera.apache.org) I0807 17:30:36.828006 709 master.cpp:2341] Launching task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140807-173036-453759884-53862-403-0 at slave(78)@140.211.11.27:53862 (hemera.apache.org) I0807 17:30:36.828172 709 slave.cpp:1002] Got assigned task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a for framework 20140807-173036-453759884-53862-403-0000 I0807 17:30:36.828387 709 slave.cpp:1112] Launching task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a for framework 20140807-173036-453759884-53862-403-0000 I0807 17:30:36.831197 709 exec.cpp:131] Version: 0.20.0 I0807 17:30:36.831306 709 slave.cpp:1222] Queuing task '81c584a6-2ff3-4e65-b99f-8a7a37c3421a' for executor default of framework '20140807-173036-453759884-53862-403-0000 I0807 17:30:36.831377 709 slave.cpp:2515] Monitoring executor 'default' of framework '20140807-173036-453759884-53862-403-0000' in container 'aa9ed10a-024d-456f-bac4-18c385b9aa01' I0807 17:30:36.831487 709 exec.cpp:181] Executor started at: executor(28)@140.211.11.27:53862 with pid 403 I0807 17:30:36.831568 709 slave.cpp:543] Successfully attached file '/tmp/SlaveTest_IgnoreNonLeaderStatusUpdateAcknowledgement_I9q9iQ/slaves/20140807-173036-453759884-53862-403-0/frameworks/20140807-173036-453759884-53862-403-0000/executors/default/runs/aa9ed10a-024d-456f-bac4-18c385b9aa01' I0807 17:30:36.831601 709 slave.cpp:1733] Got registration for executor 'default' of framework 20140807-173036-453759884-53862-403-0000 I0807 17:30:36.831707 709 slave.cpp:1852] Flushing queued task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a for executor 'default' of framework 20140807-173036-453759884-53862-403-0000 I0807 17:30:36.831787 709 exec.cpp:205] Executor registered on slave 20140807-173036-453759884-53862-403-0 I0807 17:30:36.833026 709 exec.cpp:217] Executor::registered took 17155ns I0807 17:30:36.833096 709 exec.cpp:292] Executor asked to run task '81c584a6-2ff3-4e65-b99f-8a7a37c3421a' I0807 17:30:36.833132 709 exec.cpp:301] Executor::launchTask took 24849ns I0807 17:30:36.834453 709 exec.cpp:524] Executor sending status update TASK_RUNNING (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 I0807 17:30:36.834625 709 slave.cpp:2087] Handling status update TASK_RUNNING (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 from executor(28)@140.211.11.27:53862 I0807 17:30:36.834779 709 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 I0807 17:30:36.834857 709 status_update_manager.cpp:499] Creating StatusUpdate stream for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 I0807 17:30:36.835022 709 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 to master@140.211.11.27:53862 I0807 17:30:36.835211 709 master.cpp:3196] Forwarding status update TASK_RUNNING (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 I0807 17:30:36.835320 709 master.cpp:3162] Status update TASK_RUNNING (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 from slave 20140807-173036-453759884-53862-403-0 at slave(78)@140.211.11.27:53862 (hemera.apache.org) I0807 17:30:36.835427 709 slave.cpp:2245] Status update manager successfully handled status update TASK_RUNNING (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 I0807 17:30:36.835505 709 slave.cpp:2251] Sending acknowledgement for status update TASK_RUNNING (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 to executor(28)@140.211.11.27:53862 I0807 17:30:36.835656 709 sched.cpp:637] Scheduler::statusUpdate took 15224ns I0807 17:30:36.835770 709 exec.cpp:338] Executor received status update acknowledgement dcc58d11-5209-4672-b0f2-cacf58fe2fe7 for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 I0807 17:30:36.835892 709 master.cpp:2677] Forwarding status update acknowledgement dcc58d11-5209-4672-b0f2-cacf58fe2fe7 for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 to slave 20140807-173036-453759884-53862-403-0 at slave(78)@140.211.11.27:53862 (hemera.apache.org) I0807 17:30:36.837323 692 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 13.801156ms I0807 17:30:36.837348 692 replica.cpp:676] Persisted action at 4 I0807 17:30:36.837560 692 replica.cpp:655] Replica received learned notice for position 4 I0807 17:30:36.857661 692 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 20.085146ms I0807 17:30:36.857754 692 leveldb.cpp:401] Deleting ~2 keys from leveldb took 24526ns I0807 17:30:36.857765 692 replica.cpp:676] Persisted action at 4 I0807 17:30:36.857774 692 replica.cpp:661] Replica learned TRUNCATE action at position 4 W0807 17:30:36.877737 692 slave.cpp:1640] Ignoring status update acknowledgement message from master@127.0.0.1:1 because it is not the expected master: master@140.211.11.27:53862 I0807 17:30:36.889756 677 hierarchical_allocator_process.hpp:650] Performed allocation for 1 slaves in 30199ns I0807 17:30:36.889976 677 master.cpp:120] No whitelist given. Advertising offers for all slaves W0807 17:30:36.890019 677 status_update_manager.cpp:477] Resending status update TASK_RUNNING (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 I0807 17:30:36.890033 677 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 to master@140.211.11.27:53862 I0807 17:30:36.890148 677 master.cpp:3196] Forwarding status update TASK_RUNNING (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 I0807 17:30:36.890182 677 master.cpp:3162] Status update TASK_RUNNING (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 from slave 20140807-173036-453759884-53862-403-0 at slave(78)@140.211.11.27:53862 (hemera.apache.org) I0807 17:30:36.890244 677 sched.cpp:637] Scheduler::statusUpdate took 11012ns I0807 17:30:36.890286 677 master.cpp:2677] Forwarding status update acknowledgement dcc58d11-5209-4672-b0f2-cacf58fe2fe7 for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 to slave 20140807-173036-453759884-53862-403-0 at slave(78)@140.211.11.27:53862 (hemera.apache.org) I0807 17:30:36.890352 677 status_update_manager.cpp:398] Received status update acknowledgement (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 I0807 17:30:36.890404 677 slave.cpp:1673] Status update manager successfully handled status update acknowledgement (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 I0807 17:30:36.921783 403 master.cpp:634] Master terminating I0807 17:30:36.921882 403 master.hpp:837] Removing task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140807-173036-453759884-53862-403-0 (hemera.apache.org) W0807 17:30:36.921967 403 master.cpp:4371] Removing task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 and slave 20140807-173036-453759884-53862-403-0 in non-terminal state TASK_RUNNING I0807 17:30:36.923032 403 slave.cpp:466] Slave terminating I0807 17:30:36.923048 403 slave.cpp:1406] Asked to shut down framework 20140807-173036-453759884-53862-403-0000 by @0.0.0.0:0 I0807 17:30:36.923061 403 slave.cpp:1431] Shutting down framework 20140807-173036-453759884-53862-403-0000 I0807 17:30:36.923074 403 slave.cpp:2855] Shutting down executor 'default' of framework 20140807-173036-453759884-53862-403-0000 [ OK ] SlaveTest.IgnoreNonLeaderStatusUpdateAcknowledgement (400 ms) [----------] 9 tests from SlaveTest (8449 ms total) [----------] 6 tests from RateLimitingTest [ RUN ] RateLimitingTest.DifferentPrincipalFrameworks Using temporary directory '/tmp/RateLimitingTest_DifferentPrincipalFrameworks_B7fkoR' I0807 17:30:36.985301 403 leveldb.cpp:176] Opened db in 60.744149ms I0807 17:30:37.017660 403 leveldb.cpp:183] Compacted db in 32.311501ms I0807 17:30:37.017698 403 leveldb.cpp:198] Created db iterator in 3962ns I0807 17:30:37.017705 403 leveldb.cpp:204] Seeked to beginning of db in 780ns I0807 17:30:37.017711 403 leveldb.cpp:273] Iterated through 0 keys in the db in 262ns I0807 17:30:37.017727 403 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0807 17:30:37.022848 690 master.cpp:286] Master 20140807-173037-453759884-53862-403 (hemera.apache.org) started on 140.211.11.27:53862 I0807 17:30:37.022877 690 master.cpp:325] Master allowing unauthenticated frameworks to register I0807 17:30:37.022883 690 master.cpp:328] Master only allowing authenticated slaves to register I0807 17:30:37.022891 690 credentials.hpp:36] Loading credentials for authentication from '/tmp/RateLimitingTest_DifferentPrincipalFrameworks_B7fkoR/credentials' I0807 17:30:37.023021 690 master.cpp:357] Authorization enabled I0807 17:30:37.023068 690 master.cpp:404] Framework rate limiting enabled I0807 17:30:37.023520 690 recover.cpp:425] Starting replica recovery I0807 17:30:37.023797 690 hierarchical_allocator_process.hpp:296] Initializing hierarchical allocator process with master : master@140.211.11.27:53862 I0807 17:30:37.023833 690 master.cpp:120] No whitelist given. Advertising offers for all slaves I0807 17:30:37.023905 690 master.cpp:1186] The newly elected leader is master@140.211.11.27:53862 with id 20140807-173037-453759884-53862-403 I0807 17:30:37.023916 690 master.cpp:1199] Elected as the leading master! I0807 17:30:37.023921 690 master.cpp:1017] Recovering from registrar I0807 17:30:37.023972 690 recover.cpp:451] Replica is in EMPTY status I0807 17:30:37.024025 690 registrar.cpp:313] Recovering registrar I0807 17:30:37.024520 690 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request I0807 17:30:37.024587 690 recover.cpp:188] Received a recover response from a replica in EMPTY status I0807 17:30:37.024698 690 recover.cpp:542] Updating replica status to STARTING I0807 17:30:37.041659 690 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 16.898675ms I0807 17:30:37.041756 690 replica.cpp:320] Persisted replica status to STARTING I0807 17:30:37.041893 690 recover.cpp:451] Replica is in STARTING status I0807 17:30:37.042265 690 replica.cpp:638] Replica in STARTING status received a broadcasted recover request I0807 17:30:37.042394 690 recover.cpp:188] Received a recover response from a replica in STARTING status I0807 17:30:37.042675 711 recover.cpp:542] Updating replica status to VOTING I0807 17:30:37.057548 677 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 14.812382ms I0807 17:30:37.057584 677 replica.cpp:320] Persisted replica status to VOTING I0807 17:30:37.057652 677 recover.cpp:556] Successfully joined the Paxos group I0807 17:30:37.057731 677 recover.cpp:440] Recover process terminated I0807 17:30:37.057884 684 log.cpp:656] Attempting to start the writer I0807 17:30:37.058269 684 replica.cpp:474] Replica received implicit promise request with proposal 1 I0807 17:30:37.073742 684 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 15.458383ms I0807 17:30:37.073770 684 replica.cpp:342] Persisted promised to 1 I0807 17:30:37.074256 701 coordinator.cpp:230] Coordinator attemping to fill missing position I0807 17:30:37.075018 691 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2 I0807 17:30:37.089825 691 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 14.783082ms I0807 17:30:37.089853 691 replica.cpp:676] Persisted action at 0 I0807 17:30:37.090317 694 replica.cpp:508] Replica received write request for position 0 I0807 17:30:37.090348 694 leveldb.cpp:438] Reading position from leveldb took 13689ns I0807 17:30:37.105913 694 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 15.549578ms I0807 17:30:37.105942 694 replica.cpp:676] Persisted action at 0 I0807 17:30:37.106113 694 replica.cpp:655] Replica received learned notice for position 0 I0807 17:30:37.121995 694 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 15.864808ms I0807 17:30:37.122022 694 replica.cpp:676] Persisted action at 0 I0807 17:30:37.122031 694 replica.cpp:661] Replica learned NOP action at position 0 I0807 17:30:37.122241 694 log.cpp:672] Writer started with ending position 0 I0807 17:30:37.122505 694 leveldb.cpp:438] Reading position from leveldb took 11851ns I0807 17:30:37.124013 694 registrar.cpp:346] Successfully fetched the registry (0B) I0807 17:30:37.124034 694 registrar.cpp:422] Attempting to update the 'registry' I0807 17:30:37.125591 694 log.cpp:680] Attempting to append 136 bytes to the log I0807 17:30:37.125651 694 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1 I0807 17:30:37.125869 694 replica.cpp:508] Replica received write request for position 1 I0807 17:30:37.142525 694 leveldb.cpp:343] Persisting action (155 bytes) to leveldb took 16.640654ms I0807 17:30:37.142551 694 replica.cpp:676] Persisted action at 1 I0807 17:30:37.153822 714 replica.cpp:655] Replica received learned notice for position 1 I0807 17:30:37.173665 714 leveldb.cpp:343] Persisting action (157 bytes) to leveldb took 19.756436ms I0807 17:30:37.173753 714 replica.cpp:676] Persisted action at 1 I0807 17:30:37.173810 714 replica.cpp:661] Replica learned APPEND action at position 1 I0807 17:30:37.174188 714 registrar.cpp:479] Successfully updated 'registry' I0807 17:30:37.174279 714 registrar.cpp:372] Successfully recovered registrar I0807 17:30:37.174371 714 log.cpp:699] Attempting to truncate the log to 1 I0807 17:30:37.174497 714 master.cpp:1044] Recovered 0 slaves from the Registry (98B) ; allowing 10mins for slaves to re-register I0807 17:30:37.174588 714 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2 I0807 17:30:37.175026 667 replica.cpp:508] Replica received write request for position 2 I0807 17:30:37.190742 667 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 15.687275ms I0807 17:30:37.190770 667 replica.cpp:676] Persisted action at 2 I0807 17:30:37.190974 667 replica.cpp:655] Replica received learned notice for position 2 I0807 17:30:37.210861 667 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 19.869691ms I0807 17:30:37.210911 667 leveldb.cpp:401] Deleting ~1 keys from leveldb took 18729ns I0807 17:30:37.210922 667 replica.cpp:676] Persisted action at 2 I0807 17:30:37.210932 667 replica.cpp:661] Replica learned TRUNCATE action at position 2 I0807 17:30:37.228948 403 sched.cpp:139] Version: 0.20.0 I0807 17:30:37.229142 694 sched.cpp:235] New master detected at master@140.211.11.27:53862 I0807 17:30:37.229174 694 sched.cpp:243] No credentials provided. Attempting to register without authentication I0807 17:30:37.229182 694 sched.cpp:478] Sending registration request to master@140.211.11.27:53862 I0807 17:30:37.241777 714 master.cpp:1305] Received registration request from scheduler-4f26e506-1c7a-4985-87f5-e7a0b260a2ff@140.211.11.27:53862 I0807 17:30:37.241812 714 master.cpp:1265] Authorizing framework principal 'framework1' to receive offers for role '*' I0807 17:30:37.241943 714 master.cpp:1364] Registering framework 20140807-173037-453759884-53862-403-0000 at scheduler-4f26e506-1c7a-4985-87f5-e7a0b260a2ff@140.211.11.27:53862 I0807 17:30:37.242048 714 sched.cpp:409] Framework registered with 20140807-173037-453759884-53862-403-0000 I0807 17:30:37.242069 714 sched.cpp:423] Scheduler::registered took 10298ns I0807 17:30:37.242105 714 hierarchical_allocator_process.hpp:326] Added framework 20140807-173037-453759884-53862-403-0000 I0807 17:30:37.242112 714 hierarchical_allocator_process.hpp:688] No resources available to allocate! I0807 17:30:37.242117 714 hierarchical_allocator_process.hpp:650] Performed allocation for 0 slaves in 6166ns I0807 17:30:37.264605 403 sched.cpp:139] Version: 0.20.0 I0807 17:30:37.264735 699 sched.cpp:235] New master detected at master@140.211.11.27:53862 I0807 17:30:37.264753 699 sched.cpp:243] No credentials provided. Attempting to register without authentication I0807 17:30:37.264760 699 sched.cpp:478] Sending registration request to master@140.211.11.27:53862 I0807 17:30:37.264834 699 master.cpp:1305] Received registration request from scheduler-a7479512-9f16-4147-9947-f3f5236a55f5@140.211.11.27:53862 I0807 17:30:37.264853 699 master.cpp:1265] Authorizing framework principal 'framework2' to receive offers for role '*' I0807 17:30:37.264996 699 master.cpp:1364] Registering framework 20140807-173037-453759884-53862-403-0001 at scheduler-a7479512-9f16-4147-9947-f3f5236a55f5@140.211.11.27:53862 I0807 17:30:37.265086 699 sched.cpp:409] Framework registered with 20140807-173037-453759884-53862-403-0001 I0807 17:30:37.265105 699 sched.cpp:423] Scheduler::registered took 8957ns I0807 17:30:37.265137 699 hierarchical_allocator_process.hpp:326] Added framework 20140807-173037-453759884-53862-403-0001 I0807 17:30:37.265146 699 hierarchical_allocator_process.hpp:688] No resources available to allocate! I0807 17:30:37.265151 699 hierarchical_allocator_process.hpp:650] Performed allocation for 0 slaves in 5654ns I0807 17:30:37.285781 699 master.cpp:1305] Received registration request from scheduler-4f26e506-1c7a-4985-87f5-e7a0b260a2ff@140.211.11.27:53862 I0807 17:30:37.285807 699 master.cpp:1265] Authorizing framework principal 'framework1' to receive offers for role '*' lt-mesos-tests: ../../3rdparty/libprocess/3rdparty/stout/include/stout/option.hpp:104: const T& Option<T>::get() const [with T = process::Owned<mesos::internal::master::Master::BoundedRateLimiter>]: Assertion `state == SOME' failed. make[3]: *** [check-local] Aborted (core dumped) make[3]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src' make[2]: *** [check-am] Error 2 make[2]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src' make[1]: *** [check] Error 2 make[1]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src' make: *** [check-recursive] Error 1 Build step 'Execute shell' marked build as failure
