Closed
Bug 1828687
Opened 3 years ago
Closed 3 years ago
Intermittent /webdriver/tests/bidi/log/entry_added/event_buffer.py | test_console_log_cached_messages[console_api_log] - assert 0 == 1
Categories
(Remote Protocol :: WebDriver BiDi, defect, P5)
Remote Protocol
WebDriver BiDi
Tracking
(Not tracked)
RESOLVED
DUPLICATE
of bug 1828108
People
(Reporter: intermittent-bug-filer, Unassigned)
Details
(Keywords: intermittent-failure)
Filed by: ctuns [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=412831994&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/LEwcrJ2iSdSCAXwhyJD_Mw/runs/0/artifacts/public/logs/live_backing.log
[task 2023-04-18T11:18:33.171Z] 11:18:33 INFO - TEST-START | /webdriver/tests/bidi/log/entry_added/event_buffer.py
[task 2023-04-18T11:18:33.171Z] 11:18:33 INFO - PID 2103 | 1681816713162 geckodriver::android DEBUG Marionette port forward (44217 -> 2829) stopped
[task 2023-04-18T11:18:33.171Z] 11:18:33 INFO - PID 2103 | 1681816713162 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:33.171Z] 11:18:33 INFO - PID 2103 | 1681816713162 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:33.172Z] 11:18:33 INFO - PID 2103 | 1681816713162 mozdevice TRACE execute_host_command: >> "host-serial:emulator-5554:killforward:tcp:9222"
[task 2023-04-18T11:18:33.172Z] 11:18:33 INFO - PID 2103 | 1681816713162 mozdevice TRACE execute_host_command: << ""
[task 2023-04-18T11:18:33.173Z] 11:18:33 INFO - PID 2103 | 1681816713162 geckodriver::android DEBUG WebSocket port forward (9222 -> 9222) stopped
[task 2023-04-18T11:18:33.173Z] 11:18:33 INFO - PID 2103 | 1681816713162 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:33.224Z] 11:18:33 INFO - STDOUT: ============================= test session starts ==============================
[task 2023-04-18T11:18:33.224Z] 11:18:33 INFO - STDOUT: platform linux -- Python 3.7.5, pytest-7.0.1, pluggy-unknown -- /builds/worker/workspace/build/venv/bin/python
[task 2023-04-18T11:18:33.226Z] 11:18:33 INFO - STDOUT: rootdir: /builds/worker/workspace/build
[task 2023-04-18T11:18:33.226Z] 11:18:33 INFO - STDOUT: plugins: asyncio-0.19.0
[task 2023-04-18T11:18:33.227Z] 11:18:33 INFO - STDOUT: asyncio: mode=strict
[task 2023-04-18T11:18:33.227Z] 11:18:33 INFO - STDOUT: collecting ...
[task 2023-04-18T11:18:33.235Z] 11:18:33 INFO - STDOUT: collected 4 items
[task 2023-04-18T11:18:33.235Z] 11:18:33 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/bidi/log/entry_added/event_buffer.py::test_console_log_cached_messages[console_api_log]
[task 2023-04-18T11:18:33.236Z] 11:18:33 INFO - PID 2103 | 1681816713235 webdriver::server DEBUG -> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "/tmp/tmpo4emwgfw.mozrunner"] ... RASHREPORTER": "1", "MOZ_CRASHREPORTER_SHUTDOWN": "1", "STYLO_THREADS": "1", "RUST_BACKTRACE": "1"}}, "webSocketUrl": true}}}
[task 2023-04-18T11:18:33.237Z] 11:18:33 INFO - PID 2103 | 1681816713236 mozdevice TRACE adb server response was "emulator-5554 device product:sdk_phone_x86_64 model:Android_SDK_built_for_x86_64 device:generic_x86_64 transport_id:2\n"
[task 2023-04-18T11:18:33.237Z] 11:18:33 INFO - PID 2103 | 1681816713236 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:33.237Z] 11:18:33 INFO - PID 2103 | 1681816713236 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:33.238Z] 11:18:33 INFO - PID 2103 | 1681816713236 mozdevice TRACE execute_host_command: >> "shell:id"
[task 2023-04-18T11:18:33.246Z] 11:18:33 INFO - PID 2103 | 1681816713244 mozdevice TRACE execute_host_command: << "uid=0(root) gid=0(root) groups=0(root),1004(input),1007(log),1011(adb),1015(sdcard_rw),1028(sdcard_r),3001(net_bt_admin),3002(net_bt),3003(inet),3006(net_bw_stats),3009(readproc) context=u:r:su:s0\n"
[task 2023-04-18T11:18:33.246Z] 11:18:33 INFO - PID 2103 | 1681816713245 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:33.246Z] 11:18:33 INFO - PID 2103 | 1681816713245 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:33.247Z] 11:18:33 INFO - PID 2103 | 1681816713245 mozdevice TRACE execute_host_command: >> "shell:su 0 id"
[task 2023-04-18T11:18:33.256Z] 11:18:33 INFO - PID 2103 | 1681816713255 mozdevice TRACE execute_host_command: << "uid=0(root) gid=0(root) groups=0(root),1004(input),1007(log),1011(adb),1015(sdcard_rw),1028(sdcard_r),3001(net_bt_admin),3002(net_bt),3003(inet),3006(net_bw_stats),3009(readproc) context=u:r:su:s0\n"
[task 2023-04-18T11:18:33.257Z] 11:18:33 INFO - PID 2103 | 1681816713255 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:33.257Z] 11:18:33 INFO - PID 2103 | 1681816713255 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:33.257Z] 11:18:33 INFO - PID 2103 | 1681816713255 mozdevice TRACE execute_host_command: >> "shell:su -c id"
[task 2023-04-18T11:18:33.264Z] 11:18:33 INFO - PID 2103 | 1681816713263 mozdevice TRACE execute_host_command: << "su: invalid uid/gid '-c'\n"
[task 2023-04-18T11:18:33.264Z] 11:18:33 INFO - PID 2103 | 1681816713263 mozdevice INFO Device is rooted
[task 2023-04-18T11:18:33.264Z] 11:18:33 INFO - PID 2103 | 1681816713263 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:33.265Z] 11:18:33 INFO - PID 2103 | 1681816713263 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:33.265Z] 11:18:33 INFO - PID 2103 | 1681816713263 mozdevice TRACE execute_host_command: >> "shell:setenforce permissive"
[task 2023-04-18T11:18:33.271Z] 11:18:33 INFO - PID 2103 | 1681816713271 mozdevice TRACE execute_host_command: << ""
[task 2023-04-18T11:18:33.272Z] 11:18:33 INFO - PID 2103 | 1681816713271 geckodriver::android DEBUG Marionette port forward (35181 -> 2829) started
[task 2023-04-18T11:18:33.272Z] 11:18:33 INFO - PID 2103 | 1681816713271 geckodriver::android DEBUG WebSocket port forward (9222 -> 9222) started
[task 2023-04-18T11:18:33.273Z] 11:18:33 INFO - PID 2103 | 1681816713271 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:33.273Z] 11:18:33 INFO - PID 2103 | 1681816713271 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:33.273Z] 11:18:33 INFO - PID 2103 | 1681816713271 mozdevice TRACE execute_host_command: >> "shell:echo $EXTERNAL_STORAGE"
[task 2023-04-18T11:18:33.278Z] 11:18:33 INFO - PID 2103 | 1681816713277 mozdevice TRACE execute_host_command: << "/sdcard\n"
[task 2023-04-18T11:18:33.278Z] 11:18:33 INFO - PID 2103 | 1681816713277 geckodriver::android DEBUG Connecting: options=AndroidOptions { activity: None, device_serial: Some("emulator-5554"), intent_arguments: Some(["-a", "and ... Auto }, storage=Sdcard) test_root=/sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root, run_as_package=None
[task 2023-04-18T11:18:33.278Z] 11:18:33 INFO - PID 2103 | 1681816713277 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:33.279Z] 11:18:33 INFO - PID 2103 | 1681816713277 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:33.279Z] 11:18:33 INFO - PID 2103 | 1681816713277 mozdevice TRACE execute_host_command: >> "shell:pm list packages org.mozilla.geckoview.test_runner"
[task 2023-04-18T11:18:33.484Z] 11:18:33 INFO - PID 2103 | 1681816713483 mozdevice TRACE execute_host_command: << "package:org.mozilla.geckoview.test_runner\n"
[task 2023-04-18T11:18:33.485Z] 11:18:33 INFO - PID 2103 | 1681816713484 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:33.485Z] 11:18:33 INFO - PID 2103 | 1681816713484 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:33.486Z] 11:18:33 INFO - PID 2103 | 1681816713484 mozdevice TRACE execute_host_command: >> "shell:cmd package resolve-activity --brief org.mozilla.geckoview.test_runner"
[task 2023-04-18T11:18:33.497Z] 11:18:33 INFO - PID 2103 | 1681816713496 mozdevice TRACE execute_host_command: << "priority=0 preferredOrder=0 match=0x108000 specificIndex=-1 isDefault=true\norg.mozilla.geckoview.test_runner/.App\n"
[task 2023-04-18T11:18:33.497Z] 11:18:33 INFO - PID 2103 | 1681816713496 geckodriver::browser DEBUG Backing up prefs to "/tmp/tmpo4emwgfw.mozrunner/user.geckodriver_backup"
[task 2023-04-18T11:18:33.500Z] 11:18:33 INFO - PID 2103 | 1681816713499 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:33.500Z] 11:18:33 INFO - PID 2103 | 1681816713499 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:33.500Z] 11:18:33 INFO - PID 2103 | 1681816713499 mozdevice TRACE execute_host_command: >> "shell:pm clear org.mozilla.geckoview.test_runner"
[task 2023-04-18T11:18:33.722Z] 11:18:33 INFO - PID 2103 | 1681816713721 mozdevice TRACE execute_host_command: << "Success\n"
[task 2023-04-18T11:18:33.723Z] 11:18:33 INFO - PID 2103 | 1681816713721 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:33.723Z] 11:18:33 INFO - PID 2103 | 1681816713721 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:33.723Z] 11:18:33 INFO - PID 2103 | 1681816713721 mozdevice TRACE execute_host_command: >> "shell:pm grant org.mozilla.geckoview.test_runner android.permission.READ_EXTERNAL_STORAGE"
[task 2023-04-18T11:18:33.922Z] 11:18:33 INFO - PID 2103 | 1681816713921 mozdevice TRACE execute_host_command: << ""
[task 2023-04-18T11:18:33.923Z] 11:18:33 INFO - PID 2103 | 1681816713922 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:33.923Z] 11:18:33 INFO - PID 2103 | 1681816713922 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:33.924Z] 11:18:33 INFO - PID 2103 | 1681816713922 mozdevice TRACE execute_host_command: >> "shell:pm grant org.mozilla.geckoview.test_runner android.permission.WRITE_EXTERNAL_STORAGE"
[task 2023-04-18T11:18:34.127Z] 11:18:34 INFO - PID 2103 | 1681816714126 mozdevice TRACE execute_host_command: << ""
[task 2023-04-18T11:18:34.128Z] 11:18:34 INFO - PID 2103 | 1681816714126 mozdevice DEBUG Creating /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root
[task 2023-04-18T11:18:34.128Z] 11:18:34 INFO - PID 2103 | 1681816714127 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:34.128Z] 11:18:34 INFO - PID 2103 | 1681816714127 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:34.129Z] 11:18:34 INFO - PID 2103 | 1681816714127 mozdevice TRACE execute_host_command: >> "shell:mkdir -p /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root"
[task 2023-04-18T11:18:34.138Z] 11:18:34 INFO - PID 2103 | 1681816714137 mozdevice TRACE execute_host_command: << ""
[task 2023-04-18T11:18:34.139Z] 11:18:34 INFO - PID 2103 | 1681816714138 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:34.139Z] 11:18:34 INFO - PID 2103 | 1681816714138 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:34.140Z] 11:18:34 INFO - PID 2103 | 1681816714138 mozdevice TRACE execute_host_command: >> "shell:chmod -R 777 /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root"
[task 2023-04-18T11:18:34.149Z] 11:18:34 INFO - PID 2103 | 1681816714149 mozdevice TRACE execute_host_command: << ""
[task 2023-04-18T11:18:34.150Z] 11:18:34 INFO - PID 2103 | 1681816714149 mozdevice DEBUG Deleting /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root/org.mozilla.geckoview.test_runner-geckodriver-profile
[task 2023-04-18T11:18:34.150Z] 11:18:34 INFO - PID 2103 | 1681816714149 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:34.151Z] 11:18:34 INFO - PID 2103 | 1681816714149 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:34.151Z] 11:18:34 INFO - PID 2103 | 1681816714149 mozdevice TRACE execute_host_command: >> "shell:rm -rf /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root/org.mozilla.geckoview.test_runner-geckodriver-profile"
[task 2023-04-18T11:18:34.157Z] 11:18:34 INFO - PID 2103 | 1681816714157 mozdevice TRACE execute_host_command: << ""
[task 2023-04-18T11:18:34.158Z] 11:18:34 INFO - PID 2103 | 1681816714157 mozdevice DEBUG Pushing /tmp/tmpo4emwgfw.mozrunner to /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root/org.mozilla.geckoview.test_runner-geckodriver-profile
[task 2023-04-18T11:18:34.159Z] 11:18:34 INFO - PID 2103 | 1681816714157 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:34.159Z] 11:18:34 INFO - PID 2103 | 1681816714157 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:34.159Z] 11:18:34 INFO - PID 2103 | 1681816714157 mozdevice TRACE execute_host_command: >> "shell:ls /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root/org.mozilla.geckoview.test_runner-geckodriver-profile"
[task 2023-04-18T11:18:34.166Z] 11:18:34 INFO - PID 2103 | 1681816714165 mozdevice TRACE execute_host_command: << "ls: /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root/org.mozilla.geckoview.test_runner-geckodriver-profile: No such file or directory\n"
[task 2023-04-18T11:18:34.167Z] 11:18:34 INFO - PID 2103 | 1681816714165 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:34.167Z] 11:18:34 INFO - PID 2103 | 1681816714165 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:34.168Z] 11:18:34 INFO - PID 2103 | 1681816714165 mozdevice TRACE execute_host_command: >> "shell:ls /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root"
[task 2023-04-18T11:18:34.176Z] 11:18:34 INFO - PID 2103 | 1681816714175 mozdevice TRACE execute_host_command: << ""
[task 2023-04-18T11:18:34.176Z] 11:18:34 INFO - PID 2103 | 1681816714175 mozdevice DEBUG Creating /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root/org.mozilla.geckoview.test_runner-geckodriver-profile
[task 2023-04-18T11:18:34.177Z] 11:18:34 INFO - PID 2103 | 1681816714175 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:34.177Z] 11:18:34 INFO - PID 2103 | 1681816714175 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:34.178Z] 11:18:34 INFO - PID 2103 | 1681816714175 mozdevice TRACE execute_host_command: >> "shell:mkdir -p /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root/org.mozilla.geckoview.test_runner-geckodriver-profile"
[task 2023-04-18T11:18:34.185Z] 11:18:34 INFO - PID 2103 | 1681816714185 mozdevice TRACE execute_host_command: << ""
[task 2023-04-18T11:18:34.186Z] 11:18:34 INFO - PID 2103 | 1681816714185 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:34.186Z] 11:18:34 INFO - PID 2103 | 1681816714185 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:34.187Z] 11:18:34 INFO - PID 2103 | 1681816714185 mozdevice TRACE execute_host_command: >> "shell:chmod -R 777 /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root/org.mozilla.geckoview.test_runner-geckodriver-profile"
[task 2023-04-18T11:18:34.196Z] 11:18:34 INFO - PID 2103 | 1681816714195 mozdevice TRACE execute_host_command: << ""
[task 2023-04-18T11:18:34.241Z] 11:18:34 INFO - PID 2103 | 1681816714240 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:34.242Z] 11:18:34 INFO - PID 2103 | 1681816714240 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:34.242Z] 11:18:34 INFO - PID 2103 | 1681816714240 mozdevice TRACE execute_host_command: >> "shell:ls /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root/org.mozilla.geckoview.test_runner-geckodriver-profile"
[task 2023-04-18T11:18:34.252Z] 11:18:34 INFO - PID 2103 | 1681816714252 mozdevice TRACE execute_host_command: << ""
[task 2023-04-18T11:18:34.298Z] 11:18:34 INFO - PID 2103 | 1681816714297 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:34.299Z] 11:18:34 INFO - PID 2103 | 1681816714297 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:34.299Z] 11:18:34 INFO - PID 2103 | 1681816714297 mozdevice TRACE execute_host_command: >> "shell:ls /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root/org.mozilla.geckoview.test_runner-geckodriver-profile"
[task 2023-04-18T11:18:34.311Z] 11:18:34 INFO - PID 2103 | 1681816714310 mozdevice TRACE execute_host_command: << "user.js\n"
[task 2023-04-18T11:18:34.357Z] 11:18:34 INFO - PID 2103 | 1681816714356 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:34.358Z] 11:18:34 INFO - PID 2103 | 1681816714356 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:34.358Z] 11:18:34 INFO - PID 2103 | 1681816714356 mozdevice TRACE execute_host_command: >> "shell:ls /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root/org.mozilla.geckoview.test_runner-geckodriver-profile"
[task 2023-04-18T11:18:34.370Z] 11:18:34 INFO - PID 2103 | 1681816714369 mozdevice TRACE execute_host_command: << "prefs.js user.js \n"
[task 2023-04-18T11:18:34.418Z] 11:18:34 INFO - PID 2103 | 1681816714417 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:34.418Z] 11:18:34 INFO - PID 2103 | 1681816714417 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:34.419Z] 11:18:34 INFO - PID 2103 | 1681816714417 mozdevice TRACE execute_host_command: >> "shell:ls /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root/org.mozilla.geckoview.test_runner-geckodriver-profile"
[task 2023-04-18T11:18:34.431Z] 11:18:34 INFO - PID 2103 | 1681816714431 mozdevice TRACE execute_host_command: << "prefs.js user.geckodriver_backup user.js \n"
[task 2023-04-18T11:18:34.478Z] 11:18:34 INFO - PID 2103 | 1681816714477 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:34.478Z] 11:18:34 INFO - PID 2103 | 1681816714477 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:34.479Z] 11:18:34 INFO - PID 2103 | 1681816714477 mozdevice TRACE execute_host_command: >> "shell:ls /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root/org.mozilla.geckoview.test_runner-geckodriver-profile"
[task 2023-04-18T11:18:34.491Z] 11:18:34 INFO - PID 2103 | 1681816714490 mozdevice TRACE execute_host_command: << "pkcs11.txt prefs.js user.geckodriver_backup user.js \n"
[task 2023-04-18T11:18:34.502Z] 11:18:34 INFO - PID 2103 | 1681816714501 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:34.502Z] 11:18:34 INFO - PID 2103 | 1681816714501 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:34.503Z] 11:18:34 INFO - PID 2103 | 1681816714501 mozdevice TRACE execute_host_command: >> "shell:ls /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root/org.mozilla.geckoview.test_runner-geckodriver-profile"
[task 2023-04-18T11:18:34.515Z] 11:18:34 INFO - PID 2103 | 1681816714514 mozdevice TRACE execute_host_command: << "cert9.db pkcs11.txt prefs.js user.geckodriver_backup user.js \n"
[task 2023-04-18T11:18:34.527Z] 11:18:34 INFO - PID 2103 | 1681816714526 geckodriver::android DEBUG Content of generated GeckoView config file:
[task 2023-04-18T11:18:34.527Z] 11:18:34 INFO - PID 2103 | ## GeckoView configuration YAML
[task 2023-04-18T11:18:34.528Z] 11:18:34 INFO - PID 2103 | ##
[task 2023-04-18T11:18:34.528Z] 11:18:34 INFO - PID 2103 | ## Auto-generated by geckodriver.
[task 2023-04-18T11:18:34.528Z] 11:18:34 INFO - PID 2103 | ## See https ... "--profile"
[task 2023-04-18T11:18:34.529Z] 11:18:34 INFO - PID 2103 | - /tmp/tmpo4emwgfw.mozrunner
[task 2023-04-18T11:18:34.529Z] 11:18:34 INFO - PID 2103 | - "--remote-debugging-port"
[task 2023-04-18T11:18:34.529Z] 11:18:34 INFO - PID 2103 | - "9222"
[task 2023-04-18T11:18:34.530Z] 11:18:34 INFO - PID 2103 | - "--remote-allow-hosts"
[task 2023-04-18T11:18:34.530Z] 11:18:34 INFO - PID 2103 | - localhost
[task 2023-04-18T11:18:34.530Z] 11:18:34 INFO - PID 2103 | 1681816714526 geckodriver::android DEBUG Pushing GeckoView configuration file to /data/local/tmp/org.mozilla.geckoview.test_runner-geckoview-config.yaml
[task 2023-04-18T11:18:34.531Z] 11:18:34 INFO - PID 2103 | 1681816714526 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:34.531Z] 11:18:34 INFO - PID 2103 | 1681816714527 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:34.532Z] 11:18:34 INFO - PID 2103 | 1681816714527 mozdevice TRACE execute_host_command: >> "shell:ls /data/local/tmp"
[task 2023-04-18T11:18:34.536Z] 11:18:34 INFO - PID 2103 | 1681816714535 mozdevice TRACE execute_host_command: << "test_root\n"
[task 2023-04-18T11:18:34.577Z] 11:18:34 INFO - PID 2103 | 1681816714576 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:34.577Z] 11:18:34 INFO - PID 2103 | 1681816714576 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:34.578Z] 11:18:34 INFO - PID 2103 | 1681816714576 mozdevice TRACE execute_host_command: >> "shell:am set-debug-app --persistent org.mozilla.geckoview.test_runner"
[task 2023-04-18T11:18:34.788Z] 11:18:34 INFO - PID 2103 | 1681816714787 mozdevice TRACE execute_host_command: << ""
[task 2023-04-18T11:18:34.788Z] 11:18:34 INFO - PID 2103 | 1681816714787 geckodriver::android DEBUG Launching org.mozilla.geckoview.test_runner/.App
[task 2023-04-18T11:18:34.788Z] 11:18:34 INFO - PID 2103 | 1681816714787 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:34.789Z] 11:18:34 INFO - PID 2103 | 1681816714787 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:34.789Z] 11:18:34 INFO - PID 2103 | 1681816714787 mozdevice TRACE execute_host_command: >> "shell:am start -W -n org.mozilla.geckoview.test_runner/.App -a android.intent.action.VIEW -d about: ... dcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root/org.mozilla.geckoview.test_runner-geckodriver-profile\""
[task 2023-04-18T11:18:35.872Z] 11:18:35 INFO - PID 2103 | 1681816715871 mozdevice TRACE execute_host_command: << "Starting: Intent { act=android.intent.action.VIEW dat=about:blank cmp=org.mozilla.geckoview.test_ru ... s) }\nStatus: ok\nActivity: org.mozilla.geckoview.test_runner/.App\nThisTime: 863\nTotalTime: 863\nWaitTime: 878\nComplete\n"
[task 2023-04-18T11:18:35.873Z] 11:18:35 INFO - PID 2103 | 1681816715871 geckodriver::marionette DEBUG Waiting 60s to connect to browser on 127.0.0.1
[task 2023-04-18T11:18:35.999Z] 11:18:35 INFO - PID 2103 | 1681816715998 geckodriver::marionette DEBUG Connection to Marionette established on 127.0.0.1:35181.
[task 2023-04-18T11:18:36.697Z] 11:18:36 INFO - PID 2103 | 1681816716695 webdriver::server DEBUG <- 200 OK {"value":{"sessionId":"9fbd684a-ef93-4562-82d4-18e3ae1058c4","capabilities":{"acceptInsecureCerts":false,"browserNa ... dledPromptBehavior":"dismiss and notify","webSocketUrl":"ws://127.0.0.1:9222/session/9fbd684a-ef93-4562-82d4-18e3ae1058c4"}}}
[task 2023-04-18T11:18:37.260Z] 11:18:37 INFO - STDOUT: FAILED
[task 2023-04-18T11:18:37.329Z] 11:18:37 INFO - PID 2103 | 1681816717328 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/timeouts {"implicit": 0}
[task 2023-04-18T11:18:37.347Z] 11:18:37 INFO - PID 2103 | 1681816717346 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:37.348Z] 11:18:37 INFO - PID 2103 | 1681816717347 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/timeouts {"pageLoad": 300000}
[task 2023-04-18T11:18:37.355Z] 11:18:37 INFO - PID 2103 | 1681816717354 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:37.355Z] 11:18:37 INFO - PID 2103 | 1681816717355 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/timeouts {"script": 30000}
[task 2023-04-18T11:18:37.362Z] 11:18:37 INFO - PID 2103 | 1681816717361 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:37.362Z] 11:18:37 INFO - PID 2103 | 1681816717362 webdriver::server DEBUG -> GET /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window
[task 2023-04-18T11:18:37.371Z] 11:18:37 INFO - PID 2103 | 1681816717370 webdriver::server DEBUG <- 200 OK {"value":"28ab66da-ea00-4dfa-bc21-f790b64bb17f"}
[task 2023-04-18T11:18:37.372Z] 11:18:37 INFO - PID 2103 | 1681816717371 webdriver::server DEBUG -> GET /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window
[task 2023-04-18T11:18:37.380Z] 11:18:37 INFO - PID 2103 | 1681816717379 webdriver::server DEBUG <- 200 OK {"value":"28ab66da-ea00-4dfa-bc21-f790b64bb17f"}
[task 2023-04-18T11:18:37.380Z] 11:18:37 INFO - PID 2103 | 1681816717380 webdriver::server DEBUG -> GET /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window/handles
[task 2023-04-18T11:18:37.387Z] 11:18:37 INFO - PID 2103 | 1681816717386 webdriver::server DEBUG <- 200 OK {"value":["28ab66da-ea00-4dfa-bc21-f790b64bb17f"]}
[task 2023-04-18T11:18:37.387Z] 11:18:37 INFO - PID 2103 | 1681816717387 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window {"handle": "28ab66da-ea00-4dfa-bc21-f790b64bb17f"}
[task 2023-04-18T11:18:37.395Z] 11:18:37 INFO - PID 2103 | 1681816717394 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:37.396Z] 11:18:37 INFO - PID 2103 | 1681816717395 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/alert/dismiss {}
[task 2023-04-18T11:18:37.403Z] 11:18:37 INFO - PID 2103 | 1681816717401 webdriver::server DEBUG <- 404 Not Found {"value":{"error":"no such alert","message":"","stacktrace":"RemoteError@chrome://remote/content/shared/Remo ... ontent/marionette/server.sys.mjs:249:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.sys.mjs:496:20\n"}}
[task 2023-04-18T11:18:37.403Z] 11:18:37 INFO - PID 2103 | 1681816717402 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window {"handle": "28ab66da-ea00-4dfa-bc21-f790b64bb17f"}
[task 2023-04-18T11:18:37.410Z] 11:18:37 INFO - PID 2103 | 1681816717409 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:37.411Z] 11:18:37 INFO - PID 2103 | 1681816717410 webdriver::server DEBUG -> GET /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window
[task 2023-04-18T11:18:37.418Z] 11:18:37 INFO - PID 2103 | 1681816717417 webdriver::server DEBUG <- 200 OK {"value":"28ab66da-ea00-4dfa-bc21-f790b64bb17f"}
[task 2023-04-18T11:18:37.418Z] 11:18:37 INFO - PID 2103 | 1681816717418 webdriver::server DEBUG -> GET /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window/handles
[task 2023-04-18T11:18:37.429Z] 11:18:37 INFO - PID 2103 | 1681816717428 webdriver::server DEBUG <- 200 OK {"value":["28ab66da-ea00-4dfa-bc21-f790b64bb17f"]}
[task 2023-04-18T11:18:37.430Z] 11:18:37 INFO - PID 2103 | 1681816717429 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window {"handle": "28ab66da-ea00-4dfa-bc21-f790b64bb17f"}
[task 2023-04-18T11:18:37.437Z] 11:18:37 INFO - PID 2103 | 1681816717436 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:37.438Z] 11:18:37 INFO - PID 2103 | 1681816717437 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/frame {"id": null}
[task 2023-04-18T11:18:37.459Z] 11:18:37 INFO - PID 2103 | 1681816717458 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:37.461Z] 11:18:37 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/bidi/log/entry_added/event_buffer.py::test_console_log_cached_messages[javascript_error]
[task 2023-04-18T11:18:38.040Z] 11:18:38 INFO - STDOUT: PASSED
[task 2023-04-18T11:18:38.110Z] 11:18:38 INFO - PID 2103 | 1681816718109 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/timeouts {"implicit": 0}
[task 2023-04-18T11:18:38.123Z] 11:18:38 INFO - PID 2103 | 1681816718122 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:38.125Z] 11:18:38 INFO - PID 2103 | 1681816718124 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/timeouts {"pageLoad": 300000}
[task 2023-04-18T11:18:38.132Z] 11:18:38 INFO - PID 2103 | 1681816718132 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:38.134Z] 11:18:38 INFO - PID 2103 | 1681816718133 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/timeouts {"script": 30000}
[task 2023-04-18T11:18:38.141Z] 11:18:38 INFO - PID 2103 | 1681816718140 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:38.141Z] 11:18:38 INFO - PID 2103 | 1681816718141 webdriver::server DEBUG -> GET /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window
[task 2023-04-18T11:18:38.148Z] 11:18:38 INFO - PID 2103 | 1681816718147 webdriver::server DEBUG <- 200 OK {"value":"28ab66da-ea00-4dfa-bc21-f790b64bb17f"}
[task 2023-04-18T11:18:38.149Z] 11:18:38 INFO - PID 2103 | 1681816718148 webdriver::server DEBUG -> GET /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window
[task 2023-04-18T11:18:38.155Z] 11:18:38 INFO - PID 2103 | 1681816718154 webdriver::server DEBUG <- 200 OK {"value":"28ab66da-ea00-4dfa-bc21-f790b64bb17f"}
[task 2023-04-18T11:18:38.155Z] 11:18:38 INFO - PID 2103 | 1681816718155 webdriver::server DEBUG -> GET /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window/handles
[task 2023-04-18T11:18:38.163Z] 11:18:38 INFO - PID 2103 | 1681816718162 webdriver::server DEBUG <- 200 OK {"value":["28ab66da-ea00-4dfa-bc21-f790b64bb17f"]}
[task 2023-04-18T11:18:38.164Z] 11:18:38 INFO - PID 2103 | 1681816718163 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window {"handle": "28ab66da-ea00-4dfa-bc21-f790b64bb17f"}
[task 2023-04-18T11:18:38.170Z] 11:18:38 INFO - PID 2103 | 1681816718169 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:38.171Z] 11:18:38 INFO - PID 2103 | 1681816718170 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/alert/dismiss {}
[task 2023-04-18T11:18:38.178Z] 11:18:38 INFO - PID 2103 | 1681816718177 webdriver::server DEBUG <- 404 Not Found {"value":{"error":"no such alert","message":"","stacktrace":"RemoteError@chrome://remote/content/shared/Remo ... ontent/marionette/server.sys.mjs:249:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.sys.mjs:496:20\n"}}
[task 2023-04-18T11:18:38.179Z] 11:18:38 INFO - PID 2103 | 1681816718178 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window {"handle": "28ab66da-ea00-4dfa-bc21-f790b64bb17f"}
[task 2023-04-18T11:18:38.186Z] 11:18:38 INFO - PID 2103 | 1681816718185 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:38.187Z] 11:18:38 INFO - PID 2103 | 1681816718186 webdriver::server DEBUG -> GET /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window
[task 2023-04-18T11:18:38.194Z] 11:18:38 INFO - PID 2103 | 1681816718193 webdriver::server DEBUG <- 200 OK {"value":"28ab66da-ea00-4dfa-bc21-f790b64bb17f"}
[task 2023-04-18T11:18:38.195Z] 11:18:38 INFO - PID 2103 | 1681816718194 webdriver::server DEBUG -> GET /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window/handles
[task 2023-04-18T11:18:38.200Z] 11:18:38 INFO - PID 2103 | 1681816718199 webdriver::server DEBUG <- 200 OK {"value":["28ab66da-ea00-4dfa-bc21-f790b64bb17f"]}
[task 2023-04-18T11:18:38.201Z] 11:18:38 INFO - PID 2103 | 1681816718200 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window {"handle": "28ab66da-ea00-4dfa-bc21-f790b64bb17f"}
[task 2023-04-18T11:18:38.207Z] 11:18:38 INFO - PID 2103 | 1681816718207 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:38.208Z] 11:18:38 INFO - PID 2103 | 1681816718207 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/frame {"id": null}
[task 2023-04-18T11:18:38.218Z] 11:18:38 INFO - PID 2103 | 1681816718217 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:38.220Z] 11:18:38 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/bidi/log/entry_added/event_buffer.py::test_console_log_cached_message_after_refresh[console_api_log]
[task 2023-04-18T11:18:38.616Z] 11:18:38 INFO - STDOUT: FAILED
[task 2023-04-18T11:18:38.680Z] 11:18:38 INFO - PID 2103 | 1681816718679 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/timeouts {"implicit": 0}
[task 2023-04-18T11:18:38.695Z] 11:18:38 INFO - PID 2103 | 1681816718694 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:38.696Z] 11:18:38 INFO - PID 2103 | 1681816718695 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/timeouts {"pageLoad": 300000}
[task 2023-04-18T11:18:38.703Z] 11:18:38 INFO - PID 2103 | 1681816718702 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:38.704Z] 11:18:38 INFO - PID 2103 | 1681816718703 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/timeouts {"script": 30000}
[task 2023-04-18T11:18:38.709Z] 11:18:38 INFO - PID 2103 | 1681816718709 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:38.710Z] 11:18:38 INFO - PID 2103 | 1681816718709 webdriver::server DEBUG -> GET /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window
[task 2023-04-18T11:18:38.716Z] 11:18:38 INFO - PID 2103 | 1681816718715 webdriver::server DEBUG <- 200 OK {"value":"28ab66da-ea00-4dfa-bc21-f790b64bb17f"}
[task 2023-04-18T11:18:38.717Z] 11:18:38 INFO - PID 2103 | 1681816718716 webdriver::server DEBUG -> GET /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window
[task 2023-04-18T11:18:38.723Z] 11:18:38 INFO - PID 2103 | 1681816718722 webdriver::server DEBUG <- 200 OK {"value":"28ab66da-ea00-4dfa-bc21-f790b64bb17f"}
[task 2023-04-18T11:18:38.723Z] 11:18:38 INFO - PID 2103 | 1681816718723 webdriver::server DEBUG -> GET /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window/handles
[task 2023-04-18T11:18:38.736Z] 11:18:38 INFO - PID 2103 | 1681816718735 webdriver::server DEBUG <- 200 OK {"value":["28ab66da-ea00-4dfa-bc21-f790b64bb17f"]}
[task 2023-04-18T11:18:38.737Z] 11:18:38 INFO - PID 2103 | 1681816718736 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window {"handle": "28ab66da-ea00-4dfa-bc21-f790b64bb17f"}
[task 2023-04-18T11:18:38.746Z] 11:18:38 INFO - PID 2103 | 1681816718745 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:38.746Z] 11:18:38 INFO - PID 2103 | 1681816718746 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/alert/dismiss {}
[task 2023-04-18T11:18:38.753Z] 11:18:38 INFO - PID 2103 | 1681816718752 webdriver::server DEBUG <- 404 Not Found {"value":{"error":"no such alert","message":"","stacktrace":"RemoteError@chrome://remote/content/shared/Remo ... ontent/marionette/server.sys.mjs:249:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.sys.mjs:496:20\n"}}
[task 2023-04-18T11:18:38.754Z] 11:18:38 INFO - PID 2103 | 1681816718753 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window {"handle": "28ab66da-ea00-4dfa-bc21-f790b64bb17f"}
[task 2023-04-18T11:18:38.761Z] 11:18:38 INFO - PID 2103 | 1681816718761 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:38.762Z] 11:18:38 INFO - PID 2103 | 1681816718761 webdriver::server DEBUG -> GET /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window
[task 2023-04-18T11:18:38.768Z] 11:18:38 INFO - PID 2103 | 1681816718768 webdriver::server DEBUG <- 200 OK {"value":"28ab66da-ea00-4dfa-bc21-f790b64bb17f"}
[task 2023-04-18T11:18:38.769Z] 11:18:38 INFO - PID 2103 | 1681816718768 webdriver::server DEBUG -> GET /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window/handles
[task 2023-04-18T11:18:38.775Z] 11:18:38 INFO - PID 2103 | 1681816718775 webdriver::server DEBUG <- 200 OK {"value":["28ab66da-ea00-4dfa-bc21-f790b64bb17f"]}
[task 2023-04-18T11:18:38.776Z] 11:18:38 INFO - PID 2103 | 1681816718775 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window {"handle": "28ab66da-ea00-4dfa-bc21-f790b64bb17f"}
[task 2023-04-18T11:18:38.783Z] 11:18:38 INFO - PID 2103 | 1681816718783 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:38.784Z] 11:18:38 INFO - PID 2103 | 1681816718783 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/frame {"id": null}
[task 2023-04-18T11:18:38.796Z] 11:18:38 INFO - PID 2103 | 1681816718795 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:38.798Z] 11:18:38 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/bidi/log/entry_added/event_buffer.py::test_console_log_cached_message_after_refresh[javascript_error]
[task 2023-04-18T11:18:39.183Z] 11:18:39 INFO - STDOUT: FAILED
[task 2023-04-18T11:18:39.262Z] 11:18:39 INFO - PID 2103 | 1681816719261 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/timeouts {"implicit": 0}
[task 2023-04-18T11:18:39.277Z] 11:18:39 INFO - PID 2103 | 1681816719276 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:39.278Z] 11:18:39 INFO - PID 2103 | 1681816719277 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/timeouts {"pageLoad": 300000}
[task 2023-04-18T11:18:39.287Z] 11:18:39 INFO - PID 2103 | 1681816719285 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:39.287Z] 11:18:39 INFO - PID 2103 | 1681816719286 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/timeouts {"script": 30000}
[task 2023-04-18T11:18:39.293Z] 11:18:39 INFO - PID 2103 | 1681816719293 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:39.294Z] 11:18:39 INFO - PID 2103 | 1681816719293 webdriver::server DEBUG -> GET /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window
[task 2023-04-18T11:18:39.300Z] 11:18:39 INFO - PID 2103 | 1681816719299 webdriver::server DEBUG <- 200 OK {"value":"28ab66da-ea00-4dfa-bc21-f790b64bb17f"}
[task 2023-04-18T11:18:39.301Z] 11:18:39 INFO - PID 2103 | 1681816719300 webdriver::server DEBUG -> GET /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window
[task 2023-04-18T11:18:39.307Z] 11:18:39 INFO - PID 2103 | 1681816719306 webdriver::server DEBUG <- 200 OK {"value":"28ab66da-ea00-4dfa-bc21-f790b64bb17f"}
[task 2023-04-18T11:18:39.308Z] 11:18:39 INFO - PID 2103 | 1681816719307 webdriver::server DEBUG -> GET /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window/handles
[task 2023-04-18T11:18:39.314Z] 11:18:39 INFO - PID 2103 | 1681816719314 webdriver::server DEBUG <- 200 OK {"value":["28ab66da-ea00-4dfa-bc21-f790b64bb17f"]}
[task 2023-04-18T11:18:39.315Z] 11:18:39 INFO - PID 2103 | 1681816719314 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window {"handle": "28ab66da-ea00-4dfa-bc21-f790b64bb17f"}
[task 2023-04-18T11:18:39.322Z] 11:18:39 INFO - PID 2103 | 1681816719321 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:39.323Z] 11:18:39 INFO - PID 2103 | 1681816719322 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/alert/dismiss {}
[task 2023-04-18T11:18:39.331Z] 11:18:39 INFO - PID 2103 | 1681816719329 webdriver::server DEBUG <- 404 Not Found {"value":{"error":"no such alert","message":"","stacktrace":"RemoteError@chrome://remote/content/shared/Remo ... ontent/marionette/server.sys.mjs:249:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.sys.mjs:496:20\n"}}
[task 2023-04-18T11:18:39.331Z] 11:18:39 INFO - PID 2103 | 1681816719330 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window {"handle": "28ab66da-ea00-4dfa-bc21-f790b64bb17f"}
[task 2023-04-18T11:18:39.338Z] 11:18:39 INFO - PID 2103 | 1681816719337 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:39.338Z] 11:18:39 INFO - PID 2103 | 1681816719338 webdriver::server DEBUG -> GET /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window
[task 2023-04-18T11:18:39.346Z] 11:18:39 INFO - PID 2103 | 1681816719345 webdriver::server DEBUG <- 200 OK {"value":"28ab66da-ea00-4dfa-bc21-f790b64bb17f"}
[task 2023-04-18T11:18:39.347Z] 11:18:39 INFO - PID 2103 | 1681816719346 webdriver::server DEBUG -> GET /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window/handles
[task 2023-04-18T11:18:39.353Z] 11:18:39 INFO - PID 2103 | 1681816719352 webdriver::server DEBUG <- 200 OK {"value":["28ab66da-ea00-4dfa-bc21-f790b64bb17f"]}
[task 2023-04-18T11:18:39.353Z] 11:18:39 INFO - PID 2103 | 1681816719353 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/window {"handle": "28ab66da-ea00-4dfa-bc21-f790b64bb17f"}
[task 2023-04-18T11:18:39.360Z] 11:18:39 INFO - PID 2103 | 1681816719359 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:39.361Z] 11:18:39 INFO - PID 2103 | 1681816719360 webdriver::server DEBUG -> POST /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4/frame {"id": null}
[task 2023-04-18T11:18:39.371Z] 11:18:39 INFO - PID 2103 | 1681816719370 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-18T11:18:39.372Z] 11:18:39 INFO - PID 2103 | 1681816719372 webdriver::server DEBUG -> DELETE /session/9fbd684a-ef93-4562-82d4-18e3ae1058c4
[task 2023-04-18T11:18:39.416Z] 11:18:39 INFO - PID 2103 | 1681816719415 webdriver::server DEBUG Teardown session
[task 2023-04-18T11:18:39.417Z] 11:18:39 INFO - PID 2103 | 1681816719415 geckodriver::android DEBUG Force stopping the Android package: org.mozilla.geckoview.test_runner
[task 2023-04-18T11:18:39.417Z] 11:18:39 INFO - PID 2103 | 1681816719415 mozdevice DEBUG Force stopping Android package: org.mozilla.geckoview.test_runner
[task 2023-04-18T11:18:39.418Z] 11:18:39 INFO - PID 2103 | 1681816719415 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:39.418Z] 11:18:39 INFO - PID 2103 | 1681816719416 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:39.419Z] 11:18:39 INFO - PID 2103 | 1681816719416 mozdevice TRACE execute_host_command: >> "shell:am force-stop org.mozilla.geckoview.test_runner"
[task 2023-04-18T11:18:39.669Z] 11:18:39 INFO - PID 2103 | 1681816719668 mozdevice TRACE execute_host_command: << ""
[task 2023-04-18T11:18:39.670Z] 11:18:39 INFO - PID 2103 | 1681816719669 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:39.670Z] 11:18:39 INFO - PID 2103 | 1681816719669 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:39.671Z] 11:18:39 INFO - PID 2103 | 1681816719669 mozdevice TRACE execute_host_command: >> "shell:am clear-debug-app org.mozilla.geckoview.test_runner"
[task 2023-04-18T11:18:39.903Z] 11:18:39 INFO - PID 2103 | 1681816719902 mozdevice TRACE execute_host_command: << ""
[task 2023-04-18T11:18:39.903Z] 11:18:39 INFO - PID 2103 | 1681816719902 geckodriver::android DEBUG Disabled reading from configuration file
[task 2023-04-18T11:18:39.904Z] 11:18:39 INFO - PID 2103 | 1681816719902 mozdevice DEBUG Deleting /data/local/tmp/org.mozilla.geckoview.test_runner-geckoview-config.yaml
[task 2023-04-18T11:18:39.904Z] 11:18:39 INFO - PID 2103 | 1681816719902 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:39.904Z] 11:18:39 INFO - PID 2103 | 1681816719902 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:39.905Z] 11:18:39 INFO - PID 2103 | 1681816719902 mozdevice TRACE execute_host_command: >> "shell:rm -rf /data/local/tmp/org.mozilla.geckoview.test_runner-geckoview-config.yaml"
[task 2023-04-18T11:18:39.911Z] 11:18:39 INFO - PID 2103 | 1681816719910 mozdevice TRACE execute_host_command: << ""
[task 2023-04-18T11:18:39.911Z] 11:18:39 INFO - PID 2103 | 1681816719910 geckodriver::android DEBUG Deleted GeckoView configuration file
[task 2023-04-18T11:18:39.912Z] 11:18:39 INFO - PID 2103 | 1681816719910 mozdevice DEBUG Deleting /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root
[task 2023-04-18T11:18:39.912Z] 11:18:39 INFO - PID 2103 | 1681816719910 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:39.913Z] 11:18:39 INFO - PID 2103 | 1681816719910 mozdevice TRACE execute_host_command: << []
[task 2023-04-18T11:18:39.913Z] 11:18:39 INFO - PID 2103 | 1681816719910 mozdevice TRACE execute_host_command: >> "shell:rm -rf /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root"
[task 2023-04-18T11:18:40.008Z] 11:18:40 INFO - PID 2103 | 1681816720007 mozdevice TRACE execute_host_command: << ""
[task 2023-04-18T11:18:40.008Z] 11:18:40 INFO - PID 2103 | 1681816720007 geckodriver::android DEBUG Deleted test root folder: /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root
[task 2023-04-18T11:18:40.008Z] 11:18:40 INFO - PID 2103 | 1681816720007 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2023-04-18T11:18:40.009Z] 11:18:40 INFO - PID 2103 | 1681816720007 mozdevice TRACE execute_host_command: << []
<...>
[task 2023-04-18T11:18:40.048Z] 11:18:40 INFO - STDOUT: on_event = <function test_console_log_cached_message_after_refresh.<locals>.on_event at 0x7fad33863b90>
[task 2023-04-18T11:18:40.048Z] 11:18:40 INFO - STDOUT: remove_listener = <function BidiSession.add_event_listener.<locals>.<lambda> at 0x7fad33863320>
[task 2023-04-18T11:18:40.049Z] 11:18:40 INFO - STDOUT: subscribe_events = <function subscribe_events.<locals>.subscribe_events at 0x7fad33863710>
[task 2023-04-18T11:18:40.049Z] 11:18:40 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/bidi/log/entry_added/event_buffer.py
[task 2023-04-18T11:18:40.050Z] 11:18:40 INFO - STDOUT: :85: KeyError
[task 2023-04-18T11:18:40.050Z] 11:18:40 INFO - STDOUT: _______ test_console_log_cached_message_after_refresh[javascript_error] ________
[task 2023-04-18T11:18:40.051Z] 11:18:40 INFO - STDOUT: bidi_session = <webdriver.bidi.client.BidiSession object at 0x7fad3387e9d0>
[task 2023-04-18T11:18:40.051Z] 11:18:40 INFO - STDOUT: subscribe_events = <function subscribe_events.<locals>.subscribe_events at 0x7fad33863200>
[task 2023-04-18T11:18:40.052Z] 11:18:40 INFO - STDOUT: new_tab = {'context': '64acf9d9-ffb4-4a43-88fb-7f1b9dfc0903'}
[task 2023-04-18T11:18:40.052Z] 11:18:40 INFO - STDOUT: log_type = 'javascript_error'
[task 2023-04-18T11:18:40.053Z] 11:18:40 INFO - STDOUT: @pytest.mark.asyncio
[task 2023-04-18T11:18:40.053Z] 11:18:40 INFO - STDOUT: @pytest.mark.parametrize("log_type", ["console_api_log", "javascript_error"])
[task 2023-04-18T11:18:40.054Z] 11:18:40 INFO - STDOUT: async def test_console_log_cached_message_after_refresh(
[task 2023-04-18T11:18:40.054Z] 11:18:40 INFO - STDOUT: bidi_session, subscribe_events, new_tab, log_type
[task 2023-04-18T11:18:40.055Z] 11:18:40 INFO - STDOUT: ):
[task 2023-04-18T11:18:40.055Z] 11:18:40 INFO - STDOUT: # Clear events buffer.
[task 2023-04-18T11:18:40.056Z] 11:18:40 INFO - STDOUT: await bidi_session.session.subscribe(events=["log.entryAdded"])
[task 2023-04-18T11:18:40.056Z] 11:18:40 INFO - STDOUT: await bidi_session.session.unsubscribe(events=["log.entryAdded"])
[task 2023-04-18T11:18:40.057Z] 11:18:40 INFO - STDOUT:
[task 2023-04-18T11:18:40.057Z] 11:18:40 INFO - STDOUT: # Track all received log.entryAdded events in the events array
[task 2023-04-18T11:18:40.058Z] 11:18:40 INFO - STDOUT: events = []
[task 2023-04-18T11:18:40.058Z] 11:18:40 INFO - STDOUT:
[task 2023-04-18T11:18:40.059Z] 11:18:40 INFO - STDOUT: async def on_event(method, data):
[task 2023-04-18T11:18:40.059Z] 11:18:40 INFO - STDOUT: events.append(data)
[task 2023-04-18T11:18:40.060Z] 11:18:40 INFO - STDOUT:
[task 2023-04-18T11:18:40.060Z] 11:18:40 INFO - STDOUT: remove_listener = bidi_session.add_event_listener("log.entryAdded", on_event)
[task 2023-04-18T11:18:40.061Z] 11:18:40 INFO - STDOUT:
[task 2023-04-18T11:18:40.061Z] 11:18:40 INFO - STDOUT: # Log a message, refresh, log another message and subscribe
[task 2023-04-18T11:18:40.062Z] 11:18:40 INFO - STDOUT: expected_text_1 = await create_log(bidi_session, new_tab, log_type, "cached_message_1")
[task 2023-04-18T11:18:40.062Z] 11:18:40 INFO - STDOUT: await bidi_session.browsing_context.navigate(
[task 2023-04-18T11:18:40.063Z] 11:18:40 INFO - STDOUT: > context=new_tab["context"], url=new_tab["url"], wait="complete"
[task 2023-04-18T11:18:40.063Z] 11:18:40 INFO - STDOUT: )
[task 2023-04-18T11:18:40.064Z] 11:18:40 INFO - STDOUT: E KeyError: 'url'
[task 2023-04-18T11:18:40.064Z] 11:18:40 INFO - STDOUT: bidi_session = <webdriver.bidi.client.BidiSession object at 0x7fad3387e9d0>
[task 2023-04-18T11:18:40.065Z] 11:18:40 INFO - STDOUT: events = []
[task 2023-04-18T11:18:40.065Z] 11:18:40 INFO - STDOUT: expected_text_1 = 'Error: cached_message_1'
[task 2023-04-18T11:18:40.066Z] 11:18:40 INFO - STDOUT: log_type = 'javascript_error'
[task 2023-04-18T11:18:40.066Z] 11:18:40 INFO - STDOUT: new_tab = {'context': '64acf9d9-ffb4-4a43-88fb-7f1b9dfc0903'}
[task 2023-04-18T11:18:40.067Z] 11:18:40 INFO - STDOUT: on_event = <function test_console_log_cached_message_after_refresh.<locals>.on_event at 0x7fad33863dd0>
[task 2023-04-18T11:18:40.067Z] 11:18:40 INFO - STDOUT: remove_listener = <function BidiSession.add_event_listener.<locals>.<lambda> at 0x7fad338637a0>
[task 2023-04-18T11:18:40.068Z] 11:18:40 INFO - STDOUT: subscribe_events = <function subscribe_events.<locals>.subscribe_events at 0x7fad33863200>
[task 2023-04-18T11:18:40.070Z] 11:18:40 INFO -
[task 2023-04-18T11:18:40.070Z] 11:18:40 INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/bidi/log/entry_added/event_buffer.py | test_console_log_cached_messages[console_api_log] - assert 0 == 1
[task 2023-04-18T11:18:40.070Z] 11:18:40 INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x7fad3387e9d0>
[task 2023-04-18T11:18:40.070Z] 11:18:40 INFO - wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x7fad33968cb0>
[task 2023-04-18T11:18:40.070Z] 11:18:40 INFO - log_type = 'console_api_log'
[task 2023-04-18T11:18:40.070Z] 11:18:40 INFO - new_tab = {'context': 'b951b3e3-0700-46b7-b039-205e06ba2f8c'}
[task 2023-04-18T11:18:40.070Z] 11:18:40 INFO -
[task 2023-04-18T11:18:40.070Z] 11:18:40 INFO - @pytest.mark.asyncio
[task 2023-04-18T11:18:40.070Z] 11:18:40 INFO - @pytest.mark.parametrize("log_type", ["console_api_log", "javascript_error"])
[task 2023-04-18T11:18:40.070Z] 11:18:40 INFO - async def test_console_log_cached_messages(
[task 2023-04-18T11:18:40.070Z] 11:18:40 INFO - bidi_session, wait_for_event, log_type, new_tab
[task 2023-04-18T11:18:40.070Z] 11:18:40 INFO - ):
[task 2023-04-18T11:18:40.070Z] 11:18:40 INFO - # Clear events buffer.
[task 2023-04-18T11:18:40.070Z] 11:18:40 INFO - await bidi_session.session.subscribe(events=["log.entryAdded"])
[task 2023-04-18T11:18:40.070Z] 11:18:40 INFO - await bidi_session.session.unsubscribe(events=["log.entryAdded"])
[task 2023-04-18T11:18:40.070Z] 11:18:40 INFO -
[task 2023-04-18T11:18:40.070Z] 11:18:40 INFO - # Log a message before subscribing
[task 2023-04-18T11:18:40.070Z] 11:18:40 INFO - expected_text = await create_log(bidi_session, new_tab, log_type, "cached_message")
[task 2023-04-18T11:18:40.070Z] 11:18:40 INFO -
[task 2023-04-18T11:18:40.070Z] 11:18:40 INFO - # Track all received log.entryAdded events in the events array
[task 2023-04-18T11:18:40.070Z] 11:18:40 INFO - events = []
[task 2023-04-18T11:18:40.070Z] 11:18:40 INFO -
[task 2023-04-18T11:18:40.070Z] 11:18:40 INFO - async def on_event(method, data):
[task 2023-04-18T11:18:40.071Z] 11:18:40 INFO - events.append(data)
[task 2023-04-18T11:18:40.071Z] 11:18:40 INFO -
[task 2023-04-18T11:18:40.071Z] 11:18:40 INFO - remove_listener = bidi_session.add_event_listener("log.entryAdded", on_event)
[task 2023-04-18T11:18:40.071Z] 11:18:40 INFO -
[task 2023-04-18T11:18:40.071Z] 11:18:40 INFO - # Subscribe
[task 2023-04-18T11:18:40.071Z] 11:18:40 INFO - await bidi_session.session.subscribe(events=["log.entryAdded"])
[task 2023-04-18T11:18:40.071Z] 11:18:40 INFO - # Cached events are emitted before the subscribe command is finished.
[task 2023-04-18T11:18:40.071Z] 11:18:40 INFO - > assert len(events) == 1
[task 2023-04-18T11:18:40.071Z] 11:18:40 INFO - E assert 0 == 1
[task 2023-04-18T11:18:40.071Z] 11:18:40 INFO - E +0
[task 2023-04-18T11:18:40.071Z] 11:18:40 INFO - E -1
[task 2023-04-18T11:18:40.071Z] 11:18:40 INFO -
[task 2023-04-18T11:18:40.071Z] 11:18:40 INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x7fad3387e9d0>
[task 2023-04-18T11:18:40.071Z] 11:18:40 INFO - events = []
[task 2023-04-18T11:18:40.071Z] 11:18:40 INFO - expected_text = 'cached_message'
[task 2023-04-18T11:18:40.071Z] 11:18:40 INFO - log_type = 'console_api_log'
[task 2023-04-18T11:18:40.071Z] 11:18:40 INFO - new_tab = {'context': 'b951b3e3-0700-46b7-b039-205e06ba2f8c'}
[task 2023-04-18T11:18:40.071Z] 11:18:40 INFO - on_event = <function test_console_log_cached_messages.<locals>.on_event at 0x7fad339350e0>
[task 2023-04-18T11:18:40.071Z] 11:18:40 INFO - remove_listener = <function BidiSession.add_event_listener.<locals>.<lambda> at 0x7fad33935200>
[task 2023-04-18T11:18:40.071Z] 11:18:40 INFO - wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x7fad33968cb0>
[task 2023-04-18T11:18:40.071Z] 11:18:40 INFO -
[task 2023-04-18T11:18:40.071Z] 11:18:40 INFO - tests/web-platform/tests/webdriver/tests/bidi/log/entry_added/event_buffer.py:31: AssertionError
[task 2023-04-18T11:18:40.075Z] 11:18:40 INFO - ...
[task 2023-04-18T11:18:40.075Z] 11:18:40 INFO - TEST-OK | /webdriver/tests/bidi/log/entry_added/event_buffer.py | took 6858ms
|
||
Updated•3 years ago
|
You need to log in
before you can comment on or make changes to this bug.
Description
•