sqitch check reveals divergence after fresh database deploy, sha1 hashes match

[the-noob-of-northrose]

EDIT: NOT A SQITCH PROBLEM
See my final comment. This issue was caused by the NTP service running in WSL2. If you use systemd in your WSL2 distribution, check to see if the NTP service is active with timedatectl status. If so, disabling it with systemctl stop systemd-timesyncd && systemctl disable systemd-timesyncd (requires elevated permissions) may do the trick.

Good afternoon,

My team has a sqitch plan with, at the time of writing, 542 changes.

A colleague edited a recent change during development, and as I have been doing for a while now, I pulled the changes down and ran sqitch rebase --modified. However, I noticed that it wanted to revert to a change waaaay further back, one that hasn't been modified in many months, if ever.

After confirming the divergence with sqitch check, I calculated the sha1 hash (using my OS's built-in sha1sum tool) of the deploy script it claims to diverge at, as well as the hashes of the scripts for the previous and next changes, and compared these to what is in the sqitch.changes table:

They match (wtf?)

I deleted the database and did a fresh sqitch deploy. sqitch check told me that there was a divergence at a different change (...wtf??)

I deleted and redeployed again, several times, in fact, and sqitch check reported divergences at different changes each time (WTF???)

I had not manually edited any deploy files during this testing, nor did I pull any new changes from our git repo.

This issue has apparently not been affecting my coworkers. I am so, so confused. I'm not sure if this is a sqitch bug or if I just don't understand how check actually works and I'm therefore not barking up the right tree for troubleshooting.

System info:

• My OS: Windows 10, Ubuntu 22.04 LTS and Debian 12 (Bookworm), both through WSL.
• postgres server Docker image: postgres:14-bullseye
• sqitch version: 1.3.1 on Debian, 1.2.1 on Ubuntu, same results with each.

What I have tried:

• Uninstalling/reinstalling sqitch on my primary WSL distribution (Ubuntu)
• Deleting and recomposing my postgres Docker container and its storage volume
• Using a different WSL distribution (Debian) to clone our repo and do the sqitch deploy/check
• Politely asking my computer to do what I want it to do
• Swearing loudly at my computer

[the-noob-of-northrose]

I noticed that sqitch checks (even after deploys) are not failing on databases on our production/test servers, so I guess it's somehow related to my local dev environment, but I'm at a loss as to what could be going on or how to fix it.

[theory]

My team has a sqitch plan with, at the time of writing, 542 changes.

Damn.

I deleted and redeployed again, several times, in fact, and sqitch check reported divergences at different changes each time (WTF???)

WTF indeed.

This issue has apparently not been affecting my coworkers.

That's the good news. Did you try a different computer by chance?

sqitch version: 1.3.1 on Debian, 1.2.1 on Ubuntu, same results with each.

That's a few years old. Looking through the changes, the closest match I can find is #630, but that's about unique violations in the database. The only other wildcard I can think of is if you have cloned your repo of Sqitch changes on Windows and line endings are different, but that really shouldn't matter, honestly.

Can you try a newer version?

I noticed that sqitch checks (even after deploys) are not failing on databases on our production/test servers, so I guess it's somehow related to my local dev environment, but I'm at a loss as to what could be going on or how to fix it.

Yeah, this is pretty weird!

[the-noob-of-northrose]

No parallel stuff that we're aware of—I asked our db guy, who is just as perplexed about this situation.

(FYI, this is a fresh deploy so the data presented here doesn't match that on my previous comments.)

clock_timestamp() returns 2025-01-23 14:01:28.713269+00

The changes table has the same precision.

tl;dr direct answer to your final question:

6586... 2025-01-22 19:52:44.475037+00 (Last change before things get weird)
f49a... 2025-01-22 19:52:44.540459+00 (The out-of-place change)
3e57... 2025-01-22 19:52:44.551137+00 (Back to normal...)
daf5... 2025-01-22 19:52:44.612815+00
2763... 2025-01-22 19:52:44.678552+00
[This is where the out-of-place change f49a... SHOULD be, according to the plan]
edec... 2025-01-22 19:52:44.694312+00
e375... 2025-01-22 19:52:44.865811+00

---

More data...

sqitch check results:

The order of things in my sqitch.plan:

So everything went fine for the first 16 changes, but then somehow, the change with script_hash f49af... (which comes few changes later) got committed next, before the rest of the changes got committed in plan-order.

Unsure how relevant it is, but the fresh deploy I did before this one got through about 120 changes before something weird happened. The one before that (the data included in my previous comment) got through 299.

EDIT: I manually adjusted that committed_at timestamp for script_hash f49a... and re-ran the check. Turns out it actually happened a few more times in this particular deploy.

[the-noob-of-northrose]

Just for kicks, I initialized a new sqitch project, put in 500 changes (without doing anything to the auto-generated scripts), deployed, and this problem still happens for me. So that rules out issues with our product's scripts, at least...

[theory]

tl;dr direct answer to your final question:

This is handy. The committed_at resolution is as it should be. It looks like the plan is applied out-of-order. What's the output of the deploy for that bit? Does it in fact deploy them out of order?

[the-noob-of-northrose]

Does it in fact deploy them out of order?

No. I'm now pretty daggone sure it's not a sqitch problem.

In an earlier comment, I mentioned that I created a new sqitch plan with a whole lot of empty changes, but all numbered so it would be easy to spot something out-of-order in the deploy output. I didn't see anything weird in said output when alerted about a divergence by the check command.

Well, I added a timestamp to the deploy output in Engine.pm:

sub deploy_change {
    my ( $self, $change ) = @_;
    my $sqitch = $self->sqitch;
    my $name = $change->format_name_with_tags;

    // LOG STUFF
    print DateTime->from_epoch( epoch => time )->strftime('%Y-%m-%d %H:%M:%S.%6N');

    $sqitch->info_literal(
        "  + $name ..",
        '.' x ($self->max_name_length - length $name), ' '
    );
    $self->begin_work($change);
[...]

That is what you see on the left here:

It's deploying them in plan order, but at some point, perl fancies itself a time-traveler and pulls a datetime from before the previous one it pulled (in this example it actually does that twice in a row).

I remembered you said that what's in sqitch.changes is just clock_timestamp() in postgres-land and isn't overridden...so for the timestamps in the changes table to be weird, clock_timestamp() would have to be a time-traveler as well, right? Spoiler: it is.

The time inside the postgres container shouldn't be any different from the time in WSL, but if the WSL time is screwy compared to that of Windows itself, then it makes sense that both perl and my postgres server would be misbehaving.

(Aside: it seems like there is a possibility it's a sqitch problem because the time traveling happens after deploying change 182, and 183 is the first out-of-order change in the changes table, so it appears as if the changes are possibly being committed out of order,_ but they're not...they're just logged incorrectly because the time-traveling is happening in both places simultaneously...I think that makes sense...I'm up past my bedtime.)

A couple of experiments confirmed this:

• To rule sqitch out, I wrote a standalone perl script in WSL to just firehose timestamps into a text file (a good 500K of them or so, or about 30 seconds of real time), then copied the file, sorted one lexigraphically, and diffed them, which showed that there was indeed time-travel happening.
• I did it in Python in WSL, too, to make sure it wasn't a weird perl issue. Reproduced the problem with Python.
• I did it with Python in Windows proper; did NOT reproduce the problem—no time traveling!
• I made a temp table in a db on my containerized postgres server and mass-inserted 1M rows with an auto-incrementing PK and clock_timestamp(); confirmed time-traveling there.

So yeah, it seems like I've just got some stupid clock issue with WSL that wasn't happening prior to a few weeks ago, and I don't know what changed. Hooray. If I figure that out, I'll come back and edit my post in case some other poor WSL sqitch user finds their way here after encountering the same weirdness, but I think it's finally safe to say that this is not a sqitch or database issue at all.

[theory]

Great writeup, thank you! Sounds like WSL might not be configured to use monotonic time. Maybe microsoft/WSL#3840 is related?

[the-noob-of-northrose]

David, you're the man!!!!

That issue you linked did not provide any solutions by itself, but one of the top search results for "WSL2 monotonic clock" was this SO post (containing this particular answer).

The NTP service was indeed active in my WSL2 Ubuntu (which is what Docker is using as its backend). I did not consciously turn it on in the past few weeks; maybe it has been on the whole time and some other new factor combined with with it to make it sync way more frequently 🤷‍♂️ Anyway, I disabled it and ran my perl, python, and postgres time tests again, several times each. No more time-traveling.

I'm so relieved. Thank you very much for your help 😄

[theory]

Hell yeah! So glad.