Console output logged out of order when running @nightwatch/apitesting tests

[reallymello]

Description of the bug/issue

When I execute a test suite with several test cases in it leveraging @nightwatch/apitesting I'm seeing log entries from the tests in that suite getting mixed up under the headings for the other tests in the suite. Also, despite an assertion failure being logged, the overall execution reports passing. Perhaps this is related to the use of .then?

Steps to reproduce

1. Run nightwatch in the ./apiTesting/ folder from here https://github.com/reallymello/nightwatchTutorials/tree/master/apiTesting

Sample test

module.exports = {
  'can GET count of sold inventory': ({ supertest }) => {
    supertest
      .request('https://petstore.swagger.io/v2')
      .get('/store/inventory/')
      .expect(200)
      .expect('Content-Type', /json/)
      .then((response) => {
        expect(response.body.sold).to.be.greaterThan(0);
        // console.log(JSON.stringify(response.body, null, 2));
      });
  },
  'can POST a pet to the store': ({ supertest }) => {
    supertest
      .request('https://petstore.swagger.io/v2')
      .post('/pet')
      .send({
        id: 31337,
        category: {
          id: 1313,
          name: 'owls',
        },
        name: 'Bitey',
        photoUrls: ['https://nightwatchjs.org/images/images1/mini_logo.svg'],
        tags: [
          {
            id: 0,
            name: 'replicant',
          },
        ],
        status: 'available',
      })
      .expect(200)
      .expect('Content-Type', /json/)
      .then((response) => {
        expect(response.body.id).to.equal(31337);
        expect(response.body.status).to.equal('availablee'); // purposeful typo to test Nightwatch bug
      });
  },
  'can POST order to the pet store': ({ supertest }) => {
    supertest
      .request('https://petstore.swagger.io/v2')
      .post('/store/order')
      .send({
        id: 0,
        petId: 31337,
        quantity: 1,
        shipDate: '2022-12-30T14:55:04.147Z',
        status: 'placed',
        complete: true,
      })
      .expect(200)
      .expect('Content-Type', /json/)
      .then((response) => {
        expect(response.body.id).to.be.greaterThan(0);
        expect(response.body.quantity).to.equal(1);
        expect(response.body.status).to.equal('placed');
      });
  },
};

Command to run

nightwatch

Verbose Output

C:\Projects\nightwatchTutorials\apiTesting> nightwatch --verbose
 Launching up to 1 concurrent test worker processes...

 Running:  default: petStore.js 

