[1.3.2] Possible problem with trigger updates in zabbix_server

[micha]

Hi,

I have a test installation with 4 hosts. Those hosts are based on the same template with one simple item ( agent.ping ) and one trigger ( {tpl-monitored:agent.ping.nodata(60)}=1 ) where the item is an *active* check.

When I start an agent on on of the hosts, the trigger changes its status from UNKNOWN to FALSE which is ok. The problem is the transition from FALSE to TRUE after the timeout of 60 seconds which is never triggered.

While examinging the sever log I found the following log message:

15341:20070228:152202 In update_functions(17213)
15341:20070228:152202 Executing query:select distinct function,parameter,itemid,lastvalue from functions where itemid=17213
15341:20070228:152202 ItemId:17213 Evaluating nodata(134951547)
15341:20070228:152202 In evaluate_FUNCTION() Function [nodata]
15341:20070228:152202 In evaluate_FUNCTION() pre-7
15341:20070228:152202 In evaluate_FUNCTION() 7 Formula [1]
15341:20070228:152202 In evaluate_FUNCTION() 7 Value [1]
15341:20070228:152202 In evaluate_FUNCTION() 7 Units []
15341:20070228:152202 In evaluate_FUNCTION() 7 Value [1] Units [] Formula [1]
15341:20070228:152202 End of evaluate_FUNCTION. Result [1]
15341:20070228:152202 Result of evaluate_FUNCTION [1]
15341:20070228:152202 Do not update functions, same value
15341:20070228:152202 In update_triggers [itemid:579504922043630397]
15341:20070228:152202 Executing query:select distinct t.triggerid,t.expression,t.status,t.dep_level,t.priority,t.value,t.description from triggers t,functions f,items i where i.status<>3 and i.itemid=f.itemid and t.status=0 and f.triggerid=t.triggerid and f.itemid=579504922043630397
 15341:20070228:152202 End of update_triggers [17213]

The third last line says

15341:20070228:152202 In update_triggers [itemid:579504922043630397]

which seems to be an error in type conversion ( takes place in zabbix_server/functions.c method update_triggers( zbx_uint64_t itemid ) line 290 ).

I executed the query from the last log line above and got no results.
Then I executed the same query but replaced the itemid with 17231 and got the following result:

triggerid  expression  status dep_level	 priority value  description
   12213  {11217}=1  0       0  	   5  	      2       Host {HOSTNAME} reachable

That's what I've figured out so far - unfortunately I'm a bit stuck now.
It'd be great if someone could tell me what's wrong here

The system zabbix is running on is Ubuntu Linux 5.10 ( Breezy Badger ).
I attached the config.log file ( zipping was necessary due to the size of 191kb ).

Cheers,
micha

[micha]

p.s.: macro ZBX_FS_UI64 expands to %llu

[micha]

ok, that's weird.

After figuring out the main loop "main_timer_loop()" in timer/timer.c where all starts, I added more debug output around update_functions() and update_triggers to find out where the value of itemid gets changed.

The changed code in timer/timer.c:

while((row=DBfetch(result)))
{
  DBget_item_from_db(&item,row);

  DBbegin();
  zabbix_log( LOG_LEVEL_DEBUG, "In main_timer_loop, before update_functions [item.itemid:" ZBX_FS_UI64 "]", item.itemid);
  update_functions(&item);
  zabbix_log( LOG_LEVEL_DEBUG, "In main_timer_loop, before update_triggers [item.itemid:" ZBX_FS_UI64 "]", item.itemid);
  update_triggers(item.itemid);
  DBcommit();
}

The log output:

24329:20070228:165717 In main_timer_loop, before update_functions [itemid:17213]
24329:20070228:165717 In update_functions(17213)
24329:20070228:165717 Executing query:select distinct function,parameter,itemid,lastvalue from functions where itemid=17213
24329:20070228:165717 ItemId:17213 Evaluating nodata(134951547)
24329:20070228:165717 In evaluate_FUNCTION() Function [nodata]
24329:20070228:165717 In evaluate_FUNCTION() pre-7
24329:20070228:165717 In evaluate_FUNCTION() 7 Formula [1]
24329:20070228:165717 In evaluate_FUNCTION() 7 Value [1]
24329:20070228:165717 In evaluate_FUNCTION() 7 Units []
24329:20070228:165717 In evaluate_FUNCTION() 7 Value [1] Units [] Formula [1]
24329:20070228:165717 End of evaluate_FUNCTION. Result [1]
24329:20070228:165717 Result of evaluate_FUNCTION [1]
24329:20070228:165717 Do not update functions, same value
24329:20070228:165717 In main_timer_loop, before update_triggers [itemid:17213]
24329:20070228:165717 In update_triggers [itemid:579505574878659389]
24329:20070228:165717 ZBX_FS_UI64 value: %llu
24329:20070228:165717 Executing query:select distinct t.triggerid,t.expression,t.status,t.dep_level,t.priority,t.value,t.description from tr
iggers t,functions f,items i where i.status<>3 and i.itemid=f.itemid and t.status=0 and f.triggerid=t.triggerid and f.itemid=5795055748786593
89
24329:20070228:165717 End of update_triggers [17213]

