House Management Scripting Test fails on Cygwin

[AlexProudfoot]

This doesn't happen on Linux Mint. Here is the symptom.

$ ./house_management-scripting.exe h.tcl
script starting
echo: checking that all lamps are off
echo: checking output 0 is in state false
echo: checking output 1 is in state false
echo: checking output 2 is in state false
echo: checking output 3 is in state false
echo: pushing button 0
ColdFrame: INFO: posting a HOUSE_MANAGEMENT.BUTTON.DIGITAL_IO_INPUT_SIGNAL_STATE.CALLBACK_EVENT
ColdFrame: INFO: dispatching a HOUSE_MANAGEMENT.BUTTON.DIGITAL_IO_INPUT_SIGNAL_STATE.CALLBACK_EVENT
ColdFrame: INFO: setting a Timer for a HOUSE_MANAGEMENT.TIMED_BUTTON.TIMEOUT, delay 5.000000000
echo: lamps 0 and 1 should be set
echo: checking output 0 is in state true
echo: checking output 1 is in state true
echo: checking output 2 is in state false
echo: checking output 3 is in state false
echo: waiting until just before the timeout
echo: checking the lamps are still setColdFrame: INFO: posting a COLDFRAME.PROJECT.EVENTS.HELD_EVENT

echo: checking output 0 is in state trueColdFrame: INFO: dispatching a COLDFRAME.PROJECT.EVENTS.HELD_EVENT

echo: checking output 1 is in state trueColdFrame: INFO: dispatching a HOUSE_MANAGEMENT.TIMED_BUTTON.TIMEOUT: state HOUSE_MANAGEMENT.TIMED_BUTTON.SET

ColdFrame: INFO: .. new state HOUSE_MANAGEMENT.TIMED_BUTTON.RESET
h.tcl:16: digital_io.set (o=>1,to_state) expected TRUE, got FALSE
    while executing
"go"
    (file "h.tcl" line 68)

[AlexProudfoot]

Using ActiveTcl on Linux Mint doesn't break the test.

script starting
echo: checking that all lamps are off
echo: checking output 0 is in state false
echo: checking output 1 is in state false
echo: checking output 2 is in state false
echo: checking output 3 is in state false
echo: pushing button 0
ColdFrame: INFO: posting a HOUSE_MANAGEMENT.BUTTON.DIGITAL_IO_INPUT_SIGNAL_STATE.CALLBACK_EVENT
ColdFrame: INFO: dispatching a HOUSE_MANAGEMENT.BUTTON.DIGITAL_IO_INPUT_SIGNAL_STATE.CALLBACK_EVENT
ColdFrame: INFO: setting a Timer for a HOUSE_MANAGEMENT.TIMED_BUTTON.TIMEOUT, delay 5.000000000
echo: lamps 0 and 1 should be set
echo: checking output 0 is in state true
echo: checking output 1 is in state true
echo: checking output 2 is in state false
echo: checking output 3 is in state false
echo: waiting until just before the timeout
echo: checking the lamps are still set
echo: checking output 0 is in state true
echo: checking output 1 is in state true
echo: checking output 2 is in state false
echo: checking output 3 is in state false
echo: waiting until just after the timeout
ColdFrame: INFO: posting a COLDFRAME.PROJECT.EVENTS.HELD_EVENT
ColdFrame: INFO: dispatching a COLDFRAME.PROJECT.EVENTS.HELD_EVENT
ColdFrame: INFO: dispatching a HOUSE_MANAGEMENT.TIMED_BUTTON.TIMEOUT: state HOUSE_MANAGEMENT.TIMED_BUTTON.SET
ColdFrame: INFO: .. new state HOUSE_MANAGEMENT.TIMED_BUTTON.RESET
echo: checking the lamps are now clear
echo: checking output 0 is in state false
echo: checking output 1 is in state false
echo: checking output 2 is in state false
echo: checking output 3 is in state false
echo: done.

[simonjwright]

On 5 May 2021, at 11:53, Alex Proudfoot ***@***.***> wrote: This doesn't happen on Linux Mint. Here is the symptom.

