Behaviors of timeout is different for NodeJS actions and Java actions.

[rabbah]

@daisy-ycguo commented on Sat Nov 04 2017

Environment details:

I'm running a local openwhisk and testing nodejs actions and java actions which run more than 1 minutes. The timeout of these actions are set to 60000.

Steps to reproduce the issue:

1. Create nodejs action by wsk action create run2 action_fixedlen.js -i --param timeout 2. I find no errors after wsk action invoke run2 -i. The log shows the action is halted when it's actually not finished.
2. Create java action by wsk action create javarun1 action_fixedlen.jar --main FixedTime -i. I find an error java.io.IOException: Broken pipe in log while wsk action invoke javarun1 -i.

The source code of action_fixedlen.js and action_fixedlen.jar can refer here.

Provide the expected results and outputs:

I expected clear output if the action is halted because of timeout, not java.io.IOException: Broken pipe, not "no errors" in logs.

Provide the actual results and outputs:

java.io.IOException: Broken pipe because of java action is timeout

......
    "2017-11-04T15:50:23.267170396Z stdout: I’m busy",
    "2017-11-04T15:50:24.267475348Z stdout: I’m busy",
    "2017-11-04T15:50:25.19915025Z  stdout: time out!",
    "2017-11-04T15:50:25.279663546Z stderr: java.io.IOException: Broken pipe",
    "2017-11-04T15:50:25.279751044Z stderr: at sun.nio.ch.FileDispatcherImpl.write0(Native Method)",
    "2017-11-04T15:50:25.279884854Z stderr: at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)",
    "2017-11-04T15:50:25.279953363Z stderr: at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)",
    "2017-11-04T15:50:25.279989627Z stderr: at sun.nio.ch.IOUtil.write(IOUtil.java:65)",
    "2017-11-04T15:50:25.279997402Z stderr: at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471)",
    "2017-11-04T15:50:25.280038692Z stderr: at sun.net.httpserver.Request$WriteStream.write(Request.java:391)",
    "2017-11-04T15:50:25.280082249Z stderr: at sun.net.httpserver.FixedLengthOutputStream.write(FixedLengthOutputStream.java:78)",
    "2017-11-04T15:50:25.280131273Z stderr: at java.io.FilterOutputStream.write(FilterOutputStream.java:97)",
    "2017-11-04T15:50:25.280174979Z stderr: at sun.net.httpserver.PlaceholderOutputStream.write(ExchangeImpl.java:439)",
    "2017-11-04T15:50:25.280218671Z stderr: at openwhisk.java.action.Proxy.writeResponse(Proxy.java:60)",
    "2017-11-04T15:50:25.280226498Z stderr: at openwhisk.java.action.Proxy.access$400(Proxy.java:39)",
    "2017-11-04T15:50:25.280265324Z stderr: at openwhisk.java.action.Proxy$RunHandler.handle(Proxy.java:146)",
    "2017-11-04T15:50:25.280309312Z stderr: at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:79)",
    "2017-11-04T15:50:25.280354495Z stderr: at sun.net.httpserver.AuthFilter.doFilter(AuthFilter.java:83)",
    "2017-11-04T15:50:25.280396143Z stderr: at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:82)",
    "2017-11-04T15:50:25.281136929Z stderr: at sun.net.httpserver.ServerImpl$Exchange$LinkHandler.handle(ServerImpl.java:675)",
    "2017-11-04T15:50:25.281153061Z stderr: at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:79)",
    "2017-11-04T15:50:25.281157559Z stderr: at sun.net.httpserver.ServerImpl$Exchange.run(ServerImpl.java:647)",
    "2017-11-04T15:50:25.281161357Z stderr: at sun.net.httpserver.ServerImpl$DefaultExecutor.execute(ServerImpl.java:158)",
    "2017-11-04T15:50:25.281165196Z stderr: at sun.net.httpserver.ServerImpl$Dispatcher.handle(ServerImpl.java:431)",
    "2017-11-04T15:50:25.281189194Z stderr: at sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:396)",
    "2017-11-04T15:50:25.281195336Z stderr: at java.lang.Thread.run(Thread.java:748)"

No errors in log if a nodejs action is timeout.

Activation: run2 (08b49032e2144781b49032e214278111)
[
    "2017-11-04T16:18:59.38856493Z  stdout: timeout=2",
    "2017-11-04T16:18:59.388652855Z stdout: interval=10",
    "2017-11-04T16:19:02.402712303Z stdout: I'm busy.",
    "2017-11-04T16:19:03.408028403Z stdout: I'm busy.",
    .......
    "2017-11-04T16:19:26.438918288Z stdout: I'm busy.",
    "2017-11-04T16:19:27.443382697Z stdout: I'm busy.",
    "2017-11-04T16:19:28.444408797Z stdout: I'm busy.",
    ......
    "2017-11-04T16:20:02.521283865Z stdout: I'm busy.",
    "2017-11-04T16:20:03.523249329Z stdout: I'm busy."
]

---

@kevingrozav commented on Mon Nov 06 2017

I received a broken pipe error as well when trying to run the CLI installer (Mac amd64).

---

@daisy-ycguo commented on Tue Nov 07 2017

@kevingrozav Your error looks like nothing related with an action execution. Which command are you trying to run?

---

@kevingrozav commented on Tue Nov 07 2017

@daisy-ycguo I followed the instructions on the CLI readme for building the binary from src with Go, and it is working now. Sorry for the confusion.

---

@rabbah commented on Fri Nov 24 2017

I'm not able to reproduce this with the information provided in the description.