Timeouts when sending large books to Kindle HD 7

[mathuin]

The mobile device is a Kindle Fire 7 HD (4th Generation) with Fire OS 4.5.2 and Calibre Companion version 3.5.9. The server is a Linux box running Ubuntu 14.04.1 LTS and calibre version 2.14.0.

On the mobile device, I started up CC and connected to the Linux box using the wireless device connection which succeeded with no errors. In calibre, I selected a single book -- "The Stories: Five Years of Original Fiction on Tor.Com" -- and clicked "Send to device". The calibre window went grey for a moment, then attempted to upload the book. For the first 30-45 seconds or so, the status was "Working..." and the progress was "Unavailable", then status changed to "Transferring books to device..." and the progress was 2%. This was unchanged until the running time reached 5m 48s at which point the status was "Error", progress was 100%, and a dialog box popped up with "Error communicating with device".

Here is the traceback as copied to the clipboard:
calibre, version 2.14.0
ERROR: Error: Error communicating with device

timed out

Traceback (most recent call last):
File "site-packages/calibre/gui2/device.py", line 87, in run
File "site-packages/calibre/gui2/device.py", line 584, in _upload_books
File "site-packages/calibre/devices/smart_device_app/driver.py", line 50, in _synchronizer
File "site-packages/calibre/devices/smart_device_app/driver.py", line 1444, in upload_books
File "site-packages/calibre/devices/smart_device_app/driver.py", line 682, in _put_file
File "site-packages/calibre/devices/smart_device_app/driver.py", line 573, in _send_byte_string
timeout: timed out

The last notification I saw on the mobile device was titled "Syncing with calibre ..." and said "Receiving books from calibre" and "Receiving "The Stories: Five Years of Original Fiction on Tor.com":". The progress bar gets maybe one-third of the way across before failing. To be fair, that book is fairly large -- but the same book and others had no trouble transferring to my Kindle Fire 1st Generation device.

At this point, the server no longer saw the mobile device as being connected while the mobile device thought it was still connected. Hitting 'disconnect' on the mobile device caused a dialog box to be displayed, reporting an unrecognized error during the connection progress and instructing me to try again. However, the mobile device cannot successfully reconnect to the server unless it is power-cycled -- force-stopping the application does not resolve the issue. A second run succeeds in moving the progress bar to about two-thirds of the way. A *third* run starts over again and only gets to one-third. Whee!

Smaller books do transfer correctly, individually and when selected as a group.

If there is any additional information I can give to help diagnose this issue, please let me know. Thanks!

Jack.

[chaley]

I looks like something on your network is breaking the connection between your device and your computer. The fact that you must power-cycle the device implies that the problem is somewhere inside your kindle, because it is holding on to the network socket. I suspect that waiting a couple of minutes for the network to time out will also work. It could also be something related to your wireless router and interference from neighbor access points.

Debug logs might help determine what is happening. Follow the instructions in this FAQ answer. Once you have calibre running in debug mode, try sending the book. When it fails, quit calibre, capture the debug log and email it to me at cc_debug_logs at charles dot haleys dot org. When you send the CC debug log, please erase the MultiPie address. No reason to clutter my son's inbox.

[mathuin]

I started calibre, noticed a new version was out, and updated to 2.15.0 before starting debug mode. I then tried to upload the problem book (144.9 MB), and it succeeded in 37.197 seconds according to the logs. I restarted calibre to disable debug mode and tried the other problem book (252.3 MB), and that one failed as before -- progress stopped roughly one-third into the book in about a minute or two, then waited four minutes or so for the timeout. As before, the timeout message appeared on the server and not on the mobile device. I waited five minutes by the clock, and the mobile device continued to display "Syncing with calibre ...". Hitting the back-arrow did nothing. Hitting the home icon then reopening the app brought up the app without the notification but still thinking it was connected. As before, hitting "disconnect" brought up "General connection error". I hit OK, and waited five minutes by the clock (mobile device went to sleep, had to wake it up), and still got the "Failed to connect" dialog box.

My wireless network is pretty reliable. It's currently not very busy and throughout the entire process the mobile device had a four-bar connection -- signal strength "Excellent" and Link speed "65Mbps".

