Grin node 5.1.0 won't launch on Linux

[nthrow]

Describe the bug
Grin node v5.1.0 will not launch on Debian Buster, returning "Illegal instruction" to stdout.

To Reproduce

$ grin
Illegal instruction
$ echo $?
132
$ ps aux |grep -E '[g]rin'
$ 

Relevant Information

20210506 16:53:04.446 INFO grin_util::logger - log4rs is initialized, file level: Debug, stdout level: Warn, min. level: Debug                                                                                      
20210506 16:53:04.447 INFO grin - Using configuration file at /home/$USER/.grin/main/grin-server.toml
20210506 16:53:04.447 INFO grin - This is Grin version 5.1.0 (git v5.1.0), built for x86_64-unknown-linux-gnu by rustc 1.51.0 (2fd73fabe 2021-03-23).                                                               
20210506 16:53:04.448 DEBUG grin - Built with profile "release", features "".
20210506 16:53:04.448 INFO grin - Chain: Mainnet
20210506 16:53:04.448 INFO grin - Accept Fee Base: 500000
20210506 16:53:04.449 INFO grin - Future Time Limit: 300
20210506 16:53:04.449 INFO grin - Feature: NRD kernel enabled: false
20210506 16:53:04.449 WARN grin::cmd::server - Starting GRIN in UI mode...
20210506 16:53:04.450 INFO grin_servers::grin::server - Starting server, genesis block: 40adad0aec27
20210506 16:53:04.451 DEBUG grin_store::lmdb - DB Mapsize for /home/$USER/.grin/main/chain_data/lmdb is 549755813888

Desktop (please complete the following information):

$ cat /etc/os-release
PRETTY_NAME="Debian GNU/Linux 10 (buster)"
NAME="Debian GNU/Linux"
VERSION_ID="10"
VERSION="10 (buster)"
VERSION_CODENAME=buster
ID=debian
HOME_URL="https://www.debian.org/"
SUPPORT_URL="https://www.debian.org/support"
BUG_REPORT_URL="https://bugs.debian.org/"

[nthrow]

I just tried compiling from source on a Void Linux machine. Still unable to run the node - here's a sanitized verbose stacktrace (the compilation steps are truncated for brevity's sake):

~/b/g/grin (master)> git checkout -b 5.1.0 v5.1.0
~/b/g/grin (5.1.0)> cargo build --release
...
   Compiling grin_core v5.1.0 (/opt/$USER/bench/gitrepos/grin/core)
   Compiling grin_store v5.1.0 (/opt/$USER/bench/gitrepos/grin/store)
   Compiling grin_pool v5.1.0 (/opt/$USER/bench/gitrepos/grin/pool)
   Compiling grin_chain v5.1.0 (/opt/$USER/bench/gitrepos/grin/chain)
   Compiling grin_p2p v5.1.0 (/opt/$USER/bench/gitrepos/grin/p2p)
   Compiling grin_api v5.1.0 (/opt/$USER/bench/gitrepos/grin/api)
   Compiling grin_servers v5.1.0 (/opt/$USER/bench/gitrepos/grin/servers)
   Compiling grin_config v5.1.0 (/opt/$USER/bench/gitrepos/grin/config)
    Finished release [optimized] target(s) in 5m 18s
