search

cossacklabs / acra

Database security suite. Database proxy with field-level encryption, search through encrypted data, SQL injections prevention, intrusion detection, honeypots. Supports client-side and proxy-side ("transparent") encryption. SQL, NoSQL.
https://www.cossacklabs.com/acra/
Apache License 2.0
1.32k stars 128 forks source link

[ISSUE] Tokenization in MariaDB #648

Closed afrizaloky closed 11 months ago

afrizaloky commented 1 year ago

Describe the bug There is problem/bug in mariadb if a column use tokenization. I dont see this error in postgresql.

To Reproduce Steps to reproduce the behavior:

  1. This is my table structure MariaDB [test]> describe customer; +-------+--------------+------+-----+---------+-------+ | Field | Type | Null | Key | Default | Extra | +-------+--------------+------+-----+---------+-------+ | name | varchar(255) | YES | | NULL | | | email | longblob | YES | | NULL | | +-------+--------------+------+-----+---------+-------+
  2. This is my encryption config 
    schemas:
- table: customer
columns:
- name
- email
encrypted:
- column: email
token_type: email
  3. This is the log debug 
    time="2023-04-17T07:22:04Z" level=info msg="Starting service acra-server [pid=1793]" version=0.95.0
time="2023-04-17T07:22:04Z" level=info msg="Validating service configuration..."
time="2023-04-17T07:22:04Z" level=info msg="Load encryptor configuration from /go/sgkms-proxy.yml ..."
time="2023-04-17T07:22:04Z" level=info msg="Encryptor configuration loaded"
time="2023-04-17T07:22:04Z" level=info msg="Initialising keystore..."
time="2023-04-17T07:22:04Z" level=info msg="Initializing default env ACRA_MASTER_KEY loader"
time="2023-04-17T07:22:04Z" level=warning msg="Ignoring legacy key" KeyID=token.db
time="2023-04-17T07:22:04Z" level=info msg="Cached keystore on start successfully"
time="2023-04-17T07:22:04Z" level=info msg="Keystore init OK" path=.acrakeys
time="2023-04-17T07:22:04Z" level=info msg="Configuring transport..."
time="2023-04-17T07:22:04Z" level=info msg="Use sni" sni=""
time="2023-04-17T07:22:04Z" level=info msg="Use sni" sni=mysql
time="2023-04-17T07:22:04Z" level=info msg="Loaded TLS configuration" tls_client_id_from_cert=true
time="2023-04-17T07:22:04Z" level=info msg="Initialize bolt db storage for tokens"
time="2023-04-17T07:22:04Z" level=info msg="Initialized bolt db storage for tokens"
time="2023-04-17T07:22:04Z" level=info msg="Initialized SQL query parser in default mode"
time="2023-04-17T07:22:04Z" level=info msg="Start listening to connections. Current PID: 1793"
time="2023-04-17T07:22:04Z" level=info msg="Enabling DEBUG log level"
time="2023-04-17T07:22:04Z" level=info msg="Create listener" connection_string="tcp://0.0.0.0:9393/" from_descriptor=false
time="2023-04-17T07:22:04Z" level=info msg="Start listening connections" connection_string="tcp://0.0.0.0:9393/" from_descriptor=false
time="2023-04-17T07:22:13Z" level=info msg="Got new connection to AcraServer: 172.22.0.1:48372" connection_string="tcp://0.0.0.0:9393/" from_descriptor=false
time="2023-04-17T07:22:13Z" level=debug msg="ConnectionManager Added new connection"
time="2023-04-17T07:22:13Z" level=info msg="Handle client's connection" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Connecting to db" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Start proxy db responses" client_id="" proxy=server session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Start proxy client's requests" client_id="" proxy=client session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="New packet from db to client" client_id="" sequence_number=0 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Set support protocol 41 true" client_id="" proxy=server session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="OCSP: Verifying 'CN=acra-client,OU=HQ,O=cossacklabs,L=London,ST=London,C=GB'"
time="2023-04-17T07:22:13Z" level=debug msg="CRL: Verifying 'CN=acra-client,OU=HQ,O=cossacklabs,L=London,ST=London,C=GB'"
time="2023-04-17T07:22:13Z" level=debug msg=verifyPeerCertificate error="<nil>" valid=true
time="2023-04-17T07:22:13Z" level=debug msg="ID from certificate" identifier="CN=acra-client,OU=HQ,O=cossacklabs,L=London,ST=London,C=GB"
time="2023-04-17T07:22:13Z" level=debug msg="ClientID from certificate" clientID=1ec6f16c36e6a3f1a064d708cba5b1ca760ba5ae29d3d80aab67b043ca641255c21ddf8f0fb09a8de336d555b4b961953200c7125f745cff7ed577f7c4b555c4
time="2023-04-17T07:22:13Z" level=debug msg="ClientID from certificate" clientID=1ec6f16c36e6a3f1a064d708cba5b1ca760ba5ae29d3d80aab67b043ca641255c21ddf8f0fb09a8de336d555b4b961953200c7125f745cff7ed577f7c4b555c4
time="2023-04-17T07:22:13Z" level=debug msg="Set new clientID" client_id="[49 101 99 54 102 49 54 99 51 54 101 54 97 51 102 49 97 48 54 52 100 55 48 56 99 98 97 53 98 49 99 97 55 54 48 98 97 53 97 101 50 57 100 51 100 56 48 97 97 98 54 55 98 48 52 51 99 97 54 52 49 50 53 53 99 50 49 100 100 102 56 102 48 102 98 48 57 97 56 100 101 51 51 54 100 53 53 53 98 52 98 57 54 49 57 53 51 50 48 48 99 55 49 50 53 102 55 52 53 99 102 102 55 101 100 53 55 55 102 55 99 52 98 53 53 53 99 52]" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Switched to tls with client. wait switching with db" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="OCSP: Verifying 'CN=mysql,OU=HQ,O=cossacklabs,L=London,ST=London,C=GB'"
time="2023-04-17T07:22:13Z" level=debug msg="CRL: Verifying 'CN=mysql,OU=HQ,O=cossacklabs,L=London,ST=London,C=GB'"
time="2023-04-17T07:22:13Z" level=debug msg=verifyPeerCertificate error="<nil>" valid=true
time="2023-04-17T07:22:13Z" level=debug msg="Switched to tls with db" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Switch to tls complete on client proxy side" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="New packet" client_id="" deprecate_eof=false proxy=client sequence_number=2 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Command 140 not supported now" client_id="" deprecate_eof=false proxy=client sequence_number=2 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="New packet from db to client" client_id="" sequence_number=3 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="New packet" client_id="" deprecate_eof=false proxy=client sequence_number=0 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Query command" client_id="" command=3 deprecate_eof=false proxy=client sequence_number=0 session_id=1 sql="show databases"
time="2023-04-17T07:22:13Z" level=debug msg=TokenizeQuery.OnQuery
time="2023-04-17T07:22:13Z" level=debug msg="Unsupported search query"
time="2023-04-17T07:22:13Z" level=debug msg="New packet from db to client" client_id="" sequence_number=1 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Read column descriptions" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Read column description" client_id="" column_index=0 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Parse field" client_id="" column_index=0 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Read column description" client_id="" column_index=1 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Read data rows" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Read data row" client_id="" data_row_index=0 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Process data text row" client_id="" data_row_index=0 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Process data rows in text protocol" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="OnColumn: Try to decrypt SerializedContainer"
time="2023-04-17T07:22:13Z" level=debug msg="OnColumn: Try to decrypt AcraBlock"
time="2023-04-17T07:22:13Z" level=debug msg="Encode text" client_id="" column="" decrypted=false session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Finish processing text data row" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Update row data" client_id="" data_row_index=0 newLength=19 oldLength=19 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Read data row" client_id="" data_row_index=1 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Process data text row" client_id="" data_row_index=1 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Process data rows in text protocol" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="OnColumn: Try to decrypt SerializedContainer"
time="2023-04-17T07:22:13Z" level=debug msg="OnColumn: Try to decrypt AcraBlock"
time="2023-04-17T07:22:13Z" level=debug msg="Encode text" client_id="" column="" decrypted=false session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Finish processing text data row" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Update row data" client_id="" data_row_index=1 newLength=6 oldLength=6 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Read data row" client_id="" data_row_index=2 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Process data text row" client_id="" data_row_index=2 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Process data rows in text protocol" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="OnColumn: Try to decrypt SerializedContainer"
time="2023-04-17T07:22:13Z" level=debug msg="OnColumn: Try to decrypt AcraBlock"
time="2023-04-17T07:22:13Z" level=debug msg="Encode text" client_id="" column="" decrypted=false session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Finish processing text data row" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Update row data" client_id="" data_row_index=2 newLength=19 oldLength=19 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Read data row" client_id="" data_row_index=3 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Process data text row" client_id="" data_row_index=3 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Process data rows in text protocol" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="OnColumn: Try to decrypt SerializedContainer"
time="2023-04-17T07:22:13Z" level=debug msg="OnColumn: Try to decrypt AcraBlock"
time="2023-04-17T07:22:13Z" level=debug msg="Encode text" client_id="" column="" decrypted=false session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Finish processing text data row" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Update row data" client_id="" data_row_index=3 newLength=4 oldLength=4 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Read data row" client_id="" data_row_index=4 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Process data text row" client_id="" data_row_index=4 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Process data rows in text protocol" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="OnColumn: Try to decrypt SerializedContainer"
time="2023-04-17T07:22:13Z" level=debug msg="OnColumn: Try to decrypt AcraBlock"
time="2023-04-17T07:22:13Z" level=debug msg="Encode text" client_id="" column="" decrypted=false session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Finish processing text data row" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Update row data" client_id="" data_row_index=4 newLength=5 oldLength=5 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Read data row" client_id="" data_row_index=5 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Empty result set" client_id="" data_row_index=5 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Proxy output" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Query handler finish" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="New packet" client_id="" deprecate_eof=false proxy=client sequence_number=0 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Query command" client_id="" command=3 deprecate_eof=false proxy=client sequence_number=0 session_id=1 sql="show tables"
time="2023-04-17T07:22:13Z" level=debug msg=TokenizeQuery.OnQuery
time="2023-04-17T07:22:13Z" level=debug msg="Unsupported search query"
time="2023-04-17T07:22:13Z" level=debug msg="New packet from db to client" client_id="" sequence_number=1 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Read column descriptions" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Read column description" client_id="" column_index=0 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Parse field" client_id="" column_index=0 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Read column description" client_id="" column_index=1 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Read data rows" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Read data row" client_id="" data_row_index=0 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Process data text row" client_id="" data_row_index=0 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Process data rows in text protocol" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="OnColumn: Try to decrypt SerializedContainer"
time="2023-04-17T07:22:13Z" level=debug msg="OnColumn: Try to decrypt AcraBlock"
time="2023-04-17T07:22:13Z" level=debug msg="Encode text" client_id="" column="" decrypted=false session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Finish processing text data row" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Update row data" client_id="" data_row_index=0 newLength=9 oldLength=9 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Read data row" client_id="" data_row_index=1 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Empty result set" client_id="" data_row_index=1 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Proxy output" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Query handler finish" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="New packet" client_id="" deprecate_eof=false proxy=client sequence_number=0 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Command 4 not supported now" client_id="" deprecate_eof=false proxy=client sequence_number=0 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="New packet from db to client" client_id="" sequence_number=1 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="New packet from db to client" client_id="" sequence_number=2 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="New packet from db to client" client_id="" sequence_number=3 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="New packet" client_id="" deprecate_eof=false proxy=client sequence_number=0 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Query command" client_id="" command=3 deprecate_eof=false proxy=client sequence_number=0 session_id=1 sql="select * from customer"
time="2023-04-17T07:22:13Z" level=debug msg=TokenizeQuery.OnQuery
time="2023-04-17T07:22:13Z" level=debug msg="New packet from db to client" client_id="" sequence_number=1 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Read column descriptions" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Read column description" client_id="" column_index=0 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Parse field" client_id="" column_index=0 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Read column description" client_id="" column_index=1 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Parse field" client_id="" column_index=1 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Binary field" client_id="" column_index=1 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Read column description" client_id="" column_index=2 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Read data rows" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Read data row" client_id="" data_row_index=0 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Empty result set" client_id="" data_row_index=0 session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Proxy output" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Query handler finish" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Can't read packet from client" client_id="" code=571 error=EOF session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Stop to proxy" client_id="" interrupt_side=Client-AcraServer session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="EOF connection closed" client_id="" interrupt_side=Client-AcraServer session_id=1
time="2023-04-17T07:22:13Z" level=info msg="Closing client's connection" client_id="" interrupt_side=Client-AcraServer session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Close acra-connector connection" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Close db connection" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Can't read packet from server" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="All connections closed" client_id="" session_id=1
time="2023-04-17T07:22:13Z" level=debug msg="Second proxy goroutine stopped" client_id="" error="AcraServer-Database:read tcp 172.22.0.3:34736->172.17.0.1:3306: use of closed network connection" interrupt_side=Client-AcraServer session_id=1
time="2023-04-17T07:22:13Z" level=info msg="Finished processing client's connection" client_id="" interrupt_side=Client-AcraServer session_id=1
  4. You will see the error when query to database, for example SELECT * FROM customer;. mysql client will show this error 
    
ERROR 2006 (HY000): MySQL server has gone away
No connection. Trying to reconnect...
Connection id:    8
Current database: test

ERROR 2013 (HY000): Lost connection to MySQL server during query



**Expected behavior**
Tokenization column should be work in mariadb.

**Acra configuration files**
For AcraServer: 
    - [ ] configuration file or CLI params that you use to start AcraServer; 
    ``` go run cmd/acra-server/acra-server.go   --mysql_enable   --db_host=mysql   --db_port=3306   --token_db=.acrakeys/token.db   --keys_dir=.acrakeys   --tls_auth=4   --tls_identifier_extractor_type=distinguished_name   --tls_ca=/go/example.cossacklabs.com.crt   --tls_cert=/go/acra-server.crt   --tls_key=/go/acra-server.key   --tls_client_id_from_cert=true   --encryptor_config_file=/go/encryptor_config.yml -d -v ```

**Environment**
- Acra version: 0.95
- Database server and its version: mariadb:10.7.1
- Installed components:
   - AcraServer
- Data-in-transit encryption between Acra and the client-side application:
   - TLS
- Installation way:
   - via Docker

**Additional**
1. This log debug doesn't show in postgresql
`time="2023-04-17T07:22:13Z" level=debug msg=TokenizeQuery.OnQuery`
vixentael commented 1 year ago

thank you @afrizaloky! we will take a look into this and try to reproduce. cc @Zhaars

Lagovas commented 1 year ago

Thanks for your report, we have successfully reproduced this case. At first, we should note that you use tokenization with email type and use longblob type for that when Acra expects some string type for that. One of the features of tokenization is the ability to use the same types and data formats for the data you protect. But anyway we should admit that your case looks like a bug from the Acra side and that case should be handled in another way by Acra. We will fix it and notify as soon as the fix will be merged into the main (master) branch.