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 2015/12/04 04:31:58 UTC

Build failed in Jenkins: Mesos » gcc,--verbose --enable-libevent --enable-ssl,ubuntu:14.04,docker||Hadoop #1319

See <https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose%20--enable-libevent%20--enable-ssl,OS=ubuntu%3A14.04,label_exp=docker%7C%7CHadoop/1319/changes>

Changes:

[benjamin.mahler] Documented why OsSignalsTest.Suppress works on OS X.

------------------------------------------
[...truncated 151042 lines...]
I1204 03:31:52.023347 31790 gc.cpp:54] Scheduling '/tmp/ContentType_SchedulerTest_Message_1_jkcDGA/slaves/e567d75e-4b42-4184-a487-498d6e3e86f0-S0/frameworks/e567d75e-4b42-4184-a487-498d6e3e86f0-0000/executors/default/runs/ad6c9ae3-14b4-4ae0-85e0-2b66874c1d0f' for gc 6.99999973126222days in the future
I1204 03:31:52.023437 31792 slave.cpp:3773] Cleaning up framework e567d75e-4b42-4184-a487-498d6e3e86f0-0000
I1204 03:31:52.023515 31790 gc.cpp:54] Scheduling '/tmp/ContentType_SchedulerTest_Message_1_jkcDGA/slaves/e567d75e-4b42-4184-a487-498d6e3e86f0-S0/frameworks/e567d75e-4b42-4184-a487-498d6e3e86f0-0000/executors/default' for gc 6.99999972944593days in the future
I1204 03:31:52.023558 31794 status_update_manager.cpp:282] Closing status update streams for framework e567d75e-4b42-4184-a487-498d6e3e86f0-0000
I1204 03:31:52.023623 31794 status_update_manager.cpp:528] Cleaning up status update stream for task 3ee27512-7308-4ddf-8ab0-eb17196ad555 of framework e567d75e-4b42-4184-a487-498d6e3e86f0-0000
I1204 03:31:52.023661 31790 gc.cpp:54] Scheduling '/tmp/ContentType_SchedulerTest_Message_1_jkcDGA/slaves/e567d75e-4b42-4184-a487-498d6e3e86f0-S0/frameworks/e567d75e-4b42-4184-a487-498d6e3e86f0-0000' for gc 6.99999972689778days in the future
[       OK ] ContentType/SchedulerTest.Message/1 (675 ms)
[ RUN      ] ContentType/SchedulerTest.Request/0
I1204 03:31:52.124193 31769 leveldb.cpp:174] Opened db in 94.016525ms
I1204 03:31:52.149694 31769 leveldb.cpp:181] Compacted db in 25.458791ms
I1204 03:31:52.149760 31769 leveldb.cpp:196] Created db iterator in 20834ns
I1204 03:31:52.149780 31769 leveldb.cpp:202] Seeked to beginning of db in 1977ns
I1204 03:31:52.149791 31769 leveldb.cpp:271] Iterated through 0 keys in the db in 303ns
I1204 03:31:52.149832 31769 replica.cpp:778] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1204 03:31:52.150544 31791 recover.cpp:447] Starting replica recovery
I1204 03:31:52.151046 31791 recover.cpp:473] Replica is in EMPTY status
I1204 03:31:52.152299 31802 replica.cpp:674] Replica in EMPTY status received a broadcasted recover request from (11482)@172.17.0.2:47200
I1204 03:31:52.152914 31801 recover.cpp:193] Received a recover response from a replica in EMPTY status
I1204 03:31:52.153547 31799 recover.cpp:564] Updating replica status to STARTING
I1204 03:31:52.153744 31803 master.cpp:365] Master 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe (403686b83bbb) started on 172.17.0.2:47200
I1204 03:31:52.153775 31803 master.cpp:367] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="false" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/0wBPVf/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/0wBPVf/master" --zk_session_timeout="10secs"
I1204 03:31:52.154326 31803 master.cpp:414] Master allowing unauthenticated frameworks to register
I1204 03:31:52.154345 31803 master.cpp:417] Master only allowing authenticated slaves to register
I1204 03:31:52.154361 31803 credentials.hpp:35] Loading credentials for authentication from '/tmp/0wBPVf/credentials'
I1204 03:31:52.154675 31803 master.cpp:456] Using default 'crammd5' authenticator
I1204 03:31:52.154832 31803 master.cpp:493] Authorization enabled
I1204 03:31:52.155102 31788 whitelist_watcher.cpp:77] No whitelist given
I1204 03:31:52.155231 31796 hierarchical.cpp:163] Initialized hierarchical allocator process
I1204 03:31:52.157017 31791 master.cpp:1637] The newly elected leader is master@172.17.0.2:47200 with id 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe
I1204 03:31:52.157053 31791 master.cpp:1650] Elected as the leading master!
I1204 03:31:52.157073 31791 master.cpp:1395] Recovering from registrar
I1204 03:31:52.157237 31796 registrar.cpp:307] Recovering registrar
I1204 03:31:52.186647 31798 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 32.571067ms
I1204 03:31:52.186686 31798 replica.cpp:321] Persisted replica status to STARTING
I1204 03:31:52.187000 31803 recover.cpp:473] Replica is in STARTING status
I1204 03:31:52.188062 31800 replica.cpp:674] Replica in STARTING status received a broadcasted recover request from (11483)@172.17.0.2:47200
I1204 03:31:52.188350 31792 recover.cpp:193] Received a recover response from a replica in STARTING status
I1204 03:31:52.188809 31796 recover.cpp:564] Updating replica status to VOTING
I1204 03:31:52.220109 31797 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 31.054929ms
I1204 03:31:52.220147 31797 replica.cpp:321] Persisted replica status to VOTING
I1204 03:31:52.220288 31792 recover.cpp:578] Successfully joined the Paxos group
I1204 03:31:52.220634 31792 recover.cpp:462] Recover process terminated
I1204 03:31:52.221151 31802 log.cpp:659] Attempting to start the writer
I1204 03:31:52.222534 31801 replica.cpp:494] Replica received implicit promise request from (11484)@172.17.0.2:47200 with proposal 1
I1204 03:31:52.245628 31801 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 23.049981ms
I1204 03:31:52.245667 31801 replica.cpp:343] Persisted promised to 1
I1204 03:31:52.246343 31793 coordinator.cpp:238] Coordinator attempting to fill missing positions
I1204 03:31:52.247530 31788 replica.cpp:389] Replica received explicit promise request from (11485)@172.17.0.2:47200 for position 0 with proposal 2
I1204 03:31:52.287514 31788 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 39.94388ms
I1204 03:31:52.287552 31788 replica.cpp:713] Persisted action at 0
I1204 03:31:52.288843 31802 replica.cpp:538] Replica received write request for position 0 from (11486)@172.17.0.2:47200
I1204 03:31:52.288903 31802 leveldb.cpp:436] Reading position from leveldb took 29125ns
I1204 03:31:52.329651 31802 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 40.69596ms
I1204 03:31:52.329701 31802 replica.cpp:713] Persisted action at 0
I1204 03:31:52.330826 31800 replica.cpp:692] Replica received learned notice for position 0 from @0.0.0.0:0
I1204 03:31:52.383780 31800 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 52.909056ms
I1204 03:31:52.383831 31800 replica.cpp:713] Persisted action at 0
I1204 03:31:52.383858 31800 replica.cpp:698] Replica learned NOP action at position 0
I1204 03:31:52.384644 31794 log.cpp:675] Writer started with ending position 0
I1204 03:31:52.385828 31791 leveldb.cpp:436] Reading position from leveldb took 33950ns
I1204 03:31:52.386934 31791 registrar.cpp:340] Successfully fetched the registry (0B) in 229.636864ms
I1204 03:31:52.387066 31791 registrar.cpp:439] Applied 1 operations in 36217ns; attempting to update the 'registry'
I1204 03:31:52.387809 31794 log.cpp:683] Attempting to append 170 bytes to the log
I1204 03:31:52.387995 31798 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I1204 03:31:52.388667 31802 replica.cpp:538] Replica received write request for position 1 from (11487)@172.17.0.2:47200
I1204 03:31:52.434088 31802 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 45.373715ms
I1204 03:31:52.434159 31802 replica.cpp:713] Persisted action at 1
I1204 03:31:52.435035 31803 replica.cpp:692] Replica received learned notice for position 1 from @0.0.0.0:0
I1204 03:31:52.467439 31803 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 32.356386ms
I1204 03:31:52.467502 31803 replica.cpp:713] Persisted action at 1
I1204 03:31:52.467533 31803 replica.cpp:698] Replica learned APPEND action at position 1
I1204 03:31:52.468945 31789 registrar.cpp:484] Successfully updated the 'registry' in 81.793792ms
I1204 03:31:52.469149 31789 registrar.cpp:370] Successfully recovered registrar
I1204 03:31:52.469293 31796 log.cpp:702] Attempting to truncate the log to 1
I1204 03:31:52.469637 31797 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I1204 03:31:52.469657 31802 hierarchical.cpp:181] Skipping recovery of hierarchical allocator: nothing to recover
I1204 03:31:52.469641 31795 master.cpp:1447] Recovered 0 slaves from the Registry (131B) ; allowing 10mins for slaves to re-register
I1204 03:31:52.470474 31795 replica.cpp:538] Replica received write request for position 2 from (11488)@172.17.0.2:47200
I1204 03:31:52.509683 31795 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 39.16527ms
I1204 03:31:52.509734 31795 replica.cpp:713] Persisted action at 2
I1204 03:31:52.511015 31801 replica.cpp:692] Replica received learned notice for position 2 from @0.0.0.0:0
I1204 03:31:52.546566 31801 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 35.510343ms
I1204 03:31:52.546649 31801 leveldb.cpp:399] Deleting ~1 keys from leveldb took 42968ns
I1204 03:31:52.546674 31801 replica.cpp:713] Persisted action at 2
I1204 03:31:52.546696 31801 replica.cpp:698] Replica learned TRUNCATE action at position 2
I1204 03:31:52.551092 31769 scheduler.cpp:154] Version: 0.27.0
I1204 03:31:52.552342 31798 scheduler.cpp:236] New master detected at master@172.17.0.2:47200
I1204 03:31:52.553699 31795 scheduler.cpp:298] Sending SUBSCRIBE call to master@172.17.0.2:47200
I1204 03:31:52.555797 31802 process.cpp:3067] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1204 03:31:52.555894 31802 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.0.2:33004
I1204 03:31:52.556227 31802 master.cpp:1899] Received subscription request for HTTP framework 'default'
I1204 03:31:52.556316 31802 master.cpp:1676] Authorizing framework principal 'test-principal' to receive offers for role '*'
I1204 03:31:52.556674 31802 master.cpp:1991] Subscribing framework 'default' with checkpointing disabled and capabilities [  ]
I1204 03:31:52.557163 31790 hierarchical.cpp:266] Added framework 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
I1204 03:31:52.557260 31790 hierarchical.cpp:1308] No resources available to allocate!
I1204 03:31:52.557313 31790 hierarchical.cpp:1401] No inverse offers to send out!
I1204 03:31:52.557312 31794 master.hpp:1583] Sending heartbeat to 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
I1204 03:31:52.557363 31790 hierarchical.cpp:1048] Performed allocation for 0 slaves in 164108ns
I1204 03:31:52.558205 31802 scheduler.cpp:457] Enqueuing event SUBSCRIBED received from master@172.17.0.2:47200
I1204 03:31:52.558789 31802 scheduler.cpp:457] Enqueuing event HEARTBEAT received from master@172.17.0.2:47200
I1204 03:31:52.559478 31788 master_maintenance_tests.cpp:172] Ignoring HEARTBEAT event
I1204 03:31:52.559605 31801 scheduler.cpp:298] Sending REQUEST call to master@172.17.0.2:47200
I1204 03:31:52.561221 31803 process.cpp:3067] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1204 03:31:52.561274 31803 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.0.2:33005
I1204 03:31:52.561362 31803 master.cpp:2646] Processing REQUEST call for framework 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000 (default)
I1204 03:31:52.561527 31800 hierarchical.cpp:557] Received resource request from framework 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
I1204 03:31:52.561843 31798 master.cpp:938] Master terminating
I1204 03:31:52.562047 31794 hierarchical.cpp:306] Removed framework 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
E1204 03:31:52.563323 31802 scheduler.cpp:431] End-Of-File received from master. The master closed the event stream
[       OK ] ContentType/SchedulerTest.Request/0 (540 ms)
[ RUN      ] ContentType/SchedulerTest.Request/1
I1204 03:31:52.664904 31769 leveldb.cpp:174] Opened db in 95.062723ms
I1204 03:31:52.710089 31769 leveldb.cpp:181] Compacted db in 45.135601ms
I1204 03:31:52.710189 31769 leveldb.cpp:196] Created db iterator in 41589ns
I1204 03:31:52.710208 31769 leveldb.cpp:202] Seeked to beginning of db in 1962ns
I1204 03:31:52.710218 31769 leveldb.cpp:271] Iterated through 0 keys in the db in 280ns
I1204 03:31:52.710280 31769 replica.cpp:778] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1204 03:31:52.711068 31792 recover.cpp:447] Starting replica recovery
I1204 03:31:52.711433 31792 recover.cpp:473] Replica is in EMPTY status
I1204 03:31:52.713116 31802 replica.cpp:674] Replica in EMPTY status received a broadcasted recover request from (11493)@172.17.0.2:47200
I1204 03:31:52.713871 31800 recover.cpp:193] Received a recover response from a replica in EMPTY status
I1204 03:31:52.714603 31799 recover.cpp:564] Updating replica status to STARTING
I1204 03:31:52.715018 31800 master.cpp:365] Master 82e2943a-0ffa-43db-ab30-d280bc15aad8 (403686b83bbb) started on 172.17.0.2:47200
I1204 03:31:52.715071 31800 master.cpp:367] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="false" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/3FPUXP/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/3FPUXP/master" --zk_session_timeout="10secs"
I1204 03:31:52.715515 31800 master.cpp:414] Master allowing unauthenticated frameworks to register
I1204 03:31:52.715529 31800 master.cpp:417] Master only allowing authenticated slaves to register
I1204 03:31:52.715538 31800 credentials.hpp:35] Loading credentials for authentication from '/tmp/3FPUXP/credentials'
I1204 03:31:52.715888 31800 master.cpp:456] Using default 'crammd5' authenticator
I1204 03:31:52.716110 31800 master.cpp:493] Authorization enabled
I1204 03:31:52.716346 31799 whitelist_watcher.cpp:77] No whitelist given
I1204 03:31:52.716421 31788 hierarchical.cpp:163] Initialized hierarchical allocator process
I1204 03:31:52.718489 31798 master.cpp:1637] The newly elected leader is master@172.17.0.2:47200 with id 82e2943a-0ffa-43db-ab30-d280bc15aad8
I1204 03:31:52.718533 31798 master.cpp:1650] Elected as the leading master!
I1204 03:31:52.718557 31798 master.cpp:1395] Recovering from registrar
I1204 03:31:52.718823 31803 registrar.cpp:307] Recovering registrar
I1204 03:31:52.743455 31790 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 28.301712ms
I1204 03:31:52.743496 31790 replica.cpp:321] Persisted replica status to STARTING
I1204 03:31:52.743876 31795 recover.cpp:473] Replica is in STARTING status
I1204 03:31:52.745254 31796 replica.cpp:674] Replica in STARTING status received a broadcasted recover request from (11494)@172.17.0.2:47200
I1204 03:31:52.745743 31791 recover.cpp:193] Received a recover response from a replica in STARTING status
I1204 03:31:52.746407 31797 recover.cpp:564] Updating replica status to VOTING
I1204 03:31:52.768430 31802 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 21.81261ms
I1204 03:31:52.768474 31802 replica.cpp:321] Persisted replica status to VOTING
I1204 03:31:52.768616 31802 recover.cpp:578] Successfully joined the Paxos group
I1204 03:31:52.768904 31802 recover.cpp:462] Recover process terminated
I1204 03:31:52.769584 31800 log.cpp:659] Attempting to start the writer
I1204 03:31:52.771621 31789 replica.cpp:494] Replica received implicit promise request from (11495)@172.17.0.2:47200 with proposal 1
I1204 03:31:52.793648 31789 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 21.993492ms
I1204 03:31:52.793694 31789 replica.cpp:343] Persisted promised to 1
I1204 03:31:52.794865 31798 coordinator.cpp:238] Coordinator attempting to fill missing positions
I1204 03:31:52.796506 31799 replica.cpp:389] Replica received explicit promise request from (11496)@172.17.0.2:47200 for position 0 with proposal 2
I1204 03:31:52.818649 31799 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 22.082655ms
I1204 03:31:52.818688 31799 replica.cpp:713] Persisted action at 0
I1204 03:31:52.820047 31801 replica.cpp:538] Replica received write request for position 0 from (11497)@172.17.0.2:47200
I1204 03:31:52.820125 31801 leveldb.cpp:436] Reading position from leveldb took 37411ns
I1204 03:31:52.843890 31801 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 23.710606ms
I1204 03:31:52.843935 31801 replica.cpp:713] Persisted action at 0
I1204 03:31:52.844709 31800 replica.cpp:692] Replica received learned notice for position 0 from @0.0.0.0:0
I1204 03:31:52.868993 31800 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 24.242639ms
I1204 03:31:52.869032 31800 replica.cpp:713] Persisted action at 0
I1204 03:31:52.869055 31800 replica.cpp:698] Replica learned NOP action at position 0
I1204 03:31:52.869815 31797 log.cpp:675] Writer started with ending position 0
I1204 03:31:52.871470 31789 leveldb.cpp:436] Reading position from leveldb took 40828ns
I1204 03:31:52.872885 31790 registrar.cpp:340] Successfully fetched the registry (0B) in 154.009088ms
I1204 03:31:52.873096 31790 registrar.cpp:439] Applied 1 operations in 32282ns; attempting to update the 'registry'
I1204 03:31:52.874133 31800 log.cpp:683] Attempting to append 170 bytes to the log
I1204 03:31:52.874337 31796 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I1204 03:31:52.875277 31800 replica.cpp:538] Replica received write request for position 1 from (11498)@172.17.0.2:47200
I1204 03:31:52.902500 31800 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 27.170365ms
I1204 03:31:52.902545 31800 replica.cpp:713] Persisted action at 1
I1204 03:31:52.903542 31798 replica.cpp:692] Replica received learned notice for position 1 from @0.0.0.0:0
I1204 03:31:52.927577 31798 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 23.991773ms
I1204 03:31:52.927616 31798 replica.cpp:713] Persisted action at 1
I1204 03:31:52.927639 31798 replica.cpp:698] Replica learned APPEND action at position 1
I1204 03:31:52.928863 31794 registrar.cpp:484] Successfully updated the 'registry' in 55.643136ms
I1204 03:31:52.929076 31794 registrar.cpp:370] Successfully recovered registrar
I1204 03:31:52.929177 31799 log.cpp:702] Attempting to truncate the log to 1
I1204 03:31:52.929407 31797 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I1204 03:31:52.929703 31795 master.cpp:1447] Recovered 0 slaves from the Registry (131B) ; allowing 10mins for slaves to re-register
I1204 03:31:52.929723 31799 hierarchical.cpp:181] Skipping recovery of hierarchical allocator: nothing to recover
I1204 03:31:52.930577 31788 replica.cpp:538] Replica received write request for position 2 from (11499)@172.17.0.2:47200
I1204 03:31:52.952744 31788 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 22.115164ms
I1204 03:31:52.952781 31788 replica.cpp:713] Persisted action at 2
I1204 03:31:52.953629 31798 replica.cpp:692] Replica received learned notice for position 2 from @0.0.0.0:0
I1204 03:31:52.977794 31798 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 24.127932ms
I1204 03:31:52.977882 31798 leveldb.cpp:399] Deleting ~1 keys from leveldb took 46051ns
I1204 03:31:52.977926 31798 replica.cpp:713] Persisted action at 2
I1204 03:31:52.977954 31798 replica.cpp:698] Replica learned TRUNCATE action at position 2
I1204 03:31:52.981016 31769 scheduler.cpp:154] Version: 0.27.0
I1204 03:31:52.981828 31793 scheduler.cpp:236] New master detected at master@172.17.0.2:47200
I1204 03:31:52.983167 31789 scheduler.cpp:298] Sending SUBSCRIBE call to master@172.17.0.2:47200
I1204 03:31:52.985347 31789 process.cpp:3067] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1204 03:31:52.985502 31789 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.0.2:33009
I1204 03:31:52.985939 31789 master.cpp:1899] Received subscription request for HTTP framework 'default'
I1204 03:31:52.986045 31789 master.cpp:1676] Authorizing framework principal 'test-principal' to receive offers for role '*'
I1204 03:31:52.986364 31789 master.cpp:1991] Subscribing framework 'default' with checkpointing disabled and capabilities [  ]
I1204 03:31:52.986779 31799 hierarchical.cpp:266] Added framework 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
I1204 03:31:52.986913 31796 master.hpp:1583] Sending heartbeat to 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
I1204 03:31:52.986996 31799 hierarchical.cpp:1308] No resources available to allocate!
I1204 03:31:52.987063 31799 hierarchical.cpp:1401] No inverse offers to send out!
I1204 03:31:52.987110 31799 hierarchical.cpp:1048] Performed allocation for 0 slaves in 189242ns
I1204 03:31:52.987913 31798 scheduler.cpp:457] Enqueuing event SUBSCRIBED received from master@172.17.0.2:47200
I1204 03:31:52.988831 31798 scheduler.cpp:457] Enqueuing event HEARTBEAT received from master@172.17.0.2:47200
I1204 03:31:52.989537 31788 master_maintenance_tests.cpp:172] Ignoring HEARTBEAT event
I1204 03:31:52.989886 31801 scheduler.cpp:298] Sending REQUEST call to master@172.17.0.2:47200
I1204 03:31:52.991730 31792 process.cpp:3067] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1204 03:31:52.991812 31792 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.0.2:33010
I1204 03:31:52.992156 31792 master.cpp:2646] Processing REQUEST call for framework 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000 (default)
I1204 03:31:52.992516 31790 hierarchical.cpp:557] Received resource request from framework 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
I1204 03:31:52.992923 31800 master.cpp:938] Master terminating
I1204 03:31:52.993132 31796 hierarchical.cpp:306] Removed framework 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
E1204 03:31:52.993708 31798 scheduler.cpp:431] End-Of-File received from master. The master closed the event stream
[       OK ] ContentType/SchedulerTest.Request/1 (431 ms)
[----------] 22 tests from ContentType/SchedulerTest (15741 ms total)

[----------] Global test environment tear-down
[==========] 878 tests from 116 test cases ran. (711169 ms total)
[  PASSED  ] 877 tests.
[  FAILED  ] 1 test, listed below:
[  FAILED  ] ReservationTest.ACLMultipleOperations

 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-1449197270-18036
Untagged: mesos-1449197270-18036:latest
Deleted: 71bc3adfccbfe4c515166abab14facf5895235fd4358c75eafe7552377b4ed12
Deleted: c04522c46bffaa92efd2450d00842a14171f47c8ae50942666829e4dca2a7ada
Deleted: d5849061eee06f14b51d9d7237588a0fe83fd953abfc1713692bd1247d04220f
Deleted: 20d1e630457de2edba4f2fabe62ee3bcc7de4243ec737ce2a545a83de876613d
Deleted: 64bba51bd0cdcb0d983deeb4cd1aa27ceb02bd4703c24f2692024c5a1537de44
Deleted: 59e85ec64b5ee2735cde5403fe8def7375ffca98f9ea7953c802705673efb8cd
Deleted: bee88887921d3d7d38f87744f4f49cb346037ce8a8b09af9d29686376200d66e
Deleted: 709b8b667cf349fbcf14fbc48a0316319b341baaa1dd61f6a48c66d37b2dc628
Deleted: e2c4f6d787499248e303270ff419e2545075e24a83101ed5316f4ecc907bba69
Deleted: 0b8ee088204fbd6b9b1fa2f1a503763106b444f6a0b5d64ad6136269f821e487
Deleted: 5657d8070e24ed2e2c43b0ac6ac0536208680be1f4e18031f5c76fd722aff863
Deleted: 5e4dcfbaf3cc159742402a11e2c8b27efa71ec0ec202abd22acf5f553691f9c6
Deleted: f589a283ec591fb354c074375571f136e15baa088534a380ac69255b6565ecdd
Build step 'Execute shell' marked build as failure

Re: Build failed in Jenkins: Mesos » gcc,--verbose --enable-libevent --enable-ssl,ubuntu:14.04,docker||Hadoop #1319

Posted by Greg Mann <gr...@mesosphere.io>.
Checking this out now. Have not been able to reproduce yet.

On Fri, Dec 4, 2015 at 1:07 AM, Michael Park <mp...@mesosphere.io> wrote:

> +Jie Yu <yu...@gmail.com>
>
> I've filed https://issues.apache.org/jira/browse/MESOS-4067. I've also
> figured out at least one of the issues, left a description of it in the
> comments + possible fixes.
>
> On Thu, Dec 3, 2015 at 10:51 PM Michael Park <mp...@mesosphere.io> wrote:
>
>> Jie, but I also helped out so I can look into it once I get on a computer.
>>
>> On Thu, Dec 3, 2015, 10:50 PM Benjamin Mahler <be...@gmail.com>
>> wrote:
>>
>>> Got it. Who shepherded it?
>>>
>>> On Thu, Dec 3, 2015 at 7:38 PM, Michael Park <mp...@mesosphere.io>
>>> wrote:
>>>
>>>> +Greg since he's the author, he might have a better idea
>>>>
>>>> On Thu, Dec 3, 2015, 10:36 PM Benjamin Mahler <
>>>> benjamin.mahler@gmail.com> wrote:
>>>>
>>>>> Michael can you please triage this test?
>>>>>
>>>>> On Thu, Dec 3, 2015 at 7:31 PM, Apache Jenkins Server <
>>>>> jenkins@builds.apache.org> wrote:
>>>>>
>>>>>> See <
>>>>>> https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose%20--enable-libevent%20--enable-ssl,OS=ubuntu%3A14.04,label_exp=docker%7C%7CHadoop/1319/changes
>>>>>> >
>>>>>>
>>>>>> Changes:
>>>>>>
>>>>>> [benjamin.mahler] Documented why OsSignalsTest.Suppress works on OS X.
>>>>>>
>>>>>> ------------------------------------------
>>>>>> [...truncated 151042 lines...]
>>>>>> I1204 03:31:52.023347 31790 gc.cpp:54] Scheduling
>>>>>> '/tmp/ContentType_SchedulerTest_Message_1_jkcDGA/slaves/e567d75e-4b42-4184-a487-498d6e3e86f0-S0/frameworks/e567d75e-4b42-4184-a487-498d6e3e86f0-0000/executors/default/runs/ad6c9ae3-14b4-4ae0-85e0-2b66874c1d0f'
>>>>>> for gc 6.99999973126222days in the future
>>>>>> I1204 03:31:52.023437 31792 slave.cpp:3773] Cleaning up framework
>>>>>> e567d75e-4b42-4184-a487-498d6e3e86f0-0000
>>>>>> I1204 03:31:52.023515 31790 gc.cpp:54] Scheduling
>>>>>> '/tmp/ContentType_SchedulerTest_Message_1_jkcDGA/slaves/e567d75e-4b42-4184-a487-498d6e3e86f0-S0/frameworks/e567d75e-4b42-4184-a487-498d6e3e86f0-0000/executors/default'
>>>>>> for gc 6.99999972944593days in the future
>>>>>> I1204 03:31:52.023558 31794 status_update_manager.cpp:282] Closing
>>>>>> status update streams for framework
>>>>>> e567d75e-4b42-4184-a487-498d6e3e86f0-0000
>>>>>> I1204 03:31:52.023623 31794 status_update_manager.cpp:528] Cleaning
>>>>>> up status update stream for task 3ee27512-7308-4ddf-8ab0-eb17196ad555 of
>>>>>> framework e567d75e-4b42-4184-a487-498d6e3e86f0-0000
>>>>>> I1204 03:31:52.023661 31790 gc.cpp:54] Scheduling
>>>>>> '/tmp/ContentType_SchedulerTest_Message_1_jkcDGA/slaves/e567d75e-4b42-4184-a487-498d6e3e86f0-S0/frameworks/e567d75e-4b42-4184-a487-498d6e3e86f0-0000'
>>>>>> for gc 6.99999972689778days in the future
>>>>>> [       OK ] ContentType/SchedulerTest.Message/1 (675 ms)
>>>>>> [ RUN      ] ContentType/SchedulerTest.Request/0
>>>>>> I1204 03:31:52.124193 31769 leveldb.cpp:174] Opened db in 94.016525ms
>>>>>> I1204 03:31:52.149694 31769 leveldb.cpp:181] Compacted db in
>>>>>> 25.458791ms
>>>>>> I1204 03:31:52.149760 31769 leveldb.cpp:196] Created db iterator in
>>>>>> 20834ns
>>>>>> I1204 03:31:52.149780 31769 leveldb.cpp:202] Seeked to beginning of
>>>>>> db in 1977ns
>>>>>> I1204 03:31:52.149791 31769 leveldb.cpp:271] Iterated through 0 keys
>>>>>> in the db in 303ns
>>>>>> I1204 03:31:52.149832 31769 replica.cpp:778] Replica recovered with
>>>>>> log positions 0 -> 0 with 1 holes and 0 unlearned
>>>>>> I1204 03:31:52.150544 31791 recover.cpp:447] Starting replica recovery
>>>>>> I1204 03:31:52.151046 31791 recover.cpp:473] Replica is in EMPTY
>>>>>> status
>>>>>> I1204 03:31:52.152299 31802 replica.cpp:674] Replica in EMPTY status
>>>>>> received a broadcasted recover request from (11482)@172.17.0.2:47200
>>>>>> I1204 03:31:52.152914 31801 recover.cpp:193] Received a recover
>>>>>> response from a replica in EMPTY status
>>>>>> I1204 03:31:52.153547 31799 recover.cpp:564] Updating replica status
>>>>>> to STARTING
>>>>>> I1204 03:31:52.153744 31803 master.cpp:365] Master
>>>>>> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe (403686b83bbb) started on
>>>>>> 172.17.0.2:47200
>>>>>> I1204 03:31:52.153775 31803 master.cpp:367] Flags at startup:
>>>>>> --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF"
>>>>>> --authenticate="false" --authenticate_slaves="true"
>>>>>> --authenticators="crammd5" --authorizers="local"
>>>>>> --credentials="/tmp/0wBPVf/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/0wBPVf/master" --zk_session_timeout="10secs"
>>>>>> I1204 03:31:52.154326 31803 master.cpp:414] Master allowing
>>>>>> unauthenticated frameworks to register
>>>>>> I1204 03:31:52.154345 31803 master.cpp:417] Master only allowing
>>>>>> authenticated slaves to register
>>>>>> I1204 03:31:52.154361 31803 credentials.hpp:35] Loading credentials
>>>>>> for authentication from '/tmp/0wBPVf/credentials'
>>>>>> I1204 03:31:52.154675 31803 master.cpp:456] Using default 'crammd5'
>>>>>> authenticator
>>>>>> I1204 03:31:52.154832 31803 master.cpp:493] Authorization enabled
>>>>>> I1204 03:31:52.155102 31788 whitelist_watcher.cpp:77] No whitelist
>>>>>> given
>>>>>> I1204 03:31:52.155231 31796 hierarchical.cpp:163] Initialized
>>>>>> hierarchical allocator process
>>>>>> I1204 03:31:52.157017 31791 master.cpp:1637] The newly elected leader
>>>>>> is master@172.17.0.2:47200 with id
>>>>>> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe
>>>>>> I1204 03:31:52.157053 31791 master.cpp:1650] Elected as the leading
>>>>>> master!
>>>>>> I1204 03:31:52.157073 31791 master.cpp:1395] Recovering from registrar
>>>>>> I1204 03:31:52.157237 31796 registrar.cpp:307] Recovering registrar
>>>>>> I1204 03:31:52.186647 31798 leveldb.cpp:304] Persisting metadata (8
>>>>>> bytes) to leveldb took 32.571067ms
>>>>>> I1204 03:31:52.186686 31798 replica.cpp:321] Persisted replica status
>>>>>> to STARTING
>>>>>> I1204 03:31:52.187000 31803 recover.cpp:473] Replica is in STARTING
>>>>>> status
>>>>>> I1204 03:31:52.188062 31800 replica.cpp:674] Replica in STARTING
>>>>>> status received a broadcasted recover request from (11483)@
>>>>>> 172.17.0.2:47200
>>>>>> I1204 03:31:52.188350 31792 recover.cpp:193] Received a recover
>>>>>> response from a replica in STARTING status
>>>>>> I1204 03:31:52.188809 31796 recover.cpp:564] Updating replica status
>>>>>> to VOTING
>>>>>> I1204 03:31:52.220109 31797 leveldb.cpp:304] Persisting metadata (8
>>>>>> bytes) to leveldb took 31.054929ms
>>>>>> I1204 03:31:52.220147 31797 replica.cpp:321] Persisted replica status
>>>>>> to VOTING
>>>>>> I1204 03:31:52.220288 31792 recover.cpp:578] Successfully joined the
>>>>>> Paxos group
>>>>>> I1204 03:31:52.220634 31792 recover.cpp:462] Recover process
>>>>>> terminated
>>>>>> I1204 03:31:52.221151 31802 log.cpp:659] Attempting to start the
>>>>>> writer
>>>>>> I1204 03:31:52.222534 31801 replica.cpp:494] Replica received
>>>>>> implicit promise request from (11484)@172.17.0.2:47200 with proposal
>>>>>> 1
>>>>>> I1204 03:31:52.245628 31801 leveldb.cpp:304] Persisting metadata (8
>>>>>> bytes) to leveldb took 23.049981ms
>>>>>> I1204 03:31:52.245667 31801 replica.cpp:343] Persisted promised to 1
>>>>>> I1204 03:31:52.246343 31793 coordinator.cpp:238] Coordinator
>>>>>> attempting to fill missing positions
>>>>>> I1204 03:31:52.247530 31788 replica.cpp:389] Replica received
>>>>>> explicit promise request from (11485)@172.17.0.2:47200 for position
>>>>>> 0 with proposal 2
>>>>>> I1204 03:31:52.287514 31788 leveldb.cpp:341] Persisting action (8
>>>>>> bytes) to leveldb took 39.94388ms
>>>>>> I1204 03:31:52.287552 31788 replica.cpp:713] Persisted action at 0
>>>>>> I1204 03:31:52.288843 31802 replica.cpp:538] Replica received write
>>>>>> request for position 0 from (11486)@172.17.0.2:47200
>>>>>> I1204 03:31:52.288903 31802 leveldb.cpp:436] Reading position from
>>>>>> leveldb took 29125ns
>>>>>> I1204 03:31:52.329651 31802 leveldb.cpp:341] Persisting action (14
>>>>>> bytes) to leveldb took 40.69596ms
>>>>>> I1204 03:31:52.329701 31802 replica.cpp:713] Persisted action at 0
>>>>>> I1204 03:31:52.330826 31800 replica.cpp:692] Replica received learned
>>>>>> notice for position 0 from @0.0.0.0:0
>>>>>> I1204 03:31:52.383780 31800 leveldb.cpp:341] Persisting action (16
>>>>>> bytes) to leveldb took 52.909056ms
>>>>>> I1204 03:31:52.383831 31800 replica.cpp:713] Persisted action at 0
>>>>>> I1204 03:31:52.383858 31800 replica.cpp:698] Replica learned NOP
>>>>>> action at position 0
>>>>>> I1204 03:31:52.384644 31794 log.cpp:675] Writer started with ending
>>>>>> position 0
>>>>>> I1204 03:31:52.385828 31791 leveldb.cpp:436] Reading position from
>>>>>> leveldb took 33950ns
>>>>>> I1204 03:31:52.386934 31791 registrar.cpp:340] Successfully fetched
>>>>>> the registry (0B) in 229.636864ms
>>>>>> I1204 03:31:52.387066 31791 registrar.cpp:439] Applied 1 operations
>>>>>> in 36217ns; attempting to update the 'registry'
>>>>>> I1204 03:31:52.387809 31794 log.cpp:683] Attempting to append 170
>>>>>> bytes to the log
>>>>>> I1204 03:31:52.387995 31798 coordinator.cpp:348] Coordinator
>>>>>> attempting to write APPEND action at position 1
>>>>>> I1204 03:31:52.388667 31802 replica.cpp:538] Replica received write
>>>>>> request for position 1 from (11487)@172.17.0.2:47200
>>>>>> I1204 03:31:52.434088 31802 leveldb.cpp:341] Persisting action (189
>>>>>> bytes) to leveldb took 45.373715ms
>>>>>> I1204 03:31:52.434159 31802 replica.cpp:713] Persisted action at 1
>>>>>> I1204 03:31:52.435035 31803 replica.cpp:692] Replica received learned
>>>>>> notice for position 1 from @0.0.0.0:0
>>>>>> I1204 03:31:52.467439 31803 leveldb.cpp:341] Persisting action (191
>>>>>> bytes) to leveldb took 32.356386ms
>>>>>> I1204 03:31:52.467502 31803 replica.cpp:713] Persisted action at 1
>>>>>> I1204 03:31:52.467533 31803 replica.cpp:698] Replica learned APPEND
>>>>>> action at position 1
>>>>>> I1204 03:31:52.468945 31789 registrar.cpp:484] Successfully updated
>>>>>> the 'registry' in 81.793792ms
>>>>>> I1204 03:31:52.469149 31789 registrar.cpp:370] Successfully recovered
>>>>>> registrar
>>>>>> I1204 03:31:52.469293 31796 log.cpp:702] Attempting to truncate the
>>>>>> log to 1
>>>>>> I1204 03:31:52.469637 31797 coordinator.cpp:348] Coordinator
>>>>>> attempting to write TRUNCATE action at position 2
>>>>>> I1204 03:31:52.469657 31802 hierarchical.cpp:181] Skipping recovery
>>>>>> of hierarchical allocator: nothing to recover
>>>>>> I1204 03:31:52.469641 31795 master.cpp:1447] Recovered 0 slaves from
>>>>>> the Registry (131B) ; allowing 10mins for slaves to re-register
>>>>>> I1204 03:31:52.470474 31795 replica.cpp:538] Replica received write
>>>>>> request for position 2 from (11488)@172.17.0.2:47200
>>>>>> I1204 03:31:52.509683 31795 leveldb.cpp:341] Persisting action (16
>>>>>> bytes) to leveldb took 39.16527ms
>>>>>> I1204 03:31:52.509734 31795 replica.cpp:713] Persisted action at 2
>>>>>> I1204 03:31:52.511015 31801 replica.cpp:692] Replica received learned
>>>>>> notice for position 2 from @0.0.0.0:0
>>>>>> I1204 03:31:52.546566 31801 leveldb.cpp:341] Persisting action (18
>>>>>> bytes) to leveldb took 35.510343ms
>>>>>> I1204 03:31:52.546649 31801 leveldb.cpp:399] Deleting ~1 keys from
>>>>>> leveldb took 42968ns
>>>>>> I1204 03:31:52.546674 31801 replica.cpp:713] Persisted action at 2
>>>>>> I1204 03:31:52.546696 31801 replica.cpp:698] Replica learned TRUNCATE
>>>>>> action at position 2
>>>>>> I1204 03:31:52.551092 31769 scheduler.cpp:154] Version: 0.27.0
>>>>>> I1204 03:31:52.552342 31798 scheduler.cpp:236] New master detected at
>>>>>> master@172.17.0.2:47200
>>>>>> I1204 03:31:52.553699 31795 scheduler.cpp:298] Sending SUBSCRIBE call
>>>>>> to master@172.17.0.2:47200
>>>>>> I1204 03:31:52.555797 31802 process.cpp:3067] Handling HTTP event for
>>>>>> process 'master' with path: '/master/api/v1/scheduler'
>>>>>> I1204 03:31:52.555894 31802 http.cpp:336] HTTP POST for
>>>>>> /master/api/v1/scheduler from 172.17.0.2:33004
>>>>>> I1204 03:31:52.556227 31802 master.cpp:1899] Received subscription
>>>>>> request for HTTP framework 'default'
>>>>>> I1204 03:31:52.556316 31802 master.cpp:1676] Authorizing framework
>>>>>> principal 'test-principal' to receive offers for role '*'
>>>>>> I1204 03:31:52.556674 31802 master.cpp:1991] Subscribing framework
>>>>>> 'default' with checkpointing disabled and capabilities [  ]
>>>>>> I1204 03:31:52.557163 31790 hierarchical.cpp:266] Added framework
>>>>>> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
>>>>>> I1204 03:31:52.557260 31790 hierarchical.cpp:1308] No resources
>>>>>> available to allocate!
>>>>>> I1204 03:31:52.557313 31790 hierarchical.cpp:1401] No inverse offers
>>>>>> to send out!
>>>>>> I1204 03:31:52.557312 31794 master.hpp:1583] Sending heartbeat to
>>>>>> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
>>>>>> I1204 03:31:52.557363 31790 hierarchical.cpp:1048] Performed
>>>>>> allocation for 0 slaves in 164108ns
>>>>>> I1204 03:31:52.558205 31802 scheduler.cpp:457] Enqueuing event
>>>>>> SUBSCRIBED received from master@172.17.0.2:47200
>>>>>> I1204 03:31:52.558789 31802 scheduler.cpp:457] Enqueuing event
>>>>>> HEARTBEAT received from master@172.17.0.2:47200
>>>>>> I1204 03:31:52.559478 31788 master_maintenance_tests.cpp:172]
>>>>>> Ignoring HEARTBEAT event
>>>>>> I1204 03:31:52.559605 31801 scheduler.cpp:298] Sending REQUEST call
>>>>>> to master@172.17.0.2:47200
>>>>>> I1204 03:31:52.561221 31803 process.cpp:3067] Handling HTTP event for
>>>>>> process 'master' with path: '/master/api/v1/scheduler'
>>>>>> I1204 03:31:52.561274 31803 http.cpp:336] HTTP POST for
>>>>>> /master/api/v1/scheduler from 172.17.0.2:33005
>>>>>> I1204 03:31:52.561362 31803 master.cpp:2646] Processing REQUEST call
>>>>>> for framework 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000 (default)
>>>>>> I1204 03:31:52.561527 31800 hierarchical.cpp:557] Received resource
>>>>>> request from framework 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
>>>>>> I1204 03:31:52.561843 31798 master.cpp:938] Master terminating
>>>>>> I1204 03:31:52.562047 31794 hierarchical.cpp:306] Removed framework
>>>>>> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
>>>>>> E1204 03:31:52.563323 31802 scheduler.cpp:431] End-Of-File received
>>>>>> from master. The master closed the event stream
>>>>>> [       OK ] ContentType/SchedulerTest.Request/0 (540 ms)
>>>>>> [ RUN      ] ContentType/SchedulerTest.Request/1
>>>>>> I1204 03:31:52.664904 31769 leveldb.cpp:174] Opened db in 95.062723ms
>>>>>> I1204 03:31:52.710089 31769 leveldb.cpp:181] Compacted db in
>>>>>> 45.135601ms
>>>>>> I1204 03:31:52.710189 31769 leveldb.cpp:196] Created db iterator in
>>>>>> 41589ns
>>>>>> I1204 03:31:52.710208 31769 leveldb.cpp:202] Seeked to beginning of
>>>>>> db in 1962ns
>>>>>> I1204 03:31:52.710218 31769 leveldb.cpp:271] Iterated through 0 keys
>>>>>> in the db in 280ns
>>>>>> I1204 03:31:52.710280 31769 replica.cpp:778] Replica recovered with
>>>>>> log positions 0 -> 0 with 1 holes and 0 unlearned
>>>>>> I1204 03:31:52.711068 31792 recover.cpp:447] Starting replica recovery
>>>>>> I1204 03:31:52.711433 31792 recover.cpp:473] Replica is in EMPTY
>>>>>> status
>>>>>> I1204 03:31:52.713116 31802 replica.cpp:674] Replica in EMPTY status
>>>>>> received a broadcasted recover request from (11493)@172.17.0.2:47200
>>>>>> I1204 03:31:52.713871 31800 recover.cpp:193] Received a recover
>>>>>> response from a replica in EMPTY status
>>>>>> I1204 03:31:52.714603 31799 recover.cpp:564] Updating replica status
>>>>>> to STARTING
>>>>>> I1204 03:31:52.715018 31800 master.cpp:365] Master
>>>>>> 82e2943a-0ffa-43db-ab30-d280bc15aad8 (403686b83bbb) started on
>>>>>> 172.17.0.2:47200
>>>>>> I1204 03:31:52.715071 31800 master.cpp:367] Flags at startup:
>>>>>> --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF"
>>>>>> --authenticate="false" --authenticate_slaves="true"
>>>>>> --authenticators="crammd5" --authorizers="local"
>>>>>> --credentials="/tmp/3FPUXP/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/3FPUXP/master" --zk_session_timeout="10secs"
>>>>>> I1204 03:31:52.715515 31800 master.cpp:414] Master allowing
>>>>>> unauthenticated frameworks to register
>>>>>> I1204 03:31:52.715529 31800 master.cpp:417] Master only allowing
>>>>>> authenticated slaves to register
>>>>>> I1204 03:31:52.715538 31800 credentials.hpp:35] Loading credentials
>>>>>> for authentication from '/tmp/3FPUXP/credentials'
>>>>>> I1204 03:31:52.715888 31800 master.cpp:456] Using default 'crammd5'
>>>>>> authenticator
>>>>>> I1204 03:31:52.716110 31800 master.cpp:493] Authorization enabled
>>>>>> I1204 03:31:52.716346 31799 whitelist_watcher.cpp:77] No whitelist
>>>>>> given
>>>>>> I1204 03:31:52.716421 31788 hierarchical.cpp:163] Initialized
>>>>>> hierarchical allocator process
>>>>>> I1204 03:31:52.718489 31798 master.cpp:1637] The newly elected leader
>>>>>> is master@172.17.0.2:47200 with id
>>>>>> 82e2943a-0ffa-43db-ab30-d280bc15aad8
>>>>>> I1204 03:31:52.718533 31798 master.cpp:1650] Elected as the leading
>>>>>> master!
>>>>>> I1204 03:31:52.718557 31798 master.cpp:1395] Recovering from registrar
>>>>>> I1204 03:31:52.718823 31803 registrar.cpp:307] Recovering registrar
>>>>>> I1204 03:31:52.743455 31790 leveldb.cpp:304] Persisting metadata (8
>>>>>> bytes) to leveldb took 28.301712ms
>>>>>> I1204 03:31:52.743496 31790 replica.cpp:321] Persisted replica status
>>>>>> to STARTING
>>>>>> I1204 03:31:52.743876 31795 recover.cpp:473] Replica is in STARTING
>>>>>> status
>>>>>> I1204 03:31:52.745254 31796 replica.cpp:674] Replica in STARTING
>>>>>> status received a broadcasted recover request from (11494)@
>>>>>> 172.17.0.2:47200
>>>>>> I1204 03:31:52.745743 31791 recover.cpp:193] Received a recover
>>>>>> response from a replica in STARTING status
>>>>>> I1204 03:31:52.746407 31797 recover.cpp:564] Updating replica status
>>>>>> to VOTING
>>>>>> I1204 03:31:52.768430 31802 leveldb.cpp:304] Persisting metadata (8
>>>>>> bytes) to leveldb took 21.81261ms
>>>>>> I1204 03:31:52.768474 31802 replica.cpp:321] Persisted replica status
>>>>>> to VOTING
>>>>>> I1204 03:31:52.768616 31802 recover.cpp:578] Successfully joined the
>>>>>> Paxos group
>>>>>> I1204 03:31:52.768904 31802 recover.cpp:462] Recover process
>>>>>> terminated
>>>>>> I1204 03:31:52.769584 31800 log.cpp:659] Attempting to start the
>>>>>> writer
>>>>>> I1204 03:31:52.771621 31789 replica.cpp:494] Replica received
>>>>>> implicit promise request from (11495)@172.17.0.2:47200 with proposal
>>>>>> 1
>>>>>> I1204 03:31:52.793648 31789 leveldb.cpp:304] Persisting metadata (8
>>>>>> bytes) to leveldb took 21.993492ms
>>>>>> I1204 03:31:52.793694 31789 replica.cpp:343] Persisted promised to 1
>>>>>> I1204 03:31:52.794865 31798 coordinator.cpp:238] Coordinator
>>>>>> attempting to fill missing positions
>>>>>> I1204 03:31:52.796506 31799 replica.cpp:389] Replica received
>>>>>> explicit promise request from (11496)@172.17.0.2:47200 for position
>>>>>> 0 with proposal 2
>>>>>> I1204 03:31:52.818649 31799 leveldb.cpp:341] Persisting action (8
>>>>>> bytes) to leveldb took 22.082655ms
>>>>>> I1204 03:31:52.818688 31799 replica.cpp:713] Persisted action at 0
>>>>>> I1204 03:31:52.820047 31801 replica.cpp:538] Replica received write
>>>>>> request for position 0 from (11497)@172.17.0.2:47200
>>>>>> I1204 03:31:52.820125 31801 leveldb.cpp:436] Reading position from
>>>>>> leveldb took 37411ns
>>>>>> I1204 03:31:52.843890 31801 leveldb.cpp:341] Persisting action (14
>>>>>> bytes) to leveldb took 23.710606ms
>>>>>> I1204 03:31:52.843935 31801 replica.cpp:713] Persisted action at 0
>>>>>> I1204 03:31:52.844709 31800 replica.cpp:692] Replica received learned
>>>>>> notice for position 0 from @0.0.0.0:0
>>>>>> I1204 03:31:52.868993 31800 leveldb.cpp:341] Persisting action (16
>>>>>> bytes) to leveldb took 24.242639ms
>>>>>> I1204 03:31:52.869032 31800 replica.cpp:713] Persisted action at 0
>>>>>> I1204 03:31:52.869055 31800 replica.cpp:698] Replica learned NOP
>>>>>> action at position 0
>>>>>> I1204 03:31:52.869815 31797 log.cpp:675] Writer started with ending
>>>>>> position 0
>>>>>> I1204 03:31:52.871470 31789 leveldb.cpp:436] Reading position from
>>>>>> leveldb took 40828ns
>>>>>> I1204 03:31:52.872885 31790 registrar.cpp:340] Successfully fetched
>>>>>> the registry (0B) in 154.009088ms
>>>>>> I1204 03:31:52.873096 31790 registrar.cpp:439] Applied 1 operations
>>>>>> in 32282ns; attempting to update the 'registry'
>>>>>> I1204 03:31:52.874133 31800 log.cpp:683] Attempting to append 170
>>>>>> bytes to the log
>>>>>> I1204 03:31:52.874337 31796 coordinator.cpp:348] Coordinator
>>>>>> attempting to write APPEND action at position 1
>>>>>> I1204 03:31:52.875277 31800 replica.cpp:538] Replica received write
>>>>>> request for position 1 from (11498)@172.17.0.2:47200
>>>>>> I1204 03:31:52.902500 31800 leveldb.cpp:341] Persisting action (189
>>>>>> bytes) to leveldb took 27.170365ms
>>>>>> I1204 03:31:52.902545 31800 replica.cpp:713] Persisted action at 1
>>>>>> I1204 03:31:52.903542 31798 replica.cpp:692] Replica received learned
>>>>>> notice for position 1 from @0.0.0.0:0
>>>>>> I1204 03:31:52.927577 31798 leveldb.cpp:341] Persisting action (191
>>>>>> bytes) to leveldb took 23.991773ms
>>>>>> I1204 03:31:52.927616 31798 replica.cpp:713] Persisted action at 1
>>>>>> I1204 03:31:52.927639 31798 replica.cpp:698] Replica learned APPEND
>>>>>> action at position 1
>>>>>> I1204 03:31:52.928863 31794 registrar.cpp:484] Successfully updated
>>>>>> the 'registry' in 55.643136ms
>>>>>> I1204 03:31:52.929076 31794 registrar.cpp:370] Successfully recovered
>>>>>> registrar
>>>>>> I1204 03:31:52.929177 31799 log.cpp:702] Attempting to truncate the
>>>>>> log to 1
>>>>>> I1204 03:31:52.929407 31797 coordinator.cpp:348] Coordinator
>>>>>> attempting to write TRUNCATE action at position 2
>>>>>> I1204 03:31:52.929703 31795 master.cpp:1447] Recovered 0 slaves from
>>>>>> the Registry (131B) ; allowing 10mins for slaves to re-register
>>>>>> I1204 03:31:52.929723 31799 hierarchical.cpp:181] Skipping recovery
>>>>>> of hierarchical allocator: nothing to recover
>>>>>> I1204 03:31:52.930577 31788 replica.cpp:538] Replica received write
>>>>>> request for position 2 from (11499)@172.17.0.2:47200
>>>>>> I1204 03:31:52.952744 31788 leveldb.cpp:341] Persisting action (16
>>>>>> bytes) to leveldb took 22.115164ms
>>>>>> I1204 03:31:52.952781 31788 replica.cpp:713] Persisted action at 2
>>>>>> I1204 03:31:52.953629 31798 replica.cpp:692] Replica received learned
>>>>>> notice for position 2 from @0.0.0.0:0
>>>>>> I1204 03:31:52.977794 31798 leveldb.cpp:341] Persisting action (18
>>>>>> bytes) to leveldb took 24.127932ms
>>>>>> I1204 03:31:52.977882 31798 leveldb.cpp:399] Deleting ~1 keys from
>>>>>> leveldb took 46051ns
>>>>>> I1204 03:31:52.977926 31798 replica.cpp:713] Persisted action at 2
>>>>>> I1204 03:31:52.977954 31798 replica.cpp:698] Replica learned TRUNCATE
>>>>>> action at position 2
>>>>>> I1204 03:31:52.981016 31769 scheduler.cpp:154] Version: 0.27.0
>>>>>> I1204 03:31:52.981828 31793 scheduler.cpp:236] New master detected at
>>>>>> master@172.17.0.2:47200
>>>>>> I1204 03:31:52.983167 31789 scheduler.cpp:298] Sending SUBSCRIBE call
>>>>>> to master@172.17.0.2:47200
>>>>>> I1204 03:31:52.985347 31789 process.cpp:3067] Handling HTTP event for
>>>>>> process 'master' with path: '/master/api/v1/scheduler'
>>>>>> I1204 03:31:52.985502 31789 http.cpp:336] HTTP POST for
>>>>>> /master/api/v1/scheduler from 172.17.0.2:33009
>>>>>> I1204 03:31:52.985939 31789 master.cpp:1899] Received subscription
>>>>>> request for HTTP framework 'default'
>>>>>> I1204 03:31:52.986045 31789 master.cpp:1676] Authorizing framework
>>>>>> principal 'test-principal' to receive offers for role '*'
>>>>>> I1204 03:31:52.986364 31789 master.cpp:1991] Subscribing framework
>>>>>> 'default' with checkpointing disabled and capabilities [  ]
>>>>>> I1204 03:31:52.986779 31799 hierarchical.cpp:266] Added framework
>>>>>> 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
>>>>>> I1204 03:31:52.986913 31796 master.hpp:1583] Sending heartbeat to
>>>>>> 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
>>>>>> I1204 03:31:52.986996 31799 hierarchical.cpp:1308] No resources
>>>>>> available to allocate!
>>>>>> I1204 03:31:52.987063 31799 hierarchical.cpp:1401] No inverse offers
>>>>>> to send out!
>>>>>> I1204 03:31:52.987110 31799 hierarchical.cpp:1048] Performed
>>>>>> allocation for 0 slaves in 189242ns
>>>>>> I1204 03:31:52.987913 31798 scheduler.cpp:457] Enqueuing event
>>>>>> SUBSCRIBED received from master@172.17.0.2:47200
>>>>>> I1204 03:31:52.988831 31798 scheduler.cpp:457] Enqueuing event
>>>>>> HEARTBEAT received from master@172.17.0.2:47200
>>>>>> I1204 03:31:52.989537 31788 master_maintenance_tests.cpp:172]
>>>>>> Ignoring HEARTBEAT event
>>>>>> I1204 03:31:52.989886 31801 scheduler.cpp:298] Sending REQUEST call
>>>>>> to master@172.17.0.2:47200
>>>>>> I1204 03:31:52.991730 31792 process.cpp:3067] Handling HTTP event for
>>>>>> process 'master' with path: '/master/api/v1/scheduler'
>>>>>> I1204 03:31:52.991812 31792 http.cpp:336] HTTP POST for
>>>>>> /master/api/v1/scheduler from 172.17.0.2:33010
>>>>>> I1204 03:31:52.992156 31792 master.cpp:2646] Processing REQUEST call
>>>>>> for framework 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000 (default)
>>>>>> I1204 03:31:52.992516 31790 hierarchical.cpp:557] Received resource
>>>>>> request from framework 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
>>>>>> I1204 03:31:52.992923 31800 master.cpp:938] Master terminating
>>>>>> I1204 03:31:52.993132 31796 hierarchical.cpp:306] Removed framework
>>>>>> 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
>>>>>> E1204 03:31:52.993708 31798 scheduler.cpp:431] End-Of-File received
>>>>>> from master. The master closed the event stream
>>>>>> [       OK ] ContentType/SchedulerTest.Request/1 (431 ms)
>>>>>> [----------] 22 tests from ContentType/SchedulerTest (15741 ms total)
>>>>>>
>>>>>> [----------] Global test environment tear-down
>>>>>> [==========] 878 tests from 116 test cases ran. (711169 ms total)
>>>>>> [  PASSED  ] 877 tests.
>>>>>> [  FAILED  ] 1 test, listed below:
>>>>>> [  FAILED  ] ReservationTest.ACLMultipleOperations
>>>>>>
>>>>>>  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-1449197270-18036
>>>>>> Untagged: mesos-1449197270-18036:latest
>>>>>> Deleted:
>>>>>> 71bc3adfccbfe4c515166abab14facf5895235fd4358c75eafe7552377b4ed12
>>>>>> Deleted:
>>>>>> c04522c46bffaa92efd2450d00842a14171f47c8ae50942666829e4dca2a7ada
>>>>>> Deleted:
>>>>>> d5849061eee06f14b51d9d7237588a0fe83fd953abfc1713692bd1247d04220f
>>>>>> Deleted:
>>>>>> 20d1e630457de2edba4f2fabe62ee3bcc7de4243ec737ce2a545a83de876613d
>>>>>> Deleted:
>>>>>> 64bba51bd0cdcb0d983deeb4cd1aa27ceb02bd4703c24f2692024c5a1537de44
>>>>>> Deleted:
>>>>>> 59e85ec64b5ee2735cde5403fe8def7375ffca98f9ea7953c802705673efb8cd
>>>>>> Deleted:
>>>>>> bee88887921d3d7d38f87744f4f49cb346037ce8a8b09af9d29686376200d66e
>>>>>> Deleted:
>>>>>> 709b8b667cf349fbcf14fbc48a0316319b341baaa1dd61f6a48c66d37b2dc628
>>>>>> Deleted:
>>>>>> e2c4f6d787499248e303270ff419e2545075e24a83101ed5316f4ecc907bba69
>>>>>> Deleted:
>>>>>> 0b8ee088204fbd6b9b1fa2f1a503763106b444f6a0b5d64ad6136269f821e487
>>>>>> Deleted:
>>>>>> 5657d8070e24ed2e2c43b0ac6ac0536208680be1f4e18031f5c76fd722aff863
>>>>>> Deleted:
>>>>>> 5e4dcfbaf3cc159742402a11e2c8b27efa71ec0ec202abd22acf5f553691f9c6
>>>>>> Deleted:
>>>>>> f589a283ec591fb354c074375571f136e15baa088534a380ac69255b6565ecdd
>>>>>> Build step 'Execute shell' marked build as failure
>>>>>>
>>>>>
>>>>>
>>>

