Announce: Spotify Premium Plugin (Beta)

[Triode]

Thing is... spotifyd.log is nowhere on my C:\, I have searched. I have set helper App Logging to Debug, and I have clicked "Apply" several times. Clicking the Log link next to it opens an empty browser window at http://127.0.0.1:9000/spotifyd.log.

There is something strange re paths here - you should just see the log from that link. What you can do is start the main server. Then use task manager to manually kill Spotifyd.exe

After this you can open a cmd window, change to the location of Spotifyd.exe and then start it manually. You should then see the logging information in the cmd window. What does it say?

[OppfinnarJocke]

I got all those time outs, so I thought I'd restart SBS.

I got the error:
"Stopping SBS failed. See Event Viewer and please contact support"
I guess, in this case you are "support", Triode :-)

The Event viewer gives nothing. There are two entries from "now", both concern MySQL, one says "Normal shutdown" the other says "Shutdown completed".

[verypsb]

Can you post what the helper app logging in DEBUG settings shows when you see this?

Regarding starting a track which fails to play. Sometimes squeezeplay will remember the url you are playing and not do anything for the same url unless you press stop (press and hold pause) and then play. Does this restart it?

I'm seeing the same behaviour as OppfinnarJocke. Here's my log:

[17:53:36.249] log_message:63 log: 15:53:36.249 I [file_streamer_simple.cpp:757] Request for file 3c73b6cc57766fa6ee9def76f18cd061800911e1 complete (code: 0)

[17:53:52.068] log_message:63 log: 15:53:52.068 I [file_streamer_simple.cpp:757] Request for file 3c73b6cc57766fa6ee9def76f18cd061800911e1 complete (code: 0)

[17:54:51.832] log_message:63 log: 15:54:51.832 I [file_picker.cpp:88] File picker: track=a1e692ba8d3c4c95a0454fa270863cd8, file=f16d7103accf526f56770272bcc273434ce37d26, bitrate=160000, max=320000, target=320000, num=2

[17:54:54.140] log_message:63 log: 15:54:54.140 I [file_streamer_simple.cpp:757] Request for file f16d7103accf526f56770272bcc273434ce37d26 complete (code: 0)

[17:54:54.920] log_message:63 log: 15:54:54.920 I [file_streamer_simple.cpp:757] Request for file f16d7103accf526f56770272bcc273434ce37d26 complete (code: 0)

[17:55:15.809] log_message:63 log: 15:55:15.809 I [file_streamer_simple.cpp:757] Request for file f16d7103accf526f56770272bcc273434ce37d26 complete (code: 0)

[17:55:33.842] log_message:63 log: 15:55:33.842 I [file_streamer_simple.cpp:757] Request for file f16d7103accf526f56770272bcc273434ce37d26 complete (code: 0)

[18:00:10.954] log_message:63 log: 16:00:10.954 I [file_picker.cpp:88] File picker: track=7e6088581d314110964b4770a34ffc89, file=e5b233b94c16c734b1040ee962f265a0863ea5cd, bitrate=320000, max=320000, target=320000, num=3

[18:00:12.530] log_message:63 log: 16:00:12.530 I [file_streamer_simple.cpp:757] Request for file e5b233b94c16c734b1040ee962f265a0863ea5cd complete (code: 0)

[18:00:13.294] log_message:63 log: 16:00:13.294 I [file_streamer_simple.cpp:757] Request for file e5b233b94c16c734b1040ee962f265a0863ea5cd complete (code: 0)

[18:00:18.739] log_message:63 log: 16:00:18.739 I [file_streamer_simple.cpp:757] Request for file e5b233b94c16c734b1040ee962f265a0863ea5cd complete (code: 0)

[18:00:26.539] log_message:63 log: 16:00:26.539 I [file_streamer_simple.cpp:757] Request for file e5b233b94c16c734b1040ee962f265a0863ea5cd complete (code: 0)

[18:00:35.525] log_message:63 log: 16:00:35.525 I [file_streamer_simple.cpp:757] Request for file e5b233b94c16c734b1040ee962f265a0863ea5cd complete (code: 0)

[18:00:39.518] log_message:63 log: 16:00:39.518 I [file_picker.cpp:88] File picker: track=fd92889b79744924858f653d094b0682, file=280479220b0a53e28100ea9208a36d470f9a6c6d, bitrate=320000, max=320000, target=320000, num=3

