Using Client in a class library and unit testing process fails to get message response

[Mudoch]

I've been developing a solution that I need to access data in a large DB. Ran into infrastructure issues at multiple clients, IT says NO SQL server allowed. My bypass of that is a TCP "service" that uses SQLite as the DB. The catch is the solution must be accessed through VBA, not an MS Office front end. Using .Net 4.7.2 COM exposed class library to accomplish this.

That said, I have a successful WatsonTCP server built and tested with WatsonTCP.Test.Client app. But when I add the client into the class library (.net 4.72) and test using nunit 3. I never get the response message back from an internal authenticate, NOT SSL auth process. The server fails in send: if(!_Client.Send(.....)) response with Failed message per the server log. The client side MessageReceived(object sender, MessageReceivedEventArgs args) never gets called.

    //Server side MessageReceived(...)
        RequestIn rqIn = JsonSerializer.Deserialize<RequestIn>(sdata);
        if (rqIn.Command.ToUpper() == "AUTHENTICATE") //First we authorize access
        {
          _logger.LogInformation("<{IP}> Authenticated: {Data}", args.IpPort, rqIn.Parameters);
          _Connections = _Connections.Add(args.IpPort);
          if (!_Server.Send(args.IpPort, JsonSerializer.Serialize(new ResponseOut
          {
            Command = rqIn.Command,
            Result = 200,
            ResponseInfo = null
          }))) 
          {
            _logger.LogInformation("<{source}> Authenticate failed to send OK", args.IpPort);
          }

    //Connect to DB server and auth for access Clinet side
    ....
    try
      {
        if (_Client != null) _Client.Dispose();
        _Client = new WatsonTcpClient(serverURL, port);
        _Client.Events.AuthenticationFailure += AuthFailure;
        _Client.Events.ServerConnected += ServerConnected;
        _Client.Events.ServerDisconnected += ServerDisconnected;
        _Client.Events.MessageReceived += MessageReceived;

        _Client.Settings.DebugMessages = enableDebug;
        _Client.Settings.NoDelay = true;

        _Client.Keepalive.EnableTcpKeepAlives = true;
        _Client.Keepalive.TcpKeepAliveInterval = 1;
        _Client.Keepalive.TcpKeepAliveTime = 1;
        _Client.Keepalive.TcpKeepAliveRetryCount = 3;

        _Client.Connect();
        string tmp = string.Concat("\"", authId.Replace("\\","\\\\"), ",", @authPass.Replace("\\", "\\\\"), "\"").Trim();
        //bool tst = is a temp action for manual debugging it is always true with the send to server
        bool tst =_Client.Send("{\"Command\":\"Authenticate\",\"Parameters\":" + @tmp + "}");
      }
      catch (Exception ex)
      {
        ReportStatus(new StatusMsgEventArgs(LogLevels.Information, source, ex.Message));
        return ErrorCode(9990);
      }
      return 0;
    }

The Nunit test looks like

   [Test()]
    public void OpenIPDatabaseWithEventHandlerTest()
    {
      PostalUtilData tst = GetTestObjSQLITE(false);
      tst.StatusMessage += Tst_ActionTaken;
      Assert.That(() => tst.OpenIPDatabase(sqlIteServer, sqlItePort, _pcName, _authId, false), Throws.Nothing, tst.ErrorMessage);
      
    }

    private PostalUtilData GetTestObjSQLITE(bool doOpen = true)
    {
      PostalUtilData tstObj = null;

      Assert.That(() => tstObj = new PostalUtilData(dbShortName), Throws.Nothing);
      if (doOpen)
      {
        //tstObj.DbConnectionString = dbCnnStr;
        Assert.That(() => tstObj.OpenIPDatabase(sqlIteServer, sqlItePort, _pcName, _authId, false), Throws.Nothing, tstObj.ErrorMessage);
      }
      return tstObj;
    }

Here is the server side log I get:

2022-01-27 15:40:39.773 VS2019-VM\lawre [INFO] <1> Start USPS Data Server
2022-01-27 15:40:40.166 VS2019-VM\lawre [DBUG] <1> Hosting starting
2022-01-27 15:40:40.361 VS2019-VM\lawre [INFO] <1> (PostalDataLib.ValidateSysDB) Checking for required system tables and views
2022-01-27 15:40:40.985 VS2019-VM\lawre [DBUG] <1> (PostalDataLib.ValidateSysDB) Checking for required data in system tables
2022-01-27 15:40:41.134 VS2019-VM\lawre [DBUG] <1> (PostalDataLib.ValidateSysDB) System Database validated.
2022-01-27 15:40:41.135 VS2019-VM\lawre [INFO] <1> (PostalDataLib.ValidateCustDB) Checking for required customer tables and views
2022-01-27 15:40:41.149 VS2019-VM\lawre [DBUG] <1> (PostalDataLib.ValidateCustDB) Customer Database validated.
2022-01-27 15:40:41.149 VS2019-VM\lawre [INFO] <1> Worker running <1>
2022-01-27 15:40:41.151 VS2019-VM\lawre [INFO] <1> Application started. Press Ctrl+C to shut down.
2022-01-27 15:40:41.151 VS2019-VM\lawre [INFO] <1> Hosting environment: Development
2022-01-27 15:40:41.151 VS2019-VM\lawre [INFO] <1> Content root path: Repos\PostalDataLib\PostDataService
2022-01-27 15:40:41.151 VS2019-VM\lawre [DBUG] <1> Hosting started
2022-01-27 15:40:54.522 VS2019-VM\lawre [INFO] <4> <127.0.0.1:54206> Connected
2022-01-27 15:40:54.800 VS2019-VM\lawre [INFO] <8> <127.0.0.1:54206> Disconnected: "Normal"
2022-01-27 15:42:18.148 VS2019-VM\lawre [INFO] <4> <127.0.0.1:54214> Connected
2022-01-27 15:42:18.267 VS2019-VM\lawre [INFO] <9> <127.0.0.1:54214> Authenticated: VS2019-VM,DARK\LAWRE
2022-01-27 15:42:18.279 VS2019-VM\lawre [INFO] <9> <127.0.0.1:54214> Authenticate failed to send OK
2022-01-27 15:42:18.281 VS2019-VM\lawre [INFO] <9> <127.0.0.1:54214> Disconnected: "Normal"
2022-01-27 15:44:11.075 VS2019-VM\lawre [INFO] <4> <127.0.0.1:54221> Connected
2022-01-27 15:44:29.502 VS2019-VM\lawre [INFO] <4> <127.0.0.1:54221> Authenticated: Edwards, James
2022-01-27 15:44:56.624 VS2019-VM\lawre [INFO] <4> Worker running <4>
2022-01-27 15:45:30.351 VS2019-VM\lawre [INFO] <16> <127.0.0.1:54221> Disconnected: "Normal"
2022-01-27 15:45:49.364 VS2019-VM\lawre [INFO] <20> Application is shutting down...
2022-01-27 15:45:49.368 VS2019-VM\lawre [DBUG] <4> Hosting stopping
2022-01-27 15:45:49.369 VS2019-VM\lawre [INFO] <4> Stopping server
2022-01-27 15:45:49.390 VS2019-VM\lawre [DBUG] <4> Hosting stopped
2022-01-27 15:45:49.393 VS2019-VM\lawre [INFO] <1> USPS Server stopped

The lines: 2022-01-27 15:42:18.267 and 2022-01-27 15:42:18.279 are from the class library NUnit test
The line: 2022-01-27 15:44:29.502 is what I would expect to see. This is from the WatsonTCP.Test.Client app.

Here is the WEatsonTCP.Test.Client side Console Log:

Server IP: [localhost]
Server port: [1701]
Use SSL: [y/N]?
[Info ] [WatsonTcpClient] connecting to localhost:1701
localhost:1701 connected
[Info ] [WatsonTcpClient] connected to localhost:1701
Command [? for help]: send
Data: {"Command":"Authenticate","Parameters":"Edwards, James"}
Command [? for help]: [Debug ] [WatsonMessage] found header demarcation
[Debug ] [WatsonMessage] header processing complete
{"s":"Normal","len":59}
Message from localhost:1701: {"Command":"Authenticate","Result":200,"ResponseInfo":null}

Is there something I should be doing in my NUnit test to ensure the class library actually receives the response? I think the test is terminating before the server can send the response.

Do I need to run the client as a task? The sample does not look like it would.

[Mudoch]

Well after much review of the overall process and the fact that in the Class Lib I could not get an Invoke of my logging call, I switched to Client.SendAndWait(). This solved my issues and provided a cleaner request/response handshake process and it'll remove the need to provide what command triggered the response.

Here is the server side code yet to remove the command kick back:

    private SyncResponse SyncRequestReceived(SyncRequest req)
    {
      RequestIn rqIn;
      string Resp = null;
      string sData = Encoding.UTF8.GetString(req.Data);
      try
      {
        rqIn = JsonSerializer.Deserialize<RequestIn>(sData);
      }
      catch (Exception ex)
      {
        {
          _logger.LogError(ex, "Error processing request: {msg}", sData);
          Resp = JsonSerializer.Serialize(new ResponseOut { Command = "$UNKWN$", Result = 500, ResponseInfo = "<" + req.IpPort + "> Rejected <-202001>" });
          return new SyncResponse(req, null, Resp);
        }
      }

      try
      {
        rqIn.Command = rqIn.Command.ToUpper(); //Simplify my life
        if (rqIn.Command == "AUTHENTICATE")
        {
          Resp = AuthorizeUser(req.IpPort, rqIn.Parameters);
        }

        if (_Connections.Contains(req.IpPort) && rqIn.Command != "AUTHENTICATE")
        {
          _logger.LogDebug("<{ip}> Rcvd: {msg}", req.IpPort, sData);
          Resp = rqIn.Command switch
          {
            "GETACLST" => GetAcLst(rqIn.Command),
            "CHKDBSTAT" => CheckDB(rqIn.Command),
            _ => JsonSerializer.Serialize(new ResponseOut { Command = rqIn.Command, Result = 500, ResponseInfo = "Rejected <-202003>" }),
          }; //Resp = rqIn.Command switch
        } //if (_Connections.Contains(req.IpPort) && rqIn.Command != "AUTHENTICATE")
      }
      catch (Exception ex)
      {
        _logger.LogError(ex, "<{ip}> Error processing request: {msg}", req.IpPort, sData);
        Resp = JsonSerializer.Serialize(new ResponseOut { Command = "$UNKWN$", Result = 500, ResponseInfo = "Rejected <-202000> " + ex.Message });
      }

      if (string.IsNullOrWhiteSpace(Resp))
      {
        Resp = JsonSerializer.Serialize(new ResponseOut { Command = "$UNKWN$", Result = 500, ResponseInfo = "Rejected <-202002>" });
      }

      _logger.LogDebug("<{ip}> Resp: {resp}", req.IpPort, Resp);
      return new SyncResponse(req, null, Resp);
    }