[WIP][App] LogSync - Load multiple log files and view side-by-side, synchronized by timestamps
Posted: 20 Jan 2017, 18:16
My company writes some software that involves a server and a client, and part of my job is to debug issues in communication between them.
Hence lots of looking at logs, and trying to piece together the communication between the two, and CMTrace just wasn't doing it for me.
I had a google around, but turned up nothing, so I decided to see if I could hack something together.
Here is an initial proof-of-concept. There's a bunch of borrowed code - AutXYWH and some listview scrolling synch code I found and adapted, but as a start, it seems quite promising.
You will need two log files, the ones I used varied slightly in format:
For now, it ignores the date part, so in the above example, the first example would just register as 12:50:34.702
Basically, as long as your log has HH:MM:SS.mil type timestamps, the logic should work, although the regex may need some tweaking
Hence lots of looking at logs, and trying to piece together the communication between the two, and CMTrace just wasn't doing it for me.
I had a google around, but turned up nothing, so I decided to see if I could hack something together.
Here is an initial proof-of-concept. There's a bunch of borrowed code - AutXYWH and some listview scrolling synch code I found and adapted, but as a start, it seems quite promising.
You will need two log files, the ones I used varied slightly in format:
Code: Select all
20 Jan 2017 12:50:34.702 [17308] INFO - Some Client v3.0.0.12
12:50:14.510 Some Server: v3.0.0.24 (Jan 19 2017)
2017-01-20 12:54:32,438 INFO Some other text
Basically, as long as your log has HH:MM:SS.mil type timestamps, the logic should work, although the regex may need some tweaking
Code: Select all
;OutputDebug DBGVIEWCLEAR
#SingleInstance force
Version := "1.0.1"
Gui, +Resize
; AHK_L + AutoXYWH based Autosize GUI
Gui, Add, Button, xm w300 gPick1 vPick1, Select...
Gui, Add, Button, x+10 w300 gPick2 vPick2, Select...
Gui, Add, Button, xm w610 gGo vGo, Sync!
Gui, Add, Text, xm w300 hwndhTitle1 vTitle1 Center, % A_Space
Gui, Add, Text, x+10 yp w300 hwndhTitle2 vTitle2 Center, % A_Space
Gui, Add, ListView, AltSubmit xm w300 h200 hwndhLV1 vLV1, Time|Text
Gui, Add, ListView, AltSubmit x+10 yp w300 h200 hwndhLV2 vLV2, Time|Text
; AHK_H based AutoSize GUI
;~ Gui, Add, Button, xm w300 aw1/2 gPick1, Select...
;~ Gui, Add, Button, x+10 w300 aw1/2 ax1/2 gPick2, Select...
;~ Gui, Add, Button, xm w610 aw gGo, Sync!
;~ Gui, Add, Text, xm w300 hwndhTitle1 aw1/2 Center, % A_Space
;~ Gui, Add, Text, x+10 yp w300 hwndhTitle2 aw1/2 ax1/2 axr Center, % A_Space
;~ Gui, Add, ListView, AltSubmit xm w300 h200 hwndhLV1 aw1/2 ah, Time|Text
;~ Gui, Add, ListView, AltSubmit x+10 yp w300 h200 hwndhLV2 aw1/2 ah ax1/2 axr, Time|Text
fn := Func("ListScrolled").Bind(1)
GuiControl, +g, % hLV1, % fn
fn := Func("ListScrolled").Bind(2)
GuiControl, +g, % hLV2, % fn
ListViews := [hLV1, hLV2]
Titles := [hTitle1, hTitle2]
RawLines := [[],[]]
Gui, Show, Hide ; Autosize set initial (smallest) size
Gui, Show, x0 y0 w1024 h768, % "Log Sync v" Version ; Show and size up to a reasonable size
return
GuiClose:
ExitApp
; #IfWinActive ahk_class AutoHotkeyGUI
; Any Gui-specific hotkeys would go here
; #IfWinActive
Pick1:
Pick2:
index := SubStr(A_ThisLabel, 5, 1)
FileSelectFile, file
if ErrorLevel
return
Pick(index, file)
return
Pick(index, file){
global RawLines, ListViews, Titles
GuiControl, , % Titles[index], % file
RawLines[index] := ReadLog(file)
Gui, ListView, % ListViews[1]
LV_Delete()
Gui, ListView, % ListViews[2]
LV_Delete()
}
Go:
SyncedLines := SyncLogs(RawLines)
PopulateListViews(ListViews, SyncedLines)
Gui, ListView, % ListViews[1]
LV_ModifyCol()
Gui, ListView, % ListViews[2]
LV_ModifyCol()
return
PopulateListViews(ListViews, SyncedLines){
coords := GetProgressCoords(300, 100)
Progress, % "b w300 h100 x" coords.x " y" coords.y, , Populating ListViews
prog := 0
for lv_index, hwnd in ListViews {
Gui, ListView, % hwnd
max := SyncedLines[lv_index].length()
tick := 50 / max
Loop % max {
line := SyncedLines[lv_index, A_Index]
LV_Add("", line.rawtime, line.text)
prog += tick
Progress, % round (prog)
}
}
Progress, Off
}
; Logs are expected to be in one of two formats:
; 20 Jan 2017 12:50:34.702 [17308] INFO - Some Client v3.0.0.12
; 12:50:14.510 Some Server: v3.0.0.24 (Jan 19 2017)
; For now, the Date part is thrown away...
; The regex should handle there being no milliseconds, but both logs should lack milliseconds in this instance.
ReadLog(filename){
FileRead, log_text, % filename
log_lines := []
Loop, Parse, % log_text, `n, `r
{
RegExMatch(A_LoopField, "^([\w\s-]+)?(\d{2}):(\d{2}):(\d{2}).?(\d{3})?(.*)", matches)
log_time := Trim(matches2 matches3 matches4 matches5)
log_line := Trim(matches6)
if (!log_time || !log_line)
continue
log_lines.push({time: log_time, text: log_line, rawtime: matches2 ":" matches3 ":" matches4 ":" matches5})
}
return log_lines
}
SyncLogs(RawLines){
coords := GetProgressCoords(300, 100)
Progress, % "b w300 h100 x" coords.x " y" coords.y, , Syncing Logs
Lengths := [RawLines[1].length(), RawLines[2].length()]
highest := Lengths[1]
if (Lengths[2] > highest)
highest := Lengths[2]
tick := 100 / highest
prog := 0
CurrentLine := [1,1]
SyncedLines := [[],[]]
Loop {
l1 := CurrentLine[1]
l2 := CurrentLine[2]
c1 := RawLines[1, l1]
c2 := RawLines[2, l2]
t1 := RawLines[1, l1].time
t2 := RawLines[2, l2].time
if (((t1) && t1 < t2) || t2 == ""){
; Log 1 line earlier than Log 2 line
SyncedLines[1].push(RawLines[1, l1])
SyncedLines[2].push({time: 0, text: ""})
CurrentLine[1]++
} else if (((t2) && t2 < t1) || t1 == ""){
; Log 2 line earlier than Log 1 line
SyncedLines[1].push({time: 0, text: ""})
SyncedLines[2].push(RawLines[2, l2])
CurrentLine[2]++
} else if (t1 == t2) {
; Log 1 & Log 2 line at same time
SyncedLines[1].push(RawLines[1, l1])
SyncedLines[2].push(RawLines[2, l2])
CurrentLine[1]++
CurrentLine[2]++
} else {
;~ debug := 1
msgbox ERROR
}
prog += tick
Progress, % round(prog)
Progress, , % "1: Current=" CurrentLine[1] ", max=" Lengths[1] "`n2: Current=" CurrentLine[2] ", max=" Lengths[2]
} until (CurrentLine[1] >= Lengths[1] && CurrentLine[2] >= Lengths[2])
Progress, Off
return SyncedLines
}
GetProgressCoords(pw, ph){
Gui, +HwndhMain
WinGetPos, x, y, w, h, % "ahk_id " hMain
px := (x + (w / 2)) - (pw / 2)
py := y + (h / 2) - (ph / 2)
return {x: px, y: py}
}
; -------------- End of SyncLogs-specific code ---------------------------
; code from https://autohotkey.com/board/topic/38906-scroll-3-listviews-simultaneaous/
; Handles ListView scroll position synchronization
ListScrolled(this_lv){
global ListViews
;OutputDebug % "AHK| " A_TickCount " - lv: " this_lv ", event: " A_GuiEvent ", erorlevel: " ErrorLevel
other_lv := 3 - this_lv
;~ if down||up ;i.e the scrollevent is triggered by the mousewheel or the up/down buttons
;~ return ;therefore: do not use the lines below to update the other listviexs
;critical
if (A_GuiEvent == "S")
{
startlogged = 1
;start scroll
ScrollCount++
}
if (A_GuiEvent == "I" && ErrorLevel == "SF"){
; Keyboard scroll
sa := LVC_getTopIndex(ListViews[this_lv]) - LVC_getTopIndex(ListViews[other_lv])
lh := 20 ; ToDo - why does LVC_getItemHeight not seem to work?
LVC_Scroll(ListViews[other_lv], sa * lh)
return
}
else if (A_GuiEvent == "s")
{
if !startlogged
ScrollCount++
if !ScrollCount
return
ScrollCount--
if (!ScrollCount)
{
loop,2
{
;if ("ListView" A_Index = A_GuiControl)
if (A_Index == this_lv){
continue
}
sa := LVC_getTopIndex(ListViews[this_lv]) - LVC_getTopIndex(ListViews[other_lv])
lh := 20 ; ToDo - why does LVC_getItemHeight not seem to work?
LVC_Scroll(ListViews[other_lv], sa * lh)
}
}
}
}
/*
Retrieves the index of the topmost visible item when in list or report view.
Returns the index of the item if successful,
or zero if the list-view control is in icon or small icon view.
*/
LVC_getTopIndex(ThisControl)
{
;LVM_GETTOPINDEX = LVM_FIRST + 39 = 0x1027
SendMessage, 0x1027, 0, 0, , ahk_id %ThisControl%
return ErrorLevel + 1
}
LVC_Scroll(ThisControl, pxls)
{
;if pxls > 0, scrolls down
;if pxls < 0, scrolls up
;LVM_SCROLL = LVM_FIRST + 20 = 0x1014
SendMessage, 0x1014, 0, pxls, , ahk_id %ThisControl%
}
/*
Returns the height for an item in the list-view control.
(all items, in the same control, have the same height)
If the list-view has no items, this function returns 0
*/
LVC_getItemHeight(ThisControl)
{
LVC_getItemRect(ThisControl, 1, ItemBounds)
Top := NumGet(ItemBounds, 4, "int")
Bottom := NumGet(ItemBounds, 12, "int")
return Bottom - Top
}
;Retrieves the bounding rectangle for all or part of an item in the current view.
LVC_getItemRect(ThisControl, iItem, ByRef ItemBounds, boundType = 0)
{
/*
Valid values for boundType:
LVIR_BOUNDS = 0 (default)
Returns the bounding rectangle of the entire item,
including the icon and label.
LVIR_ICON = 1
Returns the bounding rectangle of the icon or small icon.
LVIR_LABEL = 2
Returns the bounding rectangle of the item text.
LVIR_SELECTBOUNDS = 3
Returns the union of the LVIR_ICON and LVIR_LABEL rectangles,
but excludes columns in report view.
*/
;creates a new rect structure,
;and sets boundType as the LEFT member (as required for message)
VarSetCapacity(ItemBounds, 16), NumPut(boundType, ItemBounds)
;LVM_GETITEMRECT = LVM_FIRST + 14 = 0x100E
SendMessage, 0x100E, iItem - 1, &ItemBounds, , ahk_id %ThisControl%
return ErrorLevel
}
; =================================================================================
; Function: AutoXYWH
; Move and resize control automatically when GUI resizes.
; Parameters:
; DimSize - Can be one or more of x/y/w/h optional followed by a fraction
; add a '*' to DimSize to 'MoveDraw' the controls rather then just 'Move', this is recommended for Groupboxes
; cList - variadic list of ControlIDs
; ControlID can be a control HWND, associated variable name, ClassNN or displayed text.
; The later (displayed text) is possible but not recommend since not very reliable
; Examples:
; AutoXYWH("xy", "Btn1", "Btn2")
; AutoXYWH("w0.5 h 0.75", hEdit, "displayed text", "vLabel", "Button1")
; AutoXYWH("*w0.5 h 0.75", hGroupbox1, "GrbChoices")
; ---------------------------------------------------------------------------------
; Version: 2015-5-29 / Added 'reset' option (by tmplinshi)
; 2014-7-03 / toralf
; 2014-1-2 / tmplinshi
; requires AHK version : 1.1.13.01+
; =================================================================================
AutoXYWH(DimSize, cList*){ ; http://ahkscript.org/boards/viewtopic.php?t=1079
static cInfo := {}
If (DimSize = "reset")
Return cInfo := {}
For i, ctrl in cList {
ctrlID := A_Gui ":" ctrl
If ( cInfo[ctrlID].x = "" ){
GuiControlGet, i, %A_Gui%:Pos, %ctrl%
MMD := InStr(DimSize, "*") ? "MoveDraw" : "Move"
fx := fy := fw := fh := 0
For i, dim in (a := StrSplit(RegExReplace(DimSize, "i)[^xywh]")))
If !RegExMatch(DimSize, "i)" dim "\s*\K[\d.-]+", f%dim%)
f%dim% := 1
cInfo[ctrlID] := { x:ix, fx:fx, y:iy, fy:fy, w:iw, fw:fw, h:ih, fh:fh, gw:A_GuiWidth, gh:A_GuiHeight, a:a , m:MMD}
}Else If ( cInfo[ctrlID].a.1) {
dgx := dgw := A_GuiWidth - cInfo[ctrlID].gw , dgy := dgh := A_GuiHeight - cInfo[ctrlID].gh
For i, dim in cInfo[ctrlID]["a"]
Options .= dim (dg%dim% * cInfo[ctrlID]["f" dim] + cInfo[ctrlID][dim]) A_Space
GuiControl, % A_Gui ":" cInfo[ctrlID].m , % ctrl, % Options
} } }
; AutoXYWH Gui Sizing for AHK_L
GuiSize:
If (A_EventInfo = 1) ; The window has been minimized.
Return
AutoXYWH("w.5", "Pick1")
AutoXYWH("w.5 x.5", "Pick2")
AutoXYWH("w", "Go")
AutoXYWH("w.5", "Title1")
AutoXYWH("w.5 x.5", "Title2")
AutoXYWH("w.5 h", "LV1")
AutoXYWH("w.5 x.5 h", "LV2")
return