Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

console log 'cache' doesn't get cleared unless a dump is created #75

Open
2 of 3 tasks
BloodyRain2k opened this issue Dec 8, 2023 · 0 comments
Open
2 of 3 tasks
Assignees
Labels
bug Something isn't working

Comments

@BloodyRain2k
Copy link

BloodyRain2k commented Dec 8, 2023

Before opening, please confirm:

  • I have searched for duplicate or closed issues and discussions.
  • I have done my best to include a minimal, self-contained set of instructions for consistently reproducing the issue.
  • I acknowledge that I will attach a full debug log, otherwise the issue will be closed with no response.

Environment information

System:
  OS: Windows 10 10.0.19045
  CPU: (16) x64 11th Gen Intel(R) Core(TM) i7-11800H @ 2.30GHz
  Memory: 13.24 GB / 31.73 GB
Binaries:
  Node: 14.21.1 - C:\Program Files\NodeJS\node.EXE
  npm: 6.14.17 - C:\Program Files\NodeJS\npm.CMD
Browsers:
  Edge: Spartan (44.19041.3636.0), Chromium (119.0.2151.93)
  Internet Explorer: 11.0.19041.3636
npmPackages:
  @cypress/angular:  0.0.0-development 
  @cypress/mount-utils:  0.0.0-development 
  @cypress/react:  0.0.0-development 
  @cypress/react18:  0.0.0-development 
  @cypress/svelte:  0.0.0-development 
  @cypress/vue:  0.0.0-development 
  @cypress/vue2:  0.0.0-development 
  cypress: ^13.6.1 => 13.6.1 
  cypress-debugger: ^1.0.9 => 1.0.9 
npmGlobalPackages:
  @microsoft/generator-sharepoint: 1.17.4
  gulp: 4.0.2
  spfx-fast-serve: 3.0.6
  yo: 4.3.1

Describe the bug

I'm using the debugger for a SharePoint app the dumps can get very big very easily, because Cypress and in turn the Debugger snapshot all of the libraries and other stuff.

So I've enabled the option to only dump on failed tests. But then I started noticing some odd things about the Player.

For starters, sometimes the "Console" tab showed 5 digit numbers on the first step of the test.
I do have a bunch of debug output littered all over the tests and the app itself, but that amount felt off even considering that.

It got weirder when I clicked the tab in that state, and gave the Player a minute to filter out whatever it is doing in that case, only to see "No logs" as a result.

I then proceeded to find a software that can handle parsing an 800 MB JSON file to check if there actually were logs, and yes, all of those 5 digit logs were recorded and dumped.

Which brings me to what I think the actual issue is: looking at
https://github.com/currents-dev/cypress-debugger/blob/5d55028563559cd80c93ed0fb1b52cd6a70f15dd/packages/plugin/src/install.ts#L71C19-L71C19
it seems that the logs are never cleared unless a dump is made.

So in my case I had run the entire test set for the app and only in the last 80% it encountered it's first failure.
Which then made it dump the entire console output from the beginning of the run up to this point.

Luckily, it's only the console output that is affected from this, so unless the test or app itself dump a lot of complex objects into the console (like mine does...) it has hardly a noticeable effect on the dump's size.

The sheer amount of logged entries though that the Player then in turn has to filter out do have a noticeable effect on it's responsiveness.

Expected behavior

Console output 'cache' should be cleared in on("before:spec") like below.

Modified section of https://github.com/currents-dev/cypress-debugger/blob/5d55028563559cd80c93ed0fb1b52cd6a70f15dd/packages/plugin/src/install.ts#L118-L120C6

  on('before:spec', async () => {
    clearLogs();
    await recordLogs();
  });

This prevents a dump of old console output and I'm running everything with this change so far without issues.

Command and Setup

Setup: new folder in which I only ran npm install cypress cypress-debugger, then added/configured the following files after during npx cypress open once to initialize Cypress:

cypress.config.js

const { defineConfig } = require("cypress");
const debuggerPlugin = require("cypress-debugger").debuggerPlugin;

module.exports = defineConfig({
  e2e: {
    experimentalMemoryManagement: true,
    
    chromeWebSecurity: false,
    modifyObstructiveCode: true,
    experimentalModifyObstructiveThirdPartyCode: true,
    
    setupNodeEvents(on, config) {
      debuggerPlugin(on, config, {
        failedTestsOnly: true,
        callback(path, result) {
          console.info("dump:", path);
        }
      });
      
      return config;
    },
  },
});

