Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Can't Connect to DB on first run #835

Open
kousu opened this issue Jul 4, 2018 · 5 comments
Open

Can't Connect to DB on first run #835

kousu opened this issue Jul 4, 2018 · 5 comments

Comments

@kousu
Copy link

kousu commented Jul 4, 2018 •
edited
Loading

I just reinstall Sous-Chef fresh (see: #834) so I could work on it, and received "Can't connect to MySQL server on 'db' (111)".

Fuller log:

[nguenthe@papyrus sous-chef]$  docker-compose -f docker-compose.yml -f docker-compose.override.yml up
[...]
Successfully tagged sous-chef_web:latest
WARNING: Image for service web was built because it did not already exist. To rebuild this image you must use `docker-compose build` or `docker-compose up --build`.
Creating sous-chef_db_1 ... done
Creating sous-chef_web_1 ... done
Attaching to sous-chef_db_1, sous-chef_web_1
db_1   | Initializing database
db_1   | 
db_1   | 
db_1   | PLEASE REMEMBER TO SET A PASSWORD FOR THE MariaDB root USER !
db_1   | To do so, start the server, then issue the following commands:
db_1   | 
db_1   | '/usr/bin/mysqladmin' -u root password 'new-password'
db_1   | '/usr/bin/mysqladmin' -u root -h  password 'new-password'
db_1   | 
db_1   | Alternatively you can run:
db_1   | '/usr/bin/mysql_secure_installation'
db_1   | 
db_1   | which will also give you the option of removing the test
db_1   | databases and anonymous user created by default.  This is
db_1   | strongly recommended for production servers.
db_1   | 
db_1   | See the MariaDB Knowledgebase at http://mariadb.com/kb or the
db_1   | MySQL manual for more instructions.
db_1   | 
db_1   | Please report any problems at http://mariadb.org/jira
db_1   | 
db_1   | The latest information about MariaDB is available at http://mariadb.org/.
db_1   | You can find additional information about the MySQL part at:
db_1   | http://dev.mysql.com
db_1   | Consider joining MariaDB's strong and vibrant community:
db_1   | https://mariadb.org/get-involved/
db_1   | 
db_1   | Database initialized
db_1   | MySQL init process in progress...
db_1   | 2018-07-04 19:36:20 0 [Note] mysqld (mysqld 10.3.8-MariaDB-1:10.3.8+maria~jessie) starting as process 104 ...
db_1   | 2018-07-04 19:36:20 0 [Note] InnoDB: Using Linux native AIO
db_1   | 2018-07-04 19:36:20 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
db_1   | 2018-07-04 19:36:20 0 [Note] InnoDB: Uses event mutexes
db_1   | 2018-07-04 19:36:20 0 [Note] InnoDB: Compressed tables use zlib 1.2.8
db_1   | 2018-07-04 19:36:20 0 [Note] InnoDB: Number of pools: 1
db_1   | 2018-07-04 19:36:20 0 [Note] InnoDB: Using SSE2 crc32 instructions
db_1   | 2018-07-04 19:36:20 0 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk size = 128M
db_1   | 2018-07-04 19:36:20 0 [Note] InnoDB: Completed initialization of buffer pool
db_1   | 2018-07-04 19:36:20 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
db_1   | 2018-07-04 19:36:20 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
db_1   | 2018-07-04 19:36:20 0 [Note] InnoDB: Creating shared tablespace for temporary tables
db_1   | 2018-07-04 19:36:20 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
db_1   | 2018-07-04 19:36:20 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
db_1   | 2018-07-04 19:36:20 0 [Note] InnoDB: Waiting for purge to start
db_1   | 2018-07-04 19:36:20 0 [Note] InnoDB: 10.3.8 started; log sequence number 1630815; transaction id 21
db_1   | 2018-07-04 19:36:20 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
db_1   | 2018-07-04 19:36:20 0 [Note] Plugin 'FEEDBACK' is disabled.
db_1   | 2018-07-04 19:36:20 0 [Note] InnoDB: Buffer pool(s) load completed at 180704 19:36:20
db_1   | 2018-07-04 19:36:20 0 [Warning] 'user' entry 'root@f37f4a379be0' ignored in --skip-name-resolve mode.
db_1   | 2018-07-04 19:36:20 0 [Warning] 'user' entry '@f37f4a379be0' ignored in --skip-name-resolve mode.
db_1   | 2018-07-04 19:36:20 0 [Warning] 'proxies_priv' entry '@% root@f37f4a379be0' ignored in --skip-name-resolve mode.
db_1   | 2018-07-04 19:36:20 0 [Note] Reading of all Master_info entries succeded
db_1   | 2018-07-04 19:36:20 0 [Note] Added new Master_info '' to hash table
db_1   | 2018-07-04 19:36:20 0 [Note] mysqld: ready for connections.
db_1   | Version: '10.3.8-MariaDB-1:10.3.8+maria~jessie'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  mariadb.org binary distribution

db_1   | Warning: Unable to load '/usr/share/zoneinfo/leap-seconds.list' as time zone. Skipping it.
web_1  | Performing system checks...
web_1  | 
web_1  | Unhandled exception in thread started by <function check_errors.<locals>.wrapper at 0x7f0bc2072d90>
web_1  | Traceback (most recent call last):
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/db/backends/base/base.py", line 213, in ensure_connection
web_1  |     self.connect()
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/db/backends/base/base.py", line 189, in connect
web_1  |     self.connection = self.get_new_connection(conn_params)
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/db/backends/mysql/base.py", line 274, in get_new_connection
web_1  |     conn = Database.connect(**conn_params)
web_1  |   File "/usr/local/lib/python3.5/site-packages/MySQLdb/__init__.py", line 85, in Connect
web_1  |     return Connection(*args, **kwargs)
web_1  |   File "/usr/local/lib/python3.5/site-packages/MySQLdb/connections.py", line 204, in __init__
web_1  |     super(Connection, self).__init__(*args, **kwargs2)
web_1  | _mysql_exceptions.OperationalError: (2003, "Can't connect to MySQL server on 'db' (111)")
web_1  | 
web_1  | The above exception was the direct cause of the following exception:
web_1  | 
web_1  | Traceback (most recent call last):
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/utils/autoreload.py", line 228, in wrapper
web_1  |     fn(*args, **kwargs)
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/core/management/commands/runserver.py", line 124, in inner_run
web_1  |     self.check(display_num_errors=True)
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/core/management/base.py", line 359, in check
web_1  |     include_deployment_checks=include_deployment_checks,
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/core/management/base.py", line 346, in _run_checks
web_1  |     return checks.run_checks(**kwargs)
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/core/checks/registry.py", line 81, in run_checks
web_1  |     new_errors = check(app_configs=app_configs)
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/core/checks/model_checks.py", line 30, in check_all_models
web_1  |     errors.extend(model.check(**kwargs))
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/db/models/base.py", line 1284, in check
web_1  |     errors.extend(cls._check_fields(**kwargs))
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/db/models/base.py", line 1359, in _check_fields
web_1  |     errors.extend(field.check(**kwargs))
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/db/models/fields/__init__.py", line 913, in check
web_1  |     errors = super(AutoField, self).check(**kwargs)
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/db/models/fields/__init__.py", line 219, in check
web_1  |     errors.extend(self._check_backend_specific_checks(**kwargs))
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/db/models/fields/__init__.py", line 322, in _check_backend_specific_checks
web_1  |     return connections[db].validation.check_field(self, **kwargs)
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/db/backends/mysql/validation.py", line 49, in check_field
web_1  |     field_type = field.db_type(self.connection)
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/db/models/fields/__init__.py", line 644, in db_type
web_1  |     return connection.data_types[self.get_internal_type()] % data
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/utils/functional.py", line 35, in __get__
web_1  |     res = instance.__dict__[self.name] = self.func(instance)
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/db/backends/mysql/base.py", line 174, in data_types
web_1  |     if self.features.supports_microsecond_precision:
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/utils/functional.py", line 35, in __get__
web_1  |     res = instance.__dict__[self.name] = self.func(instance)
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/db/backends/mysql/features.py", line 53, in supports_microsecond_precision
web_1  |     return self.connection.mysql_version >= (5, 6, 4) and Database.version_info >= (1, 2, 5)
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/utils/functional.py", line 35, in __get__
web_1  |     res = instance.__dict__[self.name] = self.func(instance)
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/db/backends/mysql/base.py", line 385, in mysql_version
web_1  |     with self.temporary_connection() as cursor:
web_1  |   File "/usr/local/lib/python3.5/contextlib.py", line 59, in __enter__
web_1  |     return next(self.gen)
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/db/backends/base/base.py", line 591, in temporary_connection
web_1  |     cursor = self.cursor()
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/db/backends/base/base.py", line 254, in cursor
web_1  |     return self._cursor()
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/db/backends/base/base.py", line 229, in _cursor
web_1  |     self.ensure_connection()
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/db/backends/base/base.py", line 213, in ensure_connection
web_1  |     self.connect()
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/db/utils.py", line 94, in __exit__
web_1  |     six.reraise(dj_exc_type, dj_exc_value, traceback)
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/utils/six.py", line 685, in reraise
web_1  |     raise value.with_traceback(tb)
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/db/backends/base/base.py", line 213, in ensure_connection
web_1  |     self.connect()
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/db/backends/base/base.py", line 189, in connect
web_1  |     self.connection = self.get_new_connection(conn_params)
web_1  |   File "/usr/local/lib/python3.5/site-packages/django/db/backends/mysql/base.py", line 274, in get_new_connection
web_1  |     conn = Database.connect(**conn_params)
web_1  |   File "/usr/local/lib/python3.5/site-packages/MySQLdb/__init__.py", line 85, in Connect
web_1  |     return Connection(*args, **kwargs)
web_1  |   File "/usr/local/lib/python3.5/site-packages/MySQLdb/connections.py", line 204, in __init__
web_1  |     super(Connection, self).__init__(*args, **kwargs2)
web_1  | django.db.utils.OperationalError: (2003, "Can't connect to MySQL server on 'db' (111)")
db_1   | 2018-07-04 19:36:29 10 [Warning] 'proxies_priv' entry '@% root@f37f4a379be0' ignored in --skip-name-resolve mode.
db_1   | 
db_1   | 2018-07-04 19:36:29 0 [Note] mysqld (initiated by: unknown): Normal shutdown
db_1   | 2018-07-04 19:36:29 0 [Note] InnoDB: FTS optimize thread exiting.
db_1   | 2018-07-04 19:36:29 0 [Note] Event Scheduler: Purging the queue. 0 events
db_1   | 2018-07-04 19:36:29 0 [Note] InnoDB: Starting shutdown...
db_1   | 2018-07-04 19:36:29 0 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool
db_1   | 2018-07-04 19:36:29 0 [Note] InnoDB: Buffer pool(s) dump completed at 180704 19:36:29
db_1   | 2018-07-04 19:36:30 0 [Note] InnoDB: Shutdown completed; log sequence number 1630824; transaction id 24
db_1   | 2018-07-04 19:36:30 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
db_1   | 2018-07-04 19:36:30 0 [Note] mysqld: Shutdown complete
db_1   | 
db_1   | 
db_1   | MySQL init process done. Ready for start up.
db_1   | 
db_1   | 2018-07-04 19:36:30 0 [Note] mysqld (mysqld 10.3.8-MariaDB-1:10.3.8+maria~jessie) starting as process 1 ...
db_1   | 2018-07-04 19:36:30 0 [Note] InnoDB: Using Linux native AIO
db_1   | 2018-07-04 19:36:30 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
db_1   | 2018-07-04 19:36:30 0 [Note] InnoDB: Uses event mutexes
db_1   | 2018-07-04 19:36:30 0 [Note] InnoDB: Compressed tables use zlib 1.2.8
db_1   | 2018-07-04 19:36:30 0 [Note] InnoDB: Number of pools: 1
db_1   | 2018-07-04 19:36:30 0 [Note] InnoDB: Using SSE2 crc32 instructions
db_1   | 2018-07-04 19:36:30 0 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk size = 128M
db_1   | 2018-07-04 19:36:30 0 [Note] InnoDB: Completed initialization of buffer pool
db_1   | 2018-07-04 19:36:30 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
db_1   | 2018-07-04 19:36:30 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
db_1   | 2018-07-04 19:36:30 0 [Note] InnoDB: Creating shared tablespace for temporary tables
db_1   | 2018-07-04 19:36:30 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
db_1   | 2018-07-04 19:36:30 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
db_1   | 2018-07-04 19:36:30 0 [Note] InnoDB: 10.3.8 started; log sequence number 1630824; transaction id 21
db_1   | 2018-07-04 19:36:30 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
db_1   | 2018-07-04 19:36:30 0 [Note] Plugin 'FEEDBACK' is disabled.
db_1   | 2018-07-04 19:36:30 0 [Note] Server socket created on IP: '::'.
db_1   | 2018-07-04 19:36:30 0 [Note] InnoDB: Buffer pool(s) load completed at 180704 19:36:30
db_1   | 2018-07-04 19:36:30 0 [Warning] 'proxies_priv' entry '@% root@f37f4a379be0' ignored in --skip-name-resolve mode.
db_1   | 2018-07-04 19:36:30 0 [Note] Reading of all Master_info entries succeded
db_1   | 2018-07-04 19:36:30 0 [Note] Added new Master_info '' to hash table
db_1   | 2018-07-04 19:36:30 0 [Note] mysqld: ready for connections.
db_1   | Version: '10.3.8-MariaDB-1:10.3.8+maria~jessie'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution

and then trying to go to http://localhost:8000 just gets a RST.
@kousu
Copy link
Author

kousu commented Jul 4, 2018

Stopping and restarting it fixed it:


^CGracefully stopping... (press Ctrl+C again to force)
Stopping sous-chef_web_1 ... done
Stopping sous-chef_db_1  ... done
[nguenthe@papyrus sous-chef]$  docker-compose -f docker-compose.yml -f docker-compose.override.yml up
WARNING: Some networks were defined but are not used by any service: frontend
Starting sous-chef_db_1 ... done
Starting sous-chef_web_1 ... done
Attaching to sous-chef_db_1, sous-chef_web_1
db_1   | 2018-07-04 19:55:58 0 [Note] mysqld (mysqld 10.3.8-MariaDB-1:10.3.8+maria~jessie) starting as process 1 ...
db_1   | 2018-07-04 19:55:58 0 [Note] InnoDB: Using Linux native AIO
db_1   | 2018-07-04 19:55:58 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
db_1   | 2018-07-04 19:55:58 0 [Note] InnoDB: Uses event mutexes
db_1   | 2018-07-04 19:55:58 0 [Note] InnoDB: Compressed tables use zlib 1.2.8
db_1   | 2018-07-04 19:55:58 0 [Note] InnoDB: Number of pools: 1
db_1   | 2018-07-04 19:55:58 0 [Note] InnoDB: Using SSE2 crc32 instructions
db_1   | 2018-07-04 19:55:58 0 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk size = 128M
db_1   | 2018-07-04 19:55:58 0 [Note] InnoDB: Completed initialization of buffer pool
db_1   | 2018-07-04 19:55:58 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
db_1   | 2018-07-04 19:55:58 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
db_1   | 2018-07-04 19:55:58 0 [Note] InnoDB: Creating shared tablespace for temporary tables
db_1   | 2018-07-04 19:55:58 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
db_1   | 2018-07-04 19:55:58 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
db_1   | 2018-07-04 19:55:58 0 [Note] InnoDB: Waiting for purge to start
db_1   | 2018-07-04 19:55:58 0 [Note] InnoDB: 10.3.8 started; log sequence number 1630833; transaction id 21
db_1   | 2018-07-04 19:55:58 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
db_1   | 2018-07-04 19:55:58 0 [Note] Plugin 'FEEDBACK' is disabled.
db_1   | 2018-07-04 19:55:58 0 [Note] Server socket created on IP: '::'.
db_1   | 2018-07-04 19:55:58 0 [Note] InnoDB: Buffer pool(s) load completed at 180704 19:55:58
db_1   | 2018-07-04 19:55:58 0 [Warning] 'proxies_priv' entry '@% root@f37f4a379be0' ignored in --skip-name-resolve mode.
db_1   | 2018-07-04 19:55:58 0 [Note] Reading of all Master_info entries succeded
db_1   | 2018-07-04 19:55:58 0 [Note] Added new Master_info '' to hash table
db_1   | 2018-07-04 19:55:58 0 [Note] mysqld: ready for connections.
db_1   | Version: '10.3.8-MariaDB-1:10.3.8+maria~jessie'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution
web_1  | Performing system checks...
web_1  | 
web_1  | System check identified no issues (0 silenced).
web_1  | 
web_1  | You have 88 unapplied migration(s). Your project may not work properly until you apply the migrations for app(s): admin, auth, avatar, billing, contenttypes, delivery, meal, member, note, notification, order, sessions.
web_1  | Run 'python manage.py migrate' to apply them.
web_1  | July 04, 2018 - 15:56:08
web_1  | Django version 1.11.14, using settings 'sous_chef.settings'
web_1  | Starting development server at http://0.0.0.0:8000/
web_1  | Quit the server with CONTROL-C.

I believe this is a known issue---something something docker something---it's even mentioned in the docs, but it's annoying and I would like to open a bug to track getting it fixed.

@kousu kousu changed the title Startup Errors Can't Connect to DB on first run Jul 4, 2018
@erozqba
Copy link
Contributor

erozqba commented Jul 6, 2018

It's out of the scope of sou-chef, its docker related because the first time MySQL container its initialized, it takes too much time to setup and creates the database.. the Web container it's a lot faster and makes the first request before the MySQL service inside the MySQL container is ready.

@kousu
Copy link
Author

kousu commented Jul 27, 2018

Respectfully, I don't think it is out of scope. Everything from git clone to a working Sous-Chef instance in the install guide should be in scope. This issue makes Sous-Chef appear unreliable, and it's a turn off for newbie devs.

I don't mind doing the research and work to fix this myself, if you are willing to take a PR to fix it.

@erozqba
Copy link
Contributor

erozqba commented Jul 31, 2018

Thanks @kousu I will be happy to take a PR :)

@kousu
Copy link
Author

kousu commented Jul 31, 2018 via email

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@kousu @erozqba and others