"Error: Cannot pipe while currently piping" with lmtp

[tino]

I have a plugin to forward mail to archiveopteryx via lmtp:

// queue through lmtp if the message is marked to_aox
"use strict";

var outbound = require('./outbound');

exports.hook_queue = function(next, connection) {
    if (connection.transaction.notes.to_aox) {
        this.logdebug('to_aox is true, sending output with using_lmtp=true');
        connection.transaction.notes.using_lmtp = true;
        outbound.send_email(connection.transaction, next);
    } else {
        this.logdebug('to_aox is false, ignoring');
        next();
    }
}

exports.hook_get_mx = function (next, hmail, domain) {
    if (!hmail.todo.notes.using_lmtp) return next();
    var config = this.config.get('archiveopteryx.ini');
    var section = config['lmtp'] || config.main;
    this.loginfo('lmtp port: ' + section.port);
    var mx = {
        priority: 0,
        exchange: section.host || '127.0.0.1',
        port: section.port || 24,
        using_lmtp: true
    };
    return next(OK, mx);
}

debug log: https://gist.github.com/tino/675a2e0b5dd1cf71e647 (replaced the domain with mydomain.io) The list of enabled plugins is also shown there.

Any way I can debug this?

[tino]

Oke, dkim_verify is the culprit. At least, with it enabled, I get this error, without it, it works.

[smfreegard]

@tino are you using spool_after in your smtp.ini file by any chance?

[tino]

@smfreegard Nope, the only thing enabled in smtp.ini is:

; Daemonize
daemonize=true
daemon_log_file=/var/log/haraka.log
daemon_pid_file=/var/run/haraka.pid

@Dexus I understand. But where do I pipe a stream? And where has it been sent already? The only thing I am doing is duplicating the lmtp plugin, but under a certain condition.

[Dexus]

FYI

https://gist.github.com/jrb/bee88223e9d141e7ec94 http://pastebin.com/evXKQdBR

<jbaldridge> huh... this is interesting. as long as the spamassassin plugin is enabled after dkim_verify, things work.

[jrb]

Any time dkim_verify is enabled without spamassassin following it, I'm seeing this error pop up. It's easy to reproduce with an otherwise default config. Here are logs/plugins files from tests with and without the spamassassin plugin: https://gist.github.com/jrb/4130d97c99f931ea6a26

[chazomaticus]

I recently ran into this bug. I have a reproducible setup to trigger the bug, but that's as far as I've gotten yet:

$ git clone git@github.com:haraka/Haraka.git haraka-test-1163
$ cd haraka-test-1163
$ npm install
$ vi config/plugins  # disable everything but the following:
$ egrep -v '^($|#)' config/plugins
rcpt_to.in_host_list
dkim_verify
queue/smtp_proxy
$ sudo node haraka.js

Now in another terminal, pretend to the be the destination of haraka's proxying. smtp_proxy defaults to port 2555. Your input, the lines starting with numbers here, will be intermixed with sending the message in yet another terminal, but I'll type it all here first for clarity's sake. Note that that's as far as you need to get in the proxy destination window, the bug triggers before you can finish the conversation.

$ nc -l -p 2555
220 yes?
EHLO haraka.test
250 hi
MAIL FROM:<test@haraka.local>
250 cool
RCPT TO:<test@haraka.local>
250 yeah
DATA
354 sure

Now in the third terminal, send the message to haraka. Your input, the lines starting with all-caps words here, will again be intermixed with the proxy destination window input where it makes sense.

$ telnet localhost 25
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
220 haraka.test ESMTP Haraka 2.7.3 ready
HELO localhost
250 haraka.test Hello Unknown [127.0.0.1], Haraka is at your service.
MAIL FROM:<test@haraka.local>
250 sender <test@haraka.local> OK
RCPT TO:<test@haraka.local>
250 recipient <test@haraka.local> OK
DATA
354 go ahead, make my day
.            
451  (1BC0B68E-A66E-4849-BD4D-A6EF0679E860.1)

As soon as you hit enter after the dot, you can see haraka throw the error:

[CRIT] [1BC0B68E-A66E-4849-BD4D-A6EF0679E860.1] [core] Plugin queue/smtp_proxy failed: Error: Cannot pipe while currently piping
    at MessageStream.pipe (/home/chaz/haraka-test-1163/messagestream.js:325:15)
    at SMTPClient.start_data (/home/chaz/haraka-test-1163/smtp_client.js:172:10)
    at Plugin.exports.hook_queue (/home/chaz/haraka-test-1163/plugins/queue/smtp_proxy.js:99:17)
    at Object.plugins.run_next_hook (/home/chaz/haraka-test-1163/plugins.js:383:28)
    at Object.plugins.run_hooks (/home/chaz/haraka-test-1163/plugins.js:299:13)
    at Connection.data_post_respond (/home/chaz/haraka-test-1163/connection.js:1598:25)
    at callback (/home/chaz/haraka-test-1163/plugins.js:356:35)
    at /home/chaz/haraka-test-1163/plugins/dkim_verify.js:22:30
    at DKIMVerifyStream.cb (/home/chaz/haraka-test-1163/dkim.js:427:20)
    at DKIMVerifyStream.handle_buf (/home/chaz/haraka-test-1163/dkim.js:516:33)

Sure enough, both dkim_verify and smtp_proxy both call connection.transaction.message_stream.pipe(...) eventually. Sadly I don't know enough about node to have any idea the right way to proceed from here.