Output indenting issue

[oddui]

See https://travis-ci.org/oddui/webdriver-extension/jobs/170984533 the first run passes and the second fails. The indentation starts to be one level further after the failed test.

Is it just a formatting issue or are the tests running in some strange order/nesting/context? I'm not able to find out why my tests fail from time to time and hope to get some ideas here. The code for the failed test can be found here. Thank you!

[ScottFreeCode]

Hmm...

The output is definitely weird; it's not just got the wrong indentation in the next suite, it's actually missing the contents of the tabs suite, except for the name of the nested suite updateTabs_, which is mixed into the following frames suite -- and, if the following analysis of the error is right, the error is being printed too early when it should be printed in the updateTabs_ suite.

As to the error itself: the name of the failure and the stacktrace, along with the fact that updateTabs_ is the only thing in the tabs suite that gets printed, suggest that the beforeEach hook in the Session suite in the extension suite runs something that triggers a failure in the code installed by the before hook for the tabs suite. I'm not sure why it would happen inconsistently, but maybe the stack trace can point you deep enough into the code being run to figure out what actually went wrong?

In the meantime, I guess the question is, can we reproduce the garbled output by rigging a similar failure of an outer suite's beforeEach hook during testing in inner suites...

[oddui]

@ScottFreeCode thanks so much for the detailed response. I couldn't find out what could be wrong with the beforeEach hook you mentioned, but i'll keep trying.

I got another instance of the issue which you might be interested. The error happens in the Session page load timeout suite and still seems to be printed early. Also a few tests get printed twice after the error.

  Builder
    usingServer
      ✓ sets server url
    withCapabilities
      ✓ converts argument to `capabilities.Capabilities`
    delegates capabilitis methods to the capabilities object
      ✓ setProxy
      ✓ setLoggingPrefs
      ✓ setEnableNativeEvents
      ✓ setScrollBehavior
      ✓ setAlertBehavior
    build
      ✓ throws error if browser not set
      when server url is not set
        ✓ throws error for non-chrome browsers
        - creates a `webdriver.WebDriver` instance with a `debugger.Executor` for chrome

  chrome
    ✓ exports Option
    chrome.Options
      fromCapabilities
        ✓ returns a new Options instance if none was defined
        ✓ returns Options instance if present
        ✓ rebuilds options from wire representation
        ✓ rebuilds options from incomplete wire representation
        ✓ extracts supported WebDriver capabilities
      addArguments
        ✓ takes var_args
        ✓ flattens input arrays
      addExtensions
        ✓ takes var_args
        ✓ flattens input arrays
      serialize
