[bug] Django migration fails: possibly misconfigured celerydb

[Doralitze]

when running the playbook the step openwisp.openwisp2 : migrate fails.

This is the stack trace:

stdout: Operations to perform:
  Apply all migrations: account, admin, auth, authtoken, config, connection, contenttypes, geo, openwisp_notifications, openwisp_users, pki, reversion, sessions, sites, socialaccount, topology
Running migrations:
  Applying authtoken.0001_initial... OK
  Applying authtoken.0002_auto_20160226_1747... OK
  Applying config.0029_merge_django_netjsonconfig... OK
  Applying config.0030_django_taggit_update... OK
  Applying config.0031_update_vpn_dh_param... OK
  Applying config.0032_update_legacy_vpn_backend... OK
  Applying connection.0004_django3_1_upgrade... OK
  Applying connection.0005_device_connection_failure_reason... OK
  Applying openwisp_users.0008_update_admins_permissions... OK
  Applying openwisp_users.0009_create_organization_owners... OK
  Applying openwisp_notifications.0001_initial... OK
  Applying openwisp_notifications.0002_default_permissions... OK
  Applying openwisp_notifications.0003_notification_notification_type... OK
  Applying openwisp_notifications.0004_notificationsetting... OK
  Applying openwisp_notifications.0005_delete_notificationuser...
:stderr: Traceback (most recent call last):
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/utils/functional.py", line 43, in __call__
    return self.__value__
AttributeError: 'ChannelPromise' object has no attribute '__value__'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/transport/virtual/base.py", line 921, in create_channel
    return self._avail_channels.pop()
IndexError: pop from empty list

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/connection.py", line 454, in _reraise_as_library_errors
    yield
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/connection.py", line 445, in _ensure_connection
    callback, timeout=timeout
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/utils/functional.py", line 344, in retry_over_time
    return fun(*args, **kwargs)
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/connection.py", line 874, in _connection_factory
    self._connection = self._establish_connection()
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/connection.py", line 809, in _establish_connection
    conn = self.transport.establish_connection()
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/transport/virtual/base.py", line 941, in establish_connection
    self._avail_channels.append(self.create_channel(self))
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/transport/virtual/base.py", line 923, in create_channel
    channel = self.Channel(connection)
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/transport/redis.py", line 522, in __init__
    self.client.ping()
  File "/opt/openwisp2/env/lib/python3.6/site-packages/redis/client.py", line 1351, in ping
    return self.execute_command('PING')
  File "/opt/openwisp2/env/lib/python3.6/site-packages/redis/client.py", line 875, in execute_command
    conn = self.connection or pool.get_connection(command_name, **options)
  File "/opt/openwisp2/env/lib/python3.6/site-packages/redis/connection.py", line 1185, in get_connection
    connection.connect()
  File "/opt/openwisp2/env/lib/python3.6/site-packages/redis/connection.py", line 561, in connect
    self.on_connect()
  File "/opt/openwisp2/env/lib/python3.6/site-packages/redis/connection.py", line 658, in on_connect
    if nativestr(self.read_response()) != 'OK':
  File "/opt/openwisp2/env/lib/python3.6/site-packages/redis/connection.py", line 752, in read_response
    raise response
