OTP verification fails on AIX

[wrw1961]

We've compiled the project on AIX 7.1 had to include gnulib and run

./gnulib-tool --import getopt
./gnulib-tool --add-import getopt-gnu
./gnulib-tool --add-import vasprintf

and a couple other tweaks to compile sucessfully. running google-authenticator works and creates the .google_authenticator file

AIX uses /etc/pam.conf rather than /etc/pam.d/sshd in pam.conf added the second line

sshd    auth    required        pam_aix
sshd    auth    required        pam_google_authenticator.so nullok

at this point I can attempt to connect to the AIX server and receive the prompts you would expect

homer[sc2112] </home/sc2112> ssh  goob@gahost          
goob's Password:
Verification code: 
Connection closed by 192.168.14.75
homer[sc2112] </home/sc2112> 

The connection immediately closes. If I remove the users .google_authenticator file the connection succeeds, obviously without the "Verification code:" prompt.

In the syslog after the connection with verification code it has this

Jul  2 14:32:04 gahost auth|security:debug sshd: PAM: pam_start(sshd goob)
Jul  2 14:32:04 gahost auth|security:debug sshd: PAM: pam_set_item(1)
Jul  2 14:32:04 gahost auth|security:debug sshd: PAM: pam_set_item(2)
Jul  2 14:32:04 gahost auth|security:debug sshd: PAM: pam_set_item(5)
Jul  2 14:32:04 gahost auth|security:debug sshd: PAM: pam_set_item(4)
Jul  2 14:32:04 gahost auth|security:debug sshd: PAM: pam_set_item(5)
Jul  2 14:32:04 gahost auth|security:debug sshd: PAM: pam_authenticate()
Jul  2 14:32:04 gahost auth|security:debug sshd: PAM: load_modules: /usr/lib/security/pam_aix
Jul  2 14:32:04 gahost auth|security:debug sshd: PAM: load_function: successful load of pam_sm_authenticate
Jul  2 14:32:04 gahost auth|security:debug sshd: PAM: load_modules: /usr/lib/security/pam_google_authenticator.so
Jul  2 14:32:04 gahost auth|security:debug sshd: PAM: load_function: successful load of pam_sm_authenticate
Jul  2 14:32:07 gahost auth|security:debug sshd: PAM: pam_set_item(6)

Also, if I add more options to the pam.conf entry for google authenticator, for example

sshd auth required pam_google_authenticator.so nullok debug

The login process goes like this

homer[sc2112] </home/sc2112> ssh  wally@stryker
goob's Password:
goob's Password:
goob's Password:
goob@gahost's password: 
Connection closed by 192.168.14.75
homer[sc2112] </home/sc2112>

and the syslog has this

