Adium (1.2svn) fails file transfer (ICQ 6 Win)

[charlieMonroe]

My ports are open (5190 and 5431), the guy I'm trying to send this to is connected directly (no router). Here is a debug log:

13:47:20: Sending text attachment AITextAttachmentExtension<a8230f0>: <AITextAttachmentExtension: 0xa8230f0> which has path /Users/alto/Desktop/071911185207.png 13:47:20: PURPLE_XFER_SEND: c26eb70 (/Users/alto/Desktop/071911185207.png) 13:47:20: adiumPurpleConvWriteConv: Received Offering to send 071911185207.png to Jirka from 200863051 [4] 13:47:20: (Libpurple: oscar) Calculating checksum of /Users/alto/Desktop/071911185207.png 13:47:20: adiumPurpleRequestFile() returning <null> 13:47:21: (Libpurple: oscar) Checksum of /Users/alto/Desktop/071911185207.png calculated 13:47:21: (Libpurple: network) Listening on port: 5190 13:47:21: (Libpurple: nat-pmp) found a default gateway 13:47:21: (Libpurple: nat-pmp) Attempting to create a NAT-PMP mapping the private port 5190, and the public port 5190 13:47:21: (Libpurple: nat-pmp) Timeout: 0s 250000us 13:47:21: (Libpurple: nat-pmp) The opcode for the response from the NAT device does not match the request opcode! 13:47:21: (Libpurple: network) Couldn't create UPnP mapping 13:47:21: (Libpurple: network) Couldn't create UPnP mapping 13:47:21: (Libpurple: stun) using server 13:47:21: (Libpurple: oscar) Sent message to 200863051. 13:47:22: (Libpurple: oscar) Incoming rendezvous message of type 32, user 200863051, status 0 13:47:22: (Libpurple: oscar) Remote user wants to try a different connection method 13:47:22: (Libpurple: dns) DNS query for '205.188.210.205' queued 13:47:22: Performing DNS resolve: 205.188.210.205:5190 13:47:22: DNS resolve complete for 205.188.210.205:5190 13:47:22: (Libpurple: dnsquery) IP resolved for 205.188.210.205 13:47:22: (Libpurple: proxy) Attempting connection to 205.188.210.205 13:47:22: (Libpurple: proxy) Connecting to 205.188.210.205:5190 with no proxy 13:47:22: (Libpurple: proxy) Connection in progress 13:47:22: (Libpurple: proxy) Connected to 205.188.210.205:5190. 13:47:22: (Libpurple: oscar) Outgoing peer proxy frame with type=0x0004, unknown=0x00000000, flags=0x0000, and payload length=40 13:47:23: (Libpurple: oscar) Incoming peer proxy frame with type=0x0005, unknown=0x00000000, flags=0x0220, and payload length=0 13:47:23: adiumPurpleRequestClose <null> (0) 13:47:23: adiumPurpleConvWriteConv: Received Jirka canceled the transfer of 071911185207.png from 200863051 [512] 13:47:23: *** Conversation error type -2 (200863051): Jirka canceled the transfer of 071911185207.png 13:47:23: adiumPurpleNotifyMessage: type: 0

File transfer to Jirka failed. Jirka canceled the transfer of 071911185207.png 13:47:23: adiumPurpleCancelRemote 13:47:23: Destroy file transfer {<ESFileTransfer: 0xa83db30> :<Source=<ESPurpleICQAccount:64b1c60 3>:241426474> <Destination=<AIListContact:a7c6710 ICQ.200863051>> <Message=200863051 requests to send you (162.7 KB){ }>}

[jas8522]

What kind of router do you have? Try turning of port forwarding for 5190 and allowing uPnP to complete the forward (you obviously need uPnP enabled on your router). It looks like it might be trying to map the port, the router tells it that this isn't possible (possibly because the port is manually forwarded already) and it fails, attempts to fall back to a transfer through the AIM server which also fails.