Presumably it *does* happen? with the 'native' tcl?

[AlexProudfoot]

No. It doesn’t happen on Linux at all. I replaced native Tcl with ActiveTcl to see if ActiveTcl was the cause. I think it’s probably a Linux v. Windows/Cygwin issue.

[simonjwright]

This is a timing issue.

What’s supposed to happen is, the script waits until 5 ms before the ColdFrame turn-out-the-lights timeout fires, checks that nothing’s changed, waits until 5 ms after the timeout has expired, checks that the lights have in fact been turned off.

Unfortunately, the script is a bit chatty, and the timing goes to pot.

I never had this problem back in the day, but I suspect my scripts were a lot less chatty. Also, the timing works fine on macOS and Linux!

I’ve posted an adjusted script in cdcbe87. Note also script renamings in 7dcd62e.

Aside from Real Life (not that there’s a lot of that about), this has taken a while to sort out because running on Windows/Cygwin is a Real Pain. I hope you’ll find cedc2ac and 44a9303 work for you, particularly the latter, which was .. interesting.

[AlexProudfoot]

Linux Mint 19 VM

alex@mint-vm$ ./house_management-scripting house_management-scripting.tcl
script starting
echo: checking that all lamps are off
echo: checking output 0 is in state false
echo: checking output 1 is in state false
echo: checking output 2 is in state false
echo: checking output 3 is in state false
echo: pushing button 0
ColdFrame: INFO: posting a HOUSE_MANAGEMENT.BUTTON.DIGITAL_IO_INPUT_SIGNAL_STATE.CALLBACK_EVENT
ColdFrame: INFO: dispatching a HOUSE_MANAGEMENT.BUTTON.DIGITAL_IO_INPUT_SIGNAL_STATE.CALLBACK_EVENT
ColdFrame: INFO: setting a Timer for a HOUSE_MANAGEMENT.TIMED_BUTTON.TIMEOUT, delay 5.000000000
echo: lamps 0 and 1 should be set
echo: checking output 0 is in state true
echo: checking output 1 is in state true
echo: checking output 2 is in state false
echo: checking output 3 is in state false
echo: waiting until 100 ms before the timeout
  to check that the lamps are still set
echo: checking the lamps are still set; then,
  wait until 5 ms after the timeout to check that
  they're clear
echo: checking output 0 is in state true
echo: checking output 1 is in state true
echo: checking output 2 is in state false
echo: checking output 3 is in state false
ColdFrame: INFO: posting a COLDFRAME.PROJECT.EVENTS.HELD_EVENT
ColdFrame: INFO: dispatching a COLDFRAME.PROJECT.EVENTS.HELD_EVENT
ColdFrame: INFO: dispatching a HOUSE_MANAGEMENT.TIMED_BUTTON.TIMEOUT: state HOUSE_MANAGEMENT.TIMED_BUTTON.SET
ColdFrame: INFO: .. new state HOUSE_MANAGEMENT.TIMED_BUTTON.RESET
echo: checking the lamps are now clear
echo: checking output 0 is in state false
echo: checking output 1 is in state false
echo: checking output 2 is in state false
echo: checking output 3 is in state false
echo: done.
alex@mint-vm$ 

[AlexProudfoot]

Cygwin

Alex@LAPTOP-0BHHRD0H ~/Tools/coldframe/examples
$ ./house_management-scripting house_management-scripting.tcl
script starting
echo: checking that all lamps are off
echo: checking output 0 is in state false
echo: checking output 1 is in state false
echo: checking output 2 is in state false
echo: checking output 3 is in state false
echo: pushing button 0
ColdFrame: INFO: posting a HOUSE_MANAGEMENT.BUTTON.DIGITAL_IO_INPUT_SIGNAL_STATE
.CALLBACK_EVENT
ColdFrame: INFO: dispatching a HOUSE_MANAGEMENT.BUTTON.DIGITAL_IO_INPUT_SIGNAL_S
TATE.CALLBACK_EVENT
ColdFrame: INFO: setting a Timer for a HOUSE_MANAGEMENT.TIMED_BUTTON.TIMEOUT, de
lay 5.000000000
echo: lamps 0 and 1 should be set
echo: checking output 0 is in state true
echo: checking output 1 is in state true
echo: checking output 2 is in state false
echo: checking output 3 is in state false
echo: waiting until 100 ms before the timeout
  to check that the lamps are still set
