search

dyule / wamp-rs

Implementation of Web Application Messaging Protocol in Rust
MIT License
22 stars 7 forks source link

Server stops responding after a while #5

Closed Boscop closed 7 years ago

Boscop commented 7 years ago

I have the following test server to which I send keystrokes from the Web-UI for my application:

fn main() {
    dotenv().unwrap();
    env_logger::init().unwrap();
    let mut router = Router::new();
    router.add_realm("realm1");
    info!("Router listening");
    let child = router.listen("0.0.0.0:63290");

    let connection = Connection::new("ws://127.0.0.1:63290/ws", "realm1");
    info!("Connecting");
    let mut client = connection.connect().unwrap();
    info!("Connected");
    info!("Registering Keypress Procedure");
    client.register(URI::new("server.keypress"), Box::new(keypress_cb)).unwrap().await().unwrap();

    child.join().unwrap();
    client.shutdown().unwrap().await().unwrap();
}

fn keypress_cb(args: List, _kwargs: Dict) -> CallResult<(Option<List>, Option<Dict>)> {
    args.verify_len(1)?;
    let key = args.get_int(0)?.unwrap();
    info!("Receiving keypress {}", key);
    Ok((Some(vec![Value::Integer(key)]), None))
}

At first it works but after typing a few keys on the web gui, the server stops responding:

[50,2094872376676940,{},[81]]   29  
06:54:25.978
[48,8506371253933628,{},"server.keypress",[82],{}]  50  
06:54:28.064
[50,8506371253933628,{},[82]]   29  
06:54:28.065
[48,3315205349409152,{},"server.keypress",[83],{}]  50  
06:54:28.624
[50,3315205349409152,{},[83]]   29  
06:54:28.625
[48,4736671216910184,{},"server.keypress",[84],{}]  50  
06:54:32.298
[50,4736671216910184,{},[84]]   29  
06:54:32.299
[48,8733465103123834,{},"server.keypress",[85],{}]  50  
06:54:34.656
[50,8733465103123834,{},[85]]   29  
06:54:34.658
[48,6511667357184014,{},"server.keypress",[86],{}]  50  
06:54:36.312
[50,6511667357184014,{},[86]]   29  
06:54:36.313
[48,5407865983095894,{},"server.keypress",[87],{}]  50  
06:54:37.632
[50,5407865983095894,{},[87]]   29  
06:54:37.633
[48,3891173192837032,{},"server.keypress",[88],{}]  50  
06:54:39.801
[50,3891173192837032,{},[88]]   29  
06:54:39.801
[48,3832677989743216,{},"server.keypress",[89],{}]  50  
06:54:41.640
[50,3832677989743216,{},[89]]   29  
06:54:41.641
[48,7029295605444856,{},"server.keypress",[90],{}]  50  
06:54:43.098
[48,3717826704662828,{},"server.keypress",[65],{}]  50  
06:54:59.520
[48,1781967526831132,{},"server.keypress",[66],{}]  50  
06:55:03.248
[48,5900734383726916,{},"server.keypress",[67],{}]  50  
06:55:05.280
[48,1548659696291480,{},"server.keypress",[68],{}]  50  
06:55:07.827
[48,831127017980158,{},"server.keypress",[69],{}]   49  
06:55:08.113
[48,3160134408701912,{},"server.keypress",[70],{}]  50  
06:55:08.696

I typed all the letters from 'a' (65) to 'z' (90), but 'y' (89) was the last time the server responded.

