Skip to content
This repository has been archived by the owner. It is now read-only.

[dev.icinga.com #3404] macro escaping logs incorrect warning for $$ escapes #1149

Closed
icinga-migration opened this issue Oct 28, 2012 · 7 comments

Comments

Projects
None yet
1 participant
@icinga-migration
Copy link
Member

commented Oct 28, 2012

This issue has been migrated from Redmine: https://dev.icinga.com/issues/3404

Created by abgandar on 2012-10-28 17:08:48 +00:00

Assignee: mfriedrich
Status: Resolved (closed on 2012-11-09 17:35:45 +00:00)
Target Version: 1.8.2
Last Update: 2012-11-09 17:35:45 +00:00 (in Redmine)

Icinga Version: 1.8.1  (built from FreeBSD ports)
OS Version: FreeBSD 9.1

In my icinga.log file, I keep getting these messages:
[1351443452] Warning: An error occurred processing macro ''!

I traced it back to the expansion of the following check command copied straight from the example commands.cfg file provided with Icinga:
define command {
command_name check_icinga_startup_delay
command_line $USER1$/check_dummy 0 "Icinga started with $$(($EVENTSTARTTIME$-$PROCESSSTARTTIME$)) seconds delay | delay=$$(($EVENTSTARTTIME$-$PROCESSSTARTTIME$))"
}

It seems the '$$' are correctly escaped into a single '$' in the command line that is executed, but there still is a warning logged each time the $$ is encountered. This should not happen as the command line is correct and there is no reason for a warning to appear.

Here is the relevant output from the debug log illustrating the situation:

[1351442252.937270] [2048.1] [pid=67924] **** BEGIN MACRO PROCESSING *****
[1351442252.937282] [2048.1] [pid=67924] Processing: '$USER1$/check_dummy 0 "Icinga started with $$(($EVENTSTARTTIME$-$PROCESSSTARTTIME$)) seconds delay | delay=$$(($EVENTSTARTTIME$-$PROCESSSTARTTIME$))"'
[1351442252.937295] [2048.2] [pid=67924] Processing part: ''
[1351442252.937310] [2048.2] [pid=67924] Not currently in macro. Running output (0): ''
[1351442252.937322] [2048.2] [pid=67924] Processing part: 'USER1'
[1351442252.937338] [2048.2] [pid=67924] Processed 'USER1', Clean Options: 0, Free: 0
[1351442252.937351] [2048.2] [pid=67924] Processed 'USER1', Clean Options: 0, Free: 0
[1351442252.937364] [2048.2] [pid=67924] Cleaning options: global=0, local=0, effective=0
[1351442252.937377] [2048.2] [pid=67924] Uncleaned macro. Running output (25): '/usr/local/libexec/nagios'
[1351442252.937391] [2048.2] [pid=67924] Just finished macro. Running output (25): '/usr/local/libexec/nagios'
[1351442252.937403] [2048.2] [pid=67924] Processing part: '/check_dummy 0 "Icinga started with '
[1351442252.937417] [2048.2] [pid=67924] Not currently in macro. Running output (61): '/usr/local/libexec/nagios/check_dummy 0 "Icinga started with '
[1351442252.937429] [2048.2] [pid=67924] Processing part: ''
[1351442252.937444] [2048.0] [pid=67924] WARNING: Could not find a macro matching ''!
[1351442252.937457] [2048.2] [pid=67924] Processed '', Clean Options: 0, Free: 1
[1351442252.937522] [064.1] [pid=67924] Making callbacks (type 9)...
[1351442252.937536] [2048.2] [pid=67924] Escaped $. Running output (61): '/usr/local/libexec/nagios/check_dummy 0 "Icinga started with '
[1351442252.937550] [2048.2] [pid=67924] Processing part: '(('
[1351442252.937564] [2048.2] [pid=67924] Not currently in macro. Running output (64): '/usr/local/libexec/nagios/check_dummy 0 "Icinga started with $(('
[1351442252.937577] [2048.2] [pid=67924] Processing part: 'EVENTSTARTTIME'
[1351442252.937592] [2048.2] [pid=67924] macros[142] (EVENTSTARTTIME) match.
[1351442252.937606] [2048.2] [pid=67924] Processed 'EVENTSTARTTIME', Clean Options: 0, Free: 0
[1351442252.937619] [2048.2] [pid=67924] Processed 'EVENTSTARTTIME', Clean Options: 0, Free: 0
[1351442252.937644] [2048.2] [pid=67924] Cleaning options: global=0, local=0, effective=0
[1351442252.937659] [2048.2] [pid=67924] Uncleaned macro. Running output (74): '/usr/local/libexec/nagios/check_dummy 0 "Icinga started with $((1351442213'
[1351442252.937672] [2048.2] [pid=67924] Just finished macro. Running output (74): '/usr/local/libexec/nagios/check_dummy 0 "Icinga started with $((1351442213'
[1351442252.937685] [2048.2] [pid=67924] Processing part: '-'
[1351442252.937698] [2048.2] [pid=67924] Not currently in macro. Running output (75): '/usr/local/libexec/nagios/check_dummy 0 "Icinga started with $((1351442213-'
[1351442252.937711] [2048.2] [pid=67924] Processing part: 'PROCESSSTARTTIME'
[1351442252.937726] [2048.2] [pid=67924] macros[96] (PROCESSSTARTTIME) match.
[1351442252.937740] [2048.2] [pid=67924] Processed 'PROCESSSTARTTIME', Clean Options: 0, Free: 0
[1351442252.937754] [2048.2] [pid=67924] Processed 'PROCESSSTARTTIME', Clean Options: 0, Free: 0
[1351442252.937767] [2048.2] [pid=67924] Cleaning options: global=0, local=0, effective=0
[1351442252.937781] [2048.2] [pid=67924] Uncleaned macro. Running output (85): '/usr/local/libexec/nagios/check_dummy 0 "Icinga started with $((1351442213-1351442213'
[1351442252.937795] [2048.2] [pid=67924] Just finished macro. Running output (85): '/usr/local/libexec/nagios/check_dummy 0 "Icinga started with $((1351442213-1351442213'
[1351442252.937807] [2048.2] [pid=67924] Processing part: ')) seconds delay | delay='
[1351442252.937821] [2048.2] [pid=67924] Not currently in macro. Running output (110): '/usr/local/libexec/nagios/check_dummy 0 "Icinga started with $((1351442213-1351442213)) seconds delay | delay='
[1351442252.937835] [2048.2] [pid=67924] Processing part: ''
[1351442252.937848] [2048.0] [pid=67924] WARNING: Could not find a macro matching ''!
[1351442252.937861] [2048.2] [pid=67924] Processed '', Clean Options: 0, Free: 1
[1351442252.937916] [064.1] [pid=67924] Making callbacks (type 9)...
[1351442252.937931] [2048.2] [pid=67924] Escaped $. Running output (110): '/usr/local/libexec/nagios/check_dummy 0 "Icinga started with $((1351442213-1351442213)) seconds delay | delay='
[1351442252.937945] [2048.2] [pid=67924] Processing part: '(('
[1351442252.937959] [2048.2] [pid=67924] Not currently in macro. Running output (113): '/usr/local/libexec/nagios/check_dummy 0 "Icinga started with $((1351442213-1351442213)) seconds delay | delay=$(('
[1351442252.937972] [2048.2] [pid=67924] Processing part: 'EVENTSTARTTIME'
[1351442252.937986] [2048.2] [pid=67924] macros[142] (EVENTSTARTTIME) match.
[1351442252.938000] [2048.2] [pid=67924] Processed 'EVENTSTARTTIME', Clean Options: 0, Free: 0
[1351442252.938014] [2048.2] [pid=67924] Processed 'EVENTSTARTTIME', Clean Options: 0, Free: 0
[1351442252.938027] [2048.2] [pid=67924] Cleaning options: global=0, local=0, effective=0
[1351442252.938041] [2048.2] [pid=67924] Uncleaned macro. Running output (123): '/usr/local/libexec/nagios/check_dummy 0 "Icinga started with $((1351442213-1351442213)) seconds delay | delay=$((1351442213'
[1351442252.938054] [2048.2] [pid=67924] Just finished macro. Running output (123): '/usr/local/libexec/nagios/check_dummy 0 "Icinga started with $((1351442213-1351442213)) seconds delay | delay=$((1351442213'
[1351442252.938067] [2048.2] [pid=67924] Processing part: '-'
[1351442252.938081] [2048.2] [pid=67924] Not currently in macro. Running output (124): '/usr/local/libexec/nagios/check_dummy 0 "Icinga started with $((1351442213-1351442213)) seconds delay | delay=$((1351442213-'
[1351442252.938094] [2048.2] [pid=67924] Processing part: 'PROCESSSTARTTIME'
[1351442252.938108] [2048.2] [pid=67924] macros[96] (PROCESSSTARTTIME) match.
[1351442252.938121] [2048.2] [pid=67924] Processed 'PROCESSSTARTTIME', Clean Options: 0, Free: 0
[1351442252.938135] [2048.2] [pid=67924] Processed 'PROCESSSTARTTIME', Clean Options: 0, Free: 0
[1351442252.938148] [2048.2] [pid=67924] Cleaning options: global=0, local=0, effective=0
[1351442252.938174] [2048.2] [pid=67924] Uncleaned macro. Running output (134): '/usr/local/libexec/nagios/check_dummy 0 "Icinga started with $((1351442213-1351442213)) seconds delay | delay=$((1351442213-1351442213'
[1351442252.938188] [2048.2] [pid=67924] Just finished macro. Running output (134): '/usr/local/libexec/nagios/check_dummy 0 "Icinga started with $((1351442213-1351442213)) seconds delay | delay=$((1351442213-1351442213'
[1351442252.938202] [2048.2] [pid=67924] Processing part: '))"'
[1351442252.938215] [2048.2] [pid=67924] Not currently in macro. Running output (137): '/usr/local/libexec/nagios/check_dummy 0 "Icinga started with $((1351442213-1351442213)) seconds delay | delay=$((1351442213-1351442213))"'
[1351442252.938229] [2048.1] [pid=67924] Done. Final output: '/usr/local/libexec/nagios/check_dummy 0 "Icinga started with $((1351442213-1351442213)) seconds delay | delay=$((1351442213-1351442213))"'
[1351442252.938242] [2048.1] [pid=67924] **** END MACRO PROCESSING *****

Changesets

2012-10-29 18:09:49 +00:00 by mfriedrich f78e443

macros: only warn on not escaped $ signs (refs #3404)

Relations:

@icinga-migration

This comment has been minimized.

Copy link
Member Author

commented Oct 29, 2012

Updated by fmbiete on 2012-10-29 15:28:19 +00:00

I can confirm the same problem.


Debian 6.0.6
Icinga 1.8.1 built from source.

@icinga-migration

This comment has been minimized.

Copy link
Member Author

commented Oct 29, 2012

Updated by mfriedrich on 2012-10-29 16:57:05 +00:00

seems i was not really awake when fixing #3397

the logic on hitting a macro error is a bit screwed up, so once detecting an error, it could also be the case of an escaped $ - but rather then rewriting that logic now, please try the attached patch instead.

diff --git a/common/macros.c b/common/macros.c
index 4463ab2..0b4a32c 100644
--- a/common/macros.c
+++ b/common/macros.c
@@ -204,7 +204,10 @@ int process_macros_r(icinga_macros *mac, char *input_buffer, char **output_buffe

                        /* an error occurred - we couldn't parse the macro, so continue on */
                        if (result == ERROR) {
-                               logit(NSLOG_RUNTIME_WARNING, TRUE, "Warning: An error occurred processing macro '%s'!\n", temp_buffer);
+                               /* empty string still could mean that we hit the escaped $, so log an error in all other cases */
+                               if(strcmp(temp_buffer, ""))
+                                       logit(NSLOG_RUNTIME_WARNING, TRUE, "Warning: An error occurred processing macro '%s'!\n", temp_buffer);
+
                                if (free_macro == TRUE)
                                        my_free(selected_macro);
                        }
@icinga-migration

This comment has been minimized.

Copy link
Member Author

commented Oct 29, 2012

Updated by mfriedrich on 2012-10-29 16:57:35 +00:00

  • Target Version set to 1.8.2
@icinga-migration

This comment has been minimized.

Copy link
Member Author

commented Oct 29, 2012

Updated by fmbiete on 2012-10-29 19:45:11 +00:00

For me, that fixes the problem.

Thank you very much

@icinga-migration

This comment has been minimized.

Copy link
Member Author

commented Oct 29, 2012

Updated by abgandar on 2012-10-29 19:49:29 +00:00

Confirmed, this workaround removes the warnings for me as well. Thanks.

@icinga-migration

This comment has been minimized.

Copy link
Member Author

commented Oct 29, 2012

Updated by mfriedrich on 2012-10-29 19:53:08 +00:00

  • Status changed from New to Assigned
  • Assigned to set to mfriedrich
  • Done % changed from 0 to 80

ok, thx for testing. as you've seen there's an 1.8.2 already planned to address various ido and classic ui issues, to be released somewhere in november then (when ricardo is back again too).

@icinga-migration

This comment has been minimized.

Copy link
Member Author

commented Nov 9, 2012

Updated by mfriedrich on 2012-11-09 17:35:45 +00:00

  • Status changed from Assigned to Resolved
  • Done % changed from 80 to 100
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
You can’t perform that action at this time.