[Question] what is the reason when the "Browser.close" message was sent, but never received a response message back?

[microsoft]

[Question] what is the reason when the "Browser.close" message was sent, but never received a response message back?

[yury-s]

For the cases where we want to have a timeout we compose waitable with WaitableTimeout, this should be enough for current use cases and leave enough flexibility in how runUntil works. If understand correctly, you are trying to close the browser and then this code hangs in an infinite loop. This sounds like a bug as when browser closes the connection should close as well and next call to connection.processOneMessage() is expected to throw. Can you share code snippet with the infinite loop problem?

[ephung01]

The browser did close, but the process is hanging. It's very simple code open url and close browser. I've experienced this only at work environment.

[yury-s]

It may be that the browser process didn't exit actually, can you check that the browser process actually exits?

The browser did close, but the process is hanging.

Do you mean Playwright process? Are you calling Playwright.close() or just Browser.close()? Seeing your code snippet would be helpful.

[ephung01]

import com.microsoft.playwright.*;
import com.microsoft.playwright.BrowserType.LaunchOptions;
import static com.microsoft.playwright.options.WaitUntilState.DOMCONTENTLOADED;

import java.nio.file.Paths;

public class Test {
static Playwright playWright = null;
static Browser browser = null;
static BrowserContext context = null;
static Page page = null;

public static void main(String args[]) throws Exception {
    try {
        playWright = Playwright.create();
        BrowserType browserType = playWright.chromium();
        LaunchOptions options = new LaunchOptions();
        options.setExecutablePath(Paths.get("C:\\Program Files (x86)\\Microsoft\\Edge\\Application\\msedge.exe"));
        options.setHeadless(false);
        options.setChromiumSandbox(true);
        browser = browserType.launch(options);
        context = browser.newContext(
                new Browser.NewContextOptions()
                        .setViewportSize(800, 600)
        );
        page = context.newPage();
        String url = "http://www.microsoft.com";
        page.navigate(url, new Page.NavigateOptions().setWaitUntil(DOMCONTENTLOADED));
    } catch (Exception ex) {
        ex.printStackTrace();
    } finally {
        // tear down
        if (page != null) {
            page.close();
            page = null;
        }
        if (browser != null) {
            browser.close();
            browser = null;
        }
        if (context != null) {
            context.close();
            context = null;
        }
        if (playWright != null) {
            playWright.close();
            playWright = null;
        }
    }
}

}

Visually the browser is closed, but in Task Manager, there are a few processes are still running (some MSEdge closed when close page)

[ephung01]

Look like this is the process suppose to be terminated, but didn't. I manually kill it; the debug code completes gracefully.

[yury-s]

Oh, you are running against MS Edge, there has been some fixes related to browser closure in chromium quite recently (this one in particular) and they might not have made it to Edge yet. What version of MS Edge is this?

Also, does it close browser fine with bundled Chromium?

[ephung01]

Microsoft Edge version 86.0.622.56. I've the same version at home laptop and it's working fine. In company, users have limited access and will not able to upgrade any browsers (blocked) until approval by security team (chromium is not allow). May be I will wait until new version get approval and test it again.

[ephung01]

when I run chromium it will be blocked because it's unauthorized software - base on company policy

[yury-s]

Looks like 86.0.622.56 was released in October 2020 so it doesn't include aforementioned patch (and it will likely take a while until you get upgraded to a version which includes it). I wonder though what's different between your laptop and the corp machine that makes it fail on the latter.

[yury-s]

Does your corp browser run any extensions that you don't have on your personal device?

[ephung01]

There are some default company extension for business and security (cannot add the extension to browser)

Could that be the "Symantec Extension" blocks the process terminate command (playwright.cmd)? We also use Selenium here and browser process termination is not an issue.

[yury-s]

Could that be the "Symantec Extension" blocks the process terminate command (playwright.cmd)?

I would say "no" because if the browser process doesn't exit properly within 30 seconds Playwright will kill the process, see this code. You are saying the process keeps running even after 30 seconds since Browser.close() was sent, right?

Can you enable some logging to see what's going on and upload the logs here:

1. Start Playwright with DEBUG=pw:browser in the environment (I believe it is something like set DEBUG=pw:browser on Windows), it should enable launcher logging and also printing of whatever error messages are dumped by Chrome.
2. Enable verbose logging in the browser by adding the following command line arguments to the launch options:

    options.setArgs(Arrays.asList("--enable-logging=stderr",  "--v=1"));

Hopefully this will give us some clue about why it's not exiting properly.

[ephung01]

