MonitorWare Knowledge Base

We have been experiencing an issue with Winsyslog lately. After a great deal of research I believe we have determined it is related to the message volume being sent to the Winsyslog server.

We have two syslog servers both with Winsyslog running. Each is cconfigured roughly the same, the main difference being the number of devices logging to each. The total data volume is esentially identical on each server.

The Winsyslog rules are structured as follows:
Rule1
Filter - Source system equals a.b.c.d
Write to file a_b_c_d.txt
Discard
Rule2
Filter - Source system equals e.f.g.h
Write to file e_f_g_h.txt
Discard
etc.


When the volume of messages begins to reach 4,700 messages per second (averages 600-700 until these spikes) we begin to see the following errors from Winsyslog in the event logs:
EventID 114: Unknown error while applying the actions - continuing
EventID 114: An unknown exception occured in CInfoSourceSyslog::Run().
EventID 114: Unknown error while applying the actions - continuing
EventID 114: Unknown error while applying the actions - continuing
EventID 114: Unknown error while applying the actions - continuing
EventID 114: Unknown error while applying the actions - continuing
EventID 114: Unknown error while applying the actions - continuing
EventID 114: Unknown error while applying the actions - continuing
EventID 114: Unknown error while applying the actions - continuing
EventID 114: Unknown error while applying the actions - continuing
EventID 151: Numerous runtime events were encountered. This is usually caused by configuration or network problems. From now, there will no more events logged for this hour.

At this point the Winsyslog application no longer writes data to the text files defined by the rules. The Winsyslog service appears to be running and the only way to make it begin logging again is to issue a restart from the Winsyslog console application.

The server running Winsyslog is a quad processor 2.8GHz Xeon with 3.5GB of RAM. System resources (RAM, CPU, network bandwidth) do not seem to be an issue.

Any idea what may be causing this, or is it simply a matter of exceeding Winsyslog's capabilities? Worst case, it would be nice if Winsyslog would continue to log and just skip some data it cannot handle. Any assistance would be appreciated.

Thanks for the detailled bug report. I agree, there must actually be going very wrong. WinSyslog was specifically developed to handle very large message bursts, so what you intend to do is well within the specification. To track down what goes wrong in your configuration, a debug log would be most helpful. The only issue is that with the large message volume, debug logs obviously tend to become very large in a short time. Eventually we can work around this by using ring-buffered logs.

The debug logging facility can be enabled via the general properties page. Please set it to full log volume and let it use 10 1GB log files (well, the numbers must not be exactly what I propose, but I think it would be helpful if we could set it to them). The key point is to stop the service when the problem re-occurs. Then, we would need to have the zipped log files ftped to us.

If that is not an option, please let us know and we will look into other ways of handling this. I would also appreciate if you could open a support ticket by sending further information to support@adiscon.com. In the course of tackling this action, we probably need to exchange some sensitve configuration details, which are not good to have on a public forum.

Best regards,
Rainer Gerhards
Adiscon

A configuration snapshot could be very interesting.
Am I Right that you basically want to device the logfiles by source system? If yes, you can have everything with one Rule/Action. Just enable the "Include Source in FileName" Option within the File Logging Action. This will need less ressources.

best regards,
Andre Lorbach

I have sent the e-mail with incident details to the support e-mail address to have a ticket opened.

I have set the debug options as you suggested - Circular (10 logs at 1GB each) and all options checked. Do you want all of the options selected in the debug settings because they seem to be contradicting each other based on the option description. The options currently selected are:
Errors & Warnings
Minimal Debug Output
Informational Debug Output
Ultra Verbose Output
Rule & Filter Engine

With the debug enabled, Winsyslog is definitely using substantially more RAM that it had been previously. Prior to debug being enable, it had been using 9-15 MB of RAM. With debug enabled (and only running for 15 minutes) it is using 400 MB of RAM and is continuing to climb. If there are options that can/should be unchecked to prevent the memory usage from being so high, please let me know.

I will capture the debug output files the next time the issue happens. I imagine it will be this weekend since it has happened on a weekly basis for a while now.

When the support ticket is opened I will send the config information you need.

We use specific rules for each system that we know in advance that is sending syslog to the server. This allows us to define a meaningful name to the logfile. In the rule configuration, all of the "known" source rules occur first and there is a final "catch all" rule that uses the IP address of the sending system in the file name if it has not been processed by any of the earlier rules. This gives us an easy way to see if there are new systems sending logs that we are not aware of.

As I was typing this response the Winsyslog application memory usage climbed to over 1 Gig. I don't think the debug options will work as they are currently set since it continues to use more and more memory. I will need to disable the debug option until I hear from you what options I need to enable to keep the memory usage from being a problem but still get good debug information.

Try to disabled "Rule & Filter Engine" Debug Options, we don't need that Output really.

Maybe it then is able to process your queue in Realtime.

best regards,
Andre Lorbach

The memory usage seems to be stable with that option unchecked. Thanks for the quick reply.

After running both installations with debug logging enabled, one of the servers quickly began to experience the problem. I have collected the debug logs and can provide them via FTP if necessary. Listed below is a log of the activities and observations during this monitoring.



System Time ---> Observation
27 Oct 2005 08:52:00 ---> Winsyslog started with debug logging enabled
27 Oct 2005 09:00:00 ---> winsyslg.exe continues to increase the amount of RAM being used (started at 8 MB, over 200 MB at this time)
27 Oct 2005 09:30:00 ---> winsyslg.exe using all available RAM - 1.5 GB
27 Oct 2005 09:40:00 ---> 27 Oct 2005 09:24:26 (last event written to log by winsyslog rules)
27 Oct 2005 09:40:33 ---> Event Log: EventID 114 - Unknown error while applying the actions - continuing
27 Oct 2005 09:40:33 ---> Event Log: EventID 114 - An unknown exception occured in CInfoSourceSyslog::Run().
27 Oct 2005 09:40:33 ---> Event Log: EventID 114 - Unknown error while applying the actions - continuing
27 Oct 2005 09:40:33 ---> Event Log: EventID 114 - Unknown error while applying the actions - continuing
27 Oct 2005 09:40:33 ---> Event Log: EventID 114 - Unknown error while applying the actions - continuing
27 Oct 2005 09:40:33 ---> Event Log: EventID 114 - Unknown error while applying the actions - continuing
27 Oct 2005 09:40:33 ---> Event Log: EventID 114 - Unknown error while applying the actions - continuing
27 Oct 2005 09:40:33 ---> Event Log: EventID 114 - Unknown error while applying the actions - continuing
27 Oct 2005 09:40:33 ---> Event Log: EventID 114 - Unknown error while applying the actions - continuing
27 Oct 2005 09:40:33 ---> Event Log: EventID 114 - Unknown error while applying the actions - continuing
27 Oct 2005 09:40:33 ---> Event Log: Event ID 151 - Numerous runtime events were encountered. This is usually caused by configuration or network problems. From now, there will no more events logged for this hour.
27 Oct 2005 09:50:00 ---> 27 Oct 2005 09:31:56 (last event written to log by winsyslog rules)
27 Oct 2005 09:58:00 ---> 27 Oct 2005 09:40:31 (last event written to log by winsyslog rules)
27 Oct 2005 10:00:00 ---> 27 Oct 2005 09:40:31 (last event written to log by winsyslog rules)
27 Oct 2005 10:02:00 ---> 27 Oct 2005 09:40:31 (last event written to log by winsyslog rules)
27 Oct 2005 10:02:30 ---> Winsyslog service stopped
27 Oct 2005 10:02:30 ---> Saved debug logs

