Basic Logging

Introduction

This page describes the basic logging function provided by Alluxio server processes (e.g., masters, workers and etc) and application processes utilizing Alluxio clients (e.g., Spark or MapReduce jobs running on Alluxio). Note that there is an experimental feature that streams server-side and client-side logs to separate Alluxio logservers (see remote logging for more details).

Alluxio logging is implemented using log4j and thus most of the configuration is done through modifying log4j.properties.

Log Location

Server Logs

Log files for each individual Alluxio server process (e.g., master, worker, FUSE, proxy) can be found under ${ALLUXIO_HOME}/logs/. Files suffixed with .log like master.log or worker.log are generated by log4j, logging the events that Alluxio system is recording through JVM. These files are typically the main target for users to investigate logs. Files suffixed with .out like master.out or worker.out are the redirection of stdout and stderr of the corresponding process, typically empty unless fatal error happens (e.g., killed by operating system).

The log location can be customized by setting environment variable ALLUXIO_LOGS_DIR or appending alluxio.logs.dir property through JVM properties (e.g. ALLUXIO_JAVA_OPTS+=" -Dalluxio.logs.dir=/foo") See the configuration settings page for more information.

By default, the *.log files rotate. For example this is the default log4j configuration for master.log:

# Appender for Master
log4j.appender.MASTER_LOGGER=org.apache.log4j.RollingFileAppender
log4j.appender.MASTER_LOGGER.File=${alluxio.logs.dir}/master.log
log4j.appender.MASTER_LOGGER.MaxFileSize=10MB
log4j.appender.MASTER_LOGGER.MaxBackupIndex=100
log4j.appender.MASTER_LOGGER.layout=org.apache.log4j.PatternLayout
log4j.appender.MASTER_LOGGER.layout.ConversionPattern=%d{ISO8601} %-5p %c{1} - %m%n

However, the *.out files do not rotate. So it makes sense to regularly check the size of these files, and clean them up if necessary.

Application Logs

Log files for the Alluxio client utilized by different applications are located with their respective application logs. Please check out particular compute frameworks on where their logs may be found.

Here are the documentation to configure individual application logs including Apache Hadoop, Apache HBase, Apache Hive, Apache Spark.

Configuring Log Levels

Alluxio uses the following five logging levels:

• TRACE: verbose information, only useful for debugging a certain method or class
• DEBUG: fine-grained information, most useful for debugging purpose.
• INFO: messages that highlight the status of progress.
• WARN: potentially harmful events that users may need to know but the process will still continue running.
• ERROR: system errors that users should pay attention to.

By default, Alluxio server processes write logs at level INFO, which includes all events at level INFO, WARN and ERROR.

Modifying Logging with log4j.properties

You can modify ${ALLUXIO_HOME}/conf/log4j.properties to customize logging levels and restart corresponding server processes.

For example, to modify the level for all logs to DEBUG, change the rootLogger level by modifying the first line of log4j.properties as the following:

log4j.rootLogger=DEBUG, ${alluxio.logger.type}, ${alluxio.remote.logger.type}

To modify the logging level for a particular Java class (e.g., set alluxio.client.file.AlluxioFileInStream to DEBUG), add a new line in the end of this file:

log4j.logger.alluxio.client.file.AlluxioFileInStream=DEBUG

Modifying Server Logging at Runtime

It is recommended to modify the log4j.properties file, however if there is a need to modify logging parameters without stopping nodes in the cluster, then you may modify some parameters at runtime.

The Alluxio shell comes with a logLevel command that returns the current value of or updates the log level of a particular class on specific instances. Users are able to change Alluxio server-side log levels at runtime. See the logLevel command documentation for the command options.

For example, the following command sets the logger level of the class alluxio.underfs.hdfs.HdfsUnderFileSystem to DEBUG on master as well as a worker at 192.168.100.100:30000:

$ ./bin/alluxio logLevel --logName=alluxio.underfs.hdfs.HdfsUnderFileSystem \
  --target=master,192.168.100.100:30000 --level=DEBUG

And the following command returns the log level of the class alluxio.underfs.hdfs.HdfsUnderFileSystem among all the workers:

$ ./bin/alluxio logLevel --logName=alluxio.underfs.hdfs.HdfsUnderFileSystem --target=workers

You can also update the log level at a package level. For example, you can update the log level of all classes in alluxio.underfs package with the following command:

$ ./bin/alluxio logLevel --logName=alluxio.underfs --target=workers --level=DEBUG

This works because log4j loggers will inherit the log level from their ancestors. In this case alluxio.underfs.hdfs.HdfsUnderFileSystem inherits the log level if it is set on alluxio.underfs or alluxio.underfs.hdfs.

Furthermore, you can turn on Alluxio debug logging when you are troubleshooting a certain issue in a running cluster, and turn it off when you are done.

# Turn on Alluxio debug logging and start debugging
$ ./bin/alluxio logLevel --logName=alluxio --level=DEBUG
# Turn off Alluxio debug logging when you are done
$ ./bin/alluxio logLevel --logName=alluxio --level=INFO

Enabling Advanced Logging

Logging JVM GC (Garbage Collection) events

Add the following line to conf/allulxio-env.sh to enable logging GC events for server processes in log files with .out suffix like master.out and worker.out:

ALLUXIO_JAVA_OPTS+=" -XX:+PrintGCDetails -XX:+PrintTenuringDistribution -XX:+PrintGCTimeStamps"

ALLUXIO_JAVA_OPTS is included in Java VM options for all Alluxio server processes. Alternatively, modify ALLUXIO_MASTER_JAVA_OPTS, ALLUXIO_WORKER_JAVA_OPTS to turn on GC for each individual process.

Logging all FUSE API calls

Set in conf/log4j.properties:

log4j.logger.alluxio.fuse.AlluxioFuseFileSystem=DEBUG

You will see debug logs at the beginning and the end of each FUSE API call with its arguments and result in logs/fuse.log:

2020-03-03 14:33:35,129 DEBUG AlluxioFuseFileSystem - Enter: chmod(path=/aaa,mode=100644)
2020-03-03 14:33:35,131 DEBUG AlluxioFuseFileSystem - Exit (0): chmod(path=/aaa,mode=100644) in 2 ms
2020-03-03 14:33:35,132 DEBUG AlluxioFuseFileSystem - Enter: getattr(path=/aaa)
2020-03-03 14:33:35,135 DEBUG AlluxioFuseFileSystem - Exit (0): getattr(path=/aaa) in 3 ms
2020-03-03 14:33:35,138 DEBUG AlluxioFuseFileSystem - Enter: getattr(path=/._aaa)
2020-03-03 14:33:35,140 DEBUG AlluxioFuseFileSystem - Failed to get info of /._aaa, path does not exist or is invalid
2020-03-03 14:33:35,140 DEBUG AlluxioFuseFileSystem - Exit (-2): getattr(path=/._aaa) in 2 ms

Logging RPCs Calls Sent by Client

Add the following to your application-side log4j.properties to capture RPCs between the Alluxio client and FileSystem Master:

log4j.logger.alluxio.client.file.FileSystemMasterClient=DEBUG

Similarly, capture lower-level RPCs between Alluxio client and Block Master:

log4j.logger.alluxio.client.block.BlockMasterClient=DEBUG

You will see debug logs at the beginning and end of each RPC with its arguments and result in the client logs like the following:

2020-03-03 15:56:40,115 DEBUG FileSystemMasterClient - Enter: GetStatus(path=/.DS_Store,options=loadMetadataType: ONCE
commonOptions {
  syncIntervalMs: -1
  ttl: -1
  ttlAction: DELETE
}
)
2020-03-03 15:56:40,117 DEBUG FileSystemMasterClient - Exit (ERROR): GetStatus(path=/.DS_Store,options=loadMetadataType: ONCE
commonOptions {
  syncIntervalMs: -1
  ttl: -1
  ttlAction: DELETE
}
) in 2 ms: alluxio.exception.status.NotFoundException: Path "/.DS_Store" does not exist.

Logging RPC Calls Received by Masters

