I2P: also sleep after errors in Accept() & destroy the session if we get an unexpected error #28077
Conversation
|
The following sections might be updated with supplementary metadata relevant to reviewers and maintainers. Code CoverageFor detailed information about the code coverage, see the test coverage report. ReviewsSee the guideline for information on the review process.
If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update. ConflictsNo conflicts as of last run. |
|
Concept ACK. Have been testing the issue and various fixes by @vasild the past couple weeks in order to fix the issue described in
and discussed on bitcoin-core-dev IRC at https://bitcoin-irc.chaincode.com/bitcoin-core-dev/2023-07-07#941511. |
|
Win64 CI doesn't like the braced initializer list: https://github.com/bitcoin/bitcoin/pull/28077/checks?check_run_id=15050079549. |
|
Initial code review ACK (didn't review the test changes yet), will test IRL. |
e556bc6 to
ffa90fc
Compare
|
|
|
Initial testing with the Java I2P Router shows that this pull fixes the issue (nice work!) On master without this PR, thousands of lines of error messages are logged ( With this pull, the error is logged only once and there is no need to manually shut down and restart the I2P Router. A new persistent I2P session is created on the third try (perhaps a bit more sleep would create a session on the first attempt with less logging). Laptop auto-sleep for low battery, auto-awakened 2 1/2 hours later on plugging in the PSU: Will test with the i2pd router as well. |
|
Verified that the issue doesn't occur with the i2pd router, only with the Java I2P router. |
It's not clear to me if this an issue in our code, or an issue with the router (or both), especially if everything "works fine" with one router, but not the other. Have these issues been reported upstream? |
|
@fanquake, There is an issue with the I2P router - there is a discrepancy between the router behavior and the SAM specification. Then, this unexpected behavior causes Bitcoin Core to log way too many messages. It becomes a problem with Bitcoin Core too. I should report this upstream as per https://geti2p.net/en/faq#bug. |
Great. Can you link to the issue once it's reported upstream, as it'd be good to know which (if any) of the changes here are required just to work around buggy router software. |
The log flooding rate is very high, but perhaps the more severe issue fixed here is that the I2P connections remain down until the router is manually stopped and then restarted, until which time the log flooding continues, and for anyone running With this fix, the connections recover on their own, like they do for the other networks. Even if the router is eventually patched upstream, older versions are being used. So, it seems good to fix this and consider backporting. |
|
https://geti2p.net/en/download has just updated their available macOS version from 1.9 to 2.3 -- will retest. |
FWIW, I didn't manage to make the v2.3 jar work and had to reinstall v1.9 (available as a dmg) at https://geti2p.net/en/download/mac. Per that page: "Important Note: The 2.1.0 Mac OSX Easy Install Bundle release is delayed. Please install the 1.9.0 release below. You will be notified in the router console when the 2.1.0 update is available. Thank you for your patience." |
I don't think that's something we'd want to advise anyone todo, given https://geti2p.net/en/blog/post/2023/01/31/mac-easy-install-notarization:
Even though the blog post is dated, the text above was added within the last week: https://i2pgit.org/i2p-hackers/i2p.www/-/commit/2ab41d3c8551071abea1361235d8e1e95bcb410d. It also clarifies that:
|
|
Yes. I find the lighter-weight i2pd router in C++ to be an easier option for node operators to install: |
|
A couple updates:
|
Background: `Listen()` does: * if the session is not created yet * create the control socket and on it: * `HELLO` * `SESSION CREATE ID=sessid` * leave the control socked opened * create a new socket and on it: * `HELLO` * `STREAM ACCEPT ID=sessid` * read reply (`STREAM STATUS`) Then a wait starts, for a peer to connect. When connected, `Accept()` does: * on the socket from `STREAM ACCEPT` from `Listen()`: read the Base64 identification of the connecting peer Problem: The I2P router may be in such a state that this happens in a quick succession (many times per second, see bitcoin#22759 (comment)): `Listen()`-succeeds, `Accept()`-fails. `Accept()` fails because the I2P router sends something that is not Base64 on the socket: STREAM STATUS RESULT=I2P_ERROR MESSAGE="Session was closed" We only sleep after failed `Listen()` because the assumption was that if `Accept()` fails then the next `Listen()` will also fail. Solution: Avoid filling the log with "Error accepting:" messages and sleep also after a failed `Accept()`. Extra changes: * Reset the error waiting time after one successful connection. Otherwise the timer will remain high due to problems that have been solved long time in the past. * Increment the wait time less aggressively. Github-Pull: bitcoin#28077 Rebased-From: 3870734
…router From https://geti2p.net/en/docs/api/samv3: If SILENT=false was passed, which is the default value, the SAM bridge sends the client a ASCII line containing the base64 public destination key of the requesting peer So, `Accept()` is supposed to receive a Base64 encoded destination of the connecting peer, but if it receives something like this instead: STREAM STATUS RESULT=I2P_ERROR MESSAGE="Session was closed" then destroy the session. Github-Pull: bitcoin#28077 Rebased-From: ffa90fc
|
Sorry for the delay. I'm working on the I2P ticket you filed, linked above. My goal is to resolve it in a couple weeks. The current behavior has been like this for quite some time, so in practice, the workarounds in this PR are necessary even if we do get a fix out in our next release. My strategy is:
I recommend that you change your test at line 193 to be more robust by doing something like: peer_dest.startsWith("STREAM SESSION RESULT=I2P_ERROR") or just peer_dest.find("RESULT=I2P_ERROR") so you're not dependent on the message text which is undocumented, could change, or may reflect different error cases in the future. I hope to have a Java I2P patch for you to test by the end of the month, so you may resolve this in time for your 26.0 release. Concept ACK |
* Check for closed session before responding OK to ACCEPT * Close control socket on ACCEPT closed session and router restart errors * Output I2P_ERROR on accept and control sockets * Related streaming change to throw distinct exception on closed session ref: bitcoin/bitcoin#28077 Closes #399 (manual merge of i2p-hackers/i2p.i2p/-/merge_requests/114)
|
Our fixes are approved and merged. Test results are in our ticket linked above. If you wish to test it, I recommend applying the patch to our 2.3.0 release source, not the current HEAD, as our code base is currently unstable. SAM spec updates will follow soon. I hope you can get this PR merged for 26.0. Thanks again for the report. |
Background: `Listen()` does: * if the session is not created yet * create the control socket and on it: * `HELLO` * `SESSION CREATE ID=sessid` * leave the control socked opened * create a new socket and on it: * `HELLO` * `STREAM ACCEPT ID=sessid` * read reply (`STREAM STATUS`) Then a wait starts, for a peer to connect. When connected, `Accept()` does: * on the socket from `STREAM ACCEPT` from `Listen()`: read the Base64 identification of the connecting peer Problem: The I2P router may be in such a state that this happens in a quick succession (many times per second, see bitcoin#22759 (comment)): `Listen()`-succeeds, `Accept()`-fails. `Accept()` fails because the I2P router sends something that is not Base64 on the socket: STREAM STATUS RESULT=I2P_ERROR MESSAGE="Session was closed" We only sleep after failed `Listen()` because the assumption was that if `Accept()` fails then the next `Listen()` will also fail. Solution: Avoid filling the log with "Error accepting:" messages and sleep also after a failed `Accept()`. Extra changes: * Reset the error waiting time after one successful connection. Otherwise the timer will remain high due to problems that have vanished long time ago. * Increment the wait time less aggressively.
…outer From https://geti2p.net/en/docs/api/samv3: If SILENT=false was passed, which is the default value, the SAM bridge sends the client a ASCII line containing the base64 public destination key of the requesting peer So, `Accept()` is supposed to receive a Base64 encoded destination of the connecting peer, but if it receives something like this instead: STREAM STATUS RESULT=I2P_ERROR MESSAGE="Session was closed" then destroy the session.
ffa90fc to
5c8e15c
Compare
|
|
There was a problem hiding this comment.
re-ACK 5c8e15c
The only code change since my last review was this line:
- if (ToLower(peer_dest).find("session was closed") != std::string::npos) {
+ if (peer_dest.find("RESULT=I2P_ERROR") != std::string::npos) {On master without this PR, thousands of lines of error messages are logged (Error accepting: Cannot decode Base64: "STREAM STATUS RESULT=I2P_ERROR") and bitcoind I2P session re-creation fails over and over, until the I2P router is manually stopped and restarted.
With this pull, the error is logged only once and there is no need to manually shut down and restart the I2P Router. A new persistent I2P session is created on the third try (perhaps a bit more sleep would create a session on the first attempt with less logging).
It would be good to include this in v26.0. Per @zzzi2p above:
The current behavior has been like this for quite some time, so in practice, the workarounds in this PR are necessary even if we do get a fix out in our next release.
Background: `Listen()` does: * if the session is not created yet * create the control socket and on it: * `HELLO` * `SESSION CREATE ID=sessid` * leave the control socked opened * create a new socket and on it: * `HELLO` * `STREAM ACCEPT ID=sessid` * read reply (`STREAM STATUS`) Then a wait starts, for a peer to connect. When connected, `Accept()` does: * on the socket from `STREAM ACCEPT` from `Listen()`: read the Base64 identification of the connecting peer Problem: The I2P router may be in such a state that this happens in a quick succession (many times per second, see bitcoin#22759 (comment)): `Listen()`-succeeds, `Accept()`-fails. `Accept()` fails because the I2P router sends something that is not Base64 on the socket: STREAM STATUS RESULT=I2P_ERROR MESSAGE="Session was closed" We only sleep after failed `Listen()` because the assumption was that if `Accept()` fails then the next `Listen()` will also fail. Solution: Avoid filling the log with "Error accepting:" messages and sleep also after a failed `Accept()`. Extra changes: * Reset the error waiting time after one successful connection. Otherwise the timer will remain high due to problems that have vanished long time ago. * Increment the wait time less aggressively. Github-Pull: bitcoin#28077 Rebased-From: 762404a
…outer From https://geti2p.net/en/docs/api/samv3: If SILENT=false was passed, which is the default value, the SAM bridge sends the client a ASCII line containing the base64 public destination key of the requesting peer So, `Accept()` is supposed to receive a Base64 encoded destination of the connecting peer, but if it receives something like this instead: STREAM STATUS RESULT=I2P_ERROR MESSAGE="Session was closed" then destroy the session. Github-Pull: bitcoin#28077 Rebased-From: 5c8e15c
|
ACK 5c8e15c |
…oy the session if we get an unexpected error 5c8e15c i2p: destroy the session if we get an unexpected error from the I2P router (Vasil Dimov) 762404a i2p: also sleep after errors in Accept() (Vasil Dimov) Pull request description: ### Background In the `i2p::sam::Session` class: `Listen()` does: * if the session is not created yet * create the control socket and on it: * `HELLO` * `SESSION CREATE ID=sessid` * leave the control socked opened * create a new socket and on it: * `HELLO` * `STREAM ACCEPT ID=sessid` * read reply (`STREAM STATUS`), `Listen()` only succeeds if it contains `RESULT=OK` Then a wait starts, for a peer to connect. When connected, `Accept()` does: * on the socket from `STREAM ACCEPT` from `Listen()`: read the Base64 identification of the connecting peer ### Problem The I2P router may be in such a state that this happens in a quick succession (many times per second, see bitcoin#22759 (comment)): `Listen()`-succeeds, `Accept()`-fails. `Accept()` fails because the I2P router sends something that is not Base64 on the socket: `STREAM STATUS RESULT=I2P_ERROR MESSAGE="Session was closed"` We only sleep after failed `Listen()` because the assumption was that if `Accept()` fails then the next `Listen()` will also fail. ### Solution Avoid filling the log with "Error accepting:" messages and sleep also after a failed `Accept()`. ### Extra changes * Reset the error waiting time after one successful connection. Otherwise the timer will remain high due to problems that have been solved long time in the past. * Increment the wait time less aggressively. * Handle the unexpected "Session was closed" message more gracefully (don't log stupid messages like `Cannot decode Base64: "STREAM STATUS...`) and destroy the session right way. ACKs for top commit: achow101: ACK 5c8e15c jonatack: re-ACK 5c8e15c Tree-SHA512: 1d47958c50eeae9eefcb668b8539fd092adead93328e4bf3355267819304b99ab41cbe1b5dbedbc3452c2bc389dc8330c0e27eb5ccb880e33dc46930a1592885
…get an unexpected error (backported from bitcoin/bitcoin#28077)
Background
In the
i2p::sam::Sessionclass:Listen()does:HELLOSESSION CREATE ID=sessidHELLOSTREAM ACCEPT ID=sessidSTREAM STATUS),Listen()only succeeds if it containsRESULT=OKThen a wait starts, for a peer to connect. When connected,
Accept()does:STREAM ACCEPTfromListen(): read the Base64 identification of the connecting peerProblem
The I2P router may be in such a state that this happens in a quick succession (many times per second, see #22759 (comment)):
Listen()-succeeds,Accept()-fails.Accept()fails because the I2P router sends something that is not Base64 on the socket:STREAM STATUS RESULT=I2P_ERROR MESSAGE="Session was closed"We only sleep after failed
Listen()because the assumption was that ifAccept()fails then the nextListen()will also fail.Solution
Avoid filling the log with "Error accepting:" messages and sleep also after a failed
Accept().Extra changes
Reset the error waiting time after one successful connection. Otherwise the timer will remain high due to problems that have been solved long time in the past.
Increment the wait time less aggressively.
Handle the unexpected "Session was closed" message more gracefully (don't log stupid messages like
Cannot decode Base64: "STREAM STATUS...) and destroy the session right way.