Re: 1.4: Emails to BCC addresses not sent

[Melvyn Sopacua]

On 5-7-2012 19:44, Javi Romero wrote:
> Hi list, I'm new around though I've been developing Django sites since the
> early 1.0 releases
>
> I've been looking around for problems regarding email sending to BCC
> addresses but can't find anything that explains what I'm seeing.

You've included a lot of information, except the mail log on the MTA
that django connects to and that's the crucial thing. You'll need to
verify if the bcc addresses are showing up to determine the guilty party.

Also, if you bcc something to a recipient already in the recipient list,
it is not guaranteed they receive two copies and even more likely that
they don't, so use addresses you know are good but not in the list already.
--
Melvyn Sopacua

[Javi Romero]

Hello Melvyn, thank you for your input. I've requested the log to the production server's support team to provide further context.

In the meanwhile, is there any other relevant data I can provide from my development machine? I'll be more than glad to shed some light on this.

[Javi Romero]

As usual, the webfaction support team is impresive in its support. Here's the extract from the mail log after sending the contact form. As it can be seen, there is no trace of bcc addresses. Also, the addresses to be bcc'ed are not the same that the one on the "To" field.

Jul 5 11:15:56 mail6 postfix/smtpd[24001]: 1A216210E8AE: client=web317.webfaction.com[85.17.23.88], sasl_method=CRAM-MD5, sasl_username=bat...@smtp.webfaction.com
Jul 5 11:15:56 mail6 postfix/cleanup[23507]: 1A216210E8AE: message-id=<2012070516155...@web317.webfaction.com>
Jul 5 11:15:56 mail6 postfix/qmgr[3022]: 1A216210E8AE: from=<dire...@cremaycosmeticanatural.es>, size=1416, nrcpt=1 (queue active)
Jul 5 11:16:26 mail6 postfix/smtp[23745]: 1A216210E8AE: to=<te...@example.org>, relay=none, delay=30, delays=0.39/0/30/0, dsn=4.4.1, status=deferred (connect to example.org[192.0.43.10]: Connection timed out)
Jul 5 11:46:05 mail6 postfix/qmgr[3022]: 1A216210E8AE: from=<dire...@cremaycosmeticanatural.es>, size=1416, nrcpt=1 (queue active)
Jul 5 11:47:00 mail6 postfix/smtp[25697]: 1A216210E8AE: to=<te...@example.org>, relay=none, delay=1864, delays=1809/25/30/0, dsn=4.4.1, status=deferred (connect to example.org[192.0.43.10]: Connection timed out)
Jul 5 12:19:22 mail6 postfix/qmgr[3022]: 1A216210E8AE: from=<dire...@cremaycosmeticanatural.es>, size=1416, nrcpt=1 (queue active)
Jul 5 12:20:02 mail6 postfix/smtp[27946]: 1A216210E8AE: to=<te...@example.org>, relay=none, delay=3847, delays=3806/10/30/0, dsn=4.4.1, status=deferred (connect to example.org[192.0.43.10]: Connection timed out)
Jul 5 13:26:00 mail6 postfix/qmgr[3022]: 1A216210E8AE: from=<dire...@cremaycosmeticanatural.es>, size=1416, nrcpt=1 (queue active)
Jul 5 13:27:00 mail6 postfix/smtp[4785]: 1A216210E8AE: to=<te...@example.org>, relay=none, delay=7864, delays=7804/30/30/0, dsn=4.4.1, status=deferred (connect to example.org[192.0.43.10]: Connection timed out)
Jul 5 14:49:20 mail6 postfix/qmgr[3022]: 1A216210E8AE: from=<dire...@cremaycosmeticanatural.es>, size=1416, nrcpt=1 (queue active)
Jul 5 14:50:08 mail6 postfix/smtp[16526]: 1A216210E8AE: to=<te...@example.org>, relay=none, delay=12853, delays=12804/18/30/0, dsn=4.4.1, status=deferred (connect to example.org[192.0.43.10]: Connection timed out)
Jul 5 16:12:40 mail6 postfix/qmgr[3022]: 1A216210E8AE: from=<dire...@cremaycosmeticanatural.es>, size=1416, nrcpt=1 (queue active)
Jul 5 16:13:40 mail6 postfix/smtp[23562]: 1A216210E8AE: to=<te...@example.org>, relay=none, delay=17864, delays=17804/30/30/0, dsn=4.4.1, status=deferred (connect to example.org[192.0.43.10]: Connection timed out)
Jul 5 17:36:00 mail6 postfix/qmgr[3022]: 1A216210E8AE: from=<dire...@cremaycosmeticanatural.es>, size=1416, nrcpt=1 (queue active)
Jul 5 17:37:00 mail6 postfix/smtp[2988]: 1A216210E8AE: to=<te...@example.org>, relay=none, delay=22864, delays=22804/30/30/0, dsn=4.4.1, status=deferred (connect to example.org[192.0.43.10]: Connection timed out)
Jul 5 18:59:20 mail6 postfix/qmgr[3022]: 1A216210E8AE: from=<dire...@cremaycosmeticanatural.es>, size=1416, nrcpt=1 (queue active)
Jul 5 19:00:11 mail6 postfix/smtp[11827]: 1A216210E8AE: to=<te...@example.org>, relay=none, delay=27856, delays=27804/30/21/0, dsn=4.4.1, status=deferred (connect to example.org[192.0.43.10]: Connection refused)
Jul 5 20:22:42 mail6 postfix/qmgr[3022]: 1A216210E8AE: from=<dire...@cremaycosmeticanatural.es>, size=1416, nrcpt=1 (queue active)
Jul 5 20:23:41 mail6 postfix/smtp[18908]: 1A216210E8AE: to=<te...@example.org>, relay=none, delay=32865, delays=32806/28/30/0, dsn=4.4.1, status=deferred (connect to example.org[192.0.43.10]: Connection timed out)
Jul 5 21:46:00 mail6 postfix/qmgr[3022]: 1A216210E8AE: from=<dire...@cremaycosmeticanatural.es>, size=1416, nrcpt=1 (queue active)
Jul 5 21:47:00 mail6 postfix/smtp[28019]: 1A216210E8AE: to=<te...@example.org>, relay=none, delay=37864, delays=37804/30/30/0, dsn=4.4.1, status=deferred (connect to example.org[192.0.43.10]: Connection timed out)
Jul 5 23:09:20 mail6 postfix/qmgr[3022]: 1A216210E8AE: from=<dire...@cremaycosmeticanatural.es>, size=1416, nrcpt=1 (queue active)
Jul 5 23:10:02 mail6 postfix/smtp[6562]: 1A216210E8AE: to=<te...@example.org>, relay=none, delay=42846, delays=42805/32/9.3/0, dsn=4.4.1, status=deferred (connect to example.org[192.0.43.10]: Connection refused)
Jul 6 00:32:40 mail6 postfix/qmgr[3022]: 1A216210E8AE: from=<dire...@cremaycosmeticanatural.es>, size=1416, nrcpt=1 (queue active)
Jul 6 00:33:40 mail6 postfix/smtp[15683]: 1A216210E8AE: to=<te...@example.org>, relay=none, delay=47865, delays=47805/30/30/0, dsn=4.4.1, status=deferred (connect to example.org[192.0.43.10]: Connection timed out)
Jul 6 01:56:00 mail6 postfix/qmgr[3022]: 1A216210E8AE: from=<dire...@cremaycosmeticanatural.es>, size=1416, nrcpt=1 (queue active)
Jul 6 01:57:00 mail6 postfix/smtp[24233]: 1A216210E8AE: to=<te...@example.org>, relay=none, delay=52864, delays=52804/30/30/0, dsn=4.4.1, status=deferred (connect to example.org[192.0.43.10]: Connection timed out)
Jul 6 03:19:20 mail6 postfix/qmgr[3022]: 1A216210E8AE: from=<dire...@cremaycosmeticanatural.es>, size=1416, nrcpt=1 (queue active)
Jul 6 03:20:21 mail6 postfix/smtp[315]: 1A216210E8AE: to=<te...@example.org>, relay=none, delay=57865, delays=57805/30/30/0, dsn=4.4.1, status=deferred (connect to example.org[192.0.43.10]: Connection timed out)

