On Tuesday, April 16th, 2024 at 13:52, Philipp <phil...@bureaucracy.de> wrote: > > > Hi > > [2024-04-15 10:11] Lévai, Dániel l...@ecentrum.hu > > > I've been using this Samsung C480FW printer/scanner forever with OpenSMTPD > > and suddenly (no upgrades to OpenSMTPD or changes in the > > configuration) it started to complain (it's trying to send scanned > > documents via e-mail): > > > Has something on the scanner changed? Like a firmwareupdate or changed > settings. Something must have changed, when it has worked and now it > doesn't work anymore.
Yeah I know it's always suspicious when someone says "nothing changed" :) Really nothing changed on the smtpd server or the printer. The last successful scan was from the 12th of April and the next time I tried on the 15th it failed. Today, all of them succeeded again. I suspect it depends on the content of the message, somehow - as the only variable is the actual document I'm scanning. Idk, probably some weird characters, spacing or weird lines - I know, at this point it just sounds sorcery. Anyway, I was just wondering if there was an option to somehow relax some checks, but I can live with retrying until it succeeds. > > It's somewhere after DATA smtpd doesn't like what it's seeing. > > Actually I don't see why this message is not accepted. Only think I can > imagen is that the Content-features field is not properly folded. So that > the character used to indent is not WSP (space or horizontal tab). But > this is only a guess. I have the same suspicion (or let's call it feeling), but can't reproduce this willingly, unfortunately. > The attached patch adds a few more tracing information for the parser. Can > you apply this patch and try again? I've applied it to OpenBSD 7.4. The only thing I can reproduce this with reliably is the SMTP test function on the printer admin page - so this is not an actual scanned document e-mail that is sometimes failing: smtp: 0x59783b55000: connected to listener 0x598059cd000 [hostname=xxx, port=xxx, tag=INSECURE] mproc: dispatcher -> lka: realloc 0 -> 128 mproc: dispatcher -> lka : 28 IMSG_GETNAMEINFO mproc: dispatcher -> control: realloc 0 -> 128 mproc: dispatcher -> control : 46 IMSG_STAT_INCREMENT mproc: dispatcher -> control : 52 IMSG_STAT_INCREMENT imsg: control <- dispatcher: IMSG_STAT_INCREMENT (len=46) imsg: lka <- dispatcher: IMSG_GETNAMEINFO (len=28) ramstat: increment: smtp.session ramstat: smtp.session (0x8c602729211): 0 -> 1 imsg: control <- dispatcher: IMSG_STAT_INCREMENT (len=52) ramstat: increment: smtp.session.inet4 ramstat: smtp.session.inet4 (0x8c5a23055c1): 0 -> 1 mproc: lka -> dispatcher: realloc 0 -> 128 mproc: lka -> dispatcher : 49 IMSG_GETNAMEINFO imsg: dispatcher <- lka: IMSG_GETNAMEINFO (len=49) mproc: dispatcher -> lka : 51 IMSG_GETADDRINFO imsg: lka <- dispatcher: IMSG_GETADDRINFO (len=51) mproc: lka -> dispatcher : 41 IMSG_GETADDRINFO mproc: lka -> dispatcher : 8 IMSG_GETADDRINFO_END imsg: dispatcher <- lka: IMSG_GETADDRINFO (len=41) imsg: dispatcher <- lka: IMSG_GETADDRINFO_END (len=8) smtp: 0x59783b55000: STATE_NEW -> STATE_CONNECTED 6a2027eee3c2a5c4 smtp connected address=xxx.xxx.xxx.xxx host=xxx.xxx.xxx.xxx.hu mproc: dispatcher -> ca: realloc 0 -> 128 mproc: dispatcher -> ca: realloc 128 -> 256 mproc: dispatcher -> ca : 188 IMSG_CA_RSA_PRIVENC (flush) imsg: ca <- dispatcher: IMSG_CA_RSA_PRIVENC (len=188) mproc: ca -> dispatcher: realloc 0 -> 128 mproc: ca -> dispatcher: realloc 128 -> 1024 mproc: ca -> dispatcher : 532 IMSG_CA_RSA_PRIVENC imsg: dispatcher <- ca: IMSG_CA_RSA_PRIVENC (len=532) smtp: 0x59783b55000: IO_TLSREADY <io:0x59749197400 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=0 ob=0> 6a2027eee3c2a5c4 smtp tls ciphers=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384:256 mproc: dispatcher -> control : 44 IMSG_STAT_INCREMENT smtp: 0x59783b55000: >>> 220 xxx ESMTP OpenSMTPD imsg: control <- dispatcher: IMSG_STAT_INCREMENT (len=44) ramstat: increment: smtp.smtps ramstat: smtp.smtps (0x8c5879cd151): 0 -> 1 smtp: 0x59783b55000: IO_LOWAT <io:0x59749197400 fd=17 to=300000 fl=W tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=0 ob=0> smtp: 0x59783b55000: IO_DATAIN <io:0x59749197400 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=22 ob=0> smtp: 0x59783b55000: <<< EHLO SEC84251976C2A5 smtp: 0x59783b55000: STATE_CONNECTED -> STATE_HELO smtp: 0x59783b55000: >>> 250-xxx Hello SEC84251976C2A5 [xxx.xxx.xxx.xxx], pleased to meet you smtp: 0x59783b55000: >>> 250-8BITMIME smtp: 0x59783b55000: >>> 250-ENHANCEDSTATUSCODES smtp: 0x59783b55000: >>> 250-SIZE 36700160 smtp: 0x59783b55000: >>> 250-DSN smtp: 0x59783b55000: >>> 250-AUTH PLAIN LOGIN smtp: 0x59783b55000: >>> 250 HELP smtp: 0x59783b55000: IO_LOWAT <io:0x59749197400 fd=17 to=300000 fl=W tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=0 ob=0> smtp: 0x59783b55000: IO_DATAIN <io:0x59749197400 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=12 ob=0> smtp: 0x59783b55000: <<< AUTH LOGIN smtp: 0x59783b55000: STATE_HELO -> STATE_AUTH_USERNAME smtp: 0x59783b55000: >>> 334 XXX smtp: 0x59783b55000: IO_LOWAT <io:0x59749197400 fd=17 to=300000 fl=W tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=0 ob=0> smtp: 0x59783b55000: IO_DATAIN <io:0x59749197400 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=26 ob=0> smtp: 0x59783b55000: <<< XXX smtp: 0x59783b55000: STATE_AUTH_USERNAME -> STATE_AUTH_PASSWORD smtp: 0x59783b55000: >>> 334 XXX smtp: 0x59783b55000: IO_LOWAT <io:0x59749197400 fd=17 to=300000 fl=W tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=0 ob=0> smtp: 0x59783b55000: IO_DATAIN <io:0x59749197400 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=18 ob=0> smtp: 0x59783b55000: <<< XXX mproc: dispatcher -> lka : 57 IMSG_SMTP_AUTHENTICATE imsg: lka <- dispatcher: IMSG_SMTP_AUTHENTICATE (len=57) lookup: lookup "user" as CREDENTIALS in table proc:ecentrum.hu-sql -> "user:$2b$08$..." mproc: lka -> dispatcher : 12 IMSG_SMTP_AUTHENTICATE imsg: dispatcher <- lka: IMSG_SMTP_AUTHENTICATE (len=12) 6a2027eee3c2a5c4 smtp authentication user=user result=ok smtp: 0x59783b55000: >>> 235 2.0.0 Authentication succeeded smtp: 0x59783b55000: STATE_AUTH_PASSWORD -> STATE_HELO smtp: 0x59783b55000: IO_LOWAT <io:0x59749197400 fd=17 to=300000 fl=W tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=0 ob=0> smtp: 0x59783b55000: IO_DATAIN <io:0x59749197400 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=30 ob=0> smtp: 0x59783b55000: <<< mail from:<l...@ecentrum.hu> mproc: dispatcher -> queue: realloc 0 -> 128 mproc: dispatcher -> queue : 8 IMSG_SMTP_MESSAGE_CREATE imsg: queue <- dispatcher: IMSG_SMTP_MESSAGE_CREATE (len=8) queue-backend: queue_message_create() -> 1 (073d218f) mproc: queue -> dispatcher: realloc 0 -> 128 mproc: queue -> dispatcher : 16 IMSG_SMTP_MESSAGE_CREATE imsg: dispatcher <- queue: IMSG_SMTP_MESSAGE_CREATE (len=16) smtp: 0x59783b55000: >>> 250 2.0.0 Ok smtp: 0x59783b55000: IO_LOWAT <io:0x59749197400 fd=17 to=300000 fl=W tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=0 ob=0> smtp: 0x59783b55000: IO_DATAIN <io:0x59749197400 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=28 ob=0> smtp: 0x59783b55000: <<< rcpt to:<l...@ecentrum.hu> mproc: dispatcher -> lka: realloc 128 -> 512 mproc: dispatcher -> lka : 346 IMSG_SMTP_EXPAND_RCPT imsg: lka <- dispatcher: IMSG_SMTP_EXPAND_RCPT (len=346) expand: 0xba358d0c018: expand_insert() called for address:l...@ecentrum.hu[parent=0x0, rule=0x0] expand: 0xba358d0c018: inserted node 0xba3d4d96560 expand: lka_expand: address: l...@ecentrum.hu [depth=0] lookup: match "INSECURE" as STRING in table static:<dynamic:0> -> false lookup: match "xxx.xxx.xxx.xxx" as NETADDR in table static:<localhost> -> false lookup: match "INSECURE" as STRING in table static:<dynamic:2> -> true lookup: match "INSECURE" as STRING in table static:<dynamic:3> -> true lookup: match "xxx.xxx.xxx.xxx" as NETADDR in table static:<anyhost> -> true lookup: match "ecentrum.hu" as DOMAIN in table static:<anydestination> -> true lookup: match "l...@ecentrum.hu" as MAILADDR in table static:scanner_rcpts -> true rule #4 matched: match tag <dynamic:3> from any for any auth rcpt-to scanner_rcpts action sign_with_dkim mproc: lka -> queue: realloc 0 -> 128 mproc: lka -> queue: realloc 128 -> 512 mproc: lka -> queue : 388 IMSG_LKA_ENVELOPE_SUBMIT mproc: lka -> queue : 8 IMSG_LKA_ENVELOPE_COMMIT expand: 0xba358d0c018: clearing expand tree imsg: queue <- lka: IMSG_LKA_ENVELOPE_SUBMIT (len=388) queue-backend: queue_envelope_create(073d218f00000000, 379) -> 1 (073d218fcdae626e) mproc: queue -> control: realloc 0 -> 128 mproc: queue -> control : 53 IMSG_STAT_INCREMENT mproc: queue -> dispatcher : 20 IMSG_QUEUE_ENVELOPE_SUBMIT mproc: queue -> scheduler: realloc 0 -> 128 mproc: queue -> scheduler: realloc 128 -> 512 mproc: queue -> scheduler : 389 IMSG_QUEUE_ENVELOPE_SUBMIT imsg: queue <- lka: IMSG_LKA_ENVELOPE_COMMIT (len=8) mproc: queue -> dispatcher : 12 IMSG_QUEUE_ENVELOPE_COMMIT imsg: control <- queue: IMSG_STAT_INCREMENT (len=53) ramstat: increment: queue.evpcache.size ramstat: queue.evpcache.size (0x8c5a2305341): 0 -> 1 imsg: scheduler <- queue: IMSG_QUEUE_ENVELOPE_SUBMIT (len=389) imsg: dispatcher <- queue: IMSG_QUEUE_ENVELOPE_SUBMIT (len=20) imsg: dispatcher <- queue: IMSG_QUEUE_ENVELOPE_COMMIT (len=12) smtp: 0x59783b55000: >>> 250 2.1.5 Destination address valid: Recipient ok scheduler: inserting evp:073d218fcdae626e mproc: scheduler -> control: realloc 0 -> 128 mproc: scheduler -> control : 61 IMSG_STAT_INCREMENT mproc: scheduler -> control : 59 IMSG_STAT_INCREMENT mproc: scheduler -> control : 60 IMSG_STAT_INCREMENT mproc: scheduler -> control : 61 IMSG_STAT_INCREMENT imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=61) ramstat: increment: scheduler.envelope.incoming ramstat: scheduler.envelope.incoming (0x8c5a2305301): 0 -> 1 imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=59) ramstat: increment: scheduler.ramqueue.update ramstat: scheduler.ramqueue.update (0x8c597bbb9c1): 0 -> 1 imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=60) ramstat: increment: scheduler.ramqueue.message ramstat: scheduler.ramqueue.message (0x8c5d0fb2d01): 0 -> 1 imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=61) ramstat: increment: scheduler.ramqueue.envelope ramstat: scheduler.ramqueue.envelope (0x8c5d0fb2581): 0 -> 1 smtp: 0x59783b55000: IO_LOWAT <io:0x59749197400 fd=17 to=300000 fl=W tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=0 ob=0> smtp: 0x59783b55000: IO_DATAIN <io:0x59749197400 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=6 ob=0> smtp: 0x59783b55000: <<< DATA mproc: dispatcher -> queue : 12 IMSG_SMTP_MESSAGE_OPEN imsg: queue <- dispatcher: IMSG_SMTP_MESSAGE_OPEN (len=12) mproc: queue -> dispatcher : 12 IMSG_SMTP_MESSAGE_OPEN imsg: dispatcher <- queue: IMSG_SMTP_MESSAGE_OPEN (len=12, fd=18) smtp: 0x59783b55000: >>> 354 Enter mail, end with "." on a line by itself smtp: 0x59783b55000: STATE_HELO -> STATE_BODY smtp: 0x59783b55000: IO_LOWAT <io:0x59749197400 fd=17 to=300000 fl=W tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=0 ob=0> smtp: 0x59783b55000: IO_DATAIN <io:0x59749197400 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=358 ob=0> <<< [MSG] From:"Device Administrator"<l...@ecentrum.hu> rfc5322 state: RFC5322_HEADER_START rfc5322 state: RFC5322_NONE <<< [MSG] To: "Device Administrator"<l...@ecentrum.hu> rfc5322 state: <unknown> rfc5322 state: RFC5322_HEADER_START rfc5322 state: RFC5322_NONE <<< [MSG] Subject:=?utf-8?B?VGVzdCBNZXNzYWdl?= rfc5322 state: <unknown> rfc5322 state: RFC5322_HEADER_START rfc5322 state: RFC5322_NONE <<< [MSG] MIME-Version: 1.0 rfc5322 state: <unknown> rfc5322 state: RFC5322_HEADER_START rfc5322 state: RFC5322_NONE <<< [MSG] Content-Type: MULTIPART/MIXED; BOUNDARY="----=_NextPart_1156cb9_76831a23_73b5c8b9.65135af6" rfc5322 state: <unknown> rfc5322 state: RFC5322_HEADER_START rfc5322 state: RFC5322_NONE <<< [MSG] Content-features: rfc5322 state: <unknown> rfc5322 state: RFC5322_HEADER_START rfc5322 state: RFC5322_NONE <<< [MSG] (& (dpi=100) (dpi-xyratio=[100/200])) rfc5322 state: RFC5322_HEADER_CONT rfc5322 state: RFC5322_NONE <<< [MSG] rfc5322 state: RFC5322_HEADER_CONT rfc5322 state: RFC5322_NONE <<< [MSG] ------=_NextPart_1156cb9_76831a23_73b5c8b9.65135af6 rfc5322 state: <unknown> rfc5322 state: RFC5322_HEADER_END_OF_HEADERS rfc5322 parser: invalide BODY seperator rfc5322 state: RFC5322_ERR smtp: 0x59783b55000: IO_DATAIN <io:0x59749197400 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=46 ob=0> <<< [MSG] Content-Type: TEXT/PLAIN; charset=US-ASCII <<< [MSG] smtp: 0x59783b55000: IO_DATAIN <io:0x59749197400 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=17 ob=0> smtp: 0x59783b55000: IO_DATAIN <io:0x59749197400 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=74 ob=0> <<< [MSG] Test mail sending <<< [MSG] ------=_NextPart_1156cb9_76831a23_73b5c8b9.65135af6-- smtp: 0x59783b55000: IO_DATAIN <io:0x59749197400 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=3 ob=0> <<< [MSG] . <<< [EOM] smtp: 0x59783b55000: >>> 550 5.7.1 Delivery not authorized, message refused: Message is not RFC 2822 compliant 6a2027eee3c2a5c4 smtp failed-command command="DATA" result="550 5.7.1 Delivery not authorized, message refused: Message is not RFC 2822 compliant" mproc: dispatcher -> queue : 4 IMSG_SMTP_MESSAGE_ROLLBACK smtp: 0x59783b55000: STATE_BODY -> STATE_HELO imsg: queue <- dispatcher: IMSG_SMTP_MESSAGE_ROLLBACK (len=4) smtp: 0x59783b55000: IO_LOWAT <io:0x59749197400 fd=17 to=300000 fl=W tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=0 ob=0> mproc: queue -> control : 53 IMSG_STAT_DECREMENT queue-backend: queue_message_delete(073d218f) -> 1 mproc: queue -> scheduler : 4 IMSG_QUEUE_MESSAGE_ROLLBACK imsg: control <- queue: IMSG_STAT_DECREMENT (len=53) ramstat: decrement: queue.evpcache.size ramstat: queue.evpcache.size (0x8c5d0fb2f01): 1 -> 0 imsg: scheduler <- queue: IMSG_QUEUE_MESSAGE_ROLLBACK (len=4) scheduler: aborting msg:073d218f mproc: scheduler -> control : 60 IMSG_STAT_DECREMENT mproc: scheduler -> control : 61 IMSG_STAT_DECREMENT mproc: scheduler -> control : 59 IMSG_STAT_DECREMENT mproc: scheduler -> control : 61 IMSG_STAT_DECREMENT imsg: control <- scheduler: IMSG_STAT_DECREMENT (len=60) ramstat: decrement: scheduler.ramqueue.message ramstat: scheduler.ramqueue.message (0x8c599d8ed81): 1 -> 0 scheduler: getting batch: mask=0x3f, count=10 imsg: control <- scheduler: IMSG_STAT_DECREMENT (len=61) scheduler: got r=0, delay=-1, count=10 ramstat: decrement: scheduler.ramqueue.envelope scheduler: sleeping ramstat: scheduler.ramqueue.envelope (0x8c5d0fb2ec1): 1 -> 0 imsg: control <- scheduler: IMSG_STAT_DECREMENT (len=59) ramstat: decrement: scheduler.ramqueue.update ramstat: scheduler.ramqueue.update (0x8c599d8ea41): 1 -> 0 imsg: control <- scheduler: IMSG_STAT_DECREMENT (len=61) ramstat: decrement: scheduler.envelope.incoming ramstat: scheduler.envelope.incoming (0x8c5dd9dd441): 1 -> 0 smtp: 0x59783b55000: IO_DISCONNECTED <io:0x59749197400 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=0 ob=0> 6a2027eee3c2a5c4 smtp disconnected reason=disconnect mproc: dispatcher -> control : 44 IMSG_STAT_DECREMENT mproc: dispatcher -> control : 46 IMSG_STAT_DECREMENT imsg: control <- dispatcher: IMSG_STAT_DECREMENT (len=44) ramstat: decrement: smtp.smtps ramstat: smtp.smtps (0x8c602729361): 1 -> 0 imsg: control <- dispatcher: IMSG_STAT_DECREMENT (len=46) ramstat: decrement: smtp.session ramstat: smtp.session (0x8c602729d81): 1 -> 0 I just realized that I failed to remove the b64 encoded auth data from the previous trace :D Oh well, you live and learn. Daniel
