cmd() blocks when other thread blocks on get_packets()

[martinerikwerner-aac]

Summary

When combining get_packets() and cmd() calls in a multi-threaded script, cmd() unexpectedly(?) seems to block while get_packets() is blocking.

I would expect that cmd() called from a separate thread should proceed without blocking regardless of any calls to get_packets()?

Details

When using threading in a script like so:

require 'cosmos'
require 'cosmos/script'

id = subscribe_packets([['TEST', 'A_TLM']])

t = Thread.new do
  123.times do
    puts("consumer #{Time.now}")
    id, packets = get_packets(id, block: (10 * 1000), count: 1)
    raise Timeout::Error unless packets
  end
end

sleep(1)

123.times do
  puts("producer #{Time.now}")
  cmd('TEST', 'A_CMD', 'A_PARAM' => 123)
end

t.join

Where TEST here is a simple delayed (1.5 seconds) loopback target.

The following log output is produced (reverse chronological):

2022/10/13 13:00:38.533 (test.rb:18): cmd("TEST A_CMD with A_PARAM 123")
2022/10/13 13:00:38.426 (test.rb:17): producer 2022-10-13 13:00:38 +0000

2022/10/13 13:00:38.332 (test.rb:18): cmd("TEST A_CMD with A_PARAM 123")
2022/10/13 13:00:38.333 (test.rb:18):   from TEST/procedures/test.rb:7:in `block (3 levels) in run_text'

2022/10/13 13:00:38.333 (test.rb:18):   from TEST/procedures/test.rb:7:in `times'

2022/10/13 13:00:38.333 (test.rb:18): TEST/procedures/test.rb:10:in `block (4 levels) in run_text': Timeout::Error (Timeout::Error)

2022/10/13 13:00:38.333 (test.rb:18): #<Thread:0x00007fcf900b01a0 TEST/procedures/test.rb:6 run> terminated with exception (report_on_exception is true):

2022/10/13 13:00:38.327 (SCRIPTRUNNER): Error : Timeout::Error
TEST/procedures/test.rb:10:in `block (4 levels) in run_text'
TEST/procedures/test.rb:7:in `times'
TEST/procedures/test.rb:7:in `block (3 levels) in run_text'
2022/10/13 13:00:29.140 (test.rb:17): producer 2022-10-13 13:00:29 +0000

2022/10/13 13:00:28.140 (test.rb:8): consumer 2022-10-13 13:00:28 +0000

2022/10/13 13:00:27.447 (SCRIPTRUNNER): Starting script: test.rb
2022/10/13 13:00:27.411 (SCRIPTRUNNER): Script config/DEFAULT/targets/TEST/procedures/test.rb spawned in 1.151884992 seconds <ruby 3.0.4>

To Reproduce

1. Install the plugin from https://github.com/martinerikwerner-aac/cosmos-plugin-cmd-blocking (this plugin contains the items I used to reproduce the issue, including the script above)
2. Start the loopback.rb script via script runner
3. Connect the TEST interface
4. Start the test.rb script via script runner
5. Observe the log output

Expected behavior

The log output should show regular and frequent timestamps from both the "producer" and the "consumer", and in particular it should not raise a timeout exception.

Environment:

• OS: Debian 11
• COSMOS Version 5.0.5
• Cosmos v5 -- [x] Mozilla Firefox