ログ出力のベストプラクティス(VB/コンソールプログラム編) 

VB

この記事を見てわかること

障害連絡を受け、他の方が作成したプログラムの調査を行うことがあるのですが、ログにもっと必要な情報が出力されていれば、こんなに調査に時間が掛からずに済んだのに…と感じることがよくあります。きっと皆様も同じような経験があるのではないでしょうか。

この記事では、日ごろ私が感じているログ出力に関する不満を、他人に与えてしまわないように意識している個人的ベストプラクティスをご紹介いたします。ぜひ参考にしてみてください。

個人的ベストプラクティス

パラメーターを出力する

プログラム内で扱うパラメーターをログに出力します。３つほど例を挙げて順に説明していきます。

  • データベースの接続情報
  • ログファイルの出力先
  • プログラム実行時の引数

データベースの接続情報

データベースが複数存在するようなシステムに対し処理を行うバッチプログラムを作成した場合、「SQLクライアントからはテーブルが見えるんだけど、バッチプログラムからは何故か見えない。」ということがよく起こります。

原因は単純で、バッチプログラムが接続しているデータベースの接続先が間違えているからです。この単純ミスに気づけないのは、ログファイルにデータベースの接続情報を出力していないからです。接続情報を出力していれば、「あれ？接続先が違うな」と早いタイミングで気づくことできますので、データベースの接続情報は必ず出力するようにしています。

FTP接続や自動メール送信の情報などといった情報もログ出力した方がおすすめです。

VB
Imports System.Data.SQLite

Module Module1

    Sub Main()
        Try
            'ログ出力は便宜上コンソール上に出力しています。本来はログファイルに出力します。
            Debug.WriteLine($"■プロパティ情報")
            Debug.WriteLine($"・データベース接続文字列: {GetConnectionString()}")
            connectDatabase()
            Debug.WriteLine($"正常終了")
        Catch ex As Exception
            Debug.WriteLine($"例外エラーが発生しました。{vbCrLf}{ex.ToString}")
            Debug.WriteLine($"異常終了")
        End Try
    End Sub

    Private Sub connectDatabase()
        Using con = New SQLiteConnection(GetConnectionString())
            '何かしらの処理
        End Using
    End Sub

    Private Function GetConnectionString() As String
        Return New SQLiteConnectionStringBuilder() With {.DataSource = "..\..\database\ConsoleApp001.db"}.ToString()
    End Function

End Module
Plaintext
■プロパティ情報
・データベース接続文字列: data source=..\..\database\ConsoleApp001.db
正常終了

ログファイルの出力先

運用の目線で見ると、ログファイル自体にログ出力先が出力されていても、「既にログファイルを確認している→つまりログファイルの場所がわかっている」ということになるので全く意味がありませんが、開発の目線で見ると恩恵があります。

例えば、時間がない中で他の方が作成したプログラムをとりあえずデバッグ実行で動かしたいことがあるとします。もちろんそのままで動かすと「引数の指定がないからエラーになる」とか「所定のフォルダがないからエラーになる」などで上手く動かせないケースがほとんどだと思います。

こういったエラー情報は基本的にログファイルに出力されると思いますが、そのログファイルの出力先がわからない…というケースが本当に多いです。（特に共通クラスの深い部分に隠ぺいされてしまっていると追うのが大変です。）

このようなケースに特に力を発揮をするのが「ログファイルの出力先をログファイルに出力する」です。デバッグ実行していますから、「ログファイルの出力先をログファイルに出力する」部分でログファイルの出力先がどこなのかが一目瞭然です。これで本来確認したかった例外エラーの内容を素早く確認することができます。

VB
Module Module2

    Sub Main()
        Dim logger As New Logger("Module2")
        Try
            logger.WriteLine($"**************************************  処理開始  **************************************")
            logger.WriteLine($"■パラメーター出力")
            'デバッグ実行していれば、「logger.LogFilePath」の値を直接確認できます。
            logger.WriteLine($"・ログファイル出力先:{logger.LogFilePath}")
            logger.WriteLine($"■メイン処理")
            logger.WriteLine($"処理Ａ：完了")
            logger.WriteLine($"処理Ｂ：完了")
            logger.WriteLine($"処理Ｃ：完了")
            logger.WriteLine($"**************************************  正常終了  **************************************")
        Catch ex As Exception
            logger.WriteLine($"例外エラーが発生しました。{vbCrLf}{ex.ToString}")
            logger.WriteLine($"**************************************  異常終了  **************************************")
        End Try
    End Sub

End Module

