Verification emails are not being sent since upgrade to 2.1

Administrators
1

Hello Indico team,

I upgaded our indico instance at https://indico.bnl.gov to version 2.1 (from 2.0.2) on Monday. Since the upgrade, any verification emails are not being sent from the server when creating a new user. I just tried to create an account and did not receive an email. The Indico email settings have not changed. I confirmed that no email is being sent by checking logs on our mailrelay host which shows no connection attempts from the indico server since Monday (except for a few test emails I sent today as root).

Any ideas?

Thanks in advance,
Rafael

Here are the relevant email settings from indico.conf:

# Email settings
SMTP_SERVER = ('mailrelay.itd.bnl.gov', 25)
SMTP_USE_TLS = False
SMTP_LOGIN = ''
SMTP_PASSWORD = ''
SUPPORT_EMAIL = 'support@indico.bnl.gov'
PUBLIC_SUPPORT_EMAIL = 'support@indico.bnl.gov'
NO_REPLY_EMAIL = 'noreply-indico@indico.bnl.gov'
2

Did you start Celery again after upgrading (if you followed the upgrade guide, you stopped it at the beginning)?

You can check the status using systemctl status indico-celery.service and if needed restart it using systemctl start indico-celery.service (as root).

3

Yes, I restarted the indico-celery service. Sorry I should have mentioned that.
Here is output from a ps:

root@indico log # ps -ef|grep celery
indico    9621     1  0 17:54 ?        00:00:00 /opt/indico/.venv/bin/python /opt/indico/.venv/bin/indico celery worker -B
root      9623 26438  0 17:54 pts/0    00:00:00 grep --color=auto celery

I also checked the celery.log file while attempting to create a new Indico profile and I’m not seeing a “send_email” task when clicking on the send verification email link here: https://indico.bnl.gov/register/

4

Anything interesting in celery.log and/or indico.log at all? We didn’t change anything related to celery or email sending in 2.1 so it’s strange that it doesn’t work for you anymore…

Maybe tail -f both log files, then do some action that sends an email (requesting password reset, verifying an email, etc.) and see what shows up in the log files.

indico.log should have a line like this when an email gets sent:

2018-05-25 23:54:19,447  INFO     0000000000000000  indico.emails             Sent email "[Indico] ....."

and the corresponding entries in celery.log:

2018-05-25 23:54:19,256  INFO     celery.worker.strategy    Received task: send_email[a7d12b39-0716-436a-8953-55c54572dc3d]
2018-05-25 23:54:19,456  INFO     celery.app.trace          Task send_email[a7d12b39-0716-436a-8953-55c54572dc3d] succeeded in 0.197259217995s: None
5

Ok thanks. I just tried that and noticed that the celery.log file hasn’t been touched since May 21 which is when I upgraded. This probably explains why it isn’t working. Only updates to the indico.log show the connections to the /register page (ip addr removed):

2018-05-25 18:09:00,434  INFO     ac061c7d094744d9  indico.rh                 POST /register/ [IP=x.x.x.x] [PID=5663] [UID=None]
2018-05-25 18:09:00,606  INFO     bdf5e8e64c404cd9  indico.rh                 GET /register/ [IP=x.x.x.x] [PID=5663] [UID=None]
6

If there’s nothing at all in celery.log it sounds like celery isn’t working properly. The regular tasks like checking event reminders would show up in there as well.

7

Ok I just noticed a traceback in /var/log/messages every minute or so. The indico-celery service seems to be in a restart loop of sorts. Here are a few iterations from the log:

