No info shown on macOS Nix

[r-burns]

Hi, I'm reviewing a new Nix package for bottom (https://github.com/NixOS/nixpkgs/pull/99126) and having trouble using it on macOS. It compiles and runs by linking against the IOKit framework, but the graphs/lists won't populate with any info:

To reproduce

(On macOS with Nix:) $ nixpkgs-review pr 99126

bottom version (use btm -V)

bottom 0.4.7

Platform

Operating system and OS version: macos 10.14 + nixpkgs master

Terminal (i.e. urxvt, kitty, etc.): default Teminal.app

Shell (i.e. zsh, bash, etc.): bash

System info (RAM, SWAP, etc.):

Rust version (if building yourself):

$ nix eval -f . rustc.version
"1.45.2"

[ClementTsang]

Hi, thanks for the report.

That's quite strange... it runs fine for me if I compile 0.4.7 and master via just cargo b on my Macbook. It also worked fine for me last time I tried on Homebrew.

I'll try running it via nix and the linked PR to see if I can replicate it.

[ClementTsang]

@r-burns I don't normally use nixpkgs, but is it appropriate to test the PR via cloning nixpkgs and running nixpkgs-review pr 99126?

If so, it seems to work fine for me:

I'm on macOS 10.15.7, for what it's worth, but other than that, I'm kinda lost on what is causing the application to not be able to grab data. I unfortunately don't have a Mojave machine to test on.

Just to make sure, you didn't accidentally hit the f key at any time, right? As that would freeze data collection. Pretty sure it isn't that either but might as well cover every base.

[r-burns]

Huh that's weird. I can toggle freeze, navigate around, expand/collapse widgets, etc but still nothing populates, and no processes/devices are listed. Is there some kind of logging I can enable to see if it's gathering info about my system?

[r-burns]

Oh, and I don't think you being on 10.15 should make a difference - afaik nixpkgs-darwin is building against the 10.12 SDK.

[ClementTsang]

Is there some kind of logging I can enable to see if it's gathering info about my system?

Unfortunately, there isn't any (at least accessible by a user). I've planned on adding it, but never got around to doing so.

Oh, and I don't think you being on 10.15 should make a difference - afaik nixpkgs-darwin is building against the 10.12 SDK.

That's good to hear, at least one thing to rule off.

---

If you don't mind, would it be possible to try to clone and build from master to see if that still has issues? If it does, I can set up something to expose debugging utilities to help track what might be going wrong.

[r-burns]

Don't mind at all, appreciate you taking the time to walk through this with me. Oddly, I still get the same thing installing via brew and cargo build master.

[ClementTsang]

Added some simple logging to master, you can activate it by running cargo r -- --debug. It shoud say where it saved the log when the program exits.

If you could, try running it for like a 20 seconds and upload the log here. Hopefully it should help clear up the issue?

[r-burns]

Thanks! I went ahead and ran it but I'm afraid the log is looking quite sparse:

[2020-09-30][20:51:19:923125000][bottom][TRACE] Creating input thread.
[2020-09-30][20:51:19:923776000][bottom][TRACE] Spawned input thread.
[2020-09-30][20:51:19:923830000][bottom][TRACE] Waiting for an input event...
[2020-09-30][20:51:19:923863000][bottom][TRACE] Creating collection thread.
[2020-09-30][20:51:19:923948000][bottom][TRACE] Spawned collection thread.
[2020-09-30][20:51:19:923999000][mio::sys::unix::kqueue][TRACE] registering; token=Token(18446744073709551615); interests=Readable
[2020-09-30][20:51:19:924108000][mio::poll][TRACE] registering with poller
[2020-09-30][20:51:19:924165000][mio::sys::unix::kqueue][TRACE] registering; token=Token(0); interests=Readable
[2020-09-30][20:51:19:924426000][mio::poll][TRACE] registering with poller
[2020-09-30][20:51:19:924474000][mio::sys::unix::kqueue][TRACE] registering; token=Token(1); interests=Readable
[2020-09-30][20:51:57:824443000][bottom][TRACE] Input thread received an event: Key(KeyEvent { code: Char('q'), modifiers: NONE })
[2020-09-30][20:51:57:824610000][bottom][TRACE] Input thread sent data.
[2020-09-30][20:51:57:824627000][btm][TRACE] Main/drawing thread received event: KeyInput(
    KeyEvent {
        code: Char(
            'q',
        ),
        modifiers: NONE,
    },
)
[2020-09-30][20:51:57:824774000][btm][TRACE] Main/drawing thread is cleaning up.
[2020-09-30][20:51:57:824686000][bottom][TRACE] Waiting for an input event...

[ClementTsang]

Well. That's interesting. Seems like the data collection thread is entirely not running? I'll try looking into it more tomorrow.

[ClementTsang]

@r-burns would it be possible for you to try cloning from master and running cargo r -- --debug again? Added a bit more tracing to help debug.

[r-burns]

Hmm when I exit the TUI with 'q' now I don't get my shell prompt back, even using ^C and ^D - had to ^Z and kill -9 the process. Anyway here's the log:

[2020-10-02][00:02:38:387367000][btm][TRACE] Config path: Some("/Users/rtburns/Library/Application Support/bottom/bottom.toml")
[2020-10-02][00:02:38:390140000][btm][TRACE] Current config: Config {
    flags: Some(
        ConfigFlags {
            hide_avg_cpu: None,
            dot_marker: None,
            temperature_type: None,
            rate: None,
            left_legend: None,
            current_usage: None,
            group_processes: None,
            case_sensitive: None,
            whole_word: None,
            regex: None,
            default_widget: None,
            basic: None,
            default_time_value: None,
            time_delta: None,
            autohide_time: None,
            hide_time: None,
            default_widget_type: None,
            default_widget_count: None,
            use_old_network_legend: None,
            hide_table_gap: None,
            battery: None,
            disable_click: None,
            no_write: None,
            search_case_enabled_widgets_map: None,
            search_case_enabled_widgets: None,
            search_whole_word_enabled_widgets_map: None,
            search_whole_word_enabled_widgets: None,
            search_regex_enabled_widgets_map: None,
            search_regex_enabled_widgets: None,
        },
    ),
    colors: Some(
        ConfigColours {
            table_header_color: None,
            all_cpu_color: None,
            avg_cpu_color: None,
            cpu_core_colors: None,
            ram_color: None,
            swap_color: None,
            rx_color: None,
            tx_color: None,
            rx_total_color: None,
            tx_total_color: None,
            border_color: None,
            highlighted_border_color: None,
            text_color: None,
            selected_text_color: None,
            selected_bg_color: None,
            widget_title_color: None,
            graph_color: None,
            battery_colors: None,
        },
    ),
    row: None,
    disk_filter: None,
    temp_filter: None,
}
[2020-10-02][00:02:38:392467000][bottom][TRACE] Creating input thread.
[2020-10-02][00:02:38:392575000][btm][TRACE] Initializing cleaning thread...
[2020-10-02][00:02:38:392627000][bottom][TRACE] Spawned input thread.
[2020-10-02][00:02:38:392641000][bottom][TRACE] Creating collection thread.
[2020-10-02][00:02:38:392804000][bottom][TRACE] Spawned collection thread.
[2020-10-02][00:02:38:392863000][mio::sys::unix::kqueue][TRACE] registering; token=Token(18446744073709551615); interests=Readable
[2020-10-02][00:02:38:392973000][mio::poll][TRACE] registering with poller
[2020-10-02][00:02:38:393018000][mio::sys::unix::kqueue][TRACE] registering; token=Token(0); interests=Readable
[2020-10-02][00:02:38:393247000][mio::poll][TRACE] registering with poller
[2020-10-02][00:02:38:393301000][mio::sys::unix::kqueue][TRACE] registering; token=Token(1); interests=Readable
[2020-10-02][00:02:53:274755000][bottom][TRACE] Input thread received an event: Key(KeyEvent { code: Char('q'), modifiers: NONE })
[2020-10-02][00:02:53:274889000][bottom][TRACE] Input thread sent keyboard data.
[2020-10-02][00:02:53:274942000][btm][TRACE] Main/drawing thread received event: KeyInput(KeyEvent { code: Char('q'), modifiers: NONE })
[2020-10-02][00:02:53:275025000][btm][TRACE] Send termination thread locks.
[2020-10-02][00:02:53:275077000][btm][TRACE] Notifying all cvars.
[2020-10-02][00:02:53:275145000][btm][TRACE] Received termination lock in cleaning thread from cvar!
[2020-10-02][00:02:53:275252000][btm][TRACE] Cleaning thread loop has closed.
[2020-10-02][00:02:53:275214000][btm][TRACE] Main/drawing thread is cleaning up.
[2020-10-02][00:02:53:299077000][bottom][TRACE] Received termination lock in input thread!
[2020-10-02][00:02:53:299202000][bottom][TRACE] Input thread loop has closed.

[ClementTsang]

Well, I guess this confirms that for some odd reason, the loop that handles data collection is entirely not running, otherwise it should have properly shut down. The fact that you got stuck when closing the app would mean (I think) the thread never ran the loop somehow.

I'll take a look again after work.

[ClementTsang]

@r-burns Sorry that I have to ask this of you again, but could you pull and switch to the threading_debugging_v3 branch, and try running cargo r -- --debug again?

If it does fail, can you try cloning https://github.com/GuillaumeGomez/sysinfo, cding to examples, and running cargo run and tell me if it works?

I'm pretty sure I know where it's breaking now but I'm not sure why it's doing it, nor can I replicate locally which is really confusing me.

[r-burns]

Interesting, thanks. I tried your branch, and it still hung. I tried the upstream sysinfo example, and it also hung. But then I tried an old commit of sysinfo, and it worked!? So I was able to run a bisect, and I think https://github.com/GuillaumeGomez/sysinfo/commit/d10a56d7e86a30e8390df67a782b0e27180949b3 is the culprit, despite looking benign to me. So I think I'll need to take this upstream, and get back to you. Thanks for all your help :)

[ClementTsang]

Thanks for taking the time into helping me look into this - this issue was quite a wild ride, haha.

[up-to-you]

Same on Catalina 10.15.7. It has non deterministic behaviour. Waiting for 0.5.0 to test it.

[r-burns]

@up-to-you, can you check if older versions of sysinfo (i.e. prior to https://github.com/GuillaumeGomez/sysinfo/commit/d10a56d7e86a30e8390df67a782b0e27180949b3) fix the issue for you? If so, maybe you can help us resolve this upstream :)

[up-to-you]

I can confirm, that using version 0.5.1 solves the issue

[up-to-you]

Nope (( It suddenly reproduces again - like bottom need to warm up on the first start or after long sleep phase. If i reinstall bottom package (via brew) - it starts without any delay. I will try to investigate it.