Skip to content

gcplogs logging driver segfaults (static binary only) #29344

@AkihiroSuda

Description

@AkihiroSuda

Description

gcplogs logging driver segfaults

Dec 13 05:33:40 ws01 dockerd[11417]: fatal error: unexpected signal during runtime execution                                                                                                                                                                                                                        [1908/6690]
Dec 13 05:33:40 ws01 dockerd[11417]: [signal SIGSEGV: segmentation violation code=0x1 addr=0xe5 pc=0x7fa5502d43f8]
Dec 13 05:33:40 ws01 dockerd[11417]: runtime stack:
Dec 13 05:33:40 ws01 dockerd[11417]: runtime.throw(0x19aa803, 0x2a)
Dec 13 05:33:40 ws01 dockerd[11417]:         /usr/local/go/src/runtime/panic.go:566 +0x95
Dec 13 05:33:40 ws01 dockerd[11417]: runtime.sigpanic()
Dec 13 05:33:40 ws01 dockerd[11417]:         /usr/local/go/src/runtime/sigpanic_unix.go:12 +0x2cc
Dec 13 05:33:40 ws01 dockerd[11417]: goroutine 2428 [syscall, locked to thread]:
Dec 13 05:33:40 ws01 dockerd[11417]: runtime.cgocall(0x14d9760, 0xc421f5e108, 0x0)
Dec 13 05:33:40 ws01 dockerd[11417]:         /usr/local/go/src/runtime/cgocall.go:131 +0x110 fp=0xc421f5e0b8 sp=0xc421f5e078
Dec 13 05:33:40 ws01 dockerd[11417]: os/user._Cfunc_mygetpwuid_r(0x0, 0xc4209dccf0, 0x7fa4b80008c0, 0x400, 0xc424d4fba8, 0x0)
Dec 13 05:33:40 ws01 dockerd[11417]:         ??:0 +0x4d fp=0xc421f5e108 sp=0xc421f5e0b8
Dec 13 05:33:40 ws01 dockerd[11417]: os/user.lookupUnixUid.func1(0x436ca3)
Dec 13 05:33:40 ws01 dockerd[11417]:         /usr/local/go/src/os/user/lookup_unix.go:103 +0x1f7 fp=0xc421f5e198 sp=0xc421f5e108
Dec 13 05:33:40 ws01 dockerd[11417]: os/user.retryWithBuffer(0xc426ebb1c0, 0xc421f5e290, 0xc426ebb1c0, 0x1691480)
Dec 13 05:33:40 ws01 dockerd[11417]:         /usr/local/go/src/os/user/lookup_unix.go:253 +0x2b fp=0xc421f5e200 sp=0xc421f5e198
Dec 13 05:33:40 ws01 dockerd[11417]: os/user.lookupUnixUid(0x0, 0x0, 0x0, 0x0)
Dec 13 05:33:40 ws01 dockerd[11417]:         /usr/local/go/src/os/user/lookup_unix.go:105 +0x141 fp=0xc421f5e2c8 sp=0xc421f5e200
Dec 13 05:33:40 ws01 dockerd[11417]: os/user.current(0xc421f5e350, 0x74ef9d, 0x2531960)
Dec 13 05:33:40 ws01 dockerd[11417]:         /usr/local/go/src/os/user/lookup_unix.go:49 +0x2f fp=0xc421f5e2f8 sp=0xc421f5e2c8
Dec 13 05:33:40 ws01 dockerd[11417]: os/user.Current(0xc4214a7f20, 0xc421f5e350, 0x461ca0)
Dec 13 05:33:40 ws01 dockerd[11417]:         /usr/local/go/src/os/user/lookup.go:9 +0x22 fp=0xc421f5e320 sp=0xc421f5e2f8
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/vendor/golang.org/x/oauth2/google.guessUnixHomeDir(0x2531950, 0xc42000c1b0)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/vendor/golang.org/x/oauth2/google/sdk.go:163 +0x22 fp=0xc421f5e350 sp=0xc421f5e320
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/vendor/golang.org/x/oauth2/google.wellKnownFile(0x199198f, 0x1e)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/vendor/golang.org/x/oauth2/google/default.go:107 +0x26 fp=0xc421f5e3c8 sp=0xc421f5e350
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/vendor/golang.org/x/oauth2/google.DefaultTokenSource(0x24e18c0, 0xc420010d60, 0xc426ebb1b0, 0x1, 0x1, 0x41db65, 0xc426ebb1a0, 0x10, 0x10)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/vendor/golang.org/x/oauth2/google/default.go:72 +0x254 fp=0xc421f5e508 sp=0xc421f5e3c8
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/vendor/google.golang.org/cloud/internal/transport.NewHTTPClient(0x24e18c0, 0xc420010d60, 0xc421f5e690, 0x3, 0x3, 0x0, 0x0, 0x0, 0x43bdc0, 0x7fa55499f000)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/vendor/google.golang.org/cloud/internal/transport/dial.go:64 +0x19f fp=0xc421f5e5a0 sp=0xc421f5e508
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/vendor/google.golang.org/cloud/logging.NewClient(0x24e18c0, 0xc420010d60, 0xc42382c927, 0x9, 0x1981b3b, 0x15, 0x0, 0x0, 0x0, 0x2507ea0, ...)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/vendor/google.golang.org/cloud/logging/logging.go:441 +0x275 fp=0xc421f5e6d0 sp=0xc421f5e5a0
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/daemon/logger/gcplogs.New(0xc420a8a0c0, 0xc424123340, 0x40, 0xc420abfdd0, 0x10, 0xc420abf538, 0x4, 0xc424122590, 0x1, 0x3, ...)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/daemon/logger/gcplogs/gcplogging.go:117 +0x174 fp=0xc421f5e7d0 sp=0xc421f5e6d0
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/container.(*Container).StartLogger(0xc421f30000, 0x1, 0xc421ca5ea0, 0x6a, 0xc421f5ea30)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/container/container.go:352 +0x259 fp=0xc421f5e9d8 sp=0xc421f5e7d0
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/container.(*Container).startLogging(0xc421f30000, 0x74e010, 0xc42054ce60)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/container/container.go:1054 +0x59 fp=0xc421f5ea98 sp=0xc421f5e9d8
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/container.(*Container).InitializeStdio(0xc421f30000, 0x24d2d00, 0xc421ee2de0, 0x7fa55057a638, 0xc4228840c0, 0x7fa55057a638, 0xc422884240, 0x0, 0xc42054ce60, 0xc42038ae10)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/container/container.go:1094 +0x2f fp=0xc421f5eb08 sp=0xc421f5ea98
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/container.(*Container).InitializeStdio-fm(0x24d2d00, 0xc421ee2de0, 0x7fa55057a638, 0xc4228840c0, 0x7fa55057a638, 0xc422884240, 0x0, 0x4, 0x0)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/daemon/daemon.go:205 +0x51 fp=0xc421f5eb68 sp=0xc421f5eb08
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/libcontainerd.(*container).start(0xc42038ae10, 0x0, 0x0, 0xc421ca4fc0, 0x67, 0xc4209d5f30, 0x0, 0x0)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/libcontainerd/container_unix.go:150 +0x61d fp=0xc421f5ecc0 sp=0xc421f5eb68
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/libcontainerd.(*client).Create(0xc42054ce40, 0xc424123340, 0x40, 0x0, 0x0, 0xc421ca4fc0, 0x67, 0xc42034ebf0, 0xd, 0x1963466, ...)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/libcontainerd/client_unix.go:87 +0x5f7 fp=0xc421f5f140 sp=0xc421f5ecc0
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/daemon.(*Daemon).containerStart(0xc4201541e0, 0xc421f30000, 0x0, 0x0, 0xc421ca4fc0, 0x67, 0x1, 0x0, 0x0)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/daemon/start.go:167 +0x482 fp=0xc421f5f400 sp=0xc421f5f140
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/daemon.(*Daemon).ContainerStart(0xc4201541e0, 0xc426c67cf7, 0x40, 0x0, 0x0, 0x0, 0x0, 0x0, 0x24b3a10, 0x1)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/daemon/start.go:87 +0x1f7 fp=0xc421f5f4c0 sp=0xc421f5f400
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/api/server/router/container.(*containerRouter).postContainersStart(0xc4240ac0c0, 0x24e1940, 0xc420abd2f0, 0x24de0c0, 0xc423d909c0, 0xc4204542d0, 0xc4214a7d10, 0x196255a, 0x4)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/api/server/router/container/container_routes.go:159 +0x304 fp=0xc421f5f568 sp=0xc421f5f4c0
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/api/server/router/container.(*containerRouter).(github.com/docker/docker/api/server/router/container.postContainersStart)-fm(0x24e1940, 0xc420abd2f0, 0x24de0c0, 0xc423d909c0, 0xc4204542d0, 0xc4214a7d10, 0x41d098, 0x30)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/api/server/router/container/container.go:60 +0x69 fp=0xc421f5f5c0 sp=0xc421f5f568
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/api/server/middleware.ExperimentalMiddleware.WrapHandler.func1(0x24e1940, 0xc420abd2f0, 0x24de0c0, 0xc423d909c0, 0xc4204542d0, 0xc4214a7d10, 0x19, 0xe0ff5cb400000004)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/api/server/middleware/experimental.go:27 +0xd8 fp=0xc421f5f628 sp=0xc421f5f5c0
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/api/server/middleware.VersionMiddleware.WrapHandler.func1(0x24e1940, 0xc4214a7da0, 0x24de0c0, 0xc423d909c0, 0xc4204542d0, 0xc4214a7d10, 0xc4227fbad0, 0x8)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/api/server/middleware/version.go:47 +0x5ca fp=0xc421f5f778 sp=0xc421f5f628
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/pkg/authorization.(*Middleware).WrapHandler.func1(0x24e1940, 0xc4214a7da0, 0x24de0c0, 0xc423d909c0, 0xc4204542d0, 0xc4214a7d10, 0x756ea13b22f725, 0xc421f5f998)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/pkg/authorization/middleware.go:43 +0x83f fp=0xc421f5f928 sp=0xc421f5f778
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/api/server/middleware.DebugRequestMiddleware.func1(0x24e1940, 0xc4214a7da0, 0x24de0c0, 0xc423d909c0, 0xc4204542d0, 0xc4214a7d10, 0xc421f5fae0, 0x74f09b)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/api/server/middleware/debug.go:25 +0x9bf fp=0xc421f5fa88 sp=0xc421f5f928
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/api/server.(*Server).makeHTTPHandler.func1(0x24de0c0, 0xc423d909c0, 0xc4204542d0)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/api/server/server.go:139 +0x233 fp=0xc421f5fb80 sp=0xc421f5fa88
Dec 13 05:33:40 ws01 dockerd[11417]: net/http.HandlerFunc.ServeHTTP(0xc4244481c0, 0x24de0c0, 0xc423d909c0, 0xc4204542d0)
Dec 13 05:33:40 ws01 dockerd[11417]:         /usr/local/go/src/net/http/server.go:1726 +0x44 fp=0xc421f5fba8 sp=0xc421f5fb80
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/vendor/github.com/gorilla/mux.(*Router).ServeHTTP(0xc423c9def0, 0x24de0c0, 0xc423d909c0, 0xc4204542d0)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/vendor/github.com/gorilla/mux/mux.go:103 +0x255 fp=0xc421f5fc98 sp=0xc421f5fba8
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/api/server.(*routerSwapper).ServeHTTP(0xc424a73d10, 0x24de0c0, 0xc423d909c0, 0xc4204542d0)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/api/server/router_swapper.go:29 +0x70 fp=0xc421f5fcd0 sp=0xc421f5fc98
Dec 13 05:33:40 ws01 dockerd[11417]: net/http.serverHandler.ServeHTTP(0xc42005e680, 0x24de0c0, 0xc423d909c0, 0xc4204542d0)
Dec 13 05:33:40 ws01 dockerd[11417]:         /usr/local/go/src/net/http/server.go:2202 +0x7d fp=0xc421f5fd18 sp=0xc421f5fcd0
Dec 13 05:33:40 ws01 dockerd[11417]: net/http.(*conn).serve(0xc422907080, 0x24dfd00, 0xc424122380)
Dec 13 05:33:40 ws01 dockerd[11417]:         /usr/local/go/src/net/http/server.go:1579 +0x4b7 fp=0xc421f5ff78 sp=0xc421f5fd18
Dec 13 05:33:40 ws01 dockerd[11417]: runtime.goexit()
Dec 13 05:33:40 ws01 dockerd[11417]:         /usr/local/go/src/runtime/asm_amd64.s:2086 +0x1 fp=0xc421f5ff80 sp=0xc421f5ff78
Dec 13 05:33:40 ws01 dockerd[11417]: created by net/http.(*Server).Serve
Dec 13 05:33:40 ws01 dockerd[11417]:         /usr/local/go/src/net/http/server.go:2293 +0x44d
Dec 13 05:33:40 ws01 dockerd[11417]: goroutine 1 [chan receive]:
Dec 13 05:33:40 ws01 dockerd[11417]: main.(*DaemonCli).start(0xc4204db050, 0x0, 0x19844a0, 0x17, 0xc420304000, 0xc420012820, 0xc42040c360, 0x0, 0x0)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/cmd/dockerd/daemon.go:327 +0x183e
Dec 13 05:33:40 ws01 dockerd[11417]: main.runDaemon(0x0, 0x19844a0, 0x17, 0xc420304000, 0xc420012820, 0xc42040c360, 0x2, 0x0)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/cmd/dockerd/docker.go:86 +0xb2
Dec 13 05:33:40 ws01 dockerd[11417]: main.newDaemonCommand.func1(0xc42008a240, 0xc42041afa0, 0x0, 0x2, 0x0, 0x0)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/cmd/dockerd/docker.go:42 +0x71
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/vendor/github.com/spf13/cobra.(*Command).execute(0xc42008a240, 0xc42000c220, 0x2, 0x2, 0xc42008a240, 0xc42000c220)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/vendor/github.com/spf13/cobra/command.go:646 +0x26d
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/vendor/github.com/spf13/cobra.(*Command).ExecuteC(0xc42008a240, 0x1775da0, 0xc420012801, 0xc420478410)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/vendor/github.com/spf13/cobra/command.go:742 +0x377
Dec 13 05:33:40 ws01 dockerd[11417]: github.com/docker/docker/vendor/github.com/spf13/cobra.(*Command).Execute(0xc42008a240, 0xc420478410, 0xc42000e0b8)
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/vendor/github.com/spf13/cobra/command.go:695 +0x2b
Dec 13 05:33:40 ws01 dockerd[11417]: main.main()
Dec 13 05:33:40 ws01 dockerd[11417]:         /go/src/github.com/docker/docker/cmd/dockerd/docker.go:106 +0xe2

Steps to reproduce the issue:

Do docker run --rm --log-driver=gcplogs busybox echo hello twice.
The first run succeeds (and I can see the {"data": "hello"} entry in GCP console), but the second run leads to segv.

Describe the results you received:
Segfaults (see above)

Describe the results you expected:
It should not segfault

Additional information you deem important (e.g. issue happens only occasionally):

Output of docker version:

Client:
 Version:      1.14.0-dev
 API version:  1.26
 Go version:   go1.7.4
 Git commit:   e9076c0
 Built:        Tue Dec 13 05:29:39 2016
 OS/Arch:      linux/amd64

Server:
 Version:      1.14.0-dev
 API version:  1.26 (minimum version 1.12)
 Go version:   go1.7.4
 Git commit:   e9076c0
 Built:        Tue Dec 13 05:29:39 2016
 OS/Arch:      linux/amd64
 Experimental: true

Output of docker info:

Containers: 0
 Running: 0
 Paused: 0
 Stopped: 0
Images: 145
Server Version: 1.14.0-dev
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 macvlan null overlay
Swarm: active
 NodeID: ksij9f8dllodu0meynoyqhcdm
 Is Manager: true
 ClusterID: xarapgd5fodpwxxfoj1ah98z2
 Managers: 1
 Nodes: 1
 Orchestration:
  Task History Retention Limit: 5
 Raft:
  Snapshot Interval: 10000
  Number of Old Snapshots to Retain: 0
  Heartbeat Tick: 1
  Election Tick: 3
 Dispatcher:
  Heartbeat Period: 5 seconds
 CA Configuration:
  Expiry Duration: 3 months
 Node Address: 10.146.0.2
 Manager Addresses:
  10.146.0.2:2377
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: 03e5862ec0d8d3b3f750e19fca3ee367e13c090e
runc version: 51371867a01c467f08af739783b8beafc154c4d7
init version: 949e6fa
Security Options:
 apparmor
 seccomp
  Profile: default
Kernel Version: 4.4.0-53-generic
Operating System: Ubuntu 16.04.1 LTS
OSType: linux
Architecture: x86_64
CPUs: 4
Total Memory: 14.69 GiB
Name: ws01
ID: SN3T:CNK6:JKQD:54CY:XKF2:BRX3:CIRU:DQBT:6DVZ:VWQ2:Q5ET:F23L
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): true
 File Descriptors: 32
 Goroutines: 122
 System Time: 2016-12-13T05:39:08.742538732Z
 EventsListeners: 0
Registry: https://index.docker.io/v1/
WARNING: No swap limit support
Experimental: true
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: false

Additional environment details (AWS, VirtualBox, physical, etc.):
GCP, using default credential

Metadata

Metadata

Assignees

No one assigned

    Labels

    area/loggingkind/bugBugs are bugs. The cause may or may not be known at triage time so debugging may be needed.version/master

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions