Actions
Story #8460
closed[API] Port websocket service to Go
Added by Tom Clegg almost 9 years ago. Updated almost 8 years ago.
Start date:
12/13/2016
Due date:
% Done:
100%
Estimated time:
(Total: 0.00 h)
Story points:
0.5
Files
arvados-ws-internals.svg (569 KB) arvados-ws-internals.svg | Tom Clegg, 12/09/2016 03:42 PM |
Updated by Brett Smith almost 9 years ago
- Target version set to Arvados Future Sprints
Updated by Tom Clegg about 8 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"}
Updated by Tom Clegg about 8 years ago
- Target version changed from Arvados Future Sprints to 2016-12-14 sprint
Updated by Tom Clegg about 8 years ago
- File arvados-ws - internals.svg added
Updated by Tom Clegg about 8 years ago
- File deleted (
arvados-ws - internals.svg)
Updated by Tom Clegg about 8 years ago
- File arvados-ws-internals.svg arvados-ws-internals.svg added
Updated by Tom Clegg about 8 years ago
Updated by Tom Clegg about 8 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]}
Updated by Radhika Chippada about 8 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?
Updated by Tom Clegg about 8 years ago
- Target version changed from 2016-12-14 sprint to 2017-01-04 sprint
- Story points changed from 3.0 to 0.5
Updated by Tom Clegg almost 8 years ago
- Status changed from In Progress to Resolved
Actions