[ZBX-19159] Missing tags in recovery operation Created: 2021 Mar 23  Updated: 2024 Dec 19  Resolved: 2021 Jul 17

Status: Closed
Project: ZABBIX BUGS AND ISSUES
Component/s: Server (S)
Affects Version/s: 5.0.9
Fix Version/s: 5.0.12rc1, 5.2.7rc1, 5.4.0rc1, 5.4 (plan)

Type: Problem report Priority: Critical
Reporter: Alexey Pustovalov Assignee: Dmitrijs Goloscapovs
Resolution: Fixed Votes: 2
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: PNG File Screenshot 2021-03-23 at 23.28.07.png     PNG File Screenshot 2021-03-23 at 23.28.13.png     PNG File Screenshot 2021-03-23 at 23.29.37.png     PNG File Screenshot 2021-03-23 at 23.32.32.png     File ZBX-19159-5.0.patch     File zabbix_server.tar.gz    
Issue Links:
Causes
causes ZBX-19481 Zabbix server version 5.0.12 maintena... Closed
Duplicate
Team: Team A
Sprint: Sprint 74 (Mar 2021), Sprint 75 (Apr 2021), Sprint 76 (May 2021), Sprint 77 (Jun 2021), Sprint 78 (Jul 2021)
Story Points: 1

 Description   

1. Create media type withe the following configuration:


and Javascript body (3 seconds delay during problem operation):

var params = JSON.parse(value),
    result = {tags: {}};

if (params.event_value === '0' || params.event_update_status === '1') {
   throw 'Recovery ' + params.servicenow_sys_id;
}
else {
  var now = new Date().getTime();
   while(new Date().getTime() < now + 3000){ /* do nothing */ } 
  result.tags.__zbx_servicenow_number = 'test';
}

return JSON.stringify(result);

2. Configure standard action with the following operations:

3. Create a simple trigger for Zabbix trapper item:

{test:test.last()}=1

4. Send 1 using zabbix_sender, and during 3 seconds send 0 to resolve the problem
5. Finally Problem operation and Recovery operation will b executed, but in recovery operation __zbx_servicenow_number tag is missing!