┌ ────────────────── √  default: petStore.js  ───────────────────────────────────────────────────────────┐
│                                                                                                        │
│                                                                                                        │
│    [Pet Store] Test Suite                                                                              │
│    ────────────────────────────────────────────                                                        │
│    → Running [before]:                                                                                 │
│    → Completed [before].                                                                               │
│                                                                                                        │
│    – can GET count of sold inventory                                                                   │
│    → Running [beforeEach]:                                                                             │
│    → Completed [beforeEach].                                                                           │
│                                                                                                        │
│     → Running command: request ('https://petstore.swagger.io/v2')                                      │
│                                                                                                        │
│     → Running command: assert.ok ()                                                                    │
│    √ Passed [ok]: .get('/store/inventory/').expect(200) ok                                             │
│     → Completed command: assert.ok () (0ms)                                                            │
│                                                                                                        │
│     → Running command: assert.ok ()                                                                    │
│    √ Passed [ok]: .get('/store/inventory/').expect('Content-Type', /json/) ok                          │
│     → Completed command: assert.ok () (0ms)                                                            │
│                                                                                                        │
│     → Running command: expect(<value>)..to.be.greaterThan(+0) ()                                       │
│    √ Expected 3  to be greaterThan(+0):                                                                │
│     → Completed command: expect(<value>)..to.be.greaterThan(+0) () (1ms)                               │
│    → Running [afterEach]:                                                                              │
│    → Completed [afterEach].                                                                            │
│    √ default: petStore.js [Pet Store] can GET count of sold inventory (253ms)                          │
│    – can POST a pet to the store                                                                       │
│    → Running [beforeEach]:                                                                             │
│    → Completed [beforeEach].                                                                           │
│                                                                                                        │
│     → Running command: request ('https://petstore.swagger.io/v2')                                      │
│     → Completed command: request ('https://petstore.swagger.io/v2') (268ms)                            │
│     → Completed command: request ('https://petstore.swagger.io/v2') (31ms)                             │
│    → Running [afterEach]:                                                                              │
│    → Completed [afterEach].                                                                            │
│    √ default: petStore.js [Pet Store] can POST a pet to the store (36ms)                               │
│    – can POST order to the pet store                                                                   │
│    → Running [beforeEach]:                                                                             │
│    → Completed [beforeEach].                                                                           │
│                                                                                                        │
│     → Running command: request ('https://petstore.swagger.io/v2')                                      │
│     → Completed command: request ('https://petstore.swagger.io/v2') (8ms)                              │
│    → Running [afterEach]:                                                                              │
│    → Completed [afterEach].                                                                            │
│    √ default: petStore.js [Pet Store] can POST order to the pet store                                  │
│    → Running [after]:                                                                                  │
│    → Completed [after].                                                                                │
│                                                                                                        │
│     → Running command: assert.ok ()                                                                    │
│    √ Passed [ok]: .post('/pet').expect(200) ok                                                         │
│     → Completed command: assert.ok () (0ms)                                                            │
│                                                                                                        │
│     → Running command: assert.ok ()                                                                    │
│    √ Passed [ok]: .post('/pet').expect('Content-Type', /json/) ok                                      │
│     → Completed command: assert.ok () (0ms)                                                            │
│                                                                                                        │
│     → Running command: expect(<value>)..to.equal(31337) ()                                             │
│    √ Expected 31337  to equal(31337):                                                                  │
│     → Completed command: expect(<value>)..to.equal(31337) () (1ms)                                     │
│                                                                                                        │
│     → Running command: expect(<value>)..to.equal('availablee') ()                                      │
│     ✖ NightwatchAssertError                                                                            │
│       expected 'available' to equal 'availablee' - expected "availablee" but got: "available" (2ms)    │
│     → Completed command: expect(<value>)..to.equal('availablee') () (1ms)                              │
│                                                                                                        │
│     → Running command: assert.ok ()                                                                    │
│    √ Passed [ok]: .post('/store/order').expect(200) ok                                                 │
│     → Completed command: assert.ok () (0ms)                                                            │
│                                                                                                        │
│     → Running command: assert.ok ()                                                                    │
│    √ Passed [ok]: .post('/store/order').expect('Content-Type', /json/) ok                              │
│     → Completed command: assert.ok () (0ms)                                                            │
│                                                                                                        │
│     → Running command: expect(<value>)..to.be.greaterThan(+0) ()                                       │
│    √ Expected 4611686018427388000  to be greaterThan(+0):                                              │
│     → Completed command: expect(<value>)..to.be.greaterThan(+0) () (0ms)                               │
│                                                                                                        │
│     → Running command: expect(<value>)..to.equal(1) ()                                                 │
│    √ Expected 1  to equal(1):                                                                          │
│     → Completed command: expect(<value>)..to.equal(1) () (0ms)                                         │
│                                                                                                        │
│     → Running command: expect(<value>)..to.equal('placed') ()                                          │
│    √ Expected 'placed'  to equal('placed'):                                                            │
│     → Completed command: expect(<value>)..to.equal('placed') () (0ms)                                  │
│                                                                                                        │
└────────────────────────────────────────────────────────────────────────────────────────────────────────┘

  ✨ PASSED. 3 total assertions (2.037s)

Nightwatch Configuration

// Refer to the online docs for more details:
// https://nightwatchjs.org/gettingstarted/configuration/
//

//  _   _  _         _      _                     _          _
// | \ | |(_)       | |    | |                   | |        | |
// |  \| | _   __ _ | |__  | |_ __      __  __ _ | |_   ___ | |__
// | . ` || | / _` || '_ \ | __|\ \ /\ / / / _` || __| / __|| '_ \
// | |\  || || (_| || | | || |_  \ V  V / | (_| || |_ | (__ | | | |
// \_| \_/|_| \__, ||_| |_| \__|  \_/\_/   \__,_| \__| \___||_| |_|
//             __/ |
//            |___/

