Coda File System

crash during reintegration

From: Stephen J. Turnbull <stephen_at_xemacs.org>
Date: Thu, 01 Apr 2004 17:52:24 +0900
Coda 6.0.2 (I thought I had 6.0.3, but I guess not).  I'll be
upgrading soon, but it's not clear that this bug would be fixed given
that other people have mentioned unrepairable conflicts recently.

Pretty clearly I was in the middle of a CVS update.  If you need the
full log or want me to look for something, let me know.  Unfortunately
I need to work so I had to kill, restart, and in the end reinitialize
venus.

err, I get this on restart:

Date: Thu 04/01/2004

17:20:36 Coda Venus, version 6.0.2

17:20:36 /mnt/old.vicepa/venus/LOG size is 2694144 bytes
17:20:46 /mnt/old.vicepa/venus/DATA size is 10771944 bytes
17:20:46 Loading RVM data
17:20:46 Last init was Tue Nov 11 11:11:14 2003
17:20:46 Last shutdown was dirty
17:20:46 Starting RealmDB scan
17:20:46        Found 2 realms
17:20:46 starting VDB scan
17:20:46        11 volume replicas
17:20:46        9 replicated volumes
17:20:46        249 CML entries allocated
17:20:46        0 CML entries on free-list
17:20:47 starting FSDB scan (4166, 100000) (25, 75, 4)
17:20:48        (Entries.Log, 5086c488.7f000016.3028.4627c) found owrite object, discarding
17:20:48        (lost file data backed up to /mnt/old.vicepa/venus/spool/Entries.Log-3)
17:20:48        3937 cache files in table (23861 blocks)
17:20:48        229 cache files on free-list
17:20:49 starting HDB scan
17:20:49        0 hdb entries in table
17:20:49        0 hdb entries on free-list
17:20:49 Mounting root volume...
17:20:49 Venus starting...
17:20:49 /coda now mounted.

17:20:55 Reintegrate xe:21-4 pending tokens for uid = 1000
17:21:07 Resolved realm 'tleepslib.sk.tsukuba.ac.jp'
17:21:13 Checkpointing xe:21-4
17:21:13 to /mnt/old.vicepa/venus/spool/1000/tleepslib.sk.tsukuba.ac.jp_xe_21-4.tar
17:21:13 and /mnt/old.vicepa/venus/spool/1000/tleepslib.sk.tsukuba.ac.jp_xe_21-4.cml
17:21:13 can't checkpoint (/lisp/CVS/Entries.Log), no data
17:21:13 Local inconsistent object at ???/lisp/hm--html-menus, please check!

17:21:13 fatal error -- Assertion failed: file "local_cml.cc", line 96

17:21:14 RecovTerminate: clean shutdown

Restarting again, I get:

Date: Thu 04/01/2004

17:22:54 Coda Venus, version 6.0.2

17:22:54 /mnt/old.vicepa/venus/LOG size is 2694144 bytes
17:22:58 /mnt/old.vicepa/venus/DATA size is 10771944 bytes
17:22:58 Loading RVM data
17:22:58 Last init was Tue Nov 11 11:11:14 2003
17:22:58 Last shutdown was clean
17:22:58 Starting RealmDB scan
17:22:58        Found 2 realms
17:22:58 starting VDB scan
17:22:58        10 volume replicas
17:22:58        8 replicated volumes
17:22:58        249 CML entries allocated
17:22:58        0 CML entries on free-list
17:22:58 starting FSDB scan (4166, 100000) (25, 75, 4)
17:22:59        3906 cache files in table (23833 blocks)
17:22:59        260 cache files on free-list
17:22:59 starting HDB scan
17:22:59        0 hdb entries in table
17:22:59        0 hdb entries on free-list
17:22:59 Mounting root volume...
17:22:59 Venus starting...
17:22:59 /coda now mounted.

17:23:04 Local inconsistent object at ???/lisp/hm--html, please check!

