Bug in hmailserver ? Inversion of the recipients

Use this forum if you have installed hMailServer and want to ask a question related to a production release of hMailServer. Before posting, please read the troubleshooting guide. A large part of all reported issues are already described in detail here.
Post Reply
Julien@TLD
Normal user
Normal user
Posts: 53
Joined: 2005-09-12 11:57
Location: Marseille - France

Bug in hmailserver ? Inversion of the recipients

Post by Julien@TLD » 2006-03-13 16:27

Hello,

First, thanks you Martin for hMailserver 4.2. It works very well since I installed it one month ago.

But three days ago, I received an email from a new member of my website who signal me a problem and I think there is a bug in hMailserver.

For the subscription to my website, I send an email with a link to confirm the email adress. In fact, this new member who contact me has received the email of confirmation of an other member and so has access to his password, personal information...!!! After verification, I saw that this two persons have registered to my website exactly at the same time (in the same second). I verified my PHP script which send the email of confirmation and I can’t reproduce this bug. Execution of the subscription script for user A and user B is totaly independent in PHP so this bug is not linked to my script. I think it’s a hMailserver bug which has inversed the two recipients.

Below the log corresponding to the sending of this two emails to the two members. Have you an idea martin? It is perhaps due to the method for identify different emails/recipients?

The server is under Windows Server 2003 SP1 + IIS 6.0 + PHP 5.1.2 + MySQL 4.1.18 + hMailserver 4.2 build 195.

