Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Issue: First time login through Bastion fails #592

Open
2 tasks done
ed-boykin opened this issue Oct 17, 2024 · 6 comments
Open
2 tasks done

Issue: First time login through Bastion fails #592

ed-boykin opened this issue Oct 17, 2024 · 6 comments
Labels
bug Something isn't working pam

Comments

@ed-boykin
Copy link

Is there an existing issue for this?

  • I have searched the existing issues and found none that matched mine

Describe the issue

After setting up authd and the EntraID broker, new users cannot login for the first time via Azure Bastion via SSH or RDP

Steps to reproduce

1 Create Ubuntu 24.04 VM on Azure
2. Setup Authd and EntraID broker per dcoumentation wiki.
3. Attempt to login to VM via AzureBastion host.
4. Login will fail
From different VM on same network, attempt SSH to new VM. Login will succeed.
At this point, the RDP or SSH Bastion login will also work.

System information and logs

authd version

authd	0.3.6

authd-msentraid broker version

name:      authd-msentraid
summary:   MSEntra ID broker for authd
publisher: Canonical**
store-url: https://snapcraft.io/authd-msentraid
license:   GPL-3.0
description: |
  This is the MS Entra ID broker snap for authd  to provide MS Entra ID OIDC
  based authentication on Ubuntu with authd.
services:
  authd-msentraid: simple, enabled, active
snap-id:      vS3oJLMss6lgWwoFcPqYDUA2HB20I1Dc
tracking:     0.x/stable
refresh-date: today at 11:32 UTC
channels:
  0.x/stable:    0.1+4fe9826.0f76acc 2024-10-02 (51) 18MB -
  0.x/candidate: ^                                        
  0.x/beta:      ^                                        
  0.x/edge:      0.1+5e01aca.0229b6d 2024-10-15 (58) 18MB -
installed:       0.1+4fe9826.0f76acc            (51) 18MB -

gnome-shell version

gnome-shell:
  Installed: 46.3.1-1ubuntu1~24.04.1authd2
  Candidate: 46.3.1-1ubuntu1~24.04.1authd2
  Version table:
 *** 46.3.1-1ubuntu1~24.04.1authd2 500
        500 https://ppa.launchpadcontent.net/ubuntu-enterprise-desktop/authd/ubuntu noble/main amd64 Packages
        100 /var/lib/dpkg/status
     46.0-0ubuntu6~24.04.5 500
        500 http://azure.archive.ubuntu.com/ubuntu noble-updates/main amd64 Packages
     46.0-0ubuntu6~24.04.3 500
        500 http://azure.archive.ubuntu.com/ubuntu noble-security/main amd64 Packages
     46.0-0ubuntu5 500
        500 http://azure.archive.ubuntu.com/ubuntu noble/main amd64 Packages

Distribution

Distributor ID:	Ubuntu
Description:	Ubuntu 24.04.1 LTS
Release:	24.04
Codename:	noble

Logs

