Bug 1410015

Summary: [SAMBA-SSL] Huge warning messages related to /usr/lib64/glusterfs/3.8.4/xlator/features/snapview-client.so adding up to the client log on a SSL enabled cluster
Product: [Red Hat Storage] Red Hat Gluster Storage Reporter: Vivek Das <vdas>
Component: sambaAssignee: Michael Adam <madam>
Status: CLOSED DEFERRED QA Contact: Vivek Das <vdas>
Severity: medium Docs Contact:
Priority: unspecified    
Version: rhgs-3.2CC: gdeschner, rcyriac, rhs-smb, sanandpa, vdas
Target Milestone: ---Keywords: ZStream
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2019-12-12 21:55:54 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Vivek Das 2017-01-04 08:33:29 UTC 
Description of problem:
Huge number of warning messgaes like [2017-01-04 04:27:14.922410] W [dict.c:601:dict_unref] (-->/usr/lib64/glusterfs/3.8.4/xlator/protocol/client.so(+0x7c10) [0x7f76b0ef2c10] -->/usr/lib64/glusterfs/3.8.4/xlator/features/snapview-client.so(+0xc829) [0x7f76a35c7829] -->/lib64/libglusterfs.so.0(dict_unref+0xd9) [0x7f76b7fbd0f9] ) 0-dict: dict is NULL [Invalid argument]
is seen on client logs of a ssl enabled cluster over a simple IO operation.

Version-Release number of selected component (if applicable):
samba-client-4.4.6-4.el7rhgs.x86_64
glusterfs-client-xlators-3.8.4-10.el7rhgs.x86_64

How reproducible:
1/1

Steps to Reproduce:
1.4 Node SSL enabled gluster cluster with samba ctdb setup
2.Do a cifs mount
3.Run a python script that creates a simple deep or nested directory with around 50 zero kb files in each directory.

Actual results:
Client logs are filled with Warning messages

Expected results:
No such warning messgaes should be there over a clean run

Additional info:
pstack

