lorri seems to loop forever? - but nix-shell works fine

[chreekat]

Sorry it's a proprietary project, so no code sample. :( I also don't know how to create a minimal repro.

This is on the rolling release:

[b@bryan-laptop:~/Projects/dotfiles/nixos/lorri]$ git log --oneline HEAD^..
03f1039 (HEAD, origin/rolling-release) default.nix: use `nativeBuildInputs` for tools

And nix-shell works ok:

$ nix-shell --run 'echo hello world'
hello world

The shell being built comes from haskellPackages.shellFor.

I'm using the user-local socket-activation. When lorri gets activated, it pins a CPU and just sits there saying "Started..."

If I then get cheeky and start a nix shell on the console while lorri is running, lorri crashes with:

Nov 25 17:33:58 bryan-laptop lorri[3129]: lorri: ready
Nov 25 17:34:02 bryan-laptop lorri[3129]: Started
Nov 25 17:35:09 bryan-laptop lorri[3129]: thread '<unnamed>' panicked at 'Unrecoverable error!
Nov 25 17:35:09 bryan-laptop lorri[3129]: Notify(
Nov 25 17:35:09 bryan-laptop lorri[3129]:     Io(
Nov 25 17:35:09 bryan-laptop lorri[3129]:         Os {
Nov 25 17:35:09 bryan-laptop lorri[3129]:             code: 40,
Nov 25 17:35:09 bryan-laptop lorri[3129]:             kind: Other,
Nov 25 17:35:09 bryan-laptop lorri[3129]:             message: "Too many levels of symbolic links"
Nov 25 17:35:09 bryan-laptop lorri[3129]:         }
Nov 25 17:35:09 bryan-laptop lorri[3129]:     )
Nov 25 17:35:09 bryan-laptop lorri[3129]: )', src/build_loop.rs:84:56
Nov 25 17:35:09 bryan-laptop lorri[3129]: stack backtrace:
Nov 25 17:35:09 bryan-laptop lorri[3129]:    0:     0x56413c821c1f - std::sys::unix::backtrace::tracing::imp::unwind_backtrace::hfad0220813d5e5c3
Nov 25 17:35:09 bryan-laptop lorri[3129]:    1:     0x56413c832657 - std::sys_common::backtrace::print::h16017ddc8b354e39
Nov 25 17:35:09 bryan-laptop lorri[3129]:    2:     0x56413c8254c3 - std::panicking::default_hook::{{closure}}::h8b06d3b8a7138cc5
Nov 25 17:35:09 bryan-laptop lorri[3129]:    3:     0x56413c825243 - std::panicking::default_hook::h8cac4830452b35df
Nov 25 17:35:09 bryan-laptop lorri[3129]:    4:     0x56413c825bbf - std::panicking::rust_panic_with_hook::hd32c26e1600a179b
Nov 25 17:35:09 bryan-laptop lorri[3129]:    5:     0x56413c825751 - std::panicking::continue_panic_fmt::h24b78f7279f44cef
Nov 25 17:35:09 bryan-laptop lorri[3129]:    6:     0x56413c82569e - std::panicking::begin_panic_fmt::h98672d172280200e
Nov 25 17:35:09 bryan-laptop lorri[3129]:    7:     0x56413c6aa566 - lorri::build_loop::BuildLoop::forever::h107a54d9d12e731b
Nov 25 17:35:09 bryan-laptop lorri[3129]:    8:     0x56413c6acd73 - std::sys_common::backtrace::__rust_begin_short_backtrace::h6de3911e47385787
Nov 25 17:35:09 bryan-laptop lorri[3129]:    9:     0x56413c6bb9d8 - std::panicking::try::do_call::ha622cd5ff1ae34b0
Nov 25 17:35:09 bryan-laptop lorri[3129]:   10:     0x56413c83d499 - __rust_maybe_catch_panic
Nov 25 17:35:09 bryan-laptop lorri[3129]:   11:     0x56413c6b5a92 - <F as alloc::boxed::FnBox<A>>::call_box::hed14b3946e261b17
Nov 25 17:35:09 bryan-laptop lorri[3129]:   12:     0x56413c8209ed - std::sys_common::thread::start_thread::h09a6bf95952964d1
Nov 25 17:35:09 bryan-laptop lorri[3129]:   13:     0x56413c82b8e5 - std::sys::unix::thread::Thread::new::thread_start::h165ad4e27a9c9315
Nov 25 17:35:09 bryan-laptop lorri[3129]:   14:     0x7f89f991aef6 - start_thread
Nov 25 17:35:09 bryan-laptop lorri[3129]:   15:     0x7f89f963a22e - __GI___clone
Nov 25 17:35:09 bryan-laptop lorri[3129]:   16:                0x0 - <unknown>

[Profpatsch]

I'm using the user-local socket-activation. When lorri gets activated, it pins a CPU and just sits there saying "Started..."

