About DB connection random lost #3269

@bobemoe commented on GitHub (May 14, 2019):

How does go load the driver? Is it all packaged into the binary? I didn't have to install any dependencies, so I'm guessing there isn't anything I can update on the OS level, apart from MySQL itself perhaps?

@bobemoe commented on GitHub (May 14, 2019): How does go load the driver? Is it all packaged into the binary? I didn't have to install any dependencies, so I'm guessing there isn't anything I can update on the OS level, apart from MySQL itself perhaps?

GiteaMirror commented

@bobemoe commented on GitHub (May 14, 2019):

I've upgraded MySQL to 5.7.26 and still experiencing this.

The error in mysql.log is
2019-05-14T16:13:22.312637Z 3045 [Note] Aborted connection 3045 to db: 'gitea' user: 'gitea' host: 'localhost' (Got timeout reading communication packets)

@bobemoe commented on GitHub (May 14, 2019): I've upgraded MySQL to 5.7.26 and still experiencing this. The error in mysql.log is 2019-05-14T16:13:22.312637Z 3045 [Note] Aborted connection 3045 to db: 'gitea' user: 'gitea' host: 'localhost' (Got timeout reading communication packets)

GiteaMirror commented

@lafriks commented on GitHub (May 14, 2019):

Could it be that xorm does not close connection at same cases (https://github.com/go-sql-driver/mysql/issues/556)?

@lafriks commented on GitHub (May 14, 2019): Could it be that xorm does not close connection at same cases (https://github.com/go-sql-driver/mysql/issues/556)?

GiteaMirror commented

@bobemoe commented on GitHub (May 14, 2019):

Yeah I reckon it could be.

I've been sitting tailing the logs for a bit and it seems that the mysql timeout comes FIRST. Then next page refresh I get the 404/500 error accompanied by the GO error "GetUserById: invalid connection" and this is 100% repeatable.

Now also watching the MySQL process list. What it looks like is happening:

When I hit ANY frontend page, a gitea connection appears in mysql processlist.
This connection returns its data and then enters "sleep" mode.
As time passes the sleep count increases.
If I hit another page within 60 secs, the connection is reused, and the sleep count resets to 0.
If the sleep count reaches 60 then the connection times out, the mysql timeout error is logged in mysql.log
Next page hit the go error "GetUserById: invalid connection" appears in gitea.log and the frontend 404's.
A new connection now appears, go to step 3

So, I'm guessing Gitea is (efficiently) only opening one connection, and keeping it idle until it needs to use it again?

However when that time comes, if the connection is no longer available this is not caught properly to re-open the connection and retry the last query.

I can increase my mysql timeout, but this will only make the errors less frequent. Unless Gitea closes the connection after a set time, in which case if I make the mysql timeout greater than this it should solve it?

Should Gitea be closing its connection after use or is it by design keeping it open?

@bobemoe commented on GitHub (May 14, 2019): Yeah I reckon it could be. I've been sitting tailing the logs for a bit and it seems that the mysql timeout comes FIRST. Then next page refresh I get the 404/500 error accompanied by the GO error "GetUserById: invalid connection" and this is 100% repeatable. Now also watching the MySQL process list. What it looks like is happening: 1. When I hit ANY frontend page, a gitea connection appears in mysql processlist. 2. This connection returns its data and then enters "sleep" mode. 3. As time passes the sleep count increases. 4. If I hit another page within 60 secs, the connection is reused, and the sleep count resets to 0. 5. If the sleep count reaches 60 then the connection times out, the mysql timeout error is logged in mysql.log 6. Next page hit the go error "GetUserById: invalid connection" appears in gitea.log and the frontend 404's. 7. A new connection now appears, go to step 3 So, I'm guessing Gitea is (efficiently) only opening one connection, and keeping it idle until it needs to use it again? However when that time comes, if the connection is no longer available this is not caught properly to re-open the connection and retry the last query. I can increase my mysql timeout, but this will only make the errors less frequent. Unless Gitea closes the connection after a set time, in which case if I make the mysql timeout greater than this it should solve it? Should Gitea be closing its connection after use or is it by design keeping it open?

GiteaMirror commented

@lafriks commented on GitHub (May 14, 2019):

I think golang MySQL library is keeping pool of open connections to reuse them but it should have reopen new one if current one has become invalid ihmo

@lafriks commented on GitHub (May 14, 2019): I think golang MySQL library is keeping pool of open connections to reuse them but it should have reopen new one if current one has become invalid ihmo

GiteaMirror commented

@bobemoe commented on GitHub (May 14, 2019):

I've tried setting mysql timeout on the server to 120, 180 and 300 and each time the connection times out, I hit a page and get the error still. I've now set the timeout to 3000 and been watching the logs and processes, it seems Gitea has an internal cron that is making a query every 10 mins, this is essentially acting as a keep alive heartbeat that keeps resetting the connection sleep time.

2019/05/14 20:25:13 [I] [SQL] SELECT `id`, `repo_id`, `interval`, `enable_prune`, `updated_unix`, `next_update_unix` FROM `mirror` WHERE (next_update_unix<=?) AND (next_update_unix!=0) []interface {}{1557861913}

This looks like a maintenance task and not a real keep alive implementation, so its a bit of a crazy workaround, but I'm not getting the 404/500 errors any more :)

So how do I proceed? How can I see what version of go-sql-driver/mysql is in the binary? The issue go-sql-driver/mysql#556 was closed several months ago with no real solution other than either "dont forget to db.Close()" or "disable strict mode".

@bobemoe commented on GitHub (May 14, 2019): I've tried setting mysql timeout on the server to 120, 180 and 300 and each time the connection times out, I hit a page and get the error still. I've now set the timeout to 3000 and been watching the logs and processes, it seems Gitea has an internal cron that is making a query every 10 mins, this is essentially acting as a keep alive heartbeat that keeps resetting the connection sleep time. ```2019/05/14 20:25:13 [I] [SQL] SELECT `id`, `repo_id`, `interval`, `enable_prune`, `updated_unix`, `next_update_unix` FROM `mirror` WHERE (next_update_unix<=?) AND (next_update_unix!=0) []interface {}{1557861913}``` This looks like a maintenance task and not a real keep alive implementation, so its a bit of a crazy workaround, but I'm not getting the 404/500 errors any more :) So how do I proceed? How can I see what version of go-sql-driver/mysql is in the binary? The issue go-sql-driver/mysql#556 was closed several months ago with no real solution other than either "dont forget to db.Close()" or "disable strict mode".

GiteaMirror commented

@lunny commented on GitHub (May 15, 2019):

This has been packaged into Gitea binary.

@lunny commented on GitHub (May 15, 2019): This has been packaged into Gitea binary.

GiteaMirror commented

@cevin commented on GitHub (May 15, 2019):

the problem is very annoying

@cevin commented on GitHub (May 15, 2019): the problem is very annoying

GiteaMirror commented

@bobemoe commented on GitHub (May 15, 2019):

I've set my timeouts in /etc/mysql/my.cnf to just over 10 mins and can confirm that the issue has cleared up.

wait_timeout = 650         
interactive_timeout = 650

This is a shared server so not an ideal solution.

@lunny how can I check which version is packaged into the binary? Is it worth me trying Gitea@dev-master?

@cevin are you able to try this on your cloud instance? or check the mysql logs for that timeout error? It would help confirm if we are describing the same issue. I guess you don't really have that level of access on a cloud?

@bobemoe commented on GitHub (May 15, 2019): I've set my timeouts in /etc/mysql/my.cnf to just over 10 mins and can confirm that the issue has cleared up. ``` wait_timeout = 650 interactive_timeout = 650 ``` This is a shared server so not an ideal solution. @lunny how can I check which version is packaged into the binary? Is it worth me trying Gitea@dev-master? @cevin are you able to try this on your cloud instance? or check the mysql logs for that timeout error? It would help confirm if we are describing the same issue. I guess you don't really have that level of access on a cloud?

GiteaMirror commented

@bobemoe commented on GitHub (May 15, 2019):

So looks like Gitea 1.8.1 is using go mysql driver V1.4.
V1.4.1 is out now (2018-11-14) with a potential fix:
https://github.com/go-sql-driver/mysql/blob/v1.4.1/CHANGELOG.md
https://github.com/go-sql-driver/mysql/issues/836 (committed Oct 1, 2018 )

The Gitea 1.8.1 branch looks like its using driver V1.4
The Gitea 1.9.0+dev-254-g710245e81 branch looks like its using driver c45f530f8e7fe40f4687eaa50d0c8c5f1b66f9e0 which was committed Dec 18, 2018 so should include that fix??

My testing on 1.9.0+dev-254-g710245e81 still has the issue :(

So either my calculations are wrong and the fix has not been included (can anyone confirm this?) or it has not worked.

Hmmm :/

@bobemoe commented on GitHub (May 15, 2019): So looks like Gitea 1.8.1 is using go mysql driver V1.4. V1.4.1 is out now (2018-11-14) with a potential fix: https://github.com/go-sql-driver/mysql/blob/v1.4.1/CHANGELOG.md https://github.com/go-sql-driver/mysql/issues/836 (committed Oct 1, 2018 ) The Gitea 1.8.1 branch looks like its using driver V1.4 The Gitea 1.9.0+dev-254-g710245e81 branch looks like its using driver c45f530f8e7fe40f4687eaa50d0c8c5f1b66f9e0 which was committed Dec 18, 2018 so should include that fix?? My testing on 1.9.0+dev-254-g710245e81 still has the issue :( So either my calculations are wrong and the fix has not been included (can anyone confirm this?) or it has not worked. Hmmm :/

GiteaMirror commented

@sapk commented on GitHub (May 15, 2019):

We override the previous tag 1.4.0 with a commit dating 2018-12-18 that should contain this fix 🤔 710245e81e/go.mod (L140)

@sapk commented on GitHub (May 15, 2019): We override the previous tag 1.4.0 with a commit dating 2018-12-18 that should contain this fix :thinking: https://github.com/go-gitea/gitea/blame/710245e81e0d65c72231dbb3b5c9f860cdc71899/go.mod#L140

GiteaMirror commented

@cevin commented on GitHub (May 16, 2019):

@bobemoe yep, but I can set wait_timeout & interactive_timeout in rds( aliyun mysql cloud database) online dashboard. but looks that's not a good idea ?

@cevin commented on GitHub (May 16, 2019): @bobemoe yep, but I can set `wait_timeout & interactive_timeout` in rds( aliyun mysql cloud database) online dashboard. but looks that's not a good idea ?

GiteaMirror commented

https://github.com/gogs/gogs/issues/5532

@mrsdizzie commented on GitHub (May 17, 2019):

Perhaps relevant here:

0a176df6fb

Which claims to fix similar problem and has more discussion/links here:

@mrsdizzie commented on GitHub (May 17, 2019): Perhaps relevant here: https://github.com/gogs/gogs/commit/0a176df6fb4109793c7efddb493b1f2f4ba1b1b2 Which claims to fix similar problem and has more discussion/links here: https://github.com/gogs/gogs/issues/5532

GiteaMirror commented

@lunny commented on GitHub (May 18, 2019):

gogs/gogs@0a176df should be good practice, we could take it.

@lunny commented on GitHub (May 18, 2019): gogs/gogs@0a176df should be good practice, we could take it.

GiteaMirror commented

@lafriks commented on GitHub (May 24, 2019):

That should probably be set only if database is MySQL

@lafriks commented on GitHub (May 24, 2019): That should probably be set only if database is MySQL

GiteaMirror commented