Skip to content

task.cancel() does not stop _commands_consumer, causing infinite loop and socket leak #22

Open
Open
task.cancel() does not stop _commands_consumer, causing infinite loop and socket leak#22
@marcraft2

Description

@marcraft2
marcraft2
opened on Jun 23, 2025

🐞 task.cancel() does not stop _commands_consumer — causes infinite timeout loop and socket leak

The _commands_consumer task is started as follows:
(Line 76: https://github.com/gertvdijk/purepythonmilter/blob/develop/src/purepythonmilter/server/session.py#L76)

self._commands_consumer_task = asyncio.create_task(
    self._commands_consumer(),
    name=f"commands_consumer_task-{self._socket_connection.id_.short}",
)

When the MTA closes the connection (Milter-MTA connection closed), _stop_commands_consumer() is called via close_bottom_up() and is expected to cancel() the _commands_consumer task:

Lines 220–232

async def _stop_commands_consumer(self) -> None:
    task = self._commands_consumer_task
    exception = task.exception() if task.done() else None
    self.logger.debug(
        f"_stop_commands_consumer [task={task.get_name()}, exception={exception}, "
        f"cancelled={task.cancelled()}]"
    )
    if not task.cancelled():
        task.cancel()
    try:
        await asyncio.wait_for(task, 0.1)
    except asyncio.TimeoutError:
        task.cancel()

🔁 The problem is that task.cancel() does not actually stop the infinite while True loop in _commands_consumer, which continues executing.

This results in an endless timeout loop, and the socket remains open:

Show Timeout Log 
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:00:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:01:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:01:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:01:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:01:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:02:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:02:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:02:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:02:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:03:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:03:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:03:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:03:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:04:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue

🧵 lsof reveals the socket stays in CLOSE_WAIT:

Milter:

root@server.milter:~# lsof -p 3620660 -a -i |grep '58844'
nilter  3620660 milter    8u  IPv4 3669937206      0t0  TCP server.milter:9800->server.mail:58844 (CLOSE_WAIT)

Postfix:

root@server.mail:~# lsof -i -nP | grep 9800 |grep '58844'
haproxy   3462664 haproxy  222u  IPv4    7714484      0t0  TCP 10.0.0.1:58844->10.0.0.2:9800 (FIN_WAIT2)

Shortly after Postfix closes the connection, but the milter keeps its socket open:

Milter:

root@server.milter:~# lsof -p 3620660 -a -i |grep '58844'
nilter  3620660 milter    8u  IPv4 3669937206      0t0  TCP server.milter:9800->server.mail:58844 (CLOSE_WAIT)

Postfix:

root@server.mail:~# lsof -i -nP | grep 9800 |grep '58844'
root@server.mail:~#

This seems to happen when another milter rejects the message before purepythonmilter has a chance to use the queue's Connect command.

This causes _commands_consumer to continue executing, and task.cancel() doesn't work as expected; the loop continues despite the task.cancel() call.

Show Debug Stack With Probleme 
root@server.milter:~# journalctl -u spamurai_milter --since "2025-06-22 21:50" | grep e208edf4
Jun 22 22:00:02 DEBUG:purepythonmilter.server.milterserver:e208edf4[1410568]: MTA connected. peername=('10.0.0.1', 58604) <StreamReader transport=<_SelectorSocketTransport fd=25 read=polling write=<idle, bufsize=0>>> <StreamWriter transport=<_SelectorSocketTransport fd=25 read=polling write=<idle, bufsize=0>> reader=<StreamReader transport=<_SelectorSocketTransport fd=25 read=polling write=<idle, bufsize=0>>>>
[...]
Jun 22 22:00:02 DEBUG:purepythonmilter.protocol.commands:e208edf4[1410568]: MTA: milter_protocol_version=0x000006 action_flags=0x0001ff protocol_flags=0x1fffff
[...]
Jun 22 22:00:02 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: Setting queue item done_event
Jun 22 22:00:02 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
[...]
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:e208edf4[1410568]: MTA sent packet claiming payload_length=198 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:e208edf4[1410568]: command_class=<class 'purepythonmilter.protocol.commands.DefineMacro'> command_data=b'Cj\x00server.mail\x00{daemon_name}\x00server.mail\x00{daemon_addr}\x00XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX\x00v\x00Postfix 3.7.11\x00_\x00server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]\x00'
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.commands:e208edf4[1410568]: decoding DefineMacro self.data_raw.hex()='436a00736d74702d332d313030302e6d61696c2e696e666f6d616e69616b2e6368007b6461656d6f6e5f6e616d657d00736d74702d332d313030302e6d61696c2e696e666f6d616e69616b2e6368007b6461656d6f6e5f616464727d00323030313a313630303a303a616161613a3a313a36007600506f737466697820332e372e3131005f006f642d3066373239362e696e666f6d616e69616b2e6368205b323030313a313630303a31333a3130323a663831363a336566663a666561323a316332615d00'
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.commands:e208edf4[1410568]: Decoded macros: {'j': 'server.mail', '{daemon_name}': 'server.mail', '{daemon_addr}': 'XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX', 'v': 'Postfix 3.7.11', '_': 'server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]'}
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: queue_command: command=DefineMacro(data_raw=b'Cj\x00server.mail\x00{daemon_name}\x00server.mail\x00{daemon_addr}\x00XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX\x00v\x00Postfix 3.7.11\x00_\x00server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]\x00', stage=<MacroStage.CONNECT: 0>, macros={'j': 'server.mail', '{daemon_name}': 'server.mail', '{daemon_addr}': 'XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX', 'v': 'Postfix 3.7.11', '_': 'server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]'})
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: incoming_command_queue size=1
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:e208edf4[1410568]: MTA sent packet claiming payload_length=65 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:e208edf4[1410568]: command_class=<class 'purepythonmilter.protocol.commands.Connect'> command_data=b'server.client\x006\xb1"XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX\x00'
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.commands:e208edf4[1410568]: Decoded socket data family_bin=b'6'
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: queue_command: command=Connect(data_raw=b'server.client\x006\xb1"XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX\x00', connection_info_args=ConnectionInfoArgsIPv6(hostname='server.client', addr=IPv6Address('XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX'), port=45346), macros={})
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: incoming_command_queue size=2
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:e208edf4[1410568]: MTA sent packet claiming payload_length=2 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:e208edf4[1410568]: command_class=<class 'purepythonmilter.protocol.commands.DefineMacro'> command_data=b'H'
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.commands:e208edf4[1410568]: decoding DefineMacro self.data_raw.hex()='48'
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.commands:e208edf4[1410568]: No macros in DefineMacro for stage=<MacroStage.HELO: 1>
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: queue_command: command=DefineMacro(data_raw=b'H', stage=<MacroStage.HELO: 1>, macros={})
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: incoming_command_queue size=3
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:e208edf4[1410568]: MTA sent packet claiming payload_length=11 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:e208edf4[1410568]: command_class=<class 'purepythonmilter.protocol.commands.Helo'> command_data=b'localhost\x00'
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: queue_command: command=Helo(data_raw=b'localhost\x00', hostname='localhost', macros={})
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: incoming_command_queue size=4
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:e208edf4[1410568]: MTA sent packet claiming payload_length=221 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:e208edf4[1410568]: command_class=<class 'purepythonmilter.protocol.commands.DefineMacro'> command_data=b'M_\x00server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]\x00{mail_addr}\x00user@server.client\x00{client_addr}\x00IPv6:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX\x00{client_name}\x00server.client\x00{dkim_sign}\x001\x00'
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.commands:e208edf4[1410568]: decoding DefineMacro self.data_raw.hex()='4d5f006f642d3066373239362e696e666f6d616e69616b2e6368205b323030313a313630303a31333a3130323a663831363a336566663a666561323a316332615d007b6d61696c5f616464727d00756964323734373730406f642d3066373239362e696e666f6d616e69616b2e6368007b636c69656e745f616464727d00495076363a323030313a313630303a31333a3130323a663831363a336566663a666561323a31633261007b636c69656e745f6e616d657d006f642d3066373239362e696e666f6d616e69616b2e6368007b646b696d5f7369676e7d003100'
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.commands:e208edf4[1410568]: Decoded macros: {'_': 'server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]', '{mail_addr}': 'user@server.client', '{client_addr}': 'IPv6:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX', '{client_name}': 'server.client', '{dkim_sign}': '1'}
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: queue_command: command=DefineMacro(data_raw=b'M_\x00server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]\x00{mail_addr}\x00user@server.client\x00{client_addr}\x00IPv6:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX\x00{client_name}\x00server.client\x00{dkim_sign}\x001\x00', stage=<MacroStage.MAIL_FROM: 2>, macros={'_': 'server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]', '{mail_addr}': 'user@server.client', '{client_addr}': 'IPv6:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX', '{client_name}': 'server.client', '{dkim_sign}': '1'})
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: incoming_command_queue size=5
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:e208edf4[1410568]: MTA sent packet claiming payload_length=37 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:e208edf4[1410568]: command_class=<class 'purepythonmilter.protocol.commands.MailFrom'> command_data=b'<user@server.client>\x00'
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: queue_command: command=MailFrom(data_raw=b'<user@server.client>\x00', address='user@server.client', esmtp_args={}, macros={})
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: incoming_command_queue size=6
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:e208edf4[1410568]: MTA sent packet claiming payload_length=100 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:e208edf4[1410568]: command_class=<class 'purepythonmilter.protocol.commands.DefineMacro'> command_data=b'R{rcpt_addr}\x00user@server.client\x00{rcpt_host}\x00server.client\x00{rcpt_mailer}\x00roundrobin2\x00'
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.commands:e208edf4[1410568]: decoding DefineMacro self.data_raw.hex()='527b726370745f616464727d00756964323734373730406d61696c2e696e666f6d616e69616b2e6368007b726370745f686f73747d006d61696c2e696e666f6d616e69616b2e6368007b726370745f6d61696c65727d00726f756e64726f62696e3200'
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.commands:e208edf4[1410568]: Decoded macros: {'{rcpt_addr}': 'user@server.client', '{rcpt_host}': 'server.client', '{rcpt_mailer}': 'roundrobin2'}
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: queue_command: command=DefineMacro(data_raw=b'R{rcpt_addr}\x00user@server.client\x00{rcpt_host}\x00server.client\x00{rcpt_mailer}\x00roundrobin2\x00', stage=<MacroStage.RCPT_TO: 3>, macros={'{rcpt_addr}': 'user@server.client', '{rcpt_host}': 'server.client', '{rcpt_mailer}': 'roundrobin2'})
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: incoming_command_queue size=7
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:e208edf4[1410568]: MTA sent packet claiming payload_length=13 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:e208edf4[1410568]: command_class=<class 'purepythonmilter.protocol.commands.RcptTo'> command_data=b'<user>\x00'
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: queue_command: command=RcptTo(data_raw=b'<user>\x00', address='user', esmtp_args={}, macros={})
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: incoming_command_queue size=8
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:e208edf4[1410568]: MTA sent packet claiming payload_length=19 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:e208edf4[1410568]: command_class=<class 'purepythonmilter.protocol.commands.DefineMacro'> command_data=b'Ti\x004bQMWQ6wT5z7fg\x00'
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.commands:e208edf4[1410568]: decoding DefineMacro self.data_raw.hex()='5469003462514d5751367754357a37666700'
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.commands:e208edf4[1410568]: Decoded macros: {'i': '4bQMWQ6wT5z7fg'}
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: queue_command: command=DefineMacro(data_raw=b'Ti\x004bQMWQ6wT5z7fg\x00', stage=<MacroStage.DATA: 4>, macros={'i': '4bQMWQ6wT5z7fg'})
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: incoming_command_queue size=9
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:e208edf4[1410568]: MTA sent packet claiming payload_length=1 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:e208edf4[1410568]: command_class=<class 'purepythonmilter.protocol.commands.Data'> command_data=b''
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: queue_command: command=Data(data_raw=b'', macros={})
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: incoming_command_queue size=10
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:e208edf4[1410568]: No payload from packet (yet)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:e208edf4[1410568]: request to read 65540 bytes
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: got queue_item=QueueEntry(command=DefineMacro(data_raw=b'Cj\x00server.mail\x00{daemon_name}\x00server.mail\x00{daemon_addr}\x00XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX\x00v\x00Postfix 3.7.11\x00_\x00server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]\x00', stage=<MacroStage.CONNECT: 0>, macros={'j': 'server.mail', '{daemon_name}': 'server.mail', '{daemon_addr}': 'XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX', 'v': 'Postfix 3.7.11', '_': 'server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]'}), done_event=<asyncio.locks.Event object at 0x7f50bb539e50 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: on_define_macro command.macros={'j': 'server.mail', '{daemon_name}': 'server.mail', '{daemon_addr}': 'XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX', 'v': 'Postfix 3.7.11', '_': 'server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]'}
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:e208edf4[1410568]: got len(packet)=15 bytes [packet=b'\x00\x00\x00\x01A\x00\x00\x00\x01A\x00\x00\x00\x01Q']
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:e208edf4[1410568]: MTA sent packet claiming payload_length=1 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:e208edf4[1410568]: command_class=<class 'purepythonmilter.protocol.commands.Abort'> command_data=b''
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: queue_command: command=Abort(data_raw=b'')
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: incoming_command_queue size=10
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:e208edf4[1410568]: MTA sent packet claiming payload_length=1 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:e208edf4[1410568]: command_class=<class 'purepythonmilter.protocol.commands.Abort'> command_data=b''
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: queue_command: command=Abort(data_raw=b'')
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: incoming_command_queue size=11
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:e208edf4[1410568]: MTA sent packet claiming payload_length=1 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:e208edf4[1410568]: command_class=<class 'purepythonmilter.protocol.commands.Quit'> command_data=b''
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: queue_command: command=Quit(data_raw=b'')
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: incoming_command_queue size=12
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:e208edf4[1410568]: No payload from packet (yet)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:e208edf4[1410568]: request to read 65540 bytes
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:e208edf4[1410568]: Milter-MTA connection closed
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:e208edf4[1410568]: close_bottom_up
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: close_bottom_up
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: _stop_commands_consumer [task=commands_consumer_task-e208edf4, exception=None, cancelled=False]
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: got queue_item=QueueEntry(command=Connect(data_raw=b'server.client\x006\xb1"XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX\x00', connection_info_args=ConnectionInfoArgsIPv6(hostname='server.client', addr=IPv6Address('XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX'), port=45346), macros={}), done_event=<asyncio.locks.Event object at 0x7f50bb53aa10 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: handle_command_in_app command=Connect(data_raw=b'server.client\x006\xb1"XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX\x00', connection_info_args=ConnectionInfoArgsIPv6(hostname='server.client', addr=IPv6Address('XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX'), port=45346), macros={'j': 'server.mail', '{daemon_name}': 'server.mail', '{daemon_addr}': 'XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX', 'v': 'Postfix 3.7.11', '_': 'server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]'})
Jun 22 22:00:03 INFO:milter:e208edf4[1410568]: new connection: client_addr=XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX, server_name=server.mail, server_addr=XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX, server_version='Postfix 3.7.11', source='server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]'
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: got queue_item=QueueEntry(command=DefineMacro(data_raw=b'H', stage=<MacroStage.HELO: 1>, macros={}), done_event=<asyncio.locks.Event object at 0x7f50bb538a50 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: on_define_macro command.macros={}
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: got queue_item=QueueEntry(command=Helo(data_raw=b'localhost\x00', hostname='localhost', macros={}), done_event=<asyncio.locks.Event object at 0x7f50bb5388d0 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: handle_command_in_app command=Helo(data_raw=b'localhost\x00', hostname='localhost', macros={})
Jun 22 22:00:03 INFO:milter:e208edf4[1410568]: helo=localhost
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: got queue_item=QueueEntry(command=DefineMacro(data_raw=b'M_\x00server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]\x00{mail_addr}\x00user@server.client\x00{client_addr}\x00IPv6:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX\x00{client_name}\x00server.client\x00{dkim_sign}\x001\x00', stage=<MacroStage.MAIL_FROM: 2>, macros={'_': 'server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]', '{mail_addr}': 'user@server.client', '{client_addr}': 'IPv6:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX', '{client_name}': 'server.client', '{dkim_sign}': '1'}), done_event=<asyncio.locks.Event object at 0x7f50bb53bb50 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: on_define_macro command.macros={'_': 'server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]', '{mail_addr}': 'user@server.client', '{client_addr}': 'IPv6:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX', '{client_name}': 'server.client', '{dkim_sign}': '1'}
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: got queue_item=QueueEntry(command=MailFrom(data_raw=b'<user@server.client>\x00', address='user@server.client', esmtp_args={}, macros={}), done_event=<asyncio.locks.Event object at 0x7f50bb5394d0 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: handle_command_in_app command=MailFrom(data_raw=b'<user@server.client>\x00', address='user@server.client', esmtp_args={}, macros={'_': 'server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]', '{mail_addr}': 'user@server.client', '{client_addr}': 'IPv6:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX', '{client_name}': 'server.client', '{dkim_sign}': '1'})
Jun 22 22:00:03 INFO:milter:e208edf4[1410568]: env_from=user@server.client
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: got queue_item=QueueEntry(command=DefineMacro(data_raw=b'R{rcpt_addr}\x00user@server.client\x00{rcpt_host}\x00server.client\x00{rcpt_mailer}\x00roundrobin2\x00', stage=<MacroStage.RCPT_TO: 3>, macros={'{rcpt_addr}': 'user@server.client', '{rcpt_host}': 'server.client', '{rcpt_mailer}': 'roundrobin2'}), done_event=<asyncio.locks.Event object at 0x7f50bb53b610 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: on_define_macro command.macros={'{rcpt_addr}': 'user@server.client', '{rcpt_host}': 'server.client', '{rcpt_mailer}': 'roundrobin2'}
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: got queue_item=QueueEntry(command=RcptTo(data_raw=b'<user>\x00', address='user', esmtp_args={}, macros={}), done_event=<asyncio.locks.Event object at 0x7f50bb538210 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: handle_command_in_app command=RcptTo(data_raw=b'<user>\x00', address='user', esmtp_args={}, macros={'{rcpt_addr}': 'user@server.client', '{rcpt_host}': 'server.client', '{rcpt_mailer}': 'roundrobin2'})
Jun 22 22:00:03 INFO:milter:e208edf4[1410568]: rcpt=user
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: got queue_item=QueueEntry(command=DefineMacro(data_raw=b'Ti\x004bQMWQ6wT5z7fg\x00', stage=<MacroStage.DATA: 4>, macros={'i': '4bQMWQ6wT5z7fg'}), done_event=<asyncio.locks.Event object at 0x7f50bb53b750 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: on_define_macro command.macros={'i': '4bQMWQ6wT5z7fg'}
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: got queue_item=QueueEntry(command=Data(data_raw=b'', macros={}), done_event=<asyncio.locks.Event object at 0x7f50bb53b390 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: handle_command_in_app command=Data(data_raw=b'', macros={'i': '4bQMWQ6wT5z7fg'})
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: got queue_item=QueueEntry(command=Abort(data_raw=b''), done_event=<asyncio.locks.Event object at 0x7f50bb55edd0 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: Reset Session
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: handle_command_in_app command=Abort(data_raw=b'')
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: got queue_item=QueueEntry(command=Abort(data_raw=b''), done_event=<asyncio.locks.Event object at 0x7f50bb55e3d0 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: Reset Session
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: handle_command_in_app command=Abort(data_raw=b'')
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: got queue_item=QueueEntry(command=Quit(data_raw=b''), done_event=<asyncio.locks.Event object at 0x7f50bb566c90 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: handle_command_in_app command=Quit(data_raw=b'')
Jun 22 22:00:03 INFO:milter:e208edf4[1410568]: connection closed
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:00:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:01:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:01:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:01:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:01:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:02:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:02:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:02:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:02:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:03:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:03:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:03:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:03:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:04:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:04:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:04:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:04:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:05:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:05:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:05:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:05:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:06:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:06:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:06:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:06:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:07:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:07:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:07:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:07:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:08:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:08:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:08:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:08:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:09:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:09:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:09:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:09:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:10:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:10:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:10:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:10:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:11:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:11:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:11:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:11:33 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:12:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: timeout reading the command queue
Jun 22 22:12:03 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer: going to read the queue last_macro_command=None
[...] 
After manual stop milter process: 

Jun 22 22:12:20 WARNING:purepythonmilter.server.connectionhandler:e208edf4[1410568]: Reading packets task is done without having writer closed. writer=<StreamWriter transport=<_SelectorSocketTransport fd=25 read=idle write=<idle, bufsize=0>> reader=<StreamReader eof transport=<_SelectorSocketTransport fd=25 read=idle write=<idle, bufsize=0>>>>
Jun 22 22:12:20 DEBUG:purepythonmilter.server.connectionhandler:e208edf4[1410568]: DISCONNECTED reader=<StreamReader eof transport=<_SelectorSocketTransport fd=25 read=idle write=<idle, bufsize=0>>> writer=<StreamWriter transport=<_SelectorSocketTransport fd=25 read=idle write=<idle, bufsize=0>> reader=<StreamReader eof transport=<_SelectorSocketTransport fd=25 read=idle write=<idle, bufsize=0>>>>
Jun 22 22:12:20 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: commands_consumer task cancelled! read_queue_inner_task.cancelled()=True
Jun 22 22:12:20 DEBUG:purepythonmilter.server.session:e208edf4[1410568]: task done! [task=commands_consumer_task-e208edf4, done=True, cancelled=False]
Show Debug Stack Without Problème 
Jun 22 22:00:03 DEBUG:purepythonmilter.server.milterserver:68299766[1410568]: MTA connected. peername=('10.0.0.1', 58820) <StreamReader transport=<_SelectorSocketTransport fd=44 read=polling write=<idle, bufsize=0>>> <StreamWriter transport=<_SelectorSocketTransport fd=44 read=polling write=<idle, bufsize=0>> reader=<StreamReader transport=<_SelectorSocketTransport fd=44 read=polling write=<idle, bufsize=0>>>>
[...]
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.commands:68299766[1410568]: MTA: milter_protocol_version=0x000006 action_flags=0x0001ff protocol_flags=0x1fffff
[...]
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: going to read the queue last_macro_command=None
[...]
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:68299766[1410568]: MTA sent packet claiming payload_length=195 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:68299766[1410568]: command_class=<class 'purepythonmilter.protocol.commands.DefineMacro'> command_data=b'Cj\x00server.mail\x00{daemon_name}\x00server.mail\x00{daemon_addr}\x00XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX\x00v\x00Postfix 3.7.11\x00_\x00server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]\x00'
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.commands:68299766[1410568]: decoding DefineMacro self.data_raw.hex()='436a00736d74702d332d313030302e6d61696c2e696e666f6d616e69616b2e6368007b6461656d6f6e5f6e616d657d00736d74702d332d313030302e6d61696c2e696e666f6d616e69616b2e6368007b6461656d6f6e5f616464727d00323030313a313630303a303a616161613a3a313a36007600506f737466697820332e372e3131005f006f642d6565383237642e696e666f6d616e69616b2e6368205b323030313a313630303a343a393a663831363a336566663a666565653a316562305d00'
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.commands:68299766[1410568]: Decoded macros: {'j': 'server.mail', '{daemon_name}': 'server.mail', '{daemon_addr}': 'XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX', 'v': 'Postfix 3.7.11', '_': 'server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]'}
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: queue_command: command=DefineMacro(data_raw=b'Cj\x00server.mail\x00{daemon_name}\x00server.mail\x00{daemon_addr}\x00XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX\x00v\x00Postfix 3.7.11\x00_\x00server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]\x00', stage=<MacroStage.CONNECT: 0>, macros={'j': 'server.mail', '{daemon_name}': 'server.mail', '{daemon_addr}': 'XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX', 'v': 'Postfix 3.7.11', '_': 'server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]'})
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: incoming_command_queue size=1
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:68299766[1410568]: MTA sent packet claiming payload_length=62 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:68299766[1410568]: command_class=<class 'purepythonmilter.protocol.commands.Connect'> command_data=b'server.client\x006\xa4&XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX\x00'
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.commands:68299766[1410568]: Decoded socket data family_bin=b'6'
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: queue_command: command=Connect(data_raw=b'server.client\x006\xa4&XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX\x00', connection_info_args=ConnectionInfoArgsIPv6(hostname='server.client', addr=IPv6Address('XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX'), port=42022), macros={})
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: incoming_command_queue size=2
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:68299766[1410568]: MTA sent packet claiming payload_length=2 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:68299766[1410568]: command_class=<class 'purepythonmilter.protocol.commands.DefineMacro'> command_data=b'H'
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.commands:68299766[1410568]: decoding DefineMacro self.data_raw.hex()='48'
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.commands:68299766[1410568]: No macros in DefineMacro for stage=<MacroStage.HELO: 1>
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: queue_command: command=DefineMacro(data_raw=b'H', stage=<MacroStage.HELO: 1>, macros={})
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: incoming_command_queue size=3
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:68299766[1410568]: MTA sent packet claiming payload_length=11 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:68299766[1410568]: command_class=<class 'purepythonmilter.protocol.commands.Helo'> command_data=b'localhost\x00'
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: queue_command: command=Helo(data_raw=b'localhost\x00', hostname='localhost', macros={})
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: incoming_command_queue size=4
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:68299766[1410568]: MTA sent packet claiming payload_length=214 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:68299766[1410568]: command_class=<class 'purepythonmilter.protocol.commands.DefineMacro'> command_data=b'M_\x00server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]\x00{mail_addr}\x00user@server.client\x00{client_addr}\x00IPv6:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX\x00{client_name}\x00server.client\x00{dkim_sign}\x001\x00'
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.commands:68299766[1410568]: decoding DefineMacro self.data_raw.hex()='4d5f006f642d6565383237642e696e666f6d616e69616b2e6368205b323030313a313630303a343a393a663831363a336566663a666565653a316562305d007b6d61696c5f616464727d007569643734343232406f642d6565383237642e696e666f6d616e69616b2e6368007b636c69656e745f616464727d00495076363a323030313a313630303a343a393a663831363a336566663a666565653a31656230007b636c69656e745f6e616d657d006f642d6565383237642e696e666f6d616e69616b2e6368007b646b696d5f7369676e7d003100'
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.commands:68299766[1410568]: Decoded macros: {'_': 'server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]', '{mail_addr}': 'user@server.client', '{client_addr}': 'IPv6:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX', '{client_name}': 'server.client', '{dkim_sign}': '1'}
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: queue_command: command=DefineMacro(data_raw=b'M_\x00server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]\x00{mail_addr}\x00user@server.client\x00{client_addr}\x00IPv6:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX\x00{client_name}\x00server.client\x00{dkim_sign}\x001\x00', stage=<MacroStage.MAIL_FROM: 2>, macros={'_': 'server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]', '{mail_addr}': 'user@server.client', '{client_addr}': 'IPv6:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX', '{client_name}': 'server.client', '{dkim_sign}': '1'})
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: incoming_command_queue size=5
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:68299766[1410568]: MTA sent packet claiming payload_length=36 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:68299766[1410568]: command_class=<class 'purepythonmilter.protocol.commands.MailFrom'> command_data=b'<user@server.client>\x00'
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: queue_command: command=MailFrom(data_raw=b'<user@server.client>\x00', address='user@server.client', esmtp_args={}, macros={})
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: incoming_command_queue size=6
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:68299766[1410568]: MTA sent packet claiming payload_length=99 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:68299766[1410568]: command_class=<class 'purepythonmilter.protocol.commands.DefineMacro'> command_data=b'R{rcpt_addr}\x00user@mail.infomaniak.ch\x00{rcpt_host}\x00mail.infomaniak.ch\x00{rcpt_mailer}\x00roundrobin7\x00'
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.commands:68299766[1410568]: decoding DefineMacro self.data_raw.hex()='527b726370745f616464727d007569643734343232406d61696c2e696e666f6d616e69616b2e6368007b726370745f686f73747d006d61696c2e696e666f6d616e69616b2e6368007b726370745f6d61696c65727d00726f756e64726f62696e3700'
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.commands:68299766[1410568]: Decoded macros: {'{rcpt_addr}': 'user@mail.infomaniak.ch', '{rcpt_host}': 'mail.infomaniak.ch', '{rcpt_mailer}': 'roundrobin7'}
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: queue_command: command=DefineMacro(data_raw=b'R{rcpt_addr}\x00user@mail.infomaniak.ch\x00{rcpt_host}\x00mail.infomaniak.ch\x00{rcpt_mailer}\x00roundrobin7\x00', stage=<MacroStage.RCPT_TO: 3>, macros={'{rcpt_addr}': 'user@mail.infomaniak.ch', '{rcpt_host}': 'mail.infomaniak.ch', '{rcpt_mailer}': 'roundrobin7'})
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: incoming_command_queue size=7
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:68299766[1410568]: MTA sent packet claiming payload_length=12 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:68299766[1410568]: command_class=<class 'purepythonmilter.protocol.commands.RcptTo'> command_data=b'<user>\x00'
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: queue_command: command=RcptTo(data_raw=b'<user>\x00', address='user', esmtp_args={}, macros={})
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: incoming_command_queue size=8
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:68299766[1410568]: MTA sent packet claiming payload_length=19 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:68299766[1410568]: command_class=<class 'purepythonmilter.protocol.commands.DefineMacro'> command_data=b'Ti\x004bQMWR3FkHz4tG\x00'
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.commands:68299766[1410568]: decoding DefineMacro self.data_raw.hex()='5469003462514d575233466b487a34744700'
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.commands:68299766[1410568]: Decoded macros: {'i': '4bQMWR3FkHz4tG'}
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: queue_command: command=DefineMacro(data_raw=b'Ti\x004bQMWR3FkHz4tG\x00', stage=<MacroStage.DATA: 4>, macros={'i': '4bQMWR3FkHz4tG'})
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: incoming_command_queue size=9
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:68299766[1410568]: MTA sent packet claiming payload_length=1 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:68299766[1410568]: command_class=<class 'purepythonmilter.protocol.commands.Data'> command_data=b''
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: queue_command: command=Data(data_raw=b'', macros={})
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: incoming_command_queue size=10
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:68299766[1410568]: No payload from packet (yet)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:68299766[1410568]: request to read 65540 bytes
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: got queue_item=QueueEntry(command=DefineMacro(data_raw=b'Cj\x00server.mail\x00{daemon_name}\x00server.mail\x00{daemon_addr}\x00XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX\x00v\x00Postfix 3.7.11\x00_\x00server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]\x00', stage=<MacroStage.CONNECT: 0>, macros={'j': 'server.mail', '{daemon_name}': 'server.mail', '{daemon_addr}': 'XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX', 'v': 'Postfix 3.7.11', '_': 'server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]'}), done_event=<asyncio.locks.Event object at 0x7f50bbe93b10 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: on_define_macro command.macros={'j': 'server.mail', '{daemon_name}': 'server.mail', '{daemon_addr}': 'XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX', 'v': 'Postfix 3.7.11', '_': 'server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]'}
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: got queue_item=QueueEntry(command=Connect(data_raw=b'server.client\x006\xa4&XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX\x00', connection_info_args=ConnectionInfoArgsIPv6(hostname='server.client', addr=IPv6Address('XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX'), port=42022), macros={}), done_event=<asyncio.locks.Event object at 0x7f50bbede0d0 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: handle_command_in_app command=Connect(data_raw=b'server.client\x006\xa4&XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX\x00', connection_info_args=ConnectionInfoArgsIPv6(hostname='server.client', addr=IPv6Address('XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX'), port=42022), macros={'j': 'server.mail', '{daemon_name}': 'server.mail', '{daemon_addr}': 'XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX', 'v': 'Postfix 3.7.11', '_': 'server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]'})
Jun 22 22:00:03 INFO:nilter:68299766[1410568]: new connection: client_addr=XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX, server_name=server.mail, server_addr=XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX, server_version='Postfix 3.7.11', source='server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]'
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: got queue_item=QueueEntry(command=DefineMacro(data_raw=b'H', stage=<MacroStage.HELO: 1>, macros={}), done_event=<asyncio.locks.Event object at 0x7f50bbede3d0 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: on_define_macro command.macros={}
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: got queue_item=QueueEntry(command=Helo(data_raw=b'localhost\x00', hostname='localhost', macros={}), done_event=<asyncio.locks.Event object at 0x7f50bbedc1d0 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: handle_command_in_app command=Helo(data_raw=b'localhost\x00', hostname='localhost', macros={})
Jun 22 22:00:03 INFO:nilter:68299766[1410568]: helo=localhost
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: got queue_item=QueueEntry(command=DefineMacro(data_raw=b'M_\x00server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]\x00{mail_addr}\x00user@server.client\x00{client_addr}\x00IPv6:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX\x00{client_name}\x00server.client\x00{dkim_sign}\x001\x00', stage=<MacroStage.MAIL_FROM: 2>, macros={'_': 'server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]', '{mail_addr}': 'user@server.client', '{client_addr}': 'IPv6:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX', '{client_name}': 'server.client', '{dkim_sign}': '1'}), done_event=<asyncio.locks.Event object at 0x7f50bbedd4d0 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: on_define_macro command.macros={'_': 'server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]', '{mail_addr}': 'user@server.client', '{client_addr}': 'IPv6:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX', '{client_name}': 'server.client', '{dkim_sign}': '1'}
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:68299766[1410568]: got len(packet)=15 bytes [packet=b'\x00\x00\x00\x01A\x00\x00\x00\x01A\x00\x00\x00\x01Q']
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:68299766[1410568]: MTA sent packet claiming payload_length=1 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.payload:68299766[1410568]: Got command <class 'purepythonmilter.protocol.commands.Abort'>
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:68299766[1410568]: command_class=<class 'purepythonmilter.protocol.commands.Abort'> command_data=b''
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: queue_command: command=Abort(data_raw=b'')
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: incoming_command_queue size=5
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:68299766[1410568]: MTA sent packet claiming payload_length=1 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.payload:68299766[1410568]: Got command <class 'purepythonmilter.protocol.commands.Abort'>
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:68299766[1410568]: command_class=<class 'purepythonmilter.protocol.commands.Abort'> command_data=b''
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: queue_command: command=Abort(data_raw=b'')
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: incoming_command_queue size=6
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.packet:68299766[1410568]: MTA sent packet claiming payload_length=1 byte(s).
Jun 22 22:00:03 DEBUG:purepythonmilter.protocol.payload:68299766[1410568]: Got command <class 'purepythonmilter.protocol.commands.Quit'>
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:68299766[1410568]: command_class=<class 'purepythonmilter.protocol.commands.Quit'> command_data=b''
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: queue_command: command=Quit(data_raw=b'')
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: incoming_command_queue size=7
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:68299766[1410568]: No payload from packet (yet)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:68299766[1410568]: request to read 65540 bytes
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:68299766[1410568]: Milter-MTA connection closed
Jun 22 22:00:03 DEBUG:purepythonmilter.server.connectionhandler:68299766[1410568]: close_bottom_up
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: close_bottom_up
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: _stop_commands_consumer [task=commands_consumer_task-68299766, exception=None, cancelled=False]
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: got queue_item=QueueEntry(command=MailFrom(data_raw=b'<user@server.client>\x00', address='user@server.client', esmtp_args={}, macros={}), done_event=<asyncio.locks.Event object at 0x7f50bbedc190 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: handle_command_in_app command=MailFrom(data_raw=b'<user@server.client>\x00', address='user@server.client', esmtp_args={}, macros={'_': 'server.client [XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX]', '{mail_addr}': 'user@server.client', '{client_addr}': 'IPv6:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX', '{client_name}': 'server.client', '{dkim_sign}': '1'})
Jun 22 22:00:03 INFO:nilter:68299766[1410568]: env_from=user@server.client
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: got queue_item=QueueEntry(command=DefineMacro(data_raw=b'R{rcpt_addr}\x00user@mail.infomaniak.ch\x00{rcpt_host}\x00mail.infomaniak.ch\x00{rcpt_mailer}\x00roundrobin7\x00', stage=<MacroStage.RCPT_TO: 3>, macros={'{rcpt_addr}': 'user@mail.infomaniak.ch', '{rcpt_host}': 'mail.infomaniak.ch', '{rcpt_mailer}': 'roundrobin7'}), done_event=<asyncio.locks.Event object at 0x7f50bbede9d0 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: on_define_macro command.macros={'{rcpt_addr}': 'user@mail.infomaniak.ch', '{rcpt_host}': 'mail.infomaniak.ch', '{rcpt_mailer}': 'roundrobin7'}
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: got queue_item=QueueEntry(command=RcptTo(data_raw=b'<user>\x00', address='user', esmtp_args={}, macros={}), done_event=<asyncio.locks.Event object at 0x7f50bbede210 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: handle_command_in_app command=RcptTo(data_raw=b'<user>\x00', address='user', esmtp_args={}, macros={'{rcpt_addr}': 'user@mail.infomaniak.ch', '{rcpt_host}': 'mail.infomaniak.ch', '{rcpt_mailer}': 'roundrobin7'})
Jun 22 22:00:03 INFO:nilter:68299766[1410568]: rcpt=user
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: got queue_item=QueueEntry(command=DefineMacro(data_raw=b'Ti\x004bQMWR3FkHz4tG\x00', stage=<MacroStage.DATA: 4>, macros={'i': '4bQMWR3FkHz4tG'}), done_event=<asyncio.locks.Event object at 0x7f50bbedfa10 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: on_define_macro command.macros={'i': '4bQMWR3FkHz4tG'}
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: got queue_item=QueueEntry(command=Data(data_raw=b'', macros={}), done_event=<asyncio.locks.Event object at 0x7f50bbedfa50 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: handle_command_in_app command=Data(data_raw=b'', macros={'i': '4bQMWR3FkHz4tG'})
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: got queue_item=QueueEntry(command=Abort(data_raw=b''), done_event=<asyncio.locks.Event object at 0x7f50bb506550 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: Reset Session
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: handle_command_in_app command=Abort(data_raw=b'')
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: got queue_item=QueueEntry(command=Abort(data_raw=b''), done_event=<asyncio.locks.Event object at 0x7f50bbdfef50 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: Reset Session
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: handle_command_in_app command=Abort(data_raw=b'')
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: going to read the queue last_macro_command=None
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: got queue_item=QueueEntry(command=Quit(data_raw=b''), done_event=<asyncio.locks.Event object at 0x7f50bbdfe150 [unset]>)
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: handle_command_in_app command=Quit(data_raw=b'')
Jun 22 22:00:03 INFO:nilter:68299766[1410568]: connection closed
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: Setting queue item done_event
Jun 22 22:00:03 DEBUG:purepythonmilter.server.session:68299766[1410568]: commands_consumer: going to read the queue last_macro_command=None

And server crashing when sockets limit was reached with Too many open files:

2025-06-22T08:20:02.300490+02:00 server.milter ERROR:asyncio:socket.accept() out of system resource#012socket: <asyncio.TransportSocket fd=7, family=2, type=1, proto=6, laddr=('0.0.0.0', 9800)>#012Traceback (most recent call last):#012  File "/usr/lib/python3.11/asyncio/selector_events.py", line 165, in _accept_connection#012    conn, addr = sock.accept()#012                 ^^^^^^^^^^^^^#012  File "/usr/lib/python3.11/socket.py", line 294, in accept#012OSError: [Errno 24] Too many open files

✅ Temporary workaround

In my fork, I fixed/bypass the issue by pushing a sentinel value (None) into the queue right before calling task.cancel():

self._incoming_command_queue.put_nowait(None)

This allows _commands_consumer to return and exit cleanly.

🧠 Suggestion

The best fix would be to understand why task.cancel() isn't actually stopping the consumer

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions