Issue: Problem with MySQL connections
Author: felipevolpone
State: closed
Created: 2016-06-03 17:10:56

Hey guys, 

I've been facing a problem with peewee in the last days. I'm getting these errors: "Lost connection to MySQL server during query" and "MySQL server has gone away". The problem happens after the timeout time configured on MySQL, I changed it to 120 seconds to test faster. This is my scenario:
I run the server and do the first request: everything works.
After 120 seconds I do the second request: I got the error message.

I read all the issues in github and read the documentation, but I can't figure out whats is going on.

I'm using webapp2 and before each request I have:

``` python
from functools import wraps

def database_connection(func):
    @wraps(func)
    def inner(*args, **kwargs):
        database.connect()
        try:
            return func(*args, **kwargs)
        finally:
            if not database.is_closed():
                database.close()
    return inner
```

I'm using the connection pool:

``` python

import peewee, settings
from playhouse.pool import PooledMySQLDatabase


database = PooledMySQLDatabase(settings.db_DBNAME, host=settings.db_HOST, user=settings.db_USER,
                               passwd=settings.db_PASSWORD, max_connections=8, stale_timeout=110,
                               threadlocals=True)


class MySQLModel(peewee.Model):
    class Meta:
        database = database

```

I tried to use MyRetryDB(RetryOperationalError, PooledMySQLDatabase) but it didn't solved the problem.

PS: I'm using Google Cloud SQL as MySQL SaaS.
PS2: I'm using MySQL-python==1.2.3

Any help it would be awesome.
Thank for all your effort to develop this project :) :+1: 


Weird..have you tried enabling the peewee logger and adding logging statements around your db connect/close code? That might help diagnose where things are going wrong.

You can enable the peewee debugger by following these instructions: http://docs.peewee-orm.com/en/latest/peewee/database.html#logging-queries

There's another logger in the `peewee.pool` namespace that should get picked up as well, so be sure to keep an eye out for that.

Try enabling the logger and letting me know where the error occurs? Or alternatively, could you share the whole traceback?


Hi @coleifer, I put a print when I call database.open and database.close and both methods are being called and logged.

Here is the entire log. You can see the calls to my backend and the peewee log

