[ https://issues.apache.org/jira/browse/MESOS-2007?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Kevin Klues reassigned MESOS-2007: ---------------------------------- Assignee: Kevin Klues > AllocatorTest/0.SlaveReregistersFirst is flaky > ---------------------------------------------- > > Key: MESOS-2007 > URL: https://issues.apache.org/jira/browse/MESOS-2007 > Project: Mesos > Issue Type: Bug > Components: test > Affects Versions: 0.21.0 > Environment: https://builds.apache.org/computer/ubuntu-1/systemInfo > Reporter: Yan Xu > Assignee: Kevin Klues > Labels: flaky > > {noformat:title=} > [ RUN ] AllocatorTest/0.SlaveReregistersFirst > Using temporary directory '/tmp/AllocatorTest_0_SlaveReregistersFirst_YPe61d' > I1028 23:48:22.360447 31190 leveldb.cpp:176] Opened db in 2.192575ms > I1028 23:48:22.361253 31190 leveldb.cpp:183] Compacted db in 760753ns > I1028 23:48:22.361320 31190 leveldb.cpp:198] Created db iterator in 22188ns > I1028 23:48:22.361340 31190 leveldb.cpp:204] Seeked to beginning of db in > 1950ns > I1028 23:48:22.361351 31190 leveldb.cpp:273] Iterated through 0 keys in the > db in 345ns > I1028 23:48:22.361403 31190 replica.cpp:741] Replica recovered with log > positions 0 -> 0 with 1 holes and 0 unlearned > I1028 23:48:22.362185 31217 recover.cpp:437] Starting replica recovery > I1028 23:48:22.362764 31219 recover.cpp:463] Replica is in EMPTY status > I1028 23:48:22.363955 31210 replica.cpp:638] Replica in EMPTY status received > a broadcasted recover request > I1028 23:48:22.364320 31217 recover.cpp:188] Received a recover response from > a replica in EMPTY status > I1028 23:48:22.364820 31211 recover.cpp:554] Updating replica status to > STARTING > I1028 23:48:22.365365 31215 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 418991ns > I1028 23:48:22.365391 31215 replica.cpp:320] Persisted replica status to > STARTING > I1028 23:48:22.365617 31217 recover.cpp:463] Replica is in STARTING status > I1028 23:48:22.366328 31206 master.cpp:312] Master > 20141028-234822-3193029443-50043-31190 (pietas.apache.org) started on > 67.195.81.190:50043 > I1028 23:48:22.366377 31206 master.cpp:358] Master only allowing > authenticated frameworks to register > I1028 23:48:22.366391 31206 master.cpp:363] Master only allowing > authenticated slaves to register > I1028 23:48:22.366402 31206 credentials.hpp:36] Loading credentials for > authentication from > '/tmp/AllocatorTest_0_SlaveReregistersFirst_YPe61d/credentials' > I1028 23:48:22.366708 31206 master.cpp:392] Authorization enabled > I1028 23:48:22.366886 31209 replica.cpp:638] Replica in STARTING status > received a broadcasted recover request > I1028 23:48:22.367311 31208 master.cpp:120] No whitelist given. Advertising > offers for all slaves > I1028 23:48:22.367312 31207 recover.cpp:188] Received a recover response from > a replica in STARTING status > I1028 23:48:22.367686 31211 hierarchical_allocator_process.hpp:299] > Initializing hierarchical allocator process with master : > master@67.195.81.190:50043 > I1028 23:48:22.367863 31212 recover.cpp:554] Updating replica status to VOTING > I1028 23:48:22.368477 31218 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 375527ns > I1028 23:48:22.368505 31218 replica.cpp:320] Persisted replica status to > VOTING > I1028 23:48:22.368517 31204 master.cpp:1242] The newly elected leader is > master@67.195.81.190:50043 with id 20141028-234822-3193029443-50043-31190 > I1028 23:48:22.368549 31204 master.cpp:1255] Elected as the leading master! > I1028 23:48:22.368567 31204 master.cpp:1073] Recovering from registrar > I1028 23:48:22.368621 31215 recover.cpp:568] Successfully joined the Paxos > group > I1028 23:48:22.368716 31219 registrar.cpp:313] Recovering registrar > I1028 23:48:22.369000 31215 recover.cpp:452] Recover process terminated > I1028 23:48:22.369523 31208 log.cpp:656] Attempting to start the writer > I1028 23:48:22.370909 31205 replica.cpp:474] Replica received implicit > promise request with proposal 1 > I1028 23:48:22.371266 31205 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 325016ns > I1028 23:48:22.371290 31205 replica.cpp:342] Persisted promised to 1 > I1028 23:48:22.371979 31218 coordinator.cpp:230] Coordinator attemping to > fill missing position > I1028 23:48:22.373378 31210 replica.cpp:375] Replica received explicit > promise request for position 0 with proposal 2 > I1028 23:48:22.373746 31210 leveldb.cpp:343] Persisting action (8 bytes) to > leveldb took 329018ns > I1028 23:48:22.373772 31210 replica.cpp:676] Persisted action at 0 > I1028 23:48:22.374897 31214 replica.cpp:508] Replica received write request > for position 0 > I1028 23:48:22.374951 31214 leveldb.cpp:438] Reading position from leveldb > took 26002ns > I1028 23:48:22.375272 31214 leveldb.cpp:343] Persisting action (14 bytes) to > leveldb took 289094ns > I1028 23:48:22.375298 31214 replica.cpp:676] Persisted action at 0 > I1028 23:48:22.375886 31204 replica.cpp:655] Replica received learned notice > for position 0 > I1028 23:48:22.376258 31204 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 346650ns > I1028 23:48:22.376277 31204 replica.cpp:676] Persisted action at 0 > I1028 23:48:22.376298 31204 replica.cpp:661] Replica learned NOP action at > position 0 > I1028 23:48:22.376843 31215 log.cpp:672] Writer started with ending position 0 > I1028 23:48:22.378056 31205 leveldb.cpp:438] Reading position from leveldb > took 28265ns > I1028 23:48:22.380323 31217 registrar.cpp:346] Successfully fetched the > registry (0B) in 11.55584ms > I1028 23:48:22.380466 31217 registrar.cpp:445] Applied 1 operations in > 50632ns; attempting to update the 'registry' > I1028 23:48:22.382472 31217 log.cpp:680] Attempting to append 139 bytes to > the log > I1028 23:48:22.382715 31210 coordinator.cpp:340] Coordinator attempting to > write APPEND action at position 1 > I1028 23:48:22.383463 31210 replica.cpp:508] Replica received write request > for position 1 > I1028 23:48:22.383857 31210 leveldb.cpp:343] Persisting action (158 bytes) to > leveldb took 363758ns > I1028 23:48:22.383875 31210 replica.cpp:676] Persisted action at 1 > I1028 23:48:22.384397 31218 replica.cpp:655] Replica received learned notice > for position 1 > I1028 23:48:22.384840 31218 leveldb.cpp:343] Persisting action (160 bytes) to > leveldb took 420161ns > I1028 23:48:22.384862 31218 replica.cpp:676] Persisted action at 1 > I1028 23:48:22.384882 31218 replica.cpp:661] Replica learned APPEND action at > position 1 > I1028 23:48:22.385684 31211 registrar.cpp:490] Successfully updated the > 'registry' in 5.158144ms > I1028 23:48:22.385818 31211 registrar.cpp:376] Successfully recovered > registrar > I1028 23:48:22.385912 31214 log.cpp:699] Attempting to truncate the log to 1 > I1028 23:48:22.386101 31218 coordinator.cpp:340] Coordinator attempting to > write TRUNCATE action at position 2 > I1028 23:48:22.386124 31211 master.cpp:1100] Recovered 0 slaves from the > Registry (101B) ; allowing 10mins for slaves to re-register > I1028 23:48:22.387398 31209 replica.cpp:508] Replica received write request > for position 2 > I1028 23:48:22.387758 31209 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 334969ns > I1028 23:48:22.387776 31209 replica.cpp:676] Persisted action at 2 > I1028 23:48:22.388272 31204 replica.cpp:655] Replica received learned notice > for position 2 > I1028 23:48:22.388453 31204 leveldb.cpp:343] Persisting action (18 bytes) to > leveldb took 159390ns > I1028 23:48:22.388501 31204 leveldb.cpp:401] Deleting ~1 keys from leveldb > took 30409ns > I1028 23:48:22.388516 31204 replica.cpp:676] Persisted action at 2 > I1028 23:48:22.388531 31204 replica.cpp:661] Replica learned TRUNCATE action > at position 2 > I1028 23:48:22.400737 31207 slave.cpp:169] Slave started on > 34)@67.195.81.190:50043 > I1028 23:48:22.400786 31207 credentials.hpp:84] Loading credential for > authentication from > '/tmp/AllocatorTest_0_SlaveReregistersFirst_QPPV21/credential' > I1028 23:48:22.400996 31207 slave.cpp:276] Slave using credential for: > test-principal > I1028 23:48:22.401304 31207 slave.cpp:289] Slave resources: cpus(*):2; > mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000] > I1028 23:48:22.401413 31207 slave.cpp:318] Slave hostname: pietas.apache.org > I1028 23:48:22.401520 31207 slave.cpp:319] Slave checkpoint: false > W1028 23:48:22.401535 31207 slave.cpp:321] Disabling checkpointing is > deprecated and the --checkpoint flag will be removed in a future release. > Please avoid using this flag > I1028 23:48:22.402349 31207 state.cpp:33] Recovering state from > '/tmp/AllocatorTest_0_SlaveReregistersFirst_QPPV21/meta' > I1028 23:48:22.402678 31207 status_update_manager.cpp:197] Recovering status > update manager > I1028 23:48:22.403048 31211 slave.cpp:3456] Finished recovery > I1028 23:48:22.403815 31215 slave.cpp:602] New master detected at > master@67.195.81.190:50043 > I1028 23:48:22.403852 31215 slave.cpp:665] Authenticating with master > master@67.195.81.190:50043 > I1028 23:48:22.403875 31206 status_update_manager.cpp:171] Pausing sending > status updates > I1028 23:48:22.403961 31215 slave.cpp:638] Detecting new master > I1028 23:48:22.404016 31211 authenticatee.hpp:133] Creating new client SASL > connection > I1028 23:48:22.404230 31204 master.cpp:3853] Authenticating > slave(34)@67.195.81.190:50043 > I1028 23:48:22.404464 31205 authenticator.hpp:161] Creating new server SASL > connection > I1028 23:48:22.404613 31211 authenticatee.hpp:224] Received SASL > authentication mechanisms: CRAM-MD5 > I1028 23:48:22.404649 31211 authenticatee.hpp:250] Attempting to authenticate > with mechanism 'CRAM-MD5' > I1028 23:48:22.404734 31211 authenticator.hpp:267] Received SASL > authentication start > I1028 23:48:22.404783 31211 authenticator.hpp:389] Authentication requires > more steps > I1028 23:48:22.404898 31215 authenticatee.hpp:270] Received SASL > authentication step > I1028 23:48:22.404999 31215 authenticator.hpp:295] Received SASL > authentication step > I1028 23:48:22.405030 31215 auxprop.cpp:81] Request to lookup properties for > user: 'test-principal' realm: 'pietas.apache.org' server FQDN: > 'pietas.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false > SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false > I1028 23:48:22.405047 31215 auxprop.cpp:153] Looking up auxiliary property > '*userPassword' > I1028 23:48:22.405086 31215 auxprop.cpp:153] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I1028 23:48:22.405109 31215 auxprop.cpp:81] Request to lookup properties for > user: 'test-principal' realm: 'pietas.apache.org' server FQDN: > 'pietas.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false > SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true > I1028 23:48:22.405122 31215 auxprop.cpp:103] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I1028 23:48:22.405129 31215 auxprop.cpp:103] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I1028 23:48:22.405146 31215 authenticator.hpp:381] Authentication success > I1028 23:48:22.405243 31213 authenticatee.hpp:310] Authentication success > I1028 23:48:22.405253 31214 master.cpp:3893] Successfully authenticated > principal 'test-principal' at slave(34)@67.195.81.190:50043 > I1028 23:48:22.405505 31213 slave.cpp:722] Successfully authenticated with > master master@67.195.81.190:50043 > I1028 23:48:22.405619 31213 slave.cpp:1050] Will retry registration in > 17.050994ms if necessary > I1028 23:48:22.405819 31215 master.cpp:3032] Registering slave at > slave(34)@67.195.81.190:50043 (pietas.apache.org) with id > 20141028-234822-3193029443-50043-31190-S0 > I1028 23:48:22.406262 31216 registrar.cpp:445] Applied 1 operations in > 52647ns; attempting to update the 'registry' > I1028 23:48:22.406697 31190 sched.cpp:137] Version: 0.21.0 > I1028 23:48:22.407083 31211 sched.cpp:233] New master detected at > master@67.195.81.190:50043 > I1028 23:48:22.407114 31211 sched.cpp:283] Authenticating with master > master@67.195.81.190:50043 > I1028 23:48:22.407290 31214 authenticatee.hpp:133] Creating new client SASL > connection > I1028 23:48:22.407424 31214 master.cpp:3853] Authenticating > scheduler-0aa33fc7-0d29-487c-80eb-f933681f9c95@67.195.81.190:50043 > I1028 23:48:22.407659 31207 authenticator.hpp:161] Creating new server SASL > connection > I1028 23:48:22.407757 31207 authenticatee.hpp:224] Received SASL > authentication mechanisms: CRAM-MD5 > I1028 23:48:22.407774 31207 authenticatee.hpp:250] Attempting to authenticate > with mechanism 'CRAM-MD5' > I1028 23:48:22.407830 31207 authenticator.hpp:267] Received SASL > authentication start > I1028 23:48:22.407868 31207 authenticator.hpp:389] Authentication requires > more steps > I1028 23:48:22.407927 31207 authenticatee.hpp:270] Received SASL > authentication step > I1028 23:48:22.408015 31212 authenticator.hpp:295] Received SASL > authentication step > I1028 23:48:22.408037 31212 auxprop.cpp:81] Request to lookup properties for > user: 'test-principal' realm: 'pietas.apache.org' server FQDN: > 'pietas.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false > SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false > I1028 23:48:22.408046 31212 auxprop.cpp:153] Looking up auxiliary property > '*userPassword' > I1028 23:48:22.408072 31212 auxprop.cpp:153] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I1028 23:48:22.408092 31212 auxprop.cpp:81] Request to lookup properties for > user: 'test-principal' realm: 'pietas.apache.org' server FQDN: > 'pietas.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false > SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true > I1028 23:48:22.408100 31212 auxprop.cpp:103] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I1028 23:48:22.408105 31212 auxprop.cpp:103] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I1028 23:48:22.408116 31212 authenticator.hpp:381] Authentication success > I1028 23:48:22.408192 31210 authenticatee.hpp:310] Authentication success > I1028 23:48:22.408210 31217 master.cpp:3893] Successfully authenticated > principal 'test-principal' at > scheduler-0aa33fc7-0d29-487c-80eb-f933681f9c95@67.195.81.190:50043 > I1028 23:48:22.408419 31210 sched.cpp:357] Successfully authenticated with > master master@67.195.81.190:50043 > I1028 23:48:22.408460 31210 sched.cpp:476] Sending registration request to > master@67.195.81.190:50043 > I1028 23:48:22.408568 31217 master.cpp:1362] Received registration request > for framework 'default' at > scheduler-0aa33fc7-0d29-487c-80eb-f933681f9c95@67.195.81.190:50043 > I1028 23:48:22.408617 31217 master.cpp:1321] Authorizing framework principal > 'test-principal' to receive offers for role '*' > I1028 23:48:22.408937 31214 master.cpp:1426] Registering framework > 20141028-234822-3193029443-50043-31190-0000 (default) at > scheduler-0aa33fc7-0d29-487c-80eb-f933681f9c95@67.195.81.190:50043 > I1028 23:48:22.409265 31213 sched.cpp:407] Framework registered with > 20141028-234822-3193029443-50043-31190-0000 > I1028 23:48:22.409267 31212 hierarchical_allocator_process.hpp:329] Added > framework 20141028-234822-3193029443-50043-31190-0000 > I1028 23:48:22.409312 31212 hierarchical_allocator_process.hpp:697] No > resources available to allocate! > I1028 23:48:22.409324 31215 log.cpp:680] Attempting to append 316 bytes to > the log > I1028 23:48:22.409333 31213 sched.cpp:421] Scheduler::registered took 38591ns > I1028 23:48:22.409327 31212 hierarchical_allocator_process.hpp:659] Performed > allocation for 0 slaves in 24107ns > I1028 23:48:22.409518 31205 coordinator.cpp:340] Coordinator attempting to > write APPEND action at position 3 > I1028 23:48:22.410127 31206 replica.cpp:508] Replica received write request > for position 3 > I1028 23:48:22.410706 31206 leveldb.cpp:343] Persisting action (335 bytes) to > leveldb took 554098ns > I1028 23:48:22.410725 31206 replica.cpp:676] Persisted action at 3 > I1028 23:48:22.411151 31217 replica.cpp:655] Replica received learned notice > for position 3 > I1028 23:48:22.411499 31217 leveldb.cpp:343] Persisting action (337 bytes) to > leveldb took 326572ns > I1028 23:48:22.411519 31217 replica.cpp:676] Persisted action at 3 > I1028 23:48:22.411533 31217 replica.cpp:661] Replica learned APPEND action at > position 3 > I1028 23:48:22.412292 31219 registrar.cpp:490] Successfully updated the > 'registry' in 5.972992ms > I1028 23:48:22.412518 31218 log.cpp:699] Attempting to truncate the log to 3 > I1028 23:48:22.412621 31213 coordinator.cpp:340] Coordinator attempting to > write TRUNCATE action at position 4 > I1028 23:48:22.412734 31219 slave.cpp:2522] Received ping from > slave-observer(38)@67.195.81.190:50043 > I1028 23:48:22.412787 31206 master.cpp:3086] Registered slave > 20141028-234822-3193029443-50043-31190-S0 at slave(34)@67.195.81.190:50043 > (pietas.apache.org) with cpus(*):2; mem(*):1024; disk(*):3.70122e+06; > ports(*):[31000-32000] > I1028 23:48:22.412858 31219 slave.cpp:756] Registered with master > master@67.195.81.190:50043; given slave ID > 20141028-234822-3193029443-50043-31190-S0 > I1028 23:48:22.412994 31210 status_update_manager.cpp:178] Resuming sending > status updates > I1028 23:48:22.413014 31211 hierarchical_allocator_process.hpp:442] Added > slave 20141028-234822-3193029443-50043-31190-S0 (pietas.apache.org) with > cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000] (and > cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000] available) > I1028 23:48:22.413159 31211 hierarchical_allocator_process.hpp:734] Offering > cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000] on slave > 20141028-234822-3193029443-50043-31190-S0 to framework > 20141028-234822-3193029443-50043-31190-0000 > I1028 23:48:22.413290 31208 replica.cpp:508] Replica received write request > for position 4 > I1028 23:48:22.413421 31211 hierarchical_allocator_process.hpp:679] Performed > allocation for slave 20141028-234822-3193029443-50043-31190-S0 in 346658ns > I1028 23:48:22.413650 31208 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 336067ns > I1028 23:48:22.413668 31208 replica.cpp:676] Persisted action at 4 > I1028 23:48:22.413797 31216 master.cpp:3795] Sending 1 offers to framework > 20141028-234822-3193029443-50043-31190-0000 (default) at > scheduler-0aa33fc7-0d29-487c-80eb-f933681f9c95@67.195.81.190:50043 > I1028 23:48:22.414077 31212 replica.cpp:655] Replica received learned notice > for position 4 > I1028 23:48:22.414356 31212 leveldb.cpp:343] Persisting action (18 bytes) to > leveldb took 260401ns > I1028 23:48:22.414403 31212 leveldb.cpp:401] Deleting ~2 keys from leveldb > took 28541ns > I1028 23:48:22.414417 31212 replica.cpp:676] Persisted action at 4 > I1028 23:48:22.414446 31212 replica.cpp:661] Replica learned TRUNCATE action > at position 4 > I1028 23:48:22.414422 31207 sched.cpp:544] Scheduler::resourceOffers took > 310278ns > I1028 23:48:22.415086 31214 master.cpp:2321] Processing reply for offers: [ > 20141028-234822-3193029443-50043-31190-O0 ] on slave > 20141028-234822-3193029443-50043-31190-S0 at slave(34)@67.195.81.190:50043 > (pietas.apache.org) for framework 20141028-234822-3193029443-50043-31190-0000 > (default) at > scheduler-0aa33fc7-0d29-487c-80eb-f933681f9c95@67.195.81.190:50043 > W1028 23:48:22.415163 31214 master.cpp:1969] Executor default for task 0 uses > less CPUs (None) than the minimum required (0.01). Please update your > executor, as this will be mandatory in future releases. > W1028 23:48:22.415186 31214 master.cpp:1980] Executor default for task 0 uses > less memory (None) than the minimum required (32MB). Please update your > executor, as this will be mandatory in future releases. > I1028 23:48:22.415256 31214 master.cpp:2417] Authorizing framework principal > 'test-principal' to launch task 0 as user 'jenkins' > I1028 23:48:22.416033 31219 master.hpp:877] Adding task 0 with resources > cpus(*):1; mem(*):500 on slave 20141028-234822-3193029443-50043-31190-S0 > (pietas.apache.org) > I1028 23:48:22.416084 31219 master.cpp:2480] Launching task 0 of framework > 20141028-234822-3193029443-50043-31190-0000 (default) at > scheduler-0aa33fc7-0d29-487c-80eb-f933681f9c95@67.195.81.190:50043 with > resources cpus(*):1; mem(*):500 on slave > 20141028-234822-3193029443-50043-31190-S0 at slave(34)@67.195.81.190:50043 > (pietas.apache.org) > I1028 23:48:22.416317 31214 slave.cpp:1081] Got assigned task 0 for framework > 20141028-234822-3193029443-50043-31190-0000 > I1028 23:48:22.416679 31215 hierarchical_allocator_process.hpp:563] Recovered > cpus(*):1; mem(*):524; disk(*):3.70122e+06; ports(*):[31000-32000] (total > allocatable: cpus(*):1; mem(*):524; disk(*):3.70122e+06; > ports(*):[31000-32000]) on slave 20141028-234822-3193029443-50043-31190-S0 > from framework 20141028-234822-3193029443-50043-31190-0000 > I1028 23:48:22.416721 31215 hierarchical_allocator_process.hpp:599] Framework > 20141028-234822-3193029443-50043-31190-0000 filtered slave > 20141028-234822-3193029443-50043-31190-S0 for 5secs > I1028 23:48:22.416724 31214 slave.cpp:1191] Launching task 0 for framework > 20141028-234822-3193029443-50043-31190-0000 > I1028 23:48:22.418534 31214 slave.cpp:3871] Launching executor default of > framework 20141028-234822-3193029443-50043-31190-0000 in work directory > '/tmp/AllocatorTest_0_SlaveReregistersFirst_QPPV21/slaves/20141028-234822-3193029443-50043-31190-S0/frameworks/20141028-234822-3193029443-50043-31190-0000/executors/default/runs/d593f433-3c16-4678-8f76-4038fe2841c4' > I1028 23:48:22.420557 31214 exec.cpp:132] Version: 0.21.0 > I1028 23:48:22.420755 31213 exec.cpp:182] Executor started at: > executor(22)@67.195.81.190:50043 with pid 31190 > I1028 23:48:22.420903 31214 slave.cpp:1317] Queuing task '0' for executor > default of framework '20141028-234822-3193029443-50043-31190-0000 > I1028 23:48:22.420997 31214 slave.cpp:555] Successfully attached file > '/tmp/AllocatorTest_0_SlaveReregistersFirst_QPPV21/slaves/20141028-234822-3193029443-50043-31190-S0/frameworks/20141028-234822-3193029443-50043-31190-0000/executors/default/runs/d593f433-3c16-4678-8f76-4038fe2841c4' > I1028 23:48:22.421058 31214 slave.cpp:1849] Got registration for executor > 'default' of framework 20141028-234822-3193029443-50043-31190-0000 from > executor(22)@67.195.81.190:50043 > I1028 23:48:22.421295 31214 slave.cpp:1968] Flushing queued task 0 for > executor 'default' of framework 20141028-234822-3193029443-50043-31190-0000 > I1028 23:48:22.421391 31205 exec.cpp:206] Executor registered on slave > 20141028-234822-3193029443-50043-31190-S0 > I1028 23:48:22.421495 31214 slave.cpp:2802] Monitoring executor 'default' of > framework '20141028-234822-3193029443-50043-31190-0000' in container > 'd593f433-3c16-4678-8f76-4038fe2841c4' > I1028 23:48:22.422873 31205 exec.cpp:218] Executor::registered took 19148ns > I1028 23:48:22.422991 31205 exec.cpp:293] Executor asked to run task '0' > I1028 23:48:22.423085 31205 exec.cpp:302] Executor::launchTask took 76519ns > I1028 23:48:22.424541 31205 exec.cpp:525] Executor sending status update > TASK_RUNNING (UUID: 10174aa0-0e5a-4f9d-a530-dee64e93f222) for task 0 of > framework 20141028-234822-3193029443-50043-31190-0000 > I1028 23:48:22.424724 31205 slave.cpp:2202] Handling status update > TASK_RUNNING (UUID: 10174aa0-0e5a-4f9d-a530-dee64e93f222) for task 0 of > framework 20141028-234822-3193029443-50043-31190-0000 from > executor(22)@67.195.81.190:50043 > I1028 23:48:22.424932 31213 status_update_manager.cpp:317] Received status > update TASK_RUNNING (UUID: 10174aa0-0e5a-4f9d-a530-dee64e93f222) for task 0 > of framework 20141028-234822-3193029443-50043-31190-0000 > I1028 23:48:22.424963 31213 status_update_manager.cpp:494] Creating > StatusUpdate stream for task 0 of framework > 20141028-234822-3193029443-50043-31190-0000 > I1028 23:48:22.425122 31213 status_update_manager.cpp:371] Forwarding update > TASK_RUNNING (UUID: 10174aa0-0e5a-4f9d-a530-dee64e93f222) for task 0 of > framework 20141028-234822-3193029443-50043-31190-0000 to the slave > I1028 23:48:22.425257 31205 slave.cpp:2442] Forwarding the update > TASK_RUNNING (UUID: 10174aa0-0e5a-4f9d-a530-dee64e93f222) for task 0 of > framework 20141028-234822-3193029443-50043-31190-0000 to > master@67.195.81.190:50043 > I1028 23:48:22.425398 31205 slave.cpp:2369] Status update manager > successfully handled status update TASK_RUNNING (UUID: > 10174aa0-0e5a-4f9d-a530-dee64e93f222) for task 0 of framework > 20141028-234822-3193029443-50043-31190-0000 > I1028 23:48:22.425420 31205 slave.cpp:2375] Sending acknowledgement for > status update TASK_RUNNING (UUID: 10174aa0-0e5a-4f9d-a530-dee64e93f222) for > task 0 of framework 20141028-234822-3193029443-50043-31190-0000 to > executor(22)@67.195.81.190:50043 > I1028 23:48:22.425583 31212 master.cpp:3410] Forwarding status update > TASK_RUNNING (UUID: 10174aa0-0e5a-4f9d-a530-dee64e93f222) for task 0 of > framework 20141028-234822-3193029443-50043-31190-0000 > I1028 23:48:22.425621 31206 exec.cpp:339] Executor received status update > acknowledgement 10174aa0-0e5a-4f9d-a530-dee64e93f222 for task 0 of framework > 20141028-234822-3193029443-50043-31190-0000 > I1028 23:48:22.425786 31212 master.cpp:3382] Status update TASK_RUNNING > (UUID: 10174aa0-0e5a-4f9d-a530-dee64e93f222) for task 0 of framework > 20141028-234822-3193029443-50043-31190-0000 from slave > 20141028-234822-3193029443-50043-31190-S0 at slave(34)@67.195.81.190:50043 > (pietas.apache.org) > I1028 23:48:22.425832 31212 master.cpp:4617] Updating the latest state of > task 0 of framework 20141028-234822-3193029443-50043-31190-0000 to > TASK_RUNNING > I1028 23:48:22.425885 31208 sched.cpp:635] Scheduler::statusUpdate took > 49727ns > I1028 23:48:22.426082 31208 master.cpp:2882] Forwarding status update > acknowledgement 10174aa0-0e5a-4f9d-a530-dee64e93f222 for task 0 of framework > 20141028-234822-3193029443-50043-31190-0000 (default) at > scheduler-0aa33fc7-0d29-487c-80eb-f933681f9c95@67.195.81.190:50043 to slave > 20141028-234822-3193029443-50043-31190-S0 at slave(34)@67.195.81.190:50043 > (pietas.apache.org) > I1028 23:48:22.426360 31206 status_update_manager.cpp:389] Received status > update acknowledgement (UUID: 10174aa0-0e5a-4f9d-a530-dee64e93f222) for task > 0 of framework 20141028-234822-3193029443-50043-31190-0000 > I1028 23:48:22.426623 31206 slave.cpp:1789] Status update manager > successfully handled status update acknowledgement (UUID: > 10174aa0-0e5a-4f9d-a530-dee64e93f222) for task 0 of framework > 20141028-234822-3193029443-50043-31190-0000 > I1028 23:48:22.426893 31210 master.cpp:677] Master terminating > W1028 23:48:22.427028 31210 master.cpp:4662] Removing task 0 with resources > cpus(*):1; mem(*):500 of framework > 20141028-234822-3193029443-50043-31190-0000 on slave > 20141028-234822-3193029443-50043-31190-S0 at slave(34)@67.195.81.190:50043 > (pietas.apache.org) in non-terminal state TASK_RUNNING > I1028 23:48:22.427397 31209 hierarchical_allocator_process.hpp:563] Recovered > cpus(*):1; mem(*):500 (total allocatable: cpus(*):2; mem(*):1024; > disk(*):3.70122e+06; ports(*):[31000-32000]) on slave > 20141028-234822-3193029443-50043-31190-S0 from framework > 20141028-234822-3193029443-50043-31190-0000 > I1028 23:48:22.427512 31210 master.cpp:4705] Removing executor 'default' with > resources of framework 20141028-234822-3193029443-50043-31190-0000 on slave > 20141028-234822-3193029443-50043-31190-S0 at slave(34)@67.195.81.190:50043 > (pietas.apache.org) > I1028 23:48:22.428129 31206 slave.cpp:2607] master@67.195.81.190:50043 exited > W1028 23:48:22.428153 31206 slave.cpp:2610] Master disconnected! Waiting for > a new master to be elected > I1028 23:48:22.434645 31190 leveldb.cpp:176] Opened db in 2.551453ms > I1028 23:48:22.437157 31190 leveldb.cpp:183] Compacted db in 2.484612ms > I1028 23:48:22.437203 31190 leveldb.cpp:198] Created db iterator in 19171ns > I1028 23:48:22.437235 31190 leveldb.cpp:204] Seeked to beginning of db in > 18300ns > I1028 23:48:22.437306 31190 leveldb.cpp:273] Iterated through 3 keys in the > db in 59465ns > I1028 23:48:22.437347 31190 replica.cpp:741] Replica recovered with log > positions 3 -> 4 with 0 holes and 0 unlearned > I1028 23:48:22.437827 31216 recover.cpp:437] Starting replica recovery > I1028 23:48:22.438127 31216 recover.cpp:463] Replica is in VOTING status > I1028 23:48:22.438443 31216 recover.cpp:452] Recover process terminated > I1028 23:48:22.439877 31212 master.cpp:312] Master > 20141028-234822-3193029443-50043-31190 (pietas.apache.org) started on > 67.195.81.190:50043 > I1028 23:48:22.439916 31212 master.cpp:358] Master only allowing > authenticated frameworks to register > I1028 23:48:22.439931 31212 master.cpp:363] Master only allowing > authenticated slaves to register > I1028 23:48:22.439946 31212 credentials.hpp:36] Loading credentials for > authentication from > '/tmp/AllocatorTest_0_SlaveReregistersFirst_YPe61d/credentials' > I1028 23:48:22.440142 31212 master.cpp:392] Authorization enabled > I1028 23:48:22.440439 31218 master.cpp:120] No whitelist given. Advertising > offers for all slaves > I1028 23:48:22.440901 31213 hierarchical_allocator_process.hpp:299] > Initializing hierarchical allocator process with master : > master@67.195.81.190:50043 > I1028 23:48:22.441395 31206 master.cpp:1242] The newly elected leader is > master@67.195.81.190:50043 with id 20141028-234822-3193029443-50043-31190 > I1028 23:48:22.441421 31206 master.cpp:1255] Elected as the leading master! > I1028 23:48:22.441457 31206 master.cpp:1073] Recovering from registrar > I1028 23:48:22.441623 31205 registrar.cpp:313] Recovering registrar > I1028 23:48:22.442172 31219 log.cpp:656] Attempting to start the writer > I1028 23:48:22.443235 31219 replica.cpp:474] Replica received implicit > promise request with proposal 2 > I1028 23:48:22.443685 31219 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 427888ns > I1028 23:48:22.443703 31219 replica.cpp:342] Persisted promised to 2 > I1028 23:48:22.444371 31213 coordinator.cpp:230] Coordinator attemping to > fill missing position > I1028 23:48:22.444687 31209 log.cpp:672] Writer started with ending position 4 > I1028 23:48:22.445754 31215 leveldb.cpp:438] Reading position from leveldb > took 47909ns > I1028 23:48:22.445826 31215 leveldb.cpp:438] Reading position from leveldb > took 30611ns > I1028 23:48:22.446941 31218 registrar.cpp:346] Successfully fetched the > registry (277B) in 5.213184ms > I1028 23:48:22.447118 31218 registrar.cpp:445] Applied 1 operations in > 42362ns; attempting to update the 'registry' > I1028 23:48:22.449329 31204 log.cpp:680] Attempting to append 316 bytes to > the log > I1028 23:48:22.449477 31218 coordinator.cpp:340] Coordinator attempting to > write APPEND action at position 5 > I1028 23:48:22.450187 31215 replica.cpp:508] Replica received write request > for position 5 > I1028 23:48:22.450767 31215 leveldb.cpp:343] Persisting action (335 bytes) to > leveldb took 554400ns > I1028 23:48:22.450788 31215 replica.cpp:676] Persisted action at 5 > I1028 23:48:22.451561 31215 replica.cpp:655] Replica received learned notice > for position 5 > I1028 23:48:22.451979 31215 leveldb.cpp:343] Persisting action (337 bytes) to > leveldb took 397219ns > I1028 23:48:22.452000 31215 replica.cpp:676] Persisted action at 5 > I1028 23:48:22.452020 31215 replica.cpp:661] Replica learned APPEND action at > position 5 > I1028 23:48:22.452993 31213 registrar.cpp:490] Successfully updated the > 'registry' in 5.816832ms > I1028 23:48:22.453136 31213 registrar.cpp:376] Successfully recovered > registrar > I1028 23:48:22.453238 31208 log.cpp:699] Attempting to truncate the log to 5 > I1028 23:48:22.453384 31214 coordinator.cpp:340] Coordinator attempting to > write TRUNCATE action at position 6 > I1028 23:48:22.453518 31215 master.cpp:1100] Recovered 1 slaves from the > Registry (277B) ; allowing 10mins for slaves to re-register > I1028 23:48:22.454116 31207 replica.cpp:508] Replica received write request > for position 6 > I1028 23:48:22.454570 31207 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 427424ns > I1028 23:48:22.454589 31207 replica.cpp:676] Persisted action at 6 > I1028 23:48:22.455095 31219 replica.cpp:655] Replica received learned notice > for position 6 > I1028 23:48:22.455399 31219 leveldb.cpp:343] Persisting action (18 bytes) to > leveldb took 282466ns > I1028 23:48:22.455462 31219 leveldb.cpp:401] Deleting ~2 keys from leveldb > took 43939ns > I1028 23:48:22.455478 31219 replica.cpp:676] Persisted action at 6 > I1028 23:48:22.455494 31219 replica.cpp:661] Replica learned TRUNCATE action > at position 6 > I1028 23:48:22.465553 31213 status_update_manager.cpp:171] Pausing sending > status updates > I1028 23:48:22.465566 31216 slave.cpp:602] New master detected at > master@67.195.81.190:50043 > I1028 23:48:22.465612 31216 slave.cpp:665] Authenticating with master > master@67.195.81.190:50043 > I1028 23:48:23.441506 31206 hierarchical_allocator_process.hpp:697] No > resources available to allocate! > I1028 23:48:27.441004 31214 master.cpp:120] No whitelist given. Advertising > offers for all slaves > I1028 23:48:30.101379 31206 hierarchical_allocator_process.hpp:659] Performed > allocation for 0 slaves in 6.659877806secs > I1028 23:48:30.101568 31216 slave.cpp:638] Detecting new master > I1028 23:48:30.101632 31214 authenticatee.hpp:133] Creating new client SASL > connection > I1028 23:48:30.102021 31218 master.cpp:3853] Authenticating > slave(34)@67.195.81.190:50043 > I1028 23:48:30.102329 31212 authenticator.hpp:161] Creating new server SASL > connection > I1028 23:48:30.102505 31216 authenticatee.hpp:224] Received SASL > authentication mechanisms: CRAM-MD5 > I1028 23:48:30.102545 31216 authenticatee.hpp:250] Attempting to authenticate > with mechanism 'CRAM-MD5' > I1028 23:48:30.102638 31216 authenticator.hpp:267] Received SASL > authentication start > I1028 23:48:30.102709 31216 authenticator.hpp:389] Authentication requires > more steps > I1028 23:48:30.102812 31216 authenticatee.hpp:270] Received SASL > authentication step > I1028 23:48:30.102957 31204 authenticator.hpp:295] Received SASL > authentication step > I1028 23:48:30.102982 31204 auxprop.cpp:81] Request to lookup properties for > user: 'test-principal' realm: 'pietas.apache.org' server FQDN: > 'pietas.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false > SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false > I1028 23:48:30.102993 31204 auxprop.cpp:153] Looking up auxiliary property > '*userPassword' > I1028 23:48:30.103032 31204 auxprop.cpp:153] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I1028 23:48:30.103049 31204 auxprop.cpp:81] Request to lookup properties for > user: 'test-principal' realm: 'pietas.apache.org' server FQDN: > 'pietas.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false > SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true > I1028 23:48:30.103056 31204 auxprop.cpp:103] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I1028 23:48:30.103061 31204 auxprop.cpp:103] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I1028 23:48:30.103073 31204 authenticator.hpp:381] Authentication success > I1028 23:48:30.103149 31209 authenticatee.hpp:310] Authentication success > I1028 23:48:30.103153 31204 master.cpp:3893] Successfully authenticated > principal 'test-principal' at slave(34)@67.195.81.190:50043 > I1028 23:48:30.103371 31209 slave.cpp:722] Successfully authenticated with > master master@67.195.81.190:50043 > I1028 23:48:30.103773 31209 slave.cpp:1050] Will retry registration in > 12.861518ms if necessary > I1028 23:48:30.104068 31219 master.cpp:3210] Re-registering slave > 20141028-234822-3193029443-50043-31190-S0 at slave(34)@67.195.81.190:50043 > (pietas.apache.org) > I1028 23:48:30.104760 31216 registrar.cpp:445] Applied 1 operations in > 71655ns; attempting to update the 'registry' > I1028 23:48:30.107877 31205 log.cpp:680] Attempting to append 316 bytes to > the log > I1028 23:48:30.108070 31219 coordinator.cpp:340] Coordinator attempting to > write APPEND action at position 7 > I1028 23:48:30.109110 31211 replica.cpp:508] Replica received write request > for position 7 > I1028 23:48:30.109434 31211 leveldb.cpp:343] Persisting action (335 bytes) to > leveldb took 281545ns > I1028 23:48:30.109484 31211 replica.cpp:676] Persisted action at 7 > I1028 23:48:30.110124 31219 replica.cpp:655] Replica received learned notice > for position 7 > I1028 23:48:30.110903 31219 leveldb.cpp:343] Persisting action (337 bytes) to > leveldb took 750414ns > I1028 23:48:30.110927 31219 replica.cpp:676] Persisted action at 7 > I1028 23:48:30.110950 31219 replica.cpp:661] Replica learned APPEND action at > position 7 > I1028 23:48:30.112160 31205 registrar.cpp:490] Successfully updated the > 'registry' in 7.33824ms > I1028 23:48:30.112529 31217 log.cpp:699] Attempting to truncate the log to 7 > I1028 23:48:30.112714 31207 coordinator.cpp:340] Coordinator attempting to > write TRUNCATE action at position 8 > I1028 23:48:30.112870 31210 master.hpp:877] Adding task 0 with resources > cpus(*):1; mem(*):500 on slave 20141028-234822-3193029443-50043-31190-S0 > (pietas.apache.org) > W1028 23:48:30.113136 31210 master.cpp:4394] Possibly orphaned task 0 of > framework 20141028-234822-3193029443-50043-31190-0000 running on slave > 20141028-234822-3193029443-50043-31190-S0 at slave(34)@67.195.81.190:50043 > (pietas.apache.org) > I1028 23:48:30.113198 31219 slave.cpp:2522] Received ping from > slave-observer(39)@67.195.81.190:50043 > I1028 23:48:30.113340 31210 master.cpp:3278] Re-registered slave > 20141028-234822-3193029443-50043-31190-S0 at slave(34)@67.195.81.190:50043 > (pietas.apache.org) with cpus(*):2; mem(*):1024; disk(*):3.70122e+06; > ports(*):[31000-32000] > I1028 23:48:30.113499 31219 slave.cpp:824] Re-registered with master > master@67.195.81.190:50043 > I1028 23:48:30.113636 31219 replica.cpp:508] Replica received write request > for position 8 > I1028 23:48:30.113652 31210 status_update_manager.cpp:178] Resuming sending > status updates > I1028 23:48:30.113759 31212 hierarchical_allocator_process.hpp:442] Added > slave 20141028-234822-3193029443-50043-31190-S0 (pietas.apache.org) with > cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000] (and > cpus(*):1; mem(*):524; disk(*):3.70122e+06; ports(*):[31000-32000] available) > I1028 23:48:30.113904 31212 hierarchical_allocator_process.hpp:679] Performed > allocation for slave 20141028-234822-3193029443-50043-31190-S0 in 74698ns > I1028 23:48:30.114116 31219 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 452165ns > I1028 23:48:30.114142 31219 replica.cpp:676] Persisted action at 8 > I1028 23:48:30.114786 31213 replica.cpp:655] Replica received learned notice > for position 8 > I1028 23:48:30.115337 31213 leveldb.cpp:343] Persisting action (18 bytes) to > leveldb took 525187ns > I1028 23:48:30.115399 31213 leveldb.cpp:401] Deleting ~2 keys from leveldb > took 37689ns > I1028 23:48:30.115418 31213 replica.cpp:676] Persisted action at 8 > I1028 23:48:30.115484 31213 replica.cpp:661] Replica learned TRUNCATE action > at position 8 > I1028 23:48:30.116603 31212 sched.cpp:227] Scheduler::disconnected took > 16969ns > I1028 23:48:30.116624 31212 sched.cpp:233] New master detected at > master@67.195.81.190:50043 > I1028 23:48:30.116657 31212 sched.cpp:283] Authenticating with master > master@67.195.81.190:50043 > I1028 23:48:30.116870 31205 authenticatee.hpp:133] Creating new client SASL > connection > I1028 23:48:30.117084 31207 master.cpp:3853] Authenticating > scheduler-0aa33fc7-0d29-487c-80eb-f933681f9c95@67.195.81.190:50043 > I1028 23:48:30.117279 31212 authenticator.hpp:161] Creating new server SASL > connection > I1028 23:48:30.117410 31210 authenticatee.hpp:224] Received SASL > authentication mechanisms: CRAM-MD5 > I1028 23:48:30.117507 31210 authenticatee.hpp:250] Attempting to authenticate > with mechanism 'CRAM-MD5' > I1028 23:48:30.117604 31214 authenticator.hpp:267] Received SASL > authentication start > I1028 23:48:30.117652 31214 authenticator.hpp:389] Authentication requires > more steps > I1028 23:48:30.117738 31210 authenticatee.hpp:270] Received SASL > authentication step > I1028 23:48:30.117905 31208 authenticator.hpp:295] Received SASL > authentication step > I1028 23:48:30.117935 31208 auxprop.cpp:81] Request to lookup properties for > user: 'test-principal' realm: 'pietas.apache.org' server FQDN: > 'pietas.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false > SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false > I1028 23:48:30.117947 31208 auxprop.cpp:153] Looking up auxiliary property > '*userPassword' > I1028 23:48:30.117979 31208 auxprop.cpp:153] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I1028 23:48:30.118001 31208 auxprop.cpp:81] Request to lookup properties for > user: 'test-principal' realm: 'pietas.apache.org' server FQDN: > 'pietas.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false > SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true > I../../src/tests/allocator_tests.cpp:2405: Failure > 1028 23:48:30.118013 31208 auxprop.cpp:103] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > Failed to wait 10secs for resourceOffers2 > I1028 23:48:31.101976 31212 hierarchical_allocator_process.hpp:659] Performed > allocation for 1 slaves in 124354ns > I1028 23:48:58.775811 31208 auxprop.cpp:103] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > W1028 23:48:35.117725 31214 sched.cpp:378] Authentication timed out > W1028 23:48:35.117784 31219 master.cpp:3911] Authentication timed out > I1028 23:48:45.114322 31213 slave.cpp:2522] Received ping from > slave-observer(39)@67.195.81.190:50043 > I1028 23:48:35.102212 31206 master.cpp:120] No whitelist given. Advertising > offers for all slaves > I1028 23:48:58.775874 31208 authenticator.hpp:381] Authentication success > I1028 23:48:58.776267 31214 sched.cpp:338] Failed to authenticate with master > master@67.195.81.190:50043: Authentication discarded > ../../src/tests/allocator_tests.cpp:2396: Failure > Actual function call count doesn't match EXPECT_CALL(allocator2, > frameworkAdded(_, _, _))... > Expected: to be called once > Actual: never called - unsatisfied and active > I1028 23:48:58.776526 31204 master.cpp:3893] Successfully authenticated > principal 'test-principal' at > scheduler-0aa33fc7-0d29-487c-80eb-f933681f9c95@67.195.81.190:50043 > I1028 23:48:58.776626 31214 sched.cpp:283] Authenticating with master > master@67.195.81.190:50043 > I1028 23:48:58.776928 31204 authenticatee.hpp:133] Creating new client SASL > connection > I1028 23:48:58.777194 31210 master.cpp:3853] Authenticating > scheduler-0aa33fc7-0d29-487c-80eb-f933681f9c95@67.195.81.190:50043 > W1028 23:48:58.777528 31210 master.cpp:3888] Failed to authenticate > scheduler-0aa33fc7-0d29-487c-80eb-f933681f9c95@67.195.81.190:50043: Failed to > communicate with authenticatee > ../../src/tests/allocator_tests.cpp:2399: Failure > Actual function call count doesn't match EXPECT_CALL(sched, > resourceOffers(&driver, _))... > Expected: to be called once > Actual: never called - unsatisfied and active > ../../src/tests/allocator_tests.cpp:2394: Failure > Actual function call count doesn't match EXPECT_CALL(sched, > registered(&driver, _, _))... > Expected: to be called once > Actual: never called - unsatisfied and active > I1028 23:48:58.778053 31205 slave.cpp:591] Re-detecting master > I1028 23:48:58.778084 31205 slave.cpp:638] Detecting new master > I1028 23:48:58.778115 31207 status_update_manager.cpp:171] Pausing sending > status updates > F1028 23:48:58.778115 31205 logging.cpp:57] RAW: Pure virtual method called > I1028 23:48:58.778724 31210 master.cpp:677] Master terminating > W1028 23:48:58.778919 31210 master.cpp:4662] Removing task 0 with resources > cpus(*):1; mem(*):500 of framework > 20141028-234822-3193029443-50043-31190-0000 on slave > 20141028-234822-3193029443-50043-31190-S0 at slave(34)@67.195.81.190:50043 > (pietas.apache.org) in non-terminal state TASK_RUNNING > *** Aborted at 1414540138 (unix time) try "date -d @1414540138" if you are > using GNU date *** > PC: @ 0x91bc86 process::PID<>::PID() > *** SIGSEGV (@0x0) received by PID 31190 (TID 0x2b20a6d95700) from PID 0; > stack trace: *** > @ 0x2b20a41ff340 (unknown) > @ 0x2b20a1f2a188 google::LogMessage::Fail() > @ 0x2b20a1f2f87c google::RawLog__() > @ 0x91bc86 process::PID<>::PID() > @ 0x91bf24 process::Process<>::self() > @ 0x2b20a15d5c06 __cxa_pure_virtual > @ 0x2b20a1877752 mesos::internal::slave::Slave::detected() > @ 0x2b20a1671f24 process::dispatch<>() > @ 0x2b20a18b35f9 > _ZZN7process8dispatchIN5mesos8internal5slave5SlaveERKNS_6FutureI6OptionINS1_10MasterInfoEEEES9_EEvRKNS_3PIDIT_EEMSD_FvT0_ET1_ENKUlPNS_11ProcessBaseEE_clESM_ > @ 0x2b20a1663217 > mesos::internal::master::allocator::Allocator::resourcesRecovered() > @ 0x2b20a1650d01 mesos::internal::master::Master::removeTask() > @ 0x2b20a162fb41 mesos::internal::master::Master::finalize() > @ 0x2b20a1eb69a1 process::ProcessBase::visit() > @ 0x2b20a1ec0464 process::TerminateEvent::visit() > @ 0x8e0812 process::ProcessBase::serve() > @ 0x2b20a18da89e > _ZNSt17_Function_handlerIFvPN7process11ProcessBaseEEZNS0_8dispatchIN5mesos8internal5slave5SlaveERKNS0_6FutureI6OptionINS5_10MasterInfoEEEESD_EEvRKNS0_3PIDIT_EEMSH_FvT0_ET1_EUlS2_E_E9_M_invokeERKSt9_Any_dataS2_ > @ 0x2b20a1eb1ca0 process::ProcessManager::resume() > @ 0x2b20a1ea8365 process::schedule() > @ 0x2b20a41f7182 start_thread > @ 0x2b20a4507fbd (unknown) > make[3]: *** [check-local] Segmentation fault > {noformat} -- This message was sent by Atlassian JIRA (v6.3.4#6332)