Recover Berkeley DB before opening it by default

[moio]

If Berkeley DB files contain stale locks (for example if sm is killed with signal KILL), then the sm process will hang waiting on a futex forever.

Example log from sm:

Thu Jul  2 14:53:24 2015 sm.c:219 got a packet
Thu Jul  2 14:53:24 2015 pkt.c:118 creating new packet
Thu Jul  2 14:53:24 2015 mm.c:477 dispatching in-router chain
Thu Jul  2 14:53:24 2015 mm.c:491 calling module session
Thu Jul  2 14:53:24 2015 sess.c:111 session requested for rhn-dispatcher-sat@suma21pg.vagrant.local/superclient
Thu Jul  2 14:53:24 2015 mm.c:663 dispatching user-load chain
Thu Jul  2 14:53:24 2015 mm.c:676 calling module active
Thu Jul  2 14:53:24 2015 storage.c:224 storage_get: type=active owner=rhn-dispatcher-sat@suma21pg.vagrant.local filter=(null)
Thu Jul  2 14:53:24 2015 storage.c:104 adding type 'active' to driver 'db'

Corresponding strace:

write(3, "Thu Jul  2 14:53:24 2015 sm.c:24"..., 54) = 54
ioctl(6, FIONREAD, [337])               = 0
write(2, "sx (io.c:191) 6 ready for readin"..., 33) = 33
write(2, "\n", 1)                       = 1
write(2, "sx (io.c:197) tag 6 event 2 data"..., 41) = 41
write(2, "\n", 1)                       = 1
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
write(3, "Thu Jul  2 14:53:24 2015 sm.c:54"..., 48) = 48
recvfrom(6, "\0\0\1Mko6\325[\344\336\250\365Y\335U\272lG\303\247.l\275\1774\324\206\233\rp\227"..., 1024, 0, NULL, NULL) = 337
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
write(3, "Thu Jul  2 14:53:24 2015 sm.c:79"..., 48) = 48
write(2, "sx (io.c:216) passed 337 read by"..., 35) = 35
write(2, "\n", 1)                       = 1
write(2, "sx (chain.c:93) calling io read "..., 37) = 37
write(2, "\n", 1)                       = 1
write(2, "sx (sasl_cyrus.c:393) doing sasl"..., 39) = 39
write(2, "\n", 1)                       = 1
write(2, "sx (sasl_cyrus.c:407) 317 bytes "..., 57) = 57
write(2, "\n", 1)                       = 1
write(2, "sx (io.c:240) decoded read data "..., 362) = 362
write(2, "\n", 1)                       = 1
write(2, "sx (io.c:92) completed nad: <rou"..., 345) = 345
write(2, "\n", 1)                       = 1
write(2, "sx (chain.c:119) calling nad rea"..., 39) = 39
write(2, "\n", 1)                       = 1
write(2, "sx (io.c:156) tag 6 event 6 data"..., 41) = 41
write(2, "\n", 1)                       = 1
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
write(3, "Thu Jul  2 14:53:24 2015 sm.c:21"..., 47) = 47
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
write(3, "Thu Jul  2 14:53:24 2015 pkt.c:1"..., 55) = 55
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
write(3, "Thu Jul  2 14:53:24 2015 mm.c:47"..., 62) = 62
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
write(3, "Thu Jul  2 14:53:24 2015 mm.c:49"..., 57) = 57
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
write(3, "Thu Jul  2 14:53:24 2015 sess.c:"..., 112) = 112
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
write(3, "Thu Jul  2 14:53:24 2015 mm.c:66"..., 62) = 62
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
write(3, "Thu Jul  2 14:53:24 2015 mm.c:67"..., 56) = 56
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
write(3, "Thu Jul  2 14:53:24 2015 storage"..., 126) = 126
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
write(3, "Thu Jul  2 14:53:24 2015 storage"..., 75) = 75
stat("/var/lib/jabberd/db/sm.db", {st_mode=S_IFREG|0640, st_size=512000, ...}) = 0
stat("/var/lib/jabberd/db/sm.db", {st_mode=S_IFREG|0640, st_size=512000, ...}) = 0
open("/var/lib/jabberd/db/sm.db", O_RDWR) = 8
fcntl(8, F_SETFD, FD_CLOEXEC)           = 0
read(8, "\1\0\0\0\265\214F\0\0\0\0\0b1\5\0\t\0\0\0\0\20\0\0\0\t\0\0r\0\0\0"..., 512) = 512
close(8)                                = 0
stat("/var/lib/jabberd/db/sm.db", {st_mode=S_IFREG|0640, st_size=512000, ...}) = 0
open("/var/lib/jabberd/db/sm.db", O_RDWR|O_CREAT, 0) = 8
fcntl(8, F_SETFD, FD_CLOEXEC)           = 0
fstat(8, {st_mode=S_IFREG|0640, st_size=512000, ...}) = 0
futex(0x7f27c59f705c, FUTEX_WAIT, 1, NULL

Relevant Stack Overflow question:

http://stackoverflow.com/questions/12400663/berkeley-db-stuck-at-futex-wait-because-of-previous-abnormal-quit-during-c-api

This PR adds an open option that will clear stale locks, if any, before opening the db environment preventing this condition. I could reliably reproduce this as the init script here uses killproc, which will send SIGKILL after SIGTERM and waiting 5 seconds by default.

DB_RECOVER reference:

http://docs.oracle.com/cd/E17076_04/html/api_reference/C/envopen.html#envopen_DB_RECOVER

Comments welcome!

[smokku]

thx

[vinzent]

thank you for this!

[smokku]

BTW, I wouldn't dream that people are still using BDB backend with jabberd2. ;)

[sdebnath]

As much as I agree with you, there are still valid cases for Berkeley DB with jabberd2. Best part about XMPP is that it's not restricted to internet chat realm. Imagine embedded space where jabberd2 is being used to orchestrate a network of robots, or coordinating various machines in a plant, etc.

[smokku]

I would use SQLite for that.
But I see a case with legacy deployment, where it does not make sense to change storage just for the sake of change.

[dmacvicar]

• This is not a typical chat server usecase but Spacewalk uses it as a message bus.
• jabberd with bdb is deployed already in lot of customers. Changing the backend would mean making sure that the replacement is also battle tested. Unfortunately, "pluggable" backends sometimes result in no backend being better than another but they just having different issues.