Large push is duplicated every 16 minute in activity stream in what seems to be an infinite loop

Summary

When pushing a very large amount of commit (ex: pushing master linux kernel branch) on a gitlab repository:

• A new duplicated push message in the activity stream appears every 16 minutes in what seems to be an infinite loop
• on the server a sidekiq process eats continuously 100% of CPU (but RAM and disk I/O are OK)
• due to this bug the activity is unusable because it gets continuously polluted by these duplicated messages

Steps to reproduce

Initialy the bug was found on a gitlab-ee 9.3.0 instance (gitlab EE starter customer)

To clear any configuration dependency I've successfully reproduced the bug on a fresh gitlab-ce 9.4.0 instance: (that's why I report this bug in gitlab CE)

1. I've created a debian jessie amd64 lxc instance on an amd64 debian jessie server
2. I've installed omnibus gitlab-ce-9.4.0 on it with default configuration

To trigger the bug on this instance just push a big repo on an empty project:

1. create an empty project (ex: 'root/linux')
2. on a client machine clone the linux kernel master branch (ex: git clone https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git)
3. push the master branch on the gitlab instance: (ex: git push git@gitlab.exemple.com:root/linux.git master)

UPDATE: I've successfully reproduced this bug on gitlab.com here: https://gitlab.com/steissier/linux-test/activity

What is the current bug behavior?

Push messages in the activity stream are continuously duplicated every 16 minutes, making the activity stream totally unusable due to this garbage activity

Relevant logs and/or screenshots

Screenshot of the bug bad behavior:

Sidekiq stalled process in htop:

Results of GitLab environment info

nothing relevant...

# gitlab-rake gitlab:env:info

System information
System:		
Current User:	git
Using RVM:	no
Ruby Version:	2.3.3p222
Gem Version:	2.6.6
Bundler Version:1.13.7
Rake Version:	10.5.0
Redis Version:	3.2.5
Git Version:	2.13.0
Sidekiq Version:5.0.0
Go Version:	unknown

GitLab information
Version:	9.4.0
Revision:	9bbe2ac
Directory:	/opt/gitlab/embedded/service/gitlab-rails
DB Adapter:	postgresql
URL:		http://10.32.92.27
HTTP Clone URL:	http://10.32.92.27/some-group/some-project.git
SSH Clone URL:	git@10.32.92.27:some-group/some-project.git
Using LDAP:	no
Using Omniauth:	no

GitLab Shell
Version:	5.3.1
Repository storage paths:
- default: 	/var/opt/gitlab/git-data/repositories
Hooks:		/opt/gitlab/embedded/service/gitlab-shell/hooks
Git:		/opt/gitlab/embedded/bin/git

Results of GitLab application Check

nothing relevant...

# gitlab-rake gitlab:check SANITIZE=true
Checking GitLab Shell ...

GitLab Shell version >= 5.3.1 ? ... OK (5.3.1)
Repo base directory exists?
default... yes
Repo storage directories are symlinks?
default... no
Repo paths owned by git:root, or git:git?
default... yes
Repo paths access is drwxrws---?
default... yes
hooks directories in repos are links: ... 
1/1 ... ok
Running /opt/gitlab/embedded/service/gitlab-shell/bin/check
Check GitLab API access: OK
Access to /var/opt/gitlab/.ssh/authorized_keys: OK
Send ping to redis server: OK
gitlab-shell self-check successful

Checking GitLab Shell ... Finished

Checking Sidekiq ...

Running? ... yes
Number of Sidekiq processes ... 1

Checking Sidekiq ... Finished

Checking Reply by email ...

Reply by email is disabled in config/gitlab.yml

Checking Reply by email ... Finished

Checking LDAP ...

LDAP is disabled in config/gitlab.yml

Checking LDAP ... Finished

Checking GitLab ...

Git configured correctly? ... yes
Database config exists? ... yes
All migrations up? ... yes
Database contains orphaned GroupMembers? ... no
GitLab config exists? ... yes
GitLab config up to date? ... 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? ... skipped (no tmp uploads folder yet)
Init script exists? ... skipped (omnibus-gitlab has no init script)
Init script up-to-date? ... skipped (omnibus-gitlab has no init script)
Projects have namespace: ... 
1/1 ... yes
Redis version >= 2.8.0? ... yes
Ruby version >= 2.3.3 ? ... yes (2.3.3)
Git version >= 2.7.3 ? ... yes (2.13.0)
Active users: ... 1

Checking GitLab ... Finished

changed the description

I've successfully reproduced this bug on gitlab.com here: https://gitlab.com/steissier/linux-test/activity

the procedure is very simple:

git clone https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git
cd linux/
#created a new empty project on gitlab.com 'steissier/linux-test'
git push git@gitlab.com:steissier/linux-test.git master

changed title from Large push is duplicated every 16 minute in activity stream in what seems an infinite loop to Large push is duplicated every 16 minute in activity stream in what seems to be an infinite loop

Mentioned by the customer in ZD: https://gitlab.zendesk.com/agent/tickets/80623

@mydigitalself can you take a look?

added bug customer frontend labels

added Platform ~901060 and removed frontend labels

@DouweM any idea? queue keeps getting re-executed or something?

changed milestone to %Next 2-3 months

@mydigitalself This sounds to me like the PostReceive worker being retried again and again, possibly because it raises an error at one point during its execution, even though it did successfully create that activity message.

Let's see if I can find anything in the logs.

on my test gitlab-ce instance with only this bug triggered I get this log: sidekiq.log

we can see the SIGTERM on the sidekiq queue every ~16minutes

@steissier Thank you, that's extremely useful!

It looks like Sidekiq is killing itself because current RSS 2741416 exceeds maximum RSS 1000000, and because Work still in progress on the post_receive queue, it Pushed 1 jobs back to Redis, which means the same PostReceive job will get executed again after Sidekiq reboots. That matches exactly what we are seeing. So something in PostReceive ends up allocating a lot of memory, after the event is posted to the activity feed.

Let me investigate further...

The timeline looks like this:

• PostReceive worker starts
• PostReceive worker calls GitPushService
• GitPushService queues UpdateMergeRequestsWorker
• GitPushService creates activity event
• UpdateMergeRequestsWorker starts in the same Sidekiq worker
• UpdateMergeRequestsWorker finishes
• Sidekiq Memory Killer notices that the RSS of the Sidekiq worker (which is still currently handling the PostReceive worker) is higher than the limit
• Sidekiq Memory Killer sleeps for 15 minutes (grace period of 900 seconds)
• PostReceive worker (and GitPushService) are apparently still running after 15 minutes
• Sidekiq Memory Killer kills Sidekiq worker and PostReceive worker
• Sidekiq Memory Killer requeues PostReceive worker

The take aways are:

• PostReceive worker / GitPushService uses a lot of memory before UpdateMergeRequestsWorker finishes (which is mere milliseconds after it is queued)
• PostReceive worker / GitPushService takes more than 15 minutes to complete, even after the activity event is created

What may be happening is that we are loading each and every one of the pushed commits into memory, and iterating over them. Let me investigate further :)

GitPushService has multiple issues that contribute to this:

• It loads ALL pushed commits into memory: http://gitlab.com/gitlab-org/gitlab-ce/blob/master/app/services/git_push_service.rb#L126
• It iterates over ALL commits and then over ALL changed files in each of those commits: http://gitlab.com/gitlab-org/gitlab-ce/blob/master/app/services/git_push_service.rb#L69

@steissier Are you in a position where you can manually apply a patch to GitLab (gitlab-rails inside your omnibus installation dir)?

If so, can you see if the attached one resolves the problem?

process_commit_limit.diff

After restarting your GitLab instance, the PostReceive worker should run once, and properly finish.

successfully applied, I'm testing

@steissier I'm testing it locally as well and am already finding some issues. Hold on :)

assigned to @DouweM

mentioned in merge request !13132 (merged)

@steissier Can you try the patch from https://gitlab.com/gitlab-org/gitlab-ce/merge_requests/13132?

new patch applied and testing

Result of the test:

• the patch solves the problem (no duplicate message in activity page)
• there is still a SIGTERM on sidekiq triggered due to current RSS 1317900 exceeds maximum RSS 100000 (see log bellow)

sidekiq log: sidekiq2.log (the push of the big repo is finished just before 2017-07-27T13:35:04.502Z)

@steissier All right, sounds like there is still some memory use to be reduced, but it's a step in the right direction! PostReceive now finishes in 18 seconds, which means it's done way before the 15 minutes are over and it would be rescheduled.

When https://gitlab.com/gitlab-org/gitlab-ce/merge_requests/13132 is merged, I'm going to regard this particular issue as fixed, because Sidekiq self-recovers from the SIGKILL, this is only an issue with huge pushes, and because the reported bug is now fixed.

closed via merge request !13132 (merged)

mentioned in commit 0bb58ff8

Just to share my experience with this issue: I just restart my GitLab server and it stops filling the activity windows with every 16 minutes.

Until this is fixed in an official release, this may help on-premise CE users which can have a minimum of downtime on their instance and don't want to apply WIP patches

mentioned in issue #36350 (closed)

marked this issue as related to #36350 (closed)