Does this sound like I should open a new ticket on the bugtracker or does this work right for anyone else?

[Melvyn Sopacua]

On 6-7-2012 11:36, Javi Romero wrote:
> Does this sound like I should open a new ticket on the bugtracker or does
> this work right for anyone else?

It definitely works for me, when I do some testing with the EmailMessage
object. You should reduce your testing to just sending a simple message
with the EmailMessage class, like:
from django.core.mail import EmailMessage

msg = EmailMessage(
subject='test',
to=['m...@example.org'],
bcc=['now...@example.org'],
body='test'
)
msg.send()

If that fails as well, I guess a ticket is in order, but like I said
"works for me" (in version 1.4).
If that doesn't fail, then make sure cco is filled.
--
Melvyn Sopacua

[Javi Romero]

El viernes, 6 de julio de 2012 12:59:23 UTC+2, Melvyn Sopacua escribió:

On 6-7-2012 11:36, Javi Romero wrote:
> Does this sound like I should open a new ticket on the bugtracker or does
> this work right for anyone else?

It definitely works for me, when I do some testing with the EmailMessage
object. You should reduce your testing to just sending a simple message
with the EmailMessage class, like:
from django.core.mail import EmailMessage

msg = EmailMessage(
        subject='test',
        to=['m...@example.org'],

        bcc=['nowhere@example.org'],

        body='test'
)
msg.send()

