Current live Recording block lost on writing Label

[RadioDM]

Describe the bug
I record a sound from Speakers output device. While recording is going I put some labels into Label track (option Type to Create a Label enabled). Sometimes writing the label text cause stopping the recording and loose the block of recording back to when the record block has started. For this logged session (added at bottom) I have lost the recording about 3 times. First was after click CTRL+B, another time when I was writing quick a note into another label, it also often happen when input Polish regional characters: śćźżńąęół etc. The recording playback is still running after a bug, but no sound is recorded nor a silence. The previous blocks of sound within the same track are kept, lost is only currently recorded sequence. It can be hours of non-stopped record, or just a minute. Always when writing into labels.
The bug started to happen since update to Audacity 3.1.3. It happen very often. Previous version was more than year old, and bug like this never happened.

To Reproduce
It is not easy to reproduce. It doesn't happen always. But when it happened the steps I had done was:

1. Start Recording
2. Enter a label into Label Track either by command or by click on the Label Track at given time and start typing (with enabled option under Edit > Labels > Type to Create a Label)
3. Enter text, usually including regional characters
4. Might get an error as shown in Log below, causing loosing current recording sequence/block

Expected behaviour
Used to make a notes into label track while recording with no problems before updating Auda. Some Polish letters are not working at all, some working, other run commands for example AlrGr+x would make ź letter but it run command "Split Cut". There should be no commands working when inserting label text.

Additional information (please complete the following information):

• OS: Windows 10 Home 21H2
• Version: Audacity 3.1.3 (64 bit)
• Sound Device: Windows WASAPI

Additional context
In this session bug happened 16:51, and about 17:40 two or three times

LOG

16:36:24: Audacity 3.1.3
16:36:24: sqlite3 message: (1) no such table: project in "SELECT 1 FROM project LIMIT 1;"
16:36:28: Error: Failed to load shared library 'avformat-58.dll' (error 126: Nie można odnaleźć określonego modułu.)
16:36:28: Error: Failed to load avformat-58.dll (error 126: Nie można odnaleźć określonego modułu.)
16:36:28: Error: Failed to load shared library 'avformat-57.dll' (error 126: Nie można odnaleźć określonego modułu.)
16:36:28: Error: Failed to load avformat-57.dll (error 126: Nie można odnaleźć określonego modułu.)
16:36:30: Error: Couldn't find symbol 'avio_context_free' in a dynamic library (error 127: Nie można odnaleźć określonej procedury.)
16:36:30: Error: Couldn't find symbol 'av_packet_alloc' in a dynamic library (error 127: Nie można odnaleźć określonej procedury.)
16:36:30: Error: Couldn't find symbol 'av_packet_free' in a dynamic library (error 127: Nie można odnaleźć określonej procedury.)
16:36:30: Error: Couldn't find symbol 'avcodec_free_context' in a dynamic library (error 127: Nie można odnaleźć określonej procedury.)
16:51:41: sqlite3 message: (5) statement aborts at 1: [SAVEPOINT DiscardingUndoStates;] cannot open savepoint - SQL statements in progress
16:51:41: DBConnection SetDBError
	ErrorCode: 0
	LastError: Failed to create savepoint:

DiscardingUndoStates
	LibraryError: not an error
17:38:50: sqlite3 message: (5) statement aborts at 1: [SAVEPOINT UpdateProject;] cannot open savepoint - SQL statements in progress
17:38:50: DBConnection SetDBError
	ErrorCode: 5
	LastError: Failed to create savepoint:

UpdateProject
	LibraryError: cannot open savepoint - SQL statements in progress
17:38:50: DBConnection SetDBError
	ErrorCode: 1
	LastError: Unable to bind to blob
	LibraryError: SQL logic error
17:42:11: sqlite3 message: (1) statement aborts at 1: [RELEASE UpdateProject;] no such savepoint: UpdateProject
17:42:11: DBConnection SetDBError
	ErrorCode: 1
	LastError: Failed to release savepoint:

UpdateProject
	LibraryError: no such savepoint: UpdateProject
17:42:11: sqlite3 message: (1) statement aborts at 1: [ROLLBACK TO UpdateProject;] no such savepoint: UpdateProject
17:42:11: DBConnection SetDBError
	ErrorCode: 1
	LastError: Failed to release savepoint:

UpdateProject
	LibraryError: no such savepoint: UpdateProject
17:42:11: Transaction active at scope destruction

[Penikov]

The bug has been reproduced on Win 10, Audacity 3.1.3

in my case logs are slightly different but the error is still the same:

`19:08:41: Audacity 3.1.3
19:08:41: sqlite3 message: (1) no such table: project in "SELECT 1 FROM project LIMIT 1;"
19:08:41: Error: Failed to load shared library 'avformat-58.dll' (error 126: The specified module could not be found.)
19:08:41: Error: Failed to load avformat-58.dll (error 126: The specified module could not be found.)
19:08:41: Error: Failed to load shared library 'avformat-57.dll' (error 126: The specified module could not be found.)
19:08:41: Error: Failed to load avformat-57.dll (error 126: The specified module could not be found.)
19:08:41: Error: Couldn't find symbol 'avio_context_free' in a dynamic library (error 127: The specified procedure could not be found.)
19:08:41: Error: Couldn't find symbol 'av_packet_alloc' in a dynamic library (error 127: The specified procedure could not be found.)
19:08:41: Error: Couldn't find symbol 'av_packet_free' in a dynamic library (error 127: The specified procedure could not be found.)
19:08:41: Error: Couldn't find symbol 'avcodec_free_context' in a dynamic library (error 127: The specified procedure could not be found.)
19:08:57: Using internal LAME
19:08:57: Error: Failed to load shared library 'avformat-58.dll' (error 126: The specified module could not be found.)
19:08:57: Error: Failed to load avformat-58.dll (error 126: The specified module could not be found.)
19:08:57: Error: Failed to load shared library 'avformat-57.dll' (error 126: The specified module could not be found.)
19:08:57: Error: Failed to load avformat-57.dll (error 126: The specified module could not be found.)
19:08:57: Error: Couldn't find symbol 'avio_context_free' in a dynamic library (error 127: The specified procedure could not be found.)
19:08:57: Error: Couldn't find symbol 'av_packet_alloc' in a dynamic library (error 127: The specified procedure could not be found.)
19:08:57: Error: Couldn't find symbol 'av_packet_free' in a dynamic library (error 127: The specified procedure could not be found.)
19:08:57: Error: Couldn't find symbol 'avcodec_free_context' in a dynamic library (error 127: The specified procedure could not be found.)
19:14:59: sqlite3 message: (5) statement aborts at 1: [RELEASE UpdateProject;] cannot release savepoint - SQL statements in progress
19:14:59: DBConnection SetDBError
ErrorCode: 5
LastError: Failed to release savepoint:

UpdateProject
LibraryError: cannot release savepoint - SQL statements in progress
19:14:59: sqlite3 message: (5) statement aborts at 1: [RELEASE UpdateProject;] cannot release savepoint - SQL statements in progress
19:14:59: DBConnection SetDBError
ErrorCode: 0
LastError: Failed to release savepoint:

UpdateProject
LibraryError: not an error
19:14:59: Transaction active at scope destruction
19:14:59: DBConnection SetDBError
ErrorCode: 5
LastError: Unable to bind to blob
LibraryError: cannot release savepoint - SQL statements in progress
`

[pietro68]

Pavel, how often could you reproduce the bug? I could trigger it only like in 5% of my tries.

[pietro68]

I could reproduce the bug, but... like one time in 20 tries.

When it happened, I was using accented letters, but this does not automatically mean that it can happen only when using them - it might have been a coincidence.

The error in json format (which I get by clicking "problem details") tells more useful information:

{
    "timestamp": 1646147921,
    "event_id": "183d2e4ad1542e4e981241a1fcf0e5a7",
    "platform": "native",
    "release": "audacity@3.1.3",
    "contexts": {
        "os": {
            "type": "os",
            "name": "Windows",
            "version": "10.0.14393"
        }
    },
    "exception": {
        "values": [
            {
                "type": "Warning",
                "value": "Automatic database backup failed.",
                "mechanism": {
                    "type": "runtime_error",
                    "handled": false,
                    "data": {
                        "sqlite3.rc": "1",
                        "sqlite3.context": "TransactionScope::TransactionCommit",
                        "sqlite3.rc": "1",
                        "sqlite3.context": "TransactionScope::TransactionRollback"
                    }
                }
            }
        ]
    }
}

log.txt
.

[pietro68]

I could get another occurrence, this time the "json-format" error is slightly different in its "data" section:

{
    "timestamp": 1646159205,
    "event_id": "2021210c9a8e3c41bb769592023b2fc4",
    "platform": "native",
    "release": "audacity@3.1.3",
    "contexts": {
        "os": {
            "type": "os",
            "name": "Windows",
            "version": "10.0.14393"
        }
    },
    "exception": {
        "values": [
            {
                "type": "Warning",
                "value": "Automatic database backup failed.",
                "mechanism": {
                    "type": "runtime_error",
                    "handled": false,
                    "data": {
                        "sqlite3.rc": "5",
                        "sqlite3.rc": "1",
                        "sqlite3.col": "doc",
                        "sqlite3.context": "TransactionScope::TransactionCommit",
                        "sqlite3.context": "ProjectGileIO::WriteDoc::writeBlobStream",
                        "sqlite3.rc": "5",
                        "sqlite3.context": "TransactionScope::TransactionCommit"
                    }
                }
            }
        ]
    }
}

[RadioDM]

Out of 5 projects which I made since updating, each at least 1,5 hour record and many labels, only 1 I had lost no record block. In the first project after update I have lost 2:30 of non-stopped recording block. Other times I have lost 15 minutes of record block, one time it was even 1 minute. There is no pattern I think. Also if the regional characters affect it then they can only high the risk of losing record. But I am almost sure I have also got error when putting normal characters. Every time the problem occurs, the program hangs for a second before displaying an error and removing the recording block.

3 examples of last projects



It was a huge loss for me. I have had no problems before updating with the same usage manner. I updated only to get the new build-in effects

[RadioDM]

Wait. Actually there was some problem before, which I don't have after update. It was very very tiny error which wasn't affecting almost at all.
So about 10%-20% of times AFTER stopping the recording when I wanted, there was an error showing up. It was saying something about lost something, don't remember what it was called, lost sample or something. In theory it meant to mention that there was some times when recording device/process was occupied or the CPU was occupied for some times while recording and it resulted in some missing parts of recording. It sounded scary, but only in theory. In practice it meant that, after clicking ok, the another track was added with marked all the time spots/bits when CPU/driver or something was occupied. So I have received few marked spots here and there. Usually it was just a single spot, like, one bit of sound that was lost, or a few, 10 bits or so. Rare it was that there was a few seconds where the errors were marked (bit after bit), and where it was marked - there recording was silent. No huge damage really, very little. I get used to it so much that stopped to even pay attention to what was "lost" as it was always so little that it wasn't important at all.
So there is high chance that the previous, non-intrusive error was now replaced with this one which causing very big loss. Few bits lost, compared to hours is a massive difference. As I mentioned in previous comment, now just before error pops out, Audacity hangs out, so it looks like CPU or something is high occupied, but instead of recording silence, remember that instance, go forth and mark afterward it just wipe down the whole current record job.

[pietro68]

I was lucky enough to get another occurrence:

• very early after starting recording (within 5 seconds)
• upon writing the second or third label
• I was typing a label with only two plain characters ("rt")

So it looks as if the problem can happen with plain characters too.

[RadioDM]

5th second, 3rd label. Quick, random writing, plain characters only

Log:

