processone/ejabberd-contrib

mod_post_log: Hook user_send_packet crashed when running mod_post_log:log_user_send/1

PasqualePuzio opened this issue · 5 comments

PasqualePuzio commented

Hi,

we have installed mod_post_log and enabled it in the config

mod_post_log:
  url: "http://127.0.0.1:5555/chatmessages"

every time we send a message we see the following error:

[error] <0.457.0>@ejabberd_hooks:safe_apply:383 Hook user_send_packet crashed when running mod_post_log:log_user_send/1:
** Reason = {error,function_clause,
[{httpc,request,[{file,"httpc.erl"},{line,149}],
 [post,{"http://foo.bar.com/messages",[{<<"X-Message-Timestamp">>,"2020-03-02 15:11:04.964195Z"},{<<"X-Message-From">>,"1@testjabber.fantamaster.it/MacBook-Pro"},{<<"X-Message-To">>,"test@testrooms.testjabber.fantamaster.it"}],<<"text/xml">>,<<"<message xml:lang='it' to='test@testrooms.testjabber.fantamaster.it' from='1@testjabber.fantamaster.it/MacBook-Pro' type='groupchat' id='purple5aeaa5b' xmlns='jabber:client'><body>ora va?</body></message>">>},[],[{sync,false},{receiver,{mod_post_log,post_result,[]}}],default]},
{mod_post_log,post_xml,[{file,"/opt/ejabberd/.ejabberd-modules/sources/ejabberd-contrib/mod_post_log/src/mod_post_log.erl"},{line,105}],3},
{mod_post_log,log_user_send,[{file,"/opt/ejabberd/.ejabberd-modules/sources/ejabberd-contrib/mod_post_log/src/mod_post_log.erl"},{line,74}],1},
{ejabberd_hooks,safe_apply,[{file,"src/ejabberd_hooks.erl"},{line,380}],4},
{ejabberd_hooks,run_fold1,[{file,"src/ejabberd_hooks.erl"},{line,364}],4},
{ejabberd_c2s,handle_authenticated_packet,[{file,"src/ejabberd_c2s.erl"},{line,467}],2},
{xmpp_stream_in,process_authenticated_packet,[{file,"src/xmpp_stream_in.erl"},{line,620}],2},
{xmpp_stream_in,handle_info,[{file,"src/xmpp_stream_in.erl"},{line,355}],2}]}

I'm not an Erlang expert, what could be the issue? We have already checked the logs at http://127.0.0.1:5555/chatmessages and it doesn't receive any http request.

We're using ejabberd 18.03 on Ubuntu 16.04.

Thanks

badlop commented

I've applied a fix in the module. I wonder how many time it didn't work... Please update the module specs to try it, and comment here your results.

PasqualePuzio commented

Sorry but there are still several issues:

2020-03-04 10:15:02.359 [error] <0.548.0>@gen_mod:validate_opt:621 Ignoring invalid value 'undefined' for option 'url' of module 'mod_post_log'
2020-03-04 10:15:02.359 [error] <0.548.0>@gen_mod:validate_opt:621 Ignoring invalid value '"X-Message-Timestamp"' for option 'ts_header' of module 'mod_post_log'
2020-03-04 10:15:02.359 [error] <0.548.0>@gen_mod:validate_opt:621 Ignoring invalid value '"X-Message-From"' for option 'from_header' of module 'mod_post_log'
2020-03-04 10:15:02.359 [error] <0.548.0>@gen_mod:validate_opt:621 Ignoring invalid value '"X-Message-To"' for option 'to_header' of module 'mod_post_log'
2020-03-04 10:15:02.359 [error] <0.548.0>@gen_mod:validate_opt:621 Ignoring invalid value '"text/xml"' for option 'content_type' of module 'mod_post_log'
2020-03-04 10:16:09.403 [error] <0.674.0>@ejabberd_config:validate_opts:1042 unknown option 'mod_fm_post_log' will be likely ignored
2020-03-04 10:16:10.131 [error] <0.936.0>@gen_mod:validate_opt:621 Ignoring invalid value 'undefined' for option 'url' of module 'mod_post_log'
2020-03-04 10:16:10.131 [error] <0.936.0>@gen_mod:validate_opt:621 Ignoring invalid value '"X-Message-Timestamp"' for option 'ts_header' of module 'mod_post_log'
2020-03-04 10:16:10.131 [error] <0.936.0>@gen_mod:validate_opt:621 Ignoring invalid value '"X-Message-From"' for option 'from_header' of module 'mod_post_log'
2020-03-04 10:16:10.131 [error] <0.936.0>@gen_mod:validate_opt:621 Ignoring invalid value '"X-Message-To"' for option 'to_header' of module 'mod_post_log'
2020-03-04 10:16:10.131 [error] <0.936.0>@gen_mod:validate_opt:621 Ignoring invalid value '"text/xml"' for option 'content_type' of module 'mod_post_log'
2020-03-04 10:16:45.199 [error] <0.1069.0>@ejabberd_hooks:safe_apply:383 Hook user_send_packet crashed when running mod_post_log:log_user_send/1:
** Reason = {error,function_clause,
[{httpc,request,[{file,"httpc.erl"},{line,149}],
 [post,{"http://foo.bar.com/messages",
  [{undefined,"2020-03-04 10:16:45.198689Z"},
   {undefined,"1@testjabber.fantamaster.it/MacBook-Pro"},
   {undefined,"test@testrooms.testjabber.fantamaster.it"}],
 undefined,
 "<message xml:lang='it' to='test@testrooms.testjabber.fantamaster.it' from='1@testjabber.fantamaster.it/MacBook-Pro' type='groupchat' id='purpleba3b0384' xmlns='jabber:client'><body>vediamo un po&apos;</body></message>"},[],
 [{sync,false},{receiver,{mod_post_log,post_result,[]}}],default]},
{mod_post_log,post_xml,[{file,"/opt/ejabberd/.ejabberd-modules/sources/ejabberd-contrib/mod_post_log/src/mod_post_log.erl"},{line,102}],3},
{mod_post_log,log_user_send,[{file,"/opt/ejabberd/.ejabberd-modules/sources/ejabberd-contrib/mod_post_log/src/mod_post_log.erl"},{line,71}],1},
{ejabberd_hooks,safe_apply,[{file,"src/ejabberd_hooks.erl"},{line,380}],4},
{ejabberd_hooks,run_fold1,[{file,"src/ejabberd_hooks.erl"},{line,364}],4},
{ejabberd_c2s,handle_authenticated_packet,[{file,"src/ejabberd_c2s.erl"},{line,467}],2},
{xmpp_stream_in,process_authenticated_packet,[{file,"src/xmpp_stream_in.erl"},{line,620}],2},
{xmpp_stream_in,handle_info,[{file,"src/xmpp_stream_in.erl"},{line,355}],2}]}
** Arguments = [{{message,<<"purpleba3b0384">>,groupchat,<<"it">>,{jid,<<"1">>,<<"testjabber.fantamaster.it">>,<<"MacBook-Pro">>,<<"1">>,<<"testjabber.fantamaster.it">>,<<"MacBook-Pro">>},{jid,<<"test">>,<<"testrooms.testjabber.fantamaster.it">>,<<>>,<<"test">>,<<"testrooms.testjabber.fantamaster.it">>,<<>>},[],[{text,<<>>,<<"vediamo un po'">>}],undefined,[],#{ip => {0,0,0,0,0,65535,45207,50680}}},#{shaper => none,tls_required => true,conn => c2s_tls,lserver => <<"testjabber.fantamaster.it">>,auth_module => ejabberd_auth_external,user => <<"1">>,tls_enabled => true,stream_authenticated => true,lang => <<"it">>,stream_timeout => infinity,stream_compressed => false,pres_timestamp => {1583,316992,112999},mod => ejabberd_c2s,stream_state => established,access => c2s,stream_direction => in,resource => <<"MacBook-Pro">>,socket_monitor => #Ref<0.1265183697.899153921.209882>,codec_options => [ignore_els],pres_last => {presence,<<>>,available,<<"it">>,{jid,<<"1">>,<<"testjabber.fantamaster.it">>,<<"MacBook-Pro">>,<<"1">>,<<"testjabber.fantamaster.it">>,<<"MacBook-Pro">>},{jid,<<"1">>,<<"testjabber.fantamaster.it">>,<<>>,<<"1">>,<<"testjabber.fantamaster.it">>,<<>>},undefined,[],undefined,[{xmlel,<<"c">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/caps">>},{<<"node">>,<<"http://pidgin.im/">>},{<<"hash">>,<<"sha-1">>},{<<"ver">>,<<"VUFD6HcFmUT2NxJkBGCiKlZnS3M=">>}],[]},{xmlel,<<"x">>,[{<<"xmlns">>,<<"vcard-temp:x:update">>}],[]}],#{ip => {0,0,0,0,0,65535,45207,50680}}},stream_id => <<"7104137983444298327">>,tls_verify => false,socket => {socket_state,fast_tls,{tlssock,#Port<0.48408>,#Ref<0.1265183697.899284993.209903>},65536,#Ref<0.1265183697.899284993.209884>,none,undefined},owner => <0.1069.0>,zlib => true,stream_encrypted => true,pres_a => {1,{{<<"test">>,<<"testrooms.testjabber.fantamaster.it">>,<<"Pasquale Puzio">>},nil,nil}},jid => {jid,<<"1">>,<<"testjabber.fantamaster.it">>,<<"MacBook-Pro">>,<<"1">>,<<"testjabber.fantamaster.it">>,<<"MacBook-Pro">>},xmlns => <<"jabber:client">>,sid => {{1583,316991,1},<0.1069.0>},tls_options => [compression_none,{protocol_options,<<"no_sslv2|no_sslv3">>},{certfile,<<"/opt/ejabberd/conf/cert.pem">>}],stream_header_sent => true,server => <<"testjabber.fantamaster.it">>,ip => {{0,0,0,0,0,65535,45207,50680},60692},stream_version => {1,0},stream_restarted => true}}]
PasqualePuzio commented

For the record, mod_fm_post_log is a custom module that we have written and that is working fine for us (we have removed the values that are causing the function clause error):

{ok, _ReqId} = httpc:request(post,
                                 {Url, [], "application/xml", Body},
                                 [],
                                 [ {sync, false},
                                   {receiver, {?MODULE, post_result, []}} ]),
badlop commented

Aha, I see. The fix that I committed allows the module to work with recent ejabberd, at least with ejabberd 19.08 and newer. However, it still doesn't work with your ejabberd 18.03 (and I checked that with 18.06).

For those old versions, you have to apply this additional change. Once you update to newer ejabberd, you will not need it:

diff --git a/mod_post_log/src/mod_post_log.erl b/mod_post_log/src/mod_post_log.erl
index 66af7a8..55cb36b 100644
--- a/mod_post_log/src/mod_post_log.erl
+++ b/mod_post_log/src/mod_post_log.erl
@@ -42,7 +42,10 @@ stop(Host) ->
 depends(_Host, _Opts) ->
     [].
 
-mod_opt_type(url) -> fun binary_to_list/1;
+mod_opt_type(url) ->
+    fun(Val) when is_binary(Val) -> binary_to_list(Val);
+       (Val) -> Val
+    end;
 mod_opt_type(ts_header) -> fun binary_to_list/1;
 mod_opt_type(from_header) -> fun binary_to_list/1;
 mod_opt_type(to_header) -> fun binary_to_list/1;
@@ -53,11 +56,11 @@ mod_opt_type(req_options) -> fun(L) when is_list(L) -> L end.
 
 mod_options(_Host) ->
     [{url, undefined},
-     {ts_header, "X-Message-Timestamp"},
-     {from_header, "X-Message-From"},
-     {to_header, "X-Message-To"},
+     {ts_header, <<"X-Message-Timestamp">>},
+     {from_header, <<"X-Message-From">>},
+     {to_header, <<"X-Message-To">>},
      {headers, []},
-     {content_type, "text/xml"},
+     {content_type, <<"text/xml">>},
      {http_options, []},
      {req_options, []}].

You can apply this patch to your $HOME/.ejabberd-modules/sources/ejabberd-contrib/mod_post_log/src/mod_post_log.erl then uninstall and install the module again, so it gets compiled.

PasqualePuzio commented

Thank you for the clarification.