[  543.064356] authdtest systemd[1]: Starting authd.service - Authd daemon service...
[  543.103068] authdtest systemd[1]: Started authd.service - Authd daemon service.
[  589.952928] authdtest systemd[1]: Started snap.authd-msentraid.authd-msentraid.service - Service for snap application authd-msentraid.authd-msentraid.
[  590.350933] authdtest authd-msentraid.authd-msentraid[6256]: time=2024-10-17T11:32:32.270Z level=ERROR msg="config file has invalid values, did you edit the file \"/var/snap/authd-msentraid/51/broker.conf\"?\nfound invalid character in section \"oidc\", key \"issuer\"\nfound invalid character in section \"oidc\", key \"client_id\""
[  590.352617] authdtest systemd[1]: snap.authd-msentraid.authd-msentraid.service: Main process exited, code=exited, status=1/FAILURE
[  590.352723] authdtest systemd[1]: snap.authd-msentraid.authd-msentraid.service: Failed with result 'exit-code'.
[  590.577716] authdtest systemd[1]: snap.authd-msentraid.authd-msentraid.service: Scheduled restart job, restart counter is at 1.
[  590.588312] authdtest systemd[1]: Started snap.authd-msentraid.authd-msentraid.service - Service for snap application authd-msentraid.authd-msentraid.
[  590.609492] authdtest authd-msentraid.authd-msentraid[6283]: time=2024-10-17T11:32:32.530Z level=ERROR msg="config file has invalid values, did you edit the file \"/var/snap/authd-msentraid/51/broker.conf\"?\nfound invalid character in section \"oidc\", key \"issuer\"\nfound invalid character in section \"oidc\", key \"client_id\""
[  590.610569] authdtest systemd[1]: snap.authd-msentraid.authd-msentraid.service: Main process exited, code=exited, status=1/FAILURE
[  590.610662] authdtest systemd[1]: snap.authd-msentraid.authd-msentraid.service: Failed with result 'exit-code'.
[  590.828153] authdtest systemd[1]: snap.authd-msentraid.authd-msentraid.service: Scheduled restart job, restart counter is at 2.
[  590.837340] authdtest systemd[1]: Started snap.authd-msentraid.authd-msentraid.service - Service for snap application authd-msentraid.authd-msentraid.
[  590.858392] authdtest authd-msentraid.authd-msentraid[6308]: time=2024-10-17T11:32:32.779Z level=ERROR msg="config file has invalid values, did you edit the file \"/var/snap/authd-msentraid/51/broker.conf\"?\nfound invalid character in section \"oidc\", key \"issuer\"\nfound invalid character in section \"oidc\", key \"client_id\""
[  590.859625] authdtest systemd[1]: snap.authd-msentraid.authd-msentraid.service: Main process exited, code=exited, status=1/FAILURE
[  590.859748] authdtest systemd[1]: snap.authd-msentraid.authd-msentraid.service: Failed with result 'exit-code'.
[  591.078118] authdtest systemd[1]: snap.authd-msentraid.authd-msentraid.service: Scheduled restart job, restart counter is at 3.
[  591.088303] authdtest systemd[1]: Started snap.authd-msentraid.authd-msentraid.service - Service for snap application authd-msentraid.authd-msentraid.
[  591.110219] authdtest authd-msentraid.authd-msentraid[6333]: time=2024-10-17T11:32:33.031Z level=ERROR msg="config file has invalid values, did you edit the file \"/var/snap/authd-msentraid/51/broker.conf\"?\nfound invalid character in section \"oidc\", key \"issuer\"\nfound invalid character in section \"oidc\", key \"client_id\""
[  591.111292] authdtest systemd[1]: snap.authd-msentraid.authd-msentraid.service: Main process exited, code=exited, status=1/FAILURE
[  591.111391] authdtest systemd[1]: snap.authd-msentraid.authd-msentraid.service: Failed with result 'exit-code'.
[  591.328332] authdtest systemd[1]: snap.authd-msentraid.authd-msentraid.service: Scheduled restart job, restart counter is at 4.
[  591.337318] authdtest systemd[1]: Started snap.authd-msentraid.authd-msentraid.service - Service for snap application authd-msentraid.authd-msentraid.
[  591.359756] authdtest authd-msentraid.authd-msentraid[6358]: time=2024-10-17T11:32:33.280Z level=ERROR msg="config file has invalid values, did you edit the file \"/var/snap/authd-msentraid/51/broker.conf\"?\nfound invalid character in section \"oidc\", key \"issuer\"\nfound invalid character in section \"oidc\", key \"client_id\""
[  591.360811] authdtest systemd[1]: snap.authd-msentraid.authd-msentraid.service: Main process exited, code=exited, status=1/FAILURE
[  591.360901] authdtest systemd[1]: snap.authd-msentraid.authd-msentraid.service: Failed with result 'exit-code'.
[  591.578028] authdtest systemd[1]: snap.authd-msentraid.authd-msentraid.service: Scheduled restart job, restart counter is at 5.
[  591.578320] authdtest systemd[1]: snap.authd-msentraid.authd-msentraid.service: Start request repeated too quickly.
[  591.578373] authdtest systemd[1]: snap.authd-msentraid.authd-msentraid.service: Failed with result 'exit-code'.
[  591.578416] authdtest systemd[1]: Failed to start snap.authd-msentraid.authd-msentraid.service - Service for snap application authd-msentraid.authd-msentraid.
[  801.762809] authdtest authd[5311]: 2024/10/17 11:36:03 WARN rpc error: code = NotFound desc =
[  848.749022] authdtest systemd[1]: Stopping authd.service - Authd daemon service...
[  848.750434] authdtest systemd[1]: authd.service: Deactivated successfully.
[  848.750663] authdtest systemd[1]: Stopped authd.service - Authd daemon service.
[  848.759577] authdtest systemd[1]: Starting authd.service - Authd daemon service...
[  848.788316] authdtest systemd[1]: Started authd.service - Authd daemon service.
[  858.577410] authdtest systemd[1]: Started snap.authd-msentraid.authd-msentraid.service - Service for snap application authd-msentraid.authd-msentraid.
[  888.642299] authdtest authd[6492]: 2024/10/17 11:37:30 WARN rpc error: code = NotFound desc =
[ 1101.770419] authdtest authd[6492]: 2024/10/17 11:41:03 WARN rpc error: code = NotFound desc =
[ 1182.630805] authdtest authd[6492]: 2024/10/17 11:42:24 WARN rpc error: code = NotFound desc =
[ 1187.956562] authdtest authd[6492]: 2024/10/17 11:42:29 WARN rpc error: code = NotFound desc =
[ 1215.892423] authdtest gdm-authd][6634]: gkr-pam: unable to locate daemon control file
[ 1215.892721] authdtest gdm-authd][6634]: gkr-pam: stashed password to try later in open session
[ 1247.260169] authdtest authd[6492]: 2024/10/17 11:43:29 WARN rpc error: code = NotFound desc =
[ 1249.846714] authdtest authd[6492]: 2024/10/17 11:43:31 WARN rpc error: code = NotFound desc =
[ 1401.778366] authdtest authd[6492]: 2024/10/17 11:46:03 WARN rpc error: code = NotFound desc =
[ 1701.785967] authdtest authd[6492]: 2024/10/17 11:51:03 WARN rpc error: code = NotFound desc =
[ 1986.106510] authdtest gdm-authd][6872]: gkr-pam: unable to locate daemon control file
[ 1986.107221] authdtest gdm-authd][6872]: gkr-pam: stashed password to try later in open session
[ 2001.793337] authdtest authd[6492]: 2024/10/17 11:56:03 WARN rpc error: code = NotFound desc =
[ 2034.106478] authdtest systemd[1]: Stopping snap.authd-msentraid.authd-msentraid.service - Service for snap application authd-msentraid.authd-msentraid...
[ 2034.108134] authdtest systemd[1]: snap.authd-msentraid.authd-msentraid.service: Deactivated successfully.
[ 2034.108326] authdtest systemd[1]: Stopped snap.authd-msentraid.authd-msentraid.service - Service for snap application authd-msentraid.authd-msentraid.
[ 2034.126388] authdtest systemd[1]: Started snap.authd-msentraid.authd-msentraid.service - Service for snap application authd-msentraid.authd-msentraid.
[ 2034.149241] authdtest authd-msentraid.authd-msentraid[7208]: time=2024-10-17T11:56:36.070Z level=INFO msg="No configuration file: Config File \"authd-msentraid\" Not Found in \"[/var/snap/authd-msentraid/51 /root/snap/authd-msentraid/51 /etc/authd-msentraid /snap/authd-msentraid/51/bin]\".\nWe will only use the defaults, env variables or flags."
[ 2034.149611] authdtest authd-msentraid.authd-msentraid[7208]: time=2024-10-17T11:56:36.070Z level=DEBUG msg="Debug mode is enabled"
[ 2034.213891] authdtest authd-msentraid.authd-msentraid[7208]: time=2024-10-17T11:56:36.134Z level=DEBUG msg="Building new daemon"
[ 2034.213891] authdtest authd-msentraid.authd-msentraid[7208]: time=2024-10-17T11:56:36.134Z level=DEBUG msg="Starting to serve requests"
[ 2034.213891] authdtest authd-msentraid.authd-msentraid[7208]: time=2024-10-17T11:56:36.134Z level=INFO msg="Serving requests as com.ubuntu.authd.MSEntraID"
[ 2056.511552] authdtest authd[6492]: 2024/10/17 11:56:58 WARN rpc error: code = NotFound desc =
[ 2120.037282] authdtest authd[6492]: 2024/10/17 11:58:01 WARN rpc error: code = NotFound desc =
[ 2125.931103] authdtest authd[6492]: 2024/10/17 11:58:07 WARN rpc error: code = NotFound desc =
[ 2187.386028] authdtest systemd[1]: Stopping authd.service - Authd daemon service...
[ 2187.388169] authdtest systemd[1]: authd.service: Deactivated successfully.
[ 2187.388251] authdtest systemd[1]: Stopped authd.service - Authd daemon service.
[ 2187.394331] authdtest systemd[1]: Starting authd.service - Authd daemon service...
[ 2187.412755] authdtest authd[7607]: INFO Using configuration file: /etc/authd/authd.yaml
[ 2187.413104] authdtest authd[7607]: DEBUG Verbosity: 2
[ 2187.413104] authdtest authd[7607]: DEBUG Building authd object
[ 2187.413104] authdtest authd[7607]: DEBUG Building broker detection
[ 2187.413983] authdtest authd[7607]: DEBUG Auto-detecting brokers
[ 2187.413983] authdtest authd[7607]: DEBUG Loading broker from "/etc/authd/brokers.d/msentraid.conf"
[ 2187.414083] authdtest authd[7607]: DEBUG Dbus broker configuration at "/etc/authd/brokers.d/msentraid.conf"
[ 2187.414083] authdtest authd[7607]: 2024/10/17 11:59:09 DEBUG Creating user manager with config: {UIDMin:1000000000 UIDMax:1999999999 GIDMin:1000000000 GIDMax:1999999999}
[ 2187.418196] authdtest authd[7607]: 2024/10/17 11:59:09 DEBUG Cleaning up orphaned user records
[ 2187.421950] authdtest authd[7607]: 2024/10/17 11:59:09 DEBUG Done cleaning up orphaned user records
[ 2187.421950] authdtest authd[7607]: DEBUG Building new GRPC NSS service
[ 2187.421950] authdtest authd[7607]: DEBUG Building new GRPC PAM service
[ 2187.422058] authdtest authd[7607]: DEBUG Building new daemon
[ 2187.422058] authdtest authd[7607]: DEBUG Use socket activation
[ 2187.422058] authdtest authd[7607]: DEBUG Registering GRPC services
[ 2187.422058] authdtest authd[7607]: DEBUG Starting to serve requests on /run/authd.sock
[ 2187.422200] authdtest authd[7607]: DEBUG Ready state sent to systemd
[ 2187.422200] authdtest authd[7607]: INFO Serving GRPC requests on /run/authd.sock
[ 2187.422265] authdtest systemd[1]: Started authd.service - Authd daemon service.
[ 2213.183551] authdtest authd[7607]: 2024/10/17 11:59:35 WARN rpc error: code = NotFound desc =
[ 2213.183872] authdtest authd[7607]: DEBUG User "[email protected]" is unknown
[ 2301.800699] authdtest authd[7607]: 2024/10/17 12:01:03 WARN rpc error: code = NotFound desc =
[ 2322.462618] authdtest authd[7607]: 2024/10/17 12:01:24 WARN rpc error: code = NotFound desc =
[ 2322.462933] authdtest authd[7607]: DEBUG User "###.#####@#####.com" is unknown

