NetXMS Support Forum

Hi,

I wanted to do a simple log parsing. Set simple match regexp - (error.*) and event with param on netxms log file. When I enabled the parser file on agent config, it started to spam a lot of events (~10 each sec), although there were no matching lines.

Then i tried on a blank file, same thing, just spaming alot of events.
Tried matching just a letter, the same.
Anything i did, resulted in event spam.

Parser:
<parser>
    <file>C:\NetXMS\log</file>
    <rules>
        <rule>
            <match>(error.*)</match>
            <event params="1">100049</event>
        </rule>
    </rules>
</parser>


SubAgent = logwatch.nsm
*LOGWATCH
Parser = C:\NetXMS\logwatch\Test.xml

Subagent is loaded successfully.
Log:

Quote
[22-Apr-2014 14:18:56.050] [DEBUG] EVENT 100049 (ID:42456 F:0x0001 S:4 TAG:"") FROM Node:
[22-Apr-2014 14:18:56.050] [DEBUG] [CLSN-0] Sending message CMD_EVENTLOG_RECORDS
[22-Apr-2014 14:18:56.050] [DEBUG] Event 42456 match EPP rule 67
[22-Apr-2014 14:18:56.050] [DEBUG] CorrelateEvent: event BACKUP_CRIT id 42457 source Node [100]
[22-Apr-2014 14:18:56.050] [DEBUG] CorrelateEvent: finished, rootId=0
[22-Apr-2014 14:18:56.050] [DEBUG] [CLSN-0] Sending message CMD_ALARM_UPDATE
[22-Apr-2014 14:18:56.050] [DEBUG] EVENT 100049 (ID:42457 F:0x0001 S:4 TAG:"") FROM Node:
[22-Apr-2014 14:18:56.050] [DEBUG] [CLSN-0] Sending message CMD_EVENTLOG_RECORDS
[22-Apr-2014 14:18:56.050] [DEBUG] Event 42457 match EPP rule 67
[22-Apr-2014 14:18:56.050] [DEBUG] CorrelateEvent: event BACKUP_CRIT id 42458 source Node [100]
[22-Apr-2014 14:18:56.050] [DEBUG] [CLSN-0] Sending message CMD_ALARM_UPDATE
[22-Apr-2014 14:18:56.050] [DEBUG] CorrelateEvent: finished, rootId=0
[22-Apr-2014 14:18:56.050] [DEBUG] EVENT 100049 (ID:42458 F:0x0001 S:4 TAG:"") FROM Node:
[22-Apr-2014 14:18:56.050] [DEBUG] [CLSN-0] Sending message CMD_EVENTLOG_RECORDS
[22-Apr-2014 14:18:56.050] [DEBUG] Event 42458 match EPP rule 67
[22-Apr-2014 14:18:56.050] [DEBUG] CorrelateEvent: event BACKUP_CRIT id 42459 source Node [100]
[22-Apr-2014 14:18:56.050] [DEBUG] [CLSN-0] Sending message CMD_ALARM_UPDATE
[22-Apr-2014 14:18:56.050] [DEBUG] CorrelateEvent: finished, rootId=0

etc.

Is this bug or I miss something?

Regards,
Nikk

Windows event monitoring (*System etc.) works fine. But why doesn't the file option work?

Regards,
Nikk

Hi!

Can you share (part of) log file you are trying to monitor?

Best regards,
Victor

Hi,

here is a part of log file (there is no error messages), but I'm trying this only as exercise. Actual file i wish to parse ir backup systems log file, where i wish to parse error messages.

Quote[28-Apr-2014 11:52:49.631] [DEBUG] StatusPoll(KURMIS): bAllDown=false, dynFlags=0x00001001
[28-Apr-2014 11:52:49.631] [DEBUG] StatusPoll(KURMIS [786]): unable to get system uptime
[28-Apr-2014 11:52:49.631] [DEBUG] StatusPoll(LAPSA): bAllDown=false, dynFlags=0x00001001
[28-Apr-2014 11:52:49.631] [DEBUG] StatusPoll(KURMIS [786]): unable to get agent uptime
[28-Apr-2014 11:52:49.631] [DEBUG] Finished status poll for node KURMIS (ID: 786)
[28-Apr-2014 11:52:49.631] [DEBUG] StatusPoll(LAPSA [783]): unable to get system uptime
[28-Apr-2014 11:52:49.631] [DEBUG] StatusPoll(LAPSA [783]): unable to get agent uptime
[28-Apr-2014 11:52:49.631] [DEBUG] Finished status poll for node LAPSA (ID: 783)
[28-Apr-2014 11:52:49.631] [DEBUG] StatusPoll(PELE): bAllDown=false, dynFlags=0x00001001
[28-Apr-2014 11:52:49.631] [DEBUG] StatusPoll(PELE [788]): unable to get system uptime
[28-Apr-2014 11:52:49.631] [DEBUG] StatusPoll(PELE [788]): unable to get agent uptime
[28-Apr-2014 11:52:49.631] [DEBUG] Finished status poll for node PELE (ID: 788)
[28-Apr-2014 11:52:49.646] [DEBUG] StatusPoll(192.168.44.254): bAllDown=false, dynFlags=0x00001001
[28-Apr-2014 11:52:49.646] [DEBUG] Node::createAgentConnection(Proxy [383])
[28-Apr-2014 11:52:49.646] [DEBUG] Routing table updated for node TUKU [461]
[28-Apr-2014 11:52:49.646] [DEBUG] Node::createAgentConnection(Proxy [383]): conn=00000000096BC610
[28-Apr-2014 11:52:49.834] [DEBUG] Node::createAgentConnection(Proxy [383])
[28-Apr-2014 11:52:49.834] [DEBUG] Node::createAgentConnection(Proxy [383])
[28-Apr-2014 11:52:49.849] [DEBUG] Node::createAgentConnection(Proxy [383]): conn=0000000009578E40
[28-Apr-2014 11:52:49.865] [DEBUG] Routing table updated for node Liepaja [407]
[28-Apr-2014 11:52:49.865] [DEBUG] Node::createAgentConnection(Proxy [383]): conn=00000000092EA150
[28-Apr-2014 11:52:49.912] [DEBUG] StatusPoll(BALV): bAllDown=false, dynFlags=0x00001001
[28-Apr-2014 11:52:49.928] [DEBUG] StatusPoll(BALV [415]): boot time set to 1395040633 from agent
[28-Apr-2014 11:52:49.928] [DEBUG] StatusPoll(valmiera): bAllDown=false, dynFlags=0x00001001
[28-Apr-2014 11:52:49.959] [DEBUG] StatusPoll(valmiera [409]): boot time set to 1393231678 from agent
[28-Apr-2014 11:52:49.959] [DEBUG] Finished status poll for node BALV (ID: 415)
[28-Apr-2014 11:52:49.974] [DEBUG] Finished status poll for node valmiera (ID: 409)

