incubator-devlake-helm-chart icon indicating copy to clipboard operation
incubator-devlake-helm-chart copied to clipboard

Published 20 hours ago • verified publisher icon apache

"Unhealthy Readiness probe failed: Get "http://xx.xx.xx.xx:8080/ping": dial tcp xx.xx.xx.xx:8080: connect: connection refused" #bug

Open Puvendhan opened this issue 1 year ago • 15 comments
trafficstars

I am getting the below error in the devlake-lake pod, the UI is up , but after clicking on "Proceed Database Migration" , the devlake pod is going down and giving the below error.

Pod is having this event "Unhealthy Readiness probe failed: Get "http://xx.xx.xx.xx:8080/ping": dial tcp xx.xx.xx.xx:8080: connect: connection refused"

I am using gcp Cloudsql mysql instance and used the below arguments to enable external mysql server

mysql: useExternal: true externalServer: xxxxxxxx externalPort: 3306 username: testuser password: xxxxxx database: devlake option: autoCreateSecret: true

time="2024-04-25 15:43:38" level=info msg=" [migrator] applying migration script modify component type to varchar(500):20231007145127"
time="2024-04-25 15:43:39" level=info msg="\x1b[31;1m/app/impls/dalgorm/dalgorm.go:146 \x1b[35;1mError 1054 (42S22): Unknown column 'component' in '_tool_sonarqube_issues'\n\x1b[0m\x1b[33m[0.838ms] \x1b[34;1m[rows:0]\x1b[0m ALTER TABLE `_tool_sonarqube_issues` RENAME COLUMN `component` TO `component_FC59F7072BF9A4479E6A1AA0AFFDB630`"
fatal error: sync: unlock of unlocked mutex

goroutine 84 [running]:
sync.fatal({0x18c5963?, 0xc0001e3608?})
        /usr/local/go/src/runtime/panic.go:1031 +0x1e
sync.(*Mutex).unlockSlow(0x2c0b430, 0xffffffff)
        /usr/local/go/src/sync/mutex.go:229 +0x3c
sync.(*Mutex).Unlock(0xc0006de120?)
        /usr/local/go/src/sync/mutex.go:223 +0x29
github.com/apache/incubator-devlake/server/services.ExecuteMigration()
        /app/server/services/init.go:138 +0x2fa
github.com/apache/incubator-devlake/server/api.SetupApiServer.func1(0xc0000bf400?)
        /app/server/api/api.go:100 +0x25
github.com/gin-gonic/gin.(*Context).Next(...)
        /go/pkg/mod/github.com/gin-gonic/[email protected]/context.go:174
github.com/apache/incubator-devlake/server/api.OAuth2ProxyAuthentication.func1(0xc0000bf400)
        /app/server/api/middlewares.go:95 +0x143
github.com/gin-gonic/gin.(*Context).Next(...)
        /go/pkg/mod/github.com/gin-gonic/[email protected]/context.go:174
github.com/apache/incubator-devlake/server/api.RestAuthentication.func1(0xc0000bf400)
        /app/server/api/middlewares.go:117 +0x2bb
github.com/gin-gonic/gin.(*Context).Next(...)
        /go/pkg/mod/github.com/gin-gonic/[email protected]/context.go:174
github.com/gin-gonic/gin.CustomRecoveryWithWriter.func1(0xc0000bf400)
        /go/pkg/mod/github.com/gin-gonic/[email protected]/recovery.go:102 +0x82
github.com/gin-gonic/gin.(*Context).Next(...)
        /go/pkg/mod/github.com/gin-gonic/[email protected]/context.go:174
github.com/gin-gonic/gin.LoggerWithConfig.func1(0xc0000bf400)
        /go/pkg/mod/github.com/gin-gonic/[email protected]/logger.go:240 +0xe7
github.com/gin-gonic/gin.(*Context).Next(...)
        /go/pkg/mod/github.com/gin-gonic/[email protected]/context.go:174
