Bug 1384225

Summary: stack traces in node logs
Product: OpenShift Container Platform Reporter: Luke Meyer <lmeyer>
Component: NodeAssignee: Seth Jennings <sjenning>
Status: CLOSED CURRENTRELEASE QA Contact: Xiaoli Tian <xtian>
Severity: low Docs Contact:
Priority: medium    
Version: 3.2.0CC: aos-bugs, decarr, gblomqui, jokerman, mmccomas
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2019-07-03 15:21:25 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Description Luke Meyer 2016-10-12 21:02:39 UTC 
Description of problem:

This is from a customer's node logs. The node eventually failed in an interesting way, but it was much later and likely unrelated to this found in the logs. After stripping away all the uninteresting stuff that repeats in the node logs, I found this stack trace randomly thrown in there:

goroutine 10747176 [running]:
k8s.io/kubernetes/pkg/httplog.(*respLogger).recordStatus(0xc20a7a7c70, 0x190)
/builddir/build/BUILD/atomic-openshift-git-0.9fe156c/_thirdpartyhacks/src/k8s.io/kubernetes/pkg/httplog/log.go:214 +0xa6 fp=0xc20bf97048 sp=0xc20bf96ff8
k8s.io/kubernetes/pkg/httplog.(*respLogger).WriteHeader(0xc20a7a7c70, 0x190)
/builddir/build/BUILD/atomic-openshift-git-0.9fe156c/_thirdpartyhacks/src/k8s.io/kubernetes/pkg/httplog/log.go:193 +0x32 fp=0xc20bf97070 sp=0xc20bf97048
github.com/emicklei/go-restful.(*Response).WriteHeader(0xc209300600, 0x190)
/builddir/build/BUILD/atomic-openshift-git-0.9fe156c/_thirdpartyhacks/src/github.com/emicklei/go-restful/response.go:191 +0x48 fp=0xc20bf97098 sp=0xc20bf97070
github.com/emicklei/go-restful.(*Response).WriteErrorString(0xc209300600, 0x190, 0xc20aab4ea0, 0x2a, 0x0, 0x0)
/builddir/build/BUILD/atomic-openshift-git-0.9fe156c/_thirdpartyhacks/src/github.com/emicklei/go-restful/response.go:180 +0x128 fp=0xc20bf97110 sp=0xc20bf97098
github.com/emicklei/go-restful.(*Response).WriteError(0xc209300600, 0x190, 0x7f23af1e7a80, 0xc20d338640, 0x0, 0x0)
/builddir/build/BUILD/atomic-openshift-git-0.9fe156c/_thirdpartyhacks/src/github.com/emicklei/go-restful/response.go:165 +0xa8 fp=0xc20bf97158 sp=0xc20bf97110
k8s.io/kubernetes/pkg/kubelet/server.(*Server).getContainerLogs(0xc20b8100c0, 0xc20af78300, 0xc209300600)
/builddir/build/BUILD/atomic-openshift-git-0.9fe156c/_thirdpartyhacks/src/k8s.io/kubernetes/pkg/kubelet/server/server.go:474 +0x13aa fp=0xc20bf97698 sp=0xc20bf97158
k8s.io/kubernetes/pkg/kubelet/server.*Server.(k8s.io/kubernetes/pkg/kubelet/server.getContainerLogs)·fm(0xc20af78300, 0xc209300600)
/builddir/build/BUILD/atomic-openshift-git-0.9fe156c/_thirdpartyhacks/src/k8s.io/kubernetes/pkg/kubelet/server/server.go:334 +0x3b fp=0xc20bf976b8 sp=0xc20bf97698
github.com/emicklei/go-restful.func·009(0xc20af78300, 0xc209300600)
/builddir/build/BUILD/atomic-openshift-git-0.9fe156c/_thirdpartyhacks/src/github.com/emicklei/go-restful/container.go:244 +0x41 fp=0x [[Go 1.1 package http] 10.204.89.210:35525]
goroutine 10733115 [running]:
k8s.io/kubernetes/pkg/httplog.(*respLogger).recordStatus(0xc209e045b0, 0x190)
/builddir/build/BUILD/atomic-openshift-git-0.9fe156c/_thirdpartyhacks/src/k8s.io/kubernetes/pkg/httplog/log.go:214 +0xa6 fp=0xc20ddb3048 sp=0xc20ddb2ff8
k8s.io/kubernetes/pkg/httplog.(*respLogger).WriteHeader(0xc209e045b0, 0x190)
/builddir/build/BUILD/atomic-openshift-git-0.9fe156c/_thirdpartyhacks/src/k8s.io/kubernetes/pkg/httplog/log.go:193 +0x32 fp=0xc20ddb3070 sp=0xc20ddb3048
github.com/emicklei/go-restful.(*Response).WriteHeader(0xc20d4a2cc0, 0x190)
/builddir/build/BUILD/atomic-openshift-git-0.9fe156c/_thirdpartyhacks/src/github.com/emicklei/go-restful/response.go:191 +0x48 fp=0xc20ddb3098 sp=0xc20ddb3070
github.com/emicklei/go-restful.(*Response).WriteErrorString(0xc20d4a2cc0, 0x190, 0xc20ad779b0, 0x2a, 0x0, 0x0)
/builddir/build/BUILD/atomic-openshift-git-0.9fe156c/_thirdpartyhacks/src/github.com/emicklei/go-restful/response.go:180 +0x128 fp=0xc20ddb3110 sp=0xc20ddb3098
github.com/emicklei/go-restful.(*Response).WriteError(0xc20d4a2cc0, 0x190, 0x7f23af1e7a80, 0xc20ba4c340, 0x0, 0x0)
/builddir/build/BUILD/atomic-openshift-git-0.9fe156c/_thirdpartyhacks/src/github.com/emicklei/go-restful/response.go:165 +0xa8 fp=0xc20ddb3158 sp=0xc20ddb3110
k8s.io/kubernetes/pkg/kubelet/server.(*Server).getContainerLogs(0xc20b8100c0, 0xc20b1e2060, 0xc20d4a2cc0)
/builddir/build/BUILD/atomic-openshift-git-0.9fe156c/_thirdpartyhacks/src/k8s.io/kubernetes/pkg/kubelet/server/server.go:474 +0x13aa fp=0xc20ddb3698 sp=0xc20ddb3158
k8s.io/kubernetes/pkg/kubelet/server.*Server.(k8s.io/kubernetes/pkg/kubelet/server.getContainerLogs)·fm(0xc20b1e2060, 0xc20d4a2cc0)
/builddir/build/BUILD/atomic-openshift-git-0.9fe156c/_thirdpartyhacks/src/k8s.io/kubernetes/pkg/kubelet/server/server.go:334 +0x3b fp=0xc20ddb36b8 sp=0xc20ddb3698
github.com/emicklei/go-restful.func·009(0xc20b1e2060, 0xc20d4a2cc0)
/builddir/build/BUILD/atomic-openshift-git-0.9fe156c/_thirdpartyhacks/src/github.com/emicklei/go-restful/container.go:244 +0x41 fp=0x [[Go 1.1 package http] 10.204.89.210:35280]


