search

indigo-astronomy / indigo

INDIGO is a system of standards and frameworks for multiplatform and distributed astronomy software development designed to scale with your needs.
http://www.indigo-astronomy.org
Other
153 stars 70 forks source link

ASI Driver does not report CCD_EXPOSURE=OK when used via indigo_load_driver #570

Closed artyom-beilis closed 1 month ago

artyom-beilis commented 1 month ago

To reproduce I modified example driver to load asi driver and asi 224mc camera name:

Here is the end of the output - and it is stuck:

15:06:39.120105 dynamic_driver_client: connected...
15:06:39.126807 dynamic_driver_client: exposure 3s...
15:06:40.217625 dynamic_driver_client: exposure 2s...
15:06:41.217973 dynamic_driver_client: exposure 1s...
15:06:41.968176 dynamic_driver_client: exposure 0s...
15:06:42.127020 dynamic_driver_client: exposure 0s...
15:06:42.315805 dynamic_driver_client: image saved to img_05.fits...
15:06:42.315822 dynamic_driver_client: exposure done...
15:06:42.315854 dynamic_driver_client: exposure 3s...
15:06:42.465851 dynamic_driver_client: Attempt to set timer with non-NULL reference
15:06:43.468551 dynamic_driver_client: exposure 2s...
15:06:44.468806 dynamic_driver_client: exposure 1s...
15:06:45.219003 dynamic_driver_client: exposure 0s...

With my application I observe following:

Upon receiving CCD_EXPOSURE = ok I start another exposure as per example, I observe I receive CCD_EXPOSURE busy and CCD_IMAGE and than CCD_EXPOSURE = ok

I start another exposure, I receive CCD_IMAGE but I never receive CCD_EXPOSURE=ok - so I don't start another exposure as last status was bus. I also notice the "Attempt to set timer with non-NULL reference"

12:09:15.994  Setting exposure to 0.010000
12:09:15.994  ZWO ASI224MC:CCD_EXPOSURE (busy) rw type number, items 1
   0: EXPOSURE/Start exposure: val=0.010000 min=0.000032 max=2000.000000 step=1.000000 target=0.010000 (%g)
12:09:15.994  ZWO ASI224MC:CCD_IMAGE (busy) ro type blob, items 1
   0: IMAGE/Image data: format= size=0 url= ptr=(nil)
12:09:16.004  ZWO ASI224MC:CCD_EXPOSURE (busy) rw type number, items 1
   0: EXPOSURE/Start exposure: val=0.000000 min=0.000032 max=2000.000000 step=1.000000 target=0.010000 (%g)
12:09:16.212  ZWO ASI224MC:CCD_IMAGE (ok) ro type blob, items 1
   0: IMAGE/Image data: format=.fits size=1275840 url= ptr=0x790f14c01690
12:09:16.214  ZWO ASI224MC:CCD_EXPOSURE (ok) rw type number, items 1
   0: EXPOSURE/Start exposure: val=0.000000 min=0.000032 max=2000.000000 step=1.000000 target=0.010000 (%g)
12:09:16.214  Setting exposure to 0.010000
12:09:16.214  ZWO ASI224MC:CCD_EXPOSURE (busy) rw type number, items 1
   0: EXPOSURE/Start exposure: val=0.010000 min=0.000032 max=2000.000000 step=1.000000 target=0.010000 (%g)
12:09:16.214  ZWO ASI224MC:CCD_IMAGE (busy) ro type blob, items 1
   0: IMAGE/Image data: format=.fits size=1275840 url= ptr=0x790f14c01690
12:09:16.589  ZWO ASI224MC:CCD_TEMPERATURE (ok) ro type number, items 1
   0: TEMPERATURE/Temperature (°C): val=29.000000 min=-50.000000 max=50.000000 step=1.000000 target=0.000000 (%g)
12:09:21.590  ZWO ASI224MC:CCD_TEMPERATURE (ok) ro type number, items 1
   0: TEMPERATURE/Temperature (°C): val=29.100000 min=-50.000000 max=50.000000 step=1.000000 target=0.000000 (%g)

Note: touptek works Ok, and using remote server works Ok for both ASI and ToupTek

rumengb commented 1 month ago

Thank you! I see the problem but I do not know what the root cause is. I need to debug it. It may be some race in the driver. I will fix it.

On Sat, Oct 12, 2024, 3:18 PM Artyom Beilis @.***> wrote:

To reproduce I modified example driver to load asi driver and asi 224mc camera name:

Here is the end of the output - and it is stuck:

15:06:39.120105 dynamic_driver_client: connected... 15:06:39.126807 dynamic_driver_client: exposure 3s... 15:06:40.217625 dynamic_driver_client: exposure 2s... 15:06:41.217973 dynamic_driver_client: exposure 1s... 15:06:41.968176 dynamic_driver_client: exposure 0s... 15:06:42.127020 dynamic_driver_client: exposure 0s... 15:06:42.315805 dynamic_driver_client: image saved to img_05.fits... 15:06:42.315822 dynamic_driver_client: exposure done... 15:06:42.315854 dynamic_driver_client: exposure 3s... 15:06:42.465851 dynamic_driver_client: Attempt to set timer with non-NULL reference 15:06:43.468551 dynamic_driver_client: exposure 2s... 15:06:44.468806 dynamic_driver_client: exposure 1s... 15:06:45.219003 dynamic_driver_client: exposure 0s...

