Coda File System

Venus reintegration error 198

From: Florian Schaefer <listbox_at_netego.de>
Date: Fri, 3 Oct 2003 13:45:46 +0200
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Hi,

once again, my venus won't start. But this time it seems to be another
problem than the one on Sep 14, 2003. Fortunately, I've got a venus
binary with debug information now. Perhaps someone can tell me, what's
gone wrong.

FYI: The client is connected directly via 100Mbit to the server and only
one client accesses coda at a time. Therefore I don't understand how a
conflict could occur in the first place. (There's one file mentioned in
floyd.netego.de_florian.tar)

OK, below is the information I gathered - I hope it's not too long. I
haven't initialised venus till now, therefore I can try "some things"
with the system if that would be useful.

Ciao
Florian

- -----------------[ console ]-----------------

13:09:51 Reintegrate florian pending tokens for uid = 500
13:10:02 worker::main Got a bogus opcode 36
13:10:02 Resolved realm 'floyd.netego.de'
13:10:08 Checkpointing florian
13:10:08 to /usr/coda/spool/500/floyd.netego.de_florian.tar
13:10:08 and /usr/coda/spool/500/floyd.netego.de_florian.cml
13:10:08 Local inconsistent object at ???/anderes/config, please check!

13:10:08 Reintegrate: florian, 4/4 records, result = Unknown error 198
13:10:15 fatal error -- cmlent::thread: can't find
(50294108.7f000001.151.caa)
13:10:15 RecovTerminate: clean shutdown
Assertion failed: 0, file "vol_cml.cc", line 2469
Sleeping forever.  You may use gdb to attach to process 620.

- -----------------[ backtrace ]-----------------

(gdb) bt
#0  0x40214495 in nanosleep () from /lib/libc.so.6
#1  0x40214318 in sleep () from /lib/libc.so.6
#2  0x080db918 in coda_assert (pred=0x80e44f8 "0", file=0x80f1130 "vol_cml.cc", line=2469)
    at coda_assert.c:46
#3  0x08090501 in choke(char*, int, char*, ...) (file=0x80f1130 "vol_cml.cc", line=2469, 
    fmt=0x80f2380 "cmlent::thread: can't find (%s)") at venusutil.cc:210
#4  0x080a049c in cmlent::thread() (this=0x502876c8) at venusfid.h:78
#5  0x0809e825 in ClientModifyLog::IncThread(int) (this=0x50293ba8, tid=-102) at vol_cml.cc:1946
#6  0x080a5d2f in repvol::IncReintegrate(int) (this=0x50293b08, tid=-102) at vol_reintegrate.cc:278
#7  0x080a5978 in repvol::Reintegrate() (this=0x50293b08) at vol_reintegrate.cc:165
#8  0x080a6aa7 in reintegrator::main() (this=0x8136570) at vol_reintegrate.cc:753
#9  0x080acf29 in VprocPreamble(Lock*) (init_lock=0x81365b0) at vproc.cc:146
#10 0x4007ce9a in Create_Process_Part2 () at lwp.c:796

- -----------------[ venus.log ]-----------------

[ X(00) : 0000 : 13:09:44 ] Coda Venus, version 6.0.2
[ X(00) : 0000 : 13:09:44 ] Logfile initialized with LogLevel = 0 at Fri
Oct  3 13:09:44 2003

[ X(00) : 0000 : 13:09:44 ] E StatsInit()
[ X(00) : 0000 : 13:09:44 ] L StatsInit()
[ X(00) : 0000 : 13:09:45 ] BeginRvmFlush (1, 60, F)
[ X(00) : 0000 : 13:09:45 ] EndRvmFlush
[ X(00) : 0000 : 13:09:45 ] BeginRvmTruncate (1, 220, F)
[ X(00) : 0000 : 13:09:45 ] EndRvmTruncate
[ X(00) : 0000 : 13:09:46 ] BeginRvmFlush (1, 508, F)
[ X(00) : 0000 : 13:09:46 ] EndRvmFlush
[ X(00) : 0000 : 13:09:46 ] BeginRvmTruncate (3, 668, F)
[ X(00) : 0000 : 13:09:46 ] EndRvmTruncate
[ X(00) : 0000 : 13:09:46 ] E adv_daemon::adv_daemon: AdviceServer    

[ A(18) : 0000 : 13:09:46 ] adv_daemon::main()

