From 0d4def6c7b673f3be486338ced65ccdd25a859ed Mon Sep 17 00:00:00 2001 From: "E. Scott Daniels" Date: Tue, 28 Jan 2020 16:50:27 -0500 Subject: [PATCH 1/1] Allow user programme to set RMR verbosity level This change centralises the writing of messages to the standard error device which allows the user programme to have control over the verbosity level. Introduces the new rmr_set_vlevel() function. Signed-off-by: E. Scott Daniels Change-Id: I0c4b4b3af94d34b480622ec1f65a9da65cabf2b5 --- CHANGES | 5 + CMakeLists.txt | 4 +- doc/CMakeLists.txt | 1 + doc/src/man/env_var_list.im | 115 +++++++++++++++++++ doc/src/man/rmr_init.3.xfm | 23 +--- doc/src/man/rmr_set_trace.3.xfm | 2 +- doc/src/man/rmr_set_vlevel.3.xfm | 108 ++++++++++++++++++ src/rmr/common/CMakeLists.txt | 2 + src/rmr/common/include/rmr.h | 2 + src/rmr/common/include/rmr_agnostic.h | 14 ++- src/rmr/common/include/rmr_logging.h | 60 ++++++++++ src/rmr/common/src/logging.c | 201 +++++++++++++++++++++++++++++++++ src/rmr/common/src/mt_call_static.c | 2 +- src/rmr/common/src/rt_generic_static.c | 124 ++++++++++---------- src/rmr/common/src/rtc_static.c | 18 +-- src/rmr/common/src/symtab.c | 29 +++-- src/rmr/common/src/tools_static.c | 6 +- src/rmr/common/src/wormholes.c | 8 +- src/rmr/nng/src/mt_call_nng_static.c | 4 +- src/rmr/nng/src/rmr_nng.c | 48 ++++---- src/rmr/nng/src/rtable_nng_static.c | 32 +++--- src/rmr/nng/src/sr_nng_static.c | 54 ++++----- src/rmr/si/src/mt_call_si_static.c | 26 ++--- src/rmr/si/src/rmr_si.c | 54 +++++---- src/rmr/si/src/rtable_si_static.c | 54 ++++----- src/rmr/si/src/rtc_si_static.c | 14 +-- src/rmr/si/src/si95/siaddress.c | 2 +- src/rmr/si/src/si95/sicbreg.c | 2 +- src/rmr/si/src/si95/siconnect.c | 2 +- src/rmr/si/src/si95/siinit.c | 2 +- src/rmr/si/src/si95/sisetup.h | 2 + src/rmr/si/src/si95/siwait.c | 2 +- src/rmr/si/src/sr_si_static.c | 64 +++++------ test/logging_test.c | 97 ++++++++++++++++ test/rmr_nng_test.c | 2 + test/tools_test.c | 1 + test/unit_test.ksh | 2 + 37 files changed, 892 insertions(+), 296 deletions(-) create mode 100644 doc/src/man/env_var_list.im create mode 100644 doc/src/man/rmr_set_vlevel.3.xfm create mode 100644 src/rmr/common/include/rmr_logging.h create mode 100644 src/rmr/common/src/logging.c create mode 100644 test/logging_test.c diff --git a/CHANGES b/CHANGES index 249d2cf..cd88f3e 100644 --- a/CHANGES +++ b/CHANGES @@ -2,6 +2,11 @@ API and build change and fix summaries. Doc correctsions and/or changes are not mentioned here; see the commit messages. +2020 January 26; verison 3.1.0 + First step to allowing the user programme to control messages + written to standard error. Introduces the rmr_set_vlevel() + function, and related environment variable. + 2020 January 24; verison 3.0.5 Fix bug in SI95 with receive buffer allocation. diff --git a/CMakeLists.txt b/CMakeLists.txt index 981b158..9a51535 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -37,8 +37,8 @@ project( rmr LANGUAGES C ) cmake_minimum_required( VERSION 3.5 ) set( major_version "3" ) # should be automatically populated from git tag later, but until CI process sets a tag we use this -set( minor_version "0" ) -set( patch_level "5" ) +set( minor_version "1" ) +set( patch_level "0" ) set( install_root "${CMAKE_INSTALL_PREFIX}" ) set( install_inc "include/rmr" ) diff --git a/doc/CMakeLists.txt b/doc/CMakeLists.txt index 55c5098..c0efdcb 100644 --- a/doc/CMakeLists.txt +++ b/doc/CMakeLists.txt @@ -77,6 +77,7 @@ if( BUILD_DOC ) rmr_get_trace.3 rmr_init_trace.3 rmr_set_trace.3 + rmr_set_vlevel.3 rmr_tralloc_msg.3 rmr_get_trlen.3 rmr_get_src.3 diff --git a/doc/src/man/env_var_list.im b/doc/src/man/env_var_list.im new file mode 100644 index 0000000..a9d4297 --- /dev/null +++ b/doc/src/man/env_var_list.im @@ -0,0 +1,115 @@ +.** vim: ts=4 noet sw=4: +.if false +================================================================================== + Copyright (c) 2019 Nokia + Copyright (c) 2018-2019 AT&T Intellectual Property. + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + 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. +================================================================================== +.fi + +.if false + Mnemonic: env_list_vars.im + Abstract: This is a list of environment variables which are recognised + by RMR. This is an embed file as it is referenced by both + manual pages and the 'read the docs' source (allowing a single + point of maintenence). + + Date: 6 November 2019 (broken from the main manual page) + Author: E. Scott Daniels +.fi + + +&beg_dlist(.75i : ^&bold_font ) +&ditem(RMR_ASYNC_CONN) Allows the asynch connection mode to be turned off (by setting the + value to 0. When set to 1, or missing from the environment, RMR will invoke the + connection interface in the transport mechanism using the non-blocking (asynch) + mode. This will likely result in many "soft failures" (retry) until the connection + is established, but allows the application to continue unimpeeded should the + connection be slow to set up. + &half_space + +&ditem(RMR_BIND_IF) This provides the interface that RMr will bind listen ports to allowing + for a single interface to be used rather than listening across all interfaces. + This should be the IP address assigned to the interface that RMr should listen + on, and if not defined RMr will listen on all interfaces. + &half_space + +&ditem(RMR_RTG_SVC) RMr opens a TCP listen socket using the port defined by this + environment variable and expects that the route table generator process + will connect to this port. + If not supplied the port 4561 is used. + &half_space + +&ditem(RMR_HR_LOG) + By default RMR writes messages to standard error (incorrectly referred to as log messages) + in human readable format. + If this environment variable is set to 0, the format of standard error messages might + be written in some format not easily read by humans. + If missing, a value of 1 is assumed. + &half_space + +&ditem(RMR_LOG_VLEVEL) + This is a numeric value which corresponds to the verbosity level used to limit messages + written to standard error. + The lower the number the less chatty RMR functions are during execution. + The following is the current relationship between the value set on this variable and + the messages written: + + &beg_dlist(.25i : &bold_font ) + &ditem(0) Off; no messages of any sort are written. + &half_space + &ditem(1) Only critical messages are written (default if this variable does not exist) + &half_space + &ditem(2) Errors and all messages written with a lower value. + &half_space + &ditem(3) Warnings and all messages written with a lower value. + &half_space + &ditem(4) Informationional and all messages written with a lower value. + &half_space + &ditem(5) Debugging mode -- all messages written, however this requires RMR to have been compiled with debugging support enabled. + &end_dlist + &half_space + +&ditem(RMR_RTG_ISRAW) Is set to 1 if the route table generator is sending "plain" messages + (not using RMr to send messages, 0 if the rtg is using RMr to send. The default + is 1 as we don't expect the rtg to use RMr. + +&ditem(RMR_SEED_RT) This is used to supply a static route table which can be used for + debugging, testing, or if no route table generator process is being used to + supply the route table. + If not defined, no static table is used and RMr will not report &ital(ready) + until a table is received. + The static route table may contain both the route table (between newrt start + and end records), and the MEID map (between meid_map start and end records) + +&ditem(RMR_SRC_ID) This is either the name or IP address which is placed into outbound + messages as the message source. This will used when an RMR based application uses + the rmr_rts_msg() function to return a response to the sender. If not supplied + RMR will use the hostname which in some container environments might not be + routable. + +&ditem(RMR_VCTL_FILE) This supplies the name of a verbosity control file. The core + RMR functions do not produce messages unless there is a critical failure. However, + the route table collection thread, not a part of the main message processing + component, can write additional messages to standard error. If this variable is + set, RMR will extract the verbosity level for these messages (0 is silent) from + the first line of the file. Changes to the file are detected and thus the level + can be changed dynamically, however RMR will only suss out this variable during + initialisation, so it is impossible to enable verbosity after startup. + +&ditem(RMR_WARNINGS) If set to 1, RMR will write some warnings which are non-performance + impacting. If the variable is not defined, or set to 0, RMR will not write these + additional warnings. + +&end_dlist diff --git a/doc/src/man/rmr_init.3.xfm b/doc/src/man/rmr_init.3.xfm index 5e53e63..a190ef7 100644 --- a/doc/src/man/rmr_init.3.xfm +++ b/doc/src/man/rmr_init.3.xfm @@ -68,16 +68,16 @@ following flags are supported: &half_space &beg_dlist(1i : &bold_font ) -&diitem(RMRFL_NONE) +&ditem(RMRFL_NONE) No flags are set. &half_space -&diitem(RMRFL_NOTHREAD) +&ditem(RMRFL_NOTHREAD) The route table collector thread is not to be started. This should only be used by the route table generator application if it is based on RMr. &half_space -&diitem(RMRFL_MTCALL) +&ditem(RMRFL_MTCALL) Enable multi-threaded call support. &half_space @@ -117,21 +117,8 @@ environment variables to influence it's setup. The following variables will be used when found. &half_space -&beg_dlist(1i : &bold_font ) -&diitem(RMR_SEED_RT) -Assumes this is the filename of the seed route table file to use. In normal situations, -the library will wait for an update from the route table generator (expected within a few seconds -of initialisation) before being able to send messages. -However, in some situations where a bootstrap table is necessary, this is the means to -supply it to the library. -&half_space - -&diitem(RMR_RTG_SVC) -The route table generator assumes that RMr is listening on a well known port (4561) by -default, but this environment variable can be used to change the listening port if -needed. -The value of the variable is expected to be just the port. -&end_dlist +.** the list of environment vars supported +.im &{lib}/man/env_var_list.im &h2(RETURN VALUE) The &cw(rmr_init) function returns a void pointer (a contex if you will) that is passed diff --git a/doc/src/man/rmr_set_trace.3.xfm b/doc/src/man/rmr_set_trace.3.xfm index 0fb4955..67c53bf 100644 --- a/doc/src/man/rmr_set_trace.3.xfm +++ b/doc/src/man/rmr_set_trace.3.xfm @@ -38,7 +38,7 @@ &ex_start #include -int rmr_bytes2payload( rmr_mbuf_t* mbuf, unsigned char* data, int len ) +int rmr_set_trace( rmr_mbuf_t* mbuf, unsigned char* data, int len ) &ex_end &uindent diff --git a/doc/src/man/rmr_set_vlevel.3.xfm b/doc/src/man/rmr_set_vlevel.3.xfm new file mode 100644 index 0000000..763cab1 --- /dev/null +++ b/doc/src/man/rmr_set_vlevel.3.xfm @@ -0,0 +1,108 @@ +.if false +================================================================================== + Copyright (c) 2019-2020 Nokia + Copyright (c) 2018-2020 AT&T Intellectual Property. + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + 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. +================================================================================== +.fi + +.if false + Mnemonic rmr_set_vlevel.3.xfm + Abstract The manual page for the function which sets the verbosity level + in RMR logging. + Author E. Scott Daniels + Date 28 January 2020 +.fi + +.gv e LIB lib +.im &{lib}/man/setup.im + +&line_len(6i) + +&h1(RMR Library Functions) +&h2(NAME) + rmr_set_trace + +&h2(SYNOPSIS) +&indent +&ex_start +#include +#include + +void rmr_set_vlevel( int new_level ) +&ex_end + +&uindent + +&h2(DESCRIPTION) +The &cw(rmr_set_vlevel) allows the user programme to set the verbosity level +which is used to determine the messages RMR writes to standard error. +The &cw(new_vlevel) value must be one of the following constants which have the +indicated meanings: + +&beg_dlist(1i : &bold_font ) +&ditem(RMR_VL_OFF) + Turns off all message writing. This includes the stats and debugging messages generated by the + route collector thread which are normally affected only by the externally managed verbose + level file (and related environment variable). +&half_space + +&ditem(RMR_VL_CRIT) + Write only messages of critical importance. + From the point of view of RMR, when a critical proper behaviour of the library cannot be + expected or guaranteed. + +&ditem(RMR_VL_ERR) + Include error messages in the output. + An error is an event from which RMR has no means to recover. + Continued proper execution is likely except where the affected connection and/or component + mentioned in the error is concerned. + +&ditem(RMR_VL_WARN) + Include warning messages in the output. + A warning indicates an event which is not considered to be normal, but is expected and + continued acceptable behaviour of the system is assured. + +&ditem(RMR_VL_INFO) + Include informational messagees in the output. + Informational messages include some diagnostic information which explain the activities + of RMR. + +&ditem(RMR_VL_DEBUG) + Include all debugging messages in the output. + Debugging must have also been enabled during the build as a precaution to accidentally + enabling this level of output as it can grossly affect performance. +&end_dlist +&space + +generally RMR does not write messages to the standard error device from &ital(critical path) +functions, therefore it is usually not harmful to enable a verbosity level of either RMR_VL_CRIT, or RMR_VL_ERR. + +&space +Messages written from the route table collection thread are still governed by the value placed +into the verbose level control file (see the man page for rmr_init()); those messages are affected +only when logging is completely disabled by passing RMR_VL_OFF to this function. + +&space +The verbosity level can also be set via an environment variable prior to the start of the +RMR based application. +The environment variable is read only during initialisation; if the programme must change +the value during execution, this function must be used. +The default value, if this function is never called, and the environment variable is not +present, is RMR_VL_ERR. + +&h2(SEE ALSO ) +.ju off +rmr_init(3) +.ju on diff --git a/src/rmr/common/CMakeLists.txt b/src/rmr/common/CMakeLists.txt index b499a8f..35833bf 100644 --- a/src/rmr/common/CMakeLists.txt +++ b/src/rmr/common/CMakeLists.txt @@ -21,6 +21,7 @@ add_library( common_objects OBJECT src/symtab.c + src/logging.c src/mbuf_api.c src/wrapper.c ) @@ -35,6 +36,7 @@ if( DEV_PKG ) install( FILES include/rmr.h include/rmr_symtab.h + include/rmr_logging.h include/RIC_message_types.h DESTINATION ${install_root}/${install_inc} ) diff --git a/src/rmr/common/include/rmr.h b/src/rmr/common/include/rmr.h index a9805a8..88689d5 100644 --- a/src/rmr/common/include/rmr.h +++ b/src/rmr/common/include/rmr.h @@ -164,6 +164,8 @@ extern int rmr_set_trace( rmr_mbuf_t* msg, unsigned const char* data, int size ) extern int rmr_rcv_to( void* vctx, int time ); // DEPRECATED -- replaced with set_rtimeout extern int rmr_send_to( void* vctx, int time ); // DEPRECATED -- replaced with set_stimeout +// ---- misc user interface stuff ---------------------------------------------------------------------- +extern void rmr_set_vlevel( int new_level ); // --- uta compatability defs if needed user should define UTA_COMPAT ---------------------------------- #ifdef UTA_COMPAT diff --git a/src/rmr/common/include/rmr_agnostic.h b/src/rmr/common/include/rmr_agnostic.h index 6ef3aee..cb8114f 100644 --- a/src/rmr/common/include/rmr_agnostic.h +++ b/src/rmr/common/include/rmr_agnostic.h @@ -29,6 +29,8 @@ #ifndef _rmr_agnostic_h #define _rmr_agnostic_h +#include // needed to support some structs + typedef struct endpoint endpoint_t; // place holder for structs defined in nano/nng private.h typedef struct uta_ctx uta_ctx_t; @@ -53,15 +55,17 @@ typedef struct uta_ctx uta_ctx_t; #define RMR_MSG_VER 3 // message version this code was designed to handle // environment variable names we'll suss out -#define ENV_BIND_IF "RMR_BIND_IF" // the interface to bind to for both normal comma and RTG (0.0.0.0 if missing) -#define ENV_RTG_PORT "RMR_RTG_SVC" // the port we'll listen on for rtg connections -#define ENV_SEED_RT "RMR_SEED_RT" // where we expect to find the name of the seed route table +#define ENV_BIND_IF "RMR_BIND_IF" // the interface to bind to for both normal comma and RTG (0.0.0.0 if missing) +#define ENV_RTG_PORT "RMR_RTG_SVC" // the port we'll listen on for rtg connections +#define ENV_SEED_RT "RMR_SEED_RT" // where we expect to find the name of the seed route table #define ENV_SEED_MEMAP "RMR_SEED_MEMAP" // where we expect to find the name of the seed route table -#define ENV_RTG_RAW "RMR_RTG_ISRAW" // if > 0 we expect route table gen messages as raw (not sent from an RMr application) +#define ENV_RTG_RAW "RMR_RTG_ISRAW" // if > 0 we expect route table gen messages as raw (not sent from an RMr application) #define ENV_VERBOSE_FILE "RMR_VCTL_FILE" // file where vlevel may be managed for some (non-time critical) functions -#define ENV_NAME_ONLY "RMR_SRC_NAMEONLY" // src in message is name only +#define ENV_NAME_ONLY "RMR_SRC_NAMEONLY" // src in message is name only #define ENV_WARNINGS "RMR_WARNINGS" // if == 1 then we write some, non-performance impacting, warnings #define ENV_SRC_ID "RMR_SRC_ID" // forces this string (adding :port, max 63 ch) into the source field; host name used if not set +#define ENV_LOG_HR "RMR_HR_LOG" // set to 0 to turn off human readable logging and write using some formatting +#define ENV_LOG_VLEVEL "RMR_LOG_VLEVEL" // set the verbosity level (0 == 0ff; 1 == crit .... 5 == debug ) #define NO_FLAGS 0 // no flags to pass to a function diff --git a/src/rmr/common/include/rmr_logging.h b/src/rmr/common/include/rmr_logging.h new file mode 100644 index 0000000..30c9e54 --- /dev/null +++ b/src/rmr/common/include/rmr_logging.h @@ -0,0 +1,60 @@ +// :vi sw=4 ts=4 noet: +/* +================================================================================== + Copyright (c) 2019-2020 Nokia + Copyright (c) 2018-2020 AT&T Intellectual Property. + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + 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. +================================================================================== +*/ +/* + Mnemonic: rmr_logging.h + Abstract: All needed header stuff for RMR's common logger. + + Author: E. Scott Daniels + Date: 27 January 2020 +*/ + +#ifndef _logger_h +#define _logger_h + + +// situation constants +#define LOG_ERROR "ERR" +#define LOG_WARN "WARN" +#define LOG_INFO "INFO" +#define LOG_CRIT "CRIT" +#define LOG_DEBUG "DBUG" + +/* + vlevel constants; ordered such that if( vlevel >= write_level ) is true when we have a + verbose level setting condusive for writing. +*/ +#define RMR_VL_DEBUG 5 +#define RMR_VL_INFO 4 +#define RMR_VL_WARN 3 +#define RMR_VL_ERR 2 +#define RMR_VL_CRIT 1 +#define RMR_VL_OFF 0 + + +// ----- prototypes ------------------------------ +extern void rmr_vlog( int write_level, char* fmt, ... ); +extern void rmr_vlog_force( int write_level, char* fmt, ... ); +extern int rmr_vlog_init(); +extern void rmr_set_vlevel( int new_level ); + + + +#endif + diff --git a/src/rmr/common/src/logging.c b/src/rmr/common/src/logging.c new file mode 100644 index 0000000..0105391 --- /dev/null +++ b/src/rmr/common/src/logging.c @@ -0,0 +1,201 @@ +// :vi sw=4 ts=4 noet: +/* +================================================================================== + Copyright (c) 2019-2020 Nokia + Copyright (c) 2018-2020 AT&T Intellectual Property. + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + 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. +================================================================================== +*/ +/* + Mnemonic: logging.c + Abstract: Implements a common logging interface. + + Some thoughts and theory.... + Libraries should write human readable messages to standard error + when errors, warnings, or general information messages are called + for. These messages should NEVER be written to standard output, + and should never be mixed with an application's log messages which + are assumed to contain potentially sensitive information, such as + user names, and should not be written to standard error. + + For libraries such as RMR, where speed and latency are absolutely + critical, logging should only be done from non-critical path code, + or when an error has already compromised the ability to be performant. + Thus, it is expected that most calls to the functions here are of + the form: + if( DEBUG ) rmr_logger( vlevel, fmt, parms); + + such that the call to rmr_logger() is removed from the code unless + compiled with the DEBUG flag set. Code such as + if( vlevel >= WARNING ) { + rmr_logger( fmt, parms ) + } + + is unacceptable because it adds unnecessary checking for the current + verbosity level setting in line. + + + With respect to formatting messages written to stderr: they should NOT + be written with json, or anyother form of mark up. Idealy, they should + use a syntax similar to system log: + + + where timestamp is UNIX time, pid is the process id, situation is error, + warning, etc, and message is obviously the text. + + Thus, the default messages geneated are "plain." Because some might feel + that messages need to be formatted, the code here provides for the gross + encapsulation of standard error text into json (best wishes for the poor + sap who is left having to read the output on some dark and stormy night). + To enable this, the environment veriable RMR_HRLOG=0 must be set to + turn off human readable logs. + + Author: E. Scott Daniels + Date: 27 January 2020 +*/ + +#ifndef _logger_static_c +#define _logger_static_c + +#include +#include +#include +#include +#include +#include +#include +#include +#include + + +#include +#include +#include + +static int log_initialised = 0; +static int log_vlevel = RMR_VL_ERR; +static int log_hrlogging = 1; +static int log_pid = 0; +static char* log_situations[RMR_VL_DEBUG+1]; + +/* + Initialise logging. Returns the current log level. +*/ +extern int rmr_vlog_init( ) { + char* data; + + if( (data = getenv( ENV_LOG_HR )) != NULL ) { + log_hrlogging = atoi( data ); + } + + if( (data = getenv( ENV_LOG_VLEVEL )) != NULL ) { + log_vlevel = atoi( data ); + if( log_vlevel < 0 ) { + log_vlevel = 0; + } else { + if( log_vlevel > RMR_VL_DEBUG ) { + log_vlevel = RMR_VL_DEBUG; + } + } + } + + log_pid = getpid(); + log_situations[RMR_VL_DEBUG] = LOG_DEBUG; + log_situations[RMR_VL_INFO] = LOG_INFO; + log_situations[RMR_VL_WARN] = LOG_WARN; + log_situations[RMR_VL_ERR] = LOG_ERROR; + log_situations[RMR_VL_CRIT] = LOG_CRIT; + + log_initialised = 1; + + return log_vlevel; +} + +/* + Write a variable message formatted in the same vein as *printf. + We add a header to each log message with time, pid and message + situation (error, warning, etc.). +*/ +extern void rmr_vlog( int write_level, char* fmt, ... ) { + va_list argp; // first arg in our parms which is variable + char msg[4096]; + int hlen; + char* body; // pointer into msg, past header + + if( write_level > log_vlevel ) { // write too big, skip + return; + } + + if( ! log_initialised ) { + rmr_vlog_init(); + } + + if( write_level > RMR_VL_DEBUG || write_level < 0 ) { + write_level = RMR_VL_DEBUG; + } + + hlen = snprintf( msg, sizeof( msg ), "%ld %d/RMR [%s] ", (long) time( NULL ), log_pid, log_situations[write_level] ); + body = msg + hlen; + + va_start( argp, fmt ); // suss out parm past fmt + + vsnprintf( body, sizeof( msg ) - (hlen+2), fmt, argp ); // add in user message formatting it along the way + fprintf( stderr, "%s", msg ); // we grew from printfs so all existing msg have \n; assume there +} + +/* + This ensures that the message is written regardless of the current log level + setting. This allows for route table collection verbose levels to be taken + into consideration separately from the err/warn/debug messages. Component + verbosity would be better and should be implemented. +*/ + +extern void rmr_vlog_force( int write_level, char* fmt, ... ) { + va_list argp; // first arg in our parms which is variable + char msg[4096]; + int hlen; + char* body; // pointer into msg, past header + + if( ! log_initialised ) { + rmr_vlog_init(); + } + + if( write_level > RMR_VL_DEBUG || write_level < 0 ) { + write_level = RMR_VL_DEBUG; + } + + hlen = snprintf( msg, sizeof( msg ), "%ld %d/RMR [%s] ", (long) time( NULL ), log_pid, log_situations[write_level] ); + body = msg + hlen; + + va_start( argp, fmt ); // suss out parm past fmt + + vsnprintf( body, sizeof( msg ) - (hlen+2), fmt, argp ); // add in user message formatting it along the way + fprintf( stderr, "%s", msg ); // we grew from printfs so all existing msg have \n; assume there +} + +// -------------------- public functions that are needed ----------------- + +/* + Allow user control to logging level control. Accepts a new log level + from the user programme. Messages which have a write level setting + which is >= to the new level will be written. Setting the new value + to RMR_VL_OFF disables all logging (not advised). +*/ +extern void rmr_set_vlevel( int new_level ) { + if( new_level >= 0 ) { + log_vlevel = new_level; + } +} + +#endif diff --git a/src/rmr/common/src/mt_call_static.c b/src/rmr/common/src/mt_call_static.c index ee3cda2..0cbf8f6 100644 --- a/src/rmr/common/src/mt_call_static.c +++ b/src/rmr/common/src/mt_call_static.c @@ -68,7 +68,7 @@ static int init_mtcall( uta_ctx_t* ctx ) { for( i = 0; i < MAX_CALL_ID; i++ ) { // initialise all of the semaphores chutes[i].mbuf = NULL; if( sem_init( &chutes[i].barrier, 0, 0 ) < 0 ) { - fprintf( stderr, "[ERR] rmr: unable to initialise mt call chute [%d]: %s\n", i, strerror( errno ) ); + rmr_vlog( RMR_VL_ERR, "rmr: unable to initialise mt call chute [%d]: %s\n", i, strerror( errno ) ); rc = -1; } } diff --git a/src/rmr/common/src/rt_generic_static.c b/src/rmr/common/src/rt_generic_static.c index 3c73847..12edecd 100644 --- a/src/rmr/common/src/rt_generic_static.c +++ b/src/rmr/common/src/rt_generic_static.c @@ -76,7 +76,7 @@ static void ep_stats( void* st, void* entry, char const* name, void* thing, void (*counter)++; } - fprintf( stderr, "[DBUG] RMR rt endpoint: target=%s open=%d\n", ep->name, ep->open ); + rmr_vlog_force( RMR_VL_DEBUG, "rt endpoint: target=%s open=%d\n", ep->name, ep->open ); } /* @@ -95,7 +95,7 @@ static void meid_stats( void* st, void* entry, char const* name, void* thing, vo (*counter)++; } - fprintf( stderr, "[DBUG] RMR meid=%s owner=%s open=%d\n", name, ep->name, ep->open ); + rmr_vlog_force( RMR_VL_DEBUG, "meid=%s owner=%s open=%d\n", name, ep->name, ep->open ); } /* @@ -114,7 +114,7 @@ static void ep_counts( void* st, void* entry, char const* name, void* thing, voi id = "missing"; } - fprintf( stderr, "[INFO] RMR sends: ts=%lld src=%s target=%s open=%d succ=%lld fail=%lld (hard=%lld soft=%lld)\n", + rmr_vlog_force( RMR_VL_INFO, "sends: ts=%lld src=%s target=%s open=%d succ=%lld fail=%lld (hard=%lld soft=%lld)\n", (long long) time( NULL ), id, ep->name, @@ -145,7 +145,7 @@ static void rte_stats( void* st, void* entry, char const* name, void* thing, voi mtype = rte->key & 0xffff; sid = (int) (rte->key >> 32); - fprintf( stderr, "[DBUG] RMR rte: key=%016lx mtype=%4d sid=%4d nrrg=%2d refs=%d\n", rte->key, mtype, sid, rte->nrrgroups, rte->refs ); + rmr_vlog_force( RMR_VL_DEBUG, "rte: key=%016lx mtype=%4d sid=%4d nrrg=%2d refs=%d\n", rte->key, mtype, sid, rte->nrrgroups, rte->refs ); } /* @@ -155,26 +155,26 @@ static void rt_stats( route_table_t* rt ) { int* counter; if( rt == NULL ) { - fprintf( stderr, "[DBUG] rtstats: nil table\n" ); + rmr_vlog_force( RMR_VL_DEBUG, "rtstats: nil table\n" ); return; } counter = (int *) malloc( sizeof( int ) ); *counter = 0; - fprintf( stderr, "[DBUG] RMR route table stats:\n" ); - fprintf( stderr, "[DBUG] RMR route table endpoints:\n" ); + rmr_vlog_force( RMR_VL_DEBUG, "route table stats:\n" ); + rmr_vlog_force( RMR_VL_DEBUG, "route table endpoints:\n" ); rmr_sym_foreach_class( rt->hash, RT_NAME_SPACE, ep_stats, counter ); // run endpoints (names) in the active table - fprintf( stderr, "[DBUG] RMR rtable: %d known endpoints\n", *counter ); + rmr_vlog_force( RMR_VL_DEBUG, "rtable: %d known endpoints\n", *counter ); - fprintf( stderr, "[DBUG] RMR route table entries:\n" ); + rmr_vlog_force( RMR_VL_DEBUG, "route table entries:\n" ); *counter = 0; rmr_sym_foreach_class( rt->hash, RT_MT_SPACE, rte_stats, counter ); // run message type entries - fprintf( stderr, "[DBUG] RMR rtable: %d mt entries in table\n", *counter ); + rmr_vlog_force( RMR_VL_DEBUG, "rtable: %d mt entries in table\n", *counter ); - fprintf( stderr, "[DBUG] RMR route table meid map:\n" ); + rmr_vlog_force( RMR_VL_DEBUG, "route table meid map:\n" ); *counter = 0; rmr_sym_foreach_class( rt->hash, RT_ME_SPACE, meid_stats, counter ); // run meid space - fprintf( stderr, "[DBUG] RMR rtable: %d meids in map\n", *counter ); + rmr_vlog_force( RMR_VL_DEBUG, "rtable: %d meids in map\n", *counter ); free( counter ); } @@ -185,7 +185,7 @@ static void rt_stats( route_table_t* rt ) { */ static void rt_epcounts( route_table_t* rt, char* id ) { if( rt == NULL ) { - fprintf( stderr, "[INFO] RMR endpoint: no counts: empty table\n" ); + rmr_vlog_force( RMR_VL_INFO, "endpoint: no counts: empty table\n" ); return; } @@ -240,7 +240,7 @@ static char* ensure_nlterm( char* buf ) { } } else { if( buf[len-1] != '\n' ) { - fprintf( stderr, "[WRN] rmr buf_check: input buffer was not newline terminated (file missing final \\n?)\n" ); + rmr_vlog( RMR_VL_WARN, "rmr buf_check: input buffer was not newline terminated (file missing final \\n?)\n" ); if( (nb = (char *) malloc( sizeof( char ) * (len + 2) )) != NULL ) { memcpy( nb, buf, len ); *(nb+len) = '\n'; // insert \n and nil into the two extra bytes we allocated @@ -268,7 +268,7 @@ static rtable_ent_t* uta_add_rte( route_table_t* rt, uint64_t key, int nrrgroups } if( (rte = (rtable_ent_t *) malloc( sizeof( *rte ) )) == NULL ) { - fprintf( stderr, "[ERR] rmr_add_rte: malloc failed for entry\n" ); + rmr_vlog( RMR_VL_ERR, "rmr_add_rte: malloc failed for entry\n" ); return NULL; } memset( rte, 0, sizeof( *rte ) ); @@ -281,7 +281,6 @@ static rtable_ent_t* uta_add_rte( route_table_t* rt, uint64_t key, int nrrgroups if( nrrgroups ) { if( (rte->rrgroups = (rrgroup_t **) malloc( sizeof( rrgroup_t * ) * nrrgroups )) == NULL ) { - fprintf( stderr, "rmr_add_rte: malloc failed for rrgroup array\n" ); free( rte ); return NULL; } @@ -298,7 +297,7 @@ static rtable_ent_t* uta_add_rte( route_table_t* rt, uint64_t key, int nrrgroups rmr_sym_map( rt->hash, key, rte ); // add to hash using numeric mtype as key - if( DEBUG ) fprintf( stderr, "[DBUG] route table entry created: k=%llx groups=%d\n", (long long) key, nrrgroups ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "route table entry created: k=%llx groups=%d\n", (long long) key, nrrgroups ); return rte; } @@ -337,7 +336,7 @@ static void build_entry( uta_ctx_t* ctx, char* ts_field, uint32_t subid, char* r key = build_rt_key( subid, atoi( ts_field ) ); - if( DEBUG > 1 || (vlevel > 1) ) fprintf( stderr, "[DBUG] create rte for mtype=%s subid=%d key=%lx\n", ts_field, subid, key ); + if( DEBUG > 1 || (vlevel > 1) ) rmr_vlog_force( RMR_VL_DEBUG, "create rte for mtype=%s subid=%d key=%lx\n", ts_field, subid, key ); if( (ngtoks = uta_tokenise( rr_field, gtokens, 64, ';' )) > 0 ) { // split round robin groups if( strcmp( gtokens[0], "%meid" ) == 0 ) { @@ -350,7 +349,7 @@ static void build_entry( uta_ctx_t* ctx, char* ts_field, uint32_t subid, char* r if( (ntoks = uta_rmip_tokenise( gtokens[grp], ctx->ip_list, tokens, 64, ',' )) > 0 ) { // remove any referneces to our ip addrs for( i = 0; i < ntoks; i++ ) { if( strcmp( tokens[i], ctx->my_name ) != 0 ) { // don't add if it is us -- cannot send to ourself - if( DEBUG > 1 || (vlevel > 1)) fprintf( stderr, "[DBUG] add endpoint ts=%s %s\n", ts_field, tokens[i] ); + if( DEBUG > 1 || (vlevel > 1)) rmr_vlog_force( RMR_VL_DEBUG, "add endpoint ts=%s %s\n", ts_field, tokens[i] ); uta_add_ep( ctx->new_rtable, rte, tokens[i], grp ); } } @@ -359,7 +358,7 @@ static void build_entry( uta_ctx_t* ctx, char* ts_field, uint32_t subid, char* r } } else { if( DEBUG || (vlevel > 2) ) { - fprintf( stderr, "entry not included, sender not matched: %s\n", tokens[1] ); + rmr_vlog_force( RMR_VL_DEBUG, "entry not included, sender not matched: %s\n", tokens[1] ); } } } @@ -392,17 +391,17 @@ static void trash_entry( uta_ctx_t* ctx, char* ts_field, uint32_t subid, int vle rte = rmr_sym_pull( ctx->new_rtable->hash, key ); // get it if( rte != NULL ) { if( DEBUG || (vlevel > 1) ) { - fprintf( stderr, "[DBUG] delete rte for mtype=%s subid=%d key=%08lx\n", ts_field, subid, key ); + rmr_vlog_force( RMR_VL_DEBUG, "delete rte for mtype=%s subid=%d key=%08lx\n", ts_field, subid, key ); } rmr_sym_ndel( ctx->new_rtable->hash, key ); // clear from the new table del_rte( NULL, NULL, NULL, rte, NULL ); // clean up the memory: reduce ref and free if ref == 0 } else { if( DEBUG || (vlevel > 1) ) { - fprintf( stderr, "[DBUG] delete could not find rte for mtype=%s subid=%d key=%lx\n", ts_field, subid, key ); + rmr_vlog_force( RMR_VL_DEBUG, "delete could not find rte for mtype=%s subid=%d key=%lx\n", ts_field, subid, key ); } } } else { - if( DEBUG ) fprintf( stderr, "[DBUG] delete rte skipped: %s\n", ts_field ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "delete rte skipped: %s\n", ts_field ); } } @@ -432,10 +431,9 @@ static void parse_meid_ar( route_table_t* rtab, char* owner, char* meid_list, in for( i = 0; i < ntoks; i++ ) { if( (ep = rt_ensure_ep( rtab, owner )) != NULL ) { state = rmr_sym_put( rtab->hash, tokens[i], RT_ME_SPACE, ep ); // slam this one in if new; replace if there - if( DEBUG || (vlevel > 1) ) fprintf( stderr, "[DBUG] parse_meid_ar: add/replace meid: %s owned by: %s state=%d\n", tokens[i], owner, state ); -fprintf( stderr, "[DBUG] parse_meid_ar: add/replace meid: %s owned by: %s state=%d\n", tokens[i], owner, state ); + if( DEBUG || (vlevel > 1) ) rmr_vlog_force( RMR_VL_DEBUG, "parse_meid_ar: add/replace meid: %s owned by: %s state=%d\n", tokens[i], owner, state ); } else { - fprintf( stderr, "[WRN] rmr parse_meid_ar: unable to create an endpoint for owner: %s", owner ); + rmr_vlog( RMR_VL_WARN, "rmr parse_meid_ar: unable to create an endpoint for owner: %s", owner ); } } } @@ -464,7 +462,7 @@ static void parse_meid_del( route_table_t* rtab, char* meid_list, int vlevel ) { ntoks = uta_tokenise( meid_list, tokens, 128, ' ' ); for( i = 0; i < ntoks; i++ ) { rmr_sym_del( rtab->hash, tokens[i], RT_ME_SPACE ); // and it only took my little finger to blow it away! - if( DEBUG || (vlevel > 1) ) fprintf( stderr, "[DBUG] parse_meid_del: meid deleted: %s\n", tokens[i] ); + if( DEBUG || (vlevel > 1) ) rmr_vlog_force( RMR_VL_DEBUG, "parse_meid_del: meid deleted: %s\n", tokens[i] ); } } @@ -478,7 +476,7 @@ static void meid_parser( uta_ctx_t* ctx, char** tokens, int ntoks, int vlevel ) } if( ntoks < 2 ) { // must have at least two for any valid request record - fprintf( stderr, "[ERR] meid_parse: not enough tokens on %s record\n", tokens[0] ); + rmr_vlog( RMR_VL_ERR, "meid_parse: not enough tokens on %s record\n", tokens[0] ); return; } @@ -486,24 +484,24 @@ static void meid_parser( uta_ctx_t* ctx, char** tokens, int ntoks, int vlevel ) tokens[1] = clip( tokens[1] ); if( *(tokens[1]) == 's' ) { if( ctx->new_rtable != NULL ) { // one in progress? this forces it out - if( DEBUG > 1 || (vlevel > 1) ) fprintf( stderr, "[DBUG] meid map start: dropping incomplete table\n" ); + if( DEBUG > 1 || (vlevel > 1) ) rmr_vlog_force( RMR_VL_DEBUG, "meid map start: dropping incomplete table\n" ); uta_rt_drop( ctx->new_rtable ); } ctx->new_rtable = uta_rt_clone_all( ctx->rtable ); // start with a clone of everything (mtype, endpoint refs and meid) ctx->new_rtable->mupdates = 0; - if( DEBUG || (vlevel > 1) ) fprintf( stderr, "[DBUG] meid_parse: meid map start found\n" ); + if( DEBUG || (vlevel > 1) ) rmr_vlog_force( RMR_VL_DEBUG, "meid_parse: meid map start found\n" ); } else { if( strcmp( tokens[1], "end" ) == 0 ) { // wrap up the table we were building if( ntoks > 2 ) { // meid_map | end | |??? given if( ctx->new_rtable->mupdates != atoi( tokens[2] ) ) { // count they added didn't match what we received - fprintf( stderr, "[ERR] meid_parse: meid map update had wrong number of records: received %d expected %s\n", ctx->new_rtable->mupdates, tokens[2] ); + rmr_vlog( RMR_VL_ERR, "meid_parse: meid map update had wrong number of records: received %d expected %s\n", ctx->new_rtable->mupdates, tokens[2] ); uta_rt_drop( ctx->new_rtable ); ctx->new_rtable = NULL; return; } - if( DEBUG ) fprintf( stderr, "[DBUG] meid_parse: meid map update ended; found expected number of entries: %s\n", tokens[2] ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "meid_parse: meid map update ended; found expected number of entries: %s\n", tokens[2] ); } if( ctx->new_rtable ) { @@ -511,16 +509,16 @@ static void meid_parser( uta_ctx_t* ctx, char** tokens, int ntoks, int vlevel ) ctx->old_rtable = ctx->rtable; // currently active becomes old and allowed to 'drain' ctx->rtable = ctx->new_rtable; // one we've been adding to becomes active ctx->new_rtable = NULL; - if( DEBUG > 1 || (vlevel > 1) ) fprintf( stderr, "[DBUG] end of meid map noticed\n" ); + if( DEBUG > 1 || (vlevel > 1) ) rmr_vlog_force( RMR_VL_DEBUG, "end of meid map noticed\n" ); if( vlevel > 0 ) { - fprintf( stderr, "[DBUG] old route table:\n" ); + rmr_vlog_force( RMR_VL_DEBUG, "old route table:\n" ); rt_stats( ctx->old_rtable ); - fprintf( stderr, "[DBUG] new route table:\n" ); + rmr_vlog_force( RMR_VL_DEBUG, "new route table:\n" ); rt_stats( ctx->rtable ); } } else { - if( DEBUG ) fprintf( stderr, "[DBUG] end of meid map noticed, but one was not started!\n" ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "end of meid map noticed, but one was not started!\n" ); ctx->new_rtable = NULL; } } @@ -530,13 +528,13 @@ static void meid_parser( uta_ctx_t* ctx, char** tokens, int ntoks, int vlevel ) } if( ! ctx->new_rtable ) { // for any other mmap entries, there must be a table in progress or we punt - if( DEBUG ) fprintf( stderr, "[DBUG] meid update/delte (%s) encountered, but table update not started\n", tokens[0] ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "meid update/delte (%s) encountered, but table update not started\n", tokens[0] ); return; } if( strcmp( tokens[0], "mme_ar" ) == 0 ) { if( ntoks < 3 || tokens[1] == NULL || tokens[2] == NULL ) { - fprintf( stderr, "[ERR] meid_parse: mme_ar record didn't have enough tokens found %d\n", ntoks ); + rmr_vlog( RMR_VL_ERR, "meid_parse: mme_ar record didn't have enough tokens found %d\n", ntoks ); return; } parse_meid_ar( ctx->new_rtable, tokens[1], tokens[2], vlevel ); @@ -545,7 +543,7 @@ static void meid_parser( uta_ctx_t* ctx, char** tokens, int ntoks, int vlevel ) if( strcmp( tokens[0], "mme_del" ) == 0 ) { if( ntoks < 2 ) { - fprintf( stderr, "[ERR] meid_parse: mme_del record didn't have enough tokens\n" ); + rmr_vlog( RMR_VL_ERR, "meid_parse: mme_del record didn't have enough tokens\n" ); return; } parse_meid_del( ctx->new_rtable, tokens[1], vlevel ); @@ -621,7 +619,7 @@ static void parse_rt_rec( uta_ctx_t* ctx, char* buf, int vlevel ) { } if( ntoks < 3 ) { - if( DEBUG ) fprintf( stderr, "[WRN] rmr_rtc: del record had too few fields: %d instead of 3\n", ntoks ); + if( DEBUG ) rmr_vlog( RMR_VL_WARN, "rmr_rtc: del record had too few fields: %d instead of 3\n", ntoks ); break; } @@ -637,27 +635,27 @@ static void parse_rt_rec( uta_ctx_t* ctx, char* buf, int vlevel ) { ctx->old_rtable = ctx->rtable; // currently active becomes old and allowed to 'drain' ctx->rtable = ctx->new_rtable; // one we've been adding to becomes active ctx->new_rtable = NULL; - if( DEBUG > 1 || (vlevel > 1) ) fprintf( stderr, "[DBUG] end of route table noticed\n" ); + if( DEBUG > 1 || (vlevel > 1) ) rmr_vlog( RMR_VL_DEBUG, "end of route table noticed\n" ); if( vlevel > 0 ) { - fprintf( stderr, "[DBUG] old route table:\n" ); + rmr_vlog_force( RMR_VL_DEBUG, "old route table:\n" ); rt_stats( ctx->old_rtable ); - fprintf( stderr, "[DBUG] new route table:\n" ); + rmr_vlog_force( RMR_VL_DEBUG, "new route table:\n" ); rt_stats( ctx->rtable ); } } else { - if( DEBUG > 1 ) fprintf( stderr, "[DBUG] end of route table noticed, but one was not started!\n" ); + if( DEBUG > 1 ) rmr_vlog_force( RMR_VL_DEBUG, "end of route table noticed, but one was not started!\n" ); ctx->new_rtable = NULL; } } else { // start a new table. if( ctx->new_rtable != NULL ) { // one in progress? this forces it out - if( DEBUG > 1 || (vlevel > 1) ) fprintf( stderr, "[DBUG] new table; dropping incomplete table\n" ); + if( DEBUG > 1 || (vlevel > 1) ) rmr_vlog_force( RMR_VL_DEBUG, "new table; dropping incomplete table\n" ); uta_rt_drop( ctx->new_rtable ); } ctx->new_rtable = NULL; ctx->new_rtable = uta_rt_clone( ctx->rtable ); // create by cloning endpoint and meidtentries from active table - if( DEBUG > 1 || (vlevel > 1) ) fprintf( stderr, "[DBUG] start of route table noticed\n" ); + if( DEBUG > 1 || (vlevel > 1) ) rmr_vlog_force( RMR_VL_DEBUG, "start of route table noticed\n" ); } break; @@ -668,7 +666,7 @@ static void parse_rt_rec( uta_ctx_t* ctx, char* buf, int vlevel ) { } if( ntoks < 4 ) { - if( DEBUG ) fprintf( stderr, "[WRN] rmr_rtc: mse record had too few fields: %d instead of 4\n", ntoks ); + if( DEBUG ) rmr_vlog( RMR_VL_WARN, "rmr_rtc: mse record had too few fields: %d instead of 4\n", ntoks ); break; } @@ -701,7 +699,7 @@ static void parse_rt_rec( uta_ctx_t* ctx, char* buf, int vlevel ) { if( ntoks >2 ) { if( ctx->new_rtable->updates != atoi( tokens[2] ) ) { // count they added didn't match what we received - fprintf( stderr, "[ERR] rmr_rtc: RT update had wrong number of records: received %d expected %s\n", + rmr_vlog( RMR_VL_ERR, "rmr_rtc: RT update had wrong number of records: received %d expected %s\n", ctx->new_rtable->updates, tokens[2] ); uta_rt_drop( ctx->new_rtable ); ctx->new_rtable = NULL; @@ -714,32 +712,32 @@ static void parse_rt_rec( uta_ctx_t* ctx, char* buf, int vlevel ) { ctx->old_rtable = ctx->rtable; // currently active becomes old and allowed to 'drain' ctx->rtable = ctx->new_rtable; // one we've been adding to becomes active ctx->new_rtable = NULL; - if( DEBUG > 1 || (vlevel > 1) ) fprintf( stderr, "[DBUG] end of rt update noticed\n" ); + if( DEBUG > 1 || (vlevel > 1) ) rmr_vlog_force( RMR_VL_DEBUG, "end of rt update noticed\n" ); if( vlevel > 0 ) { - fprintf( stderr, "[DBUG] old route table:\n" ); + rmr_vlog_force( RMR_VL_DEBUG, "old route table:\n" ); rt_stats( ctx->old_rtable ); - fprintf( stderr, "[DBUG] updated route table:\n" ); + rmr_vlog_force( RMR_VL_DEBUG, "updated route table:\n" ); rt_stats( ctx->rtable ); } } else { - if( DEBUG > 1 ) fprintf( stderr, "[DBUG] end of rt update noticed, but one was not started!\n" ); + if( DEBUG > 1 ) rmr_vlog_force( RMR_VL_DEBUG, "end of rt update noticed, but one was not started!\n" ); ctx->new_rtable = NULL; } } else { // start a new table. if( ctx->new_rtable != NULL ) { // one in progress? this forces it out - if( DEBUG > 1 || (vlevel > 1) ) fprintf( stderr, "[DBUG] new table; dropping incomplete table\n" ); + if( DEBUG > 1 || (vlevel > 1) ) rmr_vlog_force( RMR_VL_DEBUG, "new table; dropping incomplete table\n" ); uta_rt_drop( ctx->new_rtable ); } ctx->new_rtable = uta_rt_clone_all( ctx->rtable ); // start with a clone of everything (endpts and entries) ctx->new_rtable->updates = 0; // init count of updates received - if( DEBUG > 1 || (vlevel > 1) ) fprintf( stderr, "[DBUG] start of rt update noticed\n" ); + if( DEBUG > 1 || (vlevel > 1) ) rmr_vlog_force( RMR_VL_DEBUG, "start of rt update noticed\n" ); } break; default: - if( DEBUG ) fprintf( stderr, "[WRN] rmr_rtc: unrecognised request: %s\n", tokens[0] ); + if( DEBUG ) rmr_vlog( RMR_VL_WARN, "rmr_rtc: unrecognised request: %s\n", tokens[0] ); break; } } @@ -767,11 +765,11 @@ static void read_static_rt( uta_ctx_t* ctx, int vlevel ) { } if( (fbuf = ensure_nlterm( uta_fib( fname ) ) ) == NULL ) { // read file into a single buffer (nil terminated string) - fprintf( stderr, "[WRN] rmr read_static: seed route table could not be opened: %s: %s\n", fname, strerror( errno ) ); + rmr_vlog( RMR_VL_WARN, "rmr read_static: seed route table could not be opened: %s: %s\n", fname, strerror( errno ) ); return; } - if( DEBUG ) fprintf( stderr, "[DBUG] rmr: seed route table successfully opened: %s\n", fname ); + if( DEBUG ) rmr_vlog_force( RMR_VL_DEBUG, "seed route table successfully opened: %s\n", fname ); for( eor = fbuf; *eor; eor++ ) { // fix broken systems that use \r or \r\n to terminate records if( *eor == '\r' ) { *eor = '\n'; // will look like a blank line which is ok @@ -783,8 +781,8 @@ static void read_static_rt( uta_ctx_t* ctx, int vlevel ) { if( (eor = strchr( rec, '\n' )) != NULL ) { *eor = 0; } else { - fprintf( stderr, "[WRN] rmr read_static: seed route table had malformed records (missing newline): %s\n", fname ); - fprintf( stderr, "[WRN] rmr read_static: seed route table not used: %s\n", fname ); + rmr_vlog( RMR_VL_WARN, "rmr read_static: seed route table had malformed records (missing newline): %s\n", fname ); + rmr_vlog( RMR_VL_WARN, "rmr read_static: seed route table not used: %s\n", fname ); free( fbuf ); return; } @@ -792,7 +790,7 @@ static void read_static_rt( uta_ctx_t* ctx, int vlevel ) { parse_rt_rec( ctx, rec, vlevel ); } - if( DEBUG ) fprintf( stderr, "[DBUG] rmr_read_static: seed route table successfully parsed: %d records\n", rcount ); + if( DEBUG ) rmr_vlog_force( RMR_VL_DEBUG, "rmr_read_static: seed route table successfully parsed: %d records\n", rcount ); free( fbuf ); } @@ -980,7 +978,7 @@ static route_table_t* rt_clone_space( route_table_t* srt, route_table_t* nrt, in rmr_sym_foreach_class( sst, space, collect_things, &things ); // collect things from this space - if( DEBUG ) fprintf( stderr, "[DBUG] clone space cloned %d things in space %d\n", things.nused, space ); + if( DEBUG ) rmr_vlog_force( RMR_VL_DEBUG, "clone space cloned %d things in space %d\n", things.nused, space ); for( i = 0; i < things.nused; i++ ) { if( space ) { // string key, epoint reference ep = (endpoint_t *) things.things[i]; @@ -1074,14 +1072,14 @@ static endpoint_t* rt_ensure_ep( route_table_t* rt, char const* ep_name ) { endpoint_t* ep; if( !rt || !ep_name || ! *ep_name ) { - fprintf( stderr, "[WRN] rmr: rt_ensure: internal mishap, something undefined rt=%p ep_name=%p\n", rt, ep_name ); + rmr_vlog( RMR_VL_WARN, "rt_ensure: internal mishap, something undefined rt=%p ep_name=%p\n", rt, ep_name ); errno = EINVAL; return NULL; } if( (ep = uta_get_ep( rt, ep_name )) == NULL ) { // not there yet, make if( (ep = (endpoint_t *) malloc( sizeof( *ep ) )) == NULL ) { - fprintf( stderr, "[WRN] rmr: rt_ensure: malloc failed for endpoint creation: %s\n", ep_name ); + rmr_vlog( RMR_VL_WARN, "rt_ensure: malloc failed for endpoint creation: %s\n", ep_name ); errno = ENOMEM; return NULL; } diff --git a/src/rmr/common/src/rtc_static.c b/src/rmr/common/src/rtc_static.c index 58fc940..b411dbe 100644 --- a/src/rmr/common/src/rtc_static.c +++ b/src/rmr/common/src/rtc_static.c @@ -127,7 +127,7 @@ static void* rtc( void* vctx ) { if( (ctx = (uta_ctx_t *) vctx) == NULL ) { - fprintf( stderr, "[CRI] rmr_rtc: internal mishap: context passed in was nil\n" ); + rmr_vlog( RMR_VL_CRIT, "rmr_rtc: internal mishap: context passed in was nil\n" ); return NULL; } @@ -166,7 +166,7 @@ static void* rtc( void* vctx ) { } if( (pvt_cx = init( port, MAX_RTG_MSG_SZ, FL_NOTHREAD )) == NULL ) { // open a private context - fprintf( stderr, "[CRI] rmr_rtc: unable to initialise listen port for RTG (pvt_cx)\n" ); + rmr_vlog( RMR_VL_CRIT, "rmr_rtc: unable to initialise listen port for RTG (pvt_cx)\n" ); while( TRUE ) { // no listen port, just dump counts now and then sleep( count_delay ); @@ -179,24 +179,24 @@ static void* rtc( void* vctx ) { if( (rcv_fd = rmr_get_rcvfd( pvt_cx )) >= 0 ) { // get the epoll fd for the rtg socket if( rcv_fd < 0 ) { - fprintf( stderr, "[WARN] cannot get epoll fd for rtg session; stats will generate only after update from rt manager\n" ); + rmr_vlog( RMR_VL_WARN, "cannot get epoll fd for rtg session; stats will generate only after update from rt manager\n" ); } else { if( (epfd = epoll_create1( 0 )) < 0 ) { - fprintf( stderr, "[WARN] stats will generate only after rt manager update; unable to create epoll fd for rtg session: %s\n", strerror( errno ) ); + rmr_vlog( RMR_VL_WARN, "stats will generate only after rt manager update; unable to create epoll fd for rtg session: %s\n", strerror( errno ) ); rcv_fd = -1; } else { epe.events = EPOLLIN; epe.data.fd = rcv_fd; if( epoll_ctl( epfd, EPOLL_CTL_ADD, rcv_fd, &epe ) != 0 ) { - fprintf( stderr, "[WARN] stats will generate only after rt manager update; unable to init epoll_ctl: %s\n", strerror( errno ) ); + rmr_vlog( RMR_VL_WARN, "stats will generate only after rt manager update; unable to init epoll_ctl: %s\n", strerror( errno ) ); rcv_fd = -1; } } } } - if( DEBUG ) fprintf( stderr, "[DBUG] rtc thread is running and listening; listening for rtg conns on %s\n", port ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "rtc thread is running and listening; listening for rtg conns on %s\n", port ); free( fport ); // future: if we need to register with the rtg, then build a message and send it through a wormhole here @@ -236,9 +236,9 @@ static void* rtc( void* vctx ) { payload = msg->payload; mlen = msg->len; // usable bytes in the payload if( vlevel > 1 ) { - fprintf( stderr, "[DBUG] rmr_rtc: received rt message; %d bytes (%s)\n", (int) mlen, msg->payload ); + rmr_vlog( RMR_VL_DEBUG, "rmr_rtc: received rt message; %d bytes (%s)\n", (int) mlen, msg->payload ); } else { - if( DEBUG > 1 || (vlevel > 0) ) fprintf( stderr, "[DBUG] rmr_rtc: received rt message; %d bytes\n", (int) mlen ); + if( DEBUG > 1 || (vlevel > 0) ) rmr_vlog( RMR_VL_DEBUG, "rmr_rtc: received rt message; %d bytes\n", (int) mlen ); } if( pbuf_size <= mlen ) { @@ -264,7 +264,7 @@ static void* rtc( void* vctx ) { } if( vlevel > 1 ) { - fprintf( stderr, "[DBUG] rmr_rtc: processing (%s)\n", curr ); + rmr_vlog( RMR_VL_DEBUG, "rmr_rtc: processing (%s)\n", curr ); } parse_rt_rec( ctx, curr, vlevel ); // parse record and add to in progress table diff --git a/src/rmr/common/src/symtab.c b/src/rmr/common/src/symtab.c index 4820ebd..43acfa1 100644 --- a/src/rmr/common/src/symtab.c +++ b/src/rmr/common/src/symtab.c @@ -1,8 +1,8 @@ // : vi ts=4 sw=4 noet : /* ================================================================================== - Copyright (c) 2019 Nokia - Copyright (c) 2018-2019 AT&T Intellectual Property. + Copyright (c) 2019-2020 Nokia + Copyright (c) 2018-2020 AT&T Intellectual Property. Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with the License. @@ -33,6 +33,10 @@ Abstract: Symbol table -- slightly streamlined from it's original 2000 version incorporated into the RIC msg routing library and will be available to user applications. + There is NO logging from this module! The caller is asusmed to + report any failures as it might handle them making any error messages + generated here misleading if not incorrect. + Date: 11 Feb 2000 Author: E. Scott Daniels @@ -42,6 +46,7 @@ Mod: 2016 23 Feb - converted Symtab refs so that caller need only a ------------------------------------------------------------------------------ */ +#include #include #include #include @@ -161,7 +166,7 @@ static int putin( Sym_tab *table, const char *name, unsigned int class, void *va eptr = (Sym_ele *) malloc( sizeof( Sym_ele) ); if( ! eptr ) { - fprintf( stderr, "[FAIL] symtab/putin: out of memory\n" ); + errno = ENOMEM; return -1; } @@ -237,9 +242,9 @@ extern void rmr_sym_dump( void *vtable ) for( eptr = sym_tab[i]; eptr; eptr = eptr->next ) { if( eptr->val && eptr->class ) { - fprintf( stderr, "key=%s val@=%p\n", eptr->name, eptr->val ); + fprintf( stderr, "symtab dump: key=%s val@=%p\n", eptr->name, eptr->val ); } else { - fprintf( stderr, "nkey=%lu val@=%p\n", (unsigned long) eptr->nkey, eptr->val ); + fprintf( stderr, "symtab dump: nkey=%lu val@=%p\n", (unsigned long) eptr->nkey, eptr->val ); } } } @@ -259,7 +264,7 @@ extern void *rmr_sym_alloc( int size ) if( (table = (Sym_tab *) malloc( sizeof( Sym_tab ))) == NULL ) { - fprintf( stderr, "rmr_sym_alloc: unable to get memory for symtable (%d elements)", size ); + errno = ENOMEM; return NULL; } @@ -272,7 +277,7 @@ extern void *rmr_sym_alloc( int size ) } else { - fprintf( stderr, "sym_alloc: unable to get memory for %d elements", size ); + errno = ENOMEM; return NULL; } @@ -410,9 +415,9 @@ extern void rmr_sym_stats( void *vtable, int level ) ch_count++; if( level > 3 ) { if( eptr->class ) { // a string key - fprintf( stderr, "sym: (%d) key=%s val@=%p ref=%ld mod=%lu\n", i, eptr->name, eptr->val, eptr->rcount, eptr->mcount ); + fprintf( stderr, " symtab stats: sym: (%d) key=%s val@=%p ref=%ld mod=%lu\n", i, eptr->name, eptr->val, eptr->rcount, eptr->mcount ); } else { - fprintf( stderr, "sym: (%d) key=%lu val@=%p ref=%ld mod=%lu\n", i, (unsigned long) eptr->nkey, eptr->val, eptr->rcount, eptr->mcount ); + fprintf( stderr, "symtab stats: sym: (%d) key=%lu val@=%p ref=%ld mod=%lu\n", i, (unsigned long) eptr->nkey, eptr->val, eptr->rcount, eptr->mcount ); } } } @@ -429,12 +434,12 @@ extern void rmr_sym_stats( void *vtable, int level ) twoper++; if( level > 2 ) - fprintf( stderr, "sym: (%d) chained=%ld\n", i, ch_count ); + fprintf( stderr, "symtab stats: sym: (%d) chained=%ld\n", i, ch_count ); } if( level > 1 ) { - fprintf( stderr, "sym: longest chain: idx=%d has %ld elsements):\n", maxi, max_chain ); + fprintf( stderr, "symtab stats: sym: longest chain: idx=%d has %ld elsements):\n", maxi, max_chain ); for( eptr = sym_tab[maxi]; eptr; eptr = eptr->next ) { if( eptr->class ) { fprintf( stderr, "\t%s\n", eptr->name ); @@ -444,7 +449,7 @@ extern void rmr_sym_stats( void *vtable, int level ) } } - fprintf( stderr, "sym:%ld(size) %ld(inhab) %ld(occupied) %ld(dead) %ld(maxch) %d(>2per)\n", + fprintf( stderr, "symtab stats: sym:%ld(size) %ld(inhab) %ld(occupied) %ld(dead) %ld(maxch) %d(>2per)\n", table->size, table->inhabitants, table->size - empty, table->deaths, max_chain, twoper ); } diff --git a/src/rmr/common/src/tools_static.c b/src/rmr/common/src/tools_static.c index 3aa5c43..2adf9a5 100644 --- a/src/rmr/common/src/tools_static.c +++ b/src/rmr/common/src/tools_static.c @@ -150,7 +150,7 @@ static char* uta_h2ip( char const* hname ) { hent = gethostbyname( dname ); if( hent == NULL || hent->h_addr_list == NULL ) { - //fprintf( stderr, "[WRN] h2ip: dns lookup failed for: %s\n", dname ); + //rmr_vlog( RMR_VL_WARN, "h2ip: dns lookup failed for: %s\n", dname ); free( dname ); return NULL; } @@ -314,7 +314,7 @@ if_addrs_t* mk_ip_list( char* port ) { snprintf( wbuf, sizeof( wbuf ), "%s:%s", envp, port ); // smash port onto the addr as is l->addrs[l->naddrs] = strdup( wbuf ); l->naddrs++; - if( DEBUG ) fprintf( stderr, "[INFO] rmr: using only specific bind interface when searching specific RT entries: %s\n", wbuf ); + if( DEBUG ) rmr_vlog( RMR_VL_INFO, "rmr: using only specific bind interface when searching specific RT entries: %s\n", wbuf ); return l; } @@ -342,7 +342,7 @@ if_addrs_t* mk_ip_list( char* port ) { *tok = 0; } if( l->naddrs < 128 ) { - if( DEBUG ) fprintf( stderr, "[DBUG] capture address: %s: %s\n", ele->ifa_name, octs ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "capture address: %s: %s\n", ele->ifa_name, octs ); snprintf( wbuf, sizeof( wbuf ), fmt, octs, port ); // smash port onto the addr l->addrs[l->naddrs] = strdup( wbuf ); diff --git a/src/rmr/common/src/wormholes.c b/src/rmr/common/src/wormholes.c index 2bc5c9f..1167c25 100644 --- a/src/rmr/common/src/wormholes.c +++ b/src/rmr/common/src/wormholes.c @@ -105,7 +105,7 @@ static int wh_init( uta_ctx_t* ctx ) { } if( (whm = malloc( sizeof( *whm ) )) == NULL ) { - fprintf( stderr, "mem alloc failed for whm: alloc %d bytes\n", (int) sizeof( *whm ) ); + rmr_vlog( RMR_VL_ERR, "mem alloc failed for whm: alloc %d bytes\n", (int) sizeof( *whm ) ); errno = ENOMEM; return 0; } @@ -113,7 +113,7 @@ static int wh_init( uta_ctx_t* ctx ) { whm->nalloc = 16; alloc_sz = whm->nalloc * sizeof( endpoint_t ); if( (whm->eps = (endpoint_t **) malloc( alloc_sz )) == NULL ) { - fprintf( stderr, "mem alloc failed: alloc %d bytes\n", (int) alloc_sz ); + rmr_vlog( RMR_VL_ERR, "mem alloc failed: alloc %d bytes\n", (int) alloc_sz ); free( whm ); errno = ENOMEM; return 0; @@ -209,7 +209,7 @@ extern rmr_whid_t rmr_wh_open( void* vctx, char const* target ) { if( (ep = rt_ensure_ep( ctx->rtable, target )) == NULL ) { // get pointer to ep if there, create new if not - fprintf( stderr, "ensure ep returned bad; setting no memory error\n" ); + rmr_vlog( RMR_VL_ERR, "wormhole_open: ensure ep returned bad: target=%s\n", target ); return -1; // ensure sets errno } @@ -275,7 +275,7 @@ extern rmr_mbuf_t* rmr_wh_send_msg( void* vctx, rmr_whid_t whid, rmr_mbuf_t* msg errno = 0; // nng seems not to set errno any longer, so ensure it's clear if( msg->header == NULL ) { - fprintf( stderr, "[ERR] rmr_wh_send_msg: message had no header\n" ); + rmr_vlog( RMR_VL_ERR, "rmr_wh_send_msg: message had no header\n" ); msg->state = RMR_ERR_NOHDR; errno = EBADMSG; // must ensure it's not eagain return msg; diff --git a/src/rmr/nng/src/mt_call_nng_static.c b/src/rmr/nng/src/mt_call_nng_static.c index 7820561..d3a914a 100644 --- a/src/rmr/nng/src/mt_call_nng_static.c +++ b/src/rmr/nng/src/mt_call_nng_static.c @@ -38,7 +38,7 @@ static inline void queue_normal( uta_ctx_t* ctx, rmr_mbuf_t* mbuf ) { if( ! uta_ring_insert( ctx->mring, mbuf ) ) { rmr_free_msg( mbuf ); // drop if ring is full if( !warned ) { - fprintf( stderr, "[WARN] rmr_mt_receive: application is not receiving fast enough; messages dropping\n" ); + rmr_vlog( RMR_VL_WARN, "rmr_mt_receive: application is not receiving fast enough; messages dropping\n" ); warned++; } @@ -80,7 +80,7 @@ static void* mt_receive( void* vctx ) { return NULL; } - fprintf( stderr, "[INFO] rmr mt_receiver is spinning\n" ); + rmr_vlog( RMR_VL_INFO, "rmr mt_receiver is spinning\n" ); while( ! ctx->shutdown ) { mbuf = rcv_msg( ctx, NULL ); diff --git a/src/rmr/nng/src/rmr_nng.c b/src/rmr/nng/src/rmr_nng.c index 720f6ad..fc72b36 100644 --- a/src/rmr/nng/src/rmr_nng.c +++ b/src/rmr/nng/src/rmr_nng.c @@ -1,8 +1,8 @@ // vim: ts=4 sw=4 noet : /* ================================================================================== - Copyright (c) 2019 Nokia - Copyright (c) 2018-2019 AT&T Intellectual Property. + Copyright (c) 2019-2020 Nokia + Copyright (c) 2018-2020 AT&T Intellectual Property. Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with the License. @@ -64,6 +64,7 @@ #include "rmr_agnostic.h" // agnostic things (must be included before private) #include "rmr_nng_private.h" // things that we need too #include "rmr_symtab.h" +#include "rmr_logging.h" #include "ring_static.c" // message ring support #include "rt_generic_static.c" // route table things not transport specific @@ -263,7 +264,7 @@ extern rmr_mbuf_t* rmr_rts_msg( void* vctx, rmr_mbuf_t* msg ) { errno = 0; // at this point any bad state is in msg returned if( msg->header == NULL ) { - fprintf( stderr, "[ERR] rmr_send_msg: message had no header\n" ); + rmr_vlog( RMR_VL_ERR, "rmr_send_msg: message had no header\n" ); msg->state = RMR_ERR_NOHDR; msg->tp_state = errno; return msg; @@ -359,7 +360,7 @@ extern rmr_mbuf_t* rmr_call( void* vctx, rmr_mbuf_t* msg ) { memcpy( expected_id, msg->xaction, RMR_MAX_XID ); expected_id[RMR_MAX_XID] = 0; // ensure it's a string - if( DEBUG > 1 ) fprintf( stderr, "[DBUG] rmr_call is making call, waiting for (%s)\n", expected_id ); + if( DEBUG > 1 ) rmr_vlog( RMR_VL_DEBUG, "rmr_call is making call, waiting for (%s)\n", expected_id ); errno = 0; msg->flags |= MFL_NOALLOC; // we don't need a new buffer from send @@ -535,29 +536,29 @@ extern rmr_mbuf_t* rmr_rcv_specific( void* vctx, rmr_mbuf_t* msg, char* expect, if( exp_len > RMR_MAX_XID ) { exp_len = RMR_MAX_XID; } - if( DEBUG ) fprintf( stderr, "[DBUG] rcv_specific waiting for id=%s\n", expect ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "rcv_specific waiting for id=%s\n", expect ); while( queued < allow2queue ) { msg = rcv_msg( ctx, msg ); // hard wait for next if( msg->state == RMR_OK ) { if( memcmp( msg->xaction, expect, exp_len ) == 0 ) { // got it -- return it - if( DEBUG ) fprintf( stderr, "[DBUG] rcv-specific matched (%s); %d messages were queued\n", msg->xaction, queued ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "rcv-specific matched (%s); %d messages were queued\n", msg->xaction, queued ); return msg; } if( ! uta_ring_insert( ctx->mring, msg ) ) { // just queue, error if ring is full - if( DEBUG > 1 ) fprintf( stderr, "[DBUG] rcv_specific ring is full\n" ); + if( DEBUG > 1 ) rmr_vlog( RMR_VL_DEBUG, "rcv_specific ring is full\n" ); errno = ENOBUFS; return NULL; } - if( DEBUG ) fprintf( stderr, "[DBUG] rcv_specific queued message type=%d\n", msg->mtype ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "rcv_specific queued message type=%d\n", msg->mtype ); queued++; msg = NULL; } } - if( DEBUG ) fprintf( stderr, "[DBUG] rcv_specific timeout waiting for %s\n", expect ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "rcv_specific timeout waiting for %s\n", expect ); errno = ETIMEDOUT; return NULL; } @@ -599,7 +600,7 @@ extern int rmr_set_stimeout( void* vctx, int time ) { CAUTION: this is not supported as they must be set differently (between create and open) in NNG. */ extern int rmr_set_rtimeout( void* vctx, int time ) { - fprintf( stderr, "[WRN] Current implementation of RMR ontop of NNG does not support setting a receive timeout\n" ); + rmr_vlog( RMR_VL_WARN, "Current implementation of RMR ontop of NNG does not support setting a receive timeout\n" ); return 0; } @@ -623,12 +624,17 @@ static void* init( char* uproto_port, int max_msg_size, int flags ) { char* tok; // pointer at token in a buffer char* tok2; int state; + int old_vlevel = 0; + + old_vlevel = rmr_vlog_init(); // initialise and get the current level + rmr_set_vlevel( RMR_VL_INFO ); // we WILL announce our version etc if( ! announced ) { - fprintf( stderr, "[INFO] ric message routing library on NNG mv=%d flg=%02x (%s %s.%s.%s built: %s)\n", + rmr_vlog( RMR_VL_INFO, "ric message routing library on NNG mv=%d flg=%02x (%s %s.%s.%s built: %s)\n", RMR_MSG_VER, flags, QUOTE_DEF(GIT_ID), QUOTE_DEF(MAJOR_VER), QUOTE_DEF(MINOR_VER), QUOTE_DEF(PATCH_VER), __DATE__ ); announced = 1; } + rmr_set_vlevel( old_vlevel ); // return logging to the desired state errno = 0; if( uproto_port == NULL ) { @@ -662,7 +668,7 @@ static void* init( char* uproto_port, int max_msg_size, int flags ) { //uta_lookup_rtg( ctx ); // attempt to fill in rtg info; rtc will handle missing values/errors if( nng_pull0_open( &ctx->nn_sock ) != 0 ) { // and assign the mode - fprintf( stderr, "[CRI] rmr_init: unable to initialise nng listen (pull) socket: %d\n", errno ); + rmr_vlog( RMR_VL_CRIT, "rmr_init: unable to initialise nng listen (pull) socket: %d\n", errno ); free_ctx( ctx ); return NULL; } @@ -693,7 +699,7 @@ static void* init( char* uproto_port, int max_msg_size, int flags ) { free( tok ); } else { if( (gethostname( wbuf, sizeof( wbuf ) )) != 0 ) { - fprintf( stderr, "[CRI] rmr_init: cannot determine localhost name: %s\n", strerror( errno ) ); + rmr_vlog( RMR_VL_CRIT, "rmr_init: cannot determine localhost name: %s\n", strerror( errno ) ); return NULL; } if( (tok = strchr( wbuf, '.' )) != NULL ) { @@ -703,7 +709,7 @@ static void* init( char* uproto_port, int max_msg_size, int flags ) { ctx->my_name = (char *) malloc( sizeof( char ) * RMR_MAX_SRC ); if( snprintf( ctx->my_name, RMR_MAX_SRC, "%s:%s", wbuf, port ) >= RMR_MAX_SRC ) { // our registered name is host:port - fprintf( stderr, "[CRI] rmr_init: hostname + port must be less than %d characters; %s:%s is not\n", RMR_MAX_SRC, wbuf, port ); + rmr_vlog( RMR_VL_CRIT, "rmr_init: hostname + port must be less than %d characters; %s:%s is not\n", RMR_MAX_SRC, wbuf, port ); return NULL; } @@ -719,11 +725,11 @@ static void* init( char* uproto_port, int max_msg_size, int flags ) { } else { ctx->my_ip = get_default_ip( ctx->ip_list ); // and (guess) at what should be the default to put into messages as src if( ctx->my_ip == NULL ) { - fprintf( stderr, "[WRN] rmr_init: default ip address could not be sussed out, using name\n" ); + rmr_vlog( RMR_VL_WARN, "rmr_init: default ip address could not be sussed out, using name\n" ); strcpy( ctx->my_ip, ctx->my_name ); // if we cannot suss it out, use the name rather than a nil pointer } } - if( DEBUG ) fprintf( stderr, "[DBUG] default ip address: %s\n", ctx->my_ip ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "default ip address: %s\n", ctx->my_ip ); if( (tok = getenv( ENV_WARNINGS )) != NULL ) { if( *tok == '1' ) { @@ -739,7 +745,7 @@ static void* init( char* uproto_port, int max_msg_size, int flags ) { // rather than using this generic listen() call. snprintf( bind_info, sizeof( bind_info ), "%s://%s:%s", proto, interface, port ); if( (state = nng_listen( ctx->nn_sock, bind_info, NULL, NO_FLAGS )) != 0 ) { - fprintf( stderr, "[CRI] rmr_init: unable to start nng listener for %s: %s\n", bind_info, nng_strerror( state ) ); + rmr_vlog( RMR_VL_CRIT, "rmr_init: unable to start nng listener for %s: %s\n", bind_info, nng_strerror( state ) ); nng_close( ctx->nn_sock ); free_ctx( ctx ); return NULL; @@ -747,14 +753,14 @@ static void* init( char* uproto_port, int max_msg_size, int flags ) { if( !(flags & FL_NOTHREAD) ) { // skip if internal function that doesnt need an rtc if( pthread_create( &ctx->rtc_th, NULL, rtc, (void *) ctx ) ) { // kick the rt collector thread - fprintf( stderr, "[WRN] rmr_init: unable to start route table collector thread: %s", strerror( errno ) ); + rmr_vlog( RMR_VL_WARN, "rmr_init: unable to start route table collector thread: %s", strerror( errno ) ); } } if( (flags & RMRFL_MTCALL) && ! (ctx->flags & CFL_MTC_ENABLED) ) { // mt call support is on, must start the listener thread if not running ctx->flags |= CFL_MTC_ENABLED; if( pthread_create( &ctx->mtc_th, NULL, mt_receive, (void *) ctx ) ) { // kick the receiver - fprintf( stderr, "[WRN] rmr_init: unable to start multi-threaded receiver: %s", strerror( errno ) ); + rmr_vlog( RMR_VL_WARN, "rmr_init: unable to start multi-threaded receiver: %s", strerror( errno ) ); } } @@ -836,7 +842,7 @@ extern int rmr_get_rcvfd( void* vctx ) { } if( (state = nng_getopt_int( ctx->nn_sock, NNG_OPT_RECVFD, &fd )) != 0 ) { - fprintf( stderr, "[WRN] rmr cannot get recv fd: %s\n", nng_strerror( state ) ); + rmr_vlog( RMR_VL_WARN, "rmr cannot get recv fd: %s\n", nng_strerror( state ) ); return -1; } @@ -943,7 +949,7 @@ extern rmr_mbuf_t* rmr_mt_rcv( void* vctx, rmr_mbuf_t* mbuf, int max_wait ) { mbuf = ombuf; // return caller's buffer if they passed one in } else { errno = 0; // interrupted call state could be left; clear - if( DEBUG ) fprintf( stderr, "[DBUG] mt_rcv extracting from normal ring\n" ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "mt_rcv extracting from normal ring\n" ); if( (mbuf = (rmr_mbuf_t *) uta_ring_extract( ctx->mring )) != NULL ) { // pop if queued mbuf->state = RMR_OK; diff --git a/src/rmr/nng/src/rtable_nng_static.c b/src/rmr/nng/src/rtable_nng_static.c index f5c9b7a..6adf230 100644 --- a/src/rmr/nng/src/rtable_nng_static.c +++ b/src/rmr/nng/src/rtable_nng_static.c @@ -106,14 +106,14 @@ static int uta_link2( endpoint_t* ep ) { if( nng_push0_open( nn_sock ) != 0 ) { // and assign the mode pthread_mutex_unlock( &ep->gate ); - fprintf( stderr, "[CRI] rmr: link2: unable to initialise nanomsg push socket to: %s\n", target ); + rmr_vlog( RMR_VL_CRIT, "rmr: link2: unable to initialise nanomsg push socket to: %s\n", target ); return FALSE; } snprintf( conn_info, sizeof( conn_info ), "tcp://%s", target ); if( (state = nng_dialer_create( dialer, *nn_sock, conn_info )) != 0 ) { pthread_mutex_unlock( &ep->gate ); - fprintf( stderr, "[WRN] rmr: link2: unable to create dialer for link to target: %s: %d\n", target, errno ); + rmr_vlog( RMR_VL_WARN, "rmr: link2: unable to create dialer for link to target: %s: %d\n", target, errno ); nng_close( *nn_sock ); return FALSE; } @@ -123,12 +123,12 @@ static int uta_link2( endpoint_t* ep ) { if( (state = nng_dialer_start( *dialer, flags )) != 0 ) { // can fail immediatly (unlike nanomsg) pthread_mutex_unlock( &ep->gate ); - fprintf( stderr, "[WRN] rmr: unable to create link to target: %s: %s\n", target, nng_strerror( state ) ); + rmr_vlog( RMR_VL_WARN, "rmr: unable to create link to target: %s: %s\n", target, nng_strerror( state ) ); nng_close( *nn_sock ); return FALSE; } - if( DEBUG ) fprintf( stderr, "[INFO] rmr_link2l: dial was successful: %s\n", target ); + if( DEBUG ) rmr_vlog( RMR_VL_INFO, "rmr_link2l: dial was successful: %s\n", target ); ep->open = TRUE; // must set before release pthread_mutex_unlock( &ep->gate ); @@ -167,24 +167,24 @@ extern endpoint_t* uta_add_ep( route_table_t* rt, rtable_ent_t* rte, char* ep_n rrgroup_t* rrg; // pointer at group to update if( ! rte || ! rt ) { - fprintf( stderr, "[WRN] uda_add_ep didn't get a valid rt and/or rte pointer\n" ); + rmr_vlog( RMR_VL_WARN, "uda_add_ep didn't get a valid rt and/or rte pointer\n" ); return NULL; } if( rte->nrrgroups <= group ) { - fprintf( stderr, "[WRN] uda_add_ep group out of range: %d (max == %d)\n", group, rte->nrrgroups ); + rmr_vlog( RMR_VL_WARN, "uda_add_ep group out of range: %d (max == %d)\n", group, rte->nrrgroups ); return NULL; } if( (rrg = rte->rrgroups[group]) == NULL ) { if( (rrg = (rrgroup_t *) malloc( sizeof( *rrg ) )) == NULL ) { - fprintf( stderr, "[WRN] rmr_add_ep: malloc failed for round robin group: group=%d\n", group ); + rmr_vlog( RMR_VL_WARN, "rmr_add_ep: malloc failed for round robin group: group=%d\n", group ); return NULL; } memset( rrg, 0, sizeof( *rrg ) ); if( (rrg->epts = (endpoint_t **) malloc( sizeof( endpoint_t ) * MAX_EP_GROUP )) == NULL ) { - fprintf( stderr, "[WRN] rmr_add_ep: malloc failed for group endpoint array: group=%d\n", group ); + rmr_vlog( RMR_VL_WARN, "rmr_add_ep: malloc failed for group endpoint array: group=%d\n", group ); return NULL; } memset( rrg->epts, 0, sizeof( endpoint_t ) * MAX_EP_GROUP ); @@ -201,7 +201,7 @@ extern endpoint_t* uta_add_ep( route_table_t* rt, rtable_ent_t* rte, char* ep_n if( rrg != NULL ) { if( rrg->nused >= rrg->nendpts ) { // future: reallocate - fprintf( stderr, "[WRN] endpoint array for mtype/group %d/%d is full!\n", rte->mtype, group ); + rmr_vlog( RMR_VL_WARN, "endpoint array for mtype/group %d/%d is full!\n", rte->mtype, group ); return NULL; } @@ -209,7 +209,7 @@ extern endpoint_t* uta_add_ep( route_table_t* rt, rtable_ent_t* rte, char* ep_n rrg->nused++; } - if( DEBUG > 1 ) fprintf( stderr, "[DBUG] endpoint added to mtype/group: %d/%d %s\n", rte->mtype, group, ep_name ); + if( DEBUG > 1 ) rmr_vlog( RMR_VL_DEBUG, "endpoint added to mtype/group: %d/%d %s\n", rte->mtype, group, ep_name ); return ep; } @@ -232,14 +232,14 @@ static int uta_epsock_byname( route_table_t* rt, char* ep_name, nng_socket* nn_s *uepp = ep; } if( ep == NULL ) { - if( DEBUG ) fprintf( stderr, "[DBUG] get ep by name for %s not in hash!\n", ep_name ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "get ep by name for %s not in hash!\n", ep_name ); if( ! ep_name || (ep = rt_ensure_ep( rt, ep_name)) == NULL ) { // create one if not in rt (support rts without entry in our table) return FALSE; } } if( ! ep->open ) { // not open -- connect now - if( DEBUG ) fprintf( stderr, "[DBUG] get ep by name for %s session not started... starting\n", ep_name ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "get ep by name for %s session not started... starting\n", ep_name ); if( ep->addr == NULL ) { // name didn't resolve before, try again ep->addr = strdup( ep->name ); // use the name directly; if not IP then transport will do dns lookup } @@ -248,7 +248,7 @@ static int uta_epsock_byname( route_table_t* rt, char* ep_name, nng_socket* nn_s ep->open = TRUE; *nn_sock = ep->nn_sock; // pass socket back to caller } - if( DEBUG ) fprintf( stderr, "[DBUG] epsock_bn: connection state: %s %s\n", state ? "[OK]" : "[FAIL]", ep->name ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "epsock_bn: connection state: %s %s\n", state ? "[OK]" : "[FAIL]", ep->name ); } else { *nn_sock = ep->nn_sock; state = TRUE; @@ -355,7 +355,7 @@ static int uta_epsock_rr( rtable_ent_t *rte, int group, int* more, nng_socket* n } else { state = FALSE; } - if( DEBUG ) fprintf( stderr, "[DBUG] epsock_rr: connection attempted with %s: %s\n", ep->name, state ? "[OK]" : "[FAIL]" ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "epsock_rr: connection attempted with %s: %s\n", ep->name, state ? "[OK]" : "[FAIL]" ); } else { *nn_sock = ep->nn_sock; } @@ -463,7 +463,7 @@ static int epsock_meid( route_table_t *rtable, rmr_mbuf_t* msg, nng_socket* nn_s *uepp = NULL; } - if( DEBUG ) fprintf( stderr, "[DBUG] epsock_meid: no ep in hash for (%s)\n", meid ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "epsock_meid: no ep in hash for (%s)\n", meid ); return FALSE; } @@ -479,7 +479,7 @@ static int epsock_meid( route_table_t *rtable, rmr_mbuf_t* msg, nng_socket* nn_s } else { state = FALSE; } - if( DEBUG ) fprintf( stderr, "[DBUG] epsock_meid: connection attempted with %s: %s\n", ep->name, state ? "[OK]" : "[FAIL]" ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "epsock_meid: connection attempted with %s: %s\n", ep->name, state ? "[OK]" : "[FAIL]" ); } else { *nn_sock = ep->nn_sock; } diff --git a/src/rmr/nng/src/sr_nng_static.c b/src/rmr/nng/src/sr_nng_static.c index d24a900..dd978a4 100644 --- a/src/rmr/nng/src/sr_nng_static.c +++ b/src/rmr/nng/src/sr_nng_static.c @@ -126,7 +126,7 @@ static rmr_mbuf_t* alloc_zcmsg( uta_ctx_t* ctx, rmr_mbuf_t* msg, int size, int s if( msg == NULL ) { msg = (rmr_mbuf_t *) malloc( sizeof *msg ); if( msg == NULL ) { - fprintf( stderr, "[CRI] rmr_alloc_zc: cannot get memory for message\n" ); + rmr_vlog( RMR_VL_CRIT, "rmr_alloc_zc: cannot get memory for message\n" ); exit( 1 ); } } else { @@ -136,7 +136,7 @@ static rmr_mbuf_t* alloc_zcmsg( uta_ctx_t* ctx, rmr_mbuf_t* msg, int size, int s memset( msg, 0, sizeof( *msg ) ); if( (state = nng_msg_alloc( (nng_msg **) &msg->tp_buf, mlen )) != 0 ) { - fprintf( stderr, "[CRI] rmr_alloc_zc: cannot get memory for zero copy buffer: %d\n", ENOMEM ); + rmr_vlog( RMR_VL_CRIT, "rmr_alloc_zc: cannot get memory for zero copy buffer: %d\n", ENOMEM ); abort( ); // toss out a core file for this } @@ -161,7 +161,7 @@ static rmr_mbuf_t* alloc_zcmsg( uta_ctx_t* ctx, rmr_mbuf_t* msg, int size, int s strncpy( (char *) ((uta_mhdr_t *)msg->header)->src, ctx->my_name, RMR_MAX_SRC ); strncpy( (char *) ((uta_mhdr_t *)msg->header)->srcip, ctx->my_ip, RMR_MAX_SRC ); - if( DEBUG > 1 ) fprintf( stderr, "[DBUG] alloc_zcmsg mlen=%ld size=%d mpl=%d flags=%02x\n", (long) mlen, size, ctx->max_plen, msg->flags ); + if( DEBUG > 1 ) rmr_vlog( RMR_VL_DEBUG, "alloc_zcmsg mlen=%ld size=%d mpl=%d flags=%02x\n", (long) mlen, size, ctx->max_plen, msg->flags ); return msg; } @@ -177,7 +177,7 @@ static rmr_mbuf_t* alloc_mbuf( uta_ctx_t* ctx, int state ) { msg = (rmr_mbuf_t *) malloc( sizeof *msg ); if( msg == NULL ) { - fprintf( stderr, "[CRI] rmr_alloc_zc: cannot get memory for message\n" ); + rmr_vlog( RMR_VL_CRIT, "rmr_alloc_zc: cannot get memory for message\n" ); exit( 1 ); } @@ -275,14 +275,14 @@ static inline rmr_mbuf_t* clone_msg( rmr_mbuf_t* old_msg ) { nm = (rmr_mbuf_t *) malloc( sizeof *nm ); if( nm == NULL ) { - fprintf( stderr, "[CRI] rmr_clone: cannot get memory for message buffer\n" ); + rmr_vlog( RMR_VL_CRIT, "rmr_clone: cannot get memory for message buffer\n" ); exit( 1 ); } memset( nm, 0, sizeof( *nm ) ); mlen = old_msg->alloc_len; // length allocated before if( (state = nng_msg_alloc( (nng_msg **) &nm->tp_buf, mlen )) != 0 ) { - fprintf( stderr, "[CRI] rmr_clone: cannot get memory for zero copy buffer: %d\n", ENOMEM ); + rmr_vlog( RMR_VL_CRIT, "rmr_clone: cannot get memory for zero copy buffer: %d\n", ENOMEM ); exit( 1 ); } @@ -306,7 +306,7 @@ static inline rmr_mbuf_t* clone_msg( rmr_mbuf_t* old_msg ) { nm->sub_id = old_msg->sub_id; nm->len = old_msg->len; // length of data in the payload nm->alloc_len = mlen; // length of allocated payload - if( DEBUG ) fprintf( stderr, "[DBUG] clone values: mty=%d sid=%d len=%d alloc=%d\n", nm->mtype, nm->sub_id, nm->len, nm->alloc_len ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "clone values: mty=%d sid=%d len=%d alloc=%d\n", nm->mtype, nm->sub_id, nm->len, nm->alloc_len ); nm->xaction = hdr->xid; // reference xaction nm->state = old_msg->state; // fill in caller's state (likely the state of the last operation) @@ -332,7 +332,7 @@ static inline rmr_mbuf_t* realloc_msg( rmr_mbuf_t* old_msg, int tr_len ) { nm = (rmr_mbuf_t *) malloc( sizeof *nm ); if( nm == NULL ) { - fprintf( stderr, "[CRI] rmr_clone: cannot get memory for message buffer\n" ); + rmr_vlog( RMR_VL_CRIT, "rmr_clone: cannot get memory for message buffer\n" ); exit( 1 ); } memset( nm, 0, sizeof( *nm ) ); @@ -341,9 +341,9 @@ static inline rmr_mbuf_t* realloc_msg( rmr_mbuf_t* old_msg, int tr_len ) { tr_old_len = RMR_TR_LEN( hdr ); // bytes in old header for trace mlen = old_msg->alloc_len + (tr_len - tr_old_len); // new length with trace adjustment - if( DEBUG ) fprintf( stderr, "[DBUG] tr_realloc old size=%d new size=%d new tr_len=%d\n", (int) old_msg->alloc_len, (int) mlen, (int) tr_len ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "tr_realloc old size=%d new size=%d new tr_len=%d\n", (int) old_msg->alloc_len, (int) mlen, (int) tr_len ); if( (state = nng_msg_alloc( (nng_msg **) &nm->tp_buf, mlen )) != 0 ) { - fprintf( stderr, "[CRI] rmr_clone: cannot get memory for zero copy buffer: %d\n", ENOMEM ); + rmr_vlog( RMR_VL_CRIT, "rmr_clone: cannot get memory for zero copy buffer: %d\n", ENOMEM ); exit( 1 ); } @@ -432,7 +432,7 @@ static inline rmr_mbuf_t* realloc_payload( rmr_mbuf_t* old_msg, int payload_len, old_len = old_msg->len; old_psize = old_msg->alloc_len - RMR_HDR_LEN( old_msg->header ); // allocated transport size less the header and other data bits if( !clone && payload_len <= old_psize ) { // old message is large enough, nothing to do - if( DEBUG ) fprintf( stderr, "[DBUG] rmr_realloc_payload: old msg payload larger than requested: cur=%d need=%d\n", old_psize, payload_len ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "rmr_realloc_payload: old msg payload larger than requested: cur=%d need=%d\n", old_psize, payload_len ); return old_msg; } @@ -440,12 +440,12 @@ static inline rmr_mbuf_t* realloc_payload( rmr_mbuf_t* old_msg, int payload_len, old_tp_buf = old_msg->tp_buf; if( clone ) { - if( DEBUG ) fprintf( stderr, "[DBUG] rmr_realloc_payload: cloning message\n" ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "rmr_realloc_payload: cloning message\n" ); free_tp = 0; nm = (rmr_mbuf_t *) malloc( sizeof( *nm ) ); if( nm == NULL ) { - fprintf( stderr, "[CRI] rmr_realloc_payload: cannot get memory for message buffer. bytes requested: %d\n", (int) sizeof(*nm) ); + rmr_vlog( RMR_VL_CRIT, "rmr_realloc_payload: cannot get memory for message buffer. bytes requested: %d\n", (int) sizeof(*nm) ); return NULL; } memset( nm, 0, sizeof( *nm ) ); @@ -456,9 +456,9 @@ static inline rmr_mbuf_t* realloc_payload( rmr_mbuf_t* old_msg, int payload_len, omhdr = old_msg->header; mlen = hdr_len + (payload_len > old_psize ? payload_len : old_psize); // must have larger in case copy is true - if( DEBUG ) fprintf( stderr, "[DBUG] reallocate for payload increase. new message size: %d\n", (int) mlen ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "reallocate for payload increase. new message size: %d\n", (int) mlen ); if( (state = nng_msg_alloc( (nng_msg **) &nm->tp_buf, mlen )) != 0 ) { - fprintf( stderr, "[CRI] rmr_realloc_payload: cannot get memory for zero copy buffer. bytes requested: %d\n", (int) mlen ); + rmr_vlog( RMR_VL_CRIT, "rmr_realloc_payload: cannot get memory for zero copy buffer. bytes requested: %d\n", (int) mlen ); return NULL; } @@ -466,10 +466,10 @@ static inline rmr_mbuf_t* realloc_payload( rmr_mbuf_t* old_msg, int payload_len, SET_HDR_LEN( nm->header ); if( copy ) { // if we need to copy the old payload too - if( DEBUG ) fprintf( stderr, "[DBUG] rmr_realloc_payload: copy payload into new message: %d bytes\n", old_psize ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "rmr_realloc_payload: copy payload into new message: %d bytes\n", old_psize ); memcpy( nm->header, omhdr, sizeof( char ) * (old_psize + RMR_HDR_LEN( omhdr )) ); } else { // just need to copy header - if( DEBUG ) fprintf( stderr, "[DBUG] rmr_realloc_payload: copy only header into new message: %d bytes\n", RMR_HDR_LEN( nm->header ) ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "rmr_realloc_payload: copy only header into new message: %d bytes\n", RMR_HDR_LEN( nm->header ) ); memcpy( nm->header, omhdr, sizeof( char ) * RMR_HDR_LEN( omhdr ) ); } @@ -561,7 +561,7 @@ static rmr_mbuf_t* rcv_msg( uta_ctx_t* ctx, rmr_mbuf_t* old_msg ) { hdr = (uta_mhdr_t *) msg->header; msg->flags |= MFL_ADDSRC; // turn on so if user app tries to send this buffer we reset src - if( DEBUG > 1 ) fprintf( stderr, "[DBUG] rcv_msg: got something: type=%d state=%d len=%d diff=%ld\n", + if( DEBUG > 1 ) rmr_vlog( RMR_VL_DEBUG, "rcv_msg: got something: type=%d state=%d len=%d diff=%ld\n", msg->mtype, msg->state, msg->len, msg->payload - (unsigned char *) msg->header ); } else { msg->state = RMR_ERR_EMPTY; @@ -615,7 +615,7 @@ static void* rcv_payload( uta_ctx_t* ctx, rmr_mbuf_t* old_msg ) { msg->payload = msg->header; // payload is the whole thing; no header msg->xaction = NULL; - if( DEBUG > 1 ) fprintf( stderr, "[DBUG] rcv_payload: got something: type=%d state=%d len=%d\n", msg->mtype, msg->state, msg->len ); + if( DEBUG > 1 ) rmr_vlog( RMR_VL_DEBUG, "rcv_payload: got something: type=%d state=%d len=%d\n", msg->mtype, msg->state, msg->len ); return msg; } @@ -714,7 +714,7 @@ static rmr_mbuf_t* send_msg( uta_ctx_t* ctx, rmr_mbuf_t* msg, nng_socket nn_sock msg->state = xlate_nng_state( msg->state, RMR_ERR_SENDFAILED ); // xlate to our state and set errno } - if( DEBUG ) fprintf( stderr, "[DBUG] send failed: %d %s\n", (int) msg->state, strerror( msg->state ) ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "send failed: %d %s\n", (int) msg->state, strerror( msg->state ) ); } return msg; @@ -783,7 +783,7 @@ static rmr_mbuf_t* mtosend_msg( void* vctx, rmr_mbuf_t* msg, int max_to ) { if( (rte = uta_get_rte( ctx->rtable, msg->sub_id, msg->mtype, TRUE )) == NULL ) { // find the entry which matches subid/type allow fallback to type only key if( ctx->flags & CTXFL_WARN ) { - fprintf( stderr, "[WARN] no endpoint for mtype=%d sub_id=%d\n", msg->mtype, msg->sub_id ); + rmr_vlog( RMR_VL_WARN, "no endpoint for mtype=%d sub_id=%d\n", msg->mtype, msg->sub_id ); } msg->state = RMR_ERR_NOENDPT; errno = ENXIO; // must ensure it's not eagain @@ -801,7 +801,7 @@ static rmr_mbuf_t* mtosend_msg( void* vctx, rmr_mbuf_t* msg, int max_to ) { send_again = 0; } - if( DEBUG ) fprintf( stderr, "[DBUG] mtosend_msg: flgs=0x%04x type=%d again=%d group=%d len=%d sock_ok=%d\n", + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "mtosend_msg: flgs=0x%04x type=%d again=%d group=%d len=%d sock_ok=%d\n", msg->flags, msg->mtype, send_again, group, msg->len, sock_ok ); group++; @@ -814,12 +814,12 @@ static rmr_mbuf_t* mtosend_msg( void* vctx, rmr_mbuf_t* msg, int max_to ) { errno = ENOMEM; msg->tp_state = errno; if( ctx->flags & CTXFL_WARN ) { - fprintf( stderr, "[WARN] unable to clone message for multiple rr-group send\n" ); + rmr_vlog( RMR_VL_WARN, "unable to clone message for multiple rr-group send\n" ); } return msg; } - if( DEBUG ) fprintf( stderr, "[DBUG] msg cloned: type=%d len=%d\n", msg->mtype, msg->len ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "msg cloned: type=%d len=%d\n", msg->mtype, msg->len ); msg->flags |= MFL_NOALLOC; // keep send from allocating a new message; we have a clone to use msg = send_msg( ctx, msg, nn_sock, max_to ); // do the hard work, msg should be nil on success @@ -834,7 +834,7 @@ static rmr_mbuf_t* mtosend_msg( void* vctx, rmr_mbuf_t* msg, int max_to ) { msg = send_msg( ctx, msg, nn_sock, max_to ); // send the last, and allocate a new buffer; drops the clone if it was if( DEBUG ) { if( msg == NULL ) { - fprintf( stderr, "[DBUG] mtosend_msg: send returned nil message!\n" ); + rmr_vlog( RMR_VL_DEBUG, "mtosend_msg: send returned nil message!\n" ); } } } @@ -856,7 +856,7 @@ static rmr_mbuf_t* mtosend_msg( void* vctx, rmr_mbuf_t* msg, int max_to ) { } } else { if( ctx->flags & CTXFL_WARN ) { - fprintf( stderr, "[WARN] invalid socket for rte, setting no endpoint err: mtype=%d sub_id=%d\n", msg->mtype, msg->sub_id ); + rmr_vlog( RMR_VL_WARN, "invalid socket for rte, setting no endpoint err: mtype=%d sub_id=%d\n", msg->mtype, msg->sub_id ); } msg->state = RMR_ERR_NOENDPT; errno = ENXIO; @@ -869,7 +869,7 @@ static rmr_mbuf_t* mtosend_msg( void* vctx, rmr_mbuf_t* msg, int max_to ) { msg->state = RMR_OK; } - if( DEBUG ) fprintf( stderr, "[DBUG] final send stats: ok=%d group=%d state=%d\n\n", ok_sends, group, msg->state ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "final send stats: ok=%d group=%d state=%d\n\n", ok_sends, group, msg->state ); msg->tp_state = errno; } diff --git a/src/rmr/si/src/mt_call_si_static.c b/src/rmr/si/src/mt_call_si_static.c index 55636bb..3736420 100644 --- a/src/rmr/si/src/mt_call_si_static.c +++ b/src/rmr/si/src/mt_call_si_static.c @@ -38,7 +38,7 @@ static inline void queue_normal( uta_ctx_t* ctx, rmr_mbuf_t* mbuf ) { if( ! uta_ring_insert( ctx->mring, mbuf ) ) { rmr_free_msg( mbuf ); // drop if ring is full if( !warned ) { - fprintf( stderr, "[WARN] rmr_mt_receive: application is not receiving fast enough; messages dropping\n" ); + rmr_vlog( RMR_VL_WARN, "rmr_mt_receive: application is not receiving fast enough; messages dropping\n" ); warned++; } @@ -120,7 +120,7 @@ static int mt_data_cb( void* vctx, int fd, char* buf, int buflen ) { } if( fd >= ctx->nrivers || fd < 0 ) { - if( DEBUG ) fprintf( stderr, "[DBUG] callback fd is out of range: %d nrivers=%d\n", fd, ctx->nrivers ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "callback fd is out of range: %d nrivers=%d\n", fd, ctx->nrivers ); return SI_RET_OK; } } @@ -155,17 +155,17 @@ fprintf( stderr, "\n" ); remain = buflen; while( remain > 0 ) { // until we've done something with all bytes passed in - if( DEBUG ) fprintf( stderr, "[DBUG] ====== data callback top of loop bidx=%d msize=%d ipt=%d remain=%d\n", bidx, river->msg_size, river->ipt, remain ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "====== data callback top of loop bidx=%d msize=%d ipt=%d remain=%d\n", bidx, river->msg_size, river->ipt, remain ); // FIX ME: size in the message needs to be network byte order if( river->msg_size <= 0 ) { // don't have a size yet // FIX ME: we need a frame indicator to ensure alignment need = sizeof( int ) - river->ipt; // what we need from transport buffer if( need > remain ) { // the whole size isn't there - if( DEBUG > 1 ) fprintf( stderr, "[DBUG] need more for size than we have: need=%d rmain=%d ipt=%d\n", need, remain, river->ipt ); + if( DEBUG > 1 ) rmr_vlog( RMR_VL_DEBUG, "need more for size than we have: need=%d rmain=%d ipt=%d\n", need, remain, river->ipt ); memcpy( &river->accum[river->ipt], buf+bidx, remain ); // grab what we can and depart river->ipt += remain; - if( DEBUG > 1 ) fprintf( stderr, "[DBUG] data callback not enough bytes to compute size; need=%d have=%d\n", need, remain ); + if( DEBUG > 1 ) rmr_vlog( RMR_VL_DEBUG, "data callback not enough bytes to compute size; need=%d have=%d\n", need, remain ); return SI_RET_OK; } @@ -176,7 +176,7 @@ fprintf( stderr, "\n" ); remain -= need; river->msg_size = *((int *) river->accum); if( DEBUG > 1 ) { - fprintf( stderr, "[DBUG] size from accumulator =%d\n", river->msg_size ); + rmr_vlog( RMR_VL_DEBUG, "size from accumulator =%d\n", river->msg_size ); if( river->msg_size > 500 ) { dump_40( river->accum, "msg size way too large accum:" ); } @@ -184,7 +184,7 @@ fprintf( stderr, "\n" ); } else { river->msg_size = *((int *) &buf[bidx]); // snarf directly and copy with rest later } - if( DEBUG ) fprintf( stderr, "[DBUG] data callback setting msg size: %d\n", river->msg_size ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "data callback setting msg size: %d\n", river->msg_size ); if( river->msg_size > river->nbytes ) { // message is too big, we will drop it river->flags |= RF_DROP; @@ -192,7 +192,7 @@ fprintf( stderr, "\n" ); } if( river->msg_size > (river->ipt + remain) ) { // need more than is left in buffer - if( DEBUG > 1 ) fprintf( stderr, "[DBUG] data callback not enough in the buffer size=%d remain=%d\n", river->msg_size, remain ); + if( DEBUG > 1 ) rmr_vlog( RMR_VL_DEBUG, "data callback not enough in the buffer size=%d remain=%d\n", river->msg_size, remain ); if( (river->flags & RF_DROP) == 0 ) { memcpy( &river->accum[river->ipt], buf+bidx, remain ); // buffer and go wait for more } @@ -200,14 +200,14 @@ fprintf( stderr, "\n" ); remain = 0; } else { need = river->msg_size - river->ipt; // bytes from transport we need to have complete message - if( DEBUG ) fprintf( stderr, "[DBUG] data callback enough in the buffer size=%d need=%d remain=%d\n", river->msg_size, need, remain ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "data callback enough in the buffer size=%d need=%d remain=%d\n", river->msg_size, need, remain ); if( (river->flags & RF_DROP) == 0 ) { memcpy( &river->accum[river->ipt], buf+bidx, need ); // grab just what is needed (might be more) buf2mbuf( ctx, river->accum, river->msg_size, fd ); // build an RMR mbuf and queue river->accum = (char *) malloc( sizeof( char ) * river->nbytes ); // fresh accumulator } else { if( !(river->flags & RF_NOTIFIED) ) { - fprintf( stderr, "[WRN] message larger than max (%d) have arrived on fd %d\n", river->nbytes, fd ); + rmr_vlog( RMR_VL_WARN, "message larger than max (%d) have arrived on fd %d\n", river->nbytes, fd ); river->flags |= RF_NOTIFIED; } } @@ -219,7 +219,7 @@ fprintf( stderr, "\n" ); } } - if( DEBUG >2 ) fprintf( stderr, "[DBUG] ##### data callback finished\n" ); + if( DEBUG >2 ) rmr_vlog( RMR_VL_DEBUG, "##### data callback finished\n" ); return SI_RET_OK; } @@ -248,11 +248,11 @@ static void* mt_receive( void* vctx ) { uta_ctx_t* ctx; if( (ctx = (uta_ctx_t*) vctx) == NULL ) { - fprintf( stderr, "[CRI], unable to start mt-receive: ctx was nil\n" ); + rmr_vlog( RMR_VL_CRIT, "unable to start mt-receive: ctx was nil\n" ); return NULL; } - if( DEBUG ) fprintf( stderr, "[DBUG] mt_receive: registering SI95 data callback and waiting\n" ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "mt_receive: registering SI95 data callback and waiting\n" ); SIcbreg( ctx->si_ctx, SI_CB_CDATA, mt_data_cb, vctx ); // our callback called only for "cooked" (tcp) data SIwait( ctx->si_ctx ); diff --git a/src/rmr/si/src/rmr_si.c b/src/rmr/si/src/rmr_si.c index e50b5d0..8697bc5 100644 --- a/src/rmr/si/src/rmr_si.c +++ b/src/rmr/si/src/rmr_si.c @@ -59,8 +59,9 @@ #include "rmr.h" // things the users see #include "rmr_agnostic.h" // agnostic things (must be included before private) -#include "rmr_si_private.h" // things that we need too +#include "rmr_si_private.h" // things that we need too #include "rmr_symtab.h" +#include "rmr_logging.h" #include "ring_static.c" // message ring support #include "rt_generic_static.c" // route table things not transport specific @@ -271,7 +272,7 @@ extern rmr_mbuf_t* rmr_rts_msg( void* vctx, rmr_mbuf_t* msg ) { errno = 0; // at this point any bad state is in msg returned if( msg->header == NULL ) { - fprintf( stderr, "[ERR] rmr_send_msg: message had no header\n" ); + rmr_vlog( RMR_VL_ERR, "rmr_send_msg: message had no header\n" ); msg->state = RMR_ERR_NOHDR; msg->tp_state = errno; return msg; @@ -447,42 +448,42 @@ extern rmr_mbuf_t* rmr_rcv_specific( void* vctx, rmr_mbuf_t* msg, char* expect, if( exp_len > RMR_MAX_XID ) { exp_len = RMR_MAX_XID; } - if( DEBUG ) fprintf( stderr, "[DBUG] rcv_specific waiting for id=%s\n", expect ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, " rcv_specific waiting for id=%s\n", expect ); while( queued < allow2queue ) { msg = rcv_msg( ctx, msg ); // hard wait for next if( msg->state == RMR_OK ) { if( memcmp( msg->xaction, expect, exp_len ) == 0 ) { // got it -- return it - if( DEBUG ) fprintf( stderr, "[DBUG] rcv-specific matched (%s); %d messages were queued\n", msg->xaction, queued ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, " rcv-specific matched (%s); %d messages were queued\n", msg->xaction, queued ); return msg; } if( ! uta_ring_insert( ctx->mring, msg ) ) { // just queue, error if ring is full - if( DEBUG > 1 ) fprintf( stderr, "[DBUG] rcv_specific ring is full\n" ); + if( DEBUG > 1 ) rmr_vlog( RMR_VL_DEBUG, " rcv_specific ring is full\n" ); errno = ENOBUFS; return NULL; } - if( DEBUG ) fprintf( stderr, "[DBUG] rcv_specific queued message type=%d\n", msg->mtype ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, " rcv_specific queued message type=%d\n", msg->mtype ); queued++; msg = NULL; } } - if( DEBUG ) fprintf( stderr, "[DBUG] rcv_specific timeout waiting for %s\n", expect ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, " rcv_specific timeout waiting for %s\n", expect ); errno = ETIMEDOUT; return NULL; } /* Set send timeout. The value time is assumed to be milliseconds. The timeout is the - _rough_ maximum amount of time that RMr will block on a send attempt when the underlying + _rough_ maximum amount of time that RMR will block on a send attempt when the underlying mechnism indicates eagain or etimeedout. All other error conditions are reported without this delay. Setting a timeout of 0 causes no retries to be attempted in RMr code. Setting a timeout of 1 causes RMr to spin up to 1K retries before returning, but _without_ issuing a sleep. If timeout is > 1, then RMr will issue a sleep (1us) after every 1K send attempts until the "time" value is reached. Retries are abandoned - if NNG returns anything other than NNG_EAGAIN or NNG_ETIMEDOUT. + if NNG returns anything other than EAGAIN or EINTER is returned. The default, if this function is not used, is 1; meaning that RMr will retry, but will not enter a sleep. In all cases the caller should check the status in the message returned @@ -511,7 +512,7 @@ extern int rmr_set_stimeout( void* vctx, int time ) { CAUTION: this is not supported as they must be set differently (between create and open) in NNG. */ extern int rmr_set_rtimeout( void* vctx, int time ) { - fprintf( stderr, "[WRN] Current underlying transport mechanism (SI) does not support rcv timeout; not set\n" ); + rmr_vlog( RMR_VL_WARN, "Current underlying transport mechanism (SI) does not support rcv timeout; not set\n" ); return 0; } @@ -541,12 +542,17 @@ static void* init( char* uproto_port, int max_msg_size, int flags ) { int static_rtc = 0; // if rtg env var is < 1, then we set and don't listen on a port int state; int i; + int old_vlevel; + + old_vlevel = rmr_vlog_init(); // initialise and get the current level + rmr_set_vlevel( RMR_VL_INFO ); // we WILL announce our version etc if( ! announced ) { - fprintf( stderr, "[INFO] ric message routing library on SI95/b mv=%d flg=%02x (%s %s.%s.%s built: %s)\n", + rmr_vlog( RMR_VL_INFO, "ric message routing library on SI95/b mv=%d flg=%02x (%s %s.%s.%s built: %s)\n", RMR_MSG_VER, flags, QUOTE_DEF(GIT_ID), QUOTE_DEF(MAJOR_VER), QUOTE_DEF(MINOR_VER), QUOTE_DEF(PATCH_VER), __DATE__ ); announced = 1; } + rmr_set_vlevel( old_vlevel ); // return logging to the desired state errno = 0; if( uproto_port == NULL ) { @@ -561,7 +567,7 @@ static void* init( char* uproto_port, int max_msg_size, int flags ) { } memset( ctx, 0, sizeof( uta_ctx_t ) ); - if( DEBUG ) fprintf( stderr, "[DBUG] rmr_init: allocating 266 rivers\n" ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, " rmr_init: allocating 266 rivers\n" ); ctx->nrivers = 256; // number of input flows we'll manage ctx->rivers = (river_t *) malloc( sizeof( river_t ) * ctx->nrivers ); memset( ctx->rivers, 0, sizeof( river_t ) * ctx->nrivers ); @@ -581,7 +587,7 @@ static void* init( char* uproto_port, int max_msg_size, int flags ) { uta_ring_config( ctx->mring, RING_RLOCK ); // concurrent rcv calls require read lock uta_ring_config( ctx->zcb_mring, RING_WLOCK ); // concurrent free calls from userland require write lock } else { - fprintf( stderr, "[INFO] receive ring locking disabled by user application\n" ); + rmr_vlog( RMR_VL_INFO, "receive ring locking disabled by user application\n" ); } init_mtcall( ctx ); // set up call chutes @@ -596,7 +602,7 @@ static void* init( char* uproto_port, int max_msg_size, int flags ) { ctx->si_ctx = SIinitialise( SI_OPT_FG ); // FIX ME: si needs to streamline and drop fork/bg stuff if( ctx->si_ctx == NULL ) { - fprintf( stderr, "[CRI] unable to initialise SI95 interface\n" ); + rmr_vlog( RMR_VL_CRIT, "unable to initialise SI95 interface\n" ); free_ctx( ctx ); return NULL; } @@ -633,7 +639,7 @@ static void* init( char* uproto_port, int max_msg_size, int flags ) { free( tok ); } else { if( (gethostname( wbuf, sizeof( wbuf ) )) != 0 ) { - fprintf( stderr, "[CRI] rmr_init: cannot determine localhost name: %s\n", strerror( errno ) ); + rmr_vlog( RMR_VL_CRIT, "rmr_init: cannot determine localhost name: %s\n", strerror( errno ) ); return NULL; } if( (tok = strchr( wbuf, '.' )) != NULL ) { @@ -643,7 +649,7 @@ static void* init( char* uproto_port, int max_msg_size, int flags ) { ctx->my_name = (char *) malloc( sizeof( char ) * RMR_MAX_SRC ); if( snprintf( ctx->my_name, RMR_MAX_SRC, "%s:%s", wbuf, port ) >= RMR_MAX_SRC ) { // our registered name is host:port - fprintf( stderr, "[CRI] rmr_init: hostname + port must be less than %d characters; %s:%s is not\n", RMR_MAX_SRC, wbuf, port ); + rmr_vlog( RMR_VL_CRIT, "rmr_init: hostname + port must be less than %d characters; %s:%s is not\n", RMR_MAX_SRC, wbuf, port ); return NULL; } @@ -659,11 +665,11 @@ static void* init( char* uproto_port, int max_msg_size, int flags ) { } else { ctx->my_ip = get_default_ip( ctx->ip_list ); // and (guess) at what should be the default to put into messages as src if( ctx->my_ip == NULL ) { - fprintf( stderr, "[WRN] rmr_init: default ip address could not be sussed out, using name\n" ); + rmr_vlog( RMR_VL_WARN, "rmr_init: default ip address could not be sussed out, using name\n" ); strcpy( ctx->my_ip, ctx->my_name ); // if we cannot suss it out, use the name rather than a nil pointer } } - if( DEBUG ) fprintf( stderr, "[DBUG] default ip address: %s\n", ctx->my_ip ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, " default ip address: %s\n", ctx->my_ip ); if( (tok = getenv( ENV_WARNINGS )) != NULL ) { if( *tok == '1' ) { @@ -678,7 +684,7 @@ static void* init( char* uproto_port, int max_msg_size, int flags ) { snprintf( bind_info, sizeof( bind_info ), "%s:%s", interface, port ); // FIXME -- si only supports 0.0.0.0 by default if( (state = SIlistener( ctx->si_ctx, TCP_DEVICE, bind_info )) < 0 ) { - fprintf( stderr, "[CRI] rmr_init: unable to start si listener for %s: %s\n", bind_info, strerror( errno ) ); + rmr_vlog( RMR_VL_CRIT, "rmr_init: unable to start si listener for %s: %s\n", bind_info, strerror( errno ) ); free_ctx( ctx ); return NULL; } @@ -686,18 +692,18 @@ static void* init( char* uproto_port, int max_msg_size, int flags ) { if( !(flags & FL_NOTHREAD) ) { // skip if internal function that doesnt need a RTC if( static_rtc ) { if( pthread_create( &ctx->rtc_th, NULL, rtc_file, (void *) ctx ) ) { // kick the rt collector thread as just file reader - fprintf( stderr, "[WRN] rmr_init: unable to start static route table collector thread: %s", strerror( errno ) ); + rmr_vlog( RMR_VL_WARN, "rmr_init: unable to start static route table collector thread: %s", strerror( errno ) ); } } else { if( pthread_create( &ctx->rtc_th, NULL, rtc, (void *) ctx ) ) { // kick the real rt collector thread - fprintf( stderr, "[WRN] rmr_init: unable to start dynamic route table collector thread: %s", strerror( errno ) ); + rmr_vlog( RMR_VL_WARN, "rmr_init: unable to start dynamic route table collector thread: %s", strerror( errno ) ); } } } ctx->flags |= CFL_MTC_ENABLED; // for SI threaded receiver is the only way if( pthread_create( &ctx->mtc_th, NULL, mt_receive, (void *) ctx ) ) { // so kick it - fprintf( stderr, "[WRN] rmr_init: unable to start multi-threaded receiver: %s", strerror( errno ) ); + rmr_vlog( RMR_VL_WARN, "rmr_init: unable to start multi-threaded receiver: %s", strerror( errno ) ); } free( proto_port ); @@ -778,7 +784,7 @@ extern int rmr_get_rcvfd( void* vctx ) { /* if( (state = nng_getopt_int( ctx->nn_sock, NNG_OPT_RECVFD, &fd )) != 0 ) { - fprintf( stderr, "[WRN] rmr cannot get recv fd: %s\n", nng_strerror( state ) ); + rmr_vlog( RMR_VL_WARN, "rmr cannot get recv fd: %s\n", nng_strerror( state ) ); return -1; } */ @@ -898,7 +904,7 @@ extern rmr_mbuf_t* rmr_mt_rcv( void* vctx, rmr_mbuf_t* mbuf, int max_wait ) { mbuf = ombuf; // return caller's buffer if they passed one in } else { errno = 0; // interrupted call state could be left; clear - if( DEBUG ) fprintf( stderr, "[DBUG] mt_rcv extracting from normal ring\n" ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, " mt_rcv extracting from normal ring\n" ); if( (mbuf = (rmr_mbuf_t *) uta_ring_extract( ctx->mring )) != NULL ) { // pop if queued mbuf->state = RMR_OK; diff --git a/src/rmr/si/src/rtable_si_static.c b/src/rmr/si/src/rtable_si_static.c index cf83590..f7360a9 100644 --- a/src/rmr/si/src/rtable_si_static.c +++ b/src/rmr/si/src/rtable_si_static.c @@ -53,7 +53,7 @@ */ static void uta_ep_failed( endpoint_t* ep ) { if( ep != NULL ) { - if( DEBUG ) fprintf( stderr, "[DBUG] connection to %s was closed\n", ep->name ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "connection to %s was closed\n", ep->name ); ep->open = 0; } } @@ -79,14 +79,14 @@ static int uta_link2( si_ctx_t* si_ctx, endpoint_t* ep ) { char* tok; if( ep == NULL ) { - if( DEBUG ) fprintf( stderr, "[DBUG] link2 ep was nil!\n" ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "link2 ep was nil!\n" ); return FALSE; } target = ep->name; // always give name to transport so changing dest IP does not break reconnect if( target == NULL || (addr = strchr( target, ':' )) == NULL ) { // bad address:port if( ep->notify ) { - fprintf( stderr, "[WARN] rmr: link2: unable to create link: bad target: %s\n", target == NULL ? "" : target ); + rmr_vlog( RMR_VL_WARN, "rmr: link2: unable to create link: bad target: %s\n", target == NULL ? "" : target ); ep->notify = 0; } return FALSE; @@ -100,24 +100,24 @@ static int uta_link2( si_ctx_t* si_ctx, endpoint_t* ep ) { snprintf( conn_info, sizeof( conn_info ), "%s", target ); errno = 0; - if( DEBUG > 1 ) fprintf( stderr, "[DBUG] link2 attempting connection with: %s\n", conn_info ); + if( DEBUG > 1 ) rmr_vlog( RMR_VL_DEBUG, "link2 attempting connection with: %s\n", conn_info ); if( (ep->nn_sock = SIconnect( si_ctx, conn_info )) < 0 ) { pthread_mutex_unlock( &ep->gate ); if( ep->notify ) { // need to notify if set - fprintf( stderr, "[WRN] rmr: link2: unable to connect to target: %s: %d %s\n", target, errno, strerror( errno ) ); + rmr_vlog( RMR_VL_WARN, "rmr: link2: unable to connect to target: %s: %d %s\n", target, errno, strerror( errno ) ); ep->notify = 0; } //nng_close( *nn_sock ); return FALSE; } - if( DEBUG ) fprintf( stderr, "[INFO] rmr_si_link2: connection was successful to: %s\n", target ); + if( DEBUG ) rmr_vlog( RMR_VL_INFO, "rmr_si_link2: connection was successful to: %s\n", target ); ep->open = TRUE; // set open/notify before giving up lock if( ! ep->notify ) { // if we yammered about a failure, indicate finally good - fprintf( stderr, "[INFO] rmr: link2: connection finally establisehd with target: %s\n", target ); + rmr_vlog( RMR_VL_INFO, "rmr: link2: connection finally establisehd with target: %s\n", target ); ep->notify = 1; } @@ -161,25 +161,25 @@ extern endpoint_t* uta_add_ep( route_table_t* rt, rtable_ent_t* rte, char* ep_n rrgroup_t* rrg; // pointer at group to update if( ! rte || ! rt ) { - fprintf( stderr, "[WRN] uda_add_ep didn't get a valid rt and/or rte pointer\n" ); + rmr_vlog( RMR_VL_WARN, "uda_add_ep didn't get a valid rt and/or rte pointer\n" ); return NULL; } if( rte->nrrgroups <= group || group < 0 ) { - fprintf( stderr, "[WRN] uda_add_ep group out of range: %d (max == %d)\n", group, rte->nrrgroups ); + rmr_vlog( RMR_VL_WARN, "uda_add_ep group out of range: %d (max == %d)\n", group, rte->nrrgroups ); return NULL; } //fprintf( stderr, ">>>> add ep grp=%d to rte @ 0x%p rrg=%p\n", group, rte, rte->rrgroups[group] ); if( (rrg = rte->rrgroups[group]) == NULL ) { if( (rrg = (rrgroup_t *) malloc( sizeof( *rrg ) )) == NULL ) { - fprintf( stderr, "[WRN] rmr_add_ep: malloc failed for round robin group: group=%d\n", group ); + rmr_vlog( RMR_VL_WARN, "rmr_add_ep: malloc failed for round robin group: group=%d\n", group ); return NULL; } memset( rrg, 0, sizeof( *rrg ) ); if( (rrg->epts = (endpoint_t **) malloc( sizeof( endpoint_t ) * MAX_EP_GROUP )) == NULL ) { - fprintf( stderr, "[WRN] rmr_add_ep: malloc failed for group endpoint array: group=%d\n", group ); + rmr_vlog( RMR_VL_WARN, "rmr_add_ep: malloc failed for group endpoint array: group=%d\n", group ); return NULL; } memset( rrg->epts, 0, sizeof( endpoint_t ) * MAX_EP_GROUP ); @@ -191,7 +191,7 @@ extern endpoint_t* uta_add_ep( route_table_t* rt, rtable_ent_t* rte, char* ep_n rrg->nused = 0; // number populated rrg->nendpts = MAX_EP_GROUP; // number allocated - if( DEBUG > 1 ) fprintf( stderr, "[DBUG] rrg added to rte: mtype=%d group=%d\n", rte->mtype, group ); + if( DEBUG > 1 ) rmr_vlog( RMR_VL_DEBUG, "rrg added to rte: mtype=%d group=%d\n", rte->mtype, group ); } ep = rt_ensure_ep( rt, ep_name ); // get the ep and create one if not known @@ -199,7 +199,7 @@ extern endpoint_t* uta_add_ep( route_table_t* rt, rtable_ent_t* rte, char* ep_n if( rrg != NULL ) { if( rrg->nused >= rrg->nendpts ) { // future: reallocate - fprintf( stderr, "[WRN] endpoint array for mtype/group %d/%d is full!\n", rte->mtype, group ); + rmr_vlog( RMR_VL_WARN, "endpoint array for mtype/group %d/%d is full!\n", rte->mtype, group ); return NULL; } @@ -207,7 +207,7 @@ extern endpoint_t* uta_add_ep( route_table_t* rt, rtable_ent_t* rte, char* ep_n rrg->nused++; } - if( DEBUG > 1 ) fprintf( stderr, "[DBUG] endpoint added to mtype/group: %d/%d %s nused=%d\n", rte->mtype, group, ep_name, rrg->nused ); + if( DEBUG > 1 ) rmr_vlog( RMR_VL_DEBUG, "endpoint added to mtype/group: %d/%d %s nused=%d\n", rte->mtype, group, ep_name, rrg->nused ); return ep; } @@ -230,14 +230,14 @@ static int uta_epsock_byname( route_table_t* rt, char* ep_name, int* nn_sock, en *uepp = ep; } if( ep == NULL ) { - if( DEBUG ) fprintf( stderr, "[DBUG] get ep by name for %s not in hash!\n", ep_name ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "get ep by name for %s not in hash!\n", ep_name ); if( ! ep_name || (ep = rt_ensure_ep( rt, ep_name)) == NULL ) { // create one if not in rt (support rts without entry in our table) return FALSE; } } if( ! ep->open ) { // not open -- connect now - if( DEBUG ) fprintf( stderr, "[DBUG] get ep by name for %s session not started... starting\n", ep_name ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "get ep by name for %s session not started... starting\n", ep_name ); if( ep->addr == NULL ) { // name didn't resolve before, try again ep->addr = strdup( ep->name ); // use the name directly; if not IP then transport will do dns lookup } @@ -246,7 +246,7 @@ static int uta_epsock_byname( route_table_t* rt, char* ep_name, int* nn_sock, en ep->open = TRUE; *nn_sock = ep->nn_sock; // pass socket back to caller } - if( DEBUG ) fprintf( stderr, "[DBUG] epsock_bn: connection state: %s %s\n", state ? "[OK]" : "[FAIL]", ep->name ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "epsock_bn: connection state: %s %s\n", state ? "[OK]" : "[FAIL]", ep->name ); } else { *nn_sock = ep->nn_sock; state = TRUE; @@ -295,26 +295,26 @@ static int uta_epsock_rr( rtable_ent_t *rte, int group, int* more, int* nn_sock, } if( ! nn_sock ) { // user didn't supply a pointer - if( DEBUG ) fprintf( stderr, "[DBUG] epsock_rr invalid nnsock pointer\n" ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "epsock_rr invalid nnsock pointer\n" ); errno = EINVAL; *more = 0; return FALSE; } if( rte == NULL ) { - if( DEBUG ) fprintf( stderr, "[DBUG] epsock_rr rte was nil; nothing selected\n" ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "epsock_rr rte was nil; nothing selected\n" ); *more = 0; return FALSE; } if( group < 0 || group >= rte->nrrgroups ) { - if( DEBUG > 1 ) fprintf( stderr, "[DBUG] group out of range: group=%d max=%d\n", group, rte->nrrgroups ); + if( DEBUG > 1 ) rmr_vlog( RMR_VL_DEBUG, "group out of range: group=%d max=%d\n", group, rte->nrrgroups ); *more = 0; return FALSE; } if( (rrg = rte->rrgroups[group]) == NULL ) { - if( DEBUG > 1 ) fprintf( stderr, "[DBUG] rrg not found for group %d (ptr rrgroups[g] == nil)\n", group ); + if( DEBUG > 1 ) rmr_vlog( RMR_VL_DEBUG, "rrg not found for group %d (ptr rrgroups[g] == nil)\n", group ); *more = 0; // groups are inserted contig, so nothing should be after a nil pointer return FALSE; } @@ -323,19 +323,19 @@ static int uta_epsock_rr( rtable_ent_t *rte, int group, int* more, int* nn_sock, switch( rrg->nused ) { case 0: // nothing allocated, just punt - if( DEBUG > 1 ) fprintf( stderr, "[DBUG] nothing allocated for the rrg\n" ); + if( DEBUG > 1 ) rmr_vlog( RMR_VL_DEBUG, "nothing allocated for the rrg\n" ); return FALSE; case 1: // exactly one, no rr to deal with ep = rrg->epts[0]; - if( DEBUG > 1 ) fprintf( stderr, "[DBUG] _rr returning socket with one choice in group \n" ); + if( DEBUG > 1 ) rmr_vlog( RMR_VL_DEBUG, "_rr returning socket with one choice in group \n" ); state = TRUE; break; default: // need to pick one and adjust rr counts idx = rrg->ep_idx++ % rrg->nused; // see note above ep = rrg->epts[idx]; // select next endpoint - if( DEBUG > 1 ) fprintf( stderr, "[DBUG] _rr returning socket with multiple choices in group idx=%d \n", rrg->ep_idx ); + if( DEBUG > 1 ) rmr_vlog( RMR_VL_DEBUG, "_rr returning socket with multiple choices in group idx=%d \n", rrg->ep_idx ); state = idx + 1; // unit test checks to see that we're cycling through, so must not just be TRUE break; } @@ -345,7 +345,7 @@ static int uta_epsock_rr( rtable_ent_t *rte, int group, int* more, int* nn_sock, } if( state ) { // end point selected, open if not, get socket either way if( ! ep->open ) { // not connected - if( DEBUG ) fprintf( stderr, "[DBUG] epsock_rr selected endpoint not yet open; opening %s\n", ep->name ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "epsock_rr selected endpoint not yet open; opening %s\n", ep->name ); if( ep->addr == NULL ) { // name didn't resolve before, try again ep->addr = strdup( ep->name ); // use the name directly; if not IP then transport will do dns lookup } @@ -356,13 +356,13 @@ static int uta_epsock_rr( rtable_ent_t *rte, int group, int* more, int* nn_sock, } else { state = FALSE; } - if( DEBUG ) fprintf( stderr, "[DBUG] epsock_rr: connection attempted with %s: %s\n", ep->name, state ? "[OK]" : "[FAIL]" ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "epsock_rr: connection attempted with %s: %s\n", ep->name, state ? "[OK]" : "[FAIL]" ); } else { *nn_sock = ep->nn_sock; } } - if( DEBUG > 1 ) fprintf( stderr, "[DBUG] epsock_rr returns state=%d\n", state ); + if( DEBUG > 1 ) rmr_vlog( RMR_VL_DEBUG, "epsock_rr returns state=%d\n", state ); return state; } diff --git a/src/rmr/si/src/rtc_si_static.c b/src/rmr/si/src/rtc_si_static.c index 193672f..dbccd58 100644 --- a/src/rmr/si/src/rtc_si_static.c +++ b/src/rmr/si/src/rtc_si_static.c @@ -60,7 +60,7 @@ static void* rtc_file( void* vctx ) { if( (ctx = (uta_ctx_t *) vctx) == NULL ) { - fprintf( stderr, "[CRI] rmr_rtc: internal mishap: context passed in was nil\n" ); + rmr_vlog( RMR_VL_CRIT, "rmr_rtc: internal mishap: context passed in was nil\n" ); return NULL; } @@ -167,7 +167,7 @@ static void* rtc( void* vctx ) { if( (ctx = (uta_ctx_t *) vctx) == NULL ) { - fprintf( stderr, "[CRI] rmr_rtc: internal mishap: context passed in was nil\n" ); + rmr_vlog( RMR_VL_CRIT, "rmr_rtc: internal mishap: context passed in was nil\n" ); return NULL; } @@ -206,7 +206,7 @@ static void* rtc( void* vctx ) { } if( (pvt_cx = init( port, MAX_RTG_MSG_SZ, FL_NOTHREAD )) == NULL ) { // open a private context (no RT listener!) - fprintf( stderr, "[CRI] rmr_rtc: unable to initialise listen port for RTG (pvt_cx)\n" ); + rmr_vlog( RMR_VL_CRIT, "rmr_rtc: unable to initialise listen port for RTG (pvt_cx)\n" ); while( TRUE ) { // no listen port, just dump counts now and then sleep( count_delay ); @@ -217,7 +217,7 @@ static void* rtc( void* vctx ) { return NULL; } - if( DEBUG ) fprintf( stderr, "[DBUG] rtc thread is running and listening; listening for rtg conns on %s\n", port ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "rtc thread is running and listening; listening for rtg conns on %s\n", port ); free( fport ); // future: if we need to register with the rtg, then build a message and send it through a wormhole here @@ -246,9 +246,9 @@ static void* rtc( void* vctx ) { payload = msg->payload; mlen = msg->len; // usable bytes in the payload if( vlevel > 1 ) { - fprintf( stderr, "[DBUG] rmr_rtc: received rt message; %d bytes (%s)\n", (int) mlen, msg->payload ); + rmr_vlog( RMR_VL_DEBUG, "rmr_rtc: received rt message; %d bytes (%s)\n", (int) mlen, msg->payload ); } else { - if( DEBUG > 1 || (vlevel > 0) ) fprintf( stderr, "[DBUG] rmr_rtc: received rt message; %d bytes\n", (int) mlen ); + if( DEBUG > 1 || (vlevel > 0) ) rmr_vlog( RMR_VL_DEBUG, "rmr_rtc: received rt message; %d bytes\n", (int) mlen ); } if( pbuf_size <= mlen ) { @@ -274,7 +274,7 @@ static void* rtc( void* vctx ) { } if( vlevel > 1 ) { - fprintf( stderr, "[DBUG] rmr_rtc: processing (%s)\n", curr ); + rmr_vlog( RMR_VL_DEBUG, "rmr_rtc: processing (%s)\n", curr ); } parse_rt_rec( ctx, curr, vlevel ); // parse record and add to in progress table diff --git a/src/rmr/si/src/si95/siaddress.c b/src/rmr/si/src/si95/siaddress.c index 86f54df..58a3a3d 100644 --- a/src/rmr/si/src/si95/siaddress.c +++ b/src/rmr/si/src/si95/siaddress.c @@ -112,7 +112,7 @@ extern int SIgenaddr( char *target, int proto, int family, int socktype, struct hint.ai_flags = ga_flags; if( DEBUG ) - fprintf( stderr, "[DBUG] siaddress: calling getaddrinfo flags=%x proto=%d family=%d target=%s host=%s port=%s\n", + rmr_vlog( RMR_VL_DEBUG, "siaddress: calling getaddrinfo flags=%x proto=%d family=%d target=%s host=%s port=%s\n", ga_flags, proto, family, target, dstr, pstr ); if( (error = getaddrinfo( dstr, pstr, &hint, &list )) ) { diff --git a/src/rmr/si/src/si95/sicbreg.c b/src/rmr/si/src/si95/sicbreg.c index 9adb0c0..9c7bba7 100644 --- a/src/rmr/si/src/si95/sicbreg.c +++ b/src/rmr/si/src/si95/sicbreg.c @@ -39,7 +39,7 @@ extern void SIcbreg( struct ginfo_blk *gptr, int type, int ((*fptr)()), void * dptr ) { if( gptr == NULL ) { - fprintf( stderr, "[ERR] SIcbreg -- gptr was nil\n" ); + rmr_vlog( RMR_VL_ERR, "SIcbreg -- gptr was nil\n" ); exit( 1 ); } diff --git a/src/rmr/si/src/si95/siconnect.c b/src/rmr/si/src/si95/siconnect.c index e7fd7b3..842207f 100644 --- a/src/rmr/si/src/si95/siconnect.c +++ b/src/rmr/si/src/si95/siconnect.c @@ -46,7 +46,7 @@ extern void SImap_fd( struct ginfo_blk *gptr, int fd, struct tp_blk* tpptr ) { if( fd < MAX_FDS ) { gptr->tp_map[fd] = tpptr; } else { - fprintf( stderr, "[WRN] fd on connected session is out of range: %d\n", fd ); + rmr_vlog( RMR_VL_WARN, "fd on connected session is out of range: %d\n", fd ); } } diff --git a/src/rmr/si/src/si95/siinit.c b/src/rmr/si/src/si95/siinit.c index 80bfbdc..9159f69 100644 --- a/src/rmr/si/src/si95/siinit.c +++ b/src/rmr/si/src/si95/siinit.c @@ -121,7 +121,7 @@ extern void SItp_stats( void *vgp ) { if( (gp = (struct ginfo_blk *) vgp) != NULL ) { for( tp = gp->tplist; tp != NULL; tp = tp->next ) { - fprintf( stderr, "[DBUG] si95: tp: fd=%d sent=%lld rcvd=%lld qc=%lld\n", tp->fd, tp->sent, tp->rcvd, tp->qcount ); + rmr_vlog( RMR_VL_DEBUG, "si95: tp: fd=%d sent=%lld rcvd=%lld qc=%lld\n", tp->fd, tp->sent, tp->rcvd, tp->qcount ); } } } diff --git a/src/rmr/si/src/si95/sisetup.h b/src/rmr/si/src/si95/sisetup.h index 5d72b48..5c88c27 100644 --- a/src/rmr/si/src/si95/sisetup.h +++ b/src/rmr/si/src/si95/sisetup.h @@ -40,6 +40,8 @@ #include // various system files - types #include // socket defs +#include + // pure bsd supports SIGCHLD not SIGCLD as in bastard flavours #ifndef SIGCHLD #define SIGCHLD SIGCLD diff --git a/src/rmr/si/src/si95/siwait.c b/src/rmr/si/src/si95/siwait.c index 75de117..cf06838 100644 --- a/src/rmr/si/src/si95/siwait.c +++ b/src/rmr/si/src/si95/siwait.c @@ -80,7 +80,7 @@ extern int SIwait( struct ginfo_blk *gptr ) { gptr->sierr = SI_ERR_HANDLE; if( gptr->magicnum != MAGICNUM ) { // if not a valid ginfo block - fprintf( stderr, "[CRI] SI95: wait: bad global info struct magic number is wrong\n" ); + rmr_vlog( RMR_VL_CRIT, "SI95: wait: bad global info struct magic number is wrong\n" ); return SI_ERROR; } diff --git a/src/rmr/si/src/sr_si_static.c b/src/rmr/si/src/sr_si_static.c index 6f433ac..c067948 100644 --- a/src/rmr/si/src/sr_si_static.c +++ b/src/rmr/si/src/sr_si_static.c @@ -119,7 +119,7 @@ static rmr_mbuf_t* alloc_zcmsg( uta_ctx_t* ctx, rmr_mbuf_t* msg, int size, int s if( msg == NULL && (msg = (rmr_mbuf_t *) uta_ring_extract( ctx->zcb_mring )) == NULL ) { msg = (rmr_mbuf_t *) malloc( sizeof *msg ); if( msg == NULL ) { - fprintf( stderr, "[CRI] rmr_alloc_zc: cannot get memory for message\n" ); + rmr_vlog( RMR_VL_CRIT, "rmr_alloc_zc: cannot get memory for message\n" ); return NULL; // we used to exit -- that seems wrong } memset( msg, 0, sizeof( *msg ) ); // tp_buffer will be allocated below @@ -137,7 +137,7 @@ static rmr_mbuf_t* alloc_zcmsg( uta_ctx_t* ctx, rmr_mbuf_t* msg, int size, int s msg->rts_fd = -1; // must force to be invalid; not a received message that can be returned if( !msg->alloc_len && (msg->tp_buf = (void *) malloc( mlen )) == NULL ) { - fprintf( stderr, "[CRI] rmr_alloc_zc: cannot get memory for zero copy buffer: %d bytes\n", (int) mlen ); + rmr_vlog( RMR_VL_CRIT, "rmr_alloc_zc: cannot get memory for zero copy buffer: %d bytes\n", (int) mlen ); abort( ); // toss out a core file for this } @@ -170,7 +170,7 @@ static rmr_mbuf_t* alloc_zcmsg( uta_ctx_t* ctx, rmr_mbuf_t* msg, int size, int s strncpy( (char *) ((uta_mhdr_t *)msg->header)->src, ctx->my_name, RMR_MAX_SRC ); strncpy( (char *) ((uta_mhdr_t *)msg->header)->srcip, ctx->my_ip, RMR_MAX_SRC ); - if( DEBUG > 1 ) fprintf( stderr, "[DBUG] alloc_zcmsg mlen=%ld size=%d mpl=%d flags=%02x\n", (long) mlen, size, ctx->max_plen, msg->flags ); + if( DEBUG > 1 ) rmr_vlog( RMR_VL_DEBUG, "alloc_zcmsg mlen=%ld size=%d mpl=%d flags=%02x\n", (long) mlen, size, ctx->max_plen, msg->flags ); return msg; } @@ -190,7 +190,7 @@ static rmr_mbuf_t* alloc_mbuf( uta_ctx_t* ctx, int state ) { } } else { if( (msg = (rmr_mbuf_t *) malloc( sizeof *msg )) == NULL ) { - fprintf( stderr, "[CRI] rmr_alloc_mbuf: cannot get memory for message\n" ); + rmr_vlog( RMR_VL_CRIT, "rmr_alloc_mbuf: cannot get memory for message\n" ); return NULL; // this used to exit, but that seems wrong } } @@ -294,14 +294,14 @@ static inline rmr_mbuf_t* clone_msg( rmr_mbuf_t* old_msg ) { nm = (rmr_mbuf_t *) malloc( sizeof *nm ); if( nm == NULL ) { - fprintf( stderr, "[CRI] rmr_clone: cannot get memory for message buffer\n" ); + rmr_vlog( RMR_VL_CRIT, "rmr_clone: cannot get memory for message buffer\n" ); exit( 1 ); } memset( nm, 0, sizeof( *nm ) ); mlen = old_msg->alloc_len; // length allocated before if( (nm->tp_buf = (void *) malloc( sizeof( char ) * (mlen + TP_HDR_LEN) )) == NULL ) { - fprintf( stderr, "[CRI] rmr_si_clone: cannot get memory for zero copy buffer: %d\n", (int) mlen ); + rmr_vlog( RMR_VL_CRIT, "rmr_si_clone: cannot get memory for zero copy buffer: %d\n", (int) mlen ); abort(); } @@ -352,7 +352,7 @@ static inline rmr_mbuf_t* realloc_msg( rmr_mbuf_t* old_msg, int tr_len ) { nm = (rmr_mbuf_t *) malloc( sizeof *nm ); if( nm == NULL ) { - fprintf( stderr, "[CRI] rmr_clone: cannot get memory for message buffer\n" ); + rmr_vlog( RMR_VL_CRIT, "rmr_clone: cannot get memory for message buffer\n" ); exit( 1 ); } memset( nm, 0, sizeof( *nm ) ); @@ -361,11 +361,11 @@ static inline rmr_mbuf_t* realloc_msg( rmr_mbuf_t* old_msg, int tr_len ) { tr_old_len = RMR_TR_LEN( hdr ); // bytes in old header for trace mlen = old_msg->alloc_len + (tr_len - tr_old_len); // new length with trace adjustment - if( DEBUG ) fprintf( stderr, "[DBUG] tr_realloc old size=%d new size=%d new tr_len=%d\n", (int) old_msg->alloc_len, (int) mlen, (int) tr_len ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "tr_realloc old size=%d new size=%d new tr_len=%d\n", (int) old_msg->alloc_len, (int) mlen, (int) tr_len ); tpb_len = mlen + TP_HDR_LEN; if( (nm->tp_buf = (void *) malloc( tpb_len)) == NULL ) { - fprintf( stderr, "[CRI] rmr_clone: cannot get memory for zero copy buffer: %d\n", ENOMEM ); + rmr_vlog( RMR_VL_CRIT, "rmr_clone: cannot get memory for zero copy buffer: %d\n", ENOMEM ); exit( 1 ); } memset( nm->tp_buf, 0, tpb_len ); @@ -472,7 +472,7 @@ static inline rmr_mbuf_t* realloc_payload( rmr_mbuf_t* old_msg, int payload_len, old_psize = old_msg->alloc_len - (RMR_HDR_LEN( old_msg->header ) + TP_HDR_LEN); // user payload size in orig message if( !clone && payload_len <= old_psize ) { // not cloning and old is large enough; nothing to do - if( DEBUG ) fprintf( stderr, "[DBUG] rmr_realloc_payload: old msg payload larger than requested: cur=%d need=%d\n", old_psize, payload_len ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "rmr_realloc_payload: old msg payload larger than requested: cur=%d need=%d\n", old_psize, payload_len ); return old_msg; } @@ -480,12 +480,12 @@ static inline rmr_mbuf_t* realloc_payload( rmr_mbuf_t* old_msg, int payload_len, old_tp_buf = old_msg->tp_buf; if( clone ) { - if( DEBUG ) fprintf( stderr, "[DBUG] rmr_realloc_payload: cloning message\n" ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "rmr_realloc_payload: cloning message\n" ); free_tp = 0; nm = (rmr_mbuf_t *) malloc( sizeof( *nm ) ); if( nm == NULL ) { - fprintf( stderr, "[CRI] rmr_realloc_payload: cannot get memory for message buffer. bytes requested: %d\n", (int) sizeof(*nm) ); + rmr_vlog( RMR_VL_CRIT, "rmr_realloc_payload: cannot get memory for message buffer. bytes requested: %d\n", (int) sizeof(*nm) ); return NULL; } memset( nm, 0, sizeof( *nm ) ); @@ -497,9 +497,9 @@ static inline rmr_mbuf_t* realloc_payload( rmr_mbuf_t* old_msg, int payload_len, omhdr = old_msg->header; mlen = hdr_len + (payload_len > old_psize ? payload_len : old_psize); // must have larger in case copy is true - if( DEBUG ) fprintf( stderr, "[DBUG] reallocate for payload increase. new message size: %d\n", (int) mlen ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "reallocate for payload increase. new message size: %d\n", (int) mlen ); if( (nm->tp_buf = (char *) malloc( sizeof( char ) * mlen )) == NULL ) { - fprintf( stderr, "[CRI] rmr_realloc_payload: cannot get memory for zero copy buffer. bytes requested: %d\n", (int) mlen ); + rmr_vlog( RMR_VL_CRIT, "rmr_realloc_payload: cannot get memory for zero copy buffer. bytes requested: %d\n", (int) mlen ); return NULL; } @@ -507,10 +507,10 @@ static inline rmr_mbuf_t* realloc_payload( rmr_mbuf_t* old_msg, int payload_len, SET_HDR_LEN( nm->header ); if( copy ) { // if we need to copy the old payload too - if( DEBUG ) fprintf( stderr, "[DBUG] rmr_realloc_payload: copy payload into new message: %d bytes\n", old_psize ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "rmr_realloc_payload: copy payload into new message: %d bytes\n", old_psize ); memcpy( nm->header, omhdr, sizeof( char ) * (old_psize + RMR_HDR_LEN( omhdr )) ); } else { // just need to copy header - if( DEBUG ) fprintf( stderr, "[DBUG] rmr_realloc_payload: copy only header into new message: %d bytes\n", RMR_HDR_LEN( nm->header ) ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "rmr_realloc_payload: copy only header into new message: %d bytes\n", RMR_HDR_LEN( nm->header ) ); memcpy( nm->header, omhdr, sizeof( char ) * RMR_HDR_LEN( omhdr ) ); } @@ -586,7 +586,7 @@ FIXME: do we need this in the SI world? The only user was the route table colle msg->payload = msg->header; // payload is the whole thing; no header msg->xaction = NULL; - if( DEBUG > 1 ) fprintf( stderr, "[DBUG] rcv_payload: got something: type=%d state=%d len=%d\n", msg->mtype, msg->state, msg->len ); + if( DEBUG > 1 ) rmr_vlog( RMR_VL_DEBUG, "rcv_payload: got something: type=%d state=%d len=%d\n", msg->mtype, msg->state, msg->len ); return msg; */ @@ -636,11 +636,11 @@ static rmr_mbuf_t* send_msg( uta_ctx_t* ctx, rmr_mbuf_t* msg, int nn_sock, int r tot_len = msg->len + PAYLOAD_OFFSET( hdr ) + TP_HDR_LEN; // we only send what was used + header lengths *((int*) msg->tp_buf) = tot_len; - if( DEBUG > 1 ) fprintf( stderr, "[DEBUG] send_msg: ending %d (%x) bytes usr_len=%d alloc=%d retries=%d\n", tot_len, tot_len, msg->len, msg->alloc_len, retries ); + if( DEBUG > 1 ) rmr_vlog( RMR_VL_DEBUG, "send_msg: ending %d (%x) bytes usr_len=%d alloc=%d retries=%d\n", tot_len, tot_len, msg->len, msg->alloc_len, retries ); if( DEBUG > 2 ) dump_40( msg->tp_buf, "sending" ); if( (state = SIsendt( ctx->si_ctx, nn_sock, msg->tp_buf, tot_len )) != SI_OK ) { - if( DEBUG > 1 ) fprintf( stderr, "[DBUG] send_msg: error!! sent state=%d\n", state ); + if( DEBUG > 1 ) rmr_vlog( RMR_VL_DEBUG, "send_msg: error!! sent state=%d\n", state ); msg->state = state; if( retries > 0 && state == SI_ERR_BLOCKED ) { if( --spin_retries <= 0 ) { // don't give up the processor if we don't have to @@ -654,7 +654,7 @@ static rmr_mbuf_t* send_msg( uta_ctx_t* ctx, rmr_mbuf_t* msg, int nn_sock, int r state = 0; // don't loop } } else { - if( DEBUG > 2 ) fprintf( stderr, "[DBUG] sent OK state=%d\n", state ); + if( DEBUG > 2 ) rmr_vlog( RMR_VL_DEBUG, "sent OK state=%d\n", state ); state = 0; msg->state = RMR_OK; hdr = NULL; @@ -676,7 +676,7 @@ static rmr_mbuf_t* send_msg( uta_ctx_t* ctx, rmr_mbuf_t* msg, int nn_sock, int r msg->state = RMR_ERR_SENDFAILED; } - if( DEBUG ) fprintf( stderr, "[DBUG] send failed: %d %s\n", (int) msg->state, strerror( msg->state ) ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "send failed: %d %s\n", (int) msg->state, strerror( msg->state ) ); } return msg; @@ -744,9 +744,7 @@ static rmr_mbuf_t* mtosend_msg( void* vctx, rmr_mbuf_t* msg, int max_to ) { } if( (rte = uta_get_rte( ctx->rtable, msg->sub_id, msg->mtype, TRUE )) == NULL ) { // find the entry which matches subid/type allow fallback to type only key - if( ctx->flags & CTXFL_WARN ) { - fprintf( stderr, "[WARN] no route table entry for mtype=%d sub_id=%d\n", msg->mtype, msg->sub_id ); - } + rmr_vlog( RMR_VL_WARN, "no route table entry for mtype=%d sub_id=%d\n", msg->mtype, msg->sub_id ); msg->state = RMR_ERR_NOENDPT; errno = ENXIO; // must ensure it's not eagain msg->tp_state = errno; @@ -758,7 +756,7 @@ static rmr_mbuf_t* mtosend_msg( void* vctx, rmr_mbuf_t* msg, int max_to ) { while( send_again ) { sock_ok = uta_epsock_rr( rte, group, &send_again, &nn_sock, &ep, ctx->si_ctx ); // select endpt from rr group and set again if more groups - if( DEBUG ) fprintf( stderr, "[DBUG] mtosend_msg: flgs=0x%04x type=%d again=%d group=%d len=%d sock_ok=%d\n", + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "mtosend_msg: flgs=0x%04x type=%d again=%d group=%d len=%d sock_ok=%d\n", msg->flags, msg->mtype, send_again, group, msg->len, sock_ok ); group++; @@ -770,13 +768,11 @@ static rmr_mbuf_t* mtosend_msg( void* vctx, rmr_mbuf_t* msg, int max_to ) { msg->state = RMR_ERR_SENDFAILED; errno = ENOMEM; msg->tp_state = errno; - if( ctx->flags & CTXFL_WARN ) { - fprintf( stderr, "[WARN] unable to clone message for multiple rr-group send\n" ); - } + rmr_vlog( RMR_VL_WARN, "unable to clone message for multiple rr-group send\n" ); return msg; } - if( DEBUG ) fprintf( stderr, "[DBUG] msg cloned: type=%d len=%d\n", msg->mtype, msg->len ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "msg cloned: type=%d len=%d\n", msg->mtype, msg->len ); msg->flags |= MFL_NOALLOC; // keep send from allocating a new message; we have a clone to use msg = send_msg( ctx, msg, nn_sock, max_to ); // do the hard work, msg should be nil on success @@ -791,7 +787,7 @@ static rmr_mbuf_t* mtosend_msg( void* vctx, rmr_mbuf_t* msg, int max_to ) { msg = send_msg( ctx, msg, nn_sock, max_to ); // send the last, and allocate a new buffer; drops the clone if it was if( DEBUG ) { if( msg == NULL ) { - fprintf( stderr, "[DBUG] mtosend_msg: send returned nil message!\n" ); + rmr_vlog( RMR_VL_DEBUG, "mtosend_msg: send returned nil message!\n" ); } } } @@ -813,11 +809,7 @@ static rmr_mbuf_t* mtosend_msg( void* vctx, rmr_mbuf_t* msg, int max_to ) { } } } else { -/* - if( ctx->flags & CTXFL_WARN ) { - fprintf( stderr, "[WARN] invalid socket for rte, setting no endpoint err: mtype=%d sub_id=%d\n", msg->mtype, msg->sub_id ); - } -*/ + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "invalid socket for rte, setting no endpoint err: mtype=%d sub_id=%d\n", msg->mtype, msg->sub_id ); msg->state = RMR_ERR_NOENDPT; errno = ENXIO; } @@ -829,7 +821,7 @@ static rmr_mbuf_t* mtosend_msg( void* vctx, rmr_mbuf_t* msg, int max_to ) { msg->state = RMR_OK; } - if( DEBUG ) fprintf( stderr, "[DBUG] final send stats: ok=%d group=%d state=%d\n\n", ok_sends, group, msg->state ); + if( DEBUG ) rmr_vlog( RMR_VL_DEBUG, "final send stats: ok=%d group=%d state=%d\n", ok_sends, group, msg->state ); msg->tp_state = errno; } diff --git a/test/logging_test.c b/test/logging_test.c new file mode 100644 index 0000000..dfc019d --- /dev/null +++ b/test/logging_test.c @@ -0,0 +1,97 @@ +// : vim ts=4 sw=4 noet : +/* +================================================================================== + Copyright (c) 2019-2020 Nokia + Copyright (c) 2018-2020 AT&T Intellectual Property. + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + 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. +================================================================================== +*/ + + +/* + Mnemonic: symtab_test.c + Abstract: This is the unit test module that will drive tests against + the symbol table portion of RMr. Run with: + ksh unit_test.ksh symtab_test.c + Date: 1 April 2019 + Author: E. Scott Daniels +*/ + +#define NO_DUMMY_RMR 1 // no dummy rmr functions; we don't pull in rmr.h or agnostic.h + +#include "rmr_logging.h" +#include "logging.c" +#include "test_support.c" + +/* + Logging can be difficult to verify as stderr needs to be captured and examined. + We will verify internally what we can, and drive logging functions for coverage. +*/ +int main( ) { + int llevel = 99; + int errors = 0; + + setenv( "RMR_HR_LOG", "1", 1 ); // drive for coverage in init + setenv( "RMR_LOG_VLEVEL", "90", 1 ); // force test for out of range during init + + rmr_vlog( RMR_VL_CRIT, "debug message should not be written\n" ); // force coverage with init call + + llevel = rmr_vlog_init( ); + errors += fail_if_equal( llevel, 99, "llevel was not reset by vlog init" ); + errors += fail_if_equal( llevel, 90, "vlog init did not catch out of range vlog" ); + + llevel = 99; + setenv( "RMR_LOG_VLEVEL", "-10", 1 ); // force test for out of range during init + llevel = rmr_vlog_init( ); + errors += fail_if_equal( llevel, 99, "neg llevel was not reset by vlog init" ); + errors += fail_if_equal( llevel, -10, "vlog init did not catch out of range (neg) vlog" ); + + rmr_set_vlevel( 2 ); + + rmr_vlog( RMR_VL_DEBUG, "debug message should not be written\n" ); + rmr_vlog( RMR_VL_INFO, "info message should not be written\n" ); + rmr_vlog( RMR_VL_WARN, "warn message should not be written\n" ); + rmr_vlog( RMR_VL_ERR, "error message should be written\n" ); + rmr_vlog( RMR_VL_CRIT, "crit message should be written\n" ); + + rmr_set_vlevel( 5 ); + rmr_vlog( RMR_VL_DEBUG, "debug message should be written\n" ); + rmr_vlog( RMR_VL_INFO, "info message should be written\n" ); + rmr_vlog( RMR_VL_WARN, "warn message should be written\n" ); + rmr_vlog( RMR_VL_ERR, "error message should be written\n" ); + rmr_vlog( RMR_VL_CRIT, "crit message should be written\n" ); + + rmr_set_vlevel( 0 ); + rmr_vlog( RMR_VL_DEBUG, "debug message should not be written\n" ); + rmr_vlog( RMR_VL_INFO, "info message should not be written\n" ); + rmr_vlog( RMR_VL_WARN, "warn message should not be written\n" ); + rmr_vlog( RMR_VL_ERR, "error message should not be written\n" ); + rmr_vlog( RMR_VL_CRIT, "crit message should not be written\n" ); + + rmr_set_vlevel( 1 ); + rmr_vlog_force( RMR_VL_DEBUG, "debug forced message should be written\n" ); + rmr_vlog_force( RMR_VL_INFO, "info forced message should be written\n" ); + rmr_vlog_force( RMR_VL_WARN, "warn forced message should be written\n" ); + rmr_vlog_force( RMR_VL_ERR, "error forced message should be written\n" ); + rmr_vlog_force( RMR_VL_CRIT, "crit forced message should be written\n" ); + + + rmr_vlog( -1, "out of range message might be written\n" ); // drive range checks + rmr_vlog( 10, "out of range message should not be written\n" ); + + rmr_vlog_force( -1, "out of range message might be written\n" ); // drive range checks + rmr_vlog_force( 10, "out of range message should not be written\n" ); + + return errors > 0; +} diff --git a/test/rmr_nng_test.c b/test/rmr_nng_test.c index 4fd6f02..a3aeb40 100644 --- a/test/rmr_nng_test.c +++ b/test/rmr_nng_test.c @@ -68,10 +68,12 @@ #include "rmr.h" // things the users see #include "rmr_symtab.h" +#include "rmr_logging.h" #include "rmr_agnostic.h" // transport agnostic header #include "rmr_nng_private.h" // transport specific #include "symtab.c" +#include "logging.c" #include "rmr_nng.c" #include "mbuf_api.c" diff --git a/test/tools_test.c b/test/tools_test.c index 4bcd597..35aa62f 100644 --- a/test/tools_test.c +++ b/test/tools_test.c @@ -39,6 +39,7 @@ #include #include "rmr.h" +#include "rmr_logging.h" #include "rmr_agnostic.h" #include "test_support.c" // our private library of test tools diff --git a/test/unit_test.ksh b/test/unit_test.ksh index 8b21fee..08811f6 100755 --- a/test/unit_test.ksh +++ b/test/unit_test.ksh @@ -337,6 +337,8 @@ run_nano_tests=0 export RMR_WARNING=1 # turn on warnings +ulimit -c unlimited + while [[ $1 == "-"* ]] do case $1 in -- 2.16.6