Ignore some known errors and convert some errors to metric

ref DEV-3102

Author: louischan-oursky

.vettedpositions

@@ -59,10 +59,10 @@
 /pkg/auth/handler/webapp/auth_entry_point_middleware.go:31:31: requestcontext
 /pkg/auth/handler/webapp/auth_entry_point_middleware.go:32:35: requestcontext
 /pkg/auth/handler/webapp/authflow_change_password.go:96:26: requestcontext
-/pkg/auth/handler/webapp/authflow_controller.go:1012:30: requestcontext
-/pkg/auth/handler/webapp/authflow_controller.go:1017:24: requestcontext
-/pkg/auth/handler/webapp/authflow_controller.go:1025:19: requestcontext
-/pkg/auth/handler/webapp/authflow_controller.go:1033:18: requestcontext
+/pkg/auth/handler/webapp/authflow_controller.go:1020:30: requestcontext
+/pkg/auth/handler/webapp/authflow_controller.go:1025:24: requestcontext
+/pkg/auth/handler/webapp/authflow_controller.go:1033:19: requestcontext
+/pkg/auth/handler/webapp/authflow_controller.go:1041:18: requestcontext
 /pkg/auth/handler/webapp/authflow_create_password.go:132:26: requestcontext
 /pkg/auth/handler/webapp/authflow_enter_oob_otp.go:156:26: requestcontext
 /pkg/auth/handler/webapp/authflow_enter_password.go:139:26: requestcontext

pkg/auth/handler/saml/login_finish.go

