Fix yamux listener graceful handling of peer connection closure #1114

bomanaps · 2025-12-29T13:49:45Z

What was wrong?

How was it fixed?

Handle IncompleteReadError with "received 0 bytes" as clean connection
closure instead of error. When the peer closes the connection after
completing ping/pong exchange, yamux now detects this as a graceful
shutdown and logs INFO instead of ERROR, preventing false test failures.

Fixes: jvm-v1.2 x python-v0.4 (tcp, noise, yamux) interop test failure

Summary of approach.

To-Do

Clean up commit history
Add or update documentation related to these changes
Add entry to the release notes

Cute Animal Picture

bomanaps · 2025-12-29T13:51:03Z

Hello @acul71 @seetadev @sumanjeet0012 this is the fix for yamux error

acul71 · 2025-12-30T03:55:33Z

Hi @bomanaps,

Great work on this fix! I tested the commit in test-plans transport ping interop, and the tests with jvm-v1.2 now pass. ✅ The fix correctly addresses issue #1084.

Review Summary

The code changes look good - correctly distinguishing between clean connection closures and actual errors. All checks pass:

✅ Linting, type checking, tests (1809 passed), and docs all pass
✅ No merge conflicts, branch is in sync with main

Blocker: Missing Newsfragment

The PR is missing the required newsfragment file newsfragments/1084.bugfix.rst. This is mandatory for PR approval.

Please create the file with:

Fixed yamux listener incorrectly logging errors when peers close connections gracefully after completing protocol exchanges. Clean connection closures (0 bytes received) are now logged at INFO level instead of ERROR level.

The file must be named 1084.bugfix.rst and end with a newline.

Required Changes (Must be addressed before merge)

Standardize log message wording in libp2p/stream_muxer/yamux/yamux.py for consistency:
- Line 660: f"Yamux connection closed cleanly by peer {self.peer_id}"
- Line 958: f"Connection closed cleanly for peer {self.peer_id}"
The wording differs slightly. Consider including "Yamux" in both messages for consistency, e.g., change line 958 to: f"Yamux connection closed cleanly for peer {self.peer_id}"

Add structured error details to IncompleteReadError to avoid string parsing:

Current implementation (string parsing in libp2p/stream_muxer/yamux/yamux.py):

except IncompleteReadError as e:
    error_msg = str(e)
    is_clean_close = "received 0 bytes" in error_msg  # String parsing

Required implementation: Enhance IncompleteReadError to expose structured attributes:

# In libp2p/io/exceptions.py
class IncompleteReadError(IOException):
    """Fewer bytes were read than requested."""
    
    def __init__(
        self, 
        message: str, 
        expected_bytes: int, 
        received_bytes: int
    ) -> None:
        super().__init__(message)
        self.expected_bytes = expected_bytes
        self.received_bytes = received_bytes
    
    @property
    def is_clean_close(self) -> bool:
        """Returns True if this represents a clean connection closure (0 bytes received)."""
        return self.received_bytes == 0

Then update read_exactly() in libp2p/io/utils.py:

raise IncompleteReadError(
    f"Connection closed during read operation: expected {n} bytes but "
    f"received {len(buffer)} bytes{context_info}",
    expected_bytes=n,
    received_bytes=len(buffer)
)

And simplify usage in yamux.py:

except IncompleteReadError as e:
    if e.is_clean_close:  # No string parsing needed!
        logger.info(f"Yamux connection closed cleanly by peer {self.peer_id}")

This would make the code more robust and easier to maintain.

Add a test case verifying clean closure logging behavior

Current state: While existing tests in tests/core/stream_muxer/test_yamux.py cover yamux functionality, there's no specific test verifying that clean connection closures (0 bytes received) are logged at INFO level instead of ERROR level.

What's missing: A test that:

Verifies clean closure (0 bytes) is logged at INFO level
Verifies partial reads are logged at WARNING level
Ensures the fix doesn't regress

Suggested test case (add to tests/core/stream_muxer/test_yamux.py):

import logging
import trio
from libp2p.io.exceptions import IncompleteReadError