15:55:29: DBConnection SetDBError
	ErrorCode: 0
	LastError: Unable to bind to blob
	LibraryError: not an error
15:55:29: sqlite3 message: (1) statement aborts at 1: [ROLLBACK TO UpdateProject;] no such savepoint: UpdateProject
15:55:29: DBConnection SetDBError
	ErrorCode: 1
	LastError: Failed to release savepoint:

UpdateProject
	LibraryError: no such savepoint: UpdateProject
15:55:29: Transaction active at scope destruction

Details:

{
    "timestamp": 1646232929,
    "event_id": "5538c9b57af4d048be7e2fe913df0276",
    "platform": "native",
    "release": "audacity@3.1.3",
    "contexts": {
        "os": {
            "type": "os",
            "name": "Windows",
            "version": "10.0.19044"
        }
    },
    "exception": {
        "values": [
            {
                "type": "Warning",
                "value": "Automatic database backup failed.",
                "mechanism": {
                    "type": "runtime_error",
                    "handled": false,
                    "data": {
                        "sqlite3.rc": "4",
                        "sqlite3.col": "dict",
                        "sqlite3.context": "ProjectGileIO::WriteDoc::writeBlobStream",
                        "sqlite3.rc": "1",
                        "sqlite3.context": "TransactionScope::TransactionRollback"
                    }
                }
            }
        ]
    }
}

[RadioDM]

