クラシックASPのコーディング考慮点 その3

ASPでのログ出力方法について

VBScriptでのログ出力 (Scripting.FileSystemObject)

ファイル出力自体は、Scripting.FileSystemObject があるのでこれを利用するが、 マルチスレッド下での動作となるので同期処理(排他)が必要。

VBScriptでは、プロセス間も含めてスレッド間の同期方法がない。

SleepしてWaitすることも難しい。 WScript.Shell経由でSleepするコマンドを実行する手段がないこともないが、ログ出力時のWaitには合わないし重い。 そもそもSleepしてリトライはさせたくない。

ということで、VBScript単体で実装する場合は、出力対象のログファイルが使用中なら予備のログファイルに出力する方法くらいか。


ログ出力 VBScript

Set fs_ = Server.CreateObject("Scripting.FileSystemObject")

Const ForAppending = 8 ' 追記モード
Sub WriteLog(fileNm, msg)
  Dim s
  Dim writer
  Dim i, wkFileNm, sExt, iPos
  
  s = GetTimestamp() & " " & msg
  On Error Resume Next
  Set writer = fs_.OpenTextFile(fileNm, ForAppending, True)
  If Err.Number <> 0 Then
    iPos = InStrRev(fileNm, ".")
    If iPos = 0 Then
      wkFileNm = fileNm
    Else
      wkFileNm = Mid(fileNm, 1, iPos - 1)
      sExt = Mid(fileNm, iPos)
    End If
    
    'エラーの場合、予備のログファイルへの出力
    For i = 0 To 20 - 1
      Err.Clear
      Set writer = fs_.OpenTextFile(wkFileNm & "-" & i & sExt, ForAppending, True)
      If Err.Number = 0 Then
        Exit For
      End If
    Next
  End If
  If Not writer Is Nothing Then
    writer.WriteLine s
    writer.Close
    Set writer = Nothing
  End If
  
End Sub

Function GetTimestamp()
  Dim ts, tmr
  Dim h,m,s,ms, wk
  ts = Now
  tmr = Timer
  wk = Fix(tmr)
  ms = Right("00" & Fix((tmr - wk)*1000), 3)
  s = wk Mod 60
  wk = (wk - s) \ 60
  m = wk Mod 60
  wk = (wk - m) \ 60
  h = wk Mod 60
  
  If m = 0 Then
    If h = 0 Then
      If Hour(ts) = 23 Then
        ts = DateAdd("d", 1, ts)
      End If
    End If
  End If
  
  GetTimestamp = Year(ts) & "/" & Right("0" & Month(ts), 2) & "/" & Right("0" & Day(ts), 2) _
    & " " & Right("0" & h, 2) & ":" & Right("0" & m, 2) & ":" & Right("0" & s, 2) & "." & ms
End Function

上記ではファイルオープン時にエラーが発生した場合、ファイル名を変えてオープンを試みている。20回も回しているが、ここまで切り替えが発生することはないだろう。

このログ出力関数を使う場合は、1サイトにつき1つのログファイルに出力するのでなく、ASPページ毎のログファイルに出力するなどの細かい単位で出力したほうがよい。

一応、実際のASPファイルに組み込んで、JMeterを使って負荷をかけたが問題なさそうではあった。 ノートPC上の仮想環境でテストしたのでどこまで信用できるか怪しいが。


GetTimestamp関数について補足。

1秒よりも細かい精度の時刻が欲しかったので、VBScriptのTimer関数を利用してミリ秒の出力を行っている。 ただ、精度としては10ミリ秒程度とのことらしい。


