User mattermost reply standard messages

[keachi]

matterircd Version: 0.10.0
mattermost Version 3.3.0

If I'm joined to a channel (let's say #test) and I /msg #test /join #foo, then the user mattermost write to me msg: /join #foo, instead deliver the message (/join #foo) to the channel #test.

[42wim]

I can not reproduce this.

Could you run matterircd with -debug reproduce the issue and paste the output (filter personal info if you need)

[keachi]

Aug 31 08:36:58 dagaz matterircd-linux64[5347]: time="2016-08-31T08:36:58+02:00" level=debug msg="<- PRIVMSG #testing :/join #blah" module=matterircd
Aug 31 08:36:58 dagaz matterircd-linux64[5347]: time="2016-08-31T08:36:58+02:00" level=debug msg="-> :mattermost!mattermost@mattermost PRIVMSG tobiasr :msg: /join #blah \u200b could not be send: : You do not have the appropriate permissions, " module=matterircd

But I want to send a message and not joining a channel. And as reply from user mattermost, I only become the message displayed /join #blah.

[42wim]

Could you please paste all debug messages from starting the server / logging in until getting this message ?

It seems like you're using a modified version mattermost!mattermost@mattermost does not exist in my build, this should be mattermost!mattermost@service. Did you make some changes to the code ?

[keachi]