Public Class Logger

    '通常のシステムでは、ログファイルの出力先は設定ファイル(ini、xml)やデータベースから取得するため、ソース内にオンコードで記述されることはまずありません。今回は説明簡素化のためオンコードで記載しています。
    Private Const _logFileDirectory As String = "C:\Blog\VB\ConsoleApp001\log"
    Private _logFileName As String

    ''' <summary>
    ''' ログファイルのパスを返却します
    ''' </summary>
    ''' <returns>ログファイルのパス</returns>
    ReadOnly Property LogFilePath As String
        Get
            Return IO.Path.Combine(_logFileDirectory, $"{Now.ToString("yyyyMMdd")}_{_logFileName}.log")
        End Get
    End Property

    ''' <summary>
    ''' コンストラクタ
    ''' </summary>
    ''' <param name="logFileName">ログファイル名を指定してください。</param>
    Public Sub New(logFileName As String)
        _logFileName = logFileName
    End Sub

    ''' <summary>
    ''' ログメッセージを出力します
    ''' </summary>
    ''' <param name="logMessage">出力するログメッセージ</param>
    Public Sub WriteLine(logMessage As String)
        Using writer As New IO.StreamWriter(LogFilePath, True)
            writer.WriteLine($"{Now.ToString("yyyy/MM/dd HH:mm:ss.fff")}{vbTab}{logMessage}")
        End Using
    End Sub

End Class
Plaintext
2024/06/08 23:40:35.511	**************************************  処理開始  **************************************
2024/06/08 23:40:35.511	■パラメーター出力
2024/06/08 23:40:35.512	・ログファイル出力先:C:\Blog\VB\ConsoleApp001\log\20240608_Module2.log
2024/06/08 23:40:35.512	■メイン処理
2024/06/08 23:40:35.512	処理Ａ：完了
2024/06/08 23:40:35.513	処理Ｂ：完了
2024/06/08 23:40:35.513	処理Ｃ：完了
2024/06/08 23:40:35.513	**************************************  正常終了  **************************************

ログファイルの出力先以外にも、例えば、共通クラスで暗黙的に参照しているディレクトリや、ファイル作成プログラムで出力するディレクトリの情報はログファイルに出力しておきたいですね。細かく出力することで障害発生時の助けになります。

プログラム実行時の引数

これも障害調査の時に非常に重要となる情報です。プログラムが引数を必要とする場合は、その引数の内容を必ずログに出力するようにしています。

例えば、引数で処理日を「yyyyMMdd形式」で引き受けて印刷を行うプログラムがあるとします。当プログラムは、他プログラムから呼び出されるプログラムため引数のチェックは行いません。

時間が経ち、このプログラムは他多数のプログラムから呼び出されることになりました。しかし、とあるプログラムだけ、引数に渡した処理日のデータが印刷されません。”対象データがありません”となってしまいます。”正しく”引数を渡しているのに何故だろう…

原因は、引数を「yyyy/MM/DD形式」で引き渡してしまっていたからです。印刷プログラムは引数のチェックを行わないので、引数の値そのままでデータベースの検索処理を行います。もちろんデータベース内も「yyyyMMDD形式」でデータを保持していますので、何もヒットせず、対象データがないという状態になります。

この手のタイプは、引数の情報をログファイルに出力していないとなかなか気づくことができず、悶々と時間だけが過ぎていってしまいます。引数の情報をログファイルに出力さえしていれば、上手く処理出来た場合と、上手く処理できない場合とで出力されたログファイルを比較することができますので、原因の特定は容易です。（今回の場合は、スラッシュの有無に気づくことができる。）

以下の例ではプログラム実行引数に「20240608 tomochan blog」の３つを指定しています。

VB
Module Module3

    Sub Main(args() As String)
        Try
            Debug.WriteLine($"**************************************  処理開始  **************************************")
            Debug.WriteLine($"■パラメーター出力")
            Debug.WriteLine($"・引数:{String.Join(" ", args)}")
            Debug.WriteLine($"**************************************  正常終了  **************************************")
        Catch ex As Exception
            Debug.WriteLine($"例外エラーが発生しました。{vbCrLf}{ex.ToString}")
            Debug.WriteLine($"**************************************  異常終了  **************************************")
        End Try
    End Sub

End Module
Plaintext
**************************************  処理開始  **************************************
■パラメーター出力
・引数:20240608 tomochan blog
**************************************  正常終了  **************************************

メソッド内で開始・終了ログを出力する

各メソッドにて、必ず開始・終了ログを出力するようにしています。こうすることで、メソッドの実行順序がわかるようになります。例えば「このメソッドは、特定の順番で実行される場合にだけ異常なデータが作成される。」といったケースの障害に気が付きやすくなります。

