Enter-tainer/typst-preview

No response to updates after prolonged wait time

tingerrr opened this issue · 5 comments

tingerrr commented

Describe the bug
After a prolonged period where I did not edit any files, subsequent edits do not update the logs or preview at all.

To Reproduce

  1. run typst-preview file.typ
  2. wait for some time (5 minutes should be enough)
  3. edit file and observe no update in logs or preview

Expected behavior
Edits continue to update the preview after I come back.

Package/Software version:

typst-preview 
Build Timestamp:     2024-03-25T13:38:09.901507948Z
Build Git Describe:  v0.11.3-dirty
Commit SHA:          c623b767d4b9f4968692fe5c9173d2c6be6f47d6
Commit Date:         None
Commit Branch:       None
Cargo Target Triple: x86_64-unknown-linux-gnu

typst-preview extension version: none (using cli)

Logs:
Simplified for brevity

...

[2024-05-06T09:20:47Z INFO  typst_ts_compiler::service::diag::console] /src/de/thesis.typ: compiling ...

[2024-05-06T09:20:47Z INFO  typst_ts_compiler::service::diag::console] /src/de/thesis.typ: Compilation succeeded in 2.178611ms

[2024-05-06T09:20:47Z DEBUG typst_preview::actor::render] OutlineRenderActor: received message: RenderIncremental
[2024-05-06T09:20:47Z DEBUG typst_preview::actor::render] OutlineRenderActor: received message: RenderIncremental
[2024-05-06T09:20:47Z DEBUG typst_preview::actor::render] OutlineRenderActor: sending outline
[2024-05-06T09:20:47Z DEBUG typst_preview::actor::render] OutlineRenderActor: waiting for message
[2024-05-06T09:20:47Z DEBUG typst_preview::actor::render] OutlineRenderActor: sending outline
[2024-05-06T09:20:47Z DEBUG typst_preview::actor::render] OutlineRenderActor: waiting for message
[2024-05-06T09:20:47Z DEBUG typst_preview::actor::render] RenderActor: waiting for message
[2024-05-06T09:20:47Z DEBUG typst_preview::actor::render] RenderActor: has_full_render: false
[2024-05-06T09:20:47Z DEBUG typst_preview::actor::render] RenderActor: waiting for message
[2024-05-06T09:20:47Z DEBUG typst_preview::actor::render] RenderActor: has_full_render: false
[2024-05-06T09:20:47Z DEBUG typst_preview::actor::render] RenderActor: waiting for message
[2024-05-06T09:20:47Z DEBUG typst_preview::actor::render] RenderActor: waiting for message
[2024-05-06T09:20:48Z INFO  typst_preview::actor::webview] WebviewActor: received non-text message from websocket: Close(Some(CloseFrame { code: Away, reason: "" }))
[2024-05-06T09:20:48Z INFO  typst_preview::actor::webview] WebviewActor: exiting

Additional context
OS:
Endeavor OS

kernel-name kernel-release kernel-version machine operating-system
Linux 6.8.9-arch1-1 #1 SMP PREEMPT_DYNAMIC Thu, 02 May 2024 17:49:46 +0000 x86_64 GNU/Linux
tingerrr commented

Another possibly related issue is that, when I force and update by running :w in helix, it'll work just fine, but after just a few seconds of inactivity it will stop responding to any real updates after I force one using :w.

Where using :w will cause the file to be written as it currently it's seen if it hasn't changed.

This is in the end quite annoying, as I need to restart typst-preview frequently.

EDIT:

In fact, it seems even weirder, once I encountered this issue at least once I can reproduce it instantly, even though they are completely separate instances. It seems, that it works for a while after freshly starting my PC or window manager and after a while it just doesn't anymore.

Logs:

[2024-05-06T09:38:03Z INFO  typst_preview] Arguments: CliArguments {
        preview: PreviewArgs {
            data_plane_host: "127.0.0.1:23625",
            control_plane_host: "127.0.0.1:23626",
            enable_partial_rendering: false,
            invert_colors: "never",
        },
        preview_mode: Document,
        static_file_host: "127.0.0.1:23627",
        dont_open_in_browser: false,
        font_paths: [],
        root: None,
        input: "test.typ",
    }