authd broker configuration

/etc/authd/brokers.d/msentraid.conf

# This section is used by authd to identify and communicate with the broker.
# It should not be edited.
[authd]
name = Microsoft Entra ID
brand_icon = /snap/authd-msentraid/current/broker_icon.png
dbus_name = com.ubuntu.authd.MSEntraID
dbus_object = /com/ubuntu/authd/MSEntraID

authd-msentraid configuration

[oidc]
issuer = https://login.microsoftonline.com/<UUID redacted>/v2.0
client_id = <UUID redacted> 

[users]
# The directory where the home directory will be created for new users.
# Existing users will keep their current directory.
# The user home directory will be created in the format of {home_base_dir}/{username}
home_base_dir = /home

# The username suffixes that are allowed to login via ssh without existing previously in the system.
# The suffixes must be separated by commas.
ssh_allowed_suffixes = @XXXXX.com

Double check your logs

  • I have redacted any sensitive information from the logs
@ed-boykin ed-boykin added the bug Something isn't working label Oct 17, 2024
@ed-boykin
Copy link
Author

ed-boykin commented Nov 7, 2024

A big more info, I didnt have the debug info set quite right but now I do and here's more info about what happens when I try to login using authd from an Azure Bastion host

Nov 07 18:38:53 authd xrdp[5067]: [ERROR] xrdp_rdp_recv: xrdp_channel_process failed
Nov 07 18:38:57 authd xrdp[5067]: [INFO ] connecting to sesman on 127.0.0.1:3350
Nov 07 18:38:57 authd xrdp-sesman[1194]: [INFO ] Socket 13: AF_INET6 connection received from ::1 port 34608
Nov 07 18:38:57 authd xrdp[5067]: [INFO ] xrdp_wm_log_msg: sesman connect ok
Nov 07 18:38:57 authd xrdp[5067]: [INFO ] sesman connect ok
Nov 07 18:38:57 authd xrdp[5067]: [INFO ] sending login info to session manager. Please wait...
Nov 07 18:38:57 authd authd-pam[5165]: adapter.userSelected{username:"###REDACTED###"}
Nov 07 18:38:57 authd authd-pam[5165]: Native model update: adapter.userSelected{username:"###REDACTED###"}
Nov 07 18:38:57 authd authd-pam[5165]: adapter.supportedUILayoutsReceived{layouts:[]*authd.UILayout{(*authd.UILayout)(0xc0001a79d0), (*authd.UILayout)(0xc0001a7a40), (*a>
Nov 07 18:38:57 authd authd-pam[5165]: Native model update: adapter.supportedUILayoutsReceived{layouts:[]*authd.UILayout{(*authd.UILayout)(0xc0001a79d0), (*authd.UILayou>
Nov 07 18:38:57 authd authd-pam[5165]: adapter.UsernameOrBrokerListReceived{}
Nov 07 18:38:57 authd authd-pam[5165]: adapter.GetAuthenticationModesRequested{}
Nov 07 18:38:57 authd authd-pam[5165]: adapter.brokersListReceived{brokers:[]*authd.ABResponse_BrokerInfo{(*authd.ABResponse_BrokerInfo)(0xc0000c0140), (*authd.ABRespons>
Nov 07 18:38:57 authd authd-pam[5165]: Native model update: adapter.brokersListReceived{brokers:[]*authd.ABResponse_BrokerInfo{(*authd.ABResponse_BrokerInfo)(0xc0000c014>
Nov 07 18:38:57 authd authd-pam[5165]: adapter.UsernameOrBrokerListReceived{}
Nov 07 18:38:57 authd authd[1146]: 2024/11/07 18:38:57 WARN rpc error: code = NotFound desc =
Nov 07 18:38:57 authd authd[1146]: DEBUG User "###REDACTED###" is unknown
Nov 07 18:38:57 authd authd-pam[5165]: Native model update: adapter.brokerSelectionRequired{}
Nov 07 18:38:57 authd authd-pam[5165]: Native model update: tea.sequenceMsg{(tea.Cmd)(0x56fd77ae2d80), (tea.Cmd)(0x56fd77aef160)}
Nov 07 18:38:57 authd authd-pam[5165]: adapter.ChangeStage{Stage:1}
Nov 07 18:38:57 authd authd-pam[5165]: Native model update: adapter.nativeAsyncOperationCompleted{}
Nov 07 18:38:57 authd authd-pam[5165]: Native model update: tea.sequenceMsg{(tea.Cmd)(0x56fd77aec7a0), (tea.Cmd)(nil), (tea.Cmd)(nil)}
Nov 07 18:38:57 authd authd-pam[5165]: Native model update: adapter.nativeStageChangeRequest{Stage:1}
Nov 07 18:38:57 authd authd-pam[5165]: Native model update: adapter.nativeChangeStage{Stage:1}
Nov 07 18:38:57 authd authd-pam[5165]: Native model update: tea.sequenceMsg{(tea.Cmd)(0x56fd77aef3e0), (tea.Cmd)(0x56fd77aef360)}
Nov 07 18:38:57 authd authd-pam[5165]: adapter.ChangeStage{Stage:1}
Nov 07 18:38:57 authd xrdp-sesman[1194]: [ERROR] Unhandled message in verify_pam_conv { style = PAM_PROMPT_ECHO_ON, msg = "== Broker selection ==
                                         1 - local
                                         2 - Microsoft Entra ID
                                         Select broker: " }
Nov 07 18:38:57 authd authd-pam[5165]: Native model update: adapter.nativeBrokerSelection{}
Nov 07 18:38:57 authd authd-pam[5165]: Native model update: tea.sequenceMsg{(tea.Cmd)(nil), (tea.Cmd)(nil)}
Nov 07 18:38:57 authd xrdp-sesman[1194]: pam_authd_exec(xrdp-sesman:auth): conversation failed
Nov 07 18:38:57 authd authd-pam[5165]: failed to call com.ubuntu.authd.pam.Prompt: Conversation error
Nov 07 18:38:57 authd authd-pam[5165]: Native model update: tea.sequenceMsg{(tea.Cmd)(0x56fd77ae2d80), (tea.Cmd)(0x56fd77af07c0)}
Nov 07 18:38:57 authd authd-pam[5165]: Native model update: adapter.nativeAsyncOperationCompleted{}
Nov 07 18:38:57 authd authd-pam[5165]: adapter.pamError{status:4, msg:"broker selection error: <nil>: Conversation error"}
Nov 07 18:38:57 authd xrdp-sesman[1194]: [ERROR] PAM: broker selection error: <nil>: Conversation error
Nov 07 18:38:57 authd authd-pam[5165]: AUTH: exiting with error System error: broker selection error: <nil>: Conversation error
Nov 07 18:38:57 authd xrdp-sesman[1194]: [ERROR] pam_authenticate failed: System error
Nov 07 18:38:57 authd xrdp-sesman[1194]: [INFO ] AUTHFAIL: user=###REDACTED### ip=::ffff:10.47.1.132 time=1731004737
Nov 07 18:38:57 authd xrdp-sesman[1194]: [ERROR] sesman_data_in: scp_process_msg failed
Nov 07 18:38:57 authd xrdp[5067]: [INFO ] xrdp_wm_log_msg: login failed for user ###REDACTED###
Nov 07 18:38:57 authd xrdp-sesman[1194]: [ERROR] sesman_main_loop: trans_check_wait_objs failed, removing trans
Nov 07 18:38:57 authd xrdp[5067]: [INFO ] login failed for user ###REDACTED###
Nov 07 18:39:02 authd sudo[5176]: edboykin : TTY=pts/2 ; PWD=/home/######; USER=root ; 

So, it looks like its failing because I cant respsond to the broker selection. Is there a way to force it default to EntraId?

@3v1n0
Copy link
Collaborator

3v1n0 commented Nov 8, 2024

Nov 07 18:38:57 authd xrdp-sesman[1194]: [ERROR] Unhandled message in verify_pam_conv { style = PAM_PROMPT_ECHO_ON, msg = "== Broker selection ==
1 - local
2 - Microsoft Entra ID
Select broker: " }

It seems your PAM client doesn't handle the PAM conversation properly... In particular xrdp-sesman. So it seems that it needs some work.

@3v1n0
Copy link
Collaborator

3v1n0 commented Nov 8, 2024

Ok so such client does not support the PAM_PROMPT_ECHO_ON conversations, so those where the input is shown to the user.

As workaround, maybe, we may just always use PAM_PROMPT_ECHO_OFF conversations in this client, although that is the one that really needs fix.

@3v1n0 3v1n0 added the pam label Nov 8, 2024
@ed-boykin
Copy link
Author

OK, the issue is with xrdp not handling the PAM_PROMPT_ECHO_ON at all. A possible workaround could be implemented from the authd side but the better solution is for srdp to handle the message and interaction. Thanks for looking into this! I'll submit a feature request to the xrdp project.

@ed-boykin
Copy link
Author

Ok, looks like xrdp isn't going update any time soon with this functionality :( . Any chance for the Authd workaround to be done?

@3v1n0
Copy link
Collaborator

3v1n0 commented Nov 8, 2024

Well it's still a bit problematic because I feel that even doing it, xrdp wouldn't support multiple requests...

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working pam
Projects
None yet
Development

No branches or pull requests

2 participants