Work at SourceForge, help us to make it a better place! We have an immediate need for a Support Technician in our San Francisco or Denver office.

Close

#186 Users appear offline when they are not

1.15.x
closed-fixed
Stefan Becker
Protocol/Other
5
2013-04-18
2013-03-26
Robert Szabo
No

Dear Devs

We use pidgin (2.10.2) with the sipe plugin (1.15.0) to connect to our Lync 2010 server. Until a couple weeks ago we were using sipe 1.13.x but kept having issues with users not becoming available after being idle.

Ever since we updated sipe to 1.15.0 (or the interim version 1.14.x) Pidgin clients have been occasionally showing users offline even when they are online. We have a mix of Windows Lync, Mac Lync and Linux pidgin/sipe clients (totaling at about 1300) connecting to the Lync server.

Disabling and re-enabling the sipe account (or restarting pidgin) sorts the issue for a while but the problem will come back. We noticed two different problems which may or may not be related:
1) Some users show up as being offline in the buddy list but I am able to send them messages which they will receive and they can reply too. This is confusing as users never know whether another user is actually online or offline.
2) User shows as online but trying to send him a message will result in Pidgin throwing the following error in the conversation window 'This message was not delivered to <username> because they are offline'. At this time he was online. The problem can be fixed by the user restarting his pidgin.

Have you seen these problems? I keep following the changelog but not seen anything related yet.

Thanks,
Rob

Related

Bugs: #112
Bugs: #153
Bugs: #179
Release Notes: 2013/06/pidgin-sipe-release-1160

Discussion

