Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ContextNotActiveException when access database to sample prometheus gauge #25237

Closed
hendrikstill opened this issue Apr 28, 2022 · 9 comments
Closed
Labels
kind/bug Something isn't working triage/invalid This doesn't seem right

Comments

@hendrikstill
Copy link
Contributor

Describe the bug

When building a prometheus gauge via micrometer to count database entities no metric is collected.
Also the exception ContextNotActiveException is logged when endpoint /q/metrics is called.

It seem that prometheus endpoint is not handled correctly with an active context.

This makes it hard to collect custom gauges based on data of a panache repository.

Example gauge:

@ApplicationScoped
@Startup
public class MetricsCollector {

    private final MeterRegistry registry;

    private final MyRepository myRepository;

    public MetricsCollector(MeterRegistry registry, MyRepository myRepository) {
        this.registry = registry;
        this.myRepository = myRepository;
        Gauge.builder("my-gauge", myRepository::count).register(registry);
    }
}
2022-04-28 22:15:18,757 WARN  [io.mic.cor.ins.int.DefaultGauge] (vert.x-worker-thread-0) Failed to apply the value function for the gauge 'my-gauge'. Note that subsequent logs will be logged at debug level.: javax.enterprise.context.ContextNotActiveException
	at io.quarkus.arc.impl.ClientProxies.getDelegate(ClientProxies.java:46)
	at io.quarkus.hibernate.orm.runtime.RequestScopedSessionHolder_ClientProxy.arc$delegate(Unknown Source)

Expected behavior

For every prometheus scape should return the current count of myRepository

Actual behavior

Stacktrace:

2022-04-28 22:15:18,757 WARN  [io.mic.cor.ins.int.DefaultGauge] (vert.x-worker-thread-0) Failed to apply the value function for the gauge 'my-gauge'. Note that subsequent logs will be logged at debug level.: javax.enterprise.context.ContextNotActiveException
	at io.quarkus.arc.impl.ClientProxies.getDelegate(ClientProxies.java:46)
	at io.quarkus.hibernate.orm.runtime.RequestScopedSessionHolder_ClientProxy.arc$delegate(Unknown Source)
	at io.quarkus.hibernate.orm.runtime.RequestScopedSessionHolder_ClientProxy.getOrCreateSession(Unknown Source)
	at io.quarkus.hibernate.orm.runtime.session.TransactionScopedSession.acquireSession(TransactionScopedSession.java:104)
	at io.quarkus.hibernate.orm.runtime.session.TransactionScopedSession.createQuery(TransactionScopedSession.java:344)
	at io.quarkus.hibernate.orm.runtime.session.ForwardingSession.createQuery(ForwardingSession.java:168)
	at io.quarkus.hibernate.orm.runtime.session.ForwardingSession.createQuery(ForwardingSession.java:47)
	at org.hibernate.Session_5b93bee577ae2f8d76647de04cfab36afbf52958_Synthetic_ClientProxy.createQuery(Unknown Source)
	at io.quarkus.hibernate.orm.panache.common.runtime.AbstractJpaOperations.count(AbstractJpaOperations.java:318)
	at com.example.MyRepository.count(MyRepository.java)
	at com.example.MyRepository_Subclass.count$$superforward1(Unknown Source)
	at com.example.MyRepository_Subclass$$function$$36.apply(Unknown Source)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:54)
	at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.proceed(InvocationInterceptor.java:62)
	at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.monitor(InvocationInterceptor.java:51)
	at io.quarkus.arc.runtime.devconsole.InvocationInterceptor_Bean.intercept(Unknown Source)
	at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
	at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
	at com.example.MyRepository_Subclass.count(Unknown Source)
	at com.example.MyRepository_ClientProxy.count(Unknown Source)
	at io.micrometer.core.instrument.Gauge.lambda$builder$0(Gauge.java:58)
	at io.micrometer.core.instrument.StrongReferenceGaugeFunction.applyAsDouble(StrongReferenceGaugeFunction.java:47)
	at io.micrometer.core.instrument.internal.DefaultGauge.value(DefaultGauge.java:53)
	at io.micrometer.prometheus.PrometheusMeterRegistry.lambda$newGauge$5(PrometheusMeterRegistry.java:280)
	at io.micrometer.prometheus.MicrometerCollector.collect(MicrometerCollector.java:70)
	at io.prometheus.client.Collector.collect(Collector.java:46)
	at io.prometheus.client.CollectorRegistry$MetricFamilySamplesEnumeration.findNextElement(CollectorRegistry.java:197)
	at io.prometheus.client.CollectorRegistry$MetricFamilySamplesEnumeration.nextElement(CollectorRegistry.java:212)
	at io.prometheus.client.CollectorRegistry$MetricFamilySamplesEnumeration.nextElement(CollectorRegistry.java:152)
	at io.prometheus.client.exporter.common.TextFormat.write004(TextFormat.java:71)
	at io.prometheus.client.exporter.common.TextFormat.writeFormat(TextFormat.java:53)
	at io.micrometer.prometheus.PrometheusMeterRegistry.scrape(PrometheusMeterRegistry.java:134)
	at io.micrometer.prometheus.PrometheusMeterRegistry.scrape(PrometheusMeterRegistry.java:130)
	at io.micrometer.prometheus.PrometheusMeterRegistry.scrape(PrometheusMeterRegistry.java:101)
	at io.micrometer.prometheus.PrometheusMeterRegistry.scrape(PrometheusMeterRegistry.java:87)
	at io.quarkus.micrometer.runtime.export.handlers.PrometheusHandler.handle(PrometheusHandler.java:35)
	at io.quarkus.micrometer.runtime.export.handlers.PrometheusHandler.handle(PrometheusHandler.java:16)
	at io.vertx.ext.web.impl.BlockingHandlerDecorator.lambda$handle$0(BlockingHandlerDecorator.java:48)
	at io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)
	at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
	at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)
	at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
	at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
	at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
	at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:833)

