Serilog causes collection initializing with zero rows after update to NH5

[jsmarcus]

I have a lazy loaded collection that is not initializing properly after updating to NH5. From what I can tell I have everything configured correctly and I have not found any change notes that indicate I should be doing things differently in NH5 compared to 4. I have tried debugging and tracing what is going on but have reached the limits of what I can check unassisted.

Collection config

    <set cascade="none" inverse="true" name="AccountSites" where="IsActive = 1">
      <key>
        <column name="AccountId" />
      </key>
      <one-to-many class="Manager360.Entities.Accounts.AccountSiteEntity, Manager360, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null" />
    </set>

Many-to-one config

    <many-to-one cascade="none" class="Manager360.Entities.Accounts.AccountEntity, Manager360, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null" name="Account" not-found="ignore">
      <column name="AccountId" />
    </many-to-one>

I have attached the log for the initialization of the collection. Please any direction to help track down the issue would be helpful.

Collection Initialization Log.txt

[fredericDelaporte]

No idea. Try isolating your trouble into a test case, then I may be able to check what is going on. See there.

[bahusoid]

According to log 0 records are loaded from DB.
So is generated query incorrect?

SELECT accountsit0_.AccountId AS accountid3_1_1_
	,accountsit0_.EntityId AS entityid1_1_1_
	,accountsit0_.EntityId AS entityid1_1_0_
	,accountsit0_.Version AS version2_1_0_
	,accountsit0_.AccountId AS accountid3_1_0_
	,accountsit0_.Privileges AS privileges4_1_0_
	,accountsit0_.SiteId AS siteid5_1_0_
	,accountsit0_.CreatedById AS createdbyid6_1_0_
	,accountsit0_.CreatedByName AS createdbyname7_1_0_
	,accountsit0_.CreatedCoordinates AS createdcoordinates8_1_0_
	,accountsit0_.CreatedDate AS createddate9_1_0_
	,accountsit0_.CreatedLocation AS createdlocation10_1_0_
	,accountsit0_.CreatedThreatLevel AS createdthreatlevel11_1_0_
	,accountsit0_.IsActive AS isactive12_1_0_
	,accountsit0_.ModifiedById AS modifiedbyid13_1_0_
	,accountsit0_.ModifiedByName AS modifiedbyname14_1_0_
	,accountsit0_.ModifiedCoordinates AS modifiedcoordinates15_1_0_
	,accountsit0_.ModifiedDate AS modifieddate16_1_0_
	,accountsit0_.ModifiedLocation AS modifiedlocation17_1_0_
	,accountsit0_.ModifiedThreatLevel AS modifiedthreatlevel18_1_0_
FROM AccountSites accountsit0_
WHERE (accountsit0_.IsActive = 1)
	AND accountsit0_.AccountId = '8736478d-fcff-4a35-ac44-cfdf426d83c1'

If this query loads something then it seems something wrong with parameters setting logic.

[jsmarcus]

@bahusoid When I run the query manually I get 7 records. I'm going to try to generate a test case following the instructions from @fredericDelaporte.

[gacu82]

@jsmarcus are you using Serilog NH logging? I have the same issue (no child collections loaded) when using package NHibernate.Logging.Serilog.
There is a line in SerilogLogger.cs:
_contextLogger.Write(MapLevels[logLevel], exception, state.Format, state.Args);

When I hack it and don't pass state.Args, the issue is gone.

[jsmarcus]

@gacu82 I wasn't using Serilog but was using the sample implementation of the NHibernateToMicrosoftLogger. It has a similar line which causes the problem.

nhibernate-core/src/NHibernate.Example.Web/Infrastructure/NHibernateToMicrosoftLogger.cs

Line 30 in 92de0b7

_msLogger.Log(MapLevels[logLevel], 0, new FormattedLogValues(state.Format, state.Args), exception, MessageFormatter);

[fredericDelaporte]

That is a finding! How a logger can corrupt loading? From what you have seen, is it a flaw on the NHibernate side or on the logger side? Anyway since the example logger triggers this too, a test case for reproducing this easily (then fixing either the logger or NHibernate) would still help.

[fredericDelaporte]

This is a 5.1 regression introduced by #1377.
In this case, the faulty line is this one:

log.Debug("constructing collection load context for result set [{0}]", resultSet);

Previously, it was:

log.Debug("constructing collection load context for result set [" + resultSet + "]");

The change has been made to enable structured logging. Previous code was always just calling a "ToString()" on resultSet, which was not mutating its state. But with the new code, a logger may do other operations. In this case, Serilog does find that the formatting argument contains a thing which is enumerable (DbDataReader implements IEnumerable) and it does enumerate it. But in the case of a data reader, this advances it to its end, causing it to appear empty for subsequent usages.

So enabling debug logs may wreck collection loading, depending on the used logger.

But what should be done?
(Personally I am inclined to only log exceptions and only at places where they are swallowed (so typically in the general error handling code), which would avoids this kind of big traps. But as this is not the NHibernate way, I have to bear having log bloat in its code.)

Should it be considered as a flaw of Serilog, which should have more advanced logics for avoiding mutating logged objects? (Like detecting that the enumerable is a data reader and should not be enumerated...)

Or is it a known bad practice to supply this kind of mutable objects to the logger, and this should be changed everywhere in NHibernate ? (For what? An explicit .ToString()?)

@ngbrown, any thoughts?

[ngbrown]

Serilog has logic that clones a byte[] array incase it is mutated by the application, I don't think they considered that enumerating an IEnumerable would "mutate" the object though.

Replacing resultSet with resultSet.ToString() would solve this. The if (log.IsDebugEnabled()) is still in place.

However, it appears the goal is actually to display the concrete type of the DbDataReader so it would be better to be more explicit: resultSet.GetType(). (with or without the .ToString()):

log.Debug("constructing collection load context for result set [{0}]", resultSet.GetType());