자바스크립트를 활성화 해주세요

p028 Custom Module에서 사용하는 Logging 전략(2)

 ·  ☕ 4 min read

지난 번 레거시코드중에 있던 다음과 같은 코드가 있다고 설명한 적이 있는데, 이 함수에 대한 문제점을 리뷰해보겠습니다.

지난 번의 함수는 다음과 같습니다.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
Function set-writelog{  # (1)
    [CmdletBinding()]
    Param(
        [string] $Fname,
        [string] $Command,
        [string] $Action
    )
    try {

        $Log = @()  # (2)
        $objPs = New-Object PSCustomObject  # (3)
        $objPs | Add-Member -NotePropertyMembers @{DateTime = Get-Date}
        $objPs | Add-Member -NotePropertyMembers @{Function = $Fname}
        $objPs | Add-Member -NotePropertyMembers @{Command = $Command}
        $objPs | Add-Member -NotePropertyMembers @{Action = $Action}
        $Log += $objPs

        $LogFile = "C:\Log\kase_" + (Get-Date).ToString("yyyyMMdd") + ".txt"  # (4)

        $mutex = New-Object System.Threading.Mutex($false, "logwrite")
        $mutex.WaitOne()  # (5)
        $LogText = $Log | Out-String -Stream -Width 9999 | ? {$_ -ne ""}  # (6)
        $LogText += "------------------------------"
        $LogText | Out-File -FilePath $LogFile -Encoding Default -Append -Width 99999  # (7)(8)
        $mutex.ReleaseMutex()  # (5)(9)
        Return $Log  # (10)
    } catch {
        Write-Error $_.Exception
    }
}

Review포인트

  1. 함수 이름 set-writelog
    • 이름이 애매모호합니다.
    • LogLevel도 없습니다. 대신 퍼포먼스는 좀 더 좋겠네요.
    • 대소문자를 맞추는 쪽이 좋습니다. Set-WriteLog
  2. $Log = @(), 코드를 보면 배열에 Element를 하나만 넣고 있기 때문에, 그다지 의미가 없어보입니다.
  3. PSCustomObject 생성 방법이 예전 방식입니다.
  4. Path에 대한 변수는 온전히 Parameter로 받는 쪽이 좋습니다.
    • 합성해서 만들어 사용한다면 템플릿은 Congifuration에서 받는 쪽이 좋아 보입니다.
  5. WaitOne은 여러가지 Exception을 Throw할 수 있습니다. 문서 참조
  6. 공백라인은 빼고 기록하려고 했던 것 같은데, 기록할 Data의 성형은 (3)에서 하는 것이 좋을 듯 합니다.
    • 2번은 배열처럼 움직이라고 일부러 Type을 Array로 해 둔 것일까요?
  7. 포맷은 나중에 파싱하기에 적합해 보이진 않습니다.
    • 툴을 사용해서 볼 것인지, 아니면 로그파일을 직접 열어서 눈으로 찾아 볼 것인지 정해봐야 할 것입니다.
    • Json포맷도 퍼포먼스면에서 문제없다면, One Line으로, 델리미터 없이 구성하는 것도 어떨까 합니다.
  8. Encoding이 System Default를 사용? 하는 것 보다는 ‘UTF8’ 을 사용하는 것이 좋아보입니다.
  9. Out-File에서 에러가 발생하면 이부분이 실행되지 않을 수 있습니다.
  10. 리턴하는 이유?
  • 로그기록함수가 리턴하는 것은 좀 일반적이진 않습니다.

개수 포인트 5번

WaitOne함수는 정상적인 파라메터를 전달하여도 다른 Thread나 Process의 조작에 의해 Exception이 발생할 수 있습니다.

  • ObjectDisposedException
    내 Thread가 사용해야 하는데 다른 Thread가 갑자기 이 Mutex를 Dispose해버리면 발생합니다.
  • AbandonedMutexException
    Mutex를 Release하지 않고 갑자기 Thread, Process를 종료해버리면 발생합니다.

ReleaseMutex 함수도 다음과 같은 Exception을 발생시킬 수 있습니다.

  • ApplicationException
    내가 Mutex를 획득하지 못했는데 Release하려고 하면 발생합니다.
  • ObjectDisposedException
    내 Thread가 사용해야 하는데 다른 Thread가 갑자기 이 Mutex를 Dispose해버리면 발생합니다.

이런 경우에 대한 처리는 조금 더 고민이 필요할 것 같습니다.

개수 포인트 9번

이 코드는 try 안에서 실패하면 ReleaseMutex 할 수 없게 됩니다. 만일 기다리고 있는 다른 Thread가 있다면 계속 기다리게 되겠죠. 대응방법으로는,

  • WaitOne 할 때 Timeout을 주거나,
  • finally에서 Release 하는 방법이 있습니다.

취소 처리가 가능한 경우라면 Timeout을 주어 시간내에 처리가 안되는 경우 Exception을 Throw하고, 핸들링하는 쪽에서는 CancelToken등을 하면 됩니다만, 조금 복잡한다.

