I have a very repeatable pattern that leaves Kstars partially dead, INDI still running and abnormal operation:
Initial condition - 3 filter sequence in operation - HA filter complete all 20 shots (this is PRE Flip) - EKOS starts filter change - fails focus 3 times and then KSTARS crashes partially - guiding is still going on but all other functions are dead until morning twilight - mount does not park (OnStep controlled properly suspends due to west meridian error to prevent damage)

The visual pattern of this error is extremely exact (see images) and it looks like there is a failure to perhaps find the filter, BUT looking in the logs I can see that the focus process is happening but SOMEHOW the QHY Camera has suddenly flipped from mode 0 to mode 1 (or at least INDI/Kstars think it has) and thus rejects the image

This leaves the process continuing and repeating but with nothing to work with - this appears like an infinite loop in process - not sure exactly where KSTARS dies, but when the system is viewed in the morning it is not running but INDI is and still attached - the following is the start of the problem right after filter change to OIII - inspecting the analysis view I can see that guide images are still coming in but obviously once the mount hits median stop in the mount all that goes to pot....

In my estimation since I have repeated twice, the root cause is the QHY mode flip which is either false positive or legitimate defect in QHY driver, but the error handling is ODD in this case (a use case that was never expected?)



[2022-06-25T00:33:29.355 EDT INFO ][ org.kde.kstars.ekos.guide] - "Guiding resumed."
[2022-06-25T00:33:33.450 EDT INFO ][ org.kde.kstars.ekos.capture] - "Capturing 300.000-second HA image..."
[2022-06-25T00:38:19.293 EDT INFO ][ org.kde.kstars.indi] - QHY CCD QHY294PROC-4e75 : "[INFO] Exposure done, downloading image... "
[2022-06-25T00:38:22.276 EDT INFO ][ org.kde.kstars.indi] - QHY CCD QHY294PROC-4e75 : "[INFO] Image saved to /home/astroberry/TARGETS/OSC/QHY294_ED80_NGC6888_IMAGE_040.fits "
[2022-06-25T00:38:33.530 EDT INFO ][ org.kde.kstars.indi] - QHY CCD QHY294PROM-12a6 : "[INFO] Exposure done, downloading image... "
[2022-06-25T00:38:37.312 EDT INFO ][ org.kde.kstars.indi] - "FITS" file saved to "/home/astroberry/TARGETS/NGC_6888/Light/HA/NGC_6888_Light_HA_300_secs_2022-06-25T00-38-37_020.fits"
[2022-06-25T00:38:38.596 EDT INFO ][ org.kde.kstars.ekos.capture] - "Received image 20 out of 20."
[2022-06-25T00:38:41.628 EDT INFO ][ org.kde.kstars.ekos.capture] - "Captured /home/astroberry/TARGETS/NGC_6888/Light/HA/NGC_6888_Light_HA_300_secs_2022-06-25T00-38-37_020.fits"
[2022-06-25T00:38:41.658 EDT INFO ][ org.kde.kstars.ekos.capture] - "Job requires 300.000-second OIII images, has 0/20 frames captured and will be processed."
[2022-06-25T00:38:42.488 EDT INFO ][ org.kde.kstars.ekos.capture] - "Executing pre capture script /home/astroberry/scripts/takepicture.sh"
[2022-06-25T00:38:43.324 EDT INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC 6888' 20x300\" HA sees 20 captures in output folder '/home/astroberry/TARGETS/NGC_6888/Light/HA'."
[2022-06-25T00:38:43.324 EDT INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC 6888' 20x300\" HA completed its sequence of 20 light frames."
[2022-06-25T00:38:43.325 EDT INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC 6888' 20x300\" OIII sees 0 captures in output folder '/home/astroberry/TARGETS/NGC_6888/Light/OIII'."
[2022-06-25T00:38:43.325 EDT INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC 6888' 20x300\" OIII requires a dither procedure."
[2022-06-25T00:38:43.325 EDT INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC 6888' 20x300\" SII sees 0 captures in output folder '/home/astroberry/TARGETS/NGC_6888/Light/SII'."
[2022-06-25T00:38:43.325 EDT INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC 6888' 20x300\" SII requires a dither procedure."
[2022-06-25T00:38:43.330 EDT INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC 6888' estimated to take 03h 33m 50s to complete."
[2022-06-25T00:38:43.527 EDT INFO ][ org.kde.kstars.ekos.capture] - "2nd Camera is about to take a picture\n2nd Camera execution command sent\n"
[2022-06-25T00:38:43.531 EDT INFO ][ org.kde.kstars.ekos.capture] - "Pre capture script finished with code 0."
[2022-06-25T00:38:43.534 EDT INFO ][ org.kde.kstars.ekos.capture] - Dithering...
[2022-06-25T00:38:43.534 EDT INFO ][ org.kde.kstars.ekos.capture] - "Dithering..."
[2022-06-25T00:38:43.562 EDT INFO ][ org.kde.kstars.ekos.guide] - "Dithering in progress."
[2022-06-25T00:38:50.819 EDT INFO ][ org.kde.kstars.ekos.guide] - "Post-dither settling for 2 seconds..."
[2022-06-25T00:38:52.856 EDT INFO ][ org.kde.kstars.ekos.capture] - Dithering succeeded, capture state "Dithering"
[2022-06-25T00:38:52.857 EDT INFO ][ org.kde.kstars.ekos.capture] - "Dithering succeeded."
[2022-06-25T00:38:52.860 EDT INFO ][ org.kde.kstars.ekos.capture] - "Dither complete. Resuming in 3 seconds..."
[2022-06-25T00:38:52.864 EDT INFO ][ org.kde.kstars.ekos.guide] - "Dithering completed successfully."
[2022-06-25T00:38:52.978 EDT INFO ][ org.kde.kstars.ekos.guide] - "Guiding resumed."
[2022-06-25T00:38:58.093 EDT INFO ][ org.kde.kstars.ekos.capture] - "Changing filter to OIII..."
[2022-06-25T00:38:58.111 EDT INFO ][ org.kde.kstars.indi] - ASI EFW : "[INFO] Setting current filter to slot 6 "
[2022-06-25T00:38:59.829 EDT INFO ][ org.kde.kstars.ekos.capture] - "Auto focus on filter change..."
[2022-06-25T00:38:59.833 EDT INFO ][ org.kde.kstars.ekos.focus] - "Capturing to check HFR..."
[2022-06-25T00:38:59.837 EDT INFO ][ org.kde.kstars.ekos.focus] - "Capturing image..."
[2022-06-25T00:38:59.854 EDT INFO ][ org.kde.kstars.indi] - QHY CCD QHY294PROM-12a6 : "[INFO] Gain updated to 1710 "
[2022-06-25T00:39:07.309 EDT INFO ][ org.kde.kstars.indi] - QHY CCD QHY294PROM-12a6 : "[INFO] Exposure done, downloading image... "
[2022-06-25T00:39:11.091 EDT WARN ][ org.kde.kstars.ekos.capture] - "{Device: QHY CCD QHY294PROM-12a6 Property: CCD1 Element: CCD1 Chip: 0}" Ignoring Received FITS as it has the wrong capture mode 1
[2022-06-25T00:39:11.091 EDT INFO ][ org.kde.kstars.ekos.focus] - "Image received."
[2022-06-25T00:39:11.094 EDT INFO ][ org.kde.kstars.ekos.focus] - "Detecting sources..."
[2022-06-25T00:39:11.627 EDT INFO ][ org.kde.kstars.ekos.focus] - "Detection complete."
[2022-06-25T00:39:11.657 EDT INFO ][ org.kde.kstars.ekos.focus] - "Autofocus in progress..."
[2022-06-25T00:39:11.660 EDT INFO ][ org.kde.kstars.ekos.focus] - "Focusing outward by 7000 steps..."
[2022-06-25T00:39:11.696 EDT INFO ][ org.kde.kstars.indi] - LX200 OnStep : "[INFO] Focuser is moving to position 35266 "
[2022-06-25T00:39:19.520 EDT INFO ][ org.kde.kstars.ekos.focus] - "Focusing inward by 5000 steps..."
[2022-06-25T00:39:19.526 EDT INFO ][ org.kde.kstars.indi] - LX200 OnStep : "[INFO] Focuser is moving to position 30266 "
[2022-06-25T00:39:26.447 EDT INFO ][ org.kde.kstars.ekos.focus] - "Capturing image..."
[2022-06-25T00:39:33.518 EDT INFO ][ org.kde.kstars.indi] - QHY CCD QHY294PROM-12a6 : "[INFO] Exposure done, downloading image... "
[2022-06-25T00:39:37.462 EDT WARN ][ org.kde.kstars.ekos.capture] - "{Device: QHY CCD QHY294PROM-12a6 Property: CCD1 Element: CCD1 Chip: 0}" Ignoring Received FITS as it has the wrong capture mode 1
[2022-06-25T00:39:37.463 EDT INFO ][ org.kde.kstars.ekos.focus] - "Image received."
[2022-06-25T00:39:37.466 EDT INFO ][ org.kde.kstars.ekos.focus] - "Detecting sources..."
[2022-06-25T00:39:38.443 EDT INFO ][ org.kde.kstars.ekos.focus] - "Detection complete."
[2022-06-25T00:39:38.516 EDT INFO ][ org.kde.kstars.ekos.focus] - "Focusing inward by 1000 steps..."
[2022-06-25T00:39:38.829 EDT INFO ][ org.kde.kstars.indi] - LX200 OnStep : "[INFO] Focuser is moving to position 29266 "
[2022-06-25T00:39:41.690 EDT INFO ][ org.kde.kstars.ekos.focus] - "Capturing image..."
[2022-06-25T00:39:48.758 EDT INFO ][ org.kde.kstars.indi] - QHY CCD QHY294PROM-12a6 : "[INFO] Exposure done, downloading image... "
[2022-06-25T00:39:53.038 EDT WARN ][ org.kde.kstars.ekos.capture] - "{Device: QHY CCD QHY294PROM-12a6 Property: CCD1 Element: CCD1 Chip: 0}" Ignoring Received FITS as it has the wrong capture mode 1
[2022-06-25T00:39:53.039 EDT INFO ][ org.kde.kstars.ekos.focus] - "Image received."
[2022-06-25T00:39:53.041 EDT INFO ][ org.kde.kstars.ekos.focus] - "Detecting sources..."
[2022-06-25T00:39:53.654 EDT INFO ][ org.kde.kstars.ekos.focus] - "Detection complete."
[2022-06-25T00:39:53.693 EDT INFO ][ org.kde.kstars.ekos.focus] - "Focusing inward by 1000 steps..."
[2022-06-25T00:39:53.706 EDT INFO ][ org.kde.kstars.indi] - LX200 OnStep : "[INFO] Focuser is moving to position 28266 "
[2022-06-25T00:39:55.856 EDT INFO ][ org.kde.kstars.ekos.focus] - "Capturing image..."

I have found a relationship between this issue and LOGGING, hence my working theory is there is a contention in the I/O processes for image writing to the disk vs logging:

same setup as above, but this time I have logging on verbose to try and capture more information
Auto run starts but cannot even finish focus routine before kstars crashes - in the morning I attempt to take test images with same setup - downloads are not working or extremely slow: test with OTHER SW connected to indi -> same result - Next I turn OFF logging (disable setting)
Image now download as expected - no problem with speed or delay
So I suspect that the start of the problems above is nothing more than the increased activity during focus and schedule = more logging = delay = more logging = feedback loop = crash
Is there perhaps a common writer object that is being used for both image to disk and log to disk?
or are they perhaps on the same thread? and blocking?

FYI I have and SSD with gigs of free space and raspbian confirms the health and speed are good

UPDATE - even with logging disable the same issue occurs in exactly the same pattern -