Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

"no entry found for key" panic in helix-view #3459

Closed
bcspragu opened this issue Aug 16, 2022 · 32 comments · Fixed by #2267 or #4384
Closed

"no entry found for key" panic in helix-view #3459

bcspragu opened this issue Aug 16, 2022 · 32 comments · Fixed by #2267 or #4384
Labels
A-helix-term Area: Helix term improvements C-bug Category: This is a bug

Comments

@bcspragu
Copy link
Contributor

bcspragu commented Aug 16, 2022

Summary

Helix panics (about 1-2 times a day with ~8 hour usage) with the following error:

Error
$ RUST_BACKTRACE=full GOPACKAGESDRIVER=$PWD/scripts/gopackagesdriver.sh hx
thread 'main' panicked at 'no entry found for key', helix-view/src/document.rs:1006:10
stack backtrace:
   0:     0x55bd8c72b384 - <unknown>
   1:     0x55bd8bf6965c - <unknown>
   2:     0x55bd8c724d65 - <unknown>
   3:     0x55bd8c72d22e - <unknown>
   4:     0x55bd8c72cf5d - <unknown>
   5:     0x55bd8c5b6b5c - <unknown>
   6:     0x55bd8c72d8bb - <unknown>
   7:     0x55bd8c72d6e4 - <unknown>
   8:     0x55bd8c72b8b4 - <unknown>
   9:     0x55bd8c72d44d - <unknown>
  10:     0x55bd8bee8c33 - <unknown>
  11:     0x55bd8bf67d31 - <unknown>
  12:     0x55bd8bf67cdb - <unknown>
  13:     0x55bd8bee8aa6 - <unknown>
  14:     0x55bd8c51965c - <unknown>
  15:     0x55bd8c217c29 - <unknown>
  16:     0x55bd8c3e7c3f - <unknown>
  17:     0x55bd8c5b3845 - <unknown>
  18:     0x55bd8c5d0fab - <unknown>
  19:     0x55bd8c5a9392 - <unknown>
  20:     0x55bd8c591578 - <unknown>
  21:     0x55bd8c5f27a8 - <unknown>
  22:     0x55bd8c5cdc73 - <unknown>
  23:     0x55bd8c589826 - <unknown>
  24:     0x55bd8c589953 - <unknown>
  25:     0x55bd8c5a908d - <unknown>
  26:     0x55bd8c71f5fb - <unknown>
  27:     0x55bd8c589932 - <unknown>
  28:     0x7f056d9d12d0 - <unknown>
  29:     0x7f056d9d138a - __libc_start_main
  30:     0x55bd8bf1edd5 - <unknown>
  31:                0x0 - <unknown>

