I use the Sophos Single Sign-On Client (SSO) the first one in Client downloads page. The thing happens at morning as i notice my internet connection in my desktop lost constantly, then i check the xg find there is high cpu usage with little traffic. Using top i find a "worker" process constantly running 100% (suppose it's single threaded), and "access_server" "login_user" "logout_user" apear time to time with high cpu usage. This brings me the the authentication log where i find the logs below, which is apearantly unnormal. 2017-02-13 14:33:59 Firewall Authentication SUCCESSFUL user@domain.local 10.18.100.146 SSO N/A User user@domain.local was logged out of firewall 17703 Open PCAP 2017-02-13 14:33:59 Firewall Authentication SUCCESSFUL user@domain.local 10.18.100.146 SSO AD User user@domain.local of group sys-admin logged in successfully to Firewall through AD authentication mechanism from 10.18.100.146 17701 Open PCAP 2017-02-13 14:34:00 Firewall Authentication SUCCESSFUL user@domain.local 10.18.100.146 SSO N/A User user@domain.local was logged out of firewall 17703 Open PCAP 2017-02-13 14:34:00 Firewall Authentication SUCCESSFUL user@domain.local 10.18.100.146 SSO AD User user@domain.local of group sys-admin logged in successfully to Firewall through AD authentication mechanism from 10.18.100.146 17701 Open PCAP I manually stop all of the SSO Client and CPU instantly went back to normal (mostly idle). So far i have tried reboot every thing around it and itself. I also have tried to restore a know good config backup a month ago. Rollback to the 16.01.3 MR-2. All of them didn't solve the problem. =====edited====== unrelated Find some thing strange, /log/syslog.log shows /bin/login is constantly restarted in a one sec interval Feb 14 03:08:02 (none) daemon.info init: process '/bin/login' (pid 9706) exited. Scheduling for restart. Feb 14 03:08:02 (none) daemon.info init: starting pid 9707, tty '/dev/ttyS0': '/bin/login' Feb 14 03:08:03 (none) daemon.info init: process '/bin/login' (pid 9707) exited. Scheduling for restart. Feb 14 03:08:03 (none) daemon.info init: starting pid 9708, tty '/dev/ttyS0': '/bin/login'

For anyone still experiencing this issue: They know about the problem and have a (temporary) fix one of their engineers can do for you, assuming you have the exact same issue we did. The longer-term solution should be coming in MR5. Ours is now working correctly, so we'll skip MR4 and update to 5 when it's released.

Hi, Take SSH to the XG and go to option 5. Device Management > 3. Advance Shell and execute the following command. cd /log tail -f access_server.log | grep username Please post the logs to check further. Thanks

Hi Jeremy, Could you DM us the Case # you have received along with the link to this tread . We will look into it and update you further.

Hi, I checked the access_server.log file you DMed me, it states that the Access Server is getting restarted which may be the reason for disconnections. MESSAGE Feb 14 10:39:06 [4144490304]: access_server: Access Server Shuting down MESSAGE Feb 14 10:39:06 [4144490304]: (CA_exit): ClientAuth successfully finished ERROR Feb 14 10:39:06 [4144490304]: pg_db_release_client: Database disconneted ERROR Feb 14 10:39:06 [4144490304]: pg_db_release_client: Database disconneted MESSAGE Feb 14 10:39:06 [4144490304]: access_server: Access Server Stopped Please DM me postgres and syslog from the above date and time. Thanks

This discussion has been locked.

You can no longer post new replies to this discussion. If you have a question you can start a new discussion

User login through SSO client constant login and off in 16.05.1 MR-1

daiqingxu over 8 years ago

I use the Sophos Single Sign-On Client (SSO) the first one in Client downloads page.

The thing happens at morning as i notice my internet connection in my desktop lost constantly, then i check the xg find there is high cpu usage with little traffic. Using top i find a "worker" process constantly running 100% (suppose it's single threaded), and "access_server" "login_user" "logout_user" apear time to time with high cpu usage. This brings me the the authentication log where i find the logs below, which is apearantly unnormal.

2017-02-13 14:33:59	Firewall Authentication	SUCCESSFUL	user@domain.local	10.18.100.146	SSO	N/A	User user@domain.local was logged out of firewall	17703	Open PCAP
2017-02-13 14:33:59	Firewall Authentication	SUCCESSFUL	user@domain.local	10.18.100.146	SSO	AD	User user@domain.local of group sys-admin logged in successfully to Firewall through AD authentication mechanism from 10.18.100.146	17701	Open PCAP
2017-02-13 14:34:00	Firewall Authentication	SUCCESSFUL	user@domain.local	10.18.100.146	SSO	N/A	User user@domain.local was logged out of firewall	17703	Open PCAP
2017-02-13 14:34:00	Firewall Authentication	SUCCESSFUL	user@domain.local	10.18.100.146	SSO	AD	User user@domain.local of group sys-admin logged in successfully to Firewall through AD authentication mechanism from 10.18.100.146	17701	Open PCAP

I manually stop all of the SSO Client and CPU instantly went back to normal (mostly idle).

So far i have tried reboot every thing around it and itself. I also have tried to restore a know good config backup a month ago. Rollback to the 16.01.3 MR-2. All of them didn't solve the problem.

=====edited======

unrelated

Find some thing strange, /log/syslog.log shows /bin/login is constantly restarted in a one sec interval

Feb 14 03:08:02 (none) daemon.info init: process '/bin/login' (pid 9706) exited. Scheduling for restart.
Feb 14 03:08:02 (none) daemon.info init: starting pid 9707, tty '/dev/ttyS0': '/bin/login'
Feb 14 03:08:03 (none) daemon.info init: process '/bin/login' (pid 9707) exited. Scheduling for restart.
Feb 14 03:08:03 (none) daemon.info init: starting pid 9708, tty '/dev/ttyS0': '/bin/login'

This thread was automatically locked due to age.

Parents

0 sachingurung over 8 years ago

Hi,

Which type of SSO are we looking at here? Please share some more details.

There is an unwritten rule in the Forum which defines one question per thread. Please post the HIGH CPU issue separately.

Thanks
Cancel
Vote Up 0 Vote Down

Cancel
0 daiqingxu over 8 years ago in reply to sachingurung

sachingurung said:

Hi,

Which type of SSO are we looking at here? Please share some more details.

There is an unwritten rule in the Forum which defines one question per thread. Please post the HIGH CPU issue separately.

Thanks

this first one in the Authentication client download page.

Sophos Single Sign-On Client (SSO) or cyberoam client (this is heard from forum).

I highly suspect the high CPU usage is related to client logon/logoff continuously, since every thing is normal except the authentication problem
Cancel
Vote Up 0 Vote Down

Cancel

Reply

0 daiqingxu over 8 years ago in reply to sachingurung

sachingurung said:

Hi,

Which type of SSO are we looking at here? Please share some more details.

There is an unwritten rule in the Forum which defines one question per thread. Please post the HIGH CPU issue separately.

Thanks

this first one in the Authentication client download page.

Sophos Single Sign-On Client (SSO) or cyberoam client (this is heard from forum).

I highly suspect the high CPU usage is related to client logon/logoff continuously, since every thing is normal except the authentication problem
Cancel
Vote Up 0 Vote Down

Cancel

Children

0 sachingurung over 8 years ago in reply to daiqingxu

Hi,

Did you monitor if the issue resolves when the CPU levels go down? Is the issue intermittent or the Authentication never worked stable?

Verify if the configuration is correct as in the article here. Also, show us pictures of the configuration to verify them at our end.

Test the working by turning off the local system FIREWALL.

Awaiting update.
Cancel
Vote Up 0 Vote Down

Cancel
0 daiqingxu over 8 years ago in reply to sachingurung

The issue persistent when CPU levels go down. The issue cause computer affected having trabble access anything outside the lan. While SSO Client not working, same user using Authentication Clients (that client need manual enter the username and password upon first logon) works without problem. SSO Client with same setup has been working normally for at least two months.

Configuration is setup acording to that. I'm not sure what you want me to show you. In my understand there only very limited thing can config here. AD should be correct since i can using other client and login to web admin. The client have only three configurable param, and i can confirm the FQDN of domain name and sophosxg ip address is correct the last matches whats in the link which is “ADS”.

I also removed all except one Active Directory server in Authentication - Servers, but still no luck.

I have tried disable firewall on the client and domain controller at same time, still no luck.
Cancel
Vote Up 0 Vote Down

Cancel
0 sachingurung over 8 years ago in reply to daiqingxu

Hi,

Take SSH to the XG and go to option 5. Device Management > 3. Advance Shell and execute the following command.

cd /log

tail -f access_server.log | grep username

Please post the logs to check further.

Thanks
Cancel
Vote Up 0 Vote Down

Cancel
0 daiqingxu over 8 years ago in reply to sachingurung

I can't find accessserver.log, i suppose you mean access_server.log?

If so when i stoped Authentication Clients and only run SSO Clients althrough logged in logged out event of SSO client in the authentication log continues, nothing logs to access_server.log file.

If i run Authentication Clients (which is working currently) i can see the initial login and follow keep_alive logs in the access_server.log file.
Cancel
Vote Up 0 Vote Down

Cancel
0 sachingurung over 8 years ago in reply to daiqingxu

Edited the actual name of the log file. Please post the logs to me so that I can check what is happening inside.

Thanks
Cancel
Vote Up 0 Vote Down

Cancel
0 daiqingxu over 8 years ago in reply to sachingurung

Full log is pmed

Follows are some thing i think maybe related to the problem

MESSAGE   Feb 15 08:36:46 [4144265024]: (main): Starting Sophos Firewall access_server
MESSAGE   Feb 15 08:36:46 [4144265024]: (add_worker): GENERIC
......

lots of pg_db_prepare_statements

......
MESSAGE   Feb 15 08:36:46 [4144265024]: (add_worker): POSTGRES_DB
MESSAGE   Feb 15 08:36:46 [4144265024]: sqlite_db_init: TRIGGER 'remove_liveuser_acc' created successfully
MESSAGE   Feb 15 08:36:46 [4144265024]: sqlite_db_init: TRIGGER 'update_datatransfer' created successfully
MESSAGE   Feb 15 08:36:46 [4144265024]: (add_worker): SQLITE_DB
MESSAGE   Feb 15 08:36:46 [4144265024]: pg_db_handle_get_citrix_config Total number of CITRIX Servers'0'
MESSAGE   Feb 15 08:36:46 [4144265024]: (add_worker): ADS_AUTH
MESSAGE   Feb 15 08:36:46 [4144265024]: (add_worker): RADIUS_AUTH
ERROR     Feb 15 08:36:46 [4144265024]: pg_db_handle_get_user_accounting: row count: 0
ERROR     Feb 15 08:36:46 [4144265024]: start_ippool_subsys: PPTP ip pool config failed
MESSAGE   Feb 15 08:36:46 [4144265024]: (add_worker): IP_POOL
ERROR     Feb 15 08:36:46 [4144265024]: ippool_init: table allocatedip created
ERROR     Feb 15 08:36:46 [4144265024]: ippool_init: table reservedip created
ERROR     Feb 15 08:36:46 [4144265024]: ippool_init: table reservedip created
MESSAGE   Feb 15 08:36:46 [4144265024]: ippool_free_downtime_disconnected_ip: No connection was disconnected in downtime
ERROR     Feb 15 08:36:46 [4144265024]: pg_db_handle_get_user_accounting: row count: 0
ERROR     Feb 15 08:36:46 [4144265024]: start_ippool_subsys: get reserved ip pool config failed
ERROR     Feb 15 08:36:46 [4144265024]: nvram_get(defaultlicenseuser): failed with -12
ERROR     Feb 15 08:36:46 [4144265024]: get_max_allowed_users: Failed to read nvram key defaultlicenseuser
MESSAGE   Feb 15 08:36:46 [4144265024]: (add_worker): OTP_AUTH
ERROR     Feb 15 08:36:46 [4144265024]: pg_db_handle_get_cache_configuration: Multiple rows found
ERROR     Feb 15 08:36:46 [4144265024]: configure_paraten_proxy_config: failed to get configuration
MESSAGE   Feb 15 08:36:46 [4144265024]: (add_worker): OPCODE
ERROR     Feb 15 08:36:46 [4144265024]: (pg_db_process_prepq_async): PQisBusy() > 0!
MESSAGE   Feb 15 08:36:46 [4144265024]: (main): access_server: access_server started Successfully
MESSAGE   Feb 15 08:36:49 [4144265024]: access_server: Clientless users login complete
MESSAGE   Feb 15 08:36:49 [4144265024]: (CA_init): ClientAuth initialized
MESSAGE   Feb 15 08:36:49 [4144265024]: (add_worker): EDIR_SYNC
MESSAGE   Feb 15 08:39:28 [4144265024]: config_update_group_config: UPDATING BWID IN DB
MESSAGE   Feb 15 08:53:34 [4144265024]: (process_command): Client type is OS X
MESSAGE   Feb 15 08:53:34 [4144265024]: (CA_authentication_result): User xdq authenticated (CA)
ERROR     Feb 15 08:53:34 [4131371840]: config_resolve_datatransferid: Datatransfer Policy 0 not found

=======

ERROR     Feb 16 17:23:58 [4135582528]: adsauth_bind: bind failed: Invalid credentials
ERROR     Feb 16 17:23:58 [4135582528]: adsauth_authenticate_user: '10.18.8.1:636': bind failed for User: 'DOMAIN\user'
ERROR     Feb 16 17:23:58 [4135582528]: adsauth_authenticate_user: ADS Authentication Failed for User:'user'
ERROR     Feb 16 17:23:58 [4135582528]: adsauth_parse_error_msg: ad error no: 1326
ERROR     Feb 16 17:23:58 [4135582528]: adsauth_bind: bind failed: Invalid credentials
ERROR     Feb 16 17:23:58 [4135582528]: adsauth_authenticate_user: '10.18.8.2:636': bind failed for User: 'DOMAIN\user'
ERROR     Feb 16 17:23:58 [4135582528]: adsauth_authenticate_user: ADS Authentication Failed for User:'user'
ERROR     Feb 16 17:23:58 [4135582528]: adsauth_parse_error_msg: ad error no: 1326
ERROR     Feb 16 17:23:58 [4144265024]: check_auth_result: VPN/SSLVPN/MYACC Authentication Failed
Cancel
Vote Up 0 Vote Down

Cancel

0 daiqingxu over 8 years ago in reply to sachingurung

In case it maybe usefull, Packet Capture of traffic between the client

============== first ===========

2017-02-16 17:37:40

Port1

IPv4

10.18.100.146

10.18.1.1

UDP

61532,6060

Incoming

Ethernet Header

Source MAC Address:d8:cb:8a:c9:e8:ab

Destination MAC Address: a0:36:9f:a1:03:68

Ethernet Type IPv4 (0x800)

IPv4 Header

Source IP Address:10.18.100.146

Destination IP Address:10.18.1.1

Protocol: UDP

Header:20 Bytes

Type of Service: 0

Total Length: 258 Bytes

Identification:6159

Fragment Offset:0

Time to Live: 128

Checksum: 43045

UDP Header:

Source Port:61532

Destination Port: 6060

Length: 238

Checksum: 64472

Hex & ASCII Detail

0x0000: 4500 0102 180f 0000 8011 a825 0a12 6492 E..........%..d.
       0x0010: 0a12 0101 f05c 17ac 00ee fbd8 4332 3330 .....\......C230
       0x0020: 0078 6471 00cd fdfd fdfd dddd dd00 0000 .xdq............
       0x0030: 00c4 98f7 0d90 1f00 0a48 ae60 03f0 ae00 .........H.`....
       0x0040: 0000 0000 0000 0000 0000 0000 0000 3134 ..............14
       0x0050: 3837 3233 3737 3031 3032 3931 3632 3132 8723770102916212
       0x0060: 3430 3234 0000 0000 0000 0000 0000 0000 4024............
       0x0070: 0000 0000 0000 0000 0000 0000 0000 0000 ................
       0x0080: 0000 0000 0000 0000 0000 0000 0000 0000 ................
       0x0090: 0000 0000 0000 0000 0000 0000 0000 0000 ................
       0x00a0: 0000 0000 0000 0000 0000 0000 0000 0000 ................
       0x00b0: 0000 4438 3a43 423a 3841 3a43 393a 4538 ..D8:CB:8A:C9:E8
       0x00c0: 3a41 4200 0000 687a 6b79 2e78 797a 00cd :AB...hzky.xyz..
       0x00d0: fdfd fdfd 0000 c498 f70d 901f 000f 60af ..............`.
       0x00e0: 6003 c8e5 6003 0000 0000 0000 0000 0500 `...`...........
       0x00f0: 0000 0100 0000 4501 0000 fdfd fdfd 3130 ......E.......10
       0x0100: 2e31 .1

============== secound ====

17:37:40

Port1

IPv4

10.18.100.146

10.18.1.1

UDP

61532,6060

Consumed

UDP Header:

Source Port:61532

Destination Port: 6060

Length: 238

Checksum: 64472

================ thid ==========

Port1

IPv4

10.18.1.1

10.18.100.146

UDP

6060,61532

Generated

UDP Header:

Source Port:6060

Destination Port: 61532

Length: 13

Checksum: 30484

       0x0000: 4500 0021 2cc9 4000 4011 944c 0a12 0101 E..!,.@.@..L....
       0x0010: 0a12 6492 17ac f05c 000d 7714 0200 0500 ..d....\..w.....
       0x0020: 00 .

============== same packets again =======

0 daiqingxu over 8 years ago in reply to sachingurung

spined up a complete new virtual appliance and only setup active directory integrate, the try SSO Client against it. Same problem happened.

This time access_server.log filled with

ERROR Feb 16 15:25:26 [4144236352]: config_resolve_bwid: BW Policy 0 not found
Cancel
Vote Up 0 Vote Down

Cancel

0 Biser Todorov over 8 years ago in reply to daiqingxu

Same problem on XG310 users a constantly trying to login.

On the Firewalls in access_server.log I have also this:

ERROR Feb 16 16:51:14 [4128242496]: config_resolve_bwid: BW Policy 0 not found
ERROR Feb 16 16:51:15 [4144248640]: handle_internal_logout_req: SQLITE_REQ_GETLIVEUSER query failed
ERROR Feb 16 16:51:15 [4144248640]: do_authorization_phase2: Can't Logout User from IP: '192.168.0.13'

On workstations in SSO log I have this:

02/16/17 16:53:37 Sending request size = 230
02/16/17 16:53:38 No Response From Server
02/16/17 16:53:38 Send Failed, will try again in 30 sec

0 Adriano Almeida over 8 years ago in reply to Biser Todorov

Same issue here, with same log (XG 230)

This problem has already occurred in the two previous firmware versions
Cancel
Vote Up 0 Vote Down

Cancel