strange problem with roster subscriptions

[sss123next]

What version of ejabberd are you using?

c7476875e65ce648ea58364fecbc2097a2285da1

What operating system (version) are you using?

uname -orv
4.9.3 #2 SMP Sat Jan 14 19:37:29 MSK 2017 GNU/Linux

How did you install ejabberd (source, package, distribution)?

http://sss.chaoslab.ru/git/?p=sss_overlay.git;a=blob;f=net-im/ejabberd/ejabberd-scm.ebuild;h=add257fb3ecb2f38ed17202d6fb2511304a6a2b9;hb=e5a9d08f3a4c217d146570bb03b902ebc08882d9

What did not work as expected? Are there error messages in the log? What was the unexpected behavior? What was the expected result?

most contacts is offline all the time, i am offline for most contacts, but i cant send/receive messages. errror in log:

2017-01-17 16:33:25.035 [error] <0.767.0>@ejabberd_hooks:run_fold1:368 {{badrecord,roster},[{mod_roster,fill_subs,382}]},{ejabberd_hooks,run_fold1,4,[{file,"src/ejabberd_hooks.erl"},{line,365}]},{ejabberd_c2s,open_session,1,[{_c2s,decode_element,3,[{file,"src/ejabberd_c2s.erl"},{line,928}]},{p1_fsm,handle_msg,10,[{file,"src/p1_fsm.erl"}, running hook: {roster_get_subscription_lists,[<<"sss">>,<<"sss.chaoslab.ru">>]} 2017-01-17 16:35:17.409 [error] <0.888.0>@ejabberd_hooks:run_fold1:368 {{badrecord,roster},[{mod_roster,fill_subs,382}]},{ejabberd_hooks,run_fold1,4,[{file,"src/ejabberd_hooks.erl"},{line,365}]},{ejabberd_c2s,open_session,1,[{_c2s,decode_element,3,[{file,"src/ejabberd_c2s.erl"},{line,928}]},{p1_fsm,handle_msg,10,[{file,"src/p1_fsm.erl"}, running hook: {roster_get_subscription_lists,[<<"sss">>,<<"dark-alexandr.net">>]}

[zinid]

{{badrecord,roster},[{mod_roster,fill_subs,382}]}, ...

There is no such function mod_roster:fill_subs/382. Note that 382 means the function has 382 arguments, which is ridiculous. This might be an Erlang bug, mod_roster.beam corruption or you copy-pasted wrongly.

[zinid]

Anyway, try to run the following function from ejabberdctl debug:

> mod_roster:get_subscription_lists([], <<"sss">>,<<"dark-alexandr.net">>).

[sss123next]

ejabberdctl debug
--------------------------------------------------------------------

IMPORTANT: we will attempt to attach an INTERACTIVE shell
to an already running ejabberd node.
If an ERROR is printed, it means the connection was not successful.
You can interact with the ejabberd node if you know how to use it.
Please be extremely cautious with your actions,
and exit immediately if you are not completely sure.

To detach this shell from ejabberd, press:
  control+c, control+c

--------------------------------------------------------------------
To bypass permanently this warning, add to ejabberdctl.cfg the line:
  EJABBERD_BYPASS_WARNINGS=true
Press return to continue

kernel-poll not supported; "K" parameter ignored
Erlang/OTP 19 [erts-8.1] [source] [64-bit] [smp:6:6] [async-threads:10]

Eshell V8.1  (abort with ^G)
(ejabberd@localhost)1> mod_roster:get_subscription_lists([], <<"sss">>,<<"dark-alexandr.net">>).
** exception error: {badrecord,roster}
     in function  mod_roster:fill_subscription_lists/4 (src/mod_roster.erl, line 473)
(ejabberd@localhost)2> 

[zinid]

What database backend are you using? Also, try the following:

> Mod = gen_mod:db_mod(<<"dark-alexandr.net">>, mod_roster).
> Mod:get_only_items(<<"sss">>,<<"dark-alexandr.net">>).

[sss123next]

using mysql

kernel-poll not supported; "K" parameter ignored
Erlang/OTP 19 [erts-8.1] [source] [64-bit] [smp:6:6] [async-threads:10]

Eshell V8.1  (abort with ^G)
(ejabberd@localhost)1> Mod = gen_mod:db_mod(<<"dark-alexandr.net">>, mod_roster).
mod_roster_sql
(ejabberd@localhost)2> Mod:get_only_items(<<"sss">>,<<"dark-alexandr.net">>).
[error,
 {roster,{<<"sss">>,<<"dark-alexandr.net">>,
          {<<"----8----">>,<<"jabbus.org">>,<<>>}},
         {<<"sss">>,<<"dark-alexandr.net">>},
         {<<"----8----">>,<<"jabbus.org">>,<<>>},
         <<>>,none,out,[],<<>>,[]},
 {roster,{<<"sss">>,<<"dark-alexandr.net">>,
          {<<"----8----">>,<<"miranda.im">>,<<>>}},
         {<<"sss">>,<<"dark-alexandr.net">>},
         {<<"----8----">>,<<"miranda.im">>,<<>>},
         <<"----8----">>,both,none,[],<<>>,[]},
 {roster,{<<"sss">>,<<"dark-alexandr.net">>,
          {<<"----8----\\40jabbus.org">>,
           <<"xmpp2.dark-alexandr.net">>,<<>>}},
         {<<"sss">>,<<"dark-alexandr.net">>},
         {<<"----8----\\40jabbus.org">>,
          <<"xmpp2.dark-alexandr.net">>,<<>>},
         <<>>,both,none,[],<<>>,[]},
 {roster,{<<"sss">>,<<"dark-alexandr.net">>,
          {<<"07cienintm0pt02sbs89l098ci\\40public.talk.google.com">>,
           <<"xmpp3.dark-alexandr.net">>,<<>>}},
         {<<"sss">>,<<"dark-alexandr.net">>},
         {<<"07cienintm0pt02sbs89l098ci\\40public.talk.google.com">>,
          <<"xmpp3.dark-alexandr.net">>,<<>>},
         <<"Alexander Bershadskyy">>,none,none,[],<<>>,[]},
 {roster,{<<"sss">>,<<"dark-alexandr.net">>,
          {<<"07cienintm0pt02sbs89l098ci\\40public.talk.google.com">>,
           <<"xmpp3.sss.chaoslab.ru">>,<<>>}},
         {<<"sss">>,<<"dark-alexandr.net">>},
         {<<"07cienintm0pt02sbs89l098ci\\40public.talk.google.com">>,
          <<"xmpp3.sss.chaoslab.ru">>,<<>>},
         <<"Alexander Bershadskyy">>,both,none,[],<<>>,[]},
 {roster,{<<"sss">>,<<"dark-alexandr.net">>,
          {<<"0fmzxc94mgi22269gdecx3ylo4\\40public.talk.google.com">>,
           <<"xmpp3.dark-alexandr.net">>,<<>>}},
         {<<"sss">>,<<"dark-alexandr.net">>},
         {<<"0fmzxc94mgi22269gdecx3ylo4\\40public.talk.google.com">>,
          <<"xmpp3.dark-alexandr.net">>,<<>>},
         <<"Alex Borisov">>,both,none,[],<<>>,[]},
 {roster,{<<"sss">>,<<"dark-alexandr.net">>,
          {<<"0qtdfv0aup4rg0f8kyodu1xs9t\\40public.talk.google.com">>,
           <<"xmpp3.dark-alexandr.net">>,<<>>}},
         {<<"sss">>,<<"dark-alexandr.net">>},
         {<<"0qtdfv0aup4rg0f8kyodu1xs9t\\40public.talk.google.com">>,
          <<"xmpp3.dark-alexandr.net">>,<<>>},
         <<"Evil Satanson">>,both,none,[],<<>>,[]},
 {roster,{<<"sss">>,<<"dark-alexandr.net">>,
          {<<"107007696">>,<<"icq.dark-alexandr.net">>,<<>>}},
         {<<"sss">>,<<"dark-alexandr.net">>},
         {<<"107007696">>,<<"icq.dark-alexandr.net">>,<<>>},
         <<"Alver">>,both,none,[],<<>>,[]},
 {roster,{<<"sss">>,<<"dark-alexandr.net">>,
          {<<"110704">>,<<"icq.dark-alexandr.net">>,<<>>}},
         {<<"sss">>,<<"dark-alexandr.net">>},
         {<<"110704">>,<<"icq.dark-alexandr.net">>,<<>>},
         <<"110704">>,both,none,[],<<>>,[]},
 {roster,{<<"sss">>,<<"dark-alexandr.net">>,
          {<<"112120315">>,<<"icq.dark-alexandr.net">>,<<>>}},
         {<<"sss">>,<<"dark-alexandr.net">>},
         {<<"112120315">>,<<"icq.dark-alexandr.net">>,<<>>},
         <<"m0m">>,both,none,[],<<>>,[]},
 {roster,{<<"sss">>,<<"dark-alexandr.net">>,
          {<<"113342115">>,<<"icq.dark-alexandr.net">>,<<>>}},
         {<<"sss">>,<<"dark-alexandr.net">>},
         {<<"113342115">>,<<"icq.dark-alexandr.net">>,<<>>},
         <<"Yasnovidyashii">>,both,none,[],<<>>,[]},
 {roster,{<<"sss">>,<<"dark-alexandr.net">>,
          {<<"11523425">>,<<"icq.dark-alexandr.net">>,<<>>}},
         {<<"sss">>,<<"dark-alexandr.net">>},
         {<<"11523425">>,<<"icq.dark-alexandr.net">>,<<>>},
         <<"LexSys [II]">>,both,none,[],<<>>,[]},
 {roster,{<<"sss">>,<<"dark-alexandr.net">>,
          {<<"123581859">>,<<"icq.dark-alexandr.net">>,<<>>}},
         {<<"sss">>,<<"dark-alexandr.net">>},
         {<<"123581859">>,<<"icq.dark-alexandr.net">>,<<>>},
         <<"markus">>,both,none,[],<<>>,[]},
 {roster,{<<"sss">>,<<"dark-alexandr.net">>,
          {<<"136501947">>,<<"icq.dark-alexandr.net">>,<<>>}},
         {<<"sss">>,<<"dark-alexandr.net">>},
         {<<"136501947">>,<<"icq.dark-alexandr.net">>,<<>>},
         <<"Amon Sul">>,both,none,[],<<>>,[]},
 {roster,{<<"sss">>,<<"dark-alexandr.net">>,
          {<<"136916500">>,<<"icq.dark-alexandr.net">>,<<>>}},
         {<<"sss">>,<<"dark-alexandr.net">>},
         {<<"136916500">>,<<"icq.dark-alexandr.net">>,<<>>},
         <<"Anton King">>,both,none,[],<<>>,[]},
 {roster,{<<"sss">>,<<"dark-alexandr.net">>,
          {<<"139296150">>,<<"icq.dark-alexandr.ne"...>>,<<>>}},
         {<<"sss">>,<<"dark-alexandr.net">>},
         {<<"139296150">>,<<"icq.dark-alexandr.net">>,<<>>},
         <<"Joe">>,both,none,[],<<>>,[]},
 {roster,{<<"sss">>,<<"dark-alexandr.net">>,
          {<<"140895218">>,<<"icq.dark-alexand"...>>,<<>>}},
         {<<"sss">>,<<"dark-alexandr.net">>},
         {<<"140895218">>,<<"icq.dark-alexandr.ne"...>>,<<>>},
         <<40,46,46,208,189,209,...>>,
         both,none,[],<<>>,[]},
 {roster,{<<"sss">>,<<"dark-alexandr.net">>,
          {<<"141458638">>,<<"icq.dark-ale"...>>,<<>>}},
         {<<"sss">>,<<"dark-alexandr.net">>},
         {<<"141458638">>,<<"icq.dark-alexand"...>>,<<>>},
         <<"PCLG">>,both,none,[],<<>>,[]},
 {roster,{<<"sss">>,<<"dark-alexandr.net">>,
          {<<"1457705">>,<<"icq.dark"...>>,<<>>}},
         {<<"sss">>,<<"dark-alexandr.ne"...>>},
         {<<"1457705">>,<<"icq.dark-ale"...>>,<<>>},
         <<"D@rkNeo">>,both,none,[],<<>>,...},
 {roster,{<<"sss">>,<<"dark-alexandr.ne"...>>,
          {<<"1491585">>,<<"icq."...>>,<<>>}},
         {<<"sss">>,<<"dark-alexand"...>>},
         {<<"1491585">>,<<"icq.dark"...>>,<<>>},
         <<"SurSum">>,both,none,[],...},
 {roster,{<<"sss">>,<<"dark-alexand"...>>,
          {<<"1496"...>>,<<...>>,...}},
         {<<"sss">>,<<"dark-ale"...>>},
         {<<"14967640"...>>,<<"icq."...>>,<<>>},
         <<"nullbie">>,both,none,...},
 {roster,{<<"sss">>,<<"dark-ale"...>>,{<<...>>,...}},
         {<<"sss">>,<<"dark"...>>},
         {<<"1512"...>>,<<...>>,...},
         <<"six">>,both,...},
 {roster,{<<"sss">>,<<"dark"...>>,{...}},
         {<<"sss">>,<<...>>},
         {<<...>>,...},
         <<...>>,...},
 {roster,{<<"sss">>,<<...>>,...},{<<...>>,...},{...},...},
 {roster,{<<...>>,...},{...},...},
 {roster,{...},...},
 {roster,...},
 {...}|...]

[zinid]

Seems like you have corrupted database. Run the following SQL query:

select jid from rosterusers where username='sss';

You will see a JID in a single row to be invalid (likely in the first returned row).

[sss123next]

looks correct

select username, jid from rosterusers;
+----------------------------+-----------------------------------------------------------------------------+
| username                   | jid                                                                         |
+----------------------------+-----------------------------------------------------------------------------+
....
....
+----------------------------+-----------------------------------------------------------------------------+
2259 rows in set (0,05 sec)

do you need all content of table ?

[zinid]

No, I edited the sql query, sorry. Please re-run.

[sss123next]

i have few transports attached, which kind of corruption i need to search for ?

[zinid]

jid should look like not a valid XMPP address. For example, valid addresses are: "user@server.org" and "server.com". Others are invalid. From what I see in the return of get_only_items function, malformed JID should come in the first row of the SQL command's result.

[zinid]

Anyway, I will make ejabberd logging a warning when it gets corrupted data from the database.

[sss123next]

cat jids |grep -v @
| icq.dark-alexandr.net                                                       |
| mrim.dark-alexandr.net                                                      |
| xmpp2.dark-alexandr.net                                                     |
| xmpp3.dark-alexandr.net                                                     |

i have this

[zinid]

Gosh, what's in the first row??? Also, your grepping is invalid, this doesn't detect something like "user@user@server", which is also invalid. Anyway, I'm working on the fix. After update ejabberd will log you an incorrect row (and your roster will be loaded despite the error).

[sss123next]

first row

----8----@jabbus.org

thank you, waiting for fix.

[zinid]

Please try the new HEAD (2de2d00f1457642bedf3af4c4b0bfb9c9107b0b5).

[sss123next]

ha

cat error.log 
2017-01-18 12:48:23.238 [error] <0.623.0>@mod_roster_sql:raw_to_record:239 Malformed 'jid' field with value '' detected for sss@dark-alexandr.net in table 'rosterusers'
2017-01-18 12:48:23.557 [error] <0.490.0>@mod_roster_sql:raw_to_record:239 Malformed 'jid' field with value '' detected for sss@dark-alexandr.net in table 'rosterusers'
2017-01-18 12:48:23.646 [error] <0.623.0>@mod_roster_sql:raw_to_record:239 Malformed 'jid' field with value '' detected for sss@dark-alexandr.net in table 'rosterusers'

[zinid]

I'm wondered how this JID got there.

[zinid]

When did you start getting the error? Have you updated from some ancient version of ejabberd?

[sss123next]

something like month ago. i have server crash with filesystem corruptions, i am not already noticed about problems, some time ago my contacts just asked why i am offline all the time

[zinid]

OK, well, now you can easily find the corrupted row and delete it from the table. I close the ticket.

[sss123next]

yes, thank you

[LRevs]

Hi zinid,

We are getting below error in our ejabberd server logs:

running hook: {roster_get_subscription_lists,[<<"hopw012417404">>,<<"ytchat.org">>]} 2018-10-05 18:10:03.919 [error] <0.13793.15>@ejabberd_hooks:run_fold1:368 {function_clause,[{mod_roster,raw_to_record,[<<"ytchat.org">>,error],[{file,"src/mod_roster.erl"},{line,1290}]},{mod_roster,fill_subscription_lists,4,[{file,"src/mod_roster.erl"},{line,688}]},{ejabberd_hooks,safe_apply,3,[{file,"src/ejabberd_hooks.erl"},{line,382}]},{ejabberd_hooks,run_fold1,4,[{file,"src/ejabberd_hooks.erl"},{line,365}]},{ejabberd_c2s,wait_for_session,2,[{file,"src/ejabberd_c2s.erl"},{line,1122}]},{p1_fsm,handle_msg,10,[{file,"src/p1_fsm.erl"},{line,582}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,237}]}]}

We are using ejabberd version 15.11. Can you please let us know what could be the issue.

[lock[bot]]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.