[18:00:41.219] log_message:63 log: 16:00:41.219 I [file_streamer_simple.cpp:757] Request for file 280479220b0a53e28100ea9208a36d470f9a6c6d complete (code: 0)

[18:00:41.983] log_message:63 log: 16:00:41.983 I [file_streamer_simple.cpp:757] Request for file 280479220b0a53e28100ea9208a36d470f9a6c6d complete (code: 0)

[18:00:51.203] log_message:63 log: 16:00:51.203 I [file_streamer_simple.cpp:757] Request for file 280479220b0a53e28100ea9208a36d470f9a6c6d complete (code: 0)

[18:01:00.453] log_message:63 log: 16:01:00.453 I [file_streamer_simple.cpp:757] Request for file 280479220b0a53e28100ea9208a36d470f9a6c6d complete (code: 0)

[18:01:09.751] log_message:63 log: 16:01:09.751 I [file_streamer_simple.cpp:757] Request for file 280479220b0a53e28100ea9208a36d470f9a6c6d complete (code: 0)

[18:01:18.674] log_message:63 log: 16:01:18.674 I [file_streamer_simple.cpp:757] Request for file 280479220b0a53e28100ea9208a36d470f9a6c6d complete (code: 0)

[18:01:27.987] log_message:63 log: 16:01:27.987 I [file_streamer_simple.cpp:757] Request for file 280479220b0a53e28100ea9208a36d470f9a6c6d complete (code: 0)

[18:01:35.943] log_message:63 log: 16:01:35.943 I [file_streamer_simple.cpp:757] Request for file 280479220b0a53e28100ea9208a36d470f9a6c6d complete (code: 0)

[18:01:45.069] log_message:63 log: 16:01:45.069 I [file_streamer_simple.cpp:757] Request for file 280479220b0a53e28100ea9208a36d470f9a6c6d complete (code: 0)

[18:01:45.818] log_message:63 log: 16:01:45.818 I [file_picker.cpp:88] File picker: track=30c057f299de4ac4b793e55e5f24dde5, file=07481ba8dd648d6a08f9df3edbfba50fcb4cd635, bitrate=160000, max=320000, target=320000, num=2

[18:01:47.612] log_message:63 log: 16:01:47.612 I [file_streamer_simple.cpp:757] Request for file 07481ba8dd648d6a08f9df3edbfba50fcb4cd635 complete (code: 0)

[18:01:48.486] log_message:63 log: 16:01:48.486 I [file_streamer_simple.cpp:757] Request for file 07481ba8dd648d6a08f9df3edbfba50fcb4cd635 complete (code: 0)

[18:02:03.680] log_message:63 log: 16:02:03.680 I [file_streamer_simple.cpp:757] Request for file 07481ba8dd648d6a08f9df3edbfba50fcb4cd635 complete (code: 0)

[18:02:21.558] log_message:63 log: 16:02:21.558 I [file_streamer_simple.cpp:757] Request for file 07481ba8dd648d6a08f9df3edbfba50fcb4cd635 complete (code: 0)

[18:02:39.358] log_message:63 log: 16:02:39.358 I [file_streamer_simple.cpp:757] Request for file 07481ba8dd648d6a08f9df3edbfba50fcb4cd635 complete (code: 0)

[18:03:41.461] log_message:63 log: 16:03:41.461 I [file_picker.cpp:88] File picker: track=4bc5baf948684a9daff0ae3a395a104d, file=83faee6bf2b160e8bc25a2c57e09407d72491204, bitrate=320000, max=320000, target=320000, num=3

[18:03:43.052] log_message:63 log: 16:03:43.052 I [file_streamer_simple.cpp:757] Request for file 83faee6bf2b160e8bc25a2c57e09407d72491204 complete (code: 0)

[18:03:44.051] log_message:63 log: 16:03:44.051 I [file_streamer_simple.cpp:757] Request for file 83faee6bf2b160e8bc25a2c57e09407d72491204 complete (code: 0)

[18:03:49.448] log_message:63 log: 16:03:49.448 I [file_streamer_simple.cpp:757] Request for file 83faee6bf2b160e8bc25a2c57e09407d72491204 complete (code: 0)

[18:03:58.996] log_message:63 log: 16:03:58.996 I [file_streamer_simple.cpp:757] Request for file 83faee6bf2b160e8bc25a2c57e09407d72491204 complete (code: 0)

