Sophos AD Integration - Authentication proble

Hello Team,

I´m new in the community, I Have a Sophos XG 330 productive one with SFOS 17.5.12 MR-12 and another Sophos XG 330 for backup SFOS 18.0.4 MR-4 both with AD integration working for SSO and L"TP/IPSEC VPN access but when an AD user change the AD password the sophos appliance deny access reporting authentication failure but the user AD authentication works ok. I did everything recomended such logout and login on a workstation, reboot the workstation an login again, but nothing works.

Hope someone could help.

Regards

Marcelo

  • 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

  • Hi ,

    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

    Thanks,
    Yash Kothari
    Community Support Engineer | Sophos Technical Support
    Sophos Support Videos | Product Documentation | @SophosSupport | Sign up for SMS Alerts
    If a post solves your question, use the 'Verify Answer' link.
  • 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 : 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:

      

    Regards,

    Vishal Ranpariya
    Technical Account Manager | Sophos Technical Support

    Sophos Support Videos | Knowledge Base  |  @SophosSupport | Sign up for SMS Alerts |
    If a post solves your question use the 'This helped me' link.

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

    Regards

  • Hi : 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. 

    Regards,

    Vishal Ranpariya
    Technical Account Manager | Sophos Technical Support

    Sophos Support Videos | Knowledge Base  |  @SophosSupport | Sign up for SMS Alerts |
    If a post solves your question use the 'This helped me' link.