orchagent core dump when executing with -s option (syncMode)

[dzhangalibaba]

• before changes:
  • orchagent create_switch first, which is using redis_generic_create() to write ASIC_DB, and syncd will handle this request, since syncd is in syncMode, a response with op "getresponse" is send via internal_syncd_api_send_response().
  • but in orchagent , g_syncMode is not set yet at this moment, so there is no internal_api_wait_for_response() waiting the response generated by internal_syncd_api_send_response()
  • later internal_redis_generic_get() is invoked and got the response which is not for it. That response cause get_switch_attr into segfault and orchagent exit

Aug 1 01:58:34.926936 ASW-7005 NOTICE swss#orchagent: :- clear_local_state: clearing local state
Aug 1 01:58:34.927130 ASW-7005 NOTICE swss#orchagent: :- initSaiRedis: Notify syncd INIT_VIEW
Aug 1 01:58:34.928860 ASW-7005 NOTICE swss#orchagent: :- redis_get_free_switch_id_index: got new switch index 0x0
Aug 1 01:58:34.932105 ASW-7005 NOTICE swss#orchagent: :- main: Create a switch
Aug 1 01:58:34.932105 ASW-7005 NOTICE swss#orchagent: :- redis_set_switch_attribute: disabling buffered pipeline in sync mode
Aug 1 01:58:39.280930 ASW-7005 INFO swss#supervisord 2019-08-01 01:58:30,525 INFO spawned: 'orchagent' with pid 76
Aug 1 01:58:39.280930 ASW-7005 INFO swss#supervisord 2019-08-01 01:58:31,527 INFO success: orchagent entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Aug 1 01:58:42.888892 ASW-7005 INFO swss#orchagent: :- internal_redis_generic_get: response: op = SAI_STATUS_SUCCESS, key = getresponse
Aug 1 01:58:42.891224 ASW-7005 INFO kernel: [ 1368.445943] orchagent[15338]: segfault at 0 ip 00007f62f0da45c5 sp 00007ffe656b6ff0 error 4 in libsaimetadata.so.0.0.0[7f62f0d7a000+56000]
Aug 1 01:58:43.012191 ASW-7005 INFO swss#supervisor-proc-exit-listener: Process orchagent exited unxepectedly. Terminating supervisor...

• after the changes:
  • set g_syncMode first before create_switch
  • internal_api_wait_for_response() will be there when using redis_generic_create() to consume the response generated via internal_syncd_api_send_response
  • later, internal_redis_generic_get() got its expected response

Aug 1 08:02:03.809155 ASW-7005 NOTICE swss#orchagent: :- sai_redis_internal_notify_syncd: notify response: SAI_STATUS_SUCCESS
Aug 1 08:02:03.809503 ASW-7005 NOTICE swss#orchagent: :- sai_redis_notify_syncd: notify syncd succeeded
Aug 1 08:02:03.809503 ASW-7005 NOTICE swss#orchagent: :- sai_redis_notify_syncd: clearing current local state since init view is
called on initialized switch
Aug 1 08:02:03.809503 ASW-7005 NOTICE swss#orchagent: :- clear_local_state: clearing local state
Aug 1 08:02:03.809519 ASW-7005 NOTICE swss#orchagent: :- initSaiRedis: Notify syncd INIT_VIEW
Aug 1 08:02:03.809519 ASW-7005 NOTICE swss#orchagent: :- redis_set_switch_attribute: disabling buffered pipeline in sync mode
Aug 1 08:02:03.809542 ASW-7005 NOTICE swss#orchagent: :- redis_get_free_switch_id_index: got new switch index 0x0
Aug 1 08:02:03.809876 ASW-7005 INFO syncd#syncd: :- check_notifications_pointers: SAI_SWITCH_ATTR_FDB_EVENT_NOTIFY: 0x55D912F9389
0 (orch) => 0x55E2CF67E520 (syncd)
Aug 1 08:02:03.809910 ASW-7005 INFO syncd#syncd: :- check_notifications_pointers: SAI_SWITCH_ATTR_PORT_STATE_CHANGE_NOTIFY: 0x55D
912F938A0 (orch) => 0x55E2CF67E7E0 (syncd)
Aug 1 08:02:03.809910 ASW-7005 INFO syncd#syncd: :- check_notifications_pointers: SAI_SWITCH_ATTR_SWITCH_SHUTDOWN_REQUEST_NOTIFY:
0x55D912F938B0 (orch) => 0x55E2CF67E940 (syncd)
Aug 1 08:02:03.810736 ASW-7005 INFO swss#orchagent: :- internal_api_wait_for_response: waiting for response 0
Aug 1 08:02:03.810736 ASW-7005 INFO swss#orchagent: :- internal_api_wait_for_response: wait for 0 api response
Aug 1 08:02:08.372356 ASW-7005 INFO swss#supervisord 2019-08-01 08:01:59,642 INFO spawned: 'orchagent' with pid 77
Aug 1 08:02:08.372356 ASW-7005 INFO swss#supervisord 2019-08-01 08:02:00,644 INFO success: orchagent entered RUNNING state, proce
ss has stayed up for > than 1 seconds (startsecs)
Aug 1 08:02:11.835573 ASW-7005 INFO swss#orchagent: :- internal_api_wait_for_response: response: op = SAI_STATUS_SUCCESS, key = g
etresponse
Aug 1 08:02:11.835717 ASW-7005 NOTICE swss#orchagent: :- main: Create a switch
Aug 1 08:02:11.836461 ASW-7005 INFO swss#orchagent: :- internal_redis_generic_get: response: op = SAI_STATUS_SUCCESS, key = getre
sponse
Aug 1 08:02:11.836618 ASW-7005 INFO swss#orchagent: :- meta_generic_validation_post_get_objlist: SAI_SWITCH_ATTR_DEFAULT_VIRTUAL_
ROUTER_ID:SAI_ATTR_VALUE_TYPE_OBJECT_ID returned get object on list [0] oid 0x3000000000024 object type 3 does not exists in local
DB (snoop)
Aug 1 08:02:11.836618 ASW-7005 NOTICE swss#orchagent: :- main: Get switch virtual router ID 3000000000024

[dzhangalibaba]

this issue is a must seen issue. Looks the merged syncMode commit is not tested

[lguohan]

retest this please

[dzhangalibaba]

looks the vs test itself has some issues?

[kcudnik]

yes seems like it, @lguohan have you seen this before? i saw other issues with tests before not related to actual PR, all of the error are:
E ReadTimeout: UnixHTTPConnectionPool(host='localhost', port=None): Read timed out. (read timeout=60)

AHH it maybe related to the reboot of test bed today

[kcudnik]

retest this please

[lguohan]

retest this please

[lguohan]

retest this please

[stcheng]

retest this please

[jleveque]

Retest this please