Complete crash of indiallsky last night due to Capture-3 process in syslog "sqlite3.OperationalError: database is locked" - indi_v2024.05.1-636-gd0c47508

[gaitskell]

Last night indiallsky crashed completely. Running on raspi4. The indi-allsky logfile (see below) just stopped with last entry being the "S3 bucket upload" - no errors shown.

The syslog shows crash occurred in the Capture-3 process (Jul 26 22:57:21 PiAllSky python3). Cause was that the "sqlite3.OperationalError: database is locked" (see below).

Additonally, according to GCP S3 file list the available fits files uploads had actually stopped successfully appearing in GCP an hour prior to the complete crash. Files were stored locally ion raspi. No upload errors were being reported in the indi-allsky log - looked for [ERROR] or [WARNING].

I should acknowlege we are running indi-allsky pretty hard with 1 sec exposures every 5 secs, uploading 2.6 MB fits to GCP. Using hard ethernet connection with more than adequate bandwidth.

I used './misc/upload_sync.py sync' to get the last hour of files uploaded to GCP.

Can you see why this major crash might have not been caught? I can provide any additonal log files you need.

As a secondary questions - should the GCP uploads show in log if unsuccessful?

Should I modify our setup to reduce errors?

Thanks,

DETAILS FOLLOW:

Version:

$ git describe --tags
indi_v2024.05.1-636-gd0c47508

/var/log/indi-allsky/indi-allsky.log-20240727 The last entries in logfile were :

Jul 26 22:57:24 PiAllSky [INFO] Image-3-19622/MainThread processing.apply_image_circle_mask() [1479]: Image circle mask in 0.0157 s
Jul 26 22:57:24 PiAllSky [INFO] Image-3-19622/MainThread image.processImage() [625]: Image processed in 5.2085 s
Jul 26 22:57:24 PiAllSky [INFO] Image-3-19622/MainThread image.write_img() [1312]: Image compressed in 0.0270 s
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread miscDb.addImage() [200]: Adding image ccd_f3ee6189-ab30-44e0-a7a7-75ec905af83c/exposures/20240726/night/26_22/ccd1_20240726_225645.jpg to DB
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread miscDb.addThumbnail() [1010]: Adding thumbnail to DB: /var/www/html/allsky/images/ccd_f3ee6189-ab30-44e0-a7a7-75ec905af83c/exposures/20240726/night/26_22/thumbnails/6cfb21bc-dc00-47db-aca3-6c25598eecf3.jpg
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread miscUpload.s3_upload_asset() [478]: Uploading to S3 bucket
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread miscUpload.s3_upload_asset() [478]: Uploading to S3 bucket
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread processing.add() [520]: Image bits: 16, cfa: None
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread processing._detectBitDepth() [607]: Image max value: 25985
Jul 26 22:57:38 PiAllSky [WARNING] Image-3-19622/MainThread processing._detectBitDepth() [638]: *** DETECTED BIT DEPTH (15) IS DIFFERENT FROM CONFIGURED BIT DEPTH (16) ***
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread processing._detectBitDepth() [640]: Overriding bit depth to 16 bits
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread processing._apply_calibration() [704]: Searching for bad pixel map: gain -1, exposure >= 1.0, temp >= -273.1c
Jul 26 22:57:38 PiAllSky [WARNING] Image-3-19622/MainThread processing._apply_calibration() [722]: Temperature matched bad pixel map not found: -273.15c
Jul 26 22:57:38 PiAllSky [WARNING] Image-3-19622/MainThread processing._apply_calibration() [741]: Bad Pixel Map not found: ccd1 16bit 1.0000000s gain -1 bin 1 -273.15c
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread processing._apply_calibration() [753]: Searching for dark frame: gain -1, exposure >= 1.0, temp >= -273.1c
Jul 26 22:57:38 PiAllSky [WARNING] Image-3-19622/MainThread processing._apply_calibration() [771]: Temperature matched dark not found: -273.15c
Jul 26 22:57:38 PiAllSky [WARNING] Image-3-19622/MainThread processing._apply_calibration() [790]: Dark not found: ccd1 16bit 1.0000000s gain -1 bin 1 -273.15c
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread miscDb.addFitsImage() [687]: Adding fits image ccd_f3ee6189-ab30-44e0-a7a7-75ec905af83c/fits/20240726/night/26_22/ccd1_20240726_225647.fit to DB
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread image.write_fit() [1058]: fit filename: /var/www/html/allsky/images/ccd_f3ee6189-ab30-44e0-a7a7-75ec905af83c/fits/20240726/night/26_22/ccd1_20240726_225647.fit
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread miscUpload.s3_upload_asset() [478]: Uploading to S3 bucket
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread sqm.calculate() [21]: Exposure: 1.000000, gain: -1
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread sqm.calculate() [37]: Raw SQM average: 1658.06
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread sqm.calculate() [42]: Weighted SQM average: 18404.50
Jul 26 22:57:38 PiAllSky [ERROR] Image-3-19622/MainThread processing.debayer() [1006]: No bayer pattern detected
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread image.processImage() [374]: Image: 1392 x 1040
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread processing._calculate_8bit_adu() [883]: ADU average: 1588.9 (6)
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread stretch.main() [43]: Using image stretch mode 1
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread stretch.mode1_apply_gamma() [65]: Applying gamma correction
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread stretch.mode1_apply_gamma() [85]: Image gamma in 0.0127 s
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread stretch._get_image_stddev() [168]: Mean and std dev in 0.0737 s
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread stretch.mode1_adjustImageLevels() [94]: Mean: 19196.79, StdDev: 922.04
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread stretch.mode1_adjustImageLevels() [131]: Image levels in 0.0098 s
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread processing.contrast_clahe_16bit() [1395]: Performing 16-bit CLAHE contrast enhance
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread processing._convert_16bit_to_8bit() [1084]: Resampling image from 16 to 8 bits
Jul 26 22:57:38 PiAllSky [WARNING] Image-3-19622/MainThread image.recalculate_exposure() [1660]: New calculated exposure: 1.00000000
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread processing.apply_image_circle_mask() [1479]: Image circle mask in 0.0156 s
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread image.processImage() [625]: Image processed in 0.4400 s
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread image.write_img() [1312]: Image compressed in 0.0273 s
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread miscDb.addImage() [200]: Adding image ccd_f3ee6189-ab30-44e0-a7a7-75ec905af83c/exposures/20240726/night/26_22/ccd1_20240726_225647.jpg to DB
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread miscDb.addThumbnail() [1010]: Adding thumbnail to DB: /var/www/html/allsky/images/ccd_f3ee6189-ab30-44e0-a7a7-75ec905af83c/exposures/20240726/night/26_22/thumbnails/26f69d49-10c5-4fae-82d1-6967bd0323f0.jpg
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread miscUpload.s3_upload_asset() [478]: Uploading to S3 bucket
Jul 26 22:57:38 PiAllSky [INFO] Image-3-19622/MainThread miscUpload.s3_upload_asset() [478]: Uploading to S3 bucket
(END)

The /var/log/syslog :