"SMTPD" 1380 "2006-03-09 23:29:18.750" "212.94.176.153" "SENT: 421 Connection timeout.[nl]"
"SMTPD" 1380 "2006-03-09 23:29:41.015" "212.94.176.153" "SENT: 220 SMTP"
"SMTPD" 1380 "2006-03-09 23:29:41.015" "212.94.176.153" "RECEIVED: HELO tld"
"SMTPD" 1380 "2006-03-09 23:29:41.015" "212.94.176.153" "SENT: 250 Hello."
"SMTPD" 1380 "2006-03-09 23:29:41.015" "212.94.176.153" "RECEIVED: MAIL FROM:<mail@myserver.com>"
"SMTPD" 1564 "2006-03-09 23:29:42.593" "212.94.176.153" "SENT: 220 SMTP"
"SMTPD" 1564 "2006-03-09 23:29:42.593" "212.94.176.153" "RECEIVED: HELO tld"
"SMTPD" 1564 "2006-03-09 23:29:42.593" "212.94.176.153" "SENT: 250 Hello."
"SMTPD" 1564 "2006-03-09 23:29:42.593" "212.94.176.153" "RECEIVED: MAIL FROM:<mail@myserver.com>"
"SMTPD" 1380 "2006-03-09 23:29:46.015" "212.94.176.153" "SENT: 250 OK"
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "SENT: 250 OK"
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "RECEIVED: RCPT TO:<xxxxxx@numericable.fr>"
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "SENT: 250 OK"
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "RECEIVED: RCPT TO:<yyyyyy@aol.com>"
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "SENT: 250 OK"
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "RECEIVED: DATA"
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "SENT: 354 OK, send."
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "SENT: 250 Queued (0.000 seconds)"
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "RECEIVED: Date: Thu, 09 Mar 2006 23:29:47 +0100"
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "SENT: 502 unimplemented command."
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "RECEIVED: Subject: Inscription à myserver.com"
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "SENT: 502 unimplemented command."
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "RECEIVED: To: yyyyyy@aol.com"
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "SENT: 502 unimplemented command."
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "RECEIVED: From: mail@myserver.com"
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "SENT: 502 unimplemented command."
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "RECEIVED: Content-Type: text/plain; Charset=iso-8859-1;"
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "SENT: 502 unimplemented command."
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "RECEIVED: "
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "SENT: 502 unimplemented command."
"SMTPC" 232 "2006-03-09 23:29:49.125" "205.188.159.217" "RECEIVED: 220-rly-yh05.mx.aol.com ESMTP mail_relay_in-yh5.5; Thu, 09 Mar 2006 17:28:54 -0500"
"SMTPC" 232 "2006-03-09 23:29:49.125" "205.188.159.217" "RECEIVED: 220-America Online (AOL) and its affiliated companies do not"
"SMTPC" 232 "2006-03-09 23:29:49.125" "205.188.159.217" "RECEIVED: 220- authorize the use of its proprietary computers and computer"
"SMTPC" 232 "2006-03-09 23:29:49.125" "205.188.159.217" "RECEIVED: 220- networks to accept, transmit, or distribute unsolicited bulk"
"SMTPC" 232 "2006-03-09 23:29:49.125" "205.188.159.217" "RECEIVED: 220- e-mail sent from the internet. Effective immediately: AOL "
"SMTPC" 232 "2006-03-09 23:29:49.125" "205.188.159.217" "RECEIVED: 220- may no longer accept connections from IP addresses which "
"SMTPC" 232 "2006-03-09 23:29:49.125" "205.188.159.217" "RECEIVED: 220 have no reverse-DNS (PTR record) assigned."
"SMTPC" 232 "2006-03-09 23:29:49.125" "205.188.159.217" "SENT: HELO tld1.myserver.com"
"SMTPC" 232 "2006-03-09 23:29:49.218" "205.188.159.217" "RECEIVED: 250 rly-yh05.mx.aol.com OK"
"SMTPC" 232 "2006-03-09 23:29:49.218" "205.188.159.217" "SENT: MAIL FROM:<mail@myserver.com>"
"SMTPC" 232 "2006-03-09 23:29:49.421" "205.188.159.217" "RECEIVED: 250 OK"
"SMTPC" 232 "2006-03-09 23:29:49.421" "205.188.159.217" "SENT: RCPT TO:<yyyyyy@aol.com>"
"SMTPC" 232 "2006-03-09 23:29:49.531" "205.188.159.217" "RECEIVED: 250 OK"
"SMTPC" 232 "2006-03-09 23:29:49.531" "205.188.159.217" "SENT: DATA"
"SMTPC" 232 "2006-03-09 23:29:49.640" "205.188.159.217" "RECEIVED: 354 START MAIL INPUT, END WITH "." ON A LINE BY ITSELF"
"SMTPC" 232 "2006-03-09 23:29:49.640" "205.188.159.217" "SENT: [nl]."
"SMTPC" 232 "2006-03-09 23:29:49.937" "205.188.159.217" "RECEIVED: 250 OK"
"SMTPC" 232 "2006-03-09 23:29:49.937" "205.188.159.217" "SENT: QUIT"
"SMTPC" 232 "2006-03-09 23:29:51.062" "80.236.0.232" "RECEIVED: 220 ichbiach.numericable.net ESMTP"
"SMTPC" 232 "2006-03-09 23:29:51.062" "80.236.0.232" "SENT: HELO tld1.myserver.com"
"SMTPC" 232 "2006-03-09 23:29:51.078" "80.236.0.232" "RECEIVED: 250 ichbiach.numericable.net"
"SMTPC" 232 "2006-03-09 23:29:51.078" "80.236.0.232" "SENT: MAIL FROM:<mail@myserver.com>"
"SMTPC" 232 "2006-03-09 23:29:51.203" "80.236.0.232" "RECEIVED: 250 ok"
"SMTPC" 232 "2006-03-09 23:29:51.203" "80.236.0.232" "SENT: RCPT TO:<xxxxxx@numericable.fr>"
"SMTPC" 232 "2006-03-09 23:29:51.250" "80.236.0.232" "RECEIVED: 250 ok"
"SMTPC" 232 "2006-03-09 23:29:51.250" "80.236.0.232" "SENT: DATA"
"SMTPC" 232 "2006-03-09 23:29:51.250" "80.236.0.232" "RECEIVED: 354 go ahead"
"SMTPC" 232 "2006-03-09 23:29:51.250" "80.236.0.232" "SENT: [nl]."
"SMTPC" 232 "2006-03-09 23:29:51.453" "80.236.0.232" "RECEIVED: 250 ok 1141943336 qp 28243"
"SMTPC" 232 "2006-03-09 23:29:51.453" "80.236.0.232" "SENT: QUIT"
"SMTPD" 1564 "2006-03-09 23:31:25.812" "212.94.179.247" "SENT: 220 SMTP"
"SMTPD" 1564 "2006-03-09 23:31:25.812" "212.94.179.247" "RECEIVED: HELO noc1"
"SMTPD" 1564 "2006-03-09 23:31:25.812" "212.94.179.247" "SENT: 250 Hello."
"SMTPD" 1564 "2006-03-09 23:31:25.828" "212.94.179.247" "RECEIVED: MAIL FROM: "
"SMTPD" 1564 "2006-03-09 23:31:25.828" "212.94.179.247" "SENT: 550 sender address must be specified."
"SMTPD" 1564 "2006-03-09 23:31:25.828" "212.94.179.247" "RECEIVED: QUIT"
"SMTPD" 1564 "2006-03-09 23:31:25.828" "212.94.179.247" "SENT: 221 goodbye"

