Logging library: How to exfiltrate game data?

[Luashine]

I'm primarily concerned about Lua. I want more input or suggestions, because Preload is too slow for the amount of logs I wanted to generate.

1. DisplayTextToPlayer: there're only 16 lines on screen and it is shared with map messages. In singleplayer the lines are saved to journal (F12) but not in multiplayer - I'm debugging a desync issue. If they're saved to journal/printed at a high rate, they consume a lot of memory.
2. BlzDisplayChatMessage: ~25 lines on screen, but still not enough (maybe more lines can be made visible if you move the UI frame). Not saved anywhere at all, even in multiplayer
3. Preload files: the go-to method but pretty slow. Saving 1.5MB freezes the game for 1-3 seconds. Lines are limited in length. Post-processing needed.
4. Game save files: iirc multiplayer saves were disabled for Lua maps. Potentially high memory overhead
5. Somehow saving data to replay files. Replay files should only contain player input, so idk if it's possible. The file format must be parsed and is a separate nuissance.
6. Process memory dumps: currently they're the only way to extract uncaught Lua error messages (especially when the map fails to load in lobby and script execution seems to stop). Something like storing a huge string in memory / lines in a table. Downsides: the simple approach with cat -v | grep or strings | grep is very slow, it takes minutes to finish a 1GB memory dump. Potential upsides: automatable
7. Hooking into process memory. What for exactly? Downside: hard, anti-cheat?
8. Modifying game to fully enable Lua os and io libraries. Downside: hard, anti-cheat?
9. clown method: paint colored squares on the screen, recognize the color and turn it into binary output data. You'd need to do screen recording and image recognition. Upsides: a streamable format that doesn't fill the game's memory. Downsides: clown
10. Capturing network traffic that we cause through sync. iirc network traffic is now encrypted, impossible.

I have a problem with a map that desyncs and really struggle to find the piece of code that's causing it. I wanted to print everything on the screen but there's one frame where so much stuff happens that 20-30 lines aren't enough to show it all. Then I tried to just write every line to Preload. Each logged line did overwrite the entire preload file and it was so slow... I didn't make it past 1500 lines in 20 minutes and the game window remained frozen.
Why did I overwrite the file with each new line? I think when the game desyncs, it stops the script execution completely so I can't have a line buffer with delayed flushing (i.e. keep lines in memory and only write the Preload files every 10 lines or so). I suppose it could be optimized with various tricks, but ultimately due to this limitation preload files will remain at O(n^2).

Hopefully anyone else has better ideas. Though I think the best there's are: optimized preload / memory dump extraction.

Spoiler: Preload performance

Invalid UNC:
s=os.clock(); for i = 1, 10000 do Preload([[\\.\Line\]].. i ..[[.txt]]) end; e=os.clock()
-> 50ms

Invalid relative path:
s=os.clock(); for i = 1, 10000 do Preload([[somfilee-]].. i ..[[.txt]]) end; e=os.clock()
-> 140ms
--------
PreloadGenEnd:
-> 4.84s for 4.7MiB
So preload file saving has ~1 MiB/s speed
--------
1.2GB file (not cached): 50s - time strings -5 Warcraft\ III.dmp | grep war3map.lua 
-> 24 MB/s

 

[Luashine]

I started working on this problem today and decided to go with Method 6: "Process memory dumps". I chose it because, unlike the Preload file method, I have full control over the process and don't have to work around Preloads' speed problems. The downside is that you must start the process dump manually - I mean I will automate it, but you still have to run a command from console by hand. Things continue to happen while the game's process is running, but nothing bad should happen to logs that already reside in memory.
The procedure looks like this:

1. The logger library is installed in your map and your code calls logger:log(my_text)
2. The logger saves each text as a separate line in a table.
   1. Each line is prefixed with a unique marker so it can be found in a memory dump: "###L1234567:USER_SUPPLIED_STRING\0"
3. When you want to extract the logs, you run an extractor program, wait.
   1. The script dumps memory contents of Warcraft3.exe to a file on disk and extracts log lines from it
4. Clean log file is saved to disk, you can open it in notepad.

In the post above I said that I've used this method already with grep to extract random stuff and script error messages from memory. It was very slow. My first attempt at this:

Log entries: 15001
Finished processing dump file
Size: 1028.7 MiB
Time: 18.0 seconds
Speed: 57.19 MiB/s

There were actually 4000 unique log lines, it shows 15K due to an attempted GC optimization where I reduce amount of objects in a table. If there're too many lines (objects) they're merged into one big string. I should help against this: link1, link2. Either way, the resulting log file is nicely sorted from Line 1 to Line 4000.
This method is ~50x faster than Preload and 2-3x faster than the "unix-way" grep of the dump file. It's literally the first attempt, without optimizations. And it's plain Lua too, it's supposed to be slow for text processing

