Bug 801338

Summary: NFS: Log enhancements
Product: [Community] GlusterFS Reporter: Sachidananda Urs <sac>
Component: nfsAssignee: Vivek Agarwal <vagarwal>
Status: CLOSED CURRENTRELEASE QA Contact:
Severity: unspecified Docs Contact:
Priority: urgent    
Version: pre-releaseCC: gluster-bugs, sankarshan, vbellur
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: glusterfs-3.4.0 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2013-07-24 13:46:04 EDT Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---
Bug Depends On:    
Bug Blocks: 817967    

Description Sachidananda Urs 2012-03-08 05:38:09 EST
[2012-03-08 05:30:30.768982] W [rpcsvc.c:175:rpcsvc_program_actor] 0-rpc-service: RPC program not available (req 100227 3)
[2012-03-08 05:30:30.769077] W [rpcsvc.c:1111:rpcsvc_error_reply] (-->/opt/glusterfs/3.3.0qa26/lib/libgfrpc.so.0(rpc_transport_notify+0x28) [0x7f8965584d88] (-->/opt/glusterfs/3.3.0qa26/lib/libgfrpc.so.0(rpcsvc_notify+0x93) [0x7f8965584323] (-->/opt/glusterfs/3.3.0qa26/lib/libgfrpc.so.0(rpcsvc_handle_rpc_call+0x112) [0x7f8965584032]))) 0-: sending a RPC error reply


The above logs should go to log-level DEBUG
Comment 1 Krishna Srinivas 2012-03-08 06:41:18 EST
These logs are not NFS specific and at RPC layer. Everytime an NFS client connects an RPC request of program 100227 (ACL related) is sent and hence this log. Better not to log it in WARNING so as not to confuse the users seeing the log file. Will send a patch.
Comment 2 Vijay Bellur 2012-03-09 00:14:34 EST
It would be better to filter out the log for the specific program value rather than not logging at all.
Comment 3 Sachidananda Urs 2012-03-14 01:45:43 EDT
I see the below logs in brick log but no clue in NFS logs. Need enhancements in NFS logs to capture these issues:

[2012-03-13 16:36:08.070064] I [server3_1-fops.c:1442:server_stat_cbk] 0-nfs-test-1-server: 129917235: STAT <gfid:daf46583-0db0-4328-b053-7993b13cd409> (daf46583-0db0-4
328-b053-7993b13cd409) ==> -1 (No such file or directory)
[2012-03-13 16:36:08.071559] I [server3_1-fops.c:720:server_getxattr_cbk] 0-nfs-test-1-server: 129917237: GETXATTR <gfid:daf46583-0db0-4328-b053-7993b13cd409> (trusted.
glusterfs.dht.linkto) ==> -1 (No such file or directory)
[2012-03-13 16:36:08.072283] W [server-resolve.c:516:server_resolve] 0-nfs-test-1-server: no resolution type for (null) (LOOKUP)
[2012-03-13 16:36:08.072361] I [server3_1-fops.c:142:server_lookup_cbk] 0-nfs-test-1-server: 129917242: LOOKUP (null) (--) ==> -1 (Invalid argument)
[2012-03-13 16:36:08.486949] W [server-resolve.c:516:server_resolve] 0-nfs-test-1-server: no resolution type for (null) (LOOKUP)
[2012-03-13 16:36:08.487009] I [server3_1-fops.c:142:server_lookup_cbk] 0-nfs-test-1-server: 129918977: LOOKUP (null) (--) ==> -1 (Invalid argument)
[2012-03-13 16:36:08.594933] W [server-resolve.c:516:server_resolve] 0-nfs-test-1-server: no resolution type for (null) (LOOKUP)
[2012-03-13 16:36:08.594997] I [server3_1-fops.c:142:server_lookup_cbk] 0-nfs-test-1-server: 129919519: LOOKUP (null) (--) ==> -1 (Invalid argument)
[2012-03-13 16:36:08.605519] I [server3_1-fops.c:1442:server_stat_cbk] 0-nfs-test-1-server: 129919589: STAT (null) (--) ==> -1 (No such file or directory)
[2012-03-13 16:36:08.607957] I [server3_1-fops.c:720:server_getxattr_cbk] 0-nfs-test-1-server: 129919597: GETXATTR (null) (trusted.glusterfs.dht.linkto) ==> -1 (No such
 file or directory)
[2012-03-13 16:36:08.608683] W [server-resolve.c:516:server_resolve] 0-nfs-test-1-server: no resolution type for (null) (LOOKUP)
[2012-03-13 16:36:08.608723] I [server3_1-fops.c:142:server_lookup_cbk] 0-nfs-test-1-server: 129919602: LOOKUP (null) (--) ==> -1 (Invalid argument)
[2012-03-13 16:36:08.920307] E [posix.c:204:posix_stat] 0-nfs-test-1-posix: lstat on /store/2/.glusterfs/8a/47/8a4783cd-f843-4e72-aaab-ed52d305bef5 failed: No such file
 or directory
[2012-03-13 16:36:08.920408] I [server3_1-fops.c:1442:server_stat_cbk] 0-nfs-test-1-server: 129921096: STAT <gfid:8a4783cd-f843-4e72-aaab-ed52d305bef5> (8a4783cd-f843-4
e72-aaab-ed52d305bef5) ==> -1 (No such file or directory)
[2012-03-13 16:36:08.921859] I [server3_1-fops.c:720:server_getxattr_cbk] 0-nfs-test-1-server: 129921105: GETXATTR <gfid:8a4783cd-f843-4e72-aaab-ed52d305bef5> (trusted.glusterfs.dht.linkto) ==> -1 (No such file or directory)
[2012-03-13 16:36:09.086745] W [server-resolve.c:516:server_resolve] 0-nfs-test-1-server: no resolution type for (null) (LOOKUP)
[2012-03-13 16:36:09.086807] I [server3_1-fops.c:142:server_lookup_cbk] 0-nfs-test-1-server: 129922029: LOOKUP (null) (--) ==> -1 (Invalid argument)
[2012-03-13 16:36:09.092820] I [server3_1-fops.c:1442:server_stat_cbk] 0-nfs-test-1-server: 129922072: STAT (null) (--) ==> -1 (No such file or directory)
[2012-03-13 16:36:09.093803] I [server3_1-fops.c:720:server_getxattr_cbk] 0-nfs-test-1-server: 129922077: GETXATTR (null) (trusted.glusterfs.dht.linkto) ==> -1 (No such file or directory)
[2012-03-13 16:36:09.208332] W [server-resolve.c:516:server_resolve] 0-nfs-test-1-server: no resolution type for (null) (LOOKUP)
[2012-03-13 16:36:09.208378] I [server3_1-fops.c:142:server_lookup_cbk] 0-nfs-test-1-server: 129922475: LOOKUP (null) (--) ==> -1 (Invalid argument)
[2012-03-13 16:36:09.521602] W [server-resolve.c:516:server_resolve] 0-nfs-test-1-server: no resolution type for (null) (LOOKUP)
[2012-03-13 16:36:09.521666] I [server3_1-fops.c:142:server_lookup_cbk] 0-nfs-test-1-server: 129923960: LOOKUP (null) (--) ==> -1 (Invalid argument)
Comment 4 Anand Avati 2012-03-14 09:01:35 EDT
CHANGE: http://review.gluster.com/2901 (rpc: log in DEBUG when nfs clients try to see if ACL requests are accepted by nfs server) merged in master by Vijay Bellur (vijay@gluster.com)