|
| 1 | +/** |
| 2 | + * @file test_unexpected_packet_log_attribution-t.cpp |
| 3 | + * @brief Regression: the "unexpected packet from client" error log lines carry |
| 4 | + * the frontend user and routing hostgroup, so connection churn can be |
| 5 | + * attributed to a service behind a shared pool, not just a client IP. |
| 6 | + * |
| 7 | + * Reproduces the overlap without a driver: a held 'DO SLEEP' keeps the session |
| 8 | + * in PROCESSING_QUERY while a trailing packet (a second COM_QUERY, then a |
| 9 | + * COM_QUIT) is read as unexpected. The overlap case also asserts the logged |
| 10 | + * connection id of the attached backend. Covers 2 of the 3 |
| 11 | + * enriched sites; the third (WAITING_CLIENT_DATA default) is an unreachable |
| 12 | + * defensive branch. Mutates no admin state -- default_hostgroup is only read. |
| 13 | + */ |
| 14 | + |
| 15 | +#include <cstddef> |
| 16 | +#include <cstdlib> |
| 17 | +#include <fstream> |
| 18 | +#include <string> |
| 19 | +#include <vector> |
| 20 | + |
| 21 | +#include <sys/socket.h> |
| 22 | +#include <unistd.h> |
| 23 | + |
| 24 | +#include "mysql.h" |
| 25 | + |
| 26 | +#include "tap.h" |
| 27 | +#include "command_line.h" |
| 28 | +#include "utils.h" |
| 29 | + |
| 30 | +using std::string; |
| 31 | + |
| 32 | +static constexpr int MAX_LOG_CHECK_ATTEMPTS = 20; |
| 33 | +static constexpr useconds_t LOG_CHECK_RETRY_DELAY_US = 100000; |
| 34 | + |
| 35 | +// Held server-side so the session stays in PROCESSING_QUERY while the trailing |
| 36 | +// packet is read. 'DO' (not 'SELECT') avoids '^SELECT' reader rules, so routing |
| 37 | +// lands on the user's default_hostgroup and the logged hostgroup is predictable. |
| 38 | +static const string OVERLAP_SLEEP_QUERY = "DO SLEEP(5)"; |
| 39 | + |
| 40 | +static int admin_query_one_int(MYSQL* admin, const string& sql, int& out) { |
| 41 | + if (mysql_query(admin, sql.c_str())) { |
| 42 | + diag("admin query failed: %s: %s", sql.c_str(), mysql_error(admin)); |
| 43 | + return -1; |
| 44 | + } |
| 45 | + MYSQL_RES* r = mysql_store_result(admin); |
| 46 | + if (!r) return -1; |
| 47 | + int rc = -1; |
| 48 | + MYSQL_ROW row = mysql_fetch_row(r); |
| 49 | + if (row && row[0]) { |
| 50 | + out = atoi(row[0]); |
| 51 | + rc = 0; |
| 52 | + } |
| 53 | + mysql_free_result(r); |
| 54 | + return rc; |
| 55 | +} |
| 56 | + |
| 57 | +// COM_QUERY packet: 3-byte LE length, seq 0, 0x03, query (< 16 MiB). |
| 58 | +static std::vector<unsigned char> com_query_packet(const string& query) { |
| 59 | + const size_t payload_len = 1 + query.size(); |
| 60 | + std::vector<unsigned char> pkt; |
| 61 | + pkt.reserve(4 + payload_len); |
| 62 | + pkt.push_back(static_cast<unsigned char>(payload_len & 0xff)); |
| 63 | + pkt.push_back(static_cast<unsigned char>((payload_len >> 8) & 0xff)); |
| 64 | + pkt.push_back(static_cast<unsigned char>((payload_len >> 16) & 0xff)); |
| 65 | + pkt.push_back(0x00); |
| 66 | + pkt.push_back(0x03); |
| 67 | + pkt.insert(pkt.end(), query.begin(), query.end()); |
| 68 | + return pkt; |
| 69 | +} |
| 70 | + |
| 71 | +// COM_QUIT packet. |
| 72 | +static std::vector<unsigned char> com_quit_packet() { |
| 73 | + return { 0x01, 0x00, 0x00, 0x00, 0x01 }; |
| 74 | +} |
| 75 | + |
| 76 | +static bool send_all(int fd, const unsigned char* data, size_t len) { |
| 77 | + size_t total_sent = 0; |
| 78 | + while (total_sent < len) { |
| 79 | + const ssize_t sent = send(fd, data + total_sent, len - total_sent, MSG_NOSIGNAL); |
| 80 | + if (sent <= 0) { |
| 81 | + return false; |
| 82 | + } |
| 83 | + total_sent += sent; |
| 84 | + } |
| 85 | + return true; |
| 86 | +} |
| 87 | + |
| 88 | +// The unsigned value immediately after `key` in `line`, or -1 if `key` absent. |
| 89 | +static long value_after(const string& line, const string& key) { |
| 90 | + const size_t p = line.find(key); |
| 91 | + if (p == string::npos) return -1; |
| 92 | + return atol(line.c_str() + p + key.size()); |
| 93 | +} |
| 94 | + |
| 95 | +// The connection id from the first log line matching all three needles, or -1. |
| 96 | +static long attributed_connection( |
| 97 | + const std::vector<string>& lines, |
| 98 | + const string& event, |
| 99 | + const string& user_needle, |
| 100 | + const string& hg_needle |
| 101 | +) { |
| 102 | + for (const string& l : lines) { |
| 103 | + if (l.find(event) != string::npos |
| 104 | + && l.find(user_needle) != string::npos |
| 105 | + && l.find(hg_needle) != string::npos) { |
| 106 | + return value_after(l, ", connection "); |
| 107 | + } |
| 108 | + } |
| 109 | + return -1; |
| 110 | +} |
| 111 | + |
| 112 | +// Send the held query + `trailing` in one write so the trailing packet is read |
| 113 | +// mid-query, then poll the log for a line carrying `event`, the user, and the |
| 114 | +// hostgroup. At the overlap site the line must also carry a non-zero backend |
| 115 | +// `connection` id (a real attached backend). Lines accumulate across attempts. |
| 116 | +static bool trigger_and_find( |
| 117 | + CommandLine& cl, |
| 118 | + int hg, |
| 119 | + std::fstream& log, |
| 120 | + const std::vector<unsigned char>& trailing, |
| 121 | + const string& event, |
| 122 | + bool overlap_site |
| 123 | +) { |
| 124 | + MYSQL* attack = mysql_init(NULL); |
| 125 | + if (!attack || !mysql_real_connect(attack, cl.host, cl.username, cl.password, NULL, cl.port, NULL, 0)) { |
| 126 | + diag("frontend connect failed: %s", attack ? mysql_error(attack) : "mysql_init"); |
| 127 | + if (attack) mysql_close(attack); |
| 128 | + return false; |
| 129 | + } |
| 130 | + |
| 131 | + // Pin an established backend so the overlap logs a real connection id. A cold |
| 132 | + // connection was observed to log connection 0 (no backend attached at overlap |
| 133 | + // time); a transaction attaches and pins one. 'DO' (not 'SELECT') keeps it on |
| 134 | + // default_hostgroup, no '^SELECT' reader reroute. |
| 135 | + if (overlap_site) { |
| 136 | + if (mysql_query(attack, "BEGIN") || mysql_query(attack, "DO 1")) { |
| 137 | + diag("backend warmup failed: %s", mysql_error(attack)); |
| 138 | + } |
| 139 | + } |
| 140 | + |
| 141 | + std::vector<unsigned char> buf = com_query_packet(OVERLAP_SLEEP_QUERY); |
| 142 | + buf.insert(buf.end(), trailing.begin(), trailing.end()); |
| 143 | + const bool wrote = send_all(mysql_get_socket(attack), buf.data(), buf.size()); |
| 144 | + if (!wrote) diag("send_all failed on frontend connection"); |
| 145 | + |
| 146 | + const string user_needle { "user '" + string(cl.username) + "'" }; |
| 147 | + const string hg_needle { "hostgroup " + std::to_string(hg) }; |
| 148 | + std::vector<string> lines; |
| 149 | + bool found = false; |
| 150 | + string line {}; |
| 151 | + for (int attempt = 0; wrote && attempt < MAX_LOG_CHECK_ATTEMPTS && !found; ++attempt) { |
| 152 | + log.clear(log.rdstate() & ~std::ios_base::eofbit & ~std::ios_base::failbit); |
| 153 | + while (getline(log, line)) lines.push_back(line); |
| 154 | + |
| 155 | + const long backend = attributed_connection(lines, event, user_needle, hg_needle); |
| 156 | + if (backend < 0) { |
| 157 | + usleep(LOG_CHECK_RETRY_DELAY_US); // attributed line not logged yet |
| 158 | + continue; |
| 159 | + } |
| 160 | + // Site 2 (COM_QUIT): the attributed line is the whole assertion. Overlap |
| 161 | + // site: also require a non-zero backend connection id (a real attached |
| 162 | + // backend). The matching KILL isn't asserted -- warming the backend for a |
| 163 | + // non-zero id pins it in a transaction, which suppresses the kill; the |
| 164 | + // kill only fires on a non-pinned in-flight overlap, which raw sockets |
| 165 | + // can't arrange deterministically. |
| 166 | + if (!overlap_site) { |
| 167 | + found = true; |
| 168 | + } else if (backend > 0) { |
| 169 | + found = true; |
| 170 | + } else { |
| 171 | + usleep(LOG_CHECK_RETRY_DELAY_US); // connection still 0, retry |
| 172 | + } |
| 173 | + } |
| 174 | + |
| 175 | + mysql_close(attack); |
| 176 | + return found; |
| 177 | +} |
| 178 | + |
| 179 | +int main() { |
| 180 | + CommandLine cl; |
| 181 | + |
| 182 | + plan(5); |
| 183 | + |
| 184 | + if (cl.getEnv()) { |
| 185 | + diag("Failed to get the required environmental variables."); |
| 186 | + return exit_status(); |
| 187 | + } |
| 188 | + |
| 189 | + const string log_dir { get_env("REGULAR_INFRA_DATADIR") }; |
| 190 | + ok(!log_dir.empty(), "REGULAR_INFRA_DATADIR is set"); |
| 191 | + |
| 192 | + const string log_path { log_dir + "/proxysql.log" }; |
| 193 | + std::fstream proxysql_log {}; |
| 194 | + const int log_res = log_dir.empty() ? EXIT_FAILURE : open_file_and_seek_end(log_path, proxysql_log); |
| 195 | + ok(log_res == EXIT_SUCCESS, "Opened ProxySQL log at end"); |
| 196 | + |
| 197 | + MYSQL* admin = mysql_init(NULL); |
| 198 | + int hg = -1; |
| 199 | + if (admin && mysql_real_connect(admin, cl.host, cl.admin_username, cl.admin_password, NULL, cl.admin_port, NULL, 0)) { |
| 200 | + const string q = string("SELECT default_hostgroup FROM mysql_users WHERE username = '") |
| 201 | + + cl.username + "' LIMIT 1"; |
| 202 | + admin_query_one_int(admin, q, hg); |
| 203 | + } else { |
| 204 | + diag("admin connect failed: %s", admin ? mysql_error(admin) : "mysql_init"); |
| 205 | + } |
| 206 | + if (admin) mysql_close(admin); |
| 207 | + ok(hg >= 0, "Discovered default_hostgroup=%d for user '%s'", hg, cl.username); |
| 208 | + |
| 209 | + const bool ready = (log_res == EXIT_SUCCESS && hg >= 0); |
| 210 | + |
| 211 | + // Site 1: overlapping COM_QUERY -> PMC-10001 packet line with a backend connection id. |
| 212 | + ok(ready && trigger_and_find(cl, hg, proxysql_log, com_query_packet("DO 1"), |
| 213 | + "Unexpected packet from client", true), |
| 214 | + "PMC-10001 line carries 'user %s'/'hostgroup %d' and a backend connection id", cl.username, hg); |
| 215 | + |
| 216 | + // Site 2: overlapping COM_QUIT -> COM_QUIT line. |
| 217 | + ok(ready && trigger_and_find(cl, hg, proxysql_log, com_quit_packet(), |
| 218 | + "Unexpected COM_QUIT from client", false), |
| 219 | + "COM_QUIT line carries 'user %s' and 'hostgroup %d'", cl.username, hg); |
| 220 | + |
| 221 | + if (proxysql_log.is_open()) proxysql_log.close(); |
| 222 | + |
| 223 | + return exit_status(); |
| 224 | +} |
0 commit comments