Stf: systemd service failing for websocket service

Created on 30 Sep 2019 · 15Comments · Source: openstf/stf

What is the issue or idea you have?
docker image for websocket microservice failing
Does it only happen on a specific device? Please run adb devices -l and paste the corresponding row.

Please provide the steps to reproduce the issue.
whenever i try to run websocket system service using docker image, I am getting below error
bin/stf websocket

Options:
-h, --help Show help. [boolean]
-V, --version Show version. [boolean]
--connect-push, -c App-side ZeroMQ PULL endpoint to connect to.
[array] [required]
--connect-sub, -u App-side ZeroMQ PUB endpoint to connect to.
[array] [required]
--port, -p The port to bind to. [number] [default: 7110]
--secret, -s The secret to use for auth JSON Web Tokens. Anyone who
knows this token can freely enter the system if they want,
so keep it safe. [string] [required]
--ssid, -i The name of the session ID cookie.
[string] [default: "ssid"]
--storage-url, -r URL to the storage unit. [string] [required]

Each option can be be overwritten with an environment variable by converting the
option to uppercase, replacing dashes with underscores and prefixing it with
STF_WEBSOCKET_ (e.g. STF_WEBSOCKET_STORAGE_URL).

Unexpected token ...

What is the expected behavior?
It systemd service should run normally for websocket service
Do you see errors or warnings in the stf local output? If so, please paste them or the full log here.

Please run stf doctor and paste the output here.

bug

Source

shridharkabbur

All 15 comments

Issue-Label Bot is automatically applying the label bug to this issue, with a confidence of 0.82. Please mark this comment with :thumbsup: or :thumbsdown: to give our bot feedback!

Links: app homepage, dashboard and code for this bot.

issue-label-bot[bot] on 30 Sep 2019

👍1

I always see that unexpected token ... in journalctl logs only for websocket service. Is anyone facing the same issue?
Please do the needful.
@thinkhy any thought on this..

shridharkabbur on 30 Sep 2019

👍1

this is the docker version I am using ..
Client: Docker Engine - Community
Version: 19.03.2
API version: 1.40
Go version: go1.12.8
Git commit: 6a30dfc
Built: Thu Aug 29 05:26:49 2019
OS/Arch: darwin/amd64
Experimental: false

Server: Docker Engine - Community
Engine:
Version: 19.03.2
API version: 1.40 (minimum version 1.12)
Go version: go1.12.8
Git commit: 6a30dfc
Built: Thu Aug 29 05:32:21 2019
OS/Arch: linux/amd64
Experimental: true
containerd:
Version: v1.2.6
GitCommit: 894b81a4b802e4eb2a91d1ce216b8817763c29fb
runc:
Version: 1.0.0-rc8
GitCommit: 425e105d5a03fabd737a126ad93d62a9eeede87f
docker-init:
Version: 0.18.0
GitCommit: fec3683

shridharkabbur on 1 Oct 2019

I can definitely confirm this unexpected behaviour.
There is a standalone Raspberry 4 box with latest CentOS for arm arch.

[root@localhost ~]# stf doctor
2019-10-04T07:03:00.207Z INF/cli:doctor 1121 [*] OS Arch: arm
2019-10-04T07:03:00.213Z INF/cli:doctor 1121 [*] OS Platform: linux
2019-10-04T07:03:00.215Z INF/cli:doctor 1121 [*] OS Platform: 4.19.72-v7l.1.el7
2019-10-04T07:03:00.216Z INF/cli:doctor 1121 [*] Using Node 6.17.1
2019-10-04T07:03:00.278Z INF/cli:doctor 1121 [*] Using ZeroMQ 4.1.4
2019-10-04T07:03:00.320Z INF/cli:doctor 1121 [*] Using RethinkDB 2.3.6
2019-10-04T07:03:00.322Z INF/cli:doctor 1121 [*] Using GraphicsMagick 1.3.32
2019-10-04T07:03:00.323Z INF/cli:doctor 1121 [*] Using ProtoBuf 3.10.0
2019-10-04T07:03:00.323Z INF/cli:doctor 1121 [*] Using ADB 1.0.31

Logs while running stf local

2019-10-04T07:00:06.401Z INF/app 982 [*] Using pre-built resources
2019-10-04T07:00:06.449Z INF/app 982 [*] Listening on port 7105
2019-10-04T07:00:06.458Z INF/db 982 [*] Connecting to 127.0.0.1:28015
/usr/lib/node_modules/stf/lib/cli websocket