I think it happens on save, but not every time I save (I'm saving with :wa very frequently because of this issue), but it always catches me off guard, so I can never remember exactly what I was doing when it happened.

I don't think GOPACKAGESDRIVER has anything to do with it, it's just what I use to get Go's LSP working with Bazel. I'm pretty confident I've seen this failure even when not running with GOPACKAGESDRIVER.

Reproduction Steps

Unfortunately, I don't know exactly what triggers it. I usually have lots of splits open, and it seems to be either a :w or :wa command that triggers the failure.

Helix log

~/.cache/helix/helix.log
2022-08-16T09:11:48.686 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T09:12:15.077 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T09:13:57.611 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T09:46:32.853 helix_view::editor [ERROR] Failed to initialize the LSP for `source.md` { LSP not defined }
2022-08-16T09:46:41.629 helix_view::editor [ERROR] Failed to initialize the LSP for `source.md` { LSP not defined }
2022-08-16T09:48:56.085 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T09:48:59.795 helix_lsp::transport [ERROR] err: <- StreamClosed
2022-08-16T09:49:58.990 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T09:58:05.710 helix_lsp::transport [ERROR] err: <- StreamClosed
2022-08-16T09:58:08.114 helix_lsp::transport [ERROR] err: <- StreamClosed
2022-08-16T09:59:01.288 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T09:59:31.375 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T10:00:07.235 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T10:01:48.057 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T10:03:10.204 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T10:10:03.673 helix_lsp::transport [ERROR] err: <- StreamClosed
2022-08-16T10:10:15.765 helix_view::editor [ERROR] Failed to initialize the LSP for `git.commitmsg` { LSP not defined }
2022-08-16T10:25:57.120 helix_lsp::transport [ERROR] err: <- StreamClosed
2022-08-16T10:46:11.049 helix_lsp::transport [ERROR] <- ServerError(0): 14:21: string literal not terminated (and 2 more errors)
2022-08-16T10:46:11.050 helix_view::document [WARN] LSP formatting failed: protocol error: ServerError(0): 14:21: string literal not terminated (and 2 more errors)
2022-08-16T10:54:14.696 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T10:54:22.729 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T10:55:39.396 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T10:56:59.820 helix_view::editor [ERROR] Failed to initialize the LSP for `source.sql` { LSP not defined }
2022-08-16T10:57:07.583 helix_view::editor [ERROR] Failed to initialize the LSP for `source.sql` { LSP not defined }
2022-08-16T10:59:05.821 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T10:59:40.993 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T10:59:57.991 helix_view::editor [ERROR] Failed to initialize the LSP for `source.sql` { LSP not defined }
2022-08-16T11:04:37.385 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:05:12.052 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:05:46.337 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:08:33.941 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:09:06.968 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:11:42.715 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:12:32.145 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:19:10.376 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:22:27.091 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:23:53.661 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:24:57.772 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:25:54.567 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:26:27.158 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:27:15.928 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:28:08.760 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:29:00.692 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:29:32.137 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:30:34.538 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:31:39.642 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:32:53.320 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:35:36.503 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:41:17.265 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:47:09.087 helix_term::application [WARN] lsp position out of bounds - Diagnostic { range: Range { start: Position { line: 142, character: 0 }, end: Position { line: 142, character: 0 } }, severity: Some(Error), code: None, code_description: None, source: Some("syntax"), message: "expected ';', found 'EOF'", related_information: None, tags: None, data: None }
2022-08-16T11:47:09.270 helix_term::application [WARN] lsp position out of bounds - Diagnostic { range: Range { start: Position { line: 143, character: 0 }, end: Position { line: 143, character: 0 } }, severity: Some(Error), code: None, code_description: None, source: Some("syntax"), message: "expected ';', found 'EOF'", related_information: None, tags: None, data: None }
2022-08-16T11:47:09.423 helix_term::application [WARN] lsp position out of bounds - Diagnostic { range: Range { start: Position { line: 144, character: 0 }, end: Position { line: 144, character: 0 } }, severity: Some(Error), code: None, code_description: None, source: Some("syntax"), message: "expected ';', found 'EOF'", related_information: None, tags: None, data: None }
2022-08-16T11:47:15.815 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:48:13.727 helix_term::application [WARN] lsp position out of bounds - Diagnostic { range: Range { start: Position { line: 148, character: 0 }, end: Position { line: 148, character: 0 } }, severity: Some(Error), code: None, code_description: None, source: Some("syntax"), message: "expected ';', found 'EOF'", related_information: None, tags: None, data: None }
2022-08-16T11:48:13.898 helix_term::application [WARN] lsp position out of bounds - Diagnostic { range: Range { start: Position { line: 149, character: 0 }, end: Position { line: 149, character: 0 } }, severity: Some(Error), code: None, code_description: None, source: Some("syntax"), message: "expected ';', found 'EOF'", related_information: None, tags: None, data: None }
2022-08-16T11:48:37.571 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:49:26.443 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:50:01.018 helix_term::application [WARN] lsp position out of bounds - Diagnostic { range: Range { start: Position { line: 154, character: 0 }, end: Position { line: 154, character: 0 } }, severity: Some(Error), code: None, code_description: None, source: Some("syntax"), message: "expected ';', found 'EOF'", related_information: None, tags: None, data: None }
2022-08-16T11:50:01.220 helix_term::application [WARN] lsp position out of bounds - Diagnostic { range: Range { start: Position { line: 155, character: 0 }, end: Position { line: 155, character: 0 } }, severity: Some(Error), code: None, code_description: None, source: Some("syntax"), message: "expected ';', found 'EOF'", related_information: None, tags: None, data: None }
2022-08-16T11:50:01.359 helix_term::application [WARN] lsp position out of bounds - Diagnostic { range: Range { start: Position { line: 156, character: 0 }, end: Position { line: 156, character: 0 } }, severity: Some(Error), code: None, code_description: None, source: Some("syntax"), message: "expected ';', found 'EOF'", related_information: None, tags: None, data: None }
2022-08-16T11:50:39.381 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:50:51.460 helix_term::application [WARN] lsp position out of bounds - Diagnostic { range: Range { start: Position { line: 159, character: 0 }, end: Position { line: 159, character: 0 } }, severity: Some(Error), code: None, code_description: None, source: Some("syntax"), message: "expected ';', found 'EOF'", related_information: None, tags: None, data: None }
2022-08-16T11:50:51.629 helix_term::application [WARN] lsp position out of bounds - Diagnostic { range: Range { start: Position { line: 160, character: 0 }, end: Position { line: 160, character: 0 } }, severity: Some(Error), code: None, code_description: None, source: Some("syntax"), message: "expected ';', found 'EOF'", related_information: None, tags: None, data: None }
2022-08-16T11:51:09.160 helix_term::application [WARN] lsp position out of bounds - Diagnostic { range: Range { start: Position { line: 162, character: 0 }, end: Position { line: 162, character: 0 } }, severity: Some(Error), code: None, code_description: None, source: Some("syntax"), message: "expected ';', found 'EOF'", related_information: None, tags: None, data: None }
2022-08-16T11:51:09.309 helix_term::application [WARN] lsp position out of bounds - Diagnostic { range: Range { start: Position { line: 163, character: 0 }, end: Position { line: 163, character: 0 } }, severity: Some(Error), code: None, code_description: None, source: Some("syntax"), message: "expected ';', found 'EOF'", related_information: None, tags: None, data: None }
2022-08-16T11:51:09.460 helix_term::application [WARN] lsp position out of bounds - Diagnostic { range: Range { start: Position { line: 164, character: 0 }, end: Position { line: 164, character: 0 } }, severity: Some(Error), code: None, code_description: None, source: Some("syntax"), message: "expected ';', found 'EOF'", related_information: None, tags: None, data: None }
2022-08-16T11:51:56.141 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:52:33.431 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:54:42.422 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:55:27.757 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:56:01.825 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:57:10.284 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:58:05.591 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"
2022-08-16T11:58:38.891 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <project directory>: open <project directory>/bazel-<project name>/.postgres-data/data: permission denied\n"

Most of these errors are related to $PROJECT/.postgres-data/data, which is owned by some other user (it's running in a Docker container). I believe I've seen this failure in other projects that wouldn't have this .postgres-data directory, and also when editing non-Go projects (e.g. TypeScript)

Platform

Linux

Terminal Emulator

st (4ef0cbd8)

Helix Version

helix 22.05 (8deaebd) (built from HEAD ~4 days ago)

@bcspragu bcspragu added the C-bug Category: This is a bug label Aug 16, 2022
@bcspragu
Copy link
Contributor Author

I believe this is the line in question

@the-mikedavis the-mikedavis added the A-helix-term Area: Helix term improvements label Aug 17, 2022
@humb1t
Copy link

humb1t commented Aug 18, 2022

If I remove content of one rust module to delete it and paste into another module, when saving empty module file with :wq, I get this error almost every time.

@the-mikedavis
Copy link
Member

I can't reproduce that but I'm not sure that I'm following the steps correctly. Can you create an asciinema recording with the crash?

@humb1t
Copy link

humb1t commented Aug 19, 2022

Made simple example:

.
├── Cargo.lock
├── Cargo.toml
├── src
│   ├── lib.rs
│   ├── main.rs
│   ├── mod1.rs
│   └── mod2.rs
└── target
    ├── CACHEDIR.TAG
    └── debug
        ├── build
        ├── deps
        │   ├── helix_bug-16bdb97fd248e77d.d
        │   ├── helix_bug-3d6d6a683f2aee38.d
        │   ├── helix_bug-5729db4ebce8c766.d
        │   ├── helix_bug-5cb1f29c7ffb6bb7.d
        │   ├── helix_bug-5ec8aa6c79e21635.d
        │   ├── helix_bug-9b41149b90036e58.d
        │   ├── libhelix_bug-16bdb97fd248e77d.rmeta
        │   ├── libhelix_bug-3d6d6a683f2aee38.rmeta
        │   ├── libhelix_bug-5729db4ebce8c766.rmeta
        │   ├── libhelix_bug-5cb1f29c7ffb6bb7.rmeta
        │   ├── libhelix_bug-5ec8aa6c79e21635.rmeta
        │   └── libhelix_bug-9b41149b90036e58.rmeta
        ├── examples
        └── incremental
            ├── helix_bug-1m63k964mtira
            │   ├── s-gcqgc5rrno-bebf57-2ywbmb8jj3r2k
            │   │   ├── dep-graph.bin
            │   │   ├── query-cache.bin
            │   │   └── work-products.bin
            │   └── s-gcqgc5rrno-bebf57.lock
            ├── helix_bug-1n42wvsvh69bm
            │   ├── s-gcqgaoqt0b-1rhwah0-27isxdhcp4ks9
            │   │   ├── dep-graph.bin
            │   │   ├── query-cache.bin
            │   │   └── work-products.bin
            │   └── s-gcqgaoqt0b-1rhwah0.lock
            ├── helix_bug-1sx0ze0wd15do
            │   ├── s-gcqgc5s6lu-1l7fbl9-26ief4ow1d3e5
            │   │   ├── dep-graph.bin
            │   │   ├── query-cache.bin
            │   │   └── work-products.bin
            │   └── s-gcqgc5s6lu-1l7fbl9.lock
            ├── helix_bug-22lsle841uv4b
            │   ├── s-gcqgc5rruj-1qsm263-1cephkpm09g8
            │   │   ├── dep-graph.bin
            │   │   ├── query-cache.bin
            │   │   └── work-products.bin
            │   └── s-gcqgc5rruj-1qsm263.lock
            ├── helix_bug-26k2qzk5ar6af
            │   ├── s-gcqgaoqt3z-l4a4c0-1cebsf54tlhux
            │   │   ├── dep-graph.bin
            │   │   ├── query-cache.bin
            │   │   └── work-products.bin
            │   └── s-gcqgaoqt3z-l4a4c0.lock
            └── helix_bug-z0o29aspgb1e
                ├── s-gcqgc5s8c1-1x9hkjb-2co0tpj92kpy1
                │   ├── dep-graph.bin
                │   ├── query-cache.bin
                │   └── work-products.bin
                └── s-gcqgc5s8c1-1x9hkjb.lock

19 directories, 43 files

Video of a bug:
asciicast

@bcspragu
Copy link
Contributor Author

I just had a bunch of panics back to back, and can confirm that I'm seeing it triggered when I save the file(s).

@archseer
Copy link
Member

Okay this is pretty useful data points! When saving the view id is used to manipulate document history. On :wq I think there's a race where the document gets removed from the view, but the save+format happens asynchronously and at that point the link between doc<->view is missing.

@bcspragu
Copy link
Contributor Author

One more data point: I just experienced the panic (same line number) on :wa. I've been careful not to type :wq to try and avoid triggering the issue.

@dead10ck
Copy link
Member

dead10ck commented Aug 23, 2022

@bcspragu would you be willing to pull #2267 locally and see if you can still reproduce the issue with that build?

@bcspragu
Copy link
Contributor Author

Most definitely! I've built #2267 locally, I'll test with that for a bit and update the thread.

@dead10ck
Copy link
Member

I think I can see an issue that might happen with write-all-quit: it submits the write jobs, and then immediately closes all the views without waiting for the jobs. This also should be fixed in #2267.

let future = doc.format_and_save(fmt, force);
jobs.add(Job::new(future).wait_before_exiting());
}
if quit {
if !force {
buffers_remaining_impl(cx.editor)?;
}
// close all views
let views: Vec<_> = cx.editor.tree.views().map(|(view, _)| view.id).collect();
for view_id in views {
cx.editor.close(view_id);
}
}

However, this does not explain write-all or write-quit. For the latter

fn write_quit(
cx: &mut compositor::Context,
args: &[Cow<str>],
event: PromptEvent,
) -> anyhow::Result<()> {
if event != PromptEvent::Validate {
return Ok(());
}
write_impl(cx, args.first(), false)?;
helix_lsp::block_on(cx.jobs.finish())?;
quit(cx, &[], event)
}

As we can see, it's supposed to block on the async jobs before proceeding to quit, which is what closes the view. This could have something to do with auto formatting. Currently, the auto format path has two tracks: where the file is written, and one where the changes are asynchronously applied to the in-memory document. The former is always waited on, while the latter is not.

@bcspragu it would be helpful if you could figure out the issue with your backtrace and get it populated with symbols correctly. I'm not sure if this is a platform issue, or if maybe you just need to comment out this line:

split-debuginfo = "unpacked"

I also can't think of how this could be happening with write-all. @bcspragu could you please include the helix log that happens with the verbosity turned all the way up (-vvvv) and take the same steps as the asciinema recording? It looks like the helix log you included in the OP is unrelated.

@bcspragu
Copy link
Contributor Author

bcspragu commented Aug 23, 2022

@bcspragu it would be helpful if you could figure out the issue with your backtrace and get it populated with symbols correctly.

Ah, didn't even occur to me that my stacktrace was useless. I've been building helix-git on Arch/AUR, which (quite reasonably) uses the --release flag. I've set the profile to dev, in addition to the previous changes I had made for your branch. Hopefully that makes stacktraces useful

I also can't think of how this could be happening with write-all. @bcspragu could you please include the helix log that happens with the verbosity turned all the way up (-vvvv) and take the same steps as the asciinema recording? It looks like the helix log you included in the OP is unrelated.

I just tried taking the same steps, but I ran into a different issue while trying to replicate the original one, getting an error like:

failed to send save event: channel closed

Here's the asciinema of that: asciicast

And the helix.log from that session:

helix.log
2022-08-23T08:00:30.548 helix_loader [DEBUG] Located configuration folders: ["/home/bsprague/helix-bug-test/.helix"]
2022-08-23T08:00:30.560 helix_view::clipboard [INFO] Using xclip to interact with the system and selection (primary) clipboard
2022-08-23T08:00:30.560 mio::poll [TRACE] registering event source with poller: token=Token(1), interests=READABLE | WRITABLE
2022-08-23T08:00:30.560 mio::poll [TRACE] registering event source with poller: token=Token(2), interests=READABLE | WRITABLE
2022-08-23T08:00:30.560 mio::poll [TRACE] registering event source with poller: token=Token(0), interests=READABLE
2022-08-23T08:00:30.560 mio::poll [TRACE] registering event source with poller: token=Token(1), interests=READABLE
2022-08-23T08:00:30.560 helix_view::document [DEBUG] id 1 modified - last saved: 0, current: 0
2022-08-23T08:00:30.961 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:00:32.621 helix_view::document [DEBUG] id 1 modified - last saved: 0, current: 0
2022-08-23T08:00:32.674 globset [DEBUG] glob converted to regex: Glob { glob: "*.{zip,gz,bz2,zst,lzo,sz,tgz,tbz2,lz,lz4,lzma,lzo,z,Z,xz,7z,rar,cab}", re: "(?-u)^[^/]*\\.(cab|rar|7z|xz|Z|z|lzo|lzma|lz4|lz|tbz2|tgz|sz|lzo|zst|bz2|gz|zip)$", opts: GlobOptions { case_insensitive: false, literal_separator: true, backslash_escape: true }, tokens: Tokens([ZeroOrMore, Literal('.'), Alternates([Tokens([Literal('c'), Literal('a'), Literal('b')]), Tokens([Literal('r'), Literal('a'), Literal('r')]), Tokens([Literal('7'), Literal('z')]), Tokens([Literal('x'), Literal('z')]), Tokens([Literal('Z')]), Tokens([Literal('z')]), Tokens([Literal('l'), Literal('z'), Literal('o')]), Tokens([Literal('l'), Literal('z'), Literal('m'), Literal('a')]), Tokens([Literal('l'), Literal('z'), Literal('4')]), Tokens([Literal('l'), Literal('z')]), Tokens([Literal('t'), Literal('b'), Literal('z'), Literal('2')]), Tokens([Literal('t'), Literal('g'), Literal('z')]), Tokens([Literal('s'), Literal('z')]), Tokens([Literal('l'), Literal('z'), Literal('o')]), Tokens([Literal('z'), Literal('s'), Literal('t')]), Tokens([Literal('b'), Literal('z'), Literal('2')]), Tokens([Literal('g'), Literal('z')]), Tokens([Literal('z'), Literal('i'), Literal('p')])])]) }
2022-08-23T08:00:32.674 globset [DEBUG] built glob set; 0 literals, 0 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 1 regexes
2022-08-23T08:00:32.675 globset [DEBUG] built glob set; 1 literals, 0 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 0 regexes
2022-08-23T08:00:32.675 ignore::walk [DEBUG] ignoring /home/bsprague/helix-bug-test/.gitignore: Ignore(IgnoreMatch(Hidden))
2022-08-23T08:00:32.675 ignore::walk [DEBUG] ignoring /home/bsprague/helix-bug-test/.git: Ignore(IgnoreMatch(Hidden))
2022-08-23T08:00:32.675 helix_term::ui [DEBUG] file_picker init 2.474748ms
2022-08-23T08:00:32.675 helix_view::document [DEBUG] id 1 modified - last saved: 0, current: 0
2022-08-23T08:00:33.073 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:00:33.349 helix_term::ui::picker [DEBUG] picker score 22.908µs
2022-08-23T08:00:33.349 helix_view::document [DEBUG] id 1 modified - last saved: 0, current: 0
2022-08-23T08:00:33.453 helix_term::ui::picker [DEBUG] picker score 21.651µs
2022-08-23T08:00:33.453 helix_view::document [DEBUG] id 1 modified - last saved: 0, current: 0
2022-08-23T08:00:33.525 helix_term::ui::picker [DEBUG] picker score 13.27µs
2022-08-23T08:00:33.525 helix_view::document [DEBUG] id 1 modified - last saved: 0, current: 0
2022-08-23T08:00:33.580 helix_term::ui::picker [DEBUG] picker score 12.571µs
2022-08-23T08:00:33.581 helix_view::document [DEBUG] id 1 modified - last saved: 0, current: 0
2022-08-23T08:00:34.084 helix_view::editor [ERROR] Failed to initialize the LSP for `source.rust` { cannot find binary path }
2022-08-23T08:00:34.084 helix_view::document [DEBUG] id 1 modified - last saved: 0, current: 0
2022-08-23T08:00:34.084 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-08-23T08:00:36.549 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-08-23T08:00:36.605 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-08-23T08:00:36.605 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-08-23T08:00:37.006 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:00:38.857 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-08-23T08:00:38.857 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-08-23T08:00:38.913 globset [DEBUG] glob converted to regex: Glob { glob: "*.{zip,gz,bz2,zst,lzo,sz,tgz,tbz2,lz,lz4,lzma,lzo,z,Z,xz,7z,rar,cab}", re: "(?-u)^[^/]*\\.(cab|rar|7z|xz|Z|z|lzo|lzma|lz4|lz|tbz2|tgz|sz|lzo|zst|bz2|gz|zip)$", opts: GlobOptions { case_insensitive: false, literal_separator: true, backslash_escape: true }, tokens: Tokens([ZeroOrMore, Literal('.'), Alternates([Tokens([Literal('c'), Literal('a'), Literal('b')]), Tokens([Literal('r'), Literal('a'), Literal('r')]), Tokens([Literal('7'), Literal('z')]), Tokens([Literal('x'), Literal('z')]), Tokens([Literal('Z')]), Tokens([Literal('z')]), Tokens([Literal('l'), Literal('z'), Literal('o')]), Tokens([Literal('l'), Literal('z'), Literal('m'), Literal('a')]), Tokens([Literal('l'), Literal('z'), Literal('4')]), Tokens([Literal('l'), Literal('z')]), Tokens([Literal('t'), Literal('b'), Literal('z'), Literal('2')]), Tokens([Literal('t'), Literal('g'), Literal('z')]), Tokens([Literal('s'), Literal('z')]), Tokens([Literal('l'), Literal('z'), Literal('o')]), Tokens([Literal('z'), Literal('s'), Literal('t')]), Tokens([Literal('b'), Literal('z'), Literal('2')]), Tokens([Literal('g'), Literal('z')]), Tokens([Literal('z'), Literal('i'), Literal('p')])])]) }
2022-08-23T08:00:38.913 globset [DEBUG] built glob set; 0 literals, 0 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 1 regexes
2022-08-23T08:00:38.913 globset [DEBUG] built glob set; 1 literals, 0 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 0 regexes
2022-08-23T08:00:38.913 ignore::walk [DEBUG] ignoring /home/bsprague/helix-bug-test/.gitignore: Ignore(IgnoreMatch(Hidden))
2022-08-23T08:00:38.914 ignore::walk [DEBUG] ignoring /home/bsprague/helix-bug-test/.git: Ignore(IgnoreMatch(Hidden))
2022-08-23T08:00:38.914 helix_term::ui [DEBUG] file_picker init 839.699µs
2022-08-23T08:00:38.914 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-08-23T08:00:38.914 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-08-23T08:00:39.314 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:00:39.709 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-08-23T08:00:39.709 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-08-23T08:00:40.145 helix_view::editor [ERROR] Failed to initialize the LSP for `source.rust` { cannot find binary path }
2022-08-23T08:00:40.145 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-08-23T08:00:40.145 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-08-23T08:00:40.145 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:00:42.517 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-08-23T08:00:42.517 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:00:42.673 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-08-23T08:00:42.673 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:00:42.825 helix_view::editor [DEBUG] editor status: yanked 1 selection(s) to register "
2022-08-23T08:00:42.825 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-08-23T08:00:42.825 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:00:43.089 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-08-23T08:00:43.089 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:00:43.369 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-08-23T08:00:43.369 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:00:43.553 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-08-23T08:00:43.553 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:00:43.654 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 1
2022-08-23T08:00:43.654 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:00:44.054 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:00:44.445 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-08-23T08:00:44.445 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:00:44.813 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-08-23T08:00:44.813 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:00:45.199 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:00:45.199 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-08-23T08:00:45.199 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:00:45.381 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 2
2022-08-23T08:00:45.381 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:00:45.381 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 2
2022-08-23T08:00:45.381 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:00:45.501 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 3
2022-08-23T08:00:45.501 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:00:45.902 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:00:46.501 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 3
2022-08-23T08:00:46.501 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:00:46.853 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 3
2022-08-23T08:00:46.853 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:00:47.009 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 3
2022-08-23T08:00:47.009 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:00:47.041 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 3
2022-08-23T08:00:47.041 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:00:47.096 helix_view::document [DEBUG] submitting save of doc 'Some("/home/bsprague/helix-bug-test/src/mod1.rs")'
2022-08-23T08:00:47.096 helix_term::job [DEBUG] waiting on jobs...
2022-08-23T08:00:47.096 helix_view::document [TRACE] awaiting save of 'Some("/home/bsprague/helix-bug-test/src/mod1.rs")'
2022-08-23T08:00:47.097 helix_view::document [TRACE] save of 'Some("/home/bsprague/helix-bug-test/src/mod1.rs")' result: Ok(DocumentSaveEvent { revision: 0, doc_id: DocumentId(3), path: "/home/bsprague/helix-bug-test/src/mod1.rs" })
2022-08-23T08:00:47.097 helix_view::document [DEBUG] doc 3 revision updated 0 -> 0
2022-08-23T08:00:47.097 helix_term::commands::typed [INFO] quitting...
2022-08-23T08:00:47.097 helix_term::job [DEBUG] waiting on jobs...
2022-08-23T08:00:47.097 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 3
2022-08-23T08:00:47.253 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:00:48.117 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 3
2022-08-23T08:00:48.213 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 3
2022-08-23T08:00:48.300 helix_view::document [DEBUG] submitting save of doc 'Some("/home/bsprague/helix-bug-test/src/main.rs")'
2022-08-23T08:00:48.301 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 3
2022-08-23T08:00:48.301 helix_view::document [TRACE] awaiting save of 'Some("/home/bsprague/helix-bug-test/src/main.rs")'
2022-08-23T08:00:48.518 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:00:48.518 helix_view::document [TRACE] reawaiting save of 'Some("/home/bsprague/helix-bug-test/src/main.rs")'
2022-08-23T08:00:49.417 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 3
2022-08-23T08:00:49.417 helix_view::document [TRACE] reawaiting save of 'Some("/home/bsprague/helix-bug-test/src/main.rs")'
2022-08-23T08:00:49.417 helix_view::document [TRACE] reawait save of 'Some("/home/bsprague/helix-bug-test/src/main.rs")' result: Ok(DocumentSaveEvent { revision: 3, doc_id: DocumentId(2), path: "/home/bsprague/helix-bug-test/src/main.rs" })
2022-08-23T08:00:49.417 helix_term::application [DEBUG] received editor event: DocumentSave(Ok(DocumentSaveEvent { revision: 3, doc_id: DocumentId(2), path: "/home/bsprague/helix-bug-test/src/main.rs" }))
2022-08-23T08:00:49.417 helix_term::application [DEBUG] document Some("/home/bsprague/helix-bug-test/src/main.rs") saved with revision 3
2022-08-23T08:00:49.417 helix_view::document [DEBUG] doc 2 revision updated 0 -> 3
2022-08-23T08:00:49.417 helix_view::editor [DEBUG] editor status: 'src/main.rs' written, 6L 73B
2022-08-23T08:00:49.418 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 3
2022-08-23T08:00:49.473 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 3
2022-08-23T08:00:49.473 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 3
2022-08-23T08:00:49.875 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:00:50.665 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 3
2022-08-23T08:00:50.665 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 3
2022-08-23T08:00:50.721 globset [DEBUG] glob converted to regex: Glob { glob: "*.{zip,gz,bz2,zst,lzo,sz,tgz,tbz2,lz,lz4,lzma,lzo,z,Z,xz,7z,rar,cab}", re: "(?-u)^[^/]*\\.(cab|rar|7z|xz|Z|z|lzo|lzma|lz4|lz|tbz2|tgz|sz|lzo|zst|bz2|gz|zip)$", opts: GlobOptions { case_insensitive: false, literal_separator: true, backslash_escape: true }, tokens: Tokens([ZeroOrMore, Literal('.'), Alternates([Tokens([Literal('c'), Literal('a'), Literal('b')]), Tokens([Literal('r'), Literal('a'), Literal('r')]), Tokens([Literal('7'), Literal('z')]), Tokens([Literal('x'), Literal('z')]), Tokens([Literal('Z')]), Tokens([Literal('z')]), Tokens([Literal('l'), Literal('z'), Literal('o')]), Tokens([Literal('l'), Literal('z'), Literal('m'), Literal('a')]), Tokens([Literal('l'), Literal('z'), Literal('4')]), Tokens([Literal('l'), Literal('z')]), Tokens([Literal('t'), Literal('b'), Literal('z'), Literal('2')]), Tokens([Literal('t'), Literal('g'), Literal('z')]), Tokens([Literal('s'), Literal('z')]), Tokens([Literal('l'), Literal('z'), Literal('o')]), Tokens([Literal('z'), Literal('s'), Literal('t')]), Tokens([Literal('b'), Literal('z'), Literal('2')]), Tokens([Literal('g'), Literal('z')]), Tokens([Literal('z'), Literal('i'), Literal('p')])])]) }
2022-08-23T08:00:50.721 globset [DEBUG] built glob set; 0 literals, 0 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 1 regexes
2022-08-23T08:00:50.721 globset [DEBUG] built glob set; 1 literals, 0 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 0 regexes
2022-08-23T08:00:50.721 ignore::walk [DEBUG] ignoring /home/bsprague/helix-bug-test/.gitignore: Ignore(IgnoreMatch(Hidden))
2022-08-23T08:00:50.722 ignore::walk [DEBUG] ignoring /home/bsprague/helix-bug-test/.git: Ignore(IgnoreMatch(Hidden))
2022-08-23T08:00:50.722 helix_term::ui [DEBUG] file_picker init 731.585µs
2022-08-23T08:00:50.722 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 3
2022-08-23T08:00:50.722 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 3
2022-08-23T08:00:50.929 helix_term::ui::picker [DEBUG] picker score 28.146µs
2022-08-23T08:00:50.929 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 3
2022-08-23T08:00:50.930 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 3
2022-08-23T08:00:51.001 helix_term::ui::picker [DEBUG] picker score 22.07µs
2022-08-23T08:00:51.001 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 3
2022-08-23T08:00:51.001 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 3
2022-08-23T08:00:51.017 helix_term::ui::picker [DEBUG] picker score 16.692µs
2022-08-23T08:00:51.017 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 3
2022-08-23T08:00:51.017 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 3
2022-08-23T08:00:51.122 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:00:51.285 helix_term::ui::picker [DEBUG] picker score 37.155µs
2022-08-23T08:00:51.285 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 3
2022-08-23T08:00:51.285 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 3
2022-08-23T08:00:51.565 helix_view::editor [ERROR] Failed to initialize the LSP for `source.rust` { cannot find binary path }
2022-08-23T08:00:51.565 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 3
2022-08-23T08:00:51.565 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 3
2022-08-23T08:00:51.565 helix_view::document [DEBUG] id 4 modified - last saved: 0, current: 0
2022-08-23T08:00:52.177 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 3
2022-08-23T08:00:52.177 helix_view::document [DEBUG] id 4 modified - last saved: 0, current: 0
2022-08-23T08:00:52.578 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:00:52.781 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 3
2022-08-23T08:00:52.781 helix_view::document [DEBUG] id 4 modified - last saved: 0, current: 0
2022-08-23T08:00:52.949 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 3
2022-08-23T08:00:52.949 helix_view::document [DEBUG] id 4 modified - last saved: 0, current: 0
2022-08-23T08:00:53.351 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:00:53.449 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:00:53.449 helix_view::document [DEBUG] id 4 modified - last saved: 0, current: 0
2022-08-23T08:00:53.753 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:00:53.753 helix_view::document [DEBUG] id 4 modified - last saved: 0, current: 0
2022-08-23T08:00:54.153 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:00:54.172 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:00:54.172 helix_view::document [DEBUG] id 4 modified - last saved: 0, current: 1
2022-08-23T08:00:54.573 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:00:55.049 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:00:55.049 helix_view::document [DEBUG] id 4 modified - last saved: 0, current: 1
2022-08-23T08:00:55.225 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:00:55.225 helix_view::document [DEBUG] id 4 modified - last saved: 0, current: 1
2022-08-23T08:00:55.529 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:00:55.529 helix_view::document [DEBUG] id 4 modified - last saved: 0, current: 1
2022-08-23T08:00:55.689 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:00:55.689 helix_view::document [DEBUG] id 4 modified - last saved: 0, current: 2
2022-08-23T08:00:56.091 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:00:56.277 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:00:56.277 helix_view::document [DEBUG] id 4 modified - last saved: 0, current: 1
2022-08-23T08:00:56.621 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:00:56.621 helix_view::document [DEBUG] id 4 modified - last saved: 0, current: 1
2022-08-23T08:00:56.797 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:00:56.797 helix_view::document [DEBUG] id 4 modified - last saved: 0, current: 3
2022-08-23T08:00:57.189 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:00:57.189 helix_view::document [DEBUG] id 4 modified - last saved: 0, current: 3
2022-08-23T08:00:57.373 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:00:57.373 helix_view::document [DEBUG] id 4 modified - last saved: 0, current: 3
2022-08-23T08:00:57.497 helix_view::document [DEBUG] submitting save of doc 'Some("/home/bsprague/helix-bug-test/src/mod2.rs")'
2022-08-23T08:00:57.497 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:00:57.497 helix_view::document [DEBUG] id 4 modified - last saved: 0, current: 3
2022-08-23T08:00:57.590 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:00:58.177 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:00:58.177 helix_view::document [DEBUG] id 4 modified - last saved: 0, current: 3
2022-08-23T08:00:58.301 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:00:58.301 helix_view::document [DEBUG] id 4 modified - last saved: 0, current: 3
2022-08-23T08:00:58.361 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:00:58.361 helix_view::document [DEBUG] id 4 modified - last saved: 0, current: 3
2022-08-23T08:00:58.404 helix_view::document [DEBUG] submitting save of doc 'Some("/home/bsprague/helix-bug-test/src/mod2.rs")'
2022-08-23T08:00:58.404 helix_term::job [DEBUG] waiting on jobs...
2022-08-23T08:00:58.404 helix_view::document [TRACE] awaiting save of 'Some("/home/bsprague/helix-bug-test/src/mod2.rs")'
2022-08-23T08:00:58.405 helix_view::document [TRACE] save of 'Some("/home/bsprague/helix-bug-test/src/mod2.rs")' result: Ok(DocumentSaveEvent { revision: 3, doc_id: DocumentId(4), path: "/home/bsprague/helix-bug-test/src/mod2.rs" })
2022-08-23T08:00:58.405 helix_view::document [DEBUG] doc 4 revision updated 0 -> 3
2022-08-23T08:00:58.405 helix_view::document [TRACE] awaiting save of 'Some("/home/bsprague/helix-bug-test/src/mod2.rs")'
2022-08-23T08:00:58.409 helix_view::document [TRACE] save of 'Some("/home/bsprague/helix-bug-test/src/mod2.rs")' result: Ok(DocumentSaveEvent { revision: 3, doc_id: DocumentId(4), path: "/home/bsprague/helix-bug-test/src/mod2.rs" })
2022-08-23T08:00:58.409 helix_view::document [DEBUG] doc 4 revision updated 3 -> 3
2022-08-23T08:00:58.410 helix_term::commands::typed [INFO] quitting...
2022-08-23T08:00:58.410 helix_term::job [DEBUG] waiting on jobs...
2022-08-23T08:00:58.410 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:00:58.579 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:00:59.553 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:00:59.625 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:00:59.625 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:01:00.026 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:00.501 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:01:00.501 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:01:00.608 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:01:00.608 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:01:00.665 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:01:00.665 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:01:00.716 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:01:00.716 helix_view::document [DEBUG] submitting save of doc 'Some("/home/bsprague/helix-bug-test/src/main.rs")'
2022-08-23T08:01:00.717 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:00.717 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:00.717 helix_view::editor [ERROR] editor error: 
2022-08-23T08:01:00.717 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:01:00.717 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:01:00.717 helix_view::document [TRACE] awaiting save of 'Some("/home/bsprague/helix-bug-test/src/main.rs")'
2022-08-23T08:01:00.903 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:00.903 helix_view::document [TRACE] reawaiting save of 'Some("/home/bsprague/helix-bug-test/src/main.rs")'
2022-08-23T08:01:02.145 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:01:02.145 helix_view::document [DEBUG] id 2 modified - last saved: 3, current: 4
2022-08-23T08:01:02.145 helix_view::document [TRACE] reawaiting save of 'Some("/home/bsprague/helix-bug-test/src/main.rs")'
2022-08-23T08:01:02.145 helix_view::document [TRACE] reawait save of 'Some("/home/bsprague/helix-bug-test/src/main.rs")' result: Ok(DocumentSaveEvent { revision: 4, doc_id: DocumentId(2), path: "/home/bsprague/helix-bug-test/src/main.rs" })
2022-08-23T08:01:02.145 helix_term::application [DEBUG] received editor event: DocumentSave(Ok(DocumentSaveEvent { revision: 4, doc_id: DocumentId(2), path: "/home/bsprague/helix-bug-test/src/main.rs" }))
2022-08-23T08:01:02.145 helix_term::application [DEBUG] document Some("/home/bsprague/helix-bug-test/src/main.rs") saved with revision 4
2022-08-23T08:01:02.145 helix_view::document [DEBUG] doc 2 revision updated 3 -> 4
2022-08-23T08:01:02.145 helix_view::editor [DEBUG] editor status: 'src/main.rs' written, 4L 45B
2022-08-23T08:01:02.146 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:02.146 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:02.453 globset [DEBUG] glob converted to regex: Glob { glob: "*.{zip,gz,bz2,zst,lzo,sz,tgz,tbz2,lz,lz4,lzma,lzo,z,Z,xz,7z,rar,cab}", re: "(?-u)^[^/]*\\.(cab|rar|7z|xz|Z|z|lzo|lzma|lz4|lz|tbz2|tgz|sz|lzo|zst|bz2|gz|zip)$", opts: GlobOptions { case_insensitive: false, literal_separator: true, backslash_escape: true }, tokens: Tokens([ZeroOrMore, Literal('.'), Alternates([Tokens([Literal('c'), Literal('a'), Literal('b')]), Tokens([Literal('r'), Literal('a'), Literal('r')]), Tokens([Literal('7'), Literal('z')]), Tokens([Literal('x'), Literal('z')]), Tokens([Literal('Z')]), Tokens([Literal('z')]), Tokens([Literal('l'), Literal('z'), Literal('o')]), Tokens([Literal('l'), Literal('z'), Literal('m'), Literal('a')]), Tokens([Literal('l'), Literal('z'), Literal('4')]), Tokens([Literal('l'), Literal('z')]), Tokens([Literal('t'), Literal('b'), Literal('z'), Literal('2')]), Tokens([Literal('t'), Literal('g'), Literal('z')]), Tokens([Literal('s'), Literal('z')]), Tokens([Literal('l'), Literal('z'), Literal('o')]), Tokens([Literal('z'), Literal('s'), Literal('t')]), Tokens([Literal('b'), Literal('z'), Literal('2')]), Tokens([Literal('g'), Literal('z')]), Tokens([Literal('z'), Literal('i'), Literal('p')])])]) }
2022-08-23T08:01:02.453 globset [DEBUG] built glob set; 0 literals, 0 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 1 regexes
2022-08-23T08:01:02.453 globset [DEBUG] built glob set; 1 literals, 0 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 0 regexes
2022-08-23T08:01:02.454 ignore::walk [DEBUG] ignoring /home/bsprague/helix-bug-test/.gitignore: Ignore(IgnoreMatch(Hidden))
2022-08-23T08:01:02.454 ignore::walk [DEBUG] ignoring /home/bsprague/helix-bug-test/.git: Ignore(IgnoreMatch(Hidden))
2022-08-23T08:01:02.454 helix_term::ui [DEBUG] file_picker init 854.226µs
2022-08-23T08:01:02.454 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:02.454 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:02.825 helix_term::ui::picker [DEBUG] picker score 47.911µs
2022-08-23T08:01:02.825 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:02.825 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:02.854 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:02.897 helix_term::ui::picker [DEBUG] picker score 22.35µs
2022-08-23T08:01:02.897 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:02.897 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:02.941 helix_term::ui::picker [DEBUG] picker score 15.854µs
2022-08-23T08:01:02.941 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:02.941 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:04.029 helix_term::ui::picker [DEBUG] picker score 11.804µs
2022-08-23T08:01:04.029 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:04.029 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:04.677 helix_term::ui::picker [DEBUG] picker score 19.625µs
2022-08-23T08:01:04.677 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:04.677 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:04.721 helix_term::ui::picker [DEBUG] picker score 15.016µs
2022-08-23T08:01:04.721 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:04.721 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:05.073 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:05.073 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:05.073 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:05.717 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:05.717 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:06.065 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:06.065 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:06.233 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:06.233 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:06.388 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:06.389 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:06.521 helix_view::editor [DEBUG] editor status: yanked 1 selection(s) to register "
2022-08-23T08:01:06.521 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:06.521 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:06.923 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:07.593 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:07.593 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:07.757 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:07.757 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:07.813 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:07.813 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:07.853 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:07.853 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:07.977 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:07.977 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:07.993 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:08.057 globset [DEBUG] built glob set; 1 literals, 0 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 0 regexes
2022-08-23T08:01:08.057 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:08.057 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:08.112 globset [DEBUG] built glob set; 1 literals, 0 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 0 regexes
2022-08-23T08:01:08.113 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:08.113 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:08.169 globset [DEBUG] built glob set; 1 literals, 0 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 0 regexes
2022-08-23T08:01:08.169 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:08.170 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:08.353 globset [DEBUG] built glob set; 1 literals, 0 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 0 regexes
2022-08-23T08:01:08.353 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:08.353 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:08.593 globset [DEBUG] built glob set; 1 literals, 0 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 0 regexes
2022-08-23T08:01:08.593 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:08.593 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:08.848 globset [DEBUG] built glob set; 1 literals, 0 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 0 regexes
2022-08-23T08:01:08.849 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:08.849 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:08.909 globset [DEBUG] built glob set; 1 literals, 0 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 0 regexes
2022-08-23T08:01:08.909 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:08.909 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:08.973 globset [DEBUG] built glob set; 1 literals, 0 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 0 regexes
2022-08-23T08:01:08.973 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:08.973 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:09.777 globset [DEBUG] built glob set; 1 literals, 0 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 0 regexes
2022-08-23T08:01:09.777 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:09.777 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:09.945 globset [DEBUG] built glob set; 1 literals, 0 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 0 regexes
2022-08-23T08:01:09.945 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:09.945 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:10.041 globset [DEBUG] built glob set; 1 literals, 0 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 0 regexes
2022-08-23T08:01:10.041 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:10.041 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:10.089 globset [DEBUG] built glob set; 1 literals, 0 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 0 regexes
2022-08-23T08:01:10.089 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:10.089 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:10.361 helix_view::editor [ERROR] Failed to initialize the LSP for `source.rust` { cannot find binary path }
2022-08-23T08:01:10.361 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:10.361 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:10.361 helix_view::document [DEBUG] id 5 modified - last saved: 0, current: 0
2022-08-23T08:01:10.736 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:10.737 helix_view::document [DEBUG] id 5 modified - last saved: 0, current: 1
2022-08-23T08:01:11.137 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:11.193 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:11.193 helix_view::document [DEBUG] id 5 modified - last saved: 0, current: 1
2022-08-23T08:01:11.289 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:11.289 helix_view::document [DEBUG] id 5 modified - last saved: 0, current: 1
2022-08-23T08:01:11.380 helix_view::document [DEBUG] submitting save of doc 'Some("/home/bsprague/helix-bug-test/src/mod3.rs")'
2022-08-23T08:01:11.381 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:11.381 helix_view::document [DEBUG] id 5 modified - last saved: 0, current: 1
2022-08-23T08:01:11.594 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:11.921 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:11.921 helix_view::document [DEBUG] id 5 modified - last saved: 0, current: 1
2022-08-23T08:01:12.117 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:12.117 helix_view::document [DEBUG] id 5 modified - last saved: 0, current: 1
2022-08-23T08:01:12.157 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:12.157 helix_view::document [DEBUG] id 5 modified - last saved: 0, current: 1
2022-08-23T08:01:12.212 helix_view::document [DEBUG] submitting save of doc 'Some("/home/bsprague/helix-bug-test/src/mod3.rs")'
2022-08-23T08:01:12.212 helix_term::job [DEBUG] waiting on jobs...
2022-08-23T08:01:12.212 helix_view::document [TRACE] awaiting save of 'Some("/home/bsprague/helix-bug-test/src/mod3.rs")'
2022-08-23T08:01:12.213 helix_view::document [TRACE] save of 'Some("/home/bsprague/helix-bug-test/src/mod3.rs")' result: Ok(DocumentSaveEvent { revision: 1, doc_id: DocumentId(5), path: "/home/bsprague/helix-bug-test/src/mod3.rs" })
2022-08-23T08:01:12.213 helix_view::document [DEBUG] doc 5 revision updated 0 -> 1
2022-08-23T08:01:12.213 helix_view::document [TRACE] awaiting save of 'Some("/home/bsprague/helix-bug-test/src/mod3.rs")'
2022-08-23T08:01:12.213 helix_view::document [TRACE] save of 'Some("/home/bsprague/helix-bug-test/src/mod3.rs")' result: Ok(DocumentSaveEvent { revision: 1, doc_id: DocumentId(5), path: "/home/bsprague/helix-bug-test/src/mod3.rs" })
2022-08-23T08:01:12.213 helix_view::document [DEBUG] doc 5 revision updated 1 -> 1
2022-08-23T08:01:12.213 helix_term::commands::typed [INFO] quitting...
2022-08-23T08:01:12.213 helix_term::job [DEBUG] waiting on jobs...
2022-08-23T08:01:12.213 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:12.322 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:13.141 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:13.369 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:13.533 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:13.884 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:13.993 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:14.021 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:14.116 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:14.116 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:14.116 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:14.116 helix_view::document [DEBUG] id 5 modified - last saved: 1, current: 1
2022-08-23T08:01:14.116 helix_view::editor [ERROR] editor error: 
2022-08-23T08:01:14.117 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:14.285 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:14.525 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:14.553 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:14.553 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:14.954 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:15.761 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:15.761 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:15.785 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:15.785 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:15.786 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:16.186 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:16.860 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:16.860 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:16.860 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:17.261 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:17.389 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:17.389 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:17.390 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:17.428 globset [DEBUG] glob converted to regex: Glob { glob: "*.{zip,gz,bz2,zst,lzo,sz,tgz,tbz2,lz,lz4,lzma,lzo,z,Z,xz,7z,rar,cab}", re: "(?-u)^[^/]*\\.(cab|rar|7z|xz|Z|z|lzo|lzma|lz4|lz|tbz2|tgz|sz|lzo|zst|bz2|gz|zip)$", opts: GlobOptions { case_insensitive: false, literal_separator: true, backslash_escape: true }, tokens: Tokens([ZeroOrMore, Literal('.'), Alternates([Tokens([Literal('c'), Literal('a'), Literal('b')]), Tokens([Literal('r'), Literal('a'), Literal('r')]), Tokens([Literal('7'), Literal('z')]), Tokens([Literal('x'), Literal('z')]), Tokens([Literal('Z')]), Tokens([Literal('z')]), Tokens([Literal('l'), Literal('z'), Literal('o')]), Tokens([Literal('l'), Literal('z'), Literal('m'), Literal('a')]), Tokens([Literal('l'), Literal('z'), Literal('4')]), Tokens([Literal('l'), Literal('z')]), Tokens([Literal('t'), Literal('b'), Literal('z'), Literal('2')]), Tokens([Literal('t'), Literal('g'), Literal('z')]), Tokens([Literal('s'), Literal('z')]), Tokens([Literal('l'), Literal('z'), Literal('o')]), Tokens([Literal('z'), Literal('s'), Literal('t')]), Tokens([Literal('b'), Literal('z'), Literal('2')]), Tokens([Literal('g'), Literal('z')]), Tokens([Literal('z'), Literal('i'), Literal('p')])])]) }
2022-08-23T08:01:17.428 globset [DEBUG] built glob set; 0 literals, 0 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 1 regexes
2022-08-23T08:01:17.429 globset [DEBUG] built glob set; 1 literals, 0 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 0 regexes
2022-08-23T08:01:17.429 ignore::walk [DEBUG] ignoring /home/bsprague/helix-bug-test/.gitignore: Ignore(IgnoreMatch(Hidden))
2022-08-23T08:01:17.429 ignore::walk [DEBUG] ignoring /home/bsprague/helix-bug-test/.git: Ignore(IgnoreMatch(Hidden))
2022-08-23T08:01:17.429 helix_term::ui [DEBUG] file_picker init 562.709µs
2022-08-23T08:01:17.429 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:17.429 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:17.429 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:17.732 helix_term::ui::picker [DEBUG] picker score 31.079µs
2022-08-23T08:01:17.733 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:17.733 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:17.733 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:17.830 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:17.989 helix_term::ui::picker [DEBUG] picker score 24.584µs
2022-08-23T08:01:17.989 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:17.989 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:17.989 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:18.064 helix_term::ui::picker [DEBUG] picker score 17.251µs
2022-08-23T08:01:18.065 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:18.065 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:18.065 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:18.208 helix_term::ui::picker [DEBUG] picker score 20.882µs
2022-08-23T08:01:18.209 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:18.209 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:18.209 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:18.453 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:18.453 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:18.453 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:18.453 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:19.013 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:19.013 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:19.013 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:19.413 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:19.533 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:19.533 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:19.533 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:19.593 globset [DEBUG] glob converted to regex: Glob { glob: "*.{zip,gz,bz2,zst,lzo,sz,tgz,tbz2,lz,lz4,lzma,lzo,z,Z,xz,7z,rar,cab}", re: "(?-u)^[^/]*\\.(cab|rar|7z|xz|Z|z|lzo|lzma|lz4|lz|tbz2|tgz|sz|lzo|zst|bz2|gz|zip)$", opts: GlobOptions { case_insensitive: false, literal_separator: true, backslash_escape: true }, tokens: Tokens([ZeroOrMore, Literal('.'), Alternates([Tokens([Literal('c'), Literal('a'), Literal('b')]), Tokens([Literal('r'), Literal('a'), Literal('r')]), Tokens([Literal('7'), Literal('z')]), Tokens([Literal('x'), Literal('z')]), Tokens([Literal('Z')]), Tokens([Literal('z')]), Tokens([Literal('l'), Literal('z'), Literal('o')]), Tokens([Literal('l'), Literal('z'), Literal('m'), Literal('a')]), Tokens([Literal('l'), Literal('z'), Literal('4')]), Tokens([Literal('l'), Literal('z')]), Tokens([Literal('t'), Literal('b'), Literal('z'), Literal('2')]), Tokens([Literal('t'), Literal('g'), Literal('z')]), Tokens([Literal('s'), Literal('z')]), Tokens([Literal('l'), Literal('z'), Literal('o')]), Tokens([Literal('z'), Literal('s'), Literal('t')]), Tokens([Literal('b'), Literal('z'), Literal('2')]), Tokens([Literal('g'), Literal('z')]), Tokens([Literal('z'), Literal('i'), Literal('p')])])]) }
2022-08-23T08:01:19.593 globset [DEBUG] built glob set; 0 literals, 0 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 1 regexes
2022-08-23T08:01:19.593 globset [DEBUG] built glob set; 1 literals, 0 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 0 regexes
2022-08-23T08:01:19.593 ignore::walk [DEBUG] ignoring /home/bsprague/helix-bug-test/.gitignore: Ignore(IgnoreMatch(Hidden))
2022-08-23T08:01:19.593 ignore::walk [DEBUG] ignoring /home/bsprague/helix-bug-test/.git: Ignore(IgnoreMatch(Hidden))
2022-08-23T08:01:19.593 helix_term::ui [DEBUG] file_picker init 504.183µs
2022-08-23T08:01:19.594 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:19.594 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:19.594 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:19.994 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:20.193 helix_term::ui::picker [DEBUG] picker score 30.032µs
2022-08-23T08:01:20.193 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:20.193 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:20.193 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:20.249 helix_term::ui::picker [DEBUG] picker score 19.137µs
2022-08-23T08:01:20.249 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:20.249 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:20.249 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:20.292 helix_term::ui::picker [DEBUG] picker score 15.854µs
2022-08-23T08:01:20.293 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:20.293 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:20.293 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:20.569 helix_term::ui::picker [DEBUG] picker score 16.902µs
2022-08-23T08:01:20.569 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:20.569 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:20.569 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:20.856 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:20.857 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:20.857 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:20.857 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:21.729 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:21.729 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:21.729 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:22.131 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:22.313 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:22.313 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:22.313 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:22.685 helix_view::editor [DEBUG] editor status: yanked 1 selection(s) to register "
2022-08-23T08:01:22.685 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:22.685 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:22.685 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:22.961 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:22.961 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:22.961 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 3
2022-08-23T08:01:23.308 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:23.308 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:23.308 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:23.709 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:23.921 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:23.921 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:23.921 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:24.064 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:24.064 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:24.064 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:24.173 helix_view::document [DEBUG] submitting save of doc 'Some("/home/bsprague/helix-bug-test/src/mod2.rs")'
2022-08-23T08:01:24.173 helix_view::editor [ERROR] editor error: failed to send save event: channel closed
2022-08-23T08:01:24.173 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:24.173 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:24.173 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:24.323 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:24.541 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:24.541 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:24.541 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:24.785 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:24.785 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:24.785 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:24.845 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:24.845 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:24.845 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:24.888 helix_view::document [DEBUG] submitting save of doc 'Some("/home/bsprague/helix-bug-test/src/mod2.rs")'
2022-08-23T08:01:24.889 helix_view::editor [ERROR] editor error: failed to send save event: channel closed
2022-08-23T08:01:24.889 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:24.889 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:24.889 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:24.942 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:26.349 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:26.349 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:26.349 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:26.497 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:26.497 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:26.497 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:26.569 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:26.569 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:26.569 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:26.750 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:26.792 helix_view::document [DEBUG] submitting save of doc 'Some("/home/bsprague/helix-bug-test/src/mod2.rs")'
2022-08-23T08:01:26.793 helix_view::editor [ERROR] editor error: failed to send save event: channel closed
2022-08-23T08:01:26.793 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:26.793 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:26.793 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:27.481 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:27.481 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:27.481 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:27.737 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:27.737 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:27.737 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:27.873 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:27.873 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:27.873 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:27.913 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:27.913 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:27.913 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:28.008 helix_view::document [DEBUG] submitting save of doc 'Some("/home/bsprague/helix-bug-test/src/mod1.rs")'
2022-08-23T08:01:28.008 helix_view::editor [ERROR] editor error: failed to send save event: channel closed
2022-08-23T08:01:28.008 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:28.009 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:28.009 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:28.138 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:28.529 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:28.529 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:28.529 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:28.889 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:28.889 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:28.889 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:29.217 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:29.217 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:29.217 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:29.433 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:29.433 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:29.433 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:29.834 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:30.061 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:30.061 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:30.061 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:30.349 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:30.349 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:30.350 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:30.504 helix_term::commands::typed [INFO] quitting...
2022-08-23T08:01:30.505 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:30.505 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:30.505 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:30.576 helix_term::commands::typed [INFO] quitting...
2022-08-23T08:01:30.576 helix_term::job [DEBUG] waiting on jobs...
2022-08-23T08:01:30.576 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:30.577 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:30.750 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:31.181 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:31.181 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:31.344 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:31.344 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:31.401 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:31.401 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:31.565 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:31.565 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:31.581 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:31.625 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:31.625 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:31.625 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:31.625 helix_view::document [DEBUG] submitting save of doc 'Some("/home/bsprague/helix-bug-test/src/mod2.rs")'
2022-08-23T08:01:31.625 helix_view::editor [ERROR] editor error: failed to send save event: channel closed
2022-08-23T08:01:31.625 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:31.625 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:32.757 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:32.757 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:32.921 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:32.921 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:33.064 helix_view::editor [ERROR] editor error: no such command: 'a'
2022-08-23T08:01:33.064 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:33.064 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:33.158 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:34.377 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:34.377 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:34.673 helix_term::commands::typed [INFO] quitting...
2022-08-23T08:01:34.673 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:34.673 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:34.778 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:34.972 helix_term::commands::typed [INFO] quitting...
2022-08-23T08:01:34.972 helix_term::job [DEBUG] waiting on jobs...
2022-08-23T08:01:34.973 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:36.049 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:36.185 helix_term::commands::typed [INFO] quitting...
2022-08-23T08:01:36.185 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:36.292 helix_term::commands::typed [INFO] quitting...
2022-08-23T08:01:36.292 helix_view::document [DEBUG] id 2 modified - last saved: 4, current: 4
2022-08-23T08:01:36.292 helix_view::document [DEBUG] id 3 modified - last saved: 0, current: 0
2022-08-23T08:01:36.292 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:36.292 helix_view::document [DEBUG] id 5 modified - last saved: 1, current: 1
2022-08-23T08:01:36.293 helix_view::editor [ERROR] editor error: 1 unsaved buffer(s) remaining: ["src/mod2.rs"]
2022-08-23T08:01:36.293 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:36.449 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:37.033 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:37.232 helix_term::commands::typed [INFO] quitting...
2022-08-23T08:01:37.233 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:37.434 helix_term::application [DEBUG] received editor event: IdleTimer
2022-08-23T08:01:37.444 helix_view::document [DEBUG] id 4 modified - last saved: 3, current: 4
2022-08-23T08:01:37.564 helix_term::job [DEBUG] waiting on jobs...
2022-08-23T08:01:37.565 mio::poll [TRACE] deregistering event source from poller
2022-08-23T08:01:37.565 mio::poll [TRACE] deregistering event source from poller
2022-08-23T08:01:37.565 mio::poll [TRACE] deregistering event source from poller

I'm going to switch back to the main branch in the mean time, with debug symbols + -vvvv so I can provide more info the next time it crashes.

@dead10ck
Copy link
Member

Thanks for running my branch! This is useful, I'll take a look through it.

@bcspragu
Copy link
Contributor Author

bcspragu commented Aug 23, 2022

Legible stack trace, taken at master/HEAD:

$ RUST_BACKTRACE=1 GOPACKAGESDRIVER=$PWD/scripts/gopackagesdriver.sh hx -vvvv

thread 'main' panicked at 'no entry found for key', helix-view/src/document.rs:1006:10
stack backtrace:
   0: rust_begin_unwind
             at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:584:5
   1: core::panicking::panic_fmt
             at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/core/src/panicking.rs:143:14
   2: core::panicking::panic_display
             at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/core/src/panicking.rs:72:5
   3: core::panicking::panic_str
             at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/core/src/panicking.rs:56:5
   4: core::option::expect_failed
             at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/core/src/option.rs:1874:5
   5: helix_view::document::Document::apply
   6: core::ops::function::FnOnce::call_once{{vtable.shim}}
   7: helix_term::job::Jobs::handle_callback
   8: helix_term::application::Application::event_loop_until_idle::{{closure}}
   9: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
  10: std::thread::local::LocalKey<T>::with
  11: tokio::park::thread::CachedParkThread::block_on
  12: tokio::runtime::thread_pool::ThreadPool::block_on
  13: tokio::runtime::Runtime::block_on
  14: hx::main
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

The logs from the session were tens of thousands of lines, so I've trimmed to ~the last minute of logs before the crash:

helix.log
2022-08-23T09:52:25.198 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":38,"line":907},"start":{"character":37,"line":907}},"text":""}],"textDocument":{"uri":"file://<WORKSPACE>/cmd/server/graph/project_resolvers.go","version":1918}}}
2022-08-23T09:52:25.206 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/signatureHelp","params":{"position":{"character":37,"line":907},"textDocument":{"uri":"file://<WORKSPACE>/cmd/server/graph/project_resolvers.go"}},"id":396}
2022-08-23T09:52:25.257 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","result":null,"id":396}
2022-08-23T09:52:25.257 helix_lsp::transport [INFO] <- null
2022-08-23T09:52:25.258 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"window/logMessage","params":{"type":1,"message":"2022/08/23 09:52:25 no signature help: cannot find an enclosing function\n\tposition={907 37}\n"}}
2022-08-23T09:52:25.262 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":37,"line":907},"start":{"character":37,"line":907}},"text":"e"}],"textDocument":{"uri":"file://<WORKSPACE>/cmd/server/graph/project_resolvers.go","version":1919}}}
2022-08-23T09:52:25.269 helix_term::application [INFO] window/logMessage: LogMessageParams { typ: Error, message: "2022/08/23 09:52:25 no signature help: cannot find an enclosing function\n\tposition={907 37}\n" }
2022-08-23T09:52:25.292 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"textDocument/publishDiagnostics","params":{"uri":"file://<WORKSPACE>/cmd/server/graph/project_resolvers.go","version":1919,"diagnostics":[{"range":{"start":{"line":744,"character":46},"end":{"line":744,"character":49}},"severity":1,"code":"IncompatibleAssign","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#IncompatibleAssign"},"source":"compiler","message":"cannot use req (variable of type model.ProjectFieldDiffInput) as *model.ProjectFieldDiffInput value in argument to graphconv.ProjectDiffFromGQL"},{"range":{"start":{"line":751,"character":2},"end":{"line":751,"character":17}},"severity":1,"code":"UnusedVar","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#UnusedVar"},"source":"compiler","message":"newSubresources declared but not used"},{"range":{"start":{"line":771,"character":33},"end":{"line":771,"character":41}},"severity":1,"code":"UndeclaredName","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#UndeclaredName"},"source":"compiler","message":"undeclared name: newDiffs"},{"range":{"start":{"line":907,"character":14},"end":{"line":907,"character":38}},"severity":1,"code":"UndeclaredImportedName","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#UndeclaredImportedName"},"source":"compiler","message":"ProjectFieldDiffActionRe not declared by package adsci"}]}}
2022-08-23T09:52:25.390 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":38,"line":907},"start":{"character":38,"line":907}},"text":"m"}],"textDocument":{"uri":"file://<WORKSPACE>/cmd/server/graph/project_resolvers.go","version":1920}}}
2022-08-23T09:52:25.423 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"textDocument/publishDiagnostics","params":{"uri":"file://<WORKSPACE>/cmd/server/graph/project_resolvers.go","version":1920,"diagnostics":[{"range":{"start":{"line":744,"character":46},"end":{"line":744,"character":49}},"severity":1,"code":"IncompatibleAssign","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#IncompatibleAssign"},"source":"compiler","message":"cannot use req (variable of type model.ProjectFieldDiffInput) as *model.ProjectFieldDiffInput value in argument to graphconv.ProjectDiffFromGQL"},{"range":{"start":{"line":751,"character":2},"end":{"line":751,"character":17}},"severity":1,"code":"UnusedVar","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#UnusedVar"},"source":"compiler","message":"newSubresources declared but not used"},{"range":{"start":{"line":771,"character":33},"end":{"line":771,"character":41}},"severity":1,"code":"UndeclaredName","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#UndeclaredName"},"source":"compiler","message":"undeclared name: newDiffs"},{"range":{"start":{"line":907,"character":14},"end":{"line":907,"character":39}},"severity":1,"code":"UndeclaredImportedName","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#UndeclaredImportedName"},"source":"compiler","message":"ProjectFieldDiffActionRem not declared by package adsci"}]}}
2022-08-23T09:52:25.430 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":39,"line":907},"start":{"character":39,"line":907}},"text":"o"}],"textDocument":{"uri":"file://<WORKSPACE>/cmd/server/graph/project_resolvers.go","version":1921}}}
2022-08-23T09:52:25.460 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"textDocument/publishDiagnostics","params":{"uri":"file://<WORKSPACE>/cmd/server/graph/project_resolvers.go","version":1921,"diagnostics":[{"range":{"start":{"line":744,"character":46},"end":{"line":744,"character":49}},"severity":1,"code":"IncompatibleAssign","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#IncompatibleAssign"},"source":"compiler","message":"cannot use req (variable of type model.ProjectFieldDiffInput) as *model.ProjectFieldDiffInput value in argument to graphconv.ProjectDiffFromGQL"},{"range":{"start":{"line":751,"character":2},"end":{"line":751,"character":17}},"severity":1,"code":"UnusedVar","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#UnusedVar"},"source":"compiler","message":"newSubresources declared but not used"},{"range":{"start":{"line":771,"character":33},"end":{"line":771,"character":41}},"severity":1,"code":"UndeclaredName","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#UndeclaredName"},"source":"compiler","message":"undeclared name: newDiffs"},{"range":{"start":{"line":907,"character":14},"end":{"line":907,"character":40}},"severity":1,"code":"UndeclaredImportedName","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#UndeclaredImportedName"},"source":"compiler","message":"ProjectFieldDiffActionRemo not declared by package adsci"}]}}
2022-08-23T09:52:25.486 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":40,"line":907},"start":{"character":40,"line":907}},"text":"v"}],"textDocument":{"uri":"file://<WORKSPACE>/cmd/server/graph/project_resolvers.go","version":1922}}}
2022-08-23T09:52:25.520 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"textDocument/publishDiagnostics","params":{"uri":"file://<WORKSPACE>/cmd/server/graph/project_resolvers.go","version":1922,"diagnostics":[{"range":{"start":{"line":744,"character":46},"end":{"line":744,"character":49}},"severity":1,"code":"IncompatibleAssign","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#IncompatibleAssign"},"source":"compiler","message":"cannot use req (variable of type model.ProjectFieldDiffInput) as *model.ProjectFieldDiffInput value in argument to graphconv.ProjectDiffFromGQL"},{"range":{"start":{"line":751,"character":2},"end":{"line":751,"character":17}},"severity":1,"code":"UnusedVar","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#UnusedVar"},"source":"compiler","message":"newSubresources declared but not used"},{"range":{"start":{"line":771,"character":33},"end":{"line":771,"character":41}},"severity":1,"code":"UndeclaredName","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#UndeclaredName"},"source":"compiler","message":"undeclared name: newDiffs"},{"range":{"start":{"line":907,"character":14},"end":{"line":907,"character":41}},"severity":1,"code":"UndeclaredImportedName","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#UndeclaredImportedName"},"source":"compiler","message":"ProjectFieldDiffActionRemov not declared by package adsci"}]}}
2022-08-23T09:52:25.542 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":41,"line":907},"start":{"character":41,"line":907}},"text":"e"}],"textDocument":{"uri":"file://<WORKSPACE>/cmd/server/graph/project_resolvers.go","version":1923}}}
2022-08-23T09:52:25.574 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"textDocument/publishDiagnostics","params":{"uri":"file://<WORKSPACE>/cmd/server/graph/project_resolvers.go","version":1923,"diagnostics":[{"range":{"start":{"line":744,"character":46},"end":{"line":744,"character":49}},"severity":1,"code":"IncompatibleAssign","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#IncompatibleAssign"},"source":"compiler","message":"cannot use req (variable of type model.ProjectFieldDiffInput) as *model.ProjectFieldDiffInput value in argument to graphconv.ProjectDiffFromGQL"},{"range":{"start":{"line":751,"character":2},"end":{"line":751,"character":17}},"severity":1,"code":"UnusedVar","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#UnusedVar"},"source":"compiler","message":"newSubresources declared but not used"},{"range":{"start":{"line":771,"character":33},"end":{"line":771,"character":41}},"severity":1,"code":"UndeclaredName","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#UndeclaredName"},"source":"compiler","message":"undeclared name: newDiffs"},{"range":{"start":{"line":907,"character":14},"end":{"line":907,"character":42}},"severity":1,"code":"UndeclaredImportedName","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#UndeclaredImportedName"},"source":"compiler","message":"ProjectFieldDiffActionRemove not declared by package adsci"}]}}
2022-08-23T09:52:25.828 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"window/logMessage","params":{"type":1,"message":"2022/08/23 09:52:25 tidy: diagnosing file://<WORKSPACE>/go.mod: err: exit status 1: stderr: go: finding module for package github.com/golang-jwt/jwt\ngo: finding module for package github.com/<PROJECT1>/api/v2\ngo: finding module for package github.com/<PROJECT2>/cmd/server/graph/generated\ngo: finding module for package github.com/bazelbuild/rules_go/go/tools/bazel\ngo: finding module for package github.com/<PROJECT2>/cmd/server/graph/model\ngithub.com/<PROJECT2>/blobs/blobsrv imports\n\tgithub.com/<PROJECT1>/api/v2: cannot find module providing package github.com/<PROJECT1>/api/v2: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/cmd/server imports\n\tgithub.com/<PROJECT2>/cmd/server/graph/generated: cannot find module providing package github.com/<PROJECT2>/cmd/server/graph/generated: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/cmd/server/graph imports\n\tgithub.com/<PROJECT2>/cmd/server/graph/model: cannot find module providing package github.com/<PROJECT2>/cmd/server/graph/model: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/db/sqldb/migrate imports\n\tgithub.com/bazelbuild/rules_go/go/tools/bazel: cannot find module providing package github.com/bazelbuild/rules_go/go/tools/bazel: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/authn/session tested by\n\tgithub.com/<PROJECT2>/authn/session.test imports\n\tgithub.com/golang-jwt/jwt: cannot find module providing package github.com/golang-jwt/jwt: module lookup disabled by GOPROXY=off\n\n"}}
2022-08-23T09:52:25.828 helix_term::application [INFO] window/logMessage: LogMessageParams { typ: Error, message: "2022/08/23 09:52:25 tidy: diagnosing file://<WORKSPACE>/go.mod: err: exit status 1: stderr: go: finding module for package github.com/golang-jwt/jwt\ngo: finding module for package github.com/<PROJECT1>/api/v2\ngo: finding module for package github.com/<PROJECT2>/cmd/server/graph/generated\ngo: finding module for package github.com/bazelbuild/rules_go/go/tools/bazel\ngo: finding module for package github.com/<PROJECT2>/cmd/server/graph/model\ngithub.com/<PROJECT2>/blobs/blobsrv imports\n\tgithub.com/<PROJECT1>/api/v2: cannot find module providing package github.com/<PROJECT1>/api/v2: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/cmd/server imports\n\tgithub.com/<PROJECT2>/cmd/server/graph/generated: cannot find module providing package github.com/<PROJECT2>/cmd/server/graph/generated: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/cmd/server/graph imports\n\tgithub.com/<PROJECT2>/cmd/server/graph/model: cannot find module providing package github.com/<PROJECT2>/cmd/server/graph/model: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/db/sqldb/migrate imports\n\tgithub.com/bazelbuild/rules_go/go/tools/bazel: cannot find module providing package github.com/bazelbuild/rules_go/go/tools/bazel: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/authn/session tested by\n\tgithub.com/<PROJECT2>/authn/session.test imports\n\tgithub.com/golang-jwt/jwt: cannot find module providing package github.com/golang-jwt/jwt: module lookup disabled by GOPROXY=off\n\n" }
2022-08-23T09:52:27.825 globset [DEBUG] glob converted to regex: Glob { glob: "*.{zip,gz,bz2,zst,lzo,sz,tgz,tbz2,lz,lz4,lzma,lzo,z,Z,xz,7z,rar,cab}", re: "(?-u)^[^/]*\\.(cab|rar|7z|xz|Z|z|lzo|lzma|lz4|lz|tbz2|tgz|sz|lzo|zst|bz2|gz|zip)$", opts: GlobOptions { case_insensitive: false, literal_separator: true, backslash_escape: true }, tokens: Tokens([ZeroOrMore, Literal('.'), Alternates([Tokens([Literal('c'), Literal('a'), Literal('b')]), Tokens([Literal('r'), Literal('a'), Literal('r')]), Tokens([Literal('7'), Literal('z')]), Tokens([Literal('x'), Literal('z')]), Tokens([Literal('Z')]), Tokens([Literal('z')]), Tokens([Literal('l'), Literal('z'), Literal('o')]), Tokens([Literal('l'), Literal('z'), Literal('m'), Literal('a')]), Tokens([Literal('l'), Literal('z'), Literal('4')]), Tokens([Literal('l'), Literal('z')]), Tokens([Literal('t'), Literal('b'), Literal('z'), Literal('2')]), Tokens([Literal('t'), Literal('g'), Literal('z')]), Tokens([Literal('s'), Literal('z')]), Tokens([Literal('l'), Literal('z'), Literal('o')]), Tokens([Literal('z'), Literal('s'), Literal('t')]), Tokens([Literal('b'), Literal('z'), Literal('2')]), Tokens([Literal('g'), Literal('z')]), Tokens([Literal('z'), Literal('i'), Literal('p')])])]) }
2022-08-23T09:52:27.825 globset [DEBUG] built glob set; 0 literals, 0 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 1 regexes
2022-08-23T09:52:27.826 globset [DEBUG] built glob set; 0 literals, 5 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 0 regexes
2022-08-23T09:52:27.826 ignore::walk [DEBUG] ignoring <WORKSPACE>/bazel-out: Ignore(IgnoreMatch(Gitignore(Glob { from: Some("<WORKSPACE>/.gitignore"), original: "bazel-out", actual: "**/bazel-out", is_whitelist: false, is_only_dir: false })))
2022-08-23T09:52:27.827 ignore::walk [DEBUG] ignoring <WORKSPACE>/.bazelrc: Ignore(IgnoreMatch(Hidden))
2022-08-23T09:52:27.827 ignore::walk [DEBUG] ignoring <WORKSPACE>/.vscode: Ignore(IgnoreMatch(Hidden))
2022-08-23T09:52:27.827 globset [DEBUG] built glob set; 0 literals, 9 basenames, 1 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 0 regexes
2022-08-23T09:52:27.828 globset [DEBUG] built glob set; 0 literals, 1 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 0 regexes
2022-08-23T09:52:27.828 ignore::walk [DEBUG] ignoring <WORKSPACE>/frontend/accessibility/.gitignore: Ignore(IgnoreMatch(Hidden))
2022-08-23T09:52:27.829 ignore::walk [DEBUG] ignoring <WORKSPACE>/frontend/.jest: Ignore(IgnoreMatch(Hidden))
2022-08-23T09:52:27.829 ignore::walk [DEBUG] ignoring <WORKSPACE>/frontend/.gitignore: Ignore(IgnoreMatch(Hidden))
2022-08-23T09:52:27.829 ignore::walk [DEBUG] ignoring <WORKSPACE>/frontend/.eslintrc.json: Ignore(IgnoreMatch(Hidden))
2022-08-23T09:52:27.831 ignore::walk [DEBUG] ignoring <WORKSPACE>/frontend/.stylelintrc.json: Ignore(IgnoreMatch(Hidden))
2022-08-23T09:52:27.832 ignore::walk [DEBUG] ignoring <WORKSPACE>/frontend/.firebase: Ignore(IgnoreMatch(Gitignore(Glob { from: Some("<WORKSPACE>/frontend/.gitignore"), original: ".firebase", actual: "**/.firebase", is_whitelist: false, is_only_dir: false })))
2022-08-23T09:52:27.832 ignore::walk [DEBUG] ignoring <WORKSPACE>/frontend/.nuxt: Ignore(IgnoreMatch(Gitignore(Glob { from: Some("<WORKSPACE>/frontend/.gitignore"), original: ".nuxt", actual: "**/.nuxt", is_whitelist: false, is_only_dir: false })))
2022-08-23T09:52:27.832 ignore::walk [DEBUG] ignoring <WORKSPACE>/frontend/node_modules: Ignore(IgnoreMatch(Gitignore(Glob { from: Some("<WORKSPACE>/frontend/.gitignore"), original: "node_modules", actual: "**/node_modules", is_whitelist: false, is_only_dir: false })))
2022-08-23T09:52:27.832 ignore::walk [DEBUG] ignoring <WORKSPACE>/frontend/.output: Ignore(IgnoreMatch(Gitignore(Glob { from: Some("<WORKSPACE>/frontend/.gitignore"), original: ".output", actual: "**/.output", is_whitelist: false, is_only_dir: false })))
2022-08-23T09:52:27.832 ignore::walk [DEBUG] ignoring <WORKSPACE>/frontend/ui-debug.log: Ignore(IgnoreMatch(Gitignore(Glob { from: Some("<WORKSPACE>/frontend/.gitignore"), original: "*.log", actual: "**/*.log", is_whitelist: false, is_only_dir: false })))
2022-08-23T09:52:27.832 ignore::walk [DEBUG] ignoring <WORKSPACE>/.gitattributes: Ignore(IgnoreMatch(Hidden))
2022-08-23T09:52:27.832 ignore::walk [DEBUG] ignoring <WORKSPACE>/.gitignore: Ignore(IgnoreMatch(Hidden))
2022-08-23T09:52:27.832 ignore::walk [DEBUG] ignoring <WORKSPACE>/.bazelversion: Ignore(IgnoreMatch(Hidden))
2022-08-23T09:52:27.833 globset [DEBUG] built glob set; 0 literals, 3 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 0 regexes
2022-08-23T09:52:27.833 ignore::walk [DEBUG] ignoring <WORKSPACE>/emails/.gitignore: Ignore(IgnoreMatch(Hidden))
2022-08-23T09:52:27.833 ignore::walk [DEBUG] ignoring <WORKSPACE>/emails/.bazelignore: Ignore(IgnoreMatch(Hidden))
2022-08-23T09:52:27.833 ignore::walk [DEBUG] ignoring <WORKSPACE>/.postgres-data: Ignore(IgnoreMatch(Gitignore(Glob { from: Some("<WORKSPACE>/.gitignore"), original: ".postgres-data", actual: "**/.postgres-data", is_whitelist: false, is_only_dir: false })))
2022-08-23T09:52:27.833 ignore::walk [DEBUG] ignoring <WORKSPACE>/bazel-<REMOVED>: Ignore(IgnoreMatch(Gitignore(Glob { from: Some("<WORKSPACE>/.gitignore"), original: "bazel-<REMOVED>", actual: "**/bazel-<REMOVED>", is_whitelist: false, is_only_dir: false })))
2022-08-23T09:52:27.833 globset [DEBUG] built glob set; 0 literals, 5 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 0 regexes
2022-08-23T09:52:27.834 ignore::walk [DEBUG] ignoring <WORKSPACE>/.bazelignore: Ignore(IgnoreMatch(Hidden))
2022-08-23T09:52:27.834 ignore::walk [DEBUG] ignoring <WORKSPACE>/bazel-bin: Ignore(IgnoreMatch(Gitignore(Glob { from: Some("<WORKSPACE>/.gitignore"), original: "bazel-bin", actual: "**/bazel-bin", is_whitelist: false, is_only_dir: false })))
2022-08-23T09:52:27.835 ignore::walk [DEBUG] ignoring <WORKSPACE>/.sops.yaml: Ignore(IgnoreMatch(Hidden))
2022-08-23T09:52:27.835 globset [DEBUG] built glob set; 0 literals, 2 basenames, 0 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 0 regexes
2022-08-23T09:52:27.835 ignore::walk [DEBUG] ignoring <WORKSPACE>/terraform/.terraform: Ignore(IgnoreMatch(Gitignore(Glob { from: Some("<WORKSPACE>/terraform/.gitignore"), original: ".terraform/", actual: "**/.terraform", is_whitelist: false, is_only_dir: true })))
2022-08-23T09:52:27.835 ignore::walk [DEBUG] ignoring <WORKSPACE>/terraform/.gitignore: Ignore(IgnoreMatch(Hidden))
2022-08-23T09:52:27.835 ignore::walk [DEBUG] ignoring <WORKSPACE>/terraform/shared/.terraform: Ignore(IgnoreMatch(Gitignore(Glob { from: Some("<WORKSPACE>/terraform/.gitignore"), original: ".terraform/", actual: "**/.terraform", is_whitelist: false, is_only_dir: true })))
2022-08-23T09:52:27.835 ignore::walk [DEBUG] ignoring <WORKSPACE>/terraform/shared/.terraform.lock.hcl: Ignore(IgnoreMatch(Gitignore(Glob { from: Some("<WORKSPACE>/terraform/.gitignore"), original: ".terraform.lock.hcl", actual: "**/.terraform.lock.hcl", is_whitelist: false, is_only_dir: false })))
2022-08-23T09:52:27.835 ignore::walk [DEBUG] ignoring <WORKSPACE>/terraform/.terraform.lock.hcl: Ignore(IgnoreMatch(Gitignore(Glob { from: Some("<WORKSPACE>/terraform/.gitignore"), original: ".terraform.lock.hcl", actual: "**/.terraform.lock.hcl", is_whitelist: false, is_only_dir: false })))
2022-08-23T09:52:27.835 ignore::walk [DEBUG] ignoring <WORKSPACE>/.github: Ignore(IgnoreMatch(Hidden))
2022-08-23T09:52:27.836 ignore::walk [DEBUG] ignoring <WORKSPACE>/.git: Ignore(IgnoreMatch(Hidden))
2022-08-23T09:52:27.837 ignore::walk [DEBUG] ignoring <WORKSPACE>/.nvmrc: Ignore(IgnoreMatch(Hidden))
2022-08-23T09:52:27.837 ignore::walk [DEBUG] ignoring <WORKSPACE>/bazel-testlogs: Ignore(IgnoreMatch(Gitignore(Glob { from: Some("<WORKSPACE>/.gitignore"), original: "bazel-testlogs", actual: "**/bazel-testlogs", is_whitelist: false, is_only_dir: false })))
2022-08-23T09:52:27.837 helix_term::ui [DEBUG] file_picker init 11.953751ms
2022-08-23T09:52:28.084 helix_term::ui::picker [DEBUG] picker score 2.832971ms
2022-08-23T09:52:28.331 helix_term::ui::picker [DEBUG] picker score 2.369156ms
2022-08-23T09:52:28.503 helix_term::ui::picker [DEBUG] picker score 1.589168ms
2022-08-23T09:52:28.558 helix_term::ui::picker [DEBUG] picker score 1.028273ms
2022-08-23T09:52:28.633 helix_term::ui::picker [DEBUG] picker score 526.114µs
2022-08-23T09:52:35.463 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":0,"line":141},"start":{"character":0,"line":141}},"text":"\tProjectFieldDiffActionAdd                = ProjectFieldDiffAction(\"ADD\")\n"}],"textDocument":{"uri":"file://<WORKSPACE>/adsci/adsci.go","version":10}}}
2022-08-23T09:52:35.474 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"textDocument/publishDiagnostics","params":{"uri":"file://<WORKSPACE>/adsci/adsci.go","version":10,"diagnostics":[{"range":{"start":{"line":140,"character":1},"end":{"line":140,"character":26}},"severity":1,"code":"DuplicateDecl","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#DuplicateDecl"},"source":"compiler","message":"ProjectFieldDiffActionAdd redeclared in this block (this error: other declaration of ProjectFieldDiffActionAdd)","relatedInformation":[{"location":{"uri":"file://<WORKSPACE>/adsci/adsci.go","range":{"start":{"line":141,"character":1},"end":{"line":141,"character":26}}},"message":"ProjectFieldDiffActionAdd redeclared in this block"},{"location":{"uri":"file://<WORKSPACE>/adsci/adsci.go","range":{"start":{"line":140,"character":1},"end":{"line":140,"character":26}}},"message":"other declaration of ProjectFieldDiffActionAdd (this error)"}]},{"range":{"start":{"line":141,"character":1},"end":{"line":141,"character":26}},"severity":1,"code":"DuplicateDecl","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#DuplicateDecl"},"source":"compiler","message":"ProjectFieldDiffActionAdd redeclared in this block","relatedInformation":[{"location":{"uri":"file://<WORKSPACE>/adsci/adsci.go","range":{"start":{"line":140,"character":1},"end":{"line":140,"character":26}}},"message":"other declaration of ProjectFieldDiffActionAdd"}]}]}}
2022-08-23T09:52:35.792 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"window/logMessage","params":{"type":1,"message":"2022/08/23 09:52:35 tidy: diagnosing file://<WORKSPACE>/go.mod: err: exit status 1: stderr: go: finding module for package github.com/golang-jwt/jwt\ngo: finding module for package github.com/<PROJECT1>/api/v2\ngo: finding module for package github.com/<PROJECT2>/cmd/server/graph/generated\ngo: finding module for package github.com/bazelbuild/rules_go/go/tools/bazel\ngo: finding module for package github.com/<PROJECT2>/cmd/server/graph/model\ngithub.com/<PROJECT2>/blobs/blobsrv imports\n\tgithub.com/<PROJECT1>/api/v2: cannot find module providing package github.com/<PROJECT1>/api/v2: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/cmd/server imports\n\tgithub.com/<PROJECT2>/cmd/server/graph/generated: cannot find module providing package github.com/<PROJECT2>/cmd/server/graph/generated: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/cmd/server/graph imports\n\tgithub.com/<PROJECT2>/cmd/server/graph/model: cannot find module providing package github.com/<PROJECT2>/cmd/server/graph/model: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/db/sqldb/migrate imports\n\tgithub.com/bazelbuild/rules_go/go/tools/bazel: cannot find module providing package github.com/bazelbuild/rules_go/go/tools/bazel: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/authn/session tested by\n\tgithub.com/<PROJECT2>/authn/session.test imports\n\tgithub.com/golang-jwt/jwt: cannot find module providing package github.com/golang-jwt/jwt: module lookup disabled by GOPROXY=off\n\n"}}
2022-08-23T09:52:35.792 helix_term::application [INFO] window/logMessage: LogMessageParams { typ: Error, message: "2022/08/23 09:52:35 tidy: diagnosing file://<WORKSPACE>/go.mod: err: exit status 1: stderr: go: finding module for package github.com/golang-jwt/jwt\ngo: finding module for package github.com/<PROJECT1>/api/v2\ngo: finding module for package github.com/<PROJECT2>/cmd/server/graph/generated\ngo: finding module for package github.com/bazelbuild/rules_go/go/tools/bazel\ngo: finding module for package github.com/<PROJECT2>/cmd/server/graph/model\ngithub.com/<PROJECT2>/blobs/blobsrv imports\n\tgithub.com/<PROJECT1>/api/v2: cannot find module providing package github.com/<PROJECT1>/api/v2: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/cmd/server imports\n\tgithub.com/<PROJECT2>/cmd/server/graph/generated: cannot find module providing package github.com/<PROJECT2>/cmd/server/graph/generated: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/cmd/server/graph imports\n\tgithub.com/<PROJECT2>/cmd/server/graph/model: cannot find module providing package github.com/<PROJECT2>/cmd/server/graph/model: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/db/sqldb/migrate imports\n\tgithub.com/bazelbuild/rules_go/go/tools/bazel: cannot find module providing package github.com/bazelbuild/rules_go/go/tools/bazel: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/authn/session tested by\n\tgithub.com/<PROJECT2>/authn/session.test imports\n\tgithub.com/golang-jwt/jwt: cannot find module providing package github.com/golang-jwt/jwt: module lookup disabled by GOPROXY=off\n\n" }
2022-08-23T09:52:37.771 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":71,"line":141},"start":{"character":68,"line":141}},"text":""}],"textDocument":{"uri":"file://<WORKSPACE>/adsci/adsci.go","version":11}}}
2022-08-23T09:52:37.778 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/signatureHelp","params":{"position":{"character":68,"line":141},"textDocument":{"uri":"file://<WORKSPACE>/adsci/adsci.go"}},"id":397}
2022-08-23T09:52:37.780 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","result":null,"id":397}
2022-08-23T09:52:37.780 helix_lsp::transport [INFO] <- null
2022-08-23T09:52:37.780 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"window/logMessage","params":{"type":1,"message":"2022/08/23 09:52:37 no signature help: no signature help within a string literal\n\tposition={141 68}\n"}}
2022-08-23T09:52:37.787 helix_term::application [INFO] window/logMessage: LogMessageParams { typ: Error, message: "2022/08/23 09:52:37 no signature help: no signature help within a string literal\n\tposition={141 68}\n" }
2022-08-23T09:52:38.100 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"window/logMessage","params":{"type":1,"message":"2022/08/23 09:52:38 tidy: diagnosing file://<WORKSPACE>/go.mod: err: exit status 1: stderr: go: finding module for package github.com/golang-jwt/jwt\ngo: finding module for package github.com/<PROJECT1>/api/v2\ngo: finding module for package github.com/<PROJECT2>/cmd/server/graph/generated\ngo: finding module for package github.com/bazelbuild/rules_go/go/tools/bazel\ngo: finding module for package github.com/<PROJECT2>/cmd/server/graph/model\ngithub.com/<PROJECT2>/blobs/blobsrv imports\n\tgithub.com/<PROJECT1>/api/v2: cannot find module providing package github.com/<PROJECT1>/api/v2: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/cmd/server imports\n\tgithub.com/<PROJECT2>/cmd/server/graph/generated: cannot find module providing package github.com/<PROJECT2>/cmd/server/graph/generated: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/cmd/server/graph imports\n\tgithub.com/<PROJECT2>/cmd/server/graph/model: cannot find module providing package github.com/<PROJECT2>/cmd/server/graph/model: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/db/sqldb/migrate imports\n\tgithub.com/bazelbuild/rules_go/go/tools/bazel: cannot find module providing package github.com/bazelbuild/rules_go/go/tools/bazel: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/authn/session tested by\n\tgithub.com/<PROJECT2>/authn/session.test imports\n\tgithub.com/golang-jwt/jwt: cannot find module providing package github.com/golang-jwt/jwt: module lookup disabled by GOPROXY=off\n\n"}}
2022-08-23T09:52:38.100 helix_term::application [INFO] window/logMessage: LogMessageParams { typ: Error, message: "2022/08/23 09:52:38 tidy: diagnosing file://<WORKSPACE>/go.mod: err: exit status 1: stderr: go: finding module for package github.com/golang-jwt/jwt\ngo: finding module for package github.com/<PROJECT1>/api/v2\ngo: finding module for package github.com/<PROJECT2>/cmd/server/graph/generated\ngo: finding module for package github.com/bazelbuild/rules_go/go/tools/bazel\ngo: finding module for package github.com/<PROJECT2>/cmd/server/graph/model\ngithub.com/<PROJECT2>/blobs/blobsrv imports\n\tgithub.com/<PROJECT1>/api/v2: cannot find module providing package github.com/<PROJECT1>/api/v2: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/cmd/server imports\n\tgithub.com/<PROJECT2>/cmd/server/graph/generated: cannot find module providing package github.com/<PROJECT2>/cmd/server/graph/generated: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/cmd/server/graph imports\n\tgithub.com/<PROJECT2>/cmd/server/graph/model: cannot find module providing package github.com/<PROJECT2>/cmd/server/graph/model: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/db/sqldb/migrate imports\n\tgithub.com/bazelbuild/rules_go/go/tools/bazel: cannot find module providing package github.com/bazelbuild/rules_go/go/tools/bazel: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/authn/session tested by\n\tgithub.com/<PROJECT2>/authn/session.test imports\n\tgithub.com/golang-jwt/jwt: cannot find module providing package github.com/golang-jwt/jwt: module lookup disabled by GOPROXY=off\n\n" }
2022-08-23T09:52:38.115 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":68,"line":141},"start":{"character":68,"line":141}},"text":"R"}],"textDocument":{"uri":"file://<WORKSPACE>/adsci/adsci.go","version":12}}}
2022-08-23T09:52:38.391 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":69,"line":141},"start":{"character":69,"line":141}},"text":"E"}],"textDocument":{"uri":"file://<WORKSPACE>/adsci/adsci.go","version":13}}}
2022-08-23T09:52:38.519 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":70,"line":141},"start":{"character":70,"line":141}},"text":"M"}],"textDocument":{"uri":"file://<WORKSPACE>/adsci/adsci.go","version":14}}}
2022-08-23T09:52:38.571 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":71,"line":141},"start":{"character":71,"line":141}},"text":"O"}],"textDocument":{"uri":"file://<WORKSPACE>/adsci/adsci.go","version":15}}}
2022-08-23T09:52:38.603 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":72,"line":141},"start":{"character":72,"line":141}},"text":"V"}],"textDocument":{"uri":"file://<WORKSPACE>/adsci/adsci.go","version":16}}}
2022-08-23T09:52:38.676 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":73,"line":141},"start":{"character":73,"line":141}},"text":"E"}],"textDocument":{"uri":"file://<WORKSPACE>/adsci/adsci.go","version":17}}}
2022-08-23T09:52:38.964 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"window/logMessage","params":{"type":1,"message":"2022/08/23 09:52:38 tidy: diagnosing file://<WORKSPACE>/go.mod: err: exit status 1: stderr: go: finding module for package github.com/golang-jwt/jwt\ngo: finding module for package github.com/<PROJECT1>/api/v2\ngo: finding module for package github.com/<PROJECT2>/cmd/server/graph/generated\ngo: finding module for package github.com/bazelbuild/rules_go/go/tools/bazel\ngo: finding module for package github.com/<PROJECT2>/cmd/server/graph/model\ngithub.com/<PROJECT2>/blobs/blobsrv imports\n\tgithub.com/<PROJECT1>/api/v2: cannot find module providing package github.com/<PROJECT1>/api/v2: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/cmd/server imports\n\tgithub.com/<PROJECT2>/cmd/server/graph/generated: cannot find module providing package github.com/<PROJECT2>/cmd/server/graph/generated: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/cmd/server/graph imports\n\tgithub.com/<PROJECT2>/cmd/server/graph/model: cannot find module providing package github.com/<PROJECT2>/cmd/server/graph/model: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/db/sqldb/migrate imports\n\tgithub.com/bazelbuild/rules_go/go/tools/bazel: cannot find module providing package github.com/bazelbuild/rules_go/go/tools/bazel: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/authn/session tested by\n\tgithub.com/<PROJECT2>/authn/session.test imports\n\tgithub.com/golang-jwt/jwt: cannot find module providing package github.com/golang-jwt/jwt: module lookup disabled by GOPROXY=off\n\n"}}
2022-08-23T09:52:38.964 helix_term::application [INFO] window/logMessage: LogMessageParams { typ: Error, message: "2022/08/23 09:52:38 tidy: diagnosing file://<WORKSPACE>/go.mod: err: exit status 1: stderr: go: finding module for package github.com/golang-jwt/jwt\ngo: finding module for package github.com/<PROJECT1>/api/v2\ngo: finding module for package github.com/<PROJECT2>/cmd/server/graph/generated\ngo: finding module for package github.com/bazelbuild/rules_go/go/tools/bazel\ngo: finding module for package github.com/<PROJECT2>/cmd/server/graph/model\ngithub.com/<PROJECT2>/blobs/blobsrv imports\n\tgithub.com/<PROJECT1>/api/v2: cannot find module providing package github.com/<PROJECT1>/api/v2: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/cmd/server imports\n\tgithub.com/<PROJECT2>/cmd/server/graph/generated: cannot find module providing package github.com/<PROJECT2>/cmd/server/graph/generated: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/cmd/server/graph imports\n\tgithub.com/<PROJECT2>/cmd/server/graph/model: cannot find module providing package github.com/<PROJECT2>/cmd/server/graph/model: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/db/sqldb/migrate imports\n\tgithub.com/bazelbuild/rules_go/go/tools/bazel: cannot find module providing package github.com/bazelbuild/rules_go/go/tools/bazel: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/authn/session tested by\n\tgithub.com/<PROJECT2>/authn/session.test imports\n\tgithub.com/golang-jwt/jwt: cannot find module providing package github.com/golang-jwt/jwt: module lookup disabled by GOPROXY=off\n\n" }
2022-08-23T09:52:41.323 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":26,"line":141},"start":{"character":23,"line":141}},"text":""}],"textDocument":{"uri":"file://<WORKSPACE>/adsci/adsci.go","version":18}}}
2022-08-23T09:52:41.330 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/signatureHelp","params":{"position":{"character":23,"line":141},"textDocument":{"uri":"file://<WORKSPACE>/adsci/adsci.go"}},"id":398}
2022-08-23T09:52:41.331 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"textDocument/publishDiagnostics","params":{"uri":"file://<WORKSPACE>/adsci/adsci.go","version":18,"diagnostics":[{"range":{"start":{"line":135,"character":5},"end":{"line":135,"character":27}},"severity":1,"code":"DuplicateDecl","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#DuplicateDecl"},"source":"compiler","message":"ProjectFieldDiffAction redeclared in this block (this error: other declaration of ProjectFieldDiffAction)","relatedInformation":[{"location":{"uri":"file://<WORKSPACE>/adsci/adsci.go","range":{"start":{"line":141,"character":1},"end":{"line":141,"character":23}}},"message":"ProjectFieldDiffAction redeclared in this block"},{"location":{"uri":"file://<WORKSPACE>/adsci/adsci.go","range":{"start":{"line":135,"character":5},"end":{"line":135,"character":27}}},"message":"other declaration of ProjectFieldDiffAction (this error)"}]},{"range":{"start":{"line":141,"character":1},"end":{"line":141,"character":23}},"severity":1,"code":"DuplicateDecl","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#DuplicateDecl"},"source":"compiler","message":"ProjectFieldDiffAction redeclared in this block","relatedInformation":[{"location":{"uri":"file://<WORKSPACE>/adsci/adsci.go","range":{"start":{"line":135,"character":5},"end":{"line":135,"character":27}}},"message":"other declaration of ProjectFieldDiffAction"}]}]}}
2022-08-23T09:52:41.331 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","result":null,"id":398}
2022-08-23T09:52:41.331 helix_lsp::transport [INFO] <- null
2022-08-23T09:52:41.331 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"window/logMessage","params":{"type":1,"message":"2022/08/23 09:52:41 no signature help: cannot find an enclosing function\n\tposition={141 23}\n"}}
2022-08-23T09:52:41.338 helix_term::application [INFO] window/logMessage: LogMessageParams { typ: Error, message: "2022/08/23 09:52:41 no signature help: cannot find an enclosing function\n\tposition={141 23}\n" }
2022-08-23T09:52:41.646 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"window/logMessage","params":{"type":1,"message":"2022/08/23 09:52:41 tidy: diagnosing file://<WORKSPACE>/go.mod: err: exit status 1: stderr: go: finding module for package github.com/golang-jwt/jwt\ngo: finding module for package github.com/<PROJECT1>/api/v2\ngo: finding module for package github.com/<PROJECT2>/cmd/server/graph/generated\ngo: finding module for package github.com/bazelbuild/rules_go/go/tools/bazel\ngo: finding module for package github.com/<PROJECT2>/cmd/server/graph/model\ngithub.com/<PROJECT2>/blobs/blobsrv imports\n\tgithub.com/<PROJECT1>/api/v2: cannot find module providing package github.com/<PROJECT1>/api/v2: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/cmd/server imports\n\tgithub.com/<PROJECT2>/cmd/server/graph/generated: cannot find module providing package github.com/<PROJECT2>/cmd/server/graph/generated: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/cmd/server/graph imports\n\tgithub.com/<PROJECT2>/cmd/server/graph/model: cannot find module providing package github.com/<PROJECT2>/cmd/server/graph/model: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/db/sqldb/migrate imports\n\tgithub.com/bazelbuild/rules_go/go/tools/bazel: cannot find module providing package github.com/bazelbuild/rules_go/go/tools/bazel: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/authn/session tested by\n\tgithub.com/<PROJECT2>/authn/session.test imports\n\tgithub.com/golang-jwt/jwt: cannot find module providing package github.com/golang-jwt/jwt: module lookup disabled by GOPROXY=off\n\n"}}
2022-08-23T09:52:41.646 helix_term::application [INFO] window/logMessage: LogMessageParams { typ: Error, message: "2022/08/23 09:52:41 tidy: diagnosing file://<WORKSPACE>/go.mod: err: exit status 1: stderr: go: finding module for package github.com/golang-jwt/jwt\ngo: finding module for package github.com/<PROJECT1>/api/v2\ngo: finding module for package github.com/<PROJECT2>/cmd/server/graph/generated\ngo: finding module for package github.com/bazelbuild/rules_go/go/tools/bazel\ngo: finding module for package github.com/<PROJECT2>/cmd/server/graph/model\ngithub.com/<PROJECT2>/blobs/blobsrv imports\n\tgithub.com/<PROJECT1>/api/v2: cannot find module providing package github.com/<PROJECT1>/api/v2: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/cmd/server imports\n\tgithub.com/<PROJECT2>/cmd/server/graph/generated: cannot find module providing package github.com/<PROJECT2>/cmd/server/graph/generated: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/cmd/server/graph imports\n\tgithub.com/<PROJECT2>/cmd/server/graph/model: cannot find module providing package github.com/<PROJECT2>/cmd/server/graph/model: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/db/sqldb/migrate imports\n\tgithub.com/bazelbuild/rules_go/go/tools/bazel: cannot find module providing package github.com/bazelbuild/rules_go/go/tools/bazel: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/authn/session tested by\n\tgithub.com/<PROJECT2>/authn/session.test imports\n\tgithub.com/golang-jwt/jwt: cannot find module providing package github.com/golang-jwt/jwt: module lookup disabled by GOPROXY=off\n\n" }
2022-08-23T09:52:41.729 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/completion","params":{"position":{"character":23,"line":141},"textDocument":{"uri":"file://<WORKSPACE>/adsci/adsci.go"}},"id":399}
2022-08-23T09:52:41.755 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":23,"line":141},"start":{"character":23,"line":141}},"text":"R"}],"textDocument":{"uri":"file://<WORKSPACE>/adsci/adsci.go","version":19}}}
2022-08-23T09:52:41.830 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","result":{"isIncomplete":true,"itemDefaults":{"editRange":{"start":{"line":0,"character":0},"end":{"line":0,"character":0}}},"items":[{"label":"ProjectFieldDiffAction","labelDetails":{},"kind":7,"detail":"string","preselect":true,"sortText":"00000","filterText":"ProjectFieldDiffAction","insertTextFormat":1,"textEdit":{"range":{"start":{"line":141,"character":1},"end":{"line":141,"character":23}},"newText":"ProjectFieldDiffAction"}},{"label":"ProjectFieldDiffActionAdd","labelDetails":{},"kind":21,"detail":"ProjectFieldDiffAction","sortText":"00001","filterText":"ProjectFieldDiffActionAdd","insertTextFormat":1,"textEdit":{"range":{"start":{"line":141,"character":1},"end":{"line":141,"character":23}},"newText":"ProjectFieldDiffActionAdd"}},{"label":"ProjectFieldDiffActionClear","labelDetails":{},"kind":21,"detail":"ProjectFieldDiffAction","sortText":"00002","filterText":"ProjectFieldDiffActionClear","insertTextFormat":1,"textEdit":{"range":{"start":{"line":141,"character":1},"end":{"line":141,"character":23}},"newText":"ProjectFieldDiffActionClear"}},{"label":"ProjectFieldDiffActionReplaceSubresource","labelDetails":{},"kind":21,"detail":"ProjectFieldDiffAction","sortText":"00003","filterText":"ProjectFieldDiffActionReplaceSubresource","insertTextFormat":1,"textEdit":{"range":{"start":{"line":141,"character":1},"end":{"line":141,"character":23}},"newText":"ProjectFieldDiffActionReplaceSubresource"}},{"label":"ProjectFieldDiffActionSet","labelDetails":{},"kind":21,"detail":"ProjectFieldDiffAction","sortText":"00004","filterText":"ProjectFieldDiffActionSet","insertTextFormat":1,"textEdit":{"range":{"start":{"line":141,"character":1},"end":{"line":141,"character":23}},"newText":"ProjectFieldDiffActionSet"}}]},"id":399}
2022-08-23T09:52:41.830 helix_lsp::transport [INFO] <- {"isIncomplete":true,"itemDefaults":{"editRange":{"end":{"character":0,"line":0},"start":{"character":0,"line":0}}},"items":[{"detail":"string","filterText":"ProjectFieldDiffAction","insertTextFormat":1,"kind":7,"label":"ProjectFieldDiffAction","labelDetails":{},"preselect":true,"sortText":"00000","textEdit":{"newText":"ProjectFieldDiffAction","range":{"end":{"character":23,"line":141},"start":{"character":1,"line":141}}}},{"detail":"ProjectFieldDiffAction","filterText":"ProjectFieldDiffActionAdd","insertTextFormat":1,"kind":21,"label":"ProjectFieldDiffActionAdd","labelDetails":{},"sortText":"00001","textEdit":{"newText":"ProjectFieldDiffActionAdd","range":{"end":{"character":23,"line":141},"start":{"character":1,"line":141}}}},{"detail":"ProjectFieldDiffAction","filterText":"ProjectFieldDiffActionClear","insertTextFormat":1,"kind":21,"label":"ProjectFieldDiffActionClear","labelDetails":{},"sortText":"00002","textEdit":{"newText":"ProjectFieldDiffActionClear","range":{"end":{"character":23,"line":141},"start":{"character":1,"line":141}}}},{"detail":"ProjectFieldDiffAction","filterText":"ProjectFieldDiffActionReplaceSubresource","insertTextFormat":1,"kind":21,"label":"ProjectFieldDiffActionReplaceSubresource","labelDetails":{},"sortText":"00003","textEdit":{"newText":"ProjectFieldDiffActionReplaceSubresource","range":{"end":{"character":23,"line":141},"start":{"character":1,"line":141}}}},{"detail":"ProjectFieldDiffAction","filterText":"ProjectFieldDiffActionSet","insertTextFormat":1,"kind":21,"label":"ProjectFieldDiffActionSet","labelDetails":{},"sortText":"00004","textEdit":{"newText":"ProjectFieldDiffActionSet","range":{"end":{"character":23,"line":141},"start":{"character":1,"line":141}}}}]}
2022-08-23T09:52:41.839 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":24,"line":141},"start":{"character":24,"line":141}},"text":"e"}],"textDocument":{"uri":"file://<WORKSPACE>/adsci/adsci.go","version":20}}}
2022-08-23T09:52:41.851 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"textDocument/publishDiagnostics","params":{"uri":"file://<WORKSPACE>/adsci/adsci.go","version":20,"diagnostics":[]}}
2022-08-23T09:52:41.971 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":25,"line":141},"start":{"character":25,"line":141}},"text":"m"}],"textDocument":{"uri":"file://<WORKSPACE>/adsci/adsci.go","version":21}}}
2022-08-23T09:52:42.015 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":26,"line":141},"start":{"character":26,"line":141}},"text":"o"}],"textDocument":{"uri":"file://<WORKSPACE>/adsci/adsci.go","version":22}}}
2022-08-23T09:52:42.059 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":27,"line":141},"start":{"character":27,"line":141}},"text":"v"}],"textDocument":{"uri":"file://<WORKSPACE>/adsci/adsci.go","version":23}}}
2022-08-23T09:52:42.112 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":28,"line":141},"start":{"character":28,"line":141}},"text":"e"}],"textDocument":{"uri":"file://<WORKSPACE>/adsci/adsci.go","version":24}}}
2022-08-23T09:52:42.481 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"window/logMessage","params":{"type":1,"message":"2022/08/23 09:52:42 tidy: diagnosing file://<WORKSPACE>/go.mod: err: exit status 1: stderr: go: finding module for package github.com/golang-jwt/jwt\ngo: finding module for package github.com/<PROJECT1>/api/v2\ngo: finding module for package github.com/<PROJECT2>/cmd/server/graph/generated\ngo: finding module for package github.com/bazelbuild/rules_go/go/tools/bazel\ngo: finding module for package github.com/<PROJECT2>/cmd/server/graph/model\ngithub.com/<PROJECT2>/blobs/blobsrv imports\n\tgithub.com/<PROJECT1>/api/v2: cannot find module providing package github.com/<PROJECT1>/api/v2: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/cmd/server imports\n\tgithub.com/<PROJECT2>/cmd/server/graph/generated: cannot find module providing package github.com/<PROJECT2>/cmd/server/graph/generated: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/cmd/server/graph imports\n\tgithub.com/<PROJECT2>/cmd/server/graph/model: cannot find module providing package github.com/<PROJECT2>/cmd/server/graph/model: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/db/sqldb/migrate imports\n\tgithub.com/bazelbuild/rules_go/go/tools/bazel: cannot find module providing package github.com/bazelbuild/rules_go/go/tools/bazel: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/authn/session tested by\n\tgithub.com/<PROJECT2>/authn/session.test imports\n\tgithub.com/golang-jwt/jwt: cannot find module providing package github.com/golang-jwt/jwt: module lookup disabled by GOPROXY=off\n\n"}}
2022-08-23T09:52:42.481 helix_term::application [INFO] window/logMessage: LogMessageParams { typ: Error, message: "2022/08/23 09:52:42 tidy: diagnosing file://<WORKSPACE>/go.mod: err: exit status 1: stderr: go: finding module for package github.com/golang-jwt/jwt\ngo: finding module for package github.com/<PROJECT1>/api/v2\ngo: finding module for package github.com/<PROJECT2>/cmd/server/graph/generated\ngo: finding module for package github.com/bazelbuild/rules_go/go/tools/bazel\ngo: finding module for package github.com/<PROJECT2>/cmd/server/graph/model\ngithub.com/<PROJECT2>/blobs/blobsrv imports\n\tgithub.com/<PROJECT1>/api/v2: cannot find module providing package github.com/<PROJECT1>/api/v2: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/cmd/server imports\n\tgithub.com/<PROJECT2>/cmd/server/graph/generated: cannot find module providing package github.com/<PROJECT2>/cmd/server/graph/generated: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/cmd/server/graph imports\n\tgithub.com/<PROJECT2>/cmd/server/graph/model: cannot find module providing package github.com/<PROJECT2>/cmd/server/graph/model: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/db/sqldb/migrate imports\n\tgithub.com/bazelbuild/rules_go/go/tools/bazel: cannot find module providing package github.com/bazelbuild/rules_go/go/tools/bazel: module lookup disabled by GOPROXY=off\ngithub.com/<PROJECT2>/authn/session tested by\n\tgithub.com/<PROJECT2>/authn/session.test imports\n\tgithub.com/golang-jwt/jwt: cannot find module providing package github.com/golang-jwt/jwt: module lookup disabled by GOPROXY=off\n\n" }
2022-08-23T09:52:42.490 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"textDocument/publishDiagnostics","params":{"uri":"file://<WORKSPACE>/cmd/server/graph/project_resolvers.go","version":1923,"diagnostics":[{"range":{"start":{"line":744,"character":46},"end":{"line":744,"character":49}},"severity":1,"code":"IncompatibleAssign","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#IncompatibleAssign"},"source":"compiler","message":"cannot use req (variable of type model.ProjectFieldDiffInput) as *model.ProjectFieldDiffInput value in argument to graphconv.ProjectDiffFromGQL"},{"range":{"start":{"line":751,"character":2},"end":{"line":751,"character":17}},"severity":1,"code":"UnusedVar","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#UnusedVar"},"source":"compiler","message":"newSubresources declared but not used"},{"range":{"start":{"line":771,"character":33},"end":{"line":771,"character":41}},"severity":1,"code":"UndeclaredName","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#UndeclaredName"},"source":"compiler","message":"undeclared name: newDiffs"}]}}
2022-08-23T09:52:42.985 helix_term::job [DEBUG] waiting on jobs...
2022-08-23T09:52:42.985 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/formatting","params":{"options":{"insertSpaces":false,"tabSize":2},"textDocument":{"uri":"file://<WORKSPACE>/adsci/adsci.go"}},"id":400}
2022-08-23T09:52:42.990 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","result":[{"range":{"start":{"line":141,"character":42},"end":{"line":141,"character":45}},"newText":""}],"id":400}
2022-08-23T09:52:42.990 helix_lsp::transport [INFO] <- [{"newText":"","range":{"end":{"character":45,"line":141},"start":{"character":42,"line":141}}}]
2022-08-23T09:52:42.991 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didSave","params":{"textDocument":{"uri":"file://<WORKSPACE>/adsci/adsci.go"}}}
2022-08-23T09:52:43.015 mio::poll [TRACE] deregistering event source from poller
2022-08-23T09:52:43.015 mio::poll [TRACE] deregistering event source from poller
2022-08-23T09:52:43.019 mio::poll [TRACE] deregistering event source from poller
2022-08-23T09:52:43.019 mio::poll [TRACE] deregistering event source from poller
2022-08-23T09:52:43.019 mio::poll [TRACE] deregistering event source from poller
2022-08-23T09:52:43.019 mio::poll [TRACE] deregistering event source from poller
2022-08-23T09:52:43.019 mio::poll [TRACE] deregistering event source from poller
2022-08-23T09:52:43.019 mio::poll [TRACE] deregistering event source from poller
2022-08-23T09:52:43.019 mio::poll [TRACE] deregistering event source from poller

