Log to syslog

Erth Paradine · May 13, 2016

Request:
Add support for logging to syslog (Linux & Mac), or EventLog (Windows).

Rationale:

Even when writing to SSDs, various server routines seem to block on logging I/O, and therefore slowdown server response times.
Somewhat of a workaround, is that we've symlinked StarMade/logs/ to /dev/shm/smlogs/ which means logs are now just written into a RAM-based filesystem.
Each respective OS has a standardized central logging function. This includes a means of buffering log writes (so that writing to logs no longer blocks I/O), and a means of moving logging activity off-server.
Sometimes catching a bug requires being able to look further back than 100MB of logs, and the game's built-in log rotation scheme simply deletes this older information.
At least in the unix world, there are very powerful log processing tools such as rsyslog: when a StarMade server bunches everything into just two files, processing such data gets quite complicated. Dealing with things like duplicate entries requires code changes...whereas with syslog support, sever admins have more control over this, without consuming developer resources. For instance, duplicate message suppression, multithreaded logging, support for over a million log entries per second (without crashing the server), buffering, off-server logging, inline parsing, spooling, compression, direct-to-database writes, etc.
After over a month of testing (see below), we've been unable to identify any negative performance impacts when redirecting all existing console output to syslog.

Process:

Perhaps start with a config option that allows for an either/or: enabling owners to select built-in logging or writing to syslog (with a caveat that the server owner MUST also configure adequate log rotation).
Please also ensure that information written to serverlog.txt.0 and log.txt.0, are also written to the console. This is currently not the case.

How:

A few hints on how to do this in code.

Erth Paradine · Jul 31, 2016

Making a few modifications to my original (above) suggestion/request:

Please be more consistent with console and existing file logging.
A month of console output, rotated and compressed daily, consumes less than 600MB of disk space. Our DB+blueprints consumes ~61GB at the moment. Meaning that a month of compressed console output contributes less than 1% to overall disk space requirements.
Overall, after a month of testing, we've found absolutely zero negative impacts from redirecting console's stdout/stderr to syslog.
Other improvements include taking advantage of syslog's many features, such as deduplication of log entries. Without syslog, the below logging behavior would have resulted in 387 lines all showing identical information; a waste of both I/O and disk space, it is SO NICE to see lines like this instead:

Code:

message repeated 387 times: [[AI][SEARCHFORTARGET] either own or target sector not loaded: Sector[31227](2, 2, 2); null]

nightrune · Aug 4, 2016

Logging to syslog would be amazing.

Erth Paradine · Dec 23, 2016

It's about time to update this posting again. We're now at ~6 months of full console output collection, and have not yet once run into issues from it. Total disk consumption: 4.0GB
[doublepost=1482454580,1482452555][/doublepost]Here's how to setup console output logging, on linux, in a non-blocking way. This writeup is being supplied now, due to regular requests for the info. A far more in-depth writeup is pending; detailing how our PAFKA toolkit works...but hopefully this hint helps others sooner.

