Infinite loop fetching google/protobuf when building gazelle since overlay rules

[steeve]

Hi,

Since d36234e, when trying to run gazelle, bazel 0.10.1 is stuck into an infinite loop when trying to fetch golang/tools/zip.

Even trying to run the following becomes an infinite loop:

$ bazel query --noimplicit_deps 'deps(//:gazelle)' --output graph

WORKSPACE

git_repository(
    name = "io_bazel_rules_go",
    remote = "https://github.com/bazelbuild/rules_go.git",
    commit = "d36234e86678457e769ab62e597f90eef025bf8d"
)

load("@io_bazel_rules_go//go:def.bzl", "go_rules_dependencies", "go_register_toolchains")
go_rules_dependencies()
go_register_toolchains(go_version="host")

load("@bazel_gazelle//:deps.bzl", "gazelle_dependencies")
gazelle_dependencies()

[jayconrod]

I couldn't reproduce this using the command and WORKSPACE file you posted. Is there any other configuration information (bazelrc files and such) you have locally that might affect this?

$ bazel query --noimplicit_deps 'deps(//:gazelle)' --output graph
____Cloning https://github.com/bazelbuild/bazel-skylib: remote: Counting objects (0 / 0)
____Loading package: @bazel_gazelle//internal/repos
____Loading package: @org_golang_x_tools//cmd/goyacc
____Loading package: @go_sdk//
____Loading package: @io_bazel_rules_go//go/platform
digraph mygraph {
  node [shape=box];
"//:gazelle"
"//:gazelle" -> "//:WORKSPACE"
"//:WORKSPACE"
}

[teran]

I have the same issue since the same commit but for

    Fetching https://codeload.github.com/golang/tools/zip/5d2fd3ccab986d52112bf301d47a819783339d0e; 2,365,530b

Trying to gather more details and any kind of correlation.

[teh-cmc]

I'm experiencing the exact same as @teran, i.e. running bazel run //:gazelle in a very small repository fetches https://codeload.github.com/golang/tools/zip time and times again, until it finally succeeds (it does succeed eventually).

$ bazel clean --expunge
$ time bazel run //:gazelle --curses=no
...........
Loading:
Loading: 0 packages loaded
Loading: 0 packages loaded
    currently loading:
Analyzing: target //:gazelle (1 packages loaded)
Analyzing: target //:gazelle (4 packages loaded)
Analyzing: target //:gazelle (4 packages loaded)
Analyzing: target //:gazelle (19 packages loaded)
Analyzing: target //:gazelle (29 packages loaded) // looping on https://codeload.github.com/golang/tools/zip/5d2fd3ccab986d52112bf301d47a819783339d0e
Analyzing: target //:gazelle (29 packages loaded) // looping on https://codeload.github.com/golang/tools/zip/5d2fd3ccab986d52112bf301d47a819783339d0e
Analyzing: target //:gazelle (29 packages loaded) // looping on https://codeload.github.com/golang/tools/zip/5d2fd3ccab986d52112bf301d47a819783339d0e
Analyzing: target //:gazelle (29 packages loaded) // looping on https://codeload.github.com/golang/tools/zip/5d2fd3ccab986d52112bf301d47a819783339d0e
Analyzing: target //:gazelle (29 packages loaded) // looping on https://codeload.github.com/golang/tools/zip/5d2fd3ccab986d52112bf301d47a819783339d0e
Analyzing: target //:gazelle (29 packages loaded) // looping on https://codeload.github.com/golang/tools/zip/5d2fd3ccab986d52112bf301d47a819783339d0e
Analyzing: target //:gazelle (32 packages loaded) // looping on https://codeload.github.com/golang/tools/zip/5d2fd3ccab986d52112bf301d47a819783339d0e
Analyzing: target //:gazelle (32 packages loaded) // looping on https://codeload.github.com/golang/tools/zip/5d2fd3ccab986d52112bf301d47a819783339d0e
Analyzing: target //:gazelle (32 packages loaded) // looping on https://codeload.github.com/golang/tools/zip/5d2fd3ccab986d52112bf301d47a819783339d0e
Analyzing: target //:gazelle (32 packages loaded) // looping on https://codeload.github.com/golang/tools/zip/5d2fd3ccab986d52112bf301d47a819783339d0e
Analyzing: target //:gazelle (32 packages loaded) // looping on https://codeload.github.com/golang/tools/zip/5d2fd3ccab986d52112bf301d47a819783339d0e
Analyzing: target //:gazelle (32 packages loaded) // looping on https://codeload.github.com/golang/tools/zip/5d2fd3ccab986d52112bf301d47a819783339d0e
Analyzing: target //:gazelle (32 packages loaded) // looping on https://codeload.github.com/golang/tools/zip/5d2fd3ccab986d52112bf301d47a819783339d0e
Analyzing: target //:gazelle (32 packages loaded) // looping on https://codeload.github.com/golang/tools/zip/5d2fd3ccab986d52112bf301d47a819783339d0e
Analyzing: target //:gazelle (32 packages loaded) // looping on https://codeload.github.com/golang/tools/zip/5d2fd3ccab986d52112bf301d47a819783339d0e
Analyzing: target //:gazelle (32 packages loaded) // looping on https://codeload.github.com/golang/tools/zip/5d2fd3ccab986d52112bf301d47a819783339d0e
Analyzing: target //:gazelle (32 packages loaded) // looping on https://codeload.github.com/golang/tools/zip/5d2fd3ccab986d52112bf301d47a819783339d0e
Analyzing: target //:gazelle (32 packages loaded) // looping on https://codeload.github.com/golang/tools/zip/5d2fd3ccab986d52112bf301d47a819783339d0e
INFO: Analysed target //:gazelle (34 packages loaded).
INFO: Found 1 target...
[0 / 7] [-----] BazelWorkspaceStatusAction stable-status.txt
Target //:gazelle up-to-date:
  bazel-bin/gazelle.bash
