Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

xDiskAccessPath fails test for disk and accesspath after disk format and folder creation. #121

Closed
positivism1 opened this issue Oct 17, 2017 · 16 comments · Fixed by #209
Closed
Assignees
Labels
bug The issue is a bug. in progress The issue is being actively worked on by someone.

Comments

@positivism1
Copy link

xDiskAccessPath:
xDiskAccessPath fails the disk and access path test when the Disk and Folder are created within the same configuration.


VERBOSE: Perform operation 'Invoke CimMethod' with following parameters, ''methodName' = SendConfigurationApply,'className' = MSFT_DSCLocalConfigurationManager
,'namespaceName' = root/Microsoft/Windows/DesiredStateConfiguration'.
VERBOSE: An LCM method call arrived from computer TESTAPI with user sid S-1-5-21-1463861888-1148693830-2432142812-152739.
VERBOSE: [TESTAPI]: LCM:  [ Start  Set      ]
VERBOSE: [TESTAPI]: LCM:  [ Start  Resource ]  [[xDisk]Disk1]
VERBOSE: [TESTAPI]: LCM:  [ Start  Test     ]  [[xDisk]Disk1]
VERBOSE: [TESTAPI]:                            [[xDisk]Disk1] Test-TargetResource: Testing disk with Number '1' status for drive letter 'E'.
VERBOSE: [TESTAPI]:                            [[xDisk]Disk1] Test-TargetResource: Checking if disk with Number '1' is initialized.
VERBOSE: [TESTAPI]:                            [[xDisk]Disk1] Test-TargetResource: Disk with Number '1' is initialized with 'RAW' partition style. GPT required
.
VERBOSE: [TESTAPI]: LCM:  [ End    Test     ]  [[xDisk]Disk1]  in 2.3400 seconds.
VERBOSE: [TESTAPI]: LCM:  [ Start  Set      ]  [[xDisk]Disk1]
VERBOSE: [TESTAPI]:                            [[xDisk]Disk1] Set-TargetResource: Setting disk with Number '1' status for drive letter 'E'.
VERBOSE: [TESTAPI]:                            [[xDisk]Disk1] Set-TargetResource: Checking disk with Number '1' partition style.
VERBOSE: [TESTAPI]:                            [[xDisk]Disk1] Set-TargetResource: Initializing disk with Number '1'.
VERBOSE: [TESTAPI]:                            [[xDisk]Disk1] Set-TargetResource: Disk with Number '1' does not contain a partition assigned to drive letter 'E
'.
VERBOSE: [TESTAPI]:                            [[xDisk]Disk1] Set-TargetResource: Creating partition on disk with Number '1' with drive letter 'E' using all fr
ee space.
VERBOSE: [TESTAPI]:                            [[xDisk]Disk1] Set-TargetResource: Formatting the volume as 'NTFS'.
VERBOSE: [TESTAPI]: LCM:  [ End    Set      ]  [[xDisk]Disk1]  in 3.6750 seconds.
VERBOSE: [TESTAPI]: LCM:  [ End    Resource ]  [[xDisk]Disk1]
VERBOSE: [TESTAPI]: LCM:  [ Start  Resource ]  [[File]createDataFolder]
VERBOSE: [TESTAPI]: LCM:  [ Start  Test     ]  [[File]createDataFolder]
VERBOSE: [TESTAPI]:                            [[File]createDataFolder] The system cannot find the file specified.
VERBOSE: [TESTAPI]:                            [[File]createDataFolder] The related file/directory is: E:\DATA.
VERBOSE: [TESTAPI]: LCM:  [ End    Test     ]  [[File]createDataFolder]  in 0.0320 seconds.
VERBOSE: [TESTAPI]: LCM:  [ Start  Set      ]  [[File]createDataFolder]
VERBOSE: [TESTAPI]:                            [[File]createDataFolder] The system cannot find the file specified.
VERBOSE: [TESTAPI]:                            [[File]createDataFolder] The related file/directory is: E:\DATA.
VERBOSE: [TESTAPI]: LCM:  [ End    Set      ]  [[File]createDataFolder]  in 0.0150 seconds.
VERBOSE: [TESTAPI]: LCM:  [ End    Resource ]  [[File]createDataFolder]
VERBOSE: [TESTAPI]: LCM:  [ Start  Resource ]  [[xDiskAccessPath]dataAccessPath]
VERBOSE: [TESTAPI]: LCM:  [ Start  Test     ]  [[xDiskAccessPath]dataAccessPath]
VERBOSE: [TESTAPI]:                            [[xDiskAccessPath]dataAccessPath] Test-TargetResource: Testing disk with Number '2' status for access path 'E:\D
ATA\'.
VERBOSE: [TESTAPI]: LCM:  [ End    Test     ]  [[xDiskAccessPath]dataAccessPath]  in 0.1250 seconds.
PowerShell DSC resource MSFT_xDiskAccessPath  failed to execute Test-TargetResource functionality with error message: Access Path 'E:\DATA\' is not found.
Parameter name: AccessPath 
    + CategoryInfo          : InvalidOperation: (:) [], CimException
    + FullyQualifiedErrorId : ProviderOperationExecutionFailure
    + PSComputerName        : TestAPI
 
