See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2282/changes>
Changes: [yan] Fixed a bug that caused 'make dist' unable to patch leveldb. [bmahler] Fixed the master to accept a file:// based zk flag. ------------------------------------------ [...truncated 54988 lines...] I0729 21:49:36.834485 23418 authenticator.hpp:376] Authentication success I0729 21:49:36.834508 23418 authenticatee.hpp:305] Authentication success I0729 21:49:36.834530 23418 master.cpp:3544] Successfully authenticated principal 'test-principal' at slave(195)@140.211.11.27:60822 I0729 21:49:36.834589 23418 slave.cpp:734] Successfully authenticated with master master@140.211.11.27:60822 I0729 21:49:36.834619 23418 slave.cpp:972] Will retry registration in 15.198248ms if necessary I0729 21:49:36.834677 23418 master.cpp:2762] Registering slave at slave(195)@140.211.11.27:60822 (hemera.apache.org) with id 20140729-214936-453759884-60822-23165-0 I0729 21:49:36.834776 23418 registrar.cpp:422] Attempting to update the 'registry' I0729 21:49:36.836351 23418 log.cpp:680] Attempting to append 332 bytes to the log I0729 21:49:36.836395 23418 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3 I0729 21:49:36.836596 23418 replica.cpp:508] Replica received write request for position 3 I0729 21:49:36.853652 23418 leveldb.cpp:343] Persisting action (351 bytes) to leveldb took 17.041964ms I0729 21:49:36.853672 23418 replica.cpp:676] Persisted action at 3 I0729 21:49:36.853713 23441 slave.cpp:972] Will retry registration in 24.094095ms if necessary I0729 21:49:36.853734 23418 master.cpp:2750] Ignoring register slave message from slave(195)@140.211.11.27:60822 (hemera.apache.org) as admission is already in progress I0729 21:49:36.853864 23441 replica.cpp:655] Replica received learned notice for position 3 I0729 21:49:36.869662 23441 leveldb.cpp:343] Persisting action (353 bytes) to leveldb took 15.781742ms I0729 21:49:36.869683 23441 replica.cpp:676] Persisted action at 3 I0729 21:49:36.869691 23441 replica.cpp:661] Replica learned APPEND action at position 3 I0729 21:49:36.869976 23441 registrar.cpp:479] Successfully updated 'registry' I0729 21:49:36.870048 23441 log.cpp:699] Attempting to truncate the log to 3 I0729 21:49:36.870100 23441 master.cpp:2802] Registered slave 20140729-214936-453759884-60822-23165-0 at slave(195)@140.211.11.27:60822 (hemera.apache.org) I0729 21:49:36.870111 23441 master.cpp:3972] Adding slave 20140729-214936-453759884-60822-23165-0 at slave(195)@140.211.11.27:60822 (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):127026; ports(*):[31000-32000] I0729 21:49:36.870205 23441 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4 I0729 21:49:36.870265 23441 slave.cpp:768] Registered with master master@140.211.11.27:60822; given slave ID 20140729-214936-453759884-60822-23165-0 I0729 21:49:36.870368 23441 slave.cpp:2325] Received ping from slave-observer(163)@140.211.11.27:60822 I0729 21:49:36.870425 23441 hierarchical_allocator_process.hpp:444] Added slave 20140729-214936-453759884-60822-23165-0 (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):127026; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):127026; ports(*):[31000-32000] available) I0729 21:49:36.870479 23441 hierarchical_allocator_process.hpp:750] Offering cpus(*):2; mem(*):1024; disk(*):127026; ports(*):[31000-32000] on slave 20140729-214936-453759884-60822-23165-0 to framework 20140729-214936-453759884-60822-23165-0000 I0729 21:49:36.870581 23441 hierarchical_allocator_process.hpp:706] Performed allocation for slave 20140729-214936-453759884-60822-23165-0 in 123548ns I0729 21:49:36.870661 23441 master.hpp:816] Adding offer 20140729-214936-453759884-60822-23165-0 with resources cpus(*):2; mem(*):1024; disk(*):127026; ports(*):[31000-32000] on slave 20140729-214936-453759884-60822-23165-0 (hemera.apache.org) I0729 21:49:36.870702 23441 master.cpp:3451] Sending 1 offers to framework 20140729-214936-453759884-60822-23165-0000 I0729 21:49:36.870931 23441 sched.cpp:546] Scheduler::resourceOffers took 130370ns I0729 21:49:36.871111 23441 master.hpp:826] Removing offer 20140729-214936-453759884-60822-23165-0 with resources cpus(*):2; mem(*):1024; disk(*):127026; ports(*):[31000-32000] on slave 20140729-214936-453759884-60822-23165-0 (hemera.apache.org) I0729 21:49:36.871161 23441 master.cpp:2125] Processing reply for offers: [ 20140729-214936-453759884-60822-23165-0 ] on slave 20140729-214936-453759884-60822-23165-0 at slave(195)@140.211.11.27:60822 (hemera.apache.org) for framework 20140729-214936-453759884-60822-23165-0000 I0729 21:49:36.871181 23441 master.cpp:2211] Authorizing framework principal 'test-principal' to launch task 0 as user 'jenkins' I0729 21:49:36.871446 23441 replica.cpp:508] Replica received write request for position 4 I0729 21:49:36.873731 23420 master.hpp:788] Adding task 0 with resources cpus(*):1; mem(*):500 on slave 20140729-214936-453759884-60822-23165-0 (hemera.apache.org) I0729 21:49:36.873761 23420 master.cpp:2277] Launching task 0 of framework 20140729-214936-453759884-60822-23165-0000 with resources cpus(*):1; mem(*):500 on slave 20140729-214936-453759884-60822-23165-0 at slave(195)@140.211.11.27:60822 (hemera.apache.org) I0729 21:49:36.873890 23420 slave.cpp:1003] Got assigned task 0 for framework 20140729-214936-453759884-60822-23165-0000 I0729 21:49:36.874059 23420 slave.cpp:1113] Launching task 0 for framework 20140729-214936-453759884-60822-23165-0000 I0729 21:49:36.876996 23420 exec.cpp:131] Version: 0.20.0 I0729 21:49:36.877096 23420 slave.cpp:1223] Queuing task '0' for executor default of framework '20140729-214936-453759884-60822-23165-0000 I0729 21:49:36.877140 23430 exec.cpp:181] Executor started at: executor(62)@140.211.11.27:60822 with pid 23165 I0729 21:49:36.881748 23436 hierarchical_allocator_process.hpp:546] Framework 20140729-214936-453759884-60822-23165-0000 left cpus(*):1; mem(*):524; disk(*):127026; ports(*):[31000-32000] unused on slave 20140729-214936-453759884-60822-23165-0 I0729 21:49:36.881837 23436 hierarchical_allocator_process.hpp:588] Framework 20140729-214936-453759884-60822-23165-0000 filtered slave 20140729-214936-453759884-60822-23165-0 for 5secs I0729 21:49:36.889657 23441 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 18.192211ms I0729 21:49:36.889677 23441 replica.cpp:676] Persisted action at 4 I0729 21:49:36.889827 23441 replica.cpp:655] Replica received learned notice for position 4 I0729 21:49:36.897675 23420 slave.cpp:2470] Monitoring executor 'default' of framework '20140729-214936-453759884-60822-23165-0000' in container 'c0c67c96-df20-4629-a452-a90a4dddbf00' I0729 21:49:36.897735 23420 slave.cpp:1734] Got registration for executor 'default' of framework 20140729-214936-453759884-60822-23165-0000 I0729 21:49:36.897809 23420 slave.cpp:1853] Flushing queued task 0 for executor 'default' of framework 20140729-214936-453759884-60822-23165-0000 I0729 21:49:36.897871 23420 slave.cpp:562] Successfully attached file '/tmp/AllocatorTest_0_SlaveReregistersFirst_p09RPE/slaves/20140729-214936-453759884-60822-23165-0/frameworks/20140729-214936-453759884-60822-23165-0000/executors/default/runs/c0c67c96-df20-4629-a452-a90a4dddbf00' I0729 21:49:36.897943 23420 exec.cpp:205] Executor registered on slave 20140729-214936-453759884-60822-23165-0 I0729 21:49:36.899235 23420 exec.cpp:217] Executor::registered took 12044ns I0729 21:49:36.899283 23420 exec.cpp:292] Executor asked to run task '0' I0729 21:49:36.899309 23420 exec.cpp:301] Executor::launchTask took 18158ns I0729 21:49:36.900600 23420 exec.cpp:524] Executor sending status update TASK_RUNNING (UUID: 2e23a056-5546-4488-90eb-06c422d5eec9) for task 0 of framework 20140729-214936-453759884-60822-23165-0000 I0729 21:49:36.900670 23420 slave.cpp:2088] Handling status update TASK_RUNNING (UUID: 2e23a056-5546-4488-90eb-06c422d5eec9) for task 0 of framework 20140729-214936-453759884-60822-23165-0000 from executor(62)@140.211.11.27:60822 I0729 21:49:36.900748 23420 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 2e23a056-5546-4488-90eb-06c422d5eec9) for task 0 of framework 20140729-214936-453759884-60822-23165-0000 I0729 21:49:36.900758 23420 status_update_manager.cpp:499] Creating StatusUpdate stream for task 0 of framework 20140729-214936-453759884-60822-23165-0000 I0729 21:49:36.900807 23420 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 2e23a056-5546-4488-90eb-06c422d5eec9) for task 0 of framework 20140729-214936-453759884-60822-23165-0000 to master@140.211.11.27:60822 I0729 21:49:36.900902 23420 master.cpp:3131] Forwarding status update TASK_RUNNING (UUID: 2e23a056-5546-4488-90eb-06c422d5eec9) for task 0 of framework 20140729-214936-453759884-60822-23165-0000 I0729 21:49:36.900933 23420 master.cpp:3097] Status update TASK_RUNNING (UUID: 2e23a056-5546-4488-90eb-06c422d5eec9) for task 0 of framework 20140729-214936-453759884-60822-23165-0000 from slave 20140729-214936-453759884-60822-23165-0 at slave(195)@140.211.11.27:60822 (hemera.apache.org) I0729 21:49:36.900962 23420 slave.cpp:2246] Status update manager successfully handled status update TASK_RUNNING (UUID: 2e23a056-5546-4488-90eb-06c422d5eec9) for task 0 of framework 20140729-214936-453759884-60822-23165-0000 I0729 21:49:36.900972 23420 slave.cpp:2252] Sending acknowledgement for status update TASK_RUNNING (UUID: 2e23a056-5546-4488-90eb-06c422d5eec9) for task 0 of framework 20140729-214936-453759884-60822-23165-0000 to executor(62)@140.211.11.27:60822 I0729 21:49:36.901038 23420 sched.cpp:637] Scheduler::statusUpdate took 15050ns I0729 21:49:36.901072 23420 exec.cpp:338] Executor received status update acknowledgement 2e23a056-5546-4488-90eb-06c422d5eec9 for task 0 of framework 20140729-214936-453759884-60822-23165-0000 I0729 21:49:36.901118 23420 master.cpp:2612] Forwarding status update acknowledgement 2e23a056-5546-4488-90eb-06c422d5eec9 for task 0 of framework 20140729-214936-453759884-60822-23165-0000 to slave 20140729-214936-453759884-60822-23165-0 at slave(195)@140.211.11.27:60822 (hemera.apache.org) I0729 21:49:36.901202 23420 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 2e23a056-5546-4488-90eb-06c422d5eec9) for task 0 of framework 20140729-214936-453759884-60822-23165-0000 I0729 21:49:36.901319 23420 slave.cpp:1674] Status update manager successfully handled status update acknowledgement (UUID: 2e23a056-5546-4488-90eb-06c422d5eec9) for task 0 of framework 20140729-214936-453759884-60822-23165-0000 I0729 21:49:36.904687 23441 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 14.837602ms I0729 21:49:36.904727 23441 leveldb.cpp:401] Deleting ~2 keys from leveldb took 20007ns I0729 21:49:36.904737 23441 replica.cpp:676] Persisted action at 4 I0729 21:49:36.904745 23441 replica.cpp:661] Replica learned TRUNCATE action at position 4 I0729 21:49:36.904913 23165 master.cpp:626] Master terminating I0729 21:49:36.904948 23165 master.hpp:806] Removing task 0 with resources cpus(*):1; mem(*):500 on slave 20140729-214936-453759884-60822-23165-0 (hemera.apache.org) W0729 21:49:36.904989 23165 master.cpp:4261] Removing task 0 of framework 20140729-214936-453759884-60822-23165-0000 and slave 20140729-214936-453759884-60822-23165-0 in non-terminal state TASK_RUNNING I0729 21:49:36.909679 23440 slave.cpp:2332] master@140.211.11.27:60822 exited W0729 21:49:36.909695 23440 slave.cpp:2335] Master disconnected! Waiting for a new master to be elected I0729 21:49:36.953749 23165 leveldb.cpp:176] Opened db in 47.425831ms I0729 21:49:36.997776 23165 leveldb.cpp:183] Compacted db in 44.003898ms I0729 21:49:36.997900 23165 leveldb.cpp:198] Created db iterator in 3698ns I0729 21:49:36.997970 23165 leveldb.cpp:204] Seeked to beginning of db in 7269ns I0729 21:49:36.998051 23165 leveldb.cpp:273] Iterated through 3 keys in the db in 18164ns I0729 21:49:36.998121 23165 replica.cpp:741] Replica recovered with log positions 3 -> 4 with 0 holes and 0 unlearned I0729 21:49:37.000005 23428 master.cpp:289] Master 20140729-214936-453759884-60822-23165 (hemera.apache.org) started on 140.211.11.27:60822 I0729 21:49:37.000035 23428 master.cpp:326] Master only allowing authenticated frameworks to register I0729 21:49:37.000041 23428 master.cpp:331] Master only allowing authenticated slaves to register I0729 21:49:37.000048 23428 credentials.hpp:36] Loading credentials for authentication from '/tmp/AllocatorTest_0_SlaveReregistersFirst_iMpTJU/credentials' I0729 21:49:37.000169 23428 master.cpp:360] Authorization enabled I0729 21:49:37.000643 23428 recover.cpp:425] Starting replica recovery I0729 21:49:37.000857 23437 master.cpp:123] No whitelist given. Advertising offers for all slaves I0729 21:49:37.001271 23428 recover.cpp:451] Replica is in VOTING status I0729 21:49:37.001327 23428 recover.cpp:440] Recover process terminated I0729 21:49:37.005776 23437 master.cpp:1129] The newly elected leader is master@140.211.11.27:60822 with id 20140729-214936-453759884-60822-23165 I0729 21:49:37.005792 23437 master.cpp:1142] Elected as the leading master! I0729 21:49:37.005805 23437 master.cpp:960] Recovering from registrar I0729 21:49:37.005863 23437 registrar.cpp:313] Recovering registrar I0729 21:49:37.005961 23423 hierarchical_allocator_process.hpp:301] Initializing hierarchical allocator process with master : master@140.211.11.27:60822 I0729 21:49:37.006075 23423 log.cpp:656] Attempting to start the writer I0729 21:49:37.006387 23428 replica.cpp:474] Replica received implicit promise request with proposal 2 I0729 21:49:37.019157 23428 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 12.753413ms I0729 21:49:37.019183 23428 replica.cpp:342] Persisted promised to 2 I0729 21:49:37.019361 23428 coordinator.cpp:230] Coordinator attemping to fill missing position I0729 21:49:37.019443 23428 log.cpp:672] Writer started with ending position 4 I0729 21:49:37.019686 23428 leveldb.cpp:438] Reading position from leveldb took 24690ns I0729 21:49:37.019712 23428 leveldb.cpp:438] Reading position from leveldb took 9283ns I0729 21:49:37.019980 23428 registrar.cpp:346] Successfully fetched the registry (293B) I0729 21:49:37.020002 23428 registrar.cpp:422] Attempting to update the 'registry' I0729 21:49:37.021587 23428 log.cpp:680] Attempting to append 332 bytes to the log I0729 21:49:37.021628 23428 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 5 I0729 21:49:37.021858 23428 replica.cpp:508] Replica received write request for position 5 I0729 21:49:37.035399 23428 leveldb.cpp:343] Persisting action (351 bytes) to leveldb took 13.524949ms I0729 21:49:37.035420 23428 replica.cpp:676] Persisted action at 5 I0729 21:49:37.035612 23428 replica.cpp:655] Replica received learned notice for position 5 I0729 21:49:37.057674 23428 leveldb.cpp:343] Persisting action (353 bytes) to leveldb took 22.046755ms I0729 21:49:37.057701 23428 replica.cpp:676] Persisted action at 5 I0729 21:49:37.057710 23428 replica.cpp:661] Replica learned APPEND action at position 5 I0729 21:49:37.058027 23428 registrar.cpp:479] Successfully updated 'registry' I0729 21:49:37.058078 23428 registrar.cpp:372] Successfully recovered registrar I0729 21:49:37.058143 23428 log.cpp:699] Attempting to truncate the log to 5 I0729 21:49:37.058238 23428 master.cpp:987] Recovered 1 slaves from the Registry (293B) ; allowing 10mins for slaves to re-register I0729 21:49:37.058277 23428 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 6 I0729 21:49:37.058511 23428 replica.cpp:508] Replica received write request for position 6 I0729 21:49:37.071751 23428 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 13.22495ms I0729 21:49:37.071775 23428 replica.cpp:676] Persisted action at 6 I0729 21:49:37.071974 23428 replica.cpp:655] Replica received learned notice for position 6 I0729 21:49:37.083822 23428 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 11.833875ms I0729 21:49:37.083863 23428 leveldb.cpp:401] Deleting ~2 keys from leveldb took 18355ns I0729 21:49:37.083873 23428 replica.cpp:676] Persisted action at 6 I0729 21:49:37.083881 23428 replica.cpp:661] Replica learned TRUNCATE action at position 6 I0729 21:49:37.099376 23428 slave.cpp:601] New master detected at master@140.211.11.27:60822 I0729 21:49:37.099405 23428 slave.cpp:677] Authenticating with master master@140.211.11.27:60822 I0729 21:49:37.099448 23428 slave.cpp:650] Detecting new master I0729 21:49:37.099486 23428 status_update_manager.cpp:167] New master detected at master@140.211.11.27:60822 I0729 21:49:37.099519 23428 authenticatee.hpp:128] Creating new client SASL connection I0729 21:49:37.099643 23428 master.cpp:3504] Authenticating slave(195)@140.211.11.27:60822 I0729 21:49:37.099715 23428 authenticator.hpp:156] Creating new server SASL connection I0729 21:49:37.099798 23428 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I0729 21:49:37.099812 23428 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I0729 21:49:37.099835 23428 authenticator.hpp:262] Received SASL authentication start I0729 21:49:37.099869 23428 authenticator.hpp:384] Authentication requires more steps I0729 21:49:37.099892 23428 authenticatee.hpp:265] Received SASL authentication step I0729 21:49:37.099921 23428 authenticator.hpp:290] Received SASL authentication step I0729 21:49:37.099935 23428 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0729 21:49:37.099941 23428 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I0729 21:49:37.099951 23428 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0729 21:49:37.099958 23428 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0729 21:49:37.099964 23428 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0729 21:49:37.099969 23428 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0729 21:49:37.099978 23428 authenticator.hpp:376] Authentication success I0729 21:49:37.100002 23428 authenticatee.hpp:305] Authentication success I0729 21:49:37.100021 23428 master.cpp:3544] Successfully authenticated principal 'test-principal' at slave(195)@140.211.11.27:60822 I0729 21:49:37.100080 23428 slave.cpp:734] Successfully authenticated with master master@140.211.11.27:60822 I0729 21:49:37.100152 23428 slave.cpp:972] Will retry registration in 11.433797ms if necessary I0729 21:49:37.100222 23428 master.cpp:2937] Re-registering slave 20140729-214936-453759884-60822-23165-0 at slave(195)@140.211.11.27:60822 (hemera.apache.org) I0729 21:49:37.100366 23428 registrar.cpp:422] Attempting to update the 'registry' I0729 21:49:37.101912 23428 log.cpp:680] Attempting to append 332 bytes to the log I0729 21:49:37.101955 23428 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 7 I0729 21:49:37.102157 23428 replica.cpp:508] Replica received write request for position 7 I0729 21:49:37.112546 23427 slave.cpp:972] Will retry registration in 2.150201ms if necessary I0729 21:49:37.112622 23427 master.cpp:2930] Ignoring re-register slave message from slave 20140729-214936-453759884-60822-23165-0 at slave(195)@140.211.11.27:60822 (hemera.apache.org) as readmission is already in progress I0729 21:49:37.114987 23427 slave.cpp:972] Will retry registration in 70.279157ms if necessary I0729 21:49:37.115057 23427 master.cpp:2930] Ignoring re-register slave message from slave 20140729-214936-453759884-60822-23165-0 at slave(195)@140.211.11.27:60822 (hemera.apache.org) as readmission is already in progress I0729 21:49:37.115897 23428 leveldb.cpp:343] Persisting action (351 bytes) to leveldb took 13.724569ms I0729 21:49:37.115918 23428 replica.cpp:676] Persisted action at 7 I0729 21:49:37.116106 23428 replica.cpp:655] Replica received learned notice for position 7 I0729 21:49:37.127997 23428 leveldb.cpp:343] Persisting action (353 bytes) to leveldb took 11.877137ms I0729 21:49:37.128021 23428 replica.cpp:676] Persisted action at 7 I0729 21:49:37.128028 23428 replica.cpp:661] Replica learned APPEND action at position 7 I0729 21:49:37.128324 23428 registrar.cpp:479] Successfully updated 'registry' I0729 21:49:37.128427 23428 log.cpp:699] Attempting to truncate the log to 7 I0729 21:49:37.128480 23428 master.cpp:2988] Re-registered slave 20140729-214936-453759884-60822-23165-0 at slave(195)@140.211.11.27:60822 (hemera.apache.org) I0729 21:49:37.128492 23428 master.cpp:3972] Adding slave 20140729-214936-453759884-60822-23165-0 at slave(195)@140.211.11.27:60822 (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):127026; ports(*):[31000-32000] I0729 21:49:37.128566 23428 master.hpp:788] Adding task 0 with resources cpus(*):1; mem(*):500 on slave 20140729-214936-453759884-60822-23165-0 (hemera.apache.org) W0729 21:49:37.128590 23428 master.cpp:4063] Possibly orphaned task 0 of framework 20140729-214936-453759884-60822-23165-0000 running on slave 20140729-214936-453759884-60822-23165-0 at slave(195)@140.211.11.27:60822 (hemera.apache.org) I0729 21:49:37.128672 23428 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 8 I0729 21:49:37.128734 23428 slave.cpp:818] Re-registered with master master@140.211.11.27:60822 I0729 21:49:37.128855 23428 slave.cpp:2325] Received ping from slave-observer(164)@140.211.11.27:60822 I0729 21:49:37.128926 23428 hierarchical_allocator_process.hpp:444] Added slave 20140729-214936-453759884-60822-23165-0 (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):127026; ports(*):[31000-32000] (and cpus(*):1; mem(*):524; disk(*):127026; ports(*):[31000-32000] available) I0729 21:49:37.128962 23428 hierarchical_allocator_process.hpp:706] Performed allocation for slave 20140729-214936-453759884-60822-23165-0 in 8130ns I0729 21:49:37.129138 23428 replica.cpp:508] Replica received write request for position 8 I0729 21:49:37.131124 23436 sched.cpp:229] Scheduler::disconnected took 8056ns I0729 21:49:37.131137 23436 sched.cpp:235] New master detected at master@140.211.11.27:60822 I0729 21:49:37.131150 23436 sched.cpp:285] Authenticating with master master@140.211.11.27:60822 I0729 21:49:37.131228 23436 authenticatee.hpp:128] Creating new client SASL connection I0729 21:49:37.131343 23436 master.cpp:3504] Authenticating scheduler-94956444-fee9-4b8a-af85-f9945690ee07@140.211.11.27:60822 I0729 21:49:37.131417 23436 authenticator.hpp:156] Creating new server SASL connection I0729 21:49:37.131492 23436 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I0729 21:49:37.131506 23436 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I0729 21:49:37.131527 23436 authenticator.hpp:262] Received SASL authentication start I0729 21:49:37.131557 23436 authenticator.hpp:384] Authentication requires more steps I0729 21:49:37.131580 23436 authenticatee.hpp:265] Received SASL authentication step I0729 21:49:37.131609 23436 authenticator.hpp:290] Received SASL authentication step I0729 21:49:37.131620 23436 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0729 21:49:37.131628 23436 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I0729 21:49:37.131635 23436 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0729 21:49:37.131644 23436 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0729 21:49:37.131649 23436 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0729 21:49:37.131654 23436 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0729 21:49:37.131664 23436 authenticator.hpp:376] Authentication success I0729 21:49:37.131686 23436 authenticatee.hpp:305] Authentication success I0729 21:49:37.131705 23436 master.cpp:3544] Successfully authenticated principal 'test-principal' at scheduler-94956444-fee9-4b8a-af85-f9945690ee07@140.211.11.27:60822 I0729 21:49:37.131762 23436 sched.cpp:359] Successfully authenticated with master master@140.211.11.27:60822 I0729 21:49:37.131773 23436 sched.cpp:478] Sending registration request to master@140.211.11.27:60822 I0729 21:49:37.131814 23436 master.cpp:1356] Received re-registration request from framework 20140729-214936-453759884-60822-23165-0000 at scheduler-94956444-fee9-4b8a-af85-f9945690ee07@140.211.11.27:60822 I0729 21:49:37.131832 23436 master.cpp:1208] Authorizing framework principal 'test-principal' to receive offers for role '*' I0729 21:49:37.131916 23436 master.cpp:1407] Re-registering framework 20140729-214936-453759884-60822-23165-0000 at scheduler-94956444-fee9-4b8a-af85-f9945690ee07@140.211.11.27:60822 I0729 21:49:37.132053 23436 sched.cpp:409] Framework registered with 20140729-214936-453759884-60822-23165-0000 I0729 21:49:37.132072 23436 sched.cpp:423] Scheduler::registered took 8566ns I0729 21:49:37.132170 23436 slave.cpp:1584] Updating framework 20140729-214936-453759884-60822-23165-0000 pid to scheduler-94956444-fee9-4b8a-af85-f9945690ee07@140.211.11.27:60822 I0729 21:49:37.132230 23436 hierarchical_allocator_process.hpp:331] Added framework 20140729-214936-453759884-60822-23165-0000 I0729 21:49:37.132266 23436 hierarchical_allocator_process.hpp:750] Offering cpus(*):1; mem(*):524; disk(*):127026; ports(*):[31000-32000] on slave 20140729-214936-453759884-60822-23165-0 to framework 20140729-214936-453759884-60822-23165-0000 I0729 21:49:37.132380 23436 hierarchical_allocator_process.hpp:686] Performed allocation for 1 slaves in 137410ns I0729 21:49:37.132441 23436 master.hpp:816] Adding offer 20140729-214936-453759884-60822-23165-0 with resources cpus(*):1; mem(*):524; disk(*):127026; ports(*):[31000-32000] on slave 20140729-214936-453759884-60822-23165-0 (hemera.apache.org) I0729 21:49:37.132484 23436 master.cpp:3451] Sending 1 offers to framework 20140729-214936-453759884-60822-23165-0000 I0729 21:49:37.132576 23436 sched.cpp:546] Scheduler::resourceOffers took 18628ns I0729 21:49:37.133805 23165 master.cpp:626] Master terminating I0729 21:49:37.133855 23165 master.hpp:806] Removing task 0 with resources cpus(*):1; mem(*):500 on slave 20140729-214936-453759884-60822-23165-0 (hemera.apache.org) W0729 21:49:37.133896 23165 master.cpp:4261] Removing task 0 of framework 20140729-214936-453759884-60822-23165-0000 and slave 20140729-214936-453759884-60822-23165-0 in non-terminal state TASK_RUNNING I0729 21:49:37.133930 23165 master.hpp:826] Removing offer 20140729-214936-453759884-60822-23165-0 with resources cpus(*):1; mem(*):524; disk(*):127026; ports(*):[31000-32000] on slave 20140729-214936-453759884-60822-23165-0 (hemera.apache.org) I0729 21:49:37.137677 23436 sched.cpp:747] Stopping framework '20140729-214936-453759884-60822-23165-0000' I0729 21:49:37.137723 23436 slave.cpp:2332] master@140.211.11.27:60822 exited W0729 21:49:37.137733 23436 slave.cpp:2335] Master disconnected! Waiting for a new master to be elected I0729 21:49:37.144139 23428 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 14.921098ms I0729 21:49:37.144162 23428 replica.cpp:676] Persisted action at 8 I0729 21:49:37.162089 23165 slave.cpp:485] Slave terminating I0729 21:49:37.162175 23165 slave.cpp:1407] Asked to shut down framework 20140729-214936-453759884-60822-23165-0000 by @0.0.0.0:0 I0729 21:49:37.162240 23165 slave.cpp:1432] Shutting down framework 20140729-214936-453759884-60822-23165-0000 I0729 21:49:37.162299 23165 slave.cpp:2808] Shutting down executor 'default' of framework 20140729-214936-453759884-60822-23165-0000 [ OK ] AllocatorTest/0.SlaveReregistersFirst (585 ms) [----------] 12 tests from AllocatorTest/0 (5748 ms total) [----------] Global test environment tear-down [==========] 351 tests from 57 test cases ran. (249674 ms total) [ PASSED ] 350 tests. [ FAILED ] 1 test, listed below: [ FAILED ] SlaveRecoveryTest/0.SchedulerFailover, where TypeParam = mesos::internal::slave::MesosContainerizer 1 FAILED TEST YOU HAVE 3 DISABLED TESTS make[3]: *** [check-local] Error 1 make[3]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src' make[2]: *** [check-am] Error 2 make[2]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src' make[1]: *** [check] Error 2 make[1]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src' make: *** [check-recursive] Error 1 Build step 'Execute shell' marked build as failure
