Coda File System

codasrv can't allocate RVM

From: Stephen J. Turnbull <turnbull_at_sk.tsukuba.ac.jp>
Date: Tue, 9 Oct 2001 19:32:48 +0900
I'm consistently getting a crash (assert at rvmlib.c l.209) as soon as
a client tries to update the server.  Any suggestions?  (I'm using
files for the RVM DATA and LOG, and yes, there's plenty of free space
on the partition.)  I've tried rebuilding from scratch, with CVS
updated today.  Same results.

If necessary, is there some way I can clear the log of the
"unreachable" entries without doing a full reinit and restore?  (See
SrvLog, below.)  These weird entries persist across server restarts
and crashes.  I basically don't care about the contents of any
individual files at the moment, my local files are all up-to-date in
my local CVS, and the rest is remote CVS and I have no pending changes
in my workspace that I'm worried about (and my real workspace has now
moved off Coda :-( ).

Here's what venus thinks about the volume being reintiegrated (that
triggers the crash):

bash-2.05$ cfs cs
Contacting servers .....
All servers up
bash-2.05$ cfs lv /coda/Software/XEmacs/Ben-Mule/
  Status of volume 0x7f000025 (2130706469) named "xe:ben-mule"
  Volume type is Replicated
  Connection State is Disconnected
  Write-back is disabled
  There are 5 CML entries pending for reintegration

Here's the volume that has the weird LOG entries (and just doing cfs
lv apparently crashed the codasrv, debugging is off but what appeared
is a (small) subset of what you see below):
bash-2.05$ cfs lv /coda/Software/XEmacs/Ben-Mule/
  Status of volume 0x7f000017 (2130706455) named "xe:21-5"
  Volume type is ReadWrite
  Connection State is Connected
  Minimum quota is 0, maximum quota is unlimited
  Current blocks used are 28743
  The partition has 469232 blocks available out of 727892
  Write-back is disabled

(SrvLog attached following SrvErr.)
Here's the (debug) SrvErr (debug=25):

