search

tieto / sipe

A third-party Pidgin plugin for Microsoft Lync/OCS - clone of upstream http://repo.or.cz/w/siplcs.git
GNU General Public License v2.0
129 stars 24 forks source link

Audio window closes and call drops when muting microphone in a group call #122

Open cristim opened 7 years ago

cristim commented 7 years ago

I noticed that in a group conference call, muting the microphone causes the call to drop. The call works as expected as long as the microphone is not muted.

I am running Ubuntu, and I have this version of pidgin-sipe installed from the collab PPA: 1.21.1+sipe-0+201610171930~ubuntu16.04.1

xnandersson commented 7 years ago

Sounds like a spurious correlation. I am using Pidgin SIPE for group conference calls every week and haven't noticed any drops related to mute. I do have started to get faulty audio-connections when I join a conference, and I have to manually enter "join conference audio".

cristim commented 7 years ago

I just updated to the latest version as of today and I am still having this issue just as described.

When looking at the Ubuntu sound preferences, I can see the pidgin process listed in the list of application that are playing or recording audio, but as soon as I press the mute button the call drops and pidgin is instantaneously removed from that list.

Do you have any hints on how I can investigate this further? It is not generating any logging.

Update

xhaakon commented 7 years ago

@cristim Are you connected to Lync or Skype for Business? It seems to me your server doesn't process our modifyEndpointMedia request that Sipe sends upon pressing the mute button and disconnects your call in response.

Could you repeat the steps from your video in Pidgin running with --debug option and capture the created log?

If you have access to the Windows client, I'd be also interested in seeing what it sends to the server when you mute your microphone in the conference. How you enable logging in Microsoft client.

cristim commented 7 years ago

@xhaakon this is SfB

This is the debug output I get immediately after pressing the mute button.

