RFC: Add new log macros to replace AZTracePrintf

lmbr-pip commented 1 year ago

Summary:

Add new AZ_Info and AZ_Trace log macros to enable separation of log levels for trace level logging; these macros will replace the use of AZ_TracePrintf, which will be deprecated.

What is the relevance of this feature?

O3DE lacks separation of info level log statements from debug trace.

O3DE has the notion of the following log levels, provided by ILogger - the AZ interface for logging, Debug/Trace debug log macros and ILog legacy log reporting from CrySystem code, for reporting assert, errors, warnings, and informational messages:

Level	Debug/Trace	ILogger	ILog
Trace	-	AZLOG_TRACE	-
Debug	-	AZLOG_DEBUG	-
Info	AZ_TracePrintf (*)	AZLOG_INFO	Log?
Notice	-	AZLOG_NOTICE	LogAlways
Warning	AZ_Warn, AZ_WarnOnce	AZLOG_WARN	LogWarning
Error	AZ_Error, AZ_ErrorOnce	AZLOG_ERROR	LogError
Fatal	AZ_Assert(**)	AZLOG_FATAL	-

AZ_Assert is a special case which halts execution and is compiled out in release.

For reference, looked at other common log platforms or approaches:

Level	Description	Python	Java (log4j)	glog	Unreal
trace	Designates finer-grained informational events than the DEBUG.	-	TRACE	-	VeryVerbose
debug	Designates fine-grained informational events that are most useful to debug an application.	debug	DEBUG	-	Verbose
info	Designates informational messages that highlight the progress of the application at coarse-grained level.	info	INFO	INFO	Display
warning	Designates potentially harmful situations.	warning	WARN	WARNING	Warning
error	Designates error events that might still allow the application to continue running.	error	ERROR	ERROR	Error
critical	Designates a server error that may lead application to abort or to to continue running properly.	critical	-	-	-
fatal	Designates very severe error events that will presumably lead the application to abort.	-	Fatal	FATAL	Fatal

A lot of existing O3DE code uses the AZ_TracePrintf which mixes informative messages, with often fine-grained informational events that are most useful to debug an application. This RFC proposes splitting that macro up to have a clean separation for Debug/Trace users.

Feature design description:

Add a new Trace level to LogLevel
- Note: RFC does not propose in having debug macro but that could be added later if of value.
Mark AZ_TracePrintf as deprecated in code.
Add new AZ_Trace macro to log at Trace level.
Make new AZ_Info macro that logs at Info level.
Set default log level for O3DE Applications to be Info in both systems.
Inform code owners of change and encourage migration to new macros from AZ_TracePrintf.
After some period of time, replace all usage of AZ_TracePrintf with AZ_Trace.

Technical design description:

As RFC is proposing two new AZ_Info macros, all the technical description has been added that's relevant.

Note: There is a proposal to add UX for log level control in the Editor, See https://github.com/o3de/sig-content/blob/main/rfcs/rfc-69-logging-event-viewer.md

What are the advantages of the feature?

Separate info level logging from trace/debug logging to separate log statements intent cleanly for systems that rely on Debug/Trace macros.
Users can use existing settings to tune log levels to their needs.
Avoids breaking existing code.
Code builders can easily separate messages which are informative about the state of their code/application and messages that provide extra details that may be useful for debugging

What are the disadvantages of the feature?

Code builders may see some of their log statements disappear and will need to take action to restore any true info level statements.
Does not unify Debug/Trace, ILogger and ILog, still confusing as what should be used
Does not address other log methods, which include GetErrorReport(), QMessageBox::critical, CLogFile

How will this be implemented or integrated into the O3DE environment?

Code will be merged to https://github.com/o3de/o3de/blob/development/Code/Framework/AzCore/AzCore/Debug/Trace.h#L33
- First PR to add AZ_Info level logger and announce this feature
Circulate change and making impactful change announcement
Second PR will replace AZ_TracePrintf with AZ_Trace usage.

Are there any alternatives to this feature?

Could unify Debug/Trace and ILogger macros, so O3DE has a consistent logging/filtering experience.
Provide a new unified logger

However, this RFC could be a stepping stone on those paths as it provides an immediate solution. It does not block a more extensive logger redesign.

How will users learn this feature?

Updated docs to cover log levels, what they mean. UX/Docs team would own setting best practices, which I believe is planned.
Posts to #sig-all
Impactful change notifications

Are there any open questions?

Time period to encourage migration to new macros is TBD. Look to SIG/core for guidance here.

lmbr-pip commented 1 year ago

Should we also remove the concept of window from AZ_TracePrintf/AZ_Trace?

