Unusable trace data called in a callback

[jokaorgua]

Environment

How do you use Sentry? Self-hosted (Sentry 21.11.0)

Which SDK and version? PHP 4.2.8

Used config for sentry in symfony

tracing:
        enabled: true
        dbal: # DB queries
            enabled: true
        cache:
            enabled: true
        twig: # templating engine
            enabled: true

Steps to Reproduce

1. Create any kind of a controller for symfony for any kind of a route (POST, GET)
2. Provide a CacheInterface to it (I used redis as an adapter)
3. use code similar to

return $this->cache->get(
            function (ItemInterface $item) {
                $item->expiresAfter($this->cacheTime);

                return $this->handler->handle($someDataWhatever);
            }
        );

Expected Result

Trace in sentry with normal function names. At least $this->handler->handle took 50ms or similar

Actual Result

[ste93cry]

If I understand correctly, what you are reporting is that the span has a random name (that hash is not something we’re generating in the SDK) while it should probably be the name of the retrieved key, right?

[jokaorgua]

@ste93cry not only that. I'm expecting that span will have information about the total working time of the wrapped cache function. In our case, this is the handle function.

and I like you idea of renaming the spans for including the cache key in it. Or maybe other way to understand which key was requested

[ste93cry]

I'm expecting that span will have information about the total working time of the wrapped cache function. In our case, this is the handle function.

I’m not sure I get what’s the problem right now. The span is already wrapping the execution of whatever method is called internally, so it measures and reports its execution time already

[jokaorgua]

I'm expecting that span will have information about the total working time of the wrapped cache function. In our case, this is the handle function.

I’m not sure I get what’s the problem right now. The span is already wrapping the execution of whatever method is called internally, so it measures and reports its execution time already

I do not see such functionality. At least my sentry does not show anything related to handler function in traces

this is all that I see

[ste93cry]

I think I'm getting a grasp of what you want. I completely missed the fact that $this->handler->handle() was your own code and not something part of the SDK. In this case, its execution time is of course measured as part of the parent $this->cache->get() call, but if what you're looking for is a child span that specifically measures its execution time only then you won't find it because, well, the SDK cannot instrument something that it doesn't know about. If you want to trace your own code, you have to instrument it yourself. The documentation is a good place to start from to see how you can do it

[jokaorgua]

Of course if I need to measure my own code I will add spans manually into the handler itself.

Maybe it would be possible to change the sdk to include cache key into the span ? As you proposed above. At least this could help to find the needed cache-get span where the handler has been executed.

[ste93cry]

Maybe it would be possible to change the sdk to include cache key into the span

Absolutely. I would classify this as a bug, because when I coded the integration I actually meant to log the cache key, but then I must have forgot it during the implementation

[github-actions[bot]]

This issue has gone three weeks without activity. In another week, I will close it.

But! If you comment or otherwise update it, I will reset the clock, and if you label it Status: Backlog or Status: In Progress, I will leave it alone ... forever!

---

"A weed is but an unloved flower." ― Ella Wheeler Wilcox 🥀

[jokaorgua]

No stale. This is a bug

[cleptric]

Hey @jokaorgua I know it's been a while, but I looked into this.

We could add the cache key as the span description, would this be helpful? I still have to figure out the format of these keys, I had to do some urlencode to make them look half decent.

[jokaorgua]

@cleptric awesome. Maybe would be better to have a line too ?

[cleptric]

I'm not sure if we have access to the line number here. Or did I get your question wrong?

[jokaorgua]

@cleptric my bad. I though this is a path of a caller. And this is a cache key. Sorry. Your idea is great. Would be awesome.

[cleptric]

I opened https://github.com/getsentry/sentry-symfony/pull/677. Would be happy if you can try it out and report back 👍

[cleptric]

Released via 4.8.0