(09:16:20) media: Turning mute on
(09:16:20) sipe: SIP transactions count:1 after addition
(09:16:20) sipe: sip_sec_verify_signature: message is:<TLS-DSK><3D776350><95><SIP Communications Service><pamsfelync10.ad.example.com><BA00g05FFaC1BEiB3F6mA5D3tAFEDb6EF9xAC3Bx><3><INFO><sip:user.name@example.com><5927126899><sip:conf.owner@example.com;gruu;opaque=app:conf:focus:id:43LLSD9S><2D650080><><><><202> signature to verify is:2212f1e9cd3df63ca6b0975c2591618257ee4d40
(09:16:20) sipe: sip_transport_input: signature of incoming message validated
(09:16:20) sipe: process_input_message: msg->response(202),msg->method(INFO)
(09:16:20) sipe: process_input_message: removing CSeq 6
(09:16:20) sipe: SIP transactions count:0 after removal
(09:16:20) sipe: sip_sec_verify_signature: message is:<TLS-DSK><0C46A042><96><SIP Communications Service><pamsfelync10.ad.example.com><BA00g05FFaC1BEiB3F6mA5D3tAFEDb6EF9xAC3Bx><34649><INFO><sip:conf.owner@example.com;gruu;opaque=app:conf:focus:id:43LLSD9S><2D650080><sip:user.name@example.com><5927126899><><><> signature to verify is:ac1fe212669fd780a51f9ceb395790695049b22a
(09:16:20) sipe: sip_transport_input: signature of incoming message validated
(09:16:20) sipe: process_input_message: msg->response(0),msg->method(INFO)
(09:16:20) sipe: process_incoming_info
(09:16:20) sipe: parsing address out of <sip:conf.owner@example.com;gruu;opaque=app:conf:focus:id:43LLSD9S>;tag=2D650080
(09:16:20) sipe: got sip:conf.owner@example.com;gruu;opaque=app:conf:focus:id:43LLSD9S
(09:16:20) sipe: sip_sec_verify_signature: message is:<TLS-DSK><96EFF953><97><SIP Communications Service><pamsfelync10.ad.example.com><7F6Fg2A73a7D99iD223mF4FEt968Eb4074xB0DCx><8><NOTIFY><sip:conf.owner@example.com;gruu;opaque=app:conf:focus:id:43LLSD9S><8A660080><sip:user.name@example.com><4066765455><><><> signature to verify is:d5878bf7698bf8cce781712ce4117e0c66be551b
(09:16:20) sipe: sip_transport_input: signature of incoming message validated
(09:16:20) sipe: process_input_message: msg->response(0),msg->method(NOTIFY)
(09:16:20) sipe: send->process_incoming_notify
(09:16:20) sipe: process_incoming_notify: subscription_state: active;expires=3600
(09:16:20) sipe: sipe_dialog_find who='sip:conf.owner@example.com;gruu;opaque=app:conf:chat:id:43LLSD9S'
(09:16:20) sipe: sipmsg_strip_headers: removing Authentication-Info
(09:16:20) sipe: sipmsg_strip_headers: removing Max-Forwards
(09:16:20) sipe: sipmsg_strip_headers: removing Content-Length
(09:16:20) sipe: sipmsg_strip_headers: removing Content-Type
(09:16:20) sipe: sipmsg_strip_headers: removing Event
(09:16:20) sipe: sipmsg_strip_headers: removing subscription-state
(09:16:20) sipe: sipmsg_strip_headers: removing Supported
(09:16:20) sipe: sip_sec_verify_signature: message is:<TLS-DSK><5805A8AA><98><SIP Communications Service><pamsfelync10.ad.example.com><F33Dg8ECDa0CCBi1EDFmB8BDtE408b6588x7F8Bx><1><INVITE><sip:conf.owner@example.com;gruu;opaque=app:conf:audio-video:id:43LLSD9S><16411fcb83><sip:user.name@example.com><268627250><><><> signature to verify is:b6a413f55806022117b423d723931c7eddbb8f92
(09:16:20) sipe: sip_transport_input: signature of incoming message validated
(09:16:20) sipe: process_input_message: msg->response(0),msg->method(INVITE)
(09:16:20) sipe: sipmsg_strip_headers: removing Authentication-Info
(09:16:20) sipe: sipmsg_strip_headers: removing Max-Forwards
(09:16:20) sipe: sipmsg_strip_headers: removing Content-Length
(09:16:20) sipe: sipmsg_strip_headers: removing Contact
(09:16:20) sipe: sipmsg_strip_headers: removing Supported
(09:16:20) sipe: sipmsg_strip_headers: removing Supported
(09:16:20) sipe: sipmsg_strip_headers: removing Supported
(09:16:20) sipe: sipmsg_strip_headers: removing User-Agent
(09:16:20) sipe: sipmsg_strip_headers: removing Content-Type
(09:16:20) sipe: sipmsg_strip_headers: removing ms-diagnostics
(09:16:20) sipe: sipmsg_strip_headers: removing ms-diagnostics-public
(09:16:20) sipe: sipmsg_strip_headers: removing ms-endpoint-location-data
(09:16:20) sipe: sipmsg_strip_headers: removing Session-Expires
(09:16:20) sipe: sipmsg_strip_headers: removing Min-SE
(09:16:20) sipe: sip_sec_verify_signature: message is:<TLS-DSK><9CD5A737><99><SIP Communications Service><pamsfelync10.ad.example.com><F33Dg8ECDa0CCBi1EDFmB8BDtE408b6588x7F8Bx><1><ACK><sip:conf.owner@example.com;gruu;opaque=app:conf:audio-video:id:43LLSD9S><16411fcb83><sip:user.name@example.com><268627250><><><> signature to verify is:b9f01710c7d900c88afc10974d368198690c8382
(09:16:20) sipe: sip_transport_input: signature of incoming message validated
(09:16:20) sipe: process_input_message: msg->response(0),msg->method(ACK)
(09:16:20) sipe: sip_sec_verify_signature: message is:<TLS-DSK><B3472E80><100><SIP Communications Service><pamsfelync10.ad.example.com><7F6Fg2A73a7D99iD223mF4FEt968Eb4074xB0DCx><9><NOTIFY><sip:conf.owner@example.com;gruu;opaque=app:conf:focus:id:43LLSD9S><8A660080><sip:user.name@example.com><4066765455><><><> signature to verify is:c9e9833c2d21edb3c868e5cedf81df3b010bc7af
(09:16:20) sipe: sip_transport_input: signature of incoming message validated
(09:16:20) sipe: process_input_message: msg->response(0),msg->method(NOTIFY)
(09:16:20) sipe: send->process_incoming_notify
(09:16:20) sipe: process_incoming_notify: subscription_state: active;expires=3600
(09:16:20) sipe: sipe_dialog_find who='sip:conf.owner@example.com;gruu;opaque=app:conf:chat:id:43LLSD9S'
(09:16:20) sipe: sipmsg_strip_headers: removing Authentication-Info
(09:16:20) sipe: sipmsg_strip_headers: removing Max-Forwards
(09:16:20) sipe: sipmsg_strip_headers: removing Content-Length
(09:16:20) sipe: sipmsg_strip_headers: removing Content-Type
(09:16:20) sipe: sipmsg_strip_headers: removing Event
(09:16:20) sipe: sipmsg_strip_headers: removing subscription-state
(09:16:20) sipe: sipmsg_strip_headers: removing Supported
(09:16:20) sipe: sip_sec_verify_signature: message is:<TLS-DSK><B7569527><101><SIP Communications Service><pamsfelync10.ad.example.com><F33Dg8ECDa0CCBi1EDFmB8BDtE408b6588x7F8Bx><2><BYE><sip:conf.owner@example.com;gruu;opaque=app:conf:audio-video:id:43LLSD9S><16411fcb83><sip:user.name@example.com><268627250><><><> signature to verify is:ccde93008f30a008fe746a788e6a93f25e0c4e08
(09:16:20) sipe: sip_transport_input: signature of incoming message validated
(09:16:20) sipe: process_input_message: msg->response(0),msg->method(BYE)
(09:16:20) sipe: parsing address out of <sip:conf.owner@example.com;gruu;opaque=app:conf:audio-video:id:43LLSD9S>;epid=43412BBEE3;tag=16411fcb83
(09:16:20) sipe: got sip:conf.owner@example.com;gruu;opaque=app:conf:audio-video:id:43LLSD9S
(09:16:20) gtkmedia: state: 2 sid: audio name: sip:conf.owner@example.com;gruu;opaque=app:conf:audio-video:id:43LLSD9S
(09:16:20) sipe: sipe_media_state_changed_cb: 2 audio sip:conf.owner@example.com;gruu;opaque=app:conf:audio-video:id:43LLSD9S
(09:16:20) gtkmedia: state: 2 sid: audio name: (null)
(09:16:20) sipe: sipe_media_state_changed_cb: 2 audio (null)
(09:16:20) gtkmedia: state: 2 sid: (null) name: sip:conf.owner@example.com;gruu;opaque=app:conf:audio-video:id:43LLSD9S
(09:16:20) sipe: sipe_media_state_changed_cb: 2 (null) sip:conf.owner@example.com;gruu;opaque=app:conf:audio-video:id:43LLSD9S
(09:16:20) gtkmedia: state: 2 sid: (null) name: (null)
(09:16:20) gtkmedia: pidgin_media_dispose
(09:16:20) gtkmedia: pidgin_media_dispose
(09:16:20) gtkmedia: pidgin_media_finalize
(09:16:20) sipe: sipe_media_state_changed_cb: 2 (null) (null)
(09:16:20) sipe: SIP transactions count:1 after addition
(09:16:20) media: purple_media_dispose
(09:16:20) backend-fs2: purple_media_backend_fs2_dispose
(09:16:20) backend-fs2: purple_media_backend_fs2_finalize
(09:16:20) media: purple_media_finalize
(09:16:20) sipe: sipmsg_strip_headers: removing Authentication-Info
(09:16:20) sipe: sipmsg_strip_headers: removing Max-Forwards
(09:16:20) sipe: sipmsg_strip_headers: removing CONTENT-LENGTH
(09:16:20) sipe: sipmsg_strip_headers: removing Contact
(09:16:20) sipe: sipmsg_strip_headers: removing Supported
(09:16:20) sipe: sipmsg_strip_headers: removing Supported
(09:16:20) sipe: sipmsg_strip_headers: removing User-Agent
(09:16:20) sipe: sipmsg_strip_headers: removing ms-diagnostics
(09:16:20) sipe: sipmsg_strip_headers: removing ms-diagnostics-public
(09:16:20) sipe: sipmsg_strip_headers: removing ms-endpoint-location-data
(09:16:20) sipe: process_incoming_bye: couldn't find session. Ignoring
(09:16:20) sipe: sip_sec_verify_signature: message is:<TLS-DSK><41F3003C><102><SIP Communications Service><pamsfelync10.ad.example.com><65CDg0BCBa7BE0i5F1BmCCF5t60FDbB609x31E7x><16><BENOTIFY><sip:user.name@example.com><6E1E0080><sip:user.name@example.com><5663157710><><><> signature to verify is:fc43032a3de6835aa97c51b95f68269b2aa62e91
(09:16:20) sipe: sip_transport_input: signature of incoming message validated
(09:16:20) sipe: process_input_message: msg->response(0),msg->method(BENOTIFY)
(09:16:20) sipe: send->process_incoming_benotify
(09:16:20) sipe: process_incoming_notify: subscription_state: active;expires=27460
(09:16:20) sipe: sipe_ocs2007_process_roaming_self
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: category_names length=2
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: dropping category: legacyInterop
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: dropping category: state
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: dropped category: state
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><1><2> version=5
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><268435456><2> version=3
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><808837405><2> version=1
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: added GHashTable cat=state
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: added key=<state><808837405><2> version=1
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><868593689><2> version=2
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><536870912><2> version=389
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: added to user_state_publications key=<state><536870912><2> version=389
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: added key=<state><536870912><2> version=389
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><1><3> version=5
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><808837405><3> version=1
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: added key=<state><808837405><3> version=1
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><868593689><3> version=2
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><536870912><3> version=389
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: added to user_state_publications key=<state><536870912><3> version=389
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: added key=<state><536870912><3> version=389
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><1><100> version=5
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<legacyInterop><1><100> version=5
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><1><200> version=5
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<legacyInterop><1><200> version=5
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><1><300> version=5
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<legacyInterop><1><300> version=5
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><1><400> version=5
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<legacyInterop><1><400> version=5
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: sipe_private->our_publications size=3
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: single client detected
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: access_level_set=TRUE
(09:16:20) sipe: sipe_status_and_note: switch to 'available' for the account
(09:16:20) sipe: sipe_status_and_note: updating backend status
(09:16:20) sipe: sipe_backend_status_and_note: creating new saved status available '(null)'
(09:16:20) prefs: /purple/savedstatus/default changed, scheduling save.
(09:16:20) sipe: sipe_purple_set_status[CB]: 'available'
(09:16:20) sipe: sipe_purple_set_status[CB]: triggered by core - ignoring
(09:16:20) sipe: sip_sec_verify_signature: message is:<TLS-DSK><DC1C3962><103><SIP Communications Service><pamsfelync10.ad.example.com><06ACg334Aa4558i08E9m8C5FtDD02b8AB2x7D9Bx><1><SERVICE><sip:user.name@example.com><573250632><sip:user.name@example.com><AFBF305D132BA8A8B6EE3E2C176A7595><><><><200> signature to verify is:4f227e9854b6fabdb230edfe0db6801ec812da8f
(09:16:20) sipe: sip_transport_input: signature of incoming message validated
(09:16:20) sipe: process_input_message: msg->response(200),msg->method(SERVICE)
(09:16:20) sipe: process_input_message: we have a transaction callback
(09:16:20) sipe: sipe_ocs2007_process_roaming_self
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: category_names length=2
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: dropping category: legacyInterop
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: dropping category: state
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: dropped category: state
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><1><2> version=5
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><268435456><2> version=3
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><808837405><2> version=1
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: added GHashTable cat=state
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: added key=<state><808837405><2> version=1
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><868593689><2> version=2
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><536870912><2> version=389
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: added to user_state_publications key=<state><536870912><2> version=389
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: added key=<state><536870912><2> version=389
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><1><3> version=5
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><808837405><3> version=1
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: added key=<state><808837405><3> version=1
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><868593689><3> version=2
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><536870912><3> version=389
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: added to user_state_publications key=<state><536870912><3> version=389
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: added key=<state><536870912><3> version=389
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><1><100> version=5
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<legacyInterop><1><100> version=5
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><1><200> version=5
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<legacyInterop><1><200> version=5
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><1><300> version=5
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<legacyInterop><1><300> version=5
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<state><1><400> version=5
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: key=<legacyInterop><1><400> version=5
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: sipe_private->our_publications size=3
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: single client detected
(09:16:20) sipe: sipe_ocs2007_process_roaming_self: access_level_set=TRUE
(09:16:20) sipe: sipe_status_and_note: switch to 'available' for the account
(09:16:20) sipe: process_input_message: removing CSeq 6
(09:16:20) sipe: SIP transactions count:0 after removal