[ H(07) : 0000 : 13:09:46 ] HDBDaemon about to sleep on hdbdaemon_sync

[ W(20) : 0000 : 13:09:46 ] FidToNodeid: called for volume root
(50328f88.ff000001)!!!

[ D(21) : 0000 : 13:09:51 ] WAITING(SRVRQ):

[ V(05) : 0000 : 13:09:51 ] userent::Connect:
ViceGetAttrPlusSHA(floyd.netego.de)
[ V(05) : 0000 : 13:09:51 ] userent::Connect: ViceGetAttrPlusSHA() -> 22
[ V(05) : 0000 : 13:09:51 ] userent::Connect: VGAPlusSHA_Supported -> 1

[ D(21) : 0000 : 13:09:51 ] WAIT OVER, elapsed = 19.5
[ D(21) : 0000 : 13:09:51 ] userent::Connect:
ViceGetAttrPlusSHA(floyd.netego.de)
[ D(21) : 0000 : 13:09:51 ] userent::Connect: ViceGetAttrPlusSHA() -> 22
[ D(21) : 0000 : 13:09:51 ] userent::Connect: VGAPlusSHA_Supported -> 1

[ T(01) : 0001 : 13:10:01 ] BeginRvmFlush (1, 5156, T)
[ T(01) : 0001 : 13:10:02 ] EndRvmFlush

[ W(20) : 0000 : 13:10:02 ] Cachefile::SetLength 512
[ W(20) : 0000 : 13:10:02 ] worker::main Got a bogus opcode 36

[ V(05) : 0002 : 13:10:07 ] Reintegrate

[ I(22) : 0000 : 13:10:08 ] repvol::Reintegrate
[ I(22) : 0000 : 13:10:08 ] userent::Connect:
ViceGetAttrPlusSHA(floyd.netego.de)
[ I(22) : 0000 : 13:10:08 ] userent::Connect: ViceGetAttrPlusSHA() -> 22
[ I(22) : 0000 : 13:10:08 ] userent::Connect: VGAPlusSHA_Supported -> 1
[ I(22) : 0000 : 13:10:08 ] mysha(20, 20) =
8f.be.f9.c3.09.b4.d0.79.2d.57.cf.44.47.f0.d4.f9.9b.df.73.e2
.[ I(22) : 0000 : 13:10:08 ] mysha(20, 20) =
fb.ed.ab.f0.0f.a1.13.9b.68.a9.32.53.31.a2.96.29.73.24.91.8d
.[ I(22) : 0000 : 13:10:08 ] mysha(20, 20) =
f5.f8.53.ff.82.19.85.6d.fa.7b.bd.25.ce.50.41.03.3a.a0.2d.72
.[ I(22) : 0000 : 13:10:08 ] mysha(20, 20) =
e7.a6.09.64.5b.1d.f6.fa.9d.ed.bc.a3.4d.3d.54.30.2a.38.5f.14
.[ I(22) : 0000 : 13:10:08 ] volent::DisableASR: disabling asr for
7f000001
[ I(22) : 0000 : 13:10:08 ] ClientModifyLog::GetReintegrateable:
(florian, -101) 4 records, 46 msec
[ I(22) : 0000 : 13:10:08 ] volent::IncReintegrate: (florian, -101) uid =
500
[ I(22) : 0000 : 13:10:08 ] ClientModifyLog::IncReallocFids: (florian)
[ I(22) : 0000 : 13:10:08 ] ClientModifyLog::IncThread: (florian)
[ I(22) : 0000 : 13:10:08 ] ClientModifyLog::IncPack: (florian)
[ I(22) : 0000 : 13:10:08 ] userent::Connect:
ViceGetAttrPlusSHA(floyd.netego.de)
[ I(22) : 0000 : 13:10:08 ] userent::Connect: ViceGetAttrPlusSHA() -> 22
[ I(22) : 0000 : 13:10:08 ] userent::Connect: VGAPlusSHA_Supported -> 1
[ I(22) : 0000 : 13:10:08 ] ClientModifyLog::COP1: (florian), 532 bytes,
returns 198, index = 2
[ I(22) : 0000 : 13:10:08 ] volent::IncReintegrate: fail code = 198
	ClientModifyLog: owner = 500, count = 4
	  current stats:    1	      0.2	 21.5	  3	    0.8
	cancelled stats:    0	      0.0	  0.0	  0	    0.0