``` bash
No connection available in pool.
Created new connection 23380784.
('INSERT INTO `log` (`owner`, `action`, `date`, `value`) VALUES (%s, %s, %s, %s)', [None, u'RegisterService', 1465147903, u'{"request_json": {"phone": "1111111111", "meta": {"rooted": "false", "app": "1.0", "appversion": "1.0", "Carrier": "Claro", "device_id": "12321", "OSVersion": "4.4", "gps": "13.03;15.033"}, "type": "buyer", "cpf": "1111111111"}, "mobile_meta_info": {"rooted": "false", "app": "1.0", "appversion": "1.0", "Carrier": "Claro", "device_id": "12321", "OSVersion": "4.4", "gps": "13.03;15.033"}, "method": "POST", "custom": {}}'])
('SELECT `t1`.`id`, `t1`.`name`, `t1`.`email`, `t1`.`profile`, `t1`.`cpf`, `t1`.`rg`, `t1`.`birthday`, `t1`.`ddd`, `t1`.`phone`, `t1`.`gender`, `t1`.`device_uuid`, `t1`.`city`, `t1`.`state`, `t1`.`address`, `t1`.`house_number`, `t1`.`neighborhood`, `t1`.`cep`, `t1`.`push_token` FROM `user` AS t1 WHERE (`t1`.`cpf` = %s)', [u'1111111111'])
('SELECT `t1`.`id`, `t1`.`name`, `t1`.`email`, `t1`.`profile`, `t1`.`cpf`, `t1`.`rg`, `t1`.`birthday`, `t1`.`ddd`, `t1`.`phone`, `t1`.`gender`, `t1`.`device_uuid`, `t1`.`city`, `t1`.`state`, `t1`.`address`, `t1`.`house_number`, `t1`.`neighborhood`, `t1`.`cep`, `t1`.`push_token` FROM `user` AS t1 WHERE (`t1`.`phone` = %s)', [u'1111111111'])

('SELECT `t1`.`id`, `t1`.`proposal_id`, `t1`.`account_id`, `t1`.`card_id`, `t1`.`card_number`, `t1`.`card_validation`, `t1`.`user_id`, `t1`.`has_bank_account`, `t1`.`contract_acceptance_date` FROM `customer` AS t1 WHERE (`t1`.`user_id` = %s)', [None])
('SELECT `t1`.`id`, `t1`.`owner_id`, `t1`.`phone_invited`, `t1`.`status`, `t1`.`token` FROM `invite` AS t1 WHERE (`t1`.`phone_invited` = %s)', [u'1111111111'])
Method name: ORIGINA_CLIENTE
Parameters used: ["1111111111", "11111111", "12321", 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, "11", 1, {"empresa": "20937849000101", "fluxo": "ORIGINA_CLIENTE", "senha": "x", "usuario": "x"}]
Parameters used: {}
('INSERT INTO `log` (`owner`, `action`, `date`, `value`) VALUES (%s, %s, %s, %s)', [None, u'ORIGINA_CLIENTE', 1465147906, u'{"method": "GET", "custom": {"params": ["1111111111", "11111111", "12321", 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, "11", 1, {"empresa": "20937849000101", "fluxo": "ORIGINA_CLIENTE", "senha": "x", "usuario": "x"}, {}], "value": {"processReturn": {"ticket": "414D5120514D2E524F434B45542020201D884F57035B1C20", "variaveisContexto": "", "hash": "4380401e6d6a09706e6d08e24ebd40f6"}}}}'])
('INSERT INTO `user` (`profile`, `cpf`, `ddd`, `phone`, `device_uuid`) VALUES (%s, %s, %s, %s, %s)', [u'buyer', u'1111111111', u'11', u'1111111111', u'12321'])
('INSERT INTO `rocketresource` (`user_id`, `ticket`, `hash_value`, `token`, `status`) VALUES (%s, %s, %s, %s, %s)', [10, u'414D5120514D2E524F434B45542020201D884F57035B1C20', u'4380401e6d6a09706e6d08e24ebd40f6', u'7749ba85-0d74-430a-a52b-2047177cd9ae', u'waiting_response'])
Returning 23380784 to pool.

[pid: 38|app: 0|req: 1/1] 127.0.0.1 () {48 vars in 825 bytes} [Sun Jun  5 14:31:43 2016] POST /s/user/Register => generated 155 bytes in 3162 msecs (HTTP/1.0 200) 3 headers in 112 bytes (2 switches on core 0)



('INSERT INTO `log` (`owner`, `action`, `date`, `value`) VALUES (%s, %s, %s, %s)', [None, u'MockService', 1465147928, u'{"method": "GET", "custom": {}}'])
Returning 23380784 to pool.
[pid: 38|app: 0|req: 2/2] 127.0.0.1 () {42 vars in 703 bytes} [Sun Jun  5 14:32:08 2016] GET /s/mock/Mock => generated 0 bytes in 18 msecs (HTTP/1.0 403) 3 headers in 110 bytes (1 switches on core 1)



Connection 23380784 was closed.
No connection available in pool.
Created new connection 25864240.
('INSERT INTO `log` (`owner`, `action`, `date`, `value`) VALUES (%s, %s, %s, %s)', [None, u'RegisterService', 1465149152, u'{"request_json": {"phone": "1111111111", "meta": {"rooted": "false", "app": "1.0", "appversion": "1.0", "Carrier": "Claro", "device_id": "12321", "OSVersion": "4.4", "gps": "13.03;15.033"}, "type": "buyer", "cpf": "1111111111"}, "mobile_meta_info": {"rooted": "false", "app": "1.0", "appversion": "1.0", "Carrier": "Claro", "device_id": "12321", "OSVersion": "4.4", "gps": "13.03;15.033"}, "method": "POST", "custom": {}}'])
Returning 25864240 to pool.
ERROR:root:(2006, 'MySQL server has gone away')
Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/webapp2.py", line 1535, in __call__
    rv = self.handle_exception(request, response, e)
  File "/usr/local/lib/python2.7/dist-packages/webapp2.py", line 1529, in __call__
    rv = self.router.dispatch(request, response)
  File "/usr/local/lib/python2.7/dist-packages/webapp2.py", line 1278, in default_dispatcher
    return route.handler_adapter(request, response)
  File "/usr/local/lib/python2.7/dist-packages/webapp2.py", line 1102, in __call__
    return handler.dispatch()
  File "./handler/service_handler.py", line 16, in inner
    return func(*args, **kwargs)
  File "./handler/service_handler.py", line 30, in inner
    result = fnc(*a, **k)
  File "./handler/service_handler.py", line 54, in dispatch
    raise e
OperationalError: (2006, 'MySQL server has gone away')
[pid: 38|app: 0|req: 3/3] 127.0.0.1 () {48 vars in 824 bytes} [Sun Jun  5 14:52:32 2016] POST /s/user/Register => generated 114 bytes in 11 msecs (HTTP/1.0 500) 2 headers in 100 bytes (1 switches on core 0)

```


