Arvados

Work in progress on 8460-websocket-go

Client:
  APIHost: 0.0.0.0:51388
  AuthToken: "" 
  Insecure: true
ClientEventQueue: 64
Listen: :8000
LogFormat: text
LogLevel: debug
PingTimeout: 1m0s
Postgres:
  connect_timeout: "30" 
  dbname: arvados_test
  host: localhost
  password: xyzzy
  sslmode: require
  user: arvados
ServerEventQueue: 4

ws = new WebSocket('ws://nelle:8000/websocket?api_token=1a9ffdcga2o7cw8q12dndskomgs1ygli3ns9k2o9hgzgmktc78')
ws.onopen=function(){
  ws.send('{}')
}
setTimeout(function(){
  ws.send('{"method":"subscribe","filters":[["event_type","in",["update","create","delete"]]]}')
}, 1500)
ws.onmessage=function(e){
  console.log(e)
}

if logging to a TTY, with LogFormat: text ...

DEBU[2016-11-17T16:06:33.659846828-05:00] pgEventSource listening
INFO[2016-11-17T16:06:33.659994473-05:00] listening                                     Listen=":8000" 
INFO[2016-11-17T16:06:37.775690691-05:00] accept request                                RemoteAddr="192.168.86.73:45789" RequestID=b8mxhiflv2d4 X-Forwarded-For=
INFO[2016-11-17T16:06:37.775838913-05:00] connected                                     RequestID=b8mxhiflv2d4
DEBU[2016-11-17T16:06:37.775869347-05:00] set token                                     RequestID=b8mxhiflv2d4 token=1a9ffdcga2o7cw8q12dndskomgs1ygli3ns9k2o9hgzgmktc78
DEBU[2016-11-17T16:06:37.778512953-05:00] received frame                                RequestID=b8mxhiflv2d4 frame="{}" 
INFO[2016-11-17T16:06:37.778561561-05:00] unknown method                                Method= RequestID=b8mxhiflv2d4
DEBU[2016-11-17T16:06:37.778604528-05:00] send event                                    RequestID=b8mxhiflv2d4 frame="{\"status\":400}" 
DEBU[2016-11-17T16:06:37.778651915-05:00] sent                                          RequestID=b8mxhiflv2d4
DEBU[2016-11-17T16:06:39.298544644-05:00] received frame                                RequestID=b8mxhiflv2d4 frame="{\"method\":\"subscribe\",\"filters\":[[\"event_type\",\"in\",[\"update\",\"create\",\"delete\"]]]}" 
DEBU[2016-11-17T16:06:39.298720852-05:00] sub prepared                                  RequestID=b8mxhiflv2d4 sub={subscribe [[event_type in [update create delete]]] 0 [0x40aaf0]}
DEBU[2016-11-17T16:06:39.298784674-05:00] send event                                    RequestID=b8mxhiflv2d4 frame="{\"status\":200}" 
DEBU[2016-11-17T16:06:39.298843663-05:00] sent                                          RequestID=b8mxhiflv2d4
DEBU[2016-11-17T16:06:43.858329467-05:00] received frame                                RequestID=b8mxhiflv2d4 frame=
INFO[2016-11-17T16:06:43.858393961-05:00] disconnect                                    Elapsed=6.082554805 RequestID=b8mxhiflv2d4 Stats={0s 102.682µs 28 2}
DEBU[2016-11-17T16:07:33.660456291-05:00] listener ping                                

...or, with LogFormat: json ...

