[
https://issues.apache.org/jira/browse/MESOS-1544?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Chris Lambert updated MESOS-1544:
---------------------------------
Sprint: Q2 Sprint 5
> DRFAllocatorTest.SameShareAllocations is flaky
> ----------------------------------------------
>
> Key: MESOS-1544
> URL: https://issues.apache.org/jira/browse/MESOS-1544
> Project: Mesos
> Issue Type: Bug
> Components: test
> Reporter: Vinod Kone
> Assignee: Vinod Kone
>
> {code}
> [ RUN ] DRFAllocatorTest.SameShareAllocations
> Using temporary directory '/tmp/DRFAllocatorTest_SameShareAllocations_hJgCKZ'
> I0625 16:24:17.865212 12904 leveldb.cpp:176] Opened db in 604.788644ms
> I0625 16:24:17.889785 12904 leveldb.cpp:183] Compacted db in 24.281295ms
> I0625 16:24:17.889852 12904 leveldb.cpp:198] Created db iterator in 18622ns
> I0625 16:24:17.889866 12904 leveldb.cpp:204] Seeked to beginning of db in
> 1331ns
> I0625 16:24:17.889878 12904 leveldb.cpp:273] Iterated through 0 keys in the
> db in 4855ns
> I0625 16:24:17.890364 12904 replica.cpp:741] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0625 16:24:17.892340 12929 recover.cpp:425] Starting replica recovery
> I0625 16:24:17.892524 12929 recover.cpp:451] Replica is in EMPTY status
> I0625 16:24:17.899214 12927 replica.cpp:638] Replica in EMPTY status received
> a broadcasted recover request
> I0625 16:24:17.899900 12929 recover.cpp:188] Received a recover response from
> a replica in EMPTY status
> I0625 16:24:17.903823 12930 recover.cpp:542] Updating replica status to
> STARTING
> I0625 16:24:17.923876 12931 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 19.564257ms
> I0625 16:24:17.923964 12931 replica.cpp:320] Persisted replica status to
> STARTING
> I0625 16:24:17.924154 12931 recover.cpp:451] Replica is in STARTING status
> I0625 16:24:17.924650 12931 replica.cpp:638] Replica in STARTING status
> received a broadcasted recover request
> I0625 16:24:17.924721 12931 recover.cpp:188] Received a recover response from
> a replica in STARTING status
> I0625 16:24:17.924851 12931 recover.cpp:542] Updating replica status to VOTING
> I0625 16:24:17.940956 12932 master.cpp:288] Master
> 20140625-162417-16842879-50101-12904 (quantal) started on 127.0.1.1:50101
> I0625 16:24:17.941375 12932 master.cpp:325] Master only allowing
> authenticated frameworks to register
> I0625 16:24:17.941391 12932 master.cpp:330] Master only allowing
> authenticated slaves to register
> I0625 16:24:17.941408 12932 credentials.hpp:35] Loading credentials for
> authentication from
> '/tmp/DRFAllocatorTest_SameShareAllocations_hJgCKZ/credentials'
> I0625 16:24:17.942016 12932 master.cpp:356] Authorization enabled
> I0625 16:24:17.942925 12934 master.cpp:122] No whitelist given. Advertising
> offers for all slaves
> I0625 16:24:17.943099 12934 hierarchical_allocator_process.hpp:301]
> Initializing hierarchical allocator process with master :
> master@127.0.1.1:50101
> I0625 16:24:17.946311 12932 master.cpp:1122] The newly elected leader is
> master@127.0.1.1:50101 with id 20140625-162417-16842879-50101-12904
> I0625 16:24:17.946521 12932 master.cpp:1135] Elected as the leading master!
> I0625 16:24:17.946831 12932 master.cpp:953] Recovering from registrar
> I0625 16:24:17.947140 12927 registrar.cpp:313] Recovering registrar
> I0625 16:24:17.951028 12931 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 26.114928ms
> I0625 16:24:17.951069 12931 replica.cpp:320] Persisted replica status to
> VOTING
> I0625 16:24:17.951144 12931 recover.cpp:556] Successfully joined the Paxos
> group
> I0625 16:24:17.951243 12931 recover.cpp:440] Recover process terminated
> I0625 16:24:17.951968 12931 log.cpp:656] Attempting to start the writer
> I0625 16:24:17.953315 12931 replica.cpp:474] Replica received implicit
> promise request with proposal 1
> I0625 16:24:17.973825 12931 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 20.330361ms
> I0625 16:24:17.974225 12931 replica.cpp:342] Persisted promised to 1
> I0625 16:24:17.981044 12927 coordinator.cpp:230] Coordinator attemping to
> fill missing position
> I0625 16:24:17.981698 12927 replica.cpp:375] Replica received explicit
> promise request for position 0 with proposal 2
> I0625 16:24:18.000988 12927 leveldb.cpp:343] Persisting action (8 bytes) to
> leveldb took 19.241964ms
> I0625 16:24:18.001565 12927 replica.cpp:676] Persisted action at 0
> I0625 16:24:18.005229 12931 replica.cpp:508] Replica received write request
> for position 0
> I0625 16:24:18.005295 12931 leveldb.cpp:438] Reading position from leveldb
> took 35688ns
> I0625 16:24:18.026463 12931 leveldb.cpp:343] Persisting action (14 bytes) to
> leveldb took 21.113787ms
> I0625 16:24:18.026532 12931 replica.cpp:676] Persisted action at 0
> I0625 16:24:18.026876 12931 replica.cpp:655] Replica received learned notice
> for position 0
> I0625 16:24:18.049996 12931 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 23.092481ms
> I0625 16:24:18.050042 12931 replica.cpp:676] Persisted action at 0
> I0625 16:24:18.050053 12931 replica.cpp:661] Replica learned NOP action at
> position 0
> I0625 16:24:18.052983 12928 log.cpp:672] Writer started with ending position 0
> I0625 16:24:18.053586 12928 leveldb.cpp:438] Reading position from leveldb
> took 26100ns
> I0625 16:24:18.054738 12928 registrar.cpp:346] Successfully fetched the
> registry (0B)
> I0625 16:24:18.054791 12928 registrar.cpp:422] Attempting to update the
> 'registry'
> I0625 16:24:18.064213 12932 log.cpp:680] Attempting to append 120 bytes to
> the log
> I0625 16:24:18.064332 12932 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 1
> I0625 16:24:18.064702 12932 replica.cpp:508] Replica received write request
> for position 1
> I0625 16:24:18.090069 12932 leveldb.cpp:343] Persisting action (137 bytes) to
> leveldb took 25.329614ms
> I0625 16:24:18.090127 12932 replica.cpp:676] Persisted action at 1
> I0625 16:24:18.090502 12932 replica.cpp:655] Replica received learned notice
> for position 1
> I0625 16:24:18.117938 12932 leveldb.cpp:343] Persisting action (139 bytes) to
> leveldb took 27407us
> I0625 16:24:18.118129 12932 replica.cpp:676] Persisted action at 1
> I0625 16:24:18.118147 12932 replica.cpp:661] Replica learned APPEND action at
> position 1
> I0625 16:24:18.119317 12932 registrar.cpp:479] Successfully updated 'registry'
> I0625 16:24:18.119518 12927 log.cpp:699] Attempting to truncate the log to 1
> I0625 16:24:18.119658 12927 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 2
> I0625 16:24:18.120282 12927 replica.cpp:508] Replica received write request
> for position 2
> I0625 16:24:18.120779 12932 registrar.cpp:372] Successfully recovered
> registrar
> I0625 16:24:18.121140 12932 master.cpp:980] Recovered 0 slaves from the
> Registry (84B) ; allowing 10mins for slaves to re-register
> I0625 16:24:18.123618 12904 sched.cpp:139] Version: 0.20.0
> I0625 16:24:18.124135 12929 sched.cpp:235] New master detected at
> master@127.0.1.1:50101
> I0625 16:24:18.124166 12929 sched.cpp:285] Authenticating with master
> master@127.0.1.1:50101
> I0625 16:24:18.124366 12929 authenticatee.hpp:104] Initializing client SASL
> I0625 16:24:18.143491 12927 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 23.158721ms
> I0625 16:24:18.143586 12927 replica.cpp:676] Persisted action at 2
> I0625 16:24:18.144127 12927 replica.cpp:655] Replica received learned notice
> for position 2
> I0625 16:24:18.170171 12927 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 26.0011ms
> I0625 16:24:18.170656 12927 leveldb.cpp:401] Deleting ~1 keys from leveldb
> took 57188ns
> I0625 16:24:18.170936 12927 replica.cpp:676] Persisted action at 2
> I0625 16:24:18.171087 12927 replica.cpp:661] Replica learned TRUNCATE action
> at position 2
> I0625 16:24:18.287214 12929 authenticatee.hpp:128] Creating new client SASL
> connection
> I0625 16:24:18.288033 12930 master.cpp:3499] Authenticating
> scheduler-711339df-ad84-4098-b7e1-d3d8711d17df@127.0.1.1:50101
> I0625 16:24:18.288331 12930 authenticator.hpp:94] Initializing server SASL
> I0625 16:24:18.288545 12930 auxprop.cpp:45] Initialized in-memory auxiliary
> property plugin
> I0625 16:24:18.288558 12930 authenticator.hpp:156] Creating new server SASL
> connection
> I0625 16:24:18.288981 12929 authenticatee.hpp:219] Received SASL
> authentication mechanisms: CRAM-MD5
> I0625 16:24:18.289227 12929 authenticatee.hpp:245] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0625 16:24:18.289685 12931 authenticator.hpp:262] Received SASL
> authentication start
> I0625 16:24:18.289742 12931 authenticator.hpp:384] Authentication requires
> more steps
> I0625 16:24:18.290017 12929 authenticatee.hpp:265] Received SASL
> authentication step
> I0625 16:24:18.290459 12928 authenticator.hpp:290] Received SASL
> authentication step
> I0625 16:24:18.290506 12928 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'quantal' server FQDN: 'quantal'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0625 16:24:18.290519 12928 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I0625 16:24:18.290545 12928 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0625 16:24:18.290573 12928 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'quantal' server FQDN: 'quantal'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0625 16:24:18.290591 12928 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0625 16:24:18.290602 12928 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0625 16:24:18.290624 12928 authenticator.hpp:376] Authentication success
> I0625 16:24:18.290711 12928 master.cpp:3539] Successfully authenticated
> principal 'test-principal' at
> scheduler-711339df-ad84-4098-b7e1-d3d8711d17df@127.0.1.1:50101
> I0625 16:24:18.296689 12929 authenticatee.hpp:305] Authentication success
> I0625 16:24:18.297116 12929 sched.cpp:359] Successfully authenticated with
> master master@127.0.1.1:50101
> I0625 16:24:18.297144 12929 sched.cpp:478] Sending registration request to
> master@127.0.1.1:50101
> I0625 16:24:18.307180 12928 master.cpp:1241] Received registration request
> from scheduler-711339df-ad84-4098-b7e1-d3d8711d17df@127.0.1.1:50101
> I0625 16:24:18.307859 12928 master.cpp:1201] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0625 16:24:18.308819 12928 master.cpp:1300] Registering framework
> 20140625-162417-16842879-50101-12904-0000 at
> scheduler-711339df-ad84-4098-b7e1-d3d8711d17df@127.0.1.1:50101
> I0625 16:24:18.309273 12933 sched.cpp:409] Framework registered with
> 20140625-162417-16842879-50101-12904-0000
> I0625 16:24:18.309351 12933 sched.cpp:423] Scheduler::registered took 46449ns
> I0625 16:24:18.311997 12904 sched.cpp:139] Version: 0.20.0
> I0625 16:24:18.312474 12929 sched.cpp:235] New master detected at
> master@127.0.1.1:50101
> I0625 16:24:18.312501 12929 sched.cpp:285] Authenticating with master
> master@127.0.1.1:50101
> I0625 16:24:18.312813 12929 authenticatee.hpp:128] Creating new client SASL
> connection
> I0625 16:24:18.313573 12927 hierarchical_allocator_process.hpp:331] Added
> framework 20140625-162417-16842879-50101-12904-0000
> I0625 16:24:18.313597 12927 hierarchical_allocator_process.hpp:724] No
> resources available to allocate!
> I0625 16:24:18.313606 12927 hierarchical_allocator_process.hpp:686] Performed
> allocation for 0 slaves in 13611ns
> I0625 16:24:18.314156 12928 master.cpp:3499] Authenticating
> scheduler-cf6c09b8-b207-4318-803c-4b2aec674884@127.0.1.1:50101
> I0625 16:24:18.314519 12932 authenticator.hpp:156] Creating new server SASL
> connection
> I0625 16:24:18.314666 12932 authenticatee.hpp:219] Received SASL
> authentication mechanisms: CRAM-MD5
> I0625 16:24:18.314687 12932 authenticatee.hpp:245] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0625 16:24:18.314713 12932 authenticator.hpp:262] Received SASL
> authentication start
> I0625 16:24:18.314749 12932 authenticator.hpp:384] Authentication requires
> more steps
> I0625 16:24:18.314776 12932 authenticatee.hpp:265] Received SASL
> authentication step
> I0625 16:24:18.314812 12932 authenticator.hpp:290] Received SASL
> authentication step
> I0625 16:24:18.314828 12932 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'quantal' server FQDN: 'quantal'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0625 16:24:18.314836 12932 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I0625 16:24:18.314847 12932 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0625 16:24:18.314857 12932 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'quantal' server FQDN: 'quantal'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0625 16:24:18.314862 12932 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0625 16:24:18.314867 12932 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0625 16:24:18.314877 12932 authenticator.hpp:376] Authentication success
> I0625 16:24:18.314896 12932 authenticatee.hpp:305] Authentication success
> I0625 16:24:18.315359 12932 sched.cpp:359] Successfully authenticated with
> master master@127.0.1.1:50101
> I0625 16:24:18.315397 12932 sched.cpp:478] Sending registration request to
> master@127.0.1.1:50101
> I0625 16:24:18.315868 12928 master.cpp:1233] Queuing up registration request
> from scheduler-cf6c09b8-b207-4318-803c-4b2aec674884@127.0.1.1:50101 because
> authentication is still in progress
> I0625 16:24:18.316097 12928 master.cpp:3539] Successfully authenticated
> principal 'test-principal' at
> scheduler-cf6c09b8-b207-4318-803c-4b2aec674884@127.0.1.1:50101
> I0625 16:24:18.320166 12928 master.cpp:1241] Received registration request
> from scheduler-cf6c09b8-b207-4318-803c-4b2aec674884@127.0.1.1:50101
> I0625 16:24:18.320857 12928 master.cpp:1201] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0625 16:24:18.321282 12928 master.cpp:1300] Registering framework
> 20140625-162417-16842879-50101-12904-0001 at
> scheduler-cf6c09b8-b207-4318-803c-4b2aec674884@127.0.1.1:50101
> I0625 16:24:18.321611 12933 sched.cpp:409] Framework registered with
> 20140625-162417-16842879-50101-12904-0001
> I0625 16:24:18.321655 12933 sched.cpp:423] Scheduler::registered took 22254ns
> tests/allocator_tests.cpp:371: Failure
> Mock function called more times than expected - taking default action
> specified at:
> ./tests/mesos.hpp:533:
> Function call: frameworkAdded(@0x2b5ce4003580
> 20140625-162417-16842879-50101-12904-0001, @0x2b5ce4003528 88-byte object
> <F0-FA FD-C0 5C-2B 00-00 00-00 00-00 00-00 00-00 B0-16 00-E4 5C-2B 00-00
> 90-16 00-E4 5C-2B 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 60-EA
> 71-02 00-00 00-00 60-1A 00-E4 5C-2B 00-00 00-8F 00-E4 5C-2B 00-00 00-F9 87-00
> 00-00 00-00 C3-00 00-00 00-00 00-00>, @0x2b5ce4003510 {})
> Expected: to be called once
> Actual: called twice - over-saturated and active
> I0625 16:24:18.322687 12930 hierarchical_allocator_process.hpp:331] Added
> framework 20140625-162417-16842879-50101-12904-0001
> I0625 16:24:18.322721 12930 hierarchical_allocator_process.hpp:724] No
> resources available to allocate!
> I0625 16:24:18.322731 12930 hierarchical_allocator_process.hpp:686] Performed
> allocation for 0 slaves in 13954ns
> I0625 16:24:18.342305 12904 containerizer.cpp:121] Using isolation:
> posix/cpu,posix/mem
> I0625 16:24:18.353575 12931 slave.cpp:168] Slave started on 1)@127.0.1.1:50101
> I0625 16:24:18.353618 12931 credentials.hpp:35] Loading credentials for
> authentication from
> '/tmp/DRFAllocatorTest_SameShareAllocations_PUQEbB/credential'
> I0625 16:24:18.353752 12931 slave.cpp:268] Slave using credential for:
> test-principal
> I0625 16:24:18.354610 12931 slave.cpp:281] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0625 16:24:18.354714 12931 slave.cpp:309] Slave hostname: quantal
> I0625 16:24:18.354727 12931 slave.cpp:310] Slave checkpoint: false
> I0625 16:24:18.355571 12929 state.cpp:33] Recovering state from
> '/tmp/DRFAllocatorTest_SameShareAllocations_PUQEbB/meta'
> I0625 16:24:18.356279 12931 status_update_manager.cpp:193] Recovering status
> update manager
> I0625 16:24:18.357023 12931 containerizer.cpp:279] Recovering containerizer
> I0625 16:24:18.358409 12928 slave.cpp:3111] Finished recovery
> I0625 16:24:18.359455 12928 slave.cpp:584] New master detected at
> master@127.0.1.1:50101
> I0625 16:24:18.359845 12930 status_update_manager.cpp:167] New master
> detected at master@127.0.1.1:50101
> I0625 16:24:18.360085 12928 slave.cpp:660] Authenticating with master
> master@127.0.1.1:50101
> I0625 16:24:18.360409 12928 slave.cpp:633] Detecting new master
> I0625 16:24:18.360713 12927 authenticatee.hpp:128] Creating new client SASL
> connection
> I0625 16:24:18.361093 12929 master.cpp:3499] Authenticating
> slave(1)@127.0.1.1:50101
> I0625 16:24:18.361327 12929 authenticator.hpp:156] Creating new server SASL
> connection
> I0625 16:24:18.361456 12929 authenticatee.hpp:219] Received SASL
> authentication mechanisms: CRAM-MD5
> I0625 16:24:18.361477 12929 authenticatee.hpp:245] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0625 16:24:18.361505 12929 authenticator.hpp:262] Received SASL
> authentication start
> I0625 16:24:18.361558 12929 authenticator.hpp:384] Authentication requires
> more steps
> I0625 16:24:18.361588 12929 authenticatee.hpp:265] Received SASL
> authentication step
> I0625 16:24:18.361624 12929 authenticator.hpp:290] Received SASL
> authentication step
> I0625 16:24:18.361641 12929 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'quantal' server FQDN: 'quantal'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0625 16:24:18.361649 12929 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I0625 16:24:18.361691 12929 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0625 16:24:18.361704 12929 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'quantal' server FQDN: 'quantal'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0625 16:24:18.361711 12929 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0625 16:24:18.361714 12929 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0625 16:24:18.361726 12929 authenticator.hpp:376] Authentication success
> I0625 16:24:18.361757 12929 authenticatee.hpp:305] Authentication success
> I0625 16:24:18.361783 12929 master.cpp:3539] Successfully authenticated
> principal 'test-principal' at slave(1)@127.0.1.1:50101
> I0625 16:24:18.362637 12928 slave.cpp:717] Successfully authenticated with
> master master@127.0.1.1:50101
> I0625 16:24:18.363659 12929 master.cpp:2781] Registering slave at
> slave(1)@127.0.1.1:50101 (quantal) with id
> 20140625-162417-16842879-50101-12904-0
> I0625 16:24:18.364234 12929 registrar.cpp:422] Attempting to update the
> 'registry'
> I0625 16:24:18.365439 12929 log.cpp:680] Attempting to append 295 bytes to
> the log
> I0625 16:24:18.365524 12929 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 3
> I0625 16:24:18.365939 12929 replica.cpp:508] Replica received write request
> for position 3
> I0625 16:24:18.366421 12928 slave.cpp:955] Will retry registration in
> 13.288761ms if necessary
> I0625 16:24:18.366945 12927 slave.cpp:955] Will retry registration in
> 24.888463ms if necessary
> I0625 16:24:18.366994 12927 hierarchical_allocator_process.hpp:724] No
> resources available to allocate!
> I0625 16:24:18.367004 12927 hierarchical_allocator_process.hpp:686] Performed
> allocation for 0 slaves in 12563ns
> I0625 16:24:18.367071 12927 master.cpp:2769] Ignoring register slave message
> from slave(1)@127.0.1.1:50101 (quantal) as admission is already in progress
> I0625 16:24:18.398139 12929 leveldb.cpp:343] Persisting action (314 bytes) to
> leveldb took 32.156215ms
> I0625 16:24:18.398686 12929 replica.cpp:676] Persisted action at 3
> I0625 16:24:18.404999 12933 replica.cpp:655] Replica received learned notice
> for position 3
> I0625 16:24:18.425781 12933 leveldb.cpp:343] Persisting action (316 bytes) to
> leveldb took 20.731721ms
> I0625 16:24:18.425849 12933 replica.cpp:676] Persisted action at 3
> I0625 16:24:18.425863 12933 replica.cpp:661] Replica learned APPEND action at
> position 3
> I0625 16:24:18.426399 12933 registrar.cpp:479] Successfully updated 'registry'
> I0625 16:24:18.426533 12933 log.cpp:699] Attempting to truncate the log to 3
> I0625 16:24:18.426640 12933 master.cpp:2821] Registered slave
> 20140625-162417-16842879-50101-12904-0 at slave(1)@127.0.1.1:50101 (quantal)
> I0625 16:24:18.426667 12933 master.cpp:3967] Adding slave
> 20140625-162417-16842879-50101-12904-0 at slave(1)@127.0.1.1:50101 (quantal)
> with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0625 16:24:18.426878 12933 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 4
> I0625 16:24:18.427006 12933 slave.cpp:751] Registered with master
> master@127.0.1.1:50101; given slave ID 20140625-162417-16842879-50101-12904-0
> I0625 16:24:18.427170 12933 slave.cpp:2308] Received ping from
> slave-observer(1)@127.0.1.1:50101
> I0625 16:24:18.427245 12933 hierarchical_allocator_process.hpp:444] Added
> slave 20140625-162417-16842879-50101-12904-0 (quantal) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I0625 16:24:18.427333 12933 hierarchical_allocator_process.hpp:750] Offering
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 to framework
> 20140625-162417-16842879-50101-12904-0000
> I0625 16:24:18.427441 12933 hierarchical_allocator_process.hpp:706] Performed
> allocation for slave 20140625-162417-16842879-50101-12904-0 in 153535ns
> I0625 16:24:18.427603 12933 master.hpp:794] Adding offer
> 20140625-162417-16842879-50101-12904-0 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 (quantal)
> I0625 16:24:18.427654 12933 master.cpp:3446] Sending 1 offers to framework
> 20140625-162417-16842879-50101-12904-0000
> I0625 16:24:18.427999 12933 sched.cpp:546] Scheduler::resourceOffers took
> 73203ns
> I0625 16:24:18.428915 12928 master.hpp:804] Removing offer
> 20140625-162417-16842879-50101-12904-0 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 (quantal)
> I0625 16:24:18.428980 12928 master.cpp:2125] Processing reply for offers: [
> 20140625-162417-16842879-50101-12904-0 ] on slave
> 20140625-162417-16842879-50101-12904-0 at slave(1)@127.0.1.1:50101 (quantal)
> for framework 20140625-162417-16842879-50101-12904-0000
> I0625 16:24:18.429287 12928 hierarchical_allocator_process.hpp:546] Framework
> 20140625-162417-16842879-50101-12904-0000 left cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] unused on slave
> 20140625-162417-16842879-50101-12904-0
> I0625 16:24:18.429646 12931 replica.cpp:508] Replica received write request
> for position 4
> I0625 16:24:18.454139 12931 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 24.454768ms
> I0625 16:24:18.454219 12931 replica.cpp:676] Persisted action at 4
> I0625 16:24:18.454771 12931 replica.cpp:655] Replica received learned notice
> for position 4
> I0625 16:24:18.478823 12931 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 24.015352ms
> I0625 16:24:18.478920 12931 leveldb.cpp:401] Deleting ~2 keys from leveldb
> took 44593ns
> I0625 16:24:18.478936 12931 replica.cpp:676] Persisted action at 4
> I0625 16:24:18.478947 12931 replica.cpp:661] Replica learned TRUNCATE action
> at position 4
> I0625 16:24:18.489650 12931 hierarchical_allocator_process.hpp:750] Offering
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 to framework
> 20140625-162417-16842879-50101-12904-0001
> I0625 16:24:18.489778 12931 hierarchical_allocator_process.hpp:686] Performed
> allocation for 1 slaves in 192769ns
> I0625 16:24:18.490000 12928 master.hpp:794] Adding offer
> 20140625-162417-16842879-50101-12904-1 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 (quantal)
> I0625 16:24:18.490365 12928 master.cpp:3446] Sending 1 offers to framework
> 20140625-162417-16842879-50101-12904-0001
> I0625 16:24:18.490923 12928 sched.cpp:546] Scheduler::resourceOffers took
> 59226ns
> I0625 16:24:18.491128 12928 master.hpp:804] Removing offer
> 20140625-162417-16842879-50101-12904-1 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 (quantal)
> I0625 16:24:18.491214 12928 master.cpp:2125] Processing reply for offers: [
> 20140625-162417-16842879-50101-12904-1 ] on slave
> 20140625-162417-16842879-50101-12904-0 at slave(1)@127.0.1.1:50101 (quantal)
> for framework 20140625-162417-16842879-50101-12904-0001
> I0625 16:24:18.491756 12931 hierarchical_allocator_process.hpp:546] Framework
> 20140625-162417-16842879-50101-12904-0001 left cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] unused on slave
> 20140625-162417-16842879-50101-12904-0
> I0625 16:24:18.499745 12930 hierarchical_allocator_process.hpp:750] Offering
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 to framework
> 20140625-162417-16842879-50101-12904-0000
> I0625 16:24:18.499879 12930 hierarchical_allocator_process.hpp:686] Performed
> allocation for 1 slaves in 180807ns
> I0625 16:24:18.499955 12930 master.hpp:794] Adding offer
> 20140625-162417-16842879-50101-12904-2 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 (quantal)
> I0625 16:24:18.499999 12930 master.cpp:3446] Sending 1 offers to framework
> 20140625-162417-16842879-50101-12904-0000
> I0625 16:24:18.500147 12930 sched.cpp:546] Scheduler::resourceOffers took
> 35332ns
> I0625 16:24:18.500262 12930 master.hpp:804] Removing offer
> 20140625-162417-16842879-50101-12904-2 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 (quantal)
> I0625 16:24:18.500309 12930 master.cpp:2125] Processing reply for offers: [
> 20140625-162417-16842879-50101-12904-2 ] on slave
> 20140625-162417-16842879-50101-12904-0 at slave(1)@127.0.1.1:50101 (quantal)
> for framework 20140625-162417-16842879-50101-12904-0000
> I0625 16:24:18.500497 12930 hierarchical_allocator_process.hpp:546] Framework
> 20140625-162417-16842879-50101-12904-0000 left cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] unused on slave
> 20140625-162417-16842879-50101-12904-0
> I0625 16:24:18.509912 12930 hierarchical_allocator_process.hpp:750] Offering
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 to framework
> 20140625-162417-16842879-50101-12904-0001
> I0625 16:24:18.510037 12930 hierarchical_allocator_process.hpp:686] Performed
> allocation for 1 slaves in 169758ns
> I0625 16:24:18.510110 12930 master.hpp:794] Adding offer
> 20140625-162417-16842879-50101-12904-3 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 (quantal)
> I0625 16:24:18.510165 12930 master.cpp:3446] Sending 1 offers to framework
> 20140625-162417-16842879-50101-12904-0001
> I0625 16:24:18.510316 12930 sched.cpp:546] Scheduler::resourceOffers took
> 34792ns
> I0625 16:24:18.510447 12930 master.hpp:804] Removing offer
> 20140625-162417-16842879-50101-12904-3 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 (quantal)
> I0625 16:24:18.510496 12930 master.cpp:2125] Processing reply for offers: [
> 20140625-162417-16842879-50101-12904-3 ] on slave
> 20140625-162417-16842879-50101-12904-0 at slave(1)@127.0.1.1:50101 (quantal)
> for framework 20140625-162417-16842879-50101-12904-0001
> I0625 16:24:18.510660 12930 hierarchical_allocator_process.hpp:546] Framework
> 20140625-162417-16842879-50101-12904-0001 left cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] unused on slave
> 20140625-162417-16842879-50101-12904-0
> I0625 16:24:18.520110 12927 master.cpp:122] No whitelist given. Advertising
> offers for all slaves
> I0625 16:24:18.520328 12927 hierarchical_allocator_process.hpp:750] Offering
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 to framework
> 20140625-162417-16842879-50101-12904-0000
> I0625 16:24:18.520501 12927 hierarchical_allocator_process.hpp:686] Performed
> allocation for 1 slaves in 225130ns
> I0625 16:24:18.520645 12927 master.hpp:794] Adding offer
> 20140625-162417-16842879-50101-12904-4 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 (quantal)
> I0625 16:24:18.520716 12927 master.cpp:3446] Sending 1 offers to framework
> 20140625-162417-16842879-50101-12904-0000
> I0625 16:24:18.520877 12927 sched.cpp:546] Scheduler::resourceOffers took
> 33507ns
> I0625 16:24:18.521040 12927 master.hpp:804] Removing offer
> 20140625-162417-16842879-50101-12904-4 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 (quantal)
> I0625 16:24:18.521121 12927 master.cpp:2125] Processing reply for offers: [
> 20140625-162417-16842879-50101-12904-4 ] on slave
> 20140625-162417-16842879-50101-12904-0 at slave(1)@127.0.1.1:50101 (quantal)
> for framework 20140625-162417-16842879-50101-12904-0000
> I0625 16:24:18.521340 12927 hierarchical_allocator_process.hpp:546] Framework
> 20140625-162417-16842879-50101-12904-0000 left cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] unused on slave
> 20140625-162417-16842879-50101-12904-0
> I0625 16:24:18.530293 12927 hierarchical_allocator_process.hpp:750] Offering
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 to framework
> 20140625-162417-16842879-50101-12904-0001
> I0625 16:24:18.530513 12927 hierarchical_allocator_process.hpp:686] Performed
> allocation for 1 slaves in 281957ns
> I0625 16:24:18.530675 12929 master.hpp:794] Adding offer
> 20140625-162417-16842879-50101-12904-5 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 (quantal)
> I0625 16:24:18.530748 12929 master.cpp:3446] Sending 1 offers to framework
> 20140625-162417-16842879-50101-12904-0001
> I0625 16:24:18.531296 12932 sched.cpp:546] Scheduler::resourceOffers took
> 39115ns
> I0625 16:24:18.531441 12929 master.hpp:804] Removing offer
> 20140625-162417-16842879-50101-12904-5 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 (quantal)
> I0625 16:24:18.531493 12929 master.cpp:2125] Processing reply for offers: [
> 20140625-162417-16842879-50101-12904-5 ] on slave
> 20140625-162417-16842879-50101-12904-0 at slave(1)@127.0.1.1:50101 (quantal)
> for framework 20140625-162417-16842879-50101-12904-0001
> I0625 16:24:18.531875 12927 hierarchical_allocator_process.hpp:546] Framework
> 20140625-162417-16842879-50101-12904-0001 left cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] unused on slave
> 20140625-162417-16842879-50101-12904-0
> I0625 16:24:18.540478 12929 hierarchical_allocator_process.hpp:750] Offering
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 to framework
> 20140625-162417-16842879-50101-12904-0000
> I0625 16:24:18.540642 12929 hierarchical_allocator_process.hpp:686] Performed
> allocation for 1 slaves in 218287ns
> I0625 16:24:18.540742 12932 master.hpp:794] Adding offer
> 20140625-162417-16842879-50101-12904-6 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 (quantal)
> I0625 16:24:18.540791 12932 master.cpp:3446] Sending 1 offers to framework
> 20140625-162417-16842879-50101-12904-0000
> I0625 16:24:18.540973 12932 sched.cpp:546] Scheduler::resourceOffers took
> 36583ns
> I0625 16:24:18.541095 12932 master.hpp:804] Removing offer
> 20140625-162417-16842879-50101-12904-6 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 (quantal)
> I0625 16:24:18.541143 12932 master.cpp:2125] Processing reply for offers: [
> 20140625-162417-16842879-50101-12904-6 ] on slave
> 20140625-162417-16842879-50101-12904-0 at slave(1)@127.0.1.1:50101 (quantal)
> for framework 20140625-162417-16842879-50101-12904-0000
> I0625 16:24:18.541317 12929 hierarchical_allocator_process.hpp:546] Framework
> 20140625-162417-16842879-50101-12904-0000 left cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] unused on slave
> 20140625-162417-16842879-50101-12904-0
> I0625 16:24:18.550685 12932 hierarchical_allocator_process.hpp:750] Offering
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 to framework
> 20140625-162417-16842879-50101-12904-0001
> I0625 16:24:18.550827 12932 hierarchical_allocator_process.hpp:686] Performed
> allocation for 1 slaves in 203545ns
> I0625 16:24:18.550910 12932 master.hpp:794] Adding offer
> 20140625-162417-16842879-50101-12904-7 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 (quantal)
> I0625 16:24:18.550956 12932 master.cpp:3446] Sending 1 offers to framework
> 20140625-162417-16842879-50101-12904-0001
> I0625 16:24:18.551118 12932 sched.cpp:546] Scheduler::resourceOffers took
> 36254ns
> I0625 16:24:18.551266 12932 master.hpp:804] Removing offer
> 20140625-162417-16842879-50101-12904-7 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 (quantal)
> I0625 16:24:18.551317 12932 master.cpp:2125] Processing reply for offers: [
> 20140625-162417-16842879-50101-12904-7 ] on slave
> 20140625-162417-16842879-50101-12904-0 at slave(1)@127.0.1.1:50101 (quantal)
> for framework 20140625-162417-16842879-50101-12904-0001
> I0625 16:24:18.551486 12932 hierarchical_allocator_process.hpp:546] Framework
> 20140625-162417-16842879-50101-12904-0001 left cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] unused on slave
> 20140625-162417-16842879-50101-12904-0
> I0625 16:24:18.560866 12932 hierarchical_allocator_process.hpp:750] Offering
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 to framework
> 20140625-162417-16842879-50101-12904-0000
> I0625 16:24:18.561004 12932 hierarchical_allocator_process.hpp:686] Performed
> allocation for 1 slaves in 201407ns
> I0625 16:24:18.561076 12932 master.hpp:794] Adding offer
> 20140625-162417-16842879-50101-12904-8 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 (quantal)
> I0625 16:24:18.561120 12932 master.cpp:3446] Sending 1 offers to framework
> 20140625-162417-16842879-50101-12904-0000
> I0625 16:24:18.561275 12932 sched.cpp:546] Scheduler::resourceOffers took
> 34918ns
> I0625 16:24:18.561394 12932 master.hpp:804] Removing offer
> 20140625-162417-16842879-50101-12904-8 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 (quantal)
> I0625 16:24:18.561442 12932 master.cpp:2125] Processing reply for offers: [
> 20140625-162417-16842879-50101-12904-8 ] on slave
> 20140625-162417-16842879-50101-12904-0 at slave(1)@127.0.1.1:50101 (quantal)
> for framework 20140625-162417-16842879-50101-12904-0000
> I0625 16:24:18.561606 12932 hierarchical_allocator_process.hpp:546] Framework
> 20140625-162417-16842879-50101-12904-0000 left cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] unused on slave
> 20140625-162417-16842879-50101-12904-0
> I0625 16:24:18.573181 12929 master.cpp:122] No whitelist given. Advertising
> offers for all slaves
> I0625 16:24:18.574457 12927 hierarchical_allocator_process.hpp:750] Offering
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 to framework
> 20140625-162417-16842879-50101-12904-0001
> I0625 16:24:18.574797 12927 hierarchical_allocator_process.hpp:686] Performed
> allocation for 1 slaves in 703763ns
> I0625 16:24:18.574956 12928 master.hpp:794] Adding offer
> 20140625-162417-16842879-50101-12904-9 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 (quantal)
> I0625 16:24:18.575006 12928 master.cpp:3446] Sending 1 offers to framework
> 20140625-162417-16842879-50101-12904-0001
> I0625 16:24:18.575160 12928 sched.cpp:546] Scheduler::resourceOffers took
> 34202ns
> I0625 16:24:18.575278 12928 master.hpp:804] Removing offer
> 20140625-162417-16842879-50101-12904-9 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140625-162417-16842879-50101-12904-0 (quantal)
> I0625 16:24:18.575325 12928 master.cpp:2125] Processing reply for offers: [
> 20140625-162417-16842879-50101-12904-9 ] on slave
> 20140625-162417-16842879-50101-12904-0 at slave(1)@127.0.1.1:50101 (quantal)
> for framework 20140625-162417-16842879-50101-12904-0001
> I0625 16:24:18.575769 12927 hierarchical_allocator_process.hpp:546] Framework
> 20140625-162417-16842879-50101-12904-0001 left cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] unused on slave
> 20140625-162417-16842879-50101-12904-0
> I0625 16:24:18.581789 12904 master.cpp:619] Master terminating
> I0625 16:24:18.583214 12928 sched.cpp:747] Stopping framework
> '20140625-162417-16842879-50101-12904-0000'
> I0625 16:24:18.583269 12928 sched.cpp:747] Stopping framework
> '20140625-162417-16842879-50101-12904-0001'
> I0625 16:24:18.583302 12928 slave.cpp:2315] master@127.0.1.1:50101 exited
> W0625 16:24:18.583317 12928 slave.cpp:2318] Master disconnected! Waiting for
> a new master to be elected
> I0625 16:24:18.585260 12904 slave.cpp:469] Slave terminating
> tests/allocator_tests.cpp:352: Failure
> Actual function call count doesn't match EXPECT_CALL(allocator,
> frameworkAdded(_, _, _))...
> Expected: to be called once
> Actual: never called - unsatisfied and active
> [ FAILED ] DRFAllocatorTest.SameShareAllocations (1338 ms)
> {code}
--
This message was sent by Atlassian JIRA
(v6.2#6252)