And after several more attempts another type of error. Now audacity completely crashed. Some window error poped out but I was writing so fast that it dissapeared (even that I haven't pressed enter or space), Audacity hang out and after few seconds it crashed totally showing the Error raport for Exception error 0xc0000005 (pressed "send" too):

Edit. It is long, I will put it into file:
Exception error 0xc0000005.txt

[RadioDM]

another occurrence. Pasting the log as there is some other problem described at 2 minutes before the record loss. (loss happened after 1m of new recording block started) Also the main error happened this time not at writing characters but when pressed enter to finish entering characters into label.
(Also worth to mention that the problem never happened when doing simple record without putting labels, but it might be worth to try if there will be error when putting labels when there is no recording process, idk if that will help to debug)

17:32:35: DBConnection SetDBError
	ErrorCode: 0
	LastError: Unable to bind to blob
	LibraryError: not an error
17:34:36: sqlite3 message: (5) statement aborts at 1: [RELEASE UpdateProject;] cannot release savepoint - SQL statements in progress
17:34:36: DBConnection SetDBError
	ErrorCode: 4
	LastError: Failed to release savepoint:

UpdateProject
	LibraryError: query aborted
17:34:36: DBConnection SetDBError
	ErrorCode: 0
	LastError: Unable to bind to blob
	LibraryError: not an error

[pietro68]

In an attempt to increase the rate of the bug happening, I tried these things:

• setting my computer to use only ONE core (instead of the usual 8)
• choosing "power saver" as the power plan (that means, lower CPU speed etc.)

With both of the above set on, I tried both with the official release (3.1.3) and with a debug build, run in debug mode.

The rate of the bug did not change - I got only one occurrence in about 20 tries.
The details show that this is again linked to sqlite saving, but slightly different from the other occurrences above:

{
    "timestamp": 1646927653,
    "event_id": "93be956232cf7f418640342662988c6a",
    "platform": "native",
    "release": "audacity@3.1.3",
    "contexts": {
        "os": {
            "type": "os",
            "name": "Windows",
            "version": "10.0.14393"
        }
    },
    "exception": {
        "values": [
            {
                "type": "Warning",
                "value": "Database error.  Sorry, but we don't have more details.",
                "mechanism": {
                    "type": "runtime_error",
                    "handled": false,
                    "data": {
                        "sqlite3.rc": "1",
                        "sqlite3.col": "doc",
                        "sqlite3.context": "ProjectGileIO::WriteDoc::writeBlobStream",
                        "sqlite3.rc": "5",
                        "sqlite3.context": "TransactionScope::TransactionStart"
                    }
                }
            }
        ]
    }
}

[RadioDM]

I was unlucky enough today to get error on the first label input, and another one right after, within seconds. There was several other errors but not for all I did copy the details, and I forgot to copy the whole log too. As I understand right since the error codes are different and sharing them all might help to debug, therefore I paste details which was the same for both errors I have copied details of:

{
    "timestamp": 1646929424,
    "event_id": "1a012fc22f69a04caa9e622da529b789",
    "platform": "native",
    "release": "audacity@3.1.3",
    "contexts": {
        "os": {
            "type": "os",
            "name": "Windows",
            "version": "10.0.19044"
        }
    },
    "exception": {
        "values": [
            {
                "type": "Warning",
                "value": "Automatic database backup failed.",
                "mechanism": {
                    "type": "runtime_error",
                    "handled": false,
                    "data": {
                        "sqlite3.rc": "1",
                        "sqlite3.context": "TransactionScope::TransactionCommit",
                        "sqlite3.rc": "1",
                        "sqlite3.context": "TransactionScope::TransactionRollback"
                    }
                }
            }
        ]
    }
}

[Penikov]

Regarding bug reproducing
I just have reproduced that from the first try (Current Master build)

And at the second try Audacity has crashed

2022-03-14.17-53-50.mp4

So the bug can be reproduced quite easy on my PC.

[Paul-Licameli]

The error messages tell me that the constructor of TransactionScope fails and throws. The message from sqlite, "cannot open savepoint - SQL statements in progress" suggests that there is a concurrently running statement on another thread.

The crash Pavel mentioned might be a result becuase the TransactionScope is sometimes not in the main thread, and there is no catch block for the exception.

@crsib does this suggest any changes in arguments to sqlite3 calls to fix concurrent accesses?

But an alternative is to avoid concurrent accesses, trying to serialize all work on the database in the main thread.

So my speculation about how to write a fix:

Find all of Audacity's uses of sqlite3_prepare_v3 and sqlite3_prepare_v2. Trace the call graph upward, and identify call paths that may happen outside of the main thread. Change those to delay what they do, using BasicUI::CallAfter at some level in the call stack.

Here is one such path, which I think is also the likely one at fault, but the call graph should be explored more to decide whether this is complete. I would use CallAfter in DrainRecordBuffers.

So that means this line, at 2067 in AudioIO.cpp:

mCaptureTracks[i]->Append(temp.ptr(), trackFormat, size, 1);

We should also explore the calls to the constructor of TransactionScope. And here is another path up to the same function:

[pietro68]

Thanks Paul for the pointer, that helped.
I think I found the cause of the bug, and I also found a way to trigger it much more often. Details on request. Anyway, the message is that I am now in the conditions to try to fix this, no need to further trying to trigger it!

[Paul-Licameli]

Was my guess about the cause confirmed?

[pietro68]

Yes, it happens because the same DB access is used concurrently and without fences.
ProjectFileIO::WriteDoc is called in 2 cases:

1. every 1048576 samples (or bytes?) i.e. about 5.9 seconds @44.1khz, to auto-save the recorded, in the AudioIO Thread
2. whenever a key is pressed while writing a label, in the Main Thread

So it looks like the two threads use the DB access concurrently, and that wreaks all different sorts of havoc (as you can see in the different error messages - if you look at the "json" ones).

Also, it was hard to reproduce because the keypress had to come exactly at every multiple of that 5.9 seconds. I changed things so that the auto-save of the recording happens 64 times more often, and then if I keep a key pressed, the bug is much more likely to happen - usually in the first 4 seconds.

Besides this, it seems to me a bit overkill that at every key press while writing a label, a full autosave of the project is done. But I might be wrong, maybe what is done is an incremental save - I did not dig into that level of detail yet.

[StocciD]

Thank you all very much for the bug reported here, the analysis and and for this fix !
I was about to fill in one issue because I encountered the same issue multiple times and loosing live recordings was very frustrating !
Would it be possible to plan to put it on a 3.1.4 ? (Unless 3.2.0 would be about to be released...)