NO_TRACING_STARTED error #6968

wildlyinaccurate · 2019-01-09T20:18:47Z

Provide the steps to reproduce

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

The text was updated successfully, but these errors were encountered:

patrickhulce · 2019-01-09T20:43:04Z

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

voxx · 2019-01-11T00:19:38Z

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 · 2019-01-28T12:39:13Z

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

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 · 2019-01-28T19:59:44Z

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

tmb-github · 2019-01-28T20:32:13Z

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 · 2019-01-28T20:33:14Z

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 · 2019-01-29T21:18:55Z

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

frvge · 2019-02-02T22:46:57Z

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 · 2019-02-06T14:39:17Z

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 · 2019-02-06T15:06:48Z

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

Repro:

npx -p lighthouse@4.1.0 lighthouse https://www.hoten.cc --view --chrome-flags=--single-process

wuyx0914 · 2019-02-28T01:23:07Z

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 · 2019-02-28T14:53:52Z

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 · 2019-03-01T01:55:53Z

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); 
  }

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;
  }
 }

Reason:

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

and urlA will forward to urlB immediately, like
https://www.telegraaf.nl/nieuws/667381/verpleegkundigen-luiden-noodklok-werkdruk-moet-lager
will forward to
https://tmgonlinemedia.nl/consent/consent/?return=https%3A%2F%2Fwww.telegraaf.nl%2Fnieuws%2F667381%2Fverpleegkundigen-luiden-noodklok-werkdruk-moet-lager&clienttime=1551401854965&version=5&guid=bf84919e-d774-d53b-9c7d-1a559e6483e9&detect=true

Receive trace event, and follow under scenario

'TracingStartedInBrowser' in one frame, but 'navigationStart' in another frame.
find 'TracingStartedInBrowser', but not find tid

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

Some trace event:

[{
		"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 · 2019-05-01T15:30:27Z

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

paulirish · 2019-09-24T20:03:07Z

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

patrickhulce · 2019-09-24T20:05:52Z

#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.

patrickhulce added bug needs-investigation labels Jan 9, 2019

patrickhulce mentioned this issue Jan 28, 2019

core: special case AppManifest as baseArtifact #6957

Merged

connorjclark mentioned this issue Feb 6, 2019

Lighthouse looks for event that never fires in --single-process mode #7171

Closed

paulirish added needs-priority P1 labels Feb 12, 2019

paulirish self-assigned this Feb 13, 2019

paulirish removed the needs-priority label Feb 13, 2019

paulirish added the pending-close label Sep 24, 2019

patrickhulce closed this as completed Sep 24, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

NO_TRACING_STARTED error #6968

NO_TRACING_STARTED error #6968

wildlyinaccurate commented Jan 9, 2019

patrickhulce commented Jan 9, 2019

voxx commented Jan 11, 2019

jkneepkens commented Jan 28, 2019

connorjclark commented Jan 28, 2019

tmb-github commented Jan 28, 2019

tmb-github commented Jan 28, 2019

tmb-github commented Jan 29, 2019

frvge commented Feb 2, 2019 •

edited

Loading

alekseykulikov commented Feb 6, 2019

connorjclark commented Feb 6, 2019

wuyx0914 commented Feb 28, 2019

patrickhulce commented Feb 28, 2019

wuyx0914 commented Mar 1, 2019 •

edited

Loading

pkamran commented May 1, 2019

paulirish commented Sep 24, 2019

patrickhulce commented Sep 24, 2019

NO_TRACING_STARTED error #6968

NO_TRACING_STARTED error #6968

Comments

wildlyinaccurate commented Jan 9, 2019

Provide the steps to reproduce

What is the current behavior?

What is the expected behavior?

Environment Information

patrickhulce commented Jan 9, 2019

voxx commented Jan 11, 2019

jkneepkens commented Jan 28, 2019

connorjclark commented Jan 28, 2019

tmb-github commented Jan 28, 2019

tmb-github commented Jan 28, 2019

tmb-github commented Jan 29, 2019

frvge commented Feb 2, 2019 • edited Loading

alekseykulikov commented Feb 6, 2019

connorjclark commented Feb 6, 2019

wuyx0914 commented Feb 28, 2019

patrickhulce commented Feb 28, 2019

wuyx0914 commented Mar 1, 2019 • edited Loading

pkamran commented May 1, 2019

paulirish commented Sep 24, 2019

patrickhulce commented Sep 24, 2019

frvge commented Feb 2, 2019 •

edited

Loading

wuyx0914 commented Mar 1, 2019 •

edited

Loading