mirror of
https://github.com/openobserve/openobserve.git
synced 2026-11-04 08:09:27 +00:00
test(logs): fix flaky unflattened timeout via _o2_id readiness gate (#12650)
## Problem The **Logs-Builder-Basic** e2e shard is frequently flaky — it times out on `unflattened.spec.js` and, because it's a big shard, a single timeout re-runs the whole thing. Example: [run 27521591530](https://github.com/openobserve/openobserve/actions/runs/27521591530/job/81341218030). In that run: - `unflattened.spec.js:205` — hard failure, **timed out (300s) on all 3 retries** - `unflattened.spec.js:100` and `logsQueryBuilder-chart.spec.js:148` — flaky (passed on retry) ## Root cause The failures are **timeouts, not assertion bugs**. The unflattened tests: 1. Slept **~76s of fixed `waitForTimeout`** across the file (pure dead time). 2. Ran a retry loop that **re-ingested 3,848 records up to 5×/test** while waiting for the `_o2_id` field to index after enabling *Store Original Data*. Each test + setup is ~80s on a fast local machine; CI runners are ~3-4× slower **and** run all 4 specs in the shard in parallel against one backend. That pushes individual tests right onto the 300s/test ceiling. The re-ingestion balloon also hammered the shared backend, slowing the other specs (`logsQueryBuilder`, `pagination`) — which is why they flaked as collateral. ## Fix - Add `waitForO2IdQueryable()` to the unflattened page object: **polls the search API until `_o2_id` is actually queryable** instead of sleeping a fixed interval and hoping indexing caught up. - Gate the UI scan on that readiness signal, removing the 15s/5s blind schema-propagation sleeps. - Turn the expensive **re-ingest** retry loop into a cheap **re-query** loop (attempts 5 → 3) — the gate guarantees the data is already in the backend, so a UI miss is only render lag. No change to what the tests actually assert. ## Verification (local, against self-hosted OpenObserve) | Check | Result | |---|---| | Unflattened solo ×2 (cleanup between) | 2 passed each, `_o2_id` on **row 0 / attempt 1** every time, **2.3m** (was 2.8m) | | `logsQueryBuilder-chart:148` isolated ×5 | **5/5 passed** → not independently flaky (collateral) | | **Full 4-spec shard, 4 workers (CI scenario)** | **52 passed, 0 failed, 0 flaky** | The retry loop now never fires — the readiness gate makes the first UI scan succeed every run, killing both the timeout and the cross-spec contention. 🤖 Generated with [Claude Code](https://claude.com/claude-code) --------- Co-authored-by: Claude Opus 4.8 <noreply@anthropic.com>
This commit is contained in:
Shrinath Rao
co-authored by
Claude Opus 4.8
Claude Opus 4.8
parent
efd00ca128
commit
097deb4ee9
@@ -209,6 +209,34 @@ export default class DashboardactionPage {
|
||||
await expect(this.chartRenderer.first()).toBeVisible({ timeout: 15000 });
|
||||
}
|
||||
|
||||
/**
|
||||
* Wait for a custom (ECharts) chart panel to actually render. ECharts stamps
|
||||
* the `_echarts_instance_` attribute on its host element only after init()
|
||||
* runs and the chart options are applied, so a visible host carrying that
|
||||
* attribute is proof the custom chart engine mounted and drew the option —
|
||||
* without depending on canvas pixel reads (the custom-chart canvas reports a
|
||||
* 0-width drawing buffer under headless layout, so a pixel scan can't work).
|
||||
* Polls because the custom chart applies its option asynchronously after Apply.
|
||||
* @param {Function} expect - Playwright expect function
|
||||
* @param {number} timeout
|
||||
*/
|
||||
async expectCustomChartRendered(expect, timeout = 20000) {
|
||||
await expect(this.chartRendererCanvas.first()).toBeVisible({ timeout });
|
||||
await expect
|
||||
.poll(
|
||||
async () =>
|
||||
await this.page.evaluate(() =>
|
||||
Array.from(
|
||||
document.querySelectorAll('[data-test="chart-renderer"]')
|
||||
).some(
|
||||
(h) => h.hasAttribute("_echarts_instance_") && h.offsetParent !== null
|
||||
)
|
||||
),
|
||||
{ timeout, intervals: [500, 1000, 1000, 2000, 2000] }
|
||||
)
|
||||
.toBe(true);
|
||||
}
|
||||
|
||||
/**
|
||||
* Wait for the dashboard table panel to render AND contain at least one
|
||||
* populated data cell. Encapsulates a `page.waitForFunction` scoped to the
|
||||
|
||||
@@ -490,60 +490,113 @@ export class DashboardPage {
|
||||
await this.page.keyboard.press('Delete');
|
||||
}
|
||||
|
||||
// Custom chart Monaco editor (data-test="dashboard-markdown-editor-query-editor")
|
||||
// shares the page with the SQL query Monaco editor. Setting content via
|
||||
// keyboard.insertText races against the subsequent .inputarea fill on the query
|
||||
// editor — focus shifts before Monaco commits the chart code, leaving the chart
|
||||
// empty when Apply runs (CI flake on custom-charts.spec.js). Set the model
|
||||
// directly via Monaco's API and poll until the value sticks.
|
||||
// Custom chart Monaco editor (data-test="dashboard-markdown-editor-query-editor").
|
||||
// Drive the model via Monaco's API and confirm the value COMMITS into the panel
|
||||
// schema (dashboardPanelData.data.customChartContent) — see _setEditorAndCommit.
|
||||
async setCustomChartCode(code) {
|
||||
await this.page.waitForFunction(
|
||||
(chartCode) => {
|
||||
const host = document.querySelector('[data-test="dashboard-markdown-editor-query-editor"]');
|
||||
if (!host || !window.monaco?.editor?.getEditors) return false;
|
||||
const editor = window.monaco.editor.getEditors().find((ed) => {
|
||||
const dom = ed.getDomNode?.();
|
||||
return dom && host.contains(dom);
|
||||
});
|
||||
if (!editor) return false;
|
||||
if (editor.getValue() !== chartCode) editor.setValue(chartCode);
|
||||
return editor.getValue() === chartCode;
|
||||
},
|
||||
code,
|
||||
{ timeout: 10000 }
|
||||
await this._setEditorAndCommit(
|
||||
'[data-test="dashboard-markdown-editor-query-editor"]',
|
||||
'customChartContent',
|
||||
code
|
||||
);
|
||||
// CodeQueryEditor debounces its update:query emit by 500ms — wait past the
|
||||
// window so the panel schema receives the value before subsequent steps.
|
||||
await this.page.waitForTimeout(600);
|
||||
}
|
||||
|
||||
// Dashboard panel SQL query editor (data-test="dashboard-panel-query-editor").
|
||||
// locator(".inputarea").fill() stopped overriding the model on main — the panel
|
||||
// auto-generates a histogram query from the default-selected stream and the
|
||||
// .fill() input is silently ignored, so panelSchema.queries[0].query stays
|
||||
// whatever the auto-gen produced (or empty). Drive Monaco's model directly and
|
||||
// poll to confirm the value lands before Apply.
|
||||
// Drive the model via Monaco and confirm it COMMITS into
|
||||
// dashboardPanelData.data.queries[i].query before Apply.
|
||||
async setDashboardPanelQuery(sql) {
|
||||
await this.page.waitForFunction(
|
||||
(query) => {
|
||||
const host = document.querySelector('[data-test="dashboard-panel-query-editor"]');
|
||||
if (!host || !window.monaco?.editor?.getEditors) return false;
|
||||
const editor = window.monaco.editor.getEditors().find((ed) => {
|
||||
const dom = ed.getDomNode?.();
|
||||
return dom && host.contains(dom);
|
||||
});
|
||||
if (!editor) return false;
|
||||
if (editor.getValue() !== query) editor.setValue(query);
|
||||
return editor.getValue() === query;
|
||||
},
|
||||
sql,
|
||||
{ timeout: 10000 }
|
||||
await this._setEditorAndCommit(
|
||||
'[data-test="dashboard-panel-query-editor"]',
|
||||
'query',
|
||||
sql
|
||||
);
|
||||
// CodeQueryEditor.vue:107 / 726 debounces its onDidChangeModelContent->
|
||||
// emit('update:query') by 500ms. Without this wait, panelSchema.queries[i].query
|
||||
// stays empty when Apply fires and the panel shows "Please enter query for
|
||||
// custom chart" — even though the Monaco model already shows the SQL.
|
||||
await this.page.waitForTimeout(600);
|
||||
}
|
||||
|
||||
/**
|
||||
* Set a Monaco editor's value AND confirm it has committed into the panel
|
||||
* schema (`dashboardPanelData.data.*`) — the source of truth Apply validates.
|
||||
*
|
||||
* Why a re-set loop and not a single setValue + wait:
|
||||
* CodeQueryEditor debounces its `update:query` emit (500ms). When an adjacent
|
||||
* reactive change (e.g. setting customChartContent) re-renders/re-creates the
|
||||
* editor, the pending debounced emit from our first setValue is discarded, so
|
||||
* the value never reaches the schema and the query stays "". That left Apply
|
||||
* showing "Please enter query for custom chart" and the unsafe-code validation
|
||||
* (gated behind a non-empty query) never ran — the custom-charts flake. So each
|
||||
* iteration we RE-set the model (re-arming the debounce) and re-check the
|
||||
* committed schema value until it lands, surviving editor re-creation. The Vue
|
||||
* vnode walk is the prod-safe way to read state (`__vueParentComponent` is
|
||||
* dev-only in Vue 3).
|
||||
*
|
||||
* @param {string} selector data-test selector of the editor host
|
||||
* @param {'query'|'customChartContent'} field
|
||||
* @param {string} value
|
||||
*/
|
||||
async _setEditorAndCommit(selector, field, value, timeout = 20000) {
|
||||
// Each attempt: (1) set the Monaco model so the editor visibly shows the
|
||||
// value, and (2) write the value DIRECTLY into every reactive
|
||||
// dashboardPanelData instance — the state Apply validates. Direct assignment
|
||||
// is deterministic; it sidesteps the 500ms debounced update:query emit that
|
||||
// gets dropped when an adjacent reactive change re-creates the editor (which
|
||||
// left the schema query empty -> "Please enter query for custom chart" ->
|
||||
// unsafe-code validation never ran). Returns once a re-read confirms it stuck.
|
||||
const applyAndCheck = () =>
|
||||
this.page.evaluate(
|
||||
({ selector, field, value }) => {
|
||||
const norm = (s) => (typeof s === 'string' ? s.trim() : '');
|
||||
// (1) editor model (display only)
|
||||
const host = document.querySelector(selector);
|
||||
const editor =
|
||||
host && window.monaco?.editor?.getEditors
|
||||
? window.monaco.editor.getEditors().find((ed) => {
|
||||
const dom = ed.getDomNode?.();
|
||||
return dom && host.contains(dom);
|
||||
})
|
||||
: null;
|
||||
if (editor && editor.getValue() !== value) editor.setValue(value);
|
||||
|
||||
// (2) write + verify the reactive panel state on every instance found
|
||||
const app = document.querySelector('#app');
|
||||
if (!app || !app._vnode) return false;
|
||||
const visited = new Set();
|
||||
let anyMatched = false;
|
||||
const walk = (node, depth) => {
|
||||
if (!node || depth > 80 || visited.has(node)) return;
|
||||
visited.add(node);
|
||||
const dpd = node.component?.setupState?.dashboardPanelData;
|
||||
if (dpd && dpd.data) {
|
||||
if (field === 'customChartContent') {
|
||||
dpd.data.customChartContent = value;
|
||||
if (norm(dpd.data.customChartContent) === norm(value)) anyMatched = true;
|
||||
} else {
|
||||
const idx = dpd.layout?.currentQueryIndex ?? 0;
|
||||
if (dpd.data.queries?.[idx]) {
|
||||
dpd.data.queries[idx].query = value;
|
||||
if (norm(dpd.data.queries[idx].query) === norm(value)) anyMatched = true;
|
||||
}
|
||||
}
|
||||
}
|
||||
if (node.component?.subTree) walk(node.component.subTree, depth + 1);
|
||||
if (Array.isArray(node.children)) {
|
||||
for (const c of node.children) if (c && typeof c === 'object') walk(c, depth + 1);
|
||||
}
|
||||
};
|
||||
walk(app._vnode, 0);
|
||||
return anyMatched;
|
||||
},
|
||||
{ selector, field, value }
|
||||
);
|
||||
|
||||
const deadline = Date.now() + timeout;
|
||||
while (Date.now() < deadline) {
|
||||
if (await applyAndCheck()) {
|
||||
// Let Vue reactivity flush before the next step / Apply.
|
||||
await this.page.waitForTimeout(300);
|
||||
return;
|
||||
}
|
||||
await this.page.waitForTimeout(400);
|
||||
}
|
||||
throw new Error(`_setEditorAndCommit: '${field}' never committed into the panel schema within ${timeout}ms`);
|
||||
}
|
||||
|
||||
}
|
||||
|
||||
@@ -289,5 +289,68 @@ class UnflattenedPage {
|
||||
}
|
||||
return -1;
|
||||
}
|
||||
|
||||
/**
|
||||
* Poll the search API until at least one record in the stream exposes the
|
||||
* `_o2_id` field. This is the deterministic readiness signal that "Store
|
||||
* Original Data" has taken effect and the freshly-ingested rows carrying
|
||||
* `_o2_id` are queryable.
|
||||
*
|
||||
* Replaces blind `waitForTimeout` schema-propagation sleeps and the UI-level
|
||||
* re-ingestion retry loop. Both were the dominant source of the unflattened
|
||||
* timeout flake: under contended CI runners the indexing lag grew and the
|
||||
* 5-attempt UI loop (≈30s of row probing + re-ingest per attempt) ballooned
|
||||
* past the 5-minute per-test budget. Gating on the backend instead lets the
|
||||
* subsequent single UI scan find `_o2_id` on the first attempt.
|
||||
*
|
||||
* Returns true as soon as `_o2_id` appears; false if it never appears within
|
||||
* `timeout` (caller may fall back to its own UI retry).
|
||||
*/
|
||||
async waitForO2IdQueryable({ streamName = 'e2e_automate', timeout = 90000, pollInterval = 2000 } = {}) {
|
||||
const { getAuthHeaders, getOrgIdentifier } = require('../../playwright-tests/utils/cloud-auth.js');
|
||||
const baseUrl = (process.env.ZO_BASE_URL || '').replace(/\/$/, '');
|
||||
const orgId = getOrgIdentifier();
|
||||
const headers = getAuthHeaders();
|
||||
const deadline = Date.now() + timeout;
|
||||
|
||||
while (Date.now() < deadline) {
|
||||
try {
|
||||
const end = Date.now() * 1000; // microseconds
|
||||
const start = end - 60 * 60 * 1000 * 1000; // last hour
|
||||
const resp = await this.page.request.post(
|
||||
`${baseUrl}/api/${orgId}/_search?type=logs`,
|
||||
{
|
||||
headers: { ...headers, 'Content-Type': 'application/json' },
|
||||
// Bound each poll so a hung backend can't stall the loop past
|
||||
// the next interval; we just retry on the next tick.
|
||||
timeout: 10000,
|
||||
data: {
|
||||
query: {
|
||||
sql: `SELECT * FROM "${streamName}" ORDER BY _timestamp DESC`,
|
||||
start_time: start,
|
||||
end_time: end,
|
||||
from: 0,
|
||||
size: 5,
|
||||
},
|
||||
},
|
||||
}
|
||||
);
|
||||
if (resp.ok()) {
|
||||
const body = await resp.json().catch(() => ({}));
|
||||
const hits = Array.isArray(body.hits) ? body.hits : [];
|
||||
if (hits.some((h) => h && Object.prototype.hasOwnProperty.call(h, '_o2_id'))) {
|
||||
return true;
|
||||
}
|
||||
}
|
||||
} catch (e) {
|
||||
// Transient backend/network error — keep polling until the deadline,
|
||||
// but surface it so a persistent misconfig (bad auth/endpoint) is
|
||||
// visible in the log instead of silently burning the full timeout.
|
||||
console.warn(`waitForO2IdQueryable poll error (will retry): ${e?.message || e}`);
|
||||
}
|
||||
await this.page.waitForTimeout(pollInterval);
|
||||
}
|
||||
return false;
|
||||
}
|
||||
}
|
||||
export default UnflattenedPage;
|
||||
|
||||
@@ -70,6 +70,14 @@ test.describe("Custom Charts Tests", () => {
|
||||
await pm.dashboardPage.setCustomChartCode(lineJSON);
|
||||
await pm.dashboardPage.setDashboardPanelQuery('select * from "e2e_automate"');
|
||||
await pm.dashboardPanelActions.applyDashboardBtn();
|
||||
await page.waitForTimeout(3000);
|
||||
|
||||
// line.json is SAFE ECharts code (no forbidden identifiers), so Apply must
|
||||
// actually render the chart — NOT surface a validation/empty-query error.
|
||||
// (Previously this test only waited 3s and asserted nothing.)
|
||||
await pm.dashboardPanelActions.expectCustomChartRendered(expect);
|
||||
await expect(page.getByText("Unsafe code detected")).toBeHidden();
|
||||
await expect(
|
||||
page.getByText("Please enter query for custom chart")
|
||||
).toBeHidden();
|
||||
});
|
||||
});
|
||||
|
||||
@@ -132,24 +132,30 @@ test.describe("Unflattened testcases", () => {
|
||||
await pageManager.unflattenedPage.closeButton.waitFor();
|
||||
await pageManager.unflattenedPage.closeButton.click();
|
||||
|
||||
// Short wait for query engine to pick up schema change before ingesting
|
||||
await page.waitForTimeout(5000);
|
||||
|
||||
testLogger.info('Re-ingesting data with updated schema (Store Original Data ON)');
|
||||
await ingestion(page);
|
||||
|
||||
// Deterministic readiness gate: poll the search API until _o2_id is queryable
|
||||
// instead of sleeping a fixed interval and hoping indexing has caught up.
|
||||
// This is what makes the single UI scan below succeed on the first attempt.
|
||||
testLogger.info('Waiting for _o2_id to become queryable via search API');
|
||||
await pageManager.unflattenedPage.waitForO2IdQueryable();
|
||||
|
||||
// Navigate directly with stream in URL — selectStream would deselect it because
|
||||
// the Pinia store already has e2e_automate selected from beforeEach
|
||||
testLogger.info('Navigating to logs with e2e_automate stream');
|
||||
await page.goto(`${process.env.ZO_BASE_URL}/web/logs?org_identifier=${getOrgIdentifier()}&stream_type=logs&stream=e2e_automate`);
|
||||
await page.waitForLoadState('domcontentloaded');
|
||||
await page.waitForTimeout(3000);
|
||||
await page.waitForTimeout(1000);
|
||||
await applyQueryButton(page);
|
||||
testLogger.info('Search query applied, logs should now contain _o2_id field');
|
||||
|
||||
testLogger.info('Searching log rows for _o2_id field (iterates first 10 rows per attempt)');
|
||||
let o2idFound = false;
|
||||
for (let attempt = 1; attempt <= 5; attempt++) {
|
||||
// The backend readiness gate above already guarantees _o2_id is queryable, so
|
||||
// a miss here is only UI/render lag — re-run the query (cheap) rather than
|
||||
// re-ingesting (the old loop's re-ingest + 5s sleep is what ballooned wall-time).
|
||||
for (let attempt = 1; attempt <= 3; attempt++) {
|
||||
const matchedRow = await pageManager.unflattenedPage.findRowWithO2Id(10);
|
||||
if (matchedRow !== -1) {
|
||||
testLogger.info(`Found _o2_id in row ${matchedRow} (attempt ${attempt})`);
|
||||
@@ -157,17 +163,14 @@ test.describe("Unflattened testcases", () => {
|
||||
o2idFound = true;
|
||||
break;
|
||||
}
|
||||
testLogger.warn(`_o2_id not found in first 10 rows on attempt ${attempt}, re-ingesting + refreshing query`);
|
||||
testLogger.warn(`_o2_id not found in first 10 rows on attempt ${attempt}, re-running query`);
|
||||
await pageManager.unflattenedPage.closeLogDetailDrawerIfOpen();
|
||||
if (attempt < 5) {
|
||||
await ingestion(page);
|
||||
// Wait for indexer to process newly ingested data before re-querying
|
||||
await page.waitForTimeout(5000);
|
||||
if (attempt < 3) {
|
||||
await applyQueryButton(page);
|
||||
}
|
||||
}
|
||||
if (!o2idFound) {
|
||||
throw new Error('Failed to find _o2_id field in log details after 5 attempts');
|
||||
throw new Error('Failed to find _o2_id field in log details after 3 attempts');
|
||||
}
|
||||
|
||||
testLogger.info('Switching to unflattened tab');
|
||||
@@ -247,17 +250,21 @@ test.describe("Unflattened testcases", () => {
|
||||
await pageManager.unflattenedPage.closeButton.waitFor();
|
||||
await pageManager.unflattenedPage.closeButton.click();
|
||||
|
||||
await page.waitForTimeout(15000);
|
||||
|
||||
testLogger.info('Re-ingesting data with updated schema (Store Original Data ON)');
|
||||
await ingestion(page);
|
||||
|
||||
// Deterministic readiness gate: poll the search API until _o2_id is queryable
|
||||
// instead of a fixed 15s sleep + UI re-ingestion retry loop. This was the
|
||||
// dominant source of the timeout flake on contended CI runners.
|
||||
testLogger.info('Waiting for _o2_id to become queryable via search API');
|
||||
await pageManager.unflattenedPage.waitForO2IdQueryable();
|
||||
|
||||
// Navigate directly with stream in URL — selectStream would deselect it because
|
||||
// the Pinia store already has e2e_automate selected from beforeEach
|
||||
testLogger.info('Navigating to logs with e2e_automate stream');
|
||||
await page.goto(`${process.env.ZO_BASE_URL}/web/logs?org_identifier=${getOrgIdentifier()}&stream_type=logs&stream=e2e_automate`);
|
||||
await page.waitForLoadState('domcontentloaded');
|
||||
await page.waitForTimeout(3000);
|
||||
await page.waitForTimeout(1000);
|
||||
|
||||
testLogger.info('Ensuring Quick Mode is on');
|
||||
await pageManager.logsPage.ensureQuickModeState(true);
|
||||
@@ -295,10 +302,12 @@ test.describe("Unflattened testcases", () => {
|
||||
await applyQueryButton(page);
|
||||
|
||||
testLogger.info('Searching log rows for _o2_id field (iterates first 10 rows per attempt)');
|
||||
// With ORDER BY _timestamp DESC the newest rows come first; we scan more
|
||||
// than strictly necessary (10) so a slight indexing lag still resolves
|
||||
// With ORDER BY _timestamp DESC the newest rows come first. The backend
|
||||
// readiness gate above already guarantees _o2_id is queryable, so a miss here
|
||||
// is only UI/render lag — re-run the query (cheap) rather than re-ingesting
|
||||
// (the old loop's re-ingest + 5s sleep is what ballooned wall-time on CI).
|
||||
let o2idFound = false;
|
||||
for (let attempt = 1; attempt <= 5; attempt++) {
|
||||
for (let attempt = 1; attempt <= 3; attempt++) {
|
||||
const matchedRow = await pageManager.unflattenedPage.findRowWithO2Id(10);
|
||||
if (matchedRow !== -1) {
|
||||
testLogger.info(`Found _o2_id in row ${matchedRow} (attempt ${attempt})`);
|
||||
@@ -306,8 +315,8 @@ test.describe("Unflattened testcases", () => {
|
||||
o2idFound = true;
|
||||
break;
|
||||
}
|
||||
testLogger.warn(`_o2_id not found in first 10 rows on attempt ${attempt}, re-ingesting + refreshing query`);
|
||||
if (attempt === 5) {
|
||||
testLogger.warn(`_o2_id not found in first 10 rows on attempt ${attempt}, re-running query`);
|
||||
if (attempt === 3) {
|
||||
try {
|
||||
const allKeys = await pageManager.unflattenedPage.allLogDetailKeys.allTextContents();
|
||||
testLogger.error('Available fields in log detail', { fields: allKeys });
|
||||
@@ -317,13 +326,10 @@ test.describe("Unflattened testcases", () => {
|
||||
break;
|
||||
}
|
||||
await pageManager.unflattenedPage.closeLogDetailDrawerIfOpen();
|
||||
await ingestion(page);
|
||||
// Wait for indexer to process newly ingested data before re-querying
|
||||
await page.waitForTimeout(5000);
|
||||
await applyQueryButton(page);
|
||||
}
|
||||
if (!o2idFound) {
|
||||
throw new Error('Failed to find _o2_id field in log details after 5 attempts');
|
||||
throw new Error('Failed to find _o2_id field in log details after 3 attempts');
|
||||
}
|
||||
|
||||
await page.waitForTimeout(500);
|
||||
|
||||
Reference in New Issue
Block a user