simple_kill_streaming_node_while_bootstrapping_test: Startup failed: std::runtime_error ({shard 0: fmt::v6::format_error (invalid type specifier), shard 1: fmt::v6::format_error (invalid type specifier)})']) #6874

bhalevy · 2020-07-19T11:42:10Z

Seen several time recently in next runs:
https://jenkins.scylladb.com/view/master/job/scylla-master/job/next/2255/testReport/update_cluster_layout_tests/TestUpdateClusterLayout/dtest___simple_kill_streaming_node_while_bootstrapping_test/
https://jenkins.scylladb.com/view/master/job/scylla-master/job/next/2258/testReport/update_cluster_layout_tests/TestUpdateClusterLayout/dtest___simple_kill_streaming_node_while_bootstrapping_test/
https://jenkins.scylladb.com/view/master/job/scylla-master/job/next/2262/testReport/update_cluster_layout_tests/TestUpdateClusterLayout/dtest___simple_kill_streaming_node_while_bootstrapping_test/

Unexpected errors found: [('node4', ['ERROR 2020-07-19 10:22:46,706 [shard 0] init - Startup failed: std::runtime_error ({shard 0: fmt::v6::format_error (invalid type specifier), shard 1: fmt::v6::format_error (invalid type specifier)})'])]

https://jenkins.scylladb.com/view/master/job/scylla-master/job/next/2262/artifact/logs-release.2/1595154166737_update_cluster_layout_tests.TestUpdateClusterLayout.simple_kill_streaming_node_while_bootstrapping_test/node4.log

