Komische Reihenfolge mit dynamischem Proxy

[gizmo]

Im InvocationHandler habe ich folgenden Code:

	public Object invoke(Object proxy, Method method, Object[] args) throws Throwable {
		Object ret = null;
		Transaction transaction = transactionFactory.createTransaction();
		try {
			transaction.begin();
			System.out.println("Begin Meth1: " + Thread.currentThread().getId());
			ret = method.invoke(delegate, args);
			System.out.println("Begin Comm1: " + Thread.currentThread().getId());
			transaction.commit();
			System.out.println("End Comm1: " + Thread.currentThread().getId());
		} catch (Throwable t) {
			transaction.rollback();
			throw t;
		}
		return ret;
	}

Im Log finde ich folgendes:

Begin Comm1: 17
16:21:30,953 DEBUG JDBCTransaction:134 - commit
16:21:30,953 DEBUG JDBCTransaction:147 - committed JDBC Connection
16:21:30,953 DEBUG ConnectionManager:427 - aggressively releasing JDBC connection
16:21:30,953 DEBUG ConnectionManager:464 - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
End Comm1: 17
Begin Comm1: 17
Exception in thread "AWT-EventQueue-0" org.hibernate.SessionException: Session is closed!

Kann mir das jemand erklären? Ich sehe nicht wie es sein kann, dass nach "End Comm1: 17" wieder "Begin Comm1: 17" kommt, ohne dass dazwischen ein "Begin Meth1: 17" steht.

 

[faetzminator]

Was macht [c]transactionFactory.createTransaction()[/c]?

 

[gizmo]

Erzeugt eine Transaction (Wrapper um Hibernate Transaction).

 

[FArt]

Vermutung: der Fehler sitzt davor und diese Meldung gibt es woanders auch noch ?!?

Einfach mal den Debugger anwerfen, dürfte nicht so schwer sein...

Tipp: nimm eine Logging-API, das ist nicht schwerer, ist aber besser zu lesen und enthält bei richtiger Konfiguration wichtige Informationen (ausführender Thread, Klasse, Zeilennummer, ....)

 

[gizmo]

Ich habe schon einige Zeit im Debugger verbracht und bin 100% sicher, dass es diese Meldung nirgends sonst gibt.

Daher verwirrt es mich, wie kann ein Thread bei Begin Comm1 sein, ohne bei Begin Meth1 gewesen zu sein.

 

[FArt]

Ich habe schon einige Zeit im Debugger verbracht und bin 100% sicher, dass es diese Meldung nirgends sonst gibt.

Das würde mich auch verwundern. Was sagt denn der Debugger? Da musst du doch zwei mal dran vorbeikommen an dieser Stelle... und dann würde man ja auch den Call-Stack sehen, das sollte die Lösung ein sehr gutes Stück näher bringen...

 

[gizmo]

Ausser dass es beim zweiten Mal eine andere Methode war, welche im Proxy aufgerufen wurde, ist mir nichts aufgefallen.

Begin Comm1: 17 getSubFoldersOf
21:53:36,681 DEBUG JDBCTransaction:134 - commit
21:53:36,681 DEBUG JDBCTransaction:147 - committed JDBC Connection
21:53:36,681 DEBUG ConnectionManager:427 - aggressively releasing JDBC connection
21:53:36,681 DEBUG ConnectionManager:464 - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
End Comm1: 17 getSubFoldersOf
Begin Comm1: 17 deleteFolder

 

[FArt]

Hast du einen Breakpoint auf die Logmeldung Begin Comm1? Und der zieht zwei mal? Hast du einen Breakpoint auf den Methodenanfang (Objet ret = null)? Und zieht nur einmal?
Ne, oder?

Poste doch mal die Callstacks der invoke-Methode wenn der Debugger anhält.

 

[gizmo]

Habe den Fehler nun doch noch finden und beheben können.

War ein Problem mit den Benachrichtigungen, die Observer wurden zu früh benachrichtigt und wollten sich dann updaten, was wiederum über den InvocationHandler ging. Danach war die Transaction geschlossen.

 

[FArt]

Habe den Fehler nun doch noch finden und beheben können.

War ein Problem mit den Benachrichtigungen, die Observer wurden zu früh benachrichtigt und wollten sich dann updaten, was wiederum über den InvocationHandler ging. Danach war die Transaction geschlossen.

Verstehe ich nicht. Das erklärt zwar das Fehlverhalten bzgl. der Transaktion bzw. der Connection, aber nicht die fehlende Logmeldung. Auch wenn eine andere Methode über den InvocationHandler abgefrühstückt wird, muss doch die Logmeldung kommen, oder?