Lighthouse: NO_TRACING_STARTED error

[wildlyinaccurate]

Provide the steps to reproduce

1. Run LH on https://www.telegraaf.nl/nieuws/667381/verpleegkundigen-luiden-noodklok-werkdruk-moet-lager

What is the current behavior?

Caught exception: NO_TRACING_STARTED errors in the console and no performance or PWA score.

What is the expected behavior?

No errors :)

Environment Information

• Affected Channels: CLI
• Lighthouse version: 4.0.0-alpha.2-3.2.1
• Node.js version: 10.6.0
• Operating System: Ubuntu 18.10 (4.18.0-13-generic)

Related issues

[patrickhulce]

Thank you so much for filing @wildlyinaccurate this is first actually reproducible cases of this error I've seen!! 🙏

[voxx]

The same issue appears to impact CLI tests run from Fedora 29 as well.
I recently upgraded an app server (lh.vox.io) hosting a simple lighthouse CLI tool from Fedora 27 to 29 and subsequently every performance test generated from it fails with the same "NO_TRACING_STARTED" error.

Environment Information

• Affected Channels: CLI
• Lighthouse version: 4.0.0-alpha.2-3.2.1
• Node.js version: 10.15.0
• Operating System: Fedora release 29 (Twenty Nine) (2.9.7-2.fc29)
• Chrome Version(s): Chrome/70.0.3538.110 and Chrome/71.0.3559.0

[jkneepkens]

Got the same error while testing it in latest Chrome Canary build via the Audits tab:

Something went wrong with recording the trace over your page load. Please run Lighthouse again. (NO_TRACING_STARTED)

With these runtime settings

