# 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](https://documentation.alluxio.io/ee-da-en/da-2.10/administration/remote-logging) 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. 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](https://documentation.alluxio.io/ee-da-en/da-2.10/operations/configuration#environment-variables) for more information.

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

```properties
# 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](https://documentation.alluxio.io/ee-da-en/da-2.10/compute-integration/hadoop-mapreduce#logging-configuration), [Apache Hive](https://documentation.alluxio.io/ee-da-en/da-2.10/compute-integration/hive#logging-configuration), [Apache Spark](https://documentation.alluxio.io/ee-da-en/da-2.10/compute-integration/spark#logging-configuration).

For the [Alluxio command line interface](https://documentation.alluxio.io/ee-da-en/da-2.10/operations/user-cli), 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:

```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 at the end of this file:

```properties
log4j.logger.alluxio.client.file.AlluxioFileInStream=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.

```properties
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](https://documentation.alluxio.io/ee-da-en/da-2.10/operations/user-cli#loglevel) 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`:

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

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

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

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

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

`role` can also be `cross_cluster_master`.

For example, if your master running on `10.10.10.10` has `alluxio.master.web.port=2181` configured, you would use:

```shell
$ ./bin/alluxio logLevel --logName=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:

```shell
$ ./bin/alluxio logLevel --logName=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`:

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

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

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:

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

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 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). Alluxio can record slow calls or RPCs in logs with WARN level by setting the following properties:

1. Set `alluxio.user.logging.threshold` to record slow client-side RPCs in application logs.
2. Set `alluxio.fuse.logging.threshold` to record slow FUSE API calls in fuse logs (`logs/fuse.log`).
3. Set `alluxio.underfs.logging.threshold` to record slow under storage RPCs (`logs/master.log` or `logs/worker.log`).

For example, the following setting in `conf/alluxio-site.properties` will log each FUSE API call slower than 1s, each UFS call slower than 10s, and each client-side RPC slower than 200ms:

```properties
alluxio.fuse.logging.threshold=1s
alluxio.underfs.logging.threshold=10s
alluxio.user.logging.threshold=200ms
```

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 into 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 having 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 DEBUG logs created by `alluxio.master.StateLockManager`.

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

### Disable certain log files

Sometimes it makes sense to disable certain logs files.

One example of use cases is when Alluxio is running in a containerized environment, where logs are written to the writable layer. This has performance penalties and the writable layer may grow indefinitely, causing disk pressure on the host. In that case you can either mount a volume to the log directory so logs are written to the volume, or rely on the [Remote Logging](https://documentation.alluxio.io/ee-da-en/da-2.10/administration/remote-logging) and disable local logs.

To disable local log output, you can set the corresponding logger(s) as below:

```properties
# Appender for Master
log4j.appender.MASTER_LOGGER=org.apache.log4j.varia.NullAppender
```