My theory (and I'm only a novice Android app developer, so take it for what it is) is that the CC connection code has a bug keeping it from letting go of the connection, and that connection state is persisting which is why rebooting is the only way to make the app let go of that socket.

By the way, tried to upload the big file in debug mode, timed out after 326.718 seconds according to the logs.

Jack.

[chaley]

Originally Posted by mathuin

My theory (and I'm only a novice Android app developer, so take it for what it is) is that the CC connection code has a bug keeping it from letting go of the connection, and that connection state is persisting which is why rebooting is the only way to make the app let go of that socket.

An app cannot keep a socket open that has been closed by the operating system. It get an exception every time it tries to use a disconnected socket. CC uses this exception to reset the connection. The CC debug log will show this happening, assuming it does.

Sending 144MB in 37 seconds is reasonable performance.

Is there any chance that you are running out of space on the device?

I look forward to receiving the CC debug logs.

[mathuin]

I agree that 144MB in 37 seconds is reasonable. As for filling the device, I have 1.70 GB free according to the storage meter. That should be fine for a 252MB book.

I posted the CC debug logs as attachments to the forum thread in error instead of mailing them to you. That mistake has been corrected. Sorry about that!

Jack.

[chaley]

Sorry, I wasn't clear. Those are calibre debug logs, which I need. I also need the CC debug log, which you send from CC. Go to CC's settings, scroll to the bottom, and choose "Send a debug log to multipie".

[mathuin]

Ah, it's a new device and I'm not using it for email yet so I had to setup email. I removed the multipie address and sent the 438k-or-so message on its way!

Jack.

[chaley]

I have looked through the logs and, unfortunately, nothing jumps out.

Some things I can say:

• Regarding reconnnects: you said
  

  At this point, the server no longer saw the mobile device as being connected while the mobile device thought it was still connected. Hitting 'disconnect' on the mobile device caused a dialog box to be displayed, reporting an unrecognized error during the connection progress and instructing me to try again. However, the mobile device cannot successfully reconnect to the server unless it is power-cycled -- force-stopping the application does not resolve the issue.

  The logs show that every time the app was restarted the connection succeeded. None of the failures to connect were preceded by an application start. This makes me wonder whether the force-close actually closed the app. There isn't any evidence that it did. CC will close itself if you hit the back button enough times for it to ask "do you want to quit"? However ...
• The failure to connect after the failure to send is caused by your device not being able to "see" the wireless driver on the calibre computer (connection timed out), not because CC already has the socket open. Neither the UDP broadcast to find calibre nor the TCP connection to calibre succeed. This implies that the network stack in the operating system of your device is borked, because clearly after power-cycling the device both the broadcast and the connection work.
• I successfully transferred a 269MB PDF and a 552MB PDF to my Kindle Fire 8.9. Calibre is running on Win7/64. The transfer times were 3:37 and 7:24.
• The logs imply that the device went to sleep during the transfer, around 10 minutes into the transfer. For the failing book, as far as I can tell the transfer began at 2015-01-02 11:54:46. Calibre timed out 5 minutes 40 seconds later and closed the connection. Approximately 12 minutes after the start, apparently the device went to sleep. A minute later it was awakened, and 30 seconds later CC received a socket-closed exception. This means that CC was told about the socket being closed a full 7 minutes after calibre closed it. How this could happen is a mystery to me.

I am not sure how to proceed here. I can't repeat the problem, and the logs imply that the error was somewhere between CC and calibre. I am not happy with this conclusion. I would like to know *why* it is breaking.

Question: can you transfer the failing book using the content server? it uses different networking code both in calibre and in CC.

[mathuin]

Tried the wireless transfer again, and couldn't back-arrow out while the "Syncing with Calibre..." window was up. Waited a long time (didn't check) and it eventually disappeared and was replaced with the connection error box I've mentioned before. Hit OK, then hit back arrow twice, then restarted the app, and was able to connect again. Having a cancel button on the "Syncing with Calibre..." window would be nice.

Transfer with the content server was unsuccessful. Some interesting output on the calibre xterm, though:

libpng warning: iCCP: Not recognizing known sRGB profile that has been edited
timed out

Traceback (most recent call last):
File "site-packages/calibre/gui2/device.py", line 87, in run
File "site-packages/calibre/gui2/device.py", line 584, in _upload_books
File "site-packages/calibre/devices/smart_device_app/driver.py", line 50, in _synchronizer
File "site-packages/calibre/devices/smart_device_app/driver.py", line 1445, in upload_books
File "site-packages/calibre/devices/smart_device_app/driver.py", line 683, in _put_file
File "site-packages/calibre/devices/smart_device_app/driver.py", line 574, in _send_byte_string
timeout: timed out

Syntax Error: Couldn't find trailer dictionary
Syntax Error: Couldn't find trailer dictionary
Syntax Error: Couldn't read xref table
pdfinfo errored out with return code: 1
Traceback (most recent call last):
File "site-packages/calibre/customize/ui.py", line 349, in get_file_type_metadata
File "site-packages/calibre/customize/builtins.py", line 325, in get_metadata
File "site-packages/calibre/ebooks/metadata/pdf.py", line 101, in get_metadata
ValueError: Could not read info dict from PDF
Traceback (most recent call last):
File "site-packages/calibre/devices/smart_device_app/driver.py", line 612, in _call_client
File "site-packages/calibre/devices/smart_device_app/driver.py", line 654, in _receive_from_client
ControlError: Device responded with incorrect information

Not sure what that means.

Jack.

[chaley]

Originally Posted by mathuin

Tried the wireless transfer again, and couldn't back-arrow out while the "Syncing with Calibre..." window was up. Waited a long time (didn't check) and it eventually disappeared and was replaced with the connection error box I've mentioned before. Hit OK, then hit back arrow twice, then restarted the app, and was able to connect again. Having a cancel button on the "Syncing with Calibre..." window would be nice.