But this event spam happens even if the log file is empty, so there must be something with the configuration, i think.
Whatever i define in match section, it results in event spam.

Is there anything I can do? Spamming hasn't stopped.
Maybe i need to give more information?

Please try to run agent in debug mode 9 and add trace="9" to parser tag (like <parser trace="9">) and provide agent's log.

Best regards,
Victor

I added trace 9 and runned debug mode 9, please see attachment.

It seems to be server log but I need agent log (because problem is on agent side - server just process events coming from agent).

Best regards,
Victor

Yes, sorry for wrong log, here is the agent log:

Quote
[12-May-2014 10:49:16.919] [DEBUG] LogParser: file size differs for stat(4) and fstat(C:\NetXMS\var\log), assume file rename
[12-May-2014 10:49:16.919] [DEBUG] LogParser: file "C:\NetXMS\var\log" (pattern "C:\NetXMS\var\log") successfully opened
[12-May-2014 10:49:16.919] [DEBUG] LogParser: parsing existing records in file "C:\NetXMS\var\log"
[12-May-2014 10:49:16.935] [DEBUG] Match line: "[12-May-2014 06:19:48.093] [DEBUG] Node::createAgentConnection(Proxy) [383]): conn=0000000002827EB0"
[12-May-2014 10:49:16.935] [DEBUG] checking rule 1 ""
[12-May-2014 10:49:16.935] [DEBUG]   rule has no context
[12-May-2014 10:49:16.935] [DEBUG]   matching against regexp (StatusPoll.*)
[12-May-2014 10:49:16.935] [DEBUG]   no match
[12-May-2014 10:49:16.935] [DEBUG] Processing stopped at end of rules list; result = false
[12-May-2014 10:49:16.951] [DEBUG] Match line: "[12-May-2014 06:19:48.124] [DEBUG] StatusPoll(JURM [430]): boot time set to 1395223729 from agent"
[12-May-2014 10:49:16.951] [DEBUG] checking rule 1 ""
[12-May-2014 10:49:16.951] [DEBUG]   rule has no context
[12-May-2014 10:49:16.951] [DEBUG]   matching against regexp (StatusPoll.*)
[12-May-2014 10:49:16.951] [DEBUG]   matched
[12-May-2014 10:49:16.951] [DEBUG] SendTrap(): event_code=100049, event_name=(null), num_args=0, arg[0]="(null)" arg[1]="(null)" arg[2]="(null)"
[12-May-2014 10:49:16.951] [DEBUG] rule 1 "" matched
[12-May-2014 10:49:16.951] [DEBUG] processing stopped at rule 1 ""; result = true

And DebugLevel in agent conf file doesn't work (or maybe i need to set something else?)

I'm a bit lost - are you sure this is log for parser mentioned in the beginning? From this log file I see that parser correctly found matching line (using StatusPoll.* pattern) and generate event. Parser in the first post had different matching pattern. Let's try to combine everything related in one post - server log and agent log for same time period plus actual parser definition.

Best regards,
Victor

Yes, i have changed the parser a little bit, but it doesn't change the problem. (see 1st screen) :/

So the parser is:

Quote
<parser trace="9">
    <file>C:\NetXMS\var\log</file>
   
    <rules>
        <rule>
            <match>(StatusPoll.*)</match>
         <event>100049</event>
        </rule>
    </rules>
</parser>

And attached is both agent and server logs.

First problem is that message is empty - this is because of wrong parameter count in event tag - it should be <event params="1">100049</event>. But spam problem most likely caused by this:

[14-May-2014 10:15:41.670] [DEBUG] LogParser: file size differs for stat(4) and fstat(C:\NetXMS\var\log), assume file rename
[14-May-2014 10:15:41.670] [DEBUG] LogParser: file "C:\NetXMS\var\log" (pattern "C:\NetXMS\var\log") successfully opened
[14-May-2014 10:15:41.670] [DEBUG] LogParser: parsing existing records in file "C:\NetXMS\var\log"

we recently encounter this bug on another installation - agent erroneously assume that file was renamed, and start reading file from the beginning. It is already fixed in current development version.

Best regards,
Victor

Yes, first problem was obvious negligence mistake.

And with upgrade to 1.2.14 everything works fine, thank you

Regards,
Nikk