Unexpected Extended Error Code

[scarlock]

I've run into a situation where the extended error code is not matching any of the values in apsw.mapping_extended_result_codes. Am I misunderstanding something? Running on MacOS 12.7.1; other version info is in the sample output at the bottom.

To reproduce, save the following code to an empty directory, then run it it two processes at the same time. (The second process needs an argument to the script, any string will do). Alternate hitting enter in each process. (Hopefully that makes sense).

#!/usr/bin/env python

import pprint
import sys

import apsw
import apsw.ext

retries = 0

def busy_handler(ncalls):
    global retries
    retries = ncalls
    if ncalls >= 1000:
        return False
    apsw.sleep(100)
    return True

def setup(db):
    db.execute("""
    create table if not exists foo (
        a INTEGER UNIQUE,
        b INTEGER);
""")
    db.execute("INSERT OR REPLACE INTO foo(a) values(1);")

def show_results(cursor):
    cursor.execute("select * from foo where a=1;")
    result = list(cursor)
    print("Got: ", end='')
    pp.pprint(result)


def doit(db):
    cursor = db.cursor()
    _ = input("ready...")
    cursor.execute("BEGIN;")
    show_results(cursor)
    _ = input("ready to update...")
    cursor.execute("UPDATE foo set b=? where a=1;", (nargs,))
    _ = input("ready to commit")
    cursor.execute("COMMIT;")
    show_results(cursor)
    print("done")

nargs = len(sys.argv) - 1
pp = pprint.PrettyPrinter()

print(sys.version)
print("         APSW version", apsw.apsw_version())
print("SQLite header version", apsw.SQLITE_VERSION_NUMBER)
print("   SQLite lib version", apsw.sqlite_lib_version())
print("   Using amalgamation", apsw.using_amalgamation)

db = apsw.Connection("./test.db", flags=apsw.SQLITE_OPEN_READWRITE | apsw.SQLITE_OPEN_CREATE)
db.set_busy_handler(busy_handler)
print(db.pragma("journal_mode=WAL;"))

if nargs == 0:
    setup(db)

try:
    doit(db)
except apsw.Error as exc:
    try:
        result = apsw.mapping_result_codes[exc.result]
    except:
        result = exc.result
    try:
        eresult = apsw.mapping_extended_result_codes[exc.extendedresult]
    except KeyError:
        eresult = exc.extendedresult
    print("Error occurred. Retry count:", retries, "Result:", result, "Extended Result:", eresult)

    apsw.ext.print_augmented_traceback(*sys.exc_info())
    sys.exit(1)

The results from process 2 on my system are:

3.12.0 | packaged by Anaconda, Inc. | (main, Oct  2 2023, 12:29:27) [Clang 14.0.6 ]
         APSW version 3.43.2.0
SQLite header version 3043002
   SQLite lib version 3.43.2
   Using amalgamation True
wal
ready...Got: [(1, None)]
ready to update...Traceback (most recent call last):

  File "/Users/xxx/Documents/Devel/yyy/testing/foo/./zot.py", line 65, in <module>
    doit(db)
    __annotations__ = {}
    __builtins__ = <module 'builtins' (built-in)>
    __cached__ = None
    __doc__ = None
    __file__ = '/Users/xxx/Documents/Devel/yyy/testing/foo/./zot.py'
    __loader__ = <_frozen_importlib_external.SourceFileLoader object at 0x10a589730>
    __name__ = '__main__'
    __package__ = None
    __spec__ = None
    apsw = <module 'apsw' from '/Users/xxx/opt/miniconda3/envs/yyy/lib/python3.12/site-packages/apsw/__init__.cpython-312-darwin.so'>
    busy_handler = <function busy_handler at 0x10a5622a0>
    db = <apsw.Connection object at 0x10a71d300>
    doit = <function doit at 0x10a87c180>
    eresult = 5
    exc = BusyError('BusyError: database is locked')
    nargs = 1
    path = <module 'posixpath' (frozen)>
    pp = <pprint.PrettyPrinter object at 0x10a63dd30>
    pprint = <module 'pprint' from '/Users/xxx/opt/miniconda3/envs/yyy/lib/python3.12/pprint.py'>
    result = 'SQLITE_BUSY'
    retries = 0
    setup = <function setup at 0x10a758fe0>
    show_results = <function show_results at 0x10a7584a0>
    sys = <module 'sys' (built-in)>
    time = <module 'time' (built-in)>

  File "/Users/xxx/Documents/Devel/yyy/testing/foo/./zot.py", line 42, in doit
    cursor.execute("UPDATE foo set b=? where a=1;", (nargs,))
    _ = ''
    cursor = <apsw.Cursor object at 0x10a890040>
    db = <apsw.Connection object at 0x10a71d300>

  File "src/cursor.c", line 242, in resetcursor
    res = 5

apsw.BusyError: BusyError: database is locked

Error occurred. Retry count: 0 Result: SQLITE_BUSY Extended Result: 5