User avatar
martin
Developer
Developer
Posts: 6834
Joined: 2003-11-21 01:09
Location: Sweden
Contact:

Post by martin » 2006-03-13 18:25

That logs show that someone tries to send the same email to two different receipients. The client issues RCTP TO twice in the same session which means that the two recipients will receive the same email.

Further, the log shows that the sending client doesn't wait for the DATA response from the server before trying to submit the email.

Julien@TLD
Normal user
Normal user
Posts: 53
Joined: 2005-09-12 11:57
Location: Marseille - France

Post by Julien@TLD » 2006-03-13 19:45

Thanks you Martin for the answer and for the explanation of the log. But I am a bit disapointed :) In my PHP subscription script I have only one call to the mail() function with only one email address as recipient parameter (no loops or other things like this). And data comes from the POST and not from database or an other part. I do not understand how the PHP script can send the same email to the two different members. Two PHP scripts executed simulteanously can not exchange data via the server memory :D For me the problem seems to arrive later when hMailserver threats the two simultaneous emails.

An idea to investigate on this problem?

User avatar
martin
Developer
Developer
Posts: 6834
Joined: 2003-11-21 01:09
Location: Sweden
Contact:

Post by martin » 2006-03-13 20:53

Well it does look a bit strange.
"SMTPD" 1380 "2006-03-09 23:29:41.015" "212.94.176.153" "SENT: 220 SMTP"
"SMTPD" 1380 "2006-03-09 23:29:41.015" "212.94.176.153" "RECEIVED: HELO tld"
"SMTPD" 1380 "2006-03-09 23:29:41.015" "212.94.176.153" "SENT: 250 Hello."
"SMTPD" 1380 "2006-03-09 23:29:41.015" "212.94.176.153" "RECEIVED: MAIL FROM:<mail@myserver.com>"
"SMTPD" 1564 "2006-03-09 23:29:42.593" "212.94.176.153" "SENT: 220 SMTP"
"SMTPD" 1564 "2006-03-09 23:29:42.593" "212.94.176.153" "RECEIVED: HELO tld"
"SMTPD" 1564 "2006-03-09 23:29:42.593" "212.94.176.153" "SENT: 250 Hello."
"SMTPD" 1564 "2006-03-09 23:29:42.593" "212.94.176.153" "RECEIVED: MAIL FROM:<mail@myserver.com>"
"SMTPD" 1380 "2006-03-09 23:29:46.015" "212.94.176.153" "SENT: 250 OK"
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "SENT: 250 OK"
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "RECEIVED: RCPT TO:<xxxxxx@numericable.fr>"
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "SENT: 250 OK"
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "RECEIVED: RCPT TO:<yyyyyy@aol.com>"
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "SENT: 250 OK"
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "RECEIVED: DATA"
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "SENT: 354 OK, send."
"SMTPD" 1564 "2006-03-09 23:29:47.593" "212.94.176.153" "SENT: 250 Queued (0.000 seconds)"
This log shows that two connections are opened, with ID 1380 and 1564. There's a MAIL FROM on both connections, but both the RCPT TO's are made on ID 1564.

Have you written the PHP script yourself?

Are you running PHP as CGI, or are you running it as an ISAPI module (or whatever it's called; "non-cgi").

Julien@TLD
Normal user
Normal user
Posts: 53
Joined: 2005-09-12 11:57
Location: Marseille - France

Post by Julien@TLD » 2006-03-14 09:20

Yes I wrote the PHP script myself and I use it from 2 or 3 three years obviously without any problem.

Per information, at the end of the script after the mail() function, I insert data (email, pseudo, password...) in the database and for the two members they have in their record the good data (email).

I use PHP 5.1.2 as an ISAPI module in IIS 6.0 and I have no other problem with my scripts.

Thanks you ;)

Julien@TLD
Normal user
Normal user
Posts: 53
Joined: 2005-09-12 11:57
Location: Marseille - France

Post by Julien@TLD » 2006-03-21 11:59

UP

No idea? :(

User avatar
martin
Developer
Developer
Posts: 6834
Joined: 2003-11-21 01:09
Location: Sweden
Contact:

Post by martin » 2006-03-21 20:46

I have absolutely no idéa. I still think this is something in your script / or PHP configuration. The log shows that your script opens two simultaenous TCP/IP connections to the server, but the two RCPT TO commands are sent on the same TCP/IP-connection, which will cause hMailServer to deliver the same message to both recipients.

Post Reply