log4net:WARN Exception on package uninstall

[teknowledgist]

What You Are Seeing?

A strange Chocolatey exception message when I uninstall a package:

choco uninstall fastcopy.install -y

Chocolatey v0.10.3
Uninstalling the following packages:
fastcopy.install
fastcopy.install v3.30 

log4net:WARN Exception while rendering format [

contents of chocolateyUninstall.ps1

]
System.FormatException: Input string was not in a correct format.
   at System.Text.StringBuilder.AppendFormatHelper(IFormatProvider provider, Str
ing format, ParamsArray args)
   at System.String.FormatHelper(IFormatProvider provider, String format, Params
Array args)
   at System.String.Format(IFormatProvider provider, String format, Object[] arg
s)
   at log4net.Util.SystemStringFormat.StringFormat(IFormatProvider provider, Str
ing format, Object[] args)

Skipping auto uninstaller - No registry snapshot.
fastcopy.install has been successfully uninstalled.

Chocolatey uninstalled 1/1 packages. 0 packages failed.
See the log for details (C:\ProgramData\chocolatey\logs\chocolatey.log).

What is Expected?

The uninstall doesn't spit back the contents of the chocolateyuninstall.ps1 file.

Comments

The log has nothing useful in it -- no errors prior to the warning. While this does work, it looks ugly. How do I determine where the issue is? I suspect it is a problem with the characters or encoding of the script adversely interfering with the log4net library functions, but I'm not sure how to test that.

This is on a clean, Win7x64 system with the latest Chocolatey (v0.10.3).

Note that this may be intermittent (lovely!) because I reported this problem awhile back as a side note in the Google Groups forum, but the problem went away on it's own.

[gep13]

Hmm, there seems to be a LOT going on in your uninstall script:

https://chocolatey.org/packages/fastcopy.install#files

What is the low level pinvoke for? I would be surprised if this makes it through moderation.

@ferventcoder thoughts?

[teknowledgist]

I'm not sure what you mean by "low level pinvoke", sorry. I did not write (only simplified to reduce complexity) the function in the script. I did include a reference to the original (uploaded to TechNet by Boe Prox) in the comments.

The reason for the complexity is I am trying to clean up files that are created by the install, and one of them (a .DLL) may be locked. I believe I have gone through the "proper" method of marking the file for deletion on next boot, but if there is a better method, point me in the right direction. I'm happy to adjust the script.

On 3/10/2017 2:25 PM, Gary Ewan Park wrote:

Hmm, there seems to be a LOT going on in your uninstall script:

https://chocolatey.org/packages/fastcopy.install#files

What is the low level pinvoke for? I would be surprised if this makes it through moderation.

@ferventcoder https://github.com/ferventcoder thoughts?

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/chocolatey/choco/issues/1196#issuecomment-285761311, or mute the thread https://github.com/notifications/unsubscribe-auth/ADyyEAguaAEv7uhEIBsKzBJP-feRl2wOks5rkaORgaJpZM4MZwXz.

[teknowledgist]

I'm trying to update the fastcopy.install package, and encountering a different version of this error now (with Chocolatey v0.10.8). Now, without $ErrorActionPreference = 'Stop', the uninstall script works fine as far as Windows is concerned, but Chocolatey isn't happy and treats the package as still installed.

The log contains: 2017-12-11 10:31:32,797 1560 [DEBUG] - Setting installer args for fastcopy.install 2017-12-11 10:31:32,797 1560 [DEBUG] - Setting package parameters for fastcopy.install 2017-12-11 10:31:32,797 1560 [DEBUG] - Contents of 'C:\ProgramData\chocolatey\lib\fastcopy.install\tools\chocolateyUninstall.ps1': 2017-12-11 10:31:32,812 1560 [ERROR] - Chocolatey had an error formatting string: Input string was not in a correct format. 2017-12-11 10:31:32,812 1560 [DEBUG] -

I do not need to change (and have not) the ChocolateyUninstall.ps1 file since I posted this issue. I'm guessing the issue is the same, it's just that somewhere between v0.10.3 and v0.10.8, Chocolatey handles it differently. Except now, it's in a way that will prevent the package from being approved. :frowning:

I'm willing to change the package uninstaller, I just don't know how. I have to assume that there are other packages that may have locked files. Do you know of one that handles that problem in a better way?

Thanks.

[ferventcoder]

There is likely a bug in Chocolatey's logging for that uninstall script that is bringing that up. The new error is a bit weirder. Can you post your script here?

[teknowledgist]

$ProgDir = Join-Path $env:ProgramFiles 'FastCopy'

# Win7 complains the installer didn't run correctly.  This will prevent that.
Set-Variable __COMPAT_LAYER=!Vista

& AutoHotkey.exe $(Join-Path $env:ChocolateyPackageFolder 'tools\chocolateyUninstall.ahk') $(Join-Path $ProgDir 'setup.exe') | Out-Null

# Uninstall removes desktop/Start Menu icons, but it does not remove the installed program and folder.
if (Test-Path ($ProgDir)) {
   # Test if Explorer locked the extension dll.  
   $dll = 'FastExt1.dll'
   If (Get-ProcessorBits -eq '64') { $dll = 'FastEx64.dll' }
   $Lock = Get-Process | foreach { $processVar = $_; $_.Modules | foreach { if ($_.FileName -like "*$dll") { $processVar.Name }}}

   # Register a lock for deletion.
   If ($Lock) {
      Write-Host "The FastCopy file extension is locked by $Lock. It will be deleted on next reboot." -ForegroundColor Cyan
      # Function from: https://gallery.technet.microsoft.com/scriptcenter/Register-FileToDelete-0cbb00bb
      #   with reference to "system.linq" (requiring .net 3.5+) removed as it is not needed here.
      Function Register-FileToDelete {
         [cmdletbinding(SupportsShouldProcess = $True )]
         Param (
            [parameter(ValueFromPipeline=$True, ValueFromPipelineByPropertyName=$True)]
            [Alias('FullName','File','Folder')]
            $Source = 'C:\users\Administrator\desktop\test.txt'    
         )
         Begin {
            Try { $null = [File] } 
            Catch { 
               Write-Verbose 'Compiling code to create type'   
               Add-Type @'
               using System;
               using System.Collections.Generic;
               using System.Text;
               using System.Runtime.InteropServices;

               public class Posh
               {
                   public enum MoveFileFlags
                   {
                       MOVEFILE_REPLACE_EXISTING           = 0x00000001,
                       MOVEFILE_COPY_ALLOWED               = 0x00000002,
                       MOVEFILE_DELAY_UNTIL_REBOOT         = 0x00000004,
                       MOVEFILE_WRITE_THROUGH              = 0x00000008,
                       MOVEFILE_CREATE_HARDLINK            = 0x00000010,
                       MOVEFILE_FAIL_IF_NOT_TRACKABLE      = 0x00000020
                   }

                   [DllImport("kernel32.dll", SetLastError = true, CharSet = CharSet.Unicode)]
                   static extern bool MoveFileEx(string lpExistingFileName, string lpNewFileName, MoveFileFlags dwFlags);
                   public static bool MarkFileDelete (string sourcefile)
                   {
                       bool brc = false;
                       brc = MoveFileEx(sourcefile, null, MoveFileFlags.MOVEFILE_DELAY_UNTIL_REBOOT);          
                       return brc;
                   }
               }
'@
            }
         }
         Process {
            ForEach ($item in $Source) {
               Write-Verbose ('Attempting to resolve {0} to full path if not already' -f $item)
               $item = (Resolve-Path -Path $item).ProviderPath
               If ($PSCmdlet.ShouldProcess($item,'Mark for deletion')) {
                   If (-NOT [Posh]::MarkFileDelete($item)) {
                       Try { Throw (New-Object System.ComponentModel.Win32Exception) }
                       Catch {Write-Warning $_.Exception.Message}
                   }
               }
            }
         }
      } #end Register-FileToDelete function

      Register-FileToDelete (Join-Path $ProgDir $dll)
      Register-FileToDelete $ProgDir

      # remove everything else
      Remove-Item (Join-Path $ProgDir '*.*') -Exclude $dll -Force
   } else {
      Remove-Item $ProgDir -Recurse -Force 
   }
} else {
   throw 'FastCopy install not found!' 
}

[ferventcoder]

There is a lot going on in there.

Fast copy is the one, which package version?

[teknowledgist]

That's what @gep13 said. :smile:

Most of it is a result of an attempt to remove a (possibly) locked .dll file and is simplified from this. Is there a better/simpler way to handle locked files that can't be deleted until reboot? Should I just ignore it?

That is the ChocolateyUninstall.ps1 for the current fastcopy.install v3.32, but it is also what I am using for testing v3.40.

Thanks.

[ferventcoder]

I ran the uninstall and it gave those stderr messages, but the uninstall was successful. Is that not the same as you are seeing?

[ferventcoder]

The escape of the curly braces works appropriately here for log4net, but something else is causing log4net to throw an error on the formatting.

[ferventcoder]

I wonder if it is this: Write-Verbose ('Attempting to resolve {0} to full path if not already' -f $item)

It does make the change to {{0}} but it may still see an item that needs to be input in the {0}.

[ferventcoder]

I believe that other packages have used that same form. I will need to check to see if we upgraded log4net in between those versions.

[ferventcoder]

Does not appear we've upgraded it anytime recently. Maybe there is something else in there triggering it.

[teknowledgist]

I have egg on my face (again). :blush:

The stderr message is still there, and like a freshman programmer, I looked to first resolve only that as the first of several errors. Only your different results got me looking further.

My real problem was with throw in the last line. Apparently, v3.40 has a more efficient removal process, and that bug which I put in there from the beginning was finally showing its face.

Basically, the original issue is still there, but it has not escalated and can remain a lower priority.

Thank you for your valuable time and effort.