[dev.icinga.com #3728] num_rows_affected broken in libdbi/mariadb, returned ids are 0 #1216

icinga-migration · 2013-02-22T08:40:00Z

This issue has been migrated from Redmine: https://dev.icinga.com/issues/3728

Created by fmbiete on 2013-02-22 08:40:00 +00:00

Assignee: mfriedrich
Status: Resolved (closed on 2013-04-10 16:56:40 +00:00)
Target Version: 1.9
Last Update: 2014-12-08 14:38:03 +00:00 (in Redmine)

Icinga Version: 1.10.0
OS Version: any

Hello,

I'm seeing too much rows in icinga_service_contactgroups where service_id = 0. That's a wrong service id, is that?

MariaDB [icinga]> select * from icinga_service_contactgroups where service_id = 0;
...
|                 1189151 |           1 |          0 |                    625 |
|                 1196209 |           1 |          0 |                    625 |
|                 1198299 |           1 |          0 |                    625 |
|                 1198317 |           1 |          0 |                    625 |
|                 1198335 |           1 |          0 |                    625 |
|                 1198353 |           1 |          0 |                    625 |
|                 1201949 |           1 |          0 |                    625 |
|                 1201985 |           1 |          0 |                    625 |
|                 1209043 |           1 |          0 |                    625 |
|                 1211133 |           1 |          0 |                    625 |
|                 1211151 |           1 |          0 |                    625 |
|                 1211169 |           1 |          0 |                    625 |
|                 1211187 |           1 |          0 |                    625 |
|                 1214783 |           1 |          0 |                    625 |
|                 1214819 |           1 |          0 |                    625 |
+-------------------------+-------------+------------+------------------------+
33589 rows in set (0.02 sec)

MariaDB [icinga]> select count(*) from icinga_service_contactgroups where service_id <> 0;
+----------+
| count(*) |
+----------+
|     6681 |
+----------+

Enabling debug for ido2db show inserts with that service_id.

Tue Feb 19 13:35:34 2013 .572999 [002.0] [pid=19394] [tid=140521238660864] INSERT INTO icinga_service_contactgroups (instance_id, service_id
, contactgroup_object_id) VALUES (1,0,593)
Tue Feb 19 13:35:34 2013 .838768 [002.0] [pid=19394] [tid=140521238660864] INSERT INTO icinga_service_contactgroups (instance_id, service_id
, contactgroup_object_id) VALUES (1,0,593)

If you need more info let me know.

Regards,
Francisco Miguel

Attachments

bug_testing.c fmbiete - 2013-03-10 09:15:01 +00:00
dbqueries.c fmbiete - 2013-03-16 04:43:32 +00:00
3728.diff mfriedrich - 2013-04-06 22:23:08 +00:00
dbquery.diff fmbiete - 2013-04-10 12:20:12 +00:00

Changesets

2013-04-06 22:43:01 +00:00 by (unknown) 0fb5110

idoutils: add workaround fix for num_rows_affected broken in libdbi/mariadb, returned ids are 0 #3728

refs #3728

2013-04-10 18:54:26 +00:00 by (unknown) 6dd703d

idoutils: add workaround fix for num_rows_affected broken in libdbi/mariadb, returned ids are 0 #3728

refs #3728

Conflicts:
	Changelog

The text was updated successfully, but these errors were encountered:

icinga-migration · 2013-02-22T09:15:03Z

Updated by fmbiete on 2013-02-22 09:15:03 +00:00

I'm seeing the same in icinga_host_contactgroups:

MariaDB [icinga]> select count(*) from icinga_host_contactgroups where host_id <> 0;
+----------+
| count(*) |
+----------+
|      579 |
+----------+
1 row in set (0.03 sec)

MariaDB [icinga]> select count(*) from icinga_host_contactgroups where host_id = 0;
+----------+
| count(*) |
+----------+
|     3710 |
+----------+
1 row in set (0.91 sec)

Tue Feb 19 13:32:46 2013 .841351 [002.0] [pid=19394] [tid=140521238660864] INSERT INTO icinga_host_contactgroups (instance_id, host_id, cont
actgroup_object_id) VALUES (1,0,603)
Tue Feb 19 13:32:47 2013 .091827 [002.0] [pid=19394] [tid=140521238660864] INSERT INTO icinga_host_contactgroups (instance_id, host_id, cont
actgroup_object_id) VALUES (1,0,603)
Tue Feb 19 13:32:47 2013 .325926 [002.0] [pid=19394] [tid=140521238660864] INSERT INTO icinga_host_contactgroups (instance_id, host_id, cont
actgroup_object_id) VALUES (1,0,603)
Tue Feb 19 13:32:47 2013 .567489 [002.0] [pid=19394] [tid=140521238660864] INSERT INTO icinga_host_contactgroups (instance_id, host_id, cont
actgroup_object_id) VALUES (1,0,603)

icinga-migration · 2013-03-04T18:11:05Z

Updated by mfriedrich on 2013-03-04 18:11:05 +00:00

i don't have mariadb around, but with my dev setup this does not happen

debian squeeze 6
mysql 5.1.66
icinga 2beb7c0 (current next without changes in that region)

mysql> select * +-------------------------+ | service_contactgroup_id +-------------------------+ | 28232 | | 28233 | | 28234 | | 28235 | | 28236 | | 28237 | | 28238 | | 28239 | | 28240 | | 28241 | | 28242 | | 28243 | | 28244 | | 28245 | | 28246 | | 28247 | | 28248 | | 28249 | | 28250 | | 28251 | +-------------------------+ 20 rows in set (0.02 sec) from icinga_service_contactgroups limit 20;
-------------+------------+------------------------+
| instance_id | service_id | contactgroup_object_id |
-------------+------------+------------------------+
1 | 28218 | 215 |
1 | 28218 | 214 |
1 | 28219 | 215 |
1 | 28219 | 214 |
1 | 28220 | 228 |
1 | 28221 | 228 |
1 | 28222 | 228 |
1 | 28223 | 228 |
1 | 28224 | 228 |
1 | 28225 | 227 |
1 | 28226 | 227 |
1 | 28227 | 224 |
1 | 28228 | 228 |
1 | 28229 | 228 |
1 | 28230 | 224 |
1 | 28231 | 224 |
1 | 28232 | 228 |
1 | 28233 | 224 |
1 | 28234 | 228 |
1 | 28235 | 224 |
-------------+------------+------------------------+

so, does it happen with mysql too?

icinga-migration · 2013-03-04T18:11:32Z

Updated by mfriedrich on 2013-03-04 18:11:32 +00:00

Subject changed from icinga_service_contactgroups rows with service_id = 0 to icinga_service_contactgroups rows with service_id=0 (mariadb)

icinga-migration · 2013-03-07T19:00:47Z

Updated by fmbiete on 2013-03-07 19:00:47 +00:00

I will try with MySql and report back. But will be pretty difficult since I will need to use 5.6 (using group commits in binary logs, and binary log checksum).

Regards,

icinga-migration · 2013-03-08T11:52:02Z

Updated by mfriedrich on 2013-03-08 11:52:02 +00:00

ofc. i need to figure out how and if i may test mariadb (or even mysql 5.6). still, it could be an issue with the queries invoked. can you extract those manually when the config dump happens, and re-run them against your mariadb sql client? there might be some warnings reported which the libdbi driver silently ignores.

icinga-migration · 2013-03-08T11:52:34Z

Updated by mfriedrich on 2013-03-08 11:52:34 +00:00

extracting queries = from the debug log.

icinga-migration · 2013-03-09T19:14:38Z

Updated by fmbiete on 2013-03-09 19:14:38 +00:00

Sat Mar  9 19:54:23 2013 .667710 [002.0] [pid=5968] [tid=139856054175488] SELECT object_id FROM icinga_objects WHERE instance_id=1 AND objecttype_id=12 AND name1='renr-host-alive' AND name2 IS NULL
Sat Mar  9 19:54:23 2013 .692520 [002.0] [pid=5968] [tid=139856054175488] SELECT object_id FROM icinga_objects WHERE instance_id=1 AND objecttype_id=1 AND name1='SEDES\.dominiowin\.mad\.stc' AND name2 IS NULL
Sat Mar  9 19:54:23 2013 .716824 [002.0] [pid=5968] [tid=139856054175488] UPDATE icinga_objects SET is_active='1' WHERE instance_id=1 AND objecttype_id=1 AND object_id=27
Sat Mar  9 19:54:23 2013 .740880 [002.0] [pid=5968] [tid=139856054175488] SELECT object_id FROM icinga_objects WHERE instance_id=1 AND objecttype_id=9 AND name1='24x7' AND name2 IS NULL
Sat Mar  9 19:54:23 2013 .765295 [002.0] [pid=5968] [tid=139856054175488] SELECT object_id FROM icinga_objects WHERE instance_id=1 AND objecttype_id=9 AND name1='24x7' AND name2 IS NULL
Sat Mar  9 19:54:23 2013 .789197 [002.0] [pid=5968] [tid=139856054175488] UPDATE icinga_hosts SET alias='STC - SEDES DC Madrid', display_name='SEDES\.dominiowin\.mad\.stc', address='10\.1\.17\.157', check_command_object_id=14203, check_command_args='', eventhandler_command_object_id=0, eventhandler_command_args='', check_timeperiod_object_id=3, notification_timeperiod_object_id=3, failure_prediction_options='', check_interval=5.000000, retry_interval=1.000000, max_check_attempts=5, first_notification_delay=0.000000, notification_interval=30.000000, notify_on_down=1, notify_on_unreachable=1, notify_on_recovery=1, notify_on_flapping=0, notify_on_downtime=0, stalk_on_up=0, stalk_on_down=0, stalk_on_unreachable=0, flap_detection_enabled=1, flap_detection_on_up=1, flap_detection_on_down=1, flap_detection_on_unreachable=1, low_flap_threshold=0.000000, high_flap_threshold=0.000000, process_performance_data=1, freshness_checks_enabled=0, freshness_threshold=0, passive_checks_enabled=1, event_handler_enabled=1, active_checks_enabled=1, retain_status_information=1, retain_nonstatus_information=1, notifications_enabled=1, obsess_over_host=1, failure_prediction_enabled=1, notes='', notes_url='', action_url='/pnp4nagios/graph\?host=\$HOSTNAME\$\' class=\'tips\' rel=\'/pnp4nagios/popup\?host=\$HOSTNAME\$&srv=_HOST_', icon_image='windows_server2\.png', icon_image_alt='Servidor Windows', vrml_image='windows_server2\.gd2', statusmap_image='', have_2d_coords=0, x_2d=-1, y_2d=-1, have_3d_coords=0, x_3d=0.000000, y_3d=0.000000, z_3d=0.000000, address6='SEDES\.dominiowin\.mad\.stc' WHERE instance_id=1 AND config_type=1 AND host_object_id=27
Sat Mar  9 19:54:23 2013 .814350 [002.0] [pid=5968] [tid=139856054175488] SELECT host_id FROM icinga_hosts WHERE instance_id=1 AND config_type=1 AND host_object_id=27
Sat Mar  9 19:54:23 2013 .838341 [002.0] [pid=5968] [tid=139856054175488] SELECT object_id FROM icinga_objects WHERE instance_id=1 AND objecttype_id=11 AND name1='nogroup' AND name2 IS NULL
Sat Mar  9 19:54:23 2013 .862591 [002.0] [pid=5968] [tid=139856054175488] INSERT INTO icinga_host_contactgroups (instance_id, host_id, contactgroup_object_id) VALUES (1,0,14541)

mysql> SELECT object_id FROM icinga_objects WHERE instance_id=1 AND objecttype_id=12 AND name1='renr-host-alive' AND name2 IS NULL;
+-----------+
| object_id |
+-----------+
|     14203 |
+-----------+
1 row in set (0.01 sec)

mysql> SELECT object_id FROM icinga_objects WHERE instance_id=1 AND objecttype_id=1 AND name1='SEDES\.dominiowin\.mad\.stc' AND name2 IS NULL;
+-----------+
| object_id |
+-----------+
|        27 |                                                                                                                                                                                                                                
+-----------+                                                                                                                                                                                                                                
1 row in set (0.01 sec)                                                                                                                                                                                                                      

mysql> SELECT object_id FROM icinga_objects WHERE instance_id=1 AND objecttype_id=9 AND name1='24x7' AND name2 IS NULL;                                                                                                                      
+-----------+                                                                                                                                                                                                                                
| object_id |                                                                                                                                                                                                                                
+-----------+                                                                                                                                                                                                                                
|         3 |                                                                                                                                                                                                                                
+-----------+                                                                                                                                                                                                                                
1 row in set (0.01 sec)                                                                                                                                                                                                                      

mysql> SELECT object_id FROM icinga_objects WHERE instance_id=1 AND objecttype_id=9 AND name1='24x7' AND name2 IS NULL;                                                                                                                      
+-----------+                                                                                                                                                                                                                                
| object_id |                                                                                                                                                                                                                                
+-----------+                                                                                                                                                                                                                                
|         3 |                                                                                                                                                                                                                                
+-----------+                                                                                                                                                                                                                                
1 row in set (0.02 sec)                                                                                                                                                                                                                      

mysql> SELECT host_id FROM icinga_hosts WHERE instance_id=1 AND config_type=1 AND host_object_id=27;                                                                                                                                         
+---------+
| host_id |
+---------+
|      25 |
+---------+
1 row in set (0.01 sec)

mysql> SELECT object_id FROM icinga_objects WHERE instance_id=1 AND objecttype_id=11 AND name1='nogroup' AND name2 IS NULL;
+-----------+
| object_id |
+-----------+
|     14541 |
+-----------+
1 row in set (0.01 sec)

Just a little bit around a bad insert (I thinks that will be enough, but I have more... the debug log file is huge).

Look at these things:

SELECT object_id FROM icinga_objects WHERE instance_id=1 AND objecttype_id=9 AND name1='24x7' AND name2 IS NULL

That select appears 2 times, with the same values...

Sat Mar  9 19:54:23 2013 .814350 [002.0] [pid=5968] [tid=139856054175488] SELECT host_id FROM icinga_hosts WHERE instance_id=1 AND config_type=1 AND host_object_id=27

Selecting from the client returns a row.

Sat Mar  9 19:54:23 2013 .838341 [002.0] [pid=5968] [tid=139856054175488] SELECT object_id FROM icinga_objects WHERE instance_id=1 AND objecttype_id=11 AND name1='nogroup' AND name2 IS NULL

This return 14541

And here we have an insert creating a bad data row. Host_id == 0. Why??

Sat Mar  9 19:54:23 2013 .862591 [002.0] [pid=5968] [tid=139856054175488] INSERT INTO icinga_host_contactgroups (instance_id, host_id, contactgroup_object_id) VALUES (1,0,14541)

icinga-migration · 2013-03-09T19:22:33Z

Updated by mfriedrich on 2013-03-09 19:22:33 +00:00

so it affects host_contactgroups as well, not only service_contactgroups, as your analysis differs from the original report.

any other tables affected as well?

icinga-migration · 2013-03-09T19:31:31Z

Updated by fmbiete on 2013-03-09 19:31:31 +00:00

It doesn't happen only with host_contactgroups.

Maybe data [ 1 ] gets corrupted somehow or not assigned??

Sat Mar  9 19:52:56 2013 .821129 [002.0] [pid=5968] [tid=139856054175488] INSERT INTO icinga_timeperiod_timeranges (instance_id, timeperiod_id, day, start_sec, end_sec) VALUES (1,0,0,0,86400),(1,0,1,0,86400),(1,0,2,0,86400),(1,0,3,0,8640
0),(1,0,4,0,86400),(1,0,5,0,86400),(1,0,6,0,86400)
Sat Mar  9 19:54:16 2013 .856448 [002.0] [pid=5968] [tid=139856054175488] INSERT INTO icinga_contactgroup_members (instance_id, contactgroup_id, contact_object_id) VALUES (1,0,13939)
Sat Mar  9 19:56:59 2013 .872011 [002.0] [pid=5968] [tid=139856054175488] INSERT INTO icinga_service_contactgroups (instance_id, service_id, contactgroup_object_id) VALUES (1,0,14531)
Sat Mar  9 20:20:56 2013 .161521 [002.0] [pid=5968] [tid=139856054175488] INSERT INTO icinga_servicegroup_members (instance_id, servicegroup_id, service_object_id) VALUES (1,0,5241),(1,0,5279),(1,0,5281)

icinga-migration · 2013-03-10T09:15:01Z

Updated by fmbiete on 2013-03-10 09:15:01 +00:00

File added bug_testing.c

With this test MySQL-DBI returns non 0 when updating a row, against MariaDB.

mysql> create table testdbi (id integer, intvalue integer, PRIMARY KEY (id));
Query OK, 0 rows affected (0.10 sec)

icinga:~/src/bug_testing# ./bug 
DBI returns 0 rows affected
Row not found
INSERT done

icinga:~/src/bug_testing# ./bug 
DBI returns not 0 value: 1
Found: intvalue = 1

icinga:~/src/bug_testing# rpm -q libdbi
libdbi-0.8.3-3.1.el6.x86_64

icinga-migration · 2013-03-13T23:42:51Z

Updated by mfriedrich on 2013-03-13 23:42:51 +00:00

nice test.

and yes, it's likely a bug difficult to nail down. though, the debug logs are very detailed on verbosity=2 and level=-1 ... can you post an excerpt from a complete function call to "ido2db_handle_servicedefinition() start" til end, and marking the important sections, such as the fields required. codewise, within dbhandlers.c, ignore all #ifdef USE_ORACLE sections.

e.g servicedefinition

the service_id which is 0 in your example

        /* build a multiple insert value array */
        if (asprintf(&buf1, "INSERT INTO %s (instance_id, service_id, contactgroup_object_id) VALUES ",
                     ido2db_db_tablenames[IDO2DB_DBTABLE_SERVICECONTACTGROUPS]
                    ) == -1)
                buf1 = NULL;

....
        first = 1;

        mbuf = idi->mbuf[IDO2DB_MBUF_CONTACTGROUP];
        for (x = 0; x < mbuf.used_lines; x++) {

                if (mbuf.buffer[x] == NULL)
                        continue;

                /* get the object id of the member */
                result = ido2db_get_object_id_with_insert(idi,
                         IDO2DB_OBJECTTYPE_CONTACTGROUP, mbuf.buffer[x], NULL,
                         &member_id);

                buf = buf1; /* save this pointer for later free'ing */

#ifdef USE_LIBDBI
                if (asprintf(&buf1, "%s%s(%lu,%lu,%lu)",
                             buf1,
                             (first == 1 ? "" : ","),
                             idi->dbinfo.instance_id,
                             service_id,
                             member_id
                            ) == -1)
                        buf1 = NULL;
#endif

is returned here as reference.

        result = ido2db_query_insert_or_update_servicedefinition_definition_add(idi, data, &service_id);

within dbqueries.c you'll see that the param name is generic "id".

int ido2db_query_insert_or_update_servicedefinition_definition_add(ido2db_idi *idi, void **data, unsigned long *id) {

there are 2 ways of fetching the id.

update failed, but insert was ok, use the last sequence
update was ok, select the id

likely you issue is related to fetching the service id here, and not the one level down inserts afterwards. (and other first class objects, like timeperiods, contactgroups, servicegroups).
you might check the debug log for harming entries on these objects too. maybe some dbi getulonglong or similar returns the wrong values too.

icinga-migration · 2013-03-15T19:06:55Z

Updated by fmbiete on 2013-03-15 19:06:55 +00:00

Here is the fragment debug log.

Fri Mar 15 18:32:31 2013 .424106 [001.2] [pid=29100] [tid=139957315675904] ido2db_handle_servicedefinition() start
Fri Mar 15 18:32:31 2013 .424125 [001.2] [pid=29100] [tid=139957315675904] ido2db_convert_standard_data_elements() start
Fri Mar 15 18:32:31 2013 .424151 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string('') start
Fri Mar 15 18:32:31 2013 .424170 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string end
Fri Mar 15 18:32:31 2013 .424188 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_object_id_with_insert() start
Fri Mar 15 18:32:31 2013 .424206 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_object_id() start
Fri Mar 15 18:32:31 2013 .424224 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_cached_object_id() start
Fri Mar 15 18:32:31 2013 .424241 [001.2] [pid=29100] [tid=139957315675904] ido2db_object_hashfunc() start
Fri Mar 15 18:32:31 2013 .424259 [001.2] [pid=29100] [tid=139957315675904] ido2db_object_hashfunc() end
Fri Mar 15 18:32:31 2013 .424276 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_cached_object_id(0) end
Fri Mar 15 18:32:31 2013 .424294 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string('check_dummy') start
Fri Mar 15 18:32:31 2013 .424312 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string end
Fri Mar 15 18:32:31 2013 .424336 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_query() start
Fri Mar 15 18:32:31 2013 .437493 [002.0] [pid=29100] [tid=139957315675904] SELECT object_id FROM icinga_objects WHERE instance_id=1 AND objecttype_id=12 AND name1='check_dummy' AND name2 IS NULL
Fri Mar 15 18:32:31 2013 .450124 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_query(0) end
Fri Mar 15 18:32:31 2013 .450166 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_object_id(14055) end
Fri Mar 15 18:32:31 2013 .450187 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string('0') start
Fri Mar 15 18:32:31 2013 .450206 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string end
Fri Mar 15 18:32:31 2013 .450233 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_object_id_with_insert() start
Fri Mar 15 18:32:31 2013 .450251 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string('') start
Fri Mar 15 18:32:31 2013 .450269 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string end
Fri Mar 15 18:32:31 2013 .450286 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string('') start
Fri Mar 15 18:32:31 2013 .450304 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string end
Fri Mar 15 18:32:31 2013 .450321 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string('/pnp4nagios/graph?host=$HOSTNAME$&srv=$SERVICEDESC$' class='tips' rel='/pnp4nagios/popup?host=$HOSTNAME$&srv=$SERVICEDESC$') start
Fri Mar 15 18:32:31 2013 .450341 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string changed string ('/pnp4nagios/graph\?host=\$HOSTNAME\$&srv=\$SERVICEDESC\$\' class=\'tips\' rel=\'/pnp4nagios/popup\?host=\$HOSTNAME\$&srv=\$SERVICEDESC\$')
Fri Mar 15 18:32:31 2013 .450359 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string end
Fri Mar 15 18:32:31 2013 .450376 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string('') start
Fri Mar 15 18:32:31 2013 .450393 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string end
Fri Mar 15 18:32:31 2013 .450411 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string('') start
Fri Mar 15 18:32:31 2013 .450428 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string end
Fri Mar 15 18:32:31 2013 .450445 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string('BW Corporativa') start
Fri Mar 15 18:32:31 2013 .450463 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string end
Fri Mar 15 18:32:31 2013 .450481 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_object_id_with_insert() start
Fri Mar 15 18:32:31 2013 .450498 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_object_id() start
Fri Mar 15 18:32:31 2013 .450534 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_cached_object_id() start
Fri Mar 15 18:32:31 2013 .450555 [001.2] [pid=29100] [tid=139957315675904] ido2db_object_hashfunc() start
Fri Mar 15 18:32:31 2013 .450572 [001.2] [pid=29100] [tid=139957315675904] ido2db_object_hashfunc() end
Fri Mar 15 18:32:31 2013 .450590 [001.2] [pid=29100] [tid=139957315675904] ido2db_compare_object_hashdata() start
Fri Mar 15 18:32:31 2013 .450608 [001.2] [pid=29100] [tid=139957315675904] ido2db_compare_object_hashdata() start
Fri Mar 15 18:32:31 2013 .450626 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_cached_object_id(1075) end
Fri Mar 15 18:32:31 2013 .450643 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_object_id(1075) return cached object
Fri Mar 15 18:32:31 2013 .450661 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_object_id_with_insert() start
Fri Mar 15 18:32:31 2013 .450679 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_object_id() start
Fri Mar 15 18:32:31 2013 .450696 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_cached_object_id() start
Fri Mar 15 18:32:31 2013 .450713 [001.2] [pid=29100] [tid=139957315675904] ido2db_object_hashfunc() start
Fri Mar 15 18:32:31 2013 .450731 [001.2] [pid=29100] [tid=139957315675904] ido2db_object_hashfunc() end
Fri Mar 15 18:32:31 2013 .450748 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_cached_object_id(0) end
Fri Mar 15 18:32:31 2013 .450766 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string('977_ppal.router.stc') start
Fri Mar 15 18:32:31 2013 .450784 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string changed string ('977_ppal\.router\.stc')
Fri Mar 15 18:32:31 2013 .450802 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string end
Fri Mar 15 18:32:31 2013 .450824 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_query() start
Fri Mar 15 18:32:31 2013 .462864 [002.0] [pid=29100] [tid=139957315675904] SELECT object_id FROM icinga_objects WHERE instance_id=1 AND objecttype_id=1 AND name1='977_ppal\.router\.stc' AND name2 IS NULL
Fri Mar 15 18:32:31 2013 .477101 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_query(0) end
Fri Mar 15 18:32:31 2013 .477142 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_object_id(1) end
Fri Mar 15 18:32:31 2013 .477163 [001.2] [pid=29100] [tid=139957315675904] ido2db_set_object_as_active() start
Fri Mar 15 18:32:31 2013 .477184 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_query() start
Fri Mar 15 18:32:31 2013 .489160 [002.0] [pid=29100] [tid=139957315675904] UPDATE icinga_objects SET is_active='1' WHERE instance_id=1 AND objecttype_id=2 AND object_id=1075
Fri Mar 15 18:32:31 2013 .501356 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_query(0) end
Fri Mar 15 18:32:31 2013 .501397 [001.2] [pid=29100] [tid=139957315675904] ido2db_set_object_as_active() end
Fri Mar 15 18:32:31 2013 .501417 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_object_id_with_insert() start
Fri Mar 15 18:32:31 2013 .501435 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_object_id() start
Fri Mar 15 18:32:31 2013 .501453 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_cached_object_id() start
Fri Mar 15 18:32:31 2013 .501470 [001.2] [pid=29100] [tid=139957315675904] ido2db_object_hashfunc() start
Fri Mar 15 18:32:31 2013 .501488 [001.2] [pid=29100] [tid=139957315675904] ido2db_object_hashfunc() end
Fri Mar 15 18:32:31 2013 .501505 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_cached_object_id(0) end
Fri Mar 15 18:32:31 2013 .501545 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string('24x7') start
Fri Mar 15 18:32:31 2013 .501564 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string end
Fri Mar 15 18:32:31 2013 .501587 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_query() start
Fri Mar 15 18:32:31 2013 .513985 [002.0] [pid=29100] [tid=139957315675904] SELECT object_id FROM icinga_objects WHERE instance_id=1 AND objecttype_id=9 AND name1='24x7' AND name2 IS NULL
Fri Mar 15 18:32:31 2013 .526806 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_query(0) end
Fri Mar 15 18:32:31 2013 .526854 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_object_id(3) end
Fri Mar 15 18:32:31 2013 .526876 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_object_id_with_insert() start
Fri Mar 15 18:32:31 2013 .526895 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_object_id() start
Fri Mar 15 18:32:31 2013 .526913 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_cached_object_id() start
Fri Mar 15 18:32:31 2013 .526931 [001.2] [pid=29100] [tid=139957315675904] ido2db_object_hashfunc() start
Fri Mar 15 18:32:31 2013 .526948 [001.2] [pid=29100] [tid=139957315675904] ido2db_object_hashfunc() end
Fri Mar 15 18:32:31 2013 .526966 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_cached_object_id(0) end
Fri Mar 15 18:32:31 2013 .527007 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string('24x7') start
Fri Mar 15 18:32:31 2013 .527027 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string end
Fri Mar 15 18:32:31 2013 .527052 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_query() start
Fri Mar 15 18:32:31 2013 .539173 [002.0] [pid=29100] [tid=139957315675904] SELECT object_id FROM icinga_objects WHERE instance_id=1 AND objecttype_id=9 AND name1='24x7' AND name2 IS NULL
Fri Mar 15 18:32:31 2013 .552802 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_query(0) end
Fri Mar 15 18:32:31 2013 .552873 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_object_id(3) end
Fri Mar 15 18:32:31 2013 .552911 [001.2] [pid=29100] [tid=139957315675904] ido2db_query_insert_or_update_servicedefinition_definition_add() start
Fri Mar 15 18:32:31 2013 .552967 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_query() start
Fri Mar 15 18:32:31 2013 .565111 [002.0] [pid=29100] [tid=139957315675904] UPDATE icinga_services SET host_object_id=1, display_name='BW Corporativa', check_command_object_id=14055, check_command_args='0', eventhandler_command_object_id=0, eventhandler_command_args='', check_timeperiod_object_id=3, notification_timeperiod_object_id=3, failure_prediction_options='', check_interval=5.000000, retry_interval=1.000000, max_check_attempts=1, first_notification_delay=0.000000, notification_interval=5.000000, notify_on_warning=1, notify_on_unknown=0, notify_on_critical=1, notify_on_recovery=1, notify_on_flapping=0, notify_on_downtime=1, stalk_on_ok=0, stalk_on_warning=0, stalk_on_unknown=0, stalk_on_critical=0, is_volatile=0, flap_detection_enabled=1, flap_detection_on_ok=1, flap_detection_on_warning=1, flap_detection_on_unknown=1, flap_detection_on_critical=1, low_flap_threshold=0.000000, high_flap_threshold=0.000000, process_performance_data=1, freshness_checks_enabled=0, freshness_threshold=0, passive_checks_enabled=1, event_handler_enabled=1, active_checks_enabled=0, retain_status_information=1, retain_nonstatus_information=1, notifications_enabled=1, obsess_over_service=1, failure_prediction_enabled=1, notes='', notes_url='', action_url='/pnp4nagios/graph\?host=\$HOSTNAME\$&srv=\$SERVICEDESC\$\' class=\'tips\' rel=\'/pnp4nagios/popup\?host=\$HOSTNAME\$&srv=\$SERVICEDESC\$', icon_image='', icon_image_alt='' WHERE instance_id=1 AND config_type=1 AND service_object_id=1075
Fri Mar 15 18:32:31 2013 .907594 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_query(0) end
Fri Mar 15 18:32:31 2013 .907686 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_query() start
Fri Mar 15 18:32:31 2013 .919382 [002.0] [pid=29100] [tid=139957315675904] SELECT service_id FROM icinga_services WHERE instance_id=1 AND config_type=1 AND service_object_id=1075
Fri Mar 15 18:32:31 2013 .931341 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_query(0) end
Fri Mar 15 18:32:31 2013 .931379 [001.2] [pid=29100] [tid=139957315675904] ido2db_query_insert_or_update_servicedefinition_definition_add() end
Fri Mar 15 18:32:31 2013 .931396 [001.2] [pid=29100] [tid=139957315675904] ido2db_handle_servicedefinition() contactgroups start
Fri Mar 15 18:32:31 2013 .931410 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_object_id_with_insert() start
Fri Mar 15 18:32:31 2013 .931422 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_object_id() start
Fri Mar 15 18:32:31 2013 .931434 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_cached_object_id() start
Fri Mar 15 18:32:31 2013 .931445 [001.2] [pid=29100] [tid=139957315675904] ido2db_object_hashfunc() start
Fri Mar 15 18:32:31 2013 .931457 [001.2] [pid=29100] [tid=139957315675904] ido2db_object_hashfunc() end
Fri Mar 15 18:32:31 2013 .931468 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_cached_object_id(0) end
Fri Mar 15 18:32:31 2013 .931479 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string('grupo-dummy') start
Fri Mar 15 18:32:31 2013 .931491 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_escape_string end
Fri Mar 15 18:32:31 2013 .931506 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_query() start
Fri Mar 15 18:32:31 2013 .943570 [002.0] [pid=29100] [tid=139957315675904] SELECT object_id FROM icinga_objects WHERE instance_id=1 AND objecttype_id=11 AND name1='grupo-dummy' AND name2 IS NULL
Fri Mar 15 18:32:31 2013 .955885 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_query(0) end
Fri Mar 15 18:32:31 2013 .955923 [001.2] [pid=29100] [tid=139957315675904] ido2db_get_object_id(14531) end
Fri Mar 15 18:32:31 2013 .955942 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_query() start
Fri Mar 15 18:32:31 2013 .968179 [002.0] [pid=29100] [tid=139957315675904] INSERT INTO icinga_service_contactgroups (instance_id, service_id, contactgroup_object_id) VALUES (1,0,14531)
Fri Mar 15 18:32:32 2013 .034779 [001.2] [pid=29100] [tid=139957315675904] ido2db_db_query(0) end
Fri Mar 15 18:32:32 2013 .034845 [001.2] [pid=29100] [tid=139957315675904] ido2db_handle_servicedefinition() contactsgroups end
Fri Mar 15 18:32:32 2013 .034859 [001.2] [pid=29100] [tid=139957315675904] ido2db_handle_servicedefinition() service_contacts start
Fri Mar 15 18:32:32 2013 .034873 [001.2] [pid=29100] [tid=139957315675904] ido2db_handle_servicedefinition() service_contacts end
Fri Mar 15 18:32:32 2013 .034885 [001.2] [pid=29100] [tid=139957315675904] ido2db_save_custom_variables() start
Fri Mar 15 18:32:32 2013 .034911 [001.2] [pid=29100] [tid=139957315675904] ido2db_save_custom_variables() end
Fri Mar 15 18:32:32 2013 .034923 [001.2] [pid=29100] [tid=139957315675904] ido2db_handle_servicedefinition() end
Fri Mar 15 18:32:32 2013 .034934 [001.2] [pid=29100] [tid=139957315675904] ido2db_free_input_memory() start
Fri Mar 15 18:32:32 2013 .034955 [001.2] [pid=29100] [tid=139957315675904] ido2db_free_input_memory() end
Fri Mar 15 18:32:32 2013 .034967 [001.2] [pid=29100] [tid=139957315675904] ido2db_end_input_data() end

icinga-migration · 2013-03-15T19:19:07Z

Updated by fmbiete on 2013-03-15 19:19:07 +00:00

Look at this dbqueries.c file, ido2db_query_insert_or_update_servicedefinition_definition_add function, line 7177

service_id = dbi_result_get_ulonglong(idi->dbinfo.dbi_result, "service_id");

You get the service_id into the service_id variable not the *id. In that case *id will not be set??

A fast look into that function and I don't see any place where the variable service_id is read.

icinga-migration · 2013-03-16T04:43:32Z

Updated by fmbiete on 2013-03-16 04:43:32 +00:00

File added dbqueries.c

I modified all the dbqueries.c functions (git version - file attached).

I have deleted the _id variable and assignation, using *id as needed.

I don't see inserts with _id = 0 (it's yet starting... it takes ages to do it)

icinga-migration · 2013-03-16T05:27:43Z

Updated by fmbiete on 2013-03-16 05:27:43 +00:00

After the first start the data seems fine. I don't see any orphaned rows.
Restarting a second time.

icinga-migration · 2013-03-16T14:57:23Z

Updated by fmbiete on 2013-03-16 14:57:23 +00:00

After restarting a few more times, I don't have rows with zeroed's id.

Also icinga_web shows every change done in icinga core (before if a service was deleted it would be showed in icinga_web but not icinga_cgi).

icinga-migration · 2013-03-17T15:36:56Z

Updated by mfriedrich on 2013-03-17 15:36:56 +00:00

that change is incorrect on the algorithm itsself. there is a reason why this value is ignored in that exact location, and e.g. contact_id is read, but ignored at that stage.

the flow for mysql without the insert on duplicate key update madness is like

run the update query
check if there are rows affected
libdbi sometimes returns false even if there are rows affected - so the first SELECT is just a safety select on previous where clause to be really sure that an update just happened
if the update did not happen (mysql_update = false), the actual insert happens.
once the insert happened, the sequence number is fetched and saved as *id
if the update did happen (else tree), a select fetches the contact_id into *id - at this stage the correct id.

using your attempt and actually getting current numbers would mean, that your libdbi implementation does actually return the wrong value on get_num_rows_affected and gets some id after the select again - a location you normally should not hit.

likely this is the error, and my not finished fallback may be completed by changing all the (.*)_id to *id in the insert tree, fixing some libdbi fuckup on special mysql version apis.

if you got a clean patch to apply against next, feel free to share.

icinga-migration · 2013-03-18T14:08:47Z

Updated by fmbiete on 2013-03-18 14:08:47 +00:00

The attached dbqueries.c it's the latest git version with my changes. You can diff against the git tree to review the changes and apply them.

I have changed all the (.)_id to id, and removed the unused variables (maybe it should help compile with -Wunused-but-set-variable)

In the original code, if you hit the select/insert part, * id would not receive any value in the function. It wasn't assigned to anything in that flow of code. That would cause an insert with 0 in the (.*)_id later.

icinga-migration · 2013-03-19T13:39:43Z

Updated by mfriedrich on 2013-03-19 13:39:43 +00:00

Status changed from New to Assigned
Assigned to set to mfriedrich
Target Version set to 1.9

since i cannot test it, i will add something to git and ping back when i got time for it.

icinga-migration · 2013-04-06T22:23:08Z

Updated by mfriedrich on 2013-04-06 22:23:08 +00:00

File added 3728.diff

i can't work with full files, i need diffs - attached.

icinga-migration · 2013-04-06T22:36:32Z

Updated by mfriedrich on 2013-04-06 22:36:32 +00:00

so this is really a problem with libdbi and its mysql driver, or likewise, with the mysql api not returning the proper values on an UPDATE query.

i had that problem once, when i used an older libdbi implementation with a newer mysql version, but right on, i cannot reproduce it (with packages).

so, the safety SELECT which would only be run before the INSERT query, now makes sure that the wrong affected rows from the UPDATE query does not hit yet another INSERT statement, causing a unique constraint violation.

saving the required id over there is a lucky shot for fixing the problem (even - workaround it) on the idoutils part. but the real problem lies somewhere between libdbi and mysql, where icinga cannot provide any fix, and probably you should investigate on your own and report an issue to the libdbi developers as well.

icinga-migration · 2013-04-06T22:39:24Z

Updated by mfriedrich on 2013-04-06 22:39:24 +00:00

i forgot - you should indeed fix the libdbi irritation on your server, as it causes ido2db to fire yet another SELECT query, and may influence the performance badly.

icinga-migration · 2013-04-06T22:41:47Z

Updated by mfriedrich on 2013-04-06 22:41:47 +00:00

Subject changed from icinga_service_contactgroups rows with service_id=0 (mariadb) to num_rows_affected broken in libdbi/mariadb, returned ids are 0

i'm only fixing the affected ids, and leaving the rest alone, for future reference, if any. under normal circumstances, those code regions are never hit during UPDATE queries.

icinga-migration · 2013-04-06T22:46:10Z

Updated by mfriedrich on 2013-04-06 22:46:10 +00:00

Status changed from Assigned to 7
Done % changed from 0 to 100

you may test it in git 'next'.

icinga-migration · 2013-04-09T17:29:44Z

Updated by fmbiete on 2013-04-09 17:29:44 +00:00

Thanks!!

I will try ASAP and report back.
But before I will update libdbi and libdbi-drivers, install mariadb-libs and remove mysql-libs.

icinga-migration · 2013-04-10T12:20:12Z

Updated by fmbiete on 2013-04-10 12:20:12 +00:00

File added dbquery.diff

Hello,

I've installed libdbi 0.9.0, libdbi-drivers 0.9.0 and replaced mysql-libs with mariadb-libs.

EDIT: oops, sorry I missed the 'next' branch.
Yes, your fix works!!

Thank you very much

icinga-migration · 2013-04-10T16:56:40Z

Updated by mfriedrich on 2013-04-10 16:56:40 +00:00

Status changed from 7 to Resolved

thanks for testing. i was waiting for the edit, as your diff shows clearly a different head ;-)

icinga-migration · 2014-12-08T14:38:03Z

Updated by mfriedrich on 2014-12-08 14:38:03 +00:00

Project changed from 18 to Core, Classic UI, IDOUtils
Category changed from 79 to IDOUtils
Icinga Version changed from 1 to 1
OS Version set to any

icinga-migration closed this as completed Apr 10, 2013

icinga-migration added the bug label Jan 17, 2017

icinga-migration added the IDOUtils label Jan 17, 2017

icinga-migration added this to the 1.9 milestone Jan 17, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[dev.icinga.com #3728] num_rows_affected broken in libdbi/mariadb, returned ids are 0 #1216

[dev.icinga.com #3728] num_rows_affected broken in libdbi/mariadb, returned ids are 0 #1216

icinga-migration commented Feb 22, 2013

icinga-migration commented Feb 22, 2013

icinga-migration commented Mar 4, 2013

icinga-migration commented Mar 4, 2013

icinga-migration commented Mar 7, 2013

icinga-migration commented Mar 8, 2013

icinga-migration commented Mar 8, 2013

icinga-migration commented Mar 9, 2013

icinga-migration commented Mar 9, 2013

icinga-migration commented Mar 9, 2013

icinga-migration commented Mar 10, 2013

icinga-migration commented Mar 13, 2013

icinga-migration commented Mar 15, 2013

icinga-migration commented Mar 15, 2013

icinga-migration commented Mar 16, 2013

icinga-migration commented Mar 16, 2013

icinga-migration commented Mar 16, 2013

icinga-migration commented Mar 17, 2013

icinga-migration commented Mar 18, 2013

icinga-migration commented Mar 19, 2013

icinga-migration commented Apr 6, 2013

icinga-migration commented Apr 6, 2013

icinga-migration commented Apr 6, 2013

icinga-migration commented Apr 6, 2013

icinga-migration commented Apr 6, 2013

icinga-migration commented Apr 9, 2013

icinga-migration commented Apr 10, 2013

icinga-migration commented Apr 10, 2013

icinga-migration commented Dec 8, 2014

[dev.icinga.com #3728] num_rows_affected broken in libdbi/mariadb, returned ids are 0 #1216

[dev.icinga.com #3728] num_rows_affected broken in libdbi/mariadb, returned ids are 0 #1216

Comments

icinga-migration commented Feb 22, 2013

icinga-migration commented Feb 22, 2013

icinga-migration commented Mar 4, 2013

icinga-migration commented Mar 4, 2013

icinga-migration commented Mar 7, 2013

icinga-migration commented Mar 8, 2013

icinga-migration commented Mar 8, 2013

icinga-migration commented Mar 9, 2013

icinga-migration commented Mar 9, 2013

icinga-migration commented Mar 9, 2013

icinga-migration commented Mar 10, 2013

icinga-migration commented Mar 13, 2013

icinga-migration commented Mar 15, 2013

icinga-migration commented Mar 15, 2013

icinga-migration commented Mar 16, 2013

icinga-migration commented Mar 16, 2013

icinga-migration commented Mar 16, 2013

icinga-migration commented Mar 17, 2013

icinga-migration commented Mar 18, 2013

icinga-migration commented Mar 19, 2013

icinga-migration commented Apr 6, 2013

icinga-migration commented Apr 6, 2013

icinga-migration commented Apr 6, 2013

icinga-migration commented Apr 6, 2013

icinga-migration commented Apr 6, 2013

icinga-migration commented Apr 9, 2013

icinga-migration commented Apr 10, 2013

icinga-migration commented Apr 10, 2013

icinga-migration commented Dec 8, 2014