---

This is WIP and I'm creating it to debug a desync on my map. If you want to use it too, let me know here. Then I will finish the logging library, the dump extractor and publish it.

 

[Ricola3D]

I started working on this problem today and decided to go with Method 6: "Process memory dumps". I chose it because, unlike the Preload file method, I have full control over the process and don't have to work around Preloads' speed problems. The downside is that you must start the process dump manually - I mean I will automate it, but you still have to run a command from console by hand. Things continue to happen while the game's process is running, but nothing bad should happen to logs that already reside in memory.
The procedure looks like this:

1. The logger library is installed in your map and your code calls logger:log(my_text)
2. The logger saves each text as a separate line in a table.
   1. Each line is prefixed with a unique marker so it can be found in a memory dump: "###L1234567:USER_SUPPLIED_STRING\0"
3. When you want to extract the logs, you run an extractor program, wait.
   1. The script dumps memory contents of Warcraft3.exe to a file on disk and extracts log lines from it
4. Clean log file is saved to disk, you can open it in notepad.

In the post above I said that I've used this method already with grep to extract random stuff and script error messages from memory. It was very slow. My first attempt at this:

There were actually 4000 unique log lines, it shows 15K due to an attempted GC optimization where I reduce amount of objects in a table. If there're too many lines (objects) they're merged into one big string. I should help against this: link1, link2. Either way, the resulting log file is nicely sorted from Line 1 to Line 4000.
This method is ~50x faster than Preload and 2-3x faster than the "unix-way" grep of the dump file. It's literally the first attempt, without optimizations. And it's plain Lua too, it's supposed to be slow for text processing

---

This is WIP and I'm creating it to debug a desync on my map. If you want to use it too, let me know here. Then I will finish the logging library, the dump extractor and publish it.

Hello,

Did it help you find the desync cause? What was it?
Also, is your log system LUA or vJASS ? I also have desync issues to debug, and PreLoad is slow (even if I implemented rotating files since file size was the reason for slowness).

 

[Luashine]

Hi @Ricola3D I remember your desyncing posts. Yes Preload is unusably slow there's a small spoiler at the end. The logging system is in Lua, but according to my Jass Strings test, a lightly loaded logger would be possible in Jass too. In it's current state, the Lua logger creates too much GC pressure and leaks memory.
I'm not sure if it helped in my case, my desync happened at game start, I just ended up removing code from the map and found that it still desynced when a part of transpiled Damage Engine was active.

Ultimately I found that a 0.01s (or 0.001s) timer when started at map init or early on (Lua only) WILL cause a 25% chance desync of host vs all other players (tested in LAN). It behaves differently on online bnet, some players stay in game. That's where I am at. The fix to the timer issue was to delay their iniialization by a few seconds.

Remind me please, did your desyncs happen in the middle of the game?
I still wouldn't know how to exactly pinpoint the issue with logs. Log too many things and it will leak memory. I hope my current code there can be improved but by how much? Log too little and its useless. You'll need logs from the desynced player (best if you can replicate in LAN) and to do that you need to dump the memory and analyze it on the spot.

 

[Ricola3D]

Hi @Ricola3D I remember your desyncing posts. Yes Preload is unusably slow there's a small spoiler at the end. The logging system is in Lua, but according to my Jass Strings test, a lightly loaded logger would be possible in Jass too. In it's current state, the Lua logger creates too much GC pressure and leaks memory.
I'm not sure if it helped in my case, my desync happened at game start, I just ended up removing code from the map and found that it still desynced when a part of transpiled Damage Engine was active.

Ultimately I found that a 0.01s (or 0.001s) timer when started at map init or early on (Lua only) WILL cause a 25% chance desync of host vs all other players (tested in LAN). It behaves differently on online bnet, some players stay in game. That's where I am at. The fix to the timer issue was to delay their iniialization by a few seconds.

Remind me please, did your desyncs happen in the middle of the game?
I still wouldn't know how to exactly pinpoint the issue with logs. Log too many things and it will leak memory. I hope my current code there can be improved but by how much? Log too little and its useless. You'll need logs from the desynced player (best if you can replicate in LAN) and to do that you need to dump the memory and analyze it on the spot.

Nice, I added this desync cause to my list.

So for now I'll continue with my rotating file PreLoad logger. I actually run it only during replays to avoid lags for players.

I parsed the war3map.j file to log all triggers execution but it doesn't really help me. It feels like Warcraft III desyncs if a threshold of desynced variables happen and it's not linked to the last executed trigger. And since causes could also be models, it's hard to figure out what to analyze...