# lost connection with localhost - policyd problem w/postfix

## hanj

Hello

I'm running into a weird problem with policyd-weight (possibly), but definitely with the postfix queue. On occassion, I'll have a few emails stuck in the queue with the following status message:

```
4DD4E6C3F     79763 Mon Jul 23 18:16:31  orbitz@my.orbitz.com

(lost connection with localhost[127.0.0.1] while sending end of data -- message may be sent more than once)

                                        user1@domain1.com

4335F921D9    78681 Mon Jul 23 17:15:33  orbitz@my.orbitz.com

(lost connection with localhost[127.0.0.1] while sending end of data -- message may be sent more than once)

                                         user2@domain2.com
```

Now, I have a few things listening on localhost for my MTA. Amavis and policyd-weight listen and help manage mail for me on localhost. I'm unable to identify why it's losing the connection. What I do know, is that policd-weight and amavis is working while I'm looking at these. Mail is being delivered and policies are being tested, etc.

If I try to flush the queue (postqueue -f) or re-queue (postsuper -r ALL) the messages, the messages look like they're going to go, but then fall back to the same error. I can telnet to either port (amavis or policy) on localhost and it's answering. As I said, while I'm messing with this, mails are being handled by amavis or policy.

So, I have a two part questions.

1. Does anyone know why/what is going on here?

2. How can I successfully deliver these mails?

I'm 98% sure that the problem is related to policy. Here is snip of the logs where the above messages starting having problems:

```
Jul 23 17:15:38 comp.com postfix/policyd-weight[27840]: weighted check:  NOT_IN_SBL_XBL_SPAMHAUS=-1.5 NOT_IN_SPAMCOP=-1.5 NOT_IN_BL_NJABL=-1.5 HELO_IP_IN_CL16_SUBNET=-0.41 REV_IP_EQ_HELO=-1.25 (check from: .orbitz. - helo: .mail.orbitz. - helo-domain: .orbitz.)  MAIL_SEEMS_FORGED=2.5 FROM_MULTIPARTED=1.09 <client=xxx.xxx.xxx.xxx> <helo=mail.orbitz.com> <from=orbitz@my.orbitz.com> <to=user1@domain1.com>, rate: -2.57

Jul 23 17:15:38 comp.com postfix/policyd-weight[27840]: decided action=PREPEND X-policyd-weight:  NOT_IN_SBL_XBL_SPAMHAUS=-1.5 NOT_IN_SPAMCOP=-1.5 NOT_IN_BL_NJABL=-1.5 HELO_IP_IN_CL16_SUBNET=-0.41 REV_IP_EQ_HELO=-1.25 (check from: .orbitz. - helo: .mail.orbitz. - helo-domain: .orbitz.)  MAIL_SEEMS_FORGED=2.5 FROM_MULTIPARTED=1.09 <client=xxx.xxx.xxx.xxx> <helo=mail.orbitz.com> <from=orbitz@my.orbitz.com> <to=user1@domain1.com>, rate: -2.57; delay: 3s

Jul 23 17:15:38 comp.com postfix/policyd-weight[27840]: decided action=550 temporarily blocked because of previous errors - retrying too fast. penalty: 30 seconds x 0 retries.; delay: 0s
```

Now.. 3 seconds later...

```
Jul 23 17:15:41 comp.com postfix/smtp[4260]: 7B6635A0A: to=<user1@domain1.com>, relay=localhost[127.0.0.1]:10024, delay=8.4, delays=5.2/0/0.01/3.1, dsn=4.4.2, status=deferred (lost connection with localhost[127.0.0.1] while sending end of data -- message may be sent more than once)
```

Now, it's interesting to see that the message ID is different (7B6635A0A, but what is in the queue is 4DD4E6C3F). I can navigate to /var/spool/postfix/deferred and find the message.

Any ideas?

Here are my relevant packages:

```
[ebuild   R   ] mail-filter/dcc-1.3.55  USE="-ipv6 -rrdtool" 1,424 kB

[ebuild   R   ] mail-filter/razor-2.82  78 kB

[ebuild   R   ] mail-filter/spamassassin-3.2.1-r1  USE="berkdb mysql ssl -doc -ipv6 -ldap -postgres -qmail -sqlite -tools" 959 kB

[ebuild   R   ] app-antivirus/clamav-0.91  USE="bzip2 crypt logrotate -mailwrapper -milter -nls (-selinux)" 0 kB

[ebuild   R   ] mail-filter/amavisd-new-2.4.1  USE="mysql -ldap -milter -postgres" 823 kB

[ebuild   R   ] mail-filter/policyd-weight-0.1.14.4  49 kB

[ebuild   R   ] mail-mta/postfix-2.3.6  USE="mysql pam sasl ssl vda -cdb -dovecot-sasl -hardened -ipv6 -ldap -mailwrapper -mbox -nis -postgres (-selinux)" 2,727 kB
```

Here is output from netstat:

