ci: fix flaky tests (#12836)

Author: shreemaan-abhishek

t/APISIX.pm

@@ -380,9 +380,10 @@ _EOC_
             location /exec_request {
                 content_by_lua_block {
                     local shell = require("resty.shell")
-                    local ok, stdout, stderr, reason, status = shell.run([[ $exec_snippet ]], $stdin, @{[$timeout*1000]}, $max_size)
+                    -- timeout one second before the actual timeout to allow shell.run to finish and collect the stdout/stderr
+                    local ok, stdout, stderr, reason, status = shell.run([[ $exec_snippet ]], $stdin, @{[($timeout-1)*1000]}, $max_size)
                     if not ok then
-                        ngx.log(ngx.WARN, "failed to execute the script with status: " .. status .. ", reason: " .. reason .. ", stderr: " .. stderr)
+                        ngx.log(ngx.WARN, "failed to execute the script with status: " .. (status or "nil ") .. ", reason: " .. (reason or "nil ") .. ", stderr: " .. (stderr or "nil "))
                         ngx.print("stdout: ", stdout)
                         ngx.print("stderr: ", stderr)
                         return

t/package.json

@@ -3,7 +3,7 @@
   "private": true,
   "type": "module",
   "scripts": {
-    "test": "NODE_OPTIONS=--experimental-vm-modules jest"
+    "test": "NODE_OPTIONS=--experimental-vm-modules jest --verbose"
   },
   "devDependencies": {
     "@jest/globals": "^29.7.0",

t/plugin/lago.spec.mts

@@ -19,7 +19,7 @@ import { existsSync } from 'node:fs';
 import { readFile, rm, writeFile } from 'node:fs/promises';
 import { promisify } from 'node:util';
 
-import { afterAll, beforeAll, describe, expect, it } from '@jest/globals';
+import { afterAll, beforeAll, describe, expect, it, jest } from '@jest/globals';
 import axios from 'axios';
 import * as compose from 'docker-compose';
 import { gql, request } from 'graphql-request';
@@ -69,6 +69,7 @@ const launchLago = async () => {
     cwd: LAGO_PATH,
     log: true,
     env: {
+      ...process.env,
       LAGO_RSA_PRIVATE_KEY: Buffer.from(privateKey).toString('base64'),
       FRONT_PORT: `${LAGO_FRONT_PORT}`, // avoiding conflicts, tests do not require a front-end
       API_PORT: `${LAGO_API_PORT}`,
@@ -227,24 +228,31 @@ describe('Plugin - Lago', () => {
 
   // set up
   beforeAll(async () => {
+    console.log(`[${new Date().toLocaleTimeString()}] starting suite`)
     if (existsSync(LAGO_PATH)) await rm(LAGO_PATH, { recursive: true });
+    console.log(`[${new Date().toLocaleTimeString()}] download compose file`)
     await downloadComposeFile();
+    console.log(`[${new Date().toLocaleTimeString()}] launch lago`)
     await launchLago();
+    console.log(`[${new Date().toLocaleTimeString()}] provision lago`)
     let res = await provisionLago();
     restAPIKey = res.apiKey;
     lagoClient = res.client;
   }, 120 * 1000);
 
   // clean up
   afterAll(async () => {
+    console.log(`[${new Date().toLocaleTimeString()}] cleaning up`)
     await compose.downAll({
       cwd: LAGO_PATH,
       commandOptions: ['--volumes'],
     });
+    console.log(`[${new Date().toLocaleTimeString()}] cleaned up`)
     await rm(LAGO_PATH, { recursive: true });
   }, 30 * 1000);
 
   it('should create route', async () => {
+    console.log(`[${new Date().toLocaleTimeString()}] creating route`)
     await expect(
       requestAdminAPI('/apisix/admin/routes/1', 'PUT', {
         uri: '/hello',
@@ -269,6 +277,7 @@ describe('Plugin - Lago', () => {
       }),
     ).resolves.not.toThrow();
 
+    console.log(`[${new Date().toLocaleTimeString()}] creating second route`)
     await expect(
       requestAdminAPI('/apisix/admin/routes/2', 'PUT', {
         uri: '/hello1',
@@ -293,53 +302,66 @@ describe('Plugin - Lago', () => {
         },
       }),
     ).resolves.not.toThrow();
-  });
+    console.log(`[${new Date().toLocaleTimeString()}] created routes`)
+  }, 5 * 1000);
 
-  it('should create consumer', async () =>
+  it('should create consumer', async () => {
+    console.log(`[${new Date().toLocaleTimeString()}] creating consumer`)
     expect(
       requestAdminAPI(`/apisix/admin/consumers/${JACK_USERNAME}`, 'PUT', {
         username: JACK_USERNAME,
         plugins: {
           'key-auth': { key: JACK_USERNAME },
         },
       }),
-    ).resolves.not.toThrow());
+    ).resolves.not.toThrow()
+    console.log(`[${new Date().toLocaleTimeString()}] created consumer`)
+  });
 
   it('call API (without key)', async () => {
+    console.log(`[${new Date().toLocaleTimeString()}] calling API without key`)
     const res = await client.get('/hello', { validateStatus: () => true });
     expect(res.status).toEqual(401);
-  });
+    console.log(`[${new Date().toLocaleTimeString()}] called API without key`)
+  }, 5 * 1000);
 
   it('call normal API', async () => {
+    console.log(`[${new Date().toLocaleTimeString()}] calling normal API`)
     for (let i = 0; i < 3; i++) {
       await expect(
         client.get('/hello', { headers: { apikey: JACK_USERNAME } }),
       ).resolves.not.toThrow();
     }
     await wait(500);
-  });
+    console.log(`[${new Date().toLocaleTimeString()}] called normal API`)
+  }, 5 * 1000);
 
   it('check Lago events (normal API)', async () => {
+    console.log(`[${new Date().toLocaleTimeString()}] checking Lago events (normal API)`)
     const { data } = await lagoClient.events.findAllEvents({
       external_subscription_id: LAGO_EXTERNAL_SUBSCRIPTION_ID,
     });
 
     expect(data.events).toHaveLength(3);
     expect(data.events[0].code).toEqual(LAGO_BILLABLE_METRIC_CODE);
-  });
+    console.log(`[${new Date().toLocaleTimeString()}] checked Lago events (normal API)`)
+  }, 5 * 1000);
 
   let expensiveStartAt: Date;
   it('call expensive API', async () => {
+    console.log(`[${new Date().toLocaleTimeString()}] calling expensive API`)
     expensiveStartAt = new Date();
     for (let i = 0; i < 3; i++) {
       await expect(
         client.get('/hello1', { headers: { apikey: JACK_USERNAME } }),
       ).resolves.not.toThrow();
     }
     await wait(500);
-  });
+    console.log(`[${new Date().toLocaleTimeString()}] called expensive API`)
+  }, 5 * 1000);
 
   it('check Lago events (expensive API)', async () => {
+    console.log(`[${new Date().toLocaleTimeString()}] checking Lago events (expensive API)`)
     const { data } = await lagoClient.events.findAllEvents({
       external_subscription_id: LAGO_EXTERNAL_SUBSCRIPTION_ID,
       timestamp_from: expensiveStartAt.toISOString(),
@@ -348,5 +370,6 @@ describe('Plugin - Lago', () => {
     expect(data.events).toHaveLength(3);
     expect(data.events[0].code).toEqual(LAGO_BILLABLE_METRIC_CODE);
     expect(data.events[1].properties).toEqual({ tier: 'expensive' });
-  });
+    console.log(`[${new Date().toLocaleTimeString()}] checked Lago events (expensive API)`)
+  }, 5 * 1000);
 });

t/plugin/lago.t

@@ -67,7 +67,7 @@ property "event_properties" validation failed: wrong type: expected object, got
 
 
 === TEST 2: test
---- timeout: 300
+--- timeout: 302
 --- max_size: 2048000
 --- exec
 cd t && pnpm test plugin/lago.spec.mts 2>&1

t/plugin/sls-logger.t

@@ -486,6 +486,7 @@ hello world
                 log_format = "bad plugin metadata"
             }
             local _, err = core.etcd.set(key, val)
+            ngx.sleep(1)
             if err then
                 ngx.say(err)
                 return