fix: backfilling not working for some accounts (#221)

* fix: backfilling not working for some accounts

* fix: indent comments

Author: highesttt

pkg/connector/client.go

@@ -80,6 +80,7 @@ type LineClient struct {
 	knownMemberChatMIDs     map[string]struct{} // chatMid -> current member chats returned by getAllChatMids
 	reactionIconMXC         map[int]string      // predefinedReactionType -> cached MXC URI
 	recentReactions         sync.Map            // "msgID\x00emoji" -> struct{} to dedup concurrent 139/140 events
+	unblockBackfills        sync.Map            // chat MID -> *unblockBackfillState while unblock history restoration is active
 
 	wg sync.WaitGroup
 }

pkg/connector/connector.go

@@ -3,6 +3,7 @@ package connector
 import (
 	"context"
 	"encoding/json"
+	"errors"
 	"fmt"
 	"net/http"
 	"strings"
@@ -227,6 +228,7 @@ func (ll *LineEmailLogin) StartWithOverride(ctx context.Context, override *bridg
 
 	res, err := loginWithCredentials(ll.Email, ll.Password, ll.Certificate)
 	if err != nil {
+		ll.logLoginFailure(err, "reconnect")
 		reason := loginErrorReason(err)
 		if reason == "" {
 			reason = fmt.Sprintf("Login failed: %v", err)
@@ -253,6 +255,7 @@ func (ll *LineEmailLogin) SubmitUserInput(ctx context.Context, input map[string]
 
 	res, err := loginWithCredentials(ll.Email, ll.Password, "")
 	if err != nil {
+		ll.logLoginFailure(err, "credentials")
 		reason := loginErrorReason(err)
 		if reason == "" {
 			reason = fmt.Sprintf("Login failed: %v", err)
@@ -299,28 +302,140 @@ func loginErrorInstructions(message string) string {
 	return fmt.Sprintf("Could not log in to LINE: %s", message)
 }
 
-func loginErrorReason(err error) string {
+type loginErrorDetails struct {
+	HTTPStatus        int
+	ResponseCode      int
+	ResponseMessage   string
+	ErrorName         string
+	ErrorCode         int
+	ErrorMessage      string
+	ErrorReason       string
+	HasHTTPStatus     bool
+	HasResponseCode   bool
+	HasErrorCode      bool
+	HasResponseFields bool
+}
+
+func parseLoginErrorDetails(err error) loginErrorDetails {
+	var details loginErrorDetails
 	if err == nil {
-		return ""
+		return details
 	}
+
 	msg := err.Error()
+	if apiErrorIndex := strings.Index(msg, "API error "); apiErrorIndex >= 0 {
+		if parsed, scanErr := fmt.Sscanf(msg[apiErrorIndex:], "API error %d:", &details.HTTPStatus); parsed == 1 && scanErr == nil {
+			details.HasHTTPStatus = true
+		}
+	}
+
 	start := strings.Index(msg, "{")
 	end := strings.LastIndex(msg, "}")
 	if start == -1 || end == -1 || end <= start {
-		return ""
+		return details
 	}
+
 	var payload struct {
-		Data struct {
-			Message string `json:"message"`
-			Reason  string `json:"reason"`
-		} `json:"data"`
+		Code    *int            `json:"code"`
+		Message string          `json:"message"`
+		Data    json.RawMessage `json:"data"`
+	}
+	if json.Unmarshal([]byte(msg[start:end+1]), &payload) != nil {
+		return details
+	}
+
+	details.HasResponseFields = true
+	details.ResponseMessage = payload.Message
+	if payload.Code != nil {
+		details.ResponseCode = *payload.Code
+		details.HasResponseCode = true
+	}
+
+	var responseError struct {
+		Name    string `json:"name"`
+		Code    *int   `json:"code"`
+		Message string `json:"message"`
+		Reason  string `json:"reason"`
+	}
+	if len(payload.Data) > 0 && json.Unmarshal(payload.Data, &responseError) == nil {
+		details.ErrorName = responseError.Name
+		details.ErrorMessage = responseError.Message
+		details.ErrorReason = responseError.Reason
+		if responseError.Code != nil {
+			details.ErrorCode = *responseError.Code
+			details.HasErrorCode = true
+		}
 	}
-	if err := json.Unmarshal([]byte(msg[start:end+1]), &payload); err != nil {
+	return details
+}
+
+func loginErrorSummary(err error, details loginErrorDetails) string {
+	if err == nil {
 		return ""
 	}
-	reason := payload.Data.Reason
+	if details.HasHTTPStatus {
+		return fmt.Sprintf("API error %d", details.HTTPStatus)
+	}
+	if errors.Is(err, context.DeadlineExceeded) {
+		return "request timed out"
+	}
+	if errors.Is(err, context.Canceled) {
+		return "request canceled"
+	}
+	return ""
+}
+
+func loginLogField(value string) string {
+	value = strings.TrimSpace(value)
+	const maxRunes = 512
+	runes := []rune(value)
+	if len(runes) > maxRunes {
+		return string(runes[:maxRunes]) + "…"
+	}
+	return value
+}
+
+func (ll *LineEmailLogin) logLoginFailure(err error, flow string) {
+	if err == nil || ll.User == nil {
+		return
+	}
+
+	details := parseLoginErrorDetails(err)
+	event := ll.User.Log.Warn().
+		Str("login_flow", flow).
+		Bool("has_certificate", ll.Certificate != "")
+	if summary := loginErrorSummary(err, details); summary != "" {
+		event.Str("error_summary", summary)
+	}
+	if details.HasHTTPStatus {
+		event.Int("http_status", details.HTTPStatus)
+	}
+	if details.HasResponseCode {
+		event.Int("line_response_code", details.ResponseCode)
+	}
+	if details.ResponseMessage != "" {
+		event.Str("line_response_message", loginLogField(details.ResponseMessage))
+	}
+	if details.ErrorName != "" {
+		event.Str("line_error_name", loginLogField(details.ErrorName))
+	}
+	if details.HasErrorCode {
+		event.Int("line_error_code", details.ErrorCode)
+	}
+	if details.ErrorMessage != "" {
+		event.Str("line_error_message", loginLogField(details.ErrorMessage))
+	}
+	if details.ErrorReason != "" {
+		event.Str("line_error_reason", loginLogField(details.ErrorReason))
+	}
+	event.Msg("LINE login attempt failed")
+}
+
+func loginErrorReason(err error) string {
+	details := parseLoginErrorDetails(err)
+	reason := details.ErrorReason
 	if reason == "" {
-		reason = payload.Data.Message
+		reason = details.ErrorMessage
 	}
 	if isBlockedUserLoginError(reason) {
 		return loginTooManyAttemptsReason
@@ -341,6 +456,7 @@ func (ll *LineEmailLogin) Wait(ctx context.Context) (*bridgev2.LoginStep, error)
 			}
 			return nil, fmt.Errorf("verification failed: no auth token received")
 		case err := <-ll.pollErr:
+			ll.logLoginFailure(err, "verification_poll")
 			return nil, fmt.Errorf("verification failed: %w", err)
 		case <-ctx.Done():
 			return nil, ctx.Err()
@@ -350,6 +466,7 @@ func (ll *LineEmailLogin) Wait(ctx context.Context) (*bridgev2.LoginStep, error)
 	if ll.AwaitingPIN {
 		res, err := loginWithCredentials(ll.Email, ll.Password, ll.Certificate)
 		if err != nil {
+			ll.logLoginFailure(err, "pin_continuation")
 			return nil, fmt.Errorf("login failed: %w", err)
 		}
 		return ll.handleLoginResponse(ctx, res)

pkg/connector/login_error_logging_test.go

@@ -0,0 +1,105 @@
+package connector
+
+import (
+	"bytes"
+	"context"
+	"encoding/json"
+	"errors"
+	"fmt"
+	"strings"
+	"testing"
+
+	"github.com/rs/zerolog"
+
+	"maunium.net/go/mautrix/bridgev2"
+
+	"github.com/highesttt/matrix-line-messenger/pkg/line"
+)
+
+func TestSubmitUserInputLogsStructuredLoginErrorWithoutCredentials(t *testing.T) {
+	oldLogin := loginWithCredentials
+	t.Cleanup(func() {
+		loginWithCredentials = oldLogin
+	})
+
+	loginWithCredentials = func(_, _, _ string) (*line.LoginResult, error) {
+		return nil, errors.New(`login failed: API error 400: {"code":10051,"message":"RESPONSE_ERROR","data":{"name":"TalkException","message":"Blocked user","code":35,"reason":"blocked user","token":"response-token"},"password":"response-password"}`)
+	}
+
+	var output bytes.Buffer
+	logger := zerolog.New(&output)
+	login := &LineEmailLogin{
+		User: &bridgev2.User{
+			Bridge: &bridgev2.Bridge{Log: logger},
+			Log:    logger,
+		},
+	}
+	step, err := login.SubmitUserInput(context.Background(), map[string]string{
+		"email":    "ana@example.com",
+		"password": "input-password",
+	})
+	if err != nil {
+		t.Fatalf("SubmitUserInput returned error: %v", err)
+	}
+	if step == nil || step.Instructions != loginTooManyAttemptsInstructions {
+		t.Fatalf("step instructions = %q, want %q", step.Instructions, loginTooManyAttemptsInstructions)
+	}
+
+	var event map[string]any
+	if err := json.Unmarshal(bytes.TrimSpace(output.Bytes()), &event); err != nil {
+		t.Fatalf("failed to parse log event: %v\n%s", err, output.String())
+	}
+	wantFields := map[string]any{
+		"level":                 "warn",
+		"message":               "LINE login attempt failed",
+		"login_flow":            "credentials",
+		"has_certificate":       false,
+		"error_summary":         "API error 400",
+		"http_status":           float64(400),
+		"line_response_code":    float64(10051),
+		"line_response_message": "RESPONSE_ERROR",
+		"line_error_name":       "TalkException",
+		"line_error_code":       float64(35),
+		"line_error_message":    "Blocked user",
+		"line_error_reason":     "blocked user",
+	}
+	for key, want := range wantFields {
+		if got := event[key]; got != want {
+			t.Errorf("log field %s = %#v, want %#v", key, got, want)
+		}
+	}
+
+	logged := output.String()
+	for _, secret := range []string{"ana@example.com", "input-password", "response-token", "response-password"} {
+		if strings.Contains(logged, secret) {
+			t.Errorf("log contains secret %q: %s", secret, logged)
+		}
+	}
+}
+
+func TestParseLoginErrorDetailsWithoutJSON(t *testing.T) {
+	err := errors.New("login failed: request failed: context deadline exceeded")
+	details := parseLoginErrorDetails(err)
+	if details.HasHTTPStatus || details.HasResponseFields {
+		t.Fatalf("unexpected parsed response details: %#v", details)
+	}
+	if got := loginErrorSummary(err, details); got != "" {
+		t.Fatalf("loginErrorSummary = %q, want empty", got)
+	}
+}
+
+func TestLoginErrorSummaryDoesNotIncludeNonJSONResponseBody(t *testing.T) {
+	err := errors.New("login failed: API error 502: upstream secret response")
+	details := parseLoginErrorDetails(err)
+	if got := loginErrorSummary(err, details); got != "API error 502" {
+		t.Fatalf("loginErrorSummary = %q, want %q", got, "API error 502")
+	}
+}
+
+func TestLoginErrorSummaryAllowsKnownContextErrors(t *testing.T) {
+	err := fmt.Errorf("login failed: %w", context.DeadlineExceeded)
+	details := parseLoginErrorDetails(err)
+	if got := loginErrorSummary(err, details); got != "request timed out" {
+		t.Fatalf("loginErrorSummary = %q, want %q", got, "request timed out")
+	}
+}