Can only receive files but not send to some users over AIM, pidgin incorrectly says other user canceled

[dave1g]

I successfully received a file transfer from a user, when I tried to send one back, pidgin claims the other user "canceled" the transfer, which was not the case. AIM direct connect also works fine.

she is using "aol instant messenger aim version 6.5.12.1"

I see this

(6:13:30 PM) Offering to send 100_2834.JPG to soothsayergirl
(6:13:36 PM) soothsayergirl canceled the transfer of 100_2834.JPG

she saw this

ATTENTION (06:13:22 p.m.): File Transfer session . 
ATTENTION (06:13:22 p.m.): File Transfer session . 
ATTENTION (06:13:29 p.m.): File Transfer session initiated. 
An Unknown Failure Occurred.

and here is the debug log for that failed attempt from me to her ( I have removed all of the oscar rate change logs so it is readable)

(18:13:30) win32placement: Window RECT: L:226 R:721 T:100 B:428
(18:13:30) win32placement: Working Area RECT: L:0 R:1680 T:0 B:960
(18:13:30) oscar: Calculating checksum of C:\Documents and Settings\David\Desktop\100_2834.JPG
(18:13:30) oscar: Checksum of C:\Documents and Settings\David\Desktop\100_2834.JPG calculated
(18:13:30) network: Listening on port: 10001
(18:13:30) util: requested to fetch (http://192.168.5.1:80/Public_UPNP_C3), full=0, user_agent=((null)), http11=1
(18:13:30) dnsquery: Performing DNS lookup for 192.168.5.1
(18:13:30) dnsquery: IP resolved for 192.168.5.1
(18:13:30) proxy: Attempting connection to 192.168.5.1
(18:13:30) proxy: Connecting to 192.168.5.1:80 with no proxy
(18:13:30) proxy: Connection in progress
(18:13:30) proxy: Connected to 192.168.5.1:80.
(18:13:30) util: Request: 'POST /Public_UPNP_C3 HTTP/1.1
HOST: 192.168.5.1:80
SOAPACTION: "urn:schemas-upnp-org:service:WANIPConnection:1#AddPortMapping"
CONTENT-TYPE: text/xml ; charset="utf-8"
CONTENT-LENGTH: 649

<?xml version="1.0" encoding="utf-8"?>
<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/">
<s:Body>
<u:AddPortMapping xmlns:u="urn:schemas-upnp-org:service:WANIPConnection:1">
<NewRemoteHost></NewRemoteHost>
<NewExternalPort>10001</NewExternalPort>
<NewProtocol>TCP</NewProtocol>
<NewInternalPort>10001</NewInternalPort>
<NewInternalClient>192.168.5.10</NewInternalClient>
<NewEnabled>1</NewEnabled>
<NewPortMappingDescription>PURPLE_UPNP_PORT_FORWARD</NewPortMappingDescription>
<NewLeaseDuration>0</NewLeaseDuration>
</u:AddPortMapping>
</s:Body>
</s:Envelope>'
(18:13:30) util: Response headers: 'HTTP/1.1 200 OK
CONTENT-LENGTH:267
CONTENT-TYPE:text/xml; charset="utf-8"
EXT:
SERVER:Ambit OS/1.0 UPnP/1.0 AMBIT-UPNP/1.0

'
(18:13:30) upnp: Successfully completed port mapping operation
(18:13:30) stun: using server stunserver.org
(18:13:30) oscar: Sent message to soothsayergirl.
(18:13:36) oscar: Incoming rendezvous message of type 32, user soothsayergirl, status 0
(18:13:36) oscar: Remote user wants to try a different connection method
(18:13:36) dnsquery: Performing DNS lookup for 64.12.201.144
(18:13:36) dnsquery: IP resolved for 64.12.201.144
(18:13:36) proxy: Attempting connection to 64.12.201.144
(18:13:36) proxy: Connecting to 64.12.201.144:5190 with no proxy
(18:13:36) proxy: Connection in progress
(18:13:36) proxy: Connected to 64.12.201.144:5190.
(18:13:36) oscar: Outgoing peer proxy frame with type=0x0004, unknown=0x00000000, flags=0x0000, and payload length=37
(18:13:36) oscar: Incoming peer proxy frame with type=0x0005, unknown=0x00000000, flags=0x0220, and payload length=0
(18:13:45) oscar: incomingim_ch1: unknown TLV 0x000d (len 27)
(18:13:45) oscar: incomingim_ch1: unknown TLV 0x0013 (len 1)
(18:13:45) oscar: Received IM from soothsayergirl with 1 parts
(18:13:45) oscar: Parsing IM part, charset=0x0000, charsubset=0x0000, datalen=579
(18:13:45) sound: Playing C:\Program Files\Pidgin\sounds\purple\receive.wav
(18:13:51) gtkimhtml: empty queue, more closing tags than open tags!
(18:13:51) gtkimhtml: empty queue, more closing tags than open tags!
(18:13:51) gtkimhtml: empty queue, more closing tags than open tags!
(18:13:56) oscar: Sending IM, charset=0x0000, charsubset=0x0000, length=18
(18:13:56) sound: Playing C:\Program Files\Pidgin\sounds\purple\send.wav
(18:13:56) oscar: Sent message to soothsayergirl.
(18:13:57) gtkimhtml: empty queue, more closing tags than open tags!
(18:13:57) gtkimhtml: empty queue, more closing tags than open tags!
(18:13:57) gtkimhtml: empty queue, more closing tags than open tags!
(18:13:57) oscar: Sending IM, charset=0x0000, charsubset=0x0000, length=511
(18:13:57) oscar: Sent message to soothsayergirl.
(18:14:04) oscar: incomingim_ch1: unknown TLV 0x000d (len 27)
(18:14:04) oscar: incomingim_ch1: unknown TLV 0x0013 (len 1)
(18:14:04) oscar: Received IM from soothsayergirl with 1 parts

and here is a successful attempt from her to me

(6:21:13 PM) David Grohmann: can you send me a file
(6:22:05 PM) soothsayergirl is offering to send file water.jpg
(6:22:09 PM) Starting transfer of water.jpg from soothsayergirl
(6:22:21 PM) Transfer of file water.jpg complete

debug:

(18:21:13) oscar: Sent message to soothsayergirl.
(18:22:05) oscar: Incoming rendezvous message of type 32, user soothsayergirl, status 0
(18:22:09) dnsquery: Performing DNS lookup for 68.196.149.16
(18:22:09) dnsquery: Performing DNS lookup for 192.168.1.102
(18:22:09) dnsquery: IP resolved for 68.196.149.16
(18:22:09) proxy: Attempting connection to 68.196.149.16
(18:22:09) proxy: Connecting to 68.196.149.16:61560 with no proxy
(18:22:09) proxy: Connection in progress
(18:22:09) dnsquery: IP resolved for 192.168.1.102
(18:22:09) proxy: Attempting connection to 192.168.1.102
(18:22:09) proxy: Connecting to 192.168.1.102:61560 with no proxy
(18:22:09) proxy: Connection in progress
(18:22:14) oscar: Peer connection timed out after 5 seconds.  Trying next method...
(18:22:14) network: Listening on port: 10001
(18:22:14) util: requested to fetch (http://192.168.5.1:80/Public_UPNP_C3), full=0, user_agent=((null)), http11=1
(18:22:14) dnsquery: Performing DNS lookup for 192.168.5.1
(18:22:14) dnsquery: IP resolved for 192.168.5.1
(18:22:14) proxy: Attempting connection to 192.168.5.1
(18:22:14) proxy: Connecting to 192.168.5.1:80 with no proxy
(18:22:14) proxy: Connection in progress
(18:22:14) proxy: Connected to 192.168.5.1:80.
(18:22:14) util: Request: 'POST /Public_UPNP_C3 HTTP/1.1
HOST: 192.168.5.1:80
SOAPACTION: "urn:schemas-upnp-org:service:WANIPConnection:1#AddPortMapping"
CONTENT-TYPE: text/xml ; charset="utf-8"
CONTENT-LENGTH: 649

<?xml version="1.0" encoding="utf-8"?>
<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/">
<s:Body>
<u:AddPortMapping xmlns:u="urn:schemas-upnp-org:service:WANIPConnection:1">
<NewRemoteHost></NewRemoteHost>
<NewExternalPort>10001</NewExternalPort>
<NewProtocol>TCP</NewProtocol>
<NewInternalPort>10001</NewInternalPort>
<NewInternalClient>192.168.5.10</NewInternalClient>
<NewEnabled>1</NewEnabled>
<NewPortMappingDescription>PURPLE_UPNP_PORT_FORWARD</NewPortMappingDescription>
<NewLeaseDuration>0</NewLeaseDuration>
</u:AddPortMapping>
</s:Body>
</s:Envelope>'
(18:22:14) util: Response headers: 'HTTP/1.1 200 OK
CONTENT-LENGTH:267
CONTENT-TYPE:text/xml; charset="utf-8"
EXT:
SERVER:Ambit OS/1.0 UPnP/1.0 AMBIT-UPNP/1.0

'
(18:22:14) upnp: Successfully completed port mapping operation
(18:22:14) stun: using server stunserver.org
(18:22:14) oscar: Sent message to soothsayergirl.
(18:22:16) oscar: Scheduling destruction of FLAP connection of type 0x000d
(18:22:16) oscar: Destroying oscar connection of type 0x000d.  Disconnect reason is 4
(18:22:16) oscar: Disconnected.  Code is 0x0000 and msg is Remote host closed connection.
(18:22:20) oscar: Incoming rendezvous message of type 32, user soothsayergirl, status 0
(18:22:20) oscar: Remote user wants to try a different connection method
(18:22:20) dnsquery: Performing DNS lookup for ars.oscar.aol.com
(18:22:20) dnsquery: IP resolved for ars.oscar.aol.com
(18:22:20) proxy: Attempting connection to 64.12.201.185
(18:22:20) proxy: Connecting to ars.oscar.aol.com:5190 with no proxy
(18:22:20) proxy: Connection in progress
(18:22:20) proxy: Connected to ars.oscar.aol.com:5190.
(18:22:20) oscar: Outgoing peer proxy frame with type=0x0002, unknown=0x00000000, flags=0x0000, and payload length=35
(18:22:20) oscar: Incoming peer proxy frame with type=0x0003, unknown=0x00000000, flags=0x0220, and payload length=6
(18:22:21) oscar: Sent message to soothsayergirl.
(18:22:21) oscar: Incoming rendezvous message of type 32, user soothsayergirl, status 2
(18:22:21) oscar: Incoming peer proxy frame with type=0x0005, unknown=0x00000000, flags=0x0220, and payload length=0
(18:22:21) oscar: Incoming OFT frame from soothsayergirl with type=0x0101
(18:22:36) oscar: Sending IM, charset=0x0000, charsubset=0x0000, length=6
(18:22:36) sound: Playing C:\Program Files\Pidgin\sounds\purple\send.wav

[dave1g]

full debug log

[dave1g]

Successful Direct connect attempt

(6:43:19 PM) David Grohmann: test numero tres
(6:43:46 PM) Asking soothsayergirl to connect to us at 96.246.92.236:10001 for Direct IM.
(6:43:47 PM) Attempting to connect via proxy server.
(6:43:47 PM) Direct IM established
(6:43:53 PM) soothsayergirl: it says what's things
(6:44:00 PM) soothsayergirl:  ATTENTION (06:43:38 p.m.): Direct IM session . 
ATTENTION (06:43:39 p.m.): Direct IM session initiated. What is this?
(6:44:11 PM) David Grohmann: thats fine

debug log

(18:43:19) oscar: Sent message to soothsayergirl.
(18:43:30) network: Listening on port: 10001
(18:43:30) util: requested to fetch (http://192.168.1.1:5431/uuid:0012-17bb-c5220200d6dc/WANIPConnection:1), full=0, user_agent=((null)), http11=1
(18:43:30) dnsquery: Performing DNS lookup for 192.168.1.1
(18:43:30) dnsquery: IP resolved for 192.168.1.1
(18:43:30) proxy: Attempting connection to 192.168.1.1
(18:43:30) proxy: Connecting to 192.168.1.1:5431 with no proxy
(18:43:30) proxy: Connection in progress
(18:43:30) proxy: Connected to 192.168.1.1:5431.
(18:43:30) util: Request: 'POST /uuid:0012-17bb-c5220200d6dc/WANIPConnection:1 HTTP/1.1
HOST: 192.168.1.1:5431
SOAPACTION: "urn:schemas-upnp-org:service:WANIPConnection:1#AddPortMapping"
CONTENT-TYPE: text/xml ; charset="utf-8"
CONTENT-LENGTH: 650

<?xml version="1.0" encoding="utf-8"?>
<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/">
<s:Body>
<u:AddPortMapping xmlns:u="urn:schemas-upnp-org:service:WANIPConnection:1">
<NewRemoteHost></NewRemoteHost>
<NewExternalPort>10001</NewExternalPort>
<NewProtocol>TCP</NewProtocol>
<NewInternalPort>10001</NewInternalPort>
<NewInternalClient>192.168.1.103</NewInternalClient>
<NewEnabled>1</NewEnabled>
<NewPortMappingDescription>PURPLE_UPNP_PORT_FORWARD</NewPortMappingDescription>
<NewLeaseDuration>0</NewLeaseDuration>
</u:AddPortMapping>
</s:Body>
</s:Envelope>'
(18:43:34) util: Response headers: 'HTTP/1.1 200 OK
DATE: Sat, 14 Jun 2008 18:43:14 GMT
Connection: Keep-Alive
Server: LINUX/2.4 UPnP/1.0 BRCM400/1.0
Content-Length: 289
Content-Type: text/xml; charset="utf-8"
EXT:

'
(18:43:34) util: parsed 289
(18:43:46) upnp: Successfully completed port mapping operation
(18:43:46) stun: using server stunserver.org
(18:43:46) oscar: Sent message to soothsayergirl.
(18:43:47) oscar: Incoming rendezvous message of type 4, user soothsayergirl, status 0
(18:43:47) oscar: Remote user wants to try a different connection method
(18:43:47) dnsquery: Performing DNS lookup for 64.12.201.138
(18:43:47) dnsquery: IP resolved for 64.12.201.138
(18:43:47) proxy: Attempting connection to 64.12.201.138
(18:43:47) proxy: Connecting to 64.12.201.138:5190 with no proxy
(18:43:47) proxy: Connection in progress
(18:43:47) proxy: Connected to 64.12.201.138:5190.
(18:43:47) oscar: Outgoing peer proxy frame with type=0x0004, unknown=0x00000000, flags=0x0000, and payload length=37
(18:43:47) oscar: Incoming peer proxy frame with type=0x0005, unknown=0x00000000, flags=0x0220, and payload length=0
(18:43:47) oscar: Outgoing ODC frame to soothsayergirl with type=0x0001, flags=0x0060, payload length=0
(18:43:47) oscar: Incoming ODC frame from soothsayergirl with type=0x0001, flags=0x00e0, payload length=0
(18:43:53) oscar: Incoming ODC frame from soothsayergirl with type=0x0001, flags=0x00e0, payload length=94
(18:43:53) oscar: Parsing IM part, charset=0x0000, charsubset=0x0000, datalen=94
(18:43:53) sound: Playing C:\Program Files\Pidgin\sounds\purple\receive.

[dave1g]

#5395 lists some other oddities

[Mother Fo]

I've noticed this on 2.5.2 as well. It seems if I enable force aim proxy server in my account options. The file transfer works. I'm just sending files to people on macs using ichat. I'm on vista64 and the ports are forwarded. I uploaded the debug. Similar to #6234.

[Kaze_no_Hibiki]

Replying to Mother Fo:

I've noticed this on 2.5.2 as well. It seems if I enable force aim proxy server in my account options. The file transfer works. I'm just sending files to people on macs using ichat. I'm on vista64 and the ports are forwarded. I uploaded the debug. Similar to #6234.

I've had similar results. I can already receive file transfers, but sending them always results in a claim that the receiver canceled. If I go to the settings for the account, and check the box labeled: "Always use AIM/ICQ proxy server for file transfers and direct IM" I can send file transfers without a problem. Exactly why isn't that check box selected by default, maybe until the problem is fixed or soemthing?

[dave1g]

if that is the case, then shouldnt the proxy method be a fallback?

[bernmeister]

Is this still happening on 2.5.8? Hopefully the fixes in the two related tickets have clobbered this one...