[
https://issues.apache.org/jira/browse/MESOS-2017?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14190416#comment-14190416
]
Yan Xu commented on MESOS-2017:
-------------------------------
Another instance
{noformat:title=}
[ RUN ] ReconciliationTest.TaskStateMismatch
Using temporary directory '/tmp/ReconciliationTest_TaskStateMismatch_yawZWG'
I1030 05:53:59.111893 29497 leveldb.cpp:176] Opened db in 2.498301ms
I1030 05:53:59.112458 29497 leveldb.cpp:183] Compacted db in 530104ns
I1030 05:53:59.112489 29497 leveldb.cpp:198] Created db iterator in 4725ns
I1030 05:53:59.112503 29497 leveldb.cpp:204] Seeked to beginning of db in 842ns
I1030 05:53:59.112514 29497 leveldb.cpp:273] Iterated through 0 keys in the db
in 390ns
I1030 05:53:59.112550 29497 replica.cpp:741] Replica recovered with log
positions 0 -> 0 with 1 holes and 0 unlearned
I1030 05:53:59.113093 29512 recover.cpp:437] Starting replica recovery
I1030 05:53:59.113482 29512 recover.cpp:463] Replica is in EMPTY status
I1030 05:53:59.114696 29519 replica.cpp:638] Replica in EMPTY status received a
broadcasted recover request
I1030 05:53:59.115206 29516 recover.cpp:188] Received a recover response from a
replica in EMPTY status
I1030 05:53:59.115718 29518 recover.cpp:554] Updating replica status to STARTING
I1030 05:53:59.116443 29521 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 574223ns
I1030 05:53:59.116477 29521 replica.cpp:320] Persisted replica status to
STARTING
I1030 05:53:59.116711 29524 recover.cpp:463] Replica is in STARTING status
I1030 05:53:59.117079 29517 master.cpp:312] Master
20141030-055359-3142697795-54775-29497 (pomona.apache.org) started on
67.195.81.187:54775
I1030 05:53:59.117130 29517 master.cpp:358] Master only allowing authenticated
frameworks to register
I1030 05:53:59.117151 29517 master.cpp:363] Master only allowing authenticated
slaves to register
I1030 05:53:59.117167 29517 credentials.hpp:36] Loading credentials for
authentication from
'/tmp/ReconciliationTest_TaskStateMismatch_yawZWG/credentials'
I1030 05:53:59.117463 29517 master.cpp:392] Authorization enabled
I1030 05:53:59.117905 29512 master.cpp:120] No whitelist given. Advertising
offers for all slaves
I1030 05:53:59.117903 29519 replica.cpp:638] Replica in STARTING status
received a broadcasted recover request
I1030 05:53:59.118011 29516 hierarchical_allocator_process.hpp:299]
Initializing hierarchical allocator process with master :
[email protected]:54775
I1030 05:53:59.118392 29524 recover.cpp:188] Received a recover response from a
replica in STARTING status
I1030 05:53:59.119174 29515 master.cpp:1242] The newly elected leader is
[email protected]:54775 with id 20141030-055359-3142697795-54775-29497
I1030 05:53:59.119210 29515 master.cpp:1255] Elected as the leading master!
I1030 05:53:59.119237 29515 master.cpp:1073] Recovering from registrar
I1030 05:53:59.119266 29526 recover.cpp:554] Updating replica status to VOTING
I1030 05:53:59.119467 29526 registrar.cpp:313] Recovering registrar
I1030 05:53:59.119874 29513 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 449182ns
I1030 05:53:59.119896 29513 replica.cpp:320] Persisted replica status to VOTING
I1030 05:53:59.119989 29526 recover.cpp:568] Successfully joined the Paxos group
I1030 05:53:59.120187 29526 recover.cpp:452] Recover process terminated
I1030 05:53:59.120620 29523 log.cpp:656] Attempting to start the writer
I1030 05:53:59.122113 29516 replica.cpp:474] Replica received implicit promise
request with proposal 1
I1030 05:53:59.122586 29516 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 443572ns
I1030 05:53:59.122612 29516 replica.cpp:342] Persisted promised to 1
I1030 05:53:59.123226 29514 coordinator.cpp:230] Coordinator attemping to fill
missing position
I1030 05:53:59.124930 29524 replica.cpp:375] Replica received explicit promise
request for position 0 with proposal 2
I1030 05:53:59.125406 29524 leveldb.cpp:343] Persisting action (8 bytes) to
leveldb took 442490ns
I1030 05:53:59.125424 29524 replica.cpp:676] Persisted action at 0
I1030 05:53:59.126499 29520 replica.cpp:508] Replica received write request for
position 0
I1030 05:53:59.126554 29520 leveldb.cpp:438] Reading position from leveldb took
25562ns
I1030 05:53:59.127059 29520 leveldb.cpp:343] Persisting action (14 bytes) to
leveldb took 468619ns
I1030 05:53:59.127089 29520 replica.cpp:676] Persisted action at 0
I1030 05:53:59.127712 29522 replica.cpp:655] Replica received learned notice
for position 0
I1030 05:53:59.128161 29522 leveldb.cpp:343] Persisting action (16 bytes) to
leveldb took 423207ns
I1030 05:53:59.128186 29522 replica.cpp:676] Persisted action at 0
I1030 05:53:59.128207 29522 replica.cpp:661] Replica learned NOP action at
position 0
I1030 05:53:59.129175 29524 log.cpp:672] Writer started with ending position 0
I1030 05:53:59.130544 29522 leveldb.cpp:438] Reading position from leveldb took
26234ns
I1030 05:53:59.133697 29519 registrar.cpp:346] Successfully fetched the
registry (0B) in 14.19008ms
I1030 05:53:59.133821 29519 registrar.cpp:445] Applied 1 operations in 21199ns;
attempting to update the 'registry'
I1030 05:53:59.136909 29525 log.cpp:680] Attempting to append 139 bytes to the
log
I1030 05:53:59.137105 29518 coordinator.cpp:340] Coordinator attempting to
write APPEND action at position 1
I1030 05:53:59.138020 29519 replica.cpp:508] Replica received write request for
position 1
I1030 05:53:59.138577 29519 leveldb.cpp:343] Persisting action (158 bytes) to
leveldb took 522379ns
I1030 05:54:04.498838 29519 replica.cpp:676] Persisted action at 1
I1030 05:54:00.118970 29516 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I1030 05:54:04.118438 29513 master.cpp:120] No whitelist given. Advertising
offers for all slaves
I1030 05:54:04.498904 29516 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 4.379945984secs
I1030 05:54:04.499814 29516 replica.cpp:655] Replica received learned notice
for position 1
I1030 05:54:04.500473 29516 leveldb.cpp:343] Persisting action (160 bytes) to
leveldb took 630582ns
I1030 05:54:04.500500 29516 replica.cpp:676] Persisted action at 1
I1030 05:54:04.500524 29516 replica.cpp:661] Replica learned APPEND action at
position 1
I1030 05:54:04.501904 29512 registrar.cpp:490] Successfully updated the
'registry' in 5.36800512secs
I1030 05:54:04.502051 29512 registrar.cpp:376] Successfully recovered registrar
I1030 05:54:04.502249 29520 log.cpp:699] Attempting to truncate the log to 1
I1030 05:54:04.502441 29521 master.cpp:1100] Recovered 0 slaves from the
Registry (101B) ; allowing 10mins for slaves to re-register
I1030 05:54:04.502523 29512 coordinator.cpp:340] Coordinator attempting to
write TRUNCATE action at position 2
I1030 05:54:04.503787 29513 replica.cpp:508] Replica received write request for
position 2
I1030 05:54:04.504384 29513 leveldb.cpp:343] Persisting action (16 bytes) to
leveldb took 553772ns
I1030 05:54:04.504416 29513 replica.cpp:676] Persisted action at 2
I1030 05:54:04.505110 29517 replica.cpp:655] Replica received learned notice
for position 2
I1030 05:54:04.505623 29517 leveldb.cpp:343] Persisting action (18 bytes) to
leveldb took 486006ns
I1030 05:54:04.505686 29517 leveldb.cpp:401] Deleting ~1 keys from leveldb took
32144ns
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
[email protected]:54775
I1030 05:54:04.522677 29524 slave.cpp:665] Authenticating with master
[email protected]: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 [email protected]: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
[email protected]:54775
I1030 05:54:04.526803 29514 sched.cpp:283] Authenticating with master
[email protected]: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
[email protected]: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
[email protected]:54775
I1030 05:54:07.770843 29512 sched.cpp:357] Successfully authenticated with
master [email protected]:54775
I1030 05:54:07.770891 29512 sched.cpp:476] Sending registration request to
[email protected]:54775
I1030 05:54:07.771092 29515 master.cpp:1362] Received registration request for
framework 'default' at
[email protected]: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
[email protected]: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
[email protected]: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
[email protected]: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 [email protected]: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
[email protected]: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
[email protected]: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
[email protected]: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
[email protected]: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
[email protected]: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
[email protected]:54775
I1030 05:54:20.125332 29515 master.cpp:4201] Removing framework
20141030-055359-3142697795-54775-29497-0000 (default) at
[email protected]: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 :
[email protected]: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
[email protected]: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)
{noformat}
> Segfault with "Pure virtual method called" when tests fail
> ----------------------------------------------------------
>
> Key: MESOS-2017
> URL: https://issues.apache.org/jira/browse/MESOS-2017
> Project: Mesos
> Issue Type: Bug
> Components: test
> Affects Versions: 0.21.0
> Reporter: Yan Xu
>
> The most recent one:
> {noformat:title=DRFAllocatorTest.DRFAllocatorProcess}
> [ RUN ] DRFAllocatorTest.DRFAllocatorProcess
> Using temporary directory '/tmp/DRFAllocatorTest_DRFAllocatorProcess_BI905j'
> I1030 05:55:06.934813 24459 leveldb.cpp:176] Opened db in 3.175202ms
> I1030 05:55:06.935925 24459 leveldb.cpp:183] Compacted db in 1.077924ms
> I1030 05:55:06.935976 24459 leveldb.cpp:198] Created db iterator in 16460ns
> I1030 05:55:06.935995 24459 leveldb.cpp:204] Seeked to beginning of db in
> 2018ns
> I1030 05:55:06.936005 24459 leveldb.cpp:273] Iterated through 0 keys in the
> db in 335ns
> I1030 05:55:06.936039 24459 replica.cpp:741] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I1030 05:55:06.936705 24480 recover.cpp:437] Starting replica recovery
> I1030 05:55:06.937023 24480 recover.cpp:463] Replica is in EMPTY status
> I1030 05:55:06.938158 24475 replica.cpp:638] Replica in EMPTY status received
> a broadcasted recover request
> I1030 05:55:06.938859 24482 recover.cpp:188] Received a recover response from
> a replica in EMPTY status
> I1030 05:55:06.939486 24474 recover.cpp:554] Updating replica status to
> STARTING
> I1030 05:55:06.940249 24489 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 591981ns
> I1030 05:55:06.940274 24489 replica.cpp:320] Persisted replica status to
> STARTING
> I1030 05:55:06.940752 24481 recover.cpp:463] Replica is in STARTING status
> I1030 05:55:06.940820 24489 master.cpp:312] Master
> 20141030-055506-3142697795-40429-24459 (pomona.apache.org) started on
> 67.195.81.187:40429
> I1030 05:55:06.940871 24489 master.cpp:358] Master only allowing
> authenticated frameworks to register
> I1030 05:55:06.940891 24489 master.cpp:363] Master only allowing
> authenticated slaves to register
> I1030 05:55:06.940908 24489 credentials.hpp:36] Loading credentials for
> authentication from
> '/tmp/DRFAllocatorTest_DRFAllocatorProcess_BI905j/credentials'
> I1030 05:55:06.941215 24489 master.cpp:392] Authorization enabled
> I1030 05:55:06.941751 24475 master.cpp:120] No whitelist given. Advertising
> offers for all slaves
> I1030 05:55:06.942227 24474 replica.cpp:638] Replica in STARTING status
> received a broadcasted recover request
> I1030 05:55:06.942401 24476 hierarchical_allocator_process.hpp:299]
> Initializing hierarchical allocator process with master :
> [email protected]:40429
> I1030 05:55:06.942895 24483 recover.cpp:188] Received a recover response from
> a replica in STARTING status
> I1030 05:55:06.943035 24474 master.cpp:1242] The newly elected leader is
> [email protected]:40429 with id 20141030-055506-3142697795-40429-24459
> I1030 05:55:06.943063 24474 master.cpp:1255] Elected as the leading master!
> I1030 05:55:06.943079 24474 master.cpp:1073] Recovering from registrar
> I1030 05:55:06.943313 24480 registrar.cpp:313] Recovering registrar
> I1030 05:55:06.943455 24475 recover.cpp:554] Updating replica status to VOTING
> I1030 05:55:06.944144 24474 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 536365ns
> I1030 05:55:06.944172 24474 replica.cpp:320] Persisted replica status to
> VOTING
> I1030 05:55:06.944355 24489 recover.cpp:568] Successfully joined the Paxos
> group
> I1030 05:55:06.944576 24489 recover.cpp:452] Recover process terminated
> I1030 05:55:06.945155 24486 log.cpp:656] Attempting to start the writer
> I1030 05:55:06.947013 24473 replica.cpp:474] Replica received implicit
> promise request with proposal 1
> I1030 05:55:06.947854 24473 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 806463ns
> I1030 05:55:06.947883 24473 replica.cpp:342] Persisted promised to 1
> I1030 05:55:06.948547 24481 coordinator.cpp:230] Coordinator attemping to
> fill missing position
> I1030 05:55:06.950269 24479 replica.cpp:375] Replica received explicit
> promise request for position 0 with proposal 2
> I1030 05:55:06.950933 24479 leveldb.cpp:343] Persisting action (8 bytes) to
> leveldb took 603843ns
> I1030 05:55:06.950961 24479 replica.cpp:676] Persisted action at 0
> I1030 05:55:06.952180 24476 replica.cpp:508] Replica received write request
> for position 0
> I1030 05:55:06.952239 24476 leveldb.cpp:438] Reading position from leveldb
> took 28437ns
> I1030 05:55:06.952896 24476 leveldb.cpp:343] Persisting action (14 bytes) to
> leveldb took 623980ns
> I1030 05:55:06.952926 24476 replica.cpp:676] Persisted action at 0
> I1030 05:55:06.953543 24485 replica.cpp:655] Replica received learned notice
> for position 0
> I1030 05:55:06.954082 24485 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 511807ns
> I1030 05:55:06.954107 24485 replica.cpp:676] Persisted action at 0
> I1030 05:55:06.954128 24485 replica.cpp:661] Replica learned NOP action at
> position 0
> I1030 05:55:06.954710 24473 log.cpp:672] Writer started with ending position 0
> I1030 05:55:06.956215 24478 leveldb.cpp:438] Reading position from leveldb
> took 33085ns
> I1030 05:55:06.959481 24475 registrar.cpp:346] Successfully fetched the
> registry (0B) in 16.11904ms
> I1030 05:55:06.959616 24475 registrar.cpp:445] Applied 1 operations in
> 28239ns; attempting to update the 'registry'
> I1030 05:55:06.962514 24487 log.cpp:680] Attempting to append 139 bytes to
> the log
> I1030 05:55:06.962646 24474 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 1
> I1030 05:55:06.964146 24486 replica.cpp:508] Replica received write request
> for position 1
> I1030 05:55:06.964962 24486 leveldb.cpp:343] Persisting action (158 bytes) to
> leveldb took 743389ns
> I1030 05:55:06.964993 24486 replica.cpp:676] Persisted action at 1
> I1030 05:55:06.965895 24473 replica.cpp:655] Replica received learned notice
> for position 1
> I1030 05:55:06.966531 24473 leveldb.cpp:343] Persisting action (160 bytes) to
> leveldb took 607242ns
> I1030 05:55:06.966555 24473 replica.cpp:676] Persisted action at 1
> I1030 05:55:06.966578 24473 replica.cpp:661] Replica learned APPEND action at
> position 1
> I1030 05:55:06.967706 24481 registrar.cpp:490] Successfully updated the
> 'registry' in 8.036096ms
> I1030 05:55:06.967895 24481 registrar.cpp:376] Successfully recovered
> registrar
> I1030 05:55:06.967993 24482 log.cpp:699] Attempting to truncate the log to 1
> I1030 05:55:06.968258 24479 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 2
> I1030 05:55:06.968268 24475 master.cpp:1100] Recovered 0 slaves from the
> Registry (101B) ; allowing 10mins for slaves to re-register
> I1030 05:55:06.969156 24476 replica.cpp:508] Replica received write request
> for position 2
> I1030 05:55:06.969678 24476 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 491913ns
> I1030 05:55:06.969703 24476 replica.cpp:676] Persisted action at 2
> I1030 05:55:06.970459 24478 replica.cpp:655] Replica received learned notice
> for position 2
> I1030 05:55:06.971060 24478 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 573076ns
> I1030 05:55:06.971124 24478 leveldb.cpp:401] Deleting ~1 keys from leveldb
> took 35339ns
> I1030 05:55:06.971145 24478 replica.cpp:676] Persisted action at 2
> I1030 05:55:06.971168 24478 replica.cpp:661] Replica learned TRUNCATE action
> at position 2
> I1030 05:55:06.980211 24459 containerizer.cpp:100] Using isolation:
> posix/cpu,posix/mem
> I1030 05:55:06.984153 24473 slave.cpp:169] Slave started on
> 203)@67.195.81.187:40429
> I1030 05:55:07.055308 24473 credentials.hpp:84] Loading credential for
> authentication from
> '/tmp/DRFAllocatorTest_DRFAllocatorProcess_wULx31/credential'
> I1030 05:55:06.988750 24459 sched.cpp:137] Version: 0.21.0
> I1030 05:55:07.055521 24473 slave.cpp:276] Slave using credential for:
> test-principal
> I1030 05:55:07.055726 24473 slave.cpp:289] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):0; ports(*):[31000-32000]
> I1030 05:55:07.055865 24473 slave.cpp:318] Slave hostname: pomona.apache.org
> I1030 05:55:07.055881 24473 slave.cpp:319] Slave checkpoint: false
> W1030 05:55:07.055889 24473 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:55:07.056172 24485 sched.cpp:233] New master detected at
> [email protected]:40429
> I1030 05:55:07.056222 24485 sched.cpp:283] Authenticating with master
> [email protected]:40429
> I1030 05:55:07.056717 24485 state.cpp:33] Recovering state from
> '/tmp/DRFAllocatorTest_DRFAllocatorProcess_wULx31/meta'
> I1030 05:55:07.056851 24475 authenticatee.hpp:133] Creating new client SASL
> connection
> I1030 05:55:07.057003 24473 status_update_manager.cpp:197] Recovering status
> update manager
> I1030 05:55:07.057252 24488 master.cpp:3853] Authenticating
> [email protected]:40429
> I1030 05:55:07.057502 24489 containerizer.cpp:281] Recovering containerizer
> I1030 05:55:07.057524 24475 authenticator.hpp:161] Creating new server SASL
> connection
> I1030 05:55:07.057688 24475 authenticatee.hpp:224] Received SASL
> authentication mechanisms: CRAM-MD5
> I1030 05:55:07.057719 24475 authenticatee.hpp:250] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I1030 05:55:07.057919 24481 authenticator.hpp:267] Received SASL
> authentication start
> I1030 05:55:07.057968 24481 authenticator.hpp:389] Authentication requires
> more steps
> I1030 05:55:07.058070 24473 authenticatee.hpp:270] Received SASL
> authentication step
> I1030 05:55:07.058199 24485 authenticator.hpp:295] Received SASL
> authentication step
> I1030 05:55:07.058223 24485 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:55:07.058233 24485 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I1030 05:55:07.058259 24485 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I1030 05:55:07.058290 24485 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:55:07.058302 24485 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1030 05:55:07.058307 24485 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1030 05:55:07.058320 24485 authenticator.hpp:381] Authentication success
> I1030 05:55:07.058467 24480 master.cpp:3893] Successfully authenticated
> principal 'test-principal' at
> [email protected]:40429
> I1030 05:55:07.058493 24485 slave.cpp:3456] Finished recovery
> I1030 05:55:07.058593 24478 authenticatee.hpp:310] Authentication success
> I1030 05:55:07.058838 24478 sched.cpp:357] Successfully authenticated with
> master [email protected]:40429
> I1030 05:55:07.058861 24478 sched.cpp:476] Sending registration request to
> [email protected]:40429
> I1030 05:55:07.058969 24475 slave.cpp:602] New master detected at
> [email protected]:40429
> I1030 05:55:07.058969 24487 status_update_manager.cpp:171] Pausing sending
> status updates
> I1030 05:55:07.059026 24475 slave.cpp:665] Authenticating with master
> [email protected]:40429
> I1030 05:55:07.059061 24481 master.cpp:1362] Received registration request
> for framework 'framework1' at
> [email protected]:40429
> I1030 05:55:07.059131 24481 master.cpp:1321] Authorizing framework principal
> 'test-principal' to receive offers for role 'role1'
> I1030 05:55:07.059171 24475 slave.cpp:638] Detecting new master
> I1030 05:55:07.059214 24482 authenticatee.hpp:133] Creating new client SASL
> connection
> I1030 05:55:07.059550 24481 master.cpp:3853] Authenticating
> slave(203)@67.195.81.187:40429
> I1030 05:55:07.059787 24487 authenticator.hpp:161] Creating new server SASL
> connection
> I1030 05:55:07.059922 24481 master.cpp:1426] Registering framework
> 20141030-055506-3142697795-40429-24459-0000 (framework1) at
> [email protected]:40429
> I1030 05:55:07.059996 24474 authenticatee.hpp:224] Received SASL
> authentication mechanisms: CRAM-MD5
> I1030 05:55:07.060034 24474 authenticatee.hpp:250] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I1030 05:55:07.060117 24474 authenticator.hpp:267] Received SASL
> authentication start
> I1030 05:55:07.060165 24474 authenticator.hpp:389] Authentication requires
> more steps
> I1030 05:55:07.060377 24476 hierarchical_allocator_process.hpp:329] Added
> framework 20141030-055506-3142697795-40429-24459-0000
> I1030 05:55:07.060394 24488 sched.cpp:407] Framework registered with
> 20141030-055506-3142697795-40429-24459-0000
> I1030 05:55:07.060403 24476 hierarchical_allocator_process.hpp:697] No
> resources available to allocate!
> I1030 05:55:07.060431 24476 hierarchical_allocator_process.hpp:659] Performed
> allocation for 0 slaves in 29857ns
> I1030 05:55:07.060443 24488 sched.cpp:421] Scheduler::registered took 19407ns
> I1030 05:55:07.060545 24478 authenticatee.hpp:270] Received SASL
> authentication step
> I1030 05:55:07.060645 24478 authenticator.hpp:295] Received SASL
> authentication step
> I1030 05:55:07.060673 24478 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:55:07.060685 24478 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I1030 05:55:07.060714 24478 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I1030 05:55:07.060740 24478 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:55:07.060760 24478 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1030 05:55:07.060770 24478 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1030 05:55:07.060788 24478 authenticator.hpp:381] Authentication success
> I1030 05:55:07.060920 24474 authenticatee.hpp:310] Authentication success
> I1030 05:55:07.060945 24485 master.cpp:3893] Successfully authenticated
> principal 'test-principal' at slave(203)@67.195.81.187:40429
> I1030 05:55:07.061388 24489 slave.cpp:722] Successfully authenticated with
> master [email protected]:40429
> I1030 05:55:07.061504 24489 slave.cpp:1050] Will retry registration in
> 4.778336ms if necessary
> I1030 05:55:07.061718 24480 master.cpp:3032] Registering slave at
> slave(203)@67.195.81.187:40429 (pomona.apache.org) with id
> 20141030-055506-3142697795-40429-24459-S0
> I1030 05:55:07.062119 24489 registrar.cpp:445] Applied 1 operations in
> 53691ns; attempting to update the 'registry'
> I1030 05:55:07.065182 24479 log.cpp:680] Attempting to append 316 bytes to
> the log
> I1030 05:55:07.065337 24487 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 3
> I1030 05:55:07.066359 24474 replica.cpp:508] Replica received write request
> for position 3
> I1030 05:55:07.066643 24474 leveldb.cpp:343] Persisting action (335 bytes) to
> leveldb took 249579ns
> I1030 05:55:07.066671 24474 replica.cpp:676] Persisted action at 3
> I../../src/tests/allocator_tests.cpp:120: Failure
> Failed to wait 10secs for offers1
> 1030 05:55:07.067101 24477 slave.cpp:1050] Will retry registration in
> 24.08243ms if necessary
> I1030 05:55:07.067140 24473 master.cpp:3020] Ignoring register slave message
> from slave(203)@67.195.81.187:40429 (pomona.apache.org) as admission is
> already in progress
> I1030 05:55:07.067395 24488 replica.cpp:655] Replica received learned notice
> for position 3
> I1030 05:55:07.943416 24478 hierarchical_allocator_process.hpp:697] No
> resources available to allocate!
> I1030 05:55:19.804687 24478 hierarchical_allocator_process.hpp:659] Performed
> allocation for 0 slaves in 11.861261123secs
> I1030 05:55:11.942713 24474 master.cpp:120] No whitelist given. Advertising
> offers for all slaves
> I1030 05:55:19.805850 24488 leveldb.cpp:343] Persisting action (337 bytes) to
> leveldb took 1.067224ms
> I1030 05:55:19.806012 24488 replica.cpp:676] Persisted action at 3
> ../../src/tests/allocator_tests.cpp:115: Failure
> Actual function call count doesn't match EXPECT_CALL(sched1,
> resourceOffers(_, _))...
> Expected: to be called once
> Actual: never called - unsatisfied and active
> I1030 05:55:19.806144 24488 replica.cpp:661] Replica learned APPEND action at
> position 3
> I1030 05:55:19.806695 24473 master.cpp:768] Framework
> 20141030-055506-3142697795-40429-24459-0000 (framework1) at
> [email protected]:40429
> disconnected
> I1030 05:55:19.806726 24473 master.cpp:1731] Disconnecting framework
> 20141030-055506-3142697795-40429-24459-0000 (framework1) at
> [email protected]:40429
> I1030 05:55:19.806751 24473 master.cpp:1747] Deactivating framework
> 20141030-055506-3142697795-40429-24459-0000 (framework1) at
> [email protected]:40429
> I1030 05:55:19.806967 24473 master.cpp:790] Giving framework
> 20141030-055506-3142697795-40429-24459-0000 (framework1) at
> [email protected]:40429 0ns to
> failover
> ../../src/tests/allocator_tests.cpp:94: Failure
> Actual function call count doesn't match EXPECT_CALL(allocator, slaveAdded(_,
> _, _))...
> Expected: to be called once
> Actual: never called - unsatisfied and active
> F1030 05:55:19.806967 24480 logging.cpp:57] RAW: Pure virtual method called
> I1030 05:55:19.807348 24488 master.cpp:3665] Framework failover timeout,
> removing framework 20141030-055506-3142697795-40429-24459-0000 (framework1)
> at [email protected]:40429
> I1030 05:55:19.807370 24488 master.cpp:4201] Removing framework
> 20141030-055506-3142697795-40429-24459-0000 (framework1) at
> [email protected]:40429
> *** Aborted at 1414648519 (unix time) try "date -d @1414648519" if you are
> using GNU date ***
> PC: @ 0x91bc86 process::PID<>::PID()
> *** SIGSEGV (@0x0) received by PID 24459 (TID 0x2b86c919a700) from PID 0;
> stack trace: ***
> I1030 05:55:19.808631 24489 registrar.cpp:490] Successfully updated the
> 'registry' in 12.746377984secs
> @ 0x2b86c55fc340 (unknown)
> I1030 05:55:19.808938 24473 log.cpp:699] Attempting to truncate the log to 3
> @ 0x2b86c3327174 google::LogMessage::Fail()
> I1030 05:55:19.809084 24481 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 4
> @ 0x91bc86 process::PID<>::PID()
> @ 0x2b86c332c868 google::RawLog__()
> I1030 05:55:19.810191 24479 replica.cpp:508] Replica received write request
> for position 4
> I1030 05:55:19.810899 24479 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 678090ns
> I1030 05:55:19.810919 24479 replica.cpp:676] Persisted action at 4
> @ 0x91bf24 process::Process<>::self()
> I1030 05:55:19.811635 24485 replica.cpp:655] Replica received learned notice
> for position 4
> I1030 05:55:19.812180 24485 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 523927ns
> I1030 05:55:19.812228 24485 leveldb.cpp:401] Deleting ~2 keys from leveldb
> took 29523ns
> I1030 05:55:19.812242 24485 replica.cpp:676] Persisted action at 4
> I @ 0x2b86c29d2a36 __cxa_pure_virtual
> 1030 05:55:19.812258 24485 replica.cpp:661] Replica learned TRUNCATE action
> at position 4
> @ 0x1046936
> testing::internal::UntypedFunctionMockerBase::UntypedInvokeWith()
> I1030 05:55:19.829655 24474 slave.cpp:1050] Will retry registration in
> 31.785967ms if necessary
> @ 0x9c0633
> testing::internal::FunctionMockerBase<>::InvokeWith()
> @ 0x9b6152 testing::internal::FunctionMocker<>::Invoke()
> @ 0x9abdeb
> mesos::internal::tests::MockAllocatorProcess<>::frameworkDeactivated()
> @ 0x91c78f
> _ZZN7process8dispatchIN5mesos8internal6master9allocator16AllocatorProcessERKNS1_11FrameworkIDES6_EEvRKNS_3PIDIT_EEMSA_FvT0_ET1_ENKUlPNS_11ProcessBaseEE_clESJ_
> @ 0x959ad7
> _ZNSt17_Function_handlerIFvPN7process11ProcessBaseEEZNS0_8dispatchIN5mesos8internal6master9allocator16AllocatorProcessERKNS5_11FrameworkIDESA_EEvRKNS0_3PIDIT_EEMSE_FvT0_ET1_EUlS2_E_E9_M_invokeERKSt9_Any_dataS2_
> @ 0x2b86c32d174f std::function<>::operator()()
> @ 0x2b86c32b2a17 process::ProcessBase::visit()
> @ 0x2b86c32bd34c process::DispatchEvent::visit()
> @ 0x8e0812 process::ProcessBase::serve()
> @ 0x2b86c32aec8c process::ProcessManager::resume()
> I1030 05:55:22.050081 24478 slave.cpp:1050] Will retry registration in
> 25.327301ms if necessary
> @ 0x2b86c32a5351 process::schedule()
> @ 0x2b86c55f4182 start_thread
> @ 0x2b86c5904fbd (unknown)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