VERBOSE: [TESTAPI]: LCM:  [ End    Set      ]
The SendConfigurationApply function did not succeed.
    + CategoryInfo          : NotSpecified: (root/Microsoft/...gurationManager:String) [], CimException
    + FullyQualifiedErrorId : MI RESULT 1
    + PSComputerName        : TestAPI
 
VERBOSE: Operation 'Invoke CimMethod' complete.
VERBOSE: Time taken for configuration job to complete is 6.399 seconds


```**The DSC configuration that is using the resource (as detailed as possible):**

Configuration AccessPath
{

  Import-DscResource -ModuleName "xStorage"

Node 'TestAPI' {

        xDisk Disk1{
          DiskID = "1"
          DriveLetter = 'E'
          FSLabel = "TestAPI_E"
          FSFormat="NTFS"
          }

          File createDataFolder{
          Type = 'Directory'
          DestinationPath = "E:\DATA\"
          Ensure = 'Present'
          DependsOn = "[xDisk]Disk1"
          }
         xDiskAccessPath dataAccessPath{
          DiskID=2
          AccessPath="E:\DATA\"
          Size = 5GB
          FSLabel = "E_DATA"
          FSFormat = 'NTFS'
          }
}

}


**Version of the Operating System and PowerShell the DSC Target Node is running:**
Microsoft Windows Server 2016 Standard

Name Value


PSVersion 5.1.14393.1480
PSEdition Desktop
PSCompatibleVersions {1.0, 2.0, 3.0, 4.0...}
BuildVersion 10.0.14393.1480
CLRVersion 4.0.30319.42000
WSManStackVersion 3.0
PSRemotingProtocolVersion 2.3
SerializationVersion 1.1.0.1


**Version of the DSC module you're using, or 'dev' if you're using current dev branch:**
Dev
@PlagueHO PlagueHO self-assigned this Oct 20, 2017
@PlagueHO PlagueHO added bug The issue is a bug. help wanted The issue is up for grabs for anyone in the community. labels Oct 20, 2017
@PlagueHO
Copy link
Member

Thanks for raising this @positivism1. I've come across similar problems to this when mounting disks. It seems that sometimes there is a delay after a disk is formatted before it becomes fully available.

Can you confirm a few things for me?

Which version of xStorage are you using?
Does the configuration go into alignment correctly if applied a second time?

Could you try adding an xWaitForDisk step after the xDisk step? E.g.

        xDisk Disk1{
          DiskID = "1"
          DriveLetter = 'E'
          FSLabel = "TestAPI_E"
          FSFormat="NTFS"
          }
        xWaitForDisk WaitForDisk1{
          DiskID = "1"
          }

This may help, but I'll see if I can replicate the issue and get a better resolution.

@positivism1
Copy link
Author

Version number of this module.

ModuleVersion = '3.2.0.0'

The configuration works really well if applied a second time.

I have tried adding the Wait, but with the same result.

Configuration:

            xDisk Disk1{
              DiskID = "1"
              DriveLetter = 'E'
              FSLabel = "ComputerName_E"
              FSFormat="NTFS"
              }
                 
             xWaitForDisk WaitForDisk1{
              DiskID = "1"
                       }   
            File createDataFolder{
              Type = 'Directory'
              DestinationPath = "$($DriveLetter):\DATA\"
              Ensure = 'Present'
              DependsOn = "[xWaitForDisk]WaitForDisk1"
              }

            xDiskAccessPath dataAccessPath{
              DiskID=2
              AccessPath="E:\DATA\"
              Size = 5GB
              FSLabel = "DATA"
              FSFormat = 'NTFS'
              DependsOn = "[File]createDataFolder"
              }

Result:

VERBOSE: Perform operation 'Invoke CimMethod' with following parameters, ''methodName' = SendConfigurationApply,'className' = MSFT_DSCLocalConfigurationManager,'namespaceName' = root/Microsoft/Windows/Desi
redStateConfiguration'.
VERBOSE: An LCM method call arrived from computer Server001 with user sid S-1-5-21-1463861888-1148693830-2432142812-152739.
VERBOSE: [Server001]: LCM:  [ Start  Set      ]
VERBOSE: [Server001]: LCM:  [ Start  Resource ]  [[xDisk]Disk1]
VERBOSE: [Server001]: LCM:  [ Start  Test     ]  [[xDisk]Disk1]
VERBOSE: [Server001]:                            [[xDisk]Disk1] Test-TargetResource: Testing disk with Number '1' status for drive letter 'E'.
VERBOSE: [Server001]:                            [[xDisk]Disk1] Test-TargetResource: Checking if disk with Number '1' is initialized.
VERBOSE: [Server001]:                            [[xDisk]Disk1] Test-TargetResource: Disk with Number '1' is initialized with 'RAW' partition style. GPT required.
VERBOSE: [Server001]: LCM:  [ End    Test     ]  [[xDisk]Disk1]  in 4.1730 seconds.
VERBOSE: [Server001]: LCM:  [ Start  Set      ]  [[xDisk]Disk1]
VERBOSE: [Server001]:                            [[xDisk]Disk1] Set-TargetResource: Setting disk with Number '1' status for drive letter 'E'.
VERBOSE: [Server001]:                            [[xDisk]Disk1] Set-TargetResource: Checking disk with Number '1' partition style.
VERBOSE: [Server001]:                            [[xDisk]Disk1] Set-TargetResource: Initializing disk with Number '1'.
VERBOSE: [Server001]:                            [[xDisk]Disk1] Set-TargetResource: Disk with Number '1' does not contain a partition assigned to drive letter 'E'.
VERBOSE: [Server001]:                            [[xDisk]Disk1] Set-TargetResource: Creating partition on disk with Number '1' with drive letter 'E' using all free space.
VERBOSE: [Server001]:                            [[xDisk]Disk1] Set-TargetResource: Formatting the volume as 'NTFS'.
VERBOSE: [Server001]: LCM:  [ End    Set      ]  [[xDisk]Disk1]  in 4.6570 seconds.
VERBOSE: [Server001]: LCM:  [ End    Resource ]  [[xDisk]Disk1]
VERBOSE: [Server001]: LCM:  [ Start  Resource ]  [[xWaitForDisk]WaitForDisk1]
VERBOSE: [Server001]: LCM:  [ Start  Test     ]  [[xWaitForDisk]WaitForDisk1]
VERBOSE: [Server001]:                            [[xWaitForDisk]WaitForDisk1] Test-TargetResource: Checking for disk with Number '1'.
VERBOSE: [Server001]:                            [[xWaitForDisk]WaitForDisk1] Test-TargetResource: Found disk with Number '1' named 'VMware Virtual disk'.
VERBOSE: [Server001]: LCM:  [ End    Test     ]  [[xWaitForDisk]WaitForDisk1]  in 0.1100 seconds.
VERBOSE: [Server001]: LCM:  [ Skip   Set      ]  [[xWaitForDisk]WaitForDisk1]
VERBOSE: [Server001]: LCM:  [ End    Resource ]  [[xWaitForDisk]WaitForDisk1]
VERBOSE: [Server001]: LCM:  [ Start  Resource ]  [[File]createDataFolder]
VERBOSE: [Server001]: LCM:  [ Start  Test     ]  [[File]createDataFolder]
VERBOSE: [Server001]:                            [[File]createDataFolder] The system cannot find the file specified.
VERBOSE: [Server001]:                            [[File]createDataFolder] The related file/directory is: E:\DATA.
VERBOSE: [Server001]: LCM:  [ End    Test     ]  [[File]createDataFolder]  in 0.0780 seconds.
VERBOSE: [Server001]: LCM:  [ Start  Set      ]  [[File]createDataFolder]
VERBOSE: [Server001]:                            [[File]createDataFolder] The system cannot find the file specified.
VERBOSE: [Server001]:                            [[File]createDataFolder] The related file/directory is: E:\DATA.
VERBOSE: [Server001]: LCM:  [ End    Set      ]  [[File]createDataFolder]  in 0.0150 seconds.
VERBOSE: [Server001]: LCM:  [ End    Resource ]  [[File]createDataFolder]
VERBOSE: [Server001]: LCM:  [ Start  Resource ]  [[xDiskAccessPath]dataAccessPath]
VERBOSE: [Server001]: LCM:  [ Start  Test     ]  [[xDiskAccessPath]dataAccessPath]
VERBOSE: [Server001]:                            [[xDiskAccessPath]dataAccessPath] Test-TargetResource: Testing disk with Number '2' status for access path 'E:\DATA\'.
VERBOSE: [Server001]: LCM:  [ End    Test     ]  [[xDiskAccessPath]dataAccessPath]  in 0.1720 seconds.
PowerShell DSC resource MSFT_xDiskAccessPath  failed to execute Test-TargetResource functionality with error message: Access Path 'E:\DATA\' is not found.
Parameter name: AccessPath 
    + CategoryInfo          : InvalidOperation: (:) [], CimException
    + FullyQualifiedErrorId : ProviderOperationExecutionFailure
    + PSComputerName        : Server001
 
VERBOSE: [Server001]: LCM:  [ End    Set      ]
The SendConfigurationApply function did not succeed.
    + CategoryInfo          : NotSpecified: (root/Microsoft/...gurationManager:String) [], CimException
    + FullyQualifiedErrorId : MI RESULT 1
    + PSComputerName        : Server001
 
VERBOSE: Operation 'Invoke CimMethod' complete.
VERBOSE: Time taken for configuration job to complete is 10.614 seconds

@PlagueHO
Copy link
Member

PlagueHO commented Nov 4, 2017

Thanks for this @positivism1 - I'm planning on spending some time working on issues with this resource over the next week or two and I'll see if I can replicate this one and fix it for you. Sorry about the time taken to look into this.

@VistraX
Copy link

VistraX commented Nov 8, 2017

@PlagueHO I've had this problem too, and it seemed to be a timing issue. When running it a second time right after the folder creations it still failed (and third, fourth), but after an arbitrary amount of time, a re-run worked and configured the folder mounts.

There seems to be some background 'disk refresh' process that 'helps'.

I tried doing a 'Update-Disk' for the disk that the folders where created on, but this didn't affect it.

@PlagueHO
Copy link
Member

PlagueHO commented Nov 8, 2017

Thanks @VistraX - I think you're right. I've not run into this problem in this resource but I have run across it with other disk automation processes in PowerShell.

What we need to be able to do is trigger the disk subsystems to refresh fully before returning the from the Set-TargetResource. I'll make a new version this weekend with some calls to additional functions (such as Get-PSDrive) to see if we can some how trigger the refresh. I might need a hand testing this as I've actually not been able to replicate the issue on any of my VM's/machines.

@positivism1
Copy link
Author

Yep. Get-PSDrive is required if the drive fails to appear in the FileSystem PSPRovider.

I wrote this Script resource to fix it temporarily.

     Script getPSDrive{
                GetScript= {write @{}}
                TestScript = {
                  write-verbose "Checking if PSDrive exists: $($psDrive.name)"
                    if (!($psDrive))
                    {
                        write-verbose ("E Drive failed to appear refreshing PSDrive")
                        Get-PSDrive | out-null
                        $psDrive = Get-PSDrive -Name E

                    }
                    else
                    {
                        write-verbose ("No need to refresh PSDrives")
                        write-verbose "TEST - PSDrive: $($psDrive.name)"

                    }
                   
                         return $true
                                    }
                SetScript = {write @{}}
                DependsOn = "[xDisk]Disk1"
            } 

I'm happy to try get the xDiskAccessPath to do the Get-PSDrive.

Within the Set-TargetResource check if Get-PSDrive can find the correct FileSystem name based on the Disk letter provided by the AccessPath?

@PlagueHO
Copy link
Member

PlagueHO commented Nov 9, 2017

Hi @positivism1 - definitely! If you want to have a go at this and submit a PR for it then I'd be really happy to help you get it merged (e.g. update the tests, CHANGELOG.MD etc). We're always grateful for the assistance! 😁

@positivism1
Copy link
Author

Pull requests submitted....

Let me know what else needs to happen, Its my first day :-)

@PlagueHO
Copy link
Member

Hi @positivism1 - I couldn't find your PR, but I eventually tracked it down. You've actually issued the PR to your own repo 😀 - you'll want to submit the PR to this one (a.k.a. the upstream fork). e.g. submit the PR to PowerShell/xStorage rather than positivism1/xStorage. That way it'll be merged into this repo when we accept the PR.

But we're very grateful for the help and I'll definitely help you through the process as everyone has had a "first day" 😁 So no worries if something isn't quite right - that is what a code review is for and I'll help you through the process.

@PlagueHO
Copy link
Member

PlagueHO commented Nov 12, 2017

P.S. when you've submitted the PR to this repo it'll show up here (DOH! I actually pasted your PR address in here by accident first 😁):
https://github.com/PowerShell/xStorage/pulls

@positivism1
Copy link
Author

Alright, let me try this again.. haha

@tcotten
Copy link

tcotten commented Jun 6, 2018

I've also run into this issue and will try to pick up where positivism1 left off.

@aleksbor
Copy link

Hello Everyone, what is the ETA for this fix?

@PlagueHO
Copy link