Very strange... what causes that traceback to happen? It seems like it is not related to the connection pool.


Hi @coleifer, thanks for helping me. I put some logs and the exception is raised when I try to call the create method with one of my models. Check it out:

``` bash
Connection 16238048 was closed.
DEBUG:peewee.pool:Connection 16238048 was closed.
No connection available in pool.
DEBUG:peewee.pool:No connection available in pool.
Created new connection 139681664633120.
DEBUG:peewee.pool:Created new connection 139681664633120.
('INSERT INTO `log` (`owner`, `action`, `date`, `value`) VALUES (%s, %s, %s, %s)', [None, u'RegisterService', 1465213386, u'{"request_json": {"phone": "1111121111", "meta": {"rooted": "false", "app": "1.0", "appversion": "1.0", "Carrier": "Claro", "device_id": "12321", "OSVersion": "4.4", "gps": "13.03;15.033"}, "type": "buyer", "cpf": "2222222222"}, "mobile_meta_info": {"rooted": "false", "app": "1.0", "appversion": "1.0", "Carrier": "Claro", "device_id": "12321", "OSVersion": "4.4", "gps": "13.03;15.033"}, "method": "POST", "custom": {}}'])
DEBUG:peewee:('INSERT INTO `log` (`owner`, `action`, `date`, `value`) VALUES (%s, %s, %s, %s)', [None, u'RegisterService', 1465213386, u'{"request_json": {"phone": "1111121111", "meta": {"rooted": "false", "app": "1.0", "appversion": "1.0", "Carrier": "Claro", "device_id": "12321", "OSVersion": "4.4", "gps": "13.03;15.033"}, "type": "buyer", "cpf": "2222222222"}, "mobile_meta_info": {"rooted": "false", "app": "1.0", "appversion": "1.0", "Carrier": "Claro", "device_id": "12321", "OSVersion": "4.4", "gps": "13.03;15.033"}, "method": "POST", "custom": {}}'])
Returning 139681664633120 to pool.
DEBUG:peewee.pool:Returning 139681664633120 to pool.
ERROR:root:(2006, 'MySQL server has gone away')
Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/webapp2.py", line 1535, in __call__
    rv = self.handle_exception(request, response, e)
  File "/usr/local/lib/python2.7/dist-packages/webapp2.py", line 1529, in __call__
    rv = self.router.dispatch(request, response)
  File "/usr/local/lib/python2.7/dist-packages/webapp2.py", line 1278, in default_dispatcher
    return route.handler_adapter(request, response)
  File "/usr/local/lib/python2.7/dist-packages/webapp2.py", line 1102, in __call__
    return handler.dispatch()
  File "./handler/service_handler.py", line 18, in inner
    return func(*args, **kwargs)
  File "./handler/service_handler.py", line 34, in inner
    result = fnc(*a, **k)
  File "./handler/service_handler.py", line 47, in dispatch
    self.__saving_log(obj)
  File "./handler/service_handler.py", line 75, in __saving_log
    log_helper.log(action=obj.__class__.__name__, method=self.request.method, value=result, request=req)
  File "./helper/log_helper.py", line 42, in log
    return Log.create(owner=user, action=action, value=log_json, date=now)
  File "/usr/local/lib/python2.7/dist-packages/peewee.py", line 4551, in create
    inst.save(force_insert=True)
  File "/usr/local/lib/python2.7/dist-packages/peewee.py", line 4747, in save
    pk_from_cursor = self.insert(**field_dict).execute()
  File "/usr/local/lib/python2.7/dist-packages/peewee.py", line 3244, in execute
    cursor = self._execute()
  File "/usr/local/lib/python2.7/dist-packages/peewee.py", line 2656, in _execute
    return self.database.execute_sql(sql, params, self.require_commit)
  File "/usr/local/lib/python2.7/dist-packages/peewee.py", line 3492, in execute_sql
    self.commit()
  File "/usr/local/lib/python2.7/dist-packages/peewee.py", line 3316, in __exit__
    reraise(new_type, new_type(*exc_args), traceback)
  File "/usr/local/lib/python2.7/dist-packages/peewee.py", line 3485, in execute_sql
    cursor.execute(sql, params or ())
  File "/usr/local/lib/python2.7/dist-packages/MySQLdb/cursors.py", line 174, in execute
    self.errorhandler(self, exc, value)
  File "/usr/local/lib/python2.7/dist-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
    raise errorclass, errorvalue
OperationalError: (2006, 'MySQL server has gone away')
[pid: 38|app: 0|req: 4/4] 127.0.0.1 () {48 vars in 843 bytes} [Mon Jun  6 08:43:06 2016] POST /s/user/Register => generated 114 bytes in 12 msecs (HTTP/1.0 500) 2 headers in 100 bytes (1 switches on core 1)
```


