signalwire / signalwire-ruby

MIT License
9 stars 11 forks source link

Timed out Relay events do not unblock their promise. #26

Closed lpradovera closed 5 years ago

lpradovera commented 5 years ago

Reference

lpradovera commented 5 years ago

There seems to be an issue with the ruby SDK on execute timeouts. It manifested for @anthmFS when attempting to use the SDK to answer a call through an FS that was not responding correctly. The first issue presented when the timeout occurred and the on_incoming_call seemed to stop executing entirely, or hung waiting despite the timeout occurring. The second issue, presented 30 seconds later when another command timeout occurred but nothing had been executed. Further testing into the scenarios of how the SDK deals with timeouts during blocking API's is required.

I, [2019-07-29T18:28:40.194021 #27909]  INFO -- SignalWire: Starting up call for {:call_state=>"created", :context=>"incoming", :device=>{:type=>"phone", :params=>{:from_number=>"+12623098501", :to_number=>"12623940090"}}, :direction=>"inbound", :call_id=>"fa716175-d796-4102-ae39-718534e7c557", :node_id=>"93f6af14-ee09-439b-a580-d163e8c779bc"}
D, [2019-07-29T18:28:40.194793 #27909] DEBUG -- SignalWire: SEND: {
  "method": "blade.execute",
  "params": {
    "protocol": "signalwire_a652255d7dcaf22fe67079894cf9cecccc972e2f1caa621c826d6f73b68374f2_982be683-5141-48e5-b3f9-bb7f18abeedc_d1a906e8-f5e5-4939-8c07-31105b56ec41",
    "method": "call.answer",
    "params": {
      "node_id": "93f6af14-ee09-439b-a580-d163e8c779bc",
      "call_id": "fa716175-d796-4102-ae39-718534e7c557"
    }
  },
  "jsonrpc": "2.0",
  "id": "2192922f-3a64-4b8d-8757-b683c7be6fb3"
}
D, [2019-07-29T18:28:45.193752 #27909] DEBUG -- SignalWire: RECV: {
  "jsonrpc": "2.0",
  "id": "96d1ff1e-8300-40b9-a06b-dd07783f8c99",
  "method": "blade.broadcast",
  "params": {
    "broadcaster_nodeid": "7294f67e-7973-42b5-b635-e87961d9f22a",
    "protocol": "signalwire_a652255d7dcaf22fe67079894cf9cecccc972e2f1caa621c826d6f73b68374f2_982be683-5141-48e5-b3f9-bb7f18abeedc_d1a906e8-f5e5-4939-8c07-31105b56ec41",
    "channel": "notifications",
    "event": "queuing.relay.events",
    "params": {
      "event_type": "calling.call.state",
      "timestamp": 1564442925.13107,
      "project_id": "d1a906e8-f5e5-4939-8c07-31105b56ec41",
      "space_id": "173aba80-58fc-415d-b6ed-df6e357e766f",
      "params": {
        "call_state": "ended",
        "direction": "inbound",
        "device": {
          "type": "phone",
          "params": {
            "from_number": "+12623098501",
            "to_number": "12623940090"
          }
        },
        "end_reason": "error",
        "call_id": "fa716175-d796-4102-ae39-718534e7c557",
        "node_id": "93f6af14-ee09-439b-a580-d163e8c779bc"
      },
      "event_channel": "signalwire_a652255d7dcaf22fe67079894cf9cecccc972e2f1caa621c826d6f73b68374f2_982be683-5141-48e5-b3f9-bb7f18abeedc_d1a906e8-f5e5-4939-8c07-31105b56ec41"
    }
  }
}
E, [2019-07-29T18:28:46.027527 #27909] ERROR -- SignalWire: Unknown Relay command failure, command timed out
E, [2019-07-29T18:29:10.194686 #27909] ERROR -- SignalWire: Unknown Relay command failure, command timed out
lpradovera commented 5 years ago

In my testing (performed by artificially ignoring the answer response), I am seeing the timeouts as expected, but the call loop is not blocking until the timeout. I don't think there is anything wrong here, but if I could see the code that originated the issue, I can take a look at a reproduction.

lpradovera commented 5 years ago
# The below simulates a call that does not respond to answer
        message = event.dig(:result, :result, :message)
        if message == "Answering call" && @ignore_first.nil?
          logger.debug "IGNORING ANSWERED RESPONSE"
          @ignore_first = true
        else
          promise.fulfill event
        end 
lpradovera commented 5 years ago

Fixed in #34 .