Skip to content

Instantly share code, notes, and snippets.

@thomasdarimont

thomasdarimont/readme.md

Created October 11, 2021 09:19
Show Gist options
  • Save thomasdarimont/ba609be4e6b67b5c9764955d9ce9c054 to your computer and use it in GitHub Desktop.
Save thomasdarimont/ba609be4e6b67b5c9764955d9ce9c054 to your computer and use it in GitHub Desktop.
Download ZIP
Keycloak-X with Jaeger and OpenTelemetry
Raw
readme.md 
tom@neumann ~/dev/repos/gh/thomasdarimont/keycloak-dev/keycloak/keycloak-x-with-opentelemetry/keycloak-x-with-opentelemetry/.gitpod (main) 
$ docker-compose -f docker-compose-gitpod.yml up --build                       
Building keycloak
Sending build context to Docker daemon  3.584kB

Step 1/2 : FROM quay.io/keycloak/keycloak-x:latest
 ---> 028ec5fbe69d
Step 2/2 : RUN   curl -L https://github.com/open-telemetry/opentelemetry-java-instrumentation/releases/latest/download/opentelemetry-javaagent-all.jar   -o /tmp/opentelemetry-javaagent-all.jar
 ---> Using cache
 ---> b6e3ed9ef22e
Successfully built b6e3ed9ef22e
Successfully tagged gitpod_keycloak:latest
gitpod_jaeger_1 is up-to-date
Creating keycloak ... done
Attaching to gitpod_jaeger_1, keycloak
jaeger_1    | 2021/10/11 09:15:44 maxprocs: Leaving GOMAXPROCS=12: CPU quota undefined
jaeger_1    | {"level":"info","ts":1633943744.9401226,"caller":"flags/service.go:117","msg":"Mounting metrics handler on admin server","route":"/metrics"}
jaeger_1    | {"level":"info","ts":1633943744.9401548,"caller":"flags/service.go:123","msg":"Mounting expvar handler on admin server","route":"/debug/vars"}
jaeger_1    | {"level":"info","ts":1633943744.9402428,"caller":"flags/admin.go:104","msg":"Mounting health check on admin server","route":"/"}
jaeger_1    | {"level":"info","ts":1633943744.9402704,"caller":"flags/admin.go:115","msg":"Starting admin HTTP server","http-addr":":14269"}
jaeger_1    | {"level":"info","ts":1633943744.9402816,"caller":"flags/admin.go:96","msg":"Admin server started","http.host-port":"[::]:14269","health-status":"unavailable"}
jaeger_1    | {"level":"info","ts":1633943744.9410086,"caller":"memory/factory.go:61","msg":"Memory storage initialized","configuration":{"MaxTraces":0}}
jaeger_1    | {"level":"info","ts":1633943744.9412136,"caller":"static/strategy_store.go:138","msg":"Loading sampling strategies","filename":"/etc/jaeger/sampling_strategies.json"}
jaeger_1    | {"level":"info","ts":1633943744.9481373,"caller":"server/grpc.go:82","msg":"Starting jaeger-collector gRPC server","grpc.host-port":":14250"}
jaeger_1    | {"level":"info","ts":1633943744.9481833,"caller":"server/http.go:48","msg":"Starting jaeger-collector HTTP server","http host-port":":14268"}
jaeger_1    | {"level":"info","ts":1633943744.9483109,"caller":"server/zipkin.go:49","msg":"Not listening for Zipkin HTTP traffic, port not configured"}
jaeger_1    | {"level":"info","ts":1633943744.9483283,"caller":"grpc/builder.go:70","msg":"Agent requested insecure grpc connection to collector(s)"}
jaeger_1    | {"level":"info","ts":1633943744.9483562,"caller":"channelz/logging.go:50","msg":"[core]parsed scheme: \"\"","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.9483733,"caller":"channelz/logging.go:50","msg":"[core]scheme \"\" not registered, fallback to default scheme","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.9483879,"caller":"channelz/logging.go:50","msg":"[core]ccResolverWrapper: sending update to cc: {[{:14250  <nil> 0 <nil>}] <nil> <nil>}","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.9483943,"caller":"channelz/logging.go:50","msg":"[core]ClientConn switching balancer to \"round_robin\"","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.948399,"caller":"channelz/logging.go:50","msg":"[core]Channel switches to new LB policy \"round_robin\"","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.948413,"caller":"grpclog/component.go:55","msg":"[balancer]base.baseBalancer: got new ClientConn state: {{[{:14250  <nil> 0 <nil>}] <nil> <nil>} <nil>}","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.9484637,"caller":"channelz/logging.go:50","msg":"[core]Subchannel Connectivity change to CONNECTING","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.9484682,"caller":"grpc/builder.go:109","msg":"Checking connection to collector"}
jaeger_1    | {"level":"info","ts":1633943744.9488046,"caller":"grpclog/component.go:71","msg":"[balancer]base.baseBalancer: handle SubConn state change: 0xc0004ac840, CONNECTING","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.9488277,"caller":"grpc/builder.go:120","msg":"Agent collector connection state change","dialTarget":":14250","status":"IDLE"}
jaeger_1    | {"level":"info","ts":1633943744.9488373,"caller":"channelz/logging.go:50","msg":"[core]Channel Connectivity change to CONNECTING","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.9487002,"caller":"channelz/logging.go:50","msg":"[core]Subchannel picks a new address \":14250\" to connect","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.9488504,"caller":"grpc/builder.go:120","msg":"Agent collector connection state change","dialTarget":":14250","status":"CONNECTING"}
jaeger_1    | {"level":"info","ts":1633943744.9492831,"caller":"channelz/logging.go:50","msg":"[core]Subchannel Connectivity change to READY","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.9493036,"caller":"grpclog/component.go:71","msg":"[balancer]base.baseBalancer: handle SubConn state change: 0xc0004ac840, READY","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.9493504,"caller":"grpclog/component.go:71","msg":"[roundrobin]roundrobinPicker: Build called with info: {map[0xc0004ac840:{{:14250  <nil> 0 <nil>}}]}","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.9493604,"caller":"channelz/logging.go:50","msg":"[core]Channel Connectivity change to READY","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.9493663,"caller":"grpc/builder.go:120","msg":"Agent collector connection state change","dialTarget":":14250","status":"READY"}
jaeger_1    | {"level":"info","ts":1633943744.949655,"caller":"./main.go:243","msg":"Starting agent"}
jaeger_1    | {"level":"info","ts":1633943744.9497037,"caller":"app/agent.go:69","msg":"Starting jaeger-agent HTTP server","http-port":5778}
jaeger_1    | {"level":"info","ts":1633943744.9497023,"caller":"querysvc/query_service.go:137","msg":"Archive storage not created","reason":"archive storage not supported"}
jaeger_1    | {"level":"info","ts":1633943744.9497185,"caller":"app/flags.go:124","msg":"Archive storage not initialized"}
jaeger_1    | {"level":"info","ts":1633943744.9499187,"caller":"channelz/logging.go:50","msg":"[core]parsed scheme: \"\"","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.9499357,"caller":"channelz/logging.go:50","msg":"[core]scheme \"\" not registered, fallback to default scheme","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.949955,"caller":"channelz/logging.go:50","msg":"[core]ccResolverWrapper: sending update to cc: {[{:16685  <nil> 0 <nil>}] <nil> <nil>}","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.9499664,"caller":"channelz/logging.go:50","msg":"[core]ClientConn switching balancer to \"pick_first\"","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.9499745,"caller":"channelz/logging.go:50","msg":"[core]Channel switches to new LB policy \"pick_first\"","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.950041,"caller":"channelz/logging.go:50","msg":"[core]Subchannel Connectivity change to CONNECTING","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.9500568,"caller":"channelz/logging.go:50","msg":"[core]Subchannel picks a new address \":16685\" to connect","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.9501143,"caller":"grpclog/component.go:71","msg":"[core]pickfirstBalancer: UpdateSubConnState: 0xc00047dae0, {CONNECTING <nil>}","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.9501274,"caller":"channelz/logging.go:50","msg":"[core]Channel Connectivity change to CONNECTING","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"warn","ts":1633943744.9501753,"caller":"channelz/logging.go:75","msg":"[core]grpc: addrConn.createTransport failed to connect to {:16685 localhost:16685 <nil> 0 <nil>}. Err: connection error: desc = \"transport: Error while dialing dial tcp :16685: connect: connection refused\"","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.9501896,"caller":"channelz/logging.go:50","msg":"[core]Subchannel Connectivity change to TRANSIENT_FAILURE","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.950216,"caller":"grpclog/component.go:71","msg":"[core]pickfirstBalancer: UpdateSubConnState: 0xc00047dae0, {TRANSIENT_FAILURE connection error: desc = \"transport: Error while dialing dial tcp :16685: connect: connection refused\"}","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.950227,"caller":"channelz/logging.go:50","msg":"[core]Channel Connectivity change to TRANSIENT_FAILURE","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943744.9503703,"caller":"app/static_handler.go:182","msg":"UI config path not provided, config file will not be watched"}
jaeger_1    | {"level":"info","ts":1633943744.950439,"caller":"app/server.go:197","msg":"Query server started"}
jaeger_1    | {"level":"info","ts":1633943744.9504533,"caller":"healthcheck/handler.go:129","msg":"Health Check state change","status":"ready"}
jaeger_1    | {"level":"info","ts":1633943744.9504733,"caller":"app/server.go:276","msg":"Starting GRPC server","port":16685,"addr":":16685"}
jaeger_1    | {"level":"info","ts":1633943744.950479,"caller":"app/server.go:257","msg":"Starting HTTP server","port":16686,"addr":":16686"}
jaeger_1    | {"level":"info","ts":1633943745.9507294,"caller":"channelz/logging.go:50","msg":"[core]Subchannel Connectivity change to IDLE","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943745.9508877,"caller":"grpclog/component.go:71","msg":"[core]pickfirstBalancer: UpdateSubConnState: 0xc00047dae0, {IDLE connection error: desc = \"transport: Error while dialing dial tcp :16685: connect: connection refused\"}","system":"grpc","grpc_log":true}
jaeger_1    | {"level":"info","ts":1633943745.950924,"caller":"channelz/logging.go:50","msg":"[core]Channel Connectivity change to IDLE","system":"grpc","grpc_log":true}
keycloak    | JAVA_OPTS already set in environment; overriding default settings with values: -javaagent:/tmp/opentelemetry-javaagent-all.jar -Xms64m -Xmx512m -XX:MetaspaceSize=96M -XX:MaxMetaspaceSize=256m -Djava.net.preferIPv4Stack=true
keycloak    | OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
keycloak    | [otel.javaagent 2021-10-11 09:16:12:019 +0000] [main] INFO io.opentelemetry.javaagent.tooling.VersionLogger - opentelemetry-javaagent - version: 1.6.2
keycloak    | LogManager error of type WRITE_FAILURE: The delayed handler's queue was overrun and log record(s) were lost. Did you forget to configure logging?
keycloak    | 2021-10-11 09:16:15,991 WARN  [io.qua.run.con.ConfigChangeRecorder] (main) Build time property cannot be changed at runtime:
keycloak    |  - quarkus.datasource.metrics.enabled was 'false' at build time and is now 'true'
keycloak    | 2021-10-11 09:16:18,170 INFO  [org.key.url.DefaultHostnameProviderFactory] (main) Frontend: <request>, Admin: <frontend>, Backend: <request>
keycloak    | 2021-10-11 09:16:19,182 INFO  [org.key.con.liq.QuarkusJpaUpdaterProvider] (main) Initializing database schema. Using changelog META-INF/jpa-changelog-master.xml
keycloak    | 2021-10-11 09:16:20,796 INFO  [org.key.pro.qua.QuarkusCacheManagerProvider] (main) Loading cluster configuration from /opt/jboss/keycloak/bin/../conf/cluster-default.xml
keycloak    | 2021-10-11 09:16:21,452 WARN  [org.inf.PERSISTENCE] (main) ISPN000554: jboss-marshalling is deprecated and planned for removal
keycloak    | 2021-10-11 09:16:21,455 INFO  [org.inf.CONTAINER] (main) ISPN000128: Infinispan version: Infinispan 'Corona Extra' 11.0.9.Final
keycloak    | 2021-10-11 09:16:21,489 INFO  [org.inf.PERSISTENCE] (main) ISPN000556: Starting user marshaller 'org.infinispan.jboss.marshalling.core.JBossUserMarshaller'
keycloak    | 2021-10-11 09:16:21,767 INFO  [org.inf.CLUSTER] (main) ISPN000078: Starting JGroups channel ISPN
keycloak    | 2021-10-11 09:16:21,767 INFO  [org.inf.CLUSTER] (main) ISPN000088: Unable to use any JGroups configuration mechanisms provided in properties {}. Using default JGroups configuration!
keycloak    | 2021-10-11 09:16:23,890 INFO  [org.jgr.pro.pbc.GMS] (main) 86ff49f853b0-65266: no members discovered after 2004 ms: creating cluster as coordinator
keycloak    | 2021-10-11 09:16:23,917 INFO  [org.inf.CLUSTER] (main) ISPN000094: Received new cluster view for channel ISPN: [86ff49f853b0-65266|0] (1) [86ff49f853b0-65266]
keycloak    | 2021-10-11 09:16:23,925 INFO  [org.inf.CLUSTER] (main) ISPN000079: Channel ISPN local address is 86ff49f853b0-65266, physical addresses are [192.168.48.3:46720]
keycloak    | 2021-10-11 09:16:24,653 INFO  [org.key.con.inf.DefaultInfinispanConnectionProviderFactory] (main) Node name: 86ff49f853b0-65266, Site name: null
keycloak    | 2021-10-11 09:16:24,766 INFO  [org.key.services] (main) KC-SERVICES0050: Initializing master realm
keycloak    | 2021-10-11 09:16:26,665 INFO  [org.key.services] (main) KC-SERVICES0009: Added user 'admin' to realm 'master'
keycloak    | 2021-10-11 09:16:26,986 INFO  [io.quarkus] (main) Keycloak 15.0.2 on JVM (powered by Quarkus 1.13.3.Final) started in 13.580s. Listening on: http://0.0.0.0:8080
keycloak    | 2021-10-11 09:16:26,986 INFO  [io.quarkus] (main) Profile prod activated. 
keycloak    | 2021-10-11 09:16:26,986 INFO  [io.quarkus] (main) Installed features: [agroal, cdi, hibernate-orm, jdbc-h2, jdbc-mariadb, jdbc-mysql, jdbc-postgresql, keycloak, mutiny, narayana-jta, resteasy, resteasy-jackson, smallrye-context-propagation, smallrye-health, smallrye-metrics, vertx, vertx-web]
keycloak    | 2021-10-11 09:17:19,619 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (vert.x-worker-thread-0) HTTP Request to /q/metrics failed, error id: be9ae914-2e07-44a2-946c-1d9e4474f19d-1: java.lang.NullPointerException: Event cannot be null
keycloak    | 	at java.base/java.util.Objects.requireNonNull(Objects.java:246)
keycloak    | 	at io.quarkus.arc.impl.EventImpl.fire(EventImpl.java:69)
keycloak    | 	at io.quarkus.narayana.jta.runtime.CDIDelegatingTransactionManager.commit(CDIDelegatingTransactionManager.java:93)
keycloak    | 	at org.keycloak.transaction.JtaTransactionWrapper.commit(JtaTransactionWrapper.java:90)
keycloak    | 	at org.keycloak.services.DefaultKeycloakTransactionManager.commit(DefaultKeycloakTransactionManager.java:136)
keycloak    | 	at org.keycloak.services.filters.AbstractRequestFilter.close(AbstractRequestFilter.java:64)
keycloak    | 	at org.keycloak.provider.quarkus.QuarkusRequestFilter.lambda$createEndHandler$3(QuarkusRequestFilter.java:71)
keycloak    | 	at io.vertx.ext.web.impl.RoutingContextImpl.lambda$null$1(RoutingContextImpl.java:489)
keycloak    | 	at java.base/java.lang.Iterable.forEach(Iterable.java:75)
keycloak    | 	at io.vertx.ext.web.impl.RoutingContextImpl.lambda$getHeadersEndHandlers$2(RoutingContextImpl.java:489)
keycloak    | 	at io.vertx.core.http.impl.HttpServerResponseImpl.prepareHeaders(HttpServerResponseImpl.java:661)
keycloak    | 	at io.vertx.core.http.impl.HttpServerResponseImpl.end(HttpServerResponseImpl.java:384)
keycloak    | 	at io.vertx.core.http.impl.HttpServerResponseImpl.end(HttpServerResponseImpl.java:365)
keycloak    | 	at io.quarkus.smallrye.metrics.runtime.SmallRyeMetricsHandler$1.respondWith(SmallRyeMetricsHandler.java:46)
keycloak    | 	at io.smallrye.metrics.MetricsRequestHandler.handleRequest(MetricsRequestHandler.java:168)
keycloak    | 	at io.smallrye.metrics.MetricsRequestHandler_ClientProxy.handleRequest(MetricsRequestHandler_ClientProxy.zig:242)
keycloak    | 	at io.quarkus.smallrye.metrics.runtime.SmallRyeMetricsHandler.handle(SmallRyeMetricsHandler.java:38)
keycloak    | 	at io.quarkus.smallrye.metrics.runtime.SmallRyeMetricsHandler.handle(SmallRyeMetricsHandler.java:18)
keycloak    | 	at io.vertx.ext.web.impl.BlockingHandlerDecorator.lambda$handle$0(BlockingHandlerDecorator.java:48)
keycloak    | 	at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$2(ContextImpl.java:313)
keycloak    | 	at io.opentelemetry.javaagent.instrumentation.api.concurrent.RunnableWrapper.run(RunnableWrapper.java:38)
keycloak    | 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
keycloak    | 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
keycloak    | 	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
keycloak    | 	at java.base/java.lang.Thread.run(Thread.java:829)
keycloak    | 
keycloak    | 2021-10-11 09:17:19,625 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (vert.x-eventloop-thread-5) HTTP Request to /q/metrics failed, error id: be9ae914-2e07-44a2-946c-1d9e4474f19d-2: java.lang.NullPointerException
keycloak    | 	at io.vertx.core.http.impl.Http1xServerConnection.responseComplete(Http1xServerConnection.java:185)
keycloak    | 	at io.vertx.core.http.impl.HttpServerResponseImpl.end(HttpServerResponseImpl.java:391)
keycloak    | 	at io.vertx.core.http.impl.HttpServerResponseImpl.end(HttpServerResponseImpl.java:365)
keycloak    | 	at io.quarkus.smallrye.metrics.runtime.SmallRyeMetricsHandler$1.respondWith(SmallRyeMetricsHandler.java:46)
keycloak    | 	at io.smallrye.metrics.MetricsRequestHandler.handleRequest(MetricsRequestHandler.java:168)
keycloak    | 	at io.smallrye.metrics.MetricsRequestHandler_ClientProxy.handleRequest(MetricsRequestHandler_ClientProxy.zig:242)
keycloak    | 	at io.quarkus.smallrye.metrics.runtime.SmallRyeMetricsHandler.handle(SmallRyeMetricsHandler.java:38)
keycloak    | 	at io.quarkus.smallrye.metrics.runtime.SmallRyeMetricsHandler.handle(SmallRyeMetricsHandler.java:18)
keycloak    | 	at io.vertx.ext.web.impl.BlockingHandlerDecorator.lambda$handle$0(BlockingHandlerDecorator.java:48)
keycloak    | 	at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$2(ContextImpl.java:313)
keycloak    | 	at io.opentelemetry.javaagent.instrumentation.api.concurrent.RunnableWrapper.run(RunnableWrapper.java:38)
keycloak    | 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
keycloak    | 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
keycloak    | 	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
keycloak    | 	at java.base/java.lang.Thread.run(Thread.java:829)
keycloak    |
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment