Semaphore's Not Working

🚧 Developers Broken-code
1

I have a short semaphore app that I used a month ago or so to test semaphore's and it ran fine. I just ran it again and it does not run properly. The app code:

import groovy.transform.Field

@Field static Number RunNumber = 1

definition(
    name: "SemaphoreTest1",
    namespace: "Example",
    author: "Hubitat Example",
    description: "Test Semaphors",
    category: "Convenience",
    iconUrl: "",
    iconX2Url: "",
    singleThreaded: false)

def installed() {
    log.debug "installed()"
    updated()
}

def updated() {
    log.debug "updated(" + RunNumber + ")"
    RunNumber++
    trace()
}

def uninstalled() {
    log.debug "uninstalled()"
}

def trace()
{
    [0,1,2,3].each { runInMillis(0, "MySemaphore", [overwrite: false, data: "Test${it}"]) }
}

def MySemaphore(String Line) {
    
    log.debug "BEFORE synchronized()"
    
    synchronized(this.MySemaphore) {
        
        log.debug "*** ENTER MYSEMAPHORE ***"
        log.debug Line
        
        pauseExecution(1000)    // pause for a second
        
        log.debug "*** EXIT MYSEMAPHORE ***"
    }
}

I then installed it and hit Done and then went back in to the app and hit Done again:

app:10492024-03-20 07:08:23.180 PMdebug*** EXIT MYSEMAPHORE ***
app:10492024-03-20 07:08:22.182 PMdebugTest1
app:10492024-03-20 07:08:22.179 PMdebug*** ENTER MYSEMAPHORE ***
app:10492024-03-20 07:08:22.177 PMdebug*** EXIT MYSEMAPHORE ***
app:10492024-03-20 07:08:21.179 PMdebugTest2
app:10492024-03-20 07:08:21.176 PMdebug*** ENTER MYSEMAPHORE ***
app:10492024-03-20 07:08:21.173 PMdebug*** EXIT MYSEMAPHORE ***
app:10492024-03-20 07:08:20.175 PMdebugTest3
app:10492024-03-20 07:08:20.173 PMdebug*** ENTER MYSEMAPHORE ***
app:10492024-03-20 07:08:20.170 PMdebug*** EXIT MYSEMAPHORE ***
app:10492024-03-20 07:08:19.373 PMdebugBEFORE synchronized()
app:10492024-03-20 07:08:19.275 PMdebugBEFORE synchronized()
app:10492024-03-20 07:08:19.220 PMdebugBEFORE synchronized()
app:10492024-03-20 07:08:19.172 PMdebugTest0
app:10492024-03-20 07:08:19.169 PMdebug*** ENTER MYSEMAPHORE ***
app:10492024-03-20 07:08:19.166 PMdebugBEFORE synchronized()
app:10492024-03-20 07:08:19.069 PMdebugupdated(2)
app:10492024-03-20 07:08:12.611 PMdebug*** EXIT MYSEMAPHORE ***
app:10492024-03-20 07:08:11.613 PMdebugTest2
app:10492024-03-20 07:08:11.610 PMdebug*** ENTER MYSEMAPHORE ***
app:10492024-03-20 07:08:11.607 PMdebug*** EXIT MYSEMAPHORE ***
app:10492024-03-20 07:08:10.610 PMdebugTest3
app:10492024-03-20 07:08:10.606 PMdebug*** ENTER MYSEMAPHORE ***
app:10492024-03-20 07:08:10.601 PMdebug*** EXIT MYSEMAPHORE ***
app:10492024-03-20 07:08:09.694 PMdebugBEFORE synchronized()
app:10492024-03-20 07:08:09.642 PMdebugBEFORE synchronized()
app:10492024-03-20 07:08:09.598 PMdebugTest1
app:10492024-03-20 07:08:09.595 PMdebug*** ENTER MYSEMAPHORE ***
app:10492024-03-20 07:08:09.592 PMdebugBEFORE synchronized()
app:10492024-03-20 07:08:09.362 PMdebugupdated(1)
app:10492024-03-20 07:08:09.359 PMdebuginstalled()

The first run (between updated(1) and updated(2)) is missing "Test0" output. the second run (above updated(2)) is correct and shows Test0 thru Test3. All runs after the first run are correct. The first run is no longer working. I also did the same test and used the sem object instead of using synchronized():

import java.util.concurrent.Semaphore
import groovy.transform.Field

@Field static Semaphore sem = new Semaphore(1)
@Field static RunNumber = 1