It seems to me that stack traces in logs have to mean *something* went wrong. I would appreciate someone smarter looking at this to see if it indicates anything helpful.
Comment 1 Luke Meyer 2016-10-13 17:32:42 UTC 
I guess I should add some context that's filtered out here... each stack trace is actually a continuation of a log line such as this one:

server.go:1100] GET /containerLogs/servicegateway-ofsprod/api-3-2do6k/api?follow=true&limitBytes=10485760&tailLines=1000: (9h11m52.950080139s) 400

I think all this is doing is logging a stack trace when there's an error condition, I'm not sure at what point. It's alarming to see in the logs though.
Comment 3 Avesh Agarwal 2016-10-20 13:09:15 UTC 
Derek, sure, will look into it today.
Comment 4 Avesh Agarwal 2016-10-21 18:01:54 UTC 
The stack trace is being logger for error http.StatusBadRequest(400, x190), and it is happening because ServeHTTP in pkg/kubelet/server/server.go sets a customer strack trace predictor than the default one used in pkg/httplog/log.go.
Comment 5 Avesh Agarwal 2016-10-21 18:11:33 UTC 
Sent https://github.com/kubernetes/kubernetes/pull/35312 to kube upstream.
Comment 6 Derek Carr 2016-10-25 20:17:55 UTC 
Reducing severity, this will be picked up in a future rebase once Avesh's PR merges.
Comment 9 Greg Blomquist 2019-07-03 15:21:25 UTC 
Upstream PR merged 3 years ago