Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Unable to process incoming event ‘ProgressComplete ’ (ProgressCompleteEvent) on Windows #882

Closed
wpfeiffe opened this issue Nov 17, 2016 · 29 comments · Fixed by #1155
Closed

Comments

@wpfeiffe
Copy link

Expected Behavior

When performing a largish build, a well formed build with no errors, will complete without erroring out

Current Behavior

On a large build, under windows 7, using Gradle 3.2, if the build is invoked from a command line, and the output is sufficiently long to scroll beyond the window buffer as specified in the Command properties in windows, Gradle will throw the following error when attempting to update the output:

“Unable to process incoming event ‘ProgressComplete ’ (ProgressCompleteEvent)”

Context

Using gradle 3.2, largish build output (we do an npm install as part of the script!), at a windows command prompt (in my case windows 7). Build fails to complete even through that are no actual build problems

Steps to Reproduce (for bugs)

See above

Your Environment

See above

@eriwen
Copy link
Contributor

eriwen commented Nov 18, 2016

@wpfeiffe This looks to be related to changes made in Gradle 2.13.

A few questions:

  • Can you tell us if this worked for you in Gradle 3.1 or 2.12?
  • Are you using Cygwin, Powershell, the Windows Command Prompt or something else?
  • Are you able to test this on Linux or macOS?

@wpfeiffe
Copy link
Author

We upgraded gradle from 2.11 to 3.2. The problem did not exist with 2.11.

We do have other developers running under different shells where this does
NOT happen. It seems to be isolated to a Windows command shell. Even
there, I have another box where it run under windows command shell to
completion with no errors. We can use the --console plain on the windows
machines that DO fail, and the build will succeed. Clearly points to how
the build is updating console output.

Our devops group runs the build under linux from jenkins without issue.

Is there a way for me to set the --console plain setting within the
build/wrapper env itself so the devs don't have to remember to do this?

Let me know if you have other questions on this.

Bill Pfeiffer

On Fri, Nov 18, 2016 at 11:36 AM, Eric Wendelin notifications@github.com
wrote:

@wpfeiffe https://github.com/wpfeiffe This looks to be related to
changes made in Gradle 2.13.

A few questions:

  • Can you tell us if this worked for you in Gradle 3.1 or 2.12?
  • Are you using Cygwin, Powershell, the Windows Command Prompt or
    something else?
  • Are you able to test this on Linux or macOS?


You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
#882 (comment), or mute
the thread
https://github.com/notifications/unsubscribe-auth/AAI6rbydxH5qDtOUJxnm55z16ftyNe8fks5q_dP2gaJpZM4K1wLB
.

@wpfeiffe
Copy link
Author

wpfeiffe commented Nov 21, 2016

Seeing the same behavior in a windows console running jhipster generated application using gradle. I ran "gradlew build" and this was the output:

FAILURE: Build failed with an exception.

  • What went wrong:
    Unable to process incoming event 'ProgressComplete ' (ProgressCompleteEvent)

Reran with --console plain and the task ran to completion with no errors.

@mrkam
Copy link

mrkam commented Dec 16, 2016

As I mentioned in https://issues.gradle.org/browse/GRADLE-3527, I've started getting this after I upgraded gradle version from 2.6 to 3.2

@BruceEckel
Copy link

BruceEckel commented Dec 19, 2016

I'm running Gradle 3.2.1 and Windows 10, and just started getting this message with a relatively new example.

