Doorbell - Double event trigger

[davegravy]

I have a doorbell connected to my GC-100 on input module 4, sensor 1 (shows as 4:1 in the log)

I've created a respond-to event which fires when the sensor is tripped and sends my phone a notification. For some reason, each doorbell push triggers this event twice - creating a double notification - and i'd like to stop this from happening. Here's a log of a single button press and release:

Code: [Select]

10 01/18/14 16:02:23.138 Reply received from GC100: statechange,4:1,1 <0xb5f62b70>
10 01/18/14 16:02:23.139 statechange Reply interpreted as module: 4:1 change to 1 <0xb5f62b70>
10 01/18/14 16:02:23.139 statechange Reply: found module of type SENSOR, 1 <0xb5f62b70>
10 01/18/14 16:02:23.139 statechange Reply: testing Command_Impl2 Dev #, 4:1 (state 1) default state:  <0xb5f62b70>
10 01/18/14 16:02:23.139 statechange Reply: matches exactly in m:s format <0xb5f62b70>
10 01/18/14 16:02:23.139 statechange Reply: testing Command_Impl2 Dev #, 4:2 (state 1) default state:  <0xb5f62b70>
10 01/18/14 16:02:23.139 statechange Reply: testing Command_Impl2 Dev #, 4:3 (state 1) default state:  <0xb5f62b70>
10 01/18/14 16:02:23.139 statechange Reply: testing Command_Impl2 Dev #, 5:1 (state 1) default state:  <0xb5f62b70>
10 01/18/14 16:02:23.139 statechange Reply: testing Command_Impl2 Dev #, 5:2 (state 1) default state:  <0xb5f62b70>
10 01/18/14 16:02:23.139 statechange Reply: testing Command_Impl2 Dev #, 5:3 (state 1) default state:  <0xb5f62b70>
21 01/18/14 16:02:23.139 lock(0x9ea41a4) (>956) MessageQueue: Command_Impl.cpp:845  <0xb5f62b70>
21 01/18/14 16:02:23.139 acquired(0x9ea41a4) #0 (>956) MessageQueue Command_Impl.cpp:845  <0xb5f62b70>
21 01/18/14 16:02:23.139 unlock(0x9ea41a4) #0 (>956) MessageQueue: Command_Impl.cpp:845  <0xb5f62b70>
21 01/18/14 16:02:23.139 removed from map (0x9ea41a4) #1 (>956) MessageQueue: Command_Impl.cpp:845  was: 3 size, now 2 Rel: Y Got: Y <0xb5f62b70>
21 01/18/14 16:02:23.139 lock(0x9ea41a4) (>957) MessageQueue: Command_Impl.cpp:845  <0xb5f62b70>
21 01/18/14 16:02:23.139 end cond wait Command_Impl.cpp:852 (0x9ea41a4)  <0xb7765b70>
21 01/18/14 16:02:23.149 unlock(0x9ea41a4) #0 (>149) MessageQueue: Command_Impl.cpp:852  <0xb7765b70>
10 01/18/14 16:02:23.149 Socket::SendMessage type 2 id 9 from 234 to 0 <0xb7765b70>
21 01/18/14 16:02:23.149 acquired(0x9ea41a4) #0 (>957) MessageQueue Command_Impl.cpp:845  <0xb5f62b70>
21 01/18/14 16:02:23.150 unlock(0x9ea41a4) #0 (>957) MessageQueue: Command_Impl.cpp:845  <0xb5f62b70>
21 01/18/14 16:02:23.150 removed from map (0x9ea41a4) #0 (>957) MessageQueue: Command_Impl.cpp:845  was: 3 size, now 2 Rel: Y Got: Y <0xb5f62b70>
10 01/18/14 16:02:23.150 Sending command getstate,4:1
 <0xb5f62b70>
21 01/18/14 16:02:23.150 relocking (0x9ea41a4) (>149)  <0xb7765b70>
21 01/18/14 16:02:23.150 lock(0x9ea41a4) (>149) MessageQueue: Command_Impl.cpp:852  <0xb7765b70>
21 01/18/14 16:02:23.150 acquired(0x9ea41a4) #0 (>149) MessageQueue Command_Impl.cpp:852  <0xb7765b70>
21 01/18/14 16:02:23.150 unlock(0x9ea41a4) #0 (>149) MessageQueue: Command_Impl.cpp:852  <0xb7765b70>
10 01/18/14 16:02:23.150 Socket::SendMessage type 2 id 9 from 240 to 0 <0xb7765b70>
21 01/18/14 16:02:23.150 relocking (0x9ea41a4) (>149)  <0xb7765b70>
21 01/18/14 16:02:23.150 lock(0x9ea41a4) (>149) MessageQueue: Command_Impl.cpp:852  <0xb7765b70>
21 01/18/14 16:02:23.150 acquired(0x9ea41a4) #0 (>149) MessageQueue Command_Impl.cpp:852  <0xb7765b70>
21 01/18/14 16:02:23.150 start cond wait Command_Impl.cpp:852 (0x9ea41a4)  <0xb7765b70>
10 01/18/14 16:02:23.219 Receive string: MESSAGE 77             <0xb6f64b70>
10 01/18/14 16:02:23.219 Received MESSAGE 77             0x9ea4058 device: 230 <0xb6f64b70>
10 01/18/14 16:02:23.219 Received Message type 1 ID 192 from 12 to 232 (device: 230) resp 0 <0xb6f64b70>
10 01/18/14 16:02:23.219 Message for Generic Relays RELAY 3:2 passed to Relay <0xb6f64b70>
10 01/18/14 16:02:23.219 Relay Pwr.: target device is 232 <0xb6f64b70>
10 01/18/14 16:02:23.219 gc100::GetPinDeviceID got pin 3:2 device 232 <0xb6f64b70>
10 01/18/14 16:02:23.219 Relay Pwr.: This device is 232 <0xb6f64b70>
21 01/18/14 16:02:23.219 lock(0x9ea4408) (>983) gc100: gc100.cpp:1198  <0xb6f64b70>
21 01/18/14 16:02:23.219 acquired(0x9ea4408) #0 (>983) gc100 gc100.cpp:1198  <0xb6f64b70>
10 01/18/14 16:02:23.219 Relay Pwr.: Found 3:2 in module map <0xb6f64b70>
10 01/18/14 16:02:23.219 Relay Pwr.: Regardless, module ID is 3:2 <0xb6f64b70>
10 01/18/14 16:02:23.219 Sending command setstate,3:2,1
 <0xb6f64b70>
10 01/18/14 16:02:23.300 EventThread <0xb5f62b70>
10 01/18/14 16:02:23.300 Reply received from GC100: state,4:1,1 <0xb5f62b70>
10 01/18/14 16:02:23.300 statechange Reply interpreted as module: 4:1 change to 1 <0xb5f62b70>
10 01/18/14 16:02:23.300 statechange Reply: found module of type SENSOR, 1 <0xb5f62b70>
10 01/18/14 16:02:23.300 statechange Reply: testing Command_Impl2 Dev #, 4:1 (state 1) default state:  <0xb5f62b70>
10 01/18/14 16:02:23.300 statechange Reply: matches exactly in m:s format <0xb5f62b70>
10 01/18/14 16:02:23.300 statechange Reply: testing Command_Impl2 Dev #, 4:2 (state 1) default state:  <0xb5f62b70>
10 01/18/14 16:02:23.300 statechange Reply: testing Command_Impl2 Dev #, 4:3 (state 1) default state:  <0xb5f62b70>
10 01/18/14 16:02:23.300 statechange Reply: testing Command_Impl2 Dev #, 5:1 (state 1) default state:  <0xb5f62b70>
10 01/18/14 16:02:23.300 statechange Reply: testing Command_Impl2 Dev #, 5:2 (state 1) default state:  <0xb5f62b70>
10 01/18/14 16:02:23.300 statechange Reply: testing Command_Impl2 Dev #, 5:3 (state 1) default state:  <0xb5f62b70>
21 01/18/14 16:02:23.300 lock(0x9ea41a4) (>984) MessageQueue: Command_Impl.cpp:845  <0xb5f62b70>
21 01/18/14 16:02:23.300 acquired(0x9ea41a4) #0 (>984) MessageQueue Command_Impl.cpp:845  <0xb5f62b70>
21 01/18/14 16:02:23.300 unlock(0x9ea41a4) #0 (>984) MessageQueue: Command_Impl.cpp:845  <0xb5f62b70>
21 01/18/14 16:02:23.301 removed from map (0x9ea41a4) #0 (>984) MessageQueue: Command_Impl.cpp:845  was: 3 size, now 2 Rel: Y Got: Y <0xb5f62b70>
21 01/18/14 16:02:23.301 lock(0x9ea41a4) (>985) MessageQueue: Command_Impl.cpp:845  <0xb5f62b70>
21 01/18/14 16:02:23.301 acquired(0x9ea41a4) #0 (>985) MessageQueue Command_Impl.cpp:845  <0xb5f62b70>
21 01/18/14 16:02:23.301 unlock(0x9ea41a4) #0 (>985) MessageQueue: Command_Impl.cpp:845  <0xb5f62b70>
21 01/18/14 16:02:23.301 removed from map (0x9ea41a4) #0 (>985) MessageQueue: Command_Impl.cpp:845  was: 3 size, now 2 Rel: Y Got: Y <0xb5f62b70>
21 01/18/14 16:02:23.301 end cond wait Command_Impl.cpp:852 (0x9ea41a4)  <0xb7765b70>
21 01/18/14 16:02:23.301 unlock(0x9ea41a4) #0 (>149) MessageQueue: Command_Impl.cpp:852  <0xb7765b70>
10 01/18/14 16:02:23.301 Socket::SendMessage type 2 id 9 from 234 to 0 <0xb7765b70>
10 01/18/14 16:02:23.301 Socket::SendMessage type 2 id 9 from 240 to 0 <0xb7765b70>
21 01/18/14 16:02:23.301 relocking (0x9ea41a4) (>149)  <0xb7765b70>
21 01/18/14 16:02:23.301 lock(0x9ea41a4) (>149) MessageQueue: Command_Impl.cpp:852  <0xb7765b70>
21 01/18/14 16:02:23.301 acquired(0x9ea41a4) #0 (>149) MessageQueue Command_Impl.cpp:852  <0xb7765b70>
21 01/18/14 16:02:23.301 start cond wait Command_Impl.cpp:852 (0x9ea41a4)  <0xb7765b70>
21 01/18/14 16:02:23.320 unlock(0x9ea4408) #0 (>983) gc100: gc100.cpp:1198  <0xb6f64b70>
21 01/18/14 16:02:23.320 removed from map (0x9ea4408) #0 (>983) gc100: gc100.cpp:1198  was: 2 size, now 1 Rel: Y Got: Y <0xb6f64b70>
10 01/18/14 16:02:23.338 Receive string: MESSAGE 77             <0xb6f64b70>
10 01/18/14 16:02:23.338 Received MESSAGE 77             0x9ea4058 device: 230 <0xb6f64b70>
10 01/18/14 16:02:23.338 Received Message type 1 ID 192 from 12 to 232 (device: 230) resp 0 <0xb6f64b70>
10 01/18/14 16:02:23.338 Message for Generic Relays RELAY 3:2 passed to Relay <0xb6f64b70>
10 01/18/14 16:02:23.338 Relay Pwr.: target device is 232 <0xb6f64b70>
10 01/18/14 16:02:23.338 gc100::GetPinDeviceID got pin 3:2 device 232 <0xb6f64b70>
10 01/18/14 16:02:23.338 Relay Pwr.: This device is 232 <0xb6f64b70>
21 01/18/14 16:02:23.338 lock(0x9ea4408) (>1012) gc100: gc100.cpp:1198  <0xb6f64b70>
21 01/18/14 16:02:23.338 acquired(0x9ea4408) #0 (>1012) gc100 gc100.cpp:1198  <0xb6f64b70>
10 01/18/14 16:02:23.338 Relay Pwr.: Found 3:2 in module map <0xb6f64b70>
10 01/18/14 16:02:23.338 Relay Pwr.: Regardless, module ID is 3:2 <0xb6f64b70>
10 01/18/14 16:02:23.338 Sending command setstate,3:2,1
 <0xb6f64b70>