[...]
0x50311748 : fid = (50294108.7f000001.6f4.3bb), comp = posted, vol =
50293b08
	state = Normal, stat = { 8636, 54, 1062480290, 500, 0644, 1, File
}, rc rights = 3
	VV = {[ 56 0 0 0 0 0 0 0 ] [ 0xc03 1920 ] [ 0 ]}
	voltype = [0 1 0], fake = 0, fetching = 0 local = 0
	rep = 1, data = 0, owrite = 0, dirty = 0, shadow = 0
	mvstat = Normal
	parent = (50294108.7f000001.5f.290, 50312548), children = 0
	priority = 19825 (32479), hoard = [0, -2, 0], lastref = 15407
	mle_bindings = (0, 0), cleanstat = [-1, -1]
	cachefile = [ 00/00/00/91, -1, 0/0 ]
	refs = [0 0 0], openers = [0 0 0]	lastresolved = 0

VFS Operations
 Operation		   Counts		     Times
Root	      :      0	[    0	   0	 0]  :	  0.0 (  0.0)
OpenByFD      :      0	[    0	   0	 0]  :	  0.0 (  0.0)
Open	      :      1	[    0	   0	 0]  :	  1.1 (  0.0)
Close	      :      1	[    0	   0	 0]  :	  0.0 (  0.0)
Ioctl	      :      0	[    0	   0	 0]  :	  0.0 (  0.0)
Getattr       :      1	[    0	   0	 0]  :	  0.4 (  0.0)
Setattr       :      0	[    0	   0	 0]  :	  0.0 (  0.0)
Access	      :      3	[    0	   0	 0]  :	  1.2 (  2.0)
Lookup	      :      0	[    0	   0	 0]  :	  0.0 (  0.0)
Create	      :      0	[    0	   0	 0]  :	  0.0 (  0.0)
Remove	      :      0	[    0	   0	 0]  :	  0.0 (  0.0)
Link	      :      0	[    0	   0	 0]  :	  0.0 (  0.0)
Rename	      :      0	[    0	   0	 0]  :	  0.0 (  0.0)
Mkdir	      :      0	[    0	   0	 0]  :	  0.0 (  0.0)
Rmdir	      :      0	[    0	   0	 0]  :	  0.0 (  0.0)
Symlink       :      0	[    0	   0	 0]  :	  0.0 (  0.0)
Readlink      :      0	[    0	   0	 0]  :	  0.0 (  0.0)
Fsync	      :      0	[    0	   0	 0]  :	  0.0 (  0.0)
Vget	      :      0	[    0	   0	 0]  :	  0.0 (  0.0)
Signal	      :      0	[    0	   0	 0]  :	  0.0 (  0.0)
Replace       :      6	[    0	   0	 0]  :	  0.0 (  0.0)
Flush	      :      4	[    0	   0	 0]  :	  0.0 (  0.0)
PurgeUser     :      1	[    0	   0	 0]  :	  0.0 (  0.0)
ZapFile       :     17	[    0	   0	 0]  :	  0.0 (  0.0)
ZapDir	      :     47	[    0	   0	 0]  :	  0.0 (  0.0)
PurgeFid      :    249	[    0	   0	 0]  :	  0.0 (  0.0)
OpenByPath    :      0	[    0	   0	 0]  :	  0.0 (  0.0)
Resolve       :      0	[    0	   0	 0]  :	  0.0 (  0.0)
Reintegrate   :      0	[    0	   0	 1]  :	  0.0 (  0.0)
Statfs	      :      0	[    0	   0	 0]  :	  0.0 (  0.0)

RPC Operations:
 Operation	Good  Bad   Time MGood	MBad MTime   RPCR MRPCR
