2

While integrating opentelemetry with tridion content.svc, we realized that there are a lot of broken spans in the Jaeger UI. After a bit of investigation, we suspected that the trace spans are set to a certain limit hence we increased that in opentelemetry configuration - BUT this did not solve the issue.

We then moved forward investigation more and realized that when content.svc is called for eg:

/client/v2/content.svc/Publications(27)/Keywords?$filter=(TaxonomyId%20e
q%2040)&$expand=Components&$format=json

it has alot of NullPointerException reported:

java.lang.NullPointerException 
        at com.tridion.cache.CacheChannel.isServiceValid(CacheChannel.java:369) 
        at com.tridion.cache.CacheChannel.isCachingAllowed(CacheChannel.java:380) 
        at com.tridion.cache.BroadcastCache.isCachingAllowed(BroadcastCache.java:127) 
        at com.tridion.cache.BroadcastCache.put(BroadcastCache.java:36) 
        at com.tridion.storage.caching.CachedQueryDAO.listQuery(CachedQueryDAO.java:62) 
        at com.sdl.web.content.odata.input.jpql.JPQLExecutor.execute(JPQLExecutor.java:154) 
        at 
com.sdl.web.content.resolver.PublicationsResolver.resolveEntry(PublicationsResolver.java:62) 
        at com.sdl.web.content.odata.input.resolver.ResolverBase.resolve(ResolverBase.java:88) 
        at 
com.sdl.web.content.odata.input.resolver.ResolverBase.getPreviousResolved(ResolverBase.java:20
3) 
        at com.sdl.web.content.odata.input.resolver.ResolverBase.resolve(ResolverBase.java:65) 
        at 
com.sdl.web.content.odata.input.handler.ODataFeedRenderer.renderODataFeed(ODataFeedRenderer.ja
va:57) 
        at 
com.sdl.web.content.odata.input.handler.ODataWebHandler.handleODataEntity(ODataWebHandler.java
:207) 
        at 
com.sdl.web.content.odata.input.handler.ODataWebHandler.handleResourceRequest(ODataWebHandler.
java:178) 
        at 
com.sdl.web.content.controller.ContentV2Controller.handleResourceRequest(ContentV2Controller.j
ava:92) 
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) 
        at 
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) 
        at java.lang.reflect.Method.invoke(Method.java:498) 
        at 
org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.
java:190) 
        at 
org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandle
rMethod.java:138) 
        at 
org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndH
andle(ServletInvocableHandlerMethod.java:104) 
        at 
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandl
erMethod(RequestMappingHandlerAdapter.java:892) 
        at 
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInter
nal(RequestMappingHandlerAdapter.java:797) 
        at 
org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandler
MethodAdapter.java:87) 
        at 
org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1039) 
        at 
org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:942) 
        at 
org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1005) 
        at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:897) 
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:634) 
        at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:882) 
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:741) 
        at 
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:2
31) 
        at 
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) 
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53) 
        at 
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:1
93) 
        at 
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) 
        at 
org.springframework.boot.actuate.web.trace.servlet.HttpTraceFilter.doFilterInternal(HttpTraceF
ilter.java:88) 
        at 
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:109) 
        at 
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:1
93) 
        at 
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)

We first thought that this is something with our configuration (still not sure) but we did not find anything significant.

We looked deepper into opentelemetry logs and found that every single orphan span (the ones that referenced missing parent span) that appeared in Jaeger UI is at Hibernate database operations.

We then realized that this might be happening due to open hibernate sessions because OpenTelemetry reports spans for sessions only when a session is closed. This way it can measure the time it took for a Hibernate session and all of the database operations executed within that session. If a session is never closed, it simply will not report it.

and we concluded that - the corresponding Hibernate session was not reported for all those database operations during the service call.

We decided to reproduce similar behavior in a sample Hibernate project and we also managed to get the same result by throwing an exception before the closing of Hibernate session and not handling it on purpose.

We also analyzed trace for that call and within that call, Tridion Content Service has executed 5855 database statements out of which 78 were reported without sessions (so presumably their session was not closed correctly and therefore was not reported to OpenTelemetry collector)

The only way for us to see all these exceptions is by enabling debug logging in the OpenTelemetry Java agent. Without this setting, we don’t see those errors anywhere. That could indicate that the exception is caught somewhere above and is not printed, but, because the OpenTelemetry agent intercepts and wraps the call, it is able to get it and print it.

Please let us know what could be the issue?

6
  • I'm not sure I understand the issue - yes, there are a lot of NPE's you're seeing, and it seems to be deep within Hibernate. Are you actually seeing issues because of this, is this maybe normal with how Hibernate manages pooled sessions? Is your database running out of available connections? Is the connection pool depleted? What I'm trying to say is that perhaps that's how Hibernate handles it? (I am not sure, and quite curious about it now too).
    – Nuno Linhares
    Dec 28 '21 at 9:28
  • Hey Nuno, I am not sure either, but would love to deep dive with any inputs I have to look forward into it. The current issue relates to cache channel service ( at com.tridion.cache.CacheChannel.isServiceValid) somewhere and I am not sure if hibernate leaves a connection open on purpose. Also, I might be wrong but I also see alot of queries to DB for a simple content.svc call. It might be a question for support though but just saying if it could be related. Dec 28 '21 at 16:04
  • OK. A single content service call could trigger lots of queries, depending on the information requested (the example you have is taxonomy which could be DB heavy) but as you say that's perhaps more for support to look into.
    – Nuno Linhares
    Dec 29 '21 at 13:34
  • Yeah understandble. An open db session (for a longer period) could be a performance bottleneck, indeed something that support should be able to explain. anyone else has further inputs? Jan 3 at 7:41
  • use the MS SQL Profile Tracing tool to capture your SQL query to see what it's going on. as @Nuno mentioned just for one data query in the backend it will be multiple SQL queries joining to get the response what it's expected.
    – Velmurugan
    Jan 4 at 9:10

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.