10 01/18/14 16:02:23.351 EventThread <0xb5f62b70>
10 01/18/14 16:02:23.351 Reply received from GC100: state,3:2,1 <0xb5f62b70>
10 01/18/14 16:02:23.351 statechange Reply interpreted as module: 3:2 change to 1 <0xb5f62b70>
10 01/18/14 16:02:23.351 statechange Reply: found module of type RELAY, 2 <0xb5f62b70>
10 01/18/14 16:02:23.351 statechange Reply: testing Command_Impl2 Dev #, 4:1 (state 1) default state:  <0xb5f62b70>
10 01/18/14 16:02:23.351 statechange Reply: testing Command_Impl2 Dev #, 4:2 (state 1) default state:  <0xb5f62b70>
10 01/18/14 16:02:23.351 statechange Reply: testing Command_Impl2 Dev #, 4:3 (state 1) default state:  <0xb5f62b70>
10 01/18/14 16:02:23.351 statechange Reply: testing Command_Impl2 Dev #, 5:1 (state 1) default state:  <0xb5f62b70>
10 01/18/14 16:02:23.351 statechange Reply: testing Command_Impl2 Dev #, 5:2 (state 1) default state:  <0xb5f62b70>
10 01/18/14 16:02:23.351 statechange Reply: testing Command_Impl2 Dev #, 5:3 (state 1) default state:  <0xb5f62b70>
10 01/18/14 16:02:23.351 statechange Reply: no exact match in m:s format, trying global pin number <0xb5f62b70>
05 01/18/14 16:02:23.351 statechange Reply: Sorry, after all that searching, I can't determine which child device should be sent the pin_changed <0xb5f62b70>
10 01/18/14 16:02:23.404 EventThread <0xb5f62b70>
10 01/18/14 16:02:23.405 Reply received from GC100: state,3:2,1 <0xb5f62b70>
10 01/18/14 16:02:23.405 statechange Reply interpreted as module: 3:2 change to 1 <0xb5f62b70>
10 01/18/14 16:02:23.405 statechange Reply: found module of type RELAY, 2 <0xb5f62b70>
10 01/18/14 16:02:23.405 statechange Reply: testing Command_Impl2 Dev #, 4:1 (state 1) default state:  <0xb5f62b70>
10 01/18/14 16:02:23.405 statechange Reply: testing Command_Impl2 Dev #, 4:2 (state 1) default state:  <0xb5f62b70>
10 01/18/14 16:02:23.405 statechange Reply: testing Command_Impl2 Dev #, 4:3 (state 1) default state:  <0xb5f62b70>
10 01/18/14 16:02:23.405 statechange Reply: testing Command_Impl2 Dev #, 5:1 (state 1) default state:  <0xb5f62b70>
10 01/18/14 16:02:23.405 statechange Reply: testing Command_Impl2 Dev #, 5:2 (state 1) default state:  <0xb5f62b70>
10 01/18/14 16:02:23.405 statechange Reply: testing Command_Impl2 Dev #, 5:3 (state 1) default state:  <0xb5f62b70>
10 01/18/14 16:02:23.405 statechange Reply: no exact match in m:s format, trying global pin number <0xb5f62b70>
05 01/18/14 16:02:23.405 statechange Reply: Sorry, after all that searching, I can't determine which child device should be sent the pin_changed <0xb5f62b70>
21 01/18/14 16:02:23.438 unlock(0x9ea4408) #0 (>1012) gc100: gc100.cpp:1198  <0xb6f64b70>
21 01/18/14 16:02:23.439 removed from map (0x9ea4408) #0 (>1012) gc100: gc100.cpp:1198  was: 2 size, now 1 Rel: Y Got: Y <0xb6f64b70>
10 01/18/14 16:02:23.455 EventThread <0xb5f62b70>
10 01/18/14 16:02:24.569 Reply received from GC100: statechange,4:1,0 <0xb5f62b70>
10 01/18/14 16:02:24.570 statechange Reply interpreted as module: 4:1 change to 0 <0xb5f62b70>
10 01/18/14 16:02:24.570 statechange Reply: found module of type SENSOR, 1 <0xb5f62b70>
10 01/18/14 16:02:24.570 statechange Reply: testing Command_Impl2 Dev #, 4:1 (state 0) default state:  <0xb5f62b70>
10 01/18/14 16:02:24.570 statechange Reply: matches exactly in m:s format <0xb5f62b70>
10 01/18/14 16:02:24.570 statechange Reply: testing Command_Impl2 Dev #, 4:2 (state 0) default state:  <0xb5f62b70>
10 01/18/14 16:02:24.570 statechange Reply: testing Command_Impl2 Dev #, 4:3 (state 0) default state:  <0xb5f62b70>
10 01/18/14 16:02:24.570 statechange Reply: testing Command_Impl2 Dev #, 5:1 (state 0) default state:  <0xb5f62b70>
10 01/18/14 16:02:24.570 statechange Reply: testing Command_Impl2 Dev #, 5:2 (state 0) default state:  <0xb5f62b70>
10 01/18/14 16:02:24.570 statechange Reply: testing Command_Impl2 Dev #, 5:3 (state 0) default state:  <0xb5f62b70>
21 01/18/14 16:02:24.570 lock(0x9ea41a4) (>1014) MessageQueue: Command_Impl.cpp:845  <0xb5f62b70>
21 01/18/14 16:02:24.570 acquired(0x9ea41a4) #0 (>1014) MessageQueue Command_Impl.cpp:845  <0xb5f62b70>
21 01/18/14 16:02:24.570 unlock(0x9ea41a4) #0 (>1014) MessageQueue: Command_Impl.cpp:845  <0xb5f62b70>
21 01/18/14 16:02:24.570 end cond wait Command_Impl.cpp:852 (0x9ea41a4)  <0xb7765b70>
21 01/18/14 16:02:24.570 unlock(0x9ea41a4) #0 (>149) MessageQueue: Command_Impl.cpp:852  <0xb7765b70>
10 01/18/14 16:02:24.570 Socket::SendMessage type 2 id 9 from 234 to 0 <0xb7765b70>
21 01/18/14 16:02:24.571 relocking (0x9ea41a4) (>149)  <0xb7765b70>
21 01/18/14 16:02:24.571 lock(0x9ea41a4) (>149) MessageQueue: Command_Impl.cpp:852  <0xb7765b70>
21 01/18/14 16:02:24.571 acquired(0x9ea41a4) #0 (>149) MessageQueue Command_Impl.cpp:852  <0xb7765b70>
21 01/18/14 16:02:24.571 start cond wait Command_Impl.cpp:852 (0x9ea41a4)  <0xb7765b70>
21 01/18/14 16:02:24.570 removed from map (0x9ea41a4) #1 (>1014) MessageQueue: Command_Impl.cpp:845  was: 3 size, now 2 Rel: Y Got: Y <0xb5f62b70>
21 01/18/14 16:02:24.580 lock(0x9ea41a4) (>1016) MessageQueue: Command_Impl.cpp:845  <0xb5f62b70>
21 01/18/14 16:02:24.581 acquired(0x9ea41a4) #0 (>1016) MessageQueue Command_Impl.cpp:845  <0xb5f62b70>
21 01/18/14 16:02:24.581 end cond wait Command_Impl.cpp:852 (0x9ea41a4)  <0xb7765b70>
21 01/18/14 16:02:24.581 unlock(0x9ea41a4) #1 (>149) MessageQueue: Command_Impl.cpp:852  <0xb7765b70>
10 01/18/14 16:02:24.581 Socket::SendMessage type 2 id 9 from 240 to 0 <0xb7765b70>
21 01/18/14 16:02:24.581 relocking (0x9ea41a4) (>149)  <0xb7765b70>
21 01/18/14 16:02:24.581 lock(0x9ea41a4) (>149) MessageQueue: Command_Impl.cpp:852  <0xb7765b70>
21 01/18/14 16:02:24.581 acquired(0x9ea41a4) #1 (>149) MessageQueue Command_Impl.cpp:852  <0xb7765b70>
21 01/18/14 16:02:24.581 start cond wait Command_Impl.cpp:852 (0x9ea41a4)  <0xb7765b70>
21 01/18/14 16:02:24.581 unlock(0x9ea41a4) #0 (>1016) MessageQueue: Command_Impl.cpp:845  <0xb5f62b70>
21 01/18/14 16:02:24.581 removed from map (0x9ea41a4) #0 (>1016) MessageQueue: Command_Impl.cpp:845  was: 3 size, now 2 Rel: Y Got: Y <0xb5f62b70>
10 01/18/14 16:02:24.581 Sending command getstate,4:1
 <0xb5f62b70>