[rogerbinns]

I've run into a situation where the extended error code is not matching any of the values in apsw.mapping_extended_result_codes. Am I misunderstanding something?

See the SQLite doc. In practical terms result codes were an 8 bit number. When wanting to add detail in extended result codes, the bottom 8 bits are the corresponding result code. For example from the SQLite source:

#define SQLITE_CONSTRAINT  19   /* Abort due to constraint violation */
#define SQLITE_CONSTRAINT_NOTNULL      (SQLITE_CONSTRAINT | (5<<8))

You got code 5 - SQLITE_BUSY. Because the value is less than 256 it is a standard result code, and not an extended one. I have added apsw.ext.result_string for the next release that knows about this, and looks in the appropriate mapping.

db.pragma("journal_mode=WAL;")

That should be db.pragma("journal_mode", "WAL") - the pragma function takes care of quoting values correctly as bindings can't be used for pragmas. I've updated the doc to give that as example showing a value being provided.

[scarlock]

Thanks for catching my mis-use of the pragma function. (I had just converted an execute call to a pragma call).

Thanks for reminding me of the relationship between the error codes and extended error codes.

I guess my question now is why am I getting a SQLITE_BUSY? My busy handler hasn't been called. I was expecting SQLITE_BUSY_SNAPSHOT since I'm trying to modify a row that was modified after the transaction started.