Options:
  -h, --help          Show help.                                       [boolean]
  -V, --version       Show version.                                    [boolean]
  --connect-push, -c  App-side ZeroMQ PULL endpoint to connect to.
                                                              [array] [required]
  --connect-sub, -u   App-side ZeroMQ PUB endpoint to connect to.
                                                              [array] [required]
  --port, -p          The port to bind to.              [number] [default: 7110]
  --secret, -s        The secret to use for auth JSON Web Tokens. Anyone who
                      knows this token can freely enter the system if they want,
                      so keep it safe.                       [string] [required]
  --ssid, -i          The name of the session ID cookie.
                                                      [string] [default: "ssid"]
  --storage-url, -r   URL to the storage unit.               [string] [required]

Each option can be be overwritten with an environment variable by converting the
option to uppercase, replacing dashes with underscores and prefixing it with
`STF_WEBSOCKET_` (e.g. `STF_WEBSOCKET_STORAGE_URL`).

Unexpected token ...
2019-10-04T07:00:06.706Z FTL/cli:local 938 [*] Child process had an error ExitError: Exit code "1"
    at ChildProcess.<anonymous> (/usr/lib/node_modules/stf/lib/util/procutil.js:49:23)
    at emitTwo (events.js:106:13)
    at ChildProcess.emit (events.js:191:7)
    at Process.ChildProcess._handle.onexit (internal/child_process.js:219:12)
2019-10-04T07:00:06.707Z INF/cli:local 938 [*] Shutting down all child processes
2019-10-04T07:00:06.732Z INF/util:lifecycle 950 [app001] Winding down for graceful exit
2019-10-04T07:00:06.733Z INF/util:lifecycle 951 [dev001] Winding down for graceful exit
2019-10-04T07:00:06.743Z INF/util:lifecycle 957 [proc001] Winding down for graceful exit
2019-10-04T07:00:06.750Z INF/util:lifecycle 963 [proc002] Winding down for graceful exit
2019-10-04T07:00:06.750Z INF/util:lifecycle 964 [reaper001] Winding down for graceful exit
2019-10-04T07:00:06.759Z WRN/db 957 [proc001] Connection closed
2019-10-04T07:00:06.760Z INF/util:lifecycle 975 [*] Winding down for graceful exit
2019-10-04T07:00:06.767Z WRN/db 963 [proc002] Connection closed
2019-10-04T07:00:06.772Z WRN/db 964 [reaper001] Connection closed
2019-10-04T07:00:06.760Z INF/util:lifecycle 982 [*] Winding down for graceful exit
2019-10-04T07:00:06.761Z INF/util:lifecycle 981 [*] Winding down for graceful exit
2019-10-04T07:00:06.784Z INF/auth-mock 981 [*] Waiting for client connections to end
2019-10-04T07:00:06.799Z WRN/db 982 [*] Connection closed

p00h on 4 Oct 2019

root cause is please use socket.io exact version 2.2.0 in package.json ... it will work fine..
But didn't find time to explore why new version is creating issue...

shridharkabbur on 4 Oct 2019

@shridharkabbur gonna try it right now

p00h on 4 Oct 2019

Changing socket.io version to 2.2.0 changed nothing. Fresh install with given fix gave the same result as above.

p00h on 4 Oct 2019

socket.io 2.2.0 version worked for me.. Can you please check in node_modules/socket.io folder which version exists in package.json. please use exact version...

shridharkabbur on 4 Oct 2019

