See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/2228/changes>
Changes: [benjamin.hindman] Fixed bug with snapshot positions when writing log diffs. ------------------------------------------ [...truncated 69376 lines...] I1029 09:40:19.075613 3139 hierarchical_allocator_process.hpp:299] Initializing hierarchical allocator process with master : [email protected]:52646 I1029 09:40:19.077009 3135 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request I1029 09:40:19.077117 3143 master.cpp:1242] The newly elected leader is [email protected]:52646 with id 20141029-094017-3142697795-52646-3116 I1029 09:40:19.077160 3143 master.cpp:1255] Elected as the leading master! I1029 09:40:19.077182 3143 master.cpp:1073] Recovering from registrar I1029 09:40:19.077455 3141 registrar.cpp:313] Recovering registrar I1029 09:40:19.077568 3139 recover.cpp:188] Received a recover response from a replica in EMPTY status I1029 09:40:19.078191 3131 recover.cpp:554] Updating replica status to STARTING I1029 09:40:19.079345 3138 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 985524ns I1029 09:40:19.079370 3138 replica.cpp:320] Persisted replica status to STARTING I1029 09:40:19.079610 3143 recover.cpp:463] Replica is in STARTING status I1029 09:40:19.080679 3132 replica.cpp:638] Replica in STARTING status received a broadcasted recover request I1029 09:40:19.081054 3137 recover.cpp:188] Received a recover response from a replica in STARTING status I1029 09:40:19.081483 3133 recover.cpp:554] Updating replica status to VOTING I1029 09:40:19.082223 3135 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 585974ns I1029 09:40:19.082250 3135 replica.cpp:320] Persisted replica status to VOTING I1029 09:40:19.082372 3131 recover.cpp:568] Successfully joined the Paxos group I1029 09:40:19.082594 3131 recover.cpp:452] Recover process terminated I1029 09:40:19.083050 3135 log.cpp:656] Attempting to start the writer I1029 09:40:19.084597 3142 replica.cpp:474] Replica received implicit promise request with proposal 1 I1029 09:40:19.085218 3142 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 588099ns I1029 09:40:19.085243 3142 replica.cpp:342] Persisted promised to 1 I1029 09:40:19.085911 3138 coordinator.cpp:230] Coordinator attemping to fill missing position I1029 09:40:19.087317 3141 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2 I1029 09:40:19.087848 3141 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 494271ns I1029 09:40:19.087873 3141 replica.cpp:676] Persisted action at 0 I1029 09:40:19.089040 3131 replica.cpp:508] Replica received write request for position 0 I1029 09:40:19.089090 3131 leveldb.cpp:438] Reading position from leveldb took 24077ns I1029 09:40:19.089602 3131 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 478794ns I1029 09:40:19.089628 3131 replica.cpp:676] Persisted action at 0 I1029 09:40:19.090229 3144 replica.cpp:655] Replica received learned notice for position 0 I1029 09:40:19.090790 3144 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 530255ns I1029 09:40:19.090814 3144 replica.cpp:676] Persisted action at 0 I1029 09:40:19.090836 3144 replica.cpp:661] Replica learned NOP action at position 0 I1029 09:40:19.091418 3141 log.cpp:672] Writer started with ending position 0 I1029 09:40:19.092674 3139 leveldb.cpp:438] Reading position from leveldb took 23812ns I1029 09:40:19.095818 3136 registrar.cpp:346] Successfully fetched the registry (0B) in 18.313984ms I1029 09:40:19.095935 3136 registrar.cpp:445] Applied 1 operations in 19557ns; attempting to update the 'registry' I1029 09:40:19.098989 3139 log.cpp:680] Attempting to append 138 bytes to the log I1029 09:40:19.099138 3141 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1 I1029 09:40:19.099973 3140 replica.cpp:508] Replica received write request for position 1 I1029 09:40:19.100742 3140 leveldb.cpp:343] Persisting action (157 bytes) to leveldb took 730714ns I1029 09:40:19.100769 3140 replica.cpp:676] Persisted action at 1 I1029 09:40:19.101434 3142 replica.cpp:655] Replica received learned notice for position 1 I1029 09:40:19.101959 3142 leveldb.cpp:343] Persisting action (159 bytes) to leveldb took 494168ns I1029 09:40:19.101985 3142 replica.cpp:676] Persisted action at 1 I1029 09:40:19.102006 3142 replica.cpp:661] Replica learned APPEND action at position 1 I1029 09:40:19.103004 3131 registrar.cpp:490] Successfully updated the 'registry' in 7.01696ms I1029 09:40:19.103142 3131 registrar.cpp:376] Successfully recovered registrar I1029 09:40:19.103440 3144 log.cpp:699] Attempting to truncate the log to 1 I1029 09:40:19.103482 3132 master.cpp:1100] Recovered 0 slaves from the Registry (100B) ; allowing 10mins for slaves to re-register I1029 09:40:19.103621 3134 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2 I1029 09:40:19.104642 3133 replica.cpp:508] Replica received write request for position 2 I1029 09:40:19.105180 3133 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 504427ns I1029 09:40:19.105206 3133 replica.cpp:676] Persisted action at 2 I1029 09:40:19.105888 3136 replica.cpp:655] Replica received learned notice for position 2 I1029 09:40:19.106431 3136 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 516554ns I1029 09:40:19.106487 3136 leveldb.cpp:401] Deleting ~1 keys from leveldb took 29777ns I1029 09:40:19.106506 3136 replica.cpp:676] Persisted action at 2 I1029 09:40:19.106528 3136 replica.cpp:661] Replica learned TRUNCATE action at position 2 I1029 09:40:19.118141 3142 slave.cpp:169] Slave started on 221)@67.195.81.187:52646 I1029 09:40:19.118172 3142 credentials.hpp:84] Loading credential for authentication from '/tmp/SlaveTest_IgnoreNonLeaderStatusUpdateAcknowledgement_E7ceOa/credential' I1029 09:40:19.118276 3142 slave.cpp:276] Slave using credential for: test-principal I1029 09:40:19.118526 3142 slave.cpp:289] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I1029 09:40:19.118598 3142 slave.cpp:318] Slave hostname: pomona.apache.org I1029 09:40:19.118610 3142 slave.cpp:319] Slave checkpoint: false W1029 09:40:19.118616 3142 slave.cpp:321] Disabling checkpointing is deprecated and the --checkpoint flag will be removed in a future release. Please avoid using this flag I1029 09:40:19.119204 3135 state.cpp:33] Recovering state from '/tmp/SlaveTest_IgnoreNonLeaderStatusUpdateAcknowledgement_E7ceOa/meta' I1029 09:40:19.119446 3143 status_update_manager.cpp:197] Recovering status update manager I1029 09:40:19.119691 3133 slave.cpp:3456] Finished recovery I1029 09:40:19.120076 3137 status_update_manager.cpp:171] Pausing sending status updates I1029 09:40:19.120087 3134 slave.cpp:602] New master detected at [email protected]:52646 I1029 09:40:19.120126 3134 slave.cpp:665] Authenticating with master [email protected]:52646 I1029 09:40:19.120234 3134 slave.cpp:638] Detecting new master I1029 09:40:19.120264 3141 authenticatee.hpp:133] Creating new client SASL connection I1029 09:40:19.120486 3143 master.cpp:3853] Authenticating slave(221)@67.195.81.187:52646 I1029 09:40:19.120631 3135 authenticator.hpp:161] Creating new server SASL connection I1029 09:40:19.120779 3138 authenticatee.hpp:224] Received SASL authentication mechanisms: CRAM-MD5 I1029 09:40:19.120800 3138 authenticatee.hpp:250] Attempting to authenticate with mechanism 'CRAM-MD5' I1029 09:40:19.120910 3140 authenticator.hpp:267] Received SASL authentication start I1029 09:40:19.122623 3116 sched.cpp:137] Version: 0.21.0 I1029 09:40:19.140969 3140 authenticator.hpp:389] Authentication requires more steps I1029 09:40:19.141086 3134 authenticatee.hpp:270] Received SASL authentication step I1029 09:40:19.141243 3142 authenticator.hpp:295] Received SASL authentication step I1029 09:40:19.141300 3142 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I1029 09:40:19.141329 3142 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I1029 09:40:19.141367 3142 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I1029 09:40:19.141397 3142 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I1029 09:40:19.141410 3142 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I1029 09:40:19.141419 3142 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I1029 09:40:19.141437 3142 authenticator.hpp:381] Authentication success I1029 09:40:19.141552 3137 authenticatee.hpp:310] Authentication success I1029 09:40:19.141607 3139 sched.cpp:233] New master detected at [email protected]:52646 I1029 09:40:19.141614 3136 master.cpp:3893] Successfully authenticated principal 'test-principal' at slave(221)@67.195.81.187:52646 I1029 09:40:19.141655 3139 sched.cpp:283] Authenticating with master [email protected]:52646 I1029 09:40:19.141803 3133 slave.cpp:722] Successfully authenticated with master [email protected]:52646 I1029 09:40:19.141935 3133 slave.cpp:1050] Will retry registration in 1.851985ms if necessary I1029 09:40:19.141953 3135 authenticatee.hpp:133] Creating new client SASL connection I1029 09:40:19.142122 3136 master.cpp:3032] Registering slave at slave(221)@67.195.81.187:52646 (pomona.apache.org) with id 20141029-094017-3142697795-52646-3116-S0 I1029 09:40:19.142488 3136 master.cpp:3853] Authenticating [email protected]:52646 I1029 09:40:19.142570 3144 registrar.cpp:445] Applied 1 operations in 53671ns; attempting to update the 'registry' I1029 09:40:19.142714 3142 authenticator.hpp:161] Creating new server SASL connection I1029 09:40:19.142868 3142 authenticatee.hpp:224] Received SASL authentication mechanisms: CRAM-MD5 I1029 09:40:19.142894 3142 authenticatee.hpp:250] Attempting to authenticate with mechanism 'CRAM-MD5' I1029 09:40:19.142984 3142 authenticator.hpp:267] Received SASL authentication start I1029 09:40:19.143038 3142 authenticator.hpp:389] Authentication requires more steps I1029 09:40:19.143129 3142 authenticatee.hpp:270] Received SASL authentication step I1029 09:40:19.143240 3142 authenticator.hpp:295] Received SASL authentication step I1029 09:40:19.143295 3142 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I1029 09:40:19.143311 3142 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I1029 09:40:19.143342 3142 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I1029 09:40:19.143368 3142 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I1029 09:40:19.143379 3142 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I1029 09:40:19.143388 3142 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I1029 09:40:19.143406 3142 authenticator.hpp:381] Authentication success I1029 09:40:19.143496 3143 authenticatee.hpp:310] Authentication success I1029 09:40:19.143502 3142 master.cpp:3893] Successfully authenticated principal 'test-principal' at [email protected]:52646 I1029 09:40:19.143746 3135 sched.cpp:357] Successfully authenticated with master [email protected]:52646 I1029 09:40:19.143772 3135 sched.cpp:476] Sending registration request to [email protected]:52646 I1029 09:40:19.143894 3142 master.cpp:1362] Received registration request for framework 'default' at [email protected]:52646 I1029 09:40:19.143965 3142 master.cpp:1321] Authorizing framework principal 'test-principal' to receive offers for role '*' I1029 09:40:19.144382 3134 slave.cpp:1050] Will retry registration in 26.869214ms if necessary I1029 09:40:19.144412 3131 master.cpp:1426] Registering framework 20141029-094017-3142697795-52646-3116-0000 (default) at [email protected]:52646 I1029 09:40:19.144719 3140 hierarchical_allocator_process.hpp:329] Added framework 20141029-094017-3142697795-52646-3116-0000 I1029 09:40:19.144750 3140 hierarchical_allocator_process.hpp:697] No resources available to allocate! I1029 09:40:19.144767 3140 hierarchical_allocator_process.hpp:659] Performed allocation for 0 slaves in 20887ns I1029 09:40:19.144899 3131 master.cpp:3020] Ignoring register slave message from slave(221)@67.195.81.187:52646 (pomona.apache.org) as admission is already in progress I1029 09:40:19.144927 3140 sched.cpp:407] Framework registered with 20141029-094017-3142697795-52646-3116-0000 I1029 09:40:19.145021 3140 sched.cpp:421] Scheduler::registered took 66223ns I1029 09:40:19.146101 3138 log.cpp:680] Attempting to append 314 bytes to the log I1029 09:40:19.146260 3130 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3 I1029 09:40:19.147037 3132 replica.cpp:508] Replica received write request for position 3 I1029 09:40:19.147657 3132 leveldb.cpp:343] Persisting action (333 bytes) to leveldb took 595290ns I1029 09:40:19.147685 3132 replica.cpp:676] Persisted action at 3 I1029 09:40:19.148233 3143 replica.cpp:655] Replica received learned notice for position 3 I1029 09:40:19.148720 3143 leveldb.cpp:343] Persisting action (335 bytes) to leveldb took 463427ns I1029 09:40:19.148741 3143 replica.cpp:676] Persisted action at 3 I1029 09:40:19.148756 3143 replica.cpp:661] Replica learned APPEND action at position 3 I1029 09:40:19.149673 3132 registrar.cpp:490] Successfully updated the 'registry' in 7.045888ms I1029 09:40:19.149961 3136 log.cpp:699] Attempting to truncate the log to 3 I1029 09:40:19.150087 3135 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4 I1029 09:40:19.150274 3138 slave.cpp:2522] Received ping from slave-observer(200)@67.195.81.187:52646 I1029 09:40:19.150388 3145 master.cpp:3086] Registered slave 20141029-094017-3142697795-52646-3116-S0 at slave(221)@67.195.81.187:52646 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I1029 09:40:19.150473 3138 slave.cpp:756] Registered with master [email protected]:52646; given slave ID 20141029-094017-3142697795-52646-3116-S0 I1029 09:40:19.150538 3133 hierarchical_allocator_process.hpp:442] Added slave 20141029-094017-3142697795-52646-3116-S0 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available) I1029 09:40:19.150576 3130 status_update_manager.cpp:178] Resuming sending status updates I1029 09:40:19.150753 3133 hierarchical_allocator_process.hpp:734] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20141029-094017-3142697795-52646-3116-S0 to framework 20141029-094017-3142697795-52646-3116-0000 I1029 09:40:19.150900 3144 replica.cpp:508] Replica received write request for position 4 I1029 09:40:19.205476 3133 hierarchical_allocator_process.hpp:679] Performed allocation for slave 20141029-094017-3142697795-52646-3116-S0 in 54.856249ms I1029 09:40:19.205835 3133 master.cpp:3795] Sending 1 offers to framework 20141029-094017-3142697795-52646-3116-0000 (default) at [email protected]:52646 I1029 09:40:19.205899 3144 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 745444ns I1029 09:40:19.205925 3144 replica.cpp:676] Persisted action at 4 I1029 09:40:19.206272 3145 sched.cpp:544] Scheduler::resourceOffers took 103845ns I1029 09:40:19.206784 3142 replica.cpp:655] Replica received learned notice for position 4 I1029 09:40:19.207487 3142 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 667602ns I1029 09:40:19.207556 3142 leveldb.cpp:401] Deleting ~2 keys from leveldb took 37231ns I1029 09:40:19.207578 3142 replica.cpp:676] Persisted action at 4 I1029 09:40:19.207600 3142 replica.cpp:661] Replica learned TRUNCATE action at position 4 I1029 09:40:19.210643 3145 master.cpp:2321] Processing reply for offers: [ 20141029-094017-3142697795-52646-3116-O0 ] on slave 20141029-094017-3142697795-52646-3116-S0 at slave(221)@67.195.81.187:52646 (pomona.apache.org) for framework 20141029-094017-3142697795-52646-3116-0000 (default) at [email protected]:52646 W1029 09:40:19.210777 3145 master.cpp:1969] Executor default for task ca34806b-376a-46da-b742-903aae98f312 uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases. W1029 09:40:19.210810 3145 master.cpp:1980] Executor default for task ca34806b-376a-46da-b742-903aae98f312 uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases. I1029 09:40:19.210913 3145 master.cpp:2417] Authorizing framework principal 'test-principal' to launch task ca34806b-376a-46da-b742-903aae98f312 as user 'jenkins' I1029 09:40:19.212076 3144 master.hpp:877] Adding task ca34806b-376a-46da-b742-903aae98f312 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20141029-094017-3142697795-52646-3116-S0 (pomona.apache.org) I1029 09:40:19.212195 3144 master.cpp:2480] Launching task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 (default) at [email protected]:52646 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20141029-094017-3142697795-52646-3116-S0 at slave(221)@67.195.81.187:52646 (pomona.apache.org) I1029 09:40:19.212568 3136 slave.cpp:1081] Got assigned task ca34806b-376a-46da-b742-903aae98f312 for framework 20141029-094017-3142697795-52646-3116-0000 I1029 09:40:19.213148 3136 slave.cpp:1191] Launching task ca34806b-376a-46da-b742-903aae98f312 for framework 20141029-094017-3142697795-52646-3116-0000 I1029 09:40:19.215901 3136 slave.cpp:3871] Launching executor default of framework 20141029-094017-3142697795-52646-3116-0000 in work directory '/tmp/SlaveTest_IgnoreNonLeaderStatusUpdateAcknowledgement_E7ceOa/slaves/20141029-094017-3142697795-52646-3116-S0/frameworks/20141029-094017-3142697795-52646-3116-0000/executors/default/runs/b836c8a7-d495-4ecc-9c1f-4b4d0b47841d' I1029 09:40:19.219048 3136 exec.cpp:132] Version: 0.21.0 I1029 09:40:19.219317 3132 exec.cpp:182] Executor started at: executor(74)@67.195.81.187:52646 with pid 3116 I1029 09:40:19.219502 3136 slave.cpp:1317] Queuing task 'ca34806b-376a-46da-b742-903aae98f312' for executor default of framework '20141029-094017-3142697795-52646-3116-0000 I1029 09:40:19.219641 3136 slave.cpp:555] Successfully attached file '/tmp/SlaveTest_IgnoreNonLeaderStatusUpdateAcknowledgement_E7ceOa/slaves/20141029-094017-3142697795-52646-3116-S0/frameworks/20141029-094017-3142697795-52646-3116-0000/executors/default/runs/b836c8a7-d495-4ecc-9c1f-4b4d0b47841d' I1029 09:40:19.219727 3136 slave.cpp:1849] Got registration for executor 'default' of framework 20141029-094017-3142697795-52646-3116-0000 from executor(74)@67.195.81.187:52646 I1029 09:40:19.220155 3136 slave.cpp:1968] Flushing queued task ca34806b-376a-46da-b742-903aae98f312 for executor 'default' of framework 20141029-094017-3142697795-52646-3116-0000 I1029 09:40:19.220214 3138 exec.cpp:206] Executor registered on slave 20141029-094017-3142697795-52646-3116-S0 I1029 09:40:19.220577 3136 slave.cpp:2802] Monitoring executor 'default' of framework '20141029-094017-3142697795-52646-3116-0000' in container 'b836c8a7-d495-4ecc-9c1f-4b4d0b47841d' I1029 09:40:19.222697 3138 exec.cpp:218] Executor::registered took 29157ns I1029 09:40:19.222894 3138 exec.cpp:293] Executor asked to run task 'ca34806b-376a-46da-b742-903aae98f312' I1029 09:40:19.222977 3138 exec.cpp:302] Executor::launchTask took 61419ns I1029 09:40:19.225311 3138 exec.cpp:525] Executor sending status update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 I1029 09:40:19.225558 3136 slave.cpp:2202] Handling status update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 from executor(74)@67.195.81.187:52646 I1029 09:40:19.225837 3131 status_update_manager.cpp:317] Received status update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 I1029 09:40:19.225882 3131 status_update_manager.cpp:494] Creating StatusUpdate stream for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 I1029 09:40:19.226078 3131 status_update_manager.cpp:371] Forwarding update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 to the slave I1029 09:40:19.226388 3133 slave.cpp:2442] Forwarding the update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 to [email protected]:52646 I1029 09:40:19.226567 3133 slave.cpp:2369] Status update manager successfully handled status update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 I1029 09:40:19.226599 3133 slave.cpp:2375] Sending acknowledgement for status update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 to executor(74)@67.195.81.187:52646 I1029 09:40:19.226709 3138 master.cpp:3410] Forwarding status update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 I1029 09:40:19.226758 3133 exec.cpp:339] Executor received status update acknowledgement cd782c8c-ef08-44f9-b308-b8d9b6d4534b for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 I1029 09:40:19.226868 3138 master.cpp:3382] Status update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 from slave 20141029-094017-3142697795-52646-3116-S0 at slave(221)@67.195.81.187:52646 (pomona.apache.org) I1029 09:40:19.226920 3138 master.cpp:4617] Updating the latest state of task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 to TASK_RUNNING I1029 09:40:19.226987 3144 sched.cpp:635] Scheduler::statusUpdate took 34407ns I1029 09:40:19.272017 3144 master.cpp:2882] Forwarding status update acknowledgement cd782c8c-ef08-44f9-b308-b8d9b6d4534b for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 (default) at [email protected]:52646 to slave 20141029-094017-3142697795-52646-3116-S0 at slave(221)@67.195.81.187:52646 (pomona.apache.org) W1029 09:40:19.290961 3134 slave.cpp:1756] Ignoring status update acknowledgement message from [email protected]:1 because it is not the expected master: [email protected]:52646 I1029 09:40:19.301856 3134 hierarchical_allocator_process.hpp:659] Performed allocation for 1 slaves in 132814ns I1029 09:40:19.301957 3135 master.cpp:120] No whitelist given. Advertising offers for all slaves W1029 09:40:19.302175 3139 status_update_manager.cpp:472] Resending status update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 I1029 09:40:19.302208 3139 status_update_manager.cpp:371] Forwarding update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 to the slave I1029 09:40:19.302577 3136 slave.cpp:2442] Forwarding the update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 to [email protected]:52646 I1029 09:40:19.302829 3136 master.cpp:3410] Forwarding status update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 I1029 09:40:19.302960 3136 master.cpp:3382] Status update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 from slave 20141029-094017-3142697795-52646-3116-S0 at slave(221)@67.195.81.187:52646 (pomona.apache.org) I1029 09:40:19.303009 3136 master.cpp:4617] Updating the latest state of task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 to TASK_RUNNING I1029 09:40:19.303073 3139 sched.cpp:635] Scheduler::statusUpdate took 26282ns I1029 09:40:19.303308 3139 master.cpp:2882] Forwarding status update acknowledgement cd782c8c-ef08-44f9-b308-b8d9b6d4534b for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 (default) at [email protected]:52646 to slave 20141029-094017-3142697795-52646-3116-S0 at slave(221)@67.195.81.187:52646 (pomona.apache.org) I1029 09:40:19.303616 3131 status_update_manager.cpp:389] Received status update acknowledgement (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 I1029 09:40:19.303843 3130 slave.cpp:1789] Status update manager successfully handled status update acknowledgement (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 I1029 09:40:19.331620 3116 master.cpp:677] Master terminating I1029 09:40:19.331665 3131 sched.cpp:745] Stopping framework '20141029-094017-3142697795-52646-3116-0000' W1029 09:40:19.331760 3116 master.cpp:4662] Removing task ca34806b-376a-46da-b742-903aae98f312 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 20141029-094017-3142697795-52646-3116-0000 on slave 20141029-094017-3142697795-52646-3116-S0 at slave(221)@67.195.81.187:52646 (pomona.apache.org) in non-terminal state TASK_RUNNING I1029 09:40:19.332249 3132 hierarchical_allocator_process.hpp:563] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20141029-094017-3142697795-52646-3116-S0 from framework 20141029-094017-3142697795-52646-3116-0000 I1029 09:40:19.332370 3116 master.cpp:4705] Removing executor 'default' with resources of framework 20141029-094017-3142697795-52646-3116-0000 on slave 20141029-094017-3142697795-52646-3116-S0 at slave(221)@67.195.81.187:52646 (pomona.apache.org) I1029 09:40:19.333036 3134 slave.cpp:2607] [email protected]:52646 exited W1029 09:40:19.333071 3134 slave.cpp:2610] Master disconnected! Waiting for a new master to be elected I1029 09:40:19.338084 3145 slave.cpp:2860] Executor 'default' of framework 20141029-094017-3142697795-52646-3116-0000 exited with status 0 I1029 09:40:19.340365 3145 slave.cpp:2202] Handling status update TASK_LOST (UUID: 738b05f1-43cf-48f3-a770-6512e44c7c20) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 from @0.0.0.0:0 I1029 09:40:19.340446 3145 slave.cpp:4179] Terminating task ca34806b-376a-46da-b742-903aae98f312 I1029 09:40:19.340796 3145 slave.cpp:484] Slave terminating I1029 09:40:19.340869 3145 slave.cpp:1522] Asked to shut down framework 20141029-094017-3142697795-52646-3116-0000 by @0.0.0.0:0 I1029 09:40:19.340893 3145 slave.cpp:1547] Shutting down framework 20141029-094017-3142697795-52646-3116-0000 I1029 09:40:19.340950 3145 slave.cpp:2997] Cleaning up executor 'default' of framework 20141029-094017-3142697795-52646-3116-0000 I1029 09:40:19.341166 3136 gc.cpp:56] Scheduling '/tmp/SlaveTest_IgnoreNonLeaderStatusUpdateAcknowledgement_E7ceOa/slaves/20141029-094017-3142697795-52646-3116-S0/frameworks/20141029-094017-3142697795-52646-3116-0000/executors/default/runs/b836c8a7-d495-4ecc-9c1f-4b4d0b47841d' for gc 6.99999605291556days in the future I1029 09:40:19.341214 3145 slave.cpp:3074] Cleaning up framework 20141029-094017-3142697795-52646-3116-0000 I1029 09:40:19.341369 3143 status_update_manager.cpp:279] Closing status update streams for framework 20141029-094017-3142697795-52646-3116-0000 I1029 09:40:19.341408 3136 gc.cpp:56] Scheduling '/tmp/SlaveTest_IgnoreNonLeaderStatusUpdateAcknowledgement_E7ceOa/slaves/20141029-094017-3142697795-52646-3116-S0/frameworks/20141029-094017-3142697795-52646-3116-0000/executors/default' for gc 6.99999605142519days in the future I1029 09:40:19.341442 3143 status_update_manager.cpp:525] Cleaning up status update stream for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 I1029 09:40:19.341562 3136 gc.cpp:56] Scheduling '/tmp/SlaveTest_IgnoreNonLeaderStatusUpdateAcknowledgement_E7ceOa/slaves/20141029-094017-3142697795-52646-3116-S0/frameworks/20141029-094017-3142697795-52646-3116-0000' for gc 6.99999604953778days in the future [ OK ] SlaveTest.IgnoreNonLeaderStatusUpdateAcknowledgement (2207 ms) [----------] 12 tests from SlaveTest (11982 ms total) [----------] Global test environment tear-down [==========] 449 tests from 70 test cases ran. (420137 ms total) [ PASSED ] 447 tests. [ FAILED ] 2 tests, listed below: [ FAILED ] ExamplesTest.JavaLog [ FAILED ] CoordinatorTest.TruncateNotLearnedFill 2 FAILED TESTS YOU HAVE 6 DISABLED TESTS make[3]: *** [check-local] Error 1 make[3]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'> make[2]: *** [check-am] Error 2 make[2]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'> make[1]: *** [check] Error 2 make[1]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'> make: *** [check-recursive] Error 1 Test finished Exit status: 2 Build step 'Execute shell' marked build as failure Recording test results