Cannot install extension from path extensionFilePath.
        ✓ does not support base64 encodes extensions
      toCapabilities
        ✓ returns a new capabilities object if one is not provided
        ✓ adds to input capabilities object
        ✓ sets generic driver capabilities

  extension
    Debugger
      isConnected
        ✓ returns true if connected
      connect
        ✓ returns resolved promise if connect again
        ✓ emits debugger events
        ✓ cleans debugger state on unexpected detach
      disconnect
        ✓ returns resolved promise if disconnect again
        ✓ cleans debugger state
      sendCommand
        ✓ throws error if not connected to debuggee
        ✓ resolves with command result
        ✓ emits commandSuccess event
        with timeout
          ✓ resolves if not timed out (207ms)
          ✓ rejects if timed out (108ms)

  extension
    FrameTracker
      connect
        ✓ adds listeners to debugger events
        ✓ enables reporting runtime and page events
      onExecutionContextCreated
        ✓ throws WebDriverError if parameters missing context
        ✓ throws WebDriverError if parameters has invalid context
        ✓ tracks frame if context is default and contians frameId
      onExecutionContextDestroyed
        ✓ throws WebDriverError if parameters missing executionContextId
        ✓ deletes the tracking frame
      onExecutionContextsCleared
        ✓ clears the internal frame tracking map
      Page.frameNavigated
        ✓ clears the internal frame tracking map if top frame navigated
      getContextIdForFrame
        ✓ clears the internal frame tracking map if top frame navigated

  extension
    Executor
      execute
        ✓ throws error if executing non-supported command

  extension
    JavaScriptDialogManager
      connect
        ✓ adds listeners to debugger events
        ✓ enables reporting page events
      onJavaScriptDialogOpening
        ✓ throws WebDriverError if parameters has invalid message
        ✓ pushes message to the end of the unhandled dialog queue
      onJavaScriptDialogClosed
        ✓ clears the unhandled dialog queue
      isDialogOpen
        ✓ returns true if unhandled dialog queue is not empty
      getDialogMessage
        ✓ throws no such alert error if unhandled dialog queue is empty
        ✓ returns the message at the front of the unhandled dialog queue
      handleDialog
        ✓ rejects with no such alert error if unhandled dialog queue is empty
        ✓ sends Page.handleJavaScriptDialog debugging command

  extension
    newSession
      ✓ throws session not created if reached maximum active sessions
      ✓ adds new session in active sessions
      capabilities
        ✓ throws session not created if desiredCapabilities not passed in
        ✓ throws session not created if required capabilities cannot be met
        ✓ throws session not created if required capability is unknown
    deleteSession
      ✓ throws no such session error if cannot find session with id
      ✓ removes session from active sessions

  extension
    active sessions
      findSession
        ✓ finds session by id
      removeSession
        ✓ removes session by id
    Session
      ✓ has an associated session id (UUID)
      script timeout
        ✓ is 30,000 milliseconds by default
        ✓ can be set to other values
        ✓ throws error if not set to a number
      page load timeout
        ✓ is 300,000 milliseconds by default
        1) "before each" hook
        ✓ can be set to other values
      implicit wait timeout
        ✓ is 0 milliseconds by default
        ✓ is 0 milliseconds by default
        ✓ can be set to other values
        page load strategy
          ✓ throws error if not set to a number
          ✓ can be set to other strategies
          ✓ can be set to other strategies
        secure SSL state
          ✓ is true by default
          ✓ can be set through `acceptSslCerts`
        tabs
          updateTabs_
            ✓ removes closed tabs
            ✓ adds newly-opened tabs
          getTabIds
            ✓ updates tabs and returns tab ids
          getFirstTabId
            ✓ updates tabs and returns the first tab id
          closeTab
            ✓ closes the tab in chrome and removes it from tracking tabs
          setTargetTabId
            ✓ sets target tab id
          getTargetTab
            ✓ gets target tab by target tab id
            ✓ throws no such window error if cannot find tab by target tab id
        frames
          switchToTopFrame
            ✓ empties the frames array
          switchToParentFrame
            ✓ removes a frame from the end of frames array
          switchToSubFrame
            ✓ appends the sub frame to the end of frames array
            ✓ set parent frame id
          getCurrentFrameId
            ✓ returns frame id of the frame from the end of frames array
            ✓ returns "" for top frame
    extension
      Tab
        connectIfNecessary
          ✓ connects debugger, frame tracker and dialog manager
          ✓ resovles if already connected
        getContextIdForFrame
          ✓ calls getContextIdForFrame on frameTracker
        setMobileEmulationOverride
          ✓ sends debugging commands
        load
          ✓ sends Page.navigate debugging command
        reload
          ✓ sends Page.reload debugging command
    http
      ✓ exports Request
      ✓ exports Response
      ✓ exports Executor
      ✓ exports Client
      fromXhr
        ✓ sets status
        ✓ strips null characters from response body
        parses headers
          ✓ windows
          ✓ unix
          ✓ handles response with no headers
      HttpClient
        constructor
          ✓ throws error if serverUrl is invalid
        #send()
          ✓ trims request path leading "/" if needed
          ✓ sets headers from `Request#headers`
          ✓ sets "Content-Type" header to json for POST
          ✓ sets "Content-Type" header to json for PUT
          ✓ does not send request body for GET
          ✓ does not send request body for PATCH
          ✓ does not send request body for DELETE
          ✓ returns promise resolving the response
          ✓ returns promise rejecting with an error if unable to send
    index
      ✓ exports version
      ✓ exports Builder
      ✓ exports By
      ✓ exports until
      ✓ exports logging
    version
      ✓ is SemVer
      ✓ defines selenium-webdriver version


  124 passing (607ms)
  1 pending
  1 failing

  1) extension Session "before each" hook:
     Uncaught TypeError: Cannot read property 'runtime' of undefined
      at app/src/lib/extension/debugger.js:186:19
      at null._onTimeout (app/test/spec/extension/fake_chrome_api.js:63:7)

