Bug 763006 (GLUSTER-1274)

Summary: nfs fails to start
Product: [Community] GlusterFS Reporter: Lakshmipathi G <lakshmipathi>
Component: nfsAssignee: Shehjar Tikoo <shehjart>
Status: CLOSED CURRENTRELEASE QA Contact:
Severity: high Docs Contact:
Priority: low    
Version: 3.1-alphaCC: gluster-bugs
Target Milestone: ---   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: Type: ---
Regression: RTP Mount Type: nfs
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Lakshmipathi G 2010-08-03 14:05:34 UTC
# showmount -e localhost
showmount: RPC: Program not registered

#cat /root/laks/gnfs1.log
[2010-08-03 09:57:58.226676] W [rpc-transport.c:878:rpc_transport_load] rpc-transport: missing 'option transport-type'. defaulting to "socket"
[2010-08-03 09:57:58.311055] W [graph.c:120:_log_if_option_is_invalid] nfsxlator: option 'transport-type' is not recognized
[2010-08-03 09:57:58.311113] W [graph.c:120:_log_if_option_is_invalid] nfsxlator: option 'rpc-auth.auth-glusterfs' is not recognized
[2010-08-03 09:57:58.311137] W [graph.c:120:_log_if_option_is_invalid] ec2-72-44-60-35.compute-1.amazonaws.com-1: option 'transport.socket.nodelay' is not recognized
[2010-08-03 09:57:58.311154] W [graph.c:120:_log_if_option_is_invalid] ec2-75-101-218-254.compute-1.amazonaws.com-1: option 'transport.socket.nodelay' is not recognized
[2010-08-03 09:57:58.311169] W [graph.c:120:_log_if_option_is_invalid] ec2-204-236-197-168.compute-1.amazonaws.com-1: option 'transport.socket.nodelay' is not recognized
[2010-08-03 09:57:58.311185] W [graph.c:120:_log_if_option_is_invalid] ec2-75-101-204-250.compute-1.amazonaws.com-1: option 'transport.socket.nodelay' is not recognized
[2010-08-03 09:57:58.314473] N [client-handshake.c:639:select_server_supported_programs] ec2-75-101-218-254.compute-1.amazonaws.com-1: Using Program GlusterFS-3.1.0, Num (1298437), Version (310)
[2010-08-03 09:57:58.314584] N [client-handshake.c:639:select_server_supported_programs] ec2-75-101-204-250.compute-1.amazonaws.com-1: Using Program GlusterFS-3.1.0, Num (1298437), Version (310)
[2010-08-03 09:57:58.314713] N [client-handshake.c:639:select_server_supported_programs] ec2-72-44-60-35.compute-1.amazonaws.com-1: Using Program GlusterFS-3.1.0, Num (1298437), Version (310)
[2010-08-03 09:57:58.314953] N [client-handshake.c:484:client_setvolume_cbk] ec2-75-101-218-254.compute-1.amazonaws.com-1: Connected to 10.198.110.16:6969, attached to remote volume '/mnt/laks'.
[2010-08-03 09:57:58.314978] N [afr.c:2574:notify] mirror: Subvolume 'ec2-75-101-218-254.compute-1.amazonaws.com-1' came back up; going online.
[2010-08-03 09:57:58.315668] N [client-handshake.c:484:client_setvolume_cbk] ec2-72-44-60-35.compute-1.amazonaws.com-1: Connected to 10.192.134.144:6969, attached to remote volume '/mnt/laks'.
[2010-08-03 09:57:58.315701] N [client-handshake.c:484:client_setvolume_cbk] ec2-75-101-204-250.compute-1.amazonaws.com-1: Connected to 10.192.141.187:6969, attached to remote volume '/mnt/laks/'.
[2010-08-03 09:57:58.316069] N [client-handshake.c:639:select_server_supported_programs] ec2-204-236-197-168.compute-1.amazonaws.com-1: Using Program GlusterFS-3.1.0, Num (1298437), Version (310)
[2010-08-03 09:57:58.316691] N [client-handshake.c:484:client_setvolume_cbk] ec2-204-236-197-168.compute-1.amazonaws.com-1: Connected to 10.214.231.112:6969, attached to remote volume '/mnt/laks'.
[2010-08-03 09:59:45.234867] N [glusterfsd.c:590:cleanup_and_exit] glusterfsd: shutting down
[2010-08-03 09:59:57.229631] D [glusterfsd.c:297:get_volfp] glusterfsd: loading volume file /opt/users/laks/nfs/alpha/test-tcp.vol
[2010-08-03 09:59:57.233647] T [graph.y:192:new_volume] parser: New node for 'ec2-75-101-204-250.compute-1.amazonaws.com-1'
[2010-08-03 09:59:57.233668] T [xlator.c:698:xlator_set_type] xlator: attempt to load file /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/xlator/protocol/client.so
[2010-08-03 09:59:57.310294] T [graph.y:223:volume_type] parser: Type:ec2-75-101-204-250.compute-1.amazonaws.com-1:protocol/client
[2010-08-03 09:59:57.310325] T [graph.y:258:volume_option] parser: Option:ec2-75-101-204-250.compute-1.amazonaws.com-1:transport-type:tcp
[2010-08-03 09:59:57.310344] T [graph.y:258:volume_option] parser: Option:ec2-75-101-204-250.compute-1.amazonaws.com-1:remote-host:ec2-75-101-204-250.compute-1.amazonaws.com
[2010-08-03 09:59:57.310362] T [graph.y:258:volume_option] parser: Option:ec2-75-101-204-250.compute-1.amazonaws.com-1:transport.socket.nodelay:on
[2010-08-03 09:59:57.310379] T [graph.y:258:volume_option] parser: Option:ec2-75-101-204-250.compute-1.amazonaws.com-1:remote-subvolume:/mnt/laks/
[2010-08-03 09:59:57.310393] T [graph.y:365:volume_end] parser: end:ec2-75-101-204-250.compute-1.amazonaws.com-1
[2010-08-03 09:59:57.310425] T [graph.y:192:new_volume] parser: New node for 'ec2-204-236-197-168.compute-1.amazonaws.com-1'
[2010-08-03 09:59:57.310443] T [xlator.c:698:xlator_set_type] xlator: attempt to load file /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/xlator/protocol/client.so
[2010-08-03 09:59:57.310466] T [graph.y:223:volume_type] parser: Type:ec2-204-236-197-168.compute-1.amazonaws.com-1:protocol/client
[2010-08-03 09:59:57.310483] T [graph.y:258:volume_option] parser: Option:ec2-204-236-197-168.compute-1.amazonaws.com-1:transport-type:tcp
[2010-08-03 09:59:57.310499] T [graph.y:258:volume_option] parser: Option:ec2-204-236-197-168.compute-1.amazonaws.com-1:remote-host:ec2-204-236-197-168.compute-1.amazonaws.com
[2010-08-03 09:59:57.310519] T [graph.y:258:volume_option] parser: Option:ec2-204-236-197-168.compute-1.amazonaws.com-1:transport.socket.nodelay:on
[2010-08-03 09:59:57.310535] T [graph.y:258:volume_option] parser: Option:ec2-204-236-197-168.compute-1.amazonaws.com-1:remote-subvolume:/mnt/laks
[2010-08-03 09:59:57.310549] T [graph.y:365:volume_end] parser: end:ec2-204-236-197-168.compute-1.amazonaws.com-1
[2010-08-03 09:59:57.310565] T [graph.y:192:new_volume] parser: New node for 'ec2-75-101-218-254.compute-1.amazonaws.com-1'
[2010-08-03 09:59:57.310581] T [xlator.c:698:xlator_set_type] xlator: attempt to load file /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/xlator/protocol/client.so
[2010-08-03 09:59:57.310603] T [graph.y:223:volume_type] parser: Type:ec2-75-101-218-254.compute-1.amazonaws.com-1:protocol/client
[2010-08-03 09:59:57.310619] T [graph.y:258:volume_option] parser: Option:ec2-75-101-218-254.compute-1.amazonaws.com-1:transport-type:tcp
[2010-08-03 09:59:57.310636] T [graph.y:258:volume_option] parser: Option:ec2-75-101-218-254.compute-1.amazonaws.com-1:remote-host:ec2-75-101-218-254.compute-1.amazonaws.com
[2010-08-03 09:59:57.310653] T [graph.y:258:volume_option] parser: Option:ec2-75-101-218-254.compute-1.amazonaws.com-1:transport.socket.nodelay:on
[2010-08-03 09:59:57.310669] T [graph.y:258:volume_option] parser: Option:ec2-75-101-218-254.compute-1.amazonaws.com-1:remote-subvolume:/mnt/laks
[2010-08-03 09:59:57.310683] T [graph.y:365:volume_end] parser: end:ec2-75-101-218-254.compute-1.amazonaws.com-1
[2010-08-03 09:59:57.310699] T [graph.y:192:new_volume] parser: New node for 'ec2-72-44-60-35.compute-1.amazonaws.com-1'
[2010-08-03 09:59:57.310715] T [xlator.c:698:xlator_set_type] xlator: attempt to load file /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/xlator/protocol/client.so
[2010-08-03 09:59:57.310732] T [graph.y:223:volume_type] parser: Type:ec2-72-44-60-35.compute-1.amazonaws.com-1:protocol/client
[2010-08-03 09:59:57.310749] T [graph.y:258:volume_option] parser: Option:ec2-72-44-60-35.compute-1.amazonaws.com-1:transport-type:tcp
[2010-08-03 09:59:57.310770] T [graph.y:258:volume_option] parser: Option:ec2-72-44-60-35.compute-1.amazonaws.com-1:remote-host:ec2-72-44-60-35.compute-1.amazonaws.com
[2010-08-03 09:59:57.310786] T [graph.y:258:volume_option] parser: Option:ec2-72-44-60-35.compute-1.amazonaws.com-1:transport.socket.nodelay:on
[2010-08-03 09:59:57.310803] T [graph.y:258:volume_option] parser: Option:ec2-72-44-60-35.compute-1.amazonaws.com-1:remote-subvolume:/mnt/laks
[2010-08-03 09:59:57.310817] T [graph.y:365:volume_end] parser: end:ec2-72-44-60-35.compute-1.amazonaws.com-1
[2010-08-03 09:59:57.310832] T [graph.y:192:new_volume] parser: New node for 'mirror'
[2010-08-03 09:59:57.310848] T [xlator.c:698:xlator_set_type] xlator: attempt to load file /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/xlator/cluster/replicate.so
[2010-08-03 09:59:57.366169] T [graph.y:223:volume_type] parser: Type:mirror:cluster/replicate
[2010-08-03 09:59:57.366192] T [graph.y:348:volume_sub] parser: child:mirror->ec2-75-101-204-250.compute-1.amazonaws.com-1
[2010-08-03 09:59:57.366209] T [graph.y:348:volume_sub] parser: child:mirror->ec2-204-236-197-168.compute-1.amazonaws.com-1
[2010-08-03 09:59:57.366225] T [graph.y:348:volume_sub] parser: child:mirror->ec2-75-101-218-254.compute-1.amazonaws.com-1
[2010-08-03 09:59:57.366250] T [graph.y:348:volume_sub] parser: child:mirror->ec2-72-44-60-35.compute-1.amazonaws.com-1
[2010-08-03 09:59:57.366265] T [graph.y:365:volume_end] parser: end:mirror
[2010-08-03 09:59:57.366281] T [graph.y:192:new_volume] parser: New node for 'nfsxlator'
[2010-08-03 09:59:57.366302] T [xlator.c:698:xlator_set_type] xlator: attempt to load file /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/xlator/nfs/server.so
[2010-08-03 09:59:57.442780] D [xlator.c:738:xlator_set_type] xlator: dlsym(dumpops) on /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/xlator/nfs/server.so: undefined symbol: dumpops -- neglecting
[2010-08-03 09:59:57.442804] T [graph.y:223:volume_type] parser: Type:nfsxlator:nfs/server
[2010-08-03 09:59:57.442822] T [graph.y:348:volume_sub] parser: child:nfsxlator->mirror
[2010-08-03 09:59:57.442844] T [graph.y:258:volume_option] parser: Option:nfsxlator:rpc-auth.addr.mirror.allow:*
[2010-08-03 09:59:57.442864] T [graph.y:365:volume_end] parser: end:nfsxlator
[2010-08-03 09:59:57.442968] D [xlator.c:953:xlator_mem_acct_init] nfsxlator: Allocated mem_acct_rec for 86 types
[2010-08-03 09:59:57.443009] T [rpcsvc-auth.c:117:rpcsvc_auth_init_auth] rpc-service: Authentication enabled: AUTH_GLUSTERFS
[2010-08-03 09:59:57.443025] T [rpcsvc-auth.c:117:rpcsvc_auth_init_auth] rpc-service: Authentication enabled: AUTH_UNIX
[2010-08-03 09:59:57.443039] T [rpcsvc-auth.c:117:rpcsvc_auth_init_auth] rpc-service: Authentication enabled: AUTH_NULL
[2010-08-03 09:59:57.443052] D [rpcsvc.c:2061:rpcsvc_init] rpc-service: RPC service inited.
[2010-08-03 09:59:57.443079] W [rpc-transport.c:878:rpc_transport_load] rpc-transport: missing 'option transport-type'. defaulting to "socket"
[2010-08-03 09:59:57.443103] D [rpc-transport.c:930:rpc_transport_load] rpc-transport: attempt to load file /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/rpc-transport/socket.so
[2010-08-03 09:59:57.465027] D [dict.c:324:dict_get] dict: @this=(nil) @key=0x2aaaacbed334
[2010-08-03 09:59:57.465061] D [dict.c:324:dict_get] dict: @this=(nil) @key=0x2aaaacbed35e
[2010-08-03 09:59:57.465087] D [name.c:553:server_fill_address_family] RPC: option address-family not specified, defaulting to inet/inet6
[2010-08-03 09:59:57.465188] T [socket.c:341:__socket_nodelay] : NODELAY enabled for socket 6
[2010-08-03 09:59:57.465230] T [rpcsvc.c:512:rpcsvc_conn_alloc] rpc-service: rx pool: 525
[2010-08-03 09:59:57.465822] D [rpcsvc.c:1917:rpcsvc_program_register] rpc-service: New program registered: GF-DUMP, Num: 123451501, Ver: 1, Port: 0
[2010-08-03 09:59:57.465947] T [nfs.c:344:nfs_init_subvolumes] nfs: inode table lru: 90000
[2010-08-03 09:59:57.465964] D [nfs.c:348:nfs_init_subvolumes] nfs: Initing subvolume: mirror
[2010-08-03 09:59:57.466421] T [nfs.c:368:nfs_init_subvolumes] nfs: Inited volumes: 1
[2010-08-03 09:59:57.466436] D [nfs.c:519:init] nfs: NFS service started
[2010-08-03 09:59:57.466454] D [xlator.c:953:xlator_mem_acct_init] mirror: Allocated mem_acct_rec for 83 types
[2010-08-03 09:59:57.466483] D [xlator.c:953:xlator_mem_acct_init] ec2-72-44-60-35.compute-1.amazonaws.com-1: Allocated mem_acct_rec for 71 types
[2010-08-03 09:59:57.466499] D [client.c:1495:build_client_config] ec2-72-44-60-35.compute-1.amazonaws.com-1: defaulting frame-timeout to 30mins
[2010-08-03 09:59:57.466513] D [client.c:1506:build_client_config] ec2-72-44-60-35.compute-1.amazonaws.com-1: defaulting remote-port to 'auto'
[2010-08-03 09:59:57.466527] D [client.c:1516:build_client_config] ec2-72-44-60-35.compute-1.amazonaws.com-1: defaulting ping-timeout to 42
[2010-08-03 09:59:57.468658] D [rpc-clnt.c:844:rpc_clnt_connection_init] ec2-72-44-60-35.compute-1.amazonaws.com-1: defaulting frame-timeout to 30mins
[2010-08-03 09:59:57.468693] D [rpc-transport.c:930:rpc_transport_load] rpc-transport: attempt to load file /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/rpc-transport/socket.so
[2010-08-03 09:59:57.468730] D [dict.c:324:dict_get] dict: @this=(nil) @key=0x2aaaacbed334
[2010-08-03 09:59:57.468746] D [dict.c:324:dict_get] dict: @this=(nil) @key=0x2aaaacbed35e
[2010-08-03 09:59:57.468781] T [rpc-clnt.c:381:rpc_clnt_reconnect] ec2-72-44-60-35.compute-1.amazonaws.com-1: attempting reconnect
[2010-08-03 09:59:57.468799] D [name.c:155:client_fill_address_family] ec2-72-44-60-35.compute-1.amazonaws.com-1: address-family not specified, guessing it to be inet/inet6
[2010-08-03 09:59:57.468814] T [name.c:227:af_inet_client_get_remote_sockaddr] ec2-72-44-60-35.compute-1.amazonaws.com-1: option remote-port missing in volume ec2-72-44-60-35.compute-1.amazonaws.com-1. Defaulting to 6969
[2010-08-03 09:59:57.468831] T [common-utils.c:109:gf_resolve_ip6] resolver: DNS cache not present, freshly probing hostname: ec2-72-44-60-35.compute-1.amazonaws.com
[2010-08-03 09:59:57.479824] T [common-utils.c:150:gf_resolve_ip6] resolver: returning ip-10.192.134.144 (port-acmsoda) for hostname: ec2-72-44-60-35.compute-1.amazonaws.com and port: 6969
[2010-08-03 09:59:57.479934] D [xlator.c:953:xlator_mem_acct_init] ec2-75-101-218-254.compute-1.amazonaws.com-1: Allocated mem_acct_rec for 71 types
[2010-08-03 09:59:57.479958] D [client.c:1495:build_client_config] ec2-75-101-218-254.compute-1.amazonaws.com-1: defaulting frame-timeout to 30mins
[2010-08-03 09:59:57.479973] D [client.c:1506:build_client_config] ec2-75-101-218-254.compute-1.amazonaws.com-1: defaulting remote-port to 'auto'
[2010-08-03 09:59:57.479987] D [client.c:1516:build_client_config] ec2-75-101-218-254.compute-1.amazonaws.com-1: defaulting ping-timeout to 42
[2010-08-03 09:59:57.482268] D [rpc-clnt.c:844:rpc_clnt_connection_init] ec2-75-101-218-254.compute-1.amazonaws.com-1: defaulting frame-timeout to 30mins
[2010-08-03 09:59:57.482298] D [rpc-transport.c:930:rpc_transport_load] rpc-transport: attempt to load file /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/rpc-transport/socket.so
[2010-08-03 09:59:57.482329] D [dict.c:324:dict_get] dict: @this=(nil) @key=0x2aaaacbed334
[2010-08-03 09:59:57.482344] D [dict.c:324:dict_get] dict: @this=(nil) @key=0x2aaaacbed35e
[2010-08-03 09:59:57.482359] T [rpc-clnt.c:381:rpc_clnt_reconnect] ec2-75-101-218-254.compute-1.amazonaws.com-1: attempting reconnect
[2010-08-03 09:59:57.482374] D [name.c:155:client_fill_address_family] ec2-75-101-218-254.compute-1.amazonaws.com-1: address-family not specified, guessing it to be inet/inet6
[2010-08-03 09:59:57.482389] T [name.c:227:af_inet_client_get_remote_sockaddr] ec2-75-101-218-254.compute-1.amazonaws.com-1: option remote-port missing in volume ec2-75-101-218-254.compute-1.amazonaws.com-1. Defaulting to 6969
[2010-08-03 09:59:57.482405] T [common-utils.c:109:gf_resolve_ip6] resolver: DNS cache not present, freshly probing hostname: ec2-75-101-218-254.compute-1.amazonaws.com
[2010-08-03 09:59:57.486457] T [common-utils.c:150:gf_resolve_ip6] resolver: returning ip-10.198.110.16 (port-acmsoda) for hostname: ec2-75-101-218-254.compute-1.amazonaws.com and port: 6969
[2010-08-03 09:59:57.486526] D [xlator.c:953:xlator_mem_acct_init] ec2-204-236-197-168.compute-1.amazonaws.com-1: Allocated mem_acct_rec for 71 types
[2010-08-03 09:59:57.486552] D [client.c:1495:build_client_config] ec2-204-236-197-168.compute-1.amazonaws.com-1: defaulting frame-timeout to 30mins
[2010-08-03 09:59:57.486572] D [client.c:1506:build_client_config] ec2-204-236-197-168.compute-1.amazonaws.com-1: defaulting remote-port to 'auto'
[2010-08-03 09:59:57.486586] D [client.c:1516:build_client_config] ec2-204-236-197-168.compute-1.amazonaws.com-1: defaulting ping-timeout to 42
[2010-08-03 09:59:57.488851] D [rpc-clnt.c:844:rpc_clnt_connection_init] ec2-204-236-197-168.compute-1.amazonaws.com-1: defaulting frame-timeout to 30mins
[2010-08-03 09:59:57.488878] D [rpc-transport.c:930:rpc_transport_load] rpc-transport: attempt to load file /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/rpc-transport/socket.so
[2010-08-03 09:59:57.488909] D [dict.c:324:dict_get] dict: @this=(nil) @key=0x2aaaacbed334
[2010-08-03 09:59:57.488924] D [dict.c:324:dict_get] dict: @this=(nil) @key=0x2aaaacbed35e
[2010-08-03 09:59:57.488938] T [rpc-clnt.c:381:rpc_clnt_reconnect] ec2-204-236-197-168.compute-1.amazonaws.com-1: attempting reconnect
[2010-08-03 09:59:57.488974] D [name.c:155:client_fill_address_family] ec2-204-236-197-168.compute-1.amazonaws.com-1: address-family not specified, guessing it to be inet/inet6
[2010-08-03 09:59:57.488989] T [name.c:227:af_inet_client_get_remote_sockaddr] ec2-204-236-197-168.compute-1.amazonaws.com-1: option remote-port missing in volume ec2-204-236-197-168.compute-1.amazonaws.com-1. Defaulting to 6969
[2010-08-03 09:59:57.489010] T [common-utils.c:109:gf_resolve_ip6] resolver: DNS cache not present, freshly probing hostname: ec2-204-236-197-168.compute-1.amazonaws.com
[2010-08-03 09:59:57.492901] T [common-utils.c:150:gf_resolve_ip6] resolver: returning ip-10.214.231.112 (port-acmsoda) for hostname: ec2-204-236-197-168.compute-1.amazonaws.com and port: 6969
[2010-08-03 09:59:57.492966] D [xlator.c:953:xlator_mem_acct_init] ec2-75-101-204-250.compute-1.amazonaws.com-1: Allocated mem_acct_rec for 71 types
[2010-08-03 09:59:57.492994] D [client.c:1495:build_client_config] ec2-75-101-204-250.compute-1.amazonaws.com-1: defaulting frame-timeout to 30mins
[2010-08-03 09:59:57.493009] D [client.c:1506:build_client_config] ec2-75-101-204-250.compute-1.amazonaws.com-1: defaulting remote-port to 'auto'
[2010-08-03 09:59:57.493024] D [client.c:1516:build_client_config] ec2-75-101-204-250.compute-1.amazonaws.com-1: defaulting ping-timeout to 42
[2010-08-03 09:59:57.495292] D [rpc-clnt.c:844:rpc_clnt_connection_init] ec2-75-101-204-250.compute-1.amazonaws.com-1: defaulting frame-timeout to 30mins
[2010-08-03 09:59:57.495318] D [rpc-transport.c:930:rpc_transport_load] rpc-transport: attempt to load file /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/rpc-transport/socket.so
[2010-08-03 09:59:57.495352] D [dict.c:324:dict_get] dict: @this=(nil) @key=0x2aaaacbed334
[2010-08-03 09:59:57.495367] D [dict.c:324:dict_get] dict: @this=(nil) @key=0x2aaaacbed35e
[2010-08-03 09:59:57.495381] T [rpc-clnt.c:381:rpc_clnt_reconnect] ec2-75-101-204-250.compute-1.amazonaws.com-1: attempting reconnect
[2010-08-03 09:59:57.495396] D [name.c:155:client_fill_address_family] ec2-75-101-204-250.compute-1.amazonaws.com-1: address-family not specified, guessing it to be inet/inet6
[2010-08-03 09:59:57.495411] T [name.c:227:af_inet_client_get_remote_sockaddr] ec2-75-101-204-250.compute-1.amazonaws.com-1: option remote-port missing in volume ec2-75-101-204-250.compute-1.amazonaws.com-1. Defaulting to 6969
[2010-08-03 09:59:57.495426] T [common-utils.c:109:gf_resolve_ip6] resolver: DNS cache not present, freshly probing hostname: ec2-75-101-204-250.compute-1.amazonaws.com
[2010-08-03 09:59:57.508578] T [common-utils.c:150:gf_resolve_ip6] resolver: returning ip-10.192.141.187 (port-acmsoda) for hostname: ec2-75-101-204-250.compute-1.amazonaws.com and port: 6969
[2010-08-03 09:59:57.508655] W [graph.c:120:_log_if_option_is_invalid] nfsxlator: option 'transport-type' is not recognized
[2010-08-03 09:59:57.508677] W [graph.c:120:_log_if_option_is_invalid] nfsxlator: option 'rpc-auth.auth-glusterfs' is not recognized
[2010-08-03 09:59:57.508703] W [graph.c:120:_log_if_option_is_invalid] ec2-72-44-60-35.compute-1.amazonaws.com-1: option 'transport.socket.nodelay' is not recognized
[2010-08-03 09:59:57.508725] W [graph.c:120:_log_if_option_is_invalid] ec2-75-101-218-254.compute-1.amazonaws.com-1: option 'transport.socket.nodelay' is not recognized
[2010-08-03 09:59:57.508741] W [graph.c:120:_log_if_option_is_invalid] ec2-204-236-197-168.compute-1.amazonaws.com-1: option 'transport.socket.nodelay' is not recognized
[2010-08-03 09:59:57.508756] W [graph.c:120:_log_if_option_is_invalid] ec2-75-101-204-250.compute-1.amazonaws.com-1: option 'transport.socket.nodelay' is not recognized
[2010-08-03 09:59:57.508773] T [nfs.c:535:notify] nfs: Notification received: 1
[2010-08-03 09:59:57.508789] D [client.c:1457:notify] ec2-75-101-204-250.compute-1.amazonaws.com-1: got GF_EVENT_PARENT_UP, attempting connect on transport
[2010-08-03 09:59:57.508805] T [rpc-clnt.c:381:rpc_clnt_reconnect] ec2-75-101-204-250.compute-1.amazonaws.com-1: attempting reconnect
[2010-08-03 09:59:57.508834] T [socket.c:1689:socket_connect] ec2-75-101-204-250.compute-1.amazonaws.com-1: connect () called on transport already connected
[2010-08-03 09:59:57.508850] D [client.c:1457:notify] ec2-204-236-197-168.compute-1.amazonaws.com-1: got GF_EVENT_PARENT_UP, attempting connect on transport
[2010-08-03 09:59:57.508864] T [rpc-clnt.c:381:rpc_clnt_reconnect] ec2-204-236-197-168.compute-1.amazonaws.com-1: attempting reconnect
[2010-08-03 09:59:57.508878] T [socket.c:1689:socket_connect] ec2-204-236-197-168.compute-1.amazonaws.com-1: connect () called on transport already connected
[2010-08-03 09:59:57.508893] D [client.c:1457:notify] ec2-75-101-218-254.compute-1.amazonaws.com-1: got GF_EVENT_PARENT_UP, attempting connect on transport
[2010-08-03 09:59:57.508907] T [rpc-clnt.c:381:rpc_clnt_reconnect] ec2-75-101-218-254.compute-1.amazonaws.com-1: attempting reconnect
[2010-08-03 09:59:57.508921] T [socket.c:1689:socket_connect] ec2-75-101-218-254.compute-1.amazonaws.com-1: connect () called on transport already connected
[2010-08-03 09:59:57.508935] D [client.c:1457:notify] ec2-72-44-60-35.compute-1.amazonaws.com-1: got GF_EVENT_PARENT_UP, attempting connect on transport
[2010-08-03 09:59:57.508950] T [rpc-clnt.c:381:rpc_clnt_reconnect] ec2-72-44-60-35.compute-1.amazonaws.com-1: attempting reconnect
[2010-08-03 09:59:57.508964] T [socket.c:1689:socket_connect] ec2-72-44-60-35.compute-1.amazonaws.com-1: connect () called on transport already connected
[2010-08-03 09:59:57.511000] T [client.c:1399:client_rpc_notify] ec2-75-101-204-250.compute-1.amazonaws.com-1: got RPC_CLNT_CONNECT
[2010-08-03 09:59:57.511049] T [socket.c:1689:socket_connect] ec2-75-101-204-250.compute-1.amazonaws.com-1: connect () called on transport already connected
[2010-08-03 09:59:57.511066] T [rpc-clnt.c:1164:rpc_clnt_record] : Auth Info: pid: 0, uid: 0, gid: 0, owner: 0
[2010-08-03 09:59:57.511095] T [rpc-clnt.c:1056:rpc_clnt_record_build_header] rpc-clnt: Request fraglen 136, payload: 8, rpc hdr: 128
[2010-08-03 09:59:57.511166] T [client.c:1399:client_rpc_notify] ec2-204-236-197-168.compute-1.amazonaws.com-1: got RPC_CLNT_CONNECT
[2010-08-03 09:59:57.511187] T [socket.c:1689:socket_connect] ec2-204-236-197-168.compute-1.amazonaws.com-1: connect () called on transport already connected
[2010-08-03 09:59:57.511207] T [rpc-clnt.c:1164:rpc_clnt_record] : Auth Info: pid: 0, uid: 0, gid: 0, owner: 0
[2010-08-03 09:59:57.511222] T [rpc-clnt.c:1056:rpc_clnt_record_build_header] rpc-clnt: Request fraglen 136, payload: 8, rpc hdr: 128
[2010-08-03 09:59:57.511263] T [client.c:1399:client_rpc_notify] ec2-75-101-218-254.compute-1.amazonaws.com-1: got RPC_CLNT_CONNECT
[2010-08-03 09:59:57.511284] T [socket.c:1689:socket_connect] ec2-75-101-218-254.compute-1.amazonaws.com-1: connect () called on transport already connected
[2010-08-03 09:59:57.511298] T [rpc-clnt.c:1164:rpc_clnt_record] : Auth Info: pid: 0, uid: 0, gid: 0, owner: 0
[2010-08-03 09:59:57.511312] T [rpc-clnt.c:1056:rpc_clnt_record_build_header] rpc-clnt: Request fraglen 136, payload: 8, rpc hdr: 128
[2010-08-03 09:59:57.511351] T [client.c:1399:client_rpc_notify] ec2-72-44-60-35.compute-1.amazonaws.com-1: got RPC_CLNT_CONNECT
[2010-08-03 09:59:57.511372] T [socket.c:1689:socket_connect] ec2-72-44-60-35.compute-1.amazonaws.com-1: connect () called on transport already connected
[2010-08-03 09:59:57.511386] T [rpc-clnt.c:1164:rpc_clnt_record] : Auth Info: pid: 0, uid: 0, gid: 0, owner: 0
[2010-08-03 09:59:57.511400] T [rpc-clnt.c:1056:rpc_clnt_record_build_header] rpc-clnt: Request fraglen 136, payload: 8, rpc hdr: 128
[2010-08-03 09:59:57.511759] T [socket.c:613:__socket_read_simple_msg] ec2-204-236-197-168.compute-1.amazonaws.com-1: partial read on non-blocking socket.
[2010-08-03 09:59:57.511843] T [socket.c:613:__socket_read_simple_msg] ec2-75-101-218-254.compute-1.amazonaws.com-1: partial read on non-blocking socket.
[2010-08-03 09:59:57.511981] T [socket.c:613:__socket_read_simple_msg] ec2-72-44-60-35.compute-1.amazonaws.com-1: partial read on non-blocking socket.
[2010-08-03 09:59:57.512228] T [socket.c:613:__socket_read_simple_msg] ec2-204-236-197-168.compute-1.amazonaws.com-1: partial read on non-blocking socket.
[2010-08-03 09:59:57.512276] T [rpc-clnt.c:596:rpc_clnt_reply_init] rpc-clnt: RPC XID: 43 Program: GF-DUMP, ProgVers: 1, Proc: 1
[2010-08-03 09:59:57.512310] T [client-handshake.c:645:select_server_supported_programs] ec2-75-101-218-254.compute-1.amazonaws.com-1: GF-DUMP (1) not supported
[2010-08-03 09:59:57.512326] N [client-handshake.c:639:select_server_supported_programs] ec2-75-101-218-254.compute-1.amazonaws.com-1: Using Program GlusterFS-3.1.0, Num (1298437), Version (310)
[2010-08-03 09:59:57.512404] T [socket.c:1689:socket_connect] ec2-75-101-218-254.compute-1.amazonaws.com-1: connect () called on transport already connected
[2010-08-03 09:59:57.512430] T [rpc-clnt.c:1164:rpc_clnt_record] : Auth Info: pid: 0, uid: 0, gid: 0, owner: 0
[2010-08-03 09:59:57.512452] T [rpc-clnt.c:1056:rpc_clnt_record_build_header] rpc-clnt: Request fraglen 460, payload: 332, rpc hdr: 128
[2010-08-03 09:59:57.512499] T [rpc-clnt.c:596:rpc_clnt_reply_init] rpc-clnt: RPC XID: 43 Program: GF-DUMP, ProgVers: 1, Proc: 1
[2010-08-03 09:59:57.512520] T [client-handshake.c:645:select_server_supported_programs] ec2-72-44-60-35.compute-1.amazonaws.com-1: GF-DUMP (1) not supported
[2010-08-03 09:59:57.512535] N [client-handshake.c:639:select_server_supported_programs] ec2-72-44-60-35.compute-1.amazonaws.com-1: Using Program GlusterFS-3.1.0, Num (1298437), Version (310)
[2010-08-03 09:59:57.512585] T [socket.c:1689:socket_connect] ec2-72-44-60-35.compute-1.amazonaws.com-1: connect () called on transport already connected
[2010-08-03 09:59:57.512600] T [rpc-clnt.c:1164:rpc_clnt_record] : Auth Info: pid: 0, uid: 0, gid: 0, owner: 0
[2010-08-03 09:59:57.512615] T [rpc-clnt.c:1056:rpc_clnt_record_build_header] rpc-clnt: Request fraglen 456, payload: 328, rpc hdr: 128
[2010-08-03 09:59:57.512663] T [rpc-clnt.c:596:rpc_clnt_reply_init] rpc-clnt: RPC XID: 43 Program: GF-DUMP, ProgVers: 1, Proc: 1
[2010-08-03 09:59:57.512688] T [client-handshake.c:645:select_server_supported_programs] ec2-204-236-197-168.compute-1.amazonaws.com-1: GF-DUMP (1) not supported
[2010-08-03 09:59:57.512703] N [client-handshake.c:639:select_server_supported_programs] ec2-204-236-197-168.compute-1.amazonaws.com-1: Using Program GlusterFS-3.1.0, Num (1298437), Version (310)
[2010-08-03 09:59:57.512729] T [socket.c:1689:socket_connect] ec2-204-236-197-168.compute-1.amazonaws.com-1: connect () called on transport already connected
[2010-08-03 09:59:57.512743] T [rpc-clnt.c:1164:rpc_clnt_record] : Auth Info: pid: 0, uid: 0, gid: 0, owner: 0
[2010-08-03 09:59:57.512758] T [rpc-clnt.c:1056:rpc_clnt_record_build_header] rpc-clnt: Request fraglen 464, payload: 336, rpc hdr: 128
[2010-08-03 09:59:57.512988] T [rpc-clnt.c:596:rpc_clnt_reply_init] rpc-clnt: RPC XID: 44 Program: GlusterFS Handshake, ProgVers: 1, Proc: 1
[2010-08-03 09:59:57.513035] N [client-handshake.c:484:client_setvolume_cbk] ec2-75-101-218-254.compute-1.amazonaws.com-1: Connected to 10.198.110.16:6969, attached to remote volume '/mnt/laks'.
[2010-08-03 09:59:57.513059] N [afr.c:2574:notify] mirror: Subvolume 'ec2-75-101-218-254.compute-1.amazonaws.com-1' came back up; going online.
[2010-08-03 09:59:57.513078] T [nfs.c:535:notify] nfs: Notification received: 5
[2010-08-03 09:59:57.513098] D [nfs.c:211:nfs_subvolume_set_started] nfs: Starting up: mirror , vols started till now: 1
[2010-08-03 09:59:57.513141] T [nfs-fops.c:279:nfs_fop_lookup] nfs: Lookup: /
[2010-08-03 09:59:57.513219] T [rpc-clnt.c:1164:rpc_clnt_record] : Auth Info: pid: 0, uid: 0, gid: 0, owner: 0
[2010-08-03 09:59:57.513261] T [rpc-clnt.c:1056:rpc_clnt_record_build_header] rpc-clnt: Request fraglen 556, payload: 428, rpc hdr: 128
[2010-08-03 09:59:57.513293] T [rpc-clnt.c:1164:rpc_clnt_record] : Auth Info: pid: 0, uid: 0, gid: 0, owner: 0
[2010-08-03 09:59:57.513317] T [rpc-clnt.c:1056:rpc_clnt_record_build_header] rpc-clnt: Request fraglen 128, payload: 0, rpc hdr: 128
[2010-08-03 09:59:57.513353] T [nfs.c:545:notify] nfs: All children up, starting RPC
[2010-08-03 09:59:57.513369] D [nfs.c:107:nfs_init_versions] nfs: Initing protocol versions
[2010-08-03 09:59:57.513386] D [mount3.c:1477:mnt3svc_init] nfs-mount: Initing Mount v3 state
[2010-08-03 09:59:57.513406] T [mount3.c:1376:__mnt3_init_volume_export] nfs-mount: Volume exports enabled
[2010-08-03 09:59:57.513420] T [mount3.c:1397:mnt3_init_options] nfs-mount: Initing options for: mirror
[2010-08-03 09:59:57.513436] T [mount3.c:1238:mnt3_init_export_ent] nfs-mount: Initing volume export: mirror
[2010-08-03 09:59:57.513451] D [nfs.c:123:nfs_init_versions] nfs: Starting program: MOUNT3
[2010-08-03 09:59:57.513595] D [rpcsvc.c:1917:rpcsvc_program_register] rpc-service: New program registered: MOUNT3, Num: 100005, Ver: 3, Port: 0
[2010-08-03 09:59:57.513613] D [mount3.c:1521:mnt1svc_init] nfs-mount: Initing Mount v1 state
[2010-08-03 09:59:57.513628] T [mount3.c:1376:__mnt3_init_volume_export] nfs-mount: Volume exports enabled
[2010-08-03 09:59:57.513642] T [mount3.c:1397:mnt3_init_options] nfs-mount: Initing options for: mirror
[2010-08-03 09:59:57.513656] T [mount3.c:1238:mnt3_init_export_ent] nfs-mount: Initing volume export: mirror
[2010-08-03 09:59:57.513670] D [nfs.c:123:nfs_init_versions] nfs: Starting program: MOUNT1
[2010-08-03 09:59:57.513779] D [rpcsvc.c:1917:rpcsvc_program_register] rpc-service: New program registered: MOUNT1, Num: 100005, Ver: 1, Port: 0
[2010-08-03 09:59:57.513811] T [nfs3.c:4959:nfs3_init_state] nfs-nfsv3: local pool: 225
[2010-08-03 09:59:57.514045] T [nfs3.c:4879:nfs3_init_subvolume] nfs-nfsv3: Initing state: mirror
[2010-08-03 09:59:57.514063] T [nfs3.c:4859:nfs3_init_subvolume_options] nfs-nfsv3: mirror: read-write, no trusted_sync, no trusted_write
[2010-08-03 09:59:57.514077] D [nfs.c:123:nfs_init_versions] nfs: Starting program: NFS3
[2010-08-03 09:59:57.514161] D [rpcsvc.c:1917:rpcsvc_program_register] rpc-service: New program registered: NFS3, Num: 100003, Ver: 3, Port: 0
[2010-08-03 09:59:57.514194] T [rpc-clnt.c:596:rpc_clnt_reply_init] rpc-clnt: RPC XID: 44 Program: GlusterFS Handshake, ProgVers: 1, Proc: 1
[2010-08-03 09:59:57.514213] N [client-handshake.c:484:client_setvolume_cbk] ec2-204-236-197-168.compute-1.amazonaws.com-1: Connected to 10.214.231.112:6969, attached to remote volume '/mnt/laks'.
[2010-08-03 09:59:57.514240] T [rpc-clnt.c:596:rpc_clnt_reply_init] rpc-clnt: RPC XID: 44 Program: GlusterFS Handshake, ProgVers: 1, Proc: 1
[2010-08-03 09:59:57.514258] N [client-handshake.c:484:client_setvolume_cbk] ec2-72-44-60-35.compute-1.amazonaws.com-1: Connected to 10.192.134.144:6969, attached to remote volume '/mnt/laks'.
[2010-08-03 09:59:57.514284] T [rpc-clnt.c:596:rpc_clnt_reply_init] rpc-clnt: RPC XID: 45 Program: GlusterFS 3.1, ProgVers: 310, Proc: 27
[2010-08-03 09:59:57.514462] T [nfs.c:235:nfs_start_subvol_lookup_cbk] nfs: Started mirror
[2010-08-03 09:59:57.514498] T [rpc-clnt.c:596:rpc_clnt_reply_init] rpc-clnt: RPC XID: 46 Program: GlusterFS Handshake, ProgVers: 1, Proc: 3
[2010-08-03 09:59:57.528014] T [socket.c:613:__socket_read_simple_msg] ec2-75-101-204-250.compute-1.amazonaws.com-1: partial read on non-blocking socket.
[2010-08-03 09:59:57.528445] T [rpc-clnt.c:596:rpc_clnt_reply_init] rpc-clnt: RPC XID: 43 Program: GF-DUMP, ProgVers: 1, Proc: 1
[2010-08-03 09:59:57.528469] T [client-handshake.c:645:select_server_supported_programs] ec2-75-101-204-250.compute-1.amazonaws.com-1: GF-DUMP (1) not supported
[2010-08-03 09:59:57.528495] N [client-handshake.c:639:select_server_supported_programs] ec2-75-101-204-250.compute-1.amazonaws.com-1: Using Program GlusterFS-3.1.0, Num (1298437), Version (310)
[2010-08-03 09:59:57.528526] T [socket.c:1689:socket_connect] ec2-75-101-204-250.compute-1.amazonaws.com-1: connect () called on transport already connected
[2010-08-03 09:59:57.528541] T [rpc-clnt.c:1164:rpc_clnt_record] : Auth Info: pid: 0, uid: 0, gid: 0, owner: 0
[2010-08-03 09:59:57.528556] T [rpc-clnt.c:1056:rpc_clnt_record_build_header] rpc-clnt: Request fraglen 460, payload: 332, rpc hdr: 128
[2010-08-03 09:59:57.529153] T [rpc-clnt.c:596:rpc_clnt_reply_init] rpc-clnt: RPC XID: 44 Program: GlusterFS Handshake, ProgVers: 1, Proc: 1
[2010-08-03 09:59:57.529181] N [client-handshake.c:484:client_setvolume_cbk] ec2-75-101-204-250.compute-1.amazonaws.com-1: Connected to 10.192.141.187:6969, attached to remote volume '/mnt/laks/'.
[2010-08-03 10:00:01.485229] T [rpc-clnt.c:390:rpc_clnt_reconnect] ec2-75-101-204-250.compute-1.amazonaws.com-1: breaking reconnect chain
[2010-08-03 10:00:01.485268] T [rpc-clnt.c:390:rpc_clnt_reconnect] ec2-204-236-197-168.compute-1.amazonaws.com-1: breaking reconnect chain
[2010-08-03 10:00:01.485285] T [rpc-clnt.c:390:rpc_clnt_reconnect] ec2-75-101-218-254.compute-1.amazonaws.com-1: breaking reconnect chain
[2010-08-03 10:00:01.485301] T [rpc-clnt.c:390:rpc_clnt_reconnect] ec2-72-44-60-35.compute-1.amazonaws.com-1: breaking reconnect chain

