You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mesos.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2014/10/29 00:49:29 UTC
Build failed in Jenkins:
Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2502
See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2502/changes>
Changes:
[tstclair] Add --enable-debug and --enable-optimize flag for controlling building debug and optimized verisons of libprocess
[idownes] Include tests/setns_test_helper.hpp in Makefile.
------------------------------------------
[...truncated 12824 lines...]
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
make[3]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src'>
make[2]: *** [check-am] Error 2
make[2]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src'>
make[1]: *** [check] Error 2
make[1]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src'>
make: *** [check-recursive] Error 1
Test finished
Exit status: 2
Build step 'Execute shell' marked build as failure
Recording test results
Jenkins build is back to normal :
Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2503
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2503/changes>
Re: Build failed in Jenkins: Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2502
Posted by Yan Xu <ya...@jxu.me>.
https://issues.apache.org/jira/browse/MESOS-2007
--
Jiang Yan Xu <ya...@jxu.me> @xujyan <http://twitter.com/xujyan>
On Tue, Oct 28, 2014 at 4:49 PM, Apache Jenkins Server <
jenkins@builds.apache.org> wrote:
> See <
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2502/changes
> >
>
> Changes:
>
> [tstclair] Add --enable-debug and --enable-optimize flag for controlling
> building debug and optimized verisons of libprocess
>
> [idownes] Include tests/setns_test_helper.hpp in Makefile.
>
> ------------------------------------------
> [...truncated 12824 lines...]
> 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
> make[3]: Leaving directory `<
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src
> '>
> make[2]: *** [check-am] Error 2
> make[2]: Leaving directory `<
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src
> '>
> make[1]: *** [check] Error 2
> make[1]: Leaving directory `<
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src
> '>
> make: *** [check-recursive] Error 1
> Test finished
> Exit status: 2
> Build step 'Execute shell' marked build as failure
> Recording test results
>