<tt>nagios-users-bounces@lists.sourceforge.net schrieb am 09.07.2008 12:04:01: > after debugging some retry problems, I stumbled over strange entries > in the showlog.cgi (see attached > screenshot). This is the daily log. At 00:00 it rotates and logs all > initial states of the machines/services - > even though I disabled it in the nagios.cfg. Though I do not really > mind that. The strange thing are the > empty entries of 01.01.1970 _after_ the initial states, then some > current entries, then again 01.01.1970, then > again current states, and then nagios logs ALL the initial states _again_. > > Not that it's causing any obvious problems, but it looks kinda > strange in my opinion. > Does anyone have an idea what may cause this behaviour? </tt> <tt>Self-replies rock. ;)</tt> <tt>I'll CC this to nagios-devel since it's a bug. I'm not yet sure</tt> <tt>where it actually comes from, but I guess it's inside process_macros().</tt> <tt>Still trying to pin it down exactly...</tt> <tt>Back to my initial problem (see above).</tt> <tt>After some debugging I found the culprit. It's my service definitions</tt> <tt>containing quoted $ signs. Nagios stumbles over them and logs nonsense</tt> <tt>in the current state logging after log rotating and everytime else when</tt> <tt>it processes macros for this server (see below).</tt> <tt>This is an excerpt from nagios.log (notice the lines with single $ on them):</tt> <tt>[1215727200] CURRENT SERVICE STATE: esskhk01;MSSQLSERVER;OK;HARD;1;OK: MSSQLSERVER: started</tt> <tt>[1215727200] CURRENT SERVICE STATE: esskhk01;MSSQL_PERBIT;OK;HARD;1;OK: MSSQL$PERBIT: started</tt> <tt>$</tt> <tt>[1215727200] CURRENT SERVICE STATE: esskhk01;MSSQL_PERSONAL;OK;HARD;1;OK: MSSQL$PERSONAL: started</tt> <tt>$</tt> <tt>[1215727200] CURRENT SERVICE STATE: esskhk01;NSClient_Version;OK;HARD;1;I (0.3.0.4 2007-12-04) seem to be doing fine...</tt> <tt>[1215727200] CURRENT SERVICE STATE: esskhk01;SQLAgent_PERBIT;OK;HARD;1;OK: SQLAgent$PERBIT: started</tt> <tt>$</tt> <tt>[1215727200] CURRENT SERVICE STATE: esskhk01;SQLAgent_PERSONAL;OK;HARD;1;OK: SQLAgent$PERSONAL: started</tt> <tt>$</tt> <tt>[1215727200] CURRENT SERVICE STATE: esskhk01;SQLSERVERAGENT;OK;HARD;1;OK: SQLSERVERAGENT: started</tt> <tt>Those "$" lines show up as "</tt>[01-01-1970 01:00:00] <tt>" with empty info on them in the showlog.cgi (see below).</tt> <tt>My service definition for example:</tt> <tt>define service {</tt> <tt> service_description MSSQL_PERBIT</tt> <tt> use generic-service-noperf</tt> <tt> host_name esskhk01</tt> <tt> check_command check_nrpe_services!MSSQL"$$"PERBIT</tt> <tt>}</tt> <tt>Debugging shows (debug_level=-1, debug_verbosity=2):</tt> <tt>Check gets scheduled and nagios parses the returnvalue. Obviously there is a \n that does not belong there.</tt> <tt>Not yet sure why it shows up there...</tt> <tt>[1215777431.127292] [001.0] [pid=3539] handle_async_service_check_result()</tt> <tt>[1215777431.127299] [016.0] [pid=3539] ** Handling check result for service 'MSSQL_PERBIT' on host 'esskhk01'...</tt> <tt>[1215777431.127305] [016.1] [pid=3539] HOST: esskhk01, SERVICE: MSSQL_PERBIT, CHECK TYPE: Active, OPTIONS: 0, SCHEDULED: Yes, RESCHE</tt> <tt>DULE: Yes, EXITED OK: Yes, RETURN CODE: 3, OUTPUT: Service: MSSQL$PERBI caused: GetServiceKeyName: Could not translate service name(</tt> <tt>997)\n</tt> <tt>[1215777431.127320] [016.1] [pid=3539] Service is in a non-OK state!</tt> <tt>- Shortly afterwards the macros for the alert get processed.</tt> <tt>- The fprintf parses the \n and the log shows a newline now.</tt> <tt>- Afterwards process_macros() parses the string and tries to resolve everything after the $ in the service</tt> <tt> definition.</tt> <tt>- It fails to do so for obvious reasons, but then it seems to add an extra $ at the end of the buffer,</tt> <tt> maybe while trying to fix up a "broken macro"?</tt> <tt>- Because the input buffer does not seem to be stripped yet, it adds an extra $ _after_ the \n</tt> <tt>- strip(buffer) doesn't work anymore, as it only strips \n and " " when trailing and heading.</tt> <tt>That's why I see single "$" entries in my logfile - which the showlog.cgi wrong parses as</tt> <tt>"</tt>[01-01-1970 01:00:00] <tt>"</tt> <tt>Notice the buffer before processing (no $ at the end) and after processing (with $ at the end - after the \n).</tt> <tt>[1215777431.129970] [2048.1] [pid=3539] **** BEGIN MACRO PROCESSING ***********</tt> <tt>[1215777431.129978] [2048.1] [pid=3539] Processing: 'SERVICE ALERT: esskhk01;MSSQL_PERBIT;$SERVICESTATE$;$SERVICESTATETYPE$;$SERVICE</tt> <tt>ATTEMPT$;Service: MSSQL$PERBI caused: GetServiceKeyName: Could not translate service name(997)</tt> <tt>'</tt> <tt>[1215777431.130001] [2048.0] [pid=3539] WARNING: Could not find a macro matching 'PERBI caused'!</tt> <tt>[1215777431.130010] [2048.0] [pid=3539] WARNING: An error occurred processing macro 'PERBI caused: GetServiceKeyName: Could not tra</tt> <tt>nslate service name(997)</tt> <tt>'!</tt> <tt>[1215777431.130018] [2048.1] [pid=3539] Done. Final output: 'SERVICE ALERT: esskhk01;MSSQL_PERBIT;UNKNOWN;SOFT;1;Service: MSSQL$P</tt> <tt>ERBI caused: GetServiceKeyName: Could not translate service name(997)</tt> <tt>$'</tt> <tt>[1215777431.130025] [2048.1] [pid=3539] **** END MACRO PROCESSING *************</tt> <tt>Sadly process_macros() is really ... uhm ... ugly ;) I haven't been able to find the problem yet.</tt> <tt>Maybe someone with more insight in common/macros.c can have a look? I'm more then happy to assist though.</tt> <tt>Regards</tt> <tt> Sascha</tt> <tt>PS: Nagios 3.0.3 of course.</tt> -- Sascha Runschke Netzwerk- und Systemmanagement Telefon : +49 (201) 102-1879 Mobil : +49 (173) 5419665 Fax : +49 (201) 102-1102105 GFKL Financial Services AG Vorstand: Dr. Peter Jänsch (Vors.), Jürgen Baltes, Dr. Till Ergenzinger, Dr. Tom Haverkamp Vorsitzender des Aufsichtsrats: Dr. Georg F. Thoma Sitz: Limbecker Platz 1, 45127 Essen, Amtsgericht Essen, HRB 13522