On Sun, May 11, 2014 at 02:25:24PM +0200, Reyk Floeter wrote: > On Sun, May 11, 2014 at 12:58:36PM +0300, Atanas Vladimirov wrote: > > On Sun, May 11, 2014 at 11:36:38AM +0200, Reyk Floeter wrote: > > > On Sun, May 11, 2014 at 02:05:43AM +0300, Atanas Vladimirov wrote: > > > > On Sat, May 10, 2014 at 11:52:01PM +0200, Reyk Floeter wrote: > > > > > On Sat, May 10, 2014 at 07:17:39PM +0300, [email protected] wrote: > > > > > > >Synopsis: OpenSMTPD failed with fatal: ssl_ctx_create: could not > > > > > > >fake private key: No such file or directory > > > > > > >Category: system > > > > > > >Environment: > > > > > > System : OpenBSD 5.5 > > > > > > Details : OpenBSD 5.5-current (GENERIC.MP) #100: Sat May 10 > > > > > > 02:42:31 MDT 2014 > > > > > > > > > > > > [email protected]:/usr/src/sys/arch/i386/compile/GENERIC.MP > > > > > > > > > > > > Architecture: OpenBSD.i386 > > > > > > Machine : i386 > > > > > > >Description: > > > > > > After upgrade to the latest snapshot OpenSMTPD failed with > > > > > > error - fatal: ssl_ctx_create: could not fake private key: No such > > > > > > file or directory > > > > > > > > > > > > > > > > Thanks for reporting, I just fixed it with smtpd/ssl.c 1.65. > > > > > > > > > > Reyk > > > > > > > > Thanks. I just applied smtpd/ssl.c 1.65 and now OpenSMTPD starts up > > > > normally but when I try to send a new email > > > > it closes with this output: > > > > > > > > ............. > > > > debug: smtp: new client on listener: 0x81942000 > > > > smtp-in: New session 7b84557cee266239 from host localhost [127.0.0.1] > > > > debug: lka: looking up pki "smtp.bsdbg.net" > > > > warn: parent -> lka: pipe closed > > > > warn: control -> lka: pipe closed > > > > warn: pony -> lka: pipe closed > > > > warn: scheduler -> control: pipe closed > > > > warn: queue -> lka: pipe closed > > > > warn: ca -> parent: pipe closed > > > > > > > > > > I cannot reproduce this one. > > > > > > Would share your smtpd.conf and instructions to trigger it? > > > > > > Reyk > > > > > > > I use mutt via ssh and roundcubemail with dovecot with the smtpd.conf from > > the bottom. > > When I comment out pki macros everything works as it should. > > > > OK, I can reproduce it now. It seems to be an older bug in the mta > that is just exposed by the SSL code. gilles@ and me are looking at > it. > > But you could try to send the logs by doing the following: > > # smtpd -dv -T mta -T imsg 2>&1 | tee smtpd.log
When I ran smtpd this way it worked fine. It didn't crash. See the log at the end. > > Do you have any malloc options enabled? Otherwise try with: > > # ln -sf 'S' /etc/malloc.conf I didn't have /etc/malloc.conf but I made the symbolic link. > > If you compile smtpd with debug symbols (make DEBUG=-g), we also have > a great way to get core dumps from privsep daemons now: > > # mkdir -m 0700 /var/crash/smtpd > # sysctl kern.nosuidcoredump=3 I compiled smtpd with debug symbols and enabled the core dumps. When I started smtpd from rc.d and tryed to send an email it crashed. You can download the core dump from http://bsdbg.net/~vlado/pub/8614.core > > You'll find the core dumps in /var/crash/smtpd/*.core where gdb gives > you a backtrace etc. > > Reyk > # smtpd -dv -T mta -T imsg 2>&1 | tee smtpd.log debug: init ssl-tree info: loading pki information for smtp.bsdbg.net info: OpenSMTPD 5.4.3 starting debug: bounce warning after 4h debug: using "fs" queue backend debug: using "ramqueue" scheduler backend debug: using "ram" stat backend info: startup [debug mode] debug: parent_send_config_ruleset: reloading debug: parent_send_config: configuring pony process debug: parent_send_config: configuring ca process imsg: lka <- parent: IMSG_CONF_START (len=0) debug: ca_engine_init: using RSA privsep engine debug: init ssl-tree info: loading pki keys for smtp.bsdbg.net imsg: lka <- parent: IMSG_CONF_END (len=0) imsg: pony <- parent: IMSG_CONF_START (len=0) imsg: pony <- parent: IMSG_CONF_END (len=0) debug: smtp: listen on 94.26.7.48 port 465 flags 0x4a pki "smtp.bsdbg.net" debug: smtp: listen on 192.168.1.1 port 465 flags 0x4a pki "smtp.bsdbg.net" debug: smtp: listen on 127.0.0.1 port 25 flags 0x9 pki "smtp.bsdbg.net" debug: smtp: listen on IPv6:fe80::1%lo0 port 25 flags 0x9 pki "smtp.bsdbg.net" debug: smtp: listen on IPv6:::1 port 25 flags 0x9 pki "smtp.bsdbg.net" debug: smtp: listen on 127.0.0.1 port 465 flags 0xa pki "smtp.bsdbg.net" debug: smtp: listen on IPv6:fe80::1%lo0 port 465 flags 0xa pki "smtp.bsdbg.net" debug: smtp: listen on IPv6:::1 port 465 flags 0xa pki "smtp.bsdbg.net" debug: pony: rsae_init debug: pony: rsae_init debug: smtp: will accept at most 498 clients imsg: ca <- parent: IMSG_CONF_START (len=0) imsg: ca <- parent: IMSG_CONF_START (len=0) imsg: ca <- parent: IMSG_CONF_END (len=0) imsg: ca <- parent: IMSG_CONF_END (len=0) debug: init private ssl-tree debug: queue: done loading queue into scheduler debug: smtpd: scanning offline queue... debug: smtpd: offline scanning done debug: smtp: new client on listener: 0x7b863000 imsg: lka <- pony: IMSG_SMTP_DNS_PTR (len=30) imsg: control <- pony: IMSG_STAT_INCREMENT (len=35) imsg: control <- pony: IMSG_STAT_INCREMENT (len=41) imsg: pony <- lka: IMSG_SMTP_DNS_PTR (len=25) smtp-in: New session d5741c1792b10b04 from host localhost [127.0.0.1] imsg: lka <- pony: IMSG_SMTP_SSL_INIT (len=264) debug: lka: looking up pki "smtp.bsdbg.net" imsg: pony <- lka: IMSG_SMTP_SSL_INIT (len=1973) debug: session_start_ssl: switching to SSL smtp-in: No PKI entry for requested SNI "localhost"on session d5741c1792b10b04 debug: pony: rsae_priv_enc imsg: ca <- pony: IMSG_CA_PRIVENC (len=123) imsg: ca <- pony: IMSG_CA_PRIVENC (len=123) imsg: pony <- ca: IMSG_CA_PRIVENC (len=531) smtp-in: Started TLS on session d5741c1792b10b04: version=TLSv1/SSLv3, cipher=ECDHE-RSA-AES256-GCM-SHA384, bits=256 imsg: control <- pony: IMSG_STAT_INCREMENT (len=33) imsg: lka <- pony: IMSG_SMTP_AUTHENTICATE (len=30) imsg: parent <- lka: IMSG_LKA_AUTHENTICATE (len=28) imsg: lka <- parent: IMSG_LKA_AUTHENTICATE (len=14) imsg: pony <- lka: IMSG_SMTP_AUTHENTICATE (len=14) smtp-in: Accepted authentication for user vlado on session d5741c1792b10b04 imsg: queue <- pony: IMSG_SMTP_MESSAGE_CREATE (len=9) imsg: pony <- queue: IMSG_SMTP_MESSAGE_CREATE (len=19) imsg: lka <- pony: IMSG_SMTP_EXPAND_RCPT (len=277) imsg: queue <- lka: IMSG_LKA_ENVELOPE_SUBMIT (len=354) imsg: queue <- lka: IMSG_LKA_ENVELOPE_COMMIT (len=9) imsg: control <- queue: IMSG_STAT_INCREMENT (len=42) imsg: scheduler <- queue: IMSG_QUEUE_ENVELOPE_SUBMIT (len=354) imsg: pony <- queue: IMSG_QUEUE_ENVELOPE_SUBMIT (len=23) imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=50) imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=48) imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=49) imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=50) imsg: pony <- queue: IMSG_QUEUE_ENVELOPE_COMMIT (len=14) imsg: queue <- pony: IMSG_SMTP_MESSAGE_OPEN (len=14) imsg: pony <- queue: IMSG_SMTP_MESSAGE_OPEN (len=14, fd=5) debug: 0x7891d000: end of message, msgflags=0x0000 imsg: queue <- pony: IMSG_SMTP_MESSAGE_COMMIT (len=14) imsg: scheduler <- queue: IMSG_QUEUE_MESSAGE_COMMIT (len=5) imsg: control <- scheduler: IMSG_STAT_DECREMENT (len=48) debug: scheduler: evp:479d5e87850c6021 scheduled (mta) imsg: queue <- scheduler: IMSG_SCHED_ENVELOPE_TRANSFER (len=9) imsg: pony <- queue: IMSG_SMTP_MESSAGE_COMMIT (len=14) smtp-in: Accepted message 479d5e87 on session d5741c1792b10b04: from=<[email protected]>, to=<[email protected]>, size=367, ndest=1, proto=ESMTP imsg: pony <- queue: IMSG_QUEUE_TRANSFER (len=363) imsg: control <- scheduler: IMSG_STAT_DECREMENT (len=50) debug: mta: received evp:479d5e87850c6021 for <[email protected]> debug: mta: draining [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] refcount=1, ntask=1, nconnector=0, nconn=0 debug: mta: querying MX for [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo]... debug: mta: [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] waiting for MX imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=41) imsg: control <- queue: IMSG_STAT_INCREMENT (len=46) imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=50) imsg: control <- pony: IMSG_STAT_INCREMENT (len=33) imsg: control <- pony: IMSG_STAT_INCREMENT (len=32) imsg: control <- pony: IMSG_STAT_INCREMENT (len=31) imsg: control <- pony: IMSG_STAT_INCREMENT (len=35) imsg: lka <- pony: IMSG_MTA_DNS_MX (len=20) imsg: pony <- lka: IMSG_MTA_DNS_HOST (len=35) imsg: pony <- lka: IMSG_MTA_DNS_HOST (len=47) imsg: control <- pony: IMSG_STAT_INCREMENT (len=31) imsg: control <- pony: IMSG_STAT_INCREMENT (len=31) imsg: pony <- lka: IMSG_MTA_DNS_HOST (len=35) imsg: pony <- lka: IMSG_MTA_DNS_HOST (len=47) imsg: control <- pony: IMSG_STAT_INCREMENT (len=31) imsg: control <- pony: IMSG_STAT_INCREMENT (len=31) imsg: pony <- lka: IMSG_MTA_DNS_HOST (len=35) imsg: pony <- lka: IMSG_MTA_DNS_HOST (len=47) imsg: control <- pony: IMSG_STAT_INCREMENT (len=31) imsg: control <- pony: IMSG_STAT_INCREMENT (len=31) imsg: pony <- lka: IMSG_MTA_DNS_HOST (len=35) imsg: pony <- lka: IMSG_MTA_DNS_HOST (len=47) imsg: pony <- lka: IMSG_MTA_DNS_HOST (len=35) imsg: pony <- lka: IMSG_MTA_DNS_HOST (len=47) imsg: pony <- lka: IMSG_MTA_DNS_HOST_END (len=14) debug: MXs for domain gmail.com: 74.125.136.27 preference 5 IPv6:2a00:1450:4013:c01::1a preference 5 74.125.25.27 preference 10 IPv6:2607:f8b0:400e:c03::1b preference 10 173.194.64.27 preference 20 IPv6:2607:f8b0:4003:c02::1a preference 20 74.125.193.27 preference 30 IPv6:2607:f8b0:4001:c05::1a preference 30 74.125.196.27 preference 40 IPv6:2607:f8b0:4002:c07::1a preference 40 debug: mta: ... got mx (0x823b9290, gmail.com, [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo]) debug: mta: draining [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] refcount=1, ntask=1, nconnector=0, nconn=0 debug: mta: querying source for [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo]... imsg: control <- pony: IMSG_STAT_INCREMENT (len=31) imsg: control <- pony: IMSG_STAT_INCREMENT (len=31) imsg: control <- pony: IMSG_STAT_INCREMENT (len=31) imsg: control <- pony: IMSG_STAT_INCREMENT (len=31) imsg: lka <- pony: IMSG_MTA_LOOKUP_SOURCE (len=18) imsg: pony <- lka: IMSG_MTA_LOOKUP_SOURCE (len=35) debug: mta: ... got source for [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo]: 94.26.7.48 debug: mta: new [connector:94.26.7.48->[relay:gmail.com,sourcetable=myaddrs,helotable=myhelo],0x10000] debug: mta: connecting with [connector:94.26.7.48->[relay:gmail.com,sourcetable=myaddrs,helotable=myhelo],0x0] debug: mta-routing: searching new route for [connector:94.26.7.48->[relay:gmail.com,sourcetable=myaddrs,helotable=myhelo],0x0]... debug: mta-routing: selecting candidate route 94.26.7.48 <-> 74.125.136.27 debug: mta-routing: skipping host IPv6:2a00:1450:4013:c01::1a: AF mismatch debug: mta-routing: spawning new connection on 94.26.7.48 <-> 74.125.136.27 debug: mta: 0x7df4bc00: spawned for relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] debug: mta: connecting with [connector:94.26.7.48->[relay:gmail.com,sourcetable=myaddrs,helotable=myhelo],0x0] debug: mta: cannot use [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] before 2s debug: mta-routing: no route available for [connector:94.26.7.48->[relay:gmail.com,sourcetable=myaddrs,helotable=myhelo],0x0]: must wait a bit debug: mta: retrying to connect on [connector:94.26.7.48->[relay:gmail.com,sourcetable=myaddrs,helotable=myhelo],0x0] in 2s... debug: mta: draining [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] refcount=2, ntask=1, nconnector=1, nconn=1 debug: mta: scheduling relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] in 1s... imsg: control <- pony: IMSG_STAT_INCREMENT (len=33) imsg: control <- pony: IMSG_STAT_INCREMENT (len=36) imsg: control <- pony: IMSG_STAT_INCREMENT (len=32) imsg: control <- pony: IMSG_STAT_INCREMENT (len=34) imsg: lka <- pony: IMSG_MTA_DNS_PTR (len=30) imsg: pony <- lka: IMSG_MTA_DNS_PTR (len=35) imsg: lka <- pony: IMSG_MTA_LOOKUP_HELO (len=38) debug: lka: helo myhelo:94.26.7.48 imsg: pony <- lka: IMSG_MTA_LOOKUP_HELO (len=30) smtp-out: Connecting to smtp+tls://74.125.136.27:25 (ea-in-f27.1e100.net) on session d5741c1a0f9d07f3... mta: 0x7df4bc00: MTA_INIT -> MTA_INIT smtp-out: Connected on session d5741c1a0f9d07f3 mta: 0x7df4bc00: MTA_INIT -> MTA_BANNER mta: 0x7df4bc00: <<< 220 mx.google.com ESMTP 44si8229893eef.40 - gsmtp mta: 0x7df4bc00: MTA_BANNER -> MTA_EHLO mta: 0x7df4bc00: >>> EHLO smtp.bsdbg.net smtp-in: Closing session d5741c1792b10b04 debug: smtp: 0x7891d000: deleting session: done imsg: control <- pony: IMSG_STAT_DECREMENT (len=33) imsg: control <- pony: IMSG_STAT_DECREMENT (len=35) mta: 0x7df4bc00: <<< 250-mx.google.com at your service, [94.26.7.48] mta: 0x7df4bc00: <<< 250-SIZE 35882577 mta: 0x7df4bc00: <<< 250-8BITMIME mta: 0x7df4bc00: <<< 250-STARTTLS mta: 0x7df4bc00: <<< 250-ENHANCEDSTATUSCODES mta: 0x7df4bc00: <<< 250 CHUNKING mta: 0x7df4bc00: MTA_EHLO -> MTA_STARTTLS mta: 0x7df4bc00: >>> STARTTLS mta: 0x7df4bc00: <<< 220 2.0.0 Ready to start TLS imsg: lka <- pony: IMSG_MTA_SSL_INIT (len=264) debug: lka: looking up pki "smtp.bsdbg.net" imsg: pony <- lka: IMSG_MTA_SSL_INIT (len=1973) debug: pony: rsae_init debug: pony: rsae_init debug: pony: rsae_init debug: pony: rsae_pub_dec debug: pony: rsae_bn_mod_exp smtp-out: Started TLS on session d5741c1a0f9d07f3: version=TLSv1/SSLv3, cipher=ECDHE-RSA-AES128-GCM-SHA256, bits=128 imsg: lka <- pony: IMSG_MTA_SSL_VERIFY_CERT (len=1964) imsg: lka <- pony: IMSG_MTA_SSL_VERIFY_CHAIN (len=1964) imsg: lka <- pony: IMSG_MTA_SSL_VERIFY_CHAIN (len=1324) imsg: lka <- pony: IMSG_MTA_SSL_VERIFY_CHAIN (len=1189) imsg: lka <- pony: IMSG_MTA_SSL_VERIFY (len=292) imsg: pony <- lka: IMSG_MTA_SSL_VERIFY (len=12) smtp-out: Server certificate verification succeeded on session d5741c1a0f9d07f3 mta: 0x7df4bc00: MTA_STARTTLS -> MTA_EHLO mta: 0x7df4bc00: >>> EHLO smtp.bsdbg.net mta: 0x7df4bc00: <<< 250-mx.google.com at your service, [94.26.7.48] mta: 0x7df4bc00: <<< 250-SIZE 35882577 mta: 0x7df4bc00: <<< 250-8BITMIME mta: 0x7df4bc00: <<< 250-ENHANCEDSTATUSCODES mta: 0x7df4bc00: <<< 250 CHUNKING mta: 0x7df4bc00: MTA_EHLO -> MTA_STARTTLS mta: 0x7df4bc00: MTA_STARTTLS -> MTA_AUTH mta: 0x7df4bc00: MTA_AUTH -> MTA_READY debug: mta-routing: route 94.26.7.48 <-> 74.125.136.27 (ea-in-f27.1e100.net) is now valid. debug: mta: connecting with [connector:94.26.7.48->[relay:gmail.com,sourcetable=myaddrs,helotable=myhelo],0x20000] debug: mta: canceling connector timeout debug: mta: enough connections already debug: mta: 0x7df4bc00: handling next task for relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] imsg: control <- pony: IMSG_STAT_INCREMENT (len=39) imsg: queue <- pony: IMSG_MTA_OPEN_MESSAGE (len=14) imsg: pony <- queue: IMSG_MTA_OPEN_MESSAGE (len=9, fd=4) mta: 0x7df4bc00: MTA_READY -> MTA_MAIL mta: 0x7df4bc00: >>> MAIL FROM:<[email protected]> mta: 0x7df4bc00: <<< 250 2.1.0 OK 44si8229893eef.40 - gsmtp mta: 0x7df4bc00: MTA_MAIL -> MTA_RCPT mta: 0x7df4bc00: >>> RCPT TO:<[email protected]> debug: mta: ... timeout for [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] debug: mta: draining [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] refcount=2, ntask=0, nconnector=1, nconn=1 debug: mta: all done for [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] mta: 0x7df4bc00: <<< 250 2.1.5 OK 44si8229893eef.40 - gsmtp mta: 0x7df4bc00: MTA_RCPT -> MTA_DATA mta: 0x7df4bc00: >>> DATA mta: 0x7df4bc00: <<< 354 Go ahead 44si8229893eef.40 - gsmtp mta: 0x7df4bc00: MTA_DATA -> MTA_BODY mta: 0x7df4bc00: >>> [...644 bytes...] mta: 0x7df4bc00: MTA_BODY -> MTA_BODY mta: 0x7df4bc00: end-of-file mta: 0x7df4bc00: MTA_BODY -> MTA_EOM mta: 0x7df4bc00: >>> . mta: 0x7df4bc00: <<< 250 2.0.0 OK 1399812748 44si8229893eef.40 - gsmtp relay: Ok for 479d5e87850c6021: session=d5741c1a0f9d07f3, from=<[email protected]>, to=<[email protected]>, rcpt=<->, source=94.26.7.48, relay=74.125.136.27 (ea-in-f27.1e100.net), delay=9s, stat=250 2.0.0 OK 1399812748 44si8229893eef.40 - gsmtp debug: mta: waiting for 1s before next transaction imsg: control <- pony: IMSG_STAT_DECREMENT (len=35) imsg: control <- pony: IMSG_STAT_DECREMENT (len=39) imsg: control <- pony: IMSG_STAT_DECREMENT (len=31) debug: mta: flush for 479d5e87850c6021 (-> [email protected]) imsg: queue <- pony: IMSG_MTA_DELIVERY_OK (len=14) imsg: control <- queue: IMSG_STAT_INCREMENT (len=46) imsg: control <- queue: IMSG_STAT_DECREMENT (len=42) imsg: scheduler <- queue: IMSG_QUEUE_DELIVERY_OK (len=9) imsg: control <- scheduler: IMSG_STAT_DECREMENT (len=49) imsg: control <- scheduler: IMSG_STAT_DECREMENT (len=50) imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=44) imsg: control <- scheduler: IMSG_STAT_DECREMENT (len=50) imsg: control <- scheduler: IMSG_STAT_DECREMENT (len=41) mta: timeout for session hangon mta: 0x7df4bc00: MTA_EOM -> MTA_READY debug: mta: 0x7df4bc00: no task for relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] mta: debug: last connection: hanging on for 9s mta: timeout for session hangon mta: 0x7df4bc00: MTA_READY -> MTA_READY debug: mta: 0x7df4bc00: no task for relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] mta: debug: last connection: hanging on for 8s mta: timeout for session hangon mta: 0x7df4bc00: MTA_READY -> MTA_READY debug: mta: 0x7df4bc00: no task for relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] mta: debug: last connection: hanging on for 7s mta: timeout for session hangon mta: 0x7df4bc00: MTA_READY -> MTA_READY debug: mta: 0x7df4bc00: no task for relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] mta: debug: last connection: hanging on for 6s mta: timeout for session hangon mta: 0x7df4bc00: MTA_READY -> MTA_READY debug: mta: 0x7df4bc00: no task for relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] mta: debug: last connection: hanging on for 5s mta: timeout for session hangon mta: 0x7df4bc00: MTA_READY -> MTA_READY debug: mta: 0x7df4bc00: no task for relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] mta: debug: last connection: hanging on for 4s mta: timeout for session hangon mta: 0x7df4bc00: MTA_READY -> MTA_READY debug: mta: 0x7df4bc00: no task for relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] mta: debug: last connection: hanging on for 3s mta: timeout for session hangon mta: 0x7df4bc00: MTA_READY -> MTA_READY debug: mta: 0x7df4bc00: no task for relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] mta: debug: last connection: hanging on for 2s mta: timeout for session hangon mta: 0x7df4bc00: MTA_READY -> MTA_READY debug: mta: 0x7df4bc00: no task for relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] mta: debug: last connection: hanging on for 1s mta: timeout for session hangon mta: 0x7df4bc00: MTA_READY -> MTA_READY debug: mta: 0x7df4bc00: no task for relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] mta: 0x7df4bc00: MTA_READY -> MTA_QUIT mta: 0x7df4bc00: >>> QUIT mta: 0x7df4bc00: <<< 221 2.0.0 closing connection 44si8229893eef.40 - gsmtp smtp-out: Closing session d5741c1a0f9d07f3: 1 message sent. debug: mta: 0x7df4bc00: session done debug: pony: rsae_finish debug: pony: rsae_finish debug: pony: rsae_finish debug: mta_route_collect(94.26.7.48 <-> 74.125.136.27 (ea-in-f27.1e100.net)) debug: mta: connecting with [connector:94.26.7.48->[relay:gmail.com,sourcetable=myaddrs,helotable=myhelo],0x20000] debug: mta: canceling connector timeout debug: mta: no task for connector debug: mta: ma_route_unref(): really discarding route 94.26.7.48 <-> 74.125.136.27 (ea-in-f27.1e100.net) debug: mta: freeing [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] debug: mta: freeing [connector:94.26.7.48->[relay:gmail.com,sourcetable=myaddrs,helotable=myhelo],0x20000] debug: mta: canceling timeout for [connector:94.26.7.48->[relay:gmail.com,sourcetable=myaddrs,helotable=myhelo],0x20000] imsg: control <- pony: IMSG_STAT_DECREMENT (len=34) imsg: control <- pony: IMSG_STAT_DECREMENT (len=32) imsg: control <- pony: IMSG_STAT_DECREMENT (len=33) imsg: control <- pony: IMSG_STAT_DECREMENT (len=36) imsg: control <- pony: IMSG_STAT_DECREMENT (len=31) imsg: control <- pony: IMSG_STAT_DECREMENT (len=31) imsg: control <- pony: IMSG_STAT_DECREMENT (len=31) imsg: control <- pony: IMSG_STAT_DECREMENT (len=31) imsg: control <- pony: IMSG_STAT_DECREMENT (len=31) imsg: control <- pony: IMSG_STAT_DECREMENT (len=31) imsg: control <- pony: IMSG_STAT_DECREMENT (len=31) imsg: control <- pony: IMSG_STAT_DECREMENT (len=31) imsg: control <- pony: IMSG_STAT_DECREMENT (len=31) imsg: control <- pony: IMSG_STAT_DECREMENT (len=31) imsg: control <- pony: IMSG_STAT_DECREMENT (len=33) imsg: control <- pony: IMSG_STAT_DECREMENT (len=32) debug: smtp: new client on listener: 0x7b863000 imsg: lka <- pony: IMSG_SMTP_DNS_PTR (len=30) imsg: control <- pony: IMSG_STAT_INCREMENT (len=35) imsg: pony <- lka: IMSG_SMTP_DNS_PTR (len=25) smtp-in: New session d5741c1be02e7069 from host localhost [127.0.0.1] imsg: lka <- pony: IMSG_SMTP_SSL_INIT (len=264) debug: lka: looking up pki "smtp.bsdbg.net" imsg: pony <- lka: IMSG_SMTP_SSL_INIT (len=1973) debug: session_start_ssl: switching to SSL imsg: control <- pony: IMSG_STAT_INCREMENT (len=41) smtp-in: No PKI entry for requested SNI "localhost"on session d5741c1be02e7069 debug: pony: rsae_priv_enc imsg: ca <- pony: IMSG_CA_PRIVENC (len=123) imsg: ca <- pony: IMSG_CA_PRIVENC (len=123) imsg: pony <- ca: IMSG_CA_PRIVENC (len=531) smtp-in: Started TLS on session d5741c1be02e7069: version=TLSv1/SSLv3, cipher=ECDHE-RSA-AES256-GCM-SHA384, bits=256 imsg: control <- pony: IMSG_STAT_INCREMENT (len=33) imsg: lka <- pony: IMSG_SMTP_AUTHENTICATE (len=30) imsg: parent <- lka: IMSG_LKA_AUTHENTICATE (len=28) imsg: lka <- parent: IMSG_LKA_AUTHENTICATE (len=14) imsg: pony <- lka: IMSG_SMTP_AUTHENTICATE (len=14) smtp-in: Accepted authentication for user vlado on session d5741c1be02e7069 imsg: queue <- pony: IMSG_SMTP_MESSAGE_CREATE (len=9) imsg: pony <- queue: IMSG_SMTP_MESSAGE_CREATE (len=19) imsg: lka <- pony: IMSG_SMTP_EXPAND_RCPT (len=277) imsg: queue <- lka: IMSG_LKA_ENVELOPE_SUBMIT (len=354) imsg: queue <- lka: IMSG_LKA_ENVELOPE_COMMIT (len=9) imsg: control <- queue: IMSG_STAT_INCREMENT (len=42) imsg: scheduler <- queue: IMSG_QUEUE_ENVELOPE_SUBMIT (len=354) imsg: pony <- queue: IMSG_QUEUE_ENVELOPE_SUBMIT (len=23) imsg: pony <- queue: IMSG_QUEUE_ENVELOPE_COMMIT (len=14) imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=50) imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=48) imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=49) imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=50) imsg: queue <- pony: IMSG_SMTP_MESSAGE_OPEN (len=14) imsg: pony <- queue: IMSG_SMTP_MESSAGE_OPEN (len=14, fd=5) debug: 0x75190000: end of message, msgflags=0x0000 imsg: queue <- pony: IMSG_SMTP_MESSAGE_COMMIT (len=14) imsg: scheduler <- queue: IMSG_QUEUE_MESSAGE_COMMIT (len=5) imsg: pony <- queue: IMSG_SMTP_MESSAGE_COMMIT (len=14) debug: scheduler: evp:e382f84784ed0108 scheduled (mta) imsg: control <- scheduler: IMSG_STAT_DECREMENT (len=48) imsg: queue <- scheduler: IMSG_SCHED_ENVELOPE_TRANSFER (len=9) imsg: control <- scheduler: IMSG_STAT_DECREMENT (len=50) imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=41) imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=50) imsg: control <- queue: IMSG_STAT_INCREMENT (len=46) smtp-in: Accepted message e382f847 on session d5741c1be02e7069: from=<[email protected]>, to=<[email protected]>, size=356, ndest=1, proto=ESMTP imsg: pony <- queue: IMSG_QUEUE_TRANSFER (len=363) debug: mta: received evp:e382f84784ed0108 for <[email protected]> debug: mta: draining [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] refcount=1, ntask=1, nconnector=0, nconn=0 debug: mta: querying MX for [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo]... debug: mta: [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] waiting for MX imsg: lka <- pony: IMSG_MTA_DNS_MX (len=20) imsg: control <- pony: IMSG_STAT_INCREMENT (len=33) imsg: control <- pony: IMSG_STAT_INCREMENT (len=32) imsg: control <- pony: IMSG_STAT_INCREMENT (len=31) imsg: control <- pony: IMSG_STAT_INCREMENT (len=35) imsg: pony <- lka: IMSG_MTA_DNS_HOST (len=35) imsg: pony <- lka: IMSG_MTA_DNS_HOST (len=47) imsg: pony <- lka: IMSG_MTA_DNS_HOST (len=35) imsg: pony <- lka: IMSG_MTA_DNS_HOST (len=47) imsg: pony <- lka: IMSG_MTA_DNS_HOST (len=35) imsg: pony <- lka: IMSG_MTA_DNS_HOST (len=47) imsg: pony <- lka: IMSG_MTA_DNS_HOST (len=35) imsg: pony <- lka: IMSG_MTA_DNS_HOST (len=47) imsg: pony <- lka: IMSG_MTA_DNS_HOST (len=35) imsg: pony <- lka: IMSG_MTA_DNS_HOST (len=47) imsg: pony <- lka: IMSG_MTA_DNS_HOST_END (len=14) debug: MXs for domain gmail.com: 74.125.136.27 preference 5 IPv6:2a00:1450:4013:c01::1a preference 5 74.125.25.27 preference 10 IPv6:2607:f8b0:400e:c03::1b preference 10 173.194.64.27 preference 20 IPv6:2607:f8b0:4003:c02::1a preference 20 74.125.193.27 preference 30 IPv6:2607:f8b0:4001:c05::1a preference 30 74.125.196.27 preference 40 IPv6:2607:f8b0:4002:c07::1a preference 40 debug: mta: ... got mx (0x823b9bd0, gmail.com, [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo]) debug: mta: draining [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] refcount=1, ntask=1, nconnector=0, nconn=0 debug: mta: querying source for [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo]... imsg: control <- pony: IMSG_STAT_INCREMENT (len=31) imsg: control <- pony: IMSG_STAT_INCREMENT (len=31) imsg: control <- pony: IMSG_STAT_INCREMENT (len=31) imsg: control <- pony: IMSG_STAT_INCREMENT (len=31) imsg: control <- pony: IMSG_STAT_INCREMENT (len=31) imsg: control <- pony: IMSG_STAT_INCREMENT (len=31) imsg: control <- pony: IMSG_STAT_INCREMENT (len=31) imsg: control <- pony: IMSG_STAT_INCREMENT (len=31) imsg: control <- pony: IMSG_STAT_INCREMENT (len=31) imsg: control <- pony: IMSG_STAT_INCREMENT (len=31) imsg: lka <- pony: IMSG_MTA_LOOKUP_SOURCE (len=18) imsg: pony <- lka: IMSG_MTA_LOOKUP_SOURCE (len=35) debug: mta: ... got source for [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo]: 94.26.7.48 debug: mta: new [connector:94.26.7.48->[relay:gmail.com,sourcetable=myaddrs,helotable=myhelo],0x10000] debug: mta: connecting with [connector:94.26.7.48->[relay:gmail.com,sourcetable=myaddrs,helotable=myhelo],0x0] debug: mta-routing: searching new route for [connector:94.26.7.48->[relay:gmail.com,sourcetable=myaddrs,helotable=myhelo],0x0]... debug: mta-routing: selecting candidate route 94.26.7.48 <-> 74.125.136.27 debug: mta-routing: skipping host IPv6:2a00:1450:4013:c01::1a: AF mismatch debug: mta-routing: spawning new connection on 94.26.7.48 <-> 74.125.136.27 debug: mta: 0x74cbcd00: spawned for relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] debug: mta: connecting with [connector:94.26.7.48->[relay:gmail.com,sourcetable=myaddrs,helotable=myhelo],0x0] debug: mta: cannot use [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] before 2s debug: mta-routing: no route available for [connector:94.26.7.48->[relay:gmail.com,sourcetable=myaddrs,helotable=myhelo],0x0]: must wait a bit debug: mta: retrying to connect on [connector:94.26.7.48->[relay:gmail.com,sourcetable=myaddrs,helotable=myhelo],0x0] in 2s... debug: mta: draining [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] refcount=2, ntask=1, nconnector=1, nconn=1 debug: mta: scheduling relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] in 1s... imsg: lka <- pony: IMSG_MTA_DNS_PTR (len=30) imsg: control <- pony: IMSG_STAT_INCREMENT (len=33) imsg: control <- pony: IMSG_STAT_INCREMENT (len=36) imsg: control <- pony: IMSG_STAT_INCREMENT (len=32) imsg: control <- pony: IMSG_STAT_INCREMENT (len=34) imsg: pony <- lka: IMSG_MTA_DNS_PTR (len=35) imsg: lka <- pony: IMSG_MTA_LOOKUP_HELO (len=38) debug: lka: helo myhelo:94.26.7.48 imsg: pony <- lka: IMSG_MTA_LOOKUP_HELO (len=30) smtp-out: Connecting to smtp+tls://74.125.136.27:25 (ea-in-f27.1e100.net) on session d5741c1eefb806c6... mta: 0x74cbcd00: MTA_INIT -> MTA_INIT smtp-out: Connected on session d5741c1eefb806c6 mta: 0x74cbcd00: MTA_INIT -> MTA_BANNER mta: 0x74cbcd00: <<< 220 mx.google.com ESMTP v41si8232221eew.44 - gsmtp mta: 0x74cbcd00: MTA_BANNER -> MTA_EHLO mta: 0x74cbcd00: >>> EHLO smtp.bsdbg.net mta: 0x74cbcd00: <<< 250-mx.google.com at your service, [94.26.7.48] mta: 0x74cbcd00: <<< 250-SIZE 35882577 mta: 0x74cbcd00: <<< 250-8BITMIME mta: 0x74cbcd00: <<< 250-STARTTLS mta: 0x74cbcd00: <<< 250-ENHANCEDSTATUSCODES mta: 0x74cbcd00: <<< 250 CHUNKING mta: 0x74cbcd00: MTA_EHLO -> MTA_STARTTLS mta: 0x74cbcd00: >>> STARTTLS smtp-in: Closing session d5741c1be02e7069 debug: smtp: 0x75190000: deleting session: done imsg: control <- pony: IMSG_STAT_DECREMENT (len=33) imsg: control <- pony: IMSG_STAT_DECREMENT (len=35) mta: 0x74cbcd00: <<< 220 2.0.0 Ready to start TLS imsg: lka <- pony: IMSG_MTA_SSL_INIT (len=264) debug: lka: looking up pki "smtp.bsdbg.net" imsg: pony <- lka: IMSG_MTA_SSL_INIT (len=1973) debug: pony: rsae_init debug: pony: rsae_init debug: pony: rsae_init debug: pony: rsae_pub_dec debug: pony: rsae_bn_mod_exp smtp-out: Started TLS on session d5741c1eefb806c6: version=TLSv1/SSLv3, cipher=ECDHE-RSA-AES128-GCM-SHA256, bits=128 imsg: lka <- pony: IMSG_MTA_SSL_VERIFY_CERT (len=1964) imsg: lka <- pony: IMSG_MTA_SSL_VERIFY_CHAIN (len=1964) imsg: lka <- pony: IMSG_MTA_SSL_VERIFY_CHAIN (len=1324) imsg: lka <- pony: IMSG_MTA_SSL_VERIFY_CHAIN (len=1189) imsg: lka <- pony: IMSG_MTA_SSL_VERIFY (len=292) imsg: pony <- lka: IMSG_MTA_SSL_VERIFY (len=12) smtp-out: Server certificate verification succeeded on session d5741c1eefb806c6 mta: 0x74cbcd00: MTA_STARTTLS -> MTA_EHLO mta: 0x74cbcd00: >>> EHLO smtp.bsdbg.net mta: 0x74cbcd00: <<< 250-mx.google.com at your service, [94.26.7.48] mta: 0x74cbcd00: <<< 250-SIZE 35882577 mta: 0x74cbcd00: <<< 250-8BITMIME mta: 0x74cbcd00: <<< 250-ENHANCEDSTATUSCODES mta: 0x74cbcd00: <<< 250 CHUNKING mta: 0x74cbcd00: MTA_EHLO -> MTA_STARTTLS mta: 0x74cbcd00: MTA_STARTTLS -> MTA_AUTH mta: 0x74cbcd00: MTA_AUTH -> MTA_READY debug: mta-routing: route 94.26.7.48 <-> 74.125.136.27 (ea-in-f27.1e100.net) is now valid. debug: mta: connecting with [connector:94.26.7.48->[relay:gmail.com,sourcetable=myaddrs,helotable=myhelo],0x20000] debug: mta: canceling connector timeout debug: mta: enough connections already debug: mta: 0x74cbcd00: handling next task for relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] imsg: control <- pony: IMSG_STAT_INCREMENT (len=39) imsg: queue <- pony: IMSG_MTA_OPEN_MESSAGE (len=14) imsg: pony <- queue: IMSG_MTA_OPEN_MESSAGE (len=9, fd=4) mta: 0x74cbcd00: MTA_READY -> MTA_MAIL mta: 0x74cbcd00: >>> MAIL FROM:<[email protected]> mta: 0x74cbcd00: <<< 250 2.1.0 OK v41si8232221eew.44 - gsmtp mta: 0x74cbcd00: MTA_MAIL -> MTA_RCPT mta: 0x74cbcd00: >>> RCPT TO:<[email protected]> mta: 0x74cbcd00: <<< 250 2.1.5 OK v41si8232221eew.44 - gsmtp mta: 0x74cbcd00: MTA_RCPT -> MTA_DATA mta: 0x74cbcd00: >>> DATA mta: 0x74cbcd00: <<< 354 Go ahead v41si8232221eew.44 - gsmtp mta: 0x74cbcd00: MTA_DATA -> MTA_BODY mta: 0x74cbcd00: >>> [...632 bytes...] debug: mta: ... timeout for [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] debug: mta: draining [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] refcount=2, ntask=0, nconnector=1, nconn=1 debug: mta: all done for [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] mta: 0x74cbcd00: MTA_BODY -> MTA_BODY mta: 0x74cbcd00: end-of-file mta: 0x74cbcd00: MTA_BODY -> MTA_EOM mta: 0x74cbcd00: >>> . mta: 0x74cbcd00: <<< 250 2.0.0 OK 1399812816 v41si8232221eew.44 - gsmtp relay: Ok for e382f84784ed0108: session=d5741c1eefb806c6, from=<[email protected]>, to=<[email protected]>, rcpt=<->, source=94.26.7.48, relay=74.125.136.27 (ea-in-f27.1e100.net), delay=2s, stat=250 2.0.0 OK 1399812816 v41si8232221eew.44 - gsmtp debug: mta: waiting for 1s before next transaction debug: mta: flush for e382f84784ed0108 (-> [email protected]) imsg: control <- pony: IMSG_STAT_DECREMENT (len=35) imsg: queue <- pony: IMSG_MTA_DELIVERY_OK (len=14) imsg: control <- pony: IMSG_STAT_DECREMENT (len=39) imsg: scheduler <- queue: IMSG_QUEUE_DELIVERY_OK (len=9) imsg: control <- pony: IMSG_STAT_DECREMENT (len=31) imsg: control <- queue: IMSG_STAT_INCREMENT (len=46) imsg: control <- queue: IMSG_STAT_DECREMENT (len=42) imsg: control <- scheduler: IMSG_STAT_DECREMENT (len=49) imsg: control <- scheduler: IMSG_STAT_DECREMENT (len=50) imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=44) imsg: control <- scheduler: IMSG_STAT_DECREMENT (len=50) imsg: control <- scheduler: IMSG_STAT_DECREMENT (len=41) mta: timeout for session hangon mta: 0x74cbcd00: MTA_EOM -> MTA_READY debug: mta: 0x74cbcd00: no task for relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] mta: debug: last connection: hanging on for 9s mta: timeout for session hangon mta: 0x74cbcd00: MTA_READY -> MTA_READY debug: mta: 0x74cbcd00: no task for relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] mta: debug: last connection: hanging on for 8s mta: timeout for session hangon mta: 0x74cbcd00: MTA_READY -> MTA_READY debug: mta: 0x74cbcd00: no task for relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] mta: debug: last connection: hanging on for 7s mta: timeout for session hangon mta: 0x74cbcd00: MTA_READY -> MTA_READY debug: mta: 0x74cbcd00: no task for relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] mta: debug: last connection: hanging on for 6s mta: timeout for session hangon mta: 0x74cbcd00: MTA_READY -> MTA_READY debug: mta: 0x74cbcd00: no task for relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] mta: debug: last connection: hanging on for 5s mta: timeout for session hangon mta: 0x74cbcd00: MTA_READY -> MTA_READY debug: mta: 0x74cbcd00: no task for relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] mta: debug: last connection: hanging on for 4s mta: timeout for session hangon mta: 0x74cbcd00: MTA_READY -> MTA_READY debug: mta: 0x74cbcd00: no task for relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] mta: debug: last connection: hanging on for 3s mta: timeout for session hangon mta: 0x74cbcd00: MTA_READY -> MTA_READY debug: mta: 0x74cbcd00: no task for relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] mta: debug: last connection: hanging on for 2s mta: timeout for session hangon mta: 0x74cbcd00: MTA_READY -> MTA_READY debug: mta: 0x74cbcd00: no task for relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] mta: debug: last connection: hanging on for 1s mta: timeout for session hangon mta: 0x74cbcd00: MTA_READY -> MTA_READY debug: mta: 0x74cbcd00: no task for relay [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] mta: 0x74cbcd00: MTA_READY -> MTA_QUIT mta: 0x74cbcd00: >>> QUIT mta: 0x74cbcd00: <<< 221 2.0.0 closing connection v41si8232221eew.44 - gsmtp smtp-out: Closing session d5741c1eefb806c6: 1 message sent. debug: mta: 0x74cbcd00: session done debug: pony: rsae_finish debug: pony: rsae_finish debug: pony: rsae_finish debug: mta_route_collect(94.26.7.48 <-> 74.125.136.27 (ea-in-f27.1e100.net)) debug: mta: connecting with [connector:94.26.7.48->[relay:gmail.com,sourcetable=myaddrs,helotable=myhelo],0x20000] debug: mta: canceling connector timeout debug: mta: no task for connector debug: mta: ma_route_unref(): really discarding route 94.26.7.48 <-> 74.125.136.27 (ea-in-f27.1e100.net) debug: mta: freeing [relay:gmail.com,sourcetable=myaddrs,helotable=myhelo] debug: mta: freeing [connector:94.26.7.48->[relay:gmail.com,sourcetable=myaddrs,helotable=myhelo],0x20000] debug: mta: canceling timeout for [connector:94.26.7.48->[relay:gmail.com,sourcetable=myaddrs,helotable=myhelo],0x20000] imsg: control <- pony: IMSG_STAT_DECREMENT (len=34) imsg: control <- pony: IMSG_STAT_DECREMENT (len=32) imsg: control <- pony: IMSG_STAT_DECREMENT (len=33) imsg: control <- pony: IMSG_STAT_DECREMENT (len=36) imsg: control <- pony: IMSG_STAT_DECREMENT (len=31) imsg: control <- pony: IMSG_STAT_DECREMENT (len=31) imsg: control <- pony: IMSG_STAT_DECREMENT (len=31) imsg: control <- pony: IMSG_STAT_DECREMENT (len=31) imsg: control <- pony: IMSG_STAT_DECREMENT (len=31) imsg: control <- pony: IMSG_STAT_DECREMENT (len=31) imsg: control <- pony: IMSG_STAT_DECREMENT (len=31) imsg: control <- pony: IMSG_STAT_DECREMENT (len=31) imsg: control <- pony: IMSG_STAT_DECREMENT (len=31) imsg: control <- pony: IMSG_STAT_DECREMENT (len=31) imsg: control <- pony: IMSG_STAT_DECREMENT (len=33) imsg: control <- pony: IMSG_STAT_DECREMENT (len=32) debug: smtp: new client on listener: 0x84413000 imsg: lka <- pony: IMSG_SMTP_DNS_PTR (len=30) imsg: control <- pony: IMSG_STAT_INCREMENT (len=35) imsg: control <- pony: IMSG_STAT_INCREMENT (len=41) imsg: pony <- lka: IMSG_SMTP_DNS_PTR (len=40) smtp-in: New session d5741c1ff36bf1ea from host mail-vc0-f170.google.com [209.85.220.170] imsg: lka <- pony: IMSG_SMTP_SSL_INIT (len=264) debug: lka: looking up pki "smtp.bsdbg.net" imsg: pony <- lka: IMSG_SMTP_SSL_INIT (len=1973) debug: session_start_ssl: switching to SSL debug: pony: rsae_priv_enc imsg: ca <- pony: IMSG_CA_PRIVENC (len=76) imsg: ca <- pony: IMSG_CA_PRIVENC (len=76) imsg: pony <- ca: IMSG_CA_PRIVENC (len=531) debug: pony: rsae_init debug: pony: rsae_init debug: pony: rsae_pub_dec debug: pony: rsae_bn_mod_exp debug: pony: rsae_init debug: pony: rsae_pub_dec debug: pony: rsae_bn_mod_exp debug: pony: rsae_pub_dec debug: pony: rsae_bn_mod_exp smtp-in: Started TLS on session d5741c1ff36bf1ea: version=TLSv1/SSLv3, cipher=ECDHE-RSA-AES128-SHA, bits=128 imsg: lka <- pony: IMSG_SMTP_SSL_VERIFY_CERT (len=1438) imsg: lka <- pony: IMSG_SMTP_SSL_VERIFY_CHAIN (len=1324) imsg: lka <- pony: IMSG_SMTP_SSL_VERIFY_CHAIN (len=1189) imsg: lka <- pony: IMSG_SMTP_SSL_VERIFY (len=292) imsg: pony <- lka: IMSG_SMTP_SSL_VERIFY (len=12) smtp-in: Client certificate verification succeeded on session d5741c1ff36bf1ea imsg: control <- pony: IMSG_STAT_INCREMENT (len=31) debug: smtp: SIZE in MAIL FROM command imsg: queue <- pony: IMSG_SMTP_MESSAGE_CREATE (len=9) imsg: pony <- queue: IMSG_SMTP_MESSAGE_CREATE (len=19) imsg: lka <- pony: IMSG_SMTP_EXPAND_RCPT (len=286) imsg: parent <- lka: IMSG_LKA_OPEN_FORWARD (len=1076) imsg: lka <- parent: IMSG_LKA_OPEN_FORWARD (len=1076) imsg: queue <- lka: IMSG_LKA_ENVELOPE_SUBMIT (len=399) imsg: queue <- lka: IMSG_LKA_ENVELOPE_COMMIT (len=9) imsg: control <- queue: IMSG_STAT_INCREMENT (len=42) imsg: scheduler <- queue: IMSG_QUEUE_ENVELOPE_SUBMIT (len=399) imsg: pony <- queue: IMSG_QUEUE_ENVELOPE_SUBMIT (len=23) imsg: pony <- queue: IMSG_QUEUE_ENVELOPE_COMMIT (len=14) imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=50) imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=48) imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=49) imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=50) imsg: queue <- pony: IMSG_SMTP_MESSAGE_OPEN (len=14) imsg: pony <- queue: IMSG_SMTP_MESSAGE_OPEN (len=14, fd=5) debug: 0x78099000: end of message, msgflags=0x0000 imsg: queue <- pony: IMSG_SMTP_MESSAGE_COMMIT (len=14) imsg: scheduler <- queue: IMSG_QUEUE_MESSAGE_COMMIT (len=5) imsg: pony <- queue: IMSG_SMTP_MESSAGE_COMMIT (len=14) smtp-in: Accepted message 39baf3ca on session d5741c1ff36bf1ea: from=<[email protected]>, to=<[email protected]>, size=2090, ndest=1, proto=ESMTP imsg: control <- scheduler: IMSG_STAT_DECREMENT (len=48) imsg: control <- scheduler: IMSG_STAT_DECREMENT (len=50) imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=41) debug: scheduler: evp:39baf3cae88276f5 scheduled (mda) imsg: queue <- scheduler: IMSG_SCHED_ENVELOPE_DELIVER (len=9) imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=50) imsg: pony <- queue: IMSG_QUEUE_DELIVER (len=408) imsg: control <- queue: IMSG_STAT_INCREMENT (len=46) mda: new user d5741c20e009174b for "<getpwnam>:vlado" imsg: control <- pony: IMSG_STAT_INCREMENT (len=31) imsg: control <- pony: IMSG_STAT_INCREMENT (len=35) imsg: control <- pony: IMSG_STAT_INCREMENT (len=34) imsg: lka <- pony: IMSG_MDA_LOOKUP_USERINFO (len=28) debug: lka: userinfo <getpwnam>:vlado imsg: pony <- lka: IMSG_MDA_LOOKUP_USERINFO (len=1083) debug: mda: new session d5741c214642f70b for user "<getpwnam>:vlado" evpid 39baf3cae88276f5 debug: mda: no more envelope for "<getpwnam>:vlado" imsg: control <- pony: IMSG_STAT_DECREMENT (len=34) imsg: queue <- pony: IMSG_MDA_OPEN_MESSAGE (len=14) imsg: control <- pony: IMSG_STAT_INCREMENT (len=34) imsg: pony <- queue: IMSG_MDA_OPEN_MESSAGE (len=9, fd=5) debug: mda: got message fd 5 for session d5741c214642f70b evpid 39baf3cae88276f5 debug: mda: querying mda fd for session d5741c214642f70b evpid 39baf3cae88276f5 imsg: parent <- pony: IMSG_MDA_FORK (len=5210) debug: smtpd: forking mda for session d5741c214642f70b: "/home/vlado/Maildir" as vlado imsg: pony <- parent: IMSG_MDA_FORK (len=9, fd=6) debug: mda: got mda fd 6 for session d5741c214642f70b evpid 39baf3cae88276f5 debug: mda: end-of-file for session d5741c214642f70b evpid 39baf3cae88276f5 debug: mda: all data sent for session d5741c214642f70b evpid 39baf3cae88276f5 debug: smtpd: mda process done for session d5741c214642f70b: exited okay imsg: pony <- parent: IMSG_MDA_DONE (len=22, fd=5) delivery: Ok for 39baf3cae88276f5: from=<[email protected]>, to=<[email protected]>, user=vlado, method=maildir, delay=0s, stat=Delivered debug: mda: session d5741c214642f70b done debug: mda: user "vlado" becomes runnable debug: mda: all done for user "<getpwnam>:vlado" imsg: control <- pony: IMSG_STAT_DECREMENT (len=35) imsg: queue <- pony: IMSG_MDA_DELIVERY_OK (len=9) imsg: control <- pony: IMSG_STAT_DECREMENT (len=34) imsg: control <- pony: IMSG_STAT_DECREMENT (len=31) imsg: scheduler <- queue: IMSG_QUEUE_DELIVERY_OK (len=9) imsg: control <- queue: IMSG_STAT_INCREMENT (len=46) imsg: control <- queue: IMSG_STAT_DECREMENT (len=42) imsg: control <- scheduler: IMSG_STAT_DECREMENT (len=49) imsg: control <- scheduler: IMSG_STAT_DECREMENT (len=50) imsg: control <- scheduler: IMSG_STAT_INCREMENT (len=44) imsg: control <- scheduler: IMSG_STAT_DECREMENT (len=50) imsg: control <- scheduler: IMSG_STAT_DECREMENT (len=41) smtp-in: Closing session d5741c1ff36bf1ea debug: smtp: 0x78099000: deleting session: done debug: pony: rsae_finish debug: pony: rsae_finish debug: pony: rsae_finish imsg: control <- pony: IMSG_STAT_DECREMENT (len=31) imsg: control <- pony: IMSG_STAT_DECREMENT (len=35)
