web scripts can't send to internal recipient

Discussion in 'Installation/Configuration' started by j007w, May 20, 2013.

  1. j007w

    j007w New Member

    Hi,

    None of my web scripts (Wordpress, etc.) can send to internal recipients (users' emails) but can send to external recipients just fine. The email just disappears. In Squirrelmail, users can send to each other internally as well as externally without problems. I tried to have web scripts send out via Google's SMTP but that gave the exact same behavior.

    Perhaps it's related: Wordpress asks for FTP user login information every time I tried to remove a plugin. It also says it can't write to .htaccess. I created the client account, client website and database while logged in as admin in ISPConfig. Did that mess things up?

    Thanks in advance!
     
  2. j007w

    j007w New Member

    maillog

    Hi,

    Here's some recent entries in maillog after I tried to send from website.

    Thanks so much!

    Code:
    May 20 17:02:23 mydomain postfix/local[20304]: ABA443DE23B2: to=<[email protected]>, orig_to=<[email protected]>, relay=local, delay=0.02, delays=0.01/0/0/0, dsn=2.0.0, status=sent (delivered to mailbox)
    May 20 17:02:23 mydomain postfix/qmgr[16507]: ABA443DE23B2: removed
    May 20 17:02:23 mydomain amavis[30222]: (30222-05) Passed CLEAN {RelayedOutbound}, MYNETS LOCAL [127.0.0.1]:48907 [127.0.0.1] <[email protected]> -> <[email protected]>, Message-ID: <[email protected]>, mail_id: 46QUKdovyzY2, Hits: 0.741, size: 1181, queued_as: AD5BD3DE23B4, 614 ms
    May 20 17:02:23 mydomain postfix/smtp[20296]: 0D86A3DE1481: to=<[email protected]>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.69, delays=0.06/0.01/0/0.61, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as AD5BD3DE23B4)
    May 20 17:02:23 mydomain postfix/qmgr[16507]: 0D86A3DE1481: removed
    May 20 17:02:24 mydomain postfix/smtp[20307]: AD5BD3DE23B4: to=<[email protected]>, relay=gmail-smtp-in.l.google.com[2607:f8b0:4002:c04::1b]:25, delay=0.38, delays=0.01/0.01/0.07/0.29, dsn=2.0.0, status=sent (250 2.0.0 OK 1369083744 n50si14271928yhm.281 - gsmtp)
    May 20 17:02:24 mydomain postfix/qmgr[16507]: AD5BD3DE23B4: removed
    May 20 17:03:22 mydomain postfix/anvil[20047]: statistics: max connection rate 1/60s for (smtp:71.241.225.11) at May 20 16:55:37
    May 20 17:03:22 mydomain postfix/anvil[20047]: statistics: max connection count 1 for (smtp:71.241.225.11) at May 20 16:55:37
    May 20 17:03:22 mydomain postfix/anvil[20047]: statistics: max cache size 2 at May 20 16:55:50
    May 20 17:05:02 mydomain dovecot: pop3-login: Disconnected (no auth attempts): rip=::1, lip=::1, secured
    May 20 17:05:02 mydomain dovecot: imap-login: Disconnected (no auth attempts): rip=::1, lip=::1, secured
    May 20 17:05:02 mydomain postfix/smtpd[20377]: connect from localhost[::1]
    May 20 17:05:02 mydomain postfix/smtpd[20377]: lost connection after CONNECT from localhost[::1]
    May 20 17:05:02 mydomain postfix/smtpd[20377]: disconnect from localhost[::1]
    May 20 17:06:34 mydomain dovecot: auth: mysql: Connected to localhost (dbispconfig)
    May 20 17:06:34 mydomain dovecot: imap-login: Login: user=<[email protected]>, method=PLAIN, rip=::1, lip=::1, mpid=20421, secured
    May 20 17:06:34 mydomain dovecot: imap([email protected]): Disconnected: Logged out bytes=44/709
    May 20 17:06:35 mydomain dovecot: imap-login: Login: user=<[email protected]>, method=PLAIN, rip=::1, lip=::1, mpid=20423, secured
    May 20 17:06:35 mydomain dovecot: imap([email protected]): Disconnected: Logged out bytes=399/1723
    May 20 17:06:35 mydomain dovecot: imap-login: Login: user=<[email protected]>, method=PLAIN, rip=::1, lip=::1, mpid=20425, secured
    May 20 17:06:35 mydomain dovecot: imap([email protected]): Disconnected: Logged out bytes=294/2933
    May 20 17:06:39 mydomain dovecot: imap-login: Login: user=<[email protected]>, method=PLAIN, rip=::1, lip=::1, mpid=20427, secured
    May 20 17:06:39 mydomain dovecot: imap([email protected]): Disconnected: Logged out bytes=294/2933
    May 20 17:06:40 mydomain dovecot: imap-login: Login: user=<[email protected]>, method=PLAIN, rip=::1, lip=::1, mpid=20429, secured
    May 20 17:06:40 mydomain dovecot: imap([email protected]): Disconnected: Logged out bytes=79/687
    May 20 17:07:26 mydomain postfix/smtpd[20443]: connect from 187-176-13-68.static.axtel.net[187.176.13.68]
    May 20 17:07:26 mydomain postfix/smtpd[20443]: NOQUEUE: reject: RCPT from 187-176-13-68.static.axtel.net[187.176.13.68]: 554 5.7.1 <[email protected]>: Relay access denied; from=<[email protected]> to=<[email protected]> proto=ESMTP helo=<187-176-13-68.static.axtel.net>
    May 20 17:07:26 mydomain postfix/smtpd[20443]: disconnect from 187-176-13-68.static.axtel.net[187.176.13.68]
    May 20 17:07:36 mydomain postfix/smtpd[20443]: warning: 181.23.131.133: hostname 181-23-131-133.speedy.com.ar verification failed: Name or service not known
    May 20 17:07:36 mydomain postfix/smtpd[20443]: connect from unknown[181.23.131.133]
    May 20 17:07:37 mydomain postfix/smtpd[20443]: NOQUEUE: reject: RCPT from unknown[181.23.131.133]: 554 5.7.1 <[email protected]>: Relay access denied; from=<[email protected]> to=<[email protected]> proto=ESMTP helo=<181-23-131-133.speedy.com.ar>
    May 20 17:07:37 mydomain postfix/smtpd[20443]: disconnect from unknown[181.23.131.133]
    May 20 17:10:01 mydomain dovecot: imap-login: Disconnected (no auth attempts): rip=::1, lip=::1, secured
    May 20 17:10:01 mydomain dovecot: pop3-login: Disconnected (no auth attempts): rip=::1, lip=::1, secured
    May 20 17:10:01 mydomain postfix/smtpd[20526]: connect from localhost[::1]
    May 20 17:10:01 mydomain postfix/smtpd[20526]: lost connection after CONNECT from localhost[::1]
    May 20 17:10:01 mydomain postfix/smtpd[20526]: disconnect from localhost[::1]
    May 20 17:10:57 mydomain postfix/anvil[20445]: statistics: max connection rate 1/60s for (smtp:187.176.13.68) at May 20 17:07:26
    May 20 17:10:57 mydomain postfix/anvil[20445]: statistics: max connection count 1 for (smtp:187.176.13.68) at May 20 17:07:26
    May 20 17:10:57 mydomain postfix/anvil[20445]: statistics: max cache size 2 at May 20 17:07:36
    May 20 17:11:40 mydomain dovecot: imap-login: Login: user=<[email protected]>, method=PLAIN, rip=::1, lip=::1, mpid=20563, secured
    May 20 17:11:40 mydomain dovecot: imap([email protected]): Disconnected: Logged out bytes=79/687
    May 20 17:12:23 mydomain clamd[1158]: SelfCheck: Database status OK.
    May 20 17:14:28 mydomain postfix/smtpd[20612]: connect from host217.201-253-142.telecom.net.ar[201.253.142.217]
    May 20 17:14:29 mydomain postfix/smtpd[20612]: NOQUEUE: reject: RCPT from host217.201-253-142.telecom.net.ar[201.253.142.217]: 554 5.7.1 <[email protected]>: Relay access denied; from=<[email protected]> to=<[email protected]> proto=ESMTP helo=<host217.201-253-142.telecom.net.ar>
    May 20 17:14:29 mydomain postfix/smtpd[20612]: disconnect from host217.201-253-142.telecom.net.ar[201.253.142.217]
    May 20 17:15:01 mydomain postfix/smtpd[20612]: connect from localhost[::1]
    May 20 17:15:01 mydomain postfix/smtpd[20612]: lost connection after CONNECT from localhost[::1]
    May 20 17:15:01 mydomain postfix/smtpd[20612]: disconnect from localhost[::1]
    May 20 17:15:01 mydomain dovecot: imap-login: Disconnected (no auth attempts): rip=::1, lip=::1, secured
    May 20 17:15:01 mydomain dovecot: pop3-login: Disconnected (no auth attempts): rip=::1, lip=::1, secured
    May 20 17:16:41 mydomain dovecot: auth: mysql: Connected to localhost (dbispconfig)
    May 20 17:16:41 mydomain dovecot: imap-login: Login: user=<[email protected]>, method=PLAIN, rip=::1, lip=::1, mpid=20716, secured
    May 20 17:16:41 mydomain dovecot: imap([email protected]): Disconnected: Logged out bytes=79/687
    May 20 17:16:52 mydomain postfix/smtpd[20718]: connect from unknown[190.253.12.135]
    May 20 17:16:52 mydomain postfix/smtpd[20718]: NOQUEUE: reject: RCPT from unknown[190.253.12.135]: 554 5.7.1 <[email protected]>: Relay access denied; from=<[email protected]> to=<[email protected]> proto=ESMTP helo=<[186.114.251.17]>
    May 20 17:16:53 mydomain postfix/smtpd[20718]: disconnect from unknown[190.253.12.135]
     
  3. j007w

    j007w New Member

    still not working

    It's still not working. Does anyone have any suggestions? Thanks so much!
     
  4. monkfish

    monkfish New Member

    You might want to do a live "tail -f /var/log/maillog" on your console at the same time as running the mail script in your browser - the extract from your maillog only seems to show one email processed - at 1702 to your gmail user.

    You could also "tail -f /var/www/<domain>/logs/error.log" see if any particular errors are logged by apache or php when the scripts are running.
     
  5. j007w

    j007w New Member

    new log

    Hi Monkfish,

    Thanks so much for helping me.

    I've done what you said. I ran the command immediately after I tested the web script/form. Here's the result from maillog:

    Code:
    May 23 00:37:01 mydomain postfix/smtpd[30187]: connect from localhost[::1]
    May 23 00:37:01 mydomain postfix/smtpd[30187]: lost connection after CONNECT from localhost[::1]
    May 23 00:37:01 mydomain postfix/smtpd[30187]: disconnect from localhost[::1]
    May 23 00:37:01 mydomain dovecot: imap-login: Disconnected (no auth attempts): rip=::1, lip=::1, secured
    May 23 00:37:01 mydomain dovecot: pop3-login: Disconnected (no auth attempts): rip=::1, lip=::1, secured
    May 23 00:38:01 mydomain postfix/smtpd[30187]: connect from localhost[::1]
    May 23 00:38:01 mydomain postfix/smtpd[30187]: lost connection after CONNECT from localhost[::1]
    May 23 00:38:01 mydomain postfix/smtpd[30187]: disconnect from localhost[::1]
    May 23 00:38:01 mydomain dovecot: pop3-login: Disconnected (no auth attempts): rip=::1, lip=::1, secured
    May 23 00:38:01 mydomain dovecot: imap-login: Disconnected (no auth attempts): rip=::1, lip=::1, secured
    Here's the log from error.log:

    Code:
    [Sat May 18 20:31:26 2013] [error] [client 111.111.111.111] script not found or unable to stat: /var/www/clients/client0/web1/cgi-bin/mailman
    [Sat May 18 22:28:42 2013] [warn] [client 111.111.111.111] mod_fcgid: read data timeout in 360 seconds, referer: http://123.123.123.123/wp-admin/options-general.php?page=wp-mail-smtp%2Fwp_mail_smtp.php&settings-updated=true
    [Sat May 18 22:28:42 2013] [warn] [client 111.111.111.111] (110)Connection timed out: mod_fcgid: ap_pass_brigade failed in handle_request_ipc function, referer: http://123.123.123.123/wp-admin/options-general.php?page=wp-mail-smtp%2Fwp_mail_smtp.php&settings-updated=true
    [Sun May 19 23:10:54 2013] [error] [client 111.111.111.111] attempt to invoke directory as script: /usr/lib/mailman/cgi-bin/
    [Sun May 19 23:12:54 2013] [error] [client 111.111.111.111] script not found or unable to stat: /usr/lib/mailman/cgi-bin/mailman
    [Mon May 20 14:17:35 2013] [warn] [client 111.111.111.111] mod_fcgid: HTTP request length 131420 (so far) exceeds MaxRequestLen (131072), referer: http://mydomain.com/subfolder/index.php
    [Tue May 21 11:40:24 2013] [error] [client 111.111.111.111] suexec policy violation: see suexec log for more details
    [Tue May 21 11:40:24 2013] [error] [client 111.111.111.111] Premature end of script headers: listinfo
    [Tue May 21 11:40:27 2013] [error] [client 111.111.111.111] suexec policy violation: see suexec log for more details
    [Tue May 21 11:40:27 2013] [error] [client 111.111.111.111] Premature end of script headers: listinfo
    Since I saw suexec error, I found the suexec.log and here it is:

    Code:
    [2013-05-23 00:16:08]: uid: (5004/web1) gid: (5005/client0) cmd: .php-fcgi-starter
    [2013-05-23 00:18:11]: uid: (5006/web7) gid: (5007/client2) cmd: .php-fcgi-starter
    [2013-05-23 00:18:39]: uid: (5005/web2) gid: (5006/client1) cmd: .php-fcgi-starter
    [2013-05-23 00:22:04]: uid: (5004/web1) gid: (5005/client0) cmd: .php-fcgi-starter
    [2013-05-23 00:29:17]: uid: (5004/web1) gid: (5005/client0) cmd: .php-fcgi-starter
    [2013-05-23 00:29:24]: uid: (5004/web1) gid: (5005/client0) cmd: .php-fcgi-starter
    [2013-05-23 00:29:24]: uid: (5004/web1) gid: (5005/client0) cmd: .php-fcgi-starter
    [2013-05-23 00:29:24]: uid: (5004/web1) gid: (5005/client0) cmd: .php-fcgi-starter
    [2013-05-23 00:31:55]: uid: (5006/web7) gid: (5007/client2) cmd: .php-fcgi-starter
    [2013-05-23 00:41:05]: uid: (5006/web7) gid: (5007/client2) cmd: .php-fcgi-starter
    [2013-05-23 00:41:08]: uid: (5006/web7) gid: (5007/client2) cmd: .php-fcgi-starter
    [2013-05-23 00:41:44]: uid: (5005/web2) gid: (5006/client1) cmd: .php-fcgi-starter
    [2013-05-23 00:44:00]: uid: (5004/web1) gid: (5005/client0) cmd: .php-fcgi-starter
    [2013-05-23 00:49:37]: uid: (5005/web2) gid: (5006/client1) cmd: .php-fcgi-starter
    [2013-05-23 01:03:08]: uid: (5004/web1) gid: (5005/client0) cmd: .php-fcgi-starter
    
    Thanks again!!!
     
    Last edited: May 23, 2013
  6. monkfish

    monkfish New Member

    Hello,
    The logs you posted narrow it down a little, but timings may be out not reflecting exactly whats occuring.

    - the mail logs only give last few entries, which may have occured after your scripts tried to run. The connection attempts you see to postfix and dovecot are very likely to be the ISPConfig monitor scripts, checking everything is running. From that 1 minute's extract you give, there are no actual mail attempts, suggesting the issue is further back. Either cat /var/log/maillog and look at previous entries or vim /var/log/maillog and step through the log.

    - the apache log you posted suggests you may be using mailman.I don't have cause to use it myself, but I know somewhere there are notes from the ispconfig developers stating that SuExec and CGI must be disabled for the vhost you want to run mailman on. Not sure if this applies to your platform and this is indeed your issue?

    - somewhere in there you also have a few errors from mod_fcgi suggesting data chunks you are submitting are too large for the server to handle due to default settings. Could be coming from your mail package, I certainly got that uploading attachments on one of my initial installs.

    Check out the website options tab in ispconfig, and under apache directives use something like "FcgidMaxRequestLen 5242880" or similar. Save it, and wait for the cron job to process it. You should see that entry placed into the apache vhost file.

    - Lastly are you using wordpress? Seems you have another couple of issues there, again with data lengths / mod_fcgi. Read up on the implications of setting the above line.
     
  7. j007w

    j007w New Member

    Got it working

    Thank you so very much, Monkfish, for helping me!

    I didn't have Mailman when I first installed ISPConfig but later installed it while trying to fix the email problem. I removed it today and email started sending to internal recipients in SquirrelMail. Since we use Google Apps, I added a Wordpress plugin to use Gmail's smtp server for all outgoing email but still couldn't send email to Gmail for internal recipients. I tried setting relay in ISPConfig but couldn't get it to work. They can find them in SquirrelMail, though. At least there's email so I'll try to get all email to go to Gmail in a later date.

    Thanks again. Hope you'll have a great day.
     
  8. monkfish

    monkfish New Member

    Glad you've narrowed it down.

    I think from memory when I did a "post-ispconfig" install of mailman I had to run the ispconfig installation script again to get services reconfigured properly. That could be part of your issue, simply that mail wasnt making it through any postfix/mailman configs properly.

    Not sure that using gmail to relay email to mailboxes held on your server is correct, that may cause some kind of a loop of messaging.

    Be sure your mx records are correct, dns resolves etc and everything is stable. Many moons ago I had a problem with gmail accepting messages from a domain only just set up - so-called "day old bread" for new records.
     

Share This Page