GetAttr 	     0	   0   0.0     0     0	 0.0	 0     0
GetACL		     0	   0   0.0     0     0	 0.0	 0     0
Fetch		     0	   0   0.0     0     0	 0.0	 0     0
SetAttr 	     0	   0   0.0     0     0	 0.0	 0     0
SetACL		     0	   0   0.0     0     0	 0.0	 0     0
Store		     0	   0   0.0     0     0	 0.0	 0     0
y		     0	   0   0.0     0     0	 0.0	 0     0
y		     0	   0   0.0     0     0	 0.0	 0     0
y		     0	   0   0.0     0     0	 0.0	 0     0
y		     0	   0   0.0     0     0	 0.0	 0     0
y		     0	   0   0.0     0     0	 0.0	 0     0
y		     0	   0   0.0     0     0	 0.0	 0     0
y		     0	   0   0.0     0     0	 0.0	 0     0
y		     0	   0   0.0     0     0	 0.0	 0     0
GetRootVolume	     0	   0   0.0     0     0	 0.0	 0     0
SetRootVolume	     0	   0   0.0     0     0	 0.0	 0     0
GetVolumeStatus      0	   0   0.0     0     0	 0.0	 0     0
SetVolumeStatus      0	   0   0.0     0     0	 0.0	 0     0
DisconnectFS	     0	   0   0.0     0     0	 0.0	 0     0
GetTime 	     0	   0   0.0     1     0	 1.1	 0     0
nExpired	     0	   0   0.0     0     0	 0.0	 0     0
GetOldStatistics     0	   0   0.0     0     0	 0.0	 0     0
GetStatistics	     0	   0   0.0     0     0	 0.0	 0     0
GetVolumeInfo	     0	   0   0.0     0     0	 0.0	 0     0
y		     0	   0   0.0     0     0	 0.0	 0     0
y		     0	   0   0.0     0     0	 0.0	 0     0
y		     0	   0   0.0     0     0	 0.0	 0     0
y		     0	   0   0.0     0     0	 0.0	 0     0
COP2		     0	   0   0.0     0     0	 0.0	 0     0
Resolve 	     0	   0   0.0     0     0	 0.0	 0     0
y		     0	   0   0.0     0     0	 0.0	 0     0
y		     0	   0   0.0     0     0	 0.0	 0     0
Repair		     0	   0   0.0     0     0	 0.0	 0     0
SetVV		     0	   0   0.0     0     0	 0.0	 0     0
y		     0	   0   0.0     0     0	 0.0	 0     0
y		     0	   0   0.0     0     0	 0.0	 0     0
AllocFids	     0	   0   0.0     0     0	 0.0	 0     0
ValidateAttrs	     0	   0   0.0     0     0	 0.0	 0     0
y		     0	   0   0.0     0     0	 0.0	 0     0
NewConnectFS	     4	   0   5.7     0     0	 0.0	 0     0
GetVolVS	     0	   0   0.0     1     0	 0.6	 0     0
ValidateVols	     0	   0   0.0     2     0	11.2	 0     0
y		     0	   0   0.0     0     0	 0.0	 0     0
y		     0	   0   0.0     0     0	 0.0	 0     0
VRemove 	     0	   0   0.0     0     0	 0.0	 0     0
VCreate 	     0	   0   0.0     0     0	 0.0	 0     0
VRename 	     0	   0   0.0     0     0	 0.0	 0     0
VSymLink	     0	   0   0.0     0     0	 0.0	 0     0
VLink		     0	   0   0.0     0     0	 0.0	 0     0
VMakeDir	     0	   0   0.0     0     0	 0.0	 0     0
VRemoveDir	     0	   0   0.0     0     0	 0.0	 0     0
y		     0	   0   0.0     0     0	 0.0	 0     0
y		     0	   0   0.0     0     0	 0.0	 0     0
y		     0	   0   0.0     0     0	 0.0	 0     0
OpenReintHandle      0	   0   0.0     0     0	 0.0	 0     0
QueryReintHandle     0	   0   0.0     0     0	 0.0	 0     0
SendReintFragment     0     0	0.0	0     0   0.0	  0	0
CloseReintHandle     0	   0   0.0     0     0	 0.0	 0     0
Reintegrate	     0	   0   0.0     0     1	 0.0	 0     0
GetWBPermit	     0	   0   0.0     0     0	 0.0	 0     0
TossWBPermit	     0	   0   0.0     0     0	 0.0	 0     0
RejectWBPermit	     0	   0   0.0     0     0	 0.0	 0     0
GetAttrPlusSHA	     4	   0   0.6     0     0	 0.0	 0     0
ValidateAttrsPlusSHA	 0     0   0.0	   6	 0  16.1     0	   0

RPC Packets:
RPC2:
   Sent:	   Total	Retrys	Busies	 Naks
      Uni:	 38 : 21319	    0	    0	    0
      Multi:	  0 : 0 	    0	    0	    0
   Received:	   Total	  Replys       Reqs	  Busies    Bogus
   Naks
      Uni:	 38 : 4480	   22 : 0	9 : 7	    0 : 0	0
      0
      Multi:	  0 : 0 	    0 : 0	0 : 0	    0 : 0	0
      0
