Connection Lost

[Cronos]

Some day ago started a problem with the log in

some time, the log in return me "Disconnected: Lost connection with the server"
so, i started retrying until it doesn't log in me

but, now, it NEVER log in

i were logged in 2 hours ago, now it dont let me log in


i tryed to check "connection througt port 80" and it let me to log in, but when i try to chat with someone it seemd that it cant receive some information from the contact and i can't send messages

the connection is mine, no firewall, only a router, i changed nothing in the configuration..

( i take a look in other topic and i seen that this log could be usefull )

[16:07:47] Catch in proc trans (title ): can't read "lang(title)": no such variable
[16:07:47] Catch in proc trans (followtext ): can't read "lang(followtext)": no such variable
[16:07:47] Catch in proc trans (filters ): can't read "lang(filters)": no such variable
[16:07:47] Catch in proc trans (savetofile ): can't read "lang(savetofile)": no such variable
[16:07:47] Catch in proc trans (clear ): can't read "lang(clear)": no such variable
[16:07:47] Catch in proc trans (close ): can't read "lang(close)": no such variable
[16:07:47] No LANG environment variable. Using en
[16:07:47] LoadLoginList: starting
[16:07:47] LoadLoginList: HOME=C:/Documents and Settings/Administrator/amsn, HOME2=C:/Documents and Settings/Administrator/amsn, HOMEE=C:/Documents and Settings/Administrator/amsn
[16:07:47] LoadLoginList: adding profile -censored- with lock num 0
[16:07:47] LoadLoginList: getting an initial profile
[16:07:47] CheckLock: LoginList getlock called. Lock=0
[16:07:47] CheckLock: Port is zero
[16:07:47] LockProfile: Locking -censored-
[16:07:47] LockProfile: Got random port 62507
[16:07:47] LoadLoginList: profile -censored- is free, locking
[16:07:47] LoadLoginList: we found a free profile: -censored-
[16:07:47] load_config: Started. HOME=C:/Documents and Settings/Administrator/amsn/-censored-, config(login)=cronos@clandelta.net
[16:07:47] load_config: loading file C:/Documents and Settings/Administrator/amsn/-censored-/config.xml
[16:07:47] load_config: Config loaded
[16:07:47] PLUGIN : Nudge
[16:07:47] load_lang called from a plugin
[16:07:47] load_lang called from a plugin
[16:07:47] Catch in proc trans (add_clmenuitem ): can't read "lang(add_clmenuitem)": no such element in array
[16:07:47] PLUGIN : Cam Shooter
[16:07:47] load_lang called from a plugin
[16:07:47] load_lang called from a plugin
[16:07:47] PLUGIN : remind
[16:07:47] load_lang called from a plugin
[16:07:47] load_lang called from a plugin
[16:07:47] PLUGIN : aMSN Plus
[16:07:47] PLUGIN : Organize Received Files
[16:07:47] load_my_pic: Trying to set display picture 141987633845129cb601bb0.png
[16:07:47] skin aDarwin V.4 's scrollbar loaded
[16:07:47] Event --changedSkin-- fired with caller -gui-- and args :
[16:07:47] Event --show_login_screen-- fired with caller -gui-- and args :
[16:07:47] logging out, creating loginscreen : show_login_screen
[16:07:47] LoadLoginList: starting
[16:07:47] LoadLoginList: getting profiles
[16:07:47] LoadLoginList: HOME=C:/Documents and Settings/Administrator/amsn/cronos_clandelta_net, HOME2=C:/Documents and Settings/Administrator/amsn, HOMEE=C:/Documents and Settings/Administrator/amsn
[16:07:47] LoadLoginList: adding profile -censored- with lock num 62507
[16:07:47] ConfigChange: -censored-
[16:07:47] ConfigChange: Valid email
[16:07:48] lockSvrNew: Accepting connection on port 1274
[16:07:54] lockSvrHdl: handling connection
[16:07:54] lockSvrHdl: PING - PONG
[16:07:54] lockSvrHdl: handling connection
[16:08:02] registering http secure socket
[16:08:02] Event --loggingIn-- fired with caller -protocol-- and args :
[16:08:02] logging in, destroying loginscreen : loggingIn
[16:08:02] cmsn_auth starting, stat=a
[16:08:02] cmsn_auth starting, stat=v
[16:08:02] cmsn_auth starting, stat=i
[16:08:02] cmsn_ns_handler: got a NS transfer, reconnecting to 207.46.110.63!
[16:08:02] cmsn_auth starting, stat=a
[16:08:03] gotNexusReply: loginurl=https://login.live.com/login2.srf
[16:08:03] gotNexusReply: finished before authentication took place
[16:08:03] cmsn_auth starting, stat=v
[16:08:03] cmsn_auth starting, stat=i
[16:08:03] cmsn_auth starting, stat=u
[16:08:03] cmsn_auth_msnp9: Nexus has replied so we have login URL...
[16:08:03] ::DirectConnection::authenticate: Getting https://login.live.com/login2.srf
[16:08:04] ::DirectConnection::GotAuthReply 200 Ticket= t=9hVMJTRQIAjesfnDzqXRn8Kru2ASJuZJiU3!Pp1KO!Mb45f!*kEORe1zU0cmPgtgHFSYYnYsUXWVxeKMGnpBBIXapU0tFtGOhT8o02b6F*fkuYnusSrfST32ueij7*KFIWAEj0uao8xQk$&p=9GgJB9xgdFmvIBvpNfHM66oW0rYqtRJjAVDU4MCg45LLMLjhbsVxqYAq6S8DQGrzUn3qMJcleZ95FHsdUHdP3JCXbZ0HBMFBx1SCC5D1KnhChwdpjKgw30Uk*bN3Ujow1JgA46pzMCdc1FHsjXa*IlCWskEFTG9FhkpyfM*bkGcojegrsnrYzEzA$$
[16:08:05] cmsn_auth starting, stat=us
[16:08:05] save_config: saving config for user -censored- in C:/Documents and Settings/Administrator/amsn/-censored-]
[16:08:05] save_config: saving config_file. Opening of file returned : file2e37618
[16:08:05] save_config: Config saved
[16:08:05] Loading address book data...
[16:08:07] Address book data loaded...
[16:08:07] Event --loggedIn-- fired with caller -protocol-- and args :
[16:08:07] Got unknown NS input!! --> SBS
   SBS 0 null
