1 Topic by 3m

  • 3m
  • Member
  • Offline
  • Registered: 2013-12-23
  • Posts: 149

Topic: roundcube does not send mail

======== Required information ====
- iRedMail version: 0.9 b3
- Store mail accounts in which backend (LDAP/MySQL/PGSQL): MySQ
- Linux/BSD distribution name and version: FreeBSD 9.3
- Related log if you're reporting an issue:
====

roundcube does not send mail   /var/log/cbpolicyd.log

[2014/10/10-14:58:17 - 1061] [CORE] INFO: Starting "1" children
[2014/10/10-14:58:17 - 1065] [CORE] INFO: 2014/10/10-14:58:17 CONNECT TCP Peer: "[127.0.0.1]:23119" Local: "[127.0.0.1]:10031"
[2014/10/10-14:58:17 - 1208] [CORE] DEBUG: Child Preforked (1208)
[2014/10/10-14:58:17 - 1208] [CBPOLICYD] DEBUG: Starting up caching engine
[2014/10/10-14:58:17 - 1065] [TRACKING] DEBUG: No session tracking data exists for request: $VAR1 = {
          'ccert_fingerprint' => '',
          'sasl_method' => 'LOGIN',
          'sasl_sender' => '',
          'size' => 0,
          '_timestamp' => 1412942297,
          'helo_name' => '_',
          'reverse_client_name' => 'mx',
          'queue_id' => '',
          'encryption_cipher' => 'DHE-RSA-AES256-SHA',
          'encryption_protocol' => 'TLSv1',
          'etrn_domain' => '',
          'ccert_subject' => '',
          'request' => 'smtpd_access_policy',
          'protocol_state' => 'RCPT',
          'stress' => '',
          'sasl_username' => '111@mmm.ua',
          'recipient' => '222@mmm.ua',
          'ccert_pubkey_fingerprint' => '',
          'instance' => '4b4.5437c9d9.7df90.0',
          'protocol_name' => 'ESMTP',
          'encryption_keysize' => '256',
          'recipient_count' => '0',
          'ccert_issuer' => '',
          'sender' => '111@mmm.ua',
          'client_name' => 'mx',
          'client_address' => '127.0.0.1',
          '_protocol_transport' => 'Postfix'
        };
[2014/10/10-14:58:17 - 1065] [TRACKING] DEBUG: Added session tracking information for: $VAR1 = {
          'ccert_fingerprint' => '',
          'sasl_method' => 'LOGIN',
          'sasl_sender' => '',
          'size' => 0,
          '_timestamp' => 1412942297,
          'helo_name' => '_',
          'reverse_client_name' => 'mx',
          'queue_id' => '',
          'encryption_cipher' => 'DHE-RSA-AES256-SHA',
          'encryption_protocol' => 'TLSv1',
          'etrn_domain' => '',
          'ccert_subject' => '',
          'request' => 'smtpd_access_policy',
          'protocol_state' => 'RCPT',
          'stress' => '',
          'sasl_username' => '111@mmm.ua',
          'recipient' => '222@mmm.ua',
          'ccert_pubkey_fingerprint' => '',
          'instance' => '4b4.5437c9d9.7df90.0',
          'protocol_name' => 'ESMTP',
          'encryption_keysize' => '256',
          'recipient_count' => '0',
          'ccert_issuer' => '',
          'sender' => '111@mmm.ua',
          'client_name' => 'mx',
          'client_address' => '127.0.0.1',
          '_protocol_transport' => 'Postfix'
        };
[2014/10/10-14:58:17 - 1065] [TRACKING] DEBUG: Protocol state is 'RCPT', resolving policy...
[2014/10/10-14:58:17 - 1065] [POLICIES] DEBUG: Going to resolve session data into policy: $VAR1 = {
          'Recipient' => '222@mmm.ua',
          'SASLUsername' => '111@mmm.ua',
          'QueueID' => '',
          'RecipientData' => '',
          'Instance' => '4b4.5437c9d9.7df90.0',
          'EncryptionCipher' => 'DHE-RSA-AES256-SHA',
          'Size' => '0',
          'EncryptionKeySize' => '256',
          'EncryptionProtocol' => 'TLSv1',
          'Helo' => '_',
          'ClientAddress' => '127.0.0.1',
          'ClientName' => 'mx',
          'Sender' => '111@mmm.ua',
          'SASLSender' => '',
          'Protocol' => 'ESMTP',
          'ClientReverseName' => 'mx',
          'SASLMethod' => 'LOGIN'
        };