SFTP:
   Sent:	   Total	Starts	   Datas       Acks    Naks  
Busies
      Uni:	  0 : 0 	    0	    0 : 0	  0	  0	 
0
      Multi:	  0 : 0 	    0	    0 : 0	  0	  0	 
0
   Received:	   Total	Starts	   Datas       Acks    Naks  
Busies
      Uni:	  0 : 0 	    0	    0 : 0	  0	  0	 
0
      Multi:	  0 : 0 	    0	    0 : 0	  0	  0	 
0

HDB:
counts = [625, 0, 0], namectxts = [0, 0, 0, 0] [0, 0]

connent: 1, 0, 24
srvent: 1, 0, 56
mgrpent: 3, 0, 564
vsgent: 1, 0, 64
volrep: 0, 0, 0
repvol: 0, 0, 0
binding: 7, 0, 252
namectxt: 0, 0, 0
resent: 0, 0, 0
cop2ent: 0, 0, 0
msgent: 1, 0, 8452
repair_session_tid = -1000000
repair_tid_gen = 1000000
subtree_view = SUBTREE_MIXED_VIEW
repair_root_fid = NULL
current_search_cml = NULL
repair_session_mode = REP_SCRATCH_MODE
there are 0 entries in repair_obj_list
=======================================================================
=======================================================================
there are 0 entries in repair_vol_list
=======================================================================
=======================================================================
there are 0 entries in repair_cml_list
=======================================================================
=======================================================================
there are 6 entries in the global-local-fid map
(local = 50328f88.ffffffff.ffffffff.2 global = 50294108.7f000001.151.caa)
(local = 50328f88.ffffffff.fffffffe.3 global =
50294108.7f000001.6b52.34b1)
(local = 50328f88.ffffffff.fffffffe.4 global =
50294108.7f000001.c58.52b0)
(local = 50328f88.ffffffff.fffffffe.5 global =
50294108.7f000001.24cc.84e0)
(local = 50328f88.ffffffff.fffffffe.6 global =
50294108.7f000001.24ce.84e1)
(local = 50328f88.ffffffff.fffffffe.7 global =
50294108.7f000001.25d2.84c1)
there are 1 entries in the root-fid map
====================================
	fake_root_fid = 50294108.7f000001.3cb.839b
	global_root_fid = 50294108.7f000001.151.caa
	local_root_fid = 50328f88.ffffffff.ffffffff.2
	root_parent_fid = 50294108.7f000001.43.282
	global_child_fid = 50294108.7f000001.fffffffc.80000
	LocalChildFid = 50294108.7f000001.fffffffc.80001
	name = config
	root_mtpt = 0
	root is not covered
	view = Mixed-View
====================================
************************

[ I(22) : 0001 : 13:10:15 ] BeginRvmFlush (1, 17316, F)
[ I(22) : 0001 : 13:10:15 ] EndRvmFlush

- -----------------[ rvmutl ]-----------------

root_at_zini:~ # rvmutl 
* o /usr/coda/LOG
* status
Status of log:		 /usr/coda/LOG

  log created on:	 Sun Sep 14 2003 14:41:04.277677
  log created with:	 RVM Interface Version 1.3  7 Mar 1994
			 RVM Log Version  1.4 Oct 17, 1997 
			 RVM Statistics Version 1.1 8 Dec 1992
  status last written:	 Fri Oct  3 2003 13:10:15.728607
  last truncation:	 Fri Oct  3 2003 13:09:46.398496

  log head offset:	     285552

  log tail offset:	     308396
  log empty:		 false

  space used by records:      22844
  space available:	     807620
  status area size:	       1536
  total log size:	     832000

  first record number:	       1132
  last record number:	       1135
  first timestamp:	 null
  last	timestamp:	 null
  first trans. uname:	 null
  last	trans. uname:	 null





-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.2.0 (GNU/Linux)
Comment: Get my DSA key from: www.netego.de/hpc?p=download&l=en

iD8DBQE/fWFq+2lxodi1OoURAmPXAJ984jOLNMwcsG6McfRN68PsvMnsXwCeNFRX
EXU5LV0/cwdkDLDCYmBNlfk=
=FYYE
-----END PGP SIGNATURE-----
Received on 2003-10-03 07:53:27