search

jovandeginste / workout-tracker

A workout tracking web application for personal use (or family, friends), geared towards running and other GPX-based activities
Other
945 stars 31 forks source link

Server gets stuck while updating route segments #261

Closed pixelspark closed 3 weeks ago

pixelspark commented 4 weeks ago

Hi,

After upgrading to master on my 'production' system (which has a few hundred workouts) I tried to use the route segments feature. After creating the first workout, it apparently starts a matching process in the background. When I try to create another segment however, the whole server appears to freeze. Relevant log messages:

{"time":"2024-08-31T10:00:56.284767052Z","level":"ERROR","msg":"database is locked (5) (SQLITE_BUSY)","app":"workout-tracker","version":"master","sha":"32af476e6f22f2a66f0190ec932c58709ceb74
4a","module":"database","error":"database is locked (5) (SQLITE_BUSY)","query":"UPDATE `route_segments` SET `updated_at`=\"2024-08-31 10:00:51.277\" WHERE `route_segments`.`deleted_at` IS NU
LL AND `id` = 1","duration":5007049207,"rows":1,"file":"/app/pkg/database/route_segments.go:177"}
github.com/jovandeginste/workout-tracker/pkg/app.(*App).ConfigureWebserver.LoadAndSave.LoadAndSaveWithConfig.func2.1.1()
        /app/vendor/github.com/spazzymoto/echo-scs-session/session.go:74 +0x23c
github.com/labstack/echo/v4.(*Response).WriteHeader(0xc000780000, 0xc0006ec1b0?)
        /app/vendor/github.com/labstack/echo/v4/response.go:63 +0x9e
github.com/labstack/echo/v4.(*context).Redirect(0xc00034a000, 0x12e, {0xc000166be8, 0x11})
        /app/vendor/github.com/labstack/echo/v4/context.go:615 +0x11a
github.com/jovandeginste/workout-tracker/pkg/app.(*App).redirectWithError(0xc0002226e0?, {0x26e8b10?, 0xc00034a000?}, {0xc000166be8?, 0x11?}, {0x26cafe0?, 0xc0000169a8?})
        /app/pkg/app/handlers.go:19 +0xbc
github.com/jovandeginste/workout-tracker/pkg/app.(*App).routeSegmentFindMatches(0xc0002226e0, {0x26e8b10, 0xc00034a000})
        /app/pkg/app/route_segments_handlers.go:176 +0x2aa
github.com/labstack/echo-jwt/v4.Config.ToMiddleware.func2.1({0x26e8b10, 0xc00034a000})
        /app/vendor/github.com/labstack/echo-jwt/v4/jwt.go:237 +0x3dd
github.com/labstack/echo/v4.(*Echo).add.func1({0x26e8b10, 0xc00034a000})
        /app/vendor/github.com/labstack/echo/v4/echo.go:587 +0x4b
echo: http: panic serving 172.20.0.1:49824: SQL logic error: cannot start a transaction within a transaction (1)                          
goroutine 9 [running]:                                                                                                                                                                        net/http.(*conn).serve.func1()                                                                                                                                                                        /usr/local/go/src/net/http/server.go:1947 +0xbe                                                                                                                                       panic({0xff54a0?, 0xc000016e58?})                                                                                                                                                                     /usr/local/go/src/runtime/panic.go:785 +0x132                                                                                                                                         github.com/jovandeginste/workout-tracker/pkg/app.(*App).ConfigureWebserver.LoadAndSave.LoadAndSaveWithConfig.func2.1.1()                                                                              /app/vendor/github.com/spazzymoto/echo-scs-session/session.go:74 +0x23c                                                                                                               github.com/labstack/echo/v4.(*Response).WriteHeader(0xc000780000, 0x38?)                                                                                                                              /app/vendor/github.com/labstack/echo/v4/response.go:63 +0x9e                                                                                                                          github.com/labstack/echo/v4.(*Response).Write(0xc000780000, {0xc000610240, 0x24, 0x40})                                                                                                               /app/vendor/github.com/labstack/echo/v4/response.go:75 +0x49                                                                                                                          encoding/json.(*Encoder).Encode(0xc0008b4898, {0xfe92a0, 0xc011d05c80})                                                                                                                               /usr/local/go/src/encoding/json/stream.go:231 +0x1ee                                                                                                                                  github.com/labstack/echo/v4.DefaultJSONSerializer.Serialize({}, {0x26e8b10?, 0xc00034a000?}, {0xfe92a0, 0xc011d05c80}, {0x0, 0x0})                                                                    /app/vendor/github.com/labstack/echo/v4/json.go:22 +0xc5                                                                                                                              
github.com/labstack/echo/v4.(*context).json(0xc00034a000, 0x1f4, {0xfe92a0, 0xc011d05c80}, {0x0, 0x0})                                                                                                /app/vendor/github.com/labstack/echo/v4/context.go:505 +0x8a                                                                                                                          github.com/labstack/echo/v4.(*context).JSON(0xc00034a000, 0x1f4, {0xfe92a0, 0xc011d05c80})
        /app/vendor/github.com/labstack/echo/v4/context.go:513 +0xc7                                                                                                                          github.com/labstack/echo/v4.(*Echo).DefaultHTTPErrorHandler(0xc0000b6d88, {0x26cafe0, 0xc000016cc0}, {0x26e8b10, 0xc00034a000})
        /app/vendor/github.com/labstack/echo/v4/echo.go:465 +0x353                                                                                                                            github.com/labstack/echo/v4.(*context).Error(0xc00072e600?, {0x26cafe0?, 0xc000016cc0?})
        /app/vendor/github.com/labstack/echo/v4/context.go:620 +0x38                                                                                                                          github.com/jovandeginste/workout-tracker/pkg/app.newEcho.Recover.RecoverWithConfig.func2.1.1()
        /app/vendor/github.com/labstack/echo/v4/middleware/recover.go:124 +0x5fe
panic({0xff54a0?, 0xc000016cc0?})                                                                                                                                                             
        /usr/local/go/src/runtime/panic.go:785 +0x132
github.com/jovandeginste/workout-tracker/pkg/app.(*App).ConfigureWebserver.LoadAndSave.LoadAndSaveWithConfig.func2.1({0x26e8b10, 0xc00034a000})
        /app/vendor/github.com/spazzymoto/echo-scs-session/session.go:90 +0x1cb
github.com/labstack/echo/v4/middleware.GzipWithConfig.func1.1({0x26e8b10, 0xc00034a000})
        /app/vendor/github.com/labstack/echo/v4/middleware/compress.go:139 +0x2a3
github.com/labstack/echo/v4/middleware.CORSWithConfig.func1.1({0x26e8b10, 0xc00034a000})
        /app/vendor/github.com/labstack/echo/v4/middleware/cors.go:268 +0x87f
github.com/jovandeginste/workout-tracker/pkg/app.newEcho.Secure.SecureWithConfig.func3.1({0x26e8b10, 0xc00034a000})
        /app/vendor/github.com/labstack/echo/v4/middleware/secure.go:141 +0x364
github.com/jovandeginste/workout-tracker/pkg/app.newEcho.Recover.RecoverWithConfig.func2.1({0x26e8b10, 0xc00034a000})
        /app/vendor/github.com/labstack/echo/v4/middleware/recover.go:130 +0x114
github.com/jovandeginste/workout-tracker/pkg/app.newEcho.New.NewWithConfig.func1.1({0x26e8b10, 0xc00034a000})
        /app/vendor/github.com/samber/slog-echo/middleware.go:127 +0x2ee
github.com/labstack/echo/v4.(*Echo).ServeHTTP.func1({0x26e8b10, 0xc00034a000})
        /app/vendor/github.com/labstack/echo/v4/echo.go:668 +0x127
github.com/jovandeginste/workout-tracker/pkg/app.newEcho.RemoveTrailingSlash.RemoveTrailingSlashWithConfig.func4.1({0x26e8b10, 0xc00034a000})
        /app/vendor/github.com/labstack/echo/v4/middleware/slash.go:117 +0x1fd
github.com/labstack/echo/v4.(*Echo).ServeHTTP(0xc0000b6d88, {0x26d2a50, 0xc0004560e0}, 0xc000202000)
        /app/vendor/github.com/labstack/echo/v4/echo.go:674 +0x327
net/http.serverHandler.ServeHTTP({0xc0006ec090?}, {0x26d2a50?, 0xc0004560e0?}, 0x6?)
        /usr/local/go/src/net/http/server.go:3210 +0x8e
net/http.(*conn).serve(0xc0005ce000, {0x26d4bb0, 0xc00002a8a0})
        /usr/local/go/src/net/http/server.go:2092 +0x5d0
created by net/http.(*Server).Serve in goroutine 1
        /usr/local/go/src/net/http/server.go:3360 +0x485

It's also reporting a few slow queries... and I can see why they would be slow:

{"time":"2024-08-31T10:00:56.337365949Z","level":"WARN","msg":"slow sql query [23.716834825s >= 100ms]","app":"workout-tracker","version":"master","sha":"32af476e6f22f2a66f0190ec932c58709ceb
744a","module":"database","slow_query":true,"query":"SELECT * FROM `map_data` WHERE `map_data`.`workout_id` IN (617,616,603,600,597,605,615,604,610,611,612,614,606,595,607,608,602,601,613,59
9,609,598,596,593,594,592,591,590,589,585,588,587,586,581,583,584,582,580,575,579,568,574,569,571,570,577,578,573,572,576,1,567,566,565,564,563,562,561,559,558,557,556,555,554,553,552,551,55
0,549,548,547,546,545,543,544,542,541,540,539,538,537,536,535,534,533,532,531,530,529,528,527,526,525,524,523,522,521,520,519,518,517,516,515,514,513,512,511,510,509,508,507,506,505,504,503,
502,500,499,498,497,496,495,494,493,492,488,486,489,490,487,491,485,484,483,482,481,480,479,478,477,476,475,474,473,472,471,470,469,468,467,466,465,464,463,462,461,460,457,459,458,456,455,45
4,453,452,451,450,449,448,447,446,445,444,443,442,441,440,439,435,437,436,438,434,433,432,368,367,366,365,431,364,363,362,361,360,359,358,430,357,356,355,354,353,352,351,350,349,348,347,346,
345,344,343,342,341,340,339,338,337,336,334,335,333,332,331,330,329,328,327,326,325,324,429,323,322,321,320,319,318,317,316,315,314,428,313,312,311,310,309,308,307,306,305,304,303,302,301,30
0,299,298,297,296,295,294,293,292,291,290,289,288,287,286,285,284,283,282,427,281,426,280,279,278,277,276,275,274,273,272,271,270,269,268,267,266,265,264,263,262,261,260,259,258,257,256,255,
254,253,252,251,250,249,248,247,246,245,244,243,242,241,240,239,238,237,236,235,234,233,232,231,230,229,228,227,226,225,224,223,222,221,220,219,218,217,216,215,214,213,212,211,210,209,208,20
7,206,205,204,203,202,201,200,419,420,421,422,423,424,425,199,198,197,196,195,194,193,192,191,190,189,188,187,186,185,184,183,182,181,180,179,178,177,176,175,174,173,172,171,169,170,168,167,
166,165,164,163,162,161,160,159,158,157,156,155,154,153,152,151,150,418,416,415,411,408,413,417,406,403,398,409,407,412,414,399,394,404,405,395,401,400,402,396,410,397,388,389,390,391,392,39
3,149,148,147,146,145,144,143,142,141,140,139,138,137,136,135,134,133,132,131,130,129,128,127,126,125,124,123,122,121,120,119,118,117,116,115,114,113,112,111,110,109,108,107,106,105,104,103,
102,101,100,99,98,97,96,95,94,93,92,91,90,89,88,87,86,85,84,83,82,81,80,79,78,77,76,75,74,73,72,71,70,69,68,67,66,65,64,63,62,61,60,59,58,57,56,55,54,53,52,51,50,49,48,47,46,45,44,43,42,41,4
0,39,38,37,36,35,34,33,32,31,30,29,28,27,26,25,24,23,22,21,20,19,18,17,16,15,14,13,12,11,10,9,8,7,6,5,387,386,4,3,385,384,383,382,374,381,2,380,379,373,378,377,376,372,371,375,370,369,560) A
ND `map_data`.`deleted_at` IS NULL","duration":23716834825,"rows":616,"file":"/app/pkg/database/workouts.go:264"}
pixelspark commented 4 weeks ago

It appears from the outside the worker thread somehow locks the database, or uses the same database connection as the web UI?

jovandeginste commented 3 weeks ago

@pixelspark let me know if the PR alleviates the problem...

pixelspark commented 3 weeks ago

Weirdly I am now getting this error:

{"time":"2024-09-01T14:48:44.080766679Z","level":"ERROR","msg":"SQL logic error: ambiguous column name: route_segments.dirty (1)","app":"workout-tracker","version":"master","sha":"a95dd20866dac422de9d84f43f760dfb31df38fb","module":"database","error":"SQL logic error: ambiguous column name: route_segments.dirty (1)","query":"UPDATE `route_segments` SET `updated_at`=\"2024-09-01 14:48:44.08\" FROM `route_segments` WHERE `route_segments`.`dirty` = true AND `route_segments`.`deleted_at` IS NULL AND `id` = 6","duration":409115,"rows":0,"file":"/app/pkg/database/route_segments.go:177"}
{"time":"2024-09-01T14:48:44.080789317Z","level":"ERROR","msg":"Worker error saving route segment: SQL logic error: ambiguous column name: route_segments.dirty (1)","app":"workout-tracker","version":"master","sha":"a95dd20866dac422de9d84f43f760dfb31df38fb","module":"app","module":"worker"}
{"time":"2024-09-01T14:48:44.080801886Z","level":"ERROR","msg":"Worker errors during matching: SQL logic error: ambiguous column name: route_segments.dirty (1)\nSQL logic error: ambiguous column name: route_segments.dirty (1)","app":"workout-tracker","version":"master","sha":"a95dd20866dac422de9d84f43f760dfb31df38fb","module":"app","module":"worker"}

This seems to happen here:

for _, rs := range routeSegments {
        rs.Dirty = false
        if err := rs.Save(tx); err != nil {
            errs = errors.Join(errs, err)
            l.Error("Worker error saving route segment: " + err.Error())
        }
    }

This looks like gorm generating a query that is not quite right:

UPDATE `route_segments` SET `updated_at`=\"2024-09-01 14:48:44.08\" FROM `route_segments` WHERE `route_segments`.`dirty` = true AND `route_segments`.`deleted_at` IS NULL AND `id` = 6

The fix seems to be easy however: https://github.com/jovandeginste/workout-tracker/compare/master...pixelspark:workout-tracker:feature/batch-matching

Can you re-merge the PR?

jovandeginste commented 3 weeks ago

I created a new PR and merged it.

pixelspark commented 3 weeks ago

Excellent! I haven't yet managed to make the app hang this time, definitely an improvement!