Re: Build failed in Jenkins: Mesos » gcc,--verbose --enable-libevent --enable-ssl,ubuntu:14.04,docker||Hadoop #1319

Posted by Michael Park <mp...@mesosphere.io>.
+Jie Yu <yu...@gmail.com>

I've filed https://issues.apache.org/jira/browse/MESOS-4067. I've also
figured out at least one of the issues, left a description of it in the
comments + possible fixes.

On Thu, Dec 3, 2015 at 10:51 PM Michael Park <mp...@mesosphere.io> wrote:

> Jie, but I also helped out so I can look into it once I get on a computer.
>
> On Thu, Dec 3, 2015, 10:50 PM Benjamin Mahler <be...@gmail.com>
> wrote:
>
>> Got it. Who shepherded it?
>>
>> On Thu, Dec 3, 2015 at 7:38 PM, Michael Park <mp...@mesosphere.io> wrote:
>>
>>> +Greg since he's the author, he might have a better idea
>>>
>>> On Thu, Dec 3, 2015, 10:36 PM Benjamin Mahler <be...@gmail.com>
>>> wrote:
>>>
>>>> Michael can you please triage this test?
>>>>
>>>> On Thu, Dec 3, 2015 at 7:31 PM, Apache Jenkins Server <
>>>> jenkins@builds.apache.org> wrote:
>>>>
>>>>> See <
>>>>> https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose%20--enable-libevent%20--enable-ssl,OS=ubuntu%3A14.04,label_exp=docker%7C%7CHadoop/1319/changes
>>>>> >
>>>>>
>>>>> Changes:
>>>>>
>>>>> [benjamin.mahler] Documented why OsSignalsTest.Suppress works on OS X.
>>>>>
>>>>> ------------------------------------------
>>>>> [...truncated 151042 lines...]
>>>>> I1204 03:31:52.023347 31790 gc.cpp:54] Scheduling
>>>>> '/tmp/ContentType_SchedulerTest_Message_1_jkcDGA/slaves/e567d75e-4b42-4184-a487-498d6e3e86f0-S0/frameworks/e567d75e-4b42-4184-a487-498d6e3e86f0-0000/executors/default/runs/ad6c9ae3-14b4-4ae0-85e0-2b66874c1d0f'
>>>>> for gc 6.99999973126222days in the future
>>>>> I1204 03:31:52.023437 31792 slave.cpp:3773] Cleaning up framework
>>>>> e567d75e-4b42-4184-a487-498d6e3e86f0-0000
>>>>> I1204 03:31:52.023515 31790 gc.cpp:54] Scheduling
>>>>> '/tmp/ContentType_SchedulerTest_Message_1_jkcDGA/slaves/e567d75e-4b42-4184-a487-498d6e3e86f0-S0/frameworks/e567d75e-4b42-4184-a487-498d6e3e86f0-0000/executors/default'
>>>>> for gc 6.99999972944593days in the future
>>>>> I1204 03:31:52.023558 31794 status_update_manager.cpp:282] Closing
>>>>> status update streams for framework
>>>>> e567d75e-4b42-4184-a487-498d6e3e86f0-0000
>>>>> I1204 03:31:52.023623 31794 status_update_manager.cpp:528] Cleaning up
>>>>> status update stream for task 3ee27512-7308-4ddf-8ab0-eb17196ad555 of
>>>>> framework e567d75e-4b42-4184-a487-498d6e3e86f0-0000
>>>>> I1204 03:31:52.023661 31790 gc.cpp:54] Scheduling
>>>>> '/tmp/ContentType_SchedulerTest_Message_1_jkcDGA/slaves/e567d75e-4b42-4184-a487-498d6e3e86f0-S0/frameworks/e567d75e-4b42-4184-a487-498d6e3e86f0-0000'
>>>>> for gc 6.99999972689778days in the future
>>>>> [       OK ] ContentType/SchedulerTest.Message/1 (675 ms)
>>>>> [ RUN      ] ContentType/SchedulerTest.Request/0
>>>>> I1204 03:31:52.124193 31769 leveldb.cpp:174] Opened db in 94.016525ms
>>>>> I1204 03:31:52.149694 31769 leveldb.cpp:181] Compacted db in
>>>>> 25.458791ms
>>>>> I1204 03:31:52.149760 31769 leveldb.cpp:196] Created db iterator in
>>>>> 20834ns
>>>>> I1204 03:31:52.149780 31769 leveldb.cpp:202] Seeked to beginning of db
>>>>> in 1977ns
>>>>> I1204 03:31:52.149791 31769 leveldb.cpp:271] Iterated through 0 keys
>>>>> in the db in 303ns
>>>>> I1204 03:31:52.149832 31769 replica.cpp:778] Replica recovered with
>>>>> log positions 0 -> 0 with 1 holes and 0 unlearned
>>>>> I1204 03:31:52.150544 31791 recover.cpp:447] Starting replica recovery
>>>>> I1204 03:31:52.151046 31791 recover.cpp:473] Replica is in EMPTY status
>>>>> I1204 03:31:52.152299 31802 replica.cpp:674] Replica in EMPTY status
>>>>> received a broadcasted recover request from (11482)@172.17.0.2:47200
>>>>> I1204 03:31:52.152914 31801 recover.cpp:193] Received a recover
>>>>> response from a replica in EMPTY status
>>>>> I1204 03:31:52.153547 31799 recover.cpp:564] Updating replica status
>>>>> to STARTING
>>>>> I1204 03:31:52.153744 31803 master.cpp:365] Master
>>>>> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe (403686b83bbb) started on
>>>>> 172.17.0.2:47200
>>>>> I1204 03:31:52.153775 31803 master.cpp:367] Flags at startup:
>>>>> --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF"
>>>>> --authenticate="false" --authenticate_slaves="true"
>>>>> --authenticators="crammd5" --authorizers="local"
>>>>> --credentials="/tmp/0wBPVf/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/0wBPVf/master" --zk_session_timeout="10secs"
>>>>> I1204 03:31:52.154326 31803 master.cpp:414] Master allowing
>>>>> unauthenticated frameworks to register
>>>>> I1204 03:31:52.154345 31803 master.cpp:417] Master only allowing
>>>>> authenticated slaves to register
>>>>> I1204 03:31:52.154361 31803 credentials.hpp:35] Loading credentials
>>>>> for authentication from '/tmp/0wBPVf/credentials'
>>>>> I1204 03:31:52.154675 31803 master.cpp:456] Using default 'crammd5'
>>>>> authenticator
>>>>> I1204 03:31:52.154832 31803 master.cpp:493] Authorization enabled
>>>>> I1204 03:31:52.155102 31788 whitelist_watcher.cpp:77] No whitelist
>>>>> given
>>>>> I1204 03:31:52.155231 31796 hierarchical.cpp:163] Initialized
>>>>> hierarchical allocator process
>>>>> I1204 03:31:52.157017 31791 master.cpp:1637] The newly elected leader
>>>>> is master@172.17.0.2:47200 with id
>>>>> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe
>>>>> I1204 03:31:52.157053 31791 master.cpp:1650] Elected as the leading
>>>>> master!
>>>>> I1204 03:31:52.157073 31791 master.cpp:1395] Recovering from registrar
>>>>> I1204 03:31:52.157237 31796 registrar.cpp:307] Recovering registrar
>>>>> I1204 03:31:52.186647 31798 leveldb.cpp:304] Persisting metadata (8
>>>>> bytes) to leveldb took 32.571067ms
>>>>> I1204 03:31:52.186686 31798 replica.cpp:321] Persisted replica status
>>>>> to STARTING
>>>>> I1204 03:31:52.187000 31803 recover.cpp:473] Replica is in STARTING
>>>>> status
>>>>> I1204 03:31:52.188062 31800 replica.cpp:674] Replica in STARTING
>>>>> status received a broadcasted recover request from (11483)@
>>>>> 172.17.0.2:47200
>>>>> I1204 03:31:52.188350 31792 recover.cpp:193] Received a recover
>>>>> response from a replica in STARTING status
>>>>> I1204 03:31:52.188809 31796 recover.cpp:564] Updating replica status
>>>>> to VOTING
>>>>> I1204 03:31:52.220109 31797 leveldb.cpp:304] Persisting metadata (8
>>>>> bytes) to leveldb took 31.054929ms
>>>>> I1204 03:31:52.220147 31797 replica.cpp:321] Persisted replica status
>>>>> to VOTING
>>>>> I1204 03:31:52.220288 31792 recover.cpp:578] Successfully joined the
>>>>> Paxos group
>>>>> I1204 03:31:52.220634 31792 recover.cpp:462] Recover process terminated
>>>>> I1204 03:31:52.221151 31802 log.cpp:659] Attempting to start the writer
>>>>> I1204 03:31:52.222534 31801 replica.cpp:494] Replica received implicit
>>>>> promise request from (11484)@172.17.0.2:47200 with proposal 1
>>>>> I1204 03:31:52.245628 31801 leveldb.cpp:304] Persisting metadata (8
>>>>> bytes) to leveldb took 23.049981ms
>>>>> I1204 03:31:52.245667 31801 replica.cpp:343] Persisted promised to 1
>>>>> I1204 03:31:52.246343 31793 coordinator.cpp:238] Coordinator
>>>>> attempting to fill missing positions
>>>>> I1204 03:31:52.247530 31788 replica.cpp:389] Replica received explicit
>>>>> promise request from (11485)@172.17.0.2:47200 for position 0 with
>>>>> proposal 2
>>>>> I1204 03:31:52.287514 31788 leveldb.cpp:341] Persisting action (8
>>>>> bytes) to leveldb took 39.94388ms
>>>>> I1204 03:31:52.287552 31788 replica.cpp:713] Persisted action at 0
>>>>> I1204 03:31:52.288843 31802 replica.cpp:538] Replica received write
>>>>> request for position 0 from (11486)@172.17.0.2:47200
>>>>> I1204 03:31:52.288903 31802 leveldb.cpp:436] Reading position from
>>>>> leveldb took 29125ns
>>>>> I1204 03:31:52.329651 31802 leveldb.cpp:341] Persisting action (14
>>>>> bytes) to leveldb took 40.69596ms
>>>>> I1204 03:31:52.329701 31802 replica.cpp:713] Persisted action at 0
>>>>> I1204 03:31:52.330826 31800 replica.cpp:692] Replica received learned
>>>>> notice for position 0 from @0.0.0.0:0
>>>>> I1204 03:31:52.383780 31800 leveldb.cpp:341] Persisting action (16
>>>>> bytes) to leveldb took 52.909056ms
>>>>> I1204 03:31:52.383831 31800 replica.cpp:713] Persisted action at 0
>>>>> I1204 03:31:52.383858 31800 replica.cpp:698] Replica learned NOP
>>>>> action at position 0
>>>>> I1204 03:31:52.384644 31794 log.cpp:675] Writer started with ending
>>>>> position 0
>>>>> I1204 03:31:52.385828 31791 leveldb.cpp:436] Reading position from
>>>>> leveldb took 33950ns
>>>>> I1204 03:31:52.386934 31791 registrar.cpp:340] Successfully fetched
>>>>> the registry (0B) in 229.636864ms
>>>>> I1204 03:31:52.387066 31791 registrar.cpp:439] Applied 1 operations in
>>>>> 36217ns; attempting to update the 'registry'
>>>>> I1204 03:31:52.387809 31794 log.cpp:683] Attempting to append 170
>>>>> bytes to the log
>>>>> I1204 03:31:52.387995 31798 coordinator.cpp:348] Coordinator
>>>>> attempting to write APPEND action at position 1
>>>>> I1204 03:31:52.388667 31802 replica.cpp:538] Replica received write
>>>>> request for position 1 from (11487)@172.17.0.2:47200
>>>>> I1204 03:31:52.434088 31802 leveldb.cpp:341] Persisting action (189
>>>>> bytes) to leveldb took 45.373715ms
>>>>> I1204 03:31:52.434159 31802 replica.cpp:713] Persisted action at 1
>>>>> I1204 03:31:52.435035 31803 replica.cpp:692] Replica received learned
>>>>> notice for position 1 from @0.0.0.0:0
>>>>> I1204 03:31:52.467439 31803 leveldb.cpp:341] Persisting action (191
>>>>> bytes) to leveldb took 32.356386ms
>>>>> I1204 03:31:52.467502 31803 replica.cpp:713] Persisted action at 1
>>>>> I1204 03:31:52.467533 31803 replica.cpp:698] Replica learned APPEND
>>>>> action at position 1
>>>>> I1204 03:31:52.468945 31789 registrar.cpp:484] Successfully updated
>>>>> the 'registry' in 81.793792ms
>>>>> I1204 03:31:52.469149 31789 registrar.cpp:370] Successfully recovered
>>>>> registrar
>>>>> I1204 03:31:52.469293 31796 log.cpp:702] Attempting to truncate the
>>>>> log to 1
>>>>> I1204 03:31:52.469637 31797 coordinator.cpp:348] Coordinator
>>>>> attempting to write TRUNCATE action at position 2
>>>>> I1204 03:31:52.469657 31802 hierarchical.cpp:181] Skipping recovery of
>>>>> hierarchical allocator: nothing to recover
>>>>> I1204 03:31:52.469641 31795 master.cpp:1447] Recovered 0 slaves from
>>>>> the Registry (131B) ; allowing 10mins for slaves to re-register
>>>>> I1204 03:31:52.470474 31795 replica.cpp:538] Replica received write
>>>>> request for position 2 from (11488)@172.17.0.2:47200
>>>>> I1204 03:31:52.509683 31795 leveldb.cpp:341] Persisting action (16
>>>>> bytes) to leveldb took 39.16527ms
>>>>> I1204 03:31:52.509734 31795 replica.cpp:713] Persisted action at 2
>>>>> I1204 03:31:52.511015 31801 replica.cpp:692] Replica received learned
>>>>> notice for position 2 from @0.0.0.0:0
>>>>> I1204 03:31:52.546566 31801 leveldb.cpp:341] Persisting action (18
>>>>> bytes) to leveldb took 35.510343ms
>>>>> I1204 03:31:52.546649 31801 leveldb.cpp:399] Deleting ~1 keys from
>>>>> leveldb took 42968ns
>>>>> I1204 03:31:52.546674 31801 replica.cpp:713] Persisted action at 2
>>>>> I1204 03:31:52.546696 31801 replica.cpp:698] Replica learned TRUNCATE
>>>>> action at position 2
>>>>> I1204 03:31:52.551092 31769 scheduler.cpp:154] Version: 0.27.0
>>>>> I1204 03:31:52.552342 31798 scheduler.cpp:236] New master detected at
>>>>> master@172.17.0.2:47200
>>>>> I1204 03:31:52.553699 31795 scheduler.cpp:298] Sending SUBSCRIBE call
>>>>> to master@172.17.0.2:47200
>>>>> I1204 03:31:52.555797 31802 process.cpp:3067] Handling HTTP event for
>>>>> process 'master' with path: '/master/api/v1/scheduler'
>>>>> I1204 03:31:52.555894 31802 http.cpp:336] HTTP POST for
>>>>> /master/api/v1/scheduler from 172.17.0.2:33004
>>>>> I1204 03:31:52.556227 31802 master.cpp:1899] Received subscription
>>>>> request for HTTP framework 'default'
>>>>> I1204 03:31:52.556316 31802 master.cpp:1676] Authorizing framework
>>>>> principal 'test-principal' to receive offers for role '*'
>>>>> I1204 03:31:52.556674 31802 master.cpp:1991] Subscribing framework
>>>>> 'default' with checkpointing disabled and capabilities [  ]
>>>>> I1204 03:31:52.557163 31790 hierarchical.cpp:266] Added framework
>>>>> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
>>>>> I1204 03:31:52.557260 31790 hierarchical.cpp:1308] No resources
>>>>> available to allocate!
>>>>> I1204 03:31:52.557313 31790 hierarchical.cpp:1401] No inverse offers
>>>>> to send out!
>>>>> I1204 03:31:52.557312 31794 master.hpp:1583] Sending heartbeat to
>>>>> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
>>>>> I1204 03:31:52.557363 31790 hierarchical.cpp:1048] Performed
>>>>> allocation for 0 slaves in 164108ns
>>>>> I1204 03:31:52.558205 31802 scheduler.cpp:457] Enqueuing event
>>>>> SUBSCRIBED received from master@172.17.0.2:47200
>>>>> I1204 03:31:52.558789 31802 scheduler.cpp:457] Enqueuing event
>>>>> HEARTBEAT received from master@172.17.0.2:47200
>>>>> I1204 03:31:52.559478 31788 master_maintenance_tests.cpp:172] Ignoring
>>>>> HEARTBEAT event
>>>>> I1204 03:31:52.559605 31801 scheduler.cpp:298] Sending REQUEST call to
>>>>> master@172.17.0.2:47200
>>>>> I1204 03:31:52.561221 31803 process.cpp:3067] Handling HTTP event for
>>>>> process 'master' with path: '/master/api/v1/scheduler'
>>>>> I1204 03:31:52.561274 31803 http.cpp:336] HTTP POST for
>>>>> /master/api/v1/scheduler from 172.17.0.2:33005
>>>>> I1204 03:31:52.561362 31803 master.cpp:2646] Processing REQUEST call
>>>>> for framework 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000 (default)
>>>>> I1204 03:31:52.561527 31800 hierarchical.cpp:557] Received resource
>>>>> request from framework 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
>>>>> I1204 03:31:52.561843 31798 master.cpp:938] Master terminating
>>>>> I1204 03:31:52.562047 31794 hierarchical.cpp:306] Removed framework
>>>>> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
>>>>> E1204 03:31:52.563323 31802 scheduler.cpp:431] End-Of-File received
>>>>> from master. The master closed the event stream
>>>>> [       OK ] ContentType/SchedulerTest.Request/0 (540 ms)
>>>>> [ RUN      ] ContentType/SchedulerTest.Request/1
>>>>> I1204 03:31:52.664904 31769 leveldb.cpp:174] Opened db in 95.062723ms
>>>>> I1204 03:31:52.710089 31769 leveldb.cpp:181] Compacted db in
>>>>> 45.135601ms
>>>>> I1204 03:31:52.710189 31769 leveldb.cpp:196] Created db iterator in
>>>>> 41589ns
>>>>> I1204 03:31:52.710208 31769 leveldb.cpp:202] Seeked to beginning of db
>>>>> in 1962ns
>>>>> I1204 03:31:52.710218 31769 leveldb.cpp:271] Iterated through 0 keys
>>>>> in the db in 280ns
>>>>> I1204 03:31:52.710280 31769 replica.cpp:778] Replica recovered with
>>>>> log positions 0 -> 0 with 1 holes and 0 unlearned
>>>>> I1204 03:31:52.711068 31792 recover.cpp:447] Starting replica recovery
>>>>> I1204 03:31:52.711433 31792 recover.cpp:473] Replica is in EMPTY status
>>>>> I1204 03:31:52.713116 31802 replica.cpp:674] Replica in EMPTY status
>>>>> received a broadcasted recover request from (11493)@172.17.0.2:47200
>>>>> I1204 03:31:52.713871 31800 recover.cpp:193] Received a recover
>>>>> response from a replica in EMPTY status
>>>>> I1204 03:31:52.714603 31799 recover.cpp:564] Updating replica status
>>>>> to STARTING
>>>>> I1204 03:31:52.715018 31800 master.cpp:365] Master
>>>>> 82e2943a-0ffa-43db-ab30-d280bc15aad8 (403686b83bbb) started on
>>>>> 172.17.0.2:47200
>>>>> I1204 03:31:52.715071 31800 master.cpp:367] Flags at startup:
>>>>> --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF"
>>>>> --authenticate="false" --authenticate_slaves="true"
>>>>> --authenticators="crammd5" --authorizers="local"
>>>>> --credentials="/tmp/3FPUXP/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/3FPUXP/master" --zk_session_timeout="10secs"
>>>>> I1204 03:31:52.715515 31800 master.cpp:414] Master allowing
>>>>> unauthenticated frameworks to register
>>>>> I1204 03:31:52.715529 31800 master.cpp:417] Master only allowing
>>>>> authenticated slaves to register
>>>>> I1204 03:31:52.715538 31800 credentials.hpp:35] Loading credentials
>>>>> for authentication from '/tmp/3FPUXP/credentials'
>>>>> I1204 03:31:52.715888 31800 master.cpp:456] Using default 'crammd5'
>>>>> authenticator
>>>>> I1204 03:31:52.716110 31800 master.cpp:493] Authorization enabled
>>>>> I1204 03:31:52.716346 31799 whitelist_watcher.cpp:77] No whitelist
>>>>> given
>>>>> I1204 03:31:52.716421 31788 hierarchical.cpp:163] Initialized
>>>>> hierarchical allocator process
>>>>> I1204 03:31:52.718489 31798 master.cpp:1637] The newly elected leader
>>>>> is master@172.17.0.2:47200 with id
>>>>> 82e2943a-0ffa-43db-ab30-d280bc15aad8
>>>>> I1204 03:31:52.718533 31798 master.cpp:1650] Elected as the leading
>>>>> master!
>>>>> I1204 03:31:52.718557 31798 master.cpp:1395] Recovering from registrar
>>>>> I1204 03:31:52.718823 31803 registrar.cpp:307] Recovering registrar
>>>>> I1204 03:31:52.743455 31790 leveldb.cpp:304] Persisting metadata (8
>>>>> bytes) to leveldb took 28.301712ms
>>>>> I1204 03:31:52.743496 31790 replica.cpp:321] Persisted replica status
>>>>> to STARTING
>>>>> I1204 03:31:52.743876 31795 recover.cpp:473] Replica is in STARTING
>>>>> status
>>>>> I1204 03:31:52.745254 31796 replica.cpp:674] Replica in STARTING
>>>>> status received a broadcasted recover request from (11494)@
>>>>> 172.17.0.2:47200
>>>>> I1204 03:31:52.745743 31791 recover.cpp:193] Received a recover
>>>>> response from a replica in STARTING status
>>>>> I1204 03:31:52.746407 31797 recover.cpp:564] Updating replica status
>>>>> to VOTING
>>>>> I1204 03:31:52.768430 31802 leveldb.cpp:304] Persisting metadata (8
>>>>> bytes) to leveldb took 21.81261ms
>>>>> I1204 03:31:52.768474 31802 replica.cpp:321] Persisted replica status
>>>>> to VOTING
>>>>> I1204 03:31:52.768616 31802 recover.cpp:578] Successfully joined the
>>>>> Paxos group
>>>>> I1204 03:31:52.768904 31802 recover.cpp:462] Recover process terminated
>>>>> I1204 03:31:52.769584 31800 log.cpp:659] Attempting to start the writer
>>>>> I1204 03:31:52.771621 31789 replica.cpp:494] Replica received implicit
>>>>> promise request from (11495)@172.17.0.2:47200 with proposal 1
>>>>> I1204 03:31:52.793648 31789 leveldb.cpp:304] Persisting metadata (8
>>>>> bytes) to leveldb took 21.993492ms
>>>>> I1204 03:31:52.793694 31789 replica.cpp:343] Persisted promised to 1
>>>>> I1204 03:31:52.794865 31798 coordinator.cpp:238] Coordinator
>>>>> attempting to fill missing positions
>>>>> I1204 03:31:52.796506 31799 replica.cpp:389] Replica received explicit
>>>>> promise request from (11496)@172.17.0.2:47200 for position 0 with
>>>>> proposal 2
>>>>> I1204 03:31:52.818649 31799 leveldb.cpp:341] Persisting action (8
>>>>> bytes) to leveldb took 22.082655ms
>>>>> I1204 03:31:52.818688 31799 replica.cpp:713] Persisted action at 0
>>>>> I1204 03:31:52.820047 31801 replica.cpp:538] Replica received write
>>>>> request for position 0 from (11497)@172.17.0.2:47200
>>>>> I1204 03:31:52.820125 31801 leveldb.cpp:436] Reading position from
>>>>> leveldb took 37411ns
>>>>> I1204 03:31:52.843890 31801 leveldb.cpp:341] Persisting action (14
>>>>> bytes) to leveldb took 23.710606ms
>>>>> I1204 03:31:52.843935 31801 replica.cpp:713] Persisted action at 0
>>>>> I1204 03:31:52.844709 31800 replica.cpp:692] Replica received learned
>>>>> notice for position 0 from @0.0.0.0:0
>>>>> I1204 03:31:52.868993 31800 leveldb.cpp:341] Persisting action (16
>>>>> bytes) to leveldb took 24.242639ms
>>>>> I1204 03:31:52.869032 31800 replica.cpp:713] Persisted action at 0
>>>>> I1204 03:31:52.869055 31800 replica.cpp:698] Replica learned NOP
>>>>> action at position 0
>>>>> I1204 03:31:52.869815 31797 log.cpp:675] Writer started with ending
>>>>> position 0
>>>>> I1204 03:31:52.871470 31789 leveldb.cpp:436] Reading position from
>>>>> leveldb took 40828ns
>>>>> I1204 03:31:52.872885 31790 registrar.cpp:340] Successfully fetched
>>>>> the registry (0B) in 154.009088ms
>>>>> I1204 03:31:52.873096 31790 registrar.cpp:439] Applied 1 operations in
>>>>> 32282ns; attempting to update the 'registry'
>>>>> I1204 03:31:52.874133 31800 log.cpp:683] Attempting to append 170
>>>>> bytes to the log
>>>>> I1204 03:31:52.874337 31796 coordinator.cpp:348] Coordinator
>>>>> attempting to write APPEND action at position 1
>>>>> I1204 03:31:52.875277 31800 replica.cpp:538] Replica received write
>>>>> request for position 1 from (11498)@172.17.0.2:47200
>>>>> I1204 03:31:52.902500 31800 leveldb.cpp:341] Persisting action (189
>>>>> bytes) to leveldb took 27.170365ms
>>>>> I1204 03:31:52.902545 31800 replica.cpp:713] Persisted action at 1
>>>>> I1204 03:31:52.903542 31798 replica.cpp:692] Replica received learned
>>>>> notice for position 1 from @0.0.0.0:0
>>>>> I1204 03:31:52.927577 31798 leveldb.cpp:341] Persisting action (191
>>>>> bytes) to leveldb took 23.991773ms
>>>>> I1204 03:31:52.927616 31798 replica.cpp:713] Persisted action at 1
>>>>> I1204 03:31:52.927639 31798 replica.cpp:698] Replica learned APPEND
>>>>> action at position 1
>>>>> I1204 03:31:52.928863 31794 registrar.cpp:484] Successfully updated
>>>>> the 'registry' in 55.643136ms
>>>>> I1204 03:31:52.929076 31794 registrar.cpp:370] Successfully recovered
>>>>> registrar
>>>>> I1204 03:31:52.929177 31799 log.cpp:702] Attempting to truncate the
>>>>> log to 1
>>>>> I1204 03:31:52.929407 31797 coordinator.cpp:348] Coordinator
>>>>> attempting to write TRUNCATE action at position 2
>>>>> I1204 03:31:52.929703 31795 master.cpp:1447] Recovered 0 slaves from
>>>>> the Registry (131B) ; allowing 10mins for slaves to re-register
>>>>> I1204 03:31:52.929723 31799 hierarchical.cpp:181] Skipping recovery of
>>>>> hierarchical allocator: nothing to recover
>>>>> I1204 03:31:52.930577 31788 replica.cpp:538] Replica received write
>>>>> request for position 2 from (11499)@172.17.0.2:47200
>>>>> I1204 03:31:52.952744 31788 leveldb.cpp:341] Persisting action (16
>>>>> bytes) to leveldb took 22.115164ms
>>>>> I1204 03:31:52.952781 31788 replica.cpp:713] Persisted action at 2
>>>>> I1204 03:31:52.953629 31798 replica.cpp:692] Replica received learned
>>>>> notice for position 2 from @0.0.0.0:0
>>>>> I1204 03:31:52.977794 31798 leveldb.cpp:341] Persisting action (18
>>>>> bytes) to leveldb took 24.127932ms
>>>>> I1204 03:31:52.977882 31798 leveldb.cpp:399] Deleting ~1 keys from
>>>>> leveldb took 46051ns
>>>>> I1204 03:31:52.977926 31798 replica.cpp:713] Persisted action at 2
>>>>> I1204 03:31:52.977954 31798 replica.cpp:698] Replica learned TRUNCATE
>>>>> action at position 2
>>>>> I1204 03:31:52.981016 31769 scheduler.cpp:154] Version: 0.27.0
>>>>> I1204 03:31:52.981828 31793 scheduler.cpp:236] New master detected at
>>>>> master@172.17.0.2:47200
>>>>> I1204 03:31:52.983167 31789 scheduler.cpp:298] Sending SUBSCRIBE call
>>>>> to master@172.17.0.2:47200
>>>>> I1204 03:31:52.985347 31789 process.cpp:3067] Handling HTTP event for
>>>>> process 'master' with path: '/master/api/v1/scheduler'
>>>>> I1204 03:31:52.985502 31789 http.cpp:336] HTTP POST for
>>>>> /master/api/v1/scheduler from 172.17.0.2:33009
>>>>> I1204 03:31:52.985939 31789 master.cpp:1899] Received subscription
>>>>> request for HTTP framework 'default'
>>>>> I1204 03:31:52.986045 31789 master.cpp:1676] Authorizing framework
>>>>> principal 'test-principal' to receive offers for role '*'
>>>>> I1204 03:31:52.986364 31789 master.cpp:1991] Subscribing framework
>>>>> 'default' with checkpointing disabled and capabilities [  ]
>>>>> I1204 03:31:52.986779 31799 hierarchical.cpp:266] Added framework
>>>>> 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
>>>>> I1204 03:31:52.986913 31796 master.hpp:1583] Sending heartbeat to
>>>>> 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
>>>>> I1204 03:31:52.986996 31799 hierarchical.cpp:1308] No resources
>>>>> available to allocate!
>>>>> I1204 03:31:52.987063 31799 hierarchical.cpp:1401] No inverse offers
>>>>> to send out!
>>>>> I1204 03:31:52.987110 31799 hierarchical.cpp:1048] Performed
>>>>> allocation for 0 slaves in 189242ns
>>>>> I1204 03:31:52.987913 31798 scheduler.cpp:457] Enqueuing event
>>>>> SUBSCRIBED received from master@172.17.0.2:47200
>>>>> I1204 03:31:52.988831 31798 scheduler.cpp:457] Enqueuing event
>>>>> HEARTBEAT received from master@172.17.0.2:47200
>>>>> I1204 03:31:52.989537 31788 master_maintenance_tests.cpp:172] Ignoring
>>>>> HEARTBEAT event
>>>>> I1204 03:31:52.989886 31801 scheduler.cpp:298] Sending REQUEST call to
>>>>> master@172.17.0.2:47200
>>>>> I1204 03:31:52.991730 31792 process.cpp:3067] Handling HTTP event for
>>>>> process 'master' with path: '/master/api/v1/scheduler'
>>>>> I1204 03:31:52.991812 31792 http.cpp:336] HTTP POST for
>>>>> /master/api/v1/scheduler from 172.17.0.2:33010
>>>>> I1204 03:31:52.992156 31792 master.cpp:2646] Processing REQUEST call
>>>>> for framework 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000 (default)
>>>>> I1204 03:31:52.992516 31790 hierarchical.cpp:557] Received resource
>>>>> request from framework 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
>>>>> I1204 03:31:52.992923 31800 master.cpp:938] Master terminating
>>>>> I1204 03:31:52.993132 31796 hierarchical.cpp:306] Removed framework
>>>>> 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
>>>>> E1204 03:31:52.993708 31798 scheduler.cpp:431] End-Of-File received
>>>>> from master. The master closed the event stream
>>>>> [       OK ] ContentType/SchedulerTest.Request/1 (431 ms)
>>>>> [----------] 22 tests from ContentType/SchedulerTest (15741 ms total)
>>>>>
>>>>> [----------] Global test environment tear-down
>>>>> [==========] 878 tests from 116 test cases ran. (711169 ms total)
>>>>> [  PASSED  ] 877 tests.
>>>>> [  FAILED  ] 1 test, listed below:
>>>>> [  FAILED  ] ReservationTest.ACLMultipleOperations
>>>>>
>>>>>  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-1449197270-18036
>>>>> Untagged: mesos-1449197270-18036:latest
>>>>> Deleted:
>>>>> 71bc3adfccbfe4c515166abab14facf5895235fd4358c75eafe7552377b4ed12
>>>>> Deleted:
>>>>> c04522c46bffaa92efd2450d00842a14171f47c8ae50942666829e4dca2a7ada
>>>>> Deleted:
>>>>> d5849061eee06f14b51d9d7237588a0fe83fd953abfc1713692bd1247d04220f
>>>>> Deleted:
>>>>> 20d1e630457de2edba4f2fabe62ee3bcc7de4243ec737ce2a545a83de876613d
>>>>> Deleted:
>>>>> 64bba51bd0cdcb0d983deeb4cd1aa27ceb02bd4703c24f2692024c5a1537de44
>>>>> Deleted:
>>>>> 59e85ec64b5ee2735cde5403fe8def7375ffca98f9ea7953c802705673efb8cd
>>>>> Deleted:
>>>>> bee88887921d3d7d38f87744f4f49cb346037ce8a8b09af9d29686376200d66e
>>>>> Deleted:
>>>>> 709b8b667cf349fbcf14fbc48a0316319b341baaa1dd61f6a48c66d37b2dc628
>>>>> Deleted:
>>>>> e2c4f6d787499248e303270ff419e2545075e24a83101ed5316f4ecc907bba69
>>>>> Deleted:
>>>>> 0b8ee088204fbd6b9b1fa2f1a503763106b444f6a0b5d64ad6136269f821e487
>>>>> Deleted:
>>>>> 5657d8070e24ed2e2c43b0ac6ac0536208680be1f4e18031f5c76fd722aff863
>>>>> Deleted:
>>>>> 5e4dcfbaf3cc159742402a11e2c8b27efa71ec0ec202abd22acf5f553691f9c6
>>>>> Deleted:
>>>>> f589a283ec591fb354c074375571f136e15baa088534a380ac69255b6565ecdd
>>>>> Build step 'Execute shell' marked build as failure
>>>>>
>>>>
>>>>
>>

Re: Build failed in Jenkins: Mesos » gcc,--verbose --enable-libevent --enable-ssl,ubuntu:14.04,docker||Hadoop #1319

Posted by Michael Park <mp...@mesosphere.io>.
Jie, but I also helped out so I can look into it once I get on a computer.

On Thu, Dec 3, 2015, 10:50 PM Benjamin Mahler <be...@gmail.com>
wrote:

> Got it. Who shepherded it?
>
> On Thu, Dec 3, 2015 at 7:38 PM, Michael Park <mp...@mesosphere.io> wrote:
>
>> +Greg since he's the author, he might have a better idea
>>
>> On Thu, Dec 3, 2015, 10:36 PM Benjamin Mahler <be...@gmail.com>
>> wrote:
>>
>>> Michael can you please triage this test?
>>>
>>> On Thu, Dec 3, 2015 at 7:31 PM, Apache Jenkins Server <
>>> jenkins@builds.apache.org> wrote:
>>>
>>>> See <
>>>> https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose%20--enable-libevent%20--enable-ssl,OS=ubuntu%3A14.04,label_exp=docker%7C%7CHadoop/1319/changes
>>>> >
>>>>
>>>> Changes:
>>>>
>>>> [benjamin.mahler] Documented why OsSignalsTest.Suppress works on OS X.
>>>>
>>>> ------------------------------------------
>>>> [...truncated 151042 lines...]
>>>> I1204 03:31:52.023347 31790 gc.cpp:54] Scheduling
>>>> '/tmp/ContentType_SchedulerTest_Message_1_jkcDGA/slaves/e567d75e-4b42-4184-a487-498d6e3e86f0-S0/frameworks/e567d75e-4b42-4184-a487-498d6e3e86f0-0000/executors/default/runs/ad6c9ae3-14b4-4ae0-85e0-2b66874c1d0f'
>>>> for gc 6.99999973126222days in the future
>>>> I1204 03:31:52.023437 31792 slave.cpp:3773] Cleaning up framework
>>>> e567d75e-4b42-4184-a487-498d6e3e86f0-0000
>>>> I1204 03:31:52.023515 31790 gc.cpp:54] Scheduling
>>>> '/tmp/ContentType_SchedulerTest_Message_1_jkcDGA/slaves/e567d75e-4b42-4184-a487-498d6e3e86f0-S0/frameworks/e567d75e-4b42-4184-a487-498d6e3e86f0-0000/executors/default'
>>>> for gc 6.99999972944593days in the future
>>>> I1204 03:31:52.023558 31794 status_update_manager.cpp:282] Closing
>>>> status update streams for framework
>>>> e567d75e-4b42-4184-a487-498d6e3e86f0-0000
>>>> I1204 03:31:52.023623 31794 status_update_manager.cpp:528] Cleaning up
>>>> status update stream for task 3ee27512-7308-4ddf-8ab0-eb17196ad555 of
>>>> framework e567d75e-4b42-4184-a487-498d6e3e86f0-0000
>>>> I1204 03:31:52.023661 31790 gc.cpp:54] Scheduling
>>>> '/tmp/ContentType_SchedulerTest_Message_1_jkcDGA/slaves/e567d75e-4b42-4184-a487-498d6e3e86f0-S0/frameworks/e567d75e-4b42-4184-a487-498d6e3e86f0-0000'
>>>> for gc 6.99999972689778days in the future
>>>> [       OK ] ContentType/SchedulerTest.Message/1 (675 ms)
>>>> [ RUN      ] ContentType/SchedulerTest.Request/0
>>>> I1204 03:31:52.124193 31769 leveldb.cpp:174] Opened db in 94.016525ms
>>>> I1204 03:31:52.149694 31769 leveldb.cpp:181] Compacted db in 25.458791ms
>>>> I1204 03:31:52.149760 31769 leveldb.cpp:196] Created db iterator in
>>>> 20834ns
>>>> I1204 03:31:52.149780 31769 leveldb.cpp:202] Seeked to beginning of db
>>>> in 1977ns
>>>> I1204 03:31:52.149791 31769 leveldb.cpp:271] Iterated through 0 keys in
>>>> the db in 303ns
>>>> I1204 03:31:52.149832 31769 replica.cpp:778] Replica recovered with log
>>>> positions 0 -> 0 with 1 holes and 0 unlearned
>>>> I1204 03:31:52.150544 31791 recover.cpp:447] Starting replica recovery
>>>> I1204 03:31:52.151046 31791 recover.cpp:473] Replica is in EMPTY status
>>>> I1204 03:31:52.152299 31802 replica.cpp:674] Replica in EMPTY status
>>>> received a broadcasted recover request from (11482)@172.17.0.2:47200
>>>> I1204 03:31:52.152914 31801 recover.cpp:193] Received a recover
>>>> response from a replica in EMPTY status
>>>> I1204 03:31:52.153547 31799 recover.cpp:564] Updating replica status to
>>>> STARTING
>>>> I1204 03:31:52.153744 31803 master.cpp:365] Master
>>>> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe (403686b83bbb) started on
>>>> 172.17.0.2:47200
>>>> I1204 03:31:52.153775 31803 master.cpp:367] Flags at startup: --acls=""
>>>> --allocation_interval="1secs" --allocator="HierarchicalDRF"
>>>> --authenticate="false" --authenticate_slaves="true"
>>>> --authenticators="crammd5" --authorizers="local"
>>>> --credentials="/tmp/0wBPVf/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/0wBPVf/master" --zk_session_timeout="10secs"
>>>> I1204 03:31:52.154326 31803 master.cpp:414] Master allowing
>>>> unauthenticated frameworks to register
>>>> I1204 03:31:52.154345 31803 master.cpp:417] Master only allowing
>>>> authenticated slaves to register
>>>> I1204 03:31:52.154361 31803 credentials.hpp:35] Loading credentials for
>>>> authentication from '/tmp/0wBPVf/credentials'
>>>> I1204 03:31:52.154675 31803 master.cpp:456] Using default 'crammd5'
>>>> authenticator
>>>> I1204 03:31:52.154832 31803 master.cpp:493] Authorization enabled
>>>> I1204 03:31:52.155102 31788 whitelist_watcher.cpp:77] No whitelist given
>>>> I1204 03:31:52.155231 31796 hierarchical.cpp:163] Initialized
>>>> hierarchical allocator process
>>>> I1204 03:31:52.157017 31791 master.cpp:1637] The newly elected leader
>>>> is master@172.17.0.2:47200 with id 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe
>>>> I1204 03:31:52.157053 31791 master.cpp:1650] Elected as the leading
>>>> master!
>>>> I1204 03:31:52.157073 31791 master.cpp:1395] Recovering from registrar
>>>> I1204 03:31:52.157237 31796 registrar.cpp:307] Recovering registrar
>>>> I1204 03:31:52.186647 31798 leveldb.cpp:304] Persisting metadata (8
>>>> bytes) to leveldb took 32.571067ms
>>>> I1204 03:31:52.186686 31798 replica.cpp:321] Persisted replica status
>>>> to STARTING
>>>> I1204 03:31:52.187000 31803 recover.cpp:473] Replica is in STARTING
>>>> status
>>>> I1204 03:31:52.188062 31800 replica.cpp:674] Replica in STARTING status
>>>> received a broadcasted recover request from (11483)@172.17.0.2:47200
>>>> I1204 03:31:52.188350 31792 recover.cpp:193] Received a recover
>>>> response from a replica in STARTING status
>>>> I1204 03:31:52.188809 31796 recover.cpp:564] Updating replica status to
>>>> VOTING
>>>> I1204 03:31:52.220109 31797 leveldb.cpp:304] Persisting metadata (8
>>>> bytes) to leveldb took 31.054929ms
>>>> I1204 03:31:52.220147 31797 replica.cpp:321] Persisted replica status
>>>> to VOTING
>>>> I1204 03:31:52.220288 31792 recover.cpp:578] Successfully joined the
>>>> Paxos group
>>>> I1204 03:31:52.220634 31792 recover.cpp:462] Recover process terminated
>>>> I1204 03:31:52.221151 31802 log.cpp:659] Attempting to start the writer
>>>> I1204 03:31:52.222534 31801 replica.cpp:494] Replica received implicit
>>>> promise request from (11484)@172.17.0.2:47200 with proposal 1
>>>> I1204 03:31:52.245628 31801 leveldb.cpp:304] Persisting metadata (8
>>>> bytes) to leveldb took 23.049981ms
>>>> I1204 03:31:52.245667 31801 replica.cpp:343] Persisted promised to 1
>>>> I1204 03:31:52.246343 31793 coordinator.cpp:238] Coordinator attempting
>>>> to fill missing positions
>>>> I1204 03:31:52.247530 31788 replica.cpp:389] Replica received explicit
>>>> promise request from (11485)@172.17.0.2:47200 for position 0 with
>>>> proposal 2
>>>> I1204 03:31:52.287514 31788 leveldb.cpp:341] Persisting action (8
>>>> bytes) to leveldb took 39.94388ms
>>>> I1204 03:31:52.287552 31788 replica.cpp:713] Persisted action at 0
>>>> I1204 03:31:52.288843 31802 replica.cpp:538] Replica received write
>>>> request for position 0 from (11486)@172.17.0.2:47200
>>>> I1204 03:31:52.288903 31802 leveldb.cpp:436] Reading position from
>>>> leveldb took 29125ns
>>>> I1204 03:31:52.329651 31802 leveldb.cpp:341] Persisting action (14
>>>> bytes) to leveldb took 40.69596ms
>>>> I1204 03:31:52.329701 31802 replica.cpp:713] Persisted action at 0
>>>> I1204 03:31:52.330826 31800 replica.cpp:692] Replica received learned
>>>> notice for position 0 from @0.0.0.0:0
>>>> I1204 03:31:52.383780 31800 leveldb.cpp:341] Persisting action (16
>>>> bytes) to leveldb took 52.909056ms
>>>> I1204 03:31:52.383831 31800 replica.cpp:713] Persisted action at 0
>>>> I1204 03:31:52.383858 31800 replica.cpp:698] Replica learned NOP action
>>>> at position 0
>>>> I1204 03:31:52.384644 31794 log.cpp:675] Writer started with ending
>>>> position 0
>>>> I1204 03:31:52.385828 31791 leveldb.cpp:436] Reading position from
>>>> leveldb took 33950ns
>>>> I1204 03:31:52.386934 31791 registrar.cpp:340] Successfully fetched the
>>>> registry (0B) in 229.636864ms
>>>> I1204 03:31:52.387066 31791 registrar.cpp:439] Applied 1 operations in
>>>> 36217ns; attempting to update the 'registry'
>>>> I1204 03:31:52.387809 31794 log.cpp:683] Attempting to append 170 bytes
>>>> to the log
>>>> I1204 03:31:52.387995 31798 coordinator.cpp:348] Coordinator attempting
>>>> to write APPEND action at position 1
>>>> I1204 03:31:52.388667 31802 replica.cpp:538] Replica received write
>>>> request for position 1 from (11487)@172.17.0.2:47200
>>>> I1204 03:31:52.434088 31802 leveldb.cpp:341] Persisting action (189
>>>> bytes) to leveldb took 45.373715ms
>>>> I1204 03:31:52.434159 31802 replica.cpp:713] Persisted action at 1
>>>> I1204 03:31:52.435035 31803 replica.cpp:692] Replica received learned
>>>> notice for position 1 from @0.0.0.0:0
>>>> I1204 03:31:52.467439 31803 leveldb.cpp:341] Persisting action (191
>>>> bytes) to leveldb took 32.356386ms
>>>> I1204 03:31:52.467502 31803 replica.cpp:713] Persisted action at 1
>>>> I1204 03:31:52.467533 31803 replica.cpp:698] Replica learned APPEND
>>>> action at position 1
>>>> I1204 03:31:52.468945 31789 registrar.cpp:484] Successfully updated the
>>>> 'registry' in 81.793792ms
>>>> I1204 03:31:52.469149 31789 registrar.cpp:370] Successfully recovered
>>>> registrar
>>>> I1204 03:31:52.469293 31796 log.cpp:702] Attempting to truncate the log
>>>> to 1
>>>> I1204 03:31:52.469637 31797 coordinator.cpp:348] Coordinator attempting
>>>> to write TRUNCATE action at position 2
>>>> I1204 03:31:52.469657 31802 hierarchical.cpp:181] Skipping recovery of
>>>> hierarchical allocator: nothing to recover
>>>> I1204 03:31:52.469641 31795 master.cpp:1447] Recovered 0 slaves from
>>>> the Registry (131B) ; allowing 10mins for slaves to re-register
>>>> I1204 03:31:52.470474 31795 replica.cpp:538] Replica received write
>>>> request for position 2 from (11488)@172.17.0.2:47200
>>>> I1204 03:31:52.509683 31795 leveldb.cpp:341] Persisting action (16
>>>> bytes) to leveldb took 39.16527ms
>>>> I1204 03:31:52.509734 31795 replica.cpp:713] Persisted action at 2
>>>> I1204 03:31:52.511015 31801 replica.cpp:692] Replica received learned
>>>> notice for position 2 from @0.0.0.0:0
>>>> I1204 03:31:52.546566 31801 leveldb.cpp:341] Persisting action (18
>>>> bytes) to leveldb took 35.510343ms
>>>> I1204 03:31:52.546649 31801 leveldb.cpp:399] Deleting ~1 keys from
>>>> leveldb took 42968ns
>>>> I1204 03:31:52.546674 31801 replica.cpp:713] Persisted action at 2
>>>> I1204 03:31:52.546696 31801 replica.cpp:698] Replica learned TRUNCATE
>>>> action at position 2
>>>> I1204 03:31:52.551092 31769 scheduler.cpp:154] Version: 0.27.0
>>>> I1204 03:31:52.552342 31798 scheduler.cpp:236] New master detected at
>>>> master@172.17.0.2:47200
>>>> I1204 03:31:52.553699 31795 scheduler.cpp:298] Sending SUBSCRIBE call
>>>> to master@172.17.0.2:47200
>>>> I1204 03:31:52.555797 31802 process.cpp:3067] Handling HTTP event for
>>>> process 'master' with path: '/master/api/v1/scheduler'
>>>> I1204 03:31:52.555894 31802 http.cpp:336] HTTP POST for
>>>> /master/api/v1/scheduler from 172.17.0.2:33004
>>>> I1204 03:31:52.556227 31802 master.cpp:1899] Received subscription
>>>> request for HTTP framework 'default'
>>>> I1204 03:31:52.556316 31802 master.cpp:1676] Authorizing framework
>>>> principal 'test-principal' to receive offers for role '*'
>>>> I1204 03:31:52.556674 31802 master.cpp:1991] Subscribing framework
>>>> 'default' with checkpointing disabled and capabilities [  ]
>>>> I1204 03:31:52.557163 31790 hierarchical.cpp:266] Added framework
>>>> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
>>>> I1204 03:31:52.557260 31790 hierarchical.cpp:1308] No resources
>>>> available to allocate!
>>>> I1204 03:31:52.557313 31790 hierarchical.cpp:1401] No inverse offers to
>>>> send out!
>>>> I1204 03:31:52.557312 31794 master.hpp:1583] Sending heartbeat to
>>>> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
>>>> I1204 03:31:52.557363 31790 hierarchical.cpp:1048] Performed allocation
>>>> for 0 slaves in 164108ns
>>>> I1204 03:31:52.558205 31802 scheduler.cpp:457] Enqueuing event
>>>> SUBSCRIBED received from master@172.17.0.2:47200
>>>> I1204 03:31:52.558789 31802 scheduler.cpp:457] Enqueuing event
>>>> HEARTBEAT received from master@172.17.0.2:47200
>>>> I1204 03:31:52.559478 31788 master_maintenance_tests.cpp:172] Ignoring
>>>> HEARTBEAT event
>>>> I1204 03:31:52.559605 31801 scheduler.cpp:298] Sending REQUEST call to
>>>> master@172.17.0.2:47200
>>>> I1204 03:31:52.561221 31803 process.cpp:3067] Handling HTTP event for
>>>> process 'master' with path: '/master/api/v1/scheduler'
>>>> I1204 03:31:52.561274 31803 http.cpp:336] HTTP POST for
>>>> /master/api/v1/scheduler from 172.17.0.2:33005
>>>> I1204 03:31:52.561362 31803 master.cpp:2646] Processing REQUEST call
>>>> for framework 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000 (default)
>>>> I1204 03:31:52.561527 31800 hierarchical.cpp:557] Received resource
>>>> request from framework 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
>>>> I1204 03:31:52.561843 31798 master.cpp:938] Master terminating
>>>> I1204 03:31:52.562047 31794 hierarchical.cpp:306] Removed framework
>>>> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
>>>> E1204 03:31:52.563323 31802 scheduler.cpp:431] End-Of-File received
>>>> from master. The master closed the event stream
>>>> [       OK ] ContentType/SchedulerTest.Request/0 (540 ms)
>>>> [ RUN      ] ContentType/SchedulerTest.Request/1
>>>> I1204 03:31:52.664904 31769 leveldb.cpp:174] Opened db in 95.062723ms
>>>> I1204 03:31:52.710089 31769 leveldb.cpp:181] Compacted db in 45.135601ms
>>>> I1204 03:31:52.710189 31769 leveldb.cpp:196] Created db iterator in
>>>> 41589ns
>>>> I1204 03:31:52.710208 31769 leveldb.cpp:202] Seeked to beginning of db
>>>> in 1962ns
>>>> I1204 03:31:52.710218 31769 leveldb.cpp:271] Iterated through 0 keys in
>>>> the db in 280ns
>>>> I1204 03:31:52.710280 31769 replica.cpp:778] Replica recovered with log
>>>> positions 0 -> 0 with 1 holes and 0 unlearned
>>>> I1204 03:31:52.711068 31792 recover.cpp:447] Starting replica recovery
>>>> I1204 03:31:52.711433 31792 recover.cpp:473] Replica is in EMPTY status
>>>> I1204 03:31:52.713116 31802 replica.cpp:674] Replica in EMPTY status
>>>> received a broadcasted recover request from (11493)@172.17.0.2:47200
>>>> I1204 03:31:52.713871 31800 recover.cpp:193] Received a recover
>>>> response from a replica in EMPTY status
>>>> I1204 03:31:52.714603 31799 recover.cpp:564] Updating replica status to
>>>> STARTING
>>>> I1204 03:31:52.715018 31800 master.cpp:365] Master
>>>> 82e2943a-0ffa-43db-ab30-d280bc15aad8 (403686b83bbb) started on
>>>> 172.17.0.2:47200
>>>> I1204 03:31:52.715071 31800 master.cpp:367] Flags at startup: --acls=""
>>>> --allocation_interval="1secs" --allocator="HierarchicalDRF"
>>>> --authenticate="false" --authenticate_slaves="true"
>>>> --authenticators="crammd5" --authorizers="local"
>>>> --credentials="/tmp/3FPUXP/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/3FPUXP/master" --zk_session_timeout="10secs"
>>>> I1204 03:31:52.715515 31800 master.cpp:414] Master allowing
>>>> unauthenticated frameworks to register
>>>> I1204 03:31:52.715529 31800 master.cpp:417] Master only allowing
>>>> authenticated slaves to register
>>>> I1204 03:31:52.715538 31800 credentials.hpp:35] Loading credentials for
>>>> authentication from '/tmp/3FPUXP/credentials'
>>>> I1204 03:31:52.715888 31800 master.cpp:456] Using default 'crammd5'
>>>> authenticator
>>>> I1204 03:31:52.716110 31800 master.cpp:493] Authorization enabled
>>>> I1204 03:31:52.716346 31799 whitelist_watcher.cpp:77] No whitelist given
>>>> I1204 03:31:52.716421 31788 hierarchical.cpp:163] Initialized
>>>> hierarchical allocator process
>>>> I1204 03:31:52.718489 31798 master.cpp:1637] The newly elected leader
>>>> is master@172.17.0.2:47200 with id 82e2943a-0ffa-43db-ab30-d280bc15aad8
>>>> I1204 03:31:52.718533 31798 master.cpp:1650] Elected as the leading
>>>> master!
>>>> I1204 03:31:52.718557 31798 master.cpp:1395] Recovering from registrar
>>>> I1204 03:31:52.718823 31803 registrar.cpp:307] Recovering registrar
>>>> I1204 03:31:52.743455 31790 leveldb.cpp:304] Persisting metadata (8
>>>> bytes) to leveldb took 28.301712ms
>>>> I1204 03:31:52.743496 31790 replica.cpp:321] Persisted replica status
>>>> to STARTING
>>>> I1204 03:31:52.743876 31795 recover.cpp:473] Replica is in STARTING
>>>> status
>>>> I1204 03:31:52.745254 31796 replica.cpp:674] Replica in STARTING status
>>>> received a broadcasted recover request from (11494)@172.17.0.2:47200
>>>> I1204 03:31:52.745743 31791 recover.cpp:193] Received a recover
>>>> response from a replica in STARTING status
>>>> I1204 03:31:52.746407 31797 recover.cpp:564] Updating replica status to
>>>> VOTING
>>>> I1204 03:31:52.768430 31802 leveldb.cpp:304] Persisting metadata (8
>>>> bytes) to leveldb took 21.81261ms
>>>> I1204 03:31:52.768474 31802 replica.cpp:321] Persisted replica status
>>>> to VOTING
>>>> I1204 03:31:52.768616 31802 recover.cpp:578] Successfully joined the
>>>> Paxos group
>>>> I1204 03:31:52.768904 31802 recover.cpp:462] Recover process terminated
>>>> I1204 03:31:52.769584 31800 log.cpp:659] Attempting to start the writer
>>>> I1204 03:31:52.771621 31789 replica.cpp:494] Replica received implicit
>>>> promise request from (11495)@172.17.0.2:47200 with proposal 1
>>>> I1204 03:31:52.793648 31789 leveldb.cpp:304] Persisting metadata (8
>>>> bytes) to leveldb took 21.993492ms
>>>> I1204 03:31:52.793694 31789 replica.cpp:343] Persisted promised to 1
>>>> I1204 03:31:52.794865 31798 coordinator.cpp:238] Coordinator attempting
>>>> to fill missing positions
>>>> I1204 03:31:52.796506 31799 replica.cpp:389] Replica received explicit
>>>> promise request from (11496)@172.17.0.2:47200 for position 0 with
>>>> proposal 2
>>>> I1204 03:31:52.818649 31799 leveldb.cpp:341] Persisting action (8
>>>> bytes) to leveldb took 22.082655ms
>>>> I1204 03:31:52.818688 31799 replica.cpp:713] Persisted action at 0
>>>> I1204 03:31:52.820047 31801 replica.cpp:538] Replica received write
>>>> request for position 0 from (11497)@172.17.0.2:47200
>>>> I1204 03:31:52.820125 31801 leveldb.cpp:436] Reading position from
>>>> leveldb took 37411ns
>>>> I1204 03:31:52.843890 31801 leveldb.cpp:341] Persisting action (14
>>>> bytes) to leveldb took 23.710606ms
>>>> I1204 03:31:52.843935 31801 replica.cpp:713] Persisted action at 0
>>>> I1204 03:31:52.844709 31800 replica.cpp:692] Replica received learned
>>>> notice for position 0 from @0.0.0.0:0
>>>> I1204 03:31:52.868993 31800 leveldb.cpp:341] Persisting action (16
>>>> bytes) to leveldb took 24.242639ms
>>>> I1204 03:31:52.869032 31800 replica.cpp:713] Persisted action at 0
>>>> I1204 03:31:52.869055 31800 replica.cpp:698] Replica learned NOP action
>>>> at position 0
>>>> I1204 03:31:52.869815 31797 log.cpp:675] Writer started with ending
>>>> position 0
>>>> I1204 03:31:52.871470 31789 leveldb.cpp:436] Reading position from
>>>> leveldb took 40828ns
>>>> I1204 03:31:52.872885 31790 registrar.cpp:340] Successfully fetched the
>>>> registry (0B) in 154.009088ms
>>>> I1204 03:31:52.873096 31790 registrar.cpp:439] Applied 1 operations in
>>>> 32282ns; attempting to update the 'registry'
>>>> I1204 03:31:52.874133 31800 log.cpp:683] Attempting to append 170 bytes
>>>> to the log
>>>> I1204 03:31:52.874337 31796 coordinator.cpp:348] Coordinator attempting
>>>> to write APPEND action at position 1
>>>> I1204 03:31:52.875277 31800 replica.cpp:538] Replica received write
>>>> request for position 1 from (11498)@172.17.0.2:47200
>>>> I1204 03:31:52.902500 31800 leveldb.cpp:341] Persisting action (189
>>>> bytes) to leveldb took 27.170365ms
>>>> I1204 03:31:52.902545 31800 replica.cpp:713] Persisted action at 1
>>>> I1204 03:31:52.903542 31798 replica.cpp:692] Replica received learned
>>>> notice for position 1 from @0.0.0.0:0
>>>> I1204 03:31:52.927577 31798 leveldb.cpp:341] Persisting action (191
>>>> bytes) to leveldb took 23.991773ms
>>>> I1204 03:31:52.927616 31798 replica.cpp:713] Persisted action at 1
>>>> I1204 03:31:52.927639 31798 replica.cpp:698] Replica learned APPEND
>>>> action at position 1
>>>> I1204 03:31:52.928863 31794 registrar.cpp:484] Successfully updated the
>>>> 'registry' in 55.643136ms
>>>> I1204 03:31:52.929076 31794 registrar.cpp:370] Successfully recovered
>>>> registrar
>>>> I1204 03:31:52.929177 31799 log.cpp:702] Attempting to truncate the log
>>>> to 1
>>>> I1204 03:31:52.929407 31797 coordinator.cpp:348] Coordinator attempting
>>>> to write TRUNCATE action at position 2
>>>> I1204 03:31:52.929703 31795 master.cpp:1447] Recovered 0 slaves from
>>>> the Registry (131B) ; allowing 10mins for slaves to re-register
>>>> I1204 03:31:52.929723 31799 hierarchical.cpp:181] Skipping recovery of
>>>> hierarchical allocator: nothing to recover
>>>> I1204 03:31:52.930577 31788 replica.cpp:538] Replica received write
>>>> request for position 2 from (11499)@172.17.0.2:47200
>>>> I1204 03:31:52.952744 31788 leveldb.cpp:341] Persisting action (16
>>>> bytes) to leveldb took 22.115164ms
>>>> I1204 03:31:52.952781 31788 replica.cpp:713] Persisted action at 2
>>>> I1204 03:31:52.953629 31798 replica.cpp:692] Replica received learned
>>>> notice for position 2 from @0.0.0.0:0
>>>> I1204 03:31:52.977794 31798 leveldb.cpp:341] Persisting action (18
>>>> bytes) to leveldb took 24.127932ms
>>>> I1204 03:31:52.977882 31798 leveldb.cpp:399] Deleting ~1 keys from
>>>> leveldb took 46051ns
>>>> I1204 03:31:52.977926 31798 replica.cpp:713] Persisted action at 2
>>>> I1204 03:31:52.977954 31798 replica.cpp:698] Replica learned TRUNCATE
>>>> action at position 2
>>>> I1204 03:31:52.981016 31769 scheduler.cpp:154] Version: 0.27.0
>>>> I1204 03:31:52.981828 31793 scheduler.cpp:236] New master detected at
>>>> master@172.17.0.2:47200
>>>> I1204 03:31:52.983167 31789 scheduler.cpp:298] Sending SUBSCRIBE call
>>>> to master@172.17.0.2:47200
>>>> I1204 03:31:52.985347 31789 process.cpp:3067] Handling HTTP event for
>>>> process 'master' with path: '/master/api/v1/scheduler'
>>>> I1204 03:31:52.985502 31789 http.cpp:336] HTTP POST for
>>>> /master/api/v1/scheduler from 172.17.0.2:33009
>>>> I1204 03:31:52.985939 31789 master.cpp:1899] Received subscription
>>>> request for HTTP framework 'default'
>>>> I1204 03:31:52.986045 31789 master.cpp:1676] Authorizing framework
>>>> principal 'test-principal' to receive offers for role '*'
>>>> I1204 03:31:52.986364 31789 master.cpp:1991] Subscribing framework
>>>> 'default' with checkpointing disabled and capabilities [  ]
>>>> I1204 03:31:52.986779 31799 hierarchical.cpp:266] Added framework
>>>> 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
>>>> I1204 03:31:52.986913 31796 master.hpp:1583] Sending heartbeat to
>>>> 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
>>>> I1204 03:31:52.986996 31799 hierarchical.cpp:1308] No resources
>>>> available to allocate!
>>>> I1204 03:31:52.987063 31799 hierarchical.cpp:1401] No inverse offers to
>>>> send out!
>>>> I1204 03:31:52.987110 31799 hierarchical.cpp:1048] Performed allocation
>>>> for 0 slaves in 189242ns
>>>> I1204 03:31:52.987913 31798 scheduler.cpp:457] Enqueuing event
>>>> SUBSCRIBED received from master@172.17.0.2:47200
>>>> I1204 03:31:52.988831 31798 scheduler.cpp:457] Enqueuing event
>>>> HEARTBEAT received from master@172.17.0.2:47200
>>>> I1204 03:31:52.989537 31788 master_maintenance_tests.cpp:172] Ignoring
>>>> HEARTBEAT event
>>>> I1204 03:31:52.989886 31801 scheduler.cpp:298] Sending REQUEST call to
>>>> master@172.17.0.2:47200
>>>> I1204 03:31:52.991730 31792 process.cpp:3067] Handling HTTP event for
>>>> process 'master' with path: '/master/api/v1/scheduler'
>>>> I1204 03:31:52.991812 31792 http.cpp:336] HTTP POST for
>>>> /master/api/v1/scheduler from 172.17.0.2:33010
>>>> I1204 03:31:52.992156 31792 master.cpp:2646] Processing REQUEST call
>>>> for framework 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000 (default)
>>>> I1204 03:31:52.992516 31790 hierarchical.cpp:557] Received resource
>>>> request from framework 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
>>>> I1204 03:31:52.992923 31800 master.cpp:938] Master terminating
>>>> I1204 03:31:52.993132 31796 hierarchical.cpp:306] Removed framework
>>>> 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
>>>> E1204 03:31:52.993708 31798 scheduler.cpp:431] End-Of-File received
>>>> from master. The master closed the event stream
>>>> [       OK ] ContentType/SchedulerTest.Request/1 (431 ms)
>>>> [----------] 22 tests from ContentType/SchedulerTest (15741 ms total)
>>>>
>>>> [----------] Global test environment tear-down
>>>> [==========] 878 tests from 116 test cases ran. (711169 ms total)
>>>> [  PASSED  ] 877 tests.
>>>> [  FAILED  ] 1 test, listed below:
>>>> [  FAILED  ] ReservationTest.ACLMultipleOperations
>>>>
>>>>  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-1449197270-18036
>>>> Untagged: mesos-1449197270-18036:latest
>>>> Deleted:
>>>> 71bc3adfccbfe4c515166abab14facf5895235fd4358c75eafe7552377b4ed12
>>>> Deleted:
>>>> c04522c46bffaa92efd2450d00842a14171f47c8ae50942666829e4dca2a7ada
>>>> Deleted:
>>>> d5849061eee06f14b51d9d7237588a0fe83fd953abfc1713692bd1247d04220f
>>>> Deleted:
>>>> 20d1e630457de2edba4f2fabe62ee3bcc7de4243ec737ce2a545a83de876613d
>>>> Deleted:
>>>> 64bba51bd0cdcb0d983deeb4cd1aa27ceb02bd4703c24f2692024c5a1537de44
>>>> Deleted:
>>>> 59e85ec64b5ee2735cde5403fe8def7375ffca98f9ea7953c802705673efb8cd
>>>> Deleted:
>>>> bee88887921d3d7d38f87744f4f49cb346037ce8a8b09af9d29686376200d66e
>>>> Deleted:
>>>> 709b8b667cf349fbcf14fbc48a0316319b341baaa1dd61f6a48c66d37b2dc628
>>>> Deleted:
>>>> e2c4f6d787499248e303270ff419e2545075e24a83101ed5316f4ecc907bba69
>>>> Deleted:
>>>> 0b8ee088204fbd6b9b1fa2f1a503763106b444f6a0b5d64ad6136269f821e487
>>>> Deleted:
>>>> 5657d8070e24ed2e2c43b0ac6ac0536208680be1f4e18031f5c76fd722aff863
>>>> Deleted:
>>>> 5e4dcfbaf3cc159742402a11e2c8b27efa71ec0ec202abd22acf5f553691f9c6
>>>> Deleted:
>>>> f589a283ec591fb354c074375571f136e15baa088534a380ac69255b6565ecdd
>>>> Build step 'Execute shell' marked build as failure
>>>>
>>>
>>>
>