May 25 18:17:55 indico indico-celery: Traceback (most recent call last):
May 25 18:17:55 indico indico-celery: File "/opt/indico/.venv/bin/indico", line 11, in <module>
May 25 18:17:55 indico indico-celery: sys.exit(cli())
May 25 18:17:55 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/click/core.py", line 722, in __call__
May 25 18:17:55 indico indico-celery: return self.main(*args, **kwargs)
May 25 18:17:55 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/flask/cli.py", line 380, in main
May 25 18:17:55 indico indico-celery: return AppGroup.main(self, *args, **kwargs)
May 25 18:17:55 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/click/core.py", line 697, in main
May 25 18:17:55 indico indico-celery: rv = self.invoke(ctx)
May 25 18:17:55 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/click/core.py", line 1066, in invoke
May 25 18:17:55 indico indico-celery: return _process_result(sub_ctx.command.invoke(sub_ctx))
May 25 18:17:55 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/click/core.py", line 895, in invoke
May 25 18:17:55 indico indico-celery: return ctx.invoke(self.callback, **ctx.params)
May 25 18:17:55 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/click/core.py", line 535, in invoke
May 25 18:17:55 indico indico-celery: return callback(*args, **kwargs)
May 25 18:17:55 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/click/decorators.py", line 17, in new_func
May 25 18:17:55 indico indico-celery: return f(get_current_context(), *args, **kwargs)
May 25 18:17:55 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/flask/cli.py", line 257, in decorator
May 25 18:17:55 indico indico-celery: return __ctx.invoke(f, *args, **kwargs)
May 25 18:17:55 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/click/core.py", line 535, in invoke
May 25 18:17:55 indico indico-celery: return callback(*args, **kwargs)
May 25 18:17:55 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/click/decorators.py", line 17, in new_func
May 25 18:17:55 indico indico-celery: return f(get_current_context(), *args, **kwargs)
May 25 18:17:55 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/indico/cli/core.py", line 98, in celery
May 25 18:17:55 indico indico-celery: celery_cmd(ctx.args)
May 25 18:17:55 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/indico/core/celery/cli.py", line 71, in celery_cmd
May 25 18:17:55 indico indico-celery: CeleryCommand(celery).execute_from_commandline(['indico celery'] + args)
May 25 18:17:55 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/celery/bin/celery.py", line 488, in execute_from_commandline
May 25 18:17:55 indico indico-celery: super(CeleryCommand, self).execute_from_commandline(argv)))
May 25 18:17:55 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/celery/bin/base.py", line 281, in execute_from_commandline
May 25 18:17:55 indico indico-celery: return self.handle_argv(self.prog_name, argv[1:])
May 25 18:17:55 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/celery/bin/celery.py", line 480, in handle_argv
May 25 18:17:55 indico indico-celery: return self.execute(command, argv)
May 25 18:17:55 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/celery/bin/celery.py", line 412, in execute
May 25 18:17:55 indico indico-celery: ).run_from_argv(self.prog_name, argv[1:], command=argv[0])
May 25 18:17:55 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/celery/bin/worker.py", line 221, in run_from_argv
May 25 18:17:55 indico indico-celery: return self(*args, **options)
May 25 18:17:55 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/celery/bin/base.py", line 244, in __call__
May 25 18:17:55 indico indico-celery: ret = self.run(*args, **kwargs)
May 25 18:17:55 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/celery/bin/worker.py", line 255, in run
May 25 18:17:55 indico indico-celery: **kwargs)
May 25 18:17:55 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/celery/worker/worker.py", line 99, in __init__
May 25 18:17:55 indico indico-celery: self.setup_instance(**self.prepare_args(**kwargs))
May 25 18:17:55 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/celery/worker/worker.py", line 122, in setup_instance
May 25 18:17:55 indico indico-celery: self.should_use_eventloop() if use_eventloop is None
May 25 18:17:55 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/celery/worker/worker.py", line 241, in should_use_eventloop
May 25 18:17:55 indico indico-celery: self._conninfo.transport.implements.async and
May 25 18:17:55 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/kombu/transport/base.py", line 125, in __getattr__
May 25 18:17:55 indico indico-celery: raise AttributeError(key)
May 25 18:17:55 indico indico-celery: AttributeError: async
May 25 18:17:55 indico systemd: indico-celery.service: main process exited, code=exited, status=1/FAILURE
May 25 18:17:55 indico systemd: Unit indico-celery.service entered failed state.
May 25 18:17:55 indico systemd: indico-celery.service failed.
May 25 18:17:56 indico systemd: indico-celery.service holdoff time over, scheduling restart.
May 25 18:17:56 indico systemd: Started Indico Celery.
May 25 18:17:56 indico systemd: Starting Indico Celery...
May 25 18:18:01 indico indico-celery: Traceback (most recent call last):
May 25 18:18:01 indico indico-celery: File "/opt/indico/.venv/bin/indico", line 11, in <module>
May 25 18:18:01 indico indico-celery: sys.exit(cli())
May 25 18:18:01 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/click/core.py", line 722, in __call__
May 25 18:18:01 indico indico-celery: return self.main(*args, **kwargs)
May 25 18:18:01 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/flask/cli.py", line 380, in main
May 25 18:18:01 indico indico-celery: return AppGroup.main(self, *args, **kwargs)
May 25 18:18:01 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/click/core.py", line 697, in main
May 25 18:18:01 indico indico-celery: rv = self.invoke(ctx)
May 25 18:18:01 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/click/core.py", line 1066, in invoke
May 25 18:18:01 indico indico-celery: return _process_result(sub_ctx.command.invoke(sub_ctx))
May 25 18:18:01 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/click/core.py", line 895, in invoke
May 25 18:18:01 indico indico-celery: return ctx.invoke(self.callback, **ctx.params)
May 25 18:18:01 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/click/core.py", line 535, in invoke
May 25 18:18:01 indico indico-celery: return callback(*args, **kwargs)
May 25 18:18:01 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/click/decorators.py", line 17, in new_func
May 25 18:18:01 indico indico-celery: return f(get_current_context(), *args, **kwargs)
May 25 18:18:01 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/flask/cli.py", line 257, in decorator
May 25 18:18:01 indico indico-celery: return __ctx.invoke(f, *args, **kwargs)
May 25 18:18:01 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/click/core.py", line 535, in invoke
May 25 18:18:01 indico indico-celery: return callback(*args, **kwargs)
May 25 18:18:01 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/click/decorators.py", line 17, in new_func
May 25 18:18:01 indico indico-celery: return f(get_current_context(), *args, **kwargs)
May 25 18:18:01 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/indico/cli/core.py", line 98, in celery
May 25 18:18:01 indico indico-celery: celery_cmd(ctx.args)
May 25 18:18:01 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/indico/core/celery/cli.py", line 71, in celery_cmd
May 25 18:18:01 indico indico-celery: CeleryCommand(celery).execute_from_commandline(['indico celery'] + args)
May 25 18:18:01 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/celery/bin/celery.py", line 488, in execute_from_commandline
May 25 18:18:01 indico indico-celery: super(CeleryCommand, self).execute_from_commandline(argv)))
May 25 18:18:01 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/celery/bin/base.py", line 281, in execute_from_commandline
May 25 18:18:01 indico indico-celery: return self.handle_argv(self.prog_name, argv[1:])
May 25 18:18:01 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/celery/bin/celery.py", line 480, in handle_argv
May 25 18:18:01 indico indico-celery: return self.execute(command, argv)
May 25 18:18:01 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/celery/bin/celery.py", line 412, in execute
May 25 18:18:01 indico indico-celery: ).run_from_argv(self.prog_name, argv[1:], command=argv[0])
May 25 18:18:01 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/celery/bin/worker.py", line 221, in run_from_argv
May 25 18:18:01 indico indico-celery: return self(*args, **options)
May 25 18:18:01 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/celery/bin/base.py", line 244, in __call__
May 25 18:18:01 indico indico-celery: ret = self.run(*args, **kwargs)
May 25 18:18:01 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/celery/bin/worker.py", line 255, in run
May 25 18:18:01 indico indico-celery: **kwargs)
May 25 18:18:01 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/celery/worker/worker.py", line 99, in __init__
May 25 18:18:01 indico indico-celery: self.setup_instance(**self.prepare_args(**kwargs))
May 25 18:18:01 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/celery/worker/worker.py", line 122, in setup_instance
May 25 18:18:01 indico indico-celery: self.should_use_eventloop() if use_eventloop is None
May 25 18:18:01 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/celery/worker/worker.py", line 241, in should_use_eventloop
May 25 18:18:01 indico indico-celery: self._conninfo.transport.implements.async and
May 25 18:18:01 indico indico-celery: File "/opt/indico/.venv/lib/python2.7/site-packages/kombu/transport/base.py", line 125, in __getattr__
May 25 18:18:01 indico indico-celery: raise AttributeError(key)
May 25 18:18:01 indico indico-celery: AttributeError: async
May 25 18:18:01 indico systemd: indico-celery.service: main process exited, code=exited, status=1/FAILURE
May 25 18:18:01 indico systemd: Unit indico-celery.service entered failed state.
May 25 18:18:01 indico systemd: indico-celery.service failed.
May 25 18:18:01 indico systemd: indico-celery.service holdoff time over, scheduling restart.
May 25 18:18:01 indico systemd: Started Indico Celery.
May 25 18:18:01 indico systemd: Starting Indico Celery...
8