EDIT: A full stack trace, since it happened again:

[bsprague@bsprague AdventureScientists]$ RUST_BACKTRACE=full GOPACKAGESDRIVER=$PWD/scripts/gopackagesdriver.sh vim -vvvv
thread 'main' panicked at 'no entry found for key', helix-view/src/document.rs:1006:10
stack backtrace:
   0:     0x55a64a945ab4 - std::backtrace_rs::backtrace::libunwind::trace::h22893a5306c091b4
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
   1:     0x55a64a945ab4 - std::backtrace_rs::backtrace::trace_unsynchronized::h29c3bc6f9e91819d
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:     0x55a64a945ab4 - std::sys_common::backtrace::_print_fmt::he497d8a0ec903793
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/sys_common/backtrace.rs:66:5
   3:     0x55a64a945ab4 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h9c2a9d2774d81873
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/sys_common/backtrace.rs:45:22
   4:     0x55a64a164b3c - core::fmt::write::hba4337c43d992f49
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/core/src/fmt/mod.rs:1194:17
   5:     0x55a64a93f495 - std::io::Write::write_fmt::heb73de6e02cfabed
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/io/mod.rs:1655:15
   6:     0x55a64a94795e - std::sys_common::backtrace::_print::h63c8b24acdd8e8ce
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/sys_common/backtrace.rs:48:5
   7:     0x55a64a94795e - std::sys_common::backtrace::print::h426700d6240cdcc2
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/sys_common/backtrace.rs:35:9
   8:     0x55a64a94795e - std::panicking::default_hook::{{closure}}::hc9a76eed0b18f82b
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:295:22
   9:     0x55a64a94768d - std::panicking::default_hook::h2e88d02087fae196
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:314:9
  10:     0x55a64a7cce2c - helix_term::application::Application::run::{{closure}}::{{closure}}::h8bbcf3cac74bd9cf
  11:     0x55a64a947feb - std::panicking::rust_panic_with_hook::habfdcc2e90f9fd4c
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:702:17
  12:     0x55a64a947e14 - std::panicking::begin_panic_handler::{{closure}}::he054b2a83a51d2cd
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:588:13
  13:     0x55a64a945fe4 - std::sys_common::backtrace::__rust_end_short_backtrace::ha48b94ab49b30915
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/sys_common/backtrace.rs:138:18
  14:     0x55a64a947b7d - rust_begin_unwind
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:584:5
  15:     0x55a64a0dbc73 - core::panicking::panic_fmt::h366d3a309ae17c94
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/core/src/panicking.rs:143:14
  16:     0x55a64a163581 - core::panicking::panic_display::hd3e89d99fb893792
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/core/src/panicking.rs:72:5
  17:     0x55a64a16352b - core::panicking::panic_str::h98ed104b0c03a108
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/core/src/panicking.rs:56:5
  18:     0x55a64a0dbae6 - core::option::expect_failed::h58d487f78ae9d247
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/core/src/option.rs:1874:5
  19:     0x55a64a729b6c - helix_view::document::Document::apply::he19368bd3df70284
  20:     0x55a64a425879 - core::ops::function::FnOnce::call_once{{vtable.shim}}::h7bfdd3c01e8046b7
  21:     0x55a64a5f5faf - helix_term::job::Jobs::handle_callback::h28a7ea5e7038e09d
  22:     0x55a64a7c9c09 - helix_term::application::Application::event_loop_until_idle::{{closure}}::h6df86b0079c21409
  23:     0x55a64a7e8d75 - <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::hbbe1569e4df9b43b
  24:     0x55a64a7bdd62 - std::thread::local::LocalKey<T>::with::h55d36779f4af99ba
  25:     0x55a64a7abb78 - tokio::park::thread::CachedParkThread::block_on::h71712a6eec55888d
  26:     0x55a64a80aa38 - tokio::runtime::thread_pool::ThreadPool::block_on::hce4ebbefdc228190
  27:     0x55a64a7c6bc0 - tokio::runtime::Runtime::block_on::hc02c4f5bae532a5f
  28:     0x55a64a7ae766 - hx::main::h3e1171e59638bdfa
  29:     0x55a64a7ae893 - std::sys_common::backtrace::__rust_begin_short_backtrace::he58e95ee9bc32ab7
  30:     0x55a64a7bd8cd - std::rt::lang_start::{{closure}}::h88e34aa52b213813
  31:     0x55a64a939d2b - core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::had4f69b3aefb47a8
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/core/src/ops/function.rs:259:13
  32:     0x55a64a939d2b - std::panicking::try::do_call::hf2ad5355fcafe775
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:492:40
  33:     0x55a64a939d2b - std::panicking::try::h0a63ac363423e61e
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:456:19
  34:     0x55a64a939d2b - std::panic::catch_unwind::h18088edcecb8693a
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panic.rs:137:14
  35:     0x55a64a939d2b - std::rt::lang_start_internal::{{closure}}::ha7dad166dc711761
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/rt.rs:128:48
  36:     0x55a64a939d2b - std::panicking::try::do_call::hda0c61bf3a57d6e6
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:492:40
  37:     0x55a64a939d2b - std::panicking::try::hbc940e68560040a9
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:456:19
  38:     0x55a64a939d2b - std::panic::catch_unwind::haed0df2aeb3fa368
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panic.rs:137:14
  39:     0x55a64a939d2b - std::rt::lang_start_internal::h9c06694362b5b80c
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/rt.rs:128:20
  40:     0x55a64a7ae872 - main
  41:     0x7fe9c7d2c2d0 - <unknown>
  42:     0x7fe9c7d2c38a - __libc_start_main
  43:     0x55a64a113635 - _start
                               at /build/glibc/src/glibc/csu/../sysdeps/x86_64/start.S:115
  44:                0x0 - <unknown>

