SSO AD User logout continuously

Hi,

i have a xg firewall with AD SSO.

the users logged into the firewall are continuosly logged out after 20 minutes

2016-04-11 08:44:32
Firewall Authentication
SUCCESSFUL
dario.zzzz@xxxx.local
172.16.29.115
CTA
N/A
User dario.zzzz@xxxx.local was logged out of firewall
17703
2016-04-11 08:28:48
Firewall Authentication
SUCCESSFUL
dario.zzzz@xxxx.local
172.16.29.115
CTA
AD
User dario.zzzz@xxxx.local of group Proxy_All logged in successfully to Firewall through AD authentication mechanism from 172.16.29.115
17701


I have followed all the guides but I can not fix it

thanks

Emil

  • Hi Emil,

    This sounds like you are probably being caught out by one of two things I suspect it is probably the first option.

    - logon of alternate user account, STAS tracks singular user activity. If an authentication event happens with an alternate user account that will log the existing user out. (You can exclude specific user accounts such as those used by services from being tracked, if you have a terminal server you should also exclude that IP address)

    - the log off detection being performed by the STAS collector. This mechanism will depending on what you have configured, however the collector will poll the workstation to check who is logged in, if the connection fails or it picks up an alternate username then the original user will be logged out. (You might need to check that there is nothing such as Windows Firewall blocking the connection by the collector)

    While you provided an example log entry for the logon and log off for the user, can you check if there is another authentication event for the same IP address at the same time as the log off.

  • In reply to Leon.Friend:

    HI Leon,

    I post a STAS log from test lab, error is the same in production enviroment.

    From the workstation with ip 172.16.0.22 the user's session emil.martini was disconnected while the user is still working, there aren't other services running.

    Thanks a lot

    Emil

    STAS LOG:

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_select_expired_userinfo: select query: SELECT * FROM UserInfo WHERE flags==1 AND rowid>=0 AND expire_time<=1460464273 ORDER BY rowid ASC LIMIT 5;

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_select_expired_userinfo: --- SELECTED USER INFO FOR LOGOFF DETECTION ---

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_log_userinfo: RowID: 52

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_log_userinfo: User: emil.martini

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_log_userinfo: Domain: btzit.local

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_log_userinfo: Group: NULL

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_log_userinfo: SourceDC: NULL

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_log_userinfo: WrkstName: NULL

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_log_userinfo: WrkstIP: 172.16.0.22

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_log_userinfo: CreateTime: 1460463336

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_log_userinfo: ExpireTime: 1460463940

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_log_userinfo: LogonType: 0x2

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_log_userinfo: UserSidType: 0x0

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_select_expired_userinfo: -----------------------------------------------

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_select_expired_userinfo: --- SELECTED USER INFO FOR LOGOFF DETECTION ---

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_log_userinfo: RowID: 55

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_log_userinfo: User: Administrator

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_log_userinfo: Domain: btzit.local

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_log_userinfo: Group: NULL

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_log_userinfo: SourceDC: NULL

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_log_userinfo: WrkstName: NULL

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_log_userinfo: WrkstIP: 172.16.0.230

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_log_userinfo: CreateTime: 1460463663

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_log_userinfo: ExpireTime: 1460464268

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_log_userinfo: LogonType: 0x2

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_log_userinfo: UserSidType: 0x0

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_select_expired_userinfo: -----------------------------------------------

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_select_expired_userinfo: 2 records selected

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_update_userinfo: update query: UPDATE UserInfo SET flags='2',expire_time='1460463940' WHERE rowid=='52';

    userdb_exec_query: Query:'U'

    userdb_exec_query: Query Executed, ret:101

    DEBUG [0x5bc] 12/04/2016 14:31:13 : userdb_update_userinfo: update query: UPDATE UserInfo SET flags='2',expire_time='1460464268' WHERE rowid=='55';

    userdb_exec_query: Query:'U'

    userdb_exec_query: Query Executed, ret:101

    DEBUG [0x5bc] 12/04/2016 14:31:13 : logoff_detector: UserInfo Selected: 2

    DEBUG [0x5bc] 12/04/2016 14:31:13 : logoff_detector: USER: btzit.local\emil.martini RowID: 52

    DEBUG [0x5bc] 12/04/2016 14:31:13 : threadpool_run: Submitting Function 0x455880

    DEBUG [0x5bc] 12/04/2016 14:31:13 : threadpool_run: adding function at tail

    DEBUG [0x5bc] 12/04/2016 14:31:13 : list_add_tail: first element added

    DEBUG [0x5bc] 12/04/2016 14:31:13 : threadpool_run: get free thread: ThreadID: 0x5ec

    DEBUG [0x5bc] 12/04/2016 14:31:13 : logoff_detector: callback submitted

    DEBUG [0x5bc] 12/04/2016 14:31:13 : logoff_detector: USER: btzit.local\Administrator RowID: 55

    DEBUG [0x5bc] 12/04/2016 14:31:13 : threadpool_run: Submitting Function 0x455880

    DEBUG [0x5bc] 12/04/2016 14:31:13 : threadpool_run: adding function at tail

    DEBUG [0x5bc] 12/04/2016 14:31:13 : threadpool_run: get free thread: ThreadID: 0x660

    DEBUG [0x5ec] 12/04/2016 14:31:13 : threadpool_threadproc: New Function added

    DEBUG [0x5ec] 12/04/2016 14:31:13 : threadpool_get_threadproc: Function 0x455880

    DEBUG [0x5bc] 12/04/2016 14:31:13 : logoff_detector: callback submitted

    DEBUG [0x5ec] 12/04/2016 14:31:13 : threadpool_threadproc: Executing Function 0x455880

    DEBUG [0x660] 12/04/2016 14:31:13 : threadpool_threadproc: New Function added

    DEBUG [0x660] 12/04/2016 14:31:13 : list_remove_head: last element removed

    DEBUG [0x660] 12/04/2016 14:31:13 : threadpool_get_threadproc: Function 0x455880

    DEBUG [0x5ec] 12/04/2016 14:31:13 : wrkstpoll_workerthread_wmi: connecting to WMI Namespace '\\172.16.0.22\root\cimv2'

    DEBUG [0x660] 12/04/2016 14:31:13 : threadpool_threadproc: Executing Function 0x455880

    MSG [0x5ec] 12/04/2016 14:31:13 : wrkstpoll_workerthread_wmi: username:administrator

    DEBUG [0x660] 12/04/2016 14:31:13 : wrkstpoll_workerthread_wmi: connecting to WMI Namespace '\\172.16.0.230\root\cimv2'

    MSG [0x660] 12/04/2016 14:31:13 : wrkstpoll_workerthread_wmi: username:administrator

    DEBUG [0x660] 12/04/2016 14:31:13 : wrkstpoll_workerthread_wmi: connecting to Local Namespace....

    DEBUG [0x660] 12/04/2016 14:31:13 : wrkstpoll_workerthread_wmi: Success - Connected to WMI Namespace: \\172.16.0.230\root\cimv2

    ERROR [0x660] 12/04/2016 14:31:13 : wrkstpoll_workerthread_wmi: Success - Proxy Blanket Security Settings
    DEBUG [0x5ec] 12/04/2016 14:31:13 : wrkstpoll_workerthread_wmi: Success - Connected to WMI Namespace: \\172.16.0.22\root\cimv2

    ERROR [0x5ec] 12/04/2016 14:31:13 : wrkstpoll_workerthread_wmi: Success - Proxy Blanket Security Settings
    ERROR [0x660] 12/04/2016 14:31:13 : wrkstpoll_workerthread_wmi: Success - WMI Query for: \\172.16.0.230\root\cimv2

    DEBUG [0x660] 12/04/2016 14:31:13 : wrkstpoll_workerthread_wmi: no loggedin user found

    MSG [0x660] 12/04/2016 14:31:13 : wrkstpoll_handle_logoff_req: Request received from Logoff Detector

    DEBUG [0x660] 12/04/2016 14:31:13 : userdb_delete_userinfo: delete query: DELETE FROM UserInfo WHERE user=='Administrator' AND domain=='btzit.local' AND wrkst_ip=='172.16.0.230';

    userdb_exec_query: Query:'D'

    ERROR [0x5ec] 12/04/2016 14:31:13 : wrkstpoll_workerthread_wmi: WMI Query 'SELECT UserName FROM Win32_ComputerSystem' failed: 0x80041003

    MSG [0x5ec] 12/04/2016 14:31:13 : wrkstpoll_handle_logoff_req: Request received from Logoff Detector

    DEBUG [0x5ec] 12/04/2016 14:31:13 : userdb_delete_userinfo: delete query: DELETE FROM UserInfo WHERE user=='emil.martini' AND domain=='btzit.local' AND wrkst_ip=='172.16.0.22';

    userdb_exec_query: Query Executed, ret:101

    userdb_exec_query: Query:'D'

    INFO [0x660] 12/04/2016 14:31:13 : remove_user_from_de_repositry: user Administrator with ip 172.16.0.230 removed from DE

    MSG [0x660] 12/04/2016 14:31:13 : wrkstpoll_handle_logoff_req: user 'btzit.local\Administrator' removed

    DEBUG [0x660] 12/04/2016 14:31:13 : list_add_tail: first element added

    DEBUG [0x660] 12/04/2016 14:31:13 : wrkstpoll_handle_logoff_req: user's logout request enqueued to CR Update Queue

    DEBUG [0x660] 12/04/2016 14:31:13 : threadpool_finishnotify: Thread ID: 0x660

    DEBUG [0x660] 12/04/2016 14:31:13 : threadpool_finishnotify: Reset Event

    ERROR [0x550] 12/04/2016 14:31:13 : USERINFO WAITING INFINITE
    DEBUG [0x550] 12/04/2016 14:31:13 : list_remove_head: last element removed

    MSG [0x550] 12/04/2016 14:31:13 : SSOclient_thread: got userinfo: USER: btzit.local\Administrator <-> Flags: 4

    DEBUG [0x550] 12/04/2016 14:31:13 : SSOclient_filter_CR_subnet: Entering filter function

    DEBUG [0x550] 12/04/2016 14:31:13 : SSOclient_filter_CR_subnet: authnet not specified, send reqiest to CR

    ERROR [0x550] 12/04/2016 14:31:13 : SSOclient_update_CR: domain name is there with length 11 , btzit.local

    ERROR [0x550] 12/04/2016 14:31:13 : USERNAME Administrator Length 14

    ERROR [0x550] 12/04/2016 14:31:13 : WORKSTN IP 172.16.0.230 Length 13

    ERROR [0x550] 12/04/2016 14:31:13 : DOMAIN btzit.local Length 12

    ERROR [0x550] 12/04/2016 14:31:13 : SSOclient : PACKET SIZE 285 㠲5
    DEBUG [0x550] 12/04/2016 14:31:13 : net_send: bytes sent: 285

    DEBUG [0x550] 12/04/2016 14:31:13 : net_send: full packet sent

    MSG [0x550] 12/04/2016 14:31:13 : SSOclient_thread: Logon/Logout Update sent to: 172.16.0.254:0

    ERROR [0x550] 12/04/2016 14:31:13 : GETTING (USERINFO) FROM QUEUE
    DEBUG [0x550] 12/04/2016 14:31:13 : list_remove_head: list is Empty

    userdb_exec_query: Query Executed, ret:101

    INFO [0x5ec] 12/04/2016 14:31:14 : remove_user_from_de_repositry: user emil.martini with ip 172.16.0.22 removed from DE

    MSG [0x5ec] 12/04/2016 14:31:14 : wrkstpoll_handle_logoff_req: user 'btzit.local\emil.martini' removed

    DEBUG [0x5ec] 12/04/2016 14:31:14 : list_add_tail: first element added

    DEBUG [0x5ec] 12/04/2016 14:31:14 : wrkstpoll_handle_logoff_req: user's logout request enqueued to CR Update Queue

    DEBUG [0x5ec] 12/04/2016 14:31:14 : threadpool_finishnotify: Thread ID: 0x5ec

    DEBUG [0x5ec] 12/04/2016 14:31:14 : threadpool_finishnotify: Reset Event

    ERROR [0x550] 12/04/2016 14:31:14 : USERINFO WAITING INFINITE
    DEBUG [0x550] 12/04/2016 14:31:14 : list_remove_head: last element removed

    MSG [0x550] 12/04/2016 14:31:14 : SSOclient_thread: got userinfo: USER: btzit.local\emil.martini <-> Flags: 4

    DEBUG [0x550] 12/04/2016 14:31:14 : SSOclient_filter_CR_subnet: Entering filter function

    DEBUG [0x550] 12/04/2016 14:31:14 : SSOclient_filter_CR_subnet: authnet not specified, send reqiest to CR

    ERROR [0x550] 12/04/2016 14:31:14 : SSOclient_update_CR: domain name is there with length 11 , btzit.local

    ERROR [0x550] 12/04/2016 14:31:14 : USERNAME emil.martini Length 13

    ERROR [0x550] 12/04/2016 14:31:14 : WORKSTN IP 172.16.0.22 Length 12

    ERROR [0x550] 12/04/2016 14:31:14 : DOMAIN btzit.local Length 12

    ERROR [0x550] 12/04/2016 14:31:14 : SSOclient : PACKET SIZE 273 㜲3
    DEBUG [0x550] 12/04/2016 14:31:14 : net_send: bytes sent: 273

    DEBUG [0x550] 12/04/2016 14:31:14 : net_send: full packet sent

    MSG [0x550] 12/04/2016 14:31:14 : SSOclient_thread: Logon/Logout Update sent to: 172.16.0.254:0

    ERROR [0x550] 12/04/2016 14:31:14 : GETTING (USERINFO) FROM QUEUE
    DEBUG [0x550] 12/04/2016 14:31:14 : list_remove_head: list is Empty

    DEBUG [0x5f0] 12/04/2016 14:31:14 : dca_eventlog: received event log notification

    DEBUG [0x5f0] 12/04/2016 14:31:14 : dca_eventlog: got security event: ID: 4768 <-> Type: 8

    DEBUG [0x5f0] 12/04/2016 14:31:14 : dca_eventlog: got Kerberos authentication event

    MSG [0x5f0] 12/04/2016 14:31:14 : init_userinfo_kerberos: UserName: Administrator

    MSG [0x5f0] 12/04/2016 14:31:14 : init_userinfo_kerberos: DomainName: BTZIT.LOCAL

    MSG [0x5f0] 12/04/2016 14:31:14 : init_userinfo_kerberos: IPv6 WorkstationIP: :

    DEBUG [0x5f0] 12/04/2016 14:31:14 : init_userinfo_kerberos: localhost ip given from AD(127.0.0.1)
    DEBUG [0x5f0] 12/04/2016 14:31:14 : init_userinfo_kerberos: finding interface with internet traffic
    DEBUG [0x5f0] 12/04/2016 14:31:14 : init_userinfo_kerberos: interface found with ip 1
    MSG [0x5f0] 12/04/2016 14:31:14 : init_userinfo_kerberos: IPv4 WorkstationIP: 172.16.0.230

    DEBUG [0x5f0] 12/04/2016 14:31:14 : init_userinfo_common: Event ID: 4768

    DEBUG [0x5f0] 12/04/2016 14:31:14 : init_userinfo_common: EventType: AuditSuccess

    DEBUG [0x5f0] 12/04/2016 14:31:14 : init_userinfo_common: CreateTime: 1460464273

    DEBUG [0x5f0] 12/04/2016 14:31:14 : init_userinfo_common: ExpireTime: 1460464878

    DEBUG [0x5f0] 12/04/2016 14:31:14 : init_userinfo_common: LogonType: 2

    DEBUG [0x5f0] 12/04/2016 14:31:14 : threadpool_run: Submitting Function 0x40a7e0

    DEBUG [0x5f0] 12/04/2016 14:31:14 : threadpool_run: adding function at tail

    DEBUG [0x5f0] 12/04/2016 14:31:14 : list_add_tail: first element added

    DEBUG [0x5f0] 12/04/2016 14:31:14 : threadpool_run: get free thread: ThreadID: 0x5ec

    DEBUG [0x5f0] 12/04/2016 14:31:14 : dca_enqueue_userinfo: callback submitted

    DEBUG [0x5f0] 12/04/2016 14:31:14 : dca_eventlog: userinfo enqueued to dca processor

    DEBUG [0x5ec] 12/04/2016 14:31:14 : threadpool_threadproc: New Function added

    DEBUG [0x5ec] 12/04/2016 14:31:14 : list_remove_head: last element removed

    DEBUG [0x5f0] 12/04/2016 14:31:14 : dca_eventlog: got security event: ID: 4769 <-> Type: 8

    DEBUG [0x5ec] 12/04/2016 14:31:14 : threadpool_get_threadproc: Function 0x40a7e0

    DEBUG [0x5ec] 12/04/2016 14:31:14 : threadpool_threadproc: Executing Function 0x40a7e0

    DEBUG [0x5f0] 12/04/2016 14:31:14 : dca_eventlog: got security event: ID: 4768 <-> Type: 8

    DEBUG [0x5f0] 12/04/2016 14:31:14 : dca_eventlog: got Kerberos authentication event

    DEBUG [0x5ec] 12/04/2016 14:31:14 : dca_log_userinfo: User: Administrator

    MSG [0x5f0] 12/04/2016 14:31:14 : init_userinfo_kerberos: UserName: Administrator

    DEBUG [0x5ec] 12/04/2016 14:31:14 : dca_log_userinfo: Domain: btzit.local

    MSG [0x5f0] 12/04/2016 14:31:14 : init_userinfo_kerberos: DomainName: BTZIT.LOCAL

    DEBUG [0x5ec] 12/04/2016 14:31:14 : dca_log_userinfo: WrkstIP: 172.16.0.230

    MSG [0x5f0] 12/04/2016 14:31:14 : init_userinfo_kerberos: IPv6 WorkstationIP: :

    DEBUG [0x5ec] 12/04/2016 14:31:14 : dca_log_userinfo: CreateTime: 1460464273

    DEBUG [0x5f0] 12/04/2016 14:31:14 : init_userinfo_kerberos: localhost ip given from AD(127.0.0.1)
    DEBUG [0x5ec] 12/04/2016 14:31:14 : dca_log_userinfo: ExpireTime: 1460464878

    DEBUG [0x5ec] 12/04/2016 14:31:14 : dca_log_userinfo: LogonType: 2

    DEBUG [0x5f0] 12/04/2016 14:31:14 : init_userinfo_kerberos: finding interface with internet traffic
    DEBUG [0x5ec] 12/04/2016 14:31:14 : Adding user info to db and Sophos

    DEBUG [0x5ec] 12/04/2016 14:31:14 : dca_filter_by_username

    DEBUG [0x5ec] 12/04/2016 14:31:14 : userdb_handle_duplicate_userinfo: select query: SELECT * FROM UserInfo WHERE wrkst_ip=='172.16.0.230';

    DEBUG [0x5ec] 12/04/2016 14:31:14 : userdb_insert_userinfo: no matching userinfo found

    DEBUG [0x5f0] 12/04/2016 14:31:14 : init_userinfo_kerberos: interface found with ip 1
    MSG [0x5f0] 12/04/2016 14:31:14 : init_userinfo_kerberos: IPv4 WorkstationIP: 172.16.0.230

    DEBUG [0x5f0] 12/04/2016 14:31:14 : init_userinfo_common: Event ID: 4768

    DEBUG [0x5f0] 12/04/2016 14:31:14 : init_userinfo_common: EventType: AuditSuccess

    DEBUG [0x5f0] 12/04/2016 14:31:14 : init_userinfo_common: CreateTime: 1460464273

    DEBUG [0x5f0] 12/04/2016 14:31:14 : init_userinfo_common: ExpireTime: 1460464878

    DEBUG [0x5f0] 12/04/2016 14:31:14 : init_userinfo_common: LogonType: 2

    DEBUG [0x5f0] 12/04/2016 14:31:14 : threadpool_run: Submitting Function 0x40a7e0

    DEBUG [0x5f0] 12/04/2016 14:31:14 : threadpool_run: adding function at tail

    DEBUG [0x5f0] 12/04/2016 14:31:14 : list_add_tail: first element added

    DEBUG [0x5f0] 12/04/2016 14:31:14 : threadpool_run: get free thread: ThreadID: 0x660

    DEBUG [0x5f0] 12/04/2016 14:31:14 : dca_enqueue_userinfo: callback submitted

    DEBUG [0x5f0] 12/04/2016 14:31:14 : dca_eventlog: userinfo enqueued to dca processor

    DEBUG [0x5f0] 12/04/2016 14:31:14 : dca_eventlog: got security event: ID: 4769 <-> Type: 8

    DEBUG [0x660] 12/04/2016 14:31:14 : threadpool_threadproc: New Function added

    DEBUG [0x660] 12/04/2016 14:31:14 : list_remove_head: last element removed

    DEBUG [0x660] 12/04/2016 14:31:14 : threadpool_get_threadproc: Function 0x40a7e0

    DEBUG [0x660] 12/04/2016 14:31:14 : threadpool_threadproc: Executing Function 0x40a7e0

    DEBUG [0x660] 12/04/2016 14:31:14 : dca_log_userinfo: User: Administrator

    DEBUG [0x660] 12/04/2016 14:31:14 : dca_log_userinfo: Domain: btzit.local

    DEBUG [0x660] 12/04/2016 14:31:14 : dca_log_userinfo: WrkstIP: 172.16.0.230

    DEBUG [0x5f0] 12/04/2016 14:31:14 : dca_eventlog: waiting for event log notification

    DEBUG [0x660] 12/04/2016 14:31:14 : dca_log_userinfo: CreateTime: 1460464273

    DEBUG [0x660] 12/04/2016 14:31:14 : dca_log_userinfo: ExpireTime: 1460464878

    DEBUG [0x660] 12/04/2016 14:31:14 : dca_log_userinfo: LogonType: 2

    DEBUG [0x660] 12/04/2016 14:31:14 : Adding user info to db and Sophos

    DEBUG [0x660] 12/04/2016 14:31:14 : dca_filter_by_username

    DEBUG [0x5ec] 12/04/2016 14:31:14 : userdb_insert_userinfo: UserInfo Successfully Inserted

    DEBUG [0x660] 12/04/2016 14:31:14 : userdb_handle_duplicate_userinfo: select query: SELECT * FROM UserInfo WHERE wrkst_ip=='172.16.0.230';

    INFO [0x5ec] 12/04/2016 14:31:14 : add_user_to_de_repositry: user Administrator with ip 172.16.0.230 and expiretime 〳ㄵ㌲㐴㌬㐱㌵㠲㜱6 added to DE

    DEBUG [0x5ec] 12/04/2016 14:31:14 : list_add_tail: first element added

    DEBUG [0x5ec] 12/04/2016 14:31:14 : dca_insert_userinfo_db: userinfo enqueued in CR Update Queue

    DEBUG [0x5ec] 12/04/2016 14:31:14 : dcaclient_send_data: CreateTime: 1460464273

    DEBUG [0x5ec] 12/04/2016 14:31:14 : dcaclient_send_data: ExpireTime: 1460464878

    DEBUG [0x5ec] 12/04/2016 14:31:14 : dcaclient_send_data: Flags: 0

    DEBUG [0x5ec] 12/04/2016 14:31:14 : dcaclient_send_data: LogonType: 2

    DEBUG [0x660] 12/04/2016 14:31:14 : userdb_handle_duplicate_userinfo: User 'btzit.local\Administrator' found on '172.16.0.230'

    DEBUG [0x5ec] 12/04/2016 14:31:14 : dcaclient_send_data: Offset: 0; User: Administrator

    DEBUG [0x660] 12/04/2016 14:31:14 : userdb_handle_duplicate_userinfo: userinfo matched

    DEBUG [0x5ec] 12/04/2016 14:31:14 : dcaclient_send_data: Offset: 28; WrkstIP: 172.16.0.230

    DEBUG [0x660] 12/04/2016 14:31:14 : userdb_insert_userinfo: matching userinfo found

    DEBUG [0x5ec] 12/04/2016 14:31:14 : dcaclient_send_data: Offset: 54; Domain: btzit.local

    ERROR [0x550] 12/04/2016 14:31:14 : USERINFO WAITING INFINITE
    DEBUG [0x5ec] 12/04/2016 14:31:14 : crypto_encrypt_data: data encrypted; ciphertext len: 118

    DEBUG [0x550] 12/04/2016 14:31:14 : list_remove_head: last element removed

    DEBUG [0x5ec] 12/04/2016 14:31:14 : dcaclient_send_data: Sending DATA Header

    MSG [0x550] 12/04/2016 14:31:14 : SSOclient_thread: got userinfo: USER: btzit.local\Administrator <-> Flags: 5

    DEBUG [0x550] 12/04/2016 14:31:14 : SSOclient_filter_CR_subnet: Entering filter function

    DEBUG [0x550] 12/04/2016 14:31:14 : SSOclient_filter_CR_subnet: authnet not specified, send reqiest to CR

    ERROR [0x550] 12/04/2016 14:31:14 : SSOclient_update_CR: domain name is there with length 11 , btzit.local

    ERROR [0x550] 12/04/2016 14:31:14 : USERNAME Administrator Length 14

    DEBUG [0x5ec] 12/04/2016 14:31:14 : net_send: bytes sent: 12

    DEBUG [0x5ec] 12/04/2016 14:31:14 : net_send: full packet sent

    ERROR [0x550] 12/04/2016 14:31:14 : WORKSTN IP 172.16.0.230 Length 13

    DEBUG [0x5ec] 12/04/2016 14:31:14 : dcaclient_send_data: DATA Header Sent

    ERROR [0x550] 12/04/2016 14:31:14 : DOMAIN btzit.local Length 12

    DEBUG [0x5ec] 12/04/2016 14:31:14 : dcaclient_send_data: Sending DATA

    DEBUG [0x5ec] 12/04/2016 14:31:14 : net_send: bytes sent: 118

    DEBUG [0x5ec] 12/04/2016 14:31:14 : net_send: full packet sent

    DEBUG [0x5ec] 12/04/2016 14:31:14 : dcaclient_send_data: DATA Sent

    ERROR [0x550] 12/04/2016 14:31:14 : SSOclient : PACKET SIZE 285 㠲5
    DEBUG [0x5ec] 12/04/2016 14:31:14 : dca_add_userinfo_dcaclient: DCA Client IO succeded

    DEBUG [0x5ec] 12/04/2016 14:31:14 : threadpool_finishnotify: Thread ID: 0x5ec

    DEBUG [0x5ec] 12/04/2016 14:31:14 : threadpool_finishnotify: Reset Event

    DEBUG [0x660] 12/04/2016 14:31:14 : dcaclient_send_data: CreateTime: 1460464273

    DEBUG [0x550] 12/04/2016 14:31:14 : net_send: bytes sent: 285

    DEBUG [0x660] 12/04/2016 14:31:14 : dcaclient_send_data: ExpireTime: 1460464878

    DEBUG [0x550] 12/04/2016 14:31:14 : net_send: full packet sent

    DEBUG [0x660] 12/04/2016 14:31:14 : dcaclient_send_data: Flags: 0

    MSG [0x550] 12/04/2016 14:31:14 : SSOclient_thread: Logon/Logout Update sent to: 172.16.0.254:0

    DEBUG [0x660] 12/04/2016 14:31:14 : dcaclient_send_data: LogonType: 2

    ERROR [0x550] 12/04/2016 14:31:14 : GETTING (USERINFO) FROM QUEUE
    DEBUG [0x660] 12/04/2016 14:31:14 : dcaclient_send_data: Offset: 0; User: Administrator

    DEBUG [0x550] 12/04/2016 14:31:14 : list_remove_head: list is Empty

    DEBUG [0x660] 12/04/2016 14:31:14 : dcaclient_send_data: Offset: 28; WrkstIP: 172.16.0.230

    DEBUG [0x660] 12/04/2016 14:31:14 : dcaclient_send_data: Offset: 54; Domain: btzit.local

    DEBUG [0x660] 12/04/2016 14:31:14 : crypto_encrypt_data: data encrypted; ciphertext len: 118

    DEBUG [0x660] 12/04/2016 14:31:14 : dcaclient_send_data: Sending DATA Header

    DEBUG [0x660] 12/04/2016 14:31:14 : net_send: bytes sent: 12

    DEBUG [0x660] 12/04/2016 14:31:14 : net_send: full packet sent

    DEBUG [0x660] 12/04/2016 14:31:14 : dcaclient_send_data: DATA Header Sent

    DEBUG [0x660] 12/04/2016 14:31:14 : dcaclient_send_data: Sending DATA

    DEBUG [0x660] 12/04/2016 14:31:14 : net_send: bytes sent: 118

    DEBUG [0x660] 12/04/2016 14:31:14 : net_send: full packet sent

    DEBUG [0x660] 12/04/2016 14:31:14 : dcaclient_send_data: DATA Sent

    DEBUG [0x660] 12/04/2016 14:31:14 : dca_add_userinfo_dcaclient: DCA Client IO succeded

    DEBUG [0x660] 12/04/2016 14:31:14 : threadpool_finishnotify: Thread ID: 0x660

    DEBUG [0x660] 12/04/2016 14:31:14 : threadpool_finishnotify: Reset Event

  • Hello Emil,


    Can you verify and check your STAS settings from System > Authentication > Authentication Services

    what is data threshold and inactivity time set there ?

  • In reply to EmilMartini:

    Hi Emil,

    So just looking through the log you posted I can see at 14:31:13 the Collector as part of the log off detection performed a WMI lookup on 172.16.0.22 and receieved a response that the logged on user was "administrator"

    DEBUG [0x5ec] 12/04/2016 14:31:13 : wrkstpoll_workerthread_wmi: connecting to WMI Namespace '\\172.16.0.22\root\cimv2'
    DEBUG [0x660] 12/04/2016 14:31:13 : threadpool_threadproc: Executing Function 0x455880
    MSG [0x5ec] 12/04/2016 14:31:13 : wrkstpoll_workerthread_wmi: username:administrator

    This resulted in the user emil.martini being logged off at 14:31:14.

    INFO [0x5ec] 12/04/2016 14:31:14 : remove_user_from_de_repositry: user emil.martini with ip 172.16.0.22 removed from DE
    MSG [0x5ec] 12/04/2016 14:31:14 : wrkstpoll_handle_logoff_req: user 'btzit.local\emil.martini' removed

    The indication is that there is a authenticated process executing on the workstation that uses the "administrator" account, when this executes windows reports the last logged on user as "administrator"

    Assuming that the administrator account is not used as an account in the user space, the simplest solution would be to configure the STAS environment to ignore (not track) "administrator" log on events. This can be performed ia the "Exclusion List" Tab in the STAS Client.

    Note: using the general "administrator" for dual purposes (i.e. as a user and to run services) can be problematic, I would suggest investigating the option of changing the context for the service/application currently running under "administrator" to a dedicated services account which can be excluded in its place.

  • In reply to VivekJanjrukiya:

    Hi,

    Inactivity Time: 120 Minutes

    Data Transfer Threshold: 100 Bytes

    Thanks

    Emil

  • In reply to Leon.Friend:

    Hi Leon,

    I create a new user and start STAS in all DC with this user.

    I have excluded the user created and administrator in all STAS, the result is the same.

    In DC1 STAS Show live user user emil.martini is not present, in DC2 STAS Show live user user emil.martini is present

    Thanks

    Emil

  • In reply to EmilMartini:

    Can we check your setup, you only have one STAS environment. When you have a multiple DC you have a Agent on both servers and the collector on one. Both agents populate the identity table on the single collector and the appliance only talks to one collector at a time. This means you can have a second collector deployed, however it is a backup collector and is only used when the primary collector is unavailable (both the agents and the appliance will switch to it)

    As you can tell this means that the collector should be aware of the log on events for either DC so you should not see a situation where the user is visible in one place but not another.

    Specifics of the setup for multiple domain controllers can be found at

  • In reply to Leon.Friend:

    Hi Leon,

    i have remove in dc2 the STAS suite and re-install in agent mode.

    In sophos xg console I configure only ip dc1 STAS?

    (system auth cta collector add collector-ip  <dc1 ip>

    collector-port 6677 collector-group 1)

    Thanks

    Emil

  • In reply to EmilMartini:

    Hi Emil,

    Has it started to behave now?

  • In reply to Leon.Friend:

    Hi Leon,

    only if I deactivating , logoff detection by SATS collector seems to work best

    Thanks

    Emil

  • In reply to Leon.Friend:

    Hi Leon,

    i have disable "Enable logoff detection" but now every time marked in "Dead entry timeout" the user logout

    thanks

    Emil

  • I am having a similar issue and know what is causing it but do not know how to fix it. 

     Scenario:

    USER_A logs into COMPUTER_1 and is authenticated properly.

    USER_A then remote desktops to COMPUTER_2 and logs in as USER_B. 

    USER_B is now showing as the authenticated user for COMPUTER_1, even though it should still be USER_A because USER_A is still logged into COMPUTER_1.

    20 minutes later, USER_A is disconnected and has no access to the internet on COMPUTER_1. 

    Under the STAS exclusion list I've added USER_B as a login exclusion and the IP address of COMPUTER_2 as a login/logoff exclusion. 

    This is extremely annoying, as I am constantly using Remote Desktop to connect to another machine with a different username than the username I am presently logged into on my local machine. 

  • In reply to ChristopherButler:

    Hi,

    Any resolve about this issue?

    Thanks.

  • I am having the same problem.  Its even more fun because this kills my SSL VPN session after 10 minutes and then every minute afterward.  I believe the STAS software is fundamentally broken when it comes to WMI queries for logoff information.  I followed this: https://community.sophos.com/kb/en-us/123020 

    Every 10 minutes it tries to connect to the computers via WMI to verify and it fails and then terminates the user sessions.  However if I simultaneously run the WMI query in the article, it shows me the correct the username logged into the computer.  Interestingly enough it tries to connect to non-Windows computers who have no users in the "Live Users" table, and those obviously fail too. 

    What would be the implication of just disabling all automatic logoff/session idle timers?  I would think that in theory, user A logs in and then logs off, the XG doesn't know about the logoff and still shows them as on, but if user B then comes and logs in to the same machine sometime later, wouldn't the STAS event update the Sophos box and say "User B is now logged in at IP blah blah?"  As far as I know, I believe this is how Meraki does it. 

    All in all this is extremely frustrating. 

  • In reply to Bill Roland:

    I have exectly the same problem - If I switch on Logoff detection, some users are randomly disconnectet. I have coped with this problem from the ancient times - CTAS + UTM.

    We tried several configurations (one STAT, two STAS, different agents etc.) - simply- it will be much better if this simply works.

    BTW: CAN we disable WMI pooling completely?

    Even if we have "logoff detection" switched off, WMI/remote registry polling runs permanently.