Issue: Playhouse PooledPostgresqlDatabase
Author: cypmaster14
State: closed
Created: 2019-03-13 18:50:49

Hello,

Some unexpected error occurs when the pooled connection is used for a Postgresql database.
```
File "D:\Python36_x64\test_project\lib\site-packages\playhouse\pool.py", line 125, in _connect
    ts, conn = heapq.heappop(self._connections)
TypeError: '<' not supported between instances of 'psycopg2.extensions.connection' and 'psycopg2.extensions.connection'
```



Peewee ```3.9.2``` 
Psycopg2 ```2.7.7```


Are you messing with `._connections` in any way? The `._connections` list is a heap of `(timestamp, conn)` 2-tuples.

Perhaps the issue is that there are two connections in the `_connections` heap with the exact same timestamp (down to the microsecond?).

Can you replicate this?

I just followed the steps from the docs( ```http://docs.peewee-orm.com/en/latest/peewee/playhouse.html#connection-pool```)

This is the full traceback.
```
[2019-03-13 19:36:23,065] - [CP Server Thread-19] - [ERROR - app.py] Exception on /api/v1/test 
Traceback (most recent call last):
  File "D:\Python36_x64\test_project\lib\site-packages\flask\app.py", line 2292, in wsgi_app
    response = self.full_dispatch_request()
  File "D:\Python36_x64\test_project\lib\site-packages\flask\app.py", line 1815, in full_dispatch_request
    rv = self.handle_user_exception(e)
  File "D:\Python36_x64\test_project\lib\site-packages\flask\app.py", line 1718, in handle_user_exception
    reraise(exc_type, exc_value, tb)
  File "D:\Python36_x64\test_project\lib\site-packages\flask\_compat.py", line 35, in reraise
    raise value
  File "D:\Python36_x64\test_project\lib\site-packages\flask\app.py", line 1811, in full_dispatch_request
    rv = self.preprocess_request()
  File "D:\Python36_x64\test_project\lib\site-packages\flask\app.py", line 2087, in preprocess_request
    rv = func()
  File "D:\Projects\test_project\test_api\server.py", line 135, in _db_connect
    test_api.libs.models.database.connect()
  File "D:\Python36_x64\test_project\lib\site-packages\playhouse\pool.py", line 108, in connect
    return super(PooledDatabase, self).connect(reuse_if_open)
  File "D:\Python36_x64\test_project\lib\site-packages\peewee.py", line 2777, in connect
    self._state.set_connection(self._connect())
  File "D:\Python36_x64\test_project\lib\site-packages\playhouse\pool.py", line 125, in _connect
    ts, conn = heapq.heappop(self._connections)
TypeError: '<' not supported between instances of 'psycopg2.extensions.connection' and 'psycopg2.extensions.connection'
```

I have a CheeryPy Server, with 100 threads, that is based on a Flask App.
The PooledPostgresqlDatabase configuration is: `max_connections=50, stale_timeout=300`

Can you inspect the error a bit?

```python
try:
    test_api.libs.models.database.connect()
except TypeError:
    print(test_api.libs.models.database._connections)
```

There are multiple connections with the same timestamp
```
[
  (1552507043.5142784, ....),
  (1552507043.498655, ....),
  (1552507043.498655, ....),
  (1552507043.5142784, ....)
]
```

Can you also show the connections in the tuple? I'd like to see whether the connections are also the same.

The connections aren't the same. They have different ids.

All of the connections are different

Perfect, thanks. I wonder if there's a race condition? Two of the same timestamps, down to the microsecond, is just hard for me to imagine in the course of ordinary usage.

Can you tell me how you're replicating this? Any and all information you can provide will help.

How are you triggering the error, for instance? Thanks

Additionally, if you could enable pool logging, by adding the following:

```python
import logging
logger = logging.getLogger('peewee.pool')
logger.addHandler(logging.StreamHandler())
logger.setLevel(logging.DEBUG)
```

That would provide some visibility into what might be causing the issue.

So:

What steps do you follow to replicate this? i.e., does it happen on startup, or if you make a bunch of requests, or what?

Could you try adding the logging and do whatever to trigger the issue?

Thank you.

For example, I've tried spinning up a bunch of threads and in each one opening and closing a pool connection several times. I've tried this with a max connections higher and lower than the thread count (lower so that there is contention and some threads have to block while waiting for a connection). I haven't seen any issues so far.

```python
from peewee import *
from playhouse.pool import PooledPostgresqlDatabase

db = PooledPostgresqlDatabase('peewee_test', max_connections=10,
                              timeout=10)

import threading
import time

def open_sleep_close():
    for _ in range(10):
        with db:  # Hold the connection open for 1/10th of a second.
            time.sleep(0.1)

threads = [threading.Thread(target=open_sleep_close) for _ in range(50)]
for t in threads:
    t.start()

print('waiting...')
for t in threads:
    t.join()

print('- in use? %s' % len(db._in_use))  # prints 0
print('- available? %s' % len(db._connections))  # prints 10 (or whatever max connections is set to).
```

The exception occurs after half an hour the server has started. The server receives some kind of heartbeats from other scripts. It isn't usually flooded with requests.   When the exception occurs, from what I can see in the logs, the server isn't flooded with requests.  At the second when the exception occurs, there are 3 or 4 requests.

And another interesting fact is that the server runs on two different hosts and the exception appears just on one of the hosts.

I have added the logger of peewee and I don't see something unusual in the logs. Just creation of connection when none are available, closing connections because they are stale, retrieving connections from the pool and returning connection to the pool.
Meanwhile, the exception still occurs.

> I have added the logger of peewee and I don't see something unusual in the logs. Just creation of connection when none are available, closing connections because they are stale, retrieving connections from the pool and returning connection to the pool.
> Meanwhile, the exception still occurs.

This is not very helpful. I didn't want your "interpretation" of the logs, but the logs themselves, especially in the times leading up to (and including) the exception occurring.

Similarly, if you could share your database declaration with me -- e.g., what parameters you're using to invoke the DB?

I think this is just something weird in your setup, but I'd like to be as thorough as possible, and for that I need you to help by providing information.

Please comment with more information: what settings are you using with your database (stale timeout, Max conns, timeout, etc). It'd be really helpful to see the pool logs as well.

As I can't replicate the problem I'm closing for now. If you can provide more information I'll gladly reopen.