Remove printf calls from jerry core

[LaszloLango]

Related issue: #964

JerryScript-DCO-1.0-Signed-off-by: László Langó llango.u-szeged@partner.samsung.com

[akosthekiss]

I feel that jerry_port_console is overused. As its doc says, "This function is only called with strings coming from the executed ECMAScript wanting to print something as the result of its normal operation." Thus, I think only ecma_builtin_global_object_print should call jerry_port_console. Every other instance of printf should be rewritten as jerry_port_log, probably with debug or trace level (except for the calls in jrt-fatals.c, where it should be error level).

(About main-unix.c, I'm still undecided. Both _console and _log can fit, but even printf can work there, as that's not jerry-core anymore!)

[LaszloLango]

@akosthekiss, I had similar feelings, but in the parser that was the idea to be able to print bytecode bumps in release mode too. I think printf and jerry_port_console should be the same. They are both printing to the standard output. This is why I changed every printf to a _console call. If I change it to _log with a log level, then I might change the original behavior.
@akosthekiss, what parts should be used with _log?
@zherczeg, what do you think of this change? May I change the log levels of the parser dumps?

[akosthekiss]

@LaszloLango If I'm not mistaken, we do have jerry_port_log in all builds, debug and release alike. How would calling jerry_port_log prevent bytecode dumping? (Other than setting the log level too low, of course.)
IMHO, the only valid call site for jerry_port_console is ecma_builtin_global_object_print.

[LaszloLango]

@akosthekiss, yes we have. I'm trying to explain my worries. Currently we have a "--show-opcodes" option in our default linux port. This prints the opcodes. If we change the level of opcode dump to debug or trace, then we have to set the log level when "--show-opcodes" option was passed to the engine. But if we force to debug level, not just the opcodes will be printed, but everything on debug or trace level. In the best scenario this means there will be some "trash" after the opcode dump in the output. In the worst the bytecode dump will fall apart.

[zherczeg]

I have no issues with console log. Mem stats also go to console. These are debug stuff anyway.

[akosthekiss]

@LaszloLango, we have a little bit of mess here, and this PR is a good opportunity to clean it up, IMHO.

If I'm not mistaken, what we have now is that

• some parts (functionalities) of the code can be enabled/disabled with macros, partially or completely independently from the debug/release build mode,
• but the execution of those conditional parts also depends on runtime flags of the engine,
• which are controlled by command line options, at least in the default linux app.

The now relevant functionalities / their macro guards / engine flags / command line options are:

• memory statistics / JMEM_STATS / JERRY_INIT_MEM_STATS and JERRY_INIT_MEM_STATS_SEPARATE / --mem-stats and --mem-stats-separate
• JS bytecode dumps / PARSER_DUMP_BYTE_CODE / JERRY_INIT_SHOW_OPCODES / --show-opcodes
• RegExp dumps / JERRY_ENABLE_LOG / JERRY_INIT_ENABLE_LOG (but not used in the engine) / --log-level [0-3]

This points at the problem. Actually, the log "things" (macro guard, engine flag, command line option) are only used by the RegExp engine to control its dumping behaviour. And also the JERRY_D[D]LOG macros (which expand to jerry_port_log) are only used by the regexp dumps. However, I'm quite sure that it's not what we have as a mental model about those macros/flags/etc. At least that's not how I was thinking about them. And even the jerry_port_log function was sketched along that mental model, its doc is quite clear about it "This function is only called with messages coming from the jerry engine as the result of some abnormal operation or describing its internal operations (e.g., data structure dumps or tracing info)." That is, whatever wants to print diagnostics, should use jerry_port_log.

I think, what we need is

• add something like a REGEXP_DUMP_BYTE_CODE macro guard along with a JERRY_INIT_SHOW_REGEXP_OPCODES engine flag and a --show-regexp-opcodes command line option to control regexp dumping behaviour (free to fine-tune names),
• make mem stats and JS parser dumps use jerry_port_log (or perhaps even JERRY_D[D]LOG),
• drop JERRY_ENABLE_LOG macro guard and JERRY_INIT_ENABLE_LOG engine flag, as I cannot see their point anymore,
• but keep --log-level command line option (and perhaps add some logic that if any of --mem-stats, --mem-stats-separate, --show-opcodes, or --show-regexp-opcodes is specified then it implies at least debug log level)

Final thoughts: getting a mixed output is already possible with the current setup, e.g., if we build with -DJMEM_STATS -DPARSER_DUMP_BYTE_CODE -DJERRY_ENABLE_LOG and run with --mem-stats --show-opcodes --log-level 3. We will not only get JS opcodes in the output but "trash" as well.

(This became a long line of thought and comment. Hopefully not completely "unfollowable".)

[zherczeg]

"getting a mixed output is already possible with the current setup" - this is my worry. If I want only a byte code dump, I cannot do it. Perhaps we could add log levels to all specific debug information. But personally I like the current approach as well, if I enable byte code dump, I get it on the console. Without extra diagnostic info.

[zherczeg]

An idea: we could introduce a logging level, which cannot be disabled. These explicitly enabled features could use this level to produce their output.

[zherczeg]

I think most jerry_port_console functions should be changed to jerry_port_log with debug level.

[zherczeg]

After some thinking, I realized that jerry should decide what to log instead of the port. Hence the logging level is just a hint for the port, rather than making decisions based on it. Jerry should provide API functions to configure the logging options, and call the logging functions when something must be recorded (printed).

[zherczeg]

This function should be removed in the future. Do we want to make it part of the release?

[zherczeg]

LGTM

[zherczeg]

Just an idea for future work: we could introduce a jerry_log() unction (or macro) which calls jerry_port_log() when the information needs to be logged.

[LaszloLango]

@akosthekiss, please check the PR.

[akosthekiss]

@LaszloLango I see the latest version calls jerry_port_log with appropriate log levels wherever printf was present (except in ecma_builtin_global_object_print), which is good. This gets memstats and js parser dumps OK. Two questions though: (1) do you plan to unify things even further by using the JERRY_DLOG macro in the memstats and js parser dump parts (but not in fatals, of course) and (2) do you plan to fix the regex dump part by putting it under a proper macro guard instead of JERRY_ENABLE_LOG?

@zherczeg I cannot wholeheartedly support the concept of keeping logging logic in jerry-core. To me, that's incorrectly mixing responsibilities.

[LaszloLango]

@akosthekiss, I have no further plans, but it would great to continue this work as you suggested.

[zherczeg]

@akosthekiss I really don't think each port should implement and maintain the logic behind logging, especially since it becomes more sophisticated over time. This way we need to implement it once, can be changed without changing the port api, can be efficient, and port maintainers does not need to understand it too deeply.

[akosthekiss]

@LaszloLango LGTM then, and I'll prepare a follow-up.

@zherczeg I don't think that logging would put a heavy burden on port maintainers either understanding- or implementation-wise. Separating logging logic from jerry-core could allow all parties to focus on their own tasks and needs. If a port needs intricate filtering of the logs, it is allowed to do so, if another port does not need it then it can go very lightweight. And the engine itself can become simpler by not dealing with any of these things. Anyway, this is a topic where we only agree that we disagree.