Merge pull request #1231 from France-ioi/user_id_in_logs

Add user_id into "request complete" logs

app/api/answers/submit.feature

@@ -73,6 +73,10 @@ Feature: Submit a new answer
         "success": true
       }
       """
+    And logs should contain:
+      """
+      user_id=101
+      """
     And the table "answers" should be:
       | author_id | participant_id | attempt_id | item_id | type       | answer  | ABS(TIMESTAMPDIFF(SECOND, created_at, NOW())) < 3 |
       | 101       | 101            | 1          | 50      | Submission | print 1 | 1                                                 |
@@ -125,6 +129,10 @@ Feature: Submit a new answer
         "success": true
       }
       """
+    And logs should contain:
+      """
+      user_id=101
+      """
     And the table "answers" should be:
       | author_id | participant_id | attempt_id | item_id | type       | answer  | ABS(TIMESTAMPDIFF(SECOND, created_at, NOW())) < 3 |
       | 101       | 201            | 1          | 50      | Submission | print 1 | 1                                                 |
@@ -181,6 +189,10 @@ Feature: Submit a new answer
         "success": true
       }
       """
+    And logs should contain:
+      """
+      user_id=101
+      """
     And the table "answers" should be:
       | author_id | participant_id | attempt_id | item_id | type       | answer   | ABS(TIMESTAMPDIFF(SECOND, created_at, NOW())) < 3 |
       | 101       | 101            | 1          | 50      | Submission | print(2) | 1                                                 |

app/api/answers/submit.go

@@ -13,6 +13,7 @@ import (
 
 	"github.com/France-ioi/AlgoreaBackend/v2/app/database"
 	"github.com/France-ioi/AlgoreaBackend/v2/app/doc"
+	"github.com/France-ioi/AlgoreaBackend/v2/app/logging"
 	"github.com/France-ioi/AlgoreaBackend/v2/app/service"
 	"github.com/France-ioi/AlgoreaBackend/v2/app/token"
 )
@@ -95,6 +96,8 @@ func (srv *Service) submit(rw http.ResponseWriter, httpReq *http.Request) servic
 	var hintsInfo *database.HintsInfo
 	apiError := service.NoError
 
+	logging.LogEntrySetField(httpReq, "user_id", requestData.TaskToken.Converted.UserID)
+
 	err = srv.GetStore(httpReq).InTransaction(func(store *database.DataStore) error {
 		var hasAccess bool
 		var reason error

app/api/auth/create_access_token.go

@@ -19,6 +19,7 @@ import (
 	"github.com/France-ioi/AlgoreaBackend/v2/app/auth"
 	"github.com/France-ioi/AlgoreaBackend/v2/app/database"
 	"github.com/France-ioi/AlgoreaBackend/v2/app/domain"
+	"github.com/France-ioi/AlgoreaBackend/v2/app/logging"
 	"github.com/France-ioi/AlgoreaBackend/v2/app/loginmodule"
 	"github.com/France-ioi/AlgoreaBackend/v2/app/rand"
 	"github.com/France-ioi/AlgoreaBackend/v2/app/service"
@@ -268,6 +269,7 @@ func (srv *Service) createAccessToken(w http.ResponseWriter, r *http.Request) se
 
 	service.MustNotBeError(srv.GetStore(r).InTransaction(func(store *database.DataStore) error {
 		userID := createOrUpdateUser(store.Users(), userProfile, domainConfig)
+		logging.LogEntrySetField(r, "user_id", userID)
 		service.MustNotBeError(store.Groups().StoreBadges(userProfile["badges"].([]database.Badge), userID, true))
 
 		sessionID := rand.Int63()

app/api/auth/create_access_token.robustness.feature

@@ -120,7 +120,7 @@ Feature: Login callback - robustness
     And the response error message should contain "Can't retrieve user's profile (status code = 500)"
     And logs should contain:
       """
-      Can't retrieve user's profile (status code = 500, response = "Unknown error")
+      {{ quote(`Can't retrieve user's profile (status code = 500, response = "Unknown error")`) }}
       """
     And the table "users" should stay unchanged
     And the table "groups" should stay unchanged
@@ -149,7 +149,7 @@ Feature: Login callback - robustness
     And the response error message should contain "Can't parse user's profile"
     And logs should contain:
       """
-      Can't parse user's profile (response = "Not a JSON", error = "invalid character 'N' looking for beginning of value")
+      {{ quote(`Can't parse user's profile (response = "Not a JSON", error = "invalid character 'N' looking for beginning of value")`)}}
       """
     And the table "users" should stay unchanged
     And the table "groups" should stay unchanged
@@ -178,7 +178,7 @@ Feature: Login callback - robustness
     And the response error message should contain "User's profile is invalid"
     And logs should contain:
       """