...
WARN  2020-07-19 10:22:44,017 [shard 0] repair - repair id [id=4, uuid=0b1092a1-061f-4691-b0ac-547b281ef09d] on shard 0 failed: fmt::v6::format_error (invalid type specifier)
...
WARN  2020-07-19 10:22:46,678 [shard 1] repair - repair id [id=4, uuid=0b1092a1-061f-4691-b0ac-547b281ef09d] on shard 1 failed - 1001 ranges failed
WARN  2020-07-19 10:22:46,678 [shard 1] repair - repair id [id=4, uuid=0b1092a1-061f-4691-b0ac-547b281ef09d] on shard 1 failed: fmt::v6::format_error (invalid type specifier)
INFO  2020-07-19 10:22:46,678 [shard 1] compaction - [Compact ks.cf ca2c5360-c9a9-11ea-91d4-000000000001] Compacting [/jenkins/workspace/scylla-master/next/scylla/.dtest/dtest-9ed_plr4/test/node4/data/ks/cf-8a0b8c10c9a911ea859a000000000001/mc-713-big-Data.db:level=0, /jenkins/workspace/scylla-master/next/scylla/.dtest/dtest-9ed_plr4/test/node4/data/ks/cf-8a0b8c10c9a911ea859a000000000001/mc-715-big-Data.db:level=0, /jenkins/workspace/scylla-master/next/scylla/.dtest/dtest-9ed_plr4/test/node4/data/ks/cf-8a0b8c10c9a911ea859a000000000001/mc-737-big-Data.db:level=0, /jenkins/workspace/scylla-master/next/scylla/.dtest/dtest-9ed_plr4/test/node4/data/ks/cf-8a0b8c10c9a911ea859a000000000001/mc-735-big-Data.db:level=0, /jenkins/workspace/scylla-master/next/scylla/.dtest/dtest-9ed_plr4/test/node4/data/ks/cf-8a0b8c10c9a911ea859a000000000001/mc-709-big-Data.db:level=0, /jenkins/workspace/scylla-master/next/scylla/.dtest/dtest-9ed_plr4/test/node4/data/ks/cf-8a0b8c10c9a911ea859a000000000001/mc-711-big-Data.db:level=0, /jenkins/workspace/scylla-master/next/scylla/.dtest/dtest-9ed_plr4/test/node4/data/ks/cf-8a0b8c10c9a911ea859a000000000001/mc-717-big-Data.db:level=0, /jenkins/workspace/scylla-master/next/scylla/.dtest/dtest-9ed_plr4/test/node4/data/ks/cf-8a0b8c10c9a911ea859a000000000001/mc-719-big-Data.db:level=0, /jenkins/workspace/scylla-master/next/scylla/.dtest/dtest-9ed_plr4/test/node4/data/ks/cf-8a0b8c10c9a911ea859a000000000001/mc-721-big-Data.db:level=0, /jenkins/workspace/scylla-master/next/scylla/.dtest/dtest-9ed_plr4/test/node4/data/ks/cf-8a0b8c10c9a911ea859a000000000001/mc-725-big-Data.db:level=0, /jenkins/workspace/scylla-master/next/scylla/.dtest/dtest-9ed_plr4/test/node4/data/ks/cf-8a0b8c10c9a911ea859a000000000001/mc-723-big-Data.db:level=0, /jenkins/workspace/scylla-master/next/scylla/.dtest/dtest-9ed_plr4/test/node4/data/ks/cf-8a0b8c10c9a911ea859a000000000001/mc-729-big-Data.db:level=0, /jenkins/workspace/scylla-master/next/scylla/.dtest/dtest-9ed_plr4/test/node4/data/ks/cf-8a0b8c10c9a911ea859a000000000001/mc-727-big-Data.db:level=0, /jenkins/workspace/scylla-master/next/scylla/.dtest/dtest-9ed_plr4/test/node4/data/ks/cf-8a0b8c10c9a911ea859a000000000001/mc-733-big-Data.db:level=0, /jenkins/workspace/scylla-master/next/scylla/.dtest/dtest-9ed_plr4/test/node4/data/ks/cf-8a0b8c10c9a911ea859a000000000001/mc-731-big-Data.db:level=0, /jenkins/workspace/scylla-master/next/scylla/.dtest/dtest-9ed_plr4/test/node4/data/ks/cf-8a0b8c10c9a911ea859a000000000001/mc-707-big-Data.db:level=0, ]
WARN  2020-07-19 10:22:46,678 [shard 0] repair - repair id [id=4, uuid=0b1092a1-061f-4691-b0ac-547b281ef09d] failed: std::runtime_error ({shard 0: fmt::v6::format_error (invalid type specifier), shard 1: fmt::v6::format_error (invalid type specifier)})
WARN  2020-07-19 10:22:46,678 [shard 0] repair - repair id [id=4, uuid=0b1092a1-061f-4691-b0ac-547b281ef09d] to sync data for keyspace=ks, status=failed: std::runtime_error ({shard 0: fmt::v6::format_error (invalid type specifier), shard 1: fmt::v6::format_error (invalid type specifier)})
INFO  2020-07-19 10:22:46,679 [shard 0] init - Shutting down gossiping
INFO  2020-07-19 10:22:46,679 [shard 0] gossip - My status = BOOT
WARN  2020-07-19 10:22:46,679 [shard 0] gossip - No local state or state is in silent shutdown, not announcing shutdown
INFO  2020-07-19 10:22:46,679 [shard 0] gossip - Disable and wait for gossip loop started
INFO  2020-07-19 10:22:46,679 [shard 0] gossip - Disable and wait for gossip loop finished
INFO  2020-07-19 10:22:46,679 [shard 0] gossip - Gossip is now stopped
INFO  2020-07-19 10:22:46,679 [shard 0] init - Shutting down gossiping was successful
INFO  2020-07-19 10:22:46,679 [shard 0] init - Shutting down storage service notifications
INFO  2020-07-19 10:22:46,679 [shard 0] init - Shutting down storage service notifications was successful
INFO  2020-07-19 10:22:46,679 [shard 0] init - Shutting down repair service
INFO  2020-07-19 10:22:46,679 [shard 0] init - Shutting down repair service was successful
INFO  2020-07-19 10:22:46,679 [shard 0] init - Shutting down cdc
INFO  2020-07-19 10:22:46,679 [shard 0] init - Shutting down cdc was successful
INFO  2020-07-19 10:22:46,679 [shard 0] init - Shutting down sstables format selector
INFO  2020-07-19 10:22:46,679 [shard 0] init - Shutting down sstables format selector was successful
INFO  2020-07-19 10:22:46,679 [shard 0] init - Shutting down migration manager
INFO  2020-07-19 10:22:46,679 [shard 0] migration_manager - stopping migration service
INFO  2020-07-19 10:22:46,679 [shard 1] migration_manager - stopping migration service
INFO  2020-07-19 10:22:46,679 [shard 0] init - Shutting down migration manager was successful
INFO  2020-07-19 10:22:46,679 [shard 0] init - Shutting down database
INFO  2020-07-19 10:22:46,679 [shard 0] compaction_manager - Asked to stop
INFO  2020-07-19 10:22:46,679 [shard 0] compaction_manager - Stopping 0 ongoing compactions
INFO  2020-07-19 10:22:46,679 [shard 0] compaction_manager - Stopped
INFO  2020-07-19 10:22:46,679 [shard 1] compaction_manager - Asked to stop
INFO  2020-07-19 10:22:46,679 [shard 1] compaction_manager - Stopping 1 ongoing compactions
INFO  2020-07-19 10:22:46,680 [shard 1] compaction_manager - compaction info: Compaction for ks/cf was stopped due to: shutdown: stopping
INFO  2020-07-19 10:22:46,680 [shard 1] compaction_manager - Stopped
INFO  2020-07-19 10:22:46,705 [shard 0] init - Shutting down database: waiting for background jobs...
INFO  2020-07-19 10:22:46,705 [shard 0] init - Shutting down database was successful
INFO  2020-07-19 10:22:46,706 [shard 0] init - Shutting down API server
INFO  2020-07-19 10:22:46,706 [shard 0] init - Shutting down API server was successful
INFO  2020-07-19 10:22:46,706 [shard 0] init - Shutting down migration manager notifier
INFO  2020-07-19 10:22:46,706 [shard 0] init - Shutting down migration manager notifier was successful
INFO  2020-07-19 10:22:46,706 [shard 0] init - Shutting down prometheus API server
INFO  2020-07-19 10:22:46,706 [shard 0] init - Shutting down prometheus API server was successful
INFO  2020-07-19 10:22:46,706 [shard 0] init - Shutting down sighup
INFO  2020-07-19 10:22:46,706 [shard 0] init - Shutting down sighup was successful
ERROR 2020-07-19 10:22:46,706 [shard 0] init - Startup failed: std::runtime_error ({shard 0: fmt::v6::format_error (invalid type specifier), shard 1: fmt::v6::format_error (invalid type specifier)})

