# MySQL connection: "closing bad idle connection" **URL:** \ **Category:** Pydio Cells\ **Created:** [May 20, 2023, 11:27pm UTC](https://forum.pydio.com/t/mysql-connection-closing-bad-idle-connection/5272 "2023-05-20T23:27:12Z")\ **Posts on this page:** 2\ **Page:** 1
**Author:** ![GwynethLlewelyn](https://yyz2.discourse-cdn.com/flex032/user_avatar/forum.pydio.com/gwynethllewelyn/32/2419_2.png) [@GwynethLlewelyn](https://forum.pydio.com/u/GwynethLlewelyn)\ **Post date:** [May 20, 2023, 11:27pm UTC](https://forum.pydio.com/t/mysql-connection-closing-bad-idle-connection/5272/1 "2023-05-20T23:27:12Z")
Hi, I have a very minor issue which has been baffling me for a while now. I’m currently using Pydio Cells Home Edition 4.2.1-rc1, using MariaDB 10.6.12 running on Ubuntu 22.04.2 LTS, but the issue has been present [at least as far back as October 2022](https://forum.pydio.com/t/mysql-read-connection-reset-by-peer/4767/2). I just have not been able to follow up with it. > **Briefly, all my storages show the following errors on the log (click arrow to open):** > > (some logs were partially redacted for privacy reasons) > > ```auto > {"level":"error","ts":"2023-05-20T12:19:09+01:00","logger":"pydio.grpc.data.sync.pydiods1","msg":"[mysql] 2023/05/20 12:19:09 packets.go:123: closing bad idle connection: EOF"} > {"level":"error","ts":"2023-05-20T12:19:09+01:00","logger":"pydio.grpc.data.sync.pydiods1","msg":"[mysql] 2023/05/20 12:19:09 packets.go:123: closing bad idle connection: EOF"} > {"level":"error","ts":"2023-05-20T12:19:09+01:00","logger":"pydio.grpc.data.sync.weirdworkspaces","msg":"[mysql] 2023/05/20 12:19:09 packets.go:123: closing bad idle connection: EOF"} > {"level":"error","ts":"2023-05-20T12:19:09+01:00","logger":"pydio.grpc.data.sync.weirdworkspaces","msg":"[mysql] 2023/05/20 12:19:09 packets.go:123: closing bad idle connection: EOF"} > {"level":"error","ts":"2023-05-20T12:19:09+01:00","logger":"pydio.grpc.data.sync.versions","msg":"[mysql] 2023/05/20 12:19:09 packets.go:123: closing bad idle connection: EOF"} > {"level":"error","ts":"2023-05-20T12:19:09+01:00","logger":"pydio.grpc.data.sync.thumbnails","msg":"[mysql] 2023/05/20 12:19:09 packets.go:123: closing bad idle connection: EOF"} > {"level":"error","ts":"2023-05-20T12:19:09+01:00","logger":"pydio.grpc.data.sync.thumbnails","msg":"[mysql] 2023/05/20 12:19:09 packets.go:123: closing bad idle connection: EOF"} > {"level":"error","ts":"2023-05-20T12:19:09+01:00","logger":"pydio.grpc.data.sync.maindatastorage","msg":"[mysql] 2023/05/20 12:19:09 packets.go:123: closing bad idle connection: EOF"} > {"level":"error","ts":"2023-05-20T12:19:09+01:00","logger":"pydio.grpc.data.sync.maindatastorage","msg":"[mysql] 2023/05/20 12:19:09 connection.go:173: driver: bad connection"} > {"level":"error","ts":"2023-05-20T12:19:09+01:00","logger":"pydio.grpc.data.sync.REDACTED","msg":"[mysql] 2023/05/20 12:19:09 packets.go:123: closing bad idle connection: EOF"} > {"level":"error","ts":"2023-05-20T12:19:09+01:00","logger":"pydio.grpc.data.sync.REDACTED","msg":"[mysql] 2023/05/20 12:19:09 packets.go:123: closing bad idle connection: EOF"} > {"level":"error","ts":"2023-05-20T12:19:09+01:00","logger":"pydio.grpc.data.sync.REDACTED","msg":"[mysql] 2023/05/20 12:19:09 packets.go:123: closing bad idle connection: EOF"} > {"level":"error","ts":"2023-05-20T12:19:09+01:00","logger":"pydio.grpc.data.sync.cellsdata","msg":"[mysql] 2023/05/20 12:19:09 packets.go:123: closing bad idle connection: EOF"} > {"level":"error","ts":"2023-05-20T12:19:09+01:00","logger":"pydio.grpc.data.sync.cellsdata","msg":"[mysql] 2023/05/20 12:19:09 packets.go:123: closing bad idle connection: EOF"} > {"level":"error","ts":"2023-05-20T12:19:09+01:00","logger":"pydio.grpc.data.sync.personal","msg":"[mysql] 2023/05/20 12:19:09 packets.go:123: closing bad idle connection: EOF"} > {"level":"error","ts":"2023-05-20T12:19:09+01:00","logger":"pydio.grpc.data.sync.personal","msg":"[mysql] 2023/05/20 12:19:09 packets.go:123: closing bad idle connection: EOF"} > {"level":"error","ts":"2023-05-20T12:19:09+01:00","logger":"pydio.grpc.data.sync.versions","msg":"[mysql] 2023/05/20 12:19:09 packets.go:123: closing bad idle connection: EOF"} > {"level":"error","ts":"2023-05-20T12:19:09+01:00","logger":"pydio.grpc.data.sync.versions","msg":"[mysql] 2023/05/20 12:19:09 packets.go:123: closing bad idle connection: EOF"} > {"level":"error","ts":"2023-05-20T12:19:10+01:00","logger":"pydio.grpc.data.sync.REDACTED","msg":"[mysql] 2023/05/20 12:19:10 packets.go:123: closing bad idle connection: EOF"} > {"level":"error","ts":"2023-05-20T12:19:10+01:00","logger":"pydio.grpc.data.sync.REDACTED","msg":"[mysql] 2023/05/20 12:19:10 connection.go:173: driver: bad connection"} > {"level":"error","ts":"2023-05-20T12:19:10+01:00","logger":"pydio.grpc.data.sync.REDACTED","msg":"[mysql] 2023/05/20 12:19:10 packets.go:123: closing bad idle connection: EOF"} > {"level":"error","ts":"2023-05-20T12:19:10+01:00","logger":"pydio.grpc.data.sync.REDACTED","msg":"[mysql] 2023/05/20 12:19:10 connection.go:173: driver: bad connection"} > > ``` > > … etc. etc. … > **And for about the same period, these are the MariaDB (i.e. MySQL) logs (again, click arrow to open):** > > `bt_pydio_cells` is, of course, the database name I’m using for this particular installation. > > ```auto > 2023-05-20 12:03:18 128789 [Warning] Aborted connection 128789 to db: 'bt_pydio_cells' user: 'REDACTED' host: 'localhost' (Got timeout reading communication packets) > 2023-05-20 12:08:18 129064 [Warning] Aborted connection 129064 to db: 'bt_pydio_cells' user: 'REDACTED' host: 'localhost' (Got timeout reading communication packets) > 2023-05-20 12:13:18 129287 [Warning] Aborted connection 129287 to db: 'bt_pydio_cells' user: 'REDACTED' host: 'localhost' (Got timeout reading communication packets) > 2023-05-20 12:18:18 129421 [Warning] Aborted connection 129421 to db: 'bt_pydio_cells' user: 'REDACTED' host: 'localhost' (Got timeout reading communication packets) > 2023-05-20 12:22:09 35575 [Warning] Aborted connection 35575 to db: 'bt_pydio_cells' user: 'REDACTED' host: 'localhost' (Got timeout reading communication packets) > 2023-05-20 12:22:09 35577 [Warning] Aborted connection 35577 to db: 'bt_pydio_cells' user: 'REDACTED' host: 'localhost' (Got timeout reading communication packets) > > ``` To summarise: 1. There are two errors that come straight from the MySQL database layer, namely: - `packets.go:123: closing bad idle connection: EOF` - `connection.go:173: driver: bad connection` 2. The logs show this happening in ‘bursts’, i.e. over a very short amount of time (a minute at most), and very occasionally. 3. MariaDB shows the corresponding error, i.e. that there were ‘timeout issues’ and that the connection was aborted. 4. This doesn’t seem to have an overall impact on Pydio Cells, at least, as far as I can (visually) determine. It’s just annoying, and I happen to like ‘clean’ logs 🙂 As said, the error in question does _not_ come from Pydio Cells itself, it’s just being bubbled-up from the Go library handling the MySQL driver/connection. Searching for the error message, I didn’t find many consistent reports, and these seem to be mostly related to [communication timeouts](https://github.com/go-sql-driver/mysql/issues/1120): the default timeout is set to 0, which means ‘reuse this connection forever’. As far as I could search for it in the Pydio Cells code, I couldn’t find any directive changing the timeout level, so I’m assuming it’s left at the default (but maybe I didn’t search ‘deep’ enough!.. 😉 ). MariaDB, however, _has_ some configured timeouts, which might or not be relevant to this communication error: ```ini interactive_timeout = 180 wait_timeout = 180 ``` This comes from some tuning I’ve made in the past: idle connections consume _some_ memory (even though they don’t consume CPU cycles or bandwidth — they’re just idle, after all), and there is a limit to how many connections MySQL/MariaDB can handle at a time (which is a configurable parameter; I have `max_connections` set at 512 — I’ve got plenty of memory! — but hardly ever gone above 30% of that). A good practice is to terminate idle connections after a while to preserve resources (the same applies to all sorts of servers/services as well, not only database connections). Maybe it was just that?.. As said elsewhere, my Pydio Cells installation has really very few users. But it naturally runs all regular maintenance checks; therefore, I would expect _some_ database connections to occur regularly. Well, there is something else which caught my attention: the reference to `localhost`. A few days ago, for performance reasons, I turned off DNS reverse lookup on MariaDB — after all, it runs on the local host _only_, so it makes no sense to waste resources/memory/threads to do reverse lookups all the time. This is a recommended setting, which, however, I had turned on a few years ago when I was experimenting with master/slave replication, and then forgot to turn it back off. As a precaution, because MySQL/MariaDB are so finicky about user permissions (they’re tied to hosts, and/or to IP addresses, but they’re _not_ considered ‘the same’), I made sure that the database users for Pydio Cells were allowed to connect _both_ from `localhost` _and_ `127.0.0.1`, to rule out failed authentication issues. And, in fact, those don’t seem to be the case. My next step was trying to figure out what exactly Pydio Cells is doing when it throws such errors. Since the log timestamps are pretty much random, it’s not easy to catch the culprit. Then, by sheer chance, I remembered to check the slow query logs. Mind you, I’m _very_ generous in what I consider to be a ‘slow’ query: the recommended default is 2 seconds, but I just log slow queries when they take more than _10_ seconds — mostly to avoid insanely huge logs, coming (mostly) from WordPress plugins… also, for the kind of things that run on this server, waiting 10 seconds is more than enough, or, putting it into perspective, just waiting 2 seconds for a query to finish is more than reasonable, while taking _more_ than 10 seconds shows that something is wrong somewhere: almost always it’s a database doing lots of JOINs without indexes and/or retrieving datasets with millions of rows because someone forgot to place a LIMIT clause 🙂 (or made a mistake typing) I was _not_ expecting to find anything for Pydio Cells there, but, to my surprise, there was: after converting Unix timestamps to sensible, human-readable dates, I found an almost-perfect match with the following entries: > **MariaDB slow query logs (click arrow to open)** > > ```sql > # User@Host: REDACTED[REDACTED] @ localhost [] > # Thread_id: 129481 Schema: bt_pydio_cells QC_hit: No > # Query_time: 0.000297 Lock_time: 0.000029 Rows_sent: 1 Rows_examined: 18 > # Rows_affected: 0 Bytes_sent: 0 > SET timestamp=1684581549; > SELECT > p.id, > p.effect, > p.conditions, > p.description, > subject.template AS subject, > resource.template AS resource, > action.template AS action > FROM > ladon_policy AS p > > INNER JOIN ladon_policy_subject_rel AS rs ON rs.policy = p.id > LEFT JOIN ladon_policy_action_rel AS ra ON ra.policy = p.id > LEFT JOIN ladon_policy_resource_rel AS rr ON rr.policy = p.id > > INNER JOIN ladon_subject AS subject ON rs.subject = subject.id > LEFT JOIN ladon_action AS action ON ra.action = action.id > LEFT JOIN ladon_resource AS resource ON rr.resource = resource.id > WHERE > (subject.has_regex = 0 AND subject.template = 'user:gwynethllewelyn') > OR > (subject.has_regex = 1 AND CAST('user:gwynethllewelyn' AS BINARY) REGEXP BINARY subject.compiled); > [...] > # User@Host: REDACTED[REDACTED] @ localhost [] > # Thread_id: 129481 Schema: bt_pydio_cells QC_hit: No > # Query_time: 0.000259 Lock_time: 0.000028 Rows_sent: 1 Rows_examined: 18 > # Rows_affected: 0 Bytes_sent: 0 > SET timestamp=1684581549; > SELECT > p.id, > p.effect, > p.conditions, > p.description, > subject.template AS subject, > resource.template AS resource, > action.template AS action > FROM > ladon_policy AS p > > INNER JOIN ladon_policy_subject_rel AS rs ON rs.policy = p.id > LEFT JOIN ladon_policy_action_rel AS ra ON ra.policy = p.id > LEFT JOIN ladon_policy_resource_rel AS rr ON rr.policy = p.id > > INNER JOIN ladon_subject AS subject ON rs.subject = subject.id > LEFT JOIN ladon_action AS action ON ra.action = action.id > LEFT JOIN ladon_resource AS resource ON rr.resource = resource.id > WHERE > (subject.has_regex = 0 AND subject.template = 'role:cbb95bbe-abda-44a3-b93e-7e9ce211ad66') > OR > (subject.has_regex = 1 AND CAST('role:cbb95bbe-abda-44a3-b93e-7e9ce211ad66'AS BINARY) REGEXP BINARY subject.compiled); > # User@Host: REDACTED[REDACTED] @ localhost [] > # Thread_id: 129483 Schema: bt_pydio_cells QC_hit: No > # Query_time: 0.000257 Lock_time: 0.000025 Rows_sent: 1 Rows_examined: 18 > # Rows_affected: 0 Bytes_sent: 0 > SET timestamp=1684581549; > SELECT > p.id, > p.effect, > p.conditions, > p.description, > subject.template AS subject, > resource.template AS resource, > action.template AS action > FROM > ladon_policy AS p > > INNER JOIN ladon_policy_subject_rel AS rs ON rs.policy = p.id > LEFT JOIN ladon_policy_action_rel AS ra ON ra.policy = p.id > LEFT JOIN ladon_policy_resource_rel AS rr ON rr.policy = p.id > > INNER JOIN ladon_subject AS subject ON rs.subject = subject.id > LEFT JOIN ladon_action AS action ON ra.action = action.id > LEFT JOIN ladon_resource AS resource ON rr.resource = resource.id > WHERE > (subject.has_regex = 0 AND subject.template = 'role:e69a27d7-63b4-4ad0-93ab- > 0b296ce4b769') > OR > (subject.has_regex = 1 AND CAST('role:e69a27d7-63b4-4ad0-93ab-0b296ce4b769' > AS BINARY) REGEXP BINARY subject.compiled); > > ``` > > (some details redacted for privacy reasons) Please note that the logs above are just a _tiny_ fraction of the complex queries that were logged as ‘slow’ _for a single second_ (more precisely: timestamp 1684581549, e.g. Sat May 20 2023 11:19:09 GMT+0000); there are many more on the subsequent seconds/minutes. Now, I have no easy way to figure out if those complex, sextuple JOINs are _regularly_ made — tens of times per second — and _most_ of the time, such queries just finish in less then 10 seconds and therefore never get logged. And it’s perfectly reasonable to imagine that _at the precise moment_ when these queries were made, the system was very busy with other things; all I can say is that, whatever else the server was doing, the _only_ slow queries logged during that period of time came from Pydio Cells. That’s not saying much — imagine, for instance, that the system was very slow because there was a spike of I/O activity (like a massive spam wave coming in and each message being processed independently), and, as such, MariaDB struggled to get some I/O locks for its own purposes; those queries that required at least _some_ I/O (such as temporary tables too large to be held in memory) _might_ have been delayed for an unacceptable amount of time. So it wouldn’t be the queries themselves to be ‘slow’; it was the system being slow that caused those queries to be much slower than usual. From the data I’ve got, and the lack of experience in analysing the logs I have, I cannot say. Nevertheless, what I can safely _assume_ is that these huge, complex queries _do_ have an impact on the overall health of the system. It’s just hard to understand exactly _how_ the system is affected. You can see from the logs that the actual recorded query time is measured in single-digit milliseconds (so it’s a bit baffling to understand _why_ these have been recorded as ‘slow’). A bit more digging is necessary to figure out what’s actually going on. Anyway… maybe someone can explain what exactly all these logs _mean_ — and, therefore, help me to figure out what I’m required to change! ---
**Author:** ![system](https://canada1.discourse-cdn.com/flex032/uploads/pydio/original/2X/6/61f19fa52ec15fd4250db51aea351adba0e831fd.png) [@system](https://forum.pydio.com/u/system)\ **Post date:** [July 19, 2023, 11:27pm UTC](https://forum.pydio.com/t/mysql-connection-closing-bad-idle-connection/5272/2 "2023-07-19T23:27:44Z")
This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.