x/build: plan9-386 builder fails

[bradfitz]

@0intro, what's doing on here?

/cc @bcmills @dmitshur

bradfitz@gdev:~/src/golang.org/x/build$ debugnewvm -host=host-plan9-386-gce -rev=6e9f664b9a68f2de84be9697c6ac851c7c7e1c26 -run-build=plan9-386
2019/01/17 22:00:47 Creating debug-temp-1547762447 (with VM image "plan9-386-v7")
2019/01/17 22:00:52 instance requested
2019/01/17 22:01:16 instance created
2019/01/17 22:01:16 got instance info
2019/01/17 22:01:16 About to hit http://10.240.0.4 to see if buildlet is up yet...
2019/01/17 22:01:16 SERIAL: SeaBIOS (version 1.8.2-20181112_143635-google)
                            Total RAM Size = 0x00000000e6600000 = 3686 MiB
                            CPUs found: 4     Max CPUs supported: 4
                            found virtio-scsi at 0:3
                            virtio-scsi vendor='Google' product='PersistentDisk' rev='1' type=0 removable=0
                            virtio-scsi blksize=512 sectors=20971520 = 10240 MiB
                            drive 0x000f29f0: PCHS=0/0/0 translation=lba LCHS=1024/255/63 s=20971520
                            Booting from Hard Disk 0...
                            pcirouting: BIOS workaround: PCI.0.1.3 at pin 1 link 96 irq 10 -> 9

                            no vga; serial console only
                             disk loader

                            cpu0:  2503MHz GenuineIntel P6 (cpuid: AX 0x306E4 DX 0x1F8BFBFF)
                            ELCR: 0C00
                            497M memory: 497M kernel data, 0M user, 18M swap
                            found partition #S/sd01/data 0 20,971,520
                            disks: sd01
                            trying sd01....found 9pccpuf
                            .1177998...............................................................................................................................................+2411120.......................................................................................................................................................................................................................................................................................................+488404=4077522
                            entry: 0xf0100020

                            Plan 9
                            E820: 00000000 0009fc00 memory
                            E820: 0009fc00 000a0000 reserved
                            E820: 000f0000 00100000 reserved
                            E820: 00100000 bfffd000 memory
                            E820: bfffd000 c0000000 reserved
                            E820: fffbc000 100000000 reserved
                            E820: 100000000 126600000 memory
                            cpu0:  2502MHz GenuineIntel P6 (cpuid: AX 0x306E4 DX 0x1F8BFBFF)
                            ELCR: 0C00
                            #l0: virtio: 1Gbps port 0xC040 irq 11: 42010af00004
                            3072M memory: 184M kernel data, 2887M user, 3512M swap
                            /boot/usbd: /dev/usb: no hubs
                            /boot/usbd: /dev/usb: no hubs
                            boot: can't open /srv/usb: '/srv/usb' file does not exist
                            time...
                            fossil(#S/sd01/fossil)...version...aux/randfs: '/bin/aux/randfs' does not exist
                            downloading git
....
....
2019/01/17 22:01:51 About to hit http://10.240.0.4 to see if buildlet is up yet...
2019/01/17 22:01:52 SERIAL: starting buildlet script
2019/01/17 22:01:52 About to hit http://10.240.0.4 to see if buildlet is up yet...
2019/01/17 22:01:52 client buildlet probe error: Get http://10.240.0.4: dial tcp 10.240.0.4:80: connect: connection refused
2019/01/17 22:01:53 SERIAL: 2019/01/17 17:01:51 buildlet starting.
                            2019/01/17 17:01:51 Will listen on :80
                            2019/01/17 17:01:51 Adjusted MTU.
                            2019/01/17 17:01:51 Listening on :80 ...
2019/01/17 22:01:53 About to hit http://10.240.0.4 to see if buildlet is up yet...
2019/01/17 22:01:53 buildlet probe: 200 OK
2019/01/17 22:01:53 WorkDir: /tmp/workdir, <nil>
2019/01/17 22:01:53 Pushing 'go1.4' Go bootstrap dir ...
2019/01/17 22:01:54 SERIAL: 2019/01/17 17:01:52 writetgz: untarring https://storage.googleapis.com/go-builder-data/gobootstrap-plan9-386.tar.gz (got heade
2019/01/17 22:02:02 Pushing 'go' dir...
2019/01/17 22:02:02 SERIAL: 2019/01/17 17:02:01 extracted tarball into /tmp/workdir/go1.4: 3521 files, 479 dirs (8.680247435s)
2019/01/17 22:02:04 SERIAL: 2019/01/17 17:02:02 writetgz: untarring https://go.googlesource.com/go/+archive/6e9f664b9a68f2de84be9697c6ac851c7c7e1c26.tar.g
2019/01/17 22:02:17 Running src/all.rc ...
:: Running /tmp/workdir/go/src/all.rc with args ["/tmp/workdir/go/src/all.rc"] and env ["terminal=generic /sys/src/9/pc/pccpuf" "cputype=386" "service=cpu" "bootfile=sd01!9fat!9pccpuf" "nobootprompt=local!#S/sd01/fossil" "bootargs=local!#S/sd01/fossil" "bootdisk=#S/sd01/fossil" "console=0 b115200" "dmamode=ask" "installurl=http://148.251.6.120/plan9/download" "partition=new" "mouseport=ps2intellimouse" "monitor=vesa" "vgasize=1280x1024x32" "user=glenda" "sd01part=plan9 63 20964825/9fat 63 204863/nvram 204863 204864/fossil 204864 19916249/swap 19916249 20964825" "rootdir=/root" "objtype=386" "timezone=EST -18000 EDT -14400\n   9943200   25664400   41392800   57718800   73447200   89168400\n 104896800  120618000  126669600  152067600  162352800  183517200\n 199245600  215571600  230695200  247021200  262749600  278470800\n 294199200  309920400  325648800  341370000  357098400  372819600\n 388548000  404874000  419997600  436323600  452052000  467773200\n 483501600  499222800  514951200  530672400  544586400  562122000\n 576036000  594176400  607485600  625626000  638935200  657075600\n 670989600  688525200  702439200  719974800  733888800  752029200\n 765338400  783478800  796788000  814928400  828842400  846378000\n 860292000  877827600  891741600  909277200  923191200  941331600\n 954640800  972781200  986090400 1004230800 1018144800 1035680400\n1049594400 1067130000 1081044000 1099184400 1112493600 1130634000\n1143943200 1162083600 1173578400 1194141600 1205028000 1225591200\n1236477600 1257040800 1268532000 1289095200 1299981600 1320544800\n1331431200 1351994400 1362880800 1383444000 1394330400 1414893600\n1425780000 1446343200 1457834400 1478397600 1489284000 1509847200\n1520733600 1541296800 1552183200 1572746400 1583632800 1604196000\n1615687200 1636250400 1647136800 1667700000 1678586400 1699149600\n1710036000 1730599200 1741485600 1762048800 1772935200 1793498400\n1804989600 1825552800 1836439200 1857002400 1867888800 1888452000\n1899338400 1919901600 1930788000 1951351200 1962842400 1983405600\n1994292000 2014855200 2025741600 2046304800 2057191200 2077754400\n2088640800 2109204000 2120090400 2140653600\n" "home=/usr/glenda" "path=.\x00/bin" "*=" "rcname=rc" "pid=111" "ifs= \t\n" "prompt=helix# \x00\t" "status=" "fn#sigexit=" "cflag=" "0=/rc/lib/rcmain" "boottime=Thu Jan 17 17:01:07 EST 2019\n" "sysname=helix" "NPROC=1" "site=DOM.EXAMPLE.COM" "fileserver=kfs" "facedom=FACEDOM" "apid=102" "GOROOT_BOOTSTRAP=/tmp/workdir/go1.4" "WORKDIR=/tmp/workdir" "GO_BUILDER_NAME=plan9-386" "GO_TEST_TIMEOUT_SCALE=2"] in dir /tmp/workdir/go/src

Building Go cmd/dist using /tmp/workdir/go1.4
2019/01/17 22:02:18 SERIAL: 2019/01/17 17:02:16 extracted tarball into /tmp/workdir/go: 8560 files, 1062 dirs (13.428815549s)
                            2019/01/17 17:02:16 writetgz: untarring Request.Body into /tmp/workdir/go
                            2019/01/17 17:02:16 extracted tarball into /tmp/workdir/go: 1 files, 1 dirs (3.462171ms)
                            2019/01/17 17:02:16 [0x108188f0] Running /tmp/workdir/go/src/all.rc with args ["/tmp/workdir/go/src/all.rc"] and env ["termina


Building Go toolchain1 using /tmp/workdir/go1.4.
Building Go bootstrap cmd/go (go_bootstrap) using Go toolchain1.
Building Go toolchain2 using go_bootstrap and Go toolchain1.
Building Go toolchain3 using go_bootstrap and Go toolchain2.
Building packages and commands for plan9/386.

##### Testing packages.
ok      archive/tar     0.130s
ok      archive/zip     2.249s
ok      bufio   0.158s
ok      bytes   2.061s
ok      compress/bzip2  0.109s
ok      compress/flate  1.457s
ok      compress/gzip   7.835s
ok      compress/lzw    0.145s
ok      compress/zlib   0.768s
ok      container/heap  0.047s


ok      container/list  0.041s
ok      container/ring  0.049s
ok      context 1.147s
ok      crypto  0.041s
ok      crypto/aes      0.065s
ok      crypto/cipher   27.555s
ok      crypto/des      0.059s
ok      crypto/dsa      0.044s
ok      crypto/ecdsa    0.235s
ok      crypto/elliptic 0.070s
ok      crypto/hmac     0.038s
ok      crypto/internal/subtle  0.039s
ok      crypto/md5      0.049s
ok      crypto/rand     0.299s
ok      crypto/rc4      0.090s
ok      crypto/rsa      0.198s
ok      crypto/sha1     0.099s
ok      crypto/sha256   0.050s
ok      crypto/sha512   0.051s
ok      crypto/subtle   0.045s
ok      crypto/tls      14.012s
ok      crypto/x509     6.525s
ok      database/sql    0.770s
ok      database/sql/driver     0.039s
ok      debug/dwarf     0.091s
ok      debug/elf       0.111s
ok      debug/gosym     0.040s
ok      debug/macho     0.045s
ok      debug/pe        0.055s
ok      debug/plan9obj  0.040s
ok      encoding/ascii85        0.043s
ok      encoding/asn1   0.052s
ok      encoding/base32 0.071s
ok      encoding/base64 0.047s
ok      encoding/binary 0.045s
ok      encoding/csv    0.047s
ok      encoding/gob    0.077s
ok      encoding/hex    0.043s
ok      encoding/json   0.571s
ok      encoding/pem    0.057s
ok      encoding/xml    0.108s
ok      errors  0.038s
ok      expvar  0.053s
ok      flag    0.042s
ok      fmt     0.114s
ok      go/ast  0.064s
ok      go/build        2.111s
ok      go/constant     0.047s
ok      go/doc  0.117s
ok      go/format       0.054s
ok      go/importer     0.861s
ok      go/internal/gccgoimporter       0.079s
ok      go/internal/gcimporter  6.813s
ok      go/internal/srcimporter 4.114s
ok      go/parser       0.065s
ok      go/printer      0.326s
ok      go/scanner      0.045s
ok      go/token        0.062s
ok      go/types        5.103s
ok      hash    0.043s
ok      hash/adler32    0.050s
ok      hash/crc32      0.051s
ok      hash/crc64      0.041s
ok      hash/fnv        0.042s
ok      html    0.043s
2019/01/17 22:20:49 SERIAL: 5902 template.test: checked 2245 page table entries
                            5902 template.test: checked 2247 page table entries
                            5902 template.test: checked 2247 page table entries
                            5902 template.test: checked 2247 page table entries
                            5902 template.test: checked 2251 page table entries
                            5902 template.test: checked 2251 page table entries
                            5902 template.test: checked 2251 page table entries
                            5902 template.test: checked 2251 page table entries
                            5902 template.test: checked 2253 page table entries
                            5902 template.test: checked 2253 page table entries
                            5902 template.test: checked 2256 page table entries
                            5902 template.test: checked 2256 page table entries
                            5902 template.test: checked 2256 page table entries
                            5902 template.test: checked 2256 page table entries
                            5902 template.test: checked 2256 page table entries
                            5902 template.test: checked 2256 page table entries
                            5902 template.test: checked 2257 page table entries
                            5902 template.test: checked 2257 page table entries
                            5902 template.test: c
ok      html/template   0.240s
2019/01/17 22:20:49 SERIAL: hecked 2257 page table entries
                            5902 template.test: checked 2257 page table entries
                            5902 template.test: checked 2258 page table entries
                            5902 template.test: checked 2258 page table entries
                            5902 template.test: checked 2258 page table entries
                            5902 template.test: checked 2258 page table entries
                            5902 template.test: checked 2260 page table entries
                            5902 template.test: checked 2260 page table entries
                            5902 template.test: checked 2266 page table entries
                            5902 template.test: checked 2266 page table entries
                            5902 template.test: checked 2310 page table entries
                            5902 template.test: checked 2312 page table entries
ok      image   0.118s
ok      image/color     0.057s
ok      image/draw      0.095s
ok      image/gif       0.948s
ok      image/jpeg      0.251s
ok      image/png       0.099s
ok      index/suffixarray       0.042s
ok      internal/cpu    0.041s
ok      internal/fmtsort        0.041s
ok      internal/poll   0.074s
ok      internal/singleflight   0.050s
ok      internal/trace  2.602s
ok      internal/x/crypto/chacha20poly1305      8.636s
ok      internal/x/crypto/cryptobyte    0.060s
2019/01/17 22:22:09 SERIAL: 6431 cryptobyte.test: checked 1392 page table entries
ok      internal/x/crypto/curve25519    0.177s
ok      internal/x/crypto/hkdf  0.845s
ok      internal/x/crypto/internal/chacha20     0.144s
ok      internal/x/crypto/poly1305      0.054s
ok      internal/x/net/dns/dnsmessage   0.185s
ok      internal/x/net/http/httpguts    0.042s
ok      internal/x/net/http/httpproxy   0.109s
2019/01/17 22:22:26 SERIAL: 6562 httpproxy.test: checked 1360 page table entries
                            6562 httpproxy.test: checked 1361 page table entries
                            6562 httpproxy.test: checked 1361 page table entries
                            6562 httpproxy.test: checked 1361 page table entries
                            6562 httpproxy.test: checked 1361 page table entries
                            6562 httpproxy.test: checked 1361 page table entries
                            6562 httpproxy.test: checked 1363 page table entries
                            6562 httpproxy.test: checked 1363 page table entries
ok      internal/x/net/http2/hpack      0.076s
ok      internal/x/net/idna     0.044s
ok      internal/x/net/nettest  9.947s
ok      internal/x/text/transform       0.045s
ok      internal/x/text/unicode/norm    0.043s
ok      internal/xcoff  0.168s
ok      io      0.206s
ok      io/ioutil       10.703s
ok      log     0.053s
ok      math    0.060s
ok      math/big        2.184s
ok      math/bits       0.048s
ok      math/cmplx      0.042s
ok      math/rand       0.668s
ok      mime    0.047s
ok      mime/multipart  2.525s
ok      mime/quotedprintable    0.420s
ok      net     28.558s
2019/01/17 22:25:56 SERIAL: 8008 http.test: checked 3947 page table entries
                            8008 http.test: checked 3947 page table entries
                            8008 http.test: checked 3947 page table entries
                            8008 http.test: checked 3948 page table entries
                            8008 http.test: checked 3948 page table entries
                            8008 http.test: checked 3948 page table entries
                            8008 http.test: checked 3948 page table entries
                            8008 http.test: checked 3948 page table entries
ok      net/http        143.781s
ok      net/http/cgi    0.263s
ok      net/http/cookiejar      0.240s
ok      net/http/fcgi   0.070s
ok      net/http/httptest       2.314s
ok      net/http/httptrace      0.056s
ok      net/http/httputil       4.702s
ok      net/http/internal       0.043s
ok      net/http/pprof  2.089s
ok      net/mail        0.053s
ok      net/rpc 1.706s
ok      net/rpc/jsonrpc 0.069s
ok      net/smtp        1.060s
ok      net/textproto   0.043s
ok      net/url 0.056s
ok      os      2.706s
ok      os/exec 2.556s
ok      os/signal       0.199s
ok      os/user 0.047s
ok      path    0.044s
ok      path/filepath   0.343s
ok      plugin  0.040s
ok      reflect 0.266s
2019/01/17 22:30:28 SERIAL: 8794 reflect.test: checked 2508 page table entries
                            8794 reflect.test: checked 2509 page table entries
                            8794 reflect.test: checked 2860 page table entries
ok      regexp  0.123s
ok      regexp/syntax   0.391s
2019/01/17 22:31:25 SERIAL: 9108 testprog.exe: checked 1257 page table entries
                            9110 testprog.exe: checked 1262 page table entries
                            9110 testprog.exe: checked 1264 page table entries
                            9108 testprog.exe: checked 1264 page table entries
2019/01/17 22:31:27 SERIAL: 9076 runtime.test: checked 3427 page table entries
2019/01/17 22:31:32 SERIAL: 9073 runtime.test: checked 6386 page table entries
                            9073 runtime.test: checked 6387 page table entries
                            9073 runtime.test: checked 6387 page table entries
                            9073 runtime.test: checked 6387 page table entries
                            9073 runtime.test: checked 6387 page table entries
                            9073 runtime.test: checked 6387 page table entries
                            9073 runtime.test: checked 6387 page table entries
                            9073 runtime.test: checked 6387 page table entries
                            9073 runtime.test: checked 6387 page table entries
                            9073 runtime.test: checked 6387 page table entries
                            9073 runtime.test: checked 6387 page table entries
                            9073 runtime.test: checked 6387 page table entries
                            9073 runtime.test: checked 6387 page table entries
                            9073 runtime.test: checked 6387 page table entries
                            9073 runtime.test: checked 6387 page table entries
                            9073 runtime.test: checked 6387 page table entries
                            9073 runtime.test: checked 6387 page table entries
                            9073 runtime.test: checked 6387 page table entries
2019/01/17 22:31:35 SERIAL: 9073 runtime.test: checked 6405 page table entries
                            9076 runtime.test: checked 6410 page table entries
                            9076 runtime.test: checked 6412 page table entries
ok      runtime 55.642s
ok      runtime/debug   0.055s
ok      runtime/internal/atomic 0.125s
2019/01/17 22:32:18 SERIAL: 9322 atomic.test: checked 1372 page table entries
                            9322 atomic.test: checked 1373 page table entries
                            9322 atomic.test: checked 1373 page table entries
                            9322 atomic.test: checked 1373 page table entries
                            9322 atomic.test: checked 1373 page table entries
                            9322 atomic.test: checked 1373 page table entries
ok      runtime/internal/math   0.039s
ok      runtime/internal/sys    0.046s
ok      runtime/pprof   2.239s
ok      runtime/pprof/internal/profile  0.045s
ok      runtime/trace   43.480s
ok      sort    0.106s
ok      strconv 0.460s
2019/01/17 22:34:25 serial output error: googleapi: Error 400: The resource 'projects/symbolic-datum-552/zones/us-central1-f/instances/debug-temp-1547762447' is not ready, resourceNotReady
2019/01/17 22:34:35 Buildlet http://10.240.0.4 failed three heartbeats; final error: timeout waiting for headers
2019/01/17 22:34:35 error trying to run src/all.rc: Buildlet http://10.240.0.4 failed heartbeat after 10.000362883s; marking dead; err=timeout waiting for headers
bradfitz@gdev:~/src/golang.org/x/build$

[gopherbot]

Change https://golang.org/cl/158537 mentions this issue: dashboard: increase plan9's GO_TEST_TIMEOUT_SCALE

[dmitshur]

I'm not sure if it's related to this issue, or a separate issue, but there haven't been any plan9 builder results for any of the subrepos recently. I.e., https://build.golang.org/?repo=golang.org%2fx%2ftools has no entries for plan9/386, despite the configuration suggesting there should be:

https://github.com/golang/build/blob/0261b66eb04541491e09bffe4a6d212f9a76675b/dashboard/builders.go#L881

This came up in CL 162907. /cc @rhysh

[0intro]

Yes, there is currently an issue happening on the plan9/386 builder. It started on 2019-02-01 approximately. I'll investigate.

[bradfitz]

What's the status here? I haven't seen a plan9/386 build pass in a long time.

[0intro]

I'm currently investigating an issue with the runtime/trace test running out of memory on the plan9/amd64 builder.

The issue on the plan9/386 builder is different. I've not been able to reproduce it yet, since it runs successfully on my 386 machines at home. I'll have to try on GCE.

There was something very odd on the plan9/386 builder during the past few months. The builder started to fail in early February, then after 4 weeks of failure, the tests passed successfully in early March during 8 days, then it started to fail again.

[bradfitz]

I'm going to have to stop the plan9 builders. It's a waste of resources & distracting to have them always building and resulting in crashes, loops, timeouts, or other failures.

[0intro]

Could you try to disable the runtime/trace tests? It may be the same issue I'm currently encountering on plan9/amd64.

[0intro]

After a few more tests, it seems unlikely that the issue may be caused by the runtime/trace test. I'm suspecting something else. Please hang on.