Request: Information about Logging in UnrealScript

[abeclancy]

Hey all, I kind of have a request from anyone in the forum to please provide some information regarding how to properly handle logging in UnrealScript/the XCOM 2 source.

 

For example, I've just been using `log("...",,'MyMod'); to do logging in code, but when doing a release version I've noticed that log statements are not being put in Launch.log. I think that the game by default is just disabling a lot of log statements, but I have to imagine that they can be enabled somehow. The game seems to direct the logging with that third parameter combined with XComEngine.ini [Core.System] Suppress=* options, but I can't seem to figure it out.

 

I figure instead of worrying about it, I could just ask around and get some proper instruction from someone who knows more about what they're doing. Ideally if there's log levels that'd be nice, but not necessary of course. I'd just like to be able to write warnings to a log file during normal execution, so that if there's a problem with the code it's in the log. And I can always create multiple logging groups, like MyModWarn.

[FxsRMcFall]

Hey Abeclancy, when you compile scripts in "final release" configuration the log macro is compiled away. Logging is incredibly time consuming as it involves concatenating strings in many cases. And even worse from script when you factor in marshaling the data around. It can add dozens of ms to the frame time in the worst cases.

 

If you want logging from final release script code you can use `warn. However, this will have the same negative performance impact that `log has if you throw it around too much. So it is recommended that you debug using the uncooked data / script packages and only cook in order to produce an optimized "shipping" package.

 

Since "regular" mods are actually uncooked script packages, they can use `log in an unrestricted way but should be careful with it for the same reasons.

[davidlallen]

I would actually love to see a document which shows the real syntax. Some places use @ separators, some use $ separators, some have a bunch of extra options. Personally, I use a syntax like this:

 

`log ("davea debug foo= " @ foo @ " bar is " @ bar);

 

I don't provide any of the optional arguments, and then when I am hunting in the log files, I search for "davea debug". I have never found that these get disabled in any type of "release version".

 

When you see that your log statements are not appearing in a certain run, sorry, but are you sure your mod is taking effect in those runs? If there are multiple mods which extend different classes, then junk can build up in My Documents/.../XComGame/XComEngine.ini with the result that your mod is unexpectedly disabled. Also, it seems that when steam updates one of the other mods you are using, there is a timestamp checking operation, which may again result in ini files being updated to exclude your mod. I regularly delete all the files in that directory to ensure that none of this happens to me.

 

EDIT: ninja'd with better information.

Edited March 7, 2016 by davidlallen

[abeclancy]

Thanks FxsRMcFall, I was kind of hoping that the release version wouldn't strip out `log(), but as long as `warn() works then at the very least I can still write logs when they are really needed. It's a little weird to figure that out from just looking at the logs though, because even on a final release it looks like there still are some `log()-level statements being used, but maybe those are being logged from somewhere other than the UC scripts, like the cpp engine itself. (Also looks like there's no lambda functions in Unreal unfortunately, so you can't just use lambda logging to reduce the runtime costs of logging.)

 

davidallen, @ concatenates two strings (or values) with a space. $ concatenates two strings (or values) without a space. As far as I know that's the only difference (https://udn.epicgames.com/Three/StringsInUnrealScript.html).

 

Okay, so it sounds like the best practices regarding logging is to use `log() for logging info level information, and `warn() for logging warn/error/fatal, or for information that is important to be logged regardless of log level. And if you are planning on building final-release versions of your packages (especially core mods), there's no need to place `log()s within if statements to reduce their runtime costs, or `warn()s for that matter if you use them sparingly. Finally, you can use the third parameter in the `log() and `warn() statements to create a filter for your logs (eg 'YourModFilter'), and use [Core.System] suppress=YourModFilter to hide all those logs from Launch.log.

 

Simpler than I thought. I was assuming I was doing something wrong, but it's just the compiler optimizing away logs.

 

And for anyone reading this: If you are not making a core mod, your `log() statements won't disappear. They only get optimized away if you are doing a final-release build version, which you have to specifically ask for, and ModBuddy doesn't do it natively itself. If you are making a core-mod, then your `log() statements will get removed by the cooking process.

[traenol]

@FxsMcFall -- thanks for the details on that, good to know.

 

 

And for anyone reading this: If you are not making a core mod, your `log() statements won't disappear. They only get optimized away if you are doing a final-release build version, which you have to specifically ask for, and ModBuddy doesn't do it natively itself. If you are making a core-mod, then your `log() statements will get removed by the cooking process.

I would suggest adding that to the end of your cooking process thread as a note for others.

[abeclancy]

So I've actually been testing this for awhile, and can't seem to get any `warn() statements to appear in the Launch.log when doing final release building/cooking.

 

If I have a few dozen "ScriptTrace();" calls, I can see those in the log file. But any `log() or `warn() calls both seem to be getting removed, regardless of deleting User\Config files, +Unsuppress=MyLogFilter, what-have-you.

 