If that fails as well, I guess a ticket is in order, but like I said
"works for me" (in version 1.4).
If that doesn't fail, then make sure cco is filled.
--
Melvyn Sopacua

Well I just tested this again on a clean project, with only that code and a HttpResponse as return value on a single view, on both Django 1.3 and 1.4, on my usual development machine (Archlinux) and on a fresh VirtualBox install of Kubuntu 12.04

The only thing that I can think of that all the setups also have in common is python2.7 and the use of virtualenv, but even if I install django as a system package, I get the same output:

1.4

$ python2 manage.py runserver

Validating models...

0 errors found

Django version 1.4, using settings 'bcc.settings'

Development server is running at http://127.0.0.1:8000/

Quit the server with CONTROL-C.

Content-Type: text/plain; charset="utf-8"

MIME-Version: 1.0

Content-Transfer-Encoding: 7bit

Subject: test

From: webmaster@localhost

To: m...@example.org

Date: Fri, 06 Jul 2012 12:01:03 -0000

Message-ID: <20120706120103.4768.10823@k-VirtualBox>

test

-------------------------------------------------------------------------------

[06/Jul/2012 07:01:03] "GET / HTTP/1.1" 200 10

1.3

$ python2 manage.py runserver

Validating models...

0 errors found

Django version 1.3.1, using settings 'bcc13.settings'

Development server is running at http://127.0.0.1:8000/

Quit the server with CONTROL-C.

Content-Type: text/plain; charset="utf-8"

MIME-Version: 1.0

Content-Transfer-Encoding: quoted-printable

Subject: test

From: webmaster@localhost

To: m...@example.org

Date: Fri, 06 Jul 2012 12:12:08 -0000

Message-ID: <20120706121208.5531.28602@k-VirtualBox>

test

-------------------------------------------------------------------------------

[06/Jul/2012 07:12:08] "GET / HTTP/1.1" 200 10

Thank you very much for your cooperation, I'll open a bug and try to help finding out whats wrong :-).

[Thomas Lockhart]

...

If that fails as well, I guess a ticket is in order, but like I said
"works for me" (in version 1.4).
If that doesn't fail, then make sure cco is filled.

fwiw it works for me too in 1.4 using virtualenv. Thanks Melvyn for the simple example.

                 - Tom

[Javi Romero]

Thank you for checking it out Tom. I wonder what may be the problem, this is puzzling me :-(