02.04.2017 14:59, Mark Rotteveel wrote:
> 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
It is receive buffer with two op_event (52, or 0x34) packets:
00000034 0000 0000 00000012 01 0C 544553545F4556454E545F42 C2010000 0000
00000000 00000000 000002B5
TEST_EVENT_B: cnt = 0x1C2 = 450, id = 0x2B5 = 693
00000034 0000 0000 00000012 01 0C 544553545F4556454E545F41 85030000 0000
00000000 00000000 000002B6
TEST_EVENT_A: cnt = 0x385 = 901, id = 0x2B6 = 694
> [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 }
I see no op_que_events (48, or 0x30) packets.
> [AbstractWireOperations]readStatusVector arg:isc_arg_gds int: 0
> [V10AsynchronousChannel]java.nio.HeapByteBuffer[pos=0 lim=44 cap=2048]:
> 000000340000000000000012010C544553545F4556454E545F42C301000000000000000000000000000002B8
This is received packet with
TEST_EVENT_B: cnt = 0x1C3 = 451, id = 0x2B5 = 696
You claim it must have it 695, correct ?
> [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.
I can't confirm it without op_que_events content.
> As the event name is proper (although not 100% sure it always is),
This is really interesting to check
...
> 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?
Ideally, reproducible test case needed. As simple, as possible. Also, we
could log every packet related to events on server side.
> Other example: both A and B are acknowledged with id of event B:
Provide, please, op_que_events contents to confirm this.
Regards,
Vlad
------------------------------------------------------------------------------
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
