diff --git a/examples/server.js b/examples/server.js index eef0308..2e7d0d3 100755 --- a/examples/server.js +++ b/examples/server.js @@ -8,29 +8,29 @@ const delay = (seconds) => function my_stfc_connection(request_context, abap_input) { const connection_attributes = request_context["connection_attributes"]; console.log( - "NodeJS stfc context :", + "[js] stfc context :", connection_attributes["sysId"], connection_attributes["client"], connection_attributes["user"], connection_attributes["cpicConvId"], connection_attributes["progName"] ); - console.log("NodeJS stfc request :", abap_input); + console.log("[js] stfc request :", abap_input); for (let i = 1; i < 1000000000; i++) x = i / 3; - // (async () => await delay(5))(); + //const x = (async () => await delay(5))(); abap_output = { REQUTEXT: abap_input.REQUTEXT, ECHOTEXT: abap_input.REQUTEXT, RESPTEXT: `~~~ ${abap_input.REQUTEXT} ~~~`, }; - console.log("NodeJS stfc response:", abap_output); + console.log("[js] stfc response:", abap_output); return abap_output; } server.start((err) => { if (err) return console.error("error:", err); console.log( - `Server alive: ${server.alive} client handle: ${server.client_connection} server handle: ${server.server_connection}` + `[js] Server alive: ${server.alive} client handle: ${server.client_connection} server handle: ${server.server_connection}` ); // Expose the my_stfc_connection function as RFM with STFC_CONNECTION pararameters (function definition) @@ -38,7 +38,7 @@ server.start((err) => { server.addFunction(RFM_NAME, my_stfc_connection, (err) => { if (err) return console.error(`error adding ${RFM_NAME}: ${err}`); console.log( - `Node.js function '${my_stfc_connection.name}' registered as ABAP '${RFM_NAME}' function` + `[js] Node.js function '${my_stfc_connection.name}' registered as ABAP '${RFM_NAME}' function` ); }); }); @@ -52,6 +52,8 @@ const si = setInterval(() => { setTimeout(() => { server.stop(() => { clearInterval(si); - console.log("bye bye!"); + console.log("bye!"); }); }, 10 * 1000); + +// my_stfc_connection({}, {}); diff --git a/package.json b/package.json index a096882..dd8ed76 100755 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "node-rfc", - "version": "3.2.0", + "version": "3.3.0", "description": "nodejs bindings for SAP NW RFC SDK", "keywords": [ "sap", diff --git a/src/cpp/Client.cc b/src/cpp/Client.cc index 05fd394..dde8191 100644 --- a/src/cpp/Client.cc +++ b/src/cpp/Client.cc @@ -5,6 +5,7 @@ #include "Client.h" #include #include +#include "Log.h" #include "Pool.h" namespace node_rfc { @@ -122,8 +123,6 @@ Client::Client(const Napi::CallbackInfo& info) : Napi::ObjectWrap(info) { init(); - DEBUG("Client::Client ", id); - if (!info[0].IsUndefined() && (info[0].IsFunction() || !info[0].IsObject())) { Napi::TypeError::New(Env(), "Client connection parameters missing") .ThrowAsJavaScriptException(); @@ -148,25 +147,35 @@ Client::Client(const Napi::CallbackInfo& info) info.Length()); Napi::TypeError::New(node_rfc::__env, errmsg).ThrowAsJavaScriptException(); } + + _log(logClass::client, logSeverity::info, "client created: ", id); }; Client::~Client(void) { - DEBUG("~ Client ", id); - if (pool == nullptr) { // Close own connection if (connectionHandle != nullptr) { RFC_ERROR_INFO errorInfo; - DEBUG("Closing direct connection ", (pointer_t)connectionHandle); + _log(logClass::client, + logSeverity::info, + id, + " closing connection ", + (pointer_t)connectionHandle); RFC_RC rc = RfcCloseConnection(connectionHandle, &errorInfo); if (rc != RFC_OK) { EDEBUG("Warning: Error closing the direct connection handle ", - (pointer_t)connectionHandle, + (uintptr_t)connectionHandle, " client ", id); } } else { - DEBUG("Client ", id, " handle already closed"); + _log(logClass::client, + logSeverity::warning, + "Client ", + id, + " connection ", + (uintptr_t)connectionHandle, + " already closed"); } // Unref client config @@ -190,7 +199,6 @@ Napi::Value Client::connectionClosedError(const char* suffix) { } Napi::Object Client::NewInstance(Napi::Env env) { - // DEBUG("Client::NewInstance"); Napi::EscapableHandleScope scope(env); Napi::Object obj = env.GetInstanceData()->New({}); return scope.Escape(napi_value(obj)).ToObject(); @@ -537,7 +545,10 @@ ErrorPair Client::connectionCheck(RFC_ERROR_INFO* errorInfo) { ) // closed { if (errorInfo->code == RFC_CANCELED) { - EDEBUG("Connection canceled ", (pointer_t)this->connectionHandle); + _log(logClass::client, + logSeverity::warning, + "connection cancelled ", + (pointer_t)this->connectionHandle); } RFC_CONNECTION_HANDLE new_handle; @@ -565,22 +576,32 @@ ErrorPair Client::connectionCheck(RFC_ERROR_INFO* errorInfo) { return ErrorPair(errorInfoOpen, updateError); } - DEBUG("new handle assigned to managed client"); + _log(logClass::pool, + logSeverity::info, + "closed connection handle ", + (uintptr_t)old_handle, + " replaced with ", + (uintptr_t)new_handle); this->connectionHandle = new_handle; } else { // assign new handle to direct client this->connectionHandle = new_handle; } - DEBUG("Critical connection error: group ", - errorInfo->group, - " code ", - errorInfo->code, - " closed handle ", - (pointer_t)old_handle, - " new handle ", - (pointer_t)new_handle); + _log(logClass::client, + logSeverity::warning, + "Critical ABAP error: group ", + errorInfo->group, + " code ", + errorInfo->code, + " closed connection handle ", + (pointer_t)old_handle, + " replaced with ", + (pointer_t)new_handle); } else { - DEBUG("Non-critical ABAP error: ", (pointer_t)this->connectionHandle); + _log(logClass::client, + logSeverity::warning, + "Non-critical ABAP error: ", + (pointer_t)this->connectionHandle); } return ErrorPair(errorInfoOpen, ""); @@ -612,7 +633,10 @@ Napi::Value Client::Release(const Napi::CallbackInfo& info) { void cancelConnection(RFC_RC* rc, RFC_CONNECTION_HANDLE connectionHandle, RFC_ERROR_INFO* errorInfo) { - EDEBUG("Cancel connection ", (pointer_t)connectionHandle); + _log(logClass::client, + logSeverity::info, + "connection cancelled ", + (pointer_t)connectionHandle); *rc = RfcCancel(connectionHandle, errorInfo); } diff --git a/src/cpp/Log.h b/src/cpp/Log.h new file mode 100644 index 0000000..0c1308e --- /dev/null +++ b/src/cpp/Log.h @@ -0,0 +1,71 @@ +// SPDX-FileCopyrightText: 2014 SAP SE Srdjan Boskovic +// +// SPDX-License-Identifier: Apache-2.0 + +#ifndef NodeRfc_Log_H +#define NodeRfc_Log_H + +#include +#include +#include + +namespace node_rfc { + +#define SERVER_LOGFILE "_noderfc.log" + +enum class logClass { client, pool, server, throughput }; +enum class logSeverity { info, warning, error }; + +long long timestamp() { + using namespace std; + return chrono::duration_cast( + chrono::system_clock::now().time_since_epoch()) + .count(); +} + +template +void _log(logClass component, logSeverity severity, Args&&... args) { + using namespace std; + string component_name; + string severity_name; + switch (component) { + case logClass::client: + component_name = "client"; + break; + case logClass::server: + component_name = "server"; + break; + case logClass::pool: + component_name = "pool"; + break; + case logClass::throughput: + component_name = "throughput"; + break; + default: + component_name = "component?"; + } + switch (severity) { + case logSeverity::info: + severity_name = "info"; + break; + case logSeverity::warning: + severity_name = "warning"; + break; + case logSeverity::error: + severity_name = "error"; + break; + default: + severity_name = "severity?"; + } + ofstream ofs; + ofs.open(SERVER_LOGFILE, ofstream::out | ios::app); + time_t now = time(nullptr); + ofs << put_time(localtime(&now), "%F %T [") << timestamp() << "] "; + ofs << component_name << " (" << severity_name << ") "; + (ofs << ... << args); + ofs << endl; + ofs.close(); +} + +} // namespace node_rfc +#endif \ No newline at end of file diff --git a/src/cpp/Server.cc b/src/cpp/Server.cc index 2ae1647..c18840c 100644 --- a/src/cpp/Server.cc +++ b/src/cpp/Server.cc @@ -67,8 +67,6 @@ Server::Server(const Napi::CallbackInfo& info) init(); - DEBUG("Server::Server ", id); - if (!info[0].IsObject()) { Napi::TypeError::New(Env(), "Server constructor requires server parameters") .ThrowAsJavaScriptException(); @@ -106,7 +104,6 @@ Server::Server(const Napi::CallbackInfo& info) Napi::Error::New(info.Env(), rfcSdkError(&errorInfo).ToString()) .ThrowAsJavaScriptException(); } - DEBUG("Server:: client connection open:", (uintptr_t)client_conn_handle); // create server serverHandle = RfcCreateServer(server_params.connectionParams, 1, &errorInfo); @@ -114,7 +111,12 @@ Server::Server(const Napi::CallbackInfo& info) Napi::Error::New(info.Env(), rfcSdkError(&errorInfo).ToString()) .ThrowAsJavaScriptException(); } - DEBUG("Server:: created ", (uintptr_t)serverHandle); + _log(logClass::server, + logSeverity::info, + "created; server handle", + (uintptr_t)serverHandle, + " client connection ", + (uintptr_t)client_conn_handle); }; Napi::Value wrapUnitIdentifier(RFC_UNIT_IDENTIFIER* uIdentifier) { @@ -151,11 +153,8 @@ Napi::Value getServerRequestContext(ServerRequestBaton* requestBaton) { const std::string call_type[4] = { "synchronous", "transactional", "queued", "background_unit"}; - if (requestBaton->request_connection_handle == nullptr) { - // todo error ... - } - Napi::Object requestContext = Napi::Object::New(node_rfc::__env); + requestContext.Set( "client_connection", Napi::Number::New(node_rfc::__env, @@ -172,7 +171,10 @@ Napi::Value getServerRequestContext(ServerRequestBaton* requestBaton) { requestBaton->errorInfo); if (rc != RFC_OK || requestBaton->errorInfo->code != RFC_OK) { - DEBUG("[error] Request context not set", requestContext) + _log(logClass::server, + logSeverity::error, + "Request context not set", + requestContext); return requestContext; } @@ -188,7 +190,6 @@ Napi::Value getServerRequestContext(ServerRequestBaton* requestBaton) { if (context.type == RFC_BACKGROUND_UNIT) { requestContext.Set("unitAttr", wrapUnitAttributes(context.unitAttributes)); } - DEBUG("Request context set", requestContext); return requestContext; } @@ -212,14 +213,24 @@ RFC_RC SAP_API metadataLookup(SAP_UC const* func_name, } if (rc == RFC_OK) { - DEBUG("Function found ", - it->first, - " descriptor ", - (pointer_t)*func_desc_handle); + _log(logClass::server, + logSeverity::info, + "Function found ", + it->first, + " description ", + (pointer_t)*func_desc_handle); } else { - // todo - DEBUG("[error] Function not found: "); - printfU(func_name); + _log(logClass::server, + logSeverity::error, + "Function not found ", + it->first, + " description ", + (pointer_t)*func_desc_handle); + // No access to JS and wrapString and ABAP function name + // can't be converted to unicode here. + // Write therefore to stdout + printf("\nserver [error] Function not found: "); + printfU(func_name, "\n"); } return rc; @@ -274,15 +285,20 @@ RFC_RC SAP_API genericRequestHandler(RFC_CONNECTION_HANDLE conn_handle, requestBaton->func_desc_handle = it->second->func_desc_handle; requestBaton->errorInfo = errorInfo; requestBaton->errorPath = errorPath; - - DEBUG("Generic request handler: ", - it->first, - " function handle ", - (uintptr_t)func_handle, - " descriptor: ", - (uintptr_t)requestBaton->func_desc_handle, - " from client connection: ", - (uintptr_t)conn_handle); + requestBaton->jsFunctionName = it->second->jsFunctionName; + + _log(logClass::server, + logSeverity::info, + "Client request for JS function ", + it->second->jsFunctionName, + " as ABAP function ", + it->first, + " using function handle ", + (uintptr_t)func_handle, + ", descriptor ", + (uintptr_t)requestBaton->func_desc_handle, + " client connection: ", + (uintptr_t)conn_handle); it->second->tsfnRequest.NonBlockingCall(requestBaton); @@ -334,9 +350,11 @@ class StopAsync : public Napi::AsyncWorker { void Execute() { server->LockMutex(); - DEBUG("Server::stop ", (pointer_t)server->serverHandle); + _log(logClass::server, + logSeverity::info, + "stop: ", + (pointer_t)server->serverHandle); server->_stop(); - DEBUG("Server:: stopped") server->UnlockMutex(); } @@ -395,8 +413,6 @@ class GetFunctionDescAsync : public Napi::AsyncWorker { }; Napi::Value Server::Start(const Napi::CallbackInfo& info) { - DEBUG("Server::Serve"); - std::ostringstream errmsg; if (!info[0].IsFunction()) { @@ -418,26 +434,36 @@ void Server::_start(RFC_ERROR_INFO* errorInfo) { if (errorInfo->code != RFC_OK) { return; } - DEBUG("Server:: generic request handler installed"); + _log(logClass::server, + logSeverity::info, + "start: generic request handler installed"); RfcLaunchServer(serverHandle, errorInfo); if (errorInfo->code != RFC_OK) { return; } - DEBUG("Server:: launched ", (pointer_t)serverHandle) + _log(logClass::server, + logSeverity::info, + "start: launched ", + (pointer_t)serverHandle); } void Server::_stop() { if (serverHandle != nullptr) { - DEBUG("Server stop: destroy ", (pointer_t)serverHandle); + _log(logClass::server, + logSeverity::info, + "stop: shutdown and destroy ", + (pointer_t)serverHandle); RfcShutdownServer(serverHandle, 60, nullptr); RfcDestroyServer(serverHandle, nullptr); serverHandle = nullptr; } if (client_conn_handle != nullptr) { - DEBUG("Server stop: close client connection ", - (pointer_t)client_conn_handle); + _log(logClass::server, + logSeverity::info, + "stop: close client connection ", + (pointer_t)client_conn_handle); RfcCloseConnection(client_conn_handle, nullptr); client_conn_handle = nullptr; } @@ -452,14 +478,12 @@ void Server::_stop() { } if (st.joinable()) { - DEBUG("Server stop: serve() thread join") + _log(logClass::server, logSeverity::info, "stop: serve() thread join"); st.join(); } } Napi::Value Server::Stop(const Napi::CallbackInfo& info) { - DEBUG("Server::Stop"); - std::ostringstream errmsg; if (!info[0].IsFunction()) { @@ -545,6 +569,9 @@ Napi::Value Server::AddFunction(const Napi::CallbackInfo& info) { // ABAP function description found. // Create thread-safe JS function to be called by genericRequestHandler + std::string jsFunctionName = + jsFunction.As().Get("name").As().Utf8Value(); + serverFunctions[functionName.Utf8Value()] = new ServerFunctionStruct( this, func_name, @@ -554,15 +581,19 @@ Napi::Value Server::AddFunction(const Napi::CallbackInfo& info) { "ServerRequestTsfn", // Resource name 0, // Unlimited queue 1 // Only one thread will use this initially - ) - - ); + ), + // Save JS function name for server logging later on + jsFunctionName); delete[] func_name; - DEBUG("Function added ", - functionName.Utf8Value(), - " descriptor: ", - (pointer_t)func_desc_handle); + _log(logClass::server, + logSeverity::info, + "Function added ", + jsFunctionName, + " as ABAP function ", + functionName.Utf8Value(), + " description: ", + (pointer_t)func_desc_handle); callback.Call({}); return info.Env().Undefined(); @@ -587,8 +618,6 @@ Napi::Value Server::RemoveFunction(const Napi::CallbackInfo& info) { return info.Env().Undefined(); } - DEBUG("Server::RemoveFunction ", functionName.Utf8Value()); - if (!info[1].IsFunction()) { errmsg << "Server removeFunction() requires a callback function"; Napi::TypeError::New(info.Env(), errmsg.str()).ThrowAsJavaScriptException(); @@ -597,8 +626,6 @@ Napi::Value Server::RemoveFunction(const Napi::CallbackInfo& info) { Napi::Function callback = info[1].As(); - // Remove function - SAP_UC* func_name = setString(functionName); ServerFunctionsMap::iterator it = serverFunctions.begin(); @@ -617,10 +644,14 @@ Napi::Value Server::RemoveFunction(const Napi::CallbackInfo& info) { return info.Env().Undefined(); } - DEBUG("Server::RemoveFunction removed ", - functionName.Utf8Value(), - ": ", - (pointer_t)it->second->func_desc_handle); + _log(logClass::server, + logSeverity::info, + "Function removed ", + it->second->jsFunctionName, + " as ABAP function ", + functionName.Utf8Value(), + " description: ", + (pointer_t)it->second->func_desc_handle); serverFunctions.erase(it); callback.Call({}); @@ -628,8 +659,6 @@ Napi::Value Server::RemoveFunction(const Napi::CallbackInfo& info) { }; Napi::Value Server::GetFunctionDescription(const Napi::CallbackInfo& info) { - DEBUG("Server::GetFunctionDescription"); - std::ostringstream errmsg; if (!info[0].IsString()) { @@ -653,7 +682,6 @@ Napi::Value Server::GetFunctionDescription(const Napi::CallbackInfo& info) { }; Server::~Server(void) { - DEBUG("~ Server ", id); this->_stop(); } @@ -697,9 +725,19 @@ void JSFunctionCall(Napi::Env env, requestBaton->paramNames = Napi::Persistent(abapArgs.GetPropertyNames()); // Call JavaScript handler - DEBUG("ServerCallJs start: ", (uintptr_t)requestBaton->func_handle); + _log(logClass::server, + logSeverity::info, + "JS call start ", + requestBaton->jsFunctionName, + " with ABAP function handle ", + (uintptr_t)requestBaton->func_handle); Napi::Value result = callback.Call({requestContext, abapArgs}); - DEBUG("ServerCallJs end: ", (uintptr_t)requestBaton->func_handle); + _log(logClass::server, + logSeverity::info, + "JS call end ", + requestBaton->jsFunctionName, + " with ABAP function handle ", + (uintptr_t)requestBaton->func_handle); // Transform JavaScript parameters' data to ABAP Napi::Object params = result.ToObject(); diff --git a/src/cpp/Server.h b/src/cpp/Server.h index a2d68ed..8a346e5 100644 --- a/src/cpp/Server.h +++ b/src/cpp/Server.h @@ -9,15 +9,17 @@ #include #include #include "Client.h" +#include "Log.h" namespace node_rfc { -// +// Created in genericRequestHandler to set ABAP data for JSFunctionCall struct ServerRequestBaton { RFC_CONNECTION_HANDLE request_connection_handle = nullptr; RFC_FUNCTION_DESC_HANDLE func_desc_handle; RFC_FUNCTION_HANDLE func_handle; RFC_ERROR_INFO* errorInfo; + std::string jsFunctionName; node_rfc::RfmErrorPath errorPath; node_rfc::ClientOptionsStruct client_options; @@ -30,17 +32,38 @@ struct ServerRequestBaton { void wait() { std::thread::id this_tid = std::this_thread::get_id(); - DEBUG("JavaScript call lock ", this_tid, " ", server_call_completed); + _log(logClass::server, + logSeverity::info, + "JS call lock ", + jsFunctionName, + " thread ", + this_tid, + " ", + server_call_completed); std::unique_lock lock(server_call_mutex); server_call_condition.wait(lock, [this] { return server_call_completed; }); - DEBUG("JavaScript call unlock ", this_tid, " ", server_call_completed); + _log(logClass::server, + logSeverity::info, + "JS call unlock ", + jsFunctionName, + " thread ", + this_tid, + " ", + server_call_completed); } void done() { std::thread::id this_tid = std::this_thread::get_id(); server_call_completed = true; server_call_condition.notify_one(); - DEBUG("JavaScript call completed ", this_tid, " ", server_call_completed); + _log(logClass::server, + logSeverity::info, + "JS call completed ", + jsFunctionName, + " thread ", + this_tid, + " ", + server_call_completed); } }; @@ -58,17 +81,20 @@ typedef struct _ServerFunctionStruct { RFC_ABAP_NAME func_name; RFC_FUNCTION_DESC_HANDLE func_desc_handle = nullptr; ServerRequestTsfn tsfnRequest = nullptr; + std::string jsFunctionName; _ServerFunctionStruct() { func_name[0] = 0; } _ServerFunctionStruct(Server* _server, RFC_ABAP_NAME _func_name, RFC_FUNCTION_DESC_HANDLE _func_desc_handle, - ServerRequestTsfn _tsfnRequest) { + ServerRequestTsfn _tsfnRequest, + std::string _jsFunctionName) { server = _server; strcpyU(func_name, _func_name); func_desc_handle = _func_desc_handle; tsfnRequest = _tsfnRequest; + jsFunctionName = _jsFunctionName; } _ServerFunctionStruct& operator=( @@ -78,6 +104,7 @@ typedef struct _ServerFunctionStruct { strcpyU(func_name, src.func_name); func_desc_handle = src.func_desc_handle; tsfnRequest = src.tsfnRequest; + jsFunctionName = src.jsFunctionName; return *this; } diff --git a/src/cpp/noderfc.h b/src/cpp/noderfc.h index d66e25b..59b3706 100644 --- a/src/cpp/noderfc.h +++ b/src/cpp/noderfc.h @@ -16,14 +16,14 @@ // // Logging // -#define LOG_RFC_CLIENT 1 +// #define LOG_RFC_CLIENT 1 #ifdef LOG_RFC_CLIENT // Version unit test will fail, preventing the release with activated logging #define NODERFC_VERSION "Deactivate logging: LOG_RFC_CLIENT" #else // client binding version -#define NODERFC_VERSION "3.2.0" +#define NODERFC_VERSION "3.3.0" #endif template