@@ -38,7 +38,7 @@ func (h *LoginFinishHandler) ServeHTTP(rw http.ResponseWriter, r *http.Request)
 
 	authInfoID, ok := h.AuthenticationInfoResolver.GetAuthenticationInfoID(r)
 	if !ok {
-		logger.Warn(ctx, "authentication info id is missing")
+		logger.WithSkipLogging().Warn(ctx, "authentication info id is missing")
 		// Maybe the user visited the page directly, tell him not to do so.
 		http.Error(rw, "invoking this endpoint directly is not supported", http.StatusBadRequest)
 		return

pkg/auth/handler/webapp/authflow_controller.go

@@ -950,7 +950,11 @@ func (c *AuthflowController) makeSessionOptionsFromSAML(ctx context.Context, sam
 func (c *AuthflowController) deriveFlowNameFromOAuthSession(ctx context.Context, oauthSessionID string, flowType authflow.FlowType) (string, error) {
 	entry, err := c.OAuthSessions.Get(ctx, oauthSessionID)
 	if err != nil {
-		return "", err
+		if errors.Is(err, oauthsession.ErrNotFound) {
+			return "", errors.Join(webapp.ErrInvalidSession, err)
+		} else {
+			return "", err
+		}
 	}
 
 	req := entry.T.AuthorizationRequest
@@ -968,7 +972,11 @@ func (c *AuthflowController) deriveFlowNameFromOAuthSession(ctx context.Context,
 func (c *AuthflowController) deriveFlowNameFromSAMLSession(ctx context.Context, samlSessionID string, flowType authflow.FlowType) (string, error) {
 	samlSession, err := c.SAMLSessions.Get(ctx, samlSessionID)
 	if err != nil {
-		return "", err
+		if errors.Is(err, samlsession.ErrNotFound) {
+			return "", errors.Join(webapp.ErrInvalidSession, err)
+		} else {
+			return "", err
+		}
 	}
 
 	specifiedFlowGroup := "" // SAML cannot specify flow group in request

pkg/lib/config/configsource/database.go

@@ -337,9 +337,16 @@ func (d *Database) invalidateAppByDomain(ctx context.Context, domain string) {
 	})
 	if err != nil {
 		logger := DatabaseLogger.GetLogger(ctx)
-		logger.WithError(err).Error(ctx, "failed to invalidate app cache by domain",
-			slog.String("domain", domain),
-		)
+		if errors.Is(err, ErrAppNotFound) {
+			// If the domain was deleted
+			logger.Info(ctx, "failed to invalidate app cache because domain not found",
+				slog.String("domain", domain),
+			)
+		} else {
+			logger.WithError(err).Error(ctx, "failed to invalidate app cache by domain",
+				slog.String("domain", domain),
+			)
+		}
 	}
 }
 

pkg/lib/oauthrelyingparty/oauthrelyingpartyutil/error.go

@@ -4,6 +4,7 @@ import (
 	"github.com/authgear/oauthrelyingparty/pkg/api/oauthrelyingparty"
 
 	"github.com/authgear/authgear-server/pkg/api/apierrors"
+	"github.com/authgear/authgear-server/pkg/util/slogutil"
 )
 
 var InvalidConfiguration = apierrors.InternalError.WithReason("InvalidConfiguration")
@@ -17,3 +18,19 @@ func NewOAuthError(errResp *oauthrelyingparty.ErrorResponse) error {
 		"error_uri":         errResp.ErrorURI,
 	})
 }
+
+type OAuthRelyingPartyInternalError struct {
+	err                error
+	IsLoggingSkippable bool
+}
+
+var _ error = (*OAuthRelyingPartyInternalError)(nil)
+var _ slogutil.LoggingSkippable = (*OAuthRelyingPartyInternalError)(nil)
+
+func (e *OAuthRelyingPartyInternalError) Error() string {
+	return e.err.Error()
+}
+
+func (e *OAuthRelyingPartyInternalError) SkipLogging() bool {
+	return e.IsLoggingSkippable
+}

pkg/lib/oauthrelyingparty/oauthrelyingpartyutil/oidc.go

@@ -50,7 +50,10 @@ func FetchOIDCDiscoveryDocument(ctx context.Context, client *http.Client, endpoi
 	}
 
 	if resp.StatusCode != http.StatusOK {
-		return nil, fmt.Errorf("failed to fetch OIDC discovery document: unexpected status code: %d", resp.StatusCode)
+		return nil, &OAuthRelyingPartyInternalError{
+			err:                fmt.Errorf("failed to fetch OIDC discovery document: unexpected status code: %d", resp.StatusCode),
+			IsLoggingSkippable: true,
+		}
 	}
 
 	var document OIDCDiscoveryDocument

pkg/portal/service/app.go

@@ -406,9 +406,14 @@ func (s *AppService) Create(ctx context.Context, userID string, id string) (*mod
 		}
 		err = s.AppConfigs.Create(ctx, createAppOpts)
 		if err != nil {
-			// TODO(portal): cleanup orphaned resources created from failed app creation
-			logger.WithError(err).Error(ctx, "failed to create app", slog.String("app_id", id))
-			return err
+			if errors.Is(err, ErrDuplicatedAppID) {
+				logger.Info(ctx, "failed to create duplicated app", slog.String("app_id", id))
+				return err
+			} else {
+				// TODO(portal): cleanup orphaned resources created from failed app creation
+				logger.WithError(err).Error(ctx, "failed to create app", slog.String("app_id", id))
+				return err
+			}
 		}
 
 		err = s.DefaultDomains.CreateAllDefaultDomains(ctx, id)

pkg/util/slogutil/metric.go

@@ -5,23 +5,39 @@ import (
 	"database/sql"
 	"database/sql/driver"
 	"errors"
+	"net"
 	"os"
 	"syscall"
 
 	"github.com/lib/pq"
+	"go.opentelemetry.io/otel/attribute"
+	"go.opentelemetry.io/otel/metric"
+	"golang.org/x/sys/unix"
+
+	"github.com/authgear/authgear-server/pkg/util/otelutil"
 )
 
+// MetricOptionAttributeKeyValue is a MetricOption that adds an attribute.
+type MetricOptionAttributeKeyValue struct {
+	attribute.KeyValue
+}
+
+// ToOtelMetricOption implements otelutil.MetricOption.
+func (o MetricOptionAttributeKeyValue) ToOtelMetricOption() metric.MeasurementOption {
+	return metric.WithAttributes(o.KeyValue)
+}
+
 // MetricErrorName is a symbolic name for some errors
 type MetricErrorName string
 
 const (
 	MetricErrorNameContextCanceled         MetricErrorName = "context.canceled"
 	MetricErrorNameContextDeadlineExceeded MetricErrorName = "context.deadline_exceeded"
 	MetricErrorNameOSErrDeadlineExceeded   MetricErrorName = "os.err_deadline_exceeded"
-	MetricErrorNameSyscallECONNRESET       MetricErrorName = "syscall.ECONNRESET"
 	MetricErrorNamePQ57014                 MetricErrorName = "pq.57014"
 	MetricErrorNameSQLTxDone               MetricErrorName = "sql.tx_done"
 	MetricErrorNameSQLDriverBadConn        MetricErrorName = "sql.driver.bad_conn"
+	MetricErrorNameNetOpError              MetricErrorName = "net.op_error"
 )
 
 func GetMetricErrorName(err error) (MetricErrorName, bool) {
@@ -51,13 +67,40 @@ func GetMetricErrorName(err error) (MetricErrorName, bool) {
 		return MetricErrorNameSQLDriverBadConn, true
 	case errors.Is(err, os.ErrDeadlineExceeded):
 		return MetricErrorNameOSErrDeadlineExceeded, true
-	// There are ECONNRESET, ECONNREFUSED, and ECONNABORTED.
-	// ECONNREFUSED may indicate a configuration problem that should be logged.
-	// ECONNRESET is about connection disconnected unexpectedly.
-	// We did not see ECONNABORTED so keep logging it.
-	case errors.Is(err, syscall.ECONNRESET):
-		return MetricErrorNameSyscallECONNRESET, true
+	case isNetOpError(err):
+		// We used to identify syscall.ECONNRESET separately.
+		// But I checked the log and found that syscall.ECONNRESET
+		// was actually wrapped inside a *net.OpError.
+		// Now that we track *net.OpError as metric,
+		// there is no point in handling syscall.ECONNRESET specifically.
+		return MetricErrorNameNetOpError, true
 	}
 
 	return "", false
 }
+
+func isNetOpError(err error) bool {
+	var netOpError *net.OpError
+	return errors.As(err, &netOpError)
+}
+
+func MetricOptionsForError(err error) []otelutil.MetricOption {
+	var opts []otelutil.MetricOption
+	if errorName, ok := GetMetricErrorName(err); ok {
+		opts = append(opts, MetricOptionAttributeKeyValue{attribute.Key("error_name").String(string(errorName))})
+	}
+
+	var netOpError *net.OpError
+	if errors.As(err, &netOpError) {
+		opts = append(opts, MetricOptionAttributeKeyValue{attribute.Key("net_op_error.op").String(netOpError.Op)})
+		opts = append(opts, MetricOptionAttributeKeyValue{attribute.Key("net_op_error.net").String(netOpError.Net)})
+
+		var syscallErrno syscall.Errno
+		if errors.As(netOpError.Err, &syscallErrno) {
+			symbolicName := unix.ErrnoName(syscallErrno)
+			opts = append(opts, MetricOptionAttributeKeyValue{attribute.Key("net_op_error.syscall_errno").String(symbolicName)})
+		}
+	}
+
+	return opts
+}

pkg/util/slogutil/metric_test.go

@@ -6,6 +6,7 @@ import (
 	"database/sql/driver"
 	"errors"
 	"fmt"
+	"net"
 	"os"
 	"syscall"
 	"testing"
@@ -68,11 +69,11 @@ func TestGetMetricErrorName(t *testing.T) {
 			So(name, ShouldEqual, MetricErrorNameOSErrDeadlineExceeded)
 		})
 
-		Convey("should return syscall.ECONNRESET for syscall.ECONNRESET", func() {
+		Convey("should return false for syscall.ECONNRESET", func() {
 			err := syscall.ECONNRESET
 			name, ok := GetMetricErrorName(err)
-			So(ok, ShouldBeTrue)
-			So(name, ShouldEqual, MetricErrorNameSyscallECONNRESET)
+			So(ok, ShouldBeFalse)
+			So(name, ShouldEqual, MetricErrorName(""))
 		})
 
 		Convey("should return false for other syscall errors", func() {
@@ -96,6 +97,17 @@ func TestGetMetricErrorName(t *testing.T) {
 			So(name, ShouldEqual, MetricErrorNameSQLDriverBadConn)
 		})
 
+		Convey("should return net.op_error for *net.OpError", func() {
+			err := &net.OpError{
+				Op:  "write",
+				Net: "tcp",
+				Err: syscall.ECONNRESET,
+			}
+			name, ok := GetMetricErrorName(err)
+			So(ok, ShouldBeTrue)
+			So(name, ShouldEqual, MetricErrorNameNetOpError)
+		})
+
 		Convey("should return false for unrecognized errors", func() {
 			err := errors.New("some other error")
 			name, ok := GetMetricErrorName(err)

pkg/util/slogutil/otel_metric_handler.go

@@ -6,7 +6,6 @@ import (
 
 	"github.com/jba/slog/withsupport"
 	"go.opentelemetry.io/otel"
-	"go.opentelemetry.io/otel/attribute"
 	"go.opentelemetry.io/otel/metric"
 
 	"github.com/authgear/authgear-server/pkg/util/otelutil"
@@ -24,26 +23,14 @@ var CounterErrorCount = otelutil.MustInt64Counter(
 	metric.WithUnit("{error}"),
 )
 
-type metricOptionAttributeKeyValue struct {
-	attribute.KeyValue
-}
-
-func (o metricOptionAttributeKeyValue) ToOtelMetricOption() metric.MeasurementOption {
-	return metric.WithAttributes(o.KeyValue)
-}
-
-func WithErrorName(errorName MetricErrorName) otelutil.MetricOption {
-	return metricOptionAttributeKeyValue{attribute.Key("error_name").String(string(errorName))}
-}
-
-type OtelMetricHandlerTrackFuncType func(ctx context.Context, errorName MetricErrorName)
+type OtelMetricHandlerTrackFuncType func(ctx context.Context, errorName MetricErrorName, err error)
 
 // OtelMetricHandlerTrackFunc is the real implementation.
-var OtelMetricHandlerTrackFunc OtelMetricHandlerTrackFuncType = func(ctx context.Context, errorName MetricErrorName) {
+var OtelMetricHandlerTrackFunc OtelMetricHandlerTrackFuncType = func(ctx context.Context, errorName MetricErrorName, err error) {
 	otelutil.IntCounterAddOne(
 		ctx,
 		CounterErrorCount,
-		WithErrorName(errorName),
+		MetricOptionsForError(err)...,
 	)
 }
 
@@ -76,7 +63,7 @@ func (h *OtelMetricHandler) Handle(ctx context.Context, record slog.Record) erro
 			if err, ok := attr.Value.Any().(error); ok {
 				errorName, ok := GetMetricErrorName(err)
 				if ok {
-					h.trackFunc(ctx, errorName)
+					h.trackFunc(ctx, errorName, err)
 				}
 			}
 		}
@@ -87,7 +74,7 @@ func (h *OtelMetricHandler) Handle(ctx context.Context, record slog.Record) erro
 			if err, ok := attr.Value.Any().(error); ok {
 				errorName, ok := GetMetricErrorName(err)
 				if ok {
-					h.trackFunc(ctx, errorName)
+					h.trackFunc(ctx, errorName, err)
 				}
 			}
 		}