Logger

[collinsmith]

This is a duplicate to replace #294

I've added a customizable Logger into the AMXX core and would appreciate if someone could now take a look, as I believe it is ready for general testing/review. Please let me know any improvements, questions, comments or changes you would like to make.

What does it do:
This patch adds the Logger data structure into the AMXX core. In each logger you can customize a variety of options, such as:

Item	Default	Description
verbosity	Severity_Warn	Only log messages greater or equal to this verbosity will be logged
name	%p_%d	Name of the logger, this example will create one log file per unique day
message	[%5v] [%t] %n::%f - %s	Format of a log message
path		This will create a log file in /cstrike/addons/amxmodx/logs/
stack trace	at %n::%f : %l	Format of a stack trace
date	%Y-%m-%d	Format of the date (standard C format)
time	%H:%M:%S	Format of the time (standard C format)

Severity	Value
Severity_None	0
Severity_Debug	1
Severity_Info	101
Severity_Warn	201
Severity_Error	301

Specifier	Function
%d	date
%f	function
%i	counter
%l	line #
%m	map
%n	script (with .sma)
%p	plugin file (without .amxx)
%s	log message
%t	time
%v	verbosity/severity
%%	% literal

Why does AMXX need this type of addon?
It's simple, this makes debugging and creating effective logging easier for the developer. While the current logging mechanism works great for some cases, it leaves the AMXX logs feeling bloated for large plugins which require a large amount of logging. This this data structure, developers and server admins can choose what messages they want to see. Some might want to develop their modules in debug mode and then disable logging completely for a performance boost. This module was designed to cut out of the native as soon as the message is not within the severity parameters of the server.

Some quick notes:

• I chose to double up on the natives to try and promote speed and lightweightedness of the module, so there wouldn't be any stocks performing argument formatting (vformat), and the log native will cease execution ASAP.
• documentation is still required for the logger natives, particularly the specifiers, however I wanted to nail down the specification and get general review before doing so, general info can be found here
• I already added a test suite to test the majority of the natives
• I've added a CVAR manager plugin that would need to be added to the core plugins, which creates and manages CVARs for logging verbosities (useful for server owners who want to adjust on the fly or disable all together).
• This has also committed my msvs2015 project, which is a conversion of the included msvs2012, however you may wish to remove it.

[Arkshine]

I wanted to try it for some random plugin to get myself idea on how things are working. Just few things at first try:

First thing, plugin doesn't compile (crash). As far I know, #pragma deprecated is only for natives/forwards. Compiler doesn't like you put it above an enum constant. I did not check more than that but I don't think compiler will be again modified.

Second thing is you require "debug " for all kind of severity and throw an error if not set, even regardless the different format. I'm not sure it's a good idea. I think debug should be used only when necessary, and if it requires that activated, you would show as much you can and appending a message telling to enabling debug (similar to the one amxx throws on error without debug). I don't really know what would be the best, but right now it doesn't feel right.

Third thing, adding files to VS projects would be welcomed.

[collinsmith]

@Arkshine Interesting about the deprecation errors. I did not see this behavior when compiling using a build from about early October. That's an easy fix, I just moved it to a comment.

I will need a bit of time to look into the other thing regarding plugins being in debug mode. I remember this being an issue within AMXX, i.e., tracing is only enabled within the core if debug mode is enabled for a plugin. Obviously I would not like to have debug mode enabled for all plugins by default, so I will need to find a way to have it toggled on if the logger is detected in that plugin. Like you said, it really should work automatically.

I will push the additional files to VS projects as soon as I get a chance.

[collinsmith]

Sorry for the delay (wow, over a year!), I was browsing my file system and saw I never completed this.

I made the requested changes, and even though I'd like to look over it a bit more, this should give you somewhere to start if you want to play with it a bit more. Log messages will only note the error (it's really only a warning, so I think I will change this), if debug mode is not enabled and a stack trace is trying to be printed. Otherwise, if some things are needed from the debugger (like script file / function), they are printed as "null"

[Arkshine]

