Bug 10934 - ctdb banned error,while reboot one node
ctdb banned error,while reboot one node
Status: NEW
Product: CTDB 2.5.x or older
Classification: Unclassified
Component: ctdb
2.5.3
x86 Linux
: P5 critical
: ---
Assigned To: Amitay Isaacs
Samba QA Contact
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2014-11-13 05:24 UTC by 郭成峰
Modified: 2016-07-29 16:24 UTC (History)
4 users (show)

See Also:


Attachments
this is the node which banned log when other node reboot,all nodes have same configure. (733.79 KB, text/plain)
2014-11-14 04:51 UTC, 郭成峰
no flags Details
Log of node that get's banned, low loglevel (6.80 KB, text/plain)
2015-03-11 13:15 UTC, Systemen
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description 郭成峰 2014-11-13 05:24:28 UTC
hi!
I built my ctdb&samba&gluster cluster with 4 nodes. next, i do one test.
(1)Mapping a network drive(like mount in linux, sorry i do not know how to describle)
(2)use Sanergy to write this network drive.
(3)when Sanergy write, i restart one node.
Unfortunately, another healthy node became banned. i do not know how to solve it.is there anyone can help me?
my english is poor.thanks very much.


follow is my log(/var/log/log.ctb) in healthy node which is banned.
End of debug locks PID=41866 =====
2014/11/11 08:17:58.577775 [ 6703]: Skip monitoring since databases are frozen
===== Start of debug locks PID=42220 =====
37468 /usr/bin/ctdb_lock_helper locking.tdb.0 168 136558
37468 /usr/bin/ctdb_lock_helper smbXsrv_tcon_global.tdb.0 168 EOF
37468 /usr/bin/ctdb_lock_helper smbXsrv_session_global.tdb.0 168 EOF
37468 /usr/bin/ctdb_lock_helper smbXsrv_version_global.tdb.0 168 EOF
11948 /usr/sbin/smbd locking.tdb.0 136560 136560
37468 /usr/bin/ctdb_lock_helper locking.tdb.0 136559 136561 W
----- Stack trace for PID=11948 -----
#0  0x00007f813a5c0df0 in __poll_nocancel () from /lib64/libc.so.6
#1  0x00007f813be8bdb9 in poll_one_fd () from /lib64/libsmbconf.so.0
#2  0x00007f813be8f3bb in ctdb_packet_fd_read_sync_timeout () from /lib64/libsmbconf.so.0
#3  0x00007f813be905ca in ctdb_read_req () from /lib64/libsmbconf.so.0
#4  0x00007f813be9310f in ctdbd_parse () from /lib64/libsmbconf.so.0
#5  0x00007f813be989ab in db_ctdb_parse_record () from /lib64/libsmbconf.so.0
#6  0x00007f8138794afb in dbwrap_parse_record () from /usr/lib64/samba/libdbwrap.so
#7  0x00007f8138794b2e in dbwrap_fetch () from /usr/lib64/samba/libdbwrap.so
#8  0x00007f813be9a5e1 in dbwrap_watch_record_stored () from /lib64/libsmbconf.so.0
#9  0x00007f81387948e6 in dbwrap_record_delete () from /usr/lib64/samba/libdbwrap.so
#10 0x00007f813d24b113 in share_mode_data_destructor () from /usr/lib64/samba/libsmbd_base.so
#11 0x00007f813aaa8e38 in _talloc_free_internal () from /lib64/libtalloc.so.2
#12 0x00007f813aaa8c33 in _talloc_free_internal () from /lib64/libtalloc.so.2
#13 0x00007f813aaa57db in _talloc_free () from /lib64/libtalloc.so.2
#14 0x00007f813d1cd752 in close_file () from /usr/lib64/samba/libsmbd_base.so
#15 0x00007f813d2028f8 in smbd_smb2_close () from /usr/lib64/samba/libsmbd_base.so
#16 0x00007f813d202f0d in smbd_smb2_request_process_close () from /usr/lib64/samba/libsmbd_base.so
#17 0x00007f813d1fac4d in smbd_smb2_request_dispatch () from /usr/lib64/samba/libsmbd_base.so
#18 0x00007f813d1fb19f in smbd_smb2_request_incoming () from /usr/lib64/samba/libsmbd_base.so
#19 0x00007f813d1f809c in smbd_smb2_request_read_done () from /usr/lib64/samba/libsmbd_base.so
#20 0x00007f813bc54534 in tstream_readv_pdu_queue_done () from /usr/lib64/samba/libsamba-sockets.so
#21 0x00007f813bc54069 in tstream_readv_pdu_readv_done () from /usr/lib64/samba/libsamba-sockets.so
#22 0x00007f813bc52f46 in tstream_readv_done () from /usr/lib64/samba/libsamba-sockets.so
#23 0x00007f813a89a3f4 in tevent_common_loop_immediate () from /lib64/libtevent.so.0
#24 0x00007f813bea471c in run_events_poll () from /lib64/libsmbconf.so.0
#25 0x00007f813bea4a04 in s3_event_loop_once () from /lib64/libsmbconf.so.0
#26 0x00007f813a899bcd in _tevent_loop_once () from /lib64/libtevent.so.0
#27 0x00007f813d1e6bb0 in smbd_process () from /usr/lib64/samba/libsmbd_base.so
#28 0x00007f813dc5c1b4 in smbd_accept_connection ()
#29 0x00007f813bea484c in run_events_poll () from /lib64/libsmbconf.so.0
#30 0x00007f813bea4aa0 in s3_event_loop_once () from /lib64/libsmbconf.so.0
#31 0x00007f813a899bcd in _tevent_loop_once () from /lib64/libtevent.so.0
#32 0x00007f813dc58d01 in main ()
----- Stack trace for PID=37468 -----
#0  0x00007fc028a9a094 in fcntl () from /lib64/libc.so.6
#1  0x000000000040e034 in fcntl_lock (tdb=0x1fc4530, rw=1, off=136559, len=3, waitflag=true) at lib/tdb/common/lock.c:47
#2  0x000000000040e161 in tdb_brlock (tdb=0x1fc4530, rw_type=1, offset=136559, len=3, flags=TDB_LOCK_WAIT) at lib/tdb/common/lock.c:156
#3  0x000000000040ed1b in tdb_chainlock_gradual (tdb=0x1fc4530, ltype=1, flags=TDB_LOCK_WAIT, off=136559, len=3) at lib/tdb/common/lock.c:527
#4  0x000000000040edc0 in tdb_chainlock_gradual (tdb=0x1fc4530, ltype=1, flags=TDB_LOCK_WAIT, off=136556, len=6) at lib/tdb/common/lock.c:541
#5  0x000000000040ed75 in tdb_chainlock_gradual (tdb=0x1fc4530, ltype=1, flags=TDB_LOCK_WAIT, off=136556, len=12) at lib/tdb/common/lock.c:537
#6  0x000000000040edc0 in tdb_chainlock_gradual (tdb=0x1fc4530, ltype=1, flags=TDB_LOCK_WAIT, off=136544, len=24) at lib/tdb/common/lock.c:541
#7  0x000000000040ed75 in tdb_chainlock_gradual (tdb=0x1fc4530, ltype=1, flags=TDB_LOCK_WAIT, off=136544, len=49) at lib/tdb/common/lock.c:537
#8  0x000000000040edc0 in tdb_chainlock_gradual (tdb=0x1fc4530, ltype=1, flags=TDB_LOCK_WAIT, off=136496, len=97) at lib/tdb/common/lock.c:541
#9  0x000000000040ed75 in tdb_chainlock_gradual (tdb=0x1fc4530, ltype=1, flags=TDB_LOCK_WAIT, off=136496, len=195) at lib/tdb/common/lock.c:537
#10 0x000000000040ed75 in tdb_chainlock_gradual (tdb=0x1fc4530, ltype=1, flags=TDB_LOCK_WAIT, off=136496, len=391) at lib/tdb/common/lock.c:537
#11 0x000000000040edc0 in tdb_chainlock_gradual (tdb=0x1fc4530, ltype=1, flags=TDB_LOCK_WAIT, off=136106, len=781) at lib/tdb/common/lock.c:541
#12 0x000000000040ed75 in tdb_chainlock_gradual (tdb=0x1fc4530, ltype=1, flags=TDB_LOCK_WAIT, off=136106, len=1563) at lib/tdb/common/lock.c:537
#13 0x000000000040edc0 in tdb_chainlock_gradual (tdb=0x1fc4530, ltype=1, flags=TDB_LOCK_WAIT, off=134544, len=3125) at lib/tdb/common/lock.c:541
#14 0x000000000040edc0 in tdb_chainlock_gradual (tdb=0x1fc4530, ltype=1, flags=TDB_LOCK_WAIT, off=131419, len=6250) at lib/tdb/common/lock.c:541
#15 0x000000000040edc0 in tdb_chainlock_gradual (tdb=0x1fc4530, ltype=1, flags=TDB_LOCK_WAIT, off=125169, len=12500) at lib/tdb/common/lock.c:541
#16 0x000000000040ed75 in tdb_chainlock_gradual (tdb=0x1fc4530, ltype=1, flags=TDB_LOCK_WAIT, off=125169, len=25000) at lib/tdb/common/lock.c:537
#17 0x000000000040edc0 in tdb_chainlock_gradual (tdb=0x1fc4530, ltype=1, flags=TDB_LOCK_WAIT, off=100169, len=50000) at lib/tdb/common/lock.c:541
#18 0x000000000040ed75 in tdb_chainlock_gradual (tdb=0x1fc4530, ltype=1, flags=TDB_LOCK_WAIT, off=100169, len=100001) at lib/tdb/common/lock.c:537
#19 0x000000000040edc0 in tdb_chainlock_gradual (tdb=0x1fc4530, ltype=1, flags=TDB_LOCK_WAIT, off=168, len=200002) at lib/tdb/common/lock.c:541
#20 0x000000000040ed75 in tdb_chainlock_gradual (tdb=0x1fc4530, ltype=1, flags=TDB_LOCK_WAIT, off=168, len=400004) at lib/tdb/common/lock.c:537
#21 0x000000000040ee68 in tdb_allrecord_lock (tdb=0x1fc4530, ltype=1, flags=TDB_LOCK_WAIT, upgradable=false) at lib/tdb/common/lock.c:570
#22 0x000000000040f117 in tdb_lockall (tdb=0x1fc4530) at lib/tdb/common/lock.c:650
#23 0x0000000000401d14 in lock_db (dbpath=0x7fffb6920db5 "/var/lib/ctdb/locking.tdb.0") at server/ctdb_lock_helper.c:86
#24 0x0000000000401e8a in main (argc=17, argv=0x7fffb6920278) at server/ctdb_lock_helper.c:129

