Drive removal seems stalled out?

[Sonicmojo]

A

Over the past few months I have been slowly upgrading the drives in my Pool. It's a 16TB pool with 4x4TB drives.

Last night around 7:00pm - I added the last new drive to the pool and targeted the last drive I wanted to replace. I checked Duplicate later and close all open files and let the process begin - as per usual - things moved along nicely and around 9:30 - I closed my RDP session to the server and let DP do it's thing.

When I checked back in this morning - I see the following on screen (see attached):

1. I see a ton of open files

2. The gauge has been at 94.0% like for hours

3. There is no file activity that I can see.

The only thing that DP is telling me is that - if I hover my cursor over the "Removing drive ...(94.0%) indicator near the bottom of the screen (where the progress bar is pulsating) I see a tooltip that say "removing pool part"

What the heck is going on and why is this taking hours upon hours? When I replaced my third drive a few days ago - the removal process completed cleanly, the drive I wanted to remove was 100% empty in about 5 hours and the UI was silent.

The drive I am removing here shows  949GB of "other" on it and this is causing me concern. This drive should have nothing on it if the removal process is working correctly.

Would love to know what is going on here and if I should just let it go, stop it or what? I do hear drive activity and drive LED's are flashing - but what is it doing?

S

Additional: Here are the last 20 lines of the Service log - anything here that looks suspect?

 

0:00:33.1: Information: 0 : [FsControl] Set overall pool mode: PoolModeNormal (lastKey=CoveFsPool, pool=c2cea73a-6516-4ed7-906e-864291ed7d8f)
0:03:22.7: Information: 0 : [Disks] Got MountPoint_Change (volume ID: dd88cf22-51f8-4ba9-a676-d0bb8b20430b)...
0:03:23.7: Information: 0 : [Disks] Updating disks / volumes...
0:03:30.1: Information: 0 : [Disks] Got MountPoint_Change (volume ID: dd88cf22-51f8-4ba9-a676-d0bb8b20430b)...
0:03:31.1: Information: 0 : [Disks] Updating disks / volumes...
0:03:43.1: Information: 0 : [Disks] Updating disks / volumes...
0:04:20.6: Information: 0 : [Disks] Got Pack_Arrive (pack ID: 0db29038-5dbc-4cdd-a784-5748d8b2f063)...
0:04:22.2: Information: 0 : [Disks] Updating disks / volumes...
0:04:50.5: Information: 0 : [Disks] Got Volume_Arrive (volume ID: f28ef3b5-4c91-44cb-9f35-7c76d4f97ef5, plex ID: 00000000-0000-0000-0000-000000000000, %: 0)...
0:04:51.6: Information: 0 : [Disks] Updating disks / volumes...
0:04:57.0: Information: 0 : [Disks] Got MountPoint_Change (volume ID: f28ef3b5-4c91-44cb-9f35-7c76d4f97ef5)...
0:04:58.0: Information: 0 : [Disks] Updating disks / volumes...
0:05:16.8: Information: 0 : [PoolPartUpdates] Found new pool part C6C614F2-7102-411D-B9C9-4D2F05B68ABB (isCloudDrive=False, isOtherPool=False)
0:05:27.3: Information: 0 : [FsControl] Set overall pool mode: PoolModeOverrideAllowCreateDirectories (lastKey=DrivePoolService.Pool.Tasks.RemoveDriveFromPool, pool=c2cea73a-6516-4ed7-906e-864291ed7d8f)
0:05:27.3: Information: 0 : [FsControl] Set overall pool mode: PoolModeNoReportIncomplete, PoolModeOverrideAllowCreateDirectories (lastKey=DrivePoolService.Pool.Tasks.RemoveDriveFromPool, pool=c2cea73a-6516-4ed7-906e-864291ed7d8f)
0:05:27.3: Information: 0 : [FsControl] Set overall pool mode: PoolModeNoReportIncomplete, PoolModeOverrideAllowCreateDirectories, PoolModeNoMeasure (lastKey=DrivePoolService.Pool.Tasks.RemoveDriveFromPool, pool=c2cea73a-6516-4ed7-906e-864291ed7d8f)
0:05:27.3: Information: 0 : [FsControl] Set overall pool mode: PoolModeNoReportIncomplete, PoolModeOverrideAllowCreateDirectories, PoolModeNoMeasure, PoolModeNoReparse (lastKey=DrivePoolService.Pool.Tasks.RemoveDriveFromPool, pool=c2cea73a-6516-4ed7-906e-864291ed7d8f)

 

 

 

[Sonicmojo]

Update.

After I returned home from work - the drive targeted for removal STILL said 94.1% so I killed the process and restarted the machine. Once it came back up - I assigned this drive it's own drive letter and examined the files in the Poolpart folder - seems all the files in there were the files I had set to duplicate.

So while that makes a bit of sense (I did tell DP to duplicate later) - I still do not understand why the removal stalled out and would not complete. I could have left this drive in this state for days with no change. Seems like a bug or something here.

After the drive was forcefully removed - DP went ahead and did a consistency check and then started a duplication run that took another couple of hours. Looks like everything is good now.