-      User's profile is invalid (response = "{{`<profile_body>`|safeJs}}", error = "<error_text>")
+      {{ quote(`User's profile is invalid (response = ` + quote(`<profile_body>`) + `, error = "<error_text>")`) }}
       """
     And the table "users" should stay unchanged
     And the table "groups" should stay unchanged

app/api/items/ask_hint.feature

@@ -345,5 +345,5 @@ Feature: Ask for a hint
     And the table "results_propagate" should be empty
     And logs should contain:
       """
-      Unable to parse hints_requested ({"idAttempt":"101/0","idItemLocal":"50","idUser":"101"}) having value "not an array": invalid character 'o' in literal null (expecting 'u')
+      {{ quote(`Unable to parse hints_requested ({"idAttempt":"101/0","idItemLocal":"50","idUser":"101"}) having value "not an array": invalid character 'o' in literal null (expecting 'u')`) }}
       """

app/api/items/ask_hint.go

@@ -101,6 +101,8 @@ func (srv *Service) askHint(w http.ResponseWriter, r *http.Request) service.APIE
 		return apiError
 	}
 
+	logging.LogEntrySetField(r, "user_id", requestData.TaskToken.Converted.UserID)
+
 	err = store.InTransaction(func(store *database.DataStore) error {
 		var hasAccess bool
 		var reason error

app/api/items/save_grade.go

@@ -112,6 +112,8 @@ func (srv *Service) saveGrade(w http.ResponseWriter, r *http.Request) service.AP
 		return service.ErrInvalidRequest(err)
 	}
 
+	logging.LogEntrySetField(r, "user_id", requestData.ScoreToken.Converted.UserID)
+
 	var validated, ok bool
 	unlockedItems := make([]map[string]interface{}, 0)
 	err = store.InTransaction(func(store *database.DataStore) error {
@@ -133,7 +135,7 @@ func (srv *Service) saveGrade(w http.ResponseWriter, r *http.Request) service.AP
          ON default_strings.item_id = items.id AND default_strings.language_tag = items.default_language_tag`).
 			Joins(`LEFT JOIN items_strings user_strings
          ON user_strings.item_id=items.id AND user_strings.language_tag = (SELECT default_language FROM users WHERE group_id = ?)`,
-				requestData.ScoreToken.UserID).
+				requestData.ScoreToken.Converted.UserID).
 			Where("items.id IN (?)", unlockedItemIDs.Values()).
 			Order("items.id").
 			ScanIntoSliceOfMaps(&unlockedItems).Error())

app/api/items/save_grade.robustness.feature

@@ -299,7 +299,7 @@ Feature: Save grading result - robustness
     And the response error message should contain "The answer has been already graded or is not found"
     And logs should contain:
     """
