[ISSUE]Facing lot of "use of closed network connection" error

[devendermishra]

Describe the bug
I have setup an acra-server on ec2 install on t3-micro instance. DB is on t4g medium instance (using aurora mysql). I have an existing PHP application which was connecting db directly. Now, it is connecting through acra. Now, I am getting logs of "use of closed network connection error"

time="2024-02-09T10:16:02Z" level=error msg="Network error" client_id=StashfinID code=1100 error="read tcp 172.31.9.228:51494->172.31.35.209:3306: use of closed network connection" interrupt_side=AcraServer-Database session_id=372 time="2024-02-09T10:16:02Z" level=info msg="Closing client's connection" client_id=StashfinID interrupt_side=AcraServer-Database session_id=372 time="2024-02-09T10:16:02Z" level=info msg="Finished processing client's connection" client_id=StashfinID interrupt_side=AcraServer-Database session_id=372 time="2024-02-09T10:16:02Z" level=error msg="Network error" client_id=StashfinID code=1100 error="read tcp 172.31.9.228:51542->172.31.35.209:3306: use of closed network connection" interrupt_side=AcraServer-Database session_id=380 time="2024-02-09T10:16:02Z" level=info msg="Closing client's connection" client_id=StashfinID interrupt_side=AcraServer-Database session_id=380 time="2024-02-09T10:16:02Z" level=info msg="Finished processing client's connection" client_id=StashfinID interrupt_side=AcraServer-Database session_id=380 time="2024-02-09T10:16:02Z" level=error msg="Network error" client_id=StashfinID code=1100 error="read tcp 172.31.9.228:51478->172.31.35.209:3306: use of closed network connection" interrupt_side=AcraServer-Database session_id=370 time="2024-02-09T10:16:02Z" level=info msg="Closing client's connection" client_id=StashfinID interrupt_side=AcraServer-Database session_id=370 time="2024-02-09T10:16:02Z" level=error msg="Network error" client_id=StashfinID code=1100 error="read tcp 172.31.9.228:51500->172.31.35.209:3306: use of closed network connection" interrupt_side=AcraServer-Database session_id=374 time="2024-02-09T10:16:02Z" level=info msg="Closing client's connection" client_id=StashfinID interrupt_side=AcraServer-Database session_id=374 time="2024-02-09T10:16:02Z" level=error msg="Network error" client_id=StashfinID code=1100 error="read tcp 172.31.9.228:51518->172.31.35.209:3306: use of closed network connection" interrupt_side=AcraServer-Database session_id=376

To Reproduce
./acra-server -client_id ${ACRA_CLIENT_ID} -db_host <db_host> -db_port 3306 --incoming_connection_close_timeout=60 --http_api_enable=true -mysql_enable --v -keys_dir keystore/stashfin -encryptor_config_file encryptor_config.yml

Expected behavior
A clear and concise description of what you expected to happen.
Application should be able to work. When a database connection is closed, it should be closed.

Acra configuration files

Environment (please complete the following information):

• Acra version: 0.95.0

• Database server and its version: MySQL 8

• Installed components:

  • AcraServer

• Data-in-transit encryption between Acra and the client-side application:

  • no transport encryption

• Installation way:

  • via package manager

[Zhaars]

Hello @devendermishra!

Thanks for reaching out!

Unfortunately, based on the information you provided, it's challenging to thoroughly analyze the issue. The problem seems to have multiple aspects, and it could potentially be on your end, possibly due to incorrect network settings.

To assist you more effectively, could you please provide additional details or steps to reproduce the problem? Additionally, providing a complete Acra log with details of the error you encountered, preferably using the -d flag, would be helpful.

[devendermishra]

Thanks Zhaars for helping out.

Log after -d flag:

