1067054 - Tons of startup-spam: "WARNING: SQLite returned error code 1 , Storage will convert it to NS_ERROR_FAILURE: file mozStoragePrivateHelpers.cpp" & "WARNING: Unable to create a transaction for async execution.: file mozStorageAsyncStatementExecution.cpp"

Status: RESOLVED FIXED

(Core :: SQLite and Embedded Database Bindings, defect)

Description

[Daniel Holbert [:dholbert]]

In my debug build today, when starting up, I'm getting 38 lines of the warning-spam, consisting of 4 lines of this:
{
WARNING: SQLite returned error code 1 , Storage will convert it to NS_ERROR_FAILURE: file /mozilla/storage/src/mozStoragePrivateHelpers.cpp, line 78
}
followed by one line of this:
{
WARNING: Unable to create a transaction for async execution.: file /scratch/work/builds/mozilla-central/mozilla-central.13-11-22.16-03/mozilla/storage/src/mozStorageAsyncStatementExecution.cpp, line 596
}

(and then two straggling warnings of the first type at the end)

I don't recall noticing this before, so I suspect it's a recent regression. Based on hg log for storage/src, I'm guessing bug 1047811 might be involved (that looks like the only recent change there).  Tentatively marking as blocking that bug, though I haven't confirmed that.

Comment 1

[Daniel Holbert [:dholbert]]

Attachment: log of all the warnings

Comment 2

[Marco Bonardo [:mak]]

The first warning is expected cause in many cases we don't get a proper sqlite error and blindly converting to ns_error_failure may be confusing. Though, I think SQLITE_ERROR (value 1) is so generic that a generic conversion to NS_ERROR_FAILURE is fine. We should instead report any other error that is not tracked and not SQLITE_ERROR.

The second warning is bogus, we should use getAutocommit to check if a transaction exists and only if it doesn't exists issue a warning, it's indeed expected that the transaction fails to be created if one is already active.

So, I think we can avoid both.

Comment 3

[Marco Bonardo [:mak]]

so basically we should exclude rc == 1 here http://mxr.mozilla.org/mozilla-central/source/storage/src/mozStoragePrivateHelpers.cpp#74

and use mConnection->getAutocommit here http://mxr.mozilla.org/mozilla-central/source/storage/src/mozStorageAsyncStatementExecution.cpp#589

Comment 4

[Marco Bonardo [:mak]]

This should not be that hard, and would bring huge benefit when reading test logs. Let's make it more visible.

Comment 5

[Chirag Bhatia]

Hi mak,

I'd like to work on this bug. Can you please point the line numbers where the change is to be made? I'm guessing the line numbers mentioned in Comment 3 are outdated because of the file being updated over the time.

Comment 6

[Marco Bonardo [:mak]]

The lines in comment 3 are still correct.

The first one points to the first warning, we need to condition that warning by using NS_WARN_IF instead of NS_WARNING, using rc != SQLITE_ERROR. Indeed we want to warn only if we convert other kind of Sqlite errors to a generic error, since SQLITE_ERROR is the most generic error already, there's no reason to warn.

