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

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/gin@v1.9.1/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/gin@v1.9.1/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/gin@v1.9.1/context.go:174
github.com/gin-gonic/gin.CustomRecoveryWithWriter.func1(0xc0000bf400)
        /go/pkg/mod/github.com/gin-gonic/gin@v1.9.1/recovery.go:102 +0x82
github.com/gin-gonic/gin.(*Context).Next(...)
        /go/pkg/mod/github.com/gin-gonic/gin@v1.9.1/context.go:174
github.com/gin-gonic/gin.LoggerWithConfig.func1(0xc0000bf400)
        /go/pkg/mod/github.com/gin-gonic/gin@v1.9.1/logger.go:240 +0xe7
github.com/gin-gonic/gin.(*Context).Next(...)
        /go/pkg/mod/github.com/gin-gonic/gin@v1.9.1/context.go:174
github.com/gin-gonic/gin.(*Engine).handleHTTPRequest(0xc000605520, 0xc0000bf400)
        /go/pkg/mod/github.com/gin-gonic/gin@v1.9.1/gin.go:620 +0x66b
github.com/gin-gonic/gin.(*Engine).ServeHTTP(0xc000605520, {0x1b34640?, 0xc0006f20e0}, 0xc0006e4100)
        /go/pkg/mod/github.com/gin-gonic/gin@v1.9.1/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/gin@v1.9.1/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/v2@v2.4.6/pool.go:69 +0x8b
created by github.com/panjf2000/ants/v2.NewPool
        /go/pkg/mod/github.com/panjf2000/ants/v2@v2.4.6/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/mysql@v1.7.1/connection.go:614 +0xaa
created by github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher
        /go/pkg/mod/github.com/go-sql-driver/mysql@v1.7.1/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/mysql@v1.7.1/connection.go:614 +0xaa
created by github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher
        /go/pkg/mod/github.com/go-sql-driver/mysql@v1.7.1/connection.go:611 +0x10a

@Puvendhan

@Puvendhan what's the version you are using?

Here's the version 1.0.0-beta5

Hi, Any update on this?

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

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

@hayk96

@hayk96 You can try the latest version.

@d4x1

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

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

@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).

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

@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.

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

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

@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

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

Navigation Menu

Repository navigation

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

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

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

Description

Activity

d4x1 commented on Apr 26, 2024

Puvendhan commented on Apr 26, 2024

Puvendhan commented on Apr 29, 2024

klesh commented on May 6, 2024

hayk96 commented on Jul 12, 2024

d4x1 commented on Jul 12, 2024

hayk96 commented on Jul 12, 2024

hayk96 commented on Jul 12, 2024

d4x1 commented on Jul 15, 2024

hayk96 commented on Jul 15, 2024

d4x1 commented on Jul 16, 2024

hayk96 commented on Jul 16, 2024

hayk96 commented on Jul 16, 2024

d4x1 commented on Jul 17, 2024

hayk96 commented on Jul 18, 2024

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions