First Last Prev Next    This bug is not in your last search results.
Bug 15919 - Cannot connect to mysqueezebox.com: "POST body too large" error, (max=51200)
: Cannot connect to mysqueezebox.com: "POST body too large" error, (max=51200)
Status: RESOLVED DUPLICATE of bug 16617
Product: SB Radio
Classification: Unclassified
Component: Networking
: Include FW version in comment
: PC Windows 7
: -- normal (vote)
: Investigating
Assigned To: Alan Young
:
Depends on:
Blocks:
  Show dependency tree / graph
 
Reported: 2010-03-18 15:31 UTC by Pascal Roncolato
Modified: 2010-10-28 02:58 UTC (History)
4 users (show)

See Also:
Category: ---

Attachments
This is Microsoft Netmon 2.1. Frame #4 is Radio request to mysqueezebox.com server (62.34 KB, application/octet-stream)
2010-03-18 15:31 UTC, Pascal Roncolato 		Details
Problem is back again: sending /var/mlog/messages file (162.91 KB, text/plain)
2010-03-24 23:39 UTC, Pascal Roncolato 		Details
/var/log/messages (13.02 KB, application/x-gzip)
2010-10-25 10:03 UTC, Bradley Froehle 		Details
View All Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description Pascal Roncolato 2010-03-18 15:31:04 UTC 
Created attachment 6667 [details]
This is Microsoft Netmon 2.1. Frame #4 is Radio request to mysqueezebox.com server

Today, I had a connection issue with my Squeezebox Radio while attempting to
listen to my radio. I'm running 7.4.2-r8423 over WIFI. The connection was fine
in the morning.