[oddui]

Hi @ScottFreeCode i finally fixed my randomly failing tests. The below code should reproduce the issue i had. I'm not sure if it's a bug with mocha.

'use strict';

function noop() {}

function send(timeout) {
  return new Promise((resolve, reject) => {
    let timer = setTimeout(reject, timeout);

    setTimeout(() => {
      timer && clearTimeout(timer);

      console.log('logs: invoke callme');
      global.callme();
      resolve();
    }, timeout + 5);
  });
}

describe('send', function() {
  beforeEach(() => {
    console.log('logs: beforeEach');
    global.callme = noop;
  });

  afterEach(() => {
    console.log('logs: afterEach');
    global.callme = undefined;
  });

  it('times out', function() {
    return send(100)
      .catch(e => {});
  });
});

describe('other', () => {
  it('fails', () => {});
});

I get this output sometimes

  send
logs: beforeEach
    ✓ times out (103ms)
logs: afterEach

  other
logs: invoke callme
    1) "after each" hook


  1 passing (117ms)
  1 failing

  1) send "after each" hook:
     Uncaught TypeError: global.callme is not a function
      at null._onTimeout (app/test/gjoewijldsd.js:13:14)

[boneskull]

Has something to do with cleanup not happening properly. The fix would be in the runner, reporter, or both.

[oddui]

@boneskull @ScottFreeCode I'm happy to help but i'm not sure what to do with it. It looks like the user set timeouts are not cleared. The only thing i can think of is to patch setTimeout to store timeout ids set by user and later clear them. Does that sound like a plan?

[ScottFreeCode]

:thinking: I've had to block out some time to work this one out, but I actually think the only thing Mocha's got wrong here is less-than-perfect reporting of the error.

Your promise creates two timeouts, either one of which will make the promise no longer pending (i.e. tell Mocha that the test succeeded or failed), but only one of the two timeouts stops the other from still happening later, and the one that isn't stopped takes potentially erroneous actions regardless of what it does to the test suite (indeed, if it didn't hit the hard error of using part of the environment that's no longer there, it would hit the soft error of trying to resolve the promise when it's already been rejected -- or maybe that's a hard error too depending on the promise library, I haven't checked). So we can't, say, suppress the error -- it's a legit error and should be reported as some kind of failure (ideally a failure of the test case that set up the timeout, although I'm not aware of a sane way to retrieve the point of origin of an asynchronous callback -- "something something domains bad something zones good something something why would we bother actually explaining how they're different" is all I found last time I went looking for this).

We could mayyyybe try to detect tests that set up asynchronous callbacks and don't clean them all up by test end and consider that a test failure case (as well as, perhaps, trying to cancel the callback), but there are a lot of different asynchronous callbacks in Node and I am not sure all of them are cancellable, so that behavior could get inconsistent really easily...

I suspect it would be better simply to fix the current reporting of the error so that it is not misleadingly listed as though it came from the most recently run hook, and then leave it to the JS stacktrace to point at the exact spot in the code where the error occurred (granted, stacktraces in async callbacks are useless for viewing the stack, but they can at least tell you the place inside the callback that threw, which in turn tells you which callback threw if nothing else).

[stale[bot]]

I am a bot that watches issues for inactivity. This issue hasn't had any recent activity, and I'm labeling it stale. In 14 days, if there are no further comments or activity, I will close this issue. Thanks for contributing to Mocha!

[boneskull]

not stale

[tylerweitzman]

It would be nice to have a mocha log function that would do two things: (1) Auto indent at the appropriate level (2) Delay output of errors to after the name of the test corresponding to it rather than before

[mkdior]

It would be nice to have a mocha log function that would do two things: (1) Auto indent at the appropriate level (2) Delay output of errors to after the name of the test corresponding to it rather than before

++ on (1)