Thursday 21 January 2021

Listening to the console log of a page loaded with Puppeteer

G'day:

This is a follow-up from something I touched on yesterday ("Polishing my Vue / Puppeteer / Mocha / Chai testing some more"). In that exercise I was using Puppeteer to load a web page I was testing, and then pulling some DOM element values out and checking they matched expectations. The relevant bits of code are thus:

describe.only("Tests of githubProfiles page using github data", function () {
    let browser;
    let page;
    let expectedUserData;

    before("Load the page and test data", async function () {
        await loadTestPage();
        expectedUserData = await loadTestUserFromGithub();
    });

    let loadTestPage = async function () {
        browser = await puppeteer.launch( {args: ["--no-sandbox"]});
        page = await browser.newPage();

        await Promise.all([
            page.goto("http://webserver.backend/githubProfiles.html"),
            page.waitForNavigation()
        ]);
    }

    it("should have the expected person's name", async function () {
        let name = await page.$eval("#app>.card>.content>a.header", headerElement => headerElement.innerText);
        name.should.equal(expectedUserData.name);
    });

  • Load the page with Puppeteer
  • Example test checking the page's DOM

This code seemed to be running fine, and the tests were passing. As I was adding more code ot my Vue component on the client end, I suddenly found the tests started to fail. Sometimes. If I ran them ten times, they'd fail maybe three times. At the same time, if I was just hitting the page in the browser, it was working 100% of the time. Odd. I mean clearly I was doing something wrong, and I'm new to all this async code I'm using, so figured I was using values before they were available or something. But it seemed odd that this was only manifesting sometimes. The way the tests were failing was telling though:

1) Tests of githubProfiles page using github data
       should have the expected person's name:

      AssertionError: expected '' to equal 'Alex Kyriakidis'
      + expected - actual

      +Alex Kyriakidis

The values coming from the DOM were blank. And note that it's not a case of the DOM being wrong, because if that was the case, the tests would barf all the time, with something like this:

Error: Error: failed to find element matching selector "#app>.card>.content>a.header"

The relevant mark-up here is:

<a class="header" :href="pageUrl">{{name}}</a>

So {{name}} isn't getting its value sometimes.

I faffed around for a bit reading up on Vue components, and their lifecycle handlers in case created was not the right place to load the data or something like that, but the code seemed legit.

My JS debugging is not very sophisticated, and it's basically a matter of console.logging stuff and see what happens. I chucked a bunch of log calls in to see what happens:

created () {
    console.debug(`before get call [${this.username}]`);
    axios.get(
        `https://api.github.com/users/${this.username}`,
        {
            auth: {
                username: this.$route.query.GITHUB_PERSONAL_ACCESS_TOKEN
            }
        }
    )
    .then(response => {
        console.debug(`beginning of then [${response.data.name}]`);
        this.name = response.data.name;
		// [etc...]
        console.debug("end of then");
    });
    console.debug("after get call");
}

Along with some other ones around the place, these all did what I expected when I hit the page in the browser:

beginning of js
githubProfiles.js:46 before VueRouter
githubProfiles.js:52 before Vue
githubProfiles.js:23 before get call [hootlex]
githubProfiles.js:43 after get call
githubProfiles.js:63 end of js
githubProfiles.js:33 beginning of then [Alex Kyriakidis]
githubProfiles.js:41 end of then

I noted that the then call was being fulfilled after the mainline code had finished, but in my test I was waiting for the page to fully load, so I'd catered for this. Repeated from above:

await Promise.all([
    page.goto("http://webserver.backend/githubProfiles.html"),
    page.waitForNavigation()
]);

I ran my tests, and was not seeing anything in the console which momentarily bemused me. But then I was just "errr… duh, Cameron. That stuff is logging in the web page's console. Not Node's console from the test run". I'm really thick sometimes.

This flumoxed me for a bit as I wondered how the hell I was going to get telemetry out of the page that I was calling in the Puppeteer headless browser. Then it occurred to me that I would not be the first person to wonder this, so just RTFMed.

It's really easy! The Puppeteer Page object exposes event listeners one can hook into, and one of the events is console. Perfect. All I needed to do is put this into my test code:

page = await browser.newPage();

page.on("console", (log) => console.debug(`Log from client: [${log.text()}] `));

await Promise.all([
    page.goto("http://webserver.backend/githubProfiles.html"),
    page.waitForNavigation()
]);

Then when I ran my tests, I was console-logging the log entries made in the headless browser as they occurred. What I was seeing is:

  Tests of githubProfiles page using github data
Log from client: [beginning of js]
Log from client: [before VueRouter]
Log from client: [before Vue]
Log from client: [before get call [hootlex]]
Log from client: [after get call]
Log from client: [end of js]
    1) should have the expected person's name
    2) should have the expected person's github page URL
    3) should have the expected person's avatar
    4) should have the expected person's joining year
    5) should have the expected person's description
Log from client: [beginning of xxxxxx then [Alex Kyriakidis]]
Log from client: [end of then]
    6) should have the expected person's number of friends
     should have the expected person's friends URL


  1 passing (4s)
  6 failing

Note how the tests get underway before the then call takes place. And shortly after that, the tests start passing because by then the dynamic values have actually been loaded into the DOM. This is my problem! that page.waitForNavigation() is not waiting long enough! My first reaction was to blame Puppeteer, but I quickly realised that's daft and defensive of me, given this is the first time I've messed with this stuff, almost certainly I'm doing something wrong. Then it occurred to me that a page is navigable once the various asset files are loaded, but not necessarily when any code in them has run. Duh. I figured Puppeteer would have thought of this, so there'd be something else I could make it wait for. I googled around and found the docs for page.waitForNavigation, and indeed I needed to be doing this:

page.waitForNavigation({waitUntil: "networkidle0"})

After I did that, I found the tests still failing sometimes, but now due to a time out:

  Tests of githubProfiles page using github data
Log from client: [beginning of js]
Log from client: [before VueRouter]
Log from client: [before Vue]
Log from client: [before get call [hootlex]]
Log from client: [after get call]
Log from client: [end of js]
Log from client: [beginning of then [Alex Kyriakidis]]
Log from client: [end of then]
    1) "before all" hook: Load the page for "should have the expected person's name"


  0 passing (4s)
  1 failing

  1) Tests of githubProfiles page using github data
       "before all" hook: Load the page for "should have the expected person's name":
     Error: Timeout of 5000ms exceeded. For async tests and hooks, ensure "done()" is called; if returning a Promise, ensure it resolves. (/usr/share/fullstackExercise/tests/functional/public/GithubProfilesTest.js)

I had the time out set for five seconds, but now the tests are waiting for the client to finish its async call as well, I was just edging over that five second mark sometimes. So I just bumped it to 10 seconds, and thenceforth the tests all passed all the time. I've left the telemetry in for one last successful run here:

  Tests of githubProfiles page using github data
Log from client: [beginning of js]
Log from client: [before VueRouter]
Log from client: [before Vue]
Log from client: [before get call [hootlex]]
Log from client: [after get call]
Log from client: [end of js]
Log from client: [beginning of then [Alex Kyriakidis]]
Log from client: [end of then]
     should have the expected person's name
     should have the expected person's github page URL
     should have the expected person's avatar
     should have the expected person's joining year
     should have the expected person's description
     should have the expected person's number of friends
     should have the expected person's friends URL


  7 passing (5s)

OK so that was a bit of a newbie exercise, but I'm a noob so yer gonna get that. It was actually pretty fun working through it though. I'm really liking all this tooling I'm checking out ATM, so yer likely get a few more of these basic articles from me.

Righto.

--
Adam