17:23:04 Reintegrate xe:21-4 pending tokens for uid = 1000
17:23:27 Resolved realm 'tleepslib.sk.tsukuba.ac.jp'
17:28:04 Local inconsistent object at /coda/tleepslib.sk.tsukuba.ac.jp/Software/XEmacs/21.4/lisp/hm--html, please check!

This time venus doesn't crash, but repair fails while cfs br succeeds:

steve_at_tleepslib:/coda/tleepslib.sk.tsukuba.ac.jp/Software/XEmacs/21.4/lisp$ repair
This repair tool can be used to manually repair server/server 
or local/global conflicts on files and directories. 
You will first need to do a "beginrepair" to start a repair
session where messages about the nature of the conflict and
the commands that should be used to repair the conflict will
be displayed. Help message on individual commands can also be
obtained by using the "help" facility. Finally, you can use the
"endrepair" or "quit" to terminate the current repair session.
repair > beginrepair hm-html-menus
Could not allocate new repvol: Object not in conflict
beginrepair failed.
repair > endrepair
There is no repair session to end
repair > quit
steve_at_tleepslib:/coda/tleepslib.sk.tsukuba.ac.jp/Software/XEmacs/21.4/lisp$ ls -ld hm--html-menus 
lr--r--r--    1 root     4294967294       29 Apr  1 17:30 hm--html-menus -> @7f000016.ffffffff.0008b88b_at_tleepslib.sk.tsukuba.ac.jp
steve_at_tleepslib:/coda/tleepslib.sk.tsukuba.ac.jp/Software/XEmacs/21.4/lisp$ cfs br hm--html-menus 
steve_at_tleepslib:/coda/tleepslib.sk.tsukuba.ac.jp/Software/XEmacs/21.4/lisp$ ls hm--html-menus/
global  local
steve_at_tleepslib:/coda/tleepslib.sk.tsukuba.ac.jp/Software/XEmacs/21.4/lisp$ 

Of course that's no help, because then the repair tool itself can't
see a conflict.

But doing cfs er hm--html-menus, then restarting repair works!
Weird....

Now, hm--html-menus is a CVS-deleted directory that CVS restores and
then prunes on an update (this churning of directories seems to be
something that used to confuse Coda mightily, but it's gotten a lot
better).  So I repair, beginrepair, discardalllocal, endrepair, and
quit successfully.

OK, but now I still can't get a reintegration:

steve_at_tleepslib:/coda/tleepslib.sk.tsukuba.ac.jp/Software/XEmacs/21.4/lisp$ cfs fr .
VIOC_SYNCCACHE: Invalid argument
  VIOC_SYNCCACHE returns -1
steve_at_tleepslib:/coda/tleepslib.sk.tsukuba.ac.jp/Software/XEmacs/21.4/lisp$ cfs wr .
steve_at_tleepslib:/coda/tleepslib.sk.tsukuba.ac.jp/Software/XEmacs/21.4/lisp$ cfs lv .
  Status of volume 0x7f000016 (2130706454) named "xe:21-4"
  Volume type is ReadWrite
  Connection State is WriteDisconnected
  Minimum quota is 0, maximum quota is unlimited
  Current blocks used are 57272
  The partition has 2192 blocks available out of 727892
  Write-back is disabled
  There are 251 CML entries pending for reintegration

and venus says:

17:22:59 /coda now mounted.

17:23:04 Local inconsistent object at ???/lisp/hm--html, please check!

17:23:04 Reintegrate xe:21-4 pending tokens for uid = 1000
17:23:27 Resolved realm 'tleepslib.sk.tsukuba.ac.jp'
17:28:04 Local inconsistent object at /coda/tleepslib.sk.tsukuba.ac.jp/Software/XEmacs/21.4/lisp/hm--html, please check!

17:32:59 volume xe:21-4 has unrepaired local subtree(s), skip checkpointing CML!

17:33:04 Local inconsistent object at /coda/tleepslib.sk.tsukuba.ac.jp/Software/XEmacs/21.4/lisp/hm--html, please check!