As you can see, just before the call to update_triggers the itemid is ok.

Next I introduced a local variable itemid at the beginning of the while loop, assigned a copy of item.itemid to it and added this variable to the debug output.

The changed code:

while((row=DBfetch(result)))
{
  zbx_uint64_t itemid;
  DBget_item_from_db(&item,row);

  itemid = item.itemid;

  DBbegin();
  zabbix_log( LOG_LEVEL_DEBUG, "In main_timer_loop, before update_functions [item.itemid:" ZBX_FS_UI64 ",itemid:" ZBX_FS_UI64 "]", item.itemid,itemid);
  update_functions(&item);
  zabbix_log( LOG_LEVEL_DEBUG, "In main_timer_loop, before update_triggers [item.itemid:" ZBX_FS_UI64 ",itemid:" ZBX_FS_UI64 "]", item.itemid,itemid);
  update_triggers(item.itemid);
  zabbix_log( LOG_LEVEL_DEBUG, "In main_timer_loop, after update_triggers [item.itemid:" ZBX_FS_UI64 ",itemid:" ZBX_FS_UI64 "]", item.itemid,itemid);
  DBcommit();
}

To my surprise the log says now:

26485:20070228:171617 In main_timer_loop, before update_functions [item.itemid:17213,itemid:17213]
26485:20070228:171617 In update_functions(17213)
26485:20070228:171617 Executing query:select distinct function,parameter,itemid,lastvalue from functions where itemid=17213
26485:20070228:171617 ItemId:17213 Evaluating nodata(134925699)
26485:20070228:171617 In evaluate_FUNCTION() Function [nodata]
26485:20070228:171617 In evaluate_FUNCTION() pre-7
26485:20070228:171617 In evaluate_FUNCTION() 7 Formula [1]
26485:20070228:171617 In evaluate_FUNCTION() 7 Value [1]
26485:20070228:171617 In evaluate_FUNCTION() 7 Units []
26485:20070228:171617 In evaluate_FUNCTION() 7 Value [1] Units [] Formula [1]
26485:20070228:171617 End of evaluate_FUNCTION. Result [1]
26485:20070228:171617 Result of evaluate_FUNCTION [1]
26485:20070228:171617 Do not update functions, same value
26485:20070228:171617 In main_timer_loop, before update_triggers [item.itemid:17213,itemid:17213]
26485:20070228:171617 In update_triggers [itemid:17213]
26485:20070228:171617 ZBX_FS_UI64 value: %llu
26485:20070228:171617 Executing query:select distinct t.triggerid,t.expression,t.status,t.dep_level,t.priority,t.value,t.description from tr
iggers t,functions f,items i where i.status<>3 and i.itemid=f.itemid and t.status=0 and f.triggerid=t.triggerid and f.itemid=17213
26485:20070228:171617 In evaluate_expression({11217}=1)
26485:20070228:171617 Before deleting spaces:{11217}=1
26485:20070228:171617 After deleting spaces:{11217}=1
26485:20070228:171617 BEGIN substitute_functions ({11217}=1)
26485:20070228:171617 Executing query:select 0,lastvalue from functions where functionid=11217
26485:20070228:171617 Expression1:[{11217}=1]
26485:20070228:171617 Expression2:[%lf217}=1]
26485:20070228:171617 Expression3:[%lf    =1]
26485:20070228:171617 Before deleting spaces:1.000000    =1
26485:20070228:171617 After deleting spaces:1.000000=1
26485:20070228:171617 Expression4:[1.000000=1]
26485:20070228:171617 Expression:[1.000000=1]
26485:20070228:171617 END substitute_functions
26485:20070228:171617 In evaluate([1.000000=1])
26485:20070228:171617 Evaluating simple expression [1.000000=1]
26485:20070228:171617 = is found
26485:20070228:171617 Evaluating simple expression [1.000000]
26485:20070228:171617 Evaluating simple expression [1]
26485:20070228:171617 Evaluate end:[1.000000]
26485:20070228:171617 In update_trigger_value[triggerid:12213,1,1172679377]
26485:20070228:171617 End of update_triggers [17213]
26485:20070228:171617 In main_timer_loop, after update_triggers [item.itemid:17213,itemid:17213]
26485:20070228:171617 Executing query:commit;

The trigger got executed and I got an alert email - so, this is weird, isn't it ?

My problem is still that I cannot figure out where item.itemid gets changed.

Any ideas ?

Cheers,
micha

[Alexei]

I fixed some debug printing. I believe this is no longer a problem in pre 1.3.4. Please confirm when 1.3.4 is released.