Is there anything special about these triggers? Do they reference just one item or multiple? Do they use nodata() or another time-based function?
It can be seen in the log you posted that the SQL is generated correctly in process_trigger(). However, is it really executed afterwards in process_triggers() function?
Nothing unusual about functions, and they have not changed in years.
We are not sure the SQL is executed correctly, in part as the return code is ignored/not captured in process_triggers(), in fact it's not really logged or passed up anywhere, though __zbx_DBexecute() does return a code, it's lost in DBexecute_overflowed_sql() which just returns a FAIL is dbexecute() fails. The actual failure seems totally lost.
So we are working to add logging to DBexecute_overflowed_sql() and __zbx_DBexecute() to see what is happening - maybe the transaction is failing on commit or somewhere.
We checked and we're pretty sure no deadlocks in the DB logs, so seems being lost between SQL and the DB/DB calls.
New info - seems we are getting an error on a single update in a batch, and all the rest are the same - also some odd looping going on:
I reviewed some functions from the Zabbix code and we found one bug in the logic. The function void process_triggers(zbx_vector_ptr_t *triggers) is responsible to concatenate the SQL updates and send all the updates in one transaction. To execute the SQL’s it calls the function DBexecute_overflowed_sql(). The function DBexecute_overflowed_sql() checks the string length (sql_offset) and depends on the value executes or not.
The error is the flow. The function process_triggers should concatenate all the SQL’s first and then call DBexecute_overflowed_sql() but the call is inside the loop that concatenates the SQL. It means the function DBexecute_overflowed_sql() will be called for every single SQL instruction. I am sending the code snippet below:
## source: src/libs/zbxdbhigh/db.c
## function: void process_triggers(zbx_vector_ptr_t *triggers)
for (i = 0; i < trigger_sqls.values_num; i++)
{
if (NULL == trigger_sqls.values[i].second)
continue;
zbx_strcpy_alloc(&sql, &sql_alloc, &sql_offset, trigger_sqls.values[i].second);
zbx_strcpy_alloc(&sql, &sql_alloc, &sql_offset, ";\n");
DBexecute_overflowed_sql(&sql, &sql_alloc, &sql_offset);
zbx_free(trigger_sqls.values[i].second);
}
We also have questions to the Zabbix support:
1 - The functions process_triggers() and DBexecute_overflowed_sql() call the same function to execute the SQL’s (defined by the macro DBexecute). If both of them call the same function why need one extra function only to check the SQL string length?
2 - The function zbx_db_vexecute() responsible to execute the SQL’s doesn’t consider transactions for MySQL and even though the function loops the result it doesn’t log which instruction was executed with error. How the Server knows which trigger wasn’t updated?
It used to be as you described. First, the whole sql was generated and then it was sent to the SQL server. But it appeared some SQL servers cannot handle large queries. So we had to introduce a limit (256KB) and for possibly big queries use function DBexecute_overflowed_sql() that would send what we have when we reach 256 KB of characters in SQL. This function will do nothing unless we reach this limit. So this is why we need the last DBexecute() after the loop, it will take care of the last part.
As for the second question, the function zbx_db_vexecute() considers transactions and would set txn_error to 1 if any of the queries within transaction fails. The following queries would be ignored and when finishing transaction (DBcommit()) that txn_error would be considered and if it is set to 1 a rollback would be called instead to cancel the whole transaction.
So any ideas on next steps - this is killing us and certainly seems one query and update among many is failing, and now several / many times per day out of many other alerts - not sure what else we can check or add logging on, etc.
Do you see string "query failed:" in zabbix server log file?
The problem here is how the server manage the transaction. As @dimir said "the function zbx_db_vexecute() considers transactions and would set txn_error to 1 if any of the queries within transaction fails.", well, should do that but it doesn't happen for MySQL. The code fails in the point
ret += (int)mysql_affected_rows(conn);
By the documentation the function mysql_affected_rows returns an integer greater than zero indicates the number of rows affected or retrieved. Zero indicates that no records were updated for an UPDATE statement, no rows matched the WHERE clause in the query or that no query has yet been executed. -1 indicates that the query returned an error.
The code below will never change the status for txn_error in case the first operation performs OK.
do { if (0 != mysql_field_count(conn)) { zabbix_log(LOG_LEVEL_DEBUG, "cannot retrieve result set"); break; } else ret += (int)mysql_affected_rows(conn); // If executing a single operation or if the 1st operation fails could be "ret = -1". If the 1st operation performs OK even the next one fails "ret > -1". /* more results? -1 = no, >0 = error, 0 = yes (keep looping) */ if (0 < (status = mysql_next_result(conn))) zabbix_errlog(ERR_Z3005, mysql_errno(conn), mysql_error(conn), sql); } while (0 == status);
Besides this problem the MySQL has an interesting behavior. If we try to execute COMMIT or ROLLBACK immediately after the mysql_query it will return the error Commands out of sync; you can't run this command now but if we execute after loop mysql_next_result it will perform the operation. For rollback will execute as expected and will rolled back the whole transaction but for commit it will commit all the transactions until the first error. The code below explains this behavior:
-- SQL to create the table Create Table: CREATE TABLE `test_table` ( `id` int(11) NOT NULL, `name` varchar(50) NOT NULL, PRIMARY KEY (`id`), UNIQUE KEY `name` (`name`) ) ENGINE=InnoDB
#include <mysql.h>
#include <stdio.h>
void main() {
MYSQL *conn;
MYSQL_RES *result;
MYSQL_ROW row;
char *server = "localhost";
char *user = "usr_test";
char *password = "123.com";
char *database = "test";
conn = mysql_init(NULL);
int status = 0;
/* Connect to database */
if (!mysql_real_connect(conn, server, user, password, database, 0, NULL, CLIENT_MULTI_STATEMENTS)) {
fprintf(stderr, "[%d]%s\n", __LINE__, mysql_error(conn));
exit(1);
}
/* execute multiple statements */
status = mysql_query(conn, "BEGIN;");
if (status) {
fprintf(stderr, "[%d]%s\n", __LINE__, mysql_error(conn));
goto clean;
}
status = mysql_query(conn,
"INSERT INTO test_table VALUES(10, 'ABCD0');\
INSERT INTO test_table VALUES(11, 'ABCD2');\
INSERT INTO test_table VALUES(12, 'ABCD3');\
INSERT INTO test_table VALUES(13, 'ABCD4');\
INSERT INTO test_table VALUES(10, 'ABCD8');\
INSERT INTO test_table VALUES(16, 'ABCD9');\
INSERT INTO test_table VALUES(10, 'ABCD6');\
");
if (status) {
fprintf(stderr, "[%d]%s\n", __LINE__, mysql_error(conn));
goto clean;
}
/* process each statement result */
int ret = 0;
do {
if (mysql_field_count(conn) != 0) { /* some error occurred */
printf("[%d]Could not retrieve result set\n", __LINE__);
break;
}
/* more results? -1 = no, >0 = error, 0 = yes (keep looping) */
ret += (int)mysql_affected_rows(conn);
printf("[%d]ret: %d\n", __LINE__, ret);
if ((status = mysql_next_result(conn)) > 0)
printf("[%d]Could not execute statement if it works \n", __LINE__);
} while (status == 0);
printf("[%d]Total Ret: %d\n", __LINE__, ret);
status = mysql_query(conn, "COMMIT;");
if (status)
fprintf(stderr, "[%d]%s\n", __LINE__, mysql_error(conn));
clean:
mysql_close(conn);
}
The code will insert the first 4 records and will fail the 5th and we also can see the output changing the var ret. This code has the same behavior as we have in Zabbix Server.
Thank you for your investigation. I can confirm the issue using Zabbix MySQL data exchange functionality.
Used the following code:
static int dbtest2(char **error)
{
const char *__function_name = "dbtest2";
DB_RESULT result;
DB_ROW row;
const char *table_name = "zbx_10221_test";
#define SQL_FMT "\
INSERT INTO %s VALUES(10, 'ABCD0');\
INSERT INTO %s VALUES(11, 'ABCD2');\
INSERT INTO %s VALUES(12, 'ABCD3');\
INSERT INTO %s VALUES(13, 'ABCD4');\
INSERT INTO %s VALUES(10, 'ABCD8');\
INSERT INTO %s VALUES(16, 'ABCD9');\
INSERT INTO %s VALUES(10, 'ABCD6');"
const ZBX_TABLE table =
{
table_name, "id", 0,
{
{"id", NULL, NULL, NULL, 0, ZBX_TYPE_ID, ZBX_NOTNULL, 0},
{"name", "", NULL, NULL, 50, ZBX_TYPE_CHAR, ZBX_NOTNULL, 0},
{NULL}
}
};
int results = 0, rv, ret = FAIL;
zabbix_log(LOG_LEVEL_DEBUG, "In %s()", __function_name);
if (DBtable_exists(table_name) == SUCCEED && DBdrop_table(table_name) != SUCCEED)
{
*error = zbx_strdup(*error, "cannot delete table");
goto out;
}
if (SUCCEED != DBcreate_table(&table))
{
*error = zbx_strdup(*error, "cannot create table");
goto out;
}
if (ZBX_DB_OK != DBexecute("create index %s_1 on %s (id)", table_name, table_name))
{
*error = zbx_strdup(*error, "cannot add table index");
goto out;
}
DBbegin();
if (ZBX_DB_OK > DBexecute(SQL_FMT,
table_name, table_name, table_name, table_name, table_name, table_name, table_name))
{
*error = zbx_strdup(*error, "cannot execute second INSERT statement");
goto out;
}
ret = SUCCEED;
out:
DBend(ret);
zabbix_log(LOG_LEVEL_DEBUG, "End of %s():%s", __function_name, zbx_result_string(ret));
result = DBselect("select id,name from %s order by id", table_name);
while (NULL != (row = DBfetch(result)))
{
results++;
zabbix_log(LOG_LEVEL_DEBUG, ZBX_FS_UI64 ": [%s]", row[0], row[1]);
}
if (0 == results)
zabbix_log(LOG_LEVEL_DEBUG, "no results");
return ret;
}
The following output is produced:
[5581]: query without transaction detected [5581]: query [txnlev:0] [create table zbx_10221_test ( id bigint unsigned not null, name varchar(50) default '' not null, primary key (id) ) engine=innodb] [5581]: query without transaction detected [5581]: query [txnlev:0] [create index zbx_10221_test_1 on zbx_10221_test (id)] [5581]: query [txnlev:1] [begin;] [5581]: query [txnlev:1] [INSERT INTO zbx_10221_test VALUES(10, 'ABCD0');INSERT INTO zbx_10221_test VALUES(11, 'ABCD2');INSERT INTO zbx_10221_test VALUES(12, 'ABCD3');INSERT INTO zbx_10221_test VALUES(13, 'ABCD4');INSERT INTO zbx_10221_test VALUES(10, 'ABCD8');INSERT INTO zbx_10221_test VALUES(16, 'ABCD9');INSERT INTO zbx_10221_test VALUES(10, 'ABCD6');] [5581]: Error: [Z3005] query failed: [1062] Duplicate entry '10' for key 'PRIMARY' [INSERT INTO zbx_10221_test VALUES(10, 'ABCD0');INSERT INTO zbx_10221_test VALUES(11, 'ABCD2');INSERT INTO zbx_10221_test VALUES(12, 'ABCD3');INSERT INTO zbx_10221_test VALUES(13, 'ABCD4');INSERT INTO zbx_10221_test VALUES(10, 'ABCD8');INSERT INTO zbx_10221_test VALUES(16, 'ABCD9');INSERT INTO zbx_10221_test VALUES(10, 'ABCD6');] [5581]: query [txnlev:1] [commit;] [5581]: End of dbtest2():SUCCEED [5581]: query [txnlev:0] [select id,name from zbx_10221_test order by id] [5581]: 10: [ABCD0] [5581]: 11: [ABCD2] [5581]: 12: [ABCD3] [5581]: 13: [ABCD4]
As we can see executing 7 insert statements in one query in a transaction resulted in 4 new rows. At the end of transaction "commit" was called instead of "rollback".
Problem does not happen with PostgreSQL.
[25485] query [txnlev:1] [begin;] [25485] query [txnlev:1] [INSERT INTO zbx_10221_test VALUES(10, 'ABCD0');INSERT INTO zbx_10221_test VALUES(11, 'ABCD2');INSERT INTO zbx_10221_test VALUES(12, 'ABCD3');INSERT INTO zbx_10221_test VALUES(13, 'ABCD4');INSERT INTO zbx_10221_test VALUES(10, 'ABCD8');INSERT INTO zbx_10221_test VALUES(16, 'ABCD9');INSERT INTO zbx_10221_test VALUES(10, 'ABCD6');] [25485]: Error: [Z3005] query failed: [0] PGRES_FATAL_ERROR:ERROR: duplicate key value violates unique constraint "zbx_10221_test_pkey" DETAIL: Key (id)=(10) already exists. [INSERT INTO zbx_10221_test VALUES(10, 'ABCD0');INSERT INTO zbx_10221_test VALUES(11, 'ABCD2');INSERT INTO zbx_10221_test VALUES(12, 'ABCD3');INSERT INTO zbx_10221_test VALUES(13, 'ABCD4');INSERT INTO zbx_10221_test VALUES(10, 'ABCD8');INSERT INTO zbx_10221_test VALUES(16, 'ABCD9');INSERT INTO zbx_10221_test VALUES(10, 'ABCD6');] [25485] query [INSERT INTO zbx_10221_test VALUES(10, 'ABCD0');INSERT INTO zbx_10221_test VALUES(11, 'ABCD2');INSERT INTO zbx_10221_test VALUES(12, 'ABCD3');INSERT INTO zbx_10221_test VALUES(13, 'ABCD4');INSERT INTO zbx_10221_test VALUES(10, 'ABCD8');INSERT INTO zbx_10221_test VALUES(16, 'ABCD9');INSERT INTO zbx_10221_test VALUES(10, 'ABCD6');] failed, setting transaction as failed [25485] query [txnlev:1] [rollback;] [25485] End of dbtest2():FAIL [25485] query [txnlev:0] [select id,name from zbx_10221_test order by id] [25485] no results
The fix (for 2.4.7) to properly handle such a situation and issue a rollback is as follows:
--- src/libs/zbxdb/db.c (revision 58027)
+++ src/libs/zbxdb/db.c (working copy)
@@ -1090,7 +1090,10 @@
/* more results? -1 = no, >0 = error, 0 = yes (keep looping) */
if (0 < (status = mysql_next_result(conn)))
+ {
zabbix_errlog(ERR_Z3005, mysql_errno(conn), mysql_error(conn), sql);
+ ret = ZBX_DB_FAIL;
+ }
}
while (0 == status);
}
But still, would it be possible to get the parts of the zabbix_server log file containing "query failed" strings?
@Dimir, sorry for the delay. I'm sending some parts of the zabbix_server log.
16319:20160129:031944.339 [Z3005] query failed: [1366] Incorrect string value: '\xEF\xBB\xBF#!/...' for column 'error' at row 1 [update items set error='Received value [XXXX: line 1: <U+FEFF>#!/bin/bash: No such file or directory/XXXX.conf: line 1: <U+FEFF>#: command not found8839] is not suitable for value type [Numeric (unsigned)] and data type [Decimal]' where itemid=1314581; ] 16319:20160129:031944.339 [Z3005] query failed: [1366] Incorrect string value: '\xEF\xBB\xBF#!/...' for column 'error' at row 1 [update items set error='Received value [/XXXX: line 1: <U+FEFF>#!/bin/bash: No such file or directory/XXXX.conf: line 1: <U+FEFF>#: command not found8839] is not suitable for value type [Numeric (unsigned)] and data type [Decimal]' where itemid=1314581; ] 16317:20160129:032041.793 [Z3005] query failed: [1366] Incorrect string value: '\xE6\xB2\xA1\xE6\x9C\x89...' for column 'error' at row 1 [update triggers set error='Received value [/bin/cat: /XXXX: No such file or directory-0.9902] is not suitable for value type ' where triggerid=497702; update triggers set error='Received value [/bin/cat: /XXXX: 没有那个文件或目录-0.9902] is not suitable for value type [Numeric (unsign' where triggerid=567658; ] 16320:20160129:032046.697 [Z3005] query failed: [1366] Incorrect string value: '\xE6\xB2\xA1\xE6\x9C\x89...' for column 'error' at row 1 [update triggers set error='Received value [/bin/cat: /XXXX: 没有那个文件或目录-0.9902] is not suitable for value type [Num' where triggerid=567658; ] 16319:20160129:032145.801 [Z3005] query failed: [1366] Incorrect string value: '\xEF\xBB\xBF: c...' for column 'error' at row 1 [update items set error='Received value [/XXXX.conf: line 1: <U+FEFF>: command not found83562] is not suitable for value type [Numeric (unsigned)] and data type [Decimal]' where itemid=1243305; ] 16317:20160129:032150.852 [Z3005] query failed: [1366] Incorrect string value: '\xEF\xBB\xBF#!/...' for column 'error' at row 1 [update items set state=1,error='Received value [timeout while executing a shell script] is not suitable for value type [Numeric (float)]' where itemid=1096303; update items set error='Received value [/XXXX: line 1: <U+FEFF>#!/bin/bash: 没有那个文件或目录/XXXX.conf: line 1: <U+FEFF>#: command not found38452060191] is not suitable for value type [Numeric (unsigned)] and data type [Decimal]' where itemid=1323106; ] 16318:20160129:032150.854 [Z3005] query failed: [1366] Incorrect string value: '\xEF\xBB\xBF#!/...' for column 'error' at row 1 [update items set state=1,error='Received value [] is not suitable for value type [Numeric (float)]' where itemid=1044709; update items set state=1,error='Received value [] is not suitable for value type [Numeric (unsigned)] and data type [Decimal]' where itemid=1044710; update items set state=1,error='Timeout while executing a shell script.' where itemid=1309006; update items set error='Received value [/XXXX: line 1: <U+FEFF>#!/bin/bash: 没有那个文件或目录/XXXX.conf: line 1: <U+FEFF>#: command not found19301483] is not suitable for value type [Numeric (unsigned)] and data type [Decimal]' where itemid=1323109; ] 16318:20160129:032151.280 [Z3005] query failed: [1366] Incorrect string value: '\xEF\xBB\xBF#!/...' for column 'error' at row 1 [update triggers set state=1,error='Timeout while executing a shell script.' where triggerid=481572; update triggers set state=1,error='Timeout while executing a shell script.' where triggerid=481573; update triggers set error='Received value [/XXXX: line 1: <U+FEFF>#!/bin/bash: 没有那个文件或目录/XXXX' where triggerid=486993; ] 16318:20160129:032309.591 [Z3005] query failed: [1366] Incorrect string value: '\xEF\xBB\xBF#!/...' for column 'error' at row 1 [update items set error='Received value [/XXXX: line 1: <U+FEFF>#!/bin/bash: No such file or directory/XXXX.conf: line 1: <U+FEFF>#: command not found28461117] is not suitable for value type [Numeric (unsigned)] and data type [Decimal]' where itemid=1175589; update items set error='Received value [timeout while executing a shell script] is not suitable for value type [Numeric (unsigned)] and data type [Decimal]' where itemid=1453981; update items set error='Received value [timeout while executing a shell script] is not suitable for value type [Numeric (unsigned)] and data type [Decimal]' where itemid=1453982; update items set error='Received value [timeout while executing a shell script] is not suitable for value type [Numeric (unsigned)] and data type [Decimal]' where itemid=1453983; ]
Thank you for your help!
I could not reproduce your error. It seems you have character set problem somewhere. Could you show the results of the following SQL queries?
SELECT `tables`.`TABLE_NAME`, `collations`.`character_set_name` FROM `information_schema`.`TABLES` AS `tables`, `information_schema`.`COLLATION_CHARACTER_SET_APPLICABILITY` AS `collations` WHERE `tables`.`table_schema` = DATABASE() AND `collations`.`collation_name` = `tables`.`table_collation` and `tables`.`TABLE_NAME`='items'; SHOW FULL COLUMNS FROM `items` where `field`='error'; SHOW VARIABLES LIKE '%colla%'; SHOW VARIABLES LIKE '%charac%'; SHOW VARIABLES LIKE "%version%";
I thought the same as you when I saw the log. The result for your queries are below and we can see the field error is using latin1_swedish_ci instead a utfXX.
mysql> SELECT `tables`.`TABLE_NAME`, `collations`.`character_set_name` FROM `information_schema`.`TABLES` AS `tables`, `information_schema`.`COLLATION_CHARACTER_SET_APPLICABILITY` AS `collations` WHERE `tables`.`table_schema` = DATABASE() AND `collations`.`collation_name` = `tables`.`table_collation` and `tables`.`TABLE_NAME`='items'; +------------+--------------------+ | TABLE_NAME | character_set_name | +------------+--------------------+ | items | latin1 | +------------+--------------------+ 1 row in set (0.01 sec) mysql> SHOW FULL COLUMNS FROM `items` where `field`='error'; +-------+---------------+-------------------+------+-----+---------+-------+---------------------------------+---------+ | Field | Type | Collation | Null | Key | Default | Extra | Privileges | Comment | +-------+---------------+-------------------+------+-----+---------+-------+---------------------------------+---------+ | error | varchar(2048) | latin1_swedish_ci | NO | | | | select,insert,update,references | | +-------+---------------+-------------------+------+-----+---------+-------+---------------------------------+---------+ 1 row in set (0.00 sec) mysql> SHOW VARIABLES LIKE '%colla%'; +----------------------+-----------------+ | Variable_name | Value | +----------------------+-----------------+ | collation_connection | utf8_general_ci | | collation_database | utf8_general_ci | | collation_server | utf8_unicode_ci | +----------------------+-----------------+ 3 rows in set (0.00 sec) mysql> SHOW VARIABLES LIKE '%charac%'; +--------------------------+-------------------------------------+ | Variable_name | Value | +--------------------------+-------------------------------------+ | character_set_client | utf8 | | character_set_connection | utf8 | | character_set_database | utf8 | | character_set_filesystem | binary | | character_set_results | utf8 | | character_set_server | utf8 | | character_set_system | utf8 | | character_sets_dir | /usr/share/percona-server/charsets/ | +--------------------------+-------------------------------------+ 8 rows in set (0.01 sec) mysql> SHOW VARIABLES LIKE "%version%"; +-------------------------+--------------------------------------------------+ | Variable_name | Value | +-------------------------+--------------------------------------------------+ | innodb_version | 5.5.40-36.1 | | protocol_version | 10 | | slave_type_conversions | | | version | 5.5.40-36.1-log | | version_comment | Percona Server (GPL), Release 36.1, Revision 707 | | version_compile_machine | x86_64 | | version_compile_os | Linux | +-------------------------+--------------------------------------------------+ 7 rows in set (0.00 sec)
Thank you for the information. So seems the database character set is correct but the table is not. I can't see how this could happen, perhaps you created it manually. But thanks to that this bug was uncovered. We will fix the transaction cancellation issue.
Great - not and easy thing to find !
This DB is 7 years old, from version 1.4 or so, upgraded to 1.8, then 2.x and now 2.4 though there were upgrade issues at one point, so who knows, but doubt we created manually, though this DB has also moved servers several times.
We will fix the DB on our side and confirm back that all is okay.
Our DBA will confirm other tables/fields also.
Thanks for your help.
Thank you for spending the time on investigating the issue and helping us making the product better! 
Fixed in development branch svn://svn.zabbix.com/branches/dev/ZBX-10221 .
(1) While tests showed that mysql_next_result() returned 0 (success & more results) event when DB was shut down, it might be better to check for is_recoverable_mysql_error() and return ZBX_DB_FAIL or ZBX_DB_DOWN depending on it.
dimir Agree. RESOLVED in r58517
wiper CLOSED
Successfully tested
Fixed in pre-2.0.17 (58654), pre-2.2.12 (r58655), pre-2.4.8 (r58657), pre-3.0.2 (r58789), pre-3.1.0 (trunk, r58791).