Sophos AD Integration - Authentication proble

Why do you want to use L2TP in the first place?

Was the first option we had for remote workers

Wouldnt be Sophos Connect via IPsec / SSLVPN the better approach anyway? L2TP is rather the old scenario. 

I am testing SSLVPN for a future deploy and facing the same issue with AD authentication

I'm using L2TP/IPSEC

Hi Marcelo Laurenti,

Thank you for contacting the Sophos Community.

You may check access_server debug events to get more information about auth_fail. Run the below command to put access_server service in debugging.

==> Login to SSH > 5. Device Management > 3. Advanced Shell.

SFOS 18.0.4 MR-4# service access_server:debug -ds nosync

SFOS 18.0.4 MR-4# tail -f /log/access_server.log

==> Try to login to SSL VPN client, and share log output here or in DM to investigate it further. Also please share the SSL VPN client log.

==> To stop debugging please run the below command.

SFOS 18.0.4 MR-4# service access_server:debug -ds nosync

Here is the output, as client we use L2TP/IPSEC Windows 10.

DEBUG Feb 25 06:39:49.500435 [access_server]: more_tlv_checks : current tlv len = 4 Sum of length of sub tlv = 8

DEBUG Feb 25 06:39:49.500439 [access_server]: more_tlv_checks : current tlv len = 29 Sum of length of sub tlv = 41

DEBUG Feb 25 06:39:49.500442 [access_server]: more_tlv_checks : current tlv len = 24 Sum of length of sub tlv = 69

DEBUG Feb 25 06:39:49.500446 [access_server]: more_tlv_checks : current tlv len = 20 Sum of length of sub tlv = 93

DEBUG Feb 25 06:39:49.500449 [access_server]: more_tlv_checks : current tlv len = 14 Sum of length of sub tlv = 111