It does seem to work OK with the --console plain gradle command line switch, and I would like to know how to set that through the gradle.properties file. (I have tried org.gradle.console=plain and systemProp.console=plain but it doesn't seem to do anything).

To reproduce, clone:
https://github.com/BruceEckel/OnJava8-Examples

Then run:
gradlew concurrent:run

When it breaks (it usually does) it happens on QuittingTasks, with the output:

FAILURE: Build failed with an exception.

* What went wrong:
Unable to process incoming event 'ProgressComplete ' (ProgressCompleteEvent)

But if you run QuittingTasks by itself with
gradlew QuittingTasks
it works.

If you run with
gradlew --console plain concurrent:run
it seems to always work, which is why I would like to know how to set console to plain inside the gradle.properties file as a stopgap.

Although parallel is turned on by default, this doesn't seem to make a difference one way or another. Neither does turning off the daemon. I have the Windows console buffer set to the largest size. The CI builds on both Appveyor and Travis-CI seem to work fine.

@madhead
Copy link
Contributor

madhead commented Dec 21, 2016

I am seeing this with Gradle 3.2.1 in Windows 10 + Git Bash when using gradle-node-plugin@1.0.1 on task npmInstall. --console plain helps but there is no way to put this option in Git. CMD works ok. There is no much output from npmInstall in my case: everything is already installed, I'm just forcing this task to run with npmInstall.outputs.upToDateWhen { false }. The output is:

:nodeSetup UP-TO-DATE
:npmSetup UP-TO-DATE
:npmInstall
npm WARN optional SKIPPING OPTIONAL DEPENDENCY: fsevents@^1.0.0 (node_modules\chokidar\node_modules\fsevents):
npm WARN notsup SKIPPING OPTIONAL DEPENDENCY: Unsupported platform for fsevents@1.0.15: wanted {"os":"darwin","arch":"any"} (current: {"os":"win32","arch":"x64"})
npm WARN release-dashboard@0.0.1-SNAPSHOT No description
npm WARN release-dashboard@0.0.1-SNAPSHOT No repository field.
npm WARN release-dashboard@0.0.1-SNAPSHOT No license field.

Node plugin config:

node {
	version = '6.9.2'
	npmVersion = '3.10.9'
	download = true
}

Not sure, maybe it prints some control characters that break Gradle.

@lacasseio lacasseio self-assigned this Dec 30, 2016
@lacasseio
Copy link
Contributor

lacasseio commented Dec 30, 2016

Here is my result regarding the additional debugging:

  • The issue is reproducible with sample lacasseio/issue-882 extracted from BruceEckel/OnJava8-Examples. You first need to execute gradlew groom, Ctrl-C when Shutdown appears in the console and then gradlew crash. The command gradlew groom represent gradlew :concurrent:DiningPhilosophers from BruceEckel/OnJava8-Examples and gradlew crash represent gradlew :concurrent:run -x :concurrent:DiningPhilosophers from BruceEckel/OnJava8-Examples. For some reason the task :concurrent:DiningPhilosophers would hang on my machine (hence the Ctrl-C) but seems to be triggering the crash.
  • The issue is only reproducible inside cmd.exe (couldn't reproduce under cygwin)
  • Starting a new cmd.exe prompt and running gradlew crash will not cause the crash. The grooming process need to be executed in order to cause the crash.
  • The crash worked on both the new Windows 10 console feature and the legacy pre-Windows 10 console.
  • The issue wouldn't reproduce under an integTest in Intellij
  • It seems somehow related to JavaExec task/implementation as most people seems to have reported that specific use case
  • Although the output says to use --stacktrace, --info or --debug for more information, --stacktrace will be ignored and --info/--debug will cause the failure to disappeared.
  • The sample was only tested under Windows 10 fully patched
  • More debugging is required to find out why the grooming is needed in order to cause the crash.

A possible explanation regarding changing-the-cmd-buffer-size fix is that Windows seems to be flushing some internal state which prevents the crash from happening. If the grooming scenario doesn't present itself again, the trigger won't cause the crash. Restarting the console may have the same behavior. There is a chance the issue is outside of Gradle's control, however, we should at least fail gracefully.

@BruceEckel
Copy link

BruceEckel commented Dec 30, 2016 via email

@kaidohallik
Copy link

I encountered similar issue with gradle node plugin. After adding

    doLast {
        println()
    }

to problematic tasks the problem was gone.

@lacasseio
Copy link
Contributor

@BruceEckel The important thing is we are able to reproduce with BruceEckel/OnJava8-Examples@920d169. I will keep looking at it to see why this is happening.

@kaidohallik and @wpfeiffe Could you tell me which version of Windows both of you are using?

@lacasseio
Copy link
Contributor

As a follow up on the debugging, here is the stacktrace of the exception that happen:

java.lang.IllegalStateException: Received complete event for an unknown operation (id: 9)
        at org.gradle.internal.logging.console.ProgressOperations.complete(ProgressOperations.java:51)
        at org.gradle.internal.logging.console.ConsoleBackedProgressRenderer.renderNow(ConsoleBackedProgressRenderer.java:109)
        at org.gradle.internal.logging.console.ConsoleBackedProgressRenderer.onOutput(ConsoleBackedProgressRenderer.java:67)
        at org.gradle.internal.logging.sink.OutputEventRenderer.restore(OutputEventRenderer.java:92)
        at org.gradle.internal.logging.services.DefaultLoggingManager$StartableLoggingRouter.stop(DefaultLoggingManager.java:269)
        at org.gradle.internal.logging.services.DefaultLoggingManager.stop(DefaultLoggingManager.java:94)
        at org.gradle.internal.logging.services.DefaultLoggingManager.stop(DefaultLoggingManager.java:37)
        at org.gradle.launcher.cli.CommandLineActionFactory$WithLogging.execute(CommandLineActionFactory.java:212)
        at org.gradle.launcher.cli.CommandLineActionFactory$WithLogging.execute(CommandLineActionFactory.java:174)
        at org.gradle.launcher.Main.doAction(Main.java:33)
        at org.gradle.launcher.bootstrap.EntryPoint.run(EntryPoint.java:45)
        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.gradle.launcher.bootstrap.ProcessBootstrap.runNoExit(ProcessBootstrap.java:60)
        at org.gradle.launcher.bootstrap.ProcessBootstrap.run(ProcessBootstrap.java:37)
        at org.gradle.launcher.GradleMain.main(GradleMain.java:23)

@kaidohallik
Copy link

@lacasseio My Windows version: Windows 7 Ultimate, Service Pack 1.

I encounter this problem while working with project generated with jhipster.
For example jhipster official test application: https://github.com/jhipster/jhipster-sample-app-gradle.git
Running requirements are in README.md file.
I can reproduce error by executing:

  1. open new cmd.exe
  2. set Screen Buffer Size Height = 99
  3. git clone https://github.com/jhipster/jhipster-sample-app-gradle.git
  4. cd jhipster-sample-app-gradle
  5. update gradle node plugin to version 1.0.1 in build.gradle (sample app is generated with jhipster current version 3.12.2, development version 4 of jhipster is already updated to 1.0.1)
  • replace
classpath "com.moowork.gradle:gradle-node-plugin:0.14"
classpath "com.moowork.gradle:gradle-gulp-plugin:0.13"

with

classpath "com.moowork.gradle:gradle-node-plugin:1.0.1"
  • add
apply plugin: 'com.moowork.node'
apply plugin: 'com.moowork.gulp'
  1. npm install
  2. problem occurs in executing:
  • with error (further executions can also hang, but first time gives error): gradlew -Pprod
  • with hanging: gradlew
    last output in console will be like that: [17:49:58] Finished 'ngconstant:dev' after 21 ms

Error occurs in 2 different form:

  1. sometimes it gives error:
FAILURE: Build failed with an exception.

* What went wrong:
Unable to process incoming event 'ProgressComplete ' (ProgressCompleteEvent)

* Try:
Run with --stacktrace option to get the stack trace. Run with --info or --debug option to get more log output.
  1. sometimes process just hangs

I can reproduce this problem always if I set Windows command line window Screen Buffer Size Height to 99.
At some point I get this error also with Screen Buffer Size Height = 999.
At some point I get this error even with maximum Screen Buffer Size Height 9999.
If error occurs with Buffer Height 999 then it occurs always.
If error occurs with Buffer Height 9999 then it occurs always.

Other information I gained.

Error never occurs if executing:

  • gradlew --info
  • gradlew --debug
  • gradlew --console plain

Sometimes that action can prevent error:

  • increase command line window Screen Buffer Size, for example to maximum possible value
  • open new command line window and use this new window for executing gradle tasks

Error never occurs in gulp tasks after putting this to build.gradle:

gulp {
	bufferOutput = true
}

Error never occurs in NodeTask (includes GulpTask) and NpmInstallTask (it means in this sample app error never occurs) after putting this to build.gradle:

tasks.withType(NodeTask) {
	doLast{
		println()
	}
}
tasks.withType(com.moowork.gradle.node.npm.NpmInstallTask) {
	doLast{
		println()
	}
}

@lacasseio
Copy link
Contributor

After more debugging on this issue, it doesn't seem to be needing the grooming part to cause the crash. The same code may succeed a couple time before failing. It is possible to see that the ProgressCompleteEvent is fired twice on the launcher by comparing the System.identityHashCode of both problematic events. The event is created once here:

    at org.gradle.internal.logging.events.ProgressCompleteEvent.<init>(ProgressCompleteEvent.java:37)
    at org.gradle.internal.logging.progress.DefaultProgressLoggerFactory$ProgressLoggerImpl.completed(DefaultProgressLoggerFactory.java:153)
    at org.gradle.internal.buildevents.TaskExecutionLogger.afterExecute(TaskExecutionLogger.java:61)
    at sun.reflect.GeneratedMethodAccessor7.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)
    at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
    at org.gradle.internal.event.DefaultListenerManager$ListenerDetails.dispatch(DefaultListenerManager.java:249)
    at org.gradle.internal.event.DefaultListenerManager$ListenerDetails.dispatch(DefaultListenerManager.java:229)
    at org.gradle.internal.event.AbstractBroadcastDispatch.dispatch(AbstractBroadcastDispatch.java:44)
    at org.gradle.internal.event.DefaultListenerManager$EventBroadcast$ListenerDispatch.dispatch(DefaultListenerManager.java:221)
    at org.gradle.internal.event.DefaultListenerManager$EventBroadcast$ListenerDispatch.dispatch(DefaultListenerManager.java:209)
    at org.gradle.internal.event.AbstractBroadcastDispatch.dispatch(AbstractBroadcastDispatch.java:44)
    at org.gradle.internal.event.BroadcastDispatch.dispatch(BroadcastDispatch.java:79)
    at org.gradle.internal.event.BroadcastDispatch.dispatch(BroadcastDispatch.java:30)
    at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:93)
    at com.sun.proxy.$Proxy61.afterExecute(Unknown Source)
    at org.gradle.execution.taskgraph.DefaultTaskGraphExecuter$EventFiringTaskWorker$1.execute(DefaultTaskGraphExecuter.java:237)
    at org.gradle.execution.taskgraph.DefaultTaskGraphExecuter$EventFiringTaskWorker$1.execute(DefaultTaskGraphExecuter.java:228)
    at org.gradle.internal.Transformers$4.transform(Transformers.java:169)
    at org.gradle.internal.progress.DefaultBuildOperationExecutor.run(DefaultBuildOperationExecutor.java:106)
    at org.gradle.internal.progress.DefaultBuildOperationExecutor.run(DefaultBuildOperationExecutor.java:61)
    at org.gradle.execution.taskgraph.DefaultTaskGraphExecuter$EventFiringTaskWorker.execute(DefaultTaskGraphExecuter.java:228)
    at org.gradle.execution.taskgraph.DefaultTaskGraphExecuter$EventFiringTaskWorker.execute(DefaultTaskGraphExecuter.java:215)
    at org.gradle.execution.taskgraph.AbstractTaskPlanExecutor$TaskExecutorWorker.processTask(AbstractTaskPlanExecutor.java:77)
    at org.gradle.execution.taskgraph.AbstractTaskPlanExecutor$TaskExecutorWorker.run(AbstractTaskPlanExecutor.java:58)
    at org.gradle.execution.taskgraph.DefaultTaskPlanExecutor.process(DefaultTaskPlanExecutor.java:32)
    at org.gradle.execution.taskgraph.DefaultTaskGraphExecuter.execute(DefaultTaskGraphExecuter.java:113)
    at org.gradle.execution.SelectedTaskExecutionAction.execute(SelectedTaskExecutionAction.java:37)
    at org.gradle.execution.DefaultBuildExecuter.execute(DefaultBuildExecuter.java:37)
    at org.gradle.execution.DefaultBuildExecuter.access$000(DefaultBuildExecuter.java:23)
    at org.gradle.execution.DefaultBuildExecuter$1.proceed(DefaultBuildExecuter.java:43)
    at org.gradle.execution.DryRunBuildExecutionAction.execute(DryRunBuildExecutionAction.java:32)
    at org.gradle.execution.DefaultBuildExecuter.execute(DefaultBuildExecuter.java:37)
    at org.gradle.execution.DefaultBuildExecuter.execute(DefaultBuildExecuter.java:30)
    at org.gradle.initialization.DefaultGradleLauncher$3.execute(DefaultGradleLauncher.java:196)
    at org.gradle.initialization.DefaultGradleLauncher$3.execute(DefaultGradleLauncher.java:193)
    at org.gradle.internal.Transformers$4.transform(Transformers.java:169)
    at org.gradle.internal.progress.DefaultBuildOperationExecutor.run(DefaultBuildOperationExecutor.java:106)
    at org.gradle.internal.progress.DefaultBuildOperationExecutor.run(DefaultBuildOperationExecutor.java:56)
    at org.gradle.initialization.DefaultGradleLauncher.doBuildStages(DefaultGradleLauncher.java:193)
    at org.gradle.initialization.DefaultGradleLauncher.doBuild(DefaultGradleLauncher.java:119)
    at org.gradle.initialization.DefaultGradleLauncher.run(DefaultGradleLauncher.java:102)
    at org.gradle.launcher.exec.GradleBuildController.run(GradleBuildController.java:71)
    at org.gradle.tooling.internal.provider.ExecuteBuildActionRunner.run(ExecuteBuildActionRunner.java:28)
    at org.gradle.launcher.exec.ChainingBuildActionRunner.run(ChainingBuildActionRunner.java:35)
    at org.gradle.launcher.exec.InProcessBuildActionExecuter.execute(InProcessBuildActionExecuter.java:41)
    at org.gradle.launcher.exec.InProcessBuildActionExecuter.execute(InProcessBuildActionExecuter.java:26)
    at org.gradle.tooling.internal.provider.ContinuousBuildActionExecuter.execute(ContinuousBuildActionExecuter.java:75)
    at org.gradle.tooling.internal.provider.ContinuousBuildActionExecuter.execute(ContinuousBuildActionExecuter.java:49)
    at org.gradle.tooling.internal.provider.ServicesSetupBuildActionExecuter.execute(ServicesSetupBuildActionExecuter.java:44)
    at org.gradle.tooling.internal.provider.ServicesSetupBuildActionExecuter.execute(ServicesSetupBuildActionExecuter.java:29)
    at org.gradle.launcher.daemon.server.exec.ExecuteBuild.doBuild(ExecuteBuild.java:67)
    at org.gradle.launcher.daemon.server.exec.BuildCommandOnly.execute(BuildCommandOnly.java:36)
    at org.gradle.launcher.daemon.server.api.DaemonCommandExecution.proceed(DaemonCommandExecution.java:120)
    at org.gradle.launcher.daemon.server.exec.WatchForDisconnection.execute(WatchForDisconnection.java:47)
    at org.gradle.launcher.daemon.server.api.DaemonCommandExecution.proceed(DaemonCommandExecution.java:120)
    at org.gradle.launcher.daemon.server.exec.ResetDeprecationLogger.execute(ResetDeprecationLogger.java:26)
    at org.gradle.launcher.daemon.server.api.DaemonCommandExecution.proceed(DaemonCommandExecution.java:120)
    at org.gradle.launcher.daemon.server.exec.RequestStopIfSingleUsedDaemon.execute(RequestStopIfSingleUsedDaemon.java:34)
    at org.gradle.launcher.daemon.server.api.DaemonCommandExecution.proceed(DaemonCommandExecution.java:120)
    at org.gradle.launcher.daemon.server.exec.ForwardClientInput$2.call(ForwardClientInput.java:74)
    at org.gradle.launcher.daemon.server.exec.ForwardClientInput$2.call(ForwardClientInput.java:72)
    at org.gradle.util.Swapper.swap(Swapper.java:38)
    at org.gradle.launcher.daemon.server.exec.ForwardClientInput.execute(ForwardClientInput.java:72)
    at org.gradle.launcher.daemon.server.api.DaemonCommandExecution.proceed(DaemonCommandExecution.java:120)
    at org.gradle.launcher.daemon.server.exec.LogAndCheckHealth.execute(LogAndCheckHealth.java:55)
    at org.gradle.launcher.daemon.server.api.DaemonCommandExecution.proceed(DaemonCommandExecution.java:120)
    at org.gradle.launcher.daemon.server.exec.LogToClient.doBuild(LogToClient.java:60)
    at org.gradle.launcher.daemon.server.exec.BuildCommandOnly.execute(BuildCommandOnly.java:36)
    at org.gradle.launcher.daemon.server.api.DaemonCommandExecution.proceed(DaemonCommandExecution.java:120)
    at org.gradle.launcher.daemon.server.exec.EstablishBuildEnvironment.doBuild(EstablishBuildEnvironment.java:72)
    at org.gradle.launcher.daemon.server.exec.BuildCommandOnly.execute(BuildCommandOnly.java:36)
    at org.gradle.launcher.daemon.server.api.DaemonCommandExecution.proceed(DaemonCommandExecution.java:120)
    at org.gradle.launcher.daemon.server.exec.StartBuildOrRespondWithBusy$1.run(StartBuildOrRespondWithBusy.java:50)
    at org.gradle.launcher.daemon.server.DaemonStateCoordinator$1.run(DaemonStateCoordinator.java:297)
    at org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:54)
    at org.gradle.internal.concurrent.StoppableExecutorImpl$1.run(StoppableExecutorImpl.java:40)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