Jul  2 15:00:51 gahost auth|security:debug sshd: PAM: pam_start(sshd goob)
Jul  2 15:00:51 gahost auth|security:debug sshd: PAM: pam_set_item(1)
Jul  2 15:00:51 gahost auth|security:debug sshd: PAM: pam_set_item(2)
Jul  2 15:00:51 gahost auth|security:debug sshd: PAM: pam_set_item(5)
Jul  2 15:00:51 gahost auth|security:debug sshd: PAM: pam_set_item(4)
Jul  2 15:00:51 gahost auth|security:debug sshd: PAM: pam_set_item(5)
Jul  2 15:00:51 gahost auth|security:debug sshd: PAM: pam_authenticate()
Jul  2 15:00:51 gahost auth|security:debug sshd: PAM: load_modules: /usr/lib/security/pam_aix
Jul  2 15:00:51 gahost auth|security:debug sshd: PAM: load_function: successful load of pam_sm_authenticate
Jul  2 15:00:51 gahost auth|security:debug sshd: PAM: load_modules: /usr/lib/security/pam_google_authenticator.so
Jul  2 15:00:51 gahost auth|security:debug sshd: PAM: load_function: successful load of pam_sm_authenticate
Jul  2 15:00:54 gahost auth|security:debug sshd: PAM: pam_set_item(6)
Jul  2 15:00:54 gahost auth|security:info syslog: ssh: failed login attempt for goob from homer
Jul  2 15:00:54 gahost auth|security:debug sshd: PAM: pam_set_item(5)
Jul  2 15:00:54 gahost auth|security:debug sshd: PAM: pam_authenticate()
Jul  2 15:00:54 gahost auth|security:debug sshd: PAM: load_modules: /usr/lib/security/pam_aix
Jul  2 15:00:54 gahost auth|security:debug sshd: PAM: load_function: successful load of pam_sm_authenticate
Jul  2 15:00:54 gahost auth|security:debug sshd: PAM: load_modules: /usr/lib/security/pam_google_authenticator.so
Jul  2 15:00:54 gahost auth|security:debug sshd: PAM: load_function: successful load of pam_sm_authenticate
Jul  2 15:00:58 gahost auth|security:debug sshd: PAM: pam_set_item(6)
Jul  2 15:00:58 gahost auth|security:info syslog: ssh: failed login attempt for goob from homer
Jul  2 15:00:58 gahost auth|security:debug sshd: PAM: pam_set_item(5)
Jul  2 15:00:58 gahost auth|security:debug sshd: PAM: pam_authenticate()
Jul  2 15:00:58 gahost auth|security:debug sshd: PAM: load_modules: /usr/lib/security/pam_aix
Jul  2 15:00:58 gahost auth|security:debug sshd: PAM: load_function: successful load of pam_sm_authenticate
Jul  2 15:00:58 gahost auth|security:debug sshd: PAM: load_modules: /usr/lib/security/pam_google_authenticator.so
Jul  2 15:00:58 gahost auth|security:debug sshd: PAM: load_function: successful load of pam_sm_authenticate
Jul  2 15:01:00 gahost auth|security:debug sshd: PAM: pam_set_item(6)
Jul  2 15:01:01 gahost auth|security:info syslog: ssh: failed login attempt for goob from homer
Jul  2 15:01:04 gahost auth|security:debug sshd: PAM: pam_set_item(5)
Jul  2 15:01:04 gahost auth|security:debug sshd: PAM: pam_authenticate()
Jul  2 15:01:04 gahost auth|security:debug sshd: PAM: load_modules: /usr/lib/security/pam_aix
Jul  2 15:01:04 gahost auth|security:debug sshd: PAM: load_function: successful load of pam_sm_authenticate
Jul  2 15:01:04 gahost auth|security:debug sshd: PAM: load_modules: /usr/lib/security/pam_google_authenticator.so
Jul  2 15:01:04 gahost auth|security:debug sshd: PAM: load_function: successful load of pam_sm_authenticate
Jul  2 15:01:04 gahost auth|security:debug sshd: PAM: pam_set_item(6)

Any ideas how to fix this would be appreciated.

[ThomasHabets]

Sorry for the late reply.

That's really odd. You're sure that adding debug causes Verification code to no longer be prompted for? Could you double-check?

None of the log messages you show are from pam_pam_authenticator.so, so debug isn't working. You're using the code from github, not an older version?

Could you look for more logs? Maybe more is logged elsewhere?

Oh, and double-check that you're using the correct syntax for pam.conf, in case it's different on AIX. It's curious that pam_aix doesn't have .so, too.

[wrw1961]

I'm positive I've added debug to the end of the pam line for auth Please see below with examples of both the nullok and debug options being used.

The code is from github and is version google-authenticator-libpam-1.05

I check other logs, and it appears the same messages as noted below also show up in /var/log/debug, and they are identical to those in /var/log/info. I do not see anything else anywhere that seems obvious.

The pam modules on AIX go into /usr/lib/security the pam_aix was already there, provided by IBM and in the directory does not have the .so either according to IBM the syntax we are using is correct, and it should support the debug option regardless of the module.. so maybe the debug option isn't making it to the pam_google_authenticator.so because AIX is doing it's own forwarding to syslog???

IBM PAM reference

-r--r--r--    1 root     security      37652 Nov 20 2017  /usr/lib/security/pam_aix
-r--r--r--    1 root     security     154790 Jul  2 11:02 /usr/lib/security/pam_google_authenticator.so