Thread 14 (Thread 0x7f76b7135700 (LWP 8280)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x00007f76b7ffd108 in syncenv_task () from /lib64/libglusterfs.so.0
#2  0x00007f76b7ffdf50 in syncenv_processor () from /lib64/libglusterfs.so.0
#3  0x00007f76d36e3dc5 in start_thread (arg=0x7f76b7135700) at pthread_create.c:308
#4  0x00007f76cf70673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 13 (Thread 0x7f76b6934700 (LWP 8281)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x00007f76b7ffd108 in syncenv_task () from /lib64/libglusterfs.so.0
#2  0x00007f76b7ffdf50 in syncenv_processor () from /lib64/libglusterfs.so.0
#3  0x00007f76d36e3dc5 in start_thread (arg=0x7f76b6934700) at pthread_create.c:308
#4  0x00007f76cf70673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 12 (Thread 0x7f76b491b700 (LWP 8282)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x00007f76b7ffd108 in syncenv_task () from /lib64/libglusterfs.so.0
#2  0x00007f76b7ffdf50 in syncenv_processor () from /lib64/libglusterfs.so.0
#3  0x00007f76d36e3dc5 in start_thread (arg=0x7f76b491b700) at pthread_create.c:308
#4  0x00007f76cf70673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 11 (Thread 0x7f76b411a700 (LWP 8283)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x00007f76b7ffd108 in syncenv_task () from /lib64/libglusterfs.so.0
#2  0x00007f76b7ffdf50 in syncenv_processor () from /lib64/libglusterfs.so.0
#3  0x00007f76d36e3dc5 in start_thread (arg=0x7f76b411a700) at pthread_create.c:308
#4  0x00007f76cf70673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 10 (Thread 0x7f76b2d61700 (LWP 8284)):
#0  0x00007f76d36eabdd in nanosleep () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007f76b7fd1d06 in gf_timer_proc () from /lib64/libglusterfs.so.0
#2  0x00007f76d36e3dc5 in start_thread (arg=0x7f76b2d61700) at pthread_create.c:308
#3  0x00007f76cf70673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 9 (Thread 0x7f76b235d700 (LWP 8285)):
#0  0x00007f76d36e4ef7 in pthread_join (threadid=140147764348672, thread_return=0x0) at pthread_join.c:92
#1  0x00007f76b801ead8 in event_dispatch_epoll () from /lib64/libglusterfs.so.0
#2  0x00007f76b86ccfd4 in glfs_poller () from /lib64/libgfapi.so.0
#3  0x00007f76d36e3dc5 in start_thread (arg=0x7f76b235d700) at pthread_create.c:308
#4  0x00007f76cf70673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 8 (Thread 0x7f76b1b5c700 (LWP 8286)):
#0  0x00007f76cf706d13 in epoll_wait () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007f76b801e530 in event_dispatch_epoll_worker () from /lib64/libglusterfs.so.0
#2  0x00007f76d36e3dc5 in start_thread (arg=0x7f76b1b5c700) at pthread_create.c:308
#3  0x00007f76cf70673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 7 (Thread 0x7f76a2881700 (LWP 8291)):
#0  0x00007f76cf706d13 in epoll_wait () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007f76b801e530 in event_dispatch_epoll_worker () from /lib64/libglusterfs.so.0
#2  0x00007f76d36e3dc5 in start_thread (arg=0x7f76a2881700) at pthread_create.c:308
#3  0x00007f76cf70673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 6 (Thread 0x7f76b0168700 (LWP 8292)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x00007f76a37d290c in iot_worker () from /usr/lib64/glusterfs/3.8.4/xlator/performance/io-threads.so
#2  0x00007f76d36e3dc5 in start_thread (arg=0x7f76b0168700) at pthread_create.c:308
#3  0x00007f76cf70673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 5 (Thread 0x7f7693fff700 (LWP 8296)):
#0  0x00007f76cf6fbdfd in poll () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007f76b114cd81 in socket_poller () from /usr/lib64/glusterfs/3.8.4/rpc-transport/socket.so
#2  0x00007f76d36e3dc5 in start_thread (arg=0x7f7693fff700) at pthread_create.c:308
#3  0x00007f76cf70673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 4 (Thread 0x7f76937fe700 (LWP 8298)):
#0  0x00007f76cf6fbdfd in poll () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007f76b114cd81 in socket_poller () from /usr/lib64/glusterfs/3.8.4/rpc-transport/socket.so
#2  0x00007f76d36e3dc5 in start_thread (arg=0x7f76937fe700) at pthread_create.c:308
#3  0x00007f76cf70673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 3 (Thread 0x7f7692ffd700 (LWP 8300)):
#0  0x00007f76cf6fbdfd in poll () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007f76b114cd81 in socket_poller () from /usr/lib64/glusterfs/3.8.4/rpc-transport/socket.so
#2  0x00007f76d36e3dc5 in start_thread (arg=0x7f7692ffd700) at pthread_create.c:308
#3  0x00007f76cf70673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 2 (Thread 0x7f76927fc700 (LWP 8303)):
#0  0x00007f76cf6fbdfd in poll () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007f76b114cd81 in socket_poller () from /usr/lib64/glusterfs/3.8.4/rpc-transport/socket.so
#2  0x00007f76d36e3dc5 in start_thread (arg=0x7f76927fc700) at pthread_create.c:308
#3  0x00007f76cf70673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 1 (Thread 0x7f76d3aa38c0 (LWP 8279)):
#0  0x00007f76cf6fbdfd in poll () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007f76d0fad5f8 in poll (__timeout=<optimized out>, __nfds=<optimized out>, __fds=<optimized out>) at /usr/include/bits/poll2.h:46
#2  s3_event_loop_once (ev=0x7f76d3e33da0, location=<optimized out>) at ../source3/lib/events.c:314
#3  0x00007f76cf9d440d in _tevent_loop_once (ev=ev@entry=0x7f76d3e33da0, location=location@entry=0x7f76d3187ce0 "../source3/smbd/process.c:4117") at ../tevent.c:533
#4  0x00007f76cf9d45ab in tevent_common_loop_wait (ev=0x7f76d3e33da0, location=0x7f76d3187ce0 "../source3/smbd/process.c:4117") at ../tevent.c:637
#5  0x00007f76d303d7b1 in smbd_process (ev_ctx=ev_ctx@entry=0x7f76d3e33da0, msg_ctx=msg_ctx@entry=0x7f76d3e33e90, sock_fd=sock_fd@entry=39, interactive=interactive@entry=false) at ../source3/smbd/process.c:4117
#6  0x00007f76d3b26304 in smbd_accept_connection (ev=0x7f76d3e33da0, fde=<optimized out>, flags=<optimized out>, private_data=<optimized out>) at ../source3/smbd/server.c:762
#7  0x00007f76d0fad3dc in run_events_poll (ev=0x7f76d3e33da0, pollrtn=<optimized out>, pfds=0x7f76d3e51810, num_pfds=7) at ../source3/lib/events.c:257
#8  0x00007f76d0fad630 in s3_event_loop_once (ev=0x7f76d3e33da0, location=<optimized out>) at ../source3/lib/events.c:326
#9  0x00007f76cf9d440d in _tevent_loop_once (ev=ev@entry=0x7f76d3e33da0, location=location@entry=0x7f76d3b29776 "../source3/smbd/server.c:1127") at ../tevent.c:533
#10 0x00007f76cf9d45ab in tevent_common_loop_wait (ev=0x7f76d3e33da0, location=0x7f76d3b29776 "../source3/smbd/server.c:1127") at ../tevent.c:637
#11 0x00007f76d3b21ad4 in smbd_parent_loop (parent=<optimized out>, ev_ctx=0x7f76d3e33da0) at ../source3/smbd/server.c:1127
#12 main (argc=<optimized out>, argv=<optimized out>) at ../source3/smbd/server.c:1780



pstack 2


Thread 9 (Thread 0x7f76b7135700 (LWP 3926)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x00007f76b7ffd108 in syncenv_task () from /lib64/libglusterfs.so.0
#2  0x00007f76b7ffdf50 in syncenv_processor () from /lib64/libglusterfs.so.0
#3  0x00007f76d36e3dc5 in start_thread (arg=0x7f76b7135700) at pthread_create.c:308
#4  0x00007f76cf70673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 8 (Thread 0x7f76b6934700 (LWP 3927)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x00007f76b7ffd108 in syncenv_task () from /lib64/libglusterfs.so.0
#2  0x00007f76b7ffdf50 in syncenv_processor () from /lib64/libglusterfs.so.0
#3  0x00007f76d36e3dc5 in start_thread (arg=0x7f76b6934700) at pthread_create.c:308
#4  0x00007f76cf70673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 7 (Thread 0x7f76b491b700 (LWP 3928)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x00007f76b7ffd108 in syncenv_task () from /lib64/libglusterfs.so.0
#2  0x00007f76b7ffdf50 in syncenv_processor () from /lib64/libglusterfs.so.0
#3  0x00007f76d36e3dc5 in start_thread (arg=0x7f76b491b700) at pthread_create.c:308
#4  0x00007f76cf70673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 6 (Thread 0x7f76b411a700 (LWP 3929)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x00007f76b7ffd108 in syncenv_task () from /lib64/libglusterfs.so.0
#2  0x00007f76b7ffdf50 in syncenv_processor () from /lib64/libglusterfs.so.0
#3  0x00007f76d36e3dc5 in start_thread (arg=0x7f76b411a700) at pthread_create.c:308
#4  0x00007f76cf70673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 5 (Thread 0x7f76b2d61700 (LWP 3930)):
#0  0x00007f76d36eabdd in nanosleep () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007f76b7fd1d06 in gf_timer_proc () from /lib64/libglusterfs.so.0
#2  0x00007f76d36e3dc5 in start_thread (arg=0x7f76b2d61700) at pthread_create.c:308
#3  0x00007f76cf70673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 4 (Thread 0x7f76b235d700 (LWP 3931)):
#0  0x00007f76d36e4ef7 in pthread_join (threadid=140147764348672, thread_return=0x0) at pthread_join.c:92
#1  0x00007f76b801ead8 in event_dispatch_epoll () from /lib64/libglusterfs.so.0
#2  0x00007f76b86ccfd4 in glfs_poller () from /lib64/libgfapi.so.0
#3  0x00007f76d36e3dc5 in start_thread (arg=0x7f76b235d700) at pthread_create.c:308
#4  0x00007f76cf70673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 3 (Thread 0x7f76b1b5c700 (LWP 3932)):
#0  0x00007f76cf706d13 in epoll_wait () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007f76b801e530 in event_dispatch_epoll_worker () from /lib64/libglusterfs.so.0
#2  0x00007f76d36e3dc5 in start_thread (arg=0x7f76b1b5c700) at pthread_create.c:308
#3  0x00007f76cf70673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 2 (Thread 0x7f76a2881700 (LWP 3937)):
#0  0x00007f76cf706d13 in epoll_wait () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007f76b801e530 in event_dispatch_epoll_worker () from /lib64/libglusterfs.so.0
#2  0x00007f76d36e3dc5 in start_thread (arg=0x7f76a2881700) at pthread_create.c:308
#3  0x00007f76cf70673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 1 (Thread 0x7f76d3aa38c0 (LWP 3924)):
#0  __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
#1  0x00007f76d36e5d02 in _L_lock_791 () from /lib64/libpthread.so.0
#2  0x00007f76d36e5c08 in __GI___pthread_mutex_lock (mutex=0x7f76a4059650) at pthread_mutex_lock.c:64
#3  0x00007f76b11475d1 in socket_poller_mayday () from /usr/lib64/glusterfs/3.8.4/rpc-transport/socket.so
#4  0x00007f76b80329c8 in _gf_ref_put () from /lib64/libglusterfs.so.0
#5  0x00007f76b1147f35 in socket_disconnect () from /usr/lib64/glusterfs/3.8.4/rpc-transport/socket.so

#6  0x00007f76b84ba16e in rpc_clnt_disable () from /lib64/libgfrpc.so.0
#7  0x00007f76b0efbf1e in notify () from /usr/lib64/glusterfs/3.8.4/xlator/protocol/client.so
#8  0x00007f76b7fc2416 in xlator_notify () from /lib64/libglusterfs.so.0
#9  0x00007f76b805bec7 in default_notify () from /lib64/libglusterfs.so.0
#10 0x00007f76a35ca858 in notify () from /usr/lib64/glusterfs/3.8.4/xlator/features/snapview-client.so

#11 0x00007f76b7fc2416 in xlator_notify () from /lib64/libglusterfs.so.0
#12 0x00007f76b805bec7 in default_notify () from /lib64/libglusterfs.so.0
#13 0x00007f76a33b025a in notify () from /usr/lib64/glusterfs/3.8.4/xlator/debug/io-stats.so
#14 0x00007f76b7fc2416 in xlator_notify () from /lib64/libglusterfs.so.0
#15 0x00007f76b805bec7 in default_notify () from /lib64/libglusterfs.so.0

#16 0x00007f76b7fc2416 in xlator_notify () from /lib64/libglusterfs.so.0
#17 0x00007f76b86ce8dd in glfs_fini () from /lib64/libgfapi.so.0
#18 0x00007f76b88f11a6 in glfs_clear_preopened (fs=0x7f76d3e6a6d0) at ../source3/modules/vfs_glusterfs.c:153
#19 vfs_gluster_disconnect (handle=<optimized out>) at ../source3/modules/vfs_glusterfs.c:374
#20 0x00007f76d3040271 in close_cnum (conn=0x7f76d3e58490, vuid=58399) at ../source3/smbd/service.c:1154

#21 0x00007f76d306e894 in smbXsrv_tcon_disconnect (tcon=tcon@entry=0x7f76d3e60d10, vuid=58399) at ../source3/smbd/smbXsrv_tcon.c:983
#22 0x00007f76d2ff234c in reply_tdis (req=req@entry=0x7f76d3e58e30) at ../source3/smbd/reply.c:5682
#23 0x00007f76d3038fd0 in switch_message (type=<optimized out>, req=req@entry=0x7f76d3e58e30) at ../source3/smbd/process.c:1726
#24 0x00007f76d303ad70 in construct_reply (deferred_pcd=0x0, encrypted=false, seqnum=0, unread_bytes=0, size=39, inbuf=0x0, xconn=0x7f76d3e3e980) at ../source3/smbd/process.c:1762
#25 process_smb (xconn=xconn@entry=0x7f76d3e525b0, inbuf=<optimized out>, nread=39, unread_bytes=0, seqnum=0, encrypted=<optimized out>, deferred_pcd=deferred_pcd@entry=0x0) at ../source3/smbd/process.c:2008

#26 0x00007f76d303c461 in smbd_server_connection_read_handler (xconn=0x7f76d3e525b0, fd=39) at ../source3/smbd/process.c:2607
#27 0x00007f76d0fad3dc in run_events_poll (ev=0x7f76d3e33da0, pollrtn=<optimized out>, pfds=0x7f76d3e51810, num_pfds=5) at ../source3/lib/events.c:257
#28 0x00007f76d0fad630 in s3_event_loop_once (ev=0x7f76d3e33da0, location=<optimized out>) at ../source3/lib/events.c:326
#29 0x00007f76cf9d440d in _tevent_loop_once (ev=ev@entry=0x7f76d3e33da0, location=location@entry=0x7f76d3187ce0 "../source3/smbd/process.c:4117") at ../tevent.c:533
#30 0x00007f76cf9d45ab in tevent_common_loop_wait (ev=0x7f76d3e33da0, location=0x7f76d3187ce0 "../source3/smbd/process.c:4117") at ../tevent.c:637

#31 0x00007f76d303d7b1 in smbd_process (ev_ctx=ev_ctx@entry=0x7f76d3e33da0, msg_ctx=msg_ctx@entry=0x7f76d3e33e90, sock_fd=sock_fd@entry=39, interactive=interactive@entry=false) at ../source3/smbd/process.c:4117
#32 0x00007f76d3b26304 in smbd_accept_connection (ev=0x7f76d3e33da0, fde=<optimized out>, flags=<optimized out>, private_data=<optimized out>) at ../source3/smbd/server.c:762
#33 0x00007f76d0fad3dc in run_events_poll (ev=0x7f76d3e33da0, pollrtn=<optimized out>, pfds=0x7f76d3e51810, num_pfds=7) at ../source3/lib/events.c:257
#34 0x00007f76d0fad630 in s3_event_loop_once (ev=0x7f76d3e33da0, location=<optimized out>) at ../source3/lib/events.c:326
#35 0x00007f76cf9d440d in _tevent_loop_once (ev=ev@entry=0x7f76d3e33da0, location=location@entry=0x7f76d3b29776 "../source3/smbd/server.c:1127") at ../tevent.c:533
#36 0x00007f76cf9d45ab in tevent_common_loop_wait (ev=0x7f76d3e33da0, location=0x7f76d3b29776 "../source3/smbd/server.c:1127") at ../tevent.c:637
#37 0x00007f76d3b21ad4 in smbd_parent_loop (parent=<optimized out>, ev_ctx=0x7f76d3e33da0) at ../source3/smbd/server.c:1127
#38 main (argc=<optimized out>, argv=<optimized out>) at ../source3/smbd/server.c:1780
Comment 2 Vivek Das 2017-01-04 08:41:06 UTC 
Sosreports & samba logs : http://rhsqe-repo.lab.eng.blr.redhat.com/sosreports/1410015
Comment 7 Yaniv Kaul 2019-12-12 21:55:54 UTC 
No one touched this for several years and QE did not reproduce. Closing for the time being.
Please reopen if reproduced.