[18:08:11]ClockTick: "ct.c", line 81:    Clock Tick at 1002618491
[18:08:18]SocketListener: "packet.c", line 196:    rpc2_RecvPacket()
[18:08:18]SocketListener: "sl.c", line 872:    HandleInit1()
[18:08:18]ServerLWP-0: "packet.c", line 102:    rpc2_XmitPacket()
[18:08:18]ServerLWP-0: "sftp1.c", line 263:    SFTP_NewConn()
[18:08:18]ServerLWP-0: "rpc2b.c", line 586:    RPC2_Enable()
[18:08:18]ServerLWP-0: "rpc2a.c", line 236:    RPC2_GetRequest()
[18:08:18]SocketListener: "packet.c", line 196:    rpc2_RecvPacket()
[18:08:18]SocketListener: "sl.c", line 762:    HandleNewRequest()
[18:08:18]ServerLWP-1: "sftp1.c", line 407:    SFTP_GetRequest()
[18:08:18]ServerLWP-1: "host.c", line 424:    RetryInterval: 0.300000
[18:08:18]ServerLWP-1: "rpc2a.c", line 547:    In RPC2_NewBinding()
[18:08:18]ServerLWP-1: "sftp1.c", line 212:    SFTP_Bind()
[18:08:18]ServerLWP-1: "packet.c", line 474:    rpc2_SendReliably()
[18:08:18]ServerLWP-1: "packet.c", line 102:    rpc2_XmitPacket()
[18:08:18]SocketListener: "packet.c", line 196:    rpc2_RecvPacket()
[18:08:18]SocketListener: "sl.c", line 964:    HandleInit2()
[18:08:18]SocketListener: "host.c", line 310:    uRTT: 0x5e61 24161 372
[18:08:18]SocketListener: "host.c", line 371:    Est: 130.158.98.109    0.024161/372   RTT:2558/5116 us BR:5094/8188 ns/B
[18:08:18]ServerLWP-1: "host.c", line 310:    uRTT: 0x18 24 120
[18:08:18]ServerLWP-1: "host.c", line 371:    Est: 130.158.98.109    0.000024/120   RTT:2238/4476 us BR:4775/6777 ns/B
[18:08:18]ServerLWP-1: "host.c", line 424:    RetryInterval: 0.300000
[18:08:18]ServerLWP-1: "rpc2a.c", line 374:    RPC2_MakeRPC()
[18:08:18]ServerLWP-1: "packet.c", line 474:    rpc2_SendReliably()
[18:08:18]ServerLWP-1: "packet.c", line 102:    rpc2_XmitPacket()
[18:08:18]SocketListener: "packet.c", line 196:    rpc2_RecvPacket()
[18:08:18]SocketListener: "sl.c", line 740:    HandleCurrentReply()
[18:08:18]SocketListener: "host.c", line 310:    uRTT: 0x787 1927 132
[18:08:18]SocketListener: "host.c", line 371:    Est: 130.158.98.109    0.001927/132   RTT:2055/3723 us BR:4477/5680 ns/B
[18:08:18]ServerLWP-1: "rpc2a.c", line 547:    In RPC2_NewBinding()
[18:08:18]ServerLWP-1: "sftp1.c", line 212:    SFTP_Bind()
[18:08:18]ServerLWP-1: "packet.c", line 474:    rpc2_SendReliably()
[18:08:18]ServerLWP-1: "packet.c", line 102:    rpc2_XmitPacket()
[18:08:18]SocketListener: "packet.c", line 196:    rpc2_RecvPacket()
[18:08:18]SocketListener: "sl.c", line 964:    HandleInit2()
[18:08:18]SocketListener: "host.c", line 310:    uRTT: 0xd9 217 372
[18:08:18]SocketListener: "host.c", line 371:    Est: 130.158.98.109    0.000217/372   RTT:1798/3306 us BR:4197/4820 ns/B
[18:08:18]ServerLWP-1: "host.c", line 310:    uRTT: 0x1 1 120
[18:08:18]ServerLWP-1: "host.c", line 371:    Est: 130.158.98.109    0.000001/120   RTT:1573/2929 us BR:3934/4140 ns/B
[18:08:18]ServerLWP-1: "host.c", line 424:    RetryInterval: 0.300000
[18:08:18]ServerLWP-1: "rpc2a.c", line 374:    RPC2_MakeRPC()
[18:08:18]ServerLWP-1: "packet.c", line 474:    rpc2_SendReliably()
[18:08:18]ServerLWP-1: "packet.c", line 102:    rpc2_XmitPacket()
[18:08:18]SocketListener: "packet.c", line 196:    rpc2_RecvPacket()
[18:08:18]SocketListener: "sl.c", line 740:    HandleCurrentReply()
[18:08:18]SocketListener: "host.c", line 310:    uRTT: 0xf8 248 124
[18:08:18]SocketListener: "host.c", line 371:    Est: 130.158.98.109    0.000248/124   RTT:1377/2590 us BR:3689/3596 ns/B
[18:08:18]ServerLWP-1: "rpc2a.c", line 155:    RPC2_SendResponse()
[18:08:18]ServerLWP-1: "sftp1.c", line 579:    SFTP_SendResponse()
[18:08:18]ServerLWP-1: "packet.c", line 102:    rpc2_XmitPacket()
[18:08:18]ServerLWP-1: "rpc2a.c", line 236:    RPC2_GetRequest()
[18:08:18]SocketListener: "packet.c", line 196:    rpc2_RecvPacket()
[18:08:18]SocketListener: "sl.c", line 762:    HandleNewRequest()
[18:08:18]ServerLWP-2: "sftp1.c", line 407:    SFTP_GetRequest()
[18:08:18]ServerLWP-2: "host.c", line 424:    RetryInterval: 0.300000
[18:08:18]ServerLWP-2: "rpc2a.c", line 374:    RPC2_MakeRPC()
[18:08:18]ServerLWP-2: "packet.c", line 474:    rpc2_SendReliably()
[18:08:18]ServerLWP-2: "packet.c", line 102:    rpc2_XmitPacket()
[18:08:18]SocketListener: "packet.c", line 196:    rpc2_RecvPacket()
[18:08:18]SocketListener: "sl.c", line 872:    HandleInit1()
[18:08:18]ServerLWP-3: "packet.c", line 474:    rpc2_SendReliably()
[18:08:18]ServerLWP-3: "packet.c", line 102:    rpc2_XmitPacket()
[18:08:18]SocketListener: "packet.c", line 196:    rpc2_RecvPacket()
[18:08:18]SocketListener: "sl.c", line 740:    HandleCurrentReply()
[18:08:18]SocketListener: "host.c", line 310:    uRTT: 0x58f 1423 132
[18:08:18]SocketListener: "host.c", line 371:    Est: 130.158.98.109    0.001423/132   RTT:1270/2155 us BR:3480/3115 ns/B
[18:08:18]ServerLWP-2: "rpc2a.c", line 155:    RPC2_SendResponse()
[18:08:18]ServerLWP-2: "sftp1.c", line 579:    SFTP_SendResponse()
[18:08:18]ServerLWP-2: "packet.c", line 102:    rpc2_XmitPacket()
[18:08:18]ServerLWP-2: "rpc2a.c", line 236:    RPC2_GetRequest()
[18:08:18]SocketListener: "packet.c", line 196:    rpc2_RecvPacket()
[18:08:18]SocketListener: "sl.c", line 1007:    HandleInit3()
[18:08:18]ServerLWP-3: "packet.c", line 102:    rpc2_XmitPacket()
[18:08:18]ServerLWP-3: "sftp1.c", line 263:    SFTP_NewConn()
[18:08:18]ServerLWP-3: "rpc2b.c", line 586:    RPC2_Enable()
[18:08:18]ServerLWP-3: "rpc2a.c", line 236:    RPC2_GetRequest()
[18:08:18]SocketListener: "packet.c", line 196:    rpc2_RecvPacket()
[18:08:18]SocketListener: "sl.c", line 762:    HandleNewRequest()
[18:08:18]ServerLWP-4: "sftp1.c", line 407:    SFTP_GetRequest()
[18:08:18]ServerLWP-4: "rpc2a.c", line 374:    RPC2_MakeRPC()
[18:08:18]ServerLWP-4: "packet.c", line 474:    rpc2_SendReliably()
[18:08:18]ServerLWP-4: "packet.c", line 102:    rpc2_XmitPacket()
[18:08:18]SocketListener: "packet.c", line 196:    rpc2_RecvPacket()
[18:08:18]SocketListener: "sl.c", line 740:    HandleCurrentReply()
[18:08:18]SocketListener: "host.c", line 310:    uRTT: 0x138 312 132
[18:08:18]SocketListener: "host.c", line 371:    Est: 130.158.98.109    0.000312/132   RTT:1112/1934 us BR:3262/2771 ns/B
[18:08:18]ServerLWP-4: "rpc2a.c", line 374:    RPC2_MakeRPC()
[18:08:18]ServerLWP-4: "packet.c", line 474:    rpc2_SendReliably()
[18:08:18]ServerLWP-4: "packet.c", line 102:    rpc2_XmitPacket()
[18:08:18]SocketListener: "packet.c", line 196:    rpc2_RecvPacket()
[18:08:18]SocketListener: "sl.c", line 740:    HandleCurrentReply()
[18:08:18]SocketListener: "host.c", line 310:    uRTT: 0xdc 220 124
[18:08:18]SocketListener: "host.c", line 371:    Est: 130.158.98.109    0.000220/124   RTT:973/1729 us BR:3059/2486 ns/B
[18:08:18]ServerLWP-4: "rpc2a.c", line 155:    RPC2_SendResponse()
[18:08:18]ServerLWP-4: "sftp1.c", line 579:    SFTP_SendResponse()
[18:08:18]ServerLWP-4: "packet.c", line 102:    rpc2_XmitPacket()
[18:08:18]ServerLWP-4: "rpc2a.c", line 236:    RPC2_GetRequest()
[18:08:18]SocketListener: "packet.c", line 196:    rpc2_RecvPacket()
[18:08:18]SocketListener: "multi3.c", line 755:    In HandleInitMulticast()
[18:08:18]SocketListener: "sftp6.c", line 383:    SFTP_InitMulticast()
[18:08:18]SocketListener: "packet.c", line 102:    rpc2_XmitPacket()
[18:08:18]SocketListener: "packet.c", line 196:    rpc2_RecvPacket()
[18:08:18]SocketListener: "sl.c", line 762:    HandleNewRequest()
[18:08:18]ServerLWP-5: "sftp1.c", line 407:    SFTP_GetRequest()
[18:08:18]ServerLWP-5: "rpc2a.c", line 859:    RPC2_InitSideEffect()
[18:08:18]ServerLWP-5: "sftp1.c", line 451:    SFTP_InitSE ()
[18:08:18]ServerLWP-5: "rpc2a.c", line 870:    RPC2_CheckSideEffect()
[18:08:18]ServerLWP-5: "sftp1.c", line 478:    SFTP_CheckSE()
[18:08:18]ServerLWP-5: "sftp1.c", line 507:    0x818c0d0[1124, 0]: [18:08:18]ServerLWP-5: "packet.c", line 102:    rpc2_XmitPacket()
[18:08:18]ServerLWP-5: "host.c", line 424:    RetryInterval: 0.300000
[18:08:18]SocketListener: "packet.c", line 196:    rpc2_RecvPacket()
[18:08:18]ServerLWP-5: "host.c", line 424:    RetryInterval: 0.300000
[18:08:18]SocketListener: "packet.c", line 196:    rpc2_RecvPacket()
[18:08:18]ServerLWP-5: "host.c", line 310:    uRTT: 0x2eb 747 1244
[18:08:18]ServerLWP-5: "host.c", line 371:    Est: 130.158.98.109    0.000747/1244  RTT:851/1540 us BR:2867/2247 ns/B
[18:08:18]ServerLWP-5: "sftp3.c", line 245:    sftp_UpdateBW: conn 0xa9b45cf, 1244 bytes, 1 ms
[18:08:18]ServerLWP-5: "host.c", line 424:    RetryInterval: 0.300000
[18:08:18]ServerLWP-5: "packet.c", line 102:    rpc2_XmitPacket()
RVMLIB_ASSERT: error in rvmlib_malloc

