search

SeleniumHQ / docker-selenium

Provides a simple way to run Selenium Grid with Chrome, Firefox, and Edge using Docker, making it easier to perform browser automation
http://www.selenium.dev/docker-selenium/
Other
7.95k stars 2.51k forks source link

[🐛 Bug]: Race condition when launching helm chart on k3s #1807

Closed flokain closed 1 year ago

flokain commented 1 year ago

What happened?

when I use the helm chart to bootstrap the grid on a k3s cluster (v1.24.8+k3s1) i noticed that it takes exactl 2 minutes for the nodes to register, IF they try to register with the hub before the hub is accepting requests. Otherwise the node register immediately.

Also deleting pods from the deployment will recreate new ones, which also immediately register.

I have tested the same setup on a aws eks cluster (1.24) and there the nodes register immediately in any case.

Thanks for your help!

Command used to start Selenium Grid with Docker

helm upgrade -i selenium-grid docker-selenium/selenium-grid --set hub.serviceType=ClusterIP --set hub.imageTag=4.8.1 --set global.seleniumGrid.nodesImageTag=4.8.1 --version 0.15.4 --namespace upgrade-k3s --set firefoxNode.enabled=false --set edgeNode.enabled=false --set chromeNode.replicas=6 --set chromeNode.resources.requests.memory=250Mi --set chromeNode.resources.requests.cpu=250m --wait --timeout=10m --set 'chromeNode.extraEnvironmentVariables[0].name=SE_NODE_SESSION_TIMEOUT' --set-string 'chromeNode.extraEnvironmentVariables[0].value=10' --set 'chromeNode.extraEnvironmentVariables[1].name=SE_NODE_REGISTER_PERIOD' --set-string 'chromeNode.extraEnvironmentVariables[1].value=1' --set 'chromeNode.extraEnvironmentVariables[2].name=SE_OPTS' --set-string 'chromeNode.extraEnvironmentVariables[2].value=--log-level FINE' --set 'hub.extraEnvironmentVariables[0].name=SE_OPTS' --set-string 'hub.extraEnvironmentVariables[0].value=--log-level FINE'
R

Relevant log output

#chrome node logs:

2023-03-13 21:24:28,951 INFO Included extra file "/etc/supervisor/conf.d/selenium.conf" during parsing
2023-03-13 21:24:28,956 INFO RPC interface 'supervisor' initialized
2023-03-13 21:24:28,956 CRIT Server 'unix_http_server' running without any HTTP authentication checking
2023-03-13 21:24:28,957 INFO supervisord started with pid 8
2023-03-13 21:24:29,959 INFO spawned: 'xvfb' with pid 10
2023-03-13 21:24:29,961 INFO spawned: 'vnc' with pid 11
2023-03-13 21:24:29,962 INFO spawned: 'novnc' with pid 12
2023-03-13 21:24:29,964 INFO spawned: 'selenium-node' with pid 13
2023-03-13 21:24:30,000 INFO success: selenium-node entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
Appending Selenium options: --log-level FINE
Generating Selenium Config
Configuring server...
Setting up SE_NODE_HOST...
Setting up SE_NODE_PORT...
Setting up SE_NODE_GRID_URL...
Tracing is disabled
Selenium Grid Node configuration: 
[events]
publish = "tcp://selenium-hub:4442"
subscribe = "tcp://selenium-hub:4443"

[node]
session-timeout = "10"
override-max-sessions = false
detect-drivers = false
drain-after-session-count = 0
max-sessions = 1

[[node.driver-configuration]]
display-name = "chrome"
stereotype = '{"browserName": "chrome", "browserVersion": "110.0", "platformName": "Linux"}'
max-sessions = 1

Starting Selenium Grid Node...
2023-03-13 21:24:31,025 INFO success: xvfb entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2023-03-13 21:24:31,025 INFO success: vnc entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2023-03-13 21:24:31,025 INFO success: novnc entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
21:24:31.581 INFO [LoggingOptions.configureLogEncoding] - Using the system default encoding
21:24:31.607 INFO [OpenTelemetryTracer.createTracer] - Using OpenTelemetry for tracing
21:24:31.860 DEBUG [AutoConfiguredOpenTelemetrySdkBuilder.build] - Global OpenTelemetry set to OpenTelemetrySdk{tracerProvider=SdkTracerProvider{clock=SystemClock{}, idGenerator=RandomIdGenerator{}, resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.16.0, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.22.0"}}, spanLimitsSupplier=SpanLimitsValue{maxNumberOfAttributes=128, maxNumberOfEvents=128, maxNumberOfLinks=128, maxNumberOfAttributesPerEvent=128, maxNumberOfAttributesPerLink=128, maxAttributeValueLength=2147483647}, sampler=ParentBased{root:AlwaysOnSampler,remoteParentSampled:AlwaysOnSampler,remoteParentNotSampled:AlwaysOffSampler,localParentSampled:AlwaysOnSampler,localParentNotSampled:AlwaysOffSampler}, spanProcessor=SimpleSpanProcessor{spanExporter=org.openqa.selenium.remote.tracing.opentelemetry.SeleniumSpanExporter$1@2145433b}}, meterProvider=SdkMeterProvider{clock=SystemClock{}, resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.16.0, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.22.0"}}, metricReaders=[], views=[]}, loggerProvider=SdkLoggerProvider{clock=SystemClock{}, resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.16.0, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.22.0"}}, logLimits=LogLimits{maxNumberOfAttributes=128, maxAttributeValueLength=2147483647}, logRecordProcessor=io.opentelemetry.sdk.logs.NoopLogRecordProcessor@482cd91f}, propagators=DefaultContextPropagators{textMapPropagator=MultiTextMapPropagator{textMapPropagators=[W3CTraceContextPropagator, W3CBaggagePropagator]}}} by autoconfiguration
21:24:32.132 INFO [UnboundZmqEventBus.<init>] - Connecting to tcp://selenium-hub:4442 and tcp://selenium-hub:4443
21:24:32.606 INFO [UnboundZmqEventBus.<init>] - Sockets created
21:24:33.615 INFO [UnboundZmqEventBus.<init>] - Event bus ready
21:24:34.111 INFO [NodeServer.createHandlers] - Reporting self as: http://10.42.0.211:5555
21:24:34.235 INFO [NodeOptions.getSessionFactories] - Detected 1 available processors
21:24:34.507 INFO [NodeOptions.report] - Adding chrome for {"browserVersion": "110.0","se:noVncPort": 7900,"browserName": "chrome","platformName": "LINUX","se:vncEnabled": true} 1 times
21:24:34.609 INFO [Node.<init>] - Binding additional locator mechanisms: relative
21:24:34.945 DEBUG [MultithreadEventLoopGroup.<clinit>] - -Dio.netty.eventLoopThreads: 2
21:24:35.025 DEBUG [InternalThreadLocalMap.<clinit>] - -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
21:24:35.025 DEBUG [InternalThreadLocalMap.<clinit>] - -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
21:24:35.061 DEBUG [PlatformDependent0.explicitNoUnsafeCause0] - -Dio.netty.noUnsafe: false
21:24:35.062 DEBUG [PlatformDependent0.javaVersion0] - Java version: 11
21:24:35.106 DEBUG [PlatformDependent0.<clinit>] - sun.misc.Unsafe.theUnsafe: available
21:24:35.107 DEBUG [PlatformDependent0.<clinit>] - sun.misc.Unsafe.copyMemory: available
21:24:35.108 DEBUG [PlatformDependent0.<clinit>] - sun.misc.Unsafe.storeFence: available
21:24:35.109 DEBUG [PlatformDependent0.<clinit>] - java.nio.Buffer.address: available
21:24:35.110 DEBUG [PlatformDependent0.<clinit>] - direct buffer constructor: unavailable: Reflective setAccessible(true) disabled
21:24:35.112 DEBUG [PlatformDependent0.<clinit>] - java.nio.Bits.unaligned: available, true
21:24:35.114 DEBUG [PlatformDependent0.<clinit>] - jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable: class io.netty.util.internal.PlatformDependent0$7 cannot access class jdk.internal.misc.Unsafe (in module java.base) because module java.base does not export jdk.internal.misc to unnamed module @635572a7
21:24:35.115 DEBUG [PlatformDependent0.<clinit>] - java.nio.DirectByteBuffer.<init>(long, int): unavailable
21:24:35.116 DEBUG [PlatformDependent.unsafeUnavailabilityCause0] - sun.misc.Unsafe: available
21:24:35.119 DEBUG [PlatformDependent.estimateMaxDirectMemory] - maxDirectMemory: 259522560 bytes (maybe)
21:24:35.119 DEBUG [PlatformDependent.tmpdir0] - -Dio.netty.tmpdir: /tmp (java.io.tmpdir)
21:24:35.120 DEBUG [PlatformDependent.bitMode0] - -Dio.netty.bitMode: 64 (sun.arch.data.model)
21:24:35.121 DEBUG [PlatformDependent.<clinit>] - -Dio.netty.maxDirectMemory: -1 bytes
21:24:35.121 DEBUG [PlatformDependent.<clinit>] - -Dio.netty.uninitializedArrayAllocationThreshold: -1
21:24:35.123 DEBUG [CleanerJava9.<clinit>] - java.nio.ByteBuffer.cleaner(): available
21:24:35.123 DEBUG [PlatformDependent.<clinit>] - -Dio.netty.noPreferDirect: false
21:24:35.127 DEBUG [NioEventLoop.<clinit>] - -Dio.netty.noKeySetOptimization: false
21:24:35.127 DEBUG [NioEventLoop.<clinit>] - -Dio.netty.selectorAutoRebuildThreshold: 512
21:24:35.145 DEBUG [PlatformDependent$Mpsc.<clinit>] - org.jctools-core.MpscChunkedArrayQueue: available
21:24:35.236 DEBUG [DefaultChannelId.<clinit>] - -Dio.netty.processId: 71 (auto-detected)
21:24:35.242 DEBUG [NetUtil.<clinit>] - -Djava.net.preferIPv4Stack: false
21:24:35.242 DEBUG [NetUtil.<clinit>] - -Djava.net.preferIPv6Addresses: false
21:24:35.245 DEBUG [NetUtilInitializations.determineLoopback] - Loopback interface: lo (lo, 0:0:0:0:0:0:0:1%lo)
21:24:35.247 DEBUG [NetUtil$SoMaxConnAction.run] - /proc/sys/net/core/somaxconn: 4096
21:24:35.248 DEBUG [DefaultChannelId.<clinit>] - -Dio.netty.machineId: 3e:b1:e6:ff:fe:7e:17:b7 (auto-detected)
21:24:35.267 DEBUG [ResourceLeakDetector.<clinit>] - -Dio.netty.leakDetection.level: simple
21:24:35.303 DEBUG [ResourceLeakDetector.<clinit>] - -Dio.netty.leakDetection.targetRecords: 4
21:24:35.346 DEBUG [PooledByteBufAllocator.<clinit>] - -Dio.netty.allocator.numHeapArenas: 2
21:24:35.346 DEBUG [PooledByteBufAllocator.<clinit>] - -Dio.netty.allocator.numDirectArenas: 2
21:24:35.347 DEBUG [PooledByteBufAllocator.<clinit>] - -Dio.netty.allocator.pageSize: 8192
21:24:35.347 DEBUG [PooledByteBufAllocator.<clinit>] - -Dio.netty.allocator.maxOrder: 9
21:24:35.347 DEBUG [PooledByteBufAllocator.<clinit>] - -Dio.netty.allocator.chunkSize: 4194304
21:24:35.347 DEBUG [PooledByteBufAllocator.<clinit>] - -Dio.netty.allocator.smallCacheSize: 256
21:24:35.347 DEBUG [PooledByteBufAllocator.<clinit>] - -Dio.netty.allocator.normalCacheSize: 64
21:24:35.348 DEBUG [PooledByteBufAllocator.<clinit>] - -Dio.netty.allocator.maxCachedBufferCapacity: 32768
21:24:35.348 DEBUG [PooledByteBufAllocator.<clinit>] - -Dio.netty.allocator.cacheTrimInterval: 8192
21:24:35.348 DEBUG [PooledByteBufAllocator.<clinit>] - -Dio.netty.allocator.cacheTrimIntervalMillis: 0
21:24:35.348 DEBUG [PooledByteBufAllocator.<clinit>] - -Dio.netty.allocator.useCacheForAllThreads: false
21:24:35.348 DEBUG [PooledByteBufAllocator.<clinit>] - -Dio.netty.allocator.maxCachedByteBuffersPerChunk: 1023
21:24:35.364 DEBUG [ByteBufUtil.<clinit>] - -Dio.netty.allocator.type: pooled
21:24:35.365 DEBUG [ByteBufUtil.<clinit>] - -Dio.netty.threadLocalDirectBufferSize: 0
21:24:35.365 DEBUG [ByteBufUtil.<clinit>] - -Dio.netty.maxThreadLocalCharBufferSize: 16384
21:24:35.405 DEBUG [LoggingHandler.channelRegistered] - [id: 0x2882ba35] REGISTERED
21:24:35.409 DEBUG [LoggingHandler.bind] - [id: 0x2882ba35] BIND: 0.0.0.0/0.0.0.0:5555
21:24:35.414 DEBUG [LoggingHandler.channelActive] - [id: 0x2882ba35, L:/0:0:0:0:0:0:0:0:5555] ACTIVE
21:24:35.416 INFO [NodeServer$1.start] - Starting registration process for Node http://10.42.0.211:5555
21:24:35.417 INFO [NodeServer.execute] - Started Selenium node 4.8.0 (revision 267030adea): http://10.42.0.211:5555
21:24:35.434 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
21:24:45.440 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
21:24:55.443 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
21:25:05.446 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
21:25:15.450 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
21:25:25.454 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
21:25:35.457 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
21:25:45.461 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
21:25:55.465 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
21:26:05.473 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
21:26:15.477 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
21:26:25.480 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
21:26:35.420 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
21:27:35.266 DEBUG [LoggingHandler.channelRead] - [id: 0x2882ba35, L:/0:0:0:0:0:0:0:0:5555] READ: [id: 0x87807a12, L:/10.42.0.211:5555 - R:/10.42.0.210:33222]
21:27:35.267 DEBUG [LoggingHandler.channelReadComplete] - [id: 0x2882ba35, L:/0:0:0:0:0:0:0:0:5555] READ COMPLETE
21:27:35.298 DEBUG [AbstractByteBuf.<clinit>] - -Dio.netty.buffer.checkAccessible: true
21:27:35.299 DEBUG [AbstractByteBuf.<clinit>] - -Dio.netty.buffer.checkBounds: true
21:27:35.300 DEBUG [ResourceLeakDetectorFactory$DefaultResourceLeakDetectorFactory.newResourceLeakDetector] - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@5c12859a
21:27:35.313 DEBUG [ZlibCodecFactory.<clinit>] - -Dio.netty.noJdkZlibDecoder: false
21:27:35.314 DEBUG [ZlibCodecFactory.<clinit>] - -Dio.netty.noJdkZlibEncoder: false
21:27:35.333 DEBUG [Recycler.<clinit>] - -Dio.netty.recycler.maxCapacityPerThread: 4096
21:27:35.333 DEBUG [Recycler.<clinit>] - -Dio.netty.recycler.ratio: 8
21:27:35.333 DEBUG [Recycler.<clinit>] - -Dio.netty.recycler.chunkSize: 32
21:27:35.334 DEBUG [Recycler.<clinit>] - -Dio.netty.recycler.blocking: false
21:27:35.409 DEBUG [RequestConverter.channelRead0] - Incoming message: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
GET /status HTTP/1.1
Connection: Upgrade, HTTP2-Settings
Content-Length: 0
Host: 10.42.0.211:5555
HTTP2-Settings: AAEAAEAAAAIAAAABAAMAAABkAAQBAAAAAAUAAEAA
Upgrade: h2c
traceparent: 00-2f2c17fe8cfcccd88efe1fda6933efcc-289e9a2747164b71-01
User-Agent: selenium/4.8.1 (java unix)
21:27:35.409 DEBUG [RequestConverter.channelRead0] - Start of http request: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
GET /status HTTP/1.1
Connection: Upgrade, HTTP2-Settings
Content-Length: 0
Host: 10.42.0.211:5555
HTTP2-Settings: AAEAAEAAAAIAAAABAAMAAABkAAQBAAAAAAUAAEAA
Upgrade: h2c
traceparent: 00-2f2c17fe8cfcccd88efe1fda6933efcc-289e9a2747164b71-01
User-Agent: selenium/4.8.1 (java unix)
21:27:35.419 DEBUG [RequestConverter.channelRead0] - Incoming message: EmptyLastHttpContent
21:27:35.419 DEBUG [RequestConverter.channelRead0] - End of http request: EmptyLastHttpContent
21:27:35.516 DEBUG [SpanWrappedHttpHandler.execute] - Wrapping request. Before OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@2ed0fbae, context={}, span id=0000000000000000, trace id=00000000000000000000000000000000} and after OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@2ed0fbae, context={opentelemetry-trace-span-key=SdkSpan{traceId=2f2c17fe8cfcccd88efe1fda6933efcc, spanId=3cf2a360bd2325b5, parentSpanContext=ImmutableSpanContext{traceId=2f2c17fe8cfcccd88efe1fda6933efcc, spanId=289e9a2747164b71, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, name=node.status, kind=INTERNAL, attributes=AttributesMap{data={random.key=717d9d7d-5992-4c11-86ba-3338ee941285}, capacity=128, totalAddedValues=1}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1678742855510000000, endEpochNanos=0}}, span id=3cf2a360bd2325b5, trace id=2f2c17fe8cfcccd88efe1fda6933efcc}
21:27:35.522 DEBUG [HttpTracing.inject] - Injecting (GET) /status into OpenTelemetrySpan{traceId=2f2c17fe8cfcccd88efe1fda6933efcc,spanId=3cf2a360bd2325b5} at org.openqa.selenium.remote.tracing.SpanWrappedHttpHandler:84
21:27:35.539 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=2f2c17fe8cfcccd88efe1fda6933efcc, spanId=3cf2a360bd2325b5, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=2f2c17fe8cfcccd88efe1fda6933efcc, spanId=289e9a2747164b71, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.16.0, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.22.0"}}, instrumentationScopeInfo=InstrumentationScopeInfo{name=default, version=null, schemaUrl=null, attributes={}}, name=node.status, kind=INTERNAL, startEpochNanos=1678742855510000000, endEpochNanos=1678742855535964796, attributes=AttributesMap{data={http.status_code=200, http.method=GET, random.key=717d9d7d-5992-4c11-86ba-3338ee941285, span.kind=server, http.target=/status}, capacity=128, totalAddedValues=5}, totalAttributeCount=5, events=[ImmutableEventData{name=HTTP request execution complete, attributes={http.flavor=1, http.handler_class="org.openqa.selenium.remote.http.Route$TemplatizedRoute", http.host="10.42.0.211:5555", http.method="GET", http.request_content_length="0", http.scheme="HTTP", http.status_code=200, http.target="/status", http.user_agent="selenium/4.8.1 (java unix)"}, epochNanos=1678742855534560369, totalAttributeCount=9}], totalRecordedEvents=1, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=OK, description=Kind: OK Description:}, hasEnded=true}
21:27:35.548 DEBUG [SeleniumSpanExporter$1.lambda$export$3] - {"traceId": "2f2c17fe8cfcccd88efe1fda6933efcc","eventTime": 1678742855534560369,"eventName": "HTTP request execution complete","attributes": {"http.flavor": 1,"http.handler_class": "org.openqa.selenium.remote.http.Route$TemplatizedRoute","http.host": "10.42.0.211:5555","http.method": "GET","http.request_content_length": "0","http.scheme": "HTTP","http.status_code": 200,"http.target": "\u002fstatus","http.user_agent": "selenium\u002f4.8.1 (java unix)"}}
21:27:35.637 INFO [NodeServer.lambda$createHandlers$2] - Node has been added

Operating System

ubuntu k3s v1.24.8+k3s1

Docker Selenium version (tag)

4.8.1

github-actions[bot] commented 1 year ago

@flokain, thank you for creating this issue. We will troubleshoot it as soon as we can.

Info for maintainers

Triage this issue by using labels.

If information is missing, add a helpful comment and then I-issue-template label.

If the issue is a question, add the I-question label.

If the issue is valid but there is no time to troubleshoot it, consider adding the help wanted label.

If the issue requires changes or fixes from an external project (e.g., ChromeDriver, GeckoDriver, MSEdgeDriver, W3C), add the applicable G-* label, and it will provide the correct link and auto-close the issue.

After troubleshooting the issue, please add the R-awaiting answer label.

Thank you!

flokain commented 1 year ago

hub logs