Jul 26 22:27:42 PiAllSky rngd[526]: stats: bits received from HRNG source: 1060064
Jul 26 22:27:42 PiAllSky rngd[526]: stats: bits sent to kernel pool: 1019968
Jul 26 22:27:42 PiAllSky rngd[526]: stats: entropy added to kernel pool: 1019968
Jul 26 22:27:42 PiAllSky rngd[526]: stats: FIPS 140-2 successes: 53
Jul 26 22:27:42 PiAllSky rngd[526]: stats: FIPS 140-2 failures: 0
Jul 26 22:27:42 PiAllSky rngd[526]: stats: FIPS 140-2(2001-10-10) Monobit: 0
Jul 26 22:27:42 PiAllSky rngd[526]: stats: FIPS 140-2(2001-10-10) Poker: 0
Jul 26 22:27:42 PiAllSky rngd[526]: stats: FIPS 140-2(2001-10-10) Runs: 0
Jul 26 22:27:42 PiAllSky rngd[526]: stats: FIPS 140-2(2001-10-10) Long run: 0
Jul 26 22:27:42 PiAllSky rngd[526]: stats: FIPS 140-2(2001-10-10) Continuous run: 0
Jul 26 22:27:42 PiAllSky rngd[526]: stats: HRNG source speed: (min=460.795; avg=649.949; max=679.442)Kibits/s
Jul 26 22:27:42 PiAllSky rngd[526]: stats: FIPS tests speed: (min=25.263; avg=61.726; max=78.492)Mibits/s
Jul 26 22:27:42 PiAllSky rngd[526]: stats: Lowest ready-buffers level: 2
Jul 26 22:27:42 PiAllSky rngd[526]: stats: Entropy starvations: 0
Jul 26 22:27:42 PiAllSky rngd[526]: stats: Time spent starving for entropy: (min=0; avg=0.000; max=0)us
Jul 26 22:57:21 PiAllSky python3[19958]: Process Capture-3:
Jul 26 22:57:21 PiAllSky python3[19958]: Traceback (most recent call last):
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/virtualenv/indi-allsky/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1965, in _exec_single_context
Jul 26 22:57:21 PiAllSky python3[19958]:     self.dialect.do_execute(
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/virtualenv/indi-allsky/lib/python3.9/site-packages/sqlalchemy/engine/default.py", line 921, in do_execute
Jul 26 22:57:21 PiAllSky python3[19958]:     cursor.execute(statement, parameters)
Jul 26 22:57:21 PiAllSky python3[19958]: sqlite3.OperationalError: database is locked
Jul 26 22:57:21 PiAllSky python3[19958]: The above exception was the direct cause of the following exception:
Jul 26 22:57:21 PiAllSky python3[19958]: Traceback (most recent call last):
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/usr/lib/python3.9/multiprocessing/process.py", line 315, in _bootstrap
Jul 26 22:57:21 PiAllSky python3[19958]:     self.run()
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/indi_allsky/capture.py", line 179, in run
Jul 26 22:57:21 PiAllSky python3[19958]:     raise e
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/indi_allsky/capture.py", line 175, in run
Jul 26 22:57:21 PiAllSky python3[19958]:     self.saferun()
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/indi_allsky/capture.py", line 463, in saferun
Jul 26 22:57:21 PiAllSky python3[19958]:     self._periodic_tasks()
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/indi_allsky/capture.py", line 1008, in _periodic_tasks
Jul 26 22:57:21 PiAllSky python3[19958]:     self._miscDb.setState('WATCHDOG', int(now))
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/indi_allsky/flask/miscDb.py", line 911, in setState
Jul 26 22:57:21 PiAllSky python3[19958]:     db.session.commit()
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/virtualenv/indi-allsky/lib/python3.9/site-packages/sqlalchemy/orm/scoping.py", line 554, in commit
Jul 26 22:57:21 PiAllSky python3[19958]:     return self._proxied.commit()
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/virtualenv/indi-allsky/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 1923, in commit
Jul 26 22:57:21 PiAllSky python3[19958]:     trans.commit(_to_root=True)
Jul 26 22:57:21 PiAllSky python3[19958]:   File "<string>", line 2, in commit
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/virtualenv/indi-allsky/lib/python3.9/site-packages/sqlalchemy/orm/state_changes.py", line 139, in _go
Jul 26 22:57:21 PiAllSky python3[19958]:     ret_value = fn(self, *arg, **kw)
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/virtualenv/indi-allsky/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 1239, in commit
Jul 26 22:57:21 PiAllSky python3[19958]:     self._prepare_impl()
Jul 26 22:57:21 PiAllSky python3[19958]:   File "<string>", line 2, in _prepare_impl
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/virtualenv/indi-allsky/lib/python3.9/site-packages/sqlalchemy/orm/state_changes.py", line 139, in _go
Jul 26 22:57:21 PiAllSky python3[19958]:     ret_value = fn(self, *arg, **kw)
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/virtualenv/indi-allsky/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 1214, in _prepare_impl
Jul 26 22:57:21 PiAllSky python3[19958]:     self.session.flush()
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/virtualenv/indi-allsky/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 4179, in flush
Jul 26 22:57:21 PiAllSky python3[19958]:     self._flush(objects)
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/virtualenv/indi-allsky/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 4315, in _flush
Jul 26 22:57:21 PiAllSky python3[19958]:     transaction.rollback(_capture_exception=True)
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/virtualenv/indi-allsky/lib/python3.9/site-packages/sqlalchemy/util/langhelpers.py", line 146, in __exit__
Jul 26 22:57:21 PiAllSky python3[19958]:     raise exc_value.with_traceback(exc_tb)
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/virtualenv/indi-allsky/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 4275, in _flush
Jul 26 22:57:21 PiAllSky python3[19958]:     flush_context.execute()
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/virtualenv/indi-allsky/lib/python3.9/site-packages/sqlalchemy/orm/unitofwork.py", line 466, in execute
Jul 26 22:57:21 PiAllSky python3[19958]:     rec.execute(self)
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/virtualenv/indi-allsky/lib/python3.9/site-packages/sqlalchemy/orm/unitofwork.py", line 642, in execute
Jul 26 22:57:21 PiAllSky python3[19958]:     util.preloaded.orm_persistence.save_obj(
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/virtualenv/indi-allsky/lib/python3.9/site-packages/sqlalchemy/orm/persistence.py", line 85, in save_obj
Jul 26 22:57:21 PiAllSky python3[19958]:     _emit_update_statements(
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/virtualenv/indi-allsky/lib/python3.9/site-packages/sqlalchemy/orm/persistence.py", line 909, in _emit_update_statements
Jul 26 22:57:21 PiAllSky python3[19958]:     c = connection.execute(
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/virtualenv/indi-allsky/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1412, in execute
Jul 26 22:57:21 PiAllSky python3[19958]:     return meth(
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/virtualenv/indi-allsky/lib/python3.9/site-packages/sqlalchemy/sql/elements.py", line 516, in _execute_on_connection
Jul 26 22:57:21 PiAllSky python3[19958]:     return connection._execute_clauseelement(
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/virtualenv/indi-allsky/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1635, in _execute_clauseelement
Jul 26 22:57:21 PiAllSky python3[19958]:     ret = self._execute_context(
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/virtualenv/indi-allsky/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1844, in _execute_context
Jul 26 22:57:21 PiAllSky python3[19958]:     return self._exec_single_context(
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/virtualenv/indi-allsky/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1984, in _exec_single_context
Jul 26 22:57:21 PiAllSky python3[19958]:     self._handle_dbapi_exception(
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/virtualenv/indi-allsky/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 2339, in _handle_dbapi_exception
Jul 26 22:57:21 PiAllSky python3[19958]:     raise sqlalchemy_exception.with_traceback(exc_info[2]) from e
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/virtualenv/indi-allsky/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1965, in _exec_single_context
Jul 26 22:57:21 PiAllSky python3[19958]:     self.dialect.do_execute(
Jul 26 22:57:21 PiAllSky python3[19958]:   File "/home/admin/indi-allsky/virtualenv/indi-allsky/lib/python3.9/site-packages/sqlalchemy/engine/default.py", line 921, in do_execute
Jul 26 22:57:21 PiAllSky python3[19958]:     cursor.execute(statement, parameters)
Jul 26 22:57:21 PiAllSky python3[19958]: sqlalchemy.exc.OperationalError: (sqlite3.OperationalError) database is locked
Jul 26 22:57:22 PiAllSky python3[19958]: [SQL: UPDATE state SET "createDate"=?, value=? WHERE state."key" = ?]
Jul 26 22:57:22 PiAllSky python3[19958]: [parameters: ('2024-07-26 22:56:49.468698', '1722049009', 'WATCHDOG')]
Jul 26 22:57:22 PiAllSky python3[19958]: (Background on this error at: https://sqlalche.me/e/20/e3q8)
Jul 26 23:17:01 PiAllSky CRON[25424]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Jul 26 23:27:42 PiAllSky rngd[526]: stats: bits received from HRNG source: 1100064

Let me know if you need any other log files