With my application I observe following:

Upon receiving CCD_EXPOSURE = ok I start another exposure as per example, I observe I receive CCD_EXPOSURE busy and CCD_IMAGE and than CCD_EXPOSURE = ok

I start another exposure, I receive CCD_IMAGE but I never receive CCD_EXPOSURE=ok - so I don't start another exposure as last status was bus. I also notice the "Attempt to set timer with non-NULL reference"

12:09:15.994 Setting exposure to 0.010000 12:09:15.994 ZWO ASI224MC:CCD_EXPOSURE (busy) rw type number, items 1 0: EXPOSURE/Start exposure: val=0.010000 min=0.000032 max=2000.000000 step=1.000000 target=0.010000 (%g) 12:09:15.994 ZWO ASI224MC:CCD_IMAGE (busy) ro type blob, items 1 0: IMAGE/Image data: format= size=0 url= ptr=(nil) 12:09:16.004 ZWO ASI224MC:CCD_EXPOSURE (busy) rw type number, items 1 0: EXPOSURE/Start exposure: val=0.000000 min=0.000032 max=2000.000000 step=1.000000 target=0.010000 (%g) 12:09:16.212 ZWO ASI224MC:CCD_IMAGE (ok) ro type blob, items 1 0: IMAGE/Image data: format=.fits size=1275840 url= ptr=0x790f14c01690 12:09:16.214 ZWO ASI224MC:CCD_EXPOSURE (ok) rw type number, items 1 0: EXPOSURE/Start exposure: val=0.000000 min=0.000032 max=2000.000000 step=1.000000 target=0.010000 (%g) 12:09:16.214 Setting exposure to 0.010000 12:09:16.214 ZWO ASI224MC:CCD_EXPOSURE (busy) rw type number, items 1 0: EXPOSURE/Start exposure: val=0.010000 min=0.000032 max=2000.000000 step=1.000000 target=0.010000 (%g) 12:09:16.214 ZWO ASI224MC:CCD_IMAGE (busy) ro type blob, items 1 0: IMAGE/Image data: format=.fits size=1275840 url= ptr=0x790f14c01690 12:09:16.589 ZWO ASI224MC:CCD_TEMPERATURE (ok) ro type number, items 1 0: TEMPERATURE/Temperature (°C): val=29.000000 min=-50.000000 max=50.000000 step=1.000000 target=0.000000 (%g) 12:09:21.590 ZWO ASI224MC:CCD_TEMPERATURE (ok) ro type number, items 1 0: TEMPERATURE/Temperature (°C): val=29.100000 min=-50.000000 max=50.000000 step=1.000000 target=0.000000 (%g)

— Reply to this email directly, view it on GitHub https://github.com/indigo-astronomy/indigo/issues/570, or unsubscribe https://github.com/notifications/unsubscribe-auth/AE5EZBOUA225HQJGXYFGIILZ3EHSTAVCNFSM6AAAAABP2LUQEKVHI2DSMVQWIX3LMV43ASLTON2WKOZSGU4DEOJSHE3TEOA . You are receiving this because you are subscribed to this thread.Message ID: @.***>

rumengb commented 1 month ago

I checked the diver and it was not a driver issue, it was a client issue. In this scenario, property change requests must be sent asynchronously otherwise it may end in a deadlock. I have updated the example and the CLIENT_DEVELOPMENT_BASICS.md document

rumengb commented 1 month ago

Resolved

artyom-beilis commented 1 month ago

Looking here: https://github.com/indigo-astronomy/indigo/blob/22f060d3a61d4c01019bf2c31124c268739fc803/indigo_libs/indigo_bus.c#L1797C7-L1797C15

Correct me if I wrong, but it may cause dangling property access.

I assume once on new/updated property is finished the property pointer would be invalidated, so calling indigo_handle_property_async with a callback to this property may be problematic. I assume property need to be copies and freed.

In the dynamic driver https://github.com/indigo-astronomy/indigo/blob/master/indigo_examples/dynamic_driver_client.c#L40 I see you don't actually use the property that triggered the call since you call for an update. But if user actually transfer all the calls to the callback for both handling and updating properties it may lead to crash.

rumengb commented 1 month ago

We assume developers are smart enough to figure this out :) However, I changed the example a bit to clarify that the property is not used. and will put this in the documentation.

artyom-beilis commented 1 month ago

We assume developers are smart enough to figure this out :)

My first assumption was that the property is actually copied/cloned (otherwise the user need to handle it). I got into the code in order to understand if a new thread is spawned each time or there is a persistent thread is used for such async events.

Thanks for clarification.