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.33k stars 128 forks source link

AcraServer 0.93 + PostgreSQL | "Panic in connection processing" #575

Closed Machado117 closed 1 year ago

Machado117 commented 1 year ago

Hello, I have been testing Acra Server 0.92.0 with an application. Version 0.92.0 seems to be working fine. I then realized I needed some features present in the 0.93.0 release but after updating I can't no longer run my application with acra.

To Reproduce

Expected behavior Application should work as before

Acra configuration files

--client_id="test"
--db_host=postgres
--keys_dir=/keys
--tls_auth=0
--tls_client_id_from_cert=false
--postgresql_enable=true
-d

Environment (please complete the following information):

Additional context Acra server debug logs when the application crashes

time="2022-09-01T14:04:32Z" level=debug msg="New query" client_id=test prepared_name=S_4 proxy=client session_id=1 sql=begin
time="2022-09-01T14:04:32Z" level=debug msg="Registered new prepared statement" client_id=test prepared_name=S_4 proxy=client session_id=1
time="2022-09-01T14:04:32Z" level=debug msg="Read data" client_id=test proxy=client session_id=1
time="2022-09-01T14:04:32Z" level=debug msg=GetBindData client_id=test proxy=client session_id=1
time="2022-09-01T14:04:32Z" level=debug msg="Bind packet" client_id=test portal="" proxy=client session_id=1 statement=S_4
time="2022-09-01T14:04:32Z" level=debug msg="Read data" client_id=test proxy=client session_id=1
time="2022-09-01T14:04:32Z" level=debug msg=GetExecuteData client_id=test proxy=client session_id=1
time="2022-09-01T14:04:32Z" level=debug msg="Read data" client_id=test proxy=client session_id=1
time="2022-09-01T14:04:32Z" level=debug msg=GetParseData client_id=test proxy=client session_id=1
time="2022-09-01T14:04:32Z" level=debug msg="New query" client_id=test prepared_name=S_5 proxy=client session_id=1 sql="insert into blue_FDZ_CONFIGURATION(\"key\", value) values ($1, $2)"
time="2022-09-01T14:04:32Z" level=debug msg="Hasn't schema for table blue_FDZ_CONFIGURATION"
time="2022-09-01T14:04:32Z" level=debug msg="Registered new prepared statement" client_id=test prepared_name=S_5 proxy=client session_id=1
time="2022-09-01T14:04:32Z" level=debug msg="Read data" client_id=test proxy=client session_id=1
time="2022-09-01T14:04:32Z" level=debug msg="Read data" client_id=test proxy=client session_id=1
time="2022-09-01T14:04:32Z" level=debug msg="Read data length" client_id=test proxy=server session_id=1
time="2022-09-01T14:04:32Z" level=debug msg="Read data" client_id=test proxy=server session_id=1
time="2022-09-01T14:04:32Z" level=debug msg=ParseComplete parse="&{[83 95 53 0] [73 78 83 69 82 84 32 73 78 84 79 32 34 98 108 117 101 95 70 68 90 95 67 79 78 70 73 71 85 82 65 84 73 79 78 34 32 40 34 107 101 121 34 44 32 34 118 97 108 117 101 34 41 32 86 65 76 85 69 83 32 40 36 49 44 32 36 50 41 0] [0 2] [[0 0 4 19] [0 0 4 19]]}"
time="2022-09-01T14:04:32Z" level=debug msg="Read packet" client_id=test proxy=server session_id=1
time="2022-09-01T14:04:32Z" level=debug msg="Read data length" client_id=test proxy=server session_id=1
time="2022-09-01T14:04:32Z" level=debug msg="Read data" client_id=test proxy=server session_id=1
time="2022-09-01T14:04:32Z" level=error msg="Panic in connection processing, close connection" client_id=test error="runtime error: invalid memory address or nil pointer dereference" function=ProxyDatabaseConnection session_id=1
time="2022-09-01T14:04:32Z" level=debug msg="Close acra-connector connection" client_id=test session_id=1
time="2022-09-01T14:04:32Z" level=debug msg="Can't read first 5 bytes" client_id=test code=588 error="read tcp 172.30.0.8:9393->172.30.0.9:56294: use of closed network connection" proxy=client session_id=1
time="2022-09-01T14:04:32Z" level=debug msg="Can't read packet from client to database" client_id=test error="read tcp 172.30.0.8:9393->172.30.0.9:56294: use of closed network connection" proxy=client session_id=1
time="2022-09-01T14:04:32Z" level=debug msg="Stop to proxy" client_id=test interrupt_side=Client-AcraServer session_id=1
time="2022-09-01T14:04:32Z" level=error msg="Network error" client_id=test code=1100 error="read tcp 172.30.0.8:9393->172.30.0.9:56294: use of closed network connection" interrupt_side=Client-AcraServer session_id=1
time="2022-09-01T14:04:32Z" level=info msg="Closing client's connection" client_id=test interrupt_side=Client-AcraServer session_id=1
time="2022-09-01T14:04:32Z" level=debug msg="Close acra-connector connection" client_id=test session_id=1
time="2022-09-01T14:04:32Z" level=debug msg="Close db connection" client_id=test session_id=1
time="2022-09-01T14:04:32Z" level=debug msg="Close db connection" client_id=test session_id=1
time="2022-09-01T14:04:32Z" level=debug msg="All connections closed" client_id=test session_id=1
time="2022-09-01T14:04:32Z" level=debug msg="All connections closed" client_id=test session_id=1
time="2022-09-01T14:04:33Z" level=debug msg="Can't read first 5 bytes" client_id=test code=588 error=EOF proxy=client session_id=2
time="2022-09-01T14:04:33Z" level=debug msg="Can't read packet from client to database" client_id=test error=EOF proxy=client session_id=2
time="2022-09-01T14:04:33Z" level=debug msg="Stop to proxy" client_id=test interrupt_side=Client-AcraServer session_id=2
time="2022-09-01T14:04:33Z" level=debug msg="EOF connection closed" client_id=test interrupt_side=Client-AcraServer session_id=2
time="2022-09-01T14:04:33Z" level=info msg="Closing client's connection" client_id=test interrupt_side=Client-AcraServer session_id=2
time="2022-09-01T14:04:33Z" level=debug msg="Close acra-connector connection" client_id=test session_id=2
time="2022-09-01T14:04:33Z" level=debug msg="Close db connection" client_id=test session_id=2
time="2022-09-01T14:04:33Z" level=debug msg="Can't read packet" client_id=test code=588 error="read tcp 172.30.0.8:35104->172.30.0.4:5432: use of closed network connection" proxy=server session_id=2
time="2022-09-01T14:04:33Z" level=debug msg="All connections closed" client_id=test session_id=2
time="2022-09-01T14:04:33Z" level=debug msg="Second proxy goroutine stopped" client_id=test error="AcraServer-Database:read tcp 172.30.0.8:35104->172.30.0.4:5432: use of closed network connection" interrupt_side=Client-AcraServer session_id=2
time="2022-09-01T14:04:33Z" level=info msg="Finished processing client's connection" client_id=test interrupt_side=Client-AcraServer session_id=2

