Strange - Logout not working anymore after porting to .NET core

tbednarz · May 3, 2018, 10:03am

I have written my own Authentication provider based on CredentialsAuthProvider. While the authenication itself works and I get valid session id etc back, the Logoff implementation is not reached. Here is what Fiddler shows:

POST http://linuxdev-tbws2:6090/json/reply/Authenticate HTTP/1.1
Accept: application/json
User-Agent: ServiceStack .NET Client 5.02
Accept-Encoding: gzip,deflate
Content-Type: application/json
Host: linuxdev-tbws2:6090
Cookie: ss-opt=perm
Content-Length: 21
Expect: 100-continue

{“provider”:“logout”}

Response:

HTTP/1.1 200 OK
Date: Thu, 03 May 2018 09:46:44 GMT
Content-Type: application/json; charset=utf-8
Server: Kestrel
Set-Cookie: ss-id=EvZNybodkO6EpdlWpEeG; path=/; samesite=lax; httponly
Set-Cookie: ss-pid=3oaZAA6E46zOk54BqpMB; expires=Mon, 03 May 2038 09:46:45 GMT; path=/; samesite=lax; httponly
Set-Cookie: ss-id=; expires=Wed, 02 May 2018 09:46:45 GMT; path=/; samesite=lax; httponly
Set-Cookie: ss-pid=; expires=Wed, 02 May 2018 09:46:45 GMT; path=/; samesite=lax; httponly
Set-Cookie: X-UAId=; expires=Wed, 02 May 2018 09:46:45 GMT; path=/; samesite=lax; httponly
Set-Cookie: ss-tok=; expires=Wed, 02 May 2018 09:46:45 GMT; path=/; samesite=lax; httponly
Vary: Accept
X-Powered-By: ServiceStack/5.02 NETStandard/.NET
Content-Length: 21

{“responseStatus”:{}}

This is my implementation of the Logout method in my AuthProvider:

public class LsAuthProvider : CredentialsAuthProvider
{
    private static readonly ILogger Logger = Serilog.Log.ForContext<LsAuthProvider>();

    public override object Logout(IServiceBase service, Authenticate request)
    {
        Logger.Debug($"Logout event received for user {request.UserName}");
        
        if (string.IsNullOrEmpty(request.UserName)) return base.Logout(service, request);

        try
        {
            var activityRepo = HostContext.TryResolve<LsUserActivityRepository>();
            var authRepo = (IUserAuthRepository) HostContext.TryResolve<IAuthRepository>();
            var user = authRepo.GetUserAuthByUserName(request.UserName);

            var activity = new AccountActivity
            {
                CUser = user.UserName,
                AppUserName = user.UserName,
                ActivityType = AccountActivityType.Logoff,
                ActivityDetails = "Logoff request from client.",
                RemoteIpClient = service.Request.RemoteIp
            };
            activityRepo.CreateActivity(activity);
        }
        catch (Exception e)
        {
            Logger.Error($"Error to store logoff activity in database. Error: {e}");
            throw;
        }

        return base.Logout(service, request);
    }
   // Authenticate and TryAuthenticate implementations.....

}

If I place a breakpoint in this method it is never reached and also the log does not have any entries. And the heartbeat which is sent to the client (I use ServerSide Events) are still sent.

Any idea what is wrong here? Is there something different with .NETCore regarding logout??

Additional info:
The client is WPF and calling from Windows. The idea is that you can logout and log back again with a different login ID. So the client is still alive but after logout should have no sessions anymore.

mythz · May 3, 2018, 12:32pm

It only calls Logout on the first AuthProvider registered in the AuthFeature plugin.

tbednarz · May 3, 2018, 6:40pm

Hmm, is this new? I have the ApiKeyProvider and my own provider and I just checked in Git and I have not changed this bit of code when porting to .NET core…

I changed the order now and put my own provider as first in the plugin registration and this only parially works. The problem I have now is, that the request object has only NULL values as the following debugger output shows:

Since I test the username from the request object, my code is skipped:

if (string.IsNullOrEmpty(request.UserName)) return base.Logout(service, request);

Also the base.Logout(service, request) call seems not to remove the session, at least the heartbeats are still sent to the client. And if I login again, I then have 2 subscriptions. Here a shortened (but still long) extract from my logfile:

