From 9971dc5b478009aca0f3bcef92b699be390755b8 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ren=C3=A9=20Canna=C3=B2?= Date: Sun, 18 Aug 2019 21:55:32 +1000 Subject: [PATCH] Adding several debug information --- lib/MySQL_Protocol.cpp | 41 ++++++++++++++++++++++++++++++++++++++++- lib/MySQL_Session.cpp | 41 +++++++++++++++++++++++++++++++++++++---- 2 files changed, 77 insertions(+), 5 deletions(-) diff --git a/lib/MySQL_Protocol.cpp b/lib/MySQL_Protocol.cpp index 530a471d2..c34bbbd3b 100644 --- a/lib/MySQL_Protocol.cpp +++ b/lib/MySQL_Protocol.cpp @@ -1511,7 +1511,7 @@ bool MySQL_Protocol::process_pkt_handshake_response(unsigned char *pkt, unsigned db = (*myds)->myconn->userinfo->schemaname; (*myds)->switching_auth_stage=2; charset=(*myds)->tmp_charset; - proxy_debug(PROXY_DEBUG_MYSQL_PROTOCOL,2,"Encrypted: %d , switching_auth: %d, auth_plugin_id: %d\n", (*myds)->encrypted, (*myds)->switching_auth_stage, auth_plugin_id); + proxy_debug(PROXY_DEBUG_MYSQL_PROTOCOL,2,"Session=%p , DS=%p . Encrypted: %d , switching_auth: %d, auth_plugin_id: %d\n", (*myds)->sess, (*myds), (*myds)->encrypted, (*myds)->switching_auth_stage, auth_plugin_id); goto __do_auth; } @@ -1526,6 +1526,7 @@ bool MySQL_Protocol::process_pkt_handshake_response(unsigned char *pkt, unsigned (*myds)->encrypted = true; use_ssl = true; ret = false; + proxy_debug(PROXY_DEBUG_MYSQL_AUTH, 5, "Session=%p , DS=%p , user='%s' . goto __exit_process_pkt_handshake_response\n", (*myds), (*myds)->sess, user); goto __exit_process_pkt_handshake_response; } } @@ -1549,12 +1550,14 @@ bool MySQL_Protocol::process_pkt_handshake_response(unsigned char *pkt, unsigned pkt += pass_len_enc; if (pass_len > (len - (pkt - _ptr))) { ret = false; + proxy_debug(PROXY_DEBUG_MYSQL_AUTH, 5, "Session=%p , DS=%p , user='%s' . goto __exit_process_pkt_handshake_response\n", (*myds), (*myds)->sess, user); goto __exit_process_pkt_handshake_response; } } else { pass_len = (capabilities & CLIENT_SECURE_CONNECTION ? *pkt++ : strlen((char *)pkt)); if (pass_len > (len - (pkt - _ptr))) { ret = false; + proxy_debug(PROXY_DEBUG_MYSQL_AUTH, 5, "Session=%p , DS=%p , user='%s' . goto __exit_process_pkt_handshake_response\n", (*myds), (*myds)->sess, user); goto __exit_process_pkt_handshake_response; } } @@ -1591,6 +1594,7 @@ bool MySQL_Protocol::process_pkt_handshake_response(unsigned char *pkt, unsigned auth_plugin_id = 1; } + proxy_debug(PROXY_DEBUG_MYSQL_AUTH, 5, "Session=%p , DS=%p , user='%s' , auth_plugin_id=%d\n", (*myds), (*myds)->sess, user, auth_plugin_id); if (auth_plugin_id == 0) { if (strncmp((char *)auth_plugin,(char *)"mysql_native_password",strlen((char *)"mysql_native_password"))==0) { auth_plugin_id = 1; @@ -1602,6 +1606,7 @@ bool MySQL_Protocol::process_pkt_handshake_response(unsigned char *pkt, unsigned } } //__switch_auth_plugin: + proxy_debug(PROXY_DEBUG_MYSQL_AUTH, 5, "Session=%p , DS=%p , user='%s' , auth_plugin_id=%d\n", (*myds), (*myds)->sess, user, auth_plugin_id); if (auth_plugin_id == 0) { if ((*myds)->switching_auth_stage == 0) { (*myds)->switching_auth_stage = 1; @@ -1616,6 +1621,7 @@ bool MySQL_Protocol::process_pkt_handshake_response(unsigned char *pkt, unsigned } else { #endif /* PROXYSQLCLICKHOUSE */ user_exists = GloMyAuth->exists((char *)user); + proxy_debug(PROXY_DEBUG_MYSQL_AUTH, 5, "Session=%p , DS=%p , user_exists=%d , user='%s'\n", (*myds), (*myds)->sess, user_exists, user); //password=GloMyAuth->lookup((char *)user, USERNAME_FRONTEND, &_ret_use_ssl, &default_hostgroup, &default_schema, &schema_locked, &transaction_persistent, &fast_forward, &max_connections, &sha1_pass); #ifdef PROXYSQLCLICKHOUSE } @@ -1626,6 +1632,7 @@ bool MySQL_Protocol::process_pkt_handshake_response(unsigned char *pkt, unsigned } else { (*myds)->switching_auth_type = 2; // mysql_clear_password } + proxy_debug(PROXY_DEBUG_MYSQL_AUTH, 5, "Session=%p , DS=%p , user_exists=%d , user='%s' , setting switching_auth_type=%d\n", (*myds), (*myds)->sess, user_exists, user, (*myds)->switching_auth_type); generate_pkt_auth_switch_request(true, NULL, NULL); (*myds)->myconn->userinfo->set((char *)user, NULL, db, NULL); ret = false; @@ -1654,6 +1661,7 @@ bool MySQL_Protocol::process_pkt_handshake_response(unsigned char *pkt, unsigned generate_pkt_auth_switch_request(true, NULL, NULL); (*myds)->myconn->userinfo->set((char *)user, NULL, db, NULL); ret = false; + proxy_debug(PROXY_DEBUG_MYSQL_AUTH, 5, "Session=%p , DS=%p , user='%s' . goto __exit_process_pkt_handshake_response. User does not exist\n", (*myds), (*myds)->sess, user); goto __exit_process_pkt_handshake_response; } } @@ -1662,6 +1670,7 @@ bool MySQL_Protocol::process_pkt_handshake_response(unsigned char *pkt, unsigned } if (auth_plugin_id == 0) { // unknown plugin ret = false; + proxy_debug(PROXY_DEBUG_MYSQL_AUTH, 5, "Session=%p , DS=%p , user='%s' . goto __exit_process_pkt_handshake_response . Unknown auth plugin\n", (*myds), (*myds)->sess, user); goto __exit_process_pkt_handshake_response; } //char reply[SHA_DIGEST_LENGTH+1]; @@ -1681,6 +1690,7 @@ __do_auth: const MARIADB_CHARSET_INFO * c = proxysql_find_charset_nr(charset); if (!c) { proxy_error("Client %s:%d is trying to use unknown charset %d. Disconnecting\n", (*myds)->addr.addr, (*myds)->addr.port, charset); + proxy_debug(PROXY_DEBUG_MYSQL_AUTH, 5, "Session=%p , DS=%p , user='%s' . Client %s:%d is trying to use unknown charset %d. Disconnecting\n", (*myds), (*myds)->sess, user, (*myds)->addr.addr, (*myds)->addr.port, charset); ret = false; goto __exit_do_auth; } @@ -1694,6 +1704,15 @@ __do_auth: } //assert(default_hostgroup>=0); if (password) { +#ifdef DEBUG + char *tmp_pass=strdup(password); + int lpass = strlen(tmp_pass); + for (int i=2; isess, user, tmp_pass); + free(tmp_pass); +#endif // debug (*myds)->sess->default_hostgroup=default_hostgroup; (*myds)->sess->default_schema=default_schema; // just the pointer is passed (*myds)->sess->schema_locked=schema_locked; @@ -1736,6 +1755,15 @@ __do_auth: (*myds)->sess->ldap_ctx = GloMyLdapAuth->ldap_ctx_init(); password = GloMyLdapAuth->lookup((*myds)->sess->ldap_ctx, (char *)user, (char *)pass, USERNAME_FRONTEND, &_ret_use_ssl, &default_hostgroup, &default_schema, &schema_locked, &transaction_persistent, &fast_forward, &max_connections, &sha1_pass, &backend_username); if (password) { +#ifdef DEBUG + char *tmp_pass=strdup(password); + int lpass = strlen(tmp_pass); + for (int i=2; isess, backend_username, tmp_pass); + free(tmp_pass); +#endif // debug (*myds)->sess->default_hostgroup=default_hostgroup; (*myds)->sess->default_schema=default_schema; // just the pointer is passed (*myds)->sess->schema_locked=schema_locked; @@ -1777,7 +1805,17 @@ __do_auth: } else { if (pass_len==0 && strlen(password)==0) { ret=true; + proxy_debug(PROXY_DEBUG_MYSQL_AUTH, 5, "Session=%p , DS=%p , username='%s' , password=''\n", (*myds), (*myds)->sess, user); } else { +#ifdef DEBUG + char *tmp_pass=strdup(password); + int lpass = strlen(tmp_pass); + for (int i=2; isess, user, tmp_pass, auth_plugin_id); + free(tmp_pass); +#endif // debug if (password[0]!='*') { // clear text password if (auth_plugin_id == 1) { // mysql_native_password proxy_scramble(reply, (*myds)->myconn->scramble_buff, password); @@ -1813,6 +1851,7 @@ __do_auth: uint8 hash_stage2[SHA_DIGEST_LENGTH]; unhex_pass(hash_stage2,sha1_2); */ + proxy_debug(PROXY_DEBUG_MYSQL_AUTH, 5, "Session=%p , DS=%p , username='%s' , session_type=%d\n", (*myds), (*myds)->sess, user, session_type); uint8 hash_stage1[SHA_DIGEST_LENGTH]; uint8 hash_stage2[SHA_DIGEST_LENGTH]; SHA_CTX sha1_context; diff --git a/lib/MySQL_Session.cpp b/lib/MySQL_Session.cpp index 2b0acc9c4..35167b162 100644 --- a/lib/MySQL_Session.cpp +++ b/lib/MySQL_Session.cpp @@ -4112,13 +4112,13 @@ void MySQL_Session::handler___status_CHANGING_USER_CLIENT___STATE_CLIENT_HANDSHA client_myds->myprot.process_pkt_auth_swich_response((unsigned char *)pkt->ptr,pkt->size)==true ) { l_free(pkt->size,pkt->ptr); + proxy_debug(PROXY_DEBUG_MYSQL_CONNECTION, 5, "Session=%p , DS=%p . Successful connection\n", this, client_myds); client_myds->myprot.generate_pkt_OK(true,NULL,NULL,2,0,0,0,0,NULL); GloMyLogger->log_audit_entry(PROXYSQL_MYSQL_CHANGE_USER_OK, this, NULL); status=WAITING_CLIENT_DATA; client_myds->DSS=STATE_SLEEP; } else { l_free(pkt->size,pkt->ptr); - proxy_debug(PROXY_DEBUG_MYSQL_CONNECTION, 5, "Wrong credentials for frontend: disconnecting\n"); *wrong_pass=true; // FIXME: this should become close connection client_myds->setDSS_STATE_QUERY_SENT_NET(); @@ -4153,6 +4153,19 @@ void MySQL_Session::handler___status_CHANGING_USER_CLIENT___STATE_CLIENT_HANDSHA sprintf(_s,"ProxySQL Error: Access denied for user '%s'@'%s' (using password: %s)", client_myds->myconn->userinfo->username, client_addr, (client_myds->myconn->userinfo->password ? "YES" : "NO")); proxy_error("ProxySQL Error: Access denied for user '%s'@'%s' (using password: %s)", client_myds->myconn->userinfo->username, client_addr, (client_myds->myconn->userinfo->password ? "YES" : "NO")); client_myds->myprot.generate_pkt_ERR(true,NULL,NULL,2,1045,(char *)"28000", _s, true); +#ifdef DEBUG + if (client_myds->myconn->userinfo->password) { + char *tmp_pass=strdup(client_myds->myconn->userinfo->password); + int lpass = strlen(tmp_pass); + for (int i=2; imyconn->userinfo->username, client_addr, tmp_pass); + free(tmp_pass); + } else { + proxy_debug(PROXY_DEBUG_MYSQL_CONNECTION, 5, "Session=%p , DS=%p . Wrong credentials for frontend: %s:%s . No password. Disconnecting\n", this, client_myds, client_myds->myconn->userinfo->username, client_addr); + } +#endif //DEBUG GloMyLogger->log_audit_entry(PROXYSQL_MYSQL_CHANGE_USER_ERR, this, NULL); free(_s); __sync_fetch_and_add(&MyHGM->status.access_denied_wrong_password, 1); @@ -4163,9 +4176,11 @@ void MySQL_Session::handler___status_CONNECTING_CLIENT___STATE_SERVER_HANDSHAKE( bool is_encrypted = client_myds->encrypted; bool handshake_response_return = client_myds->myprot.process_pkt_handshake_response((unsigned char *)pkt->ptr,pkt->size); + proxy_debug(PROXY_DEBUG_MYSQL_CONNECTION,8,"Session=%p , DS=%p , handshake_response=%d , switching_auth_stage=%d , is_encrypted=%d , client_encrypted=%d\n", this, client_myds, handshake_response_return, client_myds->switching_auth_stage, is_encrypted, client_myds->encrypted); if ( (handshake_response_return == false) && (client_myds->switching_auth_stage == 1) ) { + proxy_debug(PROXY_DEBUG_MYSQL_CONNECTION,8,"Session=%p , DS=%p . Returning\n", this, client_myds); return; } @@ -4175,6 +4190,7 @@ void MySQL_Session::handler___status_CONNECTING_CLIENT___STATE_SERVER_HANDSHAKE( (client_myds->encrypted == true) // client is asking for encryption ) { // use SSL + proxy_debug(PROXY_DEBUG_MYSQL_CONNECTION,8,"Session=%p , DS=%p . SSL_INIT\n", this, client_myds); client_myds->DSS=STATE_SSL_INIT; client_myds->rbio_ssl = BIO_new(BIO_s_mem()); client_myds->wbio_ssl = BIO_new(BIO_s_mem()); @@ -4275,6 +4291,7 @@ void MySQL_Session::handler___status_CONNECTING_CLIENT___STATE_SERVER_HANDSHAKE( break; #endif // TEST_AURORA || TEST_GALERA case PROXYSQL_SESSION_MYSQL: + proxy_debug(PROXY_DEBUG_MYSQL_CONNECTION,8,"Session=%p , DS=%p , session_type=PROXYSQL_SESSION_MYSQL\n", this, client_myds); if (ldap_ctx==NULL) { free_users=GloMyAuth->increase_frontend_user_connections(client_myds->myconn->userinfo->username, &used_users); } else { @@ -4294,20 +4311,21 @@ void MySQL_Session::handler___status_CONNECTING_CLIENT___STATE_SERVER_HANDSHAKE( free_users=1; } if (max_connections_reached==true || free_users<=0) { + proxy_debug(PROXY_DEBUG_MYSQL_CONNECTION,8,"Session=%p , DS=%p , max_connections_reached=%d , free_users=%d\n", this, client_myds, max_connections_reached, free_users); client_authenticated=false; *wrong_pass=true; client_myds->setDSS_STATE_QUERY_SENT_NET(); uint8_t _pid = 2; if (client_myds->switching_auth_stage) _pid+=2; if (max_connections_reached==true) { - proxy_debug(PROXY_DEBUG_MYSQL_CONNECTION, 5, "Too many connections\n"); + proxy_debug(PROXY_DEBUG_MYSQL_CONNECTION, 5, "Session=%p , DS=%p , Too many connections\n", this, client_myds); client_myds->myprot.generate_pkt_ERR(true,NULL,NULL,_pid,1040,(char *)"08004", (char *)"Too many connections", true); proxy_warning("mysql-max_connections reached. Returning 'Too many connections'\n"); GloMyLogger->log_audit_entry(PROXYSQL_MYSQL_AUTH_ERR, this, NULL, (char *)"mysql-max_connections reached"); __sync_fetch_and_add(&MyHGM->status.access_denied_max_connections, 1); } else { // see issue #794 __sync_fetch_and_add(&MyHGM->status.access_denied_max_user_connections, 1); - proxy_debug(PROXY_DEBUG_MYSQL_CONNECTION, 5, "User '%s' has exceeded the 'max_user_connections' resource (current value: %d)\n", client_myds->myconn->userinfo->username, used_users); + proxy_debug(PROXY_DEBUG_MYSQL_CONNECTION, 5, "Session=%p , DS=%p . User '%s' has exceeded the 'max_user_connections' resource (current value: %d)\n", this, client_myds, client_myds->myconn->userinfo->username, used_users); char *a=(char *)"User '%s' has exceeded the 'max_user_connections' resource (current value: %d)"; char *b=(char *)malloc(strlen(a)+strlen(client_myds->myconn->userinfo->username)+16); GloMyLogger->log_audit_entry(PROXYSQL_MYSQL_AUTH_ERR, this, NULL, b); @@ -4398,12 +4416,14 @@ void MySQL_Session::handler___status_CONNECTING_CLIENT___STATE_SERVER_HANDSHAKE( sprintf(_s, _a, client_myds->myconn->userinfo->username, (client_myds->myconn->userinfo->password ? "YES" : "NO")); client_myds->myprot.generate_pkt_ERR(true,NULL,NULL, _pid, 1045,(char *)"28000", _s, true); proxy_error("ProxySQL Error: Access denied for user '%s' (using password: %s). SSL is required", client_myds->myconn->userinfo->username, (client_myds->myconn->userinfo->password ? "YES" : "NO")); + proxy_debug(PROXY_DEBUG_MYSQL_CONNECTION,8,"Session=%p , DS=%p . Access denied for user '%s' (using password: %s). SSL is required\n", this, client_myds, client_myds->myconn->userinfo->username, (client_myds->myconn->userinfo->password ? "YES" : "NO")); __sync_add_and_fetch(&MyHGM->status.client_connections_aborted,1); free(_s); __sync_fetch_and_add(&MyHGM->status.access_denied_wrong_password, 1); } else { // we are good! //client_myds->myprot.generate_pkt_OK(true,NULL,NULL, (is_encrypted ? 3 : 2), 0,0,0,0,NULL); + proxy_debug(PROXY_DEBUG_MYSQL_CONNECTION,8,"Session=%p , DS=%p . STATE_CLIENT_AUTH_OK\n", this, client_myds); GloMyLogger->log_audit_entry(PROXYSQL_MYSQL_AUTH_OK, this, NULL); client_myds->myprot.generate_pkt_OK(true,NULL,NULL, _pid, 0,0,0,0,NULL); status=WAITING_CLIENT_DATA; @@ -4426,7 +4446,7 @@ void MySQL_Session::handler___status_CONNECTING_CLIENT___STATE_SERVER_HANDSHAKE( // } } else { l_free(pkt->size,pkt->ptr); - proxy_debug(PROXY_DEBUG_MYSQL_CONNECTION, 5, "Wrong credentials for frontend: disconnecting\n"); + proxy_debug(PROXY_DEBUG_MYSQL_CONNECTION, 5, "Session=%p , DS=%p . Wrong credentials for frontend: disconnecting\n", this, client_myds); *wrong_pass=true; // FIXME: this should become close connection client_myds->setDSS_STATE_QUERY_SENT_NET(); @@ -4462,6 +4482,19 @@ void MySQL_Session::handler___status_CONNECTING_CLIENT___STATE_SERVER_HANDSHAKE( uint8_t _pid = 2; if (client_myds->switching_auth_stage) _pid+=2; if (is_encrypted) _pid++; +#ifdef DEBUG + if (client_myds->myconn->userinfo->password) { + char *tmp_pass=strdup(client_myds->myconn->userinfo->password); + int lpass = strlen(tmp_pass); + for (int i=2; imyconn->userinfo->username, client_addr, tmp_pass); + free(tmp_pass); + } else { + proxy_debug(PROXY_DEBUG_MYSQL_CONNECTION, 5, "Session=%p , DS=%p . Error: Access denied for user '%s'@'%s' . No password. Disconnecting\n", this, client_myds, client_myds->myconn->userinfo->username, client_addr); + } +#endif // DEBUG sprintf(_s,"ProxySQL Error: Access denied for user '%s'@'%s' (using password: %s)", client_myds->myconn->userinfo->username, client_addr, (client_myds->myconn->userinfo->password ? "YES" : "NO")); client_myds->myprot.generate_pkt_ERR(true,NULL,NULL, _pid, 1045,(char *)"28000", _s, true); proxy_error("ProxySQL Error: Access denied for user '%s'@'%s' (using password: %s)\n", client_myds->myconn->userinfo->username, client_addr, (client_myds->myconn->userinfo->password ? "YES" : "NO"));