When the event is deserialized on the launcher, it is done at the following location:

    at org.gradle.internal.logging.events.ProgressCompleteEvent.<init>(ProgressCompleteEvent.java:38)
    at org.gradle.internal.logging.serializer.ProgressCompleteEventSerializer.read(ProgressCompleteEventSerializer.java:46)
    at org.gradle.internal.logging.serializer.ProgressCompleteEventSerializer.read(ProgressCompleteEventSerializer.java:25)
    at org.gradle.internal.serialize.DefaultSerializerRegistry$TaggedTypeSerializer.read(DefaultSerializerRegistry.java:134)
    at org.gradle.launcher.daemon.protocol.DaemonMessageSerializer$OutputMessageSerializer.read(DaemonMessageSerializer.java:173)
    at org.gradle.launcher.daemon.protocol.DaemonMessageSerializer$OutputMessageSerializer.read(DaemonMessageSerializer.java:159)
    at org.gradle.internal.serialize.DefaultSerializerRegistry$TaggedTypeSerializer.read(DefaultSerializerRegistry.java:134)
    at org.gradle.internal.serialize.Serializers$StatefulSerializerAdapter$1.read(Serializers.java:36)
    at org.gradle.internal.remote.internal.inet.SocketConnection.receive(SocketConnection.java:78)
    at org.gradle.launcher.daemon.client.DaemonClientConnection.receive(DaemonClientConnection.java:75)
    at org.gradle.launcher.daemon.client.DaemonClientConnection.receive(DaemonClientConnection.java:35)
    at org.gradle.launcher.daemon.client.DaemonClient.monitorBuild(DaemonClient.java:199)
    at org.gradle.launcher.daemon.client.DaemonClient.executeBuild(DaemonClient.java:167)
    at org.gradle.launcher.daemon.client.DaemonClient.execute(DaemonClient.java:130)
    at org.gradle.launcher.daemon.client.DaemonClient.execute(DaemonClient.java:81)
    at org.gradle.launcher.cli.RunBuildAction.run(RunBuildAction.java:51)
    at org.gradle.internal.Actions$RunnableActionAdapter.execute(Actions.java:173)
    at org.gradle.launcher.cli.CommandLineActionFactory$ParseAndBuildAction.execute(CommandLineActionFactory.java:244)
    at org.gradle.launcher.cli.CommandLineActionFactory$ParseAndBuildAction.execute(CommandLineActionFactory.java:217)
    at org.gradle.launcher.cli.JavaRuntimeValidationAction.execute(JavaRuntimeValidationAction.java:33)
    at org.gradle.launcher.cli.JavaRuntimeValidationAction.execute(JavaRuntimeValidationAction.java:24)
    at org.gradle.launcher.cli.ExceptionReportingAction.execute(ExceptionReportingAction.java:33)
    at org.gradle.launcher.cli.ExceptionReportingAction.execute(ExceptionReportingAction.java:22)
    at org.gradle.launcher.cli.CommandLineActionFactory$WithLogging.execute(CommandLineActionFactory.java:210)
    at org.gradle.launcher.cli.CommandLineActionFactory$WithLogging.execute(CommandLineActionFactory.java:174)
    at org.gradle.launcher.Main.doAction(Main.java:33)
    at org.gradle.launcher.bootstrap.EntryPoint.run(EntryPoint.java:45)
    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.gradle.launcher.bootstrap.ProcessBootstrap.runNoExit(ProcessBootstrap.java:60)
    at org.gradle.launcher.bootstrap.ProcessBootstrap.run(ProcessBootstrap.java:37)
    at org.gradle.launcher.GradleMain.main(GradleMain.java:23)

