From 27e88940f5e1571c081fa828bfd747754ac94705 Mon Sep 17 00:00:00 2001 From: sebv Date: Wed, 25 Jun 2014 22:22:32 +0800 Subject: [PATCH] Logging improvements --- lib/appium.js | 2 +- lib/devices/android/android-common.js | 13 ++- .../android/android-context-controller.js | 2 +- lib/devices/android/android-controller.js | 2 +- lib/devices/android/android-hybrid.js | 6 +- lib/devices/android/android.js | 4 +- .../android/bootstrap/AndroidElement.java | 4 +- .../bootstrap/AndroidElementsHash.java | 6 +- .../android/bootstrap/SocketServer.java | 18 ++--- .../android/bootstrap/handler/Drag.java | 6 +- .../android/bootstrap/handler/Flick.java | 2 +- .../bootstrap/handler/Orientation.java | 2 +- .../android/bootstrap/handler/Pinch.java | 2 +- .../android/bootstrap/handler/SetText.java | 2 +- .../android/bootstrap/handler/Swipe.java | 2 +- .../bootstrap/handler/UpdateStrings.java | 4 +- .../android/bootstrap/utils/TheWatchers.java | 2 +- lib/devices/android/uiautomator.js | 1 + lib/devices/ios/ios.js | 6 +- lib/devices/ios/settings.js | 2 +- lib/server/capabilities.js | 2 +- lib/server/helpers.js | 30 ++++++- lib/server/logger.js | 81 ++++++++++++------- lib/server/main.js | 37 +++++---- lib/server/parser.js | 3 +- lib/server/responses.js | 3 +- package.json | 6 +- submodules/appium-adb | 2 +- submodules/appium-instruments | 2 +- submodules/appium-uiauto | 2 +- 30 files changed, 160 insertions(+), 96 deletions(-) diff --git a/lib/appium.js b/lib/appium.js index 5669bc7ad..39566b0b1 100644 --- a/lib/appium.js +++ b/lib/appium.js @@ -376,7 +376,7 @@ Appium.prototype.stop = function (cb) { return cb(); } - logger.debug('Shutting down appium session...'); + logger.info('Shutting down appium session'); this.device.stop(function (code) { var err; if (code && code > 0) { diff --git a/lib/devices/android/android-common.js b/lib/devices/android/android-common.js index d0c693a14..834751f76 100644 --- a/lib/devices/android/android-common.js +++ b/lib/devices/android/android-common.js @@ -345,6 +345,7 @@ androidCommon.prepareActiveDevice = function (cb) { // deviceId is already setted return cb(); } + logger.info('Retrieving device'); this.adb.getDevicesWithRetry(function (err, devices) { if (err) return cb(err); var deviceId = null; @@ -359,6 +360,7 @@ androidCommon.prepareActiveDevice = function (cb) { var emPort = this.adb.getPortFromEmulatorString(deviceId); this.adb.setEmulatorPort(emPort); } + logger.info('Found device', deviceId); this.adb.setDeviceId(deviceId); cb(); }.bind(this)); @@ -441,8 +443,10 @@ androidCommon.installApp = function (cb) { // err is set if the remote apk doesn't exist so don't check it. this.adb.isAppInstalled(this.args.appPackage, function (err, installed) { if (installed && this.args.fastReset && remoteApk) { + logger.info('App is already installed, resetting app'); this.resetApp(cb); } else if (!installed || (this.args.fastReset && !remoteApk)) { + logger.info('Installing App'); this.adb.mkdir(this.remoteTempPath(), function (err) { if (err) return cb(err); this.getRemoteApk(function (err, remoteApk, md5Hash) { @@ -606,6 +610,7 @@ androidCommon.unlockScreen = function (cb) { this.adb.isScreenLocked(function (err, isLocked) { if (err) return cb(err); if (isLocked) { + logger.info("Unlocking screen"); var timeoutMs = 10000; var start = Date.now(); var unlockAndCheck = function () { @@ -643,12 +648,12 @@ androidCommon.unlockScreen = function (cb) { androidCommon.packageAndLaunchActivityFromManifest = function (cb) { if (!this.args.app) { - logger.info("No app capability, can't parse package/activity"); + logger.warn("No app capability, can't parse package/activity"); return cb(); } if (this.args.appPackage && this.args.appActivity) return cb(); - logger.info("Parsing package and activity from app manifest"); + logger.debug("Parsing package and activity from app manifest"); this.adb.packageAndLaunchActivityFromManifest(this.args.app, function (err, pkg, act) { if (err) { logger.error("Problem parsing package and activity from manifest: " + @@ -659,7 +664,7 @@ androidCommon.packageAndLaunchActivityFromManifest = function (cb) { if (act && !this.args.appActivity) this.args.appActivity = act; if (!this.args.appWaitPackage) this.args.appWaitPackage = this.args.appPackage; if (!this.args.appWaitActivity) this.args.appWaitActivity = this.args.appActivity; - logger.info("Parsed package and activity are: " + pkg + "/" + act); + logger.debug("Parsed package and activity are: " + pkg + "/" + act); cb(); }.bind(this)); }; @@ -720,7 +725,7 @@ androidCommon.getCurrentActivity = function (cb) { androidCommon.getDeviceLanguage = function (cb) { this.adb.shell("getprop persist.sys.language", function (err, stdout) { if (err) { - logger.warn("Error getting device language: " + err); + logger.error("Error getting device language: " + err); cb(err, null); } else { logger.debug("Current device language: " + stdout.trim()); diff --git a/lib/devices/android/android-context-controller.js b/lib/devices/android/android-context-controller.js index 8c2b455a1..95cdde03e 100644 --- a/lib/devices/android/android-context-controller.js +++ b/lib/devices/android/android-context-controller.js @@ -35,7 +35,7 @@ androidContextController.getContexts = function (cb) { this.listWebviews(function (err, webviews) { if (err) return cb(err); this.contexts = _.union([this.NATIVE_WIN], webviews); - logger.info("Available contexts: " + this.contexts); + logger.debug("Available contexts: " + this.contexts); cb(null, { status: status.codes.Success.code , value: this.contexts diff --git a/lib/devices/android/android-controller.js b/lib/devices/android/android-controller.js index fd2ad9336..6c3d2ea5c 100644 --- a/lib/devices/android/android-controller.js +++ b/lib/devices/android/android-controller.js @@ -359,7 +359,7 @@ androidController.getPageSource = function (cb) { logger.debug('transferPageSourceXML command: ' + cmd); exec(cmd, { maxBuffer: 524288 }, function (err, stdout, stderr) { if (err) { - logger.warn(stderr); + logger.error(stderr); return cb(err); } cb(null); diff --git a/lib/devices/android/android-hybrid.js b/lib/devices/android/android-hybrid.js index a9f3fa1e1..af684438f 100644 --- a/lib/devices/android/android-hybrid.js +++ b/lib/devices/android/android-hybrid.js @@ -83,9 +83,9 @@ androidHybrid.getProcessNameFromWebview = function (webview, cb) { var pid = webview.match(/\d+$/); if (!pid) return cb("No pid for webview " + webview); pid = pid[0]; - logger.info(webview + " mapped to pid " + pid); + logger.debug(webview + " mapped to pid " + pid); - logger.info("Getting process name for webview"); + logger.debug("Getting process name for webview"); this.adb.shell("ps", function (err, out) { if (err) return cb(err); var pkg = "unknown"; @@ -111,7 +111,7 @@ androidHybrid.getProcessNameFromWebview = function (webview, cb) { } }); - logger.info("returning process name: " + pkg); + logger.debug("returning process name: " + pkg); cb(null, pkg); }); }; diff --git a/lib/devices/android/android.js b/lib/devices/android/android.js index ba0685770..c0ecbd5a8 100644 --- a/lib/devices/android/android.js +++ b/lib/devices/android/android.js @@ -82,7 +82,7 @@ Android.prototype.start = function (cb, onDie) { if (this.adb === null) { // Pass Android opts and Android ref to adb. - logger.debug("Starting android appium"); + logger.info("Starting android appium"); this.adb = new ADB(this.args); this.uiautomator = new UiAutomator(this.adb, this.args); this.uiautomator.setExitHandler(this.onUiautomatorExit.bind(this)); @@ -257,7 +257,7 @@ Android.prototype.checkShouldRelaunch = function (launchErr) { Android.prototype.checkApiLevel = function (cb) { this.adb.getApiLevel(function (err, apiLevel) { if (err) return cb(err); - + logger.info('Device API level is:', parseInt(apiLevel, 10)); if (parseInt(apiLevel) < 17) { var msg = "Android devices must be of API level 17 or higher. Please change your device to Selendroid or upgrade Android on your device."; logger.error(msg); // logs the error when we encounter it diff --git a/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/AndroidElement.java b/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/AndroidElement.java index 42bd638b8..e5f956247 100644 --- a/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/AndroidElement.java +++ b/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/AndroidElement.java @@ -233,12 +233,12 @@ public class AndroidElement { public boolean setText(final String text) throws UiObjectNotFoundException { if (UnicodeEncoder.needsEncoding(text)) { - Logger.info("Sending Unicode text to element: " + text); + Logger.debug("Sending Unicode text to element: " + text); String encodedText = UnicodeEncoder.encode(text); Logger.debug("Encoded text: " + encodedText); return el.setText(encodedText); } else { - Logger.info("Sending plain text to element: " + text); + Logger.debug("Sending plain text to element: " + text); return el.setText(text); } } diff --git a/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/AndroidElementsHash.java b/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/AndroidElementsHash.java index 11ac0e62c..fd2710513 100644 --- a/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/AndroidElementsHash.java +++ b/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/AndroidElementsHash.java @@ -110,16 +110,16 @@ public class AndroidElementsHash { int counter = 0; while (keepSearching) { if (baseEl == null) { - Logger.info("Element[" + key + "] is null: (" + counter + ")"); + Logger.debug("Element[" + key + "] is null: (" + counter + ")"); if (useIndex) { - Logger.info(" using index..."); + Logger.debug(" using index..."); tmp = sel.index(counter); } else { tmp = sel.instance(counter); } lastFoundObj = new UiObject(tmp); } else { - Logger.info("Element[" + key + "] is " + baseEl.getId() + ", counter: " + Logger.debug("Element[" + key + "] is " + baseEl.getId() + ", counter: " + counter); lastFoundObj = baseEl.getChild(sel.instance(counter)); } diff --git a/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/SocketServer.java b/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/SocketServer.java index 4372b42b9..0cb7b9ab8 100644 --- a/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/SocketServer.java +++ b/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/SocketServer.java @@ -40,7 +40,7 @@ class SocketServer { executor = new AndroidCommandExecutor(); try { server = new ServerSocket(port); - Logger.info("Socket opened on port " + port); + Logger.debug("Socket opened on port " + port); } catch (final IOException e) { throw new SocketServerException( "Could not start socket server listening on " + port); @@ -81,12 +81,12 @@ class SocketServer { input.append((char) a); } String inputString = input.toString(); - Logger.info("Got data from client: " + inputString); + Logger.debug("Got data from client: " + inputString); try { AndroidCommand cmd = getCommand(inputString); - Logger.info("Got command of type " + cmd.commandType().toString()); + Logger.debug("Got command of type " + cmd.commandType().toString()); res = runCommand(cmd); - Logger.info("Returning result: " + res); + Logger.debug("Returning result: " + res); } catch (final CommandTypeException e) { res = new AndroidCommandResult(WDStatus.UNKNOWN_ERROR, e.getMessage()) .toString(); @@ -109,7 +109,7 @@ class SocketServer { * @throws SocketServerException */ public void listenForever() throws SocketServerException { - Logger.info("Appium Socket Server Ready"); + Logger.debug("Appium Socket Server Ready"); UpdateStrings.loadStringsJson(); dismissCrashAlerts(); final TimerTask updateWatchers = new TimerTask() { @@ -125,7 +125,7 @@ class SocketServer { try { client = server.accept(); - Logger.info("Client connected"); + Logger.debug("Client connected"); in = new BufferedReader(new InputStreamReader(client.getInputStream(), "UTF-8")); out = new BufferedWriter(new OutputStreamWriter(client.getOutputStream(), "UTF-8")); while (keepListening) { @@ -134,7 +134,7 @@ class SocketServer { in.close(); out.close(); client.close(); - Logger.info("Closed client connection"); + Logger.debug("Closed client connection"); } catch (final IOException e) { throw new SocketServerException("Error when client was trying to connect"); } @@ -143,9 +143,9 @@ class SocketServer { public void dismissCrashAlerts() { try { new UiWatchers().registerAnrAndCrashWatchers(); - Logger.info("Registered crash watchers."); + Logger.debug("Registered crash watchers."); } catch (Exception e) { - Logger.info("Unable to register crash watchers."); + Logger.debug("Unable to register crash watchers."); } } diff --git a/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/Drag.java b/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/Drag.java index 73a5a7b5e..1a0b1e6af 100644 --- a/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/Drag.java +++ b/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/Drag.java @@ -72,7 +72,7 @@ public class Drag extends CommandHandler { return getErrorResult(e.getMessage()); } - Logger.info("Dragging from " + absStartPos.toString() + " to " + Logger.debug("Dragging from " + absStartPos.toString() + " to " + absEndPos.toString() + " with steps: " + dragArgs.steps.toString()); final boolean rv = device.drag(absStartPos.x.intValue(), absStartPos.y.intValue(), absEndPos.x.intValue(), @@ -93,7 +93,7 @@ public class Drag extends CommandHandler { return getErrorResult(e.getMessage()); } - Logger.info("Dragging the element with id " + dragArgs.el.getId() + Logger.debug("Dragging the element with id " + dragArgs.el.getId() + " to " + absEndPos.toString() + " with steps: " + dragArgs.steps.toString()); try { @@ -109,7 +109,7 @@ public class Drag extends CommandHandler { + e.getMessage()); } } else { - Logger.info("Dragging the element with id " + dragArgs.el.getId() + Logger.debug("Dragging the element with id " + dragArgs.el.getId() + " to destination element with id " + dragArgs.destEl.getId() + " with steps: " + dragArgs.steps); try { diff --git a/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/Flick.java b/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/Flick.java index b06494cc6..dfcb793ae 100644 --- a/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/Flick.java +++ b/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/Flick.java @@ -95,7 +95,7 @@ public class Flick extends CommandHandler { } steps = Math.abs(steps); - Logger.info("Flicking from " + start.toString() + " to " + end.toString() + Logger.debug("Flicking from " + start.toString() + " to " + end.toString() + " with steps: " + steps.intValue()); final boolean res = d.swipe(start.x.intValue(), start.y.intValue(), end.x.intValue(), end.y.intValue(), steps.intValue()); diff --git a/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/Orientation.java b/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/Orientation.java index 9dec9ccc8..c990a60db 100644 --- a/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/Orientation.java +++ b/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/Orientation.java @@ -90,7 +90,7 @@ public class Orientation extends CommandHandler { .getDisplayRotation()); Logger.debug("Desired orientation: " + orientation); - Logger.info("Current rotation: " + current); + Logger.debug("Current rotation: " + current); if (orientation.equalsIgnoreCase("LANDSCAPE")) { switch (current) { diff --git a/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/Pinch.java b/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/Pinch.java index 5c7ed8985..f93df93e9 100644 --- a/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/Pinch.java +++ b/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/Pinch.java @@ -43,7 +43,7 @@ public class Pinch extends CommandHandler { return getErrorResult("Unknown error:" + e.getMessage()); } - Logger.info("Pinching " + direction + " " + percent.toString() + "%" + Logger.debug("Pinching " + direction + " " + percent.toString() + "%" + " with steps: " + steps.toString()); boolean res; if (direction.equals("in")) { diff --git a/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/SetText.java b/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/SetText.java index f7d652251..6303e7f38 100644 --- a/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/SetText.java +++ b/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/SetText.java @@ -36,7 +36,7 @@ public class SetText extends CommandHandler { if (text.endsWith("\\n")) { pressEnter = true; text = text.replace("\\n", ""); - Logger.info("Will press enter after setting text"); + Logger.debug("Will press enter after setting text"); } final Boolean result = el.setText(text); if (pressEnter) { diff --git a/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/Swipe.java b/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/Swipe.java index 281225038..6f8116ce9 100644 --- a/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/Swipe.java +++ b/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/Swipe.java @@ -58,7 +58,7 @@ public class Swipe extends CommandHandler { } } - Logger.info("Swiping from " + absStartPos.toString() + " to " + Logger.debug("Swiping from " + absStartPos.toString() + " to " + absEndPos.toString() + " with steps: " + steps.toString()); final boolean rv = device.swipe(absStartPos.x.intValue(), absStartPos.y.intValue(), absEndPos.x.intValue(), diff --git a/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/UpdateStrings.java b/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/UpdateStrings.java index 81d0e3054..f7c6a4cfd 100644 --- a/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/UpdateStrings.java +++ b/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/handler/UpdateStrings.java @@ -33,7 +33,7 @@ public class UpdateStrings extends CommandHandler { } public static boolean loadStringsJson() { - Logger.info("Loading json..."); + Logger.debug("Loading json..."); try { String filePath = "/data/local/tmp/strings.json"; final File jsonFile = new File(filePath); @@ -50,7 +50,7 @@ public class UpdateStrings extends CommandHandler { dataInput.close(); final String jsonString = new String(jsonBytes, "UTF-8"); Find.apkStrings = new JSONObject(jsonString); - Logger.info("json loading complete."); + Logger.debug("json loading complete."); } catch (final Exception e) { Logger.error("Error loading json: " + e.getMessage()); return false; diff --git a/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/utils/TheWatchers.java b/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/utils/TheWatchers.java index 6913b9d61..81230aaac 100644 --- a/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/utils/TheWatchers.java +++ b/lib/devices/android/bootstrap/src/io/appium/android/bootstrap/utils/TheWatchers.java @@ -18,7 +18,7 @@ public class TheWatchers { public boolean check() { // Send only one alert message... if (isDialogPresent() && (!alerted)) { - Logger.info("Emitting system alert message"); + Logger.debug("Emitting system alert message"); alerted = true; } diff --git a/lib/devices/android/uiautomator.js b/lib/devices/android/uiautomator.js index 5f6597f75..983de0804 100644 --- a/lib/devices/android/uiautomator.js +++ b/lib/devices/android/uiautomator.js @@ -23,6 +23,7 @@ var UiAutomator = function (adb, opts) { }; UiAutomator.prototype.start = function (readyCb) { + logger.info("Starting App"); this.adb.killProcessesByName('uiautomator', function (err) { if (err) return readyCb(err); logger.debug("Running bootstrap"); diff --git a/lib/devices/ios/ios.js b/lib/devices/ios/ios.js index c8b4f3b57..1802e7c12 100644 --- a/lib/devices/ios/ios.js +++ b/lib/devices/ios/ios.js @@ -336,7 +336,11 @@ IOS.prototype.startInstruments = function (cb) { }; IOS.prototype.makeInstruments = function (cb) { - prepareBootstrap({ verboseInstruments: !this.args.quiet }).then( + // at the moment all the logging in uiauto is at debug level + // TODO: be able to use info in appium-uiauto + prepareBootstrap({ + verboseInstruments: logger.appiumLoglevel === 'debug' + }).then( function (bootstrapPath) { var instruments = new Instruments({ app: this.args.app || this.args.bundleId diff --git a/lib/devices/ios/settings.js b/lib/devices/ios/settings.js index 950bd720e..1deef10bf 100644 --- a/lib/devices/ios/settings.js +++ b/lib/devices/ios/settings.js @@ -142,7 +142,7 @@ var getSafari7Dirs = function (sdk) { if (safariDir) { safariDirs.push(safariDir); } else { - logger.info("Could not find MobileSafari in sim applications at " + + logger.warn("Could not find MobileSafari in sim applications at " + appsDir); } }); diff --git a/lib/server/capabilities.js b/lib/server/capabilities.js index 36c4635f2..38c5f77de 100644 --- a/lib/server/capabilities.js +++ b/lib/server/capabilities.js @@ -123,7 +123,7 @@ Capabilities.prototype.checkValidity = function (deviceType, strictMode) { var allValidCaps = [].concat(generalCaps, androidCaps, iosCaps); var unknownCaps = _.difference(capsUsed, allValidCaps); if (unknownCaps.length > 0) { - logger.info('The following desired capabilities were provided, but not recognized by appium.' + + logger.debug('The following desired capabilities were provided, but not recognized by appium.' + ' They will be passed on to any other services running on this server. : ' + unknownCaps.join(', ')); } diff --git a/lib/server/helpers.js b/lib/server/helpers.js index 55b002f91..d3afc6681 100644 --- a/lib/server/helpers.js +++ b/lib/server/helpers.js @@ -177,7 +177,7 @@ module.exports.startListening = function (server, args, parser, appiumVer, appiu } var showArgs = getNonDefaultArgs(parser, args); if (_.size(showArgs)) { - logger.info("Non-default server args: " + JSON.stringify(showArgs)); + logger.debug("Non-default server args: " + JSON.stringify(showArgs)); } }); server.on('error', function (err) { @@ -201,3 +201,31 @@ module.exports.startListening = function (server, args, parser, appiumVer, appiu } }, 1000); }; + +// Copied the morgan compile function over so that cooler formats +// may be configured +function compile(fmt) { + fmt = fmt.replace(/"/g, '\\"'); + var js = ' return "' + fmt.replace(/:([-\w]{2,})(?:\[([^\]]+)\])?/g, + function (_, name, arg) { + return '"\n + (tokens["' + name + '"](req, res, "' + arg + '") || "-") + "'; + }) + '";'; + // jshint evil:true + return new Function('tokens, req, res', js); +} +module.exports.requestStartLoggingFormat = compile('-->'.white + ' ' + ':method'.white + ' ' + + ':url'.white); +// Copied the morgan format.dev function, modified to use colors package +// and custom logging line +module.exports.requestEndLoggingFormat = function (tokens, req, res) { + var status = res.statusCode; + var statusStr = ':status'; + if (status >= 500) statusStr = statusStr.red; + else if (status >= 400) statusStr = statusStr.yellow; + else if (status >= 300) statusStr = statusStr.cyan; + else statusStr = statusStr.green; + var fn = compile('<-- :method :url '.white + statusStr + + ' :response-time ms - :res[content-length]'.grey); + return fn(tokens, req, res); +}; + diff --git a/lib/server/logger.js b/lib/server/logger.js index 1b05e4231..72d47bf8f 100644 --- a/lib/server/logger.js +++ b/lib/server/logger.js @@ -1,8 +1,6 @@ "use strict"; -var winston = require('winston') - , _ = require('underscore') - , defaults = {colorize: true, timestamp: false}; +var winston = require('winston'); var levels = { debug: 1 @@ -21,45 +19,51 @@ var colors = { var logger = null; module.exports.init = function (args) { - var options = _.extend(_.clone(defaults), { - timestamp: args.logTimestamp - , handleExceptions: true - , exitOnError: false - , json: false - , level: 'debug' - }); - - var winstonOptions = { - console: - _.extend({ - colorize: !args.logNoColors - }, options) - }; + var loglevel = args.logLevel ? args.logLevel : + (args.quiet ? 'warn' : 'info'); winston.addColors(colors); - winston.loggers.add('appium', winstonOptions); + winston.loggers.add('appium', { + console: { + timestamp: args.logTimestamp ? true : false + , colorize: args.logNoColors ? false : true + , handleExceptions: true + , exitOnError: false + , json: false + , level: loglevel + } + }); logger = winston.loggers.get('appium'); logger.setLevels(levels); logger.stripColors = args.logNoColors; + logger.appiumLoglevel = loglevel; - logger.transports.console.level = args.logLevel || - (args.quiet ? 'warn' : null) || 'info'; - + var fileLogger = null; if (args.log) { - winstonOptions.file = _.extend({ - filename: args.log - , colorize: false - , maxFiles: 1 - }, options); - try { - logger.add(winston.transports.File, winstonOptions.file); + winston.loggers.add('appium-file', { + file: { + timestamp: true + , colorize: false + , filename: args.log + , maxFiles: 1 + , level: loglevel + , handleExceptions: true + , exitOnError: false + , json: false + } + } + ); + fileLogger = winston.loggers.get('appium-file'); + fileLogger.setLevels(levels); + fileLogger.stripColors = true; } catch (e) { logger.debug("Tried to attach logging to file " + args.log + " but an error occurred"); } } + var webhookLogger = null; if (args.webhook) { var host = args.webhook; var port = 9003; @@ -74,15 +78,32 @@ module.exports.init = function (args) { host = host || '127.0.0.1'; port = port || 9003; try { - logger.add(winston.transports.Webhook, { 'host': host, 'port': port, - 'path': '/' }); + winston.loggers.add('appium-webhook', { webhook: { + host: host + , port: port + , path: '/' + , level: loglevel + , handleExceptions: true + , exitOnError: false + , json: false + } + }); + webhookLogger = winston.loggers.get('appium-webhook'); + webhookLogger.setLevels(levels); + webhookLogger.stripColors = true; } catch (e) { logger.debug("Tried to attach logging to webhook at " + host + " but an error occurred"); } } + + logger.on('logging', function (transport, level, msg, meta) { + if (fileLogger) fileLogger.log(level, msg, meta); + if (webhookLogger) webhookLogger.log(level, msg, meta); + }); }; + module.exports.get = function () { if (logger === null) { exports.init({}); diff --git a/lib/server/main.js b/lib/server/main.js index e51f4c99e..38b96de0c 100644 --- a/lib/server/main.js +++ b/lib/server/main.js @@ -6,8 +6,9 @@ var parser = require('./parser.js')() , fs = require('fs') , path = require('path') , _ = require('underscore') - , noPermsCheck = false - , colors = require('colors'); + , noPermsCheck = false; + +require('colors'); process.chdir(path.resolve(__dirname, '../..')); @@ -60,12 +61,13 @@ var http = require('http') , allowCrossDomain = helpers.allowCrossDomain , catchAllHandler = helpers.catchAllHandler , checkArgs = helpers.checkArgs - , winstonStream = helpers.winstonStream , configureServer = helpers.configureServer , startListening = helpers.startListening , conditionallyPreLaunch = helpers.conditionallyPreLaunch , prepareTmpDir = helpers.prepareTmpDir - , noColorLogger = helpers.noColorLogger; + , requestStartLoggingFormat = require('./helpers.js').requestStartLoggingFormat + , requestEndLoggingFormat = require('./helpers.js').requestEndLoggingFormat; + var main = function (args, readyCb, doneCb) { @@ -86,25 +88,26 @@ var main = function (args, readyCb, doneCb) { var rest = express() , server = http.createServer(rest); + rest.use(morgan(function (tokens, req, res) { + // morgan output is redirected straight to winston + logger.info(requestEndLoggingFormat(tokens, req, res), + (res.jsonResp || '').grey); + })); rest.use(favicon(path.join(__dirname, 'static/favicon.ico'))); rest.use(express.static(path.join(__dirname, 'static'))); rest.use(allowCrossDomain); - if (!args.quiet) { - if (args.logNoColors) { - rest.use(morgan(noColorLogger)); - } else { - rest.use(morgan('dev')); - } - } - if (args.log || args.webhook) { - rest.use(morgan({stream: winstonStream})); - } - if (args.logNoColors || args.log) { - colors.mode = "none"; - } rest.use(parserWrap); rest.use(bodyParser.urlencoded({extended: true})); rest.use(bodyParser.json()); + rest.use(morgan({format: function (tokens, req, res) { + // morgan output is redirected straight to winston + var data = ''; + try { + if (req.body) data = JSON.stringify(req.body).substring(0, 1000); + } catch (ign) {} + logger.info(requestStartLoggingFormat(tokens, req, res), data.grey); + }, immediate: true})); + rest.use(methodOverride()); // Instantiate the appium instance diff --git a/lib/server/parser.js b/lib/server/parser.js index 1e1f86b24..bef294b4c 100644 --- a/lib/server/parser.js +++ b/lib/server/parser.js @@ -148,7 +148,8 @@ var args = [ [['--log-level'], { choices: ['debug','info','warn', 'error'] - , defaultValue: 'debug' + // TODO: enable this once we got rid of --quiet + //, defaultValue: 'info' , dest: 'logLevel' , required: false , example: "debug" diff --git a/lib/server/responses.js b/lib/server/responses.js index f97a81fe4..228195ac2 100644 --- a/lib/server/responses.js +++ b/lib/server/responses.js @@ -78,7 +78,8 @@ var respondSuccess = exports.respondSuccess = function (req, res, value, sid) { printResponse.value.length > maxLen) { printResponse.value = printResponse.value.slice(0, maxLen) + "..."; } - logger.debug("Responding to client with success: " + JSON.stringify(printResponse)); + res.jsonResp = JSON.stringify(printResponse); + logger.debug("Responding to client with success: " + res.jsonResp); res.send(response); }; diff --git a/package.json b/package.json index 2a3c5011c..c10d64948 100644 --- a/package.json +++ b/package.json @@ -41,10 +41,10 @@ }, "dependencies": { "adm-zip": "~0.4.4", - "appium-adb": "~1.2.2", + "appium-adb": "~1.3.0", "appium-atoms": "~0.0.5", - "appium-instruments": "~1.1.2", - "appium-uiauto": "~1.2.1", + "appium-instruments": "~1.2.0", + "appium-uiauto": "~1.3.0", "argparse": "~0.1.15", "async": "~0.9.0", "binary-cookies": "~0.1.1", diff --git a/submodules/appium-adb b/submodules/appium-adb index 06e7edf82..712dda2d8 160000 --- a/submodules/appium-adb +++ b/submodules/appium-adb @@ -1 +1 @@ -Subproject commit 06e7edf823113b16f6d7d988be4a760c4b903ba4 +Subproject commit 712dda2d86368c63bf3678cec27186be6cb3175c diff --git a/submodules/appium-instruments b/submodules/appium-instruments index 80e3a9f06..ad297ac38 160000 --- a/submodules/appium-instruments +++ b/submodules/appium-instruments @@ -1 +1 @@ -Subproject commit 80e3a9f065a472a37caf6b0ab4d976a5054c1857 +Subproject commit ad297ac386119ab97b1776b5059dedd8898c2cbd diff --git a/submodules/appium-uiauto b/submodules/appium-uiauto index 7e0ca7a89..0ba2d8d01 160000 --- a/submodules/appium-uiauto +++ b/submodules/appium-uiauto @@ -1 +1 @@ -Subproject commit 7e0ca7a8978ef5f86de33f56e095e3fd214cdfb0 +Subproject commit 0ba2d8d01df7f4dec2a5435c7f7917f5c4c4bf64