That sounds like a likely cause of it. try downgrading kombu as suggested in the answers. I guess we’ll release a 2.1.1 next week that updates celery to a version without this issue.

9

That seemed to do the trick! I ran the following commands:

root@indico log # su - indico
Last login: Fri May 25 18:32:12 EDT 2018 on pts/0
[indico@indico ~]$ source ~/.venv/bin/activate
(.venv)[indico@indico ~]$ pip list|grep kombu
kombu                              4.2.0

(.venv)[indico@indico ~]$ pip install kombu==4.1.0
Collecting kombu==4.1.0
  Downloading https://files.pythonhosted.org/packages/62/a4/5d16954803224a1e451713293c2a028614099f5538cf626e1fdd7b438c86/kombu-4.1.0-py2.py3-none-any.whl (181kB)
    100% |████████████████████████████████| 184kB 6.3MB/s
Requirement already satisfied: amqp<3.0,>=2.1.4 in ./.venv/lib/python2.7/site-packages (from kombu==4.1.0) (2.2.2)
Requirement already satisfied: vine>=1.1.3 in ./.venv/lib/python2.7/site-packages (from amqp<3.0,>=2.1.4->kombu==4.1.0) (1.1.4)
indico-migrate 1.0.2 has requirement indico<2.1.dev0,>=2.0, but you'll have indico 2.1 which is incompatible.
Installing collected packages: kombu
  Found existing installation: kombu 4.2.0
    Uninstalling kombu-4.2.0:
      Successfully uninstalled kombu-4.2.0
Successfully installed kombu-4.1.0
(.venv)[indico@indico ~]$
(.venv)[indico@indico ~]$ exit

Now the indico-celery process starts normally with 4 workers:

root@indico log # ps -ef|grep celery
indico   13408     1  2 18:31 ?        00:00:08 /opt/indico/.venv/bin/python /opt/indico/.venv/bin/indico celery worker -B
indico   13416 13408  0 18:31 ?        00:00:00 /opt/indico/.venv/bin/python /opt/indico/.venv/bin/indico celery worker -B
indico   13417 13408  0 18:31 ?        00:00:00 /opt/indico/.venv/bin/python /opt/indico/.venv/bin/indico celery worker -B
indico   13418 13408  0 18:31 ?        00:00:00 /opt/indico/.venv/bin/python /opt/indico/.venv/bin/indico celery worker -B

And all of my test emails are now being delivered. Looks like that was it.

Thank you!