Re: Build failed in Jenkins: Mesos » gcc,--verbose --enable-libevent --enable-ssl,ubuntu:14.04,docker||Hadoop #1319

Posted by Benjamin Mahler <be...@gmail.com>.
Got it. Who shepherded it?

On Thu, Dec 3, 2015 at 7:38 PM, Michael Park <mp...@mesosphere.io> wrote:

> +Greg since he's the author, he might have a better idea
>
> On Thu, Dec 3, 2015, 10:36 PM Benjamin Mahler <be...@gmail.com>
> wrote:
>
>> Michael can you please triage this test?
>>
>> On Thu, Dec 3, 2015 at 7:31 PM, Apache Jenkins Server <
>> jenkins@builds.apache.org> wrote:
>>
>>> See <
>>> https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose%20--enable-libevent%20--enable-ssl,OS=ubuntu%3A14.04,label_exp=docker%7C%7CHadoop/1319/changes
>>> >
>>>
>>> Changes:
>>>
>>> [benjamin.mahler] Documented why OsSignalsTest.Suppress works on OS X.
>>>
>>> ------------------------------------------
>>> [...truncated 151042 lines...]
>>> I1204 03:31:52.023347 31790 gc.cpp:54] Scheduling
>>> '/tmp/ContentType_SchedulerTest_Message_1_jkcDGA/slaves/e567d75e-4b42-4184-a487-498d6e3e86f0-S0/frameworks/e567d75e-4b42-4184-a487-498d6e3e86f0-0000/executors/default/runs/ad6c9ae3-14b4-4ae0-85e0-2b66874c1d0f'
>>> for gc 6.99999973126222days in the future
>>> I1204 03:31:52.023437 31792 slave.cpp:3773] Cleaning up framework
>>> e567d75e-4b42-4184-a487-498d6e3e86f0-0000
>>> I1204 03:31:52.023515 31790 gc.cpp:54] Scheduling
>>> '/tmp/ContentType_SchedulerTest_Message_1_jkcDGA/slaves/e567d75e-4b42-4184-a487-498d6e3e86f0-S0/frameworks/e567d75e-4b42-4184-a487-498d6e3e86f0-0000/executors/default'
>>> for gc 6.99999972944593days in the future
>>> I1204 03:31:52.023558 31794 status_update_manager.cpp:282] Closing
>>> status update streams for framework
>>> e567d75e-4b42-4184-a487-498d6e3e86f0-0000
>>> I1204 03:31:52.023623 31794 status_update_manager.cpp:528] Cleaning up
>>> status update stream for task 3ee27512-7308-4ddf-8ab0-eb17196ad555 of
>>> framework e567d75e-4b42-4184-a487-498d6e3e86f0-0000
>>> I1204 03:31:52.023661 31790 gc.cpp:54] Scheduling
>>> '/tmp/ContentType_SchedulerTest_Message_1_jkcDGA/slaves/e567d75e-4b42-4184-a487-498d6e3e86f0-S0/frameworks/e567d75e-4b42-4184-a487-498d6e3e86f0-0000'
>>> for gc 6.99999972689778days in the future
>>> [       OK ] ContentType/SchedulerTest.Message/1 (675 ms)
>>> [ RUN      ] ContentType/SchedulerTest.Request/0
>>> I1204 03:31:52.124193 31769 leveldb.cpp:174] Opened db in 94.016525ms
>>> I1204 03:31:52.149694 31769 leveldb.cpp:181] Compacted db in 25.458791ms
>>> I1204 03:31:52.149760 31769 leveldb.cpp:196] Created db iterator in
>>> 20834ns
>>> I1204 03:31:52.149780 31769 leveldb.cpp:202] Seeked to beginning of db
>>> in 1977ns
>>> I1204 03:31:52.149791 31769 leveldb.cpp:271] Iterated through 0 keys in
>>> the db in 303ns
>>> I1204 03:31:52.149832 31769 replica.cpp:778] Replica recovered with log
>>> positions 0 -> 0 with 1 holes and 0 unlearned
>>> I1204 03:31:52.150544 31791 recover.cpp:447] Starting replica recovery
>>> I1204 03:31:52.151046 31791 recover.cpp:473] Replica is in EMPTY status
>>> I1204 03:31:52.152299 31802 replica.cpp:674] Replica in EMPTY status
>>> received a broadcasted recover request from (11482)@172.17.0.2:47200
>>> I1204 03:31:52.152914 31801 recover.cpp:193] Received a recover response
>>> from a replica in EMPTY status
>>> I1204 03:31:52.153547 31799 recover.cpp:564] Updating replica status to
>>> STARTING
>>> I1204 03:31:52.153744 31803 master.cpp:365] Master
>>> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe (403686b83bbb) started on
>>> 172.17.0.2:47200
>>> I1204 03:31:52.153775 31803 master.cpp:367] Flags at startup: --acls=""
>>> --allocation_interval="1secs" --allocator="HierarchicalDRF"
>>> --authenticate="false" --authenticate_slaves="true"
>>> --authenticators="crammd5" --authorizers="local"
>>> --credentials="/tmp/0wBPVf/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/0wBPVf/master" --zk_session_timeout="10secs"
>>> I1204 03:31:52.154326 31803 master.cpp:414] Master allowing
>>> unauthenticated frameworks to register
>>> I1204 03:31:52.154345 31803 master.cpp:417] Master only allowing
>>> authenticated slaves to register
>>> I1204 03:31:52.154361 31803 credentials.hpp:35] Loading credentials for
>>> authentication from '/tmp/0wBPVf/credentials'
>>> I1204 03:31:52.154675 31803 master.cpp:456] Using default 'crammd5'
>>> authenticator
>>> I1204 03:31:52.154832 31803 master.cpp:493] Authorization enabled
>>> I1204 03:31:52.155102 31788 whitelist_watcher.cpp:77] No whitelist given
>>> I1204 03:31:52.155231 31796 hierarchical.cpp:163] Initialized
>>> hierarchical allocator process
>>> I1204 03:31:52.157017 31791 master.cpp:1637] The newly elected leader is
>>> master@172.17.0.2:47200 with id 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe
>>> I1204 03:31:52.157053 31791 master.cpp:1650] Elected as the leading
>>> master!
>>> I1204 03:31:52.157073 31791 master.cpp:1395] Recovering from registrar
>>> I1204 03:31:52.157237 31796 registrar.cpp:307] Recovering registrar
>>> I1204 03:31:52.186647 31798 leveldb.cpp:304] Persisting metadata (8
>>> bytes) to leveldb took 32.571067ms
>>> I1204 03:31:52.186686 31798 replica.cpp:321] Persisted replica status to
>>> STARTING
>>> I1204 03:31:52.187000 31803 recover.cpp:473] Replica is in STARTING
>>> status
>>> I1204 03:31:52.188062 31800 replica.cpp:674] Replica in STARTING status
>>> received a broadcasted recover request from (11483)@172.17.0.2:47200
>>> I1204 03:31:52.188350 31792 recover.cpp:193] Received a recover response
>>> from a replica in STARTING status
>>> I1204 03:31:52.188809 31796 recover.cpp:564] Updating replica status to
>>> VOTING
>>> I1204 03:31:52.220109 31797 leveldb.cpp:304] Persisting metadata (8
>>> bytes) to leveldb took 31.054929ms
>>> I1204 03:31:52.220147 31797 replica.cpp:321] Persisted replica status to
>>> VOTING
>>> I1204 03:31:52.220288 31792 recover.cpp:578] Successfully joined the
>>> Paxos group
>>> I1204 03:31:52.220634 31792 recover.cpp:462] Recover process terminated
>>> I1204 03:31:52.221151 31802 log.cpp:659] Attempting to start the writer
>>> I1204 03:31:52.222534 31801 replica.cpp:494] Replica received implicit
>>> promise request from (11484)@172.17.0.2:47200 with proposal 1
>>> I1204 03:31:52.245628 31801 leveldb.cpp:304] Persisting metadata (8
>>> bytes) to leveldb took 23.049981ms
>>> I1204 03:31:52.245667 31801 replica.cpp:343] Persisted promised to 1
>>> I1204 03:31:52.246343 31793 coordinator.cpp:238] Coordinator attempting
>>> to fill missing positions
>>> I1204 03:31:52.247530 31788 replica.cpp:389] Replica received explicit
>>> promise request from (11485)@172.17.0.2:47200 for position 0 with
>>> proposal 2
>>> I1204 03:31:52.287514 31788 leveldb.cpp:341] Persisting action (8 bytes)
>>> to leveldb took 39.94388ms
>>> I1204 03:31:52.287552 31788 replica.cpp:713] Persisted action at 0
>>> I1204 03:31:52.288843 31802 replica.cpp:538] Replica received write
>>> request for position 0 from (11486)@172.17.0.2:47200
>>> I1204 03:31:52.288903 31802 leveldb.cpp:436] Reading position from
>>> leveldb took 29125ns
>>> I1204 03:31:52.329651 31802 leveldb.cpp:341] Persisting action (14
>>> bytes) to leveldb took 40.69596ms
>>> I1204 03:31:52.329701 31802 replica.cpp:713] Persisted action at 0
>>> I1204 03:31:52.330826 31800 replica.cpp:692] Replica received learned
>>> notice for position 0 from @0.0.0.0:0
>>> I1204 03:31:52.383780 31800 leveldb.cpp:341] Persisting action (16
>>> bytes) to leveldb took 52.909056ms
>>> I1204 03:31:52.383831 31800 replica.cpp:713] Persisted action at 0
>>> I1204 03:31:52.383858 31800 replica.cpp:698] Replica learned NOP action
>>> at position 0
>>> I1204 03:31:52.384644 31794 log.cpp:675] Writer started with ending
>>> position 0
>>> I1204 03:31:52.385828 31791 leveldb.cpp:436] Reading position from
>>> leveldb took 33950ns
>>> I1204 03:31:52.386934 31791 registrar.cpp:340] Successfully fetched the
>>> registry (0B) in 229.636864ms
>>> I1204 03:31:52.387066 31791 registrar.cpp:439] Applied 1 operations in
>>> 36217ns; attempting to update the 'registry'
>>> I1204 03:31:52.387809 31794 log.cpp:683] Attempting to append 170 bytes
>>> to the log
>>> I1204 03:31:52.387995 31798 coordinator.cpp:348] Coordinator attempting
>>> to write APPEND action at position 1
>>> I1204 03:31:52.388667 31802 replica.cpp:538] Replica received write
>>> request for position 1 from (11487)@172.17.0.2:47200
>>> I1204 03:31:52.434088 31802 leveldb.cpp:341] Persisting action (189
>>> bytes) to leveldb took 45.373715ms
>>> I1204 03:31:52.434159 31802 replica.cpp:713] Persisted action at 1
>>> I1204 03:31:52.435035 31803 replica.cpp:692] Replica received learned
>>> notice for position 1 from @0.0.0.0:0
>>> I1204 03:31:52.467439 31803 leveldb.cpp:341] Persisting action (191
>>> bytes) to leveldb took 32.356386ms
>>> I1204 03:31:52.467502 31803 replica.cpp:713] Persisted action at 1
>>> I1204 03:31:52.467533 31803 replica.cpp:698] Replica learned APPEND
>>> action at position 1
>>> I1204 03:31:52.468945 31789 registrar.cpp:484] Successfully updated the
>>> 'registry' in 81.793792ms
>>> I1204 03:31:52.469149 31789 registrar.cpp:370] Successfully recovered
>>> registrar
>>> I1204 03:31:52.469293 31796 log.cpp:702] Attempting to truncate the log
>>> to 1
>>> I1204 03:31:52.469637 31797 coordinator.cpp:348] Coordinator attempting
>>> to write TRUNCATE action at position 2
>>> I1204 03:31:52.469657 31802 hierarchical.cpp:181] Skipping recovery of
>>> hierarchical allocator: nothing to recover
>>> I1204 03:31:52.469641 31795 master.cpp:1447] Recovered 0 slaves from the
>>> Registry (131B) ; allowing 10mins for slaves to re-register
>>> I1204 03:31:52.470474 31795 replica.cpp:538] Replica received write
>>> request for position 2 from (11488)@172.17.0.2:47200
>>> I1204 03:31:52.509683 31795 leveldb.cpp:341] Persisting action (16
>>> bytes) to leveldb took 39.16527ms
>>> I1204 03:31:52.509734 31795 replica.cpp:713] Persisted action at 2
>>> I1204 03:31:52.511015 31801 replica.cpp:692] Replica received learned
>>> notice for position 2 from @0.0.0.0:0
>>> I1204 03:31:52.546566 31801 leveldb.cpp:341] Persisting action (18
>>> bytes) to leveldb took 35.510343ms
>>> I1204 03:31:52.546649 31801 leveldb.cpp:399] Deleting ~1 keys from
>>> leveldb took 42968ns
>>> I1204 03:31:52.546674 31801 replica.cpp:713] Persisted action at 2
>>> I1204 03:31:52.546696 31801 replica.cpp:698] Replica learned TRUNCATE
>>> action at position 2
>>> I1204 03:31:52.551092 31769 scheduler.cpp:154] Version: 0.27.0
>>> I1204 03:31:52.552342 31798 scheduler.cpp:236] New master detected at
>>> master@172.17.0.2:47200
>>> I1204 03:31:52.553699 31795 scheduler.cpp:298] Sending SUBSCRIBE call to
>>> master@172.17.0.2:47200
>>> I1204 03:31:52.555797 31802 process.cpp:3067] Handling HTTP event for
>>> process 'master' with path: '/master/api/v1/scheduler'
>>> I1204 03:31:52.555894 31802 http.cpp:336] HTTP POST for
>>> /master/api/v1/scheduler from 172.17.0.2:33004
>>> I1204 03:31:52.556227 31802 master.cpp:1899] Received subscription
>>> request for HTTP framework 'default'
>>> I1204 03:31:52.556316 31802 master.cpp:1676] Authorizing framework
>>> principal 'test-principal' to receive offers for role '*'
>>> I1204 03:31:52.556674 31802 master.cpp:1991] Subscribing framework
>>> 'default' with checkpointing disabled and capabilities [  ]
>>> I1204 03:31:52.557163 31790 hierarchical.cpp:266] Added framework
>>> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
>>> I1204 03:31:52.557260 31790 hierarchical.cpp:1308] No resources
>>> available to allocate!
>>> I1204 03:31:52.557313 31790 hierarchical.cpp:1401] No inverse offers to
>>> send out!
>>> I1204 03:31:52.557312 31794 master.hpp:1583] Sending heartbeat to
>>> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
>>> I1204 03:31:52.557363 31790 hierarchical.cpp:1048] Performed allocation
>>> for 0 slaves in 164108ns
>>> I1204 03:31:52.558205 31802 scheduler.cpp:457] Enqueuing event
>>> SUBSCRIBED received from master@172.17.0.2:47200
>>> I1204 03:31:52.558789 31802 scheduler.cpp:457] Enqueuing event HEARTBEAT
>>> received from master@172.17.0.2:47200
>>> I1204 03:31:52.559478 31788 master_maintenance_tests.cpp:172] Ignoring
>>> HEARTBEAT event
>>> I1204 03:31:52.559605 31801 scheduler.cpp:298] Sending REQUEST call to
>>> master@172.17.0.2:47200
>>> I1204 03:31:52.561221 31803 process.cpp:3067] Handling HTTP event for
>>> process 'master' with path: '/master/api/v1/scheduler'
>>> I1204 03:31:52.561274 31803 http.cpp:336] HTTP POST for
>>> /master/api/v1/scheduler from 172.17.0.2:33005
>>> I1204 03:31:52.561362 31803 master.cpp:2646] Processing REQUEST call for
>>> framework 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000 (default)
>>> I1204 03:31:52.561527 31800 hierarchical.cpp:557] Received resource
>>> request from framework 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
>>> I1204 03:31:52.561843 31798 master.cpp:938] Master terminating
>>> I1204 03:31:52.562047 31794 hierarchical.cpp:306] Removed framework
>>> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
>>> E1204 03:31:52.563323 31802 scheduler.cpp:431] End-Of-File received from
>>> master. The master closed the event stream
>>> [       OK ] ContentType/SchedulerTest.Request/0 (540 ms)
>>> [ RUN      ] ContentType/SchedulerTest.Request/1
>>> I1204 03:31:52.664904 31769 leveldb.cpp:174] Opened db in 95.062723ms
>>> I1204 03:31:52.710089 31769 leveldb.cpp:181] Compacted db in 45.135601ms
>>> I1204 03:31:52.710189 31769 leveldb.cpp:196] Created db iterator in
>>> 41589ns
>>> I1204 03:31:52.710208 31769 leveldb.cpp:202] Seeked to beginning of db
>>> in 1962ns
>>> I1204 03:31:52.710218 31769 leveldb.cpp:271] Iterated through 0 keys in
>>> the db in 280ns
>>> I1204 03:31:52.710280 31769 replica.cpp:778] Replica recovered with log
>>> positions 0 -> 0 with 1 holes and 0 unlearned
>>> I1204 03:31:52.711068 31792 recover.cpp:447] Starting replica recovery
>>> I1204 03:31:52.711433 31792 recover.cpp:473] Replica is in EMPTY status
>>> I1204 03:31:52.713116 31802 replica.cpp:674] Replica in EMPTY status
>>> received a broadcasted recover request from (11493)@172.17.0.2:47200
>>> I1204 03:31:52.713871 31800 recover.cpp:193] Received a recover response
>>> from a replica in EMPTY status
>>> I1204 03:31:52.714603 31799 recover.cpp:564] Updating replica status to
>>> STARTING
>>> I1204 03:31:52.715018 31800 master.cpp:365] Master
>>> 82e2943a-0ffa-43db-ab30-d280bc15aad8 (403686b83bbb) started on
>>> 172.17.0.2:47200
>>> I1204 03:31:52.715071 31800 master.cpp:367] Flags at startup: --acls=""
>>> --allocation_interval="1secs" --allocator="HierarchicalDRF"
>>> --authenticate="false" --authenticate_slaves="true"
>>> --authenticators="crammd5" --authorizers="local"
>>> --credentials="/tmp/3FPUXP/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/3FPUXP/master" --zk_session_timeout="10secs"
>>> I1204 03:31:52.715515 31800 master.cpp:414] Master allowing
>>> unauthenticated frameworks to register
>>> I1204 03:31:52.715529 31800 master.cpp:417] Master only allowing
>>> authenticated slaves to register
>>> I1204 03:31:52.715538 31800 credentials.hpp:35] Loading credentials for
>>> authentication from '/tmp/3FPUXP/credentials'
>>> I1204 03:31:52.715888 31800 master.cpp:456] Using default 'crammd5'
>>> authenticator
>>> I1204 03:31:52.716110 31800 master.cpp:493] Authorization enabled
>>> I1204 03:31:52.716346 31799 whitelist_watcher.cpp:77] No whitelist given
>>> I1204 03:31:52.716421 31788 hierarchical.cpp:163] Initialized
>>> hierarchical allocator process
>>> I1204 03:31:52.718489 31798 master.cpp:1637] The newly elected leader is
>>> master@172.17.0.2:47200 with id 82e2943a-0ffa-43db-ab30-d280bc15aad8
>>> I1204 03:31:52.718533 31798 master.cpp:1650] Elected as the leading
>>> master!
>>> I1204 03:31:52.718557 31798 master.cpp:1395] Recovering from registrar
>>> I1204 03:31:52.718823 31803 registrar.cpp:307] Recovering registrar
>>> I1204 03:31:52.743455 31790 leveldb.cpp:304] Persisting metadata (8
>>> bytes) to leveldb took 28.301712ms
>>> I1204 03:31:52.743496 31790 replica.cpp:321] Persisted replica status to
>>> STARTING
>>> I1204 03:31:52.743876 31795 recover.cpp:473] Replica is in STARTING
>>> status
>>> I1204 03:31:52.745254 31796 replica.cpp:674] Replica in STARTING status
>>> received a broadcasted recover request from (11494)@172.17.0.2:47200
>>> I1204 03:31:52.745743 31791 recover.cpp:193] Received a recover response
>>> from a replica in STARTING status
>>> I1204 03:31:52.746407 31797 recover.cpp:564] Updating replica status to
>>> VOTING
>>> I1204 03:31:52.768430 31802 leveldb.cpp:304] Persisting metadata (8
>>> bytes) to leveldb took 21.81261ms
>>> I1204 03:31:52.768474 31802 replica.cpp:321] Persisted replica status to
>>> VOTING
>>> I1204 03:31:52.768616 31802 recover.cpp:578] Successfully joined the
>>> Paxos group
>>> I1204 03:31:52.768904 31802 recover.cpp:462] Recover process terminated
>>> I1204 03:31:52.769584 31800 log.cpp:659] Attempting to start the writer
>>> I1204 03:31:52.771621 31789 replica.cpp:494] Replica received implicit
>>> promise request from (11495)@172.17.0.2:47200 with proposal 1
>>> I1204 03:31:52.793648 31789 leveldb.cpp:304] Persisting metadata (8
>>> bytes) to leveldb took 21.993492ms
>>> I1204 03:31:52.793694 31789 replica.cpp:343] Persisted promised to 1
>>> I1204 03:31:52.794865 31798 coordinator.cpp:238] Coordinator attempting
>>> to fill missing positions
>>> I1204 03:31:52.796506 31799 replica.cpp:389] Replica received explicit
>>> promise request from (11496)@172.17.0.2:47200 for position 0 with
>>> proposal 2
>>> I1204 03:31:52.818649 31799 leveldb.cpp:341] Persisting action (8 bytes)
>>> to leveldb took 22.082655ms
>>> I1204 03:31:52.818688 31799 replica.cpp:713] Persisted action at 0
>>> I1204 03:31:52.820047 31801 replica.cpp:538] Replica received write
>>> request for position 0 from (11497)@172.17.0.2:47200
>>> I1204 03:31:52.820125 31801 leveldb.cpp:436] Reading position from
>>> leveldb took 37411ns
>>> I1204 03:31:52.843890 31801 leveldb.cpp:341] Persisting action (14
>>> bytes) to leveldb took 23.710606ms
>>> I1204 03:31:52.843935 31801 replica.cpp:713] Persisted action at 0
>>> I1204 03:31:52.844709 31800 replica.cpp:692] Replica received learned
>>> notice for position 0 from @0.0.0.0:0
>>> I1204 03:31:52.868993 31800 leveldb.cpp:341] Persisting action (16
>>> bytes) to leveldb took 24.242639ms
>>> I1204 03:31:52.869032 31800 replica.cpp:713] Persisted action at 0
>>> I1204 03:31:52.869055 31800 replica.cpp:698] Replica learned NOP action
>>> at position 0
>>> I1204 03:31:52.869815 31797 log.cpp:675] Writer started with ending
>>> position 0
>>> I1204 03:31:52.871470 31789 leveldb.cpp:436] Reading position from
>>> leveldb took 40828ns
>>> I1204 03:31:52.872885 31790 registrar.cpp:340] Successfully fetched the
>>> registry (0B) in 154.009088ms
>>> I1204 03:31:52.873096 31790 registrar.cpp:439] Applied 1 operations in
>>> 32282ns; attempting to update the 'registry'
>>> I1204 03:31:52.874133 31800 log.cpp:683] Attempting to append 170 bytes
>>> to the log
>>> I1204 03:31:52.874337 31796 coordinator.cpp:348] Coordinator attempting
>>> to write APPEND action at position 1
>>> I1204 03:31:52.875277 31800 replica.cpp:538] Replica received write
>>> request for position 1 from (11498)@172.17.0.2:47200
>>> I1204 03:31:52.902500 31800 leveldb.cpp:341] Persisting action (189
>>> bytes) to leveldb took 27.170365ms
>>> I1204 03:31:52.902545 31800 replica.cpp:713] Persisted action at 1
>>> I1204 03:31:52.903542 31798 replica.cpp:692] Replica received learned
>>> notice for position 1 from @0.0.0.0:0
>>> I1204 03:31:52.927577 31798 leveldb.cpp:341] Persisting action (191
>>> bytes) to leveldb took 23.991773ms
>>> I1204 03:31:52.927616 31798 replica.cpp:713] Persisted action at 1
>>> I1204 03:31:52.927639 31798 replica.cpp:698] Replica learned APPEND
>>> action at position 1
>>> I1204 03:31:52.928863 31794 registrar.cpp:484] Successfully updated the
>>> 'registry' in 55.643136ms
>>> I1204 03:31:52.929076 31794 registrar.cpp:370] Successfully recovered
>>> registrar
>>> I1204 03:31:52.929177 31799 log.cpp:702] Attempting to truncate the log
>>> to 1
>>> I1204 03:31:52.929407 31797 coordinator.cpp:348] Coordinator attempting
>>> to write TRUNCATE action at position 2
>>> I1204 03:31:52.929703 31795 master.cpp:1447] Recovered 0 slaves from the
>>> Registry (131B) ; allowing 10mins for slaves to re-register
>>> I1204 03:31:52.929723 31799 hierarchical.cpp:181] Skipping recovery of
>>> hierarchical allocator: nothing to recover
>>> I1204 03:31:52.930577 31788 replica.cpp:538] Replica received write
>>> request for position 2 from (11499)@172.17.0.2:47200
>>> I1204 03:31:52.952744 31788 leveldb.cpp:341] Persisting action (16
>>> bytes) to leveldb took 22.115164ms
>>> I1204 03:31:52.952781 31788 replica.cpp:713] Persisted action at 2
>>> I1204 03:31:52.953629 31798 replica.cpp:692] Replica received learned
>>> notice for position 2 from @0.0.0.0:0
>>> I1204 03:31:52.977794 31798 leveldb.cpp:341] Persisting action (18
>>> bytes) to leveldb took 24.127932ms
>>> I1204 03:31:52.977882 31798 leveldb.cpp:399] Deleting ~1 keys from
>>> leveldb took 46051ns
>>> I1204 03:31:52.977926 31798 replica.cpp:713] Persisted action at 2
>>> I1204 03:31:52.977954 31798 replica.cpp:698] Replica learned TRUNCATE
>>> action at position 2
>>> I1204 03:31:52.981016 31769 scheduler.cpp:154] Version: 0.27.0
>>> I1204 03:31:52.981828 31793 scheduler.cpp:236] New master detected at
>>> master@172.17.0.2:47200
>>> I1204 03:31:52.983167 31789 scheduler.cpp:298] Sending SUBSCRIBE call to
>>> master@172.17.0.2:47200
>>> I1204 03:31:52.985347 31789 process.cpp:3067] Handling HTTP event for
>>> process 'master' with path: '/master/api/v1/scheduler'
>>> I1204 03:31:52.985502 31789 http.cpp:336] HTTP POST for
>>> /master/api/v1/scheduler from 172.17.0.2:33009
>>> I1204 03:31:52.985939 31789 master.cpp:1899] Received subscription
>>> request for HTTP framework 'default'
>>> I1204 03:31:52.986045 31789 master.cpp:1676] Authorizing framework
>>> principal 'test-principal' to receive offers for role '*'
>>> I1204 03:31:52.986364 31789 master.cpp:1991] Subscribing framework
>>> 'default' with checkpointing disabled and capabilities [  ]
>>> I1204 03:31:52.986779 31799 hierarchical.cpp:266] Added framework
>>> 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
>>> I1204 03:31:52.986913 31796 master.hpp:1583] Sending heartbeat to
>>> 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
>>> I1204 03:31:52.986996 31799 hierarchical.cpp:1308] No resources
>>> available to allocate!
>>> I1204 03:31:52.987063 31799 hierarchical.cpp:1401] No inverse offers to
>>> send out!
>>> I1204 03:31:52.987110 31799 hierarchical.cpp:1048] Performed allocation
>>> for 0 slaves in 189242ns
>>> I1204 03:31:52.987913 31798 scheduler.cpp:457] Enqueuing event
>>> SUBSCRIBED received from master@172.17.0.2:47200
>>> I1204 03:31:52.988831 31798 scheduler.cpp:457] Enqueuing event HEARTBEAT
>>> received from master@172.17.0.2:47200
>>> I1204 03:31:52.989537 31788 master_maintenance_tests.cpp:172] Ignoring
>>> HEARTBEAT event
>>> I1204 03:31:52.989886 31801 scheduler.cpp:298] Sending REQUEST call to
>>> master@172.17.0.2:47200
>>> I1204 03:31:52.991730 31792 process.cpp:3067] Handling HTTP event for
>>> process 'master' with path: '/master/api/v1/scheduler'
>>> I1204 03:31:52.991812 31792 http.cpp:336] HTTP POST for
>>> /master/api/v1/scheduler from 172.17.0.2:33010
>>> I1204 03:31:52.992156 31792 master.cpp:2646] Processing REQUEST call for
>>> framework 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000 (default)
>>> I1204 03:31:52.992516 31790 hierarchical.cpp:557] Received resource
>>> request from framework 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
>>> I1204 03:31:52.992923 31800 master.cpp:938] Master terminating
>>> I1204 03:31:52.993132 31796 hierarchical.cpp:306] Removed framework
>>> 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
>>> E1204 03:31:52.993708 31798 scheduler.cpp:431] End-Of-File received from
>>> master. The master closed the event stream
>>> [       OK ] ContentType/SchedulerTest.Request/1 (431 ms)
>>> [----------] 22 tests from ContentType/SchedulerTest (15741 ms total)
>>>
>>> [----------] Global test environment tear-down
>>> [==========] 878 tests from 116 test cases ran. (711169 ms total)
>>> [  PASSED  ] 877 tests.
>>> [  FAILED  ] 1 test, listed below:
>>> [  FAILED  ] ReservationTest.ACLMultipleOperations
>>>
>>>  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-1449197270-18036
>>> Untagged: mesos-1449197270-18036:latest
>>> Deleted: 71bc3adfccbfe4c515166abab14facf5895235fd4358c75eafe7552377b4ed12
>>> Deleted: c04522c46bffaa92efd2450d00842a14171f47c8ae50942666829e4dca2a7ada
>>> Deleted: d5849061eee06f14b51d9d7237588a0fe83fd953abfc1713692bd1247d04220f
>>> Deleted: 20d1e630457de2edba4f2fabe62ee3bcc7de4243ec737ce2a545a83de876613d
>>> Deleted: 64bba51bd0cdcb0d983deeb4cd1aa27ceb02bd4703c24f2692024c5a1537de44
>>> Deleted: 59e85ec64b5ee2735cde5403fe8def7375ffca98f9ea7953c802705673efb8cd
>>> Deleted: bee88887921d3d7d38f87744f4f49cb346037ce8a8b09af9d29686376200d66e
>>> Deleted: 709b8b667cf349fbcf14fbc48a0316319b341baaa1dd61f6a48c66d37b2dc628
>>> Deleted: e2c4f6d787499248e303270ff419e2545075e24a83101ed5316f4ecc907bba69
>>> Deleted: 0b8ee088204fbd6b9b1fa2f1a503763106b444f6a0b5d64ad6136269f821e487
>>> Deleted: 5657d8070e24ed2e2c43b0ac6ac0536208680be1f4e18031f5c76fd722aff863
>>> Deleted: 5e4dcfbaf3cc159742402a11e2c8b27efa71ec0ec202abd22acf5f553691f9c6
>>> Deleted: f589a283ec591fb354c074375571f136e15baa088534a380ac69255b6565ecdd
>>> Build step 'Execute shell' marked build as failure
>>>
>>
>>