10 01/18/14 16:02:24.629 Receive string: MESSAGE 72             <0xb6f64b70>
10 01/18/14 16:02:24.629 Received MESSAGE 72             0x9ea4058 device: 230 <0xb6f64b70>
10 01/18/14 16:02:24.629 Received Message type 1 ID 193 from 12 to 232 (device: 230) resp 0 <0xb6f64b70>
10 01/18/14 16:02:24.629 Message for Generic Relays RELAY 3:2 passed to Relay <0xb6f64b70>
10 01/18/14 16:02:24.629 Relay Pwr.: target device is 232 <0xb6f64b70>
10 01/18/14 16:02:24.629 gc100::GetPinDeviceID got pin 3:2 device 232 <0xb6f64b70>
10 01/18/14 16:02:24.629 Relay Pwr.: This device is 232 <0xb6f64b70>
21 01/18/14 16:02:24.629 lock(0x9ea4408) (>1041) gc100: gc100.cpp:1198  <0xb6f64b70>
21 01/18/14 16:02:24.629 acquired(0x9ea4408) #0 (>1041) gc100 gc100.cpp:1198  <0xb6f64b70>
10 01/18/14 16:02:24.629 Relay Pwr.: Found 3:2 in module map <0xb6f64b70>
10 01/18/14 16:02:24.629 Relay Pwr.: Regardless, module ID is 3:2 <0xb6f64b70>
10 01/18/14 16:02:24.629 Sending command setstate,3:2,0
 <0xb6f64b70>