27 Oct 2005 10:03:30 ---> Restarted Winsyslog service
27 Oct 2005 10:20:00 ---> winsyslg.exe continues to increase the amount of RAM being used (started at 8 MB, over 500 MB at this time)
27 Oct 2005 10:30:00 ---> winsyslg.exe continues to increase the amount of RAM being used (started at 8 MB, over 800 MB at this time)
27 Oct 2005 10:37:00 ---> 27 Oct 2005 10:31:25 (last event written to log by winsyslog rules)
27 Oct 2005 10:40:00 ---> winsyslg.exe continues to increase the amount of RAM being used (started at 8 MB, over 1,330 MB at this time)
27 Oct 2005 10:40:00 ---> 27 Oct 2005 10:33:50 (last event written to log by winsyslog rules)
27 Oct 2005 10:43:00 ---> winsyslg.exe continues to increase the amount of RAM being used (started at 8 MB, over 1,496 MB at this time - all available)
27 Oct 2005 10:43:00 ---> 27 Oct 2005 10:36:27 (last event written to log by winsyslog rules)
27 Oct 2005 10:46:00 ---> 27 Oct 2005 10:37:28 (last event written to log by winsyslog rules)
27 Oct 2005 10:49:00 ---> 27 Oct 2005 10:37:38 (last event written to log by winsyslog rules)
27 Oct 2005 10:51:58 ---> Event Log: EventID 114 - An unknown exception occured in CInfoSourceSyslog::Run().
27 Oct 2005 10:51:58 ---> Event Log: EventID 114 - Unknown error while applying the actions - continuing
27 Oct 2005 10:51:58 ---> Event Log: EventID 114 - Unknown error while applying the actions - continuing
27 Oct 2005 10:51:58 ---> Event Log: EventID 114 - Unknown error while applying the actions - continuing
27 Oct 2005 10:51:58 ---> Event Log: EventID 114 - Unknown error while applying the actions - continuing
27 Oct 2005 10:51:58 ---> Event Log: EventID 114 - Unknown error while applying the actions - continuing
27 Oct 2005 10:51:58 ---> Event Log: EventID 114 - Unknown error while applying the actions - continuing
27 Oct 2005 10:51:58 ---> Event Log: EventID 114 - Unknown error while applying the actions - continuing
27 Oct 2005 10:51:58 ---> Event Log: EventID 114 - Unknown error while applying the actions - continuing
27 Oct 2005 10:51:58 ---> Event Log: EventID 114 - Unknown error while applying the actions - continuing
27 Oct 2005 10:51:58 ---> Event Log: Event ID 151 - Numerous runtime events were encountered. This is usually caused by configuration or network problems. From now, there will no more events logged for this hour.
27 Oct 2005 10:52:00 ---> 27 Oct 2005 10:37:43 (last event written to log by winsyslog rules) - memory usage decreasing as items flushed from RAM
27 Oct 2005 10:56:00 ---> 27 Oct 2005 10:38:50 (last event written to log by winsyslog rules) - memory usage decreasing as items flushed from RAM
27 Oct 2005 10:59:00 ---> 27 Oct 2005 10:41:00 (last event written to log by winsyslog rules) - memory usage decreasing as items flushed from RAM
27 Oct 2005 11:04:00 ---> 27 Oct 2005 10:46:10 (last event written to log by winsyslog rules) - memory usage decreasing as items flushed from RAM
27 Oct 2005 11:06:00 ---> 27 Oct 2005 10:49:40 (last event written to log by winsyslog rules) - memory usage decreasing as items flushed from RAM
27 Oct 2005 11:08:00 ---> 27 Oct 2005 10:51:56 (last event written to log by winsyslog rules) - memory usage stopped decreasing at 43 MB used
27 Oct 2005 11:10:51 ---> Winsyslog service stopped
27 Oct 2005 11:11:00 ---> Saved debug logs