Disclaimer: If you're not proficient in linux systems administration, don't attempt this. The following is being provided without any promise of followup support (and it's certainly NOT officially supported by Schine). However StarBits has been doing this for 6+ months without a single negative issue; performance, or otherwise. Ultimately, if you break something, you get to keep both pieces and may only blame yourself.

As best I can recall, from notes, logs, and memory...do as follows:

You must be running SM on a Linux system, with rsyslog. For the following, I'm assuming you're running CentOS 6.

StarMade can generate hundreds of log lines per second, so you must configure syslog to accommodate this higher than normal logging volume. Don't worry though, unless your underlying server is grossly underpowered for a SM instance, syslog handles this kind of log volume with ease, it's just not a default configuration.

Adjust /etc/rsyslog.conf to accomidate:

Code:

$SystemLogRateLimitInterval 0
$SystemLogRateLimitBurst 0
$RepeatedMsgReduction on  # Stop repeating the same messages
$IMJournalStateFile imjournal.state
$IMJournalRatelimitInterval 0
$IMUXSockRateLimitInterval 0

Create the file /etc/rsyslog.d/starmade.conf and put the following into it:

Code:

#Ignores server noise that's already configured to no longer appear in dev instances.
:msg, contains, "[AI] Not Roaming while in conversation" ~
:msg, contains, "[SERVER][RAIL] collision time limit reached. Returning to last possible" ~
:msg, contains, "EFFECT IS NOT CUTTENTLY ACTIVE null" ~

# Catch SMPrd-tagged syslog entries, and log to unique file
:syslogtag, isequal, "SMPrd:"    -/var/log/starmade.log
& stop

Setup automatic daily log rotation, or you WILL run out of disk space (daily logs, uncompressed, can reach well beyond 5GB. Once compressed...6 months of logs consumes a mere 4GB on a fairly-popular server. Do this by creating a at /etc/logrotate.d/starmade, with the following contents:
Code:
```
/var/log/starmade.log {
        daily
        missingok
        rotate 365
        compress
        delaycompress
        notifempty
        sharedscripts
        postrotate
        /bin/kill -HUP `cat /var/run/syslogd.pid 2> /dev/null` 2> /dev/null || true
        endscript
}
```
Configure your StarMade launcher command, to redirect stdout/stderr to syslog, with the relevant tag:
Code:
```
java -jar ./StarMade-Starter.jar -nogui |& logger -t SMPrd
```

That's it. When your SM instance is next launched using the above command, you'll no longer see any console output, and instead syslog will capture and record to /var/log/starmade.log

While this will work fine for screen-based instances, we actually use tmux due to some additional features leveraged for StarBit's PAFKA toolkit. Details will be discussed in a separate, more relevant, posting.

CHANGELOG:
11FEB2017: switched syslog daemon recommendation from syslog-ng to rsyslog.

Benevolent27 · Feb 11, 2017

Erth Paradine said:
It's about time to update this posting again. We're now at ~6 months of full console output collection, and have not yet once run into issues from it. Total disk consumption: 4.0GB
[doublepost=1482454580,1482452555][/doublepost]Here's how to setup console output logging, on linux, in a non-blocking way. This writeup is being supplied now, due to regular requests for the info. A far more in-depth writeup is pending; detailing how our PAFKA toolkit works...but hopefully this hint helps others sooner.

Disclaimer: If you're not proficient in linux systems administration, don't attempt this. The following is being provided without any promise of followup support (and it's certainly NOT officially supported by Schine). However StarBits has been doing this for 6+ months without a single negative issue; performance, or otherwise. Ultimately, if you break something, you get to keep both pieces and may only blame yourself.

As best I can recall, from notes, logs, and memory...do as follows:

You must be running SM on a Linux system, with syslog-ng. For the following, I'm assuming you're running CentOS 6.

StarMade can generate hundreds of log lines per second, so you must configure syslog to accommodate this higher than normal logging volume. Don't worry though, unless your underlying server is grossly underpowered for a SM instance, syslog handles this kind of log volume with ease, it's just not a default configuration.

Adjust /etc/rsyslog.conf to accomidate:

Code:

$SystemLogRateLimitInterval 0 $SystemLogRateLimitBurst 0 $RepeatedMsgReduction on # Stop repeating the same messages $IMJournalStateFile imjournal.state $IMJournalRatelimitInterval 0 $IMUXSockRateLimitInterval 0

Create the file /etc/rsyslog.d/starmade.conf and put the following into it:

Code:

#Ignores server noise that's already configured to no longer appear in dev instances. :msg, contains, "[AI] Not Roaming while in conversation" ~ :msg, contains, "[SERVER][RAIL] collision time limit reached. Returning to last possible" ~ :msg, contains, "EFFECT IS NOT CUTTENTLY ACTIVE null" ~ # Catch SMPrd-tagged syslog entries, and log to unique file :syslogtag, isequal, "SMPrd:" -/var/log/starmade.log & stop

Setup automatic daily log rotation, or you WILL run out of disk space (daily logs, uncompressed, can reach well beyond 5GB. Once compressed...6 months of logs consumes a mere 4GB on a fairly-popular server. Do this by creating a at /etc/logrotate.d/starmade, with the following contents:

Code:

/var/log/starmade.log { daily missingok rotate 365 compress delaycompress notifempty sharedscripts postrotate /bin/kill -HUP `cat /var/run/syslogd.pid 2> /dev/null` 2> /dev/null || true endscript }

Configure your StarMade launcher command, to redirect stdout/stderr to syslog, with the relevant tag:

Code:

java -jar ./StarMade-Starter.jar -nogui |& logger -t SMPrd

That's it. When your SM instance is next launched using the above command, you'll no longer see any console output, and instead syslog will capture and record to /var/log/starmade.log

While this will work fine for screen-based instances, we actually use tmux due to some additional features leveraged for StarBit's PAFKA toolkit. Details will be discussed in a separate, more relevant, posting.

I just now saw this! I was going to make a post for better log management, and this seems to fit the bill more expertly than I would have put it!

You get full support from me on this idea. I will be trying it out too!

Benevolent27 · Feb 11, 2017

I'm on Ubuntu here. I'll post my install log for the benefit of others (plus because I ran into some issues):
- To install syslog-ng, I followed the instructions here: Basic syslog-ng Installation (pretty straightforward apt-get, though users of Ubuntu 14 need to follow a slightly different path)
- When editing the rsyslog.conf, the "$RepeatedMsgReduction" flag was already set correctly, so I just added a little "ErthParadine" section with the others, excluding that option.

Now, I see you have "java -jar ./StarMade-Starter.jar -nogui |& logger -t SMPrd" as the command. I use a custom script which will auto-restart the server if it crashes (since sometimes we may be sleeping when something like this happens). This runs in a screen. We also have scripting for our wrapper that needs to send commands directly to the console, which is running in a screen. So, I made a duplicate install and tried just running the script in place of "java -jar ./StarMade-Starter.jar -nogui". As expected, no console output, but I typed in a command and it worked! Yipee! So it looks like this will work with our existing setup! Yay!

Edit: The rest of this post is now defunct because an issue with the original post has been fixed.

However, I ran into some issues. I tried to read the output of the file, "/var/log/starmade.log" but it does not exist. Here are the troubleshooting steps I ran:
- I ran a status on the syslog-ng and it seemed to be running (Command: sudo service syslog-ng status).
- I went over to "/var/log" and noticed a "syslog" file. I ran a tail of it. It seems to have the output of the server in there, but alas, no starmade.log file exists. Also, this file requires root permissions, which is problematic, since our server runs on a non-elevated user and I also would not want to parse system data.
- I tried restarting the syslog-ng service (command: sudo service syslog-ng restart) and then starting the server again. No change.
- I verified that all the changes proscribed above were done, and yep. They were.
- "/etc/rsyslog.conf" contains all the needed parameters and contains no typos.
- "/etc/rsyslog.d/starmade.conf" exists and contains the needed text, with no typos.
- "/etc/logrotate.d/starmade" exists and contains the needed text, with no typos.
- I tried googling the issue and found myself trapped inside giant, massive tutorials which spanned hundreds and hundreds of pages of irrelevant and technically named chapters. I believe I would need a degree in logging before I could even make sense of all this.

So, I will continue to troubleshoot here, but if you have an easy answer, I am all ears. I grabbed the version info of syslog-ng (Command: syslog-ng --version) and here is the output:

Code:

syslog-ng 3.5.6 Installer-Version: 3.5.6 Revision: 3.5.6-2.1 [@416d315] (Ubuntu/16.04) Compile-Date: Oct 24 2015 03:49:19 Available-Modules: afmongodb,csvparser,afsocket,syslogformat,afuser,tfgeoip,linux-kmsg-format,afprog,affile,dbparser,basicfuncs,redis,afsocket-notls,afamqp,afsmtp,confgen,cryptofuncs,afstomp,system-source,afsocket-tls,json-plugin,afsql Enable-Debug: off Enable-GProf: off Enable-Memtrace: off Enable-IPv6: on Enable-Spoof-Source: on Enable-TCP-Wrapper: on Enable-Linux-Caps: on Enable-Pcre: on

Thanks again for your valuable contributions to the StarMade community.

Edit: While playing around with this, I was reading on the man page for logger that the "-s" flag can be used to also display the output to stderr. I tried it, and hey! My console is sending the logging data to syslog-ng and also displays on the console as normal! You may want to consider using this flag in the command, changing it to:

Code:

java -jar ./StarMade-Starter.jar -nogui |& logger -s -t SMPrd

Edit2: Futher troubleshooting.
- I tried renaming the starmade.conf, located in "/etc/rsyslog.d" to "10-starmade.conf," since apparently it processes the configurations in order, so this should put it ahead of the default configuration. This didn't work.
-So I renamed it to 60-starmade.conf, to put it in a later order, after the default configurations. No dice.
- I tried reformatting the code to look like this:

Code:

#Ignores server noise that's already configured to no longer appear in dev instances. if $msg contains '[AI] Not Roaming while in conversation' ~ if $msg contains '[SERVER][RAIL] collision time limit reached. Returning to last possible' ~ if $msg contains 'EFFECT IS NOT CUTTENTLY ACTIVE null' ~ # Catch SMPrd-tagged syslog entries, and log to unique file if $syslogtag == 'SMPrd:' then -/var/log/starmade.log & ~

No dice.

So, I am going back to square one and I'll see about reading some tutorials on how to get a program to log to syslog-ng and let's hope I can find one that isn't over 100 pages long that contains 99.9% irrelevant details.

Benevolent27 · Feb 11, 2017

Edit: The original post had an issue which has now been fixed. The following information is how to configure syslog-ng to perform output of all text from the console, not rsyslog. I will leave this for posterity and perhaps as an alternative to rsyslog. One thing that I noticed is that syslog-ng allows easier permissions settings for individual log files. On our server, we run the server on a non-elevated user, so this is important that the non-sudo user be able to read the output.

Hokay, so after banging my head on the while trying to figure out why things weren't working, I figured out how to do the filtering with syslog-ng.

I created a file, "/etc/syslog-ng/conf.d/starmade.conf", with the following code:

Code:

options {
        owner(starmade); # This is the name of the user that the starmade server runs under
        group(starmade); # same as above
        perm(0640); # Sets permission to read/write by owner only
};

destination d_starmade {
        file("/home/starmade/logs/console/starmade.log"); # This can be changed to wherever it needs to be
};

filter f_starmade {
        # FYI:  The filter, "tags" does not appear to work.  The match command includes the tag, so this workaround worked.
        match(^SMPrd.*)
};

log {
        source(s_src);
        filter(f_starmade);
        destination(d_starmade);
};

Then I restarted syslog-ng with the command, "sudo service syslog-ng restart".
I ran my custom starter script "./StarMade-dedicated-server-linux-autorestart.sh |& logger -s -t SMPrd". Voila! It now outputs to the log, displays the text in the console, and has the permissions set that I'd like! Yipee! I also changed "/etc/logrotate.d/starmade" to point to the correct file so I hope it will keep it clean. Where it compresses though, I do not know.. hmm..

Next I gotta figure out if the changes to "/etc/rsyslog.conf" are being used for the high volume, or if any different action may be necessary for the high volume. I also gotta figure out the correct way to do the excludes for those spam messages like "EFFECT IS NOT CUTTENTLY ACTIVE null". I'm guessing I just add to the filter, "AND NOT message(".*EFFECT IS NOT CUTTENTLY ACTIVE null.*"), but I have company over and need to test this.

Erth Paradine · Feb 11, 2017

Benevolent27 said:
....

Code:

java -jar ./StarMade-Starter.jar -nogui |& logger -s -t SMPrd

Edit2: Futher troubleshooting.
- I tried renaming the starmade.conf, located in "/etc/rsyslog.d" to "10-starmade.conf," since apparently it processes the configurations in order, so this should put it ahead of the default configuration. This didn't work.
-So I renamed it to 60-starmade.conf, to put it in a later order, after the default configurations. No dice.
- I tried reformatting the code to look like this:

Code:

#Ignores server noise that's already configured to no longer appear in dev instances. if $msg contains '[AI] Not Roaming while in conversation' ~ if $msg contains '[SERVER][RAIL] collision time limit reached. Returning to last possible' ~ if $msg contains 'EFFECT IS NOT CUTTENTLY ACTIVE null' ~ # Catch SMPrd-tagged syslog entries, and log to unique file if $syslogtag == 'SMPrd:' then -/var/log/starmade.log & ~

No dice.

Well, crap...why did I suggest syslog-ng when I clearly reverted to rsyslog instead (e.g. based upon suggested config). Argh! I'm editing my original posting to clarify.

Exact contents of my production config (works great w/ rsyslog):

Code:

:msg, contains, "[AI] Not Roaming while in conversation" ~
:msg, contains, "[SERVER][RAIL] collision time limit reached. Returning to last possible" ~
:msg, contains, "EFFECT IS NOT CUTTENTLY ACTIVE null" ~

:syslogtag, isequal, "SMPrd:"    -/var/log/starmade.log
& stop

Benevolent27 · Feb 12, 2017

Erth Paradine said:
Well, crap...why did I suggest syslog-ng when I clearly reverted to rsyslog instead (e.g. based upon suggested config). Argh! I'm editing my original posting to clarify.

Exact contents of my production config (works great w/ rsyslog):

Code:

:msg, contains, "[AI] Not Roaming while in conversation" ~ :msg, contains, "[SERVER][RAIL] collision time limit reached. Returning to last possible" ~ :msg, contains, "EFFECT IS NOT CUTTENTLY ACTIVE null" ~ :syslogtag, isequal, "SMPrd:" -/var/log/starmade.log & stop

lol! Thank you for your response.

I thought maybe syslog-ng took over the functions of rsyslog and/or worked alongside it, grabbing settings from it! haha. I did consider the possibility that perhaps they really were two distinct programs, which operate independently, and maybe you were mistaken.. but I didn't want to think that.. lol. But this is why I figured out how to set up syslog-ng. haha. Though I will probably continue with syslog-ng for now because I like how you can easily set the user and permissions for the individual configuration file. Now to see if it can handle the volume of this output. If not, I will switch on over to rsyslog and figure that out, though for that I had some difficulty figuring out how to set the permissions of the resulting output file, without changing the permissions for ALL output log files.

Erth Paradine · Feb 12, 2017

Benevolent27 said:
lol! Thank you for your response.

I thought maybe syslog-ng took over the functions of rsyslog and/or worked alongside it, grabbing settings from it! haha. I did consider the possibility that perhaps they really were two distinct programs, which operate independently, and maybe you were mistaken.. but I didn't want to think that.. lol. But this is why I figured out how to set up syslog-ng. haha. Though I will probably continue with syslog-ng for now because I like how you can easily set the user and permissions for the individual configuration file. Now to see if it can handle the volume of this output. If not, I will switch on over to rsyslog and figure that out, though for that I had some difficulty figuring out how to set the permissions of the resulting output file, without changing the permissions for ALL output log files.

syslog-ng is supposed to perform even better than rsyslog, which I presume is how syslog-ng got into my build/config notes, as I would have been looking for the best-performing tools during the initial sketch-out phase of our PAFKA project. Ultimately though, we ended up sticking with the system's stock rsyslog daemon, as it continues to smoothly handle logging traffic (with the appropriate config/rate-liming tweaks of-course).

Happy to hear you found some utility in syslog-ng too.

Benevolent27 · Feb 13, 2017

Erth Paradine said:
syslog-ng is supposed to perform even better than rsyslog, which I presume is how syslog-ng got into my build/config notes, as I would have been looking for the best-performing tools during the initial sketch-out phase of our PAFKA project. Ultimately though, we ended up sticking with the system's stock rsyslog daemon, as it continues to smoothly handle logging traffic (with the appropriate config/rate-liming tweaks of-course).

Happy to hear you found some utility in syslog-ng too.

Do you think I'll need to set these for syslog-ng too?

Code:

$SystemLogRateLimitInterval 0
$SystemLogRateLimitBurst 0
$RepeatedMsgReduction on  # Stop repeating the same messages
$IMJournalStateFile imjournal.state
$IMJournalRatelimitInterval 0
$IMUXSockRateLimitInterval 0

If so, would I just plop the same code into the "/etc/syslog-ng/syslog-ng.conf" file?

Erth Paradine · Feb 13, 2017

Benevolent27 said:
Do you think I'll need to set these for syslog-ng too?

Code:

$SystemLogRateLimitInterval 0 $SystemLogRateLimitBurst 0 $RepeatedMsgReduction on # Stop repeating the same messages $IMJournalStateFile imjournal.state $IMJournalRatelimitInterval 0 $IMUXSockRateLimitInterval 0

If so, would I just plop the same code into the "/etc/syslog-ng/syslog-ng.conf" file?

I don't know. What I can tell you though, is that rsyslog will report both when suppressing duplicates, and rate-limiting. So if I were doing it, I'd start syslog-ng at defaults, while watching for similar reports.

Benevolent27 · Mar 23, 2017

Erth Paradine said:
I don't know. What I can tell you though, is that rsyslog will report both when suppressing duplicates, and rate-limiting. So if I were doing it, I'd start syslog-ng at defaults, while watching for similar reports.

So, I had to disable the logging. The logs were being duplicated to multiple places in the "/var/log/syslog" folder and it ate up every bit of hard drive space allocated to the OS, which was creating some rather interesting problems. I had to delete the "messages" and "syslog" files, which were duplicating all the output, and took up tens of gigs of space. I'll need to figure out a way to isolate where the output goes, or otherwise abandon this method.

I think perhaps I will either use tail on the log file to duplicate it, or pipe to tee to create an output log of the console (while retaining the stdout), and see how this affects performance. I figure duplicating the log file won't cause interference with the server, but piping the console output to tee may very well cause problems.

Erth Paradine · Mar 26, 2017

Benevolent27 said:
So, I had to disable the logging. The logs were being duplicated to multiple places in the "/var/log/syslog" folder and it ate up every bit of hard drive space allocated to the OS, which was creating some rather interesting problems. I had to delete the "messages" and "syslog" files, which were duplicating all the output, and took up tens of gigs of space. I'll need to figure out a way to isolate where the output goes, or otherwise abandon this method.

I think perhaps I will either use tail on the log file to duplicate it, or pipe to tee to create an output log of the console (while retaining the stdout), and see how this affects performance. I figure duplicating the log file won't cause interference with the server, but piping the console output to tee may very well cause problems.

That's an odd issue, I'd certainly encourage leveraging syslog's built-in filtering mechanisms, as StarBits currently has ALL console logs dating back 269 days, and total disk space consumed is 4GB:

Code:

~$ du -hsc /var/log/starmade.* |tail -n 1
4.0G    total
~$ ls -l /var/log/starmade.* |wc -l
269

The file /etc/rsyslog.d/starmade.conf documented above, is still the only filter we have in place.

Benevolent27 · Mar 29, 2017

Erth Paradine said:
That's an odd issue, I'd certainly encourage leveraging syslog's built-in filtering mechanisms, as StarBits currently has ALL console logs dating back 269 days, and total disk space consumed is 4GB:

Code:

~$ du -hsc /var/log/starmade.* |tail -n 1 4.0G total ~$ ls -l /var/log/starmade.* |wc -l 269

The file /etc/rsyslog.d/starmade.conf documented above, is still the only filter we have in place.

Yeah, you guys have the filtering set up with rsyslog, but I haven't had the time to figure out how to do it with syslog-ng yet, so I'm putting the project on hold for now. Or I could uninstall syslog-ng and switch to rsyslog. lol

Search

Log to syslog

Erth Paradine

Server Admln & Bug Reporter

Erth Paradine

Server Admln & Bug Reporter

nightrune

Wizard/Developer/Project Manager

Erth Paradine

Server Admln & Bug Reporter

Benevolent27

Join the Dark Side

Benevolent27

Join the Dark Side

Benevolent27

Join the Dark Side

Erth Paradine

Server Admln & Bug Reporter

Benevolent27

Join the Dark Side

Erth Paradine

Server Admln & Bug Reporter

Benevolent27

Join the Dark Side

Erth Paradine

Server Admln & Bug Reporter

Benevolent27

Join the Dark Side

Erth Paradine

Server Admln & Bug Reporter

Benevolent27

Join the Dark Side