INFO: Elapsed time: 201.040s, Critical Path: 15.58s
INFO: Build completed successfully, 40 total actions

INFO: Running command line: bazel-bin/gazelle.bash -bazel_run

real	3m22.479s
user	0m0.102s
sys 	0m0.065s

Computing the dependency graph is extremely slow too:

$ bazel clean --expunge
$ time bazel query --noimplicit_deps 'deps(//:gazelle)' --output graph
digraph mygraph {
  node [shape=box];
"//:gazelle"
"//:gazelle" -> "//:WORKSPACE"
"//:WORKSPACE"
}

real	2m3.454s
user	0m0.102s
sys 	0m0.058s

I've set up a reproduction environment:

$ git clone git@github.com:znly/bazel-fork-listen.git && cd bazel-fork-listen
$ bazel clean --expunge
$ bazel run //:gazelle

[steeve]

Here is the graph with implicit deps on @teh-cmc's repo, which took a more than 2 minutes to generate on my MBP15. I was trying to look for loops in it.

https://gist.github.com/steeve/2764badd46c8d100c868c8e81c0e94b0

[steeve]

$ bazel version
Build label: 0.10.1-homebrew
Build target: bazel-out/darwin-opt/bin/src/main/java/com/google/devtools/build/lib/bazel/BazelServer_deploy.jar
Build time: Tue Oct 11 20:06:37 +50095 (1518702897997)
Build timestamp: 1518702897997
Build timestamp as int: 1518702897997

$ bazel info
bazel-bin: /private/var/tmp/_bazel_steeve/9a05d5449b4cc06b9fd1d4ef060916a1/execroot/__main__/bazel-out/darwin-fastbuild/bin
bazel-genfiles: /private/var/tmp/_bazel_steeve/9a05d5449b4cc06b9fd1d4ef060916a1/execroot/__main__/bazel-out/darwin-fastbuild/genfiles
bazel-testlogs: /private/var/tmp/_bazel_steeve/9a05d5449b4cc06b9fd1d4ef060916a1/execroot/__main__/bazel-out/darwin-fastbuild/testlogs
character-encoding: file.encoding = ISO-8859-1, defaultCharset = ISO-8859-1
command_log: /private/var/tmp/_bazel_steeve/9a05d5449b4cc06b9fd1d4ef060916a1/command.log
committed-heap-size: 441MB
execution_root: /private/var/tmp/_bazel_steeve/9a05d5449b4cc06b9fd1d4ef060916a1/execroot/__main__
gc-count: 25
gc-time: 666ms
install_base: /var/tmp/_bazel_steeve/install/42ec9bf9ba80badd8a741014843f8655
java-home: /Library/Java/JavaVirtualMachines/jdk1.8.0_151.jdk/Contents/Home/jre
java-runtime: Java(TM) SE Runtime Environment (build 1.8.0_151-b12) by Oracle Corporation
java-vm: Java HotSpot(TM) 64-Bit Server VM (build 25.151-b12, mixed mode) by Oracle Corporation
max-heap-size: 3817MB
message_log: /private/var/tmp/_bazel_steeve/9a05d5449b4cc06b9fd1d4ef060916a1/message.log
output_base: /private/var/tmp/_bazel_steeve/9a05d5449b4cc06b9fd1d4ef060916a1
output_path: /private/var/tmp/_bazel_steeve/9a05d5449b4cc06b9fd1d4ef060916a1/execroot/__main__/bazel-out
package_path: %workspace%
release: release 0.10.1-homebrew
server_pid: 24938
used-heap-size: 141MB
workspace: /Users/steeve/go/src/github.com/znly/bazel-fork-listen

[jayconrod]

I think I saw this happen last night when running bazel test //... in rules_go. It got stuck in loading for several minutes. System monitor showed a lot of CPU activity and regular "pulses" of download activity. It does seem like it's trying and failing to load something. It did get there eventually though.

Will investigate.

[steeve]

I just had it running bazel test //... in rules_go too.

[jmhodges]

Yep, just hit this, too. Same Fetching https://codeload.github.com/golang/tools/zip/5d2fd3ccab986d52112bf301d47a819783339d0e; thing, too.

[evie404]

it seems like something is restarting the the download before it is done, but given some chance, it will finish eventually. for me it ended up taking about seven minutes to build gazelle, but subsequent runes will be ok since gazelle is cached.

$ bazel run //:gazelle
INFO: Analysed target //:gazelle (21 packages loaded).
INFO: Found 1 target...
Target //:gazelle up-to-date:
  bazel-bin/gazelle.bash
INFO: Elapsed time: 464.877s, Critical Path: 20.24s
INFO: Build completed successfully, 25 total actions

INFO: Running command line: bazel-bin/gazelle.bash -bazel_run

combinations where this is present:
bazel 0.10.1 + rules_go 0.10.0 + gazelle 0.9
bazel 0.10.1 + rules_go 0.10.0 + gazelle HEAD

combinations where this isn't present:
bazel 0.10.1 + rules_go 0.9.0 + gazelle 0.9
bazel 0.10.0 + rules_go 0.9.0 + gazelle 0.9

[jayconrod]

I'm pretty sure #1349 fixes this, but Bazel doesn't provide any useful hook to test or debug this.

Repository rule restart behavior makes it unfortunately very easy to accidentally download more than once.

[evie404]

#1349 worked for me. thanks a lot!