-    A user tries to replay a score token with a different score value ({"idAttempt":"101/1","idItem":"80","idUser":"101","idUserAnswer":"124","newScore":100,"oldScore":0})
+    {{ quote(`A user tries to replay a score token with a different score value ({"idAttempt":"101/1","idItem":"80","idUser":"101","idUserAnswer":"124","newScore":100,"oldScore":0})`) }}
     """
     And the table "answers" should stay unchanged
     And the table "attempts" should stay unchanged

app/auth/middleware.go

@@ -98,6 +98,8 @@ func ValidatesUserAuthentication(service GetStorer, w http.ResponseWriter, r *ht
 	ctx = context.WithValue(ctx, ctxUser, &user)
 	ctx = context.WithValue(ctx, ctxSessionID, sessionID)
 
+	logging.LogEntrySetField(r, "user_id", user.GroupID)
+
 	return ctx, true, "", nil
 }
 

app/auth/middleware_test.go

@@ -47,6 +47,7 @@ func TestUserMiddleware(t *testing.T) {
 			expectedStatusCode:       200,
 			expectedServiceWasCalled: true,
 			expectedBody:             "user_id:890123\nBearer:1234567",
+			expectedLogs:             "user_id=890123",
 		},
 		{
 			name:                     "missing access token",
@@ -62,7 +63,7 @@ func TestUserMiddleware(t *testing.T) {
 			expectedStatusCode:       500,
 			expectedServiceWasCalled: false,
 			expectedBody:             `{"success":false,"message":"Internal server error"}` + "\n",
-			expectedLogs:             `level=error msg="Can't validate an access token: some error"`,
+			expectedLogs:             `level=error .* msg="Can't validate an access token: some error"`,
 		},
 		{
 			name:                     "expired token",
@@ -117,6 +118,7 @@ func TestUserMiddleware(t *testing.T) {
 			expectedStatusCode:       200,
 			expectedServiceWasCalled: true,
 			expectedBody:             "user_id:890123",
+			expectedLogs:             "user_id=890123",
 		},
 		{
 			name:                     "accepts access token from cookies",
@@ -126,6 +128,7 @@ func TestUserMiddleware(t *testing.T) {
 			expectedStatusCode:       200,
 			expectedServiceWasCalled: true,
 			expectedBody:             "user_id:890123",
+			expectedLogs:             "user_id=890123",
 		},
 		{
 			name: "takes the first access token from cookies",
@@ -138,6 +141,7 @@ func TestUserMiddleware(t *testing.T) {
 			expectedStatusCode:       200,
 			expectedServiceWasCalled: true,
 			expectedBody:             "user_id:890123",
+			expectedLogs:             "user_id=890123",
 		},
 		{
 			name:                     "prefers an access token from the Authorization header if both cookie and the Authorization header are given",
@@ -148,6 +152,7 @@ func TestUserMiddleware(t *testing.T) {
 			expectedStatusCode:       200,
 			expectedServiceWasCalled: true,
 			expectedBody:             "user_id:890123",
+			expectedLogs:             "user_id=890123",
 		},
 		{
 			name:                     "sets user attributes",
@@ -217,10 +222,8 @@ func TestUserMiddleware(t *testing.T) {
 			}
 			assert.Contains(string(bodyBytes), tt.expectedBody)
 			logs := (&loggingtest.Hook{Hook: logHook}).GetAllStructuredLogs()
-			if tt.expectedLogs == "" {
-				assert.Empty(logs)
-			} else {
-				assert.Contains(logs, tt.expectedLogs)
+			if tt.expectedLogs != "" {
+				assert.Regexp(tt.expectedLogs, logs)
 			}
 			assert.NoError(mock.ExpectationsWereMet())
 		})
@@ -281,7 +284,7 @@ func callAuthThroughMiddleware(expectedAccessToken string, authorizationHeaders,
 		w.WriteHeader(http.StatusOK)
 		_, _ = w.Write([]byte(body))
 	})
-	mainSrv := httptest.NewServer(middleware(handler))
+	mainSrv := httptest.NewServer(logging.NewStructuredLogger()(middleware(handler)))
 	defer mainSrv.Close()
 
 	// calling web server

app/database/db_test.go

@@ -206,7 +206,7 @@ func TestDB_inTransaction_RetriesOnDeadlockAndLockWaitTimeoutErrors(t *testing.T
 			assert.NoError(t, mock.ExpectationsWereMet())
 
 			logs := (&loggingtest.Hook{Hook: logHook}).GetAllStructuredLogs()
-			assert.Contains(t, logs, fmt.Sprintf("Retrying transaction (count: 1) after Error %d: ", errorNumber))
+			assert.Contains(t, logs, fmt.Sprintf("Retrying transaction (count: 1) after Error %d:", errorNumber))
 		})
 	}
 }

app/logging/text_formatter.go

@@ -23,6 +23,11 @@ func newTextFormatter(useColors bool) *textFormatter {
 	}}
 }
 
+// NewTextFormatterForTests creates a new text formatter without colors.
+func NewTextFormatterForTests() logrus.Formatter {
+	return newTextFormatter(false)
+}
+
 var spacesRegexp = regexp.MustCompile(`\s+`)
 
 func (f *textFormatter) Format(entry *logrus.Entry) ([]byte, error) {

app/loggingtest/loggingtest.go

@@ -7,6 +7,8 @@ import (
 	"strings"
 
 	"github.com/sirupsen/logrus/hooks/test" //nolint
+
+	"github.com/France-ioi/AlgoreaBackend/v2/app/logging"
 )
 
 // Hook is a hook designed for dealing with logs in test scenarios. It wraps logrus/hooks/test.Hook.
@@ -34,16 +36,17 @@ func (hook *Hook) GetAllLogs() string {
 // GetAllStructuredLogs returns all the structured logs collected by the hook as a string.
 func (hook *Hook) GetAllStructuredLogs() string {
 	logs := ""
+	formatter := logging.NewTextFormatterForTests()
 
 	for _, entry := range hook.AllEntries() {
 		if len(logs) > 0 {
 			logs += newLine
 		}
-		logString, err := entry.String()
+		logBytes, err := formatter.Format(entry)
 		if err != nil {
 			logs += strings.TrimSpace(err.Error())
 		} else {
-			logs += strings.TrimSpace(logString)
+			logs += strings.TrimSpace(string(logBytes))
 		}
 	}