When network server disconnects due to an I/O Exception it does not always log the exception that caused the error

• Key: DERBY-2933
• Type: Bug
• Status: Open
• Priority: Minor
• Assignee: Unassigned
• Reporter: Kathey Marsden
• Component/s: Network Server
• Affects Version/s: 10.2.2.1

Description

I found this issue when debugging my attempted fix for DERBY-2892. The I/O Exception that occurs in writeScalarStream is not logged. To reproduce apply the patch in DERBY-2892 and run the repro there.

Comments

[Kathey Marsden]

Reproducible case is in DERBY-2892

[Kathey Marsden]

Attached is a patch that logs the IO/exceptions and other events that cause markCommunicationsFailure to be called. This change caused testNetworkServerSecurityMechanism to start logging this error. I am investigating that, but the patch to turn on the logging should not be committed until this is resolved.


testNetworkServerSecurityMechanism(org.apache.derbyTesting.functionTests.tests.derbynet.NSSecurityMechanismTest)
java.lang.Exception: totalBytesRead < minimumBytesNeeded
at org.apache.derby.impl.drda.DDMReader.fill(DDMReader.java:1936)
at org.apache.derby.impl.drda.DDMReader.ensureALayerDataInBuffer(DDMReader.java:1651)
at org.apache.derby.impl.drda.DDMReader.readDssHeader(DDMReader.java:321)
at org.apache.derby.impl.drda.DRDAConnThread.processCommands(DRDAConnThread.java:677)
at org.apache.derby.impl.drda.DRDAConnThread.run(DRDAConnThread.java:275)

[Kathey Marsden]

The error occurs whenever the datbase is shutdown and can be reproduced with this script.
It seems there is some cleanup needed of DDMReader when a severe error occurs.
 
ij> connect 'jdbc:derby://localhost:1527/wombat;create=true';
ij> connect 'jdbc:derby://localhost:1527/;shutdown=true';
totalBytesRead < minimumBytesNeeded
java.lang.Exception: totalBytesRead < minimumBytesNeeded
        at org.apache.derby.impl.drda.DDMReader.fill(DDMReader.java:1936)
        at org.apache.derby.impl.drda.DDMReader.ensureALayerDataInBuffer(DDMReader.java:1651)
        at org.apache.derby.impl.drda.DDMReader.readDssHeader(DDMReader.java:321)
        at org.apache.derby.impl.drda.DRDAConnThread.processCommands(DRDAConnThread.java:680)
        at org.apache.derby.impl.drda.DRDAConnThread.run(DRDAConnThread.java:275)
ERROR XJ015: DERBY SQL error: SQLCODE: -1, SQLSTATE: XJ015, SQLERRMC: Derby system shutdown.

[Kathey Marsden]

Here is another attempt at a patch. I am not really all that pleased with it as I fear it may still gobble some unexpected exceptions. This patch is the same as the first except for it does not log an exception for 1) SocketExceptions which are usually the client disconnecting.
2)The case where DDMReader.fill() expects bytes but gets none. This is the case when the database is shutdown.

I'd appreciate if someone can take a look. At least the patch does have the advantage that it will log some of the exceptions that were not being logged before. It is just a question of whether that is good enough.

Kathey

[Kathey Marsden]

Unassigning myself from this issue and reducing to minor. I fixed the error to log in writeScalarStream but there are still occassions where markCommunicationsFailure is called without logging, most notably when the server is brought down and active sessions are terminated. I left this as is. I am not sure if unexpected exceptions might still be left unlogged, so I am leaving this open.


Kathey

[Bernt M. Johnsen]

The exception handling in the network server should be taken into consideration in DERBY-2412. That should probably solve this in a decent way.

[Rick Hillegas]

Triage for 10.5.2: Assign normal urgency; note that has reproducible test case.