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/10/29 21:01:44 UTC
Build failed in Jenkins:
Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME #2229
See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/2229/changes>
Changes:
[idownes] Define MNT_DETACH for pid isolator.
------------------------------------------
[...truncated 69433 lines...]
I1029 20:01:09.767547 27824 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1029 20:01:09.767561 27824 authenticator.hpp:381] Authentication success
I1029 20:01:09.767650 27824 authenticatee.hpp:310] Authentication success
I1029 20:01:09.767752 27820 master.cpp:3893] Successfully authenticated principal 'test-principal' at scheduler-433d5fe0-5dd8-4eb7-96a1-75a171494d2f@67.195.81.190:41000
I1029 20:01:09.768019 27824 sched.cpp:357] Successfully authenticated with master master@67.195.81.190:41000
I1029 20:01:09.768048 27824 sched.cpp:476] Sending registration request to master@67.195.81.190:41000
I1029 20:01:09.768321 27820 master.cpp:1362] Received registration request for framework 'framework3' at scheduler-433d5fe0-5dd8-4eb7-96a1-75a171494d2f@67.195.81.190:41000
I1029 20:01:09.768384 27820 master.cpp:1321] Authorizing framework principal 'test-principal' to receive offers for role 'role3'
I1029 20:01:09.768911 27823 master.cpp:1426] Registering framework 20141029-200107-3193029443-41000-27796-0002 (framework3) at scheduler-433d5fe0-5dd8-4eb7-96a1-75a171494d2f@67.195.81.190:41000
I1029 20:01:09.769162 27817 sched.cpp:407] Framework registered with 20141029-200107-3193029443-41000-27796-0002
I1029 20:01:09.769201 27817 sched.cpp:421] Scheduler::registered took 16443ns
I1029 20:01:09.769261 27825 hierarchical_allocator_process.hpp:329] Added framework 20141029-200107-3193029443-41000-27796-0002
I1029 20:01:09.769722 27825 hierarchical_allocator_process.hpp:734] Offering cpus(role3):4; mem(role3):4096; disk(role3):0; ports(role3):[31000-32000] on slave 20141029-200107-3193029443-41000-27796-S2 to framework 20141029-200107-3193029443-41000-27796-0002
I1029 20:01:09.770187 27825 hierarchical_allocator_process.hpp:659] Performed allocation for 4 slaves in 903391ns
I1029 20:01:09.770460 27819 master.cpp:3795] Sending 1 offers to framework 20141029-200107-3193029443-41000-27796-0002 (framework3) at scheduler-433d5fe0-5dd8-4eb7-96a1-75a171494d2f@67.195.81.190:41000
I1029 20:01:09.770774 27816 sched.cpp:544] Scheduler::resourceOffers took 45045ns
I1029 20:01:09.772645 27796 containerizer.cpp:100] Using isolation: posix/cpu,posix/mem
I1029 20:01:09.776811 27820 slave.cpp:169] Slave started on 221)@67.195.81.190:41000
I1029 20:01:09.776852 27820 credentials.hpp:84] Loading credential for authentication from '/tmp/ReservationAllocatorTest_ReservedResources_amUsCX/credential'
I1029 20:01:09.777021 27820 slave.cpp:276] Slave using credential for: test-principal
I1029 20:01:09.777241 27820 slave.cpp:289] Slave resources: cpus(role1):1; mem(role1):512; disk(role1):0; ports(role1):[31000-32000]
I1029 20:01:09.777340 27820 slave.cpp:318] Slave hostname: pietas.apache.org
I1029 20:01:09.777358 27820 slave.cpp:319] Slave checkpoint: false
W1029 20:01:09.777366 27820 slave.cpp:321] Disabling checkpointing is deprecated and the --checkpoint flag will be removed in a future release. Please avoid using this flag
I1029 20:01:09.778183 27811 state.cpp:33] Recovering state from '/tmp/ReservationAllocatorTest_ReservedResources_amUsCX/meta'
I1029 20:01:09.778393 27817 status_update_manager.cpp:197] Recovering status update manager
I1029 20:01:09.778676 27815 containerizer.cpp:281] Recovering containerizer
I1029 20:01:09.779857 27816 slave.cpp:3456] Finished recovery
I1029 20:01:09.780598 27816 slave.cpp:602] New master detected at master@67.195.81.190:41000
I1029 20:01:09.780638 27816 slave.cpp:665] Authenticating with master master@67.195.81.190:41000
I1029 20:01:09.780674 27825 status_update_manager.cpp:171] Pausing sending status updates
I1029 20:01:09.780791 27816 slave.cpp:638] Detecting new master
I1029 20:01:09.780843 27818 authenticatee.hpp:133] Creating new client SASL connection
I1029 20:01:09.781141 27810 master.cpp:3853] Authenticating slave(221)@67.195.81.190:41000
I1029 20:01:09.781342 27816 authenticator.hpp:161] Creating new server SASL connection
I1029 20:01:09.781508 27816 authenticatee.hpp:224] Received SASL authentication mechanisms: CRAM-MD5
I1029 20:01:09.781529 27816 authenticatee.hpp:250] Attempting to authenticate with mechanism 'CRAM-MD5'
I1029 20:01:09.781632 27824 authenticator.hpp:267] Received SASL authentication start
I1029 20:01:09.781687 27824 authenticator.hpp:389] Authentication requires more steps
I1029 20:01:09.781771 27824 authenticatee.hpp:270] Received SASL authentication step
I1029 20:01:09.781875 27824 authenticator.hpp:295] Received SASL authentication step
I1029 20:01:09.781903 27824 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pietas.apache.org' server FQDN: 'pietas.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1029 20:01:09.781915 27824 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I1029 20:01:09.781945 27824 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1029 20:01:09.781968 27824 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pietas.apache.org' server FQDN: 'pietas.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1029 20:01:09.781980 27824 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1029 20:01:09.781988 27824 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1029 20:01:09.782004 27824 authenticator.hpp:381] Authentication success
I1029 20:01:09.782112 27824 authenticatee.hpp:310] Authentication success
I1029 20:01:09.782143 27821 master.cpp:3893] Successfully authenticated principal 'test-principal' at slave(221)@67.195.81.190:41000
I1029 20:01:09.782546 27824 slave.cpp:722] Successfully authenticated with master master@67.195.81.190:41000
I1029 20:01:09.782659 27824 slave.cpp:1050] Will retry registration in 11.769712ms if necessary
I1029 20:01:09.782820 27815 master.cpp:3032] Registering slave at slave(221)@67.195.81.190:41000 (pietas.apache.org) with id 20141029-200107-3193029443-41000-27796-S4
I1029 20:01:09.783329 27817 registrar.cpp:445] Applied 1 operations in 133421ns; attempting to update the 'registry'
I1029 20:01:09.785845 27817 log.cpp:680] Attempting to append 1127 bytes to the log
I1029 20:01:09.795310 27810 slave.cpp:1050] Will retry registration in 37.030767ms if necessary
I1029 20:01:09.795497 27814 master.cpp:3020] Ignoring register slave message from slave(221)@67.195.81.190:41000 (pietas.apache.org) as admission is already in progress
I1029 20:01:09.913693 27811 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 9
I1029 20:01:09.914785 27819 replica.cpp:508] Replica received write request for position 9
I1029 20:01:09.915117 27819 leveldb.cpp:343] Persisting action (1146 bytes) to leveldb took 294042ns
I1029 20:01:09.915148 27819 replica.cpp:676] Persisted action at 9
I1029 20:01:09.916208 27815 replica.cpp:655] Replica received learned notice for position 9
I1029 20:01:09.916882 27815 leveldb.cpp:343] Persisting action (1148 bytes) to leveldb took 644425ns
I1029 20:01:09.916908 27815 replica.cpp:676] Persisted action at 9
I1029 20:01:09.916930 27815 replica.cpp:661] Replica learned APPEND action at position 9
I1029 20:01:09.918350 27820 registrar.cpp:490] Successfully updated the 'registry' in 134.961152ms
I1029 20:01:09.918740 27813 log.cpp:699] Attempting to truncate the log to 9
I1029 20:01:09.918941 27810 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 10
I1029 20:01:09.919064 27816 slave.cpp:2522] Received ping from slave-observer(201)@67.195.81.190:41000
I1029 20:01:09.919123 27811 master.cpp:3086] Registered slave 20141029-200107-3193029443-41000-27796-S4 at slave(221)@67.195.81.190:41000 (pietas.apache.org) with cpus(role1):1; mem(role1):512; disk(role1):0; ports(role1):[31000-32000]
I1029 20:01:09.919225 27816 slave.cpp:756] Registered with master master@67.195.81.190:41000; given slave ID 20141029-200107-3193029443-41000-27796-S4
I1029 20:01:09.919546 27822 status_update_manager.cpp:178] Resuming sending status updates
I1029 20:01:09.919711 27810 hierarchical_allocator_process.hpp:442] Added slave 20141029-200107-3193029443-41000-27796-S4 (pietas.apache.org) with cpus(role1):1; mem(role1):512; disk(role1):0; ports(role1):[31000-32000] (and cpus(role1):1; mem(role1):512; disk(role1):0; ports(role1):[31000-32000] available)
I1029 20:01:09.919790 27822 replica.cpp:508] Replica received write request for position 10
I1029 20:01:09.920136 27822 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 311126ns
I1029 20:01:09.920131 27810 hierarchical_allocator_process.hpp:734] Offering cpus(role1):1; mem(role1):512; disk(role1):0; ports(role1):[31000-32000] on slave 20141029-200107-3193029443-41000-27796-S4 to framework 20141029-200107-3193029443-41000-27796-0000
I1029 20:01:09.920161 27822 replica.cpp:676] Persisted action at 10
I1029 20:01:09.920377 27810 hierarchical_allocator_process.hpp:679] Performed allocation for slave 20141029-200107-3193029443-41000-27796-S4 in 583079ns
I1029 20:01:09.920769 27811 replica.cpp:655] Replica received learned notice for position 10
I1029 20:01:09.920958 27817 master.cpp:3795] Sending 1 offers to framework 20141029-200107-3193029443-41000-27796-0000 (framework1) at scheduler-bf4f0d6f-a260-4866-aa57-59024a517c4d@67.195.81.190:41000
I1029 20:01:09.921269 27811 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 474524ns
I1029 20:01:09.921293 27813 sched.cpp:544] Scheduler::resourceOffers took 49416ns
I1029 20:01:09.921353 27811 leveldb.cpp:401] Deleting ~2 keys from leveldb took 54019ns
I1029 20:01:09.921383 27811 replica.cpp:676] Persisted action at 10
I1029 20:01:09.921417 27811 replica.cpp:661] Replica learned TRUNCATE action at position 10
I1029 20:01:09.921733 27814 sched.cpp:745] Stopping framework '20141029-200107-3193029443-41000-27796-0002'
I1029 20:01:09.921768 27815 sched.cpp:745] Stopping framework '20141029-200107-3193029443-41000-27796-0000'
I1029 20:01:09.921787 27816 sched.cpp:745] Stopping framework '20141029-200107-3193029443-41000-27796-0001'
I1029 20:01:09.921880 27821 master.cpp:677] Master terminating
I1029 20:01:09.924136 27816 slave.cpp:2607] master@67.195.81.190:41000 exited
W1029 20:01:09.924165 27816 slave.cpp:2610] Master disconnected! Waiting for a new master to be elected
I1029 20:01:09.924201 27813 slave.cpp:2607] master@67.195.81.190:41000 exited
W1029 20:01:09.924247 27813 slave.cpp:2610] Master disconnected! Waiting for a new master to be elected
I1029 20:01:09.924223 27810 slave.cpp:2607] master@67.195.81.190:41000 exited
W1029 20:01:09.924288 27810 slave.cpp:2610] Master disconnected! Waiting for a new master to be elected
I1029 20:01:09.924309 27819 slave.cpp:2607] master@67.195.81.190:41000 exited
I1029 20:01:09.924320 27818 slave.cpp:2607] master@67.195.81.190:41000 exited
W1029 20:01:09.924342 27819 slave.cpp:2610] Master disconnected! Waiting for a new master to be elected
W1029 20:01:09.924358 27818 slave.cpp:2610] Master disconnected! Waiting for a new master to be elected
I1029 20:01:09.930064 27796 slave.cpp:484] Slave terminating
I1029 20:01:09.932471 27796 slave.cpp:484] Slave terminating
I1029 20:01:09.934528 27796 slave.cpp:484] Slave terminating
I1029 20:01:09.936530 27817 slave.cpp:484] Slave terminating
I1029 20:01:09.938618 27796 slave.cpp:484] Slave terminating
[ OK ] ReservationAllocatorTest.ReservedResources (2451 ms)
[----------] 2 tests from ReservationAllocatorTest (3094 ms total)
[----------] 2 tests from AttributesTest
[ RUN ] AttributesTest.Equality
[ OK ] AttributesTest.Equality (0 ms)
[ RUN ] AttributesTest.Parsing
[ OK ] AttributesTest.Parsing (1 ms)
[----------] 2 tests from AttributesTest (1 ms total)
[----------] 35 tests from ResourcesTest
[ RUN ] ResourcesTest.Find
[ OK ] ResourcesTest.Find (1 ms)
[ RUN ] ResourcesTest.SetEquals
[ OK ] ResourcesTest.SetEquals (0 ms)
[ RUN ] ResourcesTest.ScalarSubset2
[ OK ] ResourcesTest.ScalarSubset2 (0 ms)
[ RUN ] ResourcesTest.SetAddition
[ OK ] ResourcesTest.SetAddition (0 ms)
[ RUN ] ResourcesTest.ScalarAddition
[ OK ] ResourcesTest.ScalarAddition (0 ms)
[ RUN ] ResourcesTest.RangesSubtraction
[ OK ] ResourcesTest.RangesSubtraction (0 ms)
[ RUN ] ResourcesTest.Ports
[ OK ] ResourcesTest.Ports (1 ms)
[ RUN ] ResourcesTest.ScalarAddition2
[ OK ] ResourcesTest.ScalarAddition2 (0 ms)
[ RUN ] ResourcesTest.EmptyUnequal
[ OK ] ResourcesTest.EmptyUnequal (0 ms)
[ RUN ] ResourcesTest.Printing
[ OK ] ResourcesTest.Printing (0 ms)
[ RUN ] ResourcesTest.ScalarEquals
[ OK ] ResourcesTest.ScalarEquals (0 ms)
[ RUN ] ResourcesTest.RangesSubtraction1
[ OK ] ResourcesTest.RangesSubtraction1 (0 ms)
[ RUN ] ResourcesTest.RangesAddition4
[ OK ] ResourcesTest.RangesAddition4 (1 ms)
[ RUN ] ResourcesTest.RangesAddition2
[ OK ] ResourcesTest.RangesAddition2 (0 ms)
[ RUN ] ResourcesTest.SetSubset
[ OK ] ResourcesTest.SetSubset (0 ms)
[ RUN ] ResourcesTest.RangesSubtraction2
[ OK ] ResourcesTest.RangesSubtraction2 (0 ms)
[ RUN ] ResourcesTest.ScalarSubset
[ OK ] ResourcesTest.ScalarSubset (0 ms)
[ RUN ] ResourcesTest.RangesSubtraction3
[ OK ] ResourcesTest.RangesSubtraction3 (0 ms)
[ RUN ] ResourcesTest.ScalarSubtraction2
[ OK ] ResourcesTest.ScalarSubtraction2 (0 ms)
[ RUN ] ResourcesTest.FlattenRoles
[ OK ] ResourcesTest.FlattenRoles (0 ms)
[ RUN ] ResourcesTest.SetSubtraction
[ OK ] ResourcesTest.SetSubtraction (1 ms)
[ RUN ] ResourcesTest.RangesAddition
[ OK ] ResourcesTest.RangesAddition (0 ms)
[ RUN ] ResourcesTest.RangesSubtraction5
[ OK ] ResourcesTest.RangesSubtraction5 (0 ms)
[ RUN ] ResourcesTest.Resources
[ OK ] ResourcesTest.Resources (0 ms)
[ RUN ] ResourcesTest.ScalarSubtraction
[ OK ] ResourcesTest.ScalarSubtraction (0 ms)
[ RUN ] ResourcesTest.RangesSubtraction4
[ OK ] ResourcesTest.RangesSubtraction4 (0 ms)
[ RUN ] ResourcesTest.RangesSubtraction6
[ OK ] ResourcesTest.RangesSubtraction6 (0 ms)
[ RUN ] ResourcesTest.BadResourcesNotAllocatable
[ OK ] ResourcesTest.BadResourcesNotAllocatable (0 ms)
[ RUN ] ResourcesTest.ParseError
[ OK ] ResourcesTest.ParseError (0 ms)
[ RUN ] ResourcesTest.ParsingWithRoles
[ OK ] ResourcesTest.ParsingWithRoles (0 ms)
[ RUN ] ResourcesTest.InitializedIsEmpty
[ OK ] ResourcesTest.InitializedIsEmpty (0 ms)
[ RUN ] ResourcesTest.RangesAdditon3
[ OK ] ResourcesTest.RangesAdditon3 (1 ms)
[ RUN ] ResourcesTest.RangesSubset
[ OK ] ResourcesTest.RangesSubset (0 ms)
[ RUN ] ResourcesTest.RangesEquals
[ OK ] ResourcesTest.RangesEquals (0 ms)
[ RUN ] ResourcesTest.Parsing
[ OK ] ResourcesTest.Parsing (0 ms)
[----------] 35 tests from ResourcesTest (117 ms total)
[----------] 3 tests from GarbageCollectorTest
[ RUN ] GarbageCollectorTest.Unschedule
Using temporary directory '/tmp/GarbageCollectorTest_Unschedule_AWxnXw'
I1029 20:01:10.063221 27812 gc.cpp:84] Unscheduling 'bogus' from gc
I1029 20:01:10.063886 27812 gc.cpp:56] Scheduling 'file1' for gc 10secs in the future
I1029 20:01:10.064044 27812 gc.cpp:56] Scheduling 'file2' for gc 10secs in the future
I1029 20:01:10.064129 27812 gc.cpp:56] Scheduling 'file3' for gc 10secs in the future
I1029 20:01:10.064209 27812 gc.cpp:84] Unscheduling 'file2' from gc
I1029 20:01:10.074157 27822 gc.cpp:84] Unscheduling 'file3' from gc
I1029 20:01:10.084421 27823 gc.cpp:84] Unscheduling 'file1' from gc
I1029 20:01:10.096211 27821 gc.cpp:155] Ignoring gc event at 0ns as the paths were already removed, or were unscheduled
[ OK ] GarbageCollectorTest.Unschedule (73 ms)
[ RUN ] GarbageCollectorTest.Prune
Using temporary directory '/tmp/GarbageCollectorTest_Prune_QII2t6'
I1029 20:01:10.135681 27818 gc.cpp:56] Scheduling 'file1' for gc 10secs in the future
I1029 20:01:10.135833 27818 gc.cpp:56] Scheduling 'file2' for gc 10secs in the future
I1029 20:01:10.135920 27818 gc.cpp:56] Scheduling 'file3' for gc 15secs in the future
I1029 20:01:10.135999 27818 gc.cpp:56] Scheduling 'file4' for gc 15secs in the future
I1029 20:01:10.136077 27818 gc.cpp:84] Unscheduling 'file3' from gc
I1029 20:01:10.156009 27813 gc.cpp:167] Pruning directories with remaining removal time 10secs
I1029 20:01:10.156090 27813 gc.cpp:134] Deleting file1
I1029 20:01:10.156141 27813 gc.cpp:143] Deleted 'file1'
I1029 20:01:10.156167 27813 gc.cpp:134] Deleting file2
I1029 20:01:10.156199 27813 gc.cpp:143] Deleted 'file2'
I1029 20:01:10.176352 27816 gc.cpp:167] Pruning directories with remaining removal time 15secs
I1029 20:01:10.176508 27816 gc.cpp:134] Deleting file4
I1029 20:01:10.176563 27816 gc.cpp:143] Deleted 'file4'
[ OK ] GarbageCollectorTest.Prune (51 ms)
[ RUN ] GarbageCollectorTest.Schedule
Using temporary directory '/tmp/GarbageCollectorTest_Schedule_yE838F'
I1029 20:01:10.187319 27816 gc.cpp:56] Scheduling 'file1' for gc 10secs in the future
I1029 20:01:10.187497 27816 gc.cpp:56] Scheduling 'file2' for gc 10secs in the future
I1029 20:01:10.187609 27816 gc.cpp:56] Scheduling 'file3' for gc 15secs in the future
I1029 20:01:10.228978 27815 gc.cpp:134] Deleting file1
I1029 20:01:10.229038 27815 gc.cpp:143] Deleted 'file1'
I1029 20:01:10.229069 27815 gc.cpp:134] Deleting file2
I1029 20:01:10.229109 27815 gc.cpp:143] Deleted 'file2'
I1029 20:01:10.258406 27823 gc.cpp:134] Deleting file3
I1029 20:01:10.258491 27823 gc.cpp:143] Deleted 'file3'
[ OK ] GarbageCollectorTest.Schedule (92 ms)
[----------] 3 tests from GarbageCollectorTest (216 ms total)
[----------] Global test environment tear-down
[==========] 449 tests from 70 test cases ran. (283265 ms total)
[ PASSED ] 448 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] HealthCheckTest.GracePeriod
1 FAILED TEST
YOU HAVE 6 DISABLED TESTS
make[3]: *** [check-local] Error 1
make[3]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'>
make[2]: *** [check-am] Error 2
make[2]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'>
make[1]: *** [check] Error 2
make[1]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'>
make: *** [check-recursive] Error 1
Test finished
Exit status: 2
Build step 'Execute shell' marked build as failure
Recording test results
Build failed in Jenkins:
Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME #2230
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/2230/changes>
Changes:
[vinodkone] Added MesosCon'14 playlist to presentations.
------------------------------------------
[...truncated 15872 lines...]
I1030 05:54:04.505708 29517 replica.cpp:676] Persisted action at 2
I1030 05:54:04.505733 29517 replica.cpp:661] Replica learned TRUNCATE action at position 2
I1030 05:54:04.518836 29520 slave.cpp:169] Slave started on 27)@67.195.81.187:54775
I1030 05:54:04.518879 29520 credentials.hpp:84] Loading credential for authentication from '/tmp/ReconciliationTest_TaskStateMismatch_jXTxgL/credential'
I1030 05:54:04.519043 29520 slave.cpp:276] Slave using credential for: test-principal
I1030 05:54:04.519332 29520 slave.cpp:289] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1030 05:54:04.519435 29520 slave.cpp:318] Slave hostname: pomona.apache.org
I1030 05:54:04.519454 29520 slave.cpp:319] Slave checkpoint: false
W1030 05:54:04.519462 29520 slave.cpp:321] Disabling checkpointing is deprecated and the --checkpoint flag will be removed in a future release. Please avoid using this flag
I1030 05:54:04.520382 29526 state.cpp:33] Recovering state from '/tmp/ReconciliationTest_TaskStateMismatch_jXTxgL/meta'
I1030 05:54:04.521198 29519 status_update_manager.cpp:197] Recovering status update manager
I1030 05:54:04.521605 29521 slave.cpp:3456] Finished recovery
I1030 05:54:04.522595 29515 status_update_manager.cpp:171] Pausing sending status updates
I1030 05:54:04.522593 29524 slave.cpp:602] New master detected at master@67.195.81.187:54775
I1030 05:54:04.522677 29524 slave.cpp:665] Authenticating with master master@67.195.81.187:54775
I1030 05:54:04.522855 29524 slave.cpp:638] Detecting new master
I1030 05:54:04.522924 29522 authenticatee.hpp:133] Creating new client SASL connection
I1030 05:54:04.523164 29512 master.cpp:3853] Authenticating slave(27)@67.195.81.187:54775
I1030 05:54:04.523605 29523 authenticator.hpp:161] Creating new server SASL connection
I1030 05:54:04.523784 29523 authenticatee.hpp:224] Received SASL authentication mechanisms: CRAM-MD5
I1030 05:54:04.523813 29523 authenticatee.hpp:250] Attempting to authenticate with mechanism 'CRAM-MD5'
I1030 05:54:04.523910 29519 authenticator.hpp:267] Received SASL authentication start
I1030 05:54:04.524049 29519 authenticator.hpp:389] Authentication requires more steps
I1030 05:54:04.524139 29519 authenticatee.hpp:270] Received SASL authentication step
I1030 05:54:04.524343 29524 authenticator.hpp:295] Received SASL authentication step
I1030 05:54:04.524382 29524 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1030 05:54:04.524395 29524 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I1030 05:54:04.524438 29524 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1030 05:54:04.524466 29524 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1030 05:54:04.524479 29524 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1030 05:54:04.524488 29524 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1030 05:54:04.524507 29524 authenticator.hpp:381] Authentication success
I1030 05:54:04.524592 29523 authenticatee.hpp:310] Authentication success
I1030 05:54:04.524618 29524 master.cpp:3893] Successfully authenticated principal 'test-principal' at slave(27)@67.195.81.187:54775
I1030 05:54:04.524847 29519 slave.cpp:722] Successfully authenticated with master master@67.195.81.187:54775
I1030 05:54:04.525086 29519 slave.cpp:1050] Will retry registration in 1.045728ms if necessary
I1030 05:54:04.525368 29524 master.cpp:3032] Registering slave at slave(27)@67.195.81.187:54775 (pomona.apache.org) with id 20141030-055359-3142697795-54775-29497-S0
I1030 05:54:04.525885 29523 registrar.cpp:445] Applied 1 operations in 94940ns; attempting to update the 'registry'
I1030 05:54:04.526000 29497 sched.cpp:137] Version: 0.21.0
I1030 05:54:04.526583 29521 slave.cpp:1050] Will retry registration in 17.399441ms if necessary
I1030 05:54:04.526733 29526 master.cpp:3020] Ignoring register slave message from slave(27)@67.195.81.187:54775 (pomona.apache.org) as admission is already in progress
I1030 05:54:04.526758 29514 sched.cpp:233] New master detected at master@67.195.81.187:54775
I1030 05:54:04.526803 29514 sched.cpp:283] Authenticating with master master@67.195.81.187:54775
I1030 05:54:04.527016 29518 authenticatee.hpp:133] Creating new client SASL connection
I1030 05:54:04.527230 29524 master.cpp:3853] Authenticating scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775
I1030 05:54:04.527487 29512 authenticator.hpp:161] Creating new server SASL connection
I1030 05:54:04.527606 29516 authenticatee.hpp:224] Received SASL authentication mechanisms: CRAM-MD5
I1030 05:54:04.527649 29516 authenticatee.hpp:250] Attempting to authenticate with mechanism 'CRAM-MD5'
I1030 05:54:04.527742 29516 authenticator.hpp:267] Received SASL authentication start
I1030 05:54:04.527794 29516 authenticator.hpp:389] Authentication requires more steps
I1030 05:54:04.527885 29516 authenticatee.hpp:270] Received SASL authentication step
I1030 05:54:04.527986 29516 authenticator.hpp:295] Received SASL authentication step
I1030 05:54:04.528019 29516 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1030 05:54:04.528034 29516 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I1030 05:54:04.528065 29516 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1030 05:54:04.528090 29516 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1030 05:54:04.528101 29516 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1030 05:54:04.528110 29516 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1030 05:54:04.529158 29524 log.cpp:680] Attempting to append 316 bytes to the log
I1030 05:54:04.545205 29511 slave.cpp:1050] Will retry registration in 50.72335ms if necessary
I1030 05:54:04.545310 29519 master.cpp:3020] Ignoring register slave message from slave(27)@67.195.81.187:54775 (pomona.apache.org) as admission is already in progress
I1030 05:54:05.499511 29514 hierarchical_allocator_process.hpp:697] No resources available to allocate!
I1030 05:54:07.770174 29516 authenticator.hpp:381] Authentication success
I1030 05:54:07.770304 29514 hierarchical_allocator_process.hpp:659] Performed allocation for 0 slaves in 2.270803805secs
I1030 05:54:07.770408 29521 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I1030 05:54:07.770439 29512 authenticatee.hpp:310] Authentication success
I1030 05:54:07.770506 29515 master.cpp:3893] Successfully authenticated principal 'test-principal' at scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775
I1030 05:54:07.770843 29512 sched.cpp:357] Successfully authenticated with master master@67.195.81.187:54775
I1030 05:54:07.770891 29512 sched.cpp:476] Sending registration request to master@67.195.81.187:54775
I1030 05:54:07.771092 29515 master.cpp:1362] Received registration request for framework 'default' at scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775
I1030 05:54:07.771183 29515 master.cpp:1321] Authorizing framework principal 'test-principal' to receive offers for role '*'
I1030 05:54:07.771579 29512 replica.cpp:508] Replica received write request for position 3
I1030 05:54:07.771793 29512 leveldb.cpp:343] Persisting action (335 bytes) to leveldb took 173691ns
I1030 05:54:07.771795 29524 master.cpp:1426] Registering framework 20141030-055359-3142697795-54775-29497-0000 (default) at scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775
I1030 05:54:07.771822 29512 replica.cpp:676] Persisted action at 3
I1030 05:54:07.772176 29512 hierarchical_allocator_process.hpp:329] Added framework 20141030-055359-3142697795-54775-29497-0000
I1030 05:54:07.772207 29512 hierarchical_allocator_process.hpp:697] No resources available to allocate!
I1030 05:54:07.772220 29512 hierarchical_allocator_process.hpp:659] Performed allocation for 0 slaves in 19422ns
I1030 05:54:07.772459 29526 sched.cpp:407] Framework registered with 20141030-055359-3142697795-54775-29497-0000
I1030 05:54:07.772558 29526 sched.cpp:421] Scheduler::registered took 65296ns
I1030 05:54:07.772671 29524 replica.cpp:655] Replica received learned notice for position 3
I1030 05:54:07.773195 29524 leveldb.cpp:343] Persisting action (337 bytes) to leveldb took 495300ns
I1030 05:54:07.773221 29524 replica.cpp:676] Persisted action at 3
I1030 05:54:07.773244 29524 replica.cpp:661] Replica learned APPEND action at position 3
I1030 05:54:07.774744 29516 registrar.cpp:490] Successfully updated the 'registry' in 3.248780032secs
I1030 05:54:07.775080 29523 log.cpp:699] Attempting to truncate the log to 3
I1030 05:54:07.775238 29520 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I1030 05:54:07.775401 29523 slave.cpp:2522] Received ping from slave-observer(25)@67.195.81.187:54775
I1030 05:54:07.775495 29519 master.cpp:3086] Registered slave 20141030-055359-3142697795-54775-29497-S0 at slave(27)@67.195.81.187:54775 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1030 05:54:07.775574 29523 slave.cpp:756] Registered with master master@67.195.81.187:54775; given slave ID 20141030-055359-3142697795-54775-29497-S0
I1030 05:54:07.775686 29515 status_update_manager.cpp:178] Resuming sending status updates
I1030 05:54:07.775676 29526 hierarchical_allocator_process.hpp:442] Added slave 20141030-055359-3142697795-54775-29497-S0 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
I1030 05:54:07.775938 29526 hierarchical_allocator_process.hpp:734] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20141030-055359-3142697795-54775-29497-S0 to framework 20141030-055359-3142697795-54775-29497-0000
I1030 05:54:07.776259 29517 replica.cpp:508] Replica received write request for position 4
I1030 05:54:07.776388 29526 hierarchical_allocator_process.hpp:679] Performed allocation for slave 20141030-055359-3142697795-54775-29497-S0 in 627202ns
I1030 05:54:07.776723 29517 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 403977ns
I1030 05:54:07.776726 29514 master.cpp:3795] Sending 1 offers to framework 20141030-055359-3142697795-54775-29497-0000 (default) at scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775
I1030 05:54:07.776757 29517 replica.cpp:676] Persisted action at 4
I1030 05:54:07.777396 29525 replica.cpp:655] Replica received learned notice for position 4
I1030 05:54:07.777694 29524 sched.cpp:544] Scheduler::resourceOffers took 534035ns
I1030 05:54:07.777719 29525 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 295210ns
I1030 05:54:07.777772 29525 leveldb.cpp:401] Deleting ~2 keys from leveldb took 27312ns
I1030 05:54:07.777791 29525 replica.cpp:676] Persisted action at 4
I1030 05:54:07.777813 29525 replica.cpp:661] Replica learned TRUNCATE action at position 4
I1030 05:54:07.778673 29519 master.cpp:2321] Processing reply for offers: [ 20141030-055359-3142697795-54775-29497-O0 ] on slave 20141030-055359-3142697795-54775-29497-S0 at slave(27)@67.195.81.187:54775 (pomona.apache.org) for framework 20141030-055359-3142697795-54775-29497-0000 (default) at scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775
W1030 05:54:07.778784 29519 master.cpp:1969] 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.
W1030 05:54:07.778818 29519 master.cpp:1980] 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.
I1030 05:54:07.778919 29519 master.cpp:2417] Authorizing framework principal 'test-principal' to launch task 0 as user 'jenkins'
I1030 05:54:07.779989 29512 master.hpp:877] Adding task 0 with resources cpus(*):1; mem(*):512 on slave 20141030-055359-3142697795-54775-29497-S0 (pomona.apache.org)
I1030 05:54:07.780067 29512 master.cpp:2480] Launching task 0 of framework 20141030-055359-3142697795-54775-29497-0000 (default) at scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775 with resources cpus(*):1; mem(*):512 on slave 20141030-055359-3142697795-54775-29497-S0 at slave(27)@67.195.81.187:54775 (pomona.apache.org)
I1030 05:54:07.780411 29521 slave.cpp:1081] Got assigned task 0 for framework 20141030-055359-3142697795-54775-29497-0000
I1030 05:54:07.780939 29518 hierarchical_allocator_process.hpp:563] Recovered cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000]) on slave 20141030-055359-3142697795-54775-29497-S0 from framework 20141030-055359-3142697795-54775-29497-0000
I1030 05:54:07.780995 29521 slave.cpp:1191] Launching task 0 for framework 20141030-055359-3142697795-54775-29497-0000
I1030 05:54:07.780998 29518 hierarchical_allocator_process.hpp:599] Framework 20141030-055359-3142697795-54775-29497-0000 filtered slave 20141030-055359-3142697795-54775-29497-S0 for 5secs
Itests/reconciliation_tests.cpp:112: Failure
Failed to wait 10secs for update
tests/reconciliation_tests.cpp:104: Failure
Actual function call count doesn't match EXPECT_CALL(sched, statusUpdate(&driver, _))...
Expected: to be called once
1030 05:54:07.783726 29521 slave.cpp:3871] Launching executor default of framework 20141030-055359-3142697795-54775-29497-0000 in work directory '/tmp/ReconciliationTest_TaskStateMismatch_jXTxgL/slaves/20141030-055359-3142697795-54775-29497-S0/frameworks/20141030-055359-3142697795-54775-29497-0000/executors/default/runs/f62d63de-e21a-438c-917d-ca4b61c34519'
Actual: never called - unsatisfied and active
I1030 05:54:08.771411 29516 hierarchical_allocator_process.hpp:816] Filtered cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000] on slave 20141030-055359-3142697795-54775-29497-S0 for framework 20141030-055359-3142697795-54775-29497-0000
I1030 05:54:09.499510 29514 master.cpp:120] No whitelist given. Advertising offers for all slaves
I1030 05:54:17.775676 29526 master.cpp:768] Framework 20141030-055359-3142697795-54775-29497-0000 (default) at scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775 disconnected
I1030 05:54:20.124783 29516 hierarchical_allocator_process.hpp:659] Performed allocation for 1 slaves in 11.353661562secs
I1030 05:54:20.124831 29526 master.cpp:1731] Disconnecting framework 20141030-055359-3142697795-54775-29497-0000 (default) at scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775
tests/reconciliation_tests.cpp:100: Failure
Actual function call count doesn't match EXPECT_CALL(exec, launchTask(_, _))...
Expected: to be called once
Actual: never called - unsatisfied and active
tests/reconciliation_tests.cpp:98: Failure
Actual function call count doesn't match EXPECT_CALL(exec, registered(_, _, _, _))...
Expected: to be called once
Actual: never called - unsatisfied and active
I1030 05:54:20.124938 29526 master.cpp:1747] Deactivating framework 20141030-055359-3142697795-54775-29497-0000 (default) at scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775
F1030 05:54:20.124938 29521 logging.cpp:57] RAW: Pure virtual method called
I1030 05:54:20.125049 29526 master.cpp:790] Giving framework 20141030-055359-3142697795-54775-29497-0000 (default) at scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775 0ns to failover
I1030 05:54:20.125176 29516 hierarchical_allocator_process.hpp:405] Deactivated framework 20141030-055359-3142697795-54775-29497-0000
I1030 05:54:20.125305 29515 master.cpp:3665] Framework failover timeout, removing framework 20141030-055359-3142697795-54775-29497-0000 (default) at scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775
I1030 05:54:20.125332 29515 master.cpp:4201] Removing framework 20141030-055359-3142697795-54775-29497-0000 (default) at scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775
I1030 05:54:20.127970 29515 master.cpp:4617] Updating the latest state of task 0 of framework 20141030-055359-3142697795-54775-29497-0000 to TASK_KILLED
I1030 05:54:20.128203 29515 master.cpp:4676] Removing task 0 with resources cpus(*):1; mem(*):512 of framework 20141030-055359-3142697795-54775-29497-0000 on slave 20141030-055359-3142697795-54775-29497-S0 at slave(27)@67.195.81.187:54775 (pomona.apache.org)
I1030 05:54:20.128458 29520 hierarchical_allocator_process.hpp:563] Recovered cpus(*):1; mem(*):512 (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20141030-055359-3142697795-54775-29497-S0 from framework 20141030-055359-3142697795-54775-29497-0000
I1030 05:54:20.128635 29515 master.cpp:4705] Removing executor 'default' with resources of framework 20141030-055359-3142697795-54775-29497-0000 on slave 20141030-055359-3142697795-54775-29497-S0 at slave(27)@67.195.81.187:54775 (pomona.apache.org)
I1030 05:54:20.129112 29515 master.cpp:677] Master terminating
I1030 05:54:20.129189 29523 hierarchical_allocator_process.hpp:360] Removed framework 20141030-055359-3142697795-54775-29497-0000
[ FAILED ] ReconciliationTest.TaskStateMismatch (21026 ms)
[ RUN ] ReconciliationTest.UnknownSlave
Using temporary directory '/tmp/ReconciliationTest_UnknownSlave_sz29uu'
@ 0x2adeb902ca8e google::LogMessage::Fail()
@ 0x2adeb9032182 google::RawLog__()
I1030 05:54:20.137413 29497 leveldb.cpp:176] Opened db in 2.509172ms
I1030 05:54:20.138386 29497 leveldb.cpp:183] Compacted db in 938375ns
I1030 05:54:20.138420 29497 leveldb.cpp:198] Created db iterator in 7060ns
I1030 05:54:20.138438 29497 leveldb.cpp:204] Seeked to beginning of db in 1280ns
I1030 05:54:20.138449 29497 leveldb.cpp:273] Iterated through 0 keys in the db in 630ns
@ 0x2adeb86bfb86 __cxa_pure_virtual
I1030 05:54:22.333158 29497 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1030 05:54:22.334003 29517 recover.cpp:437] Starting replica recovery
I1030 05:54:22.334370 29517 recover.cpp:463] Replica is in EMPTY status
I1030 05:54:22.336093 29515 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
I1030 05:54:22.336302 29526 recover.cpp:188] Received a recover response from a replica in EMPTY status
I1030 05:54:22.336704 29524 recover.cpp:554] Updating replica status to STARTING
I1030 05:54:22.337630 29522 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 737us
I1030 05:54:22.337677 29522 replica.cpp:320] Persisted replica status to STARTING
I1030 05:54:22.337810 29526 master.cpp:312] Master 20141030-055422-3142697795-54775-29497 (pomona.apache.org) started on 67.195.81.187:54775
I1030 05:54:22.337862 29526 master.cpp:358] Master only allowing authenticated frameworks to register
I1030 05:54:22.337878 29526 master.cpp:363] Master only allowing authenticated slaves to register
I1030 05:54:22.337898 29526 credentials.hpp:36] Loading credentials for authentication from '/tmp/ReconciliationTest_UnknownSlave_sz29uu/credentials'
I1030 05:54:22.338032 29516 recover.cpp:463] Replica is in STARTING status
I1030 05:54:22.338163 29526 master.cpp:392] Authorization enabled
@ 0x2adeb89807bd mesos::internal::slave::Framework::launchExecutor()
I1030 05:54:22.338692 29515 master.cpp:120] No whitelist given. Advertising offers for all slaves
I1030 05:54:22.339212 29519 hierarchical_allocator_process.hpp:299] Initializing hierarchical allocator process with master : master@67.195.81.187:54775
I1030 05:54:22.339202 29522 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
I1030 05:54:22.339773 29514 recover.cpp:188] Received a recover response from a replica in STARTING status
I1030 05:54:22.339844 29520 master.cpp:1242] The newly elected leader is master@67.195.81.187:54775 with id 20141030-055422-3142697795-54775-29497
I1030 05:54:22.339879 29520 master.cpp:1255] Elected as the leading master!
I1030 05:54:22.339900 29520 master.cpp:1073] Recovering from registrar
I1030 05:54:22.340183 29515 registrar.cpp:313] Recovering registrar
I1030 05:54:22.340446 29518 recover.cpp:554] Updating replica status to VOTING
I1030 05:54:22.341236 29520 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 565518ns
I1030 05:54:22.341262 29520 replica.cpp:320] Persisted replica status to VOTING
I1030 05:54:22.341406 29520 recover.cpp:568] Successfully joined the Paxos group
I1030 05:54:22.341653 29520 recover.cpp:452] Recover process terminated
I1030 05:54:22.342217 29526 log.cpp:656] Attempting to start the writer
@ 0x2adeb8968b5a mesos::internal::slave::Slave::_runTask()
I1030 05:54:22.343890 29512 replica.cpp:474] Replica received implicit promise request with proposal 1
I1030 05:54:22.344487 29512 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 563202ns
I1030 05:54:22.344512 29512 replica.cpp:342] Persisted promised to 1
@ 0x2adeb89a0a0b _ZZN7process8dispatchIN5mesos8internal5slave5SlaveERKNS_6FutureIbEERKNS1_13FrameworkInfoERKNS1_11FrameworkIDERKSsRKNS1_8TaskInfoES6_S9_SC_SsSH_EEvRKNS_3PIDIT_EEMSL_FvT0_T1_T2_T3_T4_ET5_T6_T7_T8_T9_ENKUlPNS_11ProcessBaseEE_clES12_
I1030 05:54:22.345145 29523 coordinator.cpp:230] Coordinator attemping to fill missing position
I1030 05:54:22.346741 29520 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I1030 05:54:22.347309 29520 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 531407ns
I1030 05:54:22.347337 29520 replica.cpp:676] Persisted action at 0
I1030 05:54:22.348525 29522 replica.cpp:508] Replica received write request for position 0
I1030 05:54:22.348575 29522 leveldb.cpp:438] Reading position from leveldb took 24419ns
I1030 05:54:22.349072 29522 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 463209ns
I @ 0x2adeb89c6fdd _ZNSt17_Function_handlerIFvPN7process11ProcessBaseEEZNS0_8dispatchIN5mesos8internal5slave5SlaveERKNS0_6FutureIbEERKNS5_13FrameworkInfoERKNS5_11FrameworkIDERKSsRKNS5_8TaskInfoESA_SD_SG_SsSL_EEvRKNS0_3PIDIT_EEMSP_FvT0_T1_T2_T3_T4_ET5_T6_T7_T8_T9_EUlS2_E_E9_M_invokeERKSt9_Any_dataS2_
1030 05:54:22.349097 29522 replica.cpp:676] Persisted action at 0
I1030 05:54:22.643363 29524 replica.cpp:655] Replica received learned notice for position 0
I1030 05:54:22.644031 29524 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 626475ns
I1030 05:54:22.644059 29524 replica.cpp:676] Persisted action at 0
I1030 05:54:22.644081 29524 replica.cpp:661] Replica learned NOP action at position 0
I1030 05:54:22.644937 29513 log.cpp:672] Writer started with ending position 0
I1030 05:54:22.646476 29522 leveldb.cpp:438] Reading position from leveldb took 29654ns
@ 0x2adeb8fbe89f std::function<>::operator()()
I1030 05:54:22.649744 29511 registrar.cpp:346] Successfully fetched the registry (0B) in 309.50912ms
I1030 05:54:22.649865 29511 registrar.cpp:445] Applied 1 operations in 26852ns; attempting to update the 'registry'
@ 0x2adeb8f9fb67 process::ProcessBase::visit()
I1030 05:54:22.652909 29525 log.cpp:680] Attempting to append 139 bytes to the log
I1030 05:54:22.653067 29512 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I1030 05:54:22.654033 29516 replica.cpp:508] Replica received write request for position 1
I1030 05:54:22.654588 29516 leveldb.cpp:343] Persisting action (158 bytes) to leveldb took 521467ns
I1030 05:54:22.654619 29516 replica.cpp:676] Persisted action at 1
@ 0x2adeb8faa49c process::DispatchEvent::visit()
I1030 05:54:22.655232 29514 replica.cpp:655] Replica received learned notice for position 1
I1030 05:54:22.655637 29514 leveldb.cpp:343] Persisting action (160 bytes) to leveldb took 378403ns
I1030 05:54:22.655663 29514 replica.cpp:676] Persisted action at 1
I1030 05:54:22.655683 29514 replica.cpp:661] Replica learned APPEND action at position 1
I1030 05:54:22.656695 29523 registrar.cpp:490] Successfully updated the 'registry' in 6.767872ms
I1030 05:54:22.656848 29523 registrar.cpp:376] Successfully recovered registrar
I1030 05:54:22.656976 29518 log.cpp:699] Attempting to truncate the log to 1
@ 0x8f6fa2 process::ProcessBase::serve()
I1030 05:54:22.657117 29511 master.cpp:1100] Recovered 0 slaves from the Registry (101B) ; allowing 10mins for slaves to re-register
I1030 05:54:22.657215 29516 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I1030 05:54:22.658125 29516 replica.cpp:508] Replica received write request for position 2
I1030 05:54:22.658622 29516 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 462724ns
I1030 05:54:22.658648 29516 replica.cpp:676] Persisted action at 2
I1030 05:54:22.659272 29514 replica.cpp:655] Replica received learned notice for position 2
I1030 05:54:22.659711 29514 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 395532ns
I1030 05:54:22.659757 29514 leveldb.cpp:401] Deleting ~1 keys from leveldb took 22259ns
I1030 05:54:22.659775 29514 replica.cpp:676] Persisted action at 2
I1030 05:54:22.659796 29514 replica.cpp:661] Replica learned TRUNCATE action at position 2
@ 0x2adeb8f9bddc process::ProcessManager::resume()
@ 0x2adeb8f924a1 process::schedule()
@ 0x2adebb2f0182 start_thread
@ 0x2adebb600fbd (unknown)
make[3]: *** [check-local] Aborted
make[3]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'>
make[2]: *** [check-am] Error 2
make[2]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'>
make[1]: *** [check] Error 2
make[1]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'>
make: *** [check-recursive] Error 1
Test finished
Exit status: 2
Build step 'Execute shell' marked build as failure
Recording test results