[2014/10/10-14:58:17 - 1065] [POLICIES] DEBUG: Found policy member with ID '2' in policy 'Default Outbound'
[2014/10/10-14:58:17 - 1065] [POLICIES] DEBUG: Found policy member with ID '3' in policy 'Default Inbound'
[2014/10/10-14:58:17 - 1065] [POLICIES] DEBUG: Found policy member with ID '4' in policy 'Default Internal'
[2014/10/10-14:58:17 - 1065] [POLICIES] DEBUG: Found policy member with ID '6' in policy 'whitelists'
[2014/10/10-14:58:17 - 1065] [POLICIES] DEBUG: Found policy member with ID '7' in policy 'blacklists'
[2014/10/10-14:58:17 - 1065] [POLICIES] DEBUG: Found policy member with ID '8' in policy 'no_greylisting'
[2014/10/10-14:58:17 - 1065] [POLICIES] DEBUG: Found policy member with ID '9' in policy 'no_greylisting'
[2014/10/10-14:58:17 - 1065] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]: Main policy sources '%internal_domains'
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]: Group 'internal_domains' has 1 source(s) => @test.km
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]=>(group:internal_domains): - Resolved source '@test.km' to a email address specification, match = 0
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]=>(group:internal_domains): Source group result: matched=0
[2014/10/10-14:58:18 - 1065] [POLICIES] INFO: [ID:2/Name:Default Outbound]: Source matching result: matched=0
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Main policy sources '!%internal_ips,!%internal_domains'
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Group 'internal_ips' has 1 source(s) => 10.0.0.0/8
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_ips): - Resolved source '10.0.0.0/8' to a IP/CIDR specification, match = 0
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_ips): Source group result: matched=0
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Group 'internal_domains' has 1 source(s) => @test.km
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_domains): - Resolved source '@test.km' to a email address specification, match = 0
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_domains): Source group result: matched=0
[2014/10/10-14:58:18 - 1065] [POLICIES] INFO: [ID:3/Name:Default Inbound]: Source matching result: matched=1
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Main policy destinations '%internal_domains'
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Group 'internal_domains' has 1 destination(s) => @test.km
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_domains): - Resolved destination '@test.km' to a email address specification, match = 0
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_domains): Destination group result: matched=0
[2014/10/10-14:58:18 - 1065] [POLICIES] INFO: [ID:3/Name:Default Inbound]: Destination matching result: matched=0
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:4/Name:Default Internal]: Main policy sources '%internal_ips,%internal_domains'
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:4/Name:Default Internal]: Group 'internal_ips' has 1 source(s) => 10.0.0.0/8
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:4/Name:Default Internal]=>(group:internal_ips): - Resolved source '10.0.0.0/8' to a IP/CIDR specification, match = 0
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:4/Name:Default Internal]=>(group:internal_ips): Source group result: matched=0
[2014/10/10-14:58:18 - 1065] [POLICIES] INFO: [ID:4/Name:Default Internal]: Source matching result: matched=0
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:6/Name:whitelists]: Main policy sources '%whitelists'
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:6/Name:whitelists]: Group 'whitelists' has 0 source(s) =>
[2014/10/10-14:58:18 - 1065] [POLICIES] WARNING: [ID:6/Name:whitelists]: No group members for source group 'whitelists'
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:6/Name:whitelists]=>(group:whitelists): Source group result: matched=0
[2014/10/10-14:58:18 - 1065] [POLICIES] INFO: [ID:6/Name:whitelists]: Source matching result: matched=0
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:7/Name:blacklists]: Main policy sources '%blacklists'
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:7/Name:blacklists]: Group 'blacklists' has 0 source(s) =>
[2014/10/10-14:58:18 - 1065] [POLICIES] WARNING: [ID:7/Name:blacklists]: No group members for source group 'blacklists'
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:7/Name:blacklists]=>(group:blacklists): Source group result: matched=0
[2014/10/10-14:58:18 - 1065] [POLICIES] INFO: [ID:7/Name:blacklists]: Source matching result: matched=0
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:8/Name:no_greylisting]: Main policy sources '!%internal_ips,!%internal_domains'
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:8/Name:no_greylisting]: Group 'internal_ips' has 1 source(s) => 10.0.0.0/8
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:8/Name:no_greylisting]=>(group:internal_ips): - Resolved source '10.0.0.0/8' to a IP/CIDR specification, match = 0
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:8/Name:no_greylisting]=>(group:internal_ips): Source group result: matched=0
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:8/Name:no_greylisting]: Group 'internal_domains' has 1 source(s) => @test.km
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:8/Name:no_greylisting]=>(group:internal_domains): - Resolved source '@test.km' to a email address specification, match = 0
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:8/Name:no_greylisting]=>(group:internal_domains): Source group result: matched=0
[2014/10/10-14:58:18 - 1065] [POLICIES] INFO: [ID:8/Name:no_greylisting]: Source matching result: matched=1
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:8/Name:no_greylisting]: Main policy destinations '%no_greylisting_for_internal'
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:8/Name:no_greylisting]: Group 'no_greylisting_for_internal' has 0 destination(s) =>
[2014/10/10-14:58:18 - 1065] [POLICIES] WARNING: [ID:8/Name:no_greylisting]: No group members for destination group 'no_greylisting_for_internal'
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:8/Name:no_greylisting]=>(group:no_greylisting_for_internal): Destination group result: matched=0
[2014/10/10-14:58:18 - 1065] [POLICIES] INFO: [ID:8/Name:no_greylisting]: Destination matching result: matched=0
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:9/Name:no_greylisting]: Main policy sources '%no_greylisting_for_external'
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:9/Name:no_greylisting]: Group 'no_greylisting_for_external' has 0 source(s) =>
[2014/10/10-14:58:18 - 1065] [POLICIES] WARNING: [ID:9/Name:no_greylisting]: No group members for source group 'no_greylisting_for_external'
[2014/10/10-14:58:18 - 1065] [POLICIES] DEBUG: [ID:9/Name:no_greylisting]=>(group:no_greylisting_for_external): Source group result: matched=0
[2014/10/10-14:58:18 - 1065] [POLICIES] INFO: [ID:9/Name:no_greylisting]: Source matching result: matched=0
[2014/10/10-14:58:18 - 1065] [TRACKING] DEBUG: Policy resolved into: $VAR1 = {};
[2014/10/10-14:58:18 - 1065] [TRACKING] DEBUG: Request translated into session data: $VAR1 = {
          'Recipient' => '222@mmm.ua',
          'SASLUsername' => '111@mmm.ua',
          'QueueID' => '',
          'RecipientData' => '',
          'Instance' => '4b4.5437c9d9.7df90.0',
          'EncryptionCipher' => 'DHE-RSA-AES256-SHA',
          'Size' => '0',
          'EncryptionKeySize' => '256',
          'ParsedClientAddress' => {
                                     'Broadcast_Long' => 2130706433,
                                     'Network' => '127.0.0.1',
                                     'IP_Long' => 2130706433,
                                     'Broadcast' => '127.0.0.1',
                                     'IP' => '127.0.0.1',
                                     'Mask_Long' => 4294967295,
                                     'Network_Long' => 2130706433
                                   },
          'ProtocolTransport' => 'Postfix',
          'EncryptionProtocol' => 'TLSv1',
          'Helo' => '_',
          'ClientAddress' => '127.0.0.1',
          'ClientName' => 'mx',
          'Sender' => '111@mmm.ua',
          'SASLSender' => '',
          'Timestamp' => 1412942297,
          'ProtocolState' => 'RCPT',
          'Policy' => {},
          'Protocol' => 'ESMTP',
          'ClientReverseName' => 'mx',
          'SASLMethod' => 'LOGIN'
        };
