Logging

Slack Docker Pulls GitHub edit source

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).

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

The master and worker logs are useful to understand what the Alluxio Master and Workers are doing, especially when running into any issues. If you do not understand the error messages, search for them in the Github issues, in the case the problem has been discussed before. You can also join our Slack channel and seek help there. You can find more details about the Alluxio server logs here.

The client-side logs are helpful when Alluxio service is running but the client cannot connect to the servers. Alluxio client emits logging messages through log4j, so the location of the logs is determined by the client side log4j configuration used by the application. You can find more details about the client-side logs here.

The user logs in ${ALLUXIO_HOME}/logs/user/ are the logs from running Alluxio shell. Each user will have separate log files.

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/. Each process should have two corresponding files ending with .log or .out, such as worker.log and worker.out for the worker process. job_worker.log, job_worker.out and user/user_${USER}.log. 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. Fatal error messages (e.g., killed by the OS), will most likely go to these files.

The log location can be customized by setting environment variable ALLUXIO_LOGS_DIR. 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 Hive, Apache Spark.

For the Alluxio command line interface, the user log is located at ${ALLUXIO_HOME}/logs/user/user_${user_name}.log.

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 purposes
  • INFO: messages that highlight the status or progress
  • WARN: potentially harmful events that users may need to know about, but the process will still continue running
  • ERROR: system errors that users should pay attention to

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

Modifying Logging with log4j.properties

You can modify ${ALLUXIO_HOME}/conf/log4j.properties to customize logging levels and restart corresponding server processes to apply new changes. This is the recommended way to modify logging configurations.

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.FileSystemContext to DEBUG), add a new line at the end of this file:

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

To modify the logging level for a package (e.g., set all classes under alluxio to DEBUG), add a new line in the end of this file as below. This can be helpful when you do not know what the target classes are, or many classes are relevant.

log4j.logger.alluxio=DEBUG

Modifying Server Logging at Runtime

An alternative way to modify logging configurations is use the logLevel command. This allows someone to modify the configuration at runtime without needing to restart processes. This is not the recommended way as any modifications will not be persisted across restart, and causes a configuration mismatch between the running process and its log4j.properties file. 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 conf log --name=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 conf log --name=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 conf log --name=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 conf log --name=alluxio --level=DEBUG

# Turn off Alluxio debug logging when you are done
$ ./bin/alluxio conf log --name=alluxio --level=INFO

Finally, if your Alluxio deployment uses custom web ports (e.g. alluxio.master.web.port is different from 19999, or alluxio.worker.web.port is different from 30000), you can use the format host:port:role for your target. role can be one of master or worker or job_master or job_worker. For example, if your master running on 10.10.10.10 has alluxio.master.web.port=2181 configured, you would use:

$ ./bin/alluxio conf log --name=alluxio --target=10.10.10.10:2181:master --level=DEBUG

If your worker is running on 127.0.0.1 with alluxio.worker.web.port=25252 configured, you would use:

$ ./bin/alluxio conf log --name=alluxio --target=127.0.0.1:25252:worker --level=DEBUG

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.AlluxioJniFuseFileSystem=DEBUG

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

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