.NetFramework(C#)のCOM相互運用機能を使ってログ出力

COMと言えば.NetでないVBで実装していたが、現在ではもう使えないので.Netを使う。

.Netであれば、スレッド間の同期が可能なのでログ出力するのに悩まずにすむ。


.NetでCOMを実装するポイントは以下のとおり。

  • クラスライブラリでプロジェクト作成。

  • プロジェクトのプロパティ→アプリケーションタブ→アセンブリ情報→「アセンブリをCOM参照可能にする」にチェック。

  • プロジェクトのプロパティ→ビルドタブ→「COM相互運用機能の登録」にチェック。

  • プロジェクトのプロパティ→ビルドタブ→プラットフォームターゲットをx86に変更。

  • インタフェースを用意して、インタフェース用のGUIDを割り当てる。

  • クラスにはProgIdを設定する。クラス用のGUIDを割り当てる。インタフェースをデフォルトインタフェースにするため、ClassInterface(ClassInterfaceType.None)を指定する。

  • COMを登録する場合は、「regasm 作成したdll /tlb /codebase」。「/codebase」はGACに登録しない場合は必須。

  • COMを登録解除する場合は、「regasm 作成したdll /unregister」。


ログ出力 C# COM相互運用機能利用版

using System;
using System.Collections.Generic;
using System.IO;
using System.Runtime.InteropServices;

namespace MyScriptUtil
{
    [Guid("00EE6642-ED0E-49a2-B0F0-XXXXXXXXXXXX")] //←インタフェース用のGUID
    public interface ILogger
    {
        bool IsErrorEnabled { get; }
        bool IsWarnEnabled { get; }
        bool IsInfoEnabled { get; }
        bool IsTraceEnabled { get; }
        bool IsDebugEnabled { get; }
        void Error(string msg);
        void Warn(string msg);
        void Info(string msg);
        void Trace(string msg);
        void Debug(string msg);

        string LogFileName { get; set; }
        string SourceName { get; set; }
        void SetLevel(string level);
    }

    [ComVisible(true)]
    [ClassInterface(ClassInterfaceType.None)]
    [ProgId("MyScriptUtil.Logger")]
    [Guid("4AD76CEA-4361-4a6b-8BDC-XXXXXXXXXXXX")] //←クラス用のGUID
    public class Logger : ILogger
    {
        private string _logFileName = string.Empty;
        private string _sourceName = string.Empty;
        private bool _isErrorEnabled = false;
        private bool _isWarnEnabled = false;
        private bool _isInfoEnabled = false;
        private bool _isTraceEnabled = false;
        private bool _isDebugEnabled = false;
        private readonly static object _lock = new object();
        private readonly static Dictionary<string, object> _filelock = new Dictionary<string, object>();
        private readonly static Dictionary<string, TextWriter> _writer = new Dictionary<string, TextWriter>();
        private readonly static Dictionary<string, DateTime> _lastWrote = new Dictionary<string, DateTime>();
        private static System.Threading.Thread _closer = null;

        private readonly static ILogFormatter _defaultFormatter = new DefaultFormatter();
        private ILogFormatter _formatter = _defaultFormatter;

        public void SetFormatter(ILogFormatter formatter)
        {
            _formatter = formatter;
        }

        private void PutLog(string level, string msg)
        {
            DateTime ts = DateTime.Now;
            if (!_filelock.ContainsKey(_logFileName))
            {
                if (string.IsNullOrEmpty(_logFileName))
                {
                    return;
                }
                lock (_lock)
                {
                    if (!_filelock.ContainsKey(_logFileName))
                    {
                        _filelock.Add(_logFileName, new object());
                        _writer.Add(_logFileName, File.AppendText(_logFileName));
                        _lastWrote.Add(_logFileName, DateTime.MinValue);
                    }
                    if (_closer == null)
                    {
                        _closer = new System.Threading.Thread(new System.Threading.ThreadStart(FileCloser));
                        _closer.Start();
                    }
                }
            }
            lock (_filelock[_logFileName])
            {
                try
                {
                    //using (TextWriter writer = File.AppendText(_logFileName))
                    //{
                    //    _formatter.PutLog(writer, level, _sourceName, ts.ToString("yyyy/MM/dd HH:mm:ss.fff"), msg);
                    //}
                    TextWriter writer;
                    if (_writer[_logFileName] == null)
                    {
                        _writer[_logFileName] = File.AppendText(_logFileName);
                        writer = _writer[_logFileName];
                    }
                    else
                    {
                        writer = _writer[_logFileName];
                    }
                    _formatter.PutLog(writer, level, _sourceName, ts.ToString("yyyy/MM/dd HH:mm:ss.fff"), msg);
                    writer.Flush();
                    _lastWrote[_logFileName] = DateTime.Now;
                }
                catch (Exception e)
                {
                    e.ToString();
                    try
                    {
                        if (_writer[_logFileName] != null)
                        {
                            _writer[_logFileName].Close();
                            _writer[_logFileName] = null;
                        }
                    }
                    catch
                    {
                    }
                }
            }
        }
        private static void FileCloser()
        {
            while (true)
            {
                System.Threading.Thread.Sleep(1000);

                foreach (string key in _filelock.Keys)
                {
                    lock (_filelock[key])
                    {
                        if (DateTime.Now.Subtract(_lastWrote[key]).TotalSeconds > 10.0)
                        {
                            if (_writer[key] != null)
                            {
                                _writer[key].Close();
                            }
                            _writer[key] = null;
                        }
                    }
                }
            }
        }

        #region ILogger メンバ
        public void Debug(string msg)
        {
            if (_isDebugEnabled)
            {
                PutLog("DEBUG", msg);
            }
        }
        
        // 省略
        
        #endregion
    }

    [ComVisible(false)]
    public interface ILogFormatter
    {
        void PutLog(TextWriter writer, string level, string sourceName, string timestampStr, string msg);
    }

    [ComVisible(false)]
    [ClassInterface(ClassInterfaceType.None)]
    public class DefaultFormatter : ILogFormatter
    {
        public void PutLog(TextWriter writer, string level, string sourceName, string timestampStr, string msg)
        {
            writer.Write(timestampStr);
            writer.Write(",");
            writer.Write(level);
            writer.Write(",");
            writer.Write(sourceName);
            writer.Write(",");
            writer.Write(System.Threading.Thread.CurrentThread.ManagedThreadId);
            writer.Write(" ");
            writer.WriteLine(msg);
        }
    }
}
補足

ログファイルは別スレッドにて10秒間書き込みがなければCloseするようにした。 しかし、IISでこのように勝手にスレッドを作るのは作法的によくないかもしれない。

ストリームをOpenしっぱなしにするか、書き込みごとにOpen、Closeするのが無難だろう。

ファイル出力の同期については、ファイルごとにstaticオブジェクトを割り当てそれをlockステートメント排他制御を行っている。 ストリームをOpenしたままにするのであれば、TextWriter.Synchronizedが利用できるらしい。その場合はTextWriterをstaticにする必要がある。


参考サイト

http://kwski.net/architecture/539/

http://hp.vector.co.jp/authors/VA007219/rtc_pic.html

http://internetcom.jp/developer/20060627/25.html

http://needtec.exblog.jp/21522702/

https://msdn.microsoft.com/ja-jp/library/aa288456%28v=vs.71%29.aspx