Debugging SimPy: Finding What's Wrong

def customer(env, cid, server):
    print(f"[{env.now:.2f}] Customer {cid} arrives")

    with server.request() as req:
        print(f"[{env.now:.2f}] Customer {cid} requests server")
        yield req
        print(f"[{env.now:.2f}] Customer {cid} gets server")

        service_time = random.expovariate(1/5)
        print(f"[{env.now:.2f}] Customer {cid} service time: {service_time:.2f}")
        yield env.timeout(service_time)

    print(f"[{env.now:.2f}] Customer {cid} leaves")

[0.00] Customer 0 arrives
[0.00] Customer 0 requests server
[0.00] Customer 0 gets server
[3.21] Customer 1 arrives
[3.21] Customer 1 requests server
[4.87] Customer 0 leaves
[4.87] Customer 1 gets server

import logging

logging.basicConfig(
    level=logging.DEBUG,
    format='%(asctime)s - %(levelname)s - %(message)s'
)
logger = logging.getLogger('simulation')

def customer(env, cid, server):
    logger.debug(f"[{env.now:.2f}] Customer {cid} arrives")

    with server.request() as req:
        logger.debug(f"[{env.now:.2f}] Customer {cid} queuing")
        yield req
        logger.info(f"[{env.now:.2f}] Customer {cid} served")
        yield env.timeout(5)

    logger.debug(f"[{env.now:.2f}] Customer {cid} complete")

# Show everything
logging.getLogger('simulation').setLevel(logging.DEBUG)

# Show important stuff only
logging.getLogger('simulation').setLevel(logging.INFO)

# Silence
logging.getLogger('simulation').setLevel(logging.WARNING)

class TracedEnvironment(simpy.Environment):
    def step(self):
        # Log next event before processing
        if self._queue:
            next_event = self._queue[0]
            print(f"[{self.now:.2f}] Processing event: {next_event}")

        super().step()

# Use instead of simpy.Environment()
env = TracedEnvironment()

def resource_monitor(env, resources, interval=10):
    """Periodically log resource states."""
    while True:
        print(f"\n=== Resource State at {env.now:.2f} ===")
        for name, resource in resources.items():
            print(f"  {name}:")
            print(f"    Capacity: {resource.capacity}")
            print(f"    In use: {resource.count}")
            print(f"    Queue length: {len(resource.queue)}")
            if hasattr(resource, 'queue') and resource.queue:
                for i, req in enumerate(resource.queue[:5]):
                    print(f"      Waiting[{i}]: {req}")
        yield env.timeout(interval)

# Start monitor
env.process(resource_monitor(env, {'server': server, 'checkout': checkout}))

class ProcessTracker:
    def __init__(self):
        self.active = {}
        self.completed = []

    def start(self, pid, name):
        self.active[pid] = {'name': name, 'start': None}

    def running(self, pid, time):
        if pid in self.active:
            self.active[pid]['start'] = time

    def complete(self, pid, time):
        if pid in self.active:
            info = self.active.pop(pid)
            info['end'] = time
            self.completed.append(info)

    def status(self):
        print(f"Active processes: {len(self.active)}")
        for pid, info in self.active.items():
            print(f"  {pid}: {info['name']} (started: {info['start']})")

tracker = ProcessTracker()

def customer(env, cid, server, tracker):
    tracker.start(cid, 'customer')

    with server.request() as req:
        yield req
        tracker.running(cid, env.now)
        yield env.timeout(5)

    tracker.complete(cid, env.now)

def customer(env, cid, server):
    with server.request() as req:
        yield req

        # Drop into debugger
        import pdb; pdb.set_trace()

        yield env.timeout(5)

(Pdb) env.now        # Current time
(Pdb) server.count   # Resources in use
(Pdb) len(server.queue)  # Queue length
(Pdb) c              # Continue

def customer(env, cid, server):
    arrival = env.now

    with server.request() as req:
        yield req
        wait = env.now - arrival

        # Debug long waits
        if wait > 50:
            print(f"DEBUG: Customer {cid} waited {wait:.2f}")
            print(f"  Queue length: {len(server.queue)}")
            print(f"  Server busy: {server.count}/{server.capacity}")
            import pdb; pdb.set_trace()

        yield env.timeout(5)

def state_snapshot(env, resources, stores, interval=100):
    """Capture full state periodically."""
    snapshots = []

    while True:
        snapshot = {
            'time': env.now,
            'resources': {},
            'stores': {}
        }

        for name, res in resources.items():
            snapshot['resources'][name] = {
                'count': res.count,
                'capacity': res.capacity,
                'queue_length': len(res.queue)
            }

        for name, store in stores.items():
            snapshot['stores'][name] = {
                'level': store.level if hasattr(store, 'level') else len(store.items),
                'capacity': store.capacity
            }

        snapshots.append(snapshot)
        yield env.timeout(interval)

    return snapshots

def customer(env, cid, server):
    arrival = env.now

    with server.request() as req:
        yield req
        wait = env.now - arrival

        # Sanity checks
        assert wait >= 0, f"Negative wait time: {wait}"
        assert server.count <= server.capacity, "Over capacity!"

        service = random.expovariate(1/5)
        assert service > 0, f"Invalid service time: {service}"

        yield env.timeout(service)

    # Check departure time makes sense
    assert env.now >= arrival, "Time went backwards!"

def inspect_queue(env, n=10):
    """Print next n pending events."""
    print(f"\nEvent queue at {env.now}:")

    for i, (time, priority, eid, event) in enumerate(env._queue[:n]):
        print(f"  {i}: time={time:.2f}, event={event}")

    if len(env._queue) > n:
        print(f"  ... and {len(env._queue) - n} more")

def test_customer_service():
    """Test customer process in isolation."""
    env = simpy.Environment()
    server = simpy.Resource(env, capacity=1)

    results = []

    def test_customer(env, server):
        arrival = env.now
        with server.request() as req:
            yield req
            yield env.timeout(5)
        results.append({
            'arrival': arrival,
            'departure': env.now,
            'wait': env.now - arrival - 5
        })

    # Single customer - should have no wait
    env.process(test_customer(env, server))
    env.run()

    assert len(results) == 1
    assert results[0]['wait'] == 0, "Expected no wait for single customer"
    print("Test passed!")

test_customer_service()

class Simulation:
    def __init__(self, env, debug=False):
        self.env = env
        self.debug = debug

    def log(self, message, level='DEBUG'):
        if self.debug:
            print(f"[{self.env.now:.2f}] {level}: {message}")

    def customer(self, cid, server):
        self.log(f"Customer {cid} arrives")

        with server.request() as req:
            yield req
            self.log(f"Customer {cid} starts service")
            yield self.env.timeout(5)

        self.log(f"Customer {cid} done")

# Normal run
sim = Simulation(env, debug=False)

# Debug run
sim = Simulation(env, debug=True)