I also meet the same FAIL.
I Install the dependence and then use npm install -g stf.
running stf local. websocket run error
2019-10-07T07:08:45.656Z INF/util:procutil 30332 [] Forking "/usr/local/nodejs/node-v8.1.2-linux-x64/lib/node_modules/stf/lib/cli migrate"
2019-10-07T07:08:46.549Z INF/db 30338 [] Connecting to 127.0.0.1:28015
2019-10-07T07:08:46.942Z INF/db:setup 30338 [] Database "stf" already exists
2019-10-07T07:08:46.965Z INF/db:setup 30338 [] Table "users" already exists
2019-10-07T07:08:46.966Z INF/db:setup 30338 [] Table "accessTokens" already exists
2019-10-07T07:08:46.966Z INF/db:setup 30338 [] Table "vncauth" already exists
2019-10-07T07:08:46.966Z INF/db:setup 30338 [] Table "devices" already exists
2019-10-07T07:08:46.966Z INF/db:setup 30338 [] Table "logs" already exists
2019-10-07T07:08:47.059Z INF/db:setup 30338 [] Index "users"."adbKeys" already exists
2019-10-07T07:08:47.060Z INF/db:setup 30338 [] Waiting for index "users"."adbKeys"
2019-10-07T07:08:47.063Z INF/db:setup 30338 [] Index "accessTokens"."email" already exists
2019-10-07T07:08:47.064Z INF/db:setup 30338 [] Index "vncauth"."response" already exists
2019-10-07T07:08:47.064Z INF/db:setup 30338 [] Index "vncauth"."responsePerDevice" already exists
2019-10-07T07:08:47.064Z INF/db:setup 30338 [] Index "devices"."owner" already exists
2019-10-07T07:08:47.064Z INF/db:setup 30338 [] Index "devices"."present" already exists
2019-10-07T07:08:47.064Z INF/db:setup 30338 [] Index "devices"."providerChannel" already exists
2019-10-07T07:08:47.065Z INF/db:setup 30338 [] Waiting for index "accessTokens"."email"
2019-10-07T07:08:47.067Z INF/db:setup 30338 [] Waiting for index "vncauth"."response"
2019-10-07T07:08:47.069Z INF/db:setup 30338 [] Waiting for index "vncauth"."responsePerDevice"
2019-10-07T07:08:47.076Z INF/db:setup 30338 [] Waiting for index "devices"."owner"
2019-10-07T07:08:47.077Z INF/db:setup 30338 [] Waiting for index "devices"."present"
2019-10-07T07:08:47.080Z INF/db:setup 30338 [] Waiting for index "devices"."providerChannel"
2019-10-07T07:08:47.119Z INF/db:setup 30338 [] Index "users"."adbKeys" is ready
2019-10-07T07:08:47.132Z INF/db:setup 30338 [] Index "accessTokens"."email" is ready
2019-10-07T07:08:47.134Z INF/db:setup 30338 [] Index "vncauth"."response" is ready
2019-10-07T07:08:47.134Z INF/db:setup 30338 [] Index "vncauth"."responsePerDevice" is ready
2019-10-07T07:08:47.135Z INF/db:setup 30338 [] Index "devices"."owner" is ready
2019-10-07T07:08:47.135Z INF/db:setup 30338 [] Index "devices"."present" is ready
2019-10-07T07:08:47.140Z INF/db:setup 30338 [] Index "devices"."providerChannel" is ready
2019-10-07T07:08:47.151Z INF/util:procutil 30332 [] Forking "/usr/local/nodejs/node-v8.1.2-linux-x64/lib/node_modules/stf/lib/cli triproxy app001 --bind-pub tcp://127.0.0.1:7111 --bind-dealer tcp://127.0.0.1:7112 --bind-pull tcp://127.0.0.1:7113"
2019-10-07T07:08:47.160Z INF/util:procutil 30332 [] Forking "/usr/local/nodejs/node-v8.1.2-linux-x64/lib/node_modules/stf/lib/cli triproxy dev001 --bind-pub tcp://127.0.0.1:7114 --bind-dealer tcp://127.0.0.1:7115 --bind-pull tcp://127.0.0.1:7116"
2019-10-07T07:08:47.172Z INF/util:procutil 30332 [] Forking "/usr/local/nodejs/node-v8.1.2-linux-x64/lib/node_modules/stf/lib/cli processor proc001 --connect-app-dealer tcp://127.0.0.1:7112 --connect-dev-dealer tcp://127.0.0.1:7115"
2019-10-07T07:08:47.180Z INF/util:procutil 30332 [] Forking "/usr/local/nodejs/node-v8.1.2-linux-x64/lib/node_modules/stf/lib/cli processor proc002 --connect-app-dealer tcp://127.0.0.1:7112 --connect-dev-dealer tcp://127.0.0.1:7115"
2019-10-07T07:08:47.189Z INF/util:procutil 30332 [] Forking "/usr/local/nodejs/node-v8.1.2-linux-x64/lib/node_modules/stf/lib/cli reaper reaper001 --connect-push tcp://127.0.0.1:7116 --connect-sub tcp://127.0.0.1:7111"
2019-10-07T07:08:47.206Z INF/util:procutil 30332 [] Forking "/usr/local/nodejs/node-v8.1.2-linux-x64/lib/node_modules/stf/lib/cli provider --name isg-VirtualBox --min-port 7400 --max-port 7700 --connect-sub tcp://127.0.0.1:7114 --connect-push tcp://127.0.0.1:7116 --group-timeout 900 --public-ip localhost --storage-url http://localhost:7100/ --adb-host 127.0.0.1 --adb-port 5037 --vnc-initial-size 600x800 --mute-master never"
2019-10-07T07:08:47.236Z INF/util:procutil 30332 [] Forking "/usr/local/nodejs/node-v8.1.2-linux-x64/lib/node_modules/stf/lib/cli auth-mock --port 7120 --secret kute kittykat --app-url http://localhost:7100/"
2019-10-07T07:08:47.276Z INF/util:procutil 30332 [] Forking "/usr/local/nodejs/node-v8.1.2-linux-x64/lib/node_modules/stf/lib/cli app --port 7105 --secret kute kittykat --auth-url http://localhost:7100/auth/mock/ --websocket-url http://localhost:7110/"
2019-10-07T07:08:47.292Z INF/util:procutil 30332 [] Forking "/usr/local/nodejs/node-v8.1.2-linux-x64/lib/node_modules/stf/lib/cli api --port 7106 --secret kute kittykat --connect-push tcp://127.0.0.1:7113 --connect-sub tcp://127.0.0.1:7111"
2019-10-07T07:08:47.331Z INF/util:procutil 30332 [] Forking "/usr/local/nodejs/node-v8.1.2-linux-x64/lib/node_modules/stf/lib/cli websocket --port 7110 --secret kute kittykat --storage-url http://localhost:7100/ --connect-sub tcp://127.0.0.1:7111 --connect-push tcp://127.0.0.1:7113"
2019-10-07T07:08:47.385Z INF/util:procutil 30332 [] Forking "/usr/local/nodejs/node-v8.1.2-linux-x64/lib/node_modules/stf/lib/cli storage-temp --port 7102"
2019-10-07T07:08:47.416Z INF/util:procutil 30332 [] Forking "/usr/local/nodejs/node-v8.1.2-linux-x64/lib/node_modules/stf/lib/cli storage-plugin-image --port 7103 --storage-url http://localhost:7100/"
2019-10-07T07:08:47.474Z INF/util:procutil 30332 [] Forking "/usr/local/nodejs/node-v8.1.2-linux-x64/lib/node_modules/stf/lib/cli storage-plugin-apk --port 7104 --storage-url http://localhost:7100/"
2019-10-07T07:08:47.533Z INF/util:procutil 30332 [] Forking "/usr/local/nodejs/node-v8.1.2-linux-x64/lib/node_modules/stf/lib/cli poorxy --port 7100 --app-url http://localhost:7105/ --auth-url http://localhost:7120/ --api-url http://localhost:7106/ --websocket-url http://localhost:7110/ --storage-url http://localhost:7102/ --storage-plugin-image-url http://localhost:7103/ --storage-plugin-apk-url http://localhost:7104/"
2019-10-07T07:08:53.116Z INF/triproxy 30344 [app001] PUB socket bound on tcp://127.0.0.1:7111
2019-10-07T07:08:53.114Z INF/triproxy 30345 [dev001] PUB socket bound on tcp://127.0.0.1:7114
2019-10-07T07:08:53.136Z INF/triproxy 30345 [dev001] DEALER socket bound on tcp://127.0.0.1:7115
2019-10-07T07:08:53.136Z INF/triproxy 30344 [app001] DEALER socket bound on tcp://127.0.0.1:7112
2019-10-07T07:08:53.154Z INF/triproxy 30345 [dev001] PULL socket bound on tcp://127.0.0.1:7116
2019-10-07T07:08:53.154Z INF/triproxy 30344 [app001] PULL socket bound on tcp://127.0.0.1:7113
2019-10-07T07:08:55.121Z INF/db 30346 [] Connecting to 127.0.0.1:28015
2019-10-07T07:08:55.118Z INF/db 30351 [] Connecting to 127.0.0.1:28015
2019-10-07T07:08:55.145Z INF/reaper 30360 [reaper001] Subscribing to permanent channel "ALL"
2019-10-07T07:08:55.233Z INF/reaper 30360 [reaper001] Reaping devices with no heartbeat
2019-10-07T07:08:55.262Z INF/db 30360 [reaper001] Connecting to 127.0.0.1:28015
2019-10-07T07:08:55.351Z INF/reaper 30360 [reaper001] Receiving input from "tcp://127.0.0.1:7111"
2019-10-07T07:08:55.358Z INF/processor 30346 [proc001] App dealer connected to "tcp://127.0.0.1:7112"
2019-10-07T07:08:55.353Z INF/processor 30351 [proc002] App dealer connected to "tcp://127.0.0.1:7112"
2019-10-07T07:08:55.361Z INF/reaper 30360 [reaper001] Sending output to "tcp://127.0.0.1:7116"
2019-10-07T07:08:55.374Z INF/processor 30351 [proc002] Device dealer connected to "tcp://127.0.0.1:7115"
2019-10-07T07:08:55.375Z INF/processor 30346 [proc001] Device dealer connected to "tcp://127.0.0.1:7115"
2019-10-07T07:08:58.363Z INF/poorxy 30418 [] Listening on port 7100
2019-10-07T07:09:00.835Z INF/provider 30369 [] Subscribing to permanent channel "cuBuv7x/SiGXei1rnTgaKQ=="
2019-10-07T07:09:00.856Z INF/provider 30369 [] Sending output to "tcp://127.0.0.1:7116"
2019-10-07T07:09:00.858Z INF/provider 30369 [] Receiving input from "tcp://127.0.0.1:7114"
2019-10-07T07:09:01.087Z INF/provider 30369 [] Tracking devices
2019-10-07T07:09:04.421Z INF/auth-mock 30372 [] Listening on port 7120
2019-10-07T07:09:06.105Z INF/storage:temp 30401 [*] Listening on port 7102
../../lib/cli websocket

