You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mesos.apache.org by "Dominic Hamon (JIRA)" <ji...@apache.org> on 2014/06/07 00:40:01 UTC
[jira] [Commented] (MESOS-1422) AllocatorTest/0.SchedulerFailover
test is flaky
[ https://issues.apache.org/jira/browse/MESOS-1422?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14020475#comment-14020475 ]
Dominic Hamon commented on MESOS-1422:
--------------------------------------
https://reviews.apache.org/r/22330/
> AllocatorTest/0.SchedulerFailover test is flaky
> -----------------------------------------------
>
> Key: MESOS-1422
> URL: https://issues.apache.org/jira/browse/MESOS-1422
> Project: Mesos
> Issue Type: Bug
> Components: test
> Affects Versions: 0.19.0
> Reporter: Vinod Kone
> Assignee: Dominic Hamon
>
> {noformat}
> [ RUN ] AllocatorTest/0.SchedulerFailover
> Using temporary directory '/tmp/AllocatorTest_0_SchedulerFailover_c1BnNj'
> I0527 18:39:49.033879 22750 leveldb.cpp:176] Opened db in 4.280975ms
> I0527 18:39:49.034219 22750 leveldb.cpp:183] Compacted db in 315241ns
> I0527 18:39:49.034234 22750 leveldb.cpp:198] Created db iterator in 4763ns
> I0527 18:39:49.034240 22750 leveldb.cpp:204] Seeked to beginning of db in 776ns
> I0527 18:39:49.034246 22750 leveldb.cpp:273] Iterated through 0 keys in the db in 313ns
> I0527 18:39:49.034261 22750 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I0527 18:39:49.034559 22776 recover.cpp:425] Starting replica recovery
> I0527 18:39:49.034740 22777 recover.cpp:451] Replica is in EMPTY status
> I0527 18:39:49.035194 22773 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
> I0527 18:39:49.035333 22774 recover.cpp:188] Received a recover response from a replica in EMPTY status
> I0527 18:39:49.035465 22777 recover.cpp:542] Updating replica status to STARTING
> I0527 18:39:49.036082 22770 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 554995ns
> I0527 18:39:49.036095 22770 replica.cpp:320] Persisted replica status to STARTING
> I0527 18:39:49.036195 22770 recover.cpp:451] Replica is in STARTING status
> I0527 18:39:49.036375 22775 master.cpp:272] Master 20140527-183949-143311683-39317-22750 (minerva.apache.org) started on 67.195.138.8:39317
> I0527 18:39:49.036389 22775 master.cpp:309] Master only allowing authenticated frameworks to register
> I0527 18:39:49.036396 22775 master.cpp:314] Master only allowing authenticated slaves to register
> I0527 18:39:49.036404 22775 credentials.hpp:35] Loading credentials for authentication from '/tmp/AllocatorTest_0_SchedulerFailover_c1BnNj/credentials'
> I0527 18:39:49.036476 22775 master.cpp:340] Master enabling authorization
> I0527 18:39:49.036633 22777 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
> I0527 18:39:49.036784 22777 master.cpp:108] No whitelist given. Advertising offers for all slaves
> I0527 18:39:49.037078 22776 hierarchical_allocator_process.hpp:301] Initializing hierarchical allocator process with master : master@67.195.138.8:39317
> I0527 18:39:49.037120 22774 recover.cpp:188] Received a recover response from a replica in STARTING status
> I0527 18:39:49.037168 22770 master.cpp:936] The newly elected leader is master@67.195.138.8:39317 with id 20140527-183949-143311683-39317-22750
> I0527 18:39:49.037185 22770 master.cpp:949] Elected as the leading master!
> I0527 18:39:49.037194 22770 master.cpp:767] Recovering from registrar
> I0527 18:39:49.037246 22777 registrar.cpp:313] Recovering registrar
> I0527 18:39:49.037331 22772 recover.cpp:542] Updating replica status to VOTING
> I0527 18:39:49.037518 22777 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 115462ns
> I0527 18:39:49.037530 22777 replica.cpp:320] Persisted replica status to VOTING
> I0527 18:39:49.037576 22772 recover.cpp:556] Successfully joined the Paxos group
> I0527 18:39:49.037653 22772 recover.cpp:440] Recover process terminated
> I0527 18:39:49.037768 22777 log.cpp:656] Attempting to start the writer
> I0527 18:39:49.038187 22777 replica.cpp:474] Replica received implicit promise request with proposal 1
> I0527 18:39:49.038281 22777 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 82264ns
> I0527 18:39:49.038292 22777 replica.cpp:342] Persisted promised to 1
> I0527 18:39:49.038519 22770 coordinator.cpp:230] Coordinator attemping to fill missing position
> I0527 18:39:49.039046 22774 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
> I0527 18:39:49.039160 22774 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 100359ns
> I0527 18:39:49.039171 22774 replica.cpp:676] Persisted action at 0
> I0527 18:39:49.039580 22777 replica.cpp:508] Replica received write request for position 0
> I0527 18:39:49.039607 22777 leveldb.cpp:438] Reading position from leveldb took 14246ns
> I0527 18:39:49.039716 22777 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 94200ns
> I0527 18:39:49.039727 22777 replica.cpp:676] Persisted action at 0
> I0527 18:39:49.039923 22771 replica.cpp:655] Replica received learned notice for position 0
> I0527 18:39:49.040056 22771 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 115341ns
> I0527 18:39:49.040067 22771 replica.cpp:676] Persisted action at 0
> I0527 18:39:49.040077 22771 replica.cpp:661] Replica learned NOP action at position 0
> I0527 18:39:49.040308 22774 log.cpp:672] Writer started with ending position 0
> I0527 18:39:49.040755 22775 leveldb.cpp:438] Reading position from leveldb took 7629ns
> I0527 18:39:49.041780 22776 registrar.cpp:346] Successfully fetched the registry (0B)
> I0527 18:39:49.041805 22776 registrar.cpp:422] Attempting to update the 'registry'
> I0527 18:39:49.042788 22773 log.cpp:680] Attempting to append 137 bytes to the log
> I0527 18:39:49.042891 22771 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
> I0527 18:39:49.043326 22772 replica.cpp:508] Replica received write request for position 1
> I0527 18:39:49.043556 22772 leveldb.cpp:343] Persisting action (156 bytes) to leveldb took 199861ns
> I0527 18:39:49.043570 22772 replica.cpp:676] Persisted action at 1
> I0527 18:39:49.043906 22774 replica.cpp:655] Replica received learned notice for position 1
> I0527 18:39:49.044050 22774 leveldb.cpp:343] Persisting action (158 bytes) to leveldb took 130432ns
> I0527 18:39:49.044062 22774 replica.cpp:676] Persisted action at 1
> I0527 18:39:49.044070 22774 replica.cpp:661] Replica learned APPEND action at position 1
> I0527 18:39:49.044378 22772 registrar.cpp:479] Successfully updated 'registry'
> I0527 18:39:49.044461 22772 registrar.cpp:372] Successfully recovered registrar
> I0527 18:39:49.044589 22777 log.cpp:699] Attempting to truncate the log to 1
> I0527 18:39:49.044595 22770 master.cpp:794] Recovered 0 slaves from the Registry (99B) ; allowing 10mins for slaves to re-register
> I0527 18:39:49.044667 22771 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
> I0527 18:39:49.045047 22775 replica.cpp:508] Replica received write request for position 2
> I0527 18:39:49.057709 22777 slave.cpp:143] Slave started on 62)@67.195.138.8:39317
> I0527 18:39:49.293050 22777 credentials.hpp:35] Loading credentials for authentication from '/tmp/AllocatorTest_0_SchedulerFailover_MYos5v/credential'
> I0527 18:39:49.059094 22750 sched.cpp:121] Version: 0.19.0
> I0527 18:39:49.293115 22777 slave.cpp:242] Slave using credential for: test-principal
> I0527 18:39:49.293184 22775 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 145967ns
> I0527 18:39:49.293205 22775 replica.cpp:676] Persisted action at 2
> I0527 18:39:49.293220 22777 slave.cpp:255] Slave resources: cpus(*):3; mem(*):1024; disk(*):23038; ports(*):[31000-32000]
> I0527 18:39:49.293289 22777 slave.cpp:283] Slave hostname: minerva.apache.org
> I0527 18:39:49.293298 22777 slave.cpp:284] Slave checkpoint: false
> I0527 18:39:49.293311 22774 sched.cpp:217] New master detected at master@67.195.138.8:39317
> I0527 18:39:49.293333 22774 sched.cpp:268] Authenticating with master master@67.195.138.8:39317
> I0527 18:39:49.293460 22770 replica.cpp:655] Replica received learned notice for position 2
> I0527 18:39:49.293498 22776 authenticatee.hpp:128] Creating new client SASL connection
> I0527 18:39:49.293598 22770 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 124005ns
> I0527 18:39:49.293627 22770 leveldb.cpp:401] Deleting ~1 keys from leveldb took 11392ns
> I0527 18:39:49.293637 22770 replica.cpp:676] Persisted action at 2
> I0527 18:39:49.293645 22770 replica.cpp:661] Replica learned TRUNCATE action at position 2
> I0527 18:39:49.293772 22773 state.cpp:33] Recovering state from '/tmp/AllocatorTest_0_SchedulerFailover_MYos5v/meta'
> I0527 18:39:49.293797 22776 master.cpp:2896] Authenticating scheduler(59)@67.195.138.8:39317
> I0527 18:39:49.293954 22773 authenticator.hpp:156] Creating new server SASL connection
> I0527 18:39:49.294090 22773 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0527 18:39:49.294107 22773 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0527 18:39:49.294147 22773 authenticator.hpp:262] Received SASL authentication start
> I0527 18:39:49.294191 22773 authenticator.hpp:384] Authentication requires more steps
> I0527 18:39:49.294215 22773 authenticatee.hpp:265] Received SASL authentication step
> I0527 18:39:49.294277 22773 authenticator.hpp:290] Received SASL authentication step
> I0527 18:39:49.294292 22773 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'minerva.apache.org' server FQDN: 'minerva.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0527 18:39:49.294302 22773 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0527 18:39:49.294312 22773 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0527 18:39:49.294320 22773 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'minerva.apache.org' server FQDN: 'minerva.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0527 18:39:49.294327 22773 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0527 18:39:49.294332 22773 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0527 18:39:49.294340 22773 authenticator.hpp:376] Authentication success
> I0527 18:39:49.294422 22770 authenticatee.hpp:305] Authentication success
> I0527 18:39:49.294440 22774 master.cpp:2936] Successfully authenticated principal 'test-principal' at scheduler(59)@67.195.138.8:39317
> I0527 18:39:49.294459 22773 status_update_manager.cpp:193] Recovering status update manager
> I0527 18:39:49.294543 22770 sched.cpp:342] Successfully authenticated with master master@67.195.138.8:39317
> I0527 18:39:49.294567 22770 sched.cpp:461] Sending registration request to master@67.195.138.8:39317
> W0527 18:39:49.294620 22774 master.cpp:1008] Framework at scheduler(59)@67.195.138.8:39317 does not specify principal in its FrameworkInfo
> I0527 18:39:49.294633 22774 master.cpp:1020] Received registration request from scheduler(59)@67.195.138.8:39317
> I0527 18:39:49.294677 22774 master.cpp:1038] Registering framework 20140527-183949-143311683-39317-22750-0000 at scheduler(59)@67.195.138.8:39317
> I0527 18:39:49.294693 22775 slave.cpp:2988] Finished recovery
> I0527 18:39:49.294775 22773 sched.cpp:392] Framework registered with 20140527-183949-143311683-39317-22750-0000
> I0527 18:39:49.294800 22773 sched.cpp:406] Scheduler::registered took 14760ns
> I0527 18:39:49.294837 22774 hierarchical_allocator_process.hpp:331] Added framework 20140527-183949-143311683-39317-22750-0000
> I0527 18:39:49.294847 22774 hierarchical_allocator_process.hpp:725] No resources available to allocate!
> I0527 18:39:49.294853 22774 hierarchical_allocator_process.hpp:687] Performed allocation for 0 slaves in 5683ns
> I0527 18:39:49.295058 22777 slave.cpp:536] New master detected at master@67.195.138.8:39317
> I0527 18:39:49.295092 22777 slave.cpp:612] Authenticating with master master@67.195.138.8:39317
> I0527 18:39:49.295135 22775 status_update_manager.cpp:167] New master detected at master@67.195.138.8:39317
> I0527 18:39:49.295156 22777 slave.cpp:585] Detecting new master
> I0527 18:39:49.295173 22776 authenticatee.hpp:128] Creating new client SASL connection
> I0527 18:39:49.295315 22774 master.cpp:2896] Authenticating slave(62)@67.195.138.8:39317
> I0527 18:39:49.295389 22777 authenticator.hpp:156] Creating new server SASL connection
> I0527 18:39:49.295526 22775 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0527 18:39:49.295543 22775 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0527 18:39:49.295580 22776 authenticator.hpp:262] Received SASL authentication start
> I0527 18:39:49.295622 22776 authenticator.hpp:384] Authentication requires more steps
> I0527 18:39:49.295650 22776 authenticatee.hpp:265] Received SASL authentication step
> I0527 18:39:49.295740 22774 authenticator.hpp:290] Received SASL authentication step
> I0527 18:39:49.295789 22774 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'minerva.apache.org' server FQDN: 'minerva.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0527 18:39:49.295800 22774 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0527 18:39:49.295809 22774 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0527 18:39:49.295819 22774 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'minerva.apache.org' server FQDN: 'minerva.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0527 18:39:49.295825 22774 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0527 18:39:49.295830 22774 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0527 18:39:49.295840 22774 authenticator.hpp:376] Authentication success
> I0527 18:39:49.295903 22773 authenticatee.hpp:305] Authentication success
> I0527 18:39:49.295922 22774 master.cpp:2936] Successfully authenticated principal 'test-principal' at slave(62)@67.195.138.8:39317
> I0527 18:39:49.296052 22773 slave.cpp:669] Successfully authenticated with master master@67.195.138.8:39317
> I0527 18:39:49.296100 22773 slave.cpp:903] Will retry registration in 3.726421ms if necessary
> I0527 18:39:49.296176 22770 master.cpp:2212] Registering slave at slave(62)@67.195.138.8:39317 (minerva.apache.org) with id 20140527-183949-143311683-39317-22750-0
> I0527 18:39:49.296330 22777 registrar.cpp:422] Attempting to update the 'registry'
> I0527 18:39:49.297399 22775 log.cpp:680] Attempting to append 333 bytes to the log
> I0527 18:39:49.297467 22771 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
> I0527 18:39:49.297865 22777 replica.cpp:508] Replica received write request for position 3
> I0527 18:39:49.300346 22775 slave.cpp:903] Will retry registration in 37.541739ms if necessary
> I0527 18:39:49.300380 22773 master.cpp:2200] Ignoring register slave message from slave(62)@67.195.138.8:39317 (minerva.apache.org) as admission is already in progress
> I0527 18:39:49.540730 22777 leveldb.cpp:343] Persisting action (352 bytes) to leveldb took 169361ns
> I0527 18:39:49.540743 22777 replica.cpp:676] Persisted action at 3
> I0527 18:39:49.540990 22777 replica.cpp:655] Replica received learned notice for position 3
> I0527 18:39:49.541149 22777 leveldb.cpp:343] Persisting action (354 bytes) to leveldb took 138801ns
> I0527 18:39:49.541162 22777 replica.cpp:676] Persisted action at 3
> I0527 18:39:49.541172 22777 replica.cpp:661] Replica learned APPEND action at position 3
> I0527 18:39:49.541625 22776 registrar.cpp:479] Successfully updated 'registry'
> I0527 18:39:49.541729 22771 log.cpp:699] Attempting to truncate the log to 3
> I0527 18:39:49.541784 22772 master.cpp:2252] Registered slave 20140527-183949-143311683-39317-22750-0 at slave(62)@67.195.138.8:39317 (minerva.apache.org)
> I0527 18:39:49.541805 22772 master.cpp:3382] Adding slave 20140527-183949-143311683-39317-22750-0 at slave(62)@67.195.138.8:39317 (minerva.apache.org) with cpus(*):3; mem(*):1024; disk(*):23038; ports(*):[31000-32000]
> I0527 18:39:49.541823 22777 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
> I0527 18:39:49.541868 22771 slave.cpp:703] Registered with master master@67.195.138.8:39317; given slave ID 20140527-183949-143311683-39317-22750-0
> I0527 18:39:49.542100 22771 hierarchical_allocator_process.hpp:444] Added slave 20140527-183949-143311683-39317-22750-0 (minerva.apache.org) with cpus(*):3; mem(*):1024; disk(*):23038; ports(*):[31000-32000] (and cpus(*):3; mem(*):1024; disk(*):23038; ports(*):[31000-32000] available)
> I0527 18:39:49.542166 22771 hierarchical_allocator_process.hpp:751] Offering cpus(*):3; mem(*):1024; disk(*):23038; ports(*):[31000-32000] on slave 20140527-183949-143311683-39317-22750-0 to framework 20140527-183949-143311683-39317-22750-0000
> I0527 18:39:49.542217 22770 replica.cpp:508] Replica received write request for position 4
> I0527 18:39:49.542307 22771 hierarchical_allocator_process.hpp:707] Performed allocation for slave 20140527-183949-143311683-39317-22750-0 in 170025ns
> I0527 18:39:49.542379 22773 master.hpp:669] Adding offer 20140527-183949-143311683-39317-22750-0 with resources cpus(*):3; mem(*):1024; disk(*):23038; ports(*):[31000-32000] on slave 20140527-183949-143311683-39317-22750-0 (minerva.apache.org)
> I0527 18:39:49.542404 22770 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 167475ns
> I0527 18:39:49.542417 22770 replica.cpp:676] Persisted action at 4
> I0527 18:39:49.542420 22773 master.cpp:2843] Sending 1 offers to framework 20140527-183949-143311683-39317-22750-0000
> I0527 18:39:49.542621 22777 replica.cpp:655] Replica received learned notice for position 4
> I0527 18:39:49.542757 22777 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 118653ns
> I0527 18:39:49.542734 22775 sched.cpp:529] Scheduler::resourceOffers took 174931ns
> I0527 18:39:49.542785 22777 leveldb.cpp:401] Deleting ~2 keys from leveldb took 17584ns
> I0527 18:39:49.542794 22777 replica.cpp:676] Persisted action at 4
> I0527 18:39:49.542801 22777 replica.cpp:661] Replica learned TRUNCATE action at position 4
> I0527 18:39:49.543007 22776 master.hpp:679] Removing offer 20140527-183949-143311683-39317-22750-0 with resources cpus(*):3; mem(*):1024; disk(*):23038; ports(*):[31000-32000] on slave 20140527-183949-143311683-39317-22750-0 (minerva.apache.org)
> I0527 18:39:49.543071 22776 master.cpp:1877] Processing reply for offers: [ 20140527-183949-143311683-39317-22750-0 ] on slave 20140527-183949-143311683-39317-22750-0 at slave(62)@67.195.138.8:39317 (minerva.apache.org) for framework 20140527-183949-143311683-39317-22750-0000
> I0527 18:39:49.543162 22776 master.hpp:641] Adding task 0 with resources cpus(*):1; mem(*):256 on slave 20140527-183949-143311683-39317-22750-0 (minerva.apache.org)
> I0527 18:39:49.543187 22776 master.cpp:3021] Launching task 0 of framework 20140527-183949-143311683-39317-22750-0000 with resources cpus(*):1; mem(*):256 on slave 20140527-183949-143311683-39317-22750-0 at slave(62)@67.195.138.8:39317 (minerva.apache.org)
> I0527 18:39:49.543287 22773 slave.cpp:934] Got assigned task 0 for framework 20140527-183949-143311683-39317-22750-0000
> I0527 18:39:49.543428 22775 hierarchical_allocator_process.hpp:546] Framework 20140527-183949-143311683-39317-22750-0000 left cpus(*):2; mem(*):768; disk(*):23038; ports(*):[31000-32000] unused on slave 20140527-183949-143311683-39317-22750-0
> I0527 18:39:49.543495 22773 slave.cpp:1044] Launching task 0 for framework 20140527-183949-143311683-39317-22750-0000
> I0527 18:39:49.545410 22773 exec.cpp:131] Version: 0.19.0
> I0527 18:39:49.545459 22772 exec.cpp:181] Executor started at: executor(29)@67.195.138.8:39317 with pid 22750
> I0527 18:39:49.545531 22773 slave.cpp:1154] Queuing task '0' for executor default of framework '20140527-183949-143311683-39317-22750-0000
> I0527 18:39:49.545579 22773 slave.cpp:497] Successfully attached file '/tmp/AllocatorTest_0_SchedulerFailover_MYos5v/slaves/20140527-183949-143311683-39317-22750-0/frameworks/20140527-183949-143311683-39317-22750-0000/executors/default/runs/1f93b8fc-f8ef-4d26-ad43-37df885fc912'
> I0527 18:39:49.545601 22773 slave.cpp:1634] Got registration for executor 'default' of framework 20140527-183949-143311683-39317-22750-0000
> I0527 18:39:49.545675 22773 slave.cpp:1753] Flushing queued task 0 for executor 'default' of framework 20140527-183949-143311683-39317-22750-0000
> I0527 18:39:49.545691 22772 exec.cpp:205] Executor registered on slave 20140527-183949-143311683-39317-22750-0
> I0527 18:39:49.545721 22773 slave.cpp:2325] Monitoring executor 'default' of framework '20140527-183949-143311683-39317-22750-0000' in container '1f93b8fc-f8ef-4d26-ad43-37df885fc912'
> I0527 18:39:49.546452 22772 exec.cpp:217] Executor::registered took 10956ns
> I0527 18:39:49.546490 22772 exec.cpp:292] Executor asked to run task '0'
> I0527 18:39:49.546514 22772 exec.cpp:301] Executor::launchTask took 14802ns
> I0527 18:39:49.546789 22776 sched.cpp:725] Stopping framework '20140527-183949-143311683-39317-22750-0000'
> I0527 18:39:49.546938 22776 master.cpp:655] Framework 20140527-183949-143311683-39317-22750-0000 disconnected
> I0527 18:39:49.546951 22776 master.cpp:1298] Deactivating framework 20140527-183949-143311683-39317-22750-0000
> I0527 18:39:49.546977 22776 master.cpp:677] Giving framework 20140527-183949-143311683-39317-22750-0000 100ms to failover
> I0527 18:39:49.547056 22776 hierarchical_allocator_process.hpp:407] Deactivated framework 20140527-183949-143311683-39317-22750-0000
> I0527 18:39:49.548360 22750 sched.cpp:121] Version: 0.19.0
> I0527 18:39:49.548619 22772 sched.cpp:217] New master detected at master@67.195.138.8:39317
> I0527 18:39:49.548635 22772 sched.cpp:268] Authenticating with master master@67.195.138.8:39317
> I0527 18:39:49.548727 22771 authenticatee.hpp:128] Creating new client SASL connection
> I0527 18:39:49.548872 22770 master.cpp:2896] Authenticating scheduler(60)@67.195.138.8:39317
> I0527 18:39:49.548933 22771 authenticator.hpp:156] Creating new server SASL connection
> I0527 18:39:49.549048 22772 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0527 18:39:49.549067 22772 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0527 18:39:49.549106 22772 authenticator.hpp:262] Received SASL authentication start
> I0527 18:39:49.549157 22772 authenticator.hpp:384] Authentication requires more steps
> I0527 18:39:49.549191 22772 authenticatee.hpp:265] Received SASL authentication step
> I0527 18:39:49.549237 22772 authenticator.hpp:290] Received SASL authentication step
> I0527 18:39:49.549254 22772 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'minerva.apache.org' server FQDN: 'minerva.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0527 18:39:49.647959 22773 master.cpp:2759] Framework failover timeout, removing framework 20140527-183949-143311683-39317-22750-0000
> I0527 18:39:49.794754 22772 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0527 18:39:49.794769 22773 master.cpp:3254] Removing framework 20140527-183949-143311683-39317-22750-0000
> I0527 18:39:49.794778 22772 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0527 18:39:49.794790 22772 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'minerva.apache.org' server FQDN: 'minerva.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0527 18:39:49.794800 22772 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0527 18:39:49.794806 22772 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0527 18:39:49.794824 22772 authenticator.hpp:376] Authentication success
> I0527 18:39:49.794836 22774 slave.cpp:1338] Asked to shut down framework 20140527-183949-143311683-39317-22750-0000 by master@67.195.138.8:39317
> I0527 18:39:49.794853 22772 authenticatee.hpp:305] Authentication success
> I0527 18:39:49.794854 22774 slave.cpp:1363] Shutting down framework 20140527-183949-143311683-39317-22750-0000
> I0527 18:39:49.794834 22773 master.hpp:659] Removing task 0 with resources cpus(*):1; mem(*):256 on slave 20140527-183949-143311683-39317-22750-0 (minerva.apache.org)
> I0527 18:39:49.794884 22774 slave.cpp:2668] Shutting down executor 'default' of framework 20140527-183949-143311683-39317-22750-0000
> I0527 18:39:49.794922 22772 sched.cpp:342] Successfully authenticated with master master@67.195.138.8:39317
> I0527 18:39:49.794935 22772 sched.cpp:461] Sending registration request to master@67.195.138.8:39317
> I0527 18:39:49.794952 22770 exec.cpp:378] Executor asked to shutdown
> W0527 18:39:49.794955 22773 master.cpp:3668] Removing task 0 of framework 20140527-183949-143311683-39317-22750-0000 and slave 20140527-183949-143311683-39317-22750-0 in non-terminal state TASK_STAGING
> GMOCK WARNING:
> Uninteresting mock function call - returning directly.
> Function call: shutdown(0x2b6ac80506b0)
> Stack trace:
> I0527 18:39:49.795006 22770 exec.cpp:393] Executor::shutdown took 29189ns
> GMOCK WARNING:
> Uninteresting mock function call - taking default action specified at:
> ../../src/tests/mesos.hpp:504:
> Function call: resourcesRecovered(@0x2b6ac8049fc8 20140527-183949-143311683-39317-22750-0000, @0x2b6ac8049fa8 20140527-183949-143311683-39317-22750-0, @0x2b6ac8049f90 { cpus(*):1, mem(*):256 })
> Stack trace:
> I0527 18:39:49.795085 22773 master.cpp:2936] Successfully authenticated principal 'test-principal' at scheduler(60)@67.195.138.8:39317
> GMOCK WARNING:
> Uninteresting mock function call - taking default action specified at:
> ../../src/tests/mesos.hpp:504:
> Function call: resourcesRecovered(@0x2b6ac805afb8 20140527-183949-143311683-39317-22750-0000, @0x2b6ac805af98 20140527-183949-143311683-39317-22750-0, @0x2b6ac805af80 {})
> IStack trace:
> 0527 18:39:49.795105 22770 hierarchical_allocator_process.hpp:636] Recovered cpus(*):1; mem(*):256 (total allocatable: cpus(*):3; mem(*):1024; disk(*):23038; ports(*):[31000-32000]) on slave 20140527-183949-143311683-39317-22750-0 from framework 20140527-183949-143311683-39317-22750-0000
> GMOCK WARNING:
> Uninteresting mock function call - taking default action specified at:
> ../../src/tests/mesos.hpp:474:
> Function call: frameworkRemoved(@0x2b6ac8042590 20140527-183949-143311683-39317-22750-0000)
> Stack trace:
> I0527 18:39:49.795217 22770 hierarchical_allocator_process.hpp:362] Removed framework 20140527-183949-143311683-39317-22750-0000
> I0527 18:39:49.795228 22773 master.cpp:1121] Re-registering framework 20140527-183949-143311683-39317-22750-0000 at scheduler(60)@67.195.138.8:39317
> I0527 18:39:49.795326 22775 sched.cpp:392] Framework registered with 20140527-183949-143311683-39317-22750-0000
> I0527 18:39:49.795390 22775 sched.cpp:406] Scheduler::registered took 43876ns
> W0527 18:39:49.795428 22773 slave.cpp:1511] Ignoring updating pid for framework 20140527-183949-143311683-39317-22750-0000 because it is terminating
> I0527 18:39:49.795480 22773 hierarchical_allocator_process.hpp:331] Added framework 20140527-183949-143311683-39317-22750-0000
> I0527 18:39:49.795516 22773 hierarchical_allocator_process.hpp:751] Offering cpus(*):3; mem(*):1024; disk(*):23038; ports(*):[31000-32000] on slave 20140527-183949-143311683-39317-22750-0 to framework 20140527-183949-143311683-39317-22750-0000
> ../../src/tests/allocator_tests.cpp:985: Failure
> Mock function called more times than expected - taking default action specified at:
> ../../src/tests/mesos.hpp:471:
> Function call: frameworkAdded(@0x2b6ac8049fd0 20140527-183949-143311683-39317-22750-0000, @0x2b6ac8049f78 88-byte object <50-FA 30-B9 6A-2B 00-00 00-00 00-00 00-00 00-00 C0-F2 04-C8 6A-2B 00-00 00-F3 04-C8 6A-2B 00-00 20-F3 04-C8 6A-2B 00-00 00-00 00-00 00-00 00-00 F0-27 AD-01 00-00 00-00 70-F2 04-C8 6A-2B 00-00 50-F2 04-C8 6A-2B 00-00 00-6E 28-29 00-00 00-00 C7-00 00-00 65-64 20-2D>, @0x2b6ac8049f60 {})
> Expected: to be called once
> Actual: called twice - over-saturated and active
> I0527 18:39:49.795651 22773 hierarchical_allocator_process.hpp:687] Performed allocation for 1 slaves in 160958ns
> I0527 18:39:49.795694 22772 master.hpp:669] Adding offer 20140527-183949-143311683-39317-22750-1 with resources cpus(*):3; mem(*):1024; disk(*):23038; ports(*):[31000-32000] on slave 20140527-183949-143311683-39317-22750-0 (minerva.apache.org)
> I0527 18:39:49.795737 22772 master.cpp:2843] Sending 1 offers to framework 20140527-183949-143311683-39317-22750-0000
> unknown file: Failure
> Unexpected mock function call - returning directly.
> Function call: resourceOffers(0x7fffd0fff860, @0x2b6abb7b1c70 { 128-byte object <50-09 31-B9 6A-2B 00-00 00-00 00-00 00-00 00-00 E0-B4 03-D8 6A-2B 00-00 80-B5 03-D8 6A-2B 00-00 20-B6 03-D8 6A-2B 00-00 10-74 04-D8 6A-2B 00-00 E0-5B 04-D8 6A-2B 00-00 04-00 00-00 04-00 00-00 04-00 00-00 2D-31 12-2C 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 33-33 31-31 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 1A-29 0A-27 00-00 00-00 0F-00 00-00> })
> Google Mock tried the following 1 expectation, but it didn't match:
> ../../src/tests/allocator_tests.cpp:1053: EXPECT_CALL(sched2, resourceOffers(_, OfferEq(2, 768)))...
> Expected arg #1: contains 2 cpus and 768 mem
> Actual: { 128-byte object <50-09 31-B9 6A-2B 00-00 00-00 00-00 00-00 00-00 E0-B4 03-D8 6A-2B 00-00 80-B5 03-D8 6A-2B 00-00 20-B6 03-D8 6A-2B 00-00 10-74 04-D8 6A-2B 00-00 E0-5B 04-D8 6A-2B 00-00 04-00 00-00 04-00 00-00 04-00 00-00 2D-31 12-2C 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 33-33 31-31 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 1A-29 0A-27 00-00 00-00 0F-00 00-00> }, 3 cpus and 1024mem
> Expected: to be called once
> Actual: never called - unsatisfied and active
> I0527 18:39:49.796044 22772 sched.cpp:529] Scheduler::resourceOffers took 226830ns
> I0527 18:39:50.037924 22776 hierarchical_allocator_process.hpp:687] Performed allocation for 1 slaves in 25463ns
> I0527 18:39:51.038499 22774 hierarchical_allocator_process.hpp:687] Performed allocation for 1 slaves in 13007ns
> I0527 18:39:52.038606 22772 hierarchical_allocator_process.hpp:687] Performed allocation for 1 slaves in 20094ns
> I0527 18:39:53.039710 22773 hierarchical_allocator_process.hpp:687] Performed allocation for 1 slaves in 13711ns
> I0527 18:39:54.037348 22771 master.cpp:108] No whitelist given. Advertising offers for all slaves
> I0527 18:39:54.040472 22775 hierarchical_allocator_process.hpp:687] Performed allocation for 1 slaves in 14624ns
> I0527 18:39:54.795531 22774 slave.cpp:2738] Killing executor 'default' of framework 20140527-183949-143311683-39317-22750-0000
> I0527 18:39:54.795672 22774 slave.cpp:2383] Executor 'default' of framework 20140527-183949-143311683-39317-22750-0000 has exited with status 0
> I0527 18:39:54.795761 22774 slave.cpp:2522] Cleaning up executor 'default' of framework 20140527-183949-143311683-39317-22750-0000
> W0527 18:39:54.795871 22770 master.cpp:2628] Ignoring unknown exited executor default on slave 20140527-183949-143311683-39317-22750-0 at slave(62)@67.195.138.8:39317 (minerva.apache.org)
> I0527 18:39:54.796061 22774 slave.cpp:2597] Cleaning up framework 20140527-183949-143311683-39317-22750-0000
> I0527 18:39:54.796068 22771 gc.cpp:56] Scheduling '/tmp/AllocatorTest_0_SchedulerFailover_MYos5v/slaves/20140527-183949-143311683-39317-22750-0/frameworks/20140527-183949-143311683-39317-22750-0000/executors/default/runs/1f93b8fc-f8ef-4d26-ad43-37df885fc912' for gc 6.99999078708444days in the future
> I0527 18:39:54.796128 22776 status_update_manager.cpp:282] Closing status update streams for framework 20140527-183949-143311683-39317-22750-0000
> I0527 18:39:54.796171 22771 gc.cpp:56] Scheduling '/tmp/AllocatorTest_0_SchedulerFailover_MYos5v/slaves/20140527-183949-143311683-39317-22750-0/frameworks/20140527-183949-143311683-39317-22750-0000/executors/default' for gc 6.9999907865037days in the future
> I0527 18:39:54.796210 22771 gc.cpp:56] Scheduling '/tmp/AllocatorTest_0_SchedulerFailover_MYos5v/slaves/20140527-183949-143311683-39317-22750-0/frameworks/20140527-183949-143311683-39317-22750-0000' for gc 6.99999078577481days in the future
> I0527 18:39:55.041219 22776 hierarchical_allocator_process.hpp:687] Performed allocation for 1 slaves in 28557ns
> I0527 18:39:56.041731 22777 hierarchical_allocator_process.hpp:687] Performed allocation for 1 slaves in 10760ns
> I0527 18:39:57.042177 22772 hierarchical_allocator_process.hpp:687] Performed allocation for 1 slaves in 9990ns
> I0527 18:39:58.042736 22771 hierarchical_allocator_process.hpp:687] Performed allocation for 1 slaves in 9554ns
> I0527 18:39:59.038238 22775 master.cpp:108] No whitelist given. Advertising offers for all slaves
> I0527 18:39:59.043576 22773 hierarchical_allocator_process.hpp:687] Performed allocation for 1 slaves in 47160ns
> ../../src/tests/allocator_tests.cpp:1058: Failure
> Failed to wait 10secs for resourceOffers
> I0527 18:40:00.043962 22775 hierarchical_allocator_process.hpp:687] Performed allocation for 1 slaves in 14603ns
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.2#6252)