~/b/g/grin (5.1.0)> set -x RUST_BACKTRACE full
~/b/g/grin (5.1.0)> ./target/release/grin
thread 'main' panicked at 'assertion failed: `(left == right)`
  left: `ConfigMembers { config_file_version: Some(2), server: ServerConfig { db_root: "/home/$USER/.grin/main/chain_data", api_http_addr: "127.0.0.1:3413", api_secret_path: Some("/home/$USER/.grin/main/.api_secret"), foreign_api_secret_path: None, tls_certificate_file: None, tls_certificate_key: None, chain_type: Mainnet, future_time_limit: 300, chain_validation_mode: Disabled, archive_mode: Some(false), skip_sync_wait: Some(false), run_tui: Some(true), run_test_miner: Some(false), test_miner_wallet_url: None, p2p_config: P2PConfig { host: 0.0.0.0, port: 3414, seeding_type: DNSSeed, seeds: None, peers_allow: None, peers_deny: None, peers_preferred: Some(PeerAddrs { peers: [PeerAddr(45.77.150.172:3414)] }), ban_window: None, peer_max_inbound_count: None, peer_max_outbound_count: None, peer_min_preferred_outbound_count: None, peer_listener_buffer_count: None, dandelion_peer: None }, pool_config: PoolConfig { accept_fee_base: 500000, reorg_cache_period: 30, max_pool_size: 50000, max_stempool_size: 50000, mineable_max_weight: 39976 }, dandelion_config: DandelionConfig { epoch_secs: 600, embargo_secs: 180, aggregation_secs: 30, stem_probability: 90, always_stem_our_txs: true }, stratum_mining_config: Some(StratumServerConfig { enable_stratum_server: Some(false), stratum_server_addr: Some("127.0.0.1:3416"), attempt_time_per_block: 15, minimum_share_difficulty: 1, wallet_listener_url: "http://127.0.0.1:3415", burn_reward: false }), webhook_config: WebHooksConfig { tx_received_url: None, header_received_url: None, block_received_url: None, block_accepted_url: None, nthreads: 4, timeout: 10 } }, logging: Some(LoggingConfig { log_to_stdout: true, stdout_log_level: Warn, log_to_file: true, file_log_level: Debug, log_file_path: "/home/$USER/.grin/main/grin-server.log", log_file_append: true, log_max_size: Some(16777216), log_max_files: None, tui_running: None }) }`,
 right: `ConfigMembers { config_file_version: None, server: ServerConfig { db_root: "/home/$USER/.grin/main/chain_data", api_http_addr: "127.0.0.1:3413", api_secret_path: Some("/home/$USER/.grin/main/.api_secret"), foreign_api_secret_path: None, tls_certificate_file: None, tls_certificate_key: None, chain_type: Mainnet, future_time_limit: 300, chain_validation_mode: Disabled, archive_mode: Some(false), skip_sync_wait: Some(false), run_tui: Some(true), run_test_miner: Some(false), test_miner_wallet_url: None, p2p_config: P2PConfig { host: 0.0.0.0, port: 3414, seeding_type: DNSSeed, seeds: None, peers_allow: None, peers_deny: None, peers_preferred: Some(PeerAddrs { peers: [PeerAddr(45.77.150.172:3414)] }), ban_window: None, peer_max_inbound_count: None, peer_max_outbound_count: None, peer_min_preferred_outbound_count: None, peer_listener_buffer_count: None, dandelion_peer: None }, pool_config: PoolConfig { accept_fee_base: 500000, reorg_cache_period: 30, max_pool_size: 50000, max_stempool_size: 50000, mineable_max_weight: 39976 }, dandelion_config: DandelionConfig { epoch_secs: 600, embargo_secs: 180, aggregation_secs: 30, stem_probability: 90, always_stem_our_txs: true }, stratum_mining_config: Some(StratumServerConfig { enable_stratum_server: Some(false), stratum_server_addr: Some("127.0.0.1:3416"), attempt_time_per_block: 15, minimum_share_difficulty: 1, wallet_listener_url: "http://127.0.0.1:3415", burn_reward: false }), webhook_config: WebHooksConfig { tx_received_url: None, header_received_url: None, block_received_url: None, block_accepted_url: None, nthreads: 4, timeout: 10 } }, logging: Some(LoggingConfig { log_to_stdout: true, stdout_log_level: Warn, log_to_file: true, file_log_level: Debug, log_file_path: "/home/$USER/.grin/main/grin-server.log", log_file_append: true, log_max_size: Some(16777216), log_max_files: None, tui_running: None }) }`', config/src/config.rs:345:9
