Log File not being created

[swys]

I'm having a similar issue as Issue#2

I've tried this on windows 10 Version 1607 (anniversary edition) (OS build 14393.223) and Windows Server 2012 R2 Version 6.3 (Build 9600) and OS versions are unable to create the log file in demo6.ps1.

See below for details on the Windows 10 computer :

Installation and running demo6

PS C:\ps> git clone --recurse-submodules [email protected]:gaelcolas/log4ps.git
Cloning into 'log4ps'...
remote: Counting objects: 2707, done.
remote: Total 2707 (delta 0), reused 0 (delta 0), pack-reused 2707
Receiving objects: 100% (2707/2707), 6.42 MiB | 3.65 MiB/s, done.
Resolving deltas: 100% (2404/2404), done.
Submodule 'lib/lib.common' (https://github.com/gaelcolas/lib.common) registered for path 'lib/lib.common'
Cloning into 'C:/ps/log4ps/lib/lib.common'...
Submodule path 'lib/lib.common': checked out '03c77de4e8a779138bd6dfbf12f4ca62693806b3'
PS C:\ps> cd .\log4ps\examples\
PS C:\ps\log4ps\examples> .\demo6.ps1
INFO - This test is killing puppies
This test is killing puppies
INFO - This is a verbose msg
DEBUG - Debug message
WARN - This is a WARN msg!
WARNING: This is a WARN msg!
ERROR - This is an error
Write-Error : This is an error
At C:\ps\log4ps\examples\demo6.ps1:9 char:1
+ Write-Error 'This is an error'
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : NotSpecified: (:) [Write-Error], WriteErrorException
    + FullyQualifiedErrorId : Microsoft.PowerShell.Commands.WriteErrorException,Write-Error

Get-Content : Cannot find path 'C:\Users\KEVIN~1.CAR\AppData\Local\Temp\example.log' because it does not exist.
At C:\ps\log4ps\examples\demo6.ps1:11 char:1
+ Get-Content $env:TMP\example.log
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : ObjectNotFound: (C:\Users\KEVIN~...emp\example.log:String) [Get-Content], ItemNotFoundException
    + FullyQualifiedErrorId : PathNotFound,Microsoft.PowerShell.Commands.GetContentCommand

Powershell Version

PSVersion => 5.1.14393.223
PSEdition => Desktop
PSCompatibleVersions =>{1.0, 2.0, 3.0, 4.0...}
BuildVersion => 10.0.14393.223
CLRVersion => 4.0.30319.42000
WSManStackVersion =>3.0
PSRemotingProtocolVersion => 2.3
SerializationVersion => 1.1.0.1

.NET Framework Version

.NET Framework 4.6.2

I've also tried to replace the xml config with the one used in the solution of Issue#2, but that did not work either.

Any suggestions to further troubleshoot this would be greatly appreciated.

[swys]

Ok I got this working now. I had to explicity add the path to the config xml file into the argumentlist param when importing the module.

All I had to do was change the line with the import-module statement to :
Import-Module -Force $PSScriptRoot\..\..\log4ps -ArgumentList "<path to config file>"

After making this change it worked fine. And I'm able to now use it in my own scripts without issue. I had to do the same exact thing on 3 different computers to get it working.

Could this be an issue with the code that looks for the config file? I haven't read it but that is the behavior that it seems to be displaying. Anyway, I hope this helps someone with a similar issues.

If you get time to look at this issue, I'd like to hear your thoughts on this.

Thanks!

[gaelcolas]

Hi,
Thanks for reporting. I've left this module aside before reaching v1, but seing people trying it motivates me!
issue#2 was an issue with creating the log file, not loading the xml config file (I think).
You may have a similar issue where %TMP% either does not resolve properly in log4net, or issue creating a file with that path.
For troubleshooting (I need to implement this better), you can edit the log4ps.psm1 file, line 826 with uncommenting the Log4netInternalDebug parameter. This will trace the log4net internals like telling you if the file can't be created).

Or maybe I should change ${TMP}\example.log with ${TEMP}\example.log... in the xml config (in this case ./examples/demo6.ps1.config line 8).

If you got time to try those that'd be great, as it seems to work for me :(

[swys]

Ok so I first tried to just change the xml config file to use ${TEMP} instead of ${TMP} as suggested, but that had no effect.

I then turned on debugging by added the switch Log4netInteralDebug and I ran again. I made a slight adjustments each time I ran, hoping this would give you more insight as to what is going on. See below for what I did and the output that was produced :

Running demo6.ps1 without any changes

PS C:\ps\log4ps\examples> .\demo6.ps1
log4net: Shutdown called on Hierarchy [log4net-default-repository]
log4net: Shutdown called on Hierarchy [log4net-default-repository]
log4net: Shutdown called on Hierarchy [log4net-default-repository]
INFO - This test is killing puppies
This test is killing puppies
INFO - This is a verbose msg
DEBUG - Debug message
WARN - This is a WARN msg!
WARNING: This is a WARN msg!
ERROR - This is an error
Write-Error : This is an error
At C:\ps\log4ps\examples\demo6.ps1:9 char:1
+ Write-Error 'This is an error'
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : NotSpecified: (:) [Write-Error], WriteErrorException
    + FullyQualifiedErrorId : Microsoft.PowerShell.Commands.WriteErrorException,Write-Error

Get-Content : Cannot find path 'C:\Users\ADMIN~1.KCA\AppData\Local\Temp\2\example.log' because it does not exist.
At C:\ps\log4ps\examples\demo6.ps1:11 char:1
+ Get-Content $env:TMP\example.log
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : ObjectNotFound: (C:\Users\ADMIN~...p\2\example.log:String) [Get-Content], ItemNotFoundException
    + FullyQualifiedErrorId : PathNotFound,Microsoft.PowerShell.Commands.GetContentCommand

Changing XML config file path from ${TMP}...to ${TEMP}...

Rerunning demo6.ps1

PS C:\ps\log4ps\examples> vim .\demo6.ps1.config
PS C:\ps\log4ps\examples> .\demo6.ps1
log4net: Shutdown called on Hierarchy [log4net-default-repository]
log4net: Shutdown called on Hierarchy [log4net-default-repository]
log4net: Shutdown called on Hierarchy [log4net-default-repository]
log4net: Shutdown called on Hierarchy [log4net-default-repository]
log4net: Shutdown called on Hierarchy [log4net-default-repository]
log4net: Shutdown called on Hierarchy [log4net-default-repository]
INFO - This test is killing puppies
This test is killing puppies
INFO - This is a verbose msg
DEBUG - Debug message
WARN - This is a WARN msg!
WARNING: This is a WARN msg!
ERROR - This is an error
FATAL - This is an error
Write-Error : This is an error
At C:\ps\log4ps\examples\demo6.ps1:9 char:1
+ Write-Error 'This is an error'
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : NotSpecified: (:) [Write-Error], WriteErrorException
    + FullyQualifiedErrorId : Microsoft.PowerShell.Commands.WriteErrorException,Write-Error

FATAL - Cannot find path 'C:\Users\ADMIN~1.KCA\AppData\Local\Temp\2\example.log' because it does not exist.
Get-Content : Cannot find path 'C:\Users\ADMIN~1.KCA\AppData\Local\Temp\2\example.log' because it does not exist.
At C:\ps\log4ps\examples\demo6.ps1:11 char:1
+ Get-Content $env:TMP\example.log
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : ObjectNotFound: (C:\Users\ADMIN~...p\2\example.log:String) [Get-Content], ItemNotFoundException
    + FullyQualifiedErrorId : PathNotFound,Microsoft.PowerShell.Commands.GetContentCommand

Restored demo6.ps1.config to original state. Changed demo6.ps1 Import-Module statement to : Import-Module -Force $PSScriptRoot\..\..\log4ps -ArgumentList ".\demo6.ps1.config"

Rereunning demo6.ps1

PS C:\ps\log4ps\examples> vim demo6.ps1
PS C:\ps\log4ps\examples> .\demo6.ps1
log4net: Shutdown called on Hierarchy [log4net-default-repository]
log4net: Shutdown called on Hierarchy [log4net-default-repository]
log4net: Shutdown called on Hierarchy [log4net-default-repository]
log4net: Shutdown called on Hierarchy [log4net-default-repository]
log4net: Shutdown called on Hierarchy [log4net-default-repository]
log4net: Shutdown called on Hierarchy [log4net-default-repository]
log4net: configuring repository [log4net-default-repository] using file [C:\ps\log4ps\examples\demo6.ps1.config] watching for file updates
log4net: configuring repository [log4net-default-repository] using file [C:\ps\log4ps\examples\demo6.ps1.config]
log4net: configuring repository [log4net-default-repository] using stream
log4net: loading XML configuration
log4net: Configuring Repository [log4net-default-repository]
log4net: Configuration update mode [Merge].
log4net: Logger [root] Level string is [DEBUG].
log4net: Logger [root] level set to [name="DEBUG",value=30000].
log4net: Loading Appender [RollingFile] type: [log4net.Appender.RollingFileAppender]
log4net: Setting Property [File] to String value [C:\Users\ADMIN~1.KCA\AppData\Local\Temp\2\example.log]
log4net: Setting Property [AppendToFile] to Boolean value [True]
log4net: Setting Property [MaximumFileSize] to String value [1KB]
log4net: Setting Property [MaxSizeRollBackups] to Int32 value [2]
log4net: Converter [message] Option [] Format [min=-1,max=2147483647,leftAlign=False]
log4net: Converter [newline] Option [] Format [min=-1,max=2147483647,leftAlign=False]
log4net: Setting Property [ConversionPattern] to String value [%date{yyyy-MM-dd HH:mm:ss.fff[zzz]} %logger [Line: %property{ScriptLineNumber}] %-5level - %message (%property{PSCallStack})%newline]
log4net: Converter [date] Option [yyyy-MM-dd HH:mm:ss.fff[zzz]] Format [min=-1,max=2147483647,leftAlign=False]
log4net: Converter [literal] Option [ ] Format [min=-1,max=2147483647,leftAlign=False]
log4net: Converter [logger] Option [] Format [min=-1,max=2147483647,leftAlign=False]
log4net: Converter [literal] Option [ [Line: ] Format [min=-1,max=2147483647,leftAlign=False]
log4net: Converter [property] Option [ScriptLineNumber] Format [min=-1,max=2147483647,leftAlign=False]
log4net: Converter [literal] Option [] ] Format [min=-1,max=2147483647,leftAlign=False]
log4net: Converter [level] Option [] Format [min=5,max=2147483647,leftAlign=True]
log4net: Converter [literal] Option [ - ] Format [min=-1,max=2147483647,leftAlign=False]
log4net: Converter [message] Option [] Format [min=-1,max=2147483647,leftAlign=False]
log4net: Converter [literal] Option [ (] Format [min=-1,max=2147483647,leftAlign=False]
log4net: Converter [property] Option [PSCallStack] Format [min=-1,max=2147483647,leftAlign=False]
log4net: Converter [literal] Option [)] Format [min=-1,max=2147483647,leftAlign=False]
log4net: Converter [newline] Option [] Format [min=-1,max=2147483647,leftAlign=False]
log4net: Setting Property [Layout] to object [log4net.Layout.PatternLayout]
log4net: Type = [0], r0 = [.1970-01-01], r1 = [.1970-01-01]
log4net: Type = [1], r0 = [.1970-01-01], r1 = [.1970-01-01]
log4net: Type = [2], r0 = [.1970-01-01], r1 = [.1970-01-01]
log4net: Type = [3], r0 = [.1970-01-01], r1 = [.1970-01-02]
log4net: Searched for existing files in [C:\Users\admin.kcarroll\AppData\Local\Temp\2]
log4net: curSizeRollBackups starts at [0]
log4net: Opening file for writing [C:\Users\admin.kcarroll\AppData\Local\Temp\2\example.log] append [True]
log4net: Created Appender [RollingFile]
log4net: Adding appender named [RollingFile] to logger [root].
log4net: Hierarchy Threshold []
This test is killing puppies
WARNING: This is a WARN msg!
Write-Error : This is an error
At C:\ps\log4ps\examples\demo6.ps1:9 char:1
+ Write-Error 'This is an error'
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : NotSpecified: (:) [Write-Error], WriteErrorException
    + FullyQualifiedErrorId : Microsoft.PowerShell.Commands.WriteErrorException,Write-Error

2016-10-15 15:25:15.518[-04:00] demo6.ps1 [Line: 5] INFO  - This test is killing puppies (demo6.ps1)
2016-10-15 15:25:15.642[-04:00] demo6.ps1 [Line: 6] INFO  - This is a verbose msg (demo6.ps1)
2016-10-15 15:25:15.735[-04:00] demo6.ps1 [Line: 7] DEBUG - Debug message (demo6.ps1)
log4net: rolling over count [1075]
log4net: maxSizeRollBackups [2]
log4net: curSizeRollBackups [0]
log4net: countDirection [-1]
log4net: Moving [C:\Users\admin.kcarroll\AppData\Local\Temp\2\example.log] -> [C:\Users\admin.kcarroll\AppData\Local\Temp\2\example.log.1]
log4net:ERROR [RollingFileAppender] ErrorCode: GenericFailure. Exception while rolling file [C:\Users\admin.kcarroll\AppData\Local\Temp\2\example.log] -> [C:\Users\admin.kcarroll\AppData\Local\Temp\2\example.log.1]
System.IO.IOException: The process cannot access the file because it is being used by another process.
   at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)
   at System.IO.File.InternalMove(String sourceFileName, String destFileName, Boolean checkHost)
   at log4net.Appender.RollingFileAppender.RollFile(String fromFile, String toFile)
