Displaying #maven-dev/2017-02-20.log:

Mon Feb 20 05:34:11 2017  mbenson:Joined the channel
Mon Feb 20 06:17:37 2017  mbenson:Joined the channel
Mon Feb 20 06:17:37 2017  mbenson:Joined the channel
Mon Feb 20 07:38:32 2017  Michael-O:Joined the channel
Mon Feb 20 08:17:58 2017  tibor_:Joined the channel
Mon Feb 20 08:34:30 2017  olamy:Joined the channel
Mon Feb 20 09:58:33 2017  olamy:Joined the channel
Mon Feb 20 11:49:53 2017  Michael-O:Joined the channel
Mon Feb 20 11:50:35 2017  Michael-O:tibor_: just read you mail. If I understood you correctly: you exect the forked process to start immediately and not to hang right?
Mon Feb 20 11:51:37 2017  Michael-O:so you basically need an ACK for the forked VM that it is up and running. If it does not happen without a timeout, you cann kill it.
Mon Feb 20 12:09:21 2017  Michael-O:tibor_: the hang could be these issues: http://stackoverflow.com/q/13008526/696632 and http://bjurr.com/runtime-exec-hangs-a-complete-solution/
Mon Feb 20 12:09:39 2017  tibor_:Michael-O: the forked process itself does not hang.
Mon Feb 20 12:09:52 2017  Michael-O:the forker hangs?
Mon Feb 20 12:10:01 2017  tibor_:Nut the execute() method in java.lang.Runtime
Mon Feb 20 12:10:55 2017  tibor_:execute() method should return java.lang.Process object imediatelly. And we can call waitFor() on Process.
Mon Feb 20 12:11:19 2017  tibor_:execute() lasts as long as the process lasts
Mon Feb 20 12:11:33 2017  tibor_:I think bug in JRE
Mon Feb 20 12:12:02 2017  Michael-O:I tried both Java 7 and 8
Mon Feb 20 12:12:07 2017  tibor_:I know
Mon Feb 20 12:12:47 2017  tibor_:We can confirm bug if we wronte a test console application, and start some process via shell.
Mon Feb 20 12:12:56 2017  tibor_:and print time before, after
Mon Feb 20 12:13:02 2017  Michael-O:Can you do that since you know best?
Mon Feb 20 12:13:05 2017  Michael-O:I will run that
Mon Feb 20 12:13:21 2017  tibor_:pls, send me the command to run
Mon Feb 20 12:13:56 2017  tibor_:it can be some application, notepad, or so, some which needs to last ling time
Mon Feb 20 12:13:57 2017  Michael-O:I am sorry which exactly do you mean?
Mon Feb 20 12:14:20 2017  Michael-O:why not invoke a shell script with a sleep?
Mon Feb 20 12:14:51 2017  tibor_:I am not good in these commands
Mon Feb 20 12:16:11 2017  tibor_:would be like this? /bin/sh -c sleep(10)
Mon Feb 20 12:16:36 2017  tibor_:or /bin/sh -c sleep 10 ?
Mon Feb 20 12:17:02 2017  Michael-O:yes, but quote: "sleep 10"
Mon Feb 20 12:20:59 2017  tibor_:ok
Mon Feb 20 12:24:59 2017  tibor_:Michael-O: Hanging of p.waitFor(); is expected. But hanging execute() I don't think so; otherwise the method waitFor would not make sense.
Mon Feb 20 12:26:41 2017  Michael-O:Right, exec should return immediately
Mon Feb 20 12:31:38 2017  tibor_:http://www.javaworld.com/article/2071275/core-java/when-runtime-exec---won-t.html
Mon Feb 20 12:31:46 2017  tibor_:Thus, to circumvent the second pitfall -- hanging forever in Runtime.exec() -- if the program you launch produces output or expects input, ensure that you process the input and output streams.
Mon Feb 20 12:35:37 2017  Michael-O:Found this too. It sounds reasonble.
Mon Feb 20 12:35:45 2017  Michael-O:The forked process is starving..
Mon Feb 20 12:45:41 2017  Michael-O:This is really good: I guess the issue is that you are only reading InputStream and not reading ErrorStream. You also have to take care that both the streams are read in parallel. It may so happen that currently the data piped from the output stream fills up the OS buffer, your exec command will be automatically be suspended to give your reader a chance to empty the buffer. But the program will still be waiting for the output to
Mon Feb 20 12:51:39 2017  tibor_:Michael-O: But we are reading both out and err via Utils. And then we consume the err in new NativeStdErrStreamConsumer( forkClient.getDefaultReporterFactory() ).
Mon Feb 20 12:52:03 2017  tibor_:See ForkStarter Line 618 and 615
Mon Feb 20 12:52:45 2017  tibor_:Utils starts a thread for each out and err.
Mon Feb 20 12:53:54 2017  tibor_:I think this is complicated and socket pipes will be used for unix
Mon Feb 20 12:55:48 2017  Michael-O:If we really consume both then I have currently no idea. We really need an isolated usecase, if some I could post to it Stackoverflow and the FreeBSD mailing list.
Mon Feb 20 13:05:57 2017  tibor_:In the evening I will write the test application to confirm exec() hangs.
Mon Feb 20 13:10:20 2017  Michael-O:OK, thank you. If this is the case, we can document this as long as we don't have a clean solution.
Mon Feb 20 14:31:13 2017  tibor_:Michael-O: I will send you an isolated usecase today evening.
Mon Feb 20 14:47:09 2017  tibor_:Joined the channel
Mon Feb 20 17:22:00 2017  rfscholte:Joined the channel
Mon Feb 20 18:20:28 2017  Michael-O_:Joined the channel
Mon Feb 20 18:59:06 2017  rfscholte:Joined the channel
Mon Feb 20 19:01:44 2017  tibor_:Joined the channel
Mon Feb 20 19:03:18 2017  tibor_:Michael-O: Hi Michael. I've got home. I will prepare git repo for you and we can confirm bug in Java, Runtime.exec()
Mon Feb 20 19:07:11 2017  Michael-O_:Yet, take your time. I will eat dinner first!
Mon Feb 20 19:07:14 2017  Michael-O_:Yes*
Mon Feb 20 19:19:16 2017  Michael-O_:Joined the channel
Mon Feb 20 20:16:45 2017  Michael-O_:tibor_: I'll be back in 30 min. I am nw even testing on HP-UX 11.31 with Java 7. We'll see how our code behaves.
Mon Feb 20 20:52:34 2017  Michael-O:Joined the channel
Mon Feb 20 20:54:46 2017  tibor_:Michael-O: This is the project. https://github.com/Tibor17/freebsd-issue
Mon Feb 20 20:57:00 2017  Michael-O:Got it. Give me a couple of minutes.
Mon Feb 20 21:08:54 2017  Michael-O:tibor_: this is weird, I tried the code on three completely different operating systems: RHEL 6, FreeBSD 10.3, HP-UX 11.31. In no case the waitFor() had any effect. Did it work for you?
Mon Feb 20 21:09:45 2017  tibor_:I use Windows and waitFor always worked for me
Mon Feb 20 21:10:02 2017  tibor_:how the exec behaves?
Mon Feb 20 21:10:55 2017  tibor_:In Win destroy() does not work.
Mon Feb 20 21:11:27 2017  Michael-O:[mosipov@bsd10 ~/Projekte/freebsd-issue]$ java -jar target/exec-1.0.jar
Mon Feb 20 21:11:28 2017  Michael-O:This Java application starts sleep sub-process waiting 3 seconds.
Mon Feb 20 21:11:30 2017  Michael-O:1487624667328 millis Before forking sub-process.
Mon Feb 20 21:11:31 2017  Michael-O:1487624667452 millis After Runtime.exec() method has returned.
Mon Feb 20 21:11:33 2017  Michael-O:1487624667453 millis After sub-process completed.
Mon Feb 20 21:11:34 2017  Michael-O:As is waitFor has no effect
Mon Feb 20 21:11:37 2017  Michael-O:same on Linux here
Mon Feb 20 21:12:39 2017  Michael-O:I will try something else, give me a minute
Mon Feb 20 21:16:46 2017  Michael-O:I have it, the problem is the runtime#exec
Mon Feb 20 21:16:49 2017  Michael-O:it does not work
Mon Feb 20 21:17:21 2017  tibor_:Utils wait for waitFor method and I/O to return -1 from InputStream.read()
Mon Feb 20 21:17:55 2017  Michael-O:Look at this:
Mon Feb 20 21:17:57 2017  Michael-O:[mosipov@bsd10 ~/Projekte/freebsd-issue]$ java -jar target/exec-1.0.jar
Mon Feb 20 21:17:59 2017  Michael-O:This Java application starts sleep sub-process waiting 3 seconds.
Mon Feb 20 21:18:00 2017  Michael-O:1487625455657 millis Before forking sub-process.
Mon Feb 20 21:18:02 2017  Michael-O:1487625455778 millis After Runtime.exec() method has returned.
Mon Feb 20 21:18:03 2017  Michael-O:1487625465800 millis After sub-process completed.
Mon Feb 20 21:18:05 2017  Michael-O:sleep 10 is added
Mon Feb 20 21:18:09 2017  Michael-O:here is the patch
Mon Feb 20 21:18:50 2017  Michael-O:http://pastebin.com/icBw8HXh
Mon Feb 20 21:19:05 2017  Michael-O:The ProcessBuilder does the trick
Mon Feb 20 21:19:36 2017  tibor_:possibly yes
Mon Feb 20 21:19:51 2017  Michael-O:I will retry on HP-UX and RHEL 6
Mon Feb 20 21:20:14 2017  Michael-O:Runtime#exec() is discouraged according to Javadoc
Mon Feb 20 21:20:22 2017  tibor_:but my experience on FreeBSD the exec() took 20 sec. Is Java subprocess somehow special?
Mon Feb 20 21:21:25 2017  tibor_:In this test project the exec was fast, right?
Mon Feb 20 21:21:56 2017  Michael-O:yes, your original code exits immediately. waitFor has no effect
Mon Feb 20 21:22:53 2017  Michael-O:awesome, the ProcessBuilder works on all three platforms!
Mon Feb 20 21:23:02 2017  Michael-O:10 second wait passes
Mon Feb 20 21:23:31 2017  tibor_:hm
Mon Feb 20 21:23:57 2017  Michael-O:note: I could raise an issue with HPE for Java on HP-UX, but they will likely tell me to use the ProcessBuilder
Mon Feb 20 21:24:12 2017  Michael-O:This basically means that we have to stop using exec()
Mon Feb 20 21:24:43 2017  tibor_:yes but reworking Utils would be complicated
Mon Feb 20 21:24:52 2017  tibor_:we dont have InputStream
Mon Feb 20 21:25:03 2017  tibor_:and OutputStream or do we?
Mon Feb 20 21:26:14 2017  tibor_:how is it going with HPE?
Mon Feb 20 21:26:25 2017  tibor_:this code and yours
Mon Feb 20 21:26:37 2017  Michael-O:ProcessBuilder gives you the same Process back. No real change, I guess.
Mon Feb 20 21:26:55 2017  Michael-O:With HPE: they repackage Oracle's VM for HP-UX and provide support for.
Mon Feb 20 21:26:59 2017  Michael-O:It is bascially Oracle
Mon Feb 20 21:27:13 2017  Michael-O:but with HPE's native fixes for HP-UX
Mon Feb 20 21:27:24 2017  Michael-O:it even has Oracle's internal classes
Mon Feb 20 21:27:34 2017  Michael-O:This is not like IBM's JVM
Mon Feb 20 21:29:16 2017  Michael-O:this is likely our problem: process = Runtime.getRuntime().exec( getShellCommandline(), environment, workingDir );
Mon Feb 20 21:29:43 2017  tibor_:what's wrong wih this line?
Mon Feb 20 21:29:43 2017  Michael-O:https://docs.oracle.com/javase/7/docs/api/java/lang/Process.html
Mon Feb 20 21:29:49 2017  Michael-O:it uses exec
Mon Feb 20 21:30:03 2017  Michael-O:if we turn this into ProcessBuilder, it should work, based on our findings
Mon Feb 20 21:32:02 2017  tibor_:we should handle content of target/surefire and run the command like this and check how exec() behaves
Mon Feb 20 21:32:13 2017  tibor_:because here it returns fast
Mon Feb 20 21:32:24 2017  tibor_:with native process
Mon Feb 20 21:32:49 2017  tibor_:or will we rework 0.9.x?
Mon Feb 20 21:34:07 2017  Michael-O:Does Surefire do any exec() or does it rely on Utils?
Mon Feb 20 21:34:19 2017  tibor_:uses Utils
Mon Feb 20 21:34:36 2017  tibor_:no internal exec()
Mon Feb 20 21:35:46 2017  Michael-O:The nice thing about ProcessBuilder, it seems to do any type of escaping for you. I will leave decision to you. I cannot tell which approach is better. I'd like to see the tests fork with ProcessBuilder. If this does work on 4 Unix-like OSes and Windows, we have won.
Mon Feb 20 21:39:03 2017  tibor_:Look, I can replace Runtime with ProcessBuilder. If you have better code, I am all the ear.
Mon Feb 20 21:39:37 2017  tibor_:do you want to commit
Mon Feb 20 21:40:47 2017  tibor_:Michael-O: ?
Mon Feb 20 21:40:58 2017  Michael-O:No, go ahead. The ProcessBuilder have slightly different semantics. Utils manually assembles the command line while ProcessBuilder does not require that. You can simply pass the list of args.
Mon Feb 20 21:41:11 2017  Michael-O:Commit to freeebsd-issue?
Mon Feb 20 21:41:31 2017  tibor_:Utils and Surefire branch
Mon Feb 20 21:42:34 2017  tibor_:We should maybe log thelifecycle of exec() method, and start() in new code.
Mon Feb 20 21:44:21 2017  Michael-O:Please go ahead and commit. You know Surefire better than I do.
Mon Feb 20 21:44:31 2017  Michael-O:Can you tell where Commandline.java is used in Surefire?
Mon Feb 20 21:45:30 2017  tibor_:ForkStarter L619
Mon Feb 20 21:49:24 2017  Michael-O:Got it. At first glance, it should suffice to change Commandline.java
Mon Feb 20 21:55:39 2017  tibor_:Utils is done.
Mon Feb 20 21:56:09 2017  tibor_:Can you please check the change and install and rebuild one IT?
Mon Feb 20 21:57:08 2017  Michael-O:Yes, just a minute
Mon Feb 20 22:01:56 2017  Michael-O:running tests
Mon Feb 20 22:11:34 2017  Michael-O:Done. Looks a bit different, but still "PING timer: plugin did not set me NOOP singal > exit"
Mon Feb 20 22:11:44 2017  Michael-O:I think we should focus on this first
Mon Feb 20 22:12:03 2017  Michael-O:You said yesterday that some thread does not come up. Right?
Mon Feb 20 22:14:12 2017  tibor_:right
Mon Feb 20 22:15:06 2017  Michael-O:Where is this thread started?
Mon Feb 20 22:17:48 2017  tibor_:TestProvidingInputStream in Plugin process
Mon Feb 20 22:17:52 2017  tibor_:and
Mon Feb 20 22:17:59 2017  tibor_:CommandReader in forked jvm
Mon Feb 20 22:20:41 2017  Michael-O:ForkedBooter isn
Mon Feb 20 22:20:44 2017  Michael-O:Isn
Mon Feb 20 22:20:45 2017  Michael-O:isn
Mon Feb 20 22:20:51 2017  Michael-O:isn't the issue, right?
Mon Feb 20 22:20:56 2017  Michael-O:this works as designed?
Mon Feb 20 22:22:02 2017  tibor_:no
Mon Feb 20 22:22:24 2017  tibor_:it is not issue. only consequence of another issue.
Mon Feb 20 22:22:46 2017  Michael-O:Who forks the thread for TestProvidingInputStream?
Mon Feb 20 22:22:59 2017  tibor_:Utils
Mon Feb 20 22:23:00 2017  Michael-O:I'd like to take a look at it at work tomorrow with jstack
Mon Feb 20 22:23:35 2017  tibor_:I am thinking..
Mon Feb 20 22:24:23 2017  tibor_:Utils has two Threads. 1. for reading from InputStream, 2. for writing to OutputStream
Mon Feb 20 22:24:36 2017  tibor_:after reading from Utils
Mon Feb 20 22:25:01 2017  tibor_:the data goes to ThreadedStreamConsumer
Mon Feb 20 22:25:15 2017  tibor_:then String command goes to ForkClient
Mon Feb 20 22:25:17 2017  Michael-O:and the producer does not talk to the forked VM
Mon Feb 20 22:25:36 2017  tibor_:producer of what?
Mon Feb 20 22:26:05 2017  Michael-O:plugin > fork (NOOP signal)
Mon Feb 20 22:26:22 2017  tibor_:This is another flow control
Mon Feb 20 22:26:36 2017  tibor_:NOOP is in ForkStarter
Mon Feb 20 22:27:03 2017  tibor_:There is a thread I think which sends cacheable or immediate command of NOOP
Mon Feb 20 22:27:41 2017  tibor_:see TestProvidingInputStream public void noop()
Mon Feb 20 22:29:33 2017  Michael-O:Yes, I see. This method must be called to satisfy the forked VM?
Mon Feb 20 22:30:42 2017  tibor_:It is called to indicate to fork that Maven build is alife. No segmentation fault crach of Maven.
Mon Feb 20 22:30:54 2017  tibor_:alive
Mon Feb 20 22:31:03 2017  tibor_:I have this log you sent me:
Mon Feb 20 22:31:13 2017  tibor_:1487579970885 ForkStarter NOOP sent in a loop
Mon Feb 20 22:31:21 2017  tibor_:TestProvidingInputStream#23586785 :: setFlushReceiverProvider() :: /bin/sh -c
Mon Feb 20 22:31:27 2017  tibor_:1487579980888 ForkStarter NOOP sent in a loop
Mon Feb 20 22:31:33 2017  tibor_:1487579990885 ForkStarter NOOP sent in a loop
Mon Feb 20 22:31:37 2017  tibor_:OutputStreamFlushableCommandline#21022243 :: execute() :: flushReceiver is set!!!
Mon Feb 20 22:31:43 2017  tibor_:TestProvidingInputStream#27025542 :: tryFlush() :: flushReceiver.flush();
Mon Feb 20 22:32:05 2017  tibor_:TestProvidingInputStream#23586785 :: close()
Mon Feb 20 22:32:42 2017  tibor_:This indicates the exec() took 20 seconds to complete
Mon Feb 20 22:33:21 2017  Michael-O:Yes, yes. Maybe TestProvidingInputStream hangs somewhere.
Mon Feb 20 22:33:34 2017  Michael-O:You don't know the name of the missing thread, do you?
Mon Feb 20 22:33:52 2017  tibor_:let me see
Mon Feb 20 22:35:10 2017  tibor_:CommandReader was first suspicion "surefire-forkedjvm-command-thread"
Mon Feb 20 22:35:46 2017  tibor_:and then some Thread started by Utils
Mon Feb 20 22:35:56 2017  tibor_:not sure if they have name
Mon Feb 20 22:37:18 2017  tibor_:StreamPumper is the class which extends Thread
Mon Feb 20 22:37:24 2017  tibor_:in Utils
Mon Feb 20 22:38:45 2017  tibor_:I can log the start() method lifetime. If we exclude this suspicion we can focus on another.
Mon Feb 20 22:39:44 2017  Michael-O:start of the thread?
Mon Feb 20 22:42:41 2017  tibor_:start of process
Mon Feb 20 22:44:08 2017  tibor_:According to the logs above the command awaitNextTest() was received and semaphore was waken up, but the forked JVM never received any class to test
Mon Feb 20 22:44:46 2017  Michael-O:Do you think that we could add TeeStreams to write the comm exchanged between VMs to files to analyze it better?
Mon Feb 20 22:44:57 2017  Michael-O:without manipulating stdio?
Mon Feb 20 22:44:58 2017  tibor_:[INFO] Tests run: 0, Failures: 0, Errors: 0, Skipped: 0
Mon Feb 20 22:45:59 2017  tibor_:plugin -> fork is easy
Mon Feb 20 22:46:09 2017  tibor_:ForkClient -> CommandReader
Mon Feb 20 22:47:09 2017  tibor_:I think we send it to std/out already but you know it is still the same stream
Mon Feb 20 22:48:21 2017  tibor_:Do you want to log these two classes on file system?
Mon Feb 20 22:49:50 2017  Michael-O:Yes, unbuffered, directly to disk.
Mon Feb 20 22:51:56 2017  Michael-O:I will compare the output on RHEL and FreeBSD and will try to find the difference.
Mon Feb 20 22:54:07 2017  Michael-O:I am off. See you tomorrow. I am still certain that this is our fault and not OS's one. The tests on HP-UX weren't reliable too. Will upload tomorrow.
Mon Feb 20 22:56:39 2017  olamy:Joined the channel
Mon Feb 20 23:10:55 2017  hboutemy:Joined the channel

Comments