New Internal ProxyFactory Executes Extraneous Queries (NHibernate 3.2)

[Joseph Daigle]

I believe I've discovered an issue with the new build-in proxy factory for NHibernate.

If you have a proxy object which was created using ISession.Load<>(), then exceptions within NHibernate itself and the use of the NHibernate Profiler both will call ToString() on that proxy object. This results in an unwanted database look up for that entity.

I've already reported this issue with the NHibernate Profiler team: https://groups.google.com/d/msg/nhprof/V_001ogMYC0/RVF0Ys5XQw4J

The best way to demonstrate it is to do a test like this:

session.CreateCriteria<Bar>().Add(Restrictions.Eq("FooReference", session.Load<Foo>(Guid.NewGuid()))).List();

Assuming the correct database schema, one would expect this line of code to simply return an empty list. However if you have the NHibernate Profiler hooked up and execute this line of code, NHibernate will attempt will to load the instance of Foo (the profiler I think is calling  ToString() for its output). In this specific example, since the Id is random, it throws an exception.

Additionally, if the above query generates an exception (for instance the database schema is wrong and the query cannot execute), NHibernate appears to call ToString() on the proxy object when generating the exception message. Which, again in this example, will cause a look up, which in turn throws an exception saying that the row does not exist.

[Fabio Maulo]

Which version ?

IIRC it was fixed.

--
Fabio Maulo

[Joseph Daigle]

The GA build, downloaded from sourceforge. The DLL version is 3.2.0.4000.

[Fabio Maulo]

If you have a failing test it is an issue, if you don't it is a mirage.

On Wed, Aug 10, 2011 at 1:44 PM, Joseph Daigle <joseph...@gmail.com> wrote:

The GA build, downloaded from sourceforge. The DLL version is 3.2.0.4000.

--
Fabio Maulo

[Joseph Daigle]

I have a small console-app project here:

https://github.com/jdaigle/ProfilerBreakingTest

Run the app assuming you have the correct database schema. Three things:

1. If you run it as is (the profiler is initalized) the code throws an exception saying that it cannot initialize the proxy object (it should not be initializing the proxy object!)

2. If you remove the line of code for the profiler, the code exits cleanly (as expected).

3. If the database schema is wrong (such that the query should fail), and you remove the line of code for the profiler, the code throws an exception saying that it cannot initialize the proxy object (it should not be initializing the proxy object!)

[Fabio Maulo]

http://nhforge.org/blogs/nhibernate/archive/2008/10/04/the-best-way-to-solve-nhibernate-bugs-submit-good-unit-test.aspx

--
Fabio Maulo

[Joseph Daigle]

Thanks: that's a pretty useful little framework for building nhibernate tests

I've updated my code to follow that pattern: https://github.com/jdaigle/ProfilerBreakingTest

Would you like me to also create a bug in JIRA?

-- 

Joseph Daigle

[Fabio Maulo]

You test using

 HibernatingRhinos.Profiler.Appender.NHibernate.NHibernateProfiler.Stop();

is not something we are interested in NHibernate core.

--
Fabio Maulo

[Joseph Daigle]

That's how I found the bug, by using the profiler. The other test fixture includes two failing tests which don't rely on the profiler. One test in particular is interesting because it demonstrates that nhibernate is throwing an exception while it is handling a different one.

-- 

Joseph Daigle

[Patrick Earl]

Assuming you have verified the problem and not already created an
issue in JIRA, please do so.

Patrick Earl

[Joseph Daigle]

Done: https://nhibernate.jira.com/browse/NH-2834

In doing more research I actually discovered this "bug" is really the result of relying on Castle's behavior when handling proxies. Prior to 3.1 LinFu actually behaves the same way that the new DefaultProxyFactory in 3.2 behaves; in that it intercepts calls to ToString() sent to the base object class and forces the proxy to initialize.

I personally think that the proxy should only be initialized for ToString() methods if the mapped class overrides ToString(), much in the same way the Equals() and GetHashCode() behave. So I submitted a patch which introduces that same behavior. If ToString() is not overridden on the proxy, then simply return the class name. Otherwise fall through the default behavior for initializing the proxy.

ToString() is one of those methods which is very easy to call without explicitly calling it. Passing an object into code that, for example, generates exception messages or logs will likely call ToString() somewhere, which can have unintended side-effects. Such as an extra database query.

-- 

Joseph Daigle

[Fabio Maulo]

The problem is not how ToString is intercepted but the call to ToString itself.

A proxy have to be initialized to all methods excepting get_Id (to be short).

I don't think we are calling ToString other than some special logging is called and the log is enabled.

Repeted: the problem is not the proxy behavior but the log behavior (the SQL logger call ToString to show the parameter value but the parameter should not be a proxy, just the value used for the query).

btw: in your query, if you check for the Id directly instead use session.Load your "problem" will disappear.

--
Fabio Maulo

[Ayende Rahien]

Fabio,

The actual problem happens when you are have logging enabled.

The reason for that is  at NHibernate.Loader.Criteria.CriteriaQueryTranslator.CreateCriteriaSQLAliasMap()

We log the parameter value there, which obviously calls ToString() on it. Because of the behavior of the new proxy factory, it forces lazy loading of that parameter.

I would argue that this is a bug, since logging should not cause additional calls to the DB.

[Fabio Maulo]

Sure is a bug but of the logger.

We shouldn't call ToString on a dyn-proxy if we don't want explicitly a call to the underlining instance.

For log matters on a proxy we should show : entityname#id

We are using entityname#id "pattern" in others places (for exception at least IIRC).

--
Fabio Maulo

[Joseph Daigle]

Fabio,

I would agree with that. After reading Ayende's analysis, this seems far more logical than my suggestion of adding additional logic around "ToString()" in BasicLazyInitializer. In the end we just want to prevent logging/debugging from making additional DB calls.

-- 

Joseph Daigle

[Fabio Maulo]

I know.

--
Fabio Maulo

[Joseph Daigle]

So I see that NH-2834 was closed as "not an issue". What are the plans going forward to fix the issue as identified by Fabio and Ayende?

-- 

Joseph Daigle

[Patrick Earl]

Hi Joseph.

If the original issue was closed without being replaced with another
issue, feel free to make another issue addressing the logging of
proxies. It seems that the patch for the logging would be fairly
straight-forward too. We'd be happy if you could look into it and
submit a patch with tests.

Patrick Earl

[Ramon Smits]

Hi Joseph,

It seems that you are having the same issue as I. I have created a fix for it: 

https://github.com/nhibernate/nhibernate-core/pull/36 

Maybe it is of help to you. I have also created a Jira issue for it.

--

Ramon