82. Notes客户端Print相同信息到状态栏的问题

这可能是个微不足道的问题，不过其他人也应该遇到过。在Notes客户端用LotusScript的Print语句输出信息到状态栏时，如果多次调用传入的参数实际相同，状态栏只会显示该信息一次。例如：

Print "a"

Print "a"

Print "a"

不会输出三行a，而只有一行。如果作为参数的变量内容相同，多次调用也只会输出一次。例如：

Print view.Toplevelentrycount

Print view.Toplevelentrycount

Print view.Toplevelentrycount

你或许会问，即使这有些不正常，也没什么妨碍，重复输出有什么意义呢？原因如下。在客户端应用程序中，这些对Print的调用都是为了在程序运行时给用户（不论是普通用户还是开发者人员）信息和反馈。Print重复的静态信息的用例会出现在报告事件和处理进度时，例如在批量审批流程、处理附件、查找特定记录等等时，可以在发生或处理完一个事件后，调用这样的语句：Print"A purchase workflow is reviewed."，Print "A XXX record is found."。以上情况还可以通过在输出的信息中添加序列号来解决。而受这种输出丢失影响更大的则是Print的参数为变量的情况。尤其是在调试程序时，往往会在代码的不同处Print同一变量，以理解某些语句的效果或弄清错误的原因。这时应该的多行输出变为一行，令人困扰。当然可以人为添加一些注释使得每次输出都有差别，但很麻烦。

Print只在客户端运行的代码中，也就是输出到客户端状态栏时，有这种行为。包含它的代码运行在服务器端时，按触发方式或者输出到服务器控制台，或者返回给浏览器，都没有这个问题。所以这是Print语句的特性，抑或是Notes客户机状态栏的问题，似乎更有可能是后者。

这种行为是不是bug？或者是出于某些限制或考量有意设计如此？非计算机科班出身的我，想不出来，在网上也没有查到。不过我印象中Firefox的Firebug插件的控制台也曾有同样行为，用console.log()方法输出重复信息时，只会显示一条。后来有了改进，在输出信息的左边会在括号里标注重复输出的次数，例如（5）Show me again.

剩下的就是如何应对，即workaround。

首先容易想到的就是写一个函数包装Print，在实际要输出的信息前附上当前时间。除却我们的目的，显示输出信息的时间本身也是有益的。遗憾的是LotusScript里的日期时间类型Variant只精确到秒，如果重复信息的输出是在同一秒内，问题依旧。LotusScript可获得的最精确的当前时间是Timer函数的返回值，精确到百分之一秒。于是我们可以写出如下函数：

Public Function PrintMsg(msg As Variant)Dim strTime As StringstrTime=Format(Now, "hh:mm:ss")Dim hs As Long hs=Timer Mod 100strTime=strTime & ":" & hsPrint(strTime & " - " & msg)End Function

但在应用时会发现，百分之一秒对于计算机和LotusScript仍然是很漫长的（这是件好事），所以在类似下面的代码中，输出的信息对于Print语句仍然是相同的，也就会发生丢失。

call PrintMsg(view.Toplevelentrycount)Call CreateDoc(db)call PrintMsg(view.Toplevelentrycount)

