Skip to content

Commit

Permalink
Merge pull request #4714 from ardaguclu/use-internal-logging
Browse files Browse the repository at this point in the history 
Use internal logging when context available
  • Loading branch information
@openshift-merge-robot
openshift-merge-robot committed Apr 9, 2021
2 parents aab1c9a + 975ffc6 commit 8118d4a
Show file tree
Hide file tree
Showing 9 changed files with 162 additions and 140 deletions.
36 changes: 18 additions & 18 deletions cmd/crio/main.go
View file
Expand Up @@ -63,22 +63,22 @@ func catchShutdown(ctx context.Context, cancel context.CancelFunc, gserver *grpc
case unix.SIGPIPE:
continue
case signals.Interrupt:
logrus.Debugf("Caught SIGINT")
log.Debugf(ctx, "Caught SIGINT")
case signals.Term:
logrus.Debugf("Caught SIGTERM")
log.Debugf(ctx, "Caught SIGTERM")
default:
continue
}
*signalled = true
gserver.GracefulStop()
hserver.Shutdown(ctx) // nolint: errcheck
if err := sserver.StopStreamServer(); err != nil {
logrus.Warnf("error shutting down streaming server: %v", err)
log.Warnf(ctx, "error shutting down streaming server: %v", err)
}
sserver.StopMonitors()
cancel()
if err := sserver.Shutdown(ctx); err != nil {
logrus.Warnf("error shutting down main service %v", err)
log.Warnf(ctx, "error shutting down main service %v", err)
}
return
}
Expand Down Expand Up @@ -185,9 +185,9 @@ func main() {
profilePort := c.Int("profile-port")
profileEndpoint := fmt.Sprintf("localhost:%v", profilePort)
go func() {
logrus.Debugf("starting profiling server on %v", profileEndpoint)
log.Debugf(ctx, "starting profiling server on %v", profileEndpoint)
if err := http.ListenAndServe(profileEndpoint, nil); err != nil {
logrus.Fatalf("unable to run profiling server: %v", err)
log.Fatalf(ctx, "unable to run profiling server: %v", err)
}
}()
}
Expand All @@ -211,7 +211,7 @@ func main() {

lis, err := server.Listen("unix", config.Listen)
if err != nil {
logrus.Fatalf("failed to listen: %v", err)
log.Fatalf(ctx, "failed to listen: %v", err)
}

grpcServer := grpc.NewServer(
Expand Down Expand Up @@ -254,13 +254,13 @@ func main() {
// CleanShutdownFile.
f, err := os.Create(config.CleanShutdownSupportedFileName())
if err != nil {
logrus.Errorf("Writing clean shutdown supported file: %v", err)
log.Errorf(ctx, "Writing clean shutdown supported file: %v", err)
}
f.Close()

// and sync the changes to disk
if err := utils.SyncParent(config.CleanShutdownFile); err != nil {
logrus.Errorf("failed to sync parent directory of clean shutdown file: %v", err)
log.Errorf(ctx, "failed to sync parent directory of clean shutdown file: %v", err)
}
}

Expand Down Expand Up @@ -300,12 +300,12 @@ func main() {

go func() {
if err := grpcServer.Serve(grpcL); err != nil {
logrus.Errorf("unable to run GRPC server: %v", err)
log.Errorf(ctx, "unable to run GRPC server: %v", err)
}
}()
go func() {
if err := httpServer.Serve(httpL); err != nil {
logrus.Debugf("closed http server")
log.Debugf(ctx, "closed http server")
}
}()

Expand All @@ -316,7 +316,7 @@ func main() {
if graceful && strings.Contains(strings.ToLower(err.Error()), "use of closed network connection") {
err = nil
} else {
logrus.Errorf("Failed to serve grpc request: %v", err)
log.Errorf(ctx, "Failed to serve grpc request: %v", err)
}
}
}()
Expand All @@ -330,22 +330,22 @@ func main() {
}

if err := crioServer.Shutdown(ctx); err != nil {
logrus.Warnf("error shutting down service: %v", err)
log.Warnf(ctx, "error shutting down service: %v", err)
}
cancel()

<-streamServerCloseCh
logrus.Debug("closed stream server")
log.Debugf(ctx, "closed stream server")
<-serverMonitorsCh
logrus.Debug("closed monitors")
log.Debugf(ctx, "closed monitors")
err = <-hookSync
if err == nil || err == context.Canceled {
logrus.Debug("closed hook monitor")
log.Debugf(ctx, "closed hook monitor")
} else {
logrus.Errorf("hook monitor failed: %v", err)
log.Errorf(ctx, "hook monitor failed: %v", err)
}
<-serverCloseCh
logrus.Debug("closed main server")
log.Debugf(ctx, "closed main server")

return nil
}
Expand Down
7 changes: 4 additions & 3 deletions internal/lib/container_server.go
View file
Expand Up @@ -15,6 +15,7 @@ import (
"github.com/containers/storage/pkg/truncindex"
"github.com/cri-o/cri-o/internal/hostport"
"github.com/cri-o/cri-o/internal/lib/sandbox"
"github.com/cri-o/cri-o/internal/log"
"github.com/cri-o/cri-o/internal/oci"
"github.com/cri-o/cri-o/internal/storage"
crioann "github.com/cri-o/cri-o/pkg/annotations"
Expand Down Expand Up @@ -232,7 +233,7 @@ func (c *ContainerServer) LoadSandbox(ctx context.Context, id string) (retErr er
defer func() {
if retErr != nil {
if err := c.RemoveSandbox(sb.ID()); err != nil {
logrus.Warnf("could not remove sandbox ID %s: %v", sb.ID(), err)
log.Warnf(ctx, "could not remove sandbox ID %s: %v", sb.ID(), err)
}
}
}()
Expand Down Expand Up @@ -338,7 +339,7 @@ func (c *ContainerServer) LoadSandbox(ctx context.Context, id string) (retErr er
defer func() {
if retErr != nil {
if err1 := c.ctrIDIndex.Delete(scontainer.ID()); err1 != nil {
logrus.Warnf("could not delete container ID %s: %v", scontainer.ID(), err1)
log.Warnf(ctx, "could not delete container ID %s: %v", scontainer.ID(), err1)
}
}
}()
Expand Down Expand Up @@ -492,7 +493,7 @@ func (c *ContainerServer) ContainerStateFromDisk(ctx context.Context, ctr *oci.C
// on disk
func (c *ContainerServer) ContainerStateToDisk(ctx context.Context, ctr *oci.Container) error {
if err := c.Runtime().UpdateContainerStatus(ctx, ctr); err != nil {
logrus.Warnf("error updating the container status %q: %v", ctr.ID(), err)
log.Warnf(ctx, "error updating the container status %q: %v", ctr.ID(), err)
}

jsonSource, err := ioutils.NewAtomicFileWriter(ctr.StatePath(), 0o644)
Expand Down
5 changes: 3 additions & 2 deletions internal/lib/stop.go
View file
Expand Up @@ -3,9 +3,10 @@ package lib
import (
"context"

"github.com/cri-o/cri-o/internal/log"

"github.com/cri-o/cri-o/internal/oci"
"github.com/pkg/errors"
"github.com/sirupsen/logrus"
)

// ContainerStop stops a running container with a grace period (i.e., timeout).
Expand Down Expand Up @@ -36,7 +37,7 @@ func (c *ContainerServer) ContainerStop(ctx context.Context, container string, t
}

if err := c.ContainerStateToDisk(ctx, ctr); err != nil {
logrus.Warnf("unable to write containers %s state to disk: %v", ctr.ID(), err)
log.Warnf(ctx, "unable to write containers %s state to disk: %v", ctr.ID(), err)
}

return ctrID, nil
Expand Down
4 changes: 4 additions & 0 deletions internal/log/log.go
View file
Expand Up @@ -28,6 +28,10 @@ func Errorf(ctx context.Context, format string, args ...interface{}) {
entry(ctx).Errorf(format, args...)
}

func Fatalf(ctx context.Context, format string, args ...interface{}) {
entry(ctx).Fatalf(format, args...)
}

func entry(ctx context.Context) *logrus.Entry {
logger := logrus.StandardLogger()
if ctx == nil {
Expand Down
13 changes: 13 additions & 0 deletions internal/log/log_test.go
View file
Expand Up @@ -137,4 +137,17 @@ var _ = t.Describe("Log", func() {
Expect(buf.String()).To(BeEmpty())
})
})

t.Describe("Fatalf", func() {
BeforeEach(func() { beforeEach(logrus.FatalLevel) })

It("should not error log", func() {
// Given
// When
log.Errorf(ctx, msg)

// Then
Expect(buf.String()).To(BeEmpty())
})
})
})
50 changes: 25 additions & 25 deletions internal/oci/runtime_oci.go
View file
Expand Up @@ -187,7 +187,7 @@ func (r *runtimeOCI) CreateContainer(ctx context.Context, c *Container, cgroupPa
defer func() {
if retErr != nil {
if err := r.DeleteContainer(ctx, c); err != nil {
logrus.Warnf("unable to delete container %s: %v", c.ID(), err)
log.Warnf(ctx, "unable to delete container %s: %v", c.ID(), err)
}
}
}()
Expand All @@ -214,18 +214,18 @@ func (r *runtimeOCI) CreateContainer(ctx context.Context, c *Container, cgroupPa
if ss.err != nil {
return fmt.Errorf("error reading container (probably exited) json message: %v", ss.err)
}
logrus.Debugf("Received container pid: %d", ss.si.Pid)
log.Debugf(ctx, "Received container pid: %d", ss.si.Pid)
pid = ss.si.Pid
if ss.si.Pid == -1 {
if ss.si.Message != "" {
logrus.Errorf("Container creation error: %s", ss.si.Message)
log.Errorf(ctx, "Container creation error: %s", ss.si.Message)
return fmt.Errorf("container create failed: %s", ss.si.Message)
}
logrus.Errorf("Container creation failed")
log.Errorf(ctx, "Container creation failed")
return fmt.Errorf("container create failed")
}
case <-time.After(ContainerCreateTimeout):
logrus.Errorf("Container creation timeout (%v)", ContainerCreateTimeout)
log.Errorf(ctx, "Container creation timeout (%v)", ContainerCreateTimeout)
return fmt.Errorf("create container timeout")
}

Expand Down Expand Up @@ -274,7 +274,7 @@ func prepareExec() (pidFileName string, parentPipe, childPipe *os.File, _ error)
return pidFileName, parentPipe, childPipe, nil
}

func parseLog(l []byte) (stdout, stderr []byte) {
func parseLog(ctx context.Context, l []byte) (stdout, stderr []byte) {
// Split the log on newlines, which is what separates entries.
lines := bytes.SplitAfter(l, []byte{'\n'})
for _, line := range lines {
Expand All @@ -288,7 +288,7 @@ func parseLog(l []byte) (stdout, stderr []byte) {
if len(parts) < 4 {
// Ignore the line if it's formatted incorrectly, but complain
// about it so it can be debugged.
logrus.Warnf("hit invalid log format: %q", string(line))
log.Warnf(ctx, "hit invalid log format: %q", string(line))
continue
}

Expand All @@ -310,7 +310,7 @@ func parseLog(l []byte) (stdout, stderr []byte) {
stderr = append(stderr, content...)
default:
// Complain about unknown pipes.
logrus.Warnf("hit invalid log format [unknown pipe %s]: %q", pipe, string(line))
log.Warnf(ctx, "hit invalid log format [unknown pipe %s]: %q", pipe, string(line))
continue
}
}
Expand Down Expand Up @@ -404,7 +404,7 @@ func (r *runtimeOCI) ExecSyncContainer(ctx context.Context, c *Container, comman
defer parentPipe.Close()
defer func() {
if e := os.Remove(pidFile); e != nil {
logrus.Warnf("could not remove temporary PID file %s", pidFile)
log.Warnf(ctx, "could not remove temporary PID file %s", pidFile)
}
}()

Expand Down Expand Up @@ -492,7 +492,7 @@ func (r *runtimeOCI) ExecSyncContainer(ctx context.Context, c *Container, comman
var ec *exitCodeInfo
decodeErr := json.NewDecoder(parentPipe).Decode(&ec)
if decodeErr == nil {
logrus.Debugf("Received container exit code: %v, message: %s", ec.ExitCode, ec.Message)
log.Debugf(ctx, "Received container exit code: %v, message: %s", ec.ExitCode, ec.Message)

// When we timeout the command in conmon then we should return
// an ExecSyncResponse with a non-zero exit code because
Expand Down Expand Up @@ -553,7 +553,7 @@ func (r *runtimeOCI) ExecSyncContainer(ctx context.Context, c *Container, comman
}

// We have to parse the log output into {stdout, stderr} buffers.
stdoutBytes, stderrBytes := parseLog(logBytes)
stdoutBytes, stderrBytes := parseLog(ctx, logBytes)
return &ExecSyncResponse{
Stdout: stdoutBytes,
Stderr: stderrBytes,
Expand Down Expand Up @@ -606,7 +606,7 @@ func WaitContainerStop(ctx context.Context, c *Container, timeout time.Duration,
if err := c.verifyPid(); err != nil {
// The initial container process either doesn't exist, or isn't ours.
if !errors.Is(err, ErrNotFound) {
logrus.Warnf("failed to find process for container %s: %v", c.id, err)
log.Warnf(ctx, "failed to find process for container %s: %v", c.id, err)
}
close(done)
return
Expand Down Expand Up @@ -707,7 +707,7 @@ func (r *runtimeOCI) StopContainer(ctx context.Context, c *Container, timeout in
if err == nil {
return nil
}
logrus.Warnf("Stopping container %v with stop signal timed out: %v", c.id, err)
log.Warnf(ctx, "Stopping container %v with stop signal timed out: %v", c.id, err)
}

if _, err := utils.ExecCmd(
Expand Down Expand Up @@ -772,7 +772,7 @@ func (r *runtimeOCI) UpdateContainerStatus(ctx context.Context, c *Container) er
}

if c.state.ExitCode != nil && !c.state.Finished.IsZero() {
logrus.Debugf("Skipping status update for: %+v", c.state)
log.Debugf(ctx, "Skipping status update for: %+v", c.state)
return nil
}

Expand All @@ -790,9 +790,9 @@ func (r *runtimeOCI) UpdateContainerStatus(ctx context.Context, c *Container) er
// We always populate the fields below so kube can restart/reschedule
// containers failing.
if exitErr, isExitError := err.(*exec.ExitError); isExitError {
logrus.Errorf("failed to update container state for %s: stdout: %s, stderr: %s", c.id, string(out), string(exitErr.Stderr))
log.Errorf(ctx, "failed to update container state for %s: stdout: %s, stderr: %s", c.id, string(out), string(exitErr.Stderr))
} else {
logrus.Errorf("failed to update container state for %s: %v", c.id, err)
log.Errorf(ctx, "failed to update container state for %s: %v", c.id, err)
}
c.state.Status = ContainerStateStopped
if err := updateContainerStatusFromExitFile(c); err != nil {
Expand Down Expand Up @@ -849,7 +849,7 @@ func (r *runtimeOCI) UpdateContainerStatus(ctx context.Context, c *Container) er
}
*c.state = *state
if err != nil {
logrus.Warnf("failed to find container exit file for %v: %v", c.id, err)
log.Warnf(ctx, "failed to find container exit file for %v: %v", c.id, err)
} else {
c.state.Finished, err = getFinishedTime(fi)
if err != nil {
Expand All @@ -864,7 +864,7 @@ func (r *runtimeOCI) UpdateContainerStatus(ctx context.Context, c *Container) er
return fmt.Errorf("status code conversion failed: %v", err)
}
c.state.ExitCode = utils.Int32Ptr(int32(statusCode))
logrus.Debugf("found exit code for %s: %d", c.id, statusCode)
log.Debugf(ctx, "found exit code for %s: %d", c.id, statusCode)
}

oomFilePath := filepath.Join(c.bundlePath, "oom")
Expand Down Expand Up @@ -945,10 +945,10 @@ func (r *runtimeOCI) AttachContainer(ctx context.Context, c *Container, inputStr
defer controlFile.Close()

kubecontainer.HandleResizing(resize, func(size remotecommand.TerminalSize) {
logrus.Debugf("Got a resize event: %+v", size)
log.Debugf(ctx, "Got a resize event: %+v", size)
_, err := fmt.Fprintf(controlFile, "%d %d %d\n", 1, size.Height, size.Width)
if err != nil {
logrus.Debugf("Failed to write to control file to resize terminal: %v", err)
log.Debugf(ctx, "Failed to write to control file to resize terminal: %v", err)
}
})

Expand Down Expand Up @@ -1126,11 +1126,11 @@ func (r *runtimeOCI) ReopenContainerLog(ctx context.Context, c *Container) error
for {
select {
case event := <-watcher.Events:
logrus.Debugf("event: %v", event)
log.Debugf(ctx, "event: %v", event)
if event.Op&fsnotify.Create == fsnotify.Create || event.Op&fsnotify.Write == fsnotify.Write {
logrus.Debugf("file created %s", event.Name)
log.Debugf(ctx, "file created %s", event.Name)
if event.Name == c.LogPath() {
logrus.Debugf("expected log file created")
log.Debugf(ctx, "expected log file created")
done <- struct{}{}
return
}
Expand All @@ -1144,13 +1144,13 @@ func (r *runtimeOCI) ReopenContainerLog(ctx context.Context, c *Container) error
}()
cLogDir := filepath.Dir(c.LogPath())
if err := watcher.Add(cLogDir); err != nil {
logrus.Errorf("watcher.Add(%q) failed: %s", cLogDir, err)
log.Errorf(ctx, "watcher.Add(%q) failed: %s", cLogDir, err)
close(done)
doneClosed = true
}

if _, err = fmt.Fprintf(controlFile, "%d %d %d\n", 2, 0, 0); err != nil {
logrus.Debugf("Failed to write to control file to reopen log file: %v", err)
log.Debugf(ctx, "Failed to write to control file to reopen log file: %v", err)
}

select {
Expand Down

0 comments on commit 8118d4a

Please sign in to comment.