SignalWire: Unknown Relay command failure, command timed out

[juan-voiq]

Found an issue with the relay sdk:

voiq-swrelay_1  | ==> /var/log/supervisor/sidekiq-worker_00-stdout---supervisor-SyC5l9.log <==
voiq-swrelay_1  | E, [2020-05-21T21:06:08.822726 #24] ERROR -- SignalWire: Unknown Relay command failure, command timed out
voiq-swrelay_1  | E, [2020-05-21T21:06:08.823447 #24] ERROR -- SignalWire: Unknown Relay command failure, command timed out
voiq-swrelay_1  | E, [2020-05-21T21:06:08.824870 #24] ERROR -- SignalWire: NoMethodError: undefined method `stop' for nil:NilClass
voiq-swrelay_1  | E, [2020-05-21T21:06:08.825033 #24] ERROR -- SignalWire: /usr/src/VOIQ-SWRelay/app/helpers/call_helper.rb:15:in `stop_recording'
...
...
voiq-swrelay_1  | E, [2020-05-21T21:06:08.824252 #24] ERROR -- : [135750] undefined method `dig' for nil:NilClass
voiq-swrelay_1  | E, [2020-05-21T21:06:08.825219 #24] ERROR -- : [135750] ["/usr/local/bundle/bundler/gems/signalwire-ruby-19bc8de81143/lib/signalwire/relay/calling/component/record.rb:54:in `after_execute'", "/usr/local/bundle/bundler/gems/signalwire-ruby-19bc8de81143/lib/signalwire/relay/calling/component.rb:65:in `handle_execute_result'", "/usr/local/bundle/bundler/gems/signalwire-ruby-19bc8de81143/lib/signalwire/relay/calling/component.rb:53:in `block in execute'", "/usr/local/bundle/bundler/gems/signalwire-ruby-19bc8de81143/lib/signalwire/relay/client.rb:87:in `relay_execute'", "/usr/local/lib/ruby/2.6.0/forwardable.rb:230:in `relay_execute'", "/usr/local/bundle/bundler/gems/signalwire-ruby-19bc8de81143/lib/signalwire/relay/calling/component.rb:52:in `execute'", "/usr/local/bundle/bundler/gems/signalwire-ruby-19bc8de81143/lib/signalwire/relay/calling/call.rb:219:in `record!'", "/usr/src/VOIQ-SWRelay/app/helpers/call_helper.rb:7:in `start_recording'", "/usr/src/VOIQ-SWRelay/app/services/relay/relay_consumer.rb:54:in `block in setup_answered'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:162:in `call_handler'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:141:in `block (3 levels) in trigger_handler'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:136:in `catch'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:136:in `block (2 levels) in trigger_handler'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:134:in `each'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:134:in `find'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:134:in `block in trigger_handler'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:133:in `catch'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:133:in `trigger_handler'", "/usr/local/bundle/bundler/gems/signalwire-ruby-19bc8de81143/lib/signalwire/blade/event_handler.rb:12:in `broadcast'", "/usr/local/bundle/bundler/gems/signalwire-ruby-19bc8de81143/lib/signalwire/relay/calling/call.rb:67:in `change_call_state'", "/usr/local/bundle/bundler/gems/signalwire-ruby-19bc8de81143/lib/signalwire/relay/calling/call.rb:53:in `block in setup_call_event_handlers'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:162:in `call_handler'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:141:in `block (3 levels) in trigger_handler'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:136:in `catch'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:136:in `block (2 levels) in trigger_handler'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:134:in `each'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:134:in `find'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:134:in `block in trigger_handler'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:133:in `catch'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:133:in `trigger_handler'", "/usr/local/bundle/bundler/gems/signalwire-ruby-19bc8de81143/lib/signalwire/blade/event_handler.rb:12:in `broadcast'", "/usr/local/bundle/bundler/gems/signalwire-ruby-19bc8de81143/lib/signalwire/relay/client.rb:173:in `block in setup_events'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:162:in `call_handler'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:141:in `block (3 levels) in trigger_handler'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:136:in `catch'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:136:in `block (2 levels) in trigger_handler'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:134:in `each'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:134:in `find'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:134:in `block in trigger_handler'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:133:in `catch'", "/usr/local/bundle/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:133:in `trigger_handler'", "/usr/local/bundle/bundler/gems/signalwire-ruby-19bc8de81143/lib/signalwire/blade/event_handler.rb:12:in `broadcast'", "/usr/local/bundle/bundler/gems/signalwire-ruby-19bc8de81143/lib/signalwire/blade/connection.rb:110:in `block in receive'", "/usr/local/bundle/gems/eventmachine-1.2.7/lib/eventmachine.rb:1077:in `block in spawn_threadpool'"]

It happened unexpectedly weren't doing anything weird @lpradovera

[juan-voiq]

New backtrace from today:

voiq-swrelay_1  | E, [2020-05-22T13:04:52.230623 #24] ERROR -- SignalWire: Blade error occurred, code -32004: Ignored 'blade.execute' request because the protocol is not available for access control
voiq-swrelay_1  | E, [2020-05-22T13:04:52.244391 #24] ERROR -- SignalWire: Blade error occurred, code -32004: Ignored 'blade.execute' request because the protocol is not available for access control
voiq-swrelay_1  | E, [2020-05-22T13:04:52.244737 #24] ERROR -- SignalWire: Blade error occurred, code -32004: Ignored 'blade.execute' request because the protocol is not available for access control
voiq-swrelay_1  | E, [2020-05-22T13:04:52.246509 #24] ERROR -- SignalWire: Blade error occurred, code -32004: Ignored 'blade.execute' request because the protocol is not available for access control
voiq-swrelay_1  | E, [2020-05-22T13:04:52.251224 #24] ERROR -- SignalWire: Blade error occurred, code -32004: Ignored 'blade.execute' request because the protocol is not available for access control
voiq-swrelay_1  | E, [2020-05-22T13:04:52.252765 #24] ERROR -- SignalWire: Blade error occurred, code -32004: Ignored 'blade.execute' request because the protocol is not available for access control
voiq-swrelay_1  | E, [2020-05-22T13:04:52.255708 #24] ERROR -- SignalWire: Blade error occurred, code -32004: Ignored 'blade.execute' request because the protocol is not available for access control
voiq-swrelay_1  | E, [2020-05-22T13:04:52.260221 #24] ERROR -- SignalWire: Blade error occurred, code -32004: Ignored 'blade.execute' request because the protocol is not available for access control
voiq-swrelay_1  | E, [2020-05-22T13:04:52.263072 #24] ERROR -- SignalWire: Blade error occurred, code -32004: Ignored 'blade.execute' request because the protocol is not available for access control
voiq-swrelay_1  | E, [2020-05-22T13:04:52.265479 #24] ERROR -- SignalWire: Blade error occurred, code -32004: Ignored 'blade.execute' request because the protocol is not available for access control
voiq-swrelay_1  | E, [2020-05-22T13:04:52.268867 #24] ERROR -- SignalWire: Blade error occurred, code -32004: Ignored 'blade.execute' request because the protocol is not available for access control
voiq-swrelay_1  | E, [2020-05-22T13:04:52.164642 #24] ERROR -- SignalWire: Unknown Relay command failure, command timed out
voiq-swrelay_1  | E, [2020-05-22T13:04:52.271333 #24] ERROR -- SignalWire: Blade error occurred, code -32004: Ignored 'blade.execute' request because the protocol is not available for access control
voiq-swrelay_1  | E, [2020-05-22T13:04:52.274191 #24] ERROR -- SignalWire: Blade error occurred, code -32004: Ignored 'blade.execute' request because the protocol is not available for access control
voiq-swrelay_1  | E, [2020-05-22T13:04:52.276003 #24] ERROR -- SignalWire: Blade error occurred, code -32004: Ignored 'blade.execute' request because the protocol is not available for access control
voiq-swrelay_1  | E, [2020-05-22T13:04:52.277347 #24] ERROR -- SignalWire: Blade error occurred, code -32004: Ignored 'blade.execute' request because the protocol is not available for access control
voiq-swrelay_1  | E, [2020-05-22T13:04:52.279488 #24] ERROR -- SignalWire: Blade error occurred, code -32004: Ignored 'blade.execute' request because the protocol is not available for access control
voiq-swrelay_1  | E, [2020-05-22T13:04:52.281301 #24] ERROR -- SignalWire: Blade error occurred, code -32004: Ignored 'blade.execute' request because the protocol is not available for access control
voiq-swrelay_1  | E, [2020-05-22T13:04:52.272919 #24] ERROR -- SignalWire: Blade error occurred, code -32004: Ignored 'blade.execute' request because the protocol is not available for access control
voiq-swrelay_1  | E, [2020-05-22T13:04:52.162977 #24] ERROR -- SignalWire: Blade error occurred, code -32004: Ignored 'blade.execute' request because the protocol is not available for access control
voiq-swrelay_1  | E, [2020-05-22T13:04:52.244820 #24] ERROR -- SignalWire: Unknown Relay command failure, command timed out
voiq-swrelay_1  | E, [2020-05-22T13:04:52.087241 #24] ERROR -- SignalWire: Unknown Relay command failure, command timed out
voiq-swrelay_1  | E, [2020-05-22T13:04:52.168436 #24] ERROR -- SignalWire: Unknown Relay command failure, command timed out
voiq-swrelay_1  | E, [2020-05-22T13:04:52.283896 #24] ERROR -- SignalWire: Relay error occurred, code -32004: Ignored 'blade.execute' request because the protocol is not available for access control

@lpradovera

[juan-voiq]

Call examples: https://voiq.signalwire.com/relay/356b12c4-fb6e-4355-9e49-8d3424ecfb80 https://voiq.signalwire.com/relay/af8892fb-ce2c-4be0-bf83-5bdcb31118fd https://voiq.signalwire.com/relay/5bd81beb-6154-413c-81c2-dc7c72753542 https://voiq.signalwire.com/relay/c28aa5ab-5146-46ca-9486-bc80fbfb3dd3

[lpradovera]

@juan-voiq could you please paste a snippet of the code that triggers the issue?

[juan-voiq]

There is no specific part of the SDK that we have seen triggers this, we think is because we reach a concurrency limit and the client disconnects, we were trying to make 1 call every 5 seconds with different call lenghts, we had to lower the rate to 1 call every 15 secs to avoid the error.