Re: Unexplained problem
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=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
Re: Unexplained problem
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 <
bpendleton.de...@gmail.com> 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.
Re: Unexplained problem
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-62666399
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 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.
Re: Unexplained problem
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