stack backtrace:
   0:     0x55a5cfe1e8e0 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::hc5cc02b3e453225b
   1:     0x55a5cfe42b9c - core::fmt::write::h5437b03347b2ec7a
   2:     0x55a5cfe15855 - std::io::Write::write_fmt::h16241c6ed218e16f
   3:     0x55a5cfe2129d - std::panicking::default_hook::{{closure}}::h345f4275bb854b6c
   4:     0x55a5cfe20f48 - std::panicking::default_hook::he532b712c71e2106
   5:     0x55a5cfe21981 - std::panicking::rust_panic_with_hook::hf0f7347c753b38c2
   6:     0x55a5cfe21529 - std::panicking::begin_panic_handler::{{closure}}::h274b8a0752683642
   7:     0x55a5cfe1ed4c - std::sys_common::backtrace::__rust_end_short_backtrace::hdb383c60eb8b212f
   8:     0x55a5cfe214e9 - rust_begin_unwind
   9:     0x55a5cfe2149b - std::panicking::begin_panic_fmt::h9146b8c084253738
  10:     0x55a5cf6bd218 - grin_config::config::<impl grin_config::types::GlobalConfig>::new::h1549fe7b247d1719
  11:     0x55a5cf6cf5a9 - grin_config::config::initial_setup_server::h1f16149dea01f682
  12:     0x55a5cf652759 - grin::real_main::h61b22fcdb21fa49f
  13:     0x55a5cf652386 - grin::main::hdac5ca89aa8c7e5e
  14:     0x55a5cf67cf93 - std::sys_common::backtrace::__rust_begin_short_backtrace::h5468feec152df961
  15:     0x55a5cf64d4d9 - std::rt::lang_start::{{closure}}::hcda6ca882101b4e4
  16:     0x55a5cfe21da7 - std::rt::lang_start_internal::h0c3fae9f987cf9c0
  17:     0x55a5cf6554a2 - main
  18:     0x7f75db92ae0a - __libc_start_main
                               at /builddir/glibc-2.32/csu/../csu/libc-start.c:314
  19:     0x55a5cf6063aa - _start
  20:                0x0 - <unknown>

[tromp]

The failing assert while constructing a new GlobalConfig is from here:

grin/config/src/config.rs

Lines 345 to 348 in 9e27e6f

	assert_eq!(
	config,
	toml::from_str(&GlobalConfig::fix_warning_level(config_str.clone())).unwrap()
	);

and related to the rewritten grin-server.toml configuration file.

[MCM-Mike]

To Reproduce
$ grin
Illegal instruction
$ echo $?
132
$ ps aux |grep -E '[g]rin'
$

Did you setup the GRIN server using

./grin server config

and started it as shown in grin --help ?

_$ grin server -c grin-server.toml run 

[nthrow]

Did you setup the GRIN server using

./grin server config

Yes, I have been using the same grin-server.toml essentially since the network launch.

Specifying the config as such returns the same error I posted above:

~/b/g/grin (5.1.0)> ./target/release/grin server -c ~/.grin/main/grin-server.toml run

[MCM-Mike]

Yes, I have been using the same grin-server.toml essentially since the network launch.

Keep in mind there is a config change in 5.1.0 see #3634 where you need to change the config file slightly but this should not really be a problem, if I am correctly informed.

[nthrow]

Okay, prepending config_file_version = 2 to the top of my grin-server.toml sorted the issue.

[MCM-Mike]

But to share my problems on Debian I had similar problems on Debian 9, but different error.
As I am running quite a few nodes, it was essential that the nightly compiling where not interrupted and we could upgrade our main grin-nodes to latest version. Therefore I did some manual tests with Debian 9 which failed, I also was not changing anything nor upgrading any dependencies.