LotusScript里的时间只精确到百分之一秒，是因为Notes和Domino是跨平台的，不同操作系统支持的时间精度不等，但最少都在十毫秒数量级。利用GetThreadInfo函数凭藉操作系统的clocktick概念实际能获得时间段的更高精度。下面是网上曾有人对不同系统的测试结果 (http://searchdomino.techtarget.com/tip/Accurate-LotusScript-timing-technique):

Ticks per second：

Win2000 Domino 6.0 (ticks per second1000)

Win2000 Domino 5.0.9a (ticks per second1000)

AIX 4.3.3 ML 9 with Domino 5.0.11 (ticks per second = 1,000,000)

Solaris 8 with Domino 5.0.11 (ticks per second = 1,000,000)

SuSE Linux 8.1 with Domino 6.0.1 (ticks per second 1000)

SunOS 5.8 Generic_108528-18 with Domino Release 6.0.1; (ticks per second 1000)   

因此下面的代码演示了如何获得一段时间小于一秒的部分，并将它转化到毫秒单位。

dim tick1 as Long, tick2 as Long, tps as Longtps=GetThreadInfo(7)tick1=GetThreadInfo(6)'do somethingtick2=GetThreadInfo(6)dim dif as Long 'The difference of the part of milliseconds dif=((tick2-tick1) Mod tps)/tps*1000

但是因为clock tick表示的是系统时钟自开机以来的时钟周期数，并不能由它直接确定当前时间，所以不能用在我们上面的函数以获得更高的时间精度。

为了彻底解决本文所说的问题，只有在每次输出前附上一个序列号。为此需要将PrintMsg函数包装在一个对象里，从而能够操作作为对象字段的序列号。

Private printNum As Integer 'Used for distinguish printing same contentsPublic Function PrintMsg(msg As Variant)Dim strTime As StringstrTime=Format(Now, "hh:mm:ss")Dim hs As Long hs=Timer Mod 100strTime=strTime & ":" & hsprintNum=printNum+1Print("[" & printNum & "]" & strTime & " - " & msg)End Function

调用它输出重复内容的效果如下：

[1]16:52:36:24 – 81

[2]16:52:36:24 - 81

[3]16:52:36:24 - 81

我把这个方法添加到以前曾介绍过的Log4Dom类里，当然诸位也可以单独为它创建一个更精简的类。

Class Log4Dompublic logLevel As Integerpublic module As String'module'the Log Destination, set as a variant then depending on the log type, 'set as either a LogDB, logNotesFile, logStatus or logPromptPrivate logFile As VariantPrivate s As NotesSession Private db As NotesDatabase 'current databasePrivate profile As NotesDocument 'Log4Dom profile documentpublic logName As String 'log name from the profilePrivate printNum As Integer 'Used for distinguish printing same contentsSub New ()Set s=New NotesSessionlogLevel = LEVEL_DEBUGEnd Sub%REMAdd a log destination.As the de facto only used log destination is Notes DB,I didn't handle the case of multiple log destinations of different types.%END REMPublic Function AddLogFile(file As Variant)Set logFile = fileIf TypeName(file)="LOGDB" then'read parameter from Log4Dom profile by starrowSet db=s.CurrentDatabaseSet profile=db.GetProfileDocument("Log4DomProfile")If Not profile Is Nothing ThenIf profile.GetItemValue("LogLevel")(0)><"" thenlogLevel=profile.GetItemValue("LogLevel")(0)End iflogName=profile.GetItemValue("LogName")(0)End If'if no parameter provided, try the agent nameIf logName="" ThenIf Not s.CurrentAgent Is Nothing ThenlogName=s.CurrentAgent.NameEnd IfEnd IflogFile.LogName=logNameEnd ifEnd Function'logging at the different levels, INFO, WARN etcPublic Function Info(message As String) As IntegerInfo = WriteLog(LEVEL_INFO, message)End FunctionPublic Function Warn(message As String) As IntegerWarn = WriteLog(LEVEL_WARN, message)End FunctionPublic Function Debug(message As String) As IntegerDebug = WriteLog(LEVEL_DEBUG, message)End Function'Can't use error as the function name because it's a reserved word.'If used for logging a runtime error, leave the argument as an empty string.Public Function LogError(message As String) As IntegerIf message="" Then'Generate the message for a runtime error.'The GetThreadInfo(LSI_THREAD_CALLPROC) must be called here instead of 'calling an universal function to get the error message because that would'always return LogError as the function raising the error.  'LSI_THREAD_CALLMODULE=11, LSI_THREAD_CALLPROC=10message = GetThreadInfo(11) & ">" & GetThreadInfo(10) & ": " & _"Error(" & Err() & "): " & Error() & " at line "& Erl()End IfLogError = WriteLog(LEVEL_ERROR, message) End FunctionPublic Function Fatal(message As String) As IntegerFatal = WriteLog(LEVEL_FATAL, message)End Function'user level logging, for specific level logging'@param level integer - the level 10 is the most detail, 1 the lowest level'message - a string to be logged. Number, boolean and date values would be'automatically converted to strings by LotusScript. Other types should be manually converted.Public Function WriteLog(level As Integer, message As String) As IntegerDim theDate As StringDim theLevel As StringDim theMessage As StringtheDate = Cstr(Now)theLevel = "["+GetLevelString(level)+"] "theMessage = theDate+" "+theLevel+" "+module+" - "+message' check that logging is turned on for this level' otherwise there is no need to logIf level <= logLevel ThenCall logFile.writelog(theMessage)End IfEnd Function'closes the log, saves notes doc or closes filePublic Function CloselogFile.closeEnd Function'convert from level numbers into stringPrivate Function GetLevelString(level As Integer) As StringSelect Case levelCase LEVEL_INFO : GetLevelString = LEVEL_INFO_STRINGCase LEVEL_DEBUG : GetLevelString = LEVEL_DEBUG_STRINGCase LEVEL_WARN : GetLevelString = LEVEL_WARN_STRINGCase LEVEL_ERROR : GetLevelString = LEVEL_ERROR_STRINGCase LEVEL_FATAL : GetLevelString = LEVEL_FATAL_STRINGCase Else : GetLevelString = "LEVEL "+Cstr(level)End SelectEnd Function%REM        If the argument is the same, multiple calls to Print are executed only once.This function appends the current time before the message to be printed. Thetime is rounded to the nearest hundredth of second. However, for some circumstances,this is still not enough to avoid the same content to be printed. Thus, a serialnumber is appended.%END REMPublic Function PrintMsg(msg As Variant)Dim strTime As StringstrTime=Format(Now, "hh:mm:ss")Dim hs As Long hs=Timer Mod 100strTime=strTime & ":" & hsprintNum=printNum+1Print("[" & printNum & "]" & strTime & " - " & msg)End FunctionEnd Class'Get a logger instance that writes to the specified db.Public Function GetLogger(db As NotesDatabase) As log4DomDim logger As log4domSet logger = New log4dom()Dim logFile As New LogDB(db)Call logger.AddLogFile(logFile)Set GetLogger=loggerEnd FunctionDim logger As Log4DomSet logger=GetLogger(Nothing)call logger.PrintMsg(81)call logger.PrintMsg(81)call logger.PrintMsg(81)