1 Topic by 3n4rch3 (edited by 3n4rch3 2021-02-17 04:02:51)

  • 3n4rch3
  • Member
  • Offline
  • Registered: 2021-02-11
  • Posts: 28

Topic: [SOLVED] STARTTLS not working for iRedAPD

==== REQUIRED BASIC INFO OF YOUR IREDMAIL SERVER ====
- iRedMail version (check /etc/iredmail-release):                           1.3.2 OPENLDAP edition.
- Deployed with iRedMail Easy or the downloadable installer?       Downloadable, self-hosted
- Linux/BSD distribution name and version:                                   CentOS Linux release 8.3.2011
- Store mail accounts in which backend (LDAP/MySQL/PGSQL):  LDAP
- Web server (Apache or Nginx):                                                     Nginx
- Manage mail accounts with iRedAdmin-Pro?                               Not yet on this testing server
- [IMPORTANT] Related original log or error message is required if you're experiencing an issue.
====

I'm running a separate OpenLDAP server, to which iRedMail connects for authentication. Generally, everything is working smoothly. Recently however I got around to setting up STARTTLS; and even more recently, to requiring it.  I think both iRedAdmin & iRedAPD are supposed to be ok with that (I see in the source that they try STARTTLS).

Watching the debug output for iRedAPD, I see that the modules seem to load & run properly, except for one: ldap_force_change_password. When an email is sent, I see this:

Feb 10 15:40:04 irm-ldap journal[5797]: iredapd [+] Getting LDIF data of account: user@server-z.net
Feb 10 15:40:04 irm-ldap journal[5797]: iredapd search base dn: o=domains,dc=server-y,dc=net#012search scope: SUBTREE #012search filter: (&(!(domainStatus=disabled))(|(mail=user@server-z.net)(shadowAddress=user@server-z.net))(|(objectClass=mailUser)(objectClass=mailList)(objectClass=mailAlias)))#012search attributes: ['objectClass', 'shadowLastChange']
Feb 10 15:40:04 irm-ldap journal[5797]: iredapd <!> ERROR: CONFIDENTIALITY_REQUIRED({'desc': 'Confidentiality required', 'info': 'TLS confidentiality required'},)
Feb 10 15:40:04 irm-ldap journal[5797]: iredapd --> Apply plugin: ldap_force_change_password
Feb 10 15:40:04 irm-ldap journal[5797]: iredapd <-- Result: DUNNO Not a local user (no sender ldif)

...and the email is (of course) sent successfully, because iRedAPD couldn't bind to the server, and therefore couldn't read "shadowLastChange" attribute.  In this case, it should have been blocked, because "shadowLastChange" is set to 50 years ago (and "CHANGE_PASSWORD_DAYS = 3652")!

The problem appears to be in the "CONFIDENTIALITY REQUIRED" line, which normally happens when STARTTLS is not requested (e.g., not using -Z option with 'ldapsearch', etc.), and seems to indicate that iRedAPD is not requesting STARTTLS. Am i missing something? I'm happy for suggestions! :-)

----

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

2 Reply by 3n4rch3

  • 3n4rch3
  • Member
  • Offline
  • Registered: 2021-02-11
  • Posts: 28

Re: [SOLVED] STARTTLS not working for iRedAPD

Hmm...I thought iRedAPD was starting ok, but now i see these lines in the journal after 'systemctl restart iredapd'. Apparently it's missing the connection right from the beginning:

Feb 10 17:08:51 irm-ldap.server-y.net systemd[1]: Starting iRedAPD (A simple posfix policy server)...
Feb 10 17:08:51 irm-ldap.server-y.net python3[2568]: iredapd LDAP connection initialied success.
Feb 10 17:08:51 irm-ldap.server-y.net python3[2568]: iredapd LDAP bind failed: CONFIDENTIALITY_REQUIRED({'desc': 'Confidentiality required', 'info': 'TLS confidentiality required'},)
Feb 10 17:08:51 irm-ldap.server-y.net python3[2568]: iredapd Starting iRedAPD (version: 4.6, backend: ldap), listening on 127.0.0.1:7777.
Feb 10 17:08:51 irm-ldap.server-y.net python3[2568]: iredapd Loading plugin (priority: 100): reject_null_sender
Feb 10 17:08:51 irm-ldap.server-y.net python3[2568]: iredapd Loading plugin (priority: 99): wblist_rdns
Feb 10 17:08:51 irm-ldap.server-y.net python3[2568]: iredapd Loading plugin (priority: 90): reject_sender_login_mismatch
Feb 10 17:08:51 irm-ldap.server-y.net python3[2568]: iredapd Loading plugin (priority: 80): greylisting
Feb 10 17:08:51 irm-ldap.server-y.net python3[2568]: iredapd Loading plugin (priority: 60): throttle
Feb 10 17:08:51 irm-ldap.server-y.net python3[2568]: iredapd Loading plugin (priority: 50): ldap_maillist_access_policy
Feb 10 17:08:51 irm-ldap.server-y.net python3[2568]: iredapd Loading plugin (priority: 40): amavisd_wblist
Feb 10 17:08:51 irm-ldap.server-y.net python3[2568]: iredapd Loading plugin (priority: 0): ldap_force_change_password
Feb 10 17:08:51 irm-ldap.server-y.net python3[2568]: iredapd Starting SRS sender rewriting channel, listening on 127.0.0.1:7778
Feb 10 17:08:51 irm-ldap.server-y.net python3[2568]: iredapd Starting SRS recipient rewriting channel, listening on 127.0.0.1:7779
Feb 10 17:08:51 irm-ldap.server-y.net systemd[1]: iredapd.service: Can't open PID file /run/iredapd.pid (yet?) after start: No such file or directory
Feb 10 17:08:51 irm-ldap.server-y.net systemd[1]: Started iRedAPD (A simple posfix policy server).

3 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 31,088

Re: [SOLVED] STARTTLS not working for iRedAPD

What's the LDAP server address and port (parameter "ldap_uri =" in /opt/iredapd/settings.py) defined in iRedAPD config file? Did you try "ldaps://127.0.0.1:389"?

4 Reply by 3n4rch3 (edited by 3n4rch3 2021-02-16 05:23:33)

  • 3n4rch3
  • Member
  • Offline
  • Registered: 2021-02-11
  • Posts: 28

Re: [SOLVED] STARTTLS not working for iRedAPD

I did NOT specify 'ldaps', since STARTTLS being 'opportunistic' by design means that it normally operates on the same uri/port as when insecure. So...everything is set as below:

ldap://10.X.X.XXX:389

However, I am heading over now to try ldapS for iRedAdmin & iRedAPD, as you suggest; I'll report back in a bit...

Thanks!

5 Reply by 3n4rch3 (edited by 3n4rch3 2021-02-12 00:35:37)

  • 3n4rch3
  • Member
  • Offline
  • Registered: 2021-02-11
  • Posts: 28

Re: [SOLVED] STARTTLS not working for iRedAPD

Below are my results.

Using 'ldaps://', i see this (what I would have initially expected, since port 636 is unavailable.) And FWIW, same result whether or not I specify the port (:389):

Feb 11 09:18:45 irm-ldap journal[60107]: iredapd LDAP connection initialied success.
Feb 11 09:18:45 irm-ldap journal[60107]: iredapd LDAP bind failed: SERVER_DOWN({'desc': "Can't contact LDAP server", 'errno': 107, 'info': 'Transport endpoint is not connected'},)
Feb 11 09:18:45 irm-ldap journal[60107]: iredapd Starting iRedAPD (version: 4.6, backend: ldap), listening on 127.0.0.1:7777.

Returning to 'ldap_uri = ldap://...', I once again get this result:

Feb 11 09:23:41 irm-ldap journal[60450]: iredapd LDAP connection initialied success.
Feb 11 09:23:41 irm-ldap journal[60450]: iredapd LDAP bind failed: CONFIDENTIALITY_REQUIRED({'desc': 'Confidentiality required', 'info': 'TLS confidentiality required'},)
Feb 11 09:23:41 irm-ldap journal[60450]: iredapd Starting iRedAPD (version: 4.6, backend: ldap), listening on 127.0.0.1:7777.

If, on the other hand, I remove the TLS requirement (i.e., 'olcSecurity: tls=0' on OpenLDAP server), it all succeeds:

Feb 11 11:24:24 irm-ldap journal[809]: iredapd LDAP connection initialied success.
Feb 11 11:24:24 irm-ldap journal[809]: iredapd LDAP bind success.
Feb 11 11:24:24 irm-ldap journal[809]: iredapd Starting iRedAPD (version: 4.6, backend: ldap), listening on 127.0.0.1:7777.

Is it possible that either 1.) iRedAPD is not really using STARTTLS at all, or 2.) it's trying to upgrade a 'previously opened' bind (which never actually happened because of TLS requirement)?

Any other suggestions to try? :-/

6 Reply by 3n4rch3

  • 3n4rch3
  • Member
  • Offline
  • Registered: 2021-02-11
  • Posts: 28

Re: [SOLVED] STARTTLS not working for iRedAPD

新年快乐, y'all!

As it's not a holiday here in the US, I'm working today on converting our "main" test server from MySQL to OpenLDAP backend, and hoping in the meantime for an idea, or an accidental fix. We really need "TLS required" to work. (To be fair, I've done a lot of tinkering on this server, so it's possible not everything is set up quite the way it began.)

If nothing turns up, and the problem still exists, I'll be back...

7 Reply by 3n4rch3 (edited by 3n4rch3 2021-02-16 05:25:17)

  • 3n4rch3
  • Member
  • Offline
  • Registered: 2021-02-11
  • Posts: 28

Re: [SOLVED] STARTTLS not working for iRedAPD

I'm back, although I'm guessing Mr. Zhang is not yet. (That's fine, enjoy your holidays!) :-)

Anyway...as I said earlier, on Friday I converted our other test server from MySQL backend to LDAP backend, but same buggy behavior...iRedAPD cannot do a secure ldap connection, although set as requested by ZHB in post #3 (ldap_uri = "ldaps://10.X.X.XXX:389"). It is really baffling me, because iRedAdmin (defined similarly) does seem to succeed in binding securely.


1.) Using an ldaps:// uri in 'iredapd/settings.py', logs look like this:

Feb 15 14:43:06 mail.eSERVER.email python3[13914]: iredapd [+] Getting LDIF data of account: greg@uSERVER.net
Feb 15 14:43:06 mail.eSERVER.email python3[13914]: iredapd search: base_dn=o=domains,dc=eSERVER,dc=net, scope=SUBTREE, filter=(&(!(domainStatus=disabled))(|(mail=greg@uSERVER.net)(shadowAddress=greg@uSERVER.net))(|(objectClass=mailUser)(objectClass=mailList)(objectClass=mailAlias))), attributes=['objectClass', 'shadowLastChange']
Feb 15 14:43:06 mail.eSERVER.email python3[13914]: iredapd <!> ERROR: SERVER_DOWN({'desc': "Can't contact LDAP server"},)
Feb 15 14:43:06 mail.eSERVER.email python3[13914]: iredapd --> Apply plugin: ldap_force_change_password
Feb 15 14:43:06 mail.eSERVER.email python3[13914]: iredapd <-- Result: DUNNO Not a local user (no sender ldif)
Feb 15 14:43:06 mail.eSERVER.email python3[13914]: iredapd Session ended.

2.) If I use ldap:// uri, it all succeeds, but binding insecurely:

Feb 15 15:05:47 mail.eSERVER.email python3[22106]: iredapd [+] Getting LDIF data of account: greg@uSERVER.net
Feb 15 15:05:47 mail.eSERVER.email python3[22106]: iredapd search: base_dn=o=domains,dc=eSERVER,dc=net, scope=SUBTREE, filter=(&(!(domainStatus=disabled))(|(mail=greg@uSERVER.net)(shadowAddress=greg@uSERVER.net))(|(objectClass=mailUser)(objectClass=mailList)(objectClass=mailAlias))), attributes=['objectClass', 'shadowLastChange']
Feb 15 15:05:47 mail.eSERVER.email python3[22106]: iredapd result: [('mail=greg@uSERVER.net,ou=Users,domainName=uSERVER.net,o=domains,dc=eSERVER,dc=net', {'objectClass': [b'inetOrgPerson', b'mailUser', b'shadowAccount', b'amavisAccount'], 'shadowLastChange': [b'823']})]
Feb 15 15:05:47 mail.eSERVER.email python3[22106]: iredapd --> Apply plugin: ldap_force_change_password
Feb 15 15:05:47 mail.eSERVER.email python3[22106]: iredapd Days of password last change: 823 (today: 18673)
Feb 15 15:05:47 mail.eSERVER.email python3[22106]: iredapd Password last change date is older than 3652 days.
Feb 15 15:05:47 mail.eSERVER.email python3[22106]: iredapd <-- Result: REJECT Please change your password in webmail before sending email: <https://mail.eSERVER.email/webmail>
Feb 15 15:05:47 mail.eSERVER.email python3[22106]: iredapd Session ended.