[16:08:07] Getting demographic and auth information
[16:08:07] Getting local IP
[16:08:07] Finished
[16:08:07] ::abook::getFirewalled: Connecting to 84.222.118.155 port 6891
[16:08:07] Connecting to http://www.amsn-project.net/check_connectivity.php?port=6891&id=8616
[16:08:07] ::abook::gotConnectivityReply ok : 0
[16:08:07] ::abook::getFirewalled: connection_success (0)
[16:08:07] ::abook::getFirewalled: connection_success (0)
[16:08:07] My IP is 84.222.118.155
[16:08:08] cmsn_ns_handler: evaluating handler for 8
[16:08:08] new_contact_list: new contact list version : 2007-10-05T07:34:50.543-07:00 --- previous was : 2007-10-05T07:34:50.543-07:00
[16:08:08] Going to receive contact list
[16:08:08] ----
[16:08:08] id:24125311-7861-43ae-9303-134d42992391
[16:08:08] name:5%20-%20Wc3
[16:08:08] users:
[16:08:08] ----
[16:08:08] id:49f58b9f-3bc4-4fba-83a9-208a4884d929
[16:08:08] name:2%20-%20Ally
[16:08:08] users:
[16:08:08] ----
[16:08:08] id:69be452c-1cd9-418f-a896-99aeeed9ee26
[16:08:08] name:3%20-%20Uni
[16:08:08] users:
[16:08:08] ----
[16:08:08] id:e8b27fe7-58b1-4835-b483-99bf898e751d
[16:08:08] name:1%20-%20ViP
[16:08:08] users:
[16:08:08] ----
[16:08:08] id:e599c89e-beb8-46d5-80a8-d1a8c40549f1
[16:08:08] name:4%20-%20General
[16:08:08] users:
[16:08:08] Event --contactlistLoaded-- fired with caller -protocol-- and args :
[16:08:09] Sending SOAP request to http://storage.msn.com/storageservice/schematizedstore.asmx with action http://www.msn.com/webservices/storage/w10/GetItemVersion
[16:08:09] Hotmail: 0 unread emails
[16:08:09] Hotmail: 0 unread emails in others folders
[16:08:09] hotmail_procmsg: Finishing
[16:08:09] Event --contactPSMChange-- fired with caller -protocol-- and args : -censored-
- more more contacts.. -
[16:08:09] Event --contactPSMChange-- fired with caller -protocol-- and args : -censored-
[16:08:09] Read EOF in ::NS::Connection1, closing
[16:08:09] ::MSN::CloseSB ::ns Called
[16:08:09] ::MSN::ClearSB ::ns called
[16:08:09] clearing sb ::ns. oldstat=o
[16:08:09] ::DirectConnectin::Write: SB ns problem when writing to the socket: can not find channel named ""...
[16:08:09] ::MSN::CloseSB ns Called
[16:08:09] ::MSN::ClearSB ns called
[16:08:09] clearing sb ns. oldstat=d
[16:08:09] ::MSN::CloseSB ns Called
[16:08:09] ::MSN::ClearSB ns called
[16:08:09] clearing sb ns. oldstat=d
[16:08:09] Loging out
[16:08:09] Event --loggedOut-- fired with caller -protocol-- and args :
[16:08:09] logging out, creating loginscreen : loggedOut
[16:08:10] LoadLoginList: starting
[16:08:10] LoadLoginList: getting profiles
[16:08:10] LoadLoginList: HOME=C:/Documents and Settings/Administrator/amsn/-censor-, HOME2=C:/Documents and Settings/Administrator/amsn, HOMEE=C:/Documents and Settings/Administrator/amsn
[16:08:10] LoadLoginList: adding profile -censored- with lock num 62507
[16:08:10] ConfigChange: -censored-
[16:08:10] ConfigChange: Valid email
[16:08:10] Event --contactStateChange-- fired with caller -protocol-- and args : - censored -
..

other similar