[18:04:07.466] log_message:63 log: 16:04:07.466 I [file_streamer_simple.cpp:757] Request for file 83faee6bf2b160e8bc25a2c57e09407d72491204 complete (code: 0)

[18:04:16.561] log_message:63 log: 16:04:16.561 I [file_streamer_simple.cpp:757] Request for file 83faee6bf2b160e8bc25a2c57e09407d72491204 complete (code: 0)

[18:04:19.713] log_message:63 log: 16:04:19.713 I [file_picker.cpp:88] File picker: track=771a1bfd2b124814941f3b46c31bd9c2, file=c6cad84ded5a648045f32f278efb69c0a0a126b1, bitrate=320000, max=320000, target=320000, num=3

[18:04:21.538] log_message:63 log: 16:04:21.538 I [file_streamer_simple.cpp:757] Request for file c6cad84ded5a648045f32f278efb69c0a0a126b1 complete (code: 0)

[18:04:22.427] log_message:63 log: 16:04:22.427 I [file_streamer_simple.cpp:757] Request for file c6cad84ded5a648045f32f278efb69c0a0a126b1 complete (code: 0)

[18:04:31.725] log_message:63 log: 16:04:31.725 I [file_streamer_simple.cpp:757] Request for file c6cad84ded5a648045f32f278efb69c0a0a126b1 complete (code: 0)

[18:04:38.105] log_message:63 log: 16:04:38.105 I [file_picker.cpp:88] File picker: track=df45f5909eb842eb9c35f8f02caf7475, file=f1317acfeb58049f25c0a108fa3d8a4c2f5845d4, bitrate=320000, max=320000, target=320000, num=3

[18:04:39.337] log_message:63 log: 16:04:39.337 I [file_streamer_simple.cpp:757] Request for file f1317acfeb58049f25c0a108fa3d8a4c2f5845d4 complete (code: 0)

[18:04:40.211] log_message:63 log: 16:04:40.211 I [file_streamer_simple.cpp:757] Request for file f1317acfeb58049f25c0a108fa3d8a4c2f5845d4 complete (code: 0)

[18:04:46.092] log_message:63 log: 16:04:46.092 I [file_picker.cpp:88] File picker: track=53ec847be8f94cf7afaaa7449c8b270a, file=995d910e484e56e5151a1fcb2698a2238e7d1b68, bitrate=320000, max=320000, target=320000, num=3

[18:04:47.761] log_message:63 log: 16:04:47.761 I [file_streamer_simple.cpp:757] Request for file 995d910e484e56e5151a1fcb2698a2238e7d1b68 complete (code: 0)

[18:04:48.541] log_message:63 log: 16:04:48.541 I [file_streamer_simple.cpp:757] Request for file 995d910e484e56e5151a1fcb2698a2238e7d1b68 complete (code: 0)

[18:04:56.856] log_message:63 log: 16:04:56.856 I [file_streamer_simple.cpp:757] Request for file 995d910e484e56e5151a1fcb2698a2238e7d1b68 complete (code: 0)

[18:05:06.559] log_message:63 log: 16:05:06.559 I [file_streamer_simple.cpp:757] Request for file 995d910e484e56e5151a1fcb2698a2238e7d1b68 complete (code: 0)

[18:05:15.795] log_message:63 log: 16:05:15.795 I [file_streamer_simple.cpp:757] Request for file 995d910e484e56e5151a1fcb2698a2238e7d1b68 complete (code: 0)

[Triode]

I got all those time outs, so I thought I'd restart SBS.

I got the error:
"Stopping SBS failed. See Event Viewer and please contact support"
I guess, in this case you are "support", Triode :-)

The Event viewer gives nothing. There are two entries from "now", both concern MySQL, one says "Normal shutdown" the other says "Shutdown completed".

Just restart it and make sure SBS is working ok....

[snow]

So the server it telling the player to connect to spotifyd, but we don't see anything in its log. Do you have any firewalls which would prevent the player connecting to port 9001 on the server machine?

[18:37:53.732] log_message:63 log: 16:37:53.732 I [file_streamer_simple.cpp:757] Request for file fd8356366ca4a2c9f607cc041c38ac50e66f71b4 complete (code: 0)

[18:38:03.138] log_message:63 log: 16:38:03.138 I [file_streamer_simple.cpp:757] Request for file fd8356366ca4a2c9f607cc041c38ac50e66f71b4 complete (code: 0)

