Running into issues trying to enable chromedriver logging

Any ideas here? We’re using a selenium grid with the hub running at 3.141.59. When I try to enable loggingPrefs in the capabilities, the grid throws it out stating:

2021-10-13 20:10:17.046:WARN:osjs.HttpChannel:qtp92150540-1974: /wd/hub/session java.io.IOException: org.openqa.grid.common.exception.GridException: Cannot extract a capabilities from the request: {
  "desiredCapabilities": {
    "appPackage": "com.android.settings",
    "clearSystemFiles": false,
    "loggingPrefs": {
      "browser": "ALL"
    },
    "disableAndroidWatchers": true,
    "language": "en",
    "locale": "US",
    "unlockKey": "1111",
    "deviceName": "*",
    "tripadvisor:node.defaultDevice": true,
    "tripadvisor:testng.session.hash": "a0e36394-ba0d-4af9-9dd1-ca5d3c4f53b5",
    "newCommandTimeout": 45,
    "platformVersion": "*",
    "automationName": "UIAutomator2",
    "unlockType": "pin",
    "browserName": "",
    "tripadvisor:testng.hostname": "bedouglas-mac",
    "unicodeKeyboard": true,
    "platformName": "Android",
    "resetKeyboard": true,
    "tripadvisor:testng.suite": "Default Suite",
    "appActivity": "com.android.settings.Settings",
    "tripadvisor:node.platformType": "Phone",
    "autoLaunch": false,
    "tripadvisor:testng.test": "testHotelTAPlusBooking",
    "autoGrantPermissions": true,
    "chromeOptions": {
      "w3c": false,
      "androidPackage": "com.tripadvisor.tripadvisor.prerelease"
    }
  },
  "capabilities": {
    "firstMatch": [
      {
        "appium:appActivity": "com.android.settings.Settings",
        "appium:appPackage": "com.android.settings",
        "appium:autoGrantPermissions": true,
        "appium:autoLaunch": false,
        "appium:automationName": "UIAutomator2",
        "browserName": "",
        "appium:chromeOptions": {
          "w3c": false,
          "androidPackage": "com.tripadvisor.tripadvisor.prerelease"
        },
        "appium:clearSystemFiles": false,
        "appium:deviceName": "*",
        "appium:disableAndroidWatchers": true,
        "goog:chromeOptions": {
          "w3c": false,
          "androidPackage": "com.tripadvisor.tripadvisor.prerelease"
        },
        "appium:language": "en",
        "appium:locale": "US",
        "loggingPrefs": {
          "browser": "ALL"
        },
        "appium:newCommandTimeout": 45,
        "platformName": "android",
        "appium:platformVersion": "*",
        "appium:resetKeyboard": true,
        "tripadvisor:node.defaultDevice": true,
        "tripadvisor:node.platformType": "Phone",
        "tripadvisor:testng.hostname": "bedouglas-mac",
        "tripadvisor:testng.session.hash": "a0e36394-ba0d-4af9-9dd1-ca5d3c4f53b5",
        "tripadvisor:testng.suite": "Default Suite",
        "tripadvisor:testng.test": "testHotelTAPlusBooking",
        "appium:unicodeKeyboard": true,
        "appium:unlockKey": "1111",
        "appium:unlockType": "pin"
      }
    ]
  }
}

I’ve tweaked the grid RemoteProxy to take workaround:loggingPrefs and transpose them to loggingPrefs, but then it looks like appium throws them on the ground:

