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/07/29 23:49:37 UTC
Build failed in Jenkins:
Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2282
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
Jenkins build is back to normal :
Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2284
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/2284/changes>
Re: Build failed in Jenkins: Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2283
Posted by Benjamin Mahler <be...@gmail.com>.
SlaveRecoveryTest/0.KillTask looks like the test did not wait for the
executor to re-register before advancing the clock. Will push a small fix.
SlaveRecoveryTest/0.MultipleSlaves looks like the sleep in the command
executor
<https://github.com/apache/mesos/blob/0.19.1/src/launcher/executor.cpp#L324>
was not enough time for the TASK_KILLED to be sent to the slave. I've seen
this in two tests now so it seems like the 1 second sleep might not be
enough for the CI machines.
On Tue, Jul 29, 2014 at 6:45 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/2283/changes
> >
>
> Changes:
>
> [dhamon] Converted bool returns to Try<Nothing> in stout/os.hpp.
>
> [dhamon] Mesos converted to use Try<Nothing> returns from stout/os.hpp.
>
> [bmahler] Cleaned up TODO comments for ZK file:// URL support.
>
> [niklas] Task health status change notifications
>
> [bmahler] Fixed a flaky slave recovery test.
>
> [bmahler] Cleaned up the flag help documentation.
>
> ------------------------------------------
> [...truncated 55276 lines...]
> I0730 01:45:50.575980 21067 recover.cpp:451] Replica is in EMPTY status
> I0730 01:45:50.576040 21067 registrar.cpp:313] Recovering registrar
> I0730 01:45:50.576530 21067 replica.cpp:638] Replica in EMPTY status
> received a broadcasted recover request
> I0730 01:45:50.576594 21067 recover.cpp:188] Received a recover response
> from a replica in EMPTY status
> I0730 01:45:50.576704 21067 recover.cpp:542] Updating replica status to
> STARTING
> I0730 01:45:50.589684 21067 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 12.903968ms
> I0730 01:45:50.589740 21067 replica.cpp:320] Persisted replica status to
> STARTING
> I0730 01:45:50.589856 21067 recover.cpp:451] Replica is in STARTING status
> I0730 01:45:50.590235 21067 replica.cpp:638] Replica in STARTING status
> received a broadcasted recover request
> I0730 01:45:50.590301 21067 recover.cpp:188] Received a recover response
> from a replica in STARTING status
> I0730 01:45:50.590409 21067 recover.cpp:542] Updating replica status to
> VOTING
> I0730 01:45:50.613689 21067 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 23.214235ms
> I0730 01:45:50.613843 21067 replica.cpp:320] Persisted replica status to
> VOTING
> I0730 01:45:50.613976 21067 recover.cpp:556] Successfully joined the Paxos
> group
> I0730 01:45:50.614120 21067 recover.cpp:440] Recover process terminated
> I0730 01:45:50.614296 21047 log.cpp:656] Attempting to start the writer
> I0730 01:45:50.614717 21047 replica.cpp:474] Replica received implicit
> promise request with proposal 1
> I0730 01:45:50.629683 21047 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 14.941262ms
> I0730 01:45:50.629734 21047 replica.cpp:342] Persisted promised to 1
> I0730 01:45:50.629991 21047 coordinator.cpp:230] Coordinator attemping to
> fill missing position
> I0730 01:45:50.630377 21047 replica.cpp:375] Replica received explicit
> promise request for position 0 with proposal 2
> I0730 01:45:50.645654 21047 leveldb.cpp:343] Persisting action (8 bytes)
> to leveldb took 15.245725ms
> I0730 01:45:50.645709 21047 replica.cpp:676] Persisted action at 0
> I0730 01:45:50.646080 21047 replica.cpp:508] Replica received write
> request for position 0
> I0730 01:45:50.646106 21047 leveldb.cpp:438] Reading position from leveldb
> took 14660ns
> I0730 01:45:50.665685 21047 leveldb.cpp:343] Persisting action (14 bytes)
> to leveldb took 19.555587ms
> I0730 01:45:50.665740 21047 replica.cpp:676] Persisted action at 0
> I0730 01:45:50.665961 21047 replica.cpp:655] Replica received learned
> notice for position 0
> I0730 01:45:50.681684 21047 leveldb.cpp:343] Persisting action (16 bytes)
> to leveldb took 15.693681ms
> I0730 01:45:50.681733 21047 replica.cpp:676] Persisted action at 0
> I0730 01:45:50.681743 21047 replica.cpp:661] Replica learned NOP action at
> position 0
> I0730 01:45:50.681982 21047 log.cpp:672] Writer started with ending
> position 0
> I0730 01:45:50.682251 21047 leveldb.cpp:438] Reading position from leveldb
> took 17318ns
> I0730 01:45:50.683776 21047 registrar.cpp:346] Successfully fetched the
> registry (0B)
> I0730 01:45:50.683795 21047 registrar.cpp:422] Attempting to update the
> 'registry'
> I0730 01:45:50.685314 21047 log.cpp:680] Attempting to append 138 bytes to
> the log
> I0730 01:45:50.685358 21047 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 1
> I0730 01:45:50.685586 21047 replica.cpp:508] Replica received write
> request for position 1
> I0730 01:45:50.705683 21047 leveldb.cpp:343] Persisting action (157 bytes)
> to leveldb took 20.07148ms
> I0730 01:45:50.705734 21047 replica.cpp:676] Persisted action at 1
> I0730 01:45:50.706009 21047 replica.cpp:655] Replica received learned
> notice for position 1
> I0730 01:45:50.725682 21047 leveldb.cpp:343] Persisting action (159 bytes)
> to leveldb took 19.646881ms
> I0730 01:45:50.725733 21047 replica.cpp:676] Persisted action at 1
> I0730 01:45:50.725744 21047 replica.cpp:661] Replica learned APPEND action
> at position 1
> I0730 01:45:50.726102 21047 registrar.cpp:479] Successfully updated
> 'registry'
> I0730 01:45:50.726141 21047 registrar.cpp:372] Successfully recovered
> registrar
> I0730 01:45:50.726182 21047 log.cpp:699] Attempting to truncate the log to
> 1
> I0730 01:45:50.726256 21047 master.cpp:987] Recovered 0 slaves from the
> Registry (100B) ; allowing 10mins for slaves to re-register
> I0730 01:45:50.726294 21047 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 2
> I0730 01:45:50.726553 21047 replica.cpp:508] Replica received write
> request for position 2
> I0730 01:45:50.745668 21047 leveldb.cpp:343] Persisting action (16 bytes)
> to leveldb took 19.095229ms
> I0730 01:45:50.745703 21047 replica.cpp:676] Persisted action at 2
> I0730 01:45:50.745935 21047 replica.cpp:655] Replica received learned
> notice for position 2
> I0730 01:45:50.759333 21047 leveldb.cpp:343] Persisting action (18 bytes)
> to leveldb took 13.382009ms
> I0730 01:45:50.759376 21047 leveldb.cpp:401] Deleting ~1 keys from leveldb
> took 18643ns
> I0730 01:45:50.759385 21047 replica.cpp:676] Persisted action at 2
> I0730 01:45:50.759394 21047 replica.cpp:661] Replica learned TRUNCATE
> action at position 2
> I0730 01:45:50.769793 21060 slave.cpp:169] Slave started on 196)@
> 140.211.11.27:56984
> I0730 01:45:50.769820 21060 credentials.hpp:84] Loading credential for
> authentication from
> '/tmp/MultipleExecutorsTest_ExecutorInfoDiffersOnSameSlave_3GakdP/credential'
> I0730 01:45:50.769920 21060 slave.cpp:267] Slave using credential for:
> test-principal
> I0730 01:45:50.770030 21060 slave.cpp:280] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0730 01:45:50.771483 20297 sched.cpp:139] Version: 0.20.0
> I0730 01:45:50.771796 21054 sched.cpp:235] New master detected at
> master@140.211.11.27:56984
> I0730 01:45:50.771821 21054 sched.cpp:285] Authenticating with master
> master@140.211.11.27:56984
> I0730 01:45:50.771909 21054 authenticatee.hpp:128] Creating new client
> SASL connection
> I0730 01:45:50.772047 21054 master.cpp:3504] Authenticating
> scheduler-f1390c07-a5e1-4562-b565-7f44c02b35cf@140.211.11.27:56984
> I0730 01:45:50.772128 21054 authenticator.hpp:156] Creating new server
> SASL connection
> I0730 01:45:50.772212 21054 authenticatee.hpp:219] Received SASL
> authentication mechanisms: CRAM-MD5
> I0730 01:45:50.772228 21054 authenticatee.hpp:245] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> I0730 01:45:50.772251 21054 authenticator.hpp:262] Received SASL
> authentication start
> I0730 01:45:50.772286 21054 authenticator.hpp:384] Authentication requires
> more steps
> I0730 01:45:50.772310 21054 authenticatee.hpp:265] Received SASL
> authentication step
> I0730 01:45:50.772341 21054 authenticator.hpp:290] Received SASL
> authentication step
> I0730 01:45:50.772356 21054 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
> I0730 01:45:50.772362 21054 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I0730 01:45:50.772372 21054 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0730 01:45:50.772382 21054 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
> I0730 01:45:50.772387 21054 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0730 01:45:50.772392 21054 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0730 01:45:50.772403 21054 authenticator.hpp:376] Authentication success
> I0730 01:45:50.772428 21054 authenticatee.hpp:305] Authentication success
> I0730 01:45:50.772447 21054 master.cpp:3544] Successfully authenticated
> principal 'test-principal' at
> scheduler-f1390c07-a5e1-4562-b565-7f44c02b35cf@140.211.11.27:56984
> I0730 01:45:50.772512 21054 sched.cpp:359] Successfully authenticated with
> master master@140.211.11.27:56984
> I0730 01:45:50.772522 21054 sched.cpp:478] Sending registration request to
> master@140.211.11.27:56984
> I0730 01:45:50.772570 21054 master.cpp:1248] Received registration request
> from scheduler-f1390c07-a5e1-4562-b565-7f44c02b35cf@140.211.11.27:56984
> I0730 01:45:50.772588 21054 master.cpp:1208] Authorizing framework
> principal 'test-principal' to receive offers for role '*'
> I0730 01:45:50.772685 21054 master.cpp:1307] Registering framework
> 20140730-014550-453759884-56984-20297-0000 at
> scheduler-f1390c07-a5e1-4562-b565-7f44c02b35cf@140.211.11.27:56984
> I0730 01:45:50.772768 21054 sched.cpp:409] Framework registered with
> 20140730-014550-453759884-56984-20297-0000
> I0730 01:45:50.772786 21054 sched.cpp:423] Scheduler::registered took
> 9142ns
> I0730 01:45:50.772819 21054 hierarchical_allocator_process.hpp:331] Added
> framework 20140730-014550-453759884-56984-20297-0000
> I0730 01:45:50.772826 21054 hierarchical_allocator_process.hpp:724] No
> resources available to allocate!
> I0730 01:45:50.772831 21054 hierarchical_allocator_process.hpp:686]
> Performed allocation for 0 slaves in 5748ns
> I0730 01:45:50.772984 21060 slave.cpp:325] Slave hostname:
> hemera.apache.org
> I0730 01:45:50.772997 21060 slave.cpp:326] Slave checkpoint: false
> I0730 01:45:50.773510 21060 state.cpp:33] Recovering state from
> '/tmp/MultipleExecutorsTest_ExecutorInfoDiffersOnSameSlave_3GakdP/meta'
> I0730 01:45:50.773612 21060 status_update_manager.cpp:193] Recovering
> status update manager
> I0730 01:45:50.777725 21060 slave.cpp:3128] Finished recovery
> I0730 01:45:50.777956 21060 slave.cpp:601] New master detected at
> master@140.211.11.27:56984
> I0730 01:45:50.777978 21060 slave.cpp:677] Authenticating with master
> master@140.211.11.27:56984
> I0730 01:45:50.778020 21060 slave.cpp:650] Detecting new master
> I0730 01:45:50.778059 21060 status_update_manager.cpp:167] New master
> detected at master@140.211.11.27:56984
> I0730 01:45:50.778091 21060 authenticatee.hpp:128] Creating new client
> SASL connection
> I0730 01:45:50.778219 21060 master.cpp:3504] Authenticating slave(196)@
> 140.211.11.27:56984
> I0730 01:45:50.778297 21060 authenticator.hpp:156] Creating new server
> SASL connection
> I0730 01:45:50.778384 21060 authenticatee.hpp:219] Received SASL
> authentication mechanisms: CRAM-MD5
> I0730 01:45:50.778400 21060 authenticatee.hpp:245] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> I0730 01:45:50.778425 21060 authenticator.hpp:262] Received SASL
> authentication start
> I0730 01:45:50.778457 21060 authenticator.hpp:384] Authentication requires
> more steps
> I0730 01:45:50.778489 21060 authenticatee.hpp:265] Received SASL
> authentication step
> I0730 01:45:50.778524 21060 authenticator.hpp:290] Received SASL
> authentication step
> I0730 01:45:50.778537 21060 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
> I0730 01:45:50.778544 21060 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I0730 01:45:50.778554 21060 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0730 01:45:50.778563 21060 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
> I0730 01:45:50.778568 21060 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0730 01:45:50.778573 21060 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0730 01:45:50.778584 21060 authenticator.hpp:376] Authentication success
> I0730 01:45:50.778610 21060 authenticatee.hpp:305] Authentication success
> I0730 01:45:50.778633 21060 master.cpp:3544] Successfully authenticated
> principal 'test-principal' at slave(196)@140.211.11.27:56984
> I0730 01:45:50.778698 21060 slave.cpp:734] Successfully authenticated with
> master master@140.211.11.27:56984
> I0730 01:45:50.778740 21060 slave.cpp:972] Will retry registration in
> 4.823399ms if necessary
> I0730 01:45:50.778812 21060 master.cpp:2762] Registering slave at
> slave(196)@140.211.11.27:56984 (hemera.apache.org) with id
> 20140730-014550-453759884-56984-20297-0
> I0730 01:45:50.778924 21060 registrar.cpp:422] Attempting to update the
> 'registry'
> I0730 01:45:50.780408 21060 log.cpp:680] Attempting to append 332 bytes to
> the log
> I0730 01:45:50.780468 21060 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 3
> I0730 01:45:50.780742 21060 replica.cpp:508] Replica received write
> request for position 3
> I0730 01:45:50.789727 21052 slave.cpp:972] Will retry registration in
> 4.307262ms if necessary
> I0730 01:45:50.789796 21052 master.cpp:2750] Ignoring register slave
> message from slave(196)@140.211.11.27:56984 (hemera.apache.org) as
> admission is already in progress
> I0730 01:45:50.797801 21056 slave.cpp:972] Will retry registration in
> 59.396428ms if necessary
> I0730 01:45:50.797901 21056 master.cpp:2750] Ignoring register slave
> message from slave(196)@140.211.11.27:56984 (hemera.apache.org) as
> admission is already in progress
> I0730 01:45:50.829689 21060 leveldb.cpp:343] Persisting action (351 bytes)
> to leveldb took 48.916641ms
> I0730 01:45:50.829848 21060 replica.cpp:676] Persisted action at 3
> I0730 01:45:50.830270 21056 replica.cpp:655] Replica received learned
> notice for position 3
> I0730 01:45:50.844269 21056 leveldb.cpp:343] Persisting action (353 bytes)
> to leveldb took 13.969906ms
> I0730 01:45:50.844316 21056 replica.cpp:676] Persisted action at 3
> I0730 01:45:50.844327 21056 replica.cpp:661] Replica learned APPEND action
> at position 3
> I0730 01:45:50.844794 21056 registrar.cpp:479] Successfully updated
> 'registry'
> I0730 01:45:50.844884 21056 log.cpp:699] Attempting to truncate the log to
> 3
> I0730 01:45:50.844950 21056 master.cpp:2802] Registered slave
> 20140730-014550-453759884-56984-20297-0 at slave(196)@140.211.11.27:56984
> (hemera.apache.org)
> I0730 01:45:50.844964 21056 master.cpp:3972] Adding slave
> 20140730-014550-453759884-56984-20297-0 at slave(196)@140.211.11.27:56984
> (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]
> I0730 01:45:50.845087 21056 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 4
> I0730 01:45:50.845166 21056 slave.cpp:768] Registered with master
> master@140.211.11.27:56984; given slave ID
> 20140730-014550-453759884-56984-20297-0
> I0730 01:45:50.845237 21056 hierarchical_allocator_process.hpp:444] Added
> slave 20140730-014550-453759884-56984-20297-0 (hemera.apache.org) with
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I0730 01:45:50.845298 21056 hierarchical_allocator_process.hpp:750]
> Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on
> slave 20140730-014550-453759884-56984-20297-0 to framework
> 20140730-014550-453759884-56984-20297-0000
> I0730 01:45:50.845402 21056 hierarchical_allocator_process.hpp:706]
> Performed allocation for slave 20140730-014550-453759884-56984-20297-0 in
> 134270ns
> I0730 01:45:50.845455 21056 slave.cpp:2325] Received ping from
> slave-observer(165)@140.211.11.27:56984
> I0730 01:45:50.845512 21056 master.hpp:816] Adding offer
> 20140730-014550-453759884-56984-20297-0 with resources cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140730-014550-453759884-56984-20297-0 (hemera.apache.org)
> I0730 01:45:50.845554 21056 master.cpp:3451] Sending 1 offers to framework
> 20140730-014550-453759884-56984-20297-0000
> I0730 01:45:50.845746 21056 sched.cpp:546] Scheduler::resourceOffers took
> 31773ns
> I0730 01:45:50.846127 21059 replica.cpp:508] Replica received write
> request for position 4
> I0730 01:45:50.856356 21059 leveldb.cpp:343] Persisting action (16 bytes)
> to leveldb took 10.20412ms
> I0730 01:45:50.856395 21059 replica.cpp:676] Persisted action at 4
> I0730 01:45:50.856613 21059 replica.cpp:655] Replica received learned
> notice for position 4
> I0730 01:45:50.857946 21043 master.hpp:826] Removing offer
> 20140730-014550-453759884-56984-20297-0 with resources cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140730-014550-453759884-56984-20297-0 (hemera.apache.org)
> I0730 01:45:50.858012 21043 master.cpp:2125] Processing reply for offers:
> [ 20140730-014550-453759884-56984-20297-0 ] on slave
> 20140730-014550-453759884-56984-20297-0 at slave(196)@140.211.11.27:56984
> (hemera.apache.org) for framework
> 20140730-014550-453759884-56984-20297-0000
> I0730 01:45:50.858043 21043 master.cpp:2211] Authorizing framework
> principal 'test-principal' to launch task 1 as user 'jenkins'
> I0730 01:45:50.858552 21043 master.hpp:788] Adding task 1 with resources
> cpus(*):1; mem(*):512 on slave 20140730-014550-453759884-56984-20297-0 (
> hemera.apache.org)
> I0730 01:45:50.858578 21043 master.cpp:2277] Launching task 1 of framework
> 20140730-014550-453759884-56984-20297-0000 with resources cpus(*):1;
> mem(*):512 on slave 20140730-014550-453759884-56984-20297-0 at slave(196)@
> 140.211.11.27:56984 (hemera.apache.org)
> I0730 01:45:50.859840 21043 master.cpp:3126] Sending status update
> TASK_LOST (UUID: e40f0a64-232a-4036-9f3d-d0d76fbf5489) for task 2 of
> framework 20140730-014550-453759884-56984-20297-0000 'Task has invalid
> ExecutorInfo (existing ExecutorInfo with same ExecutorID is not compatible).
> ------------------------------------------------------------
> Existing ExecutorInfo:
> executor_id {
> value: "default"
> }
> command {
> value: "exit 1"
> }
> framework_id {
> value: "20140730-014550-453759884-56984-20297-0000"
> }
>
> ------------------------------------------------------------
> Task's ExecutorInfo:
> executor_id {
> value: "default"
> }
> command {
> value: "exit 2"
> }
> framework_id {
> value: "20140730-014550-453759884-56984-20297-0000"
> }
>
> ------------------------------------------------------------
> '
> I0730 01:45:50.860007 21043 slave.cpp:1003] Got assigned task 1 for
> framework 20140730-014550-453759884-56984-20297-0000
> I0730 01:45:50.860201 21043 slave.cpp:1113] Launching task 1 for framework
> 20140730-014550-453759884-56984-20297-0000
> I0730 01:45:50.860852 21048 hierarchical_allocator_process.hpp:546]
> Framework 20140730-014550-453759884-56984-20297-0000 left cpus(*):1;
> mem(*):512; disk(*):1024; ports(*):[31000-32000] unused on slave
> 20140730-014550-453759884-56984-20297-0
> I0730 01:45:50.860898 21050 sched.cpp:637] Scheduler::statusUpdate took
> 20007ns
> I0730 01:45:50.860951 21048 hierarchical_allocator_process.hpp:588]
> Framework 20140730-014550-453759884-56984-20297-0000 filtered slave
> 20140730-014550-453759884-56984-20297-0 for 5secs
> I0730 01:45:50.863068 21043 exec.cpp:131] Version: 0.20.0
> I0730 01:45:50.863153 21066 exec.cpp:181] Executor started at:
> executor(62)@140.211.11.27:56984 with pid 20297
> I0730 01:45:50.863199 21043 slave.cpp:1223] Queuing task '1' for executor
> default of framework '20140730-014550-453759884-56984-20297-0000
> I0730 01:45:50.863251 21043 slave.cpp:562] Successfully attached file
> '/tmp/MultipleExecutorsTest_ExecutorInfoDiffersOnSameSlave_3GakdP/slaves/20140730-014550-453759884-56984-20297-0/frameworks/20140730-014550-453759884-56984-20297-0000/executors/default/runs/974ced3f-ea41-4d3a-b2ff-b698de2a04f5'
> I0730 01:45:50.863275 21043 slave.cpp:2470] Monitoring executor 'default'
> of framework '20140730-014550-453759884-56984-20297-0000' in container
> '974ced3f-ea41-4d3a-b2ff-b698de2a04f5'
> I0730 01:45:50.863332 21043 slave.cpp:1734] Got registration for executor
> 'default' of framework 20140730-014550-453759884-56984-20297-0000
> I0730 01:45:50.863428 21043 slave.cpp:1853] Flushing queued task 1 for
> executor 'default' of framework 20140730-014550-453759884-56984-20297-0000
> I0730 01:45:50.863468 21066 exec.cpp:205] Executor registered on slave
> 20140730-014550-453759884-56984-20297-0
> I0730 01:45:50.864792 21066 exec.cpp:217] Executor::registered took 14731ns
> I0730 01:45:50.864850 21066 exec.cpp:292] Executor asked to run task '1'
> I0730 01:45:50.864889 21066 exec.cpp:301] Executor::launchTask took 31367ns
> I0730 01:45:50.865082 21056 sched.cpp:747] Stopping framework
> '20140730-014550-453759884-56984-20297-0000'
> I0730 01:45:50.865114 20297 master.cpp:626] Master terminating
> I0730 01:45:50.865159 20297 master.hpp:806] Removing task 1 with resources
> cpus(*):1; mem(*):512 on slave 20140730-014550-453759884-56984-20297-0 (
> hemera.apache.org)
> W0730 01:45:50.865206 20297 master.cpp:4261] Removing task 1 of framework
> 20140730-014550-453759884-56984-20297-0000 and slave
> 20140730-014550-453759884-56984-20297-0 in non-terminal state TASK_STAGING
> I0730 01:45:50.865272 21056 hierarchical_allocator_process.hpp:635]
> Recovered cpus(*):1; mem(*):512 (total allocatable: cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000]) on slave
> 20140730-014550-453759884-56984-20297-0 from framework
> 20140730-014550-453759884-56984-20297-0000
> I0730 01:45:50.865316 21056 slave.cpp:2332] master@140.211.11.27:56984
> exited
> W0730 01:45:50.865327 21056 slave.cpp:2335] Master disconnected! Waiting
> for a new master to be elected
> I0730 01:45:50.868448 21059 leveldb.cpp:343] Persisting action (18 bytes)
> to leveldb took 11.813287ms
> I0730 01:45:50.868496 21059 leveldb.cpp:401] Deleting ~2 keys from leveldb
> took 29354ns
> I0730 01:45:50.868510 21059 replica.cpp:676] Persisted action at 4
> I0730 01:45:50.868518 21059 replica.cpp:661] Replica learned TRUNCATE
> action at position 4
> I0730 01:45:50.868931 21054 slave.cpp:2528] Executor 'default' of
> framework 20140730-014550-453759884-56984-20297-0000 exited with status 0
> I0730 01:45:50.870251 21054 slave.cpp:2088] Handling status update
> TASK_LOST (UUID: eaa81f86-f3a0-4113-90ec-b486bea51c07) for task 1 of
> framework 20140730-014550-453759884-56984-20297-0000 from @0.0.0.0:0
> I0730 01:45:50.870280 21054 slave.cpp:3770] Terminating task 1
> I0730 01:45:50.870373 21054 slave.cpp:485] Slave terminating
> I0730 01:45:50.870385 21054 slave.cpp:1407] Asked to shut down framework
> 20140730-014550-453759884-56984-20297-0000 by @0.0.0.0:0
> I0730 01:45:50.870394 21054 slave.cpp:1432] Shutting down framework
> 20140730-014550-453759884-56984-20297-0000
> I0730 01:45:50.870405 21054 slave.cpp:2662] Cleaning up executor 'default'
> of framework 20140730-014550-453759884-56984-20297-0000
> I0730 01:45:50.870507 21054 slave.cpp:2737] Cleaning up framework
> 20140730-014550-453759884-56984-20297-0000
> I0730 01:45:50.870580 21054 gc.cpp:56] Scheduling
> '/tmp/MultipleExecutorsTest_ExecutorInfoDiffersOnSameSlave_3GakdP/slaves/20140730-014550-453759884-56984-20297-0/frameworks/20140730-014550-453759884-56984-20297-0000/executors/default/runs/974ced3f-ea41-4d3a-b2ff-b698de2a04f5'
> for gc 6.99998992539259days in the future
> I0730 01:45:50.870637 21054 gc.cpp:56] Scheduling
> '/tmp/MultipleExecutorsTest_ExecutorInfoDiffersOnSameSlave_3GakdP/slaves/20140730-014550-453759884-56984-20297-0/frameworks/20140730-014550-453759884-56984-20297-0000/executors/default'
> for gc 6.99998992483852days in the future
> I0730 01:45:50.870669 21054 gc.cpp:56] Scheduling
> '/tmp/MultipleExecutorsTest_ExecutorInfoDiffersOnSameSlave_3GakdP/slaves/20140730-014550-453759884-56984-20297-0/frameworks/20140730-014550-453759884-56984-20297-0000'
> for gc 6.99998992431704days in the future
> [ OK ] MultipleExecutorsTest.ExecutorInfoDiffersOnSameSlave (368 ms)
> [----------] 2 tests from MultipleExecutorsTest (809 ms total)
>
> [----------] 1 test from ZooKeeper
> [ RUN ] ZooKeeper.URL
> [ OK ] ZooKeeper.URL (0 ms)
> [----------] 1 test from ZooKeeper (0 ms total)
>
> [----------] Global test environment tear-down
> [==========] 352 tests from 57 test cases ran. (243846 ms total)
> [ PASSED ] 350 tests.
> [ FAILED ] 2 tests, listed below:
> [ FAILED ] SlaveRecoveryTest/0.KillTask, where TypeParam =
> mesos::internal::slave::MesosContainerizer
> [ FAILED ] SlaveRecoveryTest/0.MultipleSlaves, where TypeParam =
> mesos::internal::slave::MesosContainerizer
>
> 2 FAILED TESTS
> 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
>
Build failed in Jenkins:
Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2283
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/2283/changes>
Changes:
[dhamon] Converted bool returns to Try<Nothing> in stout/os.hpp.
[dhamon] Mesos converted to use Try<Nothing> returns from stout/os.hpp.
[bmahler] Cleaned up TODO comments for ZK file:// URL support.
[niklas] Task health status change notifications
[bmahler] Fixed a flaky slave recovery test.
[bmahler] Cleaned up the flag help documentation.
------------------------------------------
[...truncated 55276 lines...]
I0730 01:45:50.575980 21067 recover.cpp:451] Replica is in EMPTY status
I0730 01:45:50.576040 21067 registrar.cpp:313] Recovering registrar
I0730 01:45:50.576530 21067 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
I0730 01:45:50.576594 21067 recover.cpp:188] Received a recover response from a replica in EMPTY status
I0730 01:45:50.576704 21067 recover.cpp:542] Updating replica status to STARTING
I0730 01:45:50.589684 21067 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 12.903968ms
I0730 01:45:50.589740 21067 replica.cpp:320] Persisted replica status to STARTING
I0730 01:45:50.589856 21067 recover.cpp:451] Replica is in STARTING status
I0730 01:45:50.590235 21067 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
I0730 01:45:50.590301 21067 recover.cpp:188] Received a recover response from a replica in STARTING status
I0730 01:45:50.590409 21067 recover.cpp:542] Updating replica status to VOTING
I0730 01:45:50.613689 21067 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 23.214235ms
I0730 01:45:50.613843 21067 replica.cpp:320] Persisted replica status to VOTING
I0730 01:45:50.613976 21067 recover.cpp:556] Successfully joined the Paxos group
I0730 01:45:50.614120 21067 recover.cpp:440] Recover process terminated
I0730 01:45:50.614296 21047 log.cpp:656] Attempting to start the writer
I0730 01:45:50.614717 21047 replica.cpp:474] Replica received implicit promise request with proposal 1
I0730 01:45:50.629683 21047 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 14.941262ms
I0730 01:45:50.629734 21047 replica.cpp:342] Persisted promised to 1
I0730 01:45:50.629991 21047 coordinator.cpp:230] Coordinator attemping to fill missing position
I0730 01:45:50.630377 21047 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I0730 01:45:50.645654 21047 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 15.245725ms
I0730 01:45:50.645709 21047 replica.cpp:676] Persisted action at 0
I0730 01:45:50.646080 21047 replica.cpp:508] Replica received write request for position 0
I0730 01:45:50.646106 21047 leveldb.cpp:438] Reading position from leveldb took 14660ns
I0730 01:45:50.665685 21047 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 19.555587ms
I0730 01:45:50.665740 21047 replica.cpp:676] Persisted action at 0
I0730 01:45:50.665961 21047 replica.cpp:655] Replica received learned notice for position 0
I0730 01:45:50.681684 21047 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 15.693681ms
I0730 01:45:50.681733 21047 replica.cpp:676] Persisted action at 0
I0730 01:45:50.681743 21047 replica.cpp:661] Replica learned NOP action at position 0
I0730 01:45:50.681982 21047 log.cpp:672] Writer started with ending position 0
I0730 01:45:50.682251 21047 leveldb.cpp:438] Reading position from leveldb took 17318ns
I0730 01:45:50.683776 21047 registrar.cpp:346] Successfully fetched the registry (0B)
I0730 01:45:50.683795 21047 registrar.cpp:422] Attempting to update the 'registry'
I0730 01:45:50.685314 21047 log.cpp:680] Attempting to append 138 bytes to the log
I0730 01:45:50.685358 21047 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I0730 01:45:50.685586 21047 replica.cpp:508] Replica received write request for position 1
I0730 01:45:50.705683 21047 leveldb.cpp:343] Persisting action (157 bytes) to leveldb took 20.07148ms
I0730 01:45:50.705734 21047 replica.cpp:676] Persisted action at 1
I0730 01:45:50.706009 21047 replica.cpp:655] Replica received learned notice for position 1
I0730 01:45:50.725682 21047 leveldb.cpp:343] Persisting action (159 bytes) to leveldb took 19.646881ms
I0730 01:45:50.725733 21047 replica.cpp:676] Persisted action at 1
I0730 01:45:50.725744 21047 replica.cpp:661] Replica learned APPEND action at position 1
I0730 01:45:50.726102 21047 registrar.cpp:479] Successfully updated 'registry'
I0730 01:45:50.726141 21047 registrar.cpp:372] Successfully recovered registrar
I0730 01:45:50.726182 21047 log.cpp:699] Attempting to truncate the log to 1
I0730 01:45:50.726256 21047 master.cpp:987] Recovered 0 slaves from the Registry (100B) ; allowing 10mins for slaves to re-register
I0730 01:45:50.726294 21047 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I0730 01:45:50.726553 21047 replica.cpp:508] Replica received write request for position 2
I0730 01:45:50.745668 21047 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 19.095229ms
I0730 01:45:50.745703 21047 replica.cpp:676] Persisted action at 2
I0730 01:45:50.745935 21047 replica.cpp:655] Replica received learned notice for position 2
I0730 01:45:50.759333 21047 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 13.382009ms
I0730 01:45:50.759376 21047 leveldb.cpp:401] Deleting ~1 keys from leveldb took 18643ns
I0730 01:45:50.759385 21047 replica.cpp:676] Persisted action at 2
I0730 01:45:50.759394 21047 replica.cpp:661] Replica learned TRUNCATE action at position 2
I0730 01:45:50.769793 21060 slave.cpp:169] Slave started on 196)@140.211.11.27:56984
I0730 01:45:50.769820 21060 credentials.hpp:84] Loading credential for authentication from '/tmp/MultipleExecutorsTest_ExecutorInfoDiffersOnSameSlave_3GakdP/credential'
I0730 01:45:50.769920 21060 slave.cpp:267] Slave using credential for: test-principal
I0730 01:45:50.770030 21060 slave.cpp:280] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0730 01:45:50.771483 20297 sched.cpp:139] Version: 0.20.0
I0730 01:45:50.771796 21054 sched.cpp:235] New master detected at master@140.211.11.27:56984
I0730 01:45:50.771821 21054 sched.cpp:285] Authenticating with master master@140.211.11.27:56984
I0730 01:45:50.771909 21054 authenticatee.hpp:128] Creating new client SASL connection
I0730 01:45:50.772047 21054 master.cpp:3504] Authenticating scheduler-f1390c07-a5e1-4562-b565-7f44c02b35cf@140.211.11.27:56984
I0730 01:45:50.772128 21054 authenticator.hpp:156] Creating new server SASL connection
I0730 01:45:50.772212 21054 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0730 01:45:50.772228 21054 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0730 01:45:50.772251 21054 authenticator.hpp:262] Received SASL authentication start
I0730 01:45:50.772286 21054 authenticator.hpp:384] Authentication requires more steps
I0730 01:45:50.772310 21054 authenticatee.hpp:265] Received SASL authentication step
I0730 01:45:50.772341 21054 authenticator.hpp:290] Received SASL authentication step
I0730 01:45:50.772356 21054 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
I0730 01:45:50.772362 21054 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0730 01:45:50.772372 21054 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0730 01:45:50.772382 21054 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
I0730 01:45:50.772387 21054 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0730 01:45:50.772392 21054 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0730 01:45:50.772403 21054 authenticator.hpp:376] Authentication success
I0730 01:45:50.772428 21054 authenticatee.hpp:305] Authentication success
I0730 01:45:50.772447 21054 master.cpp:3544] Successfully authenticated principal 'test-principal' at scheduler-f1390c07-a5e1-4562-b565-7f44c02b35cf@140.211.11.27:56984
I0730 01:45:50.772512 21054 sched.cpp:359] Successfully authenticated with master master@140.211.11.27:56984
I0730 01:45:50.772522 21054 sched.cpp:478] Sending registration request to master@140.211.11.27:56984
I0730 01:45:50.772570 21054 master.cpp:1248] Received registration request from scheduler-f1390c07-a5e1-4562-b565-7f44c02b35cf@140.211.11.27:56984
I0730 01:45:50.772588 21054 master.cpp:1208] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0730 01:45:50.772685 21054 master.cpp:1307] Registering framework 20140730-014550-453759884-56984-20297-0000 at scheduler-f1390c07-a5e1-4562-b565-7f44c02b35cf@140.211.11.27:56984
I0730 01:45:50.772768 21054 sched.cpp:409] Framework registered with 20140730-014550-453759884-56984-20297-0000
I0730 01:45:50.772786 21054 sched.cpp:423] Scheduler::registered took 9142ns
I0730 01:45:50.772819 21054 hierarchical_allocator_process.hpp:331] Added framework 20140730-014550-453759884-56984-20297-0000
I0730 01:45:50.772826 21054 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0730 01:45:50.772831 21054 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 5748ns
I0730 01:45:50.772984 21060 slave.cpp:325] Slave hostname: hemera.apache.org
I0730 01:45:50.772997 21060 slave.cpp:326] Slave checkpoint: false
I0730 01:45:50.773510 21060 state.cpp:33] Recovering state from '/tmp/MultipleExecutorsTest_ExecutorInfoDiffersOnSameSlave_3GakdP/meta'
I0730 01:45:50.773612 21060 status_update_manager.cpp:193] Recovering status update manager
I0730 01:45:50.777725 21060 slave.cpp:3128] Finished recovery
I0730 01:45:50.777956 21060 slave.cpp:601] New master detected at master@140.211.11.27:56984
I0730 01:45:50.777978 21060 slave.cpp:677] Authenticating with master master@140.211.11.27:56984
I0730 01:45:50.778020 21060 slave.cpp:650] Detecting new master
I0730 01:45:50.778059 21060 status_update_manager.cpp:167] New master detected at master@140.211.11.27:56984
I0730 01:45:50.778091 21060 authenticatee.hpp:128] Creating new client SASL connection
I0730 01:45:50.778219 21060 master.cpp:3504] Authenticating slave(196)@140.211.11.27:56984
I0730 01:45:50.778297 21060 authenticator.hpp:156] Creating new server SASL connection
I0730 01:45:50.778384 21060 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0730 01:45:50.778400 21060 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0730 01:45:50.778425 21060 authenticator.hpp:262] Received SASL authentication start
I0730 01:45:50.778457 21060 authenticator.hpp:384] Authentication requires more steps
I0730 01:45:50.778489 21060 authenticatee.hpp:265] Received SASL authentication step
I0730 01:45:50.778524 21060 authenticator.hpp:290] Received SASL authentication step
I0730 01:45:50.778537 21060 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
I0730 01:45:50.778544 21060 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0730 01:45:50.778554 21060 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0730 01:45:50.778563 21060 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
I0730 01:45:50.778568 21060 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0730 01:45:50.778573 21060 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0730 01:45:50.778584 21060 authenticator.hpp:376] Authentication success
I0730 01:45:50.778610 21060 authenticatee.hpp:305] Authentication success
I0730 01:45:50.778633 21060 master.cpp:3544] Successfully authenticated principal 'test-principal' at slave(196)@140.211.11.27:56984
I0730 01:45:50.778698 21060 slave.cpp:734] Successfully authenticated with master master@140.211.11.27:56984
I0730 01:45:50.778740 21060 slave.cpp:972] Will retry registration in 4.823399ms if necessary
I0730 01:45:50.778812 21060 master.cpp:2762] Registering slave at slave(196)@140.211.11.27:56984 (hemera.apache.org) with id 20140730-014550-453759884-56984-20297-0
I0730 01:45:50.778924 21060 registrar.cpp:422] Attempting to update the 'registry'
I0730 01:45:50.780408 21060 log.cpp:680] Attempting to append 332 bytes to the log
I0730 01:45:50.780468 21060 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I0730 01:45:50.780742 21060 replica.cpp:508] Replica received write request for position 3
I0730 01:45:50.789727 21052 slave.cpp:972] Will retry registration in 4.307262ms if necessary
I0730 01:45:50.789796 21052 master.cpp:2750] Ignoring register slave message from slave(196)@140.211.11.27:56984 (hemera.apache.org) as admission is already in progress
I0730 01:45:50.797801 21056 slave.cpp:972] Will retry registration in 59.396428ms if necessary
I0730 01:45:50.797901 21056 master.cpp:2750] Ignoring register slave message from slave(196)@140.211.11.27:56984 (hemera.apache.org) as admission is already in progress
I0730 01:45:50.829689 21060 leveldb.cpp:343] Persisting action (351 bytes) to leveldb took 48.916641ms
I0730 01:45:50.829848 21060 replica.cpp:676] Persisted action at 3
I0730 01:45:50.830270 21056 replica.cpp:655] Replica received learned notice for position 3
I0730 01:45:50.844269 21056 leveldb.cpp:343] Persisting action (353 bytes) to leveldb took 13.969906ms
I0730 01:45:50.844316 21056 replica.cpp:676] Persisted action at 3
I0730 01:45:50.844327 21056 replica.cpp:661] Replica learned APPEND action at position 3
I0730 01:45:50.844794 21056 registrar.cpp:479] Successfully updated 'registry'
I0730 01:45:50.844884 21056 log.cpp:699] Attempting to truncate the log to 3
I0730 01:45:50.844950 21056 master.cpp:2802] Registered slave 20140730-014550-453759884-56984-20297-0 at slave(196)@140.211.11.27:56984 (hemera.apache.org)
I0730 01:45:50.844964 21056 master.cpp:3972] Adding slave 20140730-014550-453759884-56984-20297-0 at slave(196)@140.211.11.27:56984 (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0730 01:45:50.845087 21056 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I0730 01:45:50.845166 21056 slave.cpp:768] Registered with master master@140.211.11.27:56984; given slave ID 20140730-014550-453759884-56984-20297-0
I0730 01:45:50.845237 21056 hierarchical_allocator_process.hpp:444] Added slave 20140730-014550-453759884-56984-20297-0 (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
I0730 01:45:50.845298 21056 hierarchical_allocator_process.hpp:750] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140730-014550-453759884-56984-20297-0 to framework 20140730-014550-453759884-56984-20297-0000
I0730 01:45:50.845402 21056 hierarchical_allocator_process.hpp:706] Performed allocation for slave 20140730-014550-453759884-56984-20297-0 in 134270ns
I0730 01:45:50.845455 21056 slave.cpp:2325] Received ping from slave-observer(165)@140.211.11.27:56984
I0730 01:45:50.845512 21056 master.hpp:816] Adding offer 20140730-014550-453759884-56984-20297-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140730-014550-453759884-56984-20297-0 (hemera.apache.org)
I0730 01:45:50.845554 21056 master.cpp:3451] Sending 1 offers to framework 20140730-014550-453759884-56984-20297-0000
I0730 01:45:50.845746 21056 sched.cpp:546] Scheduler::resourceOffers took 31773ns
I0730 01:45:50.846127 21059 replica.cpp:508] Replica received write request for position 4
I0730 01:45:50.856356 21059 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 10.20412ms
I0730 01:45:50.856395 21059 replica.cpp:676] Persisted action at 4
I0730 01:45:50.856613 21059 replica.cpp:655] Replica received learned notice for position 4
I0730 01:45:50.857946 21043 master.hpp:826] Removing offer 20140730-014550-453759884-56984-20297-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140730-014550-453759884-56984-20297-0 (hemera.apache.org)
I0730 01:45:50.858012 21043 master.cpp:2125] Processing reply for offers: [ 20140730-014550-453759884-56984-20297-0 ] on slave 20140730-014550-453759884-56984-20297-0 at slave(196)@140.211.11.27:56984 (hemera.apache.org) for framework 20140730-014550-453759884-56984-20297-0000
I0730 01:45:50.858043 21043 master.cpp:2211] Authorizing framework principal 'test-principal' to launch task 1 as user 'jenkins'
I0730 01:45:50.858552 21043 master.hpp:788] Adding task 1 with resources cpus(*):1; mem(*):512 on slave 20140730-014550-453759884-56984-20297-0 (hemera.apache.org)
I0730 01:45:50.858578 21043 master.cpp:2277] Launching task 1 of framework 20140730-014550-453759884-56984-20297-0000 with resources cpus(*):1; mem(*):512 on slave 20140730-014550-453759884-56984-20297-0 at slave(196)@140.211.11.27:56984 (hemera.apache.org)
I0730 01:45:50.859840 21043 master.cpp:3126] Sending status update TASK_LOST (UUID: e40f0a64-232a-4036-9f3d-d0d76fbf5489) for task 2 of framework 20140730-014550-453759884-56984-20297-0000 'Task has invalid ExecutorInfo (existing ExecutorInfo with same ExecutorID is not compatible).
------------------------------------------------------------
Existing ExecutorInfo:
executor_id {
value: "default"
}
command {
value: "exit 1"
}
framework_id {
value: "20140730-014550-453759884-56984-20297-0000"
}
------------------------------------------------------------
Task's ExecutorInfo:
executor_id {
value: "default"
}
command {
value: "exit 2"
}
framework_id {
value: "20140730-014550-453759884-56984-20297-0000"
}
------------------------------------------------------------
'
I0730 01:45:50.860007 21043 slave.cpp:1003] Got assigned task 1 for framework 20140730-014550-453759884-56984-20297-0000
I0730 01:45:50.860201 21043 slave.cpp:1113] Launching task 1 for framework 20140730-014550-453759884-56984-20297-0000
I0730 01:45:50.860852 21048 hierarchical_allocator_process.hpp:546] Framework 20140730-014550-453759884-56984-20297-0000 left cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000] unused on slave 20140730-014550-453759884-56984-20297-0
I0730 01:45:50.860898 21050 sched.cpp:637] Scheduler::statusUpdate took 20007ns
I0730 01:45:50.860951 21048 hierarchical_allocator_process.hpp:588] Framework 20140730-014550-453759884-56984-20297-0000 filtered slave 20140730-014550-453759884-56984-20297-0 for 5secs
I0730 01:45:50.863068 21043 exec.cpp:131] Version: 0.20.0
I0730 01:45:50.863153 21066 exec.cpp:181] Executor started at: executor(62)@140.211.11.27:56984 with pid 20297
I0730 01:45:50.863199 21043 slave.cpp:1223] Queuing task '1' for executor default of framework '20140730-014550-453759884-56984-20297-0000
I0730 01:45:50.863251 21043 slave.cpp:562] Successfully attached file '/tmp/MultipleExecutorsTest_ExecutorInfoDiffersOnSameSlave_3GakdP/slaves/20140730-014550-453759884-56984-20297-0/frameworks/20140730-014550-453759884-56984-20297-0000/executors/default/runs/974ced3f-ea41-4d3a-b2ff-b698de2a04f5'
I0730 01:45:50.863275 21043 slave.cpp:2470] Monitoring executor 'default' of framework '20140730-014550-453759884-56984-20297-0000' in container '974ced3f-ea41-4d3a-b2ff-b698de2a04f5'
I0730 01:45:50.863332 21043 slave.cpp:1734] Got registration for executor 'default' of framework 20140730-014550-453759884-56984-20297-0000
I0730 01:45:50.863428 21043 slave.cpp:1853] Flushing queued task 1 for executor 'default' of framework 20140730-014550-453759884-56984-20297-0000
I0730 01:45:50.863468 21066 exec.cpp:205] Executor registered on slave 20140730-014550-453759884-56984-20297-0
I0730 01:45:50.864792 21066 exec.cpp:217] Executor::registered took 14731ns
I0730 01:45:50.864850 21066 exec.cpp:292] Executor asked to run task '1'
I0730 01:45:50.864889 21066 exec.cpp:301] Executor::launchTask took 31367ns
I0730 01:45:50.865082 21056 sched.cpp:747] Stopping framework '20140730-014550-453759884-56984-20297-0000'
I0730 01:45:50.865114 20297 master.cpp:626] Master terminating
I0730 01:45:50.865159 20297 master.hpp:806] Removing task 1 with resources cpus(*):1; mem(*):512 on slave 20140730-014550-453759884-56984-20297-0 (hemera.apache.org)
W0730 01:45:50.865206 20297 master.cpp:4261] Removing task 1 of framework 20140730-014550-453759884-56984-20297-0000 and slave 20140730-014550-453759884-56984-20297-0 in non-terminal state TASK_STAGING
I0730 01:45:50.865272 21056 hierarchical_allocator_process.hpp:635] Recovered cpus(*):1; mem(*):512 (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20140730-014550-453759884-56984-20297-0 from framework 20140730-014550-453759884-56984-20297-0000
I0730 01:45:50.865316 21056 slave.cpp:2332] master@140.211.11.27:56984 exited
W0730 01:45:50.865327 21056 slave.cpp:2335] Master disconnected! Waiting for a new master to be elected
I0730 01:45:50.868448 21059 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 11.813287ms
I0730 01:45:50.868496 21059 leveldb.cpp:401] Deleting ~2 keys from leveldb took 29354ns
I0730 01:45:50.868510 21059 replica.cpp:676] Persisted action at 4
I0730 01:45:50.868518 21059 replica.cpp:661] Replica learned TRUNCATE action at position 4
I0730 01:45:50.868931 21054 slave.cpp:2528] Executor 'default' of framework 20140730-014550-453759884-56984-20297-0000 exited with status 0
I0730 01:45:50.870251 21054 slave.cpp:2088] Handling status update TASK_LOST (UUID: eaa81f86-f3a0-4113-90ec-b486bea51c07) for task 1 of framework 20140730-014550-453759884-56984-20297-0000 from @0.0.0.0:0
I0730 01:45:50.870280 21054 slave.cpp:3770] Terminating task 1
I0730 01:45:50.870373 21054 slave.cpp:485] Slave terminating
I0730 01:45:50.870385 21054 slave.cpp:1407] Asked to shut down framework 20140730-014550-453759884-56984-20297-0000 by @0.0.0.0:0
I0730 01:45:50.870394 21054 slave.cpp:1432] Shutting down framework 20140730-014550-453759884-56984-20297-0000
I0730 01:45:50.870405 21054 slave.cpp:2662] Cleaning up executor 'default' of framework 20140730-014550-453759884-56984-20297-0000
I0730 01:45:50.870507 21054 slave.cpp:2737] Cleaning up framework 20140730-014550-453759884-56984-20297-0000
I0730 01:45:50.870580 21054 gc.cpp:56] Scheduling '/tmp/MultipleExecutorsTest_ExecutorInfoDiffersOnSameSlave_3GakdP/slaves/20140730-014550-453759884-56984-20297-0/frameworks/20140730-014550-453759884-56984-20297-0000/executors/default/runs/974ced3f-ea41-4d3a-b2ff-b698de2a04f5' for gc 6.99998992539259days in the future
I0730 01:45:50.870637 21054 gc.cpp:56] Scheduling '/tmp/MultipleExecutorsTest_ExecutorInfoDiffersOnSameSlave_3GakdP/slaves/20140730-014550-453759884-56984-20297-0/frameworks/20140730-014550-453759884-56984-20297-0000/executors/default' for gc 6.99998992483852days in the future
I0730 01:45:50.870669 21054 gc.cpp:56] Scheduling '/tmp/MultipleExecutorsTest_ExecutorInfoDiffersOnSameSlave_3GakdP/slaves/20140730-014550-453759884-56984-20297-0/frameworks/20140730-014550-453759884-56984-20297-0000' for gc 6.99998992431704days in the future
[ OK ] MultipleExecutorsTest.ExecutorInfoDiffersOnSameSlave (368 ms)
[----------] 2 tests from MultipleExecutorsTest (809 ms total)
[----------] 1 test from ZooKeeper
[ RUN ] ZooKeeper.URL
[ OK ] ZooKeeper.URL (0 ms)
[----------] 1 test from ZooKeeper (0 ms total)
[----------] Global test environment tear-down
[==========] 352 tests from 57 test cases ran. (243846 ms total)
[ PASSED ] 350 tests.
[ FAILED ] 2 tests, listed below:
[ FAILED ] SlaveRecoveryTest/0.KillTask, where TypeParam = mesos::internal::slave::MesosContainerizer
[ FAILED ] SlaveRecoveryTest/0.MultipleSlaves, where TypeParam = mesos::internal::slave::MesosContainerizer
2 FAILED TESTS
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
Re: Build failed in Jenkins: Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2282
Posted by Benjamin Mahler <be...@gmail.com>.
Committed a fix here:
commit 444c60beac5625e22dac99a059d782e662379091
Author: Benjamin Mahler <bm...@twitter.com>
Date: Tue Jul 29 16:00:57 2014 -0700
Fixed a flaky slave recovery test.
diff --git a/src/tests/slave_recovery_tests.cpp
b/src/tests/slave_recovery_tests.cpp
index d024bd9..68ea3a2 100644
--- a/src/tests/slave_recovery_tests.cpp
+++ b/src/tests/slave_recovery_tests.cpp
@@ -2439,6 +2439,9 @@ TYPED_TEST(SlaveRecoveryTest, SchedulerFailover)
Future<Nothing> _recover = FUTURE_DISPATCH(_, &Slave::_recover);
+ Future<ReregisterExecutorMessage> reregisterExecutorMessage =
+ FUTURE_PROTOBUF(ReregisterExecutorMessage(), _, _);
+
Future<SlaveReregisteredMessage> slaveReregisteredMessage =
FUTURE_PROTOBUF(SlaveReregisteredMessage(), _, _);
@@ -2453,6 +2456,9 @@ TYPED_TEST(SlaveRecoveryTest, SchedulerFailover)
AWAIT_READY(_recover);
+ // Wait for the executor to re-register.
+ AWAIT_READY(reregisterExecutorMessage);
+
Clock::settle(); // Wait for slave to schedule reregister timeout.
Clock::advance(EXECUTOR_REREGISTER_TIMEOUT);
On Tue, Jul 29, 2014 at 2: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/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
>