Troubleshooting cipher_migrate failure using sqlite3 ruby gem

SQLCipher
1

Background:
We have a setup that has sqlcipher installed and the ruby gem sqlite3 (a wrapper around sqlite3) is built and links to sqlcipher.
I am in the process of testing sqlite databases (we have many) from our current production environment (that runs an older set of sqlite3/sqlcipher) in a newer development environment. I can determine that I need to run cipher_migrate to continue to use the dbs in the new environment.

The ruby gem is built natively on installation with the --with-sqlcipher flag and I can confirm it is linked - I can use it successfully with new encrypted databases and already migrated older encrypted databases.

In a bash shell in the environment (an Ubuntu Docker container) using sqlcipher directly at the command line, I can successfully open the db, enter the key and run PRAGMA cipher_migrate and the db will be migrated and returns a value of 0.

The problem:
If I open the db from within the Ruby (on Rails) console using the sqlite3 gem that is linked to the same installation of sqlcipher , enter the key and run PRAGMA cipher_migrate it fails with a return error of 1. If I open the db after it was migrated from the command line sqlcipher it works as expected. I need to be able to migrate as part of the new app’s process using the ruby gem.

I suspect there is something set in the sqlite3 gem that is causing a conflict for sqlcipher but I don’t know what it could be.

I enabled cipher_log at “trace” level and captured what is happening in each case and you can see there is a divergence in the output but I don’t know where to go from here.

Log using sqlcipher directly at bash command line (snipped because it is long):

sqlcipher_codec_pragma: db=0x40001ad4d0 iDb=0 pParse=0x40019ab1d0 zLeft=cipher_migrate zRight=(null) ctx=0x40001f2660
sqlcipher_malloc: calling sqlite3Malloc(22)
sqlcipher_malloc: calling sqlcipher_memset(0x40001f3c60,0,22)
sqlcipher_memset: setting 0x40001f3c60[0-22]=0)
sqlcipher_mem_lock: calling mlock(0x40001f3000,3190); _SC_PAGESIZE=4096
sqlite3_key: db=0x40001f3c80
sqlite3_key_v2: db=0x40001f3c80 zDb=main
sqlcipherCodecAttach: db=0x40001f3c80, nDb=0
sqlcipherCodecAttach: calling sqlcipher_activate()
sqlcipher_activate: entering static master mutex
sqlcipher_activate: entered static master mutex
sqlcipher_activate: leaving static master mutex
sqlcipher_activate: left static master mutex
sqlcipherCodecAttach: entering database mutex (nil)
sqlcipherCodecAttach: entered database mutex (nil)
sqlcipherCodecAttach: calling sqlcipher_codec_ctx_init()
sqlcipher_codec_ctx_init: allocating context
sqlcipher_malloc: calling sqlite3Malloc(136)
sqlcipher_malloc: calling sqlcipher_memset(0x40002038f0,0,136)
sqlcipher_memset: setting 0x40002038f0[0-136]=0)
sqlcipher_mem_lock: calling mlock(0x4000203000,2424); _SC_PAGESIZE=4096
sqlcipher_codec_ctx_init: allocating kdf_salt
sqlcipher_malloc: calling sqlite3Malloc(16)
sqlcipher_malloc: calling sqlcipher_memset(0x4000203980,0,16)
sqlcipher_memset: setting 0x4000203980[0-16]=0)
sqlcipher_mem_lock: calling mlock(0x4000203000,2448); _SC_PAGESIZE=4096
sqlcipher_codec_ctx_init: allocating hmac_kdf_salt
sqlcipher_malloc: calling sqlite3Malloc(16)
sqlcipher_malloc: calling sqlcipher_memset(0x40002039a0,0,16)
sqlcipher_memset: setting 0x40002039a0[0-16]=0)
sqlcipher_mem_lock: calling mlock(0x4000203000,2480); _SC_PAGESIZE=4096
sqlcipher_codec_ctx_init: allocating provider
sqlcipher_malloc: calling sqlite3Malloc(136)
sqlcipher_malloc: calling sqlcipher_memset(0x40002039c0,0,136)
sqlcipher_memset: setting 0x40002039c0[0-136]=0)
sqlcipher_mem_lock: calling mlock(0x4000203000,2632); _SC_PAGESIZE=4096
sqlcipher_codec_ctx_init: entering SQLCIPHER_MUTEX_PROVIDER
sqlcipher_codec_ctx_init: entered SQLCIPHER_MUTEX_PROVIDER
sqlcipher_codec_ctx_init: leaving SQLCIPHER_MUTEX_PROVIDER
sqlcipher_codec_ctx_init: left SQLCIPHER_MUTEX_PROVIDER
sqlcipher_openssl_activate: entering SQLCIPHER_MUTEX_PROVIDER_ACTIVATE
sqlcipher_openssl_activate: entered SQLCIPHER_MUTEX_PROVIDER_ACTIVATE
sqlcipher_openssl_activate: leaving SQLCIPHER_MUTEX_PROVIDER_ACTIVATE
sqlcipher_openssl_activate: left SQLCIPHER_MUTEX_PROVIDER_ACTIVATE
…snipped…