```
tcp        0      0 127.0.0.1:10024         0.0.0.0:*               LISTEN      11890/amavisd (mast

tcp        0      0 127.0.0.1:10025         0.0.0.0:*               LISTEN      11781/master

tcp        0      0 127.0.0.1:12525         0.0.0.0:*               LISTEN      9719/policyd-weight
```

Here is output from ps:

```
polw      9719  0.0  0.3   7296  5276 ?        Ss   13:26   0:00 policyd-weight (master)

polw      9754  0.1  0.3   7560  5912 ?        S    13:26   0:03 policyd-weight (child)

polw     13879  0.0  0.3   7556  5804 ?        S    14:00   0:00 policyd-weight (child)

polw     14109  0.0  0.3   7560  5856 ?        S    14:02   0:00 policyd-weight (child)

polw     27389  0.0  0.3   7428  5412 ?        Ss   11:13   0:00 policyd-weight (cache)

amavis   11890  0.0  4.1  73464 64696 ?        Ss   Jul18   0:20 amavisd (master)

amavis   12936  2.5  4.7  82628 73484 ?        S    13:53   0:25 amavisd (ch14-avail)

amavis   13387  4.6  4.4  79076 69812 ?        S    13:56   0:36 amavisd (ch9-avail)

amavis   13396  6.9  4.7  83600 74348 ?        S    13:56   0:54 amavisd (ch12-avail)

amavis   14268  7.6  4.7  83660 74272 ?        S    14:04   0:25 amavisd (ch3-avail)

postfix  14652  0.0  0.1   7552  2608 ?        S    14:08   0:00 smtp -n smtp-amavis -t unix -u -c -o smtp_data_done_timeout 1200 -o disable_dns_lookups yes

amavis   20606  0.2  4.8  93772 74800 ?        Ssl  Jul16  31:45 /usr/sbin/clamd

amavis   20618  0.0  0.0   3404  1392 ?        Ss   Jul16   0:40 /usr/bin/freshclam -d
```

Thanks in advance!

hanji

----------

## steveb

 *hanj wrote:*   

> Now.. 3 seconds later...
> 
> ```
> Jul 23 17:15:41 comp.com postfix/smtp[4260]: 7B6635A0A: to=<user1@domain1.com>, relay=localhost[127.0.0.1]:10024, delay=8.4, delays=5.2/0/0.01/3.1, dsn=4.4.2, status=deferred (lost connection with localhost[127.0.0.1] while sending end of data -- message may be sent more than once)
> ```
> ...

 Aha! Port 10024. Sounds like Amavis-New and not Policyd-weight. Correct me if I am wrong?

// SteveB

----------

## hanj

 *steveb wrote:*   

>  *hanj wrote:*   Now.. 3 seconds later...
> 
> ```
> Jul 23 17:15:41 comp.com postfix/smtp[4260]: 7B6635A0A: to=<user1@domain1.com>, relay=localhost[127.0.0.1]:10024, delay=8.4, delays=5.2/0/0.01/3.1, dsn=4.4.2, status=deferred (lost connection with localhost[127.0.0.1] while sending end of data -- message may be sent more than once)
> ```
> ...

 

Talk about being right in front of my face! Yep. That's amavis for sure. Now... what do you think the deal is? Do you have any ideas/suggestions for this? As I type, I still have them in my queue (the only two messages stuck in the queue all day).

Thanks SteveB... I feel much better since you replied!!!

hanji

----------

## steveb

Do you have pfqueue installed on your system? If so, then start it and press ENTER over the message and you will se the message headers and body. Do you see anything special there? Could you post the content of the message? Maybe directly form /var/spool/postfix/deferred/ ?

// SteveB

----------

## hanj

 *steveb wrote:*   

> Do you have pfqueue installed on your system? If so, then start it and press ENTER over the message and you will se the message headers and body. Do you see anything special there? Could you post the content of the message? Maybe directly form /var/spool/postfix/deferred/ ?
> 
> // SteveB

 

Wow.. pfqueue rules! Thanks for pointing me to that. Looks like the HTML message stops in the middle (incomplete). Could that be the problem?? I PM'd you  a link to see the message.

Thanks!

hanji

----------

## paintcheck200

I'm having a very familiar issue (even with my.orbitz.com) and I was wondering if you had pinpointed the issue and found a solution.

Thx in advance.

----------

## hanj

 *paintcheck200 wrote:*   

> I'm having a very familiar issue (even with my.orbitz.com) and I was wondering if you had pinpointed the issue and found a solution.
> 
> Thx in advance.

 

I think it's coming down to bad emails. I always will get Orbitz.com newsletters to behave like this.. also MusiciansFriend.com newsletters. I have a feeling they might be causing some problems in the queue, usually after I delete them, everything returns back to normal. You can see the incomplete emails with pfqueue.

Now, I'm running into a weird problem with unrar and amavis.. do you see similar errors?

https://forums.gentoo.org/viewtopic-t-573604-highlight-unrar.html

HTH

hanji

----------