Assertion failed: 0, file "rvmlib.c", line 209
EXITING! Bye!

Here's the SrvLog:

18:07:08 New SrvLog started at Tue Oct  9 18:07:08 2001

18:07:08 Resource limit on data size are set to -1

18:07:08 RvmType is Rvm
18:07:08 Main process doing a LWP_Init()
18:07:08 Main thread just did a RVM_SET_THREAD_DATA

18:07:08 Setting Rvm Truncate threshhold to 5.

Partition /vicepa: inodes in use: 13435, total: 262144.
Partition /vicepb: inodes in use: 2495, total: 262144.
18:07:09 Partition /vicepa: 727892K available (minfree=5%), 469232K free.
18:07:09 Partition /vicepb: 930512K available (minfree=5%), 643440K free.
18:07:09 The server (pid 860) can be controlled using volutil commands
18:07:09 "volutil -help" will give you a list of these commands
18:07:09 If desperate,
		"kill -SIGWINCH 860" will increase debugging level
18:07:09 	"kill -SIGUSR2 860" will set debugging level to zero
18:07:09 	"kill -9 860" will kill a runaway server
18:07:09 Vice file system salvager, version 3.0.
18:07:09 SanityCheckFreeLists: Checking RVM Vnode Free lists.
18:07:09 DestroyBadVolumes: Checking for destroyed volumes.
18:07:09 Salvaging file system partition /vicepa
18:07:09 Force salvage of all volumes on this partition
18:07:09 Scanning inodes in directory /vicepa...
18:07:10 Entering DCC(0x1000001)
18:07:10 DCC: Salvaging Logs for volume 0x1000001

