軟體測試 | 讀懂 Appium 日志，讓測試效率翻倍！

Appium 伺服器運作時會産生很多日志，但是很多人并不了解其中的意義，也無法掌握有用的資訊。本文将詳細解讀如何讀懂 Appium 日志，并讓你的測試效率翻倍。

開啟服務

日志第一行顯示了 Appium 版本和運作位址。

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

如果你在 Appium 上添加了參數，他們會在日志中展示，如果添加了 defaultCapabilities，日志也會顯示出來。

Appium 參數： http://appium.io/docs/en/writing-running-appium/server-args/

defaultCapabilities詳見：

http://appium.io/docs/en/writing-running-appium/default-capabilities-arg/

$ 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           

對于自動化測試來說，這個資訊很重要，因為不同的 Appium 版本有不同的功能和問題，必須要知道自己的 Appium 版本。

建立 Session

為了自動化測試跑起來，session 要做很多事，日志提供了一些基本的 session 資訊，特别是 desired capabilities 和 default capabilities。應該時刻注意 Appium 服務是否正确接收了請求内容，日志列出了建立 automation session（不懂 automation session 的看下面的連結）。

desired capabilities：

http://appium.io/docs/en/writing-running-appium/caps/

[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 指令

Appium 是一個 REST 服務，接收 HTTP 請求，展示請求内容，傳回某種結果。Appium 服務端日志用線和箭頭展示了請求和傳回的内容。在兩個箭頭之間是 Appium 服務端執行請求指令的日志資訊：

什麼是REST服務：

https://en.wikipedia.org/wiki/Representational_state_transfer

[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           

錯誤排查

利用日志可以非常友善的排查錯誤，錯誤通常發生在 automation session 之後。但有時，如果 session 持續存在，錯誤也可能發生。是以第一步是找出錯誤在哪。

下面的例子可以看出，每個指令用 [HTTP] --> 和 [HTTP] <-- 标記。這些标記之間是指令細節，包含了錯誤輸出：

[HTTP] --> POST /wd/hub/session
<SNIP>
[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 <anonymous>
at process._tickCallback (internal/process/next_tick.js:188:7)
[HTTP] <-- POST /wd/hub/session 500 40811 ms - 557           

使用者試圖用 Android driver 啟動一個 session，但發生了錯誤。Appium 為準備 session 而關掉并清除 AUT 時發現了錯誤，這個錯誤讓我們知道兩件事：

1. Appium 正在嘗試做什麼
2. 哪裡出錯了

在這個例子中，Appium 嘗試運作 adb 指令（adb shell am force-stop），adb 參數在錯誤資訊中也有顯示。發生了 Android 系統權限錯誤。此時，我們可以手動運作這個 adb 指令，看看錯誤是不是可以重制。如果錯誤重制，上網查錯吧！如果 adb 指令成功運作，可能是 Appium 的 bug，應該去 Github 的 issue 上檢視或者送出這個 bug 。（例子中的錯誤是裝置制造商的安全模型造成的）

這個例子隻是衆多錯誤中的一個，但它說明至關重要的一點，當錯誤發生時，日志可以提供更多的資訊，如果沒有完整的日志資訊，對 Appium 排錯難上加難。

可以改變日志輸出的參數

通常，預設的日志内容已經足夠，如果你想去 Github 上尋求幫助，資訊當然越多越好！下面一些參數可以改變 Appium 服務端的日志行為：

• -log-level - 改變Appium日志顯示級别。

  Appium 預設展示所有日志，它有以下一些選項：'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 - 如果你的控制台沒有顔色（日志可能會産生一些奇怪的字元，比如"TODO: find the color"），你可以用這個參數關閉顔色。
• -log-timestamp - 在日志前添加時間戳，在排查逾時錯誤時有奇效，展示如下：

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           

更多技術文章分享及測試資料點此擷取