AcraServer 0.93 + PostgreSQL | "Panic in connection processing"
Machado117 opened this issue · 11 comments
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
- Set up acra server 0.92.0 with my application
- Updated Acra server from 0.92.0 to 0.93.0
- Application no longer works with acra server
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):
- Acra version: 0.93.0
- Database server and its version: PostgreSQL 9.6.10
- Installed components:
- AcraServer
- Data-in-transit encryption between Acra and the client-side application:
- no transport encryption
- Installation way:
- via Docker
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 29eb6ff
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?
okay, can you provide sql queries and db schema that you use to reproduce this problem?
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.
Cool. To make it easier to start to debug it, can you provide instructions on how to build and run this java code?
Sure
- Save this code in a file named AcraCrash.java
import java.sql.*;
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
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.
Great, thank you!
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.
It is already fixed, so I close it. Feel free to re-open if it doesn't fix your problem.
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