The second one points to the condition that causes the second warning
595     else {
596       NS_WARNING("Unable to create a transaction for async execution.");
Here we should warn only if we were unable to create a transaction due to Sqlite errors, not if it failed cause there is already a transaction ongoing.
It should be possible to change the if to
if (statementsNeedTransaction() && !mConnection->getAutoCommit())
AutoCommit mode is active outside of transactions, so if getAutoCommit is false we are already inside a transaction and we cannot instantiate a new one.

Comment 7

[Chirag Bhatia]

I tried the code changes you mentioned above and they worked, i.e. the error messages no longer appear. Can you please assign the bug to me so that I can attach the patch?

Also, do I need to test if these error messages appear in the scenarios when they are supposed to? If yes, can you please tell me steps to do so?

Comment 8

[Marco Bonardo [:mak]]

In both cases it's hard to give reliable steps to hit the warnings, cause they are intended to happen in rare internal failure cases (for example SQLITE_INERNAL, SQLITE_NOTFOUND and such).

Comment 9

[Chirag Bhatia]

Attachment: 1067054.patch

Let me know if anything needs to be changed in this.

Comment 10

[Marco Bonardo [:mak]]

Comment on attachment 8586187 [details] [diff] [review]
1067054.patch

Review of attachment 8586187 [details] [diff] [review]:
-----------------------------------------------------------------

::: storage/src/mozStorageAsyncStatementExecution.cpp
@@ +585,5 @@
>    }
>    if (mState == CANCELED)
>      return notifyComplete();
>  
> +  if (statementsNeedTransaction() && !mConnection->getAutoCommit()) {

I just figured out that I inverted the condition in comment 6.

If getAutoCommit() returns true, a transaction is NOT ongoing, and thus we CAN begin one.
Since here we try to begin a transaction, we want autoCommit to be true.

::: storage/src/mozStoragePrivateHelpers.cpp
@@ +74,5 @@
>    nsAutoCString message;
>    message.AppendLiteral("SQLite returned error code ");
>    message.AppendInt(rc);
>    message.AppendLiteral(" , Storage will convert it to NS_ERROR_FAILURE");
> +  NS_WARN_IF(rc != SQLITE_ERROR);

you added the condition, but not the message, you still needs to use message.get() to print the warning message we built. Unfortunately NS_WARN_IF doesn't support a message, so we must use NS_WARN_IF_FALSE(condition, message); clearly you need to invert the condition.

Comment 11

[Chirag Bhatia]

Attachment: 1067054.patch

I've made the changes that you've mentioned in the above comment and re-tested, the warning messages do not appear.

Hope I got it right. Let me know if you can think of anything else we might have to add / change.

Comment 12

[Marco Bonardo [:mak]]

Comment on attachment 8586894 [details] [diff] [review]
1067054.patch

Review of attachment 8586894 [details] [diff] [review]:
-----------------------------------------------------------------

yes now it looks good, I'll push this to Try.

Comment 13

[Marco Bonardo [:mak]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=56bef64c6f00

Comment 14

[Marco Bonardo [:mak]]

Sorry but the patch doesn't compile. which command did you use to build it?
You should rebuild with ./mach build storage library

The problem is that getAutoCommit doesn't exist, it's getAutocommit
http://mxr.mozilla.org/mozilla-central/source/storage/src/mozStorageConnection.h#126

Comment 15

[Chirag Bhatia]

Attachment: 1067054.patch

You're right, sorry about that.

./mach build storage library doesn't work for me (I don't have a directory named library in my mozilla-central? Should there be?)

I just did a ./mach build to do the entire build and found the compile error, and fixed it like you said. Here's the corrected patch

Comment 16

[Marco Bonardo [:mak]]

./mach build storage toolkit/library (but maybe the latter is built automatically, don't recall off-hand)

Comment 17

[Marco Bonardo [:mak]]

Comment on attachment 8587573 [details] [diff] [review]
1067054.patch

Review of attachment 8587573 [details] [diff] [review]:
-----------------------------------------------------------------

https://treeherder.mozilla.org/#/jobs?repo=try&revision=8cca9fa03d01

Comment 18

[Daniel Holbert [:dholbert]]

("./mach build binaries" is the supported foolproof way to do a quick rebuild, if all you're changing is .cpp files and .h files.  That should always work, and if it doesn't, it's a bug.

You can also target specific directories and maybe shave a second off of your build time, but it's rarely worth it because the command will be longer and you'll be less sure that you actually did it right.)

Comment 19

[Marco Bonardo [:mak]]

looks like this is asserting in getAutocommit when running extensions/cookie/test/unit/test_eviction.js cause mDBConn is null (db is closed). I must look into that.

Comment 20

[Marco Bonardo [:mak]]

Attachment: 1067054.patch

The assert is sort of bogus, or better, it was valid until now. Async statements can run after mDBConn has been nullified, while the threads are merged.
so, this just removes the assert and avoids an eventual crash.

Comment 21

[Marco Bonardo [:mak]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=d7f12438d2bf

The os x failures don't look related to me, I actually couldn't figure them out... Maybe my trychooser is outdated? Dunno, but it seems a timeout in libicu that I didn't touch...

Comment 22

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/integration/fx-team/rev/d5df101900d9

Comment 23

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/d5df101900d9