From 504a71f2d7b5ee1d9069e5fc2357de564cb35b5a Mon Sep 17 00:00:00 2001 From: "Keith Burns (alagalah)" Date: Wed, 17 Jan 2018 15:16:32 -0800 Subject: [PATCH] Event log entries for VCL Change-Id: I288ecd7f39422ed900a5c6fbaf9c939ab5c06880 Signed-off-by: Keith Burns (alagalah) --- src/vcl/vppcom.c | 301 ++++++++++++++++++++++++++++++++++++++++++++++++++++++- 1 file changed, 300 insertions(+), 1 deletion(-) diff --git a/src/vcl/vppcom.c b/src/vcl/vppcom.c index 28dc6070572..e28da693149 100644 --- a/src/vcl/vppcom.c +++ b/src/vcl/vppcom.c @@ -1343,7 +1343,7 @@ vl_api_accept_session_t_handler (vl_api_accept_session_t * mp) ed->addr[1] = session->peer_addr.ip46.ip4.as_u8[1]; ed->addr[2] = session->peer_addr.ip46.ip4.as_u8[2]; ed->addr[3] = session->peer_addr.ip46.ip4.as_u8[3]; - ed->port = session->peer_port; + ed->port = clib_net_to_host_u16 (session->peer_port); /* *INDENT-ON* */ } else @@ -3887,6 +3887,26 @@ vppcom_epoll_ctl (uint32_t vep_idx, int op, uint32_t session_index, "sid %u, events 0x%x, data 0x%llx!", getpid (), vep_idx, session_index, event->events, event->data.u64); + if (VPPCOM_DEBUG > 0) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "epoll_ctladd: events:%x data:%x", + .format_args = "i4i4i8", + }; + struct + { + u32 events; + u64 event_data; + } *ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); + + ed->events = event->events; + ed->event_data = event->data.u64; + /* *INDENT-ON* */ + } break; case EPOLL_CTL_MOD: @@ -3983,6 +4003,24 @@ vppcom_epoll_ctl (uint32_t vep_idx, int op, uint32_t session_index, if (VPPCOM_DEBUG > 1) clib_warning ("VCL<%d>: EPOLL_CTL_DEL: vep_idx %u, sid %u!", getpid (), vep_idx, session_index); + if (VPPCOM_DEBUG > 0) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "epoll_ctldel: vep:%d", + .format_args = "i4", + }; + struct + { + u32 data; + } *ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); + + ed->data = vep_idx; + /* *INDENT-ON* */ + } break; default: @@ -4035,6 +4073,24 @@ vppcom_epoll_wait (uint32_t vep_idx, struct epoll_event *events, if (VPPCOM_DEBUG > 0) clib_warning ("VCL<%d>: WARNING: vep_idx (%u) is empty!", getpid (), vep_idx); + if (VPPCOM_DEBUG > 0) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "WRN: vep_idx:%d empty", + .format_args = "i4", + }; + struct + { + u32 data; + } *ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, vep_session->elog_track); + + ed->data = vep_idx; + /* *INDENT-ON* */ + } goto done; } @@ -4067,6 +4123,25 @@ vppcom_epoll_wait (uint32_t vep_idx, struct epoll_event *events, if (VPPCOM_DEBUG > 0) clib_warning ("VCL<%d>: ERROR: sid (%u) is a vep!", getpid (), vep_idx); + if (VPPCOM_DEBUG > 0) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "ERR:vep_idx:%d is vep", + .format_args = "i4", + }; + struct + { + u32 data; + } *ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); + + ed->data = vep_idx; + /* *INDENT-ON* */ + } + rv = VPPCOM_EINVAL; goto done; } @@ -4075,6 +4150,25 @@ vppcom_epoll_wait (uint32_t vep_idx, struct epoll_event *events, if (VPPCOM_DEBUG > 0) clib_warning ("VCL<%d>: ERROR: session (%u) is not " "a vep session!", getpid (), sid); + if (VPPCOM_DEBUG > 0) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "ERR:SID:%d not vep", + .format_args = "i4", + }; + struct + { + u32 data; + } *ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); + + ed->data = sid; + /* *INDENT-ON* */ + } + rv = VPPCOM_EINVAL; goto done; } @@ -4205,6 +4299,25 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, if (VPPCOM_DEBUG > 2) clib_warning ("VCL<%d>: VPPCOM_ATTR_GET_NREAD: sid %u, nread = %d", getpid (), rv); + if (VPPCOM_DEBUG > 0) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "VPPCOM_ATTR_GET_NREAD: nread=%d", + .format_args = "i4", + }; + struct + { + u32 data; + } *ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); + + ed->data = rv; + /* *INDENT-ON* */ + } + break; case VPPCOM_ATTR_GET_NWRITE: @@ -4212,6 +4325,24 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, if (VPPCOM_DEBUG > 2) clib_warning ("VCL<%d>: VPPCOM_ATTR_GET_NWRITE: sid %u, nwrite = %d", getpid (), session_index, rv); + if (VPPCOM_DEBUG > 0) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "VPPCOM_ATTR_GET_NWRITE: nwrite=%d", + .format_args = "i4", + }; + struct + { + u32 data; + } *ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); + + ed->data = rv; + /* *INDENT-ON* */ + } break; case VPPCOM_ATTR_GET_FLAGS: @@ -4223,6 +4354,27 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, clib_warning ("VCL<%d>: VPPCOM_ATTR_GET_FLAGS: sid %u, " "flags = 0x%08x, is_nonblocking = %u", getpid (), session_index, *flags, session->is_nonblocking); + if (VPPCOM_DEBUG > 0) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "VPPCOM_ATTR_GET_FLAGS: flags=%x is_nonblk=%d", + .format_args = "i4", + }; + struct + { + u32 flags; + u32 is_nonblk; + } *ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); + + ed->flags = *flags; + ed->is_nonblk = session->is_nonblocking; + /* *INDENT-ON* */ + } + } else rv = VPPCOM_EINVAL; @@ -4237,6 +4389,26 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, "flags = 0x%08x, is_nonblocking = %u", getpid (), session_index, *flags, session->is_nonblocking); + if (VPPCOM_DEBUG > 0) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "VPPCOM_ATTR_SET_FLAGS: flags=%x is_nonblk=%d", + .format_args = "i4", + }; + struct + { + u32 flags; + u32 is_nonblk; + } *ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); + + ed->flags = *flags; + ed->is_nonblk = session->is_nonblocking; + /* *INDENT-ON* */ + } } else rv = VPPCOM_EINVAL; @@ -4262,6 +4434,48 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, session_index, ep->is_ip4, format_ip46_address, &session->peer_addr.ip46, ep->is_ip4, clib_net_to_host_u16 (ep->port)); + if (VPPCOM_DEBUG > 0) + { + if (ep->is_ip4) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "VPPCOM_ATTR_GET_PEER_ADDR: addr:%d.%d.%d.%d:%d", + .format_args = "i1i1i1i1i2", + }; + CLIB_PACKED (struct { + u8 addr[4]; //4 + u16 port; //2 + }) * ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); + + ed->addr[0] = session->peer_addr.ip46.ip4.as_u8[0]; + ed->addr[1] = session->peer_addr.ip46.ip4.as_u8[1]; + ed->addr[2] = session->peer_addr.ip46.ip4.as_u8[2]; + ed->addr[3] = session->peer_addr.ip46.ip4.as_u8[3]; + ed->port = clib_net_to_host_u16 (session->peer_port); + /* *INDENT-ON* */ + } + else + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "VPPCOM_ATTR_GET_PEER_ADDR: addr:IP6:%d", + .format_args = "i2", + }; + CLIB_PACKED (struct { + u16 port; //2 + }) * ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); + + ed->port = clib_net_to_host_u16 (session->peer_port); + /* *INDENT-ON* */ + } + } } else rv = VPPCOM_EINVAL; @@ -4287,6 +4501,48 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, session_index, ep->is_ip4, format_ip46_address, &session->lcl_addr.ip46, ep->is_ip4, clib_net_to_host_u16 (ep->port)); + if (VPPCOM_DEBUG > 0) + { + if (ep->is_ip4) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "VPPCOM_ATTR_GET_LCL_ADDR: addr:%d.%d.%d.%d:%d", + .format_args = "i1i1i1i1i2", + }; + CLIB_PACKED (struct { + u8 addr[4]; //4 + u16 port; //2 + }) * ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); + + ed->addr[0] = session->lcl_addr.ip46.ip4.as_u8[0]; + ed->addr[1] = session->lcl_addr.ip46.ip4.as_u8[1]; + ed->addr[2] = session->lcl_addr.ip46.ip4.as_u8[2]; + ed->addr[3] = session->lcl_addr.ip46.ip4.as_u8[3]; + ed->port = clib_net_to_host_u16 (session->peer_port); + /* *INDENT-ON* */ + } + else + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "VPPCOM_ATTR_GET_LCL_ADDR: addr:IP6:%d", + .format_args = "i2", + }; + CLIB_PACKED (struct { + u16 port; //2 + }) * ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); + + ed->port = clib_net_to_host_u16 (session->peer_port); + /* *INDENT-ON* */ + } + } } else rv = VPPCOM_EINVAL; @@ -4310,6 +4566,28 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, clib_warning ("VCL<%d>: VPPCOM_ATTR_SET_LIBC_EPFD: libc_epfd %d, " "buflen %d", getpid (), session->libc_epfd, *buflen); + if (VPPCOM_DEBUG > 0) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "VPPCOM_ATTR_SET_LIBC_EPFD: libc_epfd=%s%d buflen=%d", + .format_args = "t1i4i4", + .n_enum_strings = 2, + .enum_strings = {"", "-",}, + }; + CLIB_PACKED (struct { + u8 sign; + u32 data[2]; + }) * ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); + + ed->sign = (session->libc_epfd < 0); + ed->data[0] = abs(session->libc_epfd); + ed->data[1] = *buflen; + /* *INDENT-ON* */ + } } else rv = VPPCOM_EINVAL; @@ -4325,6 +4603,27 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, clib_warning ("VCL<%d>: VPPCOM_ATTR_GET_PROTOCOL: %d (%s), " "buflen %d", getpid (), *(int *) buffer, *(int *) buffer ? "UDP" : "TCP", *buflen); + if (VPPCOM_DEBUG > 0) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "VPPCOM_ATTR_GET_PROTOCOL: %s buflen=%d", + .format_args = "t1i4", + .n_enum_strings = 2, + .enum_strings = {"TCP", "UDP",}, + }; + + CLIB_PACKED (struct { + u8 proto; + u32 buflen; + }) * ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); + ed->proto = session->proto; + ed->buflen = *(int *) buffer; + /* *INDENT-ON* */ + } } else rv = VPPCOM_EINVAL; -- 2.16.6