You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@openwhisk.apache.org by GitBox <gi...@apache.org> on 2019/01/15 08:51:58 UTC

[GitHub] jiangpengcheng opened a new issue #4218: [ContainerProxy] reading logs failed: spray.json.JsonParser happened occasionally

jiangpengcheng opened a new issue #4218: [ContainerProxy] reading logs failed: spray.json.JsonParser happened occasionally
URL: https://github.com/apache/incubator-openwhisk/issues/4218
 
 
   ## Environment details:
   
   * local deployment
   * the git head is at 57c5e9eae02f554adbca78b1fa2346fe1bd11b0c
   
   ## Steps to reproduce the issue:
   I'm not sure whether this issue is related to my environment or not, but I tend to believe it's not
   
   1. run a pressure test on openwhisk cluster   
   2. there will be some error logs
   
   
   ## Provide the actual results and outputs:
   
   error logs:
   ```
   [2019-01-15T08:31:20.957Z] [INFO] [#tid_a3da6a92ae0a74d2762165bb608cc0ee] [InvokerReactive]  [marker:invoker_activation_start:12]
   [2019-01-15T08:31:20.957Z] [INFO] [#tid_a3da6a92ae0a74d2762165bb608cc0ee] [WhiskAction] [GET] serving from cache: CacheKey(whisk.system/hello) [marker:database_cacheHit_count:12]
   [2019-01-15T08:31:20.957Z] [INFO] [#tid_a3da6a92ae0a74d2762165bb608cc0ee] [ContainerPool] containerStart containerState: warm (1 of max 3) action: hello namespace: whisk.system activationId: 068429e28d3144878429e28d319487c1 [marker:invoker_containerStart.warm_count:12]
   [2019-01-15T08:31:20.985Z] [INFO] [#tid_a3da6a92ae0a74d2762165bb608cc0ee] [DockerContainer] sending arguments to /whisk.system/hello at ContainerId(e759973fadfc585bc2149a83393a75562a1675cbdb8e052a3fdb7606bcc73f50) ContainerAddress(172.17.0.18,8080) [marker:invoker_activationRun_start:38]
   [2019-01-15T08:31:20.991Z] [INFO] [#tid_a3da6a92ae0a74d2762165bb608cc0ee] [DockerContainer] running result: ok [marker:invoker_activationRun_finish:45:7]
   [2019-01-15T08:31:20.991Z] [INFO] [#tid_a3da6a92ae0a74d2762165bb608cc0ee] [ContainerProxy]  [marker:invoker_collectLogs_start:45]
   [2019-01-15T08:31:20.991Z] [WARN] [#tid_a3da6a92ae0a74d2762165bb608cc0ee] [ContainerProxy] reading logs failed: spray.json.JsonParser$ParsingException: Unexpected character '}' at input index 0 (line 1, position 1), expected JSON Value:
   }
   ^
    [marker:invoker_collectLogs_error:46:1]
   [2019-01-15T08:31:20.991Z] [INFO] [#tid_a3da6a92ae0a74d2762165bb608cc0ee] [CouchDbRestStore] [PUT] 'lambda-bmt_activations' saving document: 'id: whisk.system/068429e28d3144878429e28d319487c1, rev: null' [marker:database_saveDocument_start:46]
   [2019-01-15T08:31:20.991Z] [INFO] [#tid_sid_invokerNanny] [DockerClientWithFileAccess] running /usr/bin/docker rm -f e759973fadfc585bc2149a83393a75562a1675cbdb8e052a3fdb7606bcc73f50 (timeout: 1 minute) [marker:invoker_docker.rm_start:2171081]
   [2019-01-15T08:31:20.993Z] [INFO] [#tid_a3da6a92ae0a74d2762165bb608cc0ee] [InvokerReactive] posted completion of activation 068429e28d3144878429e28d319487c1
   [2019-01-15T08:31:20.993Z] [INFO] [#tid_a3da6a92ae0a74d2762165bb608cc0ee] [InvokerReactive] posted completion of activation 068429e28d3144878429e28d319487c1
   [2019-01-15T08:31:21.009Z] [INFO] [#tid_a3da6a92ae0a74d2762165bb608cc0ee] [CouchDbRestStore]  [marker:database_saveDocument_finish:65:19]
   ```
   
   but the content of the container's log file seems good:
   
   ```
   e759973fadfc585bc2149a83393a75562a1675cbdb8e052a3fdb7606bcc73f50
   {"log":"XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX\n","stream":"stderr","time":"2019-01-15T08:31:20.939221646Z"}
   {"log":"XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX\n","stream":"stdout","time":"2019-01-15T08:31:20.939280794Z"}
   {"log":"XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX\n","stream":"stdout","time":"2019-01-15T08:31:20.948331713Z"}
   {"log":"XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX\n","stream":"stderr","time":"2019-01-15T08:31:20.948406585Z"}
   {"log":"XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX\n","stream":"stdout","time":"2019-01-15T08:31:20.951816597Z"}
   {"log":"XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX\n","stream":"stderr","time":"2019-01-15T08:31:20.952028823Z"}
   {"log":"XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX\n","stream":"stdout","time":"2019-01-15T08:31:20.955201709Z"}
   {"log":"XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX\n","stream":"stderr","time":"2019-01-15T08:31:20.955232142Z"}
   {"log":"XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX\n","stream":"stderr","time":"2019-01-15T08:31:20.955257815Z"}
   {"log":"XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX\n","stream":"stdout","time":"2019-01-15T08:31:20.955235214Z"}
   {"log":"XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX\n","stream":"stdout","time":"2019-01-15T08:31:20.96799271Z"}
   {"log":"XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX\n","stream":"stderr","time":"2019-01-15T08:31:20.967993254Z"}
   {"log":"XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX\n","stream":"stderr","time":"2019-01-15T08:31:20.97480418Z"}
   {"log":"XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX\n","stream":"stderr","time":"2019-01-15T08:31:20.974830507Z"}
   {"log":"XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX\n","stream":"stdout","time":"2019-01-15T08:31:20.974804579Z"}
   {"log":"XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX\n","stream":"stdout","time":"2019-01-15T08:31:20.974843273Z"}
   {"log":"XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX\n","stream":"stdout","time":"2019-01-15T08:31:20.978025611Z"}
   {"log":"XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX\n","stream":"stderr","time":"2019-01-15T08:31:20.978055679Z"}
   {"log":"XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX\n","stream":"stdout","time":"2019-01-15T08:31:20.984266238Z"}
   {"log":"XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX\n","stream":"stderr","time":"2019-01-15T08:31:20.984933416Z"}
   {"log":"XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX\n","stream":"stdout","time":"2019-01-15T08:31:20.987180686Z"}
   {"log":"XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX\n","stream":"stderr","time":"2019-01-15T08:31:20.98720477Z"}
   {"log":"XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX\n","stream":"stdout","time":"2019-01-15T08:31:20.989212639Z"}
   {"log":"XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX\n","stream":"stderr","time":"2019-01-15T08:31:20.989247137Z"}
   ```
   
   I got the log content with below script:
   
   ```bash
   id=`docker ps --no-trunc | grep hello | grep -v Paused | sed -n "1p" | awk '{print $1}'`
   echo $id
   
   sudo tailf /var/lib/docker/containers/$id/$id-json.log
   ```
   
   ## Additional information you deem important:
   * issue happens only occasionally
   

----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on GitHub and use the
URL above to go to the specific comment.
 
For queries about this service, please contact Infrastructure at:
users@infra.apache.org


With regards,
Apache Git Services