Hi all,
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): 7e1c0e5b97e7aad0 smtp connected address=xxx.xxx.xxx.xxx host=xxx.xxx.xxx.hu 7e1c0e5b97e7aad0 smtp tls ciphers=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384:256 7e1c0e5b97e7aad0 smtp authentication user=user result=ok 7e1c0e5b97e7aad0 smtp failed-command command="DATA" result="550 5.7.1 Delivery not authorized, message refused: Message is not RFC 2822 compliant" 7e1c0e5b97e7aad0 smtp disconnected reason=disconnect When I issue an SMTP test on the printer admin page, this is what happens in smtpd: # smtpd -d -Tall smtp: 0xa146908b000: connected to listener 0xa14af58b000 [hostname=xxx.xxx.hu, 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: lka <- dispatcher: IMSG_GETNAMEINFO (len=28) imsg: control <- dispatcher: IMSG_STAT_INCREMENT (len=46) ramstat: increment: smtp.session ramstat: smtp.session (0x4d6fd5c7e11): 0 -> 1 imsg: control <- dispatcher: IMSG_STAT_INCREMENT (len=52) ramstat: increment: smtp.session.inet4 ramstat: smtp.session.inet4 (0x4d660bf63c1): 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: 0xa146908b000: STATE_NEW -> STATE_CONNECTED 1d1e5bc4223e33ab smtp connected address=xxx.xxx.xxx.xxx host=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: 0xa146908b000: IO_TLSREADY <io:0xa14d67bfd00 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=0 ob=0> 1d1e5bc4223e33ab smtp tls ciphers=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384:256 mproc: dispatcher -> control : 44 IMSG_STAT_INCREMENT smtp: 0xa146908b000: >>> 220 xxx.xxx.hu ESMTP OpenSMTPD imsg: control <- dispatcher: IMSG_STAT_INCREMENT (len=44) ramstat: increment: smtp.smtps ramstat: smtp.smtps (0x4d6b663d0f1): 0 -> 1 smtp: 0xa146908b000: IO_LOWAT <io:0xa14d67bfd00 fd=17 to=300000 fl=W tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=0 ob=0> smtp: 0xa146908b000: IO_DATAIN <io:0xa14d67bfd00 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=22 ob=0> smtp: 0xa146908b000: <<< EHLO SEC84251976C2A5 smtp: 0xa146908b000: STATE_CONNECTED -> STATE_HELO smtp: 0xa146908b000: >>> 250-xxx.xxx.hu Hello SEC84251976C2A5 [xxx.xxx.xxx.xxx], pleased to meet you smtp: 0xa146908b000: >>> 250-8BITMIME smtp: 0xa146908b000: >>> 250-ENHANCEDSTATUSCODES smtp: 0xa146908b000: >>> 250-SIZE 36700160 smtp: 0xa146908b000: >>> 250-DSN smtp: 0xa146908b000: >>> 250-AUTH PLAIN LOGIN smtp: 0xa146908b000: >>> 250 HELP smtp: 0xa146908b000: IO_LOWAT <io:0xa14d67bfd00 fd=17 to=300000 fl=W tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=0 ob=0> smtp: 0xa146908b000: IO_DATAIN <io:0xa14d67bfd00 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=12 ob=0> smtp: 0xa146908b000: <<< AUTH LOGIN smtp: 0xa146908b000: STATE_HELO -> STATE_AUTH_USERNAME smtp: 0xa146908b000: >>> 334 VXNlcm5hbWU6 smtp: 0xa146908b000: IO_LOWAT <io:0xa14d67bfd00 fd=17 to=300000 fl=W tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=0 ob=0> smtp: 0xa146908b000: IO_DATAIN <io:0xa14d67bfd00 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=22 ob=0> smtp: 0xa146908b000: <<< c2Ftc3VuZ19jNDgwZnc= smtp: 0xa146908b000: STATE_AUTH_USERNAME -> STATE_AUTH_PASSWORD smtp: 0xa146908b000: >>> 334 UGFzc3dvcmQ6 smtp: 0xa146908b000: IO_LOWAT <io:0xa14d67bfd00 fd=17 to=300000 fl=W tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=0 ob=0> smtp: 0xa146908b000: IO_DATAIN <io:0xa14d67bfd00 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=18 ob=0> smtp: 0xa146908b000: <<< ZGVLVHpndlB6ZTZ2 mproc: dispatcher -> lka : 55 IMSG_SMTP_AUTHENTICATE imsg: lka <- dispatcher: IMSG_SMTP_AUTHENTICATE (len=55) 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) 1d1e5bc4223e33ab smtp authentication user=user result=ok smtp: 0xa146908b000: >>> 235 2.0.0 Authentication succeeded smtp: 0xa146908b000: STATE_AUTH_PASSWORD -> STATE_HELO smtp: 0xa146908b000: IO_LOWAT <io:0xa14d67bfd00 fd=17 to=300000 fl=W tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=0 ob=0> smtp: 0xa146908b000: IO_DATAIN <io:0xa14d67bfd00 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=30 ob=0> smtp: 0xa146908b000: <<< 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 (b666cd59) mproc: queue -> dispatcher: realloc 0 -> 128 mproc: queue -> dispatcher : 16 IMSG_SMTP_MESSAGE_CREATE imsg: dispatcher <- queue: IMSG_SMTP_MESSAGE_CREATE (len=16) smtp: 0xa146908b000: >>> 250 2.0.0 Ok smtp: 0xa146908b000: IO_LOWAT <io:0xa14d67bfd00 fd=17 to=300000 fl=W tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=0 ob=0> smtp: 0xa146908b000: IO_DATAIN <io:0xa14d67bfd00 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=28 ob=0> smtp: 0xa146908b000: <<< rcpt to:<l...@ecentrum.hu> mproc: dispatcher -> lka: realloc 128 -> 512 mproc: dispatcher -> lka : 344 IMSG_SMTP_EXPAND_RCPT imsg: lka <- dispatcher: IMSG_SMTP_EXPAND_RCPT (len=344) expand: 0xf070299d018: expand_insert() called for address:l...@ecentrum.hu[parent=0x0, rule=0x0] expand: 0xf070299d018: inserted node 0xf078eadd560 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 : 386 IMSG_LKA_ENVELOPE_SUBMIT mproc: lka -> queue : 8 IMSG_LKA_ENVELOPE_COMMIT expand: 0xf070299d018: clearing expand tree imsg: queue <- lka: IMSG_LKA_ENVELOPE_SUBMIT (len=386) queue-backend: queue_envelope_create(b666cd5900000000, 377) -> 1 (b666cd59c76944b5) 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 : 387 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 (0x4d6f11a1181): 0 -> 1 imsg: scheduler <- queue: IMSG_QUEUE_ENVELOPE_SUBMIT (len=387) scheduler: inserting evp:b666cd59c76944b5 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 imsg: dispatcher <- queue: IMSG_QUEUE_ENVELOPE_SUBMIT (len=20) mproc: scheduler -> control : 61 IMSG_STAT_INCREMENT imsg: dispatcher <- queue: IMSG_QUEUE_ENVELOPE_COMMIT (len=12) smtp: 0xa146908b000: >>> 250 2.1.5 Destination address valid: Recipient ok imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=61) ramstat: increment: scheduler.envelope.incoming ramstat: scheduler.envelope.incoming (0x4d660bf6f81): 0 -> 1 imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=59) ramstat: increment: scheduler.ramqueue.update ramstat: scheduler.ramqueue.update (0x4d6f11a1881): 0 -> 1 imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=60) ramstat: increment: scheduler.ramqueue.message ramstat: scheduler.ramqueue.message (0x4d6b82acec1): 0 -> 1 imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=61) ramstat: increment: scheduler.ramqueue.envelope ramstat: scheduler.ramqueue.envelope (0x4d68e84fdc1): 0 -> 1 smtp: 0xa146908b000: IO_LOWAT <io:0xa14d67bfd00 fd=17 to=300000 fl=W tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=0 ob=0> smtp: 0xa146908b000: IO_DATAIN <io:0xa14d67bfd00 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=6 ob=0> smtp: 0xa146908b000: <<< 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: 0xa146908b000: >>> 354 Enter mail, end with "." on a line by itself smtp: 0xa146908b000: STATE_HELO -> STATE_BODY smtp: 0xa146908b000: IO_LOWAT <io:0xa14d67bfd00 fd=17 to=300000 fl=W tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=0 ob=0> smtp: 0xa146908b000: IO_DATAIN <io:0xa14d67bfd00 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=360 ob=0> <<< [MSG] From:"Device Administrator"<l...@ecentrum.hu> <<< [MSG] To: "Device Administrator"<l...@ecentrum.hu> <<< [MSG] Subject:=?utf-8?B?VGVzdCBNZXNzYWdl?= <<< [MSG] MIME-Version: 1.0 <<< [MSG] Content-Type: MULTIPART/MIXED; BOUNDARY="----=_NextPart_2948fd8e_345963ff_126832f6.29a9d5e8" <<< [MSG] Content-features: <<< [MSG] (& (dpi=100) (dpi-xyratio=[100/200])) <<< [MSG] <<< [MSG] ------=_NextPart_2948fd8e_345963ff_126832f6.29a9d5e8 smtp: 0xa146908b000: IO_DATAIN <io:0xa14d67bfd00 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: 0xa146908b000: IO_DATAIN <io:0xa14d67bfd00 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=17 ob=0> smtp: 0xa146908b000: IO_DATAIN <io:0xa14d67bfd00 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=75 ob=0> <<< [MSG] Test mail sending <<< [MSG] ------=_NextPart_2948fd8e_345963ff_126832f6.29a9d5e8-- smtp: 0xa146908b000: IO_DATAIN <io:0xa14d67bfd00 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=3 ob=0> <<< [MSG] . <<< [EOM] smtp: 0xa146908b000: >>> 550 5.7.1 Delivery not authorized, message refused: Message is not RFC 2822 compliant 1d1e5bc4223e33ab 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: 0xa146908b000: STATE_BODY -> STATE_HELO imsg: queue <- dispatcher: IMSG_SMTP_MESSAGE_ROLLBACK (len=4) smtp: 0xa146908b000: IO_LOWAT <io:0xa14d67bfd00 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(b666cd59) -> 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 (0x4d6f11a1941): 1 -> 0 imsg: scheduler <- queue: IMSG_QUEUE_MESSAGE_ROLLBACK (len=4) scheduler: aborting msg:b666cd59 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) scheduler: getting batch: mask=0x3f, count=10 ramstat: decrement: scheduler.ramqueue.message scheduler: got r=0, delay=-1, count=10 ramstat: scheduler.ramqueue.message (0x4d660bf6441): 1 -> 0 scheduler: sleeping imsg: control <- scheduler: IMSG_STAT_DECREMENT (len=61) ramstat: decrement: scheduler.ramqueue.envelope ramstat: scheduler.ramqueue.envelope (0x4d68e84fa41): 1 -> 0 imsg: control <- scheduler: IMSG_STAT_DECREMENT (len=59) ramstat: decrement: scheduler.ramqueue.update ramstat: scheduler.ramqueue.update (0x4d68e84f201): 1 -> 0 imsg: control <- scheduler: IMSG_STAT_DECREMENT (len=61) ramstat: decrement: scheduler.envelope.incoming ramstat: scheduler.envelope.incoming (0x4d660bf6ac1): 1 -> 0 smtp: 0xa146908b000: IO_DISCONNECTED <io:0xa14d67bfd00 fd=17 to=300000 fl=R tls=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 ib=0 ob=0> 1d1e5bc4223e33ab 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 (0x4d6702df9c1): 1 -> 0 imsg: control <- dispatcher: IMSG_STAT_DECREMENT (len=46) ramstat: decrement: smtp.session ramstat: smtp.session (0x4d740968f91): 1 -> 0 It's somewhere after DATA smtpd doesn't like what it's seeing. Can I somehow relax some checks in smtpd.conf to allow - a possible broken - SMTP implementation to work reliably? Thanks in advance, Daniel
