mirror of
https://github.com/GNS3/gns3-server.git
synced 2026-08-27 12:30:13 +03:00
Merge pull request #2639 from yueguobin/fix/telnet-server-connection-race-condition-3.0
Fix/telnet server connection race condition 3.0
This commit is contained in:
Jeremy Grossmann
GitHub
commit
6ac4c27bc1
308
docs/bugs/telnet-server-connection-race-condition.md
Normal file
308
docs/bugs/telnet-server-connection-race-condition.md
Normal file
@ -0,0 +1,308 @@
|
||||
# Telnet Server Connection Race Condition Bug
|
||||
|
||||
## Bug Report
|
||||
|
||||
**Date**: 2026-03-14
|
||||
**Severity**: High
|
||||
**Status**: Open
|
||||
**Component**: Telnet Server (`gns3server/utils/asyncio/telnet_server.py`)
|
||||
|
||||
## Error Logs
|
||||
|
||||
```
|
||||
2026-03-14 15:21:31 ERROR asyncio:1879 Unhandled exception in client_connected_cb
|
||||
transport: <_SelectorSocketTransport fd=67 read=polling write=<idle, bufsize=0>>
|
||||
Traceback (most recent call last):
|
||||
File "/home/yueguobin/myCode/GNS3/gns3-server/gns3server/utils/asyncio/telnet_server.py", line 215, in run
|
||||
await self._process(network_reader, network_writer, connection)
|
||||
File "/home/yueguobin/myCode/GNS3/gns3-server/gns3server/utils/asyncio/telnet_server.py", line 305, in _process
|
||||
client_info = connection_key.get_extra_info("socket").getpeername()
|
||||
File "/usr/lib64/python3.13/asyncio/trsock.py", line 77, in getpeername
|
||||
return self._sock.getpeername()
|
||||
~~~~~~~~~~~~~~~~~~~~~~^^
|
||||
OSError: [Errno 107] Transport endpoint is not connected
|
||||
```
|
||||
|
||||
## Root Cause Analysis
|
||||
|
||||
### Architecture
|
||||
|
||||
The GNS3 Telnet server architecture supports multiple concurrent client connections to a single node console:
|
||||
|
||||
```
|
||||
┌──────────────────────────────────────────────────────────┐
|
||||
│ Node (VPCS/Docker/Router/Switch, etc.) │
|
||||
│ - Independent process │
|
||||
│ - Normal operation, processing business logic │
|
||||
└────────────────────┬─────────────────────────────────────┘
|
||||
│ stdout (device output)
|
||||
│
|
||||
┌────────────▼─────────────────────────────────────┐
|
||||
│ AsyncioTelnetServer (Telnet Proxy Server) │
|
||||
│ - Reads output from Node │
|
||||
│ - Broadcasts to all connected clients │
|
||||
│ - ← ← Bug occurs at this layer ← ← │
|
||||
└────────────┬─────────────────────────────────────┘
|
||||
│
|
||||
┌────────────┼────────────┬──────────────────┐
|
||||
│ │ │ │
|
||||
Web Console Auto Script Client 1 Client 2
|
||||
(long-lived) (quick disco) (normal) (normal)
|
||||
```
|
||||
|
||||
### The Race Condition
|
||||
|
||||
The bug occurs in the broadcast logic when a client disconnects while the server is iterating through connections:
|
||||
|
||||
**Timeline**:
|
||||
```
|
||||
t1: Clients A, B, C connect to the same Telnet port
|
||||
t2: Device has output (e.g., log message)
|
||||
t3: Client A receives data and script immediately disconnects (FIN sent)
|
||||
t4: Server hasn't read EOF yet (event loop hasn't checked this connection)
|
||||
t5: Server iterates through connections to broadcast data
|
||||
t6: When iterating to Client A, getpeername() is called → OSError!
|
||||
```
|
||||
|
||||
### Code Location
|
||||
|
||||
**File**: `gns3server/utils/asyncio/telnet_server.py`
|
||||
**Line**: 305
|
||||
|
||||
**Problematic Code**:
|
||||
```python
|
||||
# Line 304-305
|
||||
for connection_key in list(self._connections.keys()):
|
||||
client_info = connection_key.get_extra_info("socket").getpeername() # ← OSError here
|
||||
connection = self._connections[connection_key]
|
||||
|
||||
try:
|
||||
connection.writer.write(data)
|
||||
await asyncio.wait_for(connection.writer.drain(), timeout=10)
|
||||
except:
|
||||
log.debug(f"Timeout while sending data to client: {client_info}, closing and removing from connection table.")
|
||||
connection.close()
|
||||
del self._connections[connection_key]
|
||||
```
|
||||
|
||||
### The Core Issue
|
||||
|
||||
The `getpeername()` call is **outside** the try-except block, so any OSError from it is not caught.
|
||||
|
||||
Additionally, the top-level exception handler at line 216 only catches `ConnectionError`:
|
||||
|
||||
```python
|
||||
# Line 212-227
|
||||
try:
|
||||
await self._write_intro(network_writer, echo=self._echo, binary=self._binary, naws=self._naws)
|
||||
await connection.connected()
|
||||
await self._process(network_reader, network_writer, connection)
|
||||
except ConnectionError: # ← Only catches ConnectionError
|
||||
async with self._lock:
|
||||
network_writer.close()
|
||||
if self._reader_process == network_reader:
|
||||
self._reader_process = None
|
||||
if self._current_read is not None:
|
||||
self._current_read.cancel()
|
||||
|
||||
await connection.disconnected()
|
||||
del self._connections[network_writer]
|
||||
```
|
||||
|
||||
**Python Exception Hierarchy**:
|
||||
```
|
||||
BaseException
|
||||
└─ Exception
|
||||
├─ ConnectionError ← Only this is caught
|
||||
│ ├─ ConnectionResetError
|
||||
│ ├─ BrokenPipeError
|
||||
│ └─ ...
|
||||
└─ OSError ← Actually thrown! (not a subclass of ConnectionError)
|
||||
└─ [Errno 107] Transport endpoint is not connected
|
||||
```
|
||||
|
||||
Since `OSError` is **not** a subclass of `ConnectionError`, it propagates uncaught to the asyncio event loop.
|
||||
|
||||
## Impact Assessment
|
||||
|
||||
### Immediate Effects
|
||||
|
||||
| Impact | Severity | Description |
|
||||
|--------|----------|-------------|
|
||||
| Connection interrupted | 🔴 High | The connection triggering the exception is terminated |
|
||||
| Resource leak | 🟠 Medium | socket/connection not properly cleaned up |
|
||||
| Other clients affected | 🟡 Low | Other clients on same port may miss broadcast data |
|
||||
| Service stability | 🟡 Low | Long-running may accumulate zombie connections |
|
||||
|
||||
### User-Reported Symptoms
|
||||
|
||||
After this error occurs, users report:
|
||||
|
||||
1. **Cannot open the affected node** - Clicking on the node fails
|
||||
2. **Cannot close the node** - Close button doesn't work
|
||||
3. **"Node not found" errors** - Operations on the node return 404
|
||||
4. **Refresh fixes it temporarily** - Reloading the page restores functionality
|
||||
|
||||
### Why This Happens
|
||||
|
||||
When the uncaught `OSError` occurs, the cleanup code at lines 217-227 **never executes**:
|
||||
|
||||
```python
|
||||
except ConnectionError:
|
||||
async with self._lock:
|
||||
network_writer.close() # ✗ Not executed
|
||||
if self._reader_process == network_reader:
|
||||
self._reader_process = None # ✗ Not executed
|
||||
if self._current_read is not None:
|
||||
self._current_read.cancel() # ✗ Not executed
|
||||
await connection.disconnected() # ✗ Not executed
|
||||
del self._connections[network_writer] # ✗ Not executed
|
||||
```
|
||||
|
||||
This leads to:
|
||||
- **Resource leaks**: socket and writer not closed, file descriptors leaked
|
||||
- **State inconsistency**: `_connections` dictionary retains disconnected connections
|
||||
- **Potential deadlocks**: Locks may not be released if exception occurs while holding them
|
||||
- **Subsequent operation failures**: Future operations may access zombie connections
|
||||
|
||||
### Effect on Node Process
|
||||
|
||||
**The Node process itself is NOT affected**:
|
||||
- Node continues running normally
|
||||
- Node's stdout has already been read by the proxy
|
||||
- The bug occurs during the broadcast phase, after data has been read
|
||||
|
||||
The issue is in the **Telnet Proxy layer**, not the node itself.
|
||||
|
||||
## Trigger Conditions
|
||||
|
||||
This error is more likely to occur with:
|
||||
|
||||
| Scenario | Probability | Reason |
|
||||
|----------|-------------|--------|
|
||||
| **Automated scripts** | 🔴 High | Fast connect → execute → disconnect, small time window |
|
||||
| **Manual operation** | 🟡 Medium | Can occur (e.g., closing terminal, network fluctuation) |
|
||||
| **Normal usage** | 🟢 Low | Human operations slower, server usually detects EOF first |
|
||||
|
||||
### Typical Scenario
|
||||
|
||||
1. User opens Web Console (long-lived connection)
|
||||
2. Automated script connects → executes command → quickly disconnects
|
||||
3. While script disconnects, device has output that needs broadcasting
|
||||
4. During connection iteration, script connection already closed
|
||||
5. `getpeername()` call fails with OSError
|
||||
|
||||
## Related Issues
|
||||
|
||||
A secondary issue was found in the error handler:
|
||||
|
||||
**File**: `gns3server/api/server.py`
|
||||
**Line**: 162
|
||||
|
||||
```python
|
||||
@app.exception_handler(ControllerNotFoundError)
|
||||
async def controller_not_found_error_handler(request: Request, exc: ControllerNotFoundError):
|
||||
log.error(f"Controller not found error in {request.url.path} ({request.method}): {exc}")
|
||||
# ^^^^^^^^^^^^^^^
|
||||
return JSONResponse(...)
|
||||
```
|
||||
|
||||
**Problem**: `request.method` only exists in HTTP requests, not WebSocket connections.
|
||||
|
||||
When a WebSocket request triggers this exception handler:
|
||||
```
|
||||
ControllerNotFoundError: Node ID xxx doesn't exist
|
||||
↓
|
||||
Attempt to log error
|
||||
↓
|
||||
AttributeError: 'WebSocket' object has no attribute 'method'
|
||||
```
|
||||
|
||||
This masks the original error with an attribute error.
|
||||
|
||||
## Proposed Fix
|
||||
|
||||
### Primary Fix (Telnet Server)
|
||||
|
||||
Move `getpeername()` inside the try block and catch OSError:
|
||||
|
||||
```python
|
||||
# Lines 303-314
|
||||
for connection_key in list(self._connections.keys()):
|
||||
connection = self._connections[connection_key]
|
||||
client_info = None
|
||||
|
||||
try:
|
||||
client_info = connection_key.get_extra_info("socket").getpeername()
|
||||
connection.writer.write(data)
|
||||
await asyncio.wait_for(connection.writer.drain(), timeout=10)
|
||||
except (OSError, ConnectionError, asyncio.TimeoutError) as e:
|
||||
log.debug(f"Error sending data to client {client_info}: {e}, closing and removing from connection table.")
|
||||
connection.close()
|
||||
del self._connections[connection_key]
|
||||
```
|
||||
|
||||
### Secondary Fix (Top-level Exception Handler)
|
||||
|
||||
Catch OSError in the main handler to ensure cleanup:
|
||||
|
||||
```python
|
||||
# Lines 212-227
|
||||
try:
|
||||
await self._write_intro(network_writer, echo=self._echo, binary=self._binary, naws=self._naws)
|
||||
await connection.connected()
|
||||
await self._process(network_reader, network_writer, connection)
|
||||
except (ConnectionError, OSError): # ← Add OSError
|
||||
async with self._lock:
|
||||
network_writer.close()
|
||||
if self._reader_process == network_reader:
|
||||
self._reader_process = None
|
||||
if self._current_read is not None:
|
||||
self._current_read.cancel()
|
||||
|
||||
await connection.disconnected()
|
||||
del self._connections[network_writer]
|
||||
```
|
||||
|
||||
### Tertiary Fix (API Error Handler)
|
||||
|
||||
Fix the WebSocket error handler:
|
||||
|
||||
```python
|
||||
@app.exception_handler(ControllerNotFoundError)
|
||||
async def controller_not_found_error_handler(request: Request, exc: ControllerNotFoundError):
|
||||
method = getattr(request, 'method', 'WebSocket')
|
||||
log.error(f"Controller not found error in {request.url.path} ({method}): {exc}")
|
||||
return JSONResponse(
|
||||
status_code=status.HTTP_404_NOT_FOUND,
|
||||
content={"message": str(exc)},
|
||||
)
|
||||
```
|
||||
|
||||
## Reproduction Steps
|
||||
|
||||
**To be documented** after testing.
|
||||
|
||||
Potential reproduction scenario:
|
||||
1. Start a GNS3 node with console enabled (e.g., VPCS)
|
||||
2. Open web console to keep a long-lived connection
|
||||
3. Run automated script that:
|
||||
- Connects to the same console port
|
||||
- Executes a command
|
||||
- Immediately disconnects
|
||||
4. While script is disconnecting, trigger device output
|
||||
5. Observe the error in logs
|
||||
|
||||
## References
|
||||
|
||||
- **Files**:
|
||||
- `gns3server/utils/asyncio/telnet_server.py:305` (primary issue)
|
||||
- `gns3server/utils/asyncio/telnet_server.py:216` (exception handler)
|
||||
- `gns3server/api/server.py:162` (secondary issue)
|
||||
|
||||
- **Related Commits**:
|
||||
- Recent telnet-related work on feature branch
|
||||
|
||||
- **Error Patterns**:
|
||||
- Race condition in connection management
|
||||
- Incomplete exception handling in asyncio code
|
||||
@ -213,7 +213,7 @@ class AsyncioTelnetServer:
|
||||
await self._write_intro(network_writer, echo=self._echo, binary=self._binary, naws=self._naws)
|
||||
await connection.connected()
|
||||
await self._process(network_reader, network_writer, connection)
|
||||
except ConnectionError:
|
||||
except (ConnectionError, OSError):
|
||||
async with self._lock:
|
||||
network_writer.close()
|
||||
# await network_writer.wait_closed() # this doesn't work in Python 3.6
|
||||
@ -224,7 +224,8 @@ class AsyncioTelnetServer:
|
||||
self._current_read.cancel()
|
||||
|
||||
await connection.disconnected()
|
||||
del self._connections[network_writer]
|
||||
# Use pop() to avoid KeyError if connection was already removed
|
||||
self._connections.pop(network_writer, None)
|
||||
|
||||
async def close(self):
|
||||
for writer, connection in self._connections.items():
|
||||
@ -302,16 +303,17 @@ class AsyncioTelnetServer:
|
||||
|
||||
# Replicate the output on all clients
|
||||
for connection_key in list(self._connections.keys()):
|
||||
client_info = connection_key.get_extra_info("socket").getpeername()
|
||||
connection = self._connections[connection_key]
|
||||
client_info = None
|
||||
|
||||
try:
|
||||
client_info = connection_key.get_extra_info("socket").getpeername()
|
||||
connection.writer.write(data)
|
||||
await asyncio.wait_for(connection.writer.drain(), timeout=10)
|
||||
except:
|
||||
log.debug(f"Timeout while sending data to client: {client_info}, closing and removing from connection table.")
|
||||
except (OSError, ConnectionError, asyncio.TimeoutError) as e:
|
||||
log.debug(f"Error sending data to client {client_info}: {e}, closing and removing from connection table.")
|
||||
connection.close()
|
||||
del self._connections[connection_key]
|
||||
self._connections.pop(connection_key, None)
|
||||
|
||||
async def _read(self, cmd, buffer, location, reader):
|
||||
""" Reads next op from the buffer or reader"""
|
||||
|
||||
200
tests/stress/README.md
Normal file
200
tests/stress/README.md
Normal file
@ -0,0 +1,200 @@
|
||||
# Telnet Server Race Condition Stress Test
|
||||
|
||||
## Overview
|
||||
|
||||
This stress test reproduces the `OSError: [Errno 107] Transport endpoint is not connected` bug that occurs when clients rapidly connect and disconnect while the telnet server is broadcasting data to multiple clients.
|
||||
|
||||
## Background
|
||||
|
||||
The bug is a race condition in `gns3server/utils/asyncio/telnet_server.py`:
|
||||
|
||||
1. Multiple clients connect to the same telnet console port
|
||||
2. One client (typically an automated script) quickly connects, sends commands, and disconnects
|
||||
3. While the client is disconnecting, the telnet server is iterating through connections to broadcast data
|
||||
4. When the server tries to call `getpeername()` on the disconnected client's socket, it throws `OSError`
|
||||
5. This exception was not caught, causing it to propagate to the asyncio event loop
|
||||
|
||||
## Test Design
|
||||
|
||||
### Client Types
|
||||
|
||||
1. **Rapid-Fire Clients** (trigger the bug)
|
||||
- Quickly connect → send commands → immediately disconnect
|
||||
- Simulate automated scripts
|
||||
- Use immediate (abrupt) TCP close without graceful shutdown
|
||||
- Very short delays (1-10ms)
|
||||
|
||||
2. **Long-Lived Clients** (should not be affected)
|
||||
- Stay connected for the entire test duration
|
||||
- Periodically send commands
|
||||
- Simulate web console users
|
||||
- Verify they don't experience connection issues
|
||||
|
||||
### Race Condition Trigger
|
||||
|
||||
```
|
||||
Timeline:
|
||||
t1: Rapid client connects
|
||||
t2: Sends commands
|
||||
t3: Starts disconnecting (TCP FIN sent)
|
||||
t4: Server hasn't read EOF yet
|
||||
t5: Server iterates connections to broadcast
|
||||
t6: Calls getpeername() on rapid client → OSError!
|
||||
```
|
||||
|
||||
## Usage
|
||||
|
||||
### Prerequisites
|
||||
|
||||
1. Start a GNS3 node with telnet console enabled (e.g., VPCS)
|
||||
2. Note the console port (e.g., 2000)
|
||||
3. Make sure you can connect to it: `telnet 127.0.0.1 2000`
|
||||
|
||||
### Basic Test
|
||||
|
||||
```bash
|
||||
# Quick test with default settings
|
||||
python tests/stress/telnet_race_condition_test.py --port 2000
|
||||
```
|
||||
|
||||
### Heavy Load Test
|
||||
|
||||
```bash
|
||||
# 50 rapid clients, each doing 100 connect/disconnect cycles
|
||||
python tests/stress/telnet_race_condition_test.py \
|
||||
--port 2000 \
|
||||
--rapid-clients 50 \
|
||||
--iterations 100
|
||||
```
|
||||
|
||||
### Extended Duration Test
|
||||
|
||||
```bash
|
||||
# Run for 2 minutes with multiple long-lived clients
|
||||
python tests/stress/telnet_race_condition_test.py \
|
||||
--port 2000 \
|
||||
--rapid-clients 20 \
|
||||
--long-lived 5 \
|
||||
--iterations 200 \
|
||||
--duration 120
|
||||
```
|
||||
|
||||
### Verbose Logging
|
||||
|
||||
```bash
|
||||
# See detailed connection/disconnection logs
|
||||
python tests/stress/telnet_race_condition_test.py \
|
||||
--port 2000 \
|
||||
--verbose
|
||||
```
|
||||
|
||||
## Expected Results
|
||||
|
||||
### Before Fix
|
||||
|
||||
**GNS3 Server Logs:**
|
||||
```
|
||||
2026-03-14 23:32:43 ERROR asyncio:1879 Unhandled exception in client_connected_cb
|
||||
OSError: [Errno 107] Transport endpoint is not connected
|
||||
```
|
||||
|
||||
**Symptoms:**
|
||||
- ❌ Error logs appear
|
||||
- ❌ Long-lived clients may miss broadcast data
|
||||
- ❌ Possible resource leaks
|
||||
- ❌ Node state may become inconsistent
|
||||
|
||||
### After Fix
|
||||
|
||||
**GNS3 Server Logs:**
|
||||
```
|
||||
2026-03-14 23:35:12 DEBUG gns3server.utils.asyncio.telnet_server:310
|
||||
Error sending data to client None: [Errno 107] Transport endpoint is not connected,
|
||||
closing and removing from connection table.
|
||||
```
|
||||
|
||||
**Symptoms:**
|
||||
- ✅ Only DEBUG level logs (not ERROR)
|
||||
- ✅ Long-lived clients unaffected
|
||||
- ✅ Proper resource cleanup
|
||||
- ✅ Node state remains consistent
|
||||
|
||||
## Test Parameters
|
||||
|
||||
| Parameter | Default | Description |
|
||||
|-----------|---------|-------------|
|
||||
| `--host` | 127.0.0.1 | Telnet server host |
|
||||
| `--port` | 2000 | Telnet server port |
|
||||
| `--rapid-clients` | 10 | Number of rapid connect/disconnect clients |
|
||||
| `--long-lived` | 2 | Number of long-lived clients |
|
||||
| `--iterations` | 50 | Connect/disconnect cycles per rapid client |
|
||||
| `--duration` | 30.0 | Test duration in seconds |
|
||||
| `--verbose` | False | Enable debug logging |
|
||||
|
||||
## Tips for Reproducing the Bug
|
||||
|
||||
1. **Use multiple concurrent clients**: The bug is more likely with 10+ rapid clients
|
||||
2. **Very fast disconnections**: The test uses 1-10ms delays
|
||||
3. **Immediate TCP close**: Uses `writer.close()` without `wait_closed()`
|
||||
4. **Monitor GNS3 logs**: Watch for `OSError: [Errno 107]`
|
||||
5. **Long test duration**: Run for 60+ seconds to accumulate events
|
||||
|
||||
## Verification Checklist
|
||||
|
||||
Run the test and verify:
|
||||
|
||||
- [ ] Before fix: ERROR logs appear in GNS3 server
|
||||
- [ ] After fix: Only DEBUG logs appear
|
||||
- [ ] Long-lived clients stay connected throughout test
|
||||
- [ ] No resource leaks (check with `lsof` or netstat)
|
||||
- [ ] Node remains operational after test
|
||||
|
||||
## Example Session
|
||||
|
||||
```bash
|
||||
# Terminal 1: Start GNS3 server and watch logs
|
||||
gns3server --log-level debug
|
||||
# Watch for: OSError or "Error sending data to client"
|
||||
|
||||
# Terminal 2: Run stress test
|
||||
cd /home/yueguobin/myCode/GNS3/gns3-server
|
||||
python tests/stress/telnet_race_condition_test.py --port 2000 --rapid-clients 20
|
||||
|
||||
# Expected output:
|
||||
# ======================================================================
|
||||
# Telnet Server Race Condition Stress Test
|
||||
# ======================================================================
|
||||
# Target: 127.0.0.1:2000
|
||||
# Rapid clients: 20 (each 50 iterations)
|
||||
# Long-lived clients: 2 (duration: 30.0s)
|
||||
# ...
|
||||
# Rapid clients completed: 1000 success, 0 failures
|
||||
# ======================================================================
|
||||
```
|
||||
|
||||
## Troubleshooting
|
||||
|
||||
### "Connection refused"
|
||||
|
||||
- Make sure GNS3 node is started
|
||||
- Check the console port number
|
||||
- Verify telnet is working: `telnet 127.0.0.1 PORT`
|
||||
|
||||
### Bug not reproducing
|
||||
|
||||
- Increase `--rapid-clients` (try 50+)
|
||||
- Increase `--iterations` (try 200+)
|
||||
- Make sure GNS3 server log level is DEBUG
|
||||
- Verify you're testing unpatched code
|
||||
|
||||
### Test hangs
|
||||
|
||||
- Check if node is still running
|
||||
- Try reducing `--duration`
|
||||
- Check network connectivity
|
||||
|
||||
## Related Files
|
||||
|
||||
- Bug: `gns3server/utils/asyncio/telnet_server.py:305`
|
||||
- Fix commit: (to be added)
|
||||
- Documentation: `docs/bugs/telnet-server-connection-race-condition.md`
|
||||
474
tests/stress/telnet_race_condition_test.py
Normal file
474
tests/stress/telnet_race_condition_test.py
Normal file
@ -0,0 +1,474 @@
|
||||
#!/usr/bin/env python3
|
||||
"""
|
||||
Telnet Server Race Condition Stress Test
|
||||
|
||||
This script reproduces the OSError: [Errno 107] bug by rapidly
|
||||
connecting and disconnecting clients to trigger the race condition
|
||||
during broadcast operations.
|
||||
|
||||
Usage:
|
||||
python telnet_race_condition_test.py --host 127.0.0.1 --port 2000 --connections 10
|
||||
"""
|
||||
|
||||
import asyncio
|
||||
import argparse
|
||||
import logging
|
||||
import time
|
||||
from typing import List, Optional
|
||||
import sys
|
||||
|
||||
# Configure logging
|
||||
logging.basicConfig(
|
||||
level=logging.INFO,
|
||||
format='%(asctime)s - %(levelname)s - %(message)s'
|
||||
)
|
||||
log = logging.getLogger(__name__)
|
||||
|
||||
|
||||
class TelnetClient:
|
||||
"""A simple telnet client for stress testing."""
|
||||
|
||||
def __init__(self, client_id: int, host: str, port: int):
|
||||
self.client_id = client_id
|
||||
self.host = host
|
||||
self.port = port
|
||||
self.reader: Optional[asyncio.StreamReader] = None
|
||||
self.writer: Optional[asyncio.StreamWriter] = None
|
||||
self.connected = False
|
||||
|
||||
async def connect(self) -> bool:
|
||||
"""Establish telnet connection."""
|
||||
try:
|
||||
log.debug(f"Client {self.client_id}: Connecting to {self.host}:{self.port}...")
|
||||
self.reader, self.writer = await asyncio.wait_for(
|
||||
asyncio.open_connection(self.host, self.port),
|
||||
timeout=5.0
|
||||
)
|
||||
self.connected = True
|
||||
log.debug(f"Client {self.client_id}: Connected successfully")
|
||||
return True
|
||||
except Exception as e:
|
||||
log.warning(f"Client {self.client_id}: Connection failed: {e}")
|
||||
return False
|
||||
|
||||
async def send_command(self, command: str) -> bool:
|
||||
"""Send a command to the telnet server."""
|
||||
if not self.writer or not self.connected:
|
||||
return False
|
||||
|
||||
try:
|
||||
self.writer.write(command.encode() + b'\r\n')
|
||||
await asyncio.wait_for(self.writer.drain(), timeout=2.0)
|
||||
log.debug(f"Client {self.client_id}: Sent command: {command.strip()}")
|
||||
return True
|
||||
except Exception as e:
|
||||
log.warning(f"Client {self.client_id}: Send failed: {e}")
|
||||
return False
|
||||
|
||||
async def receive_response(self, timeout: float = 1.0) -> Optional[str]:
|
||||
"""Receive response from server (optional)."""
|
||||
if not self.reader or not self.connected:
|
||||
return None
|
||||
|
||||
try:
|
||||
data = await asyncio.wait_for(self.reader.read(1024), timeout=timeout)
|
||||
if data:
|
||||
response = data.decode('utf-8', errors='ignore')
|
||||
log.debug(f"Client {self.client_id}: Received: {response[:50]}...")
|
||||
return response
|
||||
except asyncio.TimeoutError:
|
||||
log.debug(f"Client {self.client_id}: No response (timeout)")
|
||||
except Exception as e:
|
||||
log.debug(f"Client {self.client_id}: Receive error: {e}")
|
||||
return None
|
||||
|
||||
async def disconnect(self, immediate: bool = False):
|
||||
"""
|
||||
Disconnect from telnet server.
|
||||
|
||||
Args:
|
||||
immediate: If True, close immediately without graceful shutdown.
|
||||
This simulates abrupt disconnection (TCP FIN/RST).
|
||||
"""
|
||||
if not self.writer:
|
||||
return
|
||||
|
||||
try:
|
||||
if immediate:
|
||||
# Abrupt close - doesn't wait for flush
|
||||
self.writer.close()
|
||||
# Don't wait for close to complete
|
||||
log.debug(f"Client {self.client_id}: Abruptly disconnected")
|
||||
else:
|
||||
# Graceful close
|
||||
self.writer.close()
|
||||
await asyncio.wait_for(self.writer.wait_closed(), timeout=1.0)
|
||||
log.debug(f"Client {self.client_id}: Gracefully disconnected")
|
||||
except Exception as e:
|
||||
log.debug(f"Client {self.client_id}: Disconnect error: {e}")
|
||||
finally:
|
||||
self.connected = False
|
||||
self.writer = None
|
||||
self.reader = None
|
||||
|
||||
|
||||
async def rapid_fire_client(
|
||||
client_id: int,
|
||||
host: str,
|
||||
port: int,
|
||||
iterations: int,
|
||||
min_delay: float = 0.001,
|
||||
max_delay: float = 0.01,
|
||||
receive_before_disconnect: bool = False,
|
||||
immediate_disconnect: bool = True,
|
||||
device_type: str = "iou-l3"
|
||||
):
|
||||
"""
|
||||
A client that rapidly connects, sends commands, and disconnects.
|
||||
|
||||
This is designed to trigger the race condition by disconnecting
|
||||
quickly while the server might be broadcasting data.
|
||||
|
||||
Args:
|
||||
client_id: Unique identifier for this client
|
||||
host: Telnet server host
|
||||
port: Telnet server port
|
||||
iterations: Number of connect/disconnect cycles
|
||||
min_delay: Minimum delay before disconnect (seconds)
|
||||
max_delay: Maximum delay before disconnect (seconds)
|
||||
receive_before_disconnect: Whether to wait for response before disconnect
|
||||
immediate_disconnect: Use abrupt close instead of graceful close
|
||||
device_type: Type of device (iou-l3, vpcs, etc.)
|
||||
"""
|
||||
success_count = 0
|
||||
fail_count = 0
|
||||
|
||||
# Cisco IOS commands for IOU-L3 that trigger broadcast output
|
||||
ios_commands = [
|
||||
"show ip interface brief",
|
||||
"show ip route",
|
||||
"show running-config",
|
||||
"show version",
|
||||
"show protocols",
|
||||
"debug ip ospf events",
|
||||
"undebug ip ospf events",
|
||||
"clear ip ospf process",
|
||||
]
|
||||
|
||||
# Commands that generate significant output
|
||||
broadcast_trigger_commands = [
|
||||
"show running-config",
|
||||
"show ip ospf neighbor",
|
||||
"show ip ospf database",
|
||||
"show ip protocols",
|
||||
"show ip route",
|
||||
"write memory", # This generates "Building configuration..." output
|
||||
]
|
||||
|
||||
for i in range(iterations):
|
||||
client = TelnetClient(client_id, host, port)
|
||||
|
||||
# Connect
|
||||
if not await client.connect():
|
||||
fail_count += 1
|
||||
await asyncio.sleep(0.1)
|
||||
continue
|
||||
|
||||
# Wait a bit for the telnet session to stabilize
|
||||
await asyncio.sleep(0.05)
|
||||
|
||||
# Send commands based on device type
|
||||
if device_type == "iou-l3":
|
||||
# Use IOS commands that trigger broadcasts
|
||||
cmd_index = i % len(broadcast_trigger_commands)
|
||||
cmd = broadcast_trigger_commands[cmd_index]
|
||||
|
||||
# Send the command
|
||||
await client.send_command(cmd)
|
||||
|
||||
# Small delay to let server start broadcasting
|
||||
await asyncio.sleep(0.01)
|
||||
|
||||
# Send another command quickly to increase broadcast chance
|
||||
await client.send_command("show ip ospf")
|
||||
|
||||
# Very short delay to increase race condition likelihood
|
||||
delay = min_delay + (max_delay - min_delay) * (i % 10) / 10.0
|
||||
await asyncio.sleep(delay)
|
||||
|
||||
else:
|
||||
# Generic test commands for other devices
|
||||
test_commands = ["?", "version", "list"]
|
||||
for cmd in test_commands:
|
||||
await client.send_command(cmd)
|
||||
|
||||
if receive_before_disconnect:
|
||||
await client.receive_response(timeout=0.1)
|
||||
|
||||
delay = min_delay + (max_delay - min_delay) * (i % 10) / 10.0
|
||||
await asyncio.sleep(delay)
|
||||
|
||||
# Disconnect - this is where the race condition triggers
|
||||
await client.disconnect(immediate=immediate_disconnect)
|
||||
|
||||
success_count += 1
|
||||
|
||||
# Small delay between iterations
|
||||
await asyncio.sleep(0.05)
|
||||
|
||||
log.info(f"Client {client_id}: Completed {success_count}/{iterations} cycles ({fail_count} failures)")
|
||||
return success_count, fail_count
|
||||
|
||||
|
||||
async def long_lived_client(
|
||||
client_id: int,
|
||||
host: str,
|
||||
port: str,
|
||||
duration: float,
|
||||
send_interval: float = 1.0
|
||||
):
|
||||
"""
|
||||
A long-lived client that stays connected and periodically sends commands.
|
||||
|
||||
This simulates a web console user and should NOT experience issues
|
||||
when other clients disconnect rapidly.
|
||||
|
||||
Args:
|
||||
client_id: Unique identifier
|
||||
host: Telnet server host
|
||||
port: Telnet server port
|
||||
duration: How long to stay connected (seconds)
|
||||
send_interval: Interval between commands (seconds)
|
||||
"""
|
||||
client = TelnetClient(client_id, host, port)
|
||||
|
||||
if not await client.connect():
|
||||
log.error(f"Long-lived client {client_id}: Failed to connect")
|
||||
return
|
||||
|
||||
log.info(f"Long-lived client {client_id}: Connected for {duration}s")
|
||||
|
||||
start_time = time.time()
|
||||
commands_sent = 0
|
||||
|
||||
while time.time() - start_time < duration:
|
||||
await asyncio.sleep(send_interval)
|
||||
|
||||
# Send periodic commands to keep connection active
|
||||
test_commands = ["?", "help", "status"]
|
||||
cmd = test_commands[commands_sent % len(test_commands)]
|
||||
|
||||
if await client.send_command(cmd):
|
||||
commands_sent += 1
|
||||
await client.receive_response(timeout=0.5)
|
||||
|
||||
await client.disconnect(immediate=False)
|
||||
log.info(f"Long-lived client {client_id}: Sent {commands_sent} commands over {duration}s")
|
||||
|
||||
|
||||
async def run_stress_test(
|
||||
host: str,
|
||||
port: int,
|
||||
rapid_clients: int,
|
||||
long_lived_clients: int,
|
||||
iterations_per_client: int,
|
||||
test_duration: float,
|
||||
device_type: str = "iou-l3"
|
||||
):
|
||||
"""
|
||||
Run the stress test with multiple concurrent clients.
|
||||
|
||||
This creates:
|
||||
1. Rapid-fire clients that connect/disconnect quickly (triggers bug)
|
||||
2. Long-lived clients that stay connected (should not be affected)
|
||||
|
||||
Args:
|
||||
host: Telnet server host
|
||||
port: Telnet server port
|
||||
rapid_clients: Number of rapid connect/disconnect clients
|
||||
long_lived_clients: Number of long-lived clients
|
||||
iterations_per_client: Iterations per rapid client
|
||||
test_duration: Test duration in seconds
|
||||
device_type: Type of device (iou-l3, vpcs, etc.)
|
||||
"""
|
||||
log.info("=" * 70)
|
||||
log.info("Telnet Server Race Condition Stress Test")
|
||||
log.info("=" * 70)
|
||||
log.info(f"Target: {host}:{port}")
|
||||
log.info(f"Device Type: {device_type}")
|
||||
log.info(f"Rapid clients: {rapid_clients} (each {iterations_per_client} iterations)")
|
||||
log.info(f"Long-lived clients: {long_lived_clients} (duration: {test_duration}s)")
|
||||
log.info(f"Expected behavior: Rapid clients disconnect, long-lived clients unaffected")
|
||||
log.info("=" * 70)
|
||||
|
||||
tasks: List[asyncio.Task] = []
|
||||
|
||||
# Start long-lived clients first (simulate web console users)
|
||||
for i in range(long_lived_clients):
|
||||
task = asyncio.create_task(
|
||||
long_lived_client(
|
||||
client_id=1000 + i,
|
||||
host=host,
|
||||
port=port,
|
||||
duration=test_duration,
|
||||
send_interval=2.0
|
||||
)
|
||||
)
|
||||
tasks.append(task)
|
||||
await asyncio.sleep(0.1) # Stagger connections
|
||||
|
||||
# Give long-lived clients time to establish
|
||||
await asyncio.sleep(1.0)
|
||||
|
||||
# Start rapid-fire clients (simulate automated scripts)
|
||||
log.info("Starting rapid-fire clients...")
|
||||
rapid_tasks: List[asyncio.Task] = []
|
||||
|
||||
for i in range(rapid_clients):
|
||||
task = asyncio.create_task(
|
||||
rapid_fire_client(
|
||||
client_id=i,
|
||||
host=host,
|
||||
port=port,
|
||||
iterations=iterations_per_client,
|
||||
min_delay=0.001, # 1ms - very fast
|
||||
max_delay=0.01, # 10ms - still fast
|
||||
receive_before_disconnect=False, # Don't wait for response
|
||||
immediate_disconnect=True, # Abrupt close
|
||||
device_type=device_type
|
||||
)
|
||||
)
|
||||
rapid_tasks.append(task)
|
||||
await asyncio.sleep(0.05) # Slightly stagger starts
|
||||
|
||||
# Wait for all rapid clients to complete
|
||||
log.info("Waiting for rapid-fire clients to complete...")
|
||||
rapid_results = await asyncio.gather(*rapid_tasks, return_exceptions=True)
|
||||
|
||||
# Calculate statistics
|
||||
total_success = 0
|
||||
total_failures = 0
|
||||
for result in rapid_results:
|
||||
if isinstance(result, Exception):
|
||||
log.error(f"Rapid client failed with exception: {result}")
|
||||
elif isinstance(result, tuple):
|
||||
success, failures = result
|
||||
total_success += success
|
||||
total_failures += failures
|
||||
|
||||
log.info(f"Rapid clients completed: {total_success} success, {total_failures} failures")
|
||||
|
||||
# Wait for long-lived clients to finish
|
||||
log.info("Waiting for long-lived clients to complete...")
|
||||
await asyncio.gather(*tasks)
|
||||
|
||||
log.info("=" * 70)
|
||||
log.info("Stress test completed!")
|
||||
log.info("=" * 70)
|
||||
log.info("Check GNS3 server logs for:")
|
||||
log.info(" - ❌ 'OSError: [Errno 107] Transport endpoint is not connected'")
|
||||
log.info(" - ✅ 'Error sending data to client None: ...' (properly handled)")
|
||||
log.info("=" * 70)
|
||||
|
||||
|
||||
def main():
|
||||
parser = argparse.ArgumentParser(
|
||||
description="Stress test for telnet server race condition",
|
||||
formatter_class=argparse.RawDescriptionHelpFormatter,
|
||||
epilog="""
|
||||
Examples:
|
||||
# Basic test with IOU-L3 device (default)
|
||||
python telnet_race_condition_test.py --port 2000
|
||||
|
||||
# Test with IOU-L3 using OSPF/show commands (triggers broadcast)
|
||||
python telnet_race_condition_test.py --port 2000 --device-type iou-l3 --rapid-clients 20
|
||||
|
||||
# Heavy load with many clients
|
||||
python telnet_race_condition_test.py --port 2000 --rapid-clients 50 --iterations 100
|
||||
|
||||
# Test with VPCS device
|
||||
python telnet_race_condition_test.py --port 2000 --device-type vpcs
|
||||
|
||||
Device Types:
|
||||
iou-l3 - Cisco IOS L3 router (uses show/run/write commands that trigger broadcast)
|
||||
vpcs - VPCS simulator (simple commands)
|
||||
generic - Generic device (basic test commands)
|
||||
"""
|
||||
)
|
||||
|
||||
parser.add_argument(
|
||||
'--host',
|
||||
default='127.0.0.1',
|
||||
help='Telnet server host (default: 127.0.0.1)'
|
||||
)
|
||||
|
||||
parser.add_argument(
|
||||
'--port',
|
||||
type=int,
|
||||
default=2000,
|
||||
help='Telnet server port (default: 2000)'
|
||||
)
|
||||
|
||||
parser.add_argument(
|
||||
'--rapid-clients',
|
||||
type=int,
|
||||
default=10,
|
||||
help='Number of rapid connect/disconnect clients (default: 10)'
|
||||
)
|
||||
|
||||
parser.add_argument(
|
||||
'--long-lived',
|
||||
type=int,
|
||||
default=2,
|
||||
help='Number of long-lived clients (default: 2)'
|
||||
)
|
||||
|
||||
parser.add_argument(
|
||||
'--iterations',
|
||||
type=int,
|
||||
default=50,
|
||||
help='Iterations per rapid client (default: 50)'
|
||||
)
|
||||
|
||||
parser.add_argument(
|
||||
'--duration',
|
||||
type=float,
|
||||
default=30.0,
|
||||
help='Test duration in seconds (default: 30.0)'
|
||||
)
|
||||
|
||||
parser.add_argument(
|
||||
'--device-type',
|
||||
default='iou-l3',
|
||||
choices=['iou-l3', 'vpcs', 'generic'],
|
||||
help='Device type for commands (default: iou-l3)'
|
||||
)
|
||||
|
||||
parser.add_argument(
|
||||
'--verbose',
|
||||
action='store_true',
|
||||
help='Enable verbose logging'
|
||||
)
|
||||
|
||||
args = parser.parse_args()
|
||||
|
||||
if args.verbose:
|
||||
logging.getLogger().setLevel(logging.DEBUG)
|
||||
|
||||
try:
|
||||
asyncio.run(run_stress_test(
|
||||
host=args.host,
|
||||
port=args.port,
|
||||
rapid_clients=args.rapid_clients,
|
||||
long_lived_clients=args.long_lived,
|
||||
iterations_per_client=args.iterations,
|
||||
test_duration=args.duration,
|
||||
device_type=args.device_type
|
||||
))
|
||||
except KeyboardInterrupt:
|
||||
log.info("Test interrupted by user")
|
||||
sys.exit(0)
|
||||
|
||||
|
||||
if __name__ == '__main__':
|
||||
main()
|
||||
Loading…
x
Reference in New Issue
Block a user