Quantcast

Unexplained problem

classic Classic list List threaded Threaded
6 messages Options
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Unexplained problem

Donald McLean-3
I'm trying to run a Derby in server mode. When I go to shut it down, I'm getting this weird error:

Mon Nov 21 16:19:44 EST 2016 : Invalid reply from network server: Insufficient data.

The command line arguments:

/usr/bin/java, -jar, /Users/dmclean/Library/java/db-derby-10.12.1.1-bin/lib/derbyrun.jar, server, shutdown
Does anyone have any suggestions as to what the problem would be and how to fix it?

Thank you,

Donald
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Unexplained problem

Bryan Pendleton-3
On 11/21/2016 1:52 PM, Donald McLean wrote:

> I'm trying to run a Derby in server mode. When I go to shut it down, I'm getting this weird error:
>
> Mon Nov 21 16:19:44 EST 2016 : Invalid reply from network server: Insufficient data.
>
> The command line arguments:
>
> /usr/bin/java, -jar, /Users/dmclean/Library/java/db-derby-10.12.1.1-bin/lib/derbyrun.jar, server, shutdown
>
> Does anyone have any suggestions as to what the problem would be and how to fix it?
>
> Thank you,
>
> Donald


I don't think I recall having seen that before. There are some old jobs
in the Derby issues database (e.g., DERBY-6337) that indicate that if the
Network Server is slow to respond, or slow to shut down, then the client
may print some odd messages.

Does this happen *every* time you shut down the Network Server?

What does the end of your derby.log file look like?

thanks,

bryan

Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Unexplained problem

Donald McLean-3
Hi Bryan,

The contents of the derby.log are confusing to me (see below). How can it be complaining that it can't bind to the port one minute and then get connections the next?

Tue Nov 22 10:10:06 EST 2016 : Apache Derby Network Server - 10.12.1.1 - (1704137) started and ready to accept connections on port 2148
Tue Nov 22 10:10:06 EST 2016 : Could not listen on port 2148 on host localhost:
java.net.BindException: Address already in use (Bind failed)
An exception was thrown during network server startup. DRDA_ListenPort.S:Could not listen on port 2148 on host localhost:
java.net.BindException: Address already in use (Bind failed)
java.lang.reflect.InvocationTargetException
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.derby.iapi.jdbc.DRDAServerStarter.run(Unknown Source)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.Exception: DRDA_ListenPort.S:Could not listen on port 2148 on host localhost:
java.net.BindException: Address already in use (Bind failed)
at org.apache.derby.impl.drda.NetworkServerControlImpl.consolePropertyMessageWork(Unknown Source)
at org.apache.derby.impl.drda.NetworkServerControlImpl.consolePropertyMessage(Unknown Source)
at org.apache.derby.impl.drda.NetworkServerControlImpl.blockingStart(Unknown Source)
... 6 more
Tue Nov 22 10:10:07 EST 2016 : Connection number: 1.
Tue Nov 22 10:10:08 EST 2016 : Connection number: 2.
----------------------------------------------------------------
Tue Nov 22 10:10:10 EST 2016:
Booting Derby version The Apache Software Foundation - Apache Derby - 10.12.1.1 - (1704137): instance a816c00e-0158-8c96-3a19-000062666399
on database directory /Users/dmclean/IdeaProjects/aoiJWSTbuild7/MyDbTest with class loader sun.misc.Launcher$AppClassLoader@6bc7c054
Loaded from file:/Users/dmclean/Library/java/db-derby-10.12.1.1-bin/lib/derby.jar
java.vendor=Oracle Corporation
java.runtime.version=1.8.0_112-b16
user.dir=/Users/dmclean/IdeaProjects/aoiJWSTbuild7
os.name=Mac OS X
os.arch=x86_64
os.version=10.11.6
derby.system.home=/Users/dmclean/IdeaProjects/aoiJWSTbuild7
Database Class Loader started - derby.database.classpath=''
Tue Nov 22 10:10:14 EST 2016 Thread[DRDAConnThread_2,5,main] (DATABASE = MyDbTest), (DRDAID = {2}), Apache Derby Network Server connected to database MyDbTest
Tue Nov 22 10:10:23 EST 2016 : Connection number: 3.
Tue Nov 22 10:10:23 EST 2016 Thread[DRDAConnThread_3,5,main] (DATABASE = MyDbTest), (DRDAID = {3}), Apache Derby Network Server connected to database MyDbTest
Tue Nov 22 10:10:24 EST 2016 : Connection number: 4.


On Tue, Nov 22, 2016 at 9:36 AM, Bryan Pendleton <[hidden email]> wrote:
On 11/21/2016 1:52 PM, Donald McLean wrote:
I'm trying to run a Derby in server mode. When I go to shut it down, I'm getting this weird error:

Mon Nov 21 16:19:44 EST 2016 : Invalid reply from network server: Insufficient data.

The command line arguments:

/usr/bin/java, -jar, /Users/dmclean/Library/java/db-derby-10.12.1.1-bin/lib/derbyrun.jar, server, shutdown

Does anyone have any suggestions as to what the problem would be and how to fix it?

Thank you,

Donald


I don't think I recall having seen that before. There are some old jobs
in the Derby issues database (e.g., DERBY-6337) that indicate that if the
Network Server is slow to respond, or slow to shut down, then the client
may print some odd messages.

Does this happen *every* time you shut down the Network Server?

What does the end of your derby.log file look like?