@dead10ck
Copy link
Member

dead10ck commented Aug 23, 2022

Ok yeah that stack trace pretty much confirms for me that it's a race: the write-quit command is finishing the whole process of writing the file and closing the view before the auto format callback gets a chance to run, and by the time it does, the view is closed. Thanks for taking the time to help debug!

Theoretically, this should be fixed by #2267 because it is serializing the whole process, so the file write and close should not happen until the auto format is done and applied to the in-memory document, but I'll try to figure out what's causing the channel close issue.

As a side note, I'm really curious what machine you're running this on. Judging by your earlier logs, I can see there are a lot of interrupts in the tokio tasks by observing all the times that it reawaits the future.

@bcspragu
Copy link
Contributor Author

As a side note, I'm really curious what machine you're running this on. Judging by your earlier logs, I can see there are a lot of interrupts in the tokio tasks by observing all the times that it reawaits the future.

Nothing too esoteric, a 2021 Lenovo Slim 7 Pro with a Ryzen 4800H, 8C/16T, running Arch Linux. I'm not familiar with tokio/have no idea what would cause interrupts, but system load is fairly low (1-2%) most of the time.

@dead10ck
Copy link
Member

@bcspragu ok, I think I may have found the problem. Can you pull the latest change on my branch and try again?

@bcspragu
Copy link
Contributor Author

