adb error: couldn't create file: Permission denied

[AlexandraMoga]

System

• Version: v0.32.2-win32
• Platform: Windows 10
• Firefox: Firefox Nightly 112.0a1 (Build #2015933405),
• Appium: v2.0.0-beta.56 (Python client)

Testcase

I'm simply traying to launch Firefox on an android device (Pixel 5, Android 11 emulator with Android studio) using the capabilities suggested in this documentation but the session hangs and finally exists with error adb error: couldn't create file: Permission denied. I'm not sure if there is some issue at my side (capabilities are visible in the stacktrace) or if this is a geckodriver issue.

Stacktrace

[HTTP] --> POST /session
[HTTP] {"capabilities":{"firstMatch":[{}],"alwaysMatch":{"appium:automationName":"Gecko","browserName":"Firefox","platformName":"windows","moz:firefoxOptions":{"androidPackage":"org.mozilla.fenix"}}}}
[debug] [AppiumDriver@20f2] Calling AppiumDriver.createSession() with args: [null,null,{"firstMatch":[{}],"alwaysMatch":{"appium:automationName":"Gecko","browserName":"Firefox","platformName":"windows","moz:firefoxOptions":{"androidPackage":"org.mozilla.fenix"}}}]
[debug] [AppiumDriver@20f2] Event 'newSessionRequested' logged at 1677594344443 (16:25:44 GMT+0200 (Eastern European Standard Time))
[Appium] Attempting to find matching driver for automationName 'Gecko' and platformName 'windows'
[Appium] The 'gecko' driver was installed and matched caps.
[Appium] Will require it at C:\Users\USER\.appium\node_modules\appium-geckodriver
[debug] [Appium] Requiring driver at C:\Users\USER\.appium\node_modules\appium-geckodriver
[AppiumDriver@20f2] Appium v2.0.0-beta.56 creating new GeckoDriver (v1.1.8) session
[AppiumDriver@20f2] Checking BaseDriver versions for Appium and GeckoDriver
[AppiumDriver@20f2] Appium's BaseDriver version is 9.3.2
[AppiumDriver@20f2] GeckoDriver's BaseDriver version is 9.3.2
[debug] [GeckoDriver@7133] Creating session with W3C capabilities: {
[debug] [GeckoDriver@7133]   "alwaysMatch": {
[debug] [GeckoDriver@7133]     "browserName": "Firefox",
[debug] [GeckoDriver@7133]     "platformName": "windows",
[debug] [GeckoDriver@7133]     "moz:firefoxOptions": {
[debug] [GeckoDriver@7133]       "androidPackage": "org.mozilla.fenix"
[debug] [GeckoDriver@7133]     },
[debug] [GeckoDriver@7133]     "appium:automationName": "Gecko"
[debug] [GeckoDriver@7133]   },
[debug] [GeckoDriver@7133]   "firstMatch": [
[debug] [GeckoDriver@7133]     {}
[debug] [GeckoDriver@7133]   ]
[debug] [GeckoDriver@7133] }
[GeckoDriver@7133 (736c9dd5)] Session created with session id: 736c9dd5-c0c3-4a40-99e2-a14304080bab
[GeckoDriver@7133 (736c9dd5)] Starting 'C:\Users\USER\AppData\Local\Programs\Python\Python39\geckodriver.exe' with args ["-p",5200]
[debug] [GeckoDriver@7133 (736c9dd5)] Matched '/status' to command name 'getStatus'
[debug] [GeckoDriver@7133 (736c9dd5)] Proxying [GET /status] to [GET http://127.0.0.1:5200/status] with no body
[GeckoDriver@7133 (736c9dd5)] connect ECONNREFUSED 127.0.0.1:5200
[debug] [GeckoDriver@7133 (736c9dd5)] [geckodriver.exe] 1677594345068   geckodriver     INFO    Listening on 127.0.0.1:5200
[debug] [GeckoDriver@7133 (736c9dd5)] Matched '/status' to command name 'getStatus'
[debug] [GeckoDriver@7133 (736c9dd5)] Proxying [GET /status] to [GET http://127.0.0.1:5200/status] with no body
[debug] [GeckoDriver@7133 (736c9dd5)] Got response with status 200: {"value":{"message":"","ready":true}}
[debug] [GeckoDriver@7133 (736c9dd5)] Matched '/session' to command name 'createSession'
[debug] [GeckoDriver@7133 (736c9dd5)] Proxying [POST /session] to [POST http://127.0.0.1:5200/session] with body: {"capabilities":{"firstMatch":[{}],"alwaysMatch":{"browserName":"firefox","platformName":"windows","moz:firefoxOptions":{"androidPackage":"org.mozilla.fenix"}}}}
[debug] [GeckoDriver@7133 (736c9dd5)] [geckodriver.exe] 1677594353781   mozdevice       INFO    Device is rooted
[GeckoDriver@7133 (736c9dd5)] Got response with status 500: {"value":{"error":"unknown error","message":"adb error: couldn't create file: Permission denied","stacktrace":""}}
[debug] [W3C] Matched W3C error code 'unknown error' to UnknownError
[GeckoDriver@7133 (736c9dd5)] Ending Gecko Driver session
[GeckoDriver@7133 (736c9dd5)] geckodriver.exe has exited with code null, signal SIGTERM
[debug] [AppiumDriver@20f2] Event 'newSessionStarted' logged at 1677594393012 (16:26:33 GMT+0200 (Eastern European Standard Time))
[debug] [AppiumDriver@20f2] Encountered internal error running command: UnknownError: An unknown server-side error occurred while processing the command. Original error: adb error: couldn't create file: Permission denied
[debug] [AppiumDriver@20f2]     at errorFromW3CJsonCode (C:\Users\USER\AppData\Roaming\nvm\v18.14.2\node_modules\appium\node_modules\@appium\base-driver\lib\protocol\errors.js:1034:25)
[debug] [AppiumDriver@20f2]     at ProxyRequestError.getActualError (C:\Users\USER\AppData\Roaming\nvm\v18.14.2\node_modules\appium\node_modules\@appium\base-driver\lib\protocol\errors.js:909:14)
[debug] [AppiumDriver@20f2]     at GeckoProxy.command (C:\Users\USER\AppData\Roaming\nvm\v18.14.2\node_modules\appium\node_modules\@appium\base-driver\lib\jsonwp-proxy\proxy.js:340:19)
[debug] [AppiumDriver@20f2]     at processTicksAndRejections (node:internal/process/task_queues:95:5)
[debug] [AppiumDriver@20f2]     at GeckoDriverServer.start (C:\Users\USER\.appium\node_modules\appium-geckodriver\lib\gecko.js:205:5)
[debug] [AppiumDriver@20f2]     at GeckoDriver.createSession (C:\Users\USER\.appium\node_modules\appium-geckodriver\lib\driver.js:58:7)
[debug] [AppiumDriver@20f2]     at AppiumDriver.createSession (C:\Users\USER\AppData\Roaming\nvm\v18.14.2\node_modules\appium\lib\appium.js:349:35)
[HTTP] <-- POST /session 500 48605 ms - 1369

[whimboo]

Could you please attach the adb logcat which was created while running the above snippet? It would be needed given that we don't seem to be able to include error details. Thanks.

[AlexandraMoga]

@whimboo this is the output from adb logcat when trying to start a session with the configuration mentioned:

03-01 12:30:20.181   524  1026 I ActivityManager: Force stopping org.mozilla.fenix appid=10122 user=0: clear data
03-01 12:30:20.184   524   553 I ActivityManager: Force stopping org.mozilla.fenix appid=10122 user=-1: clearApplicationUserData
03-01 12:30:20.185  1392  1436 I MediaProvider: Invalidating LocalCallingIdentity cache for package org.mozilla.fenix. Reason: op android:read_external_storage
03-01 12:30:20.193   427   427 I keystore: clear_uid 10122
03-01 12:30:20.196 11065 11067 I cmd     : oneway function results will be dropped but finished with status OK and parcel size 4
03-01 12:30:20.200   677   677 V AvrcpMediaPlayerList: mPackageChangedBroadcastReceiver: action: android.intent.action.PACKAGE_DATA_CLEARED
03-01 12:30:20.200  1196  1196 I GeofencerStateMachine: removeGeofences: removeRequest=RemoveGeofencingRequest[REMOVE_ALL packageName=org.mozilla.fenix]
03-01 12:30:20.200   524   552 E system_server: No package ID 7f found for ID 0x7f080169.
03-01 12:30:20.200   524   552 E system_server: No package ID 7f found for ID 0x7f1201df.
03-01 12:30:20.200   524   552 E system_server: No package ID 7f found for ID 0x7f1201df.
03-01 12:30:20.200   524   552 E system_server: No package ID 7f found for ID 0x7f080167.
03-01 12:30:20.200   524   552 E system_server: No package ID 7f found for ID 0x7f1201de.
03-01 12:30:20.200   524   552 E system_server: No package ID 7f found for ID 0x7f1201de.
03-01 12:30:20.203   932   932 D CarrierSvcBindHelper: No carrier app for: 0
03-01 12:30:20.224  1392  2566 I MediaProvider: Begin Intent { act=android.intent.action.PACKAGE_DATA_CLEARED dat=package:org.mozilla.fenix flg=0x1000010 cmp=com.android.providers.media.module/com.android.providers.media.MediaService (has extras) }
03-01 12:30:20.229  1392  2566 I MediaProvider: End Intent { act=android.intent.action.PACKAGE_DATA_CLEARED dat=package:org.mozilla.fenix flg=0x1000010 cmp=com.android.providers.media.module/com.android.providers.media.MediaService (has extras) }
03-01 12:30:20.231  1196 11071 I Fitness : FitCleanupIntentOperation received Intent android.intent.action.PACKAGE_DATA_CLEARED [CONTEXT service_id=17 ]
03-01 12:30:20.232   524   558 E libprocessgroup: AddTidToCgroup failed to write '11074'; fd=66: Invalid argument
03-01 12:30:20.232   524   558 E libprocessgroup: Failed to add task into cgroup
03-01 12:30:20.232   524   558 W libprocessgroup: ExecuteForTask failed for aggregate profile: Invalid argument
03-01 12:30:20.242  1530  8226 I Icing   : doRemovePackageData org.mozilla.fenix [CONTEXT service_id=21 ]
03-01 12:30:22.268  1392  1424 I MediaProvider: Invalidating LocalCallingIdentity cache for package org.mozilla.fenix. Reason: op android:read_external_storage
03-01 12:30:22.443   524  1026 D WifiNl80211Manager: Scan result ready event
03-01 12:30:22.443   524  1026 D WifiNative: Scan result ready event
03-01 12:30:40.914   386   386 I /apex/com.android.adbd/bin/adbd: type=1400 audit(0.0:2518): avc: denied { search } for comm=73796E6320737663203631 name="oem" dev="dm-4" ino=42 scontext=u:r:adbd:s0 tcontext=u:object_r:oemfs:s0 tclass=dir permissive=1
03-01 12:30:43.022 11108 11110 I cmd     : oneway function results will be dropped but finished with status OK and parcel size 4

[whimboo]

This is only an excerpt given that it misses all the geckodriver log output. Can you repeat again but start geckodriver with the -vv option? This will enable trace logs which hopefully give more information.

[AlexandraMoga]

@whimboo These are the captured logs when running geckodriver with log level trace:
geckodriver-appium.txt

[whimboo]

Hm, this log is really strange. The last successful command that I can see is that geckodriver tries to set the permissions for the Firefox profile to 777 but then something failed and we clean-up the device. Strangely I cannot see the command that failed here.

[debug] [GeckoDriver@03b7 (1d39ac55)] [geckodriver.exe] 1677837573945   mozdevice       TRACE   execute_host_command: >> "host:transport:emulator-5554"
[debug] [GeckoDriver@03b7 (1d39ac55)] [geckodriver.exe] 1677837573945   mozdevice       TRACE   execute_host_command: << []
[debug] [GeckoDriver@03b7 (1d39ac55)] 1677837573945     mozdevice       TRACE   execute_host_command: >> "shell:su 0 chmod  -R 777 /sdcard/Android/data/org.mozilla.fenix/files/test_root/org.mozilla.fenix-geckodriver-profile"
[debug] [GeckoDriver@03b7 (1d39ac55)] [geckodriver.exe] 1677837573968   mozdevice       TRACE   execute_host_command: << ""
[debug] [GeckoDriver@03b7 (1d39ac55)] [geckodriver.exe] 1677837578107   mozdevice       TRACE   execute_host_command: >> "host:transport:emulator-5554"
[debug] [GeckoDriver@03b7 (1d39ac55)] [geckodriver.exe] 1677837578108   mozdevice       TRACE   execute_host_command: << []
[debug] [GeckoDriver@03b7 (1d39ac55)] 1677837578108     mozdevice       TRACE   execute_host_command: >> "shell:su 0 am clear-debug-app org.mozilla.fenix"
[debug] [GeckoDriver@03b7 (1d39ac55)] [geckodriver.exe] 1677837578162   mozdevice       TRACE   execute_host_command: << ""

Could you please also attach the corresponding adb logcat with not removing too much content? Thanks.

[AlexandraMoga]

Sorry @whimboo but I'm not seeing any geckodriver logs in the adb logcat output generated when I'm running my script:
adb logcat.txt

[whimboo]

Sorry for dropping the ball on this issue. Is that still a problem with the recent versions of Firefox and geckodriver?