Я столкнулся с интересной ситуацией. В моем приложении есть worker service и web service. Статус сущности Job (enum в исходном коде и integer в базе данных) изменяется в worker service (в фоновом режиме). В веб-службе есть endpoint, который возвращает некоторую информацию, включая job статус. Я поставил точку останова, отладился и обнаружил, что статус отличается от статуса в PgAdmin. Я думал, причина в Dapper. Но я попробовал простой DataReader, и поведение было таким же. Таким образом, результат запроса только для чтения в PgAdmin и среде выполнения (C #, .NET Core) различаются в одном и том же моменте времени. Я затрудняюсь понять, в чём может быть причина и как решить проблему. Я читал о MVCC в PostgreSQL. Может, дело в этом механизме. Но я не уверен.

Ключевые моменты довольно просты:

1 - статус изменяется в TransactionScope с уровнем изоляции ReadCommited путем update SQL-запроса с использованием Dapper
2 - статус считывается простым select-запросом (не в TransactionScope) с помощью Dapper / DataReader (это не столь важно)
3 - статус получается в PgAdmin с помощью простого select-запроса

Итог: статус на шаге 2 не равен статусу на шаге 3

Есть какие-то идеи?

Maxim Boguk,

возможно, я некорректно объяснил или Вы меня не поняли. У меня в Worker Service меняется статус (в TransactionScope). В веб-сервисе в get-ендпойнте я поставил точку останова. Статус в коде и при выполнении Select-запроса в PgAdmin различаются. То есть у меня сработала точка останова (на запросе, но сам запрос пока не выполнял), я пошёл и посмотрел статус в PgAdmin. Затем выполнил в коде Select-запрос и посмотрел статус в коде. Статусы не эквивалентны. Получается, что транзакция применилась, ведь результат в PgAdmin говорит об этом. Почему же тогда в коде результат совсем другой? Вот, что мне непонятно.

P.S.: select-запросы я выполняю вообще не в TransactionScope. Запросы в данном случае вообще живут в разных сервисах - один в web service, другой - в windows service.

Maxim Boguk, тут всё, как я и думал.

Последовательный лог. Update в транзакции. При этом результат в коде совсем не равен 4 (а равен 1, как видно из скриншота).

2021-04-01 20:52:49.963 MSK [9148] СООБЩЕНИЕ: выполнение <unnamed>:

UPDATE "Jobs"

SET "StatusCode" = $1, "EndedDate" = $2, "ChangeStatusTime" = $2

WHERE "Id" = $3
2021-04-01 20:52:49.963 MSK [9148] ПОДРОБНОСТИ: параметры: $1 = '4', $2 = '2021-04-01 20:52:49.960399+03', $3 = 'a6deb163-c331-4a4b-a115-fd70388eb026'
2021-04-01 20:52:49.970 MSK [9148] СООБЩЕНИЕ: оператор: COMMIT

2021-04-01 20:53:17.233 MSK [17680] СООБЩЕНИЕ: выполнение <unnamed>: SELECT "Id"

, "ImageQueryFrameId"

, "StatusCode"

, "TypeCode"

, "OperationType"

, "EndedDate"

, "CreatedDate"

, "StartedDate"

, "LeftDirection"

, "RightDirection"

, "BottomDirection"

, "LastModifiedDate"

FROM "Jobs"

WHERE "Id" = $1
2021-04-01 20:53:17.233 MSK [17680] ПОДРОБНОСТИ: параметры: $1 = 'a6deb163-c331-4a4b-a115-fd70388eb026'
2021-04-01 20:53:18.199 MSK [9192] СООБЩЕНИЕ: оператор: /*pga4dash*/

Maxim, так что Вы скажете с учётом предоставленной мною выше информации. Заранее спасибо.

Maxim Boguk,

Прикладываю вырезку из лога. Если нужно ещё что-то, прошу уточнить. Не думаю, что Вам было бы интересно разбираться в полном логе.

1. Update статуса в значение 4 (в транзакции - виден коммит)
2. Select из кода (статус != 4)
3. Ещё один Select из кода (статус != 4)
4. Select из PgAdmin (статус = 4)

Задержка по времени из-за отладки и сбора данных, но при быстром переключении результат будет таким же. То есть при одновременном взятии статуса из кода и из PgAdmin результаты различны. При том, что все select'ы выполняются после update и коммита.

Maxim Boguk,

высылаю полный лог. Запрос в PgAdmin на этот раз не делал. Его в логе нет.
Насчёт гипотезы не уверен. Чтение происходит вообще не в транзакции (явной из кода точно нет) и по стеку выполнения я сначала дожидался коммита, а затем производил чтение. Но всякое бывает.

Заранее спасибо.

Maxim Boguk,
что скажете?

Maxim Boguk,

Вы это по логу поняли или это просто догадки?

Maxim Boguk,

Прикладываю вырезку из лога. В транзакции выполняется чтение данных и обновление статуса (в значение 4), перед этим делается pg_advisory_xact_lock.
Далее select из PgAdmin с результатом 4.
Следующий select из кода (SELECT "Id", "StatusCode" FROM "Jobs") с результатом 3. Из лога видно, что Commit уже выполнен к этому времени. Да и запрос из PgAdmin возвращает обновлённое актуальное значение. А в коде другое значение.
Если немного повисеть в отладке перед выполнением команды, то вернётся 4.
Но, по моему разумению, так быть не должно. Ведь коммит уже успешно прошёл на момент get-запроса.


2021-04-17 20:27:24.140 MSK 18296 postgres@postgres from 127.0.0.1 [vxid:6/176 txid:0] []СООБЩЕНИЕ: оператор: BEGIN TRANSACTION ISOLATION LEVEL READ COMMITTED
2021-04-17 20:27:24.140 MSK 18296 postgres@postgres from 127.0.0.1 [vxid:6/176 txid:0] []СООБЩЕНИЕ: выполнение <unnamed>: SET lock_timeout = '1s'
2021-04-17 20:27:24.140 MSK 18296 postgres@postgres from 127.0.0.1 [vxid:6/176 txid:0] []СООБЩЕНИЕ: выполнение <unnamed>: SELECT pg_advisory_xact_lock(hashtext('job:f9f0a3e7-bc13-4e73-b053-cdc34d66916f'))
2021-04-17 20:27:24.141 MSK 18296 postgres@postgres from 127.0.0.1 [vxid:6/176 txid:0] []СООБЩЕНИЕ: выполнение <unnamed>: SELECT "Id"

, "ImageQueryFrameId"

, "StatusCode"

, "TypeCode"

, "OperationType"

, "EndedDate"

, "CreatedDate"

, "StartedDate"

, "LeftDirection"

, "RightDirection"

, "BottomDirection"

, "LastModifiedDate"

FROM "Jobs"

WHERE "Id" = $1
2021-04-17 20:27:24.141 MSK 18296 postgres@postgres from 127.0.0.1 [vxid:6/176 txid:0] []ПОДРОБНОСТИ: параметры: $1 = 'f9f0a3e7-bc13-4e73-b053-cdc34d66916f'
2021-04-17 20:27:24.144 MSK 18296 postgres@postgres from 127.0.0.1 [vxid:6/176 txid:0] []СООБЩЕНИЕ: выполнение <unnamed>:

UPDATE "Jobs"

SET "StatusCode" = $1, "EndedDate" = $2, "ChangeStatusTime" = $2

WHERE "Id" = $3
2021-04-17 20:27:24.144 MSK 18296 postgres@postgres from 127.0.0.1 [vxid:6/176 txid:0] []ПОДРОБНОСТИ: параметры: $1 = '4', $2 = '2021-04-17 20:27:24.142201+03', $3 = 'f9f0a3e7-bc13-4e73-b053-cdc34d66916f'
2021-04-17 20:27:24.144 MSK 18296 postgres@postgres from 127.0.0.1 [vxid:6/176 txid:54019] []СООБЩЕНИЕ: оператор: COMMIT
2021-04-17 20:27:24.147 MSK 18296 postgres@postgres from 127.0.0.1 [vxid:6/177 txid:0] []СООБЩЕНИЕ: оператор: DISCARD ALL

__________________________

2021-04-17 20:27:39.417 MSK 17644 postgres@postgres from ::1 [vxid:9/32 txid:0] []СООБЩЕНИЕ: оператор: SELECT "CreatedDate", "EndedDate", "ChangeStatusTime", "Id", "StartedDate", "StatusCode", "TypeCode", "OperationType", "ImageQueryFrameId", "LeftDirection", "RightDirection", "BottomDirection", "LastModifiedDate"
FROM dbo."Jobs" where "Id" = 'f9f0a3e7-bc13-4e73-b053-cdc34d66916f';

__________________________

2021-04-17 20:27:43.504 MSK 21200 postgres@postgres from 127.0.0.1 [vxid:10/48 txid:0] []СООБЩЕНИЕ: выполнение <unnamed>: SELECT "Id"

, "StatusCode"

FROM "Jobs"

WHERE "Id" = 'f9f0a3e7-bc13-4e73-b053-cdc34d66916f'

Maxim Boguk,

Вижу разрыв соединения, но откуда он. Влияет ли это. Повисеть в отладке - ну секунд 5, быть может. Иногда подольше. Я точно не замерял.

2021-04-17 20:27:19.129 MSK 21200 postgres@postgres from 127.0.0.1 [vxid:10/45 txid:0] []СООБЩЕНИЕ: оператор: DISCARD ALL
2021-04-17 20:27:19.129 MSK 21200 postgres@postgres from 127.0.0.1 [vxid:10/46 txid:0] []СООБЩЕНИЕ: оператор: BEGIN ISOLATION LEVEL REPEATABLE READ
2021-04-17 20:27:19.130 MSK 21200 postgres@postgres from 127.0.0.1 [vxid:10/46 txid:0] []СООБЩЕНИЕ: выполнение <unnamed>: SELECT "Id"

, "ImageQueryFrameId"

, "StatusCode"

, "TypeCode"

, "OperationType"

, "EndedDate"

, "CreatedDate"

, "StartedDate"

, "LeftDirection"

, "RightDirection"

, "BottomDirection"

, "LastModifiedDate"

FROM "Jobs"

WHERE "Id" = $1
2021-04-17 20:27:19.130 MSK 21200 postgres@postgres from 127.0.0.1 [vxid:10/46 txid:0] []ПОДРОБНОСТИ: параметры: $1 = 'f9f0a3e7-bc13-4e73-b053-cdc34d66916f'
2021-04-17 20:27:19.131 MSK 21200 postgres@postgres from 127.0.0.1 [vxid:10/46 txid:0] []СООБЩЕНИЕ: оператор: COMMIT
2021-04-17 20:27:19.134 MSK 21200 postgres@postgres from 127.0.0.1 [vxid:10/47 txid:0] []СООБЩЕНИЕ: оператор: DISCARD ALL
2021-04-17 20:27:19.134 MSK 21200 postgres@postgres from 127.0.0.1 [vxid:10/48 txid:0] []СООБЩЕНИЕ: оператор: BEGIN ISOLATION LEVEL REPEATABLE READ
2021-04-17 20:27:19.135 MSK 21200 postgres@postgres from 127.0.0.1 [vxid:10/48 txid:0] []СООБЩЕНИЕ: выполнение <unnamed>: SELECT "Id"

, "ImageQueryFrameId"

, "StatusCode"

, "TypeCode"

, "OperationType"

, "EndedDate"

, "CreatedDate"

, "StartedDate"

, "LeftDirection"

, "RightDirection"

, "BottomDirection"

, "LastModifiedDate"

FROM "Jobs"

WHERE "Id" = $1
2021-04-17 20:27:19.135 MSK 21200 postgres@postgres from 127.0.0.1 [vxid:10/48 txid:0] []ПОДРОБНОСТИ: параметры: $1 = 'f9f0a3e7-bc13-4e73-b053-cdc34d66916f'
2021-04-17 20:27:19.235 MSK 21200 postgres@postgres from 127.0.0.1 [vxid:10/48 txid:0] []СООБЩЕНИЕ: выполнение <unnamed>: SELECT EXISTS (SELECT 1

FROM information_schema.tables

WHERE table_schema = (select current_schema()) AND table_name = $1)
2021-04-17 20:27:19.235 MSK 21200 postgres@postgres from 127.0.0.1 [vxid:10/48 txid:0] []ПОДРОБНОСТИ: параметры: $1 = 'j_f9f0a3e7bc134e73b053cdc34d66916f'
2021-04-17 20:27:19.242 MSK 21200 postgres@postgres from 127.0.0.1 [vxid:10/48 txid:0] []СООБЩЕНИЕ: выполнение <unnamed>: SELECT COUNT(*) FROM "j_f9f0a3e7bc134e73b053cdc34d66916f"
2021-04-17 20:27:19.245 MSK 21200 postgres@postgres from 127.0.0.1 [vxid:10/48 txid:0] []СООБЩЕНИЕ: выполнение <unnamed>: SELECT count(crawledImages."Id")

FROM "Scores" as scores

INNER JOIN "CrawledImages" as crawledImages

ON scores."CrawledImageId" = crawledImages."Id"

WHERE scores."ImageQueryFrameId" = $1

AND scores."MatchingType" = $2
2021-04-17 20:27:19.245 MSK 21200 postgres@postgres from 127.0.0.1 [vxid:10/48 txid:0] []ПОДРОБНОСТИ: параметры: $1 = 'a397f45e-198b-4b3b-bac0-eaaf0b692347', $2 = '6'

2021-04-17 20:27:43.504 MSK 21200 postgres@postgres from 127.0.0.1 [vxid:10/48 txid:0] []СООБЩЕНИЕ: выполнение <unnamed>: SELECT "Id"

, "StatusCode"

FROM "Jobs"

WHERE "Id" = 'f9f0a3e7-bc13-4e73-b053-cdc34d66916f'

2021-04-17 20:33:56.665 MSK 21200 postgres@postgres from 127.0.0.1 [vxid:10/48 txid:0] []СООБЩЕНИЕ: не удалось получить данные от клиента: An existing connection was forcibly closed by the remote host.


2021-04-17 20:33:56.665 MSK 21200 postgres@postgres from 127.0.0.1 [vxid:10/48 txid:0] []СООБЩЕНИЕ: неожиданный обрыв соединения с клиентом при открытой транзакции

Maxim Boguk,

понял, спасибо. Действительно у меня создаётся транзакция функцией выше.

Но не до конца понял. У меня нет RepeatableRead, у меня выставлен уровень изоляции Shapshot.
Как я понимаю, это когда на момент начала транзакции делается снимок состояния. Ок. Но тогда почему, если повисеть в отладке, то значение становится актуальным. Мы же делали снимок на момент начала транзакции. То есть значение не должно меняться в принципе со временем. Сделали снимок - зафиксировали. Если я всё верно понял.