On Debian 9 when trying to compile like usually, I got this error:
error: failed to run custom build command for croaring-sys v0.4.6
(see detail error log here: https://gist.github.com/MCM-Mike/e326734bed9e6965f95d2700179ec13c

What I ended up doing was upgrading all nodes to latest Debian 10 (buster) from Debian 9 using:
(changing source list, etc this is not a tutorial on how to upgrade Debian)

sudo apt update
sudo apt upgrade
sudo apt full-upgrade
sudo apt --purge autoremove

Then I updated rust using /root/.cargo/bin/rustup update and checked out the latest version from github via:

/usr/bin/git fetch
/usr/bin/git pull
/usr/bin/git checkout master
/usr/bin/git fetch --tags
latestTag=$(git tag --sort=refname | grep -v -e "beta" -e "rc"| tail -n 1)
/usr/bin/git checkout $latestTag

and compiled sucessfully on Debian 10 with:

/root/.cargo/bin/cargo clean
/root/.cargo/bin/cargo build --release

current Debian 10:

PRETTY_NAME="Debian GNU/Linux 10 (buster)"
NAME="Debian GNU/Linux"
VERSION_ID="10"
VERSION="10 (buster)"
VERSION_CODENAME=buster
ID=debian
HOME_URL="https://www.debian.org/"
SUPPORT_URL="https://www.debian.org/support"
BUG_REPORT_URL="https://bugs.debian.org/"

_$ uname -a
Linux XXXX.grinnode.live 4.19.0-16-amd64 #1 SMP Debian 4.19.181-1 (2021-03-19) x86_64 GNU/Linux

_$ clang --version
Debian clang version 13.0.0-++20210418102931+6e8e165085d4-1~exp1~20210418203651.2635
Target: x86_64-pc-linux-gnu
Thread model: posix
InstalledDir: /usr/bin

_$ rustc --version
rustc 1.52.0 (88f19c6da 2021-05-03)

[antiochp]

Related: #3634

@trevyn Is there an edge case here where the config file migration is not behaving as expected?

Are we handling the case where the config file is elsewhere? I wonder if we are potentially (re)writing in a different location.

Edit: @phyro pointed out the actual replace logic is maybe a little brittle as it makes some assumptions about file contents -

let config_str = config_str.replace("\n#########################################\n### SERVER CONFIGURATION ###", "\nconfig_file_version = 2\n\n#########################################\n### SERVER CONFIGURATION ###");

We want to support minimal config files etc that may not necessarily have that comment in there.

[nthrow]

To clarify: adding the config_file_version = 2 to the top of my grin-server.toml sorted the issue on Void Linux.

Following up on Debian 10, adding that changed nothing. Then, removing the old server toml, generating a new one via grin server config, adjusting what I needed to, and trying to start the server fails - but this time, with nothing returned to stderr or stdout, nor to the grin-server.log.

Please let me know if I can provide any further debug info.

[phyro]

@nthrow grin-server.toml has two settings to control the level of logging: stdout_log_level and file_log_level which both default to values that don't tell everything they see. Perhaps changing it to "Debug" will give more information about the error. Make sure to check the debug doesn't leak any of your personal information if you decide to share it here.

[antiochp]

As far as I can tell the only thing that changed that might cause something along the line of "Illegal Instruction" is -
#3596

@trevyn Any ideas if this may be related?

[ghost]

Same issue on Debian 11 (bullseye).
$ ./grin
Illegal instruction

I have "config_file_version = 2" line at the start of my grin-server.toml file.

[bladedoyle]

Core was generated by `/tmp/grin-v5.1.0-official'.
Program terminated with signal SIGILL, Illegal instruction.
#0  0x00005648256d4423 in ra_portable_serialize ()
(gdb) where
#0  0x00005648256d4423 in ra_portable_serialize ()
#1  0x000056482567d73b in grin_store::save_via_temp_file ()
#2  0x000056482567cdbc in grin_store::leaf_set::LeafSet::flush ()
#3  0x0000564825618fa1 in grin_store::pmmr::PMMRBackend<T>::sync ()
#4  0x00005648255e563c in grin_chain::txhashset::txhashset::extending ()
#5  0x0000564825632b10 in grin_chain::chain::Chain::init ()
#6  0x0000564825152051 in grin_servers::grin::server::Server::new ()
#7  0x0000564825050b04 in grin_servers::grin::server::Server::start ()
#8  0x0000564825061b31 in grin::cmd::server::start_server_tui ()
#9  0x0000564825062fee in grin::cmd::server::server_command ()
#10 0x000056482504df8e in grin::real_main ()
#11 0x000056482504c0f6 in grin::main ()


(gdb) layout asm

  >│0x5648256d4423 <ra_portable_serialize+355>      vpxord %zmm4,%zmm4,%zmm4   │

so we have an avx512 instruction?
https://en.wikipedia.org/wiki/AVX-512
Legacy instructions upgraded with EVEX encoded versions

Legacy encoding - sse sse2 mmx  | avx sse3 sse4.1 | avx2 fma    | Group | Instructions | AVX-512extensions
--------------------------------------------------------------------------------

Yes | Yes | Yes  | VPXOR | VPXORD, VPXORQ | F, VL

[bladedoyle]

It looks like this is because we use the "-march=native" flag when building croaring.
A similar issue is described here:
#2494 (comment)

bdoyle@lucy:~/dev/grin/target/release/build$ git status
HEAD detached at v5.1.0
bdoyle@lucy:~/dev/grin/target/release$ grep native ./build/croaring-sys-07b6100f886b91b1/output
running: "cc" "-O3" "-ffunction-sections" "-fdata-sections" "-fPIC" "-m64" "-Wall" "-Wextra" "-march=native" "-o" "/home/bdoyle/dev/grin/target/release/build/croaring-sys-07b6100f886b91b1/out/CRoaring/roaring.o" "-c" "CRoaring/roaring.c"
cargo:rustc-link-search=native=/home/bdoyle/dev/grin/target/release/build/croaring-sys-07b6100f886b91b1/out

[GeneFerneau]

I cannot reproduce this issue. On debian 10.8, I built grin/v5.1.0, created a new config, and started the node without issue.

What version of clang and librust-clang-sys-dev do you have installed?

[bladedoyle]

I dont believe this is related to linux version or rust version. I think we are building an avx256 instruction into the binary (because croaring is built using native arch, and the CI/CD build system used to produce the grin release binary supports that instruction) which is not supported by very old CPU.
I am able to reproduce it using an old laptop.

It looks like we used to keep our own fork of croaring, and in that fork we fix this issue:
mimblewimble/croaring-rs@444e817

We de-forked it here:
431e4b9

In the upstream croaring project I see:
https://github.com/saulius/croaring-rs/blob/master/croaring-sys/build.rs

    if let Ok(target_arch) = env::var("ROARING_ARCH") {
                build.flag_if_supported(&format!("-march={}", target_arch));      
            }

so that should allow us to pass in the arch we want to target.
I see that we are passing in:
ROARING_ARCH=x86-64-v2

[GeneFerneau]

I dont believe this is related to linux version or rust version. I think we are building an avx256 instruction into the binary (because croaring is built using native arch, and the CI/CD build system used to produce the grin release binary supports that instruction) which is not supported by very old CPU.

So, what CPU is @nthrow using? And do we want to bother supporting systems with such old CPUs?

[nthrow]

I'm not sure that's the issue as I'm currently on an AMD Ryzen 5 PRO 4650U.

[ghost]

My CPU is Intel i5-9400F

[tromp]

Ideally, a binary would check if avx2 support is present before using those instructions. But if croaring is lacking the smarts to do that, then we should avoid avx2 altogether. There's still a significant number of CPUs without avx2 that I think we should support.

[quentinlesceller]

Can confirm the binary isn't working on my i7 running Debian 10.9 in docker. But compiling from source works. I suspect a croaring issue.

[bladedoyle]

There may be more than one issue here?

I found that the first time running the new binary on an old cpu gives the "illegal instruction" crash.
Leading up to that crash, parts of the chain database have been written, but its left in a bad state.
Running grin again results in a different crash.
Its necessary to delete the bad chain database before being able to reproduce the illegal instruction crash.

root@crypto:~/.grin/main# rm -rf *
root@crypto:~/.grin/main# /tmp/grin-v5.1.0-official
Illegal instruction (core dumped)
root@crypto:~/.grin/main# /tmp/grin-v5.1.0-official
root@crypto:~/.grin/main# tail -n 40 grin-server.log
20210520 11:17:13.290 INFO grin_servers::grin::server - Starting server, genesis block: 40adad0aec27
20210520 11:17:13.290 INFO grin_store::lmdb - Resized database from 1048576 to 134217728
20210520 11:17:13.320 ERROR grin_util::logger - 
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: Chain(Error { inner: 

Other Error: output vs rproof MMRs different sizes })': src/bin/cmd/server.rs:57   0: grin_util::logger::send_panic_to_log::{{closure}}
   1: std::panicking::rust_panic_with_hook
             at /rustc/2fd73fabe469357a12c2c974c140f67e7cdd76d0/library/std/src/panicking.rs:595
   2: std::panicking::begin_panic_handler::{{closure}}
             at /rustc/2fd73fabe469357a12c2c974c140f67e7cdd76d0/library/std/src/panicking.rs:497
   3: std::sys_common::backtrace::__rust_end_short_backtrace
             at /rustc/2fd73fabe469357a12c2c974c140f67e7cdd76d0/library/std/src/sys_common/backtrace.rs:141
   4: rust_begin_unwind
             at /rustc/2fd73fabe469357a12c2c974c140f67e7cdd76d0/library/std/src/panicking.rs:493
   5: core::panicking::panic_fmt
             at /rustc/2fd73fabe469357a12c2c974c140f67e7cdd76d0/library/core/src/panicking.rs:92
   6: core::option::expect_none_failed
             at /rustc/2fd73fabe469357a12c2c974c140f67e7cdd76d0/library/core/src/option.rs:1300
   7: grin::cmd::server::start_server_tui
   8: grin::cmd::server::server_command
   9: grin::real_main
  10: grin::main
  11: std::sys_common::backtrace::__rust_begin_short_backtrace
  12: std::rt::lang_start::{{closure}}
  13: core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once
             at /rustc/2fd73fabe469357a12c2c974c140f67e7cdd76d0/library/core/src/ops/function.rs:259
      std::panicking::try::do_call
             at /rustc/2fd73fabe469357a12c2c974c140f67e7cdd76d0/library/std/src/panicking.rs:379
      std::panicking::try
             at /rustc/2fd73fabe469357a12c2c974c140f67e7cdd76d0/library/std/src/panicking.rs:343
      std::panic::catch_unwind
             at /rustc/2fd73fabe469357a12c2c974c140f67e7cdd76d0/library/std/src/panic.rs:431
      std::rt::lang_start_internal
             at /rustc/2fd73fabe469357a12c2c974c140f67e7cdd76d0/library/std/src/rt.rs:51
  14: main
  15: __libc_start_main
  16: _start
root@crypto:~/.grin/main# rm -rf *
root@crypto:~/.grin/main# /tmp/grin-v5.1.0-official
Illegal instruction (core dumped)

[bladedoyle]

I think I read in the past that "march" isnt the only compiler flag that impacts which instructions are used. The optimization setting (-On) can also cause AVX2 instructions to be used.

Here is a blurb that says something like that?
https://wiki.gentoo.org/wiki/GCC_optimization#-march

With -O2, the compiler will attempt to increase code performance without compromising on size, and without taking too much compilation time. SSE or AVX may be utilized at this level 
...
-O3 is also known to break several packages. Using -O3 is not recommended. However, it also enables -ftree-vectorize so that loops in the code get vectorized and will use AVX YMM registers.

Note that it appears croaring uses -O3 ?

---

I also see that croaring (under the rs wrapper) supports a flag for not using AVX:
https://github.com/RoaringBitmap/CRoaring/blob/master/CMakeLists.txt

option(ROARING_DISABLE_X64 "Forcefully disable x64 optimizations even if hardware supports it (this disables AVX)" OFF)
option(ROARING_DISABLE_AVX "Forcefully disable AVX even if hardware supports it " OFF)
(ROARING_DISABLE_NATIVE <span class="pl-s">"Forcefully disable -march optimizations (obsolete)"OFF")

We should try using those.

[tromp]

Thanks for investigating, Blade.

+1 on using ROARING_DISABLE_AVX

I guess that will add a -mno-avx flag to gcc.

[quentinlesceller]

Good catch @antiochp. This is now fixed by #3644. This binary should run fine on linux https://github.com/quentinlesceller/grin/releases/tag/v5.1.0-test3.