Log using sqlite3 ruby gem linked to the same sqlcipher installation in same environment as above:

sqlcipher_codec_pragma: db=0x401e2f8830 iDb=0 pParse=0x40017ff6c0 zLeft=cipher_migrate zRight=(null) ctx=0x4020b350b0
sqlcipher_malloc: calling sqlite3Malloc(1)
sqlcipher_malloc: calling sqlcipher_memset(0x4020f93630,0,1)
sqlcipher_memset: setting 0x4020f93630[0-1]=0)
sqlcipher_mem_lock: calling mlock(0x4020f93000,1585); _SC_PAGESIZE=4096
sqlite3_key: db=0x4020bc2810
sqlite3_key_v2: db=0x4020bc2810 zDb=main
sqlite3_key_v2: no key provided
sqlite3_key: db=0x4020bc2810
sqlite3_key_v2: db=0x4020bc2810 zDb=main
sqlite3_key_v2: no key provided
sqlcipher_free: calling sqlcipher_memset(0x4020bc1c60,0,32)
sqlcipher_memset: setting 0x4020bc1c60[0-32]=0)
sqlcipher_mem_unlock: calling munlock(0x4020bc1000,3200)
sqlite3_key: db=0x4020bc2810
sqlite3_key_v2: db=0x4020bc2810 zDb=main
sqlite3_key_v2: no key provided
sqlcipher_free: calling sqlcipher_memset(0x4020f93650,0,32)
sqlcipher_memset: setting 0x4020f93650[0-32]=0)
sqlcipher_mem_unlock: calling munlock(0x4020f93000,1648)
sqlite3_key: db=0x4020bc2810
sqlite3_key_v2: db=0x4020bc2810 zDb=main
sqlite3_key_v2: no key provided
sqlcipher_free: calling sqlcipher_memset(0x4020f93680,0,32)
sqlcipher_memset: setting 0x4020f93680[0-32]=0)
sqlcipher_mem_unlock: calling munlock(0x4020f93000,1696)
Upgrade format not determined
An error occurred attempting to migrate the database - last error 1
sqlcipher_free: calling sqlcipher_memset(0x4020f93630,0,0)
sqlcipher_memset: setting 0x4020f93630[0-0]=0)
sqlcipher_codec_pragma: error occurred during cipher_migrate: 1
sqlcipher_codec_ctx_set_error: ctx=0x4020b350b0, error=1
sqlcipher_codec_pragma: db=0x401e2f8830 iDb=0 pParse=0x40017fef90 zLeft=encoding zRight=(null) ctx=0x4020b350b0
sqlcipher_codec_pragma: db=0x401e2f8830 iDb=0 pParse=0x40017fef90 zLeft=encoding zRight=(null) ctx=0x4020b350b0
1

I’ve bolded some above statements in the log I think may be clues.

As mentioned above, the underlying sqlcipher installation is the same in both cases so I suspect some settings that the sqlite3 gem has imposed are causing the issue but I don’t know what they are.

Additional information:

The cipher_version for the old installation (where the dbs were built): 3.4.2
The cipher_version for the new installation: 4.5.2 community

The cipher_settings for the new installation (I think this is not a command in old):

PRAGMA kdf_iter = 256000;
PRAGMA cipher_page_size = 4096;
PRAGMA cipher_use_hmac = 1;
PRAGMA cipher_plaintext_header_size = 0;
PRAGMA cipher_hmac_algorithm = HMAC_SHA512;
PRAGMA cipher_kdf_algorithm = PBKDF2_HMAC_SHA512;

The way the new installation’s ‘sqlcipher’ is installed in the Docker image:

RUN git clone https://github.com/sqlcipher/sqlcipher.git
RUN cd sqlcipher && ./configure
–prefix=/usr
–enable-tempstore=yes
CFLAGS=“-DSQLITE_HAS_CODEC”
LDFLAGS=“-lcrypto” &&
make &&
make install &&
cd /tmp

The ruby gem is built natively in the installation using the --with-sqlcipher flag

Testing the built file for the ruby gem using ldd to see that it is linked to libsqlcipher:

ldd /.../bundle/ruby/2.6.0/bundler/gems/extensions/x86_64-linux/2.6.0/sqlite3-ruby-31ea0084ced0/sqlite3/sqlite3_native.so
libruby.so.2.6 => /usr/local/rvm/rubies/ruby-2.6.9/lib/libruby.so.2.6 (0x0000004001842000)
libsqlcipher.so.0 => /lib/libsqlcipher.so.0 (0x0000004001bd3000)
libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x0000004001d00000)
libz.so.1 => /lib/x86_64-linux-gnu/libz.so.1 (0x0000004001ef2000)
libpthread.so.0 => /lib/x86_64-linux-gnu/libpthread.so.0 (0x0000004001f0e000)
librt.so.1 => /lib/x86_64-linux-gnu/librt.so.1 (0x0000004001f31000)
libdl.so.2 => /lib/x86_64-linux-gnu/libdl.so.2 (0x0000004001f3e000)
libcrypt.so.1 => /lib/x86_64-linux-gnu/libcrypt.so.1 (0x0000004001f44000)
libm.so.6 => /lib/x86_64-linux-gnu/libm.so.6 (0x0000004001f7f000)
/lib64/ld-linux-x86-64.so.2 (0x0000004000000000)
libcrypto.so.1.1 => /lib/x86_64-linux-gnu/libcrypto.so.1.1 (0x00000040020ce000)

Note: /lib is a symlink to /usr/lib

Can someone deduce from above what is happening here that suggests what is different and what sqlite3/sqlcipher settings should be changed to resolve?

What is the next step for troubleshooting this? Some more info needed?

2

@patakijv - I would take a look at what the sqlite3 gem is doing after opening a connection. PRAGMA cipher_migrate only works if it is called immediately after keying (either via PRAGMA key or sqlite3_key). This is because it needs access prior to the database file actually being opened, and before key derivation. If the wrapper library is doing anything that would cause the database to be read or written then it could break cipher_migrate.

If that doesn’t lead anywhere, or you can’t control the opening sequence to make cipher_migrate work, you could consider handling the migration manually, e.g. as follows:

SQLCipher API - Zetetic

3

@sjlombardo

Thanks for the reply.

As far as what happens after opening, it appears the gem calls sqlite3 native open_v2 here on initialization and just after that it should be ignoring a call to disable_quirk_mode because we are not passing in :strict as an option. After that it sets some variables and then checks for a block (none provided in our case) and then the method ends.

I also tried adding the PRAGMA cipher_migrate to the same string as the key like this db.execute("PRAGMA key = '#{company.db_key}';PRAGMA cipher_migrate;") so it would all be on one line to remove the chance that the gem could intervene but it doesn’t seem to change the results.

I tried the manual migration steps as you suggested, it seems to have errors along the way and then an “out of memory” exception is thrown during the ATTACH steps.
See log output with some bolded areas I think may be clues because they are error releated:

executing PRAGMA cipher_page_size = 1024

sqlcipher_codec_pragma: db=0x4037cba340 iDb=0 pParse=0x40017ff6c0 zLeft=cipher_page_size zRight=1024 ctx=0x40378aaf90
sqlcipher_free: calling sqlcipher_memset(0x40372fc3e0,0,4096)
sqlcipher_memset: setting 0x40372fc3e0[0-4096]=0)
sqlcipher_mem_unlock: calling munlock(0x40372fc000,5088)
sqlcipher_malloc: calling sqlite3Malloc(1024)
sqlcipher_malloc: calling sqlcipher_memset(0x40376f8e10,0,1024)
sqlcipher_memset: setting 0x40376f8e10[0-1024]=0)
sqlcipher_mem_lock: calling mlock(0x40376f8000,4624); _SC_PAGESIZE=4096
codec_set_btree_to_codec_pagesize: sqlite3BtreeSetPageSize() size=1024 reserve=80
codec_set_btree_to_codec_pagesize: entering database mutex 0x403651a2c0
codec_set_btree_to_codec_pagesize: entered database mutex 0x403651a2c0
codec_set_btree_to_codec_pagesize: sqlite3BtreeSetPageSize returned 0
codec_set_btree_to_codec_pagesize: leaving database mutex 0x403651a2c0
codec_set_btree_to_codec_pagesize: left database mutex 0x403651a2c0
sqlcipher_codec_pragma: db=0x4037cba340 iDb=0 pParse=0x40017fef90 zLeft=encoding zRight=(null) ctx=0x40378aaf90
sqlite3Codec: pgno=1, mode=3, page_sz=1024
sqlcipher_free: calling sqlcipher_memset((nil),0,0)
sqlcipher_free: calling sqlcipher_memset((nil),0,0)
sqlite3Codec: switch mode=3 offset=16
sqlcipher_page_cipher: pgno=1, mode=0, size=928
sqlcipher_page_cipher: comparing hmac on in=0x4037ced268 out=0x40376f91d0 hmac_sz=64
sqlcipher_page_cipher: hmac check failed for pgno=1 returning SQLITE_ERROR
sqlcipher_memset: setting 0x40376f8e20[0-1008]=0)
sqlite3Codec: error decrypting page 1 data: 1
sqlcipher_memset: setting 0x40376f8e20[0-1008]=0)
sqlcipher_codec_ctx_set_error: ctx=0x40378aaf90, error=1

executing PRAGMA kdf_iter = 64000

sqlcipher_codec_pragma: db=0x4037cba340 iDb=0 pParse=0x40017ff6c0 zLeft=kdf_iter zRight=64000 ctx=0x40378aaf90
sqlcipher_codec_pragma: db=0x4037cba340 iDb=0 pParse=0x40017fef90 zLeft=encoding zRight=(null) ctx=0x40378aaf90
sqlite3Codec: pgno=1, mode=3, page_sz=1024
sqlcipher_cipher_ctx_key_derive: ctx->kdf_salt_sz=16 ctx->kdf_iter=64000 ctx->fast_kdf_iter=2 ctx->key_sz=32
cipher_ctx_key_derive: key material is not present on the context for key derivation
sqlcipher_codec_key_derive: error occurred deriving read_ctx key
sqlite3Codec: error occurred during key derivation: 1
sqlcipher_codec_ctx_set_error: ctx=0x40378aaf90, error=1

executing PRAGMA cipher_hmac_algorithm = HMAC_SHA1

sqlcipher_codec_pragma: db=0x4037cba340 iDb=0 pParse=0x40017ff6c0 zLeft=cipher_hmac_algorithm zRight=HMAC_SHA1 ctx=0x40378aaf90
sqlcipher_codec_ctx_reserve_setup: base_reserve=16 block_sz=16 md_size=20 reserve=48
codec_set_btree_to_codec_pagesize: sqlite3BtreeSetPageSize() size=1024 reserve=48
codec_set_btree_to_codec_pagesize: entering database mutex 0x403651a2c0
codec_set_btree_to_codec_pagesize: entered database mutex 0x403651a2c0
codec_set_btree_to_codec_pagesize: sqlite3BtreeSetPageSize returned 0
codec_set_btree_to_codec_pagesize: leaving database mutex 0x403651a2c0
codec_set_btree_to_codec_pagesize: left database mutex 0x403651a2c0
sqlcipher_codec_pragma: db=0x4037cba340 iDb=0 pParse=0x40017fef90 zLeft=encoding zRight=(null) ctx=0x40378aaf90
sqlite3Codec: pgno=1, mode=3, page_sz=1024
sqlcipher_cipher_ctx_key_derive: ctx->kdf_salt_sz=16 ctx->kdf_iter=64000 ctx->fast_kdf_iter=2 ctx->key_sz=32
cipher_ctx_key_derive: key material is not present on the context for key derivation
sqlcipher_codec_key_derive: error occurred deriving read_ctx key
sqlite3Codec: error occurred during key derivation: 1
sqlcipher_codec_ctx_set_error: ctx=0x40378aaf90, error=1

executing PRAGMA cipher_kdf_algorithm = PBKDF2_HMAC_SHA1

2022-09-27 15:30:08.688: sqlcipher_codec_pragma: db=0x4037cba340 iDb=0 pParse=0x40017ff6c0 zLeft=cipher_kdf_algorithm zRight=PBKDF2_HMAC_SHA1 ctx=0x40378aaf90
2022-09-27 15:30:08.688: sqlcipher_codec_pragma: db=0x4037cba340 iDb=0 pParse=0x40017fef90 zLeft=encoding zRight=(null) ctx=0x40378aaf90
sqlite3Codec: pgno=1, mode=3, page_sz=1024
sqlcipher_cipher_ctx_key_derive: ctx->kdf_salt_sz=16 ctx->kdf_iter=64000 ctx->fast_kdf_iter=2 ctx->key_sz=32
cipher_ctx_key_derive: key material is not present on the context for key derivation
sqlcipher_codec_key_derive: error occurred deriving read_ctx key
sqlite3Codec: error occurred during key derivation: 1
sqlcipher_codec_ctx_set_error: ctx=0x40378aaf90, error=1

executing ATTACH DATABASE ‘db/companies/7/company.sqlite.sqlcipher4.sqlite’ AS sqlcipher4 KEY ‘PASSWORD’