time="2024-02-13T03:29:08Z" level=debug msg="New packet" client_id=StashfinID deprecate_eof=false proxy=client sequence_number=0 session_id=1583
time="2024-02-13T03:29:08Z" level=debug msg="New packet" client_id=StashfinID deprecate_eof=false proxy=client sequence_number=0 session_id=1584
time="2024-02-13T03:29:08Z" level=debug msg="Can't read packet from server" client_id=StashfinID session_id=1582
time="2024-02-13T03:29:08Z" level=debug msg="Stop to proxy" client_id=StashfinID interrupt_side=Client-AcraServer session_id=1582
time="2024-02-13T03:29:08Z" level=debug msg="EOF connection closed" client_id=StashfinID interrupt_side=Client-AcraServer session_id=1582
time="2024-02-13T03:29:08Z" level=info msg="Closing client's connection" client_id=StashfinID interrupt_side=Client-AcraServer session_id=1582
time="2024-02-13T03:29:08Z" level=debug msg="Close acra-connector connection" client_id=StashfinID session_id=1582
time="2024-02-13T03:29:08Z" level=debug msg="Close db connection" client_id=StashfinID session_id=1582
time="2024-02-13T03:29:08Z" level=debug msg="All connections closed" client_id=StashfinID session_id=1582
time="2024-02-13T03:29:08Z" level=debug msg="Second proxy goroutine stopped" client_id=StashfinID error="AcraServer-Database:read tcp 172.31.12.255:54358->172.31.35.209:3306: use of closed network connection" interrupt_side=Client-AcraServer session_id=1582
time="2024-02-13T03:29:08Z" level=info msg="Finished processing client's connection" client_id=StashfinID interrupt_side=Client-AcraServer session_id=1582
time="2024-02-13T03:29:08Z" level=debug msg="Close connections on CommandQuit command" client_id=StashfinID deprecate_eof=false proxy=client sequence_number=0 session_id=1583
time="2024-02-13T03:29:08Z" level=debug msg="Can't read packet from server" client_id=StashfinID session_id=1583
time="2024-02-13T03:29:08Z" level=debug msg="Stop to proxy" client_id=StashfinID interrupt_side=AcraServer-Database session_id=1583
time="2024-02-13T03:29:08Z" level=error msg="Network error" client_id=StashfinID code=1100 error="read tcp 172.31.12.255:54360->172.31.35.209:3306: use of closed network connection" interrupt_side=AcraServer-Database session_id=1583
time="2024-02-13T03:29:08Z" level=info msg="Closing client's connection" client_id=StashfinID interrupt_side=AcraServer-Database session_id=1583
time="2024-02-13T03:29:08Z" level=debug msg="Close acra-connector connection" client_id=StashfinID session_id=1583
time="2024-02-13T03:29:08Z" level=debug msg="Close db connection" client_id=StashfinID session_id=1583
time="2024-02-13T03:29:08Z" level=debug msg="Close connections on CommandQuit command" client_id=StashfinID deprecate_eof=false proxy=client sequence_number=0 session_id=1584
time="2024-02-13T03:29:08Z" level=debug msg="Can't read packet from server" client_id=StashfinID session_id=1584
time="2024-02-13T03:29:08Z" level=debug msg="Stop to proxy" client_id=StashfinID interrupt_side=AcraServer-Database session_id=1584
time="2024-02-13T03:29:08Z" level=error msg="Network error" client_id=StashfinID code=1100 error="read tcp 172.31.12.255:54376->172.31.35.209:3306: use of closed network connection" interrupt_side=AcraServer-Database session_id=1584
time="2024-02-13T03:29:08Z" level=info msg="Closing client's connection" client_id=StashfinID interrupt_side=AcraServer-Database session_id=1584
time="2024-02-13T03:29:08Z" level=debug msg="Close acra-connector connection" client_id=StashfinID session_id=1584
time="2024-02-13T03:29:08Z" level=debug msg="Close db connection" client_id=StashfinID session_id=1584
time="2024-02-13T03:29:08Z" level=debug msg="All connections closed" client_id=StashfinID session_id=1583
time="2024-02-13T03:29:08Z" level=debug msg="Second proxy goroutine stopped" client_id=StashfinID error="Client-AcraServer:EOF" interrupt_side=AcraServer-Database session_id=1583
time="2024-02-13T03:29:08Z" level=info msg="Finished processing client's connection" client_id=StashfinID interrupt_side=AcraServer-Database session_id=1583
time="2024-02-13T03:29:08Z" level=debug msg="All connections closed" client_id=StashfinID session_id=1584
time="2024-02-13T03:29:08Z" level=debug msg="Second proxy goroutine stopped" client_id=StashfinID error="Client-AcraServer:EOF" interrupt_side=AcraServer-Database session_id=1584
time="2024-02-13T03:29:08Z" level=info msg="Finished processing client's connection" client_id=StashfinID interrupt_side=AcraServer-Database session_id=1584

Main issue seems db connection leaks.

Infra details:
RDS: Aurora cluster (t4g.medium)
Acra server: 2 (one as reader and another one as writer) in t3.small and t2.small
OS: Ubuntu 20.04, acra installed using package manager in Ubuntu
Applications: 3 PHP applications (PHP 7.2 and CodeIgniter 3), 6 Python applications (using FastApi and Sqlalchemy 2), 4 golang applications.

Python and golang applications use connection pool. PHP applications does not use connection pool. They create connection for every query.

Acra was introduced around 15:00 hours. Till midnight, everything was fine. However, after midnight, there is spike in number of connections.

Acra server is running with following options:

-client_id ${ACRA_CLIENT_ID} -db_host $DB_HOST -db_port 3306 -d --incoming_connection_close_timeout=10 --http_api_enable=true -mysql_enable --v -keys_dir keystore/stashfin -encryptor_config_file encryptor_config.yml

To reproduce, you can write sample 2-3 PHP applications using codeigniter with DB configuration as follows:

$db['db_write']['hostname'] = '<acra_host>';
$db['db_write']['username'] = '<user>';
$db['db_write']['port'] = 9393;
$db['db_write']['password'] = 'password';
$db['db_write']['database'] = 'db_name';
$db['db_write']['dbdriver'] = 'mysqli';
$db['db_write']['dbprefix'] = '';
$db['db_write']['pconnect'] = false;
$db['db_write']['db_debug'] = true;
$db['db_write']['db_debug_exception'] = true;
$db['db_write']['cache_on'] = false;
$db['db_write']['cachedir'] = '';
$db['db_write']['char_set'] = 'utf8';
$db['db_write']['dbcollat'] = 'utf8_general_ci';
$db['db_write']['swap_pre'] = '';
$db['db_write']['autoinit'] = true;
$db['db_write']['stricton'] = false;

Sample query code:

$this->db->select("concat(first_name,' ',coalesce(middle_name,''),' ',coalesce(last_name,'')) as customer_name, 
                            email,phone,gender,dob,pan_number,
                            aadhar_number,
                            coalesce(ovd_id, '') as ovd_id,
                            IF(ovd_id IS NULL, 
                                aadhar_number,
                                IF(ovd_id = 1, ovd_number, ovd_number)
                            ) AS ovd_number,
                            coalesce(se.is_active,'0') as stashfin_employee");
        $this->db->from('customer_detail as cd');
        $this->db->join('employee as e', 'e.customer_id=cd.id', 'left');
        $this->db->where('cd.id', $customer_id);
        $data = $this->db->get()->row_array();
        ```
You can do many queries. Create load on these APIs.