tests: Added progress tracker when running fuzz test

kevkevinpal commented at 10:34 pm on April 25, 2025: contributor

Summary

Right now if you run test_runner.py on all the targets it is hard to tell how far you are in the progress even with --loglevel=DEBUG on. As it just spits out the target that was completed an no info on how many targets are left.

This change gives you a count down to the last target being run and some additional info provided by libfuzzer

This also applies when you use -g/--generate and --m_dir

Note

I can append this change to either change the percent increments or move it to the DEBUG logs instead if preferred

Example run

 0./build_fuzz/test/fuzz/test_runner.py ../qa-assets/fuzz_corpora
 1219 of 219 detected fuzz target(s) selected: addition_overflow addr_info_deserialize address_deserialize addrman addrman_serdeser asmap asmap_direct autofile banman base32_encode_decode base58_encode_decode base58check_encode_decode base64_encode_decode bech32_random_decode bech32_roundtrip bip324_cipher_roundtrip bip324_ecdh bitdeque bitset block block_deserialize block_file_info_deserialize block_filter_deserialize block_header block_header_and_short_txids_deserialize block_index blockfilter blockheader_deserialize blocklocator_deserialize blockmerkleroot blocktransactions_deserialize blocktransactionsrequest_deserialize blockundo_deserialize bloom_filter bloomfilter_deserialize buffered_file build_and_compare_feerate_diagram chacha20_split_crypt chacha20_split_keystream chain checkqueue clusterlin_ancestor_finder clusterlin_chunking clusterlin_components clusterlin_depgraph_serialization clusterlin_depgraph_sim clusterlin_fix_linearization clusterlin_linearization_chunking clusterlin_linearize clusterlin_make_connected clusterlin_merge clusterlin_postlinearize clusterlin_postlinearize_moved_leaf clusterlin_postlinearize_tree clusterlin_search_finder coin_grinder coin_grinder_is_optimal coincontrol coins_deserialize coins_view coinscache_sim coinselection_bnb coinselection_knapsack coinselection_srd connman crypter crypto crypto_aeadchacha20poly1305 crypto_aes256 crypto_aes256cbc crypto_chacha20 crypto_common crypto_diff_fuzz_chacha20 crypto_fschacha20 crypto_fschacha20poly1305 crypto_hkdf_hmac_sha256_l32 crypto_poly1305 crypto_poly1305_split cuckoocache data_stream_addr_man decode_tx descriptor_parse diskblockindex_deserialize ellswift_roundtrip ephemeral_package_eval eval_script fee_rate fee_rate_deserialize feefrac fees flat_file_pos_deserialize flatfile float golomb_rice headers_sync_state hex http_request i2p integer inv_deserialize key key_io key_origin_info_deserialize kitchen_sink load_external_block_file local_address locale merkle_block_deserialize merkleblock message messageheader_deserialize mini_miner mini_miner_selection miniscript_script miniscript_smart miniscript_stable miniscript_string minisketch mocked_descriptor_parse muhash multiplication_overflow natpmp_request_port_map net net_permissions netaddr_deserialize netaddress netbase_dns_lookup node_eviction num3072_inv num3072_mul out_point_deserialize overflow p2p_handshake p2p_headers_presync p2p_transport_bidirectional p2p_transport_bidirectional_v1v2 p2p_transport_bidirectional_v2 p2p_transport_serialization package_rbf parse_hd_keypath parse_iso8601 parse_numbers parse_script parse_univalue partial_merkle_tree_deserialize partially_downloaded_block partially_signed_transaction_deserialize pcp_request_port_map policy_estimator policy_estimator_io pool_resource pow pow_transition prefilled_transaction_deserialize prevector primitives_transaction process_message process_messages protocol psbt psbt_base64_decode psbt_input_deserialize psbt_output_deserialize pub_key_deserialize random rbf rolling_bloom_filter rpc script script_descriptor_cache script_deserialize script_flags script_format script_interpreter script_ops script_parsing script_sigcache script_sign scriptnum_ops scriptpubkeyman secp256k1_ec_seckey_import_export_der secp256k1_ecdsa_signature_parse_der_lax service_deserialize signature_checker signet snapshotmetadata_deserialize socks5 span str_printf string system timeoffsets torcontrol transaction tx_in tx_in_deserialize tx_out tx_package_eval tx_pool tx_pool_standard txdownloadman txdownloadman_impl txgraph txorphan txoutcompressor_deserialize txrequest txundo_deserialize uint160_deserialize uint256_deserialize utxo_snapshot utxo_snapshot_invalid utxo_total_supply validation_load_mempool vecdeque versionbits wallet_bdb_parser wallet_create_transaction wallet_fees wallet_notifications
 2(1/219)   addition_overflow                            [#1650](/bitcoin-bitcoin/1650/)    DONE   cov: 338 ft: 440 corp: 70/2760b lim: 62 exec/s: 0 rss: 141Mb
 3(2/219)   address_deserialize                          [#2709](/bitcoin-bitcoin/2709/)    DONE   cov: 681 ft: 1394 corp: 131/4575b lim: 272 exec/s: 0 rss: 165Mb
 4(3/219)   addr_info_deserialize                        [#2989](/bitcoin-bitcoin/2989/)    DONE   cov: 530 ft: 942 corp: 146/4619b lim: 262 exec/s: 0 rss: 168Mb
 5(4/219)   asmap                                        [#1341](/bitcoin-bitcoin/1341/)    DONE   cov: 536 ft: 1403 corp: 181/5182b lim: 136 exec/s: 0 rss: 142Mb
 6(5/219)   asmap_direct                                 [#435](/bitcoin-bitcoin/435/)     DONE   cov: 237 ft: 1147 corp: 143/42Kb lim: 8290 exec/s: 435 rss: 171Mb
 7(6/219)   autofile                                     [#574](/bitcoin-bitcoin/574/)     DONE   cov: 501 ft: 3127 corp: 277/4181Kb lim: 1041292 exec/s: 574 rss: 508Mb
 8(7/219)   base32_encode_decode                         [#928](/bitcoin-bitcoin/928/)     DONE   cov: 159 ft: 429 corp: 51/3070b lim: 888 exec/s: 0 rss: 134Mb
 9(8/219)   base58_encode_decode                         [#1413](/bitcoin-bitcoin/1413/)    DONE   cov: 260 ft: 868 corp: 159/2673b lim: 102 exec/s: 0 rss: 141Mb
10(9/219)   base58check_encode_decode                    [#1107](/bitcoin-bitcoin/1107/)    DONE   cov: 405 ft: 1236 corp: 149/4043b lim: 121 exec/s: 0 rss: 141Mb
11(10/219)  base64_encode_decode                         [#518](/bitcoin-bitcoin/518/)     DONE   cov: 140 ft: 368 corp: 31/1515b lim: 220 exec/s: 0 rss: 128Mb
12(11/219)  bech32_random_decode                         [#684](/bitcoin-bitcoin/684/)     DONE   cov: 310 ft: 944 corp: 136/2388b lim: 91 exec/s: 0 rss: 130Mb
13(12/219)  bech32_roundtrip                             [#791](/bitcoin-bitcoin/791/)     DONE   cov: 287 ft: 688 corp: 86/2012b lim: 130 exec/s: 0 rss: 134Mb

DrahtBot commented at 10:34 pm on April 25, 2025: contributor

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Code Coverage & Benchmarks

For details see: https://corecheck.dev/bitcoin/bitcoin/pulls/32354.

Reviews

See the guideline for information on the review process.

Type	Reviewers
ACK	monlovesmango

If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.

DrahtBot added the label Tests on Apr 25, 2025

dergoegge commented at 12:29 pm on April 28, 2025: member

Concept ~0

it is hard to tell how far you are in the progress

I think there is only a handful of harnesses that take up most of the time, so a progress bar like you have here won’t do much to show progress. It’ll look like you’re stuck at 9x% percent for a long time, so answering “when will this finish” is about as hard as before.

maflcko commented at 12:47 pm on April 28, 2025: member

Agree. The only case where it’d help is possibly generate, which is based on a fixed time.

If this was done, i’d say it is fine to log all completed futures, and remove the 5 percent “step”.

More useful in theory could be to log the name of the remaining fuzz tests, like the functional tests.

kevkevinpal force-pushed on Apr 30, 2025

kevkevinpal commented at 8:06 pm on April 30, 2025: contributor

Updated to 7ca9b5e

This is now what it looks like, it will print <targets_finished>/<total_targets>) - <target_name> then when there are less than 10 fuzz targets it will print the name of the remaining targets

Example

 0./build_fuzz/test/fuzz/test_runner.py ../qa-assets/fuzz_corpora asmap_direct base64_encode_decode addition_overflow asmap txgraph base58_encode_decode autofile bech32_roundtrip addition_overflow addr_info_deserialize asmap banman bitdeque bip324_ecdh bip324_cipher_roundtrip
 113 of 219 detected fuzz target(s) selected: addition_overflow addr_info_deserialize asmap asmap_direct autofile banman base58_encode_decode base64_encode_decode bech32_roundtrip bip324_cipher_roundtrip bip324_ecdh bitdeque txgraph
 21/13 - addition_overflow
 32/13 - asmap
 4Remaining targets: ['asmap_direct', 'autofile', 'banman', 'base58_encode_decode', 'base64_encode_decode', 'bech32_roundtrip', 'bip324_cipher_roundtrip', 'bip324_ecdh', 'bitdeque', 'txgraph']
 5Remaining targets: ['asmap_direct', 'autofile', 'banman', 'base64_encode_decode', 'bech32_roundtrip', 'bip324_cipher_roundtrip', 'bip324_ecdh', 'bitdeque', 'txgraph']
 6Remaining targets: ['asmap_direct', 'autofile', 'banman', 'bech32_roundtrip', 'bip324_cipher_roundtrip', 'bip324_ecdh', 'bitdeque', 'txgraph']
 7Remaining targets: ['asmap_direct', 'banman', 'bech32_roundtrip', 'bip324_cipher_roundtrip', 'bip324_ecdh', 'bitdeque', 'txgraph']
 8Remaining targets: ['asmap_direct', 'banman', 'bip324_cipher_roundtrip', 'bip324_ecdh', 'bitdeque', 'txgraph']
 9Remaining targets: ['banman', 'bip324_cipher_roundtrip', 'bip324_ecdh', 'bitdeque', 'txgraph']
10Remaining targets: ['banman', 'bip324_cipher_roundtrip', 'bitdeque', 'txgraph']
11Remaining targets: ['banman', 'bip324_cipher_roundtrip', 'txgraph']
12Remaining targets: ['banman', 'txgraph']
13Remaining targets: ['txgraph']
14Remaining targets: []
15Summary:
16addition_overflow       [#60](/bitcoin-bitcoin/60/)     DONE   cov: 338 ft: 424 corp: 42/1544b lim: 62 exec/s: 0 rss: 121Mb
17addr_info_deserialize   [#110](/bitcoin-bitcoin/110/)    DONE   cov: 533 ft: 938 corp: 77/3503b lim: 346 exec/s: 0 rss: 128Mb
18asmap                   [#205](/bitcoin-bitcoin/205/)    DONE   cov: 536 ft: 1400 corp: 151/4806b lim: 136 exec/s: 0 rss: 123Mb
19asmap_direct            [#178](/bitcoin-bitcoin/178/)    DONE   cov: 237 ft: 1147 corp: 129/44Kb lim: 8298 exec/s: 178 rss: 160Mb
20autofile                [#235](/bitcoin-bitcoin/235/)    DONE   cov: 501 ft: 3122 corp: 225/4731Kb lim: 1041292 exec/s: 0 rss: 459Mb
21banman                  [#1076](/bitcoin-bitcoin/1076/)   DONE   cov: 3340 ft: 20804 corp: 915/5474Kb lim: 1032263 exec/s: 63 rss: 777Mb
22base58_encode_decode    [#91](/bitcoin-bitcoin/91/)     DONE   cov: 260 ft: 854 corp: 87/4668b lim: 857 exec/s: 0 rss: 121Mb
23base64_encode_decode    [#25](/bitcoin-bitcoin/25/)     DONE   cov: 140 ft: 365 corp: 18/853b lim: 220 exec/s: 0 rss: 120Mb
24bech32_roundtrip        [#45](/bitcoin-bitcoin/45/)     DONE   cov: 287 ft: 656 corp: 41/1626b lim: 516 exec/s: 0 rss: 120Mb
25bip324_cipher_roundtrip [#1446](/bitcoin-bitcoin/1446/)   DONE   cov: 2868 ft: 8853 corp: 263/45Kb lim: 1830 exec/s: 144 rss: 652Mb
26bip324_ecdh             [#1508](/bitcoin-bitcoin/1508/)   DONE   cov: 2174 ft: 6235 corp: 142/6812b lim: 192 exec/s: 502 rss: 146Mb
27bitdeque                [#588](/bitcoin-bitcoin/588/)    DONE   cov: 2077 ft: 16123 corp: 470/617Kb lim: 418902 exec/s: 117 rss: 415Mb
28txgraph                 [#3944](/bitcoin-bitcoin/3944/)   DONE   cov: 5461 ft: 32244 corp: 2180/175Kb lim: 357 exec/s: 187 rss: 377Mb

kevkevinpal force-pushed on Apr 30, 2025

kevkevinpal commented at 8:43 pm on April 30, 2025: contributor

Pushed 9d08d71

It adds the duration it took to run the fuzz target

Example

01/219 - addition_overflow, Duration: 0.44 s
12/219 - address_deserialize, Duration: 0.56 s
23/219 - addr_info_deserialize, Duration: 0.72 s
34/219 - asmap, Duration: 0.36 s
45/219 - asmap_direct, Duration: 1.41 s
56/219 - autofile, Duration: 1.41 s
67/219 - base32_encode_decode, Duration: 0.28 s
78/219 - base58_encode_decode, Duration: 0.42 s
89/219 - base58check_encode_decode, Duration: 0.34 s

kevkevinpal force-pushed on Apr 30, 2025

monlovesmango commented at 5:12 am on May 2, 2025: contributor

Concept ACK, but I think approach NACK.

Instead of creating a whole new set of output, why not just take the summary and print it as results arrive rather than holding them all until the end? I put together a quick POC which produces the output below in real time (rather than waiting until end):

 0(1/221)   addition_overflow                            [#60](/bitcoin-bitcoin/60/)	DONE   cov: 265 ft: 320 corp: 47/1674b lim: 62 exec/s: 0 rss: 115Mb
 1(2/221)   addr_info_deserialize                        [#110](/bitcoin-bitcoin/110/)	DONE   cov: 520 ft: 831 corp: 97/5356b lim: 346 exec/s: 0 rss: 122Mb
 2(3/221)   address_deserialize                          [#131](/bitcoin-bitcoin/131/)	DONE   cov: 628 ft: 1243 corp: 107/5276b lim: 262 exec/s: 0 rss: 122Mb
 3(4/221)   asmap                                        [#205](/bitcoin-bitcoin/205/)	DONE   cov: 554 ft: 1456 corp: 158/4758b lim: 136 exec/s: 0 rss: 118Mb
 4(5/221)   autofile                                     [#235](/bitcoin-bitcoin/235/)	DONE   cov: 555 ft: 3280 corp: 228/4733Kb lim: 1041292 exec/s: 0 rss: 446Mb
 5(6/221)   asmap_direct                                 [#178](/bitcoin-bitcoin/178/)	DONE   cov: 226 ft: 1094 corp: 129/41Kb lim: 8298 exec/s: 178 rss: 150Mb
 6(7/221)   base32_encode_decode                         [#35](/bitcoin-bitcoin/35/)	DONE   cov: 132 ft: 354 corp: 28/2034b lim: 888 exec/s: 0 rss: 115Mb
 7(8/221)   base58_encode_decode                         [#91](/bitcoin-bitcoin/91/)	DONE   cov: 228 ft: 766 corp: 85/4232b lim: 857 exec/s: 0 rss: 115Mb
 8(9/221)   base58check_encode_decode                    [#98](/bitcoin-bitcoin/98/)	DONE   cov: 365 ft: 1084 corp: 89/24Kb lim: 21168 exec/s: 0 rss: 116Mb
 9(10/221)  base64_encode_decode                         [#25](/bitcoin-bitcoin/25/)	DONE   cov: 113 ft: 307 corp: 19/861b lim: 220 exec/s: 0 rss: 113Mb
10(11/221)  bech32_random_decode                         [#77](/bitcoin-bitcoin/77/)	DONE   cov: 272 ft: 880 corp: 74/1594b lim: 91 exec/s: 0 rss: 115Mb
11(12/221)  bech32_roundtrip                             [#45](/bitcoin-bitcoin/45/)	DONE   cov: 251 ft: 688 corp: 40/1675b lim: 516 exec/s: 0 rss: 114Mb

code is here: https://github.com/monlovesmango/bitcoin/tree/fuzz-test-progress

kevkevinpal force-pushed on May 2, 2025

kevkevinpal commented at 12:29 pm on May 2, 2025: contributor

5d39a39

Thank you for the review, I agree that looks much better and makes sense to use the current output we get from libfuzzer

I pushed 5d39a39 with similar changes to what you suggested

in test/fuzz/test_runner.py:414 in 5d39a3995d outdated

408@@ -380,7 +409,7 @@ def job(t, args):
409             done_stat = [l for l in output.splitlines() if "DONE" in l]
410             assert len(done_stat) == 1
411             stats.append((target, done_stat[0]))
412-
413+            remaining_targets = log_fuzz_progress(remaining_targets, test_list, done_stat, target)
414     if using_libfuzzer:
415         print("Summary:")

monlovesmango commented at 6:20 pm on May 2, 2025:

The summary at the end should probably be removed now?

kevkevinpal commented at 11:30 pm on May 2, 2025:

Do you think the summary would still be useful if you’re running --loglevel=DEBUG?

I could put an if block around it so we still get the summary for debug mode at the end.

I agree though for logging.info and above it seems pretty redundant

kevkevinpal commented at 11:44 pm on May 2, 2025:

I just made into a debug log in c54df63

in test/fuzz/test_runner.py:348 in 5d39a3995d outdated

344+        if using_libfuzzer:
345+            done_stat = [l for l in output.splitlines() if "DONE" in l]
346+            assert len(done_stat) == 1
347+            remaining_targets = log_fuzz_progress(remaining_targets, test_list, done_stat, target)
348+
349+def log_fuzz_progress(remaining_targets, test_list, done_stat, target):

monlovesmango commented at 6:23 pm on May 2, 2025:

Was there a reason you prefer to use list arguments rather than integers that store the counts? Doesn’t really matter since this is just a fuzz test runner, but seems likes an unnecessary use of lists.

kevkevinpal commented at 11:43 pm on May 2, 2025:

no there is not, pushed c54df63

kevkevinpal force-pushed on May 2, 2025

DrahtBot added the label CI failed on May 3, 2025

DrahtBot commented at 0:42 am on May 3, 2025: contributor

🚧 At least one of the CI tasks failed. Task lint: https://github.com/bitcoin/bitcoin/runs/41572070330 LLM reason (✨ experimental): The CI failure is caused by errors detected during the lint check, specifically a ‘ruff’ error indicating an issue with Python code, leading to the failure of the lint job.

Try to run the tests locally, according to the documentation. However, a CI failure may still happen due to a number of reasons, for example:

Possibly due to a silent merge conflict (the changes in this pull request being incompatible with the current code in the target branch). If so, make sure to rebase on the latest commit of the target branch.
A sanitizer issue, which can only be found by compiling with the sanitizer and running the affected test.
An intermittent issue.

Leave a comment here, if you need help tracking down a confusing failure.

kevkevinpal force-pushed on May 3, 2025

tests: Added progress tracker when running test_runner.py

Right now if you run test_runner.py on all the targets it is hard to
tell how far you are in the progress even with --loglevel=DEBUG on. This
adds a counter and additional info while the test_runner is running

Co-authored-by: monlovesmango <monlovesmango@users.noreply.github.com>

3af8f625fa

in test/fuzz/test_runner.py:297 in 6cb07595fa outdated

289@@ -283,12 +290,19 @@ def job(command, t, t_env):
290         futures.append(fuzz_pool.submit(job, command, target, t_env))
291 
292     for future in as_completed(futures):
293-        future.result()
294+        target, output = future.result()
295+        if using_libfuzzer:
296+            done_stat = [l for l in output.splitlines() if "DONE" in l]
297+            assert len(done_stat) == 1
298+            num_targets_completed = log_fuzz_progress(num_targets_completed, len(test_list), done_stat, target, target_max_len)

monlovesmango commented at 3:47 am on May 3, 2025:

I think it should be this:

0            num_targets_completed = log_fuzz_progress(num_targets_completed, len(targets), done_stat, target, target_max_len)

My preference would probably be to change the argument targets to test_list (and also update the name in args.generate) because this is more consistent with the other modes. However I understand if this is out of scope.

kevkevinpal commented at 4:05 am on May 3, 2025:

I actually had to update this since test_list wasnt defined in this function, so I just got the num_of_targets at the top and used it here 3af8f62

lemme know if that looks good!

monlovesmango commented at 4:55 am on May 3, 2025:

lgtm!

kevkevinpal force-pushed on May 3, 2025

monlovesmango commented at 4:56 am on May 3, 2025: contributor

ACK 3af8f625fa1087fc659f5cbf0c5f568f15d89ee1

DrahtBot removed the label CI failed on May 3, 2025

tests: Added progress tracker when running fuzz test_runner.py #32354

Summary

Note

Example run

Code Coverage & Benchmarks

Reviews