Return-Path: X-Original-To: apmail-mesos-builds-archive@minotaur.apache.org Delivered-To: apmail-mesos-builds-archive@minotaur.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 48770107B1 for ; Fri, 4 Dec 2015 09:08:32 +0000 (UTC) Received: (qmail 19116 invoked by uid 500); 4 Dec 2015 09:08:32 -0000 Delivered-To: apmail-mesos-builds-archive@mesos.apache.org Received: (qmail 19092 invoked by uid 500); 4 Dec 2015 09:08:32 -0000 Mailing-List: contact builds-help@mesos.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: builds@mesos.apache.org Delivered-To: mailing list builds@mesos.apache.org Received: (qmail 19080 invoked by uid 99); 4 Dec 2015 09:08:31 -0000 Received: from Unknown (HELO spamd3-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 04 Dec 2015 09:08:31 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd3-us-west.apache.org (ASF Mail Server at spamd3-us-west.apache.org) with ESMTP id 2AD62180A34 for ; Fri, 4 Dec 2015 09:08:31 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd3-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: 5.153 X-Spam-Level: ***** X-Spam-Status: No, score=5.153 tagged_above=-999 required=6.31 tests=[DKIM_SIGNED=0.1, DKIM_VALID=-0.1, DKIM_VALID_AU=-0.1, HTML_MESSAGE=3, KAM_BADIPHTTP=2, KAM_LOTSOFHASH=0.25, NORMAL_HTTP_TO_IP=0.001, URIBL_BLOCKED=0.001, WEIRD_PORT=0.001] autolearn=disabled Authentication-Results: spamd3-us-west.apache.org (amavisd-new); dkim=pass (1024-bit key) header.d=mesosphere.io Received: from mx1-us-east.apache.org ([10.40.0.8]) by localhost (spamd3-us-west.apache.org [10.40.0.10]) (amavisd-new, port 10024) with ESMTP id 2UgLiUnEYHLC for ; Fri, 4 Dec 2015 09:08:15 +0000 (UTC) Received: from mail-ig0-f198.google.com (mail-ig0-f198.google.com [209.85.213.198]) by mx1-us-east.apache.org (ASF Mail Server at mx1-us-east.apache.org) with ESMTPS id 11B0B42BBD for ; Fri, 4 Dec 2015 09:08:15 +0000 (UTC) Received: by igcwf13 with SMTP id wf13so84052474igc.2 for ; Fri, 04 Dec 2015 01:08:08 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=mesosphere.io; s=google; h=mime-version:references:in-reply-to:from:date:message-id:subject:to :cc:content-type; bh=dT8JVZEU1X+Un+vglnU31IdtZvhRvtjujHInIIgv6d4=; b=Bwg4nWr2afyASmNeGFhgh3CPqxVxr+sAWS228tG6G/regeBeC85VB4g8XWAIh1/Nyr aTL6IEPyKJWd3gRH1Cr1zcUna158koLoxoaF592I+wWdm4ELXZMWSjwyf9flAkTwxCkp o7Ou1JRXVq71JfMY+XHlpd5VWbu9X1rETpGoY= X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20130820; h=x-gm-message-state:mime-version:references:in-reply-to:from:date :message-id:subject:to:cc:content-type; bh=dT8JVZEU1X+Un+vglnU31IdtZvhRvtjujHInIIgv6d4=; b=chFq4nOHLUhEBYez9sl4GemNP+URXhENWd17iH3YlObUVOgIccgMklLVyOIdCf8rnd APuy0xuKqdMaBHqWBh3pZmgTAmCak+HW8mRT3P7UgWIDrO7ZtEUBsDj4WyBXf/+Ofn3V WIMQWbhOAZwPIzAZsVFgDhZ3TFiGeukz5W8rviAi9ifogG1XQ5zxWI9Z5wY+R1HPYgoP kM0St3twXV5vzGEq/pbu0w2oukDajNV5NniUUUrWWXMJJ9fHG2KCfPwJsVl6XzTK5A69 6wvO/XU3L+JMydWqbKv5czd5ygwNI2tOT7P5gT9VnvO/zyifRS326aqEkcxGCngnf3nZ i3tA== X-Gm-Message-State: ALoCoQnapxrfViLMBnL6qSXPoZPHxG9Yv2hAGZa5UJG0uOdMQlD5NAhsKRggjAE6geo/KeTIC0mWk07/CximUV34/MHMrnXuEAb585NLUHNu0gPRShoVOig= X-Received: by 10.50.73.228 with SMTP id o4mr3164103igv.37.1449220088355; Fri, 04 Dec 2015 01:08:08 -0800 (PST) MIME-Version: 1.0 References: <227375123.10475.1449199918799.JavaMail.jenkins@crius> In-Reply-To: From: Michael Park Date: Fri, 04 Dec 2015 09:07:58 +0000 Message-ID: Subject: =?UTF-8?B?UmU6IEJ1aWxkIGZhaWxlZCBpbiBKZW5raW5zOiBNZXNvcyDCuyBnY2MsLS12ZXJib3NlIA==?= =?UTF-8?B?LS1lbmFibGUtbGliZXZlbnQgLS1lbmFibGUtc3NsLHVidW50dToxNC4wNCxkb2NrZXJ8fEhhZG9vcCAj?= =?UTF-8?B?MTMxOQ==?= To: Benjamin Mahler , "yujie.jay@gmail.com" Cc: Apache Jenkins Server , Greg Mann , builds@mesos.apache.org Content-Type: multipart/alternative; boundary=089e013a25489184d205260ed8ff --089e013a25489184d205260ed8ff Content-Type: text/plain; charset=UTF-8 +Jie Yu 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 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 > wrote: > >> Got it. Who shepherded it? >> >> On Thu, Dec 3, 2015 at 7:38 PM, Michael Park wrote: >> >>> +Greg since he's the author, he might have a better idea >>> >>> On Thu, Dec 3, 2015, 10:36 PM Benjamin Mahler >>> 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 >>>>> >>>> >>>> >> --089e013a25489184d205260ed8ff--