echo: checking the lamps are still set; then,
  wait until 5 ms after the timeout to check that
  they're clear
echo: checking output 0 is in state true
echo: checking output 1 is in state true
echo: checking output 2 is in state false
echo: checking output 3 is in state false
ColdFrame: INFO: posting a COLDFRAME.PROJECT.EVENTS.HELD_EVENT
ColdFrame: INFO: dispatching a COLDFRAME.PROJECT.EVENTS.HELD_EVENT
ColdFrame: INFO: dispatching a HOUSE_MANAGEMENT.TIMED_BUTTON.TIMEOUT: state HOUS
E_MANAGEMENT.TIMED_BUTTON.SET
ColdFrame: INFO: .. new state HOUSE_MANAGEMENT.TIMED_BUTTON.RESET
echo: checking the lamps are now clear
echo: checking output 0 is in state false
echo: checking output 1 is in state false
echo: checking output 2 is in state false
echo: checking output 3 is in state false
echo: done.

Alex@LAPTOP-0BHHRD0H ~/Tools/coldframe/examples
$

[AlexProudfoot]

However, also on Cygwin (1 minute later) ...

Alex@LAPTOP-0BHHRD0H ~/Tools/coldframe/examples
$ ./house_management-scripting house_management-scripting.tcl
script starting
echo: checking that all lamps are off
echo: checking output 0 is in state false
echo: checking output 1 is in state false
echo: checking output 2 is in state false
echo: checking output 3 is in state false
echo: pushing button 0
ColdFrame: INFO: posting a HOUSE_MANAGEMENT.BUTTON.DIGITAL_IO_INPUT_SIGNAL_STATE
.CALLBACK_EVENT
ColdFrame: INFO: dispatching a HOUSE_MANAGEMENT.BUTTON.DIGITAL_IO_INPUT_SIGNAL_S
TATE.CALLBACK_EVENT
ColdFrame: INFO: setting a Timer for a HOUSE_MANAGEMENT.TIMED_BUTTON.TIMEOUT, de
lay 5.000000000
echo: lamps 0 and 1 should be set
echo: checking output 0 is in state true
echo: checking output 1 is in state true
echo: checking output 2 is in state false
echo: checking output 3 is in state false
echo: waiting until 100 ms before the timeout
  to check that the lamps are still set
echo: checking the lamps are still set; then,
  wait until 5 ms after the timeout to check that
  they're clear
echo: checking output 0 is in state true
echo: checking output 1 is in state true
echo: checking output 2 is in state false
echo: checking output 3 is in state false
echo: checking the lamps are now clearColdFrame: INFO: posting a COLDFRAME.PROJE
CT.EVENTS.HELD_EVENT

ColdFrame: INFO: dispatching a COLDFRAME.PROJECT.EVENTS.HELD_EVENT
ColdFrame: INFO: dispatching a HOUSE_MANAGEMENT.TIMED_BUTTON.TIMEOUT: state HOUS
E_MANAGEMENT.TIMED_BUTTON.SET
ColdFrame: INFO: .. new state HOUSE_MANAGEMENT.TIMED_BUTTON.RESET
house_management-scripting.tcl:65: digital_io.set called 0 times, expected  2
    while executing
"go"
    (file "house_management-scripting.tcl" line 70)

Alex@LAPTOP-0BHHRD0H ~/Tools/coldframe/examples
$

[simonjwright]

Try commenting out this line in

# Check the settings of all 4 output signals. This is probably more
# verbose than you'd need.
proc check-outputs {s0 s1 s2 s3} {
    proc check-output {switch state} {
        echo "checking output $switch is in state $state"
        check-boolean-for-digital_io.output_signal \
            digital_io.set \
            o $switch \
            to_state $state
    }
    check-output 0 $s0
    check-output 1 $s1
    check-output 2 $s2
    check-output 3 $s3
}