2018-05-03 20:28:54.818 +02:00 [DBG] [BizBusLicenseServer.ServiceInterface.Util.LsAuthProvider] [ThreadId 6] Logon for user BizBusLicenseAdmin was successful…
2018-05-03 20:28:54.842 +02:00 [DBG] [BizBusLicenseServer.AppHost] [ThreadId 6] Saved session with Id jRFvtk2OJDv9HSPWIxO8.
2018-05-03 20:28:54.845 +02:00 [INF] [Microsoft.AspNetCore.Hosting.Internal.WebHost] [ThreadId 6] Request finished in 55.1604ms 200 application/json; charset=utf-8
2018-05-03 20:28:54.853 +02:00 [INF] [Microsoft.AspNetCore.Hosting.Internal.WebHost] [ThreadId 11] Request starting HTTP/1.1 GET http://linuxdev-tbws2:6090/event-stream?channels=LsChannel
2018-05-03 20:28:54.876 +02:00 [INF] [BizBusLicenseServer.AppHost] [ThreadId 11] ONCREATED EVENT: SessionProps: UserAuthID: ‘1’ | UserAuthName: ‘BizBusLicenseAdmin’ | UserName: ‘BizBusLicenseAdmin’ | SessionId: ‘jRFvtk2OJDv9HSPWIxO8’ | AuthProvider: ‘credentials’ | IsAuthenticated: ‘True’ | Request: ‘ServiceStack.Host.NetCore.NetCoreRequest’ | Subscription: ‘BizBusLicenseAdmin’
2018-05-03 20:28:54.882 +02:00 [INF] [BizBusLicenseServer.AppHost] [ThreadId 11] ONCONNECT EVENT: Subscription: BizBusLicenseAdmin | Authenticated: True
2018-05-03 20:28:54.904 +02:00 [INF] [Microsoft.AspNetCore.Hosting.Internal.WebHost] [ThreadId 21] Request starting HTTP/1.1 GET http://linuxdev-tbws2:6090/configuration/pref:bizbuslicenseadmin:tbws2:bizbuslicensemanager:1.0.000:GuiPreferences
2018-05-03 20:28:54.913 +02:00 [INF] [BizBusLicenseServer.AppHost] [ThreadId 11] SUBSCRIBE EVENT: new subscription for user: DisplayName: BizBusLicenseAdmin | UserID: 1 | UserName: BizBusLicenseAdmin | SessionID: jRFvtk2OJDv9HSPWIxO8 | SubscriptionId: 1sDzDvrAwDFoN51BmGSk | IsAuthenticated: True | IsClosed: False
Subscription stats show ONE registered subscription:
2018-05-03 20:28:54.914 +02:00 [INF] [BizBusLicenseServer.AppHost] [ThreadId 11] SUBSCRIPTION STATS:
2018-05-03 20:28:54.921 +02:00 [INF] [BizBusLicenseServer.AppHost] [ThreadId 11] There are currently 1 registered subscriptions.
2018-05-03 20:28:54.921 +02:00 [INF] [BizBusLicenseServer.AppHost] [ThreadId 11] subscription: 1sDzDvrAwDFoN51BmGSk | BizBusLicenseAdmin
2018-05-03 20:28:54.934 +02:00 [DBG] [BizBusLicenseServer.AppHost] [ThreadId 21] Saved session with Id FGS9y6VtdMKeHDD7WmXD.
…
Logging off but still receiving Heartbeats every 8 seconds as I have configured it…
2018-05-03 20:29:03.582 +02:00 [DBG] [BizBusLicenseServer.ServiceInterface.Util.LsAuthProvider] [ThreadId 5] Logout event received for user
2018-05-03 20:29:03.586 +02:00 [DBG] [BizBusLicenseServer.AppHost] [ThreadId 5] Saved session with Id FGS9y6VtdMKeHDD7WmXD.
2018-05-03 20:29:03.593 +02:00 [INF] [Microsoft.AspNetCore.Hosting.Internal.WebHost] [ThreadId 5] Request finished in 20.472ms 200 application/json; charset=utf-8
2018-05-03 20:29:03.595 +02:00 [INF] [Microsoft.AspNetCore.Hosting.Internal.WebHost] [ThreadId 5] Request starting HTTP/1.1 POST http://linuxdev-tbws2:6090/json/reply/Authenticate application/json 21
2018-05-03 20:29:03.606 +02:00 [DBG] [BizBusLicenseServer.ServiceInterface.Util.LsAuthProvider] [ThreadId 5] Logout event received for user
2018-05-03 20:29:03.608 +02:00 [DBG] [BizBusLicenseServer.AppHost] [ThreadId 5] Saved session with Id gJ2G5abQGwver52eQKqB.
2018-05-03 20:29:03.611 +02:00 [INF] [Microsoft.AspNetCore.Hosting.Internal.WebHost] [ThreadId 5] Request finished in 13.8484ms 200 application/json; charset=utf-8
2018-05-03 20:29:10.988 +02:00 [INF] [Microsoft.AspNetCore.Hosting.Internal.WebHost] [ThreadId 6] Request starting HTTP/1.1 GET http://linuxdev-tbws2:6090/event-heartbeat?id=1sDzDvrAwDFoN51BmGSk
2018-05-03 20:29:10.989 +02:00 [INF] [Microsoft.AspNetCore.Hosting.Internal.WebHost] [ThreadId 6] Request finished in 0.7606ms 200
2018-05-03 20:29:18.995 +02:00 [INF] [Microsoft.AspNetCore.Hosting.Internal.WebHost] [ThreadId 5] Request starting HTTP/1.1 GET http://linuxdev-tbws2:6090/event-heartbeat?id=1sDzDvrAwDFoN51BmGSk
2018-05-03 20:29:18.995 +02:00 [INF] [Microsoft.AspNetCore.Hosting.Internal.WebHost] [ThreadId 5] Request finished in 0.8222ms 200
…
Logging back in
2018-05-03 20:29:51.250 +02:00 [INF] [Microsoft.AspNetCore.Hosting.Internal.WebHost] [ThreadId 11] Request starting HTTP/1.1 POST http://linuxdev-tbws2:6090/json/reply/Authenticate application/json 95
2018-05-03 20:29:51.269 +02:00 [DBG] [BizBusLicenseServer.ServiceInterface.Util.LsAuthProvider] [ThreadId 11] Starting custom authentication method ‘BizBusAuthProvider’…
2018-05-03 20:29:51.269 +02:00 [DBG] [BizBusLicenseServer.ServiceInterface.Util.LsAuthProvider] [ThreadId 11] SkipPwVerificationForInProcessRequest: False | IsInprocessRequest: False
2018-05-03 20:29:51.271 +02:00 [DBG] [BizBusLicenseServer.ServiceInterface.Util.LsAuthProvider] [ThreadId 11] Starting authentication of user BizBusLicenseAdmin with password …
2018-05-03 20:29:51.293 +02:00 [DBG] [BizBusLicenseServer.ServiceInterface.Util.LsAuthProvider] [ThreadId 11] Logon for user BizBusLicenseAdmin was successful…
2018-05-03 20:29:51.300 +02:00 [DBG] [BizBusLicenseServer.AppHost] [ThreadId 11] Saved session with Id Duiw7Gx9H6X4WEyDoISw.
2018-05-03 20:29:51.300 +02:00 [INF] [Microsoft.AspNetCore.Hosting.Internal.WebHost] [ThreadId 11] Request finished in 50.2241ms 200 application/json; charset=utf-8
2018-05-03 20:29:51.311 +02:00 [INF] [Microsoft.AspNetCore.Hosting.Internal.WebHost] [ThreadId 6] Request starting HTTP/1.1 GET http://linuxdev-tbws2:6090/users/BizBusLicenseAdmin
2018-05-03 20:29:51.312 +02:00 [DBG] [BizBusLicenseServer.ServiceInterface.Services.AccountManagementService] [ThreadId 6] Retrieving application user with condition ‘BizBusLicenseServer.ServiceModel.Request.GetLsUser’.
2018-05-03 20:29:51.312 +02:00 [DBG] [BizBusLicenseServer.ServiceInterface.Services.AccountManagementService] [ThreadId 6] Searching by UserName ‘BizBusLicenseAdmin’
2018-05-03 20:29:51.314 +02:00 [DBG] [BizBusLicenseServer.AppHost] [ThreadId 6] Saved session with Id Duiw7Gx9H6X4WEyDoISw.
2018-05-03 20:29:51.314 +02:00 [INF] [Microsoft.AspNetCore.Hosting.Internal.WebHost] [ThreadId 6] Request finished in 3.741ms 200 application/json; charset=utf-8
2018-05-03 20:29:51.332 +02:00 [INF] [Microsoft.AspNetCore.Hosting.Internal.WebHost] [ThreadId 5] Request starting HTTP/1.1 POST http://linuxdev-tbws2:6090/json/reply/Authenticate application/json 95
2018-05-03 20:29:51.349 +02:00 [DBG] [BizBusLicenseServer.ServiceInterface.Util.LsAuthProvider] [ThreadId 5] Starting custom authentication method ‘BizBusAuthProvider’…
2018-05-03 20:29:51.349 +02:00 [DBG] [BizBusLicenseServer.ServiceInterface.Util.LsAuthProvider] [ThreadId 5] SkipPwVerificationForInProcessRequest: False | IsInprocessRequest: False
2018-05-03 20:29:51.351 +02:00 [DBG] [BizBusLicenseServer.ServiceInterface.Util.LsAuthProvider] [ThreadId 5] Starting authentication of user BizBusLicenseAdmin with password ‘admin’ …
2018-05-03 20:29:51.373 +02:00 [DBG] [BizBusLicenseServer.ServiceInterface.Util.LsAuthProvider] [ThreadId 5] Logon for user BizBusLicenseAdmin was successful…
2018-05-03 20:29:51.378 +02:00 [DBG] [BizBusLicenseServer.AppHost] [ThreadId 5] Saved session with Id FVZavbNtwLsaP1VMaSTt.
2018-05-03 20:29:51.379 +02:00 [INF] [Microsoft.AspNetCore.Hosting.Internal.WebHost] [ThreadId 5] Request finished in 46.6473ms 200 application/json; charset=utf-8
2018-05-03 20:29:51.385 +02:00 [INF] [Microsoft.AspNetCore.Hosting.Internal.WebHost] [ThreadId 5] Request starting HTTP/1.1 GET http://linuxdev-tbws2:6090/event-stream?channels=LsChannel
Registration for events…
2018-05-03 20:29:51.391 +02:00 [INF] [BizBusLicenseServer.AppHost] [ThreadId 5] ONCREATED EVENT: SessionProps: UserAuthID: ‘1’ | UserAuthName: ‘BizBusLicenseAdmin’ | UserName: ‘BizBusLicenseAdmin’ | SessionId: ‘FVZavbNtwLsaP1VMaSTt’ | AuthProvider: ‘credentials’ | IsAuthenticated: ‘True’ | Request: ‘ServiceStack.Host.NetCore.NetCoreRequest’ | Subscription: ‘BizBusLicenseAdmin’
2018-05-03 20:29:51.391 +02:00 [INF] [BizBusLicenseServer.AppHost] [ThreadId 5] ONCONNECT EVENT: Subscription: BizBusLicenseAdmin | Authenticated: True
2018-05-03 20:29:51.391 +02:00 [INF] [BizBusLicenseServer.AppHost] [ThreadId 5] SUBSCRIBE EVENT: new subscription for user: DisplayName: BizBusLicenseAdmin | UserID: 1 | UserName: BizBusLicenseAdmin | SessionID: FVZavbNtwLsaP1VMaSTt | SubscriptionId: t5CdrSC9vuPoCat0kLb4 | IsAuthenticated: True | IsClosed: False
Subscription stats show TWO registered subscriptions, the second in the list has the ID from above:
2018-05-03 20:29:51.391 +02:00 [INF] [BizBusLicenseServer.AppHost] [ThreadId 5] SUBSCRIPTION STATS:
2018-05-03 20:29:51.392 +02:00 [INF] [BizBusLicenseServer.AppHost] [ThreadId 5] There are currently 2 registered subscriptions.
2018-05-03 20:29:51.392 +02:00 [INF] [BizBusLicenseServer.AppHost] [ThreadId 5] subscription: t5CdrSC9vuPoCat0kLb4 | BizBusLicenseAdmin
2018-05-03 20:29:51.392 +02:00 [INF] [BizBusLicenseServer.AppHost] [ThreadId 5] subscription: 1sDzDvrAwDFoN51BmGSk | BizBusLicenseAdmin

Never saw these things on my Windows services, .NET core problems??

mythz · May 3, 2018, 8:04pm

No it’s always been that way, likewise it’s always returned an empty session for non Authenticated sessions.