Prometheus metric output:

# HELP my_gauge  
# TYPE my_gauge gauge
my_gauge NaN

How to Reproduce?

git clone https://github.com/hendrikstill/quarkus-prometheus-example
cd quarkus-prometheus-example
./mvnw quarkus:dev

curl http://localhost:8080/q/metrics

Output of uname -a or ver

Darwin xxx 21.4.0 Darwin Kernel Version 21.4.0: Fri Mar 18 00:46:32 PDT 2022; root:xnu-8020.101.4~15/RELEASE_ARM64_T6000 arm64

Output of java -version

openjdk 17.0.2 2022-01-18 OpenJDK Runtime Environment Temurin-17.0.2+8 (build 17.0.2+8) OpenJDK 64-Bit Server VM Temurin-17.0.2+8 (build 17.0.2+8, mixed mode)

GraalVM version (if different from Java)

No response

Quarkus version or git rev

2.8.2.Final

Build tool (ie. output of mvnw --version or gradlew --version)

Apache Maven 3.8.4 (9b656c72d54e5bacbed989b64718c159fe39b537) Maven home: /Users/xxx/.m2/wrapper/dists/apache-maven-3.8.4-bin/52ccbt68d252mdldqsfsn03jlf/apache-maven-3.8.4 Java version: 17.0.2, vendor: Eclipse Adoptium, runtime: /Users/xxx/Library/Java/JavaVirtualMachines/temurin-17.0.2/Contents/Home Default locale: de_DE, platform encoding: UTF-8 OS name: "mac os x", version: "12.3.1", arch: "aarch64", family: "mac"

Additional information

No response

@hendrikstill hendrikstill added the kind/bug Something isn't working label Apr 28, 2022
@ktysiac
Copy link

ktysiac commented May 5, 2022

Try adding @Transactional annotation to your repository/method

@hendrikstill
Copy link
Contributor Author

hendrikstill commented May 5, 2022

@ktysiac thanks for the hint

You are right. Wrapping the call into a transaction works 👍.

@ApplicationScoped
@Startup
public class MetricsCollector {
    private final MeterRegistry registry;

    private final MyRepository myRepository;