[2024-05-06T09:38:04Z INFO  typst_preview] Previewer: typst actor spawned
[2024-05-06T09:38:04Z DEBUG typst_ts_compiler::service::watch] start watching files...
[2024-05-06T09:38:04Z DEBUG typst_preview::actor::typst] TypstActor: waiting for message
[2024-05-06T09:38:04Z INFO  typst_preview] Data plane server listening on: 127.0.0.1:23625
[2024-05-06T09:38:04Z INFO  typst_preview] Control plane server listening on: 127.0.0.1:23626
[2024-05-06T09:38:04Z DEBUG typst_ts_compiler::service::compile] CompileActor: initialized
[2024-05-06T09:38:04Z DEBUG typst_ts_compiler::service::compile] CompileActor: fs event incoming None
[2024-05-06T09:38:04Z INFO  typst_ts_compiler::service::diag::console] /test.typ: compiling ...

[2024-05-06T09:38:04Z INFO  typst_ts_compiler::service::diag::console] /test.typ: Compilation succeeded in 1.197089ms

[2024-05-06T09:38:04Z DEBUG typst_ts_compiler::service::compile] CompileActor: fs event incoming Some(Update(FileChangeSet { removes: [], inserts: [("/home/tinger/test/test.typ", FileSnapshot { mtime: SystemTime { tv_sec: 1714988271, tv_nsec: 453606816 }, content: FileContent { len: 12 } })] }))
[2024-05-06T09:38:04Z INFO  typst_ts_compiler::service::diag::console] /test.typ: compiling ...

[2024-05-06T09:38:04Z INFO  typst_ts_compiler::service::diag::console] /test.typ: Compilation succeeded in 25.631µs

[2024-05-06T09:38:04Z INFO  typst_preview] Static file server listening on: 127.0.0.1:23627
[2024-05-06T09:38:04Z INFO  typst_preview] Peer address: 127.0.0.1:40146
[2024-05-06T09:38:04Z INFO  typst_preview] New WebSocket connection: 127.0.0.1:40146
[2024-05-06T09:38:04Z DEBUG typst_preview::actor::render] OutlineRenderActor: waiting for message
[2024-05-06T09:38:04Z DEBUG typst_preview::actor::render] RenderActor: waiting for message
[2024-05-06T09:38:04Z DEBUG typst_preview::actor::render] RenderActor: has_full_render: true
[2024-05-06T09:38:04Z DEBUG typst_preview::actor::render] OutlineRenderActor: received message: RenderFullLatest
[2024-05-06T09:38:04Z DEBUG typst_preview::actor::render] OutlineRenderActor: sending outline
[2024-05-06T09:38:04Z DEBUG typst_preview::actor::render] OutlineRenderActor: waiting for message
[2024-05-06T09:38:04Z DEBUG typst_preview::actor::render] RenderActor: waiting for message
[2024-05-06T09:38:04Z INFO  typst_preview] Serve frontend: Document
[2024-05-06T09:38:04Z INFO  typst_preview] Peer address: 127.0.0.1:40150
[2024-05-06T09:38:04Z INFO  typst_preview] New WebSocket connection: 127.0.0.1:40150
[2024-05-06T09:38:04Z DEBUG typst_preview::actor::render] OutlineRenderActor: waiting for message
[2024-05-06T09:38:04Z DEBUG typst_preview::actor::render] RenderActor: waiting for message
[2024-05-06T09:38:04Z DEBUG typst_preview::actor::render] RenderActor: has_full_render: true
[2024-05-06T09:38:04Z DEBUG typst_preview::actor::render] OutlineRenderActor: received message: RenderFullLatest
[2024-05-06T09:38:04Z DEBUG typst_preview::actor::render] OutlineRenderActor: sending outline
[2024-05-06T09:38:04Z DEBUG typst_preview::actor::render] OutlineRenderActor: waiting for message
[2024-05-06T09:38:04Z DEBUG typst_preview::actor::render] RenderActor: has_full_render: true
[2024-05-06T09:38:04Z DEBUG typst_preview::actor::render] OutlineRenderActor: received message: RenderFullLatest
[2024-05-06T09:38:04Z DEBUG typst_preview::actor::render] OutlineRenderActor: sending outline
[2024-05-06T09:38:04Z DEBUG typst_preview::actor::render] OutlineRenderActor: waiting for message
[2024-05-06T09:38:04Z DEBUG typst_preview::actor::render] RenderActor: waiting for message
[2024-05-06T09:38:04Z DEBUG typst_preview::actor::render] RenderActor: waiting for message
^C[2024-05-06T09:38:14Z INFO  typst_preview] Ctrl-C received, exiting
Enter-tainer commented

WebviewActor: received non-text message from websocket: Close(Some(CloseFrame { code: Away, reason: "" }))

This might be the root cause. The browser tab seems close the websocket. Can you provide browser logs? I will also try reproduce this when i leave work