All my drives have been replaced so I will not need to do this exercise again for a while but I would still like to know why this drive was not removed cleanly.

S

 

[Christopher (Drashna)]

Could you enable logging, and then remove the drive? 
http://wiki.covecube.com/StableBit_DrivePool_2.x_Log_Collection

Also, as for "stalled out", any unduplicated data will cause it to take much longer. And it still has to check the data.

 

[Sonicmojo]

2 hours ago, Christopher (Drashna) said:

Could you enable logging, and then remove the drive? 
http://wiki.covecube.com/StableBit_DrivePool_2.x_Log_Collection

Also, as for "stalled out", any unduplicated data will cause it to take much longer. And it still has to check the data.

 

Well - the drive is gone now so enabling logging will not help.

And as far as unduplicated data - I used the same process for 4 consecutive drive removals. The first three went like clockwork...the "remove" drive process (whatever that entails) went to 100% and then DP did a consistency check and duplication AFTER the drive was removed completely.

This last drive "removal" not go to 100% - it simply sat at 94% for like 18 hours. For me there is long and then there is REALLY long. So I eventually got fed up - cancelled the removal and pulled the drive.

My concern is that this "remove" process did not go to 100%. There was zero file activity on the pools for hours and hours - so if DP was doing something - it should have been communicated.

Oddly - the only files left on this drive (after I killed it at 94% for 18 hours) - oddly - were just the duplicates. So I do not understand what the right conclusion to this process should be. I am assuming that if I choose to "process duplicates later" the removal process should be successful and go to 100%. Yes? No? In this case it seems like it was set up to sit at 94% forever.

Something was not right with this removal - the seemingly non-existent communication of the software (telling me exactly nothing for 18 straight hours) - should be looked at.

S

 

[Christopher (Drashna)]

the "Duplicate data later" option will leave data on the drive. It will leave any duplicated data on that drive, specifically.  you can then wipe the drive, or even copy it back into the pool, if you are so inclined (but it should run a duplication pass and reduplicate data as needed).

 

[Sonicmojo]

1 hour ago, Christopher (Drashna) said:

the "Duplicate data later" option will leave data on the drive. It will leave any duplicated data on that drive, specifically.  you can then wipe the drive, or even copy it back into the pool, if you are so inclined (but it should run a duplication pass and reduplicate data as needed).

 

This makes complete sense - but how come the actual "Remove drive" process never completed?

Is it not supposed to go to 100% (while leaving the dupe files on the drive) and conclude in a correct fashion?

In my case - DP simply stopped doing anything at 94% and sat there for hours and hours and hours. This feels very uncomfortable on many levels - yet I had no choice but to kill the process.

Luckily - there was no residual damage to my hard stop as all that was left on the drive where dupes. But this experience does not make me feel very trustworthy toward this app if a process cannot wrap up gracefully and correctly - especially when user data is being manipulated.

S

[Christopher (Drashna)]

I'm not sure why it just stopped.

If this happens again, run the StableBit Troubleshooter when it happens. 

 

[dropshadow]

This happened to me 2 out of 8 drive removals. I was moving from a 8 x 4 TB pool to an 8 x 8 TB pool. Note that I do not use duplication at all, my entire pool is unduplicated, and 100% of my 8 drives are dedicated to the pool

The first time the remove stalled out at 90.8%. I only checked the (2) duplicate later box. I ended up with ~340MBs that did not move. If I recall correctly, the error message said that WindowsSearchProtocol could not be moved.

On a hunch, I stopped the Windows Search service on my server on subsequent removals, which seemed to resolve this, because I did not see this particular message again on any further removals. I do index my entire pool with Windows Search.

The second time the remove stalled out at 94.1% (I think), I was watching it...for a LONG time...and I noticed every now and then, it would try to move "desktop.ini". I have a lot of these files. I could see DrivePool moving through directories and trying to move this file. It would do this over and over again. I finally gave up waiting and force restarted my server and just removed the drive. On this remove, I checked box 2) duplicate later and 3) force close any unduplicated file.

[Christopher (Drashna)]

Make sure you're on the beta version and see if this happens:
http://dl.covecube.com/DrivePoolWindows/beta/download/StableBit.DrivePool_2.2.3.960_x64_BETA.exe

[Sonicmojo]

3 hours ago, Christopher (Drashna) said:

Make sure you're on the beta version and see if this happens:
http://dl.covecube.com/DrivePoolWindows/beta/download/StableBit.DrivePool_2.2.3.960_x64_BETA.exe

Well - I am not about to remove a drive to test this version but it's nice to know something new is available.

Also glad I am not the only one experiencing this issue.

S

[bitfidelity]

The same thing just happened to me. I tried canceling the removal, but nothing happened, so I just restarted my machine. Then I saw this:

 

 

[bitfidelity]

I was able to remove the missing disk from the pool, and now DrivePool is checking.That process seems to be moving along, but for some reason, there's 555 MB of data left on Lakeport. But Windows Explorer isn't showing me anything aside from a few empty folders...