Yubico PAM integration doesn't work w/ Teleport

[deusxanima]

Description

What happened:
Attempting to configure pam_yubico integration with teleport leads to all auth attempts failing when attempted through Teleport. Integration works fine, however, through standard OpenSSH. It appears that Teleport is injecting an extra byte or character which leads to pam_yubico module to swallow the first byte in order to fit the 12/32 token_id/otp expected response.

What you expected to happen:
pam_yubico integration should work with teleport PAM auth.

Reproduction Steps

As minimally and precisely as possible, describe step-by-step how to reproduce the problem.
1.
2.
3.

Server Details

• Teleport version (run teleport version): 9.0.4
• Server OS (e.g. from /etc/os-release): Ubuntu 20.04
• Where are you running Teleport? (e.g. AWS, GCP, Dedicated Hardware): EC2/VM
• Additional details:

PAM Auth File:

#configuration for the Secure Shell service

# Standard Un*x authentication.
# @include common-auth
#auth [success=1 default=ignore] /lib64/security/pam_duo.so
#auth requisite pam_deny.so
#auth required pam_permit.so
auth required pam_yubico.so id=my_id key=my_key debug debug_file=/var/run/pam-debug.log authfile=/etc/pam.d/authorized_yubikeys
auth    [success=1 default=ignore]      pam_unix.so nullok_secure try_first_pass
auth requisite pam_deny.so

# # Disallow non-root logins when /etc/nologin exists.
# account    required     pam_nologin.so
#
# # Uncomment and edit /etc/security/access.conf if you need to set complex
# # access limits that are hard to express in sshd_config.
# # account  required     pam_access.so
#
# # Standard Un*x authorization.
 @include common-account
#
# # SELinux needs to be the first session rule.  This ensures that any
# # lingering context has been cleared.  Without this it is possible that a
# # module could execute code in the wrong domain.
 session [success=ok ignore=ignore module_unknown=ignore default=bad]        pam_selinux.so close
#
# # Set the loginuid process attribute.
 session    required     pam_loginuid.so
#
# # Create a new session keyring.
 session    optional     pam_keyinit.so force revoke
#
# # Standard Un*x session setup and teardown.
 @include common-session
#
# # Print the message of the day upon successful login.
# # This includes a dynamically generated part from /run/motd.dynamic
# # and a static (admin-editable) part from /etc/motd.
 session    optional     pam_motd.so  #motd=/run/motd.dynamic
# session    optional     pam_motd.so noupdate
#
# # Print the status of the user's mailbox upon successful login.
 session    optional     pam_mail.so standard noenv # [1]
#
# # Set up user limits from /etc/security/limits.conf.
 session    required     pam_limits.so
#
# # Read environment variables from /etc/environment and
# # /etc/security/pam_env.conf.
 session    required     pam_env.so # [1]
# # In Debian 4.0 (etch), locale-related environment variables were moved to
# # /etc/default/locale, so read that as well.
 session    required     pam_env.so user_readenv=1 envfile=/etc/default/locale
#
# # SELinux needs to intervene at login time to ensure that the process starts
# # in the proper default security context.  Only sessions which are intended
# # to run in the user's context should be run after this.
 session [success=ok ignore=ignore module_unknown=ignore default=bad]        pam_selinux.so open
#
# # Standard Un*x password updating.
 @include common-password

PAM Auth File:

user:abcd

Client Details

• Tsh version (tsh version): 9.0.4
• Computer OS (e.g. Linux, macOS, Windows): macOS
• Browser version (for UI-related issues): Brave/Chrome/Safari/Firefox

Debug Logs

PAM Logs:

