[TB-5] Research how to setup a convenient logging practice in GCP

[vpakhuchyi]

Objective:
We want to have a convenient logging approach in our application that is aligned with GCP advice/recommendations. To achieve that we have to investigate the way how to setup/use it correctly.

Our application will be deployed in GCP (cloud functions/cloud run).

Acceptance criteria:

• An example of a code where logger initialisation and usage are presented (it's preferable to use GCP SDK instead of raw calls to GCP resources)
• An example of log message shall be presented (required log msg attributes (like timestamp, level etc) have to be mentioned)
• All written logs have to be stored in GCP in a persistent data storage
• All written logs have to be available in GCP Cloud console interface with the possibility to read the log msg attributes

Useful links:
https://cloud.google.com/logging/docs/setup/go
https://pkg.go.dev/cloud.google.com/go/logging
https://cloud.google.com/logging/docs/reference/libraries#client-libraries-install-go

[andrsj]

Slog

Розглянувши варіант того, щоб писати всі логи в STDOUT і хай вже Cloud Run з ними розбирається, в нас залишається питання того, як ми будемо логувати

Враховуючи що була пропозиція ввести структуроване логування я переглянув пакет log/slog

Examples

Розглянемо декілька варіантів логування:

Не змінюючи код

log.Infof("Starting...")
log.Debugf("Echo: [%s] %s", data.firstname, data.message)
log.Infof(
	"[CALLBACK QUERY] username: %s, firstname: %s, id: %v",
	data.lastname,
	data.firstname,
	data.userID,
)
log.Errorf("Echo message: %s", errors.New("sending message error"))

Було

INFO: Starting...
DEBUG: Echo: [Andrii] Hello everyone!
INFO: [CALLBACK QUERY] username: Derkach, firstname: Andrii, id: 123456789
ERROR: Echo message: sending message error

Стане

1. Без source:

{"time":"2024-03-21T05:44:55.398180693+02:00","level":"INFO","msg":"Starting..."}
{"time":"2024-03-21T05:44:55.398231252+02:00","level":"DEBUG","msg":"Echo: [Andrii] Hello everyone!"}
{"time":"2024-03-21T05:44:55.398233953+02:00","level":"INFO","msg":"[CALLBACK QUERY] username: Derkach, firstname: Andrii, id: 123456789"}
{"time":"2024-03-21T05:44:55.398236202+02:00","level":"ERROR","msg":"Echo message: sending message error"}

2. З source:

{"time":"2024-03-21T05:44:55.39823831+02:00","level":"INFO","source":{"function":"main.(*slogger).Infof","file":"/home/andrsj/Files/tmp/log-slog/slog.go","line":30},"msg":"Starting..."}
{"time":"2024-03-21T05:44:55.398248406+02:00","level":"DEBUG","source":{"function":"main.(*slogger).Debugf","file":"/home/andrsj/Files/tmp/log-slog/slog.go","line":26},"msg":"Echo: [Andrii] Hello everyone!"}
{"time":"2024-03-21T05:44:55.398251886+02:00","level":"INFO","source":{"function":"main.(*slogger).Infof","file":"/home/andrsj/Files/tmp/log-slog/slog.go","line":30},"msg":"[CALLBACK QUERY] username: Derkach, firstname: Andrii, id: 123456789"}
{"time":"2024-03-21T05:44:55.398255075+02:00","level":"ERROR","source":{"function":"main.(*slogger).Errorf","file":"/home/andrsj/Files/tmp/log-slog/slog.go","line":34},"msg":"Echo message: sending message error"}

Тут є проблема в тому, що ніякого профіту від структурованого логування ми не отримали, лише додали форматування в JSON, який пропонує нам log/slog.JSONHandler

Змінюючи код

Я НАПОЛЯГАЮ на тому, щоб переписати логування на структуроване, без будь якого wrapper, так як ми можемо повністю закрити всі свої потреби через std log/slog

Було

log.Infof("Starting...")
log.Debugf("Echo: [%s] %s", data.firstname, data.message)
log.Infof(
	"[CALLBACK QUERY] username: %s, firstname: %s, id: %v",
	data.lastname,
	data.firstname,
	data.userID,
)
log.Errorf("Echo message: %s", errors.New("sending message error"))

Стане

log.Info("Starting...")
log.Debug("Echo",
	"first name", data.firstname,
	"message", data.message,
)
log.Info("[CALLBACK QUERY]",
	"last name", data.lastname,
	"first name", data.firstname,
	"userID", data.userID,
)
log.Error("Echo message", "error", errors.New("sending message error"))

---

Output:

{"time":"2024-03-21T06:19:12.131858068+02:00","level":"INFO","msg":"Starting..."}
{"time":"2024-03-21T06:19:12.131860116+02:00","level":"DEBUG","msg":"Echo","first name":"Andrii","message":"Hello everyone!"}
{"time":"2024-03-21T06:19:12.131862946+02:00","level":"INFO","msg":"[CALLBACK QUERY]","last name":"Derkach","first name":"Andrii","userID":123456789}
{"time":"2024-03-21T06:19:12.131866075+02:00","level":"ERROR","msg":"Echo message","error":"sending message error"}

Модифікація логгера

Якщо нам треба буде якось модифікувати логер, нам буде достатньо тих можливостей, що пропонує std бібліотека

Зміна io.Writer

При ініціалізація slog - перший параметр в Handler - це є io.Writer

В нього ми спокійно можемо передати потрібний нам Writer (хоча малоймовірно що нам таке знадобиться)

Зміна Handler (custom)

Ми маємо можливість написати свій Handler логів, якщо буде така потреба

Дивіться приклад https://betterstack.com/community/guides/logging/logging-in-go/#customizing-slog-handlers

Мені особисто сподобався приклад з PrettyHandlerOptions, але для production ready нам достатньо log/slog.JSONHandler

Я не знаю як GCP's Cloud Run handle textPayload логів (текст логів) в одну стрічку у форматі json, але маю надію що все таки він його форматує, щоб мати можливість розкрити його, як він це робить з іншими полями (для прикладу labels or resource)

Плюшки:

Strongly-typed contextual attributes

Ну тут ржака трішки)

