extauth_program not being called, or hangs

I have ejabberd-2.0.5 installed and running fine under a single virtual host. Was able to connect to admin interface fine, connect clients and authenticate them fine.

However, now I need to try and authenticate people using an external program. Ultimately it will be a C# program that authenticates using the same hashing/authorization protocol as our other apps, so they can all share a password.

Towards that end, I tried the C# found at http://www.ejabberd.im/check_csharp.

I modified the program very slightly - namely, I added some logging so I can debug authentication. The *first* thing the program does is log to an external file at c:\temp\log.txt.

So, I dropped my script at c:\temp\jauth.exe, and my ejabberd config looks like:

%%{auth_method, internal}.
{auth_method, external}.
{extauth_program, "C:\\temp\\JabberAuthentication.exe"}.

I restart ejabberd, and I notice the logfile gets updated, but the program appears to hang at Console.In.Read, as if ejabberd is not providing any parameters via stdin for the program. Running the program manually also gets as far as the stdin read, so I know the program isn't bailing early.

So, I decided to try Ruby instead, based on the script found at http://thinkincode.net/2007/1/1/ruby-y-ejabberd (full script is at http://thinkincode.net/samples/ejabberd_authentication.rb)

I updated the ejabberd config:

{extauth_program, "C:\\temp\\jabber_auth.rb"}.

The strange thing is that I can't even get ejabberd to call this ruby program. I updated the script to run with the correct windows shebang:

#!C:\Program Files\ruby\bin\ruby.exe

And again I added some logging logic:

f = File.open("C:\\temp\\jrb.log", "a")
f << "loaded" + '\n'
f.close()

The above logic is executed even before the class/method definitions are loaded in the script. And there is some logging logic inside the "initialize" method call as well. The strange thing is *none* of the ruby logging is getting triggered - the file is always empty. I can run the script directly from the command line (c:\temp\jabber_auth.rb) and it seems to be fine - no syntax errors or anything.

What am I doing wrong here? Why would the C# exe run and hang, and the ruby script not run at all? I should note that the C# exe gets called and run when ejabberd is *started* - what/who is getting authenticated then? This is before any clients try to connect.

I tried logging in from a client anyway, just to see if whatever is happening when the server starts is different - but I get the same behavior.

Am I missing an additional configuration option somewhere?

The ejabberd log files are filled with the following error (in sasl.log)

=CRASH REPORT==== 28-Jul-2009::13:52:46 ===
crasher:
pid: <0.358.0>
registered_name: []
exception exit: {badarg,[{extauth,call_port,2},
{ejabberd_auth,check_password_loop,2},
{cyrsasl_plain,mech_step,2},
{cyrsasl,server_step,2},
{ejabberd_c2s,wait_for_feature_request,2},
{gen_fsm,handle_msg,7},
{proc_lib,init_p,5}]}
in function gen_fsm:terminate/7
initial call: gen:init_it(gen_fsm,<0.260.0>,<0.260.0>,ejabberd_c2s,
[{ejabberd_socket,
{socket_state,gen_tcp,#Port<0.420>,
<0.357.0>}},
[{certfile,
"C:\\Program Files\\ejabberd-2.0.5\\conf\\server.pem"},
starttls,
{access,c2s},
{shaper,c2s_shaper},
{max_stanza_size,65536}]],
[])
ancestors: [ejabberd_c2s_sup,ejabberd_sup,<0.36.0>]
messages: []
links: [<0.260.0>,#Port<0.422>]
dictionary: []
trap_exit: false
status: running
heap_size: 2584
stack_size: 23
reductions: 3451
neighbours:

=SUPERVISOR REPORT==== 28-Jul-2009::13:52:46 ===
Supervisor: {local,ejabberd_c2s_sup}
Context: child_terminated
Reason: {badarg,[{extauth,call_port,2},
{ejabberd_auth,check_password_loop,2},
{cyrsasl_plain,mech_step,2},
{cyrsasl,server_step,2},
{ejabberd_c2s,wait_for_feature_request,2},
{gen_fsm,handle_msg,7},
{proc_lib,init_p,5}]}
Offender: [{pid,<0.358.0>},
{name,undefined},
{mfa,
{ejabberd_c2s,start_link,
[{ejabberd_socket,
{socket_state,gen_tcp,#Port<0.420>,<0.357.0>}},
[{certfile,
"C:\\Program Files\\ejabberd-2.0.5\\conf\\server.pem"},
starttls,
{access,c2s},
{shaper,c2s_shaper},
{max_stanza_size,65536}]]}},
{restart_type,temporary},
{shutdown,brutal_kill},
{child_type,worker}]

And the ejabberd.log file itself has:

=INFO REPORT==== 2009-07-28 13:55:37 ===
I(<0.269.0>:ejabberd_listener:116) : (#Port<0.440>) Accepted connection {{10,100,101,163},4692} -> {{10,100,101,163},5222}

=ERROR REPORT==== 2009-07-28 13:55:37 ===
** State machine <0.371.0> terminating
** Last event in was {xmlstreamelement,
{xmlelement,"auth",
[{"xmlns","urn:ietf:params:xml:ns:xmpp-sasl"},
{"mechanism","PLAIN"}],
[{xmlcdata,
<<"bWlyYW5kYUBtbGlubmVsbABtaXJhbmRhAHRlc3QxMjM=">>}]}}
** When State == wait_for_feature_request
** Data == {state,{socket_state,tls,
{tlssock,#Port<0.440>,#Port<0.442>},
<0.370.0>},
ejabberd_socket,#Ref<0.0.0.9073>,"1992555507",
{sasl_state,"jabber","orion",[],
#Fun,
#Fun,undefined,
undefined},
c2s,c2s_shaper,false,true,false,true,
[verify_none,
{certfile,"C:\\Program Files\\ejabberd-2.0.5\\conf\\server.pem"}],
false,undefined,[],"orion",[],undefined,
{0,nil},
{0,nil},
{0,nil},
{0,nil},
undefined,undefined,undefined,false,
{userlist,none,[]},
unknown,unknown,
{{10,100,101,163},4692},
"en"}
** Reason for termination =
** {badarg,[{extauth,call_port,2},
{ejabberd_auth,check_password_loop,2},
{cyrsasl_plain,mech_step,2},
{cyrsasl,server_step,2},
{ejabberd_c2s,wait_for_feature_request,2},
{gen_fsm,handle_msg,7},
{proc_lib,init_p,5}]}

I notice in both log files the lines mentioning

(badarg, [{extauth, call_port,2},

I'm not familiar with erlang, but it seems to suggest there is a bad argument when calling the external authentication? I didn't think there were any arguments, just data being sent in via stdin