You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mesos.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2014/04/24 23:52:53 UTC
Build failed in Jenkins:
Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME #2087
See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/2087/changes>
Changes:
[bmahler] Added a missing call to delete on the RegistrarProcess.
[vinod] Renamed and moved MasterZooKeeperTest fixture.
[vinod] Integrated log storage into master.
[bmahler] Manipulated clock in metric tests to avoid rate limiting.
[bmahler] Added message counters and a counter for slave timeouts during recovery in Master.
[niklas] Updated containerizer.proto's Launch message, added Destroy-, Wait- and Usage-messages.
------------------------------------------
[...truncated 42723 lines...]
I0424 21:52:51.273568 16662 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 20.179263ms
I0424 21:52:51.273624 16662 replica.cpp:320] Persisted replica status to STARTING
I0424 21:52:51.273764 16663 recover.cpp:451] Replica is in STARTING status
I0424 21:52:51.274024 16664 replica.cpp:626] Replica in STARTING status received a broadcasted recover request
I0424 21:52:51.274149 16663 recover.cpp:188] Received a recover response from a replica in STARTING status
I0424 21:52:51.274288 16659 recover.cpp:542] Updating replica status to VOTING
I0424 21:52:51.278003 16663 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 3.659359ms
I0424 21:52:51.278024 16663 replica.cpp:320] Persisted replica status to VOTING
I0424 21:52:51.278082 16659 recover.cpp:556] Successfully joined the Paxos group
I0424 21:52:51.278192 16659 recover.cpp:440] Recover process terminated
I0424 21:52:51.278360 16666 log.cpp:656] Attempting to start the writer
I0424 21:52:51.278813 16660 replica.cpp:474] Replica received implicit promise request with proposal 1
I0424 21:52:51.286348 16660 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 7.51685ms
I0424 21:52:51.286365 16660 replica.cpp:342] Persisted promised to 1
I0424 21:52:51.286664 16663 coordinator.cpp:229] Coordinator attemping to fill missing position
I0424 21:52:51.287245 16665 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I0424 21:52:51.294661 16665 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 7.398646ms
I0424 21:52:51.294679 16665 replica.cpp:664] Persisted action at 0
I0424 21:52:51.295120 16660 replica.cpp:508] Replica received write request for position 0
I0424 21:52:51.295146 16660 leveldb.cpp:436] Reading position from leveldb took 11388ns
I0424 21:52:51.303009 16660 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 7.84837ms
I0424 21:52:51.303026 16660 replica.cpp:664] Persisted action at 0
I0424 21:52:51.303269 16659 replica.cpp:643] Replica received learned notice for position 0
I0424 21:52:51.311322 16659 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 8.036591ms
I0424 21:52:51.311346 16659 replica.cpp:664] Persisted action at 0
I0424 21:52:51.311355 16659 replica.cpp:649] Replica learned NOP action at position 0
I0424 21:52:51.311578 16660 log.cpp:672] Writer started with ending position 0
I0424 21:52:51.312005 16659 leveldb.cpp:436] Reading position from leveldb took 16226ns
I0424 21:52:51.313616 16661 registrar.cpp:308] Successfully recovered registrar
I0424 21:52:51.313642 16661 registrar.cpp:379] Attempting to update the 'registry'
I0424 21:52:51.315104 16661 log.cpp:680] Attempting to append 137 bytes to the log
I0424 21:52:51.315181 16665 coordinator.cpp:339] Coordinator attempting to write APPEND action at position 1
I0424 21:52:51.315495 16659 replica.cpp:508] Replica received write request for position 1
I0424 21:52:51.319648 16659 leveldb.cpp:341] Persisting action (156 bytes) to leveldb took 4.134342ms
I0424 21:52:51.319666 16659 replica.cpp:664] Persisted action at 1
I0424 21:52:51.319900 16661 replica.cpp:643] Replica received learned notice for position 1
I0424 21:52:51.327982 16661 leveldb.cpp:341] Persisting action (158 bytes) to leveldb took 8.049144ms
I0424 21:52:51.327999 16661 replica.cpp:664] Persisted action at 1
I0424 21:52:51.328007 16661 replica.cpp:649] Replica learned APPEND action at position 1
I0424 21:52:51.328378 16660 registrar.cpp:427] Successfully updated 'registry'
I0424 21:52:51.328543 16665 log.cpp:699] Attempting to truncate the log to 1
I0424 21:52:51.328601 16665 coordinator.cpp:339] Coordinator attempting to write TRUNCATE action at position 2
I0424 21:52:51.328605 16666 master.cpp:806] Recovered 0 slaves from the Registry (99B) ; allowing 10mins for slaves to re-register
I0424 21:52:51.328938 16661 replica.cpp:508] Replica received write request for position 2
I0424 21:52:51.329237 16552 containerizer.cpp:177] Using isolation: posix/cpu,posix/mem
I0424 21:52:51.330973 16659 slave.cpp:130] Slave started on 146)@67.195.138.61:59407
I0424 21:52:51.331105 16659 slave.cpp:218] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0424 21:52:51.331178 16659 slave.cpp:246] Slave hostname: juno.apache.org
I0424 21:52:51.331190 16659 slave.cpp:247] Slave checkpoint: true
I0424 21:52:51.331764 16666 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_RecoverSlaveState_5ixOwr/meta'
I0424 21:52:51.331897 16663 status_update_manager.cpp:193] Recovering status update manager
I0424 21:52:51.331982 16663 mesos_containerizer.cpp:199] Recovering containerizer
I0424 21:52:51.332229 16666 slave.cpp:2802] Finished recovery
I0424 21:52:51.332546 16666 slave.cpp:497] New master detected at master@67.195.138.61:59407
I0424 21:52:51.332607 16666 slave.cpp:731] Will retry registration in 7.264555526secs if necessary
I0424 21:52:51.332625 16662 status_update_manager.cpp:167] New master detected at master@67.195.138.61:59407
I0424 21:52:51.332631 16666 slave.cpp:522] Detecting new master
I0424 21:52:51.332801 16666 registrar.cpp:379] Attempting to update the 'registry'
I0424 21:52:51.332936 16552 sched.cpp:121] Version: 0.19.0
I0424 21:52:51.333214 16665 sched.cpp:217] New master detected at master@67.195.138.61:59407
I0424 21:52:51.333237 16665 sched.cpp:268] Authenticating with master master@67.195.138.61:59407
I0424 21:52:51.333330 16659 authenticatee.hpp:128] Creating new client SASL connection
I0424 21:52:51.333462 16665 master.cpp:2731] Authenticating framework at scheduler(138)@67.195.138.61:59407
I0424 21:52:51.333534 16659 authenticator.hpp:148] Creating new server SASL connection
I0424 21:52:51.333644 16659 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0424 21:52:51.333662 16659 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0424 21:52:51.333696 16659 authenticator.hpp:254] Received SASL authentication start
I0424 21:52:51.333746 16659 authenticator.hpp:342] Authentication requires more steps
I0424 21:52:51.333781 16659 authenticatee.hpp:265] Received SASL authentication step
I0424 21:52:51.333829 16659 authenticator.hpp:282] Received SASL authentication step
I0424 21:52:51.333850 16659 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'juno.apache.org' server FQDN: 'juno.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0424 21:52:51.333860 16659 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0424 21:52:51.333873 16659 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0424 21:52:51.333886 16659 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'juno.apache.org' server FQDN: 'juno.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0424 21:52:51.333894 16659 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0424 21:52:51.333900 16659 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0424 21:52:51.333914 16659 authenticator.hpp:334] Authentication success
I0424 21:52:51.333951 16659 authenticatee.hpp:305] Authentication success
I0424 21:52:51.333979 16662 master.cpp:2771] Successfully authenticated framework at scheduler(138)@67.195.138.61:59407
I0424 21:52:51.334007 16659 sched.cpp:342] Successfully authenticated with master master@67.195.138.61:59407
I0424 21:52:51.334031 16659 sched.cpp:461] Sending registration request to master@67.195.138.61:59407
I0424 21:52:51.334125 16662 master.cpp:1007] Received registration request from scheduler(138)@67.195.138.61:59407
I0424 21:52:51.334161 16662 master.cpp:1025] Registering framework 20140424-215251-1032504131-59407-16552-0000 at scheduler(138)@67.195.138.61:59407
I0424 21:52:51.334233 16662 sched.cpp:392] Framework registered with 20140424-215251-1032504131-59407-16552-0000
I0424 21:52:51.334255 16662 sched.cpp:406] Scheduler::registered took 10055ns
I0424 21:52:51.334292 16662 hierarchical_allocator_process.hpp:332] Added framework 20140424-215251-1032504131-59407-16552-0000
I0424 21:52:51.334303 16662 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0424 21:52:51.334310 16662 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 6927ns
I0424 21:52:51.336307 16661 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 7.351389ms
I0424 21:52:51.336325 16661 replica.cpp:664] Persisted action at 2
I0424 21:52:51.336565 16659 replica.cpp:643] Replica received learned notice for position 2
I0424 21:52:51.344638 16659 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 8.057296ms
I0424 21:52:51.344666 16659 leveldb.cpp:399] Deleting ~1 keys from leveldb took 11442ns
I0424 21:52:51.344677 16659 replica.cpp:664] Persisted action at 2
I0424 21:52:51.344686 16659 replica.cpp:649] Replica learned TRUNCATE action at position 2
I0424 21:52:51.344959 16659 log.cpp:680] Attempting to append 328 bytes to the log
I0424 21:52:51.345023 16662 coordinator.cpp:339] Coordinator attempting to write APPEND action at position 3
I0424 21:52:51.345324 16665 replica.cpp:508] Replica received write request for position 3
I0424 21:52:51.352964 16665 leveldb.cpp:341] Persisting action (347 bytes) to leveldb took 7.620106ms
I0424 21:52:51.352983 16665 replica.cpp:664] Persisted action at 3
I0424 21:52:51.353257 16666 replica.cpp:643] Replica received learned notice for position 3
I0424 21:52:51.361295 16666 leveldb.cpp:341] Persisting action (349 bytes) to leveldb took 8.021148ms
I0424 21:52:51.361315 16666 replica.cpp:664] Persisted action at 3
I0424 21:52:51.361323 16666 replica.cpp:649] Replica learned APPEND action at position 3
I0424 21:52:51.361652 16664 registrar.cpp:427] Successfully updated 'registry'
I0424 21:52:51.361783 16664 log.cpp:699] Attempting to truncate the log to 3
I0424 21:52:51.361783 16663 master.cpp:2164] Admitted slave on juno.apache.org at slave(146)@67.195.138.61:59407
I0424 21:52:51.361811 16663 master.cpp:3220] Adding slave 20140424-215251-1032504131-59407-16552-0 at juno.apache.org with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0424 21:52:51.361865 16665 coordinator.cpp:339] Coordinator attempting to write TRUNCATE action at position 4
I0424 21:52:51.361901 16660 slave.cpp:540] Registered with master master@67.195.138.61:59407; given slave ID 20140424-215251-1032504131-59407-16552-0
I0424 21:52:51.362048 16660 slave.cpp:553] Checkpointing SlaveInfo to '/tmp/SlaveRecoveryTest_0_RecoverSlaveState_5ixOwr/meta/slaves/20140424-215251-1032504131-59407-16552-0/slave.info'
I0424 21:52:51.362063 16665 hierarchical_allocator_process.hpp:445] Added slave 20140424-215251-1032504131-59407-16552-0 (juno.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
I0424 21:52:51.362120 16659 replica.cpp:508] Replica received write request for position 4
I0424 21:52:51.362131 16665 hierarchical_allocator_process.hpp:752] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140424-215251-1032504131-59407-16552-0 to framework 20140424-215251-1032504131-59407-16552-0000
I0424 21:52:51.362277 16665 hierarchical_allocator_process.hpp:708] Performed allocation for slave 20140424-215251-1032504131-59407-16552-0 in 174053ns
I0424 21:52:51.362339 16664 master.hpp:584] Adding offer 20140424-215251-1032504131-59407-16552-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140424-215251-1032504131-59407-16552-0 (juno.apache.org)
I0424 21:52:51.362396 16664 master.cpp:2692] Sending 1 offers to framework 20140424-215251-1032504131-59407-16552-0000
I0424 21:52:51.362530 16663 sched.cpp:529] Scheduler::resourceOffers took 26273ns
I0424 21:52:51.364027 16663 master.hpp:594] Removing offer 20140424-215251-1032504131-59407-16552-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140424-215251-1032504131-59407-16552-0 (juno.apache.org)
I0424 21:52:51.364086 16663 master.cpp:1827] Processing reply for offers: [ 20140424-215251-1032504131-59407-16552-0 ] on slave 20140424-215251-1032504131-59407-16552-0 (juno.apache.org) for framework 20140424-215251-1032504131-59407-16552-0000
I0424 21:52:51.364181 16663 master.hpp:556] Adding task 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140424-215251-1032504131-59407-16552-0 (juno.apache.org)
I0424 21:52:51.364240 16663 master.cpp:2855] Launching task 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework 20140424-215251-1032504131-59407-16552-0000 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140424-215251-1032504131-59407-16552-0 (juno.apache.org)
I0424 21:52:51.364332 16666 slave.cpp:765] Got assigned task 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 for framework 20140424-215251-1032504131-59407-16552-0000
I0424 21:52:51.364433 16666 slave.cpp:2941] Checkpointing FrameworkInfo to '/tmp/SlaveRecoveryTest_0_RecoverSlaveState_5ixOwr/meta/slaves/20140424-215251-1032504131-59407-16552-0/frameworks/20140424-215251-1032504131-59407-16552-0000/framework.info'
I0424 21:52:51.364609 16666 slave.cpp:2948] Checkpointing framework pid 'scheduler(138)@67.195.138.61:59407' to '/tmp/SlaveRecoveryTest_0_RecoverSlaveState_5ixOwr/meta/slaves/20140424-215251-1032504131-59407-16552-0/frameworks/20140424-215251-1032504131-59407-16552-0000/framework.pid'
I0424 21:52:51.364851 16666 slave.cpp:874] Launching task 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 for framework 20140424-215251-1032504131-59407-16552-0000
I0424 21:52:51.366386 16666 slave.cpp:3255] Checkpointing ExecutorInfo to '/tmp/SlaveRecoveryTest_0_RecoverSlaveState_5ixOwr/meta/slaves/20140424-215251-1032504131-59407-16552-0/frameworks/20140424-215251-1032504131-59407-16552-0000/executors/6a516821-c5c6-4ef5-bb5c-1c00d6c6c829/executor.info'
I0424 21:52:51.366834 16666 slave.cpp:3352] Checkpointing TaskInfo to '/tmp/SlaveRecoveryTest_0_RecoverSlaveState_5ixOwr/meta/slaves/20140424-215251-1032504131-59407-16552-0/frameworks/20140424-215251-1032504131-59407-16552-0000/executors/6a516821-c5c6-4ef5-bb5c-1c00d6c6c829/runs/f2172d63-4422-456c-a15d-4a05020c42aa/tasks/6a516821-c5c6-4ef5-bb5c-1c00d6c6c829/task.info'
I0424 21:52:51.366843 16662 mesos_containerizer.cpp:413] Starting container 'f2172d63-4422-456c-a15d-4a05020c42aa' for executor '6a516821-c5c6-4ef5-bb5c-1c00d6c6c829' of framework '20140424-215251-1032504131-59407-16552-0000'
I0424 21:52:51.366984 16666 slave.cpp:984] Queuing task '6a516821-c5c6-4ef5-bb5c-1c00d6c6c829' for executor 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework '20140424-215251-1032504131-59407-16552-0000
I0424 21:52:51.367043 16666 slave.cpp:458] Successfully attached file '/tmp/SlaveRecoveryTest_0_RecoverSlaveState_5ixOwr/slaves/20140424-215251-1032504131-59407-16552-0/frameworks/20140424-215251-1032504131-59407-16552-0000/executors/6a516821-c5c6-4ef5-bb5c-1c00d6c6c829/runs/f2172d63-4422-456c-a15d-4a05020c42aa'
I0424 21:52:51.367431 16662 mesos_containerizer.cpp:555] Fetching URIs for container 'f2172d63-4422-456c-a15d-4a05020c42aa' using command '<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/ws/build/mesos-0.19.0/_build/src/mesos-fetcher'>
I0424 21:52:51.371083 16659 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 8.862219ms
I0424 21:52:51.371178 16659 replica.cpp:664] Persisted action at 4
I0424 21:52:51.377100 16664 replica.cpp:643] Replica received learned notice for position 4
I0424 21:52:51.386318 16664 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 9.179794ms
I0424 21:52:51.386373 16664 leveldb.cpp:399] Deleting ~2 keys from leveldb took 23648ns
I0424 21:52:51.386385 16664 replica.cpp:664] Persisted action at 4
I0424 21:52:51.386399 16664 replica.cpp:649] Replica learned TRUNCATE action at position 4
I0424 21:52:51.681949 16665 launcher.cpp:117] Forked child with pid '22018' for container 'f2172d63-4422-456c-a15d-4a05020c42aa'
I0424 21:52:51.682153 16665 mesos_containerizer.cpp:650] Checkpointing executor's forked pid 22018 to '/tmp/SlaveRecoveryTest_0_RecoverSlaveState_5ixOwr/meta/slaves/20140424-215251-1032504131-59407-16552-0/frameworks/20140424-215251-1032504131-59407-16552-0000/executors/6a516821-c5c6-4ef5-bb5c-1c00d6c6c829/runs/f2172d63-4422-456c-a15d-4a05020c42aa/pids/forked.pid'
I0424 21:52:51.683718 16666 slave.cpp:2141] Monitoring executor '6a516821-c5c6-4ef5-bb5c-1c00d6c6c829' of framework '20140424-215251-1032504131-59407-16552-0000' in container 'f2172d63-4422-456c-a15d-4a05020c42aa'
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0424 21:52:51.730275 22021 process.cpp:1601] libprocess is initialized on 67.195.138.61:53773 for 8 cpus
Command terminated with signal Terminated (pid: 21975)
I0424 21:52:51.731451 22021 exec.cpp:131] Version: 0.19.0
I0424 21:52:51.732118 21966 exec.cpp:524] Executor sending status update TASK_KILLED (UUID: 52e28047-bc62-408e-ab69-9122f339de8f) for task 23d66755-753f-40f5-83cf-76992fe4bf50 of framework 20140424-215248-1032504131-59407-16552-0000
I0424 21:52:51.733001 22037 exec.cpp:181] Executor started at: executor(1)@67.195.138.61:53773 with pid 22021
I0424 21:52:51.733633 16664 slave.cpp:1457] Got registration for executor '6a516821-c5c6-4ef5-bb5c-1c00d6c6c829' of framework 20140424-215251-1032504131-59407-16552-0000
I0424 21:52:51.733744 16664 slave.cpp:1542] Checkpointing executor pid 'executor(1)@67.195.138.61:53773' to '/tmp/SlaveRecoveryTest_0_RecoverSlaveState_5ixOwr/meta/slaves/20140424-215251-1032504131-59407-16552-0/frameworks/20140424-215251-1032504131-59407-16552-0000/executors/6a516821-c5c6-4ef5-bb5c-1c00d6c6c829/runs/f2172d63-4422-456c-a15d-4a05020c42aa/pids/libprocess.pid'
I0424 21:52:51.734310 16664 slave.cpp:1576] Flushing queued task 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 for executor '6a516821-c5c6-4ef5-bb5c-1c00d6c6c829' of framework 20140424-215251-1032504131-59407-16552-0000
I0424 21:52:51.734566 22043 process.cpp:1013] Socket closed while receiving
I0424 21:52:51.734678 22040 exec.cpp:205] Executor registered on slave 20140424-215251-1032504131-59407-16552-0
I0424 21:52:51.734776 22043 process.cpp:1013] Socket closed while receiving
I0424 21:52:51.735730 22040 exec.cpp:217] Executor::registered took 108076ns
Registered executor on juno.apache.org
I0424 21:52:51.735842 22040 exec.cpp:292] Executor asked to run task '6a516821-c5c6-4ef5-bb5c-1c00d6c6c829'
IStarting task 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829
0424 21:52:51.735903 22040 exec.cpp:301] Executor::launchTask took 46177ns
Forked command at 22044
sh -c 'sleep 1000'
I0424 21:52:51.737665 22038 exec.cpp:524] Executor sending status update TASK_RUNNING (UUID: ad0c5b1f-ebdd-4e91-98a0-d2dc97e9a71f) for task 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework 20140424-215251-1032504131-59407-16552-0000
I0424 21:52:51.737987 16664 slave.cpp:1812] Handling status update TASK_RUNNING (UUID: ad0c5b1f-ebdd-4e91-98a0-d2dc97e9a71f) for task 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework 20140424-215251-1032504131-59407-16552-0000 from executor(1)@67.195.138.61:53773
I0424 21:52:51.738126 16666 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: ad0c5b1f-ebdd-4e91-98a0-d2dc97e9a71f) for task 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework 20140424-215251-1032504131-59407-16552-0000
I0424 21:52:51.738152 16666 status_update_manager.cpp:499] Creating StatusUpdate stream for task 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework 20140424-215251-1032504131-59407-16552-0000
I0424 21:52:51.738361 16666 status_update_manager.hpp:342] Checkpointing UPDATE for status update TASK_RUNNING (UUID: ad0c5b1f-ebdd-4e91-98a0-d2dc97e9a71f) for task 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework 20140424-215251-1032504131-59407-16552-0000
I0424 21:52:51.825945 16666 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: ad0c5b1f-ebdd-4e91-98a0-d2dc97e9a71f) for task 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework 20140424-215251-1032504131-59407-16552-0000 to master@67.195.138.61:59407
I0424 21:52:51.826139 16665 master.cpp:2398] Status update TASK_RUNNING (UUID: ad0c5b1f-ebdd-4e91-98a0-d2dc97e9a71f) for task 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework 20140424-215251-1032504131-59407-16552-0000 from slave(146)@67.195.138.61:59407
I0424 21:52:51.826163 16663 slave.cpp:1929] Status update manager successfully handled status update TASK_RUNNING (UUID: ad0c5b1f-ebdd-4e91-98a0-d2dc97e9a71f) for task 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework 20140424-215251-1032504131-59407-16552-0000
I0424 21:52:51.826191 16663 slave.cpp:1935] Sending acknowledgement for status update TASK_RUNNING (UUID: ad0c5b1f-ebdd-4e91-98a0-d2dc97e9a71f) for task 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework 20140424-215251-1032504131-59407-16552-0000 to executor(1)@67.195.138.61:53773
I0424 21:52:51.826297 16666 sched.cpp:620] Scheduler::statusUpdate took 9852ns
I0424 21:52:51.826486 22043 process.cpp:1013] Socket closed while receiving
I0424 21:52:51.826505 22039 exec.cpp:338] Executor received status update acknowledgement ad0c5b1f-ebdd-4e91-98a0-d2dc97e9a71f for task 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework 20140424-215251-1032504131-59407-16552-0000
I0424 21:52:51.826638 16666 status_update_manager.cpp:398] Received status update acknowledgement (UUID: ad0c5b1f-ebdd-4e91-98a0-d2dc97e9a71f) for task 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework 20140424-215251-1032504131-59407-16552-0000
I0424 21:52:51.826663 16666 status_update_manager.hpp:342] Checkpointing ACK for status update TASK_RUNNING (UUID: ad0c5b1f-ebdd-4e91-98a0-d2dc97e9a71f) for task 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework 20140424-215251-1032504131-59407-16552-0000
I0424 21:52:51.859483 16666 slave.cpp:1397] Status update manager successfully handled status update acknowledgement (UUID: ad0c5b1f-ebdd-4e91-98a0-d2dc97e9a71f) for task 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework 20140424-215251-1032504131-59407-16552-0000
I0424 21:52:51.859616 16552 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_RecoverSlaveState_5ixOwr/meta'
I0424 21:52:51.860822 16666 sched.cpp:731] Stopping framework '20140424-215251-1032504131-59407-16552-0000'
I0424 21:52:51.860838 16552 master.cpp:577] Master terminating
I0424 21:52:51.860882 22043 process.cpp:1013] Socket closed while receiving
I0424 21:52:51.860931 16552 master.hpp:574] Removing task 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140424-215251-1032504131-59407-16552-0 (juno.apache.org)
I0424 21:52:51.861032 22042 exec.cpp:378] Executor asked to shutdown
I0424 21:52:51.861090 22042 exec.cpp:393] Executor::shutdown took 9876ns
IShutting down
0424 21:52:51.861109 22042 exec.cpp:77] Scheduling shutdown of the executor
Sending SIGTERM to process tree at pid 22044
I0424 21:52:51.861351 16659 slave.cpp:2010] master@67.195.138.61:59407 exited
W0424 21:52:51.861376 16659 slave.cpp:2013] Master disconnected! Waiting for a new master to be elected
I0424 21:52:51.861371 16662 hierarchical_allocator_process.hpp:637] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20140424-215251-1032504131-59407-16552-0 from framework 20140424-215251-1032504131-59407-16552-0000
I0424 21:52:51.862850 16552 slave.cpp:387] Slave terminating
[ OK ] SlaveRecoveryTest/0.RecoverSlaveState (723 ms)
[----------] 24 tests from SlaveRecoveryTest/0 (57722 ms total)
[----------] 7 tests from InMemoryStateTest
[ RUN ] InMemoryStateTest.Names
[ OK ] InMemoryStateTest.Names (3 ms)
[ RUN ] InMemoryStateTest.FetchAndStoreAndExpungeAndFetch
[ OK ] InMemoryStateTest.FetchAndStoreAndExpungeAndFetch (4 ms)
[ RUN ] InMemoryStateTest.FetchAndStoreAndExpungeAndStoreAndFetch
[ OK ] InMemoryStateTest.FetchAndStoreAndExpungeAndStoreAndFetch (5 ms)
[ RUN ] InMemoryStateTest.FetchAndStoreAndExpungeAndExpunge
[ OK ] InMemoryStateTest.FetchAndStoreAndExpungeAndExpunge (2 ms)
[ RUN ] InMemoryStateTest.FetchAndStoreAndStoreFailAndFetch
[ OK ] InMemoryStateTest.FetchAndStoreAndStoreFailAndFetch (4 ms)
[ RUN ] InMemoryStateTest.FetchAndStoreAndFetch
[ OK ] InMemoryStateTest.FetchAndStoreAndFetch (2 ms)
[ RUN ] InMemoryStateTest.FetchAndStoreAndStoreAndFetch
Killing the following process trees:
[
-+- 22044 sh -c sleep 1000
\--- 22045 sleep 1000
]
[ OK ] InMemoryStateTest.FetchAndStoreAndStoreAndFetch (5 ms)
[----------] 7 tests from InMemoryStateTest (25 ms total)
[----------] Global test environment tear-down
../../src/tests/environment.cpp:258: Failure
Failed
Tests completed with child processes remaining:
-+- 16552 <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/ws/build/mesos-0.19.0/_build/src/.libs/lt-mesos-tests>
|-+- 21949 sh -c <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/ws/build/mesos-0.19.0/_build/src/mesos-executor>
| \--- 21952 <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/ws/build/mesos-0.19.0/_build/src/.libs/lt-mesos-executor>
\-+- 22018 sh -c <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/ws/build/mesos-0.19.0/_build/src/mesos-executor>
\-+- 22021 <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/ws/build/mesos-0.19.0/_build/src/.libs/lt-mesos-executor>
\--- 22044 ()
[==========] 299 tests from 51 test cases ran. (337401 ms total)
[ PASSED ] 299 tests.
[ FAILED ] 0 tests, listed below:
0 FAILED TESTS
YOU HAVE 1 DISABLED TEST
I0424 21:52:51.966599 21974 process.cpp:1013] Socket closed while receiving
I0424 21:52:51.966624 22043 process.cpp:1013] Socket closed while receiving
I0424 21:52:51.966701 21970 exec.cpp:439] Ignoring exited event because the driver is aborted!
I0424 21:52:51.966728 21970 exec.cpp:439] Ignoring exited event because the driver is aborted!
I0424 21:52:51.966737 22042 exec.cpp:439] Ignoring exited event because the driver is aborted!
make[4]: *** [check-local] Error 1
make[4]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/ws/build/mesos-0.19.0/_build/src'>
make[3]: *** [check-am] Error 2
make[3]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/ws/build/mesos-0.19.0/_build/src'>
make[2]: *** [check] Error 2
make[2]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/ws/build/mesos-0.19.0/_build/src'>
make[1]: *** [check-recursive] Error 1
make[1]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/ws/build/mesos-0.19.0/_build'>
make: *** [distcheck] Error 1
Command terminated with signal Terminated (pid: 22044)
Build step 'Execute shell' marked build as failure
Re: Build failed in Jenkins: Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME
#2087
Posted by Vinod Kone <vi...@twitter.com>.
this should be fixed by https://reviews.apache.org/r/20430/
@vinodkone
On Thu, Apr 24, 2014 at 2:52 PM, Apache Jenkins Server <
jenkins@builds.apache.org> wrote:
> See <
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/2087/changes
> >
>
> Changes:
>
> [bmahler] Added a missing call to delete on the RegistrarProcess.
>
> [vinod] Renamed and moved MasterZooKeeperTest fixture.
>
> [vinod] Integrated log storage into master.
>
> [bmahler] Manipulated clock in metric tests to avoid rate limiting.
>
> [bmahler] Added message counters and a counter for slave timeouts during
> recovery in Master.
>
> [niklas] Updated containerizer.proto's Launch message, added Destroy-,
> Wait- and Usage-messages.
>
> ------------------------------------------
> [...truncated 42723 lines...]
> I0424 21:52:51.273568 16662 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 20.179263ms
> I0424 21:52:51.273624 16662 replica.cpp:320] Persisted replica status to
> STARTING
> I0424 21:52:51.273764 16663 recover.cpp:451] Replica is in STARTING status
> I0424 21:52:51.274024 16664 replica.cpp:626] Replica in STARTING status
> received a broadcasted recover request
> I0424 21:52:51.274149 16663 recover.cpp:188] Received a recover response
> from a replica in STARTING status
> I0424 21:52:51.274288 16659 recover.cpp:542] Updating replica status to
> VOTING
> I0424 21:52:51.278003 16663 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 3.659359ms
> I0424 21:52:51.278024 16663 replica.cpp:320] Persisted replica status to
> VOTING
> I0424 21:52:51.278082 16659 recover.cpp:556] Successfully joined the Paxos
> group
> I0424 21:52:51.278192 16659 recover.cpp:440] Recover process terminated
> I0424 21:52:51.278360 16666 log.cpp:656] Attempting to start the writer
> I0424 21:52:51.278813 16660 replica.cpp:474] Replica received implicit
> promise request with proposal 1
> I0424 21:52:51.286348 16660 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 7.51685ms
> I0424 21:52:51.286365 16660 replica.cpp:342] Persisted promised to 1
> I0424 21:52:51.286664 16663 coordinator.cpp:229] Coordinator attemping to
> fill missing position
> I0424 21:52:51.287245 16665 replica.cpp:375] Replica received explicit
> promise request for position 0 with proposal 2
> I0424 21:52:51.294661 16665 leveldb.cpp:341] Persisting action (8 bytes)
> to leveldb took 7.398646ms
> I0424 21:52:51.294679 16665 replica.cpp:664] Persisted action at 0
> I0424 21:52:51.295120 16660 replica.cpp:508] Replica received write
> request for position 0
> I0424 21:52:51.295146 16660 leveldb.cpp:436] Reading position from leveldb
> took 11388ns
> I0424 21:52:51.303009 16660 leveldb.cpp:341] Persisting action (14 bytes)
> to leveldb took 7.84837ms
> I0424 21:52:51.303026 16660 replica.cpp:664] Persisted action at 0
> I0424 21:52:51.303269 16659 replica.cpp:643] Replica received learned
> notice for position 0
> I0424 21:52:51.311322 16659 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 8.036591ms
> I0424 21:52:51.311346 16659 replica.cpp:664] Persisted action at 0
> I0424 21:52:51.311355 16659 replica.cpp:649] Replica learned NOP action at
> position 0
> I0424 21:52:51.311578 16660 log.cpp:672] Writer started with ending
> position 0
> I0424 21:52:51.312005 16659 leveldb.cpp:436] Reading position from leveldb
> took 16226ns
> I0424 21:52:51.313616 16661 registrar.cpp:308] Successfully recovered
> registrar
> I0424 21:52:51.313642 16661 registrar.cpp:379] Attempting to update the
> 'registry'
> I0424 21:52:51.315104 16661 log.cpp:680] Attempting to append 137 bytes to
> the log
> I0424 21:52:51.315181 16665 coordinator.cpp:339] Coordinator attempting to
> write APPEND action at position 1
> I0424 21:52:51.315495 16659 replica.cpp:508] Replica received write
> request for position 1
> I0424 21:52:51.319648 16659 leveldb.cpp:341] Persisting action (156 bytes)
> to leveldb took 4.134342ms
> I0424 21:52:51.319666 16659 replica.cpp:664] Persisted action at 1
> I0424 21:52:51.319900 16661 replica.cpp:643] Replica received learned
> notice for position 1
> I0424 21:52:51.327982 16661 leveldb.cpp:341] Persisting action (158 bytes)
> to leveldb took 8.049144ms
> I0424 21:52:51.327999 16661 replica.cpp:664] Persisted action at 1
> I0424 21:52:51.328007 16661 replica.cpp:649] Replica learned APPEND action
> at position 1
> I0424 21:52:51.328378 16660 registrar.cpp:427] Successfully updated
> 'registry'
> I0424 21:52:51.328543 16665 log.cpp:699] Attempting to truncate the log to
> 1
> I0424 21:52:51.328601 16665 coordinator.cpp:339] Coordinator attempting to
> write TRUNCATE action at position 2
> I0424 21:52:51.328605 16666 master.cpp:806] Recovered 0 slaves from the
> Registry (99B) ; allowing 10mins for slaves to re-register
> I0424 21:52:51.328938 16661 replica.cpp:508] Replica received write
> request for position 2
> I0424 21:52:51.329237 16552 containerizer.cpp:177] Using isolation:
> posix/cpu,posix/mem
> I0424 21:52:51.330973 16659 slave.cpp:130] Slave started on 146)@
> 67.195.138.61:59407
> I0424 21:52:51.331105 16659 slave.cpp:218] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0424 21:52:51.331178 16659 slave.cpp:246] Slave hostname: juno.apache.org
> I0424 21:52:51.331190 16659 slave.cpp:247] Slave checkpoint: true
> I0424 21:52:51.331764 16666 state.cpp:33] Recovering state from
> '/tmp/SlaveRecoveryTest_0_RecoverSlaveState_5ixOwr/meta'
> I0424 21:52:51.331897 16663 status_update_manager.cpp:193] Recovering
> status update manager
> I0424 21:52:51.331982 16663 mesos_containerizer.cpp:199] Recovering
> containerizer
> I0424 21:52:51.332229 16666 slave.cpp:2802] Finished recovery
> I0424 21:52:51.332546 16666 slave.cpp:497] New master detected at
> master@67.195.138.61:59407
> I0424 21:52:51.332607 16666 slave.cpp:731] Will retry registration in
> 7.264555526secs if necessary
> I0424 21:52:51.332625 16662 status_update_manager.cpp:167] New master
> detected at master@67.195.138.61:59407
> I0424 21:52:51.332631 16666 slave.cpp:522] Detecting new master
> I0424 21:52:51.332801 16666 registrar.cpp:379] Attempting to update the
> 'registry'
> I0424 21:52:51.332936 16552 sched.cpp:121] Version: 0.19.0
> I0424 21:52:51.333214 16665 sched.cpp:217] New master detected at
> master@67.195.138.61:59407
> I0424 21:52:51.333237 16665 sched.cpp:268] Authenticating with master
> master@67.195.138.61:59407
> I0424 21:52:51.333330 16659 authenticatee.hpp:128] Creating new client
> SASL connection
> I0424 21:52:51.333462 16665 master.cpp:2731] Authenticating framework at
> scheduler(138)@67.195.138.61:59407
> I0424 21:52:51.333534 16659 authenticator.hpp:148] Creating new server
> SASL connection
> I0424 21:52:51.333644 16659 authenticatee.hpp:219] Received SASL
> authentication mechanisms: CRAM-MD5
> I0424 21:52:51.333662 16659 authenticatee.hpp:245] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> I0424 21:52:51.333696 16659 authenticator.hpp:254] Received SASL
> authentication start
> I0424 21:52:51.333746 16659 authenticator.hpp:342] Authentication requires
> more steps
> I0424 21:52:51.333781 16659 authenticatee.hpp:265] Received SASL
> authentication step
> I0424 21:52:51.333829 16659 authenticator.hpp:282] Received SASL
> authentication step
> I0424 21:52:51.333850 16659 auxprop.cpp:81] Request to lookup properties
> for user: 'test-principal' realm: 'juno.apache.org' server FQDN: '
> juno.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0424 21:52:51.333860 16659 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I0424 21:52:51.333873 16659 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0424 21:52:51.333886 16659 auxprop.cpp:81] Request to lookup properties
> for user: 'test-principal' realm: 'juno.apache.org' server FQDN: '
> juno.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0424 21:52:51.333894 16659 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0424 21:52:51.333900 16659 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0424 21:52:51.333914 16659 authenticator.hpp:334] Authentication success
> I0424 21:52:51.333951 16659 authenticatee.hpp:305] Authentication success
> I0424 21:52:51.333979 16662 master.cpp:2771] Successfully authenticated
> framework at scheduler(138)@67.195.138.61:59407
> I0424 21:52:51.334007 16659 sched.cpp:342] Successfully authenticated with
> master master@67.195.138.61:59407
> I0424 21:52:51.334031 16659 sched.cpp:461] Sending registration request to
> master@67.195.138.61:59407
> I0424 21:52:51.334125 16662 master.cpp:1007] Received registration request
> from scheduler(138)@67.195.138.61:59407
> I0424 21:52:51.334161 16662 master.cpp:1025] Registering framework
> 20140424-215251-1032504131-59407-16552-0000 at scheduler(138)@
> 67.195.138.61:59407
> I0424 21:52:51.334233 16662 sched.cpp:392] Framework registered with
> 20140424-215251-1032504131-59407-16552-0000
> I0424 21:52:51.334255 16662 sched.cpp:406] Scheduler::registered took
> 10055ns
> I0424 21:52:51.334292 16662 hierarchical_allocator_process.hpp:332] Added
> framework 20140424-215251-1032504131-59407-16552-0000
> I0424 21:52:51.334303 16662 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0424 21:52:51.334310 16662 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 6927ns
> I0424 21:52:51.336307 16661 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 7.351389ms
> I0424 21:52:51.336325 16661 replica.cpp:664] Persisted action at 2
> I0424 21:52:51.336565 16659 replica.cpp:643] Replica received learned
> notice for position 2
> I0424 21:52:51.344638 16659 leveldb.cpp:341] Persisting action (18 bytes)
> to leveldb took 8.057296ms
> I0424 21:52:51.344666 16659 leveldb.cpp:399] Deleting ~1 keys from leveldb
> took 11442ns
> I0424 21:52:51.344677 16659 replica.cpp:664] Persisted action at 2
> I0424 21:52:51.344686 16659 replica.cpp:649] Replica learned TRUNCATE
> action at position 2
> I0424 21:52:51.344959 16659 log.cpp:680] Attempting to append 328 bytes to
> the log
> I0424 21:52:51.345023 16662 coordinator.cpp:339] Coordinator attempting to
> write APPEND action at position 3
> I0424 21:52:51.345324 16665 replica.cpp:508] Replica received write
> request for position 3
> I0424 21:52:51.352964 16665 leveldb.cpp:341] Persisting action (347 bytes)
> to leveldb took 7.620106ms
> I0424 21:52:51.352983 16665 replica.cpp:664] Persisted action at 3
> I0424 21:52:51.353257 16666 replica.cpp:643] Replica received learned
> notice for position 3
> I0424 21:52:51.361295 16666 leveldb.cpp:341] Persisting action (349 bytes)
> to leveldb took 8.021148ms
> I0424 21:52:51.361315 16666 replica.cpp:664] Persisted action at 3
> I0424 21:52:51.361323 16666 replica.cpp:649] Replica learned APPEND action
> at position 3
> I0424 21:52:51.361652 16664 registrar.cpp:427] Successfully updated
> 'registry'
> I0424 21:52:51.361783 16664 log.cpp:699] Attempting to truncate the log to
> 3
> I0424 21:52:51.361783 16663 master.cpp:2164] Admitted slave on
> juno.apache.org at slave(146)@67.195.138.61:59407
> I0424 21:52:51.361811 16663 master.cpp:3220] Adding slave
> 20140424-215251-1032504131-59407-16552-0 at juno.apache.org with
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0424 21:52:51.361865 16665 coordinator.cpp:339] Coordinator attempting to
> write TRUNCATE action at position 4
> I0424 21:52:51.361901 16660 slave.cpp:540] Registered with master
> master@67.195.138.61:59407; given slave ID
> 20140424-215251-1032504131-59407-16552-0
> I0424 21:52:51.362048 16660 slave.cpp:553] Checkpointing SlaveInfo to
> '/tmp/SlaveRecoveryTest_0_RecoverSlaveState_5ixOwr/meta/slaves/20140424-215251-1032504131-59407-16552-0/
> slave.info'
> I0424 21:52:51.362063 16665 hierarchical_allocator_process.hpp:445] Added
> slave 20140424-215251-1032504131-59407-16552-0 (juno.apache.org) with
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I0424 21:52:51.362120 16659 replica.cpp:508] Replica received write
> request for position 4
> I0424 21:52:51.362131 16665 hierarchical_allocator_process.hpp:752]
> Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on
> slave 20140424-215251-1032504131-59407-16552-0 to framework
> 20140424-215251-1032504131-59407-16552-0000
> I0424 21:52:51.362277 16665 hierarchical_allocator_process.hpp:708]
> Performed allocation for slave 20140424-215251-1032504131-59407-16552-0 in
> 174053ns
> I0424 21:52:51.362339 16664 master.hpp:584] Adding offer
> 20140424-215251-1032504131-59407-16552-0 with resources cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140424-215251-1032504131-59407-16552-0 (juno.apache.org)
> I0424 21:52:51.362396 16664 master.cpp:2692] Sending 1 offers to framework
> 20140424-215251-1032504131-59407-16552-0000
> I0424 21:52:51.362530 16663 sched.cpp:529] Scheduler::resourceOffers took
> 26273ns
> I0424 21:52:51.364027 16663 master.hpp:594] Removing offer
> 20140424-215251-1032504131-59407-16552-0 with resources cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140424-215251-1032504131-59407-16552-0 (juno.apache.org)
> I0424 21:52:51.364086 16663 master.cpp:1827] Processing reply for offers:
> [ 20140424-215251-1032504131-59407-16552-0 ] on slave
> 20140424-215251-1032504131-59407-16552-0 (juno.apache.org) for framework
> 20140424-215251-1032504131-59407-16552-0000
> I0424 21:52:51.364181 16663 master.hpp:556] Adding task
> 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140424-215251-1032504131-59407-16552-0 (juno.apache.org)
> I0424 21:52:51.364240 16663 master.cpp:2855] Launching task
> 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework
> 20140424-215251-1032504131-59407-16552-0000 with resources cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140424-215251-1032504131-59407-16552-0 (juno.apache.org)
> I0424 21:52:51.364332 16666 slave.cpp:765] Got assigned task
> 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 for framework
> 20140424-215251-1032504131-59407-16552-0000
> I0424 21:52:51.364433 16666 slave.cpp:2941] Checkpointing FrameworkInfo to
> '/tmp/SlaveRecoveryTest_0_RecoverSlaveState_5ixOwr/meta/slaves/20140424-215251-1032504131-59407-16552-0/frameworks/20140424-215251-1032504131-59407-16552-0000/
> framework.info'
> I0424 21:52:51.364609 16666 slave.cpp:2948] Checkpointing framework pid
> 'scheduler(138)@67.195.138.61:59407' to
> '/tmp/SlaveRecoveryTest_0_RecoverSlaveState_5ixOwr/meta/slaves/20140424-215251-1032504131-59407-16552-0/frameworks/20140424-215251-1032504131-59407-16552-0000/framework.pid'
> I0424 21:52:51.364851 16666 slave.cpp:874] Launching task
> 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 for framework
> 20140424-215251-1032504131-59407-16552-0000
> I0424 21:52:51.366386 16666 slave.cpp:3255] Checkpointing ExecutorInfo to
> '/tmp/SlaveRecoveryTest_0_RecoverSlaveState_5ixOwr/meta/slaves/20140424-215251-1032504131-59407-16552-0/frameworks/20140424-215251-1032504131-59407-16552-0000/executors/6a516821-c5c6-4ef5-bb5c-1c00d6c6c829/
> executor.info'
> I0424 21:52:51.366834 16666 slave.cpp:3352] Checkpointing TaskInfo to
> '/tmp/SlaveRecoveryTest_0_RecoverSlaveState_5ixOwr/meta/slaves/20140424-215251-1032504131-59407-16552-0/frameworks/20140424-215251-1032504131-59407-16552-0000/executors/6a516821-c5c6-4ef5-bb5c-1c00d6c6c829/runs/f2172d63-4422-456c-a15d-4a05020c42aa/tasks/6a516821-c5c6-4ef5-bb5c-1c00d6c6c829/
> task.info'
> I0424 21:52:51.366843 16662 mesos_containerizer.cpp:413] Starting
> container 'f2172d63-4422-456c-a15d-4a05020c42aa' for executor
> '6a516821-c5c6-4ef5-bb5c-1c00d6c6c829' of framework
> '20140424-215251-1032504131-59407-16552-0000'
> I0424 21:52:51.366984 16666 slave.cpp:984] Queuing task
> '6a516821-c5c6-4ef5-bb5c-1c00d6c6c829' for executor
> 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework
> '20140424-215251-1032504131-59407-16552-0000
> I0424 21:52:51.367043 16666 slave.cpp:458] Successfully attached file
> '/tmp/SlaveRecoveryTest_0_RecoverSlaveState_5ixOwr/slaves/20140424-215251-1032504131-59407-16552-0/frameworks/20140424-215251-1032504131-59407-16552-0000/executors/6a516821-c5c6-4ef5-bb5c-1c00d6c6c829/runs/f2172d63-4422-456c-a15d-4a05020c42aa'
> I0424 21:52:51.367431 16662 mesos_containerizer.cpp:555] Fetching URIs for
> container 'f2172d63-4422-456c-a15d-4a05020c42aa' using command '<
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/ws/build/mesos-0.19.0/_build/src/mesos-fetcher
> '>
> I0424 21:52:51.371083 16659 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 8.862219ms
> I0424 21:52:51.371178 16659 replica.cpp:664] Persisted action at 4
> I0424 21:52:51.377100 16664 replica.cpp:643] Replica received learned
> notice for position 4
> I0424 21:52:51.386318 16664 leveldb.cpp:341] Persisting action (18 bytes)
> to leveldb took 9.179794ms
> I0424 21:52:51.386373 16664 leveldb.cpp:399] Deleting ~2 keys from leveldb
> took 23648ns
> I0424 21:52:51.386385 16664 replica.cpp:664] Persisted action at 4
> I0424 21:52:51.386399 16664 replica.cpp:649] Replica learned TRUNCATE
> action at position 4
> I0424 21:52:51.681949 16665 launcher.cpp:117] Forked child with pid
> '22018' for container 'f2172d63-4422-456c-a15d-4a05020c42aa'
> I0424 21:52:51.682153 16665 mesos_containerizer.cpp:650] Checkpointing
> executor's forked pid 22018 to
> '/tmp/SlaveRecoveryTest_0_RecoverSlaveState_5ixOwr/meta/slaves/20140424-215251-1032504131-59407-16552-0/frameworks/20140424-215251-1032504131-59407-16552-0000/executors/6a516821-c5c6-4ef5-bb5c-1c00d6c6c829/runs/f2172d63-4422-456c-a15d-4a05020c42aa/pids/forked.pid'
> I0424 21:52:51.683718 16666 slave.cpp:2141] Monitoring executor
> '6a516821-c5c6-4ef5-bb5c-1c00d6c6c829' of framework
> '20140424-215251-1032504131-59407-16552-0000' in container
> 'f2172d63-4422-456c-a15d-4a05020c42aa'
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0424 21:52:51.730275 22021 process.cpp:1601] libprocess is initialized on
> 67.195.138.61:53773 for 8 cpus
> Command terminated with signal Terminated (pid: 21975)
> I0424 21:52:51.731451 22021 exec.cpp:131] Version: 0.19.0
> I0424 21:52:51.732118 21966 exec.cpp:524] Executor sending status update
> TASK_KILLED (UUID: 52e28047-bc62-408e-ab69-9122f339de8f) for task
> 23d66755-753f-40f5-83cf-76992fe4bf50 of framework
> 20140424-215248-1032504131-59407-16552-0000
> I0424 21:52:51.733001 22037 exec.cpp:181] Executor started at: executor(1)@
> 67.195.138.61:53773 with pid 22021
> I0424 21:52:51.733633 16664 slave.cpp:1457] Got registration for executor
> '6a516821-c5c6-4ef5-bb5c-1c00d6c6c829' of framework
> 20140424-215251-1032504131-59407-16552-0000
> I0424 21:52:51.733744 16664 slave.cpp:1542] Checkpointing executor pid
> 'executor(1)@67.195.138.61:53773' to
> '/tmp/SlaveRecoveryTest_0_RecoverSlaveState_5ixOwr/meta/slaves/20140424-215251-1032504131-59407-16552-0/frameworks/20140424-215251-1032504131-59407-16552-0000/executors/6a516821-c5c6-4ef5-bb5c-1c00d6c6c829/runs/f2172d63-4422-456c-a15d-4a05020c42aa/pids/libprocess.pid'
> I0424 21:52:51.734310 16664 slave.cpp:1576] Flushing queued task
> 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 for executor
> '6a516821-c5c6-4ef5-bb5c-1c00d6c6c829' of framework
> 20140424-215251-1032504131-59407-16552-0000
> I0424 21:52:51.734566 22043 process.cpp:1013] Socket closed while receiving
> I0424 21:52:51.734678 22040 exec.cpp:205] Executor registered on slave
> 20140424-215251-1032504131-59407-16552-0
> I0424 21:52:51.734776 22043 process.cpp:1013] Socket closed while receiving
> I0424 21:52:51.735730 22040 exec.cpp:217] Executor::registered took
> 108076ns
> Registered executor on juno.apache.org
> I0424 21:52:51.735842 22040 exec.cpp:292] Executor asked to run task
> '6a516821-c5c6-4ef5-bb5c-1c00d6c6c829'
> IStarting task 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829
> 0424 21:52:51.735903 22040 exec.cpp:301] Executor::launchTask took 46177ns
> Forked command at 22044
> sh -c 'sleep 1000'
> I0424 21:52:51.737665 22038 exec.cpp:524] Executor sending status update
> TASK_RUNNING (UUID: ad0c5b1f-ebdd-4e91-98a0-d2dc97e9a71f) for task
> 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework
> 20140424-215251-1032504131-59407-16552-0000
> I0424 21:52:51.737987 16664 slave.cpp:1812] Handling status update
> TASK_RUNNING (UUID: ad0c5b1f-ebdd-4e91-98a0-d2dc97e9a71f) for task
> 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework
> 20140424-215251-1032504131-59407-16552-0000 from executor(1)@
> 67.195.138.61:53773
> I0424 21:52:51.738126 16666 status_update_manager.cpp:320] Received status
> update TASK_RUNNING (UUID: ad0c5b1f-ebdd-4e91-98a0-d2dc97e9a71f) for task
> 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework
> 20140424-215251-1032504131-59407-16552-0000
> I0424 21:52:51.738152 16666 status_update_manager.cpp:499] Creating
> StatusUpdate stream for task 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of
> framework 20140424-215251-1032504131-59407-16552-0000
> I0424 21:52:51.738361 16666 status_update_manager.hpp:342] Checkpointing
> UPDATE for status update TASK_RUNNING (UUID:
> ad0c5b1f-ebdd-4e91-98a0-d2dc97e9a71f) for task
> 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework
> 20140424-215251-1032504131-59407-16552-0000
> I0424 21:52:51.825945 16666 status_update_manager.cpp:373] Forwarding
> status update TASK_RUNNING (UUID: ad0c5b1f-ebdd-4e91-98a0-d2dc97e9a71f) for
> task 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework
> 20140424-215251-1032504131-59407-16552-0000 to master@67.195.138.61:59407
> I0424 21:52:51.826139 16665 master.cpp:2398] Status update TASK_RUNNING
> (UUID: ad0c5b1f-ebdd-4e91-98a0-d2dc97e9a71f) for task
> 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework
> 20140424-215251-1032504131-59407-16552-0000 from slave(146)@
> 67.195.138.61:59407
> I0424 21:52:51.826163 16663 slave.cpp:1929] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> ad0c5b1f-ebdd-4e91-98a0-d2dc97e9a71f) for task
> 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework
> 20140424-215251-1032504131-59407-16552-0000
> I0424 21:52:51.826191 16663 slave.cpp:1935] Sending acknowledgement for
> status update TASK_RUNNING (UUID: ad0c5b1f-ebdd-4e91-98a0-d2dc97e9a71f) for
> task 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework
> 20140424-215251-1032504131-59407-16552-0000 to executor(1)@
> 67.195.138.61:53773
> I0424 21:52:51.826297 16666 sched.cpp:620] Scheduler::statusUpdate took
> 9852ns
> I0424 21:52:51.826486 22043 process.cpp:1013] Socket closed while receiving
> I0424 21:52:51.826505 22039 exec.cpp:338] Executor received status update
> acknowledgement ad0c5b1f-ebdd-4e91-98a0-d2dc97e9a71f for task
> 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework
> 20140424-215251-1032504131-59407-16552-0000
> I0424 21:52:51.826638 16666 status_update_manager.cpp:398] Received status
> update acknowledgement (UUID: ad0c5b1f-ebdd-4e91-98a0-d2dc97e9a71f) for
> task 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework
> 20140424-215251-1032504131-59407-16552-0000
> I0424 21:52:51.826663 16666 status_update_manager.hpp:342] Checkpointing
> ACK for status update TASK_RUNNING (UUID:
> ad0c5b1f-ebdd-4e91-98a0-d2dc97e9a71f) for task
> 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework
> 20140424-215251-1032504131-59407-16552-0000
> I0424 21:52:51.859483 16666 slave.cpp:1397] Status update manager
> successfully handled status update acknowledgement (UUID:
> ad0c5b1f-ebdd-4e91-98a0-d2dc97e9a71f) for task
> 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 of framework
> 20140424-215251-1032504131-59407-16552-0000
> I0424 21:52:51.859616 16552 state.cpp:33] Recovering state from
> '/tmp/SlaveRecoveryTest_0_RecoverSlaveState_5ixOwr/meta'
> I0424 21:52:51.860822 16666 sched.cpp:731] Stopping framework
> '20140424-215251-1032504131-59407-16552-0000'
> I0424 21:52:51.860838 16552 master.cpp:577] Master terminating
> I0424 21:52:51.860882 22043 process.cpp:1013] Socket closed while receiving
> I0424 21:52:51.860931 16552 master.hpp:574] Removing task
> 6a516821-c5c6-4ef5-bb5c-1c00d6c6c829 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140424-215251-1032504131-59407-16552-0 (juno.apache.org)
> I0424 21:52:51.861032 22042 exec.cpp:378] Executor asked to shutdown
> I0424 21:52:51.861090 22042 exec.cpp:393] Executor::shutdown took 9876ns
> IShutting down
> 0424 21:52:51.861109 22042 exec.cpp:77] Scheduling shutdown of the executor
> Sending SIGTERM to process tree at pid 22044
> I0424 21:52:51.861351 16659 slave.cpp:2010] master@67.195.138.61:59407exited
> W0424 21:52:51.861376 16659 slave.cpp:2013] Master disconnected! Waiting
> for a new master to be elected
> I0424 21:52:51.861371 16662 hierarchical_allocator_process.hpp:637]
> Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]) on slave 20140424-215251-1032504131-59407-16552-0
> from framework 20140424-215251-1032504131-59407-16552-0000
> I0424 21:52:51.862850 16552 slave.cpp:387] Slave terminating
> [ OK ] SlaveRecoveryTest/0.RecoverSlaveState (723 ms)
> [----------] 24 tests from SlaveRecoveryTest/0 (57722 ms total)
>
> [----------] 7 tests from InMemoryStateTest
> [ RUN ] InMemoryStateTest.Names
> [ OK ] InMemoryStateTest.Names (3 ms)
> [ RUN ] InMemoryStateTest.FetchAndStoreAndExpungeAndFetch
> [ OK ] InMemoryStateTest.FetchAndStoreAndExpungeAndFetch (4 ms)
> [ RUN ] InMemoryStateTest.FetchAndStoreAndExpungeAndStoreAndFetch
> [ OK ] InMemoryStateTest.FetchAndStoreAndExpungeAndStoreAndFetch (5
> ms)
> [ RUN ] InMemoryStateTest.FetchAndStoreAndExpungeAndExpunge
> [ OK ] InMemoryStateTest.FetchAndStoreAndExpungeAndExpunge (2 ms)
> [ RUN ] InMemoryStateTest.FetchAndStoreAndStoreFailAndFetch
> [ OK ] InMemoryStateTest.FetchAndStoreAndStoreFailAndFetch (4 ms)
> [ RUN ] InMemoryStateTest.FetchAndStoreAndFetch
> [ OK ] InMemoryStateTest.FetchAndStoreAndFetch (2 ms)
> [ RUN ] InMemoryStateTest.FetchAndStoreAndStoreAndFetch
> Killing the following process trees:
> [
> -+- 22044 sh -c sleep 1000
> \--- 22045 sleep 1000
> ]
> [ OK ] InMemoryStateTest.FetchAndStoreAndStoreAndFetch (5 ms)
> [----------] 7 tests from InMemoryStateTest (25 ms total)
>
> [----------] Global test environment tear-down
> ../../src/tests/environment.cpp:258: Failure
> Failed
> Tests completed with child processes remaining:
> -+- 16552 <
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/ws/build/mesos-0.19.0/_build/src/.libs/lt-mesos-tests
> >
> |-+- 21949 sh -c <
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/ws/build/mesos-0.19.0/_build/src/mesos-executor
> >
> | \--- 21952 <
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/ws/build/mesos-0.19.0/_build/src/.libs/lt-mesos-executor
> >
> \-+- 22018 sh -c <
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/ws/build/mesos-0.19.0/_build/src/mesos-executor
> >
> \-+- 22021 <
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/ws/build/mesos-0.19.0/_build/src/.libs/lt-mesos-executor
> >
> \--- 22044 ()
> [==========] 299 tests from 51 test cases ran. (337401 ms total)
> [ PASSED ] 299 tests.
> [ FAILED ] 0 tests, listed below:
>
> 0 FAILED TESTS
>
> YOU HAVE 1 DISABLED TEST
>
> I0424 21:52:51.966599 21974 process.cpp:1013] Socket closed while receiving
> I0424 21:52:51.966624 22043 process.cpp:1013] Socket closed while receiving
> I0424 21:52:51.966701 21970 exec.cpp:439] Ignoring exited event because
> the driver is aborted!
> I0424 21:52:51.966728 21970 exec.cpp:439] Ignoring exited event because
> the driver is aborted!
> I0424 21:52:51.966737 22042 exec.cpp:439] Ignoring exited event because
> the driver is aborted!
> make[4]: *** [check-local] Error 1
> make[4]: Leaving directory `<
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/ws/build/mesos-0.19.0/_build/src
> '>
> make[3]: *** [check-am] Error 2
> make[3]: Leaving directory `<
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/ws/build/mesos-0.19.0/_build/src
> '>
> make[2]: *** [check] Error 2
> make[2]: Leaving directory `<
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/ws/build/mesos-0.19.0/_build/src
> '>
> make[1]: *** [check-recursive] Error 1
> make[1]: Leaving directory `<
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/ws/build/mesos-0.19.0/_build
> '>
> make: *** [distcheck] Error 1
> Command terminated with signal Terminated (pid: 22044)
> Build step 'Execute shell' marked build as failure
>