もちろん、例外発生時はスタックトレースを出力しますので、例外が発生したメソッドは判断することができますが、そのメソッドが実行されるまでにどのような順序でメソッドが呼ばれていたかという情報は、スタックトレースからは確認することができません。

全てのメソッドに記載するのは非常に面倒ですが、障害発生時にヒントになると考えて（後の自分を楽させてあげるつもりで）、開始・終了ログは必ず出力するようにしています。

VB
Module Module4

    Sub Main()
        Try
            Debug.WriteLine($"**************************************  処理開始  **************************************")
            Method1()
            Method2()
            Debug.WriteLine($"**************************************  正常終了  **************************************")
        Catch ex As Exception
            Debug.WriteLine($"例外エラーが発生しました。{vbCrLf}{ex.ToString}")
            Debug.WriteLine($"**************************************  異常終了  **************************************")
        End Try
    End Sub

    Private Sub Method1()
        Debug.WriteLine($"{GetMethodName()} - 開始")
        Method1_1()
        Debug.WriteLine($"{GetMethodName()} - 終了")
    End Sub

    Private Sub Method1_1()
        Debug.WriteLine($"{GetMethodName()} - 開始")
        Debug.WriteLine($"{GetMethodName()} - 終了")
    End Sub

    Private Sub Method2()
        Debug.WriteLine($"{GetMethodName()} - 開始")
        Method1_1()
        Debug.WriteLine($"{GetMethodName()} - 終了")
    End Sub

    ''' <summary>
    ''' メソッド名の取得
    ''' </summary>
    ''' <returns>呼び出し元のメソッド名を返却します</returns>
    Private Function GetMethodName() As String
        Dim objHistory As New StackTrace(True)

        '呼び出し元のメソッド名を返す
        If objHistory.FrameCount > 2 Then
            Return objHistory.GetFrame(1).GetMethod.Name
        End If

        Return ""
    End Function

End Module
Plaintext
**************************************  処理開始  **************************************
Method1 - 開始
Method1_1 - 開始
Method1_1 - 終了
Method1 - 終了
Method2 - 開始
Method1_1 - 開始
Method1_1 - 終了
Method2 - 終了
**************************************  正常終了  **************************************

SQL文をログに出力する

よく遭遇するのが「SQL文をプログラム内で動的に生成していて、ソースコードを見ただけでは生成されるSQLがよくわからない…」といった場面です。

これは困りますよね。数十行の短いSQL文であれば大したことはありませんが、これが数千行にわたる壮大なSQL文だった場合、とても目で見ながらSQLを解析することはできません。

ですので、システム内で発行するSQL文については、必ずログに出力するようにしています。こうすることによって、動的SQLでも、生成されたSQL文がログファイルに出力されるので、SQLクライアントツールにコピペするだけでそのまま使用できます。特に障害調査時に力を発揮します。

以下のサンプルコードでは静的SQL文となっていますが、ログ出力の考え方は一緒です。

VB
Imports System.Data.SQLite

Module Module5

    Sub Main()
        Try
            Debug.WriteLine($"**************************************  処理開始  **************************************")
            Debug.WriteLine($"■パラメーター情報")
            Debug.WriteLine($"・データベース接続文字列:{GetConnectionString()}")
            GetRecords()
            Debug.WriteLine($"**************************************  正常終了  **************************************")
        Catch ex As Exception
            Debug.WriteLine($"例外エラーが発生しました。{vbCrLf}{ex.ToString}")
            Debug.WriteLine($"**************************************  異常終了  **************************************")
        End Try
    End Sub

    Private Function GetRecords() As DataTable
        Try
            Debug.WriteLine($"{GetMethodName()} - 開始")
            Using connection = New SQLiteConnection(GetConnectionString())
                connection.Open()

                Dim selectSQL As New Text.StringBuilder
                selectSQL.AppendLine($"SELECT")
                selectSQL.AppendLine($"    id")
                selectSQL.AppendLine($"    ,name")
                selectSQL.AppendLine($"    ,age")
                selectSQL.AppendLine($"    ,email")
                selectSQL.AppendLine($"FROM")
                selectSQL.AppendLine($"    users")

                'ここでSQL文をログに出力しています。
                Debug.WriteLine($"■実行SQL文")
                Debug.WriteLine($"{selectSQL.ToString}")

                Dim adapter As New SQLiteDataAdapter(selectSQL.ToString, connection)
                Dim dtTable As New DataTable
                adapter.Fill(dtTable)

                Return dtTable
            End Using
        Finally
            Debug.WriteLine($"{GetMethodName()} - 終了")
        End Try
    End Function

    Private Function GetConnectionString() As String
        Debug.WriteLine($"{GetMethodName()} - 開始")
        Return New SQLiteConnectionStringBuilder() With {.DataSource = "..\..\database\ConsoleApp001.db"}.ToString()
        Debug.WriteLine($"{GetMethodName()} - 終了")
    End Function

    ''' <summary>
    ''' メソッド名の取得
    ''' </summary>
    ''' <returns>呼び出し元のメソッド名を返却します</returns>
    Private Function GetMethodName() As String
        Dim objHistory As New StackTrace(True)

        '呼び出し元のメソッド名を返す
        If objHistory.FrameCount > 2 Then
            Return objHistory.GetFrame(1).GetMethod.Name
        End If

        Return ""
    End Function