module.exports = {
  // An array of folders (excluding subfolders) where your tests are located;
  // if this is not specified, the test source must be passed as the second argument to the test runner.
  src_folders: ['test'],

  // See https://nightwatchjs.org/guide/concepts/page-object-model.html
  page_objects_path: [],

  // See https://nightwatchjs.org/guide/extending-nightwatch/adding-custom-commands.html
  custom_commands_path: [],

  // See https://nightwatchjs.org/guide/extending-nightwatch/adding-custom-assertions.html
  custom_assertions_path: [],

  // See https://nightwatchjs.org/guide/extending-nightwatch/adding-plugins.html
  plugins: ['@nightwatch/apitesting'],

  // See https://nightwatchjs.org/guide/concepts/test-globals.html
  globals_path: '',

  webdriver: {},

  test_workers: {
    enabled: true,
  },

  test_settings: {
    default: {
      skip_testcases_on_fail: false,
      disable_error_log: false,
      launch_url: 'http://localhost',

      screenshots: {
        enabled: false,
        path: 'screens',
        on_failure: true,
      },

      desiredCapabilities: {
        browserName: 'chrome',
      },

      start_session: false,
      webdriver: {
        start_process: false,
        server_path: '',
      },
    },

    chrome: {
      desiredCapabilities: {
        browserName: 'chrome',
        'goog:chromeOptions': {
          // More info on Chromedriver: https://sites.google.com/a/chromium.org/chromedriver/
          //
          // w3c:false tells Chromedriver to run using the legacy JSONWire protocol (not required in Chrome 78)
          w3c: true,
          args: [
            //'--no-sandbox',
            //'--ignore-certificate-errors',
            //'--allow-insecure-localhost',
            //'--headless'
          ],
        },
      },

      webdriver: {
        start_process: true,
        server_path: '',
        cli_args: [
          // --verbose
        ],
      },
    },
  },
};

Nightwatch.js Version

2.6.3

Node Version

16.15.0

Browser

Chrome

Operating System

Windows 10

Additional Information

https://github.com/reallymello/nightwatchTutorials/tree/master/apiTesting

[beatfactor]

it seems like the old callback style doesn't work reliable when using supertest api testing so we're only going to support the async version for when writing supertest api tests using the @nightwatch/apitesting plugin.

@reallymello Given the example you provided, this works reliable using nightwatch 2.6.4 and @nightwatch/apitesting v0.2.1:

test('can GET count of sold inventory', async ({ supertest }) => {
  await supertest
    .request('https://petstore.swagger.io/v2')
    .get('/store/inventory/')
    .expect(200)
    .expect('Content-Type', /json/)
    .then((response) => {
      expect(response.body.sold).to.be.greaterThan(0);
      // console.log(JSON.stringify(response.body, null, 2));
    });
});

test('can POST a pet to the store', async ({ supertest }) => {
  await supertest
    .request('https://petstore.swagger.io/v2')
    .post('/pet')
    .send({
      id: 31337,
      category: {
        id: 1313,
        name: 'owls',
      },
      name: 'Bitey',
      photoUrls: ['https://nightwatchjs.org/images/images1/mini_logo.svg'],
      tags: [
        {
          id: 0,
          name: 'replicant',
        },
      ],
      status: 'available',
    })
    .expect(200)
    .expect('Content-Type', /json/)
    .then((response) => {
      expect(response.body.id).to.equal(31337);
      expect(response.body.status).to.equal('availablee'); // purposeful typo to test Nightwatch bug
    });
});

test('can POST order to the pet store', async ({ supertest }) => {
  await supertest
    .request('https://petstore.swagger.io/v2')
    .post('/store/order')
    .send({
      id: 0,
      petId: 31337,
      quantity: 1,
      shipDate: '2022-12-30T14:55:04.147Z',
      status: 'placed',
      complete: true,
    })
    .expect(200)
    .expect('Content-Type', /json/)
    .then((response) => {
      expect(response.body.id).to.be.greaterThan(0);
      expect(response.body.quantity).to.equal(1);
      expect(response.body.status).to.equal('placed');
    });
});

[reallymello]

Just checked in 2.6.4 using async/await instead and it is logging correctly and catching the seeded expect mismatch in the then. Looks good now.

[beatfactor]

awesome, thanks for your help fixing this!