please help to resolve race-condition in zerolog #555

Slach · 2023-06-13T19:36:47Z

@rs
i have race-condition ;(
https://github.com/Altinity/clickhouse-backup/actions/runs/5259410860/jobs/9504979925#step:7:2222

WARNING: DATA RACE
Write at 0x00c000109440 by goroutine 30:
  github.com/rs/zerolog.newEvent()
      /home/runner/go/pkg/mod/github.com/rs/zerolog@v1.29.1/event.go:60 +0xd9
  github.com/rs/zerolog.(*Logger).newEvent()
      /home/runner/go/pkg/mod/github.com/rs/zerolog@v1.29.1/log.go:453 +0xec
  github.com/rs/zerolog.(*Logger).Info()
      /home/runner/go/pkg/mod/github.com/rs/zerolog@v1.29.1/log.go:334 +0x59
  github.com/Altinity/clickhouse-backup/pkg/clickhouse.(*ClickHouse).LogQuery()
      /home/runner/work/clickhouse-backup/clickhouse-backup/pkg/clickhouse/clickhouse.go:917 +0x2e4
  github.com/Altinity/clickhouse-backup/pkg/clickhouse.(*ClickHouse).Query()
      /home/runner/work/clickhouse-backup/clickhouse-backup/pkg/clickhouse/clickhouse.go:887 +0x193
  github.com/Altinity/clickhouse-backup/pkg/partition.GetPartitionId()
      /home/runner/work/clickhouse-backup/clickhouse-backup/pkg/partition/partition.go:60 +0x1058
  github.com/Altinity/clickhouse-backup/pkg/filesystemhelper.CreatePartitionsToBackupMap()
      /home/runner/work/clickhouse-backup/clickhouse-backup/pkg/filesystemhelper/filesystemhelper.go:305 +0x14d9
  github.com/Altinity/clickhouse-backup/pkg/backup.(*Backuper).downloadTableMetadata()
      /home/runner/work/clickhouse-backup/clickhouse-backup/pkg/backup/download.go:386 +0x33f7
  github.com/Altinity/clickhouse-backup/pkg/backup.(*Backuper).Download.func2()
      /home/runner/work/clickhouse-backup/clickhouse-backup/pkg/backup/download.go:196 +0x8b2
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /home/runner/go/pkg/mod/golang.org/x/sync@v0.2.0/errgroup/errgroup.go:75 +0x133

Previous read at 0x00c000109440 by goroutine 31:
  github.com/rs/zerolog.putEvent()
      /home/runner/go/pkg/mod/github.com/rs/zerolog@v1.29.1/event.go:40 +0x3c
  github.com/rs/zerolog.(*Event).write()
      /home/runner/go/pkg/mod/github.com/rs/zerolog@v1.29.1/event.go:81 +0x339
  github.com/rs/zerolog.(*Event).msg()
      /home/runner/go/pkg/mod/github.com/rs/zerolog@v1.29.1/event.go:149 +0x55d
  github.com/rs/zerolog.(*Event).Msg()
      /home/runner/go/pkg/mod/github.com/rs/zerolog@v1.29.1/event.go:108 +0x64
  github.com/Altinity/clickhouse-backup/pkg/clickhouse.(*ClickHouse).LogQuery()
      /home/runner/work/clickhouse-backup/clickhouse-backup/pkg/clickhouse/clickhouse.go:922 +0xc71
  github.com/Altinity/clickhouse-backup/pkg/clickhouse.(*ClickHouse).Query()
      /home/runner/work/clickhouse-backup/clickhouse-backup/pkg/clickhouse/clickhouse.go:887 +0x193
  github.com/Altinity/clickhouse-backup/pkg/partition.GetPartitionId()
      /home/runner/work/clickhouse-backup/clickhouse-backup/pkg/partition/partition.go:60 +0x1058
  github.com/Altinity/clickhouse-backup/pkg/filesystemhelper.CreatePartitionsToBackupMap()
      /home/runner/work/clickhouse-backup/clickhouse-backup/pkg/filesystemhelper/filesystemhelper.go:305 +0x14d9
  github.com/Altinity/clickhouse-backup/pkg/backup.(*Backuper).downloadTableMetadata()
      /home/runner/work/clickhouse-backup/clickhouse-backup/pkg/backup/download.go:386 +0x33f7
  github.com/Altinity/clickhouse-backup/pkg/backup.(*Backuper).Download.func2()
      /home/runner/work/clickhouse-backup/clickhouse-backup/pkg/backup/download.go:196 +0x8b2
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /home/runner/go/pkg/mod/golang.org/x/sync@v0.2.0/errgroup/errgroup.go:75 +0x133

when try to use zerolog with multiple go-routines + errorgroup

LogQuery() related code

import (
	"context"
	"fmt"
	"github.com/rs/zerolog"
	"github.com/rs/zerolog/log"
	"github.com/rs/zerolog/pkgerrors"
	"github.com/urfave/cli"
	stdlog "log"
	"os"
)
...
	zerolog.TimeFieldFormat = zerolog.TimeFormatUnixMs
	zerolog.ErrorStackMarshaler = pkgerrors.MarshalStack
	log.Logger = zerolog.New(zerolog.SyncWriter(os.Stdout)).With().Timestamp().Caller().Logger()
	stdlog.SetOutput(log.Logger)
...
type ClickHouse struct {
	Config               *config.ClickHouseConfig
	conn                 driver.Conn
	disks                []Disk
	Logger               zerolog.Logger
	version              int
	isPartsColumnPresent int8
	IsOpen               bool
}

...
	ch := &clickhouse.ClickHouse{
		Config: &api.config.ClickHouse,
		Logger: log.With().Str("logger", "clickhouse").Logger(),
	}
...
func (ch *ClickHouse) LogQuery(query string, args ...interface{}) string {
	var logF *zerolog.Event
	// zerolog is not thread-safe https://github.com/rs/zerolog/issues/242 ;(
	logger := ch.Logger.With().Logger()
	if !ch.Config.LogSQLQueries {
		logF = logger.Debug()
	} else {
		logF = logger.Info()
	}
	if len(args) > 0 {
		logF.Msg(strings.NewReplacer("\n", " ", "\r", " ", "\t", " ").Replace(fmt.Sprintf("%s with args %v", query, args)))
	} else {
		logF.Msg(strings.NewReplacer("\n", " ", "\r", " ", "\t", " ").Replace(query))
	}
	return query
}

How race condition possible here?
i redefine log.Logger once in main function

and after it use copy of logger

Logger: log.With().Str("logger", "clickhouse").Logger(),
and copy of copy
logger := ch.Logger.With().Logger()

during execution of With() it shall create copy of Logger

what i'm doing wrong?

The text was updated successfully, but these errors were encountered:

…erolog.Disabled

… ConsoleWriter, increase some clickhouse timeout in test config, cause clickhouse-go/v2 got some timeouts during execution

…logger in upload.go

… try to remove all local loggers with context upload.go

…erolog.Disabled

sruehl · 2023-08-08T16:41:35Z

@Slach could you try this?

func (ch *ClickHouse) LogQuery(query string, args ...interface{}) string {
	level := zerolog.InfoLevel
	if !ch.Config.LogSQLQueries {
                level = zerolog.DebugLevel
	}
	if len(args) > 0 {
		ch.Logger.WithLevel(level).Msg(strings.NewReplacer("\n", " ", "\r", " ", "\t", " ").Replace(fmt.Sprintf("%s with args %v", query, args)))
	} else {
        	ch.Logger.WithLevel(level).Msg(strings.NewReplacer("\n", " ", "\r", " ", "\t", " ").Replace(query))
	}
	return query
}

Trying to confirm if that might help.

Slach · 2023-08-12T15:00:16Z

@sruehl I can't thank you enough, it works, you save many debug hours

… gone away, need pull and resolve conflicts from master

Slach · 2023-08-13T12:35:32Z

=( but found race condition in other place

WARNING: DATA RACE
Write at 0x00c000448655 by goroutine 34:
  github.com/rs/zerolog/internal/json.Encoder.AppendString()
      /home/runner/go/pkg/mod/github.com/rs/zerolog@v1.30.0/internal/json/string.go:63 +0x71d
  github.com/rs/zerolog/internal/json.Encoder.AppendKey()
      /home/runner/go/pkg/mod/github.com/rs/zerolog@v1.30.0/internal/json/base.go:18 +0x275
  github.com/rs/zerolog.(*Event).Str()
      /home/runner/go/pkg/mod/github.com/rs/zerolog@v1.30.0/event.go:256 +0xea
  github.com/Altinity/clickhouse-backup/pkg/backup.(*Backuper).downloadTableMetadata()
      /home/runner/work/clickhouse-backup/clickhouse-backup/pkg/backup/download.go:412 +0x3c24
  github.com/Altinity/clickhouse-backup/pkg/backup.(*Backuper).Download.func2()
      /home/runner/work/clickhouse-backup/clickhouse-backup/pkg/backup/download.go:197 +0x44e
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /home/runner/go/pkg/mod/golang.org/x/sync@v0.3.0/errgroup/errgroup.go:75 +0x133

Previous write at 0x00c000448655 by goroutine 33:
  github.com/rs/zerolog/internal/json.Encoder.AppendString()
      /home/runner/go/pkg/mod/github.com/rs/zerolog@v1.30.0/internal/json/string.go:63 +0x71d
  github.com/rs/zerolog/internal/json.Encoder.AppendKey()
      /home/runner/go/pkg/mod/github.com/rs/zerolog@v1.30.0/internal/json/base.go:18 +0x275
  github.com/rs/zerolog.(*Event).Str()
      /home/runner/go/pkg/mod/github.com/rs/zerolog@v1.30.0/event.go:256 +0xea
  github.com/Altinity/clickhouse-backup/pkg/backup.(*Backuper).downloadTableMetadata()
      /home/runner/work/clickhouse-backup/clickhouse-backup/pkg/backup/download.go:412 +0x3c24
  github.com/Altinity/clickhouse-backup/pkg/backup.(*Backuper).Download.func2()
      /home/runner/work/clickhouse-backup/clickhouse-backup/pkg/backup/download.go:197 +0x44e
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /home/runner/go/pkg/mod/golang.org/x/sync@v0.3.0/errgroup/errgroup.go:75 +0x133

backup/download.go:412

// simple import zerolog
import (
	"github.com/rs/zerolog/log"
)

func (b *Backuper) downloadTableMetadata(ctx context.Context, backupName string, disks []clickhouse.Disk, tableTitle metadata.TableTitle, schemaOnly bool, partitions []string) (*metadata.TableMetadata, uint64, error) {

...
	log.Info().
		Str("operation", "download_metadata").
		Str("backup", backupName).
		Str("duration", utils.HumanizeDuration(time.Since(start))).
		Str("size", utils.FormatBytes(size)).
		Msg("done")
	return &tableMetadata, size, nil
}

just one function without instances of zerolog.Logger, which called inside pool of go-routines

	downloadSemaphore := semaphore.NewWeighted(int64(b.cfg.General.DownloadConcurrency))
	metadataGroup, metadataCtx := errgroup.WithContext(ctx)
	for i, t := range tablesForDownload {
...
		metadataGroup.Go(func() error {
			defer downloadSemaphore.Release(1)
			if err != nil {
				return err
			}
		})
	}
	if err := metadataGroup.Wait(); err != nil {
		return fmt.Errorf("one of Download Metadata go-routine return error: %v", err)
	}

Any ideas why it happen? and how to resolve it?

main.go
with zerolog initialization

import (
	stdlog "log"
	"github.com/rs/zerolog"
	"github.com/rs/zerolog/log"
	"github.com/rs/zerolog/pkgerrors"
)

func main() {
	zerolog.TimeFieldFormat = zerolog.TimeFormatUnixMs
	zerolog.ErrorStackMarshaler = pkgerrors.MarshalStack
	consoleWriter := zerolog.ConsoleWriter{Out: os.Stdout, NoColor: true, TimeFormat: "2006-01-02 15:04:05.000"}
	log.Logger = zerolog.New(zerolog.SyncWriter(consoleWriter)).With().Timestamp().Caller().Logger()
	stdlog.SetOutput(log.Logger)
...
}

Slach added a commit to Altinity/clickhouse-backup that referenced this issue Jun 13, 2023

debug thread-safe zerolog usage, rs/zerolog#555, try to apply force z…

907377c

…erolog.Disabled

Slach added a commit to Altinity/clickhouse-backup that referenced this issue Jun 14, 2023

debug thread-safe zerolog usage, rs/zerolog#555, try to remove local …

fd90f25

…logger in upload.go

Slach added a commit to Altinity/clickhouse-backup that referenced this issue Jun 14, 2023

zerolog completelly useless for multiple go-routines ;( rs/zerolog#555,…

eea4f62

… try to remove all local loggers with context upload.go

Slach mentioned this issue Jun 14, 2023

[WIP] try switch to Zerolog Altinity/clickhouse-backup#670

Open

mskwon pushed a commit to mskwon/clickhouse-backup that referenced this issue Jun 14, 2023

debug thread-safe zerolog usage, rs/zerolog#555, try to apply force z…

752a7d8

…erolog.Disabled

Slach closed this as completed Aug 12, 2023

Slach added a commit to Altinity/clickhouse-backup that referenced this issue Aug 12, 2023

apply fixes from rs/zerolog#555 (comment), looks like race conditions…

98245c3

… gone away, need pull and resolve conflicts from master

Slach reopened this Aug 13, 2023

Slach added a commit to Altinity/clickhouse-backup that referenced this issue Aug 13, 2023

try debug zerolog race condition rs/zerolog#555

2d000c5

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

please help to resolve race-condition in zerolog #555

please help to resolve race-condition in zerolog #555

Slach commented Jun 13, 2023

sruehl commented Aug 8, 2023

Slach commented Aug 12, 2023

Slach commented Aug 13, 2023 •

edited

please help to resolve race-condition in zerolog #555

please help to resolve race-condition in zerolog #555

Comments

Slach commented Jun 13, 2023

sruehl commented Aug 8, 2023

Slach commented Aug 12, 2023

Slach commented Aug 13, 2023 • edited

Slach commented Aug 13, 2023 •

edited