---
layout: global
title: Basic Logging
nickname: Basic Logging
group: Operations
priority: 11
---

* Table of Contents
{:toc}

## 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]({{ '/en/operation/Remote-Logging.html' | relativize_url }}) for more details).

Alluxio logging is implemented using [`log4j`](https://logging.apache.org/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]({{ '/en/operation/Configuration.html' | relativize_url }}#environment-variables)
for more information.

### 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]({{ '/en/compute/Hadoop-MapReduce.html' | relativize_url }}#logging-configuration),
[Apache HBase]({{ '/en/compute/HBase.html' | relativize_url }}#logging-configuration),
[Apache Hive]({{ '/en/compute/Hive.html' | relativize_url }}#logging-configuration),
[Apache Spark]({{ '/en/compute/Spark.html' | relativize_url }}#logging-configuration).

## Configuring Log Levels

Alluxio uses the following four logging levels:
- `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:

```properties
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:

```properties
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.

The command follows the format `alluxio logLevel --logName=NAME [--target=<master|worker|host:port>] [--level=LEVEL]`,
where:
* `--logName <arg>` indicates the logger's class (e.g. `alluxio.master.file.DefaultFileSystemMaster`)
* `--target <arg>` lists the Alluxio master or workers to set.
The target could be of the form `<master|workers|host:webPort>` and multiple targets can be listed as comma-separated entries.
The `host:webPort` format can only be used when referencing a worker.
The default target value is all masters and workers.
* `--level <arg>` If provided, the command changes to the given logger level,
otherwise it returns the current logger level.

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

```console
$ ./bin/alluxio logLevel --logName=alluxio.heartbeat.HeartbeatContext \
  --target=master,192.168.100.100:30000 --level=DEBUG
```

And the following command returns the log level of the class `alluxio.heartbeat.HeartbeatContext` among all the workers:
```console
$ ./bin/alluxio logLevel --logName=alluxio.heartbeat.HeartbeatContext --target=workers
```

For more information, refer to the help text of the `logLevel` command by running `./bin/alluxio logLevel`

## 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`:

```bash
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`:

```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:

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

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

```properties
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:

```console
$ ./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):

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

### 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:

```console
$ ./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
```

### 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:

```properties
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
```