21 01/18/14 16:02:24.730 unlock(0x9ea4408) #0 (>1041) gc100: gc100.cpp:1198  <0xb6f64b70>
21 01/18/14 16:02:24.730 removed from map (0x9ea4408) #0 (>1041) gc100: gc100.cpp:1198  was: 2 size, now 1 Rel: Y Got: Y <0xb6f64b70>
10 01/18/14 16:02:24.731 EventThread <0xb5f62b70>
10 01/18/14 16:02:24.732 Reply received from GC100: state,4:1,0 <0xb5f62b70>
10 01/18/14 16:02:24.732 statechange Reply interpreted as module: 4:1 change to 0 <0xb5f62b70>
10 01/18/14 16:02:24.732 statechange Reply: found module of type SENSOR, 1 <0xb5f62b70>
10 01/18/14 16:02:24.732 statechange Reply: testing Command_Impl2 Dev #, 4:1 (state 0) default state:  <0xb5f62b70>
10 01/18/14 16:02:24.732 statechange Reply: matches exactly in m:s format <0xb5f62b70>
10 01/18/14 16:02:24.732 statechange Reply: testing Command_Impl2 Dev #, 4:2 (state 0) default state:  <0xb5f62b70>
10 01/18/14 16:02:24.732 statechange Reply: testing Command_Impl2 Dev #, 4:3 (state 0) default state:  <0xb5f62b70>
10 01/18/14 16:02:24.732 statechange Reply: testing Command_Impl2 Dev #, 5:1 (state 0) default state:  <0xb5f62b70>
10 01/18/14 16:02:24.732 statechange Reply: testing Command_Impl2 Dev #, 5:2 (state 0) default state:  <0xb5f62b70>
10 01/18/14 16:02:24.732 statechange Reply: testing Command_Impl2 Dev #, 5:3 (state 0) default state:  <0xb5f62b70>
21 01/18/14 16:02:24.732 lock(0x9ea41a4) (>1043) MessageQueue: Command_Impl.cpp:845  <0xb5f62b70>
21 01/18/14 16:02:24.732 acquired(0x9ea41a4) #0 (>1043) MessageQueue Command_Impl.cpp:845  <0xb5f62b70>
21 01/18/14 16:02:24.732 end cond wait Command_Impl.cpp:852 (0x9ea41a4)  <0xb7765b70>
21 01/18/14 16:02:24.732 unlock(0x9ea41a4) #1 (>149) MessageQueue: Command_Impl.cpp:852  <0xb7765b70>
10 01/18/14 16:02:24.732 Socket::SendMessage type 2 id 9 from 234 to 0 <0xb7765b70>
21 01/18/14 16:02:24.733 relocking (0x9ea41a4) (>149)  <0xb7765b70>
21 01/18/14 16:02:24.733 lock(0x9ea41a4) (>149) MessageQueue: Command_Impl.cpp:852  <0xb7765b70>
21 01/18/14 16:02:24.733 acquired(0x9ea41a4) #1 (>149) MessageQueue Command_Impl.cpp:852  <0xb7765b70>
21 01/18/14 16:02:24.733 start cond wait Command_Impl.cpp:852 (0x9ea41a4)  <0xb7765b70>
21 01/18/14 16:02:24.733 unlock(0x9ea41a4) #0 (>1043) MessageQueue: Command_Impl.cpp:845  <0xb5f62b70>
21 01/18/14 16:02:24.733 removed from map (0x9ea41a4) #0 (>1043) MessageQueue: Command_Impl.cpp:845  was: 3 size, now 2 Rel: Y Got: Y <0xb5f62b70>
21 01/18/14 16:02:24.733 lock(0x9ea41a4) (>1045) MessageQueue: Command_Impl.cpp:845  <0xb5f62b70>
21 01/18/14 16:02:24.733 acquired(0x9ea41a4) #0 (>1045) MessageQueue Command_Impl.cpp:845  <0xb5f62b70>
21 01/18/14 16:02:24.733 end cond wait Command_Impl.cpp:852 (0x9ea41a4)  <0xb7765b70>
21 01/18/14 16:02:24.733 unlock(0x9ea41a4) #1 (>149) MessageQueue: Command_Impl.cpp:852  <0xb7765b70>
10 01/18/14 16:02:24.733 Socket::SendMessage type 2 id 9 from 240 to 0 <0xb7765b70>
21 01/18/14 16:02:24.733 relocking (0x9ea41a4) (>149)  <0xb7765b70>
21 01/18/14 16:02:24.733 lock(0x9ea41a4) (>149) MessageQueue: Command_Impl.cpp:852  <0xb7765b70>
21 01/18/14 16:02:24.733 acquired(0x9ea41a4) #1 (>149) MessageQueue Command_Impl.cpp:852  <0xb7765b70>
21 01/18/14 16:02:24.733 start cond wait Command_Impl.cpp:852 (0x9ea41a4)  <0xb7765b70>
21 01/18/14 16:02:24.733 unlock(0x9ea41a4) #0 (>1045) MessageQueue: Command_Impl.cpp:845  <0xb5f62b70>
21 01/18/14 16:02:24.733 removed from map (0x9ea41a4) #0 (>1045) MessageQueue: Command_Impl.cpp:845  was: 3 size, now 2 Rel: Y Got: Y <0xb5f62b70>
10 01/18/14 16:02:24.779 Receive string: MESSAGE 72             <0xb6f64b70>
10 01/18/14 16:02:24.779 Received MESSAGE 72             0x9ea4058 device: 230 <0xb6f64b70>
10 01/18/14 16:02:24.779 Received Message type 1 ID 193 from 12 to 232 (device: 230) resp 0 <0xb6f64b70>
10 01/18/14 16:02:24.780 Message for Generic Relays RELAY 3:2 passed to Relay <0xb6f64b70>
10 01/18/14 16:02:24.780 Relay Pwr.: target device is 232 <0xb6f64b70>
10 01/18/14 16:02:24.780 gc100::GetPinDeviceID got pin 3:2 device 232 <0xb6f64b70>
10 01/18/14 16:02:24.780 Relay Pwr.: This device is 232 <0xb6f64b70>
21 01/18/14 16:02:24.780 lock(0x9ea4408) (>1070) gc100: gc100.cpp:1198  <0xb6f64b70>
21 01/18/14 16:02:24.780 acquired(0x9ea4408) #0 (>1070) gc100 gc100.cpp:1198  <0xb6f64b70>
10 01/18/14 16:02:24.780 Relay Pwr.: Found 3:2 in module map <0xb6f64b70>
10 01/18/14 16:02:24.780 Relay Pwr.: Regardless, module ID is 3:2 <0xb6f64b70>
10 01/18/14 16:02:24.780 Sending command setstate,3:2,0
 <0xb6f64b70>
