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

[icinga-migration]

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:

• relates #3404
• relates #3404

[icinga-migration]

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]

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]

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

• Target Version set to 1.8.2

[icinga-migration]

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

For me, that fixes the problem.

Thank you very much

[icinga-migration]

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]

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]

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

• Status changed from Assigned to Resolved
• Done % changed from 80 to 100