definition(
    name: "SemaphoreTest2",
    namespace: "Example",
    author: "Hubitat Example",
    description: "Test Semaphors",
    category: "Convenience",
    iconUrl: "",
    iconX2Url: "",
    singleThreaded: false)

def installed() {
    log.debug "installed"
    updated()
}

def updated() {
    log.debug "updated(" + RunNumber + ")"
    RunNumber++
    trace()
}

def uninstalled() {
    log.debug "uninstalled()"
}

def trace()
{
    [0,1,2,3].each { runInMillis(0, "MySemaphore", [overwrite: false, data: "Test${it}"]) }
}

def MySemaphore(String Line) {
    
    log.debug "BEFORE synchronized()"
    
//    synchronized(this.MySemaphore) {
    sem.acquire()    
    
        log.debug "*** ENTER MYSEMAPHORE ***"
        log.debug Line
        
        pauseExecution(1000)    // pause for a second
        
        log.debug "*** EXIT MYSEMAPHORE ***"
//    }
    sem.release()
}

And got similar results (This scenario was also missing Test1 along with Test0).

I ran these Apps in 2.3.8.128 and if you run them and it runs correctly please provide me your version number.

Thanks

1 Like
2

I just restored version 2.3.7.146 and got the same thing??? I am questioning myself as to saying that I tested this prior and everything was OK!!?? HELP

3

I changed SemaphoreTest1 above to the following:

import groovy.transform.Field

@Field static Number RunNumber = 1

definition(
    name: "SemaphoreTest3",
    namespace: "Example",
    author: "Hubitat Example",
    description: "Test Semaphors",
    category: "Convenience",
    iconUrl: "",
    iconX2Url: "",
    singleThreaded: false)

def installed() {
    log.debug "installed()"
    updated()
}

def updated() {
    log.debug "updated(" + RunNumber + ")"
    RunNumber++
    trace()
}

def uninstalled() {
    log.debug "uninstalled()"
}

def trace()
{
//   [0,1,2,3].each { runInMillis(0, "MySemaphore", [overwrite: false, data: "Test${it}"]) }
     
     for (int i = 0; i < 4; i++) {
          MySemaphore("Test" + i)   
     }
}

def MySemaphore(String Line) {
    
    log.debug "BEFORE synchronized()"
    
    synchronized(this.MySemaphore) {
        
        log.debug "*** ENTER MYSEMAPHORE ***"
        log.debug Line
        
        pauseExecution(1000)    // pause for a second
        
        log.debug "*** EXIT MYSEMAPHORE ***"
    }
}

And the output is like run #2 above which is exactly what it should be. Can someone please explain why this change produces the correct outcome and the original version does not.

Thanks

4

I'll start by saying I'm not someone who can answer your question with any authority.... Sorry.... I'm a data guy..... I can only speculate...

My gut feel in the difference between your OP, middle attempt and your latest code is that your early use of ".each" and "runInMillis", in particular runInMillis, was a "set and forget" style call, leaving it up to the Quartz schedular or whatever may process that scheduled task. Whereas your later (most recent) code uses a for-loop, which I am suspecting will wait for the "MySemaphore()" call to complete before moving on to the next call to MySemaphore() (negating the need for a semaphore if I am correct).

My guess for why this latest code behaves like attempt two is.... :man_shrugging:

2 Likes
5

I'm inclined to blame runInMillis(0), too. It's a call to an imprecise scheduler that takes some time to do its work. By the time that work is done, the scheduled event is in the past.

3 Likes
6

Good thought. I will fool around with it and see what happens. It is interesting that the first time I install the App it doesn't work but from then on when I go in and hit Done it will always work?!

Thanks

7

I did fool around a little more based on your suggestion and found that if I changed the scheduling delay when would I get output of Test0 thru 3:

ms = 1 ==> I get Test2 and 3 output
ms=10 ==> I get Test2 and 3 output
ms=100 ==> I get Test1, 2, and 3 output
ms>110 ==> I get Test0 thru 3 (it works!)

I guess this makes sense if the App is not completely setup until the Install() exits... and then the Hubitat OS takes a little over 100ms to complete the internal structures/tables/etc (I have a C8). To make sure of this I added a one second delay prior to the scheduling (set to 0ms) in the Install() and it performed the same way.

I guess this means that people that want to code/checkout/debug their App should (to be safe) schedule another routine perhaps a second in the future in the Install() and then in that other routine do whatever they where tempted to do in the Install() routine.

I appreciate your help... Thanks