As it was mentioned previously, the event is dispatched twice on the launcher but only created once. It seems to never happen on a cold daemon which raises suspicion on a possible resource leak regarding registered listener.

@lacasseio
Copy link
Contributor

lacasseio commented Jan 2, 2017

Further information was found on this issue. Something happen causing this code to not been reached (a runtime exception is thrown) causing the code to unwind and execute the finally clause here. This will end up dispatching the EndOutputEvent. This event will call ConsoleBackedProgressRenderer.renderNow which process the event from the queue a second time as the queue wasn't clear.

Some work was done to intercept the exception causing this issue:

org.gradle.api.UncheckedIOException: java.io.IOException: T h e   o p e r a t i o n   c o m p l e t e d   s u c c e s s f u l l y . 
 
                                                                                   
	at org.gradle.internal.logging.console.AnsiConsole.flush(AnsiConsole.java:57)
	at org.gradle.internal.logging.console.ConsoleBackedProgressRenderer.renderNow(ConsoleBackedProgressRenderer.java:146)
	at org.gradle.internal.logging.console.ConsoleBackedProgressRenderer.access$200(ConsoleBackedProgressRenderer.java:38)
	at org.gradle.internal.logging.console.ConsoleBackedProgressRenderer$1.run(ConsoleBackedProgressRenderer.java:94)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
