Dear mir,

Sorry about this trouble.
Could you please modify /opt/iredapd/iredapd.py with below patch, then restart iRedAPD and keep monitor its log file?

--- iredapd.py.bak    2015-05-20 12:27:42.000000000 +0800
+++ iredapd.py    2015-05-20 12:28:58.000000000 +0800
@@ -236,6 +236,8 @@
         asyncore.loop()
     except KeyboardInterrupt:
         pass
+    except Exception, e:
+        logging.info('Error: ' + str(e))
 
 if __name__ == '__main__':
     main()

If same issue occurs, please find out log line in /var/log/iredapd.log which contains 'Error':

# grep -i 'error' /var/log/iredapd.log

Let's see what the problem is.

OK, let's keep tracking this issue.

Hi tofinus,

Thanks for the feedback. But "bad file descriptior" is meaningless, i have no idea what the problem is.
Could you please try below fix based on patched iredapd.py?

*) Find below line in /opt/iredapd/iredapd.py:

asyncore.loop()

*) Updated it to:

asyncore.loop(use_poll=True)

*) Restart iredapd service and keep tracking this issue.

By the way, which Python version are you running? Check it with command:

# python -V

Hi,

The problem is still here after the change that you say.

My system :
Debian 8
Python 2.7.9
PHP 5.6.7-1
iredmail 0.9.1
iRedAPD (version: 1.5.0, backend: mysql), listening on 127.0.0.1:7777.

2015-05-22 09:15:21 INFO Starting iRedAPD (version: 1.5.0, backend: mysql), listening on 127.0.0.1:7777.
2015-05-22 09:15:21 INFO Loading plugin: reject_null_sender
2015-05-22 09:15:21 INFO Loading plugin: amavisd_message_size_limit
2015-05-22 09:15:21 INFO Loading plugin: amavisd_wblist
2015-05-22 09:15:21 INFO Loading plugin: sql_alias_access_policy
2015-05-22 09:19:03 INFO [127.0.0.1] RCPT,cxxx@xxx.com -> xxx.xxx@doamnine.ch, DUNNO
2015-05-22 10:30:37 INFO Error: [Errno 9] Bad file descriptor

Hi all,

There seems to be problem with iredapd even after applying latest patch. This morning my script kicked in an restartet iredapd.

Nothing was logged to /var/log/iredapd.log even though the extra log instruction is present:
    # Starting loop.
    try:
        # There's a bug report for Python 2.6/3.0 that `use_poll=True` yields
        # some 2.5 incompatibilities:
        if (sys.version_info >= (2, 7) and sys.version_info < (2, 8)) \
           or (sys.version_info >= (3, 4)):     # if python 2.7 ...
            # workaround for the "Bad file descriptor" issue on Python 2.7, gh-161
            asyncore.loop(use_poll=True)
        else:
            # fixes the "Unexpected communication problem" issue on Python 2.6 and 3.0
            asyncore.loop(use_poll=False)

    except KeyboardInterrupt:
        pass
    except Exception, e:
    logging.info('Error: ' + str(e))

From syslog:
May 23 09:50:01 iredmail CRON[16950]: (root) CMD ([ -x /usr/local/sbin/check_iredapd.sh ] && /usr/local/sbin/check_iredapd.sh)
May 23 09:50:01 iredmail CRON[16949]: (www-data) CMD ([ -x /usr/share/awstats/tools/update.sh ] && /usr/share/awstats/tools/update.sh)
May 23 09:50:11 iredmail postfix/smtpd[16877]: connect from mail139.wdc02.mcdlv.net[205.201.130.139]
May 23 09:50:12 iredmail postfix/smtpd[16877]: warning: connect to 127.0.0.1:7777: Connection refused
May 23 09:50:12 iredmail postfix/smtpd[16877]: warning: problem talking to server 127.0.0.1:7777: Connection refused
May 23 09:51:01 iredmail CRON[17063]: (root) CMD ([ -x /usr/local/sbin/check_iredapd.sh ] && /usr/local/sbin/check_iredapd.sh)

From iredapd.log:
2015-05-23 09:29:15 INFO [94.136.31.133] RCPT, x@foo.bar -> mir@my.dom, DUNNO
2015-05-23 09:51:01 INFO Starting iRedAPD (version: 1.5.0, backend: ldap), listening on 127.0.0.1:77
77.
2015-05-23 09:51:01 INFO Loading plugin: reject_null_sender
2015-05-23 09:51:01 INFO Loading plugin: ldap_maillist_access_policy
2015-05-23 09:51:01 INFO Loading plugin: ldap_amavisd_block_blacklisted_senders
2015-05-23 09:51:01 INFO Loading plugin: ldap_recipient_restrictions
2015-05-23 09:51:01 INFO Loading plugin: amavisd_message_size_limit
2015-05-23 10:00:23 INFO [205.201.130.163] RCPT, <all so removed here>, DUNNO

Above facts gives me reason to expect that what we are seeing is that either iredapd or python simply is crashing unexpected since the last catchall 'except Exception, e:' is never reached.

Most likely the same problem striked also on my server this morning

I read thru the end of the logs and I found out this:

- last 2 emails was from the same (external) sender to the same (local) recipient... they was from postmaster@... maybe some concurrency happened?
- just before the session dump of the first of this 2 emails in the log, I see this line:

2015-05-24 06:11:03 DEBUG Connect from 127.0.0.1, port 41628.

Any hint based on this?

@mir:
I deployed your watchdog script for iRedAPd - thanks a lot! I modified it a bit, to send me email when iRedAPd dies:

#!/bin/sh
CMD=/etc/init.d/iredapd
ADMINEMAIL=<fill your email address>
FROMEMAIL=<fill from email address>

[ -x $CMD ] || exit 0
STATUS=$($CMD status)
if [ $? != 0 ]
then
  $CMD start 2>&1 > /dev/null
  sleep 10
  mail -r $FROMEMAIL -s "iRedAPd died!" $ADMINEMAIL < /dev/null
fi
exit 0

Hi Mir,

Are you a Python developer?

iRedAPD itself is simple and easy, we just need to rewrite the socket/daemon part, maybe use 'SocketServer' module (not sure whether it's based on asyncore/asynchat yet, need to check doc), but i personally don't want to involve big component like Twisted in iRedAPD.

Or, maybe we rewrite it in Erlang?

The worst part of this bug is, i don't know how to reproduce this issue, and have to just wait.
If we can reproduce it, at least we can try to dive into source code and (probably) figure it out.

Maybe use the work-around mentioned in my former post. Change timeout from 30 to 60 sec.

I have added this to iredapd.py to see whether increasing timeout will solve the issue.

    # Starting loop.
    try:
        # There's a bug report for Python 2.6/3.0 that `use_poll=True` yields
        # some 2.5 incompatibilities:
        if (sys.version_info >= (2, 7) and sys.version_info < (2, 8)) \
           or (sys.version_info >= (3, 4)):     # if python 2.7 ...
            # workaround for the "Bad file descriptor" issue on Python 2.7, gh-161
            asyncore.loop(timeout=60.0, use_poll=True)
        else:
            # fixes the "Unexpected communication problem" issue on Python 2.6 and 3.0
            asyncore.loop(use_poll=False)

    except KeyboardInterrupt:
        pass
    except Exception, e:
        logging.info('Error: ' + str(e))

On average 2 times a day.

hi mir,

Any progress? Did it occur again?