postmortem.io Beta
Incident

GitLab.com Database Outage Postmortem (July 7-8, 2014)

GitLab Read the original original source ↗

Welcome dear people, sorry about the downtime, we’re live editing this postmortem, enjoy the show, WE ARE DONE FOR TODAY AND ALREADY IMPLEMENTED SOME OUTCOMES, feel free to leave comments here or on HackerNews (since there are too many people viewing this doc after it was nr. 1 on HN) #openops

Background on our HA setup

Presentation from yesterdays Utrechtrb meetup https://docs.google.com/presentation/d/1gIzmp-d5X86jJMQz7Ixs_dzyhC1OTVK0w3uV_Rtc_Us/edit#slide=id.p

Timeline

  1. 12:00 CEST Monty was the operational server for the last few days
  2. 18:00 CEST Last db backup around ?18:00 CEST? yesterday, snapshot on monty
  3. 18:00 CEST / 16:00 UTC FreeNAS server most recent backup Jul 7, (same as snapshot on Monty)
  4. 19:00 CEST Sytse bragged we had zero incidents so far.
  5. 01:02 CEST Pingdom 2 minutes of downtime
  6. 01:05 CEST Pingdom 6 minutes of downtime
  7. 01:08 CEST Broken pipe PostgreSQL
    • 2014-07-07_23:08:47.89643 monty postgresql: LOG: could not send data to client: Broken pipe
  8. 01:13 CEST Pagerduty triggered because GitLab.com was offline, Pingdom incident #32 https://my.pingdom.com/ims/incidents/53bb281f39d0ec323e658b85
  9. 01:14 CEST Pagerduty resolved (unknown) Pingdom incident #32
  10. 01:14 CEST Pingdom 7 hours of downtime
  11. 01:22 CEST Pagerduty triggered because GitLab.com was offline, onwards Pingdom Incident #33 https://my.pingdom.com/ims/incidents/53bb2a3e39d0ec31f9658cac
  12. 01:25 CEST it rebooted (might have been a few minutes earlier)
  • reboot system boot 3.11.0-24-generi Mon Jul 7 23:25 - 06:25 (06:59) UTC
  • reboot system boot 3.11.0-24-generi Mon Jul 7 23:27 - 06:25 (06:57) UTC
  1. 01:25 CEST / 23:25 UTC lots of resync activity
  2. 01:59 CEST First email to sales@ about downtime
  3. 01:59 CEST First twitter report about downtime https://twitter.com/whlteXbread/status/486299248678301696 2:02 AM CEST
  4. 02:00 CEST / 0:00 UTC it was supposed to run the backup
  • Backup times: 00:00, 08:00, 16:00 UTC
  1. 07:42 CEST
  • monty postgresql: LOG: database system was shut down at 2014-05-30 13:24:32 GMT
  • monty postgresql: LOG: database system is ready to accept connections
  • monty postgresql: LOG: autovacuum launcher started
  1. 07:45 CEST monty postgresql: FATAL: database “gitlabhq_production” does not exist
  2. 07:53 CEST
  • monty postgresql: received TERM from runit, sending INT instead to force quit connections
  • monty postgresql: LOG: received fast shutdown request
  1. 8:00 CEST We now have a database of size 0 on Monty reported by Munin
  2. 8:00 CEST We also have a database of size 0 or no db on Linus (propagated)
  3. 9:00 CEST total file size of Postgres data dir on Monty seems OK
  4. 9:02 CEST stopped the db and rsynced the database directory
  5. 9:29 CEST back online
  6. 10:52 CEST sidekiq restarted (was not connected to the DB before)

