| Summary: | ASTERISK-17850: inverse / incorrect behavior for CLI / console logging of DTMF | ||||
| Reporter: | Luke H (luckman212) | Labels: | |||
| Date Opened: | 2011-05-12 23:54:32 | Date Closed: | 2011-06-06 14:46:44 | ||
| Priority: | Minor | Regression? | No | ||
| Status: | Closed/Complete | Components: | Core/Configuration | ||
| Versions: | 1.8.4 | Frequency of Occurrence | |||
| Related Issues: |
| ||||
| Environment: | Attachments: | ||||
| Description: | try this: set /etc/asterisk/logger.conf as so: [general] dateformat=%F %T [logfiles] messages => notice,warning,error full => dtmf,notice,warning,error,debug,verbose console => dtmf,notice,warning,error Now, start Asterisk CLI and try to play some DTMF tones, you won't see them logged to the console (but they ARE logged to /var/log/asterisk/full) now, type 'logger set level DTMF off' (yes, OFF) and test again, now DTMF is being logged to console! so it seems the switch is somehow 'backwards' | ||||
| Comments: | By: Leif Madsen (lmadsen) 2011-05-13 08:27:27 Well I can definitely confirm this is what is happening on trunk. I'm gonna see if I can figure out why... By: Leif Madsen (lmadsen) 2011-05-13 08:28:09 It's not just DTMF -- it's all logger levels. By: Luke H (luckman212) 2011-05-13 08:49:34 also, not just trunk... I'm running 1.8.4 (release) and see this behavior By: Leif Madsen (lmadsen) 2011-05-13 09:08:14 Yes I realize that, I just happened to be testing on trunk. Here is a conversation on IRC. I have a fix, but it's not the right "fix". I'll come back to this when I have time. If I have time :) <pre> <leifmadsen> http://pastebin.ca/2058239 <leifmadsen> when I change that line, it works as expected <leifmadsen> it seems like it should have been right in the first place though <russellb> i don't know the context <leifmadsen> argv[4] would be 'on' or 'off' <leifmadsen> logger set level DTMF on <leifmadsen> right now... on == off, and off == on <russellb> then ast_true() doesn't make any sense, i didn't know how it took "on" <leifmadsen> right <russellb> oh, it does. <leifmadsen> I just don't know if it's flipping it because of on == <something that evals to false> <russellb> but yes, it looks right before the change <russellb> check how toggle_loglevel() works <russellb> and how it handles the state argument <leifmadsen> ast_console_toggle_loglevel() ? <russellb> yes <russellb> what is it doing when given state == 1 vs state == 0 <leifmadsen> only time it deals with state is assigning it to: consoles[x].levels[level] = state; <leifmadsen> like here: http://pastebin.ca/2058244 <leifmadsen> I don't understand enough to know what it is doing there <russellb> so what tells you it's broken in the first place <pabelanger> leifmadsen: space between 0 and ; <leifmadsen> russellb: well just using it :) <pabelanger> err, ; and x <leifmadsen> when I use 'on' it turns it off, and vice-versa <leifmadsen> pabelanger: oh ya? let me try that.......... <pabelanger> leifmadsen: not the fix, just code formatting :p <leifmadsen> oh well eff that ;) <leifmadsen> anyways, it's not immediately obvious why it's broken, so I'm going to move onto releases <russellb> k! <leifmadsen> I was hoping to fix something trivial but it's not that way :) <leifmadsen> it does work opposite of what I expected, and was confused why flipping the ast_true() around worked because that seemed wrong <russellb> the next thing to look at is how consoles[].levels[] values are read <russellb> well i believe that your change fixes it <leifmadsen> it does <russellb> i just think the fix should be to make the code work how we think it should work <leifmadsen> but I don't think it's the right fix.... <russellb> right <leifmadsen> I think it's the hack <russellb> something is reading levels backwards </pre> By: Luke H (luckman212) 2011-05-13 09:30:38 Interesting! yes I was fumbling and stumbling through the code and it seemed to me like that's what was happening too- somehow the inital value was being set wrong during initial load, so if argv[4] should == 1 to cause messages to be printed to the console, then perhaps it was being set to -1, or 2 etc and then setting the loglevel to 'off' caused it to flip back to 1 somehow. But I couldn't understand why the messages were still being correctly written to the FILES. So I thought there might be some problems in the logger_print_normal() func around line of 897 logger.c as well. By: Jonathan Rose (jrose) 2011-06-01 10:47:57 This doesn't seem to work like how you guys are describing it. For me, it seems like if it's set in the conf file to log DTMF to the console, it will do so if if it's not, it won't. Meanwhile, logger set level DTMF on and logger set level DTMF off seems to do nothing within the console. logger show channels has the same output before and after both commands whether the conf file is set to log DTMF to the console or not and the actual behavior of what it writes to CLI also remains unchanged. By: Luke H (luckman212) 2011-06-01 10:55:04 Well, seems just about everyone is seeing different results. The one thing I think we can all agree on is- there's some sort of disconnect between the way logger.conf is configured, the 'logger set level DTMF off|on' CLI command, and the expected console output. By: Jonathan Rose (jrose) 2011-06-01 11:29:24 Just tried it in 1.8 checked out using revision date 5/10, same behavior. Same behavior in the 1.8.4.1 tarball from Asterisk.org as well. logger set level has no effect on behavior or output of logger show channels. Can you show me some CLI output for those two commands? First with DTMF logging enabled going to disabled and then for the reverse would be helpful. At least then I'd be able to see if my Asterisk box is just insane. By: Jonathan Rose (jrose) 2011-06-01 11:43:48 Oh ho ho, nevermind. It seems this is strictly an issue for remote coonsole sessions and I was trying to replicate it by connecting at the start. Still seems horrendously broken though. By: Jonathan Rose (jrose) 2011-06-01 16:05:04 https://reviewboard.asterisk.org/r/1244/ You can get the patch by downloading the review diff. Please let me know if you think this is an appropriate approach. By: Luke H (luckman212) 2011-06-01 17:40:09 Thanks for the patch jrose. I installed this on my * system running SVN 1.8-r321537M While there is progress towards a working patch, there is more to be done afaik. The "gotcha" with this patch, I now have to exclusively turn ON the channels via the CLI before I see anything. The only thing I see in the console now is DTMF. This appears to be because the other channels are defaulting to "off" at startup. I tried defining (in cli.conf) that I want the various channels to be 'ON' when I start asterisk. e.g. I put the following in cli.conf [startup_commands] logger set level NOTICE on = yes logger set level WARNING on = yes logger set level ERROR on = yes logger set level VERBOSE on = yes logger set level DTMF on = yes but even with those commands in, nothing gets logged to the console (well, actually **ONLY** DTMF does!) when I first attach to it. Then I type 'logger set level VERBOSE on' for example, and I start to see the normal logging. The strangeness continues! By: Jonathan Rose (jrose) 2011-06-02 13:18:16 Actually, that's not surprising to me at all. That just means the defaults are all backwards as well, which certainly helps to obscure the problem... Also, I think those startup scripts might be being ran without reference to a specific CLI session... so they might just not do anything to your attached console. EDIT: I've confirmed that this is the case since the startup scripts don't get ran every time the user connects with asterisk -r By: Luke H (luckman212) 2011-06-02 18:47:23 Yes it makes sense that the defaults would have been backwards, thus sort of hiding the original problem. It's odd that out of all the 6 channels, only DTMF is set properly when it gets initialized. But maybe that's because it was the last one added. I tried feebly to dig up the bit of code where these defaults are being set. But I really have no clue where this is hiding. Anyone know? By: Jonathan Rose (jrose) 2011-06-03 13:59:28 I looked all over and couldn't find it any friggen-where. It's obscured quite nicely, could be anything involving logger.h really. If I had to take a guess, I wouldn't be surprised if it was something completely ridiculous. I think it's possible that it could be done by anything that uses either asterisk.h or logger.h, so it's a difficult find. I've changed the patch to a slightly more superficial one, but it makes sense and it doesn't rock the boat much, so I'm going to go ahead and commit it as soon as someone gives a ship it. By: Luke H (luckman212) 2011-06-04 18:56:58 I was poking around in the '/include/asterisk/logger.h' code and it appears (to my untrained eye at least) that on line 168: {noformat} #define LOG_VERBOSE __LOG_VERBOSE, _A_ {noformat} ..should actually be.. {noformat} #define AST_LOG_VERBOSE __LOG_VERBOSE, _A_ {noformat} I only say this because that would follow the structure of the other variable declarations. AST_LOG seems to be some sort of macro but I admit I do not really understand the code here. I don't know if this relates at all but I noticed it and thought I would comment since we're on the subject of logger. Also, when I applied the reviewboard patch, it does fix the issue (although this "on=off, off=on" patch really seems quite nasty) however LOG_DTMF still needs to be toggled 'on' before it starts logging to console. If I just start up Asterisk, no DTMF gets logged until I do 'logger set level DTMF on'. Where oh where is this variable getting initialized?? Someone must know! By: Jeremy Kister (jkister) 2011-06-04 19:27:54 This is a dupe of 17922 https://issues.asterisk.org/view.php?id=17922 By: Jonathan Rose (jrose) 2011-06-06 14:46:44.029-0500 This resolves the actual issue of the logger input being reversed. If DTMF not being logged by default is something you see as aberrant behavior, please submit a new issue report for that. | ||||