Error: nippy jar error: The requested operation cannot be performed on a file with a user-mapped section open. (os error 1224)

[smye]

Describe the bug

I built from source using the fix provided in #10672

It was around 80% done on the bodies stage (2/14), when syncing crashed and does not begin resyncing upon restart

Steps to reproduce

1. Modify /crates/storage/nippy-jar/src/lib.rs: as fix: nippy jar error access is denied. os error 5 (#9747) #10672 suggests
2. Build from source on windows
3. Use lighthouse client
4. Run reth node --full

Node logs

PS C:\Users\smyeu\Desktop\reth> reth node --full -vvvvv
2024-09-04T13:24:44.781994Z  INFO reth::cli: Initialized tracing, debug log directory: C:\Users\smyeu\AppData\Local\reth\logs\mainnet
2024-09-04T13:24:44.783360Z  INFO reth::cli: Starting reth version="1.0.6-dev (d659cd36)"
2024-09-04T13:24:44.983963Z  INFO reth::cli: Opening database path="C:\\Users\\smyeu\\AppData\\Roaming\\reth\\mainnet\\db"
2024-09-04T13:24:45.018590Z  INFO reth::cli: Configuration loaded path="C:\\Users\\smyeu\\AppData\\Roaming\\reth\\mainnet\\reth.toml"
2024-09-04T13:24:45.032444Z TRACE storage::db::mdbx: Transaction opened caller=crates\storage\db\src\implementation\mdbx\tx.rs:60:25 id=16404 mode=read-only
2024-09-04T13:24:45.032619Z  INFO reth::cli: Verifying storage consistency.
2024-09-04T13:24:45.032705Z TRACE provider::static_file: Getting static file writer.
 block=20602320 segment=Headers
2024-09-04T13:24:45.032903Z TRACE provider::static_file: Getting provider segment=Headers fixed_block_range=SegmentRangeInclusive { start: 20500000, end: 20999999 }
2024-09-04T13:24:45.033062Z TRACE provider::static_file: Creating jar from scratch segment=Headers fixed_block_range=SegmentRangeInclusive { start: 20500000, end: 20999999 }
2024-09-04T13:24:45.043810Z TRACE provider::static_file: Getting static file writer.
 block=16396000 segment=Transactions
2024-09-04T13:24:45.043968Z TRACE provider::static_file: Getting provider segment=Transactions fixed_block_range=SegmentRangeInclusive { start: 16000000, end: 16499999 }
2024-09-04T13:24:45.044106Z TRACE provider::static_file: Creating jar from scratch segment=Transactions fixed_block_range=SegmentRangeInclusive { start: 16000000, end: 16499999 }
2024-09-04T13:24:45.058174Z ERROR reth::cli: shutting down due to error
Error: nippy jar error: The requested operation cannot be performed on a file with a user-mapped section open. (os error 1224)

Location:
    C:\Users\smyeu\Desktop\reth\crates\node\builder\src\launch\common.rs:403:38

2024-09-03T01:39:15.841573Z DEBUG storage::db::mdbx: Commit total_duration=2.6764ms commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 5, audit: 0, write: 143, sync: 23, ending: 0, whole: 172, gc_cputime: 0, gc_prof: MDBX_commit_latency__bindgen_ty_1 { wloops: 0, coalescences: 0, wipes: 0, flushes: 0, kicks: 0, work_counter: 0, work_rtime_monotonic: 0, work_xtime_cpu: 0, work_rsteps: 0, work_xpages: 0, work_majflt: 0, self_counter: 0, self_rtime_monotonic: 0, self_xtime_cpu: 0, self_rsteps: 0, self_xpages: 0, self_majflt: 0 } })) is_read_only=false
2024-09-03T01:39:15.842025Z  INFO reth_node_events::node: Preparing stage pipeline_stages=2/14 stage=Bodies checkpoint=16396000 target=20602320
2024-09-03T01:39:15.842216Z DEBUG sync::stages::bodies: Commencing sync stage_progress=16396001 target=20602320 start_tx_id=1839319601
2024-09-03T01:39:15.842266Z  INFO reth_node_events::node: Executing stage pipeline_stages=2/14 stage=Bodies checkpoint=16396000 target=20602320
2024-09-03T01:39:25.177641Z DEBUG consensus::engine::hooks: Next hook is not ready hook="StaticFile"
2024-09-03T01:39:27.579336Z DEBUG net: Request canceled, response channel from session closed. id=0x1487e64051fef2e925b8a39209927f03406ebb30d5662ae2c2e05ea114012920d16010359bf6007d46393b0fb5992737b766e4125ea74168c4ab2b85511ffe41
2024-09-03T01:39:27.579998Z DEBUG net::session: failed to receive message err=ECIES stream protocol error: expected message, received Err(ECIESError { inner: IO(Os { code: 10053, kind: ConnectionAborted, message: "An established connection was aborted by the software in your host machine." }) }) remote_peer_id=0x86dff5d1e9c8b912867c1239b3e9268e0c8802f8a4f9580e27ede3716f5234dfdecbc179f7d63931f80d9051bd067aaecdc1a738a30d02d4ef269e69298c08bc
2024-09-03T01:39:27.580029Z DEBUG net::session: failed to receive message err=ECIES stream protocol error: expected message, received Err(ECIESError { inner: IO(Os { code: 10053, kind: ConnectionAborted, message: "An established connection was aborted by the software in your host machine." }) }) remote_peer_id=0x3395c7697bcd9b353fdefa23b32d1cb09f1b4d41b18b14683c5e5672f07024969ee6a4a6597219abd41755128c300dce0027d1619de26a43430cd74d00e43272
2024-09-03T01:39:27.593905Z DEBUG downloaders::bodies: Error requesting bodies peer_id=None error=connection to a peer dropped while handling the request
2024-09-03T01:39:27.596286Z DEBUG net::session: eth stream completed remote_peer_id=0xaf002936bd149e51151a8e5b3f2e0f5dc261cf3b4acd9be7facd5ebd3352155f6c28a2ef048e95c2275d1406f7d81bdb6a3b08ad7f08f3bb0444b5a8e74d3646
2024-09-03T01:39:27.599377Z DEBUG net::session: eth stream completed remote_peer_id=0x80d98f7f096ae7d387f09fe9b8e8374acd5b4fcf0bc9ba2dfe01814501d6c1a57b396bec819fecbb8243c5e12b2bad109211562f30d881ff924c1f31ce51783e
2024-09-03T01:39:27.599979Z DEBUG net::session: eth stream completed remote_peer_id=0x4155e948f8da4fd283ee1dc9464e828d499eed4a09db11aef9414f1cbcfd4503d6b2fa5a8e33caf6fd6ec181d20e1e8deda28f29c8beb760d2a58d49b9153101
2024-09-03T01:39:27.600301Z DEBUG downloaders::bodies: Error requesting bodies peer_id=None error=connection to a peer dropped while handling the request
2024-09-03T01:39:27.600503Z DEBUG downloaders::bodies: Error requesting bodies peer_id=None error=connection to a peer dropped while handling the request
2024-09-03T01:39:27.601155Z DEBUG downloaders::bodies: Error requesting bodies peer_id=None error=connection to a peer dropped while handling the request
2024-09-03T01:39:27.602039Z DEBUG downloaders::bodies: Error requesting bodies peer_id=None error=connection to a peer dropped while handling the request
2024-09-03T01:39:27.602204Z DEBUG downloaders::bodies: Error requesting bodies peer_id=None error=connection to a peer dropped while handling the request
2024-09-03T01:39:27.603866Z DEBUG net::session: failed to receive message err=ECIES stream protocol error: expected message, received Err(ECIESError { inner: IO(Os { code: 10053, kind: ConnectionAborted, message: "An established connection was aborted by the software in your host machine." }) }) remote_peer_id=0xab66dfc9d5ee9e65a26de1a69d15f6a4b9643ba575bc206260d52d786543aa9705529d6216a742d05c9fee8dda5f629aecbf2aa7c0deb6ce1119a767f7579f31
2024-09-03T01:39:27.604857Z DEBUG net::session: eth stream completed remote_peer_id=0xefc9f0deaf378659753eae738648bf00bc1e5a2962363d697b3ee3e78a880e1760cfe079892462dcac9ff301e21c812e81014103240c0bb838d6e72477eb1fa6
2024-09-03T01:39:27.604987Z DEBUG downloaders::bodies: Error requesting bodies peer_id=None error=connection to a peer dropped while handling the request
2024-09-03T01:39:27.605240Z DEBUG net::session: failed to receive message err=ECIES stream protocol error: expected message, received Err(ECIESError { inner: IO(Os { code: 10053, kind: ConnectionAborted, message: "An established connection was aborted by the software in your host machine." }) }) remote_peer_id=0xa9f9fe919ff7a4c5bd3840c7d16440631012dcfd673bf8a7a8878cc3cbc6b7f79fbd1f16591090180305259936e54b3b58f676741ca1c1ec6e552d9e2446c318
2024-09-03T01:39:27.605465Z DEBUG net::session: eth stream completed remote_peer_id=0x71b4bc0970a9dcf39e8524b04bbcaebb412b6bb3e5c4364a9638d04d7145cfc5a4cf363b3c86fe1afaa4cbf99e201880b07b31602e369b931d33806ea9c29d8b
2024-09-03T01:39:27.605883Z DEBUG downloaders::bodies: Error requesting bodies peer_id=None error=connection to a peer dropped while handling the request
2024-09-03T01:39:27.606210Z DEBUG downloaders::bodies: Error requesting bodies peer_id=None error=connection to a peer dropped while handling the request
2024-09-03T01:39:27.606363Z DEBUG downloaders::bodies: Error requesting bodies peer_id=None error=connection to a peer dropped while handling the request
2024-09-03T01:39:27.607886Z DEBUG net::session: eth stream completed remote_peer_id=0x22f2ef91c8ca8c4e9a439153b051438c2ef7aea1948d9e3f2248c1684aa8976b207d123eeb6910fc0f53f6d1df0a8c3e127eea50056c7c57a031c00bb53ea015
2024-09-03T01:39:27.625116Z DEBUG downloaders::bodies: Error requesting bodies peer_id=None error=connection to a peer dropped while handling the request
2024-09-03T01:39:43.707360Z  INFO reth::cli: Status connected_peers=51 stage=Bodies checkpoint=16396000 target=20602320 stage_progress=79.58%
2024-09-04T12:55:09.230022Z  INFO reth::cli: Initialized tracing, debug log directory: C:\Users\smyeu\AppData\Local\reth\logs\mainnet
2024-09-04T12:55:09.232916Z  INFO reth::cli: Starting reth version="1.0.6 (3a49a552)"
2024-09-04T12:55:09.433449Z  INFO reth::cli: Opening database path="C:\\Users\\smyeu\\AppData\\Roaming\\reth\\mainnet\\db"
2024-09-04T12:55:09.507240Z  INFO reth::cli: Configuration loaded path="C:\\Users\\smyeu\\AppData\\Roaming\\reth\\mainnet\\reth.toml"
2024-09-04T12:55:09.824427Z  INFO reth::cli: Verifying storage consistency.
2024-09-04T12:55:10.045239Z ERROR reth::cli: shutting down due to error
2024-09-04T12:55:27.226280Z  INFO reth::cli: Initialized tracing, debug log directory: C:\Users\smyeu\AppData\Local\reth\logs\mainnet
2024-09-04T12:55:27.227722Z  INFO reth::cli: Starting reth version="1.0.6 (3a49a552)"
2024-09-04T12:55:27.428266Z  INFO reth::cli: Opening database path="C:\\Users\\smyeu\\AppData\\Roaming\\reth\\mainnet\\db"
2024-09-04T12:55:27.465066Z  INFO reth::cli: Configuration loaded path="C:\\Users\\smyeu\\AppData\\Roaming\\reth\\mainnet\\reth.toml"
2024-09-04T12:55:27.480463Z  INFO reth::cli: Verifying storage consistency.
2024-09-04T12:55:27.593217Z ERROR reth::cli: shutting down due to error
2024-09-04T12:58:08.533963Z  INFO reth::cli: Initialized tracing, debug log directory: C:\Users\smyeu\AppData\Local\reth\logs\mainnet
2024-09-04T12:58:08.535110Z  INFO reth::cli: Starting reth version="1.0.6 (3a49a552)"
2024-09-04T12:58:08.735580Z  INFO reth::cli: Opening database path="C:\\Users\\smyeu\\AppData\\Roaming\\reth\\mainnet\\db"
2024-09-04T12:58:08.779182Z  INFO reth::cli: Configuration loaded path="C:\\Users\\smyeu\\AppData\\Roaming\\reth\\mainnet\\reth.toml"
2024-09-04T12:58:09.151527Z  INFO reth::cli: Verifying storage consistency.
2024-09-04T12:58:09.249417Z ERROR reth::cli: shutting down due to error
2024-09-04T12:59:59.494120Z  INFO reth::cli: Initialized tracing, debug log directory: C:\Users\smyeu\AppData\Local\reth\logs\mainnet
2024-09-04T12:59:59.495870Z  INFO reth::cli: Starting reth version="1.0.6 (3a49a552)"
2024-09-04T12:59:59.696326Z  INFO reth::cli: Opening database path="C:\\Users\\smyeu\\AppData\\Roaming\\reth\\mainnet\\db"
2024-09-04T12:59:59.728649Z  INFO reth::cli: Configuration loaded path="C:\\Users\\smyeu\\AppData\\Roaming\\reth\\mainnet\\reth.toml"
2024-09-04T12:59:59.797404Z  INFO reth::cli: Verifying storage consistency.
2024-09-04T12:59:59.852325Z ERROR reth::cli: shutting down due to error
2024-09-04T13:03:14.514637Z  INFO reth::cli: Initialized tracing, debug log directory: C:\Users\smyeu\AppData\Local\reth\logs\mainnet
2024-09-04T13:03:14.515827Z  INFO reth::cli: Starting reth version="1.0.6 (3a49a552)"
2024-09-04T13:03:14.716270Z  INFO reth::cli: Opening database path="C:\\Users\\smyeu\\AppData\\Roaming\\reth\\mainnet\\db"
2024-09-04T13:03:14.747470Z  INFO reth::cli: Configuration loaded path="C:\\Users\\smyeu\\AppData\\Roaming\\reth\\mainnet\\reth.toml"
2024-09-04T13:03:14.758523Z  INFO reth::cli: Verifying storage consistency.
2024-09-04T13:03:14.792176Z ERROR reth::cli: shutting down due to error
2024-09-04T13:07:43.474657Z  INFO reth::cli: Initialized tracing, debug log directory: C:\Users\smyeu\AppData\Local\reth\logs\mainnet
2024-09-04T13:07:43.476552Z  INFO reth::cli: Starting reth version="1.0.6 (3a49a552)"
2024-09-04T13:07:43.677057Z  INFO reth::cli: Opening database path="C:\\Users\\smyeu\\AppData\\Roaming\\reth\\mainnet\\db"
2024-09-04T13:07:43.724318Z  INFO reth::cli: Configuration loaded path="C:\\Users\\smyeu\\AppData\\Roaming\\reth\\mainnet\\reth.toml"
2024-09-04T13:07:43.998483Z  INFO reth::cli: Verifying storage consistency.
2024-09-04T13:07:44.061382Z ERROR reth::cli: shutting down due to error
2024-09-04T13:24:02.881545Z  INFO reth::cli: Initialized tracing, debug log directory: C:\Users\smyeu\AppData\Local\reth\logs\mainnet
2024-09-04T13:24:02.882918Z  INFO reth::cli: Starting reth version="1.0.6-dev (d659cd36)"
2024-09-04T13:24:03.083472Z  INFO reth::cli: Opening database path="C:\\Users\\smyeu\\AppData\\Roaming\\reth\\mainnet\\db"
2024-09-04T13:24:03.123288Z DEBUG storage::db::mdbx: Commit total_duration=1.7297ms commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 23, audit: 0, write: 57, sync: 26, ending: 0, whole: 108, gc_cputime: 0, gc_prof: MDBX_commit_latency__bindgen_ty_1 { wloops: 0, coalescences: 0, wipes: 0, flushes: 0, kicks: 0, work_counter: 0, work_rtime_monotonic: 0, work_xtime_cpu: 0, work_rsteps: 0, work_xpages: 0, work_majflt: 0, self_counter: 0, self_rtime_monotonic: 0, self_xtime_cpu: 0, self_rsteps: 0, self_xpages: 0, self_majflt: 0 } })) is_read_only=false
2024-09-04T13:24:03.132255Z  INFO reth::cli: Configuration loaded path="C:\\Users\\smyeu\\AppData\\Roaming\\reth\\mainnet\\reth.toml"
2024-09-04T13:24:03.457103Z  INFO reth::cli: Verifying storage consistency.
2024-09-04T13:24:03.508523Z ERROR reth::cli: shutting down due to error
2024-09-04T13:24:36.421208Z  INFO reth::cli: Initialized tracing, debug log directory: C:\Users\smyeu\AppData\Local\reth\logs\mainnet
2024-09-04T13:24:36.422648Z  INFO reth::cli: Starting reth version="1.0.6-dev (d659cd36)"
2024-09-04T13:24:36.623199Z  INFO reth::cli: Opening database path="C:\\Users\\smyeu\\AppData\\Roaming\\reth\\mainnet\\db"
2024-09-04T13:24:36.656841Z  INFO reth::cli: Configuration loaded path="C:\\Users\\smyeu\\AppData\\Roaming\\reth\\mainnet\\reth.toml"
2024-09-04T13:24:36.668070Z  INFO reth::cli: Verifying storage consistency.
2024-09-04T13:24:36.694028Z ERROR reth::cli: shutting down due to error
2024-09-04T13:24:44.782271Z  INFO reth::cli: Initialized tracing, debug log directory: C:\Users\smyeu\AppData\Local\reth\logs\mainnet
2024-09-04T13:24:44.783648Z  INFO reth::cli: Starting reth version="1.0.6-dev (d659cd36)"
2024-09-04T13:24:44.984088Z  INFO reth::cli: Opening database path="C:\\Users\\smyeu\\AppData\\Roaming\\reth\\mainnet\\db"
2024-09-04T13:24:45.018715Z  INFO reth::cli: Configuration loaded path="C:\\Users\\smyeu\\AppData\\Roaming\\reth\\mainnet\\reth.toml"
2024-09-04T13:24:45.032692Z  INFO reth::cli: Verifying storage consistency.
2024-09-04T13:24:45.058607Z ERROR reth::cli: shutting down due to error