cypress/support/e2e.js

import './commands'
require('cypress-debugger').debuggerSupport();

cypress/e2e/poke1.cy.js

describe("Player test 1", () => {
  const max = 5;
  for (let i = 0; i < max; i++) {
    it(`Poke ${i + 1}`, { env: { idx: i } }, function() {
      const idx = Cypress.env("idx");
      console.debug("poking in test 1", { idx, meep: "meep?" });
      cy.wait(500)
      cy.wrap(idx, { timeout: 500 })
        .should("lt", max)
    });
  }
});

cypress/e2e/poke2.cy.js

describe("Player test 2", () => {
  const max = 5;
  for (let i = 0; i < max; i++) {
    it(`Poke ${i + 1}`, { env: { idx: i } }, function() {
      const idx = Cypress.env("idx");
      console.info("poking in test 2", { idx, meep: "meep?" });
      cy.wait(500)
      cy.wrap(idx, { timeout: 500 })
        .should("lt", max - 1)
    });
  }
});

debug_runner.bat

set ELECTRON_EXTRA_LAUNCH_ARGS=--remote-debugging-port=9222
cmd /c npx cypress run -s %*

actual test command ran:

.\debug_runner.bat .\cypress\e2e\p* (no -s for specs because that's in the .bat already)

The test then runs normally and creates a dump for the 5th test in the 2nd spec.

But here's how the "browserLogs" section of the dump looks like (I've trimmed it to the essential parts here):

"browserLogs": {
  "logEntry": [],
  "runtimeConsoleApiCalled": [
    {
      "type": "debug",
      "args": [
        {
          "type": "string",
          "value": "poking in test 1"
        },
        {
          ...
        }
      ],
      "executionContextId": 8,
    },
    {
      "type": "debug",
      "args": [
        {
          "type": "string",
          "value": "poking in test 1"
        },
        {
          ...
        }
      ],
      "executionContextId": 8,
    },
    {
      "type": "debug",
      "args": [
        {
          "type": "string",
          "value": "poking in test 1"
        },
        {
          ...
        }
      ],
      "executionContextId": 8,
    },
    {
      "type": "debug",
      "args": [
        {
          "type": "string",
          "value": "poking in test 1"
        },
        {
          ...
        }
      ],
      "executionContextId": 8,
    },
    {
      "type": "debug",
      "args": [
        {
          "type": "string",
          "value": "poking in test 1"
        },
        {
          ...
        }
      ],
      "executionContextId": 8,
    },
    {
      "type": "info",
      "args": [
        {
          "type": "string",
          "value": "poking in test 2"
        },
        {
          ...
        }
      ],
      "executionContextId": 8,
    },
    {
      "type": "info",
      "args": [
        {
          "type": "string",
          "value": "poking in test 2"
        },
        {
          ...
        }
      ],
      "executionContextId": 8,
    },
    {
      "type": "info",
      "args": [
        {
          "type": "string",
          "value": "poking in test 2"
        },
        {
          ...
        }
      ],
      "executionContextId": 8,
    },
    {
      "type": "info",
      "args": [
        {
          "type": "string",
          "value": "poking in test 2"
        },
        {
          ...
        }
      ],
      "executionContextId": 8,
    },
    {
      "type": "info",
      "args": [
        {
          "type": "string",
          "value": "poking in test 2"
        },
        {
          ...
        }
      ],
      "executionContextId": 8,
    }
  ]
}

The two specs are almost identical, except for the text and that the 1st uses console.debug and the 2nd console.info.
It makes it easier to check the actual dump without having to unfold the deeper nestings as it's directly shown in the "type":.

Although only the 2nd of the two specs failed it's last test, all logs of the 1st spec is also present.
The change I've made to the Debugger locally on my end prevents this.

PS: These logs made from Tests rather than the app/site being tested don't show up in the Player at all, but I'm making a separate issue for that after this.

Full log and debug output

Will be added later if needed as it will take a while to verify that all sensitive information is actually removed, and considering how easy this was to reproduce from scratch, I'm not making this my top priority now.

# Put your logs below this line
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

2 participants