fix: make `$inspect` logs come from the callsite (#17001)

* fix: make `$inspect` logs come from the callsite

* default to showing stack trace

* reuse id

* DRY out, improve server-side inspect

* update docs

* ugh

* fix the dang tests

* ugh windows is there no punch bowl you won't poop in?

* argh

* how about this

* alright finally

.changeset/silly-penguins-sleep.md

@@ -0,0 +1,5 @@
+---
+'svelte': patch
+---
+
+fix: make `$inspect` logs come from the callsite

documentation/docs/02-runes/07-$inspect.md

@@ -18,6 +18,8 @@ The `$inspect` rune is roughly equivalent to `console.log`, with the exception t
 <input bind:value={message} />
 ```
 
+On updates, a stack trace will be printed, making it easy to find the origin of a state change (unless you're in the playground, due to technical limitations).
+
 ## $inspect(...).with
 
 `$inspect` returns a property `with`, which you can invoke with a callback, which will then be invoked instead of `console.log`. The first argument to the callback is either `"init"` or `"update"`; subsequent arguments are the values passed to `$inspect` ([demo](/playground/untitled#H4sIAAAAAAAACkVQ24qDMBD9lSEUqlTqPlsj7ON-w7pQG8c2VCchmVSK-O-bKMs-DefKYRYx6BG9qL4XQd2EohKf1opC8Nsm4F84MkbsTXAqMbVXTltuWmp5RAZlAjFIOHjuGLOP_BKVqB00eYuKs82Qn2fNjyxLtcWeyUE2sCRry3qATQIpJRyD7WPVMf9TW-7xFu53dBcoSzAOrsqQNyOe2XUKr0Xi5kcMvdDB2wSYO-I9vKazplV1-T-d6ltgNgSG1KjVUy7ZtmdbdjqtzRcphxMS1-XubOITJtPrQWMvKnYB15_1F7KKadA_AQAA)):
@@ -36,13 +38,6 @@ The `$inspect` rune is roughly equivalent to `console.log`, with the exception t
 <button onclick={() => count++}>Increment</button>
 ```
 
-A convenient way to find the origin of some change is to pass `console.trace` to `with`:
-
-```js
-// @errors: 2304
-$inspect(stuff).with(console.trace);
-```
-
 ## $inspect.trace(...)
 
 This rune, added in 5.14, causes the surrounding function to be _traced_ in development. Any time the function re-runs as part of an [effect]($effect) or a [derived]($derived), information will be printed to the console about which pieces of reactive state caused the effect to fire.

packages/svelte/src/compiler/phases/3-transform/client/visitors/CallExpression.js

@@ -1,10 +1,10 @@
-/** @import { CallExpression, Expression } from 'estree' */
+/** @import { CallExpression, Expression, MemberExpression } from 'estree' */
 /** @import { Context } from '../types' */
 import { dev, is_ignored } from '../../../../state.js';
 import * as b from '#compiler/builders';
 import { get_rune } from '../../../scope.js';
-import { transform_inspect_rune } from '../../utils.js';
 import { should_proxy } from '../utils.js';
+import { get_inspect_args } from '../../utils.js';
 
 /**
  * @param {CallExpression} node
@@ -73,7 +73,7 @@ export function CallExpression(node, context) {
 
 		case '$inspect':
 		case '$inspect().with':
-			return transform_inspect_rune(node, context);
+			return transform_inspect_rune(rune, node, context);
 	}
 
 	if (
@@ -104,3 +104,21 @@ export function CallExpression(node, context) {
 
 	context.next();
 }
+
+/**
+ * @param {'$inspect' | '$inspect().with'} rune
+ * @param {CallExpression} node
+ * @param {Context} context
+ */
+function transform_inspect_rune(rune, node, context) {
+	if (!dev) return b.empty;
+
+	const { args, inspector } = get_inspect_args(rune, node, context.visit);
+
+	// by passing an arrow function, the log appears to come from the `$inspect` callsite
+	// rather than the `inspect.js` file containing the utility
+	const id = b.id('$$args');
+	const fn = b.arrow([b.rest(id)], b.call(inspector, b.spread(id)));
+
+	return b.call('$.inspect', b.thunk(b.array(args)), fn, rune === '$inspect' && b.true);
+}

packages/svelte/src/compiler/phases/3-transform/server/visitors/CallExpression.js

@@ -1,9 +1,9 @@
-/** @import { CallExpression, Expression } from 'estree' */
+/** @import { CallExpression, Expression, MemberExpression } from 'estree' */
 /** @import { Context } from '../types.js' */
-import { is_ignored } from '../../../../state.js';
+import { dev, is_ignored } from '../../../../state.js';
 import * as b from '#compiler/builders';
 import { get_rune } from '../../../scope.js';
-import { transform_inspect_rune } from '../../utils.js';
+import { get_inspect_args } from '../../utils.js';
 
 /**
  * @param {CallExpression} node
@@ -51,7 +51,13 @@ export function CallExpression(node, context) {
 	}
 
 	if (rune === '$inspect' || rune === '$inspect().with') {
-		return transform_inspect_rune(node, context);
+		if (!dev) return b.empty;
+
+		const { args, inspector } = get_inspect_args(rune, node, context.visit);
+
+		return rune === '$inspect'
+			? b.call(inspector, b.literal('$inspect('), ...args, b.literal(')'))
+			: b.call(inspector, b.literal('init'), ...args);
 	}
 
 	context.next();

packages/svelte/src/compiler/phases/3-transform/utils.js

@@ -1,7 +1,7 @@
 /** @import { Context } from 'zimmerframe' */
 /** @import { TransformState } from './types.js' */
 /** @import { AST, Binding, Namespace, ValidatedCompileOptions } from '#compiler' */
-/** @import { Node, Expression, CallExpression } from 'estree' */
+/** @import { Node, Expression, CallExpression, MemberExpression } from 'estree' */
 import {
 	regex_ends_with_whitespaces,
 	regex_not_whitespace,
@@ -452,30 +452,19 @@ export function determine_namespace_for_children(node, namespace) {
 }
 
 /**
- * @template {TransformState} T
+ * @param {'$inspect' | '$inspect().with'} rune
  * @param {CallExpression} node
- * @param {Context<any, T>} context
+ * @param {(node: AST.SvelteNode) => AST.SvelteNode} visit
  */
-export function transform_inspect_rune(node, context) {
-	const { state, visit } = context;
-	const as_fn = state.options.generate === 'client';
-
-	if (!dev) return b.empty;
-
-	if (node.callee.type === 'MemberExpression') {
-		const raw_inspect_args = /** @type {CallExpression} */ (node.callee.object).arguments;
-		const inspect_args =
-			/** @type {Array<Expression>} */
-			(raw_inspect_args.map((arg) => visit(arg)));
-		const with_arg = /** @type {Expression} */ (visit(node.arguments[0]));
-
-		return b.call(
-			'$.inspect',
-			as_fn ? b.thunk(b.array(inspect_args)) : b.array(inspect_args),
-			with_arg
-		);
-	} else {
-		const arg = node.arguments.map((arg) => /** @type {Expression} */ (visit(arg)));
-		return b.call('$.inspect', as_fn ? b.thunk(b.array(arg)) : b.array(arg));
-	}
+export function get_inspect_args(rune, node, visit) {
+	const call =
+		rune === '$inspect'
+			? node
+			: /** @type {CallExpression} */ (/** @type {MemberExpression} */ (node.callee).object);
+
+	return {
+		args: call.arguments.map((arg) => /** @type {Expression} */ (visit(arg))),
+		inspector:
+			rune === '$inspect' ? 'console.log' : /** @type {Expression} */ (visit(node.arguments[0]))
+	};
 }

packages/svelte/src/internal/client/dev/inspect.js

@@ -2,13 +2,14 @@ import { UNINITIALIZED } from '../../../constants.js';
 import { snapshot } from '../../shared/clone.js';
 import { inspect_effect, render_effect, validate_effect } from '../reactivity/effects.js';
 import { untrack } from '../runtime.js';
+import { get_stack } from './tracing.js';
 
 /**
  * @param {() => any[]} get_value
- * @param {Function} [inspector]
+ * @param {Function} inspector
+ * @param {boolean} show_stack
  */
-// eslint-disable-next-line no-console
-export function inspect(get_value, inspector = console.log) {
+export function inspect(get_value, inspector, show_stack = false) {
 	validate_effect('$inspect');
 
 	let initial = true;
@@ -28,7 +29,16 @@ export function inspect(get_value, inspector = console.log) {
 
 		var snap = snapshot(value, true, true);
 		untrack(() => {
-			inspector(initial ? 'init' : 'update', ...snap);
+			if (show_stack) {
+				inspector(...snap);
+
+				if (!initial) {
+					// eslint-disable-next-line no-console
+					console.log(get_stack('UpdatedAt'));
+				}
+			} else {
+				inspector(initial ? 'init' : 'update', ...snap);
+			}
 		});
 
 		initial = false;

packages/svelte/src/internal/client/dev/tracing.js

@@ -134,7 +134,16 @@ export function trace(label, fn) {
  * @returns {Error & { stack: string } | null}
  */
 export function get_stack(label) {
+	// @ts-ignore stackTraceLimit doesn't exist everywhere
+	const limit = Error.stackTraceLimit;
+
+	// @ts-ignore
+	Error.stackTraceLimit = Infinity;
 	let error = Error();
+
+	// @ts-ignore
+	Error.stackTraceLimit = limit;
+
 	const stack = error.stack;
 
 	if (!stack) return null;
@@ -151,7 +160,7 @@ export function get_stack(label) {
 		if (line.includes('validate_each_keys')) {
 			return null;
 		}
-		if (line.includes('svelte/src/internal')) {
+		if (line.includes('svelte/src/internal') || line.includes('svelte\\src\\internal')) {
 			continue;
 		}
 		new_lines.push(line);

packages/svelte/src/internal/server/index.js

@@ -418,15 +418,6 @@ export function ensure_array_like(array_like_or_iterator) {
 	return [];
 }
 
-/**
- * @param {any[]} args
- * @param {Function} [inspect]
- */
-// eslint-disable-next-line no-console
-export function inspect(args, inspect = console.log) {
-	inspect('init', ...args);
-}
-
 /**
  * @template V
  * @param {() => V} get_value

packages/svelte/tests/helpers.js

@@ -197,6 +197,26 @@ export const fragments = /** @type {'html' | 'tree'} */ (process.env.FRAGMENTS)
 
 export const async_mode = process.env.SVELTE_NO_ASYNC !== 'true';
 
+/**
+ * @param {any[]} logs
+ */
+export function normalise_inspect_logs(logs) {
+	return logs.map((log) => {
+		if (log instanceof Error) {
+			const last_line = log.stack
+				?.trim()
+				.split('\n')
+				.filter((line) => !line.includes('at Module.get_stack'))[1];
+
+			const match = last_line && /(at .+) /.exec(last_line);
+
+			return match && match[1];
+		}
+
+		return log;
+	});
+}
+
 /**
  * @param {any[]} logs
  */

packages/svelte/tests/runtime-runes/samples/class-private-fields-reassigned-this/_config.js

@@ -5,6 +5,6 @@ export default test({
 		dev: true
 	},
 	async test({ assert, logs }) {
-		assert.deepEqual(logs, ['init', 1, 'init', 1]);
+		assert.deepEqual(logs, [1, 1]);
 	}
 });

packages/svelte/tests/runtime-runes/samples/inspect-deep-array/_config.js

@@ -1,5 +1,6 @@
 import { flushSync } from 'svelte';
 import { test } from '../../test';
+import { normalise_inspect_logs } from '../../../helpers.js';
 
 export default test({
 	compileOptions: {
@@ -13,6 +14,6 @@ export default test({
 			button?.click();
 		});
 
-		assert.deepEqual(logs, ['init', [1, 2, 3, 7], 'update', [2, 3, 7]]);
+		assert.deepEqual(normalise_inspect_logs(logs), [[1, 2, 3, 7], [2, 3, 7], 'at Object.doSplice']);
 	}
 });

packages/svelte/tests/runtime-runes/samples/inspect-deep/_config.js

@@ -1,3 +1,4 @@
+import { normalise_inspect_logs } from '../../../helpers.js';
 import { test } from '../../test';
 
 export default test({
@@ -6,6 +7,6 @@ export default test({
 	},
 
 	async test({ assert, logs }) {
-		assert.deepEqual(logs, ['init', undefined, 'update', [{}]]);
+		assert.deepEqual(normalise_inspect_logs(logs), [undefined, [{}], 'at $effect']);
 	}
 });

packages/svelte/tests/runtime-runes/samples/inspect-derived-2/_config.js

@@ -1,5 +1,6 @@
 import { flushSync } from 'svelte';
 import { test } from '../../test';
+import { normalise_inspect_logs } from '../../../helpers.js';
 
 export default test({
 	compileOptions: {
@@ -14,8 +15,7 @@ export default test({
 		});
 
 		assert.htmlEqual(target.innerHTML, `<button>update</button>\n1`);
-		assert.deepEqual(logs, [
-			'init',
+		assert.deepEqual(normalise_inspect_logs(logs), [
 			{
 				data: {
 					derived: 0,
@@ -23,14 +23,14 @@ export default test({
 				},
 				derived: []
 			},
-			'update',
 			{
 				data: {
 					derived: 0,
 					list: [1]
 				},
 				derived: [1]
-			}
+			},
+			'at HTMLButtonElement.Main.button.__click'
 		]);
 	}
 });

packages/svelte/tests/runtime-runes/samples/inspect-derived-3/_config.js

@@ -1,5 +1,6 @@
 import { flushSync } from 'svelte';
 import { test } from '../../test';
+import { normalise_inspect_logs } from '../../../helpers.js';
 
 export default test({
 	compileOptions: {
@@ -13,22 +14,19 @@ export default test({
 			button?.click();
 		});
 
-		assert.deepEqual(logs, [
-			'init',
+		assert.deepEqual(normalise_inspect_logs(logs), [
 			'0',
 			true,
-			'init',
 			'1',
 			false,
-			'init',
 			'2',
 			false,
-			'update',
 			'0',
 			false,
-			'update',
+			'at $effect',
 			'1',
-			true
+			true,
+			'at $effect'
 		]);
 	}
 });

packages/svelte/tests/runtime-runes/samples/inspect-map-set/_config.js

@@ -1,5 +1,6 @@
 import { flushSync } from 'svelte';
 import { test } from '../../test';
+import { normalise_inspect_logs } from '../../../helpers.js';
 
 export default test({
 	compileOptions: {
@@ -12,15 +13,13 @@ export default test({
 		btn2.click();
 		flushSync();
 
-		assert.deepEqual(logs, [
-			'init',
+		assert.deepEqual(normalise_inspect_logs(logs), [
 			new Map(),
-			'init',
 			new Set(),
-			'update',
 			new Map([['a', 'a']]),
-			'update',
-			new Set(['a'])
+			'at SvelteMap.set',
+			new Set(['a']),
+			'at SvelteSet.add'
 		]);
 	}
 });

packages/svelte/tests/runtime-runes/samples/inspect-multiple/_config.js

@@ -1,3 +1,4 @@
+import { normalise_inspect_logs } from '../../../helpers.js';
 import { test } from '../../test';
 
 export default test({
@@ -11,6 +12,15 @@ export default test({
 		b2.click();
 		await Promise.resolve();
 
-		assert.deepEqual(logs, ['init', 0, 0, 'update', 1, 0, 'update', 1, 1]);
+		assert.deepEqual(normalise_inspect_logs(logs), [
+			0,
+			0,
+			1,
+			0,
+			'at HTMLButtonElement.<anonymous>',
+			1,
+			1,
+			'at HTMLButtonElement.<anonymous>'
+		]);
 	}
 });

packages/svelte/tests/runtime-runes/samples/inspect-nested-effect/_config.js

@@ -1,3 +1,4 @@
+import { normalise_inspect_logs } from '../../../helpers.js';
 import { test } from '../../test';
 
 export default test({
@@ -6,6 +7,6 @@ export default test({
 	},
 
 	async test({ assert, logs }) {
-		assert.deepEqual(logs, ['init', 0, 'update', 1]);
+		assert.deepEqual(normalise_inspect_logs(logs), [0, 1, 'at $effect']);
 	}
 });

packages/svelte/tests/runtime-runes/samples/inspect-nested-state/_config.js

@@ -1,3 +1,4 @@
+import { normalise_inspect_logs } from '../../../helpers.js';
 import { test } from '../../test';
 
 export default test({
@@ -10,13 +11,12 @@ export default test({
 		b1.click();
 		await Promise.resolve();
 
-		assert.deepEqual(logs, [
-			'init',
+		assert.deepEqual(normalise_inspect_logs(logs), [
 			{ x: { count: 0 } },
 			[{ count: 0 }],
-			'update',
 			{ x: { count: 1 } },
-			[{ count: 1 }]
+			[{ count: 1 }],
+			'at HTMLButtonElement.<anonymous>'
 		]);
 	}
 });

packages/svelte/tests/runtime-runes/samples/inspect-new-property/_config.js

@@ -1,3 +1,4 @@
+import { normalise_inspect_logs } from '../../../helpers.js';
 import { test } from '../../test';
 
 export default test({
@@ -10,6 +11,13 @@ export default test({
 		btn.click();
 		await Promise.resolve();
 
-		assert.deepEqual(logs, ['init', {}, 'init', [], 'update', { x: 'hello' }, 'update', ['hello']]);
+		assert.deepEqual(normalise_inspect_logs(logs), [
+			{},
+			[],
+			{ x: 'hello' },
+			'at HTMLButtonElement.on_click',
+			['hello'],
+			'at HTMLButtonElement.on_click'
+		]);
 	}
 });

packages/svelte/tests/runtime-runes/samples/inspect-recursive-2/_config.js

@@ -18,6 +18,6 @@ export default test({
 		};
 		b.a.b = b;
 
-		assert.deepEqual(logs, ['init', a, 'init', b]);
+		assert.deepEqual(logs, [a, b]);
 	}
 });

packages/svelte/tests/runtime-runes/samples/inspect-recursive/_config.js

@@ -1,3 +1,4 @@
+import { normalise_inspect_logs } from '../../../helpers.js';
 import { test } from '../../test';
 
 export default test({
@@ -11,6 +12,12 @@ export default test({
 		btn.click();
 		await Promise.resolve();
 
-		assert.deepEqual(logs, ['init', [], 'update', [{}], 'update', [{}, {}]]);
+		assert.deepEqual(normalise_inspect_logs(logs), [
+			[],
+			[{}],
+			'at HTMLButtonElement.on_click',
+			[{}, {}],
+			'at HTMLButtonElement.on_click'
+		]);
 	}
 });

packages/svelte/tests/runtime-runes/samples/inspect/_config.js

@@ -1,3 +1,4 @@
+import { normalise_inspect_logs } from '../../../helpers.js';
 import { test } from '../../test';
 
 export default test({
@@ -11,6 +12,6 @@ export default test({
 		b2.click();
 		await Promise.resolve();
 
-		assert.deepEqual(logs, ['init', 0, 'update', 1]);
+		assert.deepEqual(normalise_inspect_logs(logs), [0, 1, 'at HTMLButtonElement.<anonymous>']);
 	}
 });