Recap of events

  1. Status before failure: Monty master, linus slave
  2. Disk lock on monty, causing the reboot
  3. Monty rebooted at around 01:25 CEST
  4. Monty is now no longer master, linus is still slave: both servers are slave
  5. Gitlab doesn’t start after reboot, this is to prevent any corruption of the data due to our setup. It requires manual assistance.
  6. Production filesystem IS NOT mounted at this point
  7. Job is the first to get to the server
  8. gitlab-ctl status, this shows that everything is down
  9. gitlab-ctl start starts the GitLab with the staging data in /var/opt/gitlab on the root filesystem that doesn’t have any production data. At this point logs report that the production db doesn’t exist which is correct because we are not on the production file system. No production data has been touched at this point. The Gitlab web UI is not responding (502 error from nginx)
  10. Munin reports that the db is 6mb in size which correct since it is reporting a running staging db instead of production.
    • we look at our backups; the last backup is from 6 hours before the reboot. the backup is available locally as an LVM snapshot
  12. At this point, while the staging db is running, we promote monty to master. This mounts the production filesystem with the correct data at /var/opt/gitlab , while the running gitlab processes (unicorn, nginx, postgresql etc.) still have open files on the root filesystem.
  13. This is still not touching any production data. We still see a small db.
  14. Jacob notices that there is much more than 6 MB in /var/opt/gitlab/postgresql and wonders where the difference comes from. We now know that the difference is that munin connects to a postgres process running from the root filesystem, while we are looking at the production filesystem.
  15. Instead of restoring the LVM snapshot, at this point we restart postgresql.
    • rails console session shows the expected user count, we still have no idea why the system is not responding properly
    • we decide to restart unicorn. this time, unicorn starts running on the production filesystem and creates a socket on the production filesystem instead of the root filesystem
    • gitlab.com is mostly working again
    • we get reports about sidekiq jobs not processing; we restart sidekiq
    • 2.5 hours into our investigation we realize what happened with the filesystems, and that some running processes are still working with files on the root filesystem instead of the production filesystem. we restart sidekiq and redis.
    • we understand at this point why we had difficulties bringing the service back online
    • we do not know yet with certainty what exactly caused the reboot

Why did we start GitLab on the wrong file system?

Our gitlab master script does a start, which doesn’t restart it if it is already running.

=> We’re changing the gitlab master script to do a restart to prevent this.

Why did we get a brownout before the reboot?

Big read activity on http://graphs.gitlap.com/gitlab.com/monty.gitlab.com/iostat.html at 00:45 (times on graphs are strange)

Very large push on the biggest repository we have (~18GB).

Log message for the large repo (repo name redacted)

2014-07-07T21:00:22.192625+00:00 192.168.0.102 269 <13>Jul 7 21:00:22 monty production.log: Started GET “/api/v3/internal/allowed?action=git-receive-pack&ref=_any&project=

The push from 2014-07-07T21:00:22.192625 was only 35 MB. Enough to be labeled a ‘large git push’ in the web UI, but nowhere near sufficient to explain an hour of 50 Mbit/s sustained inbound network traffic.

Only 0.1% of repos are bigger than 1GB. => I added back the soft limit warning https://gitlab.com/gitlab-com/www-gitlab-com/commit/aaface9e825308ceec73af2ef1ccc547f70b7a8c deployed here: https://about.gitlab.com/gitlab-com/

Should be start enforcing the soft limit of 1GB we had until a day ago? Maybe at 2 or 5 GB?

And even a multi gigabyte push should not cause problems, did it have special characteristics? => the push seems to be a red herring, only 35MB

Why did it reboot?

See the Syslog for the brownout nginx makes it uninterruptible 23:12 syn timer expired

HP iLO system event log shows last event at June 6 2014, then three events on July 7 2014: Generic 07/07/2014 23:21:49 Watchdog Timer interrupt Assertion Generic 07/07/2014 23:21:49 Watchdog Hard Reset Assertion Generic 07/07/2014 23:21:57 PSRed Status Redundancy Lost Assertion

Virtual power: Last restart cause: watchdog => Due to the brownout the watchdog was triggered.

Ask friends at hosting provider what the specs of the Watchdog Timer interrupt Assertion are. =>

Read http://h30507.www3.hp.com/t5/Reality-Check-Server-Insights/Solving-the-Riddle-of-Non-Maskable-Interrupts-WatchDog-Timer/ba-p/91669#.U7vVvo2Syeg

Other references:

Why the watchdog?

The watchdog is maybe on by default, should we disable it? => Considering that we have a manual failover we should disable it. Not sure if we can do that.

Why did GitLab start when it shouldn’t?

Based on https://news.ycombinator.com/item?id=8005963 Apparently gitlab-ctl created staging data on the root filesystem. Is this something we want to happen? => Adapt Omnibus GitLab to not start when it can’t find a certain file?

