null characters at the beginning of an ASCII log file

Question

We have an java application that log4j2 to generate log file and have script to stop the process before restart it with another script. There is 5 minutes pause between stop and restart at the midnight daily. In the startup script, we use "mv" command to rename the log file with timstamp as extension. The issue is that one of the log file contains null characters( a few MB) at the beginning of the file and the log file becomes binary. a few observation notes to provide more context for this issue: 1.- Same startup script was used in other hosts with identical version of the java application. Don't have this issue at all. 2.- Occured occasionally. Ie., one week all 5 log files get corrupted and another week the log files are fine. 3.- Can not reproduce in similar developer Linux host; only in production Linux host. 4.- Size of the log file typically is about 4 - 6 GB daily. 5.- The application will be stop + 5 minutes pause + start by script at midnight daily. 6.- Used the hexdump to peek into the content of the binary log file. It had a few MB of null characters at the beginning and then followed by the normal typical ASCII content.

any suggestions will be appreciated. Thanks!

Answer 1

When you look at the size of the "binary" log file with ls -l and compare it to the size you'll get with du -k, you'll probably notice something interesting: the file seems to be bigger than the space it occupies on the disk!

You might have had a second copy of that java application process running, or the production application just sometimes takes more than 5 minutes to complete its shutdown.

So when the null characters appear, there is still an application process running that remembers where its previous write to the log file was. It opens the file for writing, seek()s to that location, and writes its log message. Just as usual.

But if the file was not there before (because it was mv'd away), that's exactly how you generate a sparse file. This is a very old Unix filesystem feature.

A sparse file is essentially the simplest prototype of data compression: whole disk blocks that only contain null bytes are not actually stored on the disk as data, but the filesystem metadata that tells the system where the blocks of the file are located will just get a special mark that effectively says "insert X blocks of null bytes at this file position".

You create a sparse file by opening a file for writing, then seeking beyond the current end-of-file without actually writing anything and then writing something. Most Unix-style filesystems will automatically add the blocks between the old EOF and the newly-written data as sparse blocks, instead of explicitly the intervening writing blocks of nulls to the disk. When you read the file, the filesystem driver will automatically fill in the sparse blocks as blocks of null bytes, so applications don't have to be aware of this at all.

You might want to add a test to your application startup script to use fuser to see if the log file is already open, and stop with an error message if it is. Something like this:

LOGFILE=/some/where/log4j2.log

if fuser -s $LOGFILE; then
    echo "ERROR: $LOGFILE is still in use. Maybe the app is still running. Make it stop." >&2
    exit 1
fi

# add here your commands to rotate the logs and start the application.

log4j2 actually has its own facilities for log file rotation: the best solution would probably be to use those instead of using an external script.