{"level":"debug","msg":"pgEventSource listening","time":"2016-11-17T16:12:43.234492867-05:00"}
{"Listen":":8000","level":"info","msg":"listening","time":"2016-11-17T16:12:43.234654205-05:00"}
{"RemoteAddr":"192.168.86.73:46176","RequestID":"b8mxm8g5273q","X-Forwarded-For":"","level":"info","msg":"accept request","time":"2016-11-17T16:12:47.860942816-05:00"}
{"RequestID":"b8mxm8g5273q","level":"info","msg":"connected","time":"2016-11-17T16:12:47.861175235-05:00"}
{"RequestID":"b8mxm8g5273q","level":"debug","msg":"set token","time":"2016-11-17T16:12:47.861215803-05:00","token":"1a9ffdcga2o7cw8q12dndskomgs1ygli3ns9k2o9hgzgmktc78"}
{"RequestID":"b8mxm8g5273q","frame":"{}","level":"debug","msg":"received frame","time":"2016-11-17T16:12:47.869139838-05:00"}
{"Method":"","RequestID":"b8mxm8g5273q","level":"info","msg":"unknown method","time":"2016-11-17T16:12:47.869178132-05:00"}
{"RequestID":"b8mxm8g5273q","frame":"{\"status\":400}","level":"debug","msg":"send event","time":"2016-11-17T16:12:47.869237974-05:00"}
{"RequestID":"b8mxm8g5273q","level":"debug","msg":"sent","time":"2016-11-17T16:12:47.869313447-05:00"}
{"RequestID":"b8mxm8g5273q","frame":"{\"method\":\"subscribe\",\"filters\":[[\"event_type\",\"in\",[\"update\",\"create\",\"delete\"]]]}","level":"debug","msg":"received frame","time":"2016-11-17T16:12:49.156624103-05:00"}
{"RequestID":"b8mxm8g5273q","level":"debug","msg":"sub prepared","sub":{"Method":"subscribe","Filters":[["event_type","in",["update","create","delete"]]],"last_log_id":0},"time":"2016-11-17T16:12:49.156768416-05:00"}
{"RequestID":"b8mxm8g5273q","frame":"{\"status\":200}","level":"debug","msg":"send event","time":"2016-11-17T16:12:49.156901803-05:00"}
{"RequestID":"b8mxm8g5273q","level":"debug","msg":"sent","time":"2016-11-17T16:12:49.156974397-05:00"}
{"RequestID":"b8mxm8g5273q","frame":"","level":"debug","msg":"received frame","time":"2016-11-17T16:12:56.257250001-05:00"}
{"Elapsed":8.396140496,"RequestID":"b8mxm8g5273q","Stats":{"QueueDelayNs":0,"WriteDelayNs":132637,"EventBytes":28,"EventCount":2},"level":"info","msg":"disconnect","time":"2016-11-17T16:12:56.257315802-05:00"}

2a1978f10b7dff4f239eb868648f404f070fccc3

b9f0177e6a477a518fd5a89156fafde57f2dddf8

• Do not point websocket_address at the Nginx proxy in source:services/api/config/application.default.yml unless some "experimental" flag is set -- otherwise, Jenkins will do python/fuse/workbench integration tests with the experimental server, and we'll lose integration test coverage with the production (Rails) websocket server.
• Fix fuse tests. This happens consistently -- even turning X way up in "still alive X seconds after umount" doesn't seem to help.

• test_refresh_old_manifest (tests.test_token_expiry.TokenExpiryTest) ... [ws] {"RequestID":"b96wfzds71qi","level":"info","msg":"accept request","remoteAddr":"127.0.0.1:58532","reqForwardedFor":"127.0.0.1","time":"2016-12-11T03:30:55.965831950-05:00"}
  [ws] {"RequestID":"b96wfzds71qi","level":"info","msg":"connected","time":"2016-12-11T03:30:55.965957845-05:00"}
  [ws] {"RequestID":"b96wfzds71qi","elapsed":6.619906978,"level":"info","msg":"disconnect","stats":{"QueueDelayNs":34528216,"WriteDelayNs":724415,"EventBytes":8360,"EventCount":16},"time":"2016-12-11T03:31:02.585870741-05:00"}
  [nginx_access_log] 127.0.0.1 - - [11/Dec/2016:03:31:02 -0500] "GET /websocket?api_token=3kg6k6lzmp9kj5cpkcoxie963cmvjahbt2fod9zru30k1jqdmi HTTP/1.1" 101 0 "-" "-" 
  2017-03-25 04:34:18 arvados.arv-mount[19797] WARNING: Mount.__exit__: llfuse thread still alive 30.000000s after umount -- abandoning and exiting anyway
  WARNING:root:IntegrationTest.mount: llfuse thread still alive after umount -- killing test suite to avoid deadlock
  ./build/run-tests.sh: line 517: 19797 Killed                  "${3}python" setup.py ${short:+--short-tests-only} test ${testargs[$1]}
  

• Since it would be impossible to change later I ask: do we want to call “services/ws” as “services/wss” and “arvados-ws” as “arvados-wss” instead?

• In the wiki diagram, since there is one set of “yellow stuff” for each client, I think having multiple boxes for “goroutine: filter” and “client outgoing queue” is confusing. I think they can be just one each like all the other yellow boxes

• Can we add a link to this diagram to doc.go?

• Client.go => “unrecognized UUID infix:” Not sure if “infix” is self-explanatory. May be “unrecognized model type in UUID: %q”?

• Can we move the rfc3339NanoFixed definition into stats package or add a constants.go in sdk/go/arvados package?

• log.go => a lot of this file such as loggerConfig is repeated. Wondering if we can have a sdk/go/arvados/logger.rb instead?

• session_v0.go => “sess.log.WithField("sub", sub).Debug("sub prepared”)” => “subscription prepared” instead?

• What is going to be session_v1.go?

• Can you please add brief description for each goroutine in handler.go?

• It would be desirable that we have some tests here?