start message sequence chart tracing (#571)

* new: RX/TX message sequence tracingvia AUTOBAHN_TRACE
* new: add message trace files for tests
* new: add option to run quietly
* fix: tune done log noise
* fix: #407

.crossbar/key.priv

@@ -1,7 +1,11 @@
 Crossbar.io node private key - KEEP THIS SAFE!
 
-creator: oberstet@thinkpad-t430s
-created-at: 2017-03-26T23:29:47.358Z
-machine-id: 7a3357418649414dbd536c31c6bd0ee8
-public-key-ed25519: 9e837b9c3b8a14ad5bbeb6b3671403f31d2010e776a36e1833356ea4be0b30b3
-private-key-ed25519: b12d4c6804da2884524addf1671d5e0d00ed0c2de624924c6b19331c4c4c9cbe
+creator: oberstet@intel-nuci7
+created-at: 2023-01-16T10:13:47.153Z
+machine-id: 816b4b901e774fc1ad59cbf2719806b7
+node-authid: intel-nuci7
+node-cluster-ip: 127.0.0.1
+public-key-ed25519: 04ffa62e526aa0ff648cd61be4cc9d92f80e973485473647f76e96bef0d84dfe
+public-adr-eth: 0x62E7Af2CF452e820051210D237723E5914fB53F4
+private-key-ed25519: 39e3c34e472b6b5e6b93f73690584471f5c717b7320ea393d90d4f15a9747338
+private-key-eth: 3dcf36bafeb82d1b3927389847c68f1920c33c5f3607fffb4b2561da24351849

.crossbar/key.pub

@@ -1,6 +1,9 @@
 Crossbar.io node public key
 
-creator: oberstet@thinkpad-t430s
-created-at: 2017-03-26T23:29:47.358Z
-machine-id: 7a3357418649414dbd536c31c6bd0ee8
-public-key-ed25519: 9e837b9c3b8a14ad5bbeb6b3671403f31d2010e776a36e1833356ea4be0b30b3
+creator: oberstet@intel-nuci7
+created-at: 2023-01-16T10:13:47.153Z
+machine-id: 816b4b901e774fc1ad59cbf2719806b7
+node-authid: intel-nuci7
+node-cluster-ip: 127.0.0.1
+public-key-ed25519: 04ffa62e526aa0ff648cd61be4cc9d92f80e973485473647f76e96bef0d84dfe
+public-adr-eth: 0x62E7Af2CF452e820051210D237723E5914fB53F4

.github/workflows/main.yml

@@ -10,21 +10,27 @@ on:
 
 jobs:
   unittest:
+    env:
+      CB_IMAGE: crossbario/crossbar:cpy-slim-amd64-22.7.1.dev1
+
     runs-on: ubuntu-latest
     strategy:
       matrix:
-        node: [ '14', '16' ]
+        # https://de.wikipedia.org/wiki/Node.js#Versionen
+        node: ['14', '18', '19']
 
     name: Node ${{ matrix.node }} run
     steps:
-    - uses: actions/checkout@v2
-    - uses: actions/setup-node@v1
+    - uses: actions/checkout@v3
+    - uses: actions/setup-node@v3
       with:
         node-version: ${{ matrix.node }}
 
     # Run this a bit early in the CI, so we don't have to "sleep".
     - name: Run crossbar
-      run: docker run -d -v $PWD/.crossbar:/node -p 8080:8080 -p 8090:8090 -u $UID crossbario/crossbar --cbdir /node
+      run: |
+        docker run --rm --entrypoint=/usr/local/bin/crossbar $CB_IMAGE version
+        docker run -d -v $PWD/.crossbar:/node -p 8080:8080 -p 8090:8090 -u $UID --entrypoint=/usr/local/bin/crossbar $CB_IMAGE start --cbdir /node
 
     - name: Install dependencies
       run: |
@@ -33,4 +39,6 @@ jobs:
         sudo pip3 install --no-cache-dir -U scons boto taschenmesser
 
     - name: Run tests
-      run: cd packages/autobahn && npm install && npm test
+      run: |
+        cd packages/autobahn && npm install
+        make test

Makefile

@@ -129,20 +129,99 @@ crossbar:
 crossbar_docker:
 	docker run -it --rm -v ${PWD}/.crossbar:/node -p 8080:8080 -p 8090:8090 -u 1000 crossbario/crossbar --cbdir /node
 
-test:
-	# npm install
-	cd packages/autobahn && npm test
-	# FIXME: add xbr specific unit tests
-	# cd packages/autobahn-xbr && npm test
+#test_binary:
+#	cd packages/autobahn && nodeunit test/test_binary.js -t testBinaryCBOR
+
+test_clean:
+	-rm packages/autobahn/test/test*.txt
+	-rm packages/autobahn/test/test*.trace
+
+test_basic_async:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_basic_async.trace nodeunit test/test_basic_async.js
+
+test_basic_sync:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_basic_sync.trace nodeunit test/test_basic_sync.js
+
+test_binary:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_binary.trace nodeunit test/test_binary.js
 
 test_connect:
-	cd packages/autobahn && nodeunit test/test_connect.js
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_connect.trace nodeunit test/test_connect.js
 
-test_serialization_cbor:
-	cd packages/autobahn && nodeunit test/test_serialization_cbor.js
+test_error_handling:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_error_handling.trace nodeunit test/test_error_handling.js
+
+test_pubsub_basic:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_pubsub_basic.trace nodeunit test/test_pubsub_basic.js
+
+test_pubsub_complex:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_pubsub_complex.trace nodeunit test/test_pubsub_complex.js
+
+test_pubsub_eligible:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_pubsub_eligible.trace nodeunit test/test_pubsub_eligible.js
+
+test_pubsub_exclude:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_pubsub_exclude.trace nodeunit test/test_pubsub_exclude.js
+
+test_pubsub_excludeme:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_pubsub_excludeme.trace nodeunit test/test_pubsub_excludeme.js
 
 test_pubsub_multiple_matching_subs:
-	cd packages/autobahn && nodeunit test/test_pubsub_multiple_matching_subs.js
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_pubsub_multiple_matching_subs.trace nodeunit test/test_pubsub_multiple_matching_subs.js
 
-test_binary:
-	cd packages/autobahn && nodeunit test/test_binary.js -t testBinaryCBOR
+test_pubsub_options:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_pubsub_options.trace nodeunit test/test_pubsub_options.js
+
+test_pubsub_prefix_sub:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_pubsub_prefix_sub.trace nodeunit test/test_pubsub_prefix_sub.js
+
+test_pubsub_wildcard_sub:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_pubsub_wildcard_sub.trace nodeunit test/test_pubsub_wildcard_sub.js
+
+test_rawsocket_protocol:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_rawsocket_protocol.trace nodeunit test/test_rawsocket_protocol.js
+
+test_rawsocket_transport:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_rawsocket_transport.trace nodeunit test/test_rawsocket_transport.js
+
+test_rpc_arguments:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_rpc_arguments.trace nodeunit test/test_rpc_arguments.js
+
+test_rpc_complex:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_rpc_complex.trace nodeunit test/test_rpc_complex.js
+
+test_rpc_error:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_rpc_error.trace nodeunit test/test_rpc_error.js
+
+test_rpc_options:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_rpc_options.trace nodeunit test/test_rpc_options.js
+
+test_rpc_progress:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_rpc_progress.trace nodeunit test/test_rpc_progress.js
+
+test_rpc_request_id_sequence:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_rpc_request_id_sequence.trace nodeunit test/test_rpc_request_id_sequence.js
+
+test_rpc_routing:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_rpc_routing.trace nodeunit test/test_rpc_routing.js
+
+test_rpc_slowsquare:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_rpc_slowsquare.trace nodeunit test/test_rpc_slowsquare.js
+
+test_sealedbox:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_sealedbox.trace nodeunit test/test_sealedbox.js
+
+test_serialization_cbor:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_serialization_cbor.trace nodeunit test/test_serialization_cbor.js
+
+test_serialization_json:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_serialization_json.trace nodeunit test/test_serialization_json.js
+
+test_serialization_msgpack:
+	cd packages/autobahn && AUTOBAHN_TRACE=test/test_serialization_json.trace nodeunit test/test_serialization_msgpack.js
+
+
+# FIXME!
+# test: test_binary test_sealedbox
+
+test: test_basic_async test_basic_sync test_connect test_error_handling test_pubsub_basic test_pubsub_complex test_pubsub_eligible test_pubsub_exclude test_pubsub_excludeme test_pubsub_multiple_matching_subs test_pubsub_options test_pubsub_prefix_sub test_pubsub_wildcard_sub test_rawsocket_protocol test_rawsocket_transport test_rpc_arguments test_rpc_complex test_rpc_error test_rpc_options test_rpc_progress test_rpc_request_id_sequence test_rpc_routing test_rpc_slowsquare test_serialization_cbor test_serialization_json test_serialization_msgpack

package.json

@@ -10,12 +10,14 @@
     "deep-equal": ">= 1.0.1",
     "google-closure-compiler": ">= 20170218.0.0",
     "nodeunit": ">= 0.11.3",
-    "random-bytes-seed": ">=1.0.3"
+    "random-bytes-seed": ">=1.0.3",
+    "dotenv": "^16.0.3"
   },
   "repository": {
     "type": "git",
     "url": "git://github.com/crossbario/autobahn-js.git"
   },
   "author": "Crossbar.io Technologies GmbH",