It was the firewall, somehow it has stopped reporting when it blocks stuff, thats why I didn't think that was a problem. Now it woks great

This is the biggest thing ever!

[Triode]

I'm seeing the same behaviour as OppfinnarJocke. Here's my log:

Hum - that looks ok, but you don't have the log setting at DEBUG? I would expect to see more details about playing streams?

Sounds like my next version needs more debugging messages..

[verypsb]

OK, here's a new log:

[18:51:50.448] main:286 C:\PROGRA~3\SQUEEZ~1\Cache\INSTAL~1\Plugins\Spotif y\Bin\MSWIN3~1\spotifyd.exe started
[18:51:50.448] main:304 Config: username: verypsb cachedir: C:\ProgramData\Squeezebox\Cache\spotifycache bitrate: 320 httpport: 8999
[18:53:13.908] main:376 new connection
[18:53:13.908] main:401 req: search.json res: (null) par: q=tag:new prot: HTTP/1.0
[18:53:13.908] main:587 decoded search: tag:new
[18:53:16.779] log_message:63 log: 16:53:16.779 E [proxy_resolver_win32.cpp:219] WinHttpGetProxyForUrl failed

[18:53:16.779] log_message:63 log: 16:53:16.779 I [ap:1368] Connecting to AP A3.spotify.com:4070

[18:53:17.746] search_callback:306 search: ok
[18:53:17.855] container_loaded:75 playlist container loaded
[18:53:22.551] main:376 new connection
[18:53:22.551] main:401 req: browse.json res: spotify:album:5EOAvD6xmE1g9XV49wFzNG par: (null) prot: HTTP/1.0
[18:53:22.566] browse_album_callback:203 browse album: ok
[18:53:26.544] main:376 new connection
[18:53:26.544] main:401 req: stream.flc res: spotify:track:1wp9SHLdY9bMy7pCa2fd7C par: player=00:04:20:22:22:21&start=0 prot: SPOTSTREAM/1.0
[18:53:26.622] main:670 Now playing: Snow
[18:53:26.622] log_message:63 log: 16:53:26.622 I [file_picker.cpp:88] File picker: track=3207c0b810df4d7da3f47b7e77835074, file=e81a75369260e4ea8d53b66fe9aaf0668c12d34f, bitrate=160000, max=320000, target=320000, num=2

[18:53:28.650] main:376 new connection
[18:53:28.791] main:401 req: cover.jpg res: 83f2c689abf2402f77c0cae64c935e94084546a0 par: (null) prot: HTTP/1.1
[18:53:28.837] write_cover:33 cover fetch: No error
[18:53:28.853] log_message:63 log: 16:53:28.853 I [file_streamer_simple.cpp:757] Request for file e81a75369260e4ea8d53b66fe9aaf0668c12d34f complete (code: 0)

[18:53:29.742] log_message:63 log: 16:53:29.742 I [file_streamer_simple.cpp:757] Request for file e81a75369260e4ea8d53b66fe9aaf0668c12d34f complete (code: 0)

[18:53:30.975] main:376 new connection
[18:53:30.975] main:401 req: cover.jpg res: 83f2c689abf2402f77c0cae64c935e94084546a0 par: (null) prot: HTTP/1.1
[18:53:30.990] write_cover:33 cover fetch: No error
[18:53:48.587] log_message:63 log: 16:53:48.587 I [file_streamer_simple.cpp:757] Request for file e81a75369260e4ea8d53b66fe9aaf0668c12d34f complete (code: 0)

[18:54:09.491] log_message:63 log: 16:54:09.491 I [file_streamer_simple.cpp:757] Request for file e81a75369260e4ea8d53b66fe9aaf0668c12d34f complete (code: 0)

[18:54:09.725] main:376 new connection
[18:54:09.725] main:401 req: status.json res: (null) par: (null) prot: HTTP/1.0
[18:54:09.725] process_status:723 process status
[18:54:30.192] log_message:63 log: 16:54:30.192 I [file_streamer_simple.cpp:757] Request for file e81a75369260e4ea8d53b66fe9aaf0668c12d34f complete (code: 0)

