From 61d7fa00022aa8e368b83b4e58b0694e90024ecc Mon Sep 17 00:00:00 2001 From: Rich Harris Date: Sat, 17 Apr 2021 10:40:04 -0400 Subject: [PATCH] Better error logging (#1062) * tidy up render options, show parent of erroring page in prerender * separate out render options from render state * small tidy up * fix * always log caught errors when rendering * changeset * fix test, apply stack fix to non-thrown errors returned from load * squelch console errors, now that we generate a bunch more of them --- .changeset/lazy-actors-add.md | 5 + packages/kit/src/core/adapt/prerender.js | 45 +++--- packages/kit/src/core/build/index.js | 76 +++++----- packages/kit/src/core/dev/index.js | 138 +++++++++--------- packages/kit/src/core/start/index.js | 37 +++-- packages/kit/src/runtime/server/index.js | 13 +- packages/kit/src/runtime/server/page/index.js | 11 +- .../kit/src/runtime/server/page/load_node.js | 16 +- .../kit/src/runtime/server/page/render.js | 19 +-- .../kit/src/runtime/server/page/respond.js | 18 ++- .../runtime/server/page/respond_with_error.js | 9 +- .../basics/src/routes/errors/__tests__.js | 19 +-- packages/kit/test/test.js | 39 +++++ packages/kit/test/types.d.ts | 1 + packages/kit/types/internal.d.ts | 64 +++++--- 15 files changed, 294 insertions(+), 216 deletions(-) create mode 100644 .changeset/lazy-actors-add.md diff --git a/.changeset/lazy-actors-add.md b/.changeset/lazy-actors-add.md new file mode 100644 index 000000000000..6e5eda4faa77 --- /dev/null +++ b/.changeset/lazy-actors-add.md @@ -0,0 +1,5 @@ +--- +'@sveltejs/kit': patch +--- + +Better error logging diff --git a/packages/kit/src/core/adapt/prerender.js b/packages/kit/src/core/adapt/prerender.js index 6c7129426313..daba3491e6c9 100644 --- a/packages/kit/src/core/adapt/prerender.js +++ b/packages/kit/src/core/adapt/prerender.js @@ -66,16 +66,17 @@ export async function prerender({ cwd, out, log, config, build_data, force }) { app.init({ paths: config.kit.paths, - prerendering: true + prerendering: true, + read: (file) => readFileSync(join(config.kit.files.assets, file)) }); - /** @type {(status: number, path: string) => void} */ + /** @type {(status: number, path: string, parent: string, verb: string) => void} */ const error = config.kit.prerender.force - ? (status, path) => { - log.error(`${status} ${path}`); + ? (status, path, parent, verb) => { + log.error(`${status} ${path} (${verb} from ${parent})`); } - : (status, path) => { - throw new Error(`${status} ${path}`); + : (status, path, parent, verb) => { + throw new Error(`${status} ${path} (${verb} from ${parent})`); }; const files = new Set([...build_data.static, ...build_data.client]); @@ -86,8 +87,11 @@ export async function prerender({ cwd, out, log, config, build_data, force }) { } }); - /** @param {string} path */ - async function visit(path) { + /** + * @param {string} path + * @param {string} parent + */ + async function visit(path, parent) { if (seen.has(path)) return; seen.add(path); @@ -104,10 +108,11 @@ export async function prerender({ cwd, out, log, config, build_data, force }) { query: new URLSearchParams() }, { - local: true, - dependencies, - only_render_prerenderable_pages: !force, - get_static_file: (file) => readFileSync(join(config.kit.files.assets, file)) + prerender: { + force, + dependencies, + error: null + } } ); @@ -138,15 +143,15 @@ export async function prerender({ cwd, out, log, config, build_data, force }) { log.info(`${rendered.status} ${path}`); writeFileSync(file, rendered.body); // TODO minify where possible? } else if (response_type !== OK) { - error(rendered.status, path); + error(rendered.status, path, parent, 'linked'); } - dependencies.forEach((result, path) => { + dependencies.forEach((result, dependency_path) => { const response_type = Math.floor(result.status / 100); const is_html = result.headers['content-type'] === 'text/html'; - const parts = path.split('/'); + const parts = dependency_path.split('/'); if (is_html && parts[parts.length - 1] !== 'index.html') { parts.push('index.html'); } @@ -157,9 +162,9 @@ export async function prerender({ cwd, out, log, config, build_data, force }) { writeFileSync(file, result.body); if (response_type === OK) { - log.info(`${result.status} ${path}`); + log.info(`${result.status} ${dependency_path}`); } else { - error(result.status, path); + error(result.status, dependency_path, path, 'fetched'); } }); @@ -200,7 +205,7 @@ export async function prerender({ cwd, out, log, config, build_data, force }) { // TODO warn that query strings have no effect on statically-exported pages } - await visit(parsed.pathname.replace(config.kit.paths.base, '')); + await visit(parsed.pathname.replace(config.kit.paths.base, ''), path); } } } @@ -209,10 +214,10 @@ export async function prerender({ cwd, out, log, config, build_data, force }) { for (const entry of config.kit.prerender.pages) { if (entry === '*') { for (const entry of build_data.entries) { - await visit(entry); + await visit(entry, null); } } else { - await visit(entry); + await visit(entry, null); } } } diff --git a/packages/kit/src/core/build/index.js b/packages/kit/src/core/build/index.js index 3b2a6da5630b..7ddb5aabb937 100644 --- a/packages/kit/src/core/build/index.js +++ b/packages/kit/src/core/build/index.js @@ -279,12 +279,42 @@ async function build_server( .replace('%svelte.head%', '" + head + "') .replace('%svelte.body%', '" + body + "')}; - set_paths(${s(config.kit.paths)}); + let options = null; // allow paths to be overridden in svelte-kit start - export function init({ paths, prerendering }) { - set_paths(paths); - set_prerendering(prerendering); + // and in prerendering + export function init(settings) { + set_paths(settings.paths); + set_prerendering(settings.prerendering || false); + + options = { + amp: ${config.kit.amp}, + dev: false, + entry: { + file: ${s(prefix + client_manifest[client_entry_file].file)}, + css: ${s(Array.from(entry_css).map(dep => prefix + dep))}, + js: ${s(Array.from(entry_js).map(dep => prefix + dep))} + }, + fetched: undefined, + get_component_path: id => ${s(`${config.kit.paths.assets}/${config.kit.appDir}/`)} + entry_lookup[id], + get_stack: error => String(error), // for security + handle_error: error => { + console.error(error.stack); + error.stack = options.get_stack(error); + }, + hooks: get_hooks(user_hooks), + hydrate: ${s(config.kit.hydrate)}, + initiator: undefined, + load_component, + manifest, + paths: settings.paths, + read: settings.read, + root, + router: ${s(config.kit.router)}, + ssr: ${s(config.kit.ssr)}, + target: ${s(config.kit.target)}, + template + }; } const d = decodeURIComponent; @@ -331,8 +361,6 @@ async function build_server( handle: hooks.handle || (({ request, render }) => render(request)) }); - const hooks = get_hooks(user_hooks); - const module_lookup = { ${manifest.components.map(file => `${s(file)}: () => import(${s(app_relative(file))})`)} }; @@ -349,39 +377,13 @@ async function build_server( }; } + init({ paths: ${s(config.kit.paths)} }); + export function render(request, { - paths = ${s(config.kit.paths)}, - local = false, - dependencies, - only_render_prerenderable_pages = false, - get_static_file + prerender } = {}) { - return ssr({ - ...request, - host: ${config.kit.host ? s(config.kit.host) : `request.headers[${s(config.kit.hostHeader || 'host')}]`} - }, { - paths, - local, - template, - manifest, - load_component, - target: ${s(config.kit.target)}, - entry: ${s(prefix + client_manifest[client_entry_file].file)}, - css: ${s(Array.from(entry_css).map(dep => prefix + dep))}, - js: ${s(Array.from(entry_js).map(dep => prefix + dep))}, - root, - hooks, - dev: false, - amp: ${config.kit.amp}, - dependencies, - only_render_prerenderable_pages, - get_component_path: id => ${s(`${config.kit.paths.assets}/${config.kit.appDir}/`)} + entry_lookup[id], - get_stack: error => error.stack, - get_static_file, - ssr: ${s(config.kit.ssr)}, - router: ${s(config.kit.router)}, - hydrate: ${s(config.kit.hydrate)} - }); + const host = ${config.kit.host ? s(config.kit.host) : `request.headers[${s(config.kit.hostHeader || 'host')}]`}; + return ssr({ ...request, host }, options, { prerender }); } ` .replace(/^\t{3}/gm, '') diff --git a/packages/kit/src/core/dev/index.js b/packages/kit/src/core/dev/index.js index 39e19227a268..6b16cd4ba8fc 100644 --- a/packages/kit/src/core/dev/index.js +++ b/packages/kit/src/core/dev/index.js @@ -5,6 +5,7 @@ import { EventEmitter } from 'events'; import CheapWatch from 'cheap-watch'; import amp_validator from 'amphtml-validator'; import vite from 'vite'; +import colors from 'kleur'; import create_manifest_data from '../../core/create_manifest_data/index.js'; import { create_app } from '../../core/create_app/index.js'; import { rimraf } from '../filesystem/index.js'; @@ -130,9 +131,6 @@ class Watcher extends EventEmitter { if (req.url === '/favicon.ico') return; - // handle dynamic requests - i.e. pages and endpoints - const template = fs.readFileSync(this.config.kit.files.template, 'utf-8'); - const hooks = /** @type {import('types/internal').Hooks} */ (await this.vite .ssrLoadModule(`/${this.config.kit.files.hooks}`) .catch(() => ({}))); @@ -162,9 +160,77 @@ class Watcher extends EventEmitter { body }, { + amp: this.config.kit.amp, + dev: true, + entry: { + file: '/.svelte/dev/runtime/internal/start.js', + css: [], + js: [] + }, + get_stack: (error) => { + this.vite.ssrFixStacktrace(error); + return error.stack; + }, + handle_error: (error) => { + this.vite.ssrFixStacktrace(error); + console.error(colors.bold().red(error.message)); + console.error(colors.gray(error.stack)); + }, + hooks: { + getContext: hooks.getContext || (() => ({})), + getSession: hooks.getSession || (() => ({})), + handle: hooks.handle || (({ request, render }) => render(request)) + }, + hydrate: this.config.kit.hydrate, paths: this.config.kit.paths, + load_component: async (id) => { + const url = path.resolve(this.cwd, id); + + const module = /** @type {SSRComponent} */ (await this.vite.ssrLoadModule(url)); + const node = await this.vite.moduleGraph.getModuleByUrl(url); + + const deps = new Set(); + find_deps(node, deps); + + const styles = new Set(); + + for (const dep of deps) { + const parsed = parse(dep.url); + const query = new URLSearchParams(parsed.query); + + // TODO what about .scss files, etc? + if ( + dep.file.endsWith('.css') || + (query.has('svelte') && query.get('type') === 'style') + ) { + try { + const mod = await this.vite.ssrLoadModule(dep.url); + styles.add(mod.default); + } catch { + // this can happen with dynamically imported modules, I think + // because the Vite module graph doesn't distinguish between + // static and dynamic imports? TODO investigate, submit fix + } + } + } + + return { + module, + entry: `/${id}?import`, + css: [], + js: [], + styles: Array.from(styles) + }; + }, + manifest: this.manifest, + read: (file) => fs.readFileSync(path.join(this.config.kit.files.assets, file)), + root, + router: this.config.kit.router, + ssr: this.config.kit.ssr, + target: this.config.kit.target, template: ({ head, body }) => { - let rendered = template + let rendered = fs + .readFileSync(this.config.kit.files.template, 'utf8') .replace('%svelte.head%', () => head) .replace('%svelte.body%', () => body); @@ -213,69 +279,7 @@ class Watcher extends EventEmitter { } return rendered; - }, - manifest: this.manifest, - load_component: async (id) => { - const url = path.resolve(this.cwd, id); - - const module = /** @type {SSRComponent} */ (await this.vite.ssrLoadModule(url)); - const node = await this.vite.moduleGraph.getModuleByUrl(url); - - const deps = new Set(); - find_deps(node, deps); - - const styles = new Set(); - - for (const dep of deps) { - const parsed = parse(dep.url); - const query = new URLSearchParams(parsed.query); - - // TODO what about .scss files, etc? - if ( - dep.file.endsWith('.css') || - (query.has('svelte') && query.get('type') === 'style') - ) { - try { - const mod = await this.vite.ssrLoadModule(dep.url); - styles.add(mod.default); - } catch { - // this can happen with dynamically imported modules, I think - // because the Vite module graph doesn't distinguish between - // static and dynamic imports? TODO investigate, submit fix - } - } - } - - return { - module, - entry: `/${id}?import`, - css: [], - js: [], - styles: Array.from(styles) - }; - }, - target: this.config.kit.target, - entry: '/.svelte/dev/runtime/internal/start.js', - css: [], - js: [], - dev: true, - amp: this.config.kit.amp, - root, - hooks: { - getContext: hooks.getContext || (() => ({})), - getSession: hooks.getSession || (() => ({})), - handle: hooks.handle || (({ request, render }) => render(request)) - }, - only_render_prerenderable_pages: false, - get_stack: (error) => { - this.vite.ssrFixStacktrace(error); - return error.stack; - }, - get_static_file: (file) => - fs.readFileSync(path.join(this.config.kit.files.assets, file)), - ssr: this.config.kit.ssr, - router: this.config.kit.router, - hydrate: this.config.kit.hydrate + } } ); diff --git a/packages/kit/src/core/start/index.js b/packages/kit/src/core/start/index.js index baffe5557b6a..01df0f66f704 100644 --- a/packages/kit/src/core/start/index.js +++ b/packages/kit/src/core/start/index.js @@ -37,30 +37,29 @@ export async function start({ port, host, config, https: use_https = false, cwd immutable: true }); + app.init({ + paths: { + base: '', + assets: '/.' + }, + prerendering: false, + read: (file) => fs.readFileSync(join(config.kit.files.assets, file)) + }); + return get_server(port, host, use_https, (req, res) => { const parsed = parse(req.url || ''); assets_handler(req, res, () => { static_handler(req, res, async () => { - const rendered = await app.render( - { - host: /** @type {string} */ (config.kit.host || - req.headers[config.kit.hostHeader || 'host']), - method: req.method, - headers: /** @type {import('types/helper').Headers} */ (req.headers), - path: parsed.pathname, - body: await get_body(req), - query: new URLSearchParams(parsed.query || '') - }, - { - paths: { - base: '', - assets: '/.' - }, - get_stack: (error) => error.stack, // TODO should this return a sourcemapped stacktrace? - get_static_file: (file) => fs.readFileSync(join(config.kit.files.assets, file)) - } - ); + const rendered = await app.render({ + host: /** @type {string} */ (config.kit.host || + req.headers[config.kit.hostHeader || 'host']), + method: req.method, + headers: /** @type {import('types/helper').Headers} */ (req.headers), + path: parsed.pathname, + body: await get_body(req), + query: new URLSearchParams(parsed.query || '') + }); if (rendered) { res.writeHead(rendered.status, rendered.headers); diff --git a/packages/kit/src/runtime/server/index.js b/packages/kit/src/runtime/server/index.js index 31adcae08541..27c1426a0fb7 100644 --- a/packages/kit/src/runtime/server/index.js +++ b/packages/kit/src/runtime/server/index.js @@ -10,8 +10,9 @@ function md5(body) { /** * @param {import('types/hooks').Incoming} incoming * @param {import('types/internal').SSRRenderOptions} options + * @param {import('types/internal').SSRRenderState} [state] */ -export async function ssr(incoming, options) { +export async function ssr(incoming, options, state = {}) { if (incoming.path.endsWith('/') && incoming.path !== '/') { const q = incoming.query.toString(); @@ -39,7 +40,7 @@ export async function ssr(incoming, options) { const response = route.type === 'endpoint' ? await render_endpoint(request, route) - : await render_page(request, route, options); + : await render_page(request, route, options, state); if (response) { // inject ETags for 200 responses @@ -63,15 +64,11 @@ export async function ssr(incoming, options) { } } - return await render_page(request, null, options); + return await render_page(request, null, options, state); } }); } catch (e) { - if (e && e.stack) { - e.stack = await options.get_stack(e); - } - - console.error((e && e.stack) || e); + options.handle_error(e); return { status: 500, diff --git a/packages/kit/src/runtime/server/page/index.js b/packages/kit/src/runtime/server/page/index.js index 67aed523edf5..850e5dc17cff 100644 --- a/packages/kit/src/runtime/server/page/index.js +++ b/packages/kit/src/runtime/server/page/index.js @@ -5,10 +5,11 @@ import { respond_with_error } from './respond_with_error.js'; * @param {import('types/endpoint').ServerRequest} request * @param {import('types/internal').SSRPage} route * @param {import('types/internal').SSRRenderOptions} options + * @param {import('types/internal').SSRRenderState} state * @returns {Promise} */ -export default async function render_page(request, route, options) { - if (options.initiator === route) { +export default async function render_page(request, route, options, state) { + if (state.initiator === route) { // infinite request cycle detected return { status: 404, @@ -23,6 +24,7 @@ export default async function render_page(request, route, options) { const response = await respond({ request, options, + state, $session, route }); @@ -31,7 +33,7 @@ export default async function render_page(request, route, options) { return response; } - if (options.fetched) { + if (state.fetched) { // we came here because of a bad request in a `load` function. // rather than render the error page — which could lead to an // infinite loop, if the `load` belonged to the root layout, @@ -39,13 +41,14 @@ export default async function render_page(request, route, options) { return { status: 500, headers: {}, - body: `Bad request in load function: failed to fetch ${options.fetched}` + body: `Bad request in load function: failed to fetch ${state.fetched}` }; } } else { return await respond_with_error({ request, options, + state, $session, status: 404, error: new Error(`Not found: ${request.path}`) diff --git a/packages/kit/src/runtime/server/page/load_node.js b/packages/kit/src/runtime/server/page/load_node.js index 19afc0f8d2a6..6fe2286502eb 100644 --- a/packages/kit/src/runtime/server/page/load_node.js +++ b/packages/kit/src/runtime/server/page/load_node.js @@ -10,6 +10,7 @@ const s = JSON.stringify; * @param {{ * request: import('types/endpoint').ServerRequest; * options: import('types/internal').SSRRenderOptions; + * state: import('types/internal').SSRRenderState; * route: import('types/internal').SSRPage; * page: import('types/page').Page; * node: import('types/internal').SSRNode; @@ -25,6 +26,7 @@ const s = JSON.stringify; export async function load_node({ request, options, + state, route, page, node, @@ -83,7 +85,7 @@ export async function load_node({ }; } - if (options.local && url.startsWith(options.paths.assets)) { + if (options.read && url.startsWith(options.paths.assets)) { // when running `start`, or prerendering, `assets` should be // config.kit.paths.assets, but we should still be able to fetch // assets directly from `static` @@ -114,9 +116,9 @@ export async function load_node({ if (asset) { // we don't have a running server while prerendering because jumping between - // processes would be inefficient so we have get_static_file instead - if (options.get_static_file) { - response = new Response(options.get_static_file(asset.file), { + // processes would be inefficient so we have options.read instead + if (options.read) { + response = new Response(options.read(asset.file), { headers: { 'content-type': asset.type } @@ -153,16 +155,16 @@ export async function load_node({ body: /** @type {any} */ (opts.body), query: new URLSearchParams(parsed.query || '') }, + options, { - ...options, fetched: url, initiator: route } ); if (rendered) { - if (options.dependencies) { - options.dependencies.set(resolved, rendered); + if (state.prerender) { + state.prerender.dependencies.set(resolved, rendered); } response = new Response(rendered.body, { diff --git a/packages/kit/src/runtime/server/page/render.js b/packages/kit/src/runtime/server/page/render.js index b43cddf203c7..df575ddaf0e9 100644 --- a/packages/kit/src/runtime/server/page/render.js +++ b/packages/kit/src/runtime/server/page/render.js @@ -26,8 +26,8 @@ export async function render_response({ branch, page }) { - const css = new Set(options.css); - const js = new Set(options.js); + const css = new Set(options.entry.css); + const js = new Set(options.entry.js); const styles = new Set(); /** @type {Array<{ url: string, json: string }>} */ @@ -38,6 +38,10 @@ export async function render_response({ let is_private = false; let maxage; + if (error) { + error.stack = options.get_stack(error); + } + if (branch) { branch.forEach(({ node, loaded, fetched, uses_credentials }) => { if (node.css) node.css.forEach((url) => css.add(url)); @@ -52,15 +56,6 @@ export async function render_response({ maxage = loaded.maxage; }); - if (error) { - if (options.dev) { - error.stack = await options.get_stack(error); - } else { - // remove error.stack in production - error.stack = String(error); - } - } - const session = writable($session); /** @type {Record} */ @@ -116,7 +111,7 @@ export async function render_response({ } else if (page_config.router || page_config.hydrate) { // prettier-ignore init = `