If uPnP works on your end, then it might be that either your manual port forward failed to work properly to begin with or Libpurple is not checking if the port is already open before attempting to map the port.

[charlieMonroe]

The Router is Asus AM200G. It's upnp capable, e.g. Lighthouse or Transmission, both are able to automatically map ports on this modem. I have removed the manually forwarded ports and this is what I got:

20:58:02: Sending text attachment AITextAttachmentExtension<92df6a0>: <AITextAttachmentExtension: 0x92df6a0> which has path /Users/alto/Desktop/071911185207.png
20:58:02: PURPLE_XFER_SEND: b101a50 (/Users/alto/Desktop/071911185207.png)
20:58:02: adiumPurpleConvWriteConv: Received Offering to send 071911185207.png to Jirka from 200863051 [4]
20:58:02: (Libpurple: oscar) Calculating checksum of /Users/alto/Desktop/071911185207.png
20:58:02: adiumPurpleRequestFile() returning <null>
20:58:02: (Libpurple: oscar) Checksum of /Users/alto/Desktop/071911185207.png calculated
20:58:02: (Libpurple: network) Listening on port: 5190
20:58:02: (Libpurple: nat-pmp) found a default gateway
20:58:02: (Libpurple: nat-pmp) Attempting to create a NAT-PMP mapping the private port 5190, and the public port 5190
20:58:02: (Libpurple: nat-pmp) 	Timeout: 0s 250000us
20:58:02: (Libpurple: nat-pmp) The opcode for the response from the NAT device does not match the request opcode!
20:58:02: Called write with no write_tag (read_tag 1778 write_tag 0) for b18c150
20:58:02: (Libpurple: util) requested to fetch (http://192.168.1.1:5431/dyndev/uuid:0000e098-10a0-00e0-80a0-489800e808e0), full=1, user_agent=((null)), http11=1
20:58:02: (Libpurple: dns) DNS query for '192.168.1.1' queued
20:58:02: Performing DNS resolve: 192.168.1.1:5431
20:58:02: DNS resolve complete for 192.168.1.1:5431
20:58:02: (Libpurple: dnsquery) IP resolved for 192.168.1.1
20:58:02: (Libpurple: proxy) Attempting connection to 192.168.1.1
20:58:02: (Libpurple: proxy) Connecting to 192.168.1.1:5431 with no proxy
20:58:02: (Libpurple: proxy) Connection in progress
20:58:02: (Libpurple: proxy) Connected to 192.168.1.1:5431.
20:58:02: (Libpurple: util) Request: 'GET /dyndev/uuid:0000e098-10a0-00e0-80a0-489800e808e0 HTTP/1.1
Connection: close
Host: 192.168.1.1:5431

'
20:58:02: (Libpurple: util) Response headers: 'HTTP/1.0 200 OK
SERVER: LINUX/2.4 UPnP/1.0 BRCM400/1.0
DATE: Sat, 01 Jan 2000 00:02:47 GMT
CONTENT-TYPE: application/octet-stream
Cache-Control: max-age=1
PRAGMA: no-cache
Connection: Close

'
20:58:02: (Libpurple: upnp) parse_description_response(): could not get serviceTypeNode 7
20:58:02: (Libpurple: upnp) purple_upnp_parse_description(): control URL is NULL
20:58:02: (Libpurple: network) Couldn't create UPnP mapping
20:58:02: (Libpurple: network) Couldn't create UPnP mapping
20:58:02: (Libpurple: stun) using server 
20:58:03: (Libpurple: oscar) Sent message to 200863051.
20:58:03: (Libpurple: msn) C: NS 000: PNG
20:58:03: (Libpurple: msn) S: NS 000: QNG 49
20:58:04: (Libpurple: oscar) Incoming rendezvous message of type 32, user 200863051, status 0
20:58:04: (Libpurple: oscar) Remote user wants to try a different connection method
20:58:04: (Libpurple: dns) DNS query for '64.12.201.132' queued
20:58:04: Performing DNS resolve: 64.12.201.132:5190
20:58:04: DNS resolve complete for 64.12.201.132:5190
20:58:04: (Libpurple: dnsquery) IP resolved for 64.12.201.132
20:58:04: (Libpurple: proxy) Attempting connection to 64.12.201.132
20:58:04: (Libpurple: proxy) Connecting to 64.12.201.132:5190 with no proxy
20:58:04: (Libpurple: proxy) Connection in progress
20:58:04: (Libpurple: proxy) Connected to 64.12.201.132:5190.
20:58:04: (Libpurple: oscar) Outgoing peer proxy frame with type=0x0004, unknown=0x00000000, flags=0x0000, and payload length=40
20:58:05: (Libpurple: oscar) Incoming peer proxy frame with type=0x0005, unknown=0x00000000, flags=0x0220, and payload length=0
20:58:05: adiumPurpleRequestClose <null> (0)
20:58:05: adiumPurpleConvWriteConv: Received Jirka canceled the transfer of 071911185207.png from 200863051 [512]
20:58:05: *** Conversation error type -2 (200863051): Jirka canceled the transfer of 071911185207.png
20:58:05: adiumPurpleNotifyMessage: type: 0

File transfer to Jirka failed.
Jirka canceled the transfer of 071911185207.png 
20:58:05: adiumPurpleCancelRemote
20:58:05: purpleThreadRequestCloseWithHandle: <ESPurpleFileReceiveRequestController: 0x95d1710>
20:58:05: Destroy file transfer {<ESFileTransfer: 0xd058a40> :<Source=<ESPurpleICQAccount:64900d0 3>:241426474> <Destination=<AIListContact:926f850 ICQ.200863051>> <Message=200863051 requests to send you  (162.7 KB){
}>}

[charlieMonroe]

Update:

I have tested it with friends who have ICQ and are on Windows: I'm getting the same result. However, when trying between two Adiums, everything's just fine. I can post a log of a successful transfer, if you'd like me to.

[jas8522]

A successful transfer log might be handy just to compare and see which type of transfer is working when it does work.

[charlieMonroe]

Sorry for the delay. Here's a successful log. The same place, just a transfer to Adium:

20:58:40: Sending text attachment AITextAttachmentExtension<79894c0>: <AITextAttachmentExtension: 0x79894c0> which has path /Users/alto/Desktop/Picture 2.png.zip
20:58:40: PURPLE_XFER_SEND: 7d93ef0 (/Users/alto/Desktop/Picture 2.png.zip)
20:58:40: adiumPurpleConvWriteConv: Received Offering to send Picture 2.png.zip to Dan from 5232308 [4]
20:58:40: (Libpurple: oscar) Calculating checksum of /Users/alto/Desktop/Picture 2.png.zip
20:58:40: adiumPurpleRequestFile() returning <null>
20:58:40: (Libpurple: oscar) Checksum of /Users/alto/Desktop/Picture 2.png.zip calculated
20:58:40: (Libpurple: network) Listening on port: 5190
20:58:40: (Libpurple: nat-pmp) found a default gateway
20:58:40: (Libpurple: nat-pmp) Attempting to create a NAT-PMP mapping the private port 5190, and the public port 5190
20:58:40: (Libpurple: nat-pmp) 	Timeout: 0s 250000us
20:58:40: (Libpurple: nat-pmp) The opcode for the response from the NAT device does not match the request opcode!
20:58:40: Called write with no write_tag (read_tag 1052 write_tag 0) for 8b14810
20:58:40: (Libpurple: util) requested to fetch (http://192.168.1.1:5431/dyndev/uuid:0000e098-10a0-00e0-80a0-489800e808e0), full=1, user_agent=((null)), http11=1
20:58:40: (Libpurple: dns) DNS query for '192.168.1.1' queued
20:58:40: Performing DNS resolve: 192.168.1.1:5431
20:58:40: DNS resolve complete for 192.168.1.1:5431
20:58:40: (Libpurple: dnsquery) IP resolved for 192.168.1.1
20:58:40: (Libpurple: proxy) Attempting connection to 192.168.1.1
20:58:40: (Libpurple: proxy) Connecting to 192.168.1.1:5431 with no proxy
20:58:40: (Libpurple: proxy) Connection in progress
20:58:40: (Libpurple: proxy) Connected to 192.168.1.1:5431.
20:58:40: (Libpurple: util) Request: 'GET /dyndev/uuid:0000e098-10a0-00e0-80a0-489800e808e0 HTTP/1.1
Connection: close
Host: 192.168.1.1:5431

'
20:58:40: (Libpurple: util) Response headers: 'HTTP/1.0 200 OK
SERVER: LINUX/2.4 UPnP/1.0 BRCM400/1.0
DATE: Fri, 07 Jan 2000 02:24:13 GMT
CONTENT-TYPE: application/octet-stream
Cache-Control: max-age=1
PRAGMA: no-cache
Connection: Close

'
20:58:40: (Libpurple: upnp) parse_description_response(): could not get serviceTypeNode 7
20:58:40: (Libpurple: upnp) purple_upnp_parse_description(): control URL is NULL
20:58:40: (Libpurple: network) Couldn't create UPnP mapping
20:58:41: (Libpurple: network) Couldn't create UPnP mapping
20:58:41: (Libpurple: stun) using server 
20:58:41: (Libpurple: nat-pmp) found a default gateway
20:58:41: (Libpurple: nat-pmp) Attempting to retrieve the public ip address for the NAT device at: 192.168.1.1
20:58:41: (Libpurple: nat-pmp) 	Timeout: 0s 250000us
20:58:41: (Libpurple: nat-pmp) Response was not received from our gateway! Instead from: 160.229.148.7
20:58:41: (Libpurple: oscar) Sent message to 5232308.
20:58:45: (Libpurple: msn) C: NS 000: PNG
20:58:45: (Libpurple: msn) S: NS 000: QNG 43
20:58:57: (Libpurple: oscar) Incoming rendezvous message of type 32, user 5232308, status 0
20:58:57: (Libpurple: oscar) Remote user wants to try a different connection method
20:58:57: (Libpurple: dns) DNS query for '70.52.183.245' queued
20:58:57: (Libpurple: dns) DNS query for '192.168.254.2' queued
20:58:57: Performing DNS resolve: 70.52.183.245:5190
20:58:57: DNS resolve complete for 70.52.183.245:5190
20:58:57: (Libpurple: dnsquery) IP resolved for 70.52.183.245
20:58:57: (Libpurple: proxy) Attempting connection to 70.52.183.245
20:58:57: (Libpurple: proxy) Connecting to 70.52.183.245:5190 with no proxy
20:58:57: (Libpurple: proxy) Connection in progress
20:58:57: Performing DNS resolve: 192.168.254.2:5190
20:58:57: DNS resolve complete for 192.168.254.2:5190
20:58:57: (Libpurple: dnsquery) IP resolved for 192.168.254.2
20:58:57: (Libpurple: proxy) Attempting connection to 192.168.254.2
20:58:57: (Libpurple: proxy) Connecting to 192.168.254.2:5190 with no proxy
20:58:57: (Libpurple: proxy) Connection in progress
20:58:57: (Libpurple: proxy) Connected to 70.52.183.245:5190.
20:58:57: (Libpurple: oscar) Incoming OFT frame from 5232308 with type=0x0202
20:59:04: adiumPurpleConvWriteConv: Received Transfer of file Picture 2.png.zip complete from 5232308 [4]
20:59:04: Called write with no write_tag (read_tag 1070 write_tag 0) for 7dadad0

[charlieMonroe]

Sorry, it seems to be a duplicate to  http://trac.adiumx.com/ticket/5932

[jas8522]

#5932