|
Daniele Ricci opened 9 years ago
|
|
From provided logs I cannot tell what caused this issue, however I'm sure that [2] is not responsible for this issue as there is a call to However I see a few things which look a little weird:
One more thing - this "new" |
|
|
Andrzej Wójcik wrote:
That's because the delivery failed 3 times (it can happen very often with mobile connections) and the message got back into offline storage.
I'm sorry I didn't explain: although it says "Restoring packet", that log is from the savePacketForOfflineUser method [1], so it is going to offline storage again (I know it's going again because of the presence of the delay element which was injected the first time the message was stored, see from #L361).
Indeed. You gave me some hints to do some more research on this. I'll get back to you. If anything pops into your mind in the meantime please share. |
|
|
I think I got it. The first line in the log shows the message stanza as coming from the sender, so without a from attribute. But then there is this line: The line after that shows the message having the from attribute just that value. I don't think it's a coincidence. I guess something weird happens if the recipient is still logging in while delivering the message. Am I getting this right? |
|
This code should be run only on the established, authorised sessions, for packets that were send by the user of that session (i.e. incoming packets) in order to be in line with specification witch enforces that all packets should have correct from set. From that excerpt it looks like the user sent the packet to it's on BareJID. |
|
|
Ok, just to give you a wider view: Let's analyze it together (correct me if I'm wrong)
|
|
|
Daniele Ricci wrote:
Ok :-)
Correct
Correct
Correct
No, those are entries from the SessionManager component itself - it performs some processing before calling the plugins. And after that plugins are executed in the documented way (all preProcessors, then processors for registered types, then postProcessors if there wasn't any processor for the given stanza, then filters)
Correct, all preProcessors are executed.
This is correct; The packet came from the user
Well, everything seems in order. Main question is - are you sure you are logging in with the different JID for this account?? |
|
|
Wojciech Kapcia wrote:
I'm quite sure yes :) It just happened again with a friend, I'm analyzing the logs. I might know what is happening. |
|
|
If you find the root-cause please share, especially if it's a bug in Tigase. |
|
|
I thought the issue was fixed by this: https://github.com/kontalk/tigase-extension/commit/68a378062b89947cb7ddb903a03b77a3a7822afe and it actually made sense, but I've received a report just yesterday of this issue happening again. Unfortunately, the user reported the issue too late for the logs to be still there (they rotated - I've activated almost maximum verbosity to debug this so they grow very quickly). I'll keep you posted. |
|
|
I got another case (among many, I'll take one as example as I've already inspected two more, they happen in the same situation). Sender: e893c4e88ccd497d019cf0391b12065f65a6bc1c@beta.kontalk.net Recipient: 301ec9a675d58bb2a9fa22f900ead23c443e0c21@beta.kontalk.net This is the case story. The recipient got his message, but it can't ack it (Session Mngt) because he loses his connection. At this time, probably the connection was already broken, but the server still doesn't realize that. And here is the server finally realizing the connection is broken: At this step I don't understand why this log is printed twice: "service stopped - resumption disabled, sending unacked packets". But let's continue for now. The message is routed again (this time by StreamManagementIOProcessor handling the unacked packets). I can't see the whole stanza, but a few log lines later I will see this packet has the delivery-error tag (injected by ClientConnectionManager). Here is what raises a doubt: the packet "from" is the recipient's connectionId. I guess it's the only way to do it, but it could bring problems later for what I can see. I know I'm just speculating for now, but let's go ahead in our log. The message continues its journey through the handling chain (a STREAM_CLOSED command is coming through too, that's from ClientConnectionManager IIRC) until it reaches BindResource.preProcess, which tries to handle the message because: And the packet is indeed from the this session, so the if block goes through. The rest is self-explainatory in the code of BindResource.preProcess, until it finally reaches these lines: Am I making any sense here? |
|
|
If you need anything else to debug this issue, please don't hesitate to ask. Several users have been reporting this behaviour by now and I want to fix this as soon as possible (it began happening since I've updated to latest release branch). |
|
|
I've included additional check in BindResource preProcessor to avoid handling such error packets. |
|
|
Thanks! I will pull the release branch tonight. |
|
|
I just checked if processing if other case will work correctly and all looks ok. |
|
|
I think this can be closed, thank you. |
| Type |
Bug
|
| Priority |
Major
|
| Assignee | |
| RedmineID |
3689
|
| Spent time |
13h 30m
|
I have a strange issue reported by a few users and I'm trying to find proof on the server logs.
I wrote a custom OfflineMessages module which is quite similar to the Tigase one [1] which does not alter the from attribute ever. Code is 90% copied from yours and it adds message expiration + a custom database repository.
Message IDs are unique (generated by clients), I'll examine a message with ID 50HeViNirO5Cp57PqRC47Eld7z7AG4 for this bug report.
That message has been apparently delivered with the sender being the recipient of the message. I can see the original (right) message reported by the OfflineMessages module after a storage loop (that is, failed to deliver because of broken connection client, then stored and then failed again: the delay element is detected by the OfflineMessages module and it doesn't add another one):
As you can see, sender is e77aa2d04b00be2002badacf9a176d31373c42e4@beta.kontalk.net/91c86d2c35575f42,
recipient is 2aa60150c7cacc53568e5923b1f365d6661acc65@beta.kontalk.net.
20 minutes later, another log appears:
The message comes from 20 minutes before (as of the delay element), but the sender has changed.
Inspecting Tigase's Message module, I can see only one point where the from might be changed [2] (release branch).
I've recently removed my custom message delivery code because you've done some modifications to improve that so I didn't need my custom code anymore. The only custom thing concerning messages is the OfflineMessages module.
Thanks for the help. If you need anything to debug this just ask. I will continue my log analysis in the meantime and keep you updated on my latest findings.
[1] https://github.com/kontalk/tigase-extension/blob/master/src/main/java/org/kontalk/xmppserver/messages/OfflineMessages.java
[2] https://projects.tigase.org/projects/tigase-server/repository/revisions/release/entry/src/main/java/tigase/xmpp/impl/Message.java#L187