Caused by: java.io.IOException: T h e   o p e r a t i o n   c o m p l e t e d   s u c c e s s f u l l y . 
 
                                                                                   
	at org.fusesource.jansi.WindowsAnsiOutputStream.applyCursorPosition(WindowsAnsiOutputStream.java:135)
	at org.fusesource.jansi.WindowsAnsiOutputStream.processCursorDown(WindowsAnsiOutputStream.java:217)
	at org.fusesource.jansi.AnsiOutputStream.processEscapeCommand(AnsiOutputStream.java:230)
	at org.fusesource.jansi.AnsiOutputStream.write(AnsiOutputStream.java:127)
	at java.io.FilterOutputStream.write(FilterOutputStream.java:125)
	at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
	at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
	at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:295)
	at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141)
	at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229)
	at org.gradle.internal.logging.console.AnsiConsole.flush(AnsiConsole.java:55)
	... 10 more

Note the output seems to be in Unicode with lots of null characters. At this point, it is not possible to know if it's related to the problem or simply the expected output. Edit: the exception message has nothing to do with the issue.

kaidohallik added a commit to kaidohallik/generator-jhipster that referenced this issue Jan 3, 2017
reverts jhipster#4683 and replaces with better solution for gulp
resolves error/hanging on executing npmInstall and yarn_install
my comment in open gradle issue: gradle/gradle#882 (comment)
@lacasseio
Copy link
Contributor