18:07:10 done:	74 files/dirs,	18040 blocks
18:07:10 Entering DCC(0x1000002)
18:07:10 DCC: Salvaging Logs for volume 0x1000002

18:07:10 done:	1727 files/dirs,	23576 blocks
18:07:10 Entering DCC(0x1000003)
18:07:10 DCC: Salvaging Logs for volume 0x1000003

18:07:10 done:	2352 files/dirs,	41082 blocks
18:07:10 Entering DCC(0x1000004)
18:07:10 DCC: Salvaging Logs for volume 0x1000004

18:07:10 recov_vol_log::SalvageLog: bitmaps are not equal

18:07:10 Log rec at index 276 is unreachable

    **Server: 0x829e626d StoreId: 0x7c1e77.6ac3 
    Directory(0x2ec1.16b6)
    Opcode: Mkdir 
    index is 276, sequence number 11885, var length is 17
    . [0x2ec1.16b6] owner 1000
    ** End of Record **

18:07:10 Log rec at index 278 is unreachable

    **Server: 0x829e626d StoreId: 0x7c1e77.6ac4 
    Directory(0x2ec1.16b6)
    Opcode: Mkdir 
    index is 278, sequence number 11886, var length is 19
    CVS [0x2ed1.16b7] owner 1000
    ** End of Record **