Cool thanks! So hmmm...are there a set of steps you follow to trigger the
error or does it just seem to happen sporadically? What values are you
using for your MySQL server connection timeout, and what is the
stale_timeout on the peewee pool? My thought is if it's random, then you've
just got to turn the pool stale timeout to a value lower than mysqls
timeout. Another option would be to stop using the pool and see how that
goes. Is this db getting a lot of traffic?
On Jun 6, 2016 6:49 AM, "Felipe Volpone" notifications@github.com wrote:

> Hi @coleifer https://github.com/coleifer, thanks for helping me. I put
> some logs and the exception is raised when I try to call the create method
> with one of my models. Check it out:
> 
> Connection 16238048 was closed.
> DEBUG:peewee.pool:Connection 16238048 was closed.
> No connection available in pool.
> DEBUG:peewee.pool:No connection available in pool.
> Created new connection 139681664633120.
> DEBUG:peewee.pool:Created new connection 139681664633120.
> ('INSERT INTO `log` (`owner`, `action`, `date`, `value`) VALUES (%s, %s, %s, %s)', [None, u'RegisterService', 1465213386, u'{"request_json": {"phone": "1111121111", "meta": {"rooted": "false", "app": "1.0", "appversion": "1.0", "Carrier": "Claro", "device_id": "12321", "OSVersion": "4.4", "gps": "13.03;15.033"}, "type": "buyer", "cpf": "2222222222"}, "mobile_meta_info": {"rooted": "false", "app": "1.0", "appversion": "1.0", "Carrier": "Claro", "device_id": "12321", "OSVersion": "4.4", "gps": "13.03;15.033"}, "method": "POST", "custom": {}}'])
> DEBUG:peewee:('INSERT INTO `log` (`owner`, `action`, `date`, `value`) VALUES (%s, %s, %s, %s)', [None, u'RegisterService', 1465213386, u'{"request_json": {"phone": "1111121111", "meta": {"rooted": "false", "app": "1.0", "appversion": "1.0", "Carrier": "Claro", "device_id": "12321", "OSVersion": "4.4", "gps": "13.03;15.033"}, "type": "buyer", "cpf": "2222222222"}, "mobile_meta_info": {"rooted": "false", "app": "1.0", "appversion": "1.0", "Carrier": "Claro", "device_id": "12321", "OSVersion": "4.4", "gps": "13.03;15.033"}, "method": "POST", "custom": {}}'])
> Returning 139681664633120 to pool.
> DEBUG:peewee.pool:Returning 139681664633120 to pool.
> ERROR:root:(2006, 'MySQL server has gone away')
> Traceback (most recent call last):
>   File "/usr/local/lib/python2.7/dist-packages/webapp2.py", line 1535, in **call**
>     rv = self.handle_exception(request, response, e)
>   File "/usr/local/lib/python2.7/dist-packages/webapp2.py", line 1529, in **call**
>     rv = self.router.dispatch(request, response)
>   File "/usr/local/lib/python2.7/dist-packages/webapp2.py", line 1278, in default_dispatcher
>     return route.handler_adapter(request, response)
>   File "/usr/local/lib/python2.7/dist-packages/webapp2.py", line 1102, in **call**
>     return handler.dispatch()
>   File "./handler/service_handler.py", line 18, in inner
>     return func(_args, *_kwargs)
>   File "./handler/service_handler.py", line 34, in inner
>     result = fnc(_a, *_k)
>   File "./handler/service_handler.py", line 47, in dispatch
>     self.**saving_log(obj)
>   File "./handler/service_handler.py", line 75, in __saving_log
>     log_helper.log(action=obj.__class**.**name**, method=self.request.method, value=result, request=req)
>   File "./helper/log_helper.py", line 42, in log
>     return Log.create(owner=user, action=action, value=log_json, date=now)
>   File "/usr/local/lib/python2.7/dist-packages/peewee.py", line 4551, in create
>     inst.save(force_insert=True)
>   File "/usr/local/lib/python2.7/dist-packages/peewee.py", line 4747, in save
>     pk_from_cursor = self.insert(*_field_dict).execute()
>   File "/usr/local/lib/python2.7/dist-packages/peewee.py", line 3244, in execute
>     cursor = self._execute()
>   File "/usr/local/lib/python2.7/dist-packages/peewee.py", line 2656, in _execute
>     return self.database.execute_sql(sql, params, self.require_commit)
>   File "/usr/local/lib/python2.7/dist-packages/peewee.py", line 3492, in execute_sql
>     self.commit()
>   File "/usr/local/lib/python2.7/dist-packages/peewee.py", line 3316, in __exit__
>     reraise(new_type, new_type(_exc_args), traceback)
>   File "/usr/local/lib/python2.7/dist-packages/peewee.py", line 3485, in execute_sql
>     cursor.execute(sql, params or ())
>   File "/usr/local/lib/python2.7/dist-packages/MySQLdb/cursors.py", line 174, in execute
>     self.errorhandler(self, exc, value)
>   File "/usr/local/lib/python2.7/dist-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
>     raise errorclass, errorvalue
> OperationalError: (2006, 'MySQL server has gone away')
> [pid: 38|app: 0|req: 4/4] 127.0.0.1 () {48 vars in 843 bytes} [Mon Jun  6 08:43:06 2016] POST /s/user/Register => generated 114 bytes in 12 msecs (HTTP/1.0 500) 2 headers in 100 bytes (1 switches on core 1)
> 
> —
> You are receiving this because you were mentioned.
> Reply to this email directly, view it on GitHub
> https://github.com/coleifer/peewee/issues/961#issuecomment-223937057,
> or mute the thread
> https://github.com/notifications/unsubscribe/AAHUprAoWZngQWMLNHKtYIc01mfr7-kiks5qJAligaJpZM4Ituf3
> .