(Don't worry, you are not ignored, health issue + busy busy busy. Thanks for updating your stuff.)

[collinsmith]

I altered the API and incorporated the concept of a by-plugin logger. This means that the API is a bit easier to use in the most common case I was running into, where I was only using one logger per plugin (it's created when first used to minimize overhead). I also added in a native which allows setting this default logger for my project linked below, so multiple plugins can reference the same logger in this manner.

https://github.com/collinsmith/zombies/tree/master/src

@Arkshine I hope you're doing alright, I know you'd get to it when you got a chance :)

[Arkshine]

Everything I'm about to say can be discussed, right.

Your current API:

enum Logger 
{
    All_Loggers = -2,
    This_Logger = -1,
    No_Logger = 0,
    Invalid_Logger = No_Logger
};

enum Severity
{
    Severity_Invalid = -1,
    Severity_None    = 0,
    Severity_Debug   = 1,
    Severity_Lowest  = Severity_Debug,
    Severity_Info    = 101,
    Severity_Warn    = 201,
    Severity_Warning = Severity_Warn,
    Severity_Error   = 301,
    Severity_Highest = Severity_Error
};

forward OnLoggerCreated(
        const plugin,
        const Logger: logger,
        const Severity: verbosity,
        const name[],
        const nameFormat[],
        const msgFormat[],
        const dateFormat[],
        const timeFormat[],
        const pathFormat[],
        const traceFormat[]);

native Logger: LoggerCreate(
        const Severity: verbosity = Severity_Warn,
        const nameFormat[]  = "%p_%d",
        const msgFormat[]   = "[%5v] [%t] %n::%f - %s",
        const dateFormat[]  = "%Y-%m-%d",
        const timeFormat[]  = "%H:%M:%S",
        const pathFormat[]  = "",
        const traceFormat[] = "    at %n::%f : %l");
native bool: LoggerDestroy(&Logger: logger);

native Logger: LoggerGetThis();
native Logger: LoggerSetThis(const Logger: logger);

native Severity: LoggerGetVerbosity(const Logger: logger = This_Logger);
native Severity: LoggerSetVerbosity(const Logger: logger = This_Logger, const Severity: verbosity);

native LoggerGetNameFormat(const Logger: logger = This_Logger, format[], const len);
native LoggerSetNameFormat(const Logger: logger = This_Logger, const format[]);
native LoggerGetMessageFormat(const Logger: logger = This_Logger, format[], const len);
native LoggerSetMessageFormat(const Logger: logger = This_Logger, const format[]);
native LoggerGetDateFormat(const Logger: logger = This_Logger, format[], const len);
native LoggerSetDateFormat(const Logger: logger = This_Logger, const format[]);
native LoggerGetTimeFormat(const Logger: logger = This_Logger, format[], const len);
native LoggerSetTimeFormat(const Logger: logger = This_Logger, const format[]);
native LoggerGetPathFormat(const Logger: logger = This_Logger, format[], const len);
native LoggerSetPathFormat(const Logger: logger = This_Logger, const format[]);
native LoggerGetTraceFormat(const Logger: logger = This_Logger, format[], const len);
native LoggerSetTraceFormat(const Logger: logger = This_Logger, const format[]);

native LoggerLog(const Severity: severity = Severity_Info, const format[], any: ...);

native LoggerLogError(const format[], any: ...);
native LoggerLogWarn(const format[], any: ...);
native LoggerLogWarning(const format[], any: ...);
native LoggerLogInfo(const format[], any: ...);
native LoggerLogDebug(const format[], any: ...);

native LoggerLog2(const Logger: logger = This_Logger, const Severity: severity = Severity_Info, const format[], any: ...);

native LoggerLogError2(const Logger: logger = This_Logger, const format[], any: ...);
native LoggerLogWarn2(const Logger: logger = This_Logger, const format[], any: ...);
native LoggerLogWarning2(const Logger: logger = This_Logger, const format[], any: ...);
native LoggerLogInfo2(const Logger: logger = This_Logger, const format[], any: ...);
native LoggerLogDebug2(const Logger: logger = This_Logger, const format[], any: ...);

The API is kind of cumbersome. You should keep it simple and let coder extend them if necessary. In case they need to use a handle across plugins, they can use a fake native (like you used in your plugin) or xvar for example.

Having something like that would be enough:

enum Logger
{
    Invalid_Logger = 0,
};

enum LoggerFormat
{
    LogFormat_Name,
    LogFormat_Message,
    LogFormat_Date,
    LogFormat_Time,
    LogFormat_Path,
    LogFormat_Trace
};

enum LoggerSeverity
{
    LogSeverity_None  = 0,
    LogSeverity_Debug = 1,
    LogSeverity_Info  = 101,
    LogSeverity_Warn  = 201,
    LogSeverity_Error = 301,
};

native Logger:LoggerCreate([...]);
native LoggerDestroy(&Logger:handle);

native LoggerLog(const Logger:handle, const LoggerSeverity:severity, const format[], any:...);

native LoggerLogDebug(const Logger:handle, const format[], any:...);
native LoggerLogInfo(const Logger:handle, const format[], any:...);
native LoggerLogWarn(const Logger:handle, const format[], any:...);
native LoggerLogError(const Logger:handle, const format[], any:...);

native LoggerSeverity:LoggerGetVerbosity(const Logger:handle);
native LoggerSeverity:LoggerSetVerbosity(const Logger:handle, const LoggerSeverity:verbosity);
native LoggerSeverity:LoggerSetDefaultVerbosity(const LoggerSeverity:verbosity);

native LoggerFormat:LoggerGetFormat(const Logger:handle, LoggerFormat:type, format[], const maxLength);
native LoggerFormat:LoggerSetFormat(const Logger:handle, LoggerFormat:type, const format[]);
native LoggerFormat:LoggerSetDefaultFormat(LoggerFormat:type, const format[]);

You get rid of "ThisLogger" and "AllLogger" handle which is confusing and doesn't apply to all natives.
You get rid of duplicated natives. If you are using an handle you should only use that.
You separate per-handle and all handlers configuration.
You factorize format configuration because they have all the same header.
This is more straight & sane I believe.

That's said, this doesn't feel right.
Having a create/free handle system when you are going to use always them globally is a bit silly.
And I don't see any usage having several loggers per plugin.

Now we removed explicit handles, we need a way to extend a plugin's log config to another plugin.
Since we are working per plugin, we should probably have a native which passes a plugin's id that you wish to copy its config from.
Similar to handle, you could pass an id either with a fake-native or xvar.

At the end I would do, maybe something like:

enum LoggerFormat
{
    LogName,
    LogMessage,
    LogDate,
    LogTime,
    LogPath,
    LogTrace
};

enum LoggerVerbosity
{
    UnsetLevel = 0,
    DebugLevel = 1,
    InfoLevel  = 101,
    WarnLevel  = 201,
    ErrorLevel = 301,
};

native Logger(const LoggerVerbosity:verbosity, const format[], any:...);

native LoadLogger(const pluginId);

native LoggerVerbosity:GetLoggerVerbosity();
native LoggerVerbosity:SetLoggerVerbosity(const LoggerVerbosity:verbosity);

native LoggerFormat:GetLoggerFormat(LoggerFormat:type, format[], const maxLength);
native LoggerFormat:SetLoggerFormat(LoggerFormat:type, const format[]);

As you can see it's much easier and cleaner.

• I removed the create/free handle natives.
• I removed *Default* natives because they are not really useful in a normal plugin. Changing the default configuration should be handled by an admin using the cvar provided by the logger plugin, and you can loop over all the plugin's id there.
• I tried to rename constants name and their length to be more comfortable and less redundant.
• Since verbosity constant names have been reduced, I think having multiple LoggerLog* is now redundant.
• I added LoadLogger native to essentially copy an existing plugin logger configuration.
• Note sure about Logger alone and LoadLogger if enough descriptive.

As a side-note, about the format specifiers, is it really needed to have precision/width here?
I would go with named specifier, like {plugin}. Can use % or whatever.

Single plugin:

public plugin_init()
{
    register_plugin("Plugin", "1.0", "Github");
}

foo()
{
    Logger(WarnLevel, "This is warning");
}

Multiple plugin:

#include <amxmodx>

new MainPluginId;

public plugin_init()
{
    MainPluginId = register_plugin("Plugin A", "1.0", "Github");

    // Changing default configuration
    SetLoggerVerbosity(DebugLevel);
    SetLoggerFormat(LogName   , "{plugin} | {datestamp}");
    SetLoggerFormat(LogMessage, "[{verbosity}] [{timestamp}] {script}::{function} - {message}");
    SetLoggerFormat(LogTrace  , "    at {script}::{function} : {line}");
}

public plugin_natives()
{
    register_native("GetBasePluginId", "@Native_GetBasePluginId");
}

@Native_GetBasePluginId()
{
    return MainPluginId;
}

foo()
{
    Logger(InfoLevel, "Hello world!");
    Logger(ErrorLevel, "This is an error.");
}

#include <amxmodx>

native GetBasePluginId();

public plugin_init()
{
    register_plugin("Plugin B", "1.0", "Github");

    LoadLogger(GetBasePluginId());
}

foo()
{
    Logger(InfoLevel, "Hello world!");
}

Overall, I think it's not that bad.

Any thoughts?

[collinsmith]

I agree with most of your suggestions, however I would prefer to keep the format specifiers as-is only because they are consistent with other loggers (log4j) and I personally like setting the width for things like log message verbosity. I think with adequate documentation the current implementation would be sufficient. Let me know what you think.

Another thing that might also be of use would be adding support for defining logger aliases, i.e., naming loggers. This could probably be done with some plugin in a future version, but would make the API a bit less cumbersome when trying to access loggers from other plugins (to avoid fake natives/xvars).

[collinsmith]

Would you be opposed to changing the log function from Logger to just Log (or even better, log)? It doesn't appear to be in use and logarithms use floatlog.

[Arkshine]

About the format specifier, it's not that a big deal for sure, as long it's properly documented as you said. You could even support both, having the simple placeholder way for basic usage, or using specifier for advanced formatting; not sure if it would make sense though.

About the name, it would be definitively better named Log or log. I don't have preference CameCasel vs underscore here. Though, I'm a bit worried such generic name is used often in plugins already?

[collinsmith]

Yeah, the name is not a big deal, I was just thinking in terms of ease-of-use. Personally I'll use a preprocessor macro to define log, I might even define macros for info/debug/error messages to have like
i("message"); for Logger(InfoLevel, "message");
d("message"); for Logger(DebugLevel, "message");
e("message"); for Logger(ErrorLevel, "message");

Do you have any suggestions for managing the global verbosity cvar? I can add (undocumented/hidden?) natives to get/set it. Or would you prefer a different implementation?

[collinsmith]

This is the latest API I'm working with.

I would like to try and keep the 4 shortcut methods for logging at the common levels (their names can also be shortened by removing Log). In my own projects I can easily define macros for these to shorten them further, and it should be faster to do it this way than to make stocks. Your thoughts?

/*******************************************************************************
 * FORWARDS
 ******************************************************************************/

// This is used to load logger verbosities from cvars. logger is now deprecated and will be removed.
// This doesn't need to be exposed as public API unless you think it should be.
forward OnLoggerCreated(
        const plugin,
        const Logger: logger,
        const LoggerVerbosity: verbosity,
        const name[],
        const nameFormat[],
        const msgFormat[],
        const dateFormat[],
        const timeFormat[],
        const pathFormat[],
        const traceFormat[]);

/*******************************************************************************
 * NATIVES
 ******************************************************************************/

native Logger(const LoggerVerbosity: verbosity, const format[], any: ...);

native LoggerLogDebug(const format[], any: ...);
native LoggerLogInfo(const format[], any: ...);
native LoggerLogWarn(const format[], any: ...);
native LoggerLogError(const format[], any: ...);

native LoadLogger(const pluginId);

native LoggerVerbosity: GetLoggerVerbosity();
native LoggerVerbosity: SetLoggerVerbosity(const LoggerVerbosity: verbosity);

// Used to manage global verbosity for all loggers. I use this to disable extremely verbose debug messages from all logs.
// This doesn't need to be exposed as public API unless you think it should be.
native LoggerVerbosity: SetGlobalLoggerVerbosity(const LoggerVerbosity: verbosity);
native LoggerVerbosity: GetGlobalLoggerVerbosity();

native GetLoggerFormat(const LoggerFormat: type, format[], const maxLength);
native SetLoggerFormat(const LoggerFormat: type, const format[]);

I have this in an include file that I use in my own projects

#define logd LoggerLogDebug
#define logi LoggerLogInfo
#define logw LoggerLogWarn
#define loge LoggerLogError

---

I also noticed an issue where my stack traces aren't outputting traces from any native callbacks, i.e., the traces are only for the plugin calling log and don't go back up the call stack properly through other plugins. This also seems to happen in a couple different areas. I didn't realize that AMXX seems to treat these as separate traces (LogError is called each time and propagates a "new" error each time which outputs a new trace).

This complicates things, as I'm not setting any error code when printing a stack trace, so I'm kind of at a loss on how to work around this issue. I think I would need to integrate some new state into these callback methods or add a new special case AMX_ERR_ code, but I don't really understand the ramifications that might have on the rest of the platform.

Here is one example of where this is happening.

[collinsmith]

I updated the API like we discussed and merged it with master. I've been using it the past week or so, and I really like it. Let me know what you think.

[IgnacioFDM]

I haven't really followed this PR, but based on personal use cases, I think it'd be nice to have some extra severity levels.

I would probably use "Error" in situations where the current call is halted (think your typical out of bounds error) but plugin continues running, "Fatal error" when plugin enters failed state and stops running (set_fail_state situations) but HLDS still runs, and "Catastrophic failure" for situations where HLDS must be killed to recover.

Also, did you test if stuff gets logged if you log something just before a crash?

[IgnacioFDM]

Inconsistent casing (upper case O here, lower case in other places)

[collinsmith]

@IgnacioFDM It's made my life a hell of a lot easier. I haven't specifically tested if stuff gets logged just before a crash, but I was able to diagnose the cause of a crash by logging messages, and it was a nasty crash too with no errors. I don't remember specifically what the problem was, only that it had to do with set_task being called.