Comment 1 Shehjar Tikoo 2010-08-04 02:20:15 UTC
Setting to blocker because NFS fails to start-up in a really simple configuration.

Comment 2 Lakshmipathi G 2010-08-04 02:42:31 UTC
Checking with simple posix+iot config. ,got the same error.
Here is the log:
--------
[2010-08-04 01:38:32.998097] D [glusterfsd.c:297:get_volfp] glusterfsd: loading volume file /opt/users/laks/nfs/854/854.vol
[2010-08-04 01:38:33.2091] T [graph.y:192:new_volume] parser: New node for 'posix1'
[2010-08-04 01:38:33.2113] T [xlator.c:698:xlator_set_type] xlator: attempt to load file /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/xlator/storage/posix.so
[2010-08-04 01:38:33.71973] T [graph.y:223:volume_type] parser: Type:posix1:storage/posix
[2010-08-04 01:38:33.72003] T [graph.y:258:volume_option] parser: Option:posix1:directory:/mnt/laks
[2010-08-04 01:38:33.72019] T [graph.y:365:volume_end] parser: end:posix1
[2010-08-04 01:38:33.72036] T [graph.y:192:new_volume] parser: New node for 'brick1'
[2010-08-04 01:38:33.72052] T [xlator.c:698:xlator_set_type] xlator: attempt to load file /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/xlator/features/access-control.so
[2010-08-04 01:38:33.115912] D [xlator.c:733:xlator_set_type] xlator: dlsym(notify) on /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/xlator/features/access-control.so: undefined symbol: notify -- neglecting
[2010-08-04 01:38:33.115935] D [xlator.c:738:xlator_set_type] xlator: dlsym(dumpops) on /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/xlator/features/access-control.so: undefined symbol: dumpops -- neglecting
[2010-08-04 01:38:33.115953] D [xlator.c:744:xlator_set_type] brick1: dlsym(mem_acct_init) on /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/xlator/features/access-control.so: undefined symbol: mem_acct_init -- neglecting
[2010-08-04 01:38:33.115972] D [xlator.c:758:xlator_set_type] brick1: Strict option validation not enforced -- neglecting
[2010-08-04 01:38:33.115986] T [graph.y:223:volume_type] parser: Type:brick1:features/access-control
[2010-08-04 01:38:33.116002] T [graph.y:348:volume_sub] parser: child:brick1->posix1
[2010-08-04 01:38:33.116016] T [graph.y:365:volume_end] parser: end:brick1
[2010-08-04 01:38:33.116032] T [graph.y:192:new_volume] parser: New node for 'nfsxlator'
[2010-08-04 01:38:33.116048] T [xlator.c:698:xlator_set_type] xlator: attempt to load file /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/xlator/nfs/server.so
[2010-08-04 01:38:33.243137] D [xlator.c:738:xlator_set_type] xlator: dlsym(dumpops) on /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/xlator/nfs/server.so: undefined symbol: dumpops -- neglecting
[2010-08-04 01:38:33.243177] T [graph.y:223:volume_type] parser: Type:nfsxlator:nfs/server
[2010-08-04 01:38:33.243195] T [graph.y:348:volume_sub] parser: child:nfsxlator->brick1
[2010-08-04 01:38:33.243212] T [graph.y:258:volume_option] parser: Option:nfsxlator:rpc-auth.addr.allow:*
[2010-08-04 01:38:33.243228] T [graph.y:365:volume_end] parser: end:nfsxlator
[2010-08-04 01:38:33.243329] D [xlator.c:953:xlator_mem_acct_init] nfsxlator: Allocated mem_acct_rec for 86 types
[2010-08-04 01:38:33.243372] T [rpcsvc-auth.c:117:rpcsvc_auth_init_auth] rpc-service: Authentication enabled: AUTH_GLUSTERFS
[2010-08-04 01:38:33.243388] T [rpcsvc-auth.c:117:rpcsvc_auth_init_auth] rpc-service: Authentication enabled: AUTH_UNIX
[2010-08-04 01:38:33.243402] T [rpcsvc-auth.c:117:rpcsvc_auth_init_auth] rpc-service: Authentication enabled: AUTH_NULL
[2010-08-04 01:38:33.243416] D [rpcsvc.c:2061:rpcsvc_init] rpc-service: RPC service inited.
[2010-08-04 01:38:33.243443] W [rpc-transport.c:878:rpc_transport_load] rpc-transport: missing 'option transport-type'. defaulting to "socket"
[2010-08-04 01:38:33.243464] D [rpc-transport.c:930:rpc_transport_load] rpc-transport: attempt to load file /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/rpc-transport/socket.so
[2010-08-04 01:38:33.278407] D [dict.c:324:dict_get] dict: @this=(nil) @key=0x2aaaacb9e334
[2010-08-04 01:38:33.278429] D [dict.c:324:dict_get] dict: @this=(nil) @key=0x2aaaacb9e35e
[2010-08-04 01:38:33.278450] D [name.c:553:server_fill_address_family] RPC: option address-family not specified, defaulting to inet/inet6
[2010-08-04 01:38:33.278604] T [socket.c:341:__socket_nodelay] : NODELAY enabled for socket 6
[2010-08-04 01:38:33.278659] T [rpcsvc.c:512:rpcsvc_conn_alloc] rpc-service: rx pool: 525
[2010-08-04 01:38:33.279307] D [rpcsvc.c:1917:rpcsvc_program_register] rpc-service: New program registered: GF-DUMP, Num: 123451501, Ver: 1, Port: 0
[2010-08-04 01:38:33.279440] T [nfs.c:344:nfs_init_subvolumes] nfs: inode table lru: 90000
[2010-08-04 01:38:33.279458] D [nfs.c:348:nfs_init_subvolumes] nfs: Initing subvolume: brick1
[2010-08-04 01:38:33.279936] T [nfs.c:368:nfs_init_subvolumes] nfs: Inited volumes: 1
[2010-08-04 01:38:33.279951] D [nfs.c:519:init] nfs: NFS service started
[2010-08-04 01:38:33.279973] D [xlator.c:953:xlator_mem_acct_init] brick1: Allocated mem_acct_rec for 65 types
[2010-08-04 01:38:33.280032] D [xlator.c:953:xlator_mem_acct_init] posix1: Allocated mem_acct_rec for 74 types
[2010-08-04 01:38:33.280136] W [graph.c:120:_log_if_option_is_invalid] nfsxlator: option 'transport-type' is not recognized
[2010-08-04 01:38:33.280154] W [graph.c:120:_log_if_option_is_invalid] nfsxlator: option 'rpc-auth.auth-glusterfs' is not recognized
[2010-08-04 01:38:33.280175] T [nfs.c:535:notify] nfs: Notification received: 1
[2010-08-04 01:38:33.280193] T [nfs.c:535:notify] nfs: Notification received: 5
[2010-08-04 01:38:33.280207] D [nfs.c:211:nfs_subvolume_set_started] nfs: Starting up: brick1 , vols started till now: 1
[2010-08-04 01:38:33.280231] T [nfs-fops.c:279:nfs_fop_lookup] nfs: Lookup: /
[2010-08-04 01:38:33.280281] T [nfs.c:235:nfs_start_subvol_lookup_cbk] nfs: Started brick1
[2010-08-04 01:38:33.280301] T [nfs.c:545:notify] nfs: All children up, starting RPC
[2010-08-04 01:38:33.280315] D [nfs.c:107:nfs_init_versions] nfs: Initing protocol versions
[2010-08-04 01:38:33.280338] D [mount3.c:1477:mnt3svc_init] nfs-mount: Initing Mount v3 state
[2010-08-04 01:38:33.280359] T [mount3.c:1376:__mnt3_init_volume_export] nfs-mount: Volume exports enabled
[2010-08-04 01:38:33.280373] T [mount3.c:1397:mnt3_init_options] nfs-mount: Initing options for: brick1
[2010-08-04 01:38:33.280388] T [mount3.c:1238:mnt3_init_export_ent] nfs-mount: Initing volume export: brick1
[2010-08-04 01:38:33.280403] D [nfs.c:123:nfs_init_versions] nfs: Starting program: MOUNT3
[2010-08-04 01:38:33.280479] T [posix.c:1273:posix_janitor_thread_proc] posix1: janitor cleaning out /.landfill
[2010-08-04 01:38:33.280528] D [rpcsvc.c:1917:rpcsvc_program_register] rpc-service: New program registered: MOUNT3, Num: 100005, Ver: 3, Port: 0
[2010-08-04 01:38:33.280544] D [mount3.c:1521:mnt1svc_init] nfs-mount: Initing Mount v1 state
[2010-08-04 01:38:33.280559] T [mount3.c:1376:__mnt3_init_volume_export] nfs-mount: Volume exports enabled
[2010-08-04 01:38:33.280573] T [mount3.c:1397:mnt3_init_options] nfs-mount: Initing options for: brick1
[2010-08-04 01:38:33.280588] T [mount3.c:1238:mnt3_init_export_ent] nfs-mount: Initing volume export: brick1
[2010-08-04 01:38:33.280602] D [nfs.c:123:nfs_init_versions] nfs: Starting program: MOUNT1
[2010-08-04 01:38:33.280696] D [rpcsvc.c:1917:rpcsvc_program_register] rpc-service: New program registered: MOUNT1, Num: 100005, Ver: 1, Port: 0
[2010-08-04 01:38:33.280718] T [nfs3.c:4959:nfs3_init_state] nfs-nfsv3: local pool: 225
[2010-08-04 01:38:33.280929] T [nfs3.c:4879:nfs3_init_subvolume] nfs-nfsv3: Initing state: brick1
[2010-08-04 01:38:33.280946] T [nfs3.c:4859:nfs3_init_subvolume_options] nfs-nfsv3: brick1: read-write, no trusted_sync, no trusted_write
[2010-08-04 01:38:33.280961] D [nfs.c:123:nfs_init_versions] nfs: Starting program: NFS3
[2010-08-04 01:38:33.281054] D [rpcsvc.c:1917:rpcsvc_program_register] rpc-service: New program registered: NFS3, Num: 100003, Ver: 3, Port: 0
[2010-08-04 01:39:17.768048] D [glusterfsd.c:1052:glusterfs_sigwaiter] sigwaiter: received signal 15
[2010-08-04 01:39:17.768137] N [glusterfsd.c:590:cleanup_and_exit] glusterfsd: shutting down
[2010-08-04 01:39:25.937957] D [glusterfsd.c:297:get_volfp] glusterfsd: loading volume file /opt/users/laks/nfs/854/854.vol
[2010-08-04 01:39:25.941793] T [graph.y:192:new_volume] parser: New node for 'posix1'
[2010-08-04 01:39:25.941819] T [xlator.c:698:xlator_set_type] xlator: attempt to load file /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/xlator/storage/posix.so
[2010-08-04 01:39:26.1436] T [graph.y:223:volume_type] parser: Type:posix1:storage/posix
[2010-08-04 01:39:26.1465] T [graph.y:258:volume_option] parser: Option:posix1:directory:/mnt/laks
[2010-08-04 01:39:26.1481] T [graph.y:365:volume_end] parser: end:posix1
[2010-08-04 01:39:26.1499] T [graph.y:192:new_volume] parser: New node for 'brick1'
[2010-08-04 01:39:26.1515] T [xlator.c:698:xlator_set_type] xlator: attempt to load file /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/xlator/features/access-control.so
[2010-08-04 01:39:26.35011] D [xlator.c:733:xlator_set_type] xlator: dlsym(notify) on /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/xlator/features/access-control.so: undefined symbol: notify -- neglecting
[2010-08-04 01:39:26.35035] D [xlator.c:738:xlator_set_type] xlator: dlsym(dumpops) on /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/xlator/features/access-control.so: undefined symbol: dumpops -- neglecting
[2010-08-04 01:39:26.35054] D [xlator.c:744:xlator_set_type] brick1: dlsym(mem_acct_init) on /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/xlator/features/access-control.so: undefined symbol: mem_acct_init -- neglecting
[2010-08-04 01:39:26.35073] D [xlator.c:758:xlator_set_type] brick1: Strict option validation not enforced -- neglecting
[2010-08-04 01:39:26.35088] T [graph.y:223:volume_type] parser: Type:brick1:features/access-control
[2010-08-04 01:39:26.35103] T [graph.y:348:volume_sub] parser: child:brick1->posix1
[2010-08-04 01:39:26.35118] T [graph.y:365:volume_end] parser: end:brick1
[2010-08-04 01:39:26.35134] T [graph.y:192:new_volume] parser: New node for 'nfsxlator'
[2010-08-04 01:39:26.35150] T [xlator.c:698:xlator_set_type] xlator: attempt to load file /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/xlator/nfs/server.so
[2010-08-04 01:39:26.94406] D [xlator.c:738:xlator_set_type] xlator: dlsym(dumpops) on /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/xlator/nfs/server.so: undefined symbol: dumpops -- neglecting
[2010-08-04 01:39:26.94430] T [graph.y:223:volume_type] parser: Type:nfsxlator:nfs/server
[2010-08-04 01:39:26.94447] T [graph.y:348:volume_sub] parser: child:nfsxlator->brick1
[2010-08-04 01:39:26.94464] T [graph.y:258:volume_option] parser: Option:nfsxlator:rpc-auth.addr.allow:*
[2010-08-04 01:39:26.94480] T [graph.y:365:volume_end] parser: end:nfsxlator
[2010-08-04 01:39:26.94572] D [xlator.c:953:xlator_mem_acct_init] nfsxlator: Allocated mem_acct_rec for 86 types
[2010-08-04 01:39:26.94614] T [rpcsvc-auth.c:117:rpcsvc_auth_init_auth] rpc-service: Authentication enabled: AUTH_GLUSTERFS
[2010-08-04 01:39:26.94630] T [rpcsvc-auth.c:117:rpcsvc_auth_init_auth] rpc-service: Authentication enabled: AUTH_UNIX
[2010-08-04 01:39:26.94644] T [rpcsvc-auth.c:117:rpcsvc_auth_init_auth] rpc-service: Authentication enabled: AUTH_NULL
[2010-08-04 01:39:26.94657] D [rpcsvc.c:2061:rpcsvc_init] rpc-service: RPC service inited.
[2010-08-04 01:39:26.94685] W [rpc-transport.c:878:rpc_transport_load] rpc-transport: missing 'option transport-type'. defaulting to "socket"
[2010-08-04 01:39:26.94705] D [rpc-transport.c:930:rpc_transport_load] rpc-transport: attempt to load file /opt/glusterfs/3.1.0qa3/lib/glusterfs/3.1.0qa3/rpc-transport/socket.so
[2010-08-04 01:39:26.128812] D [dict.c:324:dict_get] dict: @this=(nil) @key=0x2aaaacb9e334
[2010-08-04 01:39:26.128832] D [dict.c:324:dict_get] dict: @this=(nil) @key=0x2aaaacb9e35e
[2010-08-04 01:39:26.128853] D [name.c:553:server_fill_address_family] RPC: option address-family not specified, defaulting to inet/inet6
[2010-08-04 01:39:26.128959] T [socket.c:341:__socket_nodelay] : NODELAY enabled for socket 6
[2010-08-04 01:39:26.129001] T [rpcsvc.c:512:rpcsvc_conn_alloc] rpc-service: rx pool: 525
[2010-08-04 01:39:26.129603] D [rpcsvc.c:1917:rpcsvc_program_register] rpc-service: New program registered: GF-DUMP, Num: 123451501, Ver: 1, Port: 0
[2010-08-04 01:39:26.129736] T [nfs.c:344:nfs_init_subvolumes] nfs: inode table lru: 90000
[2010-08-04 01:39:26.129754] D [nfs.c:348:nfs_init_subvolumes] nfs: Initing subvolume: brick1
[2010-08-04 01:39:26.130234] T [nfs.c:368:nfs_init_subvolumes] nfs: Inited volumes: 1
[2010-08-04 01:39:26.130251] D [nfs.c:519:init] nfs: NFS service started
[2010-08-04 01:39:26.130273] D [xlator.c:953:xlator_mem_acct_init] brick1: Allocated mem_acct_rec for 65 types
[2010-08-04 01:39:26.130323] D [xlator.c:953:xlator_mem_acct_init] posix1: Allocated mem_acct_rec for 74 types
[2010-08-04 01:39:26.130419] W [graph.c:120:_log_if_option_is_invalid] nfsxlator: option 'transport-type' is not recognized
[2010-08-04 01:39:26.130436] W [graph.c:120:_log_if_option_is_invalid] nfsxlator: option 'rpc-auth.auth-glusterfs' is not recognized
[2010-08-04 01:39:26.130457] T [nfs.c:535:notify] nfs: Notification received: 1
[2010-08-04 01:39:26.130474] T [nfs.c:535:notify] nfs: Notification received: 5
[2010-08-04 01:39:26.130488] D [nfs.c:211:nfs_subvolume_set_started] nfs: Starting up: brick1 , vols started till now: 1
[2010-08-04 01:39:26.130509] T [nfs-fops.c:279:nfs_fop_lookup] nfs: Lookup: /
[2010-08-04 01:39:26.130550] T [nfs.c:235:nfs_start_subvol_lookup_cbk] nfs: Started brick1
[2010-08-04 01:39:26.130567] T [nfs.c:545:notify] nfs: All children up, starting RPC
[2010-08-04 01:39:26.130580] D [nfs.c:107:nfs_init_versions] nfs: Initing protocol versions
[2010-08-04 01:39:26.130596] D [mount3.c:1477:mnt3svc_init] nfs-mount: Initing Mount v3 state
[2010-08-04 01:39:26.130616] T [mount3.c:1376:__mnt3_init_volume_export] nfs-mount: Volume exports enabled
[2010-08-04 01:39:26.130630] T [mount3.c:1397:mnt3_init_options] nfs-mount: Initing options for: brick1
[2010-08-04 01:39:26.130645] T [mount3.c:1238:mnt3_init_export_ent] nfs-mount: Initing volume export: brick1
[2010-08-04 01:39:26.130660] D [nfs.c:123:nfs_init_versions] nfs: Starting program: MOUNT3
[2010-08-04 01:39:26.130746] D [rpcsvc.c:1917:rpcsvc_program_register] rpc-service: New program registered: MOUNT3, Num: 100005, Ver: 3, Port: 0
[2010-08-04 01:39:26.130764] D [mount3.c:1521:mnt1svc_init] nfs-mount: Initing Mount v1 state
[2010-08-04 01:39:26.130779] T [mount3.c:1376:__mnt3_init_volume_export] nfs-mount: Volume exports enabled
[2010-08-04 01:39:26.130792] T [mount3.c:1397:mnt3_init_options] nfs-mount: Initing options for: brick1
[2010-08-04 01:39:26.130808] T [mount3.c:1238:mnt3_init_export_ent] nfs-mount: Initing volume export: brick1
[2010-08-04 01:39:26.130822] D [nfs.c:123:nfs_init_versions] nfs: Starting program: MOUNT1
[2010-08-04 01:39:26.130905] D [rpcsvc.c:1917:rpcsvc_program_register] rpc-service: New program registered: MOUNT1, Num: 100005, Ver: 1, Port: 0
[2010-08-04 01:39:26.130926] T [nfs3.c:4959:nfs3_init_state] nfs-nfsv3: local pool: 225
[2010-08-04 01:39:26.131137] T [nfs3.c:4879:nfs3_init_subvolume] nfs-nfsv3: Initing state: brick1
[2010-08-04 01:39:26.131154] T [nfs3.c:4859:nfs3_init_subvolume_options] nfs-nfsv3: brick1: read-write, no trusted_sync, no trusted_write
[2010-08-04 01:39:26.131168] D [nfs.c:123:nfs_init_versions] nfs: Starting program: NFS3
[2010-08-04 01:39:26.131251] D [rpcsvc.c:1917:rpcsvc_program_register] rpc-service: New program registered: NFS3, Num: 100003, Ver: 3, Port: 0
[2010-08-04 01:39:26.131311] T [posix.c:1273:posix_janitor_thread_proc] posix1: janitor cleaning out /.landfill
----------------------

Comment 3 Shehjar Tikoo 2010-08-04 04:06:13 UTC
Confirmed that calls to RPC lib in NFS is going into the rpc lib in rpc-transport.

Comment 4 Anand Avati 2010-08-10 06:44:25 UTC
PATCH: http://patches.gluster.com/patch/4054 in master (nfs, nfs/rpc: Rename functions to prevent gfrpcsvc conflict)

Comment 5 Anand Avati 2010-08-10 06:44:30 UTC
PATCH: http://patches.gluster.com/patch/4050 in master (nfs: Do not build nfs/rpc as shared library)