Weirdly, when I reload the page with F5, it works again, for a while, until it stops working again! The log above is from Chrome dev tools WS tab, after the server stops responding, my client is still correctly sending as far as I can see (I'm using autobahn.js in the client). More specifically, I'm using wamp-web-components for Polymer: This is my client code:

<link rel="import" href="../../bower_components/polymer/polymer.html">
<link rel="import" href="../../bower_components/wamp-web-components/wamp-connection.html">
<link rel="import" href="../../bower_components/wamp-web-components/wamp-register.html">
<link rel="import" href="../../bower_components/wamp-web-components/wamp-call.html">
<link rel="import" href="../../bower_components/wamp-web-components/wamp-publish.html">
<link rel="import" href="../../bower_components/wamp-web-components/wamp-subscribe.html">

<dom-module id="my-app">
  <template>
    <style>
      :host {
        display: block;
      }
    </style>

    <h2>Hello [[prop1]]</h2>

    <wamp-connection
      url='ws://127.0.0.1:63290/ws'
      realm='realm1'
      connected='{{connected}}'
      retrying='{{retrying}}'
      session='{{session}}'
    ></wamp-connection>

    <template is="dom-if" if="[[connected]]">
      <p>Wamp is connected</p>
    </template>

    <template is="dom-if" if="[[!connected]]">
      <p>Wamp is not connected</p>
    </template>

    <template is="dom-if" if="[[retrying]]">
      <p>Autobahn is retrying connection</p>
    </template>

    <wamp-call id = "call_server_keypress"
      method='server.keypress'
      args='[]'
      session='{{session}}'
      last-response='{{res_keypress}}'
      on-response='_handleResAdd'
      auto
    ></wamp-call>

    <p>[[res_keypress]]</p>

  </template>

  <script>
    Polymer({
      is: 'my-app',
      properties: {
        prop1: {
          type: String,
          value: 'my-app',
        },
      },
      ready() {
        window.onkeydown = function(e) {
          var key = e.keyCode;
          console.log(key, String.fromCharCode(key));
          this.$.call_server_keypress.args = [key];
        }.bind(this);
      },
      _handleResAdd: function(r) {
        console.log(r);
      }
    });
  </script>
</dom-module>

What could be the cause of this?

(The reason I'm doing all this is because I want to have a web based GUI for my Rust application.)

Boscop commented 7 years ago

I confirmed that this is an issue of this crate, not of autobahn.js. When I execute the following code (simulating the wamp client in the same exe as the server), it also stops printing output (but doesn't crash) after the simulated keypress 67 every single time I execute this (!!!):

use dotenv::dotenv;

use wamp::router::Router;
use wamp::client::Connection;
use wamp::{URI, Value, Dict, List, CallResult, ArgList};
use eventual::Async;

fn main() {
    dotenv();
    env_logger::init().unwrap();
    let mut router = Router::new();
    router.add_realm("realm1");
    info!("Router listening");
    let child = router.listen("0.0.0.0:63290");

    let connection = Connection::new("ws://127.0.0.1:63290/ws", "realm1");
    info!("Connecting");
    let mut client = connection.connect().unwrap();
    info!("Connected");
    info!("Registering Keypress Procedure");
    client.register(URI::new("server.keypress"), Box::new(keypress_cb)).unwrap().await().unwrap();

    {
        use wamp::client::{Connection, Client};
        fn call_keypress(client: &mut Client, key: i64) {
            match client.call(URI::new("server.keypress"), Some(vec![Value::Integer(key)]), None).unwrap().await() {
                Ok((args, _)) => {
                    let r = args.get_int(0).unwrap().unwrap();
                    assert_eq!(r, key);
                } Err(e) => {
                    match e.take() {
                        Some(e) => {
                            println!("Error: {:?}", e);
                        } None => {
                            println!("Aborted");
                        }
                    }
                }
            }
        }
        let connection = Connection::new("ws://127.0.0.1:63290/ws", "realm1");
        let mut client = connection.connect().unwrap();
        for i in 0..1000 {
            call_keypress(&mut client, i);
        }
    }

    child.join().unwrap();
    client.shutdown().unwrap().await().unwrap();
}

fn keypress_cb(args: List, _kwargs: Dict) -> CallResult<(Option<List>, Option<Dict>)> {
    args.verify_len(1)?;
    let key = args.get_int(0)?.unwrap();
    info!("Receiving keypress {}", key);
    Ok((Some(vec![Value::Integer(key)]), None))
}

Output:

INFO:foo: Router listening
INFO:foo: Connecting
INFO:ws: Listening for new connections on 0.0.0.0:63290.
INFO:ws: Queuing connection to ws://127.0.0.1:63290/ws
INFO:ws::io: Accepted a new tcp connection from 127.0.0.1:53559.
INFO:wamp::router::messaging: New request
INFO:foo: Connected
INFO:foo: Registering Keypress Procedure
INFO:wamp::client: Recieved a registered notification
INFO:ws: Queuing connection to ws://127.0.0.1:63290/ws
INFO:ws::io: Accepted a new tcp connection from 127.0.0.1:53560.
INFO:wamp::router::messaging: New request
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(0)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 0
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(1)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 1
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(2)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 2
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(3)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 3
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(4)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 4
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(5)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 5
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(6)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 6
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(7)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 7
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(8)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 8
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(9)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 9
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(10)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 10
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(11)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 11
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(12)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 12
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(13)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 13
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(14)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 14
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(15)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 15
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(16)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 16
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(17)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 17
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(18)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 18
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(19)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 19
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(20)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 20
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(21)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 21
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(22)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 22
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(23)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 23
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(24)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 24
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(25)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 25
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(26)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 26
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(27)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 27
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(28)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 28
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(29)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 29
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(30)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 30
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(31)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 31
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(32)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 32
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(33)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 33
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(34)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 34
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(35)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 35
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(36)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 36
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(37)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 37
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(38)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 38
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(39)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 39
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(40)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 40
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(41)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 41
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(42)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 42
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(43)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 43
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(44)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 44
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(45)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 45
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(46)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 46
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(47)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 47
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(48)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 48
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(49)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 49
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(50)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 50
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(51)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 51
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(52)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 52
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(53)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 53
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(54)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 54
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(55)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 55
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(56)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 56
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(57)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 57
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(58)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 58
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(59)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 59
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(60)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 60
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(61)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 61
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(62)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 62
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(63)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 63
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(64)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 64
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(65)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 65
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(66)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 66
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(67)]) | None
INFO:wamp::router::rpc: Current procedure tree: 34155581677425374 pre: [] subs: []
server - 1954497920646432 pre: [] subs: []
    keypress - 44775292662367520 pre: [] subs: [70753485058682531]

INFO:foo: Receiving keypress 67
INFO:wamp::client: Calling URI { uri: "server.keypress" } with Some([Integer(68)]) | None

Btw, I'm on Windows 8.1. Any idea how to fix this?

Boscop commented 7 years ago

Maybe someone else can execute this and test if it works? Maybe it works on linux?

Boscop commented 7 years ago

My example apparently works on Linux: https://www.reddit.com/r/rust/comments/61f5tt/why_does_my_websocket_server_stop_responding/dfe402d/ So the bug is either in ws-rs or wamp-rs..

housleyjk commented 7 years ago

I also failed to replicate on linux. Since this is a Windows issue, it may actually be a problem in Mio. I noticed that WAMP uses ws 0.5.3. Upgrading to the latest ws may fix this because it incorporates updates to Mio that fix some windows issues, no promises though.

Boscop commented 7 years ago

Hm, I was using the crates.io version of wamp, which uses ws ^0.5, when I use the git version of wamp which uses ws 0.6, I get this output (every time):

INFO:foo: Router listening
INFO:foo: Connecting
INFO:ws: Queuing connection to ws://127.0.0.1:63290/ws
INFO:ws: Listening for new connections on 0.0.0.0:63290.
INFO:ws::io: Accepted a new tcp connection from 127.0.0.1:58582.
INFO:wamp::router::messaging: New request
INFO:foo: Connected
INFO:foo: Registering Keypress Procedure
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: Error { kind: WSError(WS Error <Queue(Disconnected)>) }', src\libcore\result.rs:859
stack backtrace:
thread '<unnamed>' panicked at 'cannot access stderr during shutdown', src\libcore\option.rs:794

I also did cargo update, and it's now using mio 0.6.6.

dyule commented 7 years ago

Looks like something I'll have to investigate. I'll update the crates.io version once I've solved this bug.

Boscop commented 7 years ago

Thanks, this is really blocking progress on my project atm.. Let me know if there's a way I can help debugging this :)

crackcomm commented 7 years ago

It seems related to #6 maybe the bug is in the client and server code or in the ws crate?

dyule commented 7 years ago

Having looked into this a little more, I'm starting to wonder if it might not be an issue with ws-rs or mio, or at least the way I'm using them.

I exactly replicated the client that @Boscop gave up above, and ran it. I got exactly the same error in exactly the same place (the client wasn't able to register the key listener). However, when I turned on trace level debugging for mio (which slowed everything down because of how much of it there was), I was able to register just fine. However, after that, the client decided to close its connection for no reason.

I think it might have something to do with timeouts, but I'm not sure, and I'm hoping @housleyjk can provide some insight into what's going on. Here's the relevant part of my log, which happens after I've registered my listener, and while both the router and client thread should be just sitting and waiting (they've both called join()). As far as I can tell none of my code is running anywhere.

TRACE:ws::frame: Position in buffer 127
TRACE:ws::io: Scheduling connection to 127.0.0.1:63290 as Ready {Readable}
TRACE:mio::poll: registering with poller
TRACE:mio::sys::windows::selector: reregister Token(0) Ready {Readable}
TRACE:mio::sys::windows::selector: set readiness to Ready {Readable | Writable}
TRACE:ws::io: Active connections 1
TRACE:ws::io: Waiting for event
TRACE:mio::sys::windows::selector: select; timeout=Some(Duration { secs: 0, nanos: 0 })
TRACE:mio::sys::windows::selector: polling IOCP
TRACE:mio::sys::windows::selector: returning
TRACE:ws::io: Processing 1 events
TRACE:ws::connection: Ready to read messages from 127.0.0.1:63290.
TRACE:ws::connection: Reading buffer for connection to 127.0.0.1:63290.
TRACE:mio::sys::windows::selector: set readiness to Ready {Writable}
TRACE:mio::sys::windows::tcp: scheduling a read
DEBUG:ws::io: WebSocket connection to 127.0.0.1:63290 disconnected.
TRACE:mio::sys::windows::tcp: cancelling active TCP read
TRACE:ws::io: Active connections 0
DEBUG:ws::io: Shutting down websocket client.
DEBUG:ws::factory: Factory received WebSocket shutdown request.

I'm unable to test this on Linux at the moment. Any thoughts?

Boscop commented 7 years ago

In my case, on windows, it could register the key listener (on every run I tried), but the server stopped responding after key 67. So it looks like it behaves differently depending on the circumstances..

Boscop commented 7 years ago

I just tried with a local fork of wamp-rs that uses ws 0.7.1, and it works now! It correctly responds to all the 1000 keypresses in the test. It also works in the normal use case when sending keypresses from the browser.

So this can be closed after updating wamp-rs to ws-rs 0.7.1.

dyule commented 7 years ago

We're now using ws 0.7.1, so I am closing this issue.