저는 Mutex나 Semaphore는 finally안에서 해 주는 쪽을 사용하고 있습니다.

1
   $mutex.ReleaseMutex()

기타

사용한 mutex는 다 사용한 경우에 $mtx.Dispose() 해주어야 합니다. 하지만, mutex를 컨트롤하는 부모 Thread에서 해주어야 합니다. 자식Thread에서 mutex.Dispose()를 해버리면 안되겠죠.

개수해본 함수

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
Function set-writelog{
    [CmdletBinding()]
    Param(
        [string] $Fname,
        [string] $Command,
        [string] $Action
    )
    try {
        $config = Get-Config
        $LogPath = $config.LogPath -f $Fname
        $LogText = ConvertTo-Json $(DateTime = $(Date-Time); Command = $Command; Action = $Action)

        $mutex = New-Object System.Threading.Mutex($false, "logwrite")
        $mutex.WaitOne()
        $LogText | Out-File -FilePath $LogPath -Encoding 'UTF8' -Append

    } catch {
        Write-Error $_.Exception
    } finally  {
        if ($mutex) {
            $mutex.ReleaseMutex()
        }
    }
}

그런데, PoshLog나 Logging 모듈을 사용하는 것도 고려해 보라고 추천하고 싶습니다.

MultiThread랑 사용하기

내친김에, RunspacePool를 사용해 MultiThread와 함께 사용해 보는 예제를 살펴보겠습니다.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
Function Test-MutexWithRunspacePool {
Param (
    $LogFile = 'C:\testlog.txt',
    $Throttle = 20,
    $Count = 100,
    [switch]$NoMutex
)
    $Parameters = @{
        LogFile = $LogFile
        NoMutex = $NoMutex
    }
    
    $DebugPreference = 'Continue'
    
    $RunspacePool = [runspacefactory]::CreateRunspacePool(
        1, #Min Runspaces
        10, #Max Runspaces
        [System.Management.Automation.Runspaces.InitialSessionState]::CreateDefault(), #Initial Session State; defines available commands and Language availability
        $host #PowerShell host
    )
    
    $RunspacePool.Open()
    
    $jobs = New-Object System.Collections.ArrayList
    
    1..$Count | ForEach {
        $PowerShell = [powershell]::Create()
        
        $PowerShell.RunspacePool = $RunspacePool
        
        [void]$PowerShell.AddScript({
            Param(
                $LogFile,
                $NoMutex
            )
            If (-Not $NoMutex) {
                $mtx = New-Object System.Threading.Mutex($false, "LogMutex")
                Write-Verbose "[$(Get-Date)][PID: $($PID)][TID: $([System.Threading.Thread]::CurrentThread.ManagedThreadId)] Requesting mutex!" -Verbose
                $mtx.WaitOne()
                Write-Verbose "[$(Get-Date)][PID: $($PID)][TID: $([System.Threading.Thread]::CurrentThread.ManagedThreadId)] Recieved mutex!" -Verbose       
            }
            Try {
                Write-Verbose "[$(Get-Date)][PID: $($PID)][TID: $([System.Threading.Thread]::CurrentThread.ManagedThreadId)] Writing data $($_) to $LogFile" -Verbose
                "[$(Get-Date)] | ThreadID: $([System.Threading.Thread]::CurrentThread.ManagedThreadId) | ProcessID $($PID) | Data: $($_)" | Out-File $LogFile -Append
            } Catch {
                Write-Warning $_
            }
            If (-Not $NoMutex) {
                Write-Verbose "[$(Get-Date)][PID: $($PID)][TID: $([System.Threading.Thread]::CurrentThread.ManagedThreadId)] Releasing mutex" -Verbose
                [void]$mtx.ReleaseMutex()
            }
        })
    
        [void]$PowerShell.AddParameters($Parameters)
    
        $Handle = $PowerShell.BeginInvoke()
        $temp = '' | Select PowerShell,Handle
        $temp.PowerShell = $PowerShell
        $temp.handle = $Handle
        [void]$jobs.Add($Temp)
        
        Write-Debug ("Available Runspaces in RunspacePool: {0}" -f $RunspacePool.GetAvailableRunspaces()) 
        Write-Debug ("Remaining Jobs: {0}" -f @($jobs | Where {
            $_.handle.iscompleted -ne 'Completed'
        }).Count)
    }
    
    #Verify completed
    Write-Debug ("Available Runspaces in RunspacePool: {0}" -f $RunspacePool.GetAvailableRunspaces()) 
    Write-Debug ("Remaining Jobs: {0}" -f @($jobs | Where {
        $_.handle.iscompleted -ne 'Completed'
    }).Count)
    
    $return = $jobs | ForEach {
        $_.powershell.EndInvoke($_.handle);$_.PowerShell.Dispose()
    }
    $jobs.clear()
}

레퍼런스

공유하기

tkim
글쓴이
tkim
Software Engineer