Closed nunoguedelha closed 1 year ago
nunoguedelha
commented
2 years ago @S-Dafarra reported that:
yarprobotinterface process logging through yarplogger and WalkingModule process logging through yarplogger.We shall test together tomorrow with some prints in the code for further analysis.
nunoguedelha
commented
1 year ago I could finally reproduce the issue on my setup by chance. Analysing...
nunoguedelha
commented
1 year ago When the issue occurs, we get the following error on the console twice, for the unsubscribe and for the subscribe events:
WebSocket is already in CLOSING or CLOSED state.The websocket used to subscribe to the telemetry relatime server crashed/closed for some reason unknown to me. Refreshing the client visualizer page restores the websocket. As a workaround, I'll add a warning in the console or on the browser for notifying the user and suggesting to refresh the page.
Ping @S-Dafarra .
nunoguedelha
commented
1 year ago Ciao @S-Dafarra , could you run a test on your side just to check if the issue is still present after re-installing yarp-openmct from scratch?
S-Dafarra
commented
1 year ago Yes, the robot is currently under maintenance, but it should be back shortly. I will pull main and check
S-Dafarra
commented
1 year ago Unfortunately, it seems to be still occurring.
I launch the WalkingModule with
YARP_LOG_PROCESS_LABEL=WalkingModule YARP_FORWARD_LOG_ENABLE=1 WalkingModulethen I need to refresh the page (so far so good). Then, I keep sending prepareRobot via RPC to generate an error, but the list of errors is updated only after clinking on another entry. Interestingly, I see the same effect also in the IMU Overlay plot (which, by the way, has only the roll entry repeated three times)
If it can be helpful, here the screen recording with the terminal
nunoguedelha
commented
1 year ago Thanks @S-Dafarra , indeed it seems to be an issue with the realtime updates and the "subscribe" mechanism. Every time you click on the entry, there is an immediate update with the already buffered values, then no further updates.
From that point on, if you refresh the page, does it restore the plot flow (at least for some time until next failure) or do you see the plot curve freezed?
S-Dafarra
commented
1 year ago When refreshing, it hangs without displaying anything
nunoguedelha
commented
1 year ago Ciao @S-Dafarra , I guess you are on commit fbd69b24de04b631ad86016161c69d6414c830fd, right? was this an install from scratch?
S-Dafarra
commented
1 year ago Ciao @S-Dafarra , I guess you are on commit fbd69b2, right?
Yes, you can see the panels on the right.
was this an install from scratch?
I used npm clean-install
nunoguedelha
commented
1 year ago For your info...
Here's how the IMU Overlay in the saved panels is rendered: https://user-images.githubusercontent.com/6848872/207684992-fa96e125-d7b1-44f0-93a2-2ad0bfde1966.mp4
More particularly:
$ npm ls | grep yarp.js
└─┬ YarpJS@1.5.0 (git+https://github.com/robotology/yarp.js.git#08c9c2cd6b6957f45ffb58779bc998252d7c5269)
$ npm ls | grep openmct
yarp-openmct@1.0.0 /Users/nunoguedelha/dev/yarp-openmct-test-2
├── openmct@1.7.8 (git+https://github.com/ami-iit/openmct.git#3e76cbb9aa2620a4660a03639ee0463cade3343f)Although the openmct tag appears to be 1.7.8, the commit actually matches the tag 1.7.8-iit, which is the expected one.
S-Dafarra
commented
1 year ago I guess that there are some issues on the robot laptop side.
Here the npm ls output
``` icub@icub-console-xps:/usr/local/src/robot/yarp-openmct$ npm ls yarp-openmct@1.0.0 /usr/local/src/robot/yarp-openmct ├── UNMET DEPENDENCY express@latest ├─┬ express-ws@4.0.0 │ └─┬ ws@5.2.3 │ └── async-limiter@1.0.1 ├── UNMET DEPENDENCY jquery@latest ├── UNMET DEPENDENCY openmct@git+https://github.com/ami-iit/openmct.git#7e67bdba9ff7d6c4a98fa952ce484b3d0f474584 ├─┬ socket.io@1.5.1 │ ├─┬ debug@2.2.0 │ │ └── ms@0.7.1 │ ├─┬ engine.io@1.7.2 │ │ ├─┬ accepts@1.3.3 │ │ │ ├── mime-types@2.1.34 deduped │ │ │ └── negotiator@0.6.1 │ │ ├── base64id@0.1.0 │ │ ├─┬ debug@2.2.0 │ │ │ └── ms@0.7.1 │ │ ├─┬ engine.io-parser@1.3.1 │ │ │ ├── after@0.8.1 │ │ │ ├── arraybuffer.slice@0.0.6 │ │ │ ├── base64-arraybuffer@0.1.5 │ │ │ ├── blob@0.0.4 │ │ │ ├─┬ has-binary@0.1.6 │ │ │ │ └── isarray@0.0.1 deduped │ │ │ └── wtf-8@1.0.0 │ │ └─┬ ws@1.1.1 │ │ ├── options@0.0.6 │ │ └── ultron@1.0.2 │ ├─┬ has-binary@0.1.7 │ │ └── isarray@0.0.1 │ ├─┬ socket.io-adapter@0.4.0 │ │ ├─┬ debug@2.2.0 │ │ │ └── ms@0.7.1 │ │ └─┬ socket.io-parser@2.2.2 │ │ ├── benchmark@1.0.0 │ │ ├── component-emitter@1.1.2 deduped │ │ ├── debug@0.7.4 │ │ ├── isarray@0.0.1 deduped │ │ └── json3@3.2.6 │ ├─┬ socket.io-client@1.5.1 │ │ ├── backo2@1.0.2 │ │ ├── component-bind@1.0.0 deduped │ │ ├── component-emitter@1.2.0 │ │ ├─┬ debug@2.2.0 │ │ │ └── ms@0.7.1 │ │ ├─┬ engine.io-client@1.7.2 │ │ │ ├── component-emitter@1.1.2 deduped │ │ │ ├── component-inherit@0.0.3 │ │ │ ├─┬ debug@2.2.0 │ │ │ │ └── ms@0.7.1 │ │ │ ├── engine.io-parser@1.3.1 deduped │ │ │ ├── has-cors@1.1.0 │ │ │ ├── indexof@0.0.1 deduped │ │ │ ├─┬ parsejson@0.0.1 │ │ │ │ └── better-assert@1.0.2 deduped │ │ │ ├─┬ parseqs@0.0.2 │ │ │ │ └── better-assert@1.0.2 deduped │ │ │ ├── parseuri@0.0.4 deduped │ │ │ ├─┬ ws@1.1.1 │ │ │ │ ├── options@0.0.6 deduped │ │ │ │ └── ultron@1.0.2 deduped │ │ │ ├── xmlhttprequest-ssl@1.5.1 │ │ │ └── yeast@0.1.2 │ │ ├── has-binary@0.1.7 deduped │ │ ├── indexof@0.0.1 │ │ ├── object-component@0.0.3 │ │ ├─┬ parseuri@0.0.4 │ │ │ └─┬ better-assert@1.0.2 │ │ │ └── callsite@1.0.0 │ │ ├── socket.io-parser@2.3.1 deduped │ │ └── to-array@0.1.4 │ └─┬ socket.io-parser@2.3.1 │ ├── component-emitter@1.1.2 │ ├─┬ debug@2.2.0 │ │ └── ms@0.7.1 │ ├── isarray@0.0.1 deduped │ └── json3@3.3.2 ├── UNMET DEPENDENCY socket.io-stream@latest ├── ws@7.5.7 └─┬ UNMET DEPENDENCY YarpJS@git+https://github.com/robotology/yarp.js.git#08c9c2cd6b6957f45ffb58779bc998252d7c5269 ├─┬ cmake-js@6.3.0 │ ├─┬ axios@0.21.4 │ │ └── follow-redirects@1.14.9 │ ├─┬ debug@4.3.3 │ │ └── ms@2.1.2 │ ├─┬ fs-extra@5.0.0 │ │ ├── graceful-fs@4.2.9 │ │ ├─┬ jsonfile@4.0.0 │ │ │ └── graceful-fs@4.2.9 deduped │ │ └── universalify@0.1.2 │ ├── is-iojs@1.1.0 │ ├── lodash@4.17.21 │ ├─┬ memory-stream@0.0.3 │ │ └─┬ readable-stream@1.0.34 │ │ ├── core-util-is@1.0.3 │ │ ├── inherits@2.0.4 │ │ ├── isarray@0.0.1 deduped │ │ └── string_decoder@0.10.31 │ ├─┬ npmlog@1.2.1 │ │ ├── ansi@0.3.1 │ │ ├─┬ are-we-there-yet@1.0.6 │ │ │ ├── delegates@1.0.0 │ │ │ └─┬ readable-stream@2.3.7 │ │ │ ├── core-util-is@1.0.3 deduped │ │ │ ├── inherits@2.0.4 deduped │ │ │ ├── isarray@1.0.0 │ │ │ ├── process-nextick-args@2.0.1 │ │ │ ├── safe-buffer@5.1.2 │ │ │ ├─┬ string_decoder@1.1.1 │ │ │ │ └── safe-buffer@5.1.2 deduped │ │ │ └── util-deprecate@1.0.2 deduped │ │ └─┬ gauge@1.2.7 │ │ ├── ansi@0.3.1 deduped │ │ ├── has-unicode@2.0.1 │ │ ├── lodash.pad@4.5.1 │ │ ├── lodash.padend@4.6.1 │ │ └── lodash.padstart@4.6.1 │ ├─┬ rc@1.2.8 │ │ ├── deep-extend@0.6.0 │ │ ├── ini@1.3.8 │ │ ├── minimist@1.2.5 │ │ └── strip-json-comments@2.0.1 │ ├── semver@5.7.1 │ ├── splitargs@0.0.7 │ ├─┬ tar@4.4.19 │ │ ├── chownr@1.1.4 │ │ ├─┬ fs-minipass@1.2.7 │ │ │ └── minipass@2.9.0 deduped │ │ ├─┬ minipass@2.9.0 │ │ │ ├── safe-buffer@5.2.1 deduped │ │ │ └── yallist@3.1.1 deduped │ │ ├─┬ minizlib@1.3.3 │ │ │ └── minipass@2.9.0 deduped │ │ ├─┬ mkdirp@0.5.5 │ │ │ └── minimist@1.2.5 deduped │ │ ├── safe-buffer@5.2.1 deduped │ │ └── yallist@3.1.1 │ ├─┬ unzipper@0.8.14 │ │ ├── big-integer@1.6.51 │ │ ├─┬ binary@0.3.0 │ │ │ ├── buffers@0.1.1 │ │ │ └─┬ chainsaw@0.1.0 │ │ │ └── traverse@0.3.9 │ │ ├── bluebird@3.4.7 │ │ ├── buffer-indexof-polyfill@1.0.2 │ │ ├─┬ duplexer2@0.1.4 │ │ │ └─┬ readable-stream@2.3.7 │ │ │ ├── core-util-is@1.0.3 deduped │ │ │ ├── inherits@2.0.4 deduped │ │ │ ├── isarray@1.0.0 │ │ │ ├── process-nextick-args@2.0.1 deduped │ │ │ ├── safe-buffer@5.1.2 │ │ │ ├─┬ string_decoder@1.1.1 │ │ │ │ └── safe-buffer@5.1.2 deduped │ │ │ └── util-deprecate@1.0.2 deduped │ │ ├─┬ fstream@1.0.12 │ │ │ ├── graceful-fs@4.2.9 deduped │ │ │ ├── inherits@2.0.4 deduped │ │ │ ├── mkdirp@0.5.5 deduped │ │ │ └─┬ rimraf@2.7.1 │ │ │ └─┬ glob@7.2.0 │ │ │ ├── fs.realpath@1.0.0 │ │ │ ├─┬ inflight@1.0.6 │ │ │ │ ├── once@1.4.0 deduped │ │ │ │ └── wrappy@1.0.2 │ │ │ ├── inherits@2.0.4 deduped │ │ │ ├─┬ minimatch@3.1.2 │ │ │ │ └─┬ brace-expansion@1.1.11 │ │ │ │ ├── balanced-match@1.0.2 │ │ │ │ └── concat-map@0.0.1 │ │ │ ├─┬ once@1.4.0 │ │ │ │ └── wrappy@1.0.2 deduped │ │ │ └── path-is-absolute@1.0.1 │ │ ├── listenercount@1.0.1 │ │ ├─┬ readable-stream@2.1.5 │ │ │ ├── buffer-shims@1.0.0 │ │ │ ├── core-util-is@1.0.3 deduped │ │ │ ├── inherits@2.0.4 deduped │ │ │ ├── isarray@1.0.0 │ │ │ ├── process-nextick-args@1.0.7 │ │ │ ├── string_decoder@0.10.31 deduped │ │ │ └── util-deprecate@1.0.2 │ │ └── setimmediate@1.0.5 │ ├── url-join@0.0.1 │ ├─┬ which@1.3.1 │ │ └── isexe@2.0.0 │ └─┬ yargs@3.32.0 │ ├── camelcase@2.1.1 │ ├─┬ cliui@3.2.0 │ │ ├── string-width@1.0.2 deduped │ │ ├─┬ strip-ansi@3.0.1 │ │ │ └── ansi-regex@2.1.1 │ │ └─┬ wrap-ansi@2.1.0 │ │ ├── string-width@1.0.2 deduped │ │ └── strip-ansi@3.0.1 deduped │ ├── decamelize@1.2.0 │ ├─┬ os-locale@1.4.0 │ │ └─┬ lcid@1.0.0 │ │ └── invert-kv@1.0.0 │ ├─┬ string-width@1.0.2 │ │ ├── code-point-at@1.1.0 │ │ ├─┬ is-fullwidth-code-point@1.0.0 │ │ │ └── number-is-nan@1.0.1 │ │ └── strip-ansi@3.0.1 deduped │ ├── window-size@0.1.4 │ └── y18n@3.2.2 ├─┬ express@4.17.3 │ ├── accepts@1.3.8 deduped │ ├── array-flatten@1.1.1 │ ├─┬ body-parser@1.19.2 │ │ ├── bytes@3.1.2 │ │ ├── content-type@1.0.4 deduped │ │ ├── debug@2.6.9 deduped │ │ ├── depd@1.1.2 deduped │ │ ├─┬ http-errors@1.8.1 │ │ │ ├── depd@1.1.2 deduped │ │ │ ├── inherits@2.0.4 deduped │ │ │ ├── setprototypeof@1.2.0 deduped │ │ │ ├── statuses@1.5.0 deduped │ │ │ └── toidentifier@1.0.1 │ │ ├─┬ iconv-lite@0.4.24 │ │ │ └── safer-buffer@2.1.2 │ │ ├── on-finished@2.3.0 deduped │ │ ├── qs@6.9.7 deduped │ │ ├─┬ raw-body@2.4.3 │ │ │ ├── bytes@3.1.2 deduped │ │ │ ├── http-errors@1.8.1 deduped │ │ │ ├── iconv-lite@0.4.24 deduped │ │ │ └── unpipe@1.0.0 deduped │ │ └── type-is@1.6.18 deduped │ ├─┬ content-disposition@0.5.4 │ │ └── safe-buffer@5.2.1 deduped │ ├── content-type@1.0.4 │ ├── cookie@0.4.2 │ ├── cookie-signature@1.0.6 │ ├─┬ debug@2.6.9 │ │ └── ms@2.0.0 │ ├── depd@1.1.2 │ ├── encodeurl@1.0.2 │ ├── escape-html@1.0.3 │ ├── etag@1.8.1 │ ├─┬ finalhandler@1.1.2 │ │ ├── debug@2.6.9 deduped │ │ ├── encodeurl@1.0.2 deduped │ │ ├── escape-html@1.0.3 deduped │ │ ├── on-finished@2.3.0 deduped │ │ ├── parseurl@1.3.3 deduped │ │ ├── statuses@1.5.0 deduped │ │ └── unpipe@1.0.0 │ ├── fresh@0.5.2 │ ├── merge-descriptors@1.0.1 │ ├── methods@1.1.2 │ ├─┬ on-finished@2.3.0 │ │ └── ee-first@1.1.1 │ ├── parseurl@1.3.3 │ ├── path-to-regexp@0.1.7 │ ├─┬ proxy-addr@2.0.7 │ │ ├── forwarded@0.2.0 │ │ └── ipaddr.js@1.9.1 │ ├── qs@6.9.7 │ ├── range-parser@1.2.1 │ ├── safe-buffer@5.2.1 │ ├─┬ send@0.17.2 │ │ ├── debug@2.6.9 deduped │ │ ├── depd@1.1.2 deduped │ │ ├── destroy@1.0.4 │ │ ├── encodeurl@1.0.2 deduped │ │ ├── escape-html@1.0.3 deduped │ │ ├── etag@1.8.1 deduped │ │ ├── fresh@0.5.2 deduped │ │ ├── http-errors@1.8.1 deduped │ │ ├── mime@1.6.0 │ │ ├── ms@2.1.3 │ │ ├── on-finished@2.3.0 deduped │ │ ├── range-parser@1.2.1 deduped │ │ └── statuses@1.5.0 deduped │ ├─┬ serve-static@1.14.2 │ │ ├── encodeurl@1.0.2 deduped │ │ ├── escape-html@1.0.3 deduped │ │ ├── parseurl@1.3.3 deduped │ │ └── send@0.17.2 deduped │ ├── setprototypeof@1.2.0 │ ├── statuses@1.5.0 │ ├─┬ type-is@1.6.18 │ │ ├── media-typer@0.3.0 │ │ └── mime-types@2.1.34 deduped │ ├── utils-merge@1.0.1 │ └── vary@1.1.2 ├── jquery@3.6.0 ├── nan@2.15.0 ├─┬ UNMET DEPENDENCY socket.io@4.4.1 │ ├─┬ accepts@1.3.8 │ │ ├─┬ mime-types@2.1.34 │ │ │ └── mime-db@1.51.0 │ │ └── negotiator@0.6.3 │ ├── UNMET DEPENDENCY base64id@2.0.0 │ ├─┬ UNMET DEPENDENCY debug@4.3.3 │ │ └── UNMET DEPENDENCY ms@2.1.2 │ ├─┬ UNMET DEPENDENCY engine.io@6.1.3 │ │ ├── @types/cookie@0.4.1 │ │ ├── @types/cors@2.8.12 │ │ ├── @types/node@17.0.21 │ │ ├── accepts@1.3.8 deduped │ │ ├── UNMET DEPENDENCY base64id@2.0.0 │ │ ├── cookie@0.4.2 deduped │ │ ├─┬ cors@2.8.5 │ │ │ ├── object-assign@4.1.1 │ │ │ └── vary@1.1.2 deduped │ │ ├── UNMET DEPENDENCY debug@4.3.3 │ │ ├─┬ UNMET DEPENDENCY engine.io-parser@5.0.3 │ │ │ └── @socket.io/base64-arraybuffer@1.0.2 │ │ └── UNMET DEPENDENCY ws@8.2.3 │ ├── UNMET DEPENDENCY socket.io-adapter@2.3.3 │ └─┬ UNMET DEPENDENCY socket.io-parser@4.0.4 │ ├── @types/component-emitter@1.2.11 │ ├── UNMET DEPENDENCY component-emitter@1.3.0 │ └── UNMET DEPENDENCY debug@4.3.3 ├─┬ socket.io-stream@0.9.1 │ ├── component-bind@1.0.0 │ └─┬ debug@2.2.0 │ └── ms@0.7.1 └── three@0.138.0 npm ERR! missing: openmct@git+https://github.com/ami-iit/openmct.git#fix/imagery-flickering, required by yarp-openmct@1.0.0 npm ERR! missing: YarpJS@git+https://github.com/robotology/yarp.js.git, required by yarp-openmct@1.0.0 npm ERR! missing: express@latest, required by yarp-openmct@1.0.0 npm ERR! missing: jquery@latest, required by yarp-openmct@1.0.0 npm ERR! missing: socket.io-stream@latest, required by yarp-openmct@1.0.0 npm ERR! extraneous: openmct@git+https://github.com/ami-iit/openmct.git#7e67bdba9ff7d6c4a98fa952ce484b3d0f474584 /usr/local/src/robot/yarp-openmct/node_modules/openmct npm ERR! missing: socket.io@4.4.1, required by YarpJS@git+https://github.com/robotology/yarp.js.git#08c9c2cd6b6957f45ffb58779bc998252d7c5269 npm ERR! missing: base64id@2.0.0, required by socket.io@4.4.1 npm ERR! missing: debug@4.3.3, required by socket.io@4.4.1 npm ERR! missing: engine.io@6.1.3, required by socket.io@4.4.1 npm ERR! missing: socket.io-adapter@2.3.3, required by socket.io@4.4.1 npm ERR! missing: socket.io-parser@4.0.4, required by socket.io@4.4.1 npm ERR! missing: ms@2.1.2, required by debug@4.3.3 npm ERR! missing: base64id@2.0.0, required by engine.io@6.1.3 npm ERR! missing: debug@4.3.3, required by engine.io@6.1.3 npm ERR! missing: engine.io-parser@5.0.3, required by engine.io@6.1.3 npm ERR! missing: ws@8.2.3, required by engine.io@6.1.3 npm ERR! missing: component-emitter@1.3.0, required by socket.io-parser@4.0.4 npm ERR! missing: debug@4.3.3, required by socket.io-parser@4.0.4 ```
How do I fix the unmet dependencies?
S-Dafarra
commented
1 year ago How do I fix the unmet dependencies?
I have removed the node_modules folder and launched npm install. This fixed the dependencies issue:
npm lsS-Dafarra
commented
1 year ago How do I fix the unmet dependencies?
I have removed the
node_modulesfolder and launchednpm install. This fixed the dependencies issue:
This fixed the issue with the IMU plot stopping. I was also able to see the three components :rocket:
Unfortunately, the issue with the logging remains. I can see the new messages only after clicking on another entry.
nunoguedelha
commented
1 year ago Sorry for the late reply @S-Dafarra . It's really great that you got rid of the side issues and we can now focus on the original one.
At first glance we seem to have the same npm ls output, at least for the main critical components.
In order for me to reproduce the same setup as much as possible on my machine, could you please tell me which superbuild tag and options you are selecting?
S-Dafarra
commented
1 year ago In order for me to reproduce the same setup as much as possible on my machine, could you please tell me which superbuild tag and options you are selecting?
Just to understand, why do you think it is related to the superbuild? Isn't it depending only on yarp?
nunoguedelha
commented
1 year ago The yarp-openmct has a dependency with Yarp only indeed, I just assumed you were building it with the superbuild. So the Yarp version or even commit suffice.
S-Dafarra
commented
1 year ago The yarp-openmct has a dependency with Yarp only indeed, I just assumed you were building it with the superbuild. So the Yarp version or even commit suffice.
We are on v3.7.2 tag at the moment
nunoguedelha
commented
1 year ago mine is 3.7.2+9-20220908.4+gitb6b13ec5c, commit b6b13ec5cd140f37f7f632f5ac0053cba0a34790.
nunoguedelha
commented
1 year ago [WARNING] wholeBodyDynamics : calibStanding ignoring calib_code all
[INFO] wholeBodyDynamics: Offset for sensor l_arm_ft_sensor 0.139563 -0.192468 0.867377 0.00205042 -0.0288921 -0.0565025
[INFO] wholeBodyDynamics: obtained assuming a measurement of 16.7978 16.9138 23.0232 -2.9501 2.21231 0.432722 and an estimated ft of 16.6582 17.1063 22.1558 -2.95215 2.2412 0.489224
[INFO] wholeBodyDynamics: Offset for sensor r_arm_ft_sensor 0.087036 -0.311485 -0.659271 0.0123236 0.00776771 -0.0080614
[INFO] wholeBodyDynamics: obtained assuming a measurement of 16.4273 -17.1213 21.1105 2.93785 2.21921 -0.496337 and an estimated ft of 16.3402 -16.8098 21.7698 2.92553 2.21144 -0.488276
[INFO] wholeBodyDynamics: Offset for sensor l_leg_ft_sensor 0.474879 2.73448 195.573 -23.1804 16.4473 0.0447365
[INFO] wholeBodyDynamics: obtained assuming a measurement of 0.531987 2.85784 -154.994 -0.397776 -2.89242 0.0376742 and an estimated ft of 0.0571078 0.123359 -350.567 22.7826 -19.3397 -0.00706231
[INFO] wholeBodyDynamics: Offset for sensor l_foot_front_ft_sensor 0.534032 -0.222507 -113.87 2.91129 2.57221 0.0064752
[INFO] wholeBodyDynamics: obtained assuming a measurement of 0.533739 -0.223028 -112.116 2.91144 2.57222 0.00647711 and an estimated ft of -0.000293361 -0.000521004 1.75365 0.000142905 1.21507e-05 1.90716e-06
[INFO] wholeBodyDynamics: Offset for sensor l_foot_rear_ft_sensor 2.30875 1.11375 309.891 27.78 -13.7213 0.0204486
[INFO] wholeBodyDynamics: obtained assuming a measurement of 2.43386 1.19187 -139.075 0.993804 1.5419 0.0104681 and an estimated ft of 0.12511 0.0781202 -448.966 -26.7862 15.2632 -0.0099805
[INFO] wholeBodyDynamics: Offset for sensor r_leg_ft_sensor 2.38609 -2.64694 -196.943 0.755242 -2.70461 -0.211887
[INFO] wholeBodyDynamics: obtained assuming a measurement of 2.45691 -2.64455 -159.916 -0.0823162 -3.25203 -0.212323 and an estimated ft of 0.0708203 0.00238504 37.0268 -0.837558 -0.547417 -0.000436473
[INFO] wholeBodyDynamics: Offset for sensor r_foot_front_ft_sensor 0.368228 1.00459 -118.867 3.72457 0.987084 -0.035494
[INFO] wholeBodyDynamics: obtained assuming a measurement of 0.367637 1.0039 -117.107 3.72349 0.987465 -0.0354924 and an estimated ft of -0.000591456 -0.00069555 1.76031 -0.00107435 0.000381909 1.65166e-06
[INFO] wholeBodyDynamics: Offset for sensor r_foot_rear_ft_sensor -3.18271 -0.396829 -79.8358 2.23825 1.72455 -0.0458248
[INFO] wholeBodyDynamics: obtained assuming a measurement of -3.21245 -0.320878 -141.499 1.38158 -0.559318 -0.0462589 and an estimated ft of -0.0297399 0.0759509 -61.6628 -0.856666 -2.28387 -0.00043412
[INFO] : calibration ended.$ yarp read ... /log/iiticublap199.lan/yarprobotinterfa[YarpJS_WholeBodyDynamics]/33280
"[/log/iiticublap199.lan/yarprobotinterfa[YarpJS_WholeBodyDynamics]/33280]" "(level WARNING) (systemtime 271715.840681944973767) (networktime 1749.92699999999990723) (message \"wholeBodyDynamics : calibStanding ignoring calib_code all\")"
"[/log/iiticublap199.lan/yarprobotinterfa[YarpJS_WholeBodyDynamics]/33280]" "(level INFO) (systemtime 271718.883475867973175) (networktime 1752.92100000000004911) (message \"wholeBodyDynamics: Offset for sensor l_arm_ft_sensor 0.139563 -0.192468 0.867377 0.00205042 -0.0288921 -0.0565025 \")"
"[/log/iiticublap199.lan/yarprobotinterfa[YarpJS_WholeBodyDynamics]/33280]" "(level INFO) (systemtime 271718.883664958004374) (networktime 1752.92100000000004911) (message \"wholeBodyDynamics: Offset for sensor l_foot_front_ft_sensor 0.534032 -0.222507 -113.87 2.91129 2.57221 0.0064752 \")"
"[/log/iiticublap199.lan/yarprobotinterfa[YarpJS_WholeBodyDynamics]/33280]" "(level INFO) (systemtime 271718.88435693201609) (networktime 1752.92200000000002547) (message \"wholeBodyDynamics: Offset for sensor r_leg_ft_sensor 2.38609 -2.64694 -196.943 0.755242 -2.70461 -0.211887 \")"
"[/log/iiticublap199.lan/yarprobotinterfa[YarpJS_WholeBodyDynamics]/33280]" "(level INFO) (systemtime 271718.884524972003419) (networktime 1752.92200000000002547) (message \"wholeBodyDynamics: Offset for sensor r_foot_front_ft_sensor 0.368228 1.00459 -118.867 3.72457 0.987084 -0.035494 \")"
"[/log/iiticublap199.lan/yarprobotinterfa[YarpJS_WholeBodyDynamics]/33280]" "(level INFO) (systemtime 271718.884748503973242) (networktime 1752.92200000000002547) (message \"wholeBodyDynamics: obtained assuming a measurement of -3.21245 -0.320878 -141.499 1.38158 -0.559318 -0.0462589 and an estimated ft of -0.0297399 0.0759509 -61.6628 -0.856666 -2.28387 -0.00043412 \")"Name, Message, Level fields
Level, Host Name, ... fields
The Yarp-OpenMCT visualiser output matches exactly the messages read on the /log port where the running process (yarprobotinterface) forwards the logging messages.
Note: There are missing INFO messages in the /log port read data w.r.t. the messages displayed on the console output, but this is not an yarp-openmct.
nunoguedelha
commented
1 year ago Unfortunately, the issue with the logging remains. I can see the new messages only after clicking on another entry.
Ciao @S-Dafarra , could you please provide the following information collected on the logging of the yarprobotinterface process instead of the walking module, while running "[calibStanding] Calibrate FT sensors" command from the control console (
yarp read ... /log/iiticublap199.lan/yarprobotinterfa[YarpJS_WholeBodyDynamics]/33280If you don't have time, we'll do it during our scheduled meeting.
[^1]: "[calibStanding] Calibrate FT sensors" command from the control console:
S-Dafarra
commented
1 year ago I have launched the robot interface adding the environmental variable YARP_LOG_PROCESS_LABEL=yarprobotinterface and it seems to be working fine
S-Dafarra
commented
1 year ago Interestingly, I still have issues with the WalkingModule log, but only on Firefox. I have opened openMCT from Chrome on my PC and I did not have issues (as @nunoguedelha suggested by the way).
S-Dafarra
commented
1 year ago Even more interestingly, after refreshing on Chrome, I started having issues also there
S-Dafarra
commented
1 year ago After restarting yarp-openmct, I was able to restore the continuous stream of messages. Is it possible that previous connections do not get removed when refreshing the page?
nunoguedelha
commented
1 year ago We discussed this directly on Teams and ran some tests together, and after the tests we ran together...
Summary
Observed behaviour
- Right after starting the server and opening the visualiser page URL on a new tab, the yarp logging messages are displayed properly, as they are received from the
/log/...port.- After we refresh the page by clicking on the browser refresh icon, we can't see anymore the messages being displayed as we trigger commands generating these messages (e.g. rpc command "calibstanding").
- If we force-refresh the page by re-typing the URL in the address box and pressing enter, the previously cached data is cleaned and the yarp logging messages are properly displayed again when we run the rpc command "calibstanding".
Probable cause
- The websocket used for sending realtime updates to the client app every 10ms is not properly restored after the page refresh, as the history buffer data is displayed, then subsequent updates are not => 100% sure
- This websocket problem is due to a kind of race condition or mis-synch between the Yarp ports de-connection, re-connection completion, followed by the Yarp-openMCT internal data pipe rewiring, and the "realtime" websocket creation by the client app after the index.html file is sent to the browser.
Proposed soludion
Send the index.html file to the browser only after the Yarp - telemetry server connections are completed. Typically we can use a Promise pattern in this case, with the resolve callback sending the index.html file, and the reject callback sending a warning to the console or browser window, or even terminating the server process.
Notes
We discussed about the Yarp logging depth being eventually too short: Stefano is ok with the current depth for now.
Actions
- Provide a fix tentative for next Monday => Nuno (Fix suggested. Implementation ongoing)
- if fix is not successful, update the README specifying the workaround (force-refresh by re-entering the page URL) => Nuno
nunoguedelha
commented
1 year ago Tentative fix by #166 .
nunoguedelha
commented
1 year ago Hi @S-Dafarra , for the record and some further clarifications on the issue, I´m just posting here a recording of the issue you described me, which I reproduced on the main branch prior the fix.
https://user-images.githubusercontent.com/6848872/214201049-e4ad02cb-f628-41c2-8328-e9f91e3294d8.mp4
For reproducing the issue observed in the recording, I´ve added a breakpoint in the callback which refreshes the ports after you click on the page refresh button.
https://github.com/ami-iit/yarp-openmct/blob/aa499a6dd984ce8dec807a431fba07b22b32c748/iCubTelemVizServer/iCubTelemVizServer.js#L198
The breakpoint delays the yarp name list command and the ports refresh that follows, leading to the observed issue.
We list below the steps leading to the issue:
We initially thought that The websocket used for sending real time updates to the client app every 10ms is not properly restored/opened after the page refresh, as mentioned in comment https://github.com/ami-iit/yarp-openmct/issues/147#issuecomment-1355885945, but this assumption was wrong.
In fact, that websocket is opened correctly and indeed conveys properly the real time data to the other telemetry entries. Nevertheless, it turned out that there is a race condition with respect to the websocket, not because it is faulty, but because it was still connecting when we try to send the first subscription. Further details in the below analysis.
Using the debugger and conveniently chosen breakpoints, we can see that when the issue occurs, no subscription is received nor sent for the faulty telemetry entry, although the OpenMCT API calls the subscribe function from the last domain object provider installed by the RealtimeTelemetryPlugin.
https://github.com/ami-iit/yarp-openmct/blob/aa499a6dd984ce8dec807a431fba07b22b32c748/openmctStaticServer/plugins/realtime-telemetry-plugin.js#L16-L22
Initially, debugging with Webstorm, by attaching its debugger to the Chrome process where we load the page, mislead the analysis as we thought the subscribe function from the provider object was never called, and this due to a bad initialisation in TelemetryAPI.prototype.subscribe. The analysis below was then completed using the debugger from Chrome developer tools.
For identifying the issue, we need to understand how the subscription works from the OpenMCT TelemetryAPI subscribe method standpoint:
https://github.com/ami-iit/openmct/blob/3e76cbb9aa2620a4660a03639ee0463cade3343f/src/api/telemetry/TelemetryAPI.js#L349-L386
domainObject and a callback for plotting the data samples,provider from the input domainObject,callback to the callbacks list associated to the key in subscribeCache: subscribeCache[key].callbacks,callback to the given key, and the provider exists, it calls provider.subscribe to send a “subscribe” request to the telemetry server through the opened websocket, and saves the returned unsubscribe method to subscribeCache[key].unsubscribe,callback, the function returns to the caller (openmct.telemetry.subscribe) an unsubscribe callback for removing the input callback from subscribeCache[key].callbacks, unsubscribe callback sends an “unsubscribe” request to the telemetry server through the opened websocket.As we enter the function TelemetryAPI.prototype.subscribe after a page refresh, subscribeCache is always undefined, and is then initialised to an empty list. We fall into the case where we’re adding the first callback to a given key, and thus provider.subscribe is called. Although socket.send is executed, no request is received on the server side and the plot canvas stays empty.
https://github.com/ami-iit/yarp-openmct/blob/aa499a6dd984ce8dec807a431fba07b22b32c748/openmctStaticServer/plugins/realtime-telemetry-plugin.js#L22
I later noticed that socket.send(…) actually fails with the error…
{
"stack": "Error: Failed to execute 'send' on 'WebSocket': Still in CONNECTING state.\n at Object.subscribe (http://192.168.1.96:8080/plugins/realtime-telemetry-plugin.js:22:24)\n at TelemetryAPI.subscribe (webpack-internal:///./src/api/telemetry/TelemetryAPI.js:365:22)\n at PlotSeries.fetch (webpack-internal:///./src/plugins/plot/configuration/PlotSeries.js:186:18)\n at PlotSeries.load (webpack-internal:///./src/plugins/plot/configuration/PlotSeries.js:308:21)\n at eval (webpack-internal:///./node_modules/vue-loader/lib/index.js?!./src/plugins/plot/MctPlot.vue?vue&type=script&lang=js&:384:28)\n at Array.forEach (<anonymous>)\n at SeriesCollection.forEach (webpack-internal:///./src/plugins/plot/configuration/Collection.js:59:21)\n at VueComponent.loadMoreData (webpack-internal:///./node_modules/vue-loader/lib/index.js?!./src/plugins/plot/MctPlot.vue?vue&type=script&lang=js&:381:32)\n at VueComponent.boundFn [as loadMoreData] (webpack-internal:///./node_modules/vue/dist/vue.js:192:14)\n at VueComponent.updateDisplayBounds (webpack-internal:///./node_modules/vue-loader/lib/index.js?!./src/plugins/plot/MctPlot.vue?vue&type=script&lang=js&:489:22)"
}This explains why the plot canvas stays empty after clicking on the page reload button.
When socket.send(…) fails, provider.subscribe does not return and neither does TelemetryAPI.prototype.subscribe. As a consequence:
unsubscribe function is called by openmct.telemetry.subscribe when we click on another telemetry entry,yarpopenmct:icubtelemetry.IMUsens.legacyIMU), subscribeCache[key] contains the leftover respective element {callbacks: [callback]} instead of being empty or undefined,callback is added to subscriber.callbacks without provider.subscribe being called nor any unsubscribe method being returned, which results in a sequence loop where the section under the !subscriber condition is never executed (no subscription request sent) for the associated key.
https://github.com/ami-iit/openmct/blob/3e76cbb9aa2620a4660a03639ee0463cade3343f/src/api/telemetry/TelemetryAPI.js#L359-L373In such case the websocket re-connection can be fast enough for avoiding the socket.send failure described above, and further subscriptions and unsubscriptions are sent as expected.
The breakpoint or normal processing delay occurring within the code section refreshing the ports, thus before the sending of the requested index.html, that pause or delay become irrelevant. The chances for the issue to occur are not null, depending processor load of the machine running the telemetry server.
A proper, robust fix would be to properly address any eventual failure of the socket.send method.
Since provider.subscribe implements the subscription request and the implementation details are unknown to the caller TelemetryAPI.prototype.subscribe, we should handle the failure (e.g. with a try/catch) the provider.subscribe.
https://github.com/ami-iit/yarp-openmct/blob/c430ddc83104148522a691c55af20daa515cef1e/openmctStaticServer/plugins/realtime-telemetry-plugin.js#L20-L33
Recording obtained with the fix improvement (commit c430ddc) and after moving the sending of index.html before the ports refresh for reproducing the issue conditions.
https://user-images.githubusercontent.com/6848872/214274961-262abd1f-1038-4be7-a465-4ceee059f100.mp4
S-Dafarra
commented
1 year ago Awesome debugging @nunoguedelha!
nunoguedelha
commented
1 year ago Actually, the report is not complete, I'm still editing. It got more clear and the explanation consistent as I used the Chrome "developper tools" to debug the client code instead of Webstorm (Webstorm is more performant for Node.js code debugging).
nunoguedelha
commented
1 year ago Done.
Refer to [issue 3] in the issue recap below:
_Originally posted by @nunoguedelha in https://github.com/ami-iit/component_ANA-Avatar-XPRIZE/issues/760#issuecomment-1266616475_