Open def- opened 8 months ago
petrosagg
commented
8 months ago I see this strange log for the panicking source that I haven't seen before.
pg-cdc-materialized-1 | cluster-u1-replica-u1: 2024-01-12T08:39:20.267823Z INFO mz_storage::healthcheck: Health transition for source u186: Some(Starting) -> Some(Stalled { error: "postgres: No such file or directory (os error 2)", hints: {}, namespaced_errors: {Postgres: "No such file or directory (os error 2)"} })A few more findings. In the postgres logs we see the following three CREATE_REPLICATION_SLOT statements being executed:
pg-cdc-postgres-1 | 2024-01-12 08:39:20.252 UTC [3040] LOG: logical decoding found consistent point at 0/57AC6490
pg-cdc-postgres-1 | 2024-01-12 08:39:20.252 UTC [3040] DETAIL: There are no running transactions.
pg-cdc-postgres-1 | 2024-01-12 08:39:20.252 UTC [3040] STATEMENT: CREATE_REPLICATION_SLOT materialize_ad4e3ba33924431bb4668267a8cfaa8d LOGICAL "pgoutput" NOEXPORT_SNAPSHOT
pg-cdc-postgres-1 | 2024-01-12 08:39:20.257 UTC [3040] LOG: logical decoding found consistent point at 0/57AC64C8
pg-cdc-postgres-1 | 2024-01-12 08:39:20.257 UTC [3040] DETAIL: There are no running transactions.
pg-cdc-postgres-1 | 2024-01-12 08:39:20.257 UTC [3040] STATEMENT: CREATE_REPLICATION_SLOT "mzsnapshot_7ece96c5f3fb4627824f82609089811d" TEMPORARY LOGICAL "pgoutput" USE_SNAPSHOT
pg-cdc-postgres-1 | 2024-01-12 08:39:20.337 UTC [3054] LOG: logical decoding found consistent point at 0/57AC6500
pg-cdc-postgres-1 | 2024-01-12 08:39:20.337 UTC [3054] DETAIL: There are no running transactions.
pg-cdc-postgres-1 | 2024-01-12 08:39:20.337 UTC [3054] STATEMENT: CREATE_REPLICATION_SLOT materialize_ad4e3ba33924431bb4668267a8cfaa8d LOGICAL "pgoutput" NOEXPORT_SNAPSHOTThe first creates the normal slot, the second one creates the slot that is used for snapshotting the tables, and the third one attempts to create the normal slot again. This is expected because there are two dataflow operators involved in pg sources, a snapshot operator and a replication operator. The snapshot operator first creates the normal slot, then the temporary one for snapshotting tables. The replication operator only attempts to create the normal slot.
The ordering is this way to ensure that the LSN at which we snapshot the tables (which is the consistent point of the temporary slot) is greater than the LSN of the normal slot, which is why the normal slot is always created first.
From the logs we see the following consistent points for each attempt:
0/57AC64900/57AC64C80/57AC6500These look correct because 0x57AC6490 < 0x57AC64C8.
Now if we look at the log of the panic (with LSNs converted to hex) it says the following:
slot compacted past snapshot point. snapshot consistent point=0/57AC6500 resume_lsn=0/57AC6538What is strange here is that the snapshot consistent point is claimed to be the LSN we got in the third attempt of creating the normal slot. But according to the code that LSN should have been 0/57AC64C8, the LSN of the temporary slot. Furthermore the resume LSN should be the LSN of the normal slot, but the value 0/57AC6538 doesn't appear anywhere in the logs.
I don't see anything related to #24240 so far but something seems off about our assumption of postgres slots and how they work.
petrosagg
commented
8 months ago Ok so the postgres logs posted above are extra weird because we see that the second attempt to create the normal slots succeeds whereas when I tried the same sequence of actions on my local machine the second attempt gets a "slot already exists" error. Indeed if we scroll up in the postgres logs to see what happens with other sources of the test we see this exact thing happening:
pg-cdc-postgres-1 | 2024-01-12 08:36:08.112 UTC [148] LOG: logical decoding found consistent point at 0/1527940
pg-cdc-postgres-1 | 2024-01-12 08:36:08.112 UTC [148] DETAIL: There are no running transactions.
pg-cdc-postgres-1 | 2024-01-12 08:36:08.112 UTC [148] STATEMENT: CREATE_REPLICATION_SLOT materialize_072a433738dc445ab1809fedae925eb1 LOGICAL "pgoutput" NOEXPORT_SNAPSHOT
pg-cdc-postgres-1 | 2024-01-12 08:36:08.113 UTC [148] LOG: logical decoding found consistent point at 0/1527978
pg-cdc-postgres-1 | 2024-01-12 08:36:08.113 UTC [148] DETAIL: There are no running transactions.
pg-cdc-postgres-1 | 2024-01-12 08:36:08.113 UTC [148] STATEMENT: CREATE_REPLICATION_SLOT "mzsnapshot_0a3dc935b4a747dc845f3e775b3d82fd" TEMPORARY LOGICAL "pgoutput" USE_SNAPSHOT
pg-cdc-postgres-1 | 2024-01-12 08:36:08.117 UTC [152] ERROR: replication slot "materialize_072a433738dc445ab1809fedae925eb1" already exists
pg-cdc-postgres-1 | 2024-01-12 08:36:08.117 UTC [152] STATEMENT: CREATE_REPLICATION_SLOT materialize_072a433738dc445ab1809fedae925eb1 LOGICAL "pgoutput" NOEXPORT_SNAPSHOTThis indicates that postgres does not guarantee that in the presence of two concurrent CREATE_REPLICATION_SLOT queries one of them will get a "slot already exists" error. It looks like it's possible for BOTH to succeed and for the second one to overwrite the details of the first. I will try to reproduce that.
petrosagg
commented
8 months ago I have been running this hot loop code against the postgres container spun up by mzcompose both when that container is idle and while the full testcase is running concurrently:
#[tokio::main]
async fn main() {
let mut config = Config::new();
config
.host("127.0.0.1")
.port(32768)
.user("postgres")
.password("postgres")
.replication_mode(ReplicationMode::Logical);
let (client1, connection1) = config.connect(NoTls).await.unwrap();
tokio::spawn(connection1);
let (client2, connection2) = config.connect(NoTls).await.unwrap();
tokio::spawn(connection2);
client1.simple_query("SELECT pg_drop_replication_slot(slot_name) FROM pg_replication_slots").await.unwrap();
let name = "materialize_ad4e3ba33924431bb4668267a8cfaa8d";
let create_q = format!("CREATE_REPLICATION_SLOT {name} LOGICAL \"pgoutput\" NOEXPORT_SNAPSHOT;");
let drop_q = format!("SELECT pg_drop_replication_slot('{name}')");
loop {
// Then we try to create it concurrently from both clients
let req1 = client1.simple_query(&create_q);
let req2 = client2.simple_query(&create_q);
match futures::future::join(req1, req2).await {
(Ok(_), Ok(_)) => panic!("Both clients succeeded"),
(Err(err1), Err(err2)) => {
println!("client1 error: {err1}");
println!("client2 error: {err2}");
panic!("Both clients failed");
}
_ => {
// Drop the slot to try again
client1.simple_query(&drop_q).await.unwrap();
}
}
}
}This busy loops trying to create the same slot concurrently but I didn't the condition we see in the logs even once. I looked at the postgres source code and the section that creates replication slots is well guarded by an exclusive lock: https://github.com/postgres/postgres/blob/master/src/backend/replication/slot.c#L263-L289
We still have the unexplained error from postgres that MZ logs ("No such file or directory (os error 2)"}) which happens at 2024-01-12T08:39:20.267823Z. This timestamp is between the second and the third CREATE_REPLICATION_SLOT query so it's unclear what this means. Creating a replication slot does involve writing files and directories on disk so maybe that error is related to one of the slots failing to get created. There isn't any relevant log from the postgres container though.
We additionally know that the first and second queries were performed by the snapshot operator because they share the same PID (3040) and the third one comes from the replication operator whose PID is (3054). What is even more confusing is that none of the ensure_replication_slot calls could have produced the No such file.. error because in all cases we have evidence of code that is after those lines running. For the snapshot operator we know it made progress after creating the slots because it let the replication operator know about rewinds (because the panic comes from processing rewinds). For the replication operator we know it made progress after creating the slots because the panic is after that point.
I will call it a day for today, I can't think of another theory. I'm pretty convinced this is unrelated to any recent code changes and we're just observing some rare race/bug.
petrosagg
commented
8 months ago The weird error might be related to ssh tunnels which were used for this connection. The previous line from the one saying "File not found" is:
pg-cdc-materialized-1 | cluster-u1-replica-u1: 2024-01-12T08:39:20.267289Z INFO mz_postgres_util::tunnel: connecting task_name=postgres_connect_replication address=postgres@postgres:5432/postgresStill does not explain why pg created the slot twice but it might explain why there isn't any similar error log in the pg logs
petrosagg
commented
8 months ago Ok, I found what's going on. We have a test that creates a postgres source only to verify that subsource resolution works correctly (i.e it doesn't query the data at all), which means that the source is created and then almost immediately afterwards dropped. This is the test: https://github.com/MaterializeInc/materialize/blob/main/test/pg-cdc/subsource-resolution-duplicates.td#L52-L59
When the adapter drops a postgres source it also cleans up its replication slot, and it does so in a retry loop. This means that the slot cleanup task is racing with dataflow creation because clusterd does not yet know that the source has been dropped.
So what happened here is the following interleaving:
u186CreateIngestion command to clusterdu186, which started the cleanup taskclusterd rendered the ingestion dataflow for u186snapshot operator created the normal slot and then the temporary snapshot slotreplication operator created the normal slot again, getting a different LSNI think what we can do is turn the panic into a definite error that permanently errors the source since this either happens as a result of this race or as a result of the user manually dropping the source from the upstream database.
Definitely not a release blocker though, phew! Removing the label
def-
commented
6 months ago
What version of Materialize are you using?
43c65e6c8545
What is the issue?
Seen in https://buildkite.com/materialize/tests/builds/72946#018cfccc-477b-40da-8c1d-108336a3e402, but is unrelated to my PR.
I think this came from https://github.com/MaterializeInc/materialize/pull/24240 @petrosagg Can you please check?
ci-regexp: slot compacted past snapshot point