Platform(s)

Windows (x86)

What version/commit are you on?

reth Version: 1.0.6-dev
Commit SHA: d659cd3
Build Timestamp: 2024-09-04T13:17:11.158134900Z
Build Features: jemalloc
Build Profile: release

What database version are you on?

Current database version: 2
Local database version: 2

Which chain / network are you on?

Mainnet

What type of node are you running?

Full via --full flag

What prune config do you use, if any?

No response

If you've built Reth from source, provide the full command you used

cargo install --locked --path bin/reth --bin reth

Code of Conduct

• I agree to follow the Code of Conduct

[kaxxa123]

Made a quick test letting syncing reach stage 2/14 (but only up to 7.5%).
Terminated reth and lighthouse with CTRL-C.

Restarted and syncing is continuing from where it left off (20% right now).

@smye your error indicates that the crash might have not closed the files cleanly and some file is still locked.
Did you try to restart windows and see if syncing continuous?

[kaxxa123]

@smye managed to reproduce your problem and found a hacky work around!

Basically I closed reth and lighthouse again with CTRL-C
This time it was 2/14 around 25%

Both seemed to close cleanly but restarting reth gave the same error as you reported (1224).
Restarting Windows did not help.

It looks like one (or more) of the files got corrupted and you need to delete it manually.

