Anatomy of Logging in Appium

When the Appium server runs there is often a bewildering stream of logs, giving information about the automation in process, but the details are often obscure.

Server Startup

The first lines of the log announce the version of Appium, and the address it is running on:

Check out: Starting Appium Server Programmatically Using AppiumServiceBuilder

$ appium
[Appium] Welcome to Appium v1.8.0-beta3 (REV 40e40975ebd3593d08c3f83de2546258f7ddf11d)
[Appium] Appium REST http interface listener started on 0.0.0.0:4723

Further, if you have started the server with any special flags, including default desired capabilities they will also be noted here, to help with understand the environment that is being run:

$ appium --address 172.19.131.113 --port 8000 --default-capabilities '{"showIOSLog": true}'
[Appium] Welcome to Appium v1.8.0-beta3 (REV 40e40975ebd3593d08c3f83de2546258f7ddf11d)
[Appium] Non-default server args:
[Appium]   address: 172.19.131.113
[Appium]   port: 8000
[Appium]   defaultCapabilities: {
[Appium]     showIOSLog: true
[Appium]   }
[Appium] Default capabilities, which will be added to each request unless overridden by desired capabilities:
[Appium]   showIOSLog: true
[Appium] Appium REST http interface listener started on 172.19.131.113:8000

This information is invaluable for providing context to the test automation that will be run. In particular, different versions of Appium will have different capacities and issues, so knowing what version is running is necessary to begin to make any determination of what is going on in any run.

Session Creation

While session creation involves a complicated array of operations to get the environment set up and the application under test running, the beginning of the logs for a command to create the session provides basic information about the session. In particular, the desired capabilities, along with any default capabilities are listed. It is often useful to check that what was intended to be requested was actually received by the Appium server, since it is the capabilities listed here that will be acted upon for the automation session.

Also check: Testing Real Time User Interaction Using Multiple Simultaneous Appium Sessions