I tried another test where I replaced the nullok with debug so I only have a single option rather than trying to have multiples and here the result

=================================================================== First with nullok

/etc/pam.conf entry sshd auth required pam_google_authenticator.so nullok

homer[sc2112] </home/sc2112> ssh goob@gahost
goob's Password:
Verification code: 
Connection closed by 192.168.14.75

AUTH LOG enjtries

Jul 10 09:42:28 homer auth|security:debug sshd: PAM: pam_start(sshd goob)
Jul 10 09:42:28 homer auth|security:debug sshd: PAM: pam_set_item(1)
Jul 10 09:42:28 homer auth|security:debug sshd: PAM: pam_set_item(2)
Jul 10 09:42:28 homer auth|security:debug sshd: PAM: pam_set_item(5)
Jul 10 09:42:28 homer auth|security:debug sshd: PAM: pam_set_item(4)
Jul 10 09:42:28 homer auth|security:debug sshd: PAM: pam_set_item(5)
Jul 10 09:42:28 homer auth|security:debug sshd: PAM: pam_authenticate()
Jul 10 09:42:28 homer auth|security:debug sshd: PAM: load_modules: /usr/lib/security/pam_aix
Jul 10 09:42:28 homer auth|security:debug sshd: PAM: load_function: successful load of pam_sm_authenticate
Jul 10 09:42:28 homer auth|security:debug sshd: PAM: load_modules: /usr/lib/security/pam_google_authenticator.so
Jul 10 09:42:28 homer auth|security:debug sshd: PAM: load_function: successful load of pam_sm_authenticate
Jul 10 09:42:31 homer auth|security:debug sshd: PAM: pam_set_item(6)

=================================================================== Now with debug

/etc/pam.conf entry sshd auth required pam_google_authenticator.so debug

homer[sc2112] </home/sc2112> ssh goob@gahost
goob's Password:
goob's Password:
goob's Password:
goob@gahost's password: 
Connection closed by 192.168.14.75

AUTH LOG entries

Jul 10 10:01:09 gahost auth|security:debug sshd: PAM: pam_start(sshd goob)
Jul 10 10:01:09 gahost auth|security:debug sshd: PAM: pam_set_item(1)
Jul 10 10:01:09 gahost auth|security:debug sshd: PAM: pam_set_item(2)
Jul 10 10:01:09 gahost auth|security:debug sshd: PAM: pam_set_item(5)
Jul 10 10:01:09 gahost auth|security:debug sshd: PAM: pam_set_item(4)
Jul 10 10:01:09 gahost auth|security:debug sshd: PAM: pam_set_item(5)
Jul 10 10:01:09 gahost auth|security:debug sshd: PAM: pam_authenticate()
Jul 10 10:01:09 gahost auth|security:debug sshd: PAM: load_modules: /usr/lib/security/pam_aix
Jul 10 10:01:09 gahost auth|security:debug sshd: PAM: load_function: successful load of pam_sm_authenticate
Jul 10 10:01:09 gahost auth|security:debug sshd: PAM: load_modules: /usr/lib/security/pam_google_authenticator.so
Jul 10 10:01:09 gahost auth|security:debug sshd: PAM: load_function: successful load of pam_sm_authenticate
Jul 10 10:01:11 gahost auth|security:debug sshd: PAM: pam_set_item(6)
Jul 10 10:01:11 gahost auth|security:info syslog: ssh: failed login attempt for goob from homer
Jul 10 10:01:11 gahost auth|security:debug sshd: PAM: pam_set_item(5)
Jul 10 10:01:11 gahost auth|security:debug sshd: PAM: pam_authenticate()
Jul 10 10:01:11 gahost auth|security:debug sshd: PAM: load_modules: /usr/lib/security/pam_aix
Jul 10 10:01:11 gahost auth|security:debug sshd: PAM: load_function: successful load of pam_sm_authenticate
Jul 10 10:01:11 gahost auth|security:debug sshd: PAM: load_modules: /usr/lib/security/pam_google_authenticator.so
Jul 10 10:01:11 gahost auth|security:debug sshd: PAM: load_function: successful load of pam_sm_authenticate
Jul 10 10:01:14 gahost auth|security:debug sshd: PAM: pam_set_item(6)
Jul 10 10:01:14 gahost auth|security:info syslog: ssh: failed login attempt for goob from homer
Jul 10 10:01:14 gahost auth|security:debug sshd: PAM: pam_set_item(5)
Jul 10 10:01:14 gahost auth|security:debug sshd: PAM: pam_authenticate()
Jul 10 10:01:14 gahost auth|security:debug sshd: PAM: load_modules: /usr/lib/security/pam_aix
Jul 10 10:01:14 gahost auth|security:debug sshd: PAM: load_function: successful load of pam_sm_authenticate
Jul 10 10:01:14 gahost auth|security:debug sshd: PAM: load_modules: /usr/lib/security/pam_google_authenticator.so
Jul 10 10:01:14 gahost auth|security:debug sshd: PAM: load_function: successful load of pam_sm_authenticate
Jul 10 10:01:16 gahost auth|security:debug sshd: PAM: pam_set_item(6)
Jul 10 10:01:16 gahost auth|security:info syslog: ssh: failed login attempt for goob from homer
Jul 10 10:01:21 gahost auth|security:debug sshd: PAM: pam_set_item(5)
Jul 10 10:01:21 gahost auth|security:debug sshd: PAM: pam_authenticate()
Jul 10 10:01:21 gahost auth|security:debug sshd: PAM: load_modules: /usr/lib/security/pam_aix
Jul 10 10:01:21 gahost auth|security:debug sshd: PAM: load_function: successful load of pam_sm_authenticate
Jul 10 10:01:21 gahost auth|security:debug sshd: PAM: load_modules: /usr/lib/security/pam_google_authenticator.so
Jul 10 10:01:21 gahost auth|security:debug sshd: PAM: load_function: successful load of pam_sm_authenticate
Jul 10 10:01:21 gahost auth|security:debug sshd: PAM: pam_set_item(6)