Aug 31 08:04:26 dagaz systemd[1]: Starting MatterIRCd...
Aug 31 08:04:26 dagaz systemd[1]: Started MatterIRCd.
Aug 31 08:04:26 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:26+02:00" level=info msg="enabling debug" module=matterircd
Aug 31 08:04:26 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:26+02:00" level=info msg="Listening on 127.0.0.1:6668" module=matterircd
Aug 31 08:04:32 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:32+02:00" level=info msg="New connection: 127.0.0.1:46756" module=matterircd
Aug 31 08:04:32 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:32+02:00" level=debug msg="<- NICK tobiasr" module=matterircd
Aug 31 08:04:32 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:32+02:00" level=debug msg="<- USER tobiasr 0 * :tobiasr" module=matterircd
Aug 31 08:04:32 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:32+02:00" level=debug msg="-> :matterircd 001 tobiasr :Welcome! tobiasr!tobiasr@localhost" module=matterircd
Aug 31 08:04:32 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:32+02:00" level=debug msg="-> :matterircd 002 tobiasr :Your host is matterircd, running version 0.10.0" module=matterircd
Aug 31 08:04:32 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:32+02:00" level=debug msg="-> :matterircd 003 tobiasr :This server was created Wed Aug 31 08:04:32 CEST 2016" module=matterircd
Aug 31 08:04:32 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:32+02:00" level=debug msg="-> :matterircd 004 tobiasr :matterircd 0.10.0 o o" module=matterircd
Aug 31 08:04:32 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:32+02:00" level=debug msg="-> :matterircd 251 tobiasr :There are 2 users and 0 services on 1 servers" module=matterircd
Aug 31 08:04:32 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:32+02:00" level=debug msg="-> :matterircd 375 tobiasr :- matterircd Message of the Day -" module=matterircd
Aug 31 08:04:32 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:32+02:00" level=debug msg="-> :matterircd 376 tobiasr :End of /MOTD command." module=matterircd
Aug 31 08:04:32 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:32+02:00" level=debug msg="<- PRIVMSG mattermost :login tobiasr verysecure" module=matterircd
Aug 31 08:04:32 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:32+02:00" level=info msg="login as tobiasr (team: adsy) on chat.example.org" module=matterircd
Aug 31 08:04:32 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:32+02:00" level=debug msg="trying login adsy tobiasr chat.example.org" module=matterclient
Aug 31 08:04:32 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:32+02:00" level=debug msg="initUser()" module=matterclient
Aug 31 08:04:32 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:32+02:00" level=debug msg="initUser(): loading all team data" module=matterclient
Aug 31 08:04:32 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:32+02:00" level=debug msg="initUser(): found our team adsy (id: pxwqd59477damnj4fjn76xwr8h)" module=matterclient
Aug 31 08:04:32 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:32+02:00" level=debug msg="WsClient: making connection" module=matterclient
Aug 31 08:04:33 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:33+02:00" level=info msg="login succeeded" module=matterircd
Aug 31 08:04:33 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:33+02:00" level=debug msg="in addUsersToChannels()" module=matterircd
Aug 31 08:04:33 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:33+02:00" level=debug msg="in handleWsMessage" module=matterircd
Aug 31 08:04:33 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:33+02:00" level=debug msg="-> :tobiasr!tobiasr@localhost JOIN &users" module=matterircd
Aug 31 08:04:33 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:33+02:00" level=debug msg="-> :matterircd 353 tobiasr = &users :tobiasr " module=matterircd
Aug 31 08:04:33 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:33+02:00" level=debug msg="-> :matterircd 366 tobiasr &users :End of /NAMES list." module=matterircd
Aug 31 08:04:33 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:33+02:00" level=debug msg="syncMMChannel adding myself to town-square (id: oir1q7rwofbm7yq8poxy5gkaay)" module=matterircd
Aug 31 08:04:33 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:33+02:00" level=debug msg="-> :tobiasr!tobiasr@localhost JOIN #town-square" module=matterircd
Aug 31 08:04:33 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:33+02:00" level=debug msg="-> :matterircd 332 tobiasr #town-square :In memory of #adsybla" module=matterircd
Aug 31 08:04:33 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:33+02:00" level=debug msg="-> :matterircd 353 tobiasr = #town-square :tobiasr " module=matterircd
Aug 31 08:04:33 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:33+02:00" level=debug msg="-> :matterircd 366 tobiasr #town-square :End of /NAMES list." module=matterircd
Aug 31 08:04:33 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:33+02:00" level=debug msg="posting lastview \"oir1q7rwofbm7yq8poxy5gkaay\"" module=matterclient
Aug 31 08:04:33 dagaz matterircd-linux64[5347]: time="2016-08-31T08:04:33+02:00" level=debug msg="-> :mattermost!mattermost@service PRIVMSG tobiasr :login OK" module=matterircd
[...]
Aug 31 08:35:34 dagaz matterircd-linux64[5347]: time="2016-08-31T08:35:34+02:00" level=debug msg="WS PING" module=matterclient
Aug 31 08:35:34 dagaz matterircd-linux64[5347]: time="2016-08-31T08:35:34+02:00" level=debug msg="sendWsRequest &model.WebSocketRequest{Seq:32, Action:\"ping\", Data:map[string]interface {}(nil), Session:model.Session{Id:\"\", Token:\"\", CreateAt:0, ExpiresAt:0, LastActivityAt:0, UserId:\"\", DeviceId:\"\", Roles:\"\", IsOAuth:false, Props:model.StringMap(nil), TeamMembers:[]*model.TeamMember(nil)}, T:(i18n.TranslateFunc)(nil), Locale:\"\"}" module=matterclient
Aug 31 08:35:34 dagaz matterircd-linux64[5347]: time="2016-08-31T08:35:34+02:00" level=debug msg="WsReceiver: model.WebSocketResponse{Status:\"OK\", SeqReply:32, Data:map[string]interface {}{\"node_id\":\"\", \"server_time\":1.472625334238e+12, \"text\":\"pong\", \"version\":\"3.3.0\"}, Error:(*model.AppError)(nil)}" module=matterclient
Aug 31 08:35:34 dagaz matterircd-linux64[5347]: time="2016-08-31T08:35:34+02:00" level=debug msg="WS PONG received" module=matterclient
Aug 31 08:36:26 dagaz matterircd-linux64[5347]: time="2016-08-31T08:36:26+02:00" level=debug msg="WsReceiver: model.WebSocketEvent{TeamId:\"\", ChannelId:\"\", UserId:\"9dofj4xcjf8s3dehj7gzgria8a\", Event:\"status_change\", Data:map[string]interface {}{\"status\":\"away\"}}" module=matterclient
Aug 31 08:36:26 dagaz matterircd-linux64[5347]: time="2016-08-31T08:36:26+02:00" level=debug msg="WsReceiver: &model.WebSocketEvent{TeamId:\"\", ChannelId:\"\", UserId:\"9dofj4xcjf8s3dehj7gzgria8a\", Event:\"status_change\", Data:map[string]interface {}{\"status\":\"away\"}}" module=matterircd
Aug 31 08:36:27 dagaz matterircd-linux64[5347]: time="2016-08-31T08:36:27+02:00" level=debug msg="in handleWsMessage" module=matterircd
Aug 31 08:36:32 dagaz matterircd-linux64[5347]: time="2016-08-31T08:36:32+02:00" level=debug msg="<- PING localhost" module=matterircd
Aug 31 08:36:32 dagaz matterircd-linux64[5347]: time="2016-08-31T08:36:32+02:00" level=debug msg="-> :matterircd PONG matterircd" module=matterircd
Aug 31 08:36:34 dagaz matterircd-linux64[5347]: time="2016-08-31T08:36:34+02:00" level=debug msg="WS PING" module=matterclient
Aug 31 08:36:34 dagaz matterircd-linux64[5347]: time="2016-08-31T08:36:34+02:00" level=debug msg="sendWsRequest &model.WebSocketRequest{Seq:33, Action:\"ping\", Data:map[string]interface {}(nil), Session:model.Session{Id:\"\", Token:\"\", CreateAt:0, ExpiresAt:0, LastActivityAt:0, UserId:\"\", DeviceId:\"\", Roles:\"\", IsOAuth:false, Props:model.StringMap(nil), TeamMembers:[]*model.TeamMember(nil)}, T:(i18n.TranslateFunc)(nil), Locale:\"\"}" module=matterclient
Aug 31 08:36:34 dagaz matterircd-linux64[5347]: time="2016-08-31T08:36:34+02:00" level=debug msg="WsReceiver: model.WebSocketResponse{Status:\"OK\", SeqReply:33, Data:map[string]interface {}{\"node_id\":\"\", \"server_time\":1.472625394246e+12, \"text\":\"pong\", \"version\":\"3.3.0\"}, Error:(*model.AppError)(nil)}" module=matterclient
Aug 31 08:36:34 dagaz matterircd-linux64[5347]: time="2016-08-31T08:36:34+02:00" level=debug msg="WS PONG received" module=matterclient
Aug 31 08:36:58 dagaz matterircd-linux64[5347]: time="2016-08-31T08:36:58+02:00" level=debug msg="<- PRIVMSG #testing :/join #blah" module=matterircd
Aug 31 08:36:58 dagaz matterircd-linux64[5347]: time="2016-08-31T08:36:58+02:00" level=debug msg="-> :mattermost!mattermost@mattermost PRIVMSG tobiasr :msg: /join #blah \u200b could not be send: : You do not have the appropriate permissions, " module=matterircd