Unfortunately at the moment I don't have time to generate a log using the Windows client.

dlenski commented 7 years ago

@xhaakon: I am having the same problem with a recently Ubuntu nightly build (1.21.1+sipe-0+201612161027~ubuntu16.04.1).

This is an Office365 Skype For Business account (server = sipdir.online.lync.com:443)

My log shows very similar results to @cristim's. As soon as I press mute, something causes the server to hang up my conference call audio connection.

(08:44:45) media: Turning mute on
(08:44:45) sipe: SIP transactions count:1 after addition
(08:44:45) sipe: sip_sec_verify_signature: message is:<TLS-DSK><808F09E9><119><SIP Communications Service><BL20A23FES06.infra.lync.com><7155g1F2Aa1B3AiE08Am99F5tE52EbA819x6F51x><30><NOTIFY><sip:daniel.lenski@mycompany.com><90030080><sip:daniel.lenski@mycompany.com><2839443486><><><> signature to verify is:2de4f36cb3bf8a9c8f4c44739352609687d073e5
(08:44:45) sipe: sip_transport_input: signature of incoming message validated
(08:44:45) sipe: process_input_message: msg->response(0),msg->method(NOTIFY)
(08:44:45) sipe: send->process_incoming_notify
(08:44:45) sipe: process_incoming_notify: subscription_state: active;expires=26535
(08:44:45) sipe: sipe_process_presence: Content-Type: application/msrtc-event-categories+xml
(08:44:45) sipe: process_incoming_notify_rlmi: busy
(08:44:45) blistnodetypes: Updating buddy status for sip:some.body@mycompany.com (Office Communicator)
(08:44:45) sipe: sipmsg_strip_headers: removing ms-user-logon-data
(08:44:45) sipe: sipmsg_strip_headers: removing Authentication-Info
(08:44:45) sipe: sipmsg_strip_headers: removing Max-Forwards
(08:44:45) sipe: sipmsg_strip_headers: removing Content-Length
(08:44:45) sipe: sipmsg_strip_headers: removing ms-telemetry-id
(08:44:45) sipe: sipmsg_strip_headers: removing Require
(08:44:45) sipe: sipmsg_strip_headers: removing Content-Type
(08:44:45) sipe: sipmsg_strip_headers: removing Event
(08:44:45) sipe: sipmsg_strip_headers: removing subscription-state
(08:44:45) sipe: sipmsg_strip_headers: removing Supported
(08:44:45) sipe: sip_sec_verify_signature: message is:<TLS-DSK><F901541F><120><SIP Communications Service><BL20A23FES06.infra.lync.com><A27Cg3622a3B4Ci216DmCC27tD458b75E5x6803x><2><INFO><sip:daniel.lenski@mycompany.com><1388638054><sip:other.person@mycompany.com;gruu;opaque=app:conf:focus:id:5RSWKWBR><70790080><><><><202> signature to verify is:de7aa3e8f7bddbffb6847a10ffcc5c1072c6ddbd
(08:44:45) sipe: sip_transport_input: signature of incoming message validated
(08:44:45) sipe: process_input_message: msg->response(202),msg->method(INFO)
(08:44:45) sipe: process_input_message: removing CSeq 8
(08:44:45) sipe: SIP transactions count:0 after removal
(08:44:45) sipe: sip_sec_verify_signature: message is:<TLS-DSK><07D4CD4E><121><SIP Communications Service><BL20A23FES06.infra.lync.com><A27Cg3622a3B4Ci216DmCC27tD458b75E5x6803x><6632><INFO><sip:other.person@mycompany.com;gruu;opaque=app:conf:focus:id:5RSWKWBR><70790080><sip:daniel.lenski@mycompany.com><1388638054><><><> signature to verify is:3898ec111081f0dad2a768d7e73bac726b0e4b3e
(08:44:45) sipe: sip_transport_input: signature of incoming message validated
(08:44:45) sipe: process_input_message: msg->response(0),msg->method(INFO)
(08:44:45) sipe: process_incoming_info
(08:44:45) sipe: parsing address out of <sip:other.person@mycompany.com;gruu;opaque=app:conf:focus:id:5RSWKWBR>;tag=70790080
(08:44:45) sipe: got sip:other.person@mycompany.com;gruu;opaque=app:conf:focus:id:5RSWKWBR
(08:44:45) sipe: sip_sec_verify_signature: message is:<TLS-DSK><62DF2D1D><122><SIP Communications Service><BL20A23FES06.infra.lync.com><010Cg1B76a1C6Ai4381m2914t7ECEb2AF9x50EDx><25><NOTIFY><sip:other.person@mycompany.com;gruu;opaque=app:conf:focus:id:5RSWKWBR><79670080><sip:daniel.lenski@mycompany.com><201049994><><><> signature to verify is:c57cb3217b394dbfed748683913f95d953ef3330
(08:44:45) sipe: sip_transport_input: signature of incoming message validated
(08:44:45) sipe: process_input_message: msg->response(0),msg->method(NOTIFY)
(08:44:45) sipe: send->process_incoming_notify
(08:44:45) sipe: process_incoming_notify: subscription_state: active;expires=3600
(08:44:45) sipe: sipe_dialog_find who='sip:other.person@mycompany.com;gruu;opaque=app:conf:chat:id:5RSWKWBR'
(08:44:45) sipe: sipmsg_strip_headers: removing ms-user-logon-data
(08:44:45) sipe: sipmsg_strip_headers: removing Authentication-Info
(08:44:45) sipe: sipmsg_strip_headers: removing Max-Forwards
(08:44:45) sipe: sipmsg_strip_headers: removing Content-Length
(08:44:45) sipe: sipmsg_strip_headers: removing ms-telemetry-id
(08:44:45) sipe: sipmsg_strip_headers: removing Content-Type
(08:44:45) sipe: sipmsg_strip_headers: removing Event
(08:44:45) sipe: sipmsg_strip_headers: removing subscription-state
(08:44:45) sipe: sipmsg_strip_headers: removing Supported
(08:44:45) sipe: sip_sec_verify_signature: message is:<TLS-DSK><529C6634><123><SIP Communications Service><BL20A23FES06.infra.lync.com><71C1gD467a1280i705EmCE3At08E1bA4DEx24D6x><1><INVITE><sip:other.person@mycompany.com;gruu;opaque=app:conf:audio-video:id:5RSWKWBR><61129fd8c5><sip:daniel.lenski@mycompany.com><1521061449><><><> signature to verify is:afbc224517cb9c55e830e11dbf2a95bc3171e221
(08:44:45) sipe: sip_transport_input: signature of incoming message validated
(08:44:45) sipe: process_input_message: msg->response(0),msg->method(INVITE)
(08:44:45) g_log: purple_media_candidate_get_port: assertion 'PURPLE_IS_MEDIA_CANDIDATE(candidate)' failed
(08:44:45) g_log: purple_media_candidate_get_base_port: assertion 'PURPLE_IS_MEDIA_CANDIDATE(candidate)' failed
(08:44:45) sipe: sipmsg_strip_headers: removing ms-user-logon-data
(08:44:45) sipe: sipmsg_strip_headers: removing Authentication-Info
(08:44:45) sipe: sipmsg_strip_headers: removing Max-Forwards
(08:44:45) sipe: sipmsg_strip_headers: removing Content-Length
(08:44:45) sipe: sipmsg_strip_headers: removing Contact
(08:44:45) sipe: sipmsg_strip_headers: removing Supported
(08:44:45) sipe: sipmsg_strip_headers: removing Supported
(08:44:45) sipe: sipmsg_strip_headers: removing Supported
(08:44:45) sipe: sipmsg_strip_headers: removing User-Agent
(08:44:45) sipe: sipmsg_strip_headers: removing Content-Type
(08:44:45) sipe: sipmsg_strip_headers: removing ms-diagnostics
(08:44:45) sipe: sipmsg_strip_headers: removing ms-diagnostics-public
(08:44:45) sipe: sipmsg_strip_headers: removing ms-endpoint-location-data
(08:44:45) sipe: sipmsg_strip_headers: removing Session-Expires
(08:44:45) sipe: sipmsg_strip_headers: removing Min-SE
(08:44:45) sipe: sipmsg_strip_headers: removing ms-telemetry-id
(08:44:45) sipe: sip_sec_verify_signature: message is:<TLS-DSK><4867F38A><124><SIP Communications Service><BL20A23FES06.infra.lync.com><71C1gD467a1280i705EmCE3At08E1bA4DEx24D6x><1><ACK><sip:other.person@mycompany.com;gruu;opaque=app:conf:audio-video:id:5RSWKWBR><61129fd8c5><sip:daniel.lenski@mycompany.com><1521061449><><><> signature to verify is:39a10e65725816dbe65d2a23ed9c6d23ee2b0f08
(08:44:45) sipe: sip_transport_input: signature of incoming message validated
(08:44:45) sipe: process_input_message: msg->response(0),msg->method(ACK)
(08:44:46) sipe: sip_sec_verify_signature: message is:<TLS-DSK><F8C90920><125><SIP Communications Service><BL20A23FES06.infra.lync.com><010Cg1B76a1C6Ai4381m2914t7ECEb2AF9x50EDx><26><NOTIFY><sip:other.person@mycompany.com;gruu;opaque=app:conf:focus:id:5RSWKWBR><79670080><sip:daniel.lenski@mycompany.com><201049994><><><> signature to verify is:85f08cf0df6d60272f492d15c4ddebf2cc0b3fe7
(08:44:46) sipe: sip_transport_input: signature of incoming message validated
(08:44:46) sipe: process_input_message: msg->response(0),msg->method(NOTIFY)
(08:44:46) sipe: send->process_incoming_notify
(08:44:46) sipe: process_incoming_notify: subscription_state: active;expires=3600
(08:44:46) sipe: sipe_dialog_find who='sip:other.person@mycompany.com;gruu;opaque=app:conf:chat:id:5RSWKWBR'
(08:44:46) sipe: sipmsg_strip_headers: removing ms-user-logon-data
(08:44:46) sipe: sipmsg_strip_headers: removing Authentication-Info
(08:44:46) sipe: sipmsg_strip_headers: removing Max-Forwards
(08:44:46) sipe: sipmsg_strip_headers: removing Content-Length
(08:44:46) sipe: sipmsg_strip_headers: removing ms-telemetry-id
(08:44:46) sipe: sipmsg_strip_headers: removing Content-Type
(08:44:46) sipe: sipmsg_strip_headers: removing Event
(08:44:46) sipe: sipmsg_strip_headers: removing subscription-state
(08:44:46) sipe: sipmsg_strip_headers: removing Supported
(08:44:46) sipe: sip_sec_verify_signature: message is:<TLS-DSK><3C05AE7E><126><SIP Communications Service><BL20A23FES06.infra.lync.com><71C1gD467a1280i705EmCE3At08E1bA4DEx24D6x><2><BYE><sip:other.person@mycompany.com;gruu;opaque=app:conf:audio-video:id:5RSWKWBR><61129fd8c5><sip:daniel.lenski@mycompany.com><1521061449><><><> signature to verify is:34db6e6ebef9ba91358d098ba1e33bdbe6ac5098
(08:44:46) sipe: sip_transport_input: signature of incoming message validated
(08:44:46) sipe: process_input_message: msg->response(0),msg->method(BYE)
(08:44:46) sipe: parsing address out of <sip:other.person@mycompany.com;gruu;opaque=app:conf:audio-video:id:5RSWKWBR>;epid=6DB5CBC354;tag=61129fd8c5
(08:44:46) sipe: got sip:other.person@mycompany.com;gruu;opaque=app:conf:audio-video:id:5RSWKWBR
(08:44:46) gtkmedia: state: 2 sid: audio name: sip:other.person@mycompany.com;gruu;opaque=app:conf:audio-video:id:5RSWKWBR
(08:44:46) sipe: sipe_media_state_changed_cb: 2 audio sip:other.person@mycompany.com;gruu;opaque=app:conf:audio-video:id:5RSWKWBR
(08:44:46) gtkmedia: state: 2 sid: audio name: (null)
(08:44:46) sipe: sipe_media_state_changed_cb: 2 audio (null)
(08:44:46) gtkmedia: state: 2 sid: (null) name: sip:other.person@mycompany.com;gruu;opaque=app:conf:audio-video:id:5RSWKWBR
(08:44:46) sipe: sipe_media_state_changed_cb: 2 (null) sip:other.person@mycompany.com;gruu;opaque=app:conf:audio-video:id:5RSWKWBR
(08:44:46) gtkmedia: state: 2 sid: (null) name: (null)
(08:44:46) gtkmedia: pidgin_media_dispose
(08:44:46) gtkmedia: pidgin_media_dispose
(08:44:46) gtkmedia: pidgin_media_finalize
(08:44:46) sipe: sipe_media_state_changed_cb: 2 (null) (null)
(08:44:46) sipe: SIP transactions count:1 after addition
(08:44:46) media: purple_media_dispose
(08:44:46) backend-fs2: purple_media_backend_fs2_dispose
(08:44:46) backend-fs2: purple_media_backend_fs2_finalize
(08:44:46) media: purple_media_finalize
(08:44:46) sipe: sipmsg_strip_headers: removing ms-user-logon-data
(08:44:46) sipe: sipmsg_strip_headers: removing Authentication-Info
(08:44:46) sipe: sipmsg_strip_headers: removing Max-Forwards
(08:44:46) sipe: sipmsg_strip_headers: removing CONTENT-LENGTH
(08:44:46) sipe: sipmsg_strip_headers: removing Contact
(08:44:46) sipe: sipmsg_strip_headers: removing Supported
(08:44:46) sipe: sipmsg_strip_headers: removing Supported
(08:44:46) sipe: sipmsg_strip_headers: removing User-Agent
(08:44:46) sipe: sipmsg_strip_headers: removing ms-diagnostics
(08:44:46) sipe: sipmsg_strip_headers: removing ms-diagnostics-public
(08:44:46) sipe: sipmsg_strip_headers: removing ms-endpoint-location-data
(08:44:46) sipe: sipmsg_strip_headers: removing ms-telemetry-id
(08:44:46) sipe: process_incoming_bye: couldn't find session. Ignoring
(08:44:46) sipe: sip_sec_verify_signature: message is:<TLS-DSK><4512FC71><127><SIP Communications Service><BL20A23FES06.infra.lync.com><058Eg4DF4aA866i34FCmD93Dt29F8b6D97xDDC8x><1><SERVICE><sip:daniel.lenski@mycompany.com><4296952839><sip:daniel.lenski@mycompany.com><A06092D4C83D1709DB5A6E8FC6A9E81B><><><><200> signature to verify is:50edea9e10582ee8f27d40b58c54c8ef3a683b06
(08:44:46) sipe: sip_transport_input: signature of incoming message validated
(08:44:46) sipe: process_input_message: msg->response(200),msg->method(SERVICE)
(08:44:46) sipe: process_input_message: we have a transaction callback
(08:44:46) sipe: sipe_ocs2007_process_roaming_self
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: category_names length=2
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: dropping category: legacyInterop
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: dropping category: state
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: dropped category: state
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<state><1><2> version=4
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<state><919232497><2> version=2
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: added GHashTable cat=state
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: added key=<state><919232497><2> version=2
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<state><1187667953><2> version=8
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: hash=<1484841600><Application Developer Standup (20 minutes)><Our Conference Room><1>
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: added key=<state><1187667953><2> version=8
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<state><536870912><2> version=45
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: added to user_state_publications key=<state><536870912><2> version=45
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: added key=<state><536870912><2> version=45
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<state><1><3> version=4
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<state><919232497><3> version=2
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: added key=<state><919232497><3> version=2
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<state><1187667953><3> version=8
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: hash=<1484841600><Application Developer Standup (20 minutes)><Our Conference Room><1>
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: added key=<state><1187667953><3> version=8
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<state><536870912><3> version=45
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: added to user_state_publications key=<state><536870912><3> version=45
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: added key=<state><536870912><3> version=45
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<state><1><100> version=4
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<legacyInterop><1><100> version=4
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<state><1><200> version=4
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<legacyInterop><1><200> version=4
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<state><1><300> version=4
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<legacyInterop><1><300> version=4
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<state><1><400> version=4
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<legacyInterop><1><400> version=4
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: sipe_private->our_publications size=3
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: single client detected
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: access_level_set=TRUE
(08:44:46) sipe: sipe_status_and_note: switch to 'busy' for the account
(08:44:46) sipe: process_input_message: removing CSeq 8
(08:44:46) sipe: SIP transactions count:0 after removal
(08:44:46) sipe: sip_sec_verify_signature: message is:<TLS-DSK><DF203247><128><SIP Communications Service><BL20A23FES06.infra.lync.com><D2D6g4400a3F81iE48Cm935Dt585Ab5A91xF7FEx><13><NOTIFY><sip:daniel.lenski@mycompany.com><DC140080><sip:daniel.lenski@mycompany.com><3199032583><><><> signature to verify is:e6280d75efff36c4465f93b5403870a98a096072
(08:44:46) sipe: sip_transport_input: signature of incoming message validated
(08:44:46) sipe: process_input_message: msg->response(0),msg->method(NOTIFY)
(08:44:46) sipe: send->process_incoming_notify
(08:44:46) sipe: process_incoming_notify: subscription_state: active;expires=31454
(08:44:46) sipe: sipe_ocs2007_process_roaming_self
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: category_names length=2
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: dropping category: legacyInterop
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: dropping category: state
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: dropped category: state
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<state><1><2> version=4
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<state><919232497><2> version=2
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: added GHashTable cat=state
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: added key=<state><919232497><2> version=2
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<state><1187667953><2> version=8
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: hash=<1484841600><Application Developer Standup (20 minutes)><Our Conference Room><1>
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: added key=<state><1187667953><2> version=8
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<state><536870912><2> version=45
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: added to user_state_publications key=<state><536870912><2> version=45
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: added key=<state><536870912><2> version=45
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<state><1><3> version=4
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<state><919232497><3> version=2
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: added key=<state><919232497><3> version=2
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<state><1187667953><3> version=8
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: hash=<1484841600><Application Developer Standup (20 minutes)><Our Conference Room><1>
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: added key=<state><1187667953><3> version=8
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<state><536870912><3> version=45
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: added to user_state_publications key=<state><536870912><3> version=45
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: added key=<state><536870912><3> version=45
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<state><1><100> version=4
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<legacyInterop><1><100> version=4
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<state><1><200> version=4
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<legacyInterop><1><200> version=4
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<state><1><300> version=4
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<legacyInterop><1><300> version=4
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<state><1><400> version=4
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: key=<legacyInterop><1><400> version=4
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: sipe_private->our_publications size=3
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: single client detected
(08:44:46) sipe: sipe_ocs2007_process_roaming_self: access_level_set=TRUE
(08:44:46) sipe: sipe_status_and_note: switch to 'busy' for the account
(08:44:46) sipe: sipmsg_strip_headers: removing ms-user-logon-data
(08:44:46) sipe: sipmsg_strip_headers: removing Authentication-Info
(08:44:46) sipe: sipmsg_strip_headers: removing Max-Forwards
(08:44:46) sipe: sipmsg_strip_headers: removing Content-Length
(08:44:46) sipe: sipmsg_strip_headers: removing ms-telemetry-id
(08:44:46) sipe: sipmsg_strip_headers: removing Require
(08:44:46) sipe: sipmsg_strip_headers: removing Content-Type
(08:44:46) sipe: sipmsg_strip_headers: removing Event
(08:44:46) sipe: sipmsg_strip_headers: removing subscription-state
(08:44:46) sipe: sipmsg_strip_headers: removing Supported
gjfoster commented 6 years ago

Seeing the same issue here. Ubuntu 16.04 with the following: 1.21.1+sipe+stable1-1~ubuntu16.04.1

cervaens commented 6 years ago

Same here. Any news on this?