Dotaz: Postfix hlasi RSET

[pepek]

Zdravim.
Resim jeden problem. Provozuji aplikaci zalozenou na php fusion. Tato app jela na vyvojovem serveru na Debianu (bez problemu). Nyni nastal cas na migraci do produkce, coz je primarne SUNovsky zelezo a Solaris 10. Migrace probehla v pohode az na jednu vec. Pokud z teto app je potreba odeslat email (postfix 2.6.2) logy hlasi:

postfix/smtpd[26768]: [ID 197553 mail.info] connect from (hostname)[192.168.1.5]
postfix/smtpd[26768]: [ID 197553 mail.info] lost connection after RSET from (hostname)[192.168.1.5]
postfix/smtpd[26768]: [ID 197553 mail.info] disconnect from (hostname)[192.168.1.5]

Nalezl jsem podobny dotaz, ktery tu uz byl, ale nebyl zodpovezen. Zde.
Chovani je velice podobne, posta z konzole ci jineho mailklienta (squirell, thunderbird ad.) chodi bez problemu. Domnivam se, ze asi bude problem nekde v php a nejakejch konekci ci modulu na postfix, nebo ne? Dekuji za pripadne odpovedi.

PS: Co presne si mam pod touto hlaskou predstavit? Prijde mi hodne obecna.

Odpovědi

[Martin H.]

Napadla mě jedna věc: možná máš nějaké restrikce pro SMTP v Postfixu a máš je ve špatném pořadí - aplikace není autorizována jako klient s možností posílat bez ověření a proto se aplikuje pravidlo autentizace SMTP.

Bohužel tvůj dotaz je velice obecný.

Viděl bych to tak, že PHP odesílá ze 127.0.0.1, ale localhost není v RELAY ... nebo naopak síť 192 ... není v RELAY a klenti používají SMTP autorizaci (stejné jméno a heslo, jako k POP3/IMAP).

Jen střílím od boku ... prověř to.

Příkaz říká, že klient ukončil spojení ihned po navázání spojení.

[pepek]

No asi odtud bude vitr foukat, ale trochu mi to prosim upresni.

Relay mam nastaven pro localhost (mynetworks_style = host) pokud zmenim mynetworks_style = class tak ze stejne site maily chodej taky:
telnet 192.168.1.5 25
Trying 192.168.1.5...
Connected to 192.168.1.5.
Escape character is '^]'.
220 hostname.mydomain.cz ESMTP Postfix
HELO localhost
250 hostname.domain.cz
MAIL FROM:novak@mydomain.cz
250 2.1.0 Ok
RCPT TO:pepek@domain.cz
250 2.1.5 Ok
DATA
354 End data with .
ggg
.
250 2.0.0 Ok: queued as 92B5347604
quit

Nicmene, pokud zkusim z app tak opet nic.
POP/IMAP autorizuji klasicky proti passwd, shadow. SMTP autorizaci nepouzivam. Prave pt je mi to divny. Jedina restrikce, kterou mam je relay pouze na localhost. Jeste jsem koukal na vlastnictvi te app, ale to je take v poradku. Jine bezici app na serveru problem s odesilanim posty nemaji. Takze tak nejak tapu, zda je to nejaka restrikce v postfixu, nebo neco v te aplikaci.

[Kriegel]

Takhle je to koukani do koule...

 

Hod sem vystup

postconf -n

pak do main.cf dej

debug_peer_list = cl.ie.nt.IP

popr uprav verbosity level

debug_peer_level = 5

a postni log

[Pavel]

postconf -n :

command_directory = /usr/sbin
config_directory = /etc/postfix
daemon_directory = /usr/libexec/postfix
data_directory = /var/lib/postfix
debug_peer_level = 5
debug_peer_list = 127.0.0.1
html_directory = no
mail_owner = postfix
mailq_path = /usr/bin/mailq
manpage_directory = /usr/share/man
message_size_limit = 20480000
mydestination = $myhostname, localhost.$mydomain, localhost, $mydomain, mail.$mydomain, www.$mydomain, ftp.$mydomain
mydomain = domena.cz
myhostname = hostname.domena.cz
mynetworks_style = host
myorigin = $mydomain
newaliases_path = /usr/bin/newaliases
queue_directory = /var/spool/postfix
readme_directory = no
sample_directory = /etc/postfix
sendmail_path = /usr/lib/sendmail
setgid_group = postdrop
smtpd_timeout = 100
unknown_local_recipient_reject_code = 550

A vystup z logu:

Feb 10 13:15:46 hostname postfix/smtpd[28318]: [ID 197553 mail.info] connect from hostname[192.168.1.5]
Feb 10 13:15:46 hostname postfix/smtpd[28318]: [ID 197553 mail.info] lost connection after RSET from hostname[192.168.1.5]
Feb 10 13:15:46 hostname postfix/smtpd[28318]: [ID 197553 mail.info] disconnect from hostname[192.168.1.5]

