Adium

Opened 4 years ago

Closed 4 years ago

Last modified 3 years ago

#16345 closed defect (fixed)

1.5.6 breaks Sametime support - 'Login verification down or unavailable'

Reported by: bstreiff Owned by:
Milestone: Adium 1.5.8 Component: Service/Sametime
Version: 1.5.6 Severity: regression
Keywords: Cc: jricesterenator
Patch Status:

Description

Summary

Upon upgrading from Adium 1.5.4 to 1.5.6, attempting to connect to a Sametime network gives an error 'Login verification down or unavailable.'

Steps to reproduce

  1. Connect to a Sametime network using Adium 1.5.4 to verify that such a connection works.
  2. Upgrade to 1.5.6.
  3. Attempt to connect to the same network (using saved settings) with Adium 1.5.6. You'll get the above error.

Expected results

I expected the connection to succeed.

Actual results

I got an error dialog with the text 'Login verification down or unavailable.'

Regression

The problem occurs with Adium 1.5.6 on OS X 10.7.5.
The problem does not occur with Adium 1.5.4 on same. A workaround is to downgrade to this version.

Notes

(I have anonymized my username and the server name with USERNAME and SERVERNAME as appropriate.)

This is the log of a connection failing in 1.5.6.

Opened debug log at 2013-03-18 14:58:37 -0500
14:58:40: <ESPurpleMeanwhileAccount:7a27430 5>:USERNAME: Original image of size 218.000000 218.000000
14:58:40: -[CBPurpleAccount setAccountUserImage:withData:]:2717: <ESPurpleMeanwhileAccount:7a27430 5>:USERNAME: Setting icon data of length 0
14:58:40: <ESPurpleMeanwhileAccount:7a27430 5>:USERNAME: Updating status for key: User Icon
14:58:40: Adium: Connect: USERNAME initiating connection using status state <AIStatus: 7a12870 [Available]> ((null)).
14:58:40: Setting status on 8d2b020 (USERNAME): ID active, isActive 1, attributes {
}
14:58:40: (Libpurple: account) Connecting to account USERNAME.
14:58:40: (Libpurple: connection) Connecting. gc = 0x108f073f0
14:58:40: (Libpurple: meanwhile) adding cipher RC2/40 Cipher
14:58:40: (Libpurple: meanwhile) adding cipher RC2/128 Cipher
14:58:40: (Libpurple: sametime) user: 'USERNAME'
14:58:40: (Libpurple: sametime) host: 'SERVERNAME'
14:58:40: (Libpurple: sametime) port: 1533
14:58:40: (Libpurple: sametime) client id: 0x1002
14:58:40: (Libpurple: sametime) client major: 0x001e
14:58:40: (Libpurple: sametime) client minor: 0x196f
14:58:40: Connecting: gc=0x8f073f0 (Connecting) 1 / 11
14:58:40: (Libpurple: dnsquery) Performing DNS lookup for SERVERNAME
14:58:40: <ESPurpleMeanwhileAccount:7a27430 5>:USERNAME: Updating status for key: isOnline
14:58:40: ************ USERNAME --step-- 1
14:58:40: -[AdiumPurpleDnsRequest startLookup]:198: Performing DNS resolve: SERVERNAME:1533
14:58:40: DNS resolve complete for SERVERNAME:1533; 1 addresses returned
14:58:40: (Libpurple: dnsquery) IP resolved for SERVERNAME
14:58:40: (Libpurple: proxy) Attempting connection to 123.45.67.89
14:58:40: (Libpurple: proxy) Connecting to SERVERNAME:1533 with no proxy
14:58:40: (Libpurple: proxy) Connection in progress
14:58:40: (Libpurple: proxy) Connecting to SERVERNAME:1533.
14:58:40: (Libpurple: proxy) Connected to SERVERNAME:1533.
14:58:40: (Libpurple: meanwhile) session state: starting
14:58:40: Connecting: gc=0x8f073f0 (Sending Handshake) 2 / 11
14:58:40: (Libpurple: meanwhile) session state: handshake sent
14:58:40: Connecting: gc=0x8f073f0 (Waiting for Handshake Acknowledgement) 3 / 11
14:58:40: ************ USERNAME --step-- 2
14:58:40: ************ USERNAME --step-- 3
14:58:40: (Libpurple: meanwhile) session state: handshake acknowledged
14:58:40: Connecting: gc=0x8f073f0 (Handshake Acknowledged, Sending Login) 4 / 11
14:58:40: (Libpurple: meanwhile) Sametime server version (major/minor): 0x1e / 0x1f4a
14:58:40: (Libpurple: meanwhile) session state: login sent
14:58:40: Connecting: gc=0x8f073f0 (Waiting for Login Acknowledgement) 5 / 11
14:58:40: ************ USERNAME --step-- 4
14:58:40: ************ USERNAME --step-- 5
14:58:40: (Libpurple: meanwhile) session state: stopping (0x80000214)
14:58:40: (Libpurple: connection) Connection error on 0x108f073f0 (reason: 3 description: Login verification down or unavailable)
14:58:40: Connection Disconnected: gc=8f073f0 (Login verification down or unavailable)
14:58:40: <ESPurpleMeanwhileAccount:7a27430 5>:USERNAME accountConnectionReportDisconnect: Login verification down or unavailable
14:58:40: (Libpurple: meanwhile) session state: stopped (0x80000214)
14:58:41: (Libpurple: account) Disconnecting account USERNAME (0x108d2b020)
14:58:41: (Libpurple: connection) Disconnecting connection 0x108f073f0
14:58:41: (Libpurple: meanwhile) attempted to stop session that is already stopped/stopping
14:58:41: Disconnected: gc=8f073f0
14:58:41: <ESPurpleMeanwhileAccount:7a27430 5>:USERNAME: Telling the core we disconnected
14:58:41: -[AIContactObserverManager endListObjectNotificationsDelaysImmediately]:144: 
14:58:41: <ESPurpleMeanwhileAccount:7a27430 5>:USERNAME: Disconnected: Will not reconnect
14:58:41: Posting Growl notification: Event ID: Interface_ErrorMessageReceived, listObject: (null), chat: (null), description: USERNAME (Sametime) : Error
Login verification down or unavailable
14:58:41: (Libpurple: connection) Destroying connection 0x108f073f0
14:58:45: (Libpurple: util) Writing file accounts.xml to directory /Users/USERNAME/Library/Application Support/Adium 2.0/Users/Default/libpurple
14:58:45: (Libpurple: util) Writing file /Users/USERNAME/Library/Application Support/Adium 2.0/Users/Default/libpurple/accounts.xml
14:58:55: -[AIListWindowController adiumFrameAutosaveName]:167: My autosave name is Contact List:ROOTJKSHFOEIZNGIOEOP

Here's the same bit from 1.5.4, where it works:

15:07:03: -[AIAccount(Abstract) retrievePasswordThenConnect]:448: Retrieving <ESPurpleMeanwhileAccount:7974fa0 5>:USERNAME password (promptOption 0)
15:07:03: <ESPurpleMeanwhileAccount:7974fa0 5>:USERNAME: Updating status for key: isOnline
15:07:03: <ESPurpleMeanwhileAccount:7974fa0 5>:USERNAME: Original image of size 218.000000 218.000000
15:07:03: -[CBPurpleAccount setAccountUserImage:withData:]:2717: <ESPurpleMeanwhileAccount:7974fa0 5>:USERNAME: Setting icon data of length 0
15:07:03: <ESPurpleMeanwhileAccount:7974fa0 5>:USERNAME: Updating status for key: User Icon
15:07:03: Adium: Connect: USERNAME initiating connection using status state <AIStatus: 793ac90 [Available]> ((null)).
15:07:03: Setting status on 94451d0 (USERNAME): ID active, isActive 1, attributes {
}
15:07:03: (Libpurple: account) Connecting to account USERNAME.
15:07:03: (Libpurple: connection) Connecting. gc = 0x1094c1420
15:07:03: (Libpurple: meanwhile) adding cipher RC2/40 Cipher
15:07:03: (Libpurple: meanwhile) adding cipher RC2/128 Cipher
15:07:03: (Libpurple: sametime) user: 'USERNAME'
15:07:03: (Libpurple: sametime) host: 'SERVERNAME'
15:07:03: (Libpurple: sametime) port: 1533
15:07:03: (Libpurple: sametime) client id: 0x1002
15:07:03: (Libpurple: sametime) client major: 0x001e
15:07:03: (Libpurple: sametime) client minor: 0x196f
15:07:03: Connecting: gc=0x94c1420 (Connecting) 1 / 11
15:07:03: (Libpurple: dnsquery) Performing DNS lookup for SERVERNAME
15:07:03: (Libpurple: account) Connecting to account USERNAME.
15:07:03: ************ USERNAME --step-- 1
15:07:03: -[AdiumPurpleDnsRequest startLookup]:198: Performing DNS resolve: SERVERNAME:1533
15:07:03: DNS resolve complete for SERVERNAME:1533; 1 addresses returned
15:07:03: (Libpurple: dnsquery) IP resolved for SERVERNAME
15:07:03: (Libpurple: proxy) Attempting connection to 130.164.14.254
15:07:03: (Libpurple: proxy) Connecting to SERVERNAME:1533 with no proxy
15:07:03: (Libpurple: proxy) Connection in progress
15:07:03: (Libpurple: proxy) Connecting to SERVERNAME:1533.
15:07:03: (Libpurple: proxy) Connected to SERVERNAME:1533.
15:07:03: (Libpurple: meanwhile) session state: starting
15:07:03: Connecting: gc=0x94c1420 (Sending Handshake) 2 / 11
15:07:03: (Libpurple: meanwhile) session state: handshake sent
15:07:03: Connecting: gc=0x94c1420 (Waiting for Handshake Acknowledgement) 3 / 11
15:07:03: ************ USERNAME --step-- 2
15:07:03: ************ USERNAME --step-- 3
15:07:03: (Libpurple: meanwhile) session state: handshake acknowledged
15:07:03: Connecting: gc=0x94c1420 (Handshake Acknowledged, Sending Login) 4 / 11
15:07:03: (Libpurple: meanwhile) Sametime server version (major/minor): 0x1e / 0x1f4a
15:07:03: (Libpurple: meanwhile) session state: login sent
15:07:03: Connecting: gc=0x94c1420 (Waiting for Login Acknowledgement) 5 / 11
15:07:03: ************ USERNAME --step-- 4
15:07:03: ************ USERNAME --step-- 5
15:07:03: (Libpurple: meanwhile) session state: login acknowledged
15:07:03: Connecting: gc=0x94c1420 (Login Acknowledged) 8 / 11

Change History (32)

comment:1 follow-up: Changed 4 years ago by bstreiff

I marked the version as '1.5.5' here because there wasn't an option for '1.5.6'.

comment:2 in reply to: ↑ 1 Changed 4 years ago by sphynx

  • Version changed from 1.5.5 to 1.5.6

Replying to bstreiff:

I marked the version as '1.5.5' here because there wasn't an option for '1.5.6'.

Okay, fixed that.

comment:3 Changed 4 years ago by Robby

  • Component changed from Adium Core to Service/Sametime
  • Keywords sametime removed
  • Milestone Adium 1.5.x deleted

Please don't set the milestone unless you plan to fix the ticket.

We also got a report for this via feedback email.

comment:4 Changed 4 years ago by Robby

  • Milestone set to Adium 1.5.7

comment:5 Changed 4 years ago by houchin

I am seeing the same problem, running on Mac OS X 10.6.8. Downgrading to Adium 1.5.4 also solved the problem. In addition to my Sametime account, I also log into a GoogleTalk account, and that login was unaffected.

comment:6 Changed 4 years ago by sphynx

Ticket #16347 has been marked as a duplicate of this ticket.

comment:7 Changed 4 years ago by realityczar

I see the same problem running OS X 10.8.2. GoogleTalk, AIM and MobileMe logins are unaffected.

comment:8 Changed 4 years ago by sphynx

The only change that springs to mind that could cause this is https://hg.pidgin.im/pidgin/main/rev/c31cf8de31cd.

comment:9 Changed 4 years ago by David Munch

Ticket #16348 has been marked as a duplicate of this ticket.

comment:10 Changed 4 years ago by algal000

I'm seeing the same problem on OS X 10.8.3.

I am not familiar with this codebase at all, but I noticed a few points that might help others who know better:

  1. the working adium logs an update to "isOnline", then logs "Connecting to account USERNAME" two times, once before and once after connecting to the server. The broken adium logs only one "Connecting to account USERNAME", before the connection to the server.
  1. the broken adium is setting "isOnline" later, seemingly instead of trying to "Connect to account".
  1. re: change in sametime.c from strncpy to g_strlcpy. The main behavioral difference between these functions is that g_strlcpy doesn't pad the destination buffer. This is based on the docs at https://developer.gnome.org/glib/2.28/glib-String-Utility-Functions.html#g-strlcpy and at http://linux.die.net/man/3/strncpy . Maybe if the argument id was not properly null-terminated in the old version, strncpy was inadvertently fixing this by padding with nulls, while g_strlcpy doesn't fix that?

These points may be totally irrelevant but I thought I'd add them in case wiser heads than me can make use of them.

comment:11 Changed 4 years ago by gregrebholz