17:39:05 Propagating updates to all volumes
17:41:51 Logging updates to volume xe:21-4
17:42:18 Propagating updates to volume xe:21-4 (|CML| = 251)
17:43:03 volume xe:21-4 has unrepaired local subtree(s), skip checkpointing CML!

/etc/init.d/venus.init stop
Shutting down venus: 17:44:47 RecovTerminate: clean shutdown
clean up ... done.
tleepslib:/home/steve# /etc/init.d/venus.init start
Starting venus: done.
tleepslib:/home/steve# 
Date: Thu 04/01/2004

17:44:52 Coda Venus, version 6.0.2

17:44:52 /mnt/old.vicepa/venus/LOG size is 2694144 bytes
17:44:52 /mnt/old.vicepa/venus/DATA size is 10771944 bytes
17:44:52 Loading RVM data
17:44:52 Last init was Tue Nov 11 11:11:14 2003
17:44:52 Last shutdown was clean
17:44:52 Starting RealmDB scan
17:44:52        Found 2 realms
17:44:52 starting VDB scan
17:44:52        10 volume replicas
17:44:52        8 replicated volumes
17:44:52        251 CML entries allocated
17:44:52        0 CML entries on free-list
17:44:52 starting FSDB scan (4166, 100000) (25, 75, 4)
17:44:52        3903 cache files in table (23458 blocks)
17:44:52        263 cache files on free-list
17:44:52 fatal error -- cmlent::AttachFidBindings: can't find (5086c488.7f000016.241.46249)
17:44:53 RecovTerminate: dirty shutdown (1 uncommitted transactions)

tleepslib:/home/steve# /etc/init.d/venus.init stop
Shutting down venus: 17:45:12 RecovTerminate: dirty shutdown (1 uncommitted transactions)
umount: /coda: not mounted
clean up ... done.

After cycling this with identical results, I've reinitted and things
seem to be OK.

Here are the logs just before the original crash.

venus.err says:

07:01:45 Reintegrate: xe:pkg, 8/8 records, result = SUCCESS
07:02:49 Reintegrate: xe:pkg, 17/17 records, result = SUCCESS
07:03:03 Reintegrate: xe:pkg, 33/33 records, result = SUCCESS
07:03:06 Reintegrate: xe:pkg, 84/84 records, result = SUCCESS
07:03:10 Reintegrate: xe:pkg, 36/36 records, result = SUCCESS
07:03:16 Reintegrate: xe:pkg, 100/141 records, result = SUCCESS
07:03:25 Reintegrate: xe:pkg, 41/41 records, result = SUCCESS
07:03:25 Reintegrate: xe:pkg, 13/13 records, result = SUCCESS
07:03:25 Reintegrate: xe:pkg, 1/1 records, result = SUCCESS
07:42:27 Reintegrate: xe:21-4, 1/1 records, result = SUCCESS
07:42:42 Reintegrate: xe:21-4, 4/4 records, result = SUCCESS
07:44:45 Reintegrate: xe:21-4, 100/330 records, result = SUCCESS
07:45:01 Reintegrate: xe:21-4, 100/335 records, result = SUCCESS
07:45:05 Reintegrate: xe:21-4, 100/367 records, result = SUCCESS
07:45:17 Reintegrate: xe:21-4, 100/354 records, result = SUCCESS
07:45:21 Reintegrate: xe:21-4, 100/314 records, result = SUCCESS
07:45:25 Reintegrate: xe:21-4, 100/293 records, result = SUCCESS
Assertion failed: recovering || (off_t)length == tstat.st_size, file "fso_cachef
ile.cc", line 229
Sleeping forever.  You may use gdb to attach to process 8086.

venus.log says:

[[[*** cut and paste from terminal, so linebreaks are a little messed up***]]]