1. Go to your reth data folder under:
   mainnet/staticfiles

2. Sort the files by modified date and look for the most recently modified files.

3. In my case I deleted the last 3 files named (in your case the block range will be different):
   static_file_transactions_4500000_4999999
   static_file_transactions_4500000_4999999.conf
   static_file_transactions_4500000_4999999.off

4. Start Reth now. If it gives you some error keep trying to restart a few times. Funnily I had to try starting Reth a couple of times until it got working again.

Hope it helps! Report back if you try this.

[joshieDo]

It's not clear what caused the first crash in the first place, which can be valuable in itself

Assuming that the first error is unrelated, this makes me believe that the current consistency healing impl is not supported by non-wsl Windows

[smye]

@smye managed to reproduce your problem and found a hacky work around!

Basically I closed reth and lighthouse again with CTRL-C This time it was 2/14 around 25%

Both seemed to close cleanly but restarting reth gave the same error as you reported (1224). Restarting Windows did not help.

It looks like one (or more) of the files got corrupted and you need to delete it manually.

1. Go to your reth data folder under:
   mainnet/staticfiles
2. Sort the files by modified date and look for the most recently modified files.
3. In my case I deleted the last 3 files named (in your case the block range will be different):
   static_file_transactions_4500000_4999999
   static_file_transactions_4500000_4999999.conf
   static_file_transactions_4500000_4999999.off
4. Start Reth now. If it gives you some error keep trying to restart a few times. Funnily I had to try starting Reth a couple of times until it got working again.

Hope it helps! Report back if you try this.

Awesome! This looks like it has fixed it, and is now resyncing after running reth node --full twice

Had to delete the 2nd, 3rd and 4th most recent file but keep the first static_file_headers_20500000_20999999.conf otherwise would complain about a missing file

[smye]

It's not clear what caused the first crash in the first place, which can be valuable in itself

Assuming that the first error is unrelated, this makes me believe that the current consistency healing impl is not supported by non-wsl Windows

I am not sure what caused the crash sadly. Checked the debug log file and wasn't anything immediately obvious

One thing to note was that both lighthouse and reth had both crashed when returning to check

[joshieDo]

the error/issue is still active, so leaving it open (added a draft PR)

if the syncing crashes, feel free to post here the error message! i'm leaning again to both errors being related