You are viewing a plain text version of this content. The canonical link for it is here.
Posted to builds@mesos.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2016/01/07 23:09:43 UTC
Build failed in Jenkins: Mesos » gcc,--verbose --enable-libevent --enable-ssl,centos:7,docker||Hadoop #1456
See <https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose%20--enable-libevent%20--enable-ssl,OS=centos%3A7,label_exp=docker%7C%7CHadoop/1456/changes>
Changes:
[yujie.jay] Fixed handling of failed authorization for (un)reserve operations.
[yujie.jay] Fixed race in persistent volume tests.
[yujie.jay] Added docs for persistent volume endpoint authorization.
------------------------------------------
[...truncated 126811 lines...]
I0107 22:09:30.054131 1378 replica.cpp:697] Replica learned APPEND action at position 3
I0107 22:09:30.055318 1364 registrar.cpp:484] Successfully updated the 'registry' in 4.043008ms
I0107 22:09:30.055572 1373 log.cpp:702] Attempting to truncate the log to 3
I0107 22:09:30.055784 1375 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
I0107 22:09:30.055809 1366 slave.cpp:1254] Will retry registration in 28.106144ms if necessary
I0107 22:09:30.056504 1370 slave.cpp:3371] Received ping from slave-observer(327)@172.17.0.3:45238
I0107 22:09:30.056567 1368 replica.cpp:537] Replica received write request for position 4 from (10162)@172.17.0.3:45238
I0107 22:09:30.056620 1369 master.cpp:4222] Registered slave 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0 at slave(345)@172.17.0.3:45238 (e70672e666f9) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0107 22:09:30.056828 1369 master.cpp:4124] Slave 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0 at slave(345)@172.17.0.3:45238 (e70672e666f9) already registered, resending acknowledgement
I0107 22:09:30.057077 1368 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 393985ns
I0107 22:09:30.057106 1368 replica.cpp:712] Persisted action at 4
I0107 22:09:30.057241 1365 hierarchical.cpp:465] Added slave 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0 (e70672e666f9) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
I0107 22:09:30.057461 1370 slave.cpp:904] Registered with master master@172.17.0.3:45238; given slave ID 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0
I0107 22:09:30.057484 1370 fetcher.cpp:81] Clearing fetcher cache
I0107 22:09:30.057886 1372 status_update_manager.cpp:181] Resuming sending status updates
I0107 22:09:30.058130 1370 slave.cpp:927] Checkpointing SlaveInfo to '/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_lX8H7C/meta/slaves/7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0/slave.info'
I0107 22:09:30.058583 1370 slave.cpp:963] Forwarding total oversubscribed resources
W0107 22:09:30.058691 1370 slave.cpp:949] Already registered with master master@172.17.0.3:45238
I0107 22:09:30.058717 1370 slave.cpp:963] Forwarding total oversubscribed resources
I0107 22:09:30.058797 1370 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
I0107 22:09:30.058977 1378 master.cpp:4564] Received update of slave 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0 at slave(345)@172.17.0.3:45238 (e70672e666f9) with total oversubscribed resources
I0107 22:09:30.059172 1378 master.cpp:4564] Received update of slave 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0 at slave(345)@172.17.0.3:45238 (e70672e666f9) with total oversubscribed resources
I0107 22:09:30.060096 1365 hierarchical.cpp:1423] No inverse offers to send out!
I0107 22:09:30.060138 1365 hierarchical.cpp:1101] Performed allocation for slave 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0 in 2.844428ms
I0107 22:09:30.060431 1370 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 1.604179ms
I0107 22:09:30.060508 1370 leveldb.cpp:399] Deleting ~2 keys from leveldb took 42714ns
I0107 22:09:30.060533 1370 replica.cpp:712] Persisted action at 4
I0107 22:09:30.060555 1370 replica.cpp:697] Replica learned TRUNCATE action at position 4
I0107 22:09:30.060824 1365 hierarchical.cpp:521] Slave 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0 (e70672e666f9) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
I0107 22:09:30.060982 1365 hierarchical.cpp:1329] No resources available to allocate!
I0107 22:09:30.061022 1365 hierarchical.cpp:1423] No inverse offers to send out!
I0107 22:09:30.061043 1365 hierarchical.cpp:1101] Performed allocation for slave 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0 in 171644ns
I0107 22:09:30.061496 1365 hierarchical.cpp:521] Slave 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0 (e70672e666f9) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
I0107 22:09:30.061653 1365 hierarchical.cpp:1329] No resources available to allocate!
I0107 22:09:30.061693 1365 hierarchical.cpp:1423] No inverse offers to send out!
I0107 22:09:30.061714 1365 hierarchical.cpp:1101] Performed allocation for slave 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0 in 170348ns
I0107 22:09:30.063616 1369 master.cpp:5274] Sending 1 offers to framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 (default) at scheduler-45fb2d87-20ce-4364-96d8-df8e14bdaad8@172.17.0.3:45238
I0107 22:09:30.064155 1376 resources.cpp:481] Parsing resources as JSON failed: cpus:1;mem:64
Trying semicolon-delimited string format instead
I0107 22:09:30.065156 1376 sched.cpp:819] Scheduler::resourceOffers took 1.075571ms
I0107 22:09:30.066092 1369 master.cpp:3055] Processing ACCEPT call for offers: [ 7d0a14fb-e4c2-40c7-b8da-607deaba6261-O0 ] on slave 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0 at slave(345)@172.17.0.3:45238 (e70672e666f9) for framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 (default) at scheduler-45fb2d87-20ce-4364-96d8-df8e14bdaad8@172.17.0.3:45238
I0107 22:09:30.066133 1369 master.cpp:2742] Authorizing framework principal 'test-principal' to launch task 0 as user 'mesos'
W0107 22:09:30.067205 1369 validation.cpp:420] Executor default for task 0 uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases.
W0107 22:09:30.067241 1369 validation.cpp:432] Executor default for task 0 uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases.
I0107 22:09:30.067447 1369 master.hpp:176] Adding task 0 with resources cpus(*):1; mem(*):64 on slave 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0 (e70672e666f9)
I0107 22:09:30.067528 1369 master.cpp:3540] Launching task 0 of framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 (default) at scheduler-45fb2d87-20ce-4364-96d8-df8e14bdaad8@172.17.0.3:45238 with resources cpus(*):1; mem(*):64 on slave 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0 at slave(345)@172.17.0.3:45238 (e70672e666f9)
I0107 22:09:30.067801 1378 slave.cpp:1294] Got assigned task 0 for framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000
I0107 22:09:30.068208 1378 slave.cpp:1413] Launching task 0 for framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000
I0107 22:09:30.068167 1375 hierarchical.cpp:880] Recovered cpus(*):1; mem(*):960; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):64) on slave 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0 from framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000
I0107 22:09:30.068277 1375 hierarchical.cpp:917] Framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 filtered slave 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0 for 5secs
I0107 22:09:30.068776 1378 paths.cpp:434] Trying to chown '/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_lX8H7C/slaves/7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0/frameworks/7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000/executors/default/runs/d6f78025-91b4-469b-9d6e-c6afea5c20ff' to user 'mesos'
I0107 22:09:30.076092 1378 slave.cpp:5213] Launching executor default of framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 with resources in work directory '/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_lX8H7C/slaves/7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0/frameworks/7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000/executors/default/runs/d6f78025-91b4-469b-9d6e-c6afea5c20ff'
I0107 22:09:30.078622 1378 exec.cpp:134] Version: 0.27.0
I0107 22:09:30.079071 1373 exec.cpp:184] Executor started at: executor(98)@172.17.0.3:45238 with pid 1344
I0107 22:09:30.079438 1378 slave.cpp:1631] Queuing task '0' for executor 'default' of framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000
I0107 22:09:30.079707 1378 slave.cpp:682] Successfully attached file '/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_lX8H7C/slaves/7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0/frameworks/7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000/executors/default/runs/d6f78025-91b4-469b-9d6e-c6afea5c20ff'
I0107 22:09:30.079830 1378 slave.cpp:2578] Got registration for executor 'default' of framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 from executor(98)@172.17.0.3:45238
I0107 22:09:30.080334 1373 exec.cpp:208] Executor registered on slave 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0
I0107 22:09:30.080415 1373 exec.cpp:220] Executor::registered took 49330ns
I0107 22:09:30.080893 1378 slave.cpp:1796] Sending queued task '0' to executor 'default' of framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 at executor(98)@172.17.0.3:45238
I0107 22:09:30.081296 1371 exec.cpp:295] Executor asked to run task '0'
I0107 22:09:30.081436 1371 exec.cpp:304] Executor::launchTask took 96434ns
I0107 22:09:30.081553 1371 exec.cpp:517] Executor sending status update TASK_RUNNING (UUID: 9af70ee9-254b-4774-9ba9-25ec36991965) for task 0 of framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000
I0107 22:09:30.081877 1378 slave.cpp:2937] Handling status update TASK_RUNNING (UUID: 9af70ee9-254b-4774-9ba9-25ec36991965) for task 0 of framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 from executor(98)@172.17.0.3:45238
I0107 22:09:30.082253 1373 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 9af70ee9-254b-4774-9ba9-25ec36991965) for task 0 of framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000
I0107 22:09:30.082300 1373 status_update_manager.cpp:497] Creating StatusUpdate stream for task 0 of framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000
I0107 22:09:30.082908 1373 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: 9af70ee9-254b-4774-9ba9-25ec36991965) for task 0 of framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 to the slave
I0107 22:09:30.083287 1365 slave.cpp:3289] Forwarding the update TASK_RUNNING (UUID: 9af70ee9-254b-4774-9ba9-25ec36991965) for task 0 of framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 to master@172.17.0.3:45238
I0107 22:09:30.083608 1365 slave.cpp:3183] Status update manager successfully handled status update TASK_RUNNING (UUID: 9af70ee9-254b-4774-9ba9-25ec36991965) for task 0 of framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000
I0107 22:09:30.083669 1365 slave.cpp:3199] Sending acknowledgement for status update TASK_RUNNING (UUID: 9af70ee9-254b-4774-9ba9-25ec36991965) for task 0 of framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 to executor(98)@172.17.0.3:45238
I0107 22:09:30.083860 1365 exec.cpp:341] Executor received status update acknowledgement 9af70ee9-254b-4774-9ba9-25ec36991965 for task 0 of framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000
I0107 22:09:30.084127 1370 master.cpp:4709] Status update TASK_RUNNING (UUID: 9af70ee9-254b-4774-9ba9-25ec36991965) for task 0 of framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 from slave 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0 at slave(345)@172.17.0.3:45238 (e70672e666f9)
I0107 22:09:30.084180 1370 master.cpp:4757] Forwarding status update TASK_RUNNING (UUID: 9af70ee9-254b-4774-9ba9-25ec36991965) for task 0 of framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000
I0107 22:09:30.084501 1370 master.cpp:6369] Updating the state of task 0 of framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I0107 22:09:30.084816 1365 sched.cpp:927] Scheduler::statusUpdate took 169602ns
I0107 22:09:30.085441 1374 master.cpp:3866] Processing ACKNOWLEDGE call 9af70ee9-254b-4774-9ba9-25ec36991965 for task 0 of framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 (default) at scheduler-45fb2d87-20ce-4364-96d8-df8e14bdaad8@172.17.0.3:45238 on slave 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0
I0107 22:09:30.085912 1365 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 9af70ee9-254b-4774-9ba9-25ec36991965) for task 0 of framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000
I0107 22:09:30.086360 1365 slave.cpp:2348] Status update manager successfully handled status update acknowledgement (UUID: 9af70ee9-254b-4774-9ba9-25ec36991965) for task 0 of framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000
I0107 22:09:30.086745 1375 status_update_manager.cpp:174] Pausing sending status updates
I0107 22:09:30.086771 1363 slave.cpp:729] New master detected at master@172.17.0.3:45238
I0107 22:09:30.086843 1363 slave.cpp:792] Authenticating with master master@172.17.0.3:45238
I0107 22:09:30.086866 1363 slave.cpp:797] Using default CRAM-MD5 authenticatee
I0107 22:09:30.087081 1363 slave.cpp:765] Detecting new master
I0107 22:09:30.087340 1376 authenticatee.cpp:121] Creating new client SASL connection
I0107 22:09:30.087851 1376 master.cpp:5445] Authenticating slave(345)@172.17.0.3:45238
I0107 22:09:30.088107 1376 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(743)@172.17.0.3:45238
I0107 22:09:30.088569 1376 authenticator.cpp:98] Creating new server SASL connection
I0107 22:09:30.088798 1365 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
I0107 22:09:30.088831 1365 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
I0107 22:09:30.088976 1365 authenticator.cpp:203] Received SASL authentication start
I0107 22:09:30.089052 1365 authenticator.cpp:325] Authentication requires more steps
I0107 22:09:30.089164 1365 authenticatee.cpp:258] Received SASL authentication step
I0107 22:09:30.089293 1365 authenticator.cpp:231] Received SASL authentication step
I0107 22:09:30.089329 1365 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'e70672e666f9' server FQDN: 'e70672e666f9' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0107 22:09:30.089349 1365 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
I0107 22:09:30.089444 1365 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0107 22:09:30.089496 1365 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'e70672e666f9' server FQDN: 'e70672e666f9' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0107 22:09:30.089514 1365 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0107 22:09:30.089527 1365 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0107 22:09:30.089550 1365 authenticator.cpp:317] Authentication success
I0107 22:09:30.089663 1371 authenticatee.cpp:298] Authentication success
I0107 22:09:30.089797 1365 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(743)@172.17.0.3:45238
I0107 22:09:30.089800 1367 master.cpp:5475] Successfully authenticated principal 'test-principal' at slave(345)@172.17.0.3:45238
I0107 22:09:30.090302 1377 slave.cpp:860] Successfully authenticated with master master@172.17.0.3:45238
I0107 22:09:30.090898 1377 slave.cpp:1254] Will retry registration in 10.342679ms if necessary
I0107 22:09:30.091387 1371 master.cpp:4314] Re-registering slave 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0 at slave(345)@172.17.0.3:45238 (e70672e666f9)
I0107 22:09:30.092227 1371 master.cpp:4502] Sending updated checkpointed resources to slave 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0 at slave(345)@172.17.0.3:45238 (e70672e666f9)
W0107 22:09:30.092332 1377 slave.cpp:2162] Dropping updateFramework message for 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 because the slave is in DISCONNECTED state
I0107 22:09:30.092921 1377 slave.cpp:2277] Updated checkpointed resources from to
I0107 22:09:30.096886 1367 slave.cpp:643] Slave asked to shut down by master@172.17.0.3:45238
I0107 22:09:30.097147 1367 slave.cpp:2012] Asked to shut down framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 by master@172.17.0.3:45238
I0107 22:09:30.097218 1367 slave.cpp:2037] Shutting down framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000
I0107 22:09:30.097316 1367 slave.cpp:4062] Shutting down executor 'default' of framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 at executor(98)@172.17.0.3:45238
I0107 22:09:30.100950 1372 hierarchical.cpp:1423] No inverse offers to send out!
I0107 22:09:30.101035 1372 hierarchical.cpp:1079] Performed allocation for 1 slaves in 1.441343ms
I0107 22:09:30.101562 1367 slave.cpp:1125] Skipping registration because slave is terminating
I0107 22:09:30.101647 1367 slave.cpp:4601] Querying resource estimator for oversubscribable resources
I0107 22:09:30.102052 1372 master.cpp:5274] Sending 1 offers to framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 (default) at scheduler-45fb2d87-20ce-4364-96d8-df8e14bdaad8@172.17.0.3:45238
I0107 22:09:30.102200 1367 slave.cpp:3371] Received ping from slave-observer(327)@172.17.0.3:45238
I0107 22:09:30.102617 1367 slave.cpp:4157] Ignoring registration timeout for executor 'default' because the framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 is terminating
I0107 22:09:30.102720 1367 slave.cpp:4615] Received oversubscribable resources from the resource estimator
I0107 22:09:30.102856 1367 slave.cpp:4238] Current disk usage 4.61%. Max allowed age: 5.977635301509086days
I0107 22:09:30.103066 1372 sched.cpp:819] Scheduler::resourceOffers took 175534ns
2016-01-07 22:09:30,479:1344(0x7f1b4cffe700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:53039] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
I0107 22:09:31.086976 1364 hierarchical.cpp:1329] No resources available to allocate!
I0107 22:09:31.087043 1364 hierarchical.cpp:1423] No inverse offers to send out!
I0107 22:09:31.087067 1364 hierarchical.cpp:1079] Performed allocation for 1 slaves in 328060ns
I0107 22:09:32.088578 1376 hierarchical.cpp:1329] No resources available to allocate!
I0107 22:09:32.088654 1376 hierarchical.cpp:1423] No inverse offers to send out!
I0107 22:09:32.088690 1376 hierarchical.cpp:1079] Performed allocation for 1 slaves in 344419ns
I0107 22:09:33.090194 1373 hierarchical.cpp:1329] No resources available to allocate!
I0107 22:09:33.090266 1373 hierarchical.cpp:1423] No inverse offers to send out!
I0107 22:09:33.090298 1373 hierarchical.cpp:1079] Performed allocation for 1 slaves in 341022ns
2016-01-07 22:09:33,815:1344(0x7f1b4cffe700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:53039] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
I0107 22:09:34.091236 1378 hierarchical.cpp:1329] No resources available to allocate!
I0107 22:09:34.091323 1378 hierarchical.cpp:1423] No inverse offers to send out!
I0107 22:09:34.091356 1378 hierarchical.cpp:1079] Performed allocation for 1 slaves in 388710ns
I0107 22:09:35.092813 1377 hierarchical.cpp:1329] No resources available to allocate!
I0107 22:09:35.092890 1377 hierarchical.cpp:1423] No inverse offers to send out!
I0107 22:09:35.092919 1377 hierarchical.cpp:1079] Performed allocation for 1 slaves in 345883ns
I0107 22:09:36.093906 1365 hierarchical.cpp:1329] No resources available to allocate!
I0107 22:09:36.093984 1365 hierarchical.cpp:1423] No inverse offers to send out!
I0107 22:09:36.094014 1365 hierarchical.cpp:1079] Performed allocation for 1 slaves in 341316ns
I0107 22:09:37.094885 1368 hierarchical.cpp:1329] No resources available to allocate!
I0107 22:09:37.094967 1368 hierarchical.cpp:1423] No inverse offers to send out!
I0107 22:09:37.095003 1368 hierarchical.cpp:1079] Performed allocation for 1 slaves in 387981ns
2016-01-07 22:09:37,151:1344(0x7f1b4cffe700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:53039] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
I0107 22:09:38.095870 1370 hierarchical.cpp:1329] No resources available to allocate!
I0107 22:09:38.095943 1370 hierarchical.cpp:1423] No inverse offers to send out!
I0107 22:09:38.095968 1370 hierarchical.cpp:1079] Performed allocation for 1 slaves in 346998ns
I0107 22:09:39.097084 1371 hierarchical.cpp:1329] No resources available to allocate!
I0107 22:09:39.097174 1371 hierarchical.cpp:1423] No inverse offers to send out!
I0107 22:09:39.097208 1371 hierarchical.cpp:1079] Performed allocation for 1 slaves in 458211ns
I0107 22:09:40.098181 1372 hierarchical.cpp:1329] No resources available to allocate!
I0107 22:09:40.098255 1372 hierarchical.cpp:1423] No inverse offers to send out!
I0107 22:09:40.098280 1372 hierarchical.cpp:1079] Performed allocation for 1 slaves in 320207ns
2016-01-07 22:09:40,488:1344(0x7f1b4cffe700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:53039] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
I0107 22:09:41.099517 1374 hierarchical.cpp:1329] No resources available to allocate!
I0107 22:09:41.099612 1374 hierarchical.cpp:1423] No inverse offers to send out!
I0107 22:09:41.099647 1374 hierarchical.cpp:1079] Performed allocation for 1 slaves in 442935ns
I0107 22:09:42.100324 1369 hierarchical.cpp:1329] No resources available to allocate!
I0107 22:09:42.100419 1369 hierarchical.cpp:1423] No inverse offers to send out!
I0107 22:09:42.100451 1369 hierarchical.cpp:1079] Performed allocation for 1 slaves in 452523ns
I0107 22:09:43.101866 1363 hierarchical.cpp:1329] No resources available to allocate!
I0107 22:09:43.101966 1363 hierarchical.cpp:1423] No inverse offers to send out!
I0107 22:09:43.102015 1363 hierarchical.cpp:1079] Performed allocation for 1 slaves in 489050ns
2016-01-07 22:09:43,824:1344(0x7f1b4cffe700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:53039] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
I0107 22:09:44.102731 1370 hierarchical.cpp:1329] No resources available to allocate!
I0107 22:09:44.102828 1370 hierarchical.cpp:1423] No inverse offers to send out!
I0107 22:09:44.102865 1370 hierarchical.cpp:1079] Performed allocation for 1 slaves in 548024ns
I0107 22:09:45.087080 1370 slave.cpp:3371] Received ping from slave-observer(327)@172.17.0.3:45238
I0107 22:09:45.087270 1370 slave.cpp:4601] Querying resource estimator for oversubscribable resources
I0107 22:09:45.087663 1364 slave.cpp:4615] Received oversubscribable resources from the resource estimator
I0107 22:09:45.103659 1370 hierarchical.cpp:1329] No resources available to allocate!
I0107 22:09:45.103736 1370 hierarchical.cpp:1423] No inverse offers to send out!
I0107 22:09:45.103771 1370 hierarchical.cpp:1079] Performed allocation for 1 slaves in 333319ns
../../src/tests/slave_tests.cpp:1416: Failure
Failed to wait 15secs for executorLost
I0107 22:09:45.112030 1364 master.cpp:1130] Framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 (default) at scheduler-45fb2d87-20ce-4364-96d8-df8e14bdaad8@172.17.0.3:45238 disconnected
I0107 22:09:45.112071 1364 master.cpp:2493] Disconnecting framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 (default) at scheduler-45fb2d87-20ce-4364-96d8-df8e14bdaad8@172.17.0.3:45238
I0107 22:09:45.112113 1364 master.cpp:2517] Deactivating framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 (default) at scheduler-45fb2d87-20ce-4364-96d8-df8e14bdaad8@172.17.0.3:45238
I0107 22:09:45.112247 1375 hierarchical.cpp:366] Deactivated framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000
W0107 22:09:45.112643 1364 master.hpp:1763] Master attempted to send message to disconnected framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 (default) at scheduler-45fb2d87-20ce-4364-96d8-df8e14bdaad8@172.17.0.3:45238
I0107 22:09:45.112776 1364 master.cpp:1154] Giving framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 (default) at scheduler-45fb2d87-20ce-4364-96d8-df8e14bdaad8@172.17.0.3:45238 0ns to failover
I0107 22:09:45.112855 1369 hierarchical.cpp:880] Recovered cpus(*):1; mem(*):960; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):64) on slave 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0 from framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000
I0107 22:09:45.113064 1377 master.cpp:5122] Framework failover timeout, removing framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 (default) at scheduler-45fb2d87-20ce-4364-96d8-df8e14bdaad8@172.17.0.3:45238
I0107 22:09:45.113106 1377 master.cpp:5857] Removing framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 (default) at scheduler-45fb2d87-20ce-4364-96d8-df8e14bdaad8@172.17.0.3:45238
I0107 22:09:45.113324 1363 slave.cpp:2012] Asked to shut down framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 by master@172.17.0.3:45238
W0107 22:09:45.113370 1363 slave.cpp:2033] Ignoring shutdown framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 because it is terminating
I0107 22:09:45.113363 1377 master.cpp:6369] Updating the state of task 0 of framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 (latest state: TASK_KILLED, status update state: TASK_KILLED)
../../src/tests/slave_tests.cpp:1404: Failure
Actual function call count doesn't match EXPECT_CALL(sched, executorLost(&driver, ({ ExecutorInfo executor; executor.mutable_executor_id()->set_value("default"); executor.mutable_command()->set_value("exit 1"); executor; }).executor_id(), _, _))...
Expected: to be called once
Actual: never called - unsatisfied and active
I0107 22:09:45.113757 1376 hierarchical.cpp:880] Recovered cpus(*):1; mem(*):64 (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0 from framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000
I0107 22:09:45.113806 1371 status_update_manager.cpp:174] Pausing sending status updates
I0107 22:09:45.113895 1377 master.cpp:6435] Removing task 0 with resources cpus(*):1; mem(*):64 of framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 on slave 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0 at slave(345)@172.17.0.3:45238 (e70672e666f9)
I0107 22:09:45.113976 1372 slave.cpp:718] Re-detecting master
I0107 22:09:45.114001 1372 slave.cpp:765] Detecting new master
F0107 22:09:45.114001 1372 logging.cpp:55] RAW: Pure virtual method called
I0107 22:09:45.114306 1377 master.cpp:6464] Removing executor 'default' with resources of framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000 on slave 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0 at slave(345)@172.17.0.3:45238 (e70672e666f9)
I0107 22:09:45.114850 1377 master.cpp:930] Master terminating
I0107 22:09:45.114918 1373 hierarchical.cpp:321] Removed framework 7d0a14fb-e4c2-40c7-b8da-607deaba6261-0000
I0107 22:09:45.115393 1373 hierarchical.cpp:496] Removed slave 7d0a14fb-e4c2-40c7-b8da-607deaba6261-S0
@ 0x7f1c58b36306 google::LogMessage::Fail()
@ 0x7f1c58b3b85c google::RawLog__()
@ 0x7f1c57d42a7c __cxa_pure_virtual
@ 0x7f1c580950eb mesos::internal::slave::Slave::detected()
@ 0x7f1c580e6779 _ZZN7process8dispatchIN5mesos8internal5slave5SlaveERKNS_6FutureI6OptionINS1_10MasterInfoEEEES9_EEvRKNS_3PIDIT_EEMSD_FvT0_ET1_ENKUlPNS_11ProcessBaseEE_clESM_
@ 0x7f1c5811a156 _ZNSt17_Function_handlerIFvPN7process11ProcessBaseEEZNS0_8dispatchIN5mesos8internal5slave5SlaveERKNS0_6FutureI6OptionINS5_10MasterInfoEEEESD_EEvRKNS0_3PIDIT_EEMSH_FvT0_ET1_EUlS2_E_E9_M_invokeERKSt9_Any_dataS2_
@ 0x7f1c58a9e301 std::function<>::operator()()
@ 0x7f1c58a8328b process::ProcessBase::visit()
@ 0x7f1c58a890e2 process::DispatchEvent::visit()
@ 0x94ddc4 process::ProcessBase::serve()
@ 0x7f1c58a7f683 process::ProcessManager::resume()
@ 0x7f1c58a7c7cc _ZZN7process14ProcessManager12init_threadsEvENKUlRKSt11atomic_boolE_clES3_
@ 0x7f1c58a888a4 _ZNSt5_BindIFZN7process14ProcessManager12init_threadsEvEUlRKSt11atomic_boolE_St17reference_wrapperIS3_EEE6__callIvIEILm0EEEET_OSt5tupleIIDpT0_EESt12_Index_tupleIIXspT1_EEE
@ 0x7f1c58a88854 _ZNSt5_BindIFZN7process14ProcessManager12init_threadsEvEUlRKSt11atomic_boolE_St17reference_wrapperIS3_EEEclIIEvEET0_DpOT_
@ 0x7f1c58a887e6 _ZNSt12_Bind_simpleIFSt5_BindIFZN7process14ProcessManager12init_threadsEvEUlRKSt11atomic_boolE_St17reference_wrapperIS4_EEEvEE9_M_invokeIIEEEvSt12_Index_tupleIIXspT_EEE
@ 0x7f1c58a8873d _ZNSt12_Bind_simpleIFSt5_BindIFZN7process14ProcessManager12init_threadsEvEUlRKSt11atomic_boolE_St17reference_wrapperIS4_EEEvEEclEv
@ 0x7f1c58a886d6 _ZNSt6thread5_ImplISt12_Bind_simpleIFSt5_BindIFZN7process14ProcessManager12init_threadsEvEUlRKSt11atomic_boolE_St17reference_wrapperIS6_EEEvEEE6_M_runEv
@ 0x7f1c53a09220 (unknown)
@ 0x7f1c5406fdc5 start_thread
@ 0x7f1c5317121d __clone
make[4]: *** [check-local] Aborted
make[4]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
make[3]: *** [check-am] Error 2
make[3]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
make[2]: *** [check] Error 2
make[2]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
make[1]: *** [check-recursive] Error 1
make[1]: Leaving directory `/mesos/mesos-0.27.0/_build'
make: *** [distcheck] Error 1
+ docker rmi mesos-1452202892-15995
Untagged: mesos-1452202892-15995:latest
Deleted: 5b8cdb89ae16d7a4fe96bb507b633505373880569ddb9e81fd487113c5e6ad50
Deleted: 0077a7ce4d8ee282556d3720a516a2e8ea658147ecb1891906051e087c52b2d3
Deleted: 7527032b06ba38abbf6c8a2763ec168f8ce68ee7093ba038a3918e52187ea96d
Deleted: 788d41fc0d8aa80a7258bba94ee27b7ce6fae2f9b0dfc5bc32fb18bd2a4d246c
Deleted: 58fcc8335be8d58290ede8cdbaa274797e1bf6a08f72be6e8fcbffd1cd783b0a
Deleted: 53c0b916afec93365decbca260183ce7e1b7507279c4170ef54ef3e9bf4f09af
Deleted: 53bf2c367d41c57394adef9973f9157d4c496dba4ff56e8ed4b7a27acc3f8e94
Deleted: b2af391c55982dd895dd81d35a05539482a3f3ad49c7386a667d0a31d57a866c
Deleted: 1a8955f579b00b1a9884c2515572560a89a747d347268c4e7e9dcb44f44a9852
Deleted: 2bb57a8f273d5efbe08e319b600ef3fab5cd13e947ecb4a728bce19e0ce479b6
Deleted: 07793a3febd362385fd9bfd783324603ede845ae7fd60af231904af7b04dcda5
Deleted: 193e7d74761b9ca30ba1b1ee59fabd4c2c46737734df2e762142678217c7445f
Deleted: dfeef5ee44ade29fdf12d3d001f3fa3d5f0b404da2cd3cf583a187ed3c15301c
Build step 'Execute shell' marked build as failure
Jenkins build is back to normal : Mesos » gcc,--verbose --enable-libevent --enable-ssl,centos:7,docker||Hadoop #1458
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose%20--enable-libevent%20--enable-ssl,OS=centos%3A7,label_exp=docker%7C%7CHadoop/1458/changes>
Build failed in Jenkins: Mesos » gcc,--verbose --enable-libevent --enable-ssl,centos:7,docker||Hadoop #1457
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose%20--enable-libevent%20--enable-ssl,OS=centos%3A7,label_exp=docker%7C%7CHadoop/1457/changes>
Changes:
[adam] Disabled flaky/failing TerminatingSlaveDoesNotReregister test.
------------------------------------------
[...truncated 153909 lines...]
I0108 01:15:43.746836 1359 gc.cpp:54] Scheduling '/tmp/ContentType_SchedulerTest_Message_1_YnW5sT/slaves/6089e8b0-5cd7-4105-88bb-2a7d4ba5033c-S0/frameworks/6089e8b0-5cd7-4105-88bb-2a7d4ba5033c-0000/executors/default/runs/3cf1d709-8162-4021-bf81-67337522f42d' for gc 6.99999135696889days in the future
I0108 01:15:43.746981 1351 slave.cpp:3942] Cleaning up framework 6089e8b0-5cd7-4105-88bb-2a7d4ba5033c-0000
I0108 01:15:43.747202 1359 gc.cpp:54] Scheduling '/tmp/ContentType_SchedulerTest_Message_1_YnW5sT/slaves/6089e8b0-5cd7-4105-88bb-2a7d4ba5033c-S0/frameworks/6089e8b0-5cd7-4105-88bb-2a7d4ba5033c-0000/executors/default' for gc 6.99999135517333days in the future
I0108 01:15:43.747262 1350 status_update_manager.cpp:282] Closing status update streams for framework 6089e8b0-5cd7-4105-88bb-2a7d4ba5033c-0000
I0108 01:15:43.747501 1350 status_update_manager.cpp:528] Cleaning up status update stream for task f7d8ca9b-beee-4b5e-85da-6464bea61f2c of framework 6089e8b0-5cd7-4105-88bb-2a7d4ba5033c-0000
I0108 01:15:43.747570 1359 gc.cpp:54] Scheduling '/tmp/ContentType_SchedulerTest_Message_1_YnW5sT/slaves/6089e8b0-5cd7-4105-88bb-2a7d4ba5033c-S0/frameworks/6089e8b0-5cd7-4105-88bb-2a7d4ba5033c-0000' for gc 6.99999135107556days in the future
[ OK ] ContentType/SchedulerTest.Message/1 (100 ms)
[ RUN ] ContentType/SchedulerTest.Request/0
I0108 01:15:43.755234 1325 leveldb.cpp:174] Opened db in 2.542473ms
I0108 01:15:43.756042 1325 leveldb.cpp:181] Compacted db in 689905ns
I0108 01:15:43.756144 1325 leveldb.cpp:196] Created db iterator in 19851ns
I0108 01:15:43.756240 1325 leveldb.cpp:202] Seeked to beginning of db in 2112ns
I0108 01:15:43.756326 1325 leveldb.cpp:271] Iterated through 0 keys in the db in 457ns
I0108 01:15:43.756443 1325 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0108 01:15:43.756991 1357 recover.cpp:447] Starting replica recovery
I0108 01:15:43.757303 1352 recover.cpp:473] Replica is in EMPTY status
I0108 01:15:43.758620 1357 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (12944)@172.17.0.2:32801
I0108 01:15:43.759131 1358 recover.cpp:193] Received a recover response from a replica in EMPTY status
I0108 01:15:43.760004 1358 recover.cpp:564] Updating replica status to STARTING
I0108 01:15:43.760980 1358 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 610077ns
I0108 01:15:43.760990 1352 master.cpp:365] Master 92c71da8-e7d7-417a-bc6e-c019214ad008 (d9632dd1c41e) started on 172.17.0.2:32801
I0108 01:15:43.761075 1358 replica.cpp:320] Persisted replica status to STARTING
I0108 01:15:43.761085 1352 master.cpp:367] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="false" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/vjYx2e/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="25secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.27.0/_inst/share/mesos/webui" --work_dir="/tmp/vjYx2e/master" --zk_session_timeout="10secs"
I0108 01:15:43.761386 1352 master.cpp:414] Master allowing unauthenticated frameworks to register
I0108 01:15:43.761399 1352 master.cpp:417] Master only allowing authenticated slaves to register
I0108 01:15:43.761407 1352 credentials.hpp:35] Loading credentials for authentication from '/tmp/vjYx2e/credentials'
I0108 01:15:43.761617 1358 recover.cpp:473] Replica is in STARTING status
I0108 01:15:43.761714 1352 master.cpp:456] Using default 'crammd5' authenticator
I0108 01:15:43.761843 1352 master.cpp:493] Authorization enabled
I0108 01:15:43.762121 1351 hierarchical.cpp:147] Initialized hierarchical allocator process
I0108 01:15:43.762367 1359 whitelist_watcher.cpp:77] No whitelist given
I0108 01:15:43.763084 1344 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (12945)@172.17.0.2:32801
I0108 01:15:43.763512 1348 recover.cpp:193] Received a recover response from a replica in STARTING status
I0108 01:15:43.764020 1349 recover.cpp:564] Updating replica status to VOTING
I0108 01:15:43.764716 1347 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 434648ns
I0108 01:15:43.764742 1347 replica.cpp:320] Persisted replica status to VOTING
I0108 01:15:43.765203 1359 master.cpp:1629] The newly elected leader is master@172.17.0.2:32801 with id 92c71da8-e7d7-417a-bc6e-c019214ad008
I0108 01:15:43.765209 1349 recover.cpp:578] Successfully joined the Paxos group
I0108 01:15:43.765240 1359 master.cpp:1642] Elected as the leading master!
I0108 01:15:43.765261 1359 master.cpp:1387] Recovering from registrar
I0108 01:15:43.765435 1345 registrar.cpp:307] Recovering registrar
I0108 01:15:43.765590 1349 recover.cpp:462] Recover process terminated
I0108 01:15:43.766433 1353 log.cpp:659] Attempting to start the writer
I0108 01:15:43.767930 1356 replica.cpp:493] Replica received implicit promise request from (12946)@172.17.0.2:32801 with proposal 1
I0108 01:15:43.768350 1356 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 378801ns
I0108 01:15:43.768373 1356 replica.cpp:342] Persisted promised to 1
I0108 01:15:43.769183 1359 coordinator.cpp:238] Coordinator attempting to fill missing positions
I0108 01:15:43.770367 1347 replica.cpp:388] Replica received explicit promise request from (12947)@172.17.0.2:32801 for position 0 with proposal 2
I0108 01:15:43.770697 1347 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 289280ns
I0108 01:15:43.770725 1347 replica.cpp:712] Persisted action at 0
I0108 01:15:43.771877 1356 replica.cpp:537] Replica received write request for position 0 from (12948)@172.17.0.2:32801
I0108 01:15:43.771935 1356 leveldb.cpp:436] Reading position from leveldb took 29358ns
I0108 01:15:43.772353 1356 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 364949ns
I0108 01:15:43.772377 1356 replica.cpp:712] Persisted action at 0
I0108 01:15:43.773003 1353 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
I0108 01:15:43.773563 1353 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 443351ns
I0108 01:15:43.773602 1353 replica.cpp:712] Persisted action at 0
I0108 01:15:43.773627 1353 replica.cpp:697] Replica learned NOP action at position 0
I0108 01:15:43.774176 1359 log.cpp:675] Writer started with ending position 0
I0108 01:15:43.775185 1349 leveldb.cpp:436] Reading position from leveldb took 42678ns
I0108 01:15:43.776077 1358 registrar.cpp:340] Successfully fetched the registry (0B) in 10.58304ms
I0108 01:15:43.776196 1358 registrar.cpp:439] Applied 1 operations in 28656ns; attempting to update the 'registry'
I0108 01:15:43.776850 1353 log.cpp:683] Attempting to append 170 bytes to the log
I0108 01:15:43.777051 1356 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I0108 01:15:43.777712 1347 replica.cpp:537] Replica received write request for position 1 from (12949)@172.17.0.2:32801
I0108 01:15:43.778061 1347 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 307285ns
I0108 01:15:43.778084 1347 replica.cpp:712] Persisted action at 1
I0108 01:15:43.778625 1358 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
I0108 01:15:43.778916 1358 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 263371ns
I0108 01:15:43.778941 1358 replica.cpp:712] Persisted action at 1
I0108 01:15:43.778981 1358 replica.cpp:697] Replica learned APPEND action at position 1
I0108 01:15:43.779803 1356 registrar.cpp:484] Successfully updated the 'registry' in 3.544064ms
I0108 01:15:43.779968 1356 registrar.cpp:370] Successfully recovered registrar
I0108 01:15:43.780058 1357 log.cpp:702] Attempting to truncate the log to 1
I0108 01:15:43.780279 1355 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I0108 01:15:43.780534 1346 master.cpp:1439] Recovered 0 slaves from the Registry (131B) ; allowing 10mins for slaves to re-register
I0108 01:15:43.780580 1357 hierarchical.cpp:165] Skipping recovery of hierarchical allocator: nothing to recover
I0108 01:15:43.781052 1346 replica.cpp:537] Replica received write request for position 2 from (12950)@172.17.0.2:32801
I0108 01:15:43.781395 1346 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 302232ns
I0108 01:15:43.781417 1346 replica.cpp:712] Persisted action at 2
I0108 01:15:43.782009 1358 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
I0108 01:15:43.782311 1358 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 271471ns
I0108 01:15:43.782358 1358 leveldb.cpp:399] Deleting ~1 keys from leveldb took 24308ns
I0108 01:15:43.782377 1358 replica.cpp:712] Persisted action at 2
I0108 01:15:43.782392 1358 replica.cpp:697] Replica learned TRUNCATE action at position 2
I0108 01:15:43.791069 1325 scheduler.cpp:154] Version: 0.27.0
I0108 01:15:43.791728 1355 scheduler.cpp:236] New master detected at master@172.17.0.2:32801
I0108 01:15:43.792979 1348 scheduler.cpp:298] Sending SUBSCRIBE call to master@172.17.0.2:32801
I0108 01:15:43.795135 1359 process.cpp:3141] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0108 01:15:43.795833 1359 http.cpp:315] HTTP POST for /master/api/v1/scheduler from 172.17.0.2:54790
I0108 01:15:43.796161 1359 master.cpp:1891] Received subscription request for HTTP framework 'default'
I0108 01:15:43.796301 1359 master.cpp:1668] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0108 01:15:43.797760 1359 master.cpp:1982] Subscribing framework 'default' with checkpointing disabled and capabilities [ ]
I0108 01:15:43.798355 1356 hierarchical.cpp:260] Added framework 92c71da8-e7d7-417a-bc6e-c019214ad008-0000
I0108 01:15:43.798434 1356 hierarchical.cpp:1329] No resources available to allocate!
I0108 01:15:43.798473 1356 hierarchical.cpp:1423] No inverse offers to send out!
I0108 01:15:43.798499 1356 hierarchical.cpp:1079] Performed allocation for 0 slaves in 113813ns
I0108 01:15:43.798993 1352 master.hpp:1662] Sending heartbeat to 92c71da8-e7d7-417a-bc6e-c019214ad008-0000
I0108 01:15:43.799540 1359 scheduler.cpp:457] Enqueuing event SUBSCRIBED received from master@172.17.0.2:32801
I0108 01:15:43.800511 1359 scheduler.cpp:457] Enqueuing event HEARTBEAT received from master@172.17.0.2:32801
I0108 01:15:43.801496 1359 scheduler.cpp:298] Sending REQUEST call to master@172.17.0.2:32801
I0108 01:15:43.804383 1358 process.cpp:3141] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0108 01:15:43.805138 1358 http.cpp:315] HTTP POST for /master/api/v1/scheduler from 172.17.0.2:54791
I0108 01:15:43.805389 1358 master.cpp:2636] Processing REQUEST call for framework 92c71da8-e7d7-417a-bc6e-c019214ad008-0000 (default)
I0108 01:15:43.805711 1352 hierarchical.cpp:579] Received resource request from framework 92c71da8-e7d7-417a-bc6e-c019214ad008-0000
I0108 01:15:43.807724 1358 master.cpp:930] Master terminating
I0108 01:15:43.807945 1354 hierarchical.cpp:321] Removed framework 92c71da8-e7d7-417a-bc6e-c019214ad008-0000
E0108 01:15:43.809092 1359 scheduler.cpp:431] End-Of-File received from master. The master closed the event stream
I0108 01:15:43.809103 1351 master_maintenance_tests.cpp:177] Ignoring HEARTBEAT event
[ OK ] ContentType/SchedulerTest.Request/0 (62 ms)
[ RUN ] ContentType/SchedulerTest.Request/1
I0108 01:15:43.816985 1325 leveldb.cpp:174] Opened db in 2.518146ms
I0108 01:15:43.817798 1325 leveldb.cpp:181] Compacted db in 778415ns
I0108 01:15:43.817852 1325 leveldb.cpp:196] Created db iterator in 20628ns
I0108 01:15:43.817876 1325 leveldb.cpp:202] Seeked to beginning of db in 1946ns
I0108 01:15:43.817893 1325 leveldb.cpp:271] Iterated through 0 keys in the db in 555ns
I0108 01:15:43.817942 1325 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0108 01:15:43.818445 1355 recover.cpp:447] Starting replica recovery
I0108 01:15:43.818794 1355 recover.cpp:473] Replica is in EMPTY status
I0108 01:15:43.819813 1356 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (12958)@172.17.0.2:32801
I0108 01:15:43.820382 1350 recover.cpp:193] Received a recover response from a replica in EMPTY status
I0108 01:15:43.820858 1345 recover.cpp:564] Updating replica status to STARTING
I0108 01:15:43.821437 1353 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 390604ns
I0108 01:15:43.821468 1353 replica.cpp:320] Persisted replica status to STARTING
I0108 01:15:43.821679 1351 recover.cpp:473] Replica is in STARTING status
I0108 01:15:43.821720 1353 master.cpp:365] Master ef4fe11d-a25a-43d9-bf3c-d0b11687ee27 (d9632dd1c41e) started on 172.17.0.2:32801
I0108 01:15:43.821743 1353 master.cpp:367] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="false" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/O5wcum/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="25secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.27.0/_inst/share/mesos/webui" --work_dir="/tmp/O5wcum/master" --zk_session_timeout="10secs"
I0108 01:15:43.822177 1353 master.cpp:414] Master allowing unauthenticated frameworks to register
I0108 01:15:43.822198 1353 master.cpp:417] Master only allowing authenticated slaves to register
I0108 01:15:43.822211 1353 credentials.hpp:35] Loading credentials for authentication from '/tmp/O5wcum/credentials'
I0108 01:15:43.822520 1353 master.cpp:456] Using default 'crammd5' authenticator
I0108 01:15:43.822649 1353 master.cpp:493] Authorization enabled
I0108 01:15:43.822708 1352 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (12959)@172.17.0.2:32801
I0108 01:15:43.822788 1355 whitelist_watcher.cpp:77] No whitelist given
I0108 01:15:43.822813 1359 hierarchical.cpp:147] Initialized hierarchical allocator process
I0108 01:15:43.823192 1344 recover.cpp:193] Received a recover response from a replica in STARTING status
I0108 01:15:43.823617 1351 recover.cpp:564] Updating replica status to VOTING
I0108 01:15:43.824249 1347 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 354905ns
I0108 01:15:43.824275 1347 replica.cpp:320] Persisted replica status to VOTING
I0108 01:15:43.824398 1347 recover.cpp:578] Successfully joined the Paxos group
I0108 01:15:43.824578 1347 recover.cpp:462] Recover process terminated
I0108 01:15:43.824854 1347 master.cpp:1629] The newly elected leader is master@172.17.0.2:32801 with id ef4fe11d-a25a-43d9-bf3c-d0b11687ee27
I0108 01:15:43.824880 1347 master.cpp:1642] Elected as the leading master!
I0108 01:15:43.824898 1347 master.cpp:1387] Recovering from registrar
I0108 01:15:43.825073 1353 registrar.cpp:307] Recovering registrar
I0108 01:15:43.825794 1353 log.cpp:659] Attempting to start the writer
I0108 01:15:43.826925 1352 replica.cpp:493] Replica received implicit promise request from (12960)@172.17.0.2:32801 with proposal 1
I0108 01:15:43.827270 1352 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 299716ns
I0108 01:15:43.827294 1352 replica.cpp:342] Persisted promised to 1
I0108 01:15:43.827877 1344 coordinator.cpp:238] Coordinator attempting to fill missing positions
I0108 01:15:43.828987 1348 replica.cpp:388] Replica received explicit promise request from (12961)@172.17.0.2:32801 for position 0 with proposal 2
I0108 01:15:43.829344 1348 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 314900ns
I0108 01:15:43.829367 1348 replica.cpp:712] Persisted action at 0
I0108 01:15:43.830354 1349 replica.cpp:537] Replica received write request for position 0 from (12962)@172.17.0.2:32801
I0108 01:15:43.830483 1349 leveldb.cpp:436] Reading position from leveldb took 38991ns
I0108 01:15:43.830894 1349 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 304213ns
I0108 01:15:43.830917 1349 replica.cpp:712] Persisted action at 0
I0108 01:15:43.831562 1345 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
I0108 01:15:43.831993 1345 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 322785ns
I0108 01:15:43.832018 1345 replica.cpp:712] Persisted action at 0
I0108 01:15:43.832038 1345 replica.cpp:697] Replica learned NOP action at position 0
I0108 01:15:43.832669 1351 log.cpp:675] Writer started with ending position 0
I0108 01:15:43.833644 1359 leveldb.cpp:436] Reading position from leveldb took 30474ns
I0108 01:15:43.834591 1344 registrar.cpp:340] Successfully fetched the registry (0B) in 9.473024ms
I0108 01:15:43.834705 1344 registrar.cpp:439] Applied 1 operations in 26564ns; attempting to update the 'registry'
I0108 01:15:43.835402 1358 log.cpp:683] Attempting to append 170 bytes to the log
I0108 01:15:43.835563 1356 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I0108 01:15:43.836282 1358 replica.cpp:537] Replica received write request for position 1 from (12963)@172.17.0.2:32801
I0108 01:15:43.836643 1358 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 326635ns
I0108 01:15:43.836668 1358 replica.cpp:712] Persisted action at 1
I0108 01:15:43.837296 1354 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
I0108 01:15:43.837683 1354 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 360286ns
I0108 01:15:43.837707 1354 replica.cpp:712] Persisted action at 1
I0108 01:15:43.837728 1354 replica.cpp:697] Replica learned APPEND action at position 1
I0108 01:15:43.838575 1346 registrar.cpp:484] Successfully updated the 'registry' in 3.803136ms
I0108 01:15:43.838762 1346 registrar.cpp:370] Successfully recovered registrar
I0108 01:15:43.838840 1347 log.cpp:702] Attempting to truncate the log to 1
I0108 01:15:43.838945 1358 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I0108 01:15:43.839274 1351 master.cpp:1439] Recovered 0 slaves from the Registry (131B) ; allowing 10mins for slaves to re-register
I0108 01:15:43.839318 1348 hierarchical.cpp:165] Skipping recovery of hierarchical allocator: nothing to recover
I0108 01:15:43.840004 1352 replica.cpp:537] Replica received write request for position 2 from (12964)@172.17.0.2:32801
I0108 01:15:43.840417 1352 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 331142ns
I0108 01:15:43.840440 1352 replica.cpp:712] Persisted action at 2
I0108 01:15:43.841017 1347 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
I0108 01:15:43.841341 1347 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 297299ns
I0108 01:15:43.841389 1347 leveldb.cpp:399] Deleting ~1 keys from leveldb took 24116ns
I0108 01:15:43.841413 1347 replica.cpp:712] Persisted action at 2
I0108 01:15:43.841430 1347 replica.cpp:697] Replica learned TRUNCATE action at position 2
I0108 01:15:43.849781 1325 scheduler.cpp:154] Version: 0.27.0
I0108 01:15:43.850419 1355 scheduler.cpp:236] New master detected at master@172.17.0.2:32801
I0108 01:15:43.851462 1353 scheduler.cpp:298] Sending SUBSCRIBE call to master@172.17.0.2:32801
I0108 01:15:43.853049 1345 process.cpp:3141] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0108 01:15:43.853494 1356 http.cpp:315] HTTP POST for /master/api/v1/scheduler from 172.17.0.2:54792
I0108 01:15:43.853796 1356 master.cpp:1891] Received subscription request for HTTP framework 'default'
I0108 01:15:43.853863 1356 master.cpp:1668] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0108 01:15:43.854153 1356 master.cpp:1982] Subscribing framework 'default' with checkpointing disabled and capabilities [ ]
I0108 01:15:43.854521 1354 hierarchical.cpp:260] Added framework ef4fe11d-a25a-43d9-bf3c-d0b11687ee27-0000
I0108 01:15:43.854585 1354 hierarchical.cpp:1329] No resources available to allocate!
I0108 01:15:43.854622 1354 hierarchical.cpp:1423] No inverse offers to send out!
I0108 01:15:43.854650 1354 hierarchical.cpp:1079] Performed allocation for 0 slaves in 101452ns
I0108 01:15:43.854681 1354 master.hpp:1662] Sending heartbeat to ef4fe11d-a25a-43d9-bf3c-d0b11687ee27-0000
I0108 01:15:43.855329 1348 scheduler.cpp:457] Enqueuing event SUBSCRIBED received from master@172.17.0.2:32801
I0108 01:15:43.855742 1348 scheduler.cpp:457] Enqueuing event HEARTBEAT received from master@172.17.0.2:32801
I0108 01:15:43.856345 1349 master_maintenance_tests.cpp:177] Ignoring HEARTBEAT event
I0108 01:15:43.856360 1348 scheduler.cpp:298] Sending REQUEST call to master@172.17.0.2:32801
I0108 01:15:43.857589 1357 process.cpp:3141] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0108 01:15:43.857990 1353 http.cpp:315] HTTP POST for /master/api/v1/scheduler from 172.17.0.2:54793
I0108 01:15:43.858228 1353 master.cpp:2636] Processing REQUEST call for framework ef4fe11d-a25a-43d9-bf3c-d0b11687ee27-0000 (default)
I0108 01:15:43.858561 1356 hierarchical.cpp:579] Received resource request from framework ef4fe11d-a25a-43d9-bf3c-d0b11687ee27-0000
I0108 01:15:43.858993 1358 master.cpp:930] Master terminating
I0108 01:15:43.859226 1349 hierarchical.cpp:321] Removed framework ef4fe11d-a25a-43d9-bf3c-d0b11687ee27-0000
E0108 01:15:43.860128 1355 scheduler.cpp:431] End-Of-File received from master. The master closed the event stream
[ OK ] ContentType/SchedulerTest.Request/1 (51 ms)
[----------] 22 tests from ContentType/SchedulerTest (4203 ms total)
[----------] Global test environment tear-down
[==========] 931 tests from 122 test cases ran. (372853 ms total)
[ PASSED ] 930 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] PersistentVolumeTest.BadACLNoPrincipal
1 FAILED TEST
YOU HAVE 7 DISABLED TESTS
make[4]: *** [check-local] Error 1
make[4]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
make[3]: *** [check-am] Error 2
make[3]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
make[2]: *** [check] Error 2
make[2]: Leaving directory `/mesos/mesos-0.27.0/_build/src'
make[1]: *** [check-recursive] Error 1
make[1]: Leaving directory `/mesos/mesos-0.27.0/_build'
make: *** [distcheck] Error 1
+ docker rmi mesos-1452213951-21579
Untagged: mesos-1452213951-21579:latest
Deleted: cd6f4a79c2055267f9a0604345127d444c4be9151706956c88612d58650f3070
Deleted: 06a0d721e0841cf2a06c776b5e9e3afb9137746aa7e6df4047ffa64a3c89e2f9
Deleted: cc56438b4dfcbdd854d1cb1fad8c2c1e96571e7bb2feb36440f940ab8db0077e
Deleted: daed4ad4c8665014966a59cea243cb5ab86550df035974a58236922ef8ae68c1
Deleted: 9dc4f1da0efc6fefeb9eee37aa8d43f59c97b4c2710d5a52d5c1ad22a324472e
Deleted: bce35b99da2d06993c826a0398a5edbab11bcb726508bc96dec93cbdc766dd8e
Deleted: 6a20ba0ccb4dbfabab635ba935527ea9a264654fe343f6e98a89f33b72679940
Deleted: 38305848c4494f714fae47ecd57388ca66f200928c14b32f4f9b1b1029af2f9c
Deleted: 19b186f9fa1975b68f326f11be9c73afc7ad238d37f09cf51901ea9075e299fb
Deleted: 90ab5fb09a81b2eff729e98c14891af4ac8b8055191abe9ac145f0bf54ad5397
Deleted: ae4a2a5d7ead7175c327482ced9790fcda57ae12468f12f01a9ed30087e650c2
Deleted: 44f20e9d6a91141dc54cd3703996fcf72f21ed4dc7c138906752f7d776e0cc71
Deleted: 5f01dcb8613f0eeb4e31ab95e9ab0b19536f8ae7974ab9ee4a0d9db68d6e9771
Build step 'Execute shell' marked build as failure