[ I(23) : 0196 : 07:45:17 ] *** Long Running (Multi)COP2: code = -2001, elapsed 
= 1169.6 ***
[ I(23) : 0196 : 07:45:17 ] ClientModifyLog::IncCommit: (xe:21-4)
[ I(23) : 0196 : 07:45:17 ] volent::IncReintegrate: committed
[ I(23) : 0196 : 07:45:17 ] IncReintegrate: (xe:21-4,-2030) result = SUCCESS, el
apsed = 12202.6 (31.1, 879.0, 11292.4)
[ I(23) : 0196 : 07:45:17 ]     new stats = [  39,   9.1,     1.1,   61,  14.8],
 [   0,   0.0,     0.0,    0,   0.0]
[ I(23) : 0196 : 07:45:17 ] ClientModifyLog::GetReintegrateable: (xe:21-4, -2031
) 100 records, 312 msec
[ I(23) : 0196 : 07:45:17 ] volent::IncReintegrate: (xe:21-4, -2031) uid = 1000
[ I(23) : 0196 : 07:45:17 ] k_Replace: VenusFid (5086c488.7f000016.ffffffff.8b7d
8) with VenusFid (5086c488.7f000016.2f9.462ac) in mini-cache
[ I(23) : 0196 : 07:45:17 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:17 ] k_Replace: VenusFid (5086c488.7f000016.ffffffff.8b7d
9) with VenusFid (5086c488.7f000016.2fb.462ad) in mini-cache
[ I(23) : 0196 : 07:45:17 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:17 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b7d
a) with VenusFid (5086c488.7f000016.31c4.462b2) in mini-cache
[ I(23) : 0196 : 07:45:17 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:17 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b7d
b) with VenusFid (5086c488.7f000016.31c6.462b3) in mini-cache
[ I(23) : 0196 : 07:45:17 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:17 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b7d
e) with VenusFid (5086c488.7f000016.31c8.462b4) in mini-cache
[ I(23) : 0196 : 07:45:17 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:17 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b7d
f) with VenusFid (5086c488.7f000016.31ca.462b5) in mini-cache
[ I(23) : 0196 : 07:45:17 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:17 ] k_Replace: VenusFid (5086c488.7f000016.ffffffff.8b7e
0) with VenusFid (5086c488.7f000016.2fd.462ae) in mini-cache
[ I(23) : 0196 : 07:45:17 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:17 ] k_Replace: VenusFid (5086c488.7f000016.ffffffff.8b7e
1) with VenusFid (5086c488.7f000016.2ff.462af) in mini-cache
[ I(23) : 0196 : 07:45:17 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:17 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b7e
2) with VenusFid (5086c488.7f000016.31cc.462b6) in mini-cache
[ I(23) : 0196 : 07:45:17 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:17 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b7e
3) with VenusFid (5086c488.7f000016.31ce.462b7) in mini-cache
[ I(23) : 0196 : 07:45:17 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:17 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b7e
6) with VenusFid (5086c488.7f000016.31d0.462b8) in mini-cache
[ I(23) : 0196 : 07:45:17 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:17 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b7e
7) with VenusFid (5086c488.7f000016.31d2.462b9) in mini-cache
[ I(23) : 0196 : 07:45:17 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:17 ] k_Replace: VenusFid (5086c488.7f000016.ffffffff.8b7e
8) with VenusFid (5086c488.7f000016.301.462b0) in mini-cache
[ I(23) : 0196 : 07:45:17 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:17 ] k_Replace: VenusFid (5086c488.7f000016.ffffffff.8b7e
9) with VenusFid (5086c488.7f000016.303.462b1) in mini-cache
[ I(23) : 0196 : 07:45:17 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:17 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b7e
a) with VenusFid (5086c488.7f000016.31d4.462ba) in mini-cache
[ I(23) : 0196 : 07:45:17 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:17 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b7e
b) with VenusFid (5086c488.7f000016.31d6.462bb) in mini-cache
[ I(23) : 0196 : 07:45:17 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:17 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b7e
e) with VenusFid (5086c488.7f000016.31d8.462bc) in mini-cache
[ I(23) : 0196 : 07:45:17 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:17 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b7e
f) with VenusFid (5086c488.7f000016.31da.462bd) in mini-cache
[ I(23) : 0196 : 07:45:17 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:17 ] k_Replace: VenusFid (5086c488.7f000016.ffffffff.8b7f
0) with VenusFid (5086c488.7f000016.333.462d2) in mini-cache
[ I(23) : 0196 : 07:45:17 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:17 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b7f
2) with VenusFid (5086c488.7f000016.31dc.462be) in mini-cache
[ I(23) : 0196 : 07:45:17 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:17 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b7f
3) with VenusFid (5086c488.7f000016.31de.462bf) in mini-cache
[ I(23) : 0196 : 07:45:17 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:17 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b7f
4) with VenusFid (5086c488.7f000016.31e0.462c0) in mini-cache
[ I(23) : 0196 : 07:45:17 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:17 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b7f
5) with VenusFid (5086c488.7f000016.31e2.462c1) in mini-cache
[ I(23) : 0196 : 07:45:17 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:17 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b7f
8) with VenusFid (5086c488.7f000016.31e4.462c2) in mini-cache
[ I(23) : 0196 : 07:45:17 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:17 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b7f
9) with VenusFid (5086c488.7f000016.31e6.462c3) in mini-cache
[ I(23) : 0196 : 07:45:17 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:17 ] ClientModifyLog::IncReallocFids: (xe:21-4)
[ I(23) : 0196 : 07:45:17 ] ClientModifyLog::IncThread: (xe:21-4)
[ I(23) : 0196 : 07:45:17 ] ClientModifyLog::IncPack: (xe:21-4)