I made a network capture which I can provide if needed (Netmon 2.1 or
Ethereal).
What I can see is the my SB Radio connects to mysqueezebox.com succesfully and
sends 58081 bytes over TCP port 9000:
TCP: Control Bits: .A...., len: 1440, seq:1582145320-1582146760, ack:
267207787, win: 2920, src:57523  dst: 9000 
00000040        50 4F 53 54 20 2F 63 6F 6D 65 74 64 20 48   POST./cometd.H
00000050  54 54 50 2F 31 2E 31 0D 0A 55 73 65 72 2D 41 67 TTP/1.1..User-Ag
00000060  65 6E 74 3A 20 53 71 75 65 65 7A 65 50 6C 61 79 ent:.SqueezePlay
00000070  2D 62 61 62 79 2F 37 2E 34 2E 32 2D 72 38 34 32 -baby/7.4.2-r842
00000080  33 20 28 61 72 6D 76 35 74 65 6A 6C 29 0D 0A 43 3.(armv5tejl)..C
00000090  6F 6E 74 65 6E 74 2D 4C 65 6E 67 74 68 3A 20 35 ontent-Length:.5
000000A0  37 38 39 37 0D 0A 48 6F 73 74 3A 20 62 61 62 79 7897..Host:.baby
000000B0  2E 73 71 75 65 65 7A 65 6E 65 74 77 6F 72 6B 2E .squeezenetwork.
000000C0  63 6F 6D 3A 39 30 30 30 0D 0A 43 6F 6E 74 65 6E com:9000..Conten
000000D0  74 2D 54 79 70 65 3A 20 74 65 78 74 2F 6A 73 6F t-Type:.text/jso
000000E0  6E 0D 0A 41 63 63 65 70 74 2D 4C 61 6E 67 75 61 n..Accept-Langua
000000F0  67 65 3A 20 66 72 0D 0A 0D 0A 5B 7B 22 69 64 22 ge:.fr....[{"id"
00000100  3A 31 2C 22 64 61 74 61 22 3A 7B 22 72 65 71 75 :1,"data":{"requ
00000110  65 73 74 22 3A 5B 22 22 2C 5B 22 73 65 72 76 65 est":["",["serve
00000120  72 73 74 61 74 75 73 22 2C 30 2C 35 30 2C 22 73 rstatus",0,50,"s
00000130  75 62 73 63 72 69 62 65 3A 36 30 22 5D 5D 2C 22 ubscribe:60"]],"
00000140  72 65 73 70 6F 6E 73 65 22 3A 22 5C 2F 32 30 33 response":"\/203
00000150  37 39 39 38 58 30 38 36 35 63 32 36 39 32 31 66 7998X0865c26921f
...
TCP: Control Bits: .AP..., len:  481, seq:1582202920-1582203401, ack:
267207787, win: 2920, src:57523  dst: 9000 

00000040        31 32 36 38 39 34 33 33 36 31 58 38 36 33   1268943361X863
00000050  30 31 31 33 36 5C 2F 73 6C 69 6D 5C 2F 72 65 71 01136\/slim\/req
00000060  75 65 73 74 22 7D 2C 22 63 68 61 6E 6E 65 6C 22 uest"},"channel"
00000070  3A 22 5C 2F 73 6C 69 6D 5C 2F 72 65 71 75 65 73 :"\/slim\/reques
00000080  74 22 7D 2C 7B 22 69 64 22 3A 37 32 30 2C 22 64 t"},{"id":720,"d
00000090  61 74 61 22 3A 7B 22 72 65 71 75 65 73 74 22 3A ata":{"request":
000000A0  5B 22 30 30 3A 30 34 3A 32 30 3A 32 36 3A 31 36 ["00:04:20:26:16
000000B0  3A 37 37 22 2C 5B 22 62 75 74 74 6F 6E 22 2C 22 :77",["button","
000000C0  70 72 65 73 65 74 5F 31 2E 73 69 6E 67 6C 65 22 preset_1.single"
000000D0  5D 5D 2C 22 72 65 73 70 6F 6E 73 65 22 3A 22 5C ]],"response":"\
000000E0  2F 32 30 33 37 39 39 38 58 30 38 36 35 63 32 36 /2037998X0865c26
000000F0  39 32 31 66 36 35 64 61 31 35 33 37 35 63 66 32 921f65da15375cf2
00000100  66 36 32 32 38 38 32 30 39 58 30 30 30 34 32 30 f62288209X000420
00000110  32 36 31 36 37 37 58 31 58 31 32 36 38 39 34 33 261677X1X1268943
00000120  33 36 31 58 38 36 33 30 31 31 33 36 5C 2F 73 6C 361X86301136\/sl
00000130  69 6D 5C 2F 72 65 71 75 65 73 74 22 7D 2C 22 63 im\/request"},"c
00000140  68 61 6E 6E 65 6C 22 3A 22 5C 2F 73 6C 69 6D 5C hannel":"\/slim\
00000150  2F 72 65 71 75 65 73 74 22 7D 2C 7B 22 69 64 22 /request"},{"id"
00000160  3A 37 32 31 2C 22 64 61 74 61 22 3A 7B 22 72 65 :721,"data":{"re
00000170  71 75 65 73 74 22 3A 5B 22 30 30 3A 30 34 3A 32 quest":["00:04:2
00000180  30 3A 32 36 3A 31 36 3A 37 37 22 2C 5B 22 70 61 0:26:16:77",["pa
00000190  75 73 65 22 2C 22 31 22 5D 5D 2C 22 72 65 73 70 use","1"]],"resp
000001A0  6F 6E 73 65 22 3A 22 5C 2F 32 30 33 37 39 39 38 onse":"\/2037998
000001B0  58 30 38 36 35 63 32 36 39 32 31 66 36 35 64 61 X0865c26921f65da
000001C0  31 35 33 37 35 63 66 32 66 36 32 32 38 38 32 30 15375cf2f6228820
000001D0  39 58 30 30 30 34 32 30 32 36 31 36 37 37 58 31 9X000420261677X1
000001E0  58 31 32 36 38 39 34 33 33 36 31 58 38 36 33 30 X1268943361X8630
000001F0  31 31 33 36 5C 2F 73 6C 69 6D 5C 2F 72 65 71 75 1136\/slim\/requ
00000200  65 73 74 22 7D 2C 22 63 68 61 6E 6E 65 6C 22 3A est"},"channel":
00000210  22 5C 2F 73 6C 69 6D 5C 2F 72 65 71 75 65 73 74 "\/slim\/request
00000220  22 7D 5D                                        "}]             


The squeezebox server replies with:
TCP: Control Bits: .AP..., len:  223, seq: 267207787-267208010, ack:1582203401,
win:  484, src: 9000  dst:57523 
00000040        48 54 54 50 2F 31 2E 31 20 32 30 30 20 28   HTTP/1.1.200.(
00000050  4F 4B 29 0D 0A 44 61 74 65 3A 20 54 68 75 2C 20 OK)..Date:.Thu,.
00000060  31 38 20 4D 61 72 20 32 30 31 30 20 32 30 3A 31 18.Mar.2010.20:1
00000070  36 3A 30 34 20 47 4D 54 0D 0A 53 65 72 76 65 72 6:04.GMT..Server
00000080  3A 20 53 71 75 65 65 7A 65 4E 65 74 77 6F 72 6B :.SqueezeNetwork
00000090  20 4A 69 76 65 64 2F 37 2E 34 0D 0A 43 6F 6E 74 .Jived/7.4..Cont
000000A0  65 6E 74 2D 4C 65 6E 67 74 68 3A 20 31 31 30 0D ent-Length:.110.
000000B0  0A 0D 0A 5B 7B 22 65 72 72 6F 72 22 3A 22 50 4F ...[{"error":"PO
000000C0  53 54 20 62 6F 64 79 20 74 6F 6F 20 6C 61 72 67 ST.body.too.larg
000000D0  65 20 28 6D 61 78 3D 35 31 32 30 30 29 22 2C 22 e.(max=51200)","
000000E0  61 64 76 69 63 65 22 3A 7B 22 69 6E 74 65 72 76 advice":{"interv
000000F0  61 6C 22 3A 35 30 30 30 2C 22 72 65 63 6F 6E 6E al":5000,"reconn
00000100  65 63 74 22 3A 22 6E 6F 6E 65 22 7D 2C 22 73 75 ect":"none"},"su
00000110  63 63 65 73 73 66 75 6C 22 3A 66 61 6C 73 65 7D ccessful":false}
00000120  5D                                              ]               


The connectivity was restored immediately after powering down my radio.
The network capture is slightly different when powering up. It's like
mysqueezebox server connected my radio.

I hope this might help root causing a bunch of connectivity issues that seems
to be reported here.
Comment 1 Pascal Roncolato 2010-03-18 15:40:52 UTC 
Forgot to tell that:
when problem was occurring ("cannot connect to mysqueezebox.com" error when using the SB radio equipement), I could succesfully launch/play my favorite radio station from the "Squeezebox server" web interface installed on my PC.
Comment 2 Pascal Roncolato 2010-03-24 23:39:00 UTC 
Created attachment 6696 [details]
Problem is back again: sending /var/mlog/messages file

When I woke up this morning, radio was playing a default looping music instead of my favorite radio.
Aroung 6:50 am my time I started attempting to restore radio.
I noticed that symptoms were the same.
I can see a blue network connectivity icon at the bottom right (instead of the white one)

In the log, I can find the error that I was able to collect in my network trace:
Mar 24 21:14:00 squeezeplay: WARN   net.comet - Comet.lua:876 Comet {mysqueezebox.com}: _response, nil id=nil failed: POST body too large (max=51200)
(Sounds like SB radio has built a request with a set of the same repeated fragments)


Mar 24 21:13:54 squeezeplay: INFO   net.comet - Comet.lua:804 Comet {mysqueezebox.com}: _getEventSink error: inactivity timeout
Mar 24 21:13:54 squeezeplay: INFO   net.comet - Comet.lua:997 Comet {mysqueezebox.com}: handleAdvice state=CONNECTED
Mar 24 21:13:54 squeezeplay: INFO   squeezebox.server - SlimServer.lua:714 disconnected mysqueezebox.com idleTimeoutTriggered: nil
Mar 24 21:13:54 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:305 notify_serverDisconnected: SlimServer {mysqueezebox.com} is now disconnected
Mar 24 21:13:54 squeezeplay: WARN   applet.AlarmSnooze - AlarmSnoozeApplet.lua:318 notify_serverDisconnected: SlimServer {mysqueezebox.com} - disconnected, but no server alarm in progress : nil
Mar 24 21:13:54 squeezeplay: INFO   net.comet - Comet.lua:1038 Comet {mysqueezebox.com}: advice is handshake, connect in 0 seconds
Mar 24 21:13:55 squeezeplay: INFO   squeezebox.server - SlimServer.lua:691 connected EEE-PRO
Mar 24 21:13:55 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:283 notify_serverConnected: SlimServer {EEE-PRO} is now connected
Mar 24 21:13:55 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:289 local player connection status is true
Mar 24 21:13:55 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:296                       local player->server is SlimServer {mysqueezebox.com}
Mar 24 21:13:55 squeezeplay: INFO   squeezebox.server - SlimServer.lua:314 EEE-PRO firmware=http://192.168.1.106:9000/firmware/baby_7.4.2_r8423.bin force=false
Mar 24 21:13:55 squeezeplay: INFO   applet.SlimMenus - SlimMenusApplet.lua:420 _menuSink(36) SlimServer {EEE-PRO} menuDirective: nil isCurrentServer:nil
Mar 24 21:13:55 squeezeplay: INFO   applet.SlimMenus - SlimMenusApplet.lua:535 Eliminated myMusic node from server, since now handled locally
Mar 24 21:13:55 squeezeplay: INFO   squeezebox.server - SlimServer.lua:691 connected mysqueezebox.com
Mar 24 21:13:55 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:283 notify_serverConnected: SlimServer {mysqueezebox.com} is now connected
Mar 24 21:13:55 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:289 local player connection status is true
Mar 24 21:13:55 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:296                       local player->server is SlimServer {mysqueezebox.com}
Mar 24 21:13:55 squeezeplay: WARN   applet.AlarmSnooze - AlarmSnoozeApplet.lua:214 alarm_sledgehammerRearm(notify_serverConnected): nil alarm in progress - audioState is 0
Mar 24 21:14:00 squeezeplay: WARN   net.comet - Comet.lua:876 Comet {mysqueezebox.com}: _response, nil id=nil failed: POST body too large (max=51200)
Mar 24 21:14:00 squeezeplay: WARN   net.comet - Comet.lua:956 Comet {mysqueezebox.com}: _response, unknown error: POST body too large (max=51200)
Mar 24 21:14:00 squeezeplay: INFO   net.comet - Comet.lua:997 Comet {mysqueezebox.com}: handleAdvice state=CONNECTED
Mar 24 21:14:00 squeezeplay: INFO   squeezebox.server - SlimServer.lua:714 disconnected mysqueezebox.com idleTimeoutTriggered: nil
Mar 24 21:14:00 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:305 notify_serverDisconnected: SlimServer {mysqueezebox.com} is now disconnected
Mar 24 21:14:00 squeezeplay: WARN   applet.AlarmSnooze - AlarmSnoozeApplet.lua:318 notify_serverDisconnected: SlimServer {mysqueezebox.com} - disconnected, but no server alarm in progress : nil
Mar 24 21:14:00 squeezeplay: INFO   net.comet - Comet.lua:1035 Comet {mysqueezebox.com}: advice is none server told us not to reconnect
Mar 24 21:14:26 squeezeplay: INFO   squeezebox.server - SlimServer.lua:714 disconnected EEE-PRO idleTimeoutTriggered: true
Mar 24 21:14:26 squeezeplay: INFO   squeezebox.server - SlimServer.lua:717 idle disconnected EEE-PRO
Mar 24 21:14:26 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:305 notify_serverDisconnected: SlimServer {EEE-PRO} is now disconnected
Mar 24 21:14:26 squeezeplay: WARN   applet.AlarmSnooze - AlarmSnoozeApplet.lua:318 notify_serverDisconnected: SlimServer {EEE-PRO} - disconnected, but no server alarm in progress : nil
Mar 24 21:14:30 squeezeplay: INFO   squeezebox.server - SlimServer.lua:691 connected EEE-PRO
Mar 24 21:14:30 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:283 notify_serverConnected: SlimServer {EEE-PRO} is now connected
Mar 24 21:14:30 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:289 local player connection status is true
Comment 3 Andy Grundman 2010-03-25 14:27:59 UTC 
Yeah there is probably a bug where the list of subscriptions builds up and when it tries to resubscribe it ends up sending a very large request.

If you have a way to reproduce this, it would be very helpful.
Comment 4 Pascal Roncolato 2010-03-25 23:03:09 UTC 
My SB Radio is still in this weird state (unable to connect to mysqueezebox.com)
I've left it untouched for any potential debug purpose.
If you want me to try something for you, I'll be glad to help (although I'd like to restore connectivity as soon as possible)

This morning (around 6:40 below), my daily alarm didn't trigger (programmed for 6:00), but I don't use the equipement to wake me up in the morning as I cannot trust in it. 
I found it with the clock screen (switched off). When I turned the volume button, it started to player the radio. I had to switch it ON/OFF/ON/OFF as sound level was blocked at a high level.

However, I checked that /nas/var/log/messages doesn't not contain any new "Post body too long" error, since I reported it.

This morning's log:
Mar 25 22:03:53 squeezeplay: INFO   applet.SlimMenus - SlimMenusApplet.lua:535 Eliminated myMusic node from server, since now handled locally
Mar 25 22:04:53 squeezeplay: WARN   net.thread - NetworkThread.lua:146 network thread timeout for Task(SocketHttp {EEE-PRO_Request}(R))
Mar 26 05:59:50 squeezeplay: INFO   audio.decode - decode_start_handler:274 init decoder mp3
Mar 26 05:59:50 squeezeplay: INFO   audio.decode - Playback.lua:413 connect 92.61.164.12:80 GET /rtl-1-44-96 HTTP/1.0^M
Mar 26 06:40:23 squeezeplay: INFO   squeezeplay - JiveMain.lua:207 Turn soft power on
Mar 26 06:40:23 squeezeplay: INFO   squeezebox.server - SlimServer.lua:714 disconnected mysqueezebox.com idleTimeoutTriggered: nil
Mar 26 06:40:23 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:305 notify_serverDisconnected: SlimServer {mysqueezebox.com} is now disconnected
Mar 26 06:40:23 squeezeplay: WARN   applet.AlarmSnooze - AlarmSnoozeApplet.lua:318 notify_serverDisconnected: SlimServer {mysqueezebox.com} - disconnected, but no server alarm in progress : nil
Mar 26 06:40:24 squeezeplay: INFO   squeezeplay.applets - AppletManager.lua:704 store settings: Playback
Mar 26 06:40:30 squeezeplay: INFO   squeezebox.server - SlimServer.lua:714 disconnected mysqueezebox.com idleTimeoutTriggered: nil
Mar 26 06:40:30 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:305 notify_serverDisconnected: SlimServer {mysqueezebox.com} is now disconnected
Mar 26 06:40:30 squeezeplay: WARN   applet.AlarmSnooze - AlarmSnoozeApplet.lua:318 notify_serverDisconnected: SlimServer {mysqueezebox.com} - disconnected, but no server alarm in progress : nil
Mar 26 06:40:30 squeezeplay: INFO   squeezebox.server - SlimServer.lua:714 disconnected mysqueezebox.com idleTimeoutTriggered: nil
Mar 26 06:40:30 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:305 notify_serverDisconnected: SlimServer {mysqueezebox.com} is now disconnected
Mar 26 06:40:30 squeezeplay: WARN   applet.AlarmSnooze - AlarmSnoozeApplet.lua:318 notify_serverDisconnected: SlimServer {mysqueezebox.com} - disconnected, but no server alarm in progress : nil
Mar 26 06:40:30 squeezeplay: INFO   squeezebox.server - SlimServer.lua:714 disconnected mysqueezebox.com idleTimeoutTriggered: nil
M
.... (stripped)
Mar 26 06:40:34 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:305 notify_serverDisconnected: SlimServer {mysqueezebox.com} is now disconnected
Mar 26 06:40:34 squeezeplay: WARN   applet.AlarmSnooze - AlarmSnoozeApplet.lua:318 notify_serverDisconnected: SlimServer {mysqueezebox.com} - disconnected, but no server alarm in progress : nil
Mar 26 06:40:34 squeezeplay: INFO   squeezeplay.applets - AppletManager.lua:704 store settings: Playback
Mar 26 06:40:56 squeezeplay: INFO   squeezeplay - JiveMain.lua:200 Turn soft power off
Mar 26 06:40:56 squeezeplay: INFO   squeezebox.server - SlimServer.lua:714 disconnected mysqueezebox.com idleTimeoutTriggered: nil
Mar 26 06:40:56 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:305 notify_serverDisconnected: SlimServer {mysqueezebox.com} is now disconnected
Mar 26 06:40:56 squeezeplay: WARN   applet.AlarmSnooze - AlarmSnoozeApplet.lua:318 notify_serverDisconnected: SlimServer {mysqueezebox.com} - disconnected, but no server alarm in progress : nil
Mar 26 06:40:56 squeezeplay: INFO   applet.ScreenSavers - ScreenSaversApplet.lua:243 activating Clock screensaver
Mar 26 06:40:56 squeezeplay: INFO   applet.SlimBrowser - SlimBrowserApplet.lua:2825 _problemConnectingPopupInternal
Mar 26 06:41:04 squeezeplay: INFO   squeezeplay.applets - AppletManager.lua:704 store settings: Playback
Mar 26 06:41:17 squeezeplay: INFO   applet.SlimBrowser - SlimBrowserApplet.lua:2890 _problemConnectingInternal
Mar 26 06:41:19 squeezeplay: INFO   squeezeplay - JiveMain.lua:207 Turn soft power on
Mar 26 06:41:19 squeezeplay: INFO   squeezebox.server - SlimServer.lua:714 disconnected mysqueezebox.com idleTimeoutTriggered: nil
Mar 26 06:41:19 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:305 notify_serverDisconnected: SlimServer {mysqueezebox.com} is now disconnected
Mar 26 06:41:19 squeezeplay: WARN   applet.AlarmSnooze - AlarmSnoozeApplet.lua:318 notify_serverDisconnected: SlimServer {mysqueezebox.com} - disconnected, but no server alarm in progress : nil
Mar 26 06:41:23 squeezeplay: INFO   squeezeplay - JiveMain.lua:200 Turn soft power off
Mar 26 06:41:23 squeezeplay: INFO   squeezebox.server - SlimServer.lua:714 disconnected mysqueezebox.com idleTimeoutTriggered: nil
Mar 26 06:41:23 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:305 notify_serverDisconnected: SlimServer {mysqueezebox.com} is now disconnected
Mar 26 06:41:23 squeezeplay: WARN   applet.AlarmSnooze - AlarmSnoozeApplet.lua:318 notify_serverDisconnected: SlimServer {mysqueezebox.com} - disconnected, but no server alarm in progress : nil
Mar 26 06:41:23 squeezeplay: INFO   applet.ScreenSavers - ScreenSaversApplet.lua:243 activating Clock screensaver
Mar 26 06:42:54 dropbear[5900]: Child connection from 192.168.1.105:2166
Comment 5 Bradley Froehle 2010-10-22 21:48:58 UTC 
I'm having this same issue.  Rebooting the SB Radio always allows it to reconnect to mySB without issue.  After a certain length of time connected (normally a day or two) the radio reaches a state where it has disconnected and cannot reconnect.

The connection to mySB is somewhat functional, for example the remote control feature on the mySB site remains working.

Reading through /var/log/messages on the SB Radio gives this sort of trace:

(note the POST BODY TOO LARGE message in the final coda below.

NORMAL FUNCTIONING
....
Oct 21 20:01:38 udhcpc[783]: Sending renew...
Oct 21 20:01:41 udhcpc[783]: Lease of 10.0.1.2 obtained, lease time 86400
Oct 21 20:01:41 root: udhcpc_action eth1 renew ip=10.0.1.2

THE START OF SOMETHING GOING WRONG

Oct 22 02:41:49 squeezeplay: WARN   net.thread - NetworkThread.lua:146 network thread timeout for Task(SocketHttp {mysqueezebox.com_Chunked}(R))
Oct 22 02:41:49 squeezeplay: ERROR  net.http - SocketHttp.lua:803 SocketHttp {mysqueezebox.com_Chunked}:t_rcvResponse.pump() error:inactivity timeout
Oct 22 02:41:49 squeezeplay: stack traceback:
Oct 22 02:41:49 squeezeplay: 	/usr/share/jive/jive/net/SocketHttp.lua:803: in function 'pump'
Oct 22 02:41:49 squeezeplay: 	/usr/share/jive/jive/net/SocketTcp.lua:192: in function 'readPump'
Oct 22 02:41:49 squeezeplay: 	/usr/share/jive/jive/net/Socket.lua:161: in function </usr/share/jive/jive/net/Socket.lua:159>
Oct 22 02:41:49 squeezeplay: INFO   net.comet - Comet.lua:804 Comet {mysqueezebox.com}: _getEventSink error: inactivity timeout
Oct 22 02:41:49 squeezeplay: INFO   net.comet - Comet.lua:997 Comet {mysqueezebox.com}: handleAdvice state=CONNECTED
Oct 22 02:41:49 squeezeplay: INFO   squeezebox.server - SlimServer.lua:734 disconnected mysqueezebox.com idleTimeoutTriggered: nil
Oct 22 02:41:49 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:367 notify_serverDisconnected: SlimServer {mysqueezebox.com} is now disconnected
Oct 22 02:41:49 squeezeplay: WARN   applet.AlarmSnooze - AlarmSnoozeApplet.lua:380 notify_serverDisconnected: SlimServer {mysqueezebox.com} - disconnected, but no server alarm in progress : nil
Oct 22 02:41:49 squeezeplay: INFO   net.comet - Comet.lua:1038 Comet {mysqueezebox.com}: advice is retry, connect in 7.538 seconds
Oct 22 02:41:50 squeezeplay: WARN   net.thread - NetworkThread.lua:146 network thread timeout for Task(SocketTcp {SlimProto}(R))
Oct 22 02:41:50 squeezeplay: INFO   net.slimproto - SlimProto.lua:754 connection error: inactivity timeout, reconnecting in 3.008 seconds
Oct 22 02:41:53 squeezeplay: INFO   net.slimproto - SlimProto.lua:577 connect to baby.squeezenetwork.com (66.150.114.115)
Oct 22 02:41:53 squeezeplay: INFO   net.slimproto - SlimProto.lua:135 Send HELO: reconnect-bit=0 bytesReceived(H,L)=0,0
Oct 22 02:41:57 squeezeplay: WARN   net.comet - Comet.lua:876 Comet {mysqueezebox.com}: _response, /meta/reconnect id=nil failed: invalid clientId
Oct 22 02:41:57 squeezeplay: INFO   net.comet - Comet.lua:997 Comet {mysqueezebox.com}: handleAdvice state=CONNECTING
Oct 22 02:41:57 squeezeplay: INFO   squeezebox.server - SlimServer.lua:734 disconnected mysqueezebox.com idleTimeoutTriggered: nil
Oct 22 02:41:57 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:367 notify_serverDisconnected: SlimServer {mysqueezebox.com} is now disconnected
Oct 22 02:41:57 squeezeplay: WARN   applet.AlarmSnooze - AlarmSnoozeApplet.lua:380 notify_serverDisconnected: SlimServer {mysqueezebox.com} - disconnected, but no server alarm in progress : nil
Oct 22 02:41:57 squeezeplay: INFO   net.comet - Comet.lua:1038 Comet {mysqueezebox.com}: advice is handshake, connect in 0 seconds
Oct 22 02:41:57 squeezeplay: INFO   squeezebox.server - SlimServer.lua:710 connected mysqueezebox.com
Oct 22 02:41:57 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:348 notify_serverConnected: SlimServer {mysqueezebox.com} is now connected
Oct 22 02:41:57 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:351 local player connection status is true
Oct 22 02:41:57 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:358                       local player->server is SlimServer {mysqueezebox.com}
Oct 22 02:41:57 squeezeplay: WARN   applet.AlarmSnooze - AlarmSnoozeApplet.lua:241 alarm_sledgehammerRearm(notify_serverConnected): nil alarm in progress - audioState is 0
Oct 22 02:41:57 squeezeplay: INFO   squeezebox.server - SlimServer.lua:722 self.mac being set to---->nil

A REPEATING SECTION OF ERROR  (This same string of logs display roughly every minute for a long time)

Oct 22 02:42:07 squeezeplay: WARN   net.thread - NetworkThread.lua:146 network thread timeout for Task(SocketHttp {mysqueezebox.com_Request}(W))
Oct 22 02:42:07 squeezeplay: ERROR  net.http - SocketHttp.lua:373 SocketHttp {mysqueezebox.com_Request}:t_sendRequest.pump: inactivity timeout
Oct 22 02:42:07 squeezeplay: stack traceback:
Oct 22 02:42:07 squeezeplay: 	/usr/share/jive/jive/net/SocketHttp.lua:373: in function 'pump'
Oct 22 02:42:07 squeezeplay: 	/usr/share/jive/jive/net/SocketTcp.lua:200: in function 'writePump'
Oct 22 02:42:07 squeezeplay: 	/usr/share/jive/jive/net/Socket.lua:186: in function </usr/share/jive/jive/net/Socket.lua:184>
Oct 22 02:42:07 squeezeplay: INFO   net.comet - Comet.lua:804 Comet {mysqueezebox.com}: _getEventSink error: inactivity timeout
Oct 22 02:42:07 squeezeplay: INFO   net.comet - Comet.lua:997 Comet {mysqueezebox.com}: handleAdvice state=CONNECTED
Oct 22 02:42:07 squeezeplay: INFO   squeezebox.server - SlimServer.lua:734 disconnected mysqueezebox.com idleTimeoutTriggered: nil
Oct 22 02:42:07 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:367 notify_serverDisconnected: SlimServer {mysqueezebox.com} is now disconnected
Oct 22 02:42:07 squeezeplay: WARN   applet.AlarmSnooze - AlarmSnoozeApplet.lua:380 notify_serverDisconnected: SlimServer {mysqueezebox.com} - disconnected, but no server alarm in progress : nil
Oct 22 02:42:07 squeezeplay: INFO   net.comet - Comet.lua:1038 Comet {mysqueezebox.com}: advice is retry, connect in 7.392 seconds
Oct 22 02:42:15 squeezeplay: INFO   squeezebox.server - SlimServer.lua:710 connected mysqueezebox.com
Oct 22 02:42:15 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:348 notify_serverConnected: SlimServer {mysqueezebox.com} is now connected
Oct 22 02:42:15 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:351 local player connection status is true
Oct 22 02:42:15 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:358                       local player->server is SlimServer {mysqueezebox.com}
Oct 22 02:42:15 squeezeplay: WARN   applet.AlarmSnooze - AlarmSnoozeApplet.lua:241 alarm_sledgehammerRearm(notify_serverConnected): nil alarm in progress - audioState is 0
Oct 22 02:42:15 squeezeplay: INFO   squeezebox.server - SlimServer.lua:722 self.mac being set to---->nil

THE CODA
Oct 22 03:24:16 squeezeplay: WARN   net.thread - NetworkThread.lua:146 network thread timeout for Task(SocketHttp {mysqueezebox.com_Request}(R))
Oct 22 03:24:26 squeezeplay: WARN   net.thread - NetworkThread.lua:146 network thread timeout for Task(SocketHttp {mysqueezebox.com_Chunked}(R))
Oct 22 03:24:26 squeezeplay: ERROR  net.http - SocketHttp.lua:803 SocketHttp {mysqueezebox.com_Chunked}:t_rcvResponse.pump() error:inactivity timeout
Oct 22 03:24:26 squeezeplay: stack traceback:
Oct 22 03:24:26 squeezeplay: 	/usr/share/jive/jive/net/SocketHttp.lua:803: in function 'pump'
Oct 22 03:24:26 squeezeplay: 	/usr/share/jive/jive/net/SocketTcp.lua:192: in function 'readPump'
Oct 22 03:24:26 squeezeplay: 	/usr/share/jive/jive/net/Socket.lua:161: in function </usr/share/jive/jive/net/Socket.lua:159>
Oct 22 03:24:26 squeezeplay: INFO   net.comet - Comet.lua:804 Comet {mysqueezebox.com}: _getEventSink error: inactivity timeout
Oct 22 03:24:26 squeezeplay: INFO   net.comet - Comet.lua:997 Comet {mysqueezebox.com}: handleAdvice state=CONNECTED
Oct 22 03:24:26 squeezeplay: INFO   squeezebox.server - SlimServer.lua:734 disconnected mysqueezebox.com idleTimeoutTriggered: nil
Oct 22 03:24:26 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:367 notify_serverDisconnected: SlimServer {mysqueezebox.com} is now disconnected
Oct 22 03:24:26 squeezeplay: WARN   applet.AlarmSnooze - AlarmSnoozeApplet.lua:380 notify_serverDisconnected: SlimServer {mysqueezebox.com} - disconnected, but no server alarm in progress : nil
Oct 22 03:24:26 squeezeplay: INFO   net.comet - Comet.lua:1038 Comet {mysqueezebox.com}: advice is handshake, connect in 0 seconds
Oct 22 03:24:26 squeezeplay: INFO   squeezebox.server - SlimServer.lua:710 connected mysqueezebox.com
Oct 22 03:24:26 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:348 notify_serverConnected: SlimServer {mysqueezebox.com} is now connected
Oct 22 03:24:26 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:351 local player connection status is true
Oct 22 03:24:26 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:358                       local player->server is SlimServer {mysqueezebox.com}
Oct 22 03:24:26 squeezeplay: WARN   applet.AlarmSnooze - AlarmSnoozeApplet.lua:241 alarm_sledgehammerRearm(notify_serverConnected): nil alarm in progress - audioState is 0
Oct 22 03:24:27 squeezeplay: INFO   squeezebox.server - SlimServer.lua:722 self.mac being set to---->nil
Oct 22 03:24:27 squeezeplay: WARN   net.comet - Comet.lua:876 Comet {mysqueezebox.com}: _response, nil id=nil failed: POST body too large (max=51200)
Oct 22 03:24:27 squeezeplay: WARN   net.comet - Comet.lua:956 Comet {mysqueezebox.com}: _response, unknown error: POST body too large (max=51200)
Oct 22 03:24:27 squeezeplay: INFO   net.comet - Comet.lua:997 Comet {mysqueezebox.com}: handleAdvice state=CONNECTED
Oct 22 03:24:27 squeezeplay: INFO   squeezebox.server - SlimServer.lua:734 disconnected mysqueezebox.com idleTimeoutTriggered: nil
Oct 22 03:24:27 squeezeplay: INFO   applet.AlarmSnooze - AlarmSnoozeApplet.lua:367 notify_serverDisconnected: SlimServer {mysqueezebox.com} is now disconnected
Oct 22 03:24:27 squeezeplay: WARN   applet.AlarmSnooze - AlarmSnoozeApplet.lua:380 notify_serverDisconnected: SlimServer {mysqueezebox.com} - disconnected, but no server alarm in progress : nil
Oct 22 03:24:27 squeezeplay: INFO   net.comet - Comet.lua:1035 Comet {mysqueezebox.com}: advice is none server told us not to reconnect
Comment 6 Bradley Froehle 2010-10-25 10:03:58 UTC 
Created attachment 7016 [details]
/var/log/messages

Full /var/log/messages
Comment 7 Alan Young 2010-10-28 02:58:48 UTC 
Thanks for the logs and network trace.

This is part of a collection of issues being handled under bug 16617.

When this large POST error occurs, the UI part of the player will no longer attempt to connect to the server or mysqueezebox.com.

The cause is the result of a sequence of bugs which may be triggered by a network connection failure at a critical point in the connection sequence. When this happens, subsequent reconnection attempts use an expired identifier which gets rejected. With each rejection, the set of active subscriptions requests gets re-added to the set of outstanding requests, eventually resulting in a request message that is too large.

*** This bug has been marked as a duplicate of bug 16617 ***
First Last Prev Next    This bug is not in your last search results.