sqlcipher_codec_pragma: db=0x4037cba340 iDb=0 pParse=0x40017fef90 zLeft=encoding zRight=(null) ctx=0x40378aaf90
sqlite3Codec: pgno=1, mode=3, page_sz=1024
sqlcipher_cipher_ctx_key_derive: ctx->kdf_salt_sz=16 ctx->kdf_iter=64000 ctx->fast_kdf_iter=2 ctx->key_sz=32
cipher_ctx_key_derive: key material is not present on the context for key derivation
sqlcipher_codec_key_derive: error occurred deriving read_ctx key
sqlite3Codec: error occurred during key derivation: 1
sqlcipher_codec_ctx_set_error: ctx=0x40378aaf90, error=1
sqlcipherCodecAttach: db=0x4037cba340, nDb=2
sqlcipherCodecAttach: calling sqlcipher_activate()
sqlcipher_activate: entering static master mutex
sqlcipher_activate: entered static master mutex
sqlcipher_activate: leaving static master mutex
sqlcipher_activate: left static master mutex
sqlcipherCodecAttach: entering database mutex 0x403651a2c0
sqlcipherCodecAttach: entered database mutex 0x403651a2c0
sqlcipherCodecAttach: calling sqlcipher_codec_ctx_init()
sqlcipher_codec_ctx_init: allocating context
sqlcipher_malloc: calling sqlite3Malloc(136)
sqlcipher_malloc: calling sqlcipher_memset(0x403722aa10,0,136)
sqlcipher_memset: setting 0x403722aa10[0-136]=0)
sqlcipher_mem_lock: calling mlock(0x403722a000,2712); _SC_PAGESIZE=4096
sqlcipher_codec_ctx_init: allocating kdf_salt
sqlcipher_malloc: calling sqlite3Malloc(16)
sqlcipher_malloc: calling sqlcipher_memset(0x4036a4fb40,0,16)
sqlcipher_memset: setting 0x4036a4fb40[0-16]=0)
sqlcipher_mem_lock: calling mlock(0x4036a4f000,2896); _SC_PAGESIZE=4096
sqlcipher_codec_ctx_init: allocating hmac_kdf_salt
sqlcipher_malloc: calling sqlite3Malloc(16)
sqlcipher_malloc: calling sqlcipher_memset(0x4037ba7370,0,16)
sqlcipher_memset: setting 0x4037ba7370[0-16]=0)
sqlcipher_mem_lock: calling mlock(0x4037ba7000,896); _SC_PAGESIZE=4096
sqlcipher_codec_ctx_init: allocating provider
sqlcipher_malloc: calling sqlite3Malloc(136)
sqlcipher_malloc: calling sqlcipher_memset(0x403722aaa0,0,136)
sqlcipher_memset: setting 0x403722aaa0[0-136]=0)
sqlcipher_mem_lock: calling mlock(0x403722a000,2856); _SC_PAGESIZE=4096
sqlcipher_codec_ctx_init: entering SQLCIPHER_MUTEX_PROVIDER
sqlcipher_codec_ctx_init: entered SQLCIPHER_MUTEX_PROVIDER
sqlcipher_codec_ctx_init: leaving SQLCIPHER_MUTEX_PROVIDER
sqlcipher_codec_ctx_init: left SQLCIPHER_MUTEX_PROVIDER
sqlcipher_openssl_activate: entering SQLCIPHER_MUTEX_PROVIDER_ACTIVATE
sqlcipher_openssl_activate: entered SQLCIPHER_MUTEX_PROVIDER_ACTIVATE
sqlcipher_openssl_activate: leaving SQLCIPHER_MUTEX_PROVIDER_ACTIVATE
sqlcipher_openssl_activate: left SQLCIPHER_MUTEX_PROVIDER_ACTIVATE
sqlcipher_free: calling sqlcipher_memset((nil),0,0)
sqlcipher_malloc: calling sqlite3Malloc(4096)
sqlcipher_malloc: calling sqlcipher_memset(0x40374c5070,0,4096)
sqlcipher_memset: setting 0x40374c5070[0-4096]=0)
sqlcipher_mem_lock: calling mlock(0x40374c5000,4208); _SC_PAGESIZE=4096
sqlcipher_codec_ctx_reserve_setup: base_reserve=16 block_sz=16 md_size=64 reserve=80
sqlcipher_codec_ctx_reserve_setup: base_reserve=16 block_sz=16 md_size=64 reserve=80
sqlcipher_cipher_ctx_init: allocating context
sqlcipher_malloc: calling sqlite3Malloc(40)
sqlcipher_malloc: calling sqlcipher_memset(0x4036a4fb60,0,40)
sqlcipher_memset: setting 0x4036a4fb60[0-40]=0)
sqlcipher_mem_lock: calling mlock(0x4036a4f000,2952); _SC_PAGESIZE=4096
sqlcipher_cipher_ctx_init: allocating key
sqlcipher_malloc: calling sqlite3Malloc(32)
sqlcipher_malloc: calling sqlcipher_memset(0x4037216e00,0,32)
sqlcipher_memset: setting 0x4037216e00[0-32]=0)
sqlcipher_mem_lock: calling mlock(0x4037216000,3616); _SC_PAGESIZE=4096
sqlcipher_cipher_ctx_init: allocating hmac_key
sqlcipher_malloc: calling sqlite3Malloc(32)
sqlcipher_malloc: calling sqlcipher_memset(0x4037ba7210,0,32)
sqlcipher_memset: setting 0x4037ba7210[0-32]=0)
sqlcipher_mem_lock: calling mlock(0x4037ba7000,560); _SC_PAGESIZE=4096
sqlcipher_cipher_ctx_init: allocating context
sqlcipher_malloc: calling sqlite3Malloc(40)
sqlcipher_malloc: calling sqlcipher_memset(0x4037ba71e0,0,40)
sqlcipher_memset: setting 0x4037ba71e0[0-40]=0)
sqlcipher_mem_lock: calling mlock(0x4037ba7000,520); _SC_PAGESIZE=4096
sqlcipher_cipher_ctx_init: allocating key
sqlcipher_malloc: calling sqlite3Malloc(32)
sqlcipher_malloc: calling sqlcipher_memset(0x40362f4fe0,0,32)
sqlcipher_memset: setting 0x40362f4fe0[0-32]=0)
sqlcipher_mem_lock: calling mlock(0x40362f4000,4096); _SC_PAGESIZE=4096
sqlcipher_cipher_ctx_init: allocating hmac_key
sqlcipher_malloc: calling sqlite3Malloc(32)
sqlcipher_malloc: calling sqlcipher_memset(0x4036a4f900,0,32)
sqlcipher_memset: setting 0x4036a4f900[0-32]=0)
sqlcipher_mem_lock: calling mlock(0x4036a4f000,2336); _SC_PAGESIZE=4096
sqlcipher_free: calling sqlcipher_memset((nil),0,0)
sqlcipher_malloc: calling sqlite3Malloc(21)
sqlcipher_malloc: calling sqlcipher_memset(0x4037b53ef0,0,21)
sqlcipher_memset: setting 0x4037b53ef0[0-21]=0)
sqlcipher_mem_lock: calling mlock(0x4037b53000,3845); _SC_PAGESIZE=4096
sqlcipher_cipher_ctx_copy: target=0x4037ba71e0, source=0x4036a4fb60
sqlcipher_free: calling sqlcipher_memset((nil),0,0)
sqlcipher_free: calling sqlcipher_memset((nil),0,99)
sqlcipher_malloc: calling sqlite3Malloc(21)
sqlcipher_malloc: calling sqlcipher_memset(0x4037112a00,0,21)
sqlcipher_memset: setting 0x4037112a00[0-21]=0)
sqlcipher_mem_lock: calling mlock(0x4037112000,2581); _SC_PAGESIZE=4096
sqlcipherCodecAttach: calling sqlcipherPagerSetCodec()
sqlcipherCodecAttach: calling codec_set_btree_to_codec_pagesize()
codec_set_btree_to_codec_pagesize: sqlite3BtreeSetPageSize() size=4096 reserve=80
codec_set_btree_to_codec_pagesize: entering database mutex 0x403651a2c0
codec_set_btree_to_codec_pagesize: entered database mutex 0x403651a2c0
codec_set_btree_to_codec_pagesize: sqlite3BtreeSetPageSize returned 0
codec_set_btree_to_codec_pagesize: leaving database mutex 0x403651a2c0
codec_set_btree_to_codec_pagesize: left database mutex 0x403651a2c0
sqlcipherCodecAttach: calling sqlite3BtreeSecureDelete()
sqlcipherCodecAttach: calling sqlite3BtreeSetAutoVacuum()
sqlcipherCodecAttach: leaving database mutex 0x403651a2c0
sqlcipherCodecAttach: left database mutex 0x403651a2c0
sqlite3Codec: pgno=1, mode=3, page_sz=1024
sqlcipher_cipher_ctx_key_derive: ctx->kdf_salt_sz=16 ctx->kdf_iter=64000 ctx->fast_kdf_iter=2 ctx->key_sz=32
cipher_ctx_key_derive: key material is not present on the context for key derivation
sqlcipher_codec_key_derive: error occurred deriving read_ctx key
sqlite3Codec: error occurred during key derivation: 1
sqlcipher_codec_ctx_set_error: ctx=0x40378aaf90, error=1
codec_ctx_free: iCtx=0x40017fea40
sqlcipher_free: calling sqlcipher_memset(0x4036a4fb40,0,16)
sqlcipher_memset: setting 0x4036a4fb40[0-16]=0)
sqlcipher_mem_unlock: calling munlock(0x4036a4f000,2896)
sqlcipher_free: calling sqlcipher_memset(0x4037ba7370,0,16)
sqlcipher_memset: setting 0x4037ba7370[0-16]=0)
sqlcipher_mem_unlock: calling munlock(0x4037ba7000,896)
sqlcipher_free: calling sqlcipher_memset(0x40374c5070,0,4096)
sqlcipher_memset: setting 0x40374c5070[0-4096]=0)
sqlcipher_mem_unlock: calling munlock(0x40374c5000,4208)
sqlcipher_openssl_deactivate: entering SQLCIPHER_MUTEX_PROVIDER_ACTIVATE
sqlcipher_openssl_deactivate: entered SQLCIPHER_MUTEX_PROVIDER_ACTIVATE
sqlcipher_openssl_deactivate: leaving SQLCIPHER_MUTEX_PROVIDER_ACTIVATE
sqlcipher_openssl_deactivate: left SQLCIPHER_MUTEX_PROVIDER_ACTIVATE
sqlcipher_free: calling sqlcipher_memset(0x403722aaa0,0,136)
sqlcipher_memset: setting 0x403722aaa0[0-136]=0)
sqlcipher_mem_unlock: calling munlock(0x403722a000,2856)
cipher_ctx_free: iCtx=0x403722aa78
sqlcipher_free: calling sqlcipher_memset(0x4037216e00,0,32)
sqlcipher_memset: setting 0x4037216e00[0-32]=0)
sqlcipher_mem_unlock: calling munlock(0x4037216000,3616)
sqlcipher_free: calling sqlcipher_memset(0x4037ba7210,0,32)
sqlcipher_memset: setting 0x4037ba7210[0-32]=0)
sqlcipher_mem_unlock: calling munlock(0x4037ba7000,560)
sqlcipher_free: calling sqlcipher_memset(0x4037b53ef0,0,21)
sqlcipher_memset: setting 0x4037b53ef0[0-21]=0)
sqlcipher_mem_unlock: calling munlock(0x4037b53000,3845)
sqlcipher_free: calling sqlcipher_memset((nil),0,99)
sqlcipher_free: calling sqlcipher_memset(0x4036a4fb60,0,40)
sqlcipher_memset: setting 0x4036a4fb60[0-40]=0)
sqlcipher_mem_unlock: calling munlock(0x4036a4f000,2952)
cipher_ctx_free: iCtx=0x403722aa80
sqlcipher_free: calling sqlcipher_memset(0x40362f4fe0,0,32)
sqlcipher_memset: setting 0x40362f4fe0[0-32]=0)
sqlcipher_mem_unlock: calling munlock(0x40362f4000,4096)
sqlcipher_free: calling sqlcipher_memset(0x4036a4f900,0,32)
sqlcipher_memset: setting 0x4036a4f900[0-32]=0)
sqlcipher_mem_unlock: calling munlock(0x4036a4f000,2336)
sqlcipher_free: calling sqlcipher_memset(0x4037112a00,0,21)
sqlcipher_memset: setting 0x4037112a00[0-21]=0)
sqlcipher_mem_unlock: calling munlock(0x4037112000,2581)
sqlcipher_free: calling sqlcipher_memset((nil),0,99)
sqlcipher_free: calling sqlcipher_memset(0x4037ba71e0,0,40)
sqlcipher_memset: setting 0x4037ba71e0[0-40]=0)
sqlcipher_mem_unlock: calling munlock(0x4037ba7000,520)
sqlcipher_free: calling sqlcipher_memset(0x403722aa10,0,136)
sqlcipher_memset: setting 0x403722aa10[0-136]=0)
sqlcipher_mem_unlock: calling munlock(0x403722a000,2712)
sqlcipher_deactivate: entering static master mutex
sqlcipher_deactivate: entered static master mutex
sqlcipher_deactivate: leaving static master mutex
sqlcipher_deactivate: left static master mutex
Traceback (most recent call last):
16: from /…/bundle/ruby/2.6.0/gems/activesupport-4.2.10/lib/active_support/dependencies.rb:274:in block in require' 15: from /.../bundle/ruby/2.6.0/gems/activesupport-4.2.10/lib/active_support/dependencies.rb:274:in require’
14: from /…/bundle/ruby/2.6.0/gems/railties-4.2.10/lib/rails/commands.rb:17:in <top (required)>' 13: from /.../bundle/ruby/2.6.0/gems/railties-4.2.10/lib/rails/commands/commands_tasks.rb:39:in run_command!’
12: from /…/bundle/ruby/2.6.0/gems/railties-4.2.10/lib/rails/commands/commands_tasks.rb:68:in console' 11: from /.../bundle/ruby/2.6.0/gems/railties-4.2.10/lib/rails/commands/console.rb:9:in start’
10: from /…/bundle/ruby/2.6.0/gems/railties-4.2.10/lib/rails/commands/console.rb:110:in start' 9: from (irb):7 8: from /var/www/lib/content/database/company_content.rb:75:in forced_sqlcipher4_cipher_migrate’
7: from /…/bundle/ruby/2.6.0/bundler/gems/sqlite3-ruby-31ea0084ced0/lib/sqlite3/database.rb:198:in execute' 6: from /.../bundle/ruby/2.6.0/bundler/gems/sqlite3-ruby-31ea0084ced0/lib/sqlite3/database.rb:156:in prepare’
5: from /…/bundle/ruby/2.6.0/bundler/gems/sqlite3-ruby-31ea0084ced0/lib/sqlite3/database.rb:207:in block in execute' 4: from /.../bundle/ruby/2.6.0/bundler/gems/sqlite3-ruby-31ea0084ced0/lib/sqlite3/database.rb:207:in to_a’
3: from /…/bundle/ruby/2.6.0/bundler/gems/sqlite3-ruby-31ea0084ced0/lib/sqlite3/resultset.rb:133:in each' 2: from /.../bundle/ruby/2.6.0/bundler/gems/sqlite3-ruby-31ea0084ced0/lib/sqlite3/resultset.rb:108:in next’
1: from /…/bundle/ruby/2.6.0/bundler/gems/sqlite3-ruby-31ea0084ced0/lib/sqlite3/resultset.rb:108:in `step’
SQLite3::MemoryException (out of memory)

Note this is a small database so being out of memory for sure is not because it is an unusually large database.

4

@sjlombardo Do any of those errors in my previous post for the manual migration steps jump out as being an obvious reason for what might be happening when using the gem linked to sqlcipher and what settings/similar might need to be adjusted so it works?

5

Well I would l really be interested to hear suggestions for what to try differently to get the sqlite3 gem to perform the cipher_migrate or manual migration steps to work. If someone does have ideas of things to try, I would be up for testing suggestions. It seems like it is some combination of settings or something that need to be messed with so it works as expected.

In the meantime, I have a workaround of just interacting with sqlcipher at the system level from ruby to perform the migration as follows:

system("sqlcipher","#{db_file_path}","PRAGMA key='#{db_key}';PRAGMA cipher_migrate;")

For those further interested in a ruby setup for this, here is a simple sample class for all of the steps together to open, test, migrate if test fails (using system sqlcipher command), etc.

require 'sqlite3'
class EncryptedContent
    
    attr_accessor :db, :db_key, :db_file_path

    def initialize(db_key,file_path)
        self.db_key = db_key
        self.db_file_path = file_path
        open_db
    end

    # use sqlcipher system command to cipher migrate the db
    def cipher_migrate_using_system_sqlcipher
        system("sqlcipher","#{db_file_path}","PRAGMA key='#{db_key}';PRAGMA cipher_migrate;")
    end

    # test the db connection by running a simple query
    def test_db_connection
        result = db.execute("SELECT count(*) FROM sqlite_master;") rescue nil
        result.present?
    end

    # set the db key
    def set_db_key
        db.execute("PRAGMA key='#{db_key}';")
    end

    # open the db connection
    def open_db
        self.db = SQLite3::Database.new db_file_path
        set_db_key
        unless test_db_connection
            db.close
            cipher_migrate_using_system_sqlcipher
            self.db = SQLite3::Database.new db_file_path
            set_db_key
        end
    end

end

Note: the above works with sqlite3 v1.5.0 ruby gem and sqlcipher 4.5.2. installed.

Further lessons learned here:

To hopefully save someone else some time I lost (and hair pulling), since v1.5.0 of the gem there are now precompiled versions loaded into RubyGems which will be selected when you bundle by default. This means there is no native build step anymore by default so you won’t be able to link it to sqlcipher unless you override this. So, if you plan to use the gem with sqlcipher you must install the gem specifically for the ruby platform vs one of the many precompiled platform specific versions. This is documented here

In our case we are using bundler v1.17.3 and those instructions say for v2.0 or older to use bundle config force_ruby_platform true meaning that ALL of your gems that have native build options will be forced to be built which is not what we wanted because we have over a dozen gems that we prefer to use the precompiled versions when available (saves time and pain of fixing dependency issues). And using platform: :ruby in the Gemfile was not enough to tell bundler with RubyGems to do what we wanted.

The solution we found was to tell bundler (at least on the older version we are using) to use git and Github as the source (as opposed to RubyGems) and then finally it would build natively:

in Gemfile

gem 'sqlite3', '1.5.0', platforms: :ruby, git: 'https://github.com/sparklemotion/sqlite3-ruby.git', tag: 'v1.5.0'

and don’t forget to tell bundler to build the gem with --with-sqlicpher

bundle config --local build.sqlite3 '--with-sqlcipher'

You also need to be mindful of where the sqlcipher library flles get installed and if in a non-standard location you need to add those to the build config. This is documented here.

In our case for installation of sqlcipher was as identified with a prefix of /usr in the original post, so apparently it is standard since we didn’t use the other build config options.

6

Hello @patakijv - I have reviewed the logs and I suspect the problem is that something is manipulating the file encoding, e.g.

sqlcipher_codec_pragma: db=0x4037cba340 iDb=0 pParse=0x40017fef90 zLeft=encoding zRight=(null) ctx=0x40378aaf90
sqlite3Codec: pgno=1, mode=3, page_sz=1024

Encoding updates would trigger access to the database, causing key derivation to run. I haven’t poured through the code, but it does seem like there is a fair bit of code managing encoding in the library, even in the native .c files. This makes me wonder whether there is something forcing encoding during the execution of a statement. Do you have any insight on that?

7

@sjlombardo

Hmm… I don’t necessarily have insight… but I am willing to help dig around … if by encoding, if you look at this line of the initialization method where it calls the underlying sqlite3 open_v2 method, I see it shows file.encode("utf-8") as the first argument. Is this what you mean by encoding? I thought that was just encoding the file path string, not the file contents. What do you think?

The first argument into the method is a string and the encode method is for strings.

irb(main):001:0> file="/some/path/to/db.sqlite"
=> "/some/path/to/db.sqlite"
irb(main):002:0> file.encode("utf-8")
=> "/some/path/to/db.sqlite"

Maybe you are not referring to this reference to encoding.

According to documentation on sqlite3 open

The default encoding will be UTF-8 for databases created using sqlite3_open() or sqlite3_open_v2(). The default encoding for databases created using sqlite3_open16() will be UTF-16 in the native byte order.

Are you suspecting that the encoding should be different than UTF-8?

8

Hello @patakijv - I agree that the file.encode is just dealing with the file name. The encoding I’m referring to is the database encoding, i.e. PRAGMA encoding. You can see from the logs in several places a line like this:

sqlcipher_codec_pragma: db=0x4037cba340 iDb=0 pParse=0x40017fef90 zLeft=encoding zRight=(null) ctx=0x40378aaf90

This line indicates that PRAGMA encoding is being invoked. Since encoding settings are stored in the database header SQLCipher will read the first page invoking key derivation and making migration or setting changes impossible.

Looking closer at the code, I believe the library is be checking the database encoding when stepping in order to handle conversions in statement.c. That check is in turn invoking PRAGMA encoding on the database handle in database.c.

That being the case, one possible workaround would be to invoke PRAGMA cipher_migrate using db.execute_batch2 function instead of db.execute. execute_batch2 appears to avoid using the prepare / step interface and instead passes the SQL statements directly to sqlite3_exec without any encoding checks.