docker build prints fatal error (MSpanList_Insert) on macOS 10.13.1

[epong]

Description

When I run docker build, I see an error trace, widely cited as a bug in go for binaries running on macOS Sierra/High Sierra built with older versions of go.

I've installed the latest stable and edge versions of docker-ce, and the error still shows up.

The docker build actually continues to run and builds an image, but this error trace is printed every time and breaks some of our custom build tools.

Here is the trace:

failed MSpanList_Insert 0x4384000 0x13f987be9a8d 0x0 0x0
fatal error: MSpanList_Insert

runtime stack:
runtime.throw(0x4164a40, 0x10)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/panic.go:530 +0x90 fp=0x7ffeefbfeee0 sp=0x7ffeefbfeec8
runtime.(*mSpanList).insert(0x420eea8, 0x4384000)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/mheap.go:933 +0x293 fp=0x7ffeefbfef10 sp=0x7ffeefbfeee0
runtime.(*mheap).freeSpanLocked(0x420e6a0, 0x4384000, 0x100, 0x0)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/mheap.go:809 +0x4be fp=0x7ffeefbfef78 sp=0x7ffeefbfef10
runtime.(*mheap).grow(0x420e6a0, 0x8, 0x0)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/mheap.go:675 +0x2a0 fp=0x7ffeefbfefd0 sp=0x7ffeefbfef78
runtime.(*mheap).allocSpanLocked(0x420e6a0, 0x1, 0x0)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/mheap.go:553 +0x4e3 fp=0x7ffeefbff028 sp=0x7ffeefbfefd0
runtime.(*mheap).alloc_m(0x420e6a0, 0x1, 0x15, 0x0)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/mheap.go:437 +0x119 fp=0x7ffeefbff058 sp=0x7ffeefbff028
runtime.(*mheap).alloc.func1()
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/mheap.go:502 +0x41 fp=0x7ffeefbff088 sp=0x7ffeefbff058
runtime.systemstack(0x7ffeefbff0a8)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/asm_amd64.s:307 +0xab fp=0x7ffeefbff090 sp=0x7ffeefbff088
runtime.(*mheap).alloc(0x420e6a0, 0x1, 0x10000000015, 0x400ebdf)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/mheap.go:503 +0x63 fp=0x7ffeefbff0d8 sp=0x7ffeefbff090
runtime.(*mcentral).grow(0x42102a0, 0x0)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/mcentral.go:209 +0x93 fp=0x7ffeefbff140 sp=0x7ffeefbff0d8
runtime.(*mcentral).cacheSpan(0x42102a0, 0x420b2c8)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/mcentral.go:89 +0x47d fp=0x7ffeefbff180 sp=0x7ffeefbff140
runtime.(*mcache).refill(0x4380000, 0x15, 0x7ffeefbff1e8)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/mcache.go:119 +0xcc fp=0x7ffeefbff1b8 sp=0x7ffeefbff180
runtime.mallocgc.func2()
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/malloc.go:642 +0x2b fp=0x7ffeefbff1d8 sp=0x7ffeefbff1b8
runtime.systemstack(0x7ffeefbff278)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/asm_amd64.s:307 +0xab fp=0x7ffeefbff1e0 sp=0x7ffeefbff1d8
runtime.mallocgc(0x180, 0x4147ac0, 0x0, 0x800000000)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/malloc.go:643 +0x869 fp=0x7ffeefbff2b8 sp=0x7ffeefbff1e0
runtime.newobject(0x4147ac0, 0x420b570)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/malloc.go:781 +0x42 fp=0x7ffeefbff2e0 sp=0x7ffeefbff2b8
runtime.malg(0x8000, 0x420b7e0)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/proc.go:2634 +0x27 fp=0x7ffeefbff318 sp=0x7ffeefbff2e0
runtime.mpreinit(0x420bb20)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/os1_darwin.go:140 +0x1f fp=0x7ffeefbff330 sp=0x7ffeefbff318
runtime.mcommoninit(0x420bb20)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/proc.go:494 +0x105 fp=0x7ffeefbff378 sp=0x7ffeefbff330
runtime.schedinit()
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/proc.go:434 +0x79 fp=0x7ffeefbff3c0 sp=0x7ffeefbff378
runtime.rt0_go(0x7ffeefbff400, 0x2, 0x7ffeefbff400, 0x0, 0x7fff6b629145, 0x0, 0x2, 0x7ffeefbff620, 0x7ffeefbff63e, 0x0, ...)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/asm_amd64.s:138 +0x132 fp=0x7ffeefbff3c8 sp=0x7ffeefbff3c0`

I suspect docker-cli builds are using travis, and the travis configuration is using go 1.6?

Steps to reproduce the issue:

1. On macOS 10.13.1, install latest docker-ce
2. Run docker build on any Dockerfile

Describe the results you received:
Image is built with error cited above.

Describe the results you expected:
Built image with no errors.

Additional information you deem important (e.g. issue happens only occasionally):
Don't think this is relevant, but local go version: go version go1.9.2 darwin/amd64
macOS version: 10.13.1

Output of docker version:

Client:
 Version:      17.11.0-ce-rc2
 API version:  1.34
 Go version:   go1.8.4
 Git commit:   d7062e5
 Built:        Wed Nov  1 22:08:25 2017
 OS/Arch:      darwin/amd64

Server:
 Version:      17.11.0-ce-rc2
 API version:  1.34 (minimum version 1.12)
 Go version:   go1.8.5
 Git commit:   d7062e5
 Built:        Wed Nov  1 22:14:52 2017
 OS/Arch:      linux/amd64
 Experimental: true

Output of docker info:

Containers: 0
 Running: 0
 Paused: 0
 Stopped: 0
Images: 0
Server Version: 17.11.0-ce-rc2
Storage Driver: overlay2
 Backing Filesystem: extfs
 Supports d_type: true
 Native Overlay Diff: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
 Volume: local
 Network: bridge host ipvlan macvlan null overlay
 Log: awslogs fluentd gcplogs gelf journald json-file logentries splunk syslog
Swarm: inactive
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: v1.0.0-beta.2-53-g992280e8 (expected: 992280e8e265f491f7a624ab82f3e238be086e49)
runc version: 0351df1c5a66838d0c392b4ac4cf9450de844e2d
init version: 949e6fa
Security Options:
 seccomp
  Profile: default
Kernel Version: 4.9.44-linuxkit-aufs
Operating System: Docker for Mac
OSType: linux
Architecture: x86_64
CPUs: 4
Total Memory: 1.952GiB
Name: linuxkit-025000000001
ID: RHBG:F5GU:YWGH:FVEG:2HXI:PELW:SS7Y:LZ5Y:MGGY:U5CC:5TLG:QZV4
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): true
 File Descriptors: 21
 Goroutines: 40
 System Time: 2017-11-08T02:26:18.595260676Z
 EventsListeners: 2
No Proxy: *.local, 169.254/16
Registry: https://index.docker.io/v1/
Experimental: true
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: false

[dnephin]

I don't think this is a bug in the docker cli. docker/cli does not use travis, it is built with go1.8, and nothing in that stack trace is from this repo.

I'm going to close this issue since it doesn't seem to be related, but please continue to comment if you have more information.

[epong]

Yes, I suspect the trace is from the golang library, but by whichever binary is built with go 1.6.

Any guess as to which process might be causing this error or how I can identify the process? Might build be spawning some other process?

We don't use travis either, this docker is run from a rather plain shell environment, and this trace only shows up with docker build. Notably, other docker commands run without error (e.g. version, start, run, stop, rm, etc.).

[dnephin]

I can't really guess without knowing more about the context. Is docker build called from a script? Maybe run with bash -x ? Do you have a log that includes some of the build output and the command you ran?

[epong]

You can ignore that this happened in our build process. This trace shows up when directly running docker build for any Dockerfile on [my] macOS 10.13. bash -x indicates all that's running is docker build:

$ docker build .
+ docker build .
failed MSpanList_Insert 0x4384000 0x37718b8d7e83 0x0 0x0
fatal error: MSpanList_Insert

runtime stack:
runtime.throw(0x4164a40, 0x10)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/panic.go:530 +0x90 fp=0x7ffeefbfefc0 sp=0x7ffeefbfefa8
runtime.(*mSpanList).insert(0x420eea8, 0x4384000)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/mheap.go:933 +0x293 fp=0x7ffeefbfeff0 sp=0x7ffeefbfefc0
runtime.(*mheap).freeSpanLocked(0x420e6a0, 0x4384000, 0x100, 0x0)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/mheap.go:809 +0x4be fp=0x7ffeefbff058 sp=0x7ffeefbfeff0
runtime.(*mheap).grow(0x420e6a0, 0x8, 0x0)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/mheap.go:675 +0x2a0 fp=0x7ffeefbff0b0 sp=0x7ffeefbff058
runtime.(*mheap).allocSpanLocked(0x420e6a0, 0x1, 0x0)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/mheap.go:553 +0x4e3 fp=0x7ffeefbff108 sp=0x7ffeefbff0b0
runtime.(*mheap).alloc_m(0x420e6a0, 0x1, 0x15, 0x0)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/mheap.go:437 +0x119 fp=0x7ffeefbff138 sp=0x7ffeefbff108
runtime.(*mheap).alloc.func1()
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/mheap.go:502 +0x41 fp=0x7ffeefbff168 sp=0x7ffeefbff138
runtime.systemstack(0x7ffeefbff188)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/asm_amd64.s:307 +0xab fp=0x7ffeefbff170 sp=0x7ffeefbff168
runtime.(*mheap).alloc(0x420e6a0, 0x1, 0x10000000015, 0x400ebdf)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/mheap.go:503 +0x63 fp=0x7ffeefbff1b8 sp=0x7ffeefbff170
runtime.(*mcentral).grow(0x42102a0, 0x0)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/mcentral.go:209 +0x93 fp=0x7ffeefbff220 sp=0x7ffeefbff1b8
runtime.(*mcentral).cacheSpan(0x42102a0, 0x420b2c8)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/mcentral.go:89 +0x47d fp=0x7ffeefbff260 sp=0x7ffeefbff220
runtime.(*mcache).refill(0x4380000, 0x15, 0x7ffeefbff2c8)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/mcache.go:119 +0xcc fp=0x7ffeefbff298 sp=0x7ffeefbff260
runtime.mallocgc.func2()
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/malloc.go:642 +0x2b fp=0x7ffeefbff2b8 sp=0x7ffeefbff298
runtime.systemstack(0x7ffeefbff358)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/asm_amd64.s:307 +0xab fp=0x7ffeefbff2c0 sp=0x7ffeefbff2b8
runtime.mallocgc(0x180, 0x4147ac0, 0x0, 0x800000000)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/malloc.go:643 +0x869 fp=0x7ffeefbff398 sp=0x7ffeefbff2c0
runtime.newobject(0x4147ac0, 0x420b570)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/malloc.go:781 +0x42 fp=0x7ffeefbff3c0 sp=0x7ffeefbff398
runtime.malg(0x8000, 0x420b7e0)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/proc.go:2634 +0x27 fp=0x7ffeefbff3f8 sp=0x7ffeefbff3c0
runtime.mpreinit(0x420bb20)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/os1_darwin.go:140 +0x1f fp=0x7ffeefbff410 sp=0x7ffeefbff3f8
runtime.mcommoninit(0x420bb20)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/proc.go:494 +0x105 fp=0x7ffeefbff458 sp=0x7ffeefbff410
runtime.schedinit()
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/proc.go:434 +0x79 fp=0x7ffeefbff4a0 sp=0x7ffeefbff458
runtime.rt0_go(0x7ffeefbff4e8, 0x2, 0x7ffeefbff4e8, 0x0, 0x7fff6b629145, 0x7fff6b629145, 0x0, 0x2, 0x7ffeefbff6e0, 0x7ffeefbff6fe, ...)
	/Users/travis/.gimme/versions/go1.6.darwin.amd64/src/runtime/asm_amd64.s:138 +0x132 fp=0x7ffeefbff4a8 sp=0x7ffeefbff4a0
Sending build context to Docker daemon  3.365MB
...

And it goes on from there building the actual image.

FWIW, /Users/travis/.gimme/versions/go1.6.darwin.amd64/ is not a path on my or any of our build machines.

And even with an essentially empty Dockerfile:

FROM busybox

I see the same behavior. Very odd.

[dnephin]

Please include the output of docker version, docker info, and alias | grep docker, and how docker was installed (Docker for Mac?)

[epong]

This is largely the same as from my initial post. I've just downgraded to the latest stable, from edge, but the behavior is the same on both versions:

docker version:

Client:
 Version:      17.09.0-ce
 API version:  1.32
 Go version:   go1.8.3
 Git commit:   afdb6d4
 Built:        Tue Sep 26 22:40:09 2017
 OS/Arch:      darwin/amd64

Server:
 Version:      17.09.0-ce
 API version:  1.32 (minimum version 1.12)
 Go version:   go1.8.3
 Git commit:   afdb6d4
 Built:        Tue Sep 26 22:45:38 2017
 OS/Arch:      linux/amd64
 Experimental: true

docker info:

Containers: 0
 Running: 0
 Paused: 0
 Stopped: 0
Images: 0
Server Version: 17.09.0-ce
Storage Driver: overlay2
 Backing Filesystem: extfs
 Supports d_type: true
 Native Overlay Diff: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
 Volume: local
 Network: bridge host ipvlan macvlan null overlay
 Log: awslogs fluentd gcplogs gelf journald json-file logentries splunk syslog
Swarm: inactive
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: 06b9cb35161009dcb7123345749fef02f7cea8e0
runc version: 3f2f8b84a77f73d38244dd690525642a72156c64
init version: 949e6fa
Security Options:
 seccomp
  Profile: default
Kernel Version: 4.9.49-moby
Operating System: Alpine Linux v3.5
OSType: linux
Architecture: x86_64
CPUs: 4
Total Memory: 1.952GiB
Name: moby
ID: W6IS:QADP:HWKN:FC4Q:AX3A:NEKN:B6ZX:NPND:7MPG:HHZ4:XMBO:3DYF
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): true
 File Descriptors: 18
 Goroutines: 29
 System Time: 2017-11-08T21:27:38.669242692Z
 EventsListeners: 1
No Proxy: *.local, 169.254/16
Registry: https://index.docker.io/v1/
Experimental: true
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: false

alias | grep docker:

d=docker
dc=docker-compose
dm=docker-machine

[epong]

Got it: I had an old docker credential helper (osxkeychain) binary in my $PATH, which docker build silently picks up (https://github.com/docker/docker-credential-helpers). They've already updated their travis config to use go 1.7/1.8 earlier this year (docker/docker-credential-helpers@5651367#diff-354f30a63fb0907d4ad57269548329e30), so there's nothing left to do here (unless you want to change whether these helpers are reported in something like docker info, which I recommend).

Thanks, @dnephin, for helping me look into this.