test/offline-entities: massively increase timeout - #1860
Conversation
|
I'm suspicious that this is a postgres issue rather than a timeout that can safely be increased - looking at the logs for the failing test in the linked build https://github.com/getodk/central-backend/actions/runs/28377183995/job/84069808050: Notice that the event processing gets very slow just before failure: Object.entries(fs.readFileSync('./broken.log', 'utf8')
.split('\n')
.filter(it => it.includes('processing event'))
.reduce((logs, line) => {
const type = line.includes('finish processing event') ? 'finish' : 'start';
const id = line.match(/::(.*)::/)[1];
const timestamp = line.split('Z')[0];
if(!logs[id]) logs[id] = {};
if(logs[id][type]) throw new Error('already seen!');
logs[id][type] = timestamp; return logs;
}, {}))
.map(([ id, { start, finish }]) => [ id, new Date(finish) - new Date(start) ])
.sort((a, b) => a[0] - b[0])
.forEach(([ts, duration]) => console.log(`\`${ts}\` | \`${duration.toString().padStart(4, ' ')}ms\``));
Perhaps getting progressively slower, or something has caused a slowdown which then causes test timeout. |
|
This timeout has come up a few times for me in the past day. What do you think about merging this PR just to ease development on other work and prevent timeouts, even as we continue investigating the progressive slowdown described above? We could file a separate issue to investigate the progressive slowdown (I'd be happy to file it). |
Please add failed job links at getodk/central#2027
I don't think investigation is ongoing. Creating a specific Issue and prioritising would be helpful 👍 |
Done: getodk/central#2027 (comment)
I've filed an issue about this at getodk/central#2258. Feel free to edit the issue description or add a comment if I got anything wrong. The issue is in the project inbox, so we can discuss its priority the next time we review the inbox. In the meantime, I think it'd ease development to go ahead and merge this PR. |
One question I'm now wondering is whether we're sure this timeout increase will stop the test from failing. Does the test stop failing when the timeout is increased to 32 seconds? I think we could just merge and find out, but it's something I'm now wondering. |
Easily tested, per the description:
|
|
Ran 1000 iterations with 16 second timeout, and 1000 iterations with 32 second timeout.
There were zero failures due to offline-entities with either. I don't think there's clear justification for increasing the timeout right now. Maybe next time that failures are happening frequently, this can be checked again. |
That's kind of surprising to me given that I've had 3 failures in recent days in much less than 1000 runs. Maybe just bad luck on my part? Looking at my failures, I'm noticing that they were all
That sounds reasonable to me. There's no evidence yet that a larger timeout would have prevented the timeouts we've seen. I'll try to remember to post on the issue if/when I see this failure again in the future. |
Let's find out 🙃 |
|
Per getodk/central#2258 (comment), timeout increased to 120 seconds. |
Closes getodk/central#2027
What has been done to verify that this works as intended?
Why is this the best possible solution? Were any other approaches considered?
It might be good to understand why such a huge timeout is required. But it's also good if an intermittent failure can easily be avoided, or at least may to occur less frequently.
How does this change affect users? Describe intentional changes to behavior and behavior that could have accidentally been affected by code changes. In other words, what are the regression risks?
No effect - just test code.
Does this change require updates to the API documentation? If so, please update docs/api.yaml as part of this PR.
No.
Before submitting this PR, please make sure you have:
make testand confirmed all checks still pass, or witnessed Github completing all checks with success