I'm going to re-write my example to be self-contained (using threads) to make sure it's doing what I want it to do. (I'm trying to make it fail so I can test my error handling).

[scarlock]

I've re-written my example to (hopefully) make it obvious what I'm try to do.

I'm still not understanding why I'm getting just a SQLITE_BUSY (especially since my busy handler never fires) and not a SQLITE_BUSY_SNAPSHOT like I think I should get.

Thanks for any insights.

#!/usr/bin/env python

import io
import logging
import sys
import threading

import apsw
import apsw.ext

SETUP_SQL = '''
DROP TABLE IF EXISTS test;
CREATE TABLE test (
    a INTEGER UNIQUE,
    b TEXT);
INSERT OR REPLACE INTO test(a) VALUES(1);
'''

QUERY = 'SELECT a, b FROM test WHERE a=1;'

def setup_logging():
    root = logging.getLogger()
    root.setLevel(logging.DEBUG)
    fh = logging.FileHandler('./test.log', mode='w')
    fh.setLevel(logging.DEBUG)
    sh = logging.StreamHandler()
    sh.setLevel(logging.DEBUG)
    log_fmt = '%(relativeCreated)6d %(levelname)-5s %(threadName)-16s %(message)s'
    formatter = logging.Formatter(log_fmt)
    fh.setFormatter(formatter)
    sh.setFormatter(formatter)
    root.addHandler(sh)
    root.addHandler(fh)

def get_db(initial=False):
    flags = apsw.SQLITE_OPEN_READWRITE
    if initial:
        flags |= apsw.SQLITE_OPEN_CREATE
    db = apsw.Connection('./test.db', flags=flags)
    if initial:
        res = db.pragma('JOURNAL_MODE', 'WAL')
        if res != 'wal':
            raise RuntimeError('Unable to set WAL mode')
        db.execute(SETUP_SQL)
    return db

def doit(**kwargs):
    barriers = kwargs['barriers']

    db = get_db()

    retries = 0

    def busy_handler(ncalls):
        retries = ncalls
        if ncalls >= 1000:
            return False
        logging.info('Busy Handler')
        apsw.sleep(100)
        return True

    db.set_busy_handler(busy_handler)

    myname = threading.current_thread().name

    logging.info('Starting')

    barriers['Begin'].wait()
    logging.info('Entering Begin')
    db.execute('BEGIN;')

    barriers['Select'].wait()
    logging.info('Entering Select')
    logging.info("Got:\n" + apsw.ext.format_query_table(db, QUERY))

    updated = False
    barriers['Update'].wait()
    logging.info('Entering Update')
    try:
        db.execute('UPDATE test SET b = ? WHERE a = 1;', (myname, ))
        updated = True
    except apsw.Error as exc:
        try:
            resultc = apsw.mapping_result_codes[exc.result]
        except:
            resultc = exc.result
        try:
            eresultc = apsw.mapping_extended_result_codes[exc.extendedresult]
        except KeyError:
            eresultc = exc.extendedresult

        traceback = io.StringIO()
        apsw.ext.print_augmented_traceback(*sys.exc_info(), file=traceback)
        logging.error(traceback.getvalue())

    barriers['Commit'].wait()
    logging.info('Entering Commit')
    db.execute('COMMIT;')

    logging.info('Done')

    return None

# # # # #
setup_logging()
apsw.ext.log_sqlite()

logging.info(sys.version)
logging.info("         APSW version: %s", apsw.apsw_version())
logging.info("SQLite header version: %s", apsw.SQLITE_VERSION_NUMBER)
logging.info("   SQLite lib version: %s", apsw.sqlite_lib_version())
logging.info("   Using amalgamation: %s", apsw.using_amalgamation)

barriers = {}
for k in ('Begin', 'Select', 'Update', 'Commit'):
    barriers[k] = threading.Barrier(2)

db = get_db(initial=True)

kwargs = {}
kwargs['barriers'] = barriers
logging.info('Starting threads')
for _ in (1, 2):
    thread = threading.Thread(target=doit, kwargs=kwargs)
    thread.start()

logging.info('Joining Threads')
current_thread = threading.current_thread()
while (threading.active_count() > 1):
    for thread in threading.enumerate():
        if thread == current_thread:
            continue
        thread.join(timeout=0.25)

logging.info('All threads finished')
logging.info("Got:\n" + apsw.ext.format_query_table(db, QUERY))
logging.info('Finished')

    23 INFO  MainThread       3.12.0 | packaged by Anaconda, Inc. | (main, Oct  2 2023, 12:29:27) [Clang 14.0.6 ]
    23 INFO  MainThread                APSW version: 3.43.2.0
    23 INFO  MainThread       SQLite header version: 3043002
    23 INFO  MainThread          SQLite lib version: 3.43.2
    23 INFO  MainThread          Using amalgamation: True
    26 INFO  MainThread       Starting threads
    26 INFO  MainThread       Joining Threads
    26 INFO  Thread-1 (doit)  Starting
    26 INFO  Thread-2 (doit)  Starting
    26 INFO  Thread-2 (doit)  Entering Begin
    26 INFO  Thread-1 (doit)  Entering Begin
    27 INFO  Thread-1 (doit)  Entering Select
    27 INFO  Thread-2 (doit)  Entering Select
    27 INFO  Thread-1 (doit)  Got:
┌───┬────────┐
│ a │   b    │
│ 1 │ (null) │
└───┴────────┘

    27 INFO  Thread-2 (doit)  Got:
┌───┬────────┐
│ a │   b    │
│ 1 │ (null) │
└───┴────────┘

    27 INFO  Thread-2 (doit)  Entering Update
    27 INFO  Thread-1 (doit)  Entering Update
    28 ERROR Thread-1 (doit)  Traceback (most recent call last):

  File "/Users/xxx/Documents/Devel/yyy/testing/foo/./test2.py", line 81, in doit
    db.execute('UPDATE test SET b = ? WHERE a = 1;', (myname, ))
    barriers = {'Begin': <threading.Barrier at 0x1076c1ac0: waiters=0/2>, 'Select': <threading.Barrier at 0x107972e70: waiters=0/2>, 'Update': <threading.Barrier at 0x107970950: waiters=0/2>, 'Commit': <threading.Barrier at 0x107971bb0: waiters=1/2>}
    busy_handler = <function doit.<locals>.busy_handler at 0x1079b1940>
    db = <apsw.Connection object at 0x10793aa70>
    eresultc = 5
    exc = BusyError('BusyError: database is locked')
    kwargs = {'barriers': {'Begin': <threading.Barrier at 0x1076c1ac0: waiters=0/2>, 'Select': <threading.Barrier at 0x107972e70: waiters=0/2>, 'Update': <threading.Barrier at 0x107970950: waiters=0/2>, 'Commit': <threading.Barrier at 0x107971bb0: waiters=1/2>}}
    myname = 'Thread-1 (doit)'
    resultc = 'SQLITE_BUSY'
    retries = 0
    traceback = <_io.StringIO object at 0x10787a440>
    updated = False

  File "src/cursor.c", line 242, in resetcursor
    res = 5

apsw.BusyError: BusyError: database is locked


    28 INFO  Thread-1 (doit)  Entering Commit
    28 INFO  Thread-2 (doit)  Entering Commit
    28 INFO  Thread-1 (doit)  Done
    29 INFO  Thread-2 (doit)  Done
    29 INFO  MainThread       All threads finished
    29 INFO  MainThread       Got:
┌───┬─────────────────┐
│ a │        b        │
│ 1 │ Thread-2 (doit) │
└───┴─────────────────┘

    29 INFO  MainThread       Finished

[rogerbinns]

BTW BEGIN just defines a transaction boundary. It does not mean that locks etc are acquired. Semantically the only time locks have to be acquired is to do a commit. SQLite will buffer up a transaction in memory, and access the database file and locks as it deems necessary. Read about SQLite transaction control. DEFERRED is the default.

[scarlock]

Agreed. I don't want locks acquired unless/until needed.

I'm implementing a job queue. My worker(s) will start a transaction, then check if there is work available. If not, we commit the transaction and sleep for a while. If there is work, we update the work request to show that it is in process and commit that. Of course, with multiple workers it's likely that more than one worker will try to take the same work request. I'm relying on SQLite to mediate that for me. I just want to make sure I know what I get back from apsw/SQLite when the conflict occurs so I can do the right thing.

Thanks.