[18:54:35.262] main:376 new connection
[18:54:35.278] main:401 req: stream.flc res: spotify:track:3mWMPUs1phDizmYspQJpVF par: player=00:04:20:22:22:21&start=0 prot: SPOTSTREAM/1.0
[18:54:35.278] main:453 existing streaming connection exists - killing
[18:54:52.173] main:376 new connection
[18:54:52.173] main:401 req: stream.flc res: spotify:track:1xrr9bAS0zfjCXdLKpLJnA par: player=00:04:20:22:22:21&start=0 prot: SPOTSTREAM/1.0
[18:54:52.173] main:453 existing streaming connection exists - killing
[18:54:59.286] main:376 new connection
[18:54:59.286] main:401 req: stream.flc res: spotify:track:5Te7AHL5oAW2S8GDsdv1vA par: player=00:04:20:22:22:21&start=0 prot: SPOTSTREAM/1.0
[18:54:59.286] main:453 existing streaming connection exists - killing
[18:55:19.176] main:376 new connection
[18:55:19.192] main:401 req: stream.flc res: spotify:track:1lhZ16dpgTLkM0nWGy9zdw par: player=00:04:20:22:22:21&start=0 prot: SPOTSTREAM/1.0
[18:55:19.192] main:453 existing streaming connection exists - killing
[18:55:31.064] main:376 new connection
[18:55:31.064] main:401 req: stream.flc res: spotify:track:3mWMPUs1phDizmYspQJpVF par: player=00:04:20:22:22:21&start=0 prot: SPOTSTREAM/1.0
[18:55:31.064] main:453 existing streaming connection exists - killing
[18:55:34.355] main:376 new connection
[18:55:34.355] main:401 req: stream.flc res: spotify:track:4Vv8u8Gbey9XAsF8oL84LS par: player=00:04:20:22:22:21&start=0 prot: SPOTSTREAM/1.0
[18:55:34.355] main:453 existing streaming connection exists - killing
[18:55:46.211] main:376 new connection
[18:55:46.211] main:401 req: browse.json res: spotify:album:0eeRKrhPyIAOxK2zemQiWd par: (null) prot: HTTP/1.0
[18:55:46.320] browse_album_callback:203 browse album: ok
[18:55:50.376] main:376 new connection
[18:55:50.376] main:401 req: stream.flc res: spotify:track:3DYZZZgqcRiQki31E6PHhv par: player=00:04:20:22:22:21&start=0 prot: SPOTSTREAM/1.0
[18:55:50.376] main:453 existing streaming connection exists - killing
[18:55:50.376] main:670 Now playing: Don't Give Up On Us
[18:55:50.376] log_message:63 log: 16:55:50.376 I [file_picker.cpp:88] File picker: track=77c28ec0da134ef19ca89beaa40e8571, file=f398a559918bcde47d843f055d19b39932a476de, bitrate=96000, max=320000, target=320000, num=1

[18:55:51.344] main:376 new connection
[18:55:51.359] main:401 req: cover.jpg res: 3d79e2fa95635e510dc1083d249a1120a6c91bd5 par: (null) prot: HTTP/1.1
[18:55:51.406] write_cover:33 cover fetch: No error
[18:55:52.139] log_message:63 log: 16:55:52.139 I [file_streamer_simple.cpp:757] Request for file f398a559918bcde47d843f055d19b39932a476de complete (code: 0)

[18:55:53.060] log_message:63 log: 16:55:53.060 I [file_streamer_simple.cpp:757] Request for file f398a559918bcde47d843f055d19b39932a476de complete (code: 0)

[18:55:53.621] main:376 new connection
[18:55:53.699] main:401 req: cover.jpg res: 3d79e2fa95635e510dc1083d249a1120a6c91bd5 par: (null) prot: HTTP/1.1
[18:55:53.699] write_cover:33 cover fetch: No error
[18:55:54.729] main:376 new connection
[18:55:54.729] main:401 req: cover.jpg res: 3d79e2fa95635e510dc1083d249a1120a6c91bd5 par: (null) prot: HTTP/1.1
[18:55:54.729] write_cover:33 cover fetch: No error
[18:55:57.350] main:376 new connection
[18:55:57.350] main:401 req: stream.flc res: spotify:track:1WtmYmcM3i2irFQrJKoH8q par: player=00:04:20:22:22:21&start=0 prot: SPOTSTREAM/1.0
[18:55:57.350] main:453 existing streaming connection exists - killing
[18:56:04.744] main:376 new connection
[18:56:04.760] main:401 req: stream.flc res: spotify:track:7DLMPjlUHdnZewnwmlCo7q par: player=00:04:20:22:22:21&start=0 prot: SPOTSTREAM/1.0
[18:56:04.760] main:453 existing streaming connection exists - killing
[18:56:16.647] main:376 new connection
[18:56:16.647] main:401 req: stream.flc res: spotify:track:7DLMPjlUHdnZewnwmlCo7q par: player=00:04:20:22:22:21&start=0 prot: SPOTSTREAM/1.0
[18:56:16.647] main:453 existing streaming connection exists - killing
[18:56:20.313] main:376 new connection
[18:56:20.313] main:401 req: cover.jpg res: 3d79e2fa95635e510dc1083d249a1120a6c91bd5 par: (null) prot: HTTP/1.1
[18:56:20.313] write_cover:33 cover fetch: No error
[18:56:58.658] main:376 new connection
[18:56:58.658] main:401 req: status.json res: (null) par: (null) prot: HTTP/1.0
[18:56:58.658] process_status:723 process status