redis.exceptions.ResponseError: DB index is out of range

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "./manage.py", line 10, in <module>
    execute_from_command_line(sys.argv)
  File "/opt/openwisp2/env/lib/python3.6/site-packages/django/core/management/__init__.py", line 401, in execute_from_command_line
    utility.execute()
  File "/opt/openwisp2/env/lib/python3.6/site-packages/django/core/management/__init__.py", line 395, in execute
    self.fetch_command(subcommand).run_from_argv(self.argv)
  File "/opt/openwisp2/env/lib/python3.6/site-packages/django/core/management/base.py", line 328, in run_from_argv
    self.execute(*args, **cmd_options)
  File "/opt/openwisp2/env/lib/python3.6/site-packages/django/core/management/base.py", line 369, in execute
    output = self.handle(*args, **options)
  File "/opt/openwisp2/env/lib/python3.6/site-packages/django/core/management/base.py", line 83, in wrapped
    res = handle_func(*args, **kwargs)
  File "/opt/openwisp2/env/lib/python3.6/site-packages/django/core/management/commands/migrate.py", line 233, in handle
    fake_initial=fake_initial,
  File "/opt/openwisp2/env/lib/python3.6/site-packages/django/db/migrations/executor.py", line 117, in migrate
    state = self._migrate_all_forwards(state, plan, full_plan, fake=fake, fake_initial=fake_initial)
  File "/opt/openwisp2/env/lib/python3.6/site-packages/django/db/migrations/executor.py", line 147, in _migrate_all_forwards
    state = self.apply_migration(state, migration, fake=fake, fake_initial=fake_initial)
  File "/opt/openwisp2/env/lib/python3.6/site-packages/django/db/migrations/executor.py", line 245, in apply_migration
    state = migration.apply(state, schema_editor)
  File "/opt/openwisp2/env/lib/python3.6/site-packages/django/db/migrations/migration.py", line 124, in apply
    operation.database_forwards(self.app_label, schema_editor, old_state, project_state)
  File "/opt/openwisp2/env/lib/python3.6/site-packages/django/db/migrations/operations/special.py", line 190, in database_forwards
    self.code(from_state.apps, schema_editor)
  File "/opt/openwisp2/env/lib/python3.6/site-packages/openwisp_notifications/migrations/0005_delete_notificationuser.py", line 11, in delete_notification_user_permissions
    content_type__model='notificationuser',
  File "/opt/openwisp2/env/lib/python3.6/site-packages/django/db/models/query.py", line 722, in delete
    deleted, _rows_count = collector.delete()
  File "/opt/openwisp2/env/lib/python3.6/site-packages/django/db/models/deletion.py", line 309, in delete
    sender=model, instance=obj, using=self.using
  File "/opt/openwisp2/env/lib/python3.6/site-packages/django/dispatch/dispatcher.py", line 175, in send
    for receiver in self._live_receivers(sender)
  File "/opt/openwisp2/env/lib/python3.6/site-packages/django/dispatch/dispatcher.py", line 175, in <listcomp>
    for receiver in self._live_receivers(sender)
  File "/opt/openwisp2/env/lib/python3.6/site-packages/openwisp_notifications/handlers.py", line 248, in related_object_deleted
    instance_app_label, instance_model, instance_id
  File "/opt/openwisp2/env/lib/python3.6/site-packages/celery/app/task.py", line 424, in delay
    return self.apply_async(args, kwargs)
  File "/opt/openwisp2/env/lib/python3.6/site-packages/celery/app/task.py", line 568, in apply_async
    **options
  File "/opt/openwisp2/env/lib/python3.6/site-packages/celery/app/base.py", line 780, in send_task
    amqp.send_task_message(P, name, message, **options)
  File "/opt/openwisp2/env/lib/python3.6/site-packages/celery/app/amqp.py", line 559, in send_task_message
    **properties
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/messaging.py", line 181, in publish
    exchange_name, declare,
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/connection.py", line 533, in _ensured
    return fun(*args, **kwargs)
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/messaging.py", line 187, in _publish
    channel = self.channel
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/messaging.py", line 209, in _get_channel
    channel = self._channel = channel()
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/utils/functional.py", line 45, in __call__
    value = self.__value__ = self.__contract__()
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/messaging.py", line 224, in <lambda>
    channel = ChannelPromise(lambda: connection.default_channel)
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/connection.py", line 892, in default_channel
    self._ensure_connection(**conn_opts)
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/connection.py", line 445, in _ensure_connection
    callback, timeout=timeout
  File "/usr/lib/python3.6/contextlib.py", line 99, in __exit__
    self.gen.throw(type, value, traceback)
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/connection.py", line 459, in _reraise_as_library_errors
    sys.exc_info()[2])
  File "/opt/openwisp2/env/lib/python3.6/site-packages/vine/five.py", line 194, in reraise
    raise value.with_traceback(tb)
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/connection.py", line 454, in _reraise_as_library_errors
    yield
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/connection.py", line 445, in _ensure_connection
    callback, timeout=timeout
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/utils/functional.py", line 344, in retry_over_time
    return fun(*args, **kwargs)
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/connection.py", line 874, in _connection_factory
    self._connection = self._establish_connection()
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/connection.py", line 809, in _establish_connection
    conn = self.transport.establish_connection()
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/transport/virtual/base.py", line 941, in establish_connection
    self._avail_channels.append(self.create_channel(self))
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/transport/virtual/base.py", line 923, in create_channel
    channel = self.Channel(connection)
  File "/opt/openwisp2/env/lib/python3.6/site-packages/kombu/transport/redis.py", line 522, in __init__
    self.client.ping()
  File "/opt/openwisp2/env/lib/python3.6/site-packages/redis/client.py", line 1351, in ping
    return self.execute_command('PING')
  File "/opt/openwisp2/env/lib/python3.6/site-packages/redis/client.py", line 875, in execute_command
    conn = self.connection or pool.get_connection(command_name, **options)
  File "/opt/openwisp2/env/lib/python3.6/site-packages/redis/connection.py", line 1185, in get_connection
    connection.connect()
  File "/opt/openwisp2/env/lib/python3.6/site-packages/redis/connection.py", line 561, in connect
    self.on_connect()
  File "/opt/openwisp2/env/lib/python3.6/site-packages/redis/connection.py", line 658, in on_connect
    if nativestr(self.read_response()) != 'OK':
  File "/opt/openwisp2/env/lib/python3.6/site-packages/redis/connection.py", line 752, in read_response
    raise response