DEBUG Feb 25 06:39:49.500453 [access_server]: more_tlv_checks : Valid TLV received, Length of main TLV = 116 Sum of length of sub tlv = 111
INFO Feb 25 06:39:49.500458 [access_server]: print_auth_tlv: -----------------AUTH_TLV--------
INFO Feb 25 06:39:49.500462 [access_server]: print_auth_tlv: TLV Type: 0
INFO Feb 25 06:39:49.500465 [access_server]: print_auth_tlv: TLV Length: 4
INFO Feb 25 06:39:49.500469 [access_server]: print_auth_tlv: ---------------------------------
DEBUG Feb 25 06:39:49.500472 [access_server]: (process_pam_request): clienttype:'6'
INFO Feb 25 06:39:49.500476 [access_server]: print_auth_tlv: -----------------AUTH_TLV--------
INFO Feb 25 06:39:49.500479 [access_server]: print_auth_tlv: TLV Type: 1
INFO Feb 25 06:39:49.500482 [access_server]: print_auth_tlv: TLV Length: 29
INFO Feb 25 06:39:49.500486 [access_server]: print_auth_tlv: ---------------------------------
DEBUG Feb 25 06:39:49.500489 [access_server]: (process_pam_request): username:'mlaurenti@xxxx.xxxx.com.ar'
INFO Feb 25 06:39:49.500492 [access_server]: print_auth_tlv: -----------------AUTH_TLV--------
INFO Feb 25 06:39:49.500496 [access_server]: print_auth_tlv: TLV Type: 2
INFO Feb 25 06:39:49.500499 [access_server]: print_auth_tlv: TLV Length: 24
INFO Feb 25 06:39:49.500502 [access_server]: print_auth_tlv: ---------------------------------
DEBUG Feb 25 06:39:49.500506 [access_server]: (process_pam_request): password: not empty
INFO Feb 25 06:39:49.500509 [access_server]: print_auth_tlv: -----------------AUTH_TLV--------
INFO Feb 25 06:39:49.500524 [access_server]: print_auth_tlv: TLV Type: 3
INFO Feb 25 06:39:49.500528 [access_server]: print_auth_tlv: TLV Length: 20
INFO Feb 25 06:39:49.500531 [access_server]: print_auth_tlv: ---------------------------------
DEBUG Feb 25 06:39:49.500535 [access_server]: (process_pam_request): CHAP Auth Requested
DEBUG Feb 25 06:39:49.500538 [access_server]: (process_pam_request): ChapPass: not empty
INFO Feb 25 06:39:49.500542 [access_server]: print_auth_tlv: -----------------AUTH_TLV--------
INFO Feb 25 06:39:49.500545 [access_server]: print_auth_tlv: TLV Type: 5
INFO Feb 25 06:39:49.500548 [access_server]: print_auth_tlv: TLV Length: 14
INFO Feb 25 06:39:49.500552 [access_server]: print_auth_tlv: ---------------------------------
DEBUG Feb 25 06:39:49.500555 [access_server]: (process_pam_request): ipaddress:'XX.162.40.125'
DEBUG Feb 25 06:39:49.500562 [access_server]: (authenticate_chap_user): current server:0, auth_client:1
DEBUG Feb 25 06:39:49.500566 [access_server]: (authenticate_chap_user): current server:1, auth_client:1
INFO Feb 25 06:39:49.500570 [access_server]: (authenticate_chap_user): Server:1, Local Authentication
DEBUG Feb 25 06:39:49.500574 [access_server]: (subsys_submit_request): subsys_name=POSTGRES_DB req_type=50 req_handler=0x5666dc51 res_handler=0x5663723c handler_data=0x57708740
DEBUG Feb 25 06:39:49.500579 [access_server]: (append_subsysqueue): : CLIENT, datasize: 16
DEBUG Feb 25 06:39:49.500583 [access_server]: (append_subsysqueue): acquiring lock 0x576979c8
DEBUG Feb 25 06:39:49.500588 [access_server]: (append_subsysqueue): : CLIENT, remlen: 160
DEBUG Feb 25 06:39:49.500592 [access_server]: (append_subsysqueue): released lock 0x576979c8
INFO Feb 25 06:39:49.500596 [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue
DEBUG Feb 25 06:39:49.500599 [access_server]: (subsys_submit_request): POSTGRES_DB: request submitted, req_type=50
DEBUG Feb 25 06:39:49.500603 [access_server]: (write_subsysqueue): acquiring lock 0x576979c8
DEBUG Feb 25 06:39:49.500611 [access_server]: (write_subsysqueue): released lock 0x576979c8
INFO Feb 25 06:39:49.500614 [access_server]: (write_subsysqueue): POSTGRES_DB CLIENT: written 16 bytes, fd=8 wq=0x576a7200 buf=0x576a7208 offset=0
INFO Feb 25 06:39:49.500620 [access_server]: (authenticate_chap_user): Server:0, ADS Authentication
DEBUG Feb 25 06:39:49.500621 [POSTGRES_DB]: subsys_thread_main: POSTGRES_DB: event received on fd: 9
DEBUG Feb 25 06:39:49.500625 [access_server]: (do_epoll): Waiting for events
DEBUG Feb 25 06:39:49.500631 [POSTGRES_DB]: handle_server_events: EVENT_READ
INFO Feb 25 06:39:49.500635 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: READING... fd=9
INFO Feb 25 06:39:49.500641 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: read 16 bytes, fd=9
DEBUG Feb 25 06:39:49.500645 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server tlv=0x576a6ff8 req_handler=0x5666dc51 type=50 handler_data=0x57708740 res_handler=0x5663723c
DEBUG Feb 25 06:39:49.500651 [POSTGRES_DB]: (pg_db_handle_request): access_server heartbeat
DEBUG Feb 25 06:39:49.500656 [POSTGRES_DB]: (pg_db_handle_request): L2TP_GETPASS triggers alloc_query_vals()
DEBUG Feb 25 06:39:49.500659 [POSTGRES_DB]: (alloc_query_vals): using query_vals on stack 0xf72fe62c
DEBUG Feb 25 06:39:49.500664 [POSTGRES_DB]: (pg_db_process_prepq_async): executing command 'L2TP_GETPASS'
DEBUG Feb 25 06:39:49.500668 [POSTGRES_DB]: (pg_db_process_prepq_async): PG's socket (fd 6) is NON-blocking
DEBUG Feb 25 06:39:49.500671 [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[0]: 'mlaurenti@xxxx.xxxx.com.ar'
DEBUG Feb 25 06:39:49.500675 [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[1]: 'mlaurenti@xxxx.xxxx.com.ar'
DEBUG Feb 25 06:39:49.500679 [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[2]: 'mlaurenti@xxxx.xxxx.com.ar'
DEBUG Feb 25 06:39:49.500997 [POSTGRES_DB]: (pg_db_get_async_prepq_result): retrieving PGresult of 'L2TP_GETPASS'
DEBUG Feb 25 06:39:49.501013 [POSTGRES_DB]: (pg_db_get_async_prepq_result): returning PGresult 1 (0xf5c181c0)
DEBUG Feb 25 06:39:49.501017 [POSTGRES_DB]: (pg_db_handle_chap_getpass): row count: 0
ERROR Feb 25 06:39:49.501021 [POSTGRES_DB]: (pg_db_handle_chap_getpass): No rows found
DEBUG Feb 25 06:39:49.501025 [POSTGRES_DB]: pg_db_submit_response: Request Processed: res_type=-1
DEBUG Feb 25 06:39:49.501029 [POSTGRES_DB]: (append_subsysqueue): : SERVER, datasize: 16
DEBUG Feb 25 06:39:49.501033 [POSTGRES_DB]: (append_subsysqueue): acquiring lock 0x576979ec
DEBUG Feb 25 06:39:49.501037 [POSTGRES_DB]: (append_subsysqueue): : SERVER, remlen: 160
DEBUG Feb 25 06:39:49.501040 [POSTGRES_DB]: (append_subsysqueue): released lock 0x576979ec
INFO Feb 25 06:39:49.501044 [POSTGRES_DB]: (append_subsysqueue): SERVER: '16' bytes appended to subsys queue
DEBUG Feb 25 06:39:49.501047 [POSTGRES_DB]: subsys_submit_response: POSTGRES_DB: response submitted, res_type=255
DEBUG Feb 25 06:39:49.501051 [POSTGRES_DB]: (write_subsysqueue): acquiring lock 0x576979ec
DEBUG Feb 25 06:39:49.501057 [POSTGRES_DB]: (write_subsysqueue): released lock 0x576979ec
DEBUG Feb 25 06:39:49.501060 [access_server]: handle_client_events: EVENT_READ
INFO Feb 25 06:39:49.501061 [POSTGRES_DB]: (write_subsysqueue): POSTGRES_DB SERVER: written 16 bytes, fd=9 wq=0x576a70a0 buf=0x576a70a8 offset=0
INFO Feb 25 06:39:49.501066 [access_server]: (do_handle_read): POSTGRES_DB client: READING... fd=8
INFO Feb 25 06:39:49.501067 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: READING... fd=9
INFO Feb 25 06:39:49.501071 [access_server]: (do_handle_read): POSTGRES_DB client: read 16 bytes, fd=8
INFO Feb 25 06:39:49.501072 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: read blocked
DEBUG Feb 25 06:39:49.501075 [access_server]: (do_handle_read): POSTGRES_DB client tlv=0x576a7158 req_handler=(nil) type=255 handler_data=0x57708740 res_handler=0x5663723c
INFO Feb 25 06:39:49.501077 [POSTGRES_DB]: subsys_thread_main: POSTGRES_DB: waiting for events...
DEBUG Feb 25 06:39:49.501081 [access_server]: (authenticate_chap_user): current server:2, auth_client:1
DEBUG Feb 25 06:39:49.501085 [access_server]: (authenticate_chap_user): authserver_id <= 0, No server left
ERROR Feb 25 06:39:49.501089 [access_server]: check_auth_result: VPN/SSLVPN/MYACC Authentication Failed
DEBUG Feb 25 06:39:49.501094 [access_server]: (fill_pam_garner_data): AF_INET ip address 'XXX.162.40.125' is valid
DEBUG Feb 25 06:39:49.501104 [access_server]: (update_admin_access_table): ip=XXX.162.40.125 clienttype=6
DEBUG Feb 25 06:39:49.501108 [access_server]: (update_admin_access_table): attempt_allowed: '5', attempts_duration: '60', block_for_minutes: '5'
DEBUG Feb 25 06:39:49.501113 [access_server]: (sqlite_db_handle_request): access_server heartbeat
DEBUG Feb 25 06:39:49.501117 [access_server]: (bind_parameters_to_statement): Binding 1 parameters 0xffea0f08 for query 0x5676f928
DEBUG Feb 25 06:39:49.501122 [access_server]: (bind_parameters_to_statement): Query name IS_ADMIN_IP_EXIST
DEBUG Feb 25 06:39:49.501132 [access_server]: (check_sqlite_bind_text_result): sqlite3_bind_text(IS_ADMIN_IP_EXIST, XXX.162.40.125) succeeded
DEBUG Feb 25 06:39:49.501149 [access_server]: (handle_count_star_query): IS_ADMIN_IP_EXIST retrieved: count = 1
DEBUG Feb 25 06:39:49.501155 [access_server]: (handle_count_star_query): returning 1
DEBUG Feb 25 06:39:49.501160 [access_server]: (sqlite_db_submit_response): Request processed res=1

DEBUG Feb 25 06:39:49.501163 [access_server]: (sqlite_db_handle_request): access_server heartbeat
DEBUG Feb 25 06:39:49.501167 [access_server]: (bind_parameters_to_statement): Binding 1 parameters 0xffea0f08 for query 0x5676fb6c
DEBUG Feb 25 06:39:49.501171 [access_server]: (bind_parameters_to_statement): Query name GET_ADMINACCESS_INFO
DEBUG Feb 25 06:39:49.501176 [access_server]: (check_sqlite_bind_text_result): sqlite3_bind_text(GET_ADMINACCESS_INFO, XXX.162.40.125) succeeded
DEBUG Feb 25 06:39:49.501191 [access_server]: (_sqlite_db_handle_get_adminaccess_info): GET_ADMINACCESS_INFO retrieved: lastfail=1717762 timeleft=60 counter=1 blocking=0
DEBUG Feb 25 06:39:49.501197 [access_server]: (_sqlite_db_handle_get_adminaccess_info): returning 0
DEBUG Feb 25 06:39:49.501201 [access_server]: (sqlite_db_submit_response): Request processed res=0

MESSAGE Feb 25 06:39:49.501204 [access_server]: (update_admin_access_table): # Admin user authentication fail from IP XXX.162.40.125
DEBUG Feb 25 06:39:49.501208 [access_server]: (bind_parameters_to_statement): Binding 5 parameters 0xffea1980 for query 0x5676fd4c
DEBUG Feb 25 06:39:49.501212 [access_server]: (bind_parameters_to_statement): Query name UPDATE_ADMINACCESS
DEBUG Feb 25 06:39:49.501217 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_ADMINACCESS, 1718090) succeeded
DEBUG Feb 25 06:39:49.501220 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_ADMINACCESS, 60) succeeded
DEBUG Feb 25 06:39:49.501224 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_ADMINACCESS, 1) succeeded
DEBUG Feb 25 06:39:49.501227 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_ADMINACCESS, 0) succeeded
DEBUG Feb 25 06:39:49.501232 [access_server]: (check_sqlite_bind_text_result): sqlite3_bind_text(UPDATE_ADMINACCESS, XXX.162.40.125) succeeded
DEBUG Feb 25 06:39:49.501236 [access_server]: (sqlite_db_handle_request): access_server heartbeat
DEBUG Feb 25 06:39:49.501253 [access_server]: (sqlite_db_submit_response): Request processed res=0

