search

SeleniumHQ / selenium

A browser automation framework and ecosystem.
https://selenium.dev
Apache License 2.0
29.75k stars 8.02k forks source link

Unterminated String Error: driver.manage().logs().get(LogType.PERFORMANCE) #9442

Closed githubuser100007 closed 2 years ago

githubuser100007 commented 3 years ago

🐛 Bug Report

Getting a JsonException: Unterminated string when attempting to retrieve the performance logs via 

driver.manage().logs().get(LogType.PERFORMANCE);

To Reproduce

  1. Retrieve URL: https://squareup.com/us/en/townsquare/why-plastic-straws-are-being-banned
  2. Call driver.manage().logs().get(LogType.PERFORMANCE);

Expected behavior

Should not present error

Test script or set of commands reproducing this issue

        ChromiumDriver driver = null;

        ChromeOptions options = new ChromeOptions();
        options.setBinary("/usr/bin/chrome"); 

        //remove unexepectedalertexceptions
        options.addArguments("--silent", "--headless", "--blink-settings=imagesEnabled=false", "--disable-blink-features", "--disable-blink-features=AutomationControlled", "--disable-gpu", "--no-sandbox", "--window-size=1920,1200", "--ignore-certificate-errors", "--disable-application-cache");  
        options.setCapability(CapabilityType.UNEXPECTED_ALERT_BEHAVIOUR, UnexpectedAlertBehaviour.DISMISS);

        LoggingPreferences logPrefs = new LoggingPreferences();
        logPrefs.enable(LogType.PERFORMANCE, Level.ALL);
        options.setCapability(CapabilityType.LOGGING_PREFS, logPrefs);
        options.setCapability( "goog:loggingPrefs", logPrefs );
        options.setPageLoadStrategy(PageLoadStrategy.EAGER);

        DriverService.Builder serviceBuilder = new ChromeDriverService.Builder().withSilent(true);
        ChromeDriverService chromeDriverService = (ChromeDriverService)serviceBuilder.build(); 
        driver = new ChromeDriver(chromeDriverService, options);

        driver.manage().timeouts().pageLoadTimeout(Duration.ofMillis(JAVASCRIPT_PARSER_TIMEOUT_IN_MILLIS));
        driver.manage().timeouts().setScriptTimeout(Duration.ofMillis(JAVASCRIPT_SCRIPT_TIMEOUT_IN_MILLIS));

        URL uRL = new URL("https://squareup.com/us/en/townsquare/why-plastic-straws-are-being-banned");
        try {

            driver.get(uRL.toExternalForm());
            content = driver.getPageSource();
            LogEntries logs = driver.manage().logs().get(LogType.PERFORMANCE);

        } catch (Exception e) {
            log.error("[" + uRL.toExternalForm() + "] log retrieval error", e.getMessage());
        }

Error Produced