18:07:10 Log rec at index 280 is unreachable

    **Server: 0x829e626d StoreId: 0x7c1e77.6ac4 
    Directory(0x2ed1.16b7)
    Opcode: Mkdir 
    index is 280, sequence number 11887, var length is 17
    . [0x2ed1.16b7] owner 1000
    ** End of Record **

18:07:10 Log rec at index 282 is unreachable

    **Server: 0x829e626d StoreId: 0x7c1e77.6ac5 
    Directory(0x2ed1.16b7)
    Opcode: Create 
    index is 282, sequence number 11888, var length is 20
    Root [0xedd2.16c2] owner 0
    ** End of Record **

18:07:10 Log rec at index 351 is unreachable

    **Server: 0x829e626d StoreId: 0x7c1e77.6dcd 
    Directory(0x2ed1.16b7)
    Opcode: Remove 
    index is 351, sequence number 11924, var length is 60
    Root [0xedd2.16c2][0 0 0 0 0 0 0 0 (7c1e77.6dcd)(0x0)]
    ** End of Record **

18:07:10 Log rec at index 352 is unreachable

    **Server: 0x829e626d StoreId: 0x7c1e77.6dce 
    Directory(0x2ec1.16b6)
    Opcode: Rmdir 
    index is 352, sequence number 11925, var length is 35
    CVS [0x2ed1.16b7] del storeid [0x7c1e77.6dce]
    ** End of Record **

18:07:10 done:	1914 files/dirs,	28743 blocks
18:07:10 Entering DCC(0x1000005)
18:07:10 DCC: Salvaging Logs for volume 0x1000005

18:07:10 done:	4868 files/dirs,	62700 blocks
18:07:10 Entering DCC(0x1000006)
18:07:10 DCC: Salvaging Logs for volume 0x1000006

18:07:10 done:	897 files/dirs,	14583 blocks
18:07:10 Entering DCC(0x1000007)
18:07:10 DCC: Salvaging Logs for volume 0x1000007

18:07:10 done:	75 files/dirs,	293 blocks
18:07:10 Entering DCC(0x1000011)
18:07:10 DCC: Salvaging Logs for volume 0x1000011

18:07:10 done:	2660 files/dirs,	39410 blocks
18:07:10 SalvageFileSys completed on /vicepa
18:07:10 Salvaging file system partition /vicepb
18:07:10 Force salvage of all volumes on this partition
18:07:10 Scanning inodes in directory /vicepb...
18:07:11 SFS: There are some volumes without any inodes in them
18:07:11 SFS:No Inode summary for volume 0x1000008; skipping full salvage
18:07:11 SalvageFileSys: Therefore only resetting inUse flag
18:07:11 Entering DCC(0x1000009)
18:07:11 DCC: Salvaging Logs for volume 0x1000009

18:07:11 done:	1708 files/dirs,	22317 blocks
18:07:11 SFS:No Inode summary for volume 0x100000a; skipping full salvage
18:07:11 SalvageFileSys: Therefore only resetting inUse flag
18:07:11 SFS:No Inode summary for volume 0x100000b; skipping full salvage
18:07:11 SalvageFileSys: Therefore only resetting inUse flag
18:07:11 Entering DCC(0x100000c)
18:07:11 DCC: Salvaging Logs for volume 0x100000c

18:07:11 done:	36 files/dirs,	485 blocks
18:07:11 SFS:No Inode summary for volume 0x100000d; skipping full salvage
18:07:11 SalvageFileSys: Therefore only resetting inUse flag
18:07:11 Entering DCC(0x100000e)
18:07:11 DCC: Salvaging Logs for volume 0x100000e

