Sql_exec_internal: cannot start a transaction within a transaction

Archive Greenbone Community Edition
1

Hello hive mind and fearless admins,

We’ve been having an issue where gvmd will periodically (between 15 minutes and a few hours) start throwing sqlite3 and sql_exec_internal errors the first of which is usually cannot start a transaction within a transaction, and eventually it will cancel a bunch of running scans and restart.

Any ideas on where we can look to track down why this is happening / how to fix it?

I realize this is probably related to this question, but the underlying issue was never addressed there because the OP was in an enterprise situation.

gvmd --version yields:

Greenbone Vulnerability Manager 9.0+alpha~git-ffd53273-master
GIT revision 962e6434-master

See the excerpt below from our gvmd.log:

event target:MESSAGE:2019-05-30 17h35.10 UTC:22515: Target 1015 (86722092-478e-43f4-a3be-0a3ee3d02d00) has been created by xxxx
event task:MESSAGE:2019-05-30 17h35.11 UTC:22617: Status of task  (992d9198-c2ef-4794-94a9-28fb35e87b72) has changed to New
event task:MESSAGE:2019-05-30 17h35.11 UTC:22617: Task ff-1015 (992d9198-c2ef-4794-94a9-28fb35e87b72) has been created by xxxx
event task:MESSAGE:2019-05-30 17h35.13 UTC:22686: Status of task ff-1015 (992d9198-c2ef-4794-94a9-28fb35e87b72) has changed to Requested
event task:MESSAGE:2019-05-30 17h35.13 UTC:22686: Task ff-1015 (992d9198-c2ef-4794-94a9-28fb35e87b72) has been requested to start by xxxx
event task:MESSAGE:2019-05-30 17h35.33 UTC:23208: Task ff-1015 (992d9198-c2ef-4794-94a9-28fb35e87b72) could not be started by xxxx
event task:MESSAGE:2019-05-30 17h35.41 UTC:24326: Task ff-1015 (992d9198-c2ef-4794-94a9-28fb35e87b72) could not be started by xxxx
event task:MESSAGE:2019-05-30 17h35.47 UTC:22815: Status of task ff-1015 (992d9198-c2ef-4794-94a9-28fb35e87b72) has changed to Running
event task:MESSAGE:2019-05-30 17h35.48 UTC:24791: Task ff-1015 (992d9198-c2ef-4794-94a9-28fb35e87b72) could not be started by xxxx

a few minutes pass…

md manage:WARNING:2019-05-30 17h38.13 UTC:22815: sql_exec_internal: sqlite3_step failed: cannot start a transaction within a transaction
md manage:WARNING:2019-05-30 17h38.13 UTC:22815: sqlv: sql_exec_internal failed
md manage:WARNING:2019-05-30 17h38.13 UTC:22815: manage_cleanup_process_error: Error exit, setting running task to Interrupted
event task:MESSAGE:2019-05-30 17h38.13 UTC:22815: Status of task ff-1015 (992d9198-c2ef-4794-94a9-28fb35e87b72) has changed to Interrupted
event task:MESSAGE:2019-05-30 17h38.55 UTC:4223: Status of task ff-1036 (35d05dad-5f07-4bd2-aa73-f8c715bfb51b) has changed to Done
event task:MESSAGE:2019-05-30 17h38.59 UTC:7862: Task ff-1036 (35d05dad-5f07-4bd2-aa73-f8c715bfb51b) has been stopped by xxxx
event task:MESSAGE:2019-05-30 17h38.59 UTC:7862: Task ff-1036 (35d05dad-5f07-4bd2-aa73-f8c715bfb51b) has been deleted by xxxx
event report:MESSAGE:2019-05-30 17h38.59 UTC:7862: Report 6b3a018f-9a43-4866-8461-f07074762eb3 has been deleted by xxxx
md manage:WARNING:2019-05-30 17h40.09 UTC:4250: sql_exec_internal: sqlite3_step failed: interrupted
md manage:WARNING:2019-05-30 17h40.09 UTC:4250: next: sql_exec_internal failed
md manage:WARNING:2019-05-30 17h40.09 UTC:4250: manage_cleanup_process_error: Error exit, setting running task to Interrupted
event task:MESSAGE:2019-05-30 17h40.09 UTC:4250: Status of task ff-1035 (24fddede-91e3-4826-9132-a4b6b0eecd16) has changed to Interrupted
md manage:WARNING:2019-05-30 17h40.09 UTC:31745: sql_exec_internal: sqlite3_step failed: interrupted
md manage:WARNING:2019-05-30 17h40.09 UTC:31745: sqlv: sql_exec_internal failed
md manage:WARNING:2019-05-30 17h40.09 UTC:31745: manage_cleanup_process_error: Error exit, setting running task to Interrupted
event task:MESSAGE:2019-05-30 17h40.09 UTC:31745: Status of task ff-2224 (88cd9c5d-b05d-421e-b213-2747ff5ca5bf) has changed to Interrupted
md manage:WARNING:2019-05-30 17h40.09 UTC:4224: sql_exec_internal: sqlite3_step failed: interrupted
md manage:WARNING:2019-05-30 17h40.09 UTC:4224: sqlv: sql_exec_internal failed
md manage:WARNING:2019-05-30 17h40.09 UTC:4224: manage_cleanup_process_error: Error exit, setting running task to Interrupted
event task:MESSAGE:2019-05-30 17h40.09 UTC:4224: Status of task ff-1031 (9b139864-1121-44a2-9260-cbff192b71d1) has changed to Interrupted
md manage:WARNING:2019-05-30 17h40.09 UTC:31746: sql_exec_internal: sqlite3_step failed: interrupted
md manage:WARNING:2019-05-30 17h40.09 UTC:31746: sqlv: sql_exec_internal failed
md manage:WARNING:2019-05-30 17h40.09 UTC:31746: manage_cleanup_process_error: Error exit, setting running task to Interrupted
event task:MESSAGE:2019-05-30 17h40.09 UTC:31746: Status of task ff-2172 (50f7b5f4-4841-4f6a-9fc9-fb3955f64d5f) has changed to Interrupted
md   main:MESSAGE:2019-05-30 17h41.39 utc:18382:    Greenbone Vulnerability Manager version 9.0+alpha~git-ffd53273-master (GIT revision ffd53273-master) (DB revision 208)
util gpgme:MESSAGE:2019-05-30 17h41.39 utc:18383: Setting GnuPG dir to '/var/lib/gvm/gvmd/gnupg'
util gpgme:MESSAGE:2019-05-30 17h41.39 utc:18383: Using OpenPGP engine version '2.2.4'
2

While it doesn’t answer the “how so fix it” questions still a quite important note:

Please note that this is a commit of the current “master” branch where all development is happening. This branch might show unexpected behavior or could even break at any time.

If you don’t want to contribute to the development of GVM and want to have the best experience with GVM it is strongly suggested to stay with the official announced source code releases in About the Greenbone Community Edition category - Greenbone Community Edition - Greenbone Community Forum.

After switching to a stable release and if the same messages are showing up there you could open an issue report to the development team working on the GVMd at Issues · greenbone/gvmd · GitHub

Keep the following in mind when using SQLite3: Gvm-cli connections fail under openvassd load · Issue #347 · greenbone/gvmd · GitHub. Switching/migrating to the PostgreSQL backend might be an alternative as well.