You are viewing a plain text version of this content. The canonical link for it is here.
Posted to builds@mesos.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2016/01/26 22:12:53 UTC
Build failed in Jenkins: Mesos » gcc,--verbose,centos:7,docker||Hadoop #1553
See <https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,OS=centos%3A7,label_exp=docker%7C%7CHadoop/1553/changes>
Changes:
[joris.van.remoortere] Resource Math: Substituted DeleteSubrange with Swap + RemoveLast.
[joris.van.remoortere] Improved performance of 'roles::validate'.
[joris.van.remoortere] Fixed error message style in 'roles::validate'.
[joris.van.remoortere] Allocator Benchmark: Pull resource parsing out of for loop.
------------------------------------------
[...truncated 160502 lines...]
I0126 21:12:48.856724 831 status_update_manager.cpp:528] Cleaning up status update stream for task e8b2d31c-072d-44ee-8f4c-f47b1b2a8353 of framework eecb8a2c-bd91-4a1b-bd6a-03bbc1820fc7-0000
I0126 21:12:48.857102 830 gc.cpp:54] Scheduling '/tmp/ContentType_SchedulerTest_Message_1_dbHkG6/slaves/eecb8a2c-bd91-4a1b-bd6a-03bbc1820fc7-S0/frameworks/eecb8a2c-bd91-4a1b-bd6a-03bbc1820fc7-0000/executors/default' for gc 6.99999008773037days in the future
I0126 21:12:48.857195 830 gc.cpp:54] Scheduling '/tmp/ContentType_SchedulerTest_Message_1_dbHkG6/slaves/eecb8a2c-bd91-4a1b-bd6a-03bbc1820fc7-S0/frameworks/eecb8a2c-bd91-4a1b-bd6a-03bbc1820fc7-0000' for gc 6.99999008569482days in the future
[ OK ] ContentType/SchedulerTest.Message/1 (123 ms)
[ RUN ] ContentType/SchedulerTest.Request/0
I0126 21:12:48.864636 800 leveldb.cpp:174] Opened db in 2.739276ms
I0126 21:12:48.865427 800 leveldb.cpp:181] Compacted db in 759974ns
I0126 21:12:48.865473 800 leveldb.cpp:196] Created db iterator in 19200ns
I0126 21:12:48.865746 800 leveldb.cpp:202] Seeked to beginning of db in 2465ns
I0126 21:12:48.865766 800 leveldb.cpp:271] Iterated through 0 keys in the db in 432ns
I0126 21:12:48.865819 800 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0126 21:12:48.866345 819 recover.cpp:447] Starting replica recovery
I0126 21:12:48.866909 833 recover.cpp:473] Replica is in EMPTY status
I0126 21:12:48.867897 826 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (14131)@172.17.0.5:52680
I0126 21:12:48.868383 826 recover.cpp:193] Received a recover response from a replica in EMPTY status
I0126 21:12:48.869029 833 recover.cpp:564] Updating replica status to STARTING
I0126 21:12:48.869792 828 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 548751ns
I0126 21:12:48.869822 828 replica.cpp:320] Persisted replica status to STARTING
I0126 21:12:48.870527 828 recover.cpp:473] Replica is in STARTING status
I0126 21:12:48.870883 822 master.cpp:374] Master 2d7d35ee-f3b9-4d21-ba7a-3f0bed41d6b4 (c0bf249b6465) started on 172.17.0.5:52680
I0126 21:12:48.870985 822 master.cpp:376] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="false" --authenticate_http="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/x4f098/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --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/x4f098/master" --zk_session_timeout="10secs"
I0126 21:12:48.871316 822 master.cpp:423] Master allowing unauthenticated frameworks to register
I0126 21:12:48.871333 822 master.cpp:426] Master only allowing authenticated slaves to register
I0126 21:12:48.871343 822 credentials.hpp:35] Loading credentials for authentication from '/tmp/x4f098/credentials'
I0126 21:12:48.871693 822 master.cpp:466] Using default 'crammd5' authenticator
I0126 21:12:48.871881 822 master.cpp:535] Using default 'basic' HTTP authenticator
I0126 21:12:48.872040 822 master.cpp:569] Authorization enabled
I0126 21:12:48.873024 827 whitelist_watcher.cpp:77] No whitelist given
I0126 21:12:48.873107 830 hierarchical.cpp:144] Initialized hierarchical allocator process
I0126 21:12:48.873756 830 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (14133)@172.17.0.5:52680
I0126 21:12:48.874063 829 master.cpp:1710] The newly elected leader is master@172.17.0.5:52680 with id 2d7d35ee-f3b9-4d21-ba7a-3f0bed41d6b4
I0126 21:12:48.874101 829 master.cpp:1723] Elected as the leading master!
I0126 21:12:48.874125 829 master.cpp:1468] Recovering from registrar
I0126 21:12:48.874332 827 registrar.cpp:307] Recovering registrar
I0126 21:12:48.874424 821 recover.cpp:193] Received a recover response from a replica in STARTING status
I0126 21:12:48.875213 828 recover.cpp:564] Updating replica status to VOTING
I0126 21:12:48.875758 834 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 433985ns
I0126 21:12:48.875782 834 replica.cpp:320] Persisted replica status to VOTING
I0126 21:12:48.875900 819 recover.cpp:578] Successfully joined the Paxos group
I0126 21:12:48.876207 819 recover.cpp:462] Recover process terminated
I0126 21:12:48.876693 829 log.cpp:659] Attempting to start the writer
I0126 21:12:48.877979 821 replica.cpp:493] Replica received implicit promise request from (14134)@172.17.0.5:52680 with proposal 1
I0126 21:12:48.878325 821 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 316096ns
I0126 21:12:48.878351 821 replica.cpp:342] Persisted promised to 1
I0126 21:12:48.878971 819 coordinator.cpp:238] Coordinator attempting to fill missing positions
I0126 21:12:48.880206 828 replica.cpp:388] Replica received explicit promise request from (14135)@172.17.0.5:52680 for position 0 with proposal 2
I0126 21:12:48.880578 828 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 327878ns
I0126 21:12:48.880604 828 replica.cpp:712] Persisted action at 0
I0126 21:12:48.881901 820 replica.cpp:537] Replica received write request for position 0 from (14136)@172.17.0.5:52680
I0126 21:12:48.881983 820 leveldb.cpp:436] Reading position from leveldb took 49682ns
I0126 21:12:48.882346 820 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 309637ns
I0126 21:12:48.882380 820 replica.cpp:712] Persisted action at 0
I0126 21:12:48.882972 820 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
I0126 21:12:48.883333 820 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 326997ns
I0126 21:12:48.883437 820 replica.cpp:712] Persisted action at 0
I0126 21:12:48.883467 820 replica.cpp:697] Replica learned NOP action at position 0
I0126 21:12:48.884199 820 log.cpp:675] Writer started with ending position 0
I0126 21:12:48.885287 821 leveldb.cpp:436] Reading position from leveldb took 24741ns
I0126 21:12:48.886590 828 registrar.cpp:340] Successfully fetched the registry (0B) in 12.0832ms
I0126 21:12:48.886710 828 registrar.cpp:439] Applied 1 operations in 26665ns; attempting to update the 'registry'
I0126 21:12:48.887418 820 log.cpp:683] Attempting to append 170 bytes to the log
I0126 21:12:48.887596 830 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I0126 21:12:48.888419 819 replica.cpp:537] Replica received write request for position 1 from (14137)@172.17.0.5:52680
I0126 21:12:48.888854 819 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 396306ns
I0126 21:12:48.888887 819 replica.cpp:712] Persisted action at 1
I0126 21:12:48.889531 822 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
I0126 21:12:48.889991 822 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 422124ns
I0126 21:12:48.890097 822 replica.cpp:712] Persisted action at 1
I0126 21:12:48.890230 822 replica.cpp:697] Replica learned APPEND action at position 1
I0126 21:12:48.891278 823 registrar.cpp:484] Successfully updated the 'registry' in 4.472064ms
I0126 21:12:48.891492 823 registrar.cpp:370] Successfully recovered registrar
I0126 21:12:48.891551 822 log.cpp:702] Attempting to truncate the log to 1
I0126 21:12:48.891799 822 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I0126 21:12:48.891978 823 master.cpp:1520] Recovered 0 slaves from the Registry (131B) ; allowing 10mins for slaves to re-register
I0126 21:12:48.892261 822 hierarchical.cpp:171] Skipping recovery of hierarchical allocator: nothing to recover
I0126 21:12:48.892774 827 replica.cpp:537] Replica received write request for position 2 from (14138)@172.17.0.5:52680
I0126 21:12:48.893280 827 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 465845ns
I0126 21:12:48.893308 827 replica.cpp:712] Persisted action at 2
I0126 21:12:48.894024 821 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
I0126 21:12:48.894449 821 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 330835ns
I0126 21:12:48.894567 821 leveldb.cpp:399] Deleting ~1 keys from leveldb took 32275ns
I0126 21:12:48.894670 821 replica.cpp:712] Persisted action at 2
I0126 21:12:48.894772 821 replica.cpp:697] Replica learned TRUNCATE action at position 2
I0126 21:12:48.903159 800 scheduler.cpp:154] Version: 0.27.0
I0126 21:12:48.903868 828 scheduler.cpp:236] New master detected at master@172.17.0.5:52680
I0126 21:12:48.905156 819 scheduler.cpp:298] Sending SUBSCRIBE call to master@172.17.0.5:52680
I0126 21:12:48.907083 832 process.cpp:3141] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0126 21:12:48.907589 832 http.cpp:503] HTTP POST for /master/api/v1/scheduler from 172.17.0.5:46763
I0126 21:12:48.907858 832 master.cpp:1972] Received subscription request for HTTP framework 'default'
I0126 21:12:48.908005 832 master.cpp:1749] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0126 21:12:48.908371 832 master.cpp:2063] Subscribing framework 'default' with checkpointing disabled and capabilities [ ]
I0126 21:12:48.908829 834 hierarchical.cpp:265] Added framework 2d7d35ee-f3b9-4d21-ba7a-3f0bed41d6b4-0000
I0126 21:12:48.908902 834 hierarchical.cpp:1355] No resources available to allocate!
I0126 21:12:48.908938 834 hierarchical.cpp:1450] No inverse offers to send out!
I0126 21:12:48.908989 834 hierarchical.cpp:1090] Performed allocation for 0 slaves in 131469ns
I0126 21:12:48.909019 834 master.hpp:1658] Sending heartbeat to 2d7d35ee-f3b9-4d21-ba7a-3f0bed41d6b4-0000
I0126 21:12:48.910071 820 scheduler.cpp:457] Enqueuing event SUBSCRIBED received from master@172.17.0.5:52680
I0126 21:12:48.910754 820 scheduler.cpp:457] Enqueuing event HEARTBEAT received from master@172.17.0.5:52680
I0126 21:12:48.911468 831 master_maintenance_tests.cpp:177] Ignoring HEARTBEAT event
I0126 21:12:48.911552 833 scheduler.cpp:298] Sending REQUEST call to master@172.17.0.5:52680
I0126 21:12:48.913182 828 process.cpp:3141] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0126 21:12:48.913661 831 http.cpp:503] HTTP POST for /master/api/v1/scheduler from 172.17.0.5:46764
I0126 21:12:48.913765 831 master.cpp:2717] Processing REQUEST call for framework 2d7d35ee-f3b9-4d21-ba7a-3f0bed41d6b4-0000 (default)
I0126 21:12:48.914017 824 hierarchical.cpp:585] Received resource request from framework 2d7d35ee-f3b9-4d21-ba7a-3f0bed41d6b4-0000
I0126 21:12:48.915192 800 master.cpp:1025] Master terminating
I0126 21:12:48.915560 824 hierarchical.cpp:326] Removed framework 2d7d35ee-f3b9-4d21-ba7a-3f0bed41d6b4-0000
E0126 21:12:48.916788 825 scheduler.cpp:431] End-Of-File received from master. The master closed the event stream
[ OK ] ContentType/SchedulerTest.Request/0 (62 ms)
[ RUN ] ContentType/SchedulerTest.Request/1
I0126 21:12:48.927021 800 leveldb.cpp:174] Opened db in 2.613044ms
I0126 21:12:48.927630 800 leveldb.cpp:181] Compacted db in 580240ns
I0126 21:12:48.927677 800 leveldb.cpp:196] Created db iterator in 20388ns
I0126 21:12:48.927701 800 leveldb.cpp:202] Seeked to beginning of db in 2137ns
I0126 21:12:48.927718 800 leveldb.cpp:271] Iterated through 0 keys in the db in 475ns
I0126 21:12:48.927772 800 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0126 21:12:48.928249 832 recover.cpp:447] Starting replica recovery
I0126 21:12:48.929188 832 recover.cpp:473] Replica is in EMPTY status
I0126 21:12:48.930225 834 master.cpp:374] Master 609f3254-9020-4f15-a970-91534c11d60c (c0bf249b6465) started on 172.17.0.5:52680
I0126 21:12:48.930250 834 master.cpp:376] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="false" --authenticate_http="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/IFWVfa/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --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/IFWVfa/master" --zk_session_timeout="10secs"
I0126 21:12:48.930615 834 master.cpp:423] Master allowing unauthenticated frameworks to register
I0126 21:12:48.930629 834 master.cpp:426] Master only allowing authenticated slaves to register
I0126 21:12:48.930639 834 credentials.hpp:35] Loading credentials for authentication from '/tmp/IFWVfa/credentials'
I0126 21:12:48.930990 834 master.cpp:466] Using default 'crammd5' authenticator
I0126 21:12:48.931146 834 master.cpp:535] Using default 'basic' HTTP authenticator
I0126 21:12:48.931265 834 master.cpp:569] Authorization enabled
I0126 21:12:48.931499 821 whitelist_watcher.cpp:77] No whitelist given
I0126 21:12:48.931655 821 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (14146)@172.17.0.5:52680
I0126 21:12:48.932071 822 hierarchical.cpp:144] Initialized hierarchical allocator process
I0126 21:12:48.932855 826 recover.cpp:193] Received a recover response from a replica in EMPTY status
I0126 21:12:48.933588 825 recover.cpp:564] Updating replica status to STARTING
I0126 21:12:48.934062 826 master.cpp:1710] The newly elected leader is master@172.17.0.5:52680 with id 609f3254-9020-4f15-a970-91534c11d60c
I0126 21:12:48.934088 826 master.cpp:1723] Elected as the leading master!
I0126 21:12:48.934108 826 master.cpp:1468] Recovering from registrar
I0126 21:12:48.934284 829 registrar.cpp:307] Recovering registrar
I0126 21:12:48.935475 825 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.468364ms
I0126 21:12:48.935583 825 replica.cpp:320] Persisted replica status to STARTING
I0126 21:12:48.935891 820 recover.cpp:473] Replica is in STARTING status
I0126 21:12:48.936811 827 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (14148)@172.17.0.5:52680
I0126 21:12:48.937140 820 recover.cpp:193] Received a recover response from a replica in STARTING status
I0126 21:12:48.937587 826 recover.cpp:564] Updating replica status to VOTING
I0126 21:12:48.938043 824 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 302791ns
I0126 21:12:48.938072 824 replica.cpp:320] Persisted replica status to VOTING
I0126 21:12:48.938215 833 recover.cpp:578] Successfully joined the Paxos group
I0126 21:12:48.938442 833 recover.cpp:462] Recover process terminated
I0126 21:12:48.939018 826 log.cpp:659] Attempting to start the writer
I0126 21:12:48.940201 832 replica.cpp:493] Replica received implicit promise request from (14149)@172.17.0.5:52680 with proposal 1
I0126 21:12:48.940552 832 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 319917ns
I0126 21:12:48.940578 832 replica.cpp:342] Persisted promised to 1
I0126 21:12:48.941167 819 coordinator.cpp:238] Coordinator attempting to fill missing positions
I0126 21:12:48.942297 828 replica.cpp:388] Replica received explicit promise request from (14150)@172.17.0.5:52680 for position 0 with proposal 2
I0126 21:12:48.942692 828 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 346504ns
I0126 21:12:48.942718 828 replica.cpp:712] Persisted action at 0
I0126 21:12:48.943825 828 replica.cpp:537] Replica received write request for position 0 from (14151)@172.17.0.5:52680
I0126 21:12:48.943888 828 leveldb.cpp:436] Reading position from leveldb took 31321ns
I0126 21:12:48.944456 828 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 400796ns
I0126 21:12:48.944545 828 replica.cpp:712] Persisted action at 0
I0126 21:12:48.945248 825 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
I0126 21:12:48.945709 825 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 426968ns
I0126 21:12:48.945737 825 replica.cpp:712] Persisted action at 0
I0126 21:12:48.945760 825 replica.cpp:697] Replica learned NOP action at position 0
I0126 21:12:48.946410 831 log.cpp:675] Writer started with ending position 0
I0126 21:12:48.947729 823 leveldb.cpp:436] Reading position from leveldb took 30984ns
I0126 21:12:48.948747 822 registrar.cpp:340] Successfully fetched the registry (0B) in 14.329088ms
I0126 21:12:48.948866 822 registrar.cpp:439] Applied 1 operations in 31121ns; attempting to update the 'registry'
I0126 21:12:48.950023 821 log.cpp:683] Attempting to append 170 bytes to the log
I0126 21:12:48.950237 833 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I0126 21:12:48.951225 823 replica.cpp:537] Replica received write request for position 1 from (14152)@172.17.0.5:52680
I0126 21:12:48.957044 823 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 5.780168ms
I0126 21:12:48.957172 823 replica.cpp:712] Persisted action at 1
I0126 21:12:48.958106 832 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
I0126 21:12:48.958582 832 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 442252ns
I0126 21:12:48.958614 832 replica.cpp:712] Persisted action at 1
I0126 21:12:48.958636 832 replica.cpp:697] Replica learned APPEND action at position 1
I0126 21:12:48.959554 823 registrar.cpp:484] Successfully updated the 'registry' in 10.49472ms
I0126 21:12:48.959756 823 registrar.cpp:370] Successfully recovered registrar
I0126 21:12:48.959872 821 log.cpp:702] Attempting to truncate the log to 1
I0126 21:12:48.960068 828 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I0126 21:12:48.960176 827 master.cpp:1520] Recovered 0 slaves from the Registry (131B) ; allowing 10mins for slaves to re-register
I0126 21:12:48.960196 821 hierarchical.cpp:171] Skipping recovery of hierarchical allocator: nothing to recover
I0126 21:12:48.961004 824 replica.cpp:537] Replica received write request for position 2 from (14153)@172.17.0.5:52680
I0126 21:12:48.961397 824 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 355936ns
I0126 21:12:48.961423 824 replica.cpp:712] Persisted action at 2
I0126 21:12:48.962100 829 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
I0126 21:12:48.962527 829 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 335898ns
I0126 21:12:48.962584 829 leveldb.cpp:399] Deleting ~1 keys from leveldb took 31618ns
I0126 21:12:48.962610 829 replica.cpp:712] Persisted action at 2
I0126 21:12:48.962636 829 replica.cpp:697] Replica learned TRUNCATE action at position 2
I0126 21:12:48.970995 800 scheduler.cpp:154] Version: 0.27.0
I0126 21:12:48.971504 830 scheduler.cpp:236] New master detected at master@172.17.0.5:52680
I0126 21:12:48.972497 821 scheduler.cpp:298] Sending SUBSCRIBE call to master@172.17.0.5:52680
I0126 21:12:48.974743 831 process.cpp:3141] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0126 21:12:48.975226 833 http.cpp:503] HTTP POST for /master/api/v1/scheduler from 172.17.0.5:46765
I0126 21:12:48.975628 833 master.cpp:1972] Received subscription request for HTTP framework 'default'
I0126 21:12:48.975697 833 master.cpp:1749] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0126 21:12:48.976029 833 master.cpp:2063] Subscribing framework 'default' with checkpointing disabled and capabilities [ ]
I0126 21:12:48.976435 827 hierarchical.cpp:265] Added framework 609f3254-9020-4f15-a970-91534c11d60c-0000
I0126 21:12:48.976480 833 master.hpp:1658] Sending heartbeat to 609f3254-9020-4f15-a970-91534c11d60c-0000
I0126 21:12:48.976635 827 hierarchical.cpp:1355] No resources available to allocate!
I0126 21:12:48.976774 827 hierarchical.cpp:1450] No inverse offers to send out!
I0126 21:12:48.976900 827 hierarchical.cpp:1090] Performed allocation for 0 slaves in 361800ns
I0126 21:12:48.978000 822 scheduler.cpp:457] Enqueuing event SUBSCRIBED received from master@172.17.0.5:52680
I0126 21:12:48.978399 822 scheduler.cpp:457] Enqueuing event HEARTBEAT received from master@172.17.0.5:52680
I0126 21:12:48.979051 832 master_maintenance_tests.cpp:177] Ignoring HEARTBEAT event
I0126 21:12:48.979266 833 scheduler.cpp:298] Sending REQUEST call to master@172.17.0.5:52680
I0126 21:12:48.980732 832 process.cpp:3141] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0126 21:12:48.981122 820 http.cpp:503] HTTP POST for /master/api/v1/scheduler from 172.17.0.5:46766
I0126 21:12:48.981443 820 master.cpp:2717] Processing REQUEST call for framework 609f3254-9020-4f15-a970-91534c11d60c-0000 (default)
I0126 21:12:48.981714 820 hierarchical.cpp:585] Received resource request from framework 609f3254-9020-4f15-a970-91534c11d60c-0000
I0126 21:12:48.982326 800 master.cpp:1025] Master terminating
I0126 21:12:48.983392 828 hierarchical.cpp:326] Removed framework 609f3254-9020-4f15-a970-91534c11d60c-0000
E0126 21:12:48.985258 830 scheduler.cpp:431] End-Of-File received from master. The master closed the event stream
[ OK ] ContentType/SchedulerTest.Request/1 (67 ms)
[----------] 22 tests from ContentType/SchedulerTest (4428 ms total)
[----------] Global test environment tear-down
2016-01-26 21:12:49,294:800(0x7f7b957b6700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:36129] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
[==========] 954 tests from 124 test cases ran. (392712 ms total)
[ PASSED ] 953 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] MasterTest.MaxCompletedTasksPerFrameworkFlag
1 FAILED TEST
YOU HAVE 8 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-1453840719-22760
Untagged: mesos-1453840719-22760:latest
Deleted: 06cbd68cc90fc1b3600ba430794df94c6575e9fe5b6049a41549a2938b878ba4
Deleted: 8ec112a64c70ff3686e3db1d1583a2461e979c8144547047eca05a1b75c99d8b
Deleted: 34f9d28e655f12f64065599e22cd85e26fec3aabbfd334211dda2cdd946b69cf
Deleted: 0cdbd7862620058d04eeb010cf083b82ab841769ebc81eee588d27f2e442f299
Deleted: 68df0e8b2592e570a3183a600051bcf264676fe474487ada495931ccecc349f9
Deleted: f2422e7be3d9781fa7533f4014ee09b9e062f0340ba62e7739012098e918a708
Deleted: 581e2052cff0aacfd491800308066b5e5e23aa706c7c1f9694a5b7d5e234dc25
Deleted: 1fae74e409d2d2c38569a0208b945781c035384896f84b511b83f703681b14fd
Deleted: 29e6bd353b0937624d3f8e3265ed5a2cef2928a4ba5996ec20dd3ab685c802a1
Deleted: d1286506871dea101369c732938d1dec03017d0c1e4078fc7f0cb0a3cbef7d39
Deleted: 712df17d45c12b561c1cb90666e813be96a8734d2e0f2aba0eefe28f9fd28daa
Deleted: 34372e0c6dc544839f872ffaa75dd31c72167c213dd6e7cc2c5b4f111cdce4eb
Deleted: 356f5f3794b297e2b1eccee8efdb6a2ad2219c136b3cf6eeb7f21f7d07924f1e
Build step 'Execute shell' marked build as failure
Jenkins build is back to normal : Mesos » gcc,--verbose,centos:7,docker||Hadoop #1554
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,OS=centos%3A7,label_exp=docker%7C%7CHadoop/1554/changes>
Re: Build failed in Jenkins: Mesos » gcc,--verbose,centos:7,docker||Hadoop #1553
Posted by Greg Mann <gr...@mesosphere.io>.
I didn't see a ticket for this failure, so I created one here:
https://issues.apache.org/jira/browse/MESOS-4518
On Tue, Jan 26, 2016 at 1:12 PM, Apache Jenkins Server <
jenkins@builds.apache.org> wrote:
> See <
> https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,OS=centos%3A7,label_exp=docker%7C%7CHadoop/1553/changes
> >
>
> Changes:
>
> [joris.van.remoortere] Resource Math: Substituted DeleteSubrange with Swap
> + RemoveLast.
>
> [joris.van.remoortere] Improved performance of 'roles::validate'.
>
> [joris.van.remoortere] Fixed error message style in 'roles::validate'.
>
> [joris.van.remoortere] Allocator Benchmark: Pull resource parsing out of
> for loop.
>
> ------------------------------------------
> [...truncated 160502 lines...]
> I0126 21:12:48.856724 831 status_update_manager.cpp:528] Cleaning up
> status update stream for task e8b2d31c-072d-44ee-8f4c-f47b1b2a8353 of
> framework eecb8a2c-bd91-4a1b-bd6a-03bbc1820fc7-0000
> I0126 21:12:48.857102 830 gc.cpp:54] Scheduling
> '/tmp/ContentType_SchedulerTest_Message_1_dbHkG6/slaves/eecb8a2c-bd91-4a1b-bd6a-03bbc1820fc7-S0/frameworks/eecb8a2c-bd91-4a1b-bd6a-03bbc1820fc7-0000/executors/default'
> for gc 6.99999008773037days in the future
> I0126 21:12:48.857195 830 gc.cpp:54] Scheduling
> '/tmp/ContentType_SchedulerTest_Message_1_dbHkG6/slaves/eecb8a2c-bd91-4a1b-bd6a-03bbc1820fc7-S0/frameworks/eecb8a2c-bd91-4a1b-bd6a-03bbc1820fc7-0000'
> for gc 6.99999008569482days in the future
> [ OK ] ContentType/SchedulerTest.Message/1 (123 ms)
> [ RUN ] ContentType/SchedulerTest.Request/0
> I0126 21:12:48.864636 800 leveldb.cpp:174] Opened db in 2.739276ms
> I0126 21:12:48.865427 800 leveldb.cpp:181] Compacted db in 759974ns
> I0126 21:12:48.865473 800 leveldb.cpp:196] Created db iterator in 19200ns
> I0126 21:12:48.865746 800 leveldb.cpp:202] Seeked to beginning of db in
> 2465ns
> I0126 21:12:48.865766 800 leveldb.cpp:271] Iterated through 0 keys in
> the db in 432ns
> I0126 21:12:48.865819 800 replica.cpp:779] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0126 21:12:48.866345 819 recover.cpp:447] Starting replica recovery
> I0126 21:12:48.866909 833 recover.cpp:473] Replica is in EMPTY status
> I0126 21:12:48.867897 826 replica.cpp:673] Replica in EMPTY status
> received a broadcasted recover request from (14131)@172.17.0.5:52680
> I0126 21:12:48.868383 826 recover.cpp:193] Received a recover response
> from a replica in EMPTY status
> I0126 21:12:48.869029 833 recover.cpp:564] Updating replica status to
> STARTING
> I0126 21:12:48.869792 828 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 548751ns
> I0126 21:12:48.869822 828 replica.cpp:320] Persisted replica status to
> STARTING
> I0126 21:12:48.870527 828 recover.cpp:473] Replica is in STARTING status
> I0126 21:12:48.870883 822 master.cpp:374] Master
> 2d7d35ee-f3b9-4d21-ba7a-3f0bed41d6b4 (c0bf249b6465) started on
> 172.17.0.5:52680
> I0126 21:12:48.870985 822 master.cpp:376] Flags at startup: --acls=""
> --allocation_interval="1secs" --allocator="HierarchicalDRF"
> --authenticate="false" --authenticate_http="true"
> --authenticate_slaves="true" --authenticators="crammd5"
> --authorizers="local" --credentials="/tmp/x4f098/credentials"
> --framework_sorter="drf" --help="false" --hostname_lookup="true"
> --http_authenticators="basic" --initialize_driver_logging="true"
> --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO"
> --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000"
> --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/x4f098/master" --zk_session_timeout="10secs"
> I0126 21:12:48.871316 822 master.cpp:423] Master allowing
> unauthenticated frameworks to register
> I0126 21:12:48.871333 822 master.cpp:426] Master only allowing
> authenticated slaves to register
> I0126 21:12:48.871343 822 credentials.hpp:35] Loading credentials for
> authentication from '/tmp/x4f098/credentials'
> I0126 21:12:48.871693 822 master.cpp:466] Using default 'crammd5'
> authenticator
> I0126 21:12:48.871881 822 master.cpp:535] Using default 'basic' HTTP
> authenticator
> I0126 21:12:48.872040 822 master.cpp:569] Authorization enabled
> I0126 21:12:48.873024 827 whitelist_watcher.cpp:77] No whitelist given
> I0126 21:12:48.873107 830 hierarchical.cpp:144] Initialized hierarchical
> allocator process
> I0126 21:12:48.873756 830 replica.cpp:673] Replica in STARTING status
> received a broadcasted recover request from (14133)@172.17.0.5:52680
> I0126 21:12:48.874063 829 master.cpp:1710] The newly elected leader is
> master@172.17.0.5:52680 with id 2d7d35ee-f3b9-4d21-ba7a-3f0bed41d6b4
> I0126 21:12:48.874101 829 master.cpp:1723] Elected as the leading master!
> I0126 21:12:48.874125 829 master.cpp:1468] Recovering from registrar
> I0126 21:12:48.874332 827 registrar.cpp:307] Recovering registrar
> I0126 21:12:48.874424 821 recover.cpp:193] Received a recover response
> from a replica in STARTING status
> I0126 21:12:48.875213 828 recover.cpp:564] Updating replica status to
> VOTING
> I0126 21:12:48.875758 834 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 433985ns
> I0126 21:12:48.875782 834 replica.cpp:320] Persisted replica status to
> VOTING
> I0126 21:12:48.875900 819 recover.cpp:578] Successfully joined the Paxos
> group
> I0126 21:12:48.876207 819 recover.cpp:462] Recover process terminated
> I0126 21:12:48.876693 829 log.cpp:659] Attempting to start the writer
> I0126 21:12:48.877979 821 replica.cpp:493] Replica received implicit
> promise request from (14134)@172.17.0.5:52680 with proposal 1
> I0126 21:12:48.878325 821 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 316096ns
> I0126 21:12:48.878351 821 replica.cpp:342] Persisted promised to 1
> I0126 21:12:48.878971 819 coordinator.cpp:238] Coordinator attempting to
> fill missing positions
> I0126 21:12:48.880206 828 replica.cpp:388] Replica received explicit
> promise request from (14135)@172.17.0.5:52680 for position 0 with
> proposal 2
> I0126 21:12:48.880578 828 leveldb.cpp:341] Persisting action (8 bytes)
> to leveldb took 327878ns
> I0126 21:12:48.880604 828 replica.cpp:712] Persisted action at 0
> I0126 21:12:48.881901 820 replica.cpp:537] Replica received write
> request for position 0 from (14136)@172.17.0.5:52680
> I0126 21:12:48.881983 820 leveldb.cpp:436] Reading position from leveldb
> took 49682ns
> I0126 21:12:48.882346 820 leveldb.cpp:341] Persisting action (14 bytes)
> to leveldb took 309637ns
> I0126 21:12:48.882380 820 replica.cpp:712] Persisted action at 0
> I0126 21:12:48.882972 820 replica.cpp:691] Replica received learned
> notice for position 0 from @0.0.0.0:0
> I0126 21:12:48.883333 820 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 326997ns
> I0126 21:12:48.883437 820 replica.cpp:712] Persisted action at 0
> I0126 21:12:48.883467 820 replica.cpp:697] Replica learned NOP action at
> position 0
> I0126 21:12:48.884199 820 log.cpp:675] Writer started with ending
> position 0
> I0126 21:12:48.885287 821 leveldb.cpp:436] Reading position from leveldb
> took 24741ns
> I0126 21:12:48.886590 828 registrar.cpp:340] Successfully fetched the
> registry (0B) in 12.0832ms
> I0126 21:12:48.886710 828 registrar.cpp:439] Applied 1 operations in
> 26665ns; attempting to update the 'registry'
> I0126 21:12:48.887418 820 log.cpp:683] Attempting to append 170 bytes to
> the log
> I0126 21:12:48.887596 830 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 1
> I0126 21:12:48.888419 819 replica.cpp:537] Replica received write
> request for position 1 from (14137)@172.17.0.5:52680
> I0126 21:12:48.888854 819 leveldb.cpp:341] Persisting action (189 bytes)
> to leveldb took 396306ns
> I0126 21:12:48.888887 819 replica.cpp:712] Persisted action at 1
> I0126 21:12:48.889531 822 replica.cpp:691] Replica received learned
> notice for position 1 from @0.0.0.0:0
> I0126 21:12:48.889991 822 leveldb.cpp:341] Persisting action (191 bytes)
> to leveldb took 422124ns
> I0126 21:12:48.890097 822 replica.cpp:712] Persisted action at 1
> I0126 21:12:48.890230 822 replica.cpp:697] Replica learned APPEND action
> at position 1
> I0126 21:12:48.891278 823 registrar.cpp:484] Successfully updated the
> 'registry' in 4.472064ms
> I0126 21:12:48.891492 823 registrar.cpp:370] Successfully recovered
> registrar
> I0126 21:12:48.891551 822 log.cpp:702] Attempting to truncate the log to
> 1
> I0126 21:12:48.891799 822 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 2
> I0126 21:12:48.891978 823 master.cpp:1520] Recovered 0 slaves from the
> Registry (131B) ; allowing 10mins for slaves to re-register
> I0126 21:12:48.892261 822 hierarchical.cpp:171] Skipping recovery of
> hierarchical allocator: nothing to recover
> I0126 21:12:48.892774 827 replica.cpp:537] Replica received write
> request for position 2 from (14138)@172.17.0.5:52680
> I0126 21:12:48.893280 827 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 465845ns
> I0126 21:12:48.893308 827 replica.cpp:712] Persisted action at 2
> I0126 21:12:48.894024 821 replica.cpp:691] Replica received learned
> notice for position 2 from @0.0.0.0:0
> I0126 21:12:48.894449 821 leveldb.cpp:341] Persisting action (18 bytes)
> to leveldb took 330835ns
> I0126 21:12:48.894567 821 leveldb.cpp:399] Deleting ~1 keys from leveldb
> took 32275ns
> I0126 21:12:48.894670 821 replica.cpp:712] Persisted action at 2
> I0126 21:12:48.894772 821 replica.cpp:697] Replica learned TRUNCATE
> action at position 2
> I0126 21:12:48.903159 800 scheduler.cpp:154] Version: 0.27.0
> I0126 21:12:48.903868 828 scheduler.cpp:236] New master detected at
> master@172.17.0.5:52680
> I0126 21:12:48.905156 819 scheduler.cpp:298] Sending SUBSCRIBE call to
> master@172.17.0.5:52680
> I0126 21:12:48.907083 832 process.cpp:3141] Handling HTTP event for
> process 'master' with path: '/master/api/v1/scheduler'
> I0126 21:12:48.907589 832 http.cpp:503] HTTP POST for
> /master/api/v1/scheduler from 172.17.0.5:46763
> I0126 21:12:48.907858 832 master.cpp:1972] Received subscription request
> for HTTP framework 'default'
> I0126 21:12:48.908005 832 master.cpp:1749] Authorizing framework
> principal 'test-principal' to receive offers for role '*'
> I0126 21:12:48.908371 832 master.cpp:2063] Subscribing framework
> 'default' with checkpointing disabled and capabilities [ ]
> I0126 21:12:48.908829 834 hierarchical.cpp:265] Added framework
> 2d7d35ee-f3b9-4d21-ba7a-3f0bed41d6b4-0000
> I0126 21:12:48.908902 834 hierarchical.cpp:1355] No resources available
> to allocate!
> I0126 21:12:48.908938 834 hierarchical.cpp:1450] No inverse offers to
> send out!
> I0126 21:12:48.908989 834 hierarchical.cpp:1090] Performed allocation
> for 0 slaves in 131469ns
> I0126 21:12:48.909019 834 master.hpp:1658] Sending heartbeat to
> 2d7d35ee-f3b9-4d21-ba7a-3f0bed41d6b4-0000
> I0126 21:12:48.910071 820 scheduler.cpp:457] Enqueuing event SUBSCRIBED
> received from master@172.17.0.5:52680
> I0126 21:12:48.910754 820 scheduler.cpp:457] Enqueuing event HEARTBEAT
> received from master@172.17.0.5:52680
> I0126 21:12:48.911468 831 master_maintenance_tests.cpp:177] Ignoring
> HEARTBEAT event
> I0126 21:12:48.911552 833 scheduler.cpp:298] Sending REQUEST call to
> master@172.17.0.5:52680
> I0126 21:12:48.913182 828 process.cpp:3141] Handling HTTP event for
> process 'master' with path: '/master/api/v1/scheduler'
> I0126 21:12:48.913661 831 http.cpp:503] HTTP POST for
> /master/api/v1/scheduler from 172.17.0.5:46764
> I0126 21:12:48.913765 831 master.cpp:2717] Processing REQUEST call for
> framework 2d7d35ee-f3b9-4d21-ba7a-3f0bed41d6b4-0000 (default)
> I0126 21:12:48.914017 824 hierarchical.cpp:585] Received resource
> request from framework 2d7d35ee-f3b9-4d21-ba7a-3f0bed41d6b4-0000
> I0126 21:12:48.915192 800 master.cpp:1025] Master terminating
> I0126 21:12:48.915560 824 hierarchical.cpp:326] Removed framework
> 2d7d35ee-f3b9-4d21-ba7a-3f0bed41d6b4-0000
> E0126 21:12:48.916788 825 scheduler.cpp:431] End-Of-File received from
> master. The master closed the event stream
> [ OK ] ContentType/SchedulerTest.Request/0 (62 ms)
> [ RUN ] ContentType/SchedulerTest.Request/1
> I0126 21:12:48.927021 800 leveldb.cpp:174] Opened db in 2.613044ms
> I0126 21:12:48.927630 800 leveldb.cpp:181] Compacted db in 580240ns
> I0126 21:12:48.927677 800 leveldb.cpp:196] Created db iterator in 20388ns
> I0126 21:12:48.927701 800 leveldb.cpp:202] Seeked to beginning of db in
> 2137ns
> I0126 21:12:48.927718 800 leveldb.cpp:271] Iterated through 0 keys in
> the db in 475ns
> I0126 21:12:48.927772 800 replica.cpp:779] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0126 21:12:48.928249 832 recover.cpp:447] Starting replica recovery
> I0126 21:12:48.929188 832 recover.cpp:473] Replica is in EMPTY status
> I0126 21:12:48.930225 834 master.cpp:374] Master
> 609f3254-9020-4f15-a970-91534c11d60c (c0bf249b6465) started on
> 172.17.0.5:52680
> I0126 21:12:48.930250 834 master.cpp:376] Flags at startup: --acls=""
> --allocation_interval="1secs" --allocator="HierarchicalDRF"
> --authenticate="false" --authenticate_http="true"
> --authenticate_slaves="true" --authenticators="crammd5"
> --authorizers="local" --credentials="/tmp/IFWVfa/credentials"
> --framework_sorter="drf" --help="false" --hostname_lookup="true"
> --http_authenticators="basic" --initialize_driver_logging="true"
> --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO"
> --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000"
> --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/IFWVfa/master" --zk_session_timeout="10secs"
> I0126 21:12:48.930615 834 master.cpp:423] Master allowing
> unauthenticated frameworks to register
> I0126 21:12:48.930629 834 master.cpp:426] Master only allowing
> authenticated slaves to register
> I0126 21:12:48.930639 834 credentials.hpp:35] Loading credentials for
> authentication from '/tmp/IFWVfa/credentials'
> I0126 21:12:48.930990 834 master.cpp:466] Using default 'crammd5'
> authenticator
> I0126 21:12:48.931146 834 master.cpp:535] Using default 'basic' HTTP
> authenticator
> I0126 21:12:48.931265 834 master.cpp:569] Authorization enabled
> I0126 21:12:48.931499 821 whitelist_watcher.cpp:77] No whitelist given
> I0126 21:12:48.931655 821 replica.cpp:673] Replica in EMPTY status
> received a broadcasted recover request from (14146)@172.17.0.5:52680
> I0126 21:12:48.932071 822 hierarchical.cpp:144] Initialized hierarchical
> allocator process
> I0126 21:12:48.932855 826 recover.cpp:193] Received a recover response
> from a replica in EMPTY status
> I0126 21:12:48.933588 825 recover.cpp:564] Updating replica status to
> STARTING
> I0126 21:12:48.934062 826 master.cpp:1710] The newly elected leader is
> master@172.17.0.5:52680 with id 609f3254-9020-4f15-a970-91534c11d60c
> I0126 21:12:48.934088 826 master.cpp:1723] Elected as the leading master!
> I0126 21:12:48.934108 826 master.cpp:1468] Recovering from registrar
> I0126 21:12:48.934284 829 registrar.cpp:307] Recovering registrar
> I0126 21:12:48.935475 825 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 1.468364ms
> I0126 21:12:48.935583 825 replica.cpp:320] Persisted replica status to
> STARTING
> I0126 21:12:48.935891 820 recover.cpp:473] Replica is in STARTING status
> I0126 21:12:48.936811 827 replica.cpp:673] Replica in STARTING status
> received a broadcasted recover request from (14148)@172.17.0.5:52680
> I0126 21:12:48.937140 820 recover.cpp:193] Received a recover response
> from a replica in STARTING status
> I0126 21:12:48.937587 826 recover.cpp:564] Updating replica status to
> VOTING
> I0126 21:12:48.938043 824 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 302791ns
> I0126 21:12:48.938072 824 replica.cpp:320] Persisted replica status to
> VOTING
> I0126 21:12:48.938215 833 recover.cpp:578] Successfully joined the Paxos
> group
> I0126 21:12:48.938442 833 recover.cpp:462] Recover process terminated
> I0126 21:12:48.939018 826 log.cpp:659] Attempting to start the writer
> I0126 21:12:48.940201 832 replica.cpp:493] Replica received implicit
> promise request from (14149)@172.17.0.5:52680 with proposal 1
> I0126 21:12:48.940552 832 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 319917ns
> I0126 21:12:48.940578 832 replica.cpp:342] Persisted promised to 1
> I0126 21:12:48.941167 819 coordinator.cpp:238] Coordinator attempting to
> fill missing positions
> I0126 21:12:48.942297 828 replica.cpp:388] Replica received explicit
> promise request from (14150)@172.17.0.5:52680 for position 0 with
> proposal 2
> I0126 21:12:48.942692 828 leveldb.cpp:341] Persisting action (8 bytes)
> to leveldb took 346504ns
> I0126 21:12:48.942718 828 replica.cpp:712] Persisted action at 0
> I0126 21:12:48.943825 828 replica.cpp:537] Replica received write
> request for position 0 from (14151)@172.17.0.5:52680
> I0126 21:12:48.943888 828 leveldb.cpp:436] Reading position from leveldb
> took 31321ns
> I0126 21:12:48.944456 828 leveldb.cpp:341] Persisting action (14 bytes)
> to leveldb took 400796ns
> I0126 21:12:48.944545 828 replica.cpp:712] Persisted action at 0
> I0126 21:12:48.945248 825 replica.cpp:691] Replica received learned
> notice for position 0 from @0.0.0.0:0
> I0126 21:12:48.945709 825 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 426968ns
> I0126 21:12:48.945737 825 replica.cpp:712] Persisted action at 0
> I0126 21:12:48.945760 825 replica.cpp:697] Replica learned NOP action at
> position 0
> I0126 21:12:48.946410 831 log.cpp:675] Writer started with ending
> position 0
> I0126 21:12:48.947729 823 leveldb.cpp:436] Reading position from leveldb
> took 30984ns
> I0126 21:12:48.948747 822 registrar.cpp:340] Successfully fetched the
> registry (0B) in 14.329088ms
> I0126 21:12:48.948866 822 registrar.cpp:439] Applied 1 operations in
> 31121ns; attempting to update the 'registry'
> I0126 21:12:48.950023 821 log.cpp:683] Attempting to append 170 bytes to
> the log
> I0126 21:12:48.950237 833 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 1
> I0126 21:12:48.951225 823 replica.cpp:537] Replica received write
> request for position 1 from (14152)@172.17.0.5:52680
> I0126 21:12:48.957044 823 leveldb.cpp:341] Persisting action (189 bytes)
> to leveldb took 5.780168ms
> I0126 21:12:48.957172 823 replica.cpp:712] Persisted action at 1
> I0126 21:12:48.958106 832 replica.cpp:691] Replica received learned
> notice for position 1 from @0.0.0.0:0
> I0126 21:12:48.958582 832 leveldb.cpp:341] Persisting action (191 bytes)
> to leveldb took 442252ns
> I0126 21:12:48.958614 832 replica.cpp:712] Persisted action at 1
> I0126 21:12:48.958636 832 replica.cpp:697] Replica learned APPEND action
> at position 1
> I0126 21:12:48.959554 823 registrar.cpp:484] Successfully updated the
> 'registry' in 10.49472ms
> I0126 21:12:48.959756 823 registrar.cpp:370] Successfully recovered
> registrar
> I0126 21:12:48.959872 821 log.cpp:702] Attempting to truncate the log to
> 1
> I0126 21:12:48.960068 828 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 2
> I0126 21:12:48.960176 827 master.cpp:1520] Recovered 0 slaves from the
> Registry (131B) ; allowing 10mins for slaves to re-register
> I0126 21:12:48.960196 821 hierarchical.cpp:171] Skipping recovery of
> hierarchical allocator: nothing to recover
> I0126 21:12:48.961004 824 replica.cpp:537] Replica received write
> request for position 2 from (14153)@172.17.0.5:52680
> I0126 21:12:48.961397 824 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 355936ns
> I0126 21:12:48.961423 824 replica.cpp:712] Persisted action at 2
> I0126 21:12:48.962100 829 replica.cpp:691] Replica received learned
> notice for position 2 from @0.0.0.0:0
> I0126 21:12:48.962527 829 leveldb.cpp:341] Persisting action (18 bytes)
> to leveldb took 335898ns
> I0126 21:12:48.962584 829 leveldb.cpp:399] Deleting ~1 keys from leveldb
> took 31618ns
> I0126 21:12:48.962610 829 replica.cpp:712] Persisted action at 2
> I0126 21:12:48.962636 829 replica.cpp:697] Replica learned TRUNCATE
> action at position 2
> I0126 21:12:48.970995 800 scheduler.cpp:154] Version: 0.27.0
> I0126 21:12:48.971504 830 scheduler.cpp:236] New master detected at
> master@172.17.0.5:52680
> I0126 21:12:48.972497 821 scheduler.cpp:298] Sending SUBSCRIBE call to
> master@172.17.0.5:52680
> I0126 21:12:48.974743 831 process.cpp:3141] Handling HTTP event for
> process 'master' with path: '/master/api/v1/scheduler'
> I0126 21:12:48.975226 833 http.cpp:503] HTTP POST for
> /master/api/v1/scheduler from 172.17.0.5:46765
> I0126 21:12:48.975628 833 master.cpp:1972] Received subscription request
> for HTTP framework 'default'
> I0126 21:12:48.975697 833 master.cpp:1749] Authorizing framework
> principal 'test-principal' to receive offers for role '*'
> I0126 21:12:48.976029 833 master.cpp:2063] Subscribing framework
> 'default' with checkpointing disabled and capabilities [ ]
> I0126 21:12:48.976435 827 hierarchical.cpp:265] Added framework
> 609f3254-9020-4f15-a970-91534c11d60c-0000
> I0126 21:12:48.976480 833 master.hpp:1658] Sending heartbeat to
> 609f3254-9020-4f15-a970-91534c11d60c-0000
> I0126 21:12:48.976635 827 hierarchical.cpp:1355] No resources available
> to allocate!
> I0126 21:12:48.976774 827 hierarchical.cpp:1450] No inverse offers to
> send out!
> I0126 21:12:48.976900 827 hierarchical.cpp:1090] Performed allocation
> for 0 slaves in 361800ns
> I0126 21:12:48.978000 822 scheduler.cpp:457] Enqueuing event SUBSCRIBED
> received from master@172.17.0.5:52680
> I0126 21:12:48.978399 822 scheduler.cpp:457] Enqueuing event HEARTBEAT
> received from master@172.17.0.5:52680
> I0126 21:12:48.979051 832 master_maintenance_tests.cpp:177] Ignoring
> HEARTBEAT event
> I0126 21:12:48.979266 833 scheduler.cpp:298] Sending REQUEST call to
> master@172.17.0.5:52680
> I0126 21:12:48.980732 832 process.cpp:3141] Handling HTTP event for
> process 'master' with path: '/master/api/v1/scheduler'
> I0126 21:12:48.981122 820 http.cpp:503] HTTP POST for
> /master/api/v1/scheduler from 172.17.0.5:46766
> I0126 21:12:48.981443 820 master.cpp:2717] Processing REQUEST call for
> framework 609f3254-9020-4f15-a970-91534c11d60c-0000 (default)
> I0126 21:12:48.981714 820 hierarchical.cpp:585] Received resource
> request from framework 609f3254-9020-4f15-a970-91534c11d60c-0000
> I0126 21:12:48.982326 800 master.cpp:1025] Master terminating
> I0126 21:12:48.983392 828 hierarchical.cpp:326] Removed framework
> 609f3254-9020-4f15-a970-91534c11d60c-0000
> E0126 21:12:48.985258 830 scheduler.cpp:431] End-Of-File received from
> master. The master closed the event stream
> [ OK ] ContentType/SchedulerTest.Request/1 (67 ms)
> [----------] 22 tests from ContentType/SchedulerTest (4428 ms total)
>
> [----------] Global test environment tear-down
> 2016-01-26
> 21:12:49,294:800(0x7f7b957b6700):ZOO_ERROR@handle_socket_error_msg@1697:
> Socket [127.0.0.1:36129] zk retcode=-4, errno=111(Connection refused):
> server refused to accept the client
> [==========] 954 tests from 124 test cases ran. (392712 ms total)
> [ PASSED ] 953 tests.
> [ FAILED ] 1 test, listed below:
> [ FAILED ] MasterTest.MaxCompletedTasksPerFrameworkFlag
>
> 1 FAILED TEST
> YOU HAVE 8 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-1453840719-22760
> Untagged: mesos-1453840719-22760:latest
> Deleted: 06cbd68cc90fc1b3600ba430794df94c6575e9fe5b6049a41549a2938b878ba4
> Deleted: 8ec112a64c70ff3686e3db1d1583a2461e979c8144547047eca05a1b75c99d8b
> Deleted: 34f9d28e655f12f64065599e22cd85e26fec3aabbfd334211dda2cdd946b69cf
> Deleted: 0cdbd7862620058d04eeb010cf083b82ab841769ebc81eee588d27f2e442f299
> Deleted: 68df0e8b2592e570a3183a600051bcf264676fe474487ada495931ccecc349f9
> Deleted: f2422e7be3d9781fa7533f4014ee09b9e062f0340ba62e7739012098e918a708
> Deleted: 581e2052cff0aacfd491800308066b5e5e23aa706c7c1f9694a5b7d5e234dc25
> Deleted: 1fae74e409d2d2c38569a0208b945781c035384896f84b511b83f703681b14fd
> Deleted: 29e6bd353b0937624d3f8e3265ed5a2cef2928a4ba5996ec20dd3ab685c802a1
> Deleted: d1286506871dea101369c732938d1dec03017d0c1e4078fc7f0cb0a3cbef7d39
> Deleted: 712df17d45c12b561c1cb90666e813be96a8734d2e0f2aba0eefe28f9fd28daa
> Deleted: 34372e0c6dc544839f872ffaa75dd31c72167c213dd6e7cc2c5b4f111cdce4eb
> Deleted: 356f5f3794b297e2b1eccee8efdb6a2ad2219c136b3cf6eeb7f21f7d07924f1e
> Build step 'Execute shell' marked build as failure
>