[ W(27) : 0000 : 07:45:17 ] Cachefile::SetLength 43
[ W(27) : 0000 : 07:45:17 ] Cachefile::SetLength 29
[ W(27) : 0000 : 07:45:17 ] Cachefile::SetLength 0
[ W(27) : 0000 : 07:45:17 ] Cachefile::SetLength 11
[ W(27) : 0000 : 07:45:17 ] Cachefile::SetLength 0
[ W(27) : 0000 : 07:45:17 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:17 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:17 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:17 ] Cachefile::SetLength 2
[ W(27) : 0000 : 07:45:17 ] repvol::LogRemove: record cancelled, Entries, size =
 247
[ W(27) : 0000 : 07:45:17 ] repvol::LogRemove: record cancelled, Entries.Log, si
ze = 251
[ W(27) : 0000 : 07:45:17 ] Cachefile::SetLength 43
[ W(27) : 0000 : 07:45:17 ] Cachefile::SetLength 29
[ W(27) : 0000 : 07:45:17 ] Cachefile::SetLength 0
[ W(27) : 0000 : 07:45:17 ] Cachefile::SetLength 0
[ W(27) : 0000 : 07:45:17 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:17 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:17 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:17 ] Cachefile::SetLength 2
[ W(27) : 0000 : 07:45:17 ] repvol::LogRemove: record cancelled, Entries, size =
 247
[ W(27) : 0000 : 07:45:18 ] repvol::LogRemove: record cancelled, Entries.Log, si
ze = 251
[ W(27) : 0000 : 07:45:18 ] Cachefile::SetLength 43
[ W(27) : 0000 : 07:45:18 ] Cachefile::SetLength 29
[ W(27) : 0000 : 07:45:18 ] Cachefile::SetLength 0
[ W(27) : 0000 : 07:45:18 ] Cachefile::SetLength 0

[ I(23) : 0196 : 07:45:18 ] ClientModifyLog::COP1: (replica 0) 0 stale dirs
[ I(23) : 0196 : 07:45:18 ] ClientModifyLog::COP1: (xe:21-4), 10416 bytes, retur
ns 0, index = 100

[ W(27) : 0000 : 07:45:18 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:18 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:18 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:18 ] Cachefile::SetLength 2
[ W(27) : 0000 : 07:45:18 ] repvol::LogRemove: record cancelled, Entries, size =
 247