```Runtime settings
URL: https://www.efteling.com/nl
Fetch time: Jan 28, 2019, 1:30 PM GMT+1
Device: No emulation
Network throttling: Provided by environment
CPU throttling: Provided by environment
User agent (host): Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3686.0 Safari/537.36
Generated by Lighthouse 3.0.0-beta.0 | File an issue

[connorjclark]

Thanks @jkneepkens, we're working on a fix now.

[tmb-github]

I'm getting the same results in Chrome 74.0.3686.0 when running Lighthouse on this site:

https://ives-fourth-symphony.com

As with the other reports here, NO_TRACING_STARTED is reported for each test within the Performance category.

[tmb-github]

Stats on my test:

Runtime settings
URL: https://ives-fourth-symphony.com/
Fetch time: Jan 28, 2019, 2:28 PM CST
Device: No emulation
Network throttling: Provided by environment
CPU throttling: Provided by environment
User agent (host): Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3686.0 Safari/537.36

[tmb-github]

The same problem is now in the stable version of Chrome 72.0.3626.81 (Official Build) (64-bit), released today.

[frvge]

Using a docker-based version that I built today, it has the same issue for https://www.trivago.de , but it works on https://www.projectstealthgame.com :

Lighthouse 4.1.0
Google Chrome 73.0.3683.10 dev
Linux 78e9cd85f091 4.9.93-boot2docker #1 SMP Thu May 10 16:27:54 UTC 2018 x86_64 GNU/Linux

[alekseykulikov]

I've got the same issue when I run Chrome 72.0.3626.81 for Linux with a --single-process option.

The problem, that there's no CrRendererMain event name. https://github.com/GoogleChrome/lighthouse/blob/master/lighthouse-core/lib/traces/tracing-processor.js#L213

A quick fix is to use Chrome_InProcRendererThread which appears as the main thread in a single process environment.

(e.args.name === 'CrRendererMain' || e.args.name === 'Chrome_InProcRendererThread')

[connorjclark]

Thanks for sharing @alekseykulikov. That certainly deserves an issue of its own.

Repro:

npx -p [email protected] lighthouse https://www.hoten.cc --view --chrome-flags=--single-process

[wuyx0914]

Lifecycle:
GatherRunner.pass
--- await driver.beginTrace(settings); // only Tracing.start, but not listen Tracing.dataCollected event
--- await GatherRunner.loadPage(driver, passContext);
GatherRunner.afterPass
--- trace = await driver.endTrace(); // start listen Tracing.dataCollected event

Some trace event were lost before listen Tracing.dataCollected? Is it possibility?

[patrickhulce]

Thanks for finding @wuyx0914! Unless things drastically changed on the Chrome side of things. This isn't a possibility. Chrome keeps those events in a buffer until tracing is over to avoid dirtying the trace with all this unrelated protocol traffic.

[wuyx0914]

Thanks for finding @wuyx0914! Unless things drastically changed on the Chrome side of things. This isn't a possibility. Chrome keeps those events in a buffer until tracing is over to avoid dirtying the trace with all this unrelated protocol traffic.

Thank you for your explanation.
I solve this problems by modify these code (work for electron), but I don't know whether affect lighthouse audit.

TraceOfTab.compute_ = async (trace) => {
    // ...

    // const frameEvents = keyEvents.filter(e => e.args.frame === mainFrameIds.frameId);
    const frameEvents = keyEvents.filter(e => e.pid === mainFrameIds.pid && e.tid === mainFrameIds.tid)

    // ...
}

TraceOfTab.isNavigationStartOfInterest = (event) => {
    let url;
    if (event.args.data) {
      url = event.args.data.documentLoaderURL;
    }
    if (!url) {
      url = '';
    }
    // Config.blankUrl like 'about:blank'；
    return event.name === 'navigationStart' && !url.startsWith(Config.blankUrl); 
  }



md5-369b5e952905028fd1047ff91488813e



const findMainFrameIds = TracingProcessor.findMainFrameIds;
TracingProcessor.findMainFrameIds = (events) => {
  try {
    return findMainFrameIds(events);
  } catch (err) {
    const frameCommittedInBrowserEvt = events.find(e => e.name === 'FrameCommittedInBrowser');
    if (frameCommittedInBrowserEvt && frameCommittedInBrowserEvt.args.data) {
      const frameId = frameCommittedInBrowserEvt.args.data.frame;
      const pid = frameCommittedInBrowserEvt.args.data.processId;

      const threadNameEvt = events.find(e => e.pid === pid && e.ph === 'M' &&
        e.cat === '__metadata' && e.name === 'thread_name' && e.args.name === 'CrRendererMain');
      const tid = threadNameEvt && threadNameEvt.tid;

      if (pid && tid && frameId) {
        let res = {
          pid,
          tid,
          frameId,
        };
        return res;
      }
    }
    throw err;
  }
 }



md5-f6db606dff502c1b1c65919a0393ae95



// initial
const { lhr, artifacts } = await lighthouse({urlA}, {
    port: new URL(browser.wsEndpoint()).port,
    logLevel: "info"
});



md5-e8d66ecf84244dc4afaf7c068e9edacf



const threadNameEvt = events.find(e => e.pid === pid && e.ph === 'M' &&
        e.cat === '__metadata' && e.name === 'thread_name' && e.args.name === 'CrRendererMain')
const tid = threadNameEvt && threadNameEvt.tid



md5-d96f8267edc60ac5664b2bf7aa2e452a



[{
        "pid": 39299,
        "tid": 775,
        "ts": 1471163671541,
        "ph": "I",
        "cat": "disabled-by-default-devtools.timeline",
        "name": "TracingStartedInBrowser",
        "args": {
            "data": {
                "frameTreeNodeId": 1,
                "persistentIds": true,
                "frames": [{
                    "frame": "A3D104ED5ED2D6329FBB2EC53DC00D92",
                    "url": "http://localhost:3000/?t=1551402431715",
                    "name": "",
                    "processId": 39304
                }]
            }
        },
        "tts": 393827,
        "s": "t"
    },
    {
        "pid": 39299,
        "tid": 775,
        "ts": 1471163749265,
        "ph": "I",
        "cat": "disabled-by-default-devtools.timeline",
        "name": "FrameCommittedInBrowser",
        "args": {
            "data": {
                "frame": "A3D104ED5ED2D6329FBB2EC53DC00D92",
                "url": "https://{host}/?code=xxxx&state=yyy",
                "name": "",
                "processId": 39306
            }
        },
        "tts": 402028,
        "s": "t"
    },
    {
        "pid": 39306,
        "tid": 775,
        "ts": 1471164946302,
        "ph": "R",
        "cat": "blink.user_timing",
        "name": "navigationStart",
        "args": {
            "frame": "268AFFEF79709B8325B55117FF0A159C",
            "data": {
                "documentLoaderURL": "",
                "isLoadingMainFrame": true
            }
        },
        "tts": 815887
    },
    {
        "pid": 39306,
        "tid": 775,
        "ts": 0,
        "ph": "M",
        "cat": "__metadata",
        "name": "thread_name",
        "args": {
            "name": "CrRendererMain"
        }
    },
    {
        "pid": 39306,
        "tid": 775,
        "ts": 1471164946592,
        "ph": "R",
        "cat": "blink.user_timing",
        "name": "navigationStart",
        "args": {
            "frame": "268AFFEF79709B8325B55117FF0A159C",
            "data": {
                "documentLoaderURL": "https://{host}/service-worker.js",
                "isLoadingMainFrame": true
            }
        },
        "tts": 816174
    },
    {
        "pid": 39306,
        "tid": 775,
        "ts": 1471166064316,
        "ph": "R",
        "cat": "blink.user_timing",
        "name": "navigationStart",
        "args": {
            "frame": "6D2ECC2D774D2C3549D161CD7E1C644F",
            "data": {
                "documentLoaderURL": "",
                "isLoadingMainFrame": true
            }
        },
        "tts": 1772664
    }
]

Looking forward to your reply. @patrickhulce

[pkamran]

any update on this defect, we are facing similar king of problem, when triggering lighthouse from WPT.

[paulirish]

We think this may be resolved in 5.2.0. Sentry hasn't shown this error for a while.

[patrickhulce]

https://github.com/GoogleChrome/lighthouse/pull/7122 also should have fixed many of these cases and the original repro URL is no longer erroring. I think this can be closed. If someone finds a URL that regularly reproduces this error, please file a new issue with repro steps.

At this time, supporting traces from other Chromium-like environments (i.e. Electron) won't be officially supported if they alter the trace format.