From d9252f53a3b98d15ace1b3aba12b599a803c009b Mon Sep 17 00:00:00 2001 From: Mathieu Fenniak Date: Thu, 5 Dec 2024 18:08:11 +0000 Subject: [PATCH] Fix bug where Action UI may occasionally not load logs (#6122) In the combination of events where the user is viewing an action that is completed (and therefore no interval-based loading of logs is occurring), and `loadJob` is called while `loadJob` is already running (commonly from expanding two log sections back-to-back), the second request for loading would be discarded and never occur. To fix this, the invocation of `loadJob` keeps track of the log cursors it is attempting to load, and an aborted invocation stores its attempted load. If `loadJob` succeeds in loading and finds that an attempt was aborted while it was busy, it will reload the data. Steps to reproduce: - Open an Action UI that is already "Done". - Click on two steps in rapid succession to expand their logs. - (Race condition) As long as the second click is registered while the first log chunk is being loaded, its data won't load. ## Checklist The [contributor guide](https://forgejo.org/docs/next/contributor/) contains information that will be helpful to first time contributors. There also are a few [conditions for merging Pull Requests in Forgejo repositories](https://codeberg.org/forgejo/governance/src/branch/main/PullRequestsAgreement.md). You are also welcome to join the [Forgejo development chatroom](https://matrix.to/#/#forgejo-development:matrix.org). ### Tests - I added test coverage for Go changes... (**not applicable**) - [ ] in their respective `*_test.go` for unit tests. - [ ] in the `tests/integration` directory if it involves interactions with a live Forgejo server. - I added test coverage for JavaScript changes... - [x] in `web_src/js/*.test.js` if it can be unit tested. - [ ] in `tests/e2e/*.test.e2e.js` if it requires interactions with a live Forgejo server (see also the [developer guide for JavaScript testing](https://codeberg.org/forgejo/forgejo/src/branch/forgejo/tests/e2e/README.md#end-to-end-tests)). ### Documentation - [ ] I created a pull request [to the documentation](https://codeberg.org/forgejo/docs) to explain to Forgejo users how to use this change. - [x] I did not document these changes and I do not expect someone else to do it. ### Release notes - [ ] I do not want this change to show in the release notes. - [x] I want the title to show in the release notes with a link to this pull request. - [ ] I want the content of the `release-notes/.md` to be be used for the release notes instead of the title. Reviewed-on: https://codeberg.org/forgejo/forgejo/pulls/6122 Reviewed-by: Earl Warren Reviewed-by: Otto Reviewed-by: Gusted Co-authored-by: Mathieu Fenniak Co-committed-by: Mathieu Fenniak --- web_src/js/components/RepoActionView.test.js | 112 +++++++++++++++++++ web_src/js/components/RepoActionView.vue | 56 ++++++++-- 2 files changed, 156 insertions(+), 12 deletions(-) diff --git a/web_src/js/components/RepoActionView.test.js b/web_src/js/components/RepoActionView.test.js index 8c4e1506be..0b9527ced1 100644 --- a/web_src/js/components/RepoActionView.test.js +++ b/web_src/js/components/RepoActionView.test.js @@ -103,3 +103,115 @@ test('processes ##[group] and ##[endgroup]', async () => { // Check if after the log list exists another log line expect(wrapper.get('.job-log-list + .job-log-line > .log-msg').text()).toEqual('A line outside the group'); }); + +test('load multiple steps on a finished action', async () => { + Object.defineProperty(document.documentElement, 'lang', {value: 'en'}); + vi.spyOn(global, 'fetch').mockImplementation((url, opts) => { + if (url.endsWith('/artifacts')) { + return Promise.resolve({ + ok: true, + json: vi.fn().mockResolvedValue( + { + artifacts: [], + }, + ), + }); + } + + const postBody = JSON.parse(opts.body); + const stepsLog_value = []; + for (const cursor of postBody.logCursors) { + if (cursor.expanded) { + stepsLog_value.push( + { + step: cursor.step, + cursor: 0, + lines: [ + {index: 1, message: `Step #${cursor.step + 1} Log #1`, timestamp: 0}, + {index: 1, message: `Step #${cursor.step + 1} Log #2`, timestamp: 0}, + {index: 1, message: `Step #${cursor.step + 1} Log #3`, timestamp: 0}, + ], + }, + ); + } + } + const jobs_value = { + state: { + run: { + status: 'success', + commit: { + pusher: {}, + }, + }, + currentJob: { + steps: [ + { + summary: 'Test Step #1', + duration: '1s', + status: 'success', + }, + { + summary: 'Test Step #2', + duration: '1s', + status: 'success', + }, + ], + }, + }, + logs: { + stepsLog: opts.body?.includes('"cursor":null') ? stepsLog_value : [], + }, + }; + + return Promise.resolve({ + ok: true, + json: vi.fn().mockResolvedValue( + jobs_value, + ), + }); + }); + + const wrapper = mount(RepoActionView, { + props: { + actionsURL: 'https://example.com/example-org/example-repo/actions', + runIndex: '1', + jobIndex: '2', + locale: { + approve: '', + cancel: '', + rerun: '', + artifactsTitle: '', + areYouSure: '', + confirmDeleteArtifact: '', + rerun_all: '', + showTimeStamps: '', + showLogSeconds: '', + showFullScreen: '', + downloadLogs: '', + status: { + unknown: '', + waiting: '', + running: '', + success: '', + failure: '', + cancelled: '', + skipped: '', + blocked: '', + }, + }, + }, + }); + await flushPromises(); + // Click on both steps to start their log loading in fast succession... + await wrapper.get('.job-step-section:nth-of-type(1) .job-step-summary').trigger('click'); + await wrapper.get('.job-step-section:nth-of-type(2) .job-step-summary').trigger('click'); + await flushPromises(); + + // Verify both step's logs were loaded + expect(wrapper.get('.job-step-section:nth-of-type(1) .job-log-line:nth-of-type(1) .log-msg').text()).toEqual('Step #1 Log #1'); + expect(wrapper.get('.job-step-section:nth-of-type(1) .job-log-line:nth-of-type(2) .log-msg').text()).toEqual('Step #1 Log #2'); + expect(wrapper.get('.job-step-section:nth-of-type(1) .job-log-line:nth-of-type(3) .log-msg').text()).toEqual('Step #1 Log #3'); + expect(wrapper.get('.job-step-section:nth-of-type(2) .job-log-line:nth-of-type(1) .log-msg').text()).toEqual('Step #2 Log #1'); + expect(wrapper.get('.job-step-section:nth-of-type(2) .job-log-line:nth-of-type(2) .log-msg').text()).toEqual('Step #2 Log #2'); + expect(wrapper.get('.job-step-section:nth-of-type(2) .job-log-line:nth-of-type(3) .log-msg').text()).toEqual('Step #2 Log #3'); +}); diff --git a/web_src/js/components/RepoActionView.vue b/web_src/js/components/RepoActionView.vue index 4e8e18e80b..b96d1f7573 100644 --- a/web_src/js/components/RepoActionView.vue +++ b/web_src/js/components/RepoActionView.vue @@ -26,6 +26,7 @@ const sfc = { return { // internal state loading: false, + needLoadingWithLogCursors: null, intervalID: null, currentJobStepsStates: [], artifacts: [], @@ -114,7 +115,9 @@ const sfc = { toggleStepLogs(idx) { this.currentJobStepsStates[idx].expanded = !this.currentJobStepsStates[idx].expanded; if (this.currentJobStepsStates[idx].expanded) { - this.loadJob(); // try to load the data immediately instead of waiting for next timer interval + // request data load immediately instead of waiting for next timer interval (which, if the job is done, will + // never happen because the interval will have been disabled) + this.loadJob(); } }, // cancel a run @@ -229,13 +232,16 @@ const sfc = { await this.loadJob(); }, - async fetchJob() { - const logCursors = this.currentJobStepsStates.map((it, idx) => { + getLogCursors() { + return this.currentJobStepsStates.map((it, idx) => { // cursor is used to indicate the last position of the logs // it's only used by backend, frontend just reads it and passes it back, it and can be any type. // for example: make cursor=null means the first time to fetch logs, cursor=eof means no more logs, etc return {step: idx, cursor: it.cursor, expanded: it.expanded}; }); + }, + + async fetchJob(logCursors) { const resp = await POST(`${this.actionsURL}/runs/${this.runIndex}/jobs/${this.jobIndex}`, { data: {logCursors}, }); @@ -243,19 +249,45 @@ const sfc = { }, async loadJob() { - if (this.loading) return; + let myLoadingLogCursors = this.getLogCursors(); + if (this.loading) { + // loadJob is already executing; but it's possible that our log cursor request has changed since it started. If + // the interval load is active, that problem would solve itself, but if it isn't (say we're viewing a "done" + // job), then the change to the requested cursors may never be loaded. To address this we set our newest + // requested log cursors into a state property and rely on loadJob to retry at the end of its execution if it + // notices these have changed. + this.needLoadingWithLogCursors = myLoadingLogCursors; + return; + } + try { this.loading = true; + // Since no async operations occured since fetching myLoadingLogCursors, we can be sure that we have the most + // recent needed log cursors, so we can reset needLoadingWithLogCursors -- it could be stale if exceptions + // occurred in previous load attempts. + this.needLoadingWithLogCursors = null; let job, artifacts; - try { - [job, artifacts] = await Promise.all([ - this.fetchJob(), - this.fetchArtifacts(), // refresh artifacts if upload-artifact step done - ]); - } catch (err) { - if (err instanceof TypeError) return; // avoid network error while unloading page - throw err; + + while (true) { + try { + [job, artifacts] = await Promise.all([ + this.fetchJob(myLoadingLogCursors), + this.fetchArtifacts(), // refresh artifacts if upload-artifact step done + ]); + } catch (err) { + if (err instanceof TypeError) return; // avoid network error while unloading page + throw err; + } + + // We can be done as long as needLoadingWithLogCursors is null, or the same as what we just loaded. + if (this.needLoadingWithLogCursors === null || JSON.stringify(this.needLoadingWithLogCursors) === JSON.stringify(myLoadingLogCursors)) { + this.needLoadingWithLogCursors = null; + break; + } + + // Otherwise we need to retry that. + myLoadingLogCursors = this.needLoadingWithLogCursors; } this.artifacts = artifacts['artifacts'] || [];