Hi :).
When i register with transport, i log to web andmin and on user's roster the subscription for this transport is set to 'none' and pending groups is set to 'out'. In effect when i open psi, change status to online for the whole jabber account, i'm not logged in to that transport automatically. I tried to re-authorize transport but with no success - the subscription type remains without change ('none').
This strange error doesn't happen for all accounts but i can't investigate why for some of them it does. This is even stranger because the same problem sometimes happen for one particullar account and another time for that same account it doesn't! For ex. when i remove the whole account from ejabberd, register it again, register in transport, repeat this steps few times and then suddenly after few cycles the problem just dissapears... i repeat it another few times and it appear again...
Debug output when i use "Request authorization from" for that transport:
=INFO REPORT==== 3-Apr-2010::10:29:42 ===
D(<0.439.0>:ejabberd_receiver:320) : Received XML on stream = "<presence xmlns=\"jabber:client\" type=\"subscribe\" to=\"gg.jabber.my.domain\" >\n<nick xmlns=\"http://jabber.org/pro
tocol/nick\">siwuch</nick>\n</presence>\n"
=INFO REPORT==== 3-Apr-2010::10:29:42 ===
D(<0.439.0>:shaper:61) : State: {maxrate,1000,494.57823412880464,
1270283369321911}, Size=149
M=98.97558503398741, I=13332.576
=INFO REPORT==== 3-Apr-2010::10:29:42 ===
D(<0.440.0>:ejabberd_sm:409) : session manager
from {jid,[],[],[],[],[],[]}
to {jid,"siwuch","my.domain",[],"siwuch",
"my.domain",[]}
packet {xmlelement,"broadcast",[],[{item,{...},...}]}
=INFO REPORT==== 3-Apr-2010::10:29:42 ===
D(<0.440.0>:ejabberd_sm:409) : session manager
from {jid,[],[],[],[],[],[]}
to {jid,"siwuch","my.domain","Psi","siwuch",
"my.domain","Psi"}
packet {xmlelement,"broadcast",[],[{item,{...},...}]}
=INFO REPORT==== 3-Apr-2010::10:29:42 ===
D(<0.440.0>:ejabberd_sm:508) : sending to process <0.440.0>
=INFO REPORT==== 3-Apr-2010::10:29:42 ===
D(<0.440.0>:ejabberd_router:301) : route
from {jid,"siwuch","my.domain",[],"siwuch",
"my.domain",[]}
to {jid,"siwuch","my.domain","Psi","siwuch",
"my.domain","Psi"}
packet {xmlelement,"iq",
[{"id","push719581502"},{"type","set"}],
[{xmlelement,"query",
[{"xmlns","jabber:iq:roster"}],
[{xmlelement,"item",
[{"ask","subscribe"},
{"subscription","none"},
{"jid","gg.jabber.my.domain"}],
[]}]}]}
=INFO REPORT==== 3-Apr-2010::10:29:42 ===
D(<0.440.0>:ejabberd_local:286) : local route
from {jid,"siwuch","my.domain",[],"siwuch",
"my.domain",[]}
to {jid,"siwuch","my.domain","Psi","siwuch",
"my.domain","Psi"}
packet {xmlelement,"iq",
[{"id","push719581502"},{"type",[...]}],
[{xmlelement,[...],...}]}
=INFO REPORT==== 3-Apr-2010::10:29:42 ===
D(<0.440.0>:ejabberd_sm:409) : session manager
from {jid,"siwuch","my.domain",[],"siwuch",
"my.domain",[]}
to {jid,"siwuch","my.domain","Psi","siwuch",
"my.domain","Psi"}
packet {xmlelement,"iq",
[{"id","push719581502"},{"type",[...]}],
[{xmlelement,[...],...}]}
=INFO REPORT==== 3-Apr-2010::10:29:42 ===
D(<0.440.0>:ejabberd_sm:508) : sending to process <0.440.0>
=INFO REPORT==== 3-Apr-2010::10:29:42 ===
D(<0.440.0>:ejabberd_router:301) : route
from {jid,"siwuch","my.domain",[],"siwuch",
"my.domain",[]}
to {jid,[],"gg.jabber.my.domain",[],[],"gg.jabber.my.domain",
[]}
packet {xmlelement,"presence",
[{"xml:lang","en"},
{"type","subscribe"},
{"to","gg.jabber.my.domain"}],
[{xmlcdata,<<"\n">>},
{xmlelement,"nick",
[{"xmlns","http://jabber.org/protocol/nick"}],
[{xmlcdata,<<"siwuch">>}]},
{xmlcdata,<<"\n">>}]}
=INFO REPORT==== 3-Apr-2010::10:29:42 ===
D(<0.440.0>:ejabberd_c2s:1194) : broadcast
[{item,{[],"gg.jabber.my.domain",[]},none}]
=INFO REPORT==== 3-Apr-2010::10:29:42 ===
D(<0.440.0>:ejabberd_c2s:1892) : roster changed for "siwuch"
=INFO REPORT==== 3-Apr-2010::10:29:42 ===
D(<0.440.0>:ejabberd_c2s:1412) : Send XML on stream = "<iq from='siwuch@my.domain' to='siwuch@my.domain/Psi' id='push719581502' type='set'><query xmlns=
'jabber:iq:roster'><item ask='subscribe' subscription='none' jid='gg.jabber.my.domain'/></query></iq>"
=INFO REPORT==== 3-Apr-2010::10:29:42 ===
D(<0.437.0>:ejabberd_receiver:320) : Received XML on stream = "<presence from='gg.jabber.my.domain/registered' to='siwuch@my.domain'/>"
=INFO REPORT==== 3-Apr-2010::10:29:42 ===
D(<0.438.0>:ejabberd_router:301) : route
from {jid,[],"gg.jabber.my.domain","registered",[],
"gg.jabber.my.domain","registered"}
to {jid,"siwuch","my.domain",[],"siwuch",
"my.domain",[]}
packet {xmlelement,"presence",
[{"from","gg.jabber.my.domain/registered"},
{"to","siwuch@my.domain"}],
[]}
=INFO REPORT==== 3-Apr-2010::10:29:42 ===
D(<0.438.0>:ejabberd_local:286) : local route
from {jid,[],"gg.jabber.my.domain","registered",[],
"gg.jabber.my.domain","registered"}
to {jid,"siwuch","my.domain",[],"siwuch",
"my.domain",[]}
packet {xmlelement,"presence",
[{"from","gg.jabber.my.domain/registered"},
{"to",[...]}],
[]}
=INFO REPORT==== 3-Apr-2010::10:29:42 ===
D(<0.438.0>:ejabberd_sm:409) : session manager
from {jid,[],"gg.jabber.my.domain","registered",[],
"gg.jabber.my.domain","registered"}
to {jid,"siwuch","my.domain",[],"siwuch",
"my.domain",[]}
packet {xmlelement,"presence",
[{"from","gg.jabber.my.domain/registered"},
{"to",[...]}],
[]}
=INFO REPORT==== 3-Apr-2010::10:29:42 ===
D(<0.438.0>:ejabberd_sm:409) : session manager
from {jid,[],"gg.jabber.my.domain","registered",[],
"gg.jabber.my.domain","registered"}
to {jid,"siwuch","my.domain","Psi","siwuch",
"my.domain","Psi"}
packet {xmlelement,"presence",
[{"from","gg.jabber.my.domain/registered"},
{"to",[...]}],
[]}
=INFO REPORT==== 3-Apr-2010::10:29:42 ===
D(<0.438.0>:ejabberd_sm:508) : sending to process <0.440.0>
=INFO REPORT==== 3-Apr-2010::10:29:42 ===
D(<0.440.0>:ejabberd_c2s:1412) : Send XML on stream = "<presence from='gg.jabber.my.domain/registered' to='siwuch@my.domain/Psi'/>"
=INFO REPORT==== 3-Apr-2010::10:29:42 ===
D(<0.439.0>:ejabberd_receiver:320) : Received XML on stream = "<iq xmlns=\"jabber:client\" type=\"result\" to=\"siwuch@my.domain\" id=\"push719581502\" />\n"
=INFO REPORT==== 3-Apr-2010::10:29:42 ===
D(<0.439.0>:shaper:61) : State: {maxrate,1000,252.876930261332,
1270283382654497}, Size=96
M=54.94747431522356, I=51.324
=INFO REPORT==== 3-Apr-2010::10:29:42 ===
D(<0.440.0>:ejabberd_router:301) : route
from {jid,"siwuch","my.domain","Psi","siwuch",
"my.domain","Psi"}
to {jid,"siwuch","my.domain",[],"siwuch",
"my.domain",[]}
packet {xmlelement,"iq",
[{"xml:lang","en"},
{"type","result"},
{"to","siwuch@my.domain"},
{"id","push719581502"}],
[]}
=INFO REPORT==== 3-Apr-2010::10:29:42 ===
D(<0.440.0>:ejabberd_local:286) : local route
from {jid,"siwuch","my.domain","Psi","siwuch",
"my.domain","Psi"}
to {jid,"siwuch","my.domain",[],"siwuch",
"my.domain",[]}
packet {xmlelement,"iq",
[{"xml:lang","en"},
{"type",[...]},
{[...],...},
{...}],
[]}
=INFO REPORT==== 3-Apr-2010::10:29:42 ===
D(<0.440.0>:ejabberd_sm:409) : session manager
from {jid,"siwuch","my.domain","Psi","siwuch",
"my.domain","Psi"}
to {jid,"siwuch","my.domain",[],"siwuch",
"my.domain",[]}
packet {xmlelement,"iq",
[{"xml:lang","en"},
{"type",[...]},
{[...],...},
{...}],
[]}
BTW, what is a meaning of 'Pending groups' ?
Presence of ejabberd users is not propagated to spectrum clients
I have similar problems with the spectrum transport.
If an ejabberd JID sends an authorization request to an ICQ number
<presence xmlns='jabber:client' to='1234567@host.com' type='subscribe'/>I get in the spectrum logs
[12/16/10 22:39:11] <XML IN> <presence from='bot@host.com' to='1234567@icq.host.com' xml:lang='en' type='subscribed'/>[12/16/10 22:39:11] <bot@host.com> Subscribe presence received, but this user is not logged in
If I then switch the online status of I don't see any change in the transport's roster.
ATM, I don't know on which side the bug is - ejabberd or spectrum.
It seems like the presence notification from the ejabberd JIDs are not transmitted to the transports - the IQ stanzas, however, are.
Any suggestions what can be done in this regard?