Hi All,
I'm noticing that a iozone sanity check fails on the latest cvs code
with 2.6.16 (fedora core 4). I think the server is crashing. I'm doing
this all on one node. This works successfully with 1.5.1.
In /var/log/messages:
Jul 18 13:19:22 foufoune kernel: pvfs2_permission: inode: e4225e10 mask
= 1 mode = 43ff current->fsuid = 0 inode->i_uid = 0, inode->i_gid = 0
ret = 0
Jul 18 13:19:22 foufoune kernel: pvfs2_permission: mode [43ff] & mask
[1] & S_IRWXO [7] = 1 == mask [1]?
Jul 18 13:19:22 foufoune kernel: pvfs2_permission: inode: e4225e10 mask
= 1 mode = 43ff current->fsuid = 0 inode->i_uid = 0, inode->i_gid = 0
ret = 0
Jul 18 13:19:22 foufoune kernel: pvfs2_permission: mode [43ff] & mask
[1] & S_IRWXO [7] = 1 == mask [1]?
Jul 18 13:19:22 foufoune kernel: pvfs2_lookup called on a2
Jul 18 13:19:22 foufoune kernel: Alloced OP (e02543a0: 121 OP_LOOKUP)
Jul 18 13:19:22 foufoune kernel: pvfs2_lookup: doing lookup on a2
Jul 18 13:19:22 foufoune kernel: under 1048576,408205455 (follow=no)
Jul 18 13:19:22 foufoune kernel: pvfs2: service_operation: pvfs2_lookup
e02543a0
Jul 18 13:19:22 foufoune kernel: client-core: reading op tag 121 OP_LOOKUP
Jul 18 13:19:22 foufoune kernel: (get) Alloced OP (e02543a0:121)
Jul 18 13:19:22 foufoune kernel: pvfs2: service_operation pvfs2_lookup
returning: -2 for e02543a0.
Jul 18 13:19:22 foufoune kernel: Lookup Got 0, fsid 0 (ret=-2)
Jul 18 13:19:22 foufoune kernel: pvfs2_lookup: Adding *negative* dentry
e4d28914Jul 18 13:19:22 foufoune kernel: for a2
Jul 18 13:19:22 foufoune kernel: Releasing OP (e02543a0: 121)
Jul 18 13:19:22 foufoune kernel: pvfs2_permission: inode: e4225e10 mask
= 3 mode = 43ff current->fsuid = 0 inode->i_uid = 0, inode->i_gid = 0
ret = 0
Jul 18 13:19:22 foufoune kernel: pvfs2_create: called
Jul 18 13:19:22 foufoune kernel: Alloced OP (e02543a0: 122 OP_CREATE)
Jul 18 13:19:22 foufoune kernel: pvfs2: service_operation:
pvfs2_create_file e02543a0
Jul 18 13:19:22 foufoune kernel: client-core: reading op tag 122 OP_CREATE
Jul 18 13:19:22 foufoune kernel: (get) Alloced OP (e02543a0:122)
Jul 18 13:19:22 foufoune kernel: pvfs2: service_operation
pvfs2_create_file returning: 0 for e02543a0.
Jul 18 13:19:22 foufoune kernel: Create Got PVFS2 handle 1048573 on fsid
408205455 (ret=0)
Jul 18 13:19:22 foufoune kernel: pvfs2_get_custom_inode: called
Jul 18 13:19:22 foufoune kernel: (sb is f6e98600 | MAJOR(dev)=0 |
MINOR(dev)=0)
Jul 18 13:19:22 foufoune kernel: pvfs2_alloc_inode: allocated e42251f4
Jul 18 13:19:22 foufoune kernel: pvfs2_read_inode: e42251f4 (inode =
1048573 | ct = 1)
Jul 18 13:19:22 foufoune kernel: pvfs2_inode_getattr: called on inode
1048573
Jul 18 13:19:22 foufoune kernel: Alloced OP (e0260420: 123 OP_GETATTR)
Jul 18 13:19:22 foufoune kernel: pvfs2: service_operation:
pvfs2_inode_getattr e0260420
Jul 18 13:19:22 foufoune kernel: client-core: reading op tag 123 OP_GETATTR
Jul 18 13:19:22 foufoune kernel: (get) Alloced OP (e0260420:123)
Jul 18 13:19:22 foufoune kernel: pvfs2: service_operation
pvfs2_inode_getattr returning: 0 for e0260420.
Jul 18 13:19:22 foufoune kernel: attrs->mask = 710007f (1048576, objtype
= 1), size = 0
Jul 18 13:19:22 foufoune kernel: pvfs2: copy_attributes_to_inode:
setting inode->i_mode to 8000 from 0
Jul 18 13:19:22 foufoune kernel: Getattr on handle 1048573, fsid 408205455
Jul 18 13:19:22 foufoune kernel: (inode ct = 1) returned 0
Jul 18 13:19:22 foufoune kernel: Releasing OP (e0260420: 123)
Jul 18 13:19:22 foufoune kernel: pvfs2_get_custom_inode: inode e4225224
allocated
Jul 18 13:19:22 foufoune kernel: (pvfs2_inode is e42251f4 | sb is
f6e98600)
Jul 18 13:19:22 foufoune kernel: Assigned file inode new number of 1048573
Jul 18 13:19:22 foufoune kernel: pvfs2_create_file: Instantiating
Jul 18 13:19:22 foufoune kernel: *negative* dentry e4d28914 for a2
Jul 18 13:19:22 foufoune kernel: Releasing OP (e02543a0: 122)
Jul 18 13:19:22 foufoune kernel: pvfs2_create: returning 0
Jul 18 13:19:22 foufoune kernel: pvfs2_permission: inode: e4225224 mask
= 0 mode = 8000 current->fsuid = 0 inode->i_uid = 0, inode->i_gid = 0
ret = 0
Jul 18 13:19:22 foufoune kernel: pvfs2_permission: mode [8000] & mask
[0] & S_IRWXO [7] = 0 == mask [0]?
Jul 18 13:19:22 foufoune kernel: pvfs2_file_open: called on a2 (inode is
1048573)
Jul 18 13:19:22 foufoune kernel: pvfs2_file_open returning normally: 0
Jul 18 13:19:22 foufoune kernel: pvfs2_setattr: called on a2
Jul 18 13:19:22 foufoune kernel: pvfs2: pvfs2_truncate called on inode
1048573 with size 0
Jul 18 13:19:22 foufoune kernel: pvfs2: pvfs2_truncate_inode 1048573:
Handle is 1048573 | fs_id 408205455 | size is 0
Jul 18 13:19:22 foufoune kernel: Alloced OP (e02543a0: 124 OP_TRUNCATE)
Jul 18 13:19:22 foufoune kernel: pvfs2: service_operation:
pvfs2_truncate_inode e02543a0
Jul 18 13:19:22 foufoune kernel: client-core: reading op tag 124 OP_TRUNCATE
Jul 18 13:19:32 foufoune kernel: (get) Alloced OP (e02543a0:124)
Jul 18 13:19:32 foufoune kernel: pvfs2: service_operation
pvfs2_truncate_inode returning: -111 for e02543a0.
Jul 18 13:19:32 foufoune kernel: pvfs2: pvfs2_truncate got return value
of -111
Jul 18 13:19:32 foufoune kernel: Releasing OP (e02543a0: 124)
Jul 18 13:19:32 foufoune kernel: pvfs2_setattr: inode_setattr returned 0
Jul 18 13:19:32 foufoune kernel: Alloced OP (e02543a0: 125 OP_SETATTR)
Jul 18 13:19:32 foufoune kernel: mode is 32768 | translated perms is 0
Jul 18 13:19:32 foufoune kernel: pvfs2: service_operation:
pvfs2_inode_setattr e02543a0
Jul 18 13:19:32 foufoune kernel: client-core: reading op tag 125 OP_SETATTR
Jul 18 13:19:42 foufoune kernel: (get) Alloced OP (e02543a0:125)
Jul 18 13:19:42 foufoune kernel: pvfs2: service_operation
pvfs2_inode_setattr returning: -111 for e02543a0.
Jul 18 13:19:42 foufoune kernel: pvfs2_inode_setattr: returning -111
Jul 18 13:19:42 foufoune kernel: Releasing OP (e02543a0: 125)
Jul 18 13:19:42 foufoune kernel: pvfs2_setattr: returning -111
Jul 18 13:19:42 foufoune kernel: pvfs2_file_release: called on a2
I attached the /tmp/pvfs2-client.log:
I didn't have logging on the server, but there isn't any errors in the
server log.
The code that fails (from iozone.c) is below. I just ran 'iozone -aec
-i 0 -i 1 -+n -f /mnt/pvfs2/a2'
/* Sanity check */
/* Some filesystems do not behave correctly and fail
* when this sequence is performned. This is a very
* bad thing. It breaks many applications and lurks
* around quietly. This code should never get
* triggered, but in the case of running iozone on
* an NFS client, the filesystem type on the server
* that is being exported can cause this failure.
* If this failure happens, then the NFS client is
* going to going to have problems, but the acutal
* problem is the filesystem on the NFS server.
* It's not NFS, it's the local filesystem on the
* NFS server that is not correctly permitting
* the sequence to function.
*/
if((fd = I_OPEN(filename, (int)O_CREAT|O_WRONLY,0))<0)
{
printf("\nCan not open temp file: %s\n",
filename);
perror("open");
exit(44);
}
wval=ftruncate(fd,0);
if(wval < 0)
{
printf("Sanity check failed. Do not deploy this
filesystem in a production environment !\n");
exit(44);
}
close(fd);
unlink(filename);
/* Sanity check */
--
Dean Hildebrand
Ph.D. Candidate
University of Michigan
[D 13:19:22.562960] [+] dev req msg: sz: 644,tag: 121,data: 0x80d7720,type: 0
[D 13:19:22.563032] [*] handling new unexp vfs_request 0x81c8978
[D 13:19:22.563062] is_op_in_progress called on tag 121
[D 13:19:22.563099] Got a lookup request for a2 (fsid 408205455 | parent
1048576)
[D 13:19:22.563130] PVFS_isys_ref_lookup entered
[D 13:19:22.563181] initialize_context called
[D 13:19:22.563217] original pathname is: a2
[D 13:19:22.563246] cur_seg_name[0]: a2
[D 13:19:22.563275] pathname is: a2
[D 13:19:22.563304] *seg_remaining is: a2
[D 13:19:22.563332] lookup got: a2 (parent 1048576)
[D 13:19:22.563400] lookup state: lookup_init
[D 13:19:22.563426] lookup state: lookup_segment_lookup_setup_msgpair
[D 13:19:22.563451] Looking up segment a2 under handle 1048576
[D 13:19:22.563486] lookup_ncache state: lookup
[D 13:19:22.563516] *** ncache clean miss on a2.
[D 13:19:22.563546] (0x81cafa8) msgpairarray state: init (1 msgpair(s))
[D 13:19:22.563577] msgpairarray_post: sm 0x81cafa8 2 total message(s) with 2
incomplete
[D 13:19:22.563617] msgpairarray_post: sm 0x81cafa8 msgpair 0: posting recv
[D 13:19:22.563653] BMI_post_recv: addr: 140, offset: 0x80d7c50, size: 8224
[D 13:19:22.563719] msgpairarray_post: sm 0x81cafa8 msgpair 0: posting send
[D 13:19:22.563750] BMI_post_sendunexpected_list: addr: 140, count: 1,
total_size: 52
[D 13:19:22.563776] element 0: offset: 0x80d6a80, size: 52
[D 13:19:22.563845] BMI_tcp_post_send_generic: Sent: 52 bytes of data.
[D 13:19:22.563879] Posted PVFS_SYS_LOOKUP (waiting for test)
[D 13:19:22.566494] tcp_do_work_recv: Reading header for new op.
[D 13:19:22.566589] tcp_do_work_recv: Received new message; mode: 4.
[D 13:19:22.566624] tcp_do_work_recv: tag: 24
[D 13:19:22.566684] BMI_testcontext completing: 321
[D 13:19:22.566741] msgpairarray_complete: sm 0x81cafa8 status_user_tag 0
msgarray_count 1
[D 13:19:22.566789] msgpairarray: all operations complete
[D 13:19:22.566821] (0x81cafa8) msgpairarray state: completion_fn
[D 13:19:22.566848] lookup_segment_lookup_comp_fn
[D 13:19:22.566876] msgpairarray_completion_fn: sm 0x81cafa8 msgpair 0 marked
complete
[D 13:19:22.566903] lookup state: lookup_segment_lookup_failure
[D 13:19:22.566928] lookup state: lookup_cleanup
[D 13:19:22.566972] Freeing segment a2
[D 13:19:22.567013] Freeing remaining segment a2
[D 13:19:22.567055] All contexts finalized
[D 13:19:22.567084] Lookup failed to resolve a2: No such file or directory
[D 13:19:22.567135] PINT_sys_testsome returned completed vfs_request 0x81c8978
[D 13:19:22.567216] downcall write returned 1
[D 13:19:22.567273] [-] reposted unexp req [0x81c8978] due to normal completion
[D 13:19:22.567590] [+] dev req msg: sz: 644,tag: 122,data: 0x80d7720,type: 0
[D 13:19:22.567639] [*] handling new unexp vfs_request 0x81d4410
[D 13:19:22.567674] is_op_in_progress called on tag 122
[D 13:19:22.567719] Got a create request for a2 (fsid 408205455 | parent
1048576)
[D 13:19:22.567752] PVFS_isys_create entered
[D 13:19:22.567827] Creating file a2 under 1048576, 408205455
[D 13:19:22.567871] create state: init
[D 13:19:22.567909] getattr_acache_lookup: handle 1048576 fsid 408205455
[D 13:19:22.567947] acache: get_cached_entry(): H=1048576
[D 13:19:22.567983] acache: miss: H=1048576
[D 13:19:22.568010] acache: clean acache miss: [1048576]
[D 13:19:22.568035] (0x81d6a40) getattr_setup_msgpair
[D 13:19:22.568064] (0x81d6a40) msgpairarray state: init (1 msgpair(s))
[D 13:19:22.568089] msgpairarray_post: sm 0x81d6a40 2 total message(s) with 2
incomplete
[D 13:19:22.568125] msgpairarray_post: sm 0x81d6a40 msgpair 0: posting recv
[D 13:19:22.568157] BMI_post_recv: addr: 140, offset: 0x80d7c50, size: 9280
[D 13:19:22.568223] msgpairarray_post: sm 0x81d6a40 msgpair 0: posting send
[D 13:19:22.568256] BMI_post_sendunexpected_list: addr: 140, count: 1,
total_size: 40
[D 13:19:22.568285] element 0: offset: 0x80d68e0, size: 40
[D 13:19:22.568353] BMI_tcp_post_send_generic: Sent: 40 bytes of data.
[D 13:19:22.568387] Posted PVFS_SYS_CREATE (waiting for test)
[D 13:19:22.568747] tcp_do_work_recv: Reading header for new op.
[D 13:19:22.568802] tcp_do_work_recv: Received new message; mode: 4.
[D 13:19:22.568829] tcp_do_work_recv: tag: 25
[D 13:19:22.568869] BMI_testcontext completing: 327
[D 13:19:22.568907] msgpairarray_complete: sm 0x81d6a40 status_user_tag 0
msgarray_count 1
[D 13:19:22.568933] msgpairarray: all operations complete
[D 13:19:22.568960] (0x81d6a40) msgpairarray state: completion_fn
[D 13:19:22.568992] getattr_object_getattr_comp_fn called
[D 13:19:22.569020] getattr comp_fn [0x81d6a80] dfile_count = 0 dist_name_len =
0 dist_params_len = 0
[D 13:19:22.569054] msgpairarray_completion_fn: sm 0x81d6a40 msgpair 0 marked
complete
[D 13:19:22.569123] acache: update(): H=1048576
[D 13:19:22.569155] acache: update(): attr_status=0, size_status=-1073741858
[D 13:19:22.569195] acache: update(): return=0
[D 13:19:22.569224] trying to add object reference to acache
[D 13:19:22.569253] (0x81d6a40) getattr state: getattr_cleanup
[D 13:19:22.569294] create state: parent_getattr_inspect
[D 13:19:22.569356] parent owner: 0, group: 0, perms: 511
[D 13:19:22.569386] create_parent_getattr: [0x81d6a80] dfile_count = 0
dist_name_len = 0 dist_params_len = 0
[D 13:19:22.569414] Setting number of datafiles to 1 [requested 0]
[D 13:19:22.569441] create state: dspace_create_setup_msgpair
[D 13:19:22.569465] need to create 1 datafiles
[D 13:19:22.569489] create: posting create req
[D 13:19:22.569519] (0x81d6a40) msgpairarray state: init (1 msgpair(s))
[D 13:19:22.569544] msgpairarray_post: sm 0x81d6a40 2 total message(s) with 2
incomplete
[D 13:19:22.569585] msgpairarray_post: sm 0x81d6a40 msgpair 0: posting recv
[D 13:19:22.569617] BMI_post_recv: addr: 140, offset: 0x80d6a40, size: 24
[D 13:19:22.569682] msgpairarray_post: sm 0x81d6a40 msgpair 0: posting send
[D 13:19:22.569714] BMI_post_sendunexpected_list: addr: 140, count: 1,
total_size: 56
[D 13:19:22.569742] element 0: offset: 0x80d7c50, size: 56
[D 13:19:22.569805] BMI_tcp_post_send_generic: Sent: 56 bytes of data.
[D 13:19:22.578335] tcp_do_work_recv: Reading header for new op.
[D 13:19:22.578423] tcp_do_work_recv: Received new message; mode: 4.
[D 13:19:22.578457] tcp_do_work_recv: tag: 26
[D 13:19:22.578495] BMI_testcontext completing: 330
[D 13:19:22.578526] msgpairarray_complete: sm 0x81d6a40 status_user_tag 0
msgarray_count 1
[D 13:19:22.578546] msgpairarray: all operations complete
[D 13:19:22.578564] (0x81d6a40) msgpairarray state: completion_fn
[D 13:19:22.578583] create_create_comp_fn
[D 13:19:22.578601] *** Got newly created handle 1048573
[D 13:19:22.578622] msgpairarray_completion_fn: sm 0x81d6a40 msgpair 0 marked
complete
[D 13:19:22.578641] create state: datafiles_setup_msgpair_array
[D 13:19:22.578666] posting datafile[0] create with extents
4294967298-8589934591
[D 13:19:22.578687] (0x81d6a40) msgpairarray state: init (1 msgpair(s))
[D 13:19:22.578705] msgpairarray_post: sm 0x81d6a40 2 total message(s) with 2
incomplete
[D 13:19:22.578728] msgpairarray_post: sm 0x81d6a40 msgpair 0: posting recv
[D 13:19:22.578749] BMI_post_recv: addr: 140, offset: 0x80d6a40, size: 24
[D 13:19:22.578791] msgpairarray_post: sm 0x81d6a40 msgpair 0: posting send
[D 13:19:22.578812] BMI_post_sendunexpected_list: addr: 140, count: 1,
total_size: 56
[D 13:19:22.578831] element 0: offset: 0x80d7c50, size: 56
[D 13:19:22.578881] BMI_tcp_post_send_generic: Sent: 56 bytes of data.
[D 13:19:22.579750] tcp_do_work_recv: Reading header for new op.
[D 13:19:22.579893] tcp_do_work_recv: Received new message; mode: 4.
[D 13:19:22.579923] tcp_do_work_recv: tag: 27
[D 13:19:22.579955] BMI_testcontext completing: 333
[D 13:19:22.579984] msgpairarray_complete: sm 0x81d6a40 status_user_tag 0
msgarray_count 1
[D 13:19:22.580004] msgpairarray: all operations complete
[D 13:19:22.580023] (0x81d6a40) msgpairarray state: completion_fn
[D 13:19:22.580042] create_datafiles_comp_fn[0]
[D 13:19:22.580060] Datafile handle 0 is 8589934590
[D 13:19:22.580081] msgpairarray_completion_fn: sm 0x81d6a40 msgpair 0 marked
complete
[D 13:19:22.580100] create state: setattr_setup_msgpair
[D 13:19:22.580117] create: posting setattr req
[D 13:19:22.580141] (0x81d6a40) msgpairarray state: init (1 msgpair(s))
[D 13:19:22.580167] msgpairarray_post: sm 0x81d6a40 2 total message(s) with 2
incomplete
[D 13:19:22.580193] msgpairarray_post: sm 0x81d6a40 msgpair 0: posting recv
[D 13:19:22.580213] BMI_post_recv: addr: 140, offset: 0x80d6a40, size: 16
[D 13:19:22.580257] msgpairarray_post: sm 0x81d6a40 msgpair 0: posting send
[D 13:19:22.580278] BMI_post_sendunexpected_list: addr: 140, count: 1,
total_size: 144
[D 13:19:22.580296] element 0: offset: 0x80d7c50, size: 144
[D 13:19:22.580337] BMI_tcp_post_send_generic: Sent: 144 bytes of data.
[D 13:19:22.587355] tcp_do_work_recv: Reading header for new op.
[D 13:19:22.587412] tcp_do_work_recv: Received new message; mode: 4.
[D 13:19:22.587431] tcp_do_work_recv: tag: 28
[D 13:19:22.587461] BMI_testcontext completing: 336
[D 13:19:22.587491] msgpairarray_complete: sm 0x81d6a40 status_user_tag 0
msgarray_count 1
[D 13:19:22.587511] msgpairarray: all operations complete
[D 13:19:22.587529] (0x81d6a40) msgpairarray state: completion_fn
[D 13:19:22.587548] create_setattr_comp_fn
[D 13:19:22.587566] acache: update(): H=1048573
[D 13:19:22.587587] acache: update(): attr_status=0, size_status=0
[D 13:19:22.587611] acache: update(): return=0
[D 13:19:22.587631] msgpairarray_completion_fn: sm 0x81d6a40 msgpair 0 marked
complete
[D 13:19:22.587650] create state: crdirent_setup_msgpair
[D 13:19:22.587668] create: posting crdirent req
[D 13:19:22.587690] (0x81d6a40) msgpairarray state: init (1 msgpair(s))
[D 13:19:22.587709] msgpairarray_post: sm 0x81d6a40 2 total message(s) with 2
incomplete
[D 13:19:22.587732] msgpairarray_post: sm 0x81d6a40 msgpair 0: posting recv
[D 13:19:22.587752] BMI_post_recv: addr: 140, offset: 0x80d6a40, size: 16
[D 13:19:22.587796] msgpairarray_post: sm 0x81d6a40 msgpair 0: posting send
[D 13:19:22.587816] BMI_post_sendunexpected_list: addr: 140, count: 1,
total_size: 80
[D 13:19:22.587834] element 0: offset: 0x80d6a80, size: 80
[D 13:19:22.587875] BMI_tcp_post_send_generic: Sent: 80 bytes of data.
[D 13:19:22.588594] tcp_do_work_recv: Reading header for new op.
[D 13:19:22.588643] tcp_do_work_recv: Received new message; mode: 4.
[D 13:19:22.588662] tcp_do_work_recv: tag: 29
[D 13:19:22.588690] BMI_testcontext completing: 339
[D 13:19:22.588717] msgpairarray_complete: sm 0x81d6a40 status_user_tag 0
msgarray_count 1
[D 13:19:22.588737] msgpairarray: all operations complete
[D 13:19:22.588755] (0x81d6a40) msgpairarray state: completion_fn
[D 13:19:22.588774] create_crdirent_comp_fn
[D 13:19:22.588794] msgpairarray_completion_fn: sm 0x81d6a40 msgpair 0 marked
complete
[D 13:19:22.588813] create state: cleanup
[D 13:19:22.588844] PINT_sys_testsome returned completed vfs_request 0x81d4410
[D 13:19:22.588892] downcall write returned 1
[D 13:19:22.588947] [-] reposted unexp req [0x81d4410] due to normal completion
[D 13:19:22.589003] [+] dev req msg: sz: 644,tag: 123,data: 0x80d7720,type: 0
[D 13:19:22.589023] [*] handling new unexp vfs_request 0x81dfea8
[D 13:19:22.589041] is_op_in_progress called on tag 123
[D 13:19:22.589063] got a getattr request for fsid 408205455 | handle 1048573
[D 13:19:22.589082] PVFS_isys_getattr entered
[D 13:19:22.589123] attrmask being passed to server: [D 13:19:22.589143] mask =
0xc8c00:
[D 13:19:22.589160] PVFS_ATTR_META_DIST
[D 13:19:22.589177] PVFS_ATTR_META_DFILES
[D 13:19:22.589194] PVFS_ATTR_DATA_SIZE
[D 13:19:22.589213] getattr_acache_lookup: handle 1048573 fsid 408205455
[D 13:19:22.589232] acache: get_cached_entry(): H=1048573
[D 13:19:22.589254] acache: status=0, attr_status=0, size_status=0
[D 13:19:22.589272] acache: copying out attr.
[D 13:19:22.589323] acache: copying out size.
[D 13:19:22.589350] acache: hit: H=1048573, size_status=0, attr_status=0
[D 13:19:22.589382] acache: acache hit [1048573]
[D 13:19:22.589414] (0x81e24d8) getattr state: getattr_cleanup
[D 13:19:22.589443] Posted PVFS_SYS_GETATTR (immediate completion)
[D 13:19:22.589487] PINT_sys_testsome returned completed vfs_request 0x81dfea8
[D 13:19:22.589518] object type = 1
[D 13:19:22.589572] downcall write returned 1
[D 13:19:22.589621] [-] reposted unexp req [0x81dfea8] due to normal completion
[D 13:19:22.589723] [+] dev req msg: sz: 644,tag: 124,data: 0x80d7720,type: 0
[D 13:19:22.589747] [*] handling new unexp vfs_request 0x81eb940
[D 13:19:22.589764] is_op_in_progress called on tag 124
[D 13:19:22.589787] Got a truncate request for 1048573 under fsid 408205455 to
be size 0
[D 13:19:22.589806] PVFS_isys_truncate entered with 0
[D 13:19:22.589849] getattr_acache_lookup: handle 1048573 fsid 408205455
[D 13:19:22.589870] acache: get_cached_entry(): H=1048573
[D 13:19:22.589930] acache: status=0, attr_status=0, size_status=0
[D 13:19:22.589948] acache: copying out attr.
[D 13:19:22.589967] acache: copying out size.
[D 13:19:22.589984] acache: hit: H=1048573, size_status=0, attr_status=0
[D 13:19:22.590004] acache: acache hit [1048573]
[D 13:19:22.590022] (0x81edf70) getattr state: getattr_cleanup
[D 13:19:22.590040] (0x81edf70) truncate state: datafile_setup_msgpairarray
[D 13:19:22.590058] datafile_truncate: client requests 0: resizing
8589934590[D 13:19:22.590078] to 0 bytes
[D 13:19:22.590100] mapped handle 8589934590 to server 140
[D 13:19:22.590119] (0x81edf70) msgpairarray state: init (1 msgpair(s))
[D 13:19:22.590137] msgpairarray_post: sm 0x81edf70 2 total message(s) with 2
incomplete
[D 13:19:22.590160] msgpairarray_post: sm 0x81edf70 msgpair 0: posting recv
[D 13:19:22.590180] BMI_post_recv: addr: 140, offset: 0x81bce80, size: 16
[D 13:19:22.590228] msgpairarray_post: sm 0x81edf70 msgpair 0: posting send
[D 13:19:22.590248] BMI_post_sendunexpected_list: addr: 140, count: 1,
total_size: 52
[D 13:19:22.590266] element 0: offset: 0x80d6a28, size: 52
[D 13:19:22.590322] BMI_tcp_post_send_generic: Sent: 52 bytes of data.
[D 13:19:22.590353] Posted PVFS_SYS_TRUNCATE (waiting for test)
[D 13:19:22.597325] BMI_testcontext completing: 348
[D 13:19:22.597382] msgpairarray_complete: sm 0x81edf70 status_user_tag 0
msgarray_count 1
[D 13:19:22.597402] msgpairarray: all operations complete
[D 13:19:22.597420] (0x81edf70) msgpairarray state: completion_fn
[E 13:19:22.597448] msgpair failed, will retry: Broken pipe
[D 13:19:22.597467] *** msgpairarray_completion_fn: msgpair 0 failed, retry 1
[D 13:19:22.597485] msgpairarray_post_retry: sm 0x81edf70, wait 2000 ms
[D 13:19:24.601542] msgpairarray_post: sm 0x81edf70 2 total message(s) with 2
incomplete
[D 13:19:24.601600] msgpairarray_post: sm 0x81edf70 msgpair 0: posting recv
[D 13:19:24.601621] BMI_post_recv: addr: 140, offset: 0x81bce80, size: 16
[D 13:19:24.601666] msgpairarray_post: sm 0x81edf70 msgpair 0: posting send
[D 13:19:24.601688] BMI_post_sendunexpected_list: addr: 140, count: 1,
total_size: 52
[D 13:19:24.601706] element 0: offset: 0x80d6a28, size: 52
[D 13:19:24.601726] tcp_sock_init: attempting reconnect.
[D 13:19:24.601748] Default socket buffers send:-1 receive:-1
[D 13:19:24.601766] Setting socket buffer size for send:0 receive:0
[D 13:19:24.601786] Reread socket buffers send:-1 receive:-1
[D 13:19:24.601824] Default socket buffers send:16384 receive:87380
[D 13:19:24.601843] Setting socket buffer size for send:0 receive:0
[D 13:19:24.601863] Reread socket buffers send:16384 receive:87380
[D 13:19:24.601881] tcp_sock_init: Connect: socket=7,
hostname=foufoune.citi.umich.edu, port=3334
[D 13:19:24.602037] Error: bmi_tcp: Connection refused
[D 13:19:24.605521] BMI_testcontext completing: 356
[D 13:19:24.605542] BMI_testcontext completing: 354
[D 13:19:24.605568] msgpairarray_complete: sm 0x81edf70 status_user_tag 1
msgarray_count 1
[D 13:19:24.605588] msgpairarray_complete: sm 0x81edf70 status_user_tag 0
msgarray_count 1
[D 13:19:24.605606] msgpairarray: all operations complete
[D 13:19:24.605624] (0x81edf70) msgpairarray state: completion_fn
[E 13:19:24.605645] msgpair failed, will retry: Connection refused
[D 13:19:24.605663] *** msgpairarray_completion_fn: msgpair 0 failed, retry 2
[D 13:19:24.605682] msgpairarray_post_retry: sm 0x81edf70, wait 2000 ms
[D 13:19:26.609745] msgpairarray_post: sm 0x81edf70 2 total message(s) with 2
incomplete
[D 13:19:26.609810] msgpairarray_post: sm 0x81edf70 msgpair 0: posting recv
[D 13:19:26.609830] BMI_post_recv: addr: 140, offset: 0x81bce80, size: 16
[D 13:19:26.609875] msgpairarray_post: sm 0x81edf70 msgpair 0: posting send
[D 13:19:26.609896] BMI_post_sendunexpected_list: addr: 140, count: 1,
total_size: 52
[D 13:19:26.609914] element 0: offset: 0x80d6a28, size: 52
[D 13:19:26.609933] tcp_sock_init: attempting reconnect.
[D 13:19:26.609955] Default socket buffers send:-1 receive:-1
[D 13:19:26.609973] Setting socket buffer size for send:0 receive:0
[D 13:19:26.610024] Reread socket buffers send:-1 receive:-1
[D 13:19:26.610066] Default socket buffers send:16384 receive:87380
[D 13:19:26.610085] Setting socket buffer size for send:0 receive:0
[D 13:19:26.610105] Reread socket buffers send:16384 receive:87380
[D 13:19:26.610123] tcp_sock_init: Connect: socket=7,
hostname=foufoune.citi.umich.edu, port=3334
[D 13:19:26.610279] Error: bmi_tcp: Connection refused
[D 13:19:26.613728] BMI_testcontext completing: 363
[D 13:19:26.613748] BMI_testcontext completing: 361
[D 13:19:26.613774] msgpairarray_complete: sm 0x81edf70 status_user_tag 1
msgarray_count 1
[D 13:19:26.613795] msgpairarray_complete: sm 0x81edf70 status_user_tag 0
msgarray_count 1
[D 13:19:26.613813] msgpairarray: all operations complete
[D 13:19:26.613831] (0x81edf70) msgpairarray state: completion_fn
[E 13:19:26.613852] msgpair failed, will retry: Connection refused
[D 13:19:26.613870] *** msgpairarray_completion_fn: msgpair 0 failed, retry 3
[D 13:19:26.613889] msgpairarray_post_retry: sm 0x81edf70, wait 2000 ms
[D 13:19:28.617944] msgpairarray_post: sm 0x81edf70 2 total message(s) with 2
incomplete
[D 13:19:28.618010] msgpairarray_post: sm 0x81edf70 msgpair 0: posting recv
[D 13:19:28.618031] BMI_post_recv: addr: 140, offset: 0x81bce80, size: 16
[D 13:19:28.618077] msgpairarray_post: sm 0x81edf70 msgpair 0: posting send
[D 13:19:28.618098] BMI_post_sendunexpected_list: addr: 140, count: 1,
total_size: 52
[D 13:19:28.618117] element 0: offset: 0x80d6a28, size: 52
[D 13:19:28.618136] tcp_sock_init: attempting reconnect.
[D 13:19:28.618157] Default socket buffers send:-1 receive:-1
[D 13:19:28.618175] Setting socket buffer size for send:0 receive:0
[D 13:19:28.618195] Reread socket buffers send:-1 receive:-1
[D 13:19:28.618237] Default socket buffers send:16384 receive:87380
[D 13:19:28.618256] Setting socket buffer size for send:0 receive:0
[D 13:19:28.618276] Reread socket buffers send:16384 receive:87380
[D 13:19:28.618294] tcp_sock_init: Connect: socket=7,
hostname=foufoune.citi.umich.edu, port=3334
[D 13:19:28.618453] Error: bmi_tcp: Connection refused
[D 13:19:28.621924] BMI_testcontext completing: 370
[D 13:19:28.621951] BMI_testcontext completing: 368
[D 13:19:28.621977] msgpairarray_complete: sm 0x81edf70 status_user_tag 1
msgarray_count 1
[D 13:19:28.621997] msgpairarray_complete: sm 0x81edf70 status_user_tag 0
msgarray_count 1
[D 13:19:28.622015] msgpairarray: all operations complete
[D 13:19:28.622033] (0x81edf70) msgpairarray state: completion_fn
[E 13:19:28.622054] msgpair failed, will retry: Connection refused
[D 13:19:28.622073] *** msgpairarray_completion_fn: msgpair 0 failed, retry 4
[D 13:19:28.622091] msgpairarray_post_retry: sm 0x81edf70, wait 2000 ms
[D 13:19:30.626145] msgpairarray_post: sm 0x81edf70 2 total message(s) with 2
incomplete
[D 13:19:30.626208] msgpairarray_post: sm 0x81edf70 msgpair 0: posting recv
[D 13:19:30.626229] BMI_post_recv: addr: 140, offset: 0x81bce80, size: 16
[D 13:19:30.626274] msgpairarray_post: sm 0x81edf70 msgpair 0: posting send
[D 13:19:30.626296] BMI_post_sendunexpected_list: addr: 140, count: 1,
total_size: 52
[D 13:19:30.626315] element 0: offset: 0x80d6a28, size: 52
[D 13:19:30.626334] tcp_sock_init: attempting reconnect.
[D 13:19:30.626356] Default socket buffers send:-1 receive:-1
[D 13:19:30.626374] Setting socket buffer size for send:0 receive:0
[D 13:19:30.626394] Reread socket buffers send:-1 receive:-1
[D 13:19:30.626434] Default socket buffers send:16384 receive:87380
[D 13:19:30.626453] Setting socket buffer size for send:0 receive:0
[D 13:19:30.626473] Reread socket buffers send:16384 receive:87380
[D 13:19:30.626491] tcp_sock_init: Connect: socket=7,
hostname=foufoune.citi.umich.edu, port=3334
[D 13:19:30.626644] Error: bmi_tcp: Connection refused
[D 13:19:30.630125] BMI_testcontext completing: 377
[D 13:19:30.630146] BMI_testcontext completing: 375
[D 13:19:30.630172] msgpairarray_complete: sm 0x81edf70 status_user_tag 1
msgarray_count 1
[D 13:19:30.630193] msgpairarray_complete: sm 0x81edf70 status_user_tag 0
msgarray_count 1
[D 13:19:30.630242] msgpairarray: all operations complete
[D 13:19:30.630261] (0x81edf70) msgpairarray state: completion_fn
[E 13:19:30.630282] msgpair failed, will retry: Connection refused
[D 13:19:30.630300] *** msgpairarray_completion_fn: msgpair 0 failed, retry 5
[D 13:19:30.630319] msgpairarray_post_retry: sm 0x81edf70, wait 2000 ms
[D 13:19:32.634430] msgpairarray_post: sm 0x81edf70 2 total message(s) with 2
incomplete
[D 13:19:32.634516] msgpairarray_post: sm 0x81edf70 msgpair 0: posting recv
[D 13:19:32.634544] BMI_post_recv: addr: 140, offset: 0x81bce80, size: 16
[D 13:19:32.634602] msgpairarray_post: sm 0x81edf70 msgpair 0: posting send
[D 13:19:32.634630] BMI_post_sendunexpected_list: addr: 140, count: 1,
total_size: 52
[D 13:19:32.634654] element 0: offset: 0x80d6a28, size: 52
[D 13:19:32.634680] tcp_sock_init: attempting reconnect.
[D 13:19:32.634709] Default socket buffers send:-1 receive:-1
[D 13:19:32.634733] Setting socket buffer size for send:0 receive:0
[D 13:19:32.634759] Reread socket buffers send:-1 receive:-1
[D 13:19:32.634809] Default socket buffers send:16384 receive:87380
[D 13:19:32.634835] Setting socket buffer size for send:0 receive:0
[D 13:19:32.634861] Reread socket buffers send:16384 receive:87380
[D 13:19:32.634885] tcp_sock_init: Connect: socket=7,
hostname=foufoune.citi.umich.edu, port=3334
[D 13:19:32.635072] Error: bmi_tcp: Connection refused
[D 13:19:32.638334] BMI_testcontext completing: 384
[D 13:19:32.638372] BMI_testcontext completing: 382
[D 13:19:32.638401] msgpairarray_complete: sm 0x81edf70 status_user_tag 1
msgarray_count 1
[D 13:19:32.638422] msgpairarray_complete: sm 0x81edf70 status_user_tag 0
msgarray_count 1
[D 13:19:32.638441] msgpairarray: all operations complete
[D 13:19:32.638459] (0x81edf70) msgpairarray state: completion_fn
[E 13:19:32.638481] msgpair failed, will retry: Connection refused
[E 13:19:32.638508] *** msgpairarray_completion_fn: msgpair to server
tcp://foufoune.citi.umich.edu:3334 failed: Connection refused
[E 13:19:32.638528] *** Out of retries.
[D 13:19:32.638546] (0x81edf70) truncate state: datafile_failure
[D 13:19:32.638564] (0x81edf70) truncate state: truncate_cleanup
[D 13:19:32.638582] acache: invalidate(): H=1048573
[D 13:19:32.638619] PINT_sys_testsome returned completed vfs_request 0x81eb940
[D 13:19:32.638670] downcall write returned 1
[D 13:19:32.638728] [-] reposted unexp req [0x81eb940] due to normal completion
[D 13:19:32.638801] [+] dev req msg: sz: 644,tag: 125,data: 0x80d7720,type: 0
[D 13:19:32.638836] [*] handling new unexp vfs_request 0x81f73d8
[D 13:19:32.638865] is_op_in_progress called on tag 125
[D 13:19:32.638898] got a setattr request for fsid 408205455 | handle 1048573
[D 13:19:32.638927] perms: 0
[D 13:19:32.638955] PVFS_isys_setattr entered
[D 13:19:32.639011] Doing setattr on handle 1048573 on fs 408205455
[D 13:19:32.639042] setattr state: init
[D 13:19:32.639060] setattr state: setattr_msg_setup_msgpair
[D 13:19:32.639078] setattr: posting setattr req
[D 13:19:32.639096] setattr attr mask sent to server: 0x3f
[D 13:19:32.639117] (0x81f9a08) msgpairarray state: init (1 msgpair(s))
[D 13:19:32.639135] msgpairarray_post: sm 0x81f9a08 2 total message(s) with 2
incomplete
[D 13:19:32.639159] msgpairarray_post: sm 0x81f9a08 msgpair 0: posting recv
[D 13:19:32.639179] BMI_post_recv: addr: 140, offset: 0x80d7b18, size: 16
[D 13:19:32.639222] msgpairarray_post: sm 0x81f9a08 msgpair 0: posting send
[D 13:19:32.639243] BMI_post_sendunexpected_list: addr: 140, count: 1,
total_size: 88
[D 13:19:32.639261] element 0: offset: 0x80d7c50, size: 88
[D 13:19:32.639281] tcp_sock_init: attempting reconnect.
[D 13:19:32.639302] Default socket buffers send:-1 receive:-1
[D 13:19:32.639321] Setting socket buffer size for send:0 receive:0
[D 13:19:32.639340] Reread socket buffers send:-1 receive:-1
[D 13:19:32.639379] Default socket buffers send:16384 receive:87380
[D 13:19:32.639398] Setting socket buffer size for send:0 receive:0
[D 13:19:32.639419] Reread socket buffers send:16384 receive:87380
[D 13:19:32.639462] tcp_sock_init: Connect: socket=7,
hostname=foufoune.citi.umich.edu, port=3334
[D 13:19:32.639582] Posted PVFS_SYS_SETATTR (waiting for test)
[D 13:19:32.639636] Error: bmi_tcp: Connection refused
[D 13:19:32.642354] BMI_testcontext completing: 391
[D 13:19:32.642387] BMI_testcontext completing: 389
[D 13:19:32.642415] msgpairarray_complete: sm 0x81f9a08 status_user_tag 1
msgarray_count 1
[D 13:19:32.642435] msgpairarray_complete: sm 0x81f9a08 status_user_tag 0
msgarray_count 1
[D 13:19:32.642454] msgpairarray: all operations complete
[D 13:19:32.642472] (0x81f9a08) msgpairarray state: completion_fn
[E 13:19:32.642493] msgpair failed, will retry: Connection refused
[D 13:19:32.642512] *** msgpairarray_completion_fn: msgpair 0 failed, retry 1
[D 13:19:32.642530] msgpairarray_post_retry: sm 0x81f9a08, wait 2000 ms
[D 13:19:34.646565] msgpairarray_post: sm 0x81f9a08 2 total message(s) with 2
incomplete
[D 13:19:34.646656] msgpairarray_post: sm 0x81f9a08 msgpair 0: posting recv
[D 13:19:34.646690] BMI_post_recv: addr: 140, offset: 0x80d7b18, size: 16
[D 13:19:34.646757] msgpairarray_post: sm 0x81f9a08 msgpair 0: posting send
[D 13:19:34.646794] BMI_post_sendunexpected_list: addr: 140, count: 1,
total_size: 88
[D 13:19:34.646823] element 0: offset: 0x80d7c50, size: 88
[D 13:19:34.646853] tcp_sock_init: attempting reconnect.
[D 13:19:34.646889] Default socket buffers send:-1 receive:-1
[D 13:19:34.646919] Setting socket buffer size for send:0 receive:0
[D 13:19:34.646948] Reread socket buffers send:-1 receive:-1
[D 13:19:34.647000] Default socket buffers send:16384 receive:87380
[D 13:19:34.647020] Setting socket buffer size for send:0 receive:0
[D 13:19:34.647041] Reread socket buffers send:16384 receive:87380
[D 13:19:34.647059] tcp_sock_init: Connect: socket=7,
hostname=foufoune.citi.umich.edu, port=3334
[D 13:19:34.647224] Error: bmi_tcp: Connection refused
[D 13:19:34.650538] BMI_testcontext completing: 398
[D 13:19:34.650574] BMI_testcontext completing: 396
[D 13:19:34.650602] msgpairarray_complete: sm 0x81f9a08 status_user_tag 1
msgarray_count 1
[D 13:19:34.650623] msgpairarray_complete: sm 0x81f9a08 status_user_tag 0
msgarray_count 1
[D 13:19:34.650642] msgpairarray: all operations complete
[D 13:19:34.650660] (0x81f9a08) msgpairarray state: completion_fn
[E 13:19:34.650682] msgpair failed, will retry: Connection refused
[D 13:19:34.650700] *** msgpairarray_completion_fn: msgpair 0 failed, retry 2
[D 13:19:34.650719] msgpairarray_post_retry: sm 0x81f9a08, wait 2000 ms
[D 13:19:36.654741] msgpairarray_post: sm 0x81f9a08 2 total message(s) with 2
incomplete
[D 13:19:36.654800] msgpairarray_post: sm 0x81f9a08 msgpair 0: posting recv
[D 13:19:36.654821] BMI_post_recv: addr: 140, offset: 0x80d7b18, size: 16
[D 13:19:36.654866] msgpairarray_post: sm 0x81f9a08 msgpair 0: posting send
[D 13:19:36.654888] BMI_post_sendunexpected_list: addr: 140, count: 1,
total_size: 88
[D 13:19:36.654906] element 0: offset: 0x80d7c50, size: 88
[D 13:19:36.654925] tcp_sock_init: attempting reconnect.
[D 13:19:36.654947] Default socket buffers send:-1 receive:-1
[D 13:19:36.654965] Setting socket buffer size for send:0 receive:0
[D 13:19:36.654984] Reread socket buffers send:-1 receive:-1
[D 13:19:36.655021] Default socket buffers send:16384 receive:87380
[D 13:19:36.655040] Setting socket buffer size for send:0 receive:0
[D 13:19:36.655060] Reread socket buffers send:16384 receive:87380
[D 13:19:36.655078] tcp_sock_init: Connect: socket=7,
hostname=foufoune.citi.umich.edu, port=3334
[D 13:19:36.655226] Error: bmi_tcp: Connection refused
[D 13:19:36.658733] BMI_testcontext completing: 405
[D 13:19:36.658754] BMI_testcontext completing: 403
[D 13:19:36.658780] msgpairarray_complete: sm 0x81f9a08 status_user_tag 1
msgarray_count 1
[D 13:19:36.658801] msgpairarray_complete: sm 0x81f9a08 status_user_tag 0
msgarray_count 1
[D 13:19:36.658819] msgpairarray: all operations complete
[D 13:19:36.658837] (0x81f9a08) msgpairarray state: completion_fn
[E 13:19:36.658858] msgpair failed, will retry: Connection refused
[D 13:19:36.658908] *** msgpairarray_completion_fn: msgpair 0 failed, retry 3
[D 13:19:36.658927] msgpairarray_post_retry: sm 0x81f9a08, wait 2000 ms
[D 13:19:38.662947] msgpairarray_post: sm 0x81f9a08 2 total message(s) with 2
incomplete
[D 13:19:38.663015] msgpairarray_post: sm 0x81f9a08 msgpair 0: posting recv
[D 13:19:38.663036] BMI_post_recv: addr: 140, offset: 0x80d7b18, size: 16
[D 13:19:38.663082] msgpairarray_post: sm 0x81f9a08 msgpair 0: posting send
[D 13:19:38.663103] BMI_post_sendunexpected_list: addr: 140, count: 1,
total_size: 88
[D 13:19:38.663121] element 0: offset: 0x80d7c50, size: 88
[D 13:19:38.663140] tcp_sock_init: attempting reconnect.
[D 13:19:38.663162] Default socket buffers send:-1 receive:-1
[D 13:19:38.663180] Setting socket buffer size for send:0 receive:0
[D 13:19:38.663200] Reread socket buffers send:-1 receive:-1
[D 13:19:38.663240] Default socket buffers send:16384 receive:87380
[D 13:19:38.663259] Setting socket buffer size for send:0 receive:0
[D 13:19:38.663279] Reread socket buffers send:16384 receive:87380
[D 13:19:38.663297] tcp_sock_init: Connect: socket=7,
hostname=foufoune.citi.umich.edu, port=3334
[D 13:19:38.663453] Error: bmi_tcp: Connection refused
[D 13:19:38.666931] BMI_testcontext completing: 412
[D 13:19:38.666952] BMI_testcontext completing: 410
[D 13:19:38.666978] msgpairarray_complete: sm 0x81f9a08 status_user_tag 1
msgarray_count 1
[D 13:19:38.666998] msgpairarray_complete: sm 0x81f9a08 status_user_tag 0
msgarray_count 1
[D 13:19:38.667017] msgpairarray: all operations complete
[D 13:19:38.667034] (0x81f9a08) msgpairarray state: completion_fn
[E 13:19:38.667055] msgpair failed, will retry: Connection refused
[D 13:19:38.667073] *** msgpairarray_completion_fn: msgpair 0 failed, retry 4
[D 13:19:38.667092] msgpairarray_post_retry: sm 0x81f9a08, wait 2000 ms
[D 13:19:40.671152] msgpairarray_post: sm 0x81f9a08 2 total message(s) with 2
incomplete
[D 13:19:40.671216] msgpairarray_post: sm 0x81f9a08 msgpair 0: posting recv
[D 13:19:40.671237] BMI_post_recv: addr: 140, offset: 0x80d7b18, size: 16
[D 13:19:40.671282] msgpairarray_post: sm 0x81f9a08 msgpair 0: posting send
[D 13:19:40.671303] BMI_post_sendunexpected_list: addr: 140, count: 1,
total_size: 88
[D 13:19:40.671322] element 0: offset: 0x80d7c50, size: 88
[D 13:19:40.671341] tcp_sock_init: attempting reconnect.
[D 13:19:40.671363] Default socket buffers send:-1 receive:-1
[D 13:19:40.671381] Setting socket buffer size for send:0 receive:0
[D 13:19:40.671401] Reread socket buffers send:-1 receive:-1
[D 13:19:40.671442] Default socket buffers send:16384 receive:87380
[D 13:19:40.671460] Setting socket buffer size for send:0 receive:0
[D 13:19:40.671480] Reread socket buffers send:16384 receive:87380
[D 13:19:40.671498] tcp_sock_init: Connect: socket=7,
hostname=foufoune.citi.umich.edu, port=3334
[D 13:19:40.671653] Error: bmi_tcp: Connection refused
[D 13:19:40.675136] BMI_testcontext completing: 419
[D 13:19:40.675157] BMI_testcontext completing: 417
[D 13:19:40.675183] msgpairarray_complete: sm 0x81f9a08 status_user_tag 1
msgarray_count 1
[D 13:19:40.675203] msgpairarray_complete: sm 0x81f9a08 status_user_tag 0
msgarray_count 1
[D 13:19:40.675222] msgpairarray: all operations complete
[D 13:19:40.675240] (0x81f9a08) msgpairarray state: completion_fn
[E 13:19:40.675260] msgpair failed, will retry: Connection refused
[D 13:19:40.675279] *** msgpairarray_completion_fn: msgpair 0 failed, retry 5
[D 13:19:40.675297] msgpairarray_post_retry: sm 0x81f9a08, wait 2000 ms
[D 13:19:42.679347] msgpairarray_post: sm 0x81f9a08 2 total message(s) with 2
incomplete
[D 13:19:42.679404] msgpairarray_post: sm 0x81f9a08 msgpair 0: posting recv
[D 13:19:42.679425] BMI_post_recv: addr: 140, offset: 0x80d7b18, size: 16
[D 13:19:42.679470] msgpairarray_post: sm 0x81f9a08 msgpair 0: posting send
[D 13:19:42.679491] BMI_post_sendunexpected_list: addr: 140, count: 1,
total_size: 88
[D 13:19:42.679509] element 0: offset: 0x80d7c50, size: 88
[D 13:19:42.679529] tcp_sock_init: attempting reconnect.
[D 13:19:42.679551] Default socket buffers send:-1 receive:-1
[D 13:19:42.679598] Setting socket buffer size for send:0 receive:0
[D 13:19:42.679618] Reread socket buffers send:-1 receive:-1
[D 13:19:42.679656] Default socket buffers send:16384 receive:87380
[D 13:19:42.679674] Setting socket buffer size for send:0 receive:0
[D 13:19:42.679695] Reread socket buffers send:16384 receive:87380
[D 13:19:42.679713] tcp_sock_init: Connect: socket=7,
hostname=foufoune.citi.umich.edu, port=3334
[D 13:19:42.679859] Error: bmi_tcp: Connection refused
[D 13:19:42.683337] BMI_testcontext completing: 426
[D 13:19:42.683358] BMI_testcontext completing: 424
[D 13:19:42.683383] msgpairarray_complete: sm 0x81f9a08 status_user_tag 1
msgarray_count 1
[D 13:19:42.683403] msgpairarray_complete: sm 0x81f9a08 status_user_tag 0
msgarray_count 1
[D 13:19:42.683422] msgpairarray: all operations complete
[D 13:19:42.683439] (0x81f9a08) msgpairarray state: completion_fn
[E 13:19:42.683459] msgpair failed, will retry: Connection refused
[E 13:19:42.683483] *** msgpairarray_completion_fn: msgpair to server
tcp://foufoune.citi.umich.edu:3334 failed: Connection refused
[E 13:19:42.683502] *** Out of retries.
[D 13:19:42.683521] setattr state: setattr_msg_failure
[D 13:19:42.683538] setattr state: cleanup
[D 13:19:42.683556] acache: invalidate(): H=1048573
[D 13:19:42.683587] PINT_sys_testsome returned completed vfs_request 0x81f73d8
[D 13:19:42.683638] downcall write returned 1
[D 13:19:42.683697] [-] reposted unexp req [0x81f73d8] due to normal completion
_______________________________________________
Pvfs2-developers mailing list
Pvfs2-developers@beowulf-underground.org
http://www.beowulf-underground.org/mailman/listinfo/pvfs2-developers