By default які б типи ти не передавав - це завжди буде:

// Any returns an Attr for the supplied value.
// See [AnyValue] for how values are treated.
func Any(key string, value any) Attr {
	return Attr{key, AnyValue(value)}
}

В цьому AnyValue(v any) Value відбувається маппінг типів з конкретним типом Value

Тобто ті типи, які вказані в прикладі ні на що не впливають

Це лише візуальний прикол :)

---

log.Info("[CALLBACK QUERY]",
	slog.String("last name", data.lastname),
	slog.String("first name", data.firstname),
	slog.Int("userID", data.userID),
)

Grouping

log.Info("[CALLBACK QUERY]",
	slog.Group("User",
		slog.String("last name", data.lastname),
		slog.String("first name", data.firstname),
		slog.Int("userID", data.userID),
	),
)

{
	"time": "2024-03-21T06:26:43.211238448+02:00",
	"level": "INFO",
	"msg": "[CALLBACK QUERY]",
	"User": {
		"last name":"Derkach",
		"first name":"Andrii",
		"userID":123456789
	}
}

Use 3rd party backends

package main

import (
    "log/slog"

    "go.uber.org/zap"
    "go.uber.org/zap/exp/zapslog"
)

func main() {
    zapL := zap.Must(zap.NewProduction())

    defer zapL.Sync()

    logger := slog.New(zapslog.NewHandler(zapL.Core(), nil))

    logger.Info(
        "incoming request",
        slog.String("method", "GET"),
        slog.String("path", "/api/user"),
        slog.Int("status", 200),
    )
}

OR

package main

import (
    "log/slog"
    "os"

    "github.com/rs/zerolog"
    slogzerolog "github.com/samber/slog-zerolog"
)

func main() {
    zerologL := zerolog.New(os.Stdout).Level(zerolog.InfoLevel)

    logger := slog.New(
        slogzerolog.Option{Logger: &zerologL}.NewZerologHandler(),
    )

    logger.Info(
        "incoming request",
        slog.String("method", "GET"),
        slog.String("path", "/api/user"),
        slog.Int("status", 200),
    )
}

LINTER!

linters-settings:
  sloglint:
    # Enforce not mixing key-value pairs and attributes.
    # Default: true
    no-mixed-args: false
    # Enforce using key-value pairs only (overrides no-mixed-args, incompatible with attr-only).
    # Default: false
    kv-only: true
    # Enforce using attributes only (overrides no-mixed-args, incompatible with kv-only).
    # Default: false
    attr-only: true
    # Enforce using methods that accept a context.
    # Default: false
    context-only: true
    # Enforce using static values for log messages.
    # Default: false
    static-msg: true
    # Enforce using constants instead of raw keys.
    # Default: false
    no-raw-keys: true
    # Enforce a single key naming convention.
    # Values: snake, kebab, camel, pascal
    # Default: ""
    key-naming-case: snake
    # Enforce putting arguments on separate lines.
    # Default: false
    args-on-sep-lines: true

[andrsj]

@vpakhuchyi @mymmrac дайте зелене світло на перепис format string -> structured record і я зроблю все сам

Благо коду в нас не так вже і багато)

[mymmrac]

@andrsj мені все ок, але тоді як ти і написав треба додати лінтери і узгодити формат ключів, я за snake_case, але штуку з логером в контексті я б все одно залишив, щоб не юзати глобальний логер але одночасно мати його всюди де треба (контекст практично завжди прокидується)