lacasseio commented Jan 3, 2017

The issue seems to be related to Jansi hence explains why using plain console is a valid workaround. Jansi tries to call SetConsoleCursorPosition here. For some reason (still unknown at this point edit: see this comment), the Win32 API returns zero (error value) but the GetLastError returns ERROR_SUCCESS with the message "The operation completed successfully". It must be related to the state of the state of the console window when SetConsoleCursorPosition is called. Assuming ReactOS's implementation of that function correctly represent the behavior of Microsoft's implementation, it would seem the MSDN documentation erronously reference to GetLastError for additional error information as the code doesn't do any call to SetLastError which would mean the success result returned by GetLastError comes from another Win32 API call that succeeds previously. It would also mean we would loose the underlying error code due to the used of NT_SUCCESS macro for success testing. Note that GetLastError is a Win32 API and the Nt* function use NTSTATUS return code only. Edit: it was confirm the last error is ERROR_INVALID_PARAMETER, see comments below.

The next debugging step would be to try and reproduce this failure using native code only and inspect the context in which is happen.

@lacasseio
Copy link
Contributor

It is important to note the issue is related to Jansi but doesn't mean the issue is inside Jansi. Gradle does its fair share of console cursor manipulation.

@wpfeiffe
Copy link
Author

wpfeiffe commented Jan 3, 2017 via email