Bootstrap false https://dev.gitlab.org/cookbooks/chef-repo/blob/master/roles/gitlab-cluster.json#L121

Don’t want to start services when you are not on the production file system

Why did it look at the root filesystem? Because /var/opt/gitlab was on the root system, it just didn’t have any mounts.

Don’t create dir when the ‘mounted’ directory does not exist and bootstrap is false? => Can do this but a lot of work because there are a lot of dirs. Advantage is that you don’t create confusing directories (have to use mount) that might lead to other problems.

Have gitlab-ctr start check if a mounted directory exists? => Yes, can test if /var/opt/gitlab is a mountpoint

NOTE: You can hide a directory by mounting over it but can still have the files open that are now hidden.

Services won’t start when a master file is missing. Make with hand just like the production filesystem. Just like https://gitlab.com/gitlab-org/omnibus-gitlab/blob/master/files/gitlab-cookbooks/gitlab/recipes/bootstrap.rb That is created after all services are running https://gitlab.com/gitlab-org/omnibus-gitlab/blob/master/files/gitlab-cookbooks/gitlab/recipes/default.rb#L67 Is there something we deleted from https://github.com/opscode/omnibus-chef-server/blob/master/files/chef-server-cookbooks/chef-server/recipes/bootstrap.rb ? Bootstrap file is made for things that have to happen only once => Don’t reuse bootstrap

Do it in ctr or in each service individually? => Each service is easier due to https://github.com/opscode/omnibus-ctl/blob/master/lib/omnibus-ctl.rb#L123 the start files are written with the cookbook ‘run’ script comes from a template https://gitlab.com/gitlab-org/omnibus-gitlab/blob/master/files/gitlab-cookbooks/gitlab/templates/default/sv-nginx-run.erb and the start-preventer can be written only if that is enabled

Conclusion: we’ll introduce a mounpoint_check setting that adds a check to every service script that tests if /var/opt/gitlab is a mountpoint

Why did we see the db was 6MB in Munin?

The data dir was 1.8GB at the time. It could have been unmounted but even when mounted it looked like 6MB. => The postgres process that was running opened the database files on the root filesystem (not the production one).

Why did we get the gitlabhq_production missing error?

2014-07-08_05:45:12.32497 monty postgresql: FATAL: database “gitlabhq_production” does not exist => See answer to: Why did we get the db is 6MB in Munin?

Why did the reconfigure command try to create a database?

Maybe because the disk wasn’t mounted at the time? => See answer to: Why did we get the db is 6MB in Munin?

Why didn’t it work when Job made it master?

Upon running sudo gitlab-drbd master on monty, no specific warning or force message was given. sudo gitlab-ctl status was positive => Because he started the services before. Solved with answer to: Why did we start GitLab on the wrong file system?

Why did we suspect the backup script caused something?

Because we recently automated it. But it does not look like it caused problems, monty had already rebooted before the last time the backup ran. considering that monty was not master, it is expected behavior that there is no snapshot from July 8 0:00 UTC. => Because the brownout started less than an hour before the brand new backup script was scheduled. But this was a coincidence.

Why did we miss pagerduty?

Sytse: My phone was on silent. Didn’t get a call even though my profile read: Immediately after an incident is assigned to me, email me at sytse@gitlab.com (Default) Immediately after an incident is assigned to me, push notify me on Nexus 5 2 minutes after an incident is assigned to me, push notify me on Sytse’s iPhone 5 minutes after an incident is assigned to me, SMS me at +31 REDACTED (Mobile) 8 minutes after an incident is assigned to me, phone me at +31 REDACTED (Mobile) 10 minutes after an incident is assigned to me, phone me at +31 REDACTED (Home) This was due to our escalation being 5 minutes => Add pagerduty to no-block list, added +1 (415) 349-5750, done Changed my escalation policy to 4 minutes, done Added to the agenda to check other peoples, done

Job: I was on duty, didn’t get text, only push notification because the notification settings were not set up to call / text me, only push message and email => Set up better notifications with SMS and phone and set to unblock list

