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/29 19:57:12 UTC
Build failed in Jenkins: Mesos » gcc,--verbose,GLOG_v=1 MESOS_VERBOSE=1,centos:7,docker||Hadoop #1585
See <https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=centos%3A7,label_exp=docker%7C%7CHadoop/1585/>
------------------------------------------
Started by upstream project "Mesos" build number 1585
originally caused by:
Started by an SCM change
[EnvInject] - Loading node environment variables.
Building remotely on H2 (Mapreduce zookeeper Hadoop Pig falcon Hdfs) in workspace <https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=centos%3A7,label_exp=docker%7C%7CHadoop/ws/>
Cloning the remote Git repository
Using shallow clone
Cloning repository https://git-wip-us.apache.org/repos/asf/mesos.git
> git init <https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=centos%3A7,label_exp=docker%7C%7CHadoop/ws/> # timeout=10
Fetching upstream changes from https://git-wip-us.apache.org/repos/asf/mesos.git
> git --version # timeout=10
> git -c core.askpass=true fetch --tags --progress https://git-wip-us.apache.org/repos/asf/mesos.git +refs/heads/*:refs/remotes/origin/* --depth=1 # timeout=60
> git config remote.origin.url https://git-wip-us.apache.org/repos/asf/mesos.git # timeout=10
> git config --add remote.origin.fetch +refs/heads/*:refs/remotes/origin/* # timeout=10
> git config remote.origin.url https://git-wip-us.apache.org/repos/asf/mesos.git # timeout=10
Fetching upstream changes from https://git-wip-us.apache.org/repos/asf/mesos.git
> git -c core.askpass=true fetch --tags --progress https://git-wip-us.apache.org/repos/asf/mesos.git +refs/heads/*:refs/remotes/origin/* # timeout=60
Checking out Revision fac024fda0897a62377f17549e61b8ac8e531e2e (origin/master)
> git config core.sparsecheckout # timeout=10
> git checkout -f fac024fda0897a62377f17549e61b8ac8e531e2e
FATAL: Could not checkout fac024fda0897a62377f17549e61b8ac8e531e2e
hudson.plugins.git.GitException: Could not checkout fac024fda0897a62377f17549e61b8ac8e531e2e
at org.jenkinsci.plugins.gitclient.CliGitAPIImpl$9.execute(CliGitAPIImpl.java:1964)
at org.jenkinsci.plugins.gitclient.RemoteGitImpl$CommandInvocationHandler$1.call(RemoteGitImpl.java:152)
at org.jenkinsci.plugins.gitclient.RemoteGitImpl$CommandInvocationHandler$1.call(RemoteGitImpl.java:145)
at hudson.remoting.UserRequest.perform(UserRequest.java:121)
at hudson.remoting.UserRequest.perform(UserRequest.java:49)
at hudson.remoting.Request$2.run(Request.java:326)
at hudson.remoting.InterceptingExecutorService$1.call(InterceptingExecutorService.java:68)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
at ......remote call to H2(Native Method)
at hudson.remoting.Channel.attachCallSiteStackTrace(Channel.java:1413)
at hudson.remoting.UserResponse.retrieve(UserRequest.java:221)
at hudson.remoting.Channel.call(Channel.java:778)
at org.jenkinsci.plugins.gitclient.RemoteGitImpl$CommandInvocationHandler.execute(RemoteGitImpl.java:145)
at sun.reflect.GeneratedMethodAccessor533.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.jenkinsci.plugins.gitclient.RemoteGitImpl$CommandInvocationHandler.invoke(RemoteGitImpl.java:131)
at com.sun.proxy.$Proxy75.execute(Unknown Source)
at hudson.plugins.git.GitSCM.checkout(GitSCM.java:1081)
at hudson.scm.SCM.checkout(SCM.java:484)
at hudson.model.AbstractProject.checkout(AbstractProject.java:1274)
at hudson.model.AbstractBuild$AbstractBuildExecution.defaultCheckout(AbstractBuild.java:609)
at jenkins.scm.SCMCheckoutStrategy.checkout(SCMCheckoutStrategy.java:86)
at hudson.model.AbstractBuild$AbstractBuildExecution.run(AbstractBuild.java:531)
at hudson.model.Run.execute(Run.java:1738)
at hudson.matrix.MatrixRun.run(MatrixRun.java:146)
at hudson.model.ResourceController.execute(ResourceController.java:98)
at hudson.model.Executor.run(Executor.java:381)
Caused by: hudson.plugins.git.GitException: Command "git checkout -f fac024fda0897a62377f17549e61b8ac8e531e2e" returned status code 128:
stdout:
stderr: fatal: reference is not a tree: fac024fda0897a62377f17549e61b8ac8e531e2e
at org.jenkinsci.plugins.gitclient.CliGitAPIImpl.launchCommandIn(CliGitAPIImpl.java:1693)
at org.jenkinsci.plugins.gitclient.CliGitAPIImpl.access$500(CliGitAPIImpl.java:62)
at org.jenkinsci.plugins.gitclient.CliGitAPIImpl$9.execute(CliGitAPIImpl.java:1956)
at org.jenkinsci.plugins.gitclient.RemoteGitImpl$CommandInvocationHandler$1.call(RemoteGitImpl.java:152)
at org.jenkinsci.plugins.gitclient.RemoteGitImpl$CommandInvocationHandler$1.call(RemoteGitImpl.java:145)
at hudson.remoting.UserRequest.perform(UserRequest.java:121)
at hudson.remoting.UserRequest.perform(UserRequest.java:49)
at hudson.remoting.Request$2.run(Request.java:326)
at hudson.remoting.InterceptingExecutorService$1.call(InterceptingExecutorService.java:68)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Jenkins build is back to normal : Mesos » gcc,--verbose,GLOG_v=1 MESOS_VERBOSE=1,centos:7,docker||Hadoop #1588
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=centos%3A7,label_exp=docker%7C%7CHadoop/1588/>
Build failed in Jenkins: Mesos » gcc,--verbose,GLOG_v=1 MESOS_VERBOSE=1,centos:7,docker||Hadoop #1587
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=centos%3A7,label_exp=docker%7C%7CHadoop/1587/>
------------------------------------------
[...truncated 160089 lines...]
I0129 21:31:59.456373 975 slave.cpp:667] Slave terminating
I0129 21:31:59.456547 975 slave.cpp:2078] Asked to shut down framework 306afbb1-df94-468e-b04a-d9709df6f2c3-0000 by @0.0.0.0:0
I0129 21:31:59.456676 975 slave.cpp:2103] Shutting down framework 306afbb1-df94-468e-b04a-d9709df6f2c3-0000
I0129 21:31:59.456866 975 slave.cpp:4128] Shutting down executor 'default' of framework 306afbb1-df94-468e-b04a-d9709df6f2c3-0000 at executor(139)@172.17.0.6:41178
[ OK ] ContentType/SchedulerTest.Message/1 (126 ms)
[ RUN ] ContentType/SchedulerTest.Request/0
I0129 21:31:59.469012 975 leveldb.cpp:174] Opened db in 2.580924ms
I0129 21:31:59.470223 975 leveldb.cpp:181] Compacted db in 1.091344ms
I0129 21:31:59.470337 975 leveldb.cpp:196] Created db iterator in 21181ns
I0129 21:31:59.470449 975 leveldb.cpp:202] Seeked to beginning of db in 2533ns
I0129 21:31:59.470546 975 leveldb.cpp:271] Iterated through 0 keys in the db in 432ns
I0129 21:31:59.470685 975 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0129 21:31:59.471577 1000 recover.cpp:447] Starting replica recovery
I0129 21:31:59.471895 1000 recover.cpp:473] Replica is in EMPTY status
I0129 21:31:59.473665 994 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (14177)@172.17.0.6:41178
I0129 21:31:59.475364 1003 recover.cpp:193] Received a recover response from a replica in EMPTY status
I0129 21:31:59.475805 1001 master.cpp:374] Master 1d79b63f-6f94-4746-8a40-c054975b8fd4 (d66130543b12) started on 172.17.0.6:41178
I0129 21:31:59.476156 1001 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/ucNPvy/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.28.0/_inst/share/mesos/webui" --work_dir="/tmp/ucNPvy/master" --zk_session_timeout="10secs"
I0129 21:31:59.476578 1001 master.cpp:423] Master allowing unauthenticated frameworks to register
I0129 21:31:59.476590 1001 master.cpp:426] Master only allowing authenticated slaves to register
I0129 21:31:59.476599 1001 credentials.hpp:35] Loading credentials for authentication from '/tmp/ucNPvy/credentials'
I0129 21:31:59.477010 1001 master.cpp:466] Using default 'crammd5' authenticator
I0129 21:31:59.477186 1001 master.cpp:535] Using default 'basic' HTTP authenticator
I0129 21:31:59.477365 1001 master.cpp:569] Authorization enabled
I0129 21:31:59.477682 1000 hierarchical.cpp:144] Initialized hierarchical allocator process
I0129 21:31:59.477741 1006 whitelist_watcher.cpp:77] No whitelist given
I0129 21:31:59.477833 996 recover.cpp:564] Updating replica status to STARTING
I0129 21:31:59.478490 1006 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 495055ns
I0129 21:31:59.478513 1006 replica.cpp:320] Persisted replica status to STARTING
I0129 21:31:59.478745 999 recover.cpp:473] Replica is in STARTING status
I0129 21:31:59.479526 996 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (14179)@172.17.0.6:41178
I0129 21:31:59.479610 1000 master.cpp:1710] The newly elected leader is master@172.17.0.6:41178 with id 1d79b63f-6f94-4746-8a40-c054975b8fd4
I0129 21:31:59.479745 1000 master.cpp:1723] Elected as the leading master!
I0129 21:31:59.479778 1000 master.cpp:1468] Recovering from registrar
I0129 21:31:59.479980 1005 registrar.cpp:307] Recovering registrar
I0129 21:31:59.479998 1007 recover.cpp:193] Received a recover response from a replica in STARTING status
I0129 21:31:59.480531 996 recover.cpp:564] Updating replica status to VOTING
I0129 21:31:59.481019 995 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 305963ns
I0129 21:31:59.481042 995 replica.cpp:320] Persisted replica status to VOTING
I0129 21:31:59.481139 1001 recover.cpp:578] Successfully joined the Paxos group
I0129 21:31:59.481340 1001 recover.cpp:462] Recover process terminated
I0129 21:31:59.481806 1004 log.cpp:659] Attempting to start the writer
I0129 21:31:59.482942 995 replica.cpp:493] Replica received implicit promise request from (14180)@172.17.0.6:41178 with proposal 1
I0129 21:31:59.483259 995 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 286350ns
I0129 21:31:59.483281 995 replica.cpp:342] Persisted promised to 1
I0129 21:31:59.483999 1008 coordinator.cpp:238] Coordinator attempting to fill missing positions
I0129 21:31:59.485302 1004 replica.cpp:388] Replica received explicit promise request from (14181)@172.17.0.6:41178 for position 0 with proposal 2
I0129 21:31:59.485611 1004 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 268815ns
I0129 21:31:59.485635 1004 replica.cpp:712] Persisted action at 0
I0129 21:31:59.487153 1009 replica.cpp:537] Replica received write request for position 0 from (14182)@172.17.0.6:41178
I0129 21:31:59.487223 1009 leveldb.cpp:436] Reading position from leveldb took 31622ns
I0129 21:31:59.487675 1009 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 386749ns
I0129 21:31:59.487712 1009 replica.cpp:712] Persisted action at 0
I0129 21:31:59.488600 1008 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
I0129 21:31:59.489073 1008 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 372491ns
I0129 21:31:59.489109 1008 replica.cpp:712] Persisted action at 0
I0129 21:31:59.489130 1008 replica.cpp:697] Replica learned NOP action at position 0
I0129 21:31:59.489877 1005 log.cpp:675] Writer started with ending position 0
I0129 21:31:59.491212 995 leveldb.cpp:436] Reading position from leveldb took 28901ns
I0129 21:31:59.492470 1005 registrar.cpp:340] Successfully fetched the registry (0B) in 12.425984ms
I0129 21:31:59.492620 1005 registrar.cpp:439] Applied 1 operations in 36972ns; attempting to update the 'registry'
I0129 21:31:59.493448 999 log.cpp:683] Attempting to append 170 bytes to the log
I0129 21:31:59.493584 1006 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I0129 21:31:59.494451 994 replica.cpp:537] Replica received write request for position 1 from (14183)@172.17.0.6:41178
I0129 21:31:59.494843 994 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 346366ns
I0129 21:31:59.494873 994 replica.cpp:712] Persisted action at 1
I0129 21:31:59.496042 1000 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
I0129 21:31:59.496501 1000 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 359999ns
I0129 21:31:59.496531 1000 replica.cpp:712] Persisted action at 1
I0129 21:31:59.496552 1000 replica.cpp:697] Replica learned APPEND action at position 1
I0129 21:31:59.497607 995 registrar.cpp:484] Successfully updated the 'registry' in 4.922112ms
I0129 21:31:59.497752 995 registrar.cpp:370] Successfully recovered registrar
I0129 21:31:59.497933 998 log.cpp:702] Attempting to truncate the log to 1
I0129 21:31:59.498286 1001 master.cpp:1520] Recovered 0 slaves from the Registry (131B) ; allowing 10mins for slaves to re-register
I0129 21:31:59.498291 1009 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I0129 21:31:59.498328 1006 hierarchical.cpp:171] Skipping recovery of hierarchical allocator: nothing to recover
I0129 21:31:59.499166 1001 replica.cpp:537] Replica received write request for position 2 from (14184)@172.17.0.6:41178
I0129 21:31:59.499541 1001 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 333943ns
I0129 21:31:59.499574 1001 replica.cpp:712] Persisted action at 2
I0129 21:31:59.500339 1002 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
I0129 21:31:59.500712 1002 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 330536ns
I0129 21:31:59.500776 1002 leveldb.cpp:399] Deleting ~1 keys from leveldb took 32560ns
I0129 21:31:59.500805 1002 replica.cpp:712] Persisted action at 2
I0129 21:31:59.500860 1002 replica.cpp:697] Replica learned TRUNCATE action at position 2
I0129 21:31:59.509646 975 scheduler.cpp:154] Version: 0.28.0
I0129 21:31:59.510967 1004 scheduler.cpp:236] New master detected at master@172.17.0.6:41178
I0129 21:31:59.512274 995 scheduler.cpp:298] Sending SUBSCRIBE call to master@172.17.0.6:41178
I0129 21:31:59.514884 999 process.cpp:3141] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0129 21:31:59.515410 1002 http.cpp:503] HTTP POST for /master/api/v1/scheduler from 172.17.0.6:55358
I0129 21:31:59.515736 1002 master.cpp:1972] Received subscription request for HTTP framework 'default'
I0129 21:31:59.515908 1002 master.cpp:1749] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0129 21:31:59.516307 1002 master.cpp:2063] Subscribing framework 'default' with checkpointing disabled and capabilities [ ]
I0129 21:31:59.517016 996 hierarchical.cpp:265] Added framework 1d79b63f-6f94-4746-8a40-c054975b8fd4-0000
I0129 21:31:59.517966 996 hierarchical.cpp:1403] No resources available to allocate!
I0129 21:31:59.518118 996 hierarchical.cpp:1498] No inverse offers to send out!
I0129 21:31:59.518232 996 hierarchical.cpp:1096] Performed allocation for 0 slaves in 333959ns
I0129 21:31:59.517335 1002 master.hpp:1658] Sending heartbeat to 1d79b63f-6f94-4746-8a40-c054975b8fd4-0000
I0129 21:31:59.520084 997 scheduler.cpp:457] Enqueuing event SUBSCRIBED received from master@172.17.0.6:41178
I0129 21:31:59.520884 1009 scheduler.cpp:457] Enqueuing event HEARTBEAT received from master@172.17.0.6:41178
I0129 21:31:59.522068 1005 master_maintenance_tests.cpp:177] Ignoring HEARTBEAT event
I0129 21:31:59.522969 1009 scheduler.cpp:298] Sending REQUEST call to master@172.17.0.6:41178
I0129 21:31:59.525184 1005 process.cpp:3141] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0129 21:31:59.526145 997 http.cpp:503] HTTP POST for /master/api/v1/scheduler from 172.17.0.6:55359
I0129 21:31:59.526322 997 master.cpp:2717] Processing REQUEST call for framework 1d79b63f-6f94-4746-8a40-c054975b8fd4-0000 (default)
I0129 21:31:59.526609 997 hierarchical.cpp:589] Received resource request from framework 1d79b63f-6f94-4746-8a40-c054975b8fd4-0000
I0129 21:31:59.527719 975 master.cpp:1025] Master terminating
I0129 21:31:59.528703 997 hierarchical.cpp:326] Removed framework 1d79b63f-6f94-4746-8a40-c054975b8fd4-0000
E0129 21:31:59.530696 997 scheduler.cpp:431] End-Of-File received from master. The master closed the event stream
[ OK ] ContentType/SchedulerTest.Request/0 (86 ms)
[ RUN ] ContentType/SchedulerTest.Request/1
I0129 21:31:59.557366 975 leveldb.cpp:174] Opened db in 3.358128ms
I0129 21:31:59.558579 975 leveldb.cpp:181] Compacted db in 1.163825ms
I0129 21:31:59.558640 975 leveldb.cpp:196] Created db iterator in 20631ns
I0129 21:31:59.558660 975 leveldb.cpp:202] Seeked to beginning of db in 2224ns
I0129 21:31:59.558667 975 leveldb.cpp:271] Iterated through 0 keys in the db in 235ns
I0129 21:31:59.558707 975 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0129 21:31:59.559193 1004 recover.cpp:447] Starting replica recovery
I0129 21:31:59.559424 1004 recover.cpp:473] Replica is in EMPTY status
I0129 21:31:59.560430 1005 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (14192)@172.17.0.6:41178
I0129 21:31:59.560729 1003 recover.cpp:193] Received a recover response from a replica in EMPTY status
I0129 21:31:59.561184 1000 recover.cpp:564] Updating replica status to STARTING
I0129 21:31:59.561704 1007 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 388069ns
I0129 21:31:59.561728 1007 replica.cpp:320] Persisted replica status to STARTING
I0129 21:31:59.561902 997 recover.cpp:473] Replica is in STARTING status
I0129 21:31:59.562039 1005 master.cpp:374] Master 2b3039ee-3c8f-4282-bfc3-d85d699f3896 (d66130543b12) started on 172.17.0.6:41178
I0129 21:31:59.562063 1005 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/xiH32d/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.28.0/_inst/share/mesos/webui" --work_dir="/tmp/xiH32d/master" --zk_session_timeout="10secs"
I0129 21:31:59.562511 1005 master.cpp:423] Master allowing unauthenticated frameworks to register
I0129 21:31:59.562522 1005 master.cpp:426] Master only allowing authenticated slaves to register
I0129 21:31:59.562530 1005 credentials.hpp:35] Loading credentials for authentication from '/tmp/xiH32d/credentials'
I0129 21:31:59.562758 1001 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (14193)@172.17.0.6:41178
I0129 21:31:59.562916 1005 master.cpp:466] Using default 'crammd5' authenticator
I0129 21:31:59.563010 999 recover.cpp:193] Received a recover response from a replica in STARTING status
I0129 21:31:59.563079 1005 master.cpp:535] Using default 'basic' HTTP authenticator
I0129 21:31:59.563359 1005 master.cpp:569] Authorization enabled
I0129 21:31:59.563558 996 hierarchical.cpp:144] Initialized hierarchical allocator process
I0129 21:31:59.563561 1004 recover.cpp:564] Updating replica status to VOTING
I0129 21:31:59.563568 1008 whitelist_watcher.cpp:77] No whitelist given
I0129 21:31:59.564105 997 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 327357ns
I0129 21:31:59.564131 997 replica.cpp:320] Persisted replica status to VOTING
I0129 21:31:59.564268 1004 recover.cpp:578] Successfully joined the Paxos group
I0129 21:31:59.564478 1004 recover.cpp:462] Recover process terminated
I0129 21:31:59.565383 997 master.cpp:1710] The newly elected leader is master@172.17.0.6:41178 with id 2b3039ee-3c8f-4282-bfc3-d85d699f3896
I0129 21:31:59.565418 997 master.cpp:1723] Elected as the leading master!
I0129 21:31:59.565440 997 master.cpp:1468] Recovering from registrar
I0129 21:31:59.565575 1009 registrar.cpp:307] Recovering registrar
I0129 21:31:59.566113 1002 log.cpp:659] Attempting to start the writer
I0129 21:31:59.567210 1005 replica.cpp:493] Replica received implicit promise request from (14195)@172.17.0.6:41178 with proposal 1
I0129 21:31:59.567531 1005 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 287138ns
I0129 21:31:59.567554 1005 replica.cpp:342] Persisted promised to 1
I0129 21:31:59.568099 1008 coordinator.cpp:238] Coordinator attempting to fill missing positions
I0129 21:31:59.569119 1005 replica.cpp:388] Replica received explicit promise request from (14196)@172.17.0.6:41178 for position 0 with proposal 2
I0129 21:31:59.569469 1005 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 309123ns
I0129 21:31:59.569494 1005 replica.cpp:712] Persisted action at 0
I0129 21:31:59.570600 1000 replica.cpp:537] Replica received write request for position 0 from (14197)@172.17.0.6:41178
I0129 21:31:59.570662 1000 leveldb.cpp:436] Reading position from leveldb took 27386ns
I0129 21:31:59.571008 1000 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 304878ns
I0129 21:31:59.571034 1000 replica.cpp:712] Persisted action at 0
I0129 21:31:59.571636 1002 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
I0129 21:31:59.572058 1002 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 384831ns
I0129 21:31:59.572090 1002 replica.cpp:712] Persisted action at 0
I0129 21:31:59.572113 1002 replica.cpp:697] Replica learned NOP action at position 0
I0129 21:31:59.572899 1009 log.cpp:675] Writer started with ending position 0
I0129 21:31:59.574156 997 leveldb.cpp:436] Reading position from leveldb took 37236ns
I0129 21:31:59.575402 994 registrar.cpp:340] Successfully fetched the registry (0B) in 9.772032ms
I0129 21:31:59.575525 994 registrar.cpp:439] Applied 1 operations in 28486ns; attempting to update the 'registry'
I0129 21:31:59.576361 1005 log.cpp:683] Attempting to append 170 bytes to the log
I0129 21:31:59.576508 1006 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I0129 21:31:59.577405 1004 replica.cpp:537] Replica received write request for position 1 from (14198)@172.17.0.6:41178
I0129 21:31:59.577932 1004 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 475249ns
I0129 21:31:59.577966 1004 replica.cpp:712] Persisted action at 1
I0129 21:31:59.578752 1003 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
I0129 21:31:59.579201 1003 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 404051ns
I0129 21:31:59.579236 1003 replica.cpp:712] Persisted action at 1
I0129 21:31:59.579257 1003 replica.cpp:697] Replica learned APPEND action at position 1
I0129 21:31:59.580453 995 registrar.cpp:484] Successfully updated the 'registry' in 4.84608ms
I0129 21:31:59.580620 995 registrar.cpp:370] Successfully recovered registrar
I0129 21:31:59.580683 996 log.cpp:702] Attempting to truncate the log to 1
I0129 21:31:59.580858 1003 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I0129 21:31:59.581423 994 master.cpp:1520] Recovered 0 slaves from the Registry (131B) ; allowing 10mins for slaves to re-register
I0129 21:31:59.581454 998 hierarchical.cpp:171] Skipping recovery of hierarchical allocator: nothing to recover
I0129 21:31:59.582008 1003 replica.cpp:537] Replica received write request for position 2 from (14199)@172.17.0.6:41178
I0129 21:31:59.582429 1003 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 370389ns
I0129 21:31:59.582461 1003 replica.cpp:712] Persisted action at 2
I0129 21:31:59.583206 996 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
I0129 21:31:59.583639 996 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 389413ns
I0129 21:31:59.583705 996 leveldb.cpp:399] Deleting ~1 keys from leveldb took 34574ns
I0129 21:31:59.583731 996 replica.cpp:712] Persisted action at 2
I0129 21:31:59.583755 996 replica.cpp:697] Replica learned TRUNCATE action at position 2
I0129 21:31:59.592245 975 scheduler.cpp:154] Version: 0.28.0
I0129 21:31:59.593148 1002 scheduler.cpp:236] New master detected at master@172.17.0.6:41178
I0129 21:31:59.594462 999 scheduler.cpp:298] Sending SUBSCRIBE call to master@172.17.0.6:41178
I0129 21:31:59.596606 997 process.cpp:3141] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0129 21:31:59.597251 1005 http.cpp:503] HTTP POST for /master/api/v1/scheduler from 172.17.0.6:55360
I0129 21:31:59.597637 1005 master.cpp:1972] Received subscription request for HTTP framework 'default'
I0129 21:31:59.597707 1005 master.cpp:1749] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0129 21:31:59.598016 1005 master.cpp:2063] Subscribing framework 'default' with checkpointing disabled and capabilities [ ]
I0129 21:31:59.598485 996 hierarchical.cpp:265] Added framework 2b3039ee-3c8f-4282-bfc3-d85d699f3896-0000
I0129 21:31:59.598582 996 hierarchical.cpp:1403] No resources available to allocate!
I0129 21:31:59.598615 1000 master.hpp:1658] Sending heartbeat to 2b3039ee-3c8f-4282-bfc3-d85d699f3896-0000
I0129 21:31:59.598706 996 hierarchical.cpp:1498] No inverse offers to send out!
I0129 21:31:59.598736 996 hierarchical.cpp:1096] Performed allocation for 0 slaves in 215232ns
I0129 21:31:59.599658 995 scheduler.cpp:457] Enqueuing event SUBSCRIBED received from master@172.17.0.6:41178
I0129 21:31:59.600270 995 scheduler.cpp:457] Enqueuing event HEARTBEAT received from master@172.17.0.6:41178
I0129 21:31:59.601065 995 scheduler.cpp:298] Sending REQUEST call to master@172.17.0.6:41178
I0129 21:31:59.601115 1004 master_maintenance_tests.cpp:177] Ignoring HEARTBEAT event
I0129 21:31:59.603474 997 process.cpp:3141] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0129 21:31:59.603989 994 http.cpp:503] HTTP POST for /master/api/v1/scheduler from 172.17.0.6:55361
I0129 21:31:59.604259 994 master.cpp:2717] Processing REQUEST call for framework 2b3039ee-3c8f-4282-bfc3-d85d699f3896-0000 (default)
I0129 21:31:59.604480 997 hierarchical.cpp:589] Received resource request from framework 2b3039ee-3c8f-4282-bfc3-d85d699f3896-0000
I0129 21:31:59.604961 1008 master.cpp:1025] Master terminating
I0129 21:31:59.605283 996 hierarchical.cpp:326] Removed framework 2b3039ee-3c8f-4282-bfc3-d85d699f3896-0000
E0129 21:31:59.607245 1007 scheduler.cpp:431] End-Of-File received from master. The master closed the event stream
[ OK ] ContentType/SchedulerTest.Request/1 (60 ms)
[----------] 22 tests from ContentType/SchedulerTest (4490 ms total)
[----------] Global test environment tear-down
[==========] 963 tests from 126 test cases ran. (350129 ms total)
[ PASSED ] 962 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] ShasumTest.SHA512SimpleFile
1 FAILED TEST
YOU HAVE 8 DISABLED TESTS
make[4]: *** [check-local] Error 1
make[4]: Leaving directory `/mesos/mesos-0.28.0/_build/src'
make[3]: *** [check-am] Error 2
make[3]: Leaving directory `/mesos/mesos-0.28.0/_build/src'
make[2]: *** [check] Error 2
make[2]: Leaving directory `/mesos/mesos-0.28.0/_build/src'
make[1]: *** [check-recursive] Error 1
make[1]: Leaving directory `/mesos/mesos-0.28.0/_build'
make: *** [distcheck] Error 1
+ docker rmi mesos-1454101017-12995
Untagged: mesos-1454101017-12995:latest
Deleted: cd1dbd58025178e7666fc03a147fcbc4f916dec2284164c2a904ff458a48276e
Deleted: 9827d2fd3ed97132171e60c7375d322c9d785e496ca115901ef6cc376ad872e4
Deleted: 136557ae71fabf904aa6f3599c15d61db19b19ec3c417a70fc0a6962551c88db
Deleted: 2b44acb99c0986908b807bad1c0411b29c646e2fc2ae5a771037f741366775b2
Deleted: 07b42ef73c2723f6ec744f52360f23d462920dd8fc16dbdee88b5eae68cc5ea5
Deleted: 93c9d796d6cf4473dec036d7ddd08f658ca375b7e6a78fd3876c4850aedc4e08
Deleted: d9de8b70857dfc014afabd9bdada2e596c7d6117dda2ecc142c6cffe50c27e2d
Deleted: 7ecfd740e9b1cfeaacbae5bb7b177c2f9fe62d4d78a0e11b900979d15207a0b2
Deleted: a20406ca06b40b9315db1fc3a828ae423cb4156d09d5cea79c5972be71f3ba03
Deleted: 11a09f92e3815c10afba77bc846b080fd345f1cc78f556798ae8f8392edbe182
Deleted: 770da6b39ea19852a37b6f9964cc6c38d4a8a41fa5654c1f4a6b17df5764c65d
Deleted: 21a7f1bcd50775725b3f4449fe878bd28c3153b4a2dcfae5a1fdb73be26f23e0
Deleted: a37e22c5568a789b26f00d3f901ac6c7b5253e0d9cc7ba0db89411e2a6f53e27
Build step 'Execute shell' marked build as failure
Build failed in Jenkins: Mesos » gcc,--verbose,GLOG_v=1 MESOS_VERBOSE=1,centos:7,docker||Hadoop #1586
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=centos%3A7,label_exp=docker%7C%7CHadoop/1586/>
------------------------------------------
[...truncated 159702 lines...]
I0129 19:54:20.987282 992 gc.cpp:54] Scheduling '/tmp/ContentType_SchedulerTest_Message_1_x92AAI/slaves/400b239b-74c9-4241-8edc-c6354fc27cbe-S0/frameworks/400b239b-74c9-4241-8edc-c6354fc27cbe-0000/executors/default' for gc 6.99998857464296days in the future
I0129 19:54:20.987401 999 status_update_manager.cpp:282] Closing status update streams for framework 400b239b-74c9-4241-8edc-c6354fc27cbe-0000
I0129 19:54:20.987417 992 gc.cpp:54] Scheduling '/tmp/ContentType_SchedulerTest_Message_1_x92AAI/slaves/400b239b-74c9-4241-8edc-c6354fc27cbe-S0/frameworks/400b239b-74c9-4241-8edc-c6354fc27cbe-0000' for gc 6.99998857246519days in the future
I0129 19:54:20.987483 999 status_update_manager.cpp:528] Cleaning up status update stream for task 8f483474-b4f0-4c3a-a0b4-fcbc5852ed44 of framework 400b239b-74c9-4241-8edc-c6354fc27cbe-0000
[ OK ] ContentType/SchedulerTest.Message/1 (124 ms)
[ RUN ] ContentType/SchedulerTest.Request/0
I0129 19:54:20.996332 968 leveldb.cpp:174] Opened db in 3.286965ms
I0129 19:54:20.997465 968 leveldb.cpp:181] Compacted db in 1.090023ms
I0129 19:54:20.997531 968 leveldb.cpp:196] Created db iterator in 19825ns
I0129 19:54:20.997552 968 leveldb.cpp:202] Seeked to beginning of db in 1955ns
I0129 19:54:20.997565 968 leveldb.cpp:271] Iterated through 0 keys in the db in 310ns
I0129 19:54:20.997609 968 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0129 19:54:20.998302 996 recover.cpp:447] Starting replica recovery
I0129 19:54:20.998720 989 recover.cpp:473] Replica is in EMPTY status
I0129 19:54:20.999891 1002 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (14153)@172.17.0.4:43331
I0129 19:54:21.000393 998 recover.cpp:193] Received a recover response from a replica in EMPTY status
I0129 19:54:21.000833 996 recover.cpp:564] Updating replica status to STARTING
I0129 19:54:21.001600 989 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 487056ns
I0129 19:54:21.001629 989 replica.cpp:320] Persisted replica status to STARTING
I0129 19:54:21.001762 996 master.cpp:374] Master 75466650-49f2-4441-b87e-d3b6c651802c (31ea9d77aa96) started on 172.17.0.4:43331
I0129 19:54:21.001863 989 recover.cpp:473] Replica is in STARTING status
I0129 19:54:21.001786 996 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/PDUVyn/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.28.0/_inst/share/mesos/webui" --work_dir="/tmp/PDUVyn/master" --zk_session_timeout="10secs"
I0129 19:54:21.002127 996 master.cpp:423] Master allowing unauthenticated frameworks to register
I0129 19:54:21.002146 996 master.cpp:426] Master only allowing authenticated slaves to register
I0129 19:54:21.002158 996 credentials.hpp:35] Loading credentials for authentication from '/tmp/PDUVyn/credentials'
I0129 19:54:21.002454 996 master.cpp:466] Using default 'crammd5' authenticator
I0129 19:54:21.002593 996 master.cpp:535] Using default 'basic' HTTP authenticator
I0129 19:54:21.002851 996 master.cpp:569] Authorization enabled
I0129 19:54:21.003382 993 whitelist_watcher.cpp:77] No whitelist given
I0129 19:54:21.003401 992 hierarchical.cpp:144] Initialized hierarchical allocator process
I0129 19:54:21.003499 995 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (14155)@172.17.0.4:43331
I0129 19:54:21.003890 1000 recover.cpp:193] Received a recover response from a replica in STARTING status
I0129 19:54:21.004560 1002 recover.cpp:564] Updating replica status to VOTING
I0129 19:54:21.005240 991 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 459222ns
I0129 19:54:21.005295 991 replica.cpp:320] Persisted replica status to VOTING
I0129 19:54:21.005539 1002 recover.cpp:578] Successfully joined the Paxos group
I0129 19:54:21.005900 1002 recover.cpp:462] Recover process terminated
I0129 19:54:21.006870 999 master.cpp:1710] The newly elected leader is master@172.17.0.4:43331 with id 75466650-49f2-4441-b87e-d3b6c651802c
I0129 19:54:21.006916 999 master.cpp:1723] Elected as the leading master!
I0129 19:54:21.006942 999 master.cpp:1468] Recovering from registrar
I0129 19:54:21.007107 1002 registrar.cpp:307] Recovering registrar
I0129 19:54:21.008183 998 log.cpp:659] Attempting to start the writer
I0129 19:54:21.009821 988 replica.cpp:493] Replica received implicit promise request from (14156)@172.17.0.4:43331 with proposal 1
I0129 19:54:21.010311 988 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 449630ns
I0129 19:54:21.010344 988 replica.cpp:342] Persisted promised to 1
I0129 19:54:21.011107 1002 coordinator.cpp:238] Coordinator attempting to fill missing positions
I0129 19:54:21.012635 988 replica.cpp:388] Replica received explicit promise request from (14157)@172.17.0.4:43331 for position 0 with proposal 2
I0129 19:54:21.013186 988 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 499324ns
I0129 19:54:21.013221 988 replica.cpp:712] Persisted action at 0
I0129 19:54:21.014659 1001 replica.cpp:537] Replica received write request for position 0 from (14158)@172.17.0.4:43331
I0129 19:54:21.014741 1001 leveldb.cpp:436] Reading position from leveldb took 34659ns
I0129 19:54:21.015154 1001 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 364334ns
I0129 19:54:21.015187 1001 replica.cpp:712] Persisted action at 0
I0129 19:54:21.015852 1002 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
I0129 19:54:21.016269 1002 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 372949ns
I0129 19:54:21.016301 1002 replica.cpp:712] Persisted action at 0
I0129 19:54:21.016324 1002 replica.cpp:697] Replica learned NOP action at position 0
I0129 19:54:21.016983 999 log.cpp:675] Writer started with ending position 0
I0129 19:54:21.018355 989 leveldb.cpp:436] Reading position from leveldb took 35257ns
I0129 19:54:21.019433 1001 registrar.cpp:340] Successfully fetched the registry (0B) in 12.272128ms
I0129 19:54:21.019559 1001 registrar.cpp:439] Applied 1 operations in 30151ns; attempting to update the 'registry'
I0129 19:54:21.020428 989 log.cpp:683] Attempting to append 170 bytes to the log
I0129 19:54:21.020581 996 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I0129 19:54:21.021515 996 replica.cpp:537] Replica received write request for position 1 from (14159)@172.17.0.4:43331
I0129 19:54:21.022133 996 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 571282ns
I0129 19:54:21.022167 996 replica.cpp:712] Persisted action at 1
I0129 19:54:21.022930 988 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
I0129 19:54:21.023591 988 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 617976ns
I0129 19:54:21.023624 988 replica.cpp:712] Persisted action at 1
I0129 19:54:21.023646 988 replica.cpp:697] Replica learned APPEND action at position 1
I0129 19:54:21.024837 992 registrar.cpp:484] Successfully updated the 'registry' in 5.202944ms
I0129 19:54:21.025048 992 registrar.cpp:370] Successfully recovered registrar
I0129 19:54:21.025177 993 log.cpp:702] Attempting to truncate the log to 1
I0129 19:54:21.025591 1002 master.cpp:1520] Recovered 0 slaves from the Registry (131B) ; allowing 10mins for slaves to re-register
I0129 19:54:21.025629 1000 hierarchical.cpp:171] Skipping recovery of hierarchical allocator: nothing to recover
I0129 19:54:21.025740 1002 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I0129 19:54:21.026867 988 replica.cpp:537] Replica received write request for position 2 from (14160)@172.17.0.4:43331
I0129 19:54:21.027497 988 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 584149ns
I0129 19:54:21.027529 988 replica.cpp:712] Persisted action at 2
I0129 19:54:21.028458 994 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
I0129 19:54:21.029014 994 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 521406ns
I0129 19:54:21.029114 994 leveldb.cpp:399] Deleting ~1 keys from leveldb took 61439ns
I0129 19:54:21.029144 994 replica.cpp:712] Persisted action at 2
I0129 19:54:21.029172 994 replica.cpp:697] Replica learned TRUNCATE action at position 2
I0129 19:54:21.036303 968 scheduler.cpp:154] Version: 0.28.0
I0129 19:54:21.036963 990 scheduler.cpp:236] New master detected at master@172.17.0.4:43331
I0129 19:54:21.038348 992 scheduler.cpp:298] Sending SUBSCRIBE call to master@172.17.0.4:43331
I0129 19:54:21.040298 1000 process.cpp:3141] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0129 19:54:21.040690 995 http.cpp:503] HTTP POST for /master/api/v1/scheduler from 172.17.0.4:43931
I0129 19:54:21.040854 995 master.cpp:1972] Received subscription request for HTTP framework 'default'
I0129 19:54:21.040909 995 master.cpp:1749] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0129 19:54:21.041182 994 master.cpp:2063] Subscribing framework 'default' with checkpointing disabled and capabilities [ ]
I0129 19:54:21.041555 991 hierarchical.cpp:265] Added framework 75466650-49f2-4441-b87e-d3b6c651802c-0000
I0129 19:54:21.041628 991 hierarchical.cpp:1403] No resources available to allocate!
I0129 19:54:21.041630 994 master.hpp:1658] Sending heartbeat to 75466650-49f2-4441-b87e-d3b6c651802c-0000
I0129 19:54:21.041671 991 hierarchical.cpp:1498] No inverse offers to send out!
I0129 19:54:21.041698 991 hierarchical.cpp:1096] Performed allocation for 0 slaves in 116239ns
I0129 19:54:21.042273 996 scheduler.cpp:457] Enqueuing event SUBSCRIBED received from master@172.17.0.4:43331
I0129 19:54:21.042665 996 scheduler.cpp:457] Enqueuing event HEARTBEAT received from master@172.17.0.4:43331
I0129 19:54:21.043419 992 master_maintenance_tests.cpp:177] Ignoring HEARTBEAT event
I0129 19:54:21.043509 996 scheduler.cpp:298] Sending REQUEST call to master@172.17.0.4:43331
I0129 19:54:21.045189 994 process.cpp:3141] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0129 19:54:21.045650 1000 http.cpp:503] HTTP POST for /master/api/v1/scheduler from 172.17.0.4:43932
I0129 19:54:21.045786 1000 master.cpp:2717] Processing REQUEST call for framework 75466650-49f2-4441-b87e-d3b6c651802c-0000 (default)
I0129 19:54:21.045966 994 hierarchical.cpp:589] Received resource request from framework 75466650-49f2-4441-b87e-d3b6c651802c-0000
I0129 19:54:21.046416 999 master.cpp:1025] Master terminating
I0129 19:54:21.046655 1001 hierarchical.cpp:326] Removed framework 75466650-49f2-4441-b87e-d3b6c651802c-0000
E0129 19:54:21.047761 990 scheduler.cpp:431] End-Of-File received from master. The master closed the event stream
[ OK ] ContentType/SchedulerTest.Request/0 (61 ms)
[ RUN ] ContentType/SchedulerTest.Request/1
I0129 19:54:21.057546 968 leveldb.cpp:174] Opened db in 3.075225ms
I0129 19:54:21.058589 968 leveldb.cpp:181] Compacted db in 1.002252ms
I0129 19:54:21.058650 968 leveldb.cpp:196] Created db iterator in 16867ns
I0129 19:54:21.058670 968 leveldb.cpp:202] Seeked to beginning of db in 1750ns
I0129 19:54:21.058682 968 leveldb.cpp:271] Iterated through 0 keys in the db in 290ns
I0129 19:54:21.058722 968 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0129 19:54:21.059322 1000 recover.cpp:447] Starting replica recovery
I0129 19:54:21.059598 1000 recover.cpp:473] Replica is in EMPTY status
I0129 19:54:21.060968 1000 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (14168)@172.17.0.4:43331
I0129 19:54:21.061398 995 recover.cpp:193] Received a recover response from a replica in EMPTY status
I0129 19:54:21.061960 987 recover.cpp:564] Updating replica status to STARTING
I0129 19:54:21.062839 988 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 658857ns
I0129 19:54:21.062875 988 replica.cpp:320] Persisted replica status to STARTING
I0129 19:54:21.063197 991 recover.cpp:473] Replica is in STARTING status
I0129 19:54:21.063253 999 master.cpp:374] Master b243e52e-9f55-41b9-b06e-50b3a923c0cc (31ea9d77aa96) started on 172.17.0.4:43331
I0129 19:54:21.063283 999 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/1zkOuB/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.28.0/_inst/share/mesos/webui" --work_dir="/tmp/1zkOuB/master" --zk_session_timeout="10secs"
I0129 19:54:21.063694 999 master.cpp:423] Master allowing unauthenticated frameworks to register
I0129 19:54:21.063712 999 master.cpp:426] Master only allowing authenticated slaves to register
I0129 19:54:21.063729 999 credentials.hpp:35] Loading credentials for authentication from '/tmp/1zkOuB/credentials'
I0129 19:54:21.064193 999 master.cpp:466] Using default 'crammd5' authenticator
I0129 19:54:21.064385 999 master.cpp:535] Using default 'basic' HTTP authenticator
I0129 19:54:21.064579 999 master.cpp:569] Authorization enabled
I0129 19:54:21.064615 1001 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (14169)@172.17.0.4:43331
I0129 19:54:21.064800 992 whitelist_watcher.cpp:77] No whitelist given
I0129 19:54:21.064807 993 hierarchical.cpp:144] Initialized hierarchical allocator process
I0129 19:54:21.064857 995 recover.cpp:193] Received a recover response from a replica in STARTING status
I0129 19:54:21.065428 993 recover.cpp:564] Updating replica status to VOTING
I0129 19:54:21.066047 988 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 345437ns
I0129 19:54:21.066095 988 replica.cpp:320] Persisted replica status to VOTING
I0129 19:54:21.066232 997 recover.cpp:578] Successfully joined the Paxos group
I0129 19:54:21.066498 997 recover.cpp:462] Recover process terminated
I0129 19:54:21.067276 1000 master.cpp:1710] The newly elected leader is master@172.17.0.4:43331 with id b243e52e-9f55-41b9-b06e-50b3a923c0cc
I0129 19:54:21.067314 1000 master.cpp:1723] Elected as the leading master!
I0129 19:54:21.067333 1000 master.cpp:1468] Recovering from registrar
I0129 19:54:21.067489 992 registrar.cpp:307] Recovering registrar
I0129 19:54:21.068238 997 log.cpp:659] Attempting to start the writer
I0129 19:54:21.069591 990 replica.cpp:493] Replica received implicit promise request from (14171)@172.17.0.4:43331 with proposal 1
I0129 19:54:21.070072 990 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 424525ns
I0129 19:54:21.070109 990 replica.cpp:342] Persisted promised to 1
I0129 19:54:21.070767 1002 coordinator.cpp:238] Coordinator attempting to fill missing positions
I0129 19:54:21.072166 989 replica.cpp:388] Replica received explicit promise request from (14172)@172.17.0.4:43331 for position 0 with proposal 2
I0129 19:54:21.072628 989 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 415641ns
I0129 19:54:21.072665 989 replica.cpp:712] Persisted action at 0
I0129 19:54:21.073884 990 replica.cpp:537] Replica received write request for position 0 from (14173)@172.17.0.4:43331
I0129 19:54:21.073947 990 leveldb.cpp:436] Reading position from leveldb took 28745ns
I0129 19:54:21.074362 990 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 369063ns
I0129 19:54:21.074393 990 replica.cpp:712] Persisted action at 0
I0129 19:54:21.075104 989 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
I0129 19:54:21.075639 989 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 499819ns
I0129 19:54:21.075670 989 replica.cpp:712] Persisted action at 0
I0129 19:54:21.075690 989 replica.cpp:697] Replica learned NOP action at position 0
I0129 19:54:21.076397 996 log.cpp:675] Writer started with ending position 0
I0129 19:54:21.077538 989 leveldb.cpp:436] Reading position from leveldb took 34957ns
I0129 19:54:21.078568 987 registrar.cpp:340] Successfully fetched the registry (0B) in 11.02208ms
I0129 19:54:21.078683 987 registrar.cpp:439] Applied 1 operations in 25939ns; attempting to update the 'registry'
I0129 19:54:21.079491 995 log.cpp:683] Attempting to append 170 bytes to the log
I0129 19:54:21.079700 993 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I0129 19:54:21.080508 1001 replica.cpp:537] Replica received write request for position 1 from (14174)@172.17.0.4:43331
I0129 19:54:21.080972 1001 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 419813ns
I0129 19:54:21.081003 1001 replica.cpp:712] Persisted action at 1
I0129 19:54:21.081830 987 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
I0129 19:54:21.082397 987 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 529118ns
I0129 19:54:21.082430 987 replica.cpp:712] Persisted action at 1
I0129 19:54:21.082453 987 replica.cpp:697] Replica learned APPEND action at position 1
I0129 19:54:21.083652 994 registrar.cpp:484] Successfully updated the 'registry' in 4.905984ms
I0129 19:54:21.083802 998 log.cpp:702] Attempting to truncate the log to 1
I0129 19:54:21.083818 994 registrar.cpp:370] Successfully recovered registrar
I0129 19:54:21.083952 996 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I0129 19:54:21.084503 997 master.cpp:1520] Recovered 0 slaves from the Registry (131B) ; allowing 10mins for slaves to re-register
I0129 19:54:21.084533 989 hierarchical.cpp:171] Skipping recovery of hierarchical allocator: nothing to recover
I0129 19:54:21.085273 1000 replica.cpp:537] Replica received write request for position 2 from (14175)@172.17.0.4:43331
I0129 19:54:21.085682 1000 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 360695ns
I0129 19:54:21.085714 1000 replica.cpp:712] Persisted action at 2
I0129 19:54:21.086357 1001 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
I0129 19:54:21.086802 1001 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 401808ns
I0129 19:54:21.086868 1001 leveldb.cpp:399] Deleting ~1 keys from leveldb took 33749ns
I0129 19:54:21.086892 1001 replica.cpp:712] Persisted action at 2
I0129 19:54:21.086916 1001 replica.cpp:697] Replica learned TRUNCATE action at position 2
I0129 19:54:21.095288 968 scheduler.cpp:154] Version: 0.28.0
I0129 19:54:21.096158 991 scheduler.cpp:236] New master detected at master@172.17.0.4:43331
I0129 19:54:21.097352 992 scheduler.cpp:298] Sending SUBSCRIBE call to master@172.17.0.4:43331
I0129 19:54:21.099517 994 process.cpp:3141] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0129 19:54:21.100302 989 http.cpp:503] HTTP POST for /master/api/v1/scheduler from 172.17.0.4:43933
I0129 19:54:21.100719 989 master.cpp:1972] Received subscription request for HTTP framework 'default'
I0129 19:54:21.100785 989 master.cpp:1749] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0129 19:54:21.101125 989 master.cpp:2063] Subscribing framework 'default' with checkpointing disabled and capabilities [ ]
I0129 19:54:21.101596 995 hierarchical.cpp:265] Added framework b243e52e-9f55-41b9-b06e-50b3a923c0cc-0000
I0129 19:54:21.101686 995 hierarchical.cpp:1403] No resources available to allocate!
I0129 19:54:21.101711 998 master.hpp:1658] Sending heartbeat to b243e52e-9f55-41b9-b06e-50b3a923c0cc-0000
I0129 19:54:21.101738 995 hierarchical.cpp:1498] No inverse offers to send out!
I0129 19:54:21.101778 995 hierarchical.cpp:1096] Performed allocation for 0 slaves in 145891ns
I0129 19:54:21.102943 1000 scheduler.cpp:457] Enqueuing event SUBSCRIBED received from master@172.17.0.4:43331
I0129 19:54:21.103565 1000 scheduler.cpp:457] Enqueuing event HEARTBEAT received from master@172.17.0.4:43331
I0129 19:54:21.104210 992 master_maintenance_tests.cpp:177] Ignoring HEARTBEAT event
I0129 19:54:21.104251 1000 scheduler.cpp:298] Sending REQUEST call to master@172.17.0.4:43331
I0129 19:54:21.106369 989 process.cpp:3141] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0129 19:54:21.106839 994 http.cpp:503] HTTP POST for /master/api/v1/scheduler from 172.17.0.4:43934
I0129 19:54:21.107141 994 master.cpp:2717] Processing REQUEST call for framework b243e52e-9f55-41b9-b06e-50b3a923c0cc-0000 (default)
I0129 19:54:21.107372 991 hierarchical.cpp:589] Received resource request from framework b243e52e-9f55-41b9-b06e-50b3a923c0cc-0000
I0129 19:54:21.107848 968 master.cpp:1025] Master terminating
I0129 19:54:21.108204 997 hierarchical.cpp:326] Removed framework b243e52e-9f55-41b9-b06e-50b3a923c0cc-0000
E0129 19:54:21.109509 1002 scheduler.cpp:431] End-Of-File received from master. The master closed the event stream
[ OK ] ContentType/SchedulerTest.Request/1 (62 ms)
[----------] 22 tests from ContentType/SchedulerTest (4333 ms total)
[----------] Global test environment tear-down
[==========] 962 tests from 126 test cases ran. (332256 ms total)
[ PASSED ] 961 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] ShasumTest.SHA512SimpleFile
1 FAILED TEST
YOU HAVE 8 DISABLED TESTS
make[4]: *** [check-local] Error 1
make[4]: Leaving directory `/mesos/mesos-0.28.0/_build/src'
make[3]: *** [check-am] Error 2
make[3]: Leaving directory `/mesos/mesos-0.28.0/_build/src'
make[2]: *** [check] Error 2
make[2]: Leaving directory `/mesos/mesos-0.28.0/_build/src'
make[1]: *** [check-recursive] Error 1
make[1]: Leaving directory `/mesos/mesos-0.28.0/_build'
make: *** [distcheck] Error 1
+ docker rmi mesos-1454095710-6030
Untagged: mesos-1454095710-6030:latest
Deleted: b6d8b4c2895ccb99b8d77c6df3c0ed7f6b0fa1aead3a964eab15e92c94433445
Deleted: d36c174e57bfc90842f1c558d8cfd526570015ff1a1649bcd126a8a73d6deec8
Deleted: 7e74ca567741fc858e64041f79dfcebc65fc591684257139348f8f6338a086c9
Deleted: 1b21cf106e48aa17da7d85ff46109cbbc1ca2bc986aadf646e1c72909383413f
Deleted: 3dcaf4af3ab92bc9bdf4299132605f40b1153134920b850147cccbdc37bdcbe4
Deleted: 2039ea0fbfb1f7fc8846fcc8e97d34c1e84cb70927854cfdd996119fafaebaf6
Deleted: ad07dd22ea2335e8437283db36dfdc558e0903224b6cd6ee48d4f3e90a4f255b
Deleted: c3a1ebf3db273d2f870b310370ad7f0b18ff07a70cad4c3c4081ccab9743a35b
Deleted: 9e084e093f4918f50ea880180910a3d7a0147ae16cd0c5d191acb7fa097af202
Deleted: 9a2ea74a778309e3473bfb3f4e655285ebaf89db8e66f7549a963e2440e8c34a
Deleted: b132a5a5e18f022316f29bd75e3677d758c6701b6b75f5287b4af74f9bb0a052
Deleted: 009b06b2ec08ce2e4f5d9596990769c8ff7a69295a6285dabb06bcd832d299be
Deleted: 30b3a9a4497ddf907a22bdfe59a567b3cc9a38b87622d55d9c99b16b4b5d5c91
Build step 'Execute shell' marked build as failure