I have a set of Selenium tests running in AWS Synthetic canaries. I recently upgraded the runtime the canaries use from syn-python-selenium-2.1
to syn-python-selenium-4.0
and the tests have started hitting sporadic, but frequent failures where the connectivity between Selenium and Chromedriver appears to drop.
I have enabled various bits of logging and would like help trying to interpret what the logs are showing. I have copied some more detailed snippets from the logs at the bottom. The selenium logs don’t appear to reveal anything interesting to me, however urllib3 shows the following happening:
2024-08-08 19:16:13,590 DEBUG: Incremented Retry for (url='/session/d2fce95c49c29f09a04300b98b19fa52/element/f.8B288A6684E4F6D6F3484B1DEF095396.d.BCFB2DDB752682B894CDCEAE0060D046.e.722/enabled'): Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-08-08 19:16:13,591 WARNING: Retrying (Retry(total=0, connect=None, read=None, redirect=None, status=None)) after connection broken by 'ReadTimeoutError("HTTPConnectionPool(host='localhost', port=60503): Read timed out. (read timeout=61)")': /session/d2fce95c49c29f09a04300b98b19fa52/element/f.8B288A6684E4F6D6F3484B1DEF095396.d.BCFB2DDB752682B894CDCEAE0060D046.e.722/enabled
Once this has occurred, no further Selenium commands work – they all timeout or error in some way.
From the Chrome and Chromedriver logs, neither of these seem to crash or error at that point in time. Am I correct in saying this means the connectivity between selenium/urllib3 and Chromedriver running on localhost port 60503 breaks down at this point?
My instinct is that the new chrome-headless-shell
binary is somehow involved as that was the only obvious significant change AWS made in syn-python-selenium-4.0
vs 2.1
, but I’m unclear how that could be.
Does anyone have any advice about how to proceed or what more could be investigated? Thanks for any help!
Selenium logs
2024-08-08 19:15:11,863 DEBUG: POST http://localhost:60503/session/d2fce95c49c29f09a04300b98b19fa52/element {'using': 'css selector', 'value': '[id="id_deliver_report_btn"]'}
2024-08-08 19:15:11,885 DEBUG: Remote response: status=200 | data={"value":{"element-6066-11e4-a52e-4f735466cecf":"f.8B288A6684E4F6D6F3484B1DEF095396.d.BCFB2DDB752682B894CDCEAE0060D046.e.722"}} | headers=HTTPHeaderDict({'Content-Length': '127', 'Content-Type': 'application/json; charset=utf-8', 'cache-control': 'no-cache'})
2024-08-08 19:15:11,885 DEBUG: Finished Request
2024-08-08 19:15:11,885 DEBUG: POST http://localhost:60503/session/d2fce95c49c29f09a04300b98b19fa52/execute/sync {'script': '/* isDisplayed */return (function(){return (function(){var g=this||self;nfunction aa(a){var b=typeof...', 'args': [{'element-6066-11e4-a52e-4f735466cecf': 'f.8B288A6684E4F6D6F3484B1DEF095396.d.BCFB2DDB752682B894CDCEAE0060D046.e.722'}]}
2024-08-08 19:15:11,907 DEBUG: Remote response: status=200 | data={"value":true} | headers=HTTPHeaderDict({'Content-Length': '14', 'Content-Type': 'application/json; charset=utf-8', 'cache-control': 'no-cache'})
2024-08-08 19:15:11,907 DEBUG: Finished Request
2024-08-08 19:15:11,908 DEBUG: GET http://localhost:60503/session/d2fce95c49c29f09a04300b98b19fa52/element/f.8B288A6684E4F6D6F3484B1DEF095396.d.BCFB2DDB752682B894CDCEAE0060D046.e.722/enabled {}
2024-08-08 19:15:11,926 DEBUG: Remote response: status=200 | data={"value":true} | headers=HTTPHeaderDict({'Content-Length': '14', 'Content-Type': 'application/json; charset=utf-8', 'cache-control': 'no-cache'})
2024-08-08 19:15:11,926 DEBUG: Finished Request
2024-08-08 19:15:11,926 DEBUG: GET http://localhost:60503/session/d2fce95c49c29f09a04300b98b19fa52/element/f.8B288A6684E4F6D6F3484B1DEF095396.d.BCFB2DDB752682B894CDCEAE0060D046.e.722/enabled {}
2024-08-08 19:15:11,932 DEBUG: Remote response: status=200 | data={"value":true} | headers=HTTPHeaderDict({'Content-Length': '14', 'Content-Type': 'application/json; charset=utf-8', 'cache-control': 'no-cache'})
2024-08-08 19:15:11,932 DEBUG: Finished Request
2024-08-08 19:15:11,932 DEBUG: POST http://localhost:60503/session/d2fce95c49c29f09a04300b98b19fa52/element/f.8B288A6684E4F6D6F3484B1DEF095396.d.BCFB2DDB752682B894CDCEAE0060D046.e.722/click {}
2024-08-08 19:15:12,005 DEBUG: Remote response: status=200 | data={"value":null} | headers=HTTPHeaderDict({'Content-Length': '14', 'Content-Type': 'application/json; charset=utf-8', 'cache-control': 'no-cache'})
2024-08-08 19:15:12,006 DEBUG: Finished Request
2024-08-08 19:15:12,006 DEBUG: GET http://localhost:60503/session/d2fce95c49c29f09a04300b98b19fa52/element/f.8B288A6684E4F6D6F3484B1DEF095396.d.BCFB2DDB752682B894CDCEAE0060D046.e.722/enabled {}
2024-08-08 19:15:12,027 DEBUG: Remote response: status=200 | data={"value":false} | headers=HTTPHeaderDict({'Content-Length': '15', 'Content-Type': 'application/json; charset=utf-8', 'cache-control': 'no-cache'})
2024-08-08 19:15:12,027 DEBUG: Finished Request
2024-08-08 19:15:12,528 DEBUG: GET http://localhost:60503/session/d2fce95c49c29f09a04300b98b19fa52/element/f.8B288A6684E4F6D6F3484B1DEF095396.d.BCFB2DDB752682B894CDCEAE0060D046.e.722/enabled {}
2024-08-08 19:17:14,654 DEBUG: POST http://localhost:60503/session/d2fce95c49c29f09a04300b98b19fa52/execute/sync {'script': 'return document.documentElement.outerHTML', 'args': []}
urllib3 logs
2024-08-08 19:15:11,862 DEBUG: http://localhost:60503 "POST /session/d2fce95c49c29f09a04300b98b19fa52/execute/sync HTTP/1.1" 200 31
2024-08-08 19:15:11,884 DEBUG: http://localhost:60503 "POST /session/d2fce95c49c29f09a04300b98b19fa52/element HTTP/1.1" 200 127
2024-08-08 19:15:11,907 DEBUG: http://localhost:60503 "POST /session/d2fce95c49c29f09a04300b98b19fa52/execute/sync HTTP/1.1" 200 14
2024-08-08 19:15:11,925 DEBUG: http://localhost:60503 "GET /session/d2fce95c49c29f09a04300b98b19fa52/element/f.8B288A6684E4F6D6F3484B1DEF095396.d.BCFB2DDB752682B894CDCEAE0060D046.e.722/enabled HTTP/1.1" 200 14
2024-08-08 19:15:11,932 DEBUG: http://localhost:60503 "GET /session/d2fce95c49c29f09a04300b98b19fa52/element/f.8B288A6684E4F6D6F3484B1DEF095396.d.BCFB2DDB752682B894CDCEAE0060D046.e.722/enabled HTTP/1.1" 200 14
2024-08-08 19:15:12,005 DEBUG: http://localhost:60503 "POST /session/d2fce95c49c29f09a04300b98b19fa52/element/f.8B288A6684E4F6D6F3484B1DEF095396.d.BCFB2DDB752682B894CDCEAE0060D046.e.722/click HTTP/1.1" 200 14
2024-08-08 19:15:12,026 DEBUG: http://localhost:60503 "GET /session/d2fce95c49c29f09a04300b98b19fa52/element/f.8B288A6684E4F6D6F3484B1DEF095396.d.BCFB2DDB752682B894CDCEAE0060D046.e.722/enabled HTTP/1.1" 200 15
2024-08-08 19:16:13,590 DEBUG: Incremented Retry for (url='/session/d2fce95c49c29f09a04300b98b19fa52/element/f.8B288A6684E4F6D6F3484B1DEF095396.d.BCFB2DDB752682B894CDCEAE0060D046.e.722/enabled'): Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-08-08 19:16:13,591 WARNING: Retrying (Retry(total=0, connect=None, read=None, redirect=None, status=None)) after connection broken by 'ReadTimeoutError("HTTPConnectionPool(host='localhost', port=60503): Read timed out. (read timeout=61)")': /session/d2fce95c49c29f09a04300b98b19fa52/element/f.8B288A6684E4F6D6F3484B1DEF095396.d.BCFB2DDB752682B894CDCEAE0060D046.e.722/enabled
2024-08-08 19:16:13,591 DEBUG: Starting new HTTP connection (2): localhost:60503
2024-08-08 19:17:14,655 DEBUG: Starting new HTTP connection (3): localhost:60503
2024-08-08 19:18:15,718 DEBUG: Starting new HTTP connection (4): localhost:60503
2024-08-08 19:19:16,781 DEBUG: Starting new HTTP connection (5): localhost:60503
2024-08-08 19:20:17,844 DEBUG: Incremented Retry for (url='/session/d2fce95c49c29f09a04300b98b19fa52/url'): Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-08-08 19:20:17,844 WARNING: Retrying (Retry(total=0, connect=None, read=None, redirect=None, status=None)) after connection broken by 'ReadTimeoutError("HTTPConnectionPool(host='localhost', port=60503): Read timed out. (read timeout=61)")': /session/d2fce95c49c29f09a04300b98b19fa52/url
Chrome logs
[0808/191512.001895:VERBOSE1:network_delegate.cc(35)] NetworkDelegate::NotifyBeforeURLRequest: https://portal.**********.com/api/v2/study/370973/analysis/343494/analysis_report/156963/deliver/
[0808/191512.195147:VERBOSE1:back_forward_cache_impl.cc(725)] BackForwardCacheImpl::GetFutureBackForwardCacheEligibilityPotential: https://portal.**********.com/view/370973/analysis/343494 : No: BackForwardCache is not supported by delegate
[0808/191512.195179:VERBOSE1:back_forward_cache_impl.cc(725)] BackForwardCacheImpl::GetCompleteBackForwardCacheEligibilityForReporting: https://portal.**********.com/view/370973/analysis/343494 : No: BackForwardCache is not supported by delegate
[0808/191512.195942:VERBOSE1:network_delegate.cc(35)] NetworkDelegate::NotifyBeforeURLRequest: https://portal.**********.com/view/370973/analysis/343494?tab=reports
[0808/191512.382052:VERBOSE1:back_forward_cache_impl.cc(725)] BackForwardCacheImpl::GetFutureBackForwardCacheEligibilityPotential: https://portal.**********.com/view/370973/analysis/343494 : No: BackForwardCache is not supported by delegate
[0808/191512.382090:VERBOSE1:back_forward_cache_impl.cc(725)] BackForwardCacheImpl::GetCompleteBackForwardCacheEligibilityForReporting: https://portal.**********.com/view/370973/analysis/343494 : No: BackForwardCache is not supported by delegate
[0808/191512.386472:VERBOSE1:network_delegate.cc(35)] NetworkDelegate::NotifyBeforeURLRequest: https://col.site24x7rum.eu/rum/trace
[0808/191512.387951:VERBOSE1:network_delegate.cc(35)] NetworkDelegate::NotifyBeforeURLRequest: https://col.site24x7rum.eu/rum/wcv
[0808/191512.403232:VERBOSE1:network_delegate.cc(35)] NetworkDelegate::NotifyBeforeURLRequest: https://portal.**********.com/static/js/localise.js?v=v6.10.3
[0808/191512.421399:VERBOSE1:network_delegate.cc(35)] NetworkDelegate::NotifyBeforeURLRequest: https://portal.**********.com/jsi18n/
[0808/191512.646039:VERBOSE1:network_delegate.cc(35)] NetworkDelegate::NotifyBeforeURLRequest: https://static.site24x7rum.eu/beacon/site24x7rum-min.js?appKey=2afbfd621b81476d3ee6b72522e7325b
[0808/191512.701097:INFO:CONSOLE(24)] "You are using the in-browser Babel transformer. Be sure to precompile your scripts for production - https://babeljs.io/docs/setup/", source: https://unpkg.com/[email protected]/babel.min.js (24)
[0808/191512.721499:VERBOSE1:network_delegate.cc(35)] NetworkDelegate::NotifyBeforeURLRequest: https://portal.**********.com/static/js/react/utils.js?v=v6.10.3
[0808/191512.721739:VERBOSE1:network_delegate.cc(35)] NetworkDelegate::NotifyBeforeURLRequest: https://portal.**********.com/static/js/react/StepBar.js?v=v6.10.3
[0808/191512.721907:VERBOSE1:network_delegate.cc(35)] NetworkDelegate::NotifyBeforeURLRequest: https://portal.**********.com/static/js/react/incidentalFindingsModal.js?v=v6.10.3
[0808/191512.722207:VERBOSE1:network_delegate.cc(35)] NetworkDelegate::NotifyBeforeURLRequest: https://portal.**********.com/static/js/localise.js?v=v6.10.3
[0808/191512.722594:VERBOSE1:network_delegate.cc(35)] NetworkDelegate::NotifyBeforeURLRequest: https://portal.**********.com/static/js/react/view_analysis/dataFilesApp.js?v=v6.10.3
[0808/191512.723427:VERBOSE1:network_delegate.cc(35)] NetworkDelegate::NotifyBeforeURLRequest: https://portal.**********.com/static/js/react/view_analysis/reportsApp.js?v=v6.10.3
[0808/191512.723679:VERBOSE1:network_delegate.cc(35)] NetworkDelegate::NotifyBeforeURLRequest: https://portal.**********.com/static/js/react/view_analysis/rejectionReportsApp.js?v=v6.10.3
[0808/191512.724175:VERBOSE1:network_delegate.cc(35)] NetworkDelegate::NotifyBeforeURLRequest: https://portal.**********.com/static/js/react/linksApp.js?v=v6.10.3
[0808/191512.724344:VERBOSE1:network_delegate.cc(35)] NetworkDelegate::NotifyBeforeURLRequest: https://portal.**********.com/static/js/react/summaryApp.js?v=v6.10.3
[0808/191512.724507:VERBOSE1:network_delegate.cc(35)] NetworkDelegate::NotifyBeforeURLRequest: https://portal.**********.com/static/js/react/comment.js?v=v6.10.3
[0808/191512.724661:VERBOSE1:network_delegate.cc(35)] NetworkDelegate::NotifyBeforeURLRequest: https://portal.**********.com/static/js/react/view_study/filesTabApp.js?v=v6.10.3
[0808/191512.801367:VERBOSE1:network_delegate.cc(35)] NetworkDelegate::NotifyBeforeURLRequest: https://col.site24x7rum.eu/rum/data
Chromedriver logs
[1723144512.802][DEBUG]: DevTools WebSocket Event: Network.responseReceived (session_id=E997E753EA90A061F6B711C5598C65DB) 8B288A6684E4F6D6F3484B1DEF095396 {
"frameId": "8B288A6684E4F6D6F3484B1DEF095396",
"hasExtraInfo": false,
"loaderId": "249E481227E62BBD19999E2D230A440C",
"requestId": "17.1877",
"response": {
"alternateProtocolUsage": "unspecifiedReason",
"charset": "",
"connectionId": 0,
"connectionReused": false,
"encodedDataLength": 0,
"fromDiskCache": true,
"fromPrefetchCache": false,
"fromServiceWorker": false,
"headers": {
"content-encoding": "gzip",
"content-type": "application/javascript",
"date": "Thu, 08 Aug 2024 19:13:06 GMT",
"etag": "W/"66b3dbf2-3b44"",
"last-modified": "Wed, 07 Aug 2024 20:41:22 GMT",
"server": "nginx",
"vary": "Accept-Encoding"
},
"mimeType": "application/javascript",
"protocol": "h2",
"remoteIPAddress": "23.20.119.29",
"remotePort": 443,
"responseTime": 1.723144386184758e+12,
"securityDetails": {
"certificateId": 0,
"certificateTransparencyCompliance": "unknown",
"cipher": "AES_128_GCM",
"encryptedClientHello": false,
"issuer": "Amazon RSA 2048 M03",
"keyExchange": "ECDHE_RSA",
"keyExchangeGroup": "P-256",
"protocol": "TLS 1.2",
"sanList": [ "*.**********.com" ],
"serverSignatureAlgorithm": 1025,
"signedCertificateTimestampList": [ ],
"subjectName": "*.**********.com",
"validFrom": 1713657600,
"validTo": 1747699199
},
"securityState": "secure",
"status": 200,
"statusText": "",
"timing": {
"connectEnd": -1,
"connectStart": -1,
"dnsEnd": -1,
"dnsStart": -1,
"proxyEnd": -1,
"proxyStart": -1,
"pushEnd": 0,
"pushStart": 0,
"receiveHeadersEnd": 39.451,
"receiveHeadersStart": 1.249,
"requestTime": 8416.062898,
"sendEnd": 0.219,
"sendStart": 0.219,
"sslEnd": -1,
"sslStart": -1,
"workerFetchStart": -1,
"workerReady": -1,
"workerRespondWithSettled": -1,
"workerStart": -1
},
"~~~": "..."
},
"timestamp": 8416.141347,
"type": "XHR"
}
[1723144512.802][DEBUG]: DevTools WebSocket Event: Network.dataReceived (session_id=E997E753EA90A061F6B711C5598C65DB) 8B288A6684E4F6D6F3484B1DEF095396 {
"dataLength": 15172,
"encodedDataLength": 0,
"requestId": "17.1877",
"timestamp": 8416.141592
}
[1723144512.802][DEBUG]: DevTools WebSocket Event: Network.loadingFinished (session_id=E997E753EA90A061F6B711C5598C65DB) 8B288A6684E4F6D6F3484B1DEF095396 {
"encodedDataLength": 0,
"requestId": "17.1877",
"timestamp": 8416.124562
}
[1723144512.802][DEBUG]: DevTools WebSocket Event: Network.dataReceived (session_id=E997E753EA90A061F6B711C5598C65DB) 8B288A6684E4F6D6F3484B1DEF095396 {
"dataLength": 14411,
"encodedDataLength": 0,
"requestId": "17.1871",
"timestamp": 8416.142401
}
[1723144512.927][DEBUG]: DevTools WebSocket Event: Network.responseReceivedExtraInfo (session_id=E997E753EA90A061F6B711C5598C65DB) 8B288A6684E4F6D6F3484B1DEF095396 {
"blockedCookies": [ ],
"cookiePartitionKey": "https://**********.com",
"cookiePartitionKeyOpaque": false,
"exemptedCookies": [ ],
"headers": {
"access-control-allow-headers": "request-id, request-context, Origin, Accept-Language",
"access-control-allow-methods": "POST,OPTIONS",
"access-control-allow-origin": "*",
"content-length": "0",
"content-type": "application/json;charset=ISO-8859-1",
"date": "Thu, 08 Aug 2024 19:15:12 GMT",
"server": "ZGS",
"vary": "Origin",
"x-content-type-options": "nosniff",
"x-frame-options": "SAMEORIGIN"
},
"requestId": "17.1882",
"resourceIPAddressSpace": "Public",
"statusCode": 200
}
Versions Used
- Selenium v4.21.0
- Chromedriver 126.0.6478.126
- Chromium 126.0.6478.126 (with headless-chrome-shell)