Logger: failed to get caller

[loeffel-io]

Go version used:

1.20.2 - package version rc-5

What happened:

Receiving Logger.check error: failed to get caller every few seconds

How to reproduce it (as minimally and precisely as possible):

Using the example

func InterceptorLogger(l *zap.Logger) logging.Logger {
	return logging.LoggerFunc(func(ctx context.Context, lvl logging.Level, msg string, fields ...any) {
		f := make([]zap.Field, 0, len(fields)/2)
		for i := 0; i < len(fields); i += 2 {
			iter := logging.Fields(fields).Iterator()
			if iter.Next() {
				k, v := iter.At()
				f = append(f, zap.Any(k, v))
			}
		}
		l = l.WithOptions(zap.AddCallerSkip(1)).With(f...)

		switch lvl {
		case logging.LevelDebug:
			l.Debug(msg)
		case logging.LevelInfo:
			l.Info(msg)
		case logging.LevelWarn:
			l.Warn(msg)
		case logging.LevelError:
			l.Error(msg)
		default:
			panic(fmt.Sprintf("unknown level %v", lvl))
		}
	})
}

[loeffel-io]

And i have no information which method is called ..

Checking the fields results prints (looks pretty broken to me, haha)

[protocol grpc grpc.component server grpc.service grpc.health.v1.Health grpc.method Check grpc.method_type unary peer.address 127.0.0.6:44615 grpc.start_time 2023-04-14T12:32:02Z grpc.request.deadline 2023-04-14T12:32:03Z grpc.code OK grpc.time_ms 0.125]{"severity":"INFO","time":"2023-04-14T12:32:02Z","caller":"earth_category_service/zap.go:28","message":"finished call","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc","protocol":"grpc"}

[loeffel-io]

With every new log the "protocol":"grpc" increases!

[loeffel-io]

moving tmp back to rc-3 which worked perfectly

{
  "insertId": "vpua3z0cys98r8v8",
  "jsonPayload": {
    "grpc.code": "OK",
    "grpc.request.deadline": "2023-04-14T13:02:54Z",
    "grpc.start_time": "2023-04-14T13:02:53Z",
    "grpc.time_ms": "0.06",
    "grpc.service": "grpc.health.v1.Health",
    "grpc.method_type": "unary",
    "peer.address": "127.0.0.6:36741",
    "message": "started call",
    "caller": "logging/interceptors.go:35",
    "protocol": "grpc",
    "grpc.method": "Check",
    "grpc.component": "server"
  },
  "resource": {
    "type": "k8s_container",
    "labels": {
      "pod_name": "earth-category-service-5d67b58f69-dvhvk",
      "container_name": "earth-category-service",
      "project_id": "earth-dev-382708",
      "namespace_name": "earth-category-service-loeffel-io",
      "location": "us-central1",
      "cluster_name": "earth-gke-dev"
    }
  },
  "timestamp": "2023-04-14T13:02:53Z",
  "severity": "INFO",
  "labels": {
    "k8s-pod/pod-template-hash": "5d67b58f69",
    "k8s-pod/app": "earth-category-service",
    "k8s-pod/service_istio_io/canonical-revision": "latest",
    "k8s-pod/service_istio_io/canonical-name": "earth-category-service",
    "k8s-pod/security_istio_io/tlsMode": "istio",
    "compute.googleapis.com/resource_name": "gk3-earth-gke-dev-nap-d79hh0r9-f0a48e8e-z99r"
  },
  "logName": "projects/earth-dev-382708/logs/stdout",
  "receiveTimestamp": "2023-04-14T13:02:55.192864872Z"
}

[bwplotka]

Thanks! This is duplicate of #559 , so closing.

The example is wrong.

You can fix it by using something like this instead:

func InterceptorLogger(l *zap.Logger) logging.Logger {
	return logging.LoggerFunc(func(ctx context.Context, lvl logging.Level, msg string, fields ...any) {
		f := make([]zap.Field, 0, len(fields)/2)
		iter := logging.Fields(fields).Iterator()
		for iter.Next() {
			k, v := iter.At()
			f = append(f, zap.Any(k, v))
		}
		l = l.WithOptions(zap.AddCallerSkip(1)).With(f...)

		switch lvl {
		case logging.LevelDebug:
			l.Debug(msg)
		case logging.LevelInfo:
			l.Info(msg)
		case logging.LevelWarn:
			l.Warn(msg)
		case logging.LevelError:
			l.Error(msg)
		default:
			panic(fmt.Sprintf("unknown level %v", lvl))
		}
	})
}

[bwplotka]

Help wanted to fix this on main 🤗