Unexpected token ...
2019-10-07T07:09:07.842Z FTL/cli:local 30332 [] Child process had an error ExitError: Exit code "1"
at ChildProcess. (/usr/local/nodejs/node-v8.1.2-linux-x64/lib/node_modules/stf/lib/util/procutil.js:49:23)
at emitTwo (events.js:125:13)
at ChildProcess.emit (events.js:213:7)
at Process.ChildProcess._handle.onexit (internal/child_process.js:197:12)
2019-10-07T07:09:07.842Z INF/cli:local 30332 [] Shutting down all child processes
2019-10-07T07:09:07.855Z INF/util:lifecycle 30344 [app001] Winding down for graceful exit
2019-10-07T07:09:07.868Z INF/util:lifecycle 30345 [dev001] Winding down for graceful exit
2019-10-07T07:09:07.883Z INF/util:lifecycle 30346 [proc001] Winding down for graceful exit
2019-10-07T07:09:07.889Z INF/util:lifecycle 30351 [proc002] Winding down for graceful exit
2019-10-07T07:09:07.901Z INF/util:lifecycle 30360 [reaper001] Winding down for graceful exit
2019-10-07T07:09:07.916Z INF/util:lifecycle 30369 [] Winding down for graceful exit
2019-10-07T07:09:07.932Z WRN/db 30346 [proc001] Connection closed
2019-10-07T07:09:07.936Z INF/util:lifecycle 30372 [] Winding down for graceful exit
2019-10-07T07:09:07.947Z INF/auth-mock 30372 [] Waiting for client connections to end
2019-10-07T07:09:07.936Z WRN/db 30351 [proc002] Connection closed
2019-10-07T07:09:07.937Z WRN/db 30360 [reaper001] Connection closed
2019-10-07T07:09:08.695Z INF/app 30379 [] Using pre-built resources
2019-10-07T07:09:08.732Z INF/app 30379 [] Listening on port 7105
2019-10-07T07:09:08.733Z INF/util:lifecycle 30379 [] Winding down for graceful exit
2019-10-07T07:09:08.735Z INF/db 30379 [*] Connecting to 127.0.0.1:28015

sssz on 7 Oct 2019

local/index.js run the websocket subprocess by using
stf websocket --port 7110 --secret "kute kittykat" --storage-url http://localhost:7100 --connect-sub tcp://127.0.0.1:7111 --connect-push tcp://127.0.0.1:7113.
If I input the command. the error is the same.
How to fix this? thanks

sssz on 7 Oct 2019

I had the same issue. It's probably related to the version of Node you're running. I fixed it by using 8.16.1. See #1102

entomber on 7 Oct 2019

对的，把版本换换成8.16.1是可以的。具体方法如下（要是没有nvm，可以使用这样的办法安装：
NVM（Node version manager）顾名思义，就是Node.js的版本管理软件
下载并安装NVM脚本
curl https://raw.githubusercontent.com/creationix/nvm/v0.13.1/install.sh | bash
source ~/.bash_profile
）
查看本地 nvm ls
查看所有node版本：nvm ls-remote
安装对应的版本：nvm install 版本(不要加v)
切换node的版本：nvm alias default 版本(不要加v)