2021-10-13 21:05:37:405 - [debug] [BaseDriver] Event 'newSessionRequested' logged at 1634159137405 (17:05:37 GMT-0400 (Eastern Daylight Time))
2021-10-13 21:05:37:407 - [BaseDriver] The following capabilities are not standard capabilities and should have an extension prefix:
2021-10-13 21:05:37:407 - [BaseDriver]   deviceName
2021-10-13 21:05:37:407 - [BaseDriver]   udid
2021-10-13 21:05:37:408 - [BaseDriver]   systemPort
2021-10-13 21:05:37:408 - [BaseDriver]   wdaLocalPort
2021-10-13 21:05:37:410 - [Appium] The following capabilities were provided in the JSONWP desired capabilities that are missing in W3C capabilities: ["appPackage","clearSystemFiles","loggingPrefs","disableAndroidWatchers","language","locale","unlockKey","newCommandTimeout",
"platformVersion","automationName","unlockType","unicodeKeyboard","resetKeyboard","appActivity","autoLaunch","autoGrantPermissions","chromeOptions"]
2021-10-13 21:05:37:410 - [Appium] Trying to fix W3C capabilities by merging them with JSONWP caps
2021-10-13 21:05:37:411 - [BaseDriver] The following capabilities are not standard capabilities and should have an extension prefix:
2021-10-13 21:05:37:411 - [BaseDriver]   appPackage
2021-10-13 21:05:37:411 - [BaseDriver]   clearSystemFiles
2021-10-13 21:05:37:411 - [BaseDriver]   disableAndroidWatchers
2021-10-13 21:05:37:411 - [BaseDriver]   language
2021-10-13 21:05:37:411 - [BaseDriver]   locale
2021-10-13 21:05:37:411 - [BaseDriver]   unlockKey
2021-10-13 21:05:37:411 - [BaseDriver]   newCommandTimeout
2021-10-13 21:05:37:411 - [BaseDriver]   platformVersion
2021-10-13 21:05:37:411 - [BaseDriver]   automationName
2021-10-13 21:05:37:411 - [BaseDriver]   unlockType
2021-10-13 21:05:37:411 - [BaseDriver]   unicodeKeyboard
2021-10-13 21:05:37:411 - [BaseDriver]   resetKeyboard
2021-10-13 21:05:37:411 - [BaseDriver]   appActivity
2021-10-13 21:05:37:411 - [BaseDriver]   autoLaunch
2021-10-13 21:05:37:411 - [BaseDriver]   autoGrantPermissions
2021-10-13 21:05:37:411 - [BaseDriver]   deviceName
2021-10-13 21:05:37:411 - [BaseDriver]   udid
2021-10-13 21:05:37:411 - [BaseDriver]   systemPort
2021-10-13 21:05:37:411 - [BaseDriver]   wdaLocalPort
2021-10-13 21:05:37:413 - [Appium] Appium v1.22.0 creating new AndroidUiautomator2Driver (v1.70.1) session
2021-10-13 21:05:37:413 - [debug] [Appium] There are no active sessions for cleanup
2021-10-13 21:05:37:416 - [Appium] Applying relaxed security to 'AndroidUiautomator2Driver' as per server command line argument. All insecure features will be enabled unless explicitly disabled by --deny-insecure
2021-10-13 21:05:37:417 - [debug] [BaseDriver] W3C capabilities and MJSONWP desired capabilities were provided
2021-10-13 21:05:37:417 - [debug] [BaseDriver] Creating session with W3C capabilities: {
2021-10-13 21:05:37:417 - [debug] [BaseDriver]   "alwaysMatch": {
2021-10-13 21:05:37:417 - [debug] [BaseDriver]     "appium:appPackage": "com.android.settings",
2021-10-13 21:05:37:417 - [debug] [BaseDriver]     "appium:clearSystemFiles": false,
2021-10-13 21:05:37:417 - [debug] [BaseDriver]     "appium:disableAndroidWatchers": true,
2021-10-13 21:05:37:417 - [debug] [BaseDriver]     "appium:language": "en",
2021-10-13 21:05:37:417 - [debug] [BaseDriver]     "appium:locale": "US",
2021-10-13 21:05:37:417 - [debug] [BaseDriver]     "appium:unlockKey": "1111",
2021-10-13 21:05:37:417 - [debug] [BaseDriver]     "appium:newCommandTimeout": 45,
2021-10-13 21:05:37:417 - [debug] [BaseDriver]     "appium:platformVersion": "*",
2021-10-13 21:05:37:417 - [debug] [BaseDriver]     "appium:automationName": "UIAutomator2",
2021-10-13 21:05:37:417 - [debug] [BaseDriver]     "appium:unlockType": "pin",
2021-10-13 21:05:37:417 - [debug] [BaseDriver]     "appium:unicodeKeyboard": true,
2021-10-13 21:05:37:417 - [debug] [BaseDriver]     "appium:resetKeyboard": true,
2021-10-13 21:05:37:417 - [debug] [BaseDriver]     "appium:appActivity": "com.android.settings.Settings",
2021-10-13 21:05:37:417 - [debug] [BaseDriver]     "appium:autoLaunch": false,
2021-10-13 21:05:37:419 - [debug] [BaseDriver]     "appium:autoGrantPermissions": true,
2021-10-13 21:05:37:419 - [debug] [BaseDriver]     "browserName": "",
2021-10-13 21:05:37:419 - [debug] [BaseDriver]     "goog:chromeOptions": {
2021-10-13 21:05:37:419 - [debug] [BaseDriver]       "w3c": false,
2021-10-13 21:05:37:419 - [debug] [BaseDriver]       "androidPackage": "com.tripadvisor.tripadvisor.prerelease"
2021-10-13 21:05:37:419 - [debug] [BaseDriver]     },
2021-10-13 21:05:37:419 - [debug] [BaseDriver]     "platformName": "android",
2021-10-13 21:05:37:420 - [debug] [BaseDriver]     "server:CONFIG_UUID": "cc5da938-fc08-4847-ae08-cf988b7f06e0",
2021-10-13 21:05:37:420 - [debug] [BaseDriver]     "tripadvisor:node.defaultDevice": true,
2021-10-13 21:05:37:420 - [debug] [BaseDriver]     "tripadvisor:node.platformType": "Phone",
2021-10-13 21:05:37:420 - [debug] [BaseDriver]     "tripadvisor:testng.hostname": "bedouglas-mac",
2021-10-13 21:05:37:420 - [debug] [BaseDriver]     "tripadvisor:testng.session.hash": "bbf67542-4f9a-47e9-9f39-369f33c63006",
2021-10-13 21:05:37:420 - [debug] [BaseDriver]     "tripadvisor:testng.suite": "Default Suite",
2021-10-13 21:05:37:420 - [debug] [BaseDriver]     "tripadvisor:testng.test": "testHotelTAPlusBooking",
2021-10-13 21:05:37:420 - [debug] [BaseDriver]     "workaround:loggingPrefs": {
2021-10-13 21:05:37:420 - [debug] [BaseDriver]       "browser": "ALL"
2021-10-13 21:05:37:420 - [debug] [BaseDriver]     },
2021-10-13 21:05:37:420 - [debug] [BaseDriver]     "appium:deviceName": "accf5280",
2021-10-13 21:05:37:420 - [debug] [BaseDriver]     "appium:udid": "accf5280",
2021-10-13 21:05:37:420 - [debug] [BaseDriver]     "appium:systemPort": 7823,
2021-10-13 21:05:37:420 - [debug] [BaseDriver]     "appium:wdaLocalPort": 7823
2021-10-13 21:05:37:420 - [debug] [BaseDriver]   },
2021-10-13 21:05:37:420 - [debug] [BaseDriver]   "firstMatch": [
2021-10-13 21:05:37:420 - [debug] [BaseDriver]     {}
2021-10-13 21:05:37:420 - [debug] [BaseDriver]   ]
2021-10-13 21:05:37:420 - [debug] [BaseDriver] }

