Attachment 588182 Details for Bug 827172 – client log between mounting volume and crash

client log between mounting volume and crash

gluster-mount-repstr.log (text/x-log), 54.23 KB, created by PL on 2012-05-31 19:47:23 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: PL

Created: 2012-05-31 19:47:23 UTC

Size: 54.23 KB

patch

obsolete

>---------
>[2012-05-31 12:07:59.073966] I [glusterfsd.c:1651:main] 0-/usr/sbin/glusterfs: Started running /usr/sbin/glusterfs version 3.3.0beta4
>[2012-05-31 12:07:59.074426] D [glusterfsd.c:384:create_fuse_mount] 0-: fuse direct io type 2
>[2012-05-31 12:07:59.106104] D [rpc-clnt.c:973:rpc_clnt_connection_init] 0-glusterfs: defaulting frame-timeout to 30mins
>[2012-05-31 12:07:59.106184] D [rpc-transport.c:248:rpc_transport_load] 0-rpc-transport: attempt to load file /usr/lib64/glusterfs/3.3.0beta4/rpc-transport/socket.so
>[2012-05-31 12:07:59.106690] D [rpc-clnt.c:1379:rpcclnt_cbk_program_register] 0-glusterfs: New program registered: GlusterFS Callback, Num: 52743234, Ver: 1
>[2012-05-31 12:07:59.113356] D [common-utils.c:151:gf_resolve_ip6] 0-resolver: returning ip-10.10.10.101 (port-24007) for hostname: GLUSTER-SERVER-1 and port: 24007
>[2012-05-31 12:07:59.117411] D [io-stats.c:2533:init] 0-datastore: dangling volume. check volfile 
>[2012-05-31 12:07:59.117451] D [options.c:1042:xlator_option_init_bool] 0-datastore: option count-fop-hits using set value off
>[2012-05-31 12:07:59.117469] D [options.c:1042:xlator_option_init_bool] 0-datastore: option latency-measurement using set value off
>[2012-05-31 12:07:59.117583] I [io-cache.c:1549:check_cache_size_ok] 0-datastore-quick-read: Max cache size is 1073741824
>[2012-05-31 12:07:59.117660] I [io-cache.c:1549:check_cache_size_ok] 0-datastore-io-cache: Max cache size is 1073741824
>[2012-05-31 12:07:59.122167] D [client.c:2315:client_init_grace_timer] 0-datastore-client-3: lk-heal = off
>[2012-05-31 12:07:59.122211] D [client.c:2326:client_init_grace_timer] 0-datastore-client-3: Client grace timeout value = 10
>[2012-05-31 12:07:59.122234] D [options.c:1044:xlator_option_init_path] 0-datastore-client-3: option remote-subvolume using set value /brick/datastore
>[2012-05-31 12:07:59.123505] D [rpc-clnt.c:973:rpc_clnt_connection_init] 0-datastore-client-3: defaulting frame-timeout to 30mins
>[2012-05-31 12:07:59.123531] D [rpc-transport.c:248:rpc_transport_load] 0-rpc-transport: attempt to load file /usr/lib64/glusterfs/3.3.0beta4/rpc-transport/socket.so
>[2012-05-31 12:07:59.123577] D [rpc-clnt.c:1379:rpcclnt_cbk_program_register] 0-datastore-client-3: New program registered: GlusterFS Callback, Num: 52743234, Ver: 1
>[2012-05-31 12:07:59.123633] D [client.c:2290:client_init_rpc] 0-datastore-client-3: client init successful
>[2012-05-31 12:07:59.123650] D [client.c:2315:client_init_grace_timer] 0-datastore-client-2: lk-heal = off
>[2012-05-31 12:07:59.123665] D [client.c:2326:client_init_grace_timer] 0-datastore-client-2: Client grace timeout value = 10
>[2012-05-31 12:07:59.123684] D [options.c:1044:xlator_option_init_path] 0-datastore-client-2: option remote-subvolume using set value /brick/datastore
>[2012-05-31 12:07:59.125002] D [rpc-clnt.c:973:rpc_clnt_connection_init] 0-datastore-client-2: defaulting frame-timeout to 30mins
>[2012-05-31 12:07:59.125023] D [rpc-transport.c:248:rpc_transport_load] 0-rpc-transport: attempt to load file /usr/lib64/glusterfs/3.3.0beta4/rpc-transport/socket.so
>[2012-05-31 12:07:59.125050] D [rpc-clnt.c:1379:rpcclnt_cbk_program_register] 0-datastore-client-2: New program registered: GlusterFS Callback, Num: 52743234, Ver: 1
>[2012-05-31 12:07:59.125066] D [client.c:2290:client_init_rpc] 0-datastore-client-2: client init successful
>[2012-05-31 12:07:59.125082] D [client.c:2315:client_init_grace_timer] 0-datastore-client-1: lk-heal = off
>[2012-05-31 12:07:59.125097] D [client.c:2326:client_init_grace_timer] 0-datastore-client-1: Client grace timeout value = 10
>[2012-05-31 12:07:59.125115] D [options.c:1044:xlator_option_init_path] 0-datastore-client-1: option remote-subvolume using set value /brick/datastore
>[2012-05-31 12:07:59.126442] D [rpc-clnt.c:973:rpc_clnt_connection_init] 0-datastore-client-1: defaulting frame-timeout to 30mins
>[2012-05-31 12:07:59.126463] D [rpc-transport.c:248:rpc_transport_load] 0-rpc-transport: attempt to load file /usr/lib64/glusterfs/3.3.0beta4/rpc-transport/socket.so
>[2012-05-31 12:07:59.126495] D [rpc-clnt.c:1379:rpcclnt_cbk_program_register] 0-datastore-client-1: New program registered: GlusterFS Callback, Num: 52743234, Ver: 1
>[2012-05-31 12:07:59.126511] D [client.c:2290:client_init_rpc] 0-datastore-client-1: client init successful
>[2012-05-31 12:07:59.126527] D [client.c:2315:client_init_grace_timer] 0-datastore-client-0: lk-heal = off
>[2012-05-31 12:07:59.126542] D [client.c:2326:client_init_grace_timer] 0-datastore-client-0: Client grace timeout value = 10
>[2012-05-31 12:07:59.126561] D [options.c:1044:xlator_option_init_path] 0-datastore-client-0: option remote-subvolume using set value /brick/datastore
>[2012-05-31 12:07:59.127884] D [rpc-clnt.c:973:rpc_clnt_connection_init] 0-datastore-client-0: defaulting frame-timeout to 30mins
>[2012-05-31 12:07:59.127904] D [rpc-transport.c:248:rpc_transport_load] 0-rpc-transport: attempt to load file /usr/lib64/glusterfs/3.3.0beta4/rpc-transport/socket.so
>[2012-05-31 12:07:59.127930] D [rpc-clnt.c:1379:rpcclnt_cbk_program_register] 0-datastore-client-0: New program registered: GlusterFS Callback, Num: 52743234, Ver: 1
>[2012-05-31 12:07:59.127946] D [client.c:2290:client_init_rpc] 0-datastore-client-0: client init successful
>[2012-05-31 12:07:59.127980] D [fuse-bridge.c:4156:notify] 0-fuse: got event 12 on graph 0
>[2012-05-31 12:07:59.128021] I [client.c:2142:notify] 0-datastore-client-0: parent translators are ready, attempting connect on transport
>[2012-05-31 12:07:59.128041] D [name.c:149:client_fill_address_family] 0-datastore-client-0: address-family not specified, guessing it to be inet/inet6
>[2012-05-31 12:07:59.131832] D [common-utils.c:151:gf_resolve_ip6] 0-resolver: returning ip-10.10.10.101 (port-24007) for hostname: GLUSTER-SERVER-1 and port: 24007
>[2012-05-31 12:07:59.131970] I [client.c:2142:notify] 0-datastore-client-1: parent translators are ready, attempting connect on transport
>[2012-05-31 12:07:59.131990] D [name.c:149:client_fill_address_family] 0-datastore-client-1: address-family not specified, guessing it to be inet/inet6
>[2012-05-31 12:07:59.135550] D [common-utils.c:151:gf_resolve_ip6] 0-resolver: returning ip-10.10.10.102 (port-24007) for hostname: GLUSTER-SERVER-2 and port: 24007
>[2012-05-31 12:07:59.135665] I [client.c:2142:notify] 0-datastore-client-2: parent translators are ready, attempting connect on transport
>[2012-05-31 12:07:59.135703] D [name.c:149:client_fill_address_family] 0-datastore-client-2: address-family not specified, guessing it to be inet/inet6
>[2012-05-31 12:07:59.139503] D [common-utils.c:151:gf_resolve_ip6] 0-resolver: returning ip-10.10.10.103 (port-24007) for hostname: GLUSTER-SERVER-3 and port: 24007
>[2012-05-31 12:07:59.139612] I [client.c:2142:notify] 0-datastore-client-3: parent translators are ready, attempting connect on transport
>[2012-05-31 12:07:59.139630] D [name.c:149:client_fill_address_family] 0-datastore-client-3: address-family not specified, guessing it to be inet/inet6
>[2012-05-31 12:07:59.143236] D [common-utils.c:151:gf_resolve_ip6] 0-resolver: returning ip-10.10.10.104 (port-24007) for hostname: GLUSTER-SERVER-4 and port: 24007
>Given volfile:
>+------------------------------------------------------------------------------+
>  1: volume datastore-client-0
>  2:     type protocol/client
>  3:     option remote-host GLUSTER-SERVER-1
>  4:     option remote-subvolume /brick/datastore
>  5:     option transport-type tcp
>  6: end-volume
>  7: 
>  8: volume datastore-client-1
>  9:     type protocol/client
> 10:     option remote-host GLUSTER-SERVER-2
> 11:     option remote-subvolume /brick/datastore
> 12:     option transport-type tcp
> 13: end-volume
> 14: 
> 15: volume datastore-client-2
> 16:     type protocol/client
> 17:     option remote-host GLUSTER-SERVER-3
> 18:     option remote-subvolume /brick/datastore
> 19:     option transport-type tcp
> 20: end-volume
> 21: 
> 22: volume datastore-client-3
> 23:     type protocol/client
> 24:     option remote-host GLUSTER-SERVER-4
> 25:     option remote-subvolume /brick/datastore
> 26:     option transport-type tcp
> 27: end-volume
> 28: 
> 29: volume datastore-replicate-0
> 30:     type cluster/replicate
> 31:     subvolumes datastore-client-0 datastore-client-1
> 32: end-volume
> 33: 
> 34: volume datastore-replicate-1
> 35:     type cluster/replicate
> 36:     subvolumes datastore-client-2 datastore-client-3
> 37: end-volume
> 38: 
> 39: volume datastore-stripe-0
> 40:     type cluster/stripe
> 41:     subvolumes datastore-replicate-0 datastore-replicate-1
> 42: end-volume
> 43: 
> 44: volume datastore-write-behind
> 45:     type performance/write-behind
> 46:     subvolumes datastore-stripe-0
> 47: end-volume
> 48: 
> 49: volume datastore-read-ahead
> 50:     type performance/read-ahead
> 51:     subvolumes datastore-write-behind
> 52: end-volume
> 53: 
> 54: volume datastore-io-cache
> 55:     type performance/io-cache
> 56:     subvolumes datastore-read-ahead
> 57: end-volume
> 58: 
> 59: volume datastore-quick-read
> 60:     type performance/quick-read
> 61:     subvolumes datastore-io-cache
> 62: end-volume
> 63: 
> 64: volume datastore-md-cache
> 65:     type performance/md-cache
> 66:     subvolumes datastore-quick-read
> 67: end-volume
> 68: 
> 69: volume datastore
> 70:     type debug/io-stats
> 71:     option latency-measurement off
> 72:     option count-fop-hits off
> 73:     subvolumes datastore-md-cache
> 74: end-volume
>
>+------------------------------------------------------------------------------+
>[2012-05-31 12:07:59.143471] D [glusterfsd-mgmt.c:2050:glusterfs_mgmt_pmap_signin] 0-fsd-mgmt: portmapper signin arguments not given
>[2012-05-31 12:07:59.143536] D [client.c:2043:client_rpc_notify] 0-datastore-client-2: got RPC_CLNT_CONNECT
>[2012-05-31 12:07:59.143612] D [client-handshake.c:184:client_start_ping] 0-datastore-client-2: returning as transport is already disconnected OR there are no frames (1 || 1)
>[2012-05-31 12:07:59.143650] D [client.c:2043:client_rpc_notify] 0-datastore-client-1: got RPC_CLNT_CONNECT
>[2012-05-31 12:07:59.143692] D [client-handshake.c:184:client_start_ping] 0-datastore-client-1: returning as transport is already disconnected OR there are no frames (1 || 1)
>[2012-05-31 12:07:59.143723] D [client.c:2043:client_rpc_notify] 0-datastore-client-0: got RPC_CLNT_CONNECT
>[2012-05-31 12:07:59.143764] D [client-handshake.c:184:client_start_ping] 0-datastore-client-0: returning as transport is already disconnected OR there are no frames (1 || 1)
>[2012-05-31 12:07:59.143912] D [client.c:2043:client_rpc_notify] 0-datastore-client-3: got RPC_CLNT_CONNECT
>[2012-05-31 12:07:59.143966] D [client-handshake.c:184:client_start_ping] 0-datastore-client-3: returning as transport is already disconnected OR there are no frames (1 || 1)
>[2012-05-31 12:07:59.144066] D [client-handshake.c:1662:server_has_portmap] 0-datastore-client-2: detected portmapper on server
>[2012-05-31 12:07:59.144116] D [client-handshake.c:184:client_start_ping] 0-datastore-client-2: returning as transport is already disconnected OR there are no frames (1 || 1)
>[2012-05-31 12:07:59.144165] D [client-handshake.c:1662:server_has_portmap] 0-datastore-client-0: detected portmapper on server
>[2012-05-31 12:07:59.144200] D [client-handshake.c:184:client_start_ping] 0-datastore-client-0: returning as transport is already disconnected OR there are no frames (1 || 1)
>[2012-05-31 12:07:59.144237] D [client-handshake.c:1662:server_has_portmap] 0-datastore-client-1: detected portmapper on server
>[2012-05-31 12:07:59.144270] D [client-handshake.c:184:client_start_ping] 0-datastore-client-1: returning as transport is already disconnected OR there are no frames (1 || 1)
>[2012-05-31 12:07:59.144367] I [rpc-clnt.c:1660:rpc_clnt_reconfig] 0-datastore-client-2: changing port to 24009 (from 0)
>[2012-05-31 12:07:59.144423] D [client-handshake.c:1662:server_has_portmap] 0-datastore-client-3: detected portmapper on server
>[2012-05-31 12:07:59.144471] D [client-handshake.c:184:client_start_ping] 0-datastore-client-3: returning as transport is already disconnected OR there are no frames (1 || 1)
>[2012-05-31 12:07:59.144506] D [socket.c:184:__socket_rwv] 0-datastore-client-2: EOF from peer 10.10.10.103:24007
>[2012-05-31 12:07:59.144540] D [socket.c:1512:__socket_proto_state_machine] 0-datastore-client-2: reading from socket failed. Error (Transport endpoint is not connected), peer (10.10.10.103:24007)
>[2012-05-31 12:07:59.144563] D [socket.c:1798:socket_event_handler] 0-transport: disconnecting now
>[2012-05-31 12:07:59.144592] D [client.c:2108:client_rpc_notify] 0-datastore-client-2: disconnected (skipped notify)
>[2012-05-31 12:07:59.144622] I [rpc-clnt.c:1660:rpc_clnt_reconfig] 0-datastore-client-1: changing port to 24010 (from 0)
>[2012-05-31 12:07:59.144696] I [rpc-clnt.c:1660:rpc_clnt_reconfig] 0-datastore-client-0: changing port to 24010 (from 0)
>[2012-05-31 12:07:59.144736] I [rpc-clnt.c:1660:rpc_clnt_reconfig] 0-datastore-client-3: changing port to 24009 (from 0)
>[2012-05-31 12:07:59.144768] D [socket.c:184:__socket_rwv] 0-datastore-client-0: EOF from peer 10.10.10.101:24007
>[2012-05-31 12:07:59.144786] D [socket.c:1512:__socket_proto_state_machine] 0-datastore-client-0: reading from socket failed. Error (Transport endpoint is not connected), peer (10.10.10.101:24007)
>[2012-05-31 12:07:59.144805] D [socket.c:1798:socket_event_handler] 0-transport: disconnecting now
>[2012-05-31 12:07:59.144829] D [client.c:2108:client_rpc_notify] 0-datastore-client-0: disconnected (skipped notify)
>[2012-05-31 12:07:59.144853] D [socket.c:184:__socket_rwv] 0-datastore-client-1: EOF from peer 10.10.10.102:24007
>[2012-05-31 12:07:59.144870] D [socket.c:1512:__socket_proto_state_machine] 0-datastore-client-1: reading from socket failed. Error (Transport endpoint is not connected), peer (10.10.10.102:24007)
>[2012-05-31 12:07:59.144900] D [socket.c:1798:socket_event_handler] 0-transport: disconnecting now
>[2012-05-31 12:07:59.144943] D [client.c:2108:client_rpc_notify] 0-datastore-client-1: disconnected (skipped notify)
>[2012-05-31 12:07:59.144968] D [socket.c:184:__socket_rwv] 0-datastore-client-3: EOF from peer 10.10.10.104:24007
>[2012-05-31 12:07:59.144985] D [socket.c:1512:__socket_proto_state_machine] 0-datastore-client-3: reading from socket failed. Error (Transport endpoint is not connected), peer (10.10.10.104:24007)
>[2012-05-31 12:07:59.145017] D [socket.c:1798:socket_event_handler] 0-transport: disconnecting now
>[2012-05-31 12:07:59.145044] D [client.c:2108:client_rpc_notify] 0-datastore-client-3: disconnected (skipped notify)
>[2012-05-31 12:08:03.116831] D [name.c:149:client_fill_address_family] 0-datastore-client-2: address-family not specified, guessing it to be inet/inet6
>[2012-05-31 12:08:03.121178] D [common-utils.c:151:gf_resolve_ip6] 0-resolver: returning ip-10.10.10.103 (port-24007) for hostname: GLUSTER-SERVER-3 and port: 24007
>[2012-05-31 12:08:03.121385] D [name.c:149:client_fill_address_family] 0-datastore-client-1: address-family not specified, guessing it to be inet/inet6
>[2012-05-31 12:08:03.121928] D [client.c:2043:client_rpc_notify] 0-datastore-client-2: got RPC_CLNT_CONNECT
>[2012-05-31 12:08:03.122023] D [client-handshake.c:184:client_start_ping] 0-datastore-client-2: returning as transport is already disconnected OR there are no frames (1 || 1)
>[2012-05-31 12:08:03.122377] I [client-handshake.c:1628:select_server_supported_programs] 0-datastore-client-2: Using Program GlusterFS 3.3.0beta4, Num (1298437), Version (330)
>[2012-05-31 12:08:03.122439] D [client-handshake.c:184:client_start_ping] 0-datastore-client-2: returning as transport is already disconnected OR there are no frames (1 || 1)
>[2012-05-31 12:08:03.125301] D [common-utils.c:151:gf_resolve_ip6] 0-resolver: returning ip-10.10.10.102 (port-24007) for hostname: GLUSTER-SERVER-2 and port: 24007
>[2012-05-31 12:08:03.125458] D [name.c:149:client_fill_address_family] 0-datastore-client-0: address-family not specified, guessing it to be inet/inet6
>[2012-05-31 12:08:03.125641] D [client-handshake.c:1399:client_setvolume_cbk] 0-datastore-client-2: clnt-lk-version = 1, server-lk-version = 0
>[2012-05-31 12:08:03.125660] I [client-handshake.c:1425:client_setvolume_cbk] 0-datastore-client-2: Connected to 10.10.10.103:24009, attached to remote volume '/brick/datastore'.
>[2012-05-31 12:08:03.125682] I [client-handshake.c:1437:client_setvolume_cbk] 0-datastore-client-2: Server and Client lk-version numbers are not same, reopening the fds
>[2012-05-31 12:08:03.125702] D [client-handshake.c:1287:client_post_handshake] 0-datastore-client-2: No fds to open - notifying all parents child up
>[2012-05-31 12:08:03.125717] D [client-handshake.c:477:client_set_lk_version] 0-datastore-client-2: Sending SET_LK_VERSION
>[2012-05-31 12:08:03.125775] I [afr-common.c:3620:afr_notify] 0-datastore-replicate-1: Subvolume 'datastore-client-2' came back up; going online.
>[2012-05-31 12:08:03.125889] D [client.c:2043:client_rpc_notify] 0-datastore-client-1: got RPC_CLNT_CONNECT
>[2012-05-31 12:08:03.125932] D [client-handshake.c:184:client_start_ping] 0-datastore-client-1: returning as transport is already disconnected OR there are no frames (1 || 1)
>[2012-05-31 12:08:03.126061] I [client-handshake.c:453:client_set_lk_version_cbk] 0-datastore-client-2: Server lk version = 1
>[2012-05-31 12:08:03.126245] I [client-handshake.c:1628:select_server_supported_programs] 0-datastore-client-1: Using Program GlusterFS 3.3.0beta4, Num (1298437), Version (330)
>[2012-05-31 12:08:03.126308] D [client-handshake.c:184:client_start_ping] 0-datastore-client-1: returning as transport is already disconnected OR there are no frames (1 || 1)
>[2012-05-31 12:08:03.127096] D [client-handshake.c:1399:client_setvolume_cbk] 0-datastore-client-1: clnt-lk-version = 1, server-lk-version = 0
>[2012-05-31 12:08:03.127115] I [client-handshake.c:1425:client_setvolume_cbk] 0-datastore-client-1: Connected to 10.10.10.102:24010, attached to remote volume '/brick/datastore'.
>[2012-05-31 12:08:03.127132] I [client-handshake.c:1437:client_setvolume_cbk] 0-datastore-client-1: Server and Client lk-version numbers are not same, reopening the fds
>[2012-05-31 12:08:03.127149] D [client-handshake.c:1287:client_post_handshake] 0-datastore-client-1: No fds to open - notifying all parents child up
>[2012-05-31 12:08:03.127164] D [client-handshake.c:477:client_set_lk_version] 0-datastore-client-1: Sending SET_LK_VERSION
>[2012-05-31 12:08:03.127217] I [afr-common.c:3620:afr_notify] 0-datastore-replicate-0: Subvolume 'datastore-client-1' came back up; going online.
>[2012-05-31 12:08:03.127496] I [client-handshake.c:453:client_set_lk_version_cbk] 0-datastore-client-1: Server lk version = 1
>[2012-05-31 12:08:03.129453] D [common-utils.c:151:gf_resolve_ip6] 0-resolver: returning ip-10.10.10.101 (port-24007) for hostname: GLUSTER-SERVER-1 and port: 24007
>[2012-05-31 12:08:03.129586] D [name.c:149:client_fill_address_family] 0-datastore-client-3: address-family not specified, guessing it to be inet/inet6
>[2012-05-31 12:08:03.130024] D [client.c:2043:client_rpc_notify] 0-datastore-client-0: got RPC_CLNT_CONNECT
>[2012-05-31 12:08:03.130071] D [client-handshake.c:184:client_start_ping] 0-datastore-client-0: returning as transport is already disconnected OR there are no frames (1 || 1)
>[2012-05-31 12:08:03.130400] I [client-handshake.c:1628:select_server_supported_programs] 0-datastore-client-0: Using Program GlusterFS 3.3.0beta4, Num (1298437), Version (330)
>[2012-05-31 12:08:03.130456] D [client-handshake.c:184:client_start_ping] 0-datastore-client-0: returning as transport is already disconnected OR there are no frames (1 || 1)
>[2012-05-31 12:08:03.130942] D [client-handshake.c:1399:client_setvolume_cbk] 0-datastore-client-0: clnt-lk-version = 1, server-lk-version = 0
>[2012-05-31 12:08:03.130961] I [client-handshake.c:1425:client_setvolume_cbk] 0-datastore-client-0: Connected to 10.10.10.101:24010, attached to remote volume '/brick/datastore'.
>[2012-05-31 12:08:03.130977] I [client-handshake.c:1437:client_setvolume_cbk] 0-datastore-client-0: Server and Client lk-version numbers are not same, reopening the fds
>[2012-05-31 12:08:03.130993] D [client-handshake.c:1287:client_post_handshake] 0-datastore-client-0: No fds to open - notifying all parents child up
>[2012-05-31 12:08:03.131008] D [client-handshake.c:477:client_set_lk_version] 0-datastore-client-0: Sending SET_LK_VERSION
>[2012-05-31 12:08:03.131337] I [client-handshake.c:453:client_set_lk_version_cbk] 0-datastore-client-0: Server lk version = 1
>[2012-05-31 12:08:03.133413] D [common-utils.c:151:gf_resolve_ip6] 0-resolver: returning ip-10.10.10.104 (port-24007) for hostname: GLUSTER-SERVER-4 and port: 24007
>[2012-05-31 12:08:03.133964] D [client.c:2043:client_rpc_notify] 0-datastore-client-3: got RPC_CLNT_CONNECT
>[2012-05-31 12:08:03.134009] D [client-handshake.c:184:client_start_ping] 0-datastore-client-3: returning as transport is already disconnected OR there are no frames (1 || 1)
>[2012-05-31 12:08:03.134436] I [client-handshake.c:1628:select_server_supported_programs] 0-datastore-client-3: Using Program GlusterFS 3.3.0beta4, Num (1298437), Version (330)
>[2012-05-31 12:08:03.134491] D [client-handshake.c:184:client_start_ping] 0-datastore-client-3: returning as transport is already disconnected OR there are no frames (1 || 1)
>[2012-05-31 12:08:03.134999] D [client-handshake.c:1399:client_setvolume_cbk] 0-datastore-client-3: clnt-lk-version = 1, server-lk-version = 0
>[2012-05-31 12:08:03.135017] I [client-handshake.c:1425:client_setvolume_cbk] 0-datastore-client-3: Connected to 10.10.10.104:24009, attached to remote volume '/brick/datastore'.
>[2012-05-31 12:08:03.135033] I [client-handshake.c:1437:client_setvolume_cbk] 0-datastore-client-3: Server and Client lk-version numbers are not same, reopening the fds
>[2012-05-31 12:08:03.135048] D [client-handshake.c:1287:client_post_handshake] 0-datastore-client-3: No fds to open - notifying all parents child up
>[2012-05-31 12:08:03.135063] D [client-handshake.c:477:client_set_lk_version] 0-datastore-client-3: Sending SET_LK_VERSION
>[2012-05-31 12:08:03.135118] D [fuse-bridge.c:4156:notify] 0-fuse: got event 5 on graph 0
>[2012-05-31 12:08:03.144823] I [fuse-bridge.c:4138:fuse_graph_setup] 0-fuse: switched to graph 0
>[2012-05-31 12:08:03.145031] I [client-handshake.c:453:client_set_lk_version_cbk] 0-datastore-client-3: Server lk version = 1
>[2012-05-31 12:08:03.145172] I [fuse-bridge.c:3376:fuse_init] 0-glusterfs-fuse: FUSE inited with protocol versions: glusterfs 7.13 kernel 7.10
>[2012-05-31 12:08:03.146018] I [afr-common.c:1962:afr_set_root_inode_on_first_lookup] 0-datastore-replicate-0: added root inode
>[2012-05-31 12:08:03.146118] I [afr-common.c:1962:afr_set_root_inode_on_first_lookup] 0-datastore-replicate-1: added root inode
>[2012-05-31 12:08:03.146203] D [afr-self-heal-common.c:139:afr_sh_print_pending_matrix] 0-datastore-replicate-1: pending_matrix: [ 0 0 ]
>[2012-05-31 12:08:03.146225] D [afr-self-heal-common.c:139:afr_sh_print_pending_matrix] 0-datastore-replicate-1: pending_matrix: [ 0 0 ]
>[2012-05-31 12:08:03.146241] D [afr-self-heal-common.c:744:afr_mark_sources] 0-datastore-replicate-1: Number of sources: 0
>[2012-05-31 12:08:03.146258] D [afr-self-heal-data.c:833:afr_lookup_select_read_child_by_txn_type] 0-datastore-replicate-1: returning read_child: 1
>[2012-05-31 12:08:03.146274] D [afr-common.c:1292:afr_lookup_select_read_child] 0-datastore-replicate-1: Source selected as 1 for /
>[2012-05-31 12:08:03.146300] D [afr-common.c:1094:afr_lookup_build_response_params] 0-datastore-replicate-1: Building lookup response from 1
>[2012-05-31 12:08:03.146367] D [afr-self-heal-common.c:139:afr_sh_print_pending_matrix] 0-datastore-replicate-0: pending_matrix: [ 0 0 ]
>[2012-05-31 12:08:03.146385] D [afr-self-heal-common.c:139:afr_sh_print_pending_matrix] 0-datastore-replicate-0: pending_matrix: [ 0 0 ]
>[2012-05-31 12:08:03.146400] D [afr-self-heal-common.c:744:afr_mark_sources] 0-datastore-replicate-0: Number of sources: 0
>[2012-05-31 12:08:03.146415] D [afr-self-heal-data.c:833:afr_lookup_select_read_child_by_txn_type] 0-datastore-replicate-0: returning read_child: 1
>[2012-05-31 12:08:03.146430] D [afr-common.c:1292:afr_lookup_select_read_child] 0-datastore-replicate-0: Source selected as 1 for /
>[2012-05-31 12:08:03.146446] D [afr-common.c:1094:afr_lookup_build_response_params] 0-datastore-replicate-0: Building lookup response from 1
>[2012-05-31 12:08:23.154092] D [afr-self-heal-common.c:139:afr_sh_print_pending_matrix] 0-datastore-replicate-0: pending_matrix: [ 0 0 ]
>[2012-05-31 12:08:23.154149] D [afr-self-heal-common.c:139:afr_sh_print_pending_matrix] 0-datastore-replicate-0: pending_matrix: [ 0 0 ]
>[2012-05-31 12:08:23.154167] D [afr-self-heal-common.c:744:afr_mark_sources] 0-datastore-replicate-0: Number of sources: 0
>[2012-05-31 12:08:23.154185] D [afr-self-heal-data.c:833:afr_lookup_select_read_child_by_txn_type] 0-datastore-replicate-0: returning read_child: 1
>[2012-05-31 12:08:23.154201] D [afr-common.c:1292:afr_lookup_select_read_child] 0-datastore-replicate-0: Source selected as 1 for /
>[2012-05-31 12:08:23.154220] D [afr-common.c:1094:afr_lookup_build_response_params] 0-datastore-replicate-0: Building lookup response from 1
>[2012-05-31 12:08:23.154281] D [afr-self-heal-common.c:139:afr_sh_print_pending_matrix] 0-datastore-replicate-1: pending_matrix: [ 0 0 ]
>[2012-05-31 12:08:23.154299] D [afr-self-heal-common.c:139:afr_sh_print_pending_matrix] 0-datastore-replicate-1: pending_matrix: [ 0 0 ]
>[2012-05-31 12:08:23.154315] D [afr-self-heal-common.c:744:afr_mark_sources] 0-datastore-replicate-1: Number of sources: 0
>[2012-05-31 12:08:23.154330] D [afr-self-heal-data.c:833:afr_lookup_select_read_child_by_txn_type] 0-datastore-replicate-1: returning read_child: 1
>[2012-05-31 12:08:23.154346] D [afr-common.c:1292:afr_lookup_select_read_child] 0-datastore-replicate-1: Source selected as 1 for /
>[2012-05-31 12:08:23.154362] D [afr-common.c:1094:afr_lookup_build_response_params] 0-datastore-replicate-1: Building lookup response from 1
>[2012-05-31 12:08:23.155242] D [afr-self-heal-common.c:139:afr_sh_print_pending_matrix] 0-datastore-replicate-0: pending_matrix: [ 0 0 ]
>[2012-05-31 12:08:23.155263] D [afr-self-heal-common.c:139:afr_sh_print_pending_matrix] 0-datastore-replicate-0: pending_matrix: [ 0 0 ]
>[2012-05-31 12:08:23.155280] D [afr-self-heal-common.c:744:afr_mark_sources] 0-datastore-replicate-0: Number of sources: 0
>[2012-05-31 12:08:23.155296] D [afr-self-heal-data.c:833:afr_lookup_select_read_child_by_txn_type] 0-datastore-replicate-0: returning read_child: 0
>[2012-05-31 12:08:23.155311] D [afr-common.c:1292:afr_lookup_select_read_child] 0-datastore-replicate-0: Source selected as 0 for /PPPP
>[2012-05-31 12:08:23.155328] D [afr-common.c:1094:afr_lookup_build_response_params] 0-datastore-replicate-0: Building lookup response from 0
>[2012-05-31 12:08:23.155447] D [afr-self-heal-common.c:139:afr_sh_print_pending_matrix] 0-datastore-replicate-1: pending_matrix: [ 0 0 ]
>[2012-05-31 12:08:23.155466] D [afr-self-heal-common.c:139:afr_sh_print_pending_matrix] 0-datastore-replicate-1: pending_matrix: [ 0 0 ]
>[2012-05-31 12:08:23.155482] D [afr-self-heal-common.c:744:afr_mark_sources] 0-datastore-replicate-1: Number of sources: 0
>[2012-05-31 12:08:23.155497] D [afr-self-heal-data.c:833:afr_lookup_select_read_child_by_txn_type] 0-datastore-replicate-1: returning read_child: 0
>[2012-05-31 12:08:23.155512] D [afr-common.c:1292:afr_lookup_select_read_child] 0-datastore-replicate-1: Source selected as 0 for /PPPP
>[2012-05-31 12:08:23.155529] D [afr-common.c:1094:afr_lookup_build_response_params] 0-datastore-replicate-1: Building lookup response from 0
>[2012-05-31 12:08:23.156213] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.156325] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.156767] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.157112] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.157335] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.157472] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.157510] D [afr-transaction.c:1019:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks failed. Proceeding to blocking
>[2012-05-31 12:08:23.158258] D [afr-lk-common.c:1021:afr_lock_blocking] 0-datastore-replicate-1: we're done locking
>[2012-05-31 12:08:23.158278] D [afr-transaction.c:999:afr_post_blocking_inodelk_cbk] 0-datastore-replicate-1: Blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.180947] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.181160] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.182630] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.188958] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.189070] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.189206] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.189299] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.189420] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.189517] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.189627] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.189725] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.189853] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.189947] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.204782] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.204957] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.205187] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.206015] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.212168] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.212249] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.212353] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.212452] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.212577] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.212680] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.212787] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.212886] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.213017] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.213106] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.213207] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.213985] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.214065] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.214412] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.232429] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.232665] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.232741] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.232862] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.234334] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.235359] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.235473] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.235651] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.235743] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.235890] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.235972] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.236070] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.236195] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.236328] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.236411] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.236529] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.236630] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.237140] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.256561] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.256654] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.256841] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.256916] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.257948] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.258954] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.259090] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.259243] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.259347] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.259475] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.259558] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.259671] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.259739] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.259862] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.259946] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.260072] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.260154] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.260642] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.275294] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.275469] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.281241] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.281468] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.281767] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.282775] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.282869] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.283054] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.283148] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.283241] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.283395] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.283477] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.283571] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.283649] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.283768] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.283902] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.284000] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.284537] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.301704] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.301830] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.301957] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.302174] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.306262] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.306394] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.306482] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.306577] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.306703] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.306815] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.306908] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.307016] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.307107] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.307232] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.307324] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.308173] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.308246] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.309069] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.323818] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.326001] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.328257] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.328417] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.329317] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:23.329438] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.329517] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.329683] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:23.329754] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.329911] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.329999] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.330097] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.330207] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.330305] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.330425] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.330510] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:23.330642] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>.
>.--------------
>.SNIPPED
>.--------------
>.
>[2012-05-31 12:08:25.279549] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:25.300802] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:25.300957] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:25.301829] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:25.301955] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:25.302046] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:25.302135] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:25.302321] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:25.302416] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:25.302523] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:25.302616] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:25.302714] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:25.302811] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:25.302926] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:25.303027] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:25.303143] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:25.303231] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:25.303365] D [afr-transaction.c:1026:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:25.303493] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:25.325014] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:25.325167] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:25.325290] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:25.325373] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:25.325488] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:25.325580] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:25.325706] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:25.325794] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:25.325812] D [afr-transaction.c:1019:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-0: Non blocking inodelks failed. Proceeding to blocking
>[2012-05-31 12:08:25.325914] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:25.326007] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:25.326037] D [afr-transaction.c:1019:afr_post_nonblocking_inodelk_cbk] 0-datastore-replicate-1: Non blocking inodelks failed. Proceeding to blocking
>[2012-05-31 12:08:25.326115] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:25.327633] D [afr-lk-common.c:1021:afr_lock_blocking] 0-datastore-replicate-1: we're done locking
>[2012-05-31 12:08:25.327655] D [afr-transaction.c:999:afr_post_blocking_inodelk_cbk] 0-datastore-replicate-1: Blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:25.328047] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-1: lk op is for a transaction
>[2012-05-31 12:08:25.328128] D [afr-lk-common.c:1021:afr_lock_blocking] 0-datastore-replicate-0: we're done locking
>[2012-05-31 12:08:25.328147] D [afr-transaction.c:999:afr_post_blocking_inodelk_cbk] 0-datastore-replicate-0: Blocking inodelks done. Proceeding to FOP
>[2012-05-31 12:08:25.328512] D [afr-lk-common.c:400:transaction_lk_op] 0-datastore-replicate-0: lk op is for a transaction
>[2012-05-31 12:08:25.328873] D [client3_1-fops.c:2790:client_fdctx_destroy] 0-datastore-client-0: sending release on fd
>[2012-05-31 12:08:25.328913] D [client3_1-fops.c:2790:client_fdctx_destroy] 0-datastore-client-1: sending release on fd
>[2012-05-31 12:08:25.328954] D [client3_1-fops.c:2790:client_fdctx_destroy] 0-datastore-client-2: sending release on fd
>[2012-05-31 12:08:25.328995] D [client3_1-fops.c:2790:client_fdctx_destroy] 0-datastore-client-3: sending release on fd
>[2012-05-31 12:08:33.642494] D [afr-self-heal-common.c:139:afr_sh_print_pending_matrix] 0-datastore-replicate-0: pending_matrix: [ 0 0 ]
>[2012-05-31 12:08:33.642539] D [afr-self-heal-common.c:139:afr_sh_print_pending_matrix] 0-datastore-replicate-0: pending_matrix: [ 0 0 ]
>[2012-05-31 12:08:33.642557] D [afr-self-heal-common.c:744:afr_mark_sources] 0-datastore-replicate-0: Number of sources: 0
>[2012-05-31 12:08:33.642574] D [afr-self-heal-data.c:833:afr_lookup_select_read_child_by_txn_type] 0-datastore-replicate-0: returning read_child: 1
>[2012-05-31 12:08:33.642589] D [afr-common.c:1292:afr_lookup_select_read_child] 0-datastore-replicate-0: Source selected as 1 for /
>[2012-05-31 12:08:33.642608] D [afr-common.c:1094:afr_lookup_build_response_params] 0-datastore-replicate-0: Building lookup response from 1
>[2012-05-31 12:08:33.642666] D [afr-self-heal-common.c:139:afr_sh_print_pending_matrix] 0-datastore-replicate-1: pending_matrix: [ 0 0 ]
>[2012-05-31 12:08:33.642684] D [afr-self-heal-common.c:139:afr_sh_print_pending_matrix] 0-datastore-replicate-1: pending_matrix: [ 0 0 ]
>[2012-05-31 12:08:33.642699] D [afr-self-heal-common.c:744:afr_mark_sources] 0-datastore-replicate-1: Number of sources: 0
>[2012-05-31 12:08:33.642713] D [afr-self-heal-data.c:833:afr_lookup_select_read_child_by_txn_type] 0-datastore-replicate-1: returning read_child: 1
>[2012-05-31 12:08:33.642728] D [afr-common.c:1292:afr_lookup_select_read_child] 0-datastore-replicate-1: Source selected as 1 for /
>[2012-05-31 12:08:33.642744] D [afr-common.c:1094:afr_lookup_build_response_params] 0-datastore-replicate-1: Building lookup response from 1
>[2012-05-31 12:08:33.644649] D [afr-dir-read.c:126:afr_examine_dir_readdir_cbk] 0-datastore-replicate-1: /: no entries found in datastore-client-2
>[2012-05-31 12:08:33.644684] D [afr-dir-read.c:126:afr_examine_dir_readdir_cbk] 0-datastore-replicate-1: /: no entries found in datastore-client-3
>[2012-05-31 12:08:33.644749] D [afr-dir-read.c:126:afr_examine_dir_readdir_cbk] 0-datastore-replicate-0: /: no entries found in datastore-client-1
>[2012-05-31 12:08:33.644779] D [afr-dir-read.c:126:afr_examine_dir_readdir_cbk] 0-datastore-replicate-0: /: no entries found in datastore-client-0
>[2012-05-31 12:08:33.644899] D [afr-common.c:701:afr_get_call_child] 0-datastore-replicate-0: Returning 0, call_child: 1, last_index: -1
>pending frames:
>frame : type(1) op(READDIR)
>frame : type(1) op(READDIR)
>frame : type(1) op(READDIR)
>
>patchset: git://git.gluster.com/glusterfs.git
>signal received: 11
>time of crash: 2012-05-31 12:08:33
>configuration details:
>argp 1
>backtrace 1
>dlfcn 1
>fdatasync 1
>libpthread 1
>llistxattr 1
>setfsid 1
>spinlock 1
>epoll.h 1
>xattr.h 1
>st_atim.tv_nsec 1
>package-string: glusterfs 3.3.0beta4
>/lib64/libc.so.6[0x36e20302d0]
>/usr/lib64/glusterfs/3.3.0beta4/xlator/cluster/replicate.so(afr_lookup+0xa5)[0x2aaaab36bac5]
>/usr/lib64/glusterfs/3.3.0beta4/xlator/cluster/stripe.so(stripe_readdirp_cbk+0x536)[0x2aaaab593346]
>/usr/lib64/glusterfs/3.3.0beta4/xlator/cluster/replicate.so(afr_readdirp_cbk+0x1ca)[0x2aaaab32769a]
>/usr/lib64/glusterfs/3.3.0beta4/xlator/protocol/client.so(client3_1_readdirp_cbk+0x170)[0x2aaaab0f5be0]
>/usr/lib64/libgfrpc.so.0(rpc_clnt_handle_reply+0xa2)[0x39ec80f302]
>/usr/lib64/libgfrpc.so.0(rpc_clnt_notify+0xb6)[0x39ec80f516]
>/usr/lib64/libgfrpc.so.0(rpc_transport_notify+0x27)[0x39ec80ae17]
>/usr/lib64/glusterfs/3.3.0beta4/rpc-transport/socket.so(socket_event_poll_in+0x3f)[0x2aaaaaab6c8f]
>/usr/lib64/glusterfs/3.3.0beta4/rpc-transport/socket.so(socket_event_handler+0x188)[0x2aaaaaab6e38]
>/usr/lib64/libglusterfs.so.0[0x39ec03eb51]
>/usr/sbin/glusterfs(main+0x502)[0x406612]
>/lib64/libc.so.6(__libc_start_main+0xf4)[0x36e201d994]
>/usr/sbin/glusterfs[0x404399]
>---------

Actions: View

Attachments on bug 827172: 588182