DEBUG Feb 25 06:39:49.501257 [access_server]: (send_pam_response): resp_code=3, clienttype=6, message='Login failed. Invalid user name/password. Please contact the administrator. '
DEBUG Feb 25 06:39:49.501261 [access_server]: send_pam_response: message:'Login failed. Invalid user name/password. Please contact the administrator. ', len:76, data:'Login failed. Invalid user name/password. Please contact the administrator. '
DEBUG Feb 25 06:39:49.501265 [access_server]: (send_response_authtlv): Packetlen:80
DEBUG Feb 25 06:39:49.501270 [access_server]: (do_sendto): send response of 80 bytes to IP: 127.0.0.1 PORT: 34852
DEBUG Feb 25 06:39:49.501274 [access_server]: (do_sendto): pktinfo: ifindex: 0, local address: 127.0.0.1
DEBUG Feb 25 06:39:49.501288 [access_server]: (send_response_authtlv): Bytes sent:80, Buf len:80
DEBUG Feb 25 06:39:49.501292 [access_server]: free_session_data: session_data=0x57708740
INFO Feb 25 06:39:49.501296 [access_server]: (do_handle_read): POSTGRES_DB client: READING... fd=8
INFO Feb 25 06:39:49.501301 [access_server]: (do_handle_read): POSTGRES_DB client: read blocked
DEBUG Feb 25 06:39:49.501305 [access_server]: (do_epoll): Waiting for events
DEBUG Feb 25 06:39:50.586613 [CAA]: (CA_epoll_wait): returning 0
MESSAGE Feb 25 06:39:50.586630 [CAA]: (CA_keep_alive): access_server heartbeat
DEBUG Feb 25 06:39:50.586635 [CAA]: (CA_keep_alive): Checking connections status
MESSAGE Feb 25 06:39:50.586639 [CAA]: (CA_keep_alive): Next CA batch in 45 seconds
DEBUG Feb 25 06:39:50.586643 [CAA]: (process_caa_messages): Waiting for CAA events
DEBUG Feb 25 06:39:50.586646 [CAA]: (CA_epoll_wait): timeout=45000, time_to_keep_alive=45000
DEBUG Feb 25 06:39:58.536217 [access_server]: (handle_client): 11 bytes from IP: XXX.211.1.196, PORT: 65402
DEBUG Feb 25 06:39:58.536229 [access_server]: (handle_client): pktinfo: ifindex: 5, local address: XXX.211.254.244

Hi Marcelo Laurenti : Is login request getting failed all the time over XG when AD user change his password on AD server or is it only for the 1st time getting failed?

What is the order OR position of AD server in the Authentication server settings? 

Reference snapshot:

 

Hi, when the user change the password. The DC is first.

Regards

Hi Marcelo Laurenti : thanks for sharing the requested information, if issue still present and re producible then please open a support case to have further investigation and finding.