debug: pam_yubico.c:933 (parse_cfg): called.
debug: pam_yubico.c:934 (parse_cfg): flags 0 argc 5
debug: pam_yubico.c:936 (parse_cfg): argv[0]=id=my_id
debug: pam_yubico.c:936 (parse_cfg): argv[1]=key=my_key
debug: pam_yubico.c:936 (parse_cfg): argv[2]=debug
debug: pam_yubico.c:936 (parse_cfg): argv[3]=debug_file=/var/run/pam-debug.log
debug: pam_yubico.c:936 (parse_cfg): argv[4]=authfile=/etc/pam.d/authorized_yubikeys
debug: pam_yubico.c:937 (parse_cfg): id=74082
debug: pam_yubico.c:938 (parse_cfg): key=my_key
debug: pam_yubico.c:939 (parse_cfg): debug=1
debug: pam_yubico.c:940 (parse_cfg): debug_file=13
debug: pam_yubico.c:941 (parse_cfg): alwaysok=0
debug: pam_yubico.c:942 (parse_cfg): verbose_otp=0
debug: pam_yubico.c:943 (parse_cfg): try_first_pass=0
debug: pam_yubico.c:944 (parse_cfg): use_first_pass=0
debug: pam_yubico.c:945 (parse_cfg): always_prompt=0
debug: pam_yubico.c:946 (parse_cfg): nullok=0
debug: pam_yubico.c:947 (parse_cfg): ldap_starttls=0
debug: pam_yubico.c:948 (parse_cfg): ldap_bind_as_user=0
debug: pam_yubico.c:949 (parse_cfg): authfile=/etc/pam.d/authorized_yubikeys
debug: pam_yubico.c:950 (parse_cfg): ldapserver=(null)
debug: pam_yubico.c:951 (parse_cfg): ldap_uri=(null)
debug: pam_yubico.c:952 (parse_cfg): ldap_bind_user=(null)
debug: pam_yubico.c:953 (parse_cfg): ldap_bind_password=(null)
debug: pam_yubico.c:954 (parse_cfg): ldap_filter=(null)
debug: pam_yubico.c:955 (parse_cfg): ldap_cacertfile=(null)
debug: pam_yubico.c:956 (parse_cfg): ldapdn=(null)
debug: pam_yubico.c:957 (parse_cfg): ldap_clientcertfile=(null)
debug: pam_yubico.c:958 (parse_cfg): ldap_clientkeyfile=(null)
debug: pam_yubico.c:959 (parse_cfg): user_attr=(null)
debug: pam_yubico.c:960 (parse_cfg): yubi_attr=(null)
debug: pam_yubico.c:961 (parse_cfg): yubi_attr_prefix=(null)
debug: pam_yubico.c:962 (parse_cfg): url=(null)
debug: pam_yubico.c:963 (parse_cfg): urllist=(null)
debug: pam_yubico.c:964 (parse_cfg): capath=(null)
debug: pam_yubico.c:965 (parse_cfg): cainfo=(null)
debug: pam_yubico.c:966 (parse_cfg): proxy=(null)
debug: pam_yubico.c:967 (parse_cfg): token_id_length=12
debug: pam_yubico.c:968 (parse_cfg): mode=client
debug: pam_yubico.c:969 (parse_cfg): chalresp_path=(null)
debug: pam_yubico.c:970 (parse_cfg): mysql_server=(null)
debug: pam_yubico.c:971 (parse_cfg): mysql_port=0
debug: pam_yubico.c:972 (parse_cfg): mysql_user=(null)
debug: pam_yubico.c:973 (parse_cfg): mysql_database=(null)
debug: pam_yubico.c:1009 (pam_sm_authenticate): pam_yubico version: 2.27
debug: pam_yubico.c:1024 (pam_sm_authenticate): get user returned: user
debug: pam_yubico.c:190 (authorize_user_token): Using system-wide auth_file /etc/pam.d/authorized_yubikeys
debug: util.c:351 (check_user_token): Authorization line: user:abcd
debug: util.c:356 (check_user_token): Matched user: user
debug: util.c:362 (check_user_token): Authorization token: abcd
debug: util.c:362 (check_user_token): Authorization token: (null)
debug: pam_yubico.c:1146 (pam_sm_authenticate): Tokens found for user
debug: pam_yubico.c:1209 (pam_sm_authenticate): conv returned 45 bytes
debug: pam_yubico.c:1223 (pam_sm_authenticate): Skipping first 1 bytes. Length is 45, token_id set to 12 and token OTP always 32.
debug: pam_yubico.c:1243 (pam_sm_authenticate): Extracted a probable system password entered before the OTP - setting item PAM_AUTHTOK
debug: pam_yubico.c:190 (authorize_user_token): Using system-wide auth_file /etc/pam.d/authorized_yubikeys
debug: util.c:351 (check_user_token): Authorization line: user:abcd
debug: util.c:356 (check_user_token): Matched user: user
debug: util.c:362 (check_user_token): Authorization token: abcd
debug: util.c:362 (check_user_token): Authorization token: (null)
debug: pam_yubico.c:1292 (pam_sm_authenticate): Unauthorized token for this user
debug: pam_yubico.c:1337 (pam_sm_authenticate): done. [Authentication failure]