10 01/18/14 16:02:24.784 EventThread <0xb5f62b70>
10 01/18/14 16:02:24.784 Reply received from GC100: state,3:2,0 <0xb5f62b70>
10 01/18/14 16:02:24.784 statechange Reply interpreted as module: 3:2 change to 0 <0xb5f62b70>
10 01/18/14 16:02:24.784 statechange Reply: found module of type RELAY, 2 <0xb5f62b70>
10 01/18/14 16:02:24.784 statechange Reply: testing Command_Impl2 Dev #, 4:1 (state 0) default state:  <0xb5f62b70>
10 01/18/14 16:02:24.784 statechange Reply: testing Command_Impl2 Dev #, 4:2 (state 0) default state:  <0xb5f62b70>
10 01/18/14 16:02:24.784 statechange Reply: testing Command_Impl2 Dev #, 4:3 (state 0) default state:  <0xb5f62b70>
10 01/18/14 16:02:24.784 statechange Reply: testing Command_Impl2 Dev #, 5:1 (state 0) default state:  <0xb5f62b70>
10 01/18/14 16:02:24.784 statechange Reply: testing Command_Impl2 Dev #, 5:2 (state 0) default state:  <0xb5f62b70>
10 01/18/14 16:02:24.784 statechange Reply: testing Command_Impl2 Dev #, 5:3 (state 0) default state:  <0xb5f62b70>
10 01/18/14 16:02:24.784 statechange Reply: no exact match in m:s format, trying global pin number <0xb5f62b70>
05 01/18/14 16:02:24.784 statechange Reply: Sorry, after all that searching, I can't determine which child device should be sent the pin_changed <0xb5f62b70>
10 01/18/14 16:02:24.834 EventThread <0xb5f62b70>
10 01/18/14 16:02:24.834 Reply received from GC100: state,3:2,0 <0xb5f62b70>
10 01/18/14 16:02:24.834 statechange Reply interpreted as module: 3:2 change to 0 <0xb5f62b70>
10 01/18/14 16:02:24.834 statechange Reply: found module of type RELAY, 2 <0xb5f62b70>
10 01/18/14 16:02:24.834 statechange Reply: testing Command_Impl2 Dev #, 4:1 (state 0) default state:  <0xb5f62b70>
10 01/18/14 16:02:24.835 statechange Reply: testing Command_Impl2 Dev #, 4:2 (state 0) default state:  <0xb5f62b70>
10 01/18/14 16:02:24.835 statechange Reply: testing Command_Impl2 Dev #, 4:3 (state 0) default state:  <0xb5f62b70>
10 01/18/14 16:02:24.835 statechange Reply: testing Command_Impl2 Dev #, 5:1 (state 0) default state:  <0xb5f62b70>
10 01/18/14 16:02:24.835 statechange Reply: testing Command_Impl2 Dev #, 5:2 (state 0) default state:  <0xb5f62b70>
10 01/18/14 16:02:24.835 statechange Reply: testing Command_Impl2 Dev #, 5:3 (state 0) default state:  <0xb5f62b70>
10 01/18/14 16:02:24.835 statechange Reply: no exact match in m:s format, trying global pin number <0xb5f62b70>
05 01/18/14 16:02:24.835 statechange Reply: Sorry, after all that searching, I can't determine which child device should be sent the pin_changed <0xb5f62b70>
21 01/18/14 16:02:24.880 unlock(0x9ea4408) #0 (>1070) gc100: gc100.cpp:1198  <0xb6f64b70>
21 01/18/14 16:02:24.880 removed from map (0x9ea4408) #0 (>1070) gc100: gc100.cpp:1198  was: 2 size, now 1 Rel: Y Got: Y <0xb6f64b70>
10 01/18/14 16:02:24.885 EventThread <0xb5f62b70>