[ W(27) : 0000 : 07:45:18 ] repvol::LogRemove: record cancelled, Entries.Log, si
ze = 251
[ W(27) : 0000 : 07:45:18 ] Cachefile::SetLength 43
[ W(27) : 0000 : 07:45:18 ] Cachefile::SetLength 23
[ W(27) : 0000 : 07:45:18 ] Cachefile::SetLength 0
[ W(27) : 0000 : 07:45:18 ] Cachefile::SetLength 0
[ W(27) : 0000 : 07:45:18 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:19 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:19 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:19 ] Cachefile::SetLength 2
[ W(27) : 0000 : 07:45:19 ] repvol::LogRemove: record cancelled, Entries, size =
 247
[ W(27) : 0000 : 07:45:19 ] repvol::LogRemove: record cancelled, Entries.Log, si
ze = 251
[ W(27) : 0000 : 07:45:19 ] Cachefile::SetLength 43
[ W(27) : 0000 : 07:45:19 ] Cachefile::SetLength 24
[ W(27) : 0000 : 07:45:19 ] Cachefile::SetLength 0
[ W(27) : 0000 : 07:45:19 ] Cachefile::SetLength 0

[ I(23) : 0196 : 07:45:19 ] *** Long Running (Multi)COP2: code = -2001, elapsed 
= 1446.1 ***

[ W(27) : 0000 : 07:45:19 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:19 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:20 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:20 ] Cachefile::SetLength 2
[ W(27) : 0000 : 07:45:20 ] repvol::LogRemove: record cancelled, Entries, size =
 247
[ W(27) : 0000 : 07:45:20 ] repvol::LogRemove: record cancelled, Entries.Log, si
ze = 251
[ W(27) : 0000 : 07:45:20 ] Cachefile::SetLength 43
[ W(27) : 0000 : 07:45:20 ] Cachefile::SetLength 43
[ W(27) : 0000 : 07:45:20 ] Cachefile::SetLength 25
[ W(27) : 0000 : 07:45:20 ] Cachefile::SetLength 0
[ W(27) : 0000 : 07:45:20 ] Cachefile::SetLength 0
[ W(27) : 0000 : 07:45:20 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:20 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:20 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:20 ] Cachefile::SetLength 2
[ W(27) : 0000 : 07:45:20 ] repvol::LogRemove: record cancelled, Entries, size =
 247
[ W(27) : 0000 : 07:45:20 ] repvol::LogRemove: record cancelled, Entries.Log, si
ze = 251
[ W(27) : 0000 : 07:45:20 ] Cachefile::SetLength 43
[ W(27) : 0000 : 07:45:21 ] Cachefile::SetLength 22
[ W(27) : 0000 : 07:45:21 ] Cachefile::SetLength 0
[ W(27) : 0000 : 07:45:21 ] Cachefile::SetLength 0

[ I(23) : 0196 : 07:45:21 ] ClientModifyLog::IncCommit: (xe:21-4)
[ I(23) : 0196 : 07:45:21 ] volent::IncReintegrate: committed
[ I(23) : 0196 : 07:45:21 ] IncReintegrate: (xe:21-4,-2031) result = SUCCESS, el
apsed = 3730.0 (22.0, 849.5, 2858.5)
[ I(23) : 0196 : 07:45:21 ]     new stats = [  36,   8.4,     0.7,   64,  15.5],
 [   0,   0.0,     0.0,    0,   0.0]
[ I(23) : 0196 : 07:45:21 ] ClientModifyLog::GetReintegrateable: (xe:21-4, -2032
) 100 records, 9 msec
[ I(23) : 0196 : 07:45:21 ] volent::IncReintegrate: (xe:21-4, -2032) uid = 1000

[ W(27) : 0000 : 07:45:21 ] Cachefile::SetLength 14