Any ideas anybody?

[abeclancy]

Found it. From the Unreal documentation page: https://udn.epicgames.com/Three/UnrealScriptPreprocessor.html

 

log / warn

`log(string OutputString, optional bool bRequiredCondition, optional name LogTag);
`warn(string OutputString, optional bool bRequiredCondition);

Wrapper macros for the LogInternal and WarnInternal functions declared in Object.uc. If bRequiredCondition is specified, the message will only be logged if the condition is true.

Both macros are disabled if scripts are compiled with the -final_release switch.

 

So, all log messages from UnrealScript will be unable to make it to the log file in final release builds.

 

Fiddlesticks.

 

From https://wiki.beyondunreal.com/Preprocessor :

 

There is a good reason to use the `log and `warn macros instead of LogInternal() and WarnInternal() functions. If you use the -final_release command line option when you "make", it will turn off all logging because `log and `warn are empty defines when using -final_release. However, the LogInternal() and WarnInternal() function(s) will still be called if you use them directly. Using the macro to write to the log for debug info will not incur a function call overhead in a release build.

More importantly, it also appears that calls to LogInternal (or anything *Internal) generate compiler errors when using -final_release.

 

More Fiddlesticks. There doesn't seem to be a good built-in way to log a message to the log file (in particular when doing core mod releases, since non-core mod packages don't have to be cooked). And when you try the following code:

LogInternal("this is a test log message");

You end up with this compiler error when making final release scripting:

Error, Can't access private function 'LogInternal' in 'Object'

This is because the final release makes these functions private, so they fail. We can theoretically remove this restriction by, say, removing the "privatization" of WarnInternal of Object.uc so we can at least use `warn() like was mentioned earlier (without the macro), which actually is quite doable in a core mod since there will likely only be a single core mod in use at a time. However it is not exactly pretty, as someone doing an XComGame.upk core mod would also have to overwrite Core.upk to allow for logging.

 

Unfortunately this doesn't seem to work. I didn't try too hard, but log messages still did not seem to be writing to the log file for some reason. I'm guessing that might be part of the whole "don't call it directly" thing that UDK and the wiki pages are all recommending against.

 

So, can't `log() or `warn() unless someone comes up with a way to do so from UnrealScript. I'm going to take a look to see if I can't find a native logging function built-in to the game code somewhere, like "native function LogWithFilter(msg,filtername)", but I doubt I'll find something too useful. And there's a ton of code to comb through.

[abeclancy]

Also... is the XCom_HitRolls log filter broken? It's filtered to the "Combat" log file along with "XCom_CombatLog", but doesn't show up. "XCom_CombatLog" messages show up in "Combat.log", but "XCom_HitRolls" don't. Doesn't seem to matter how you change the filters, what you suppress or unsuppress (neither are suppressed or unsuppressed by default), `log("TESTING", true, 'XCom_HitRolls'); doesn't log anything, but `log("TESTING", true, 'XCom_CombatLog'); logs perfectly, to both log files in fact.

 

Maybe it's just the XCom_HitRolls logging that isn't working, or maybe I'm just losing my mind.

 

I mean, it's not particularly important for this one log filter to work properly, because I can always test using an empty filter and it works fine. But it doesn't seem to work as intended which makes me worry that when someone releases a massive mod, the logging might not function as they intend, which might be important for things like basic bug reports or debugging.

[abeclancy]

I did actually manage to find something that might allow me to write log messages to the log files in UnrealScript, regardless of whether the build is a final release build or not.

 

Basically, instead of using `log() or `warn(), the following is used instead. This appears to use a native C++ function to do the actual logging, so it is completely unaffected by the build state of UnrealScript code:

`CHEATMGR.WriteToFilteredLogFile("To Hit: " $ ToHitValue, 'XCom_HitRolls');

I haven't looked at this in too much depth, but it works in my tests so far, the cheat manager is a part of WorldInfo, and it seems to be a valid object everywhere. Unless someone comes up with a better workaround, this is as good as a solution to logging as I can get. (This is also a very early idea that might be a very bad idea in the long run, I'm just trying to find things in the code to use for logging.)

 

However, do note that using this to do logging means that log messages are not disabled in release builds! Logging always has a performance impact, which is why `log() and `warn() are removed from final release builds in the first place!

 

So, use `log() and `warn() during testing of your mod. Use the `CHEATMGR macro to log errors or information that you KNOW that you will want to have in your final release version. But try to keep the use of these to a minimum, both for performance impact purposes as well as log file size purposes!

 

Yay/Nay?

[abeclancy]

Seems like Nay. I don't know if either I'm not setting up filtered logs correctly or what, but attempting to pipe logs through the `CHEATMGR doesn't seem to work. Maybe the native code has its own list of allowed filters or something.

 

So, back to square one, and trying to figure out a way to allow some form of logging in a mod's final release build.