-  "license": "MIT"
+  "license": "MIT",
+  "dependencies": {}
 }

packages/autobahn/lib/connection.js

@@ -107,11 +107,9 @@ Connection.prototype._create_transport = function () {
 
    for (var i = 0; i < this._transport_factories.length; ++i) {
       var transport_factory = this._transport_factories[i];
-      log.debug("trying to create WAMP transport of type: " + transport_factory.type);
       try {
          var transport = transport_factory.create();
          if (transport) {
-            log.debug("using WAMP transport type: " + transport_factory.type);
             return transport;
          }
       } catch (e) {

packages/autobahn/lib/log.js

@@ -12,11 +12,29 @@
 ///////////////////////////////////////////////////////////////////////////////
 
 
+// use empty debug() function as default
 let debug = function () {};
 
-if ('AUTOBAHN_DEBUG' in global && AUTOBAHN_DEBUG && 'console' in global) {
+// log debug messages to console if AUTOBAHN_DEBUG is in globals or set as environment variable - works in browser and NodeJS
+if ('console' in global) {
+   if (('AUTOBAHN_DEBUG' in global && AUTOBAHN_DEBUG) || ('process' in global && process.env.AUTOBAHN_DEBUG)) {
+      debug = function () {
+         // console.log.apply(console, arguments);
+
+         // If you want to send an arguments list you need to use call:
+         // https://stackoverflow.com/a/41354496/884770
+         console.log.call(console, JSON.stringify(arguments[0], null, '  '));
+      }
+   }
+}
+
+console.log('Sdfsdf');
+
+// write debug messages to tracefile if AUTOBAHN_TRACE is set as environment variable - only works on NodeJS
+if ('process' in global && process.env.AUTOBAHN_TRACE) {
    debug = function () {
-      console.log.apply(console, arguments);
+      const fs = require("fs");
+      fs.appendFileSync(process.env.AUTOBAHN_TRACE, JSON.stringify(arguments[0], null, '  ') + '\n\n');
    }
 }
 

packages/autobahn/lib/session.js

@@ -273,7 +273,9 @@ var Session = function (socket, defer, onchallenge, on_user_error, on_internal_e
    self._publisher_disclose_me = false;
 
    self._send_wamp = function (msg) {
-      log.debug(msg);
+      // message sequence (MSC) tracing:
+      log.debug(['TX', self._realm, self._id, msg]);
+
       // forward WAMP message to be sent to WAMP transport
       self._socket.send(msg);
    };
@@ -854,6 +856,8 @@ var Session = function (socket, defer, onchallenge, on_user_error, on_internal_e
    // callback fired by WAMP transport on receiving a WAMP message
    //
    self._socket.onmessage = function (msg) {
+      // message sequence (MSC) tracing:
+      log.debug(['RX', self._realm, self._id, msg]);
 
       var msg_type = msg[0];
 

packages/autobahn/lib/transport/websocket.js

@@ -43,14 +43,12 @@ function Factory (options) {
 
    if (options.autoping_interval) {
      util.assert(options.autoping_interval > 0, "options.autoping_interval must be greater than 0");
-     options.autoping_interval = options.autoping_interval * 1000
    } else {
      options.autoping_interval = 10000;
    }
 
    if (options.autoping_timeout) {
      util.assert(options.autoping_timeout > 0, "options.autoping_timeout must be greater than 0");
-     options.autoping_timeout = options.autoping_timeout * 1000
    } else {
      options.autoping_timeout = 5000;
    }
@@ -183,18 +181,16 @@ Factory.prototype.create = function () {
                // Only using the known working flags in the options.
                // https://nodejs.org/api/https.html#https_https_request_options_callback
 
-               log.debug('Using TLS Client Authentication.');
-
                options.ca = self._options.tlsConfiguration.ca;
                options.cert = self._options.tlsConfiguration.cert;
                options.key = self._options.tlsConfiguration.key;
                options.rejectUnauthorized = false;
             } else {
-               log.debug("Not using TLS Client Authentication. tlsConfiguration should include " +
+               log.warn("Not using TLS Client Authentication. tlsConfiguration should include " +
                    "'ca' 'cert' and 'key' parameters.");
             }
          } else {
-            log.debug('Not using TLS Client Authentication.');
+            // not using TLS Client Authentication
          }
 
          websocket = new WebSocket(self._options.url, protocols, options);

packages/autobahn/test/test_connect.js

@@ -14,11 +14,13 @@
 var autobahn = require('../index.js');
 var testutil = require('./testutil.js');
 
+process.on('warning', e => console.warn(e.stack));
+
 exports.testConnect = function (testcase) {
 
    testcase.expect(1);
 
-   var test = new testutil.Testlog("test/test_connect.txt");
+   var test = new testutil.Testlog("test/test_connect.txt", true);
    var N = 10;
 
    test.log("connecting " + N + " sessions ...");