test(nix): fix race condition in portail-identity-aware-upstream

[RealHinome]

Add node.wait_until_succeeds before running curl assertions to ensure the proxy has fully established its internal tunnel.

Comment

[rlahfa-dinum]

No, I don't understand how this is fixing anything here. The next line is going to be doing the very much same thing. Can you explain what are you trying to do?

[RealHinome]

This does not do the same thing. wait_until_succeeds is used as a readiness barrier, not as the final assertion. portail.service being active and listening on port 8080 does not guarantee that the identity-aware upstream path is already usable.

We sometimes observe curl timeouts (exit code 28) in CI when the first proxied request happened too early (e.g. on latest commit, link), including in my PR CI.

This is currently a workaround to avoid the race condition. A better solution would be to have an explicit readiness signal from portail once the identity-aware upstream path is fully ready.

[RealHinome]

A better elegant solution would probably be to use the existing systemd readiness notification properly. sd_notify_ready() is currently called before proxy::start() and rpc::start() are actually running, so systemd may consider portail ready before it can handle requests. This likely explains the intermittent CI failures. The wait_until_succeeds is a valid workaround for now, but moving the readiness notification to a point where portail is actually ready would be cleaner. I hadn't realized the root cause of the problem; this hotfix addresses the symptom for now, not the root cause. That's why I said it was a workaround, but it's better to update notify.

[RealHinome]

To achieve an elegant solution, however, we'll need to make a few more changes to the current code (it's not just adding a single line); the workaround solution allows you to fix the CI without major changes. In production, such a race condition is possible, but less common. I'll leave it up to you to decide what to do.

Edit: I'll see tomorrow if it's not possible to move the notify call to one of the functions handled in the tokio::join! macro.

[rlahfa-dinum]

This commit already do the move: 354eeab.

You can cherry-pick it and isolate it from the rest of the logging and verify this does fix the problem.

[RealHinome]

Perfect, my bad--sorry. However, I am not sure if your patch works. Since you're saying to Tokio (via the Tokio::join) still after the notification to start it. Tokio has its own scheduler and you don't do .await before.
I am currently on phone, I'll try to see if I am right or wrong later on the morning.
Edit: fix typos.

[RealHinome]

After carefully consideration, I think there is still a catch and doesn't fix the problem. As long as the functions aren't polled (.await, join!), or at least placed in the scheduler of your asynchronous runtime (in this case, Tokio), they aren't executed.

If sd_notify_ready() is still called before the futures are first polled, I think the race remains. Unless I'm missing something in the commit, systemd can still observe the service as ready before proxy/rpc are actually running.

[RealHinome]

Your latest CI also appears to fail in portail-identity-aware-upstream with curl timing out (exit code 28). I'm not sure whether this is the same race condition or a different issue, but it might be worth comparing the VM logs.

Edit: after re-reading the logs, my first analyze looks limited.

[RealHinome]

I've created a small playground and I still believe sd_notify_ready() is called too early, even with your changes.

However, I still have some difficulties to understand if it's really the root problem. This may fix some failures. While I still have concerns regarding 354eeab, I am no longer convinced that this is the error in question.
I may be missing something, but I'd prefer to wait for more logs before drawing conclusions. Your additional logs should help clarify the sequence of events if the failure happens again; perhaps it'd be worth adding a few more debug logs around the CONNECT/TLS path.

In any case, the best approach would be to rewrite code using a oneshot to signal when the proxy has actually started, rather than rely on call async function without polling them. This PR could still improve CI stability (since it's a readiness probe, like on k8s), without addressing the root cause of the problem.

[rlahfa-dinum]

Can you suggest a patch to apply on the PR for structured logging to add more logs that would help you?

[rlahfa-dinum]

I looked at it again because our CI was starting to be always red due to this and I disagree with your analysis of the start loop, this has nothing to do with systemd readiness. The problem lies in the fact that systems can be quite slow and servicing the request can take longer than the allowed timeout which was 5s.

Removing the timeouts seems to have fixed it, obviously, it can happen again if the system is too slow but the default timeout should work reasonably for the level of work these CI workers have to do.

Closing here.

[RealHinome]

You're probably right; I can see that all the CI runs are now passing. I was wrong in my analysis of the cause. That said, my point about systemd still holds true, as the playground demonstrates. However, you're right: this PR is no longer necessary.