[2014/10/10-14:58:18 - 1065] [CBPOLICYD] DEBUG: Got request, running modules...
[2014/10/10-14:58:18 - 1065] [CBPOLICYD] DEBUG: Running module: Access Control Plugin
[2014/10/10-14:58:18 - 1065] [CBPOLICYD] DEBUG: Running module: HELO/EHLO Check Plugin
[2014/10/10-14:58:18 - 1065] [CBPOLICYD] DEBUG: Running module: Greylisting Plugin
[2014/10/10-14:58:18 - 1065] [CBPOLICYD] DEBUG: Running module: Quotas Plugin
[2014/10/10-14:58:18 - 1065] [CBPOLICYD] DEBUG: Done with modules
[2014/10/10-14:58:48 - 1061] [CORE] INFO: Killing "1" children
[2014/10/10-14:58:48 - 1208] [CBPOLICYD] DEBUG: Shutting down caching engine (1208)

----

Spider Email Archiver: On-Premises, lightweight email archiving software developed by iRedMail team. Supports Amazon S3 compatible storage and custom branding.

2 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 30,770

Re: roundcube does not send mail

If you're report sending email issue, please post "sending email" related log or error message.

Mail sending is processed via SMTP protocol, so could you please extract related log in Postfix (SMTP server) log file (/var/log/maillog)? Also, any error message in Roundcube webmail?