Problem log:

   209:20210323:232216.948 End substitute_simple_macros_impl() data:'Problem started at 23:22:15 on 2021.03.23
   209:20210323:232216.948 End of add_user_msg()
   209:20210323:232216.948 End of add_user_msgs()
   209:20210323:232216.948 End of add_object_msg()
   209:20210323:232216.948 In add_message_alert()
   209:20210323:232216.948 query [txnlev:0] [select m.mediatypeid,m.sendto,m.severity,m.period,mt.status,m.active from media m,media_type mt where m.mediatypeid=mt.mediatypeid and m.userid=3 and m.mediatypeid=29]
   209:20210323:232216.949 In substitute_simple_macros_impl() data:'1-7,00:00-24:00'
   209:20210323:232216.949 severity:4, media severity:63, period:'1-7,00:00-24:00', userid:3
   209:20210323:232216.949 query [txnlev:0] [select name,value from media_type_param where mediatypeid=29]
   209:20210323:232216.950 In substitute_simple_macros_impl() data:'servicenow_sys_id'
   209:20210323:232216.950 In substitute_simple_macros_impl() data:'{EVENT.TAGS.__zbx_servicenow_number}'
   209:20210323:232216.950 End substitute_simple_macros_impl() data:'{EVENT.TAGS.__zbx_servicenow_number}'
   209:20210323:232216.950 In substitute_simple_macros_impl() data:'event_source'
   209:20210323:232216.950 In substitute_simple_macros_impl() data:'{EVENT.SOURCE}'
   209:20210323:232216.950 End substitute_simple_macros_impl() data:'0'
   209:20210323:232216.950 In substitute_simple_macros_impl() data:'event_update_status'
   209:20210323:232216.950 In substitute_simple_macros_impl() data:'{EVENT.UPDATE.STATUS}'
   209:20210323:232216.950 End substitute_simple_macros_impl() data:'0'
   209:20210323:232216.950 In substitute_simple_macros_impl() data:'event_value'
   209:20210323:232216.950 In substitute_simple_macros_impl() data:'{EVENT.VALUE}'
   209:20210323:232216.950 End substitute_simple_macros_impl() data:'1'
   209:20210323:232216.950 In DCget_nextid() table:'alerts' num:1
   209:20210323:232216.950 End of DCget_nextid() table:'alerts' [19:19]
   209:20210323:232216.950 query without transaction detected
   209:20210323:232216.950 query [txnlev:0] [insert into alerts (alertid,actionid,eventid,userid,clock,mediatypeid,sendto,subject,message,status,error,esc_step,alerttype,acknowledgeid,parameters) values (19,3,33,3,1616523736,29,'dummy','Problem: test2','Problem started at 23:22:15 on 2021.03.23
   209:20210323:232216.951 End of add_message_alert()
   209:20210323:232216.952 query [txnlev:0] [select null from operations where actionid=3 and (esc_step_to>1 or esc_step_to=0) and recovery=0 limit 1]
   209:20210323:232216.952 End of escalation_execute_operations()
   209:20210323:232216.952 End of escalation_execute()
   209:20210323:232216.952 query [txnlev:1] [begin;]
   209:20210323:232216.952 query [txnlev:1] [update escalations set nextcheck=case when r_eventid is null then 1616527336 else 0 end,esc_step=1,status=2 where escalationid=11;
   209:20210323:232216.952 query [txnlev:1] [commit;]
   209:20210323:232216.954 End of process_escalations()
   209:20210323:232216.954 In process_escalations()
   209:20210323:232216.954 query [txnlev:0] [select escalationid,actionid,triggerid,eventid,r_eventid,nextcheck,esc_step,status,itemid,acknowledgeid from escalations where triggerid is null and itemid is not null and nextcheck<=1616523739 order by actionid,triggerid,itemid,escalationid]
   209:20210323:232216.954 End of process_escalations()
   209:20210323:232216.954 In process_escalations()
   209:20210323:232216.954 query [txnlev:0] [select escalationid,actionid,triggerid,eventid,r_eventid,nextcheck,esc_step,status,itemid,acknowledgeid from escalations where triggerid is null and itemid is null and nextcheck<=1616523739 order by actionid,triggerid,itemid,escalationid]
   209:20210323:232216.954 End of process_escalations()
   209:20210323:232216.954 zbx_setproctitle() title:'escalator #1 [processed 0 escalations in 0.012355 sec, idle 3 sec]'
   234:20210323:232217.953 zbx_ipc_socket_read() code:1105 size:638 data:f1 01 00 00 bf 00 00 00 | 36 00 00 00 0f 00 00 00 | 00 00 09 00 01 00 00 00 | 00 00 00 00 00 18 04 0b | 80 00 00 04 0b 00 04 06 | 00 01 06 05 d2 00 00 07 | 00 00 05 01 b0 00 05 01 | 00 00 06 01 c0 00 02 07 | 03 00 08 00 c0 02 07 06 | c2 00 06 02 00 03 01 04 | 6e 04 04 05 1a 00 05 00 | 32 80 00 02 02 05 01 06 | 6e 06 06 05 1a 00 05 00 | 30 80 00 04 02 07 01 04 | 6e 04 08 04 35 00 04 00 | a9 80 00 18 02 00 09 04
   234:20210323:232217.953 End of zbx_ipc_socket_read():SUCCEED
   234:20210323:232217.953 In zbx_es_execute() param:{"servicenow_sys_id":"{EVENT.TAGS.__zbx_servicenow_number}","event_source":"0","event_update_status":"0","event_value":"1"}
...
   242:20210323:232220.963 query [txnlev:1] [insert into event_tag (eventtagid,eventid,tag,value) values (5,33,'__zbx_servicenow_number','test');
   242:20210323:232220.963 query [txnlev:1] [insert into problem_tag (problemtagid,eventid,tag,value) values (5,33,'__zbx_servicenow_number','test');

Recovery log:

  209:20210323:232219.956 query [txnlev:0] [select eventid,tag,value from event_tag where eventid in (33,34) order by eventid]
...
   209:20210323:232219.959 query [txnlev:0] [select name,value from media_type_param where mediatypeid=29]
   209:20210323:232219.959 In substitute_simple_macros_impl() data:'servicenow_sys_id'
   209:20210323:232219.959 In substitute_simple_macros_impl() data:'{EVENT.TAGS.__zbx_servicenow_number}'
   209:20210323:232219.959 End substitute_simple_macros_impl() data:'{EVENT.TAGS.__zbx_servicenow_number}'
   209:20210323:232219.959 In substitute_simple_macros_impl() data:'event_source'
   209:20210323:232219.959 In substitute_simple_macros_impl() data:'{EVENT.SOURCE}'
   209:20210323:232219.959 End substitute_simple_macros_impl() data:'0'
   209:20210323:232219.959 In substitute_simple_macros_impl() data:'event_update_status'
   209:20210323:232219.959 In substitute_simple_macros_impl() data:'{EVENT.UPDATE.STATUS}'
   209:20210323:232219.959 End substitute_simple_macros_impl() data:'0'
   209:20210323:232219.959 In substitute_simple_macros_impl() data:'event_value'
   209:20210323:232219.959 In substitute_simple_macros_impl() data:'{EVENT.VALUE}'
   209:20210323:232219.959 End substitute_simple_macros_impl() data:'0'
   209:20210323:232219.959 In DCget_nextid() table:'alerts' num:1
   209:20210323:232219.959 End of DCget_nextid() table:'alerts' [20:20]
   209:20210323:232219.959 query without transaction detected
   209:20210323:232219.959 query [txnlev:0] [insert into alerts (alertid,actionid,eventid,userid,clock,mediatypeid,sendto,subject,message,status,error,esc_step,alerttype,acknowledgeid,parameters,p_eventid) values (20,3,34,3,1616523739,29,'dummy','Resolved in 2s: test2','Problem has been resolved at 23:22:17 on 2021.03.23
   209:20210323:232219.961 End of add_message_alert()
   209:20210323:232219.961 End of escalation_execute_recovery_operations()
   209:20210323:232219.961 End of escalation_recover()
   209:20210323:232219.961 query [txnlev:1] [begin;]
   209:20210323:232219.961 query [txnlev:1] [delete from escalations where escalationid=11;
   209:20210323:232219.961 query [txnlev:1] [commit;]
   209:20210323:232219.962 End of process_escalations()
   209:20210323:232219.962 In process_escalations()
   209:20210323:232219.962 query [txnlev:0] [select escalationid,actionid,triggerid,eventid,r_eventid,nextcheck,esc_step,status,itemid,acknowledgeid from escalations where triggerid is null and itemid is not null and nextcheck<=1616523742 order by actionid,triggerid,itemid,escalationid]
   209:20210323:232219.962 End of process_escalations()
   209:20210323:232219.962 In process_escalations()
   209:20210323:232219.962 query [txnlev:0] [select escalationid,actionid,triggerid,eventid,r_eventid,nextcheck,esc_step,status,itemid,acknowledgeid from escalations where triggerid is null and itemid is null and nextcheck<=1616523742 order by actionid,triggerid,itemid,escalationid]
   209:20210323:232219.962 End of process_escalations()
   209:20210323:232219.962 zbx_setproctitle() title:'escalator #1 [processed 1 escalations in 0.007608 sec, idle 3 sec]'
   233:20210323:232220.962 zbx_ipc_socket_read() code:1105 size:638 data:f1 01 00 00 bf 00 00 00 | 36 00 00 00 0f 00 00 00 | 00 00 09 00 01 00 00 00 | 00 00 00 00 00 18 04 0b | 80 00 00 04 0b 00 04 06 | 00 01 06 05 d2 00 00 07 | 00 00 05 01 b0 00 05 01 | 00 00 06 01 c0 00 02 07 | 03 00 08 00 c0 02 07 06 | c2 00 06 02 00 03 01 04 | 6e 04 04 05 1a 00 05 00 | 32 80 00 02 02 05 01 06 | 6e 06 06 05 1a 00 05 00 | 30 80 00 04 02 07 01 04 | 6e 04 08 04 35 00 04 00 | a9 80 00 18 02 00 09 04
   233:20210323:232220.962 End of zbx_ipc_socket_read():SUCCEED
   233:20210323:232220.962 In zbx_es_execute() param:{"servicenow_sys_id":"{EVENT.TAGS.__zbx_servicenow_number}","event_source":"0","event_update_status":"0","event_value":"0"}
   233:20210323:232220.962 End of zbx_es_execute():FAIL Recovery {EVENT.TAGS.__zbx_servicenow_number}

Expected:
1. Recovery must be executed only when problem operation is finished;
2. Tags from problem operations must be exist during recovery operations.



 Comments   
Comment by Bob Lomax [ 2021 Mar 31 ]

Is it possible to have an update on this bug please?  I note the 'fix' version on here for the 5.0 branch is 5.0.11rc1, but will that not be several weeks away?  This issue is currently holding up further rollout of the Zabbix platform for additional customer tenants at my organisation.

Comment by Dmitrijs Goloscapovs [ 2021 Apr 27 ]

Available in versions:

Documentation updated:

Generated at Fri May 09 07:55:43 EEST 2025 using Jira 9.12.4#9120004-sha1:625303b708afdb767e17cb2838290c41888e9ff0.