===================================================================

[wrw1961]

I have an update on this...

What we believe is happening is with the debug option the process core dumps. Which might explain why we do not get any debug output, and why we do not get the prompt.

[wrw1961]

I have more information...

To try and get around the issue where the authentication was failing with the DEBUG option on in the pam.conf file, I decided to modify the source file pam_google_authenticator.c and updated the function: static int parse_args

I added params->debug = 1; just above the line in the function with return 0;

The idea was to force debugging. This caused the core dump as before, which clarified it was not do to multiple options in the pam.conf entry.

Ran dbx on the core file and found the core dump happened with this line

Segmentation fault in vsyslog at 0xd24a404c ($t1) 0xd24a404c (vsyslog+0x8) 800c0000 lwz r0,0x0(r12)

anyone have any insight? I'm kinda above my skill set when it comes to programming in C

thank you

[ThomasHabets]

Can you get a backtrace on the coredump? Looks like the dbx command is where, from my googling.

[wrw1961]

I was pulled off this project for awhile so hadn't had a chance to look at it. I will see what can do to get the backtrace.. since it's been awhile I'll have to spend some time re-acquainting myself with this.. hopefully post the results this week.

thank you

[wrw1961]

Didn't take as long as I thought to re-acquaint myself..

Here's what I think you ask for

reading symbolic information ...