I wasn't able to cause the crash by moving yanked + pasted chunks around between a few different files, which is good! I'm going to use it for a day of work and I'll report back. Recently, I've been seeing crashes every few hours, so if it doesn't crash after a full day, that's a good sign

@dead10ck
Copy link
Member

Awesome, thanks for testing!

@bcspragu
Copy link
Contributor Author

@dead10ck I'm still getting a panic on the same line (line number has changed in your branch though):

stack trace
thread 'main' panicked at 'no entry found for key', helix-view/src/document.rs:1200:10
stack backtrace:
   0:     0x5589b184bed4 - std::backtrace_rs::backtrace::libunwind::trace::h22893a5306c091b4
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
   1:     0x5589b184bed4 - std::backtrace_rs::backtrace::trace_unsynchronized::h29c3bc6f9e91819d
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:     0x5589b184bed4 - std::sys_common::backtrace::_print_fmt::he497d8a0ec903793
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/sys_common/backtrace.rs:66:5
   3:     0x5589b184bed4 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h9c2a9d2774d81873
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/sys_common/backtrace.rs:45:22
   4:     0x5589b106f7dc - core::fmt::write::hba4337c43d992f49
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/core/src/fmt/mod.rs:1194:17
   5:     0x5589b18458b5 - std::io::Write::write_fmt::heb73de6e02cfabed
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/io/mod.rs:1655:15
   6:     0x5589b184dd7e - std::sys_common::backtrace::_print::h63c8b24acdd8e8ce
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/sys_common/backtrace.rs:48:5
   7:     0x5589b184dd7e - std::sys_common::backtrace::print::h426700d6240cdcc2
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/sys_common/backtrace.rs:35:9
   8:     0x5589b184dd7e - std::panicking::default_hook::{{closure}}::hc9a76eed0b18f82b
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:295:22
   9:     0x5589b184daad - std::panicking::default_hook::h2e88d02087fae196
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:314:9
  10:     0x5589b16aaddc - helix_term::application::Application::run::{{closure}}::{{closure}}::h2a171355ca53c72c
  11:     0x5589b184e40b - std::panicking::rust_panic_with_hook::habfdcc2e90f9fd4c
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:702:17
  12:     0x5589b184e234 - std::panicking::begin_panic_handler::{{closure}}::he054b2a83a51d2cd
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:588:13
  13:     0x5589b184c404 - std::sys_common::backtrace::__rust_end_short_backtrace::ha48b94ab49b30915
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/sys_common/backtrace.rs:138:18
  14:     0x5589b184df9d - rust_begin_unwind
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:584:5
  15:     0x5589b0feec33 - core::panicking::panic_fmt::h366d3a309ae17c94
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/core/src/panicking.rs:143:14
  16:     0x5589b106deb1 - core::panicking::panic_display::hd3e89d99fb893792
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/core/src/panicking.rs:72:5
  17:     0x5589b106de5b - core::panicking::panic_str::h98ed104b0c03a108
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/core/src/panicking.rs:56:5
  18:     0x5589b0feeaa6 - core::option::expect_failed::h58d487f78ae9d247
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/core/src/option.rs:1874:5
  19:     0x5589b163033c - helix_view::document::Document::apply::hdd9730fbde23cca3
  20:     0x5589b1582e05 - core::ops::function::FnOnce::call_once{{vtable.shim}}::he5341b3c91860820
  21:     0x5589b15ad29e - <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h236cde45d77243bf
  22:     0x5589b144027e - std::thread::local::LocalKey<T>::with::h440c0bd8e97a5284
  23:     0x5589b154dd68 - futures_executor::local_pool::block_on::hff98863698998444
  24:     0x5589b146a885 - tokio::runtime::enter::exit::hbdc9c7ff73bf1342
  25:     0x5589b13c3ab4 - tokio::runtime::thread_pool::worker::block_in_place::hb38f1bb8e6a60a62
  26:     0x5589b13341db - helix_term::compositor::Context::block_try_flush_writes::hfdbc70b629937314
  27:     0x5589b132d69a - helix_term::commands::typed::write_all_impl::hce3a06ee086ddcf8
  28:     0x5589b1563c79 - helix_term::commands::typed::command_mode::{{closure}}::h162efeea55d3791c
  29:     0x5589b1572ed3 - <helix_term::ui::prompt::Prompt as helix_term::compositor::Component>::handle_event::hd7e09ffd9de34d7b
  30:     0x5589b1334db0 - helix_term::compositor::Compositor::handle_event::h1b818966a61e8398
  31:     0x5589b15c33da - helix_term::application::Application::handle_terminal_events::ha4be59be0fc0081c
  32:     0x5589b16a6b9a - helix_term::application::Application::event_loop_until_idle::{{closure}}::haa95758a1fce8ebe
  33:     0x5589b16c253b - hx::main_impl::{{closure}}::h9515a8a871fef1e9
  34:     0x5589b16df095 - std::thread::local::LocalKey<T>::with::h4a2650524fd0402e
  35:     0x5589b16bb5e8 - tokio::park::thread::CachedParkThread::block_on::h23825ea45ad693b3
  36:     0x5589b1693008 - tokio::runtime::thread_pool::ThreadPool::block_on::h7d48bcf67d5258ff
  37:     0x5589b16f0750 - tokio::runtime::Runtime::block_on::hab8dd3ba388c1c22
  38:     0x5589b16a3666 - hx::main::h8012874220ecbbec
  39:     0x5589b16b2e63 - std::sys_common::backtrace::__rust_begin_short_backtrace::h8b4ea23ef8b6946e
  40:     0x5589b16def7d - std::rt::lang_start::{{closure}}::hc01c98d73647ef30
  41:     0x5589b18401bb - core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::had4f69b3aefb47a8
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/core/src/ops/function.rs:259:13
  42:     0x5589b18401bb - std::panicking::try::do_call::hf2ad5355fcafe775
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:492:40
  43:     0x5589b18401bb - std::panicking::try::h0a63ac363423e61e
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:456:19
  44:     0x5589b18401bb - std::panic::catch_unwind::h18088edcecb8693a
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panic.rs:137:14
  45:     0x5589b18401bb - std::rt::lang_start_internal::{{closure}}::ha7dad166dc711761
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/rt.rs:128:48
  46:     0x5589b18401bb - std::panicking::try::do_call::hda0c61bf3a57d6e6
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:492:40
  47:     0x5589b18401bb - std::panicking::try::hbc940e68560040a9
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:456:19
  48:     0x5589b18401bb - std::panic::catch_unwind::haed0df2aeb3fa368
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panic.rs:137:14
  49:     0x5589b18401bb - std::rt::lang_start_internal::h9c06694362b5b80c
                               at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/rt.rs:128:20
  50:     0x5589b16a3772 - main
  51:     0x7f458d77c2d0 - <unknown>
  52:     0x7f458d77c38a - __libc_start_main
  53:     0x5589b1024f55 - _start
                               at /build/glibc/src/glibc/csu/../sysdeps/x86_64/start.S:115
  54:                0x0 - <unknown>