Usually that means it’s building in the background with nix-instantiate or nix-build. If you open up (h)top you should se it in the process list (as subprocess to lorri daemon).

You should try running the daemon in a terminal with lorri -vvv daemon.

[chreekat]

I'll try running the daemon with extra verbosity when I get the chance. But should lorri be building so furiously when nix-shell completes immediately?

[Profpatsch]

But should lorri be building so furiously when nix-shell completes immediately?

It should indeed not, but we can only know for sure when we see the verbose output.

[turboMaCk]

I'm also experiencing this issue quite frequently. Even if I let the daemon and all its nix-instantiate processes running for hours it seems to never finish. Is there anything we can do to help to debug this?

My current workaround is to systemctl --user restart lorri.service (I'm on NixOS) when I spot such activity.

[chreekat]

@turboMaCk , can you try stopping the service and then running the daemon directly in another terminal with lorri -vvv daemon? Then we might get some clues.

I plan on doing that myself as soon as I get the chance.

[turboMaCk]

I will try it but it seems to be fixed after service restarts so I think running it as a new process won't guarantee to replicate the issue. BTW I have 2 machines (desktop and laptop) and I've observed this issue on both of them.

I'll get back to this once I have some more data.

[johnae]

I wonder if this may be a duplicate of https://github.com/target/lorri/issues/176

[curiousleo]

@chreekat does your project import <nixpkgs> or use niv?

[chreekat]

@curiousleo It's importing <nixpkgs>.

@Profpatsch , I had a chance to run lorri -vvvv daemon, and it looks like lorri is watching my entire filesystem.

[2019-12-02T12:48:51Z DEBUG lorri::nix] "nix-build" "--out-link" "/tmp/.tmpDi0suK/result" "--" "/tmp/.tmpnHIEZW/result"
[2019-12-02T12:49:33Z DEBUG lorri::build_loop] original paths: 2069
[2019-12-02T12:49:33Z DEBUG lorri::build_loop]   -> reduced to: 2
[2019-12-02T12:49:33Z DEBUG lorri::watch] Watching path "/nix/var/nix/profiles/per-user/root"
[2019-12-02T12:49:33Z DEBUG lorri::watch] Watching parent path "/nix/var/nix/profiles/per-user"
[2019-12-02T12:49:33Z DEBUG lorri::watch] Watching path "/nix/var/nix/profiles/per-user/root/channels-52-link"
[2019-12-02T12:49:33Z DEBUG lorri::watch] Watching path "/nix/var/nix/profiles/per-user/root/channels"
[2019-12-02T12:49:33Z DEBUG lorri::watch] Watching path "/home/b"
[2019-12-02T12:49:33Z DEBUG lorri::watch] Watching parent path "/home"
[2019-12-02T12:49:33Z DEBUG lorri::watch] Watching path "/home/b/.gnupg"
[2019-12-02T12:49:33Z DEBUG lorri::watch] Watching path "/home/b/.gnupg/private-keys-v1.d"
[2019-12-02T12:49:33Z DEBUG lorri::watch] Watching path "/home/b/.gnupg/openpgp-revocs.d"
[2019-12-02T12:49:33Z DEBUG lorri::watch] Watching path "/home/b/.gnupg/crls.d"
[2019-12-02T12:49:33Z DEBUG lorri::watch] Watching path "/home/b/.nix-profile"
[2019-12-02T12:49:33Z DEBUG lorri::watch] Watching path "/home/b/.nix-defexpr"
[2019-12-02T12:49:33Z DEBUG lorri::watch] Watching path "/home/b/.nix-defexpr/channels_root"
[2019-12-02T12:49:33Z DEBUG lorri::watch] Watching path "/home/b/.nix-defexpr/channels"
[2019-12-02T12:49:33Z DEBUG lorri::watch] Watching path "/home/b/.dbus"
[2019-12-02T12:49:33Z DEBUG lorri::watch] Watching path "/home/b/.dbus/session-bus"
[2019-12-02T12:49:33Z DEBUG lorri::watch] Watching path "/home/b/.local"
[2019-12-02T12:49:33Z DEBUG lorri::watch] Watching path "/home/b/.local/share"
[2019-12-02T12:49:33Z DEBUG lorri::watch] Watching path "/home/b/.local/share/gegl-0.4"
[2019-12-02T12:49:33Z DEBUG lorri::watch] Watching path "/home/b/.local/share/gegl-0.4/plug-ins"
[2019-12-02T12:49:33Z DEBUG lorri::watch] Watching path "/home/b/.local/share/keybase"
<continues forever>

[curiousleo]

@chreekat does the project use some third-party mechanism for excluding source files, e.g. gitignore.nix? (See https://github.com/target/lorri/issues/211#issuecomment-555026353)

[chreekat]

@curiousleo yes! This issue is a duplicate of #211. Thanks for the tip. Closing.