Teleport node logs:

Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [NODE:PROX] Handing off connection to a local "node" service. leaseID:1 target:rc.ateleport.cf:443 reversetunnel/transport.go:283
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [NODE]      conn(99.131.53.188:54128->172.31.89.172:50890, user=user) auth attempt fingerprint:[email protected] SHA256:khOqn4HAj1wDMfT3RrUu local:172.31.89.172:50890 remote:99.131.53.188:54128 user:user srv/authhandlers.go:230
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [NODE]      conn(99.131.53.188:54128->172.31.89.172:50890, user=user) auth attempt with key [email protected] SHA256:khOqn4HAj1wDMfT3RrUu, &ssh.Certificate{Nonce:[]uint8{0xf2, 0xd8, 0x76, 0x6, 0xcb, 0x70, 0x82, 0xbc, 0xe9, 0xb7, 0x7b, 0x4f, 0xd8, 0xda, 0xcc, 0xc4, 0x6a, 0x4f, 0x58, 0x4f, 0x4c, 0x1d, 0xea, 0x9e, 0x31, 0x3b, 0x72, 0x79, 0x7d, 0xcb, 0xc0, 0xae}, Key:(*ssh.rsaPublicKey)(0xc001a843e0), Serial:0x0, CertType:0x1, KeyId:"user", ValidPrincipals:[]string{"user"}, ValidAfter:0x6266f17f, ValidBefore:0x626895f2, Permissions:ssh.Permissions{CriticalOptions:map[string]string{}, Extensions:map[string]string{"permit-X11-forwarding":"", "permit-agent-forwarding":"", "permit-port-forwarding":"", "permit-pty":"", "teleport-roles":"{\"version\":\"v1\",\"roles\":[\"admin\"]}", "teleport-route-to-cluster":"ip-172-31-72-82-ec2-internal", "teleport-traits":"{\"at_hash\":[\"ManCdDHwG48LUL2IxIp_eA\"],\"aud\":[\"137662272699-gabolkl4ml1f5pkhe5jhg99jinu0cilr.apps.googleusercontent.com\"],\"azp\":[\"137662272699-gabolkl4ml1f5pkhe5jhg99jinu0cilr.apps.googleusercontent.com\"],\"email\":[\"user\"],\"family_name\":[\"Name\"],\"given_name\":[\"User\"],\"groups\":[\"admin\"],\"hd\":[\"test\"],\"iss\":[\"https://accounts.google.com\"],\"locale\":[\"en\"],\"name\":[\"User Name\"],\"picture\":[\"https://lh3.googleusercontent.com/a/AATXAJy2wmImhRXAkQz5a5XYmWce7Npo5O5oBz_z4ZOP=s96-c\"],\"sub\":[\"109322739229550318006\"]}"}}, Reserved:[]uint8{}, SignatureKey:(*ssh.rsaPublicKey)(0xc001a84420), Signature:(*ssh.Signature)(0xc001222680)} fingerprint:[email protected] SHA256:khOqn4HAj1wDMfT3RrUu local:172.31.89.172:50890 remote:99.131.53.188:54128 user:user srv/authhandlers.go:233
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [NODE]      Successfully authenticated fingerprint:[email protected] SHA256:khOqn4HAj1wDMfT3RrUu local:172.31.89.172:50890 remote:99.131.53.188:54128 user:user srv/authhandlers.go:293
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [NODE]      Checking permissions for (user) to login to node with RBAC checks. srv/authhandlers.go:422
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [RBAC]      Access to node "480777bd-cc65-4d8c-8f26-9ad46bdf8fef" granted, allow rule in role "admin" matched. services/role.go:1854
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [SSH:NODE]  Incoming connection 99.131.53.188:54128 -> 172.31.89.172:50890 version: SSH-2.0-Go, certtype: "user" sshutils/server.go:466
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [SSH:NODE]  Received out-of-band request: &{Type:x-teleport-version WantReply:true Payload:[] ch:<nil> mux:0xc00024d420}. sshutils/server.go:521
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [KEEPALIVE] Starting keep-alive loop with with interval 30s and max count 2. srv/keepalive.go:65
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [NODE]      Handling request env, want reply true. id:25 idle:30m0s local:172.31.89.172:50890 login:user remote:99.131.53.188:54128 teleportUser:user regular/sshserver.go:1398
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [NODE]      Handling request env, want reply true. id:25 idle:30m0s local:172.31.89.172:50890 login:user remote:99.131.53.188:54128 teleportUser:user regular/sshserver.go:1398
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU             Will create new session for SSH connection 99.131.53.188:54128. srv/ctx.go:512
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [NODE]      Handling request env, want reply true. id:25 idle:30m0s local:172.31.89.172:50890 login:user remote:99.131.53.188:54128 teleportUser:user regular/sshserver.go:1398
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU             Will create new session for SSH connection 99.131.53.188:54128. srv/ctx.go:512
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [NODE]      Handling request env, want reply true. id:25 idle:30m0s local:172.31.89.172:50890 login:user remote:99.131.53.188:54128 teleportUser:user regular/sshserver.go:1398
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU             Will create new session for SSH connection 99.131.53.188:54128. srv/ctx.go:512
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [NODE]      Handling request env, want reply true. id:25 idle:30m0s local:172.31.89.172:50890 login:user remote:99.131.53.188:54128 teleportUser:user regular/sshserver.go:1398
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU             Will create new session for SSH connection 99.131.53.188:54128. srv/ctx.go:512
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [NODE]      Handling request env, want reply true. id:25 idle:30m0s local:172.31.89.172:50890 login:user remote:99.131.53.188:54128 teleportUser:user regular/sshserver.go:1398
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU             Will create new session for SSH connection 99.131.53.188:54128. srv/ctx.go:512
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [NODE]      Handling request [email protected], want reply true. id:25 idle:30m0s local:172.31.89.172:50890 login:user remote:99.131.53.188:54128 teleportUser:user regular/sshserver.go:1398
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [NODE]      Starting agent server for Teleport user user and socket /tmp/teleport-1718047921/teleport-331472.socket. id:25 idle:30m0s local:172.31.89.172:50890 login:user remote:99.131.53.188:54128 teleportUser:user regular/sshserver.go:889
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU             Will create new session for SSH connection 99.131.53.188:54128. srv/ctx.go:512
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [NODE]      Handling request pty-req, want reply true. id:25 idle:30m0s local:172.31.89.172:50890 login:user remote:99.131.53.188:54128 teleportUser:user regular/sshserver.go:1398
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [NODE]      Requested terminal "xterm" of size {80 25} id:25 idle:30m0s local:172.31.89.172:50890 login:user remote:99.131.53.188:54128 teleportUser:user srv/termhandlers.go:73
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU             Set permissions on /dev/pts/25 to 1001:5 with mode -rw-------. srv/term.go:407
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [SESSION:N] Unable to update window size, no session found in context. srv/sess.go:445
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU             Will create new session for SSH connection 99.131.53.188:54128. srv/ctx.go:512
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [NODE]      Handling request shell, want reply true. id:25 idle:30m0s local:172.31.89.172:50890 login:user remote:99.131.53.188:54128 teleportUser:user regular/sshserver.go:1398
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [SESSION:N] Creating tracker srv/sess.go:1709
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z INFO [NODE]      Creating (interactive) session e6ab0541-591f-41aa-a7c2-68288f1d6b0d. id:25 idle:30m0s local:172.31.89.172:50890 login:user remote:99.131.53.188:54128 teleportUser:user srv/sess.go:223
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [SESSION:N] Using async streamer for session e6ab0541-591f-41aa-a7c2-68288f1d6b0d. srv/sess.go:1255
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [SESSION:N] Tracking participant: user srv/sess.go:1751
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z INFO [AUDIT]     session.start addr.remote:99.131.53.188:54128 cluster_name:ip-172-31-72-82-ec2-internal code:T2000I ei:0 event:session.start login:user namespace:default server_addr:172.31.89.172:50890 server_hostname:cloud-node server_id:480777bd-cc65-4d8c-8f26-9ad46bdf8fef server_labels:map[env:cloud hostname:ip-172-31-89-172] session_recording:node sid:e6ab0541-591f-41aa-a7c2-68288f1d6b0d size:80:25 time:2022-04-25T19:09:03.178Z uid:944a111d-772d-4fac-a50c-786592f3712c user:user events/emitter.go:325
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z INFO [SESSION:N] New party ServerContext(99.131.53.188:54128->172.31.89.172:50890, user=user, id=25) party(id=41c336a0-0f34-41f0-b2cf-c47029a0c474) joined session: e6ab0541-591f-41aa-a7c2-68288f1d6b0d srv/sess.go:1516
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU             Will join session e6ab0541-591f-41aa-a7c2-68288f1d6b0d for SSH connection 99.131.53.188:54128. srv/ctx.go:514
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [SESSION:N] Starting poll and sync of terminal size to all parties. srv/sess.go:1394
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [SESSION:N] Launching session e6ab0541-591f-41aa-a7c2-68288f1d6b0d. srv/sess.go:823
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU [NODE]      Handling request window-change, want reply false. id:25 idle:30m0s local:172.31.89.172:50890 login:user remote:99.131.53.188:54128 teleportUser:user regular/sshserver.go:1398
Apr 25 19:09:03 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:03Z DEBU             Will join session e6ab0541-591f-41aa-a7c2-68288f1d6b0d for SSH connection 99.131.53.188:54128. srv/ctx.go:514
**Apr 25 19:09:05 ip-172-31-89-172 teleport[395351]: pam_unix(teleport_pam_auth:auth): authentication failure; logname= uid=0 euid=0 tty= ruser= rhost=  user=user**
Apr 25 19:09:07 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:07Z DEBU [SESSION:N] Copying from PTY to writer completed with error read /dev/ptmx: input/output error. srv/sess.go:871
Apr 25 19:09:07 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:07Z DEBU [NODE]      Exec request ("/proc/331472/fd/3") complete: 255 id:25 idle:30m0s local:172.31.89.172:50890 login:user remote:99.131.53.188:54128 teleportUser:user regular/sshserver.go:1378
Apr 25 19:09:07 ip-172-31-89-172 teleport[331472]: 2022-04-25T19:09:07Z INFO [SESSION:N] Closing party 41c336a0-0f34-41f0-b2cf-c47029a0c474 srv/sess.go:1679

gz#4642

[deusxanima]

Circled back w/ end-user re: requirement for external MFA outside of Teleport-provided MFA. Response received is copied below:

With Teleport MFA we are trusting Teleport with MFA since a coding/config issue can disable/void the trigger (since it's all managed by teleport)
With OS/PAM MFA when if Teleport is compromised, OS will still block and unauthorized access. That's the difference to us.