@pytest.mark.trio
async def test_yamux_clean_closure_logging(yamux_pair, caplog):
    """
    Test that clean connection closures (0 bytes received) are logged
    at INFO level, not ERROR level.
    
    This verifies the fix for issue #1084 where yamux listener
    incorrectly logged clean peer disconnections as errors.
    """
    client_yamux, server_yamux = yamux_pair
    
    # Set up logging capture
    with caplog.at_level(logging.INFO):
        # Open a stream and send some data
        stream = await client_yamux.open_stream()
        await stream.write(b"test data")
        await stream.close()
        
        # Close the underlying connection cleanly (simulating peer closure)
        # This should trigger IncompleteReadError with 0 bytes received
        await client_yamux.secured_conn.close()
        
        # Wait a bit for handle_incoming to process the closure
        await trio.sleep(0.1)
        
        # Verify clean closure is logged at INFO level
        info_logs = [r for r in caplog.records if r.levelname == "INFO"]
        error_logs = [r for r in caplog.records if r.levelname == "ERROR"]
        
        # Should have INFO log about clean closure
        clean_closure_logs = [
            r for r in info_logs 
            if "closed cleanly" in r.message.lower()
        ]
        assert len(clean_closure_logs) > 0, "Expected INFO log for clean closure"
        
        # Should NOT have ERROR log for clean closure
        error_closure_logs = [
            r for r in error_logs 
            if "received 0 bytes" in r.message.lower() or "incompleteread" in r.message.lower()
        ]
        assert len(error_closure_logs) == 0, "Clean closure should not log ERROR"

Alternative simpler test (if the above is too complex):

from libp2p.io.exceptions import IncompleteReadError

@pytest.mark.trio
async def test_yamux_incomplete_read_error_clean_close_detection():
    """
    Test that IncompleteReadError with 0 bytes is correctly identified
    as a clean closure.
    """
    # Simulate the error message format from read_exactly()
    error = IncompleteReadError(
        "Connection closed during read operation: expected 2 bytes but received 0 bytes"
    )
    
    # Verify the string-based detection works
    error_msg = str(error)
    is_clean_close = "received 0 bytes" in error_msg
    assert is_clean_close, "Should detect clean closure from error message"
    
    # Test partial read (not clean closure)
    partial_error = IncompleteReadError(
        "Connection closed during read operation: expected 2 bytes but received 1 bytes"
    )
    partial_msg = str(partial_error)
    is_partial = "received 0 bytes" not in partial_msg
    assert is_partial, "Partial read should not be detected as clean closure"

This would help prevent regressions and document the expected behavior.

Next Steps

All of the following must be addressed before this PR can be merged:

Add the newsfragment file newsfragments/1084.bugfix.rst as described in the "Blocker" section above.
Standardize log message wording (Suggestion added host folder & interface.py #1): Update line 958 in libp2p/stream_muxer/yamux/yamux.py to include "Yamux" for consistency with line 660:
```
f"Yamux connection closed cleanly for peer {self.peer_id}"
```
Add structured error details (Suggestion added basic_host.py #2): Implement the structured error details for IncompleteReadError as shown in the detailed example above. This includes:
- Enhancing IncompleteReadError in libp2p/io/exceptions.py to include expected_bytes and received_bytes attributes
- Adding an is_clean_close property
- Updating read_exactly() in libp2p/io/utils.py to pass these structured attributes
- Updating yamux.py to use e.is_clean_close instead of string parsing
Add test case (Suggestion define interfaces for milestone 1 #3): Add a test case to tests/core/stream_muxer/test_yamux.py verifying that clean closure (0 bytes) is logged at INFO level and partial reads are logged at WARNING level. You can use one of the test examples provided above.

Once all the above items are addressed, this PR will be ready for merge! 🚀

acul71 · 2025-12-30T04:05:10Z

jvm x python

   Test                                                 │ Dialer              │ Listener         │ Transport │ Secure │ Muxer │ Status │ Duration │ Handshake+RTT (ms) │ Ping RTT (ms) 
  ──────────────────────────────────────────────────────┼─────────────────────┼──────────────────┼───────────┼────────┼───────┼────────┼──────────┼────────────────────┼───────────────
   python-v0.4 x jvm-v1.2 (tcp, noise, yamux)           | python-v0.4         | jvm-v1.2         | tcp       | noise  | yamux | ✅     | 6s       | -                  | -             
   python-v0.4 x jvm-v1.2 (tcp, noise, mplex)           | python-v0.4         | jvm-v1.2         | tcp       | noise  | mplex | ✅     | 6s       | -                  | -             
   python-v0.4 x jvm-v1.2 (ws, noise, mplex)            | python-v0.4         | jvm-v1.2         | ws        | noise  | mplex | ✅     | 6s       | -                  | -             
   python-v0.4 x jvm-v1.2 (ws, noise, yamux)            | python-v0.4         | jvm-v1.2         | ws        | noise  | yamux | ✅     | 4s       | -                  | -             
   python-v0.4 x jvm-v1.2 (quic-v1)                     | python-v0.4         | jvm-v1.2         | quic-v1   | -      | -     | ✅     | 4s       | -                  | -             
   jvm-v1.2 x python-v0.4 (tcp, noise, yamux)           | jvm-v1.2            | python-v0.4      | tcp       | noise  | yamux | ✅     | 6s       | -                  | -             
   jvm-v1.2 x python-v0.4 (tcp, noise, mplex)           | jvm-v1.2            | python-v0.4      | tcp       | noise  | mplex | ✅     | 7s       | -                  | -             
   jvm-v1.2 x python-v0.4 (ws, noise, mplex)            | jvm-v1.2            | python-v0.4      | ws        | noise  | mplex | ✅     | 7s       | -                  | -             
   jvm-v1.2 x python-v0.4 (ws, noise, yamux)            | jvm-v1.2            | python-v0.4      | ws        | noise  | yamux | ✅     | 6s       | -                  | -             
   jvm-v1.2 x python-v0.4 (quic-v1)                     | jvm-v1.2            | python-v0.4      | quic-v1   | -      | -     | ✅     | 10s      | -                  | -

bomanaps · 2025-12-30T10:52:07Z

Hi @bomanaps,

Great work on this fix! I tested the commit in test-plans transport ping interop, and the tests with jvm-v1.2 now pass. ✅ The fix correctly addresses issue #1084.

Review Summary

The code changes look good - correctly distinguishing between clean connection closures and actual errors. All checks pass:

* ✅ Linting, type checking, tests (1809 passed), and docs all pass

* ✅ No merge conflicts, branch is in sync with main

Blocker: Missing Newsfragment

The PR is missing the required newsfragment file newsfragments/1084.bugfix.rst. This is mandatory for PR approval.

Please create the file with:

Fixed yamux listener incorrectly logging errors when peers close connections gracefully after completing protocol exchanges. Clean connection closures (0 bytes received) are now logged at INFO level instead of ERROR level.

The file must be named 1084.bugfix.rst and end with a newline.

Required Changes (Must be addressed before merge)

1. **Standardize log message wording** in `libp2p/stream_muxer/yamux/yamux.py` for consistency:
   
   * Line 660: `f"Yamux connection closed cleanly by peer {self.peer_id}"`
   * Line 958: `f"Connection closed cleanly for peer {self.peer_id}"`
   
   The wording differs slightly. Consider including "Yamux" in both messages for consistency, e.g., change line 958 to: `f"Yamux connection closed cleanly for peer {self.peer_id}"`

2. **Add structured error details to `IncompleteReadError`** to avoid string parsing:
   **Current implementation** (string parsing in `libp2p/stream_muxer/yamux/yamux.py`):
   ```python
   except IncompleteReadError as e:
       error_msg = str(e)
       is_clean_close = "received 0 bytes" in error_msg  # String parsing
   ```
   
   
       
         
       
   
         
       
   
       
     
   **Required implementation**: Enhance `IncompleteReadError` to expose structured attributes:
   ```python
   # In libp2p/io/exceptions.py
   class IncompleteReadError(IOException):
       """Fewer bytes were read than requested."""
       
       def __init__(
           self, 
           message: str, 
           expected_bytes: int, 
           received_bytes: int
       ) -> None:
           super().__init__(message)
           self.expected_bytes = expected_bytes
           self.received_bytes = received_bytes
       
       @property
       def is_clean_close(self) -> bool:
           """Returns True if this represents a clean connection closure (0 bytes received)."""
           return self.received_bytes == 0
   ```
   
   
       
         
       
   
         
       
   
       
     
   Then update `read_exactly()` in `libp2p/io/utils.py`:
   ```python
   raise IncompleteReadError(
       f"Connection closed during read operation: expected {n} bytes but "
       f"received {len(buffer)} bytes{context_info}",
       expected_bytes=n,
       received_bytes=len(buffer)
   )
   ```
   
   
       
         
       
   
         
       
   
       
     
   And simplify usage in `yamux.py`:
   ```python
   except IncompleteReadError as e:
       if e.is_clean_close:  # No string parsing needed!
           logger.info(f"Yamux connection closed cleanly by peer {self.peer_id}")
   ```
   
   
       
         
       
   
         
       
   
       
     
   This would make the code more robust and easier to maintain.

3. **Add a test case** verifying clean closure logging behavior
   **Current state**: While existing tests in `tests/core/stream_muxer/test_yamux.py` cover yamux functionality, there's no specific test verifying that clean connection closures (0 bytes received) are logged at INFO level instead of ERROR level.
   **What's missing**: A test that:
   
   * Verifies clean closure (0 bytes) is logged at INFO level
   * Verifies partial reads are logged at WARNING level
   * Ensures the fix doesn't regress
   
   **Suggested test case** (add to `tests/core/stream_muxer/test_yamux.py`):
   ```python
   import logging
   import trio
   from libp2p.io.exceptions import IncompleteReadError
   
   @pytest.mark.trio
   async def test_yamux_clean_closure_logging(yamux_pair, caplog):
       """
       Test that clean connection closures (0 bytes received) are logged
       at INFO level, not ERROR level.
       
       This verifies the fix for issue #1084 where yamux listener
       incorrectly logged clean peer disconnections as errors.
       """
       client_yamux, server_yamux = yamux_pair
       
       # Set up logging capture
       with caplog.at_level(logging.INFO):
           # Open a stream and send some data
           stream = await client_yamux.open_stream()
           await stream.write(b"test data")
           await stream.close()
           
           # Close the underlying connection cleanly (simulating peer closure)
           # This should trigger IncompleteReadError with 0 bytes received
           await client_yamux.secured_conn.close()
           
           # Wait a bit for handle_incoming to process the closure
           await trio.sleep(0.1)
           
           # Verify clean closure is logged at INFO level
           info_logs = [r for r in caplog.records if r.levelname == "INFO"]
           error_logs = [r for r in caplog.records if r.levelname == "ERROR"]
           
           # Should have INFO log about clean closure
           clean_closure_logs = [
               r for r in info_logs 
               if "closed cleanly" in r.message.lower()
           ]
           assert len(clean_closure_logs) > 0, "Expected INFO log for clean closure"
           
           # Should NOT have ERROR log for clean closure
           error_closure_logs = [
               r for r in error_logs 
               if "received 0 bytes" in r.message.lower() or "incompleteread" in r.message.lower()
           ]
           assert len(error_closure_logs) == 0, "Clean closure should not log ERROR"
   ```
   
   
       
         
       
   
         
       
   
       
     
   **Alternative simpler test** (if the above is too complex):
   ```python
   from libp2p.io.exceptions import IncompleteReadError
   
   @pytest.mark.trio
   async def test_yamux_incomplete_read_error_clean_close_detection():
       """
       Test that IncompleteReadError with 0 bytes is correctly identified
       as a clean closure.
       """
       # Simulate the error message format from read_exactly()
       error = IncompleteReadError(
           "Connection closed during read operation: expected 2 bytes but received 0 bytes"
       )
       
       # Verify the string-based detection works
       error_msg = str(error)
       is_clean_close = "received 0 bytes" in error_msg
       assert is_clean_close, "Should detect clean closure from error message"
       
       # Test partial read (not clean closure)
       partial_error = IncompleteReadError(
           "Connection closed during read operation: expected 2 bytes but received 1 bytes"
       )
       partial_msg = str(partial_error)
       is_partial = "received 0 bytes" not in partial_msg
       assert is_partial, "Partial read should not be detected as clean closure"
   ```
   
   
       
         
       
   
         
       
   
       
     
   This would help prevent regressions and document the expected behavior.

Next Steps

All of the following must be addressed before this PR can be merged:

1. **Add the newsfragment file** `newsfragments/1084.bugfix.rst` as described in the "Blocker" section above.

2. **Standardize log message wording** (Suggestion [added host folder & interface.py #1](https://github.com/libp2p/py-libp2p/pull/1)): Update line 958 in `libp2p/stream_muxer/yamux/yamux.py` to include "Yamux" for consistency with line 660:
   ```python
   f"Yamux connection closed cleanly for peer {self.peer_id}"
   ```

3. **Add structured error details** (Suggestion [added basic_host.py #2](https://github.com/libp2p/py-libp2p/pull/2)): Implement the structured error details for `IncompleteReadError` as shown in the detailed example above. This includes:
   
   * Enhancing `IncompleteReadError` in `libp2p/io/exceptions.py` to include `expected_bytes` and `received_bytes` attributes
   * Adding an `is_clean_close` property
   * Updating `read_exactly()` in `libp2p/io/utils.py` to pass these structured attributes
   * Updating `yamux.py` to use `e.is_clean_close` instead of string parsing

4. **Add test case** (Suggestion [define interfaces for milestone 1 #3](https://github.com/libp2p/py-libp2p/pull/3)): Add a test case to `tests/core/stream_muxer/test_yamux.py` verifying that clean closure (0 bytes) is logged at INFO level and partial reads are logged at WARNING level. You can use one of the test examples provided above.

Once all the above items are addressed, this PR will be ready for merge! 🚀

Hello @acul71 I have addressed the above review

acul71 · 2025-12-31T02:17:42Z

@bomanaps Thanks.
Merging this

Fix yamux listener graceful handling of peer connection closure

3fadaf5

add test cases and newsfragments

14a7881

acul71 merged commit f8ec326 into libp2p:main Dec 31, 2025
38 checks passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Fix yamux listener graceful handling of peer connection closure #1114

Fix yamux listener graceful handling of peer connection closure #1114

Uh oh!

bomanaps commented Dec 29, 2025

Uh oh!

bomanaps commented Dec 29, 2025

Uh oh!

acul71 commented Dec 30, 2025

Uh oh!

acul71 commented Dec 30, 2025 •

edited

Loading

Uh oh!

bomanaps commented Dec 30, 2025

Review Summary

Blocker: Missing Newsfragment

Required Changes (Must be addressed before merge)

Next Steps

Uh oh!

Uh oh!

acul71 commented Dec 31, 2025

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

Fix yamux listener graceful handling of peer connection closure #1114

Fix yamux listener graceful handling of peer connection closure #1114

Uh oh!

Conversation

bomanaps commented Dec 29, 2025

What was wrong?

How was it fixed?

To-Do

Cute Animal Picture

Uh oh!

bomanaps commented Dec 29, 2025

Uh oh!

acul71 commented Dec 30, 2025

Review Summary

Blocker: Missing Newsfragment

Required Changes (Must be addressed before merge)

Next Steps

Uh oh!

acul71 commented Dec 30, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

bomanaps commented Dec 30, 2025

Review Summary

Blocker: Missing Newsfragment

Required Changes (Must be addressed before merge)

Next Steps

Uh oh!

Uh oh!

acul71 commented Dec 31, 2025

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

acul71 commented Dec 30, 2025 •

edited

Loading