kombu.exceptions.OperationalError: DB index is out of range

According to this issue this is a misconfiguration of the celery database connection hence Iḿ reporting this here.

In case it's useful I've posted my playbook configuration below:

openwisp2_default_from_email: "ow@openwisp.technikradio.org"
    openwisp2_network_topology: true
    openwisp2_ssl_cert: /usr/local/etc/cert/fullchain.pem
    openwisp2_ssl_key: /usr/local/etc/cert/privkey.pem
    openwisp2_nginx_client_max_body_size: 1024M
    openwisp2_nginx_ssl_config:
        gzip: "off"
    openwisp2_nginx_http2: false
    openwisp2_extra_python_packages:
        - django_extensions
    openwisp2_redis_cache_url: redis://127.0.0.1:6379/1
    openwisp_database_user: openwisp
    openwisp_database_name: openwisp2
    openwisp2_database:
            engine: "django.contrib.gis.db.backends.postgis"
            name: "{{ openwisp_database_name }}"
            user: "{{ openwisp_database_user }}"
            password: "{{ openwisp_database_password }}"
            host: "127.0.0.1"
            port: "5432"
            options: {}

I'm hoping someone can help me with this.

[pandafy]

@Doralitze what is the OS of the target machine?

[Doralitze]

@Doralitze what is the OS of the target machine?

output from uname -a: Linux openwispcontroller 4.15.0-143-generic #147-Ubuntu SMP Wed Apr 14 16:10:11 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

output from lsb_release -a:

No LSB modules are available.
Distributor ID:	Ubuntu
Description:	Ubuntu 18.04.5 LTS
Release:	18.04
Codename:	bionic

[pandafy]

Hi @Doralitze, I was not able to replicate this issue on my Ubuntu 18.04 machine. But, here are some pointers to help us find out the possible reason for this error.

1. Check CELERY_BROKER_URL settings in /opt/openwisp2/openwisp2/settings.py. You should get same output after running this command

# cat /opt/openwisp2/openwisp2/settings.py | grep CELERY_BROKER_URL
     CELERY_BROKER_URL = 'redis://localhost:6379/3'
     CELERY_BROKER_URL = 'memory://'

2. Check the number of databases in redis.conf

# cat /etc/redis/redis.conf | grep databases
# Set the number of databases. The default database is DB 0, you can select
# dbid is a number between 0 and 'databases'-1
databases 16
# Compress string objects using LZF when dump .rdb databases?

In this example, the number of databases is 16

Alternatively, you can check via redis-cli

127.0.0.1:6379> INFO keyspace
# Keyspace
db3:keys=4,expires=0,avg_ttl=0

[Doralitze]

Hi @pandafy

I was following your steps

Check CELERY_BROKER_URL settings in /opt/openwisp2/openwisp2/settings.py. You should get same output after running this command

I indeed I got the same result.

    CELERY_BROKER_URL = 'redis://localhost:6379/3'
    CELERY_BROKER_URL = 'memory://'

Check the number of databases in redis.conf

Said command outputs databases 3 instead of databases 16. So I changed my playbook accordingly and voila it works. Since when does openwisp use that may redis databses?

Thanks a lot for your help dough!

[Doralitze]

A quick grep of the README revealed that celery uses Database 3 by default and since redis databases are 0 indexed it couldn't have worked. Looks like i missed that when upgrading my controller instance. I'm truly sorry that I wasted your time for something that collapses to RTFM but I'm really glad you put me on the right spot. Again: Thanks a lot for your help.

[pandafy]

No worries @Doralitze! It was a learning experience for me as well. I am glad that you got it working. 👍🏼