Also tried to run different commits of release 0.93.0 and this starts to happen after commit 29eb6ffb20ecbefd2f7f1684ec16666c1ab6169a

Lagovas commented 1 year ago

hm, you tried 0.93.0 release version of acra and got errors. then you tried acra from master after new commits and found that it works or broken after 29eb6ff? did you try acra from master branch? is it work or not?

Machado117 commented 1 year ago

it's broken after 29eb6ffb20ecbefd2f7f1684ec16666c1ab6169a and still broken on master 34eabbaa0bcfd6bc312f9950efb62dda7bb6f379

Lagovas commented 1 year ago

okay, can you provide sql queries and db schema that you use to reproduce this problem?

Machado117 commented 1 year ago

Hi, I was having trouble reproducing the problem because I would run the logged query and it would run with no issues. After debugging the app I realized that the app was running a jdbc batch insert and this is what is causing trouble. I think it can be reproduced with any table. I can reproduce it with this java code:

Class.forName("org.postgresql.Driver");
String url = "jdbc:postgresql://localhost:9393/testdb";
Connection conn = DriverManager.getConnection(url, "postgres", "postgres");
PreparedStatement st = conn.prepareStatement("INSERT INTO mytable (name, age) VALUES (?, ?)");
conn.setAutoCommit(false);

st.setString(1, "name1");
st.setInt(2, 1);
st.addBatch();

st.setString(1, "name2");
st.setInt(2, 2);
st.addBatch();

st.executeBatch();

conn.commit();
st.close();
conn.close();

As long as there is more than one submitted query acra will fail.

Lagovas commented 1 year ago

Cool. To make it easier to start to debug it, can you provide instructions on how to build and run this java code?

Machado117 commented 1 year ago

Sure

public class AcraCrash {

public static void main(String[] args) throws Exception {
    Class.forName("org.postgresql.Driver");
    String url = "jdbc:postgresql://localhost:9393/testdb";
    Connection conn = DriverManager.getConnection(url, "postgres", "postgres");
    PreparedStatement st = conn.prepareStatement("INSERT INTO mytable (name, age) VALUES (?, ?)");
    conn.setAutoCommit(false);

    st.setString(1, "name1");
    st.setInt(2, 1);
    st.addBatch();

    st.setString(1, "name2");
    st.setInt(2, 2);
    st.addBatch();

    st.executeBatch();

    conn.commit();

    st.close();
    conn.close();
}

}


* Compile (Assuming java sdk is already installed)
`javac AcraCrash.java`
* Run the code ( You will need to download jdbc driver first https://jdbc.postgresql.org/download/)
`java -classpath .:postgresql-42.4.0.jar AcraCrash`
Lagovas commented 1 year ago

Great, thanks. I reproduced this error. At first glance looks like error in processing sequence of packets that contains two PARSE packets and one BIND packet. But BIND packet is related to first PARSE, but Acra tries to link it to the second one... I will notify you when we fix it and merge it to master.

Machado117 commented 1 year ago

Great, thank you!

Lagovas commented 1 year ago

We fixed this problem in #580. You can try to build binary from the sources from master branch or build new images via make docker-build. This fix will be included in the new version of Acrathat we plan to release soon in the next 1-2 weeks. After release will be updated images and binaries in our docker and deb/rpm repositories.

Lagovas commented 1 year ago

It is already fixed, so I close it. Feel free to re-open if it doesn't fix your problem.

Machado117 commented 1 year ago

Hi, sorry for the late reply.

I've tried the fix and it seems to be working, unfortunately when I enable encryption it stops working again. I'm using this config:

  - table: mytable
    columns:
      - name
      - age
    encrypted:
      - column: name
        data_type: str

It seems acra is not converting the parameter type