3.) I know that the ldap server properly accepts STARTTLS requests, because if i query the same information via CLI with required TLS (-ZZ): 

ldapsearch -ZZ -D "cn=manager,dc=eSERVER,dc=net" -W -H ldap://10.X.X.XXX:389 -b o=domains,dc=eSERVER,dc=net -s subtree "(&(!(domainStatus=disabled))(|(mail=greg@uSERVER.net)(shadowAddress=greg@uSERVER.net))(|(objectClass=mailUser)(objectClass=mailList)(objectClass=mailAlias)))" objectClass shadowLastChange

...everything is returned as expected...and securely!!

What needs to happen for iRedAPD to do this properly?

8 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 31,088

Re: [SOLVED] STARTTLS not working for iRedAPD

Confirmed it's a bug of iRedAPD and fixed in newly tagged version 4.9. Please upgrade and try again:
https://docs.iredmail.org/upgrade.iredapd.html

Note: With TLS support, the ldap URI is same as the plain one, and there's a NEW parameter "ldap_enable_tls" introduced:

ldap_uri = "ldap://10.X.X.XXX:389"
ldap_enable_tls = True

9 Reply by 3n4rch3 (edited by 3n4rch3 2021-02-16 23:31:37)

  • 3n4rch3
  • Member
  • Offline
  • Registered: 2021-02-11
  • Posts: 28

Re: [SOLVED] STARTTLS not working for iRedAPD

Thanks, I'm grateful for your work. This is moving in the right direction, but it still doesn't seem to work (at least for me). I ran 'iRedAPD-4.9/tools/upgrade_iredapd.sh', and restarted iRedAPD. Also verified afterward that the iredapd symlink actually pointed to '/opt/iRedAPD-4.9'.

With the above settings modified/added to '/opt/iredapd/settings.py', it seemed to work at first (I didn't verify TLS usage). However, upon _requiring_ TLS (set 'olcSecurity: tls=1' on the OpenLDAP server), logs once again look like this:

Feb 16 09:53:35 mail.eSERVER.email python3[187604]: iredapd [+] Getting LDIF data of account: greg@uSERVER.net
Feb 16 09:53:35 mail.eSERVER.email python3[187604]: iredapd search: base_dn=o=domains,dc=eSERVER,dc=net, scope=SUBTREE, filter=(&(!(domainStatus=disabled))(|(mail=greg@uSERVER.net)(shadowAddress=greg@uSERVER.net))(|(objectClass=mailUser)(objectClass=mailList)(objectClass=mailAlias))), attributes=['objectClass', 'shadowLastChange']
Feb 16 09:53:35 mail.eSERVER.email python3[187604]: iredapd <!> ERROR: CONFIDENTIALITY_REQUIRED({'desc': 'Confidentiality required', 'info': 'TLS confidentiality required'},)
Feb 16 09:53:35 mail.eSERVER.email python3[187604]: iredapd --> Apply plugin: ldap_force_change_password
Feb 16 09:53:35 mail.eSERVER.email python3[187604]: iredapd <-- Result: DUNNO Not a local user (no sender ldif)
Feb 16 09:53:35 mail.eSERVER.email python3[187604]: iredapd Session ended.

And the email gets sent, although the password is still expired.

Am I missing something in my setup?

10 Reply by 3n4rch3

  • 3n4rch3
  • Member
  • Offline
  • Registered: 2021-02-11
  • Posts: 28

Re: [SOLVED] STARTTLS not working for iRedAPD

Ahhh, found it!! :facepalm:

I didn't realize that the update script had already added 'ldap_enable_tls = False' to the tail end of my settings.py, so after upgrading i added 'ldap_enable_tls = True', which was obviously overridden by the later statement. Fixed that, and it seems to work properly.

Thanks again for your help and the quick fix!