[Triode]

OK, here's a new log:

Thanks - will review the code and come back to you on this - can you confirm the log setting was DEBUG for all of this period?

[OppfinnarJocke]

There is something strange re paths here - you should just see the log from that link. What you can do is start the main server. Then use task manager to manually kill Spotifyd.exe

After this you can open a cmd window, change to the location of Spotifyd.exe and then start it manually. You should then see the logging information in the cmd window. What does it say?

Playing this way now, with spotifyd.exe started in a cmd window, and I can tell you it seems to work *much better* than earlier. I get the playlists shown correctly as well, all of them. I have tried to abuse the system by switching FWD and BWD and changing songs etc, and it works, even the playlists.

The cmd win shows stuff like:

[19:20:02.937] main:376 new connection
[19:20:02.937] main:401 req: playlists.json res: spotify:user:kusin.knaselayli
st:567F8RrrJZkRfaLCjFZLGW par: (null) prot: HTTP/1.0
[19:20:02.937] process_singleplaylist:616 process single playlist
[19:20:27.078] main:376 new connection
[19:20:27.093] main:401 req: stream.flc res: spotify:track:1juMBk5TgYxjJF3nngPkk
e par: player=00:04:20:16:d6:58&start=0 prot: SPOTSTREAM/1.0
[19:20:27.093] main:453 existing streaming connection exists - killing
[19:20:27.093] main:670 Now playing: Legend
[19:20:27.093] log_message:63 log: 17:20:27.093 I [file_picker.cpp:88] File picker: track=2b306396a78244fa98576f7f3ab749fe, file=96241dc3195679fcc3b4d4e0b40d9c0
35d7fc5c1, bitrate=160000, max=320000, target=320000, num=2

[19:22:23.328] streambuf_canwrite:85 resetting stream
[19:22:23.328] streambuf_write:44 can't write: Unknown error 10054
[19:22:23.328] music_delivery:216 closing stream - flac returns error
[19:22:23.328] music_delivery:157 streamfd is 0 - discarding frames
[19:22:23.359] main:376 new connection
[19:22:23.359] main:401 req: stream.flc res: spotify:track:4BPRg6Wz7mYT4X2JmSJgv
k par: player=00:04:20:16:d6:58&start=0 prot: SPOTSTREAM/1.0
[19:22:23.359] main:670 Now playing: Circus Of Death
[19:22:23.359] log_message:63 log: 17:22:23.359 I [file_picker.cpp:88] File pick
er: track=977a939af8b34c238ba4761eebe78f4e, file=c5e87f1bd44ab3d8768245452c61893
77b8091df, bitrate=320000, max=320000, target=320000, num=3

[19:22:24.875] main:376 new connection
[19:22:24.875] main:401 req: cover.jpg res: 0eec07de5be2461275941113ba982860b574
b6db par: (null) prot: HTTP/1.1
[19:22:25.578] write_cover:33 cover fetch: No error
[19:22:25.671] main:376 new connection
[19:22:25.718] main:401 req: cover.jpg res: 0eec07de5be2461275941113ba982860b574
b6db par: (null) prot: HTTP/1.1
[19:22:25.718] write_cover:33 cover fetch: No error
[19:22:28.859] log_message:63 log: 17:22:28.859 I [file_streamer_simple.cpp:757]
Request for file c5e87f1bd44ab3d8768245452c6189377b8091df complete (code: 0)

[verypsb]

Thanks - will review the code and come back to you on this - can you confirm the log setting was DEBUG for all of this period?

Yes, the 2nd log has been in debug mode from start to finish.