have you tried to put it under appium:loggingPrefs capability?

Tried that. It doesn’t show browser as an option for getting logs, and there is no output in logcat either.

2021-10-14 13:19:35:887 - [HTTP] --> GET /wd/hub/session/9b232160-65ee-49d4-b2b4-ee177fff54a1/log/types
2021-10-14 13:19:35:887 - [HTTP] {}
2021-10-14 13:19:35:888 - [debug] [W3C (9b232160)] Calling AppiumDriver.getLogTypes() with args: ["9b232160-65ee-49d4-b2b4-ee177fff54a1"]
2021-10-14 13:19:35:888 - [debug] [BaseDriver] Retrieving supported log types\
2021-10-14 13:19:35:888 - [debug] [W3C (9b232160)] Responding to client with driver.getLogTypes() result: ["logcat","bugreport","server"]
2021-10-14 13:19:35:888 - [HTTP] <-- GET /wd/hub/session/9b232160-65ee-49d4-b2b4-ee177fff54a1/log/types 200 1 ms - 41

you should be in web context to be able to fetch browser logs

Closer, but nothing in the log :frowning:

2021-10-14 17:09:36:004 - [HTTP] --> GET /wd/hub/session/b819ecb8-6144-4efd-8f2e-f426447e48d3/log/types
2021-10-14 17:09:36:004 - [HTTP] {}
2021-10-14 17:09:36:004 - [debug] [W3C (b819ecb8)] Calling AppiumDriver.getLogTypes() with args: ["b819ecb8-6144-4efd-8f2e-f426447e48d3"]
2021-10-14 17:09:36:004 - [debug] [BaseDriver] Retrieving supported log types
2021-10-14 17:09:36:005 - [debug] [WD Proxy] Matched '/log/types' to command name 'getLogTypes'
2021-10-14 17:09:36:005 - [debug] [WD Proxy] Proxying [GET /log/types] to [GET http://127.0.0.1:8001/wd/hub/session/26ab01fffedbf4a85a09d6d0eae1d322/log/types] with no body
2021-10-14 17:09:36:006 - [debug] [WD Proxy] Got response with status 200: {"sessionId":"26ab01fffedbf4a85a09d6d0eae1d322","status":0,"value":["browser","driver"]}
2021-10-14 17:09:36:006 - [debug] [W3C (b819ecb8)] Responding to client with driver.getLogTypes() result: ["logcat","bugreport","server","browser","driver"]
2021-10-14 17:09:36:007 - [HTTP] <-- GET /wd/hub/session/b819ecb8-6144-4efd-8f2e-f426447e48d3/log/types 200 3 ms - 60
2021-10-14 17:09:36:007 - [HTTP]
2021-10-14 17:09:36:013 - [HTTP] --> POST /wd/hub/session/b819ecb8-6144-4efd-8f2e-f426447e48d3/log
2021-10-14 17:09:36:014 - [HTTP] {"type":"browser"}
2021-10-14 17:09:36:014 - [debug] [W3C (b819ecb8)] Calling AppiumDriver.getLog() with args: ["browser","b819ecb8-6144-4efd-8f2e-f426447e48d3"]
2021-10-14 17:09:36:014 - [debug] [WD Proxy] Matched '/log' to command name 'getLog'
2021-10-14 17:09:36:014 - [debug] [WD Proxy] Proxying [POST /log] to [POST http://127.0.0.1:8001/wd/hub/session/26ab01fffedbf4a85a09d6d0eae1d322/log] with body: {"type":"browser"}
2021-10-14 17:09:36:026 - [debug] [WD Proxy] Got response with status 200: {"sessionId":"26ab01fffedbf4a85a09d6d0eae1d322","status":0,"value":[]}
2021-10-14 17:09:36:026 - [debug] [W3C (b819ecb8)] Responding to client with driver.getLog() result: []
2021-10-14 17:09:36:027 - [HTTP] <-- POST /wd/hub/session/b819ecb8-6144-4efd-8f2e-f426447e48d3/log 200 13 ms - 12

Appium log starting up chromedriver, looks like the parameter is getting to chromedriver, but we’re either not finding the logs, or not capturing them

2021-10-14 17:09:18:398 - [Chromedriver] Spawning chromedriver with: /Users/bdouglas/build_tools/android_phone/accf5280/chromedriver --url-base=wd/hub --port=8001 --adb-port=5037 --verbose
2021-10-14 17:09:18:410 - [HTTP] --> GET /wd/hub/status
2021-10-14 17:09:18:411 - [HTTP] {}
2021-10-14 17:09:18:411 - [debug] [GENERIC] Calling AppiumDriver.getStatus() with args: []
2021-10-14 17:09:18:411 - [debug] [GENERIC] Responding to client with driver.getStatus() result: {"build":{"version":"1.22.0"}}
2021-10-14 17:09:18:412 - [HTTP] <-- GET /wd/hub/status 200 1 ms - 68
2021-10-14 17:09:18:412 - [HTTP] 
2021-10-14 17:09:18:428 - [debug] [Chromedriver] Chromedriver version: '77.0.3865.40'
2021-10-14 17:09:18:428 - [Chromedriver] Chromedriver v. 77.0.3865.40 supports W3C protocol, but MJSONWP one has been explicitly requested
2021-10-14 17:09:18:429 - [debug] [WD Proxy] Matched '/status' to command name 'getStatus'
2021-10-14 17:09:18:429 - [debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8001/wd/hub/status] with no body
2021-10-14 17:09:18:430 - [WD Proxy] connect ECONNREFUSED 127.0.0.1:8001
2021-10-14 17:09:18:632 - [debug] [WD Proxy] Matched '/status' to command name 'getStatus'
2021-10-14 17:09:18:632 - [debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8001/wd/hub/status] with no body
2021-10-14 17:09:18:640 - [debug] [WD Proxy] Got response with status 200: {"value":{"build":{"version":"77.0.3865.40 (f484704e052e0b556f8030b65b953dce96503217-refs/branch-heads/[email protected]{#442})"},"message":"ChromeDriver ready for new sessions.","os":{"arch":"x86_64","name":"Mac OS X","version":"10.16.0"},"ready":true}}
2021-10-14 17:09:18:640 - [Chromedriver] Starting MJSONWP Chromedriver session with capabilities: {
2021-10-14 17:09:18:640 - [Chromedriver]   "desiredCapabilities": {
2021-10-14 17:09:18:640 - [Chromedriver]     "chromeOptions": {
2021-10-14 17:09:18:640 - [Chromedriver]       "androidPackage": "com.tripadvisor.tripadvisor.prerelease",
2021-10-14 17:09:18:640 - [Chromedriver]       "androidUseRunningApp": true,
2021-10-14 17:09:18:640 - [Chromedriver]       "androidProcess": "com.tripadvisor.tripadvisor.prerelease",
2021-10-14 17:09:18:640 - [Chromedriver]       "androidDeviceSerial": "accf5280",
2021-10-14 17:09:18:640 - [Chromedriver]       "w3c": false
2021-10-14 17:09:18:640 - [Chromedriver]     },
2021-10-14 17:09:18:640 - [Chromedriver]     "loggingPrefs": {
2021-10-14 17:09:18:640 - [Chromedriver]       "browser": "ALL"
2021-10-14 17:09:18:640 - [Chromedriver]     }
2021-10-14 17:09:18:640 - [Chromedriver]   }
2021-10-14 17:09:18:640 - [Chromedriver] }
2021-10-14 17:09:18:640 - [debug] [WD Proxy] Matched '/session' to command name 'createSession'
2021-10-14 17:09:18:640 - [debug] [WD Proxy] Proxying [POST /session] to [POST http://127.0.0.1:8001/wd/hub/session] with body: {"desiredCapabilities":{"chromeOptions":{"androidPackage":"com.tripadvisor.tripadvisor.prerelease","androidUseRunningApp":true,"androidProcess":"com.tripadvisor.tripadvisor.prerelease","androidDeviceSerial":"accf5280","w3c":false},"loggingPrefs":{"browser":"ALL"}}}
2021-10-14 17:09:20:309 - [debug] [Chromedriver] Webview version: 'Chrome/77.0.3865.92'
2021-10-14 17:09:20:415 - [debug] [WD Proxy] Got response with status 200: {"sessionId":"26ab01fffedbf4a85a09d6d0eae1d322","status":0,"value":{"acceptInsecureCerts":false,"acceptSslCerts":false,"applicationCacheEnabled":false,"browserConnectionEnabled":false,"browserName":"chrome","chrome":{"chromedriverVersion":"77.0.3865.40 (f484704e052e0b556f8030b65b953dce96503217-refs/branch-heads/[email protected]{#442})"},"cssSelectorsEnabled":true,"databaseEnabled":false,"goog:chromeOptions":{"debuggerAddress":"localhost:50865"},"handlesAlerts":true,"hasTouchScreen":true,"javascriptEnabled":true,"locationContextEnabled":true,"mobileEmulationEnabled":false,"nativeEvents":true,"pageLoadStrategy":"normal","platform":"ANDROID","proxy":{},"rotatable":false,"setWindowRect":false,"strictFileInteractability":false,"takesHeapSnapshot":true,"takesScreenshot":true,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"unexpectedAlertBehaviour":"ignore","version":"77.0.3865.92","webStorageEnabled":true}}
2021-10-14 17:09:20:415 - [WD Proxy] Determined the downstream protocol as 'MJSONWP'
2021-10-14 17:09:20:415 - [debug] [Chromedriver] Changed state to 'online'
2021-10-14 17:09:20:415 - [debug] [W3C (b819ecb8)] Responding to client with driver.setContext() result: null
2021-10-14 17:09:20:416 - [HTTP] <-- POST /wd/hub/session/b819ecb8-6144-4efd-8f2e-f426447e48d3/context 200 2486 ms - 14

Ah, I see that this is literally the browser logs inside the webview. Is there a way to get the output of chromedriver? We’re failing to find an element inside an iframe in the webview, and I want to know what it thinks it’s trying to do.

Maybe try showChromedriverLog capability?

I figured it out, I didn’t pass in the driver level in the loggingPrefs. Good to go now! Thanks!