Files
VRCWT-OSC/internal/app/vrc_log.go
messypy b25e002092
Some checks failed
build-windows-exe / build (push) Failing after 1m43s
Make log decoding build on non-Windows CI
2026-07-27 23:13:30 +09:00

554 lines
14 KiB
Go
Raw Blame History

package app
import (
"bytes"
"fmt"
"io"
"log"
"os"
"path/filepath"
"regexp"
"strings"
"time"
"unicode/utf16"
)
var (
joinPattern = regexp.MustCompile(`OnPlayerJoined\s+(.+?)\s+\(usr_[0-9a-fA-F-]+\)`)
leftPattern = regexp.MustCompile(`OnPlayerLeft\s+(.+?)\s+\(usr_[0-9a-fA-F-]+\)`)
worldIdPattern = regexp.MustCompile(`worldId=(wrld_[0-9a-fA-F-]+)`)
instanceIdPattern = regexp.MustCompile(`instanceId=([^,}\s]+)`)
worldNamePattern = regexp.MustCompile(`worldName=([^,}]+)`)
worldLocationPattern = regexp.MustCompile(`worldId=(wrld_[0-9a-fA-F-]+):([^\s,\]\)\"']+)`)
worldPattern = regexp.MustCompile(`(wrld_[0-9a-fA-F-]+(?::[^\s\]\)\"']+)?)`)
enteringRoomPattern = regexp.MustCompile(`\[Behaviour\]\s+(?:Entering Room|Joining or Creating Room):\s+(.+)$`)
)
const vrchatLogTailBytes = 2 * 1024 * 1024
type vrcLogState struct {
location string
worldID string
instanceID string
worldName string
pendingWorldName string
presentSet map[string]struct{}
initialized bool
}
func getVrchatLogDir() (string, error) {
userProfile := os.Getenv("USERPROFILE")
if userProfile == "" {
return "", os.ErrNotExist
}
return filepath.Join(userProfile, "AppData", "LocalLow", "VRChat", "VRChat"), nil
}
func findLatestVrchatLog() (string, error) {
dir, err := getVrchatLogDir()
if err != nil {
return "", err
}
entries, err := os.ReadDir(dir)
if err != nil {
return "", err
}
var latest string
var latestMod time.Time
for _, entry := range entries {
if entry.IsDir() {
continue
}
name := entry.Name()
if !strings.HasSuffix(strings.ToLower(name), ".log") && !strings.HasSuffix(strings.ToLower(name), ".txt") {
continue
}
info, err := entry.Info()
if err != nil {
continue
}
if info.ModTime().After(latestMod) {
latestMod = info.ModTime()
latest = filepath.Join(dir, name)
}
}
if latest == "" {
return "", os.ErrNotExist
}
return latest, nil
}
func watchVrchatLog() {
log.Printf("vrchat log watcher started")
defer func() {
if r := recover(); r != nil {
log.Printf("vrchat log watcher panic: %v", r)
}
}()
lastPath := ""
lastSize := int64(0)
state := &vrcLogState{
presentSet: map[string]struct{}{},
}
for {
path, err := findLatestVrchatLog()
if err != nil {
log.Printf("vrchat log not found: %v", err)
time.Sleep(currentGUIRefreshInterval())
continue
}
info, err := os.Stat(path)
if err != nil {
log.Printf("vrchat log stat failed: %v", err)
time.Sleep(currentGUIRefreshInterval())
continue
}
log.Printf("vrchat log loop path=%s size=%d last=%d", path, info.Size(), lastSize)
if path != lastPath {
log.Printf("vrchat log watching %s", path)
lastPath = path
lastSize = 0
log.Printf("vrchat log initial scan begin path=%s", path)
if err := scanExistingVrchatLog(path, state); err != nil {
log.Printf("vrchat log initial scan failed: %v", err)
} else {
log.Printf("vrchat log initial scan ok path=%s", path)
}
if info2, err := os.Stat(path); err == nil {
lastSize = info2.Size()
} else {
lastSize = info.Size()
}
time.Sleep(currentGUIRefreshInterval())
continue
}
if info.Size() < lastSize {
lastSize = 0
}
if info.Size() > lastSize {
log.Printf("vrchat log updated path=%s old=%d new=%d", path, lastSize, info.Size())
b, err := readFileFrom(path, lastSize)
if err != nil {
log.Printf("vrchat log read failed: %v", err)
time.Sleep(currentGUIRefreshInterval())
continue
}
text := decodeVRChatLog(b)
lines := strings.Split(text, "\n")
joinHits := 0
leaveHits := 0
for _, line := range lines {
line = strings.TrimRight(line, "\r")
if line == "" {
continue
}
if err := appendRuntimeLog("VRC LOG", line); err != nil {
log.Printf("append runtime log failed: %v", err)
}
at := extractLineTime(line)
if changed, worldLabel := updateWorldState(state, line); changed {
log.Printf("world changed: %s", worldLabel)
state.presentSet = map[string]struct{}{}
handleWorldChange(state, worldLabel, at)
_ = appendRuntimeLog("VRC WORLD", worldLabel)
}
if m := joinPattern.FindStringSubmatch(line); len(m) == 2 {
name := strings.TrimSpace(m[1])
log.Printf("join detected: %s", name)
joinHits++
state.presentSet[name] = struct{}{}
if tracker := GetGuestTracker(); tracker != nil {
tracker.MarkJoin(name, at)
}
if tracker := GetJoinLeaveEventTracker(); tracker != nil {
tracker.Record("join", name, len(state.presentSet), at)
}
out := fmt.Sprintf("[join] %s (%d)", name, len(state.presentSet))
log.Print(out)
if err := appendJoinLeaveLog(out); err != nil {
log.Printf("append join log failed: %v", err)
}
continue
}
if m := leftPattern.FindStringSubmatch(line); len(m) == 2 {
name := strings.TrimSpace(m[1])
log.Printf("leave detected: %s", name)
leaveHits++
delete(state.presentSet, name)
if tracker := GetGuestTracker(); tracker != nil {
tracker.MarkLeave(name, at)
}
if tracker := GetJoinLeaveEventTracker(); tracker != nil {
tracker.Record("leave", name, len(state.presentSet), at)
}
out := fmt.Sprintf("[leave] %s (%d)", name, len(state.presentSet))
log.Print(out)
if err := appendJoinLeaveLog(out); err != nil {
log.Printf("append leave log failed: %v", err)
}
continue
}
}
log.Printf("vrchat log batch done join=%d leave=%d", joinHits, leaveHits)
lastSize = info.Size()
}
time.Sleep(currentGUIRefreshInterval())
}
}
func readFileFrom(path string, offset int64) ([]byte, error) {
f, err := os.Open(path)
if err != nil {
return nil, err
}
defer f.Close()
if offset > 0 {
if _, err := f.Seek(offset, 0); err != nil {
return nil, err
}
}
return io.ReadAll(f)
}
func readFileTail(path string, maxBytes int64) ([]byte, error) {
if maxBytes <= 0 {
return os.ReadFile(path)
}
info, err := os.Stat(path)
if err != nil {
return nil, err
}
if info.Size() <= maxBytes {
return os.ReadFile(path)
}
f, err := os.Open(path)
if err != nil {
return nil, err
}
defer f.Close()
if _, err := f.Seek(info.Size()-maxBytes, 0); err != nil {
return nil, err
}
b, err := io.ReadAll(f)
if err != nil {
return nil, err
}
for i, c := range b {
if c == '\n' && i+1 < len(b) {
return b[i+1:], nil
}
}
return b, nil
}
func scanExistingVrchatLog(path string, state *vrcLogState) error {
b, err := os.ReadFile(path)
if err != nil {
return err
}
state.presentSet = map[string]struct{}{}
state.location = ""
state.worldID = ""
state.instanceID = ""
state.worldName = ""
state.pendingWorldName = ""
state.initialized = false
text := decodeVRChatLog(b)
var lastWorldAt time.Time
sawWorldChange := false
for _, raw := range strings.Split(text, "\n") {
line := strings.TrimRight(raw, "\r")
if line == "" {
continue
}
if changed, _ := updateWorldState(state, line); changed {
sawWorldChange = true
lastWorldAt = extractLineTime(line)
state.presentSet = map[string]struct{}{}
handleWorldChange(state, state.worldName, lastWorldAt)
}
if m := joinPattern.FindStringSubmatch(line); len(m) == 2 {
name := strings.TrimSpace(m[1])
state.presentSet[name] = struct{}{}
if tracker := GetGuestTracker(); tracker != nil {
tracker.MarkJoin(name, extractLineTime(line))
}
continue
}
if m := leftPattern.FindStringSubmatch(line); len(m) == 2 {
name := strings.TrimSpace(m[1])
delete(state.presentSet, name)
if tracker := GetGuestTracker(); tracker != nil {
tracker.MarkLeave(name, extractLineTime(line))
}
continue
}
}
state.initialized = true
if state.worldName != "" {
if !sawWorldChange {
log.Printf("world changed: %s", state.worldName)
if lastWorldAt.IsZero() {
lastWorldAt = time.Now()
}
handleWorldChange(state, state.worldName, lastWorldAt)
}
if err := appendRuntimeLog("VRC WORLD", state.worldName); err != nil {
log.Printf("append world log failed: %v", err)
}
}
return nil
}
func decodeVRChatLog(b []byte) string {
if len(b) == 0 {
return ""
}
if len(b) >= 2 {
if b[0] == 0xff && b[1] == 0xfe {
u16 := make([]uint16, 0, (len(b)-2)/2)
for i := 2; i+1 < len(b); i += 2 {
u16 = append(u16, uint16(b[i])|uint16(b[i+1])<<8)
}
return strings.TrimPrefix(fixMojibake(utf16ToString(u16)), "\ufeff")
}
if b[0] == 0xfe && b[1] == 0xff {
u16 := make([]uint16, 0, (len(b)-2)/2)
for i := 2; i+1 < len(b); i += 2 {
u16 = append(u16, uint16(b[i+1])|uint16(b[i])<<8)
}
return strings.TrimPrefix(fixMojibake(utf16ToString(u16)), "\ufeff")
}
}
lines := bytes.Split(b, []byte{'\n'})
var out strings.Builder
for i, raw := range lines {
if i > 0 {
out.WriteByte('\n')
}
out.WriteString(decodeVRChatLogLine(raw))
}
return strings.TrimPrefix(out.String(), "\ufeff")
}
func decodeVRChatLogLine(b []byte) string {
line := bytes.TrimRight(b, "\r")
if len(line) == 0 {
return ""
}
return strings.TrimPrefix(string(line), "\ufeff")
}
func DecodeVRChatLog(b []byte) string {
return decodeVRChatLog(b)
}
func fixMojibake(s string) string {
if s == "" {
return ""
}
candidates := []string{s}
if repaired := tryRepairShiftJISMojibake(s); repaired != "" {
candidates = append(candidates, repaired)
}
best := s
bestScore := scoreReadable(best)
for _, cand := range candidates {
if score := scoreReadable(cand); score > bestScore {
best = cand
bestScore = score
}
}
return best
}
func tryRepairShiftJISMojibake(s string) string {
raw := []byte(s)
// Try the common "UTF-8 bytes interpreted as CP932" pattern repair by
// round-tripping through CP932 in the reverse direction.
if repaired := decodeWithCodePage(raw, 932); repaired != "" && repaired != s {
return repaired
}
return ""
}
func utf16ToString(u16 []uint16) string {
for i, r := range u16 {
if r == 0 {
u16 = u16[:i]
break
}
}
return string(utf16.Decode(u16))
}
func scoreReadable(s string) int {
if s == "" {
return -1
}
score := 0
for _, r := range s {
switch {
case r == '<27>':
score -= 8
case r >= 0x3040 && r <= 0x30ff:
score += 3
case r >= 0x4e00 && r <= 0x9fff:
score += 3
case r >= 0x0020 && r <= 0x007e:
score += 1
case r == '\n' || r == '\r' || r == '\t':
score += 1
default:
score -= 1
}
}
return score
}
func updateWorldState(state *vrcLogState, line string) (bool, string) {
worldID := ""
instanceID := ""
worldName := ""
roomTitle := ""
if m := enteringRoomPattern.FindStringSubmatch(line); len(m) == 2 {
roomTitle = strings.TrimSpace(m[1])
state.pendingWorldName = roomTitle
}
if m := worldLocationPattern.FindStringSubmatch(line); len(m) == 3 {
worldID = strings.TrimSpace(m[1])
instanceID = strings.TrimSpace(m[2])
}
if m := worldIdPattern.FindStringSubmatch(line); len(m) == 2 {
worldID = strings.TrimSpace(m[1])
}
if m := instanceIdPattern.FindStringSubmatch(line); len(m) == 2 {
instanceID = strings.TrimSpace(m[1])
}
if m := worldNamePattern.FindStringSubmatch(line); len(m) == 2 {
worldName = strings.TrimSpace(m[1])
}
if m := enteringRoomPattern.FindStringSubmatch(line); len(m) == 2 && worldID == "" {
if worldMatch := worldPattern.FindStringSubmatch(m[1]); len(worldMatch) == 2 {
worldID = worldMatch[1]
}
}
nextLocation := ""
if worldID != "" {
nextLocation = worldID
if instanceID != "" {
nextLocation = worldID + ":" + instanceID
}
}
if nextLocation == "" && roomTitle != "" {
nextLocation = roomTitle
}
if nextLocation != "" && nextLocation != state.location {
state.location = nextLocation
state.worldID = worldID
state.instanceID = instanceID
if worldName != "" {
state.worldName = worldName
} else if shouldUseRoomTitlePreferLatest(roomTitle, state.worldName) {
state.worldName = roomTitle
}
label := state.worldName
if label == "" {
label = state.worldID
}
if label == "" {
label = nextLocation
}
if state.initialized {
log.Printf("world changed: %s", label)
}
state.initialized = true
return true, label
}
if worldName != "" {
state.worldName = worldName
state.pendingWorldName = ""
return false, ""
}
if shouldUseRoomTitlePreferLatest(roomTitle, state.worldName) {
state.worldName = roomTitle
}
return false, ""
}
func shouldUseRoomTitle(roomTitle, currentWorldName string) bool {
if roomTitle == "" {
return false
}
if strings.Contains(roomTitle, "Home Location") {
return false
}
if roomTitle == "Holiday-Cottage" && currentWorldName != "" && currentWorldName != roomTitle {
return false
}
if currentWorldName == "" {
return true
}
if roomTitle == currentWorldName {
return false
}
if len(roomTitle) > len(currentWorldName) {
return true
}
if strings.Contains(roomTitle, "「") || strings.Contains(roomTitle, "」") || strings.Contains(roomTitle, "[") {
return true
}
return false
}
func shouldUseRoomTitlePreferLatest(roomTitle, currentWorldName string) bool {
if roomTitle == "" {
return false
}
if strings.Contains(roomTitle, "Home Location") {
return false
}
if currentWorldName == "" {
return true
}
if roomTitle == currentWorldName {
return false
}
return true
}
func extractLineTime(line string) time.Time {
if len(line) < 19 {
return time.Now()
}
t, err := time.ParseInLocation("2006.01.02 15:04:05", line[:19], time.Local)
if err == nil {
return t
}
return time.Now()
}
func handleWorldChange(state *vrcLogState, worldLabel string, at time.Time) {
if state == nil {
return
}
SetCurrentWorldVisit(worldLabel, at)
if tracker := GetWorldHistoryTracker(); tracker != nil {
tracker.ObserveWorld(worldLabel, state.worldID, state.instanceID, at)
}
if tracker := GetGuestTracker(); tracker != nil {
tracker.ResetCurrentInstance(worldLabel)
}
}