Story #8460

[API] Port websocket service to Go

Added by Tom Clegg over 5 years ago. Updated almost 5 years ago.

Status:
Resolved
Priority:
Normal
Assigned To:
Category:
-
Target version:
Start date:
12/13/2016
Due date:
% Done:

100%

Estimated time:
(Total: 0.00 h)
Story points:
0.5

arvados-ws-internals.svg (569 KB) arvados-ws-internals.svg Tom Clegg, 12/09/2016 03:42 PM

Subtasks

Task #10724: Help with dev/test deployResolvedTom Clegg

Task #10680: Review 8460-websocket-goResolvedTom Clegg


Related issues

Related to Arvados - Feature #10763: [arvbox] [arvados-ws] Make arvbox use the new arvados-wsResolved

Related to Arvados - Feature #10764: [arvados-ws] Write unit testsResolved02/27/2017

Related to Arvados - Feature #10765: [arvados-ws] switch our test infrastructure over to arvados-wsResolved

Related to Arvados - Feature #10766: [Docs] [arvados-ws] make the arvados-ws documentation official, remove all mentions of the old puma websockets setupResolved03/23/2017

Related to Arvados - Feature #10767: [API] [arvados-ws] remove all websockets and puma related code from the api server codebaseNew

Associated revisions

Revision 57170c25
Added by Tom Clegg almost 5 years ago

Merge branch '8460-websocket-go' refs #8460

History

#1 Updated by Brett Smith over 5 years ago

  • Target version set to Arvados Future Sprints

#2 Updated by Tom Clegg about 5 years ago

  • Description updated (diff)

#3 Updated by Tom Clegg almost 5 years ago

  • Status changed from New to In Progress

#4 Updated by Tom Clegg almost 5 years ago

  • Assigned To set to Tom Clegg

#5 Updated by Tom Clegg almost 5 years ago

Work in progress on 8460-websocket-go

#6 Updated by Tom Clegg almost 5 years ago

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"}

#8 Updated by Tom Clegg almost 5 years ago

  • Target version changed from Arvados Future Sprints to 2016-12-14 sprint

#10 Updated by Tom Clegg almost 5 years ago

  • File deleted (arvados-ws - internals.svg)

#13 Updated by Tom Clegg almost 5 years ago

Todo before merging as experimental:
  • 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]}
    

#14 Updated by Radhika Chippada almost 5 years ago

  • 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?

#15 Updated by Tom Clegg almost 5 years ago

  • Description updated (diff)

#16 Updated by Tom Clegg almost 5 years ago

  • Target version changed from 2016-12-14 sprint to 2017-01-04 sprint
  • Story points changed from 3.0 to 0.5

#17 Updated by Tom Clegg almost 5 years ago

  • Status changed from In Progress to Resolved

Also available in: Atom PDF