[Appium] Creating new XCUITestDriver (v2.68.0) session
[Appium] Capabilities:
[Appium]   app: /Users/isaac/apps/UICatalog-iphonesimulator.app
[Appium]   platformName: iOS
[Appium]   platformVersion: 11.3
[Appium]   deviceName: iPhone 6
[Appium]   automationName: XCUITest
[Appium]   noReset: true
[Appium]   maxTypingFrequency: 30
[Appium]   clearSystemFiles: true
[Appium]   showXcodeLog: false
[debug] [BaseDriver]
[debug] [BaseDriver] Creating session with MJSONWP desired capabilities: {"app":"/Users/isaac/code/a...

Appium Commands

Appium is a REST server, accepting incoming HTTP requests, performing the action requested, and returning a result of some sort. In the Appium server logs, each such incoming request is delineated by a line indicating the request, and a line indicating the response. In between these are the details of the execution of the requested command:

Recommended post: Batching Appium Commands Using Execute Driver Script to Speed Up Tests

[HTTP] --> GET /wd/hub/status {}
[debug] [MJSONWP] Calling AppiumDriver.getStatus() with args: []
[debug] [MJSONWP] Responding to client with driver.getStatus() result: {"build":{"version":"1.8.0-beta3","revision":"30e7b45bdc5668124af33c41492aa5195fcdf64d"}}
[HTTP] <-- GET /wd/hub/status 200 121 ms - 126

Investigating Errors

On the client-side errors are usually helpful, there is usually more information to be found in the logs. Usually, the errors will be at the end of the automation session, but sometimes the session can continue, and the error logs will be earlier. So, the first step is to identify the command where the error happened. As we have already seen, each command is marked by [HTTP] --> and [HTTP] <--. Within these markers is the details of the execution of the command, including any error output.

Read: Getting Started with Appium for Android on Windows

Let's take a look at a concrete example:

[HTTP] --> POST /wd/hub/session

[debug] [AndroidDriver] Shutting down Android driver
[debug] [AndroidDriver] Called deleteSession but bootstrap wasn't active
[debug] [Logcat] Stopping logcat capture
[debug] [ADB] Getting connected devices...
[debug] [ADB] 1 device(s) connected
[debug] [ADB] Running '/home/user/Android/Sdk/platform-tools//adb' with args: ["-P",5037,"-s","ec8c4df","shell","am","force-stop","io.appium.unlock"]
[debug] [AndroidDriver] Not cleaning generated files. Add `clearSystemFiles` capability if wanted.
[MJSONWP] Encountered internal error running command: Error: Cannot stop and clear com.company.app. Original error: Error executing adbExec. Original error: 'Command '/home/user/Android/Sdk/platform-tools//adb -P 5037 -s ec8c4df shell pm clear com.company.app' exited with code 1'; Stderr: 'Error: java.lang.SecurityException: PID 22126 does not have permission android.permission.CLEAR_APP_USER_DATA to clear data of package com.company.app'; Code: '1'
    at Object.wrappedLogger.errorAndThrow (../../lib/logging.js:63:13)
    at ADB.callee$0$0$ (../../../lib/tools/adb-commands.js:334:9)
    at tryCatch (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/babel-runtime/regenerator/runtime.js:67:40)
    at GeneratorFunctionPrototype.invoke [as _invoke] (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/babel-runtime/regenerator/runtime.js:315:22)
    at GeneratorFunctionPrototype.prototype.(anonymous function) [as throw] (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/babel-runtime/regenerator/runtime.js:100:21)
    at GeneratorFunctionPrototype.invoke (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/babel-runtime/regenerator/runtime.js:136:37)
    at 
    at process._tickCallback (internal/process/next_tick.js:188:7)
[HTTP] <-- POST /wd/hub/session 500 40811 ms - 557

In this abridged set of logs, the user has attempted to start a session using the Android driver and has been met with an error. In this case it looks like the error happened during Appium's attempt to stop and clear the AUT in preparation for the session. Here the error gives us two important pieces of information:

1. What Appium was trying to do, specifically
2. What went wrong (in the form of error text and any related codes)

Also read: Tips for Speeding Up Your Remote Appium Sessions

In this case, Appium was trying to run an adb command (adb shell am force-stop), with parameters that have been included in the error text. And what happened? It was met with an Android system error about permissions. At this point, we have everything we need to troubleshoot locally. We can run the adb command that Appium tried to run, for example, and determine whether we can reproduce the issue outside of Appium. If so, we can then seek recourse through a helpful Android-specific forum, or from other Appium users who might have run into the same problem. If the command can be run successfully from the command line, then it may be we have uncovered a bug in Appium, and it should be reported as a GitHub issue.

(If you're curious, in this case the user was able to reproduce the problem outside of Appium, so it appeared to be related to the specific device manufacturer's security model).

Obviously, this is one of many, many examples that could have been given, but it illustrates the core point that, when faced with an error, the logs can help provide more information that facilitate a local repro attempt or help the Appium team understand what could be going wrong. No issue should ever be submitted to the Appium issue tracker without a complete set of logs!

Check: Attaching Appium Clients to Existing Sessions

Server Flags for Changing the Logging Output

While the default logging output is often enough, and if you are opening an issue on GitHub to get help with a problem, the more information the better, there are server flags provided to change the logging behavior of the Appium server.

• --log-level - change the level at which Appium logs information. Appium defaults to logging everything, which can be a lot. The options for the flag are 'info', 'info:debug', 'info:info', 'info:warn', 'info:error', 'warn', 'warn:debug', 'warn:info', 'warn:warn', 'warn:error', 'error', 'error:debug', 'error:info', 'error:warn', 'error:error', 'debug', 'debug:debug', 'debug:info', 'debug:warn', 'debug:error'
• --log-no-colors - If your console does not display colors (this will be manifested as logs with odd character sequences like TODO: find the color) you can turn off colors with this flag
• --log-timestamp - Add a timestamp to the beginning of each log line, which is useful in cases where timeouts are occurring. The log lines will look like

2018-03-15 13:17:58:663 - [Appium] Welcome to Appium v1.8.0-beta3 (REV 30e7b45bdc5668124af33c41492aa5195fcdf64d)
2018-03-15 13:17:58:664 - [Appium] Non-default server args:
2018-03-15 13:17:58:665 - [Appium]   logTimestamp: true
2018-03-15 13:17:58:732 - [Appium] Appium REST http interface listener started on 0.0.0.0:4723