Segmentation fault in vsyslog at 0xd24a404c ($t1)
0xd24a404c (vsyslog+0x8) 800c0000            lwz   r0,0x0(r12)
(dbx) where
vsyslog() at 0xd24a404c
internal error: unexpected value 120 at line 5201 in file stabstring.c
internal error: expected char ',', found 's__LC_locale:,768,32;__meth_ptr:92,800,32;__data_ptr:92,832,32;;'
internal error: expected char ',', found '__LC_locale:,768,32;__meth_ptr:92,800,32;__data_ptr:92,832,32;;'
internal error: expected char ';', found '_LC_locale:,768,32;__meth_ptr:92,800,32;__data_ptr:92,832,32;;'
internal error: unexpected value 44 at line 5201 in file stabstring.c
internal error: expected char ',', found '768,32;__meth_ptr:92,800,32;__data_ptr:92,832,32;;'
internal error: unexpected value 120 at line 5201 in file stabstring.c
internal error: unexpected value 120 at line 5201 in file stabstring.c
internal error: expected char ',', found 's_LC_locale_objhdl:,64,32;;'
internal error: expected char ',', found '_LC_locale_objhdl:,64,32;;'
internal error: expected char ';', found 'LC_locale_objhdl:,64,32;;'
internal error: unexpected value 44 at line 5201 in file stabstring.c
internal error: expected char ',', found '64,32;;'
internal error: unexpected value 120 at line 5201 in file stabstring.c
internal error: unexpected value 120 at line 5201 in file stabstring.c
internal error: unexpected value 120 at line 5201 in file stabstring.c
internal error: unexpected value 120 at line 5201 in file stabstring.c
internal error: unexpected value 120 at line 5201 in file stabstring.c
internal error: unexpected value 120 at line 5201 in file stabstring.c
internal error: unexpected value 120 at line 5201 in file stabstring.c
internal error: unexpected value 120 at line 5201 in file stabstring.c
log_message(priority = 6, pamh = ??, format = "debug: start of google_authenticator for "%s""), line 108 in "pam_google_authenticator.c"
unnamed block in google_authenticator(pamh = 0x2009bdd8, argc = 1, argv = 0x2009a828), line 159 in "pam_google_authenticator.c"
google_authenticator(pamh = 0x2009bdd8, argc = 1, argv = 0x2009a828), line 159 in "pam_google_authenticator.c"
pam_authenticate(??, ??) at 0xd0666888
sshpam_auth_passwd(authctxt = 0x20040ee8, password = "XXXX"), line 1210 in "auth-pam.c"
auth_password(authctxt = 0x20040ee8, password = "XXXX"), line 139 in "auth-passwd.c"
mm_answer_authpassword(sock = 6, m = 0x2ff22700), line 892 in "monitor.c"
monitor_read(pmonitor = 0x20047218, ent = 0x2001d02c, pent = 0x2ff22780), line 628 in "monitor.c"
monitor_child_preauth(_authctxt = 0x20040ee8, pmonitor = 0x20047218), line 399 in "monitor.c"
privsep_preauth(authctxt = 0x20040ee8), line 666 in "sshd.c"
main(ac = 3, av = 0x20034818), line 2092 in "sshd.c"

Thank you

[wrw1961]

Just wondering if anyone has any ideas to resolve the issue??

[ThomasHabets]

Sorry, don't know. From backtrace I don't see anything immediately bad, why that log_message would cause SEGV. It checks for success and nullptr.

I'm afraid that realistically I don't have time to troubleshoot this, not having access to an AIX system[1]. You could sprinkle some fprintf(stderr, in there, which may help if you know what you're doing.

[1] even with access I'm unlikely to have time at least the next month or two.

[stwongst]

Hi, I tried to compile it on AIX 7.2 but failed with error during make:

  CC       src/google-authenticator.o
src/google-authenticator.c:25:10: fatal error: getopt.h: No such file or directory
 #include <getopt.h>
          ^~~~~~~~~~
compilation terminated.
make: 1254-004 The error code from the last command is 1.

I tried to add getopt module but not sure if the steps are correct:

./bootstrap.sh
/usr/local/src/gnulib/gnulib-tool --import getopt
/usr/local/src/gnulib/gnulib-tool --add-import getopt
/usr/local/src/gnulib/gnulib-tool --add-import vasprintf
./configure
make

Would anyone please help? Sorry for the newbie question.

Thanks and rgds

[ThomasHabets]

@stwongst could you open a new issue about that, since it's not related to the issue described in this one?

My guess would be that your include path is incomplete, and you should do something like configure CPPFLAGS=-I/usr/local/include or whereever getopt.h ended up.

[stwongst]

Thanks for your help. the getopt.h not found problem is fixed but got some other error. Started a new issue thread. Sorry for any trouble caused. Thanks.

[ThomasHabets]

Maybe the same issue: #122