===== End of debug locks PID=42220 =====
2014/11/11 08:18:13.577961 [ 6703]: Skip monitoring since databases are frozen
2014/11/11 08:18:14.009436 [ 6703]: Recovery daemon ping timeout. Count : 0
2014/11/11 08:18:14.010584 [recoverd: 6928]: ctdb_control error: 'ctdb_control timed out'
2014/11/11 08:18:14.010619 [recoverd: 6928]: ctdb_control error: 'ctdb_control timed out'
2014/11/11 08:18:14.010637 [recoverd: 6928]: Async operation failed with ret=-1 res=-1 opcode=33
2014/11/11 08:18:14.010648 [recoverd: 6928]: Failed to freeze node 0 during recovery. Set it as ban culprit for 4 credits
2014/11/11 08:18:14.010661 [recoverd: 6928]: Async wait failed - fail_count=1
2014/11/11 08:18:14.010671 [recoverd: 6928]: server/ctdb_recoverd.c:395 Unable to freeze nodes. Recovery failed.
2014/11/11 08:18:14.010681 [recoverd: 6928]: server/ctdb_recoverd.c:2720 Unable to set recovery mode to active on cluster
2014/11/11 08:18:14.011559 [ 6703]: Banning this node for 30 seconds
Comment 1 Amitay Isaacs 2014-11-13 05:33:07 UTC
Instead of pasting the log in the notes, can you attach complete log file from the banned node?
Comment 2 郭成峰 2014-11-14 04:51:44 UTC
Created attachment 10432 [details]
this is the node which banned log when other node reboot,all nodes have same configure.