Dmitriy: Yes i got an alert. Email and push notification to iPad => Maybe there was a problem adding DZ his phone number before but right now Ukraine is on the list of supported countries

Jacob: I was not on call and my phone was in another room. => OK

Marin: I was not on call and my phone was next to my head fully turned on. I just wasn’t woken up by the call. I received a call and 2 SMS. => OK

Why was the Pagerduty incident resolved by Sytse?

=> It wasn’t. It was resolved by timeout. We should increase the timeout or disable it.

Pagerduty timeout is now disabled for all services (cloud, pingdom, emergency):

Why didn’t Job and Sytse know what to do?

We couldn’t find the drbd documentation. => Add DRBD troubleshooting section to gitlab-drdb and https://dev.gitlab.org/cookbooks/gitlab-drbd/blob/master/README.md should link to the docs inside that repo => https://dev.gitlab.org/cookbooks/gitlab-drbd/commit/1578ebcf9402d30a5f8ce4f0fdf2802a6199f9bd

Lack of training (was on the agenda for today) => Start training later this week.

Look in the operations doc but didn’t find anything => Add references in the gitlab operations doc to drbd doc: https://dev.gitlab.org/cookbooks/gitlab-drbd/blob/master/doc/control_script.md => https://docs.google.com/document/d/1JZ0fj9YCn6sSyDyMu4ygxA3YmFaeOT4S4jFPEZcHLOE/edit#heading=h.t4ytv7iahkds

Can’t find document how to check the logs in the FreeBSD jail? => Already in the Chef repo, add reference from operations doc

Document what to do if the server is not responding? => Make a step by step, include reboot instructions and what to check if you can log in.

Why did we use gitlab-ctl instead of the failover script?

Hard to think about two scripts => Maybe integrate into gitlab-ctl? (or maybe not) Not sure we should ensure status shows everything? Would need a runit service for that? Or create a simple ‘master’ service that the other services depend on. Create a ‘gitlab-ctl drbd’ porcelain command https://gitlab.com/gitlab-org/omnibus-gitlab/issues/185

Why did we consider restoring from backup?

Because it looked like our DB was 6MB on munin. => Always important to check the state yourself and to copy any files you’ll replace to a safe location. Be very careful before doing a restore. As soon as you give people access the data loss is still a fact.

Why was sidekiq not connected to the database after restart?

If we need to check this it should be on a list. => We never restarted sidekiq because we only stopped/start unicorn. Should be solved by the automatic restart, answer to: Why did we start GitLab on the wrong file system?

Why do the graphs times seem to be neither CEST or UTC?

For example on http://graphs.gitlap.com/gitlab.com/monty.gitlab.com/postgres_checkpoints.html They are on some U.S. time zone that the server is on. => We’ll change the graph server to UTC, risking that our data will jump. => done, no data jump

Why aren’t MR’s updated?

Sytse: This MR doesn’t seem to be updated https://gitlab.com/gitlab-org/gitlab-ce/merge_requests/137#note_152441 is this due to sidekiq? jacobvosmaer [11:37 AM] maybe, sidekiq was on but not functioning for a while jacobvosmaer [11:37 AM] could be that the job got processed, failed, and never retried the postreceive job [11:38 AM] sidekiq is running all retries have been done, only a few missing id for mailers that are now in the retry queue Sytse: maybe look into the retrying of post receive jobs? => The job might have been lost on the root filesystem.

Why was the backup more than 6 hours old?

Because it backs up every 8 hours. That is because transferring the data takes multiple hours (4+ hours and growing). => Apart from the ‘backup snapshots’ also take hourly snapshots in case something goes wrong but LVM survives. Ensure to monitor for disk usage due to the snapshots.

Why was the pingdom 314 incident closed?

https://my.pingdom.com/ims/incidents/53bb2a3e39d0ec31f9658cac

The pingdom incidents closed automatically when the GitLab.com service was restored around 9:28 CET.

Comcoaster monitoring 314: 2014-07-08 09:28:04 Closed the incident 2014-07-08 01:16:00 Incident triggered

GitLab monitoring 33: 07/08/2014 08:28:09AM Closed the incident 07/08/2014 12:16:14AM Incident triggered

GitLab account was in GMT => Changed in Localization from GMT to CET

