You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Benjamin Mahler (JIRA)" <ji...@apache.org> on 2014/09/11 06:39:33 UTC
[jira] [Updated] (MESOS-1786)
FaultToleranceTest.ReconcilePendingTasks is flaky.
[ https://issues.apache.org/jira/browse/MESOS-1786?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Benjamin Mahler updated MESOS-1786:
-----------------------------------
Sprint: Mesos Q3 Sprint 5
> FaultToleranceTest.ReconcilePendingTasks is flaky.
> --------------------------------------------------
>
> Key: MESOS-1786
> URL: https://issues.apache.org/jira/browse/MESOS-1786
> Project: Mesos
> Issue Type: Bug
> Components: test
> Reporter: Benjamin Mahler
> Assignee: Benjamin Mahler
>
> {noformat}
> [ RUN ] FaultToleranceTest.ReconcilePendingTasks
> Using temporary directory '/tmp/FaultToleranceTest_ReconcilePendingTasks_TwmFlm'
> I0910 20:18:02.308562 21634 leveldb.cpp:176] Opened db in 28.520372ms
> I0910 20:18:02.315268 21634 leveldb.cpp:183] Compacted db in 6.37495ms
> I0910 20:18:02.315588 21634 leveldb.cpp:198] Created db iterator in 6338ns
> I0910 20:18:02.315745 21634 leveldb.cpp:204] Seeked to beginning of db in 1781ns
> I0910 20:18:02.315901 21634 leveldb.cpp:273] Iterated through 0 keys in the db in 537ns
> I0910 20:18:02.316076 21634 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I0910 20:18:02.316524 21654 recover.cpp:425] Starting replica recovery
> I0910 20:18:02.316800 21654 recover.cpp:451] Replica is in EMPTY status
> I0910 20:18:02.317245 21654 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
> I0910 20:18:02.317445 21654 recover.cpp:188] Received a recover response from a replica in EMPTY status
> I0910 20:18:02.317672 21654 recover.cpp:542] Updating replica status to STARTING
> I0910 20:18:02.321723 21652 master.cpp:286] Master 20140910-201802-16842879-60361-21634 (precise) started on 127.0.1.1:60361
> I0910 20:18:02.322041 21652 master.cpp:332] Master only allowing authenticated frameworks to register
> I0910 20:18:02.322320 21652 master.cpp:337] Master only allowing authenticated slaves to register
> I0910 20:18:02.322568 21652 credentials.hpp:36] Loading credentials for authentication from '/tmp/FaultToleranceTest_ReconcilePendingTasks_TwmFlm/credentials'
> I0910 20:18:02.323031 21652 master.cpp:366] Authorization enabled
> I0910 20:18:02.323663 21654 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 5.781277ms
> I0910 20:18:02.324074 21654 replica.cpp:320] Persisted replica status to STARTING
> I0910 20:18:02.324443 21654 recover.cpp:451] Replica is in STARTING status
> I0910 20:18:02.325106 21654 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
> I0910 20:18:02.325454 21654 recover.cpp:188] Received a recover response from a replica in STARTING status
> I0910 20:18:02.326408 21654 recover.cpp:542] Updating replica status to VOTING
> I0910 20:18:02.323892 21649 hierarchical_allocator_process.hpp:299] Initializing hierarchical allocator process with master : master@127.0.1.1:60361
> I0910 20:18:02.326120 21652 master.cpp:1212] The newly elected leader is master@127.0.1.1:60361 with id 20140910-201802-16842879-60361-21634
> I0910 20:18:02.323938 21651 master.cpp:120] No whitelist given. Advertising offers for all slaves
> I0910 20:18:04.209081 21655 hierarchical_allocator_process.hpp:697] No resources available to allocate!
> I0910 20:18:04.209183 21655 hierarchical_allocator_process.hpp:659] Performed allocation for 0 slaves in 118308ns
> I0910 20:18:04.209230 21652 master.cpp:1225] Elected as the leading master!
> I0910 20:18:04.209246 21652 master.cpp:1043] Recovering from registrar
> I0910 20:18:04.209360 21650 registrar.cpp:313] Recovering registrar
> I0910 20:18:04.214040 21654 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 1.887284299secs
> I0910 20:18:04.214094 21654 replica.cpp:320] Persisted replica status to VOTING
> I0910 20:18:04.214190 21654 recover.cpp:556] Successfully joined the Paxos group
> I0910 20:18:04.214258 21654 recover.cpp:440] Recover process terminated
> I0910 20:18:04.214437 21654 log.cpp:656] Attempting to start the writer
> I0910 20:18:04.214756 21654 replica.cpp:474] Replica received implicit promise request with proposal 1
> I0910 20:18:04.223865 21654 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 9.044596ms
> I0910 20:18:04.223944 21654 replica.cpp:342] Persisted promised to 1
> I0910 20:18:04.229053 21652 coordinator.cpp:230] Coordinator attemping to fill missing position
> I0910 20:18:04.229552 21652 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
> I0910 20:18:04.248437 21652 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 18.839475ms
> I0910 20:18:04.248525 21652 replica.cpp:676] Persisted action at 0
> I0910 20:18:04.251194 21650 replica.cpp:508] Replica received write request for position 0
> I0910 20:18:04.251260 21650 leveldb.cpp:438] Reading position from leveldb took 43213ns
> I0910 20:18:04.262251 21650 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 10.949353ms
> I0910 20:18:04.262346 21650 replica.cpp:676] Persisted action at 0
> I0910 20:18:04.262717 21650 replica.cpp:655] Replica received learned notice for position 0
> I0910 20:18:04.271878 21650 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 9.087356ms
> I0910 20:18:04.271956 21650 replica.cpp:676] Persisted action at 0
> I0910 20:18:04.271972 21650 replica.cpp:661] Replica learned NOP action at position 0
> I0910 20:18:04.275356 21653 log.cpp:672] Writer started with ending position 0
> I0910 20:18:04.276454 21653 leveldb.cpp:438] Reading position from leveldb took 37820ns
> I0910 20:18:04.277881 21653 registrar.cpp:346] Successfully fetched the registry (0B)
> I0910 20:18:04.277921 21653 registrar.cpp:422] Attempting to update the 'registry'
> I0910 20:18:04.280483 21655 log.cpp:680] Attempting to append 120 bytes to the log
> I0910 20:18:04.281225 21655 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
> I0910 20:18:04.281950 21655 replica.cpp:508] Replica received write request for position 1
> I0910 20:18:04.292848 21655 leveldb.cpp:343] Persisting action (137 bytes) to leveldb took 10.351597ms
> I0910 20:18:04.293210 21655 replica.cpp:676] Persisted action at 1
> I0910 20:18:04.293721 21655 replica.cpp:655] Replica received learned notice for position 1
> I0910 20:18:04.302923 21655 leveldb.cpp:343] Persisting action (139 bytes) to leveldb took 8.901156ms
> I0910 20:18:04.303695 21655 replica.cpp:676] Persisted action at 1
> I0910 20:18:04.303903 21655 replica.cpp:661] Replica learned APPEND action at position 1
> I0910 20:18:04.304616 21655 registrar.cpp:479] Successfully updated 'registry'
> I0910 20:18:04.304955 21655 registrar.cpp:372] Successfully recovered registrar
> I0910 20:18:04.304765 21651 log.cpp:699] Attempting to truncate the log to 1
> I0910 20:18:04.305518 21652 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
> I0910 20:18:04.305964 21652 replica.cpp:508] Replica received write request for position 2
> I0910 20:18:04.306421 21654 master.cpp:1070] Recovered 0 slaves from the Registry (84B) ; allowing 10mins for slaves to re-register
> I0910 20:18:04.316412 21652 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 10.237975ms
> I0910 20:18:04.317004 21652 replica.cpp:676] Persisted action at 2
> I0910 20:18:04.317464 21652 replica.cpp:655] Replica received learned notice for position 2
> I0910 20:18:04.329123 21652 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 11.358383ms
> I0910 20:18:04.329660 21652 leveldb.cpp:401] Deleting ~1 keys from leveldb took 269555ns
> I0910 20:18:04.329916 21652 replica.cpp:676] Persisted action at 2
> I0910 20:18:04.330127 21652 replica.cpp:661] Replica learned TRUNCATE action at position 2
> I0910 20:18:04.339833 21634 containerizer.cpp:89] Using isolation: posix/cpu,posix/mem
> I0910 20:18:04.344403 21653 slave.cpp:169] Slave started on 24)@127.0.1.1:60361
> I0910 20:18:04.344971 21653 credentials.hpp:84] Loading credential for authentication from '/tmp/FaultToleranceTest_ReconcilePendingTasks_FXm7UD/credential'
> I0910 20:18:04.345918 21653 slave.cpp:276] Slave using credential for: test-principal
> I0910 20:18:04.346575 21653 slave.cpp:289] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0910 20:18:04.347172 21653 slave.cpp:317] Slave hostname: precise
> I0910 20:18:04.347419 21653 slave.cpp:318] Slave checkpoint: false
> I0910 20:18:04.349021 21653 state.cpp:33] Recovering state from '/tmp/FaultToleranceTest_ReconcilePendingTasks_FXm7UD/meta'
> I0910 20:18:04.349709 21648 status_update_manager.cpp:193] Recovering status update manager
> I0910 20:18:04.350198 21651 containerizer.cpp:252] Recovering containerizer
> I0910 20:18:04.351310 21648 slave.cpp:3219] Finished recovery
> I0910 20:18:04.352331 21648 slave.cpp:600] New master detected at master@127.0.1.1:60361
> I0910 20:18:04.352740 21648 slave.cpp:674] Authenticating with master master@127.0.1.1:60361
> I0910 20:18:04.353178 21648 slave.cpp:647] Detecting new master
> I0910 20:18:04.352905 21650 status_update_manager.cpp:167] New master detected at master@127.0.1.1:60361
> I0910 20:18:04.353587 21651 authenticatee.hpp:128] Creating new client SASL connection
> I0910 20:18:04.354601 21651 master.cpp:3653] Authenticating slave(24)@127.0.1.1:60361
> I0910 20:18:04.355185 21651 authenticator.hpp:156] Creating new server SASL connection
> I0910 20:18:04.355768 21651 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0910 20:18:04.356117 21651 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0910 20:18:04.356462 21651 authenticator.hpp:262] Received SASL authentication start
> I0910 20:18:04.356808 21651 authenticator.hpp:384] Authentication requires more steps
> I0910 20:18:04.357166 21654 authenticatee.hpp:265] Received SASL authentication step
> I0910 20:18:04.357511 21651 authenticator.hpp:290] Received SASL authentication step
> I0910 20:18:04.357791 21651 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0910 20:18:04.358079 21651 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0910 20:18:04.358352 21651 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0910 20:18:04.358670 21651 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0910 20:18:04.358933 21651 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0910 20:18:04.359192 21651 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0910 20:18:04.359459 21651 authenticator.hpp:376] Authentication success
> I0910 20:18:04.359907 21655 authenticatee.hpp:305] Authentication success
> I0910 20:18:04.363769 21651 master.cpp:3693] Successfully authenticated principal 'test-principal' at slave(24)@127.0.1.1:60361
> I0910 20:18:04.367661 21655 slave.cpp:731] Successfully authenticated with master master@127.0.1.1:60361
> I0910 20:18:04.370323 21652 master.cpp:2843] Registering slave at slave(24)@127.0.1.1:60361 (precise) with id 20140910-201802-16842879-60361-21634-0
> I0910 20:18:04.371011 21652 registrar.cpp:422] Attempting to update the 'registry'
> I0910 20:18:04.373313 21652 log.cpp:680] Attempting to append 295 bytes to the log
> I0910 20:18:04.373972 21654 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
> I0910 20:18:04.374662 21654 replica.cpp:508] Replica received write request for position 3
> I0910 20:18:04.375222 21655 slave.cpp:994] Will retry registration in 11.863581ms if necessary
> I0910 20:18:04.376184 21634 sched.cpp:137] Version: 0.21.0
> I0910 20:18:04.376742 21648 sched.cpp:233] New master detected at master@127.0.1.1:60361
> I0910 20:18:04.377110 21648 sched.cpp:283] Authenticating with master master@127.0.1.1:60361
> I0910 20:18:04.377522 21648 authenticatee.hpp:128] Creating new client SASL connection
> I0910 20:18:04.378106 21648 master.cpp:3653] Authenticating scheduler-a1fcef65-4ac6-4d25-b188-183b31a8ed07@127.0.1.1:60361
> I0910 20:18:04.378566 21648 authenticator.hpp:156] Creating new server SASL connection
> I0910 20:18:04.379065 21648 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0910 20:18:04.379361 21648 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0910 20:18:04.379767 21648 authenticator.hpp:262] Received SASL authentication start
> I0910 20:18:04.380115 21648 authenticator.hpp:384] Authentication requires more steps
> I0910 20:18:04.380450 21648 authenticatee.hpp:265] Received SASL authentication step
> I0910 20:18:04.380851 21651 authenticator.hpp:290] Received SASL authentication step
> I0910 20:18:04.381153 21651 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0910 20:18:04.381420 21651 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0910 20:18:04.381705 21651 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0910 20:18:04.381968 21651 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0910 20:18:04.382248 21651 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0910 20:18:04.382503 21651 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0910 20:18:04.382761 21651 authenticator.hpp:376] Authentication success
> I0910 20:18:04.383116 21651 master.cpp:3693] Successfully authenticated principal 'test-principal' at scheduler-a1fcef65-4ac6-4d25-b188-183b31a8ed07@127.0.1.1:60361
> I0910 20:18:04.383469 21654 leveldb.cpp:343] Persisting action (314 bytes) to leveldb took 8.456876ms
> I0910 20:18:04.387476 21654 replica.cpp:676] Persisted action at 3
> I0910 20:18:04.387897 21648 authenticatee.hpp:305] Authentication success
> I0910 20:18:04.388624 21654 replica.cpp:655] Replica received learned notice for position 3
> I0910 20:18:04.388919 21653 slave.cpp:994] Will retry registration in 10.775584ms if necessary
> I0910 20:18:04.389798 21648 sched.cpp:357] Successfully authenticated with master master@127.0.1.1:60361
> I0910 20:18:04.390142 21648 sched.cpp:476] Sending registration request to master@127.0.1.1:60361
> I0910 20:18:04.390756 21651 master.cpp:2831] Ignoring register slave message from slave(24)@127.0.1.1:60361 (precise) as admission is already in progress
> I0910 20:18:04.391089 21651 master.cpp:1331] Received registration request from scheduler-a1fcef65-4ac6-4d25-b188-183b31a8ed07@127.0.1.1:60361
> I0910 20:18:04.391381 21651 master.cpp:1291] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I0910 20:18:04.391989 21651 master.cpp:1390] Registering framework 20140910-201802-16842879-60361-21634-0000 at scheduler-a1fcef65-4ac6-4d25-b188-183b31a8ed07@127.0.1.1:60361
> I0910 20:18:04.392401 21649 sched.cpp:407] Framework registered with 20140910-201802-16842879-60361-21634-0000
> I0910 20:18:04.392680 21649 sched.cpp:421] Scheduler::registered took 18845ns
> I0910 20:18:04.393061 21653 hierarchical_allocator_process.hpp:329] Added framework 20140910-201802-16842879-60361-21634-0000
> I0910 20:18:04.393316 21653 hierarchical_allocator_process.hpp:697] No resources available to allocate!
> I0910 20:18:04.393573 21653 hierarchical_allocator_process.hpp:659] Performed allocation for 0 slaves in 257139ns
> I0910 20:18:04.400673 21654 leveldb.cpp:343] Persisting action (316 bytes) to leveldb took 11.558054ms
> I0910 20:18:04.401371 21654 replica.cpp:676] Persisted action at 3
> I0910 20:18:04.401671 21654 replica.cpp:661] Replica learned APPEND action at position 3
> I0910 20:18:04.402506 21654 registrar.cpp:479] Successfully updated 'registry'
> I0910 20:18:04.401196 21653 master.cpp:2831] Ignoring register slave message from slave(24)@127.0.1.1:60361 (precise) as admission is already in progress
> I0910 20:18:04.403311 21653 master.cpp:2883] Registered slave 20140910-201802-16842879-60361-21634-0 at slave(24)@127.0.1.1:60361 (precise)
> I0910 20:18:04.403646 21653 master.cpp:4126] Adding slave 20140910-201802-16842879-60361-21634-0 at slave(24)@127.0.1.1:60361 (precise) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0910 20:18:04.404180 21653 hierarchical_allocator_process.hpp:442] Added slave 20140910-201802-16842879-60361-21634-0 (precise) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I0910 20:18:04.404558 21653 hierarchical_allocator_process.hpp:734] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140910-201802-16842879-60361-21634-0 to framework 20140910-201802-16842879-60361-21634-0000
> I0910 20:18:04.404975 21653 hierarchical_allocator_process.hpp:679] Performed allocation for slave 20140910-201802-16842879-60361-21634-0 in 459402ns
> I0910 20:18:04.401103 21652 slave.cpp:994] Will retry registration in 20.005959ms if necessary
> I0910 20:18:04.405747 21652 slave.cpp:765] Registered with master master@127.0.1.1:60361; given slave ID 20140910-201802-16842879-60361-21634-0
> I0910 20:18:04.406059 21652 slave.cpp:2346] Received ping from slave-observer(25)@127.0.1.1:60361
> I0910 20:18:04.402688 21648 log.cpp:699] Attempting to truncate the log to 3
> I0910 20:18:04.406587 21648 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
> I0910 20:18:04.407150 21648 replica.cpp:508] Replica received write request for position 4
> I0910 20:18:04.405216 21655 master.hpp:861] Adding offer 20140910-201802-16842879-60361-21634-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140910-201802-16842879-60361-21634-0 (precise)
> I0910 20:18:04.407920 21655 master.cpp:3600] Sending 1 offers to framework 20140910-201802-16842879-60361-21634-0000
> I0910 20:18:04.408318 21655 sched.cpp:544] Scheduler::resourceOffers took 36202ns
> I0910 20:18:04.411108 21652 master.hpp:871] Removing offer 20140910-201802-16842879-60361-21634-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140910-201802-16842879-60361-21634-0 (precise)
> I0910 20:18:04.411722 21652 master.cpp:2201] Processing reply for offers: [ 20140910-201802-16842879-60361-21634-0 ] on slave 20140910-201802-16842879-60361-21634-0 at slave(24)@127.0.1.1:60361 (precise) for framework 20140910-201802-16842879-60361-21634-0000
> I0910 20:18:04.411389 21650 slave.cpp:600] New master detected at master@127.0.1.1:60361
> I0910 20:18:04.412308 21650 slave.cpp:674] Authenticating with master master@127.0.1.1:60361
> I0910 20:18:04.412757 21650 slave.cpp:647] Detecting new master
> I0910 20:18:04.413105 21650 authenticatee.hpp:128] Creating new client SASL connection
> I0910 20:18:04.412503 21649 status_update_manager.cpp:167] New master detected at master@127.0.1.1:60361
> I0910 20:18:04.413862 21652 master.cpp:2284] Authorizing framework principal 'test-principal' to launch task 1 as user 'jenkins'
> I0910 20:18:04.414806 21652 master.cpp:1712] Disconnecting slave 20140910-201802-16842879-60361-21634-0
> I0910 20:18:04.415308 21652 master.cpp:3653] Authenticating slave(24)@127.0.1.1:60361
> I0910 20:18:04.415475 21650 hierarchical_allocator_process.hpp:481] Slave 20140910-201802-16842879-60361-21634-0 deactivated
> I0910 20:18:04.416304 21654 authenticator.hpp:156] Creating new server SASL connection
> I0910 20:18:04.416821 21654 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0910 20:18:04.417127 21654 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0910 20:18:04.417448 21654 authenticator.hpp:262] Received SASL authentication start
> I0910 20:18:04.417774 21654 authenticator.hpp:384] Authentication requires more steps
> I0910 20:18:04.418092 21654 authenticatee.hpp:265] Received SASL authentication step
> I0910 20:18:04.418447 21654 authenticator.hpp:290] Received SASL authentication step
> I0910 20:18:04.418763 21654 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0910 20:18:04.419051 21654 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0910 20:18:04.419308 21654 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0910 20:18:04.419648 21654 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0910 20:18:04.420095 21654 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0910 20:18:04.421145 21654 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0910 20:18:04.419919 21648 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 12.505129ms
> I0910 20:18:04.421670 21648 replica.cpp:676] Persisted action at 4
> I0910 20:18:04.422497 21655 replica.cpp:655] Replica received learned notice for position 4
> I0910 20:18:04.423131 21654 authenticator.hpp:376] Authentication success
> I0910 20:18:04.423929 21654 authenticatee.hpp:305] Authentication success
> I0910 20:18:04.424384 21650 slave.cpp:731] Successfully authenticated with master master@127.0.1.1:60361
> I0910 20:18:04.424733 21650 slave.cpp:994] Will retry registration in 13.701773ms if necessary
> I0910 20:18:04.425688 21652 master.cpp:3207] Sending status update TASK_LOST (UUID: b30985be-9f73-4cb7-aee1-fa467f35663a) for task 1 of framework 20140910-201802-16842879-60361-21634-0000 'Slave disconnected'
> I0910 20:18:04.426226 21649 slave.cpp:994] Will retry registration in 72.412521ms if necessary
> tests/fault_tolerance_tests.cpp:2252: Failure
> Mock function called more times than expected - returning directly.
> Function call: statusUpdate(0x7fffb701c160, @0x2b9c8c000a10 80-byte object <D0-63 A9-7F 9C-2B 00-00 00-00 00-00 00-00 00-00 00-DA 05-8C 9C-2B 00-00 A0-6E 05-8C 9C-2B 00-00 B8-92 F8-00 00-00 00-00 40-10 05-8C 9C-2B 00-00 05-00 00-00 00-36 30-33 00-00 00-00 00-00 00-00 2F-A2 5A-56 45-04 D5-41 00-00 00-00 57-00 00-00>)
> Expected: to be never called
> Actual: called once - over-saturated and active
> I0910 20:18:04.427433 21653 sched.cpp:635] Scheduler::statusUpdate took 788485ns
> I0910 20:18:04.428004 21650 hierarchical_allocator_process.hpp:563] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20140910-201802-16842879-60361-21634-0 from framework 20140910-201802-16842879-60361-21634-0000
> I0910 20:18:04.428382 21652 master.cpp:3693] Successfully authenticated principal 'test-principal' at slave(24)@127.0.1.1:60361
> I0910 20:18:04.432242 21655 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 9.373136ms
> I0910 20:18:04.432965 21655 leveldb.cpp:401] Deleting ~2 keys from leveldb took 60691ns
> I0910 20:18:04.433315 21655 replica.cpp:676] Persisted action at 4
> I0910 20:18:04.433562 21655 replica.cpp:661] Replica learned TRUNCATE action at position 4
> W0910 20:18:04.434289 21652 master.cpp:2958] Slave at slave(24)@127.0.1.1:60361 (precise) is being allowed to re-register with an already in use id (20140910-201802-16842879-60361-21634-0)
> I0910 20:18:04.434967 21649 slave.cpp:827] Re-registered with master master@127.0.1.1:60361
> I0910 20:18:04.435667 21653 hierarchical_allocator_process.hpp:495] Slave 20140910-201802-16842879-60361-21634-0 reactivated
> W0910 20:18:04.436084 21652 master.cpp:2958] Slave at slave(24)@127.0.1.1:60361 (precise) is being allowed to re-register with an already in use id (20140910-201802-16842879-60361-21634-0)
> W0910 20:18:04.436462 21654 slave.cpp:842] Already re-registered with master master@127.0.1.1:60361
> I0910 20:18:04.446319 21634 master.cpp:650] Master terminating
> I0910 20:18:04.446532 21651 sched.cpp:745] Stopping framework '20140910-201802-16842879-60361-21634-0000'
> I0910 20:18:04.447758 21651 slave.cpp:2378] master@127.0.1.1:60361 exited
> W0910 20:18:04.448004 21651 slave.cpp:2381] Master disconnected! Waiting for a new master to be elected
> I0910 20:18:04.451472 21650 slave.cpp:477] Slave terminating
> ../3rdparty/libprocess/include/process/gmock.hpp:298: Failure
> Actual function call count doesn't match EXPECT_CALL(filter->mock, filter(testing::A<const DispatchEvent&>()))...
> Expected args: dispatch matcher (1, 16-byte object <D0-5E 4A-00 00-00 00-00 00-00 00-00 00-00 00-00>)
> Expected: to be called once
> Actual: never called - unsatisfied and active
> [ FAILED ] FaultToleranceTest.ReconcilePendingTasks (2197 ms)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)