2021-05-05 00:45:16,298 ERROR [https://squareup.com/us/en/townsquare/why-plastic-straws-are-being-banned] timed out.: org.openqa.selenium.json.JsonException: Unterminated string: {"message":{"method":"Network.requestWillBeSent","params":{"documentURL":"https://squareup.com/us/en/townsquare/why-plastic-straws-are-being-banned","frameId":"EB93FE7EE56B44A5FC9DEECD1D9A6717","hasUserGesture":false,"initiator":{"stack":{"callFrames":[{"columnNumber":143415,"functionName":"Xi","lineNumber":2,"scriptId":"19","url":"https://edge.fullstory.com/s/fs.js"},{"columnNumber":141656,"functionName":"e.post","lineNumber":2,"scriptId":"19","url":"https://edge.fullstory.com/s/fs.js"},{"columnNumber":141133,"functionName":"e.bundle","lineNumber":2,"scriptId":"19","url":"https://edge.fullstory.com/s/fs.js"},{"columnNumber":167633,"functionName":"e.sendBundle","lineNumber":2,"scriptId":"19","url":"https://edge.fullstory.com/s/fs.js"},{"columnNumber":166823,"functionName":"e._sendPendingBundle","lineNumber":2,"scriptId":"19","url":"https://edge.fullstory.com/s/fs.js"},{"columnNumber":166586,"functionName":"e.maybeSendNextBundle","lineNumber":2,"scriptId":"19","url":"https://edge.fullstory.com/s/fs.js"},{"columnNumber":166380,"functionName":"e.enqueueNextBundle","lineNumber":2,"scriptId":"19","url":"https://edge.fullstory.com/s/fs.js"},{"columnNumber":165794,"functionName":"e.enqueueAndSendBundle","lineNumber":2,"scriptId":"19","url":"https://edge.fullstory.com/s/fs.js"},{"columnNumber":163674,"functionName":"e.startPipeline","lineNumber":2,"scriptId":"19","url":"https://edge.fullstory.com/s/fs.js"},{"columnNumber":129679,"functionName":"","lineNumber":2,"scriptId":"19","url":"https://edge.fullstory.com/s/fs.js"},{"columnNumber":3613,"functionName":"","lineNumber":2,"scriptId":"19","url":"https://edge.fullstory.com/s/fs.js"},{"columnNumber":3718,"functionName":"","lineNumber":2,"scriptId":"19","url":"https://edge.fullstory.com/s/fs.js"},{"columnNumber":2443,"functionName":"s","lineNumber":2,"scriptId":"19","url":"https://edge.fullstory.com/s/fs.js"}]},"type":"script"},"loaderId":"978E2C78A12ED9FBF48B2C4042A3E3EC","request":{"hasPostData":true,"headers":{"Content-Type":"text/plain","Referer":"https://squareup.com/","User-Agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/88.0.4324.190 Safari/537.36"},"initialPriority":"High","method":"POST","mixedContentType":"none","postData":"{\"Seq\":1,\"When\":49,\"Evts\":[{\"Kind\":25,\"Args\":[\"https://squareup.com/us/en/townsquare/why-plastic-straws-are-being-banned\",\"\u003C!DOCTYPE html>\",\"https://squareup.com/us/en/townsquare/why-plastic-straws-are-being-banned\",\"\"],\"When\":49},{\"Kind\":8198,\"Args\":[false,1],\"When\":49},{\"Kind\":81,\"Args\":[\"https://squareup.com/us/en/townsquare/why-plastic-straws-are-being-banned\",\"navigate\"],\"When\":49},{\"Kind\":20,\"Args\":[],\"When\":49},{\"Kind\":57,\"Args\":[0,1620189903525,0,0,0,0,1620189903531,1620189903533,1620189903533,1620189903533,1620189903688,1620189903598,1620189903689,1620189904935,1620189904945,1620189904964,1620189908121,1620189908123,1620189908126,1620189910774,1620189910776,1620189910926],\"When\":334},{\"Kind\":21,\"Args\":[],\"When\":383},{\"Kind\":58,\"Args\":[0,true,1,true,2,true,5,true,7,true],\"When\":519},{\"Kind\":57,\"Args\":[6,2190000000,15200000,12700000],\"When\":519},{\"Kind\":57,\"Args\":[7,1620189903526],\"When\":519},{\"Kind\":58,\"Args\":[3,true],\"When\":520},{\"Kind\":52,\"Args\":[],\"When\":540},{\"Kind\":66,\"Args\":[\"any-pointer\",\"coarse\"],\"When\":540},{\"Kind\":66,\"Args\":[\"any-hover\",\"none\"],\"When\":540},{\"Kind\":66,\"Args\":[\"pointer\",\"none\"],\"When\":540},{\"Kind\":66,\"Args\":[\"prefers-color-scheme\",\"light\"],\"When\":540},{\"Kind\":2,\"Args\":[-1,-1,[\"\u003C#document\",\"[\",\"\u003C!DOCTYPE\",\":name\",\"html\",\":publicId\",\"\",\":systemId\",6,\"\u003CHTML\",\":_fs_masked\",\"true\",\":class\",\"country-US lang-en locale-en-US site-squareup lazyload-images show-time\",\":data-entry-id\",\"7BaFsE02iMnBsWzmkQSNNn\",\":lang\",\"en-US\",1,\"\u003CHEAD\",[10,2],1,\"\u003CMETA\",[10,2],\":http-equiv\",\"Content-Type\",\":content\",\"text/html; charset=utf-8\",\"\u003C#text\",\"\\n\",[23,2],11,3,\"viewport\",28,\"width=device-width, initial-scale=1, user-scalable=no, shrink-to-fit=no, viewport-fit=cover\",[30,2],[32,3],3,\"format-detection\",28,\"telephone=no\",[30,2],\"\u003CLINK\",\":rel\",\"icon\",\":href\",\"https://xms-production-f.squarecdn.com/xms/assets/public-web-styles/favicon-770e0889aefd823056c7cdbb066a445be0f0754c1b4d4cba877e120fdbcb63e6.ico\",[39,3],[10,2],3,\"sq:environment\",28,\"{\\\"env\\\":\\\"production\\\",\\\"country_code\\\":\\\"US\\\",\\\"lang_code\\\":\\\"en\\\",\\\"locale\\\":\\\"en-US\\\",\\\"country_default_language\\\":\\\"en\\\",\\\"default_country\\\":\\\"US\\\",\\\"default_language\\\":\\\"en\\\",\\\"supported_countries\\\":[\\\"AU\\\",\\\"CA\\\",\\\"GB\\\",\\\"IE\\\",\\\"JP\\\",\\\"US\\\"],\\\"detected_country_code\\\":\\\"us\\\",\\\"available_languages\\\":[\\\"en\\\",\\\"en-AU\\\",\\\"en-CA\\\",\\\"en-GB\\\",\\\"en-US\\\",\\\"fr\\\",\\\"fr-CA\\\",\\\"es\\\",\\\"es-US\\\",\\\"ja\\\",\\\"ja-JP\\\"]}\",[55,4],[34,2],\"sq:tracking\",28,\"{\\\"eventstream\\\":\\\"xms\\\",\\\"google_universal\\\":[\\\"UA-9517040-46\\\"],\\\"autotrack\\\":{\\\"page_view\\\":true,\\\"link_click\\\":true,\\\"scroll_depth\\\":true},\\\"cdp\\\":\\\"41ec1b68-21b1-4687-853a-f968e54134db\\\",\\\"pageview_rawdata\\\":{\\\"entry_id\\\":\\\"7BaFsE02iMnBsWzmkQSNNn\\\"},\\\"full_story\\\":\\\"12758A\\\"}\",[64,5],3,\"sq:gtm\",28,\"{\\\"enabled\\\":true,\\\"domain\\\":\\\"tealium-f.squarecdn.com\\\",\\\"delay\\\":1000}\",[30,2],\"\u003CTITLE\",[20,3],30,\". Last 128 characters read: main\\\\\\\":\\\\\\\"tealium-f.squarecdn.com\\\\\\\",\\\\\\\"delay\\\\\\\":1000}\\\",[30,2],\\\"\\u003CTITLE\\\",[20,3],30,\\\"�
Build info: version: '4.0.0-beta-2', revision: 'Unknown'
System info: host: 'ip-172-30-0-243.ec2.internal', ip: '172.30.0.243', os.name: 'Linux', os.arch: 'amd64', os.version: '4.14.225-168.357.amzn2.x86_64', java.version: '1.8.0_231'
Driver info: org.openqa.selenium.chrome.ChromeDriver
Command: [95a2d3788abfb80dee40c13431aadd99, getLog {type=performance}]
Capabilities {acceptInsecureCerts: false, browserName: chrome, browserVersion: 89.0.4389.90, chrome: {chromedriverVersion: 88.0.4324.96 (68dba2d8a0b14..., userDataDir: /tmp/.com.google.Chrome.iWuNGV}, goog:chromeOptions: {debuggerAddress: localhost:39827}, javascriptEnabled: true, networkConnectionEnabled: false, pageLoadStrategy: eager, platform: LINUX, platformName: LINUX, proxy: Proxy(), setWindowRect: true, strictFileInteractability: false, timeouts: {implicit: 0, pageLoad: 300000, script: 30000}, unhandledPromptBehavior: dismiss, webauthn:extension:largeBlob: true, webauthn:virtualAuthenticators: true}
Session ID: 95a2d3788abfb80dee40c13431aadd99

Environment

OS: AWS Linux 2 Browser: Chrome Browser version: Version 89.0.4389.90 (Official Build) (64-bit) Browser Driver version: ChromeDriver 89.0.4389.23 Language Bindings version: Java 8 Selenium Grid version (if applicable): Beta 2

pujagani commented 3 years ago

Thank you for providing the example and the details. I have used the same example and unable to see the issue mentioned. I am seeing well-formatted logs.

Though I had few questions about this.

Based on what I observe is the issue lies in the postData received from the website.

What I have observed, is that the postData field has a value of a string followed by postDataEntries. Example: 

"postData" : "{\"batch\":[{\"context\":{\"page\":{\"path\":\"/us/en/townsquare/why-plastic-straws-are-being-banned\",\"referrer\":\"\",\"search\":\"\",\"title\":\"Why Plastic Straws Are Being Banned\",\"url\":\"https://squareup.com/us/en/townsquare/why-plastic-straws-are-being-banned\"},\"subject\":{\"anonymousToken\":\"9fd8800c-21dc-49a3-8ac2-a5b1dfc563e8\"},\"browser\":{\"name\":\"Chrome Headless\",\"version\":\"90.0.4430.212\",\"height\":1200,\"width\":1920},\"campaign\":{},\"locale\":{\"countryCode\":\"US\",\"language\":\"en-US\"},\"os\":{\"name\":\"Mac OS\",\"version\":\"10.13.6\"},\"referrer\":{\"referrer\":\"\"},\"userAgent\":\"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/90.0.4430.212 Safari/537.36\",\"library\":{\"name\":\"data-api.js\",\"version\":\"5.2.0\"}},\"integrations\":{},\"properties\":{\"window_width\":1920,\"window_height\":1200,\"device_pixel_ratio\":1,\"network_time\":3261,\"rendering_time\":1261,\"time_to_dom_ready\":4522,\"entry_id\":\"7BaFsE02iMnBsWzmkQSNNn\",\"path\":\"/us/en/townsquare/why-plastic-straws-are-being-banned\",\"referrer\":\"\",\"search\":\"\",\"title\":\"Why Plastic Straws Are Being Banned\",\"url\":\"https://squareup.com/us/en/townsquare/why-plastic-straws-are-being-banned\"},\"category\":null,\"name\":null,\"anonymousId\":\"9fd8800c-21dc-49a3-8ac2-a5b1dfc563e8\",\"entityType\":\"anonymous_visitor\",\"entityId\":null,\"timestamp\":\"2021-05-13T11:56:54.556Z\",\"type\":\"page\",\"apiMethod\":\"page\",\"apiKey\":\"41ec1b68-21b1-4687-853a-f968e54134db\",\"sentAt\":\"2021-05-13T11:56:54.557Z\"}]}"

However, that is not followed in the log the error occurred in.

OS: MacOS Browser: Chrome Browser version: Version 90.0.4430.24 (Official Build) (64-bit) Browser Driver version: ChromeDriver 90.0.4430.24 Language Bindings Version: Beta 2

githubuser100007 commented 3 years ago

Issue seems intermittent. It appears during large scale parallel testing.

One error that just happened today was when crawling: https://bookiesbonuses.com/visit/888sport-finland

Should I just treat this as a timeout exception?

pujagani commented 3 years ago

Thank you for your response. Did you face the same error while crawling the website mentioned? or was it a timeout exception? Please provide a reproducible code/script for recreating the error in the parallel setting.

pujagani commented 3 years ago

Did you get a TimeoutException while starting the driver when running tests in parallel? I tried to recreate the issue by running a TestNG suite in parallel. I saw a bunch of TimeoutExceptions with the stack trace:

org.openqa.selenium.SessionNotCreatedException: Could not start a new session. Possible causes are invalid address of the remote server or browser start-up failure.

    at org.openqa.selenium.remote.RemoteWebDriver.execute(RemoteWebDriver.java:638)
    at org.openqa.selenium.remote.RemoteWebDriver.startSession(RemoteWebDriver.java:252)
    at org.openqa.selenium.remote.RemoteWebDriver.<init>(RemoteWebDriver.java:174)
    at org.openqa.selenium.chromium.ChromiumDriver.<init>(ChromiumDriver.java:82)
    at org.openqa.selenium.chrome.ChromeDriver.<init>(ChromeDriver.java:99)
    at org.openqa.selenium.chrome.ChromeDriver.<init>(ChromeDriver.java:86)
    at com.company.TestClassParallelLogs.waitTest2(TestClassParallelLogs.java:126)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:133)
    at org.testng.internal.TestInvoker.invokeMethod(TestInvoker.java:598)
    at org.testng.internal.TestInvoker.invokeTestMethod(TestInvoker.java:173)
    at org.testng.internal.MethodRunner.runInSequence(MethodRunner.java:46)
    at org.testng.internal.TestInvoker$MethodInvocationAgent.invoke(TestInvoker.java:824)
    at org.testng.internal.TestInvoker.invokeTestMethods(TestInvoker.java:146)
    at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:146)
    at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:128)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:834)
Driver info: driver.version: ChromeDriver
    at org.openqa.selenium.remote.service.DriverService.start(DriverService.java:224)
    at org.openqa.selenium.remote.service.DriverCommandExecutor.execute(DriverCommandExecutor.java:86)
    at org.openqa.selenium.remote.RemoteWebDriver.execute(RemoteWebDriver.java:620)
    ... 21 more
Caused by: java.util.concurrent.TimeoutException
    at java.base/java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1886)
    at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2021)
    at org.openqa.selenium.remote.service.DriverService.start(DriverService.java:214)

If yes, then https://github.com/SeleniumHQ/selenium/commit/49f706f436b7c97d5ac39596d141d345aef58b79 fixes it. However, I still was unable to see the Unterminated String Error: driver.manage().logs().get(LogType.PERFORMANCE).

AutomatedTester commented 2 years ago

Closing as we have not had a reply from the user. If this is still an issue please raise and issue again with all the details we would need to recreate.

github-actions[bot] commented 2 years ago

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.