openlang

-race сообщает DATA RACE, хотя ack — это приём из небуферизованного канала. Виноват time.After?

Может ли быть, что race detector здесь ошибается, или я неправильно понимаю, что мне даёт ack? Это pushgate, небольшой сервис, который проверяет HMAC-подписи у токенов устройств для пуш-уведомлений в моём мобильном приложении. Вызывающий код шлёт Request в небуферизованный канал, воркер заполняет Result, потом отправляет ID в канал ack. Вызывающий читает Result только после получения ack. Тесты я специально написал так, чтобы там не было time.Sleep. select с time.After нужен только затем, чтобы зависший тест завершался.

Обычный go test всегда зелёный. Сегодня перед тегированием релиза я запустил go test -race -count=200 ./.... Примерно один запуск из 30-40 выводит WARNING: DATA RACE, с чтением в горутине теста и записью в горутине воркера. Со стороны воркера указывает на verify.go, со стороны теста на строку с t.Logf в verify_test.go. Похоже, чаще это происходит в TestWorkerRejectsBadSig, но я не уверен.

Что я пробовал:

  • буферизованный канал ack: гонка стала появляться чаще, так что вернул как было
  • -cpu 1: гонка пропадает, но я этому не доверяю
  • у старого Result было два поля, а на прошлой неделе я добавил timestamp для аудит-логов. Не вижу, почему это должно иметь значение

Воркер:

for r := range in {
	want := sign(secret, r.Token)
	ok := hmac.Equal([]byte(want), []byte(r.Sig))

	r.Result.DeviceID = r.ID
	r.Result.Valid = ok
	ack <- r.ID

	// stamp after the ack so the caller is not kept waiting
	r.Result.Checked = time.Now()
	if verbose {
		log.Printf("checked device=%d valid=%v", r.ID, ok)
	}
}

Тест, который падает чаще:

func TestWorkerRejectsBadSig(t *testing.T) {
	res := runOne(t, 9, "apns-abc123", "deadbeef")
	t.Logf("result for bad sig: %+v", *res)
	if res.Valid {
		t.Fatal("bad signature accepted")
	}
	if res.DeviceID != 9 {
		t.Fatalf("device id %d", res.DeviceID)
	}
}

runOne создаёт оба канала через обычный make(chan ...), запускает воркер, отправляет Request, затем делает select по ack и time.After(2 * time.Second) и возвращает res. Я читал https://go.dev/ref/mem, но всё равно не вижу, где ломается порядок. Может, указатель внутри структуры что-то скрывает от детектора?

Переведено с английскогоПоказать оригинал

Разговор продолжается 4

Следуя доводам
  1. Ссылка на ответ

    Нашлось, и детектор был прав)) Проблема в моём же комментарии, "stamp after the ack". Ack упорядочивает только те записи, которые происходят до него. r.Result.Checked = time.Now() выполняется после ack <- r.ID, так что ничто не упорядочивает эту запись относительно чтения на стороне вызывающего. t.Logf("%+v", *res) копирует всю структуру, включая Checked, пока воркер может её ещё писать.

    Это же объясняет всё остальное:

    • С двумя полями оба писались до ack, поэтому гонки не было. Таймстемп, добавленный на прошлой неделе, — первая запись после ack.
    • -cpu 1 это скрывает, потому что воркер редко успевает выполниться в этом окне.
    • Буферизованный ack делает хуже, потому что воркер никогда не блокируется на отправке, и до поздней записи добирается раньше.
    • TestWorkerRejectsBadSig падает чаще, потому что это единственный тест, который логирует всю структуру. Остальные читают отдельные поля, так что попадают на гонку, только если случайно читают Checked.

    Фикс — перенести штамп до ack:

    r.Result.DeviceID = r.ID
    r.Result.Valid = ok
    r.Result.Checked = time.Now()
    ack <- r.ID

    Отправка happens-before завершения приёма, как в разделе "Channel communication" на https://go.dev/ref/mem. Повторный прогон -race -count=200 чистый. log.Printf после ack в порядке, потому что не трогает Result.

    Переведено с английскогоПоказать оригинал
  2. Ссылка на ответ

    Небольшое дополнение для тех, кто найдёт это потом. Комментарий над отправкой теперь такой: "everything the caller reads is written before this line", а штамп стоит прямо под двумя другими полями. Неправильный комментарий и сбил с толку с самого начала.

    Ещё статья про race detector на этот раз прочитана как следует: https://go.dev/doc/articles/race_detector. Там сказано, что детектор сообщает только о гонках, которые реально произошли в этом прогоне. Так что мой зелёный обычный go test ничего не доказывал, а чистый -count=200 — это свидетельство, а не гарантия. Поэтому теперь -race стоит в предрелизном скрипте, а не только в голове.

    Если audit-таймстемп обязательно писать после ack, воркер мог бы отправлять его вторым сообщением, либо вызывающая сторона могла бы копировать Result только после более поздней точки синхронизации. Для pushgate это не нужно, так что обошлось без этого.

    Забавно, что такая же ошибка в Android-клиенте проявилась бы редким крашем в логах пользователя, а на ноутбуке её было бы не воспроизвести))

    Переведено с английскогоПоказать оригинал
  3. Ссылка на ответ

    Не соглашусь, по-моему, детектор не ошибается. Запись после ack как раз и выглядит гонкой. Зачем вообще шарить указатель на Result? Почему не отправлять Result по значению через канал? Признаю, из-за audit-таймстемпа это выходит немного неудобно.

    Переведено с английскогоПоказать оригинал

Другие стороны того же вопроса

  1. Несовпадение HMAC только на одном вебхуке (с акцентами в имени)

    Написал небольшой чекер на Node (чистый JS, без сборки): он переигрывает сохранённые доставки вебхуков и проверяет HMAC-SHA25…

    Ответы 7Последняя активность typescriptjavascript
  2. memset перед free проходит с флагами по умолчанию, падает с OPT=-O2

    Делаю небольшое хранилище учётных данных на C, называется vault, собираю в WSL. vault_release() должна затирать секрет и пото…

    Ответы 6Последняя активность c
  3. Одна и та же проверка переполнения, разные ветки ошибки на -O0 и -O2

    Враждебный pack с count=65536 и rec_size=32768. На -O0 получаю "pack too large". На -O2 вместо этого получаю "out of memory".…

    Ответы 6Последняя активность c