I see, that at the beginning (or normally) it's mattermost!mattermost@service, except for this one message it's mattermost!mattermost@mattermost.
I didn't change anything on the code, I used the binaries from GitHub.

[42wim]

Thanks, but I need more debug, the part you snipped out actually :(
Where all the channels are joined / parted etc.., this way I can see exactly what happens with that channel.

If it's to difficult to paste the whole debuglog here, you can put it up at pastebin.com

Here's what happens if I try to reproduce it

DEBU[2016-09-01T23:36:18+02:00] <- PRIVMSG #testing :/join #blah              module=matterircd
DEBU[2016-09-01T23:36:18+02:00] WsReceiver: model.WebSocketEvent{TeamId:"65dp43wnhpg9dp6p64jmkgphtw", ChannelId:"7oyeupz3e3ydbewxajotm44e3r", UserId:"yr6h1qebfjnoikgp66gfqci53r", Event:"posted", Data:map[string]interface {}{"channel_display_name":"testing", "channel_type":"O", "post":"{\"id\":\"4jgpfcy5n7yzurn9quueaj6zga\",\"create_at\":1472765778243,\"update_at\":1472765778243,\"delete_at\":0,\"user_id\":\"yr6h1qebfjnoikgp66gfqci53r\",\"channel_id\":\"7oyeupz3e3ydbewxajotm44e3r\",\"root_id\":\"\",\"parent_id\":\"\",\"original_id\":\"\",\"message\":\"/join #blah \u200b\",\"type\":\"\",\"props\":{},\"hashtags\":\"#blah\",\"filenames\":[],\"pending_post_id\":\"\"}", "sender_name":"wimtest", "team_id":"65dp43wnhpg9dp6p64jmkgphtw"}}  module=matterclient
DEBU[2016-09-01T23:36:18+02:00] WsReceiver: &model.WebSocketEvent{TeamId:"65dp43wnhpg9dp6p64jmkgphtw", ChannelId:"7oyeupz3e3ydbewxajotm44e3r", UserId:"yr6h1qebfjnoikgp66gfqci53r", Event:"posted", Data:map[string]interface {}{"channel_type":"O", "post":"{\"id\":\"4jgpfcy5n7yzurn9quueaj6zga\",\"create_at\":1472765778243,\"update_at\":1472765778243,\"delete_at\":0,\"user_id\":\"yr6h1qebfjnoikgp66gfqci53r\",\"channel_id\":\"7oyeupz3e3ydbewxajotm44e3r\",\"root_id\":\"\",\"parent_id\":\"\",\"original_id\":\"\",\"message\":\"/join #blah \u200b\",\"type\":\"\",\"props\":{},\"hashtags\":\"#blah\",\"filenames\":[],\"pending_post_id\":\"\"}", "sender_name":"wimtest", "team_id":"65dp43wnhpg9dp6p64jmkgphtw", "channel_display_name":"testing"}}  module=matterircd
DEBU[2016-09-01T23:36:18+02:00] handleWsActionPost() receiving userid yr6h1qebfjnoikgp66gfqci53r  module=matterircd
DEBU[2016-09-01T23:36:18+02:00] message is sent from IRC, contains unicode, not relaying "/join #blah \u200b"  module=matterircd

[keachi]

Oh, sorry. I wanted to reproduce the bug, with lesser log data.
After starting once the binary https://github.com/42wim/matterircd/releases/download/v0.10.0/matterircd-linux64-test I was unable to reproduce the bug. So I close this issue, and will reopen it, if I run into the bug again.

[42wim]

Thanks for your help for reporting and debugging this and the two other bugs.