Yea, I can see why you would want it in this case. The problem we face is that it would be very easy to corrupt the database, and there isn't any way to tell calibre that CC wants to stop short of forcing a disconnect. I will look for some way to reliably stop the transfers.

It is good that connections worked again without power-cycling your device. That means that the OS (Android) recovered all the resources when CC died and cleaned up after itself, exactly as it is supposed to do.

Transfer with the content server was unsuccessful.

That is interesting. That says with certainty that the problem is not in calibre's wireless device driver or protocol, because the driver isn't used for content server connections. It also says with high probability that the problem is not in CC because the HTTP file transfer code comes (unmodified) from the Apache project. One way to check the latter point for sure: attempt a transfer using Chrome (or whatever web browser you have), which will entirely eliminate CC from the transfer process. In any event, it is looking more and more like the problem is in your device or in your network somewhere.

Note: the content server logs are available in Preferences / Sharing over the net.

Some interesting output on the calibre xterm, though:

libpng warning: iCCP: Not recognizing known sRGB profile that has been edited
timed out

Traceback (most recent call last):
File "site-packages/calibre/gui2/device.py", line 87, in run
File "site-packages/calibre/gui2/device.py", line 584, in _upload_books
File "site-packages/calibre/devices/smart_device_app/driver.py", line 50, in _synchronizer
File "site-packages/calibre/devices/smart_device_app/driver.py", line 1445, in upload_books
File "site-packages/calibre/devices/smart_device_app/driver.py", line 683, in _put_file
File "site-packages/calibre/devices/smart_device_app/driver.py", line 574, in _send_byte_string
timeout: timed out

This is left over from the transfer attempt

Syntax Error: Couldn't find trailer dictionary
Syntax Error: Couldn't find trailer dictionary
Syntax Error: Couldn't read xref table
pdfinfo errored out with return code: 1
Traceback (most recent call last):
File "site-packages/calibre/customize/ui.py", line 349, in get_file_type_metadata
File "site-packages/calibre/customize/builtins.py", line 325, in get_metadata
File "site-packages/calibre/ebooks/metadata/pdf.py", line 101, in get_metadata
ValueError: Could not read info dict from PDF

This looks like a PDF book was added to calibre, and calibre failed to read the metadata inside the PDF.

Traceback (most recent call last):
File "site-packages/calibre/devices/smart_device_app/driver.py", line 612, in _call_client
File "site-packages/calibre/devices/smart_device_app/driver.py", line 654, in _receive_from_client
ControlError: Device responded with incorrect information

This is probably CC disconnecting. We made a small mistake when we designed the wireless device protocol, leaving out a command to tell calibre when the device wants to disconnect. Instead we simply close the connection, which calibre detects as "incorrect information" when it attempts to poll the device.