See
<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2591/changes>
Changes:
[yujie.jay] Allowed slave to checkpoint resources.
[yujie.jay] Fixed a compilation error on gcc-4.4.
------------------------------------------
[...truncated 4907 lines...]
I1122 02:45:56.360049 14198 leveldb.cpp:343] Persisting action (16 bytes) to
leveldb took 552812ns
I1122 02:45:56.360086 14198 replica.cpp:676] Persisted action at 4
I1122 02:45:56.360723 14211 replica.cpp:655] Replica received learned notice
for position 4
I1122 02:45:56.360962 14213 sched.cpp:602] Scheduler::resourceOffers took
625811ns
I1122 02:45:56.361233 14211 leveldb.cpp:343] Persisting action (18 bytes) to
leveldb took 477776ns
I1122 02:45:56.361343 14211 leveldb.cpp:401] Deleting ~2 keys from leveldb took
78151ns
I1122 02:45:56.361369 14211 replica.cpp:676] Persisted action at 4
I1122 02:45:56.361392 14211 replica.cpp:661] Replica learned TRUNCATE action at
position 4
I1122 02:45:56.361846 14206 master.cpp:2363] Processing reply for offers: [
20141122-024556-3142697795-59073-14184-O0 ] on slave
20141122-024556-3142697795-59073-14184-S0 at slave(8)@67.195.81.187:59073
(pomona.apache.org) for framework 20141122-024556-3142697795-59073-14184-0000
(default) at scheduler-8f3b101e-2bb8-4815-8f22-4e22f722288a@67.195.81.187:59073
I1122 02:45:56.361882 14206 master.cpp:2461] Authorizing framework principal
'test-principal' to launch task 0 as user 'jenkins'
W1122 02:45:56.362598 14202 master.cpp:1998] Executor default for task 0 uses
less CPUs (None) than the minimum required (0.01). Please update your executor,
as this will be mandatory in future releases.
W1122 02:45:56.362640 14202 master.cpp:2010] Executor default for task 0 uses
less memory (None) than the minimum required (32MB). Please update your
executor, as this will be mandatory in future releases.
I1122 02:45:56.362905 14202 master.hpp:759] Adding task 0 with resources
cpus(*):1; mem(*):16 on slave 20141122-024556-3142697795-59073-14184-S0
(pomona.apache.org)
I1122 02:45:56.362990 14202 master.cpp:2531] Launching task 0 of framework
20141122-024556-3142697795-59073-14184-0000 (default) at
scheduler-8f3b101e-2bb8-4815-8f22-4e22f722288a@67.195.81.187:59073 with
resources cpus(*):1; mem(*):16 on slave
20141122-024556-3142697795-59073-14184-S0 at slave(8)@67.195.81.187:59073
(pomona.apache.org)
I1122 02:45:56.363240 14198 slave.cpp:1098] Got assigned task 0 for framework
20141122-024556-3142697795-59073-14184-0000
I1122 02:45:56.363394 14201 hierarchical_allocator_process.hpp:563] Recovered
cpus(*):1; mem(*):1008; disk(*):1024; ports(*):[31000-32000] (total
allocatable: cpus(*):1; mem(*):1008; disk(*):1024; ports(*):[31000-32000]) on
slave 20141122-024556-3142697795-59073-14184-S0 from framework
20141122-024556-3142697795-59073-14184-0000
I1122 02:45:56.363448 14201 hierarchical_allocator_process.hpp:599] Framework
20141122-024556-3142697795-59073-14184-0000 filtered slave
20141122-024556-3142697795-59073-14184-S0 for 5secs
I1122 02:45:56.363756 14198 slave.cpp:1208] Launching task 0 for framework
20141122-024556-3142697795-59073-14184-0000
I1122 02:45:56.366338 14198 slave.cpp:3864] Launching executor default of
framework 20141122-024556-3142697795-59073-14184-0000 in work directory
'/tmp/MesosSchedulerDriverTest_DropAckIfStopCalledBeforeAbort_fqeve2/slaves/20141122-024556-3142697795-59073-14184-S0/frameworks/20141122-024556-3142697795-59073-14184-0000/executors/default/runs/cff9c739-840e-483d-8f9c-4313330957a2'
I1122 02:45:56.369133 14198 exec.cpp:132] Version: 0.22.0
I1122 02:45:56.369391 14212 exec.cpp:182] Executor started at:
executor(2)@67.195.81.187:59073 with pid 14184
I1122 02:45:56.369492 14198 slave.cpp:1331] Queuing task '0' for executor
default of framework '20141122-024556-3142697795-59073-14184-0000
I1122 02:45:56.369647 14198 slave.cpp:558] Successfully attached file
'/tmp/MesosSchedulerDriverTest_DropAckIfStopCalledBeforeAbort_fqeve2/slaves/20141122-024556-3142697795-59073-14184-S0/frameworks/20141122-024556-3142697795-59073-14184-0000/executors/default/runs/cff9c739-840e-483d-8f9c-4313330957a2'
I1122 02:45:56.369763 14198 slave.cpp:2855] Monitoring executor 'default' of
framework '20141122-024556-3142697795-59073-14184-0000' in container
'cff9c739-840e-483d-8f9c-4313330957a2'
I1122 02:45:56.369974 14198 slave.cpp:1875] Got registration for executor
'default' of framework 20141122-024556-3142697795-59073-14184-0000 from
executor(2)@67.195.81.187:59073
I1122 02:45:56.370362 14198 slave.cpp:1994] Flushing queued task 0 for executor
'default' of framework 20141122-024556-3142697795-59073-14184-0000
I1122 02:45:56.370394 14213 exec.cpp:206] Executor registered on slave
20141122-024556-3142697795-59073-14184-S0
I1122 02:45:56.372503 14213 exec.cpp:218] Executor::registered took 24279ns
I1122 02:45:56.372670 14213 exec.cpp:293] Executor asked to run task '0'
I1122 02:45:56.372745 14213 exec.cpp:302] Executor::launchTask took 51196ns
I1122 02:45:56.374919 14213 exec.cpp:525] Executor sending status update
TASK_RUNNING (UUID: 31e3c537-b4b7-47ea-8da3-def98f475378) for task 0 of
framework 20141122-024556-3142697795-59073-14184-0000
I1122 02:45:56.375136 14213 slave.cpp:2230] Handling status update TASK_RUNNING
(UUID: 31e3c537-b4b7-47ea-8da3-def98f475378) for task 0 of framework
20141122-024556-3142697795-59073-14184-0000 from executor(2)@67.195.81.187:59073
I1122 02:45:56.375396 14198 status_update_manager.cpp:317] Received status
update TASK_RUNNING (UUID: 31e3c537-b4b7-47ea-8da3-def98f475378) for task 0 of
framework 20141122-024556-3142697795-59073-14184-0000
I1122 02:45:56.375435 14198 status_update_manager.cpp:494] Creating
StatusUpdate stream for task 0 of framework
20141122-024556-3142697795-59073-14184-0000
I1122 02:45:56.375622 14198 status_update_manager.cpp:371] Forwarding update
TASK_RUNNING (UUID: 31e3c537-b4b7-47ea-8da3-def98f475378) for task 0 of
framework 20141122-024556-3142697795-59073-14184-0000 to the slave
I1122 02:45:56.375849 14213 slave.cpp:2473] Forwarding the update TASK_RUNNING
(UUID: 31e3c537-b4b7-47ea-8da3-def98f475378) for task 0 of framework
20141122-024556-3142697795-59073-14184-0000 to master@67.195.81.187:59073
I1122 02:45:56.376039 14213 slave.cpp:2400] Status update manager successfully
handled status update TASK_RUNNING (UUID: 31e3c537-b4b7-47ea-8da3-def98f475378)
for task 0 of framework 20141122-024556-3142697795-59073-14184-0000
I1122 02:45:56.376086 14213 slave.cpp:2406] Sending acknowledgement for status
update TASK_RUNNING (UUID: 31e3c537-b4b7-47ea-8da3-def98f475378) for task 0 of
framework 20141122-024556-3142697795-59073-14184-0000 to
executor(2)@67.195.81.187:59073
I1122 02:45:56.376117 14207 master.cpp:3409] Forwarding status update
TASK_RUNNING (UUID: 31e3c537-b4b7-47ea-8da3-def98f475378) for task 0 of
framework 20141122-024556-3142697795-59073-14184-0000
I1122 02:45:56.376241 14213 exec.cpp:339] Executor received status update
acknowledgement 31e3c537-b4b7-47ea-8da3-def98f475378 for task 0 of framework
20141122-024556-3142697795-59073-14184-0000
I1122 02:45:56.376248 14207 master.cpp:3381] Status update TASK_RUNNING (UUID:
31e3c537-b4b7-47ea-8da3-def98f475378) for task 0 of framework
20141122-024556-3142697795-59073-14184-0000 from slave
20141122-024556-3142697795-59073-14184-S0 at slave(8)@67.195.81.187:59073
(pomona.apache.org)
I1122 02:45:56.376327 14207 master.cpp:4666] Updating the latest state of task
0 of framework 20141122-024556-3142697795-59073-14184-0000 to TASK_RUNNING
I1122 02:45:56.376412 14199 sched.cpp:1364] Asked to stop the driver
I1122 02:45:56.376457 14199 sched.cpp:1398] Asked to abort the driver
I1122 02:45:56.376482 14199 sched.cpp:1401] Ignoring abort because the status
of the driver is DRIVER_STOPPED
I1122 02:45:56.376526 14199 sched.cpp:693] Scheduler::statusUpdate took 139711ns
I1122 02:45:56.376544 14199 sched.cpp:699] Not sending status update
acknowledgment message because the driver is not running!
I1122 02:45:56.376585 14199 sched.cpp:805] Stopping framework
'20141122-024556-3142697795-59073-14184-0000'
I1122 02:45:56.376943 14203 master.cpp:1707] Asked to unregister framework
20141122-024556-3142697795-59073-14184-0000
I1122 02:45:56.376976 14203 master.cpp:4244] Removing framework
20141122-024556-3142697795-59073-14184-0000 (default) at
scheduler-8f3b101e-2bb8-4815-8f22-4e22f722288a@67.195.81.187:59073
I1122 02:45:56.377104 14209 hierarchical_allocator_process.hpp:405] Deactivated
framework 20141122-024556-3142697795-59073-14184-0000
I1122 02:45:56.377151 14212 slave.cpp:1548] Asked to shut down framework
20141122-024556-3142697795-59073-14184-0000 by master@67.195.81.187:59073
I1122 02:45:56.377185 14212 slave.cpp:1573] Shutting down framework
20141122-024556-3142697795-59073-14184-0000
I1122 02:45:56.377241 14212 slave.cpp:3161] Shutting down executor 'default' of
framework 20141122-024556-3142697795-59073-14184-0000
I1122 02:45:56.377375 14202 exec.cpp:379] Executor asked to shutdown
I1122 02:45:56.377437 14202 exec.cpp:394] Executor::shutdown took 40943ns
I1122 02:45:56.378716 14203 master.cpp:4666] Updating the latest state of task
0 of framework 20141122-024556-3142697795-59073-14184-0000 to TASK_KILLED
I1122 02:45:56.378859 14203 master.cpp:4725] Removing task 0 with resources
cpus(*):1; mem(*):16 of framework 20141122-024556-3142697795-59073-14184-0000
on slave 20141122-024556-3142697795-59073-14184-S0 at
slave(8)@67.195.81.187:59073 (pomona.apache.org)
I1122 02:45:56.378906 14199 hierarchical_allocator_process.hpp:563] Recovered
cpus(*):1; mem(*):16 (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000]) on slave 20141122-024556-3142697795-59073-14184-S0 from
framework 20141122-024556-3142697795-59073-14184-0000
I1122 02:45:56.379161 14203 master.cpp:4754] Removing executor 'default' with
resources of framework 20141122-024556-3142697795-59073-14184-0000 on slave
20141122-024556-3142697795-59073-14184-S0 at slave(8)@67.195.81.187:59073
(pomona.apache.org)
I1122 02:45:56.379955 14210 hierarchical_allocator_process.hpp:360] Removed
framework 20141122-024556-3142697795-59073-14184-0000
I1122 02:45:56.386850 14184 sched.cpp:1364] Asked to stop the driver
I1122 02:45:56.386872 14184 sched.cpp:1367] Ignoring stop because the status of
the driver is DRIVER_STOPPED
I1122 02:45:56.386921 14204 master.cpp:698] Master terminating
I1122 02:45:56.387245 14213 slave.cpp:2638] master@67.195.81.187:59073 exited
W1122 02:45:56.387269 14213 slave.cpp:2641] Master disconnected! Waiting for a
new master to be elected
I1122 02:45:56.410712 14209 slave.cpp:2913] Executor 'default' of framework
20141122-024556-3142697795-59073-14184-0000 exited with status 0
I1122 02:45:56.410866 14209 slave.cpp:3022] Cleaning up executor 'default' of
framework 20141122-024556-3142697795-59073-14184-0000
I1122 02:45:56.411033 14210 gc.cpp:56] Scheduling
'/tmp/MesosSchedulerDriverTest_DropAckIfStopCalledBeforeAbort_fqeve2/slaves/20141122-024556-3142697795-59073-14184-S0/frameworks/20141122-024556-3142697795-59073-14184-0000/executors/default/runs/cff9c739-840e-483d-8f9c-4313330957a2'
for gc 6.99999563916741days in the future
I1122 02:45:56.411166 14209 slave.cpp:3099] Cleaning up framework
20141122-024556-3142697795-59073-14184-0000
I1122 02:45:56.411237 14210 gc.cpp:56] Scheduling
'/tmp/MesosSchedulerDriverTest_DropAckIfStopCalledBeforeAbort_fqeve2/slaves/20141122-024556-3142697795-59073-14184-S0/frameworks/20141122-024556-3142697795-59073-14184-0000/executors/default'
for gc 6.99999563916741days in the future
I1122 02:45:56.411267 14206 status_update_manager.cpp:279] Closing status
update streams for framework 20141122-024556-3142697795-59073-14184-0000
I1122 02:45:56.411428 14206 status_update_manager.cpp:525] Cleaning up status
update stream for task 0 of framework
20141122-024556-3142697795-59073-14184-0000
I1122 02:45:56.411476 14210 gc.cpp:56] Scheduling
'/tmp/MesosSchedulerDriverTest_DropAckIfStopCalledBeforeAbort_fqeve2/slaves/20141122-024556-3142697795-59073-14184-S0/frameworks/20141122-024556-3142697795-59073-14184-0000'
for gc 6.99999563916741days in the future
I1122 02:45:56.420907 14203 slave.cpp:487] Slave terminating
[ OK ] MesosSchedulerDriverTest.DropAckIfStopCalledBeforeAbort (140 ms)
[ RUN ] MesosSchedulerDriverTest.MetricsEndpoint
Using temporary directory '/tmp/MesosSchedulerDriverTest_MetricsEndpoint_njlZv5'
I1122 02:45:56.432256 14184 leveldb.cpp:176] Opened db in 2.873509ms
I1122 02:45:56.433259 14184 leveldb.cpp:183] Compacted db in 905238ns
I1122 02:45:56.433365 14184 leveldb.cpp:198] Created db iterator in 15089ns
I1122 02:45:56.433385 14184 leveldb.cpp:204] Seeked to beginning of db in 1530ns
I1122 02:45:56.433397 14184 leveldb.cpp:273] Iterated through 0 keys in the db
in 347ns
I1122 02:45:56.433428 14184 replica.cpp:741] Replica recovered with log
positions 0 -> 0 with 1 holes and 0 unlearned
I1122 02:45:56.433797 14207 recover.cpp:437] Starting replica recovery
I1122 02:45:56.434098 14207 recover.cpp:463] Replica is in EMPTY status
I1122 02:45:56.435060 14206 replica.cpp:638] Replica in EMPTY status received a
broadcasted recover request
I1122 02:45:56.435406 14208 recover.cpp:188] Received a recover response from a
replica in EMPTY status
I1122 02:45:56.435791 14198 recover.cpp:554] Updating replica status to STARTING
I1122 02:45:56.436455 14203 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 587392ns
I1122 02:45:56.436519 14203 replica.cpp:320] Persisted replica status to
STARTING
I1122 02:45:56.436749 14204 recover.cpp:463] Replica is in STARTING status
I1122 02:45:56.437732 14206 replica.cpp:638] Replica in STARTING status
received a broadcasted recover request
I1122 02:45:56.438171 14198 recover.cpp:188] Received a recover response from a
replica in STARTING status
I1122 02:45:56.438568 14210 recover.cpp:554] Updating replica status to VOTING
I1122 02:45:56.439245 14202 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 475153ns
I1122 02:45:56.439322 14202 replica.cpp:320] Persisted replica status to VOTING
I1122 02:45:56.439488 14198 recover.cpp:568] Successfully joined the Paxos group
I1122 02:45:56.439726 14198 recover.cpp:452] Recover process terminated
I1122 02:45:56.447832 14207 master.cpp:318] Master
20141122-024556-3142697795-59073-14184 (pomona.apache.org) started on
67.195.81.187:59073
I1122 02:45:56.447913 14207 master.cpp:364] Master only allowing authenticated
frameworks to register
I1122 02:45:56.447937 14207 master.cpp:369] Master only allowing authenticated
slaves to register
I1122 02:45:56.447964 14207 credentials.hpp:36] Loading credentials for
authentication from
'/tmp/MesosSchedulerDriverTest_MetricsEndpoint_njlZv5/credentials'
I1122 02:45:56.448190 14207 master.cpp:413] Authorization enabled
I1122 02:45:56.448653 14204 master.cpp:126] No whitelist given. Advertising
offers for all slaves
I1122 02:45:56.448710 14208 hierarchical_allocator_process.hpp:299]
Initializing hierarchical allocator process with master :
master@67.195.81.187:59073
I1122 02:45:56.449702 14209 master.cpp:1263] The newly elected leader is
master@67.195.81.187:59073 with id 20141122-024556-3142697795-59073-14184
I1122 02:45:56.449739 14209 master.cpp:1276] Elected as the leading master!
I1122 02:45:56.449764 14209 master.cpp:1094] Recovering from registrar
I1122 02:45:56.449872 14206 registrar.cpp:313] Recovering registrar
I1122 02:45:56.450426 14207 log.cpp:656] Attempting to start the writer
I1122 02:45:56.451602 14209 replica.cpp:474] Replica received implicit promise
request with proposal 1
I1122 02:45:56.452096 14209 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 463061ns
I1122 02:45:56.452122 14209 replica.cpp:342] Persisted promised to 1
I1122 02:45:56.452685 14208 coordinator.cpp:230] Coordinator attemping to fill
missing position
I1122 02:45:56.453802 14210 replica.cpp:375] Replica received explicit promise
request for position 0 with proposal 2
I1122 02:45:56.454262 14210 leveldb.cpp:343] Persisting action (8 bytes) to
leveldb took 422864ns
I1122 02:45:56.454336 14210 replica.cpp:676] Persisted action at 0
I1122 02:45:56.455329 14201 replica.cpp:508] Replica received write request for
position 0
I1122 02:45:56.455386 14201 leveldb.cpp:438] Reading position from leveldb took
26442ns
I1122 02:45:56.455867 14201 leveldb.cpp:343] Persisting action (14 bytes) to
leveldb took 447132ns
I1122 02:45:56.455893 14201 replica.cpp:676] Persisted action at 0
I1122 02:45:56.456486 14210 replica.cpp:655] Replica received learned notice
for position 0
I1122 02:45:56.456934 14210 leveldb.cpp:343] Persisting action (16 bytes) to
leveldb took 417880ns
I1122 02:45:56.456960 14210 replica.cpp:676] Persisted action at 0
I1122 02:45:56.456981 14210 replica.cpp:661] Replica learned NOP action at
position 0
I1122 02:45:56.457437 14208 log.cpp:672] Writer started with ending position 0
I1122 02:45:56.458385 14211 leveldb.cpp:438] Reading position from leveldb took
27829ns
I1122 02:45:56.461175 14199 registrar.cpp:346] Successfully fetched the
registry (0B) in 11.259136ms
I1122 02:45:56.461264 14199 registrar.cpp:445] Applied 1 operations in 16909ns;
attempting to update the 'registry'
I1122 02:45:56.464001 14200 log.cpp:680] Attempting to append 139 bytes to the
log
I1122 02:45:56.464154 14205 coordinator.cpp:340] Coordinator attempting to
write APPEND action at position 1
I1122 02:45:56.464997 14199 replica.cpp:508] Replica received write request for
position 1
I1122 02:45:56.465515 14199 leveldb.cpp:343] Persisting action (158 bytes) to
leveldb took 485555ns
I1122 02:45:56.465543 14199 replica.cpp:676] Persisted action at 1
I1122 02:45:56.466168 14204 replica.cpp:655] Replica received learned notice
for position 1
I1122 02:45:56.466608 14204 leveldb.cpp:343] Persisting action (160 bytes) to
leveldb took 407299ns
I1122 02:45:56.466635 14204 replica.cpp:676] Persisted action at 1
I1122 02:45:56.466656 14204 replica.cpp:661] Replica learned APPEND action at
position 1
I1122 02:45:56.467424 14213 registrar.cpp:490] Successfully updated the
'registry' in 6.087936ms
I1122 02:45:56.467548 14213 registrar.cpp:376] Successfully recovered registrar
I1122 02:45:56.467597 14199 log.cpp:699] Attempting to truncate the log to 1
I1122 02:45:56.467788 14198 coordinator.cpp:340] Coordinator attempting to
write TRUNCATE action at position 2
I1122 02:45:56.467823 14203 master.cpp:1121] Recovered 0 slaves from the
Registry (101B) ; allowing 10mins for slaves to re-register
I1122 02:45:56.468619 14210 replica.cpp:508] Replica received write request for
position 2
I1122 02:45:56.469063 14210 leveldb.cpp:343] Persisting action (16 bytes) to
leveldb took 407815ns
I1122 02:45:56.469089 14210 replica.cpp:676] Persisted action at 2
I1122 02:45:56.469738 14202 replica.cpp:655] Replica received learned notice
for position 2
I1122 02:45:56.470185 14202 leveldb.cpp:343] Persisting action (18 bytes) to
leveldb took 413530ns
I1122 02:45:56.470242 14202 leveldb.cpp:401] Deleting ~1 keys from leveldb took
31536ns
I1122 02:45:56.470260 14202 replica.cpp:676] Persisted action at 2
I1122 02:45:56.470299 14202 replica.cpp:661] Replica learned TRUNCATE action at
position 2
I1122 02:45:56.483842 14184 sched.cpp:148] Version: 0.22.0
I1122 02:45:56.484411 14213 sched.cpp:245] New master detected at
master@67.195.81.187:59073
I1122 02:45:56.484465 14213 sched.cpp:301] Authenticating with master
master@67.195.81.187:59073
I1122 02:45:56.484483 14213 sched.cpp:308] Using default CRAM-MD5 authenticatee
I1122 02:45:56.484756 14211 authenticatee.hpp:138] Creating new client SASL
connection
I1122 02:45:56.484962 14208 master.cpp:3874] Authenticating
scheduler-4dc5e91d-72df-4049-bb03-2fe412d1563a@67.195.81.187:59073
I1122 02:45:56.484993 14208 master.cpp:3885] Using default CRAM-MD5
authenticator
I1122 02:45:56.485263 14203 authenticator.hpp:170] Creating new server SASL
connection
I1122 02:45:56.485566 14212 authenticatee.hpp:229] Received SASL authentication
mechanisms: CRAM-MD5
I1122 02:45:56.485597 14212 authenticatee.hpp:255] Attempting to authenticate
with mechanism 'CRAM-MD5'
I1122 02:45:56.485692 14210 authenticator.hpp:276] Received SASL authentication
start
I1122 02:45:56.485770 14210 authenticator.hpp:398] Authentication requires more
steps
I1122 02:45:56.485863 14212 authenticatee.hpp:275] Received SASL authentication
step
I1122 02:45:56.485985 14210 authenticator.hpp:304] Received SASL authentication
step
I1122 02:45:56.486016 14210 auxprop.cpp:99] Request to lookup properties for
user: 'test-principal' realm: 'pomona.apache.org' server FQDN:
'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1122 02:45:56.486029 14210 auxprop.cpp:171] Looking up auxiliary property
'*userPassword'
I1122 02:45:56.486063 14210 auxprop.cpp:171] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I1122 02:45:56.486089 14210 auxprop.cpp:99] Request to lookup properties for
user: 'test-principal' realm: 'pomona.apache.org' server FQDN:
'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1122 02:45:56.486102 14210 auxprop.cpp:121] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I1122 02:45:56.486110 14210 auxprop.cpp:121] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1122 02:45:56.486127 14210 authenticator.hpp:390] Authentication success
I1122 02:45:56.486212 14208 authenticatee.hpp:315] Authentication success
I1122 02:45:56.486238 14202 master.cpp:3932] Successfully authenticated
principal 'test-principal' at
scheduler-4dc5e91d-72df-4049-bb03-2fe412d1563a@67.195.81.187:59073
I1122 02:45:56.486446 14205 sched.cpp:389] Successfully authenticated with
master master@67.195.81.187:59073
I1122 02:45:56.486472 14205 sched.cpp:512] Sending registration request to
master@67.195.81.187:59073
I1122 02:45:56.486513 14205 sched.cpp:545] Will retry registration in
1.563529507secs if necessary
I1122 02:45:56.486574 14202 master.cpp:1383] Received registration request for
framework 'default' at
scheduler-4dc5e91d-72df-4049-bb03-2fe412d1563a@67.195.81.187:59073
I1122 02:45:56.486631 14202 master.cpp:1342] Authorizing framework principal
'test-principal' to receive offers for role '*'
I1122 02:45:56.486928 14198 master.cpp:1447] Registering framework
20141122-024556-3142697795-59073-14184-0000 (default) at
scheduler-4dc5e91d-72df-4049-bb03-2fe412d1563a@67.195.81.187:59073
I1122 02:45:56.487177 14204 hierarchical_allocator_process.hpp:329] Added
framework 20141122-024556-3142697795-59073-14184-0000
I1122 02:45:56.487206 14204 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I1122 02:45:56.487223 14204 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 19950ns
I1122 02:45:56.487452 14207 sched.cpp:439] Framework registered with
20141122-024556-3142697795-59073-14184-0000
I1122 02:45:56.487524 14207 sched.cpp:453] Scheduler::registered took 42286ns
I1122 02:45:56.488739 14199 process.cpp:2910] Handling HTTP event for process
'metrics' with path: '/metrics//snapshot'
Sat Nov 22 03:15:49 UTC 2014: process still running after 1800 seconds
==========
Attaching gdb to 14023 bash ../support/timed_tests.sh GLOG_v=1 MESOS_VERBOSE=1
make check GTEST_SHUFFLE=1 GTEST_OUTPUT=xml: 1800
==========
../support/timed_tests.sh: line 72: gdb: command not found
==========
Attaching gdb to 14026 bash ../support/timed_tests.sh GLOG_v=1 MESOS_VERBOSE=1
make check GTEST_SHUFFLE=1 GTEST_OUTPUT=xml: 1800
==========
../support/timed_tests.sh: line 72: gdb: command not found
==========
Attaching gdb to 14028 make check GTEST_SHUFFLE=1 GTEST_OUTPUT=xml:
==========
../support/timed_tests.sh: line 72: gdb: command not found
==========
Attaching gdb to 14032 /bin/bash -c fail=; \ if (target_option=k; case
${target_option-} in ?) ;; *) echo "am__make_running_with_option: internal
error: invalid" "target option '${target_option-}' specified" >&2; exit 1;;
esac; has_opt=no; sane_makeflags=$MAKEFLAGS; if test -n ' Makefile' && test -n
'0'; then sane_makeflags=$MFLAGS; else case $MAKEFLAGS in *\\[\ \.]*) bs=\\;
sane_makeflags=`printf '%s\n' "$MAKEFLAGS" | sed "s/$bs$bs[$bs $bs.]*//g"`;;
esac; fi; skip_next=no; strip_trailopt () { flg=`printf '%s\n' "$flg" | sed
"s/$1.*$//"`; }; for flg in $sane_makeflags; do test $skip_next = yes && {
skip_next=no; continue; }; case $flg in *=*|--*) continue;; -*I) strip_trailopt
'I'; skip_next=yes;; -*I?*) strip_trailopt 'I';; -*O) strip_trailopt 'O';
skip_next=yes;; -*O?*) strip_trailopt 'O';; -*l) strip_trailopt 'l';
skip_next=yes;; -*l?*) strip_trailopt 'l';; -[dEDm]) skip_next=yes;; -[JT])
skip_next=yes;; esac; case $flg in *$target_option*) has_opt=yes; break;; esac;
done; test $has_opt = yes); then \ failcom='fail=yes'; \ else \
failcom='exit 1'; \ fi; \ dot_seen=no; \ target=`echo check-recursive | sed
s/-recursive//`; \ case "check-recursive" in \ distclean-* |
maintainer-clean-*) list='. 3rdparty src ec2' ;; \ *) list='. 3rdparty src
ec2' ;; \ esac; \ for subdir in $list; do \ echo "Making $target in $subdir";
\ if test "$subdir" = "."; then \ dot_seen=yes; \
local_target="$target-am"; \ else \ local_target="$target"; \ fi; \
(CDPATH="${ZSH_VERSION+.}:" && cd $subdir && make $local_target) \ || eval
$failcom; \ done; \ if test "$dot_seen" = "no"; then \ make "$target-am" ||
exit 1; \ fi; test -z "$fail"
==========
../support/timed_tests.sh: line 72: gdb: command not found
==========
Attaching gdb to 14174 /bin/bash -c fail=; \ if (target_option=k; case
${target_option-} in ?) ;; *) echo "am__make_running_with_option: internal
error: invalid" "target option '${target_option-}' specified" >&2; exit 1;;
esac; has_opt=no; sane_makeflags=$MAKEFLAGS; if test -n ' Makefile' && test -n
'0'; then sane_makeflags=$MFLAGS; else case $MAKEFLAGS in *\\[\ \.]*) bs=\\;
sane_makeflags=`printf '%s\n' "$MAKEFLAGS" | sed "s/$bs$bs[$bs $bs.]*//g"`;;
esac; fi; skip_next=no; strip_trailopt () { flg=`printf '%s\n' "$flg" | sed
"s/$1.*$//"`; }; for flg in $sane_makeflags; do test $skip_next = yes && {
skip_next=no; continue; }; case $flg in *=*|--*) continue;; -*I) strip_trailopt
'I'; skip_next=yes;; -*I?*) strip_trailopt 'I';; -*O) strip_trailopt 'O';
skip_next=yes;; -*O?*) strip_trailopt 'O';; -*l) strip_trailopt 'l';
skip_next=yes;; -*l?*) strip_trailopt 'l';; -[dEDm]) skip_next=yes;; -[JT])
skip_next=yes;; esac; case $flg in *$target_option*) has_opt=yes; break;; esac;
done; test $has_opt = yes); then \ failcom='fail=yes'; \ else \
failcom='exit 1'; \ fi; \ dot_seen=no; \ target=`echo check-recursive | sed
s/-recursive//`; \ case "check-recursive" in \ distclean-* |
maintainer-clean-*) list='. 3rdparty src ec2' ;; \ *) list='. 3rdparty src
ec2' ;; \ esac; \ for subdir in $list; do \ echo "Making $target in $subdir";
\ if test "$subdir" = "."; then \ dot_seen=yes; \
local_target="$target-am"; \ else \ local_target="$target"; \ fi; \
(CDPATH="${ZSH_VERSION+.}:" && cd $subdir && make $local_target) \ || eval
$failcom; \ done; \ if test "$dot_seen" = "no"; then \ make "$target-am" ||
exit 1; \ fi; test -z "$fail"
==========
../support/timed_tests.sh: line 72: gdb: command not found
==========
Attaching gdb to 14175 make check
==========
../support/timed_tests.sh: line 72: gdb: command not found
==========
Attaching gdb to 14176 make check-am
==========
../support/timed_tests.sh: line 72: gdb: command not found
==========
Attaching gdb to 14183 make check-local
==========
../support/timed_tests.sh: line 72: gdb: command not found
==========
Attaching gdb to 14184
<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src/.libs/lt-mesos-tests>
==========
../support/timed_tests.sh: line 72: gdb: command not found
Test failed and killing the stuck test process
W1122 02:45:56.488739 14184 logging.cpp:81] RAW: Received signal SIGTERM from
process 6318 of user 2395; exiting
make: *** [check-recursive] Terminated
/tmp/hudson428561946673777410.sh: line 16: 14023 Terminated
../support/timed_tests.sh "GLOG_v=1 MESOS_VERBOSE=1 make check GTEST_SHUFFLE=1
GTEST_OUTPUT=xml:" 1800
make[3]: *** [check-local] Terminated
Build step 'Execute shell' marked build as failure
Recording test results
