Make db connect more robust #5738

pbrackin · 2019-01-15T15:54:35Z

Refer to #2907

(It was auto-closed by your bot, but still an issue.)

Note that your contributing instructions for running drone CLI did not work for me. It seems like the instructions may be outdated or incomplete. Here is what I got:

/home/grokman/go_projects/src/code.gitea.io/gitea % drone exec --local --build-event "pull_request" Incorrect Usage: flag provided but not defined: -local

However, I did build & run this successfully. Here is a pertinent log snippet:

2019/01/14 21:41:32 [I] Log Mode: File(Info)
2019/01/14 21:41:32 [I] XORM Log Mode: File(Info)
2019/01/14 21:41:32 [I] Cache Service Enabled
2019/01/14 21:41:32 [I] Session Service Enabled
2019/01/14 21:41:32 [I] Beginning ORM engine init...
2019/01/14 21:41:35 [I] ORM engine initialization failed. Retry #1/10...
2019/01/14 21:41:38 [I] ORM engine initialization failed. Retry #2/10...
2019/01/14 21:41:41 [I] ORM engine initialization failed. Retry #3/10...
2019/01/14 21:41:43 [I] ORM engine init success!
2019/01/14 21:41:44 [I] Git Version: 2.8.0
2019/01/14 21:41:45 [I] Run Mode: Production

I hope this is helpful to your project which - other than this issue - has worked well for me on my Synology Diskstation. If you like my change and what to pull it, but want the tests working on my side first, just guide me in there. & I'd be happy to have another go at that.

custom/conf/app.ini.sample

routers/init.go

zeripath · 2019-01-15T16:25:55Z

Please also rebase on to Gitea/master. For some reason these patches aren't applying properly on to master and I suspect your master might be out of date

…e cheatsheet

…ea into Make_DB_Connect_More_Robust

zeripath

Just a few more little things, mostly just for consistency and nicer logging.

There are likely errors returned from models.NewEngine that would mean we should stop earlier but we can deal with those later - so long as we get told them early (hence the logging).

routers/init.go

zeripath · 2019-01-15T18:49:01Z

routers/init.go