log4net:ERROR RollingFileAppender: INTERNAL ERROR. Append is False but OutputFile [C:\Users\admin.kcarroll\AppData\Local\Temp\2\example.log] already exists.
log4net: Opening file for writing [C:\Users\admin.kcarroll\AppData\Local\Temp\2\example.log] append [False]
2016-10-15 15:25:15.822[-04:00] demo6.ps1 [Line: 8] WARN  - This is a WARN msg! (demo6.ps1)
2016-10-15 15:25:15.917[-04:00] demo6.ps1 [Line: 9] ERROR - This is an error (demo6.ps1)
2016-10-15 15:25:16.009[-04:00] demo6.ps1 [Line: 9] FATAL - This is an error (demo6.ps1 => Write-Error)

[Workshopshed]

That last example might be a case where you want to use the file locking setting in the configuration file, as the file is still locked when you try to read it back

[chrissten]

I have the same problem, but when I run it in Powershell ISE, it works. It's only on in PowerShell itself that it throws the error. I think I've tracked the issue to Receive-ModuleParameter in the referenced project, but since it works in Powershell ISE, I can't debug it line by line, and when I add any sort of Write-Verbose or Write-Host to "ReceiveModuleParams.ps1", nothing gets written, so I'm not sure how to debug it.

[crshnbrn66]

if you use relative pathing in the xml config it appears to default to c:\windows\system32<your relative path> where does it load in the path from the config?
REason I ask I was thinking of adding the ability to use the module root as the relative path from.