[Alpha] Kobo-UNCaGED - Calibre wireless connection - Page 7

sherman · 12-17-2020, 01:24 AM

Here's a version of KU that logs to .adds/kobo-uncaged/ku.log instead of syslog.

It might help.

MGlitch · 12-17-2020, 01:37 AM

That's done the trick, at least in terms of getting a logfile that isn't gibberish

I believe this is the relevant bit

Code:

[Kobo-UNCaGED] 2020/12/17 01:27:48 [DEBUG] Read TCP packet: [5, {}]
[Kobo-UNCaGED] 2020/12/17 01:27:48 [DEBUG] Calibre Opcode received: 5
[Kobo-UNCaGED] 2020/12/17 01:27:48 [DEBUG] Processing FREE_SPACE packet: {}
[Kobo-UNCaGED] 2020/12/17 01:27:48 [DEBUG] Wrote TCP packet: 40[0,{"free_space_on_device":25799557120
[Kobo-UNCaGED] 2020/12/17 01:27:48 [DEBUG] Read TCP packet: [12, {}]
[Kobo-UNCaGED] 2020/12/17 01:27:48 [DEBUG] Calibre Opcode received: 12
[Kobo-UNCaGED] 2020/12/17 01:27:48 [DEBUG] Processing NOOP packet: {}
[Kobo-UNCaGED] 2020/12/17 01:27:48 [DEBUG] Wrote TCP packet: 6[0,{}]
[Kobo-UNCaGED] 2020/12/17 01:27:50 [DEBUG] Read TCP packet: [12, {}]
[Kobo-UNCaGED] 2020/12/17 01:27:50 [DEBUG] Calibre Opcode received: 12
[Kobo-UNCaGED] 2020/12/17 01:27:50 [DEBUG] Processing NOOP packet: {}
[Kobo-UNCaGED] 2020/12/17 01:27:50 [DEBUG] Wrote TCP packet: 6[0,{}]
[Kobo-UNCaGED] 2020/12/17 01:27:52 [DEBUG] Read TCP packet: [12, {}]
[Kobo-UNCaGED] 2020/12/17 01:27:52 [DEBUG] Calibre Opcode received: 12
[Kobo-UNCaGED] 2020/12/17 01:27:52 [DEBUG] Processing NOOP packet: {}
[Kobo-UNCaGED] 2020/12/17 01:27:52 [DEBUG] Wrote TCP packet: 6[0,{}]
[Kobo-UNCaGED] 2020/12/17 01:27:54 [DEBUG] Read TCP packet: [12, {}]
[Kobo-UNCaGED] 2020/12/17 01:27:54 [DEBUG] Calibre Opcode received: 12
[Kobo-UNCaGED] 2020/12/17 01:27:54 [DEBUG] Processing NOOP packet: {}
[Kobo-UNCaGED] 2020/12/17 01:27:54 [DEBUG] Wrote TCP packet: 6[0,{}]
[Kobo-UNCaGED] 2020/12/17 01:27:56 [DEBUG] Read TCP packet: [12, {}]
[Kobo-UNCaGED] 2020/12/17 01:27:56 [DEBUG] Calibre Opcode received: 12
[Kobo-UNCaGED] 2020/12/17 01:27:56 [DEBUG] Processing NOOP packet: {}
[Kobo-UNCaGED] 2020/12/17 01:27:56 [DEBUG] Wrote TCP packet: 6[0,{}]
[Kobo-UNCaGED] 2020/12/17 01:27:58 [DEBUG] Read TCP packet: [12, {}]
[Kobo-UNCaGED] 2020/12/17 01:27:58 [DEBUG] Calibre Opcode received: 12
[Kobo-UNCaGED] 2020/12/17 01:27:58 [DEBUG] Processing NOOP packet: {}
[Kobo-UNCaGED] 2020/12/17 01:27:58 [DEBUG] Wrote TCP packet: 6[0,{}]
[Kobo-UNCaGED] 2020/12/17 01:28:08 [DEBUG] Read TCP packet: [12, {}]
[Kobo-UNCaGED] 2020/12/17 01:28:08 [DEBUG] Calibre Opcode received: 12
[Kobo-UNCaGED] 2020/12/17 01:28:08 [DEBUG] Processing NOOP packet: {}
[Kobo-UNCaGED] 2020/12/17 01:28:08 [DEBUG] Wrote TCP packet: 6[0,{}]
[Kobo-UNCaGED] 2020/12/17 01:28:18 [DEBUG] Read TCP packet: [12, {}]
[Kobo-UNCaGED] 2020/12/17 01:28:18 [DEBUG] Calibre Opcode received: 12
[Kobo-UNCaGED] 2020/12/17 01:28:18 [DEBUG] Processing NOOP packet: {}
[Kobo-UNCaGED] 2020/12/17 01:28:18 [DEBUG] Wrote TCP packet: 6[0,{}]
[Kobo-UNCaGED] 2020/12/17 01:28:29 [DEBUG] Read TCP packet: [12, {}]
[Kobo-UNCaGED] 2020/12/17 01:28:29 [DEBUG] Calibre Opcode received: 12
[Kobo-UNCaGED] 2020/12/17 01:28:29 [DEBUG] Processing NOOP packet: {}
[Kobo-UNCaGED] 2020/12/17 01:28:29 [DEBUG] Wrote TCP packet: 6[0,{}]
[Kobo-UNCaGED] 2020/12/17 01:28:42 [DEBUG] Read TCP packet: [12, {}]
[Kobo-UNCaGED] 2020/12/17 01:28:42 [DEBUG] Calibre Opcode received: 12
[Kobo-UNCaGED] 2020/12/17 01:28:42 [DEBUG] Processing NOOP packet: {}
[Kobo-UNCaGED] 2020/12/17 01:28:42 [DEBUG] Wrote TCP packet: 6[0,{}]
[Kobo-UNCaGED] 2020/12/17 01:28:57 Start: packet reading failed: readDecodeCalibrePayload: connection closed: readTCP: connection timed out: read tcp 192.168.1.117:44818->192.168.1.248:9090: i/o timeout
[Kobo-UNCaGED] 2020/12/17 01:28:57 Start: packet reading failed: readDecodeCalibrePayload: connection closed: readTCP: connection timed out: read tcp 192.168.1.117:44818->192.168.1.248:9090: i/o timeout
Dec 17 01:28:57 [Kobo-UNCaGED] Running precautionary library rescan
Dec 17 01:29:02 [Kobo-UNCaGED] Disabled loopback interface

If you need more let me know, interestingly no mention of any book either on my Kobo or in my Calibre library is in the log.

sherman · 12-17-2020, 01:50 AM

Quote:

Originally Posted by MGlitch

That's done the trick, at least in terms of getting a logfile that isn't gibberish

If you need more let me know, interestingly no mention of any book either on my Kobo or in my Calibre library is in the log.

Thanks. This is weird. It seems that for some reason Calibre just stops sending NOOP packets, which then causes my code to timeout after a set period of time.

As for not seeing books in the log, I truncate each line to make sure the log doesn't balloon in size. You should see something like the following:

Code:

[Kobo-UNCaGED] 2020/12/17 19:45:44 [DEBUG] Processing SET_LIBRARY_INFO packet: {"libraryName": "Calibre Library", "libr
[Kobo-UNCaGED] 2020/12/17 19:45:44 [DEBUG] Wrote TCP packet: 6[0,{}]
[Kobo-UNCaGED] 2020/12/17 19:45:44 [DEBUG] Read TCP packet: [6, {"canStream": true, "canScan": true,
[Kobo-UNCaGED] 2020/12/17 19:45:44 [DEBUG] Calibre Opcode received: 6
[Kobo-UNCaGED] 2020/12/17 19:45:44 [DEBUG] Processing GET_BOOK_COUNT packet: {"canStream": true, "canScan": true, "wi
[Kobo-UNCaGED] 2020/12/17 19:45:44 [DEBUG] Wrote TCP packet: 51[0,{"count":107,"willStream":true,"wil
[Kobo-UNCaGED] 2020/12/17 19:45:44 [DEBUG] Wrote TCP packet: 201[0,{"priKey":0,"uuid":"088ca258-a4e7-
[Kobo-UNCaGED] 2020/12/17 19:45:44 [DEBUG] Wrote TCP packet: 223[0,{"priKey":1,"uuid":"fd21303e-27bd-

That is the Kobo sending the list of books to Calibre.

EDIT: I guess the only thing I can think to try would be to restart both your Kobo, and Calibre, and see what happens. I must confess I'm a bit perplexed.

sherman · 12-17-2020, 02:04 AM

Ok, just noticed something even weirder. The timestamps for the NOOP packets seem to be getting further and further apart.

The first few are approx 2 seconds apart.

Then after 01:27:58, it seems to jump to around 10 seconds apart. Then approx 11 seconds, then 13 seconds

I have my timeout set to 15 seconds.

That log is showing something very very strange.

davidfor · 12-17-2020, 02:44 AM

Quote:

Originally Posted by sherman

Ooof, that doesn't sound good!

Maybe others may have an idea of what's going on here? I certainly don't. I've never seen a corrupted syslog like that.

It isn't corrupted. As of firmware version 4.25.x, the log files produced when developers mode is on are encrypted. There is some discussion of this and how to look at the syslog in Trouble Getting Kobo Sync with CalibreWeb working.

sherman · 12-17-2020, 02:51 AM

Quote:

Originally Posted by davidfor

It isn't corrupted. As of firmware version 4.25.x, the log files produced when developers mode is on are encrypted. There is some discussion of this and how to look at the syslog in Trouble Getting Kobo Sync with CalibreWeb working.

Ah.

Thanks for the heads-up on that.

I'm almost always using logread to read syslog, so I hadn't really noticed the change.

I think I'm definitely switching to a dedicated logfile for KU now.

MGlitch · 12-17-2020, 02:53 AM

Quote:

Originally Posted by sherman

Ok, just noticed something even weirder. The timestamps for the NOOP packets seem to be getting further and further apart.

The first few are approx 2 seconds apart.

Then after 01:27:58, it seems to jump to around 10 seconds apart. Then approx 11 seconds, then 13 seconds

I have my timeout set to 15 seconds.

That log is showing something very very strange.

I've not looked at the logs again, but I restarted the Kobo and Calibre and still getting the disconnect. Tomorrow I'll try rebooting my Mac and the router etc. and see if that helps, though I doubt it as every other indication of my network is healthy.

Quote:

Originally Posted by davidfor

It isn't corrupted. As of firmware version 4.25.x, the log files produced when developers mode is on are encrypted. There is some discussion of this and how to look at the syslog in Trouble Getting Kobo Sync with CalibreWeb working.

That's a relief actually. Was worried I'd need to do the deeper reset of my Forma.

Carmelocotonto · 12-17-2020, 03:49 AM

Quote:

Originally Posted by sherman

Here's a version of KU that logs to .adds/kobo-uncaged/ku.log instead of syslog.

It might help.

This afternoon I will try this version for more information for you. thanks

sherman · 12-17-2020, 04:32 AM

So, looking at the Calibre source code, this is what sends the periodic NOOP opcode.

The documentation for that method indicates that the GUI thread periodically calls it.

The smart device driver sends a NOOP every five probes. The 'normal' time between NOOP opcodes appears to be 2-3 seconds, so each probe is probably around 500ms apart (I haven't actually checked the code to see what it is).

The issue MGlitch appears to be having is that there seems to be something preventing the probes from occurring at a 'normal' rate. If Calibre is idle, then the only thing I can think of that would cause this issue would be a misbehaving plugin.

Of course, this is all a bunch of speculation...

MGlitch · 12-17-2020, 05:08 AM

Quote:

Originally Posted by sherman

The issue MGlitch appears to be having is that there seems to be something preventing the probes from occurring at a 'normal' rate. If Calibre is idle, then the only thing I can think of that would cause this issue would be a misbehaving plugin.

Of course, this is all a bunch of speculation...

I've removed every user installed plugin, restarted Calibre. All pre-installed plugins are up to date. Issue persists. Log, though I dunno if it'll help clear anything up.

Code:

[Kobo-UNCaGED] 2020/12/17 05:03:09 [DEBUG] Calibre Opcode received: 7
[Kobo-UNCaGED] 2020/12/17 05:03:09 [DEBUG] Processing SEND_BOOKLISTS packet: {"count": 0, "collections": {}, "willStr
[Kobo-UNCaGED] 2020/12/17 05:03:09 [DEBUG] Read TCP packet: [5, {}]
[Kobo-UNCaGED] 2020/12/17 05:03:09 [DEBUG] Calibre Opcode received: 5
[Kobo-UNCaGED] 2020/12/17 05:03:09 [DEBUG] Processing FREE_SPACE packet: {}
[Kobo-UNCaGED] 2020/12/17 05:03:09 [DEBUG] Wrote TCP packet: 40[0,{"free_space_on_device":25801392128
[Kobo-UNCaGED] 2020/12/17 05:03:09 [DEBUG] Read TCP packet: [12, {}]
[Kobo-UNCaGED] 2020/12/17 05:03:09 [DEBUG] Calibre Opcode received: 12
[Kobo-UNCaGED] 2020/12/17 05:03:09 [DEBUG] Processing NOOP packet: {}
[Kobo-UNCaGED] 2020/12/17 05:03:09 [DEBUG] Wrote TCP packet: 6[0,{}]
[Kobo-UNCaGED] 2020/12/17 05:03:11 [DEBUG] Read TCP packet: [12, {}]
[Kobo-UNCaGED] 2020/12/17 05:03:11 [DEBUG] Calibre Opcode received: 12
[Kobo-UNCaGED] 2020/12/17 05:03:11 [DEBUG] Processing NOOP packet: {}
[Kobo-UNCaGED] 2020/12/17 05:03:11 [DEBUG] Wrote TCP packet: 6[0,{}]
[Kobo-UNCaGED] 2020/12/17 05:03:13 [DEBUG] Read TCP packet: [12, {}]
[Kobo-UNCaGED] 2020/12/17 05:03:13 [DEBUG] Calibre Opcode received: 12
[Kobo-UNCaGED] 2020/12/17 05:03:13 [DEBUG] Processing NOOP packet: {}
[Kobo-UNCaGED] 2020/12/17 05:03:13 [DEBUG] Wrote TCP packet: 6[0,{}]
[Kobo-UNCaGED] 2020/12/17 05:03:16 [DEBUG] Read TCP packet: [12, {}]
[Kobo-UNCaGED] 2020/12/17 05:03:16 [DEBUG] Calibre Opcode received: 12
[Kobo-UNCaGED] 2020/12/17 05:03:16 [DEBUG] Processing NOOP packet: {}
[Kobo-UNCaGED] 2020/12/17 05:03:16 [DEBUG] Wrote TCP packet: 6[0,{}]
[Kobo-UNCaGED] 2020/12/17 05:03:18 [DEBUG] Read TCP packet: [12, {}]
[Kobo-UNCaGED] 2020/12/17 05:03:18 [DEBUG] Calibre Opcode received: 12
[Kobo-UNCaGED] 2020/12/17 05:03:18 [DEBUG] Processing NOOP packet: {}
[Kobo-UNCaGED] 2020/12/17 05:03:18 [DEBUG] Wrote TCP packet: 6[0,{}]
[Kobo-UNCaGED] 2020/12/17 05:03:20 [DEBUG] Read TCP packet: [12, {}]
[Kobo-UNCaGED] 2020/12/17 05:03:20 [DEBUG] Calibre Opcode received: 12
[Kobo-UNCaGED] 2020/12/17 05:03:20 [DEBUG] Processing NOOP packet: {}
[Kobo-UNCaGED] 2020/12/17 05:03:20 [DEBUG] Wrote TCP packet: 6[0,{}]
[Kobo-UNCaGED] 2020/12/17 05:03:30 [DEBUG] Read TCP packet: [12, {}]
[Kobo-UNCaGED] 2020/12/17 05:03:30 [DEBUG] Calibre Opcode received: 12
[Kobo-UNCaGED] 2020/12/17 05:03:30 [DEBUG] Processing NOOP packet: {}
[Kobo-UNCaGED] 2020/12/17 05:03:30 [DEBUG] Wrote TCP packet: 6[0,{}]
[Kobo-UNCaGED] 2020/12/17 05:03:40 [DEBUG] Read TCP packet: [12, {}]
[Kobo-UNCaGED] 2020/12/17 05:03:40 [DEBUG] Calibre Opcode received: 12
[Kobo-UNCaGED] 2020/12/17 05:03:40 [DEBUG] Processing NOOP packet: {}
[Kobo-UNCaGED] 2020/12/17 05:03:40 [DEBUG] Wrote TCP packet: 6[0,{}]
[Kobo-UNCaGED] 2020/12/17 05:03:50 [DEBUG] Read TCP packet: [12, {}]
[Kobo-UNCaGED] 2020/12/17 05:03:50 [DEBUG] Calibre Opcode received: 12
[Kobo-UNCaGED] 2020/12/17 05:03:50 [DEBUG] Processing NOOP packet: {}
[Kobo-UNCaGED] 2020/12/17 05:03:50 [DEBUG] Wrote TCP packet: 6[0,{}]
[Kobo-UNCaGED] 2020/12/17 05:04:05 Start: packet reading failed: readDecodeCalibrePayload: connection closed: readTCP: connection timed out: read tcp 192.168.1.117:47039->192.168.1.248:9090: i/o timeout
[Kobo-UNCaGED] 2020/12/17 05:04:05 Start: packet reading failed: readDecodeCalibrePayload: connection closed: readTCP: connection timed out: read tcp 192.168.1.117:47039->192.168.1.248:9090: i/o timeout
Dec 17 05:04:05 [Kobo-UNCaGED] Running precautionary library rescan
Dec 17 05:04:10 [Kobo-UNCaGED] Disabled loopback interface

sherman · 12-17-2020, 05:40 AM

This is a headscratcher indeed.

I shall sleep on it to see if I receive any enlightenment.

As an interim measure, tomorrow I can increase the timeout period a bit to see if that helps for you, although it isn't really a proper solution.

sherman · 12-17-2020, 05:52 AM

One final request before I jump into bed if I may @MGlitch

Could you please post the entire log? I want to double check that the sequence of events happens as expected without irregularities.

If you don't want to paste it into a code block, feel free to attach it, or even PM it to me.

Thanks.

Carmelocotonto · 12-17-2020, 10:18 AM

Quote:

Originally Posted by Carmelocotonto

This afternoon I will try this version for more information for you. thanks

My try:

Dec 17 15:55:26 [Kobo-UNCaGED] Enabled loopback interface
Dec 17 15:55:26 [Kobo-UNCaGED] Starting Kobo UNCaGED
[Kobo-UNCaGED] 2020/12/17 15:55:27 Started Kobo-UNCaGED
[Kobo-UNCaGED] 2020/12/17 15:55:27 Reading options
[Kobo-UNCaGED] 2020/12/17 15:55:27 Creating KU object
[Kobo-UNCaGED] 2020/12/17 15:55:27 Getting Kobo Info
[Kobo-UNCaGED] 2020/12/17 15:55:33 Getting Device Info
[Kobo-UNCaGED] 2020/12/17 15:55:33 Reading Metadata
[Kobo-UNCaGED] 2020/12/17 15:55:33 Reading metadata.calibre
[Kobo-UNCaGED] 2020/12/17 15:55:34 Gathering metadata
[Kobo-UNCaGED] 2020/12/17 15:55:34 New: failed to read metadata file: readMDfile: bkRows error: database disk image is malformed
[Kobo-UNCaGED] 2020/12/17 15:55:34 New: failed to read metadata file: readMDfile: bkRows error: database disk image is malformed
Dec 17 15:55:34 [Kobo-UNCaGED] Running precautionary library rescan
Dec 17 15:55:45 [Kobo-UNCaGED] Disabled loopback interface

It is possible that my kobo database is malformed or my calibre.metadata file?

MGlitch · 12-17-2020, 12:57 PM

Heres the full log

MGsKULog.txt

NiLuJe · 12-17-2020, 01:45 PM

@sherman: FWIW, I'm seeing a similar pattern of a burst of NOOP every 2s for a while on connect, before it gets staggered a bit more towards ~10s.

It's been holding steady at ~10s for a few minutes now, and I haven't touched calibre at all during the experiment

.

(Calibre 5.7.2 on a Linux host).

Code:

Dec 17 19:39:03 KoboUNCaGED[18271]: 2020/12/17 19:39:03 [DEBUG] setTCPDeadline: setting TCP deadline to 120000 milliseconds
Dec 17 19:39:03 KoboUNCaGED[18271]: 2020/12/17 19:39:03 [DEBUG] Read TCP packet: [7, {"count": 2, "collections": {}, "wil
Dec 17 19:39:03 KoboUNCaGED[18271]: 2020/12/17 19:39:03 [DEBUG] Calibre Opcode received: 7
Dec 17 19:39:03 KoboUNCaGED[18271]: 2020/12/17 19:39:03 [DEBUG] Processing SEND_BOOKLISTS packet: {"count": 2, "collections": {}, "willStr
Dec 17 19:39:03 KoboUNCaGED[18271]: 2020/12/17 19:39:03 [DEBUG] Read TCP packet: [16, {"index": 0, "count": 2, "data": {"
Dec 17 19:39:04 KoboUNCaGED[18271]: 2020/12/17 19:39:04 [DEBUG] Read TCP packet: [16, {"index": 1, "count": 2, "data": {"
Dec 17 19:39:05 KoboUNCaGED[18271]: 2020/12/17 19:39:05 [DEBUG] Read TCP packet: [5, {}]
Dec 17 19:39:05 KoboUNCaGED[18271]: 2020/12/17 19:39:05 [DEBUG] Calibre Opcode received: 5
Dec 17 19:39:05 KoboUNCaGED[18271]: 2020/12/17 19:39:05 [DEBUG] Processing FREE_SPACE packet: {}
Dec 17 19:39:05 KoboUNCaGED[18271]: 2020/12/17 19:39:05 [DEBUG] Wrote TCP packet: 39[0,{"free_space_on_device":1156497408}
Dec 17 19:39:05 KoboUNCaGED[18271]: 2020/12/17 19:39:05 [DEBUG] Read TCP packet: [12, {}]
Dec 17 19:39:05 KoboUNCaGED[18271]: 2020/12/17 19:39:05 [DEBUG] Calibre Opcode received: 12
Dec 17 19:39:05 KoboUNCaGED[18271]: 2020/12/17 19:39:05 [DEBUG] Processing NOOP packet: {}
Dec 17 19:39:05 KoboUNCaGED[18271]: 2020/12/17 19:39:05 [DEBUG] Wrote TCP packet: 6[0,{}]
Dec 17 19:39:07 KoboUNCaGED[18271]: 2020/12/17 19:39:07 [DEBUG] Read TCP packet: [12, {}]
Dec 17 19:39:07 KoboUNCaGED[18271]: 2020/12/17 19:39:07 [DEBUG] Calibre Opcode received: 12
Dec 17 19:39:07 KoboUNCaGED[18271]: 2020/12/17 19:39:07 [DEBUG] Processing NOOP packet: {}
Dec 17 19:39:07 KoboUNCaGED[18271]: 2020/12/17 19:39:07 [DEBUG] Wrote TCP packet: 6[0,{}]
Dec 17 19:39:09 KoboUNCaGED[18271]: 2020/12/17 19:39:09 [DEBUG] Read TCP packet: [12, {}]
Dec 17 19:39:09 KoboUNCaGED[18271]: 2020/12/17 19:39:09 [DEBUG] Calibre Opcode received: 12
Dec 17 19:39:09 KoboUNCaGED[18271]: 2020/12/17 19:39:09 [DEBUG] Processing NOOP packet: {}
Dec 17 19:39:09 KoboUNCaGED[18271]: 2020/12/17 19:39:09 [DEBUG] Wrote TCP packet: 6[0,{}]
Dec 17 19:39:11 KoboUNCaGED[18271]: 2020/12/17 19:39:11 [DEBUG] Read TCP packet: [12, {}]
Dec 17 19:39:11 KoboUNCaGED[18271]: 2020/12/17 19:39:11 [DEBUG] Calibre Opcode received: 12
Dec 17 19:39:11 KoboUNCaGED[18271]: 2020/12/17 19:39:11 [DEBUG] Processing NOOP packet: {}
Dec 17 19:39:11 KoboUNCaGED[18271]: 2020/12/17 19:39:11 [DEBUG] Wrote TCP packet: 6[0,{}]
Dec 17 19:39:13 KoboUNCaGED[18271]: 2020/12/17 19:39:13 [DEBUG] Read TCP packet: [12, {}]
Dec 17 19:39:13 KoboUNCaGED[18271]: 2020/12/17 19:39:13 [DEBUG] Calibre Opcode received: 12
Dec 17 19:39:13 KoboUNCaGED[18271]: 2020/12/17 19:39:13 [DEBUG] Processing NOOP packet: {}
Dec 17 19:39:13 KoboUNCaGED[18271]: 2020/12/17 19:39:13 [DEBUG] Wrote TCP packet: 6[0,{}]
Dec 17 19:39:15 KoboUNCaGED[18271]: 2020/12/17 19:39:15 [DEBUG] Read TCP packet: [12, {}]
Dec 17 19:39:15 KoboUNCaGED[18271]: 2020/12/17 19:39:15 [DEBUG] Calibre Opcode received: 12
Dec 17 19:39:15 KoboUNCaGED[18271]: 2020/12/17 19:39:15 [DEBUG] Processing NOOP packet: {}
Dec 17 19:39:15 KoboUNCaGED[18271]: 2020/12/17 19:39:15 [DEBUG] Wrote TCP packet: 6[0,{}]
Dec 17 19:39:25 KoboUNCaGED[18271]: 2020/12/17 19:39:25 [DEBUG] Read TCP packet: [12, {}]
Dec 17 19:39:25 KoboUNCaGED[18271]: 2020/12/17 19:39:25 [DEBUG] Calibre Opcode received: 12
Dec 17 19:39:25 KoboUNCaGED[18271]: 2020/12/17 19:39:25 [DEBUG] Processing NOOP packet: {}
Dec 17 19:39:25 KoboUNCaGED[18271]: 2020/12/17 19:39:25 [DEBUG] Wrote TCP packet: 6[0,{}]
Dec 17 19:39:35 KoboUNCaGED[18271]: 2020/12/17 19:39:35 [DEBUG] Read TCP packet: [12, {}]
Dec 17 19:39:35 KoboUNCaGED[18271]: 2020/12/17 19:39:35 [DEBUG] Calibre Opcode received: 12
Dec 17 19:39:35 KoboUNCaGED[18271]: 2020/12/17 19:39:35 [DEBUG] Processing NOOP packet: {}
Dec 17 19:39:35 KoboUNCaGED[18271]: 2020/12/17 19:39:35 [DEBUG] Wrote TCP packet: 6[0,{}]
Dec 17 19:39:45 KoboUNCaGED[18271]: 2020/12/17 19:39:45 [DEBUG] Read TCP packet: [12, {}]
Dec 17 19:39:45 KoboUNCaGED[18271]: 2020/12/17 19:39:45 [DEBUG] Calibre Opcode received: 12
Dec 17 19:39:45 KoboUNCaGED[18271]: 2020/12/17 19:39:45 [DEBUG] Processing NOOP packet: {}
Dec 17 19:39:45 KoboUNCaGED[18271]: 2020/12/17 19:39:45 [DEBUG] Wrote TCP packet: 6[0,{}]
Dec 17 19:39:55 KoboUNCaGED[18271]: 2020/12/17 19:39:55 [DEBUG] Read TCP packet: [12, {}]
Dec 17 19:39:55 KoboUNCaGED[18271]: 2020/12/17 19:39:55 [DEBUG] Calibre Opcode received: 12
Dec 17 19:39:55 KoboUNCaGED[18271]: 2020/12/17 19:39:55 [DEBUG] Processing NOOP packet: {}
Dec 17 19:39:55 KoboUNCaGED[18271]: 2020/12/17 19:39:55 [DEBUG] Wrote TCP packet: 6[0,{}]
Dec 17 19:40:05 KoboUNCaGED[18271]: 2020/12/17 19:40:05 [DEBUG] Read TCP packet: [12, {}]
Dec 17 19:40:05 KoboUNCaGED[18271]: 2020/12/17 19:40:05 [DEBUG] Calibre Opcode received: 12
Dec 17 19:40:05 KoboUNCaGED[18271]: 2020/12/17 19:40:05 [DEBUG] Processing NOOP packet: {}
Dec 17 19:40:05 KoboUNCaGED[18271]: 2020/12/17 19:40:05 [DEBUG] Wrote TCP packet: 6[0,{}]

...

Dec 17 19:45:07 KoboUNCaGED[18271]: 2020/12/17 19:45:07 [DEBUG] Read TCP packet: [12, {}]
Dec 17 19:45:07 KoboUNCaGED[18271]: 2020/12/17 19:45:07 [DEBUG] Calibre Opcode received: 12
Dec 17 19:45:07 KoboUNCaGED[18271]: 2020/12/17 19:45:07 [DEBUG] Processing NOOP packet: {}
Dec 17 19:45:07 KoboUNCaGED[18271]: 2020/12/17 19:45:07 [DEBUG] Wrote TCP packet: 6[0,{}]
Dec 17 19:45:17 KoboUNCaGED[18271]: 2020/12/17 19:45:17 [DEBUG] Read TCP packet: [12, {}]
Dec 17 19:45:17 KoboUNCaGED[18271]: 2020/12/17 19:45:17 [DEBUG] Calibre Opcode received: 12
Dec 17 19:45:17 KoboUNCaGED[18271]: 2020/12/17 19:45:17 [DEBUG] Processing NOOP packet: {}
Dec 17 19:45:17 KoboUNCaGED[18271]: 2020/12/17 19:45:17 [DEBUG] Wrote TCP packet: 6[0,{}]

Similar Threads
Thread	Thread Starter	Forum	Replies	Last Post
PDF compressed when sent with Calibre Wireless Connection	zorrodee666	KOReader	1	03-23-2019 10:50 PM
connecting Calibre to Calibre without wireless connection	TomSpot	Calibre Companion	1	07-10-2018 06:07 AM
Wireless connection to calibre.	sorg	Kindle Developer's Corner	33	07-16-2015 11:49 AM
Calibre Companion and wireless connection	taratears	Calibre Companion	13	03-28-2015 05:32 PM
Nook Touch/Calibre wireless connection?	tigersfan	Devices	8	01-10-2012 02:51 PM

12-17-2020, 02:04 AM	#94
sherman Guru Posts: 856 Karma: 2676800 Join Date: Aug 2008 Location: Taranaki - NZ Device: Kobo Aura H2O, Kobo Forma	Ok, just noticed something even weirder. The timestamps for the NOOP packets seem to be getting further and further apart. The first few are approx 2 seconds apart. Then after 01:27:58, it seems to jump to around 10 seconds apart. Then approx 11 seconds, then 13 seconds I have my timeout set to 15 seconds. That log is showing something very very strange.

12-17-2020, 04:32 AM	#99
sherman Guru Posts: 856 Karma: 2676800 Join Date: Aug 2008 Location: Taranaki - NZ Device: Kobo Aura H2O, Kobo Forma	So, looking at the Calibre source code, this is what sends the periodic NOOP opcode. The documentation for that method indicates that the GUI thread periodically calls it. The smart device driver sends a NOOP every five probes. The 'normal' time between NOOP opcodes appears to be 2-3 seconds, so each probe is probably around 500ms apart (I haven't actually checked the code to see what it is). The issue MGlitch appears to be having is that there seems to be something preventing the probes from occurring at a 'normal' rate. If Calibre is idle, then the only thing I can think of that would cause this issue would be a misbehaving plugin. Of course, this is all a bunch of speculation...

12-17-2020, 05:40 AM	#101
sherman Guru Posts: 856 Karma: 2676800 Join Date: Aug 2008 Location: Taranaki - NZ Device: Kobo Aura H2O, Kobo Forma	This is a headscratcher indeed. I shall sleep on it to see if I receive any enlightenment. As an interim measure, tomorrow I can increase the timeout period a bit to see if that helps for you, although it isn't really a proper solution.

12-17-2020, 05:52 AM	#102
sherman Guru Posts: 856 Karma: 2676800 Join Date: Aug 2008 Location: Taranaki - NZ Device: Kobo Aura H2O, Kobo Forma	One final request before I jump into bed if I may @MGlitch Could you please post the entire log? I want to double check that the sequence of events happens as expected without irregularities. If you don't want to paste it into a code block, feel free to attach it, or even PM it to me. Thanks.

12-17-2020, 12:57 PM	#104
MGlitch Wizard Posts: 2,841 Karma: 22003124 Join Date: Aug 2014 Device: Kobo Forma, Kobo Sage, Kobo Libra 2	Heres the full log MGsKULog.txt

Advert

Advert