Errors with multiline strings are printed incorrectly

[jkrumbiegel]

Bug description

I noticed that error messages I throw from the julia engine code sometimes contain repeated sections, this seems to happen when the error message is a multiline string. For some reason lines 2:end are spliced into the stack trace. It looks like this, notice the repeated lines after Stack trace::

ERROR: Julia server returned error after receiving "close" command:

Failed to close notebook: /Users/krumbiegel/.julia/dev/QuartoNotebookRunner/scratch/test.qmd

The underlying Julia error was:

Tried to close file "/Users/krumbiegel/.julia/dev/QuartoNotebookRunner/scratch/test.qmd" but the corresponding worker is busy.

Stack trace:

Failed to close notebook: /Users/krumbiegel/.julia/dev/QuartoNotebookRunner/scratch/test.qmd

The underlying Julia error was:

Tried to close file "/Users/krumbiegel/.julia/dev/QuartoNotebookRunner/scratch/test.qmd" but the corresponding worker is busy.
    at writeJuliaCommand (file:///Users/krumbiegel/dev/quarto-cli/src/execute/julia.ts:791:13)
    at eventLoopTick (ext:core/01_core.js:175:7)
    at async connectAndWriteJuliaCommandToRunningServer (file:///Users/krumbiegel/dev/quarto-cli/src/execute/julia.ts:958:20)
    at async closeWorker (file:///Users/krumbiegel/dev/quarto-cli/src/execute/julia.ts:975:3)
    at async Command.actionHandler (file:///Users/krumbiegel/dev/quarto-cli/src/execute/julia.ts:876:7)
    at async Command.execute (https://deno.land/x/cliffy@v1.0.0-rc.3/command/command.ts:1948:7)
    at async Command.parseCommand (https://deno.land/x/cliffy@v1.0.0-rc.3/command/command.ts:1780:14)
    at async quarto (file:///Users/krumbiegel/dev/quarto-cli/src/quarto.ts:191:5)
    at async file:///Users/krumbiegel/dev/quarto-cli/src/quarto.ts:220:5
    at async file:///Users/krumbiegel/dev/quarto-cli/src/core/main.ts:41:14

I guess it's this code that does the splicing https://github.com/PumasAI/quarto-cli/blob/d109025e0bd34c0dfeb23780669c361e7c561016/src/core/log.ts#L347-L349 but I'm not sure why part of the message is considered the stack in the first place.

Steps to reproduce

No response

Actual behavior

No response

Expected behavior

No response

Your environment

No response

Quarto check output

% quarto check
Check file:///Users/krumbiegel/dev/quarto-cli/src/quarto.ts
Quarto 99.9.9
[✓] Checking environment information...
      Quarto cache location: /Users/krumbiegel/Library/Caches/quarto
[✓] Checking versions of quarto binary dependencies...
      Pandoc version 3.4.0: OK
      Dart Sass version 1.70.0: OK
      Deno version 1.46.3: OK
      Typst version 0.11.0: OK
[✓] Checking versions of quarto dependencies......OK
[✓] Checking Quarto installation......OK
      Version: 99.9.9
      commit: b41d51371a167411c8a6938f86d850e1e66e3108
      Path: /Users/krumbiegel/dev/quarto-cli/package/dist/bin

[✓] Checking tools....................OK
      TinyTeX: v2025.01
      Chromium: (not installed)

[✓] Checking LaTeX....................OK
      Using: TinyTex
      Path: /Users/krumbiegel/Library/TinyTeX/bin/universal-darwin
      Version: 2024

[✓] Checking Chrome Headless....................OK
      Using: Chrome found on system
      Path: /Applications/Google Chrome.app/Contents/MacOS/Google Chrome
      Source: MacOS known location

[✓] Checking basic markdown render....OK

[✓] Checking Python 3 installation....OK
      Version: 3.12.2 (Conda)
      Path: /Users/krumbiegel/miniconda3/bin/python
      Jupyter: 5.5.0
      Kernels: julia-1.11, julia-1.10, julia-1.8, julia-1.7, python3

[✓] Checking Jupyter engine render....OK

[✓] Checking R installation...........OK
      Version: 4.3.2
      Path: /Library/Frameworks/R.framework/Resources
      LibPaths:
        - /Users/krumbiegel/dev/quarto-cli/tests/renv/library/R-4.3/aarch64-apple-darwin20
        - /Users/krumbiegel/Library/Caches/org.R-project.R/R/renv/sandbox/R-4.3/aarch64-apple-darwin20/ac5c2659
      knitr: 1.49.8
      rmarkdown: 2.29.1

[✓] Checking Knitr engine render......OK

[mcanouil]

@jkrumbiegel Could you add an example of code producing this?

[jkrumbiegel]

You can't trigger it from the outside unless there's a multiline error message in quarto. I only recently added one in #11803 which is when I noticed this. I don't know if quarto has another one. If you wanted to reproduce it, you could edit any location in quarto you find suitable to throw with a multiline error message, and then trigger that condition.

[jkrumbiegel]

Ok I actually made a reproducible example for you for simplicity. I just searched for errors thrown with input interpolated into the error string and voila:

% quarto convert "line 1
line 2
line 3
line 4"
ERROR: File not found: 'line 1
line 2
line 3
line 4'

Stack trace:
line 2
line 3
line 4'
    at Command.actionHandler (file:///Users/krumbiegel/dev/quarto-cli/src/command/convert/cmd.ts:54:13)
    at async Command.execute (https://deno.land/x/cliffy@v1.0.0-rc.3/command/command.ts:1948:7)
    at async Command.parseCommand (https://deno.land/x/cliffy@v1.0.0-rc.3/command/command.ts:1780:14)
    at async quarto (file:///Users/krumbiegel/dev/quarto-cli/src/quarto.ts:191:5)
    at async file:///Users/krumbiegel/dev/quarto-cli/src/quarto.ts:220:5
    at async file:///Users/krumbiegel/dev/quarto-cli/src/core/main.ts:41:14
    at async mainRunner (file:///Users/krumbiegel/dev/quarto-cli/src/core/main.ts:43:5)
    at async file:///Users/krumbiegel/dev/quarto-cli/src/quarto.ts:210:3

[cderv]

Thank you for finding that. This will definitely help

[cderv]

It happens here

quarto-cli/src/core/log.ts

Lines 343 to 350 in 2ae62ed

	if (err.stack && (isDebug || err.printStack)) {
	if (!message) {
	message = err.stack;
	} else {
	message = message + "\n\nStack trace:\n" +
	err.stack.split("\n").slice(1).join("\n");
	}
	}

We split on newlines, and only remove the first line. So We don't handle multiline error.

This leads to the duplicate.

This is err.stack (just got a different error on windows powershell)

err.stack
"Error: La syntaxe du nom de fichier, de répertoire ou de volume est incorrecte. (os error 123): stat 'line1
line2
line3'
    at Object.statSync (ext:deno_fs/30_fs.js:425:3)
    at existsSync (https://jsr.io/@std/fs/0.224.0/exists.ts:242:23)
    at Command.actionHandler (file:///C:/Users/chris/Documents/DEV_R/quarto-cli/src/command/convert/cmd.ts:53:10)
    at async Command.execute (https://deno.land/x/cliffy@v1.0.0-rc.3/command/command.ts:1948:7)
    at async Command.parseCommand (https://deno.land/x/cliffy@v1.0.0-rc.3/command/command.ts:1780:14)
    at async quarto (file:///C:/Users/chris/Documents/DEV_R/quarto-cli/src/quarto.ts:190:5)
    at async file:///C:/Users/chris/Documents/DEV_R/quarto-cli/src/quarto.ts:219:5
    at async file:///C:/Users/chris/DOCUME~1/DEV_R/QUARTO~1/src/core/main.ts:41:14
    at async mainRunner (file:///C:/Users/chris/DOCUME~1/DEV_R/QUARTO~1/src/core/main.ts:43:5)
    at async file:///C:/Users/chris/Documents/DEV_R/quarto-cli/src/quarto.ts:209:3"

Could we look maybe for the first line with at in the stack ??