lemonade-dm commented 1 year ago

Should we also remove the concept of window from AZ_TracePrintf/AZ_Trace?

Well to be consistent with AZ_Warning and AZ_Error would would still need the "window" parameter. That being said I think the Window parameter is unnecessary to the trace system as the caller could specify any prefix information as part of the trace message itself, it inhibits output of trace messages without an intermediate buffer which results in lower trace performance.

Examining the Feature design description section, I do have one question about the deprecation phase of AZ_TracePrintf. Will it output at the new "info" log level while deprecated or it will use the "trace" log level.

Having AZ_TracePrintf log at "trace" log level encourages authors to update their uses to use the appropriate AZ_Trace or AZ_Info level as they would need to make a manual local change to lower the log level to trace.

The reason of the proposal looks good to me. I think time period wise, if we have the AZ_TracePrintf remain at the "trace" log level, while making the default "info", then I say we can wait for two releases after the implementation of this feature to remove usages of AZ_TracePrintf while we can immediately encourage users to use the AZ_Trace/AZ_Info macro as soon as the feature is in. One alternative of removing the AZ_TracePrintf macro define at the end of the deprecation phase, is have it be no-op, so that existing code will still compile, but will no longer receive trace or info messages until they update their macros.

lsemp3d commented 1 year ago

On issue I have with the window parameter is that it prevents a useful feature of Visual Studio that if you output a log with the format __FILE__(__LINE__): <description> you can double click on that log entry and VS will take you to that file + line. I know it seems simple, but the amount of time it saves is considerable. That said, I think this only applies to AZ_Assert, however, AZ_Debug could leverage it as well as it's a developer tool that could help navigate quickly through logged messages.

lmbr-pip commented 1 year ago

@lumberyard-employee-dm

Plan is to:

[ ] Provide new macros. See https://github.com/o3de/o3de/pull/13851
[ ] Mark AZ_TracePrintf as deprecated and begin to encourage shift to new macros
[ ] Wait "some time" and then drop AZ_TracePrintf level down to trace.
[ ] Convert existing AZ_TracePrintf -> AZ_Trace usage.
[ ] Null OP AZ_TracePrintf
[ ] Remove AZ_TracePrint and AZ_TracePrintfOnce

@lsemp3d

For now, removing Window is non-trivial and beyond time commitment I can make for this change. Would love to see after this change, a proposal for a unified, up-to-date, logging implementation for O3DE.

lemonade-dm commented 1 year ago

@lumberyard-employee-dm

Plan is to:

* [ ]  Provide new macros. See [Add new AZ_Trace and AZ_Info macros o3de#13851](https://github.com/o3de/o3de/pull/13851)

* [ ]  Mark `AZ_TracePrintf` as deprecated and begin to encourage shift to new macros

* [ ]  Wait "some time" and then drop `AZ_TracePrintf` level down to trace.

* [ ]  Convert existing `AZ_TracePrintf` -> `AZ_Trace` usage.

* [ ]  Null OP `AZ_TracePrintf`

* [ ]  Remove `AZ_TracePrint` and `AZ_TracePrintfOnce`

@lsemp3d

* For now, removing Window is non-trivial and beyond time commitment I can make for this change. Would love to see after this change, a proposal for a unified, up-to-date, logging implementation for O3DE.

The plan looks good to me. I think there is one minor piece of information missing and that is in bullet 2, the AZ_TracePrintf will be initially set to be at the info log level.

lsemp3d commented 1 year ago

It would only be necessary to remove the (System) one that is emitted by errors and asserts by default, not the entire concept of Window in order to enable the functionality in Visual Studio. This much is fairly straightforward.

lemonade-dm commented 1 year ago

This RFC has been signed off by @o3de/sig-core and the change is free to go into development.

lmbr-pip commented 1 year ago

Action Plan

[x] Add macros - https://github.com/o3de/o3de/pull/13851
[x] Update docs - https://github.com/o3de/o3de.org/pull/2283
[x] Send out notifications of new macros
[x] Mark AZ_TracePrintf for deprecation: https://github.com/o3de/o3de/issues/14838
[ ] Create timelime for code to migrate to AZ_Trace or AZ_Info voluntarily.
[ ] Drop remaining usages of AZ_TracePrintf to trace level
[ ] Move all instances of AZ_TracePrintf to AZ_Trace (1 month later)
[ ] Remove AZ_TracePrintf from code under breaking change condition and close out deprecation notice

lmbr-pip commented 1 year ago

Migrate some PerformanceCollector AZ_TracePrintf to AZ_Trace: https://github.com/o3de/o3de/pull/15433

o3de / sig-core