Re: Build failed in Jenkins: Mesos » gcc,--verbose --enable-libevent --enable-ssl,ubuntu:14.04,docker||Hadoop #1319

Posted by Michael Park <mp...@mesosphere.io>.
+Greg since he's the author, he might have a better idea

On Thu, Dec 3, 2015, 10:36 PM Benjamin Mahler <be...@gmail.com>
wrote:

> Michael can you please triage this test?
>
> On Thu, Dec 3, 2015 at 7:31 PM, Apache Jenkins Server <
> jenkins@builds.apache.org> wrote:
>
>> See <
>> https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose%20--enable-libevent%20--enable-ssl,OS=ubuntu%3A14.04,label_exp=docker%7C%7CHadoop/1319/changes
>> >
>>
>> Changes:
>>
>> [benjamin.mahler] Documented why OsSignalsTest.Suppress works on OS X.
>>
>> ------------------------------------------
>> [...truncated 151042 lines...]
>> I1204 03:31:52.023347 31790 gc.cpp:54] Scheduling
>> '/tmp/ContentType_SchedulerTest_Message_1_jkcDGA/slaves/e567d75e-4b42-4184-a487-498d6e3e86f0-S0/frameworks/e567d75e-4b42-4184-a487-498d6e3e86f0-0000/executors/default/runs/ad6c9ae3-14b4-4ae0-85e0-2b66874c1d0f'
>> for gc 6.99999973126222days in the future
>> I1204 03:31:52.023437 31792 slave.cpp:3773] Cleaning up framework
>> e567d75e-4b42-4184-a487-498d6e3e86f0-0000
>> I1204 03:31:52.023515 31790 gc.cpp:54] Scheduling
>> '/tmp/ContentType_SchedulerTest_Message_1_jkcDGA/slaves/e567d75e-4b42-4184-a487-498d6e3e86f0-S0/frameworks/e567d75e-4b42-4184-a487-498d6e3e86f0-0000/executors/default'
>> for gc 6.99999972944593days in the future
>> I1204 03:31:52.023558 31794 status_update_manager.cpp:282] Closing status
>> update streams for framework e567d75e-4b42-4184-a487-498d6e3e86f0-0000
>> I1204 03:31:52.023623 31794 status_update_manager.cpp:528] Cleaning up
>> status update stream for task 3ee27512-7308-4ddf-8ab0-eb17196ad555 of
>> framework e567d75e-4b42-4184-a487-498d6e3e86f0-0000
>> I1204 03:31:52.023661 31790 gc.cpp:54] Scheduling
>> '/tmp/ContentType_SchedulerTest_Message_1_jkcDGA/slaves/e567d75e-4b42-4184-a487-498d6e3e86f0-S0/frameworks/e567d75e-4b42-4184-a487-498d6e3e86f0-0000'
>> for gc 6.99999972689778days in the future
>> [       OK ] ContentType/SchedulerTest.Message/1 (675 ms)
>> [ RUN      ] ContentType/SchedulerTest.Request/0
>> I1204 03:31:52.124193 31769 leveldb.cpp:174] Opened db in 94.016525ms
>> I1204 03:31:52.149694 31769 leveldb.cpp:181] Compacted db in 25.458791ms
>> I1204 03:31:52.149760 31769 leveldb.cpp:196] Created db iterator in
>> 20834ns
>> I1204 03:31:52.149780 31769 leveldb.cpp:202] Seeked to beginning of db in
>> 1977ns
>> I1204 03:31:52.149791 31769 leveldb.cpp:271] Iterated through 0 keys in
>> the db in 303ns
>> I1204 03:31:52.149832 31769 replica.cpp:778] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I1204 03:31:52.150544 31791 recover.cpp:447] Starting replica recovery
>> I1204 03:31:52.151046 31791 recover.cpp:473] Replica is in EMPTY status
>> I1204 03:31:52.152299 31802 replica.cpp:674] Replica in EMPTY status
>> received a broadcasted recover request from (11482)@172.17.0.2:47200
>> I1204 03:31:52.152914 31801 recover.cpp:193] Received a recover response
>> from a replica in EMPTY status
>> I1204 03:31:52.153547 31799 recover.cpp:564] Updating replica status to
>> STARTING
>> I1204 03:31:52.153744 31803 master.cpp:365] Master
>> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe (403686b83bbb) started on
>> 172.17.0.2:47200
>> I1204 03:31:52.153775 31803 master.cpp:367] Flags at startup: --acls=""
>> --allocation_interval="1secs" --allocator="HierarchicalDRF"
>> --authenticate="false" --authenticate_slaves="true"
>> --authenticators="crammd5" --authorizers="local"
>> --credentials="/tmp/0wBPVf/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/0wBPVf/master" --zk_session_timeout="10secs"
>> I1204 03:31:52.154326 31803 master.cpp:414] Master allowing
>> unauthenticated frameworks to register
>> I1204 03:31:52.154345 31803 master.cpp:417] Master only allowing
>> authenticated slaves to register
>> I1204 03:31:52.154361 31803 credentials.hpp:35] Loading credentials for
>> authentication from '/tmp/0wBPVf/credentials'
>> I1204 03:31:52.154675 31803 master.cpp:456] Using default 'crammd5'
>> authenticator
>> I1204 03:31:52.154832 31803 master.cpp:493] Authorization enabled
>> I1204 03:31:52.155102 31788 whitelist_watcher.cpp:77] No whitelist given
>> I1204 03:31:52.155231 31796 hierarchical.cpp:163] Initialized
>> hierarchical allocator process
>> I1204 03:31:52.157017 31791 master.cpp:1637] The newly elected leader is
>> master@172.17.0.2:47200 with id 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe
>> I1204 03:31:52.157053 31791 master.cpp:1650] Elected as the leading
>> master!
>> I1204 03:31:52.157073 31791 master.cpp:1395] Recovering from registrar
>> I1204 03:31:52.157237 31796 registrar.cpp:307] Recovering registrar
>> I1204 03:31:52.186647 31798 leveldb.cpp:304] Persisting metadata (8
>> bytes) to leveldb took 32.571067ms
>> I1204 03:31:52.186686 31798 replica.cpp:321] Persisted replica status to
>> STARTING
>> I1204 03:31:52.187000 31803 recover.cpp:473] Replica is in STARTING status
>> I1204 03:31:52.188062 31800 replica.cpp:674] Replica in STARTING status
>> received a broadcasted recover request from (11483)@172.17.0.2:47200
>> I1204 03:31:52.188350 31792 recover.cpp:193] Received a recover response
>> from a replica in STARTING status
>> I1204 03:31:52.188809 31796 recover.cpp:564] Updating replica status to
>> VOTING
>> I1204 03:31:52.220109 31797 leveldb.cpp:304] Persisting metadata (8
>> bytes) to leveldb took 31.054929ms
>> I1204 03:31:52.220147 31797 replica.cpp:321] Persisted replica status to
>> VOTING
>> I1204 03:31:52.220288 31792 recover.cpp:578] Successfully joined the
>> Paxos group
>> I1204 03:31:52.220634 31792 recover.cpp:462] Recover process terminated
>> I1204 03:31:52.221151 31802 log.cpp:659] Attempting to start the writer
>> I1204 03:31:52.222534 31801 replica.cpp:494] Replica received implicit
>> promise request from (11484)@172.17.0.2:47200 with proposal 1
>> I1204 03:31:52.245628 31801 leveldb.cpp:304] Persisting metadata (8
>> bytes) to leveldb took 23.049981ms
>> I1204 03:31:52.245667 31801 replica.cpp:343] Persisted promised to 1
>> I1204 03:31:52.246343 31793 coordinator.cpp:238] Coordinator attempting
>> to fill missing positions
>> I1204 03:31:52.247530 31788 replica.cpp:389] Replica received explicit
>> promise request from (11485)@172.17.0.2:47200 for position 0 with
>> proposal 2
>> I1204 03:31:52.287514 31788 leveldb.cpp:341] Persisting action (8 bytes)
>> to leveldb took 39.94388ms
>> I1204 03:31:52.287552 31788 replica.cpp:713] Persisted action at 0
>> I1204 03:31:52.288843 31802 replica.cpp:538] Replica received write
>> request for position 0 from (11486)@172.17.0.2:47200
>> I1204 03:31:52.288903 31802 leveldb.cpp:436] Reading position from
>> leveldb took 29125ns
>> I1204 03:31:52.329651 31802 leveldb.cpp:341] Persisting action (14 bytes)
>> to leveldb took 40.69596ms
>> I1204 03:31:52.329701 31802 replica.cpp:713] Persisted action at 0
>> I1204 03:31:52.330826 31800 replica.cpp:692] Replica received learned
>> notice for position 0 from @0.0.0.0:0
>> I1204 03:31:52.383780 31800 leveldb.cpp:341] Persisting action (16 bytes)
>> to leveldb took 52.909056ms
>> I1204 03:31:52.383831 31800 replica.cpp:713] Persisted action at 0
>> I1204 03:31:52.383858 31800 replica.cpp:698] Replica learned NOP action
>> at position 0
>> I1204 03:31:52.384644 31794 log.cpp:675] Writer started with ending
>> position 0
>> I1204 03:31:52.385828 31791 leveldb.cpp:436] Reading position from
>> leveldb took 33950ns
>> I1204 03:31:52.386934 31791 registrar.cpp:340] Successfully fetched the
>> registry (0B) in 229.636864ms
>> I1204 03:31:52.387066 31791 registrar.cpp:439] Applied 1 operations in
>> 36217ns; attempting to update the 'registry'
>> I1204 03:31:52.387809 31794 log.cpp:683] Attempting to append 170 bytes
>> to the log
>> I1204 03:31:52.387995 31798 coordinator.cpp:348] Coordinator attempting
>> to write APPEND action at position 1
>> I1204 03:31:52.388667 31802 replica.cpp:538] Replica received write
>> request for position 1 from (11487)@172.17.0.2:47200
>> I1204 03:31:52.434088 31802 leveldb.cpp:341] Persisting action (189
>> bytes) to leveldb took 45.373715ms
>> I1204 03:31:52.434159 31802 replica.cpp:713] Persisted action at 1
>> I1204 03:31:52.435035 31803 replica.cpp:692] Replica received learned
>> notice for position 1 from @0.0.0.0:0
>> I1204 03:31:52.467439 31803 leveldb.cpp:341] Persisting action (191
>> bytes) to leveldb took 32.356386ms
>> I1204 03:31:52.467502 31803 replica.cpp:713] Persisted action at 1
>> I1204 03:31:52.467533 31803 replica.cpp:698] Replica learned APPEND
>> action at position 1
>> I1204 03:31:52.468945 31789 registrar.cpp:484] Successfully updated the
>> 'registry' in 81.793792ms
>> I1204 03:31:52.469149 31789 registrar.cpp:370] Successfully recovered
>> registrar
>> I1204 03:31:52.469293 31796 log.cpp:702] Attempting to truncate the log
>> to 1
>> I1204 03:31:52.469637 31797 coordinator.cpp:348] Coordinator attempting
>> to write TRUNCATE action at position 2
>> I1204 03:31:52.469657 31802 hierarchical.cpp:181] Skipping recovery of
>> hierarchical allocator: nothing to recover
>> I1204 03:31:52.469641 31795 master.cpp:1447] Recovered 0 slaves from the
>> Registry (131B) ; allowing 10mins for slaves to re-register
>> I1204 03:31:52.470474 31795 replica.cpp:538] Replica received write
>> request for position 2 from (11488)@172.17.0.2:47200
>> I1204 03:31:52.509683 31795 leveldb.cpp:341] Persisting action (16 bytes)
>> to leveldb took 39.16527ms
>> I1204 03:31:52.509734 31795 replica.cpp:713] Persisted action at 2
>> I1204 03:31:52.511015 31801 replica.cpp:692] Replica received learned
>> notice for position 2 from @0.0.0.0:0
>> I1204 03:31:52.546566 31801 leveldb.cpp:341] Persisting action (18 bytes)
>> to leveldb took 35.510343ms
>> I1204 03:31:52.546649 31801 leveldb.cpp:399] Deleting ~1 keys from
>> leveldb took 42968ns
>> I1204 03:31:52.546674 31801 replica.cpp:713] Persisted action at 2
>> I1204 03:31:52.546696 31801 replica.cpp:698] Replica learned TRUNCATE
>> action at position 2
>> I1204 03:31:52.551092 31769 scheduler.cpp:154] Version: 0.27.0
>> I1204 03:31:52.552342 31798 scheduler.cpp:236] New master detected at
>> master@172.17.0.2:47200
>> I1204 03:31:52.553699 31795 scheduler.cpp:298] Sending SUBSCRIBE call to
>> master@172.17.0.2:47200
>> I1204 03:31:52.555797 31802 process.cpp:3067] Handling HTTP event for
>> process 'master' with path: '/master/api/v1/scheduler'
>> I1204 03:31:52.555894 31802 http.cpp:336] HTTP POST for
>> /master/api/v1/scheduler from 172.17.0.2:33004
>> I1204 03:31:52.556227 31802 master.cpp:1899] Received subscription
>> request for HTTP framework 'default'
>> I1204 03:31:52.556316 31802 master.cpp:1676] Authorizing framework
>> principal 'test-principal' to receive offers for role '*'
>> I1204 03:31:52.556674 31802 master.cpp:1991] Subscribing framework
>> 'default' with checkpointing disabled and capabilities [  ]
>> I1204 03:31:52.557163 31790 hierarchical.cpp:266] Added framework
>> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
>> I1204 03:31:52.557260 31790 hierarchical.cpp:1308] No resources available
>> to allocate!
>> I1204 03:31:52.557313 31790 hierarchical.cpp:1401] No inverse offers to
>> send out!
>> I1204 03:31:52.557312 31794 master.hpp:1583] Sending heartbeat to
>> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
>> I1204 03:31:52.557363 31790 hierarchical.cpp:1048] Performed allocation
>> for 0 slaves in 164108ns
>> I1204 03:31:52.558205 31802 scheduler.cpp:457] Enqueuing event SUBSCRIBED
>> received from master@172.17.0.2:47200
>> I1204 03:31:52.558789 31802 scheduler.cpp:457] Enqueuing event HEARTBEAT
>> received from master@172.17.0.2:47200
>> I1204 03:31:52.559478 31788 master_maintenance_tests.cpp:172] Ignoring
>> HEARTBEAT event
>> I1204 03:31:52.559605 31801 scheduler.cpp:298] Sending REQUEST call to
>> master@172.17.0.2:47200
>> I1204 03:31:52.561221 31803 process.cpp:3067] Handling HTTP event for
>> process 'master' with path: '/master/api/v1/scheduler'
>> I1204 03:31:52.561274 31803 http.cpp:336] HTTP POST for
>> /master/api/v1/scheduler from 172.17.0.2:33005
>> I1204 03:31:52.561362 31803 master.cpp:2646] Processing REQUEST call for
>> framework 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000 (default)
>> I1204 03:31:52.561527 31800 hierarchical.cpp:557] Received resource
>> request from framework 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
>> I1204 03:31:52.561843 31798 master.cpp:938] Master terminating
>> I1204 03:31:52.562047 31794 hierarchical.cpp:306] Removed framework
>> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
>> E1204 03:31:52.563323 31802 scheduler.cpp:431] End-Of-File received from
>> master. The master closed the event stream
>> [       OK ] ContentType/SchedulerTest.Request/0 (540 ms)
>> [ RUN      ] ContentType/SchedulerTest.Request/1
>> I1204 03:31:52.664904 31769 leveldb.cpp:174] Opened db in 95.062723ms
>> I1204 03:31:52.710089 31769 leveldb.cpp:181] Compacted db in 45.135601ms
>> I1204 03:31:52.710189 31769 leveldb.cpp:196] Created db iterator in
>> 41589ns
>> I1204 03:31:52.710208 31769 leveldb.cpp:202] Seeked to beginning of db in
>> 1962ns
>> I1204 03:31:52.710218 31769 leveldb.cpp:271] Iterated through 0 keys in
>> the db in 280ns
>> I1204 03:31:52.710280 31769 replica.cpp:778] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I1204 03:31:52.711068 31792 recover.cpp:447] Starting replica recovery
>> I1204 03:31:52.711433 31792 recover.cpp:473] Replica is in EMPTY status
>> I1204 03:31:52.713116 31802 replica.cpp:674] Replica in EMPTY status
>> received a broadcasted recover request from (11493)@172.17.0.2:47200
>> I1204 03:31:52.713871 31800 recover.cpp:193] Received a recover response
>> from a replica in EMPTY status
>> I1204 03:31:52.714603 31799 recover.cpp:564] Updating replica status to
>> STARTING
>> I1204 03:31:52.715018 31800 master.cpp:365] Master
>> 82e2943a-0ffa-43db-ab30-d280bc15aad8 (403686b83bbb) started on
>> 172.17.0.2:47200
>> I1204 03:31:52.715071 31800 master.cpp:367] Flags at startup: --acls=""
>> --allocation_interval="1secs" --allocator="HierarchicalDRF"
>> --authenticate="false" --authenticate_slaves="true"
>> --authenticators="crammd5" --authorizers="local"
>> --credentials="/tmp/3FPUXP/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/3FPUXP/master" --zk_session_timeout="10secs"
>> I1204 03:31:52.715515 31800 master.cpp:414] Master allowing
>> unauthenticated frameworks to register
>> I1204 03:31:52.715529 31800 master.cpp:417] Master only allowing
>> authenticated slaves to register
>> I1204 03:31:52.715538 31800 credentials.hpp:35] Loading credentials for
>> authentication from '/tmp/3FPUXP/credentials'
>> I1204 03:31:52.715888 31800 master.cpp:456] Using default 'crammd5'
>> authenticator
>> I1204 03:31:52.716110 31800 master.cpp:493] Authorization enabled
>> I1204 03:31:52.716346 31799 whitelist_watcher.cpp:77] No whitelist given
>> I1204 03:31:52.716421 31788 hierarchical.cpp:163] Initialized
>> hierarchical allocator process
>> I1204 03:31:52.718489 31798 master.cpp:1637] The newly elected leader is
>> master@172.17.0.2:47200 with id 82e2943a-0ffa-43db-ab30-d280bc15aad8
>> I1204 03:31:52.718533 31798 master.cpp:1650] Elected as the leading
>> master!
>> I1204 03:31:52.718557 31798 master.cpp:1395] Recovering from registrar
>> I1204 03:31:52.718823 31803 registrar.cpp:307] Recovering registrar
>> I1204 03:31:52.743455 31790 leveldb.cpp:304] Persisting metadata (8
>> bytes) to leveldb took 28.301712ms
>> I1204 03:31:52.743496 31790 replica.cpp:321] Persisted replica status to
>> STARTING
>> I1204 03:31:52.743876 31795 recover.cpp:473] Replica is in STARTING status
>> I1204 03:31:52.745254 31796 replica.cpp:674] Replica in STARTING status
>> received a broadcasted recover request from (11494)@172.17.0.2:47200
>> I1204 03:31:52.745743 31791 recover.cpp:193] Received a recover response
>> from a replica in STARTING status
>> I1204 03:31:52.746407 31797 recover.cpp:564] Updating replica status to
>> VOTING
>> I1204 03:31:52.768430 31802 leveldb.cpp:304] Persisting metadata (8
>> bytes) to leveldb took 21.81261ms
>> I1204 03:31:52.768474 31802 replica.cpp:321] Persisted replica status to
>> VOTING
>> I1204 03:31:52.768616 31802 recover.cpp:578] Successfully joined the
>> Paxos group
>> I1204 03:31:52.768904 31802 recover.cpp:462] Recover process terminated
>> I1204 03:31:52.769584 31800 log.cpp:659] Attempting to start the writer
>> I1204 03:31:52.771621 31789 replica.cpp:494] Replica received implicit
>> promise request from (11495)@172.17.0.2:47200 with proposal 1
>> I1204 03:31:52.793648 31789 leveldb.cpp:304] Persisting metadata (8
>> bytes) to leveldb took 21.993492ms
>> I1204 03:31:52.793694 31789 replica.cpp:343] Persisted promised to 1
>> I1204 03:31:52.794865 31798 coordinator.cpp:238] Coordinator attempting
>> to fill missing positions
>> I1204 03:31:52.796506 31799 replica.cpp:389] Replica received explicit
>> promise request from (11496)@172.17.0.2:47200 for position 0 with
>> proposal 2
>> I1204 03:31:52.818649 31799 leveldb.cpp:341] Persisting action (8 bytes)
>> to leveldb took 22.082655ms
>> I1204 03:31:52.818688 31799 replica.cpp:713] Persisted action at 0
>> I1204 03:31:52.820047 31801 replica.cpp:538] Replica received write
>> request for position 0 from (11497)@172.17.0.2:47200
>> I1204 03:31:52.820125 31801 leveldb.cpp:436] Reading position from
>> leveldb took 37411ns
>> I1204 03:31:52.843890 31801 leveldb.cpp:341] Persisting action (14 bytes)
>> to leveldb took 23.710606ms
>> I1204 03:31:52.843935 31801 replica.cpp:713] Persisted action at 0
>> I1204 03:31:52.844709 31800 replica.cpp:692] Replica received learned
>> notice for position 0 from @0.0.0.0:0
>> I1204 03:31:52.868993 31800 leveldb.cpp:341] Persisting action (16 bytes)
>> to leveldb took 24.242639ms
>> I1204 03:31:52.869032 31800 replica.cpp:713] Persisted action at 0
>> I1204 03:31:52.869055 31800 replica.cpp:698] Replica learned NOP action
>> at position 0
>> I1204 03:31:52.869815 31797 log.cpp:675] Writer started with ending
>> position 0
>> I1204 03:31:52.871470 31789 leveldb.cpp:436] Reading position from
>> leveldb took 40828ns
>> I1204 03:31:52.872885 31790 registrar.cpp:340] Successfully fetched the
>> registry (0B) in 154.009088ms
>> I1204 03:31:52.873096 31790 registrar.cpp:439] Applied 1 operations in
>> 32282ns; attempting to update the 'registry'
>> I1204 03:31:52.874133 31800 log.cpp:683] Attempting to append 170 bytes
>> to the log
>> I1204 03:31:52.874337 31796 coordinator.cpp:348] Coordinator attempting
>> to write APPEND action at position 1
>> I1204 03:31:52.875277 31800 replica.cpp:538] Replica received write
>> request for position 1 from (11498)@172.17.0.2:47200
>> I1204 03:31:52.902500 31800 leveldb.cpp:341] Persisting action (189
>> bytes) to leveldb took 27.170365ms
>> I1204 03:31:52.902545 31800 replica.cpp:713] Persisted action at 1
>> I1204 03:31:52.903542 31798 replica.cpp:692] Replica received learned
>> notice for position 1 from @0.0.0.0:0
>> I1204 03:31:52.927577 31798 leveldb.cpp:341] Persisting action (191
>> bytes) to leveldb took 23.991773ms
>> I1204 03:31:52.927616 31798 replica.cpp:713] Persisted action at 1
>> I1204 03:31:52.927639 31798 replica.cpp:698] Replica learned APPEND
>> action at position 1
>> I1204 03:31:52.928863 31794 registrar.cpp:484] Successfully updated the
>> 'registry' in 55.643136ms
>> I1204 03:31:52.929076 31794 registrar.cpp:370] Successfully recovered
>> registrar
>> I1204 03:31:52.929177 31799 log.cpp:702] Attempting to truncate the log
>> to 1
>> I1204 03:31:52.929407 31797 coordinator.cpp:348] Coordinator attempting
>> to write TRUNCATE action at position 2
>> I1204 03:31:52.929703 31795 master.cpp:1447] Recovered 0 slaves from the
>> Registry (131B) ; allowing 10mins for slaves to re-register
>> I1204 03:31:52.929723 31799 hierarchical.cpp:181] Skipping recovery of
>> hierarchical allocator: nothing to recover
>> I1204 03:31:52.930577 31788 replica.cpp:538] Replica received write
>> request for position 2 from (11499)@172.17.0.2:47200
>> I1204 03:31:52.952744 31788 leveldb.cpp:341] Persisting action (16 bytes)
>> to leveldb took 22.115164ms
>> I1204 03:31:52.952781 31788 replica.cpp:713] Persisted action at 2
>> I1204 03:31:52.953629 31798 replica.cpp:692] Replica received learned
>> notice for position 2 from @0.0.0.0:0
>> I1204 03:31:52.977794 31798 leveldb.cpp:341] Persisting action (18 bytes)
>> to leveldb took 24.127932ms
>> I1204 03:31:52.977882 31798 leveldb.cpp:399] Deleting ~1 keys from
>> leveldb took 46051ns
>> I1204 03:31:52.977926 31798 replica.cpp:713] Persisted action at 2
>> I1204 03:31:52.977954 31798 replica.cpp:698] Replica learned TRUNCATE
>> action at position 2
>> I1204 03:31:52.981016 31769 scheduler.cpp:154] Version: 0.27.0
>> I1204 03:31:52.981828 31793 scheduler.cpp:236] New master detected at
>> master@172.17.0.2:47200
>> I1204 03:31:52.983167 31789 scheduler.cpp:298] Sending SUBSCRIBE call to
>> master@172.17.0.2:47200
>> I1204 03:31:52.985347 31789 process.cpp:3067] Handling HTTP event for
>> process 'master' with path: '/master/api/v1/scheduler'
>> I1204 03:31:52.985502 31789 http.cpp:336] HTTP POST for
>> /master/api/v1/scheduler from 172.17.0.2:33009
>> I1204 03:31:52.985939 31789 master.cpp:1899] Received subscription
>> request for HTTP framework 'default'
>> I1204 03:31:52.986045 31789 master.cpp:1676] Authorizing framework
>> principal 'test-principal' to receive offers for role '*'
>> I1204 03:31:52.986364 31789 master.cpp:1991] Subscribing framework
>> 'default' with checkpointing disabled and capabilities [  ]
>> I1204 03:31:52.986779 31799 hierarchical.cpp:266] Added framework
>> 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
>> I1204 03:31:52.986913 31796 master.hpp:1583] Sending heartbeat to
>> 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
>> I1204 03:31:52.986996 31799 hierarchical.cpp:1308] No resources available
>> to allocate!
>> I1204 03:31:52.987063 31799 hierarchical.cpp:1401] No inverse offers to
>> send out!
>> I1204 03:31:52.987110 31799 hierarchical.cpp:1048] Performed allocation
>> for 0 slaves in 189242ns
>> I1204 03:31:52.987913 31798 scheduler.cpp:457] Enqueuing event SUBSCRIBED
>> received from master@172.17.0.2:47200
>> I1204 03:31:52.988831 31798 scheduler.cpp:457] Enqueuing event HEARTBEAT
>> received from master@172.17.0.2:47200
>> I1204 03:31:52.989537 31788 master_maintenance_tests.cpp:172] Ignoring
>> HEARTBEAT event
>> I1204 03:31:52.989886 31801 scheduler.cpp:298] Sending REQUEST call to
>> master@172.17.0.2:47200
>> I1204 03:31:52.991730 31792 process.cpp:3067] Handling HTTP event for
>> process 'master' with path: '/master/api/v1/scheduler'
>> I1204 03:31:52.991812 31792 http.cpp:336] HTTP POST for
>> /master/api/v1/scheduler from 172.17.0.2:33010
>> I1204 03:31:52.992156 31792 master.cpp:2646] Processing REQUEST call for
>> framework 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000 (default)
>> I1204 03:31:52.992516 31790 hierarchical.cpp:557] Received resource
>> request from framework 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
>> I1204 03:31:52.992923 31800 master.cpp:938] Master terminating
>> I1204 03:31:52.993132 31796 hierarchical.cpp:306] Removed framework
>> 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
>> E1204 03:31:52.993708 31798 scheduler.cpp:431] End-Of-File received from
>> master. The master closed the event stream
>> [       OK ] ContentType/SchedulerTest.Request/1 (431 ms)
>> [----------] 22 tests from ContentType/SchedulerTest (15741 ms total)
>>
>> [----------] Global test environment tear-down
>> [==========] 878 tests from 116 test cases ran. (711169 ms total)
>> [  PASSED  ] 877 tests.
>> [  FAILED  ] 1 test, listed below:
>> [  FAILED  ] ReservationTest.ACLMultipleOperations
>>
>>  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-1449197270-18036
>> Untagged: mesos-1449197270-18036:latest
>> Deleted: 71bc3adfccbfe4c515166abab14facf5895235fd4358c75eafe7552377b4ed12
>> Deleted: c04522c46bffaa92efd2450d00842a14171f47c8ae50942666829e4dca2a7ada
>> Deleted: d5849061eee06f14b51d9d7237588a0fe83fd953abfc1713692bd1247d04220f
>> Deleted: 20d1e630457de2edba4f2fabe62ee3bcc7de4243ec737ce2a545a83de876613d
>> Deleted: 64bba51bd0cdcb0d983deeb4cd1aa27ceb02bd4703c24f2692024c5a1537de44
>> Deleted: 59e85ec64b5ee2735cde5403fe8def7375ffca98f9ea7953c802705673efb8cd
>> Deleted: bee88887921d3d7d38f87744f4f49cb346037ce8a8b09af9d29686376200d66e
>> Deleted: 709b8b667cf349fbcf14fbc48a0316319b341baaa1dd61f6a48c66d37b2dc628
>> Deleted: e2c4f6d787499248e303270ff419e2545075e24a83101ed5316f4ecc907bba69
>> Deleted: 0b8ee088204fbd6b9b1fa2f1a503763106b444f6a0b5d64ad6136269f821e487
>> Deleted: 5657d8070e24ed2e2c43b0ac6ac0536208680be1f4e18031f5c76fd722aff863
>> Deleted: 5e4dcfbaf3cc159742402a11e2c8b27efa71ec0ec202abd22acf5f553691f9c6
>> Deleted: f589a283ec591fb354c074375571f136e15baa088534a380ac69255b6565ecdd
>> Build step 'Execute shell' marked build as failure
>>
>
>

