pixie icon indicating copy to clipboard operation
pixie copied to clipboard
verified publisher icon pixie-io

Add support for tracing tls traffic from finagle (netty based) services

Open ddelnano opened this issue 3 years ago • 4 comments

This PR will complete the initial support of #407 and is a refresh of an earlier proof of concept change (https://github.com/pixie-io/pixie/pull/463).

The goal is to provide an extensible way for supporting other boringssl based tracing targets if the target binary supports the following:

  • Ability to determine the target binary's openssl version through the RawFptrManager or through dlsym
  • The boringssl implementation populate's openssl's bio_st data structure with the fd of the socket file descriptor (like I did with netty - https://github.com/netty/netty-tcnative/pull/731).

This won't work for envoy's case, but the hope is that this is more similar to Pixie's dynamic openssl tracing while envoy is more similar to nodejs (requiring additional application specific integration).

Testing

New test verifies that TLS tracing is successful (output below) vagrant@vagrant:/vagrant$ ./scripts/sudo_bazel_run.sh -c dbg src/stirling/source_connectors/socket_tracer:thriftmux_openssl_trace_bpf_test INFO: Analyzed target //src/stirling/source_connectors/socket_tracer:thriftmux_openssl_trace_bpf_test (2 packages loaded, 329 targets configured). INFO: Found 1 target... Target //src/stirling/source_connectors/socket_tracer:thriftmux_openssl_trace_bpf_test up-to-date: bazel-bin/src/stirling/source_connectors/socket_tracer/thriftmux_openssl_trace_bpf_test INFO: Elapsed time: 23.604s, Critical Path: 12.10s INFO: 3 processes: 1 internal, 2 linux-sandbox. INFO: Build completed successfully, 3 total actions INFO: Build completed successfully, 3 total actions exec ${PAGER:-/usr/bin/less} "$0" || exit 1 Executing tests from //src/stirling/source_connectors/socket_tracer:thriftmux_openssl_trace_bpf_test ----------------------------------------------------------------------------- I20220817 06:45:16.290016 243447 env.cc:47] Started: src/stirling/source_connectors/socket_tracer/thriftmux_openssl_trace_bpf_test [==========] Running 1 test from 1 test suite. [----------] Global test environment set-up. [----------] 1 test from OpenSSLTraceRawFptrsTest/0, where TypeParam = px::stirling::ThriftMuxServerContainerWrapper [ RUN ] OpenSSLTraceRawFptrsTest/0.mtls_thriftmux_client I20220817 06:45:17.457741 243447 container_runner.cc:43] Loaded image: bazel/src/stirling/source_connectors/socket_tracer/testing/containers/thriftmux:server_image I20220817 06:45:17.457787 243447 container_runner.cc:121] docker run --rm --pid=host --name=thriftmux_server_445962533992195 bazel/src/stirling/source_connectors/socket_tracer/testing/containers/thriftmux:server_image --use-tls true Error: No such object: thriftmux_server_445962533992195 I20220817 06:45:17.615180 243447 container_runner.cc:160] Container thriftmux_server_445962533992195 status: I20220817 06:45:17.615226 243447 container_runner.cc:169] Container thriftmux_server_445962533992195 not yet running, will try again (60 attempts remaining). I20220817 06:45:18.659492 243447 container_runner.cc:160] Container thriftmux_server_445962533992195 status: running I20220817 06:45:18.730299 243447 container_runner.cc:191] Container thriftmux_server_445962533992195 process PID: 243532 I20220817 06:45:18.730358 243447 container_runner.cc:193] Container thriftmux_server_445962533992195 waiting for log message: Finagle version I20220817 06:45:18.810045 243447 container_runner.cc:205] Container thriftmux_server_445962533992195 status: running I20220817 06:45:18.810093 243447 container_runner.cc:218] Container thriftmux_server_445962533992195 not in ready state, will try again (59 attempts remaining). I20220817 06:45:19.842669 243447 container_runner.cc:205] Container thriftmux_server_445962533992195 status: running I20220817 06:45:19.842713 243447 container_runner.cc:241] Container thriftmux_server_445962533992195 is ready. Warning: use -cacerts option to access cacerts keystore Certificate was added to keystore I20220817 06:45:20.214411 243447 thriftmux_openssl_trace_bpf_test.cc:102] keytool -importcert command output: '' WARNING: An illegal reflective access operation has occurred WARNING: Illegal reflective access by com.twitter.jvm.Hotspot (file:/app/maven/v1/https/repo1.maven.org/maven2/com/twitter/util-jvm_2.13/22.7.0/util-jvm_2.13-22.7.0.jar) to field sun.management.ManagementFactoryHelper.jvm WARNING: Please consider reporting this to the maintainers of com.twitter.jvm.Hotspot WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations WARNING: All illegal access operations will be denied in a future release Aug 17, 2022 6:45:21 AM com.twitter.finagle.Init$ $anonfun$once$1 INFO: Finagle version 22.7.0 (rev=4d10525ef4fe89732bcfec6286fac7fe426e9082) built at 20220728-183850 Aug 17, 2022 6:45:21 AM com.twitter.finagle.FixedInetResolver$ factory$lzycompute INFO: Successfully loaded a fixed inet resolver: com.twitter.finagle.netty4.FixedNetty4InetResolver$Factory@470a659f Aug 17, 2022 6:45:21 AM com.twitter.finagle.BaseResolver inetResolver$lzycompute INFO: Using default inet resolver Aug 17, 2022 6:45:21 AM com.twitter.finagle.InetResolver$ factory$lzycompute INFO: Successfully loaded an inet resolver: com.twitter.finagle.netty4.Netty4InetResolver$Factory@5ac6c4f2 Aug 17, 2022 6:45:21 AM com.twitter.finagle.BaseResolver $anonfun$resolvers$3 INFO: Resolver[inet] = com.twitter.finagle.InetResolver(com.twitter.finagle.InetResolver@5fbdc49b) Aug 17, 2022 6:45:21 AM com.twitter.finagle.BaseResolver $anonfun$resolvers$3 INFO: Resolver[fixedinet] = com.twitter.finagle.FixedInetResolver(com.twitter.finagle.FixedInetResolver@65753040) Aug 17, 2022 6:45:21 AM com.twitter.finagle.BaseResolver $anonfun$resolvers$3 INFO: Resolver[neg] = com.twitter.finagle.NegResolver$(com.twitter.finagle.NegResolver$@2954b5ea) Aug 17, 2022 6:45:21 AM com.twitter.finagle.BaseResolver $anonfun$resolvers$3 INFO: Resolver[nil] = com.twitter.finagle.NilResolver$(com.twitter.finagle.NilResolver$@4acb2510) Aug 17, 2022 6:45:21 AM com.twitter.finagle.BaseResolver $anonfun$resolvers$3 INFO: Resolver[fail] = com.twitter.finagle.FailResolver$(com.twitter.finagle.FailResolver$@7be3a9ce) I20220817 06:45:23.707464 243447 thriftmux_openssl_trace_bpf_test.cc:109] thriftmux client command output: '243649 06:45:21.059 [main] DEBUG io.netty.util.internal.logging.InternalLoggerFactory - Using SLF4J as the default logging framework 06:45:21.062 [main] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.level: simple 06:45:21.062 [main] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.targetRecords: 4 06:45:21.075 [main] DEBUG io.netty.util.internal.PlatformDependent0 - -Dio.netty.noUnsafe: false 06:45:21.075 [main] DEBUG io.netty.util.internal.PlatformDependent0 - Java version: 11 06:45:21.076 [main] DEBUG io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.theUnsafe: available 06:45:21.077 [main] DEBUG io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.copyMemory: available 06:45:21.077 [main] DEBUG io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.storeFence: available 06:45:21.078 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.Buffer.address: available 06:45:21.078 [main] DEBUG io.netty.util.internal.PlatformDependent0 - direct buffer constructor: unavailable: Reflective setAccessible(true) disabled 06:45:21.079 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.Bits.unaligned: available, true 06:45:21.080 [main] DEBUG io.netty.util.internal.PlatformDependent0 - 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 @4f49f6af 06:45:21.080 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.DirectByteBuffer.(long, int): unavailable 06:45:21.081 [main] DEBUG io.netty.util.internal.PlatformDependent - sun.misc.Unsafe: available 06:45:21.081 [main] DEBUG io.netty.util.internal.PlatformDependent - maxDirectMemory: 2084569088 bytes (maybe) 06:45:21.082 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.tmpdir: /tmp (java.io.tmpdir) 06:45:21.082 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.bitMode: 64 (sun.arch.data.model) 06:45:21.083 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.maxDirectMemory: -1 bytes 06:45:21.083 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.uninitializedArrayAllocationThreshold: -1 06:45:21.084 [main] DEBUG io.netty.util.internal.CleanerJava9 - java.nio.ByteBuffer.cleaner(): available 06:45:21.084 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.noPreferDirect: false 06:45:21.086 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numHeapArenas: 8 06:45:21.086 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numDirectArenas: 8 06:45:21.086 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.pageSize: 8192 06:45:21.087 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxOrder: 7 06:45:21.087 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.chunkSize: 1048576 06:45:21.087 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.smallCacheSize: 256 06:45:21.087 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.normalCacheSize: 64 06:45:21.087 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxCachedBufferCapacity: 32768 06:45:21.087 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimInterval: 8192 06:45:21.088 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimIntervalMillis: 0 06:45:21.088 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.useCacheForAllThreads: false 06:45:21.088 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxCachedByteBuffersPerChunk: 1023 06:45:21.091 [main] DEBUG io.netty.util.internal.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024 06:45:21.092 [main] DEBUG io.netty.util.internal.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096 06:45:21.107 [main] DEBUG io.netty.util.internal.NativeLibraryLoader - -Dio.netty.native.workdir: /tmp (io.netty.tmpdir) 06:45:21.107 [main] DEBUG io.netty.util.internal.NativeLibraryLoader - -Dio.netty.native.deleteLibAfterLoading: true 06:45:21.107 [main] DEBUG io.netty.util.internal.NativeLibraryLoader - -Dio.netty.native.tryPatchShadedId: true 06:45:21.107 [main] DEBUG io.netty.util.internal.NativeLibraryLoader - -Dio.netty.native.detectNativeLibraryDuplicates: true 06:45:21.137 [main] DEBUG io.netty.util.internal.NativeLibraryLoader - Successfully loaded the library /tmp/libnetty_transport_native_epoll_x86_648940572427438364515.so 06:45:21.140 [main] DEBUG io.netty.util.NetUtil - -Djava.net.preferIPv4Stack: false 06:45:21.141 [main] DEBUG io.netty.util.NetUtil - -Djava.net.preferIPv6Addresses: false 06:45:21.142 [main] DEBUG io.netty.util.NetUtilInitializations - Loopback interface: lo (lo, 127.0.0.1) 06:45:21.143 [main] DEBUG io.netty.util.NetUtil - /proc/sys/net/core/somaxconn: 4096 06:45:21.647 [main] DEBUG io.netty.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@5c20aab9 06:45:21.653 [main] DEBUG io.netty.util.internal.PlatformDependent - org.jctools-core.MpscChunkedArrayQueue: available 06:45:22.024 [main] DEBUG io.netty.channel.MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 4 06:45:22.081 [main] DEBUG io.netty.channel.DefaultChannelId - -Dio.netty.processId: 243667 (auto-detected) 06:45:22.083 [main] DEBUG io.netty.channel.DefaultChannelId - -Dio.netty.machineId: 02:42:ac:ff:fe:11:00:02 (auto-detected) 06:45:22.096 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.allocator.type: pooled 06:45:22.097 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 0 06:45:22.097 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.maxThreadLocalCharBufferSize: 16384 06:45:22.156 [finagle/netty4-1-1] DEBUG io.netty.util.internal.NativeLibraryLoader - Successfully loaded the library /tmp/libnetty_tcnative_linux_x86_6413878350725438279019.so 06:45:22.157 [finagle/netty4-1-1] DEBUG io.netty.util.internal.NativeLibraryLoader - Loaded library with name 'netty_tcnative_linux_x86_64' 06:45:22.157 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.OpenSsl - Initialize netty-tcnative using engine: 'default' 06:45:22.158 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.OpenSsl - netty-tcnative using native library: BoringSSL 06:45:22.256 [finagle/netty4-1-1] DEBUG io.netty.buffer.AbstractByteBuf - -Dio.netty.buffer.checkAccessible: true 06:45:22.256 [finagle/netty4-1-1] DEBUG io.netty.buffer.AbstractByteBuf - -Dio.netty.buffer.checkBounds: true 06:45:22.256 [finagle/netty4-1-1] DEBUG io.netty.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@402ada0e 06:45:22.272 [finagle/netty4-1-1] DEBUG io.netty.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@3ba1ffe8 06:45:22.276 [finagle/netty4-1-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxCapacityPerThread: disabled 06:45:22.276 [finagle/netty4-1-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.ratio: disabled 06:45:22.277 [finagle/netty4-1-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.chunkSize: disabled 06:45:22.277 [finagle/netty4-1-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.blocking: disabled 06:45:22.287 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256 => ECDHE-ECDSA-AES128-GCM-SHA256 06:45:22.287 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256 => ECDHE-ECDSA-AES128-GCM-SHA256 06:45:22.288 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 => ECDHE-RSA-AES128-GCM-SHA256 06:45:22.288 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_RSA_WITH_AES_128_GCM_SHA256 => ECDHE-RSA-AES128-GCM-SHA256 06:45:22.288 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384 => ECDHE-ECDSA-AES256-GCM-SHA384 06:45:22.288 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384 => ECDHE-ECDSA-AES256-GCM-SHA384 06:45:22.288 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 => ECDHE-RSA-AES256-GCM-SHA384 06:45:22.288 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_RSA_WITH_AES_256_GCM_SHA384 => ECDHE-RSA-AES256-GCM-SHA384 06:45:22.289 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256 => ECDHE-ECDSA-CHACHA20-POLY1305 06:45:22.289 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256 => ECDHE-ECDSA-CHACHA20-POLY1305 06:45:22.289 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256 => ECDHE-RSA-CHACHA20-POLY1305 06:45:22.289 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256 => ECDHE-RSA-CHACHA20-POLY1305 06:45:22.290 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_PSK_WITH_CHACHA20_POLY1305_SHA256 => ECDHE-PSK-CHACHA20-POLY1305 06:45:22.291 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_PSK_WITH_CHACHA20_POLY1305_SHA256 => ECDHE-PSK-CHACHA20-POLY1305 06:45:22.291 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA => ECDHE-ECDSA-AES128-SHA 06:45:22.291 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_ECDSA_WITH_AES_128_CBC_SHA => ECDHE-ECDSA-AES128-SHA 06:45:22.291 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA => ECDHE-RSA-AES128-SHA 06:45:22.291 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_RSA_WITH_AES_128_CBC_SHA => ECDHE-RSA-AES128-SHA 06:45:22.292 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_PSK_WITH_AES_128_CBC_SHA => ECDHE-PSK-AES128-CBC-SHA 06:45:22.292 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_PSK_WITH_AES_128_CBC_SHA => ECDHE-PSK-AES128-CBC-SHA 06:45:22.292 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA => ECDHE-ECDSA-AES256-SHA 06:45:22.293 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_ECDSA_WITH_AES_256_CBC_SHA => ECDHE-ECDSA-AES256-SHA 06:45:22.293 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA => ECDHE-RSA-AES256-SHA 06:45:22.293 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_RSA_WITH_AES_256_CBC_SHA => ECDHE-RSA-AES256-SHA 06:45:22.293 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_PSK_WITH_AES_256_CBC_SHA => ECDHE-PSK-AES256-CBC-SHA 06:45:22.293 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_PSK_WITH_AES_256_CBC_SHA => ECDHE-PSK-AES256-CBC-SHA 06:45:22.294 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_RSA_WITH_AES_128_GCM_SHA256 => AES128-GCM-SHA256 06:45:22.294 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_RSA_WITH_AES_128_GCM_SHA256 => AES128-GCM-SHA256 06:45:22.294 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_RSA_WITH_AES_256_GCM_SHA384 => AES256-GCM-SHA384 06:45:22.294 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_RSA_WITH_AES_256_GCM_SHA384 => AES256-GCM-SHA384 06:45:22.295 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_RSA_WITH_AES_128_CBC_SHA => AES128-SHA 06:45:22.295 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_RSA_WITH_AES_128_CBC_SHA => AES128-SHA 06:45:22.295 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_PSK_WITH_AES_128_CBC_SHA => PSK-AES128-CBC-SHA 06:45:22.295 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_PSK_WITH_AES_128_CBC_SHA => PSK-AES128-CBC-SHA 06:45:22.295 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_RSA_WITH_AES_256_CBC_SHA => AES256-SHA 06:45:22.295 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_RSA_WITH_AES_256_CBC_SHA => AES256-SHA 06:45:22.296 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_PSK_WITH_AES_256_CBC_SHA => PSK-AES256-CBC-SHA 06:45:22.296 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_PSK_WITH_AES_256_CBC_SHA => PSK-AES256-CBC-SHA 06:45:22.296 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_RSA_WITH_3DES_EDE_CBC_SHA => DES-CBC3-SHA 06:45:22.296 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_RSA_WITH_3DES_EDE_CBC_SHA => DES-CBC3-SHA 06:45:22.297 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.OpenSsl - Supported protocols (OpenSSL): [SSLv2Hello, TLSv1, TLSv1.1, TLSv1.2, TLSv1.3] 06:45:22.297 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.OpenSsl - Default cipher suites (OpenSSL): [TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_256_CBC_SHA, TLS_AES_128_GCM_SHA256, TLS_AES_256_GCM_SHA384, TLS_AES_128_GCM_SHA256, TLS_AES_256_GCM_SHA384, TLS_AES_128_GCM_SHA256, TLS_AES_256_GCM_SHA384, TLS_CHACHA20_POLY1305_SHA256] 06:45:22.419 [finagle/netty4-1-1] DEBUG io.netty.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@11d430c2 06:45:22.466 [finagle/netty4-1-1] DEBUG io.netty.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@72538187 06:45:23.158 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.SslHandler - [id: 0x1b74c3b0, L:/127.0.0.1:55396 - R:localhost/127.0.0.1:8080] HANDSHAKEN: protocol:TLSv1.3 cipher suite:TLS_AES_128_GCM_SHA256 StringString ' I20220817 06:45:23.707774 243447 thriftmux_openssl_trace_bpf_test.cc:118] Client PID: 243649 I20220817 06:45:24.708307 243447 source_connector.cc:36] Initializing source connector: socket_trace_connector I20220817 06:45:24.708359 243447 linux_headers.cc:209] Found Linux kernel version using .note section. I20220817 06:45:24.708366 243447 linux_headers.cc:90] Obtained Linux version string from `uname`: 5.15.0-30-generic I20220817 06:45:24.708372 243447 linux_headers.cc:599] Detected kernel release (uname -r): 5.15.0-30-generic I20220817 06:45:24.708408 243447 bcc_wrapper.cc:120] Using linux headers found at /lib/modules/5.15.0-30-generic/build for BCC runtime. warning: ./src/stirling/source_connectors/socket_tracer/bcc_bpf/grpc_c_trace.c:652:3: loop not unrolled: the optimizer was unable to perform the requested transformation; the transformation might be disabled or specified as part of an unsupported transformation ordering I20220817 06:45:41.949194 243447 socket_trace_connector.cc:404] Number of kprobes deployed = 40 I20220817 06:45:41.949318 243447 socket_trace_connector.cc:405] Probes successfully deployed. I20220817 06:45:41.949431 243447 socket_trace_connector.cc:340] Initializing perf buffers with ncpus=2 and scaling_factor=0.9 I20220817 06:45:41.950176 243447 socket_trace_connector.cc:329] Total perf buffer usage for kData buffers across all cpus: 188743680 I20220817 06:45:41.950258 243447 socket_trace_connector.cc:329] Total perf buffer usage for kControl buffers across all cpus: 3963614 I20220817 06:45:41.950860 243447 bcc_wrapper.cc:345] Opening perf buffer: socket_data_events [requested_size=18874368 num_pages=8192 size=33554432] (per cpu) I20220817 06:45:41.956878 243447 bcc_wrapper.cc:345] Opening perf buffer: socket_control_events [requested_size=943718 num_pages=256 size=1048576] (per cpu) I20220817 06:45:41.957451 243447 bcc_wrapper.cc:345] Opening perf buffer: conn_stats_events [requested_size=943718 num_pages=256 size=1048576] (per cpu) I20220817 06:45:41.957908 243447 bcc_wrapper.cc:345] Opening perf buffer: mmap_events [requested_size=94371 num_pages=32 size=131072] (per cpu) I20220817 06:45:41.958210 243447 bcc_wrapper.cc:345] Opening perf buffer: go_grpc_events [requested_size=18874368 num_pages=8192 size=33554432] (per cpu) I20220817 06:45:41.962934 243447 bcc_wrapper.cc:345] Opening perf buffer: grpc_c_events [requested_size=18874368 num_pages=8192 size=33554432] (per cpu) I20220817 06:45:41.968755 243447 bcc_wrapper.cc:345] Opening perf buffer: grpc_c_header_events [requested_size=18874368 num_pages=8192 size=33554432] (per cpu) I20220817 06:45:41.974740 243447 bcc_wrapper.cc:345] Opening perf buffer: grpc_c_close_events [requested_size=18874368 num_pages=8192 size=33554432] (per cpu) I20220817 06:45:41.981499 243447 socket_trace_connector.cc:409] Number of perf buffers opened = 8 W20220817 06:45:42.051280 243702 uprobe_symaddrs.cc:620] Unable to find openssl symbol 'OpenSSL_version_num' using dlopen/dlsym. Attempting to find address manually for pid 243532 I20220817 06:45:42.916184 243702 uprobe_manager.cc:755] Number of uprobes deployed = 5 Warning: use -cacerts option to access cacerts keystore I20220817 06:45:43.465761 243447 thriftmux_openssl_trace_bpf_test.cc:102] keytool -importcert command output: 'keytool error: java.lang.Exception: Certificate not imported, alias already exists ' WARNING: An illegal reflective access operation has occurred WARNING: Illegal reflective access by com.twitter.jvm.Hotspot (file:/app/maven/v1/https/repo1.maven.org/maven2/com/twitter/util-jvm_2.13/22.7.0/util-jvm_2.13-22.7.0.jar) to field sun.management.ManagementFactoryHelper.jvm WARNING: Please consider reporting this to the maintainers of com.twitter.jvm.Hotspot WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations WARNING: All illegal access operations will be denied in a future release Aug 17, 2022 6:45:44 AM com.twitter.finagle.Init$ $anonfun$once$1 INFO: Finagle version 22.7.0 (rev=4d10525ef4fe89732bcfec6286fac7fe426e9082) built at 20220728-183850 Aug 17, 2022 6:45:45 AM com.twitter.finagle.FixedInetResolver$ factory$lzycompute INFO: Successfully loaded a fixed inet resolver: com.twitter.finagle.netty4.FixedNetty4InetResolver$Factory@213bd3d5 Aug 17, 2022 6:45:45 AM com.twitter.finagle.BaseResolver inetResolver$lzycompute INFO: Using default inet resolver Aug 17, 2022 6:45:45 AM com.twitter.finagle.InetResolver$ factory$lzycompute INFO: Successfully loaded an inet resolver: com.twitter.finagle.netty4.Netty4InetResolver$Factory@3a230001 Aug 17, 2022 6:45:45 AM com.twitter.finagle.BaseResolver $anonfun$resolvers$3 INFO: Resolver[inet] = com.twitter.finagle.InetResolver(com.twitter.finagle.InetResolver@6ef1a1b9) Aug 17, 2022 6:45:45 AM com.twitter.finagle.BaseResolver $anonfun$resolvers$3 INFO: Resolver[fixedinet] = com.twitter.finagle.FixedInetResolver(com.twitter.finagle.FixedInetResolver@5fbdc49b) Aug 17, 2022 6:45:45 AM com.twitter.finagle.BaseResolver $anonfun$resolvers$3 INFO: Resolver[neg] = com.twitter.finagle.NegResolver$(com.twitter.finagle.NegResolver$@65753040) Aug 17, 2022 6:45:45 AM com.twitter.finagle.BaseResolver $anonfun$resolvers$3 INFO: Resolver[nil] = com.twitter.finagle.NilResolver$(com.twitter.finagle.NilResolver$@2954b5ea) Aug 17, 2022 6:45:45 AM com.twitter.finagle.BaseResolver $anonfun$resolvers$3 INFO: Resolver[fail] = com.twitter.finagle.FailResolver$(com.twitter.finagle.FailResolver$@4acb2510) I20220817 06:45:45.885520 243703 conn_tracker.cc:461] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kCollecting remote_addr=-:-1 role=kRoleUnknown protocol=kProtocolUnknown ssl=false New connection tracker I20220817 06:45:45.885609 243703 conn_tracker.cc:471] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kCollecting remote_addr=127.0.0.1:55398 role=kRoleUnknown protocol=kProtocolUnknown ssl=false RemoteAddr updated 127.0.0.1, reason=[Inferred from conn_open.] I20220817 06:45:45.885650 243703 conn_tracker.cc:491] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kCollecting remote_addr=127.0.0.1:55398 role=kRoleUnknown protocol=kProtocolUnknown ssl=false Role updated kRoleUnknown -> kRoleServer, reason=[Inferred from conn_open.]] I20220817 06:45:45.885674 243703 conn_tracker.cc:107] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kCollecting remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolUnknown ssl=false conn_open: [type=kConnOpen ts=445990939788410 conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] source_fn=kSyscallAccept [addr=[family=2 addr=127.0.0.1 port=26328]]] I20220817 06:45:46.102075 243703 conn_tracker.cc:519] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kCollecting remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=false Protocol changed: kProtocolUnknown->kProtocolMux, reason=[inferred from data_event] I20220817 06:45:46.102159 243703 conn_tracker.cc:543] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kCollecting remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true SSL state changed: false->true, reason=[inferred from data_event] I20220817 06:45:46.102195 243703 conn_tracker.cc:150] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kCollecting remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true Data event: attr:[[ts=445991139087516 conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] protocol=kProtocolMux role=kRoleServer dir=kIngress ssl=true source_fn=kSSLRead pos=220 size=19 buf_size=19]] msg_size:19 msg:[\x00\x00\x00\x0F\x7F\x00\x00\x01tinit check] I20220817 06:45:46.102247 243703 conn_tracker.cc:150] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kCollecting remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true Data event: attr:[[ts=445991139891730 conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] protocol=kProtocolMux role=kRoleServer dir=kEgress ssl=true source_fn=kSSLWrite pos=0 size=19 buf_size=19]] msg_size:19 msg:[\x00\x00\x00\x0F\x7F\x00\x00\x01tinit check] I20220817 06:45:46.102296 243703 conn_tracker.cc:150] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kCollecting remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true Data event: attr:[[ts=445991143109532 conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] protocol=kProtocolMux role=kRoleServer dir=kIngress ssl=true source_fn=kSSLRead pos=239 size=46 buf_size=46]] msg_size:46 msg:[\x00\x00\x00*D\x00\x00\x01\x00\x01\x00\x00\x00\x0Amux-framer\x00\x00\x00\x04\x7F\xFF\xFF\xFF\x00\x00\x00\x03tls\x00\x00\x00\x03off] I20220817 06:45:46.102355 243703 conn_tracker.cc:150] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kCollecting remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true Data event: attr:[[ts=445991143560078 conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] protocol=kProtocolMux role=kRoleServer dir=kEgress ssl=true source_fn=kSSLWrite pos=19 size=46 buf_size=46]] msg_size:46 msg:[\x00\x00\x00*\xBC\x00\x00\x01\x00\x01\x00\x00\x00\x0Amux-framer\x00\x00\x00\x04\x7F\xFF\xFF\xFF\x00\x00\x00\x03tls\x00\x00\x00\x03off] I20220817 06:45:46.102818 243703 conn_tracker.h:271] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kTransferring remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true req_frames=2 resp_frames=2 I20220817 06:45:46.103344 243703 conn_tracker.h:278] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kTransferring remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true records=2 I20220817 06:45:46.214886 243703 conn_tracker.cc:150] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kTransferring remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true Data event: attr:[[ts=445991198314214 conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] protocol=kProtocolMux role=kRoleServer dir=kIngress ssl=true source_fn=kSSLRead pos=285 size=8 buf_size=8]] msg_size:8 msg:[\x00\x00\x00\x04A\x00\x00\x01] I20220817 06:45:46.215129 243703 conn_tracker.cc:150] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kTransferring remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true Data event: attr:[[ts=445991198705762 conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] protocol=kProtocolMux role=kRoleServer dir=kEgress ssl=true source_fn=kSSLWrite pos=65 size=8 buf_size=8]] msg_size:8 msg:[\x00\x00\x00\x04\xBF\x00\x00\x01] I20220817 06:45:46.215293 243703 conn_tracker.cc:150] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kTransferring remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true Data event: attr:[[ts=445991206331970 conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] protocol=kProtocolMux role=kRoleServer dir=kIngress ssl=true source_fn=kSSLRead pos=293 size=204 buf_size=204]] msg_size:204 msg:[\x00\x00\x00\xC8\x02\x00\x00\x02\x00\x03\x00(com.twitter.finagle.tracing.TraceContext\x00 \xA9_\xE5\x18n\xF3\x86\xF8\xA9_\xE5\x18n\xF3\x86\xF8\xA9_\xE5\x18n\xF3\x86\xF8\x00\x00\x00\x00\x00\x00\x00\x00\x00\x1Bcom.twitter.finagle.Retries\x00\x04\x00\x00\x00\x00\x00\x1Ccom.twitter.finagle.Deadline\x00\x10\x17\x0C\x0E\xE6\x962\x0D\x80\x7F\xFF\xFF\xFF\xFF\xFF\xFF\xFF\x00\x00\x00\x00\x80\x01\x00\x01\x00\x00\x00\x05query\x00\x00\x00\x00\x0B\x00\x01\x00\x00\x00\x06String\x00] I20220817 06:45:46.215481 243703 conn_tracker.cc:150] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kTransferring remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true Data event: attr:[[ts=445991207463787 conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] protocol=kProtocolMux role=kRoleServer dir=kEgress ssl=true source_fn=kSSLWrite pos=73 size=48 buf_size=48]] msg_size:48 msg:[\x00\x00\x00,\xFE\x00\x00\x02\x00\x00\x00\x80\x01\x00\x02\x00\x00\x00\x05query\x00\x00\x00\x00\x0B\x00\x00\x00\x00\x00\x0CStringString\x00] I20220817 06:45:46.216001 243703 conn_tracker.h:271] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kTransferring remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true req_frames=2 resp_frames=2 I20220817 06:45:46.216141 243703 conn_tracker.h:278] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kTransferring remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true records=2 I20220817 06:45:46.334108 243703 conn_tracker.h:271] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kTransferring remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true req_frames=0 resp_frames=0 I20220817 06:45:46.334323 243703 conn_tracker.h:278] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kTransferring remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true records=0 I20220817 06:45:46.446976 243703 conn_tracker.h:271] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kTransferring remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true req_frames=0 resp_frames=0 I20220817 06:45:46.447182 243703 conn_tracker.h:278] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kTransferring remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true records=0 I20220817 06:45:46.516883 243447 thriftmux_openssl_trace_bpf_test.cc:109] thriftmux client command output: '243755 06:45:44.361 [main] DEBUG io.netty.util.internal.logging.InternalLoggerFactory - Using SLF4J as the default logging framework 06:45:44.364 [main] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.level: simple 06:45:44.364 [main] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.targetRecords: 4 06:45:44.381 [main] DEBUG io.netty.util.internal.PlatformDependent0 - -Dio.netty.noUnsafe: false 06:45:44.382 [main] DEBUG io.netty.util.internal.PlatformDependent0 - Java version: 11 06:45:44.383 [main] DEBUG io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.theUnsafe: available 06:45:44.384 [main] DEBUG io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.copyMemory: available 06:45:44.385 [main] DEBUG io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.storeFence: available 06:45:44.385 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.Buffer.address: available 06:45:44.386 [main] DEBUG io.netty.util.internal.PlatformDependent0 - direct buffer constructor: unavailable: Reflective setAccessible(true) disabled 06:45:44.386 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.Bits.unaligned: available, true 06:45:44.387 [main] DEBUG io.netty.util.internal.PlatformDependent0 - 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 @4f49f6af 06:45:44.388 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.DirectByteBuffer.(long, int): unavailable 06:45:44.388 [main] DEBUG io.netty.util.internal.PlatformDependent - sun.misc.Unsafe: available 06:45:44.389 [main] DEBUG io.netty.util.internal.PlatformDependent - maxDirectMemory: 2084569088 bytes (maybe) 06:45:44.389 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.tmpdir: /tmp (java.io.tmpdir) 06:45:44.389 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.bitMode: 64 (sun.arch.data.model) 06:45:44.390 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.maxDirectMemory: -1 bytes 06:45:44.391 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.uninitializedArrayAllocationThreshold: -1 06:45:44.391 [main] DEBUG io.netty.util.internal.CleanerJava9 - java.nio.ByteBuffer.cleaner(): available 06:45:44.392 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.noPreferDirect: false 06:45:44.393 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numHeapArenas: 8 06:45:44.394 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numDirectArenas: 8 06:45:44.394 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.pageSize: 8192 06:45:44.394 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxOrder: 7 06:45:44.394 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.chunkSize: 1048576 06:45:44.394 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.smallCacheSize: 256 06:45:44.395 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.normalCacheSize: 64 06:45:44.395 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxCachedBufferCapacity: 32768 06:45:44.395 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimInterval: 8192 06:45:44.395 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimIntervalMillis: 0 06:45:44.395 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.useCacheForAllThreads: false 06:45:44.396 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxCachedByteBuffersPerChunk: 1023 06:45:44.399 [main] DEBUG io.netty.util.internal.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024 06:45:44.399 [main] DEBUG io.netty.util.internal.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096 06:45:44.430 [main] DEBUG io.netty.util.internal.NativeLibraryLoader - -Dio.netty.native.workdir: /tmp (io.netty.tmpdir) 06:45:44.431 [main] DEBUG io.netty.util.internal.NativeLibraryLoader - -Dio.netty.native.deleteLibAfterLoading: true 06:45:44.431 [main] DEBUG io.netty.util.internal.NativeLibraryLoader - -Dio.netty.native.tryPatchShadedId: true 06:45:44.431 [main] DEBUG io.netty.util.internal.NativeLibraryLoader - -Dio.netty.native.detectNativeLibraryDuplicates: true 06:45:44.445 [main] DEBUG io.netty.util.internal.NativeLibraryLoader - Successfully loaded the library /tmp/libnetty_transport_native_epoll_x86_6417257840684434158261.so 06:45:44.448 [main] DEBUG io.netty.util.NetUtil - -Djava.net.preferIPv4Stack: false 06:45:44.448 [main] DEBUG io.netty.util.NetUtil - -Djava.net.preferIPv6Addresses: false 06:45:44.450 [main] DEBUG io.netty.util.NetUtilInitializations - Loopback interface: lo (lo, 127.0.0.1) 06:45:44.451 [main] DEBUG io.netty.util.NetUtil - /proc/sys/net/core/somaxconn: 4096 06:45:45.041 [main] DEBUG io.netty.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@5c20aab9 06:45:45.047 [main] DEBUG io.netty.util.internal.PlatformDependent - org.jctools-core.MpscChunkedArrayQueue: available 06:45:45.427 [main] DEBUG io.netty.channel.MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 4 06:45:45.481 [main] DEBUG io.netty.channel.DefaultChannelId - -Dio.netty.processId: 243772 (auto-detected) 06:45:45.483 [main] DEBUG io.netty.channel.DefaultChannelId - -Dio.netty.machineId: 02:42:ac:ff:fe:11:00:02 (auto-detected) 06:45:45.497 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.allocator.type: pooled 06:45:45.497 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 0 06:45:45.497 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.maxThreadLocalCharBufferSize: 16384 06:45:45.551 [finagle/netty4-1-1] DEBUG io.netty.util.internal.NativeLibraryLoader - Successfully loaded the library /tmp/libnetty_tcnative_linux_x86_644027974589868220049.so 06:45:45.551 [finagle/netty4-1-1] DEBUG io.netty.util.internal.NativeLibraryLoader - Loaded library with name 'netty_tcnative_linux_x86_64' 06:45:45.552 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.OpenSsl - Initialize netty-tcnative using engine: 'default' 06:45:45.552 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.OpenSsl - netty-tcnative using native library: BoringSSL 06:45:45.621 [finagle/netty4-1-1] DEBUG io.netty.buffer.AbstractByteBuf - -Dio.netty.buffer.checkAccessible: true 06:45:45.621 [finagle/netty4-1-1] DEBUG io.netty.buffer.AbstractByteBuf - -Dio.netty.buffer.checkBounds: true 06:45:45.622 [finagle/netty4-1-1] DEBUG io.netty.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@6c663826 06:45:45.637 [finagle/netty4-1-1] DEBUG io.netty.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@34d6c055 06:45:45.641 [finagle/netty4-1-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxCapacityPerThread: disabled 06:45:45.641 [finagle/netty4-1-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.ratio: disabled 06:45:45.641 [finagle/netty4-1-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.chunkSize: disabled 06:45:45.641 [finagle/netty4-1-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.blocking: disabled 06:45:45.651 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256 => ECDHE-ECDSA-AES128-GCM-SHA256 06:45:45.651 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256 => ECDHE-ECDSA-AES128-GCM-SHA256 06:45:45.651 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 => ECDHE-RSA-AES128-GCM-SHA256 06:45:45.651 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_RSA_WITH_AES_128_GCM_SHA256 => ECDHE-RSA-AES128-GCM-SHA256 06:45:45.651 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384 => ECDHE-ECDSA-AES256-GCM-SHA384 06:45:45.652 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384 => ECDHE-ECDSA-AES256-GCM-SHA384 06:45:45.652 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 => ECDHE-RSA-AES256-GCM-SHA384 06:45:45.652 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_RSA_WITH_AES_256_GCM_SHA384 => ECDHE-RSA-AES256-GCM-SHA384 06:45:45.652 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256 => ECDHE-ECDSA-CHACHA20-POLY1305 06:45:45.652 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256 => ECDHE-ECDSA-CHACHA20-POLY1305 06:45:45.652 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256 => ECDHE-RSA-CHACHA20-POLY1305 06:45:45.652 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256 => ECDHE-RSA-CHACHA20-POLY1305 06:45:45.653 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_PSK_WITH_CHACHA20_POLY1305_SHA256 => ECDHE-PSK-CHACHA20-POLY1305 06:45:45.653 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_PSK_WITH_CHACHA20_POLY1305_SHA256 => ECDHE-PSK-CHACHA20-POLY1305 06:45:45.653 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA => ECDHE-ECDSA-AES128-SHA 06:45:45.653 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_ECDSA_WITH_AES_128_CBC_SHA => ECDHE-ECDSA-AES128-SHA 06:45:45.653 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA => ECDHE-RSA-AES128-SHA 06:45:45.653 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_RSA_WITH_AES_128_CBC_SHA => ECDHE-RSA-AES128-SHA 06:45:45.653 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_PSK_WITH_AES_128_CBC_SHA => ECDHE-PSK-AES128-CBC-SHA 06:45:45.654 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_PSK_WITH_AES_128_CBC_SHA => ECDHE-PSK-AES128-CBC-SHA 06:45:45.654 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA => ECDHE-ECDSA-AES256-SHA 06:45:45.654 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_ECDSA_WITH_AES_256_CBC_SHA => ECDHE-ECDSA-AES256-SHA 06:45:45.654 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA => ECDHE-RSA-AES256-SHA 06:45:45.654 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_RSA_WITH_AES_256_CBC_SHA => ECDHE-RSA-AES256-SHA 06:45:45.654 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_ECDHE_PSK_WITH_AES_256_CBC_SHA => ECDHE-PSK-AES256-CBC-SHA 06:45:45.654 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_ECDHE_PSK_WITH_AES_256_CBC_SHA => ECDHE-PSK-AES256-CBC-SHA 06:45:45.655 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_RSA_WITH_AES_128_GCM_SHA256 => AES128-GCM-SHA256 06:45:45.655 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_RSA_WITH_AES_128_GCM_SHA256 => AES128-GCM-SHA256 06:45:45.655 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_RSA_WITH_AES_256_GCM_SHA384 => AES256-GCM-SHA384 06:45:45.655 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_RSA_WITH_AES_256_GCM_SHA384 => AES256-GCM-SHA384 06:45:45.655 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_RSA_WITH_AES_128_CBC_SHA => AES128-SHA 06:45:45.655 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_RSA_WITH_AES_128_CBC_SHA => AES128-SHA 06:45:45.655 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_PSK_WITH_AES_128_CBC_SHA => PSK-AES128-CBC-SHA 06:45:45.655 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_PSK_WITH_AES_128_CBC_SHA => PSK-AES128-CBC-SHA 06:45:45.656 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_RSA_WITH_AES_256_CBC_SHA => AES256-SHA 06:45:45.656 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_RSA_WITH_AES_256_CBC_SHA => AES256-SHA 06:45:45.656 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_PSK_WITH_AES_256_CBC_SHA => PSK-AES256-CBC-SHA 06:45:45.656 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_PSK_WITH_AES_256_CBC_SHA => PSK-AES256-CBC-SHA 06:45:45.656 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: TLS_RSA_WITH_3DES_EDE_CBC_SHA => DES-CBC3-SHA 06:45:45.656 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.CipherSuiteConverter - Cipher suite mapping: SSL_RSA_WITH_3DES_EDE_CBC_SHA => DES-CBC3-SHA 06:45:45.657 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.OpenSsl - Supported protocols (OpenSSL): [SSLv2Hello, TLSv1, TLSv1.1, TLSv1.2, TLSv1.3] 06:45:45.657 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.OpenSsl - Default cipher suites (OpenSSL): [TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_256_CBC_SHA, TLS_AES_128_GCM_SHA256, TLS_AES_256_GCM_SHA384, TLS_AES_128_GCM_SHA256, TLS_AES_256_GCM_SHA384, TLS_AES_128_GCM_SHA256, TLS_AES_256_GCM_SHA384, TLS_CHACHA20_POLY1305_SHA256] 06:45:45.797 [finagle/netty4-1-1] DEBUG io.netty.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@7eb0d956 06:45:45.844 [finagle/netty4-1-1] DEBUG io.netty.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@4cedc670 06:45:46.050 [finagle/netty4-1-1] DEBUG io.netty.handler.ssl.SslHandler - [id: 0xeab700d9, L:/127.0.0.1:55398 - R:localhost/127.0.0.1:8080] HANDSHAKEN: protocol:TLSv1.3 cipher suite:TLS_AES_128_GCM_SHA256 StringString ' I20220817 06:45:46.516991 243447 thriftmux_openssl_trace_bpf_test.cc:118] Client PID: 243755 I20220817 06:45:46.555589 243703 conn_tracker.cc:136] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kTransferring remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true conn_close: [type=kConnClose ts=445991588344702 conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] source_fn=kSyscallClose [wr_bytes=121 rd_bytes=497]] I20220817 06:45:46.555630 243703 conn_tracker.cc:593] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kTransferring remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true Marked for death, countdown=3 I20220817 06:45:46.555649 243703 conn_tracker.cc:195] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kTransferring remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true ConnStats timestamp=445991588353438 wr=121 rd=497 close=2 I20220817 06:45:46.556063 243703 conn_tracker.h:271] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kTransferring remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true req_frames=0 resp_frames=0 I20220817 06:45:46.556085 243703 conn_tracker.h:278] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kTransferring remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true records=0 I20220817 06:45:46.556097 243703 conn_tracker.cc:793] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kTransferring remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true Death countdown=2 I20220817 06:45:46.671743 243703 conn_tracker.h:271] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kTransferring remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true req_frames=0 resp_frames=0 I20220817 06:45:46.671780 243703 conn_tracker.h:278] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kTransferring remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true records=0 I20220817 06:45:46.671792 243703 conn_tracker.cc:793] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kTransferring remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true Death countdown=1 I20220817 06:45:48.469894 243447 container_runner.cc:59] docker rm -f thriftmux_server_445962533992195 I20220817 06:45:48.696987 243447 conn_tracker.cc:75] conn_id=[upid=243532:44596285 fd=140 gen=445990939787797] state=kTransferring remote_addr=127.0.0.1:55398 role=kRoleServer protocol=kProtocolMux ssl=true Being destroyed [ OK ] OpenSSLTraceRawFptrsTest/0.mtls_thriftmux_client (32478 ms) [----------] 1 test from OpenSSLTraceRawFptrsTest/0 (32478 ms total)

[----------] Global test environment tear-down [==========] 1 test from 1 test suite ran. (32478 ms total) [ PASSED ] 1 test. I20220817 06:45:48.768321 243447 env.cc:51] Shutting down

Todo

  • [x] Rebase once #562 is merged
  • [x] Rebase once #583 is merged
  • [x] Correctly identify when to use the offsets for existing openssl support and netty's borginssl

ddelnano avatar Aug 17 '22 14:08 ddelnano

Can one of the admins verify this patch?

pixie-io-buildbot avatar Aug 17 '22 14:08 pixie-io-buildbot

@oazizi000 @yzhao1012 this is ready for some early feedback. The part I'm specifically seeking feedback on is the approach for detecting when to use the boringssl data structure offsets and the changes to UProbeManager::AttachOpenSSLUProbesOnDynamicLib, which I hope will make it easier to support other libraries in the optimistic case of boring ssl tracing (where Openssl_version_num is available).

ddelnano avatar Aug 28 '22 22:08 ddelnano

@yzhao1012 @oazizi000 this is ready for a more thorough review now.

ddelnano avatar Sep 07 '22 15:09 ddelnano

@yzhao1012 your comments should be addressed, so this is ready for another look when you have the chance.

ddelnano avatar Sep 09 '22 14:09 ddelnano