Bugzilla (bugzilla.redhat.com) will be under maintenance for infrastructure upgrades and will not be unavailable on July 31st between 12:30 AM - 05:30 AM UTC. We appreciate your understanding and patience. You can follow status.redhat.com for details.
Bug 1410015 - [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
Summary: [SAMBA-SSL] Huge warning messages related to /usr/lib64/glusterfs/3.8.4/xlat...
Keywords:
Status: CLOSED DEFERRED
Alias: None
Product: Red Hat Gluster Storage
Classification: Red Hat
Component: samba
Version: rhgs-3.2
Hardware: Unspecified
OS: Unspecified
unspecified
medium
Target Milestone: ---
: ---
Assignee: Michael Adam
QA Contact: Vivek Das
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-01-04 08:33 UTC by Vivek Das
Modified: 2020-04-06 11:45 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-12-12 21:55:54 UTC
Target Upstream Version:


Attachments (Terms of Use)

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.


Note You need to log in before you can comment on or make changes to this bug.