chore(server): print request ID to logs (#530)

server/go.mod

@@ -21,14 +21,12 @@ require (
 	github.com/kelseyhightower/envconfig v1.4.0
 	github.com/kennygrant/sanitize v1.2.4
 	github.com/labstack/echo/v4 v4.7.2
-	github.com/labstack/gommon v0.3.1
 	github.com/mitchellh/mapstructure v1.5.0
 	github.com/paulmach/go.geojson v1.4.0
 	github.com/pkg/errors v0.9.1
 	github.com/ravilushqa/otelgqlgen v0.8.0
-	github.com/reearth/reearthx v0.0.0-20230530055440-86a8d4675853
+	github.com/reearth/reearthx v0.0.0-20230629030550-b8c5785d95e2
 	github.com/samber/lo v1.27.0
-	github.com/sirupsen/logrus v1.8.1
 	github.com/spf13/afero v1.9.3
 	github.com/square/mongo-lock v0.0.0-20201208161834-4db518ed7fb2
 	github.com/stretchr/testify v1.8.0
@@ -112,6 +110,7 @@ require (
 	github.com/imkira/go-interpol v1.0.0 // indirect
 	github.com/jmespath/go-jmespath v0.4.0 // indirect
 	github.com/klauspost/compress v1.13.6 // indirect
+	github.com/labstack/gommon v0.3.1 // indirect
 	github.com/maruel/panicparse/v2 v2.3.1 // indirect
 	github.com/matryer/moq v0.2.7 // indirect
 	github.com/mattn/go-colorable v0.1.13 // indirect
@@ -125,6 +124,7 @@ require (
 	github.com/sendgrid/rest v2.6.9+incompatible // indirect
 	github.com/sendgrid/sendgrid-go v3.12.0+incompatible // indirect
 	github.com/sergi/go-diff v1.1.0 // indirect
+	github.com/sirupsen/logrus v1.8.1 // indirect
 	github.com/smartystreets/assertions v1.1.1 // indirect
 	github.com/smartystreets/goconvey v1.6.4 // indirect
 	github.com/urfave/cli/v2 v2.8.1 // indirect

server/go.sum

@@ -80,6 +80,7 @@ github.com/Masterminds/goutils v1.1.0/go.mod h1:8cTjp+g8YejhMuvIA5y2vz3BpJxksy86
 github.com/Masterminds/semver v1.5.0/go.mod h1:MB6lktGJrhw8PrUyiEoblNEGEQ+RzHPF078ddwwvV3Y=
 github.com/Masterminds/sprig v2.22.0+incompatible/go.mod h1:y6hNFY5UBTIWBxnzTeuNhlNS5hqE0NB0E6fgfo2Br3o=
 github.com/OneOfOne/xxhash v1.2.2/go.mod h1:HSdplMjZKSmBqAxg5vPj2TmRDmfkzw+cTzAElWljhcU=
+github.com/acarl005/stripansi v0.0.0-20180116102854-5a71ef0e047d h1:licZJFw2RwpHMqeKTCYkitsPqHNxTmd4SNR5r94FGM8=
 github.com/agnivade/levenshtein v1.0.1/go.mod h1:CURSv5d9Uaml+FovSIICkLbAUZ9S4RqaHDIsdSBg7lM=
 github.com/agnivade/levenshtein v1.1.1 h1:QY8M92nrzkmr798gCo3kmMyqXFzdQVpxLlGPRBij0P8=
 github.com/agnivade/levenshtein v1.1.1/go.mod h1:veldBMzWxcCG2ZvUTKD2kJNRdCk5hVbJomOvKkmgYbo=
@@ -492,8 +493,10 @@ github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZN
 github.com/prometheus/client_model v0.0.0-20190812154241-14fe0d1b01d4/go.mod h1:xMI15A0UPsDsEKsMN9yxemIoYk6Tm2C1GtYGdfGttqA=
 github.com/ravilushqa/otelgqlgen v0.8.0 h1:x48k+D1GMgm87xhMO2Lekrr9YGzFbpG3yijn9GpxuAY=
 github.com/ravilushqa/otelgqlgen v0.8.0/go.mod h1:6JO5YO2iY4POC7R6yB/L/RKXCcyISL8qQt5NnHOhh0o=
-github.com/reearth/reearthx v0.0.0-20230530055440-86a8d4675853 h1:eO1u6WJ/B1j/uC0ZnHS21EYuaREbdYDgHAExy7LLAnw=
-github.com/reearth/reearthx v0.0.0-20230530055440-86a8d4675853/go.mod h1:Rh7MJPKq43f+HZ/PwjZ5vEbGPpllNFvUrxn9sBn2b+s=
+github.com/reearth/reearthx v0.0.0-20230628105450-fa673eee6505 h1:lTPbUsI7F1W5drXgWhPkSYRprC2j5xS/Fq2c2d+eIys=
+github.com/reearth/reearthx v0.0.0-20230628105450-fa673eee6505/go.mod h1:O4zFr6ks8jDKfgy9NBpZKp31jpmAPnfOtMQK9B6xX54=
+github.com/reearth/reearthx v0.0.0-20230629030550-b8c5785d95e2 h1:hVSBdiK+0/1WsTkANFncN0hq/xa4xJZ7Sl75Dxwr5Cw=
+github.com/reearth/reearthx v0.0.0-20230629030550-b8c5785d95e2/go.mod h1:O4zFr6ks8jDKfgy9NBpZKp31jpmAPnfOtMQK9B6xX54=
 github.com/robertkrimen/godocdown v0.0.0-20130622164427-0bfa04905481/go.mod h1:C9WhFzY47SzYBIvzFqSvHIR6ROgDo4TtdTuRaOMjF/s=
 github.com/rogpeppe/fastuuid v1.2.0/go.mod h1:jVj6XXZzXRy/MSR5jhDC/2q6DgLz+nrA6LYCDYWNEvQ=
 github.com/rogpeppe/go-internal v1.1.0/go.mod h1:M8bDsm7K2OlrFYOpmOWEs/qY81heoFRclV5y23lUDJ4=

server/internal/adapter/gql/loader_plugin.go

@@ -6,7 +6,6 @@ import (
 	"github.com/reearth/reearth/server/internal/adapter/gql/gqldataloader"
 	"github.com/reearth/reearth/server/internal/adapter/gql/gqlmodel"
 	"github.com/reearth/reearth/server/internal/usecase/interfaces"
-	"github.com/reearth/reearth/server/pkg/log"
 	"github.com/reearth/reearthx/util"
 )
 
@@ -25,8 +24,6 @@ func (c *PluginLoader) Fetch(ctx context.Context, ids []gqlmodel.ID) ([]*gqlmode
 	}
 
 	op := getOperator(ctx)
-	log.Infof("TEMP: PluginLoader.Fetch op: %#v", op)
-	log.Infof("TEMP: PluginLoader.Fetch ids: %v", ids)
 
 	res, err := c.usecase.Fetch(ctx, ids2, op)
 	if err != nil {

server/internal/adapter/gql/loader_property.go

@@ -7,7 +7,6 @@ import (
 	"github.com/reearth/reearth/server/internal/adapter/gql/gqlmodel"
 	"github.com/reearth/reearth/server/internal/usecase/interfaces"
 	"github.com/reearth/reearth/server/pkg/id"
-	"github.com/reearth/reearth/server/pkg/log"
 	"github.com/reearth/reearthx/util"
 )
 
@@ -26,8 +25,6 @@ func (c *PropertyLoader) Fetch(ctx context.Context, ids []gqlmodel.ID) ([]*gqlmo
 	}
 
 	op := getOperator(ctx)
-	log.Infof("TEMP: PropertyLoader.Fetch op: %#v", op)
-	log.Infof("TEMP: PropertyLoader.Fetch ids: %v", ids)
 
 	res, err := c.usecase.Fetch(ctx, ids2, op)
 	if err != nil {

server/internal/app/app.go

@@ -23,7 +23,7 @@ import (
 
 func initEcho(ctx context.Context, cfg *ServerConfig) *echo.Echo {
 	if cfg.Config == nil {
-		log.Fatalln("ServerConfig.Config is nil")
+		log.Fatalf("ServerConfig.Config is nil")
 	}
 
 	e := echo.New()
@@ -36,9 +36,10 @@ func initEcho(ctx context.Context, cfg *ServerConfig) *echo.Echo {
 	logger := log.NewEcho()
 	e.Logger = logger
 	e.Use(
-		logger.AccessLogger(),
 		middleware.Recover(),
 		otelecho.Middleware("reearth"),
+		echo.WrapMiddleware(appx.RequestIDMiddleware()),
+		logger.AccessLogger(),
 	)
 	if cfg.Config.HTTPSREDIRECT {
 		e.Use(middleware.HTTPSRedirectWithConfig(middleware.RedirectConfig{
@@ -54,8 +55,11 @@ func initEcho(ctx context.Context, cfg *ServerConfig) *echo.Echo {
 		)
 	}
 
+	// auth
+	authConfig := cfg.Config.JWTProviders()
+	log.Infof("auth: config: %#v", authConfig)
 	e.Use(
-		echo.WrapMiddleware(lo.Must(appx.AuthMiddleware(cfg.Config.JWTProviders(), adapter.ContextAuthInfo, true))),
+		echo.WrapMiddleware(lo.Must(appx.AuthMiddleware(authConfig, adapter.ContextAuthInfo, true))),
 		attachOpMiddleware(cfg),
 	)
 
@@ -75,7 +79,7 @@ func initEcho(ctx context.Context, cfg *ServerConfig) *echo.Echo {
 		e.GET("/graphql", echo.WrapHandler(
 			playground.Handler("reearth", "/api/graphql"),
 		))
-		log.Infof("gql: GraphQL Playground is available")
+		log.Infofc(ctx, "gql: GraphQL Playground is available")
 	}
 
 	// init usecases
@@ -139,7 +143,6 @@ func initEcho(ctx context.Context, cfg *ServerConfig) *echo.Echo {
 
 func errorHandler(next func(error, echo.Context)) func(error, echo.Context) {
 	return func(err error, c echo.Context) {
-		ctx := c.Request().Context()
 		if c.Response().Committed {
 			return
 		}
@@ -148,17 +151,8 @@ func errorHandler(next func(error, echo.Context)) func(error, echo.Context) {
 			err = rerror.ErrNotFound
 		}
 
-		if err := rerror.UnwrapErrInternal(err); err != nil {
-			au := adapter.GetAuthInfo(ctx)
-			u := adapter.User(ctx)
-			op := adapter.Operator(ctx)
-			c.Echo().Logger.Errorf("AUTH: %#v", au)
-			c.Echo().Logger.Errorf("USER: %#v", u)
-			c.Echo().Logger.Errorf("OP: %#v", op)
-		}
-
 		code, msg := errorMessage(err, func(f string, args ...interface{}) {
-			c.Echo().Logger.Errorf(f, args...)
+			log.Errorfc(c.Request().Context(), f, args...)
 		})
 		if err := c.JSON(code, map[string]string{
 			"error": msg,

server/internal/app/auth_client.go

@@ -9,6 +9,7 @@ import (
 	"github.com/reearth/reearth/server/pkg/id"
 	"github.com/reearth/reearth/server/pkg/user"
 	"github.com/reearth/reearth/server/pkg/workspace"
+	"github.com/reearth/reearthx/log"
 	"github.com/reearth/reearthx/rerror"
 	"github.com/reearth/reearthx/util"
 )
@@ -78,13 +79,16 @@ func attachOpMiddleware(cfg *ServerConfig) echo.MiddlewareFunc {
 			}
 
 			if u != nil {
+				ctx = adapter.AttachUser(ctx, u)
+				log.Debugfc(ctx, "auth: user: id=%s name=%s email=%s", u.ID(), u.Name(), u.Email())
+
 				op, err := generateOperator(ctx, cfg, u)
 				if err != nil {
 					return err
 				}
 
-				ctx = adapter.AttachUser(ctx, u)
 				ctx = adapter.AttachOperator(ctx, op)
+				log.Debugfc(ctx, "auth: op: %#v", op)
 			}
 
 			c.SetRequest(req.WithContext(ctx))

server/internal/app/config/auth.go

@@ -67,7 +67,7 @@ func (c Auth0Config) AuthConfigForWeb() *AuthConfig {
 	if c.Domain == "" || c.WebClientID == "" {
 		return nil
 	}
-	domain := prepareUrl(c.Domain)
+	domain := getAuthDomain(c.Domain)
 	var aud []string
 	if len(c.Audience) > 0 {
 		aud = []string{c.Audience}
@@ -83,7 +83,7 @@ func (c Auth0Config) AuthConfigForM2M() *AuthConfig {
 	if c.Domain == "" || c.ClientID == "" {
 		return nil
 	}
-	domain := prepareUrl(c.Domain)
+	domain := getAuthDomain(c.Domain)
 	var aud []string
 	if len(c.Audience) > 0 {
 		aud = []string{c.Audience}
@@ -125,11 +125,11 @@ func (c CognitoConfig) Configs() AuthConfigs {
 	}
 }
 
-func prepareUrl(url string) string {
+func getAuthDomain(url string) string {
 	if !strings.HasPrefix(url, "https://") && !strings.HasPrefix(url, "http://") {
 		url = "https://" + url
 	}
-	// url = strings.TrimSuffix(url, "/")
+	// Auth0 JS library adds slash to the end of the domain (issuer)
 	if !strings.HasSuffix(url, "/") {
 		url = url + "/"
 	}

server/internal/app/config/auth_server.go

@@ -37,7 +37,7 @@ func (c AuthSrvConfig) AuthConfig(debug bool, host string) *AuthConfig {
 	}
 
 	return &AuthConfig{
-		ISS:      domain,
+		ISS:      getAuthDomain(domain),
 		AUD:      aud,
 		ClientID: lo.ToPtr(AuthServerDefaultClientID),
 	}

server/internal/app/config/config_test.go

@@ -9,7 +9,7 @@ import (
 func TestReadConfig(t *testing.T) {
 	clientID := AuthServerDefaultClientID
 	localAuth := AuthConfig{
-		ISS:      "http://localhost:8080",
+		ISS:      "http://localhost:8080/",
 		AUD:      []string{"http://localhost:8080"},
 		ClientID: &clientID,
 	}

server/internal/app/main.go

@@ -23,7 +23,7 @@ func Start(debug bool, version string) {
 	// Load config
 	conf, cerr := config.ReadConfig(debug)
 	if cerr != nil {
-		log.Fatal(cerr)
+		log.Fatalf("failed to load config: %v", cerr)
 	}
 	log.Infof("config: %s", conf.Print())
 
@@ -89,7 +89,7 @@ func NewServer(ctx context.Context, cfg *ServerConfig) *WebServer {
 }
 
 func (w *WebServer) Run() {
-	defer log.Infoln("Server shutdown")
+	defer log.Infof("Server shutdown")
 
 	debugLog := ""
 	if w.appServer.Debug {
@@ -99,7 +99,7 @@ func (w *WebServer) Run() {
 
 	go func() {
 		err := w.appServer.StartH2CServer(w.address, &http2.Server{})
-		log.Fatalln(err.Error())
+		log.Fatalf("failed to run server: %v", err)
 	}()
 
 	quit := make(chan os.Signal, 1)

server/internal/app/profiler.go

@@ -22,6 +22,6 @@ func initGCPProfiler(version string) {
 		Service:        "reearth",
 		ServiceVersion: version,
 	}); err != nil {
-		log.Fatalln(err)
+		log.Fatalf("failed to init GCP profiler: %v", err)
 	}
 }

server/internal/app/repo.go

@@ -2,7 +2,6 @@ package app
 
 import (
 	"context"
-	"fmt"
 
 	"github.com/reearth/reearth/server/internal/app/config"
 	"github.com/reearth/reearth/server/internal/infrastructure/auth0"
@@ -61,7 +60,7 @@ func initReposAndGateways(ctx context.Context, conf *config.Config, debug bool)
 
 	// release lock of all scenes
 	if err := repos.SceneLock.ReleaseAllLock(context.Background()); err != nil {
-		log.Fatalln(fmt.Sprintf("repo initialization error: %+v", err))
+		log.Fatalf("repo initialization error: %v", err)
 	}
 
 	return repos, gateways
@@ -70,7 +69,7 @@ func initReposAndGateways(ctx context.Context, conf *config.Config, debug bool)
 func initFile(ctx context.Context, conf *config.Config) (fileRepo gateway.File) {
 	var err error
 	if conf.GCS.IsConfigured() {
-		log.Infof("file: GCS storage is used: %s\n", conf.GCS.BucketName)
+		log.Infofc(ctx, "file: GCS storage is used: %s\n", conf.GCS.BucketName)
 		fileRepo, err = gcs.NewFile(conf.GCS.BucketName, conf.AssetBaseURL, conf.GCS.PublicationCacheControl)
 		if err != nil {
 			log.Warnf("file: failed to init GCS storage: %s\n", err.Error())
@@ -80,19 +79,19 @@ func initFile(ctx context.Context, conf *config.Config) (fileRepo gateway.File)
 	}
 
 	if conf.S3.IsConfigured() {
-		log.Infof("file: S3 storage is used: %s\n", conf.S3.BucketName)
+		log.Infofc(ctx, "file: S3 storage is used: %s\n", conf.S3.BucketName)
 		fileRepo, err = s3.NewS3(ctx, conf.S3.BucketName, conf.AssetBaseURL, conf.S3.PublicationCacheControl)
 		if err != nil {
 			log.Warnf("file: failed to init S3 storage: %s\n", err.Error())
 		}
 		return
 	}
 
-	log.Infoln("file: local storage is used")
+	log.Infof("file: local storage is used")
 	afs := afero.NewBasePathFs(afero.NewOsFs(), "data")
 	fileRepo, err = fs.NewFile(afs, conf.AssetBaseURL)
 	if err != nil {
-		log.Fatalln(fmt.Sprintf("file: init error: %+v", err))
+		log.Fatalf("file: init error: %+v", err)
 	}
 	return fileRepo
 }

server/internal/app/tracer.go

@@ -27,7 +27,7 @@ func initTracer(ctx context.Context, conf *config.Config) io.Closer {
 func initGCPTracer(ctx context.Context, conf *config.Config) {
 	exporter, err := texporter.New(texporter.WithProjectID(conf.GCPProject))
 	if err != nil {
-		log.Fatalln(err)
+		log.Fatalf("failed to init GCP tracer: %v", err)
 	}
 
 	tp := sdktrace.NewTracerProvider(sdktrace.WithSyncer(exporter), sdktrace.WithSampler(sdktrace.TraceIDRatioBased(conf.TracerSample)))

server/internal/app/web.go

@@ -55,7 +55,7 @@ func (w *WebHandler) Handler(e *echo.Echo) {
 		return
 	}
 
-	e.Logger.Info("web: web directory will be delivered\n")
+	log.Infof("web: web directory will be delivered")
 
 	cfg := map[string]any{}
 	if w.AuthConfig != nil {

server/internal/infrastructure/adapter/property_schema.go

@@ -64,28 +64,28 @@ func (r *propertySchema) FindByIDs(ctx context.Context, ids []id.PropertySchemaI
 
 func (r *propertySchema) Save(ctx context.Context, p *property.Schema) error {
 	if r.writer == nil {
-		return rerror.ErrInternalBy(errors.New("writer is not set"))
+		return rerror.ErrInternalByWithContext(ctx, errors.New("writer is not set"))
 	}
 	return r.writer.Save(ctx, p)
 }
 
 func (r *propertySchema) SaveAll(ctx context.Context, p property.SchemaList) error {
 	if r.writer == nil {
-		return rerror.ErrInternalBy(errors.New("writer is not set"))
+		return rerror.ErrInternalByWithContext(ctx, errors.New("writer is not set"))
 	}
 	return r.writer.SaveAll(ctx, p)
 }
 
 func (r *propertySchema) Remove(ctx context.Context, p id.PropertySchemaID) error {
 	if r.writer == nil {
-		return rerror.ErrInternalBy(errors.New("writer is not set"))
+		return rerror.ErrInternalByWithContext(ctx, errors.New("writer is not set"))
 	}
 	return r.writer.Remove(ctx, p)
 }
 
 func (r *propertySchema) RemoveAll(ctx context.Context, p []id.PropertySchemaID) error {
 	if r.writer == nil {
-		return rerror.ErrInternalBy(errors.New("writer is not set"))
+		return rerror.ErrInternalByWithContext(ctx, errors.New("writer is not set"))
 	}
 	return r.writer.RemoveAll(ctx, p)
 }