See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2095/>
------------------------------------------ [...truncated 5711 lines...] I0428 16:00:02.257123 12910 sched.cpp:529] Scheduler::resourceOffers took 223588ns I0428 16:00:02.257308 12913 master.hpp:596] Removing offer 20140428-160001-453759884-35073-12543-1 with resources disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024 on slave 20140428-160001-453759884-35073-12543-0 (hemera.apache.org) I0428 16:00:02.257372 12913 master.cpp:1806] Processing reply for offers: [ 20140428-160001-453759884-35073-12543-1 ] on slave 20140428-160001-453759884-35073-12543-0 (hemera.apache.org) for framework 20140428-160001-453759884-35073-12543-0000 I0428 16:00:02.257431 12913 master.hpp:558] Adding task 0 with resources cpus(*):2; mem(*):1024 on slave 20140428-160001-453759884-35073-12543-0 (hemera.apache.org) I0428 16:00:02.257462 12913 master.cpp:2919] Launching task 0 of framework 20140428-160001-453759884-35073-12543-0000 with resources cpus(*):2; mem(*):1024 on slave 20140428-160001-453759884-35073-12543-0 (hemera.apache.org) I0428 16:00:02.257585 12913 hierarchical_allocator_process.hpp:547] Framework 20140428-160001-453759884-35073-12543-0000 left disk(*):1024; ports(*):[31000-32000] unused on slave 20140428-160001-453759884-35073-12543-0 I0428 16:00:02.257591 12910 slave.cpp:905] Got assigned task 0 for framework 20140428-160001-453759884-35073-12543-0000 I0428 16:00:02.257652 12913 hierarchical_allocator_process.hpp:590] Framework 20140428-160001-453759884-35073-12543-0000 filtered slave 20140428-160001-453759884-35073-12543-0 for 5secs I0428 16:00:02.257894 12910 gc.cpp:84] Unscheduling '/tmp/GarbageCollectorIntegrationTest_Unschedule_iXYmV4/slaves/20140428-160001-453759884-35073-12543-0/frameworks/20140428-160001-453759884-35073-12543-0000' from gc I0428 16:00:02.258018 12915 slave.cpp:1015] Launching task 0 for framework 20140428-160001-453759884-35073-12543-0000 I0428 16:00:02.262248 12915 exec.cpp:131] Version: 0.19.0 I0428 16:00:02.262312 12894 exec.cpp:181] Executor started at: executor(7)@140.211.11.27:35073 with pid 12543 I0428 16:00:02.262390 12915 slave.cpp:1125] Queuing task '0' for executor executor-2 of framework '20140428-160001-453759884-35073-12543-0000 I0428 16:00:02.262464 12915 slave.cpp:486] Successfully attached file '/tmp/GarbageCollectorIntegrationTest_Unschedule_iXYmV4/slaves/20140428-160001-453759884-35073-12543-0/frameworks/20140428-160001-453759884-35073-12543-0000/executors/executor-2/runs/6de316ff-ef68-4a45-8deb-2e6111c81819' I0428 16:00:02.262505 12915 slave.cpp:1598] Got registration for executor 'executor-2' of framework 20140428-160001-453759884-35073-12543-0000 I0428 16:00:02.262624 12915 slave.cpp:1717] Flushing queued task 0 for executor 'executor-2' of framework 20140428-160001-453759884-35073-12543-0000 I0428 16:00:02.262696 12914 exec.cpp:205] Executor registered on slave 20140428-160001-453759884-35073-12543-0 I0428 16:00:02.262711 12915 slave.cpp:2282] Monitoring executor 'executor-2' of framework '20140428-160001-453759884-35073-12543-0000' in container '6de316ff-ef68-4a45-8deb-2e6111c81819' I0428 16:00:02.264513 12914 exec.cpp:217] Executor::registered took 19500ns I0428 16:00:02.264590 12914 exec.cpp:292] Executor asked to run task '0' I0428 16:00:02.264657 12914 exec.cpp:301] Executor::launchTask took 49717ns I0428 16:00:02.266593 12914 exec.cpp:524] Executor sending status update TASK_RUNNING (UUID: b35958f7-bbcc-4b96-a94e-58b37363aa5d) for task 0 of framework 20140428-160001-453759884-35073-12543-0000 I0428 16:00:02.266716 12909 slave.cpp:1953] Handling status update TASK_RUNNING (UUID: b35958f7-bbcc-4b96-a94e-58b37363aa5d) for task 0 of framework 20140428-160001-453759884-35073-12543-0000 from executor(7)@140.211.11.27:35073 I0428 16:00:02.266849 12914 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: b35958f7-bbcc-4b96-a94e-58b37363aa5d) for task 0 of framework 20140428-160001-453759884-35073-12543-0000 I0428 16:00:02.266908 12914 status_update_manager.cpp:499] Creating StatusUpdate stream for task 0 of framework 20140428-160001-453759884-35073-12543-0000 I0428 16:00:02.266998 12914 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: b35958f7-bbcc-4b96-a94e-58b37363aa5d) for task 0 of framework 20140428-160001-453759884-35073-12543-0000 to [email protected]:35073 I0428 16:00:02.267144 12909 slave.cpp:2070] Status update manager successfully handled status update TASK_RUNNING (UUID: b35958f7-bbcc-4b96-a94e-58b37363aa5d) for task 0 of framework 20140428-160001-453759884-35073-12543-0000 I0428 16:00:02.267170 12909 slave.cpp:2076] Sending acknowledgement for status update TASK_RUNNING (UUID: b35958f7-bbcc-4b96-a94e-58b37363aa5d) for task 0 of framework 20140428-160001-453759884-35073-12543-0000 to executor(7)@140.211.11.27:35073 I0428 16:00:02.267173 12915 master.cpp:2444] Status update TASK_RUNNING (UUID: b35958f7-bbcc-4b96-a94e-58b37363aa5d) for task 0 of framework 20140428-160001-453759884-35073-12543-0000 from slave(7)@140.211.11.27:35073 I0428 16:00:02.267256 12915 exec.cpp:338] Executor received status update acknowledgement b35958f7-bbcc-4b96-a94e-58b37363aa5d for task 0 of framework 20140428-160001-453759884-35073-12543-0000 I0428 16:00:02.267273 12910 sched.cpp:620] Scheduler::statusUpdate took 15096ns I0428 16:00:02.267436 12897 status_update_manager.cpp:398] Received status update acknowledgement (UUID: b35958f7-bbcc-4b96-a94e-58b37363aa5d) for task 0 of framework 20140428-160001-453759884-35073-12543-0000 I0428 16:00:02.267535 12897 slave.cpp:1538] Status update manager successfully handled status update acknowledgement (UUID: b35958f7-bbcc-4b96-a94e-58b37363aa5d) for task 0 of framework 20140428-160001-453759884-35073-12543-0000 I0428 16:00:02.286553 12543 master.cpp:551] Master terminating I0428 16:00:02.286576 12897 sched.cpp:731] Stopping framework '20140428-160001-453759884-35073-12543-0000' I0428 16:00:02.286619 12543 master.hpp:576] Removing task 0 with resources cpus(*):2; mem(*):1024 on slave 20140428-160001-453759884-35073-12543-0 (hemera.apache.org) I0428 16:00:02.286741 12900 hierarchical_allocator_process.hpp:637] Recovered cpus(*):2; mem(*):1024 (total allocatable: disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024) on slave 20140428-160001-453759884-35073-12543-0 from framework 20140428-160001-453759884-35073-12543-0000 I0428 16:00:02.287065 12900 slave.cpp:2151] [email protected]:35073 exited W0428 16:00:02.287088 12900 slave.cpp:2154] Master disconnected! Waiting for a new master to be elected I0428 16:00:02.290055 12543 slave.cpp:414] Slave terminating I0428 16:00:02.290071 12543 slave.cpp:1309] Asked to shut down framework 20140428-160001-453759884-35073-12543-0000 by @0.0.0.0:0 I0428 16:00:02.290081 12543 slave.cpp:1334] Shutting down framework 20140428-160001-453759884-35073-12543-0000 I0428 16:00:02.290089 12543 slave.cpp:2625] Shutting down executor 'executor-2' of framework 20140428-160001-453759884-35073-12543-0000 I0428 16:00:02.290123 12894 exec.cpp:378] Executor asked to shutdown I0428 16:00:02.290222 12894 exec.cpp:393] Executor::shutdown took 85585ns [ OK ] GarbageCollectorIntegrationTest.Unschedule (395 ms) [----------] 5 tests from GarbageCollectorIntegrationTest (2128 ms total) [----------] 7 tests from MesosContainerizerProcessTest [ RUN ] MesosContainerizerProcessTest.NoHadoop [ OK ] MesosContainerizerProcessTest.NoHadoop (0 ms) [ RUN ] MesosContainerizerProcessTest.NoUser [ OK ] MesosContainerizerProcessTest.NoUser (0 ms) [ RUN ] MesosContainerizerProcessTest.EmptyHadoop [ OK ] MesosContainerizerProcessTest.EmptyHadoop (0 ms) [ RUN ] MesosContainerizerProcessTest.NoExtract [ OK ] MesosContainerizerProcessTest.NoExtract (0 ms) [ RUN ] MesosContainerizerProcessTest.Simple [ OK ] MesosContainerizerProcessTest.Simple (0 ms) [ RUN ] MesosContainerizerProcessTest.NoExtractExecutable [ OK ] MesosContainerizerProcessTest.NoExtractExecutable (0 ms) [ RUN ] MesosContainerizerProcessTest.MultipleURIs [ OK ] MesosContainerizerProcessTest.MultipleURIs (0 ms) [----------] 7 tests from MesosContainerizerProcessTest (1 ms total) [----------] 1 test from ExternalContainerizerTest [ RUN ] ExternalContainerizerTest.Launch I0428 16:00:02.340895 12543 leveldb.cpp:174] Opened db in 48.172651ms I0428 16:00:02.357269 12543 leveldb.cpp:181] Compacted db in 16.353102ms I0428 16:00:02.357292 12543 leveldb.cpp:196] Created db iterator in 4041ns I0428 16:00:02.357300 12543 leveldb.cpp:202] Seeked to beginning of db in 666ns I0428 16:00:02.357306 12543 leveldb.cpp:271] Iterated through 0 keys in the db in 301ns I0428 16:00:02.357319 12543 replica.cpp:729] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0428 16:00:02.357566 12917 recover.cpp:425] Starting replica recovery I0428 16:00:02.357954 12916 master.cpp:266] Master 20140428-160002-453759884-35073-12543 (hemera.apache.org) started on 140.211.11.27:35073 I0428 16:00:02.357976 12897 recover.cpp:451] Replica is in EMPTY status I0428 16:00:02.357983 12916 master.cpp:303] Master only allowing authenticated frameworks to register I0428 16:00:02.358031 12916 master.cpp:308] Master only allowing authenticated slaves to register I0428 16:00:02.358039 12916 credentials.hpp:35] Loading credentials for authentication W0428 16:00:02.358146 12916 credentials.hpp:48] Failed to stat credentials file 'file:///tmp/ExternalContainerizerTest_Launch_vWFfWy/credentials': No such file or directory I0428 16:00:02.358522 12914 master.cpp:104] No whitelist given. Advertising offers for all slaves I0428 16:00:02.358592 12899 hierarchical_allocator_process.hpp:302] Initializing hierarchical allocator process with master : [email protected]:35073 I0428 16:00:02.358732 12902 replica.cpp:626] Replica in EMPTY status received a broadcasted recover request I0428 16:00:02.358999 12907 recover.cpp:188] Received a recover response from a replica in EMPTY status I0428 16:00:02.359308 12917 master.cpp:922] The newly elected leader is [email protected]:35073 with id 20140428-160002-453759884-35073-12543 I0428 16:00:02.359380 12917 master.cpp:932] Elected as the leading master! I0428 16:00:02.359386 12917 master.cpp:753] Recovering from registrar I0428 16:00:02.359639 12903 registrar.cpp:275] Recovering registrar I0428 16:00:02.359868 12896 recover.cpp:542] Updating replica status to STARTING I0428 16:00:02.373303 12902 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 12.739312ms I0428 16:00:02.373324 12902 replica.cpp:320] Persisted replica status to STARTING I0428 16:00:02.373386 12902 recover.cpp:451] Replica is in STARTING status I0428 16:00:02.374486 12915 replica.cpp:626] Replica in STARTING status received a broadcasted recover request I0428 16:00:02.374752 12904 recover.cpp:188] Received a recover response from a replica in STARTING status I0428 16:00:02.375953 12911 recover.cpp:542] Updating replica status to VOTING I0428 16:00:02.385390 12911 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 8.63671ms I0428 16:00:02.385408 12911 replica.cpp:320] Persisted replica status to VOTING I0428 16:00:02.385468 12911 recover.cpp:556] Successfully joined the Paxos group I0428 16:00:02.385516 12911 recover.cpp:440] Recover process terminated I0428 16:00:02.385853 12910 log.cpp:656] Attempting to start the writer I0428 16:00:02.387519 12910 replica.cpp:474] Replica received implicit promise request with proposal 1 I0428 16:00:02.397522 12910 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 9.973951ms I0428 16:00:02.397552 12910 replica.cpp:342] Persisted promised to 1 I0428 16:00:02.398980 12905 coordinator.cpp:229] Coordinator attemping to fill missing position I0428 16:00:02.399971 12906 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2 I0428 16:00:02.409569 12906 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 9.573327ms I0428 16:00:02.409598 12906 replica.cpp:664] Persisted action at 0 I0428 16:00:02.411128 12899 replica.cpp:508] Replica received write request for position 0 I0428 16:00:02.411152 12899 leveldb.cpp:436] Reading position from leveldb took 11977ns I0428 16:00:02.421641 12899 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 10.477552ms I0428 16:00:02.421661 12899 replica.cpp:664] Persisted action at 0 I0428 16:00:02.422251 12915 replica.cpp:643] Replica received learned notice for position 0 I0428 16:00:02.433766 12915 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 11.491455ms I0428 16:00:02.433797 12915 replica.cpp:664] Persisted action at 0 I0428 16:00:02.433809 12915 replica.cpp:649] Replica learned NOP action at position 0 I0428 16:00:02.434239 12896 log.cpp:672] Writer started with ending position 0 I0428 16:00:02.435423 12895 leveldb.cpp:436] Reading position from leveldb took 9215ns I0428 16:00:02.437248 12898 registrar.cpp:308] Successfully recovered registrar I0428 16:00:02.437279 12898 registrar.cpp:379] Attempting to update the 'registry' I0428 16:00:02.439064 12916 log.cpp:680] Attempting to append 138 bytes to the log I0428 16:00:02.439527 12915 coordinator.cpp:339] Coordinator attempting to write APPEND action at position 1 I0428 16:00:02.441226 12896 replica.cpp:508] Replica received write request for position 1 I0428 16:00:02.449812 12896 leveldb.cpp:341] Persisting action (157 bytes) to leveldb took 8.569294ms I0428 16:00:02.449832 12896 replica.cpp:664] Persisted action at 1 I0428 16:00:02.450150 12896 replica.cpp:643] Replica received learned notice for position 1 I0428 16:00:02.461909 12896 leveldb.cpp:341] Persisting action (159 bytes) to leveldb took 11.744459ms I0428 16:00:02.461930 12896 replica.cpp:664] Persisted action at 1 I0428 16:00:02.461937 12896 replica.cpp:649] Replica learned APPEND action at position 1 I0428 16:00:02.462373 12913 registrar.cpp:427] Successfully updated 'registry' I0428 16:00:02.463577 12909 log.cpp:699] Attempting to truncate the log to 1 I0428 16:00:02.463837 12908 master.cpp:780] Recovered 0 slaves from the Registry (100B) ; allowing 10mins for slaves to re-register I0428 16:00:02.463969 12902 coordinator.cpp:339] Coordinator attempting to write TRUNCATE action at position 2 I0428 16:00:02.465935 12901 replica.cpp:508] Replica received write request for position 2 I0428 16:00:02.466832 12916 slave.cpp:140] Slave started on 8)@140.211.11.27:35073 I0428 16:00:02.466850 12916 credentials.hpp:35] Loading credentials for authentication W0428 16:00:02.467068 12916 credentials.hpp:48] Failed to stat credentials file 'file:///tmp/ExternalContainerizerTest_Launch_oPOdv3/credential': No such file or directory I0428 16:00:02.467150 12916 slave.cpp:231] Slave using credential for: test-principal I0428 16:00:02.467243 12916 slave.cpp:244] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0428 16:00:02.467326 12916 slave.cpp:272] Slave hostname: hemera.apache.org I0428 16:00:02.467339 12916 slave.cpp:273] Slave checkpoint: false I0428 16:00:02.467818 12906 state.cpp:33] Recovering state from '/tmp/ExternalContainerizerTest_Launch_oPOdv3/meta' I0428 16:00:02.467993 12911 status_update_manager.cpp:193] Recovering status update manager I0428 16:00:02.468261 12894 slave.cpp:2943] Finished recovery I0428 16:00:02.468559 12894 slave.cpp:525] New master detected at [email protected]:35073 I0428 16:00:02.468585 12894 slave.cpp:585] Authenticating with master [email protected]:35073 I0428 16:00:02.468615 12894 slave.cpp:558] Detecting new master I0428 16:00:02.468696 12911 status_update_manager.cpp:167] New master detected at [email protected]:35073 I0428 16:00:02.468761 12894 authenticatee.hpp:128] Creating new client SASL connection I0428 16:00:02.468897 12543 sched.cpp:121] Version: 0.19.0 I0428 16:00:02.469069 12905 master.cpp:2795] Authenticating slave(8)@140.211.11.27:35073 I0428 16:00:02.469511 12912 authenticator.hpp:148] Creating new server SASL connection I0428 16:00:02.469753 12905 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I0428 16:00:02.469826 12905 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I0428 16:00:02.469818 12914 sched.cpp:217] New master detected at [email protected]:35073 I0428 16:00:02.469882 12914 sched.cpp:268] Authenticating with master [email protected]:35073 I0428 16:00:02.469969 12913 authenticatee.hpp:128] Creating new client SASL connection I0428 16:00:02.470269 12910 master.cpp:2795] Authenticating scheduler(7)@140.211.11.27:35073 I0428 16:00:02.470461 12899 authenticator.hpp:254] Received SASL authentication start I0428 16:00:02.470500 12899 authenticator.hpp:342] Authentication requires more steps I0428 16:00:02.470641 12908 authenticatee.hpp:265] Received SASL authentication step I0428 16:00:02.470788 12900 authenticator.hpp:148] Creating new server SASL connection I0428 16:00:02.471194 12895 authenticator.hpp:282] Received SASL authentication step I0428 16:00:02.471215 12895 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 I0428 16:00:02.471225 12895 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I0428 16:00:02.471233 12895 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0428 16:00:02.471241 12895 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 I0428 16:00:02.471246 12895 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0428 16:00:02.471249 12895 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0428 16:00:02.471258 12895 authenticator.hpp:334] Authentication success I0428 16:00:02.471338 12902 authenticatee.hpp:305] Authentication success I0428 16:00:02.471674 12898 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I0428 16:00:02.471699 12898 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I0428 16:00:02.471765 12913 slave.cpp:642] Successfully authenticated with master [email protected]:35073 I0428 16:00:02.471843 12910 authenticator.hpp:254] Received SASL authentication start I0428 16:00:02.471951 12910 authenticator.hpp:342] Authentication requires more steps I0428 16:00:02.471951 12913 slave.cpp:871] Will retry registration in 9.60804613secs if necessary I0428 16:00:02.471982 12909 master.cpp:2835] Successfully authenticated slave(8)@140.211.11.27:35073 I0428 16:00:02.472069 12916 authenticatee.hpp:265] Received SASL authentication step I0428 16:00:02.472141 12905 authenticator.hpp:282] Received SASL authentication step I0428 16:00:02.472157 12905 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 I0428 16:00:02.472162 12905 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I0428 16:00:02.472167 12905 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0428 16:00:02.472172 12905 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 I0428 16:00:02.472177 12905 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0428 16:00:02.472179 12905 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0428 16:00:02.472187 12905 authenticator.hpp:334] Authentication success I0428 16:00:02.472599 12912 authenticatee.hpp:305] Authentication success I0428 16:00:02.472636 12909 master.cpp:2835] Successfully authenticated scheduler(7)@140.211.11.27:35073 I0428 16:00:02.472643 12911 registrar.cpp:379] Attempting to update the 'registry' I0428 16:00:02.472981 12907 sched.cpp:342] Successfully authenticated with master [email protected]:35073 I0428 16:00:02.473001 12907 sched.cpp:461] Sending registration request to [email protected]:35073 I0428 16:00:02.473069 12902 master.cpp:981] Received registration request from scheduler(7)@140.211.11.27:35073 I0428 16:00:02.473141 12902 master.cpp:999] Registering framework 20140428-160002-453759884-35073-12543-0000 at scheduler(7)@140.211.11.27:35073 I0428 16:00:02.473228 12897 sched.cpp:392] Framework registered with 20140428-160002-453759884-35073-12543-0000 I0428 16:00:02.473322 12900 hierarchical_allocator_process.hpp:332] Added framework 20140428-160002-453759884-35073-12543-0000 I0428 16:00:02.473326 12897 sched.cpp:406] Scheduler::registered took 71326ns I0428 16:00:02.473358 12900 hierarchical_allocator_process.hpp:726] No resources available to allocate! I0428 16:00:02.473387 12900 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 26812ns I0428 16:00:02.478169 12901 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 12.218818ms I0428 16:00:02.478185 12901 replica.cpp:664] Persisted action at 2 I0428 16:00:02.478386 12911 replica.cpp:643] Replica received learned notice for position 2 I0428 16:00:02.490278 12911 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 11.862075ms I0428 16:00:02.490314 12911 leveldb.cpp:399] Deleting ~1 keys from leveldb took 16337ns I0428 16:00:02.490324 12911 replica.cpp:664] Persisted action at 2 I0428 16:00:02.490331 12911 replica.cpp:649] Replica learned TRUNCATE action at position 2 I0428 16:00:02.491200 12899 log.cpp:680] Attempting to append 332 bytes to the log I0428 16:00:02.491495 12906 coordinator.cpp:339] Coordinator attempting to write APPEND action at position 3 I0428 16:00:02.492511 12915 replica.cpp:508] Replica received write request for position 3 I0428 16:00:02.502383 12915 leveldb.cpp:341] Persisting action (351 bytes) to leveldb took 9.846269ms I0428 16:00:02.502414 12915 replica.cpp:664] Persisted action at 3 I0428 16:00:02.502840 12912 replica.cpp:643] Replica received learned notice for position 3 I0428 16:00:02.514464 12912 leveldb.cpp:341] Persisting action (353 bytes) to leveldb took 11.537694ms I0428 16:00:02.514495 12912 replica.cpp:664] Persisted action at 3 I0428 16:00:02.514507 12912 replica.cpp:649] Replica learned APPEND action at position 3 I0428 16:00:02.514791 12905 registrar.cpp:427] Successfully updated 'registry' I0428 16:00:02.515210 12896 master.cpp:2169] Admitted slave on hemera.apache.org at slave(8)@140.211.11.27:35073 I0428 16:00:02.515225 12896 master.cpp:3283] Adding slave 20140428-160002-453759884-35073-12543-0 at hemera.apache.org with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0428 16:00:02.515394 12897 log.cpp:699] Attempting to truncate the log to 3 I0428 16:00:02.515413 12913 slave.cpp:675] Registered with master [email protected]:35073; given slave ID 20140428-160002-453759884-35073-12543-0 I0428 16:00:02.515547 12896 hierarchical_allocator_process.hpp:445] Added slave 20140428-160002-453759884-35073-12543-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) I0428 16:00:02.515658 12913 coordinator.cpp:339] Coordinator attempting to write TRUNCATE action at position 4 I0428 16:00:02.515683 12896 hierarchical_allocator_process.hpp:752] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140428-160002-453759884-35073-12543-0 to framework 20140428-160002-453759884-35073-12543-0000 I0428 16:00:02.515745 12896 hierarchical_allocator_process.hpp:708] Performed allocation for slave 20140428-160002-453759884-35073-12543-0 in 80476ns I0428 16:00:02.515789 12896 master.hpp:586] Adding offer 20140428-160002-453759884-35073-12543-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140428-160002-453759884-35073-12543-0 (hemera.apache.org) I0428 16:00:02.515830 12896 master.cpp:2744] Sending 1 offers to framework 20140428-160002-453759884-35073-12543-0000 I0428 16:00:02.516471 12901 sched.cpp:529] Scheduler::resourceOffers took 382996ns I0428 16:00:02.517318 12899 master.hpp:596] Removing offer 20140428-160002-453759884-35073-12543-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140428-160002-453759884-35073-12543-0 (hemera.apache.org) I0428 16:00:02.517356 12899 master.cpp:1806] Processing reply for offers: [ 20140428-160002-453759884-35073-12543-0 ] on slave 20140428-160002-453759884-35073-12543-0 (hemera.apache.org) for framework 20140428-160002-453759884-35073-12543-0000 I0428 16:00:02.517403 12899 master.hpp:558] Adding task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140428-160002-453759884-35073-12543-0 (hemera.apache.org) I0428 16:00:02.517442 12899 master.cpp:2919] Launching task 1 of framework 20140428-160002-453759884-35073-12543-0000 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140428-160002-453759884-35073-12543-0 (hemera.apache.org) I0428 16:00:02.517693 12897 slave.cpp:905] Got assigned task 1 for framework 20140428-160002-453759884-35073-12543-0000 I0428 16:00:02.517957 12897 slave.cpp:1015] Launching task 1 for framework 20140428-160002-453759884-35073-12543-0000 I0428 16:00:02.518523 12902 replica.cpp:508] Replica received write request for position 4 I0428 16:00:02.520025 12897 slave.cpp:1125] Queuing task '1' for executor 1 of framework '20140428-160002-453759884-35073-12543-0000 I0428 16:00:02.520045 12912 external_containerizer.cpp:266] Launching container 'b757cf3d-ab7a-4f78-a177-acc862081bbe' I0428 16:00:02.520081 12897 slave.cpp:486] Successfully attached file '/tmp/ExternalContainerizerTest_Launch_oPOdv3/slaves/20140428-160002-453759884-35073-12543-0/frameworks/20140428-160002-453759884-35073-12543-0000/executors/1/runs/b757cf3d-ab7a-4f78-a177-acc862081bbe' I0428 16:00:02.520180 12912 external_containerizer.cpp:804] Invoking external containerizer for method 'launch' I0428 16:00:02.520216 12912 external_containerizer.cpp:818] user: jenkins I0428 16:00:02.530993 12902 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 12.432026ms I0428 16:00:02.531069 12902 replica.cpp:664] Persisted action at 4 make[3]: *** [check-local] Broken pipe 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 I0428 16:00:04.833143 13947 exec.cpp:85] Committing suicide by killing the process group Build step 'Execute shell' marked build as failure