2023-03-13 21:24:28,683 INFO Included extra file "/etc/supervisor/conf.d/selenium-grid-hub.conf" during parsing
2023-03-13 21:24:28,687 INFO RPC interface 'supervisor' initialized
2023-03-13 21:24:28,687 CRIT Server 'unix_http_server' running without any HTTP authentication checking
2023-03-13 21:24:28,687 INFO supervisord started with pid 8
2023-03-13 21:24:29,689 INFO spawned: 'selenium-grid-hub' with pid 10
Appending Selenium options: --log-level FINE
Tracing is disabled
2023-03-13 21:24:29,697 INFO success: selenium-grid-hub entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
21:24:30.906 INFO [LoggingOptions.configureLogEncoding] - Using the system default encoding
21:24:31.014 INFO [OpenTelemetryTracer.createTracer] - Using OpenTelemetry for tracing
21:24:31.473 DEBUG [AutoConfiguredOpenTelemetrySdkBuilder.build] - Global OpenTelemetry set to OpenTelemetrySdk{tracerProvider=SdkTracerProvider{clock=SystemClock{}, idGenerator=RandomIdGenerator{}, resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.16.0, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.22.0"}}, spanLimitsSupplier=SpanLimitsValue{maxNumberOfAttributes=128, maxNumberOfEvents=128, maxNumberOfLinks=128, maxNumberOfAttributesPerEvent=128, maxNumberOfAttributesPerLink=128, maxAttributeValueLength=2147483647}, sampler=ParentBased{root:AlwaysOnSampler,remoteParentSampled:AlwaysOnSampler,remoteParentNotSampled:AlwaysOffSampler,localParentSampled:AlwaysOnSampler,localParentNotSampled:AlwaysOffSampler}, spanProcessor=SimpleSpanProcessor{spanExporter=org.openqa.selenium.remote.tracing.opentelemetry.SeleniumSpanExporter$1@5e25a92e}}, meterProvider=SdkMeterProvider{clock=SystemClock{}, resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.16.0, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.22.0"}}, metricReaders=[], views=[]}, loggerProvider=SdkLoggerProvider{clock=SystemClock{}, resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.16.0, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.22.0"}}, logLimits=LogLimits{maxNumberOfAttributes=128, maxAttributeValueLength=2147483647}, logRecordProcessor=io.opentelemetry.sdk.logs.NoopLogRecordProcessor@31206beb}, propagators=DefaultContextPropagators{textMapPropagator=MultiTextMapPropagator{textMapPropagators=[W3CTraceContextPropagator, W3CBaggagePropagator]}}} by autoconfiguration
21:24:31.507 INFO [BoundZmqEventBus.<init>] - XPUB binding to [binding to tcp://*:4442, advertising as tcp://10.42.0.210:4442], XSUB binding to [binding to tcp://*:4443, advertising as tcp://10.42.0.210:4443]
21:24:31.685 INFO [UnboundZmqEventBus.<init>] - Connecting to tcp://10.42.0.210:4442 and tcp://10.42.0.210:4443
21:24:31.718 INFO [UnboundZmqEventBus.<init>] - Sockets created
21:24:32.731 INFO [UnboundZmqEventBus.<init>] - Event bus ready
21:24:33.418 DEBUG [MultithreadEventLoopGroup.<clinit>] - -Dio.netty.eventLoopThreads: 16
21:24:33.443 DEBUG [InternalThreadLocalMap.<clinit>] - -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
21:24:33.443 DEBUG [InternalThreadLocalMap.<clinit>] - -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
21:24:33.465 DEBUG [PlatformDependent0.explicitNoUnsafeCause0] - -Dio.netty.noUnsafe: false
21:24:33.466 DEBUG [PlatformDependent0.javaVersion0] - Java version: 11
21:24:33.467 DEBUG [PlatformDependent0.<clinit>] - sun.misc.Unsafe.theUnsafe: available
21:24:33.467 DEBUG [PlatformDependent0.<clinit>] - sun.misc.Unsafe.copyMemory: available
21:24:33.468 DEBUG [PlatformDependent0.<clinit>] - sun.misc.Unsafe.storeFence: available
21:24:33.468 DEBUG [PlatformDependent0.<clinit>] - java.nio.Buffer.address: available
21:24:33.468 DEBUG [PlatformDependent0.<clinit>] - direct buffer constructor: unavailable: Reflective setAccessible(true) disabled
21:24:33.469 DEBUG [PlatformDependent0.<clinit>] - java.nio.Bits.unaligned: available, true
21:24:33.470 DEBUG [PlatformDependent0.<clinit>] - jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable: class io.netty.util.internal.PlatformDependent0$7 cannot access class jdk.internal.misc.Unsafe (in module java.base) because module java.base does not export jdk.internal.misc to unnamed module @23202fce
21:24:33.471 DEBUG [PlatformDependent0.<clinit>] - java.nio.DirectByteBuffer.<init>(long, int): unavailable
21:24:33.471 DEBUG [PlatformDependent.unsafeUnavailabilityCause0] - sun.misc.Unsafe: available
21:24:33.472 DEBUG [PlatformDependent.estimateMaxDirectMemory] - maxDirectMemory: 8346664960 bytes (maybe)
21:24:33.472 DEBUG [PlatformDependent.tmpdir0] - -Dio.netty.tmpdir: /tmp (java.io.tmpdir)
21:24:33.472 DEBUG [PlatformDependent.bitMode0] - -Dio.netty.bitMode: 64 (sun.arch.data.model)
21:24:33.473 DEBUG [PlatformDependent.<clinit>] - -Dio.netty.maxDirectMemory: -1 bytes
21:24:33.473 DEBUG [PlatformDependent.<clinit>] - -Dio.netty.uninitializedArrayAllocationThreshold: -1
21:24:33.474 DEBUG [CleanerJava9.<clinit>] - java.nio.ByteBuffer.cleaner(): available
21:24:33.474 DEBUG [PlatformDependent.<clinit>] - -Dio.netty.noPreferDirect: false
21:24:33.475 DEBUG [NioEventLoop.<clinit>] - -Dio.netty.noKeySetOptimization: false
21:24:33.475 DEBUG [NioEventLoop.<clinit>] - -Dio.netty.selectorAutoRebuildThreshold: 512
21:24:33.481 DEBUG [PlatformDependent$Mpsc.<clinit>] - org.jctools-core.MpscChunkedArrayQueue: available
21:24:33.502 DEBUG [DefaultChannelId.<clinit>] - -Dio.netty.processId: 11 (auto-detected)
21:24:33.515 DEBUG [NetUtil.<clinit>] - -Djava.net.preferIPv4Stack: false
21:24:33.516 DEBUG [NetUtil.<clinit>] - -Djava.net.preferIPv6Addresses: false
21:24:33.518 DEBUG [NetUtilInitializations.determineLoopback] - Loopback interface: lo (lo, 0:0:0:0:0:0:0:1%lo)
21:24:33.519 DEBUG [NetUtil$SoMaxConnAction.run] - /proc/sys/net/core/somaxconn: 4096
21:24:33.520 DEBUG [DefaultChannelId.<clinit>] - -Dio.netty.machineId: 32:f0:68:ff:fe:89:31:2b (auto-detected)
21:24:33.533 DEBUG [ResourceLeakDetector.<clinit>] - -Dio.netty.leakDetection.level: simple
21:24:33.534 DEBUG [ResourceLeakDetector.<clinit>] - -Dio.netty.leakDetection.targetRecords: 4
21:24:33.579 DEBUG [PooledByteBufAllocator.<clinit>] - -Dio.netty.allocator.numHeapArenas: 16
21:24:33.580 DEBUG [PooledByteBufAllocator.<clinit>] - -Dio.netty.allocator.numDirectArenas: 16
21:24:33.580 DEBUG [PooledByteBufAllocator.<clinit>] - -Dio.netty.allocator.pageSize: 8192
21:24:33.580 DEBUG [PooledByteBufAllocator.<clinit>] - -Dio.netty.allocator.maxOrder: 9
21:24:33.580 DEBUG [PooledByteBufAllocator.<clinit>] - -Dio.netty.allocator.chunkSize: 4194304
21:24:33.580 DEBUG [PooledByteBufAllocator.<clinit>] - -Dio.netty.allocator.smallCacheSize: 256
21:24:33.580 DEBUG [PooledByteBufAllocator.<clinit>] - -Dio.netty.allocator.normalCacheSize: 64
21:24:33.580 DEBUG [PooledByteBufAllocator.<clinit>] - -Dio.netty.allocator.maxCachedBufferCapacity: 32768
21:24:33.580 DEBUG [PooledByteBufAllocator.<clinit>] - -Dio.netty.allocator.cacheTrimInterval: 8192
21:24:33.581 DEBUG [PooledByteBufAllocator.<clinit>] - -Dio.netty.allocator.cacheTrimIntervalMillis: 0
21:24:33.581 DEBUG [PooledByteBufAllocator.<clinit>] - -Dio.netty.allocator.useCacheForAllThreads: false
21:24:33.581 DEBUG [PooledByteBufAllocator.<clinit>] - -Dio.netty.allocator.maxCachedByteBuffersPerChunk: 1023
21:24:33.592 DEBUG [ByteBufUtil.<clinit>] - -Dio.netty.allocator.type: pooled
21:24:33.592 DEBUG [ByteBufUtil.<clinit>] - -Dio.netty.threadLocalDirectBufferSize: 0
21:24:33.592 DEBUG [ByteBufUtil.<clinit>] - -Dio.netty.maxThreadLocalCharBufferSize: 16384
21:24:33.605 DEBUG [LoggingHandler.channelRegistered] - [id: 0xb17fbee5] REGISTERED
21:24:33.637 DEBUG [LoggingHandler.bind] - [id: 0xb17fbee5] BIND: 0.0.0.0/0.0.0.0:4444
21:24:33.640 INFO [Hub.execute] - Started Selenium Hub 4.8.1 (revision 8ebccac989): http://10.42.0.210:4444
21:24:33.642 DEBUG [LoggingHandler.channelActive] - [id: 0xb17fbee5, L:/0:0:0:0:0:0:0:0:4444] ACTIVE
21:24:47.861 DEBUG [LoggingHandler.channelRead] - [id: 0xb17fbee5, L:/0:0:0:0:0:0:0:0:4444] READ: [id: 0x1fb87ca3, L:/10.42.0.210:4444 - R:/10.42.0.1:34864]
21:24:47.863 DEBUG [LoggingHandler.channelRead] - [id: 0xb17fbee5, L:/0:0:0:0:0:0:0:0:4444] READ: [id: 0x0b2e3e09, L:/10.42.0.210:4444 - R:/10.42.0.1:34860]
21:24:47.864 DEBUG [LoggingHandler.channelReadComplete] - [id: 0xb17fbee5, L:/0:0:0:0:0:0:0:0:4444] READ COMPLETE
21:24:47.901 DEBUG [AbstractByteBuf.<clinit>] - -Dio.netty.buffer.checkAccessible: true
21:24:47.902 DEBUG [AbstractByteBuf.<clinit>] - -Dio.netty.buffer.checkBounds: true
21:24:47.903 DEBUG [ResourceLeakDetectorFactory$DefaultResourceLeakDetectorFactory.newResourceLeakDetector] - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@175cd4d7
21:24:47.919 DEBUG [ZlibCodecFactory.<clinit>] - -Dio.netty.noJdkZlibDecoder: false
21:24:47.919 DEBUG [ZlibCodecFactory.<clinit>] - -Dio.netty.noJdkZlibEncoder: false
21:24:47.932 DEBUG [Recycler.<clinit>] - -Dio.netty.recycler.maxCapacityPerThread: 4096
21:24:47.933 DEBUG [Recycler.<clinit>] - -Dio.netty.recycler.ratio: 8
21:24:47.933 DEBUG [Recycler.<clinit>] - -Dio.netty.recycler.chunkSize: 32
21:24:47.933 DEBUG [Recycler.<clinit>] - -Dio.netty.recycler.blocking: false
21:24:47.983 DEBUG [RequestConverter.channelRead0] - Incoming message: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
GET /readyz HTTP/1.1
Host: 10.42.0.210:4444
User-Agent: kube-probe/1.24
Accept: */*
Connection: close
21:24:47.984 DEBUG [RequestConverter.channelRead0] - Start of http request: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
GET /readyz HTTP/1.1
Host: 10.42.0.210:4444
User-Agent: kube-probe/1.24
Accept: */*
Connection: close
21:24:47.983 DEBUG [RequestConverter.channelRead0] - Incoming message: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
GET /readyz HTTP/1.1
Host: 10.42.0.210:4444
User-Agent: kube-probe/1.24
Accept: */*
Connection: close
21:24:47.984 DEBUG [RequestConverter.channelRead0] - Start of http request: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
GET /readyz HTTP/1.1
Host: 10.42.0.210:4444
User-Agent: kube-probe/1.24
Accept: */*
Connection: close
21:24:47.988 DEBUG [RequestConverter.channelRead0] - Incoming message: EmptyLastHttpContent
21:24:47.989 DEBUG [RequestConverter.channelRead0] - End of http request: EmptyLastHttpContent
21:24:47.990 DEBUG [RequestConverter.channelRead0] - Incoming message: EmptyLastHttpContent
21:24:47.990 DEBUG [RequestConverter.channelRead0] - End of http request: EmptyLastHttpContent
21:24:48.020 DEBUG [RequestConverter.channelInactive] - Channel became inactive.
21:24:48.020 DEBUG [RequestConverter.channelInactive] - Channel became inactive.
21:24:57.849 DEBUG [LoggingHandler.channelRead] - [id: 0xb17fbee5, L:/0:0:0:0:0:0:0:0:4444] READ: [id: 0x6471aff6, L:/10.42.0.210:4444 - R:/10.42.0.1:51098]
21:24:57.850 DEBUG [LoggingHandler.channelRead] - [id: 0xb17fbee5, L:/0:0:0:0:0:0:0:0:4444] READ: [id: 0xb1ce7465, L:/10.42.0.210:4444 - R:/10.42.0.1:51112]
21:24:57.851 DEBUG [LoggingHandler.channelReadComplete] - [id: 0xb17fbee5, L:/0:0:0:0:0:0:0:0:4444] READ COMPLETE
21:24:57.858 DEBUG [RequestConverter.channelRead0] - Incoming message: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
GET /readyz HTTP/1.1
Host: 10.42.0.210:4444
User-Agent: kube-probe/1.24
Accept: */*
Connection: close

....

21:27:27.853 DEBUG [RequestConverter.channelRead0] - Incoming message: EmptyLastHttpContent
21:27:27.853 DEBUG [RequestConverter.channelRead0] - Incoming message: EmptyLastHttpContent
21:27:27.853 DEBUG [RequestConverter.channelRead0] - End of http request: EmptyLastHttpContent
21:27:27.853 DEBUG [RequestConverter.channelRead0] - End of http request: EmptyLastHttpContent
21:27:27.856 DEBUG [RequestConverter.channelInactive] - Channel became inactive.
21:27:27.856 DEBUG [RequestConverter.channelInactive] - Channel became inactive.
21:27:33.288 INFO [Node.<init>] - Binding additional locator mechanisms: relative
21:27:33.416 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:5f70e86da49f346352ebab2, Subject:CN=Trustwave Global Certification Authority, O="Trustwave Holdings, Inc.", L=Chicago, ST=Illinois, C=US, Issuer:CN=Trustwave Global Certification Authority, O="Trustwave Holdings, Inc.", L=Chicago, ST=Illinois, C=US, Key type:RSA, Length:4096, Cert Id:416366836, Valid from:8/23/17, 7:34 PM, Valid until:8/23/42, 7:34 PM
21:27:33.419 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withRSA, Serial:6e47a9c65ab3e720c5309a3f6852f26f, Subject:CN=GTS Root R2, O=Google Trust Services LLC, C=US, Issuer:CN=GTS Root R2, O=Google Trust Services LLC, C=US, Key type:RSA, Length:4096, Cert Id:-1151551794, Valid from:6/22/16, 12:00 AM, Valid until:6/22/36, 12:00 AM
21:27:33.421 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withECDSA, Serial:7497258ac73f7a54, Subject:CN=AffirmTrust Premium ECC, O=AffirmTrust, C=US, Issuer:CN=AffirmTrust Premium ECC, O=AffirmTrust, C=US, Key type:EC, Length:384, Cert Id:-2080363786, Valid from:1/29/10, 2:20 PM, Valid until:12/31/40, 2:20 PM
21:27:33.423 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:8165f8a4ca5ec00c99340dfc4c6ae23b81c5aa4, Subject:CN=Hongkong Post Root CA 3, O=Hongkong Post, L=Hong Kong, ST=Hong Kong, C=HK, Issuer:CN=Hongkong Post Root CA 3, O=Hongkong Post, L=Hong Kong, ST=Hong Kong, C=HK, Key type:RSA, Length:4096, Cert Id:-901951080, Valid from:6/3/17, 2:29 AM, Valid until:6/3/42, 2:29 AM
21:27:33.425 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:bb401c43f55e4fb0, Subject:CN=SwissSign Gold CA - G2, O=SwissSign AG, C=CH, Issuer:CN=SwissSign Gold CA - G2, O=SwissSign AG, C=CH, Key type:RSA, Length:4096, Cert Id:1516221943, Valid from:10/25/06, 8:30 AM, Valid until:10/25/36, 8:30 AM
21:27:33.429 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:5ec3b7a6437fa4e0, Subject:C=ES, O=ACCV, OU=PKIACCV, CN=ACCVRAIZ1, Issuer:C=ES, O=ACCV, OU=PKIACCV, CN=ACCVRAIZ1, Key type:RSA, Length:4096, Cert Id:-592111236, Valid from:5/5/11, 9:37 AM, Valid until:12/31/30, 9:37 AM
21:27:33.431 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withECDSA, Serial:66f23daf87de8bb14aea0c573101c2ec, Subject:CN=Microsoft ECC Root Certificate Authority 2017, O=Microsoft Corporation, C=US, Issuer:CN=Microsoft ECC Root Certificate Authority 2017, O=Microsoft Corporation, C=US, Key type:EC, Length:384, Cert Id:-1054206011, Valid from:12/18/19, 11:06 PM, Valid until:7/18/42, 11:16 PM
21:27:33.432 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:76b1205274f0858746b3f8231af6c2c0, Subject:CN=OISTE WISeKey Global Root GB CA, OU=OISTE Foundation Endorsed, O=WISeKey, C=CH, Issuer:CN=OISTE WISeKey Global Root GB CA, OU=OISTE Foundation Endorsed, O=WISeKey, C=CH, Key type:RSA, Length:2048, Cert Id:-613481516, Valid from:12/1/14, 3:00 PM, Valid until:12/1/39, 3:10 PM
21:27:33.434 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:aecf00bac4cf32f843b2, Subject:CN=emSign Root CA - C1, O=eMudhra Inc, OU=emSign PKI, C=US, Issuer:CN=emSign Root CA - C1, O=eMudhra Inc, OU=emSign PKI, C=US, Key type:RSA, Length:2048, Cert Id:-1268863356, Valid from:2/18/18, 6:30 PM, Valid until:2/18/43, 6:30 PM
21:27:33.436 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:57cb336fc25c16e6471617e3903168e0, Subject:CN=Network Solutions Certificate Authority, O=Network Solutions L.L.C., C=US, Issuer:CN=Network Solutions Certificate Authority, O=Network Solutions L.L.C., C=US, Key type:RSA, Length:2048, Cert Id:1751576863, Valid from:12/1/06, 12:00 AM, Valid until:12/31/29, 11:59 PM
21:27:33.437 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withECDSA, Serial:d6a5f083f285c3e5195df5d, Subject:CN=Trustwave Global ECC P256 Certification Authority, O="Trustwave Holdings, Inc.", L=Chicago, ST=Illinois, C=US, Issuer:CN=Trustwave Global ECC P256 Certification Authority, O="Trustwave Holdings, Inc.", L=Chicago, ST=Illinois, C=US, Key type:EC, Length:256, Cert Id:948272517, Valid from:8/23/17, 7:35 PM, Valid until:8/23/42, 7:35 PM
21:27:33.439 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:3863def8, Subject:CN=Entrust.net Certification Authority (2048), OU=(c) 1999 Entrust.net Limited, OU=www.entrust.net/CPS_2048 incorp. by ref. (limits liab.), O=Entrust.net, Issuer:CN=Entrust.net Certification Authority (2048), OU=(c) 1999 Entrust.net Limited, OU=www.entrust.net/CPS_2048 incorp. by ref. (limits liab.), O=Entrust.net, Key type:RSA, Length:2048, Cert Id:-328536082, Valid from:12/24/99, 5:50 PM, Valid until:7/24/29, 2:15 PM
21:27:33.441 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withECDSA, Serial:66c9fd5749736663f3b0b9ad9e89e7603f24a, Subject:CN=Amazon Root CA 3, O=Amazon, C=US, Issuer:CN=Amazon Root CA 3, O=Amazon, C=US, Key type:EC, Length:256, Cert Id:-1562287523, Valid from:5/26/15, 12:00 AM, Valid until:5/26/40, 12:00 AM
21:27:33.443 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withRSA, Serial:45e6bb038333c3856548e6ff4551, Subject:CN=GlobalSign, O=GlobalSign, OU=GlobalSign Root CA - R6, Issuer:CN=GlobalSign, O=GlobalSign, OU=GlobalSign Root CA - R6, Key type:RSA, Length:4096, Cert Id:-506627753, Valid from:12/10/14, 12:00 AM, Valid until:12/10/34, 12:00 AM
21:27:33.445 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:a0142800000014523c844b500000002, Subject:CN=IdenTrust Commercial Root CA 1, O=IdenTrust, C=US, Issuer:CN=IdenTrust Commercial Root CA 1, O=IdenTrust, C=US, Key type:RSA, Length:4096, Cert Id:1232565210, Valid from:1/16/14, 6:12 PM, Valid until:1/16/34, 6:12 PM
21:27:33.449 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:cf08e5c0816a5ad427ff0eb271859d0, Subject:CN=SecureTrust CA, O=SecureTrust Corporation, C=US, Issuer:CN=SecureTrust CA, O=SecureTrust Corporation, C=US, Key type:RSA, Length:2048, Cert Id:2034155325, Valid from:11/7/06, 7:31 PM, Valid until:12/31/29, 7:40 PM
21:27:33.452 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:83be056904246b1a1756ac95991c74a, Subject:CN=DigiCert Global Root CA, OU=www.digicert.com, O=DigiCert Inc, C=US, Issuer:CN=DigiCert Global Root CA, OU=www.digicert.com, O=DigiCert Inc, C=US, Key type:RSA, Length:2048, Cert Id:1341898239, Valid from:11/10/06, 12:00 AM, Valid until:11/10/31, 12:00 AM
21:27:33.453 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:7777062726a9b17c, Subject:CN=AffirmTrust Commercial, O=AffirmTrust, C=US, Issuer:CN=AffirmTrust Commercial, O=AffirmTrust, C=US, Key type:RSA, Length:2048, Cert Id:630485644, Valid from:1/29/10, 2:06 PM, Valid until:12/31/30, 2:06 PM
21:27:33.456 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withECDSA, Serial:15448ef21fd97590df5040a, Subject:CN=e-Szigno Root CA 2017, OID.2.5.4.97=VATHU-23584497, O=Microsec Ltd., L=Budapest, C=HU, Issuer:CN=e-Szigno Root CA 2017, OID.2.5.4.97=VATHU-23584497, O=Microsec Ltd., L=Budapest, C=HU, Key type:EC, Length:256, Cert Id:-991173715, Valid from:8/22/17, 12:07 PM, Valid until:8/22/42, 12:07 PM
21:27:33.457 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:5ddfb1da5aa3ed5dbe5a6520650390ef, Subject:CN=UCA Global G2 Root, O=UniTrust, C=CN, Issuer:CN=UCA Global G2 Root, O=UniTrust, C=CN, Key type:RSA, Length:4096, Cert Id:1844967193, Valid from:3/11/16, 12:00 AM, Valid until:12/31/40, 12:00 AM
21:27:33.460 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withRSA, Serial:6e47a9c54b470c0dec33d089b91cf4e1, Subject:CN=GTS Root R1, O=Google Trust Services LLC, C=US, Issuer:CN=GTS Root R1, O=Google Trust Services LLC, C=US, Key type:RSA, Length:4096, Cert Id:-1684052905, Valid from:6/22/16, 12:00 AM, Valid until:6/22/36, 12:00 AM
21:27:33.461 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:50946cec18ead59c4dd597ef758fa0ad, Subject:CN=XRamp Global Certification Authority, O=XRamp Security Services Inc, OU=www.xrampsecurity.com, C=US, Issuer:CN=XRamp Global Certification Authority, O=XRamp Security Services Inc, OU=www.xrampsecurity.com, C=US, Key type:RSA, Length:2048, Cert Id:-952474086, Valid from:11/1/04, 5:14 PM, Valid until:1/1/35, 5:37 AM
21:27:33.463 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withECDSA, Serial:75e6dfcbc1685ba8, Subject:CN=SSL.com Root Certification Authority ECC, O=SSL Corporation, L=Houston, ST=Texas, C=US, Issuer:CN=SSL.com Root Certification Authority ECC, O=SSL Corporation, L=Houston, ST=Texas, C=US, Key type:EC, Length:384, Cert Id:-1368293613, Valid from:2/12/16, 6:14 PM, Valid until:2/12/41, 6:14 PM
21:27:33.464 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:92b888dbb08ac163, Subject:CN=CA Disig Root R2, O=Disig a.s., L=Bratislava, C=SK, Issuer:CN=CA Disig Root R2, O=Disig a.s., L=Bratislava, C=SK, Key type:RSA, Length:4096, Cert Id:747175721, Valid from:7/19/12, 9:15 AM, Valid until:7/19/42, 9:15 AM
21:27:33.466 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:5c6, Subject:CN=QuoVadis Root CA 3, O=QuoVadis Limited, C=BM, Issuer:CN=QuoVadis Root CA 3, O=QuoVadis Limited, C=BM, Key type:RSA, Length:4096, Cert Id:1470392860, Valid from:11/24/06, 7:11 PM, Valid until:11/24/31, 7:06 PM
21:27:33.467 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:0, Subject:OU=Starfield Class 2 Certification Authority, O="Starfield Technologies, Inc.", C=US, Issuer:OU=Starfield Class 2 Certification Authority, O="Starfield Technologies, Inc.", C=US, Key type:RSA, Length:2048, Cert Id:1825617644, Valid from:6/29/04, 5:39 PM, Valid until:6/29/34, 5:39 PM
21:27:33.468 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:0, Subject:CN=Starfield Services Root Certificate Authority - G2, O="Starfield Technologies, Inc.", L=Scottsdale, ST=Arizona, C=US, Issuer:CN=Starfield Services Root Certificate Authority - G2, O="Starfield Technologies, Inc.", L=Scottsdale, ST=Arizona, C=US, Key type:RSA, Length:2048, Cert Id:1964785574, Valid from:9/1/09, 12:00 AM, Valid until:12/31/37, 11:59 PM
21:27:33.470 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:456b5054, Subject:CN=Entrust Root Certification Authority, OU="(c) 2006 Entrust, Inc.", OU=www.entrust.net/CPS is incorporated by reference, O="Entrust, Inc.", C=US, Issuer:CN=Entrust Root Certification Authority, OU="(c) 2006 Entrust, Inc.", OU=www.entrust.net/CPS is incorporated by reference, O="Entrust, Inc.", C=US, Key type:RSA, Length:2048, Cert Id:-1261404096, Valid from:11/27/06, 8:23 PM, Valid until:11/27/26, 8:53 PM
21:27:33.472 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:5a4bbd5afb4f8a5bfa65e5, Subject:CN=GLOBALTRUST 2020, O=e-commerce monitoring GmbH, C=AT, Issuer:CN=GLOBALTRUST 2020, O=e-commerce monitoring GmbH, C=AT, Key type:RSA, Length:4096, Cert Id:-522246883, Valid from:2/10/20, 12:00 AM, Valid until:6/10/40, 12:00 AM
21:27:33.473 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:110034b64ec6362d36, Subject:OU=certSIGN ROOT CA G2, O=CERTSIGN SA, C=RO, Issuer:OU=certSIGN ROOT CA G2, O=CERTSIGN SA, C=RO, Key type:RSA, Length:4096, Cert Id:-2113880430, Valid from:2/6/17, 9:27 AM, Valid until:2/6/42, 9:27 AM
21:27:33.475 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:5c33cb622c5fb332, Subject:C=DE, O=Atos, CN=Atos TrustedRoot 2011, Issuer:C=DE, O=Atos, CN=Atos TrustedRoot 2011, Key type:RSA, Length:2048, Cert Id:-28528624, Valid from:7/7/11, 2:58 PM, Valid until:12/31/30, 11:59 PM
21:27:33.476 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withRSA, Serial:66c9fd29635869f0a0fe58678f85b26bb8a37, Subject:CN=Amazon Root CA 2, O=Amazon, C=US, Issuer:CN=Amazon Root CA 2, O=Amazon, C=US, Key type:RSA, Length:4096, Cert Id:-1766132388, Valid from:5/26/15, 12:00 AM, Valid until:5/26/40, 12:00 AM
21:27:33.478 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:1, Subject:CN=T-TeleSec GlobalRoot Class 3, OU=T-Systems Trust Center, O=T-Systems Enterprise Services GmbH, C=DE, Issuer:CN=T-TeleSec GlobalRoot Class 3, OU=T-Systems Trust Center, O=T-Systems Enterprise Services GmbH, C=DE, Key type:RSA, Length:2048, Cert Id:1894096264, Valid from:10/1/08, 10:29 AM, Valid until:10/1/33, 11:59 PM
21:27:33.479 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:ce7e0e517d846fe8fe560fc1bf03039, Subject:CN=DigiCert Assured ID Root CA, OU=www.digicert.com, O=DigiCert Inc, C=US, Issuer:CN=DigiCert Assured ID Root CA, OU=www.digicert.com, O=DigiCert Inc, C=US, Key type:RSA, Length:2048, Cert Id:-860404528, Valid from:11/10/06, 12:00 AM, Valid until:11/10/31, 12:00 AM
21:27:33.480 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withRSA, Serial:194301ea20bddf5c5332ab1434471f8d6504d0d, Subject:CN=NAVER Global Root Certification Authority, O=NAVER BUSINESS PLATFORM Corp., C=KR, Issuer:CN=NAVER Global Root Certification Authority, O=NAVER BUSINESS PLATFORM Corp., C=KR, Key type:RSA, Length:4096, Cert Id:1777546867, Valid from:8/18/17, 8:58 AM, Valid until:8/18/37, 11:59 PM
21:27:33.482 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:fedce3010fc948ff, Subject:CN=Certigna, O=Dhimyotis, C=FR, Issuer:CN=Certigna, O=Dhimyotis, C=FR, Key type:RSA, Length:2048, Cert Id:-788091456, Valid from:6/29/07, 3:13 PM, Valid until:6/29/27, 3:13 PM
21:27:33.483 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:6a683e9c519bcb53, Subject:CN=E-Tugra Certification Authority, OU=E-Tugra Sertifikasyon Merkezi, O=E-Tuğra EBG Bilişim Teknolojileri ve Hizmetleri A.Ş., L=Ankara, C=TR, Issuer:CN=E-Tugra Certification Authority, OU=E-Tugra Sertifikasyon Merkezi, O=E-Tuğra EBG Bilişim Teknolojileri ve Hizmetleri A.Ş., L=Ankara, C=TR, Key type:RSA, Length:4096, Cert Id:-673382379, Valid from:3/5/13, 12:09 PM, Valid until:3/3/23, 12:09 PM
21:27:33.484 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:0, Subject:CN=Hellenic Academic and Research Institutions RootCA 2011, O=Hellenic Academic and Research Institutions Cert. Authority, C=GR, Issuer:CN=Hellenic Academic and Research Institutions RootCA 2011, O=Hellenic Academic and Research Institutions Cert. Authority, C=GR, Key type:RSA, Length:2048, Cert Id:-1841489473, Valid from:12/6/11, 1:49 PM, Valid until:12/1/31, 1:49 PM
21:27:33.485 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:2, Subject:CN=Buypass Class 2 Root CA, O=Buypass AS-983163327, C=NO, Issuer:CN=Buypass Class 2 Root CA, O=Buypass AS-983163327, C=NO, Key type:RSA, Length:4096, Cert Id:969960563, Valid from:10/26/10, 8:38 AM, Valid until:10/26/40, 8:38 AM
21:27:33.486 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:78585f2ead2c194be3370735341328b596d46593, Subject:CN=QuoVadis Root CA 1 G3, O=QuoVadis Limited, C=BM, Issuer:CN=QuoVadis Root CA 1 G3, O=QuoVadis Limited, C=BM, Key type:RSA, Length:4096, Cert Id:-762436034, Valid from:1/12/12, 5:27 PM, Valid until:1/12/42, 5:27 PM
21:27:33.487 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:98968d, Subject:CN=Staat der Nederlanden EV Root CA, O=Staat der Nederlanden, C=NL, Issuer:CN=Staat der Nederlanden EV Root CA, O=Staat der Nederlanden, C=NL, Key type:RSA, Length:4096, Cert Id:1444801426, Valid from:12/8/10, 11:19 AM, Valid until:12/8/22, 11:10 AM
21:27:33.487 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:2ef59b0228a7db7affd5a3a9eebd03a0cf126a1d, Subject:CN=QuoVadis Root CA 3 G3, O=QuoVadis Limited, C=BM, Issuer:CN=QuoVadis Root CA 3 G3, O=QuoVadis Limited, C=BM, Key type:RSA, Length:4096, Cert Id:-705622991, Valid from:1/12/12, 8:26 PM, Valid until:1/12/42, 8:26 PM
21:27:33.488 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:-11d4c2142bde21eb579d53fb0c223bff, Subject:CN=EC-ACC, OU=Jerarquia Entitats de Certificacio Catalanes, OU=Vegeu https://www.catcert.net/verarrel (c)03, OU=Serveis Publics de Certificacio, O=Agencia Catalana de Certificacio (NIF Q-0801176-I), C=ES, Issuer:CN=EC-ACC, OU=Jerarquia Entitats de Certificacio Catalanes, OU=Vegeu https://www.catcert.net/verarrel (c)03, OU=Serveis Publics de Certificacio, O=Agencia Catalana de Certificacio (NIF Q-0801176-I), C=ES, Key type:RSA, Length:2048, Cert Id:1077306647, Valid from:1/7/03, 11:00 PM, Valid until:1/7/31, 10:59 PM
21:27:33.489 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:dd3e3bc6cf96bb1, Subject:CN=ANF Secure Server Root CA, OU=ANF CA Raiz, O=ANF Autoridad de Certificacion, C=ES, SERIALNUMBER=G63287510, Issuer:CN=ANF Secure Server Root CA, OU=ANF CA Raiz, O=ANF Autoridad de Certificacion, C=ES, SERIALNUMBER=G63287510, Key type:RSA, Length:4096, Cert Id:-841649695, Valid from:9/4/19, 10:00 AM, Valid until:8/30/39, 10:00 AM
21:27:33.490 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withRSA, Serial:1fd6d30fca3ca51a81bbc640e35032d, Subject:CN=USERTrust RSA Certification Authority, O=The USERTRUST Network, L=Jersey City, ST=New Jersey, C=US, Issuer:CN=USERTrust RSA Certification Authority, O=The USERTRUST Network, L=Jersey City, ST=New Jersey, C=US, Key type:RSA, Length:4096, Cert Id:-347365895, Valid from:2/1/10, 12:00 AM, Valid until:1/18/38, 11:59 PM
21:27:33.491 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:4e812d8a8265e00b02ee3e350246e53d, Subject:CN=COMODO Certification Authority, O=COMODO CA Limited, L=Salford, ST=Greater Manchester, C=GB, Issuer:CN=COMODO Certification Authority, O=COMODO CA Limited, L=Salford, ST=Greater Manchester, C=GB, Key type:RSA, Length:2048, Cert Id:904304908, Valid from:12/1/06, 12:00 AM, Valid until:12/31/29, 11:59 PM
21:27:33.492 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:49412ce40010, Subject:CN=NetLock Arany (Class Gold) Főtanúsítvány, OU=Tanúsítványkiadók (Certification Services), O=NetLock Kft., L=Budapest, C=HU, Issuer:CN=NetLock Arany (Class Gold) Főtanúsítvány, OU=Tanúsítványkiadók (Certification Services), O=NetLock Kft., L=Budapest, C=HU, Key type:RSA, Length:2048, Cert Id:58541246, Valid from:12/11/08, 3:08 PM, Valid until:12/6/28, 3:08 PM
21:27:33.492 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withECDSA, Serial:a68b79290000000050d091f9, Subject:CN=Entrust Root Certification Authority - EC1, OU="(c) 2012 Entrust, Inc. - for authorized use only", OU=See www.entrust.net/legal-terms, O="Entrust, Inc.", C=US, Issuer:CN=Entrust Root Certification Authority - EC1, OU="(c) 2012 Entrust, Inc. - for authorized use only", OU=See www.entrust.net/legal-terms, O="Entrust, Inc.", C=US, Key type:EC, Length:384, Cert Id:924514073, Valid from:12/18/12, 3:25 PM, Valid until:12/18/37, 3:55 PM
21:27:33.493 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:3e8, Subject:CN=Hongkong Post Root CA 1, O=Hongkong Post, C=HK, Issuer:CN=Hongkong Post Root CA 1, O=Hongkong Post, C=HK, Key type:RSA, Length:2048, Cert Id:-1426826250, Valid from:5/15/03, 5:13 AM, Valid until:5/15/23, 4:52 AM
21:27:33.494 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:1, Subject:CN=TWCA Root Certification Authority, OU=Root CA, O=TAIWAN-CA, C=TW, Issuer:CN=TWCA Root Certification Authority, OU=Root CA, O=TAIWAN-CA, C=TW, Key type:RSA, Length:2048, Cert Id:-1642094263, Valid from:8/28/08, 7:24 AM, Valid until:12/31/30, 3:59 PM
21:27:33.494 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withECDSA, Serial:5c8b99c55a94c5d27156decd8980cc26, Subject:CN=USERTrust ECC Certification Authority, O=The USERTRUST Network, L=Jersey City, ST=New Jersey, C=US, Issuer:CN=USERTrust ECC Certification Authority, O=The USERTRUST Network, L=Jersey City, ST=New Jersey, C=US, Key type:EC, Length:384, Cert Id:-965679910, Valid from:2/1/10, 12:00 AM, Valid until:1/18/38, 11:59 PM
21:27:33.495 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:0, Subject:CN=Starfield Root Certificate Authority - G2, O="Starfield Technologies, Inc.", L=Scottsdale, ST=Arizona, C=US, Issuer:CN=Starfield Root Certificate Authority - G2, O="Starfield Technologies, Inc.", L=Scottsdale, ST=Arizona, C=US, Key type:RSA, Length:2048, Cert Id:-1026641587, Valid from:9/1/09, 12:00 AM, Valid until:12/31/37, 11:59 PM
21:27:33.496 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:509, Subject:CN=QuoVadis Root CA 2, O=QuoVadis Limited, C=BM, Issuer:CN=QuoVadis Root CA 2, O=QuoVadis Limited, C=BM, Key type:RSA, Length:4096, Cert Id:338250116, Valid from:11/24/06, 6:27 PM, Valid until:11/24/31, 6:23 PM
21:27:33.496 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:444c0, Subject:CN=Certum Trusted Network CA, OU=Certum Certification Authority, O=Unizeto Technologies S.A., C=PL, Issuer:CN=Certum Trusted Network CA, OU=Certum Certification Authority, O=Unizeto Technologies S.A., C=PL, Key type:RSA, Length:2048, Cert Id:2014002193, Valid from:10/22/08, 12:07 PM, Valid until:12/31/29, 12:07 PM
21:27:33.497 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:c27e43044e473f19, Subject:EMAILADDRESS=info@e-szigno.hu, CN=Microsec e-Szigno Root CA 2009, O=Microsec Ltd., L=Budapest, C=HU, Issuer:EMAILADDRESS=info@e-szigno.hu, CN=Microsec e-Szigno Root CA 2009, O=Microsec Ltd., L=Budapest, C=HU, Key type:RSA, Length:2048, Cert Id:-1903950012, Valid from:6/16/09, 11:30 AM, Valid until:12/30/29, 11:30 AM
21:27:33.499 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:95be16a0f72e46f17b398272fa8bcd96, Subject:CN=TeliaSonera Root CA v1, O=TeliaSonera, Issuer:CN=TeliaSonera Root CA v1, O=TeliaSonera, Key type:RSA, Length:4096, Cert Id:1495358374, Valid from:10/18/07, 12:00 PM, Valid until:10/18/32, 12:00 PM
21:27:33.499 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withECDSA, Serial:605949e0262ebb55f90a778a71f94ad86c, Subject:CN=GlobalSign, O=GlobalSign, OU=GlobalSign ECC Root CA - R5, Issuer:CN=GlobalSign, O=GlobalSign, OU=GlobalSign ECC Root CA - R5, Key type:EC, Length:384, Cert Id:1997048439, Valid from:11/13/12, 12:00 AM, Valid until:1/19/38, 3:14 AM
21:27:33.500 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withECDSA, Serial:55556bcf25ea43535c3a40fd5ab4572, Subject:CN=DigiCert Global Root G3, OU=www.digicert.com, O=DigiCert Inc, C=US, Issuer:CN=DigiCert Global Root G3, OU=www.digicert.com, O=DigiCert Inc, C=US, Key type:EC, Length:384, Cert Id:-795968543, Valid from:8/1/13, 12:00 PM, Valid until:1/15/38, 12:00 PM
21:27:33.501 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:66c9fcf99bf8c0a39e2f0788a43e696365bca, Subject:CN=Amazon Root CA 1, O=Amazon, C=US, Issuer:CN=Amazon Root CA 1, O=Amazon, C=US, Key type:RSA, Length:2048, Cert Id:-1472444962, Valid from:5/26/15, 12:00 AM, Valid until:1/17/38, 12:00 AM
21:27:33.502 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:983f4, Subject:CN=D-TRUST Root Class 3 CA 2 EV 2009, O=D-Trust GmbH, C=DE, Issuer:CN=D-TRUST Root Class 3 CA 2 EV 2009, O=D-Trust GmbH, C=DE, Key type:RSA, Length:2048, Cert Id:971313728, Valid from:11/5/09, 8:50 AM, Valid until:11/5/29, 8:50 AM
21:27:33.502 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:1, Subject:CN=T-TeleSec GlobalRoot Class 2, OU=T-Systems Trust Center, O=T-Systems Enterprise Services GmbH, C=DE, Issuer:CN=T-TeleSec GlobalRoot Class 2, OU=T-Systems Trust Center, O=T-Systems Enterprise Services GmbH, C=DE, Key type:RSA, Length:2048, Cert Id:-1238464039, Valid from:10/1/08, 10:40 AM, Valid until:10/1/33, 11:59 PM
21:27:33.503 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withECDSA, Serial:8bd85976c9927a48068473b, Subject:CN=Trustwave Global ECC P384 Certification Authority, O="Trustwave Holdings, Inc.", L=Chicago, ST=Illinois, C=US, Issuer:CN=Trustwave Global ECC P384 Certification Authority, O="Trustwave Holdings, Inc.", L=Chicago, ST=Illinois, C=US, Key type:EC, Length:384, Cert Id:-1993924923, Valid from:8/23/17, 7:36 PM, Valid until:8/23/42, 7:36 PM
21:27:33.504 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withECDSA, Serial:212a560caeda0cab4045bf2ba22d3aea, Subject:CN=OISTE WISeKey Global Root GC CA, OU=OISTE Foundation Endorsed, O=WISeKey, C=CH, Issuer:CN=OISTE WISeKey Global Root GC CA, OU=OISTE Foundation Endorsed, O=WISeKey, C=CH, Key type:EC, Length:384, Cert Id:-1513165457, Valid from:5/9/17, 9:48 AM, Valid until:5/9/42, 9:58 AM
21:27:33.504 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:1, Subject:CN=SecureSign RootCA11, O="Japan Certification Services, Inc.", C=JP, Issuer:CN=SecureSign RootCA11, O="Japan Certification Services, Inc.", C=JP, Key type:RSA, Length:2048, Cert Id:2079057034, Valid from:4/8/09, 4:56 AM, Valid until:4/8/29, 4:56 AM
21:27:33.505 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:184accd6, Subject:CN=CFCA EV ROOT, O=China Financial Certification Authority, C=CN, Issuer:CN=CFCA EV ROOT, O=China Financial Certification Authority, C=CN, Key type:RSA, Length:4096, Cert Id:551407782, Valid from:8/8/12, 3:07 AM, Valid until:12/31/29, 3:07 AM
21:27:33.505 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA512withRSA, Serial:21d6d04a4f250fc93237fcaa5e128de9, Subject:CN=Certum Trusted Network CA 2, OU=Certum Certification Authority, O=Unizeto Technologies S.A., C=PL, Issuer:CN=Certum Trusted Network CA 2, OU=Certum Certification Authority, O=Unizeto Technologies S.A., C=PL, Key type:RSA, Length:4096, Cert Id:1983350452, Valid from:10/6/11, 8:39 AM, Valid until:10/6/46, 8:39 AM
21:27:33.506 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:983f3, Subject:CN=D-TRUST Root Class 3 CA 2 2009, O=D-Trust GmbH, C=DE, Issuer:CN=D-TRUST Root Class 3 CA 2 2009, O=D-Trust GmbH, C=DE, Key type:RSA, Length:2048, Cert Id:1430153102, Valid from:11/5/09, 8:35 AM, Valid until:11/5/29, 8:35 AM
21:27:33.507 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:7d0997fef047ea7a, Subject:CN=GDCA TrustAUTH R5 ROOT, O="GUANG DONG CERTIFICATE AUTHORITY CO.,LTD.", C=CN, Issuer:CN=GDCA TrustAUTH R5 ROOT, O="GUANG DONG CERTIFICATE AUTHORITY CO.,LTD.", C=CN, Key type:RSA, Length:4096, Cert Id:494136981, Valid from:11/26/14, 5:13 AM, Valid until:12/31/40, 3:59 PM
21:27:33.507 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:0, Subject:CN=Hellenic Academic and Research Institutions RootCA 2015, O=Hellenic Academic and Research Institutions Cert. Authority, L=Athens, C=GR, Issuer:CN=Hellenic Academic and Research Institutions RootCA 2015, O=Hellenic Academic and Research Institutions Cert. Authority, L=Athens, C=GR, Key type:RSA, Length:4096, Cert Id:-802976731, Valid from:7/7/15, 10:11 AM, Valid until:6/30/40, 10:11 AM
21:27:33.508 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withRSA, Serial:1ed397095fd8b4b347701eaabe7f45b3, Subject:CN=Microsoft RSA Root Certificate Authority 2017, O=Microsoft Corporation, C=US, Issuer:CN=Microsoft RSA Root Certificate Authority 2017, O=Microsoft Corporation, C=US, Key type:RSA, Length:4096, Cert Id:-1446618248, Valid from:12/18/19, 10:51 PM, Valid until:7/18/42, 11:00 PM
21:27:33.508 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withRSA, Serial:11d2bbb9d723189e405f0a9d2dd0df2567d1, Subject:CN=GlobalSign Root R46, O=GlobalSign nv-sa, C=BE, Issuer:CN=GlobalSign Root R46, O=GlobalSign nv-sa, C=BE, Key type:RSA, Length:4096, Cert Id:1275948927, Valid from:3/20/19, 12:00 AM, Valid until:3/20/46, 12:00 AM
21:27:33.509 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withECDSA, Serial:ba15afa1ddfa0b54944afcd24a06cec, Subject:CN=DigiCert Assured ID Root G3, OU=www.digicert.com, O=DigiCert Inc, C=US, Issuer:CN=DigiCert Assured ID Root G3, OU=www.digicert.com, O=DigiCert Inc, C=US, Key type:EC, Length:384, Cert Id:-645537245, Valid from:8/1/13, 12:00 PM, Valid until:1/15/38, 12:00 PM
21:27:33.510 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:4f1bd42f54bb2f4b, Subject:CN=SwissSign Silver CA - G2, O=SwissSign AG, C=CH, Issuer:CN=SwissSign Silver CA - G2, O=SwissSign AG, C=CH, Key type:RSA, Length:4096, Cert Id:126726124, Valid from:10/25/06, 8:32 AM, Valid until:10/25/36, 8:32 AM
21:27:33.510 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:570a119742c4e3cc, Subject:CN=Actalis Authentication Root CA, O=Actalis S.p.A./03358520967, L=Milan, C=IT, Issuer:CN=Actalis Authentication Root CA, O=Actalis S.p.A./03358520967, L=Milan, C=IT, Key type:RSA, Length:4096, Cert Id:1729119956, Valid from:9/22/11, 11:22 AM, Valid until:9/22/30, 11:22 AM
21:27:33.511 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withECDSA, Serial:788f275c81125220a504d02dddba73f4, Subject:CN=Certum EC-384 CA, OU=Certum Certification Authority, O=Asseco Data Systems S.A., C=PL, Issuer:CN=Certum EC-384 CA, OU=Certum Certification Authority, O=Asseco Data Systems S.A., C=PL, Key type:EC, Length:384, Cert Id:994586241, Valid from:3/26/18, 7:24 AM, Valid until:3/26/43, 7:24 AM
21:27:33.511 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withRSA, Serial:59b1b579e8e2132e23907bda777755c, Subject:CN=DigiCert Trusted Root G4, OU=www.digicert.com, O=DigiCert Inc, C=US, Issuer:CN=DigiCert Trusted Root G4, OU=www.digicert.com, O=DigiCert Inc, C=US, Key type:RSA, Length:4096, Cert Id:1057369358, Valid from:8/1/13, 12:00 PM, Valid until:1/15/38, 12:00 PM
21:27:33.512 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:40000000001154b5ac394, Subject:CN=GlobalSign Root CA, OU=Root CA, O=GlobalSign nv-sa, C=BE, Issuer:CN=GlobalSign Root CA, OU=Root CA, O=GlobalSign nv-sa, C=BE, Key type:RSA, Length:2048, Cert Id:536948034, Valid from:9/1/98, 12:00 PM, Valid until:1/28/28, 12:00 PM
21:27:33.512 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withECDSA, Serial:3cf607a968700eda8b84, Subject:CN=emSign ECC Root CA - G3, O=eMudhra Technologies Limited, OU=emSign PKI, C=IN, Issuer:CN=emSign ECC Root CA - G3, O=eMudhra Technologies Limited, OU=emSign PKI, C=IN, Key type:EC, Length:384, Cert Id:-462931589, Valid from:2/18/18, 6:30 PM, Valid until:2/18/43, 6:30 PM
21:27:33.513 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:d9b5437fafa9390f000000005565ad58, Subject:CN=Entrust Root Certification Authority - G4, OU="(c) 2015 Entrust, Inc. - for authorized use only", OU=See www.entrust.net/legal-terms, O="Entrust, Inc.", C=US, Issuer:CN=Entrust Root Certification Authority - G4, OU="(c) 2015 Entrust, Inc. - for authorized use only", OU=See www.entrust.net/legal-terms, O="Entrust, Inc.", C=US, Key type:RSA, Length:4096, Cert Id:1368037548, Valid from:5/27/15, 11:11 AM, Valid until:12/27/37, 11:41 AM
21:27:33.514 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withECDSA, Serial:6e47a9c88b94b6e8bb3b2ad8a2b2c199, Subject:CN=GTS Root R4, O=Google Trust Services LLC, C=US, Issuer:CN=GTS Root R4, O=Google Trust Services LLC, C=US, Key type:EC, Length:384, Cert Id:-1824562466, Valid from:6/22/16, 12:00 AM, Valid until:6/22/36, 12:00 AM
21:27:33.514 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:7c4f04391cd4992d, Subject:CN=AffirmTrust Networking, O=AffirmTrust, C=US, Issuer:CN=AffirmTrust Networking, O=AffirmTrust, C=US, Key type:RSA, Length:2048, Cert Id:651670175, Valid from:1/29/10, 2:08 PM, Valid until:12/31/30, 2:08 PM
21:27:33.515 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:56b629cd34bc78f6, Subject:CN=SSL.com EV Root Certification Authority RSA R2, O=SSL Corporation, L=Houston, ST=Texas, C=US, Issuer:CN=SSL.com EV Root Certification Authority RSA R2, O=SSL Corporation, L=Houston, ST=Texas, C=US, Key type:RSA, Length:4096, Cert Id:1381862403, Valid from:5/31/17, 6:14 PM, Valid until:5/30/42, 6:14 PM
21:27:33.515 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:4fd22b8ff564c8339e4f345866237060, Subject:CN=UCA Extended Validation Root, O=UniTrust, C=CN, Issuer:CN=UCA Extended Validation Root, O=UniTrust, C=CN, Key type:RSA, Length:4096, Cert Id:649181271, Valid from:3/13/15, 12:00 AM, Valid until:12/31/38, 12:00 AM
21:27:33.516 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withECDSA, Serial:2a38a41c960a04de42b228a50be8349802, Subject:CN=GlobalSign, O=GlobalSign, OU=GlobalSign ECC Root CA - R4, Issuer:CN=GlobalSign, O=GlobalSign, OU=GlobalSign ECC Root CA - R4, Key type:EC, Length:256, Cert Id:-1923273545, Valid from:11/13/12, 12:00 AM, Valid until:1/19/38, 3:14 AM
21:27:33.516 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:33af1e6a711a9a0bb2864b11d09fae5, Subject:CN=DigiCert Global Root G2, OU=www.digicert.com, O=DigiCert Inc, C=US, Issuer:CN=DigiCert Global Root G2, OU=www.digicert.com, O=DigiCert Inc, C=US, Key type:RSA, Length:2048, Cert Id:1136084297, Valid from:8/1/13, 12:00 PM, Valid until:1/15/38, 12:00 PM
21:27:33.517 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:20000b9, Subject:CN=Baltimore CyberTrust Root, OU=CyberTrust, O=Baltimore, C=IE, Issuer:CN=Baltimore CyberTrust Root, OU=CyberTrust, O=Baltimore, C=IE, Key type:RSA, Length:2048, Cert Id:1425294543, Valid from:5/12/00, 6:46 PM, Valid until:5/12/25, 11:59 PM
21:27:33.517 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:0, Subject:OU=Security Communication RootCA2, O="SECOM Trust Systems CO.,LTD.", C=JP, Issuer:OU=Security Communication RootCA2, O="SECOM Trust Systems CO.,LTD.", C=JP, Key type:RSA, Length:2048, Cert Id:1521072570, Valid from:5/29/09, 5:00 AM, Valid until:5/29/29, 5:00 AM
21:27:33.518 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:4000000000121585308a2, Subject:CN=GlobalSign, O=GlobalSign, OU=GlobalSign Root CA - R3, Issuer:CN=GlobalSign, O=GlobalSign, OU=GlobalSign Root CA - R3, Key type:RSA, Length:2048, Cert Id:733875591, Valid from:3/18/09, 10:00 AM, Valid until:3/18/29, 10:00 AM
21:27:33.518 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:75622a4e8d48a894df413c8f0f8eaa5, Subject:CN=Secure Global CA, O=SecureTrust Corporation, C=US, Issuer:CN=Secure Global CA, O=SecureTrust Corporation, C=US, Key type:RSA, Length:2048, Cert Id:-1476772975, Valid from:11/7/06, 7:42 PM, Valid until:12/31/29, 7:52 PM
21:27:33.519 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:8210cfb0d240e3594463e0bb63828b00, Subject:CN=ISRG Root X1, O=Internet Security Research Group, C=US, Issuer:CN=ISRG Root X1, O=Internet Security Research Group, C=US, Key type:RSA, Length:4096, Cert Id:1521974916, Valid from:6/4/15, 11:04 AM, Valid until:6/4/35, 11:04 AM
21:27:33.519 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:2, Subject:CN=Buypass Class 3 Root CA, O=Buypass AS-983163327, C=NO, Issuer:CN=Buypass Class 3 Root CA, O=Buypass AS-983163327, C=NO, Key type:RSA, Length:4096, Cert Id:1264269967, Valid from:10/26/10, 8:28 AM, Valid until:10/26/40, 8:28 AM
21:27:33.520 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:31f5e4620c6c58edd6d8, Subject:CN=emSign Root CA - G1, O=eMudhra Technologies Limited, OU=emSign PKI, C=IN, Issuer:CN=emSign Root CA - G1, O=eMudhra Technologies Limited, OU=emSign PKI, C=IN, Key type:RSA, Length:2048, Cert Id:392709196, Valid from:2/18/18, 6:30 PM, Valid until:2/18/43, 6:30 PM
21:27:33.520 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withRSA, Serial:6d8c1446b1a60aee, Subject:CN=AffirmTrust Premium, O=AffirmTrust, C=US, Issuer:CN=AffirmTrust Premium, O=AffirmTrust, C=US, Key type:RSA, Length:4096, Cert Id:-2130283955, Valid from:1/29/10, 2:10 PM, Valid until:12/31/40, 2:10 PM
21:27:33.521 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:a0142800000014523cf467c00000002, Subject:CN=IdenTrust Public Sector Root CA 1, O=IdenTrust, C=US, Issuer:CN=IdenTrust Public Sector Root CA 1, O=IdenTrust, C=US, Key type:RSA, Length:4096, Cert Id:2123370772, Valid from:1/16/14, 5:53 PM, Valid until:1/16/34, 5:53 PM
21:27:33.521 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:0, Subject:OU=Security Communication RootCA1, O=SECOM Trust.net, C=JP, Issuer:OU=Security Communication RootCA1, O=SECOM Trust.net, C=JP, Key type:RSA, Length:2048, Cert Id:1802358121, Valid from:9/30/03, 4:20 AM, Valid until:9/30/23, 4:20 AM
21:27:33.522 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:445734245b81899b35f2ceb82b3b5ba726f07528, Subject:CN=QuoVadis Root CA 2 G3, O=QuoVadis Limited, C=BM, Issuer:CN=QuoVadis Root CA 2 G3, O=QuoVadis Limited, C=BM, Key type:RSA, Length:4096, Cert Id:696763521, Valid from:1/12/12, 6:59 PM, Valid until:1/12/42, 6:59 PM
21:27:33.522 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:cbe, Subject:CN=TWCA Global Root CA, OU=Root CA, O=TAIWAN-CA, C=TW, Issuer:CN=TWCA Global Root CA, OU=Root CA, O=TAIWAN-CA, C=TW, Key type:RSA, Length:4096, Cert Id:861175838, Valid from:6/27/12, 6:28 AM, Valid until:12/31/30, 3:59 PM
21:27:33.523 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:b931c3ad63967ea6723bfc3af9af44b, Subject:CN=DigiCert Assured ID Root G2, OU=www.digicert.com, O=DigiCert Inc, C=US, Issuer:CN=DigiCert Assured ID Root G2, OU=www.digicert.com, O=DigiCert Inc, C=US, Key type:RSA, Length:2048, Cert Id:-385398383, Valid from:8/1/13, 12:00 PM, Valid until:1/15/38, 12:00 PM
21:27:33.524 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:b0b75a16485fbfe1cbf58bd719e67d, Subject:CN=Izenpe.com, O=IZENPE S.A., C=ES, Issuer:CN=Izenpe.com, O=IZENPE S.A., C=ES, Key type:RSA, Length:4096, Cert Id:-1845580984, Valid from:12/13/07, 1:08 PM, Valid until:12/13/37, 8:27 AM
21:27:33.524 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withECDSA, Serial:6e47a9c76ca9732440890f0355dd8d1d, Subject:CN=GTS Root R3, O=Google Trust Services LLC, C=US, Issuer:CN=GTS Root R3, O=Google Trust Services LLC, C=US, Key type:EC, Length:384, Cert Id:-1415630551, Valid from:6/22/16, 12:00 AM, Valid until:6/22/36, 12:00 AM
21:27:33.525 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:7b2c9bd316803299, Subject:CN=SSL.com Root Certification Authority RSA, O=SSL Corporation, L=Houston, ST=Texas, C=US, Issuer:CN=SSL.com Root Certification Authority RSA, O=SSL Corporation, L=Houston, ST=Texas, C=US, Key type:RSA, Length:4096, Cert Id:156725711, Valid from:2/12/16, 5:39 PM, Valid until:2/12/41, 5:39 PM
21:27:33.526 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:0, Subject:CN=Go Daddy Root Certificate Authority - G2, O="GoDaddy.com, Inc.", L=Scottsdale, ST=Arizona, C=US, Issuer:CN=Go Daddy Root Certificate Authority - G2, O="GoDaddy.com, Inc.", L=Scottsdale, ST=Arizona, C=US, Key type:RSA, Length:2048, Cert Id:439600313, Valid from:9/1/09, 12:00 AM, Valid until:12/31/37, 11:59 PM
21:27:33.526 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA512withRSA, Serial:1ebf5950b8c980374c06f7eb554fb5ed, Subject:CN=Certum Trusted Root CA, OU=Certum Certification Authority, O=Asseco Data Systems S.A., C=PL, Issuer:CN=Certum Trusted Root CA, OU=Certum Certification Authority, O=Asseco Data Systems S.A., C=PL, Key type:RSA, Length:4096, Cert Id:-774327051, Valid from:3/16/18, 12:10 PM, Valid until:3/16/43, 12:10 PM
21:27:33.528 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withECDSA, Serial:62f6326ce5c4e3685c1b62dd9c2e9d95, Subject:CN=AC RAIZ FNMT-RCM SERVIDORES SEGUROS, OID.2.5.4.97=VATES-Q2826004J, OU=Ceres, O=FNMT-RCM, C=ES, Issuer:CN=AC RAIZ FNMT-RCM SERVIDORES SEGUROS, OID.2.5.4.97=VATES-Q2826004J, OU=Ceres, O=FNMT-RCM, C=ES, Key type:EC, Length:384, Cert Id:246315697, Valid from:12/20/18, 9:37 AM, Valid until:12/20/43, 9:37 AM
21:27:33.529 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:15c8bd65475cafb897005ee406d2bc9d, Subject:OU=ePKI Root Certification Authority, O="Chunghwa Telecom Co., Ltd.", C=TW, Issuer:OU=ePKI Root Certification Authority, O="Chunghwa Telecom Co., Ltd.", C=TW, Key type:RSA, Length:4096, Cert Id:-662636137, Valid from:12/20/04, 2:31 AM, Valid until:12/20/34, 2:31 AM
21:27:33.529 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withECDSA, Serial:11d2bbba336ed4bce62468c50d841d98e843, Subject:CN=GlobalSign Root E46, O=GlobalSign nv-sa, C=BE, Issuer:CN=GlobalSign Root E46, O=GlobalSign nv-sa, C=BE, Key type:EC, Length:384, Cert Id:-889363391, Valid from:3/20/19, 12:00 AM, Valid until:3/20/46, 12:00 AM
21:27:33.530 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:5d938d306736c8061d1ac754846907, Subject:OU=AC RAIZ FNMT-RCM, O=FNMT-RCM, C=ES, Issuer:OU=AC RAIZ FNMT-RCM, O=FNMT-RCM, C=ES, Key type:RSA, Length:4096, Cert Id:1555523573, Valid from:10/29/08, 3:59 PM, Valid until:1/1/30, 12:00 AM
21:27:33.531 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withRSA, Serial:4caaf9cadb636fe01ff74ed85b03869d, Subject:CN=COMODO RSA Certification Authority, O=COMODO CA Limited, L=Salford, ST=Greater Manchester, C=GB, Issuer:CN=COMODO RSA Certification Authority, O=COMODO CA Limited, L=Salford, ST=Greater Manchester, C=GB, Key type:RSA, Length:4096, Cert Id:1769425049, Valid from:1/19/10, 12:00 AM, Valid until:1/18/38, 11:59 PM
21:27:33.532 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:cae91b89f155030da3e6416dc4e3a6e1, Subject:CN=Certigna Root CA, OU=0002 48146308100036, O=Dhimyotis, C=FR, Issuer:CN=Certigna Root CA, OU=0002 48146308100036, O=Dhimyotis, C=FR, Key type:RSA, Length:4096, Cert Id:356684591, Valid from:10/1/13, 8:32 AM, Valid until:10/1/33, 8:32 AM
21:27:33.533 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withECDSA, Serial:0, Subject:CN=Hellenic Academic and Research Institutions ECC RootCA 2015, O=Hellenic Academic and Research Institutions Cert. Authority, L=Athens, C=GR, Issuer:CN=Hellenic Academic and Research Institutions ECC RootCA 2015, O=Hellenic Academic and Research Institutions Cert. Authority, L=Athens, C=GR, Key type:EC, Length:384, Cert Id:513613456, Valid from:7/7/15, 10:37 AM, Valid until:6/30/40, 10:37 AM
21:27:33.533 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:400000000010f8626e60d, Subject:CN=GlobalSign, O=GlobalSign, OU=GlobalSign Root CA - R2, Issuer:CN=GlobalSign, O=GlobalSign, OU=GlobalSign Root CA - R2, Key type:RSA, Length:2048, Cert Id:7087067, Valid from:12/15/06, 8:00 AM, Valid until:12/15/21, 8:00 AM
21:27:33.534 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:0, Subject:OU=Go Daddy Class 2 Certification Authority, O="The Go Daddy Group, Inc.", C=US, Issuer:OU=Go Daddy Class 2 Certification Authority, O="The Go Daddy Group, Inc.", C=US, Key type:RSA, Length:2048, Cert Id:-271444299, Valid from:6/29/04, 5:06 PM, Valid until:6/29/34, 5:06 PM
21:27:33.535 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:53ec3beefbb2485f, Subject:CN=Autoridad de Certificacion Firmaprofesional CIF A62634068, C=ES, Issuer:CN=Autoridad de Certificacion Firmaprofesional CIF A62634068, C=ES, Key type:RSA, Length:4096, Cert Id:692250759, Valid from:5/20/09, 8:38 AM, Valid until:12/31/30, 8:38 AM
21:27:33.535 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:1, Subject:CN=TUBITAK Kamu SM SSL Kok Sertifikasi - Surum 1, OU=Kamu Sertifikasyon Merkezi - Kamu SM, O=Turkiye Bilimsel ve Teknolojik Arastirma Kurumu - TUBITAK, L=Gebze - Kocaeli, C=TR, Issuer:CN=TUBITAK Kamu SM SSL Kok Sertifikasi - Surum 1, OU=Kamu Sertifikasyon Merkezi - Kamu SM, O=Turkiye Bilimsel ve Teknolojik Arastirma Kurumu - TUBITAK, L=Gebze - Kocaeli, C=TR, Key type:RSA, Length:2048, Cert Id:1093603654, Valid from:11/25/13, 8:25 AM, Valid until:10/25/43, 8:25 AM
21:27:33.536 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withECDSA, Serial:1f47afaa62007050544c019e9b63992a, Subject:CN=COMODO ECC Certification Authority, O=COMODO CA Limited, L=Salford, ST=Greater Manchester, C=GB, Issuer:CN=COMODO ECC Certification Authority, O=COMODO CA Limited, L=Salford, ST=Greater Manchester, C=GB, Key type:EC, Length:384, Cert Id:1146488932, Valid from:3/6/08, 12:00 AM, Valid until:1/18/38, 11:59 PM
21:27:33.537 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:1, Subject:CN=AAA Certificate Services, O=Comodo CA Limited, L=Salford, ST=Greater Manchester, C=GB, Issuer:CN=AAA Certificate Services, O=Comodo CA Limited, L=Salford, ST=Greater Manchester, C=GB, Key type:RSA, Length:2048, Cert Id:-1197580894, Valid from:1/1/04, 12:00 AM, Valid until:12/31/28, 11:59 PM
21:27:33.538 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withECDSA, Serial:2c299c5b16ed0595, Subject:CN=SSL.com EV Root Certification Authority ECC, O=SSL Corporation, L=Houston, ST=Texas, C=US, Issuer:CN=SSL.com EV Root Certification Authority ECC, O=SSL Corporation, L=Houston, ST=Texas, C=US, Key type:EC, Length:384, Cert Id:1789254518, Valid from:2/12/16, 6:15 PM, Valid until:2/12/41, 6:15 PM
21:27:33.538 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withECDSA, Serial:66c9fd7c1bb104c2943e5717b7b2cc81ac10e, Subject:CN=Amazon Root CA 4, O=Amazon, C=US, Issuer:CN=Amazon Root CA 4, O=Amazon, C=US, Key type:EC, Length:384, Cert Id:-1654272513, Valid from:5/26/15, 12:00 AM, Valid until:5/26/40, 12:00 AM
21:27:33.539 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:200605167002, Subject:OU=certSIGN ROOT CA, O=certSIGN, C=RO, Issuer:OU=certSIGN ROOT CA, O=certSIGN, C=RO, Key type:RSA, Length:2048, Cert Id:-289960676, Valid from:7/4/06, 5:20 PM, Valid until:7/4/31, 5:20 PM
21:27:33.540 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:3e8a5d07ec55d232d5b7e3b65f01eb2ddce4d6e4, Subject:CN=SZAFIR ROOT CA2, O=Krajowa Izba Rozliczeniowa S.A., C=PL, Issuer:CN=SZAFIR ROOT CA2, O=Krajowa Izba Rozliczeniowa S.A., C=PL, Key type:RSA, Length:2048, Cert Id:381279303, Valid from:10/19/15, 7:43 AM, Valid until:10/19/35, 7:43 AM
21:27:33.540 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA384withECDSA, Serial:7b71b68256b8127c9ca8, Subject:CN=emSign ECC Root CA - C3, O=eMudhra Inc, OU=emSign PKI, C=US, Issuer:CN=emSign ECC Root CA - C3, O=eMudhra Inc, OU=emSign PKI, C=US, Key type:EC, Length:384, Cert Id:-948456756, Valid from:2/18/18, 6:30 PM, Valid until:2/18/43, 6:30 PM
21:27:33.541 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA256withRSA, Serial:4a538c28, Subject:CN=Entrust Root Certification Authority - G2, OU="(c) 2009 Entrust, Inc. - for authorized use only", OU=See www.entrust.net/legal-terms, O="Entrust, Inc.", C=US, Issuer:CN=Entrust Root Certification Authority - G2, OU="(c) 2009 Entrust, Inc. - for authorized use only", OU=See www.entrust.net/legal-terms, O="Entrust, Inc.", C=US, Key type:RSA, Length:2048, Cert Id:1936920337, Valid from:7/7/09, 5:25 PM, Valid until:12/7/30, 5:55 PM
21:27:33.541 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:2ac5c266a0b409b8f0b79f2ae462577, Subject:CN=DigiCert High Assurance EV Root CA, OU=www.digicert.com, O=DigiCert Inc, C=US, Issuer:CN=DigiCert High Assurance EV Root CA, OU=www.digicert.com, O=DigiCert Inc, C=US, Key type:RSA, Length:2048, Cert Id:-1410680354, Valid from:11/10/06, 12:00 AM, Valid until:11/10/31, 12:00 AM
21:27:33.542 DEBUG [EventHelper.logX509CertificateEvent] - X509Certificate: Alg:SHA1withRSA, Serial:400000000010f85aa2d48, Subject:CN=Cybertrust Global Root, O="Cybertrust, Inc", Issuer:CN=Cybertrust Global Root, O="Cybertrust, Inc", Key type:RSA, Length:2048, Cert Id:2057719675, Valid from:12/15/06, 8:00 AM, Valid until:12/15/21, 8:00 AM
21:27:33.549 DEBUG [HttpClientImpl.<init>] - [Event Bus Listener Notifier] [219ms] HttpClientImpl(1) proxySelector is sun.net.spi.DefaultProxySelector@7ed04d8e (user-supplied=false)
21:27:33.562 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [232ms] HttpClientImpl(1) next timeout: 0
21:27:33.562 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [232ms] HttpClientImpl(1) next expired: 0
21:27:33.562 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [232ms] HttpClientImpl(1) Next deadline is 3000
21:27:33.571 DEBUG [HttpTracing.inject] - Injecting (GET) /status into OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@6c3f5566, context={}, span id=0000000000000000, trace id=00000000000000000000000000000000} at org.openqa.selenium.grid.node.remote.RemoteNode:211
21:27:33.583 DEBUG [JdkHttpClient.execute] - Executing request: (GET) /status
21:27:33.589 DEBUG [HttpClientImpl.sendAsync] - [Event Bus Listener Notifier] [259ms] HttpClientImpl(1) ClientImpl (async) send http://10.42.0.207:5555/status GET
21:27:33.595 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [265ms] HttpClientImpl(1) next timeout: 179999
21:27:33.595 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [265ms] HttpClientImpl(1) next expired: 0
21:27:33.595 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [265ms] HttpClientImpl(1) Next deadline is 3000
21:27:33.596 DEBUG [Exchange.establishExchange] - [Event Bus Listener Notifier] [265ms] Exchange establishing exchange for http://10.42.0.207:5555/status GET,
     proxy=null
21:27:33.607 DEBUG [Http2ClientImpl.getConnectionFor] - [Event Bus Listener Notifier] [277ms] Http2ClientImpl not found in connection pool
21:27:33.607 DEBUG [ExchangeImpl.get] - [Event Bus Listener Notifier] [277ms] ExchangeImpl get: Trying to get HTTP/2 connection
21:27:33.607 DEBUG [ExchangeImpl.createExchangeImpl] - [Event Bus Listener Notifier] [277ms] ExchangeImpl handling HTTP/2 connection creation result
21:27:33.607 DEBUG [ExchangeImpl.createExchangeImpl] - [Event Bus Listener Notifier] [277ms] ExchangeImpl new Http1Exchange, try to upgrade
21:27:33.613 DEBUG [PlainHttpConnection.<init>] - [Event Bus Listener Notifier] [283ms] PlainHttpConnection(?) Initial receive buffer size is: 65536
21:27:33.619 DEBUG [Exchange.checkFor407] - [Event Bus Listener Notifier] [289ms] Exchange checkFor407: all clear
21:27:33.619 DEBUG [Http1Exchange.sendHeadersAsync] - [Event Bus Listener Notifier] [289ms] Http1Exchange Sending headers only
21:27:33.627 DEBUG [Http1AsyncReceiver.subscribe] - [Event Bus Listener Notifier] [297ms] Http1AsyncReceiver(SocketTube(1)) Subscribed pending jdk.internal.net.http.Http1Response$HeadersReader@7627a18b queue.isEmpty: true
21:27:33.633 DEBUG [Http1AsyncReceiver.handlePendingDelegate] - [Event Bus Listener Notifier] [303ms] Http1AsyncReceiver(SocketTube(1)) delegate is now jdk.internal.net.http.Http1Response$HeadersReader@7627a18b, demand=1, canRequestMore=true, queue.isEmpty=true
21:27:33.633 DEBUG [Http1AsyncReceiver.hasDemand] - [Event Bus Listener Notifier] [303ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1
21:27:33.637 DEBUG [Http1AsyncReceiver.checkRequestMore] - [Event Bus Listener Notifier] [306ms] Http1AsyncReceiver(SocketTube(1)) checkRequestMore: canRequestMore=true, hasDemand=true
21:27:33.637 DEBUG [Http1AsyncReceiver.hasDemand] - [Event Bus Listener Notifier] [307ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1
21:27:33.637 DEBUG [Http1AsyncReceiver.checkRequestMore] - [Event Bus Listener Notifier] [307ms] Http1AsyncReceiver(SocketTube(1)) checkRequestMore: canRequestMore=true, hasDemand=true
21:27:33.637 DEBUG [Http1Exchange.sendHeadersAsync] - [Event Bus Listener Notifier] [307ms] Http1Exchange response created in advance
21:27:33.637 DEBUG [Http1Exchange.sendHeadersAsync] - [Event Bus Listener Notifier] [307ms] Http1Exchange initiating connect async
21:27:33.647 DEBUG [PlainHttpConnection.connectAsync] - [Event Bus Listener Notifier] [317ms] PlainHttpConnection(SocketTube(1)) registering connect timer: ConnectTimerEvent, TimeoutEvent[id=2, duration=PT10S, deadline=2023-03-13T21:27:43.638166Z]
21:27:33.647 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [317ms] HttpClientImpl(1) next timeout: 9991
21:27:33.648 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [317ms] HttpClientImpl(1) next expired: 0
21:27:33.648 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [318ms] HttpClientImpl(1) Next deadline is 3000
21:27:33.649 DEBUG [PlainHttpConnection.connectAsync] - [Event Bus Listener Notifier] [319ms] PlainHttpConnection(SocketTube(1)) registering connect event
21:27:33.650 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-1-SelectorManager] [319ms] SelectorAttachment Registering jdk.internal.net.http.PlainHttpConnection$ConnectEvent@6f4b97d1 for 8 (true)
21:27:33.651 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [321ms] HttpClientImpl(1) next timeout: 9987
21:27:33.651 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [321ms] HttpClientImpl(1) next expired: 0
21:27:33.651 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [321ms] HttpClientImpl(1) Next deadline is 3000
21:27:33.652 DEBUG [PlainHttpConnection$ConnectEvent.handle] - [HttpClient-1-SelectorManager] [322ms] PlainHttpConnection(SocketTube(1)) ConnectEvent: finishing connect
21:27:33.652 DEBUG [PlainHttpConnection$ConnectEvent.handle] - [HttpClient-1-SelectorManager] [322ms] PlainHttpConnection(SocketTube(1)) ConnectEvent: connect finished: true Local addr: /10.42.0.210:51538
21:27:33.653 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [323ms] HttpClientImpl(1) next timeout: 9985
21:27:33.653 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [323ms] HttpClientImpl(1) next expired: 0
21:27:33.654 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [323ms] HttpClientImpl(1) Next deadline is 3000
21:27:33.654 DEBUG [PlainHttpConnection.finishConnect] - [pool-2-thread-1] [324ms] PlainHttpConnection(SocketTube(1)) finishConnect, setting connected=true
21:27:33.654 DEBUG [Http1Exchange.connectFlows] - [pool-2-thread-1] [324ms] Http1Exchange SocketTube(1) connecting flows
21:27:33.655 DEBUG [SocketTube.connectFlows] - [pool-2-thread-1] [324ms] SocketTube(1) connecting flows
21:27:33.655 DEBUG [SocketTube$InternalReadPublisher.subscribe] - [pool-2-thread-1] [325ms] SocketTube(1) read publisher got subscriber
21:27:33.655 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalSubscribe] - [pool-2-thread-1] [325ms] SocketTube(1) registering subscribe event
21:27:33.655 DEBUG [SocketTube.debugState] - [pool-2-thread-1] [325ms] SocketTube(1) leaving read.subscribe:  Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=0]
21:27:33.656 DEBUG [Http1Exchange$Http1Publisher.subscribe] - [pool-2-thread-1] [326ms] Http1Publisher(SocketTube(1)) got subscriber: SocketTube(1)
21:27:33.656 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-2-thread-1] [326ms] SocketTube(1) subscribed for writing
21:27:33.656 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-2-thread-1] [326ms] SocketTube(1) write: registering startSubscription event
21:27:33.656 DEBUG [Http1Exchange.lambda$sendHeadersAsync$4] - [pool-2-thread-1] [326ms] Http1Exchange requestAction.headers
21:27:33.658 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handleSubscribeEvent] - [HttpClient-1-SelectorManager] [328ms] SocketTube(1) subscribe event raised
21:27:33.658 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-1-SelectorManager] [328ms] SocketTube(1) handling pending subscription for jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber@52a6e7b
21:27:33.658 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-1-SelectorManager] [328ms] SocketTube(1) read demand reset to 0
21:27:33.658 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-1-SelectorManager] [328ms] SocketTube(1) calling onSubscribe
21:27:33.658 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.onSubscribe] - [HttpClient-1-SelectorManager] [328ms] Http1AsyncReceiver(SocketTube(1)) Received onSubscribed from upstream
21:27:33.659 DEBUG [SocketTube$InternalReadPublisher$ReadSubscription.signalOnSubscribe] - [HttpClient-1-SelectorManager] [328ms] SocketTube(1) onSubscribe called
21:27:33.659 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-2-thread-2] [329ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1
21:27:33.659 DEBUG [Http1AsyncReceiver.checkRequestMore] - [pool-2-thread-2] [329ms] Http1AsyncReceiver(SocketTube(1)) checkRequestMore: canRequestMore=true, hasDemand=true
21:27:33.659 DEBUG [Http1Exchange.lambda$sendHeadersAsync$4] - [pool-2-thread-1] [329ms] Http1Exchange setting outgoing with headers
21:27:33.659 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.requestMore] - [pool-2-thread-2] [329ms] Http1AsyncReceiver(SocketTube(1)) Http1TubeSubscriber: requesting one more from upstream
21:27:33.659 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.request] - [pool-2-thread-2] [329ms] SocketTube(1) got some demand for reading
21:27:33.659 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [pool-2-thread-2] [329ms] SocketTube(1) resuming read event
21:27:33.661 DEBUG [SocketTube.debugState] - [pool-2-thread-2] [330ms] SocketTube(1) leaving request(1):  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=0]
21:27:33.659 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-1-SelectorManager] [329ms] SocketTube(1) pending subscriber subscribed
21:27:33.663 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-1-SelectorManager] [333ms] SocketTube(1) write: starting subscription
21:27:33.663 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-1-SelectorManager] [333ms] SocketTube(1) write: offloading requestMore
21:27:33.664 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [334ms] HttpClientImpl(1) next timeout: 179930
21:27:33.664 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [334ms] HttpClientImpl(1) next expired: 0
21:27:33.664 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [334ms] HttpClientImpl(1) Next deadline is 3000
21:27:33.664 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-2-thread-2] [334ms] SocketTube(1) write: requesting more...
21:27:33.665 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-1-SelectorManager] [334ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@4096dfcf for 1 (true)
21:27:33.665 DEBUG [Http1Exchange$Http1Publisher$Http1WriteSubscription.request] - [pool-2-thread-2] [335ms] Http1Publisher(SocketTube(1)) subscription request(1), demand=1
21:27:33.665 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-2-thread-2] [335ms] Http1Publisher(SocketTube(1)) WriteTask
21:27:33.665 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [335ms] HttpClientImpl(1) next timeout: 179929
21:27:33.665 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [335ms] HttpClientImpl(1) next expired: 0
21:27:33.665 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [335ms] HttpClientImpl(1) Next deadline is 3000
21:27:33.665 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-2-thread-2] [335ms] Http1Publisher(SocketTube(1)) hasOutgoing = false
21:27:33.666 DEBUG [SocketTube.debugState] - [pool-2-thread-2] [335ms] SocketTube(1) leaving requestMore:  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
21:27:33.667 DEBUG [Http1Exchange.appendToOutgoing] - [pool-2-thread-1] [337ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=286 cap=286]], throwable=null]
21:27:33.667 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-2-thread-1] [337ms] Http1Publisher(SocketTube(1)) WriteTask
21:27:33.667 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-2-thread-1] [337ms] Http1Publisher(SocketTube(1)) hasOutgoing = true
21:27:33.668 DEBUG [Http1Exchange.getOutgoing] - [pool-2-thread-1] [338ms] Http1Exchange initiating completion of headersSentCF
21:27:33.668 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-2-thread-1] [338ms] Http1Publisher(SocketTube(1)) onNext with 286 bytes
21:27:33.669 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [pool-2-thread-1] [339ms] SocketTube(1) trying to write: 286
21:27:33.670 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [pool-2-thread-1] [339ms] SocketTube(1) wrote: 286
21:27:33.670 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-2-thread-1] [340ms] SocketTube(1) write: requesting more...
21:27:33.670 DEBUG [Http1Exchange$Http1Publisher$Http1WriteSubscription.request] - [pool-2-thread-1] [340ms] Http1Publisher(SocketTube(1)) subscription request(1), demand=1
21:27:33.670 DEBUG [SocketTube.debugState] - [pool-2-thread-1] [340ms] SocketTube(1) leaving requestMore:  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
21:27:33.670 DEBUG [SocketTube.debugState] - [pool-2-thread-1] [340ms] SocketTube(1) leaving w.onNext Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
21:27:33.670 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-2-thread-1] [340ms] Http1Publisher(SocketTube(1)) WriteTask
21:27:33.670 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-2-thread-1] [340ms] Http1Publisher(SocketTube(1)) hasOutgoing = false
21:27:33.670 DEBUG [Exchange.checkFor407] - [pool-2-thread-1] [340ms] Exchange checkFor407: all clear
21:27:33.671 DEBUG [Exchange.sendRequestBody] - [pool-2-thread-1] [341ms] Exchange sendRequestBody
21:27:33.671 DEBUG [Http1Exchange.sendBodyAsync] - [pool-2-thread-1] [341ms] Http1Exchange sendBodyAsync
21:27:33.671 DEBUG [Http1Exchange.sendBodyAsync] - [pool-2-thread-1] [341ms] Http1Exchange bodySubscriber is null
21:27:33.671 DEBUG [Http1Exchange.appendToOutgoing] - [pool-2-thread-1] [341ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]], throwable=null]
21:27:33.671 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-2-thread-1] [341ms] Http1Publisher(SocketTube(1)) WriteTask
21:27:33.671 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-2-thread-1] [341ms] Http1Publisher(SocketTube(1)) hasOutgoing = true
21:27:33.672 DEBUG [Http1Exchange.getOutgoing] - [pool-2-thread-1] [341ms] Http1Exchange initiating completion of bodySentCF
21:27:33.672 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-2-thread-1] [342ms] Http1Publisher(SocketTube(1)) completed, stopping jdk.internal.net.http.common.SequentialScheduler@93b4192
21:27:33.672 DEBUG [Utils.lambda$wrapForDebug$8] - [pool-2-thread-1] [342ms] Http1Exchange sendBodyAsync completed successfully
21:27:33.673 DEBUG [Http1Exchange.getResponseAsync] - [pool-2-thread-1] [343ms] Http1Exchange reading headers
21:27:33.680 DEBUG [Http1Response.readHeadersAsync] - [pool-2-thread-1] [350ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) Reading Headers: (remaining: 0) READING_HEADERS
21:27:33.680 DEBUG [Http1Response.readHeadersAsync] - [pool-2-thread-1] [350ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) First time around
21:27:33.680 DEBUG [Http1Response.readHeadersAsync] - [pool-2-thread-1] [350ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) headersReader is not yet completed
21:27:33.908 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-1-SelectorManager] [578ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@4096dfcf for 0 (false)
21:27:33.912 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-1-SelectorManager] [582ms] SocketTube(1) read bytes: 973
21:27:33.912 DEBUG [Http1AsyncReceiver.asyncReceive] - [HttpClient-1-SelectorManager] [582ms] Http1AsyncReceiver(SocketTube(1)) Putting 973 bytes into the queue
21:27:33.913 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [HttpClient-1-SelectorManager] [583ms] SocketTube(1) resuming read event
21:27:33.913 DEBUG [Http1AsyncReceiver.flush] - [pool-2-thread-1] [583ms] Http1AsyncReceiver(SocketTube(1)) Got 973 bytes for delegate jdk.internal.net.http.Http1Response$HeadersReader@7627a18b
21:27:33.913 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-1-SelectorManager] [583ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@4096dfcf for 1 (false)
21:27:33.914 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-2-thread-1] [583ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1
21:27:33.914 DEBUG [SocketTube.debugState] - [HttpClient-1-SelectorManager] [584ms] SocketTube(1) leaving read() loop after onNext:  Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
21:27:33.914 DEBUG [Http1AsyncReceiver.flush] - [pool-2-thread-1] [584ms] Http1AsyncReceiver(SocketTube(1)) Forwarding 973 bytes to delegate jdk.internal.net.http.Http1Response$HeadersReader@7627a18b
21:27:33.914 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [584ms] HttpClientImpl(1) next timeout: 179680
21:27:33.914 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [584ms] HttpClientImpl(1) next expired: 0
21:27:33.915 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [585ms] HttpClientImpl(1) Next deadline is 3000
21:27:33.919 DEBUG [Http1Response$HeadersReader.handle] - [pool-2-thread-1] [589ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) Sending 973/973 bytes to header parser
21:27:33.920 DEBUG [Http1Response$HeadersReader.handle] - [pool-2-thread-1] [590ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) Parsing headers completed. bytes=40
21:27:33.921 DEBUG [Http1AsyncReceiver.unsubscribe] - [pool-2-thread-1] [591ms] Http1AsyncReceiver(SocketTube(1)) Unsubscribed jdk.internal.net.http.Http1Response$HeadersReader@7627a18b
21:27:33.922 DEBUG [Http1Response.lambda$readHeadersAsync$0] - [pool-2-thread-1] [592ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) Reading Headers: creating Response object; state is now READING_BODY
21:27:33.922 DEBUG [Utils.lambda$wrapForDebug$8] - [pool-2-thread-1] [592ms] Http1Exchange getResponseAsync completed successfully
21:27:33.925 DEBUG [Http1Response.readBody] - [pool-2-thread-1] [595ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) readBody: return2Cache: true
21:27:33.937 DEBUG [Http1Response$ClientRefCountTracker.acquire] - [pool-2-thread-1] [607ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) Operation started: incrementing ref count for jdk.internal.net.http.HttpClientImpl@2efc70aa(1)
21:27:33.939 DEBUG [Http1AsyncReceiver.subscribe] - [pool-2-thread-1] [609ms] Http1AsyncReceiver(SocketTube(1)) Subscribed pending jdk.internal.net.http.Http1Response$BodyReader@57541e5a/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@22184d66 queue.isEmpty: false
21:27:33.954 DEBUG [Http1AsyncReceiver.flush] - [pool-2-thread-1] [623ms] Http1AsyncReceiver(SocketTube(1)) Delegate done: 933
21:27:33.955 DEBUG [ResponseContent$FixedLengthBodyParser.onSubscribe] - [pool-2-thread-1] [625ms] PlainHttpConnection(SocketTube(1))/ResponseContent/FixedLengthBodyParser length=933, onSubscribe: jdk.internal.net.http.Http1Response$Http1BodySubscriber
21:27:33.955 DEBUG [Http1AsyncReceiver.handlePendingDelegate] - [pool-2-thread-1] [625ms] Http1AsyncReceiver(SocketTube(1)) delegate is now jdk.internal.net.http.Http1Response$BodyReader@57541e5a/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@22184d66, demand=9223372036854775807, canRequestMore=false, queue.isEmpty=false
21:27:33.956 DEBUG [Http1AsyncReceiver.flush] - [pool-2-thread-1] [626ms] Http1AsyncReceiver(SocketTube(1)) Got 933 bytes for delegate jdk.internal.net.http.Http1Response$BodyReader@57541e5a/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@22184d66
21:27:33.956 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-2-thread-1] [626ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 9223372036854775807
21:27:33.956 DEBUG [Http1AsyncReceiver.flush] - [pool-2-thread-1] [626ms] Http1AsyncReceiver(SocketTube(1)) Forwarding 933 bytes to delegate jdk.internal.net.http.Http1Response$BodyReader@57541e5a/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@22184d66
21:27:33.957 DEBUG [Http1Response$BodyReader.handle] - [pool-2-thread-1] [627ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) Sending 933/973 bytes to body parser
21:27:33.957 DEBUG [ResponseContent$FixedLengthBodyParser.accept] - [pool-2-thread-1] [627ms] PlainHttpConnection(SocketTube(1))/ResponseContent/FixedLengthBodyParser Parser got 933 bytes (933 remaining / 933)
21:27:33.958 DEBUG [ResponseContent$FixedLengthBodyParser.accept] - [pool-2-thread-1] [628ms] PlainHttpConnection(SocketTube(1))/ResponseContent/FixedLengthBodyParser Parser got all expected bytes: completing
21:27:33.958 DEBUG [Http1AsyncReceiver.clear] - [pool-2-thread-1] [628ms] Http1AsyncReceiver(SocketTube(1)) cleared
21:27:33.958 DEBUG [Http1Response.onFinished] - [pool-2-thread-1] [628ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) SocketTube(1): return to HTTP/1.1 pool
21:27:33.960 DEBUG [ConnectionPool.registerCleanupTrigger] - [pool-2-thread-1] [630ms] ConnectionPool(1) registering CleanupTrigger(SocketTube(1))
21:27:33.961 DEBUG [SocketTube.connectFlows] - [pool-2-thread-1] [631ms] SocketTube(1) connecting flows
21:27:33.961 DEBUG [SocketTube$InternalReadPublisher.subscribe] - [pool-2-thread-1] [631ms] SocketTube(1) read publisher got subscriber
21:27:33.961 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalSubscribe] - [pool-2-thread-1] [631ms] SocketTube(1) registering subscribe event
21:27:33.961 DEBUG [SocketTube.debugState] - [pool-2-thread-1] [631ms] SocketTube(1) leaving read.subscribe:  Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
21:27:33.961 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-2-thread-1] [631ms] SocketTube(1) subscribed for writing
21:27:33.961 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handleSubscribeEvent] - [HttpClient-1-SelectorManager] [631ms] SocketTube(1) subscribe event raised
21:27:33.962 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-1-SelectorManager] [632ms] SocketTube(1) handling pending subscription for CleanupTrigger(SocketTube(1))
21:27:33.962 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.dropSubscription] - [HttpClient-1-SelectorManager] [632ms] Http1AsyncReceiver(SocketTube(1)) Http1TubeSubscriber: dropSubscription
21:27:33.963 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-1-SelectorManager] [633ms] SocketTube(1) read demand reset to 0
21:27:33.963 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-1-SelectorManager] [633ms] SocketTube(1) calling onSubscribe
21:27:33.963 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.request] - [HttpClient-1-SelectorManager] [633ms] SocketTube(1) got some demand for reading
21:27:33.963 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [HttpClient-1-SelectorManager] [633ms] SocketTube(1) resuming read event
21:27:33.963 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-1-SelectorManager] [633ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@4096dfcf for 1 (false)
21:27:33.963 DEBUG [SocketTube.debugState] - [HttpClient-1-SelectorManager] [633ms] SocketTube(1) leaving request(1):  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
21:27:33.964 DEBUG [SocketTube$InternalReadPublisher$ReadSubscription.signalOnSubscribe] - [HttpClient-1-SelectorManager] [633ms] SocketTube(1) onSubscribe called
21:27:33.964 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-1-SelectorManager] [634ms] SocketTube(1) pending subscriber subscribed
21:27:33.964 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [634ms] HttpClientImpl(1) next timeout: 0
21:27:33.964 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [634ms] HttpClientImpl(1) next expired: 0
21:27:33.964 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [634ms] HttpClientImpl(1) Next deadline is 3000
21:27:33.962 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.dropSubscription] - [pool-2-thread-1] [631ms] SocketTube(1) write: resetting demand to 0
21:27:33.965 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-2-thread-1] [634ms] SocketTube(1) write: registering startSubscription event
21:27:33.966 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-1-SelectorManager] [636ms] SocketTube(1) write: starting subscription
21:27:33.966 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-1-SelectorManager] [636ms] SocketTube(1) write: offloading requestMore
21:27:33.967 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [637ms] HttpClientImpl(1) next timeout: 0
21:27:33.967 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-2-thread-2] [637ms] SocketTube(1) write: requesting more...
21:27:33.968 DEBUG [SocketTube.debugState] - [pool-2-thread-2] [638ms] SocketTube(1) leaving requestMore:  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
21:27:33.968 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [637ms] HttpClientImpl(1) next expired: 1199033
21:27:33.969 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [639ms] HttpClientImpl(1) Next deadline is 3000
21:27:33.968 DEBUG [Http1Response.lambda$readBody$2] - [pool-2-thread-1] [638ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) Finished reading body: READING_BODY
21:27:33.969 DEBUG [Http1Response$ClientRefCountTracker.tryRelease] - [pool-2-thread-1] [639ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) Operation finished: decrementing ref count for jdk.internal.net.http.HttpClientImpl@2efc70aa(1)
21:27:33.970 DEBUG [Http1AsyncReceiver.flush] - [pool-2-thread-1] [640ms] Http1AsyncReceiver(SocketTube(1)) Delegate done: 0
21:27:33.970 DEBUG [Http1AsyncReceiver.flush] - [pool-2-thread-1] [640ms] Http1AsyncReceiver(SocketTube(1)) Got 0 bytes for delegate null
21:27:33.972 DEBUG [JdkHttpClient.execute] - Ending request (GET) /status in 388ms
21:27:33.976 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=38f0220fd8612637fb3b0d4c41b9f213, spanId=1f6a88569fd0aef0, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.16.0, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.22.0"}}, instrumentationScopeInfo=InstrumentationScopeInfo{name=default, version=null, schemaUrl=null, attributes={}}, name=httpclient.execute, kind=INTERNAL, startEpochNanos=1678742853578000000, endEpochNanos=1678742853972274210, attributes=AttributesMap{data={http.method=GET, http.status_code=200, span.kind=client, http.target=/status}, capacity=128, totalAddedValues=4}, totalAttributeCount=4, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=OK, description=Kind: OK Description:}, hasEnded=true}
21:27:33.983 DEBUG [GridModel.add] - Adding node with id ea2f95c6-5431-4a92-a83d-f0f1b97ec33b and URI http://10.42.0.207:5555
21:27:33.985 DEBUG [LocalDistributor.updateNodeAvailability] - Health check result for http://10.42.0.207:5555 was UP
21:27:33.987 INFO [GridModel.setAvailability] - Switching Node ea2f95c6-5431-4a92-a83d-f0f1b97ec33b (uri: http://10.42.0.207:5555) from DOWN to UP
21:27:33.987 INFO [LocalDistributor.add] - Added node ea2f95c6-5431-4a92-a83d-f0f1b97ec33b at http://10.42.0.207:5555. Health check every 120s
21:27:33.998 INFO [Node.<init>] - Binding additional locator mechanisms: relative
21:27:34.002 DEBUG [HttpClientImpl.<init>] - [Event Bus Listener Notifier] [672ms] HttpClientImpl(2) proxySelector is sun.net.spi.DefaultProxySelector@7ed04d8e (user-supplied=false)
21:27:34.003 DEBUG [HttpTracing.inject] - Injecting (GET) /status into OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@6c3f5566, context={}, span id=0000000000000000, trace id=00000000000000000000000000000000} at org.openqa.selenium.grid.node.remote.RemoteNode:211
21:27:34.012 DEBUG [JdkHttpClient.execute] - Executing request: (GET) /status
21:27:34.016 DEBUG [HttpClientImpl.sendAsync] - [Event Bus Listener Notifier] [686ms] HttpClientImpl(2) ClientImpl (async) send http://10.42.0.208:5555/status GET
21:27:34.011 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [681ms] HttpClientImpl(2) next timeout: 0
21:27:34.017 DEBUG [Exchange.establishExchange] - [Event Bus Listener Notifier] [687ms] Exchange establishing exchange for http://10.42.0.208:5555/status GET,
     proxy=null
21:27:34.018 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [687ms] HttpClientImpl(2) next expired: 0
21:27:34.018 DEBUG [Http2ClientImpl.getConnectionFor] - [Event Bus Listener Notifier] [687ms] Http2ClientImpl not found in connection pool
21:27:34.018 DEBUG [ExchangeImpl.get] - [Event Bus Listener Notifier] [688ms] ExchangeImpl get: Trying to get HTTP/2 connection
21:27:34.018 DEBUG [ExchangeImpl.createExchangeImpl] - [Event Bus Listener Notifier] [688ms] ExchangeImpl handling HTTP/2 connection creation result
21:27:34.018 DEBUG [ExchangeImpl.createExchangeImpl] - [Event Bus Listener Notifier] [688ms] ExchangeImpl new Http1Exchange, try to upgrade
21:27:34.018 DEBUG [PlainHttpConnection.<init>] - [Event Bus Listener Notifier] [688ms] PlainHttpConnection(?) Initial receive buffer size is: 65536
21:27:34.018 DEBUG [Exchange.checkFor407] - [Event Bus Listener Notifier] [688ms] Exchange checkFor407: all clear
21:27:34.018 DEBUG [Http1Exchange.sendHeadersAsync] - [Event Bus Listener Notifier] [688ms] Http1Exchange Sending headers only
21:27:34.018 DEBUG [Http1AsyncReceiver.subscribe] - [Event Bus Listener Notifier] [688ms] Http1AsyncReceiver(SocketTube(2)) Subscribed pending jdk.internal.net.http.Http1Response$HeadersReader@822a5cc queue.isEmpty: true
21:27:34.018 DEBUG [Http1AsyncReceiver.handlePendingDelegate] - [Event Bus Listener Notifier] [688ms] Http1AsyncReceiver(SocketTube(2)) delegate is now jdk.internal.net.http.Http1Response$HeadersReader@822a5cc, demand=1, canRequestMore=true, queue.isEmpty=true
21:27:34.019 DEBUG [Http1AsyncReceiver.hasDemand] - [Event Bus Listener Notifier] [688ms] Http1AsyncReceiver(SocketTube(2)) downstream subscription demand is 1
21:27:34.019 DEBUG [Http1AsyncReceiver.checkRequestMore] - [Event Bus Listener Notifier] [688ms] Http1AsyncReceiver(SocketTube(2)) checkRequestMore: canRequestMore=true, hasDemand=true
21:27:34.019 DEBUG [Http1AsyncReceiver.hasDemand] - [Event Bus Listener Notifier] [689ms] Http1AsyncReceiver(SocketTube(2)) downstream subscription demand is 1
21:27:34.019 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [689ms] HttpClientImpl(2) Next deadline is 3000
21:27:34.019 DEBUG [Http1AsyncReceiver.checkRequestMore] - [Event Bus Listener Notifier] [689ms] Http1AsyncReceiver(SocketTube(2)) checkRequestMore: canRequestMore=true, hasDemand=true
21:27:34.020 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [689ms] HttpClientImpl(2) next timeout: 179998
21:27:34.020 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [690ms] HttpClientImpl(2) next expired: 0
21:27:34.020 DEBUG [Http1Exchange.sendHeadersAsync] - [Event Bus Listener Notifier] [689ms] Http1Exchange response created in advance
21:27:34.020 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [690ms] HttpClientImpl(2) Next deadline is 3000
21:27:34.020 DEBUG [Http1Exchange.sendHeadersAsync] - [Event Bus Listener Notifier] [690ms] Http1Exchange initiating connect async
21:27:34.020 DEBUG [PlainHttpConnection.connectAsync] - [Event Bus Listener Notifier] [690ms] PlainHttpConnection(SocketTube(2)) registering connect timer: ConnectTimerEvent, TimeoutEvent[id=4, duration=PT10S, deadline=2023-03-13T21:27:44.020621Z]
21:27:34.021 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [690ms] HttpClientImpl(2) next timeout: 10000
21:27:34.021 DEBUG [PlainHttpConnection.connectAsync] - [Event Bus Listener Notifier] [691ms] PlainHttpConnection(SocketTube(2)) registering connect event
21:27:34.021 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [691ms] HttpClientImpl(2) next expired: 0
21:27:34.021 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [691ms] HttpClientImpl(2) Next deadline is 3000
21:27:34.021 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-2-SelectorManager] [691ms] SelectorAttachment Registering jdk.internal.net.http.PlainHttpConnection$ConnectEvent@15b3c368 for 8 (true)
21:27:34.021 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [691ms] HttpClientImpl(2) next timeout: 9999
21:27:34.021 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [691ms] HttpClientImpl(2) next expired: 0
21:27:34.022 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [692ms] HttpClientImpl(2) Next deadline is 3000
21:27:34.022 DEBUG [PlainHttpConnection$ConnectEvent.handle] - [HttpClient-2-SelectorManager] [692ms] PlainHttpConnection(SocketTube(2)) ConnectEvent: finishing connect
21:27:34.022 DEBUG [PlainHttpConnection$ConnectEvent.handle] - [HttpClient-2-SelectorManager] [692ms] PlainHttpConnection(SocketTube(2)) ConnectEvent: connect finished: true Local addr: /10.42.0.210:40412
21:27:34.023 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [693ms] HttpClientImpl(2) next timeout: 9997
21:27:34.023 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [693ms] HttpClientImpl(2) next expired: 0
21:27:34.023 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [693ms] HttpClientImpl(2) Next deadline is 3000
21:27:34.023 DEBUG [PlainHttpConnection.finishConnect] - [pool-3-thread-1] [693ms] PlainHttpConnection(SocketTube(2)) finishConnect, setting connected=true
21:27:34.023 DEBUG [Http1Exchange.connectFlows] - [pool-3-thread-1] [693ms] Http1Exchange SocketTube(2) connecting flows
21:27:34.023 DEBUG [SocketTube.connectFlows] - [pool-3-thread-1] [693ms] SocketTube(2) connecting flows
21:27:34.023 DEBUG [SocketTube$InternalReadPublisher.subscribe] - [pool-3-thread-1] [693ms] SocketTube(2) read publisher got subscriber
21:27:34.024 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalSubscribe] - [pool-3-thread-1] [693ms] SocketTube(2) registering subscribe event
21:27:34.024 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handleSubscribeEvent] - [HttpClient-2-SelectorManager] [694ms] SocketTube(2) subscribe event raised
21:27:34.024 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-2-SelectorManager] [694ms] SocketTube(2) handling pending subscription for jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber@5a492595
21:27:34.024 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-2-SelectorManager] [694ms] SocketTube(2) read demand reset to 0
21:27:34.024 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-2-SelectorManager] [694ms] SocketTube(2) calling onSubscribe
21:27:34.024 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.onSubscribe] - [HttpClient-2-SelectorManager] [694ms] Http1AsyncReceiver(SocketTube(2)) Received onSubscribed from upstream
21:27:34.024 DEBUG [SocketTube.debugState] - [pool-3-thread-1] [694ms] SocketTube(2) leaving read.subscribe:  Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=0]
21:27:34.024 DEBUG [Http1Exchange$Http1Publisher.subscribe] - [pool-3-thread-1] [694ms] Http1Publisher(SocketTube(2)) got subscriber: SocketTube(2)
21:27:34.024 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-3-thread-1] [694ms] SocketTube(2) subscribed for writing
21:27:34.025 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-3-thread-1] [694ms] SocketTube(2) write: registering startSubscription event
21:27:34.025 DEBUG [Http1Exchange.lambda$sendHeadersAsync$4] - [pool-3-thread-1] [694ms] Http1Exchange requestAction.headers
21:27:34.025 DEBUG [Http1Exchange.lambda$sendHeadersAsync$4] - [pool-3-thread-1] [695ms] Http1Exchange setting outgoing with headers
21:27:34.025 DEBUG [SocketTube$InternalReadPublisher$ReadSubscription.signalOnSubscribe] - [HttpClient-2-SelectorManager] [695ms] SocketTube(2) onSubscribe called
21:27:34.025 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-2-SelectorManager] [695ms] SocketTube(2) pending subscriber subscribed
21:27:34.025 DEBUG [Http1Exchange.appendToOutgoing] - [pool-3-thread-1] [695ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=286 cap=286]], throwable=null]
21:27:34.026 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [696ms] HttpClientImpl(2) next timeout: 179991
21:27:34.026 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-3-thread-1] [696ms] Http1Publisher(SocketTube(2)) WriteTask
21:27:34.026 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-3-thread-1] [696ms] Http1Publisher(SocketTube(2)) hasOutgoing = true
21:27:34.026 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [696ms] HttpClientImpl(2) next expired: 0
21:27:34.027 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [696ms] HttpClientImpl(2) Next deadline is 3000
21:27:34.027 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-3-thread-2] [697ms] Http1AsyncReceiver(SocketTube(2)) downstream subscription demand is 1
21:27:34.027 DEBUG [Http1AsyncReceiver.checkRequestMore] - [pool-3-thread-2] [697ms] Http1AsyncReceiver(SocketTube(2)) checkRequestMore: canRequestMore=true, hasDemand=true
21:27:34.027 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.requestMore] - [pool-3-thread-2] [697ms] Http1AsyncReceiver(SocketTube(2)) Http1TubeSubscriber: requesting one more from upstream
21:27:34.027 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.request] - [pool-3-thread-2] [697ms] SocketTube(2) got some demand for reading
21:27:34.027 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [pool-3-thread-2] [697ms] SocketTube(2) resuming read event
21:27:34.027 DEBUG [SocketTube.debugState] - [pool-3-thread-2] [697ms] SocketTube(2) leaving request(1):  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=0]
21:27:34.027 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-2-SelectorManager] [697ms] SocketTube(2) write: starting subscription
21:27:34.028 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-2-SelectorManager] [698ms] SocketTube(2) write: offloading requestMore
21:27:34.028 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-3-thread-2] [698ms] SocketTube(2) write: requesting more...
21:27:34.028 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [698ms] HttpClientImpl(2) next timeout: 179989
21:27:34.028 DEBUG [Http1Exchange$Http1Publisher$Http1WriteSubscription.request] - [pool-3-thread-2] [698ms] Http1Publisher(SocketTube(2)) subscription request(1), demand=1
21:27:34.028 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [698ms] HttpClientImpl(2) next expired: 0
21:27:34.029 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [698ms] HttpClientImpl(2) Next deadline is 3000
21:27:34.029 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-2-SelectorManager] [699ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@6b5959fb for 1 (true)
21:27:34.029 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [699ms] HttpClientImpl(2) next timeout: 179988
21:27:34.029 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [699ms] HttpClientImpl(2) next expired: 0
21:27:34.029 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [699ms] HttpClientImpl(2) Next deadline is 3000
21:27:34.030 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-3-thread-2] [699ms] Http1Publisher(SocketTube(2)) WriteTask
21:27:34.030 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-3-thread-2] [700ms] Http1Publisher(SocketTube(2)) hasOutgoing = true
21:27:34.030 DEBUG [Http1Exchange.getOutgoing] - [pool-3-thread-2] [700ms] Http1Exchange initiating completion of headersSentCF
21:27:34.030 DEBUG [Exchange.checkFor407] - [pool-3-thread-2] [700ms] Exchange checkFor407: all clear
21:27:34.030 DEBUG [Exchange.sendRequestBody] - [pool-3-thread-2] [700ms] Exchange sendRequestBody
21:27:34.031 DEBUG [Http1Exchange.sendBodyAsync] - [pool-3-thread-2] [700ms] Http1Exchange sendBodyAsync
21:27:34.031 DEBUG [Http1Exchange.sendBodyAsync] - [pool-3-thread-2] [701ms] Http1Exchange bodySubscriber is null
21:27:34.031 DEBUG [Http1Exchange.appendToOutgoing] - [pool-3-thread-2] [701ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]], throwable=null]
21:27:34.031 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-3-thread-2] [701ms] Http1Publisher(SocketTube(2)) onNext with 286 bytes
21:27:34.031 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [pool-3-thread-2] [701ms] SocketTube(2) trying to write: 286
21:27:34.031 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [pool-3-thread-2] [701ms] SocketTube(2) wrote: 286
21:27:34.032 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-3-thread-2] [701ms] SocketTube(2) write: requesting more...
21:27:34.032 DEBUG [Http1Exchange$Http1Publisher$Http1WriteSubscription.request] - [pool-3-thread-2] [702ms] Http1Publisher(SocketTube(2)) subscription request(1), demand=1
21:27:34.032 DEBUG [SocketTube.debugState] - [pool-3-thread-2] [702ms] SocketTube(2) leaving requestMore:  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
21:27:34.032 DEBUG [SocketTube.debugState] - [pool-3-thread-2] [702ms] SocketTube(2) leaving w.onNext Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
21:27:34.032 DEBUG [Http1Exchange.getOutgoing] - [pool-3-thread-2] [702ms] Http1Exchange initiating completion of bodySentCF
21:27:34.032 DEBUG [Utils.lambda$wrapForDebug$8] - [pool-3-thread-2] [702ms] Http1Exchange sendBodyAsync completed successfully
21:27:34.032 DEBUG [Http1Exchange.getResponseAsync] - [pool-3-thread-2] [702ms] Http1Exchange reading headers
21:27:34.032 DEBUG [Http1Response.readHeadersAsync] - [pool-3-thread-2] [702ms] Http1Response(id=2, PlainHttpConnection(SocketTube(2))) Reading Headers: (remaining: 0) READING_HEADERS
21:27:34.032 DEBUG [Http1Response.readHeadersAsync] - [pool-3-thread-2] [702ms] Http1Response(id=2, PlainHttpConnection(SocketTube(2))) First time around
21:27:34.032 DEBUG [Http1Response.readHeadersAsync] - [pool-3-thread-2] [702ms] Http1Response(id=2, PlainHttpConnection(SocketTube(2))) headersReader is not yet completed
21:27:34.032 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-3-thread-2] [702ms] Http1Publisher(SocketTube(2)) completed, stopping jdk.internal.net.http.common.SequentialScheduler@495b8560
21:27:34.033 DEBUG [SocketTube.debugState] - [pool-3-thread-2] [702ms] SocketTube(2) leaving requestMore:  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
21:27:34.414 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-2-SelectorManager] [1s 84ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@6b5959fb for 0 (false)
21:27:34.415 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-2-SelectorManager] [1s 85ms] SocketTube(2) read bytes: 973
21:27:34.415 DEBUG [Http1AsyncReceiver.asyncReceive] - [HttpClient-2-SelectorManager] [1s 85ms] Http1AsyncReceiver(SocketTube(2)) Putting 973 bytes into the queue
21:27:34.415 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [HttpClient-2-SelectorManager] [1s 85ms] SocketTube(2) resuming read event
21:27:34.416 DEBUG [Http1AsyncReceiver.flush] - [pool-3-thread-2] [1s 85ms] Http1AsyncReceiver(SocketTube(2)) Got 973 bytes for delegate jdk.internal.net.http.Http1Response$HeadersReader@822a5cc
21:27:34.416 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-3-thread-2] [1s 86ms] Http1AsyncReceiver(SocketTube(2)) downstream subscription demand is 1
21:27:34.416 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-2-SelectorManager] [1s 86ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@6b5959fb for 1 (false)
21:27:34.416 DEBUG [Http1AsyncReceiver.flush] - [pool-3-thread-2] [1s 86ms] Http1AsyncReceiver(SocketTube(2)) Forwarding 973 bytes to delegate jdk.internal.net.http.Http1Response$HeadersReader@822a5cc
21:27:34.416 DEBUG [SocketTube.debugState] - [HttpClient-2-SelectorManager] [1s 86ms] SocketTube(2) leaving read() loop after onNext:  Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
21:27:34.416 DEBUG [Http1Response$HeadersReader.handle] - [pool-3-thread-2] [1s 86ms] Http1Response(id=2, PlainHttpConnection(SocketTube(2))) Sending 973/973 bytes to header parser
21:27:34.417 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [1s 87ms] HttpClientImpl(2) next timeout: 179600
21:27:34.417 DEBUG [Http1Response$HeadersReader.handle] - [pool-3-thread-2] [1s 87ms] Http1Response(id=2, PlainHttpConnection(SocketTube(2))) Parsing headers completed. bytes=40
21:27:34.417 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [1s 87ms] HttpClientImpl(2) next expired: 0
21:27:34.417 DEBUG [Http1AsyncReceiver.unsubscribe] - [pool-3-thread-2] [1s 87ms] Http1AsyncReceiver(SocketTube(2)) Unsubscribed jdk.internal.net.http.Http1Response$HeadersReader@822a5cc
21:27:34.417 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [1s 87ms] HttpClientImpl(2) Next deadline is 3000
21:27:34.417 DEBUG [Http1Response.lambda$readHeadersAsync$0] - [pool-3-thread-2] [1s 87ms] Http1Response(id=2, PlainHttpConnection(SocketTube(2))) Reading Headers: creating Response object; state is now READING_BODY
21:27:34.418 DEBUG [Utils.lambda$wrapForDebug$8] - [pool-3-thread-2] [1s 88ms] Http1Exchange getResponseAsync completed successfully
21:27:34.418 DEBUG [Http1Response.readBody] - [pool-3-thread-2] [1s 88ms] Http1Response(id=2, PlainHttpConnection(SocketTube(2))) readBody: return2Cache: true
21:27:34.419 DEBUG [Http1Response$ClientRefCountTracker.acquire] - [pool-3-thread-2] [1s 89ms] Http1Response(id=2, PlainHttpConnection(SocketTube(2))) Operation started: incrementing ref count for jdk.internal.net.http.HttpClientImpl@2f6e5a2f(2)
21:27:34.419 DEBUG [Http1AsyncReceiver.subscribe] - [pool-3-thread-2] [1s 89ms] Http1AsyncReceiver(SocketTube(2)) Subscribed pending jdk.internal.net.http.Http1Response$BodyReader@479c623b/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@43a3ee10 queue.isEmpty: false
21:27:34.419 DEBUG [Http1AsyncReceiver.flush] - [pool-3-thread-2] [1s 89ms] Http1AsyncReceiver(SocketTube(2)) Delegate done: 933
21:27:34.419 DEBUG [ResponseContent$FixedLengthBodyParser.onSubscribe] - [pool-3-thread-2] [1s 89ms] PlainHttpConnection(SocketTube(2))/ResponseContent/FixedLengthBodyParser length=933, onSubscribe: jdk.internal.net.http.Http1Response$Http1BodySubscriber
21:27:34.420 DEBUG [Http1AsyncReceiver.handlePendingDelegate] - [pool-3-thread-2] [1s 89ms] Http1AsyncReceiver(SocketTube(2)) delegate is now jdk.internal.net.http.Http1Response$BodyReader@479c623b/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@43a3ee10, demand=9223372036854775807, canRequestMore=false, queue.isEmpty=false
21:27:34.420 DEBUG [Http1AsyncReceiver.flush] - [pool-3-thread-2] [1s 90ms] Http1AsyncReceiver(SocketTube(2)) Got 933 bytes for delegate jdk.internal.net.http.Http1Response$BodyReader@479c623b/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@43a3ee10
21:27:34.420 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-3-thread-2] [1s 90ms] Http1AsyncReceiver(SocketTube(2)) downstream subscription demand is 9223372036854775807
21:27:34.420 DEBUG [Http1AsyncReceiver.flush] - [pool-3-thread-2] [1s 90ms] Http1AsyncReceiver(SocketTube(2)) Forwarding 933 bytes to delegate jdk.internal.net.http.Http1Response$BodyReader@479c623b/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@43a3ee10
21:27:34.420 DEBUG [Http1Response$BodyReader.handle] - [pool-3-thread-2] [1s 90ms] Http1Response(id=2, PlainHttpConnection(SocketTube(2))) Sending 933/973 bytes to body parser
21:27:34.420 DEBUG [ResponseContent$FixedLengthBodyParser.accept] - [pool-3-thread-2] [1s 90ms] PlainHttpConnection(SocketTube(2))/ResponseContent/FixedLengthBodyParser Parser got 933 bytes (933 remaining / 933)
21:27:34.420 DEBUG [ResponseContent$FixedLengthBodyParser.accept] - [pool-3-thread-2] [1s 90ms] PlainHttpConnection(SocketTube(2))/ResponseContent/FixedLengthBodyParser Parser got all expected bytes: completing
21:27:34.420 DEBUG [Http1AsyncReceiver.clear] - [pool-3-thread-2] [1s 90ms] Http1AsyncReceiver(SocketTube(2)) cleared
21:27:34.421 DEBUG [Http1Response.onFinished] - [pool-3-thread-2] [1s 90ms] Http1Response(id=2, PlainHttpConnection(SocketTube(2))) SocketTube(2): return to HTTP/1.1 pool
21:27:34.421 DEBUG [ConnectionPool.registerCleanupTrigger] - [pool-3-thread-2] [1s 91ms] ConnectionPool(2) registering CleanupTrigger(SocketTube(2))
21:27:34.421 DEBUG [SocketTube.connectFlows] - [pool-3-thread-2] [1s 91ms] SocketTube(2) connecting flows
21:27:34.421 DEBUG [SocketTube$InternalReadPublisher.subscribe] - [pool-3-thread-2] [1s 91ms] SocketTube(2) read publisher got subscriber
21:27:34.421 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalSubscribe] - [pool-3-thread-2] [1s 91ms] SocketTube(2) registering subscribe event
21:27:34.421 DEBUG [SocketTube.debugState] - [pool-3-thread-2] [1s 91ms] SocketTube(2) leaving read.subscribe:  Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
21:27:34.421 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handleSubscribeEvent] - [HttpClient-2-SelectorManager] [1s 91ms] SocketTube(2) subscribe event raised
21:27:34.421 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-3-thread-2] [1s 91ms] SocketTube(2) subscribed for writing
21:27:34.422 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-2-SelectorManager] [1s 92ms] SocketTube(2) handling pending subscription for CleanupTrigger(SocketTube(2))
21:27:34.422 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.dropSubscription] - [pool-3-thread-2] [1s 92ms] SocketTube(2) write: resetting demand to 0
21:27:34.422 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.dropSubscription] - [HttpClient-2-SelectorManager] [1s 92ms] Http1AsyncReceiver(SocketTube(2)) Http1TubeSubscriber: dropSubscription
21:27:34.422 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-3-thread-2] [1s 92ms] SocketTube(2) write: registering startSubscription event
21:27:34.422 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-2-SelectorManager] [1s 92ms] SocketTube(2) read demand reset to 0
21:27:34.422 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-2-SelectorManager] [1s 92ms] SocketTube(2) calling onSubscribe
21:27:34.423 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.request] - [HttpClient-2-SelectorManager] [1s 92ms] SocketTube(2) got some demand for reading
21:27:34.423 DEBUG [Http1Response.lambda$readBody$2] - [pool-3-thread-2] [1s 92ms] Http1Response(id=2, PlainHttpConnection(SocketTube(2))) Finished reading body: READING_BODY
21:27:34.423 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [HttpClient-2-SelectorManager] [1s 93ms] SocketTube(2) resuming read event
21:27:34.423 DEBUG [Http1Response$ClientRefCountTracker.tryRelease] - [pool-3-thread-2] [1s 93ms] Http1Response(id=2, PlainHttpConnection(SocketTube(2))) Operation finished: decrementing ref count for jdk.internal.net.http.HttpClientImpl@2f6e5a2f(2)
21:27:34.423 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-2-SelectorManager] [1s 93ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@6b5959fb for 1 (false)
21:27:34.423 DEBUG [Http1AsyncReceiver.flush] - [pool-3-thread-2] [1s 93ms] Http1AsyncReceiver(SocketTube(2)) Delegate done: 0
21:27:34.423 DEBUG [JdkHttpClient.execute] - Ending request (GET) /status in 407ms
21:27:34.423 DEBUG [Http1AsyncReceiver.flush] - [pool-3-thread-2] [1s 93ms] Http1AsyncReceiver(SocketTube(2)) Got 0 bytes for delegate null
21:27:34.423 DEBUG [SocketTube.debugState] - [HttpClient-2-SelectorManager] [1s 93ms] SocketTube(2) leaving request(1):  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=0]
21:27:34.424 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=d50f091d0fc3ecdf19c77f7755ee6935, spanId=3adf06e5e467da8d, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.16.0, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.22.0"}}, instrumentationScopeInfo=InstrumentationScopeInfo{name=default, version=null, schemaUrl=null, attributes={}}, name=httpclient.execute, kind=INTERNAL, startEpochNanos=1678742854012000000, endEpochNanos=1678742854423906041, attributes=AttributesMap{data={http.method=GET, http.status_code=200, span.kind=client, http.target=/status}, capacity=128, totalAddedValues=4}, totalAttributeCount=4, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=OK, description=Kind: OK Description:}, hasEnded=true}
21:27:34.424 DEBUG [SocketTube$InternalReadPublisher$ReadSubscription.signalOnSubscribe] - [HttpClient-2-SelectorManager] [1s 94ms] SocketTube(2) onSubscribe called
21:27:34.424 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-2-SelectorManager] [1s 94ms] SocketTube(2) pending subscriber subscribed
21:27:34.425 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [1s 94ms] HttpClientImpl(2) next timeout: 0
21:27:34.425 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [1s 95ms] HttpClientImpl(2) next expired: 1199575
21:27:34.425 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [1s 95ms] HttpClientImpl(2) Next deadline is 3000
21:27:34.425 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-2-SelectorManager] [1s 95ms] SocketTube(2) write: starting subscription
21:27:34.425 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-2-SelectorManager] [1s 95ms] SocketTube(2) write: offloading requestMore
21:27:34.425 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-3-thread-2] [1s 95ms] SocketTube(2) write: requesting more...
21:27:34.425 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [1s 95ms] HttpClientImpl(2) next timeout: 0
21:27:34.426 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [1s 96ms] HttpClientImpl(2) next expired: 1199574
21:27:34.426 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-2-SelectorManager] [1s 96ms] HttpClientImpl(2) Next deadline is 3000
21:27:34.425 DEBUG [SocketTube.debugState] - [pool-3-thread-2] [1s 95ms] SocketTube(2) leaving requestMore:  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
21:27:34.426 DEBUG [GridModel.add] - Adding node with id 6c249aa3-40ca-48c7-a23f-f994fea8f83c and URI http://10.42.0.208:5555
21:27:34.426 DEBUG [LocalDistributor.updateNodeAvailability] - Health check result for http://10.42.0.208:5555 was UP
21:27:34.427 INFO [GridModel.setAvailability] - Switching Node 6c249aa3-40ca-48c7-a23f-f994fea8f83c (uri: http://10.42.0.208:5555) from DOWN to UP
21:27:34.427 INFO [LocalDistributor.add] - Added node 6c249aa3-40ca-48c7-a23f-f994fea8f83c at http://10.42.0.208:5555. Health check every 120s
21:27:34.429 INFO [Node.<init>] - Binding additional locator mechanisms: relative
21:27:34.433 DEBUG [HttpClientImpl.<init>] - [Event Bus Listener Notifier] [1s 103ms] HttpClientImpl(3) proxySelector is sun.net.spi.DefaultProxySelector@7ed04d8e (user-supplied=false)
21:27:34.434 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 104ms] HttpClientImpl(3) next timeout: 0
21:27:34.434 DEBUG [HttpTracing.inject] - Injecting (GET) /status into OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@6c3f5566, context={}, span id=0000000000000000, trace id=00000000000000000000000000000000} at org.openqa.selenium.grid.node.remote.RemoteNode:211
21:27:34.434 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 104ms] HttpClientImpl(3) next expired: 0
21:27:34.435 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 105ms] HttpClientImpl(3) Next deadline is 3000
21:27:34.435 DEBUG [JdkHttpClient.execute] - Executing request: (GET) /status
21:27:34.436 DEBUG [HttpClientImpl.sendAsync] - [Event Bus Listener Notifier] [1s 105ms] HttpClientImpl(3) ClientImpl (async) send http://10.42.0.209:5555/status GET
21:27:34.436 DEBUG [Exchange.establishExchange] - [Event Bus Listener Notifier] [1s 106ms] Exchange establishing exchange for http://10.42.0.209:5555/status GET,
     proxy=null
21:27:34.437 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 106ms] HttpClientImpl(3) next timeout: 180000
21:27:34.437 DEBUG [Http2ClientImpl.getConnectionFor] - [Event Bus Listener Notifier] [1s 107ms] Http2ClientImpl not found in connection pool
21:27:34.437 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 107ms] HttpClientImpl(3) next expired: 0
21:27:34.437 DEBUG [ExchangeImpl.get] - [Event Bus Listener Notifier] [1s 107ms] ExchangeImpl get: Trying to get HTTP/2 connection
21:27:34.437 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 107ms] HttpClientImpl(3) Next deadline is 3000
21:27:34.437 DEBUG [ExchangeImpl.createExchangeImpl] - [Event Bus Listener Notifier] [1s 107ms] ExchangeImpl handling HTTP/2 connection creation result
21:27:34.437 DEBUG [ExchangeImpl.createExchangeImpl] - [Event Bus Listener Notifier] [1s 107ms] ExchangeImpl new Http1Exchange, try to upgrade
21:27:34.438 DEBUG [PlainHttpConnection.<init>] - [Event Bus Listener Notifier] [1s 108ms] PlainHttpConnection(?) Initial receive buffer size is: 65536
21:27:34.438 DEBUG [Exchange.checkFor407] - [Event Bus Listener Notifier] [1s 108ms] Exchange checkFor407: all clear
21:27:34.438 DEBUG [Http1Exchange.sendHeadersAsync] - [Event Bus Listener Notifier] [1s 108ms] Http1Exchange Sending headers only
21:27:34.439 DEBUG [Http1AsyncReceiver.subscribe] - [Event Bus Listener Notifier] [1s 108ms] Http1AsyncReceiver(SocketTube(3)) Subscribed pending jdk.internal.net.http.Http1Response$HeadersReader@4ecc61b3 queue.isEmpty: true
21:27:34.439 DEBUG [Http1AsyncReceiver.handlePendingDelegate] - [Event Bus Listener Notifier] [1s 109ms] Http1AsyncReceiver(SocketTube(3)) delegate is now jdk.internal.net.http.Http1Response$HeadersReader@4ecc61b3, demand=1, canRequestMore=true, queue.isEmpty=true
21:27:34.439 DEBUG [Http1AsyncReceiver.hasDemand] - [Event Bus Listener Notifier] [1s 109ms] Http1AsyncReceiver(SocketTube(3)) downstream subscription demand is 1
21:27:34.439 DEBUG [Http1AsyncReceiver.checkRequestMore] - [Event Bus Listener Notifier] [1s 109ms] Http1AsyncReceiver(SocketTube(3)) checkRequestMore: canRequestMore=true, hasDemand=true
21:27:34.439 DEBUG [Http1AsyncReceiver.hasDemand] - [Event Bus Listener Notifier] [1s 109ms] Http1AsyncReceiver(SocketTube(3)) downstream subscription demand is 1
21:27:34.439 DEBUG [Http1AsyncReceiver.checkRequestMore] - [Event Bus Listener Notifier] [1s 109ms] Http1AsyncReceiver(SocketTube(3)) checkRequestMore: canRequestMore=true, hasDemand=true
21:27:34.439 DEBUG [Http1Exchange.sendHeadersAsync] - [Event Bus Listener Notifier] [1s 109ms] Http1Exchange response created in advance
21:27:34.439 DEBUG [Http1Exchange.sendHeadersAsync] - [Event Bus Listener Notifier] [1s 109ms] Http1Exchange initiating connect async
21:27:34.439 DEBUG [PlainHttpConnection.connectAsync] - [Event Bus Listener Notifier] [1s 109ms] PlainHttpConnection(SocketTube(3)) registering connect timer: ConnectTimerEvent, TimeoutEvent[id=6, duration=PT10S, deadline=2023-03-13T21:27:44.439761Z]
21:27:34.440 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 109ms] HttpClientImpl(3) next timeout: 9999
21:27:34.440 DEBUG [PlainHttpConnection.connectAsync] - [Event Bus Listener Notifier] [1s 110ms] PlainHttpConnection(SocketTube(3)) registering connect event
21:27:34.440 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 110ms] HttpClientImpl(3) next expired: 0
21:27:34.440 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 110ms] HttpClientImpl(3) Next deadline is 3000
21:27:34.440 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-3-SelectorManager] [1s 110ms] SelectorAttachment Registering jdk.internal.net.http.PlainHttpConnection$ConnectEvent@2ba4deca for 8 (true)
21:27:34.443 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 113ms] HttpClientImpl(3) next timeout: 9996
21:27:34.443 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 113ms] HttpClientImpl(3) next expired: 0
21:27:34.443 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 113ms] HttpClientImpl(3) Next deadline is 3000
21:27:34.443 DEBUG [PlainHttpConnection$ConnectEvent.handle] - [HttpClient-3-SelectorManager] [1s 113ms] PlainHttpConnection(SocketTube(3)) ConnectEvent: finishing connect
21:27:34.444 DEBUG [PlainHttpConnection$ConnectEvent.handle] - [HttpClient-3-SelectorManager] [1s 114ms] PlainHttpConnection(SocketTube(3)) ConnectEvent: connect finished: true Local addr: /10.42.0.210:51854
21:27:34.445 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 114ms] HttpClientImpl(3) next timeout: 9995
21:27:34.445 DEBUG [PlainHttpConnection.finishConnect] - [pool-4-thread-1] [1s 114ms] PlainHttpConnection(SocketTube(3)) finishConnect, setting connected=true
21:27:34.445 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 115ms] HttpClientImpl(3) next expired: 0
21:27:34.445 DEBUG [Http1Exchange.connectFlows] - [pool-4-thread-1] [1s 115ms] Http1Exchange SocketTube(3) connecting flows
21:27:34.445 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 115ms] HttpClientImpl(3) Next deadline is 3000
21:27:34.445 DEBUG [SocketTube.connectFlows] - [pool-4-thread-1] [1s 115ms] SocketTube(3) connecting flows
21:27:34.445 DEBUG [SocketTube$InternalReadPublisher.subscribe] - [pool-4-thread-1] [1s 115ms] SocketTube(3) read publisher got subscriber
21:27:34.445 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalSubscribe] - [pool-4-thread-1] [1s 115ms] SocketTube(3) registering subscribe event
21:27:34.445 DEBUG [SocketTube.debugState] - [pool-4-thread-1] [1s 115ms] SocketTube(3) leaving read.subscribe:  Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=0]
21:27:34.445 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handleSubscribeEvent] - [HttpClient-3-SelectorManager] [1s 115ms] SocketTube(3) subscribe event raised
21:27:34.446 DEBUG [Http1Exchange$Http1Publisher.subscribe] - [pool-4-thread-1] [1s 115ms] Http1Publisher(SocketTube(3)) got subscriber: SocketTube(3)
21:27:34.446 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-3-SelectorManager] [1s 116ms] SocketTube(3) handling pending subscription for jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber@645e3ff5
21:27:34.446 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-4-thread-1] [1s 116ms] SocketTube(3) subscribed for writing
21:27:34.446 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-3-SelectorManager] [1s 116ms] SocketTube(3) read demand reset to 0
21:27:34.446 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-4-thread-1] [1s 116ms] SocketTube(3) write: registering startSubscription event
21:27:34.446 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-3-SelectorManager] [1s 116ms] SocketTube(3) calling onSubscribe
21:27:34.446 DEBUG [Http1Exchange.lambda$sendHeadersAsync$4] - [pool-4-thread-1] [1s 116ms] Http1Exchange requestAction.headers
21:27:34.446 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.onSubscribe] - [HttpClient-3-SelectorManager] [1s 116ms] Http1AsyncReceiver(SocketTube(3)) Received onSubscribed from upstream
21:27:34.447 DEBUG [SocketTube$InternalReadPublisher$ReadSubscription.signalOnSubscribe] - [HttpClient-3-SelectorManager] [1s 117ms] SocketTube(3) onSubscribe called
21:27:34.447 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-3-SelectorManager] [1s 117ms] SocketTube(3) pending subscriber subscribed
21:27:34.447 DEBUG [Http1Exchange.lambda$sendHeadersAsync$4] - [pool-4-thread-1] [1s 117ms] Http1Exchange setting outgoing with headers
21:27:34.447 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 117ms] HttpClientImpl(3) next timeout: 179989
21:27:34.448 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 118ms] HttpClientImpl(3) next expired: 0
21:27:34.448 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 118ms] HttpClientImpl(3) Next deadline is 3000
21:27:34.448 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-4-thread-2] [1s 118ms] Http1AsyncReceiver(SocketTube(3)) downstream subscription demand is 1
21:27:34.448 DEBUG [Http1Exchange.appendToOutgoing] - [pool-4-thread-1] [1s 118ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=286 cap=286]], throwable=null]
21:27:34.448 DEBUG [Http1AsyncReceiver.checkRequestMore] - [pool-4-thread-2] [1s 118ms] Http1AsyncReceiver(SocketTube(3)) checkRequestMore: canRequestMore=true, hasDemand=true
21:27:34.448 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-3-SelectorManager] [1s 118ms] SocketTube(3) write: starting subscription
21:27:34.449 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.requestMore] - [pool-4-thread-2] [1s 118ms] Http1AsyncReceiver(SocketTube(3)) Http1TubeSubscriber: requesting one more from upstream
21:27:34.448 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-4-thread-1] [1s 118ms] Http1Publisher(SocketTube(3)) WriteTask
21:27:34.449 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.request] - [pool-4-thread-2] [1s 119ms] SocketTube(3) got some demand for reading
21:27:34.449 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-3-SelectorManager] [1s 119ms] SocketTube(3) write: offloading requestMore
21:27:34.449 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [pool-4-thread-2] [1s 119ms] SocketTube(3) resuming read event
21:27:34.449 DEBUG [SocketTube.debugState] - [pool-4-thread-2] [1s 119ms] SocketTube(3) leaving request(1):  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=0]
21:27:34.449 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-4-thread-1] [1s 119ms] Http1Publisher(SocketTube(3)) hasOutgoing = true
21:27:34.450 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 120ms] HttpClientImpl(3) next timeout: 179986
21:27:34.450 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 120ms] HttpClientImpl(3) next expired: 0
21:27:34.451 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 120ms] HttpClientImpl(3) Next deadline is 3000
21:27:34.451 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-3-SelectorManager] [1s 121ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@1145f4f0 for 1 (true)
21:27:34.451 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 121ms] HttpClientImpl(3) next timeout: 179985
21:27:34.451 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 121ms] HttpClientImpl(3) next expired: 0
21:27:34.451 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 121ms] HttpClientImpl(3) Next deadline is 3000
21:27:34.450 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-4-thread-3] [1s 120ms] SocketTube(3) write: requesting more...
21:27:34.452 DEBUG [Http1Exchange$Http1Publisher$Http1WriteSubscription.request] - [pool-4-thread-3] [1s 122ms] Http1Publisher(SocketTube(3)) subscription request(1), demand=1
21:27:34.455 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-4-thread-3] [1s 125ms] Http1Publisher(SocketTube(3)) WriteTask
21:27:34.455 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-4-thread-3] [1s 125ms] Http1Publisher(SocketTube(3)) hasOutgoing = true
21:27:34.455 DEBUG [Http1Exchange.getOutgoing] - [pool-4-thread-3] [1s 125ms] Http1Exchange initiating completion of headersSentCF
21:27:34.455 DEBUG [Exchange.checkFor407] - [pool-4-thread-3] [1s 125ms] Exchange checkFor407: all clear
21:27:34.455 DEBUG [Exchange.sendRequestBody] - [pool-4-thread-3] [1s 125ms] Exchange sendRequestBody
21:27:34.455 DEBUG [Http1Exchange.sendBodyAsync] - [pool-4-thread-3] [1s 125ms] Http1Exchange sendBodyAsync
21:27:34.455 DEBUG [Http1Exchange.sendBodyAsync] - [pool-4-thread-3] [1s 125ms] Http1Exchange bodySubscriber is null
21:27:34.456 DEBUG [Http1Exchange.appendToOutgoing] - [pool-4-thread-3] [1s 125ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]], throwable=null]
21:27:34.456 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-4-thread-3] [1s 126ms] Http1Publisher(SocketTube(3)) onNext with 286 bytes
21:27:34.456 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [pool-4-thread-3] [1s 126ms] SocketTube(3) trying to write: 286
21:27:34.456 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [pool-4-thread-3] [1s 126ms] SocketTube(3) wrote: 286
21:27:34.457 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-4-thread-3] [1s 126ms] SocketTube(3) write: requesting more...
21:27:34.457 DEBUG [Http1Exchange$Http1Publisher$Http1WriteSubscription.request] - [pool-4-thread-3] [1s 127ms] Http1Publisher(SocketTube(3)) subscription request(1), demand=1
21:27:34.457 DEBUG [SocketTube.debugState] - [pool-4-thread-3] [1s 127ms] SocketTube(3) leaving requestMore:  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
21:27:34.457 DEBUG [SocketTube.debugState] - [pool-4-thread-3] [1s 127ms] SocketTube(3) leaving w.onNext Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
21:27:34.457 DEBUG [Http1Exchange.getOutgoing] - [pool-4-thread-3] [1s 127ms] Http1Exchange initiating completion of bodySentCF
21:27:34.457 DEBUG [Utils.lambda$wrapForDebug$8] - [pool-4-thread-3] [1s 127ms] Http1Exchange sendBodyAsync completed successfully
21:27:34.457 DEBUG [Http1Exchange.getResponseAsync] - [pool-4-thread-3] [1s 127ms] Http1Exchange reading headers
21:27:34.457 DEBUG [Http1Response.readHeadersAsync] - [pool-4-thread-3] [1s 127ms] Http1Response(id=3, PlainHttpConnection(SocketTube(3))) Reading Headers: (remaining: 0) READING_HEADERS
21:27:34.457 DEBUG [Http1Response.readHeadersAsync] - [pool-4-thread-3] [1s 127ms] Http1Response(id=3, PlainHttpConnection(SocketTube(3))) First time around
21:27:34.458 DEBUG [Http1Response.readHeadersAsync] - [pool-4-thread-3] [1s 127ms] Http1Response(id=3, PlainHttpConnection(SocketTube(3))) headersReader is not yet completed
21:27:34.458 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-4-thread-3] [1s 128ms] Http1Publisher(SocketTube(3)) completed, stopping jdk.internal.net.http.common.SequentialScheduler@64b0d8a1
21:27:34.459 DEBUG [SocketTube.debugState] - [pool-4-thread-3] [1s 129ms] SocketTube(3) leaving requestMore:  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
21:27:34.820 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-3-SelectorManager] [1s 490ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@1145f4f0 for 0 (false)
21:27:34.821 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-3-SelectorManager] [1s 491ms] SocketTube(3) read bytes: 973
21:27:34.821 DEBUG [Http1AsyncReceiver.asyncReceive] - [HttpClient-3-SelectorManager] [1s 491ms] Http1AsyncReceiver(SocketTube(3)) Putting 973 bytes into the queue
21:27:34.821 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [HttpClient-3-SelectorManager] [1s 491ms] SocketTube(3) resuming read event
21:27:34.822 DEBUG [Http1AsyncReceiver.flush] - [pool-4-thread-3] [1s 492ms] Http1AsyncReceiver(SocketTube(3)) Got 973 bytes for delegate jdk.internal.net.http.Http1Response$HeadersReader@4ecc61b3
21:27:34.822 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-3-SelectorManager] [1s 492ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@1145f4f0 for 1 (false)
21:27:34.822 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-4-thread-3] [1s 492ms] Http1AsyncReceiver(SocketTube(3)) downstream subscription demand is 1
21:27:34.822 DEBUG [SocketTube.debugState] - [HttpClient-3-SelectorManager] [1s 492ms] SocketTube(3) leaving read() loop after onNext:  Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
21:27:34.822 DEBUG [Http1AsyncReceiver.flush] - [pool-4-thread-3] [1s 492ms] Http1AsyncReceiver(SocketTube(3)) Forwarding 973 bytes to delegate jdk.internal.net.http.Http1Response$HeadersReader@4ecc61b3
21:27:34.822 DEBUG [Http1Response$HeadersReader.handle] - [pool-4-thread-3] [1s 492ms] Http1Response(id=3, PlainHttpConnection(SocketTube(3))) Sending 973/973 bytes to header parser
21:27:34.822 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 492ms] HttpClientImpl(3) next timeout: 179614
21:27:34.822 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 492ms] HttpClientImpl(3) next expired: 0
21:27:34.822 DEBUG [Http1Response$HeadersReader.handle] - [pool-4-thread-3] [1s 492ms] Http1Response(id=3, PlainHttpConnection(SocketTube(3))) Parsing headers completed. bytes=40
21:27:34.822 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 492ms] HttpClientImpl(3) Next deadline is 3000
21:27:34.822 DEBUG [Http1AsyncReceiver.unsubscribe] - [pool-4-thread-3] [1s 492ms] Http1AsyncReceiver(SocketTube(3)) Unsubscribed jdk.internal.net.http.Http1Response$HeadersReader@4ecc61b3
21:27:34.823 DEBUG [Http1Response.lambda$readHeadersAsync$0] - [pool-4-thread-3] [1s 492ms] Http1Response(id=3, PlainHttpConnection(SocketTube(3))) Reading Headers: creating Response object; state is now READING_BODY
21:27:34.823 DEBUG [Utils.lambda$wrapForDebug$8] - [pool-4-thread-3] [1s 493ms] Http1Exchange getResponseAsync completed successfully
21:27:34.823 DEBUG [Http1Response.readBody] - [pool-4-thread-3] [1s 493ms] Http1Response(id=3, PlainHttpConnection(SocketTube(3))) readBody: return2Cache: true
21:27:34.823 DEBUG [Http1Response$ClientRefCountTracker.acquire] - [pool-4-thread-3] [1s 493ms] Http1Response(id=3, PlainHttpConnection(SocketTube(3))) Operation started: incrementing ref count for jdk.internal.net.http.HttpClientImpl@44813ee8(3)
21:27:34.823 DEBUG [Http1AsyncReceiver.subscribe] - [pool-4-thread-3] [1s 493ms] Http1AsyncReceiver(SocketTube(3)) Subscribed pending jdk.internal.net.http.Http1Response$BodyReader@6a772a47/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@6e48b3d1 queue.isEmpty: false
21:27:34.823 DEBUG [Http1AsyncReceiver.flush] - [pool-4-thread-3] [1s 493ms] Http1AsyncReceiver(SocketTube(3)) Delegate done: 933
21:27:34.823 DEBUG [ResponseContent$FixedLengthBodyParser.onSubscribe] - [pool-4-thread-3] [1s 493ms] PlainHttpConnection(SocketTube(3))/ResponseContent/FixedLengthBodyParser length=933, onSubscribe: jdk.internal.net.http.Http1Response$Http1BodySubscriber
21:27:34.824 DEBUG [Http1AsyncReceiver.handlePendingDelegate] - [pool-4-thread-3] [1s 493ms] Http1AsyncReceiver(SocketTube(3)) delegate is now jdk.internal.net.http.Http1Response$BodyReader@6a772a47/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@6e48b3d1, demand=9223372036854775807, canRequestMore=false, queue.isEmpty=false
21:27:34.824 DEBUG [Http1AsyncReceiver.flush] - [pool-4-thread-3] [1s 494ms] Http1AsyncReceiver(SocketTube(3)) Got 933 bytes for delegate jdk.internal.net.http.Http1Response$BodyReader@6a772a47/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@6e48b3d1
21:27:34.824 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-4-thread-3] [1s 494ms] Http1AsyncReceiver(SocketTube(3)) downstream subscription demand is 9223372036854775807
21:27:34.824 DEBUG [Http1AsyncReceiver.flush] - [pool-4-thread-3] [1s 494ms] Http1AsyncReceiver(SocketTube(3)) Forwarding 933 bytes to delegate jdk.internal.net.http.Http1Response$BodyReader@6a772a47/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@6e48b3d1
21:27:34.824 DEBUG [Http1Response$BodyReader.handle] - [pool-4-thread-3] [1s 494ms] Http1Response(id=3, PlainHttpConnection(SocketTube(3))) Sending 933/973 bytes to body parser
21:27:34.824 DEBUG [ResponseContent$FixedLengthBodyParser.accept] - [pool-4-thread-3] [1s 494ms] PlainHttpConnection(SocketTube(3))/ResponseContent/FixedLengthBodyParser Parser got 933 bytes (933 remaining / 933)
21:27:34.824 DEBUG [ResponseContent$FixedLengthBodyParser.accept] - [pool-4-thread-3] [1s 494ms] PlainHttpConnection(SocketTube(3))/ResponseContent/FixedLengthBodyParser Parser got all expected bytes: completing
21:27:34.824 DEBUG [Http1AsyncReceiver.clear] - [pool-4-thread-3] [1s 494ms] Http1AsyncReceiver(SocketTube(3)) cleared
21:27:34.824 DEBUG [Http1Response.onFinished] - [pool-4-thread-3] [1s 494ms] Http1Response(id=3, PlainHttpConnection(SocketTube(3))) SocketTube(3): return to HTTP/1.1 pool
21:27:34.824 DEBUG [ConnectionPool.registerCleanupTrigger] - [pool-4-thread-3] [1s 494ms] ConnectionPool(3) registering CleanupTrigger(SocketTube(3))
21:27:34.825 DEBUG [SocketTube.connectFlows] - [pool-4-thread-3] [1s 494ms] SocketTube(3) connecting flows
21:27:34.825 DEBUG [SocketTube$InternalReadPublisher.subscribe] - [pool-4-thread-3] [1s 494ms] SocketTube(3) read publisher got subscriber
21:27:34.825 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalSubscribe] - [pool-4-thread-3] [1s 495ms] SocketTube(3) registering subscribe event
21:27:34.825 DEBUG [SocketTube.debugState] - [pool-4-thread-3] [1s 495ms] SocketTube(3) leaving read.subscribe:  Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
21:27:34.825 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handleSubscribeEvent] - [HttpClient-3-SelectorManager] [1s 495ms] SocketTube(3) subscribe event raised
21:27:34.825 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-4-thread-3] [1s 495ms] SocketTube(3) subscribed for writing
21:27:34.825 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-3-SelectorManager] [1s 495ms] SocketTube(3) handling pending subscription for CleanupTrigger(SocketTube(3))
21:27:34.825 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.dropSubscription] - [pool-4-thread-3] [1s 495ms] SocketTube(3) write: resetting demand to 0
21:27:34.825 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.dropSubscription] - [HttpClient-3-SelectorManager] [1s 495ms] Http1AsyncReceiver(SocketTube(3)) Http1TubeSubscriber: dropSubscription
21:27:34.825 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-4-thread-3] [1s 495ms] SocketTube(3) write: registering startSubscription event
21:27:34.825 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-3-SelectorManager] [1s 495ms] SocketTube(3) read demand reset to 0
21:27:34.825 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-3-SelectorManager] [1s 495ms] SocketTube(3) calling onSubscribe
21:27:34.825 DEBUG [Http1Response.lambda$readBody$2] - [pool-4-thread-3] [1s 495ms] Http1Response(id=3, PlainHttpConnection(SocketTube(3))) Finished reading body: READING_BODY
21:27:34.825 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.request] - [HttpClient-3-SelectorManager] [1s 495ms] SocketTube(3) got some demand for reading
21:27:34.826 DEBUG [JdkHttpClient.execute] - Ending request (GET) /status in 391ms
21:27:34.826 DEBUG [Http1Response$ClientRefCountTracker.tryRelease] - [pool-4-thread-3] [1s 495ms] Http1Response(id=3, PlainHttpConnection(SocketTube(3))) Operation finished: decrementing ref count for jdk.internal.net.http.HttpClientImpl@44813ee8(3)
21:27:34.826 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [HttpClient-3-SelectorManager] [1s 496ms] SocketTube(3) resuming read event
21:27:34.826 DEBUG [Http1AsyncReceiver.flush] - [pool-4-thread-3] [1s 496ms] Http1AsyncReceiver(SocketTube(3)) Delegate done: 0
21:27:34.826 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-3-SelectorManager] [1s 496ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@1145f4f0 for 1 (false)
21:27:34.826 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=2863db62b31266e2087c5cc8b343c5cb, spanId=7f33765dfd237cd9, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.16.0, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.22.0"}}, instrumentationScopeInfo=InstrumentationScopeInfo{name=default, version=null, schemaUrl=null, attributes={}}, name=httpclient.execute, kind=INTERNAL, startEpochNanos=1678742854435000000, endEpochNanos=1678742854825956907, attributes=AttributesMap{data={http.method=GET, http.status_code=200, span.kind=client, http.target=/status}, capacity=128, totalAddedValues=4}, totalAttributeCount=4, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=OK, description=Kind: OK Description:}, hasEnded=true}
21:27:34.826 DEBUG [Http1AsyncReceiver.flush] - [pool-4-thread-3] [1s 496ms] Http1AsyncReceiver(SocketTube(3)) Got 0 bytes for delegate null
21:27:34.826 DEBUG [SocketTube.debugState] - [HttpClient-3-SelectorManager] [1s 496ms] SocketTube(3) leaving request(1):  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=0]
21:27:34.826 DEBUG [SocketTube$InternalReadPublisher$ReadSubscription.signalOnSubscribe] - [HttpClient-3-SelectorManager] [1s 496ms] SocketTube(3) onSubscribe called
21:27:34.826 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-3-SelectorManager] [1s 496ms] SocketTube(3) pending subscriber subscribed
21:27:34.826 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 496ms] HttpClientImpl(3) next timeout: 0
21:27:34.827 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 496ms] HttpClientImpl(3) next expired: 1199174
21:27:34.827 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 496ms] HttpClientImpl(3) Next deadline is 3000
21:27:34.827 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-3-SelectorManager] [1s 497ms] SocketTube(3) write: starting subscription
21:27:34.827 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-3-SelectorManager] [1s 497ms] SocketTube(3) write: offloading requestMore
21:27:34.827 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-4-thread-3] [1s 497ms] SocketTube(3) write: requesting more...
21:27:34.827 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 497ms] HttpClientImpl(3) next timeout: 0
21:27:34.827 DEBUG [SocketTube.debugState] - [pool-4-thread-3] [1s 497ms] SocketTube(3) leaving requestMore:  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
21:27:34.827 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 497ms] HttpClientImpl(3) next expired: 1199173
21:27:34.827 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [1s 497ms] HttpClientImpl(3) Next deadline is 3000
21:27:34.827 DEBUG [GridModel.add] - Adding node with id 16038c20-20ab-4df0-a91b-6380813a79d3 and URI http://10.42.0.209:5555
21:27:34.828 DEBUG [LocalDistributor.updateNodeAvailability] - Health check result for http://10.42.0.209:5555 was UP
21:27:34.828 INFO [GridModel.setAvailability] - Switching Node 16038c20-20ab-4df0-a91b-6380813a79d3 (uri: http://10.42.0.209:5555) from DOWN to UP
21:27:34.828 INFO [LocalDistributor.add] - Added node 16038c20-20ab-4df0-a91b-6380813a79d3 at http://10.42.0.209:5555. Health check every 120s
21:27:34.830 INFO [Node.<init>] - Binding additional locator mechanisms: relative
21:27:34.833 DEBUG [HttpClientImpl.<init>] - [Event Bus Listener Notifier] [1s 503ms] HttpClientImpl(4) proxySelector is sun.net.spi.DefaultProxySelector@7ed04d8e (user-supplied=false)
21:27:34.834 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 504ms] HttpClientImpl(4) next timeout: 0
21:27:34.834 DEBUG [HttpTracing.inject] - Injecting (GET) /status into OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@6c3f5566, context={}, span id=0000000000000000, trace id=00000000000000000000000000000000} at org.openqa.selenium.grid.node.remote.RemoteNode:211
21:27:34.834 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 504ms] HttpClientImpl(4) next expired: 0
21:27:34.834 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 504ms] HttpClientImpl(4) Next deadline is 3000
21:27:34.835 DEBUG [JdkHttpClient.execute] - Executing request: (GET) /status
21:27:34.836 DEBUG [HttpClientImpl.sendAsync] - [Event Bus Listener Notifier] [1s 505ms] HttpClientImpl(4) ClientImpl (async) send http://10.42.0.212:5555/status GET
21:27:34.848 DEBUG [Exchange.establishExchange] - [Event Bus Listener Notifier] [1s 518ms] Exchange establishing exchange for http://10.42.0.212:5555/status GET,
     proxy=null
21:27:34.848 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 518ms] HttpClientImpl(4) next timeout: 179988
21:27:34.849 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 519ms] HttpClientImpl(4) next expired: 0
21:27:34.849 DEBUG [Http2ClientImpl.getConnectionFor] - [Event Bus Listener Notifier] [1s 518ms] Http2ClientImpl not found in connection pool
21:27:34.849 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 519ms] HttpClientImpl(4) Next deadline is 3000
21:27:34.849 DEBUG [ExchangeImpl.get] - [Event Bus Listener Notifier] [1s 519ms] ExchangeImpl get: Trying to get HTTP/2 connection
21:27:34.849 DEBUG [ExchangeImpl.createExchangeImpl] - [Event Bus Listener Notifier] [1s 519ms] ExchangeImpl handling HTTP/2 connection creation result
21:27:34.850 DEBUG [ExchangeImpl.createExchangeImpl] - [Event Bus Listener Notifier] [1s 520ms] ExchangeImpl new Http1Exchange, try to upgrade
21:27:34.851 DEBUG [PlainHttpConnection.<init>] - [Event Bus Listener Notifier] [1s 521ms] PlainHttpConnection(?) Initial receive buffer size is: 65536
21:27:34.851 DEBUG [Exchange.checkFor407] - [Event Bus Listener Notifier] [1s 521ms] Exchange checkFor407: all clear
21:27:34.851 DEBUG [Http1Exchange.sendHeadersAsync] - [Event Bus Listener Notifier] [1s 521ms] Http1Exchange Sending headers only
21:27:34.851 DEBUG [Http1AsyncReceiver.subscribe] - [Event Bus Listener Notifier] [1s 521ms] Http1AsyncReceiver(SocketTube(4)) Subscribed pending jdk.internal.net.http.Http1Response$HeadersReader@44bc9f9a queue.isEmpty: true
21:27:34.852 DEBUG [Http1AsyncReceiver.handlePendingDelegate] - [Event Bus Listener Notifier] [1s 521ms] Http1AsyncReceiver(SocketTube(4)) delegate is now jdk.internal.net.http.Http1Response$HeadersReader@44bc9f9a, demand=1, canRequestMore=true, queue.isEmpty=true
21:27:34.852 DEBUG [Http1AsyncReceiver.hasDemand] - [Event Bus Listener Notifier] [1s 522ms] Http1AsyncReceiver(SocketTube(4)) downstream subscription demand is 1
21:27:34.852 DEBUG [Http1AsyncReceiver.checkRequestMore] - [Event Bus Listener Notifier] [1s 522ms] Http1AsyncReceiver(SocketTube(4)) checkRequestMore: canRequestMore=true, hasDemand=true
21:27:34.852 DEBUG [Http1AsyncReceiver.hasDemand] - [Event Bus Listener Notifier] [1s 522ms] Http1AsyncReceiver(SocketTube(4)) downstream subscription demand is 1
21:27:34.852 DEBUG [Http1AsyncReceiver.checkRequestMore] - [Event Bus Listener Notifier] [1s 522ms] Http1AsyncReceiver(SocketTube(4)) checkRequestMore: canRequestMore=true, hasDemand=true
21:27:34.852 DEBUG [Http1Exchange.sendHeadersAsync] - [Event Bus Listener Notifier] [1s 522ms] Http1Exchange response created in advance
21:27:34.852 DEBUG [Http1Exchange.sendHeadersAsync] - [Event Bus Listener Notifier] [1s 522ms] Http1Exchange initiating connect async
21:27:34.852 DEBUG [PlainHttpConnection.connectAsync] - [Event Bus Listener Notifier] [1s 522ms] PlainHttpConnection(SocketTube(4)) registering connect timer: ConnectTimerEvent, TimeoutEvent[id=8, duration=PT10S, deadline=2023-03-13T21:27:44.852668Z]
21:27:34.853 DEBUG [PlainHttpConnection.connectAsync] - [Event Bus Listener Notifier] [1s 523ms] PlainHttpConnection(SocketTube(4)) registering connect event
21:27:34.853 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-4-SelectorManager] [1s 523ms] SelectorAttachment Registering jdk.internal.net.http.PlainHttpConnection$ConnectEvent@5877980b for 8 (true)
21:27:34.854 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 524ms] HttpClientImpl(4) next timeout: 9998
21:27:34.855 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 525ms] HttpClientImpl(4) next expired: 0
21:27:34.855 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 525ms] HttpClientImpl(4) Next deadline is 3000
21:27:34.855 DEBUG [PlainHttpConnection$ConnectEvent.handle] - [HttpClient-4-SelectorManager] [1s 525ms] PlainHttpConnection(SocketTube(4)) ConnectEvent: finishing connect
21:27:34.856 DEBUG [PlainHttpConnection$ConnectEvent.handle] - [HttpClient-4-SelectorManager] [1s 525ms] PlainHttpConnection(SocketTube(4)) ConnectEvent: connect finished: true Local addr: /10.42.0.210:51478
21:27:34.856 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 526ms] HttpClientImpl(4) next timeout: 9996
21:27:34.857 DEBUG [PlainHttpConnection.finishConnect] - [pool-5-thread-1] [1s 526ms] PlainHttpConnection(SocketTube(4)) finishConnect, setting connected=true
21:27:34.857 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 526ms] HttpClientImpl(4) next expired: 0
21:27:34.857 DEBUG [Http1Exchange.connectFlows] - [pool-5-thread-1] [1s 527ms] Http1Exchange SocketTube(4) connecting flows
21:27:34.857 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 527ms] HttpClientImpl(4) Next deadline is 3000
21:27:34.857 DEBUG [SocketTube.connectFlows] - [pool-5-thread-1] [1s 527ms] SocketTube(4) connecting flows
21:27:34.858 DEBUG [SocketTube$InternalReadPublisher.subscribe] - [pool-5-thread-1] [1s 527ms] SocketTube(4) read publisher got subscriber
21:27:34.858 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalSubscribe] - [pool-5-thread-1] [1s 528ms] SocketTube(4) registering subscribe event
21:27:34.858 DEBUG [SocketTube.debugState] - [pool-5-thread-1] [1s 528ms] SocketTube(4) leaving read.subscribe:  Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=0]
21:27:34.858 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handleSubscribeEvent] - [HttpClient-4-SelectorManager] [1s 528ms] SocketTube(4) subscribe event raised
21:27:34.858 DEBUG [Http1Exchange$Http1Publisher.subscribe] - [pool-5-thread-1] [1s 528ms] Http1Publisher(SocketTube(4)) got subscriber: SocketTube(4)
21:27:34.858 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-4-SelectorManager] [1s 528ms] SocketTube(4) handling pending subscription for jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber@178d674e
21:27:34.858 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-5-thread-1] [1s 528ms] SocketTube(4) subscribed for writing
21:27:34.858 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-4-SelectorManager] [1s 528ms] SocketTube(4) read demand reset to 0
21:27:34.859 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-5-thread-1] [1s 528ms] SocketTube(4) write: registering startSubscription event
21:27:34.859 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-4-SelectorManager] [1s 529ms] SocketTube(4) calling onSubscribe
21:27:34.859 DEBUG [Http1Exchange.lambda$sendHeadersAsync$4] - [pool-5-thread-1] [1s 529ms] Http1Exchange requestAction.headers
21:27:34.859 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.onSubscribe] - [HttpClient-4-SelectorManager] [1s 529ms] Http1AsyncReceiver(SocketTube(4)) Received onSubscribed from upstream
21:27:34.859 DEBUG [SocketTube$InternalReadPublisher$ReadSubscription.signalOnSubscribe] - [HttpClient-4-SelectorManager] [1s 529ms] SocketTube(4) onSubscribe called
21:27:34.860 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-4-SelectorManager] [1s 529ms] SocketTube(4) pending subscriber subscribed
21:27:34.860 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 530ms] HttpClientImpl(4) next timeout: 179976
21:27:34.860 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 530ms] HttpClientImpl(4) next expired: 0
21:27:34.860 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 530ms] HttpClientImpl(4) Next deadline is 3000
21:27:34.860 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-4-SelectorManager] [1s 530ms] SocketTube(4) write: starting subscription
21:27:34.861 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-4-SelectorManager] [1s 531ms] SocketTube(4) write: offloading requestMore
21:27:34.862 DEBUG [Http1Exchange.lambda$sendHeadersAsync$4] - [pool-5-thread-1] [1s 531ms] Http1Exchange setting outgoing with headers
21:27:34.862 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 532ms] HttpClientImpl(4) next timeout: 179974
21:27:34.862 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-5-thread-2] [1s 532ms] Http1AsyncReceiver(SocketTube(4)) downstream subscription demand is 1
21:27:34.862 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 532ms] HttpClientImpl(4) next expired: 0
21:27:34.862 DEBUG [Http1Exchange.appendToOutgoing] - [pool-5-thread-1] [1s 532ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=286 cap=286]], throwable=null]
21:27:34.862 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 532ms] HttpClientImpl(4) Next deadline is 3000
21:27:34.862 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-5-thread-3] [1s 532ms] SocketTube(4) write: requesting more...
21:27:34.862 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-5-thread-1] [1s 532ms] Http1Publisher(SocketTube(4)) WriteTask
21:27:34.862 DEBUG [Http1AsyncReceiver.checkRequestMore] - [pool-5-thread-2] [1s 532ms] Http1AsyncReceiver(SocketTube(4)) checkRequestMore: canRequestMore=true, hasDemand=true
21:27:34.863 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-5-thread-1] [1s 533ms] Http1Publisher(SocketTube(4)) hasOutgoing = true
21:27:34.863 DEBUG [Http1Exchange.getOutgoing] - [pool-5-thread-1] [1s 533ms] Http1Exchange initiating completion of headersSentCF
21:27:34.863 DEBUG [Http1Exchange$Http1Publisher$Http1WriteSubscription.request] - [pool-5-thread-3] [1s 533ms] Http1Publisher(SocketTube(4)) subscription request(1), demand=1
21:27:34.864 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-5-thread-1] [1s 533ms] Http1Publisher(SocketTube(4)) onNext with 286 bytes
21:27:34.864 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [pool-5-thread-1] [1s 534ms] SocketTube(4) trying to write: 286
21:27:34.864 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [pool-5-thread-1] [1s 534ms] SocketTube(4) wrote: 286
21:27:34.863 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.requestMore] - [pool-5-thread-2] [1s 533ms] Http1AsyncReceiver(SocketTube(4)) Http1TubeSubscriber: requesting one more from upstream
21:27:34.865 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-5-thread-1] [1s 535ms] SocketTube(4) write: requesting more...
21:27:34.864 DEBUG [SocketTube.debugState] - [pool-5-thread-3] [1s 534ms] SocketTube(4) leaving requestMore:  Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=1]
21:27:34.865 DEBUG [Http1Exchange$Http1Publisher$Http1WriteSubscription.request] - [pool-5-thread-1] [1s 535ms] Http1Publisher(SocketTube(4)) subscription request(1), demand=1
21:27:34.865 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.request] - [pool-5-thread-2] [1s 535ms] SocketTube(4) got some demand for reading
21:27:34.865 DEBUG [SocketTube.debugState] - [pool-5-thread-1] [1s 535ms] SocketTube(4) leaving requestMore:  Reading: [ops=0, demand=1, stopped=false], Writing: [ops=0, demand=1]
21:27:34.865 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [pool-5-thread-2] [1s 535ms] SocketTube(4) resuming read event
21:27:34.865 DEBUG [SocketTube.debugState] - [pool-5-thread-1] [1s 535ms] SocketTube(4) leaving w.onNext Reading: [ops=0, demand=1, stopped=false], Writing: [ops=0, demand=1]
21:27:34.866 DEBUG [SocketTube.debugState] - [pool-5-thread-2] [1s 535ms] SocketTube(4) leaving request(1):  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
21:27:34.866 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-5-thread-1] [1s 535ms] Http1Publisher(SocketTube(4)) WriteTask
21:27:34.866 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-4-SelectorManager] [1s 536ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@be92925 for 1 (true)
21:27:34.866 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-5-thread-1] [1s 536ms] Http1Publisher(SocketTube(4)) hasOutgoing = false
21:27:34.866 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 536ms] HttpClientImpl(4) next timeout: 179970
21:27:34.866 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 536ms] HttpClientImpl(4) next expired: 0
21:27:34.866 DEBUG [Exchange.checkFor407] - [pool-5-thread-1] [1s 536ms] Exchange checkFor407: all clear
21:27:34.866 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 536ms] HttpClientImpl(4) Next deadline is 3000
21:27:34.866 DEBUG [Exchange.sendRequestBody] - [pool-5-thread-1] [1s 536ms] Exchange sendRequestBody
21:27:34.867 DEBUG [Http1Exchange.sendBodyAsync] - [pool-5-thread-1] [1s 537ms] Http1Exchange sendBodyAsync
21:27:34.867 DEBUG [Http1Exchange.sendBodyAsync] - [pool-5-thread-1] [1s 537ms] Http1Exchange bodySubscriber is null
21:27:34.867 DEBUG [Http1Exchange.appendToOutgoing] - [pool-5-thread-1] [1s 537ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]], throwable=null]
21:27:34.867 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-5-thread-1] [1s 537ms] Http1Publisher(SocketTube(4)) WriteTask
21:27:34.867 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-5-thread-1] [1s 537ms] Http1Publisher(SocketTube(4)) hasOutgoing = true
21:27:34.867 DEBUG [Http1Exchange.getOutgoing] - [pool-5-thread-1] [1s 537ms] Http1Exchange initiating completion of bodySentCF
21:27:34.867 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-5-thread-1] [1s 537ms] Http1Publisher(SocketTube(4)) completed, stopping jdk.internal.net.http.common.SequentialScheduler@56ece67d
21:27:34.867 DEBUG [Utils.lambda$wrapForDebug$8] - [pool-5-thread-1] [1s 537ms] Http1Exchange sendBodyAsync completed successfully
21:27:34.868 DEBUG [Http1Exchange.getResponseAsync] - [pool-5-thread-1] [1s 537ms] Http1Exchange reading headers
21:27:34.868 DEBUG [Http1Response.readHeadersAsync] - [pool-5-thread-1] [1s 538ms] Http1Response(id=4, PlainHttpConnection(SocketTube(4))) Reading Headers: (remaining: 0) READING_HEADERS
21:27:34.868 DEBUG [Http1Response.readHeadersAsync] - [pool-5-thread-1] [1s 538ms] Http1Response(id=4, PlainHttpConnection(SocketTube(4))) First time around
21:27:34.868 DEBUG [Http1Response.readHeadersAsync] - [pool-5-thread-1] [1s 538ms] Http1Response(id=4, PlainHttpConnection(SocketTube(4))) headersReader is not yet completed
21:27:35.237 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-4-SelectorManager] [1s 907ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@be92925 for 0 (false)
21:27:35.237 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-4-SelectorManager] [1s 907ms] SocketTube(4) read bytes: 973
21:27:35.237 DEBUG [Http1AsyncReceiver.asyncReceive] - [HttpClient-4-SelectorManager] [1s 907ms] Http1AsyncReceiver(SocketTube(4)) Putting 973 bytes into the queue
21:27:35.238 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [HttpClient-4-SelectorManager] [1s 907ms] SocketTube(4) resuming read event
21:27:35.238 DEBUG [Http1AsyncReceiver.flush] - [pool-5-thread-1] [1s 907ms] Http1AsyncReceiver(SocketTube(4)) Got 973 bytes for delegate jdk.internal.net.http.Http1Response$HeadersReader@44bc9f9a
21:27:35.238 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-4-SelectorManager] [1s 908ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@be92925 for 1 (false)
21:27:35.238 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-5-thread-1] [1s 908ms] Http1AsyncReceiver(SocketTube(4)) downstream subscription demand is 1
21:27:35.238 DEBUG [SocketTube.debugState] - [HttpClient-4-SelectorManager] [1s 908ms] SocketTube(4) leaving read() loop after onNext:  Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
21:27:35.238 DEBUG [Http1AsyncReceiver.flush] - [pool-5-thread-1] [1s 908ms] Http1AsyncReceiver(SocketTube(4)) Forwarding 973 bytes to delegate jdk.internal.net.http.Http1Response$HeadersReader@44bc9f9a
21:27:35.238 DEBUG [Http1Response$HeadersReader.handle] - [pool-5-thread-1] [1s 908ms] Http1Response(id=4, PlainHttpConnection(SocketTube(4))) Sending 973/973 bytes to header parser
21:27:35.238 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 908ms] HttpClientImpl(4) next timeout: 179598
21:27:35.238 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 908ms] HttpClientImpl(4) next expired: 0
21:27:35.238 DEBUG [Http1Response$HeadersReader.handle] - [pool-5-thread-1] [1s 908ms] Http1Response(id=4, PlainHttpConnection(SocketTube(4))) Parsing headers completed. bytes=40
21:27:35.238 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 908ms] HttpClientImpl(4) Next deadline is 3000
21:27:35.238 DEBUG [Http1AsyncReceiver.unsubscribe] - [pool-5-thread-1] [1s 908ms] Http1AsyncReceiver(SocketTube(4)) Unsubscribed jdk.internal.net.http.Http1Response$HeadersReader@44bc9f9a
21:27:35.238 DEBUG [Http1Response.lambda$readHeadersAsync$0] - [pool-5-thread-1] [1s 908ms] Http1Response(id=4, PlainHttpConnection(SocketTube(4))) Reading Headers: creating Response object; state is now READING_BODY
21:27:35.239 DEBUG [Utils.lambda$wrapForDebug$8] - [pool-5-thread-1] [1s 908ms] Http1Exchange getResponseAsync completed successfully
21:27:35.239 DEBUG [Http1Response.readBody] - [pool-5-thread-1] [1s 909ms] Http1Response(id=4, PlainHttpConnection(SocketTube(4))) readBody: return2Cache: true
21:27:35.239 DEBUG [Http1Response$ClientRefCountTracker.acquire] - [pool-5-thread-1] [1s 909ms] Http1Response(id=4, PlainHttpConnection(SocketTube(4))) Operation started: incrementing ref count for jdk.internal.net.http.HttpClientImpl@12b821a6(4)
21:27:35.239 DEBUG [Http1AsyncReceiver.subscribe] - [pool-5-thread-1] [1s 909ms] Http1AsyncReceiver(SocketTube(4)) Subscribed pending jdk.internal.net.http.Http1Response$BodyReader@582b12d0/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@5c148d0d queue.isEmpty: false
21:27:35.239 DEBUG [Http1AsyncReceiver.flush] - [pool-5-thread-1] [1s 909ms] Http1AsyncReceiver(SocketTube(4)) Delegate done: 933
21:27:35.239 DEBUG [ResponseContent$FixedLengthBodyParser.onSubscribe] - [pool-5-thread-1] [1s 909ms] PlainHttpConnection(SocketTube(4))/ResponseContent/FixedLengthBodyParser length=933, onSubscribe: jdk.internal.net.http.Http1Response$Http1BodySubscriber
21:27:35.239 DEBUG [Http1AsyncReceiver.handlePendingDelegate] - [pool-5-thread-1] [1s 909ms] Http1AsyncReceiver(SocketTube(4)) delegate is now jdk.internal.net.http.Http1Response$BodyReader@582b12d0/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@5c148d0d, demand=9223372036854775807, canRequestMore=false, queue.isEmpty=false
21:27:35.239 DEBUG [Http1AsyncReceiver.flush] - [pool-5-thread-1] [1s 909ms] Http1AsyncReceiver(SocketTube(4)) Got 933 bytes for delegate jdk.internal.net.http.Http1Response$BodyReader@582b12d0/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@5c148d0d
21:27:35.240 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-5-thread-1] [1s 909ms] Http1AsyncReceiver(SocketTube(4)) downstream subscription demand is 9223372036854775807
21:27:35.240 DEBUG [Http1AsyncReceiver.flush] - [pool-5-thread-1] [1s 909ms] Http1AsyncReceiver(SocketTube(4)) Forwarding 933 bytes to delegate jdk.internal.net.http.Http1Response$BodyReader@582b12d0/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@5c148d0d
21:27:35.240 DEBUG [Http1Response$BodyReader.handle] - [pool-5-thread-1] [1s 910ms] Http1Response(id=4, PlainHttpConnection(SocketTube(4))) Sending 933/973 bytes to body parser
21:27:35.240 DEBUG [ResponseContent$FixedLengthBodyParser.accept] - [pool-5-thread-1] [1s 910ms] PlainHttpConnection(SocketTube(4))/ResponseContent/FixedLengthBodyParser Parser got 933 bytes (933 remaining / 933)
21:27:35.240 DEBUG [ResponseContent$FixedLengthBodyParser.accept] - [pool-5-thread-1] [1s 910ms] PlainHttpConnection(SocketTube(4))/ResponseContent/FixedLengthBodyParser Parser got all expected bytes: completing
21:27:35.240 DEBUG [Http1AsyncReceiver.clear] - [pool-5-thread-1] [1s 910ms] Http1AsyncReceiver(SocketTube(4)) cleared
21:27:35.240 DEBUG [Http1Response.onFinished] - [pool-5-thread-1] [1s 910ms] Http1Response(id=4, PlainHttpConnection(SocketTube(4))) SocketTube(4): return to HTTP/1.1 pool
21:27:35.240 DEBUG [ConnectionPool.registerCleanupTrigger] - [pool-5-thread-1] [1s 910ms] ConnectionPool(4) registering CleanupTrigger(SocketTube(4))
21:27:35.240 DEBUG [SocketTube.connectFlows] - [pool-5-thread-1] [1s 910ms] SocketTube(4) connecting flows
21:27:35.240 DEBUG [SocketTube$InternalReadPublisher.subscribe] - [pool-5-thread-1] [1s 910ms] SocketTube(4) read publisher got subscriber
21:27:35.240 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalSubscribe] - [pool-5-thread-1] [1s 910ms] SocketTube(4) registering subscribe event
21:27:35.240 DEBUG [SocketTube.debugState] - [pool-5-thread-1] [1s 910ms] SocketTube(4) leaving read.subscribe:  Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
21:27:35.240 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handleSubscribeEvent] - [HttpClient-4-SelectorManager] [1s 910ms] SocketTube(4) subscribe event raised
21:27:35.240 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-5-thread-1] [1s 910ms] SocketTube(4) subscribed for writing
21:27:35.240 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-4-SelectorManager] [1s 910ms] SocketTube(4) handling pending subscription for CleanupTrigger(SocketTube(4))
21:27:35.240 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.dropSubscription] - [pool-5-thread-1] [1s 910ms] SocketTube(4) write: resetting demand to 0
21:27:35.240 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.dropSubscription] - [HttpClient-4-SelectorManager] [1s 910ms] Http1AsyncReceiver(SocketTube(4)) Http1TubeSubscriber: dropSubscription
21:27:35.241 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-5-thread-1] [1s 910ms] SocketTube(4) write: registering startSubscription event
21:27:35.241 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-4-SelectorManager] [1s 910ms] SocketTube(4) read demand reset to 0
21:27:35.241 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-4-SelectorManager] [1s 911ms] SocketTube(4) calling onSubscribe
21:27:35.241 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.request] - [HttpClient-4-SelectorManager] [1s 911ms] SocketTube(4) got some demand for reading
21:27:35.241 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [HttpClient-4-SelectorManager] [1s 911ms] SocketTube(4) resuming read event
21:27:35.241 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-4-SelectorManager] [1s 911ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@be92925 for 1 (false)
21:27:35.241 DEBUG [SocketTube.debugState] - [HttpClient-4-SelectorManager] [1s 911ms] SocketTube(4) leaving request(1):  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=0]
21:27:35.241 DEBUG [JdkHttpClient.execute] - Ending request (GET) /status in 406ms
21:27:35.241 DEBUG [SocketTube$InternalReadPublisher$ReadSubscription.signalOnSubscribe] - [HttpClient-4-SelectorManager] [1s 911ms] SocketTube(4) onSubscribe called
21:27:35.241 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-4-SelectorManager] [1s 911ms] SocketTube(4) pending subscriber subscribed
21:27:35.241 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=9a0bc236ff144503ef6a16acce5046e7, spanId=a7130565adebc599, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.16.0, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.22.0"}}, instrumentationScopeInfo=InstrumentationScopeInfo{name=default, version=null, schemaUrl=null, attributes={}}, name=httpclient.execute, kind=INTERNAL, startEpochNanos=1678742854834000000, endEpochNanos=1678742855240836669, attributes=AttributesMap{data={http.method=GET, http.status_code=200, span.kind=client, http.target=/status}, capacity=128, totalAddedValues=4}, totalAttributeCount=4, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=OK, description=Kind: OK Description:}, hasEnded=true}
21:27:35.241 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 911ms] HttpClientImpl(4) next timeout: 0
21:27:35.241 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 911ms] HttpClientImpl(4) next expired: 1199759
21:27:35.242 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 911ms] HttpClientImpl(4) Next deadline is 3000
21:27:35.242 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-4-SelectorManager] [1s 911ms] SocketTube(4) write: starting subscription
21:27:35.242 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-4-SelectorManager] [1s 912ms] SocketTube(4) write: offloading requestMore
21:27:35.242 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 912ms] HttpClientImpl(4) next timeout: 0
21:27:35.242 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-5-thread-2] [1s 912ms] SocketTube(4) write: requesting more...
21:27:35.242 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 912ms] HttpClientImpl(4) next expired: 1199758
21:27:35.242 DEBUG [SocketTube.debugState] - [pool-5-thread-2] [1s 912ms] SocketTube(4) leaving requestMore:  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
21:27:35.242 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-4-SelectorManager] [1s 912ms] HttpClientImpl(4) Next deadline is 3000
21:27:35.243 DEBUG [Http1Response.lambda$readBody$2] - [pool-5-thread-1] [1s 913ms] Http1Response(id=4, PlainHttpConnection(SocketTube(4))) Finished reading body: READING_BODY
21:27:35.243 DEBUG [Http1Response$ClientRefCountTracker.tryRelease] - [pool-5-thread-1] [1s 913ms] Http1Response(id=4, PlainHttpConnection(SocketTube(4))) Operation finished: decrementing ref count for jdk.internal.net.http.HttpClientImpl@12b821a6(4)
21:27:35.243 DEBUG [Http1AsyncReceiver.flush] - [pool-5-thread-1] [1s 913ms] Http1AsyncReceiver(SocketTube(4)) Delegate done: 0
21:27:35.243 DEBUG [Http1AsyncReceiver.flush] - [pool-5-thread-1] [1s 913ms] Http1AsyncReceiver(SocketTube(4)) Got 0 bytes for delegate null
21:27:35.243 DEBUG [GridModel.add] - Adding node with id 84889509-e0c3-400f-9427-3b94decec776 and URI http://10.42.0.212:5555
21:27:35.243 DEBUG [LocalDistributor.updateNodeAvailability] - Health check result for http://10.42.0.212:5555 was UP
21:27:35.244 INFO [GridModel.setAvailability] - Switching Node 84889509-e0c3-400f-9427-3b94decec776 (uri: http://10.42.0.212:5555) from DOWN to UP
21:27:35.244 INFO [LocalDistributor.add] - Added node 84889509-e0c3-400f-9427-3b94decec776 at http://10.42.0.212:5555. Health check every 120s
21:27:35.246 INFO [Node.<init>] - Binding additional locator mechanisms: relative
21:27:35.249 DEBUG [HttpClientImpl.<init>] - [Event Bus Listener Notifier] [1s 919ms] HttpClientImpl(5) proxySelector is sun.net.spi.DefaultProxySelector@7ed04d8e (user-supplied=false)
21:27:35.250 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [1s 920ms] HttpClientImpl(5) next timeout: 0
21:27:35.250 DEBUG [HttpTracing.inject] - Injecting (GET) /status into OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@6c3f5566, context={}, span id=0000000000000000, trace id=00000000000000000000000000000000} at org.openqa.selenium.grid.node.remote.RemoteNode:211
21:27:35.250 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [1s 920ms] HttpClientImpl(5) next expired: 0
21:27:35.251 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [1s 921ms] HttpClientImpl(5) Next deadline is 3000
21:27:35.251 DEBUG [JdkHttpClient.execute] - Executing request: (GET) /status
21:27:35.251 DEBUG [HttpClientImpl.sendAsync] - [Event Bus Listener Notifier] [1s 921ms] HttpClientImpl(5) ClientImpl (async) send http://10.42.0.211:5555/status GET
21:27:35.252 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [1s 921ms] HttpClientImpl(5) next timeout: 179999
21:27:35.252 DEBUG [Exchange.establishExchange] - [Event Bus Listener Notifier] [1s 921ms] Exchange establishing exchange for http://10.42.0.211:5555/status GET,
     proxy=null
21:27:35.252 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [1s 922ms] HttpClientImpl(5) next expired: 0
21:27:35.252 DEBUG [Http2ClientImpl.getConnectionFor] - [Event Bus Listener Notifier] [1s 922ms] Http2ClientImpl not found in connection pool
21:27:35.252 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [1s 922ms] HttpClientImpl(5) Next deadline is 3000
21:27:35.252 DEBUG [ExchangeImpl.get] - [Event Bus Listener Notifier] [1s 922ms] ExchangeImpl get: Trying to get HTTP/2 connection
21:27:35.252 DEBUG [ExchangeImpl.createExchangeImpl] - [Event Bus Listener Notifier] [1s 922ms] ExchangeImpl handling HTTP/2 connection creation result
21:27:35.252 DEBUG [ExchangeImpl.createExchangeImpl] - [Event Bus Listener Notifier] [1s 922ms] ExchangeImpl new Http1Exchange, try to upgrade
21:27:35.252 DEBUG [PlainHttpConnection.<init>] - [Event Bus Listener Notifier] [1s 922ms] PlainHttpConnection(?) Initial receive buffer size is: 65536
21:27:35.252 DEBUG [Exchange.checkFor407] - [Event Bus Listener Notifier] [1s 922ms] Exchange checkFor407: all clear
21:27:35.253 DEBUG [Http1Exchange.sendHeadersAsync] - [Event Bus Listener Notifier] [1s 922ms] Http1Exchange Sending headers only
21:27:35.253 DEBUG [Http1AsyncReceiver.subscribe] - [Event Bus Listener Notifier] [1s 922ms] Http1AsyncReceiver(SocketTube(5)) Subscribed pending jdk.internal.net.http.Http1Response$HeadersReader@4f856e97 queue.isEmpty: true
21:27:35.253 DEBUG [Http1AsyncReceiver.handlePendingDelegate] - [Event Bus Listener Notifier] [1s 923ms] Http1AsyncReceiver(SocketTube(5)) delegate is now jdk.internal.net.http.Http1Response$HeadersReader@4f856e97, demand=1, canRequestMore=true, queue.isEmpty=true
21:27:35.253 DEBUG [Http1AsyncReceiver.hasDemand] - [Event Bus Listener Notifier] [1s 923ms] Http1AsyncReceiver(SocketTube(5)) downstream subscription demand is 1
21:27:35.253 DEBUG [Http1AsyncReceiver.checkRequestMore] - [Event Bus Listener Notifier] [1s 923ms] Http1AsyncReceiver(SocketTube(5)) checkRequestMore: canRequestMore=true, hasDemand=true
21:27:35.253 DEBUG [Http1AsyncReceiver.hasDemand] - [Event Bus Listener Notifier] [1s 923ms] Http1AsyncReceiver(SocketTube(5)) downstream subscription demand is 1
21:27:35.253 DEBUG [Http1AsyncReceiver.checkRequestMore] - [Event Bus Listener Notifier] [1s 923ms] Http1AsyncReceiver(SocketTube(5)) checkRequestMore: canRequestMore=true, hasDemand=true
21:27:35.253 DEBUG [Http1Exchange.sendHeadersAsync] - [Event Bus Listener Notifier] [1s 923ms] Http1Exchange response created in advance
21:27:35.253 DEBUG [Http1Exchange.sendHeadersAsync] - [Event Bus Listener Notifier] [1s 923ms] Http1Exchange initiating connect async
21:27:35.253 DEBUG [PlainHttpConnection.connectAsync] - [Event Bus Listener Notifier] [1s 923ms] PlainHttpConnection(SocketTube(5)) registering connect timer: ConnectTimerEvent, TimeoutEvent[id=10, duration=PT10S, deadline=2023-03-13T21:27:45.253507Z]
21:27:35.253 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [1s 923ms] HttpClientImpl(5) next timeout: 10000
21:27:35.253 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [1s 923ms] HttpClientImpl(5) next expired: 0
21:27:35.253 DEBUG [PlainHttpConnection.connectAsync] - [Event Bus Listener Notifier] [1s 923ms] PlainHttpConnection(SocketTube(5)) registering connect event
21:27:35.253 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [1s 923ms] HttpClientImpl(5) Next deadline is 3000
21:27:35.254 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-5-SelectorManager] [1s 923ms] SelectorAttachment Registering jdk.internal.net.http.PlainHttpConnection$ConnectEvent@37f312f6 for 8 (true)
21:27:35.254 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [1s 924ms] HttpClientImpl(5) next timeout: 9999
21:27:35.254 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [1s 924ms] HttpClientImpl(5) next expired: 0
21:27:35.254 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [1s 924ms] HttpClientImpl(5) Next deadline is 3000
21:27:35.254 DEBUG [PlainHttpConnection$ConnectEvent.handle] - [HttpClient-5-SelectorManager] [1s 924ms] PlainHttpConnection(SocketTube(5)) ConnectEvent: finishing connect
21:27:35.254 DEBUG [PlainHttpConnection$ConnectEvent.handle] - [HttpClient-5-SelectorManager] [1s 924ms] PlainHttpConnection(SocketTube(5)) ConnectEvent: connect finished: true Local addr: /10.42.0.210:33222
21:27:35.254 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [1s 924ms] HttpClientImpl(5) next timeout: 9999
21:27:35.255 DEBUG [PlainHttpConnection.finishConnect] - [pool-6-thread-1] [1s 924ms] PlainHttpConnection(SocketTube(5)) finishConnect, setting connected=true
21:27:35.255 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [1s 924ms] HttpClientImpl(5) next expired: 0
21:27:35.255 DEBUG [Http1Exchange.connectFlows] - [pool-6-thread-1] [1s 925ms] Http1Exchange SocketTube(5) connecting flows
21:27:35.255 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [1s 925ms] HttpClientImpl(5) Next deadline is 3000
21:27:35.256 DEBUG [SocketTube.connectFlows] - [pool-6-thread-1] [1s 925ms] SocketTube(5) connecting flows
21:27:35.256 DEBUG [SocketTube$InternalReadPublisher.subscribe] - [pool-6-thread-1] [1s 926ms] SocketTube(5) read publisher got subscriber
21:27:35.256 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalSubscribe] - [pool-6-thread-1] [1s 926ms] SocketTube(5) registering subscribe event
21:27:35.256 DEBUG [SocketTube.debugState] - [pool-6-thread-1] [1s 926ms] SocketTube(5) leaving read.subscribe:  Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=0]
21:27:35.256 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handleSubscribeEvent] - [HttpClient-5-SelectorManager] [1s 926ms] SocketTube(5) subscribe event raised
21:27:35.256 DEBUG [Http1Exchange$Http1Publisher.subscribe] - [pool-6-thread-1] [1s 926ms] Http1Publisher(SocketTube(5)) got subscriber: SocketTube(5)
21:27:35.256 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-5-SelectorManager] [1s 926ms] SocketTube(5) handling pending subscription for jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber@7809e043
21:27:35.256 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-6-thread-1] [1s 926ms] SocketTube(5) subscribed for writing
21:27:35.256 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-5-SelectorManager] [1s 926ms] SocketTube(5) read demand reset to 0
21:27:35.256 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-6-thread-1] [1s 926ms] SocketTube(5) write: registering startSubscription event
21:27:35.256 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-5-SelectorManager] [1s 926ms] SocketTube(5) calling onSubscribe
21:27:35.256 DEBUG [Http1Exchange.lambda$sendHeadersAsync$4] - [pool-6-thread-1] [1s 926ms] Http1Exchange requestAction.headers
21:27:35.256 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.onSubscribe] - [HttpClient-5-SelectorManager] [1s 926ms] Http1AsyncReceiver(SocketTube(5)) Received onSubscribed from upstream
21:27:35.257 DEBUG [Http1Exchange.lambda$sendHeadersAsync$4] - [pool-6-thread-1] [1s 927ms] Http1Exchange setting outgoing with headers
21:27:35.257 DEBUG [SocketTube$InternalReadPublisher$ReadSubscription.signalOnSubscribe] - [HttpClient-5-SelectorManager] [1s 927ms] SocketTube(5) onSubscribe called
21:27:35.257 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-5-SelectorManager] [1s 927ms] SocketTube(5) pending subscriber subscribed
21:27:35.257 DEBUG [Http1Exchange.appendToOutgoing] - [pool-6-thread-1] [1s 927ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=286 cap=286]], throwable=null]
21:27:35.257 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-6-thread-2] [1s 927ms] Http1AsyncReceiver(SocketTube(5)) downstream subscription demand is 1
21:27:35.257 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-6-thread-1] [1s 927ms] Http1Publisher(SocketTube(5)) WriteTask
21:27:35.257 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [1s 927ms] HttpClientImpl(5) next timeout: 179994
21:27:35.257 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-6-thread-1] [1s 927ms] Http1Publisher(SocketTube(5)) hasOutgoing = true
21:27:35.257 DEBUG [Http1AsyncReceiver.checkRequestMore] - [pool-6-thread-2] [1s 927ms] Http1AsyncReceiver(SocketTube(5)) checkRequestMore: canRequestMore=true, hasDemand=true
21:27:35.257 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [1s 927ms] HttpClientImpl(5) next expired: 0
21:27:35.258 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.requestMore] - [pool-6-thread-2] [1s 928ms] Http1AsyncReceiver(SocketTube(5)) Http1TubeSubscriber: requesting one more from upstream
21:27:35.258 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [1s 928ms] HttpClientImpl(5) Next deadline is 3000
21:27:35.258 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.request] - [pool-6-thread-2] [1s 928ms] SocketTube(5) got some demand for reading
21:27:35.258 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-5-SelectorManager] [1s 928ms] SocketTube(5) write: starting subscription
21:27:35.258 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [pool-6-thread-2] [1s 928ms] SocketTube(5) resuming read event
21:27:35.258 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-5-SelectorManager] [1s 928ms] SocketTube(5) write: offloading requestMore
21:27:35.258 DEBUG [SocketTube.debugState] - [pool-6-thread-2] [1s 928ms] SocketTube(5) leaving request(1):  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=0]
21:27:35.258 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-6-thread-1] [1s 928ms] SocketTube(5) write: requesting more...
21:27:35.258 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [1s 928ms] HttpClientImpl(5) next timeout: 179993
21:27:35.259 DEBUG [Http1Exchange$Http1Publisher$Http1WriteSubscription.request] - [pool-6-thread-1] [1s 928ms] Http1Publisher(SocketTube(5)) subscription request(1), demand=1
21:27:35.259 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [1s 929ms] HttpClientImpl(5) next expired: 0
21:27:35.259 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [1s 929ms] HttpClientImpl(5) Next deadline is 3000
21:27:35.259 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-6-thread-1] [1s 929ms] Http1Publisher(SocketTube(5)) WriteTask
21:27:35.259 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-5-SelectorManager] [1s 929ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@49bb7ebc for 1 (true)
21:27:35.259 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-6-thread-1] [1s 929ms] Http1Publisher(SocketTube(5)) hasOutgoing = true
21:27:35.259 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [1s 929ms] HttpClientImpl(5) next timeout: 179992
21:27:35.259 DEBUG [Http1Exchange.getOutgoing] - [pool-6-thread-1] [1s 929ms] Http1Exchange initiating completion of headersSentCF
21:27:35.259 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [1s 929ms] HttpClientImpl(5) next expired: 0
21:27:35.260 DEBUG [Exchange.checkFor407] - [pool-6-thread-1] [1s 929ms] Exchange checkFor407: all clear
21:27:35.260 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [1s 929ms] HttpClientImpl(5) Next deadline is 3000
21:27:35.260 DEBUG [Exchange.sendRequestBody] - [pool-6-thread-1] [1s 930ms] Exchange sendRequestBody
21:27:35.260 DEBUG [Http1Exchange.sendBodyAsync] - [pool-6-thread-1] [1s 930ms] Http1Exchange sendBodyAsync
21:27:35.260 DEBUG [Http1Exchange.sendBodyAsync] - [pool-6-thread-1] [1s 930ms] Http1Exchange bodySubscriber is null
21:27:35.260 DEBUG [Http1Exchange.appendToOutgoing] - [pool-6-thread-1] [1s 930ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]], throwable=null]
21:27:35.260 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-6-thread-1] [1s 930ms] Http1Publisher(SocketTube(5)) onNext with 286 bytes
21:27:35.260 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [pool-6-thread-1] [1s 930ms] SocketTube(5) trying to write: 286
21:27:35.261 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [pool-6-thread-1] [1s 931ms] SocketTube(5) wrote: 286
21:27:35.261 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-6-thread-1] [1s 931ms] SocketTube(5) write: requesting more...
21:27:35.261 DEBUG [Http1Exchange$Http1Publisher$Http1WriteSubscription.request] - [pool-6-thread-1] [1s 931ms] Http1Publisher(SocketTube(5)) subscription request(1), demand=1
21:27:35.261 DEBUG [SocketTube.debugState] - [pool-6-thread-1] [1s 931ms] SocketTube(5) leaving requestMore:  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
21:27:35.261 DEBUG [SocketTube.debugState] - [pool-6-thread-1] [1s 931ms] SocketTube(5) leaving w.onNext Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
21:27:35.261 DEBUG [Http1Exchange.getOutgoing] - [pool-6-thread-1] [1s 931ms] Http1Exchange initiating completion of bodySentCF
21:27:35.261 DEBUG [Utils.lambda$wrapForDebug$8] - [pool-6-thread-1] [1s 931ms] Http1Exchange sendBodyAsync completed successfully
21:27:35.261 DEBUG [Http1Exchange.getResponseAsync] - [pool-6-thread-1] [1s 931ms] Http1Exchange reading headers
21:27:35.261 DEBUG [Http1Response.readHeadersAsync] - [pool-6-thread-1] [1s 931ms] Http1Response(id=5, PlainHttpConnection(SocketTube(5))) Reading Headers: (remaining: 0) READING_HEADERS
21:27:35.261 DEBUG [Http1Response.readHeadersAsync] - [pool-6-thread-1] [1s 931ms] Http1Response(id=5, PlainHttpConnection(SocketTube(5))) First time around
21:27:35.262 DEBUG [Http1Response.readHeadersAsync] - [pool-6-thread-1] [1s 931ms] Http1Response(id=5, PlainHttpConnection(SocketTube(5))) headersReader is not yet completed
21:27:35.262 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-6-thread-1] [1s 932ms] Http1Publisher(SocketTube(5)) completed, stopping jdk.internal.net.http.common.SequentialScheduler@1be62e93
21:27:35.262 DEBUG [SocketTube.debugState] - [pool-6-thread-1] [1s 932ms] SocketTube(5) leaving requestMore:  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
21:27:35.621 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-5-SelectorManager] [2s 291ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@49bb7ebc for 0 (false)
21:27:35.621 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-5-SelectorManager] [2s 291ms] SocketTube(5) read bytes: 973
21:27:35.621 DEBUG [Http1AsyncReceiver.asyncReceive] - [HttpClient-5-SelectorManager] [2s 291ms] Http1AsyncReceiver(SocketTube(5)) Putting 973 bytes into the queue
21:27:35.622 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [HttpClient-5-SelectorManager] [2s 291ms] SocketTube(5) resuming read event
21:27:35.622 DEBUG [Http1AsyncReceiver.flush] - [pool-6-thread-1] [2s 292ms] Http1AsyncReceiver(SocketTube(5)) Got 973 bytes for delegate jdk.internal.net.http.Http1Response$HeadersReader@4f856e97
21:27:35.622 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-5-SelectorManager] [2s 292ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@49bb7ebc for 1 (false)
21:27:35.622 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-6-thread-1] [2s 292ms] Http1AsyncReceiver(SocketTube(5)) downstream subscription demand is 1
21:27:35.622 DEBUG [SocketTube.debugState] - [HttpClient-5-SelectorManager] [2s 292ms] SocketTube(5) leaving read() loop after onNext:  Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
21:27:35.622 DEBUG [Http1AsyncReceiver.flush] - [pool-6-thread-1] [2s 292ms] Http1AsyncReceiver(SocketTube(5)) Forwarding 973 bytes to delegate jdk.internal.net.http.Http1Response$HeadersReader@4f856e97
21:27:35.622 DEBUG [Http1Response$HeadersReader.handle] - [pool-6-thread-1] [2s 292ms] Http1Response(id=5, PlainHttpConnection(SocketTube(5))) Sending 973/973 bytes to header parser
21:27:35.623 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [2s 292ms] HttpClientImpl(5) next timeout: 179629
21:27:35.623 DEBUG [Http1Response$HeadersReader.handle] - [pool-6-thread-1] [2s 293ms] Http1Response(id=5, PlainHttpConnection(SocketTube(5))) Parsing headers completed. bytes=40
21:27:35.623 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [2s 293ms] HttpClientImpl(5) next expired: 0
21:27:35.623 DEBUG [Http1AsyncReceiver.unsubscribe] - [pool-6-thread-1] [2s 293ms] Http1AsyncReceiver(SocketTube(5)) Unsubscribed jdk.internal.net.http.Http1Response$HeadersReader@4f856e97
21:27:35.623 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [2s 293ms] HttpClientImpl(5) Next deadline is 3000
21:27:35.623 DEBUG [Http1Response.lambda$readHeadersAsync$0] - [pool-6-thread-1] [2s 293ms] Http1Response(id=5, PlainHttpConnection(SocketTube(5))) Reading Headers: creating Response object; state is now READING_BODY
21:27:35.624 DEBUG [Utils.lambda$wrapForDebug$8] - [pool-6-thread-1] [2s 293ms] Http1Exchange getResponseAsync completed successfully
21:27:35.624 DEBUG [Http1Response.readBody] - [pool-6-thread-1] [2s 294ms] Http1Response(id=5, PlainHttpConnection(SocketTube(5))) readBody: return2Cache: true
21:27:35.625 DEBUG [Http1Response$ClientRefCountTracker.acquire] - [pool-6-thread-1] [2s 294ms] Http1Response(id=5, PlainHttpConnection(SocketTube(5))) Operation started: incrementing ref count for jdk.internal.net.http.HttpClientImpl@6056a8db(5)
21:27:35.625 DEBUG [Http1AsyncReceiver.subscribe] - [pool-6-thread-1] [2s 295ms] Http1AsyncReceiver(SocketTube(5)) Subscribed pending jdk.internal.net.http.Http1Response$BodyReader@1521c39f/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@111e45e3 queue.isEmpty: false
21:27:35.625 DEBUG [Http1AsyncReceiver.flush] - [pool-6-thread-1] [2s 295ms] Http1AsyncReceiver(SocketTube(5)) Delegate done: 933
21:27:35.625 DEBUG [ResponseContent$FixedLengthBodyParser.onSubscribe] - [pool-6-thread-1] [2s 295ms] PlainHttpConnection(SocketTube(5))/ResponseContent/FixedLengthBodyParser length=933, onSubscribe: jdk.internal.net.http.Http1Response$Http1BodySubscriber
21:27:35.625 DEBUG [Http1AsyncReceiver.handlePendingDelegate] - [pool-6-thread-1] [2s 295ms] Http1AsyncReceiver(SocketTube(5)) delegate is now jdk.internal.net.http.Http1Response$BodyReader@1521c39f/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@111e45e3, demand=9223372036854775807, canRequestMore=false, queue.isEmpty=false
21:27:35.625 DEBUG [Http1AsyncReceiver.flush] - [pool-6-thread-1] [2s 295ms] Http1AsyncReceiver(SocketTube(5)) Got 933 bytes for delegate jdk.internal.net.http.Http1Response$BodyReader@1521c39f/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@111e45e3
21:27:35.625 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-6-thread-1] [2s 295ms] Http1AsyncReceiver(SocketTube(5)) downstream subscription demand is 9223372036854775807
21:27:35.626 DEBUG [Http1AsyncReceiver.flush] - [pool-6-thread-1] [2s 295ms] Http1AsyncReceiver(SocketTube(5)) Forwarding 933 bytes to delegate jdk.internal.net.http.Http1Response$BodyReader@1521c39f/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@111e45e3
21:27:35.626 DEBUG [Http1Response$BodyReader.handle] - [pool-6-thread-1] [2s 296ms] Http1Response(id=5, PlainHttpConnection(SocketTube(5))) Sending 933/973 bytes to body parser
21:27:35.626 DEBUG [ResponseContent$FixedLengthBodyParser.accept] - [pool-6-thread-1] [2s 296ms] PlainHttpConnection(SocketTube(5))/ResponseContent/FixedLengthBodyParser Parser got 933 bytes (933 remaining / 933)
21:27:35.626 DEBUG [ResponseContent$FixedLengthBodyParser.accept] - [pool-6-thread-1] [2s 296ms] PlainHttpConnection(SocketTube(5))/ResponseContent/FixedLengthBodyParser Parser got all expected bytes: completing
21:27:35.626 DEBUG [Http1AsyncReceiver.clear] - [pool-6-thread-1] [2s 296ms] Http1AsyncReceiver(SocketTube(5)) cleared
21:27:35.626 DEBUG [Http1Response.onFinished] - [pool-6-thread-1] [2s 296ms] Http1Response(id=5, PlainHttpConnection(SocketTube(5))) SocketTube(5): return to HTTP/1.1 pool
21:27:35.627 DEBUG [ConnectionPool.registerCleanupTrigger] - [pool-6-thread-1] [2s 296ms] ConnectionPool(5) registering CleanupTrigger(SocketTube(5))
21:27:35.627 DEBUG [SocketTube.connectFlows] - [pool-6-thread-1] [2s 297ms] SocketTube(5) connecting flows
21:27:35.627 DEBUG [SocketTube$InternalReadPublisher.subscribe] - [pool-6-thread-1] [2s 297ms] SocketTube(5) read publisher got subscriber
21:27:35.627 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalSubscribe] - [pool-6-thread-1] [2s 297ms] SocketTube(5) registering subscribe event
21:27:35.627 DEBUG [SocketTube.debugState] - [pool-6-thread-1] [2s 297ms] SocketTube(5) leaving read.subscribe:  Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
21:27:35.627 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handleSubscribeEvent] - [HttpClient-5-SelectorManager] [2s 297ms] SocketTube(5) subscribe event raised
21:27:35.627 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-6-thread-1] [2s 297ms] SocketTube(5) subscribed for writing
21:27:35.627 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-5-SelectorManager] [2s 297ms] SocketTube(5) handling pending subscription for CleanupTrigger(SocketTube(5))
21:27:35.627 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.dropSubscription] - [pool-6-thread-1] [2s 297ms] SocketTube(5) write: resetting demand to 0
21:27:35.627 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.dropSubscription] - [HttpClient-5-SelectorManager] [2s 297ms] Http1AsyncReceiver(SocketTube(5)) Http1TubeSubscriber: dropSubscription
21:27:35.628 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-6-thread-1] [2s 297ms] SocketTube(5) write: registering startSubscription event
21:27:35.628 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-5-SelectorManager] [2s 298ms] SocketTube(5) read demand reset to 0
21:27:35.628 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-5-SelectorManager] [2s 298ms] SocketTube(5) calling onSubscribe
21:27:35.628 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.request] - [HttpClient-5-SelectorManager] [2s 298ms] SocketTube(5) got some demand for reading
21:27:35.628 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [HttpClient-5-SelectorManager] [2s 298ms] SocketTube(5) resuming read event
21:27:35.628 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-5-SelectorManager] [2s 298ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@49bb7ebc for 1 (false)
21:27:35.628 DEBUG [Http1Response.lambda$readBody$2] - [pool-6-thread-1] [2s 298ms] Http1Response(id=5, PlainHttpConnection(SocketTube(5))) Finished reading body: READING_BODY
21:27:35.629 DEBUG [JdkHttpClient.execute] - Ending request (GET) /status in 378ms
21:27:35.628 DEBUG [SocketTube.debugState] - [HttpClient-5-SelectorManager] [2s 298ms] SocketTube(5) leaving request(1):  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=0]
21:27:35.629 DEBUG [Http1Response$ClientRefCountTracker.tryRelease] - [pool-6-thread-1] [2s 299ms] Http1Response(id=5, PlainHttpConnection(SocketTube(5))) Operation finished: decrementing ref count for jdk.internal.net.http.HttpClientImpl@6056a8db(5)
21:27:35.629 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=2f2c17fe8cfcccd88efe1fda6933efcc, spanId=289e9a2747164b71, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.16.0, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.22.0"}}, instrumentationScopeInfo=InstrumentationScopeInfo{name=default, version=null, schemaUrl=null, attributes={}}, name=httpclient.execute, kind=INTERNAL, startEpochNanos=1678742855251000000, endEpochNanos=1678742855629206839, attributes=AttributesMap{data={http.method=GET, http.status_code=200, span.kind=client, http.target=/status}, capacity=128, totalAddedValues=4}, totalAttributeCount=4, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=OK, description=Kind: OK Description:}, hasEnded=true}
21:27:35.629 DEBUG [SocketTube$InternalReadPublisher$ReadSubscription.signalOnSubscribe] - [HttpClient-5-SelectorManager] [2s 299ms] SocketTube(5) onSubscribe called
21:27:35.629 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-5-SelectorManager] [2s 299ms] SocketTube(5) pending subscriber subscribed
21:27:35.630 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [2s 299ms] HttpClientImpl(5) next timeout: 0
21:27:35.630 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [2s 300ms] HttpClientImpl(5) next expired: 1199370
21:27:35.630 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [2s 300ms] HttpClientImpl(5) Next deadline is 3000
21:27:35.630 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-5-SelectorManager] [2s 300ms] SocketTube(5) write: starting subscription
21:27:35.630 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-5-SelectorManager] [2s 300ms] SocketTube(5) write: offloading requestMore
21:27:35.629 DEBUG [Http1AsyncReceiver.flush] - [pool-6-thread-1] [2s 299ms] Http1AsyncReceiver(SocketTube(5)) Delegate done: 0
21:27:35.631 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-6-thread-2] [2s 300ms] SocketTube(5) write: requesting more...
21:27:35.631 DEBUG [SocketTube.debugState] - [pool-6-thread-2] [2s 301ms] SocketTube(5) leaving requestMore:  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
21:27:35.630 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [2s 300ms] HttpClientImpl(5) next timeout: 0
21:27:35.631 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [2s 301ms] HttpClientImpl(5) next expired: 1199369
21:27:35.631 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-5-SelectorManager] [2s 301ms] HttpClientImpl(5) Next deadline is 3000
21:27:35.631 DEBUG [Http1AsyncReceiver.flush] - [pool-6-thread-1] [2s 301ms] Http1AsyncReceiver(SocketTube(5)) Got 0 bytes for delegate null
21:27:35.632 DEBUG [GridModel.add] - Adding node with id 7b0db9a6-e1b1-4d95-a4a5-aea8cbb4697b and URI http://10.42.0.211:5555
21:27:35.632 DEBUG [LocalDistributor.updateNodeAvailability] - Health check result for http://10.42.0.211:5555 was UP
21:27:35.632 INFO [GridModel.setAvailability] - Switching Node 7b0db9a6-e1b1-4d95-a4a5-aea8cbb4697b (uri: http://10.42.0.211:5555) from DOWN to UP
21:27:35.632 INFO [LocalDistributor.add] - Added node 7b0db9a6-e1b1-4d95-a4a5-aea8cbb4697b at http://10.42.0.211:5555. Health check every 120s
diemol commented 1 year ago

@flokain not sure how to help? Could you please give any pointers on what needs to be done? We do not have a k3 environment so we are unaware of what might be the differences between eks and k3.

flokain commented 1 year ago

hi @diemol, I understand. I think it might be related to the technical process of a node registering with the hub. My suspicion is that there is a different configuration on the eks nodes with AWS flavored linux systems and my laptop which runs k3s. TO be more precisely it might be on the TCP config that in a container could be inherited from the host. For example a timeout for half open connections.

two ways i think would be of help:

Also to provide more detail on how this impacts us:

we have a dev setup that tries to mimic other stages as close as possible. we therefore are able to run e2e tests on developers machines. Whenever one does so this bootstraps selenium grid and launches webdriverio in another pod to run tests. unfortunately this does not work if the tests start before any node are registered with the hub. even if they register later one the tests run in a connectionRetryTimeout.

It would be awesome if there wasnt a strict dependency here or at least have the launch time as short as possible. Currently we have a work around, where we restart the pods after hub is operational. Maybe there should be (an option for) readiness probe in the container startup of a node to check if it can reach the hub and set the timeout there?.

diemol commented 1 year ago

The Nodes register by sending a message to the EventBus via TCP, which is then received by the Distributor (a component inside the Hub), and after the Distributor reads the message, it proceeds to confirm the Node presence by doing an HTTP request to the /status endpoint in the Node.

If you enable the FINE log level, you should be able to see how the Distributor tries to reach out the Node to complete the registration. If you do not see any activity, it might be that the Nodes cannot connect to the Event Bus. Also, the flow mentioned above means that the start up order does not matter. If Nodes come up first, they will send the message every 10 seconds during 2 minutes until they register (those values are configurable), so with that, when the Hub comes up, they should all connect.

Registration issues are most of the time related to network configuration and the log gives pointers where to look.

diemol commented 1 year ago

Closing as no more feedback was provided.

github-actions[bot] commented 10 months 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.