目录
企业管理软件领域内棘手故障的一些表现形式
1. 需要复杂的流程才能重现
2. 故障横跨企业管理软件的多个模块
3. 故障只能在客户生产系统重现
4. 故障只能在后台作业模式下重现,在 online 模式运行时一切正常
5. 故障只能在软件正常运行模式时才能重现,单步调试时,软件工作一切正常
一个实际故障排查过程的案例分享
1. 试图找到稳定重现故障的办法
2. 缩小可能引起故障的代码排查范围
3. 利用调试器锁定问题
故障排查过程总结
笔者从2007年大学毕业加入 SAP 成都研究院至今,一直从事企业管理软件领域的开发工作。
企业管理软件面向的是企业级用户,如果软件出现故障(bug),在某些极端情况下,可能会让企业蒙受巨大的经济损失,故而对软件开发人员在编程规范,软件测试和软件交付之前的验证等各方面都提出了更高的要求。同时,由于企业管理软件自身高度的复杂性,有些故障很难重现或者只能在运行了客户特定业务流程的生产系统上才能重现。这些都给企业管理软件分析和故障处理带来了巨大的挑战。
本文从笔者处理过的一个实际软件故障出发,谈谈自己对企业管理软件里一些棘手故障的处理体会。
在笔者看来,这些棘手故障,可以分为以下几类。
笔者在 SAP成都研究院处理过很多曾让我头痛的软件故障,它们具有下列一项或几项特征。
例如我处理过的一个客户发票(Customer Invoice)相关的故障。这个故障只有在每次 release 发票时才能重现。为了 release 发票,我们必须先创建一个销售订单(Sales Order),基于该订单创建 Customer Demand,然后创建捡货任务(Pick Task),生成交货单(Delivery Note),最后才能生成一张新的客户发票。
这些复杂的流程往往也需要系统事先维护好对应的主数据(Master Data)和事务数据(Transaction Data)才能顺利执行。复杂的业务流程增添了故障重现的难度。
由于企业管理软件自身的复杂度,终端用户眼中看到的貌似简单的一个故障,背后可能横跨了软件实现的多个模块。
以上述形式1描述的故障为例,假设软件帮助文档上描述的支持功能为:客户在销售订单界面上添加了一个新的自定义字段并维护了对应值,该值能够从销售订单,经捡货任务,交货单,最后传递到客户发票上。我们称这种字段值从多个文档间的传递称为 data flow.
那么如果客户在发票页面上,看到这个字段的值为空,客户可能认为是发票模块出了故障。然而,在 data flow 的每个节点对应的模块处理,可能都是造成该故障的罪魁祸首。销售订单和客户发票属于 CRM 模块,而捡货任务和发货单则归属 SCM 的范畴。
在实际开发工作中,这意味着分析该故障往往需要跨团队间协作,因为 CRM 和 SCM 模块往往分属不同的开发团队负责。
在企业管理软件交付之前,必定在内部开发,测试和验证系统(validation system)进行过不同层次的测试。即便如此,由于种种客观原因,比如当应用运行在客户生产系统上,基于某些只有该客户才会用到的特定业务流程的配置时,故障才会暴露,而这些配置并没有被企业管理软件供应商的内部系统测试所涵盖到。
这类故障因为只能在客户生产系统重现,在分析和定位问题时更加困难重重,尤其当重现步骤会在客户生产系统进行写操作时,通常只能联系客户相关人员,采用远程桌面+电话会议的方式,让客户相关人员进行操作,然后软件供应商的支持人员在线调试。
在企业管理软件领域特别是 ERP 领域,后台作业常常被用来执行一些费时的批处理工作,比如订单批量处理,报表数据分析和聚合汇总等等。后台作业模式不同于挂接了用户界面的 online 模式,给单步调试也带来了困难。
当故障出现这种特征时,实际给支持人员传递了一个信号:该故障可能与程序特定的执行时序相关。因为程序正常运行,与处于单步调试模式下运行,执行时序显然不同,比如在调试器单步调试时,可能会破坏多线程程序正常的执行时序。
因为缺少了调试器这一强有力的武器,分析该类故障,需要支持人员具有更强的理论分析能力和问题抽象能力。
由于篇幅限制,本文仅举一个实际例子,对上述第五类故障的分析处理流程做一个分享。
笔者曾经负责 SAP CRM IBASE(Installed Base) 模块。IBase 是一个抽象模型,用于描述已在客户位置安装的资源对象,例如设备、机器,服务或软件。IBase 模型以树形结构,描述了这些对象的层级结构和它们的各个组件,是服务模块的参考基础。
并不总是能够重现 != 不能重现。
为了分析这个问题,我得先找到能够稳定重现的办法。因为该故障对单步调试大法免疫,我只能另想他法。
逐字逐句死扣故障报告里的描述,发生故障之前的操作流程为:
(1) 创建 IBASE
(2) 修改 IBASE
(3) 删除 IBASE
(4) 保存事务。
出现运行时错误。
因为我就是 IBASE 模块的负责人,所以我三下五除二就写好了一个不到 200 行的程序,在程序里依次调用 IBASE 的创建,修改和删除 API,再保存事务。
程序源代码如下:
REPORT zibase_create_delete.
PARAMETERS: txt TYPE char40 OBLIGATORY DEFAULT 'description test',
eid TYPE char30 OBLIGATORY DEFAULT 'PROGRAM',
oid TYPE comm_product-product_id OBLIGATORY DEFAULT 'CHILDOBJ8',
fam TYPE comm_product-object_family OBLIGATORY DEFAULT '0401',
cat TYPE COMT_CATEGORY_ID OBLIGATORY DEFAULT 'OBJ_0401'.
DATA: lt_param TYPE crmt_name_value_pair_tab,
ls_param TYPE crmt_name_value_pair,
lr_core TYPE REF TO cl_crm_bol_core,
ls_object TYPE comm_product,
lr_root TYPE REF TO if_bol_entity_col,
entity TYPE REF TO cl_crm_bol_entity.
CHECK zcl_object_generator=>create_object( iv_id = oid iv_family = fam iv_catid = cat ) = abap_true.
ls_param-name = cl_crm_ibase_il_constant=>createparam.
ls_param-value = '01'.
APPEND ls_param TO lt_param.
lr_core = cl_crm_bol_core=>get_instance( ).
lr_core->load_component_set('IBASE_ONLY').
CALL METHOD lr_core->root_create
EXPORTING
iv_object_name = cl_crm_ibase_il_constant=>root_object
iv_create_param = lt_param
iv_number = 1
RECEIVING
rv_result = lr_root.
CHECK lr_root IS BOUND.
entity ?= lr_root->get_current( ).
CHECK entity IS BOUND.
IF entity->lock( ) = abap_true.
entity->switch_to_change_mode( ).
ENDIF.
entity->set_property_as_string( iv_attr_name = 'DESCR' iv_value = CONV #( txt ) ).
entity->set_property_as_string( iv_attr_name = 'EXTID' iv_value = CONV #( eid ) ).
"entity->set_property_as_string( iv_attr_name = 'IBTYP' iv_value = '01' ).
lr_core->modify( ).
DATA(lv_ibase_id) = entity->get_property_as_string( 'IBASE' ).
DATA(component) = entity->create_related_entity( 'FirstLevelComponent' ).
CHECK component IS NOT INITIAL.
DATA(obj_comp) = component->create_related_entity( 'IBCompObj').
CHECK obj_comp IS NOT INITIAL.
obj_comp->set_property_as_string( iv_attr_name = 'OBJECT_ID' iv_value = CONV #( oid ) ).
SELECT SINGLE * INTO ls_object FROM comm_product WHERE product_id = oid.
ASSERT sy-subrc = 0.
obj_comp->set_property_as_string( iv_attr_name = 'OBJECT_GUID' iv_value = CONV #( ls_object-product_guid ) ).
obj_comp->set_property_as_string( iv_attr_name = 'OBJECT_FAMILY' iv_value = CONV #( ls_object-product_guid ) ).
DATA(lo_message_container) = entity->get_message_container( ).
CALL METHOD lo_message_container->get_messages
iv_message_type = if_genil_message_container=>mt_all
IMPORTING
et_messages = DATA(lt_msg1).
LOOP AT lt_msg1 ASSIGNING FIELD-SYMBOL().
WRITE:/ -message COLOR COL_NEGATIVE.
ENDLOOP.
CHECK lt_msg1 IS INITIAL.
DATA: ls_header TYPE ibap_head1,
lt_struc_tab TYPE ibap_struc1_tab,
ls_comp TYPE IBAP_DAT1.
"delete component"
ls_header-ibase = lv_ibase_id.
CALL FUNCTION 'CRM_IBASE_GET_DETAIL'
i_ibase_head = ls_header
e_struc_ibase_tab = lt_struc_tab
EXCEPTIONS
not_specified = 1
doesnt_exist = 2
no_authority = 3.
CHECK sy-subrc = 0.
READ TABLE lt_struc_tab ASSIGNING FIELD-SYMBOL() INDEX 1.
ls_comp-instance = -instance.
CALL FUNCTION 'CRM_IBASE_COMP_DELETE'
i_comp = ls_comp
DATA_NOT_CONSISTENT = 1
IBASE_LOCKED = 2
NOT_SUCCESFUL = 3
NO_AUTHORITY = 4.
CASE sy-subrc.
WHEN 1.
WRITE: / 'data not consistent' COLOR COL_NEGATIVE.
WHEN 2.
WRITE: / 'cannot delete locked component' COLOR COL_NEGATIVE.
WHEN 3.
WRITE: / 'deletion not successful' COLOR COL_NEGATIVE.
WHEN 4.
WRITE: / 'no deletion authorization' COLOR COL_NEGATIVE.
ENDCASE.
DATA(lo_transaction) = lr_core->get_transaction( ).
DATA(lv_changed) = lo_transaction->check_save_needed( ).
CHECK lv_changed EQ abap_true.
DATA(lv_success) = lo_transaction->save( ).
DATA(lo_glb_msg_cont) = lr_core->get_global_message_cont( ).
CALL METHOD lo_glb_msg_cont->if_genil_message_container~get_messages
et_messages = DATA(lt_msg).
LOOP AT lt_msg ASSIGNING FIELD-SYMBOL().
WRITE:/ -message.
IF lv_success = abap_true.
lo_transaction->commit( ).
WRITE:/ 'IBASE Created Successfully: ', lv_ibase_id COLOR COL_NEGATIVE.
ELSE.
lo_transaction->rollback( ).
执行这个报表,遇到了期望中的运行时错误。这是一个好兆头,因为我现在找到了稳定重现问题的办法。下一步,我需要缩小问题的范围,找出我这 200 行代码里,到底哪一行代码的执行,引起了运行时错误。
笔者喜欢称自己开发的这种专门用于分析故障,重现错误的程序,为“脚手架程序”或者“故障触发器”。
因为这 200 行代码是我自己编写的,所以我可以任意修改。首先把所有代码全部注释掉,只留下 IBASE 创建 API 的调用。执行程序,一切正常。
再解除 IBASE 修改 API 调用代码的注释,让其参与到程序执行中,一切正常。
再反注释 IBASE 删除 API 调用代码,执行程序,出现了运行时错误!
由此说明,这个运行时错误和 IBASE 删除的场景相关。
回到故障提交报告里的运行时错误截图:第 103 行抛出了一个类型为 X 的错误,因为调用函数 CRM_IBASE_COMP_GET_DETAIL, 并没有读取到通过输入参数 i_date 和 i_time 指定的时间戳对应的 IBASE 数据,因此程序决定通过抛出错误的方式来终止执行。
在后台作业运行模式,以及我的脚手架程序执行时,第 53 行时间戳判断条件没有满足,因此退出了循环,导致 CRM_IBASE_COMP_GET_DETAIL 读取失败,所以引发了故障。
要想满足 53 行的判断条件,只有两种可能:
当前时间戳 > IBASE valto 字段值
当前时间戳 = IBASE valto 字段值
需要强调的是,ABAP 编程语言里的时间戳字段,精确到秒,比如 20211024102424 代表 2021年10月24日10点24分24秒。
虽然我的脚手架应用在单步调试模式下也无法重现故障,但是直接执行可以重现。因此,执行执行脚手架应用,在运行时故障页面点击工具栏的 Debugger 按钮,能弹出调试器,查看应用程序抛出运行时错误的各种信息:
而在后台作业模式以及脚手架程序正常运行情况下,如果 IBASE 创建,修改和删除的 API 执行得足够快速,能够在一秒钟之内完成,则 t3 与 t1 之差小于 1 秒,故 CHECK 语句执行失败,直接返回。
换言之,这个故障提交时,CRM IBASE API 的开发人员,并没有考虑到 IBASE 的创建和删除会在`同一秒之内`完成的场景。毕竟正常情况下,客户不可能在 1 秒钟之内,在 UI 完成 IBASE 先创建再删除的操作。这种场景只可能在客户使用 IBASE API 进行一些二次开发场景下才有可能出现。
当然,最后这个问题,也绝非仅仅是把 53 行 CHECK 语句的 < 符号,改成小于等于操作那么简单。我们仔细评估了改动可能带来的其他副作用,并和提交该故障的团队开发人员进行了讨论,最后采取了其他的方式来避免这个故障的发生。
回到这个故障分析过程本身,最开始接到故障时,因为单步调试无法重现,因此笔者很是一筹莫展了一阵,后来想到编写脚手架程序来稳定重现该故障,这一步是问题分析的突破口。
有了脚手架程序之后,先注释掉所有的 API 调用,再逐步开放 IBASE 创建,修改和删除的代码,最终把问题范围缩小到 IBASE 删除过程。
通过脚手架应用的直接执行触发的运行时错误,利用调试器查看程序抛出错误时的变量值,将问题锁定到时间戳的处理逻辑上,进而找出根源。
这一分析步骤有点像上世纪末本世纪初电脑 DIY 发烧友们遇到组装机无法启动时的排查措施。当组装机无法启动时,只保留电源,主板和 CPU,尝试启动,如果成功,再逐一添加显卡,硬盘等其他设备。当新添加的设备导致系统重新回到无法启动状态,说明该设备有问题。当时发烧友们把这种方式称为“最小系统法”。
而整个分析过程的重中之重,就是把故障报告中无法稳定重现故障的后台作业里执行的内容,抽象成一个不到 200 行的脚手架程序。
《编程珠玑》第五章曾经分享过一个关于故障调试的有趣故事:IBM 研究中心一位程序员,新安装了一台工作站,发现一个故障:他只能采取坐着的姿势登录系统;一旦站起来,就无法登陆系统了。大家知道这个故障最后怎么定位的吗?去读读原书吧!