diff options
| author |   Florin Coras <fcoras@cisco.com> | 2018-06-27 03:24:07 -0700 |
|---|---|---|
| committer | Florin Coras <fcoras@cisco.com> | 2018-06-27 10:14:25 -0700 |
| commit | 0d427d8d8a48af404dfc6535ae72d334b790f809 (patch) | |
| tree | 5ec458ba9d9920e33a3982b60a2be1dbe6dececa | |
| parent | 0654dcc7b9370be6472f306d0a7b5ba9bf2b7962 (diff) | |
vcl: refactor debugging
Change-Id: I82e5239239ea24bdc97b1d59946ca0bba739f248
Signed-off-by: Florin Coras <fcoras@cisco.com>
| -rw-r--r-- | src/vcl.am | 1 | ||||
| -rw-r--r-- | src/vcl/vcl_debug.h | 300 | ||||
| -rw-r--r-- | src/vcl/vppcom.c | 2255 |
3 files changed, 756 insertions, 1800 deletions
diff --git a/src/vcl.am b/src/vcl.am index 554ebfc893a..6a1a85cefef 100644 --- a/src/vcl.am +++ b/src/vcl.am @@ -24,6 +24,7 @@ libvppcom_la_LIBADD = $(libvppcom_la_DEPENDENCIES) -lpthread -lrt -ldl libvppcom_la_SOURCES += \ vcl/vcl_event.c \ vcl/vppcom.c \ + vcl/vcl_debug.h \ $(libvppinfra_la_SOURCES) \ $(libsvm_la_SOURCES) \ $(libvlibmemoryclient_la_SOURCES) diff --git a/src/vcl/vcl_debug.h b/src/vcl/vcl_debug.h new file mode 100644 index 00000000000..13e6726c259 --- /dev/null +++ b/src/vcl/vcl_debug.h @@ -0,0 +1,300 @@ +/* + * Copyright (c) 2018 Cisco and/or its affiliates. + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this + * You may obtain a copy of the License at: + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#ifndef SRC_VCL_VCL_DEBUG_H_ +#define SRC_VCL_VCL_DEBUG_H_ + +#include <vppinfra/elog.h> + +#define VCL_ELOG 0 + +#define VDBG(_lvl, _fmt, _args...) \ + if (vcm->debug > _lvl) \ + clib_warning (_fmt, ##_args) + +#define foreach_vcl_dbg_evt \ + _(INIT, "vcl init track") \ + _(TIMEOUT, "vcl timeout") \ + _(DETACH, "vcl detach") \ + _(SESSION_INIT, "init session track") \ + _(SESSION_TIMEOUT, "session timeout") \ + _(CREATE, "session create") \ + _(CLOSE, "session close") \ + _(BIND, "session bind") \ + _(UNBIND, "session unbind") \ + _(ACCEPT, "session accept") \ + _(EPOLL_CREATE, "epoll session create") \ + _(EPOLL_CTLADD, "epoll ctl add") \ + _(EPOLL_CTLDEL, "epoll ctl del") \ + +typedef enum vcl_dbg_evt_ +{ +#define _(sym, str) VCL_EVT_##sym, + foreach_vcl_dbg_evt +#undef _ +} vcl_dbg_evt_e; + +#if VCL_ELOG + +#define VCL_DECLARE_ETD(_s, _e, _size) \ + struct { u32 data[_size]; } * ed; \ + ed = ELOG_TRACK_DATA (&vcm->elog_main, _e, _s->elog_track) \ + +#define VCL_EVT_INIT_HANDLER(_vcm, ...) \ +{ \ + _vcm->elog_track.name = (char *) format (0, "P:%d:C:%d%c", getpid (), \ + _vcm->my_client_index, 0); \ + elog_track_register (&_vcm->elog_main, &_vcm->elog_track); \ + ELOG_TYPE_DECLARE (e) = \ + { \ + .format = "connect_vpp:rv:%d", \ + .format_args = "i4", \ + }; \ + struct { u32 data; } *ed; \ + ed = ELOG_TRACK_DATA (&_vcm->elog_main, e, _vcm->elog_track); \ + ed->data = (u32) rv; \ +} + +#define VCL_EVT_SESSION_INIT_HANDLER(_s, _s_index, ...) \ +{ \ + _s->elog_track.name = (char *) format (0, "CI:%d:S:%d%c", \ + vcm->my_client_index, \ + _s_index, 0); \ + elog_track_register (&vcm->elog_main, &_s->elog_track); \ +} + +#define VCL_EVT_BIND_HANDLER(_s, ...) \ +{ \ + if (_s->lcl_addr.is_ip4) \ + { \ + ELOG_TYPE_DECLARE (_e) = \ + { \ + .format = "bind local:%s:%d.%d.%d.%d:%d ", \ + .format_args = "t1i1i1i1i1i2", \ + .n_enum_strings = 2, \ + .enum_strings = {"TCP", "UDP",}, \ + }; \ + CLIB_PACKED (struct { \ + u8 proto; \ + u8 addr[4]; \ + u16 port; \ + }) *ed; \ + ed = ELOG_TRACK_DATA (&vcm->elog_main, _e, _s->elog_track); \ + ed->proto = _s->proto; \ + ed->addr[0] = _s->lcl_addr.ip46.ip4.as_u8[0]; \ + ed->addr[1] = _s->lcl_addr.ip46.ip4.as_u8[1]; \ + ed->addr[2] = _s->lcl_addr.ip46.ip4.as_u8[2]; \ + ed->addr[3] = _s->lcl_addr.ip46.ip4.as_u8[3]; \ + ed->port = clib_net_to_host_u16 (_s->lcl_port); \ + } \ + else \ + { \ + /* TBD */ \ + } \ +} + +#define VCL_EVT_ACCEPT_HANDLER(_s, _ls, _s_idx, ...) \ +{ \ + VCL_EVT_SESSION_INIT_HANDLER (_s, _s_idx); \ + ELOG_TYPE_DECLARE (_e) = \ + { \ + .format = "accept: listen_handle:%x from_handle:%x", \ + .format_args = "i8i8", \ + }; \ + struct { u64 handle[2]; } *ed; \ + ed = ELOG_TRACK_DATA (&vcm->elog_main, _e, _s->elog_track); \ + ed->handle[0] = _ls->vpp_handle; \ + ed->handle[1] = _s->vpp_handle; \ + if (_s->peer_addr.is_ip4) \ + { \ + ELOG_TYPE_DECLARE (_e) = \ + { \ + .format = "accept:S:%x addr:%d.%d.%d.%d:%d", \ + .format_args = "i8i1i1i1i1i2", \ + }; \ + CLIB_PACKED (struct { \ + u32 s_idx; \ + u8 addr[4]; \ + u16 port; \ + }) * ed; \ + ed = ELOG_TRACK_DATA (&vcm->elog_main, _e, _s->elog_track); \ + ed->s_idx = _s_idx; \ + ed->addr[0] = _s->peer_addr.ip46.ip4.as_u8[0]; \ + ed->addr[1] = _s->peer_addr.ip46.ip4.as_u8[1]; \ + ed->addr[2] = _s->peer_addr.ip46.ip4.as_u8[2]; \ + ed->addr[3] = _s->peer_addr.ip46.ip4.as_u8[3]; \ + ed->port = clib_net_to_host_u16 (_s->peer_port); \ + } \ + else \ + { \ + /* TBD */ \ + } \ +} + +#define VCL_EVT_CREATE_HANDLER(_s, _proto, _state, _is_nb, _s_idx, ...) \ +{ \ + VCL_EVT_SESSION_INIT_HANDLER (_s, _s_idx); \ + ELOG_TYPE_DECLARE (_e) = \ + { \ + .format = "create:proto:%d state:%d is_nonblk:%d idx: %d", \ + .format_args = "i4i4i4i4", \ + }; \ + VCL_DECLARE_ETD (_s, _e, 4); \ + ed->data[0] = _proto; \ + ed->data[1] = _state; \ + ed->data[2] = _is_nb; \ + ed->data[3] = _s_idx; \ +} + +#define VCL_EVT_CLOSE_HANDLER(_s, _rv, ...) \ +{ \ + ELOG_TYPE_DECLARE (_e) = \ + { \ + .format = "session_close:rv:%d", \ + .format_args = "i4", \ + }; \ + VCL_DECLARE_ETD (_s, _e, 1); \ + ed->data[0] = _rv; \ +} + +#define VCL_EVT_SESSION_TIMEOUT_HANDLER(_s, _state, ...) \ +{ \ + ELOG_TYPE_DECLARE (_e) = \ + { \ + .format = "ERR: timeout state:%d", \ + .format_args = "i4", \ + }; \ + VCL_DECLARE_ETD (_s, _e, 1); \ + ed->data[0] = _state; \ +} + +#define VCL_EVT_TIMEOUT_HANDLER(_vcm, _state, ...) \ +{ \ + ELOG_TYPE_DECLARE (_e) = \ + { \ + .format = "ERR: timeout state:%d", \ + .format_args = "i4", \ + }; \ + struct { u32 data; } * ed; \ + ed = ELOG_TRACK_DATA (&_vcm->elog_main, _e, _vcm->elog_track); \ + ed->data[0] = _state; \ +} + +#define VCL_EVT_DETACH_HANDLER(_vcm, ...) \ +{ \ + ELOG_TYPE_DECLARE (_e) = \ + { \ + .format = "app_detach:C:%d", \ + .format_args = "i4", \ + }; \ + struct { u32 data; } * ed; \ + ed = ELOG_TRACK_DATA (&_vcm->elog_main, _e, _vcm->elog_track); \ + ed->data = _vcm->my_client_index; \ +} + +#define VCL_EVT_UNBIND_HANDLER(_s, ...) \ +{ \ + ELOG_TYPE_DECLARE (_e) = \ + { \ + .format = "unbind: handle:%x", \ + .format_args = "i8", \ + }; \ + struct { u64 data; } * ed; \ + ed = ELOG_TRACK_DATA (&vcm->elog_main, _e, _s->elog_track); \ + ed->data = _s->vpp_handle; \ +} + +#define VCL_EVT_EPOLL_CREATE_HANDLER(_s, _s_idx, ...) \ +{ \ + VCL_EVT_SESSION_INIT_HANDLER (_s, _s_idx); \ + ELOG_TYPE_DECLARE (_e) = \ + { \ + .format = "create epoll vep_idx: %d", \ + .format_args = "i4", \ + }; \ + VCL_DECLARE_ETD (_s, _e, 1); \ + ed->data[0] = _s_idx; \ +} + +#define VCL_EVT_EPOLL_CTLADD_HANDLER(_s, _evts, _evt_data, ...) \ +{ \ + ELOG_TYPE_DECLARE (_e) = \ + { \ + .format = "epoll_ctladd: events:%x data:%x", \ + .format_args = "i4", \ + }; \ + struct { \ + u32 events; \ + u64 event_data; \ + } * ed; \ + ed = ELOG_TRACK_DATA (&vcm->elog_main, _e, _s->elog_track); \ + ed->events = _evts; \ + ed->event_data = _evt_data; \ +} + +#define VCL_EVT_EPOLL_CTLDEL_HANDLER(_s, _vep_idx, ...) \ +{ \ + ELOG_TYPE_DECLARE (_e) = \ + { \ + .format = "epoll_ctldel: vep:%d", \ + .format_args = "i4", \ + }; \ + VCL_DECLARE_ETD (_s, _e, 1); \ + ed->data[0] = _vep_idx; \ +} + +#define vcl_elog_init(_vcm) \ +{ \ + _vcm->elog_main.lock = clib_mem_alloc_aligned (CLIB_CACHE_LINE_BYTES, \ + CLIB_CACHE_LINE_BYTES);\ + _vcm->elog_main.lock[0] = 0; \ + _vcm->elog_main.event_ring_size = _vcm->cfg.event_ring_size; \ + elog_init (&_vcm->elog_main, _vcm->elog_main.event_ring_size); \ + elog_enable_disable (&_vcm->elog_main, 1); \ +} + +#define vcl_elog_stop(_vcm) \ +{ \ + clib_error_t *error = 0; \ + char *chroot_file = (char *) format (0, "%s/%d-%d-vcl-elog%c", \ + _vcm->cfg.event_log_path, \ + _vcm->my_client_index, \ + getpid (), 0); \ + error = elog_write_file (&_vcm->elog_main, chroot_file, \ + 1 /* flush ring */ ); \ + if (error) \ + clib_error_report (error); \ + clib_warning ("[%d] Event Log:'%s' ", getpid (), chroot_file); \ + vec_free (chroot_file); \ +} + +#define CONCAT_HELPER(_a, _b) _a##_b +#define CC(_a, _b) CONCAT_HELPER(_a, _b) +#define vcl_evt(_evt, _args...) CC(_evt, _HANDLER)(_args) +#else +#define vcl_evt(_evt, _args...) +#define vcl_elog_init(_vcm) +#define vcl_elog_stop(_vcm) +#endif + +#endif /* SRC_VCL_VCL_DEBUG_H_ */ + +/* + * fd.io coding-style-patch-verification: ON + * + * Local Variables: + * eval: (c-set-style "gnu") + * End: + */ diff --git a/src/vcl/vppcom.c b/src/vcl/vppcom.c index 62d754b8f92..794a030456e 100644 --- a/src/vcl/vppcom.c +++ b/src/vcl/vppcom.c @@ -22,9 +22,9 @@ #include <vnet/session/application_interface.h> #include <vcl/vppcom.h> #include <vcl/vcl_event.h> +#include <vcl/vcl_debug.h> #include <vlib/unix/unix.h> #include <vppinfra/vec_bootstrap.h> -#include <vppinfra/elog.h> #define vl_typedefs /* define message structures */ #include <vpp/api/vpe_all_api_h.h> @@ -237,9 +237,11 @@ typedef struct vppcom_main_t_ /* IO thread */ vppcom_session_io_thread_t session_io_thread; +#ifdef VCL_ELOG /* VPP Event-logger */ elog_main_t elog_main; elog_track_t elog_track; +#endif /* VNET_API_ERROR_FOO -> "Foo" hash table */ uword *error_string_by_error_number; @@ -406,9 +408,7 @@ vppcom_session_table_lookup_listener (u64 listener_handle) } if (pool_is_free_index (vcm->sessions, p[0])) { - if (VPPCOM_DEBUG > 1) - clib_warning ("VCL<%d>: invalid listen session, sid (%u)", - getpid (), p[0]); + VDBG (1, "VCL<%d>: invalid listen session, sid (%u)", getpid (), p[0]); return 0; } @@ -424,26 +424,6 @@ vppcom_session_table_del_listener (u64 listener_handle) hash_unset (vcm->session_index_by_vpp_handles, listener_handle); } -static void -write_elog (void) -{ - elog_main_t *em = &vcm->elog_main; - char *chroot_file; - clib_error_t *error = 0; - - chroot_file = - (char *) format (0, "%s/%d-%d-vcl-elog%c", vcm->cfg.event_log_path, - vcm->my_client_index, getpid (), 0); - error = elog_write_file (em, chroot_file, 1 /* flush ring */ ); - if (error) - { - clib_error_report (error); - } - if (VPPCOM_DEBUG > 0) - clib_warning ("[%d] Event Log:'%s' ", getpid (), chroot_file); - -} - static inline void vppcom_send_accept_session_reply (u64 handle, u32 context, int retval) { @@ -468,9 +448,8 @@ vppcom_connect_to_vpp (char *app_name) if (!vcl_cfg->vpp_api_filename) vcl_cfg->vpp_api_filename = format (0, "/vpe-api%c", 0); - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: app (%s) connecting to VPP api (%s)...", - getpid (), app_name, vcl_cfg->vpp_api_filename); + VDBG (0, "VCL<%d>: app (%s) connecting to VPP api (%s)...", + getpid (), app_name, vcl_cfg->vpp_api_filename); if (vl_client_connect_to_vlib ((char *) vcl_cfg->vpp_api_filename, app_name, vcm->cfg.vpp_api_q_length) < 0) @@ -484,39 +463,10 @@ vppcom_connect_to_vpp (char *app_name) vcm->my_client_index = (u32) am->my_client_index; vcm->app_state = STATE_APP_CONN_VPP; - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: app (%s) is connected to VPP!", - getpid (), app_name); + VDBG (0, "VCL<%d>: app (%s) is connected to VPP!", getpid (), app_name); } - if (VPPCOM_DEBUG > 0) - { - vcm->elog_main.lock = - clib_mem_alloc_aligned (CLIB_CACHE_LINE_BYTES, CLIB_CACHE_LINE_BYTES); - vcm->elog_main.lock[0] = 0; - vcm->elog_main.event_ring_size = vcm->cfg.event_ring_size; - elog_init (&vcm->elog_main, vcm->elog_main.event_ring_size); - elog_enable_disable (&vcm->elog_main, 1); - - vcm->elog_track.name = - (char *) format (0, "P:%d:C:%d%c", getpid (), - vcm->my_client_index, 0); - elog_track_register (&vcm->elog_main, &vcm->elog_track); - - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "connect_vpp:rv:%d", - .format_args = "i4", - }; - struct - { - u32 data; - } *ed; - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, vcm->elog_track); - ed->data = (u32) rv; - /* *INDENT-ON* */ - } + vcl_evt (VCL_EVT_INIT, vcm); return rv; } @@ -557,28 +507,9 @@ vppcom_wait_for_app_state_change (app_state_t app_state) if (vcm->app_state == app_state) return VPPCOM_OK; } - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: timeout waiting for state %s (%d)", getpid (), - vppcom_app_state_str (app_state), app_state); - - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "ERR: timeout state:%d", - .format_args = "i4", - }; - struct - { - u32 data; - } *ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, vcm->elog_track); - - ed->data = app_state; - /* *INDENT-ON* */ - } + VDBG (0, "VCL<%d>: timeout waiting for state %s (%d)", getpid (), + vppcom_app_state_str (app_state), app_state); + vcl_evt (VCL_EVT_SESSION_TIMEOUT, vcm, app_state); return VPPCOM_ETIMEDOUT; } @@ -616,28 +547,9 @@ vppcom_wait_for_session_state_change (u32 session_index, } while (clib_time_now (&vcm->clib_time) < timeout); - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: timeout waiting for state 0x%x (%s)", getpid (), - state, vppcom_session_state_str (state)); - - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "ERR: timeout state:%d", - .format_args = "i4", - }; - struct - { - u32 data; - } *ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - - ed->data = state; - /* *INDENT-ON* */ - } + VDBG (0, "VCL<%d>: timeout waiting for state 0x%x (%s)", getpid (), state, + vppcom_session_state_str (state)); + vcl_evt (VCL_EVT_SESSION_TIMEOUT, session, state); return VPPCOM_ETIMEDOUT; } @@ -670,10 +582,8 @@ vppcom_app_session_enable (void) rv = vppcom_wait_for_app_state_change (STATE_APP_ENABLED); if (PREDICT_FALSE (rv)) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: application session enable timed out! " - "returning %d (%s)", - getpid (), rv, vppcom_retval_str (rv)); + VDBG (0, "VCL<%d>: application session enable timed out! " + "returning %d (%s)", getpid (), rv, vppcom_retval_str (rv)); return rv; } } @@ -740,10 +650,8 @@ vppcom_app_attach (void) rv = vppcom_wait_for_app_state_change (STATE_APP_ATTACHED); if (PREDICT_FALSE (rv)) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: application attach timed out! " - "returning %d (%s)", - getpid (), rv, vppcom_retval_str (rv)); + VDBG (0, "VCL<%d>: application attach timed out! returning %d (%s)", + getpid (), rv, vppcom_retval_str (rv)); return rv; } @@ -846,9 +754,9 @@ vl_api_map_another_segment_t_handler (vl_api_map_another_segment_t * mp) getpid (), mp->segment_name); return; } - if (VPPCOM_DEBUG > 1) - clib_warning ("VCL<%d>: mapped new segment '%s' size %d", getpid (), - mp->segment_name, mp->segment_size); + + VDBG (1, "VCL<%d>: mapped new segment '%s' size %d", getpid (), + mp->segment_name, mp->segment_size); } static void @@ -859,8 +767,8 @@ vl_api_unmap_segment_t_handler (vl_api_unmap_segment_t * mp) * XXX Need segment_name to session_id hash, * XXX - have sessionID by handle hash currently */ - if (VPPCOM_DEBUG > 1) - clib_warning ("Unmapped segment '%s'", mp->segment_name); + + VDBG (1, "Unmapped segment '%s'", mp->segment_name); } static void @@ -878,19 +786,15 @@ vl_api_disconnect_session_t_handler (vl_api_disconnect_session_t * mp) VCL_SESSION_LOCK_AND_GET (session_index, &session); session->state = STATE_CLOSE_ON_EMPTY; - if (VPPCOM_DEBUG > 1) - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: " - "setting state to 0x%x (%s)", - getpid (), mp->handle, session_index, session->state, - vppcom_session_state_str (session->state)); + VDBG (1, "VCL<%d>: vpp handle 0x%llx, sid %u: setting state to 0x%x " + "(%s)", getpid (), mp->handle, session_index, session->state, + vppcom_session_state_str (session->state)); VCL_SESSION_UNLOCK (); return; done: - if (VPPCOM_DEBUG > 1) - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: " - "session lookup failed!", - getpid (), mp->handle, session_index); + VDBG (1, "VCL<%d>: vpp handle 0x%llx, sid %u: session lookup failed!", + getpid (), mp->handle, session_index); } else clib_warning ("VCL<%d>: vpp handle 0x%llx: session lookup by " @@ -926,11 +830,9 @@ vl_api_reset_session_t_handler (vl_api_reset_session_t * mp) */ session->state = STATE_CLOSE_ON_EMPTY; - if (VPPCOM_DEBUG > 1) - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: " - "state set to %d (%s)!", getpid (), - mp->handle, p[0], session->state, - vppcom_session_state_str (session->state)); + VDBG (1, "VCL<%d>: vpp handle 0x%llx, sid %u: state set to %d " + "(%s)!", getpid (), mp->handle, p[0], session->state, + vppcom_session_state_str (session->state)); } VCL_SESSION_UNLOCK (); } @@ -1017,14 +919,10 @@ done: /* Add it to lookup table */ hash_set (vcm->session_index_by_vpp_handles, mp->handle, session_index); - if (VPPCOM_DEBUG > 1) - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: connect succeeded!" - " session_rx_fifo %p, refcnt %d," - " session_tx_fifo %p, refcnt %d", - getpid (), mp->handle, session_index, - session->rx_fifo, - session->rx_fifo->refcnt, - session->tx_fifo, session->tx_fifo->refcnt); + VDBG (1, "VCL<%d>: vpp handle 0x%llx, sid %u: connect succeeded! " + "session_rx_fifo %p, refcnt %d, session_tx_fifo %p, refcnt %d", + getpid (), mp->handle, session_index, session->rx_fifo, + session->rx_fifo->refcnt, session->tx_fifo, session->tx_fifo->refcnt); done_unlock: VCL_SESSION_UNLOCK (); } @@ -1055,10 +953,8 @@ vppcom_send_disconnect_session_reply (u64 vpp_handle, u32 session_index, { vl_api_disconnect_session_reply_t *rmp; - if (VPPCOM_DEBUG > 1) - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: " - "sending disconnect msg", - getpid (), vpp_handle, session_index); + VDBG (1, "VCL<%d>: vpp handle 0x%llx, sid %u: sending disconnect msg", + getpid (), vpp_handle, session_index); rmp = vl_msg_api_alloc (sizeof (*rmp)); memset (rmp, 0, sizeof (*rmp)); @@ -1074,10 +970,8 @@ vppcom_send_disconnect_session (u64 vpp_handle, u32 session_index) { vl_api_disconnect_session_t *dmp; - if (VPPCOM_DEBUG > 1) - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: " - "sending disconnect msg", - getpid (), vpp_handle, session_index); + VDBG (1, "VCL<%d>: vpp handle 0x%llx, sid %u: sending disconnect msg", + getpid (), vpp_handle, session_index); dmp = vl_msg_api_alloc (sizeof (*dmp)); memset (dmp, 0, sizeof (*dmp)); @@ -1125,9 +1019,8 @@ done: vppcom_session_table_add_listener (mp->handle, session_index); session->state = STATE_LISTEN; - if (VPPCOM_DEBUG > 1) - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: bind succeeded!", - getpid (), mp->handle, mp->context); + VDBG (1, "VCL<%d>: vpp handle 0x%llx, sid %u: bind succeeded!", + getpid (), mp->handle, mp->context); done_unlock: VCL_SESSION_UNLOCK (); } @@ -1140,9 +1033,8 @@ vl_api_unbind_sock_reply_t_handler (vl_api_unbind_sock_reply_t * mp) getpid (), mp->context, format_api_error, ntohl (mp->retval)); - else if (VPPCOM_DEBUG > 1) - clib_warning ("VCL<%d>: sid %u: unbind succeeded!", - getpid (), mp->context); + else + VDBG (1, "VCL<%d>: sid %u: unbind succeeded!", getpid (), mp->context); } u8 * @@ -1314,55 +1206,14 @@ vl_api_accept_session_t_handler (vl_api_accept_session_t * mp) rv = vce_generate_event (&vcm->event_thread, ev_idx); ASSERT (rv == 0); - if (VPPCOM_DEBUG > 1) - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: client accept " - "request from %s address %U port %d queue %p!", getpid (), - mp->handle, session_index, mp->is_ip4 ? "IPv4" : "IPv6", - format_ip46_address, &mp->ip, - mp->is_ip4 ? IP46_TYPE_IP4 : IP46_TYPE_IP6, - clib_net_to_host_u16 (mp->port), session->vpp_event_queue); - - if (VPPCOM_DEBUG > 0) - { - session->elog_track.name = - (char *) format (0, "C:%d:S:%d%c", vcm->my_client_index, - session_index, 0); - elog_track_register (&vcm->elog_main, &session->elog_track); - - if (session->peer_addr.is_ip4) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = - "client_accept:handle:%x addr:%d.%d.%d.%d:%d", - .format_args = "i8i1i1i1i1i2", - }; - - CLIB_PACKED (struct { - u64 handle; //8 - u8 addr[4]; //4 - u16 port; //2 - }) * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - - ed->handle = mp->handle; - 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 - { - clib_warning ("ip6"); - } - } + VDBG (1, "VCL<%d>: vpp handle 0x%llx, sid %u: client accept request from %s" + " address %U port %d queue %p!", getpid (), mp->handle, session_index, + mp->is_ip4 ? "IPv4" : "IPv6", format_ip46_address, &mp->ip, + mp->is_ip4 ? IP46_TYPE_IP4 : IP46_TYPE_IP6, + clib_net_to_host_u16 (mp->port), session->vpp_event_queue); + vcl_evt (VCL_EVT_ACCEPT, session, listen_session, session_index); VCL_SESSION_UNLOCK (); - } /* VPP combines bind and listen as one operation. VCL manages the separation @@ -1408,7 +1259,6 @@ vppcom_session_unbind (u32 session_index) session_t *session = 0; int rv; u64 vpp_handle; - elog_track_t session_elog_track; VCL_SESSION_LOCK_AND_GET (session_index, &session); @@ -1416,36 +1266,13 @@ vppcom_session_unbind (u32 session_index) vppcom_session_table_del_listener (vpp_handle); session->vpp_handle = ~0; session->state = STATE_DISCONNECT; - session_elog_track = session->elog_track; VCL_SESSION_UNLOCK (); - if (VPPCOM_DEBUG > 1) - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: " - "sending unbind msg! new state 0x%x (%s)", - getpid (), vpp_handle, session_index, - STATE_DISCONNECT, - vppcom_session_state_str (STATE_DISCONNECT)); - - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "unbind: handle:%x", - .format_args = "i8", - }; - - struct - { - u64 handle; - } *ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session_elog_track); - ed->handle = vpp_handle; - /* *INDENT-ON* */ - } - + VDBG (1, "VCL<%d>: vpp handle 0x%llx, sid %u: sending unbind msg! new state" + " 0x%x (%s)", getpid (), vpp_handle, session_index, STATE_DISCONNECT, + vppcom_session_state_str (STATE_DISCONNECT)); + vcl_evt (VCL_EVT_UNBIND, session); vppcom_send_unbind_sock (vpp_handle); done: @@ -1466,13 +1293,8 @@ vppcom_session_disconnect (u32 session_index) state = session->state; VCL_SESSION_UNLOCK (); - if (VPPCOM_DEBUG > 1) - { - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u " - "state 0x%x (%s)", - getpid (), vpp_handle, session_index, - state, vppcom_session_state_str (state)); - } + VDBG (1, "VCL<%d>: vpp handle 0x%llx, sid %u state 0x%x (%s)", getpid (), + vpp_handle, session_index, state, vppcom_session_state_str (state)); if (PREDICT_FALSE (state & STATE_LISTEN)) { @@ -1491,20 +1313,16 @@ vppcom_session_disconnect (u32 session_index) //XXX alagalah - Check and drain here? vppcom_send_disconnect_session_reply (vpp_handle, session_index, 0 /* rv */ ); - if (VPPCOM_DEBUG > 1) - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: " - "sending disconnect REPLY...", - getpid (), vpp_handle, session_index); + VDBG (1, "VCL<%d>: vpp handle 0x%llx, sid %u: sending disconnect " + "REPLY...", getpid (), vpp_handle, session_index); } /* Otherwise, send a disconnect session msg... */ else { - if (VPPCOM_DEBUG > 1) - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: " - "sending disconnect...", - getpid (), vpp_handle, session_index); + VDBG (1, "VCL<%d>: vpp handle 0x%llx, sid %u: sending disconnect...", + getpid (), vpp_handle, session_index); vppcom_send_disconnect_session (vpp_handle, session_index); } @@ -1582,19 +1400,16 @@ vppcom_cfg_heapsize (char *conf_fname) fp = fopen (conf_fname, "r"); if (fp == NULL) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: using default heapsize %lld (0x%llx)", - getpid (), vcl_cfg->heapsize, vcl_cfg->heapsize); + VDBG (0, "VCL<%d>: using default heapsize %lld (0x%llx)", getpid (), + vcl_cfg->heapsize, vcl_cfg->heapsize); goto defaulted; } argv = calloc (1, sizeof (char *)); if (argv == NULL) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: calloc failed, using default " - "heapsize %lld (0x%llx)", - getpid (), vcl_cfg->heapsize, vcl_cfg->heapsize); + VDBG (0, "VCL<%d>: calloc failed, using default heapsize %lld (0x%llx)", + getpid (), vcl_cfg->heapsize, vcl_cfg->heapsize); goto defaulted; } @@ -1611,22 +1426,18 @@ vppcom_cfg_heapsize (char *conf_fname) char **tmp = realloc (argv, argc * sizeof (char *)); if (tmp == NULL) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: realloc failed, " - "using default heapsize %lld (0x%llx)", - getpid (), vcl_cfg->heapsize, - vcl_cfg->heapsize); + VDBG (0, "VCL<%d>: realloc failed, using default heapsize %lld " + "(0x%llx)", getpid (), vcl_cfg->heapsize, + vcl_cfg->heapsize); goto defaulted; } argv = tmp; arg = strndup (p, 1024); if (arg == NULL) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: strndup failed, " - "using default heapsize %lld (0x%llx)", - getpid (), vcl_cfg->heapsize, - vcl_cfg->heapsize); + VDBG (0, "VCL<%d>: strndup failed, using default heapsize %lld " + "(0x%llx)", getpid (), vcl_cfg->heapsize, + vcl_cfg->heapsize); goto defaulted; } argv[argc - 1] = arg; @@ -1640,10 +1451,8 @@ vppcom_cfg_heapsize (char *conf_fname) char **tmp = realloc (argv, (argc + 1) * sizeof (char *)); if (tmp == NULL) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: realloc failed, " - "using default heapsize %lld (0x%llx)", - getpid (), vcl_cfg->heapsize, vcl_cfg->heapsize); + VDBG (0, "VCL<%d>: realloc failed, using default heapsize %lld " + "(0x%llx)", getpid (), vcl_cfg->heapsize, vcl_cfg->heapsize); goto defaulted; } argv = tmp; @@ -1669,11 +1478,9 @@ vppcom_cfg_heapsize (char *conf_fname) } if (size == 0) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: parse error '%s %s', " - "using default heapsize %lld (0x%llx)", - getpid (), argv[i], argv[i + 1], - vcl_cfg->heapsize, vcl_cfg->heapsize); + VDBG (0, "VCL<%d>: parse error '%s %s', using default " + "heapsize %lld (0x%llx)", getpid (), argv[i], argv[i + 1], + vcl_cfg->heapsize, vcl_cfg->heapsize); goto defaulted; } @@ -1683,11 +1490,9 @@ vppcom_cfg_heapsize (char *conf_fname) vcl_cfg->heapsize = size << 20; else { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: parse error '%s %s', " - "using default heapsize %lld (0x%llx)", - getpid (), argv[i], argv[i + 1], - vcl_cfg->heapsize, vcl_cfg->heapsize); + VDBG (0, "VCL<%d>: parse error '%s %s', using default " + "heapsize %lld (0x%llx)", getpid (), argv[i], argv[i + 1], + vcl_cfg->heapsize, vcl_cfg->heapsize); goto defaulted; } } @@ -1728,9 +1533,8 @@ defaulted: clib_memcpy (vcl_mem, &_vppcom_main, sizeof (_vppcom_main)); vcm = vcl_mem; - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: allocated VCL heap = %p, size %lld (0x%llx)", - getpid (), heap, vcl_cfg->heapsize, vcl_cfg->heapsize); + VDBG (0, "VCL<%d>: allocated VCL heap = %p, size %lld (0x%llx)", getpid (), + heap, vcl_cfg->heapsize, vcl_cfg->heapsize); } static void @@ -1748,25 +1552,22 @@ vppcom_cfg_read (char *conf_fname) fd = open (conf_fname, O_RDONLY); if (fd < 0) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: using default configuration.", - getpid (), conf_fname); + VDBG (0, "VCL<%d>: using default configuration.", getpid (), + conf_fname); goto file_done; } if (fstat (fd, &s) < 0) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: failed to stat `%s', " - "using default configuration", getpid (), conf_fname); + VDBG (0, "VCL<%d>: failed to stat `%s', using default configuration", + getpid (), conf_fname); goto file_done; } if (!(S_ISREG (s.st_mode) || S_ISLNK (s.st_mode))) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: not a regular file `%s', " - "using default configuration", getpid (), conf_fname); + VDBG (0, "VCL<%d>: not a regular file `%s', using default " + "configuration", getpid (), conf_fname); goto file_done; } @@ -1788,11 +1589,9 @@ vppcom_cfg_read (char *conf_fname) if (unformat (line_input, "heapsize %s", &chroot_path)) { vec_terminate_c_string (chroot_path); - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured heapsize %s, " - "actual heapsize %lld (0x%llx)", - getpid (), chroot_path, vcl_cfg->heapsize, - vcl_cfg->heapsize); + VDBG (0, "VCL<%d>: configured heapsize %s, actual heapsize %lld" + " (0x%llx)", getpid (), chroot_path, vcl_cfg->heapsize, + vcl_cfg->heapsize); vec_free (chroot_path); } else if (unformat (line_input, "api-prefix %s", &chroot_path)) @@ -1804,10 +1603,9 @@ vppcom_cfg_read (char *conf_fname) chroot_path, 0); vl_set_memory_root_path ((char *) chroot_path); - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured api-prefix (%s) and " - "api filename (%s)", getpid (), chroot_path, - vcl_cfg->vpp_api_filename); + VDBG (0, "VCL<%d>: configured api-prefix (%s) and api filename" + " (%s)", getpid (), chroot_path, + vcl_cfg->vpp_api_filename); chroot_path = 0; /* Don't vec_free() it! */ } else if (unformat (line_input, "vpp-api-q-length %d", &q_len)) @@ -1822,200 +1620,159 @@ vppcom_cfg_read (char *conf_fname) { vcl_cfg->vpp_api_q_length = q_len; - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured vpp-api-q-length %u", - getpid (), vcl_cfg->vpp_api_q_length); + VDBG (0, "VCL<%d>: configured vpp-api-q-length %u", + getpid (), vcl_cfg->vpp_api_q_length); } } else if (unformat (line_input, "uid %d", &uid)) { vl_set_memory_uid (uid); - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured uid %d", getpid (), uid); + VDBG (0, "VCL<%d>: configured uid %d", getpid (), uid); } else if (unformat (line_input, "gid %d", &gid)) { vl_set_memory_gid (gid); - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured gid %d", getpid (), gid); + VDBG (0, "VCL<%d>: configured gid %d", getpid (), gid); } else if (unformat (line_input, "segment-baseva 0x%lx", &vcl_cfg->segment_baseva)) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured segment_baseva 0x%lx", - getpid (), vcl_cfg->segment_baseva); + VDBG (0, "VCL<%d>: configured segment_baseva 0x%lx", getpid (), + vcl_cfg->segment_baseva); } else if (unformat (line_input, "segment-size 0x%lx", &vcl_cfg->segment_size)) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured segment_size 0x%lx (%ld)", - getpid (), vcl_cfg->segment_size, - vcl_cfg->segment_size); + VDBG (0, "VCL<%d>: configured segment_size 0x%lx (%ld)", + getpid (), vcl_cfg->segment_size, vcl_cfg->segment_size); } else if (unformat (line_input, "segment-size %ld", &vcl_cfg->segment_size)) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured segment_size %ld (0x%lx)", - getpid (), vcl_cfg->segment_size, - vcl_cfg->segment_size); + VDBG (0, "VCL<%d>: configured segment_size %ld (0x%lx)", + getpid (), vcl_cfg->segment_size, vcl_cfg->segment_size); } else if (unformat (line_input, "add-segment-size 0x%lx", &vcl_cfg->add_segment_size)) { - if (VPPCOM_DEBUG > 0) - clib_warning - ("VCL<%d>: configured add_segment_size 0x%lx (%ld)", - getpid (), vcl_cfg->add_segment_size, - vcl_cfg->add_segment_size); + VDBG (0, "VCL<%d>: configured add_segment_size 0x%lx (%ld)", + getpid (), vcl_cfg->add_segment_size, + vcl_cfg->add_segment_size); } else if (unformat (line_input, "add-segment-size %ld", &vcl_cfg->add_segment_size)) { - if (VPPCOM_DEBUG > 0) - clib_warning - ("VCL<%d>: configured add_segment_size %ld (0x%lx)", - getpid (), vcl_cfg->add_segment_size, - vcl_cfg->add_segment_size); + VDBG (0, "VCL<%d>: configured add_segment_size %ld (0x%lx)", + getpid (), vcl_cfg->add_segment_size, + vcl_cfg->add_segment_size); } else if (unformat (line_input, "preallocated-fifo-pairs %d", &vcl_cfg->preallocated_fifo_pairs)) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured preallocated_fifo_pairs " - "%d (0x%x)", getpid (), - vcl_cfg->preallocated_fifo_pairs, - vcl_cfg->preallocated_fifo_pairs); + VDBG (0, "VCL<%d>: configured preallocated_fifo_pairs %d " + "(0x%x)", getpid (), vcl_cfg->preallocated_fifo_pairs, + vcl_cfg->preallocated_fifo_pairs); } else if (unformat (line_input, "rx-fifo-size 0x%lx", &vcl_cfg->rx_fifo_size)) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured rx_fifo_size 0x%lx (%ld)", - getpid (), vcl_cfg->rx_fifo_size, - vcl_cfg->rx_fifo_size); + VDBG (0, "VCL<%d>: configured rx_fifo_size 0x%lx (%ld)", + getpid (), vcl_cfg->rx_fifo_size, vcl_cfg->rx_fifo_size); } else if (unformat (line_input, "rx-fifo-size %ld", &vcl_cfg->rx_fifo_size)) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured rx_fifo_size %ld (0x%lx)", - getpid (), vcl_cfg->rx_fifo_size, - vcl_cfg->rx_fifo_size); + VDBG (0, "VCL<%d>: configured rx_fifo_size %ld (0x%lx)", + getpid (), vcl_cfg->rx_fifo_size, vcl_cfg->rx_fifo_size); } else if (unformat (line_input, "tx-fifo-size 0x%lx", &vcl_cfg->tx_fifo_size)) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured tx_fifo_size 0x%lx (%ld)", - getpid (), vcl_cfg->tx_fifo_size, - vcl_cfg->tx_fifo_size); + VDBG (0, "VCL<%d>: configured tx_fifo_size 0x%lx (%ld)", + getpid (), vcl_cfg->tx_fifo_size, vcl_cfg->tx_fifo_size); } else if (unformat (line_input, "tx-fifo-size %ld", &vcl_cfg->tx_fifo_size)) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured tx_fifo_size %ld (0x%lx)", - getpid (), vcl_cfg->tx_fifo_size, - vcl_cfg->tx_fifo_size); + VDBG (0, "VCL<%d>: configured tx_fifo_size %ld (0x%lx)", + getpid (), vcl_cfg->tx_fifo_size, vcl_cfg->tx_fifo_size); } else if (unformat (line_input, "event-queue-size 0x%lx", &vcl_cfg->event_queue_size)) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured event_queue_size " - "0x%lx (%ld)", - getpid (), vcl_cfg->event_queue_size, - vcl_cfg->event_queue_size); + VDBG (0, "VCL<%d>: configured event_queue_size 0x%lx (%ld)", + getpid (), vcl_cfg->event_queue_size, + vcl_cfg->event_queue_size); } else if (unformat (line_input, "event-queue-size %ld", &vcl_cfg->event_queue_size)) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured event_queue_size " - "%ld (0x%lx)", - getpid (), vcl_cfg->event_queue_size, - vcl_cfg->event_queue_size); + VDBG (0, "VCL<%d>: configured event_queue_size %ld (0x%lx)", + getpid (), vcl_cfg->event_queue_size, + vcl_cfg->event_queue_size); } else if (unformat (line_input, "listen-queue-size 0x%lx", &vcl_cfg->listen_queue_size)) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured listen_queue_size " - "0x%lx (%ld)", - getpid (), vcl_cfg->listen_queue_size, - vcl_cfg->listen_queue_size); + VDBG (0, "VCL<%d>: configured listen_queue_size 0x%lx (%ld)", + getpid (), vcl_cfg->listen_queue_size, + vcl_cfg->listen_queue_size); } else if (unformat (line_input, "listen-queue-size %ld", &vcl_cfg->listen_queue_size)) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured listen_queue_size " - "%ld (0x%lx)", - getpid (), vcl_cfg->listen_queue_size, - vcl_cfg->listen_queue_size); + VDBG (0, "VCL<%d>: configured listen_queue_size %ld (0x%lx)", + getpid (), vcl_cfg->listen_queue_size, + vcl_cfg->listen_queue_size); } else if (unformat (line_input, "app-timeout %f", &vcl_cfg->app_timeout)) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured app_timeout %f", - getpid (), vcl_cfg->app_timeout); + VDBG (0, "VCL<%d>: configured app_timeout %f", + getpid (), vcl_cfg->app_timeout); } else if (unformat (line_input, "session-timeout %f", &vcl_cfg->session_timeout)) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured session_timeout %f", - getpid (), vcl_cfg->session_timeout); + VDBG (0, "VCL<%d>: configured session_timeout %f", + getpid (), vcl_cfg->session_timeout); } else if (unformat (line_input, "accept-timeout %f", &vcl_cfg->accept_timeout)) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured accept_timeout %f", - getpid (), vcl_cfg->accept_timeout); + VDBG (0, "VCL<%d>: configured accept_timeout %f", + getpid (), vcl_cfg->accept_timeout); } else if (unformat (line_input, "app-proxy-transport-tcp")) { vcl_cfg->app_proxy_transport_tcp = 1; - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured " - "app_proxy_transport_tcp (%d)", - getpid (), vcl_cfg->app_proxy_transport_tcp); + VDBG (0, "VCL<%d>: configured app_proxy_transport_tcp (%d)", + getpid (), vcl_cfg->app_proxy_transport_tcp); } else if (unformat (line_input, "app-proxy-transport-udp")) { vcl_cfg->app_proxy_transport_udp = 1; - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured " - "app_proxy_transport_udp (%d)", - getpid (), vcl_cfg->app_proxy_transport_udp); + VDBG (0, "VCL<%d>: configured app_proxy_transport_udp (%d)", + getpid (), vcl_cfg->app_proxy_transport_udp); } else if (unformat (line_input, "app-scope-local")) { vcl_cfg->app_scope_local = 1; - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured app_scope_local (%d)", - getpid (), vcl_cfg->app_scope_local); + VDBG (0, "VCL<%d>: configured app_scope_local (%d)", + getpid (), vcl_cfg->app_scope_local); } else if (unformat (line_input, "app-scope-global")) { vcl_cfg->app_scope_global = 1; - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured app_scope_global (%d)", - getpid (), vcl_cfg->app_scope_global); + VDBG (0, "VCL<%d>: configured app_scope_global (%d)", + getpid (), vcl_cfg->app_scope_global); } else if (unformat (line_input, "namespace-secret %lu", &vcl_cfg->namespace_secret)) { - if (VPPCOM_DEBUG > 0) - clib_warning - ("VCL<%d>: configured namespace_secret %lu (0x%lx)", - getpid (), vcl_cfg->namespace_secret, - vcl_cfg->namespace_secret); + VDBG (0, "VCL<%d>: configured namespace_secret %lu (0x%lx)", + getpid (), vcl_cfg->namespace_secret, + vcl_cfg->namespace_secret); } else if (unformat (line_input, "namespace-id %v", &vcl_cfg->namespace_id)) @@ -2026,22 +1783,19 @@ vppcom_cfg_read (char *conf_fname) if (nsid_vec_len > max_nsid_vec_len) { _vec_len (vcl_cfg->namespace_id) = max_nsid_vec_len; - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured namespace_id is " - "too long, truncated to %d characters!", - getpid (), max_nsid_vec_len); + VDBG (0, "VCL<%d>: configured namespace_id is too long," + " truncated to %d characters!", + getpid (), max_nsid_vec_len); } - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured namespace_id %v", - getpid (), vcl_cfg->namespace_id); + VDBG (0, "VCL<%d>: configured namespace_id %v", + getpid (), vcl_cfg->namespace_id); } else if (unformat (line_input, "}")) { vc_cfg_input = 0; - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: completed parsing vppcom config!", - getpid ()); + VDBG (0, "VCL<%d>: completed parsing vppcom config!", + getpid ()); goto input_done; } else @@ -2093,9 +1847,8 @@ vppcom_app_create (char *app_name) else { vcm->debug = tmp; - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured VCL debug level (%u) from " - VPPCOM_ENV_DEBUG "!", getpid (), vcm->debug); + VDBG (0, "VCL<%d>: configured VCL debug level (%u) from " + VPPCOM_ENV_DEBUG "!", getpid (), vcm->debug); } } conf_fname = getenv (VPPCOM_ENV_CONF); @@ -2118,10 +1871,9 @@ vppcom_app_create (char *app_name) env_var_str, 0); vl_set_memory_root_path ((char *) env_var_str); - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured api prefix (%s) and " - "filename (%s) from " VPPCOM_ENV_API_PREFIX "!", - getpid (), env_var_str, vcl_cfg->vpp_api_filename); + VDBG (0, "VCL<%d>: configured api prefix (%s) and filename (%s) " + "from " VPPCOM_ENV_API_PREFIX "!", + getpid (), env_var_str, vcl_cfg->vpp_api_filename); } env_var_str = getenv (VPPCOM_ENV_APP_NAMESPACE_ID); if (env_var_str) @@ -2132,10 +1884,9 @@ vppcom_app_create (char *app_name) vec_validate (vcm->cfg.namespace_id, ns_id_vec_len - 1); clib_memcpy (vcm->cfg.namespace_id, env_var_str, ns_id_vec_len); - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured namespace_id (%v) from " - VPPCOM_ENV_APP_NAMESPACE_ID - "!", getpid (), vcm->cfg.namespace_id); + VDBG (0, "VCL<%d>: configured namespace_id (%v) from " + VPPCOM_ENV_APP_NAMESPACE_ID "!", getpid (), + vcm->cfg.namespace_id); } env_var_str = getenv (VPPCOM_ENV_APP_NAMESPACE_SECRET); if (env_var_str) @@ -2149,46 +1900,38 @@ vppcom_app_create (char *app_name) else { vcm->cfg.namespace_secret = tmp; - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured namespace secret " - "(%lu) from " - VPPCOM_ENV_APP_NAMESPACE_SECRET - "!", getpid (), vcm->cfg.namespace_secret); + VDBG (0, "VCL<%d>: configured namespace secret (%lu) from " + VPPCOM_ENV_APP_NAMESPACE_SECRET "!", getpid (), + vcm->cfg.namespace_secret); } } if (getenv (VPPCOM_ENV_APP_PROXY_TRANSPORT_TCP)) { vcm->cfg.app_proxy_transport_tcp = 1; - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured app_proxy_transport_tcp " - "(%u) from " - VPPCOM_ENV_APP_PROXY_TRANSPORT_TCP - "!", getpid (), vcm->cfg.app_proxy_transport_tcp); + VDBG (0, "VCL<%d>: configured app_proxy_transport_tcp (%u) from " + VPPCOM_ENV_APP_PROXY_TRANSPORT_TCP "!", getpid (), + vcm->cfg.app_proxy_transport_tcp); } if (getenv (VPPCOM_ENV_APP_PROXY_TRANSPORT_UDP)) { vcm->cfg.app_proxy_transport_udp = 1; - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured app_proxy_transport_udp " - "(%u) from " - VPPCOM_ENV_APP_PROXY_TRANSPORT_UDP - "!", getpid (), vcm->cfg.app_proxy_transport_udp); + VDBG (0, "VCL<%d>: configured app_proxy_transport_udp (%u) from " + VPPCOM_ENV_APP_PROXY_TRANSPORT_UDP "!", getpid (), + vcm->cfg.app_proxy_transport_udp); } if (getenv (VPPCOM_ENV_APP_SCOPE_LOCAL)) { vcm->cfg.app_scope_local = 1; - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured app_scope_local (%u) from " - VPPCOM_ENV_APP_SCOPE_LOCAL - "!", getpid (), vcm->cfg.app_scope_local); + VDBG (0, "VCL<%d>: configured app_scope_local (%u) from " + VPPCOM_ENV_APP_SCOPE_LOCAL "!", getpid (), + vcm->cfg.app_scope_local); } if (getenv (VPPCOM_ENV_APP_SCOPE_GLOBAL)) { vcm->cfg.app_scope_global = 1; - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: configured app_scope_global (%u) from " - VPPCOM_ENV_APP_SCOPE_GLOBAL - "!", getpid (), vcm->cfg.app_scope_global); + VDBG (0, "VCL<%d>: configured app_scope_global (%u) from " + VPPCOM_ENV_APP_SCOPE_GLOBAL "!", getpid (), + vcm->cfg.app_scope_global); } vcm->main_cpu = os_get_thread_index (); @@ -2212,6 +1955,7 @@ vppcom_app_create (char *app_name) /* API hookup and connect to VPP */ vppcom_api_hookup (); + vcl_elog_init (vcm); vcm->app_state = STATE_APP_START; rv = vppcom_connect_to_vpp (app_name); if (rv) @@ -2225,8 +1969,7 @@ vppcom_app_create (char *app_name) rv = vce_start_event_thread (&(vcm->event_thread), 20); - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: sending session enable", getpid ()); + VDBG (0, "VCL<%d>: sending session enable", getpid ()); rv = vppcom_app_session_enable (); if (rv) @@ -2236,8 +1979,7 @@ vppcom_app_create (char *app_name) return rv; } - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: sending app attach", getpid ()); + VDBG (0, "VCL<%d>: sending app attach", getpid ()); rv = vppcom_app_attach (); if (rv) @@ -2247,10 +1989,8 @@ vppcom_app_create (char *app_name) return rv; } - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: app_name '%s', my_client_index %d (0x%x)", - getpid (), app_name, vcm->my_client_index, - vcm->my_client_index); + VDBG (0, "VCL<%d>: app_name '%s', my_client_index %d (0x%x)", + getpid (), app_name, vcm->my_client_index, vcm->my_client_index); } return VPPCOM_OK; @@ -2265,27 +2005,9 @@ vppcom_app_destroy (void) if (vcm->my_client_index == ~0) return; - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: detaching from VPP, my_client_index %d (0x%x)", - getpid (), vcm->my_client_index, vcm->my_client_index); - - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "app_detach:C:%d", - .format_args = "i4", - }; - - struct - { - u32 data; - } *ed; - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, vcm->elog_track); - ed->data = vcm->my_client_index; - /* *INDENT-ON* */ - } + VDBG (0, "VCL<%d>: detaching from VPP, my_client_index %d (0x%x)", + getpid (), vcm->my_client_index, vcm->my_client_index); + vcl_evt (VCL_EVT_DETACH, vcm); vppcom_app_detach (); orig_app_timeout = vcm->cfg.app_timeout; @@ -2293,17 +2015,10 @@ vppcom_app_destroy (void) rv = vppcom_wait_for_app_state_change (STATE_APP_ENABLED); vcm->cfg.app_timeout = orig_app_timeout; if (PREDICT_FALSE (rv)) - { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: application detach timed out! " - "returning %d (%s)", - getpid (), rv, vppcom_retval_str (rv)); - } - - /* Finished with logging before client gets reset to ~0 */ - if (VPPCOM_DEBUG > 0) - write_elog (); + VDBG (0, "VCL<%d>: application detach timed out! returning %d (%s)", + getpid (), rv, vppcom_retval_str (rv)); + vcl_elog_stop (vcm); vl_client_disconnect_from_vlib (); vcm->my_client_index = ~0; vcm->app_state = STATE_APP_START; @@ -2314,8 +2029,6 @@ vppcom_session_create (u8 proto, u8 is_nonblocking) { session_t *session; u32 session_index; - session_state_t state; - elog_track_t session_elog_track; VCL_SESSION_LOCK (); pool_get (vcm->sessions, session); @@ -2324,7 +2037,6 @@ vppcom_session_create (u8 proto, u8 is_nonblocking) session->proto = proto; session->state = STATE_START; - state = session->state; session->vpp_handle = ~0; if (is_nonblocking) @@ -2332,40 +2044,12 @@ vppcom_session_create (u8 proto, u8 is_nonblocking) else VCL_SESS_ATTR_CLR (session->attr, VCL_SESS_ATTR_NONBLOCK); - if (VPPCOM_DEBUG > 0) - { - session->elog_track.name = - (char *) format (0, "C:%d:S:%d%c", vcm->my_client_index, - session_index, 0); - elog_track_register (&vcm->elog_main, &session->elog_track); - session_elog_track = session->elog_track; - } + vcl_evt (VCL_EVT_CREATE, session, proto, session->state, is_nonblocking, + session_index); VCL_SESSION_UNLOCK (); - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: sid %u", getpid (), session_index); - - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "session_create:proto:%d state:%d is_nonblocking:%d", - .format_args = "i4i4i4", - }; - - struct - { - u32 data[3]; - } *ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session_elog_track); - ed->data[0] = proto; - ed->data[1] = state; - ed->data[2] = is_nonblocking; - /* *INDENT-ON* */ - } + VDBG (0, "VCL<%d>: sid %u", getpid (), session_index); return (int) session_index; } @@ -2382,7 +2066,6 @@ vppcom_session_close (uint32_t session_index) u64 vpp_handle; uword *p; session_state_t state; - elog_track_t session_elog_track; VCL_SESSION_LOCK_AND_GET (session_index, &session); is_vep = session->is_vep; @@ -2393,19 +2076,6 @@ vppcom_session_close (uint32_t session_index) vpp_handle = session->vpp_handle; VCL_SESSION_UNLOCK (); - /* - * Why two if(VPPCOM_DEBUG) checks? - * - * Eventually all clib_warnings need their own way of being - * logged and signalled (like severity) where event logging - * is a separate debugging tool. It will make the separation - * easier. ... parting is such sweet sorrow ... - */ - if (VPPCOM_DEBUG > 0) - { - session_elog_track = session->elog_track; - } - if (VPPCOM_DEBUG > 0) { if (is_vep) @@ -2423,11 +2093,11 @@ vppcom_session_close (uint32_t session_index) while (next_sid != ~0) { rv = vppcom_epoll_ctl (session_index, EPOLL_CTL_DEL, next_sid, 0); - if ((VPPCOM_DEBUG > 0) && PREDICT_FALSE (rv < 0)) - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: " - "EPOLL_CTL_DEL vep_idx %u failed! rv %d (%s)", - getpid (), vpp_handle, next_sid, vep_idx, - rv, vppcom_retval_str (rv)); + if (PREDICT_FALSE (rv < 0)) + VDBG (0, "VCL<%d>: vpp handle 0x%llx, sid %u: EPOLL_CTL_DEL " + "vep_idx %u failed! rv %d (%s)", + getpid (), vpp_handle, next_sid, vep_idx, + rv, vppcom_retval_str (rv)); VCL_SESSION_LOCK_AND_GET (session_index, &session); next_sid = session->vep.next_sid; @@ -2439,24 +2109,21 @@ vppcom_session_close (uint32_t session_index) if (is_vep_session) { rv = vppcom_epoll_ctl (vep_idx, EPOLL_CTL_DEL, session_index, 0); - if ((VPPCOM_DEBUG > 0) && (rv < 0)) - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: " - "EPOLL_CTL_DEL vep_idx %u failed! rv %d (%s)", - getpid (), vpp_handle, session_index, - vep_idx, rv, vppcom_retval_str (rv)); + if (rv < 0) + VDBG (0, "VCL<%d>: vpp handle 0x%llx, sid %u: EPOLL_CTL_DEL " + "vep_idx %u failed! rv %d (%s)", + getpid (), vpp_handle, session_index, + vep_idx, rv, vppcom_retval_str (rv)); } if (state & STATE_LISTEN) { rv = vppcom_session_unbind (session_index); if (PREDICT_FALSE (rv < 0)) - { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: " - "listener unbind failed! rv %d (%s)", - getpid (), vpp_handle, session_index, - rv, vppcom_retval_str (rv)); - } + VDBG (0, "VCL<%d>: vpp handle 0x%llx, sid %u: listener unbind " + "failed! rv %d (%s)", + getpid (), vpp_handle, session_index, + rv, vppcom_retval_str (rv)); } else if (state & (CLIENT_STATE_OPEN | SERVER_STATE_OPEN)) @@ -2493,24 +2160,7 @@ vppcom_session_close (uint32_t session_index) } done: - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "session_close:rv:%d", - .format_args = "i4", - }; - - struct - { - u32 data; - } *ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session_elog_track); - ed->data = rv; - /* *INDENT-ON* */ - } + vcl_evt (VCL_EVT_CLOSE, session, rv); return rv; } @@ -2540,45 +2190,14 @@ vppcom_session_bind (uint32_t session_index, vppcom_endpt_t * ep) IP46_TYPE_IP6, ep->ip); session->lcl_port = ep->port; - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: sid %u: binding to local %s address %U " - "port %u, proto %s", getpid (), session_index, - session->lcl_addr.is_ip4 ? "IPv4" : "IPv6", - format_ip46_address, &session->lcl_addr.ip46, - session->lcl_addr.is_ip4 ? IP46_TYPE_IP4 : IP46_TYPE_IP6, - clib_net_to_host_u16 (session->lcl_port), - session->proto ? "UDP" : "TCP"); - - if (VPPCOM_DEBUG > 0) - { - if (session->lcl_addr.is_ip4) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "bind local:%s:%d.%d.%d.%d:%d ", - .format_args = "t1i1i1i1i1i2", - .n_enum_strings = 2, - .enum_strings = {"TCP", "UDP",}, - }; - - CLIB_PACKED (struct { - u8 proto; - u8 addr[4]; - u16 port; - }) *ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->proto = session->proto; - 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->lcl_port); - /* *INDENT-ON* */ - } - } - + VDBG (0, "VCL<%d>: sid %u: binding to local %s address %U port %u, " + "proto %s", getpid (), session_index, + session->lcl_addr.is_ip4 ? "IPv4" : "IPv6", + format_ip46_address, &session->lcl_addr.ip46, + session->lcl_addr.is_ip4 ? IP46_TYPE_IP4 : IP46_TYPE_IP6, + clib_net_to_host_u16 (session->lcl_port), + session->proto ? "UDP" : "TCP"); + vcl_evt (VCL_EVT_BIND, session); VCL_SESSION_UNLOCK (); done: return rv; @@ -2609,18 +2228,14 @@ vppcom_session_listen (uint32_t listen_session_index, uint32_t q_len) if (listen_session->state & STATE_LISTEN) { VCL_SESSION_UNLOCK (); - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: " - "already in listen state!", - getpid (), listen_vpp_handle, listen_session_index); + VDBG (0, "VCL<%d>: vpp handle 0x%llx, sid %u: already in listen state!", + getpid (), listen_vpp_handle, listen_session_index); rv = VPPCOM_OK; goto done; } - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: vpp handle 0x%llx, " - "sid %u: sending VPP bind+listen request...", - getpid (), listen_vpp_handle, listen_session_index); + VDBG (0, "VCL<%d>: vpp handle 0x%llx, sid %u: sending VPP bind+listen " + "request...", getpid (), listen_vpp_handle, listen_session_index); vppcom_send_bind_sock (listen_session, listen_session_index); VCL_SESSION_UNLOCK (); @@ -2631,11 +2246,9 @@ vppcom_session_listen (uint32_t listen_session_index, uint32_t q_len) VCL_SESSION_LOCK_AND_GET (listen_session_index, &listen_session); if (PREDICT_FALSE (retval)) { - if (VPPCOM_DEBUG > 0) - clib_warning - ("VCL<%d>: vpp handle 0x%llx, sid %u: bind+listen failed! " - "returning %d (%s)", getpid (), listen_session->vpp_handle, - listen_session_index, retval, vppcom_retval_str (retval)); + VDBG (0, "VCL<%d>: vpp handle 0x%llx, sid %u: bind+listen failed! " + "returning %d (%s)", getpid (), listen_session->vpp_handle, + listen_session_index, retval, vppcom_retval_str (retval)); VCL_SESSION_UNLOCK (); rv = retval; goto done; @@ -2775,13 +2388,12 @@ vppcom_session_accept (uint32_t listen_session_index, vppcom_endpt_t * ep, else VCL_SESS_ATTR_CLR (client_session->attr, VCL_SESS_ATTR_NONBLOCK); - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: Got a client request! " - "vpp handle 0x%llx, sid %u, flags %d, is_nonblocking %u", - getpid (), listen_vpp_handle, listen_session_index, - client_session->vpp_handle, client_session_index, - flags, VCL_SESS_ATTR_TEST (client_session->attr, - VCL_SESS_ATTR_NONBLOCK)); + VDBG (0, "VCL<%d>: vpp handle 0x%llx, sid %u: Got a client request! " + "vpp handle 0x%llx, sid %u, flags %d, is_nonblocking %u", + getpid (), listen_vpp_handle, listen_session_index, + client_session->vpp_handle, client_session_index, + flags, VCL_SESS_ATTR_TEST (client_session->attr, + VCL_SESS_ATTR_NONBLOCK)); if (ep) { @@ -2799,76 +2411,24 @@ vppcom_session_accept (uint32_t listen_session_index, vppcom_endpt_t * ep, client_session->client_context, 0 /* retval OK */ ); - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: accepted vpp handle " - "0x%llx, sid %u connection from peer %s address %U port %u " - "to local %s address %U port %u", - getpid (), listen_vpp_handle, - listen_session_index, client_session->vpp_handle, - client_session_index, - client_session->peer_addr.is_ip4 ? "IPv4" : "IPv6", - format_ip46_address, &client_session->peer_addr.ip46, - client_session->peer_addr.is_ip4 ? - IP46_TYPE_IP4 : IP46_TYPE_IP6, - clib_net_to_host_u16 (client_session->peer_port), - client_session->lcl_addr.is_ip4 ? "IPv4" : "IPv6", - format_ip46_address, &client_session->lcl_addr.ip46, - client_session->lcl_addr.is_ip4 ? - IP46_TYPE_IP4 : IP46_TYPE_IP6, - clib_net_to_host_u16 (client_session->lcl_port)); - - if (VPPCOM_DEBUG > 0) - { - client_session->elog_track.name = - (char *) format (0, "C:%d:S:%d%c", vcm->my_client_index, - client_session_index, 0); - elog_track_register (&vcm->elog_main, &client_session->elog_track); - - // Two elog entries due to 20-byte per entry constraint. - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "accept: listen_handle:%x from_handle:%x", - .format_args = "i8i8", - }; - - struct - { - u64 handle[2]; - } *ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, client_session->elog_track); - ed->handle[0] = listen_vpp_handle; - ed->handle[1] = client_session->vpp_handle; - /* *INDENT-ON* */ - - if (client_session->lcl_addr.is_ip4) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e2) = - { - .format = "accept: S:%d %d.%d.%d.%d:%d ", - .format_args = "i4i1i1i1i1i2", - }; - - CLIB_PACKED (struct { - u32 session; - u8 addr[4]; - u16 port; - }) *ed2; - - ed2 = - ELOG_TRACK_DATA (&vcm->elog_main, e2, client_session->elog_track); - ed2->session = client_session_index; - ed2->addr[0] = client_session->lcl_addr.ip46.ip4.as_u8[0]; - ed2->addr[1] = client_session->lcl_addr.ip46.ip4.as_u8[1]; - ed2->addr[2] = client_session->lcl_addr.ip46.ip4.as_u8[2]; - ed2->addr[3] = client_session->lcl_addr.ip46.ip4.as_u8[3]; - ed2->port = clib_net_to_host_u16 (client_session->lcl_port); - /* *INDENT-ON* */ - } - } - + VDBG (0, "VCL<%d>: vpp handle 0x%llx, sid %u: accepted vpp handle 0x%llx," + " sid %u connection from peer %s address %U port %u to local %s address" + " %U port %u", + getpid (), listen_vpp_handle, + listen_session_index, client_session->vpp_handle, + client_session_index, + client_session->peer_addr.is_ip4 ? "IPv4" : "IPv6", + format_ip46_address, &client_session->peer_addr.ip46, + client_session->peer_addr.is_ip4 ? + IP46_TYPE_IP4 : IP46_TYPE_IP6, + clib_net_to_host_u16 (client_session->peer_port), + client_session->lcl_addr.is_ip4 ? "IPv4" : "IPv6", + format_ip46_address, &client_session->lcl_addr.ip46, + client_session->lcl_addr.is_ip4 ? + IP46_TYPE_IP4 : IP46_TYPE_IP6, + clib_net_to_host_u16 (client_session->lcl_port)); + vcl_evt (VCL_EVT_ACCEPT, client_session, listen_session, + client_session_index); VCL_SESSION_UNLOCK (); rv = (int) client_session_index; @@ -2911,17 +2471,16 @@ vppcom_session_connect (uint32_t session_index, vppcom_endpt_t * server_ep) if (PREDICT_FALSE (session->state & CLIENT_STATE_OPEN)) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: session already " - "connected to %s %U port %d proto %s, state 0x%x (%s)", - getpid (), session->vpp_handle, session_index, - session->peer_addr.is_ip4 ? "IPv4" : "IPv6", - format_ip46_address, - &session->peer_addr.ip46, session->peer_addr.is_ip4 ? - IP46_TYPE_IP4 : IP46_TYPE_IP6, - clib_net_to_host_u16 (session->peer_port), - session->proto ? "UDP" : "TCP", session->state, - vppcom_session_state_str (session->state)); + VDBG (0, "VCL<%d>: vpp handle 0x%llx, sid %u: session already " + "connected to %s %U port %d proto %s, state 0x%x (%s)", + getpid (), session->vpp_handle, session_index, + session->peer_addr.is_ip4 ? "IPv4" : "IPv6", + format_ip46_address, + &session->peer_addr.ip46, session->peer_addr.is_ip4 ? + IP46_TYPE_IP4 : IP46_TYPE_IP6, + clib_net_to_host_u16 (session->peer_port), + session->proto ? "UDP" : "TCP", session->state, + vppcom_session_state_str (session->state)); VCL_SESSION_UNLOCK (); goto done; @@ -2936,16 +2495,15 @@ vppcom_session_connect (uint32_t session_index, vppcom_endpt_t * server_ep) sizeof (ip6_address_t)); session->peer_port = server_ep->port; - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: connecting to server " - "%s %U port %d proto %s", - getpid (), session->vpp_handle, session_index, - session->peer_addr.is_ip4 ? "IPv4" : "IPv6", - format_ip46_address, - &session->peer_addr.ip46, session->peer_addr.is_ip4 ? - IP46_TYPE_IP4 : IP46_TYPE_IP6, - clib_net_to_host_u16 (session->peer_port), - session->proto ? "UDP" : "TCP"); + VDBG (0, "VCL<%d>: vpp handle 0x%llx, sid %u: connecting to server %s %U " + "port %d proto %s", + getpid (), session->vpp_handle, session_index, + session->peer_addr.is_ip4 ? "IPv4" : "IPv6", + format_ip46_address, + &session->peer_addr.ip46, session->peer_addr.is_ip4 ? + IP46_TYPE_IP4 : IP46_TYPE_IP6, + clib_net_to_host_u16 (session->peer_port), + session->proto ? "UDP" : "TCP"); vppcom_send_connect_sock (session, session_index); VCL_SESSION_UNLOCK (); @@ -2965,19 +2523,18 @@ done: if (VPPCOM_DEBUG > 0) { if (session) - clib_warning - ("VCL<%d>: vpp handle 0x%llx, sid %u: connect failed! " - "returning %d (%s)", getpid (), vpp_handle, - session_index, rv, vppcom_retval_str (rv)); + clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: connect " + "failed! returning %d (%s)", getpid (), vpp_handle, + session_index, rv, vppcom_retval_str (rv)); else clib_warning ("VCL<%d>: no session for sid %u: connect failed! " "returning %d (%s)", getpid (), session_index, rv, vppcom_retval_str (rv)); } } - else if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: connected!", - getpid (), vpp_handle, session_index); + else + VDBG (0, "VCL<%d>: vpp handle 0x%llx, sid %u: connected!", + getpid (), vpp_handle, session_index); return rv; } @@ -3019,12 +2576,10 @@ vppcom_session_read_internal (uint32_t session_index, void *buf, int n, VCL_SESSION_UNLOCK (); rv = ((state & STATE_DISCONNECT) ? VPPCOM_ECONNRESET : VPPCOM_ENOTCONN); - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: %s session is " - "not open! state 0x%x (%s), returning %d (%s)", - getpid (), vpp_handle, session_index, state, - vppcom_session_state_str (state), - rv, vppcom_retval_str (rv)); + VDBG (0, "VCL<%d>: vpp handle 0x%llx, sid %u: %s session is not open! " + "state 0x%x (%s), returning %d (%s)", + getpid (), vpp_handle, session_index, state, + vppcom_session_state_str (state), rv, vppcom_retval_str (rv)); goto done; } @@ -3052,17 +2607,14 @@ vppcom_session_read_internal (uint32_t session_index, void *buf, int n, { rv = VPPCOM_ECONNRESET; - if (VPPCOM_DEBUG > 1) - { - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: Empty fifo " - "with session state 0x%x (%s)!" - " Setting state to 0x%x (%s), returning %d (%s)", - getpid (), session->vpp_handle, session_index, - state, vppcom_session_state_str (state), - STATE_DISCONNECT, - vppcom_session_state_str (STATE_DISCONNECT), rv, - vppcom_retval_str (rv)); - } + VDBG (1, "VCL<%d>: vpp handle 0x%llx, sid %u: Empty fifo with " + "session state 0x%x (%s)! Setting state to 0x%x (%s), " + "returning %d (%s)", + getpid (), session->vpp_handle, session_index, + state, vppcom_session_state_str (state), + STATE_DISCONNECT, + vppcom_session_state_str (STATE_DISCONNECT), rv, + vppcom_retval_str (rv)); session->state = STATE_DISCONNECT; } @@ -3132,12 +2684,11 @@ vppcom_session_read_ready (session_t * session, u32 session_index) rv = ((state & STATE_DISCONNECT) ? VPPCOM_ECONNRESET : VPPCOM_ENOTCONN); - if (VPPCOM_DEBUG > 1) - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: session is " - "not open! state 0x%x (%s), returning %d (%s)", - getpid (), vpp_handle, session_index, - state, vppcom_session_state_str (state), - rv, vppcom_retval_str (rv)); + VDBG (1, "VCL<%d>: vpp handle 0x%llx, sid %u: session is not open!" + " state 0x%x (%s), returning %d (%s)", + getpid (), vpp_handle, session_index, + state, vppcom_session_state_str (state), + rv, vppcom_retval_str (rv)); goto done; } @@ -3155,18 +2706,14 @@ vppcom_session_read_ready (session_t * session, u32 session_index) { rv = VPPCOM_ECONNRESET; - if (VPPCOM_DEBUG > 1) - { - clib_warning ("VCL<%d>: vpp handle 0x%llx, " - "sid %u: Empty fifo with" - " session state 0x%x (%s)! Setting state to " - "0x%x (%s), returning %d (%s)", - getpid (), session_index, vpp_handle, - state, vppcom_session_state_str (state), - STATE_DISCONNECT, - vppcom_session_state_str (STATE_DISCONNECT), rv, - vppcom_retval_str (rv)); - } + VDBG (1, "VCL<%d>: vpp handle 0x%llx, sid %u: Empty fifo with " + "session state 0x%x (%s)! Setting state to 0x%x (%s), " + "returning %d (%s)", + getpid (), session_index, vpp_handle, + state, vppcom_session_state_str (state), + STATE_DISCONNECT, + vppcom_session_state_str (STATE_DISCONNECT), rv, + vppcom_retval_str (rv)); session->state = STATE_DISCONNECT; goto done; } @@ -3227,11 +2774,10 @@ vppcom_session_write (uint32_t session_index, void *buf, size_t n) VPPCOM_ENOTCONN); VCL_SESSION_UNLOCK (); - if (VPPCOM_DEBUG > 1) - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: " - "session is not open! state 0x%x (%s)", - getpid (), vpp_handle, session_index, - state, vppcom_session_state_str (state)); + VDBG (1, "VCL<%d>: vpp handle 0x%llx, sid %u: session is not open! " + "state 0x%x (%s)", + getpid (), vpp_handle, session_index, + state, vppcom_session_state_str (state)); goto done; } @@ -3260,11 +2806,9 @@ vppcom_session_write (uint32_t session_index, void *buf, size_t n) ASSERT (q); svm_queue_add (q, (u8 *) & evt, 0 /* do wait for mutex */ ); VCL_SESSION_UNLOCK (); - if (VPPCOM_DEBUG > 1) - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: " - "added FIFO_EVENT_APP_TX to " - "vpp_event_q %p, n_write %d", getpid (), - vpp_handle, session_index, q, n_write); + VDBG (1, "VCL<%d>: vpp handle 0x%llx, sid %u: added FIFO_EVENT_APP_TX " + "to vpp_event_q %p, n_write %d", getpid (), + vpp_handle, session_index, q, n_write); } if (n_write <= 0) @@ -3280,18 +2824,15 @@ vppcom_session_write (uint32_t session_index, void *buf, size_t n) { rv = VPPCOM_ECONNRESET; - if (VPPCOM_DEBUG > 1) - { - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: " - "Empty fifo with session state 0x%x (%s)!" - " Setting state to 0x%x (%s), returning %d (%s)", - getpid (), session->vpp_handle, session_index, - session->state, - vppcom_session_state_str (session->state), - STATE_DISCONNECT, - vppcom_session_state_str (STATE_DISCONNECT), rv, - vppcom_retval_str (rv)); - } + VDBG (1, "VCL<%d>: vpp handle 0x%llx, sid %u: Empty fifo with " + "session state 0x%x (%s)! Setting state to 0x%x (%s), " + "returning %d (%s)", + getpid (), session->vpp_handle, session_index, + session->state, + vppcom_session_state_str (session->state), + STATE_DISCONNECT, + vppcom_session_state_str (STATE_DISCONNECT), rv, + vppcom_retval_str (rv)); session->state = STATE_DISCONNECT; } @@ -3363,11 +2904,9 @@ vppcom_session_write_ready (session_t * session, u32 session_index) ready = svm_fifo_max_enqueue (session->tx_fifo); - if (VPPCOM_DEBUG > 3) - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: " - "peek %s (%p), ready = %d", getpid (), - session->vpp_handle, session_index, - session->tx_fifo, ready); + VDBG (3, "VCL<%d>: vpp handle 0x%llx, sid %u: peek %s (%p), ready = %d", + getpid (), session->vpp_handle, session_index, session->tx_fifo, + ready); if (ready == 0) { @@ -3380,19 +2919,15 @@ vppcom_session_write_ready (session_t * session, u32 session_index) { rv = VPPCOM_ECONNRESET; - if (VPPCOM_DEBUG > 1) - { - clib_warning ("VCL<%d>: vpp handle 0x%llx, sid %u: " - "Empty fifo with session " - "state 0x%x (%s)! Setting state to 0x%x (%s), " - "returning %d (%s)", getpid (), - session->vpp_handle, session_index, - session->state, - vppcom_session_state_str (session->state), - STATE_DISCONNECT, - vppcom_session_state_str (STATE_DISCONNECT), rv, - vppcom_retval_str (rv)); - } + VDBG (1, "VCL<%d>: vpp handle 0x%llx, sid %u: Empty fifo with " + "session state 0x%x (%s)! Setting state to 0x%x (%s), " + "returning %d (%s)", getpid (), + session->vpp_handle, session_index, + session->state, + vppcom_session_state_str (session->state), + STATE_DISCONNECT, + vppcom_session_state_str (STATE_DISCONNECT), rv, + vppcom_retval_str (rv)); session->state = STATE_DISCONNECT; goto done; } @@ -3453,9 +2988,8 @@ vppcom_select (unsigned long n_bits, unsigned long *read_map, if (rv < 0) { VCL_SESSION_UNLOCK(); - if (VPPCOM_DEBUG > 1) - clib_warning ("VCL<%d>: session %d specified in " - "read_map is closed.", getpid (), + VDBG (1, "VCL<%d>: session %d specified in read_map is" + " closed.", getpid (), session_index); bits_set = VPPCOM_EBADFD; goto select_done; @@ -3510,8 +3044,7 @@ vppcom_select (unsigned long n_bits, unsigned long *read_map, if (rv < 0) { VCL_SESSION_UNLOCK(); - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: session %d specified in " + VDBG (0, "VCL<%d>: session %d specified in " "write_map is closed.", getpid (), session_index); bits_set = VPPCOM_EBADFD; @@ -3537,9 +3070,8 @@ vppcom_select (unsigned long n_bits, unsigned long *read_map, if (rv < 0) { VCL_SESSION_UNLOCK(); - if (VPPCOM_DEBUG > 1) - clib_warning ("VCL<%d>: session %d specified in " - "except_map is closed.", getpid (), + VDBG (1, "VCL<%d>: session %d specified in except_map " + "is closed.", getpid (), session_index); bits_set = VPPCOM_EBADFD; goto select_done; @@ -3651,7 +3183,6 @@ vppcom_epoll_create (void) { session_t *vep_session; u32 vep_idx; - elog_track_t vep_elog_track; VCL_SESSION_LOCK (); pool_get (vcm->sessions, vep_session); @@ -3666,40 +3197,11 @@ vppcom_epoll_create (void) vep_session->vpp_handle = ~0; vep_session->poll_reg = 0; - if (VPPCOM_DEBUG > 0) - { - vep_session->elog_track.name = - (char *) format (0, "C:%d:VEP:%d%c", vcm->my_client_index, - vep_idx, 0); - elog_track_register (&vcm->elog_main, &vep_session->elog_track); - vep_elog_track = vep_session->elog_track; - } - + vcl_evt (VCL_EVT_EPOLL_CREATE, vep_session, vep_idx); VCL_SESSION_UNLOCK (); - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: Created vep_idx %u / sid %u!", - getpid (), vep_idx, vep_idx); - - if (VPPCOM_DEBUG > 0) - { - - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "created epoll session:%d", - .format_args = "i4", - }; - - struct - { - u32 data; - } *ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, vep_elog_track); - ed->data = vep_idx; - /* *INDENT-ON* */ - } + VDBG (0, "VCL<%d>: Created vep_idx %u / sid %u!", + getpid (), vep_idx, vep_idx); return (vep_idx); } @@ -3740,9 +3242,8 @@ vppcom_epoll_ctl (uint32_t vep_idx, int op, uint32_t session_index, rv = vppcom_session_at_index (session_index, &session); if (PREDICT_FALSE (rv)) { - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: ERROR: Invalid session_index (%u)!", - getpid (), session_index); + VDBG (0, "VCL<%d>: ERROR: Invalid session_index (%u)!", + getpid (), session_index); goto done; } if (PREDICT_FALSE (session->is_vep)) @@ -3798,31 +3299,11 @@ vppcom_epoll_ctl (uint32_t vep_idx, int op, uint32_t session_index, vce_poll_wait_connect_request_handler_fn, 0 /* No callback args */ ); } - if (VPPCOM_DEBUG > 1) - clib_warning ("VCL<%d>: EPOLL_CTL_ADD: vep_idx %u, " - "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* */ - } + VDBG (1, "VCL<%d>: EPOLL_CTL_ADD: vep_idx %u, " + "sid %u, events 0x%x, data 0x%llx!", + getpid (), vep_idx, session_index, + event->events, event->data.u64); + vcl_evt (VCL_EVT_EPOLL_CTLADD, session, event->events, event->data.u64); break; case EPOLL_CTL_MOD: @@ -3851,11 +3332,9 @@ vppcom_epoll_ctl (uint32_t vep_idx, int op, uint32_t session_index, } session->vep.et_mask = VEP_DEFAULT_ET_MASK; session->vep.ev = *event; - if (VPPCOM_DEBUG > 1) - clib_warning - ("VCL<%d>: EPOLL_CTL_MOD: vep_idx %u, sid %u, events 0x%x," - " data 0x%llx!", getpid (), vep_idx, session_index, event->events, - event->data.u64); + VDBG (1, "VCL<%d>: EPOLL_CTL_MOD: vep_idx %u, sid %u, events 0x%x," + " data 0x%llx!", getpid (), vep_idx, session_index, event->events, + event->data.u64); break; case EPOLL_CTL_DEL: @@ -3923,27 +3402,9 @@ vppcom_epoll_ctl (uint32_t vep_idx, int op, uint32_t session_index, session->vep.prev_sid = ~0; session->vep.vep_idx = ~0; session->is_vep_session = 0; - 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* */ - } + VDBG (1, "VCL<%d>: EPOLL_CTL_DEL: vep_idx %u, sid %u!", + getpid (), vep_idx, session_index); + vcl_evt (VCL_EVT_EPOLL_CTLDEL, session, vep_idx); break; default: @@ -3963,7 +3424,6 @@ vppcom_epoll_wait (uint32_t vep_idx, struct epoll_event *events, int maxevents, double wait_for_time) { session_t *vep_session; - elog_track_t vep_elog_track; int rv; f64 timeout = clib_time_now (&vcm->clib_time) + wait_for_time; u32 keep_trying = 1; @@ -3983,7 +3443,6 @@ vppcom_epoll_wait (uint32_t vep_idx, struct epoll_event *events, vep_next_sid = vep_session->vep.next_sid; is_vep = vep_session->is_vep; wait_cont_idx = vep_session->wait_cont_idx; - vep_elog_track = vep_session->elog_track; VCL_SESSION_UNLOCK (); if (PREDICT_FALSE (!is_vep)) @@ -3995,27 +3454,8 @@ vppcom_epoll_wait (uint32_t vep_idx, struct epoll_event *events, } if (PREDICT_FALSE (vep_next_sid == ~0)) { - if (VPPCOM_DEBUG > 1) - clib_warning ("VCL<%d>: WARNING: vep_idx (%u) is empty!", - getpid (), vep_idx); - if (VPPCOM_DEBUG > 1) - { - /* *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_elog_track); - - ed->data = vep_idx; - /* *INDENT-ON* */ - } + VDBG (1, "VCL<%d>: WARNING: vep_idx (%u) is empty!", + getpid (), vep_idx); goto done; } @@ -4024,7 +3464,6 @@ vppcom_epoll_wait (uint32_t vep_idx, struct epoll_event *events, u32 sid; u32 next_sid = ~0; session_t *session; - elog_track_t session_elog_track; for (sid = (wait_cont_idx == ~0) ? vep_next_sid : wait_cont_idx; sid != ~0; sid = next_sid) @@ -4043,64 +3482,19 @@ vppcom_epoll_wait (uint32_t vep_idx, struct epoll_event *events, session_vep_idx = session->vep.vep_idx; session_ev_data = session->vep.ev.data.u64; - if (VPPCOM_DEBUG > 0) - { - session_elog_track = session->elog_track; - } - VCL_SESSION_UNLOCK (); if (PREDICT_FALSE (is_vep)) { - 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* */ - } - + VDBG (0, "VCL<%d>: ERROR: sid (%u) is a vep!", + getpid (), vep_idx); rv = VPPCOM_EINVAL; goto done; } if (PREDICT_FALSE (!is_vep_session)) { - 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* */ - } - + VDBG (0, "VCL<%d>: ERROR: session (%u) is not " + "a vep session!", getpid (), sid); rv = VPPCOM_EINVAL; goto done; } @@ -4231,53 +3625,14 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, { case VPPCOM_ATTR_GET_NREAD: rv = vppcom_session_read_ready (session, session_index); - 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* */ - } - + VDBG (2, "VCL<%d>: VPPCOM_ATTR_GET_NREAD: sid %u, nread = %d", + getpid (), rv); break; case VPPCOM_ATTR_GET_NWRITE: rv = vppcom_session_write_ready (session, session_index); - 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* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_GET_NWRITE: sid %u, nwrite = %d", + getpid (), session_index, rv); break; case VPPCOM_ATTR_GET_FLAGS: @@ -4286,33 +3641,10 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, *flags = O_RDWR | (VCL_SESS_ATTR_TEST (session->attr, VCL_SESS_ATTR_NONBLOCK)); *buflen = sizeof (*flags); - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_GET_FLAGS: sid %u, " - "flags = 0x%08x, is_nonblocking = %u", getpid (), - session_index, *flags, - VCL_SESS_ATTR_TEST (session->attr, - VCL_SESS_ATTR_NONBLOCK)); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_GET_FLAGS: flags=%x is_nonblk=%d", - .format_args = "i4i4", - }; - struct - { - u32 flags; - u32 is_nonblk; - } *ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - - ed->flags = *flags; - ed->is_nonblk = VCL_SESS_ATTR_TEST (session->attr, VCL_SESS_ATTR_NONBLOCK); - /* *INDENT-ON* */ - } - + VDBG (2, "VCL<%d>: VPPCOM_ATTR_GET_FLAGS: sid %u, flags = 0x%08x, " + "is_nonblocking = %u", getpid (), + session_index, *flags, + VCL_SESS_ATTR_TEST (session->attr, VCL_SESS_ATTR_NONBLOCK)); } else rv = VPPCOM_EINVAL; @@ -4326,32 +3658,10 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, else VCL_SESS_ATTR_CLR (session->attr, VCL_SESS_ATTR_NONBLOCK); - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_SET_FLAGS: sid %u, " - "flags = 0x%08x, is_nonblocking = %u", - getpid (), session_index, *flags, - VCL_SESS_ATTR_TEST (session->attr, - VCL_SESS_ATTR_NONBLOCK)); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_SET_FLAGS: flags=%x is_nonblk=%d", - .format_args = "i4i4", - }; - struct - { - u32 flags; - u32 is_nonblk; - } *ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - - ed->flags = *flags; - ed->is_nonblk = VCL_SESS_ATTR_TEST (session->attr, VCL_SESS_ATTR_NONBLOCK); - /* *INDENT-ON* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_SET_FLAGS: sid %u, flags = 0x%08x," + " is_nonblocking = %u", + getpid (), session_index, *flags, + VCL_SESS_ATTR_TEST (session->attr, VCL_SESS_ATTR_NONBLOCK)); } else rv = VPPCOM_EINVAL; @@ -4370,55 +3680,12 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, clib_memcpy (ep->ip, &session->peer_addr.ip46.ip6, sizeof (ip6_address_t)); *buflen = sizeof (*ep); - if (VPPCOM_DEBUG > 1) - clib_warning ("VCL<%d>: VPPCOM_ATTR_GET_PEER_ADDR: sid %u, " - "is_ip4 = %u, addr = %U, port %u", getpid (), - session_index, ep->is_ip4, format_ip46_address, - &session->peer_addr.ip46, - ep->is_ip4 ? IP46_TYPE_IP4 : IP46_TYPE_IP6, - 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* */ - } - } + VDBG (1, "VCL<%d>: VPPCOM_ATTR_GET_PEER_ADDR: sid %u, is_ip4 = %u, " + "addr = %U, port %u", getpid (), + session_index, ep->is_ip4, format_ip46_address, + &session->peer_addr.ip46, + ep->is_ip4 ? IP46_TYPE_IP4 : IP46_TYPE_IP6, + clib_net_to_host_u16 (ep->port)); } else rv = VPPCOM_EINVAL; @@ -4437,55 +3704,12 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, clib_memcpy (ep->ip, &session->lcl_addr.ip46.ip6, sizeof (ip6_address_t)); *buflen = sizeof (*ep); - if (VPPCOM_DEBUG > 1) - clib_warning ("VCL<%d>: VPPCOM_ATTR_GET_LCL_ADDR: sid %u, " - "is_ip4 = %u, addr = %U port %d", getpid (), - session_index, ep->is_ip4, format_ip46_address, - &session->lcl_addr.ip46, - ep->is_ip4 ? IP46_TYPE_IP4 : IP46_TYPE_IP6, - 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* */ - } - } + VDBG (1, "VCL<%d>: VPPCOM_ATTR_GET_LCL_ADDR: sid %u, is_ip4 = %u," + " addr = %U port %d", getpid (), + session_index, ep->is_ip4, format_ip46_address, + &session->lcl_addr.ip46, + ep->is_ip4 ? IP46_TYPE_IP4 : IP46_TYPE_IP6, + clib_net_to_host_u16 (ep->port)); } else rv = VPPCOM_EINVAL; @@ -4493,26 +3717,8 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, case VPPCOM_ATTR_GET_LIBC_EPFD: rv = session->libc_epfd; - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_GET_LIBC_EPFD: libc_epfd %d", - getpid (), rv); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_GET_LIBC_EPFD: libc_epfd=%d", - .format_args = "i4", - }; - CLIB_PACKED (struct { - i32 data; - }) *ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->data = session->libc_epfd; - /* *INDENT-ON* */ - } - + VDBG (2, "VCL<%d>: VPPCOM_ATTR_GET_LIBC_EPFD: libc_epfd %d", + getpid (), rv); break; case VPPCOM_ATTR_SET_LIBC_EPFD: @@ -4522,32 +3728,8 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, session->libc_epfd = *(int *) buffer; *buflen = sizeof (session->libc_epfd); - if (VPPCOM_DEBUG > 2) - 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* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_SET_LIBC_EPFD: libc_epfd %d, " + "buflen %d", getpid (), session->libc_epfd, *buflen); } else rv = VPPCOM_EINVAL; @@ -4559,31 +3741,9 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, *(int *) buffer = session->proto; *buflen = sizeof (int); - if (VPPCOM_DEBUG > 2) - 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* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_GET_PROTOCOL: %d (%s), buflen %d", + getpid (), *(int *) buffer, *(int *) buffer ? "UDP" : "TCP", + *buflen); } else rv = VPPCOM_EINVAL; @@ -4596,27 +3756,8 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, VCL_SESS_ATTR_LISTEN); *buflen = sizeof (int); - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_GET_LISTEN: %d, " - "buflen %d", getpid (), *(int *) buffer, *buflen); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_GET_LISTEN: %d buflen=%d", - .format_args = "i4i4", - }; - - struct { - u32 data[2]; - } * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->data[0] = *(int *) buffer; - ed->data[1] = *buflen; - /* *INDENT-ON* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_GET_LISTEN: %d, buflen %d", + getpid (), *(int *) buffer, *buflen); } else rv = VPPCOM_EINVAL; @@ -4628,28 +3769,8 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, *(int *) buffer = 0; *buflen = sizeof (int); - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_GET_ERROR: %d, " - "buflen %d, #VPP-TBD#", getpid (), - *(int *) buffer, *buflen); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_GET_ERROR: %d buflen=%d", - .format_args = "i4i4", - }; - - struct { - u32 data[2]; - } * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->data[0] = *(int *) buffer; - ed->data[1] = *buflen; - /* *INDENT-ON* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_GET_ERROR: %d, buflen %d, #VPP-TBD#", + getpid (), *(int *) buffer, *buflen); } else rv = VPPCOM_EINVAL; @@ -4665,28 +3786,9 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, vcm->cfg.tx_fifo_size); *buflen = sizeof (u32); - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_GET_TX_FIFO_LEN: %u (0x%x), " - "buflen %d, #VPP-TBD#", getpid (), - *(size_t *) buffer, *(size_t *) buffer, *buflen); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_GET_TX_FIFO_LEN: 0x%x buflen=%d", - .format_args = "i4i4", - }; - - struct { - u32 data[2]; - } * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->data[0] = *(size_t *) buffer; - ed->data[1] = *buflen; - /* *INDENT-ON* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_GET_TX_FIFO_LEN: %u (0x%x), " + "buflen %d, #VPP-TBD#", getpid (), + *(size_t *) buffer, *(size_t *) buffer, *buflen); } else rv = VPPCOM_EINVAL; @@ -4697,29 +3799,9 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, { /* VPP-TBD */ session->sndbuf_size = *(u32 *) buffer; - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_SET_TX_FIFO_LEN: %u (0x%x), " - "buflen %d, #VPP-TBD#", getpid (), - session->sndbuf_size, session->sndbuf_size, - *buflen); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_SET_TX_FIFO_LEN: 0x%x buflen=%d", - .format_args = "i4i4", - }; - - struct { - u32 data[2]; - } * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->data[0] = session->sndbuf_size; - ed->data[1] = *buflen; - /* *INDENT-ON* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_SET_TX_FIFO_LEN: %u (0x%x), " + "buflen %d, #VPP-TBD#", getpid (), + session->sndbuf_size, session->sndbuf_size, *buflen); } else rv = VPPCOM_EINVAL; @@ -4735,28 +3817,9 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, vcm->cfg.rx_fifo_size); *buflen = sizeof (u32); - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_GET_RX_FIFO_LEN: %u (0x%x), " - "buflen %d, #VPP-TBD#", getpid (), - *(size_t *) buffer, *(size_t *) buffer, *buflen); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_GET_RX_FIFO_LEN: 0x%x buflen=%d", - .format_args = "i4i4", - }; - - struct { - u32 data[2]; - } * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->data[0] = *(size_t *) buffer; - ed->data[1] = *buflen; - /* *INDENT-ON* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_GET_RX_FIFO_LEN: %u (0x%x), " + "buflen %d, #VPP-TBD#", getpid (), + *(size_t *) buffer, *(size_t *) buffer, *buflen); } else rv = VPPCOM_EINVAL; @@ -4767,29 +3830,9 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, { /* VPP-TBD */ session->rcvbuf_size = *(u32 *) buffer; - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_SET_RX_FIFO_LEN: %u (0x%x), " - "buflen %d, #VPP-TBD#", getpid (), - session->sndbuf_size, session->sndbuf_size, - *buflen); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_SET_RX_FIFO_LEN: 0x%x buflen=%d", - .format_args = "i4i4", - }; - - struct { - u32 data[2]; - } * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->data[0] = session->sndbuf_size; - ed->data[1] = *buflen; - /* *INDENT-ON* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_SET_RX_FIFO_LEN: %u (0x%x), " + "buflen %d, #VPP-TBD#", getpid (), + session->sndbuf_size, session->sndbuf_size, *buflen); } else rv = VPPCOM_EINVAL; @@ -4803,28 +3846,8 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, VCL_SESS_ATTR_REUSEADDR); *buflen = sizeof (int); - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_GET_REUSEADDR: %d, " - "buflen %d, #VPP-TBD#", getpid (), *(int *) buffer, - *buflen); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_GET_REUSEADDR: %d buflen=%d", - .format_args = "i4i4", - }; - - struct { - u32 data[2]; - } * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->data[0] = *(int *) buffer; - ed->data[1] = *buflen; - /* *INDENT-ON* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_GET_REUSEADDR: %d, " + "buflen %d, #VPP-TBD#", getpid (), *(int *) buffer, *buflen); } else rv = VPPCOM_EINVAL; @@ -4840,31 +3863,10 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, else VCL_SESS_ATTR_CLR (session->attr, VCL_SESS_ATTR_REUSEADDR); - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_SET_REUSEADDR: %d, " - "buflen %d, #VPP-TBD#", getpid (), - VCL_SESS_ATTR_TEST (session->attr, - VCL_SESS_ATTR_REUSEADDR), - *buflen); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_SET_REUSEADDR: %d buflen=%d", - .format_args = "i4i4", - }; - - struct { - u32 data[2]; - } * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->data[0] = VCL_SESS_ATTR_TEST (session->attr, - VCL_SESS_ATTR_REUSEADDR); - ed->data[1] = *buflen; - /* *INDENT-ON* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_SET_REUSEADDR: %d, buflen %d," + " #VPP-TBD#", getpid (), + VCL_SESS_ATTR_TEST (session->attr, + VCL_SESS_ATTR_REUSEADDR), *buflen); } else rv = VPPCOM_EINVAL; @@ -4878,28 +3880,8 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, VCL_SESS_ATTR_REUSEPORT); *buflen = sizeof (int); - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_GET_REUSEPORT: %d, " - "buflen %d, #VPP-TBD#", getpid (), *(int *) buffer, - *buflen); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_GET_REUSEPORT: %d buflen=%d", - .format_args = "i4i4", - }; - - struct { - u32 data[2]; - } * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->data[0] = *(int *) buffer; - ed->data[1] = *buflen; - /* *INDENT-ON* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_GET_REUSEPORT: %d, buflen %d," + " #VPP-TBD#", getpid (), *(int *) buffer, *buflen); } else rv = VPPCOM_EINVAL; @@ -4915,31 +3897,10 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, else VCL_SESS_ATTR_CLR (session->attr, VCL_SESS_ATTR_REUSEPORT); - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_SET_REUSEPORT: %d, " - "buflen %d, #VPP-TBD#", getpid (), - VCL_SESS_ATTR_TEST (session->attr, - VCL_SESS_ATTR_REUSEPORT), - *buflen); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_SET_REUSEPORT: %d buflen=%d", - .format_args = "i4i4", - }; - - struct { - u32 data[2]; - } * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->data[0] = VCL_SESS_ATTR_TEST (session->attr, - VCL_SESS_ATTR_REUSEPORT); - ed->data[1] = *buflen; - /* *INDENT-ON* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_SET_REUSEPORT: %d, buflen %d," + " #VPP-TBD#", getpid (), + VCL_SESS_ATTR_TEST (session->attr, + VCL_SESS_ATTR_REUSEPORT), *buflen); } else rv = VPPCOM_EINVAL; @@ -4953,28 +3914,8 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, VCL_SESS_ATTR_BROADCAST); *buflen = sizeof (int); - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_GET_BROADCAST: %d, " - "buflen %d, #VPP-TBD#", getpid (), *(int *) buffer, - *buflen); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_GET_BROADCAST: %d buflen=%d", - .format_args = "i4i4", - }; - - struct { - u32 data[2]; - } * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->data[0] = *(int *) buffer; - ed->data[1] = *buflen; - /* *INDENT-ON* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_GET_BROADCAST: %d, buflen %d," + " #VPP-TBD#", getpid (), *(int *) buffer, *buflen); } else rv = VPPCOM_EINVAL; @@ -4989,31 +3930,10 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, else VCL_SESS_ATTR_CLR (session->attr, VCL_SESS_ATTR_BROADCAST); - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_SET_BROADCAST: %d, " - "buflen %d, #VPP-TBD#", getpid (), - VCL_SESS_ATTR_TEST (session->attr, - VCL_SESS_ATTR_BROADCAST), - *buflen); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_SET_BROADCAST: %d buflen=%d", - .format_args = "i4i4", - }; - - struct { - u32 data[2]; - } * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->data[0] = VCL_SESS_ATTR_TEST (session->attr, - VCL_SESS_ATTR_BROADCAST); - ed->data[1] = *buflen; - /* *INDENT-ON* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_SET_BROADCAST: %d, buflen %d, " + "#VPP-TBD#", getpid (), + VCL_SESS_ATTR_TEST (session->attr, + VCL_SESS_ATTR_BROADCAST), *buflen); } else rv = VPPCOM_EINVAL; @@ -5027,28 +3947,8 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, VCL_SESS_ATTR_V6ONLY); *buflen = sizeof (int); - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_GET_V6ONLY: %d, " - "buflen %d, #VPP-TBD#", getpid (), *(int *) buffer, - *buflen); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_GET_V6ONLY: %d buflen=%d", - .format_args = "i4i4", - }; - - struct { - u32 data[2]; - } * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->data[0] = *(int *) buffer; - ed->data[1] = *buflen; - /* *INDENT-ON* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_GET_V6ONLY: %d, buflen %d, " + "#VPP-TBD#", getpid (), *(int *) buffer, *buflen); } else rv = VPPCOM_EINVAL; @@ -5063,30 +3963,10 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, else VCL_SESS_ATTR_CLR (session->attr, VCL_SESS_ATTR_V6ONLY); - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_SET_V6ONLY: %d, " - "buflen %d, #VPP-TBD#", getpid (), - VCL_SESS_ATTR_TEST (session->attr, - VCL_SESS_ATTR_V6ONLY), *buflen); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_SET_V6ONLY: %d buflen=%d", - .format_args = "i4i4", - }; - - struct { - u32 data[2]; - } * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->data[0] = VCL_SESS_ATTR_TEST (session->attr, - VCL_SESS_ATTR_V6ONLY); - ed->data[1] = *buflen; - /* *INDENT-ON* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_SET_V6ONLY: %d, buflen %d, " + "#VPP-TBD#", getpid (), + VCL_SESS_ATTR_TEST (session->attr, + VCL_SESS_ATTR_V6ONLY), *buflen); } else rv = VPPCOM_EINVAL; @@ -5100,28 +3980,8 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, VCL_SESS_ATTR_KEEPALIVE); *buflen = sizeof (int); - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_GET_KEEPALIVE: %d, " - "buflen %d, #VPP-TBD#", getpid (), *(int *) buffer, - *buflen); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_GET_KEEPALIVE: %d buflen=%d", - .format_args = "i4i4", - }; - - struct { - u32 data[2]; - } * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->data[0] = *(int *) buffer; - ed->data[1] = *buflen; - /* *INDENT-ON* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_GET_KEEPALIVE: %d, buflen %d, " + "#VPP-TBD#", getpid (), *(int *) buffer, *buflen); } else rv = VPPCOM_EINVAL; @@ -5136,31 +3996,10 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, else VCL_SESS_ATTR_CLR (session->attr, VCL_SESS_ATTR_KEEPALIVE); - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_SET_KEEPALIVE: %d, " - "buflen %d, #VPP-TBD#", getpid (), - VCL_SESS_ATTR_TEST (session->attr, - VCL_SESS_ATTR_KEEPALIVE), - *buflen); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_SET_KEEPALIVE: %d buflen=%d", - .format_args = "i4i4", - }; - - struct { - u32 data[2]; - } * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->data[0] = VCL_SESS_ATTR_TEST (session->attr, - VCL_SESS_ATTR_KEEPALIVE); - ed->data[1] = *buflen; - /* *INDENT-ON* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_SET_KEEPALIVE: %d, buflen %d, " + "#VPP-TBD#", getpid (), + VCL_SESS_ATTR_TEST (session->attr, + VCL_SESS_ATTR_KEEPALIVE), *buflen); } else rv = VPPCOM_EINVAL; @@ -5174,28 +4013,8 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, VCL_SESS_ATTR_TCP_NODELAY); *buflen = sizeof (int); - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_GET_TCP_NODELAY: %d, " - "buflen %d, #VPP-TBD#", getpid (), *(int *) buffer, - *buflen); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_GET_TCP_NODELAY: %d buflen=%d", - .format_args = "i4i4", - }; - - struct { - u32 data[2]; - } * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->data[0] = *(int *) buffer; - ed->data[1] = *buflen; - /* *INDENT-ON* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_GET_TCP_NODELAY: %d, buflen %d, " + "#VPP-TBD#", getpid (), *(int *) buffer, *buflen); } else rv = VPPCOM_EINVAL; @@ -5210,31 +4029,10 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, else VCL_SESS_ATTR_CLR (session->attr, VCL_SESS_ATTR_TCP_NODELAY); - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_SET_TCP_NODELAY: %d, " - "buflen %d, #VPP-TBD#", getpid (), - VCL_SESS_ATTR_TEST (session->attr, - VCL_SESS_ATTR_TCP_NODELAY), - *buflen); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_SET_TCP_NODELAY: %d buflen=%d", - .format_args = "i4i4", - }; - - struct { - u32 data[2]; - } * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->data[0] = VCL_SESS_ATTR_TEST (session->attr, - VCL_SESS_ATTR_TCP_NODELAY); - ed->data[1] = *buflen; - /* *INDENT-ON* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_SET_TCP_NODELAY: %d, buflen %d, " + "#VPP-TBD#", getpid (), + VCL_SESS_ATTR_TEST (session->attr, + VCL_SESS_ATTR_TCP_NODELAY), *buflen); } else rv = VPPCOM_EINVAL; @@ -5248,28 +4046,8 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, VCL_SESS_ATTR_TCP_KEEPIDLE); *buflen = sizeof (int); - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_GET_TCP_KEEPIDLE: %d, " - "buflen %d, #VPP-TBD#", getpid (), *(int *) buffer, - *buflen); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_GET_TCP_KEEPIDLE: %d buflen=%d", - .format_args = "i4i4", - }; - - struct { - u32 data[2]; - } * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->data[0] = *(int *) buffer; - ed->data[1] = *buflen; - /* *INDENT-ON* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_GET_TCP_KEEPIDLE: %d, buflen %d, " + "#VPP-TBD#", getpid (), *(int *) buffer, *buflen); } else rv = VPPCOM_EINVAL; @@ -5284,31 +4062,10 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, else VCL_SESS_ATTR_CLR (session->attr, VCL_SESS_ATTR_TCP_KEEPIDLE); - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_SET_TCP_KEEPIDLE: %d, " - "buflen %d, #VPP-TBD#", getpid (), - VCL_SESS_ATTR_TEST (session->attr, - VCL_SESS_ATTR_TCP_KEEPIDLE), - *buflen); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_SET_TCP_KEEPIDLE: %d buflen=%d", - .format_args = "i4i4", - }; - - struct { - u32 data[2]; - } * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->data[0] = VCL_SESS_ATTR_TEST (session->attr, - VCL_SESS_ATTR_TCP_KEEPIDLE); - ed->data[1] = *buflen; - /* *INDENT-ON* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_SET_TCP_KEEPIDLE: %d, buflen %d, " + "#VPP-TBD#", getpid (), + VCL_SESS_ATTR_TEST (session->attr, + VCL_SESS_ATTR_TCP_KEEPIDLE), *buflen); } else rv = VPPCOM_EINVAL; @@ -5322,28 +4079,8 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, VCL_SESS_ATTR_TCP_KEEPINTVL); *buflen = sizeof (int); - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_GET_TCP_KEEPINTVL: %d, " - "buflen %d, #VPP-TBD#", getpid (), *(int *) buffer, - *buflen); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_GET_TCP_KEEPIDLE: %d buflen=%d", - .format_args = "i4i4", - }; - - struct { - u32 data[2]; - } * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->data[0] = *(int *) buffer; - ed->data[1] = *buflen; - /* *INDENT-ON* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_GET_TCP_KEEPINTVL: %d, buflen %d, " + "#VPP-TBD#", getpid (), *(int *) buffer, *buflen); } else rv = VPPCOM_EINVAL; @@ -5358,31 +4095,10 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, else VCL_SESS_ATTR_CLR (session->attr, VCL_SESS_ATTR_TCP_KEEPINTVL); - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_SET_TCP_KEEPINTVL: %d, " - "buflen %d, #VPP-TBD#", getpid (), - VCL_SESS_ATTR_TEST (session->attr, - VCL_SESS_ATTR_TCP_KEEPINTVL), - *buflen); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_SET_TCP_KEEPINTVL: %d buflen=%d", - .format_args = "i4i4", - }; - - struct { - u32 data[2]; - } * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->data[0] = VCL_SESS_ATTR_TEST (session->attr, - VCL_SESS_ATTR_TCP_KEEPINTVL); - ed->data[1] = *buflen; - /* *INDENT-ON* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_SET_TCP_KEEPINTVL: %d, buflen %d, " + "#VPP-TBD#", getpid (), + VCL_SESS_ATTR_TEST (session->attr, + VCL_SESS_ATTR_TCP_KEEPINTVL), *buflen); } else rv = VPPCOM_EINVAL; @@ -5395,28 +4111,8 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, *(u32 *) buffer = session->user_mss; *buflen = sizeof (int); - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_GET_TCP_USER_MSS: %d, " - "buflen %d, #VPP-TBD#", getpid (), *(int *) buffer, - *buflen); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_GET_TCP_USER_MSS: %d buflen=%d", - .format_args = "i4i4", - }; - - struct { - u32 data[2]; - } * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->data[0] = *(int *) buffer; - ed->data[1] = *buflen; - /* *INDENT-ON* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_GET_TCP_USER_MSS: %d, buflen %d," + " #VPP-TBD#", getpid (), *(int *) buffer, *buflen); } else rv = VPPCOM_EINVAL; @@ -5428,28 +4124,8 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, /* VPP-TBD */ session->user_mss = *(u32 *) buffer; - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: VPPCOM_ATTR_SET_TCP_USER_MSS: %u, " - "buflen %d, #VPP-TBD#", getpid (), - session->user_mss, *buflen); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "VPPCOM_ATTR_SET_TCP_USER_MSS: %d buflen=%d", - .format_args = "i4i4", - }; - - struct { - u32 data[2]; - } * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); - ed->data[0] = session->user_mss; - ed->data[1] = *buflen; - /* *INDENT-ON* */ - } + VDBG (2, "VCL<%d>: VPPCOM_ATTR_SET_TCP_USER_MSS: %u, buflen %d, " + "#VPP-TBD#", getpid (), session->user_mss, *buflen); } else rv = VPPCOM_EINVAL; @@ -5479,27 +4155,8 @@ vppcom_session_recvfrom (uint32_t session_index, void *buffer, if (PREDICT_FALSE (rv)) { VCL_SESSION_UNLOCK (); - if (VPPCOM_DEBUG > 0) - clib_warning ("VCL<%d>: invalid session, " - "sid (%u) has been closed!", - getpid (), session_index); - if (VPPCOM_DEBUG > 0) - { - /* *INDENT-OFF* */ - ELOG_TYPE_DECLARE (e) = - { - .format = "invalid session: %d closed", - .format_args = "i4", - }; - - struct { - u32 data; - } * ed; - - ed = ELOG_TRACK_DATA (&vcm->elog_main, e, vcm->elog_track); - ed->data = session_index; - /* *INDENT-ON* */ - } + VDBG (0, "VCL<%d>: invalid session, sid (%u) has been closed!", + getpid (), session_index); rv = VPPCOM_EBADFD; VCL_SESSION_UNLOCK (); goto done; @@ -5546,9 +4203,8 @@ vppcom_session_sendto (uint32_t session_index, void *buffer, if (flags) { // TBD check the flags and do the right thing - if (VPPCOM_DEBUG > 2) - clib_warning ("VCL<%d>: handling flags 0x%u (%d) " - "not implemented yet.", getpid (), flags, flags); + VDBG (2, "VCL<%d>: handling flags 0x%u (%d) not implemented yet.", + getpid (), flags, flags); } return (vppcom_session_write (session_index, buffer, buflen)); @@ -5561,9 +4217,8 @@ vppcom_poll (vcl_poll_t * vp, uint32_t n_sids, double wait_for_time) u32 i, keep_trying = 1; int rv, num_ev = 0; - if (VPPCOM_DEBUG > 3) - clib_warning ("VCL<%d>: vp %p, nsids %u, wait_for_time %f", - getpid (), vp, n_sids, wait_for_time); + VDBG (3, "VCL<%d>: vp %p, nsids %u, wait_for_time %f", + getpid (), vp, n_sids, wait_for_time); if (!vp) return VPPCOM_EFAULT; |