"C:\Program Files\Java\jdk1.8.0_121\bin\java.exe" -javaagent:C:\ideaIC-2020.2.1\lib\idea_rt.jar=58509:C:\ideaIC-2020.2.1\bin -Dfile.encoding=UTF-8 -classpath "C:\Program Files\Java\jdk1.8.0_121\jre\lib\charsets.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\deploy.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\ext\access-bridge-64.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\ext\cldrdata.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\ext\dnsns.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\ext\jaccess.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\ext\jfxrt.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\ext\localedata.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\ext\nashorn.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\ext\sunec.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\ext\sunjce_provider.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\ext\sunmscapi.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\ext\sunpkcs11.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\ext\zipfs.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\javaws.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\jce.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\jfr.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\jfxswt.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\jsse.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\management-agent.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\plugin.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\resources.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\rt.jar;C:\Users\ephung\Development\TestPlayWright\out\production\classes;C:\Users\ephung.gradle\caches\modules-2\files-2.1\com.microsoft.playwright\playwright\1.9.1-alpha-0\dbb6f4a7686b61da408c92fa926c22aae333562c\playwright-1.9.1-alpha-0.jar;C:\Users\ephung.gradle\caches\modules-2\files-2.1\com.microsoft.playwright\driver-bundle\1.9.1-alpha-0\dd9ed2801d0205ed8d97f4c6bdf2a048fde1b922\driver-bundle-1.9.1-alpha-0.jar;C:\Users\ephung.gradle\caches\modules-2\files-2.1\com.microsoft.playwright\driver\1.9.1-alpha-0\943047a4ad4d98143812ca0300fc8bd940a3f22e\driver-1.9.1-alpha-0.jar;C:\Users\ephung.gradle\caches\modules-2\files-2.1\com.google.code.gson\gson\2.8.6\9180733b7df8542621dc12e21e87557e8c99b8cb\gson-2.8.6.jar;C:\Users\ephung.gradle\caches\modules-2\files-2.1\org.java-websocket\Java-WebSocket\1.5.1\382b302303c830a7edb20c9ed61c4ac2cdf7a7a4\Java-WebSocket-1.5.1.jar;C:\Users\ephung.gradle\caches\modules-2\files-2.1\org.slf4j\slf4j-api\1.7.25\da76ca59f6a57ee3102f8f9bd9cee742973efa8a\slf4j-api-1.7.25.jar" Test
2021-03-24T21:31:27.577Z pw:browser C:\Program Files (x86)\Microsoft\Edge\Application\msedge.exe --disable-background-networking --enable-features=NetworkService,NetworkServiceInProcess --disable-background-timer-throttling --disable-backgrounding-occluded-windows --disable-breakpad --disable-client-side-phishing-detection --disable-component-extensions-with-background-pages --disable-default-apps --disable-dev-shm-usage --disable-extensions --disable-features=TranslateUI,BlinkGenPropertyTrees,ImprovedCookieControls,SameSiteByDefaultCookies,LazyFrameLoading --disable-hang-monitor --disable-ipc-flooding-protection --disable-popup-blocking --disable-prompt-on-repost --disable-renderer-backgrounding --disable-sync --force-color-profile=srgb --metrics-recording-only --no-first-run --enable-automation --password-store=basic --use-mock-keychain --user-data-dir=C:\Users\ephung\AppData\Local\Temp\playwright_chromiumdev_profile-ETaA6I --remote-debugging-pipe --enable-logging=stderr --v=1 --no-startup-window
2021-03-24T21:31:27.577Z pw:browser pid=20540
2021-03-24T21:31:27.770Z pw:browser [err] [20540:12700:0324/173127.769:VERBOSE1:win_util.cc(1162)] Checking if internal user
2021-03-24T21:31:27.822Z pw:browser [err] [20540:12700:0324/173127.822:VERBOSE1:edge_ui_features.cc(223)] IsWindowTabManagerEnabled starting
2021-03-24T21:31:27.822Z pw:browser [err] [20540:12700:0324/173127.822:VERBOSE1:wtm_interface_factory.cc(155)] IsApiAvailable starting
2021-03-24T21:31:27.822Z pw:browser [err] [20540:12700:0324/173127.822:VERBOSE1:wtm_interface_factory.cc(201)] IsApiAvailable returning false
2021-03-24T21:31:27.822Z pw:browser [err] [20540:12700:0324/173127.822:VERBOSE1:edge_ui_features.cc(240)] IsWindowTabManagerEnabled returning false
2021-03-24T21:31:27.824Z pw:browser [err] [20540:12700:0324/173127.823:VERBOSE1:webrtc_event_log_manager.cc(93)] WebRTC remote-bound event logging enabled.
2021-03-24T21:31:27.828Z pw:browser [err] [20540:12700:0324/173127.828:VERBOSE1:pref_proxy_config_tracker_impl.cc(186)] 0000029B82133FE0: set chrome proxy config service to 0000029B82134440
2021-03-24T21:31:27.884Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Argon2020' log
2021-03-24T21:31:27.884Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Argon2021' log
2021-03-24T21:31:27.884Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Argon2022' log
2021-03-24T21:31:27.885Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Argon2023' log
2021-03-24T21:31:27.885Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Xenon2020' log
2021-03-24T21:31:27.885Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Xenon2021' log
2021-03-24T21:31:27.885Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Xenon2022' log
2021-03-24T21:31:27.885Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Xenon2023' log
2021-03-24T21:31:27.885Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Aviator' log
2021-03-24T21:31:27.885Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Icarus' log
2021-03-24T21:31:27.885Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Pilot' log
2021-03-24T21:31:27.885Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Rocketeer' log
2021-03-24T21:31:27.885Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Skydiver' log
2021-03-24T21:31:27.885Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Cloudflare 'Nimbus2020' Log
2021-03-24T21:31:27.885Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Cloudflare 'Nimbus2021' Log
2021-03-24T21:31:27.885Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Cloudflare 'Nimbus2022' Log
2021-03-24T21:31:27.885Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Cloudflare 'Nimbus2023' Log
2021-03-24T21:31:27.885Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Log Server
2021-03-24T21:31:27.885Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Yeti2020 Log
2021-03-24T21:31:27.885Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Yeti2021 Log
2021-03-24T21:31:27.885Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Yeti2022 Log
2021-03-24T21:31:27.885Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Yeti2023 Log
2021-03-24T21:31:27.885Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Nessie2020 Log
2021-03-24T21:31:27.886Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Nessie2021 Log
2021-03-24T21:31:27.886Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Nessie2022 Log
2021-03-24T21:31:27.886Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Nessie2023 Log
2021-03-24T21:31:27.886Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Sectigo 'Sabre' CT log
2021-03-24T21:31:27.886Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Sectigo 'Mammoth' CT log
2021-03-24T21:31:27.886Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Let's Encrypt 'Oak2020' log
2021-03-24T21:31:27.886Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Let's Encrypt 'Oak2021' log
2021-03-24T21:31:27.886Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Let's Encrypt 'Oak2022' log
2021-03-24T21:31:27.886Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Symantec 'Sirius' log
2021-03-24T21:31:27.886Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: StartCom log
2021-03-24T21:31:27.886Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: WoSign log
2021-03-24T21:31:27.886Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Izenpe log
2021-03-24T21:31:27.886Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Log Server 2
2021-03-24T21:31:27.886Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: CNNIC CT log
2021-03-24T21:31:27.886Z pw:browser [err] [20540:31556:0324/173127.884:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Venafi log
2021-03-24T21:31:27.886Z pw:browser [err] [20540:31556:0324/173127.885:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Symantec 'Vega' log
2021-03-24T21:31:27.886Z pw:browser [err] [20540:31556:0324/173127.885:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Certly.IO log
2021-03-24T21:31:27.886Z pw:browser [err] [20540:31556:0324/173127.885:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Symantec log
2021-03-24T21:31:27.887Z pw:browser [err] [20540:12700:0324/173127.886:VERBOSE1:install_util.cc(253)] Existing version found: 86.0.622.56
2021-03-24T21:31:27.887Z pw:browser [err] [20540:12700:0324/173127.887:VERBOSE1:wam_account_manager.cc(517)] wam_default_account_token_fetcher::StartFetchingTokenForImplicitSignin: Calling API
2021-03-24T21:31:27.906Z pw:browser [err] [20540:12700:0324/173127.906:WARNING:account_consistency_mode_manager.cc(196)] Desktop Identity Consistency cannot be enabled as no OAuth client ID and client secret have been configured.
2021-03-24T21:31:27.906Z pw:browser [err] [20540:12700:0324/173127.906:VERBOSE1:account_consistency_mode_manager.cc(120)] Dice migration completed.
2021-03-24T21:31:27.909Z pw:browser [err] [20540:12700:0324/173127.909:VERBOSE1:mutable_profile_oauth2_token_service_delegate.cc(357)] MutablePO2TS::MutablePO2TS
2021-03-24T21:31:27.909Z pw:browser [err] [20540:12700:0324/173127.909:VERBOSE1:pref_proxy_config_tracker_impl.cc(186)] 0000029B8388FA30: set chrome proxy config service to 0000029B83630050
2021-03-24T21:31:27.911Z pw:browser [err] [20540:12700:0324/173127.911:VERBOSE1:nearby_sharing_service_factory.cc(59)] BuildServiceInstanceFor: Nearby Sharing feature flag is not enabled.
2021-03-24T21:31:27.911Z pw:browser [err] [20540:31556:0324/173127.911:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Argon2020' log
2021-03-24T21:31:27.911Z pw:browser [err] [20540:31556:0324/173127.911:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Argon2021' log
2021-03-24T21:31:27.911Z pw:browser [err] [20540:31556:0324/173127.911:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Argon2022' log
2021-03-24T21:31:27.911Z pw:browser [err] [20540:31556:0324/173127.911:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Argon2023' log
2021-03-24T21:31:27.911Z pw:browser [err] [20540:31556:0324/173127.911:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Xenon2020' log
2021-03-24T21:31:27.912Z pw:browser [err] [20540:31556:0324/173127.911:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Xenon2021' log
2021-03-24T21:31:27.912Z pw:browser [err] [20540:31556:0324/173127.911:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Xenon2022' log
2021-03-24T21:31:27.912Z pw:browser [err] [20540:31556:0324/173127.911:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Xenon2023' log
2021-03-24T21:31:27.912Z pw:browser [err] [20540:31556:0324/173127.911:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Aviator' log
2021-03-24T21:31:27.912Z pw:browser [err] [20540:31556:0324/173127.911:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Icarus' log
2021-03-24T21:31:27.912Z pw:browser [err] [20540:31556:0324/173127.911:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Pilot' log
2021-03-24T21:31:27.912Z pw:browser [err] [20540:12700:0324/173127.912:VERBOSE1:bluetooth_low_energy_event_router.cc(242)] Initializing BluetoothLowEnergyEventRouter.
2021-03-24T21:31:27.912Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Rocketeer' log
2021-03-24T21:31:27.912Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Skydiver' log
2021-03-24T21:31:27.912Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Cloudflare 'Nimbus2020' Log
2021-03-24T21:31:27.912Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Cloudflare 'Nimbus2021' Log
2021-03-24T21:31:27.912Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Cloudflare 'Nimbus2022' Log
2021-03-24T21:31:27.912Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Cloudflare 'Nimbus2023' Log
2021-03-24T21:31:27.912Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Log Server
2021-03-24T21:31:27.912Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Yeti2020 Log
2021-03-24T21:31:27.912Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Yeti2021 Log
2021-03-24T21:31:27.912Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Yeti2022 Log
2021-03-24T21:31:27.912Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Yeti2023 Log
2021-03-24T21:31:27.912Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Nessie2020 Log
2021-03-24T21:31:27.912Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Nessie2021 Log
2021-03-24T21:31:27.912Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Nessie2022 Log
2021-03-24T21:31:27.913Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Nessie2023 Log
2021-03-24T21:31:27.913Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Sectigo 'Sabre' CT log
2021-03-24T21:31:27.913Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Sectigo 'Mammoth' CT log
2021-03-24T21:31:27.913Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Let's Encrypt 'Oak2020' log
2021-03-24T21:31:27.913Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Let's Encrypt 'Oak2021' log
2021-03-24T21:31:27.913Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Let's Encrypt 'Oak2022' log
2021-03-24T21:31:27.913Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Symantec 'Sirius' log
2021-03-24T21:31:27.913Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: StartCom log
2021-03-24T21:31:27.913Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: WoSign log
2021-03-24T21:31:27.913Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Izenpe log
2021-03-24T21:31:27.913Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Log Server 2
2021-03-24T21:31:27.913Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: CNNIC CT log
2021-03-24T21:31:27.913Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Venafi log
2021-03-24T21:31:27.913Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Symantec 'Vega' log
2021-03-24T21:31:27.913Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Certly.IO log
2021-03-24T21:31:27.913Z pw:browser [err] [20540:31556:0324/173127.912:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Symantec log
2021-03-24T21:31:27.918Z pw:browser [err] [20540:12700:0324/173127.918:VERBOSE1:device_event_log_impl.cc(210)] [17:31:27.917] Bluetooth: EVENT: bluetooth_api.cc:73 BluetoothAPI: 0000029B838182D0
2021-03-24T21:31:27.923Z pw:browser [err] [20540:12700:0324/173127.923:VERBOSE1:extension_service.cc(1491)] AddComponentExtension Microsoft Edge PDF Viewer
2021-03-24T21:31:27.923Z pw:browser [err] [20540:12700:0324/173127.923:VERBOSE1:extension_service.cc(1493)] Component extension Microsoft Edge PDF Viewer (mhjfbmdgcfjbbpaeojofohoefgiehjai) installing/upgrading from '' to 1
2021-03-24T21:31:27.924Z pw:browser [err] [20540:12700:0324/173127.924:VERBOSE1:extension_service.cc(1491)] AddComponentExtension Microsoft Store
2021-03-24T21:31:27.924Z pw:browser [err] [20540:12700:0324/173127.924:VERBOSE1:extension_service.cc(1493)] Component extension Microsoft Store (iglcjdemknebjbklcgkfaebgojjphkec) installing/upgrading from '' to 0.2
2021-03-24T21:31:27.924Z pw:browser [err] [20540:12152:0324/173127.924:VERBOSE1:content_verifier.cc(646)] OnFetchComplete mhjfbmdgcfjbbpaeojofohoefgiehjai success:0
2021-03-24T21:31:27.924Z pw:browser [err] [20540:12700:0324/173127.924:VERBOSE1:extension_service.cc(1491)] AddComponentExtension Microsoft Clipboard Extension
2021-03-24T21:31:27.924Z pw:browser [err] [20540:12152:0324/173127.924:VERBOSE1:content_verifier.cc(646)] OnFetchComplete iglcjdemknebjbklcgkfaebgojjphkec success:0
2021-03-24T21:31:27.925Z pw:browser [err] [20540:12700:0324/173127.924:VERBOSE1:extension_service.cc(1493)] Component extension Microsoft Clipboard Extension (dgiklkfkllikcanfonkcabmbdfmgleag) installing/upgrading from '' to 1.0
2021-03-24T21:31:27.925Z pw:browser [err] [20540:12700:0324/173127.925:VERBOSE1:extension_service.cc(1491)] AddComponentExtension Edge Collections
2021-03-24T21:31:27.925Z pw:browser [err] [20540:12152:0324/173127.925:VERBOSE1:content_verifier.cc(646)] OnFetchComplete dgiklkfkllikcanfonkcabmbdfmgleag success:0
2021-03-24T21:31:27.925Z pw:browser [err] [20540:12700:0324/173127.925:VERBOSE1:extension_service.cc(1493)] Component extension Edge Collections (fogppepbgmgkpdkinbojbibkhoffpief) installing/upgrading from '' to 1.0
2021-03-24T21:31:27.926Z pw:browser [err] [20540:12152:0324/173127.926:VERBOSE1:content_verifier.cc(646)] OnFetchComplete fogppepbgmgkpdkinbojbibkhoffpief success:0
2021-03-24T21:31:27.926Z pw:browser [err] [20540:12700:0324/173127.926:VERBOSE1:account_reconcilor.cc(248)] AccountReconcilor::AccountReconcilor
2021-03-24T21:31:27.926Z pw:browser [err] [20540:12700:0324/173127.926:VERBOSE1:account_reconcilor.cc(271)] AccountReconcilor::Initialize
2021-03-24T21:31:27.927Z pw:browser [err] [20540:12700:0324/173127.927:VERBOSE1:mutable_profile_oauth2_token_service_delegate.cc(536)] MutablePO2TS::RefreshTokenIsAvailable
2021-03-24T21:31:27.927Z pw:browser [err] [20540:12700:0324/173127.927:VERBOSE1:sync_session_durations_metrics_recorder.cc(54)] Ready to track Session.TotalDuration metrics
2021-03-24T21:31:27.939Z pw:browser [err] [20540:16316:0324/173127.939:VERBOSE1:component_installer.cc(257)] StartRegistration for Subresource Filter Rules
2021-03-24T21:31:27.939Z pw:browser [err] [20540:5608:0324/173127.939:VERBOSE1:component_installer.cc(257)] StartRegistration for Edge Improved Recovery
2021-03-24T21:31:27.939Z pw:browser [err] [20540:29760:0324/173127.939:VERBOSE1:component_installer.cc(257)] StartRegistration for Widevine Content Decryption Module
2021-03-24T21:31:27.939Z pw:browser [err] [20540:26488:0324/173127.939:VERBOSE1:component_installer.cc(257)] StartRegistration for Adobe Flash Player
2021-03-24T21:31:27.939Z pw:browser [err] [20540:6480:0324/173127.939:VERBOSE1:component_installer.cc(257)] StartRegistration for Trust Protection Lists
2021-03-24T21:31:27.940Z pw:browser [err] [20540:24344:0324/173127.939:VERBOSE1:component_installer.cc(257)] StartRegistration for CRLSet
2021-03-24T21:31:27.940Z pw:browser [err] [20540:33328:0324/173127.939:VERBOSE1:component_installer.cc(257)] StartRegistration for Origin Trials
2021-03-24T21:31:27.940Z pw:browser [err] [20540:12700:0324/173127.940:VERBOSE1:first_run.cc(2071)] Browser insatnce coming out to be null
2021-03-24T21:31:27.940Z pw:browser [err] [20540:29992:0324/173127.940:VERBOSE1:taskbar_integration.cc(584)] Pinning or updating taskbar shortcut
2021-03-24T21:31:27.941Z pw:browser [err] [20540:29760:0324/173127.941:VERBOSE1:component_installer.cc(244)] Preinstalled component found for Widevine Content Decryption Module at C:\Program Files (x86)\Microsoft\Edge\Application\86.0.622.56\WidevineCdm with version 4.10.1610.0.
2021-03-24T21:31:27.941Z pw:browser [err] [20540:6480:0324/173127.941:VERBOSE1:component_installer.cc(244)] Preinstalled component found for Trust Protection Lists at C:\Program Files (x86)\Microsoft\Edge\Application\86.0.622.56\Trust Protection Lists with version 1.0.0.13.
2021-03-24T21:31:27.971Z pw:browser [err] [0324/173127.970:ERROR:process_reader_win.cc(127)] NtOpenThread: {Access Denied} A process has requested access to an object, but has not been granted those access rights. (0xc0000022)
2021-03-24T21:31:27.978Z pw:browser [err] [0324/173127.978:ERROR:process_info.cc(617)] range at 0x1e06f5eba40, size 0x84 fully unreadable
2021-03-24T21:31:27.978Z pw:browser [err] [0324/173127.978:ERROR:process_info.cc(617)] range at 0x1e06f5ead30, size 0x84 fully unreadable
2021-03-24T21:31:27.978Z pw:browser [err] [0324/173127.978:ERROR:process_info.cc(617)] range at 0x1e06f5ebb70, size 0x84 fully unreadable
2021-03-24T21:31:27.978Z pw:browser [err] [0324/173127.978:ERROR:process_info.cc(617)] range at 0x1e06f5eb580, size 0x84 fully unreadable
2021-03-24T21:31:27.978Z pw:browser [err] [0324/173127.978:ERROR:process_info.cc(617)] range at 0x1e06f5eba40, size 0x84 fully unreadable
2021-03-24T21:31:27.978Z pw:browser [err] [0324/173127.979:ERROR:process_info.cc(617)] range at 0x1e06f5ead30, size 0x84 fully unreadable
2021-03-24T21:31:27.978Z pw:browser [err] [0324/173127.979:ERROR:process_info.cc(617)] range at 0x1e06f5ebb70, size 0x84 fully unreadable
2021-03-24T21:31:27.979Z pw:browser [err] [0324/173127.979:ERROR:process_info.cc(617)] range at 0x1e06f5eb580, size 0x84 fully unreadable
2021-03-24T21:31:27.979Z pw:browser [err] [20540:18492:0324/173127.979:VERBOSE1:token_service_table.cc(153)] Loaded tokens: result = 3 ; number of tokens loaded = 0
2021-03-24T21:31:27.979Z pw:browser [err] [0324/173127.979:ERROR:process_info.cc(617)] range at 0x1e06f5eba40, size 0x84 fully unreadable
2021-03-24T21:31:27.979Z pw:browser [err] [0324/173127.979:ERROR:process_info.cc(617)] range at 0x1e06f5ead30, size 0x84 fully unreadable
2021-03-24T21:31:27.979Z pw:browser [err] [0324/173127.979:ERROR:process_info.cc(617)] range at 0x1e06f5f1fc0, size 0x30 fully unreadable
2021-03-24T21:31:27.979Z pw:browser [err] [0324/173127.979:ERROR:process_info.cc(617)] range at 0x7ff87c46f280, size 0x28 fully unreadable
2021-03-24T21:31:27.979Z pw:browser [err] [20540:12700:0324/173127.980:VERBOSE1:gaia_cookie_manager_service.cc(1027)] GaiaCookieManagerService::ListAccounts
2021-03-24T21:31:27.980Z pw:browser [err] [20540:25388:0324/173127.980:VERBOSE1:simple_index_file.cc(583)] Simple Cache Index is being restored from disk.
2021-03-24T21:31:27.980Z pw:browser [err] [20540:21000:0324/173127.980:VERBOSE1:simple_index_file.cc(583)] Simple Cache Index is being restored from disk.
2021-03-24T21:31:27.980Z pw:browser [err] [20540:12700:0324/173127.980:VERBOSE1:internet_explorer_session_host_win.cc(510)] LazyParseEmieSitelist emie_xml_path =
2021-03-24T21:31:27.980Z pw:browser [err] [20540:12700:0324/173127.981:VERBOSE1:internet_explorer_session_host_win.cc(523)] LazySetHostAccelerators
2021-03-24T21:31:27.981Z pw:browser [err] [20540:12700:0324/173127.981:VERBOSE1:internet_explorer_session_host_win.cc(550)] LazySetPopupBlockerPermissions
2021-03-24T21:31:27.981Z pw:browser [err] [20540:12700:0324/173127.981:VERBOSE1:internet_explorer_session_host_win.cc(564)] LazySetGeolocationPermissions
2021-03-24T21:31:27.981Z pw:browser [err] [20540:12700:0324/173127.981:VERBOSE1:internet_explorer_session_host_win.cc(510)] LazyParseEmieSitelist emie_xml_path =
2021-03-24T21:31:27.983Z pw:browser [err] [20540:12700:0324/173127.982:VERBOSE1:component_installer.cc(401)] FinishRegistration for Origin Trials
2021-03-24T21:31:27.983Z pw:browser [err] [20540:12700:0324/173127.982:VERBOSE1:component_updater_service.cc(126)] CrxUpdateService starting up. First update attempt will take place in 60 seconds. Next update attempt will take place in 18000 seconds.
2021-03-24T21:31:27.983Z pw:browser [err] [20540:12700:0324/173127.982:VERBOSE1:component_installer.cc(401)] FinishRegistration for CRLSet
2021-03-24T21:31:27.983Z pw:browser [err] [20540:12700:0324/173127.982:VERBOSE1:component_installer.cc(401)] FinishRegistration for Edge Improved Recovery
2021-03-24T21:31:27.983Z pw:browser [err] [20540:12700:0324/173127.982:VERBOSE1:component_installer.cc(401)] FinishRegistration for Adobe Flash Player
2021-03-24T21:31:27.983Z pw:browser [err] [20540:12700:0324/173127.982:VERBOSE1:component_installer.cc(401)] FinishRegistration for Subresource Filter Rules
2021-03-24T21:31:27.983Z pw:browser [err] [20540:12700:0324/173127.982:VERBOSE1:component_installer.cc(401)] FinishRegistration for Widevine Content Decryption Module
2021-03-24T21:31:27.983Z pw:browser [err] [20540:12700:0324/173127.982:VERBOSE1:component_installer.cc(451)] Component ready, version 4.10.1610.0 in C:\Program Files (x86)\Microsoft\Edge\Application\86.0.622.56\WidevineCdm
2021-03-24T21:31:27.983Z pw:browser [err] [20540:12700:0324/173127.982:VERBOSE1:component_installer.cc(401)] FinishRegistration for Trust Protection Lists
2021-03-24T21:31:27.983Z pw:browser [err] [20540:12700:0324/173127.982:VERBOSE1:component_installer.cc(451)] Component ready, version 1.0.0.13 in C:\Program Files (x86)\Microsoft\Edge\Application\86.0.622.56\Trust Protection Lists
2021-03-24T21:31:27.983Z pw:browser [err] [20540:12700:0324/173127.984:VERBOSE1:mutable_profile_oauth2_token_service_delegate.cc(622)] MutablePO2TS::OnWebDataServiceRequestDone. Result type: 6
2021-03-24T21:31:27.984Z pw:browser [err] [20540:12700:0324/173127.984:VERBOSE1:mutable_profile_oauth2_token_service_delegate.cc(682)] MutablePO2TS::LoadAllCredentialsIntoMemory; 0 Credential(s).
2021-03-24T21:31:27.984Z pw:browser [err] [20540:12700:0324/173127.984:VERBOSE1:sync_session_durations_metrics_recorder.cc(146)] OnRefreshTokensLoaded
2021-03-24T21:31:27.989Z pw:browser [err] [20540:12700:0324/173127.989:VERBOSE1:widevine_cdm_component_installer.cc(121)] Register Widevine CDM with Chrome
2021-03-24T21:31:27.989Z pw:browser [err] [20540:12700:0324/173127.989:VERBOSE1:collections_backend.cc(462)] Collections - Sync fetching existing collections
2021-03-24T21:31:28.010Z pw:browser [err] [20540:12700:0324/173128.010:VERBOSE1:pref_proxy_config_tracker_impl.cc(186)] 0000029B83AA2D10: set chrome proxy config service to 0000029B83BC64A0
2021-03-24T21:31:28.012Z pw:browser [err] [20540:12700:0324/173128.012:VERBOSE1:mutable_profile_oauth2_token_service_delegate.cc(536)] MutablePO2TS::RefreshTokenIsAvailable
2021-03-24T21:31:28.014Z pw:browser [err] [20540:31556:0324/173128.013:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Argon2020' log
2021-03-24T21:31:28.014Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Argon2021' log
2021-03-24T21:31:28.015Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Argon2022' log
2021-03-24T21:31:28.015Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Argon2023' log
2021-03-24T21:31:28.015Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Xenon2020' log
2021-03-24T21:31:28.015Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Xenon2021' log
2021-03-24T21:31:28.015Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Xenon2022' log
2021-03-24T21:31:28.015Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Xenon2023' log
2021-03-24T21:31:28.015Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Aviator' log
2021-03-24T21:31:28.015Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Icarus' log
2021-03-24T21:31:28.015Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Pilot' log
2021-03-24T21:31:28.015Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Rocketeer' log
2021-03-24T21:31:28.015Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Google 'Skydiver' log
2021-03-24T21:31:28.015Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Cloudflare 'Nimbus2020' Log
2021-03-24T21:31:28.015Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Cloudflare 'Nimbus2021' Log
2021-03-24T21:31:28.015Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Cloudflare 'Nimbus2022' Log
2021-03-24T21:31:28.015Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Cloudflare 'Nimbus2023' Log
2021-03-24T21:31:28.015Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Log Server
2021-03-24T21:31:28.015Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Yeti2020 Log
2021-03-24T21:31:28.015Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Yeti2021 Log
2021-03-24T21:31:28.015Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Yeti2022 Log
2021-03-24T21:31:28.015Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Yeti2023 Log
2021-03-24T21:31:28.015Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Nessie2020 Log
2021-03-24T21:31:28.015Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Nessie2021 Log
2021-03-24T21:31:28.015Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Nessie2022 Log
2021-03-24T21:31:28.015Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Nessie2023 Log
2021-03-24T21:31:28.015Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Sectigo 'Sabre' CT log
2021-03-24T21:31:28.016Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Sectigo 'Mammoth' CT log
2021-03-24T21:31:28.016Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Let's Encrypt 'Oak2020' log
2021-03-24T21:31:28.016Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Let's Encrypt 'Oak2021' log
2021-03-24T21:31:28.016Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Let's Encrypt 'Oak2022' log
2021-03-24T21:31:28.016Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Symantec 'Sirius' log
2021-03-24T21:31:28.016Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: StartCom log
2021-03-24T21:31:28.016Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: WoSign log
2021-03-24T21:31:28.016Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Izenpe log
2021-03-24T21:31:28.016Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: DigiCert Log Server 2
2021-03-24T21:31:28.016Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: CNNIC CT log
2021-03-24T21:31:28.016Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Venafi log
2021-03-24T21:31:28.016Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Symantec 'Vega' log
2021-03-24T21:31:28.016Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Certly.IO log
2021-03-24T21:31:28.016Z pw:browser [err] [20540:31556:0324/173128.014:VERBOSE1:multi_log_ct_verifier.cc(62)] Adding CT log: Symantec log
2021-03-24T21:31:28.044Z pw:browser [err] [20540:29992:0324/173128.043:VERBOSE1:taskbar_integration.cc(442)] Couldn't replace Edge UWP taskbar pin, falling back to pinning or updating
2021-03-24T21:31:28.129Z pw:browser [err] [20540:29992:0324/173128.129:VERBOSE1:shell_util.cc(3877)] IsEnterpriseDevice() returning true VersionType == SUITE_ENTERPRISE
2021-03-24T21:31:28.130Z pw:browser [err] [20540:29992:0324/173128.129:VERBOSE1:taskbar_integration.cc(375)] Did not pin or update Edge taskbar shortcut
2021-03-24T21:31:28.282Z pw:browser [err] [20540:12152:0324/173128.282:WARNING:gpu_process_host.cc(1279)] The GPU process has crashed 1 time(s)
2021-03-24T21:31:28.407Z pw:browser [err] [0324/173128.406:ERROR:minidumpwritedump_with_crashpad_info.cc(452)] Failed to call MiniDumpWriteDump: The program issued a command but the command length is incorrect. (0x80070018)
2021-03-24T21:31:28.407Z pw:browser [err] [0324/173128.406:ERROR:minidumpwritedump_with_crashpad_info.cc(661)] Failed to write minidump file
2021-03-24T21:31:28.407Z pw:browser [err] [0324/173128.406:ERROR:crash_report_exception_handler.cc(134)] TryMiniDumpWriteDumpWithCrashpadInfo failed
2021-03-24T21:31:28.542Z pw:browser [err] [20540:12152:0324/173128.542:WARNING:gpu_process_host.cc(1279)] The GPU process has crashed 2 time(s)
2021-03-24T21:31:28.652Z pw:browser [err] [20540:12700:0324/173128.651:VERBOSE1:chrome_password_manager_client.cc(1277)] ChromePasswordManagerClient: this: 0000029B8422FE50
2021-03-24T21:31:28.652Z pw:browser [err] [20540:12700:0324/173128.651:VERBOSE1:chrome_password_manager_client.cc(1278)] wc: 0000029B84227AC0
2021-03-24T21:31:28.652Z pw:browser [err] [20540:12700:0324/173128.651:VERBOSE1:chrome_password_manager_client.cc(1279)] wc->GetRenderViewHost(): 0000029B840CD560
2021-03-24T21:31:28.653Z pw:browser [err] [20540:12700:0324/173128.652:VERBOSE1:edge_ui_features.cc(223)] IsWindowTabManagerEnabled starting
2021-03-24T21:31:28.653Z pw:browser [err] [20540:12700:0324/173128.652:VERBOSE1:wtm_interface_factory.cc(155)] IsApiAvailable starting
2021-03-24T21:31:28.653Z pw:browser [err] [20540:12700:0324/173128.652:VERBOSE1:wtm_interface_factory.cc(201)] IsApiAvailable returning false
2021-03-24T21:31:28.653Z pw:browser [err] [20540:12700:0324/173128.652:VERBOSE1:edge_ui_features.cc(240)] IsWindowTabManagerEnabled returning false
2021-03-24T21:31:28.668Z pw:browser [err] [0324/173128.667:ERROR:minidumpwritedump_with_crashpad_info.cc(452)] Failed to call MiniDumpWriteDump: The program issued a command but the command length is incorrect. (0x80070018)
2021-03-24T21:31:28.668Z pw:browser [err] [0324/173128.667:ERROR:minidumpwritedump_with_crashpad_info.cc(661)] Failed to write minidump file
2021-03-24T21:31:28.668Z pw:browser [err] [0324/173128.667:ERROR:crash_report_exception_handler.cc(134)] TryMiniDumpWriteDumpWithCrashpadInfo failed
2021-03-24T21:31:28.679Z pw:browser [err] [20540:12700:0324/173128.678:VERBOSE1:chrome_password_manager_client.cc(1374)] RenderFrameCreated: this: 0000029B8422FE50
2021-03-24T21:31:28.679Z pw:browser [err] [20540:12700:0324/173128.678:VERBOSE1:chrome_password_manager_client.cc(1375)] rfh: 0000029B8422DE50
2021-03-24T21:31:28.679Z pw:browser [err] [20540:12700:0324/173128.678:VERBOSE1:chrome_password_manager_client.cc(1376)] rfh->GetView(): 0000029B84268DC0
2021-03-24T21:31:28.679Z pw:browser [err] [20540:12700:0324/173128.678:VERBOSE1:chrome_password_manager_client.cc(183)] AddToWidgetInputEventObservers: widget_host: 0000029B8422D710; observer: 0000029B8422FE78
2021-03-24T21:31:28.731Z pw:browser [err] [20540:12700:0324/173128.727:VERBOSE1:service_discovery_device_lister.cc(40)] DeviceListerStart: service_type: _googlecast._tcp.local
2021-03-24T21:31:28.731Z pw:browser [err] [20540:12700:0324/173128.727:VERBOSE1:service_discovery_device_lister.cc(46)] DiscoverNewDevices: service_type: _googlecast._tcp.local
2021-03-24T21:31:28.815Z pw:browser [err] [0324/173128.814:ERROR:process_reader_win.cc(127)] NtOpenThread: {Access Denied} A process has requested access to an object, but has not been granted those access rights. (0xc0000022)
2021-03-24T21:31:28.892Z pw:browser [err] [20540:12152:0324/173128.892:WARNING:gpu_process_host.cc(1279)] The GPU process has crashed 3 time(s)
2021-03-24T21:31:29.100Z pw:browser [err] [20540:12700:0324/173129.100:VERBOSE1:chrome_password_manager_client.cc(1391)] RenderFrameDeleted: this: 0000029B8422FE50
2021-03-24T21:31:29.100Z pw:browser [err] [20540:12700:0324/173129.100:VERBOSE1:chrome_password_manager_client.cc(1392)] rfh: 0000029B8422DE50
2021-03-24T21:31:29.100Z pw:browser [err] [20540:12700:0324/173129.100:VERBOSE1:chrome_password_manager_client.cc(1393)] rfh->GetView(): 0000000000000000
2021-03-24T21:31:29.239Z pw:browser [err] [20540:12152:0324/173129.239:WARNING:gpu_process_host.cc(1279)] The GPU process has crashed 4 time(s)
2021-03-24T21:31:29.598Z pw:browser [err] [20540:12152:0324/173129.598:WARNING:gpu_process_host.cc(1279)] The GPU process has crashed 5 time(s)
2021-03-24T21:31:29.929Z pw:browser [err] [20540:12152:0324/173129.928:WARNING:gpu_process_host.cc(1279)] The GPU process has crashed 6 time(s)
2021-03-24T21:31:29.930Z pw:browser [err] [20540:12152:0324/173129.929:ERROR:browser_gpu_channel_host_factory.cc(167)] Failed to launch GPU process.
2021-03-24T21:31:36.954Z pw:browser [err] [20540:12700:0324/173136.954:VERBOSE1:device_event_log_impl.cc(210)] [17:31:36.953] FIDO: DEBUG: webauthn_api.cc:85 webauthn.dll version 1
2021-03-24T21:31:37.007Z pw:browser [err] [20540:31556:0324/173137.007:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: https://edge.microsoft.com/abusiveadblocking/api/v1/blocklist
2021-03-24T21:31:37.055Z pw:browser [err] [20540:12152:0324/173137.054:VERBOSE1:mdns_client_impl.cc(161)] Sockets ready:2
2021-03-24T21:31:37.071Z pw:browser [err] [20540:12700:0324/173137.070:ERROR:device_event_log_impl.cc(208)] [17:31:37.070] Bluetooth: bluetooth_adapter_winrt.cc:1076 Getting Default Adapter failed.

[ephung01]

if I have DEBUG=pw.browser only
"C:\Program Files\Java\jdk1.8.0_121\bin\java.exe" -javaagent:C:\ideaIC-2020.2.1\lib\idea_rt.jar=58600:C:\ideaIC-2020.2.1\bin -Dfile.encoding=UTF-8 -classpath "C:\Program Files\Java\jdk1.8.0_121\jre\lib\charsets.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\deploy.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\ext\access-bridge-64.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\ext\cldrdata.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\ext\dnsns.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\ext\jaccess.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\ext\jfxrt.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\ext\localedata.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\ext\nashorn.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\ext\sunec.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\ext\sunjce_provider.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\ext\sunmscapi.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\ext\sunpkcs11.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\ext\zipfs.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\javaws.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\jce.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\jfr.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\jfxswt.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\jsse.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\management-agent.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\plugin.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\resources.jar;C:\Program Files\Java\jdk1.8.0_121\jre\lib\rt.jar;C:\Users\ephung\Development\TestPlayWright\out\production\classes;C:\Users\ephung.gradle\caches\modules-2\files-2.1\com.microsoft.playwright\playwright\1.9.1-alpha-0\dbb6f4a7686b61da408c92fa926c22aae333562c\playwright-1.9.1-alpha-0.jar;C:\Users\ephung.gradle\caches\modules-2\files-2.1\com.microsoft.playwright\driver-bundle\1.9.1-alpha-0\dd9ed2801d0205ed8d97f4c6bdf2a048fde1b922\driver-bundle-1.9.1-alpha-0.jar;C:\Users\ephung.gradle\caches\modules-2\files-2.1\com.microsoft.playwright\driver\1.9.1-alpha-0\943047a4ad4d98143812ca0300fc8bd940a3f22e\driver-1.9.1-alpha-0.jar;C:\Users\ephung.gradle\caches\modules-2\files-2.1\com.google.code.gson\gson\2.8.6\9180733b7df8542621dc12e21e87557e8c99b8cb\gson-2.8.6.jar;C:\Users\ephung.gradle\caches\modules-2\files-2.1\org.java-websocket\Java-WebSocket\1.5.1\382b302303c830a7edb20c9ed61c4ac2cdf7a7a4\Java-WebSocket-1.5.1.jar;C:\Users\ephung.gradle\caches\modules-2\files-2.1\org.slf4j\slf4j-api\1.7.25\da76ca59f6a57ee3102f8f9bd9cee742973efa8a\slf4j-api-1.7.25.jar" Test
2021-03-24T21:35:56.127Z pw:browser C:\Program Files (x86)\Microsoft\Edge\Application\msedge.exe --disable-background-networking --enable-features=NetworkService,NetworkServiceInProcess --disable-background-timer-throttling --disable-backgrounding-occluded-windows --disable-breakpad --disable-client-side-phishing-detection --disable-component-extensions-with-background-pages --disable-default-apps --disable-dev-shm-usage --disable-extensions --disable-features=TranslateUI,BlinkGenPropertyTrees,ImprovedCookieControls,SameSiteByDefaultCookies,LazyFrameLoading --disable-hang-monitor --disable-ipc-flooding-protection --disable-popup-blocking --disable-prompt-on-repost --disable-renderer-backgrounding --disable-sync --force-color-profile=srgb --metrics-recording-only --no-first-run --enable-automation --password-store=basic --use-mock-keychain --user-data-dir=C:\Users\ephung\AppData\Local\Temp\playwright_chromiumdev_profile-z0obei --remote-debugging-pipe --no-startup-window
2021-03-24T21:35:56.128Z pw:browser pid=31788
2021-03-24T21:36:01.357Z pw:browser
2021-03-24T21:36:02.635Z pw:browser [err] [31788:27056:0324/173602.634:ERROR:device_event_log_impl.cc(208)] [17:36:02.634] Bluetooth: bluetooth_adapter_winrt.cc:1076 Getting Default Adapter failed.

The process would stuck forever(I left it overnight and still running next day) unless I manually kill it.

[ephung01]

Thanks. Do you know when will this get push to maven central? Current version 1.10.0 is not included this change.

[yury-s]

Publishing it to 1.11.0-SNAPSHOT, should be available there in a few minutes.

[ephung01]

It's still not working with Browser.close(). But if I removed the Browser.close(), playwright is terminated after 30 seconds timeout (which is work - I can live with 30 sec slower). Previously, playwright cannot be terminate and got stuck even after remove Browser.close(). I've tested with Chrome Version 88.0.4324.150 also (latest my company allow) and experienced the same issue.

[Question] With 30 secs timeout, all scripts are now take 30 seconds longer. Is there a way to force kill playwright (without waiting?) - like forceClose()?

NOTE: the error seems to relate to chromium core (C++). I found on internet it also happens with Selenium. I've tried to put chrome options --enable-logging and --no-sandbox, but did not resolve the issue.

ERROR:device_event_log_impl.cc(211)] [11:58:41.262] Bluetooth: bluetooth_adapter_winrt.cc:1072 Getting Default Adapter failed.

screenshot 30 seconds timeout after comment out Browser.close():

[yury-s]

It's still not working with Browser.close(). But if I removed the Browser.close(), playwright is terminated after 30 seconds timeout (which is work - I can live with 30 sec slower). Previously, playwright cannot be terminate and got stuck even after remove Browser.close(). I've tested with Chrome Version 88.0.4324.150 also (latest my company allow) and experienced the same issue.

Oh, interesting. So playwright driver process (should be something like node.exe package\lib\cli\cli.js on Windows) must be also hanging, can you check that in task manager? This means that our code that kills browser process on Windows doesn't work in your case.

Can you try running taskkill /pid <browser process id> /T /F in terminal manually and see what it returns for the hanging process?

[Question] With 30 secs timeout, all scripts are now take 30 seconds longer.

Not a solution to this particular bug but in general we assume that you will create a new context for next test and reuse the same browser instance. The contexts are very cheap to create/destroy compared to launching new process, yet they provide nice isolation between tests. Is there a particular reason you have to restart the browser between tests?

Is there a way to force kill playwright (without waiting?) - like forceClose()?

This is one of the options we discussed (the other was to allow configuring timeout in close()), the main issue is that on linux (probably on windows too) this would create core dumps on every abnormal process exit which we'd like to avoid. So we are hesitant at the moment.

NOTE: the error seems to relate to chromium core (C++). I found on internet it also happens with Selenium. I've tried to put chrome options --enable-logging and --no-sandbox, but did not resolve the issue.

ERROR:device_event_log_impl.cc(211)] [11:58:41.262] Bluetooth: bluetooth_adapter_winrt.cc:1072 Getting Default Adapter failed.

This seems like a benign error to me which should not prevent the browser from exiting. Are there any evidences from others showing their browsers hang because of the same problem? Can you share a link?

[ephung01]

It's still not working with Browser.close(). But if I removed the Browser.close(), playwright is terminated after 30 seconds timeout (which is work - I can live with 30 sec slower). Previously, playwright cannot be terminate and got stuck even after remove Browser.close(). I've tested with Chrome Version 88.0.4324.150 also (latest my company allow) and experienced the same issue.

Oh, interesting. So playwright driver process (should be something like node.exe package\lib\cli\cli.js on Windows) must be also hanging, can you check that in task manager? This means that our code that kills browser process on Windows doesn't work in your case.

Can you try running taskkill /pid <browser process id> /T /F in terminal manually and see what it returns for the hanging process?

[Question] With 30 secs timeout, all scripts are now take 30 seconds longer.

Not a solution to this particular bug but in general we assume that you will create a new context for next test and reuse the same browser instance. The contexts are very cheap to create/destroy compared to launching new process, yet they provide nice isolation between tests. Is there a particular reason you have to restart the browser between tests?

Is there a way to force kill playwright (without waiting?) - like forceClose()?

This is one of the options we discussed (the other was to allow configuring timeout in close()), the main issue is that on linux (probably on windows too) this would create core dumps on every abnormal process exit which we'd like to avoid. So we are hesitant at the moment.

NOTE: the error seems to relate to chromium core (C++). I found on internet it also happens with Selenium. I've tried to put chrome options --enable-logging and --no-sandbox, but did not resolve the issue.

ERROR:device_event_log_impl.cc(211)] [11:58:41.262] Bluetooth: bluetooth_adapter_winrt.cc:1072 Getting Default Adapter failed.

This seems like a benign error to me which should not prevent the browser from exiting. Are there any evidences from others showing their browsers hang because of the same problem? Can you share a link?

It's still not working with Browser.close(). But if I removed the Browser.close(), playwright is terminated after 30 seconds timeout (which is work - I can live with 30 sec slower). Previously, playwright cannot be terminate and got stuck even after remove Browser.close(). I've tested with Chrome Version 88.0.4324.150 also (latest my company allow) and experienced the same issue.

Oh, interesting. So playwright driver process (should be something like node.exe package\lib\cli\cli.js on Windows) must be also hanging, can you check that in task manager? This means that our code that kills browser process on Windows doesn't work in your case.
Could that be because of user's ACL (Access Control List) is lack of authorization?

Can you try running taskkill /pid <browser process id> /T /F in terminal manually and see what it returns for the hanging process?

[Question] With 30 secs timeout, all scripts are now take 30 seconds longer.

Not a solution to this particular bug but in general we assume that you will create a new context for next test and reuse the same browser instance. The contexts are very cheap to create/destroy compared to launching new process, yet they provide nice isolation between tests. Is there a particular reason you have to restart the browser between tests?

Is there a way to force kill playwright (without waiting?) - like forceClose()?

This is one of the options we discussed (the other was to allow configuring timeout in close()), the main issue is that on linux (probably on windows too) this would create core dumps on every abnormal process exit which we'd like to avoid. So we are hesitant at the moment.

NOTE: the error seems to relate to chromium core (C++). I found on internet it also happens with Selenium. I've tried to put chrome options --enable-logging and --no-sandbox, but did not resolve the issue.

ERROR:device_event_log_impl.cc(211)] [11:58:41.262] Bluetooth: bluetooth_adapter_winrt.cc:1072 Getting Default Adapter failed.

This seems like a benign error to me which should not prevent the browser from exiting. Are there any evidences from others showing their browsers hang because of the same problem? Can you share a link?

https://stackoverflow.com/questions/61561112/how-to-solve-getting-default-adapter-failed-error-when-launching-chrome-and-tr

I cannot delete the registry as instructed in the article.
http://blogs.stevelongchen.com/2020/05/15/selenium-chrome-driver-resolve-error-messages-regarding-registry-keys-and-experimental-options/

[ephung01]

Thanks for checking this! Do I understand correctly that the same taskkill command works perfectly fine when you run it manually in command line but fails when we do it from nodejs in response to Browser.close? Do you see line like [pid=12345] <kill> after you started Browser.close() and it was hanging for 30 seconds? Meanwhile let me add some more logging to that code.

That is correct.   When manually do taskkill in command prompt, it terminates the process.   When I run using playwright-java to call browser.close(), it hanged - it hang indefinitely (NO timeout).   Timeout happens when I don't call browser.close() (comment out) and just call playwright.close() -  see image posted with circle red on comment out browser.close().

[yury-s]

That is correct. When manually do taskkill in command prompt, it terminates the process. When I run using playwright-java to call browser.close(), it hanged - it hang indefinitely (NO timeout). Timeout happens when I don't call browser.close() (comment out) and just call playwright.close() - see image posted with circle red on comment out browser.close().

I see, thanks for confirming. I'd like you to run Browser.close with the logging added (once I roll it to java).

Reading the stackoverflow thread you referred to and this comment in particular I suspect that it might be a problem with privileges. Could it be that you run your tests as a normal(unprivileged) user but executed taskkill in command line window which was 'Run as Administrator' ? It might be that if you run your test from terminal started as Administrator the problem will vanish.

[ephung01]

Reading the stackoverflow thread you referred to and this comment in particular I suspect that it might be a problem with privileges. Could it be that you run your tests as a normal(unprivileged) user but executed taskkill in command line window which was 'Run as Administrator' ? It might be that if you run your test from terminal started as Administrator the problem will vanish.

My windows user does not have Administrator role (all developers do not have Administrator role). So taskkill in command line were not executed under administrator privilege. Could it be node is running as sandbox and cannot kill the outside process?

[yury-s]

Could it be node is running as sandbox and cannot kill the outside process?

This is unlikely. We start it as a regular process. That code runs this script on windows, as you can see it is simple wrapper around node.exe and the args, should not add any sandboxes.

[ephung01]

Could it be node is running as sandbox and cannot kill the outside process?

This is unlikely. We start it as a regular process. That code runs this script on windows, as you can see it is simple wrapper around node.exe and the args, should not add any sandboxes.

New Log:
2021-04-01T13:13:14.650Z pw:browser [pid=12740][err] [12740:980:0401/091314.650:WARNING:spdy_session.cc(3403)] Received HEADERS for invalid stream 31
Close Browser: 2021-04-01 09:13:14.704
2021-04-01T13:13:14.706Z pw:browser [pid=12740]
2021-04-01T13:13:14.714Z pw:browser [pid=12740][err] [12740:20468:0401/091314.714:VERBOSE1:application_lifetime.cc(328)] ExitIgnoreUnloadHandlers
2021-04-01T13:13:18.992Z pw:browser [pid=12740][err] [12740:20468:0401/091318.991:VERBOSE1:device_event_log_impl.cc(210)] [09:13:18.991] FIDO: DEBUG: webauthn_api.cc:85 webauthn.dll version 1
2021-04-01T13:13:19.311Z pw:browser [pid=12740][err] [12740:980:0401/091319.311:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: https://edge.microsoft.com/abusiveadblocking/api/v1/blocklist
2021-04-01T13:13:19.350Z pw:browser [pid=12740][err] [12740:18208:0401/091319.349:VERBOSE1:mdns_client_impl.cc(161)] Sockets ready:2
2021-04-01T13:13:19.365Z pw:browser [pid=12740][err] [12740:20468:0401/091319.364:ERROR:device_event_log_impl.cc(208)] [09:13:19.365] Bluetooth: bluetooth_adapter_winrt.cc:1076 Getting Default Adapter failed.
2021-04-01T13:14:10.015Z pw:browser [pid=12740][err] [12740:20468:0401/091410.014:VERBOSE1:component_updater_service.cc(372)] CheckForUpdates: automatic updatecheck for components.
2021-04-01T13:14:10.015Z pw:browser [pid=12740][err] [12740:20468:0401/091410.014:VERBOSE1:request_sender.cc(140)] is off the record0
2021-04-01T13:14:10.016Z pw:browser [pid=12740][err] [12740:980:0401/091410.015:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: https://edge.microsoft.com/componentupdater/api/v1/update?cup2key=3:982047197&cup2hreq=1d286b77a8d108e4f73d2a90981542ecc543c0f146175e79f5ea5a23f6f17ac4
2021-04-01T13:14:10.056Z pw:browser [pid=12740][err] [12740:20468:0401/091410.056:VERBOSE1:request_sender.cc(215)] Request completed from url: https://edge.microsoft.com/componentupdater/api/v1/update?cup2key=3:982047197&cup2hreq=1d286b77a8d108e4f73d2a90981542ecc543c0f146175e79f5ea5a23f6f17ac4
2021-04-01T13:14:10.057Z pw:browser [pid=12740][err] [12740:20468:0401/091410.056:VERBOSE1:request_sender.cc(140)] is off the record0
2021-04-01T13:14:10.057Z pw:browser [pid=12740][err] [12740:980:0401/091410.057:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: https://edge.microsoft.com/componentupdater/api/v1/update
2021-04-01T13:14:10.087Z pw:browser [pid=12740][err] [12740:14008:0401/091410.086:VERBOSE1:background_downloader_win.cc(441)] Starting BITS download for: http://msedge.b.tlu.dl.delivery.mp.microsoft.com/filestreamingservice/files/b22f5f18-f7ea-4290-929d-b13c03908334?P1=1617837385&P2=404&P3=2&P4=Er265y3oNa6DPwa%2b2xwPre6BulPhCfKAPWbIBwT6%2bwVU979G9ep7BhZlZ9APH6CQc%2fOLWJrPTvMeCns5WC%2bXYg%3d%3d
2021-04-01T13:14:10.096Z pw:browser [pid=12740][err] [12740:20468:0401/091410.095:VERBOSE1:request_sender.cc(215)] Request completed from url: https://edge.microsoft.com/componentupdater/api/v1/update
2021-04-01T13:14:14.091Z pw:browser [pid=12740][err] [12740:7656:0401/091414.091:VERBOSE1:component_unpacker.cc(59)] Verifying component: C:\Users\ephung\AppData\Local\Temp\edge_BITS_12740_773950349\b22f5f18-f7ea-4290-929d-b13c03908334
2021-04-01T13:14:14.092Z pw:browser [pid=12740][err] [12740:7656:0401/091414.092:VERBOSE1:component_unpacker.cc(77)] Verification successful: C:\Users\ephung\AppData\Local\Temp\edge_BITS_12740_773950349\b22f5f18-f7ea-4290-929d-b13c03908334
2021-04-01T13:14:14.092Z pw:browser [pid=12740][err] [12740:7656:0401/091414.092:VERBOSE1:component_unpacker.cc(90)] Unpacking in: C:\Users\ephung\AppData\Local\Temp\12740_1497483445
2021-04-01T13:14:14.251Z pw:browser [pid=12740][err] [12740:7656:0401/091414.251:VERBOSE1:component_unpacker.cc(103)] Unpacked successfully
2021-04-01T13:14:14.253Z pw:browser [pid=12740][err] [12740:7656:0401/091414.254:VERBOSE1:component_installer.cc(109)] Install: version=0.0.1.4 current version=0.0.0.0
2021-04-01T13:14:14.254Z pw:browser [pid=12740][err] [12740:7656:0401/091414.254:VERBOSE1:component_installer.cc(127)] unpack_path=C:\Users\ephung\AppData\Local\Temp\12740_1497483445 install_path=C:\Users\ephung\AppData\Local\Temp\playwright_chromiumdev_profile-PfJ2bE\OriginTrials\0.0.1.4
2021-04-01T13:14:14.255Z pw:browser [pid=12740][err] [12740:20468:0401/091414.255:VERBOSE1:component_installer.cc(451)] Component ready, version 0.0.1.4 in C:\Users\ephung\AppData\Local\Temp\playwright_chromiumdev_profile-PfJ2bE\OriginTrials\0.0.1.4
2021-04-01T13:14:14.256Z pw:browser [pid=12740][err] [12740:20468:0401/091414.256:VERBOSE1:request_sender.cc(140)] is off the record0
2021-04-01T13:14:14.256Z pw:browser [pid=12740][err] [12740:980:0401/091414.257:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: https://edge.microsoft.com/componentupdater/api/v1/update
2021-04-01T13:14:14.294Z pw:browser [pid=12740][err] [12740:20468:0401/091414.294:VERBOSE1:request_sender.cc(215)] Request completed from url: https://edge.microsoft.com/componentupdater/api/v1/update
2021-04-01T13:14:18.458Z pw:browser [pid=12740][err] [12740:20468:0401/091418.458:VERBOSE1:request_sender.cc(140)] is off the record0
2021-04-01T13:14:18.458Z pw:browser [pid=12740][err] [12740:980:0401/091418.458:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: https://edge.microsoft.com/componentupdater/api/v1/update
2021-04-01T13:14:18.470Z pw:browser [pid=12740][err] [12740:14008:0401/091418.470:VERBOSE1:background_downloader_win.cc(441)] Starting BITS download for: http://msedge.b.tlu.dl.delivery.mp.microsoft.com/filestreamingservice/files/70ac302a-1075-4e20-9e11-b87864a817bb?P1=1617837385&P2=404&P3=2&P4=RQKV6rKWQz2FjBOHsrXzywYzx9qsqYwZbdDQvY8Rq5ZCh5keMNIihUoMWMtz%2bz2uizrGqMgHfVOK802CdX1vkQ%3d%3d
2021-04-01T13:14:18.497Z pw:browser [pid=12740][err] [12740:20468:0401/091418.497:VERBOSE1:request_sender.cc(215)] Request completed from url: https://edge.microsoft.com/componentupdater/api/v1/update
2021-04-01T13:14:22.476Z pw:browser [pid=12740][err] [12740:7656:0401/091422.476:VERBOSE1:component_unpacker.cc(59)] Verifying component: C:\Users\ephung\AppData\Local\Temp\edge_BITS_12740_356234188\70ac302a-1075-4e20-9e11-b87864a817bb
2021-04-01T13:14:22.476Z pw:browser [pid=12740][err] [12740:7656:0401/091422.476:VERBOSE1:component_unpacker.cc(77)] Verification successful: C:\Users\ephung\AppData\Local\Temp\edge_BITS_12740_356234188\70ac302a-1075-4e20-9e11-b87864a817bb
2021-04-01T13:14:22.477Z pw:browser [pid=12740][err] [12740:7656:0401/091422.477:VERBOSE1:component_unpacker.cc(90)] Unpacking in: C:\Users\ephung\AppData\Local\Temp\12740_1799687248
2021-04-01T13:14:22.637Z pw:browser [pid=12740][err] [12740:7656:0401/091422.637:VERBOSE1:component_unpacker.cc(103)] Unpacked successfully
2021-04-01T13:14:22.640Z pw:browser [pid=12740][err] [12740:18976:0401/091422.639:VERBOSE1:component_installer.cc(109)] Install: version=6498.2021.3.1 current version=0.0.0.0
2021-04-01T13:14:22.640Z pw:browser [pid=12740][err] [12740:18976:0401/091422.639:VERBOSE1:component_installer.cc(127)] unpack_path=C:\Users\ephung\AppData\Local\Temp\12740_1799687248 install_path=C:\Users\ephung\AppData\Local\Temp\playwright_chromiumdev_profile-PfJ2bE\CertificateRevocation\6498.2021.3.1
2021-04-01T13:14:22.643Z pw:browser [pid=12740][err] [12740:20468:0401/091422.643:VERBOSE1:component_installer.cc(451)] Component ready, version 6498.2021.3.1 in C:\Users\ephung\AppData\Local\Temp\playwright_chromiumdev_profile-PfJ2bE\CertificateRevocation\6498.2021.3.1
2021-04-01T13:14:22.646Z pw:browser [pid=12740][err] [12740:20468:0401/091422.646:VERBOSE1:request_sender.cc(140)] is off the record0
2021-04-01T13:14:22.646Z pw:browser [pid=12740][err] [12740:980:0401/091422.646:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: https://edge.microsoft.com/componentupdater/api/v1/update
2021-04-01T13:14:22.685Z pw:browser [pid=12740][err] [12740:20468:0401/091422.684:VERBOSE1:request_sender.cc(215)] Request completed from url: https://edge.microsoft.com/componentupdater/api/v1/update
2021-04-01T13:14:26.837Z pw:browser [pid=12740][err] [12740:20468:0401/091426.836:VERBOSE1:request_sender.cc(140)] is off the record0
2021-04-01T13:14:26.837Z pw:browser [pid=12740][err] [12740:980:0401/091426.836:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: https://edge.microsoft.com/componentupdater/api/v1/update
2021-04-01T13:14:26.837Z pw:browser [pid=12740][err] [12740:20468:0401/091426.836:VERBOSE1:request_sender.cc(140)] is off the record0
2021-04-01T13:14:26.837Z pw:browser [pid=12740][err] [12740:20468:0401/091426.836:VERBOSE1:component_updater_service.cc(471)] Update completed with error 0
2021-04-01T13:14:26.837Z pw:browser [pid=12740][err] [12740:980:0401/091426.837:VERBOSE1:network_delegate.cc(32)] NetworkDelegate::NotifyBeforeURLRequest: https://edge.microsoft.com/componentupdater/api/v1/update
2021-04-01T13:14:26.874Z pw:browser [pid=12740][err] [12740:20468:0401/091426.874:VERBOSE1:request_sender.cc(215)] Request completed from url: https://edge.microsoft.com/componentupdater/api/v1/update
2021-04-01T13:14:26.878Z pw:browser [pid=12740][err] [12740:20468:0401/091426.878:VERBOSE1:request_sender.cc(215)] Request completed from url: https://edge.microsoft.com/componentupdater/api/v1/update
2021-04-01T13:23:09.773Z pw:browser [pid=12740][err] [0401/092309.772:ERROR:directory_reader_win.cc(43)] FindFirstFile: The system cannot find the path specified. (0x3)

NOTE:
When Browser start to close ( circle red below). Internal chrome/edge chrome is looking for update to newer version. All the update request will be blocked due to company policy - this process retried 3 times and then hang thereafter.

this error and log is from Microsoft Edge Chromium, when run against chrome, there are alot more in error log.

The error: "ERROR:device_event_log_impl.cc(208)] [09:13:19.365] Bluetooth: bluetooth_adapter_winrt.cc:1076 Getting Default Adapter failed" is probaly trying to access to RSA authenticatio (not sure).

[ephung01]

I added the flag "--disable-component-update". I don't see any further update request, but it just hang without further error

[yury-s]

Nice finding! So the autoupdate kicks in while we are closing the browser. I'm still trying to roll my change to the driver with more logging around forceful process kill but it got stuck because I found more issues that need to be fixed upstream first. Once that lands it should help us understand why taskkill cannot terminate the updater.

[yury-s]

I landed changes with extra logging and they are now available in 1.11.0-SNAPSHOT, I'd appreciate if you could give it a try and see what the output is when running with DEBUG=pw:browser

[ephung01]

I landed changes with extra logging and they are now available in 1.11.0-SNAPSHOT, I'd appreciate if you could give it a try and see what the output is when running with DEBUG=pw:browser

Look like it's working. Browser.close() with 30 seconds delay, but it did closed (circle time in red). Playwright is terminated right away (previously took 30 seconds).

[yury-s]

Hmm, this is weird. I only added more logging and expected it to fail again but a bit more details in the console. Also there are now traces of auto-update in this log so maybe it succeeded and stopped until the next update (just a wild guess) and now the browser is not hanging anymore 🤷‍♂️

[ephung01]

Hmm, this is weird. I only added more logging and expected it to fail again but a bit more details in the console. Also there are now traces of auto-update in this log so maybe it succeeded and stopped until the next update (just a wild guess) and now the browser is not hanging anymore 🤷‍♂️

Is there updated on the playwright node side? I find out that whenever get new playwright code, ran "./scripts/download_driver_for_all_platforms.sh -f", then rebuild my project; it behave different.

[yury-s]

Is there updated on the playwright node side?

Yes, it was changed in the node. I see the new line (<will force kill>) in your logs so you picked it up already.

I find out that whenever get new playwright code, ran "./scripts/download_driver_for_all_platforms.sh -f", then rebuild my project; it behave different.

This is expected, there should be no regressions though.

I just realized that you are building playwright and the driver too from source while I was assuming that you just use the version published to Maven Central. In this case you DO need to run ./scripts/download_driver_for_all_platforms.sh -f again to fetch updated driver version and then rebuild playwright. Sorry for the misunderstanding.

[ephung01]

I just realized that you are building playwright and the driver too from source while I was assuming that you just use the version published to Maven Central. In this case you DO need to run ./scripts/download_driver_for_all_platforms.sh -f again to fetch updated driver version and then rebuild playwright. Sorry for the misunderstanding.

I tried to check for SNAPSHOT version but couldn't find it (see pix). If you have a branch on your github repository fork, I can tried it with your change.

[yury-s]

I tried to check for SNAPSHOT version but couldn't find it (see pix). If you have a branch on your github repository fork, I can tried it with your change.

*-SNAPSHOT versions are served from their staging repo, to use that you need to add these lines to your pom.xml:

  <repositories>
    <repository>
      <id>snapshots-repo</id>
      <url>https://oss.sonatype.org/content/repositories/snapshots</url>
      <releases><enabled>false</enabled></releases>
      <snapshots><enabled>true</enabled></snapshots>
    </repository>
  </repositories>

But if you build from source with updated driver it should make no difference.

[yury-s]

@ephung01 did you manage to run it with -snapshot version and collect DEBUG=pw:browser logs it'd be very nice to nail it down while it is reproducible on your machine?

[yury-s]

microsoft/playwright#6232 might be helpful for this issue too

[mrsenzy]

Just for reference, Below step helped to complete the process after execution.

    if(browser==null) {
        try {
            Runtime.getRuntime().exec("taskkill /im chrome.exe /f");
        } catch (IOException e) {
            e.printStackTrace();
        }
    }

[yury-s]

I wonder why it gives different result than what we do here: taskkill /pid <id> /T /F

[ephung01]

Just for reference, Below step helped to complete the process after execution.

    if(browser==null) {
        try {
            Runtime.getRuntime().exec("taskkill /im chrome.exe /f");
        } catch (IOException e) {
            e.printStackTrace();
        }
    }

blindly force to kill chrome.exe will kill other browsers that are currently execute scripts in parallel

[ephung01]

@ephung01 did you manage to run it with -snapshot version and collect DEBUG=pw:browser logs it'd be very nice to nail it down while it is reproducible on your machine?

I will try it tomorrow

[mrsenzy]

Just for reference, Below step helped to complete the process after execution.

    if(browser==null) {
        try {
            Runtime.getRuntime().exec("taskkill /im chrome.exe /f");
        } catch (IOException e) {
            e.printStackTrace();
        }
    }

blindly force to kill chrome.exe will kill other browsers that are currently execute scripts in parallel

That is the reason we are checking if Condition for browser==null and then killing the browser - tested parallel execution and it works fine.

[ephung01]

I wonder why it gives different result than what we do here: taskkill /pid <id> /T /F

Look like 1.11.0-SNAPSHOT is not a fat jar. It missed the dependency library gson (see pix). Can you please rebuild it?

[ephung01]

That is the reason we are checking if Condition for browser==null and then killing the browser - tested parallel execution and it works fine.

example there are 5 tests are running parallel, and one of the test is completed then execute the taskkill command to kill chrome. It would undesirably kill the chrome browser of the one the four left current running which will yield fault result. Kill by PID is the correct way to go.

Also the issue I have is that the browser is not null, but when try to close with browser.close() it hang.

[mrsenzy]

That is the reason we are checking if Condition for browser==null and then killing the browser - tested parallel execution and it works fine.

example there are 5 tests are running parallel, and one of the test is completed then execute the taskkill command to kill chrome. It would undesirably kill the chrome browser of the one the four left current running which will yield fault result. Kill by PID is the correct way to go.

Also the issue I have is that the browser is not null, but when try to close with browser.close() it hang.

Thats correct ... i see sometimes this solution work and most times its not working.

[yury-s]

Look like 1.11.0-SNAPSHOT is not a fat jar. It missed the dependency library gson (see pix). Can you please rebuild it?

It has never been a fat jar. Dependencies are pulled by maven, in particular gson is specified here. Looks like your IDE didn't update the project properly after the version was changed.

[ephung01]

Look like 1.11.0-SNAPSHOT is not a fat jar. It missed the dependency library gson (see pix). Can you please rebuild it?

It has never been a fat jar. Dependencies are pulled by maven, in particular gson is specified here. Looks like your IDE didn't update the project properly after the version was changed.

It's my bad. I replaced the repository with the snapshot repo (https://oss.sonatype.org/content/repositories/snapshots) and accidentally override mavenCentral. That's why even I did add gson dependency but it couldn't find it (I use gradle, but there shouldn't be any different). I am testing it.

[ephung01]

Still 30 seconds timeout and force kill. Is there any specific log you've added that you would like to look at?

[yury-s]

Still 30 seconds timeout and force kill. Is there any specific log you've added that you would like to look at?

Yeah, the lines I was curious about are <will force kill> and the output of taskkill that follows after it, we were not printing that before. From the log it seems that the process is successfully killed and there should be no hanging browser processes and Browser.close() should return after the browser process was killed. Does it match what you are seeing in debugger and in the task manager?

The question why the browser doesn't close gracefully when we send it Browser.close command still stands but that's a separate issue from hanging browser process.

[yury-s]

Is there any object you want me to inspect in debug mode?

Can you explain where we as I'm a bit lost. My understanding is that

1. The browser now does exit after 30 seconds and the client code returns from the call to Browser.close(). Is that correct? If not, does the browser process disappears (the error log suggests that it does)? Does control flow returns from Browser.close() ?
2. We are now investigating why the browser has to be killed after 30s rather than exits gracefully. This is the only remaining problem, is that correct?

Base on what I see in debug, the transport incoming Message Queue is share ford all page and frames. How is Playwright determine if it's the page or the frame that will dequeue message from the incoming Message Queue?

There is no such logic. Whatever function ends up on top of the call stack that expects a response from the server will process all messages from the incoming queue until it's condition is met. You can look at the callers of processOneMessage to get an idea. If there are other methods on the stack that wait for a response from the server they will be handled when the stack unwinds.

Because when I am using Frame object, at this time the incoming queue already have 5 messages pending in the queue (trigger by javascript long polling from page). when the frame context try to execute querySelector, it sends the message and try to process message from the incoming queue. The pending messages (5 pending messages) get pull off the queue and process and somehow stuck in page context instead of frame context - therefore the frame context somehow never get the response of the querySelector message from incoming queue

This should work correctly. In which method on the page object does it get stuck in? Could you share relevant code, it's hard to understand what it does and where it fails?

[ephung01]

Sorry I posted on the wrong issue (I deleted and repost this on [Question] Search element inside frame #397)

[yury-s]

@ephung01 in #426 I made some changes that should terminate connection if the pipe to child process becomes unreadable. I hope this should help with this issue. Can you give it a try (the fix is already in the latest 1.11.0-SNAPSHOT) ?

[ephung01]

1.11.0-SNAPSHOT

It's still stuck for 30 seconds and get force kill. I see alot more log print out; and certificate display with non-displayable characters, but when I post it is just blank space characters (see pix)

Here is the Log file

cert with non display character

[yury-s]

Hmm, this is something new. Do you think you see more logs because of the aforementioned change or just because the browser has been updated since last time?

[yury-s]

Here is the Log file

This URL gives me error 404.

[ephung01]

Here is the Log file

This URL gives me error 404.

Sorry access issue. Fixed.

[ephung01]

Hmm, this is something new. Do you think you see more logs because of the aforementioned change or just because the browser has been updated since last time?

There is no browser upgrade version on the box. More likely it's the changes in Playwright.

[yury-s]

Sorry access issue. Fixed.

The USB error persists across all logs, so it seems that this is a problem with the usb discovery service in Chrome working hard and getting into the way of the normal shutdown flow. We've seen similar issue in a network that had a lot of chrome cast devices, Chrome was busy discovering all of them.

Since the version you are running is less than 89 (the flag was replaced with --enable-device-discovery-notifications after starting 89), can you try launching with --disable-device-discovery-notifications flag and see if it makes any difference?

browserType.launch(new BrowserType.LaunchOptions().setArgs(Arrays.asList("--disable-device-discovery-notifications")));

[ephung01]

browserType.launch(new BrowserType.LaunchOptions().setArgs(Arrays.asList("--disable-device-discovery-notifications")));

I add option "--disable-device-discovery-notifications" still has the same result. 30 seconds and force kill. All UBS ports are blocked as the company policy - cannot copy information to external storage. This could be the problem if chrome tries to access the UBS devices.

[yury-s]

Yeah, my hunch is that something gets busted when the usb ports are blocked. It'd be nice to just disable those discovery services altogether in chrome but I don't see an easy way to do so, we may need to add a flag to chrome for that.

[mxschmitt]

Closing as part of the triage process. Please create a new issue with a detailed reproducible if you still face issues with Playwright for Java.