The text was updated successfully, but these errors were encountered:

asias · 2020-07-20T02:04:43Z

I will take a look.

bhalevy · 2020-07-20T07:00:48Z

I will take a look.

thanks.

Hit again BTW in https://jenkins.scylladb.com/view/master/job/scylla-master/job/next/2267/testReport/junit/update_cluster_layout_tests/TestUpdateClusterLayout/dtest___simple_kill_streaming_node_while_bootstrapping_test/

asias · 2020-07-20T07:08:01Z

I could not reproduce with the exact scylla version. I am building with the dbuild. The fmt version it uses: fmt-devel-6.2.1-1.fc32.x86_64.

I suspect it is libfmt related.

asias · 2020-07-20T07:12:06Z

The line in question was:

(id is of type repair_uniq_id)

 383         }).handle_exception([this, id] (std::exception_ptr ep) {
 384             rlogger.warn("repair id {} failed: {}", id, ep);

The print function for the repair_uniq_id is:

std::ostream& operator<<(std::ostream& os, const repair_uniq_id& x) {
    return os << format("[id={}, uuid={}]", x.id, x.uuid);
}

@avikivity Do you know if there is any limitation on recursive format() usage?

bhalevy · 2020-07-20T07:54:04Z

@asias we don't use format in seastar logger. See logger::really_do_log

bhalevy · 2020-07-20T07:57:03Z

Also, the following log message indicates that repair_uniq_id is printed just fine, no?

WARN  2020-07-19 10:22:44,017 [shard 0] repair - repair id [id=4, uuid=0b1092a1-061f-4691-b0ac-547b281ef09d] on shard 0 failed: fmt::v6::format_error (invalid type specifier)

asias · 2020-07-20T07:58:14Z

Also, the following log message indicates that repair_uniq_id is printed just fine, no?
WARN  2020-07-19 10:22:44,017 [shard 0] repair - repair id [id=4, uuid=0b1092a1-061f-4691-b0ac-547b281ef09d] on shard 0 failed: fmt::v6::format_error (invalid type specifier)

You are correct. The exception comes from somewhere else.

asias · 2020-07-20T07:58:53Z

@bhalevy Do you have a recent "good" commit?

asias · 2020-07-20T08:01:35Z

I think I know what is problem now:

throw std::runtime_error(format("repair id {:d} on shard {:d} failed to repair {:d} sub ranges", id, shard, nr_failed_ranges));

bhalevy · 2020-07-20T08:03:09Z

I think I know what is problem now:

throw std::runtime_error(format("repair id {:d} on shard {:d} failed to repair {:d} sub ranges", id, shard, nr_failed_ranges));

yes, I just saw it too...

bhalevy · 2020-07-20T08:03:27Z

in repair_info::check_failed_ranges right?

bhalevy · 2020-07-20T08:04:10Z

I'd leave the format specifiers out when not required....

asias · 2020-07-20T08:06:04Z

Yes, I am working on a patch.

We recently saw a weird log message: WARN 2020-07-19 10:22:46,678 [shard 0] repair - repair id [id=4, uuid=0b1092a1-061f-4691-b0ac-547b281ef09d] failed: std::runtime_error ({shard 0: fmt::v6::format_error (invalid type specifier), shard 1: fmt::v6::format_error (invalid type specifier)}) It turned out we have: throw std::runtime_error(format("repair id {:d} on shard {:d} failed to repair {:d} sub ranges", id, shard, nr_failed_ranges)); in the code, but we changed the id from integer to repair_uniq_id class. We do not really need to specify the format specifiers for numbers. Fixes scylladb#6874

asias · 2020-07-20T08:57:07Z

Patch sent: #6880

avikivity · 2020-07-21T05:50:38Z

No vulnerable branches.

bhalevy · 2020-07-21T07:39:40Z

Should be backported along with #6786 if the latter is ever backported.

bhalevy assigned asias Jul 19, 2020

bhalevy added tests/dtest area/repair area/repair-based operations repare based node operations labels Jul 19, 2020

asias mentioned this issue Jul 20, 2020

repair: Do not use libfmt format specifiers if not needed #6880

Closed

scylladb-promoter added the Backport candidate label Jul 20, 2020

scylladb-promoter closed this as completed in 28f8798 Jul 20, 2020

avikivity removed the Backport candidate label Jul 21, 2020

asias mentioned this issue Jul 30, 2020

Failure with repair when bootstrapping a node, but the error message failed to print #6886

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

simple_kill_streaming_node_while_bootstrapping_test: Startup failed: std::runtime_error ({shard 0: fmt::v6::format_error (invalid type specifier), shard 1: fmt::v6::format_error (invalid type specifier)})']) #6874

simple_kill_streaming_node_while_bootstrapping_test: Startup failed: std::runtime_error ({shard 0: fmt::v6::format_error (invalid type specifier), shard 1: fmt::v6::format_error (invalid type specifier)})']) #6874

bhalevy commented Jul 19, 2020

asias commented Jul 20, 2020

bhalevy commented Jul 20, 2020

asias commented Jul 20, 2020

asias commented Jul 20, 2020

bhalevy commented Jul 20, 2020

bhalevy commented Jul 20, 2020

asias commented Jul 20, 2020

asias commented Jul 20, 2020

asias commented Jul 20, 2020

bhalevy commented Jul 20, 2020

bhalevy commented Jul 20, 2020

bhalevy commented Jul 20, 2020

asias commented Jul 20, 2020

asias commented Jul 20, 2020

avikivity commented Jul 21, 2020

bhalevy commented Jul 21, 2020

simple_kill_streaming_node_while_bootstrapping_test: Startup failed: std::runtime_error ({shard 0: fmt::v6::format_error (invalid type specifier), shard 1: fmt::v6::format_error (invalid type specifier)})']) #6874

simple_kill_streaming_node_while_bootstrapping_test: Startup failed: std::runtime_error ({shard 0: fmt::v6::format_error (invalid type specifier), shard 1: fmt::v6::format_error (invalid type specifier)})']) #6874

Comments

bhalevy commented Jul 19, 2020

asias commented Jul 20, 2020

bhalevy commented Jul 20, 2020

asias commented Jul 20, 2020

asias commented Jul 20, 2020

bhalevy commented Jul 20, 2020

bhalevy commented Jul 20, 2020

asias commented Jul 20, 2020

asias commented Jul 20, 2020

asias commented Jul 20, 2020

bhalevy commented Jul 20, 2020

bhalevy commented Jul 20, 2020

bhalevy commented Jul 20, 2020

asias commented Jul 20, 2020

asias commented Jul 20, 2020

avikivity commented Jul 21, 2020

bhalevy commented Jul 21, 2020