    public MetricsCollector(MeterRegistry registry, MyRepository myRepository) {
        this.registry = registry;
        this.myRepository = myRepository;
        Gauge.builder("my-gauge", () -> QuarkusTransaction.call(myRepository::count)).register(registry);
    }
} 

What is still frustrating is the missleading Exception as in I would expect a TransactionRequiredException in this case or an active context, which wouldn't need a dedicated transactional context for read access.

@geoand
Copy link
Contributor

geoand commented May 16, 2022

@yrodiere
Copy link
Member

yrodiere commented May 16, 2022

I wonder if we should catch the exception at https://github.com/quarkusio/quarkus/blob/2.9.0.Final/extensions/hibernate-orm/runtime/src/main/java/io/quarkus/hibernate/orm/runtime/session/TransactionScopedSession.java#L103 and try to provide a more useful error message

Assuming we can accurately identify the "context not active" exception or perform a preliminary check, indeed it would be nice to provide a more helpful message. Something that tells users "you need a transaction to use the entitymanager/session. Alternatively, if you really don't want transactions, you need to be in a request processing thread, or you need to activate the CDI request context explicitly". With better phrasing, of course, but that's the gist of it.

What is still frustrating is the missleading Exception as in I would expect a TransactionRequiredException in this case

That's out of the question, since sessions can be used outside of transactions, as long as there is a request context (yes, that means TransactionScopedSession is a very bad name, but not using transactions is kind of an exotic use case).

or an active context, which wouldn't need a dedicated transactional context for read access.

If you're handling a request, I think it's fair to expect the request context to be active. Though I can't tell whether it makes sense in the context of prometheus.

@geoand
Copy link
Contributor

geoand commented May 16, 2022

Assuming we can accurately identify the "context not active" exception or perform a preliminary check, indeed it would be nice to provide a more helpful message. Something that tells users "you need a transaction to use the entitymanager/session. Alternatively, if you really don't want transactions, you need to be in a request processing thread, or you need to activate the CDI request context explicitly". With better phrasing, of course, but that's the gist of it.

+1

If you're handling a request, I think it's fair to expect the request context to be active. Though I can't tell whether it makes sense in the context of prometheus.

Technically this is totally correct. But I have seen that this expectation often confuses users, who when they see ContextNotActiveException, have no idea what to do about it - that is why I am pushing for actionable error messages.

@yrodiere
Copy link
Member

If you're handling a request, I think it's fair to expect the request context to be active. Though I can't tell whether it makes sense in the context of prometheus.

Technically this is totally correct. But I have seen that this expectation often confuses users, who when they see ContextNotActiveException, have no idea what to do about it - that is why I am pushing for actionable error messages.

Right, I did not mean to deny the need for a better exception message in TransactionScopedSession. I just think we should also make sure Prometheus handlers activate the request context.

@yrodiere
Copy link
Member

I just think we should also make sure Prometheus handlers activate the request context.

Though in that case I see the exception occurs in the bean's constructor, so we're probably no handling a request. It's probably less clear-cut than what I thought.

@geoand
Copy link
Contributor

geoand commented May 16, 2022

Was about to say :)

Gauge.builder("my-gauge", myRepository::count).register(registry);

the call to our code is hidden. However, we can enable the request context at: https://github.com/quarkusio/quarkus/blob/2.9.0.Final/extensions/micrometer/runtime/src/main/java/io/quarkus/micrometer/runtime/export/handlers/PrometheusHandler.java#L35

I think I'll go ahead and do that, it makes sense as we don't really know what user code will be executed here, so we'd better be on the safe side.

@geoand
Copy link
Contributor

geoand commented May 16, 2022

#25594 is what I am talking about.

In any case, I'll close this issue as it's not a Quarkus issue (apart from the error message discussion above)

@geoand geoand closed this as completed May 16, 2022
@geoand geoand added the triage/invalid This doesn't seem right label May 16, 2022
geoand added a commit that referenced this issue May 16, 2022
Activate request context when prometheus scraping is invoked
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
kind/bug Something isn't working triage/invalid This doesn't seem right
Projects
None yet
Development

No branches or pull requests

4 participants