[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b7f
a) with VenusFid (5086c488.7f000016.3376.462f2) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b7f
b) with VenusFid (5086c488.7f000016.3378.462f3) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b7f
e) with VenusFid (5086c488.7f000016.337a.462f4) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b7f
f) with VenusFid (5086c488.7f000016.337c.462f5) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b80
0) with VenusFid (5086c488.7f000016.337e.462f6) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b80
1) with VenusFid (5086c488.7f000016.3380.462f7) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b80
4) with VenusFid (5086c488.7f000016.3382.462f8) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b80
5) with VenusFid (5086c488.7f000016.3384.462f9) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b80
6) with VenusFid (5086c488.7f000016.3386.462fa) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b80
7) with VenusFid (5086c488.7f000016.3388.462fb) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b80
a) with VenusFid (5086c488.7f000016.338a.462fc) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b80
b) with VenusFid (5086c488.7f000016.338c.462fd) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b80
c) with VenusFid (5086c488.7f000016.338e.462fe) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b80
d) with VenusFid (5086c488.7f000016.3390.462ff) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b81
0) with VenusFid (5086c488.7f000016.3392.46300) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b81
1) with VenusFid (5086c488.7f000016.3394.46301) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.ffffffff.8b81
2) with VenusFid (5086c488.7f000016.34f.462e0) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b81
3) with VenusFid (5086c488.7f000016.3396.46302) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b81
4) with VenusFid (5086c488.7f000016.3398.46303) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b81
7) with VenusFid (5086c488.7f000016.339a.46304) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b81
8) with VenusFid (5086c488.7f000016.339c.46305) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.ffffffff.8b81
9) with VenusFid (5086c488.7f000016.351.462e1) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.ffffffff.8b81
a) with VenusFid (5086c488.7f000016.353.462e2) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b81
b) with VenusFid (5086c488.7f000016.339e.46306) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b81
c) with VenusFid (5086c488.7f000016.33a0.46307) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b81
f) with VenusFid (5086c488.7f000016.33a2.46308) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b82
0) with VenusFid (5086c488.7f000016.33a4.46309) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.ffffffff.8b82
1) with VenusFid (5086c488.7f000016.355.462e3) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.ffffffff.8b82
2) with VenusFid (5086c488.7f000016.357.462e4) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b82
3) with VenusFid (5086c488.7f000016.33a6.4630a) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] k_Replace: VenusFid (5086c488.7f000016.fffffffe.8b82
4) with VenusFid (5086c488.7f000016.33a8.4630b) in mini-cache
[ I(23) : 0196 : 07:45:21 ] k_Replace: returns 0
[ I(23) : 0196 : 07:45:21 ] ClientModifyLog::IncReallocFids: (xe:21-4)
[ I(23) : 0196 : 07:45:21 ] ClientModifyLog::IncThread: (xe:21-4)
[ I(23) : 0196 : 07:45:21 ] ClientModifyLog::IncPack: (xe:21-4)

[ W(27) : 0000 : 07:45:21 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:21 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:21 ] Cachefile::SetLength 2
[ W(27) : 0000 : 07:45:21 ] repvol::LogRemove: record cancelled, Entries, size =
 247
[ W(27) : 0000 : 07:45:21 ] repvol::LogRemove: record cancelled, Entries.Log, si
ze = 251

[ T(01) : 149019 : 07:45:22 ] BeginRvmFlush (1, 334660, S)
[ T(01) : 149019 : 07:45:22 ] EndRvmFlush

[ W(27) : 0000 : 07:45:22 ] Cachefile::SetValidData 1763
[ W(27) : 0000 : 07:45:22 ] Cachefile::SetLength 43
[ W(27) : 0000 : 07:45:22 ] Cachefile::SetLength 22
[ W(27) : 0000 : 07:45:22 ] Cachefile::SetLength 0
[ W(27) : 0000 : 07:45:22 ] Cachefile::SetLength 0
[ W(27) : 0000 : 07:45:22 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:22 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:22 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:22 ] Cachefile::SetLength 2
[ W(27) : 0000 : 07:45:22 ] repvol::LogRemove: record cancelled, Entries, size =
 247
[ W(27) : 0000 : 07:45:22 ] repvol::LogRemove: record cancelled, Entries.Log, si
ze = 251

[ I(23) : 0196 : 07:45:22 ] *** Long Running (Multi)Reintegrate: code = -2001, e
lapsed = 1531.7 ***
[ I(23) : 0196 : 07:45:22 ] ClientModifyLog::COP1: (replica 0) 0 stale dirs
[ I(23) : 0196 : 07:45:22 ] ClientModifyLog::COP1: (xe:21-4), 10344 bytes, retur
ns 0, index = 100

[ W(27) : 0000 : 07:45:22 ] Cachefile::SetLength 43
[ W(27) : 0000 : 07:45:22 ] Cachefile::SetLength 24
[ W(27) : 0000 : 07:45:22 ] Cachefile::SetLength 0
[ W(27) : 0000 : 07:45:22 ] Cachefile::SetLength 0
[ W(27) : 0000 : 07:45:23 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:23 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:23 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:23 ] Cachefile::SetLength 2
[ W(27) : 0000 : 07:45:23 ] repvol::LogRemove: record cancelled, Entries, size =
 247
[ W(27) : 0000 : 07:45:23 ] repvol::LogRemove: record cancelled, Entries.Log, size = 251
[ W(27) : 0000 : 07:45:23 ] Cachefile::SetLength 43
[ W(27) : 0000 : 07:45:23 ] Cachefile::SetLength 32
[ W(27) : 0000 : 07:45:23 ] Cachefile::SetLength 0
[ W(27) : 0000 : 07:45:23 ] Cachefile::SetLength 16
[ W(27) : 0000 : 07:45:24 ] Cachefile::SetLength 0
[ W(27) : 0000 : 07:45:24 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:24 ] Cachefile::SetLength 14

[ I(23) : 0196 : 07:45:24 ] *** Long Running (Multi)COP2: code = -2001, elapsed 
= 1193.1 ***

[ W(27) : 0000 : 07:45:24 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:24 ] Cachefile::SetLength 2
[ W(27) : 0000 : 07:45:24 ] repvol::LogRemove: record cancelled, Entries, size =
 247
[ W(27) : 0000 : 07:45:24 ] repvol::LogRemove: record cancelled, Entries.Log, si
ze = 251
[ W(27) : 0000 : 07:45:24 ] Cachefile::SetLength 43
[ W(27) : 0000 : 07:45:24 ] Cachefile::SetLength 46
[ W(27) : 0000 : 07:45:24 ] Cachefile::SetLength 0
[ W(27) : 0000 : 07:45:24 ] Cachefile::SetLength 22
[ W(27) : 0000 : 07:45:24 ] Cachefile::SetLength 0
[ W(27) : 0000 : 07:45:24 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:24 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:24 ] Cachefile::SetLength 14
[ W(27) : 0000 : 07:45:24 ] Cachefile::SetLength 2
[ W(27) : 0000 : 07:45:24 ] repvol::LogRemove: record cancelled, Entries, size =
 247
[ W(27) : 0000 : 07:45:24 ] repvol::LogRemove: record cancelled, Entries.Log, si
ze = 251
[ W(27) : 0000 : 07:45:25 ] Cachefile::SetLength 43
[ W(27) : 0000 : 07:45:25 ] Cachefile::SetLength 60
[ W(27) : 0000 : 07:45:25 ] Cachefile::SetLength 0

[ I(23) : 0196 : 07:45:25 ] ClientModifyLog::IncCommit: (xe:21-4)
[ I(23) : 0196 : 07:45:25 ] volent::IncReintegrate: committed
[ I(23) : 0196 : 07:45:25 ] IncReintegrate: (xe:21-4,-2032) result = SUCCESS, el
apsed = 4086.0 (24.7, 1532.2, 2529.1)
[ I(23) : 0196 : 07:45:25 ]     new stats = [  36,   8.4,     0.7,   64,  15.5],
 [   0,   0.0,     0.0,    0,   0.0]

-- 
Institute of Policy and Planning Sciences     http://turnbull.sk.tsukuba.ac.jp
University of Tsukuba                    Tennodai 1-1-1 Tsukuba 305-8573 JAPAN
               Ask not how you can "do" free software business;
              ask what your business can "do for" free software.
Received on 2004-04-01 03:58:41