API request to /version returns truncated result to Renovate bot running under gitlab-runner

Everyone can contribute. Help move this issue forward while earning points, leveling up and collecting rewards.

Summary

For about a week now, we've had intermittent yet seemingly consistent/recurring failures by Renovate bot attempting to do its work using an otherwise working API token. Every day around 5am, the scheduled build fails because the api/v4/version endpoint returns less data, making Renovate fail.

I believe this is an issue with GitLab and/or my installation; rather than with Renovate (mainly because the NGINX logs give me reason to believe that GitLab is returning unexpected data.) However, I have no idea how to debug this any further than this; the main issue being the cadence of how and when this occurred over the past week.

Steps to reproduce

This is a long shot, but here's my setup:

  1. Install gitlab-runner, Node and then Renovate bot on a worker machine (that isn't the same as the one where GitLab is running)
  2. Create a GitLab project to host the Renovate configuration, which also has a Schedule trigger that runs Renovate every hour (this is similar to the setup described in renovate-bot/renovate-runner>)
  3. Add a Personal Access Token for a dedicated bot user as RENOVATE_TOKEN CI variable (or alternatively as local environment variable on the worker machine)
  4. Allow the dedicated bot user to access at least one repository and complete the onboarding process (this one might be optional, but that's what I have)
  5. Wait. No seriously, this used to work for months, and suddenly stopped failing fairly consistently at 5am every day after a partial power outage that took down the worker but not GitLab (which subsequently failed a few jobs over the weekend due to the machine not rebooting automatically, and since then failing once a day but working the remaining 23 times just fine.)

Example Project

What is the current bug behavior?

Renovate attempts to orient itself (by requesting api/v4/user, api/v4/version and others) before iterating its repositories, then checking for updates.

However, the request to api/v4/version appears to be truncated, leading Renovate to fail with the following error (and incorrectly assuming that the PAT is invalid):

DEBUG: Error authenticating with GitLab. Check that your token includes "api" permissions
       "err": {
         "message": "Cannot read properties of null (reading 'version')",
         "stack": "TypeError: Cannot read properties of null (reading 'version')\n    at Proxy.initPlatform (C:\\Users\\builder\\AppData\\Roaming\\npm\\node_modules\\renovate\\lib\\modules\\platform\\gitlab\\index.ts:139:31)\n    at processTicksAndRejections (node:internal/process/task_queues:95:5)\n    at initPlatform (C:\\Users\\builder\\AppData\\Roaming\\npm\\node_modules\\renovate\\lib\\modules\\platform\\index.ts:49:24)\n    at globalInitialize (C:\\Users\\builder\\AppData\\Roaming\\npm\\node_modules\\renovate\\lib\\workers\\global\\initialize.ts:86:12)\n    at C:\\Users\\builder\\AppData\\Roaming\\npm\\node_modules\\renovate\\lib\\workers\\global\\index.ts:148:16\n    at start (C:\\Users\\builder\\AppData\\Roaming\\npm\\node_modules\\renovate\\lib\\workers\\global\\index.ts:137:5)\n    at C:\\Users\\builder\\AppData\\Roaming\\npm\\node_modules\\renovate\\lib\\renovate.ts:18:22"
       }
FATAL: Authentication failure
 INFO: Renovate is exiting with a non-zero code due to the following logged errors
       "loggerErrors": [
         {
           "name": "renovate",
           "level": 60,
           "logContext": "CG5Kr71zoBhSmRCUrI-R9",
           "msg": "Authentication failure"
         }
       ]

That "Authentication failure" message is obviously bogus, because the job works just fine every other time around the clock; plus the api/v4/user request immediately before it also works.

The associated entries in nginx.log look like this:

192.168.1.162 - - [14/Mar/2024:05:07:07 +0100] "GET /api/v4/user HTTP/1.1" 200 478 "" "RenovateBot/37.230.0 (https://github.com/renovatebot/renovate)" 1.94
192.168.1.162 - - [14/Mar/2024:05:07:08 +0100] "GET /api/v4/version HTTP/1.1" 200 4 "" "RenovateBot/37.230.0 (https://github.com/renovatebot/renovate)" -

Note the 4 bytes returned for the api/v4/version call, which should normally return a bit more than that.

Associated entry from `api_json.log` 
{
    "time": "2024-03-14T04:07:08.708Z",
    "severity": "INFO",
    "duration_s": 0.99246,
    "db_duration_s": 0.00235,
    "view_duration_s": 0.99011,
    "status": 200,
    "method": "GET",
    "path": "/api/v4/version",
    "params": [],
    "host": "gitlab",
    "remote_ip": "192.168.1.162, 127.0.0.1",
    "ua": "RenovateBot/37.230.0 (https://github.com/renovatebot/renovate)",
    "route": "/api/:version/version",
    "user_id": 42,
    "username": "renovate-bot",
    "token_type": "PersonalAccessToken",
    "token_id": 21,
    "queue_duration_s": 0.012942,
    "redis_calls": 1,
    "redis_duration_s": 0.001102,
    "redis_write_bytes": 108,
    "redis_shared_state_calls": 1,
    "redis_shared_state_duration_s": 0.001102,
    "redis_shared_state_write_bytes": 108,
    "db_count": 3,
    "db_write_count": 0,
    "db_cached_count": 0,
    "db_replica_count": 0,
    "db_primary_count": 3,
    "db_main_count": 3,
    "db_ci_count": 0,
    "db_main_replica_count": 0,
    "db_ci_replica_count": 0,
    "db_replica_cached_count": 0,
    "db_primary_cached_count": 0,
    "db_main_cached_count": 0,
    "db_ci_cached_count": 0,
    "db_main_replica_cached_count": 0,
    "db_ci_replica_cached_count": 0,
    "db_replica_wal_count": 0,
    "db_primary_wal_count": 0,
    "db_main_wal_count": 0,
    "db_ci_wal_count": 0,
    "db_main_replica_wal_count": 0,
    "db_ci_replica_wal_count": 0,
    "db_replica_wal_cached_count": 0,
    "db_primary_wal_cached_count": 0,
    "db_main_wal_cached_count": 0,
    "db_ci_wal_cached_count": 0,
    "db_main_replica_wal_cached_count": 0,
    "db_ci_replica_wal_cached_count": 0,
    "db_replica_duration_s": 0.0,
    "db_primary_duration_s": 0.002,
    "db_main_duration_s": 0.002,
    "db_ci_duration_s": 0.0,
    "db_main_replica_duration_s": 0.0,
    "db_ci_replica_duration_s": 0.0,
    "cpu_s": 0.043503,
    "mem_objects": 7916,
    "mem_bytes": 655664,
    "mem_mallocs": 2651,
    "mem_total_bytes": 972304,
    "pid": 2728685,
    "worker_id": "puma_3",
    "rate_limiting_gates": [],
    "correlation_id": "01HRXJ8W5HS83NKZP6JRRMFKJJ",
    "meta.caller_id": "GET /api/:version/version",
    "meta.remote_ip": "192.168.1.162",
    "meta.feature_category": "not_owned",
    "meta.user": "renovate-bot",
    "meta.user_id": 42,
    "meta.client_id": "user/42",
    "request_urgency": "default",
    "target_duration_s": 1
}

I couldn't find any detailed request/response logs, and I'd rather not enable them over night just to get 2 entries in the morning if I can avoid it (but if thats what I'll have to do, let me know how.)
Renovate doesn't log any more than that, even with LOG_LEVEL=debug; at least I couldn't get any more than that. Going by the odd return value length of 4, I'm somewhat assuming that it returns the string "null" (since an empty JSON object {} or array [] would likely be anything thats not 4.)

What is the expected correct behavior?

Renovate attempts to orient itself (by requesting api/v4/user, api/v4/version and others) before iterating its repositories, then checking for updates.

This happens around the clock, without fail, every hour as the schedule dictates. Only the one around 5am appears to fail for unknown reasons.

The associated entries in nginx.log look like this:

192.168.1.162 - - [14/Mar/2024:06:04:38 +0100] "GET /api/v4/user HTTP/1.1" 200 478 "" "RenovateBot/37.230.0 (https://github.com/renovatebot/renovate)" 1.94
192.168.1.162 - - [14/Mar/2024:06:04:39 +0100] "GET /api/v4/version HTTP/1.1" 200 156 "" "RenovateBot/37.230.0 (https://github.com/renovatebot/renovate)" -

Note the 156 bytes returned for the api/v4/version call, which are probably the expected response including the GitLab version and other info (as JSON.)
Except that I cannot really see any difference in the API log between the two.

Associated entry from `api_json.log` 
{
    "time": "2024-03-14T05:04:39.626Z",
    "severity": "INFO",
    "duration_s": 0.35442,
    "db_duration_s": 0.00228,
    "view_duration_s": 0.35214,
    "status": 200,
    "method": "GET",
    "path": "/api/v4/version",
    "params": [],
    "host": "gitlab",
    "remote_ip": "192.168.1.162, 127.0.0.1",
    "ua": "RenovateBot/37.230.0 (https://github.com/renovatebot/renovate)",
    "route": "/api/:version/version",
    "user_id": 42,
    "username": "renovate-bot",
    "token_type": "PersonalAccessToken",
    "token_id": 21,
    "queue_duration_s": 0.011923,
    "redis_calls": 1,
    "redis_duration_s": 0.000419,
    "redis_write_bytes": 54,
    "redis_shared_state_calls": 1,
    "redis_shared_state_duration_s": 0.000419,
    "redis_shared_state_write_bytes": 54,
    "db_count": 3,
    "db_write_count": 0,
    "db_cached_count": 0,
    "db_replica_count": 0,
    "db_primary_count": 3,
    "db_main_count": 3,
    "db_ci_count": 0,
    "db_main_replica_count": 0,
    "db_ci_replica_count": 0,
    "db_replica_cached_count": 0,
    "db_primary_cached_count": 0,
    "db_main_cached_count": 0,
    "db_ci_cached_count": 0,
    "db_main_replica_cached_count": 0,
    "db_ci_replica_cached_count": 0,
    "db_replica_wal_count": 0,
    "db_primary_wal_count": 0,
    "db_main_wal_count": 0,
    "db_ci_wal_count": 0,
    "db_main_replica_wal_count": 0,
    "db_ci_replica_wal_count": 0,
    "db_replica_wal_cached_count": 0,
    "db_primary_wal_cached_count": 0,
    "db_main_wal_cached_count": 0,
    "db_ci_wal_cached_count": 0,
    "db_main_replica_wal_cached_count": 0,
    "db_ci_replica_wal_cached_count": 0,
    "db_replica_duration_s": 0.0,
    "db_primary_duration_s": 0.002,
    "db_main_duration_s": 0.002,
    "db_ci_duration_s": 0.0,
    "db_main_replica_duration_s": 0.0,
    "db_ci_replica_duration_s": 0.0,
    "cpu_s": 0.040541,
    "mem_objects": 8836,
    "mem_bytes": 607056,
    "mem_mallocs": 2499,
    "mem_total_bytes": 960496,
    "pid": 2728681,
    "worker_id": "puma_1",
    "rate_limiting_gates": [],
    "correlation_id": "01HRXNJ6TS28352RWJMH8GDB94",
    "meta.caller_id": "GET /api/:version/version",
    "meta.remote_ip": "192.168.1.162",
    "meta.feature_category": "not_owned",
    "meta.user": "renovate-bot",
    "meta.user_id": 42,
    "meta.client_id": "user/42",
    "request_urgency": "default",
    "target_duration_s": 1
}

Relevant logs and/or screenshots

Full CI Job log 
Running with gitlab-runner 16.9.1 (782c6ecb)
  on build03a gqSWmGzn, system ID: s_8cec47978d7f
section_start:1710389173:prepare_executor
Preparing the "shell" executor
Using Shell (powershell) executor...
section_end:1710389173:prepare_executor
section_start:1710389173:prepare_script
Preparing environment
Running on ATEIS105...
section_end:1710389174:prepare_script
section_start:1710389174:get_sources
Getting source from Git repository
Fetching changes with git depth set to 20...
Reinitialized existing Git repository in E:/GitLab/builds/gqSWmGzn/0/renovate/runner/.git/
Checking out dbe440ea as detached HEAD (ref is master)...
git-lfs/3.4.0 (GitHub; windows amd64; go 1.20.6; git d06d6e9e)

Skipping Git submodules setup
section_end:1710389181:get_sources
section_start:1710389181:step_script
Executing "step_script" stage of the job script
$ npx renovate $RENOVATE_EXTRA_FLAGS
DEBUG: Using RE2 regex engine
DEBUG: Parsing configs
DEBUG: Checking for config file in config.js
DEBUG: Converting GITHUB_COM_TOKEN into a global host rule
DEBUG: File config
"config": {
"endpoint": "https://gitlab/api/v4/",
"platform": "gitlab",
"onboardingConfig": {"extends": ["renovate/config"]},
"autodiscover": true,
"autodiscoverFilter": ["!/utils/./"],
"optimizeForDisabled": true,
"persistRepoData": true,
"detectGlobalManagerConfig": true
}
DEBUG: CLI config
"config": {}
DEBUG: Env config
"config": {
"hostRules": [
{"hostType": "github", "matchHost": "github.com", "token": ""}
],
"baseDir": "E:\GitLab\builds\gqSWmGzn\0\renovate\runner/renovate",
"endpoint": "https://gitlab/api/v4",
"token": ""
}
DEBUG: Combined config
"config": {
"endpoint": "https://gitlab/api/v4",
"platform": "gitlab",
"onboardingConfig": {"extends": ["renovate/config"]},
"autodiscover": true,
"autodiscoverFilter": ["!/utils/./"],
"optimizeForDisabled": true,
"persistRepoData": true,
"detectGlobalManagerConfig": true,
"hostRules": [
{"hostType": "github", "matchHost": "github.com", "token": ""}
],
"baseDir": "E:\GitLab\builds\gqSWmGzn\0\renovate\runner/renovate",
"token": ""
}
DEBUG: Detecting global manager config
DEBUG: Detected C:/Users/builder/.npmrc and adding it to global config
DEBUG: Global manager config
"config": {"npmrc": "***********", "npmrcMerge": true}
DEBUG: Adding trailing slash to endpoint
DEBUG: Found valid git version: 2.42.0
DEBUG: Setting global hostRules
DEBUG: Adding token authentication for github.com (hostType=github) to hostRules
DEBUG: hostRules: authentication already set for gitlab
DEBUG: Using throttle 200 intervalMs for host gitlab
DEBUG: Using queue: host=gitlab, concurrency=5
DEBUG: Error authenticating with GitLab. Check that your token includes "api" permissions
"err": {
"message": "Cannot read properties of null (reading 'version')",
"stack": "TypeError: Cannot read properties of null (reading 'version')\n    at Proxy.initPlatform (C:\Users\builder\AppData\Roaming\npm\node_modules\renovate\lib\modules\platform\gitlab\index.ts:139:31)\n    at processTicksAndRejections (node:internal/process/task_queues:95:5)\n    at initPlatform (C:\Users\builder\AppData\Roaming\npm\node_modules\renovate\lib\modules\platform\index.ts:49:24)\n    at globalInitialize (C:\Users\builder\AppData\Roaming\npm\node_modules\renovate\lib\workers\global\initialize.ts:86:12)\n    at C:\Users\builder\AppData\Roaming\npm\node_modules\renovate\lib\workers\global\index.ts:148:16\n    at start (C:\Users\builder\AppData\Roaming\npm\node_modules\renovate\lib\workers\global\index.ts:137:5)\n    at C:\Users\builder\AppData\Roaming\npm\node_modules\renovate\lib\renovate.ts:18:22"
}
FATAL: Authentication failure
INFO: Renovate is exiting with a non-zero code due to the following logged errors
"loggerErrors": [
{
"name": "renovate",
"level": 60,
"logContext": "CG5Kr71zoBhSmRCUrI-R9",
"msg": "Authentication failure"
}
]
section_end:1710389229:step_script
section_start:1710389229:cleanup_file_variables
Cleaning up project directory and file based variables
section_end:1710389229:cleanup_file_variables
ERROR: Job failed: exit status 1

Output of checks

Results of GitLab environment info

Expand for output related to GitLab environment info 
root@gitlab:~# gitlab-rake gitlab:env:info

System information
System:         Debian 12
Current User:   git
Using RVM:      no
Ruby Version:   3.1.4p223
Gem Version:    3.5.5
Bundler Version:2.5.5
Rake Version:   13.0.6
Redis Version:  7.0.15
Sidekiq Version:7.1.6
Go Version:     unknown

GitLab information
Version:        16.9.0
Revision:       969e1ff3ab9
Directory:      /opt/gitlab/embedded/service/gitlab-rails
DB Adapter:     PostgreSQL
DB Version:     13.13
URL:            https://gitlab
HTTP Clone URL: https://gitlab/some-group/some-project.git
SSH Clone URL:  git@gitlab:some-group/some-project.git
Using LDAP:     yes
Using Omniauth: yes
Omniauth Providers:

GitLab Shell
Version:        14.33.0
Repository storages:
- default:      unix:/var/opt/gitlab/gitaly/gitaly.socket
GitLab Shell path:              /opt/gitlab/embedded/service/gitlab-shell

Gitaly
- default Address:      unix:/var/opt/gitlab/gitaly/gitaly.socket
- default Version:      16.9.0
- default Git Version:  2.43.0

Results of GitLab application Check

Expand for output related to the GitLab application check 
root@gitlab:~# gitlab-rake gitlab:check SANITIZE=true

Checking GitLab subtasks ...


Checking GitLab Shell ...


GitLab Shell: ... GitLab Shell version >= 14.33.0 ? ... OK (14.33.0)
Running /opt/gitlab/embedded/service/gitlab-shell/bin/check
Internal API available: OK
Redis available via internal API: OK
gitlab-shell self-check successful


Checking GitLab Shell ... Finished


Checking Gitaly ...


Gitaly: ... default ... OK


Checking Gitaly ... Finished


Checking Sidekiq ...


Sidekiq: ... Running? ... yes
Number of Sidekiq processes (cluster/worker) ... 1/1


Checking Sidekiq ... Finished


Checking Incoming Email ...


Incoming Email: ... Reply by email is disabled in config/gitlab.yml


Checking Incoming Email ... Finished


Checking LDAP ...


LDAP: ... Server: ldapmain
not verifying SSL hostname of LDAPS server 'dc01.domain.tld:389'
LDAP authentication... Success
LDAP users with access to your GitLab server (only showing the first 100 results)
User output sanitized. Found 100 users of 100 limit.


Checking LDAP ... Finished


Checking GitLab App ...


Database config exists? ... yes
Tables are truncated? ... skipped
All migrations up? ... yes
Database contains orphaned GroupMembers? ... no
GitLab config exists? ... yes
GitLab config up to date? ... yes
Cable config exists? ... yes
Resque config exists? ... yes
Log directory writable? ... yes
Tmp directory writable? ... yes
Uploads directory exists? ... yes
Uploads directory has correct permissions? ... yes
Uploads directory tmp has correct permissions? ... yes
Systemd unit files or init script exist? ... skipped (omnibus-gitlab has neither init script nor systemd units)
Systemd unit files or init script up-to-date? ... skipped (omnibus-gitlab has neither init script nor systemd units)
Projects have namespace: ...
3/2 ... yes
4/3 ... yes
4/4 ... yes
5/5 ... yes
8/6 ... yes
8/7 ... yes
8/8 ... yes
5/9 ... yes
12/10 ... yes
8/11 ... yes
17/12 ... yes
19/13 ... yes
8/15 ... yes
31/16 ... yes
31/18 ... yes
31/19 ... yes
31/20 ... yes
4/21 ... yes
8/23 ... yes
34/24 ... yes
34/25 ... yes
34/26 ... yes
34/27 ... yes
34/28 ... yes
8/29 ... yes
35/30 ... yes
35/31 ... yes
35/32 ... yes
35/33 ... yes
34/34 ... yes
34/35 ... yes
38/36 ... yes
12/37 ... yes
8/38 ... yes
39/39 ... yes
39/40 ... yes
8/41 ... yes
34/43 ... yes
10/44 ... yes
10/45 ... yes
10/46 ... yes
10/47 ... yes
10/48 ... yes
10/49 ... yes
40/50 ... yes
40/51 ... yes
40/52 ... yes
41/53 ... yes
42/54 ... yes
43/55 ... yes
43/56 ... yes
4/57 ... yes
44/58 ... yes
45/59 ... yes
4/60 ... yes
4/61 ... yes
17/62 ... yes
46/63 ... yes
46/64 ... yes
46/65 ... yes
47/66 ... yes
13/67 ... yes
13/68 ... yes
13/69 ... yes
2/70 ... yes
2/71 ... yes
2/72 ... yes
2/73 ... yes
2/74 ... yes
40/75 ... yes
31/76 ... yes
31/77 ... yes
6/78 ... yes
49/80 ... yes
13/81 ... yes
51/82 ... yes
19/83 ... yes
2/84 ... yes
2/85 ... yes
54/86 ... yes
19/87 ... yes
8/88 ... yes
173/90 ... yes
2/91 ... yes
10/92 ... yes
8/93 ... yes
49/94 ... yes
31/95 ... yes
49/96 ... yes
2/97 ... yes
4/98 ... yes
155/99 ... yes
37/100 ... yes
7/101 ... yes
7/102 ... yes
13/104 ... yes
167/105 ... yes
25/106 ... yes
25/107 ... yes
173/108 ... yes
167/109 ... yes
167/110 ... yes
167/111 ... yes
10/112 ... yes
167/113 ... yes
167/114 ... yes
185/115 ... yes
2/116 ... yes
173/117 ... yes
173/118 ... yes
25/119 ... yes
196/120 ... yes
196/121 ... yes
31/122 ... yes
173/123 ... yes
17/124 ... yes
167/125 ... yes
2/126 ... yes
167/127 ... yes
7/128 ... yes
7/129 ... yes
7/130 ... yes
7/131 ... yes
Redis version >= 6.2.14? ... yes
Ruby version >= 3.0.6 ? ... yes (3.1.4)
Git user has default SSH configuration? ... yes
Active users: ... 34
Is authorized keys file accessible? ... yes
GitLab configured to store new projects in hashed storage? ... yes
All projects are in hashed storage? ... yes


Checking GitLab App ... Finished


Checking GitLab subtasks ... Finished

Possible fixes

Edited by 🤖 GitLab Bot 🤖