End Module

SELECT文で抽出した内容をファイルに出力する(レコード件数注意)

障害発生から調査までの時間が空いてしまい、当時の抽出結果と異なるため障害が再現できないといったケースもよくあります。

このケースに対応する方法が「SELECT文で抽出した内容をファイルに出力する」です。

業務システムでは各テーブルから様々なレコードを抽出して処理を行いますが、この抽出した結果をすべてファイルに保存するようにします。こうすることで障害が発生した当時にどのようなレコードが抽出されていたのかがわかるようになります。

ただ、この方法はあまりに大量のレコードが抽出されるような場面ではお勧めしません。保存時のファイルサイズが大きくなってしまうことと、ファイル保存時の処理スピードがボトルネックとなってしまうからです。ログ出力に意識を持ちすぎるあまり、プログラム全体に影響を与えすぎるのは本末転倒ですよね…。

この方法は対象データがあまり多くない場合に使用してください。後、保存したファイルを一定期間で自動削除するような仕組みも必要になります。（プログラム実行のたびファイルが増え続けてしまいますので。）

VB
Imports System.Data.SQLite

Module Module6

    Sub Main()
        Try
            Debug.WriteLine($"**************************************  処理開始  **************************************")
            Debug.WriteLine($"■パラメーター情報")
            Debug.WriteLine($"・データベース接続文字列:{GetConnectionString()}")
            GetUsers()
            Debug.WriteLine($"**************************************  正常終了  **************************************")
        Catch ex As Exception
            Debug.WriteLine($"例外エラーが発生しました。{vbCrLf}{ex.ToString}")
            Debug.WriteLine($"**************************************  異常終了  **************************************")
        End Try
    End Sub

    Private Function GetUsers() As DataTable
        Try
            Debug.WriteLine($"{GetMethodName()} - 開始")
            Using connection = New SQLiteConnection(GetConnectionString())
                connection.Open()

                Dim selectSQL As New Text.StringBuilder
                selectSQL.AppendLine($"SELECT")
                selectSQL.AppendLine($"    id")
                selectSQL.AppendLine($"    ,name")
                selectSQL.AppendLine($"    ,age")
                selectSQL.AppendLine($"    ,email")
                selectSQL.AppendLine($"FROM")
                selectSQL.AppendLine($"    users")

                Debug.WriteLine($"■実行SQL文")
                Debug.WriteLine($"{selectSQL.ToString}")

                Dim adapter As New SQLiteDataAdapter(selectSQL.ToString, connection)
                Dim dtTable As New DataTable
                adapter.Fill(dtTable)
                dtTable.TableName = "users"

                'データテーブルをCSV形式で保存
                SaveDatatableToCSV(dtTable)

                Return dtTable
            End Using
        Finally
            Debug.WriteLine($"{GetMethodName()} - 終了")
        End Try
    End Function

    Private Function GetConnectionString() As String
        Debug.WriteLine($"{GetMethodName()} - 開始")
        Return New SQLiteConnectionStringBuilder() With {.DataSource = "..\..\database\ConsoleApp001.db"}.ToString()
        Debug.WriteLine($"{GetMethodName()} - 終了")
    End Function

    ''' <summary>
    ''' メソッド名の取得
    ''' </summary>
    ''' <returns>呼び出し元のメソッド名を返却します</returns>
    Private Function GetMethodName() As String
        Dim objHistory As New StackTrace(True)

        '呼び出し元のメソッド名を返す
        If objHistory.FrameCount > 2 Then
            Return objHistory.GetFrame(1).GetMethod.Name
        End If

        Return ""
    End Function

    ''' <summary>
    ''' データテープルをCSV形式で保存
    ''' </summary>
    ''' <param name="dtTable">データテーブル</param>
    Public Sub SaveDatatableToCSV(dtTable As DataTable)
        Const delimiter As Char = ","c
        If Not IO.Directory.Exists(IO.Path.Combine("..\..\", "SaveDatatable")) Then IO.Directory.CreateDirectory(IO.Path.Combine("..\..\", "SaveDatatable"))
        Dim fileName As String = $"{dtTable.TableName}_{Now.ToString("yyyyMMdd_HHmmss")}.csv"

        Using sw As New IO.StreamWriter(IO.Path.Combine("..\..\", "SaveDatatable", fileName), False, Text.Encoding.GetEncoding("shift_jis"))
            'ヘッダを書き込む
            For i As Integer = 0 To dtTable.Columns.Count - 1
                Dim field As String = dtTable.Columns(i).Caption
                sw.Write(field)
                If dtTable.Columns.Count - 1 > i Then
                    sw.Write(delimiter)
                End If
            Next
            sw.Write(vbCrLf)

            'レコードを書き込む
            For Each row As DataRow In dtTable.Rows
                For i As Integer = 0 To dtTable.Columns.Count - 1
                    Dim field As String = row(i).ToString()
                    sw.Write(field)
                    If dtTable.Columns.Count - 1 > i Then
                        sw.Write(delimiter)
                    End If
                Next
                sw.Write(vbCrLf)
            Next
        End Using
    End Sub

End Module

上記を実行すると、「users_20240609_100743.csv」というファイルが作成されます。内容は以下のようになっています。

Plaintext
id,name,age,email
1,テスト　太郎,36,t_taro@gmail.com
2,テスト　花子,35,t_hanako@google.com

ログの内容をコンソール上に出力させる

ログファイルに出力する以外にも、同じ内容をDOS画面に出力させるのもおすすめです。

開発時に、いちいちログファイルを開いて内容を確認するのが面倒ですよね。その場合、コンソールのDOS画面に、ログメッセージを出力するようにしてしまえば、ログファイルを開かずとも現在の実行状況が一目でわかるようになります。

当機能は、あくまで開発補助的な立ち位置の考え方ですので、本番環境で他プログラムから起動させる場合は、DOS画面が開かないように起動させてあげれば問題ありません。

VB
Module Module2_2

    Sub Main()
        Dim logger As New Logger2("Module2_2")
        Try
            logger.WriteLine($"**************************************  処理開始  **************************************")
            logger.WriteLine($"■パラメーター出力")
            logger.WriteLine($"・ログファイル出力先:{logger.LogFilePath}")
            logger.WriteLine($"■メイン処理")
            logger.WriteLine($"処理Ａ：完了")
            logger.WriteLine($"処理Ｂ：完了")
            logger.WriteLine($"処理Ｃ：完了")
            logger.WriteLine($"**************************************  正常終了  **************************************")
            Console.WriteLine("終了するには何かキーを押してください . . .")
            Console.ReadKey()
        Catch ex As Exception
            logger.WriteLine($"例外エラーが発生しました。{vbCrLf}{ex.ToString}")
            logger.WriteLine($"**************************************  異常終了  **************************************")
            Console.WriteLine("終了するには何かキーを押してください . . .")
            Console.ReadKey()
        End Try
    End Sub

End Module

Friend Class Logger2

    Private Const _logFileDirectory As String = "C:\Blog\VB\ConsoleApp001\log"
    Private _logFileName As String

    ''' <summary>
    ''' ログファイルのパスを返却します
    ''' </summary>
    ''' <returns>ログファイルのパス</returns>
    ReadOnly Property LogFilePath As String
        Get
            Return IO.Path.Combine(_logFileDirectory, $"{Now.ToString("yyyyMMdd")}_{_logFileName}.log")
        End Get
    End Property

    ''' <summary>
    ''' コンストラクタ
    ''' </summary>
    ''' <param name="logFileName">ログファイル名を指定してください。</param>
    Public Sub New(logFileName As String)
        _logFileName = logFileName
    End Sub

    ''' <summary>
    ''' 引数で指定されたログメッセージを出力します
    ''' </summary>
    ''' <param name="logMessage">出力するログメッセージ</param>
    Public Sub WriteLine(logMessage As String)
        Using writer As New IO.StreamWriter(LogFilePath, True)
            Dim message As String = $"{Now.ToString("yyyy/MM/dd HH:mm:ss.fff")}{vbTab}{logMessage}"
            writer.WriteLine(message)
            'ここでDOS画面にログメッセージを表示させています。
            Console.WriteLine(message)
        End Using
    End Sub

End Class

いかがだったでしょうか。ご紹介したベストプラクティスの中で、興味のあるものがあれば是非実践してみてください。

コメント

タイトルとURLをコピーしました