Milter-MTA connection reset unexpectedly
raphaelm opened this issue · 1 comments
raphaelm commented
Hey, thanks so much for releasing this package! It makes it really easy to get started with a custom milter. I'm using purepythonmilter with Postfix 3.7.10-0+deb12u1. Whenever I send a response from my python script, postfix disconnects and purepythonmilter logs a warning. If I remove the return statement and just return nothing, no issue occurs. I've tested with 0.0.1 and the current git master.
Here's the minimal code exmaple I've reduced it to:
from __future__ import annotations
import logging
import os
import time
import purepythonmilter
from purepythonmilter import Continue, PurePythonMilter, RejectWithCode
from purepythonmilter.api import models
logger: logging.LoggerAdapter[logging.Logger]
async def on_mail_from(cmd: purepythonmilter.MailFrom) -> None:
return RejectWithCode(
primary_code=(5, 5, 3),
enhanced_code=(5, 7, 1),
text="Sample text"
)
from_alignment_milter = PurePythonMilter(
name="from-alignment",
hook_on_mail_from=on_mail_from,
)
logger = from_alignment_milter.logger
if __name__ == "__main__":
logging.basicConfig(level=logging.DEBUG)
from_alignment_milter.run_server(host="127.0.0.1", port="9098")
Here's the log from a sample run with one incoming email:
Feb 11 11:53:43 maildev python[63936]: DEBUG:asyncio:Using selector: EpollSelector
Feb 11 11:53:43 maildev python[63936]: INFO:purepythonmilter.server.milterserver:Purepythonmilter version 0.0.2.dev90+gaf4d329 starting...
Feb 11 11:53:43 maildev python[63936]: INFO:purepythonmilter.server.milterserver:Server started, awaiting connections on 127.0.0.1:9098...
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.milterserver:15821898: MTA connected. peername=('127.0.0.1', 40622) <StreamReader transport=<_SelectorSocketTransport fd=7 read=polling write=<idle, bufsize=0>>> <StreamWriter transport=<_SelectorSocketTransport fd=7 read=polling write=<idle, bufsize=0>> reader=<StreamReader transport=<_SelectorSocketTransport fd=7 read=polling write=<idle, bufsize=0>>>>
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: Starting commands_consumer task
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: going to read the queue last_macro_command=None
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: request to read 65540 bytes
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: got len(packet)=17 bytes [packet=b'\x00\x00\x00\rO\x00\x00\x00\x06\x00\x00\x01\xff\x00\x1f\xff\xff']
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: MTA sent packet claiming payload_length=13 byte(s).
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: claimed_payload_length=13 len(assembled_payload)=13 len(self._data_so_far)=0
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.payload:15821898: Got command <class 'purepythonmilter.protocol.commands.OptionsNegotiate'>
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: command_class=<class 'purepythonmilter.protocol.commands.OptionsNegotiate'> command_data=b'\x00\x00\x00\x06\x00\x00\x01\xff\x00\x1f\xff\xff'
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.commands:15821898: decoding options negotiate self.data_raw.hex()='00000006000001ff001fffff'
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.commands:15821898: MTA: milter_protocol_version=0x000006 action_flags=0x0001ff protocol_flags=0x1fffff
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.commands:15821898: self.flags=MtaSupportsProtocolFlags(disable_call_connect=True, disable_call_helo=True, disable_call_mail_from=True, disable_call_rcpt_to=True, disable_call_rcpt_to_rejected=True, disable_call_data=True, disable_call_headers=True, disable_call_end_of_headers=True, disable_call_body_chunk=True, disable_call_unknown=True, disable_reply_connect=True, disable_reply_helo=True, disable_reply_mail_from=True, disable_reply_rcpt_to=True, disable_reply_data=True, disable_reply_headers=True, disable_reply_end_of_headers=True, disable_reply_body_chunk=True, disable_reply_unknown=True, allows_change_mail_from=True, allows_add_headers=True, allows_change_headers=True, allows_change_body=True, allows_add_recipients=True, allows_add_recipients_with_esmtp_args=True, allows_remove_recipients=True, allows_quarantine=True, allows_specify_macros=True, allows_skip_body_chunks=True, headers_with_leading_space=True)
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: queue_command: command=OptionsNegotiate(data_raw=b'\x00\x00\x00\x06\x00\x00\x01\xff\x00\x1f\xff\xff', flags=MtaSupportsProtocolFlags(disable_call_connect=True, disable_call_helo=True, disable_call_mail_from=True, disable_call_rcpt_to=True, disable_call_rcpt_to_rejected=True, disable_call_data=True, disable_call_headers=True, disable_call_end_of_headers=True, disable_call_body_chunk=True, disable_call_unknown=True, disable_reply_connect=True, disable_reply_helo=True, disable_reply_mail_from=True, disable_reply_rcpt_to=True, disable_reply_data=True, disable_reply_headers=True, disable_reply_end_of_headers=True, disable_reply_body_chunk=True, disable_reply_unknown=True, allows_change_mail_from=True, allows_add_headers=True, allows_change_headers=True, allows_change_body=True, allows_add_recipients=True, allows_add_recipients_with_esmtp_args=True, allows_remove_recipients=True, allows_quarantine=True, allows_specify_macros=True, allows_skip_body_chunks=True, headers_with_leading_space=True))
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: incoming_command_queue size=1
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: No payload from packet (yet)
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: request to read 65540 bytes
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: got queue_item=QueueEntry(command=OptionsNegotiate(data_raw=b'\x00\x00\x00\x06\x00\x00\x01\xff\x00\x1f\xff\xff', flags=MtaSupportsProtocolFlags(disable_call_connect=True, disable_call_helo=True, disable_call_mail_from=True, disable_call_rcpt_to=True, disable_call_rcpt_to_rejected=True, disable_call_data=True, disable_call_headers=True, disable_call_end_of_headers=True, disable_call_body_chunk=True, disable_call_unknown=True, disable_reply_connect=True, disable_reply_helo=True, disable_reply_mail_from=True, disable_reply_rcpt_to=True, disable_reply_data=True, disable_reply_headers=True, disable_reply_end_of_headers=True, disable_reply_body_chunk=True, disable_reply_unknown=True, allows_change_mail_from=True, allows_add_headers=True, allows_change_headers=True, allows_change_body=True, allows_add_recipients=True, allows_add_recipients_with_esmtp_args=True, allows_remove_recipients=True, allows_quarantine=True, allows_specify_macros=True, allows_skip_body_chunks=True, headers_with_leading_space=True)), done_event=<asyncio.locks.Event object at 0x7fbf1fca4fd0 [unset]>)
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: on_options_negotiate
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: Encoded options negotiate response flags [version=self.protocol_version=0x000006 action=action_flags=0x000100 protocol=protocol_flags=0x0ff7fb]
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000000000000000000001 CONNECT True
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000000000000000000010 HELO True
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000000000000000000100 MAIL_FROM False
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000000000000000001000 RCPT_TO True
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000000000000000010000 BODY True
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000000000000000100000 HEADERS True
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000000000000001000000 END_OF_HEADERS True
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000000000000010000000 REPLY_HEADERS True
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000000000000100000000 UNKNOWN True
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000000000001000000000 DATA True
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000000000010000000000 SKIP True
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000000000100000000000 SEND_REJECTED_RCPT_TOS False
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000000001000000000000 REPLY_CONNECTION True
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000000010000000000000 REPLY_HELO True
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000000100000000000000 REPLY_MAIL_FROM True
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000001000000000000000 REPLY_RCPT_TO True
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000010000000000000000 REPLY_DATA True
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000100000000000000000 REPLY_UNKNOWN True
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000001000000000000000000 REPLY_END_OF_HEADERS True
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000010000000000000000000 REPLY_BODY_CHUNK True
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000100000000000000000000 HEADER_VALUE_LEADING_SPACE False
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000000000000000000001 ADD_HEADERS False
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000000000000000000010 CHANGE_BODY False
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000000000000000000100 ADD_RECIPIENTS False
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000000000000000001000 REMOVE_RECIPIENTS False
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000000000000000010000 CHANGE_HEADERS False
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000000000000000100000 QUARANTINE False
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000000000000001000000 CHANGE_ENVELOPE_FROM False
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000000000000010000000 ADD_RECIPIENT_ESMTP_ARGS False
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: 0b00000000000000000000000100000000 SET_MACROS_LIST True
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: <MacroStage.MAIL_FROM: 2> <None> (encoded as b'\x00\x00\x00\x02\x00')
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: <MacroStage.END_OF_MESSAGE: 5> <None> (encoded as b'\x00\x00\x00\x05\x00')
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: <MacroStage.CONNECT: 0> <None> (encoded as b'\x00\x00\x00\x00\x00')
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: <MacroStage.DATA: 4> <None> (encoded as b'\x00\x00\x00\x04\x00')
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: <MacroStage.RCPT_TO: 3> <None> (encoded as b'\x00\x00\x00\x03\x00')
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: <MacroStage.END_OF_HEADERS: 6> <None> (encoded as b'\x00\x00\x00\x06\x00')
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: <MacroStage.HELO: 1> <None> (encoded as b'\x00\x00\x00\x01\x00')
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.responses:15821898: symbols_bytes=b'\x00\x00\x00\x02\x00\x00\x00\x00\x05\x00\x00\x00\x00\x00\x00\x00\x00\x00\x04\x00\x00\x00\x00\x03\x00\x00\x00\x00\x06\x00\x00\x00\x00\x01\x00'
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: writing packet len=52 packet=b'\x00\x00\x000O\x00\x00\x00\x06\x00\x00\x01\x00\x00\x0f\xf7\xfb\x00\x00\x00\x02\x00\x00\x00\x00\x05\x00\x00\x00\x00\x00\x00\x00\x00\x00\x04\x00\x00\x00\x00\x03\x00\x00\x00\x00\x06\x00\x00\x00\x00\x01\x00'
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: Setting queue item done_event
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: going to read the queue last_macro_command=None
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: got len(packet)=446 bytes [packet=b'\x00\x00\x00KDCj\x00maildev.pretix.work\x00{daemon_name}\x00maildev.pretix.work\x00v\x00Postfix 3.7.10\x00\x00\x00\x00\x02DH\x00\x00\x00\x01A\x00\x00\x00JDH{tls_version}\x00TLSv1.3\x00{cipher}\x00TLS_AES_256_GCM_SHA384\x00{cipher_bits}\x00256\x00\x00\x00\x00\x94DM{auth_type}\x00LOGIN\x00{auth_authen}\x00test@maildev.pretix.work\x00{mail_addr}\x00test@maildev.pretix.work\x00{mail_host}\x00maildev.pretix.work\x00{mail_mailer}\x00local\x00\x00\x00\x00\x1cM<test@maildev.pretix.work>\x00\x00\x00\x00GDR{rcpt_addr}\x00blackhole@rami.io\x00{rcpt_host}\x00rami.io\x00{rcpt_mailer}\x00smtp\x00\x00\x00\x00\x0fDTi\x00E6FF541A5C\x00']
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: MTA sent packet claiming payload_length=75 byte(s).
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: claimed_payload_length=75 len(assembled_payload)=75 len(self._data_so_far)=367
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.payload:15821898: Got command <class 'purepythonmilter.protocol.commands.DefineMacro'>
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: command_class=<class 'purepythonmilter.protocol.commands.DefineMacro'> command_data=b'Cj\x00maildev.pretix.work\x00{daemon_name}\x00maildev.pretix.work\x00v\x00Postfix 3.7.10\x00'
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.commands:15821898: decoding DefineMacro self.data_raw.hex()='436a006d61696c6465762e7072657469782e776f726b007b6461656d6f6e5f6e616d657d006d61696c6465762e7072657469782e776f726b007600506f737466697820332e372e313000'
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.commands:15821898: Decoded macros: {'j': 'maildev.pretix.work', '{daemon_name}': 'maildev.pretix.work', 'v': 'Postfix 3.7.10'}
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: queue_command: command=DefineMacro(data_raw=b'Cj\x00maildev.pretix.work\x00{daemon_name}\x00maildev.pretix.work\x00v\x00Postfix 3.7.10\x00', stage=<MacroStage.CONNECT: 0>, macros={'j': 'maildev.pretix.work', '{daemon_name}': 'maildev.pretix.work', 'v': 'Postfix 3.7.10'})
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: incoming_command_queue size=1
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: MTA sent packet claiming payload_length=2 byte(s).
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: claimed_payload_length=2 len(assembled_payload)=2 len(self._data_so_far)=361
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.payload:15821898: Got command <class 'purepythonmilter.protocol.commands.DefineMacro'>
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: command_class=<class 'purepythonmilter.protocol.commands.DefineMacro'> command_data=b'H'
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.commands:15821898: decoding DefineMacro self.data_raw.hex()='48'
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.commands:15821898: No macros in DefineMacro for stage=<MacroStage.HELO: 1>
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: queue_command: command=DefineMacro(data_raw=b'H', stage=<MacroStage.HELO: 1>, macros={})
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: incoming_command_queue size=2
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: MTA sent packet claiming payload_length=1 byte(s).
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: claimed_payload_length=1 len(assembled_payload)=1 len(self._data_so_far)=356
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.payload:15821898: Got command <class 'purepythonmilter.protocol.commands.Abort'>
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: command_class=<class 'purepythonmilter.protocol.commands.Abort'> command_data=b''
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: queue_command: command=Abort(data_raw=b'')
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: incoming_command_queue size=3
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: MTA sent packet claiming payload_length=74 byte(s).
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: claimed_payload_length=74 len(assembled_payload)=74 len(self._data_so_far)=278
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.payload:15821898: Got command <class 'purepythonmilter.protocol.commands.DefineMacro'>
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: command_class=<class 'purepythonmilter.protocol.commands.DefineMacro'> command_data=b'H{tls_version}\x00TLSv1.3\x00{cipher}\x00TLS_AES_256_GCM_SHA384\x00{cipher_bits}\x00256\x00'
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.commands:15821898: decoding DefineMacro self.data_raw.hex()='487b746c735f76657273696f6e7d00544c5376312e33007b6369706865727d00544c535f4145535f3235365f47434d5f534841333834007b6369706865725f626974737d0032353600'
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.commands:15821898: Decoded macros: {'{tls_version}': 'TLSv1.3', '{cipher}': 'TLS_AES_256_GCM_SHA384', '{cipher_bits}': '256'}
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: queue_command: command=DefineMacro(data_raw=b'H{tls_version}\x00TLSv1.3\x00{cipher}\x00TLS_AES_256_GCM_SHA384\x00{cipher_bits}\x00256\x00', stage=<MacroStage.HELO: 1>, macros={'{tls_version}': 'TLSv1.3', '{cipher}': 'TLS_AES_256_GCM_SHA384', '{cipher_bits}': '256'})
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: incoming_command_queue size=4
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: MTA sent packet claiming payload_length=148 byte(s).
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: claimed_payload_length=148 len(assembled_payload)=148 len(self._data_so_far)=126
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.payload:15821898: Got command <class 'purepythonmilter.protocol.commands.DefineMacro'>
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: command_class=<class 'purepythonmilter.protocol.commands.DefineMacro'> command_data=b'M{auth_type}\x00LOGIN\x00{auth_authen}\x00test@maildev.pretix.work\x00{mail_addr}\x00test@maildev.pretix.work\x00{mail_host}\x00maildev.pretix.work\x00{mail_mailer}\x00local\x00'
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.commands:15821898: decoding DefineMacro self.data_raw.hex()='4d7b617574685f747970657d004c4f47494e007b617574685f61757468656e7d0074657374406d61696c6465762e7072657469782e776f726b007b6d61696c5f616464727d0074657374406d61696c6465762e7072657469782e776f726b007b6d61696c5f686f73747d006d61696c6465762e7072657469782e776f726b007b6d61696c5f6d61696c65727d006c6f63616c00'
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.commands:15821898: Decoded macros: {'{auth_type}': 'LOGIN', '{auth_authen}': 'test@maildev.pretix.work', '{mail_addr}': 'test@maildev.pretix.work', '{mail_host}': 'maildev.pretix.work', '{mail_mailer}': 'local'}
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: queue_command: command=DefineMacro(data_raw=b'M{auth_type}\x00LOGIN\x00{auth_authen}\x00test@maildev.pretix.work\x00{mail_addr}\x00test@maildev.pretix.work\x00{mail_host}\x00maildev.pretix.work\x00{mail_mailer}\x00local\x00', stage=<MacroStage.MAIL_FROM: 2>, macros={'{auth_type}': 'LOGIN', '{auth_authen}': 'test@maildev.pretix.work', '{mail_addr}': 'test@maildev.pretix.work', '{mail_host}': 'maildev.pretix.work', '{mail_mailer}': 'local'})
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: incoming_command_queue size=5
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: MTA sent packet claiming payload_length=28 byte(s).
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: claimed_payload_length=28 len(assembled_payload)=28 len(self._data_so_far)=94
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.payload:15821898: Got command <class 'purepythonmilter.protocol.commands.MailFrom'>
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: command_class=<class 'purepythonmilter.protocol.commands.MailFrom'> command_data=b'<test@maildev.pretix.work>\x00'
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: queue_command: command=MailFrom(data_raw=b'<test@maildev.pretix.work>\x00', address='test@maildev.pretix.work', esmtp_args={}, macros={})
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: incoming_command_queue size=6
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: MTA sent packet claiming payload_length=71 byte(s).
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: claimed_payload_length=71 len(assembled_payload)=71 len(self._data_so_far)=19
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.payload:15821898: Got command <class 'purepythonmilter.protocol.commands.DefineMacro'>
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: command_class=<class 'purepythonmilter.protocol.commands.DefineMacro'> command_data=b'R{rcpt_addr}\x00blackhole@rami.io\x00{rcpt_host}\x00rami.io\x00{rcpt_mailer}\x00smtp\x00'
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.commands:15821898: decoding DefineMacro self.data_raw.hex()='527b726370745f616464727d00626c61636b686f6c654072616d692e696f007b726370745f686f73747d0072616d692e696f007b726370745f6d61696c65727d00736d747000'
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.commands:15821898: Decoded macros: {'{rcpt_addr}': 'blackhole@rami.io', '{rcpt_host}': 'rami.io', '{rcpt_mailer}': 'smtp'}
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: queue_command: command=DefineMacro(data_raw=b'R{rcpt_addr}\x00blackhole@rami.io\x00{rcpt_host}\x00rami.io\x00{rcpt_mailer}\x00smtp\x00', stage=<MacroStage.RCPT_TO: 3>, macros={'{rcpt_addr}': 'blackhole@rami.io', '{rcpt_host}': 'rami.io', '{rcpt_mailer}': 'smtp'})
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: incoming_command_queue size=7
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: MTA sent packet claiming payload_length=15 byte(s).
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: claimed_payload_length=15 len(assembled_payload)=15 len(self._data_so_far)=0
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.payload:15821898: Got command <class 'purepythonmilter.protocol.commands.DefineMacro'>
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: command_class=<class 'purepythonmilter.protocol.commands.DefineMacro'> command_data=b'Ti\x00E6FF541A5C\x00'
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.commands:15821898: decoding DefineMacro self.data_raw.hex()='5469004536464635343141354300'
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.protocol.commands:15821898: Decoded macros: {'i': 'E6FF541A5C'}
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: queue_command: command=DefineMacro(data_raw=b'Ti\x00E6FF541A5C\x00', stage=<MacroStage.DATA: 4>, macros={'i': 'E6FF541A5C'})
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: incoming_command_queue size=8
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: No payload from packet (yet)
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: request to read 65540 bytes
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: got queue_item=QueueEntry(command=DefineMacro(data_raw=b'Cj\x00maildev.pretix.work\x00{daemon_name}\x00maildev.pretix.work\x00v\x00Postfix 3.7.10\x00', stage=<MacroStage.CONNECT: 0>, macros={'j': 'maildev.pretix.work', '{daemon_name}': 'maildev.pretix.work', 'v': 'Postfix 3.7.10'}), done_event=<asyncio.locks.Event object at 0x7fbf1fca4390 [unset]>)
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: on_define_macro command.macros={'j': 'maildev.pretix.work', '{daemon_name}': 'maildev.pretix.work', 'v': 'Postfix 3.7.10'}
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: Setting queue item done_event
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: going to read the queue last_macro_command=None
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: got queue_item=QueueEntry(command=DefineMacro(data_raw=b'H', stage=<MacroStage.HELO: 1>, macros={}), done_event=<asyncio.locks.Event object at 0x7fbf1fca5250 [unset]>)
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: on_define_macro command.macros={}
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: Setting queue item done_event
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: going to read the queue last_macro_command=None
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: got queue_item=QueueEntry(command=Abort(data_raw=b''), done_event=<asyncio.locks.Event object at 0x7fbf1fca5450 [unset]>)
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: handle_command_in_app command=Abort(data_raw=b'')
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: Setting queue item done_event
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: going to read the queue last_macro_command=None
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: got queue_item=QueueEntry(command=DefineMacro(data_raw=b'H{tls_version}\x00TLSv1.3\x00{cipher}\x00TLS_AES_256_GCM_SHA384\x00{cipher_bits}\x00256\x00', stage=<MacroStage.HELO: 1>, macros={'{tls_version}': 'TLSv1.3', '{cipher}': 'TLS_AES_256_GCM_SHA384', '{cipher_bits}': '256'}), done_event=<asyncio.locks.Event object at 0x7fbf1fca5650 [unset]>)
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: on_define_macro command.macros={'{tls_version}': 'TLSv1.3', '{cipher}': 'TLS_AES_256_GCM_SHA384', '{cipher_bits}': '256'}
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: Setting queue item done_event
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: going to read the queue last_macro_command=None
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: got queue_item=QueueEntry(command=DefineMacro(data_raw=b'M{auth_type}\x00LOGIN\x00{auth_authen}\x00test@maildev.pretix.work\x00{mail_addr}\x00test@maildev.pretix.work\x00{mail_host}\x00maildev.pretix.work\x00{mail_mailer}\x00local\x00', stage=<MacroStage.MAIL_FROM: 2>, macros={'{auth_type}': 'LOGIN', '{auth_authen}': 'test@maildev.pretix.work', '{mail_addr}': 'test@maildev.pretix.work', '{mail_host}': 'maildev.pretix.work', '{mail_mailer}': 'local'}), done_event=<asyncio.locks.Event object at 0x7fbf1fca5710 [unset]>)
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: on_define_macro command.macros={'{auth_type}': 'LOGIN', '{auth_authen}': 'test@maildev.pretix.work', '{mail_addr}': 'test@maildev.pretix.work', '{mail_host}': 'maildev.pretix.work', '{mail_mailer}': 'local'}
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: Setting queue item done_event
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: going to read the queue last_macro_command=None
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: got queue_item=QueueEntry(command=MailFrom(data_raw=b'<test@maildev.pretix.work>\x00', address='test@maildev.pretix.work', esmtp_args={}, macros={}), done_event=<asyncio.locks.Event object at 0x7fbf1fca5a90 [unset]>)
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: handle_command_in_app command=MailFrom(data_raw=b'<test@maildev.pretix.work>\x00', address='test@maildev.pretix.work', esmtp_args={}, macros={'{auth_type}': 'LOGIN', '{auth_authen}': 'test@maildev.pretix.work', '{mail_addr}': 'test@maildev.pretix.work', '{mail_host}': 'maildev.pretix.work', '{mail_mailer}': 'local'})
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: Adding 0 to current list of length 0
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: writing packet len=27 packet=b'\x00\x00\x00\x17y553 5.7.1 Sample text\x00'
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: Setting queue item done_event
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: going to read the queue last_macro_command=None
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: got queue_item=QueueEntry(command=DefineMacro(data_raw=b'R{rcpt_addr}\x00blackhole@rami.io\x00{rcpt_host}\x00rami.io\x00{rcpt_mailer}\x00smtp\x00', stage=<MacroStage.RCPT_TO: 3>, macros={'{rcpt_addr}': 'blackhole@rami.io', '{rcpt_host}': 'rami.io', '{rcpt_mailer}': 'smtp'}), done_event=<asyncio.locks.Event object at 0x7fbf1fca5cd0 [unset]>)
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: on_define_macro command.macros={'{rcpt_addr}': 'blackhole@rami.io', '{rcpt_host}': 'rami.io', '{rcpt_mailer}': 'smtp'}
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: Setting queue item done_event
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: going to read the queue last_macro_command=None
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: got queue_item=QueueEntry(command=DefineMacro(data_raw=b'Ti\x00E6FF541A5C\x00', stage=<MacroStage.DATA: 4>, macros={'i': 'E6FF541A5C'}), done_event=<asyncio.locks.Event object at 0x7fbf1fca5d90 [unset]>)
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: on_define_macro command.macros={'i': 'E6FF541A5C'}
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: Setting queue item done_event
Feb 11 11:53:47 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: going to read the queue last_macro_command=None
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: got len(packet)=24 bytes [packet=b'\x00\x00\x00\x0fDEi\x00E6FF541A5C\x00\x00\x00\x00\x01E']
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: MTA sent packet claiming payload_length=15 byte(s).
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: claimed_payload_length=15 len(assembled_payload)=15 len(self._data_so_far)=5
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.protocol.payload:15821898: Got command <class 'purepythonmilter.protocol.commands.DefineMacro'>
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: command_class=<class 'purepythonmilter.protocol.commands.DefineMacro'> command_data=b'Ei\x00E6FF541A5C\x00'
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.protocol.commands:15821898: decoding DefineMacro self.data_raw.hex()='4569004536464635343141354300'
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.protocol.commands:15821898: Decoded macros: {'i': 'E6FF541A5C'}
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: queue_command: command=DefineMacro(data_raw=b'Ei\x00E6FF541A5C\x00', stage=<MacroStage.END_OF_MESSAGE: 5>, macros={'i': 'E6FF541A5C'})
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: incoming_command_queue size=1
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: MTA sent packet claiming payload_length=1 byte(s).
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: claimed_payload_length=1 len(assembled_payload)=1 len(self._data_so_far)=0
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.protocol.payload:15821898: Got command <class 'purepythonmilter.protocol.commands.EndOfMessage'>
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: command_class=<class 'purepythonmilter.protocol.commands.EndOfMessage'> command_data=b''
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: queue_command: command=EndOfMessage(data_raw=b'', macros={})
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: incoming_command_queue size=2
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: No payload from packet (yet)
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: request to read 65540 bytes
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: got queue_item=QueueEntry(command=DefineMacro(data_raw=b'Ei\x00E6FF541A5C\x00', stage=<MacroStage.END_OF_MESSAGE: 5>, macros={'i': 'E6FF541A5C'}), done_event=<asyncio.locks.Event object at 0x7fbf1fca5990 [unset]>)
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: on_define_macro command.macros={'i': 'E6FF541A5C'}
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: Setting queue item done_event
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: going to read the queue last_macro_command=None
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: got queue_item=QueueEntry(command=EndOfMessage(data_raw=b'', macros={}), done_event=<asyncio.locks.Event object at 0x7fbf1fca5710 [unset]>)
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: handle_command_in_app command=EndOfMessage(data_raw=b'', macros={'i': 'E6FF541A5C'})
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: Adding 0 to current list of length 0
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: Sending 0 manipulations before end_of_message response.
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: writing packet len=5 packet=b'\x00\x00\x00\x01c'
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: Setting queue item done_event
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: going to read the queue last_macro_command=None
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: got len(packet)=15 bytes [packet=b'\x00\x00\x00\x01A\x00\x00\x00\x01A\x00\x00\x00\x01Q']
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: MTA sent packet claiming payload_length=1 byte(s).
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: claimed_payload_length=1 len(assembled_payload)=1 len(self._data_so_far)=10
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.protocol.payload:15821898: Got command <class 'purepythonmilter.protocol.commands.Abort'>
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: command_class=<class 'purepythonmilter.protocol.commands.Abort'> command_data=b''
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: queue_command: command=Abort(data_raw=b'')
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: incoming_command_queue size=1
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: MTA sent packet claiming payload_length=1 byte(s).
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: claimed_payload_length=1 len(assembled_payload)=1 len(self._data_so_far)=5
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.protocol.payload:15821898: Got command <class 'purepythonmilter.protocol.commands.Abort'>
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: command_class=<class 'purepythonmilter.protocol.commands.Abort'> command_data=b''
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: queue_command: command=Abort(data_raw=b'')
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: incoming_command_queue size=2
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: MTA sent packet claiming payload_length=1 byte(s).
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.protocol.packet:15821898: claimed_payload_length=1 len(assembled_payload)=1 len(self._data_so_far)=0
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.protocol.payload:15821898: Got command <class 'purepythonmilter.protocol.commands.Quit'>
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: command_class=<class 'purepythonmilter.protocol.commands.Quit'> command_data=b''
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: queue_command: command=Quit(data_raw=b'')
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: incoming_command_queue size=3
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: No payload from packet (yet)
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: request to read 65540 bytes
Feb 11 11:53:48 maildev python[63936]: ERROR:purepythonmilter.server.connectionhandler:15821898: Milter-MTA connection reset unexpectedly. This may indicate a protocol violation as observed from the MTA.
Feb 11 11:53:48 maildev python[63936]: Traceback (most recent call last):
Feb 11 11:53:48 maildev python[63936]: File "/var/mailfrommilter/venv/lib/python3.11/site-packages/purepythonmilter/server/connectionhandler.py", line 127, in keep_reading_packets
Feb 11 11:53:48 maildev python[63936]: packet: Packet = await self._reader.read(self.READER_CHUNK_SIZE)
Feb 11 11:53:48 maildev python[63936]: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Feb 11 11:53:48 maildev python[63936]: File "/usr/lib/python3.11/asyncio/streams.py", line 689, in read
Feb 11 11:53:48 maildev python[63936]: await self._wait_for_data('read')
Feb 11 11:53:48 maildev python[63936]: File "/usr/lib/python3.11/asyncio/streams.py", line 522, in _wait_for_data
Feb 11 11:53:48 maildev python[63936]: await self._waiter
Feb 11 11:53:48 maildev python[63936]: File "/usr/lib/python3.11/asyncio/selector_events.py", line 995, in _read_ready__data_received
Feb 11 11:53:48 maildev python[63936]: data = self._sock.recv(self.max_size)
Feb 11 11:53:48 maildev python[63936]: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Feb 11 11:53:48 maildev python[63936]: ConnectionResetError: [Errno 104] Connection reset by peer
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: close_bottom_up
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: close_bottom_up
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: _stop_commands_consumer [task=commands_consumer_task-15821898, exception=None, cancelled=False]
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: got queue_item=QueueEntry(command=Abort(data_raw=b''), done_event=<asyncio.locks.Event object at 0x7fbf1fca5310 [unset]>)
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: handle_command_in_app command=Abort(data_raw=b'')
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: Setting queue item done_event
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: going to read the queue last_macro_command=None
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: got queue_item=QueueEntry(command=Abort(data_raw=b''), done_event=<asyncio.locks.Event object at 0x7fbf1fca6190 [unset]>)
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: handle_command_in_app command=Abort(data_raw=b'')
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: Setting queue item done_event
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: going to read the queue last_macro_command=None
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: got queue_item=QueueEntry(command=Quit(data_raw=b''), done_event=<asyncio.locks.Event object at 0x7fbf1fca6250 [unset]>)
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: handle_command_in_app command=Quit(data_raw=b'')
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: Setting queue item done_event
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer: going to read the queue last_macro_command=None
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: commands_consumer task cancelled! read_queue_inner_task.cancelled()=True
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.session:15821898: task done! [task=commands_consumer_task-15821898, done=True, cancelled=False]
Feb 11 11:53:48 maildev python[63936]: DEBUG:from-alignment:15821898: on_mta_close_connection
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: close_top_down; going to cancel_reader_task=True
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: _cancel_reader_task: self._keep_reading_packets_task.done()=False self._keep_reading_packets_task.cancelled()=False exception=None
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: close_top_down; _cancel_reader_task done
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.milterserver:server_on_close_cb
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: writing EOF if self._writer.can_write_eof()=True
Feb 11 11:53:48 maildev python[63936]: ERROR:purepythonmilter.server.connectionhandler:15821898: Error closing client writer, ignoring.
Feb 11 11:53:48 maildev python[63936]: Traceback (most recent call last):
Feb 11 11:53:48 maildev python[63936]: File "/var/mailfrommilter/venv/lib/python3.11/site-packages/purepythonmilter/server/connectionhandler.py", line 188, in _close
Feb 11 11:53:48 maildev python[63936]: await self._writer.drain()
Feb 11 11:53:48 maildev python[63936]: File "/usr/lib/python3.11/asyncio/streams.py", line 366, in drain
Feb 11 11:53:48 maildev python[63936]: raise exc
Feb 11 11:53:48 maildev python[63936]: File "/var/mailfrommilter/venv/lib/python3.11/site-packages/purepythonmilter/server/connectionhandler.py", line 127, in keep_reading_packets
Feb 11 11:53:48 maildev python[63936]: packet: Packet = await self._reader.read(self.READER_CHUNK_SIZE)
Feb 11 11:53:48 maildev python[63936]: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Feb 11 11:53:48 maildev python[63936]: File "/usr/lib/python3.11/asyncio/streams.py", line 689, in read
Feb 11 11:53:48 maildev python[63936]: await self._wait_for_data('read')
Feb 11 11:53:48 maildev python[63936]: File "/usr/lib/python3.11/asyncio/streams.py", line 522, in _wait_for_data
Feb 11 11:53:48 maildev python[63936]: await self._waiter
Feb 11 11:53:48 maildev python[63936]: File "/usr/lib/python3.11/asyncio/selector_events.py", line 995, in _read_ready__data_received
Feb 11 11:53:48 maildev python[63936]: data = self._sock.recv(self.max_size)
Feb 11 11:53:48 maildev python[63936]: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Feb 11 11:53:48 maildev python[63936]: ConnectionResetError: [Errno 104] Connection reset by peer
Feb 11 11:53:48 maildev python[63936]: WARNING:purepythonmilter.server.connectionhandler:15821898: Reading packets task is done without reader at at_eof. reader=<StreamReader exception=ConnectionResetError(104, 'Connection reset by peer') transport=<_SelectorSocketTransport closed fd=7>>
Feb 11 11:53:48 maildev python[63936]: WARNING:purepythonmilter.server.connectionhandler:15821898: Reading packets task is done with reader exception=reader.exception=<bound method StreamReader.exception of <StreamReader exception=ConnectionResetError(104, 'Connection reset by peer') transport=<_SelectorSocketTransport closed fd=7>>>
Feb 11 11:53:48 maildev python[63936]: DEBUG:purepythonmilter.server.connectionhandler:15821898: DISCONNECTED reader=<StreamReader exception=ConnectionResetError(104, 'Connection reset by peer') transport=<_SelectorSocketTransport closed fd=7>> writer=<StreamWriter transport=<_SelectorSocketTransport closed fd=7> reader=<StreamReader exception=ConnectionResetError(104, 'Connection reset by peer') transport=<_SelectorSocketTransport closed fd=7>>>
It seems to still work, but the warning sounds concerning. Do you have any idea what might be going on?
raphaelm commented
I missed the docs part about the return type annotations being critical, sorry for the noise. Could maybe use a better error message (like a TypeError?) when it happens, though?