Hi, I am one of the maintainers of a OpenAFS cell. The cell runs on Debian 8.x with OpenAFS 1.6.15-1 from backports. The clients I use for maintenance are Debian 8.x and Debian 9.x, aka 1.6.15-1 and 1.6.20-2.
I have 2 volumes that refused to do a maintenance "vos move". I started to investigate one of the volumes. To my surprise, the "vos restore" fails from a Debian 9.x client. Then I tried to do a "bos salvage", but it did not found a problem. Then I upgraded the fileserver to Debian 9.x and repeated the "bos salvage" and the "vos restore" but there is still a problem. Follow what I think is the relevant logs. The SalsrvLog on the destination of a vos move is too big, so I can send it compressed by private email. I am open to do more tests and to provide more logs. The problematic volumes are preventing the a shutdown of the fileservers for a must needed maintenance. cat VolserLog on the destination fileserver during a vos restore: Fri Sep 1 15:01:17 2017 Starting AFS Volserver 2.0 (/usr/lib/openafs/davolserver -p 16 -udpsize 16777216) Fri Sep 1 15:30:49 2017 trans 22 on volume 538192990 is older than 300 seconds Fri Sep 1 15:31:19 2017 trans 22 on volume 538192990 is older than 330 seconds Fri Sep 1 15:31:49 2017 trans 22 on volume 538192990 is older than 360 seconds Fri Sep 1 15:32:19 2017 trans 22 on volume 538192990 is older than 390 seconds Fri Sep 1 15:32:49 2017 trans 22 on volume 538192990 is older than 420 seconds Fri Sep 1 15:33:19 2017 trans 22 on volume 538192990 is older than 450 seconds Fri Sep 1 15:33:49 2017 trans 22 on volume 538192990 is older than 480 seconds Fri Sep 1 15:34:19 2017 trans 22 on volume 538192990 is older than 510 seconds Fri Sep 1 15:34:49 2017 trans 22 on volume 538192990 is older than 540 seconds Fri Sep 1 15:35:19 2017 trans 22 on volume 538192990 is older than 570 seconds Fri Sep 1 15:35:49 2017 trans 22 on volume 538192990 is older than 600 seconds Fri Sep 1 15:36:19 2017 trans 22 on volume 538192990 is older than 630 seconds Fri Sep 1 15:36:49 2017 trans 22 on volume 538192990 is older than 660 seconds Fri Sep 1 15:37:19 2017 trans 22 on volume 538192990 is older than 690 seconds Fri Sep 1 15:37:50 2017 trans 22 on volume 538192990 is older than 720 seconds Fri Sep 1 15:38:20 2017 trans 22 on volume 538192990 is older than 750 seconds Fri Sep 1 15:38:50 2017 trans 22 on volume 538192990 is older than 780 seconds Fri Sep 1 15:39:20 2017 trans 22 on volume 538192990 is older than 810 seconds Fri Sep 1 15:39:50 2017 trans 22 on volume 538192990 is older than 840 seconds Fri Sep 1 15:40:04 2017 1 Volser: Delete: volume 538192990 deleted Fri Sep 1 15:40:26 2017 1 Volser: CreateVolume: volume 538193041 (test) created Fri Sep 1 15:40:48 2017 1 Volser: ReadVnodes: Error writing vnode index: Invalid argument; restore aborted Fri Sep 1 15:40:48 2017 Scheduling salvage for volume 538193041 on part /vicepa over FSSYNC Fri Sep 1 15:46:30 2017 1 Volser: Delete: volume 538193041 deleted Fri Sep 1 15:47:22 2017 1 Volser: CreateVolume: volume 538193042 (test) created Fri Sep 1 15:47:45 2017 1 Volser: ReadVnodes: Error writing vnode index: Invalid argument; restore aborted Fri Sep 1 15:47:45 2017 Scheduling salvage for volume 538193042 on part /vicepa over FSSYNC Fri Sep 1 15:54:21 2017 1 Volser: Delete: volume 538193042 deleted Sat Sep 2 08:57:39 2017 1 Volser: CreateVolume: volume 538193047 (test) created Sat Sep 2 08:58:03 2017 1 Volser: ReadVnodes: Error writing vnode index: Invalid argument; restore aborted Sat Sep 2 08:58:03 2017 Scheduling salvage for volume 538193047 on part /vicepa over FSSYNC >From a OpenAFS Client 1.6.20: bos salvage -server afs16 -partition /vicepa -volume ciist_compras005 -showlog -forceDAFS -localauth Starting salvage. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: waiting for salvage to complete. bos: salvage completed SalvageLog: @(#) OpenAFS 1.6.15-1-debian built 2015-11-29 08/28/2017 19:46:54 STARTING AFS SALVAGER 2.4 (/usr/lib/openafs/salvager -force) 08/28/2017 19:46:54 Starting salvage of file system partition /vicepa 08/28/2017 19:46:54 SALVAGING FILE SYSTEM PARTITION /vicepa (device=vicepa) 08/28/2017 19:46:54 ***Forced salvage of all volumes on this partition*** 08/28/2017 19:50:31 4 nVolumesInInodeFile 128 08/28/2017 19:50:31 CHECKING CLONED VOLUME 538034125. 08/28/2017 19:50:31 ciist_compras005.backup (538034125) updated 08/27/2017 21:35 08/28/2017 19:50:39 SALVAGING VOLUME 538034123. 08/28/2017 19:50:39 ciist_compras005 (538034123) updated 08/28/2017 19:41 08/28/2017 19:50:47 totalInodes 10388297 08/28/2017 21:24:09 Salvaged ciist_compras005 (538034123): 10385952 files, 19652064 blocks 08/28/2017 21:24:09 CHECKING CLONED VOLUME 538185110. 08/28/2017 21:24:09 base.groups2.readonly (538185110) updated 08/03/2017 17:19 08/28/2017 21:24:09 totalInodes 526 08/28/2017 21:24:09 SALVAGING OF PARTITION /vicepa COMPLETED vos move -id ciist_compras005 -fromserver afs16 -frompartition /vicepa -toserver afs15 -topartition /vicepa -verbose -localauth Starting transaction on source volume 538034123 ... done Allocating new volume id for clone of volume 538034123 ... done Cloning source volume 538034123 ... done Ending the transaction on the source volume 538034123 ... done Starting transaction on the cloned volume 538193048 ... done Setting flags on cloned volume 538193048 ... done Getting status of cloned volume 538193048 ... done Deleting pre-existing destination volume 538034123 ...Creating the destination volume 538034123 ... done Setting volume flags on destination volume 538034123 ... done Dumping from clone 538193048 on source to volume 538034123 on destination ... Failed to move data for the volume 538034123 VOLSER: Problems encountered in doing the dump ! vos move: operation interrupted, cleanup in progress... clear transaction contexts Recovery: Releasing VLDB lock on volume 538034123 ... done Recovery: Ending transaction on clone volume ... done Recovery: Ending transaction on destination volume ... done Recovery: Accessing VLDB. move incomplete - attempt cleanup of target partition - no guarantee Recovery:Deleting destination volume 538034123 ... done Recovery: Creating transaction on source volume 538034123 ... done Recovery: Setting flags on source volume 538034123 ... done Recovery: Ending transaction on source volume 538034123 ... done Recovery:Deleting clone volume 538193048 ... done cleanup complete - user verify desired result On afs15: head -40 VolserLog Sat Sep 2 09:52:47 2017 Starting AFS Volserver 2.0 (/usr/lib/openafs/davolserver -p 16 -udpsize 16777216) Sat Sep 2 09:54:51 2017 VReadVolumeDiskHeader: Couldn't open header for volume 538034123 (errno 2). Sat Sep 2 09:54:51 2017 attach2: forcing vol 538034123 to error state (state 0 flags 0x0 ec 103) Sat Sep 2 09:54:51 2017 1 Volser: CreateVolume: volume 538034123 (ciist_compras005) created Sat Sep 2 09:55:49 2017 1 Volser: ReadVnodes: Error writing vnode index: Invalid argument; restore aborted Sat Sep 2 09:55:49 2017 Scheduling salvage for volume 538034123 on part /vicepa over FSSYNC Sat Sep 2 09:55:49 2017 SYNC_ask: negative response on circuit 'FSSYNC' Sat Sep 2 09:55:49 2017 FSYNC_askfs: FSSYNC request denied for reason=65537 Sat Sep 2 09:55:49 2017 VAttachVolume: file server says volume 538034123 is salvaging Sat Sep 2 09:55:49 2017 Scheduling salvage for volume 538034123 on part /vicepa over FSSYNC Sat Sep 2 09:55:52 2017 SYNC_ask: negative response on circuit 'FSSYNC' Sat Sep 2 09:55:52 2017 FSYNC_askfs: FSSYNC request denied for reason=65537 Sat Sep 2 09:55:52 2017 VAttachVolume: file server says volume 538034123 is salvaging Sat Sep 2 09:55:52 2017 Scheduling salvage for volume 538034123 on part /vicepa over FSSYNC Sat Sep 2 09:55:55 2017 SYNC_ask: negative response on circuit 'FSSYNC' Sat Sep 2 09:55:55 2017 FSYNC_askfs: FSSYNC request denied for reason=65537 Sat Sep 2 09:55:55 2017 VAttachVolume: file server says volume 538034123 is salvaging Sat Sep 2 09:55:55 2017 Scheduling salvage for volume 538034123 on part /vicepa over FSSYNC Sat Sep 2 09:55:58 2017 SYNC_ask: negative response on circuit 'FSSYNC' Sat Sep 2 09:55:58 2017 FSYNC_askfs: FSSYNC request denied for reason=65537 Sat Sep 2 09:55:58 2017 VAttachVolume: file server says volume 538034123 is salvaging Sat Sep 2 09:55:58 2017 Scheduling salvage for volume 538034123 on part /vicepa over FSSYNC Sat Sep 2 09:56:01 2017 SYNC_ask: negative response on circuit 'FSSYNC' Sat Sep 2 09:56:01 2017 FSYNC_askfs: FSSYNC request denied for reason=65537 Sat Sep 2 09:56:01 2017 VAttachVolume: file server says volume 538034123 is salvaging Sat Sep 2 09:56:01 2017 Scheduling salvage for volume 538034123 on part /vicepa over FSSYNC Sat Sep 2 09:56:04 2017 SYNC_ask: negative response on circuit 'FSSYNC' Sat Sep 2 09:56:04 2017 FSYNC_askfs: FSSYNC request denied for reason=65537 Sat Sep 2 09:56:04 2017 VAttachVolume: file server says volume 538034123 is salvaging Sat Sep 2 09:56:04 2017 Scheduling salvage for volume 538034123 on part /vicepa over FSSYNC Sat Sep 2 09:56:07 2017 SYNC_ask: negative response on circuit 'FSSYNC' Sat Sep 2 09:56:07 2017 FSYNC_askfs: FSSYNC request denied for reason=65537 Sat Sep 2 09:56:07 2017 VAttachVolume: file server says volume 538034123 is salvaging Sat Sep 2 09:56:07 2017 Scheduling salvage for volume 538034123 on part /vicepa over FSSYNC Sat Sep 2 09:56:10 2017 SYNC_ask: negative response on circuit 'FSSYNC' Sat Sep 2 09:56:10 2017 FSYNC_askfs: FSSYNC request denied for reason=65537 Sat Sep 2 09:56:10 2017 VAttachVolume: file server says volume 538034123 is salvaging Sat Sep 2 09:56:10 2017 Scheduling salvage for volume 538034123 on part /vicepa over FSSYNC Sat Sep 2 09:56:13 2017 SYNC_ask: negative response on circuit 'FSSYNC' Sat Sep 2 09:56:13 2017 FSYNC_askfs: FSSYNC request denied for reason=65537 ls -alFh SalsrvLog -rw-r--r-- 1 root root 8.0M Set 2 09:57 SalsrvLog Kind regards Jose M Calhariz -- -- Então o Nhonho é um adulto horizontal!!! -- Chaves _______________________________________________ OpenAFS-info mailing list [email protected] https://lists.openafs.org/mailman/listinfo/openafs-info