Re: Build failed in Jenkins: Mesos » gcc,--verbose --enable-libevent --enable-ssl,ubuntu:14.04,docker||Hadoop #1319

Posted by Benjamin Mahler <be...@gmail.com>.
Michael can you please triage this test?

On Thu, Dec 3, 2015 at 7:31 PM, Apache Jenkins Server <
jenkins@builds.apache.org> wrote:

> See <
> https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose%20--enable-libevent%20--enable-ssl,OS=ubuntu%3A14.04,label_exp=docker%7C%7CHadoop/1319/changes
> >
>
> Changes:
>
> [benjamin.mahler] Documented why OsSignalsTest.Suppress works on OS X.
>
> ------------------------------------------
> [...truncated 151042 lines...]
> I1204 03:31:52.023347 31790 gc.cpp:54] Scheduling
> '/tmp/ContentType_SchedulerTest_Message_1_jkcDGA/slaves/e567d75e-4b42-4184-a487-498d6e3e86f0-S0/frameworks/e567d75e-4b42-4184-a487-498d6e3e86f0-0000/executors/default/runs/ad6c9ae3-14b4-4ae0-85e0-2b66874c1d0f'
> for gc 6.99999973126222days in the future
> I1204 03:31:52.023437 31792 slave.cpp:3773] Cleaning up framework
> e567d75e-4b42-4184-a487-498d6e3e86f0-0000
> I1204 03:31:52.023515 31790 gc.cpp:54] Scheduling
> '/tmp/ContentType_SchedulerTest_Message_1_jkcDGA/slaves/e567d75e-4b42-4184-a487-498d6e3e86f0-S0/frameworks/e567d75e-4b42-4184-a487-498d6e3e86f0-0000/executors/default'
> for gc 6.99999972944593days in the future
> I1204 03:31:52.023558 31794 status_update_manager.cpp:282] Closing status
> update streams for framework e567d75e-4b42-4184-a487-498d6e3e86f0-0000
> I1204 03:31:52.023623 31794 status_update_manager.cpp:528] Cleaning up
> status update stream for task 3ee27512-7308-4ddf-8ab0-eb17196ad555 of
> framework e567d75e-4b42-4184-a487-498d6e3e86f0-0000
> I1204 03:31:52.023661 31790 gc.cpp:54] Scheduling
> '/tmp/ContentType_SchedulerTest_Message_1_jkcDGA/slaves/e567d75e-4b42-4184-a487-498d6e3e86f0-S0/frameworks/e567d75e-4b42-4184-a487-498d6e3e86f0-0000'
> for gc 6.99999972689778days in the future
> [       OK ] ContentType/SchedulerTest.Message/1 (675 ms)
> [ RUN      ] ContentType/SchedulerTest.Request/0
> I1204 03:31:52.124193 31769 leveldb.cpp:174] Opened db in 94.016525ms
> I1204 03:31:52.149694 31769 leveldb.cpp:181] Compacted db in 25.458791ms
> I1204 03:31:52.149760 31769 leveldb.cpp:196] Created db iterator in 20834ns
> I1204 03:31:52.149780 31769 leveldb.cpp:202] Seeked to beginning of db in
> 1977ns
> I1204 03:31:52.149791 31769 leveldb.cpp:271] Iterated through 0 keys in
> the db in 303ns
> I1204 03:31:52.149832 31769 replica.cpp:778] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I1204 03:31:52.150544 31791 recover.cpp:447] Starting replica recovery
> I1204 03:31:52.151046 31791 recover.cpp:473] Replica is in EMPTY status
> I1204 03:31:52.152299 31802 replica.cpp:674] Replica in EMPTY status
> received a broadcasted recover request from (11482)@172.17.0.2:47200
> I1204 03:31:52.152914 31801 recover.cpp:193] Received a recover response
> from a replica in EMPTY status
> I1204 03:31:52.153547 31799 recover.cpp:564] Updating replica status to
> STARTING
> I1204 03:31:52.153744 31803 master.cpp:365] Master
> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe (403686b83bbb) started on
> 172.17.0.2:47200
> I1204 03:31:52.153775 31803 master.cpp:367] Flags at startup: --acls=""
> --allocation_interval="1secs" --allocator="HierarchicalDRF"
> --authenticate="false" --authenticate_slaves="true"
> --authenticators="crammd5" --authorizers="local"
> --credentials="/tmp/0wBPVf/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/0wBPVf/master" --zk_session_timeout="10secs"
> I1204 03:31:52.154326 31803 master.cpp:414] Master allowing
> unauthenticated frameworks to register
> I1204 03:31:52.154345 31803 master.cpp:417] Master only allowing
> authenticated slaves to register
> I1204 03:31:52.154361 31803 credentials.hpp:35] Loading credentials for
> authentication from '/tmp/0wBPVf/credentials'
> I1204 03:31:52.154675 31803 master.cpp:456] Using default 'crammd5'
> authenticator
> I1204 03:31:52.154832 31803 master.cpp:493] Authorization enabled
> I1204 03:31:52.155102 31788 whitelist_watcher.cpp:77] No whitelist given
> I1204 03:31:52.155231 31796 hierarchical.cpp:163] Initialized hierarchical
> allocator process
> I1204 03:31:52.157017 31791 master.cpp:1637] The newly elected leader is
> master@172.17.0.2:47200 with id 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe
> I1204 03:31:52.157053 31791 master.cpp:1650] Elected as the leading master!
> I1204 03:31:52.157073 31791 master.cpp:1395] Recovering from registrar
> I1204 03:31:52.157237 31796 registrar.cpp:307] Recovering registrar
> I1204 03:31:52.186647 31798 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 32.571067ms
> I1204 03:31:52.186686 31798 replica.cpp:321] Persisted replica status to
> STARTING
> I1204 03:31:52.187000 31803 recover.cpp:473] Replica is in STARTING status
> I1204 03:31:52.188062 31800 replica.cpp:674] Replica in STARTING status
> received a broadcasted recover request from (11483)@172.17.0.2:47200
> I1204 03:31:52.188350 31792 recover.cpp:193] Received a recover response
> from a replica in STARTING status
> I1204 03:31:52.188809 31796 recover.cpp:564] Updating replica status to
> VOTING
> I1204 03:31:52.220109 31797 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 31.054929ms
> I1204 03:31:52.220147 31797 replica.cpp:321] Persisted replica status to
> VOTING
> I1204 03:31:52.220288 31792 recover.cpp:578] Successfully joined the Paxos
> group
> I1204 03:31:52.220634 31792 recover.cpp:462] Recover process terminated
> I1204 03:31:52.221151 31802 log.cpp:659] Attempting to start the writer
> I1204 03:31:52.222534 31801 replica.cpp:494] Replica received implicit
> promise request from (11484)@172.17.0.2:47200 with proposal 1
> I1204 03:31:52.245628 31801 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 23.049981ms
> I1204 03:31:52.245667 31801 replica.cpp:343] Persisted promised to 1
> I1204 03:31:52.246343 31793 coordinator.cpp:238] Coordinator attempting to
> fill missing positions
> I1204 03:31:52.247530 31788 replica.cpp:389] Replica received explicit
> promise request from (11485)@172.17.0.2:47200 for position 0 with
> proposal 2
> I1204 03:31:52.287514 31788 leveldb.cpp:341] Persisting action (8 bytes)
> to leveldb took 39.94388ms
> I1204 03:31:52.287552 31788 replica.cpp:713] Persisted action at 0
> I1204 03:31:52.288843 31802 replica.cpp:538] Replica received write
> request for position 0 from (11486)@172.17.0.2:47200
> I1204 03:31:52.288903 31802 leveldb.cpp:436] Reading position from leveldb
> took 29125ns
> I1204 03:31:52.329651 31802 leveldb.cpp:341] Persisting action (14 bytes)
> to leveldb took 40.69596ms
> I1204 03:31:52.329701 31802 replica.cpp:713] Persisted action at 0
> I1204 03:31:52.330826 31800 replica.cpp:692] Replica received learned
> notice for position 0 from @0.0.0.0:0
> I1204 03:31:52.383780 31800 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 52.909056ms
> I1204 03:31:52.383831 31800 replica.cpp:713] Persisted action at 0
> I1204 03:31:52.383858 31800 replica.cpp:698] Replica learned NOP action at
> position 0
> I1204 03:31:52.384644 31794 log.cpp:675] Writer started with ending
> position 0
> I1204 03:31:52.385828 31791 leveldb.cpp:436] Reading position from leveldb
> took 33950ns
> I1204 03:31:52.386934 31791 registrar.cpp:340] Successfully fetched the
> registry (0B) in 229.636864ms
> I1204 03:31:52.387066 31791 registrar.cpp:439] Applied 1 operations in
> 36217ns; attempting to update the 'registry'
> I1204 03:31:52.387809 31794 log.cpp:683] Attempting to append 170 bytes to
> the log
> I1204 03:31:52.387995 31798 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 1
> I1204 03:31:52.388667 31802 replica.cpp:538] Replica received write
> request for position 1 from (11487)@172.17.0.2:47200
> I1204 03:31:52.434088 31802 leveldb.cpp:341] Persisting action (189 bytes)
> to leveldb took 45.373715ms
> I1204 03:31:52.434159 31802 replica.cpp:713] Persisted action at 1
> I1204 03:31:52.435035 31803 replica.cpp:692] Replica received learned
> notice for position 1 from @0.0.0.0:0
> I1204 03:31:52.467439 31803 leveldb.cpp:341] Persisting action (191 bytes)
> to leveldb took 32.356386ms
> I1204 03:31:52.467502 31803 replica.cpp:713] Persisted action at 1
> I1204 03:31:52.467533 31803 replica.cpp:698] Replica learned APPEND action
> at position 1
> I1204 03:31:52.468945 31789 registrar.cpp:484] Successfully updated the
> 'registry' in 81.793792ms
> I1204 03:31:52.469149 31789 registrar.cpp:370] Successfully recovered
> registrar
> I1204 03:31:52.469293 31796 log.cpp:702] Attempting to truncate the log to
> 1
> I1204 03:31:52.469637 31797 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 2
> I1204 03:31:52.469657 31802 hierarchical.cpp:181] Skipping recovery of
> hierarchical allocator: nothing to recover
> I1204 03:31:52.469641 31795 master.cpp:1447] Recovered 0 slaves from the
> Registry (131B) ; allowing 10mins for slaves to re-register
> I1204 03:31:52.470474 31795 replica.cpp:538] Replica received write
> request for position 2 from (11488)@172.17.0.2:47200
> I1204 03:31:52.509683 31795 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 39.16527ms
> I1204 03:31:52.509734 31795 replica.cpp:713] Persisted action at 2
> I1204 03:31:52.511015 31801 replica.cpp:692] Replica received learned
> notice for position 2 from @0.0.0.0:0
> I1204 03:31:52.546566 31801 leveldb.cpp:341] Persisting action (18 bytes)
> to leveldb took 35.510343ms
> I1204 03:31:52.546649 31801 leveldb.cpp:399] Deleting ~1 keys from leveldb
> took 42968ns
> I1204 03:31:52.546674 31801 replica.cpp:713] Persisted action at 2
> I1204 03:31:52.546696 31801 replica.cpp:698] Replica learned TRUNCATE
> action at position 2
> I1204 03:31:52.551092 31769 scheduler.cpp:154] Version: 0.27.0
> I1204 03:31:52.552342 31798 scheduler.cpp:236] New master detected at
> master@172.17.0.2:47200
> I1204 03:31:52.553699 31795 scheduler.cpp:298] Sending SUBSCRIBE call to
> master@172.17.0.2:47200
> I1204 03:31:52.555797 31802 process.cpp:3067] Handling HTTP event for
> process 'master' with path: '/master/api/v1/scheduler'
> I1204 03:31:52.555894 31802 http.cpp:336] HTTP POST for
> /master/api/v1/scheduler from 172.17.0.2:33004
> I1204 03:31:52.556227 31802 master.cpp:1899] Received subscription request
> for HTTP framework 'default'
> I1204 03:31:52.556316 31802 master.cpp:1676] Authorizing framework
> principal 'test-principal' to receive offers for role '*'
> I1204 03:31:52.556674 31802 master.cpp:1991] Subscribing framework
> 'default' with checkpointing disabled and capabilities [  ]
> I1204 03:31:52.557163 31790 hierarchical.cpp:266] Added framework
> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
> I1204 03:31:52.557260 31790 hierarchical.cpp:1308] No resources available
> to allocate!
> I1204 03:31:52.557313 31790 hierarchical.cpp:1401] No inverse offers to
> send out!
> I1204 03:31:52.557312 31794 master.hpp:1583] Sending heartbeat to
> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
> I1204 03:31:52.557363 31790 hierarchical.cpp:1048] Performed allocation
> for 0 slaves in 164108ns
> I1204 03:31:52.558205 31802 scheduler.cpp:457] Enqueuing event SUBSCRIBED
> received from master@172.17.0.2:47200
> I1204 03:31:52.558789 31802 scheduler.cpp:457] Enqueuing event HEARTBEAT
> received from master@172.17.0.2:47200
> I1204 03:31:52.559478 31788 master_maintenance_tests.cpp:172] Ignoring
> HEARTBEAT event
> I1204 03:31:52.559605 31801 scheduler.cpp:298] Sending REQUEST call to
> master@172.17.0.2:47200
> I1204 03:31:52.561221 31803 process.cpp:3067] Handling HTTP event for
> process 'master' with path: '/master/api/v1/scheduler'
> I1204 03:31:52.561274 31803 http.cpp:336] HTTP POST for
> /master/api/v1/scheduler from 172.17.0.2:33005
> I1204 03:31:52.561362 31803 master.cpp:2646] Processing REQUEST call for
> framework 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000 (default)
> I1204 03:31:52.561527 31800 hierarchical.cpp:557] Received resource
> request from framework 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
> I1204 03:31:52.561843 31798 master.cpp:938] Master terminating
> I1204 03:31:52.562047 31794 hierarchical.cpp:306] Removed framework
> 0b57d640-d54a-4ef7-b6c0-df2eaa52b0fe-0000
> E1204 03:31:52.563323 31802 scheduler.cpp:431] End-Of-File received from
> master. The master closed the event stream
> [       OK ] ContentType/SchedulerTest.Request/0 (540 ms)
> [ RUN      ] ContentType/SchedulerTest.Request/1
> I1204 03:31:52.664904 31769 leveldb.cpp:174] Opened db in 95.062723ms
> I1204 03:31:52.710089 31769 leveldb.cpp:181] Compacted db in 45.135601ms
> I1204 03:31:52.710189 31769 leveldb.cpp:196] Created db iterator in 41589ns
> I1204 03:31:52.710208 31769 leveldb.cpp:202] Seeked to beginning of db in
> 1962ns
> I1204 03:31:52.710218 31769 leveldb.cpp:271] Iterated through 0 keys in
> the db in 280ns
> I1204 03:31:52.710280 31769 replica.cpp:778] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I1204 03:31:52.711068 31792 recover.cpp:447] Starting replica recovery
> I1204 03:31:52.711433 31792 recover.cpp:473] Replica is in EMPTY status
> I1204 03:31:52.713116 31802 replica.cpp:674] Replica in EMPTY status
> received a broadcasted recover request from (11493)@172.17.0.2:47200
> I1204 03:31:52.713871 31800 recover.cpp:193] Received a recover response
> from a replica in EMPTY status
> I1204 03:31:52.714603 31799 recover.cpp:564] Updating replica status to
> STARTING
> I1204 03:31:52.715018 31800 master.cpp:365] Master
> 82e2943a-0ffa-43db-ab30-d280bc15aad8 (403686b83bbb) started on
> 172.17.0.2:47200
> I1204 03:31:52.715071 31800 master.cpp:367] Flags at startup: --acls=""
> --allocation_interval="1secs" --allocator="HierarchicalDRF"
> --authenticate="false" --authenticate_slaves="true"
> --authenticators="crammd5" --authorizers="local"
> --credentials="/tmp/3FPUXP/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/3FPUXP/master" --zk_session_timeout="10secs"
> I1204 03:31:52.715515 31800 master.cpp:414] Master allowing
> unauthenticated frameworks to register
> I1204 03:31:52.715529 31800 master.cpp:417] Master only allowing
> authenticated slaves to register
> I1204 03:31:52.715538 31800 credentials.hpp:35] Loading credentials for
> authentication from '/tmp/3FPUXP/credentials'
> I1204 03:31:52.715888 31800 master.cpp:456] Using default 'crammd5'
> authenticator
> I1204 03:31:52.716110 31800 master.cpp:493] Authorization enabled
> I1204 03:31:52.716346 31799 whitelist_watcher.cpp:77] No whitelist given
> I1204 03:31:52.716421 31788 hierarchical.cpp:163] Initialized hierarchical
> allocator process
> I1204 03:31:52.718489 31798 master.cpp:1637] The newly elected leader is
> master@172.17.0.2:47200 with id 82e2943a-0ffa-43db-ab30-d280bc15aad8
> I1204 03:31:52.718533 31798 master.cpp:1650] Elected as the leading master!
> I1204 03:31:52.718557 31798 master.cpp:1395] Recovering from registrar
> I1204 03:31:52.718823 31803 registrar.cpp:307] Recovering registrar
> I1204 03:31:52.743455 31790 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 28.301712ms
> I1204 03:31:52.743496 31790 replica.cpp:321] Persisted replica status to
> STARTING
> I1204 03:31:52.743876 31795 recover.cpp:473] Replica is in STARTING status
> I1204 03:31:52.745254 31796 replica.cpp:674] Replica in STARTING status
> received a broadcasted recover request from (11494)@172.17.0.2:47200
> I1204 03:31:52.745743 31791 recover.cpp:193] Received a recover response
> from a replica in STARTING status
> I1204 03:31:52.746407 31797 recover.cpp:564] Updating replica status to
> VOTING
> I1204 03:31:52.768430 31802 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 21.81261ms
> I1204 03:31:52.768474 31802 replica.cpp:321] Persisted replica status to
> VOTING
> I1204 03:31:52.768616 31802 recover.cpp:578] Successfully joined the Paxos
> group
> I1204 03:31:52.768904 31802 recover.cpp:462] Recover process terminated
> I1204 03:31:52.769584 31800 log.cpp:659] Attempting to start the writer
> I1204 03:31:52.771621 31789 replica.cpp:494] Replica received implicit
> promise request from (11495)@172.17.0.2:47200 with proposal 1
> I1204 03:31:52.793648 31789 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 21.993492ms
> I1204 03:31:52.793694 31789 replica.cpp:343] Persisted promised to 1
> I1204 03:31:52.794865 31798 coordinator.cpp:238] Coordinator attempting to
> fill missing positions
> I1204 03:31:52.796506 31799 replica.cpp:389] Replica received explicit
> promise request from (11496)@172.17.0.2:47200 for position 0 with
> proposal 2
> I1204 03:31:52.818649 31799 leveldb.cpp:341] Persisting action (8 bytes)
> to leveldb took 22.082655ms
> I1204 03:31:52.818688 31799 replica.cpp:713] Persisted action at 0
> I1204 03:31:52.820047 31801 replica.cpp:538] Replica received write
> request for position 0 from (11497)@172.17.0.2:47200
> I1204 03:31:52.820125 31801 leveldb.cpp:436] Reading position from leveldb
> took 37411ns
> I1204 03:31:52.843890 31801 leveldb.cpp:341] Persisting action (14 bytes)
> to leveldb took 23.710606ms
> I1204 03:31:52.843935 31801 replica.cpp:713] Persisted action at 0
> I1204 03:31:52.844709 31800 replica.cpp:692] Replica received learned
> notice for position 0 from @0.0.0.0:0
> I1204 03:31:52.868993 31800 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 24.242639ms
> I1204 03:31:52.869032 31800 replica.cpp:713] Persisted action at 0
> I1204 03:31:52.869055 31800 replica.cpp:698] Replica learned NOP action at
> position 0
> I1204 03:31:52.869815 31797 log.cpp:675] Writer started with ending
> position 0
> I1204 03:31:52.871470 31789 leveldb.cpp:436] Reading position from leveldb
> took 40828ns
> I1204 03:31:52.872885 31790 registrar.cpp:340] Successfully fetched the
> registry (0B) in 154.009088ms
> I1204 03:31:52.873096 31790 registrar.cpp:439] Applied 1 operations in
> 32282ns; attempting to update the 'registry'
> I1204 03:31:52.874133 31800 log.cpp:683] Attempting to append 170 bytes to
> the log
> I1204 03:31:52.874337 31796 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 1
> I1204 03:31:52.875277 31800 replica.cpp:538] Replica received write
> request for position 1 from (11498)@172.17.0.2:47200
> I1204 03:31:52.902500 31800 leveldb.cpp:341] Persisting action (189 bytes)
> to leveldb took 27.170365ms
> I1204 03:31:52.902545 31800 replica.cpp:713] Persisted action at 1
> I1204 03:31:52.903542 31798 replica.cpp:692] Replica received learned
> notice for position 1 from @0.0.0.0:0
> I1204 03:31:52.927577 31798 leveldb.cpp:341] Persisting action (191 bytes)
> to leveldb took 23.991773ms
> I1204 03:31:52.927616 31798 replica.cpp:713] Persisted action at 1
> I1204 03:31:52.927639 31798 replica.cpp:698] Replica learned APPEND action
> at position 1
> I1204 03:31:52.928863 31794 registrar.cpp:484] Successfully updated the
> 'registry' in 55.643136ms
> I1204 03:31:52.929076 31794 registrar.cpp:370] Successfully recovered
> registrar
> I1204 03:31:52.929177 31799 log.cpp:702] Attempting to truncate the log to
> 1
> I1204 03:31:52.929407 31797 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 2
> I1204 03:31:52.929703 31795 master.cpp:1447] Recovered 0 slaves from the
> Registry (131B) ; allowing 10mins for slaves to re-register
> I1204 03:31:52.929723 31799 hierarchical.cpp:181] Skipping recovery of
> hierarchical allocator: nothing to recover
> I1204 03:31:52.930577 31788 replica.cpp:538] Replica received write
> request for position 2 from (11499)@172.17.0.2:47200
> I1204 03:31:52.952744 31788 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 22.115164ms
> I1204 03:31:52.952781 31788 replica.cpp:713] Persisted action at 2
> I1204 03:31:52.953629 31798 replica.cpp:692] Replica received learned
> notice for position 2 from @0.0.0.0:0
> I1204 03:31:52.977794 31798 leveldb.cpp:341] Persisting action (18 bytes)
> to leveldb took 24.127932ms
> I1204 03:31:52.977882 31798 leveldb.cpp:399] Deleting ~1 keys from leveldb
> took 46051ns
> I1204 03:31:52.977926 31798 replica.cpp:713] Persisted action at 2
> I1204 03:31:52.977954 31798 replica.cpp:698] Replica learned TRUNCATE
> action at position 2
> I1204 03:31:52.981016 31769 scheduler.cpp:154] Version: 0.27.0
> I1204 03:31:52.981828 31793 scheduler.cpp:236] New master detected at
> master@172.17.0.2:47200
> I1204 03:31:52.983167 31789 scheduler.cpp:298] Sending SUBSCRIBE call to
> master@172.17.0.2:47200
> I1204 03:31:52.985347 31789 process.cpp:3067] Handling HTTP event for
> process 'master' with path: '/master/api/v1/scheduler'
> I1204 03:31:52.985502 31789 http.cpp:336] HTTP POST for
> /master/api/v1/scheduler from 172.17.0.2:33009
> I1204 03:31:52.985939 31789 master.cpp:1899] Received subscription request
> for HTTP framework 'default'
> I1204 03:31:52.986045 31789 master.cpp:1676] Authorizing framework
> principal 'test-principal' to receive offers for role '*'
> I1204 03:31:52.986364 31789 master.cpp:1991] Subscribing framework
> 'default' with checkpointing disabled and capabilities [  ]
> I1204 03:31:52.986779 31799 hierarchical.cpp:266] Added framework
> 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
> I1204 03:31:52.986913 31796 master.hpp:1583] Sending heartbeat to
> 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
> I1204 03:31:52.986996 31799 hierarchical.cpp:1308] No resources available
> to allocate!
> I1204 03:31:52.987063 31799 hierarchical.cpp:1401] No inverse offers to
> send out!
> I1204 03:31:52.987110 31799 hierarchical.cpp:1048] Performed allocation
> for 0 slaves in 189242ns
> I1204 03:31:52.987913 31798 scheduler.cpp:457] Enqueuing event SUBSCRIBED
> received from master@172.17.0.2:47200
> I1204 03:31:52.988831 31798 scheduler.cpp:457] Enqueuing event HEARTBEAT
> received from master@172.17.0.2:47200
> I1204 03:31:52.989537 31788 master_maintenance_tests.cpp:172] Ignoring
> HEARTBEAT event
> I1204 03:31:52.989886 31801 scheduler.cpp:298] Sending REQUEST call to
> master@172.17.0.2:47200
> I1204 03:31:52.991730 31792 process.cpp:3067] Handling HTTP event for
> process 'master' with path: '/master/api/v1/scheduler'
> I1204 03:31:52.991812 31792 http.cpp:336] HTTP POST for
> /master/api/v1/scheduler from 172.17.0.2:33010
> I1204 03:31:52.992156 31792 master.cpp:2646] Processing REQUEST call for
> framework 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000 (default)
> I1204 03:31:52.992516 31790 hierarchical.cpp:557] Received resource
> request from framework 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
> I1204 03:31:52.992923 31800 master.cpp:938] Master terminating
> I1204 03:31:52.993132 31796 hierarchical.cpp:306] Removed framework
> 82e2943a-0ffa-43db-ab30-d280bc15aad8-0000
> E1204 03:31:52.993708 31798 scheduler.cpp:431] End-Of-File received from
> master. The master closed the event stream
> [       OK ] ContentType/SchedulerTest.Request/1 (431 ms)
> [----------] 22 tests from ContentType/SchedulerTest (15741 ms total)
>
> [----------] Global test environment tear-down
> [==========] 878 tests from 116 test cases ran. (711169 ms total)
> [  PASSED  ] 877 tests.
> [  FAILED  ] 1 test, listed below:
> [  FAILED  ] ReservationTest.ACLMultipleOperations
>
>  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-1449197270-18036
> Untagged: mesos-1449197270-18036:latest
> Deleted: 71bc3adfccbfe4c515166abab14facf5895235fd4358c75eafe7552377b4ed12
> Deleted: c04522c46bffaa92efd2450d00842a14171f47c8ae50942666829e4dca2a7ada
> Deleted: d5849061eee06f14b51d9d7237588a0fe83fd953abfc1713692bd1247d04220f
> Deleted: 20d1e630457de2edba4f2fabe62ee3bcc7de4243ec737ce2a545a83de876613d
> Deleted: 64bba51bd0cdcb0d983deeb4cd1aa27ceb02bd4703c24f2692024c5a1537de44
> Deleted: 59e85ec64b5ee2735cde5403fe8def7375ffca98f9ea7953c802705673efb8cd
> Deleted: bee88887921d3d7d38f87744f4f49cb346037ce8a8b09af9d29686376200d66e
> Deleted: 709b8b667cf349fbcf14fbc48a0316319b341baaa1dd61f6a48c66d37b2dc628
> Deleted: e2c4f6d787499248e303270ff419e2545075e24a83101ed5316f4ecc907bba69
> Deleted: 0b8ee088204fbd6b9b1fa2f1a503763106b444f6a0b5d64ad6136269f821e487
> Deleted: 5657d8070e24ed2e2c43b0ac6ac0536208680be1f4e18031f5c76fd722aff863
> Deleted: 5e4dcfbaf3cc159742402a11e2c8b27efa71ec0ec202abd22acf5f553691f9c6
> Deleted: f589a283ec591fb354c074375571f136e15baa088534a380ac69255b6565ecdd
> Build step 'Execute shell' marked build as failure
>

Jenkins build is back to normal : Mesos » gcc,--verbose --enable-libevent --enable-ssl,ubuntu:14.04,docker||Hadoop #1320

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=ubuntu%3A14.04,label_exp=docker%7C%7CHadoop/1320/changes>