On the master, debug-level logging for incoming File System level RPC calls can be turned on (e.g., creating/reading/writing/removing files, updating file attributions) using the logLevel command:

$ ./bin/alluxio logLevel \
--logName=alluxio.master.file.FileSystemMasterClientServiceHandler \
--target master --level=DEBUG

Similarly, turn on the debug-level logging for block related RPC calls (e.g., adding/removing blocks):

$ ./bin/alluxio logLevel \
--logName=alluxio.master.block.BlockMasterClientServiceHandler \
--target master --level=DEBUG

Similarly, you can update the log level for these classes in the conf/log4j.properties file. You need to restart the relevant processes for the log4j properties to take effect.

Logging UnderFileSystem Operations

Sometimes it can be useful to log all operations on under storage. On the master, debug-level logging for UnderFileSystem operations can be turned on (e.g., creating/reading/writing/removing files on UFS) using the logLevel command:

$ ./bin/alluxio logLevel \
--logName=alluxio.underfs.UnderFileSystemWithLogging \
--target master --level=DEBUG

One can similarly turn on UFS operations on workers by passing --target workers. You can see operations in corresponding master or worker logs like below:

2020-06-02 11:28:21,824 DEBUG UnderFileSystemWithLogging - Enter: GetSpace: path=/opt/alluxio/underFSStorage, type=SPACE_USED
2020-06-02 11:28:21,824 DEBUG UnderFileSystemWithLogging - Exit (OK): GetSpace: path=/opt/alluxio/underFSStorage, type=SPACE_USED

Similarly, you can update the log level for these classes in the conf/log4j.properties file. You need to restart the relevant processes for the log4j properties to take effect.

Identifying Expensive Client RPCs / FUSE calls

When debugging the performance, it is often useful to understand which RPCs take most of the time but without recording all the communication (e.g., enabling all debug logging). There are two properties introduced in v2.3.0 in Alluxio to record expensive calls or RPCs in logs with WARN level. Setting in conf/alluxio-site.properties records client-side RPCs taking more than 200ms and FUSE APIs taking more than 1s:

alluxio.user.logging.threshold=200ms
alluxio.fuse.logging.threshold=1s

Example results are:

2020-03-08 23:40:44,374 WARN  BlockMasterClient - GetBlockMasterInfo(fields=[USED_BYTES,
FREE_BYTES, CAPACITY_BYTES]) returned BlockMasterInfo{capacityBytes=11453246122,
capacityBytesOnTiers={}, freeBytes=11453237930, liveWorkerNum=0, lostWorkerNum=0, usedBytes=8192, usedBytesOnTiers={}} in 600 ms
2020-03-08 23:40:44,374 WARN  AlluxioFuseFileSystem - statfs(path=/) returned 0 in 1200 ms

Redirecting debug log for certain classes

Sometimes it is useful to separate the log for certain classes to a separate log. This can be useful for reasons including but not limited to:

1. Clearly separate the wanted logs for further analysis.
2. Avoid master.log or worker.log being too big or have too many files created by log rotation.
3. Use a separate logger to send logs to a remote endpoint like a socket.

This can be achieved by adding a separate logger in the conf/log4j.properties. For example, the below example redirects debug logs of alluxio.master.StateLockManager to a separate set of files, so the master.log will not be full of the DEBUG logs created by alluxio.master.StateLockManager.

log4j.category.alluxio.master.StateLockManager=DEBUG, State_LOCK_LOGGER
log4j.additivity.alluxio.master.StateLockManager=false
log4j.appender.State_LOCK_LOGGER=org.apache.log4j.RollingFileAppender
log4j.appender.State_LOCK_LOGGER.File=<ALLUXIO_HOME>/logs/statelock.log
log4j.appender.State_LOCK_LOGGER.MaxFileSize=10MB
log4j.appender.State_LOCK_LOGGER.MaxBackupIndex=100
log4j.appender.State_LOCK_LOGGER.layout=org.apache.log4j.PatternLayout
log4j.appender.State_LOCK_LOGGER.layout.ConversionPattern=%d{ISO8601} %-5p %c{1} - %m%n