See
<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/1887/changes>
Changes:
[vinod] post-reviews.py: compatible with git previous to 1.7.2.
[vinod] Switched to subprocess.Popen to get stdout streamed from
------------------------------------------
[...truncated 10620 lines...]
I0610 20:49:30.914072 14559 authenticator.hpp:384] Authentication requires more
steps
I0610 20:49:30.914093 14559 authenticatee.hpp:265] Received SASL authentication
step
I0610 20:49:30.914119 14559 authenticator.hpp:290] Received SASL authentication
step
I0610 20:49:30.914132 14559 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'janus.apache.org' server FQDN:
'janus.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0610 20:49:30.914139 14559 auxprop.cpp:153] Looking up auxiliary property
'*userPassword'
I0610 20:49:30.914147 14559 auxprop.cpp:153] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0610 20:49:30.914156 14559 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'janus.apache.org' server FQDN:
'janus.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0610 20:49:30.914162 14559 auxprop.cpp:103] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0610 20:49:30.914167 14559 auxprop.cpp:103] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0610 20:49:30.914176 14559 authenticator.hpp:376] Authentication success
I0610 20:49:30.914196 14559 authenticatee.hpp:305] Authentication success
I0610 20:49:30.914214 14559 master.cpp:3024] Successfully authenticated
principal 'test-principal' at scheduler(25)@67.195.138.60:41444
I0610 20:49:30.914263 14559 sched.cpp:348] Successfully authenticated with
master master@67.195.138.60:41444
I0610 20:49:30.914274 14559 sched.cpp:467] Sending registration request to
master@67.195.138.60:41444
I0610 20:49:30.914315 14559 master.cpp:1047] Received registration request from
scheduler(25)@67.195.138.60:41444
I0610 20:49:30.914345 14559 master.cpp:1065] Registering framework
20140610-204930-1015726915-41444-14533-0000 at scheduler(25)@67.195.138.60:41444
I0610 20:49:30.914433 14559 sched.cpp:398] Framework registered with
20140610-204930-1015726915-41444-14533-0000
I0610 20:49:30.914460 14559 sched.cpp:412] Scheduler::registered took 15875ns
I0610 20:49:30.914510 14557 hierarchical_allocator_process.hpp:331] Added
framework 20140610-204930-1015726915-41444-14533-0000
I0610 20:49:30.914522 14557 hierarchical_allocator_process.hpp:725] No
resources available to allocate!
I0610 20:49:30.914528 14557 hierarchical_allocator_process.hpp:687] Performed
allocation for 0 slaves in 6768ns
I0610 20:49:30.929287 14556 slave.cpp:908] Will retry registration in
16.44422ms if necessary
I0610 20:49:30.929317 14557 master.cpp:2258] Ignoring register slave message
from slave(20)@67.195.138.60:41444 (janus.apache.org) as admission is already
in progress
I0610 20:49:30.946528 14557 master.cpp:2258] Ignoring register slave message
from slave(20)@67.195.138.60:41444 (janus.apache.org) as admission is already
in progress
I0610 20:49:30.946568 14552 slave.cpp:908] Will retry registration in
58.944718ms if necessary
I0610 20:49:30.949265 14554 leveldb.cpp:343] Persisting action (16 bytes) to
leveldb took 40.766844ms
I0610 20:49:30.949285 14554 replica.cpp:676] Persisted action at 2
I0610 20:49:30.949492 14554 replica.cpp:655] Replica received learned notice
for position 2
I0610 20:49:30.973949 14554 leveldb.cpp:343] Persisting action (18 bytes) to
leveldb took 24.445319ms
I0610 20:49:30.973980 14554 leveldb.cpp:401] Deleting ~1 keys from leveldb took
11733ns
I0610 20:49:30.973992 14554 replica.cpp:676] Persisted action at 2
I0610 20:49:30.974001 14554 replica.cpp:661] Replica learned TRUNCATE action at
position 2
I0610 20:49:30.974279 14554 log.cpp:680] Attempting to append 331 bytes to the
log
I0610 20:49:30.974328 14554 coordinator.cpp:340] Coordinator attempting to
write APPEND action at position 3
I0610 20:49:30.974593 14554 replica.cpp:508] Replica received write request for
position 3
I0610 20:49:31.005784 14553 slave.cpp:908] Will retry registration in
52.454098ms if necessary
I0610 20:49:31.005813 14558 master.cpp:2258] Ignoring register slave message
from slave(20)@67.195.138.60:41444 (janus.apache.org) as admission is already
in progress
I0610 20:49:31.015900 14554 leveldb.cpp:343] Persisting action (350 bytes) to
leveldb took 41.288166ms
I0610 20:49:31.015920 14554 replica.cpp:676] Persisted action at 3
I0610 20:49:31.016109 14554 replica.cpp:655] Replica received learned notice
for position 3
I0610 20:49:31.059015 14553 slave.cpp:908] Will retry registration in
216.38024ms if necessary
I0610 20:49:31.059048 14556 master.cpp:2258] Ignoring register slave message
from slave(20)@67.195.138.60:41444 (janus.apache.org) as admission is already
in progress
I0610 20:49:31.108543 14554 leveldb.cpp:343] Persisting action (352 bytes) to
leveldb took 92.421953ms
I0610 20:49:31.108563 14554 replica.cpp:676] Persisted action at 3
I0610 20:49:31.108572 14554 replica.cpp:661] Replica learned APPEND action at
position 3
I0610 20:49:31.108909 14554 registrar.cpp:479] Successfully updated 'registry'
I0610 20:49:31.108984 14554 log.cpp:699] Attempting to truncate the log to 3
I0610 20:49:31.109036 14554 master.cpp:2310] Registered slave
20140610-204930-1015726915-41444-14533-0 at slave(20)@67.195.138.60:41444
(janus.apache.org)
I0610 20:49:31.109046 14554 master.cpp:3470] Adding slave
20140610-204930-1015726915-41444-14533-0 at slave(20)@67.195.138.60:41444
(janus.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000]
I0610 20:49:31.109148 14554 coordinator.cpp:340] Coordinator attempting to
write TRUNCATE action at position 4
I0610 20:49:31.109207 14554 slave.cpp:704] Registered with master
master@67.195.138.60:41444; given slave ID
20140610-204930-1015726915-41444-14533-0
I0610 20:49:31.109320 14554 slave.cpp:717] Checkpointing SlaveInfo to
'/tmp/StatusUpdateManagerTest_DuplicateTerminalUpdateBeforeAck_QHy1bZ/meta/slaves/20140610-204930-1015726915-41444-14533-0/slave.info'
I0610 20:49:31.109447 14554 hierarchical_allocator_process.hpp:444] Added slave
20140610-204930-1015726915-41444-14533-0 (janus.apache.org) with cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000] available)
I0610 20:49:31.109508 14554 hierarchical_allocator_process.hpp:751] Offering
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
20140610-204930-1015726915-41444-14533-0 to framework
20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.109613 14554 hierarchical_allocator_process.hpp:707] Performed
allocation for slave 20140610-204930-1015726915-41444-14533-0 in 135038ns
I0610 20:49:31.109696 14554 master.hpp:692] Adding offer
20140610-204930-1015726915-41444-14533-0 with resources cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000] on slave
20140610-204930-1015726915-41444-14533-0 (janus.apache.org)
I0610 20:49:31.109745 14554 master.cpp:2931] Sending 1 offers to framework
20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.109872 14554 sched.cpp:535] Scheduler::resourceOffers took
18734ns
I0610 20:49:31.110070 14554 replica.cpp:508] Replica received write request for
position 4
I0610 20:49:31.110486 14553 master.hpp:702] Removing offer
20140610-204930-1015726915-41444-14533-0 with resources cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000] on slave
20140610-204930-1015726915-41444-14533-0 (janus.apache.org)
I0610 20:49:31.110532 14553 master.cpp:1857] Processing reply for offers: [
20140610-204930-1015726915-41444-14533-0 ] on slave
20140610-204930-1015726915-41444-14533-0 at slave(20)@67.195.138.60:41444
(janus.apache.org) for framework 20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.110640 14553 master.hpp:664] Adding task 1 with resources
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
20140610-204930-1015726915-41444-14533-0 (janus.apache.org)
I0610 20:49:31.110685 14553 master.cpp:3109] Launching task 1 of framework
20140610-204930-1015726915-41444-14533-0000 with resources cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
20140610-204930-1015726915-41444-14533-0 at slave(20)@67.195.138.60:41444
(janus.apache.org)
I0610 20:49:31.110774 14552 slave.cpp:939] Got assigned task 1 for framework
20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.110836 14552 slave.cpp:3296] Checkpointing FrameworkInfo to
'/tmp/StatusUpdateManagerTest_DuplicateTerminalUpdateBeforeAck_QHy1bZ/meta/slaves/20140610-204930-1015726915-41444-14533-0/frameworks/20140610-204930-1015726915-41444-14533-0000/framework.info'
I0610 20:49:31.110935 14552 slave.cpp:3303] Checkpointing framework pid
'scheduler(25)@67.195.138.60:41444' to
'/tmp/StatusUpdateManagerTest_DuplicateTerminalUpdateBeforeAck_QHy1bZ/meta/slaves/20140610-204930-1015726915-41444-14533-0/frameworks/20140610-204930-1015726915-41444-14533-0000/framework.pid'
I0610 20:49:31.111115 14552 slave.cpp:1049] Launching task 1 for framework
20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.112324 14552 slave.cpp:3618] Checkpointing ExecutorInfo to
'/tmp/StatusUpdateManagerTest_DuplicateTerminalUpdateBeforeAck_QHy1bZ/meta/slaves/20140610-204930-1015726915-41444-14533-0/frameworks/20140610-204930-1015726915-41444-14533-0000/executors/default/executor.info'
I0610 20:49:31.113687 14552 exec.cpp:131] Version: 0.20.0
I0610 20:49:31.113767 14559 exec.cpp:181] Executor started at:
executor(9)@67.195.138.60:41444 with pid 14533
I0610 20:49:31.113873 14552 slave.cpp:3733] Checkpointing TaskInfo to
'/tmp/StatusUpdateManagerTest_DuplicateTerminalUpdateBeforeAck_QHy1bZ/meta/slaves/20140610-204930-1015726915-41444-14533-0/frameworks/20140610-204930-1015726915-41444-14533-0000/executors/default/runs/9cc7245a-e285-400e-a66f-3303a613acee/tasks/1/task.info'
I0610 20:49:31.114044 14552 slave.cpp:1159] Queuing task '1' for executor
default of framework '20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.114083 14552 slave.cpp:498] Successfully attached file
'/tmp/StatusUpdateManagerTest_DuplicateTerminalUpdateBeforeAck_QHy1bZ/slaves/20140610-204930-1015726915-41444-14533-0/frameworks/20140610-204930-1015726915-41444-14533-0000/executors/default/runs/9cc7245a-e285-400e-a66f-3303a613acee'
I0610 20:49:31.114104 14552 slave.cpp:1670] Got registration for executor
'default' of framework 20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.114122 14552 slave.cpp:1755] Checkpointing executor pid
'executor(9)@67.195.138.60:41444' to
'/tmp/StatusUpdateManagerTest_DuplicateTerminalUpdateBeforeAck_QHy1bZ/meta/slaves/20140610-204930-1015726915-41444-14533-0/frameworks/20140610-204930-1015726915-41444-14533-0000/executors/default/runs/9cc7245a-e285-400e-a66f-3303a613acee/pids/libprocess.pid'
I0610 20:49:31.114287 14552 slave.cpp:1789] Flushing queued task 1 for executor
'default' of framework 20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.114338 14552 slave.cpp:2361] Monitoring executor 'default' of
framework '20140610-204930-1015726915-41444-14533-0000' in container
'9cc7245a-e285-400e-a66f-3303a613acee'
I0610 20:49:31.114393 14552 exec.cpp:205] Executor registered on slave
20140610-204930-1015726915-41444-14533-0
I0610 20:49:31.115365 14552 exec.cpp:217] Executor::registered took 10271ns
I0610 20:49:31.115409 14552 exec.cpp:292] Executor asked to run task '1'
I0610 20:49:31.115434 14552 exec.cpp:301] Executor::launchTask took 17744ns
I0610 20:49:31.116399 14552 exec.cpp:524] Executor sending status update
TASK_FINISHED (UUID: ba41f62b-f87a-4ff6-82e7-3c6622d16cc6) for task 1 of
framework 20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.116459 14552 slave.cpp:2024] Handling status update
TASK_FINISHED (UUID: ba41f62b-f87a-4ff6-82e7-3c6622d16cc6) for task 1 of
framework 20140610-204930-1015726915-41444-14533-0000 from
executor(9)@67.195.138.60:41444
I0610 20:49:31.116477 14552 slave.cpp:3666] Terminating task 1
I0610 20:49:31.116570 14552 status_update_manager.cpp:320] Received status
update TASK_FINISHED (UUID: ba41f62b-f87a-4ff6-82e7-3c6622d16cc6) for task 1 of
framework 20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.116580 14552 status_update_manager.cpp:499] Creating
StatusUpdate stream for task 1 of framework
20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.116689 14552 status_update_manager.hpp:342] Checkpointing UPDATE
for status update TASK_FINISHED (UUID: ba41f62b-f87a-4ff6-82e7-3c6622d16cc6)
for task 1 of framework 20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.140540 14554 leveldb.cpp:343] Persisting action (16 bytes) to
leveldb took 30.4544ms
I0610 20:49:31.140560 14554 replica.cpp:676] Persisted action at 4
I0610 20:49:31.140702 14554 replica.cpp:655] Replica received learned notice
for position 4
I0610 20:49:31.184063 14554 leveldb.cpp:343] Persisting action (18 bytes) to
leveldb took 43.347761ms
I0610 20:49:31.184099 14554 leveldb.cpp:401] Deleting ~2 keys from leveldb took
16766ns
I0610 20:49:31.184111 14554 replica.cpp:676] Persisted action at 4
I0610 20:49:31.184119 14554 replica.cpp:661] Replica learned TRUNCATE action at
position 4
I0610 20:49:31.267495 14552 status_update_manager.cpp:373] Forwarding status
update TASK_FINISHED (UUID: ba41f62b-f87a-4ff6-82e7-3c6622d16cc6) for task 1 of
framework 20140610-204930-1015726915-41444-14533-0000 to
master@67.195.138.60:41444
I0610 20:49:31.267642 14552 master.cpp:2596] Status update TASK_FINISHED (UUID:
ba41f62b-f87a-4ff6-82e7-3c6622d16cc6) for task 1 of framework
20140610-204930-1015726915-41444-14533-0000 from slave
20140610-204930-1015726915-41444-14533-0 at slave(20)@67.195.138.60:41444
(janus.apache.org)
I0610 20:49:31.267695 14552 master.hpp:682] Removing task 1 with resources
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
20140610-204930-1015726915-41444-14533-0 (janus.apache.org)
I0610 20:49:31.267793 14552 slave.cpp:2145] Status update manager successfully
handled status update TASK_FINISHED (UUID:
ba41f62b-f87a-4ff6-82e7-3c6622d16cc6) for task 1 of framework
20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.267807 14552 slave.cpp:2151] Sending acknowledgement for status
update TASK_FINISHED (UUID: ba41f62b-f87a-4ff6-82e7-3c6622d16cc6) for task 1 of
framework 20140610-204930-1015726915-41444-14533-0000 to
executor(9)@67.195.138.60:41444
I0610 20:49:31.267874 14552 sched.cpp:626] Scheduler::statusUpdate took 12896ns
I0610 20:49:31.267967 14552 hierarchical_allocator_process.hpp:636] Recovered
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total
allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on
slave 20140610-204930-1015726915-41444-14533-0 from framework
20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.268009 14552 exec.cpp:338] Executor received status update
acknowledgement ba41f62b-f87a-4ff6-82e7-3c6622d16cc6 for task 1 of framework
20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.292354 14552 exec.cpp:524] Executor sending status update
TASK_KILLED (UUID: 3eacb574-f7cb-4caa-ac40-94c3bfa88219) for task 1 of
framework 20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.292412 14552 slave.cpp:2024] Handling status update TASK_KILLED
(UUID: 3eacb574-f7cb-4caa-ac40-94c3bfa88219) for task 1 of framework
20140610-204930-1015726915-41444-14533-0000 from executor(9)@67.195.138.60:41444
I0610 20:49:31.292490 14552 status_update_manager.cpp:320] Received status
update TASK_KILLED (UUID: 3eacb574-f7cb-4caa-ac40-94c3bfa88219) for task 1 of
framework 20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.292506 14552 status_update_manager.hpp:342] Checkpointing UPDATE
for status update TASK_KILLED (UUID: 3eacb574-f7cb-4caa-ac40-94c3bfa88219) for
task 1 of framework 20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.488090 14554 slave.cpp:2145] Status update manager successfully
handled status update TASK_KILLED (UUID: 3eacb574-f7cb-4caa-ac40-94c3bfa88219)
for task 1 of framework 20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.488104 14554 slave.cpp:2151] Sending acknowledgement for status
update TASK_KILLED (UUID: 3eacb574-f7cb-4caa-ac40-94c3bfa88219) for task 1 of
framework 20140610-204930-1015726915-41444-14533-0000 to
executor(9)@67.195.138.60:41444
I0610 20:49:31.488143 14554 exec.cpp:338] Executor received status update
acknowledgement 3eacb574-f7cb-4caa-ac40-94c3bfa88219 for task 1 of framework
20140610-204930-1015726915-41444-14533-0000
W0610 20:49:31.492707 14556 status_update_manager.cpp:477] Resending status
update TASK_FINISHED (UUID: ba41f62b-f87a-4ff6-82e7-3c6622d16cc6) for task 1 of
framework 20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.492722 14556 status_update_manager.cpp:373] Forwarding status
update TASK_FINISHED (UUID: ba41f62b-f87a-4ff6-82e7-3c6622d16cc6) for task 1 of
framework 20140610-204930-1015726915-41444-14533-0000 to
master@67.195.138.60:41444
W0610 20:49:31.492817 14556 master.cpp:2589] Could not lookup task for status
update TASK_FINISHED (UUID: ba41f62b-f87a-4ff6-82e7-3c6622d16cc6) for task 1 of
framework 20140610-204930-1015726915-41444-14533-0000 from slave
20140610-204930-1015726915-41444-14533-0 at slave(20)@67.195.138.60:41444
(janus.apache.org)
I0610 20:49:31.492867 14554 sched.cpp:626] Scheduler::statusUpdate took 13011ns
I0610 20:49:31.492859 14558 hierarchical_allocator_process.hpp:751] Offering
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
20140610-204930-1015726915-41444-14533-0 to framework
20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.492939 14554 status_update_manager.cpp:398] Received status
update acknowledgement (UUID: ba41f62b-f87a-4ff6-82e7-3c6622d16cc6) for task 1
of framework 20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.492954 14554 status_update_manager.hpp:342] Checkpointing ACK
for status update TASK_FINISHED (UUID: ba41f62b-f87a-4ff6-82e7-3c6622d16cc6)
for task 1 of framework 20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.493026 14558 hierarchical_allocator_process.hpp:687] Performed
allocation for 1 slaves in 404583ns
I0610 20:49:31.493041 14557 master.cpp:108] No whitelist given. Advertising
offers for all slaves
I0610 20:49:31.493082 14558 master.hpp:692] Adding offer
20140610-204930-1015726915-41444-14533-1 with resources cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000] on slave
20140610-204930-1015726915-41444-14533-0 (janus.apache.org)
I0610 20:49:31.493121 14558 master.cpp:2931] Sending 1 offers to framework
20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.493234 14559 sched.cpp:535] Scheduler::resourceOffers took 9335ns
2014-06-10
20:49:31,561:14533(0x2b894c803700):ZOO_ERROR@handle_socket_error_msg@1697:
Socket [127.0.0.1:59491] zk retcode=-4, errno=111(Connection refused): server
refused to accept the client
W0610 20:49:31.699092 14554 status_update_manager.cpp:452] Acknowledged a
terminal status update TASK_FINISHED (UUID:
ba41f62b-f87a-4ff6-82e7-3c6622d16cc6) for task 1 of framework
20140610-204930-1015726915-41444-14533-0000 but updates are still pending
I0610 20:49:31.699115 14554 status_update_manager.cpp:530] Cleaning up status
update stream for task 1 of framework
20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.699206 14554 slave.cpp:1610] Status update manager successfully
handled status update acknowledgement (UUID:
ba41f62b-f87a-4ff6-82e7-3c6622d16cc6) for task 1 of framework
20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.699219 14554 slave.cpp:3708] Completing task 1
I0610 20:49:31.713764 14554 sched.cpp:731] Stopping framework
'20140610-204930-1015726915-41444-14533-0000'
I0610 20:49:31.713791 14533 master.cpp:573] Master terminating
I0610 20:49:31.713857 14533 master.hpp:702] Removing offer
20140610-204930-1015726915-41444-14533-1 with resources cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000] on slave
20140610-204930-1015726915-41444-14533-0 (janus.apache.org)
I0610 20:49:31.714154 14554 slave.cpp:2230] master@67.195.138.60:41444 exited
W0610 20:49:31.714171 14554 slave.cpp:2233] Master disconnected! Waiting for a
new master to be elected
I0610 20:49:31.716492 14555 slave.cpp:2419] Executor 'default' of framework
20140610-204930-1015726915-41444-14533-0000 has exited with status 0
I0610 20:49:31.716539 14555 slave.cpp:2558] Cleaning up executor 'default' of
framework 20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.716727 14555 slave.cpp:2633] Cleaning up framework
20140610-204930-1015726915-41444-14533-0000
I0610 20:49:31.716796 14555 slave.cpp:426] Slave terminating
I0610 20:49:31.716861 14555 gc.cpp:56] Scheduling
'/tmp/StatusUpdateManagerTest_DuplicateTerminalUpdateBeforeAck_QHy1bZ/slaves/20140610-204930-1015726915-41444-14533-0/frameworks/20140610-204930-1015726915-41444-14533-0000/executors/default/runs/9cc7245a-e285-400e-a66f-3303a613acee'
for gc 6.99999170565926days in the future
I0610 20:49:31.716909 14555 gc.cpp:56] Scheduling
'/tmp/StatusUpdateManagerTest_DuplicateTerminalUpdateBeforeAck_QHy1bZ/slaves/20140610-204930-1015726915-41444-14533-0/frameworks/20140610-204930-1015726915-41444-14533-0000/executors/default'
for gc 6.99999170524444days in the future
[ OK ] StatusUpdateManagerTest.DuplicateTerminalUpdateBeforeAck (1317 ms)
[ RUN ] StatusUpdateManagerTest.DuplicateTerminalUpdateAfterAck
Using temporary directory
'/tmp/StatusUpdateManagerTest_DuplicateTerminalUpdateAfterAck_ZNvq7Y'
I0610 20:49:31.966441 14533 leveldb.cpp:176] Opened db in 247.821983ms
I0610 20:49:31.991216 14533 leveldb.cpp:183] Compacted db in 24.751295ms
I0610 20:49:31.991236 14533 leveldb.cpp:198] Created db iterator in 3684ns
I0610 20:49:31.991243 14533 leveldb.cpp:204] Seeked to beginning of db in 519ns
I0610 20:49:31.991250 14533 leveldb.cpp:273] Iterated through 0 keys in the db
in 300ns
I0610 20:49:31.991264 14533 replica.cpp:741] Replica recovered with log
positions 0 -> 0 with 1 holes and 0 unlearned
I0610 20:49:31.991521 14555 recover.cpp:425] Starting replica recovery
I0610 20:49:31.991730 14555 recover.cpp:451] Replica is in EMPTY status
I0610 20:49:31.992102 14559 replica.cpp:638] Replica in EMPTY status received a
broadcasted recover request
I0610 20:49:31.992240 14555 recover.cpp:188] Received a recover response from a
replica in EMPTY status
I0610 20:49:31.992435 14555 recover.cpp:542] Updating replica status to STARTING
I0610 20:49:31.993227 14555 master.cpp:272] Master
20140610-204931-1015726915-41444-14533 (janus.apache.org) started on
67.195.138.60:41444
I0610 20:49:31.993244 14555 master.cpp:309] Master only allowing authenticated
frameworks to register
I0610 20:49:31.993252 14555 master.cpp:314] Master only allowing authenticated
slaves to register
I0610 20:49:31.993259 14555 credentials.hpp:35] Loading credentials for
authentication from
'/tmp/StatusUpdateManagerTest_DuplicateTerminalUpdateAfterAck_ZNvq7Y/credentials'
I0610 20:49:31.993319 14555 master.cpp:340] Master enabling authorization
I0610 20:49:31.993686 14556 master.cpp:108] No whitelist given. Advertising
offers for all slaves
I0610 20:49:31.993724 14558 hierarchical_allocator_process.hpp:301]
Initializing hierarchical allocator process with master :
master@67.195.138.60:41444
I0610 20:49:31.994132 14552 master.cpp:956] The newly elected leader is
master@67.195.138.60:41444 with id 20140610-204931-1015726915-41444-14533
I0610 20:49:31.994144 14552 master.cpp:969] Elected as the leading master!
I0610 20:49:31.994151 14552 master.cpp:787] Recovering from registrar
I0610 20:49:31.994195 14559 registrar.cpp:313] Recovering registrar
I0610 20:49:32.058512 14557 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 65.984151ms
I0610 20:49:32.058537 14557 replica.cpp:320] Persisted replica status to
STARTING
I0610 20:49:32.058627 14557 recover.cpp:451] Replica is in STARTING status
I0610 20:49:32.058923 14559 replica.cpp:638] Replica in STARTING status
received a broadcasted recover request
I0610 20:49:32.059054 14554 recover.cpp:188] Received a recover response from a
replica in STARTING status
I0610 20:49:32.059136 14554 recover.cpp:542] Updating replica status to VOTING
I0610 20:49:32.084653 14554 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 25.45617ms
I0610 20:49:32.084692 14554 replica.cpp:320] Persisted replica status to VOTING
I0610 20:49:32.084736 14554 recover.cpp:556] Successfully joined the Paxos group
I0610 20:49:32.084805 14554 recover.cpp:440] Recover process terminated
I0610 20:49:32.084929 14554 log.cpp:656] Attempting to start the writer
I0610 20:49:32.085247 14559 replica.cpp:474] Replica received implicit promise
request with proposal 1
I0610 20:49:32.098386 14559 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 13.11769ms
I0610 20:49:32.098402 14559 replica.cpp:342] Persisted promised to 1
I0610 20:49:32.098582 14553 coordinator.cpp:230] Coordinator attemping to fill
missing position
I0610 20:49:32.098888 14553 replica.cpp:375] Replica received explicit promise
request for position 0 with proposal 2
I0610 20:49:32.107013 14553 leveldb.cpp:343] Persisting action (8 bytes) to
leveldb took 8.111418ms
I0610 20:49:32.107033 14553 replica.cpp:676] Persisted action at 0
I0610 20:49:32.107348 14553 replica.cpp:508] Replica received write request for
position 0
I0610 20:49:32.107378 14553 leveldb.cpp:438] Reading position from leveldb took
12444ns
I0610 20:49:32.156746 14553 leveldb.cpp:343] Persisting action (14 bytes) to
leveldb took 49.333299ms
I0610 20:49:32.156779 14553 replica.cpp:676] Persisted action at 0
I0610 20:49:32.156947 14553 replica.cpp:655] Replica received learned notice
for position 0
I0610 20:49:32.994202 14557 hierarchical_allocator_process.hpp:725] No
resources available to allocate!
I0610 20:49:32.994228 14557 hierarchical_allocator_process.hpp:687] Performed
allocation for 0 slaves in 60261ns
I0610 20:49:33.995412 14555 hierarchical_allocator_process.hpp:725] No
resources available to allocate!
I0610 20:49:33.995432 14555 hierarchical_allocator_process.hpp:687] Performed
allocation for 0 slaves in 112690ns
I0610 20:49:34.045660 14553 leveldb.cpp:343] Persisting action (16 bytes) to
leveldb took 1.888690966secs
I0610 20:49:34.045701 14553 replica.cpp:676] Persisted action at 0
I0610 20:49:34.045709 14553 replica.cpp:661] Replica learned NOP action at
position 0
I0610 20:49:34.046006 14554 log.cpp:672] Writer started with ending position 0
I0610 20:49:34.046483 14559 leveldb.cpp:438] Reading position from leveldb took
23759ns
I0610 20:49:34.048163 14556 registrar.cpp:346] Successfully fetched the
registry (0B)
I0610 20:49:34.048190 14556 registrar.cpp:422] Attempting to update the
'registry'
I0610 20:49:34.049628 14556 log.cpp:680] Attempting to append 138 bytes to the
log
I0610 20:49:34.049690 14556 coordinator.cpp:340] Coordinator attempting to
write APPEND action at position 1
I0610 20:49:34.050078 14552 replica.cpp:508] Replica received write request for
position 1
2014-06-10
20:49:34,897:14533(0x2b894c803700):ZOO_ERROR@handle_socket_error_msg@1697:
Socket [127.0.0.1:59491] zk retcode=-4, errno=111(Connection refused): server
refused to accept the client
I0610 20:49:34.996449 14558 hierarchical_allocator_process.hpp:725] No
resources available to allocate!
I0610 20:49:34.996485 14558 hierarchical_allocator_process.hpp:687] Performed
allocation for 0 slaves in 52372ns
I0610 20:49:35.997508 14554 hierarchical_allocator_process.hpp:725] No
resources available to allocate!
I0610 20:49:35.997522 14554 hierarchical_allocator_process.hpp:687] Performed
allocation for 0 slaves in 24401ns
I0610 20:49:36.993772 14556 master.cpp:108] No whitelist given. Advertising
offers for all slaves
I0610 20:49:36.997895 14553 hierarchical_allocator_process.hpp:725] No
resources available to allocate!
I0610 20:49:36.997907 14553 hierarchical_allocator_process.hpp:687] Performed
allocation for 0 slaves in 20989ns
I0610 20:49:37.998998 14555 hierarchical_allocator_process.hpp:725] No
resources available to allocate!
I0610 20:49:37.999047 14555 hierarchical_allocator_process.hpp:687] Performed
allocation for 0 slaves in 54724ns
2014-06-10
20:49:38,234:14533(0x2b894c803700):ZOO_ERROR@handle_socket_error_msg@1697:
Socket [127.0.0.1:59491] zk retcode=-4, errno=111(Connection refused): server
refused to accept the client
I0610 20:49:39.000146 14558 hierarchical_allocator_process.hpp:725] No
resources available to allocate!
I0610 20:49:39.000166 14558 hierarchical_allocator_process.hpp:687] Performed
allocation for 0 slaves in 23860ns
I0610 20:49:40.000255 14557 hierarchical_allocator_process.hpp:725] No
resources available to allocate!
I0610 20:49:40.000274 14557 hierarchical_allocator_process.hpp:687] Performed
allocation for 0 slaves in 30151ns
I0610 20:49:41.001391 14558 hierarchical_allocator_process.hpp:725] No
resources available to allocate!
I0610 20:49:41.001412 14558 hierarchical_allocator_process.hpp:687] Performed
allocation for 0 slaves in 26837ns
2014-06-10
20:49:41,570:14533(0x2b894c803700):ZOO_ERROR@handle_socket_error_msg@1697:
Socket [127.0.0.1:59491] zk retcode=-4, errno=111(Connection refused): server
refused to accept the client
F0610 20:49:41.993479 14533 cluster.hpp:379] Failed to wait for _recover
*** Check failure stack trace: ***
I0610 20:49:41.994530 14559 master.cpp:108] No whitelist given. Advertising
offers for all slaves
I0610 20:49:42.001608 14553 hierarchical_allocator_process.hpp:725] No
resources available to allocate!
I0610 20:49:42.025499 14553 hierarchical_allocator_process.hpp:687] Performed
allocation for 0 slaves in 23.893418ms
@ 0x2b878f62d11d google::LogMessage::Fail()
@ 0x2b878f62f1af google::LogMessage::SendToLog()
@ 0x2b878f62cd0c google::LogMessage::Flush()
@ 0x2b878f62fa1d google::LogMessageFatal::~LogMessageFatal()
@ 0x788320 mesos::internal::tests::Cluster::Masters::start()
@ 0x783b73 mesos::internal::tests::MesosTest::StartMaster()
@ 0x8ba939
StatusUpdateManagerTest_DuplicateTerminalUpdateAfterAck_Test::TestBody()
@ 0x938b3d
testing::internal::HandleExceptionsInMethodIfSupported<>()
@ 0x931171 testing::Test::Run()
@ 0x931256 testing::TestInfo::Run()
@ 0x931397 testing::TestCase::Run()
@ 0x9316fe testing::internal::UnitTestImpl::RunAllTests()
@ 0x9386bd
testing::internal::HandleExceptionsInMethodIfSupported<>()
@ 0x9307ce testing::UnitTest::Run()
@ 0x4b3b20 main
@ 0x2b87912c476d (unknown)
@ 0x4c0721 (unknown)
make[4]: *** [check-local] Aborted
make[4]: Leaving directory
`<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/mesos-0.20.0/_build/src'>
make[3]: *** [check-am] Error 2
make[3]: Leaving directory
`<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/mesos-0.20.0/_build/src'>
make[2]: *** [check] Error 2
make[2]: Leaving directory
`<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/mesos-0.20.0/_build/src'>
make[1]: *** [check-recursive] Error 1
make[1]: Leaving directory
`<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/mesos-0.20.0/_build'>
make: *** [distcheck] Error 1
Build step 'Execute shell' marked build as failure