27 Oct 2005 11:11:10 ---> Changed Winsyslog config to not save debug logs
27 Oct 2005 11:11:34 ---> Restarted Winsyslog service
27 Oct 2005 11:13:00 ---> winsyslg.exe using 8 MB of RAM
27 Oct 2005 11:15:00 ---> 27 Oct 2005 11:15:00 (last event written to log by winsyslog rules)
27 Oct 2005 11:27:00 ---> winsyslg.exe using 15 MB of RAM
27 Oct 2005 11:27:00 ---> 27 Oct 2005 11:27:00 (last event written to log by winsyslog rules)
27 Oct 2005 11:50:00 ---> winsyslg.exe using 17 MB of RAM
27 Oct 2005 11:50:00 ---> 27 Oct 2005 11:50:00 (last event written to log by winsyslog rules)
27 Oct 2005 12:11:00 ---> winsyslg.exe using 60 MB of RAM
27 Oct 2005 12:11:00 ---> 27 Oct 2005 12:10:51 (last event written to log by winsyslog rules)
27 Oct 2005 12:20:00 ---> winsyslg.exe using 117 MB of RAM
27 Oct 2005 12:20:00 ---> 27 Oct 2005 12:19:53 (last event written to log by winsyslog rules)
27 Oct 2005 12:31:00 ---> winsyslg.exe using 78 MB of RAM
27 Oct 2005 12:31:00 ---> 27 Oct 2005 12:30:25 (last event written to log by winsyslog rules)
27 Oct 2005 13:00:00 ---> winsyslg.exe using 21 MB of RAM
27 Oct 2005 13:00:00 ---> 27 Oct 2005 13:00:00 (last event written to log by winsyslog rules)

Thanks for the message. Yes, the debug files will most probably contain good information about what is causing this behaviour. Please compress them (zip, rar, tar.gz) and upload them to our anonymous ftp at hetzner.adiscon.com. Be sure to change to the /incoming directory!

As a side-note, the reason for the memory consumption is that debug logging unfortunately takes considerable ressources. As it looks, this slowed WinSyslog down enough so that it needed to buffer messages in its memory queue. Thus the memory went up. Please note that you can limit the queue size in general properties.

Looking forward to the debug log.

Best regards,
Rainer Gerhards
Adiscon

The logs should be available now. By the way - I still have not received any information related to a ticket being opened from the e-mails I sent to support@adiscon.com. I sent the original e-mail on 19 Oct and the second yesterday, 27 Oct.

Let me know if you find that you need other information.

Thanks for the logs, we will analyze them. This could take a little while.

Regarding the tickets, none of them seems to have reached the ticket system. I would appreciate if you could let me know which email address you sent your mail from. This enables us to check the systems.

Rainer

Both e-mail messages would have been from smparcel@aep.com

Hi,

I have received and processed one of your tickets.
Didn't my answer to this ticket?

best regards,
Andre Lorbach

Sorry, I just noticed (by lookup) that yesterday's ticket actually arrived. My co-worker answered a short while ago. Please let me know if you received his reply.

Rainer

Have not seen the reply at this time. I have received all of the notifications (almost instantly) when a reply to the support forum is posted which are originating from SupportForumForwarder@adiscon.com. I will keep an eye open for a reply to the e-mail messages.

OK, we have checked all systems now. Mail destined to your server has left ours and your server response was that it was queued. So there was no fault indication. The transaction from this morning is here:

Oct 28 13:58:39 localhost amavis[28382]: (28382-09) Passed, <pt1@adiscon.com> -> <smparcel@aep.com>, Message-ID: <P15111116GXix4A2Dre00000084@monitorware.de>, Hits: -
Oct 28 13:58:39 localhost postfix/smtp[28881]: 3646627C018: to=<smparcel@aep.com>, relay=127.0.0.1[127.0.0.1], delay=0, status=sent (250 2.6.0 Ok, id=28382-09, from MTA: 250 Ok: queued as 5A53A27C027)
Oct 28 13:58:39 localhost postfix/qmgr[18957]: 3646627C018: removed
Oct 28 13:58:39 localhost postfix/smtpd[28884]: disconnect from localhost[127.0.0.1]
Oct 28 13:58:41 localhost postfix/smtp[28885]: 5A53A27C027: to=<smparcel@aep.com>, relay=mail3.aep.com[161.235.223.208], delay=2, status=sent (250 Ok: queued as 74252D6)

Maybe you can put us in contact with your mail administrator so that we can sort out the issue.

I have just sent another ticket reply a few minutes ago. And I have also seen that the initial ticket was answered, actually by me. Obviously, the reply never reached you...

Rainer