Nothing interesting in the logs prior to the crash, though I hadn't specified -vvvv:

helix.log
2022-08-24T10:03:47.565 helix_view::editor [ERROR] Failed to initialize the LSP for `git.commitmsg` { LSP not defined }
2022-08-24T10:06:03.874 helix_view::editor [ERROR] Failed to initialize the LSP for `source.gitattributes` { LSP not defined }
2022-08-24T10:06:57.493 helix_view::editor [ERROR] Failed to initialize the LSP for `git.commitmsg` { LSP not defined }
2022-08-24T10:33:48.962 helix_view::editor [ERROR] Failed to initialize the LSP for `source.bash` { cannot find binary path }
2022-08-24T10:34:26.519 helix_lsp::transport [ERROR] err: <- StreamClosed
2022-08-24T10:34:26.519 helix_lsp::transport [ERROR] err: <- StreamClosed
2022-08-24T10:34:26.521 helix_lsp::transport [ERROR] err: <- StreamClosed
2022-08-24T10:45:05.255 helix_term::application [ERROR] Language Server: Method not found client/registerCapability
2022-08-24T10:45:07.462 helix_term::application [ERROR] Language Server: Method not found window/showMessageRequest
2022-08-24T10:45:07.462 helix_term::application [ERROR] Language Server: Method not found window/showMessageRequest
2022-08-24T10:45:15.017 helix_view::editor [ERROR] Failed to initialize the LSP for `git.commitmsg` { LSP not defined }
2022-08-24T10:50:28.822 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <WORKSPACE>: open <WORKSPACE>/bazel-<PROJECT>/.postgres-data/data: permission denied\n"
2022-08-24T10:53:02.827 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <WORKSPACE>: open <WORKSPACE>/bazel-<PROJECT>/.postgres-data/data: permission denied\n"
2022-08-24T10:53:57.772 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <WORKSPACE>: open <WORKSPACE>/bazel-<PROJECT>/.postgres-data/data: permission denied\n"
2022-08-24T10:57:01.145 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <WORKSPACE>: open <WORKSPACE>/bazel-<PROJECT>/.postgres-data/data: permission denied\n"
2022-08-24T11:04:37.184 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <WORKSPACE>: open <WORKSPACE>/bazel-<PROJECT>/.postgres-data/data: permission denied\n"
2022-08-24T11:42:30.290 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <WORKSPACE>: open <WORKSPACE>/bazel-<PROJECT>/.postgres-data/data: permission denied\n"
2022-08-24T11:43:29.826 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <WORKSPACE>: open <WORKSPACE>/bazel-<PROJECT>/.postgres-data/data: permission denied\n"
2022-08-24T11:44:18.305 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <WORKSPACE>: open <WORKSPACE>/bazel-<PROJECT>/.postgres-data/data: permission denied\n"
2022-08-24T11:44:57.857 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <WORKSPACE>: open <WORKSPACE>/bazel-<PROJECT>/.postgres-data/data: permission denied\n"
2022-08-24T11:45:51.101 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <WORKSPACE>: open <WORKSPACE>/bazel-<PROJECT>/.postgres-data/data: permission denied\n"
2022-08-24T11:46:53.216 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <WORKSPACE>: open <WORKSPACE>/bazel-<PROJECT>/.postgres-data/data: permission denied\n"
2022-08-24T11:49:27.238 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <WORKSPACE>: open <WORKSPACE>/bazel-<PROJECT>/.postgres-data/data: permission denied\n"
2022-08-24T11:50:01.288 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <WORKSPACE>: open <WORKSPACE>/bazel-<PROJECT>/.postgres-data/data: permission denied\n"
2022-08-24T11:50:54.952 helix_lsp::transport [ERROR] err <- "walk.go:91: gopathwalk: scanning directory <WORKSPACE>: open <WORKSPACE>/bazel-<PROJECT>/.postgres-data/data: permission denied\n"
2022-08-24T11:53:58.083 helix_view::editor [ERROR] Failed to initialize the LSP for `source.graphql` { LSP not defined }