+                // In case of delays connecting to DB, retry connection. Eg, PGSQL in Docker Container on Synolgy
+		log.Info("Beginning ORM engine init...")
+		for i := 0; i < setting.DBConnectRetries; i++ {
+			if err := models.NewEngine(migrations.Migrate); err == nil {


Log at the start of the loop:

log.Info("ORM engine initialization (Attempt: #%d/%d).", i, setting.DBConnectRetries)

in the function turn the := into =

zeripath · 2019-01-15T18:51:02Z

routers/init.go

-		if err := models.NewEngine(migrations.Migrate); err != nil {
-			log.Fatal(4, "Failed to initialize ORM engine: %v", err)
+                // In case of delays connecting to DB, retry connection. Eg, PGSQL in Docker Container on Synolgy
+		log.Info("Beginning ORM engine init...")


OK I think we should strip this out to a separate function:

func initDBEngine() (err error) { // With the contents of lines 61 - 72 (as amended) // return the last error which you then log.Fatal(4, "Failed to initialize ORM engine: %v", err) }

Be consistent with the log message. So make this line:

log.Info("Beginning ORM engine initialization...")

routers/init.go

modules/setting/setting.go

routers/init.go

pbrackin · 2019-01-16T00:48:38Z

After these changes, the new pertinent log sections looks like:

2019/01/15 16:32:32 [I] Beginning ORM engine initialization.
2019/01/15 16:32:32 [I] ORM engine initialization attempt #1/10...
2019/01/15 16:32:35 [I] ORM engine initialization attempt #2/10...
2019/01/15 16:32:38 [I] ORM engine initialization attempt #3/10...
2019/01/15 16:32:41 [I] ORM engine initialization attempt #4/10...
2019/01/15 16:32:43 [I] ORM engine initialization successful!

codecov-io · 2019-01-16T01:10:06Z

Codecov Report

❗ No coverage uploaded for pull request base (master@f54e0d2). Click here to learn what that means.
The diff coverage is 60%.

@@            Coverage Diff            @@
##             master    #5738   +/-   ##
=========================================
  Coverage          ?   37.74%           
=========================================
  Files             ?      327           
  Lines             ?    47840           
  Branches          ?        0           
=========================================
  Hits              ?    18059           
  Misses            ?    27187           
  Partials          ?     2594

Impacted Files	Coverage Δ
modules/setting/setting.go	`49.31% <100%> (ø)`
routers/init.go	`71.83% <55.55%> (ø)`

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update f54e0d2...b05babf. Read the comment docs.

routers/init.go

pbrackin · 2019-01-17T14:53:49Z

Anything happening here? I saw there was changes requested, but they appear to be outdated.

NVM I see the one "log error" comment now. My browser must have gone stale. Just to clarify there.. the error is already being logged at the end of the connect attempt. You are saying now that you want to log the same error over and over for each attempt? As the error is very likely the same error each time, this seems redundant. If you insist on this, it may be advisable to increase the log level for the intermediate error logging. But, your project, so jsut let me know.

zeripath · 2019-01-17T15:16:47Z

You should log the error before sleeping in the backoff as suggested above and I'll then lgtm it.

pbrackin · 2019-01-17T16:05:51Z

OK sure. So, did you want to keep it at the info log level as well? And then also did you want to remove the logging of the error at the final of all the attempts (which also would then become redundant).

zeripath · 2019-01-17T16:31:27Z

Yeah keep it at Info. The point is that if you're watching your logs and you see it fail you can terminate early if it's an unexpected failure.

pbrackin · 2019-01-17T19:04:47Z

Well, as it is, you know the last error from the last try, if the ORM fails to init at all, since the last error is printed after the new fcn returns.

But so if you want to print the error for each failed attempt & keep it all at info, it seems like you would want to remove the final info error log print after the fcn call, as it will be completely redundant. Let me know on that & I will proceed.

zeripath · 2019-01-17T19:16:59Z

Hmm I'm not sure I see it log twice from the current suggested change. Your current code returns early when there's an error at the end.

If you really don't think it's helpful to log the backed off errors at Info, drop em to Debug.

I'm just cautious that we're going to make Gitea take ten times longer to fail is there's a database problem and not actually tell people what the problem is until the end of that of 10 attempts.

pbrackin · 2019-01-17T22:03:04Z

Doesn't this make it log the final error after the new fcn call:

if err := initDBEngine(); err == nil {
                        log.Info("ORM engine initialization successful!")
                } else {
                        log.Fatal(4, "ORM engine initialization failed: %v", err)
                }

I assume fatal gets logged no matter the log setting? Hopefully I didn't screw this code up - I think it was mainly recycled from the pre-this-PR code.

Now I understand a little better where you were coming from. So for failure modes OTHER than the startup order issue, you may frustrate some real-time debuggers. I think that's a fair point. So now I am glad I was not dogmatically standing my ground there :) But yeah I think making the retry failures debug level makes the most sense. Peeps who are actively debugging will surely have their log levels turned up, and the rest will have less noisy logs. I will go ahead and do that.

zeripath · 2019-01-17T22:42:36Z

Yeah log.Fatal logs no matter the setting and kills the program too.

I was meaning replace line 56 (the sleep command) with the 2 log lines plus sleep command. If you look carefully when you've backed off n -1 times and still don't get a dB on the nth, that is the last time, line 53's test evaluates true and line 54 returns the error, so on the nth time you only get the log.Fatal.

One other thing, because this code is using a go log, I'm not sure that there is a log.Debug in that logger, but if there is feel free to drop it the logging down to debug.

The other benefit of logging this stuff, even for those not debugging Gitea, is that we can find out what xorm returns when it can't connect because the db isn't ready and we can adjust this code in the future to report better information and/or not back off if the error isn't the right type. At present I at least have no idea what xorm would return, and in some ways noisy logs that annoy users means we get that information so we can make better code in future.

pbrackin · 2019-01-18T05:01:08Z

This is what the new output looks like, with log level set to Debug. You can see the log level of each print with the letter in brackets between the timestamp and the message.

2019/01/17 19:49:12 [I] Beginning ORM engine initialization.
2019/01/17 19:49:12 [I] ORM engine initialization attempt #1/10...
2019/01/17 19:49:12 [D] ORM engine initialization attempt #1/10 failed. Error: <nil>
2019/01/17 19:49:12 [I] Backing off for 3 seconds
2019/01/17 19:49:15 [I] ORM engine initialization attempt #2/10...
2019/01/17 19:49:15 [D] ORM engine initialization attempt #2/10 failed. Error: <nil>
2019/01/17 19:49:15 [I] Backing off for 3 seconds
2019/01/17 19:49:18 [I] ORM engine initialization attempt #3/10...
2019/01/17 19:49:18 [D] ORM engine initialization attempt #3/10 failed. Error: <nil>
2019/01/17 19:49:18 [I] Backing off for 3 seconds
2019/01/17 19:49:21 [I] ORM engine initialization attempt #4/10...
2019/01/17 19:49:23 [I] ORM engine initialization successful!

custom/conf/app.ini.sample

pbrackin · 2019-01-18T23:09:51Z

OK incoming. Looks like I only need to set the ini value as we already were reading it as a Duration & not a constant. I tested that out locally & was able to set the Duration in the file to 2s & it actually worked, lol. Stand by.

…ea into Make_DB_Connect_More_Robust

docs/content/doc/advanced/config-cheat-sheet.en-us.md

zeripath · 2019-01-18T23:17:09Z

Thanks for your work Paul sorry there's been so many little changes.

pbrackin · 2019-01-18T23:23:14Z

Nah its nothing. Thank y'all. I do like giving back a little bit on projects that have helped me & yours is a good one. I was SO glad to get rid of GitLab, haha. Maybe c yall again u never know.... Keep up the good work!

zeripath · 2019-01-18T23:26:03Z

Ok Paul, you've already got my lgtm. Need one more maintainer to look at this and say it's a good idea.

Btw Is it really the case that the xorm dB just returns a error when there's a failure to connect? That seems weird!

pbrackin · 2019-01-19T23:45:56Z

NOOOooooo!!! Heh. Well I appreciate the merge, but guess what? We need one more change. After your last comment I went back to look at the output before this PR & saw that it was not <nil> for the one fatal attempt. So I figured something was wrong. It turns out that we have a scoping issue. In Go, conditional blocks have their own scope. So, that is why the err wasn't showing up in the intermediate failure prints. The err var was out of scope. And it would also not show up for the fatal print case now. I just was testing a patch for this as you were merging, lol. Since this PR was merged, do you want me to make another one?

pbrackin · 2019-01-19T23:48:06Z

BTW, with the patch, the output looks like:

2019/01/19 15:29:48 [I] Beginning ORM engine initialization.
2019/01/19 15:29:48 [I] ORM engine initialization attempt #1/10...
2019/01/19 15:29:48 [D] ORM engine initialization attempt #1/10 failed. Error: read tcp 127.0.0.1:57118->127.0.0.1:5433: read: connection reset by peer
2019/01/19 15:29:48 [I] Backing off for 2 seconds
2019/01/19 15:29:50 [I] ORM engine initialization attempt #2/10...
2019/01/19 15:29:50 [D] ORM engine initialization attempt #2/10 failed. Error: read tcp 127.0.0.1:57125->127.0.0.1:5433: read: connection reset by peer
2019/01/19 15:29:50 [I] Backing off for 2 seconds
2019/01/19 15:29:52 [I] ORM engine initialization attempt #3/10...
2019/01/19 15:29:52 [D] ORM engine initialization attempt #3/10 failed. Error: read tcp 127.0.0.1:57129->127.0.0.1:5433: read: connection reset by peer
2019/01/19 15:29:52 [I] Backing off for 2 seconds
2019/01/19 15:29:54 [I] ORM engine initialization attempt #4/10...
2019/01/19 15:29:54 [D] ORM engine initialization attempt #4/10 failed. Error: read tcp 127.0.0.1:57134->127.0.0.1:5433: read: connection reset by peer
2019/01/19 15:29:54 [I] Backing off for 2 seconds
2019/01/19 15:29:56 [I] ORM engine initialization attempt #5/10...
2019/01/19 15:29:58 [I] ORM engine initialization successful!
2019/01/19 15:29:58 [I] ORM engine had intermediate failure(s): read tcp 127.0.0.1:57134->127.0.0.1:5433: read: connection reset by peer

zeripath · 2019-01-19T23:49:41Z

Just push the changes to this branch we should be able to remerge off it.

Neither of us reviewers caught it.

zeripath · 2019-01-19T23:52:37Z

routers/init.go

+	log.Info("Beginning ORM engine initialization.")
+	for i := 0; i < setting.DBConnectRetries; i++ {
+		log.Info("ORM engine initialization attempt #%d/%d...", i+1, setting.DBConnectRetries)
+		if err := models.NewEngine(migrations.Migrate); err == nil {


Here should have been:

if err = ...

The reason the compiler didn't alarm is because there was a named err always available. I knew I never liked that feature of the language!

ur right. I did have it that way the first go around, then I changed it due to a compile error (which was for another unrelated problem). I currently have em on separate lines tho. u want me to condense it back down?

Push your current changes up, and let's see.

I pushed it already. It didn't show up here I guess becz its merged?

Should I hit the "compare & new PR" button. u reckon?

well i went ahead and condensed it back down to a one-liner, sans the re-declaration

OK the new PR is is #5780

Paul Brackin added 2 commits January 14, 2019 12:43

Add retry loop to DB connect logic

a3937ad

make DB connect vars configurable

461665d

zeripath suggested changes Jan 15, 2019

View reviewed changes

custom/conf/app.ini.sample Outdated Show resolved Hide resolved

routers/init.go Outdated Show resolved Hide resolved

bkcsoft added the lgtm/need 2 This PR needs two approvals by maintainers to be considered for merging. label Jan 15, 2019

techknowlogick and others added 4 commits January 15, 2019 11:31

Merge branch 'master' into Make_DB_Connect_More_Robust

a2122a6

Update DB retry field names, add as setting subfield, add to US local…

16db020

…e cheatsheet

spaces->tabs

b74d936

fix new DB setting declaration

5dc2abc

pbrackin force-pushed the Make_DB_Connect_More_Robust branch from cc47fe3 to 5dc2abc Compare January 15, 2019 18:00

Paul Brackin and others added 7 commits January 15, 2019 10:12

Add retry loop to DB connect logic

38dbb4d

Support CORS headers to git smart http protocol (go-gitea#5719)

f6fb9aa

make DB connect vars configurable

aa178f7

Update DB retry field names, add as setting subfield, add to US local…

72c624f

…e cheatsheet

spaces->tabs

2f6f57a

fix new DB setting declaration

8544971

Merge branch 'Make_DB_Connect_More_Robust' of github.com:pbrackin/git…

d57e3a4

…ea into Make_DB_Connect_More_Robust

zeripath suggested changes Jan 15, 2019

View reviewed changes

lafriks added the type/enhancement An improvement of existing functionality label Jan 15, 2019

lafriks added this to the 1.8.0 milestone Jan 15, 2019

Paul Brackin added 2 commits January 15, 2019 16:34

Moving retry logic to separate func. More spaces->tabs.

990691b

spaces->tabs

9113c75

fix spacing fmt gripe, I think.

602159c

zeripath suggested changes Jan 16, 2019

View reviewed changes

routers/init.go Show resolved Hide resolved

add additional logging per connect attempt

c2060d0

zeripath approved these changes Jan 18, 2019

View reviewed changes

bkcsoft added lgtm/need 1 This PR needs approval from one additional maintainer to be merged. and removed lgtm/need 2 This PR needs two approvals by maintainers to be considered for merging. labels Jan 18, 2019

Merge branch 'master' into Make_DB_Connect_More_Robust

eb90cc7

techknowlogick reviewed Jan 18, 2019

View reviewed changes

custom/conf/app.ini.sample Outdated Show resolved Hide resolved

Change backoff timer ini setting to a Duration vs constant

eff081e

Merge branch 'Make_DB_Connect_More_Robust' of github.com:pbrackin/git…

edb820d

…ea into Make_DB_Connect_More_Robust

zeripath reviewed Jan 18, 2019

View reviewed changes

docs/content/doc/advanced/config-cheat-sheet.en-us.md Outdated Show resolved Hide resolved

Update backoff timer to Duration in cheatsheet

9b6c7ef

techknowlogick approved these changes Jan 19, 2019

View reviewed changes

bkcsoft added lgtm/done This PR has enough approvals to get merged. There are no important open reservations anymore. and removed lgtm/need 1 This PR needs approval from one additional maintainer to be merged. labels Jan 19, 2019

Merge branch 'master' into Make_DB_Connect_More_Robust

b05babf

techknowlogick merged commit 1bb22b2 into go-gitea:master Jan 19, 2019

zeripath reviewed Jan 19, 2019

View reviewed changes

go-gitea locked and limited conversation to collaborators Nov 24, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Make db connect more robust #5738

Make db connect more robust #5738

pbrackin commented Jan 15, 2019

zeripath commented Jan 15, 2019

zeripath left a comment

zeripath Jan 15, 2019

zeripath Jan 15, 2019

pbrackin commented Jan 16, 2019

codecov-io commented Jan 16, 2019 •

edited

Loading

pbrackin commented Jan 17, 2019 •

edited

Loading

zeripath commented Jan 17, 2019

pbrackin commented Jan 17, 2019 •

edited

Loading

zeripath commented Jan 17, 2019

pbrackin commented Jan 17, 2019

zeripath commented Jan 17, 2019

pbrackin commented Jan 17, 2019

zeripath commented Jan 17, 2019

pbrackin commented Jan 18, 2019 •

edited

Loading

pbrackin commented Jan 18, 2019 •

edited

Loading

zeripath commented Jan 18, 2019

pbrackin commented Jan 18, 2019

zeripath commented Jan 18, 2019

pbrackin commented Jan 19, 2019 •

edited

Loading

pbrackin commented Jan 19, 2019

zeripath commented Jan 19, 2019

zeripath Jan 19, 2019

pbrackin Jan 19, 2019

zeripath Jan 20, 2019

pbrackin Jan 20, 2019

pbrackin Jan 20, 2019

zeripath Jan 20, 2019

pbrackin Jan 20, 2019

pbrackin Jan 20, 2019

Make db connect more robust #5738

Make db connect more robust #5738

Conversation

pbrackin commented Jan 15, 2019

zeripath commented Jan 15, 2019

zeripath left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pbrackin commented Jan 16, 2019

codecov-io commented Jan 16, 2019 • edited Loading

Codecov Report

pbrackin commented Jan 17, 2019 • edited Loading

zeripath commented Jan 17, 2019

pbrackin commented Jan 17, 2019 • edited Loading

zeripath commented Jan 17, 2019

pbrackin commented Jan 17, 2019

zeripath commented Jan 17, 2019

pbrackin commented Jan 17, 2019

zeripath commented Jan 17, 2019

pbrackin commented Jan 18, 2019 • edited Loading

pbrackin commented Jan 18, 2019 • edited Loading

zeripath commented Jan 18, 2019

pbrackin commented Jan 18, 2019

zeripath commented Jan 18, 2019

pbrackin commented Jan 19, 2019 • edited Loading

pbrackin commented Jan 19, 2019

zeripath commented Jan 19, 2019

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

codecov-io commented Jan 16, 2019 •

edited

Loading

pbrackin commented Jan 17, 2019 •

edited

Loading

pbrackin commented Jan 17, 2019 •

edited

Loading

pbrackin commented Jan 18, 2019 •

edited

Loading

pbrackin commented Jan 18, 2019 •

edited

Loading

pbrackin commented Jan 19, 2019 •

edited

Loading