Why did some repo’s get corrupted?

See https://gitlab.com/gitlab-com/support-forum/issues/2 =>

Log volume

log volume going down

grep -c ‘^2014-07-07T22’ 192.168.0.102-20140707

201657

grep -c ‘^2014-07-07T23’ 192.168.0.102-20140707

31519

Graphs

Disk http://graphs.gitlap.com/gitlab.com/monty.gitlab.com/diskstats_throughput/ Big read spike http://graphs.gitlap.com/gitlab.com/monty.gitlab.com/iostat.html Throughput was spiking http://graphs.gitlap.com/gitlab.com/monty.gitlab.com/fw_packets.html Postgres checkpoint big spike http://graphs.gitlap.com/gitlab.com/monty.gitlab.com/postgres_checkpoints.html

Postgres data dir

postgres directory with useful-looking data /var/opt/gitlab/postgresql/data/base/16386/

Postgresql logs

2014-07-07_23:08:47.89643 monty postgresql: LOG: could not send data to client: Broken pipe 2014-07-07_23:08:47.89648 monty postgresql: FATAL: connection to client lost 2014-07-07_23:08:48.39191 monty postgresql: LOG: could not send data to client: Broken pipe 2014-07-07_23:08:48.39197 monty postgresql: FATAL: connection to client lost 2014-07-07_23:12:05.55348 monty postgresql: LOG: could not receive data from client: Connection reset by peer 2014-07-07_23:13:55.04398 monty postgresql: WARNING: pgstat wait timeout

^ last item in the log from the previous days logs(7.7.2014)

First items at the current log(8.7.2014) 2014-07-08_05:42:21.61125 monty postgresql: LOG: database system was shut down at 2014-05-30 13:24:32 GMT 2014-07-08_05:42:21.73421 monty postgresql: LOG: database system is ready to accept connections 2014-07-08_05:42:21.73491 monty postgresql: LOG: autovacuum launcher started

2014-07-08_05:45:12.32497 monty postgresql: FATAL: database “gitlabhq_production” does not exist 2014-07-08_05:45:12.42393 monty postgresql: FATAL: database “gitlabhq_production” does not exist 2014-07-08_05:45:12.87318 monty postgresql: FATAL: database “gitlabhq_production” does not exist 2014-07-08_05:45:12.96982 monty postgresql: FATAL: database “gitlabhq_production” does not exist

2014-07-08_05:53:18.67242 monty postgresql: received TERM from runit, sending INT instead to force quit connections 2014-07-08_05:53:18.67355 monty postgresql: LOG: received fast shutdown request 2014-07-08_05:53:18.67360 monty postgresql: LOG: aborting any active transactions 2014-07-08_05:53:18.67364 monty postgresql: LOG: autovacuum launcher shutting down 2014-07-08_05:53:18.67548 monty postgresql: LOG: shutting down 2014-07-08_05:53:18.75024 monty postgresql: LOG: database system is shut down 2014-07-08_05:53:30.15686 monty postgresql: LOG: database system was shut down at 2014-07-08 05:53:18 GMT 2014-07-08_05:53:30.15914 monty postgresql: LOG: database system is ready to accept connections 2014-07-08_05:53:30.15934 monty postgresql: LOG: autovacuum launcher started

Syslog

