[asterisk-dev] [Code Review] 2825: Remote console: more output discrepancies

[Kevin Harwell]

> On Sept. 5, 2013, 5:08 a.m., Tilghman Lesher wrote:
> > It's not clear why adding a magic value for cli output is the answer here.
> 
> Kevin Harwell wrote:
>     There must be a way to tell if incoming text on a remote console are log messages vs. cli output. 
>     
>     Say for instance the log level was 3 on the remote console and a few lines of log messages had been sent to it.  At this point the last known log level was 3.  Now a cli output message is sent to the remote console and since it has no "magic" the last known log level was assumed and it would print the cli output using the verbose level 3 prefix.
>     
>     By adding a "magic" value to the cli output going to a remote console it can now tell the difference between incoming log messages and cli output and print them appropriately.
> 
> Tilghman Lesher wrote:
>     A magic value is only supposed to be good until a newline.  Once you hit the newline, you reset back to cli output unless you see another magic value directly after the newline character.
> 
> Kevin Harwell wrote:
>     There are some scenarios where that would fail, thus the discrepancies.  For instance, if someone did the following:
>     
>     ast_verb(3, "hello\nworld\n");
>     
>     That would only output the level 3 prefix for the "hello" and then no prefix for "world".  Another example would be if there is no newline:
>     
>     ast_verb(3, "hello world");
>     
>     If cli output is received the first line would be on the same line as the log message.  If another verbose log message, say at level 2, was issued it would also show up appended to the level 3 message.
> 
> Tilghman Lesher wrote:
>     If either of those cases existed in the code, they should definitely be fixed.  It's kind of hard to argue, "Well, if there are bugs in the code, then things don't work correctly, so we should code around it, instead of fixing those bugs."  Think about it.
> 
> Matt Jordan wrote:
>     We've never had a limitation against putting multi-line output in a single verbose message before. (There's probably even more debug messages that do this). I'm not against that limitation - I personally don't care for log messages that are multiple lines - but that doesn't mean there aren't plenty of instances of it littered throughout the source code. In fact, Asterisk even leads off with one:
>     
>     #define WELCOME_MESSAGE \
>         ast_verbose("Asterisk %s, Copyright (C) 1999 - 2013 Digium, Inc. and others.\n" \
>                     "Created by Mark Spencer <markster at digium.com>\n" \
>                     "Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details.\n" \
>                     "This is free software, with components licensed under the GNU General Public\n" \
>                     "License version 2 and other licenses; you are welcome to redistribute it under\n" \
>                     "certain conditions. Type 'core show license' for details.\n" \
>                     "=========================================================================\n", ast_get_version()) \
>     
>     We'd certainly have to publicize "Don't do this, you screw up remote consoles" for all contributors. Finding all of these would certainly be a joy as well.
>     
>     The fact that we have to massage the output as it goes to the remote console in such a fashion is the result of the feature in Asterisk 11. I'd prefer to get that tolerant of as many scenarios as possible *and* make a note not to ever allow messages like that again.
> 
> Kevin Harwell wrote:
>     I'd also add that possible multi-line strings can come from an embedded string or a string created from another function/module/etc.  One still has to check and possibly parse any string given to a log statement since it may contain multiple lines.
>     
>     I don't believe the second case is a bug either.  There may be instances (if some are not already in Asterisk) where a developer may want/need to write out part of a log message and then finish that line later.
> 
> Tilghman Lesher wrote:
>     > I don't believe the second case is a bug either.  There may be instances (if some are not already in Asterisk) where a developer may want/need to write out part of a log message and then finish that line later.
>     
>     The second case is definitely a bug in any multithreaded code, UNLESS the logging module held up that message from going anywhere.  You cannot have that expectation in multithreaded code without getting yourself in trouble.
>     
>     > The fact that we have to massage the output as it goes to the remote console in such a fashion is the result of the feature in Asterisk 11. I'd prefer to get that tolerant of as many scenarios as possible *and* make a note not to ever allow messages like that again.
>     
>     That's fair enough.

Aaah yes multithreading - always need to keep in mind.  So the second case (hopefully none in Asterisk!) is a bug and it sounds like the first is allowed.  Actually, I don't think the first case was the sole problem, but it was one that initiated the changes.

With that in mind, and hopefully to further clarify the answer to your original statement, the remote console can not distinguish between a log message and cli output.  Each new line that the remote console receives might be a log message originating from the same string (multi-line message), a new log message altogether, or cli output.  So there needed to be a way to let the remote console know that the incoming text was part of cli output, thus the "magic" value was added to it.


- Kevin


-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviewboard.asterisk.org/r/2825/#review9594
-----------------------------------------------------------


On Sept. 6, 2013, 4:14 p.m., Kevin Harwell wrote:
> 
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviewboard.asterisk.org/r/2825/
> -----------------------------------------------------------
> 
> (Updated Sept. 6, 2013, 4:14 p.m.)
> 
> 
> Review request for Asterisk Developers.
> 
> 
> Bugs: ASTERISK-22450
>     https://issues.asterisk.org/jira/browse/ASTERISK-22450
> 
> 
> Repository: Asterisk
> 
> 
> Description
> -------
> 
> This is a follow up to https://reviewboard.asterisk.org/r/2798/
> 
> The remote console continued to have issues with its output.  In this case CLI command output would either not show up (if verbose level = 0) or would contain verbose prefixes (if verbose level > 0) once log messages were sent to the remote console.  The fix now distinguishes between verbose log messages and cli command output sent to a remote console.
> 
> 
> Diffs
> -----
> 
>   branches/11/include/asterisk/cli.h 398227 
>   branches/11/main/asterisk.c 398227 
>   branches/11/main/cli.c 398227 
>   branches/11/main/logger.c 398227 
> 
> Diff: https://reviewboard.asterisk.org/r/2825/diff/
> 
> 
> Testing
> -------
> 
> Duplicated issues.  Then ran scenarios again and observed that the issues were no longer occurring.  Also tried several other combinations of log levels and cli commands between consoles (local/remote).
> 
> 
> Thanks,
> 
> Kevin Harwell
> 
>

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-dev/attachments/20130906/8958a0e7/attachment.htm>