Heavy use of message-sending delaying receipt of incoming messages

SPADE version: 3.1.4
Python version: 3.7.4
Operating System: Mac OS Mojave
IM Server: prosody version 0.9.14

Description

Tried to apply basic send/receive comms examples to possible agents for sequential-step toy-game play. The execution of the game steps, and related "inform" behaviour execution, always seemed to take priority over receipt of incoming messages. Incoming messages would not start to be received while the steps were running.

What I Did

Code:

import concurrent.futures
import datetime
import random
import time

from spade import quit_spade
from spade.agent import Agent
from spade.behaviour import CyclicBehaviour, OneShotBehaviour
from spade.message import Message
from spade.template import Template

class InformativePlayerAgent(Agent):
    class InformBehav(OneShotBehaviour):
        def __init__(self, action):
            self.action = action
            super().__init__()

        async def run(self):
            nowtime = datetime.datetime.now().time()
            print(f"InformBehav running at {nowtime}")
            msg = Message(to=self.agent.buddy)
            msg.set_metadata("performative", "inform")
            msg.body = f"Hello from {self.agent.jid.localpart}, info from {nowtime}. Action: {self.action}"  # Set the message content

            await self.send(msg)
            print(f"DBG: SENT: {msg.body}")

    class RecvBehav(CyclicBehaviour):
        async def run(self):
            print("RecvBehav running")
            msg = await self.receive(timeout=600)
            if msg:
                nowtime = datetime.datetime.now().time()
                print(f"DBG: RECEIVED: by {self.agent.jid.localpart}: {msg.body}, at {nowtime}")
            else:
                print("DBG: Did not received any message after a timeout")

    def __init__(self, jid, password, buddy, verify_security=False):
        self.buddy = buddy
        super().__init__(jid, password, verify_security)

    async def setup(self):
        print(f"InformativePlayerAgent started at {datetime.datetime.now().time()}")
        b = self.RecvBehav()
        template = Template()
        template.set_metadata("performative", "inform")
        self.add_behaviour(b, template)
        print("Receive behaviour added.")

    def generate_move(self):
        my_action = random.randrange(2)
        b = self.InformBehav(my_action)
        self.add_behaviour(b)
        print("Inform behaviour added.")
        return my_action

if __name__ == "__main__":
    agent1 = InformativePlayerAgent("agent1@localhost", "fake-pwd", "agent2@localhost")
    agent2 = InformativePlayerAgent("agent2@localhost", "fake-pwd", "agent1@localhost")
    future1 = agent1.start()
    future2 = agent2.start()

    concurrent.futures.wait([future1, future2], return_when=concurrent.futures.ALL_COMPLETED)
    print("Agents started. Start firing off messages")
    # Mimicking toy-game-play steps in MAS experiment:
    for _ in range(100):
        agent1.generate_move()
        # time.sleep(0.005)
        agent2.generate_move()
        # time.sleep(0.005)

    print("DBG: SCENARIO COMPLETE........")

    for _ in range(30):
        try:
            time.sleep(1)
        except KeyboardInterrupt:
            break

    print("DBG: Quitting Spade........")\

    future_stop1 = agent1.stop()
    future_stop2 = agent2.stop()
    concurrent.futures.wait([future_stop1, future_stop2], return_when=concurrent.futures.ALL_COMPLETED)

    quit_spade() # shouldn't be needed, but agent.stop doesn't seem to be killing all threads (behaviours?).
    print("Agents finished")

Expected Output

Interleaved sending and receiving:

Inform behaviour added.
InformBehav running at 16:30:34.689014
DBG: SENT: Hello from agent2, info from 16:30:34.689014. Action: 1
Inform behaviour added.
InformBehav running at 16:30:34.714802
DBG: SENT: Hello from agent1, info from 16:30:34.714802. Action: 1
DBG: RECEIVED: by agent1: Hello from agent2, info from 16:30:34.689014. Action: 1, at 16:30:34.721157

Actual Output

Delayed receipt.

There seems to be no opportunity for the awaiting routine to get priority till steps are complete. This can be mitigated with a small delay to slow down the rate of InformBehav firing (see commented out sleep calls). But without, nothing is received till the steps complete:

...
InformBehav running at 16:34:12.275002
DBG: SENT: Hello from agent2, info from 16:34:12.275002. Action: 1
InformBehav running at 16:34:12.277587
DBG: SENT: Hello from agent1, info from 16:34:12.277587. Action: 0
InformBehav running at 16:34:12.280894
DBG: SENT: Hello from agent2, info from 16:34:12.280894. Action: 0
DBG: RECEIVED: by agent2: Hello from agent1, info from 16:34:11.443607. Action: 1, at 16:34:12.832015
DBG: RECEIVED: by agent1: Hello from agent2, info from 16:34:11.444462. Action: 0, at 16:34:12.861977
RecvBehav running
RecvBehav running
DBG: RECEIVED: by agent2: Hello from agent1, info from 16:34:11.445153. Action: 0, at 16:34:12.931661
DBG: RECEIVED: by agent1: Hello from agent2, info from 16:34:11.445794. Action: 1, at 16:34:12.931705
RecvBehav running
RecvBehav running
DBG: RECEIVED: by agent2: Hello from agent1, info from 16:34:11.448487. Action: 1, at 16:34:12.931805
DBG: RECEIVED: by agent1: Hello from agent2, info from 16:34:11.449333. Action: 1, at 16:34:12.931824
....

javipalanca / spade