..
[16:08:10] Event --contactStateChange-- fired with caller -protocol-- and args : - censored -
[16:08:13] Connection lost
[16:08:18] User -censored- has a space but no resource ID : SpaceVersion {} {{SpaceHandle {} {{ResourceID {} {{#text 1pVRFP9QcGzg4EMK4Dovxt-Q!101}}} {RelationshipName {} {{#text MySpace}}} {Alias {} {{Name {} {{#text l_dalamar@hotmail.com}}} {NameSpace {} {{#text MyStuff}}}}}}} {LastModifiedDate {} {{#text 2007-10-02T00:56:42-07:00}}} {HasNewItem {} {{#text false}}}}

..

more more.. more..
contact later..

..

[16:08:18] User -censored- has a space but no resource ID : SpaceVersion {} {{SpaceHandle {} {{ResourceID {} {{#text 1plV-uY-H10vQhMBLmhosmgA!101}}} {RelationshipName {} {{#text MySpace}}} {Alias {} {{Name {} {{#text presic_ff@msn.com}}} {NameSpace {} {{#text MyStuff}}}}}}} {Error {} {{#text 3001}}}}
[16:08:18] Event --contactSpaceChange-- fired with caller -protocol-- and args : {}

[kakaroto]

Many people start reporting they can't log in, which is just pissing me off because I don't know what might cause this!!! (not your fault)
the log says :  

[16:08:13] Connection lost

so I don't know what's the cause but it seems the connection just closes itself, maybe the server has this issue... I know for sure that microsoft are working on their servers, I don't know if anyone noticed, but hotmail.com is now becoming the windows live mail.. the beta of live mail is now released... *some* accounts (all of mine) are now using the released version, the account of my sister was ported to live mail weeks before mine, and some still aren't ported.. probably because they switch from hotmail to live mail gradually, one server at a time, maybe the M$ server containing your account is being upgraded and it's causing this issue for you.
In any case, you can still use the connect through htpp port 80 trick from the preferences->connection tab.
About not being able to send/receive messages, it's a bug that was fixed in the latest SVN version, so you would need to upgrade to SVN. Instructions are found here :
http://amsn-project.net/wiki/SVN

[Cronos]

Many people start reporting they can't log in, which is just pissing me off because I don't know what might cause this!!! (not your fault)
the log says :  

[16:08:13] Connection lost

so I don't know what's the cause but it seems the connection just closes itself, maybe the server has this issue... I know for sure that microsoft are working on their servers, I don't know if anyone noticed, but hotmail.com is now becoming the windows live mail.. the beta of live mail is now released... *some* accounts (all of mine) are now using the released version, the account of my sister was ported to live mail weeks before mine, and some still aren't ported.. probably because they switch from hotmail to live mail gradually, one server at a time, maybe the M$ server containing your account is being upgraded and it's causing this issue for you.
In any case, you can still use the connect through htpp port 80 trick from the preferences->connection tab.
About not being able to send/receive messages, it's a bug that was fixed in the latest SVN version, so you would need to upgrade to SVN. Instructions are found here :
http://amsn-project.net/wiki/SVN

i'll try

for first.. i missed to say "thank you" for all of your work coding amsn ( and this is a thanks from a programmer )

if it could help you..
i don't know why the connection being closed, but i can say you this:

3 month ago, no problem
1 month ago, some problem
2 week ago, much problem
now.. dont log

it seem an "incremental problem", seems something linked with the "contact number" ( i have much contact, about 400 ), 3 month ago i had 100 contact..
and it seems linked with the 'connection speed'

1 month ago
 -> with wireless -> some problem
 -> with lan -> no problem

2 week ago
 -> with wireless -> much problem ( about 40-50 try before login )
 -> with lan -> some problem ( about 2-3 try before login )




anyway
thanks for your patience, i'm afraid for my very very bad english
i'll try the latest version of the code and i think i'll use the port 80 that seems work well


edit: just for confirm it, now with port 80 works, with 'direct connection' still remaining the error

[galmiche]

Dear All,

I exactly now on Vista Ultimate with aMsn 0.97 have the same random disconnection.
(I log in, the be visible - I can login again after beeing disconnected)
I've tryed port 80, running XP compatible and so on. No way.

How did you solved your problem?

Thx for help
Hervé

Here is my log.

[21:38:05] Accepting conversation from: kuirdijon@free.fr... (Got ANS1 in SB ::MSN::SB29
[21:38:06] sb::handleCommand: ANS Chat started. 1 users: kuirdijon@free.fr
[21:38:06] ::MSN::AddSBFor: Creating sb_chatid list for kuirdijon@free.fr
[21:38:06] ::MSN::AddSBFor: Adding SB ::MSN::SB29 to chat kuirdijon@free.fr
[21:38:06] ::MSN::AddSBFor: sb_chatid(kuirdijon@free.fr) was
[21:38:06] ::MSN::AddSBFor: sb_chatid(kuirdijon@free.fr) is now ::MSN::SB29
[21:38:06] ::MSNP2P::GetUser: filename is 84555354d45475f44507962627972396b636559647230575079637d3
[21:38:06] Send text/x-clientcaps
[21:38:06] Got INVITE with content-type : application/x-msnmsgr-sessionreqbody
[21:38:06] 459 702
[21:38:06] MSNP2P | 789 kuirdijon@free.fr -> Got INVITE for buddy icon, emoticon, or file transfer, or Wink(MSN 7)
[21:38:06] GetFilenameFromContext : PG1zbm9iaiBDcmVhdG9yPSJpbmZvQHJhdW5jaGVyLmNvbSIgU2l6ZT0iMTMzMDMiIFR5cGU9IjMiIExvY2F0aW9uPSJhbXNuJTVGQUFDJTVGOTYudG1wIiBGcmllbmRseT0iQUFBPSIgU0hBMUQ9IkltcXFUeE1TOXFZUTBadE51RUZrc1Mrc3V4cz0iIFNIQTFDPSJZa2RCZ0JrTFpoTGt3TVpkQWQrOThQeHF0d3M9Ii8+AA== == <msnobj Creator="info@rauncher.com" Size="13303" Type="3" Location="amsn%5FAAC%5F96.tmp" Friendly="AAA=" SHA1D="ImqqTxMS9qYQ0ZtNuEFksS+suxs=" SHA1C="YkdBgBkLZhLkwMZdAd+98Pxqtws="/>  == <msnobj Creator="info@rauncher.com" Size="13303" Type="3" Location="amsn%5FAAC%5F96.tmp" Friendly="AAA=" SHA1D="ImqqTxMS9qYQ0ZtNuEFksS+suxs=" SHA1C="YkdBgBkLZhLkwMZdAd+98Pxqtws="/>
0 - 178

[21:38:06] Found filename
[21:38:06] MSNP2P | 789 kuirdijon@free.fr -> Sent ACK for INVITE
[21:38:06] MSNP2P | 789 kuirdijon@free.fr -> Sent 200 OK Message
[21:38:06] GOT SID : 789 for Ackid : 715900
[21:38:06] MSNP2P | 789 -> Sent DATA Preparation
[21:38:07] Accepting conversation from: paros77@hotmail.fr... (Got ANS1 in SB ::MSN::SB31
[21:38:07] Got INVITE with content-type : application/x-msnmsgr-transreqbody
[21:38:07] GOT SID : 789 for Ackid : 715901
[21:38:07] sb::handleCommand: ANS Chat started. 1 users: paros77@hotmail.fr
[21:38:07] ::MSN::AddSBFor: Creating sb_chatid list for paros77@hotmail.fr
[21:38:07] ::MSN::AddSBFor: Adding SB ::MSN::SB31 to chat paros77@hotmail.fr
[21:38:07] ::MSN::AddSBFor: sb_chatid(paros77@hotmail.fr) was
[21:38:07] ::MSN::AddSBFor: sb_chatid(paros77@hotmail.fr) is now ::MSN::SB31
[21:38:07] ::MSNP2P::GetUser: filename is 97c6e61625437767c6463655331787d695865373f6b2757597d6b6d3
[21:38:07] ::MSNP2P::GetUser: FILE C:/Users/Administrateur/amsn/info_rauncher_com/displaypic/cache/97c6e61625437767c6463655331787d695865373f6b2757597d6b6d3 doesn't exist!!
[21:38:07] Sent an INVITE to paros77@hotmail.fr on chatid paros77@hotmail.fr of object <msnobj Creator="paros77@hotmail.fr" Type="3" SHA1D="ylnaR4wvldcU3qxmYh57o+WWymk=" Size="26459" Location="0" Friendly="UwBQAF8AQQAwADcAMwA3AAAA"/>
[21:38:07] Send text/x-clientcaps
[21:38:07] Got INVITE with content-type : application/x-msnmsgr-sessionreqbody
[21:38:07] 464 707
[21:38:07] MSNP2P | 9268033 paros77@hotmail.fr -> Got INVITE for buddy icon, emoticon, or file transfer, or Wink(MSN 7)
[21:38:07] GetFilenameFromContext : PG1zbm9iaiBDcmVhdG9yPSJpbmZvQHJhdW5jaGVyLmNvbSIgU2l6ZT0iMTMzMDMiIFR5cGU9IjMiIExvY2F0aW9uPSJhbXNuJTVGQUFDJTVGOTYudG1wIiBGcmllbmRseT0iQUFBPSIgU0hBMUQ9IkltcXFUeE1TOXFZUTBadE51RUZrc1Mrc3V4cz0iIFNIQTFDPSJZa2RCZ0JrTFpoTGt3TVpkQWQrOThQeHF0d3M9Ii8+AA== == <msnobj Creator="info@rauncher.com" Size="13303" Type="3" Location="amsn%5FAAC%5F96.tmp" Friendly="AAA=" SHA1D="ImqqTxMS9qYQ0ZtNuEFksS+suxs=" SHA1C="YkdBgBkLZhLkwMZdAd+98Pxqtws="/>  == <msnobj Creator="info@rauncher.com" Size="13303" Type="3" Location="amsn%5FAAC%5F96.tmp" Friendly="AAA=" SHA1D="ImqqTxMS9qYQ0ZtNuEFksS+suxs=" SHA1C="YkdBgBkLZhLkwMZdAd+98Pxqtws="/>
0 - 178

[21:38:07] Found filename
[21:38:07] MSNP2P | 9268033 paros77@hotmail.fr -> Sent ACK for INVITE
[21:38:07] MSNP2P | 9268033 paros77@hotmail.fr -> Sent 200 OK Message
[21:38:07] GOT SID : 2373432 for Ackid : 542345
[21:38:08] Got INVITE with content-type : application/x-msnmsgr-transreqbody
[21:38:08] GOT SID : 9268033 for Ackid : 700106
[21:38:08] MSNP2P | 9268033 -> Sent DATA Preparation
[21:38:09] GOT SID : 9268033 for Ackid : 700107
[21:38:09] GOT SID : 789 for Ackid : 715903
[21:38:09] GOT SID : 789 for Ackid : 715904
[21:38:10] MSNP2P | 789 -> Got BYE for UID : 2B3CF35B-4E42-4152-BA68-F0BEAE475D6E
[21:38:10] MSNP2P | 789 -> Sending BYE ACK
[21:38:11] GOT SID : 9268033 for Ackid : 700108
[21:38:12] GOT SID : 9268033 for Ackid : 700109
[21:38:12] MSNP2P | 9268033 -> Got BYE for UID : 899526AC-4B82-4CCD-B480-D082E7153257
[21:38:12] MSNP2P | 9268033 -> Sending BYE ACK
[21:38:16] Event --contactPSMChange-- fired with caller -protocol-- and args : xavier.nicolle@gmail.com
[21:38:16] Event --contactPSMChange-- fired with caller -protocol-- and args : xavier.nicolle@gmail.com
[21:38:17] Event --contactStateChange-- fired with caller -protocol-- and args : xavier.nicolle@gmail.com
[21:38:19] MSNP2P | 2373432 -> Got picture with file : 97c6e61625437767c6463655331787d695865373f6b2757597d6b6d3 and 97c6e61625437767c6463655331787d695865373f6b2757597d6b6d3
[21:38:19] MSNP2P | 2373432 -> Closed file 97c6e61625437767c6463655331787d695865373f6b2757597d6b6d3.. finished writing
[21:38:19] Writing description to C:/Users/Administrateur/amsn/info_rauncher_com/displaypic/cache/97c6e61625437767c6463655331787d695865373f6b2757597d6b6d3.dat
[21:38:20] GOT SID : 2373432 for Ackid : 542350
[21:39:51] Read EOF in ::NS::Connection1, closing
[21:39:51] ::MSN::CloseSB ::ns Called
[21:39:51] ::MSN::ClearSB ::ns called
[21:39:51] clearing sb ::ns. oldstat=o
[21:39:51] ::DirectConnectin::Write: SB ns problem when writing to the socket: can not find channel named ""...
[21:39:51] ::MSN::CloseSB ns Called
[21:39:51] ::MSN::ClearSB ns called
[21:39:51] clearing sb ns. oldstat=d
[21:39:51] ::MSN::CloseSB ns Called
[21:39:51] ::MSN::ClearSB ns called
[21:39:51] clearing sb ns. oldstat=d
[21:39:51] Loging out
[21:39:51] Event --loggedOut-- fired with caller -protocol-- and args :
[21:39:51] logging out, creating loginscreen : loggedOut
[21:39:51] LoadLoginList: starting
[21:39:51] LoadLoginList: getting profiles
[21:39:51] LoadLoginList: HOME=C:/Users/Administrateur/amsn/info_rauncher_com, HOME2=C:/Users/Administrateur/amsn, HOMEE=C:/Users/Administrateur/amsn
[21:39:51] LoadLoginList: adding profile info@rauncher.com with lock num 63630
[21:39:51] ConfigChange: info@rauncher.com
[21:39:51] ConfigChange: Valid email
[21:39:58] Connection lost

[kakaroto]

try sending the protocol log instead : Ctrl-D for its window. And yes, it seems to be the same symptoms...

[Kormath]

Hi,

I'm having this problem for a couple of weeks, so I've investigated a bit. First of all, here's the protocol log:

Code:

[04:45:19] ::Proxy::ProxyDirect1
[04:45:19] < Connected to: 207.46.107.67 1863 >
[04:45:34] ->ns-sock460 VER 1 MSNP12 CVR0


[04:45:34] ->ns-sock460 CVR 2 0x0409 winnt 5.1 i386 MSNMSGR 8.0.0812 msmsgs *******@msn.com


[04:45:34] ->ns-sock460 USR 3 TWN I *******@msn.com


[04:45:34] <-ns-sock460 VER 1 MSNP12 CVR0
[04:45:34] <-ns-sock460 CVR 2 8.1.0178 8.1.0178 8.1.0178 http://msgruser.dlservice.microsoft.com/download/1/A/4/1A4FEB1A-18E0-423A-B898-F697402E4F7F/Install_Messenger.exe http://get.live.com
[04:45:34] <-ns-sock460 USR 3 TWN S ct=1200800720,rver=5.0.3270.0,wp=FS_40SEC_0_COMPACT,lc=1033,id=507,ru=http:%2F%2Fmessenger.msn.com,tw=0,kpp=1,kv=4,ver=2.1.6000.1,rn=1lgjBfIL,tpf=b0735e3a873dfb5e75054465196398e0
[04:48:19] ->ns FAILED: OUT


[04:48:20] ::Proxy::ProxyDirect3
[04:48:20] < Connected to: 207.46.107.67 1863 >
[04:48:20] ->ns-sock408 VER 4 MSNP12 CVR0


[04:48:20] ->ns-sock408 CVR 5 0x0409 winnt 5.1 i386 MSNMSGR 8.0.0812 msmsgs *******@msn.com


[04:48:20] ->ns-sock408 USR 6 TWN I *******@msn.com


[04:48:20] <-ns-sock408 VER 4 MSNP12 CVR0
[04:48:21] <-ns-sock408 CVR 5 8.1.0178 8.1.0178 8.1.0178 http://msgruser.dlservice.microsoft.com/download/1/A/4/1A4FEB1A-18E0-423A-B898-F697402E4F7F/Install_Messenger.exe http://get.live.com
[04:48:21] <-ns-sock408 USR 6 TWN S ct=1200800887,rver=5.0.3270.0,wp=FS_40SEC_0_COMPACT,lc=1033,id=507,ru=http:%2F%2Fmessenger.msn.com,tw=0,kpp=1,kv=4,ver=2.1.6000.1,rn=1lgjBfIL,tpf=b0735e3a873dfb5e75054465196398e0
[04:48:23] ->ns-sock408 USR 7 TWN S t=9nVaVWGWZAlpMV4P16rzNDKkUmn*KzBev9wRN5PKNzNtMIX9HXmjpdeSckyxRq2gA7EqyX48W2glMNjGQj2xwuLnqPBoZsXs*4!B2VFsDWcD12U3Hid4gbuw$$&p=99svTWVJfF0dbfXZ05Ib2x8H2qJvjlj3CUSHTTNGuZmf5BEhvgBnHO*haGIgrimgEhiWb1DGWSu8g8nRB10x*o!dlKbk*zJg2Zclrb1nhn6vZrJnljf9V1bDilfL*J2qOzPKdPF0gFItNNdscQqLt6t*PFD3bcmcrNOk9nD3ZYh!CS1FhyjXRLgQ$$


[04:48:23] <-ns-sock408 USR 7 OK *******@msn.com 1 0

As you can see, the only difference is between "::Proxy::ProxyDirect1" and "::Proxy::ProxyDirect3". I don't know why $self returns the 1 and the 3 (I have no knowledge of tcl/tk), but the method is the same in both cases (authInit)

The weird thing is that the issue only happens the first time I try to connect. After a successful connection it always works the first time when reconnecting, even after restarting aMSN, so that makes me think that the key could be something about cached data, like when you try to resolve a DNS and the first time it's slow or times out, but the rest works fine 'cause it's cached.

If that's the case, it could be some server issue as you said before (assuming the data is cached on the server) or maybe somehing related with aMSN, assuming we store the data.

I hope this will give you a hint to solve the problem. Maybe it has nothing to do with it, but it's an idea

By the way, I have the status log too, if you want it

[kakaroto]

Hi,
it looks like it can connect, but it can't authenticate for some reason (the USR 3 TWN S message is asking for authentication and you should answer with another USR x TWN S message.. after 3 minutes you don't so it logs you out). The second time, it takes 2 seconds to authenticate and then it answers with the authentication token and you get logged in..
I don't know why this would happen, maybe the status log will give more info but I doubt it.. in any case, for some reason, we don't get the authentication answer and it times out...
It's an https request.. so I don't know if that helps...

[Kormath]

It's me who cancelled at USR 3 TWN S, there's not timeout as far as I know (if I don't cancell it just hangs there forever)

So, the problem is that aMSN doesn't send a USR 4 TWN S (in this example)... that would be logical if it never received the USR 3 TWN S, but it does, so it's strange. I assume it sends it to the same server it's already connected, so it should have nothing to do with what I was saying in the other post...

I'll try to trace it with Ethereal (or whatever it's called now) and see what happens. I'll have to wait untill it decides not to connect (today it connected at the first attempt), so it may take a while.

Anyway, here's the status log, just in case:

Code:

[04:45:18] Catch in proc trans (title ): can't read "lang(title)": no such variable
[04:45:18] Catch in proc trans (followtext ): can't read "lang(followtext)": no such variable
[04:45:18] Catch in proc trans (filters ): can't read "lang(filters)": no such variable
[04:45:18] Catch in proc trans (savetofile ): can't read "lang(savetofile)": no such variable
[04:45:18] Catch in proc trans (clear ): can't read "lang(clear)": no such variable
[04:45:18] Catch in proc trans (close ): can't read "lang(close)": no such variable
[04:45:18] No LANG environment variable. Using en
[04:45:18] LoadLoginList: starting
[04:45:18] LoadLoginList: HOME=*******/amsn, HOME2=*******/amsn, HOMEE=*******/amsn
[04:45:18] LoadLoginList: adding profile ******@hotmail.com with lock num 0
[04:45:18] LoadLoginList: adding profile ******@msn.com with lock num 63695
[04:45:18] LoadLoginList: getting an initial profile
[04:45:18] CheckLock: LoginList getlock called. Lock=63695
[04:45:18] CheckLock: Port 63695 is free!!
[04:45:18] LockProfile: Locking ******@msn.com
[04:45:18] LockProfile: Got random port 65094
[04:45:18] LoadLoginList: profile ******@msn.com is free, locking
[04:45:18] LoadLoginList: we found a free profile: ******@msn.com
[04:45:18] load_config: Started. HOME=*******, config(login)=******@msn.com
[04:45:18] load_config: loading file *******/config.xml
[04:45:18] load_config: Config loaded
[04:45:18] PLUGIN : Nudge
[04:45:18] load_lang called from a plugin
[04:45:18] load_lang called from a plugin
[04:45:18] PLUGIN : Cam Shooter
[04:45:18] load_lang called from a plugin
[04:45:18] load_lang called from a plugin
[04:45:18] PLUGIN : Inkdraw
[04:45:18] PLUGIN : ColoredNicks
[04:45:18] ColoredNicks loaded
[04:45:18] load_lang called from a plugin
[04:45:18] load_lang called from a plugin
[04:45:18] PLUGIN : Winks
[04:45:18] Loading Winks plugin...
[04:45:18] load_lang called from a plugin
[04:45:18] load_lang called from a plugin
[04:45:18] utils/windows/gnash/gnash.exe
[04:45:18] Winks Loaded OK.
[04:45:18] load_my_pic: Trying to set display picture *******/displaypic/Thriller.png
[04:45:18] skin custom 's scrollbar loaded
[04:45:18] Themes ERR: AddClass with incomplete option list
[04:45:18] Themes ERR: AddClass with incomplete option list
[04:45:18] Themes ERR: AddClass with incomplete option list
[04:45:18] logging out, creating loginscreen : show_login_screen
[04:45:19] LoadLoginList: starting
[04:45:19] LoadLoginList: getting profiles
[04:45:19] LoadLoginList: HOME=*******, HOME2=*******/amsn, HOMEE=*******/amsn
[04:45:19] LoadLoginList: adding profile ******@hotmail.com with lock num 0
[04:45:19] LoadLoginList: adding profile ******@msn.com with lock num 65094
[04:45:19] ConfigChange: ******@msn.com
[04:45:19] ConfigChange: Valid email
[04:45:19] logging in, destroying loginscreen : loggingIn
[04:45:34] cmsn_auth starting, stat=a
[04:45:34] check_web_ver: status=timeout ncode=
[04:45:34] cmsn_auth starting, stat=v
[04:45:34] cmsn_auth starting, stat=i
[04:45:34] cmsn_auth starting, stat=u
[04:45:34] cmsn_auth: Nexus didn't reply yet...
[04:46:27] Read EOF in ::NS::Connection1, closing
[04:46:27] ::MSN::CloseSB ::ns Called
[04:46:27] ::MSN::ClearSB ::ns called
[04:46:27] clearing sb ::ns. oldstat=u
[04:48:19] ::DirectConnectin::Write: SB ns problem when writing to the socket: can not find channel named ""...
[04:48:19] ::MSN::CloseSB ns Called
[04:48:19] ::MSN::ClearSB ns called
[04:48:19] clearing sb ns. oldstat=d
[04:48:19] ::MSN::CloseSB ns Called
[04:48:19] ::MSN::ClearSB ns called
[04:48:19] clearing sb ns. oldstat=d
[04:48:19] Loging out
[04:48:19] logging out, creating loginscreen : loggedOut
[04:48:19] LoadLoginList: starting
[04:48:19] LoadLoginList: getting profiles
[04:48:19] LoadLoginList: HOME=*******, HOME2=*******/amsn, HOMEE=*******/amsn
[04:48:19] LoadLoginList: adding profile ******@hotmail.com with lock num 0
[04:48:19] LoadLoginList: adding profile ******@msn.com with lock num 65094
[04:48:19] logging out, creating loginscreen : show_login_screen
[04:48:19] ConfigChange: ******@msn.com
[04:48:19] ConfigChange: Valid email
[04:48:20] logging in, destroying loginscreen : loggingIn
[04:48:20] cmsn_auth starting, stat=a
[04:48:20] cmsn_auth starting, stat=v
[04:48:21] cmsn_auth starting, stat=i
[04:48:21] cmsn_auth starting, stat=u
[04:48:21] cmsn_auth: Nexus didn't reply yet...
[04:48:21] gotNexusReply: loginurl=https://loginnet.passport.com/login2.srf
[04:48:21] gotNexusReply: authentication was waiting for me, so I'll do it
[04:48:21] ::DirectConnection::authenticate: Getting https://loginnet.passport.com/login2.srf
[04:48:22] ::DirectConnection::GotAuthReply 302: Forward to https://msnialogin.passport.com/login2.srf
[04:48:22] ::DirectConnection::authenticate: Getting https://msnialogin.passport.com/login2.srf
[04:48:23] ::DirectConnection::GotAuthReply 200 Ticket= t=9nVaVWGWZAlpMV4P16rzNDKkUmn*KzBev9wRN5PKNzNtMIX9HXmjpdeSckyxRq2gA7EqyX48W2glMNjGQj2xwuLnqPBoZsXs*4!B2VFsDWcD12U3Hid4gbuw$$&p=99svTWVJfF0dbfXZ05Ib2x8H2qJvjlj3CUSHTTNGuZmf5BEhvgBnHO*haGIgrimgEhiWb1DGWSu8g8nRB10x*o!dlKbk*zJg2Zclrb1nhn6vZrJnljf9V1bDilfL*J2qOzPKdPF0gFItNNdscQqLt6t*PFD3bcmcrNOk9nD3ZYh!CS1FhyjXRLgQ$$
[04:48:23] cmsn_auth starting, stat=us
[04:48:23] save_config: saving config for user ******@msn.com in *******]
[04:48:23] save_config: saving config_file. Opening of file returned : file2136a50
[04:48:23] save_config: Config saved
[04:48:23] Loading address book data...

PS: Take a look at [04:46:27]... it seems that it do times out after all.

[Kormath]

Ok, I've got the traces and have found something.

The first time it tried to log in without SSL authentication, and failed. The second time it authenticated and loged in successfully.

Could that be the problem?

[kakaroto]

Code:

[04:45:34] cmsn_auth: Nexus didn't reply yet...

it was waiting for the answer from the 'nexus' server...
 

Code:

[04:48:21] cmsn_auth: Nexus didn't reply yet...
[04:48:21] gotNexusReply: loginurl=https://loginnet.passport.com/login2.srf
[04:48:21] gotNexusReply: authentication was waiting for me, so I'll do it
[04:48:21] ::DirectConnection::authenticate: Getting https://loginnet.passport.com/login2.srf

It was still waiting, but then it got an answer and proceeded to authenticate...
'nexus' is a server to which we send your email address, and it tells us on which server we should try to authenticate.. @msn.com, @hotmail.com, @gmail.com, etc.. accounts each have a different server that hosts the authentication information, so we need to authenticate on the right server ever time...
the nexus request is https so it should be using SSL... the authentication is also done through SSL...
Problem is that nexus doesn't reply for some reason...
OR, after it times out with no answer, it will take the default URL as if nexus had replied with that URL being the server hosting your information... but seeine the log, it seems that we do receive the answer from nexus the second time...

[Kormath]

I'm pretty sure that the problem is the SSL authentication thing. Here's what Ethereal's trace says when aMSN can't connect:

1. Begins handshake with *.gateway.edge.messenger.live.com (let's call it Gateway), and connects.
2. Begins handshake with Nexus, but it never receives the SYN/ACK, so there's no SSL authentication!
3. Sends MSN commands through Gateway and then hangs at USR 3 TWN S because there is no SSL auth.


Here's what it does when the connection is successful:

1. Begins handshake with Gateway and connects.
2. Begins handshake with Nexus and connects.
3. Sends MSN commands through Gateway and SSL commands through Nexus.
4. Continues with the login process.


So, could it be possible to make sure that the connection with Nexus is established before connecting with Gateway?
Probably that's the problem

I can email you the traces if you want

PS: It's essentially what you said before about the Nexus server no responding... just making sure it connects before sending the other commands should do it.

[kakaroto]

Hi,
We can't really connect only after the nexus server replied.. in this case, if it doesn't reply, then it will be the same problem again.. We already have a system that checks which connection finished first.. if nexus finishes first, it will store the response somewhere, and when the 'gateway' server answers with the USR TWN, we will use the previously retreived response from nexus and continue the connection. If we get the USR TWN before nexus finishes, then once we get the response from nexus, we will continue the authentication. (That's why you see the 'Nexus didn't reply yet" and the "authentication was waiting for me" messages...
If we do it your way, then we'll still have to implement a way to know if the nexus never replies, and that would be using a timeout.. but we already set a 5 second timeout, so I don't know why it doesn't work. I guess the http module to tcl has a bug in its timeout handling...

[Kormath]

Finally!!

After some hours of coding (it was my first time with tcl/tk  :oops:) I've found the problem, which was, of course, pretty lame ;p

Just open proxy.tcl and change this:

Code:

after 0 "catch {::http::geturl [list https://nexus.passport.com/rdr/pprdr.asp] -timeout 5000 -command {globalGotNexusReply $self}}"

for this:

Code:

if { [catch {set token [::http::geturl [list https://nexus.passport.com/rdr/pprdr.asp] -timeout 5000]}] } {
return -1
}

globalGotNexusReply $self $token
return ok

The tcl/tk documentation says that catch returns 1 when there's an error, but this proc must return -1. Take a look at protocol.tcl:

Code:

if { [$proxy authInit] < 0 } {

Sometimes ::http::geturl throws an exception (or whatever it's called in tcl/tk), and that's where it hanged, 'cause the execution continued as if globalGotNexusReply was called, but it wasn't

And finally, the reason why I don't call globalGotNexusReply using -command is 'cause it seems that when the request times out, -command is not executed, so it should hang too (I couldn't test this enough, so I'm not 100% sure)

A warning or something when the exception is catched would be nice, too, so the user can now that there has been a problem and must reconnect

[kakaroto]

oh.. I see.. I thought in case of error, the callback would be called and you would get [::http::status $token] == "error" or "timeout".. so it just throws an error.. !
ok, now I can fix it correctly, thanks! and good job on finding the problem!

btw, your solution is not good because it makes the http call synchronous which could make aMSN hang instead of having it asynchronous...

[Kormath]

Yes, I didn't realize that... it seems that the only way to make it asynchronous is by using -command, so be careful