vcmp filter with operator "spy.NE" not working properly about zorka HOT 7 CLOSED

I just noticed the zorka logfile gets a new entry every time a filter applies/matches:
2015-03-26 11:44:26 INFO DispatchingSubmitter Submission thread local stack mismatch (ctx=com.jitlogic.zorka.core.spy.SpyContext@6dc65da5, stage=2, submitFlags=2)

Then, I saw some TODO comment in the DispatchingSubmitter:
"TODO what happens to submission stack when spy context disappears when some method is executing ?"

Does that mean, there's no implementation for this case yet?
Is it safe to just uncomment the logging code for now (to prevent spammy entries in the logs) or are there other consequences of this behaviour?

from zorka.

Ah thank you. Unfortunately when I was implementing ComparatorProcessor I tried to be "clever" and this resulted in unreadable mess that is now bringing such nasty bugs you've discovered. Now I'm integrating your fix into mainline codebase, maybe later on I'll try to rethink and rewrite this piece into a more decent form :)

Thanks (and sorry for delayed answer).

from zorka.

Regarding DispatchingSubmitter: in principle this situation should not happen. At the beginning of each instrumented method [.onEnter()] a newly created context object is put onto stack. On return [.onReturn(),.onError(),.onSubmit()] context is popped out of the stack, so information grabbed at method entry can be reused after method execution. There is a bunch of corner cases as well, for example you can have only .onEnter() chain defined, so only method entry will be instrumented. This is somewhat delicate situation as one needs to keep context stack in sync with instrumented code execution. Agent tries to handle such cases as well (at least those I've envisioned or encountered) but no one says there are no additional ones. In order not to break monitored code, spy cannot just crash - it handles such 'unexpected' situations (that shouldn't happen) by issuing log message. It might be either a bug in intrumentation engine itself or beanshell instrumentation definitions (or even BSH functions when used inside instrumentation chains). For me this indicates that the particular case you've encountered should be isolated and debugged. Ignoring these messages will lead to a number of dropped (or only partially executed) monitorings of instrumented method.

from zorka.

Thanks for your reply.
In my case, this log message shows up, every time my vcmp filter matches:

.onEnter(
spy.fetchArg("THIS", 0),
spy.get( "CLASSNAME", "THIS", "class", "name"),
//vcmp code below causes log entry, if filter matches
spy.vcmp( "CLASSNAME", spy.NE, "com.sun.jersey.spi.container.servlet.ServletContainer"),
//some more code here...
)

I am instrumenting:
.include(spy.byMethod( "javax.servlet.http.HttpServlet", "service"))

from zorka.

So here we are. If spy.vcmp(...) stops .onEnter() chain (and that's how filters work - they stop chain execution), it will result in context not being pushed onto stack. Try something like this:

.onEnter(
spy.fetchArg("THIS", 0),
spy.get( "CLASSNAME", "THIS", "class", "name"),
spy.subchain(
//vcmp code below causes log entry, if filter matches
spy.vcmp( "CLASSNAME", spy.NE, "com.sun.jersey.spi.container.servlet.ServletContainer"),
//some more code here...
)
)

Function spy.subchain() will group another elements into a (sub-)chain that will return context even if chain execution will be stopped.

from zorka.

Every time you do some kind of filtering in .onEnter() and then have either .onReturn(), .onError() or .onSubmit() defined, you need to be careful about always returning something. Maybe I should handle this case more gracefuly (eg. push null into stack - to ensure that exit chains won't execute in more controlled way).

from zorka.

Works like a charm, thank you!

from zorka.