@dead10ck
Copy link
Member

Hmm, ok, thanks so much for testing and the stack trace. I'll try to dig some more.

@AndyJado
Copy link

:wa triggers panics a few times in a hour.

things were smooth till today, I got a big .rs file which has over 2500 lines.

thread 'main' panicked at 'no entry found for key', helix-view/src/document.rs:1006:10
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

@dead10ck
Copy link
Member

dead10ck commented Aug 25, 2022

Ok, I'm fairly certain I've narrowed down the cause. It's pretty easily reproducible. I'll post details and hopefully a fix later when I can get to it. But short version is this can happen basically any time you have more than two splits and do a write-all and an out of focus view gets auto formatted. For the time being, it will be necessary to save each file individually.

Edit: alternatively, you can turn off auto formatting

@bcspragu
Copy link
Contributor Author

Ok, I'm fairly certain I've narrowed down the cause. It's pretty easily reproducible. I'll post details and hopefully a fix later when I can get to it. But short version is this can happen basically any time you have more than two splits and do a write-all and an out of focus view gets auto formatted. For the time being, it will be necessary to save each file individually.

Yup, that matches my experience. Using only :w, I haven't seen the crash yet, and I'm usually working in large (~1k-3k) Go files, which have an autoformatter.

@dead10ck
Copy link
Member

dead10ck commented Aug 26, 2022

Okay, so the problem is basically that when we do auto formatting, the code that takes the LSP's response and applies the changes to the document are just getting the currently focused view and giving that to the function, basically always assuming that the document that we're applying the change to is in focus, and not in a background view.

async fn make_format_callback(
doc_id: DocumentId,
doc_version: i32,
modified: Modified,
format: impl Future<Output = Result<Transaction, FormatterError>> + Send + 'static,
) -> anyhow::Result<job::Callback> {
let format = format.await?;
let call: job::Callback = Box::new(move |editor, _compositor| {
let view_id = view!(editor).id;
if let Some(doc) = editor.document_mut(doc_id) {
if doc.version() == doc_version {
doc.apply(&format, view_id);
doc.append_changes_to_history(view_id);
doc.detect_indent_and_line_ending();
if let Modified::SetUnmodified = modified {
doc.reset_modified();
}
} else {
log::info!("discarded formatting changes because the document changed");
}
}
});
Ok(call)
}

This is usually fine for a single view, even if it's a buffer in the background, because it's still the same view and the selection will get updated accordingly for when you switch back to it. But it's obviously a problem for when there are multiple views, because if you don't have the target document in focus, it will ask the document to update the wrong view, hence the crash.

This is easily reproducible:

  1. Open document 1 in view 1, make some edits without saving
  2. Split
  3. Open document 2 in view 2, make some edits without saving
  4. Split
  5. Open document 3 in view 3, make some edits without saving
  6. :write-all

You need 3 or more documents open to hit this because when you split, you actually start with the previous document open in it before opening another, so it is in fact associated with that view. So in using the above example, view 1 is associated with doc 1, view 2 is associated with doc 1 and doc 2, and view 3 is associated with docs 2 and 3. So I suspect that we haven't had any reports of this until now because OP is the first user that makes use of many views as part of their normal workflow.

I think the solution is to explicitly pass in the view we want to apply the change to as part of the function arguments. However, this raises a UX issue: when we're doing a write-all, which view do we pass to the auto formatting callback? We could have several views associated with the same document.

Furthermore, part of what the view is used for is to save the old state so that we can undo it if we want:

pub fn apply(&mut self, transaction: &Transaction, view_id: ViewId) -> bool {
// store the state just before any changes are made. This allows us to undo to the
// state just before a transaction was applied.
if self.changes.is_empty() && !transaction.changes().is_empty() {
self.old_state = Some(State {
doc: self.text.clone(),
selection: self.selection(view_id).clone(),
});
}
let success = self.apply_impl(transaction, view_id);

So, our options seem to be:

  1. Change the document application functions to just use all views associated with the document. This would potentially set all views to the same selection that we get back from the auto format response. There is only one shared document history for all the views, so undo history currently doesn't seem well-suited for having multiple different selections of the same document. It's unclear how to address this without a large redesign of the history system to support keeping all selections from all views when we save document states in the history. As for updating the selection, part of the reason to have multiple views of the same document to begin with is to have your selections in different parts of the document, and this could end up moving them all to the same place. This might annoy some users.
  2. Continue just passing in the focused view, and have the apply function just check if this view actually belongs to this document. If not, just proceed without saving document state just before formatting, and don't update the selection if the formatter returns one. This way, background views get their formatting changes applied correctly, and their selections don't change, and the foreground view gets state saved as well as an updated selection. It seems desirable to leave the background views' selections alone so we're not disturbing the user's workflow, but they also won't be able to undo to get back to the state they had before the formatting change.
  3. For each document we're saving, try to pick just one view out of possibly many to send to the document change application. This would preserve the selections of the different views of the same document. Problem here is how do we choose which one? I could be missing knowledge of the tree stuff in the code base, but to my knowledge, I don't think we'd have a way to e.g. track which view last had a document focused, so we'd have to pick arbitrarily.
  4. Don't update any views when we're applying a change. Selections don't move anywhere, and state is not saved for any views.

The latter seems the least desirable. 3 would seem like the best balanced approach, but seems like it could end up with confusing undo history. e.g. if we had two views of a document, and we pick view 1, we'll save the document state with the selection of view 1. So if you go to view 2 and undo the formatting change, you'd end up with the selection you previously had in view 1 in view 2. However, this seems like the best option for the time being, without having to totally redesign the history system all at once in order to fix this crash.

@archseer do you care to weigh in?

Also, it's worth noting that no matter what we end up picking, I'm fairly certain it will still have to be based on top of #2267 because without it, the race condition is still possible, i.e. we could end up closing the view before we got the chance to apply the auto formatting change to it.

@dead10ck
Copy link
Member

I opted to just pick the first view of the document we're trying to save. I have a branch up here that's based on top of #2267, and will submit a PR once that is merged.

@bcspragu could you please try out this branch when you get a chance? I was no longer able to reproduce the issue locally after this change.

@archseer
Copy link
Member

I opted to just pick the first view of the document we're trying to save.

I think that's a good choice, we do this in a couple of other scenarios too 👍🏻

@bcspragu
Copy link
Contributor Author

@bcspragu could you please try out this branch when you get a chance? I was no longer able to reproduce the issue locally after this change.

I used your branch for a full work day yesterday, frequently with 5+ splits open (frequently with 2 of them the same large file), using :wa to save files, and I didn't experience any crashes! I'll keep using it today, but I'm cautiously optimistic you've nailed the root cause here. Thanks for all the debugging help!

@dead10ck
Copy link
Member

Awesome, glad to hear it! Thanks so much for working with me to solve it.

@nextuponstream
Copy link

@bcspragu could you please try out this branch when you get a chance? I was no longer able to reproduce the issue locally after this change.

I used the branch for two weeks now and I don't crash anymore when I use my :wa shortcut. Thank you @dead10ck

@dead10ck
Copy link
Member

@bcspragu could you please try out this branch when you get a chance? I was no longer able to reproduce the issue locally after this change.

I used the branch for two weeks now and I don't crash anymore when I use my :wa shortcut. Thank you @dead10ck

Awesome, great to hear, thanks for testing!

@archseer archseer linked a pull request Oct 12, 2022 that will close this issue
@dead10ck
Copy link
Member

Actually I was waiting to submit the fix for this because it needed #2267 as well, but I didn't want to just keep piling on the same PR. I'll submit a PR for a fix for this now though :)

@dead10ck
Copy link
Member

dead10ck commented Oct 20, 2022

PR here (it's much smaller): #4384

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
A-helix-term Area: Helix term improvements C-bug Category: This is a bug
Projects
None yet
Development

Successfully merging a pull request may close this issue.

7 participants