Thursday, 2 July 2015

Logging compendium

Here follow some thoughts on how best to do application logging; they are very Java-centric and primarily based on my experience and various source of information googled along the way.


Use log4j2/logback/name-your-modern-logging-framework

As soon as you can, move to a newer logging framework. Modern API/frameworks have higher performance, have a better API and more useful features.
I have settled for log4j2 although I use it via slf4j - for historic reasons. But others may do well too (namely logback!).

Use logOnce technique

When a LOG statement is in a loop and (a) that loop is infinite or (b) has the potential to be running many times, there's a risk to spam the log messages with the same entry on and on.

This could make the file grow indefinitely making it hard to read/analyse; it may also roll over causing loss of important logged information.

The logOnce technique prevents these nasty side effect and it works as following:

  1. define a special logger L that logs a log entry.
  2. log a message within a loop using the logger L, remember the last logged message
  3. next time you need to log on the same logger, the new message with the last logged message.
  4. if matches skip the statement log; if not go back to step 2.
Variations include
  • match new log statements using regex to allow for differences in some dynamic data
  • log every N entry: even if the new line matches the last logged line, log every N occurrences
  • record some metrics - like number of occurrences logged/skipped etc
Examples where you want to use this pattern are:
  • scheduled threads like Heartbeats
  • Log statements occurring in a for/while loop or recursive functions. especially when logs are on high log levels like ERROR or WARN

Other implementation details

  • Logging statements must be side effect free. Besides appending the statement to the configured appender, a LOG statement MUSTN'T change the internal application state.
  • Make sure that a log actually happens: either log BEFORE the action Or try { action } finally { LOG after } to make sure the LOG after always happens.
In a distributed application, make sure that
  • all nodes share the same wall clock - use NTP to sync
  • all applications share the same configuration; or at least the same message pattern layout.

Log levels

Logs *are* a user interface. And, as such, they deserve the right attention to details... (Yeah, right!)...

At a basic level I personally group INFO and above as forming Administration/Support user interfaces to the system runtime logs.

  • ERROR (aliases severe/fatal): for messages that need to be looked at immediately because a transaction or part of the system is in an un-recoverable state (albeit temporary).
  • WARN : for messages that need to be looked at immediately because a transaction or part of the system is went wrong but managed to recover.
  • INFO: descriptive messages about a meaningful system transaction happened. Or for long transactions start/stop.
On the other end, below INFO is for Developers.
  • DEBUG (alias fine): follow system transactions' execution with the intention of reporting the runtime flow.
  • TRACE (alias finer/finest): uber-details - to report application state or transmitted data, etc.
In essence, a support person looking at the logs should be able to determine whether an application transaction has occurred and what the final execution state is just by having INFO on.

Developers should be able to diagnose went on/wrong by looking at the DEBUG trace. That's why it is important to be able to simply turn DEBUG on/off possibly selectively per Logger or group of loggers.

Traces should only be used during development and never in production.


Experiment with Markers to provide a better partition of logs depending on application specific contexts.


For transactions spawning across several threads in the same process OR different processes in the same host OR different apps in different hosts it's important that
  • Each log entry, in each file reports some ID to trace back the transaction
  • For example an operation starting from a browser client and going via a web services layer, consuming various microservices and/or middleware components should ideally report a single transaction id in all systems.
Provide a diagnostic context where appropriate to propagate internal state of a thread/process across other systems.
  • Speeds up diagnostics because it won't require trawling multiple files, dispersed in various locations
Log a single transaction contextual message in a single LOG line

Separate concerns by delegation and composition.

  • If you're logging latency of code blocks or entry/exit of code blocks, don't clutter the block, rather create a wrapper and use the wrapper (or use AOP)
Log different concerns in different files. For example
  • traffic data should go on a file,
  • application logs on another,
  • performance and metrics on another.
Link log entries with a common transaction ID.

NEVER log the same log entry in two different parts of the code.