tingerrr commented

This might be the root cause. The browser tab seems close the websocket. Can you provide browser logs? I will also try reproduce this when i leave work

I'm not sure, in the second log I sent you can't see that at all.

The browser logs are structured, so I opened them to the depth I deemed important.

Here too I noticed that regular updates work, then a non-update using :w without changes causes no update in the logs at all, and any subsequent writes don't either.

Bowser Logs

plugin initialized, build info: 
  Object { version: "0.4.2-rc10", features: (4) […], commit_hash: "895133795fb71e6f37771acbebfe65df43862850", profile: "opt_level(3)" }
  commit_hash: "895133795fb71e6f37771acbebfe65df43862850"
  features: Array(4) [ "render_canvas", "render_dom", "render_svg", … ]
  0: "render_canvas"
  1: "render_dom"
  2: "render_svg"
  3: "web"
  length: 4
  <prototype>: Array []
  profile: "opt_level(3)"
  version: "0.4.2-rc10"
  <prototype>: Object { … }
WebSocket connection opened
  WebSocket { url: "ws://127.0.0.1:23625/", readyState: 1, bufferedAmount: 0, onopen: onopen(evt), onerror: onerror(e), onclose: onclose(e), extensions: "", protocol: "", onmessage: onmessage(e), binaryType: "arraybuffer" }
  binaryType: "arraybuffer"
  bufferedAmount: 0
  extensions: ""
  onclose: function onclose(e)​
  onerror: function onerror(e)​
  onmessage: function onmessage(e)​
  onopen: function onopen(evt)
  protocol: ""
  readyState: 1
  url: "ws://127.0.0.1:23625/"
  <prototype>: WebSocketPrototype { close: close(), send: send(), url: Getter, … }
batch 1 messages
recv invert-colors 19
Experimental feature: invert colors strategy taken: never
batch 2 messages
recv diff-v1 614196
recv diff-v1 556
render_in_window with partial rendering disabled 0 0 1e+33 1e+33
parse 3.00 ms, rerender 58.00 ms, total 61.00 ms
updateCanvas start
updateCanvas done 1
render_in_window with partial rendering disabled 0 0 1e+33 1e+33
parse 0.00 ms, rerender 8.00 ms, total 8.00 ms
updateCanvas start
updateCanvas done 0
batch 1 messages
recv diff-v1 1524
render_in_window with partial rendering disabled 0 0 1e+33 1e+33
parse 0.00 ms, rerender 8.00 ms, total 8.00 ms
updateCanvas start
updateCanvas done 1
batch 1 messages
recv diff-v1 556
render_in_window with partial rendering disabled 0 0 1e+33 1e+33
parse 0.00 ms, rerender 9.00 ms, total 9.00 ms
updateCanvas start
updateCanvas done 0
element path  Array(3) [ (3) […], (3) […], (3) […] ]
batch 1 messages
recv diff-v1 556 
render_in_window with partial rendering disabled 0 0 1e+33 1e+33
parse 1.00 ms, rerender 6.00 ms, total 7.00 ms
updateCanvas start
updateCanvas done 1
render_in_window with partial rendering disabled 0 0 1e+33 1e+33
parse 0.00 ms, rerender 8.00 ms, total 8.00 ms
updateCanvas start
updateCanvas done 0
render_in_window with partial rendering disabled 0 0 1e+33 1e+33
parse 0.00 ms, rerender 8.00 ms, total 8.00 ms
updateCanvas start
updateCanvas done 0
batch 1 messages
recv diff-v1 2740
render_in_window with partial rendering disabled 0 0 1e+33 1e+33
parse 0.00 ms, rerender 9.00 ms, total 9.00 ms
updateCanvas start
updateCanvas done 0
batch 1 messages
recv diff-v1 556
render_in_window with partial rendering disabled 0 0 1e+33 1e+33
reuse directly <g transform="translate(85.039,459.840)" data-tid="pVNTvJMZoFxQ">
parse 0.00 ms, rerender 11.00 ms, total 11.00 ms
updateCanvas start
updateCanvas done 0
render_in_window with partial rendering disabled 0 0 1e+33 1e+33
parse 0.00 ms, rerender 8.00 ms, total 8.00 ms

PS.: I didn't find a way to easily export the logs in firefox, sanitizing this myself was painful, surely there's a better way in case you need more logs.

Enter-tainer commented

The second log may indicates something might be wrong with file watcher.

  • 👍1
tingerrr commented

So this may be a problem upstream at typst.ts? It seems the file watching is done using their CompileActor from what I could gather after a quick peek.