To come back to this again, there seems to be a concurrency bug in
events posted by Firebird to the client. It looks like it overwrites
local event ids (shared buffer, race condition?).
This is triggered by running the entire Jaybird test suite. Running the
specific test, TestFBEventManager.testLargeMultiLoad, in isolation
significantly reduces the chance of it occurring.
For example a test run shows:
[V10AsynchronousChannel]Queue event: WireEventHandle:{
name:TEST_EVENT_A, localId:694, eventId:0, internalCount:897,
previousInternalCount:897 }
[AbstractWireOperations]readStatusVector arg:isc_arg_gds int: 0
[V10AsynchronousChannel]java.nio.HeapByteBuffer[pos=0 lim=88 cap=2048]:
000000340000000000000012010C544553545F4556454E545F42C201000000000000000000000000000002B5000000340000000000000012010C544553545F4556454E545F418503000000000000000000000000000002B6
[V10AsynchronousChannel]Received event id 693, eventCount 450
[V10AsynchronousChannel]Queue event: WireEventHandle:{
name:TEST_EVENT_B, localId:695, eventId:0, internalCount:450,
previousInternalCount:450 }
[AbstractWireOperations]readStatusVector arg:isc_arg_gds int: 0
[AbstractWireOperations]readStatusVector arg:isc_arg_gds int: 0
[V10AsynchronousChannel]Received event id 694, eventCount 901
[V10AsynchronousChannel]Queue event: WireEventHandle:{
name:TEST_EVENT_A, localId:696, eventId:0, internalCount:901,
previousInternalCount:901 }
[AbstractWireOperations]readStatusVector arg:isc_arg_gds int: 0
[V10AsynchronousChannel]java.nio.HeapByteBuffer[pos=0 lim=44 cap=2048]:
000000340000000000000012010C544553545F4556454E545F42C301000000000000000000000000000002B8
[AbstractWireOperations]readStatusVector arg:isc_arg_gds int: 0
[V10AsynchronousChannel]Received event id 696, eventCount 451
[V10AsynchronousChannel]Queue event: WireEventHandle:{
name:TEST_EVENT_A, localId:697, eventId:0, internalCount:451,
previousInternalCount:451 }
In other words, Firebird posts event data for TEST_EVENT_B (count 450 ->
451) with the local event id of TEST_EVENT_A. On occasion I also see
that it resends an earlier - already acknowledged - local event id.
As the event name is proper (although not 100% sure it always is), I
might be able to workaround this in the pure java implementation by
matching based on the event name instead, but that is hardly a good
workaround, because it is possible the same event name is registered
multiple times, and it won't solve the occurrence of the same bug with
the native client.
This seems to suggest a race condition of some kind when the events are
posted/written to the aux connection.
I can reproduce this with Jaybird master, Firebird 3.0.2.32703 on
Windows 10 64 bit, but I have also seen it with other Firebird versions,
and with Jaybird 2.2 (which has a significantly different implementation
of event handling), both with pure java and the native client use.
Any thoughts or ideas on this, or is it better if I just create a bug
report?
Other example: both A and B are acknowledged with id of event B:
[V10AsynchronousChannel]Received event id 640, eventCount 843
[V10AsynchronousChannel]Queue event: WireEventHandle:{
name:TEST_EVENT_A, localId:642, eventId:0, internalCount:843,
previousInternalCount:843 }
[AbstractWireOperations]readStatusVector arg:isc_arg_gds int: 0
[AbstractWireOperations]readStatusVector arg:isc_arg_gds int: 0
[FBManagedConnection]End called: Xid[773794790]
[V10AsynchronousChannel]Received event id 641, eventCount 422
[V10AsynchronousChannel]Queue event: WireEventHandle:{
name:TEST_EVENT_B, localId:643, eventId:0, internalCount:422,
previousInternalCount:422 }
[AbstractWireOperations]readStatusVector arg:isc_arg_gds int: 0
[AbstractWireOperations]readStatusVector arg:isc_arg_gds int: 0
[AbstractWireOperations]readStatusVector arg:isc_arg_gds int: 0
[V10AsynchronousChannel]java.nio.HeapByteBuffer[pos=0 lim=88 cap=2048]:
000000340000000000000012010C544553545F4556454E545F414D0300000000000000000000000000000283000000340000000000000012010C544553545F4556454E545F42A70100000000000000000000000000000283
[V10AsynchronousChannel]Received event id 643, eventCount 845
[V10AsynchronousChannel]Queue event: WireEventHandle:{
name:TEST_EVENT_B, localId:644, eventId:0, internalCount:845,
previousInternalCount:845 }
[AbstractWireOperations]readStatusVector arg:isc_arg_gds int: 0
[AbstractWireOperations]readStatusVector arg:isc_arg_gds int: 0
[V10AsynchronousChannel]Received event id 643, eventCount 423
On 15-1-2017 11:56, Mark Rotteveel wrote:
> I have a test in Jaybird that post multiple events
> (https://github.com/FirebirdSQL/jaybird/blob/master/src/test/org/firebirdsql/event/TestFBEventManager.java#L173)
>
> Essentially it inserts on multiple threads (100 inserts per thread, 5
> threads, a commit after each insert) which causes a trigger to post
>
> POST_EVENT 'TEST_EVENT_A'
> POST_EVENT 'TEST_EVENT_B'
> POST_EVENT 'TEST_EVENT_A'
>
> (yes, it is posting TEST_EVENT_A twice)
>
> Which should lead to posting TEST_EVENT_A 1000 times and TEST_EVENT_B
> 500 times. This test occasionally fails (about 1 in 3 runs on Firebird
> 3). I initially thought I wasn't waiting long enough for all events to
> be received.
>
> After adding some extra debug logging, it looks like Firebird is
> occasionally losing event registrations (not posting them, but the event
> is unregistered), or posting an event with the id of TEST_EVENT_A, but
> posting the count of TEST_EVENT_B (or vice versa), but both events are
> unregistered, which seems to indicate some sort of race condition or
> interleaved writes of the event.
>
> I can reproduce this problem both with Jaybird 2.2 and Jaybird 3, which
> have a totally different implementations.
>
> As far as I can tell it is not version specific, but it is more easily
> reproducible on Firebird 3 and 4 (probably because I'm using SuperServer).
>
> Could someone take a look at this?
>
> Mark
>
--
Mark Rotteveel
------------------------------------------------------------------------------
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot
Firebird-Devel mailing list, web interface at
https://lists.sourceforge.net/lists/listinfo/firebird-devel
