Skip to content

Conversation

@paalbra
Copy link
Contributor

@paalbra paalbra commented Oct 26, 2018

PR Summary

Currently Start-Transcript will delete the file it refers to if it's not set to append. This might lead to issues if the user running the command only has access to the file and not the parent folder. This PR makes sure the file is emptied rather than deleted. There are more details in the issue. Fix #4065.

PR Checklist

P.S.

This is my first PR in this project. I'm hopefully doing things right...

@iSazonov
Copy link
Collaborator

My understanding is that currently we write an error and remove the file. Your suggestion is don'nt remove the file but wipe. Right?

/cc @mklement0 What do you think about the special case?

@paalbra
Copy link
Contributor Author

paalbra commented Oct 27, 2018

My understanding is that currently we write an error and remove the file. Your suggestion is don'nt remove the file but wipe. Right?

Well, kind of. The file is deleted and when Start-Transcript tries to recreate the file you get an access denied error (if the access is set in a way mentioned in #4065 ). But it is a bit OS/filesystem dependent.

This can be avoided by not deleting the file, but rather wiping it.

The fix should not alter the behavior of successful usage of Start-Transcript, but it will fix this special access case.

@iSazonov
Copy link
Collaborator

@paalbra Thanks for clarification! I don't like the change because there can be very many permission combinations and we can not address all cases. Ex.: user could allow file removing and disable creation or create as read-only. Also on user system there could be a protection application which can overlap system assigned permissions.

@mklement0
Copy link
Contributor

I too agree that we shouldn't special-case this:

Start-Tanscript makes no promises about preexisting files; it blindly tries to replace them, and always creates the new files with the default permissions.

In other words: loss of any preexisting file with the same name is always to be expected and no relationship between the old and the new file can and should be assumed.

That creation of a new file then fails, is a separate issue, and requires that the permissions be set accordingly on the enclosing directory to allow file creation by the current user - which strikes me as reasonable.

@paalbra: Your scenario sounds exotic and the steps to reproduce it (as shown in #4065) are quite involved. Is this a real-life scenario you've run into, and why would you expect to run into this repeatedly?

@iSazonov
Copy link
Collaborator

@mklement0 Thanks!

@SteveL-MSFT Please confirm that current behavior is "by-design" and we can not accept the PR.

@SteveL-MSFT
Copy link
Member

According to the documentation, one must use the existing -NoClobber switch otherwise the default is to clobber if the path is specified (otherwise it generates a unique log name to avoid collisions). This is currently by-design.

@paalbra
Copy link
Contributor Author

paalbra commented Oct 28, 2018

Yes, I've run into this issue in my real-life environment. I don't view this issue as a special or exotic case myself.

You could even compare this to Out-File which also has an Append parameter. Out-File has no issues with the same access permissions set because Out-File doesn't delete the file. I would expect both commands to work in this setup and this is what I try to fix with this PR.

@SteveL-MSFT
Copy link
Member

@paalbra I appreciate you bringing up this inconsistent experience and taking the time to submit a PR, however, we need to balance changes with impact to backwards compatibility. In this specific case, it seems the current behavior is documented so it's not a strong enough justification to change the current behavior. (I'm always open to reconsidering if there's sufficient community feedback)

@paalbra
Copy link
Contributor Author

paalbra commented Oct 28, 2018

With the current behavior you also have other bad side effects. E.g. you can't point Start-Transcript to a symlink. If you do Start-Transcript will just delete the symlink and create a file.

There is simply no reason for Start-Transcript to delete the file. I should just overwrite the file. This is also what it says that it does in the documentation. Overwriting a file is not the same as recreating a file. So I think the current documentation and behavior don't match.

@paalbra
Copy link
Contributor Author

paalbra commented Oct 28, 2018

I really can't agree that the behavior is the same as the documentation.

Again you could compare Start-Transcript and Out-File. They both have similar documentation when it comes to Append and NoClobber, but they do not behave the same way.

@mklement0
Copy link
Contributor

@paalbra:

I see your point now: Out-File (without -Append) / > and Set-Content indeed open a preexisting file and truncate it before writing the new content.
> in POSIX-like shells works the same.

In light of this, I think your PR has merit.

@SteveL-MSFT:

Unless I'm missing something, I think this PR would be an easy consistency improvement that shouldn't impact existing scripts.

@SteveL-MSFT
Copy link
Member

@paalbra I misunderstood the intent, but thanks to @mklement0 I get it. Based on the explanation, I would agree that this PR makes sense particularly in the symlink case.

@SteveL-MSFT SteveL-MSFT changed the title Avoid file deletion in Start-Transcript when not appending When using Start-Transcript and file exists, empty file rather than deleting Oct 28, 2018
@SteveL-MSFT
Copy link
Member

@paalbra it would be great if you can add a test for this specific behavior. You can probably just check the file creation date hasn't changed.

@iSazonov iSazonov self-assigned this Oct 29, 2018
@paalbra
Copy link
Contributor Author

paalbra commented Oct 29, 2018

@SteveL-MSFT I'm not very familiar with the project yet, since this is my first PR, but I'll certainly look into adding more tests.

@iSazonov
Copy link
Collaborator

iSazonov commented Oct 29, 2018

@SteveL-MSFT
Copy link
Member

@paalbra Just give it a try and we'll make suggestions :)

@paalbra
Copy link
Contributor Author

paalbra commented Oct 29, 2018

Ok, so I've tried to add a test that checks creation time, as suggested by @SteveL-MSFT , but I've encountered some problems.

I've tried to add something like

    It "Should not change the creation time of existing file" {
        $oldDate = (Get-Date).AddDays(-1)
        "" | Out-File -FilePath $transcriptFilePath
        (Get-Item $transcriptFilePath).CreationTime = $oldDate
        Start-Transcript -Path $transcriptFilePath
        Stop-Transcript

        (Get-Item $transcriptFilePath).CreationTime | Should -Be $oldDate
    }

The thing is that the CreationTime property on Windows apparently does not change when the file is recreated within a few seconds. This makes the whole test kind of useless since it won't fail.

PS C:\temp> "" | Out-File temp.txt; (gi temp.txt).creationtime.tostring("o"); del temp.txt; sleep -seconds 1; "" | Out-File temp.txt; (gi temp.txt).creationtime.tostring("o")
2018-10-29T22:13:09.4519817+01:00
2018-10-29T22:13:09.4519817+01:00

Also: I found out that on Ubuntu a modification of the CreationTime actually alters the LastAccessTime. So I can't really do the above test on Linux.

PS /home/myuser> "" | Out-File temp.txt
PS /home/myuser> gi ./temp.txt | % {$_.creationtime.tostring("o");$_.lastaccesstime.tostring("o")}
2018-10-29T22:32:19.7754239+01:00
2018-10-29T22:32:19.7754239+01:00
PS /home/myuser> (gi ./temp.txt).CreationTime = (get-date).adddays(-1)                               
PS /home/myuser> gi ./temp.txt | % {$_.creationtime.tostring("o");$_.lastaccesstime.tostring("o")}
2018-10-29T22:32:19.0000000+01:00
2018-10-28T22:32:36.0000000+01:00

The issue on Linux I could work around, but on Windows I'm not sure if I really can tell if a file has been deleted and recreated or not.

I'm not really sure what to do here as I quickly run into these kind of filesystem/OS dependent issues. Any suggestions?

@paalbra
Copy link
Contributor Author

paalbra commented Oct 29, 2018

A bit more of searching the web led me to the FileSystemWatcher class.

I guess I could use one of those and make a test that makes sure no file deletion events are emitted when running Start-Transcript. This seems a bit excessive to me though. Any thoughts?

@SteveL-MSFT
Copy link
Member

@paalbra Thanks for making the effort. I agree that using FileSystemWatcher is overkill for this. I suspect you can't reply on the CreationTime because the filesystem or disk driver hasn't flushed it before the write happens within that window. Another option (on Windows, perhaps skip on non-Windows) is to remove Delete permission from that file and check that no error is returned (see Set-Acl)

@msftclas
Copy link

msftclas commented Oct 30, 2018

CLA assistant check
All CLA requirements met.

@paalbra paalbra force-pushed the bugfix-4065 branch 2 times, most recently from 3f2233f to 3385cfc Compare October 30, 2018 17:07
@paalbra
Copy link
Contributor Author

paalbra commented Oct 30, 2018

I decided to try the FileSystemWatcher path since I got it working on Windows and Ubuntu (the test is failing in master and passing in my branch).

But for some reason it's failing on MacOS. I'm really not sure why and I currently have no Mac available for debugging. I'll try to get my hands on a Mac some day soon though...

@SteveL-MSFT
Copy link
Member

@paalbra there may be an issue in CoreFx where the file on macOS is deleted or that the event is being incorrectly raised

@vexx32
Copy link
Collaborator

vexx32 commented Oct 30, 2018

@paalbra looks like the file gets deleted on MacOS when you're not expecting it to, at least from the build logs:

2018-10-30T18:20:10.2962680Z TEST FAILURES
2018-10-30T18:20:10.2962740Z Description: Should not delete the file if it already exist
2018-10-30T18:20:10.2963680Z Name:        Start-Transcript, Stop-Transcript tests.Should not delete the file if it already exist
2018-10-30T18:20:10.2963770Z message:
2018-10-30T18:20:10.2964240Z Expected $null, but got 'FileDeleted'.
2018-10-30T18:20:10.2964700Z stack-trace:
2018-10-30T18:20:10.2965270Z at <ScriptBlock>, /Users/vsts/agent/2.141.1/work/1/s/test/powershell/Modules/Microsoft.Powershell.Host/Start-Transcript.Tests.ps1: line 127
2018-10-30T18:20:10.2965760Z 127:         Receive-Job $job | Should -Be $null
2018-10-30T18:20:10.2965830Z 1 tests in test/powershell failed
2018-10-30T18:20:10.2965890Z At /Users/vsts/agent/2.141.1/work/1/s/build.psm1:1347 char:13
2018-10-30T18:20:10.2966380Z +             throw "$($x.'test-results'.failures) tests in $TestArea f ...
2018-10-30T18:20:10.2966450Z +             ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
2018-10-30T18:20:10.2966990Z + CategoryInfo          : OperationStopped: (1 tests in test/powershell failed:String) [], RuntimeException
2018-10-30T18:20:10.2967050Z + FullyQualifiedErrorId : 1 tests in test/powershell failed

@mklement0
Copy link
Contributor

I have no explanation, but here's a data point: I just ran the test locally against this PR's code on my macOS 10.14 machine, and it succeeded in 100 successive invocations.

@iSazonov
Copy link
Collaborator

How we open the file? If "Read shared" we could open the file twice and check its content by second handle.

@paalbra
Copy link
Contributor Author

paalbra commented Nov 2, 2018

So, I've gotten my hands on a Mac (10.13.6) and done some debugging.

I also get failing results. Sometimes I actually see two file deletion events when running the test.

These failures seems to be related to the testdrive. I do not get failures if I modify the test to use some other path elsewhere. I'm not familiar with the testdrive and I honestly have no idea why the file somehow gets deleted multiple times from the testdrive when running the test. Apperently @mklement0 does not experience the same thing, which only makes it harder to understand.

@mklement0
Copy link
Contributor

mklement0 commented Nov 2, 2018

Interesting, @paalbra, but there's some consistency: I hadn't used the testdrive: drive in my tests.

@SteveL-MSFT
Copy link
Member

Perhaps to help isolate if this is a $TestDrive issue or something due to PSDrives, can you try creating a PSDrive and see if you still get delete events?

New-PSDrive -PSProvider FileSystem -Name MyTestDrive -Root $env:TMPDIR

@paalbra
Copy link
Contributor Author

paalbra commented Nov 3, 2018

Ok, so I've done some more testing. On MacOS the TestDrive doesn't seem to be "clean" between tests. Somehow the state/file deletion events "bleed through" from other tests. I've tried to resolve this by creating a new, unique path within my test and this seems to work. $transcriptFilePath = Join-Path $TestDrive ([System.IO.Path]::GetRandomFileName())

Any thoughts or feedback on this method?

@paalbra
Copy link
Contributor Author

paalbra commented Nov 3, 2018

I guess this is something you might want for all tests. So a better solution might be to create a new unique path in the BeforeAll block. I'm not sure I should touch that block in this PR though. It might be better to create this as an separate issue?

@mklement0
Copy link
Contributor

I think creating a unique path for this PR is definitely the way to go.

My sense is that we needn't worry about the other tests, as they don't use file-system watchers.

It is curious that only macOS is affected, though.

There are several open issues for the FileSystemWatcher type in the CoreFx repo, though only
one macOS-specific one and one cross-platform one: https://github.com/dotnet/corefx/issues?utf8=%E2%9C%93&q=is%3Aissue+is%3Aopen+filesystemwatcher++in%3Atitle

Another thing to try - though more out of curiosity, given that the use [System.IO.Path]::GetRandomFileName() seems like the best solution - is to call CLI sync beforehand, which commits pending disk writes system-wide - note that this can be expensive.

@SteveL-MSFT
Copy link
Member

@paalbra thanks for taking the time to investigate this. My suggestion is for this PR to have the macOS specific code path (with appropriate comments). Agree with @mklement0 that the other tests are probably ok although not ideal. It may be worthwhile to see if sync helps which would indicate to me that this is an OS problem with caching.

@paalbra
Copy link
Contributor Author

paalbra commented Nov 3, 2018

Adding sync doesn't seem to help. I've also tried adding sleep like this:

It "Should not delete the file if it already exist" {
    # Create an existing file
    #$transcriptFilePath = Join-Path $TestDrive ([System.IO.Path]::GetRandomFileName())
    Out-File $transcriptFilePath
    Start-Sleep -Seconds 20

    $FileSystemWatcher = [System.IO.FileSystemWatcher]::new((Split-Path -Parent $transcriptFilePath), (Split-Path -Leaf $transcriptFilePath))

    $Job = Register-ObjectEvent -InputObject $FileSystemWatcher -EventName "Deleted" -SourceIdentifier "FileDeleted" -Action {
        return "FileDeleted"
    }

    Start-Transcript -Path $transcriptFilePath
    Stop-Transcript

    Unregister-Event -SourceIdentifier "FileDeleted"

    # Nothing should have been returned by the FileSystemWatcher
    Receive-Job $job | Should -Be $null
}

The above actually makes the test pass on MacOS.

My guess is that the FileSystemWatcher receives some kind of old events. Maybe events from the previous AfterEach block where the file is removed.

I think the current solution, with unique file path, is the best for all OSes.

@iSazonov iSazonov requested a review from SteveL-MSFT November 6, 2018 06:22
Copy link
Member

@SteveL-MSFT SteveL-MSFT left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Only need to address @iSazonov's comment on try..finally

Copy link
Member

@SteveL-MSFT SteveL-MSFT left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM . Thanks!

@iSazonov iSazonov merged commit 2e89efa into PowerShell:master Nov 7, 2018
@iSazonov
Copy link
Collaborator

iSazonov commented Nov 7, 2018

@paalbra Thanks for your contribution!

@iSazonov iSazonov added the CL-General Indicates that a PR should be marked as a general cmdlet change in the Change Log label Jan 17, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

CL-General Indicates that a PR should be marked as a general cmdlet change in the Change Log

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Start-Transcript might silently delete the output file

6 participants