@lacasseio
Copy link
Contributor

I think got to the bottom of this issue. Brace yourself as there are 2 sneaky issues in this scenario.

Let's start with the simple one. Although it's a neat idea to map all Win32 API in Java with a JNI generator and use that in the native implementation of the Jansi, not all Win32 API are created equal. The best example is GetLastError() mapped here as a simple JNI call. With careful reading of the MSDN documentation we can read the following:

[...] You should call the GetLastError function immediately when a function's return value indicates that such a call will return useful data. That is because some functions call SetLastError with a zero when they succeed, wiping out the error code set by the most recently failed function.

The Jansi code does try to grab the last error message immediately. However, what is neglected here is the overhead happening through JNI call. There is at least a heap allocation happening or another Win32 API call which causes the GetLastError() value to be lost. To correctly implement this function call, the generator project would need to create code that cache the GetLastError() after each Win32 API calls and the JNI version would simply retrieve the cached value. That been said, from my debugging inside a small native project, the actual GetLastError() value is most likely ERROR_INVALID_PARAMETER:

87 (0x57)
The parameter is incorrect.

This brings us to the second issue related to how Jansi process escapes code on Windows. The crash happens while processing a cursor down movement which is handled by WindowsAnsiOutputStream.processCursorDown. Let's play a game of pretending. Disclaimer, the value are all doubled checked in a custom native application. Let's assume that WindowsAnsiOutputStream.getConsoleInfo() called here return the following data structure. For the mapping between native structure and the Jansi, refer to the the Java binding of CONSOLE_SCREEN_BUFFER_INFO:

screen shot 2017-01-03 at 7 19 53 pm

Let's manually execute the next line of processCursorDown with count=1 (this is what was seen during debugging):

  • info.size.y == info.dwSize.Y == 9001
  • info.cursorPosition.y + count == info.dwCursorPosition.Y + count == 9000 + 1 == 9001
  • Math.min(9001, 9001) == 9001

This means info.cursorPosition.y will now equal to 9001. Next applyCursorPosition() will call SetConsoleCursorPostion with info. As you guessed it, the Win32 API call returns FALSE with the last error set to ERROR_INVALID_PARAMETER. In fact, trying to set the cursor position to info.dwSize.X will also fail in the same way. This means the cursor need to be restricted to info.dwSize.Y - 1 and info.dwSize.X - 1. The method processCursorRight doesn't expose the issue as it uses info.window.width(), a custom JNI bridge function that result in info.srWindow.Right - info.srWindow.Left which is never equals to info.dwSize.X.

The solution (not yet tested) to this last issue would be to replace processCursorDown with the following code:

    protected void processCursorDown(int count) throws IOException {
        getConsoleInfo();
        info.cursorPosition.y = (short) Math.min(Math.max(0, info.size.y - 1), info.cursorPosition.y + count);
        applyCursorPosition();
    }

@lacasseio
Copy link
Contributor

It is worth mentioning that for both discovered issues, there isn't any test written in the source project that could have helped avoid those issues.

@lacasseio
Copy link
Contributor

Since the exception happens when JAnsi process the ANSI Console string (at flush or, sometimes, at write), it's very hard to fix in Gradle. The previously proposed fixed was tried locally and worked as expected, meaning no crash happen. PR fusesource/jansi#70 was submitted on the JAnsi project to fix the problem.

@lacasseio
Copy link
Contributor

In order to avoid waiting for fusesouce, a fix was pushed in Gradle code base to workaround the issue. See PR #1155.

@stealthrabbi
Copy link

I had this issue with gradle 3.3. on windows + git bash. This will be resolved in 3.4?

@bmuschko
Copy link
Contributor

@stealthrabbi As indicated by the milestone the issue has been fixed with 3.4-RC1. You can either try out a RC build or wait for the final release of 3.4.

@khriskooper
Copy link

Can confirm that 3.4 fixed the issue for us. Thank you!

@lengerrong
Copy link

lengerrong commented Jan 23, 2018

Dear All,

Just close your shell window(cmd.exe or powershell.exe) and reopen a new one,
the issue will gone.

I found it works for me.

@chiragms
Copy link

Damn!! Wouldn't have guessed it in a million years.
Worked like a charm.
Thanks @lengerrong

@alainib
Copy link

alainib commented Mar 12, 2018

Thanks @lengerrong worked for me on windows 10 + powershell after 5 failed compilation

@cvvspb
Copy link

cvvspb commented Mar 13, 2018

Thanks, lengerrong, it worked!

@merbin2012
Copy link

Copy all your image files into projectFolder\android\app\src\main\assets here and try to build

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.