3 Reply by 3m

  • 3m
  • Member
  • Offline
  • Registered: 2013-12-23
  • Posts: 149

Re: roundcube does not send mail

I previously publish a maillog but you did not answer me

Oct 13 20:20:41 mx roundcube: Recv: 220 test.ua ESMTP Postfix
Oct 13 20:20:41 mx roundcube: Send: EHLO _
Oct 13 20:20:41 mx roundcube: Recv: 250-test.ua
Oct 13 20:20:41 mx roundcube: Recv: 250-PIPELINING
Oct 13 20:20:41 mx roundcube: Recv: 250-SIZE 15728640
Oct 13 20:20:41 mx roundcube: Recv: 250-ETRN
Oct 13 20:20:41 mx roundcube: Recv: 250-STARTTLS
Oct 13 20:20:41 mx roundcube: Recv: 250-ENHANCEDSTATUSCODES
Oct 13 20:20:41 mx roundcube: Recv: 250-8BITMIME
Oct 13 20:20:41 mx roundcube: Recv: 250 DSN
Oct 13 20:20:41 mx roundcube: Send: STARTTLS
Oct 13 20:20:41 mx roundcube: Recv: 220 2.0.0 Ready to start TLS
Oct 13 20:20:41 mx roundcube: Send: EHLO _
Oct 13 20:20:41 mx roundcube: Recv: 250-test.ua
Oct 13 20:20:41 mx roundcube: Recv: 250-PIPELINING
Oct 13 20:20:41 mx roundcube: Recv: 250-SIZE 15728640
Oct 13 20:20:41 mx roundcube: Recv: 250-ETRN
Oct 13 20:20:41 mx roundcube: Recv: 250-AUTH PLAIN LOGIN
Oct 13 20:20:41 mx roundcube: Recv: 250-AUTH=PLAIN LOGIN
Oct 13 20:20:41 mx roundcube: Recv: 250-ENHANCEDSTATUSCODES
Oct 13 20:20:41 mx roundcube: Recv: 250-8BITMIME
Oct 13 20:20:41 mx roundcube: Recv: 250 DSN
Oct 13 20:20:41 mx roundcube: Send: AUTH LOGIN
Oct 13 20:20:41 mx roundcube: Recv: 334 VXNlcm5hbWU6
Oct 13 20:20:41 mx roundcube: Send: MjIyQG1tbS51YQ==
Oct 13 20:20:41 mx roundcube: Recv: 334 UGFzc3dvcmQ6
Oct 13 20:20:41 mx roundcube: Send: ****** [12]
Oct 13 20:20:42 mx roundcube: Recv: 235 2.7.0 Authentication successful
Oct 13 20:20:42 mx roundcube: Send: MAIL FROM:<222@mmm.ua>
Oct 13 20:20:42 mx roundcube: Recv: 250 2.1.0 Ok
Oct 13 20:20:42 mx roundcube: Send: RCPT TO:<111@mmm.ua>
Oct 13 20:20:44 mx postfix/smtpd[48474]: E48C19CEB6: client=mx[127.0.0.1], sasl_method=LOGIN, sasl_username=222@mmm.ua
Oct 13 20:20:44 mx roundcube: Recv: 250 2.1.5 Ok
Oct 13 20:20:44 mx roundcube: Send: DATA
Oct 13 20:21:44 mx roundcube: Send: RSET
Oct 13 20:21:44 mx roundcube: SMTP Error: SMTP error: Failed to send data in /usr/local/www/roundcube/program/lib/Roundcube/rcube.php on line 1505 (POST /mail/?_task=mail&_unlock=loading1413220840705&_lang=ru&_framed=1?_task=mail&_action=send)
Oct 13 20:21:45 mx roundcube: Send: QUIT
Oct 13 20:21:45 mx postfix/smtpd[48474]: lost connection after DATA (12 bytes) from mx[127.0.0.1]
Oct 13 20:21:45 mx postfix/cleanup[48478]: E48C19CEB6: message-id=<20141013172044.E48C19CEB6@test.ua>
Oct 13 20:21:45 mx postfix/smtpd[48474]: disconnect from mx[127.0.0.1]

4 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 30,770

Re: roundcube does not send mail

3m wrote:

I previously publish a maillog but you did not answer me

Cannot know which log content you posted before is related to your NEW forum topic. and it's impossible for me to check all your posts before answer a new topic. So, please just attach related log/config file in single one topic, it will help me to understand the situation and you will get quicker reply.

Unfortunately, I cannot understand what the problem is with pasted log, no obvious and possible error message at all.
I suggest you post to Postfix mailing list to ask for help.