github.com/gin-gonic/gin.(*Engine).handleHTTPRequest(0xc000605520, 0xc0000bf400)
        /go/pkg/mod/github.com/gin-gonic/[email protected]/gin.go:620 +0x66b
github.com/gin-gonic/gin.(*Engine).ServeHTTP(0xc000605520, {0x1b34640?, 0xc0006f20e0}, 0xc0006e4100)
        /go/pkg/mod/github.com/gin-gonic/[email protected]/gin.go:576 +0x1dd
net/http.serverHandler.ServeHTTP({0xc0006e0120?}, {0x1b34640, 0xc0006f20e0}, 0xc0006e4100)
        /usr/local/go/src/net/http/server.go:2936 +0x316
net/http.(*conn).serve(0xc002f3e360, {0x1b35600, 0xc002f14c90})
        /usr/local/go/src/net/http/server.go:1995 +0x612
created by net/http.(*Server).Serve
        /usr/local/go/src/net/http/server.go:3089 +0x5ed

goroutine 1 [IO wait]:
internal/poll.runtime_pollWait(0x7eaf6c986978, 0x72)
        /usr/local/go/src/runtime/netpoll.go:306 +0x89
internal/poll.(*pollDesc).wait(0xc0000b1b00?, 0x4?, 0x0)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Accept(0xc0000b1b00)
        /usr/local/go/src/internal/poll/fd_unix.go:614 +0x2bd
net.(*netFD).accept(0xc0000b1b00)
        /usr/local/go/src/net/fd_unix.go:172 +0x35
net.(*TCPListener).accept(0xc0000173b0)
        /usr/local/go/src/net/tcpsock_posix.go:148 +0x25
net.(*TCPListener).Accept(0xc0000173b0)
        /usr/local/go/src/net/tcpsock.go:297 +0x3d
net/http.(*Server).Serve(0xc002d21ef0, {0x1b34430, 0xc0000173b0})
        /usr/local/go/src/net/http/server.go:3059 +0x385
net/http.(*Server).ListenAndServe(0xc002d21ef0)
        /usr/local/go/src/net/http/server.go:2988 +0x7d
net/http.ListenAndServe(...)
        /usr/local/go/src/net/http/server.go:3242
github.com/gin-gonic/gin.(*Engine).Run(0xc000605520, {0xc001087ee8, 0x1, 0x1})
        /go/pkg/mod/github.com/gin-gonic/[email protected]/gin.go:386 +0x20e
github.com/apache/incubator-devlake/server/api.RunApiServer(0xc000605520?)
        /app/server/api/api.go:172 +0xdb
github.com/apache/incubator-devlake/server/api.CreateAndRunApiServer()
        /app/server/api/api.go:73 +0x67
main.main()
        /app/server/main.go:33 +0x36

goroutine 8 [chan receive]:
github.com/panjf2000/ants/v2.(*Pool).purgePeriodically(0xc0001f8620)
        /go/pkg/mod/github.com/panjf2000/ants/[email protected]/pool.go:69 +0x8b
created by github.com/panjf2000/ants/v2.NewPool
        /go/pkg/mod/github.com/panjf2000/ants/[email protected]/pool.go:137 +0x365

goroutine 9 [select, 1 minutes]:
database/sql.(*DB).connectionOpener(0xc0001a11e0, {0x1b35558, 0xc0004e47d0})
        /usr/local/go/src/database/sql/sql.go:1218 +0x8d
created by database/sql.OpenDB
        /usr/local/go/src/database/sql/sql.go:791 +0x18d

goroutine 35 [select, 1 minutes]:
github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1()
        /go/pkg/mod/github.com/go-sql-driver/[email protected]/connection.go:614 +0xaa
created by github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher
        /go/pkg/mod/github.com/go-sql-driver/[email protected]/connection.go:611 +0x10a

goroutine 10 [select, 1 minutes]:
database/sql.(*DB).connectionCleaner(0xc0001a11e0, 0x0?)
        /usr/local/go/src/database/sql/sql.go:1061 +0xa7