I don't think this is an electronic switch bounce because

a) I've filtered bounces with a hardware circuit and
b) the log doesn't show the state switching from 1 to 0, and then back to 1.

Of note from the log:

10   01/18/14 16:02:23.139      statechange Reply interpreted as module: 4:1 change to 1 <0xb5f62b70>
10   01/18/14 16:02:23.300      statechange Reply interpreted as module: 4:1 change to 1 <0xb5f62b70>
10   01/18/14 16:02:24.570      statechange Reply interpreted as module: 4:1 change to 0 <0xb5f62b70>
10   01/18/14 16:02:24.732      statechange Reply interpreted as module: 4:1 change to 0 <0xb5f62b70>

It seems the GC-100 is double-reporting state changes and LMCE doesn't check to see whether each is a legit state change. Has anyone else noticed this?

Suppose I could have my event script check the time stamp it was last executed and abort if it was under a second ago, but that just seems like a bandaid solution.

Ideas?

[davegravy]

In case you're wondering about the 3:2 device, that's the chime which I toggle on doorbell press and release... but I don't THINK that's relevant to my problem.

EDIT: I removed the chime command to be sure, and the GC100 still seems to report each state change twice.

[tschak909]

This may very well be a bug. Can you file a ticket, so we can take a look @ it?

-Thom

[davegravy]

Ticket filed: http://svn.linuxmce.org/trac/ticket/2049