1 2 3 > >> (Page 1 of 3)
  • Robert Szabo
    Robert Szabo
    2013-03-28

    I failed to mention that we use pidgin on CentOS6.

    I normally see status change messages for buddies in the debug log:
    (16:22:23) sipe:
    MESSAGE START <<<<<<<<<< SIP - 2013-03-28T23:22:23.988749Z
    BENOTIFY sip:xx.xx.145.27:50664;transport=tls;ms-opaque=d3470f2e1d;ms-received-cid=2DD3200;grid SIP/2.0
    Via: SIP/2.0/TLS xx.xx.193.96:5061;branch=z9hG4bK8DA4F63A.814448A28FFA3540;branched=FALSE
    Authentication-Info: NTLM qop="auth", opaque="1CDE4391", srand="C54B7177", snum="49", rspauth="01000000041e0d81b5b39a6064000000", targetname="xxxxxLYNC01.internal.domain", realm="SIP Communications Service", version=4
    Max-Forwards: 70
    To: sip:robert-sz@company.com;tag=4158757103;epid=d61367106f73
    Content-Length: 624
    From: sip:robert-sz@company.com;tag=8E6F0080
    Call-ID: 76B3g27DEa8D79iFF44m06F3t3437b0055x6A9Bx
    CSeq: 35 BENOTIFY
    Require: eventlist
    Content-Type: application/msrtc-event-categories+xml
    Event: presence
    subscription-state: active;expires=26677

    <categories xmlns="http://schemas.microsoft.com/2006/09/sip/categories" uri="sip:gurdip-b@company.com"><category xmlns="http://schemas.microsoft.com/2006/09/sip/categories" name="state" instance="1" publishTime="2013-03-28T23:22:23.850">
    

    <state xsi:type="aggregateState" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns="http://schemas.microsoft.com/2006/09/sip/state"><availability>9000</availability><delimiter xmlns="http://schemas.microsoft.com/2006/09/sip/commontypes"/><device>computer</device><end xmlns="http://schemas.microsoft.com/2006/09/sip/commontypes"/></state>
    </category>
    </categories>
    MESSAGE END <<<<<<<<<< SIP - 2013-03-28T23:22:23.988749Z
    (16:22:23) sipe: sip_sec_verify_signature: message is:<NTLM><C54B7177><49><SIP Communications="" Service=""><xxxxxLYNC01.internal.domain><76B3g27DEa8D79iFF44m06F3t3437b0055x6A9Bx><35><BENOTIFY>sip:robert-sz@company.com<8E6F0080>sip:robert-sz@company.com<4158757103><><><> signature to verify is:01000000041e0d81b5b39a6064000000
    (16:22:23) sipe: NTLM MAC(): Extented Session Security
    (16:22:23) sipe: NTLM MAC(): Key Exchange
    (16:22:23) sipe: NTLM calculated MAC: 01000000041E0D81B5B39A6064000000
    (16:22:23) sipe: sip_transport_input: signature of incoming message validated
    (16:22:23) sipe: process_input_message: msg->response(0),msg->method(BENOTIFY)
    (16:22:23) sipe: send->process_incoming_benotify
    (16:22:23) sipe: process_incoming_notify: subscription_state: active;expires=26677
    (16:22:23) sipe: sipe_process_presence: Content-Type: application/msrtc-event-categories+xml
    (16:22:23) sipe: process_incoming_notify_rlmi: do-not-disturb
    (16:22:23) blist: Updating buddy status for sip:gurdip-b@company.com (Office Communicator)

    But when pidgin gets into the above described state, I no longer see status change SIP messages in the pidgin debug log.

    Since pidgin debug logging is very verbose (and contains lots of sensitive data), could anyone give me some tips about what to filter on to see where it goes wrong?

    Any help would be much appreciated!

    Thanks,
    Rob

     
    Last edit: Robert Szabo 2013-03-28
    • Stefan Becker
      Stefan Becker
      2013-03-29

      But when pidgin gets into the above described state, I no longer see status change SIP messages in the pidgin debug log.

      You don't see any status updates for ANY buddy or only updates for that particular buddy gurdip-b?

      As SIPE only reacts to the status update sent by the server it would be important to know if this happens only for users that are using SIPE themselves (i.e. their status would also show up wrong in another Lync client), are using the official Lync client or with any client.

      You could strip down the log by cutting out +-1000 lines around each place where the user name is mentioned and then remove message conversation contents in those snippets. If you don't like attaching, then send them by email.

       
  • Robert Szabo
    Robert Szabo
    2013-04-03

    Hi Stefan

    Thanks for your reply. Sorry for the delay in getting back to you, but it was taking a while for pidgin/sipe "break" again:

    I can now confirm that I am not seeing ANY status updates for ANY user. I've tested with 3 different people (using a mix of pidgin/linux and lync/mac clients) - my linux pidgin client does not log anything nor does it change the user status.

    Interestingly at the same time, my status is Available on my client but my colleagues have advised me that I show up as being "away for 4 days".
    I can toggle my status to busy or D-N-D which work okay as in my status gets changed on their pidgin, but I cannot set my status to Available.

    When I do that I see this in my client's debug log:

    (17:01:35) prefs: /purple/savedstatus/default changed, scheduling save.
    (17:01:35) sipe: sipe_purple_set_status[CB]: status=available
    (17:01:35) sipe: sipe_core_status_set: was: sipe_private->do_not_publish[available]=0 [?] now(time)=1364947295
    (17:01:35) sipe: sipe_core_status_set: set: sipe_private->do_not_publish[available]=0 [0]
    (17:01:35) sipe: sipe_schedule_allocate timeouts count 9 after addition
    (17:01:35) sipe: scheduling action <+set-status> timeout 1 seconds
    (17:01:36) sipe: sipe_core_schedule_execute: executing <+set-status>
    (17:01:36) sipe: sipe_core_schedule_execute timeouts count 8 after removal
    (17:01:36) sipe: sipe_status_changed_by_user: sipe_private->idle_switch : Tue Apr 2 09:18:40 2013

    (17:01:36) sipe: sipe_status_changed_by_user: now : Tue Apr 2 17:01:36 2013

    (17:01:36) sipe: sipe_status_changed_by_user: res = USER
    (17:01:36) sipe: sipe_status_update: status: available (USER)
    (17:01:36) sipe: sipe_status_changed_by_user: sipe_private->idle_switch : Tue Apr 2 09:18:40 2013

    (17:01:36) sipe: sipe_status_changed_by_user: now : Tue Apr 2 17:01:36 2013

    (17:01:36) sipe: sipe_status_changed_by_user: res = USER
    (17:01:36) sipe: sipe_publish_get_category_state: state has NOT changed. Exiting.
    (17:01:36) sipe: sipe_publish_get_category_note: note has NOT changed. Exiting.
    (17:01:36) sipe: sipe_osc2007_category_publish: nothing has changed. Exiting.

    Am I seeing two different problems or the same problem manifests in many ways?

    Thanks for looking into this!

    Rob

     
  • Stefan Becker
    Stefan Becker
    2013-04-03

    I don't think the two issues you describe are related.

    That your status isn't updated sounds like bug [#179]. I guess your status at others' client gets updated after uses "SIPE account -> Reset Status"? You might want to add yourself to your buddy list. Does that entry also not get updated when others tell you that you show up as "Away"?

    For the other issues: not receiving any updates. That does sound like a server issue, because SIPE is just listening to the updates from the server. I have never seen or heard about such an issue. I would need to see a --debug log from your client to be convinced otherwise.

     

    Related

    Bugs: #179

  • Robert Szabo
    Robert Szabo
    2013-04-03

    I added myself as a buddy and tried to toggle my status a couple times. The self-buddy contact changed between different states of away, but I couldn't get it to change to Available even though my client was set to Available. It behaved exactly like on other clients.

    I'm not sure what you mean by 'server issue'. There are many hundred users on the same lync server and only pidgin (linux) users have these issues. Windows and MacOS clients don't.

    I will catch the problem again and upload the debug log.

    Cheers,
    Rob

     
    • Stefan Becker
      Stefan Becker
      2013-04-03

      but I couldn't get it to change to Available even though my client was set to Available

      Have you tried the menu Accounts -> OC account -> Reset status?

      I'm not sure what you mean by 'server issue'.

      I mean that after subscribing to the buddies SIPE doesn't do anything else than waiting for BENOTIFY messages arriving from the server with buddy status updates. You are saying that your log doesn't show any BENOTIFY after a certain point in time, so there must be a reason why the server stops sending them to your account.

      The only pure speculation I have right now is that this "point in time" you are describing might be the full re-authentication to the server and that the server then forgets all our subscriptions. I.e. you would see in the log some of these messages:

      1. "+reauthentication" timer expired
      2. "sipe: do a full reauthentication"
      3. "sipe: process_register_response: RE-REGISTER rejected, triggering re-authentication"

      That's why I need to see the full log. case (1) you could force by reducing the time for the time down from 8 hours to e.g. 30 minutes in the code, to see if the issue happens faster.

      If you don't feel comfortable to post the log, then please email it (or the link to the pastebin page).

       
  • Robert Szabo
    Robert Szabo
    2013-04-04

    I've tried the Accounts->OC account->Reset status but all it seemingly did was to reset status to Available. If I changed my status again to Away and back to Available, the self-buddy stayed on Away. It didn't change to Available until I went to OC account->Reset status again.

    I've now created a test user with only 4 buddies (including self). I'll reproduce the BENOTIFY missing problem and will send you the debug logs.

    Thanks again for spending time troubleshooting this!

    Rob

     
    • Stefan Becker
      Stefan Becker
      2013-04-04

      the self-buddy stayed on Away.

      Well, if this is after BENOTIFY's stop to arrive, then I'm not surprised.

      Just to be complete: after trying to reset your status, can you open "Manage accounts" and disable and then re-enable the OC account? I bet that after the reconnect the self-buddy has the status Available, correct?

       
  • Robert Szabo
    Robert Szabo
    2013-04-04

    Here are 2 debug logs from the same running pidgin process taken at different times:

    pidgin-status-problem-anon.log:
    Should show the self-buddy (sip:systest2) being out of sync to the client itself. Self-buddy follows the client's status except for Available. It only goes to Available if the account is manually reset. (I have to mention that disabling and re-enabling the account as you suggested in your post fixes the problem altogether. All status changes will then be reflected on the self-buddy.)

    pidgin-status-problem-anon-2.log:
    This should show that some BENOTIFY messages do not arrive to the client.
    I toggled a remote client (sip:robert-sz) between Available->Away->Do-not-disturb->Available
    But the client was only notified of Available->Do-not-disturb->Available

    Let me know if you need more logs to investigate or if I missed something.

    Thanks,
    Rob

     
    Last edit: Robert Szabo 2013-04-04
    Attachments
    • Stefan Becker
      Stefan Becker
      2013-04-05

      Sorry for the late reply. Thanks for the logs. Using a test user is very helpful, because the log doesn't contain so much junk.

      I didn't look at the first log yet, but I found something in the second log. At some point our SUBSCRIPTION to "roaming self" expires and SIPE apparently does not re-subscribe to it. Here is the last one SIPE receives (search the log for Call-ID: 1001g1832a3079i2904m80F7t83FCb77B5xBF8Ax):

      ...
      (01:25:01) sipe: 
      MESSAGE START <<<<<<<<<< SIP - 2013-04-04T08:25:01.296338Z
      BENOTIFY sip:xx.xx.145.27:39673;transport=tls;ms-opaque=... SIP/2.0
      ...
      Call-ID: 1001g1832a3079i2904m80F7t83FCb77B5xBF8Ax
      CSeq: 109 BENOTIFY
      Require: eventlist
      Content-Type: application/vnd-microsoft-roaming-self+xml
      Event: vnd-microsoft-roaming-self
      subscription-state: active;expires=119
      

      Those appear every 300 seconds (= 5 minutes), which co-incites with the 5 min calendar publish interval.

      My best guess is that re-subscribing is broken. I haven't looked for the code for that, but I have a gut feeling that if this is true for all events we subscribe to, then this could explain a lot of the odd behaviours...

       
1 2 3 > >> (Page 1 of 3)