18:07:11 done:	2 files/dirs,	3 blocks
18:07:11 Entering DCC(0x100000f)
18:07:11 DCC: Salvaging Logs for volume 0x100000f

18:07:11 done:	849 files/dirs,	258021 blocks
18:07:11 Entering DCC(0x1000010)
18:07:11 DCC: Salvaging Logs for volume 0x1000010

18:07:11 done:	3 files/dirs,	8 blocks
18:07:11 SalvageFileSys completed on /vicepb
18:07:11 VAttachVolumeById: vol 1000001 (coda:root.0) attached and online
18:07:11 VAttachVolumeById: vol 1000002 (xe:21-1.0) attached and online
18:07:11 VAttachVolumeById: vol 1000003 (xe:21-4.0) attached and online
18:07:11 VAttachVolumeById: vol 1000004 (xe:21-5.0) attached and online
18:07:11 VAttachVolumeById: vol 1000005 (xe:pkg.0) attached and online
18:07:11 VAttachVolumeById: vol 1000006 (xe:web.0) attached and online
18:07:11 VAttachVolumeById: vol 1000007 (xe:tools.0) attached and online
18:07:11 VAttachVolumeById: vol 1000008 (python.0) attached and online
18:07:11 VAttachVolumeById: vol 1000009 (ghost.0) attached and online
18:07:11 VAttachVolumeById: vol 100000a (coda.0) attached and online
18:07:11 VAttachVolumeById: vol 100000b (ug:micro.0) attached and online
18:07:11 VAttachVolumeById: vol 100000c (ug:dynamics.0) attached and online
18:07:11 VAttachVolumeById: vol 100000d (mba:nyuushi.0) attached and online
18:07:11 VAttachVolumeById: vol 100000e (steve.0) attached and online
18:07:11 VAttachVolumeById: vol 100000f (steve:mail.0) attached and online
18:07:11 VAttachVolumeById: vol 1000010 (zemi.0) attached and online
18:07:11 VAttachVolumeById: vol 1000011 (xe:ben-mule.0) attached and online
18:07:11 Attached 17 volumes; 0 volumes not attached
lqman: Creating LockQueue Manager.....LockQueue Manager starting .....
18:07:11 LockQueue Manager just did a rvmlib_set_thread_data()

done
18:07:11 CallBackCheckLWP just did a rvmlib_set_thread_data()

18:07:11 CheckLWP just did a rvmlib_set_thread_data()

18:07:11 ServerLWP 0 just did a rvmlib_set_thread_data()

18:07:11 ServerLWP 1 just did a rvmlib_set_thread_data()

18:07:11 ServerLWP 2 just did a rvmlib_set_thread_data()

18:07:11 ServerLWP 3 just did a rvmlib_set_thread_data()

18:07:11 ServerLWP 4 just did a rvmlib_set_thread_data()

18:07:11 ServerLWP 5 just did a rvmlib_set_thread_data()

18:07:11 ResLWP-0 just did a rvmlib_set_thread_data()

18:07:11 ResLWP-1 just did a rvmlib_set_thread_data()

18:07:11 VolUtilLWP 0 just did a rvmlib_set_thread_data()

18:07:11 VolUtilLWP 1 just did a rvmlib_set_thread_data()

18:07:11 Starting SmonDaemon timer
18:07:11 File Server started Tue Oct  9 18:07:11 2001

18:07:22 Set Debug On level = 1, RPC level = 0
18:07:24 Set Debug On level = 5, RPC level = 0
18:07:24 Set Debug On level = 25, RPC level = 2
0x817e188 : Cop Pending Manager
18:08:11 LockQueue Manager woken up
18:08:11 LockQueue Manager sleeping for 60 seconds
18:08:18 Worker 0 received request -13 on cid 794115898 for NA at NA
18:08:18 Cleaning up a HostTable for 0.0.0.0.0
18:08:18 DeleteVenus for venus 0.0.0.0.0
18:08:18 client_GetVenusId: got new host 130.158.98.109:1034
18:08:18 in AL_NameToId(System:AnyUser)
18:08:18 in AL_GetInternalCPS(-101, 0x8184e64)
18:08:18 New connection received RPCid 794115898, security lvl 98, rem id 352857848
18:08:18 Worker 1 received request 40 on cid 794115898 for root at 130.158.98.109
18:08:18 FS_ViceNewConnectFS (version 3) for user root at tleepslib.venus
18:08:18 Building callback conn.
18:08:18 No idle WriteBack conns, building new one
18:08:18 Writeback message to 130.158.98.109 port 1034 on conn 96dfd66 succeeded
18:08:18 FS_ViceNewConnectFS returns Success
18:08:18 Worker 2 received request 20 on cid 794115898 for root at 130.158.98.109
18:08:18 ViceGetTime for user root at 130.158.98.109:1034 on conn 794115898.
18:08:18 GetTime returns 1002618498, 187788, errorCode 0
18:08:18 Worker 3 received request -13 on cid 177948111 for NA at NA
18:08:18 in AL_IdToName(500)
18:08:18 Authorized Connection for user codakami, uid 500, Start 0, end 1002708494, time 1002618498
18:08:18 in AL_NameToId(codakami)
18:08:18 in AL_GetInternalCPS(500, 0x8186944)
18:08:18 New connection received RPCid 177948111, security lvl 12, rem id 353177336
18:08:18 Worker 4 received request 40 on cid 177948111 for codakami at 130.158.98.109
18:08:18 FS_ViceNewConnectFS (version 3) for user UID=00001000 at tleepslib.venus
18:08:18 Probing existing WriteBack conn 96dfd66
18:08:18 RevokeWBPermit on conn 96dfd66 returned 0
18:08:18 FS_ViceNewConnectFS returns Success
18:08:18 Worker 5 received request 59 on cid 177948111 for codakami at 130.158.98.109
18:08:18 ViceReintegrate: Volume = 7f000025
18:08:18 Starting ValidateReintegrateParms for 0x7f000025
18:08:18 ValidateReintegrateParms: RPCid = 177948111, *Vid = 7f000025
18:08:18 ValidateReintegrateParms: 7f000025 --> 1000011
18:08:18 ValidateReintegrateParms: codakami 130.158.98.109.1034
18:08:18 Reintegrate transferred 1124 bytes.
18:08:18 ValidateReintegrateParms: rlog count = 5
18:08:18 Entering VGetVolume for volume 1000011
18:08:18 VGetVolume: nUsers == 0
18:08:18 Entering AvailVolumeHeader()
18:08:18 Entering GetVolumeHeader()
18:08:18 GetVolObj: returns 0
18:08:18 ValidateReintegrateParms: returning Success
18:08:18 Starting  GetReintegrateObjects for 0x1000011
18:08:18 GetReintegrateObjects: client = codakami
18:08:18 Entering VGetVolume for volume 1000011
18:08:18 VGetVolume: nUsers == 1
18:08:18 GetVolObj: returns 0
18:08:18 AllocVnode: Fid = (1000011.ba12.10db), type = 1, pFid = (1000011.1421.983), Owner = 500
18:08:18 VAllocVnode: fid = (1000011.ba12.10db)
18:08:18 VAllocFid: fid = (1000011.ba12.10db)
18:08:18 VAllocBitmapEntry: volume = 1000011, vnode = ba12
18:08:18 VAllocBitmapEntry: bitmapOffset = 0, bitmapSize = 2976
18:08:18 VAllocBitmapEntry: realloc'ing from ba0 to bb0
18:08:18 Entering VAllocVnodeCommon: 
18:08:18 Entering ActiveVnodes for index 16, vclass = 1
18:08:18 vol_index.elts = 23808
18:08:18 Entering ActiveVnodes for index 16, vclass = 1
18:08:18 VAllocVnode: growing small vnode array
18:08:18 Entering GrowVnodes for volid 1000011, vclass 1
18:08:18 GrowVnodes: growing Small list from 23808 to 24064 for volume 0x1000011


-- 
University of Tsukuba                Tennodai 1-1-1 Tsukuba 305-8573 JAPAN
Institute of Policy and Planning Sciences       Tel/fax: +81 (298) 53-5091
	  Don't ask how you can "do" free software business;
	  ask what your business can "do for" free software.
Received on 2001-10-09 06:33:10