Not only is it more verbose than we need, but in this case it’s breaking the test if output is slow and the model overtakes the test.

[AlexProudfoot]

New output.

Alex@LAPTOP-0BHHRD0H ~/Tools/coldframe/examples
$ ./house_management-scripting house_management-scripting.tcl
script starting
echo: checking that all lamps are off
echo: pushing button 0
ColdFrame: INFO: posting a HOUSE_MANAGEMENT.BUTTON.DIGITAL_IO_INPUT_SIGNAL_STATE
.CALLBACK_EVENT
ColdFrame: INFO: dispatching a HOUSE_MANAGEMENT.BUTTON.DIGITAL_IO_INPUT_SIGNAL_S
TATE.CALLBACK_EVENT
ColdFrame: INFO: setting a Timer for a HOUSE_MANAGEMENT.TIMED_BUTTON.TIMEOUT, de
lay 5.000000000
echo: lamps 0 and 1 should be set
echo: waiting until 100 ms before the timeout
  to check that the lamps are still set
echo: checking the lamps are still set; then,
  wait until 5 ms after the timeout to check that
  they're clear
ColdFrame: INFO: posting a COLDFRAME.PROJECT.EVENTS.HELD_EVENTecho: checking the
 lamps are now clear

ColdFrame: INFO: dispatching a COLDFRAME.PROJECT.EVENTS.HELD_EVENT
ColdFrame: INFO: dispatching a HOUSE_MANAGEMENT.TIMED_BUTTON.TIMEOUT: state HOUS
E_MANAGEMENT.TIMED_BUTTON.SET
ColdFrame: INFO: .. new state HOUSE_MANAGEMENT.TIMED_BUTTON.RESET
house_management-scripting.tcl:65: digital_io.set called 0 times, expected  2
    while executing
"go"
    (file "house_management-scripting.tcl" line 70)

Alex@LAPTOP-0BHHRD0H ~/Tools/coldframe/examples
$

[AlexProudfoot]

But on second attempt ...

Alex@LAPTOP-0BHHRD0H ~/Tools/coldframe/examples
$ ./house_management-scripting house_management-scripting.tcl
script starting
echo: checking that all lamps are off
echo: pushing button 0
ColdFrame: INFO: posting a HOUSE_MANAGEMENT.BUTTON.DIGITAL_IO_INPUT_SIGNAL_STATE
.CALLBACK_EVENT
ColdFrame: INFO: dispatching a HOUSE_MANAGEMENT.BUTTON.DIGITAL_IO_INPUT_SIGNAL_S
TATE.CALLBACK_EVENT
ColdFrame: INFO: setting a Timer for a HOUSE_MANAGEMENT.TIMED_BUTTON.TIMEOUT, de
lay 5.000000000
echo: lamps 0 and 1 should be set
echo: waiting until 100 ms before the timeout
  to check that the lamps are still set
echo: checking the lamps are still set; then,
  wait until 5 ms after the timeout to check that
  they're clear
ColdFrame: INFO: posting a COLDFRAME.PROJECT.EVENTS.HELD_EVENT
ColdFrame: INFO: dispatching a COLDFRAME.PROJECT.EVENTS.HELD_EVENT
ColdFrame: INFO: dispatching a HOUSE_MANAGEMENT.TIMED_BUTTON.TIMEOUT: state HOUS
E_MANAGEMENT.TIMED_BUTTON.SET
ColdFrame: INFO: .. new state HOUSE_MANAGEMENT.TIMED_BUTTON.RESET
echo: checking the lamps are now clear
echo: done.

Alex@LAPTOP-0BHHRD0H ~/Tools/coldframe/examples
$

[simonjwright]

Still working on this: arranging to send output text to a synchronized queue, with the actual output done in a lower-priority task.

A bit cobbled-together at the moment.

[simonjwright]

I’m afraid I’ve now forgotten why the synchronised queue scheme didn’t work out, sorry.