created by database/sql.(*DB).startCleanerLocked
        /usr/local/go/src/database/sql/sql.go:1048 +0x105

goroutine 11 [chan receive, 1 minutes]:
database/sql.(*Tx).awaitDone(0xc0004f1d80)
        /usr/local/go/src/database/sql/sql.go:2167 +0x31
created by database/sql.(*DB).beginDC
        /usr/local/go/src/database/sql/sql.go:1887 +0x23b

goroutine 67 [IO wait]:
internal/poll.runtime_pollWait(0x7eaf6c986d38, 0x72)
        /usr/local/go/src/runtime/netpoll.go:306 +0x89
internal/poll.(*pollDesc).wait(0xc0000b1f80?, 0xc0006e0131?, 0x0)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc0000b1f80, {0xc0006e0131, 0x1, 0x1})
        /usr/local/go/src/internal/poll/fd_unix.go:167 +0x299
net.(*netFD).Read(0xc0000b1f80, {0xc0006e0131?, 0x173c920?, 0xc00060cf48?})
        /usr/local/go/src/net/fd_posix.go:55 +0x29
net.(*conn).Read(0xc002f1a0e8, {0xc0006e0131?, 0xc002f11590?, 0xc00009aff0?})
        /usr/local/go/src/net/net.go:183 +0x45
net/http.(*connReader).backgroundRead(0xc0006e0120)
        /usr/local/go/src/net/http/server.go:674 +0x3f
created by net/http.(*connReader).startBackgroundRead
        /usr/local/go/src/net/http/server.go:670 +0xca

goroutine 13 [select, 1 minutes]:
github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1()
        /go/pkg/mod/github.com/go-sql-driver/[email protected]/connection.go:614 +0xaa
created by github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher
        /go/pkg/mod/github.com/go-sql-driver/[email protected]/connection.go:611 +0x10a

Puvendhan avatar Apr 25 '24 16:04 Puvendhan

@Puvendhan what's the version you are using?

d4x1 avatar Apr 26 '24 01:04 d4x1

Here's the version 1.0.0-beta5

Puvendhan avatar Apr 26 '24 04:04 Puvendhan

Hi, Any update on this?

Puvendhan avatar Apr 29 '24 04:04 Puvendhan

Seems like a compatibility problem of the gcp Cloudsql mysql, try using mysql or mariadb instead.

klesh avatar May 06 '24 04:05 klesh

Hello I'm experiencing this issue as well, starting from 1.0.0-beta3. Database: MySQL (bitnami), Version: 8.0.37

hayk96 avatar Jul 12 '24 09:07 hayk96

@hayk96 You can try the latest version.

d4x1 avatar Jul 12 '24 09:07 d4x1

Thanks for your response @d4x1 I've just tried the latest version: 1.0.0 and the same issue there

hayk96 avatar Jul 12 '24 10:07 hayk96

I've tried the 1.0.1-beta1 version as well. Here the error looks like different

time="2024-07-12 10:46:53" level=error msg="failed to execute migration\n\tcaused by: Error 1406 (22001): Data too long for column 'file_path' at row 3191 (500)\n\tWraps: (2) Error 1406 (22001): Data too long for column 'file_path' at row 3191\n\tError types: (1) *hintdetail.withDetail (2) *mysql.MySQLError"

hayk96 avatar Jul 12 '24 10:07 hayk96

@hayk96 Please paste more logs so we can find which migration script failed with this error message. And meanwhile you can check the field's length in your database(I am not sure which table, maybe cq_file_metrics or commits or commit_files or others).

d4x1 avatar Jul 15 '24 09:07 d4x1

sure, in that time the pod was printing the following logs:

database is ready
time="2024-07-12T10:45:12Z" level=info msg="no [.env] file, devlake will read configuration from environment, please make sure you have set correct environment variable."
Version:  v1.0.1-beta1@4cdd754
[GIN-debug] [WARNING] Creating an Engine instance with the Logger and Recovery middleware already attached.
[GIN-debug] [WARNING] Running in "debug" mode. Switch to "release" mode in production.
 - using env:	export GIN_MODE=release
 - using code:	gin.SetMode(gin.ReleaseMode)
[GIN-debug] GET    /ping                     --> github.com/apache/incubator-devlake/server/api/ping.Get (4 handlers)
[GIN-debug] GET    /ready                    --> github.com/apache/incubator-devlake/server/api/ping.Ready (4 handlers)
[GIN-debug] GET    /health                   --> github.com/apache/incubator-devlake/server/api/ping.Health (4 handlers)
[GIN-debug] GET    /version                  --> github.com/apache/incubator-devlake/server/api/version.Get (4 handlers)
[GIN-debug] GET    /proceed-db-migration     --> github.com/apache/incubator-devlake/server/api.SetupApiServer.func1 (6 handlers)
[GIN-debug] GET    /swagger/*any             --> github.com/swaggo/gin-swagger.CustomWrapHandler.func1 (8 handlers)
[GIN-debug] GET    /plugins/swagger/azuredevops/*any --> github.com/swaggo/gin-swagger.CustomWrapHandler.func1 (7 handlers)
[GIN-debug] [WARNING] You trusted all proxies, this is NOT safe. We recommend you to set a value.
Please check https://pkg.go.dev/github.com/gin-gonic/gin#readme-don-t-trust-all-proxies for details.
[GIN-debug] Listening and serving HTTP on :8080
[GIN] 2024/07/12 - 10:46:28 | 200 |       7.447µs |   172.25.41.121 | GET      "/ping"
time="2024-07-12 10:46:31" level=error msg="HTTP 428 error\n\tcaused by: \n\tNew migration scripts detected. Database migration is required to launch DevLake.\n\tWARNING: Performing migration may wipe collected data for consistency and re-collecting data may be required.\n\tTo proceed, please send a request to <config-ui-endpoint>/api/proceed-db-migration (or <devlake-endpoint>/proceed-db-migration).\n\tAlternatively, you may downgrade back to the previous DevLake version.\n\t (428)"
[GIN] 2024/07/12 - 10:46:31 | 428 |     863.029µs |      10.42.39.0 | GET      "/store/onboard"
[GIN] 2024/07/12 - 10:46:33 | 200 |       3.447µs |   172.25.41.121 | GET      "/ping"
[GIN] 2024/07/12 - 10:46:33 | 200 |         719ns |   172.25.41.121 | GET      "/ping"
[GIN] 2024/07/12 - 10:46:38 | 200 |       3.379µs |   172.25.41.121 | GET      "/ping"
[GIN] 2024/07/12 - 10:46:53 | 200 |       2.073µs |   172.25.41.121 | GET      "/ping"
time="2024-07-12 10:46:53" level=error msg="failed to execute migration\n\tcaused by: Error 1406 (22001): Data too long for column 'file_path' at row 3191 (500)\n\tWraps: (2) Error 1406 (22001): Data too long for column 'file_path' at row 3191\n\tError types: (1) *hintdetail.withDetail (2) *mysql.MySQLError"
time="2024-07-12 10:46:53" level=error msg="HTTP 500 error\n\tcaused by: error executing migration (500)\n\tWraps: (2) Error 1406 (22001): Data too long for column 'file_path' at row 3191 (500)\n\tWraps: (3) Error 1406 (22001): Data too long for column 'file_path' at row 3191\n\tError types: (1) *hintdetail.withDetail (2) *hintdetail.withDetail (3) *mysql.MySQLError"
[GIN] 2024/07/12 - 10:46:53 | 500 |  280.721364ms |      10.42.39.0 | GET      "/proceed-db-migration"
[GIN] 2024/07/12 - 10:46:58 | 200 |       3.538µs |   172.25.41.121 | GET      "/ping"
[GIN] 2024/07/12 - 10:46:58 | 200 |       1.111µs |   172.25.41.121 | GET      "/ping"
time="2024-07-12 10:47:00" level=error msg="HTTP 400 error\n\tcaused by: error executing migration (400)\n\tWraps: (2) already migrating (400)\n\tError types: (1) *hintdetail.withDetail (2) *errors.errorString"
[GIN] 2024/07/12 - 10:47:00 | 400 |     302.657µs |      10.42.38.0 | GET      "/proceed-db-migration"
[GIN] 2024/07/12 - 10:47:03 | 200 |       5.526µs |   172.25.41.121 | GET      "/ping"

hayk96 avatar Jul 15 '24 11:07 hayk96

@hayk96 I've tried v1.0.1-beta1 with am empty database, there is no error. Is your devlake upgraded from an old version? If yes, check your database's data in column file_path. It seems the actual data length is bigger than expected column length.

d4x1 avatar Jul 16 '24 13:07 d4x1

yes, all DevLeke versions work fine with an empty database. These errors have been raised during upgrades. Will check.

hayk96 avatar Jul 16 '24 13:07 hayk96

tables that have file_path column

mysql> SELECT DISTINCT TABLE_NAME
    ->     FROM INFORMATION_SCHEMA.COLUMNS
    ->     WHERE COLUMN_NAME IN ('file_path')
    ->         AND TABLE_SCHEMA='lake';
+------------------------------+
| TABLE_NAME                   |
+------------------------------+
| _tool_sonarqube_file_metrics |
| commit_files                 |
| cq_file_metrics              |
| repo_snapshot                |
+------------------------------+
4 rows in set (0.01 sec)

length of the columns

mysql> SELECT CHARACTER_MAXIMUM_LENGTH FROM information_schema.COLUMNS WHERE TABLE_SCHEMA = 'lake' AND TABLE_NAME = '_tool_sonarqube_file_metrics' AND COLUMN_NAME = 'file_path';
+--------------------------+
| CHARACTER_MAXIMUM_LENGTH |
+--------------------------+
|               4294967295 |
+--------------------------+
1 row in set (0.00 sec)

mysql> SELECT CHARACTER_MAXIMUM_LENGTH FROM information_schema.COLUMNS WHERE TABLE_SCHEMA = 'lake' AND TABLE_NAME = 'commit_files' AND COLUMN_NAME = 'file_path';
+--------------------------+
| CHARACTER_MAXIMUM_LENGTH |
+--------------------------+
|                     1024 |
+--------------------------+
1 row in set (0.01 sec)

mysql> SELECT CHARACTER_MAXIMUM_LENGTH FROM information_schema.COLUMNS WHERE TABLE_SCHEMA = 'lake' AND TABLE_NAME = 'cq_file_metrics' AND COLUMN_NAME = 'file_path';
+--------------------------+
| CHARACTER_MAXIMUM_LENGTH |
+--------------------------+
|               4294967295 |
+--------------------------+
1 row in set (0.00 sec)

mysql> SELECT CHARACTER_MAXIMUM_LENGTH FROM information_schema.COLUMNS WHERE TABLE_SCHEMA = 'lake' AND TABLE_NAME = 'repo_snapshot' AND COLUMN_NAME = 'file_path';
+--------------------------+
| CHARACTER_MAXIMUM_LENGTH |
+--------------------------+
|                      255 |
+--------------------------+
1 row in set (0.00 sec)

hayk96 avatar Jul 16 '24 13:07 hayk96

@hayk96 I cannot find which scipr fialed from you logs. You can change the log level and if something went wrong, we can find the script id from this line: https://github.com/apache/incubator-devlake/blob/main/backend/core/migration/migrator.go#L99

d4x1 avatar Jul 17 '24 06:07 d4x1

I have deleted the entire stack, so can not reproduce it.

hayk96 avatar Jul 18 '24 14:07 hayk96