Bug 801338

Summary:	NFS: Log enhancements
Product:	[Community] GlusterFS	Reporter:	Sachidananda Urs <sac>
Component:	nfs	Assignee:	Vivek Agarwal <vagarwal>
Status:	CLOSED CURRENTRELEASE	QA Contact:
Severity:	unspecified	Docs Contact:
Priority:	urgent
Version:	pre-release	CC:	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 17:46:04 UTC	Type:	---
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:
Bug Depends On:
Bug Blocks:	817967

Description Sachidananda Urs 2012-03-08 10:38:09 UTC

[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 11:41:18 UTC

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 05:14:34 UTC

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 05:45:43 UTC

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 13:01:35 UTC

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)