From dev-return-2777-archive-asf-public=cust-asf.ponee.io@openwhisk.apache.org Sun Oct 28 15:28:04 2018 Return-Path: X-Original-To: archive-asf-public@cust-asf.ponee.io Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by mx-eu-01.ponee.io (Postfix) with SMTP id 9A085180671 for ; Sun, 28 Oct 2018 15:28:03 +0100 (CET) Received: (qmail 29931 invoked by uid 500); 28 Oct 2018 14:28:02 -0000 Mailing-List: contact dev-help@openwhisk.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@openwhisk.apache.org Delivered-To: mailing list dev@openwhisk.apache.org Received: (qmail 29919 invoked by uid 99); 28 Oct 2018 14:28:01 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd2-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Sun, 28 Oct 2018 14:28:01 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd2-us-west.apache.org (ASF Mail Server at spamd2-us-west.apache.org) with ESMTP id 7B0FD1A56DE for ; Sun, 28 Oct 2018 14:28:01 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd2-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: 2.139 X-Spam-Level: ** X-Spam-Status: No, score=2.139 tagged_above=-999 required=6.31 tests=[DKIM_SIGNED=0.1, DKIM_VALID=-0.1, DKIM_VALID_AU=-0.1, FREEMAIL_ENVFROM_END_DIGIT=0.25, HTML_MESSAGE=2, RCVD_IN_DNSWL_NONE=-0.0001, SPF_PASS=-0.001, T_DKIMWL_WL_MED=-0.01] autolearn=disabled Authentication-Results: spamd2-us-west.apache.org (amavisd-new); dkim=pass (2048-bit key) header.d=gmail.com Received: from mx1-lw-us.apache.org ([10.40.0.8]) by localhost (spamd2-us-west.apache.org [10.40.0.9]) (amavisd-new, port 10024) with ESMTP id OLPsdxsT-MQv for ; Sun, 28 Oct 2018 14:27:59 +0000 (UTC) Received: from mail-ua1-f45.google.com (mail-ua1-f45.google.com [209.85.222.45]) by mx1-lw-us.apache.org (ASF Mail Server at mx1-lw-us.apache.org) with ESMTPS id 789BA5F4DB for ; Sun, 28 Oct 2018 14:27:59 +0000 (UTC) Received: by mail-ua1-f45.google.com with SMTP id c89so2043720uac.10 for ; Sun, 28 Oct 2018 07:27:59 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:references:in-reply-to:from:date:message-id:subject:to; bh=zQrHnG7NQs8U7fRw5YzdLR3HID7eTgrzR3TVozZQyrk=; b=kN9wMv+jOCQYWP34WlBRc2M1M+3CsfGTSPdj0u31eBYUwB6h8Mdo1RklA977cXeWkP 0AVw1EicYKsvfJq6mOZaE7nI01LrfS3AGwcQsTyXyCfQg0QJk91rxasTsqe3DprIh3eu M5AEKQViSA+171BtaAdozDfH1jCg3g1LzqNVOWkJqVPlvMj8R9kWpEXuRzzgZTzXEskv 5dEP7PhkkrUjcxnnf6lO1jlgNkMUslLpo4j9Qr1nK773XCGDoIGzOaE/mN/F7f1qwoz4 fjcAhe0SQRbDqano14gEOEc3Obz846fyfZSWPaMrEuJWgmkJ+Z6eOXMVbRUkXfdlq/sr xxbA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:references:in-reply-to:from:date :message-id:subject:to; bh=zQrHnG7NQs8U7fRw5YzdLR3HID7eTgrzR3TVozZQyrk=; b=TjIDeRKjZnCYex9/TZO1TQ9NuNzwtBVf2/F0vZQ8r8MI0m5Dq6Z+gGKvhpsM25JYuI v7+O+Q0DMD3qXoNN2FKmTbidKIIAFyRd/unwEMuL/8sZq2BYXrJo3Jf/6KntouMJX/Dj tWJ48TiwjTth3G9scm1lJYUk+ihRdfdJn/P5djVejdA9MOxz1/TLdzveifmSsgMEb0vS 7uTqPazY3JXIqSyG1MGBpoqp57ffSm41AvlFO9iFJ02IWCDH/4ItdbIWM1EwgkNlUWnp CPb032VEJfTVja2Z/bB87I7QX2vOYi1/HORIZNySoENkvoIOa0Hb2XkvhrRAjkUGXyMa GgzQ== X-Gm-Message-State: AGRZ1gJod+ruSTqChdgVeQDRB317UGniGDwt5cdNr9BTso2Ia/j76QO8 7z07Fe9w+vW13J2V9Z0PY3BENaMWQZVrLUgDaufJEQ== X-Google-Smtp-Source: AJdET5fjhScFomoc9W4ebLjeKzDGypWhhDi5GlatxXI552ADBz39tb16FKmNxRmOlk9T2m+upsr9x+mWrDryELDHZm4= X-Received: by 2002:a9f:28c4:: with SMTP id d62mr4444427uad.42.1540736873308; Sun, 28 Oct 2018 07:27:53 -0700 (PDT) MIME-Version: 1.0 References: <1540658218.924702.1556689000.006C27D5@webmail.messagingengine.com> <1540727239.2113700.1557221528.3BDFA0A4@webmail.messagingengine.com> <997DB07F-0655-47A3-BB1F-1B651AD6E473@gmail.com> <5CC38E53-1FC4-473B-9736-4A172667C7DC@gmail.com> In-Reply-To: <5CC38E53-1FC4-473B-9736-4A172667C7DC@gmail.com> From: Carlos Santana Date: Sun, 28 Oct 2018 10:27:42 -0400 Message-ID: Subject: Re: [long] I need help to find an issue with the Go runtime that I cannot track down To: dev@openwhisk.apache.org Content-Type: multipart/alternative; boundary="00000000000006a6de05794ac2ca" --00000000000006a6de05794ac2ca Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable We could add a test for every runtime in the core repo integration tests, similar way we have the tests for Unicode. On Sun, Oct 28, 2018 at 10:13 AM Carlos Santana wrote: > Great Michele +1 > > Rodric, > I was thinking the same, on how to catch this on the conformance unit > tests. > > I think running 2 invokes would catch this since the unit test framework > to do the docker run doesn=E2=80=99t do reuse. > > I think to reproduce needs to be done with a fast back to back invokes bu= t > using the same container. > > - Carlos Santana > @csantanapr > > > On Oct 28, 2018, at 8:32 AM, Rodric Rabbah wrote: > > > > I=E2=80=99m wondering why the =E2=80=9Cbasic=E2=80=9D runtime unit test= s didn=E2=80=99t catch the lack > of flush (this same symptom was observed during the dev of C# runtime and= I > thought the unit tests flagged it). Maybe we need a tighter tests with tw= o > invokes. > > > > -r > > > >> On Oct 28, 2018, at 7:47 AM, Michele Sciabarra > wrote: > >> > >> Ok I fixed it. > >> Please merge PR58 > >> > >> If someone could explain me why os.File.Sync() is not enough to flush > the stdout/stderr, and you need to wrap stdout/stderr in bufio.Writer and > Flush() it, I would be happy. > >> > >> -- > >> Michele Sciabarra > >> michele@sciabarra.com > >> > >> ----- Original message ----- > >> From: Carlos Santana > >> To: dev@openwhisk.apache.org > >> Subject: Re: [long] I need help to find an issue with the Go runtime > that I cannot track down > >> Date: Sat, 27 Oct 2018 14:38:18 -0400 > >> > >> Make sure both stdout and stderr are flushed before you return from th= e > >> http post on /run > >> > >> =E2=80=94 Carlos > >> On Sat, Oct 27, 2018 at 12:37 PM Michele Sciabarra < > michele@sciabarra.com> > >> wrote: > >> > >>> Developing with the Go runtime I wrote (yes I am eating my own dog > food!) > >>> I found an issue. Of course, I tried to track it but I cannot see the > >>> differences so I post here for help since I think it is related to th= e > way > >>> OpenWhisk interact with runtimes. > >>> > >>> The bug can be easily demonstrated with a very simple "echo" action: > >>> > >>> --- > >>> package main > >>> > >>> import ( > >>> "fmt" > >>> "log" > >>> ) > >>> > >>> // Main is... > >>> func Main(args map[string]interface{}) map[string]interface{} { > >>> log.Println(args["name"].(string)) > >>> fmt.Println(args["name"].(string)) > >>> return args > >>> } > >>> > >>> --- > >>> > >>> > >>> If I deploy and invoke it twice I get the wrong log for the > activations: > >>> > >>> $ wsk -i action invoke logbug.go -p name alpha -b | tail +2 | jq -r > >>> .activationId >go.id > >>> $ wsk -i activation logs $(cat go.id) > >>> 2018-10-27T16:18:15.62887961Z stdout: alpha > >>> $ wsk -i activation result $(cat go.id) > >>> { > >>> "name": "alpha" > >>> } > >>> $ wsk -i action invoke logbug.go -p name beta -b | tail +2 | jq -r > >>> .activationId >go.id > >>> $ wsk -i activation logs $(cat go.id) > >>> 2018-10-27T16:18:15.634172847Z stderr: 2018/10/27 16:18:15 alpha > >>> $ wsk -i activation result $(cat go.id) > >>> { > >>> "name": "beta" > >>> } > >>> > >>> As you can see the output is associated to the wrong action, the > stderr of > >>> the first action is taken from the second action. > >>> > >>> For comparison, I tried with an equivalent javascript action: > >>> > >>> ---- > >>> function main(args) { > >>> console.log(args.name) > >>> console.error(args.name) > >>> return args > >>> } > >>> ---- > >>> > >>> This one works properly: > >>> > >>> $ wsk -i action invoke logbug.js -p name alpha -b | tail +2 | jq -r > >>> .activationId >js.id > >>> $ wsk -i activation logs $(cat js.id) > >>> 2018-10-27T16:25:37.089015311Z stdout: alpha > >>> 2018-10-27T16:25:37.08909633Z stderr: alpha > >>> $ wsk -i activation result $(cat js.id) > >>> { > >>> "name": "alpha" > >>> } > >>> $ wsk -i action invoke logbug.js -p name beta -b | tail +2 | jq -r > >>> .activationId >js.id > >>> $ wsk -i activation logs $(cat js.id) > >>> 2018-10-27T16:25:37.446571251Z stderr: beta > >>> 2018-10-27T16:25:37.446598483Z stdout: beta > >>> $ wsk -i activation result $(cat js.id) > >>> { > >>> "name": "beta" > >>> } > >>> > >>> I tried to track the bug launching the runtime locally and looking fo= r > >>> differences in the output but unfortunately, it looks identical! > >>> > >>> Example with JS: > >>> > >>> $ docker run -p 8080:8080 openwhisk/nodejs6action >js_out 2>js_err & > >>> $ invoke init logbug.js > >>> {"OK":true} > >>> $ invoke run '{"name":"Mike"}' > >>> {"name":"Mike"} > >>> $ invoke run '{"name":"Miri"}' > >>> {"name":"Miri"} > >>> > >>> Output: > >>> > >>> $ cat js_out > >>> Mike > >>> XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX > >>> Miri > >>> XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX > >>> > >>> $ cat js_err > >>> Mike > >>> XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX > >>> Miri > >>> XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX > >>> > >>> Example with GO > >>> > >>> $ docker run -p 8080:8080 openwhisk/actionloop-golang-v1.11 >go_out > >>> 2>go_err & > >>> $ invoke init logbug.go > >>> {"ok":true} > >>> > >>> $ invoke run '{"name":"Mike"}' > >>> {"name":"Mike"} > >>> > >>> $ invoke run '{"name":"Miri"}' > >>> {"name":"Miri"} > >>> > >>> Output: > >>> > >>> $ cat go_out > >>> Mike > >>> XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX > >>> Miri > >>> XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX > >>> > >>> $ cat go_err > >>> cat go_err > >>> 2018/10/27 16:32:47 Mike > >>> XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX > >>> 2018/10/27 16:32:48 Miri > >>> XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX > >>> > >>> I do not see any difference in output, so I guess the problem is > related > >>> to something else, like timing or similar issues. > >>> > >>> Any hint? > >>> > >>> > >>> -- > >>> Michele Sciabarra > >>> michele@sciabarra.com > >>> > --00000000000006a6de05794ac2ca--