my ctdb configure file.

CTDB_RECOVERY_LOCK=/mnt/lock/lockfile
CTDB_PUBLIC_INTERFACE=bond1
CTDB_PUBLIC_ADDRESSES=/etc/ctdb/public_addresses
CTDB_MANAGES_SAMBA=yes
#CTDB_MANAGES_WINBIND=no
CTDB_MANAGES_NFS=yes
CTDB_NODES=/etc/ctdb/nodes
CTDB_DEBUGLEVEL=ERR
CTDB_LOGFILE=/var/log/log.ctdb
CTDB_AUTO_STARTSTOP=yes
#CTDB_RPCINFO_LOCALHOST="127.0.0.1"
CTDB_SAMBA_SKIP_SHARE_CHECK=yes
CTDB_SET_RecoveryBanPeriod=30
CTDB_SET_RecoverTimeout=60
CTDB_NFS_SKIP_SHARE_CHECK=yes
CTDB_INIT_STYLE=redhat
CTDB_SET_EventScriptTimeout=60
Comment 3 郭成峰 2014-11-14 04:56:48 UTC
(In reply to Amitay Isaacs from comment #1)
hi!
  thanks you pay attention to this problem. i just add my configure file and the ctdb log from banned node.
Comment 4 Amitay Isaacs 2014-11-21 10:15:53 UTC
For recovery lock to work, you need posix locking support on the cluster file system.  Gluster does not enable posix locking support by default, therefore CTDB recovery locking will not work.

To enable posix locking, please follow the instructions here:

http://www.gluster.org/community/documentation/index.php/Translators/features/locks

Other option is to disable recovery lock by commenting the configuration variable CTDB_RECOVERY_LOCK.
Comment 5 郭成峰 2014-11-25 02:04:30 UTC
(In reply to Amitay Isaacs from comment #4)
thanks you. as far as i know, glusterfs3.5.1 support this translator by default.by the way, i want to know if i disable recover lock ,what risk may have in my ctdb cluster.
Comment 6 郭成峰 2014-11-25 02:18:57 UTC
(In reply to Amitay Isaacs from comment #4)
thank you very much. there is another problem.
when a node down, i know ctdb will freeze tdb databases,such as /var/lib/ctdb/lock.tdb*. 

unfortunately, ctdb_lock_helper will stuck in "fcntl_lock (tdb=0x1fc4530, rw=1, off=136559, len=3, waitflag=true) at lib/tdb/common/lock.c:47"
i encountered a few times. 
ctdb_lock_helper locking.tdb.* and  smbXsrv_session_global.tdb.* may stuck. and this may cause node banned?
Comment 7 郭成峰 2014-11-25 03:12:45 UTC
(In reply to Amitay Isaacs from comment #4)
thank you very much. 
(1) as far as i know, glusterfs3.5.1 support this by default.
by the way, if i disable recovery lock, what risk may have,ctdb will select a right recmaster?
(2)and i also Analysis this log,when samba are using ctdb datebase, samba also fcntl lock tdb*,this may can ctdb_lock_helper stuck in fcntl lock ,such as   locking.tdb,  smbXsrv_session_global.tdb. and after while, ctdb will banned ?
if i can only lock persistent tdb?
(3)/etc/ctdb/events.d/00.ctdb monitor may timeout(CTDB_SET_EventScriptTimeout=60)
i check this script, and do not know why,i do not set memeoy check option.
Comment 8 Systemen 2015-03-11 13:12:24 UTC
Hi,

We are experiencing similar issues.
Some info on our setup:
- 2 servers, running debian 7.8
- ctdb 2.5.3
- samba 4.1.17
- GPFS 3.5.0 u18
- pingpong test is ok on the GPFS

Issue reproduction:
1. put some load on the server being the ctdb recovery master
2. ctdb stop on the other node
3. ctdb start on the other node
4. the other node's ctdb wants to become recovery master but something goes wrong and the previous master gets banned, resulting in an unusable cluster

We also tested with 3 ctdb nodes, we noticed the same behavior.
Comment 9 Systemen 2015-03-11 13:15:24 UTC
Created attachment 10853 [details]
Log of node that get's banned, low loglevel
Comment 10 Michael Adam 2015-03-17 15:51:34 UTC
(In reply to Systemen from comment #9)

Not sure if it is correct to re-use this bug, since at least
the file system is different in the setup. Anyhow:

I see in the log that the recovery lock file is

   /users/local/ctdb.lock

Is this file on shared storage?

Also, I'd need to see more of the config (ctdb configs, ....)
and more high level logs of ctdb would help.
Also logs of corresponding time on the other node.

Thanks
Comment 11 Michael Adam 2015-03-17 15:57:08 UTC
(In reply to 郭成峰 from comment #7)

> (1) as far as i know, glusterfs3.5.1 support this by default.

correct.
Depending on the version of your os/brick filesystem/userland,
you may have to put some mount options like acl,user_xattr in
in some places..

> by the way, if i disable recovery lock, what risk may have,

There is no split-brain protection. I.e. if ctdb nodes can't
talk to each other over the network (e.g. cable unplugged), then
there will be a split of the cluster and in the worst case
data corruption can occur because samba's SMB locking etc does
not work correctly any more. This protection is the only reason 
for the recovery lock.