thanks,

bryan




--
Family photographs are a critical legacy for
ourselves and our descendants. Protect that
legacy with a digital backup and recovery plan.
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Unexplained problem

Bryan Pendleton-3
On 11/22/2016 7:14 AM, Donald McLean wrote:
> it can't bind to the port one minute and then get connections the next?
>

Perhaps you accidentally started two copies of the Network Server, in the
same directory and (trying to) listen on the same port.

Both servers are writing messages to the same derby.log file, but only one
of them is successfully accepting connections; the other one may have
tried to start, received the "can't bind" error, then quit?

Perhaps use the 'ps' command to have a close look at which 'java'
processes are running on your machine.

Or be more thorough: reboot your machine, then start the Network Server,
then check the ps command to make sure all is well, then shut it down,
and see if it's acting better now?

thanks,

bryan


Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Unexplained problem

Donald McLean-3
I'm starting the Derby server by spawning a process from a test (see below), so I can't imagine how two copies could be getting started in this way.

I monitored the test while it was running and found only three java processes running:

1. IDE
2. The test
3. The Derby server:
2530 84445 84438   0  9:08AM ??         0:27.71 /usr/bin/java -jar /Users/dmclean/Library/java/db-derby-10.12.1.1-bin/lib/derbyrun.jar server start

When my test spawns the "server shutdown", the "server start" process exits shortly afterward, except that it prints a message on its STDOUT:

Wed Nov 23 09:09:25 EST 2016 : Invalid reply from network server: Insufficient data

Something is definitely not working correctly and it would be really helpful if I could figure out what the problem is.
val p = new ProcessBuilder("/usr/bin/java", "-jar", "/Users/dmclean/Library/java/db-derby-10.12.1.1-bin/lib/derbyrun.jar", "server", command)
val commandArray = p.command().toArray()
val commandList = commandArray.toList
logger.trace("[runDBCommand] command is: {}", commandList)

val now = new Date()
val outputFile = new File("derby" + dateFormat.format(now) + ".out")
p.redirectOutput(outputFile)
p.redirectError(new File("derby" + dateFormat.format(now) + ".err"))

addEnvironmentVariables(p)
val result = p.start()


On Tue, Nov 22, 2016 at 10:22 AM, Bryan Pendleton <[hidden email]> wrote:
On 11/22/2016 7:14 AM, Donald McLean wrote:
it can't bind to the port one minute and then get connections the next?


Perhaps you accidentally started two copies of the Network Server, in the
same directory and (trying to) listen on the same port.

Both servers are writing messages to the same derby.log file, but only one
of them is successfully accepting connections; the other one may have
tried to start, received the "can't bind" error, then quit?

Perhaps use the 'ps' command to have a close look at which 'java'
processes are running on your machine.

Or be more thorough: reboot your machine, then start the Network Server,
then check the ps command to make sure all is well, then shut it down,
and see if it's acting better now?

thanks,

bryan





--
Family photographs are a critical legacy for
ourselves and our descendants. Protect that
legacy with a digital backup and recovery plan.
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Unexplained problem

Bryan Pendleton-3
> When my test spawns the "server shutdown", the "server start" process exits shortly afterward, except that it prints a message on its STDOUT:
>
> Wed Nov 23 09:09:25 EST 2016 : Invalid reply from network server: Insufficient data

The *"server start"* process is the one which has this behavior?

Thank you for clarifying that, I didn't understand that detail initially.

This feels almost identical to a similar problem in one of the Derby
regression test suites:

        https://issues.apache.org/jira/browse/DERBY-6337?focusedCommentId=13976483&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-13976483

Here's what Knut Anders suggested at the time:

        The "insufficient data" error indicates that the ping
        command was able to connect to the server, but didn't
        get a full response back from it. I suppose that it
        might happen if the server shutdown is completed after
        the ping command has connected to it and before the
        response has been sent back.

I think that, basically, the problem is that the Network Server is
multi-threaded and has some rather complex internal state, and the
simple atomic operation that we think of as "server shutdown" is
actually more complex, and so there can be a situation, where the server
shutdown interrupts/interferes with other server connections that are
still connected at the time.

I'm speculating that the "server start" part of your system has
retained some level of connection to the Derby Network Server, even
though the Network Server is already up-and-running.

Then, subsequently, the "server shutdown" request interrupts the
"server start" connection, not allowing it a chance to fully
send the network messages back to your client.

And so the code on the client sees a partial response from the
server, and tells you that fact.

Unfortunately, this doesn't look like a simple situation to improve.

 From what I can tell by studying DERBY-6337, the solution that
the developers chose at the time was to recognize in the test program
that this was a possible result, and to teach the test program to
allow for this awkward response from shutting the server down.

You could certainly log an enhancement request to try to make
this cleaner, although I think if there were an easy way to do
that, it would have been pursued during the DERBY-6337 research.

However, it's interesting to me that it's the "server start" part
of your test which receives this error.

That says to me that the mechanism you're using the *start* the
server is successfully starting the Network Server, but is also
retaining a network connection to the server, which doesn't seem
necessary to me.

If that startup technique were able to start the Network Server,
then "detach" from it, then when the server is subsequently shut
down, it wouldn't have any message to try to send back to that
startup connection (since the connection would no longer exist),
and so the partial message error would not arise.

Lots of speculation and hand-waving here, but perhaps it gives
you some more ideas about further diagnosis you can perform?

thanks,

bryan

Loading...