2 *------------------------------------------------------------------
3 * spp_platform_trace_log.c
5 * Copyright (c) 2008-2011, 2013 Cisco and/or its affiliates.
6 * Licensed under the Apache License, Version 2.0 (the "License");
7 * you may not use this file except in compliance with the License.
8 * You may obtain a copy of the License at:
10 * http://www.apache.org/licenses/LICENSE-2.0
12 * Unless required by applicable law or agreed to in writing, software
13 * distributed under the License is distributed on an "AS IS" BASIS,
14 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
15 * See the License for the specific language governing permissions and
16 * limitations under the License.
17 *---------------------------------------------------------------------------
20 #include <vlib/vlib.h>
22 #include <vppinfra/vec.h>
23 #include <vppinfra/bitmap.h>
24 #include <vppinfra/hash.h>
25 #include <vppinfra/pool.h>
26 #include <vppinfra/clib.h>
27 #include <vlib/main.h>
29 #include "tcp_header_definitions.h"
30 #include "platform_common.h"
31 #include "spp_platform_trace_log.h"
33 #define WORD_SIZE sizeof(u32)
35 int temperature_read_blocked = 1;
37 spp_cnat_logger_tbl_t spp_cnat_logger_table[] =
46 { CNAT_NO_CONFIG_ERROR,
53 { CNAT_NO_VRF_RUN_ERROR,
60 { CNAT_NO_POOL_FOR_ANY_ERROR,
67 { CNAT_NO_PORT_FOR_ANY_ERROR,
74 { CNAT_BAD_INUSE_ANY_ERROR,
81 { CNAT_NOT_FOUND_ANY_ERROR,
88 { CNAT_INV_PORT_FOR_DIRECT_ERROR,
95 { CNAT_BAD_INUSE_DIRECT_ERROR,
102 { CNAT_NOT_FOUND_DIRECT_ERROR,
109 { CNAT_OUT_OF_PORT_LIMIT_ERROR,
116 { CNAT_MAIN_DB_CREATE_ERROR,
126 { CNAT_INDEX_MISMATCH_ERROR,
132 { CNAT_PACKET_DROP_ERROR,
139 { CNAT_INV_UNUSED_USR_INDEX,
142 {"invalid/unused user index"}
144 { CNAT_INVALID_VRFMAP_INDEX,
149 { CNAT_USER_OUT_OF_PORTS,
155 { CNAT_EXT_PORT_THRESH_EXCEEDED,
161 { CNAT_EXT_PORT_THRESH_NORMAL,
167 { CNAT_NO_EXT_PORT_AVAILABLE,
172 { CNAT_SESSION_THRESH_EXCEEDED,
178 { CNAT_SESSION_THRESH_NORMAL,
180 30, /* changed to 30 */
184 { WQE_ALLOCATION_ERROR,
186 180, /* changed to 180 */
191 60, /* changed to 60 */
195 { SYSMGR_PD_KEY_CREATION_ERROR,
200 { SYSMGR_PD_SHMEM_ID_ERROR,
205 { SYSMGR_PD_SHMEM_ATTACH_ERROR,
210 { OCTEON_CKHUM_SKIPPED,
212 60, /* changed to 60 */
226 { SPP_CTX_ALLOC_FAILED,
228 300, /* every 5 min */
231 { SPP_MAX_DISPATCH_REACHED,
248 { HA_INVALID_SEQ_OR_CONFIG_OR_TYPE,
251 {"seq-id or config option",
254 { NODE_CREATION_ERROR,
260 { CNAT_CLI_INVALID_INPUT,
268 { CNAT_DUMMY_HANDLER_HIT,
284 180, /* changed to 180 */
287 { CNAT_CMVX_TWSI_READ_WRITE_FAIL,
294 { CNAT_TEMP_SENSOR_TIMEOUT,
299 { CNAT_TEMP_SENSOR_DATA_MISMATCH,
305 { CNAT_TEMP_SENSOR_CONFIG_FAILED,
310 { HA_APP_NOT_RESPONDING,
316 { HA_DATA_PATH_TEST_FAILED,
321 { CNAT_WRONG_PORT_ALLOC_TYPE,
328 { CNAT_NEW_PORT_ALLOC_ERROR,
335 { CNAT_INVALID_INDEX_TO_FREE_PORT,
340 { CNAT_DELETE_DB_ENTRY_NO_PORTMAP,
345 { CNAT_MAIN_DB_LIMIT_ERROR,
350 { CNAT_USER_DB_LIMIT_ERROR,
355 { CNAT_FRAG_DB_ERROR,
368 #define LOG_TABLE_MAX_ENTRIES \
369 (sizeof(spp_cnat_logger_table)/sizeof(spp_cnat_logger_table[0]))
371 u32 error_code_timestamps[LOG_TABLE_MAX_ENTRIES];
372 spp_timer_t sensor_timer;
373 spp_trace_log_global_info_t spp_trace_log_global_info;
374 spp_global_counters_t spp_global_counters;
377 * Logging information structures
379 spp_trace_log_info_t spp_default_trace_log_info;
380 spp_trace_log_info_t *spp_trace_log_info_pool;
384 * The following 2 functions are temporary hacks until
385 * we have RTC support from the PD nodes
388 u32 spp_trace_log_get_sys_up_time_in_ms (void)
390 spp_node_main_vector_t *nmv;
393 nmv = spp_get_node_main_vectorized_inline();
395 sys_up_time = (u32) (nmv->ticks / nmv->ticks_per_ms);
397 return (sys_up_time);
401 u32 spp_trace_log_get_unix_time_in_seconds (void)
403 spp_node_main_vector_t *nmv;
406 nmv = spp_get_node_main_vectorized_inline();
408 unix_time = (u32) (nmv->ticks / nmv->ticks_per_second);
414 * edt: * * spp_trace_log_send_queued_pkt
416 * Tries to send a logging pkt that has been queued earlier
417 * because it could not be sent due to downstream constipation
419 * Argument: spp_trace_log_info_t *trace_logging_info
420 * structure that contains the packet context
423 void spp_trace_log_send_queued_pkt (spp_trace_log_info_t *trace_logging_info)
425 spp_node_t *output_node;
427 output_node = spp_get_nodes() +
428 spp_trace_log_global_info.spp_trace_log_disp_node_index;
430 if (PREDICT_TRUE(output_node->sf.nused < SPP_MAXDISPATCH)) {
432 * Move the logging context to output node
434 spp_dispatch_make_node_runnable(output_node);
435 output_node->sf.ctxs[output_node->sf.nused++] =
436 trace_logging_info->queued_logging_context;
439 * Context has been queued, it will be freed after the pkt
440 * is sent. Clear this from the logging_context_info structure
442 trace_logging_info->queued_logging_context = NULL;
446 * Can't do much, just return, may be we can send it later
448 spp_global_counters.spp_trace_log_downstream_constipation_count++;
453 * edt: * * spp_trace_log_send_pkt
455 * Tries to send a logging pkt. If the packet cannot be sent
456 * because of rewrite_output node cannot process it, queue
457 * it temporarily and try to send it later.
459 * Argument: spp_trace_log_info_t *trace_logging_info
460 * structure that contains the packet context
463 void spp_trace_log_send_pkt (spp_trace_log_info_t *trace_logging_info)
465 spp_node_t *output_node;
468 output_node = spp_get_nodes() +
469 spp_trace_log_global_info.spp_trace_log_disp_node_index;
471 if (PREDICT_TRUE(output_node->sf.nused < SPP_MAXDISPATCH)) {
473 * Move the logging context to output node
475 spp_dispatch_make_node_runnable(output_node);
476 output_node->sf.ctxs[output_node->sf.nused++] =
477 trace_logging_info->current_logging_context;
481 * Queue the context into the logging_info structure,
482 * We will try to send it later. Currently, we will
483 * restrict to only one context queued.
485 spp_global_counters.spp_trace_log_downstream_constipation_count++;
488 * Attach the current logging context which is full to the
489 * queued context list in trace_logging_info structure
491 trace_logging_info->queued_logging_context =
492 trace_logging_info->current_logging_context;
495 * Whether the context is queued or not, set the current context index
496 * to EMPTY, as the earlier context can no more be used to send
497 * more logging records.
501 trace_logging_info->current_logging_context = NULL;
505 * edt: * * spp_trace_log_send_pkt_always_success
507 * Tries to send a logging pkt. This cannot fail due to downstream
508 * constipation because we have already checked if the rewrite_output
509 * node can accept it.
511 * Argument: spp_trace_log_info_t *trace_logging_info
512 * structure that contains the packet context
514 * Argument: spp_node_t *output_node
515 * spp_node_t structure for rewrite_output node
518 void spp_trace_log_send_pkt_always_success (
519 spp_trace_log_info_t *trace_logging_info,
520 spp_node_t *output_node)
523 * At this point we either have a current or queued logging context
525 if (PREDICT_TRUE(trace_logging_info->current_logging_context != NULL)) {
527 output_node->sf.ctxs[output_node->sf.nused++] =
528 trace_logging_info->current_logging_context;
530 trace_logging_info->current_logging_context = NULL;
533 * For queued logging context
535 output_node->sf.ctxs[output_node->sf.nused++] =
536 trace_logging_info->queued_logging_context;
538 trace_logging_info->queued_logging_context = NULL;
542 * Move the logging context to output node
544 spp_dispatch_make_node_runnable(output_node);
549 * edt: * * spp_create_trace_log_context
551 * Tries to create a logging context with packet buffer
552 * to send a new logging packet
554 * Argument: spp_trace_log_info_t *trace_logging_info
555 * structure that contains the nfv9 logging info and will store
556 * the packet context as well.
559 void spp_create_trace_log_context (
560 spp_trace_log_info_t *trace_logging_info)
565 * If queued_logging_context_index is non-EMPTY, we already have a logging
566 * packet queued to be sent. First try sending this before allocating
567 * a new context. We can have only one active packet context per
568 * trace_logging_info structure
570 if (PREDICT_FALSE(trace_logging_info->queued_logging_context != NULL)) {
571 spp_trace_log_send_queued_pkt(trace_logging_info);
573 * If we cannot still send the queued pkt, just return
574 * Downstream Constipation count would have increased anyway
576 if (trace_logging_info->queued_logging_context != NULL) {
577 spp_global_counters.spp_trace_log_context_creation_deferred_count++;
584 * No context can be allocated, return silently
585 * calling routine will handle updating the error counters
587 if (spp_ctx_alloc(&ctx, 1) < 1) {
588 spp_global_counters.spp_trace_log_context_creation_fail_count++;
592 trace_logging_info->current_logging_context = ctx;
593 trace_logging_info->pkt_length = 0;
595 trace_logging_info->current_logging_context_timestamp =
596 spp_trace_log_get_sys_up_time_in_ms();
598 ctx->flags = SPP_CTX_END_OF_PACKET;
599 ctx->ru.tx.from_node = NODE_TRACE_BACKUP;
600 ctx->ru.tx.dst_ip_port_idx = EXT_TRACE_BACKUP_INDEX;
601 ctx->next_ctx_this_packet = (spp_ctx_t*) SPP_CTX_NO_NEXT_CTX;
602 ctx->current_header = &ctx->packet_data[SPP_TRACE_LOG_HDR_OFFSET];
603 ctx->current_length = 0;
605 trace_logging_info->log_record = 0;
606 trace_logging_info->total_record_count = 0;
607 trace_logging_info->next_data_ptr =
608 (u8 *) &ctx->packet_data[SPP_TRACE_LOG_HDR_OFFSET];
613 * edt: * * spp_trace_log_add_record_create
615 * Tries to create an add record to the NFV9 packet
617 * Argument: spp_trace_log_info_t *trace_logging_info
618 * structure that contains the nfv9 logging info and will store
619 * the packet context as well.
622 void spp_trace_log_add_record_create (spp_trace_log_info_t *trace_logging_info)
625 trace_logging_info->log_header =
626 (spp_trace_log_hdr_t *) (trace_logging_info->next_data_ptr);
629 * Initialize the number of traces recorded
631 trace_logging_info->log_header->num_traces =
632 spp_host_to_net_byte_order_32(0);
635 trace_logging_info->log_record =
636 (spp_trace_log_t *) (trace_logging_info->log_header + 1);
639 * Update the length of the total pkt
641 trace_logging_info->pkt_length +=
642 SPP_LOG_TRACE_HEADER_LENGTH;
645 * Set the data pointer beyond the trace header field
647 trace_logging_info->next_data_ptr =
648 (u8 *) (trace_logging_info->log_header + 1);
653 * edt: * * spp_trace_logger
655 * Tries to log spp/cnat event/errors
657 * Argument: u8 *error_code
660 * Argument: optional arguments
662 void spp_trace_logger (u16 error_code, u16 num_args, u32 *arg)
664 spp_trace_log_info_t *trace_logging_info = 0;
668 spp_trace_log_info_pool +
669 spp_trace_log_global_info.spp_log_pool_index[SPP_LOG_LTRACE];
671 if (PREDICT_FALSE(trace_logging_info->current_logging_context == NULL)) {
672 spp_create_trace_log_context(trace_logging_info);
675 * If still empty, return after increasing the count
677 if (PREDICT_FALSE(trace_logging_info->current_logging_context == NULL)) {
682 if (PREDICT_FALSE(trace_logging_info->log_record == NULL)) {
683 spp_trace_log_add_record_create(trace_logging_info);
687 * We should definitely have add_record now, no need to sanitize
689 trace_logging_info->log_record->error_code =
690 spp_host_to_net_byte_order_16(error_code);
691 trace_logging_info->log_record->num_args =
692 spp_host_to_net_byte_order_16(num_args);
694 for (i = 0; i < num_args; i++) {
695 trace_logging_info->log_record->arg[i] =
696 spp_host_to_net_byte_order_32(*(arg + i));
699 trace_logging_info->pkt_length += SPP_TRACE_LOG_RECORD_LENGTH + WORD_SIZE*num_args;
700 trace_logging_info->current_logging_context->current_length =
701 trace_logging_info->pkt_length;
702 trace_logging_info->total_record_count += 1;
704 trace_logging_info->next_data_ptr =
705 (u8 *) (trace_logging_info->next_data_ptr + WORD_SIZE + WORD_SIZE*num_args);
707 trace_logging_info->log_record =
708 (spp_trace_log_t *) (trace_logging_info->next_data_ptr);
711 * Initialize the number of traces recorded
713 trace_logging_info->log_header->num_traces =
714 spp_host_to_net_byte_order_32(trace_logging_info->total_record_count);
719 * If we have exceeded the packet length, let us send the
720 * packet now. There is buffer of additional bytes beyond
721 * max_pkt_length to ensure that the last add/delete record
722 * can be stored safely.
724 if (trace_logging_info->pkt_length >
725 trace_logging_info->max_length_minus_max_record_size) {
726 spp_trace_log_send_pkt(trace_logging_info);
732 * edt: * * spp_trace_log_timer_handler
734 * Timer handler for sending any pending NFV9 record
736 * Argument: spp_timer_t * timer_p
737 * Timer handler structure
740 void spp_trace_log_timer_handler (spp_timer_t * timer_p)
742 spp_node_t *output_node;
743 spp_trace_log_info_t *trace_logging_info = 0;
744 u32 current_timestamp = spp_trace_log_get_sys_up_time_in_ms();
747 output_node = spp_get_nodes() +
748 spp_trace_log_global_info.spp_trace_log_disp_node_index;
750 sf_nused = output_node->sf.nused;
752 pool_foreach (trace_logging_info, spp_trace_log_info_pool, ({
754 * Check if no more logging contexts can be queued
756 if (PREDICT_FALSE(sf_nused >= SPP_MAXDISPATCH)) {
761 * If there is a current logging context and timestamp
762 * indicates it is pending for long, send it out
763 * Also if there is a queued context send it out as well
765 if (trace_logging_info->queued_logging_context ||
766 (trace_logging_info->current_logging_context &&
768 trace_logging_info->current_logging_context_timestamp)
770 spp_trace_log_send_pkt_always_success(trace_logging_info,
777 spp_timer_in_n_ms_inline(1000); /* every 1 sec */
778 spp_timer_start(timer_p);
782 void spp_sensor_timer_handler (spp_timer_t * timer_p)
784 #ifdef TARGET_RODDICK
785 if (!temperature_read_blocked) {
786 Init_temperature_sensors();
787 read_octeon_sensors(TEMPERATURE_SENSOR_QUIET_MODE);
791 spp_timer_in_n_ms_inline(60000); /* every 1 sec */
792 spp_timer_start(timer_p);
796 void init_trace_log_buf_pool (void)
798 spp_trace_log_info_t *my_spp_log_info;
800 spp_log_type_t log_type;
803 * Init SPP logging info as needed, this will be done only once
805 spp_trace_log_init();
809 for (log_type = SPP_LOG_LTRACE; log_type < SPP_LOG_MAX; log_type++ ) {
810 /* Do we already have a map for this log type? */
811 pool_foreach (my_spp_log_info, spp_trace_log_info_pool, ({
812 if (my_spp_log_info->log_type == log_type) {
822 pool_get(spp_trace_log_info_pool, my_spp_log_info);
823 memset(my_spp_log_info, 0, sizeof(*my_spp_log_info));
826 * Make the current and head logging context indeices as EMPTY.
827 * When first logging happens, these get set correctly
829 my_spp_log_info->current_logging_context = NULL;
830 my_spp_log_info->queued_logging_context = NULL;
832 my_spp_log_info->log_type = log_type;
833 my_spp_log_info->max_length_minus_max_record_size =
834 SPP_TRACE_LOG_MAX_PKT_LENGTH;
836 spp_trace_log_global_info.spp_log_pool_index[log_type] =
837 my_spp_log_info - spp_trace_log_info_pool;
848 * has to be called at the init time
850 void spp_trace_log_init (void)
852 if (!spp_trace_log_global_info.spp_trace_log_init_done) {
854 #ifdef TARGET_RODDICK
855 spp_trace_log_global_info.spp_trace_log_disp_node_index =
856 spp_lookup_node_index("roddick_infra_l3_tx");
857 #elif defined(TARGET_BOOSTER)
858 spp_trace_log_global_info.spp_trace_log_disp_node_index =
859 spp_lookup_node_index("booster_infra_l3_tx");
861 ASSERT(spp_trace_log_global_info.spp_trace_log_disp_node_index != (u16)~0);
863 spp_trace_log_global_info.log_timer.cb_index =
864 spp_timer_register_callback(spp_trace_log_timer_handler);
865 spp_trace_log_global_info.log_timer.expires =
866 spp_timer_in_n_ms_inline(1000); /* every 1 sec */
867 spp_timer_start(&spp_trace_log_global_info.log_timer);
870 sensor_timer.cb_index =
871 spp_timer_register_callback(spp_sensor_timer_handler);
872 sensor_timer.expires =
873 spp_timer_in_n_ms_inline(60000); /* every 1 sec */
874 spp_timer_start(&sensor_timer);
877 spp_trace_log_global_info.spp_trace_log_init_done = 1;
880 * Set MSC ip_addr, port values
882 #ifdef TARGET_RODDICK
883 dst_ipv4_port_table[EXT_TRACE_BACKUP_INDEX].ipv4_address =
884 vpp_boot_params.msc_ip_address;
885 switch(vpp_boot_params.octeon_number) {
887 dst_ipv4_port_table[EXT_TRACE_BACKUP_INDEX].port = 0x15BF;
890 dst_ipv4_port_table[EXT_TRACE_BACKUP_INDEX].port = 0x15BF;
893 dst_ipv4_port_table[EXT_TRACE_BACKUP_INDEX].port = 0x15BF;
896 dst_ipv4_port_table[EXT_TRACE_BACKUP_INDEX].port = 0x15BF;
900 dst_ipv4_port_table[EXT_TRACE_BACKUP_INDEX].ipv4_address = 0x01020304;
901 dst_ipv4_port_table[EXT_TRACE_BACKUP_INDEX].port = 0x15BF;
907 void spp_printf (u16 error_code, u16 num_args, u32 *arg)
909 u32 current_timestamp;
910 spp_node_main_vector_t *nmv;
912 if (PREDICT_FALSE(error_code >= LOG_TABLE_MAX_ENTRIES))
914 /* printf("Error code invalid %d, %d, %d, %d\n",
915 error_code, LOG_TABLE_MAX_ENTRIES,
916 sizeof(spp_cnat_logger_table), sizeof(spp_cnat_logger_table[0]));
918 return; /* Should not happen */
921 nmv = spp_get_node_main_vectorized_inline();
922 current_timestamp = nmv->ticks / nmv->ticks_per_second;
924 /* Check if any further hashing is required */
926 if (PREDICT_FALSE(error_code == DUMP_PKT_IDX)) {
927 #ifdef TARGET_RODDICK || defined(TARGET_BOOSTER)
928 spp_trace_logger(error_code, num_args, arg);
932 printf("PKT DUMP :: ");
933 for (j = 0 ; j < num_args; j++) {
934 printf("0x%x ", arg[j]);
935 if (j == (num_args - 1)) {
940 } else if (PREDICT_TRUE((current_timestamp - error_code_timestamps[error_code]) >=
941 spp_cnat_logger_table[error_code].rate_limit_time)) {
942 /* update timestamp */
943 error_code_timestamps[error_code] = current_timestamp;
945 #ifdef TARGET_RODDICK || defined(TARGET_BOOSTER)
946 spp_trace_logger(error_code, num_args, arg);
950 for (j = 0 ; j < num_args; j++) {
951 printf("%s: %d ", spp_cnat_logger_table[error_code].param_name[j], arg[j]);
952 if (j == (num_args - 1)) {
960 #else /* TOBE_PORTEED */
961 void spp_trace_logger(u16 error_code, u16 num_args, u32 *arg)
966 void spp_trace_log_init(void)
971 void init_trace_log_buf_pool(void)
976 void spp_printf(u16 error_code, u16 num_args, u32 *arg)
982 u32 spp_trace_log_get_unix_time_in_seconds (void)
984 vlib_main_t *vlib_main;
986 vlib_main = vlib_get_main();
987 return(vlib_time_now((vlib_main_t *) vlib_main));
990 #endif /* TOBE_PORTED */