Yes, when I do these steps, the error always happens:
1. Run my uwsgi server
2. Do the first request, who will use peewee to do some queries etc
3. I wait for three minutes (180 seconds) and do another request to my backend: everything works fine.  When I do the third request to my backend is when the error happens. In this third request I get the error "mysql server has gone away". Also, I can do 20, 30 or even 40 request before the 180 seconds, but the second after this time, shit happens.

MySQL configuration:
wait_timeout 180
interactive_timeout 180

My peewee db settings:

``` python
import peewee

database = PooledMySQLDatabase(settings.db_DBNAME, host=settings.db_HOST, user=settings.db_USER,
                               passwd=settings.db_PASSWORD, max_connections=8, stale_timeout=110,
                               threadlocals=True)

```

The database don't receive any traffic, just these requests that I said.

I tried to use the MySQLDatabase with this config:

``` python
from playhouse.shortcuts import RetryOperationalError

database = peewee.MySQLDatabase(settings.db_DBNAME, host=settings.db_HOST, user=settings.db_USER,
                                passwd=settings.db_PASSWORD, threadlocals=True)

```

It took more time (almost 10 minutes) to get the error, but it happened. 


Doing more tests, it's seems that if I leave mysql "without use" the problem happens. If I call my backend frequently, the error don't happen. 


Hi @coleifer, I fixed it creating a uwsgi spooler that hit my API and do a simple select in the database each 3 minutes. Now, I'll change the timeout configuration at MySQL to 8 hours (the default) and increase the frequency of my spooler. This is not a "best practice" solution, but it's the only thing that worked after almost 10 days trying everything. 

Anyway, very thank you for your effort creating the project and maintaining it. :+1: 


Glad you found something that works...I'm not very familiar with MySQL and am not too sure what might be going on. At any rate, feel free to comment with new details if you find anything out!


I solved it in the following way:
```
def refresh_db_connection(fn):
    # It's fix to avoid error "MySQL was gone away".
    # Here we check whether our current db connection is accessible or not (if not, refresh it)
    db.get_conn().ping(True)

@refresh_db_connection
def register_nickname(nickname=""):
    pass
```
Just handled the decorator to refresh the connection if it was closed.