[Kriegel]

debug_peer_list = 192.168.1.5

a samozrejme postfix reload

pak by to do logu melo sypat neco vic...

[pepek]

Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] connect from sun1[192.168.1.5]
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] match_hostname: sun1 ~? 127.0.0.1/32
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] match_hostaddr: 192.168.1.5 ~? 127.0.0.1/32
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] match_hostname: sun1 ~? 192.168.1.5/32
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] match_hostaddr: 192.168.1.5 ~? 192.168.1.5/32
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] > sun1[192.168.1.5]: 220 hostname.domena.cz ESMTP Postfix
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] watchdog_pat: a72f8
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] vstream_fflush_some: fd 12 flush 47
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] vstream_buf_get_ready: fd 12 got 28
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] < sun1[192.168.1.5]: EHLO www.domena.cz
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] > sun1[192.168.1.5]: 250-hostname.domena.cz
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] > sun1[192.168.1.5]: 250-PIPELINING
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] > sun1[192.168.1.5]: 250-SIZE 20480000
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] > sun1[192.168.1.5]: 250-VRFY
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] match_list_match: sun1: no match
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] match_list_match: 192.168.1.5: no match
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] > sun1[192.168.1.5]: 250-ETRN
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] > sun1[192.168.1.5]: 250-ENHANCEDSTATUSCODES
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] > sun1[192.168.1.5]: 250-8BITMIME
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] > sun1[192.168.1.5]: 250 DSN
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] watchdog_pat: a72f8
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] vstream_fflush_some: fd 12 flush 136
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] vstream_buf_get_ready: fd 12 got 12
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] < sun1[192.168.1.5]: AUTH LOGIN
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] match_string: AUTH ~? CONNECT
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] match_string: AUTH ~? GET
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] match_string: AUTH ~? POST
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] match_list_match: AUTH: no match
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] > sun1[192.168.1.5]: 502 5.5.2 Error: command not recognized
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] watchdog_pat: a72f8
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] vstream_fflush_some: fd 12 flush 41
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] vstream_buf_get_ready: fd 12 got 6
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] < sun1[192.168.1.5]: RSET
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] > sun1[192.168.1.5]: 250 2.0.0 Ok
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] watchdog_pat: a72f8
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] vstream_fflush_some: fd 12 flush 14
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] smtp_get: EOF
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] match_hostname: sun1 ~? 127.0.0.1/32
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] match_hostaddr: 192.168.1.5 ~? 127.0.0.1/32
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] match_hostname: sun1 ~? 192.168.1.5/32
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] match_hostaddr: 192.168.1.5 ~? 192.168.1.5/32
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] lost connection after RSET from sun1[192.168.1.5]
Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] disconnect from sun1[192.168.1.5]

[Kriegel]

(1) Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] < sun1[192.168.1.5]: AUTH LOGIN
(2) Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] > sun1[192.168.1.5]: 502 5.5.2 Error: command not recognized
(3) Feb 11 10:06:59 sun1 postfix/smtpd[28617]: [ID 197553 mail.info] < sun1[192.168.1.5]: RSET

Klient se snazi o autentifikaci (1), ale server ho nepodporuje, proto posila 502 ... (2), na coz klient reaguje resetem (3)  a ukonci session

 

Resenim je bud

a) zprovoznit na serveru overovani, pak zacni tady http://www.postfix.org/postconf.5.html#smtp_sasl_auth_enable nebo

b) donutit klienta, aby nemel potrebu se autentifikovat

[pepek]

Myslel jsem si to po precteni tech logu

Preferoval bych moznost b, ale to tedy znamena prepsat prislusnou cast v aplikaci?

[Kriegel]

Tak pak podle preferenci :)

Vzhledem k tomu, ze to fungovalo driv, tak na tom testovacim serveru muselo byt a nebo b...

[Kriegel]

reseni mozna najdes tady http://www.php-fusion.co.uk/print.php?type=F&thread=24556

public $SMTPAuth=0;

[pepek]

Jj, zatim dik za rady. Kontroloval jsem jeste postfix a zkompilovanej je s podporou ssl. Takze jeste se ozvu jak jsem pokrocil.....

[Martin H.]

To nemá nic společného se SSL, ale SASL ...

Doporučil bych to vypnout, jak je nabízeno výše ...

[pepek]

Ahoj, tak jsem to prosel. Je evidentni, ze php-fusion pouziva k odesilani mailu php-mailer
Primarni soubory, ktere to ridi jsou: class.phpmailer.php a class.smtp.php
Bohuzel kdyz jsem je prolezl, tak $SMTPAuth se nachazi v prvnim jmenovanem, ale ma hodnotu: var $SMTPAuth = false;
Pokud ji zmenim na public $SMTPAuth=0; nebo var $SMTPAuth=0; vysledek je stale stejny. Nebo je to jeste nekde jinde? Nevite, kde ta autentizace je ve fusionu zadratovana?