{"action":"created","issue":{"url":"https://api.github.com/repos/mercury-hpc/mercury/issues/111","repository_url":"https://api.github.com/repos/mercury-hpc/mercury","labels_url":"https://api.github.com/repos/mercury-hpc/mercury/issues/111/labels{/name}","comments_url":"https://api.github.com/repos/mercury-hpc/mercury/issues/111/comments","events_url":"https://api.github.com/repos/mercury-hpc/mercury/issues/111/events","html_url":"https://github.com/mercury-hpc/mercury/issues/111","id":161345591,"number":111,"title":"NA CCI: race in connection","user":{"login":"soumagne","id":5613371,"avatar_url":"https://avatars.githubusercontent.com/u/5613371?v=3","gravatar_id":"","url":"https://api.github.com/users/soumagne","html_url":"https://github.com/soumagne","followers_url":"https://api.github.com/users/soumagne/followers","following_url":"https://api.github.com/users/soumagne/following{/other_user}","gists_url":"https://api.github.com/users/soumagne/gists{/gist_id}","starred_url":"https://api.github.com/users/soumagne/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/soumagne/subscriptions","organizations_url":"https://api.github.com/users/soumagne/orgs","repos_url":"https://api.github.com/users/soumagne/repos","events_url":"https://api.github.com/users/soumagne/events{/privacy}","received_events_url":"https://api.github.com/users/soumagne/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/mercury-hpc/mercury/labels/bug","name":"bug","color":"000000"},{"url":"https://api.github.com/repos/mercury-hpc/mercury/labels/major","name":"major","color":"fbca04"},{"url":"https://api.github.com/repos/mercury-hpc/mercury/labels/na","name":"na","color":"c7def8"}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":{"url":"https://api.github.com/repos/mercury-hpc/mercury/milestones/8","html_url":"https://github.com/mercury-hpc/mercury/milestones/mercury-1.0.0","labels_url":"https://api.github.com/repos/mercury-hpc/mercury/milestones/8/labels","id":1576694,"number":8,"title":"mercury-1.0.0","description":"### Features:\r\n * Full cancellation support","creator":{"login":"soumagne","id":5613371,"avatar_url":"https://avatars.githubusercontent.com/u/5613371?v=3","gravatar_id":"","url":"https://api.github.com/users/soumagne","html_url":"https://github.com/soumagne","followers_url":"https://api.github.com/users/soumagne/followers","following_url":"https://api.github.com/users/soumagne/following{/other_user}","gists_url":"https://api.github.com/users/soumagne/gists{/gist_id}","starred_url":"https://api.github.com/users/soumagne/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/soumagne/subscriptions","organizations_url":"https://api.github.com/users/soumagne/orgs","repos_url":"https://api.github.com/users/soumagne/repos","events_url":"https://api.github.com/users/soumagne/events{/privacy}","received_events_url":"https://api.github.com/users/soumagne/received_events","type":"User","site_admin":false},"open_issues":15,"closed_issues":0,"state":"open","created_at":"2016-02-10T23:23:55Z","updated_at":"2016-06-29T22:41:39Z","due_on":"2016-11-15T06:00:00Z","closed_at":null},"comments":41,"created_at":"2016-06-21T04:08:38Z","updated_at":"2016-07-07T19:03:27Z","closed_at":null,"body":"Xuezhao reported the following issue (must investigate):\r\n\r\n> One problem we observed is that sometimes mercury reports such error and cause the RPC broken:\r\nNA: Error in /scratch/DAOS_OPT/src/mercury_github/src/na/na_cci.c:1678             \r\n # handle_recv_unexpected(): host boro-47.boro.hpdd.intel.com, na_cci_addr->cci_addr: (nil), NA_CCI_PRIVATE_DATA(na_class)->uri: verbs://192.168.1.47:21090,  peer verbs://192.168.1.33:51218 refcnt 1\r\n (the above msg is a little different with mercury master as I added some info)\r\n\r\n> It can be triggered when there are multiple client-side processes send RPC request to the server concurrently.\r\n \r\n> After some investigations, I think it is a race condition in the connection establish process:\r\nThe server receive connect request from client, and do “cci_accept” in which will send reply to client. The client will get a “CCI_EVENT_CONNECT” event to notify the connecting done, and server will get a “CCI_EVENT_ACCEPT” event to notify the connection is established.\r\n \r\n> The problem is in some race condition, the client gets the “CCI_EVENT_CONNECT” first and then send RPC request (unexpected msg), but when the server got the unexpected msg it has not polled out the “CCI_EVENT_ACCEPT” event and firstly got another “CCI_EVENT_RECV” notification of the new unexpected msg arriving. Then when processing the unexpected msg the server treats it is invalid as the connection is not valid.\r\n \r\n> The attached simple patch is my fixing to that problem, I think that it is possibly not the best fix, but I cannot find out a better solution right now. And our testing can pass after that patch.\r\n\r\n[0001-handle-the-possible-race-in-connection-establish.txt](https://github.com/mercury-hpc/mercury/files/324771/0001-handle-the-possible-race-in-connection-establish.txt)\r\n"},"comment":{"url":"https://api.github.com/repos/mercury-hpc/mercury/issues/comments/231175799","html_url":"https://github.com/mercury-hpc/mercury/issues/111#issuecomment-231175799","issue_url":"https://api.github.com/repos/mercury-hpc/mercury/issues/111","id":231175799,"user":{"login":"scottatchley","id":612032,"avatar_url":"https://avatars.githubusercontent.com/u/612032?v=3","gravatar_id":"","url":"https://api.github.com/users/scottatchley","html_url":"https://github.com/scottatchley","followers_url":"https://api.github.com/users/scottatchley/followers","following_url":"https://api.github.com/users/scottatchley/following{/other_user}","gists_url":"https://api.github.com/users/scottatchley/gists{/gist_id}","starred_url":"https://api.github.com/users/scottatchley/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/scottatchley/subscriptions","organizations_url":"https://api.github.com/users/scottatchley/orgs","repos_url":"https://api.github.com/users/scottatchley/repos","events_url":"https://api.github.com/users/scottatchley/events{/privacy}","received_events_url":"https://api.github.com/users/scottatchley/received_events","type":"User","site_admin":false},"created_at":"2016-07-07T19:03:27Z","updated_at":"2016-07-07T19:03:27Z","body":"While waiting for the cluster access, can you try this patch? You will need to remove the old patch first.\n\nAlso, only use CCI_DEBUG=conn. We do not need the other (msg and info) messages.\n\n\ndiff --git a/src/plugins/ctp/verbs/ctp_verbs.h b/src/plugins/ctp/verbs/ctp_verbs.h\r\nindex c4fa95b..3e4bf67 100644\r\n--- a/src/plugins/ctp/verbs/ctp_verbs.h\r\n+++ b/src/plugins/ctp/verbs/ctp_verbs.h\r\n@@ -392,7 +392,9 @@ typedef struct verbs_conn {\r\n \tuint32_t last;\t\t/* last slot used */\r\n \tuint32_t **slots;\t/* pointers to buffer headers\r\n \t\t\t\t   to poll */\r\n-\tint is_polling;\t\t/* polling RDMA MSGs */\r\n+\tuint32_t is_polling :1;\t/* polling RDMA MSGs */\r\n+\tuint32_t rdma_disconn :1; /* still needs rdma_disconnect */\r\n+\tuint32_t cci_disconn :1; /* still needs cci_disconnect */\r\n \r\n \t/* for RO connections when using both SendRecv and RDMA */\r\n \tuint16_t seqno;\t\t/* last seqno sent */\r\ndiff --git a/src/plugins/ctp/verbs/ctp_verbs_api.c b/src/plugins/ctp/verbs/ctp_verbs_api.c\r\nindex 5a29ac3..3f06333 100644\r\n--- a/src/plugins/ctp/verbs/ctp_verbs_api.c\r\n+++ b/src/plugins/ctp/verbs/ctp_verbs_api.c\r\n@@ -2034,6 +2034,7 @@ verbs_insert_conn(cci__conn_t *conn)\r\n \tpthread_rwlock_unlock(&vep->conn_tree_lock);\r\n \tpthread_mutex_lock(&ep->lock);\r\n \tTAILQ_INSERT_TAIL(&vep->conns, vconn, entry);\r\n+\tvconn->cci_disconn = 1;\r\n \tpthread_mutex_unlock(&ep->lock);\r\n \tdebug(CCI_DB_CONN, \"%s [%s]: added conn %p qp_num %u\", __func__,\r\n \t\tep->uri, (void*)conn, vconn->qp_num);\r\n@@ -2345,20 +2346,23 @@ out:\r\n \r\n static const char *verbs_conn_state_str(verbs_conn_state_t state);\r\n \r\n-static int ctp_verbs_disconnect(cci_connection_t * connection)\r\n+static void verbs_destroy_conn(cci__ep_t *ep, cci__conn_t *conn)\r\n {\r\n-\tint ret = CCI_SUCCESS;\r\n-\tcci__conn_t *conn = container_of(connection, cci__conn_t, connection);\r\n-\tverbs_conn_t *vconn = conn->priv;\r\n-\tcci_endpoint_t *endpoint = connection->endpoint;\r\n-\tcci__ep_t *ep = container_of(endpoint, cci__ep_t, endpoint);\r\n+\tint ret = 0;\r\n \tverbs_ep_t *vep = ep->priv;\r\n+\tverbs_conn_t *vconn = conn->priv;\r\n \r\n-\tCCI_ENTER;\r\n+\tdebug(CCI_DB_CONN, \"%s: conn %p vconn %p qp_num %u (%s)\",\r\n+\t\t__func__, (void*) conn, (void*)vconn, vconn->qp_num, conn->uri);\r\n \r\n-\tdebug(CCI_DB_CONN, \"%s [%s]: conn %p state %s qp_num %u\", __func__,\r\n-\t\tep->uri, (void*)conn, verbs_conn_state_str(vconn->state),\r\n-\t\tvconn->qp_num);\r\n+\tif (vconn->rdma_disconn) {\r\n+\t\tret = rdma_disconnect(vconn->id);\r\n+\t\tif (ret == -1) {\r\n+\t\t\tret = errno;\r\n+\t\t\tdebug(CCI_DB_WARN, \"%s: rdma_disconnect() returned %s\",\r\n+\t\t\t      __func__, strerror(ret));\r\n+\t\t}\r\n+\t}\r\n \r\n \tpthread_rwlock_wrlock(&vep->conn_tree_lock);\r\n \ttdelete(&vconn->qp_num, &vep->conn_tree, verbs_compare_u32);\r\n@@ -2377,13 +2381,6 @@ static int ctp_verbs_disconnect(cci_connection_t * connection)\r\n \t\t\tfree(vconn->conn_req->ptr);\r\n \t}\r\n \r\n-\tret = rdma_disconnect(vconn->id);\r\n-\tif (ret == -1) {\r\n-\t\tret = errno;\r\n-\t\tdebug(CCI_DB_WARN, \"%s: rdma_disconnect() returned %s\",\r\n-\t\t      __func__, strerror(ret));\r\n-\t}\r\n-\r\n \tif (vconn->rbuf) {\r\n \t\tif (vconn->rmr) {\r\n \t\t\tret = ibv_dereg_mr(vconn->rmr);\r\n@@ -2399,12 +2396,49 @@ static int ctp_verbs_disconnect(cci_connection_t * connection)\r\n \t\tfree(vconn->rbuf);\r\n \t}\r\n \r\n-\trdma_destroy_ep(vconn->id);\r\n-\r\n \tfree((void *)conn->uri);\r\n \tfree(vconn);\r\n \tfree(conn);\r\n \r\n+\treturn;\r\n+}\r\n+\r\n+static int ctp_verbs_disconnect(cci_connection_t * connection)\r\n+{\r\n+\tint ret = CCI_SUCCESS;\r\n+\tcci__conn_t *conn = container_of(connection, cci__conn_t, connection);\r\n+\tverbs_conn_t *vconn = conn->priv;\r\n+\tcci_endpoint_t *endpoint = connection->endpoint;\r\n+\tcci__ep_t *ep = container_of(endpoint, cci__ep_t, endpoint);\r\n+\tverbs_ep_t *vep = ep->priv;\r\n+\tint rdma_disconn = 0;\r\n+\r\n+\tCCI_ENTER;\r\n+\r\n+\tdebug(CCI_DB_CONN, \"%s [%s]: conn %p state %s qp_num %u\", __func__,\r\n+\t\tep->uri, (void*)conn, verbs_conn_state_str(vconn->state),\r\n+\t\tvconn->qp_num);\r\n+\r\n+\tvconn->cci_disconn = 0;\r\n+\r\n+\tif (vconn->rdma_disconn) {\r\n+\t\t/* The conn is established and we are the one trying to\r\n+\t\t * tear it down.\r\n+\t\t */\r\n+\t\tret = rdma_disconnect(vconn->id);\r\n+\t\tif (ret == -1) {\r\n+\t\t\tret = errno;\r\n+\t\t\tdebug(CCI_DB_WARN, \"%s: rdma_disconnect() returned %s\",\r\n+\t\t\t      __func__, strerror(ret));\r\n+\t\t}\r\n+\t\tvconn->rdma_disconn = 0;\r\n+\t} else {\r\n+\t\t/* We have already received the RDMA_CM_EVENT_DISCONNECTED\r\n+\t\t * event. Go ahead and cleanup.\r\n+\t\t */\r\n+\t\tverbs_destroy_conn(ep, conn);\r\n+\t}\r\n+\r\n \tCCI_EXIT;\r\n \treturn ret;\r\n }\r\n@@ -2891,6 +2925,13 @@ verbs_handle_conn_established(cci__ep_t * ep, struct rdma_cm_event *cm_evt)\r\n \tvconn = conn->priv;\r\n \tassert(vconn);\r\n \r\n+\t/* The RDMA connection is established. We will need to call\r\n+\t * rdma_disconnect() in the future.\r\n+\t */\r\n+\tpthread_mutex_lock(&ep->lock);\r\n+\tvconn->rdma_disconn = 1;\r\n+\tpthread_mutex_unlock(&ep->lock);\r\n+\r\n \tswitch (vconn->state) {\r\n \tcase VERBS_CONN_ACTIVE:\r\n \t\tret = verbs_conn_est_active(ep, cm_evt);\r\n@@ -2924,22 +2965,52 @@ verbs_handle_disconnected(cci__ep_t * ep, struct rdma_cm_event *cm_evt)\r\n \tvconn = conn->priv;\r\n \tassert(vconn);\r\n \r\n-\tswitch (vconn->state) {\r\n-\tcase VERBS_CONN_ESTABLISHED:\r\n-\t\tvconn->state = VERBS_CONN_CLOSED;\r\n-\t\tdebug(CCI_DB_CONN, \"%s: marking vconn %p closed (%s)\",\r\n-\t\t\t__func__, (void*)vconn, conn->uri);\r\n-\t\tbreak;\r\n-\tdefault:\r\n-\t\tdebug(CCI_DB_INFO, \"%s: incorrect conn state %s\", __func__,\r\n-\t\t      verbs_conn_state_str(vconn->state));\r\n-\t\tbreak;\r\n+\tif (vconn->rdma_disconn) {\r\n+\t\t/* We did not initiate the disconnect. We will not get\r\n+\t\t * another RDMA_CM_EVENT_DISCONNECTED, so go ahead and\r\n+\t\t * call it now.\r\n+\t\t */\r\n+\t\tret = rdma_disconnect(vconn->id);\r\n+\t\tif (ret == -1) {\r\n+\t\t\tret = errno;\r\n+\t\t\tdebug(CCI_DB_WARN, \"%s: rdma_disconnect() returned %s\",\r\n+\t\t\t      __func__, strerror(ret));\r\n+\t\t}\r\n+\t\tvconn->rdma_disconn = 0;\r\n+\t}\r\n+\r\n+\t/* Either way, we got the DISCONNECTED event, it is safe to cleanup\r\n+\t * the QP and CM id.\r\n+\t */\r\n+\tret = rdma_destroy_ep(vconn->id);\r\n+\tif (ret == -1) {\r\n+\t\tret = errno;\r\n+\t\tdebug(CCI_DB_WARN, \"%s: rdma_destroy_ep() returned %s\",\r\n+\t\t      __func__, strerror(ret));\r\n+\t}\r\n+\r\n+\tif (!vconn->cci_disconn) {\r\n+\t\tverbs_destroy_conn(ep, conn);\r\n \t}\r\n \r\n \tCCI_EXIT;\r\n \treturn ret;\r\n }\r\n \r\n+static void\r\n+verbs_handle_timewait_exit(cci__ep_t * ep, struct rdma_cm_event *cm_evt)\r\n+{\r\n+\t/* The CM can reuse the QP now. We should have already torn down the\r\n+\t * QP, destroyed the RDMA id, and freed the CCI conn. Simply\r\n+\t * print the QP number and the possibly freed CCI conn address\r\n+\t * for informational purposes.\r\n+\t */\r\n+\tdebug(CCI_DB_CONN, \"%s: qp_num %u context (conn) %p\", __func__,\r\n+\t\tcm_evt->id->qp->qp_num, cm_evt->id->context);\r\n+\r\n+\treturn;\r\n+}\r\n+\r\n static int verbs_get_cm_event(cci__ep_t * ep)\r\n {\r\n \tint ret = CCI_EAGAIN;\r\n@@ -2986,6 +3057,9 @@ static int verbs_get_cm_event(cci__ep_t * ep)\r\n \t\t\tdebug(CCI_DB_CONN, \"%s: verbs_handle_conn_rejected()\"\r\n \t\t\t      \"returned %s\", __func__, strerror(ret));\r\n \t\tbreak;\r\n+\tcase RDMA_CM_EVENT_TIMEWAIT_EXIT:\r\n+\t\tverbs_handle_timewait_exit(ep, cm_evt);\r\n+\t\tbreak;\r\n \tdefault:\r\n \t\tdebug(CCI_DB_CONN, \"ignoring %s event\",\r\n \t\t      rdma_event_str(cm_evt->event));\r\n"}}
{"actor":{"display_login":"scottatchley"}}