NEVER log an entry in multiple lines (caveat informational banners etc)

You should never log at INF/ERR/WRN inside utility function or classes: let the caller log within the context of the application.


Antipattern 1 - Have to log caller class and line number
If you find the need to log the caller's file name and line number, something's wrong with your log OR with your pattern layout. Logging caller file and line number is very inefficient.

Antipattern 2 - Need to write a custom log file parser
If you find the need to write a parser to parse the logs, somethings wrong with your logs or with the way you use logs. Possible causes include:

  • You're logging too much and - for a given transaction - you cant work out what's going on
  • Your logs are too complex to read (Log statement don't have a constant and predictable format or are split in multiple lines - which will make writing the parser hard anyway)
  • You are using log files where you should instead use a proper "inter process communication" mechanism, or a proper auditing mechanism, etc
You should always get away with grep/awk/sed/tail - which are common tools in every platform.

Antipattern 3 - DEBUG (or even TRACE) has to be turned ON in production.
Your logs suck. The system performances will be degraded and you'll spend your days staring at your screen trying to figure out what's going on... the classic needle in the haystack.

Monday, 13 April 2015

Minecraft server on a Synology NAS

It had to happen - my son "requires" a Minecraft server! One of those things... I have installed mine on my Synology 415play following these instructions.
These instructions worked for me, and may not work for you. They are "AS IS" and I accept NO RESPONSIBILITY WHATSOEVER for any loss or damage to your data or functionality. You have been warned.
Also: these are unsupported... if something doesn't work for you, you'll have to fix it yourself.



The "Java Manager" package must be installed. You can install it via the Package Manager, under "Utilities". 
Once the package is installed, the JVM will be located at


Terminal access

Enable terminal access via "Control Panel", "Terminal & SNMP". Then check "Enable SSH service" on port 22. Now you may need a SSH client, like PuTTY and connect to your NAS.

Manual installation

Create user

Create a user to run minecraft server as. To do so, I found easier to edit /etc/passwd and append the following line
minecraft:x:25565:100:Minecraft Server:/volume1/minecraft:/sbin/nologin

Create the server directory and download the server

I decided to put the server directory in /volume1/minecraft
mkdir /volume1/minecraft
 cd /volume1/minecraft  
Note that the server version may change in the future. Check the latest version of the multiplayer server from Mojang's website

Create the start script

I am using a script to run the server. Use your favourite editor to create a file in /volume1/minecraft/ with this content
 cd /volume1/minecraft
/var/packages/JavaManager/target/Java/bin/java -Xmx1024M -Xms1024M -jar /volume1/minecraft/minecraft_server.1.8.3.jar -o true -d64 nogui
chown minecraft:users
chmod 755

Run the server

cd /volume1/minecraft

The first run will start the server and stop it straight away. In fact you need now to edit the eula.txt and "accept" as per instructions.
Re-run the script and the server should now start successfully. You can now try to connect your minecraft client.

Automatic start/stop

Create the file "/etc/init/minecraft.conf" with this content: 

description "start minecraft server"
author "smartrics"
console log
start on syno.share.ready and

stop on runlevel [06]

setuid minecraft

pre-start script
    echo "netatalk start" || true
    date || true
    if [ ! -x /volume1/minecraft/ ]; then
      stop; exit 1
end script

    exec /volume1/minecraft/
end script

post-stop script
    echo "minecraft server stop" || true
    date || true
    rm -f /var/run/
end script

Then the server can simply be started/stopped with 

start minecraft
stop minecraft

and automatically be started at the next NAS reboot.

Check that service is running

If the server is running, this command
ps -w | grep minecraft
should show something similar to
 4735 minecraf  3768 S    /bin/sh /volume1/minecraft/
 4737 minecraf 1188m S    /var/packages/JavaManager/target/Java/bin/java -Xmx1024M -Xms1024M -jar /volume1/minecraft/minecraft_serv