mongodb fails to start -- preallocation takes too long

[Giulio Fidente]

sometimes the CI ha job fails due to mongodb_conn_validator timing out, this can be seen for example in the os-collect-config logs at http://logs.openstack.org/24/194624/2/check-tripleo/check-tripleo-ironic-overcloud-f21puppet-ha/fca023b/logs/overcloud-controller-0_logs/os-collect-config.txt.gz#_Jun_23_19_48_29

the typical message logged is:

  Notice: Failed to connect to mongodb within timeout window of 60 seconds; giving up.

[Yanis Guenane (yanis-guenane)]

The issue is not related to the mongodb_conn_validator timeout. But mongodb itself timed out when it tries to start some times[1].

[1] http://logs.openstack.org/24/194624/2/check-tripleo/check-tripleo-ironic-overcloud-f21puppet-ha/fca023b/logs/overcloud-controller-0_logs/mongod.txt.gz

[Giulio Fidente (gfidente)]

hi Yanis, thanks for pointing this out. As discussed on IRC, we might still want to increase the timeout as 60secs is a little short to wait for all mongod(s) to come up, but it is definitely not the fix for this bug. I'll disown the bug and decouple it from the change.

[Jiří Stránský (jistr)]

A bit of logs from the timed-out mongodb:

Thu Jun 25 20:13:35.067 [initandlisten] preallocating a journal file /var/lib/mongodb/journal/prealloc.0
Thu Jun 25 20:13:38.133 [initandlisten] File Preallocator Progress: 157286400/1073741824 14%
Thu Jun 25 20:13:41.252 [initandlisten] File Preallocator Progress: 230686720/1073741824 21%
Thu Jun 25 20:13:44.159 [initandlisten] File Preallocator Progress: 367001600/1073741824 34%
Thu Jun 25 20:13:47.490 [initandlisten] File Preallocator Progress: 450887680/1073741824 41%
Thu Jun 25 20:13:50.291 [initandlisten] File Preallocator Progress: 524288000/1073741824 48%
Thu Jun 25 20:13:53.025 [initandlisten] File Preallocator Progress: 576716800/1073741824 53%
Thu Jun 25 20:13:56.289 [initandlisten] File Preallocator Progress: 734003200/1073741824 68%
Thu Jun 25 20:13:59.069 [initandlisten] File Preallocator Progress: 786432000/1073741824 73%
Thu Jun 25 20:14:02.202 [initandlisten] File Preallocator Progress: 891289600/1073741824 83%
Thu Jun 25 20:14:05.228 [initandlisten] File Preallocator Progress: 975175680/1073741824 90%
Thu Jun 25 20:14:18.921 [initandlisten] preallocating a journal file /var/lib/mongodb/journal/prealloc.1
Thu Jun 25 20:14:21.052 [initandlisten] File Preallocator Progress: 367001600/1073741824 34%
Thu Jun 25 20:14:24.273 [initandlisten] File Preallocator Progress: 461373440/1073741824 42%
Thu Jun 25 20:14:27.759 [initandlisten] File Preallocator Progress: 524288000/1073741824 48%
Thu Jun 25 20:14:30.249 [initandlisten] File Preallocator Progress: 555745280/1073741824 51%
Thu Jun 25 20:14:33.226 [initandlisten] File Preallocator Progress: 849346560/1073741824 79%
Thu Jun 25 20:14:36.004 [initandlisten] File Preallocator Progress: 964689920/1073741824 89%
Thu Jun 25 20:14:37.639 [initandlisten] preallocating a journal file /var/lib/mongodb/journal/prealloc.2
Thu Jun 25 20:14:40.159 [initandlisten] File Preallocator Progress: 335544320/1073741824 31%
Thu Jun 25 20:14:43.217 [initandlisten] File Preallocator Progress: 450887680/1073741824 41%
Thu Jun 25 20:14:46.151 [initandlisten] File Preallocator Progress: 650117120/1073741824 60%
Thu Jun 25 20:14:49.212 [initandlisten] File Preallocator Progress: 765460480/1073741824 71%
Thu Jun 25 20:14:49.432 [signalProcessingThread] got signal 15 (Terminated), will terminate after current cmd ends
Thu Jun 25 20:14:49.432 [signalProcessingThread] now exiting
Thu Jun 25 20:14:49.432 dbexit:
Thu Jun 25 20:14:49.432 [signalProcessingThread] shutdown: going to close listening sockets...
Thu Jun 25 20:14:49.432 [signalProcessingThread] shutdown: going to flush diaglog...
Thu Jun 25 20:14:49.432 [signalProcessingThread] shutdown: going to close sockets...
Thu Jun 25 20:14:49.432 [signalProcessingThread] shutdown: waiting for fs preallocator...
Thu Jun 25 20:14:49.432 [signalProcessingThread] shutdown: lock for final commit...
Thu Jun 25 20:14:49.432 [signalProcessingThread] shutdown: final commit...
Thu Jun 25 20:14:49.432 [signalProcessingThread] shutdown: closing all files...
Thu Jun 25 20:14:49.432 [signalProcessingThread] closeAllFiles() finished
Thu Jun 25 20:14:49.432 [signalProcessingThread] journalCleanup.....

[Jiří Stránský (jistr)]

Maybe if we could tune down the default preallocation of space, it wouldn't be hitting the timeout. At least for CI purposes this is probably worth doing if possible.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/201025

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/201025
Committed: https://git.openstack.org/cgit/openstack/tripleo-heat-templates/commit/?id=e0ed4b315a5e12703a1e1dfc538863425e6ab81e
Submitter: Jenkins
Branch: master

commit e0ed4b315a5e12703a1e1dfc538863425e6ab81e
Author: Yanis Guenane <email address hidden>
Date: Mon Jul 13 09:12:51 2015 +0200

    Allow a user to disable MongoDB journaling

    By default MongoDB enables a journaling system that prevents loss of
    data in case of an unexpected shut-down. When journaling is enabled,
    MongoDB will create the journal files before actually starting the
    daemon[1].

    The journaling feature is useful in production environment, but not
    really on a CI-like system, where we only want to make sure MongoDB is
    setup correctly and running, hence here we allow a user to
    enable/disable MongoDB journaling.

    [1] http://docs.mongodb.org/manual/core/journaling/

    Change-Id: I0e4e65af9f650c10fdf5155ff709b4eb984cf4e1
    Closes-bug: #1468246