Syslog shows drbd and postgres in lock state(state D) at 23:11 (SEE: http://stackoverflow.com/a/6685764 ). After this has started, nginx takes over and goes into uninterruptable state over and over again:

Jul 7 23:11:42 monty kernel: [2735354.795380] jbd2/drbd0-8 D ffff880426b71e60 0 14679 2 0x00000000 Jul 7 23:11:42 monty kernel: [2735354.795385] ffff8803d1c39c58 0000000000000046 00000000000000f2 ffff88083fc54580 Jul 7 23:11:42 monty kernel: [2735354.795390] ffff8803d1c39fd8 ffff8803d1c39fd8 ffff8803d1c39fd8 0000000000014580 Jul 7 23:11:42 monty kernel: [2735354.795394] ffff880429e3ddc0 ffff880428372ee0 ffff8803d1c39c68 ffff8803d1c39d88 Jul 7 23:11:42 monty kernel: [2735354.795399] Call Trace: Jul 7 23:11:42 monty kernel: [2735354.795413] [] schedule+0x29/0x70 Jul 7 23:11:42 monty kernel: [2735354.795421] [] jbd2_journal_commit_transaction+0x241/0x1580 Jul 7 23:11:42 monty kernel: [2735354.795428] [] ? __switch_to+0x12a/0x4b0 Jul 7 23:11:42 monty kernel: [2735354.795441] [] ? _raw_spin_lock+0xe/0x20 Jul 7 23:11:42 monty kernel: [2735354.795449] [] ? add_wait_queue+0x60/0x60 Jul 7 23:11:42 monty kernel: [2735354.795456] [] ? try_to_del_timer_sync+0x4f/0x70 Jul 7 23:11:42 monty kernel: [2735354.795461] [] kjournald2+0xb8/0x240 Jul 7 23:11:42 monty kernel: [2735354.795464] [] ? add_wait_queue+0x60/0x60 Jul 7 23:11:42 monty kernel: [2735354.795468] [] ? commit_timeout+0x10/0x10 Jul 7 23:11:42 monty kernel: [2735354.795471] [] kthread+0xc0/0xd0 Jul 7 23:11:42 monty kernel: [2735354.795475] [] ? flush_kthread_worker+0xb0/0xb0 Jul 7 23:11:42 monty kernel: [2735354.795481] [] ret_from_fork+0x7c/0xb0 Jul 7 23:11:42 monty kernel: [2735354.795493] [] ? flush_kthread_worker+0xb0/0xb0 Jul 7 23:11:42 monty kernel: [2735354.795499] INFO: task postgres:19875 blocked for more than 120 seconds. Jul 7 23:11:42 monty kernel: [2735354.804138] “echo 0 > /proc/sys/kernel/hung_task_timeout_secs” disables this message. Jul 7 23:11:42 monty kernel: [2735354.821558] postgres D ffff880426b71e60 0 19875 19862 0x00000000 Jul 7 23:11:42 monty kernel: [2735354.821564] ffff88036df3ba78 0000000000000046 ffff88036df3ba48 ffff88083fc14580 Jul 7 23:11:42 monty kernel: [2735354.821571] ffff88036df3bfd8 ffff88036df3bfd8 ffff88036df3bfd8 0000000000014580 Jul 7 23:11:42 monty kernel: [2735354.821576] ffff880429e3aee0 ffff880168a20000 ffff88036df3ba88 ffff8803d1f78070 Jul 7 23:11:42 monty kernel: [2735354.821583] Call Trace: Jul 7 23:11:42 monty kernel: [2735354.821590] [] schedule+0x29/0x70 Jul 7 23:11:42 monty kernel: [2735354.821596] [] wait_transaction_locked+0x80/0xb0 Jul 7 23:11:42 monty kernel: [2735354.821601] [] ? add_wait_queue+0x60/0x60 Jul 7 23:11:42 monty kernel: [2735354.821604] [] add_transaction_credits+0xe0/0x230 Jul 7 23:11:42 monty kernel: [2735354.821610] [] ? find_get_pages+0xca/0x150 Jul 7 23:11:42 monty kernel: [2735354.821614] [] start_this_handle+0x15f/0x2f0 Jul 7 23:11:42 monty kernel: [2735354.821620] [] ? kmem_cache_alloc+0x12c/0x150 Jul 7 23:11:42 monty kernel: [2735354.821632] [] ? jbd2__journal_start.part.9+0x45/0x1d0 Jul 7 23:11:42 monty kernel: [2735354.821640] [] jbd2__journal_start.part.9+0x9f/0x1d0 Jul 7 23:11:42 monty kernel: [2735354.821646] [] ? __dec_zone_page_state+0x33/0x40 Jul 7 23:11:42 monty kernel: [2735354.821650] [] jbd2__journal_start+0x4d/0x60 Jul 7 23:11:42 monty kernel: [2735354.821656] [] __ext4_journal_start_sb+0x7c/0x100 Jul 7 23:11:42 monty kernel: [2735354.821663] [] ? ext4_evict_inode+0x1c4/0x510 Jul 7 23:11:42 monty kernel: [2735354.821666] [] ext4_evict_inode+0x1c4/0x510 Jul 7 23:11:42 monty kernel: [2735354.821672] [] evict+0xc0/0x1d0 Jul 7 23:11:42 monty kernel: [2735354.821682] [] iput_final+0xe2/0x170 Jul 7 23:11:42 monty kernel: [2735354.821686] [] iput+0x3e/0x50 Jul 7 23:11:42 monty kernel: [2735354.821689] [] dentry_iput+0xa8/0xf0 Jul 7 23:11:42 monty kernel: [2735354.821692] [] dput+0x13e/0x220 Jul 7 23:11:42 monty kernel: [2735354.821697] [] SYSC_renameat+0x33a/0x3d0 Jul 7 23:11:42 monty kernel: [2735354.821703] [] ? lg_local_unlock+0x18/0x20 Jul 7 23:11:42 monty kernel: [2735354.821708] [] ? kmem_cache_free+0x121/0x180 Jul 7 23:11:42 monty kernel: [2735354.821711] [] SyS_renameat+0xe/0x10 Jul 7 23:11:42 monty kernel: [2735354.821724] [] SyS_rename+0x1b/0x20 Jul 7 23:11:42 monty kernel: [2735354.821727] [] system_call_fastpath+0x1a/0x1f Jul 7 23:11:42 monty kernel: [2735354.821734] INFO: task nginx:18911 blocked for more than 120 seconds. Jul 7 23:11:42 monty kernel: [2735354.830705] “echo 0 > /proc/sys/kernel/hung_task_timeout_secs” disables this message. Jul 7 23:11:42 monty kernel: [2735354.848906] nginx D ffff880426b71e60 0 18911 18909 0x00000000 Jul 7 23:11:42 monty kernel: [2735354.848910] ffff88082135fcc8 0000000000000046 ffff88082135ffd8 ffff88042fc14580 Jul 7 23:11:42 monty kernel: [2735354.848914] ffff88082135ffd8 ffff88082135ffd8 ffff88082135ffd8 0000000000014580 Jul 7 23:11:42 monty kernel: [2735354.848918] ffffffff81c14440 ffff8804671f5dc0 00000b50c4757e80 ffff8807d341cd58 Jul 7 23:11:42 monty kernel: [2735354.848922] Call Trace:

Jul 7 23:12:04 monty kernel: [2735376.138956] block drbd0: md_sync_timer expired! Worker calls drbd_md_sync(). Jul 7 23:12:04 monty kernel: [2735376.139077] d-con gitlab_data: asender terminated Jul 7 23:12:04 monty kernel: [2735376.139087] d-con gitlab_data: Terminating drbd_a_gitlab_d Jul 7 23:12:04 monty kernel: [2735376.140787] [UFW BLOCK] IN=eth1 OUT= MAC=18:a9:05:41:19:57:18:a9:05:41:19:51:08:00 SRC=192.168.0.101 DST=192.168.0.102 LEN=40 TOS=0x00 PREC=0x00 TTL=64 ID=11087 DF PROTO=TCP SPT=7789 DPT=51070 WINDOW=0 RES=0x00 RST URGP=0 Jul 7 23:12:04 monty kernel: [2735376.373246] block drbd0: drbd_rs_complete_io() called, but extent not found Jul 7 23:12:04 monty kernel: [2735376.385958] block drbd0: drbd_send_block() failed Jul 7 23:12:04 monty kernel: [2735376.508758] d-con gitlab_data: Connection closed Jul 7 23:12:04 monty kernel: [2735376.508794] d-con gitlab_data: conn( Timeout -> Unconnected ) Jul 7 23:12:04 monty kernel: [2735376.508796] d-con gitlab_data: receiver terminated Jul 7 23:12:04 monty kernel: [2735376.508799] d-con gitlab_data: Restarting receiver thread Jul 7 23:12:04 monty kernel: [2735376.508800] d-con gitlab_data: receiver (re)started Jul 7 23:12:04 monty kernel: [2735376.508817] d-con gitlab_data: conn( Unconnected -> WFConnection )

Last thing that happened before the crash was DRBD getting disconnected and then reconnecting (reformatted from above; UFW filtered out)

23:11:43 [2735355.077061] [] system_call_fastpath+0x1a/0x1f 23:12:04 [2735376.138956] block drbd0: md_sync_timer expired! Worker calls drbd_md_sync(). 23:12:04 [2735376.139077] d-con gitlab_data: asender terminated 23:12:04 [2735376.139087] d-con gitlab_data: Terminating drbd_a_gitlab_d 23:12:04 [2735376.373246] block drbd0: drbd_rs_complete_io() called, but extent not found 23:12:04 [2735376.385958] block drbd0: drbd_send_block() failed 23:12:04 [2735376.508758] d-con gitlab_data: Connection closed 23:12:04 [2735376.508794] d-con gitlab_data: conn( Timeout -> Unconnected ) 23:12:04 [2735376.508796] d-con gitlab_data: receiver terminated 23:12:04 [2735376.508799] d-con gitlab_data: Restarting receiver thread 23:12:04 [2735376.508800] d-con gitlab_data: receiver (re)started 23:12:04 [2735376.508817] d-con gitlab_data: conn( Unconnected -> WFConnection ) 23:12:05 [2735377.007796] d-con gitlab_data: Handshake successful: Agreed network protocol version 101 23:12:05 [2735377.007862] d-con gitlab_data: conn( WFConnection -> WFReportParams ) 23:12:05 [2735377.007895] d-con gitlab_data: Starting asender thread (from drbd_r_gitlab_d [1937]) 23:12:05 [2735377.680880] block drbd0: drbd_sync_handshake: 23:12:05 [2735377.680889] block drbd0: self 291708424FD2A34F:182432E200A841B9:182332E200A841B9:40CCDFEA34730C19 bits:37243 flags:0 23:12:05 [2735377.680894] block drbd0: peer 182432E200A841B8:0000000000000000:40CCDFEA34730C18:40CBDFEA34730C19 bits:16438 flags:0 23:12:05 [2735377.680898] block drbd0: uuid_compare()=1 by rule 70 23:12:05 [2735377.680901] block drbd0: Becoming sync source due to disk states. 23:12:05 [2735377.680914] block drbd0: peer( Unknown -> Secondary ) conn( WFReportParams -> WFBitMapS ) 23:12:05 [2735377.815441] block drbd0: send bitmap stats [Bytes(packets)]: plain 0(0), RLE 348(1), total 348; compression: 100.0% 23:12:05 [2735377.897060] block drbd0: receive bitmap stats [Bytes(packets)]: plain 0(0), RLE 348(1), total 348; compression: 100.0% 23:12:05 [2735377.897068] block drbd0: helper command: /sbin/drbdadm before-resync-source minor-0 23:12:06 [2735378.332122] block drbd0: helper command: /sbin/drbdadm before-resync-source minor-0 exit code 0 (0x0) 23:12:06 [2735378.332152] block drbd0: conn( WFBitMapS -> SyncSource ) 23:12:06 [2735378.332163] block drbd0: Began resync as SyncSource (will sync 233468 KB [58367 bits set]). 23:12:06 [2735378.332200] block drbd0: updated sync UUID 291708424FD2A34F:182532E200A841B9:182432E200A841B9:182332E200A841B9 23:12:49 [2735421.553564] block drbd0: Resync done (total 43 sec; paused 0 sec; 5428 K/sec) 23:12:49 [2735421.553572] block drbd0: updated UUIDs 291708424FD2A34F:0000000000000000:182532E200A841B9:182432E200A841B9 23:12:49 [2735421.553580] block drbd0: conn( SyncSource -> Connected ) pdsk( Inconsistent -> UpToDate ) 23:25:38 imklog 5.8.6, log source = /proc/kmsg started.

2014-07-07T23:14:45.240486+00:00 192.168.0.102 122 <4>Jul 7 23:14:45 monty kernel: [2735537.275978] block drbd0: Remote failed to finish a request within ko-count * timeout 2014-07-07T23:14:45.240495+00:00 192.168.0.102 150 <6>Jul 7 23:14:45 monty kernel: [2735537.275990] block drbd0: peer( Secondary -> Unknown ) conn( Connected -> Timeout ) pdsk( UpToDate -> DUnknown )