Same problem here. Upgraded from 1.5.4 to 1.5.6 and Sametime can no longer connect. OSX 10.8.3. I generated a debug log but other than hex addresses the output is identical to the above. I have to downgrade to work around, but I'm open to testing again if needed.

comment:12 Changed 4 years ago by rrspurlock

I'm currently able to reproduce this also with 1.5.6. Downgrading to v1.5.4 allows me to successfully connect to Sametime servers.

comment:13 Changed 4 years ago by XianPalin

Just for the record, this is still occurring in 1.5.7

comment:14 Changed 4 years ago by Robby

Yes, the issue is still being looked into.

comment:15 Changed 4 years ago by Robby

  • Milestone changed from Adium 1.5.7 to Adium 1.5.8

1.5.7 has been released so I'm pushing all the issues which haven't been fixed yet.

comment:16 Changed 4 years ago by sphynx

Ticket #16428 has been marked as a duplicate of this ticket.

comment:17 Changed 4 years ago by vapourick

I just upgraded to 1.5.7 and I'm now getting this same problem.

comment:18 Changed 4 years ago by Robby

  • Cc jricesterenator added

All versions after 1.5.4 are affected. There's no fix yet, I'm afraid.

comment:19 Changed 4 years ago by jricesterenator

I think I've got it. For whatever reason, Sametime doesn't work when you build meanwhile with Clang, but it works fine using gcc (whichever is in homebrew). I verified this against Adium 1.5.5 when Sametime first broke and against the lastest Adium.

Fix: In meanwhile.rb, add ENV['CC'] = 'gcc' and rebuild. (Patch: https://gist.github.com/jricesterenator/5959974). Without knowing the actual problem, I don't know what a proper solution would be.
Thijs, can you make a nightly with this?

Why is this happening? I'm not sure. I hex dumped the Sametime login messages, and the main parts are the same when it works/doesn't. There's some kind of key exchange in there, so maybe the calculations are coming out differently? There's a dummy login server in the meanwhile source that I can login to in all scenarios; a real Sametime server must be pickier.

If anyone's interested in the initial investigation or for a discussion on building Adium dependencies, see "Trouble compiling libpurple for debugging Sametime regression" in the May and June mailing list archives.
https://adium.im/pipermail/devel_adium.im/2013-May/thread.html
https://adium.im/pipermail/devel_adium.im/2013-June/thread.html

comment:20 Changed 4 years ago by Thijs Alkemade <me@…>

  • Resolution set to fixed
  • Status changed from new to closed

(In d40510e6c20e) Updated a number of dependencies and rebuilt meanwhile with GCC instead of clang.

Fixes #16345

comment:21 Changed 4 years ago by sphynx

There is now a nightly available with this change here: http://nightly.adium.im/adium-adium-1.5.8/Adium_1.5.8hgr5671.dmg.

Please try this and let us know wether it works!

Edit: Oh, nevermind. This build has some other problems with libintl. Please give me a minute to fix that.

Last edited 4 years ago by sphynx (previous) (diff)

comment:22 Changed 4 years ago by sphynx

Okay, a fixed nightly is now available here: http://nightly.adium.im/adium-adium-1.5.8/Adium_1.5.8hgr5673.dmg.

comment:23 Changed 4 years ago by houchin

1.5.8hgr5673 worked for me.

comment:24 Changed 4 years ago by XianPalin

1.5.8hgr5673 works for me as well.

comment:25 Changed 4 years ago by bstreiff

I can also confirm that 1.5.8hgr5673 works. Thanks!

comment:26 Changed 3 years ago by erikzaadi

+1 on 1.5.8hgr5673 , works like a boss

comment:27 Changed 3 years ago by mjmjmj

1.5.8hgr5673 works for me as well. Thanks very much!

comment:28 Changed 3 years ago by nihar

Looks like the latest 1.7 nightly build breaks this again...

comment:29 Changed 3 years ago by adregner

Sametime was connecting fine for me in 1.5.10b1 however I needed to start using a 1.6 nightly version to get access to other features, but this issue came up again. Same symptoms.

comment:30 Changed 3 years ago by Robby

The fix for 1.5.x has not been ported to 1.6hg and 1.7hg yet.

comment:31 Changed 3 years ago by adregner

Can that get ported into the 1.6 branch so I can try a newer nightly? I tried porting it myself but my mercurial and Adium development skills are next to nil and I had all sorts of random additional issues.

comment:32 Changed 3 years ago by Robby

It will happen at some point.

Note: See TracTickets for help on using tickets.